{"action":"created","issue":{"url":"https://api.github.com/repos/rsyslog/rsyslog/issues/874","repository_url":"https://api.github.com/repos/rsyslog/rsyslog","labels_url":"https://api.github.com/repos/rsyslog/rsyslog/issues/874/labels{/name}","comments_url":"https://api.github.com/repos/rsyslog/rsyslog/issues/874/comments","events_url":"https://api.github.com/repos/rsyslog/rsyslog/issues/874/events","html_url":"https://github.com/rsyslog/rsyslog/issues/874","id":140150514,"number":874,"title":"imfile: multiline buffer corruption","user":{"login":"mhyllander","id":3501939,"avatar_url":"https://avatars.githubusercontent.com/u/3501939?v=3","gravatar_id":"","url":"https://api.github.com/users/mhyllander","html_url":"https://github.com/mhyllander","followers_url":"https://api.github.com/users/mhyllander/followers","following_url":"https://api.github.com/users/mhyllander/following{/other_user}","gists_url":"https://api.github.com/users/mhyllander/gists{/gist_id}","starred_url":"https://api.github.com/users/mhyllander/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/mhyllander/subscriptions","organizations_url":"https://api.github.com/users/mhyllander/orgs","repos_url":"https://api.github.com/users/mhyllander/repos","events_url":"https://api.github.com/users/mhyllander/events{/privacy}","received_events_url":"https://api.github.com/users/mhyllander/received_events","type":"User","site_admin":false},"labels":[],"state":"closed","locked":false,"assignee":null,"milestone":null,"comments":7,"created_at":"2016-03-11T10:39:19Z","updated_at":"2016-05-19T06:11:22Z","closed_at":"2016-05-19T06:11:22Z","body":"I'm testing a setup where I collect logs using rsyslog imfile and pass them to kafka. Some of the logs (~30%) are multiline. I'm seeing a problem where around 1% of the multiline logs are corrupted. The symptoms are that the first line of the multiline log message is intact, but the rest of the message is corrupt. Initially I discovered the problem because logstash was unable to parse the corrupt logs after retrieving them from kafka. I've tried to isolate the problem by saving the log messages to a local file using omfile, on the source host. The problem appears there as well, so I believe we can safely leave kafka and logstash out of the picture.\r\n\r\n**Example of good log message**\r\nOriginal log lines:\r\n```\r\n1457562691510 [E(6)] INFO  LookupClient  - UPDATE api-test.jobrstreaming.com/192.168.185.222:443 sLen:256 cLen:52\r\nConnectivityInfoUpdate(guid:2B 24 97 74 F5 EB D2 AE B4 1B 1C 01 A3 36 24 9F, gatewayType:2, publicAddress:InetAddress(address:C0 4B B2 81, port:8001), privateAddress:InetAddress(address:C0 4B B2 81, port:8001), isDialup:false, uploadBandwidth:0, justRelay:true, externalAS:8075, internalAS:0)\r\n```\r\nLog message after collection by imfile and output with omfile using a json template (I've indented the json structure to make it easier to read):\r\n```\r\n{\"@timestamp\":\"2016-03-09T22:34:41.367305+00:00\",\r\n  \"host\":\"jobr-test-euw-relay-ry1-0\",\r\n  \"type\":\"relay-service\",\r\n  \"file\":\"\\/opt\\/relay-service\\/current\\/logs\\/main.log\",\r\n  \"message\":\"1457562691510 [E(6)] INFO  LookupClient  - UPDATE api-test.jobrstreaming.com\\/192.168.185.222:443 sLen:256 cLen:52ConnectivityInfoUpdate(guid:2B 24 97 74 F5 EB D2 AE B4 1B 1C 01 A3 36 24 9F, gatewayType:2, publicAddress:InetAddress(address:C0 4B B2 81, port:8001), privateAddress:InetAddress(address:C0 4B B2 81, port:8001), isDialup:false, uploadBandwidth:0, justRelay:true, externalAS:8075, internalAS:0)\\\\n\"\r\n}\r\n```\r\n_(The newline marker `\\\\n` is misplaced, but I've reported that in a separate issue #843. It should have been placed before the second line instead of after, i.e. between `cLen:52` and `ConnectivityInfoUpdate`.)_\r\n\r\n**Example of corrupt log message**\r\nOriginal log lines:\r\n```\r\n1457569891545 [E(7)] INFO  LookupClient  - UPDATE api-test.jobrstreaming.com/192.168.185.222:443 sLen:256 cLen:52\r\nConnectivityInfoUpdate(guid:2B 24 97 74 F5 EB D2 AE B4 1B 1C 01 A3 36 24 9F, gatewayType:2, publicAddress:InetAddress(address:C0 4B B2 81, port:8001), privateAddress:InetAddress(address:C0 4B B2 81, port:8001), isDialup:false, uploadBandwidth:0, justRelay:true, externalAS:8075, internalAS:0)\r\n```\r\nOutput log message:\r\n```\r\n{\"@timestamp\":\"2016-03-10T00:31:31.548801+00:00\",\r\n  \"host\":\"jobr-test-euw-relay-ry1-0\",\r\n  \"type\":\"relay-service\",\r\n  \"file\":\"\\/opt\\/relay-service\\/current\\/logs\\/main.log\",\r\n  \"message\":\"1457569891545 [E(7)] INFO  LookupClient  - UPDATE api-test.jobrstreaming.com\\/192.168.185.222:443 sLen:256 cLen:52\\u0000\\u0000\\u0000\\u0000\\u0000\\u0000\\u0000q\\u0001\\u0000\\u0000\\u0000\\u0000\\u0000\\u0000 \\u0001\\u0000D\\u0013\\u0000\\u0000 \\u0001\\u0000D\\u0013\\u0000\\u0000(7)] DEBUG WebClient  - LOOKUP REQ: https:\\/\\/api-test.jobrstreaming.com:443\\/v1\\/lookup\\/2b249774f5ebd2aeb41b1c01a33X\\u0001\\u0000D\\u0013\\u0000\\u0000 \\u0000\\u0000\\u0000\\u0000\\u0000\\u0000\\u0000H\\u0001\\u0000D\\u0013\\u0000\\u0000H\\u0001\\u0000D\\u0013\\u0000\\u0000pClient  - UPDATE api-test.jobrstreaming.com\\/192.168.185.222:443 sLen:256 cLen:52\\u00002aeb41b1c01a33 \\u0000\\u0000\\u0000\\u0000\\u0000\\u0000\\u0000d\\u0000\\u0000\\u0000\\u0000\\u0000\\u0000\\u0000\\u0010 \\u0001D\\u0013\\u0000\"\r\n}\r\n```\r\nAs you can see, everything after the first line of the message (after `cLen:52`) is corrupt. This is true for all corrupted log messages. You can also see bits and pieces of other log lines in the corrupt data. (In one case I could see the beginning of the next log line from the file in the middle of the corrupt data.)\r\n\r\nAs I mentioned, this happens in about 1% of the multiline log messages. Single-line log messages are unaffected. I ran the system for a couple of days and got 28 corrupted log messages out of a total of 2980 multiline log messages.\r\n\r\nI'm running this on Ubuntu 14.04.1, using rsyslog (and rsyslog-kafka) version 8.16.0-0adiscon1trusty1 from the http://ppa.launchpad.net/adiscon/v8-stable/ubuntu repository. Below is the configuration I used:\r\n\r\n```\r\nmodule(load=\"imfile\")\r\n\r\nmain_queue(\r\n  queue.workerthreads=\"1\"      # threads to work on the queue\r\n  queue.dequeueBatchSize=\"100\" # max number of messages to process at once\r\n  queue.size=\"10000\"           # max queue size\r\n)\r\n\r\ntemplate(name=\"debug_json\" type=\"list\") {\r\n  constant(value=\"{\")\r\n  constant(value=\"\\\"@timestamp\\\":\\\"\")\r\n  property(name=\"timereported\" dateFormat=\"rfc3339\" format=\"json\")\r\n  constant(value=\"\\\",\\\"host\\\":\\\"\")\r\n  property(name=\"hostname\" format=\"json\")\r\n  constant(value=\"\\\",\\\"type\\\":\\\"\")\r\n  property(name=\"syslogtag\" format=\"json\")\r\n  constant(value=\"\\\",\\\"file\\\":\\\"\")\r\n  property(name=\"$!metadata!filename\" format=\"json\")\r\n  constant(value=\"\\\",\\\"message\\\":\\\"\")\r\n  property(name=\"msg\" format=\"json\")\r\n  constant(value=\"\\\"}\\n\")\r\n}\r\n\r\nruleset(name=\"kafka_logstash_debug\") {\r\n  action(\r\n    type=\"omfile\"\r\n    file=\"/mnt/relay.log\"\r\n    template=\"debug_json\"\r\n  )\r\n  stop\r\n}\r\n\r\n$RepeatedMsgReduction off\r\ninput(type=\"imfile\"\r\n  file=\"/opt/relay-service/current/logs/main.log\"\r\n  tag=\"relay-service\"\r\n  PersistStateInterval=\"100\"\r\n  startmsg.regex=\"^[0-9]{13} \"\r\n  addMetaData=\"on\"\r\n  ruleset=\"kafka_logstash_debug\"\r\n)\r\n$RepeatedMsgReduction on\r\n```"},"comment":{"url":"https://api.github.com/repos/rsyslog/rsyslog/issues/comments/220236212","html_url":"https://github.com/rsyslog/rsyslog/issues/874#issuecomment-220236212","issue_url":"https://api.github.com/repos/rsyslog/rsyslog/issues/874","id":220236212,"user":{"login":"rgerhards","id":1482123,"avatar_url":"https://avatars.githubusercontent.com/u/1482123?v=3","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":"2016-05-19T06:11:22Z","updated_at":"2016-05-19T06:11:22Z","body":"fixed via #1042 "}}