{"action":"created","issue":{"url":"https://api.github.com/repos/Metaswitch/clearwater-infrastructure/issues/391","repository_url":"https://api.github.com/repos/Metaswitch/clearwater-infrastructure","labels_url":"https://api.github.com/repos/Metaswitch/clearwater-infrastructure/issues/391/labels{/name}","comments_url":"https://api.github.com/repos/Metaswitch/clearwater-infrastructure/issues/391/comments","events_url":"https://api.github.com/repos/Metaswitch/clearwater-infrastructure/issues/391/events","html_url":"https://github.com/Metaswitch/clearwater-infrastructure/issues/391","id":185088083,"number":391,"title":"Poll processes can end up being unmonitored because of issue alarm failures","user":{"login":"eleanor-merry","id":5425325,"avatar_url":"https://avatars.githubusercontent.com/u/5425325?v=3","gravatar_id":"","url":"https://api.github.com/users/eleanor-merry","html_url":"https://github.com/eleanor-merry","followers_url":"https://api.github.com/users/eleanor-merry/followers","following_url":"https://api.github.com/users/eleanor-merry/following{/other_user}","gists_url":"https://api.github.com/users/eleanor-merry/gists{/gist_id}","starred_url":"https://api.github.com/users/eleanor-merry/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/eleanor-merry/subscriptions","organizations_url":"https://api.github.com/users/eleanor-merry/orgs","repos_url":"https://api.github.com/users/eleanor-merry/repos","events_url":"https://api.github.com/users/eleanor-merry/events{/privacy}","received_events_url":"https://api.github.com/users/eleanor-merry/received_events","type":"User","site_admin":false},"labels":[{"id":38604158,"url":"https://api.github.com/repos/Metaswitch/clearwater-infrastructure/labels/bug","name":"bug","color":"fc2929","default":true},{"id":173606828,"url":"https://api.github.com/repos/Metaswitch/clearwater-infrastructure/labels/cat:diagnostics","name":"cat:diagnostics","color":"0052cc","default":false},{"id":173606872,"url":"https://api.github.com/repos/Metaswitch/clearwater-infrastructure/labels/cat:stability","name":"cat:stability","color":"009800","default":false},{"id":241894696,"url":"https://api.github.com/repos/Metaswitch/clearwater-infrastructure/labels/critical","name":"critical","color":"ff0000","default":false},{"id":90665951,"url":"https://api.github.com/repos/Metaswitch/clearwater-infrastructure/labels/medium-priority","name":"medium-priority","color":"eb6420","default":false}],"state":"open","locked":false,"assignee":{"login":"mirw","id":2963879,"avatar_url":"https://avatars.githubusercontent.com/u/2963879?v=3","gravatar_id":"","url":"https://api.github.com/users/mirw","html_url":"https://github.com/mirw","followers_url":"https://api.github.com/users/mirw/followers","following_url":"https://api.github.com/users/mirw/following{/other_user}","gists_url":"https://api.github.com/users/mirw/gists{/gist_id}","starred_url":"https://api.github.com/users/mirw/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/mirw/subscriptions","organizations_url":"https://api.github.com/users/mirw/orgs","repos_url":"https://api.github.com/users/mirw/repos","events_url":"https://api.github.com/users/mirw/events{/privacy}","received_events_url":"https://api.github.com/users/mirw/received_events","type":"User","site_admin":false},"assignees":[{"login":"mirw","id":2963879,"avatar_url":"https://avatars.githubusercontent.com/u/2963879?v=3","gravatar_id":"","url":"https://api.github.com/users/mirw","html_url":"https://github.com/mirw","followers_url":"https://api.github.com/users/mirw/followers","following_url":"https://api.github.com/users/mirw/following{/other_user}","gists_url":"https://api.github.com/users/mirw/gists{/gist_id}","starred_url":"https://api.github.com/users/mirw/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/mirw/subscriptions","organizations_url":"https://api.github.com/users/mirw/orgs","repos_url":"https://api.github.com/users/mirw/repos","events_url":"https://api.github.com/users/mirw/events{/privacy}","received_events_url":"https://api.github.com/users/mirw/received_events","type":"User","site_admin":false}],"milestone":null,"comments":2,"created_at":"2016-10-25T11:20:32Z","updated_at":"2016-12-13T14:42:53Z","closed_at":null,"body":"<!--\nThis page is for reporting issues with Project Clearwater. If you have a question, rather than a bug report, the mailing list at clearwater@lists.projectclearwater.org is a better place for it.\n\nTo give us the best chance of fixing the problem, we've suggested some information to give - please follow these guidelines if possible.\n\nDon't forget that you can attach logs and screenshots to Github issues - this may help us debug a problem.\n-->\n#### Symptoms\n\nI started the AIO OVF. Running `sudo monit summary` showed me that the `poll_homestead` and `homestead_uptime` programs were `Not monitored` (everything else was running fine).\n\nLooking in \\var\\log\\monit.log there was the message\n\n```\n'homestead_process' failed to restart (exit status 0) -- /bin/bash: zmq_msg_recv: Resource temporarily unavailable\n```\n\nThis comes from the issue-alarm script being unable to contact the alarm agent (as it's not installed on an AIO node by default). I think what's going wrong here is that monit views the restart command to have failed, so it doesn't remonitor the dependent programs. Homestead is running successfully though - so it never tries to restart Homestead again and so doesn't ever remonitor the programs.\n\nWe also see spammy log messages, e.g. `zmq_msg_recv: Resource temporarily unavailable`, which look worrying.\n#### Impact\n\nIf the poll programs aren't running, then we're less reliable as we can't recover from some error cases. If the uptime programs aren't running then the process failed alarm is never cleared. The log spam makes it harder to diagnose issues.\n\n<!-- What is this preventing you from doing? Does this stop Clearwater working, or stop some calls being processed? -->\n#### Release and environment\n\nThe Quilava release\n"},"comment":{"url":"https://api.github.com/repos/Metaswitch/clearwater-infrastructure/issues/comments/266755812","html_url":"https://github.com/Metaswitch/clearwater-infrastructure/issues/391#issuecomment-266755812","issue_url":"https://api.github.com/repos/Metaswitch/clearwater-infrastructure/issues/391","id":266755812,"user":{"login":"mirw","id":2963879,"avatar_url":"https://avatars.githubusercontent.com/u/2963879?v=3","gravatar_id":"","url":"https://api.github.com/users/mirw","html_url":"https://github.com/mirw","followers_url":"https://api.github.com/users/mirw/followers","following_url":"https://api.github.com/users/mirw/following{/other_user}","gists_url":"https://api.github.com/users/mirw/gists{/gist_id}","starred_url":"https://api.github.com/users/mirw/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/mirw/subscriptions","organizations_url":"https://api.github.com/users/mirw/orgs","repos_url":"https://api.github.com/users/mirw/repos","events_url":"https://api.github.com/users/mirw/events{/privacy}","received_events_url":"https://api.github.com/users/mirw/received_events","type":"User","site_admin":false},"created_at":"2016-12-13T14:42:53Z","updated_at":"2016-12-13T14:42:53Z","body":"I've done a bit of testing, and it actually looks as though the `issue-alarm` script always returns success, so monit can't have decided that the homestead process was failed due to `issue-alarm` failing.\r\n\r\nI have, however, reviewed the code:\r\n\r\n```\r\n                if (status < 0 || (s->type == Service_Process && _waitProcessStart(s, &timeout) != Process_Started)) {\r\n                        rv = false;\r\n                        Event_post(s, Event_Exec, State_Failed, s->action_EXEC, \"failed to restart (exit status %d) -- %s\", status, msg);\r\n                } else {\r\n                        Event_post(s, Event_Exec, State_Succeeded, s->action_EXEC, \"restarted\");\r\n                }\r\n```\r\n\r\nand also reproduced the issue, e.g. with the following logs:\r\n\r\n```\r\n[UTC Dec 13 14:23:35] error    : 'astaire_process' process is not running\r\n[UTC Dec 13 14:23:35] info     : 'astaire_process' trying to restart\r\n[UTC Dec 13 14:23:35] info     : 'astaire_process' restart: /bin/bash\r\n[UTC Dec 13 14:24:03] error    : 'astaire_process' failed to restart (exit status 0) -- /bin/bash: zmq_msg_recv: Resource temporarily unavailable\r\n```\r\n\r\nNote that given that the status is 0, the only way we could get this log is if the service is a process (it is) and `_waitProcessStart` doesn't return `Process_Started`.  Looking at the code of `_waitProcessStart`, the only alternative to `Process_Started` is `Process_Stopped` and this is returned either if the process stops running or if the restart job times out returning.  Given the timing we see in the logs above (~28s), my guess is that it is timing out - certainly this is a very long time for it to take.\r\n\r\nNext step is to investigate why a restart job would take so long to complete.\r\n\r\nNote that in my testing, the process itself would generally keep trying to restart and would eventually succeed (at which point its dependent processes would wake up too).  The one exception seemed to be if monit was kicked to re-read its configuration - in this case, it seems monit would sometimes realize that the process itself was running (and not restart it again), but then also not wake up its dependent processes.  We might need to fix that separately, because even if we reduce the time a restart job takes to complete, it feels like there might still be a race condition here."}}
{"actor":{"display_login":"mirw"}}