{"action":"created","issue":{"url":"https://api.github.com/repos/WPO-Foundation/webpagetest/issues/1114","repository_url":"https://api.github.com/repos/WPO-Foundation/webpagetest","labels_url":"https://api.github.com/repos/WPO-Foundation/webpagetest/issues/1114/labels{/name}","comments_url":"https://api.github.com/repos/WPO-Foundation/webpagetest/issues/1114/comments","events_url":"https://api.github.com/repos/WPO-Foundation/webpagetest/issues/1114/events","html_url":"https://github.com/WPO-Foundation/webpagetest/issues/1114","id":300676842,"number":1114,"title":"EC2 instances terminated while test is running","user":{"login":"mkreidenweis","id":250584,"avatar_url":"https://avatars3.githubusercontent.com/u/250584?v=4","gravatar_id":"","url":"https://api.github.com/users/mkreidenweis","html_url":"https://github.com/mkreidenweis","followers_url":"https://api.github.com/users/mkreidenweis/followers","following_url":"https://api.github.com/users/mkreidenweis/following{/other_user}","gists_url":"https://api.github.com/users/mkreidenweis/gists{/gist_id}","starred_url":"https://api.github.com/users/mkreidenweis/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/mkreidenweis/subscriptions","organizations_url":"https://api.github.com/users/mkreidenweis/orgs","repos_url":"https://api.github.com/users/mkreidenweis/repos","events_url":"https://api.github.com/users/mkreidenweis/events{/privacy}","received_events_url":"https://api.github.com/users/mkreidenweis/received_events","type":"User","site_admin":false},"labels":[],"state":"closed","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":11,"created_at":"2018-02-27T15:30:15Z","updated_at":"2018-03-05T14:48:34Z","closed_at":"2018-03-05T14:48:34Z","author_association":"NONE","body":"Hi Pat, \r\n\r\nyou already mentioned this issue at SmashingConf in London, but I couldn't find a Github issue for it, so I'm opening one here: \r\n\r\nWe're running the provided AMI which automatically launches test agents. However, regularly test agents are being terminated while a test is still running on there. For example look at this `test.log`:\r\n```\r\n2018/02/27 06:17:10 - Test Created\r\n2018/02/27 06:35:25 - Starting test (initiated by tester i-01cf3db507534ac23)\r\n2018/02/27 06:36:20 - Test Run Complete. Run: 1, Cached: 0, Done: , Tester: i-01cf3db507534ac23\r\n2018/02/27 06:36:20 - Extracting 799545 byte uploaded file '/tmp/php6blpLh' to './results/18/02/27/8V/8Q'\r\n2018/02/27 06:36:20 - Done Processing. Run: 1, Cached: 0, Done: , Tester: i-01cf3db507534ac23\r\n2018/02/27 06:37:08 - Test Run Complete. Run: 1, Cached: 1, Done: , Tester: i-01cf3db507534ac23\r\n2018/02/27 06:37:08 - Extracting 1064700 byte uploaded file '/tmp/phpWbqCOs' to './results/18/02/27/8V/8Q'\r\n2018/02/27 06:37:08 - Done Processing. Run: 1, Cached: 1, Done: , Tester: i-01cf3db507534ac23\r\n2018/02/27 06:38:03 - Test Run Complete. Run: 2, Cached: 0, Done: , Tester: i-01cf3db507534ac23\r\n2018/02/27 06:38:03 - Extracting 859846 byte uploaded file '/tmp/phpuDxVrn' to './results/18/02/27/8V/8Q'\r\n2018/02/27 06:38:04 - Done Processing. Run: 2, Cached: 0, Done: , Tester: i-01cf3db507534ac23\r\n2018/02/27 06:38:48 - Test Run Complete. Run: 2, Cached: 1, Done: , Tester: i-01cf3db507534ac23\r\n2018/02/27 06:38:48 - Extracting 750702 byte uploaded file '/tmp/phpchoP8X' to './results/18/02/27/8V/8Q'\r\n2018/02/27 06:38:49 - Done Processing. Run: 2, Cached: 1, Done: , Tester: i-01cf3db507534ac23\r\n2018/02/27 06:39:40 - Test Run Complete. Run: 3, Cached: 0, Done: , Tester: i-01cf3db507534ac23\r\n2018/02/27 06:39:40 - Extracting 819225 byte uploaded file '/tmp/phpcCCDEF' to './results/18/02/27/8V/8Q'\r\n2018/02/27 06:39:40 - Done Processing. Run: 3, Cached: 0, Done: , Tester: i-01cf3db507534ac23\r\n2018/02/27 06:51:42 - Test has been running for 16 minutes and it has been 12.033333333333 since the last update, forcing the full test to finish.\r\n```\r\n\r\nThe last repeat run never returns. In `ec2.log.20180227` I can find the following entries referencing this tester instance: \r\n```\r\n06:20:15 - Instance i-01cf3db507534ac23 started: m3.medium ami ami-87f2ebeb in eu-central-1 for eu-central-1,eu-central-1_IE11 with user data: wpt_server=[censored] wpt_loc=eu-central-1,eu-central-1_IE11 wpt_key=[censored]\r\n06:40:13 - Terminated instance i-01cf3db507534ac23 in eu-central-1\r\n```\r\n\r\nThis config in `settings.ini` might be relevant: \r\n```\r\n    EC2.ScaleFactor=2\r\n    EC2.max=8\r\n    max_run_minutes=12\r\n    maxtime=480\r\n```\r\nWe did *not* set `EC2.IdleTerminateMinutes`, thinking a 15 minute default should be fine.\r\n\r\nThe most annoying side effect of this behavior actually is that `jsonResult.php` returns an error 500 when checking for the test status. See this excerpt from the nginx access log:\r\n```\r\n35.189.195.204 - - [27/Feb/2018:06:50:41 +0000] \"GET /jsonResult.php?test=180227_8V_8Q HTTP/1.1\" 200 486 \"-\" \"-\"\r\n35.189.195.204 - - [27/Feb/2018:06:50:51 +0000] \"GET /jsonResult.php?test=180227_8V_8Q HTTP/1.1\" 200 485 \"-\" \"-\"\r\n35.189.195.204 - - [27/Feb/2018:06:51:01 +0000] \"GET /jsonResult.php?test=180227_8V_8Q HTTP/1.1\" 200 483 \"-\" \"-\"\r\n35.189.195.204 - - [27/Feb/2018:06:51:11 +0000] \"GET /jsonResult.php?test=180227_8V_8Q HTTP/1.1\" 200 487 \"-\" \"-\"\r\n35.189.195.204 - - [27/Feb/2018:06:51:22 +0000] \"GET /jsonResult.php?test=180227_8V_8Q HTTP/1.1\" 200 482 \"-\" \"-\"\r\n35.189.195.204 - - [27/Feb/2018:06:51:32 +0000] \"GET /jsonResult.php?test=180227_8V_8Q HTTP/1.1\" 200 485 \"-\" \"-\"\r\n35.189.195.204 - - [27/Feb/2018:06:51:42 +0000] \"GET /jsonResult.php?test=180227_8V_8Q HTTP/1.1\" 500 5 \"-\" \"-\"\r\n```\r\nThis causes the sitespeed.io job to crash (`ERROR: Error creating WebPageTest result {\"name\":\"WPTAPIError\",\"code\":500,\"message\":\"Internal Server Error\"}`).\r\nMaybe it's because the test is never seen \"done\" in `workdone.php` and thus `postprocess.php` is never called there and then some ad-hoc post-processing happens which leads to an error. \r\nAny subsequent requests to the same `/jsonResult.php?test=180227_8V_8Q` URL actually succeed though. So I cannot really reproduce this error unfortunately. It doesn't show up in any nginx or php error log either. \r\n\r\nIs there any way we can help getting this fixed?\r\n\r\nBest regards, \r\nMartin"},"comment":{"url":"https://api.github.com/repos/WPO-Foundation/webpagetest/issues/comments/370442337","html_url":"https://github.com/WPO-Foundation/webpagetest/issues/1114#issuecomment-370442337","issue_url":"https://api.github.com/repos/WPO-Foundation/webpagetest/issues/1114","id":370442337,"user":{"login":"mkreidenweis","id":250584,"avatar_url":"https://avatars3.githubusercontent.com/u/250584?v=4","gravatar_id":"","url":"https://api.github.com/users/mkreidenweis","html_url":"https://github.com/mkreidenweis","followers_url":"https://api.github.com/users/mkreidenweis/followers","following_url":"https://api.github.com/users/mkreidenweis/following{/other_user}","gists_url":"https://api.github.com/users/mkreidenweis/gists{/gist_id}","starred_url":"https://api.github.com/users/mkreidenweis/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/mkreidenweis/subscriptions","organizations_url":"https://api.github.com/users/mkreidenweis/orgs","repos_url":"https://api.github.com/users/mkreidenweis/repos","events_url":"https://api.github.com/users/mkreidenweis/events{/privacy}","received_events_url":"https://api.github.com/users/mkreidenweis/received_events","type":"User","site_admin":false},"created_at":"2018-03-05T14:48:34Z","updated_at":"2018-03-05T14:48:34Z","author_association":"NONE","body":"@abarre Actually we didn't change anything about `ec2_locations.ini` IIRC. The `[locations]` section contains all numbers between 1 and 30 for us. \r\n\r\nRegular 500 errors are gone for us. Last one of them happened on `28/Feb/2018:16:57:49 +0000`. (Not sure how often the autoupdate for WPT runs.)\r\nSo I'd consider this bug fixed and am closing this issue now, okay?\r\n\r\nThank you @pmeenan for addressing this so quickly. :-)"}}
{"actor":{"display_login":"mkreidenweis"}}