{"action":"created","issue":{"url":"https://api.github.com/repos/mozilla-services/heka/issues/1561","labels_url":"https://api.github.com/repos/mozilla-services/heka/issues/1561/labels{/name}","comments_url":"https://api.github.com/repos/mozilla-services/heka/issues/1561/comments","events_url":"https://api.github.com/repos/mozilla-services/heka/issues/1561/events","html_url":"https://github.com/mozilla-services/heka/issues/1561","id":85557679,"number":1561,"title":"ProcessInput silently stops Processing Input","user":{"login":"hynd","id":1405193,"avatar_url":"https://avatars.githubusercontent.com/u/1405193?v=3","gravatar_id":"","url":"https://api.github.com/users/hynd","html_url":"https://github.com/hynd","followers_url":"https://api.github.com/users/hynd/followers","following_url":"https://api.github.com/users/hynd/following{/other_user}","gists_url":"https://api.github.com/users/hynd/gists{/gist_id}","starred_url":"https://api.github.com/users/hynd/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/hynd/subscriptions","organizations_url":"https://api.github.com/users/hynd/orgs","repos_url":"https://api.github.com/users/hynd/repos","events_url":"https://api.github.com/users/hynd/events{/privacy}","received_events_url":"https://api.github.com/users/hynd/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":4,"created_at":"2015-06-05T15:21:29Z","updated_at":"2015-06-13T08:04:19Z","closed_at":null,"body":"I'm encountering a super-weird bug with ProcessInput's.  Not particularly easy to repro, but i think now i know why...\r\n\r\nThe symptoms are the Heka ProcessInput plugin gets into a weird state where doesn't appear to be reading input (and doesn't exit), but the spawned cmd stays running.  I see the same behaviour from version 0.9.0 to 0.10/dev.\r\n\r\nNot all ProcessInput-fired cmd's trigger the behaviour, just those that have particular output characteristics - those that end up splitting the output into multiple `write(2)` calls where a record's content is broken across them.  (Linux buffers processes stdout by default when it's hooked up to a pipe - it's possible to manipulate that in various ways, but that gets a little clunky and the buffering's for a reason).\r\n\r\nThe following Heka .toml and Python generates batches of data >4KB (which should get split into multiple write()s) hopefully reproduces the problem...  I say \"hopefully\", because this only seems to happen on boxes that are busy (my dev/test boxes don't hit it so frequently) - sometimes the ProcessInput stops producing data immediately, sometimes after just a couple of `ticker_intervals`.  Turns out strace'ing the Python after Heka spawns it was a fairly consistent way to trigger it.  I guess both the extra load or strace increases the delay between write()s...\r\n\r\n```toml\r\n[ProcessInput]\r\nstdout = true\r\nstderr = false\r\nsplitter = \"TokenSplitter\"\r\nticker_interval = 0\r\n\r\n[ProcessInput.command.0]\r\nbin = \"/path/to/test.py\"\r\n\r\n[PayloadEncoder]\r\nappend_newlines = false\r\n\r\n[LogOutput]\r\nencoder = \"PayloadEncoder\"\r\nmessage_matcher = \"TRUE\"\r\n```\r\n\r\n```python\r\n#!/usr/bin/python\r\nimport sys\r\nimport time\r\n\r\nwhile True:\r\n    for i in xrange(50):\r\n      print \"x\"*128\r\n    sys.stdout.flush()\r\n    time.sleep(5)\r\n```\r\n\r\nI think this happens because for whatever reason (seems like some kind of synchronisation between the underlying Pipe buf being filled and Read), the sRunner buf isn't quite populated with enough data from multiple write()s when [GetRecordFromStream hands it to FindRecord](https://github.com/mozilla-services/heka/blob/272ce8fbe2c33d07bf8e315ff297900d0af80b7d/pipeline/splitter_runner.go#L207).  FindRecord doesn't see a delimiter and returns a 0-length record (even though we're not EOF, it'll likely be in the buf next time it's read()).  GetRecordFromStream itself returns with a record length of 0, [SplitStream traps that and break's](https://github.com/mozilla-services/heka/blob/272ce8fbe2c33d07bf8e315ff297900d0af80b7d/pipeline/splitter_runner.go#L340).  That in turn causes the [ProcessInput's ParseOutput](https://github.com/mozilla-services/heka/blob/272ce8fbe2c33d07bf8e315ff297900d0af80b7d/plugins/process/process_input.go#L346) goroutine to end.  With nothing draining their stdout, the ProcessInput-spawned cmd's end up blocking on write()s when the pipe buffer fills.\r\n\r\nI'm not familiar enough with the other Inputs and how they interact with Splitters to know the best way of tackling this.  TcpInput's also capable of sending 0-length records when its SetReadDeadline fires, but it doesn't seem to trigger the same behaviour because that's caught as an err :("},"comment":{"url":"https://api.github.com/repos/mozilla-services/heka/issues/comments/111685939","html_url":"https://github.com/mozilla-services/heka/issues/1561#issuecomment-111685939","issue_url":"https://api.github.com/repos/mozilla-services/heka/issues/1561","id":111685939,"user":{"login":"hynd","id":1405193,"avatar_url":"https://avatars.githubusercontent.com/u/1405193?v=3","gravatar_id":"","url":"https://api.github.com/users/hynd","html_url":"https://github.com/hynd","followers_url":"https://api.github.com/users/hynd/followers","following_url":"https://api.github.com/users/hynd/following{/other_user}","gists_url":"https://api.github.com/users/hynd/gists{/gist_id}","starred_url":"https://api.github.com/users/hynd/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/hynd/subscriptions","organizations_url":"https://api.github.com/users/hynd/orgs","repos_url":"https://api.github.com/users/hynd/repos","events_url":"https://api.github.com/users/hynd/events{/privacy}","received_events_url":"https://api.github.com/users/hynd/received_events","type":"User","site_admin":false},"created_at":"2015-06-13T08:04:19Z","updated_at":"2015-06-13T08:04:19Z","body":"The tweak in PR #1572 (Travis is failing, though it seems unrelated?) seemed to fix it for me.  I was a little worried that it might affect other plugins like TcpInput (though that seems to work OK too)..."}}