{"action":"created","issue":{"url":"https://api.github.com/repos/rsyslog/rsyslog/issues/1906","repository_url":"https://api.github.com/repos/rsyslog/rsyslog","labels_url":"https://api.github.com/repos/rsyslog/rsyslog/issues/1906/labels{/name}","comments_url":"https://api.github.com/repos/rsyslog/rsyslog/issues/1906/comments","events_url":"https://api.github.com/repos/rsyslog/rsyslog/issues/1906/events","html_url":"https://github.com/rsyslog/rsyslog/issues/1906","id":268700619,"number":1906,"title":"omelasticsearch: Segfault on HTTP error","user":{"login":"hakman","id":2759402,"avatar_url":"https://avatars0.githubusercontent.com/u/2759402?v=4","gravatar_id":"","url":"https://api.github.com/users/hakman","html_url":"https://github.com/hakman","followers_url":"https://api.github.com/users/hakman/followers","following_url":"https://api.github.com/users/hakman/following{/other_user}","gists_url":"https://api.github.com/users/hakman/gists{/gist_id}","starred_url":"https://api.github.com/users/hakman/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/hakman/subscriptions","organizations_url":"https://api.github.com/users/hakman/orgs","repos_url":"https://api.github.com/users/hakman/repos","events_url":"https://api.github.com/users/hakman/events{/privacy}","received_events_url":"https://api.github.com/users/hakman/received_events","type":"User","site_admin":false},"labels":[{"id":42065809,"url":"https://api.github.com/repos/rsyslog/rsyslog/labels/bug","name":"bug","color":"fc2929","default":true},{"id":42065810,"url":"https://api.github.com/repos/rsyslog/rsyslog/labels/duplicate","name":"duplicate","color":"cccccc","default":true}],"state":"open","locked":false,"assignee":{"login":"rgerhards","id":1482123,"avatar_url":"https://avatars3.githubusercontent.com/u/1482123?v=4","gravatar_id":"","url":"https://api.github.com/users/rgerhards","html_url":"https://github.com/rgerhards","followers_url":"https://api.github.com/users/rgerhards/followers","following_url":"https://api.github.com/users/rgerhards/following{/other_user}","gists_url":"https://api.github.com/users/rgerhards/gists{/gist_id}","starred_url":"https://api.github.com/users/rgerhards/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/rgerhards/subscriptions","organizations_url":"https://api.github.com/users/rgerhards/orgs","repos_url":"https://api.github.com/users/rgerhards/repos","events_url":"https://api.github.com/users/rgerhards/events{/privacy}","received_events_url":"https://api.github.com/users/rgerhards/received_events","type":"User","site_admin":false},"assignees":[{"login":"rgerhards","id":1482123,"avatar_url":"https://avatars3.githubusercontent.com/u/1482123?v=4","gravatar_id":"","url":"https://api.github.com/users/rgerhards","html_url":"https://github.com/rgerhards","followers_url":"https://api.github.com/users/rgerhards/followers","following_url":"https://api.github.com/users/rgerhards/following{/other_user}","gists_url":"https://api.github.com/users/rgerhards/gists{/gist_id}","starred_url":"https://api.github.com/users/rgerhards/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/rgerhards/subscriptions","organizations_url":"https://api.github.com/users/rgerhards/orgs","repos_url":"https://api.github.com/users/rgerhards/repos","events_url":"https://api.github.com/users/rgerhards/events{/privacy}","received_events_url":"https://api.github.com/users/rgerhards/received_events","type":"User","site_admin":false}],"milestone":{"url":"https://api.github.com/repos/rsyslog/rsyslog/milestones/22","html_url":"https://github.com/rsyslog/rsyslog/milestone/22","labels_url":"https://api.github.com/repos/rsyslog/rsyslog/milestones/22/labels","id":2747728,"number":22,"title":"v8.31","description":"","creator":{"login":"rgerhards","id":1482123,"avatar_url":"https://avatars3.githubusercontent.com/u/1482123?v=4","gravatar_id":"","url":"https://api.github.com/users/rgerhards","html_url":"https://github.com/rgerhards","followers_url":"https://api.github.com/users/rgerhards/followers","following_url":"https://api.github.com/users/rgerhards/following{/other_user}","gists_url":"https://api.github.com/users/rgerhards/gists{/gist_id}","starred_url":"https://api.github.com/users/rgerhards/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/rgerhards/subscriptions","organizations_url":"https://api.github.com/users/rgerhards/orgs","repos_url":"https://api.github.com/users/rgerhards/repos","events_url":"https://api.github.com/users/rgerhards/events{/privacy}","received_events_url":"https://api.github.com/users/rgerhards/received_events","type":"User","site_admin":false},"open_issues":26,"closed_issues":42,"state":"open","created_at":"2017-09-06T11:01:19Z","updated_at":"2017-10-27T09:40:57Z","due_on":"2017-11-24T08:00:00Z","closed_at":null},"comments":16,"created_at":"2017-10-26T10:04:29Z","updated_at":"2017-10-27T09:53:36Z","closed_at":null,"author_association":"CONTRIBUTOR","body":"Lately, due to some AWS ELB timeouts and errors we are seeing 30-50 Rsyslog crashes a day. After some debugging, I think I managed to reproduce this with v8.30.0 by restarting ES while pushing data to it.\r\nI think this happens because the module doesn't handle too well HTTP errors like timeouts and other 4xx and 5xx. We discussed a little about this some time ago as part of #505.\r\n\r\nSteps to reproduce:\r\n1. generate a bigger than usual \"log\" file, the content is not that important\r\n2. read from file and push to ES using the config file below\r\n3. restart ES so that libcurl generates an error (sometimes needs to be done a few times)\r\n4. check segfault\r\n\r\nThe gdb stack trace looks like this:\r\n```\r\n#0  strlen () at ../sysdeps/x86_64/strlen.S:106\r\nNo locals.\r\n#1  0x00007f37b8390e29 in computeMessageSize (pWrkrData=0x7f37a8002320, tpls=0x7f37b30f1ae0, message=0x5013b2280 <error: Cannot access memory at address 0x5013b2280>) at omelasticsearch.c:553\r\n        searchType = 0x13952e0 \"example-type\"\r\n        parent = 0x0\r\n        r = 37\r\n        searchIndex = 0x13b24f0 \"xxxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxx\"\r\n        bulkId = 0x0\r\n#2  doAction (pMsgData=0x7f37b30f1ae0, pWrkrData=0x7f37a8002320) at omelasticsearch.c:1219\r\n        nBytes = 21495489152\r\n        ppString = 0x7f37b30f1ae0\r\n        iRet = RS_RET_OK\r\n#3  0x0000000000459a35 in actionCallDoAction (pWti=0x13b2280, iparams=<optimized out>, pThis=0x13b2c40) at ../action.c:1109\r\n        param = {0x5013b2280, 0x45976a <actionPrepare+874>, 0x0, 0x869a1851333dd200, 0x0}\r\n        i = <optimized out>\r\n        iRet = RS_RET_OK\r\n#4  actionProcessMessage (pThis=0x13b2c40, actParams=0x7f37b30f1bc0, pWti=0x13b2280) at ../action.c:1151\r\n        iRet = <optimized out>\r\n#5  0x0000000000459e4c in doTransaction (nparams=1, iparams=0x7f37b30f1ba0, pWti=0x13b2280, pThis=0x13b2c40) at ../action.c:1179\r\n        wrkrInfo = 0x1383af0\r\n        i = 2\r\n        iRet = RS_RET_OK\r\n#6  actionTryCommit (pThis=pThis@entry=0x13b2c40, pWti=pWti@entry=0x13b2280, iparams=iparams@entry=0x7f37b30f1ba0, nparams=nparams@entry=1) at ../action.c:1205\r\n        iRet = <optimized out>\r\n#7  0x000000000045a37f in actionTryRemoveHardErrorsFromBatch (new_nMsgs=<synthetic pointer>, new_iparams=0x7f37a80998f0, pWti=0x13b2280, pThis=0x13b2c40) at ../action.c:1279\r\n        i = 0\r\n        wrkrInfo = 0x1383af0\r\n        ret = <optimized out>\r\n        iRet = RS_RET_OK\r\n        nMsgs = <optimized out>\r\n        oneParam = {\r\n          param = 0x7f37a8002190 \"{\\\"@timestamp\\\":\\\"2017-10-26T08:55:07.977511+00:00\\\",\\\"message\\\":\\\"Oct 24 15:43:01 router-dc1 kernel: [LAN_OUT-default-D]IN=eth1 OUT=vti0 MAC=00:00:00:00:00:00:00:00:00:00:00:00:00:00 SRC=10.10.10.10 DST=10.\"..., lenBuf = 384, lenStr = 296}\r\n#8  actionCommit (pThis=pThis@entry=0x13b2c40, pWti=pWti@entry=0x13b2280) at ../action.c:1349\r\n        wrkrInfo = 0x1383af0\r\n        nMsgs = 0\r\n        iparams = 0x7f37a80998f0\r\n        needfree_iparams = 1\r\n        iRet = <optimized out>\r\n        bDone = <optimized out>\r\n#9  0x000000000045b482 in processBatchMain (pVoid=0x13b2c40, pBatch=<optimized out>, pWti=0x13b2280) at ../action.c:1479\r\n        pAction = 0x13b2c40\r\n        i = <optimized out>\r\n        ttNow = {timeType = 1 '\\001', month = 0 '\\000', day = 0 '\\000', hour = 0 '\\000', minute = 55 '7', second = 127 '\\177', secfracPrecision = 0 '\\000', OffsetMinute = 0 '\\000', OffsetHour = 1 '\\001', OffsetMode = 0 '\\000', year = 0,\r\n          secfrac = 0, inUTC = 64 '@'}\r\n        iRet = RS_RET_OK\r\n#10 0x000000000045012a in ConsumerReg (pThis=0x13b3070, pWti=0x13b2280) at queue.c:2005\r\n        iCancelStateSave = 1\r\n        bNeedReLock = 1\r\n        skippedMsgs = 0\r\n        iRet = RS_RET_OK\r\n#11 0x000000000044c92e in wtiWorker (pThis=pThis@entry=0x13b2280) at wti.c:365\r\n        __cancel_buf = {__cancel_jmp_buf = {{__cancel_jmp_buf = {20652408, -8949826815573126435, 1, 139877212432671, 20652352, 20652672, -8949826815539572003, 9053560688049492701}, __mask_was_saved = 0}}, __pad = {0x7f37b30f1d90, 0x0, 0x0,\r\n            0x0}}\r\n        __cancel_routine = 0x44c410 <wtiWorkerCancelCleanup>\r\n        __cancel_arg = 0x13b2280\r\n        __not_first_call = <optimized out>\r\n        pWtp = 0x13b2140\r\n        pAction = <optimized out>\r\n        bInactivityTOOccured = 0\r\n        localRet = <optimized out>\r\n        terminateRet = RS_RET_OK\r\n        wrkrInfo = <optimized out>\r\n        iCancelStateSave = 0\r\n        i = <optimized out>\r\n        j = <optimized out>\r\n        k = <optimized out>\r\n#12 0x000000000044b906 in wtpWorker (arg=0x13b2280) at wtp.c:417\r\n        __cancel_buf = {__cancel_jmp_buf = {{__cancel_jmp_buf = {139877204041344, 9053560702056501981, 1, 139877212432671, 139877204044224, 20652672, -8949826815575223587, 9053560689646998237}, __mask_was_saved = 0}}, __pad = {\r\n            0x7f37b30f1ef0, 0x0, 0x0, 0x0}}\r\n        __cancel_routine = 0x44b740 <wtpWrkrExecCancelCleanup>\r\n        __cancel_arg = 0x13b2280\r\n        __not_first_call = <optimized out>\r\n        pWti = 0x13b2280\r\n        pThis = 0x13b2140\r\n        sigSet = {__val = {1048576, 0 <repeats 15 times>}}\r\n        pszDbgHdr = <optimized out>\r\n        thrdName = \"rs:action 0 queue:Reg\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\"\r\n#13 0x00007f37b97986ba in start_thread (arg=0x7f37b30f2700) at pthread_create.c:333\r\n        __res = <optimized out>\r\n        pd = 0x7f37b30f2700\r\n        now = <optimized out>\r\n        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {139877204043520, 9053561209615258333, 1, 139877212432671, 139877204044224, 20652672, -8949826815470365987, -8949841028305284387}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0},\r\n            data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}\r\n        not_first_call = <optimized out>\r\n        pagesize_m1 = <optimized out>\r\n        sp = <optimized out>\r\n        freesize = <optimized out>\r\n        __PRETTY_FUNCTION__ = \"start_thread\"\r\n#14 0x00007f37b8aae3dd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109\r\n```\r\n\r\nThe config file that was used is:\r\n```\r\nmodule(load=\"imfile\" mode=\"polling\")\r\nmodule(load=\"omelasticsearch\")\r\n\r\ninput(\r\n  type=\"imfile\"\r\n  File=\"/tmp/test.log\"\r\n  Tag=\"example\"\r\n  Ruleset=\"example-elasticsearch\"\r\n)\r\n\r\ntemplate(name=\"example-data\" type=\"list\"){\r\n  constant(value=\"{\")\r\n  constant(value=\"\\\"@timestamp\\\":\\\"\") property(name=\"timestamp\" dateFormat=\"rfc3339\")\r\n  constant(value=\"\\\",\\\"message\\\":\\\"\") property(name=\"msg\" format=\"jsonr\")\r\n  constant(value=\"\\\"}\")\r\n}\r\n\r\nruleset(name=\"example-elasticsearch\"){\r\n  action(\r\n    type=\"omelasticsearch\"\r\n    server=\"10.0.0.10\"\r\n    serverport=\"9200\"\r\n    searchIndex=\"xxxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxx\"\r\n    searchType=\"example-type\"\r\n    template=\"example-data\"\r\n    bulkmode=\"on\"\r\n    action.resumeRetryCount=\"5\"\r\n    action.resumeInterval=\"60\"\r\n    queue.type=\"FixedArray\"\r\n    queue.size=\"10000\"\r\n    queue.dequeuebatchsize=\"1000\"\r\n    queue.dequeueslowdown=\"10000000\"\r\n  )\r\n}\r\n```\r\n\r\nThe last lines for the debug log from rsyslog -dn:\r\n```\r\n8178.361110393:main Q:Reg/w0  : action 0 queue: queue.c: queue nearly full (10000 entries), but could not drop msg (iRet: 0, severity 5)\r\n8178.361112748:main Q:Reg/w0  : action 0 queue: queue.c: doEnqSingleObject: queue FULL - waiting 2000ms to drain.\r\n8178.576389721:action 0 queue:Reg/w0: ../action.c: actionDoRetry: action 0 enter loop, iRetries=1, ResumeInRow 0\r\n8178.576409932:action 0 queue:Reg/w0: omelasticsearch.c: omelasticsearch: tryResume called\r\n8178.728289646:main Q:Reg/w1  : action 0 queue: queue.c: doEnqSingleObject: cond timeout, dropping message!\r\n8178.728305722:main Q:Reg/w1  : action 0 queue: queue.c: EnqueueMsg advised worker start\r\n8178.728309791:main Q:Reg/w1  : ../action.c: action 'action 0': set suspended state to 0\r\n8178.728313462:main Q:Reg/w1  : ruleset.c: processBATCH: next msg 35: ...\r\n8178.728316502:main Q:Reg/w1  : rainerscript.c:     ACTION 0 [omelasticsearch:action(type=\"omelasticsearch\" ...)]\r\n8178.728321972:main Q:Reg/w1  : ruleset.c: executing action 0\r\n8178.728324626:main Q:Reg/w1  : ../action.c: action 'action 0': called, logging to omelasticsearch (susp 0/0, direct q 0)\r\n8178.728327857:main Q:Reg/w1  : action 0 queue: queue.c: queue nearly full (10000 entries), but could not drop msg (iRet: 0, severity 5)\r\n8178.728330224:main Q:Reg/w1  : action 0 queue: queue.c: doEnqSingleObject: queue FULL - waiting 2000ms to drain.\r\n8178.775932490:imfile.c       : strm 0x7f37ac002080: stream.c: file 5 read 0 bytes\r\n8178.775974681:imfile.c       : stream.c: stream checking for file change on '/tmp/test1.log', inode 18617/18617\r\n8178.936493320:action 0 queue:Reg/w0: omelasticsearch.c: omelasticsearch: checkConn(http://10.0.0.10:9200/) completed with success on attempt 0\r\n8178.936527317:action 0 queue:Reg/w0: ../action.c: actionDoRetry: action 0 action->tryResume returned 0\r\n8178.936534248:action 0 queue:Reg/w0: ../action.c: actionDoRetry: action 0 had success RDY again (iRet=0)\r\n8178.936542317:action 0 queue:Reg/w0: errmsg.c: Called LogMsg, msg: action 'action 0' resumed (module 'omelasticsearch')\r\n8178.936564661:action 0 queue:Reg/w0: iminternal.c: signaling new internal message via SIGTTOU: 'action 'action 0' resumed (module 'omelasticsearch') [v8.30.0 try http://www.rsyslog.com/e/2359 ]'\r\n8178.936589585:action 0 queue:Reg/w0: ../action.c: action[action 0] transitioned to state: rdy\r\n8178.936599744:action 0 queue:Reg/w0: ../action.c: action[action 0] transitioned to state: itx\r\n8178.936608069:action 0 queue:Reg/w0: ../action.c: doTransaction: action 'action 0', currIParam 1000\r\n8178.936616790:action 0 queue:Reg/w0: ../action.c: entering actionCalldoAction(), state: itx, actionNbr 0\r\n8178.936628109:action 0 queue:Reg/w0: ../action.c: doTransaction: action 0, processing msg 0, result -2122\r\n8178.936656153:action 0 queue:Reg/w0: ../action.c: entering actionCalldoAction(), state: itx, actionNbr 0\r\n8178.936681541:action 0 queue:Reg/w0: ../action.c: doTransaction: action 0, processing msg 1, result -2121\r\n8178.936693269:main thread    : janitor.c: janitorRun() called\r\n8178.936737827:action 0 queue:Reg/w0: ../action.c: entering actionCalldoAction(), state: itx, actionNbr 0\r\n```"},"comment":{"url":"https://api.github.com/repos/rsyslog/rsyslog/issues/comments/339927731","html_url":"https://github.com/rsyslog/rsyslog/issues/1906#issuecomment-339927731","issue_url":"https://api.github.com/repos/rsyslog/rsyslog/issues/1906","id":339927731,"user":{"login":"rgerhards","id":1482123,"avatar_url":"https://avatars3.githubusercontent.com/u/1482123?v=4","gravatar_id":"","url":"https://api.github.com/users/rgerhards","html_url":"https://github.com/rgerhards","followers_url":"https://api.github.com/users/rgerhards/followers","following_url":"https://api.github.com/users/rgerhards/following{/other_user}","gists_url":"https://api.github.com/users/rgerhards/gists{/gist_id}","starred_url":"https://api.github.com/users/rgerhards/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/rgerhards/subscriptions","organizations_url":"https://api.github.com/users/rgerhards/orgs","repos_url":"https://api.github.com/users/rgerhards/repos","events_url":"https://api.github.com/users/rgerhards/events{/privacy}","received_events_url":"https://api.github.com/users/rgerhards/received_events","type":"User","site_admin":false},"created_at":"2017-10-27T09:53:36Z","updated_at":"2017-10-27T09:53:36Z","author_association":"OWNER","body":"which patch did you apply? you need to have both from https://github.com/rsyslog/rsyslog/pull/1888 -- the one that references this issue only targets that specific issue, whereas the other in the PR targets another one.\r\n\r\nIf you applied both, can you please also provide a valgrind log? Thx!"}}
{"actor":{"display_login":"rgerhards"}}