{"action":"created","issue":{"url":"https://api.github.com/repos/joyent/containerpilot/issues/548","repository_url":"https://api.github.com/repos/joyent/containerpilot","labels_url":"https://api.github.com/repos/joyent/containerpilot/issues/548/labels{/name}","comments_url":"https://api.github.com/repos/joyent/containerpilot/issues/548/comments","events_url":"https://api.github.com/repos/joyent/containerpilot/issues/548/events","html_url":"https://github.com/joyent/containerpilot/issues/548","id":298691287,"number":548,"title":"Full event bus causing job timeouts.","user":{"login":"eliasbrange","id":8293016,"avatar_url":"https://avatars2.githubusercontent.com/u/8293016?v=4","gravatar_id":"","url":"https://api.github.com/users/eliasbrange","html_url":"https://github.com/eliasbrange","followers_url":"https://api.github.com/users/eliasbrange/followers","following_url":"https://api.github.com/users/eliasbrange/following{/other_user}","gists_url":"https://api.github.com/users/eliasbrange/gists{/gist_id}","starred_url":"https://api.github.com/users/eliasbrange/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/eliasbrange/subscriptions","organizations_url":"https://api.github.com/users/eliasbrange/orgs","repos_url":"https://api.github.com/users/eliasbrange/repos","events_url":"https://api.github.com/users/eliasbrange/events{/privacy}","received_events_url":"https://api.github.com/users/eliasbrange/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":2,"created_at":"2018-02-20T17:59:34Z","updated_at":"2018-02-20T21:00:48Z","closed_at":null,"author_association":"NONE","body":"## Background\r\n\r\nWe have uncovered what might be a bug with the job event bus getting overflowed when running jobs on an interval. In our case, we have scripts running on 30s intervals over a long period. Over time as data has flowed into the system these scripts have sometimes taken longer than the interval time to execute which we countered by setting a timeout that is greater than the interval time. We have multiple containers with different job configurations and we have seen that after a varying amount of time (usually a couple of hours) the jobs start to always timeout even though it seems that they are successfully executed. This makes e.g. containerpilot marking health checks as failed even though the health check command actually succeeded.\r\n\r\n## Containerpilot version\r\n\r\n`3.6.1`\r\n\r\n## Problem location\r\n\r\nWe think we have pinpointed the problem to https://github.com/joyent/containerpilot/blob/7208e025644e9d9b0ca06d26ee97a4c612af7788/commands/commands.go#L158 where somehow the event never gets published. Containerpilot waits for that line to finish execution within the configured deadline which does not happen, and the Context and thus the job \"times out\".\r\n\r\n## Reproduciton\r\n\r\nTo reproduce the problem I have created a rather extreme and unrealistic configuration to encounter the problem quickly. Instead of a job taking between 20-40 seconds that runs every 30th second I have a job taking 10 seconds running every 10th millisecond.\r\n\r\n`containerpilot.json5`:\r\n\r\n```\r\n{\r\n  consul: \"consul:8500\",\r\n  logging: {\r\n    level: \"DEBUG\",\r\n    format: \"default\",\r\n    output: \"stdout\"\r\n  },\r\n  jobs: [\r\n    {\r\n      name: \"test\",\r\n      restarts: \"unlimited\",\r\n      port: 80,\r\n      health: {\r\n        exec: \"/test.py\",\r\n        interval: 20,\r\n        ttl: 20,\r\n        timeout: \"20s\",\r\n      },\r\n    },\r\n    {\r\n      name: \"interval\",\r\n      restarts: \"unlimited\",\r\n      exec: [\"/test.py\"],\r\n      timeout: \"20s\",\r\n      when: {\r\n        interval: \"10ms\"\r\n      }\r\n    },\r\n  ],\r\n  control: {\r\n    socket: \"/var/run/containerpilot.socket\"\r\n  }\r\n}\r\n\r\n```\r\n\r\n`test.py`:\r\n```\r\n#!/usr/bin/env python3\r\nimport time\r\nimport sys\r\nimport logging\r\n\r\n\r\nlogger = logging.getLogger(__name__)\r\n\r\n\r\ndef _setup_logging(logger, loglevel=logging.INFO):\r\n    root = logging.getLogger()\r\n    root.setLevel(loglevel)\r\n\r\n    formatter = logging.Formatter('%(asctime)s - %(levelname)s - %(message)s')\r\n    handler = logging.StreamHandler()\r\n    handler.setFormatter(formatter)\r\n\r\n    logger.addHandler(handler)\r\n\r\n\r\ndef main():\r\n    logger.warn('FUNNY OUTPUT')\r\n    time.sleep(10)\r\n    sys.exit(0)\r\n\r\n\r\nif __name__ == '__main__':\r\n    sys.exit(main())\r\n```\r\n\r\nOn my machine the above starts encountering the problem in about 10-15 seconds with the following logs when trying to run the health check and interval job.\r\n\r\n```\r\n2018-02-20T18:26:42.77342415+01:00 interval.Run start\r\n2018-02-20T18:26:42.773593279+01:00 timer: {TimerExpired interval.run-every}\r\n2018-02-20T18:26:42.864558348+01:00 FUNNY OUTPUT\r\n2018-02-20T18:26:52.901450783+01:00 interval exited without error\r\n2018-02-20T18:27:02.77381208+01:00 interval timeout after 20s: '[]'\r\n2018-02-20T18:27:02.773881327+01:00 interval.kill\r\n2018-02-20T18:27:02.773908902+01:00 killing command 'interval' at pid: 60\r\n\r\n2018-02-20T18:28:22.80610908+01:00 check.test.Run start\r\n2018-02-20T18:28:22.847114529+01:00 FUNNY OUTPUT\r\n2018-02-20T18:28:32.88316921+01:00 check.test exited without error\r\n2018-02-20T18:28:42.757582579+01:00 timer: {TimerExpired test.heartbeat}\r\n2018-02-20T18:28:42.806392321+01:00 check.test timeout after 20s: '[]'\r\n2018-02-20T18:28:42.806441683+01:00 check.test.kill\r\n2018-02-20T18:28:42.806461393+01:00 killing command 'check.test' at pid: 71\r\n```\r\n\r\nThe logs clearly shows that the jobs actually executes due to the \"FUNNY OUTPUT\" and \"* exited without error.\" However, the events are never sent which can be seen by the missing `event: {ExitSuccess interval}` and `event: {ExitSuccess check.test}` log entries. Those logs should be the last thing happening before the job finishes.\r\n\r\n## Workaround\r\n\r\nWhile it might be unclever to have interval jobs on a shorter interval than the actual execution time, it can be hard to decide a appropriate interval time on a job with varying execution time. We think we have found a workaround by using regular jobs with `restarts: unlimited\" with sleeps included in the scripts instead of utilizing the interval functionality.\r\n"},"comment":{"url":"https://api.github.com/repos/joyent/containerpilot/issues/comments/367117631","html_url":"https://github.com/joyent/containerpilot/issues/548#issuecomment-367117631","issue_url":"https://api.github.com/repos/joyent/containerpilot/issues/548","id":367117631,"user":{"login":"eliasbrange","id":8293016,"avatar_url":"https://avatars2.githubusercontent.com/u/8293016?v=4","gravatar_id":"","url":"https://api.github.com/users/eliasbrange","html_url":"https://github.com/eliasbrange","followers_url":"https://api.github.com/users/eliasbrange/followers","following_url":"https://api.github.com/users/eliasbrange/following{/other_user}","gists_url":"https://api.github.com/users/eliasbrange/gists{/gist_id}","starred_url":"https://api.github.com/users/eliasbrange/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/eliasbrange/subscriptions","organizations_url":"https://api.github.com/users/eliasbrange/orgs","repos_url":"https://api.github.com/users/eliasbrange/repos","events_url":"https://api.github.com/users/eliasbrange/events{/privacy}","received_events_url":"https://api.github.com/users/eliasbrange/received_events","type":"User","site_admin":false},"created_at":"2018-02-20T21:00:48Z","updated_at":"2018-02-20T21:00:48Z","author_association":"NONE","body":"Looking at the subscribers for a certain bus the two jobs seems to been subscribed to each other, which means that the `events.ExitSuccess` of the health check command is tried to be received by the interval job, which has a full event queue, which in turn makes the health check command \"time out\". So one job with a full event queue will hinder execution of other jobs."}}
{"actor":{"display_login":"eliasbrange"}}