{"action":"created","issue":{"url":"https://api.github.com/repos/Bioconductor/packagebuilder/issues/31","labels_url":"https://api.github.com/repos/Bioconductor/packagebuilder/issues/31/labels{/name}","comments_url":"https://api.github.com/repos/Bioconductor/packagebuilder/issues/31/comments","events_url":"https://api.github.com/repos/Bioconductor/packagebuilder/issues/31/events","html_url":"https://github.com/Bioconductor/packagebuilder/issues/31","id":123368284,"number":31,"title":"SPB builds are failing","user":{"login":"b-long","id":66993,"avatar_url":"https://avatars.githubusercontent.com/u/66993?v=3","gravatar_id":"","url":"https://api.github.com/users/b-long","html_url":"https://github.com/b-long","followers_url":"https://api.github.com/users/b-long/followers","following_url":"https://api.github.com/users/b-long/following{/other_user}","gists_url":"https://api.github.com/users/b-long/gists{/gist_id}","starred_url":"https://api.github.com/users/b-long/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/b-long/subscriptions","organizations_url":"https://api.github.com/users/b-long/orgs","repos_url":"https://api.github.com/users/b-long/repos","events_url":"https://api.github.com/users/b-long/events{/privacy}","received_events_url":"https://api.github.com/users/b-long/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":12,"created_at":"2015-12-21T22:03:39Z","updated_at":"2015-12-30T16:54:47Z","closed_at":null,"body":"The build nodes are not processing builds properly.  For example, consider a recent build for @priscian .  The package that needs to be built is \"_psygenet2r_\".  I start the build using `rerun_build`, a part of `spb_history` (which lives [here][1] now). \r\n  \r\n##### On the controller node (staging.bioconductor.org)\r\n```\r\nsource env/bin/activate\r\npython -m rerun_build 1329 https://tracker.bioconductor.org/file6645/psygenet2r_0.9.0.tar.gz \r\n```\r\nThe build began normally, printing some information to the console : \r\n```\r\n(env)biocadmin@ip-172-30-0-180:~/packagebuilder (changes-on-staging)$ python -m rerun_build 1329 https://tracker.bioconductor.org/file6645/psygenet2r_0.9.0.tar.gz DEBUG: 12/21/2015 03:31:24 PM config.py - Loading configuration\r\nINFO: 12/21/2015 03:31:24 PM config.py - Environment is set to: 'production'.\r\nINFO: 12/21/2015 03:31:24 PM config.py - The following build nodes are enabled: ['zin2', 'moscato2'].\r\nINFO: 12/21/2015 03:31:24 PM config.py - Finished loading configuration.\r\nDEBUG: 12/21/2015 03:31:24 PM communication.py - The module search path is: \r\n['', '/home/biocadmin/spb_history/env/lib/python2.7', '/home/biocadmin/spb_history/env/lib/python2.7/plat-x86_64-linux-gnu', '/home/biocadmin/spb_history/env/lib/python2.7/lib-tk', '/home/biocadmin/spb_history/env/lib/python2.7/lib-old', '/home/biocadmin/spb_history/env/lib/python2.7/lib-dynload', '/usr/lib/python2.7', '/usr/lib/python2.7/plat-x86_64-linux-gnu', '/usr/lib/python2.7/lib-tk', '/home/biocadmin/spb_history/env/local/lib/python2.7/site-packages']\r\nDEBUG: 12/21/2015 03:31:24 PM rerun_build.py - Received JSON object: '{\"force\": true, \"job_id\": \"psygenet2r_20151221153124\", \"repository\": \"scratch\", \"bioc_version\": \"3.3\", \"svn_url\": \"https://tracker.bioconductor.org/file6645/psygenet2r_0.9.0.tar.gz\", \"r_version\": \"3.3\", \"client_id\": \"single_package_builder_autobuild:1329:psygenet2r_0.9.0.tar.gz\", \"time\": \"Mon Dec 21 2015 15:31:24 GMT-0800 (PST)\"}'\r\nDEBUG: 12/21/2015 03:31:24 PM communication.py - Attempting to open connection to ActiveMQ at 'broker.bioconductor.org:61613'.\r\nINFO: 12/21/2015 03:31:24 PM transport.py - Attempting connection to host broker.bioconductor.org, port 61613\r\nINFO: 12/21/2015 03:31:24 PM transport.py - Established connection to host broker.bioconductor.org, port 61613\r\nDEBUG: 12/21/2015 03:31:24 PM rerun_build.py - on_connecting() broker.bioconductor.org 61613.\r\nDEBUG: 12/21/2015 03:31:24 PM communication.py - Not attempting authentication\r\nDEBUG: 12/21/2015 03:31:24 PM rerun_build.py - on_send() STOMP {'accept-version': '1.1'} .\r\nINFO: 12/21/2015 03:31:24 PM rerun_build.py - Receipt: None\r\nDEBUG: 12/21/2015 03:31:24 PM transport.py - Sending frame ['STOMP', '\\n', 'accept-version:1.1\\n', '\\n', '\\x00']\r\nDEBUG: 12/21/2015 03:31:24 PM communication.py - Stomp connection established.\r\nDEBUG: 12/21/2015 03:31:24 PM rerun_build.py - on_send() SEND {'content-length': 331, 'destination': '/topic/buildjobs'} {\"force\": true, \"job_id\": \"psygenet2r_20151221153124\", \"repository\": \"scratch\", \"bioc_version\": \"3.3\", \"svn_url\": \"https://tracker.bioconductor.org/file6645/psygenet2r_0.9.0.tar.gz\", \"r_version\": \"3.3\", \"client_id\": \"single_package_builder_autobuild:1329:psygenet2r_0.9.0.tar.gz\", \"time\": \"Mon Dec 21 2015 15:31:24 GMT-0800 (PST)\"}.\r\nINFO: 12/21/2015 03:31:24 PM rerun_build.py - Receipt: None\r\nDEBUG: 12/21/2015 03:31:24 PM transport.py - Sending frame ['SEND', '\\n', 'content-length:331\\n', 'destination:/topic/buildjobs\\n', '\\n', '{\"force\": true, \"job_id\": \"psygenet2r_20151221153124\", \"repository\": \"scratch\", \"bioc_version\": \"3.3\", \"svn_url\": \"https://tracker.bioconductor.org/file6645/psygenet2r_0.9.0.tar.gz\", \"r_version\": \"3.3\", \"client_id\": \"single_package_builder_autobuild:1329:psygenet2r_0.9.0.tar.gz\", \"time\": \"Mon Dec 21 2015 15:31:24 GMT-0800 (PST)\"}', '\\x00']\r\n\r\n```\r\nA page was created to track the build.  However, output from the build nodes is never displayed: http://staging.bioconductor.org:8000/job/552/ .  \r\n\r\n##### On zin2 (a build node)\r\nNext, I began investigating the build machine.  The service running on all build nodes is `server.py`, which prints it's output to `server.log`.  This service regularly receives the command to start build.  In the log file we see that the service is  \"_Waiting to do work._\": \r\n```\r\npkgbuild@zin2:~/packagebuilder$ grep -F \"server.py\" server.log  | tail -n 11\r\nDEBUG: 12/21/2015 12:07:24 PM server.py - main() Waiting to do work.\r\nDEBUG: 12/21/2015 12:12:24 PM server.py - main() Waiting to do work.\r\nDEBUG: 12/21/2015 12:17:24 PM server.py - main() Waiting to do work.\r\nDEBUG: 12/21/2015 12:22:24 PM server.py - main() Waiting to do work.\r\nDEBUG: 12/21/2015 12:27:24 PM server.py - main() Waiting to do work.\r\nDEBUG: 12/21/2015 12:32:25 PM server.py - main() Waiting to do work.\r\nDEBUG: 12/21/2015 12:37:25 PM server.py - main() Waiting to do work.\r\nDEBUG: 12/21/2015 12:42:25 PM server.py - main() Waiting to do work.\r\nDEBUG: 12/21/2015 12:47:25 PM server.py - main() Waiting to do work.\r\nDEBUG: 12/21/2015 12:52:25 PM server.py - main() Waiting to do work.\r\nDEBUG: 12/21/2015 12:57:25 PM server.py - main() Waiting to do work.\r\n```\r\n\r\nInterestingly, If I omit the `main()` loop in searching the log file, we see that the last time instruction was received to perform a build is days ago: \r\n```\r\npkgbuild@zin2:~/packagebuilder$ grep -F \"server.py\" server.log |grep -v \"main()\" | tail -n 11\r\nDEBUG: 12/18/2015 04:58:58 PM server.py - on_before_message() {'expires': '0', 'timestamp': '1450486995478', 'destination': '/topic/buildjobs', 'persistent': 'true', 'priority': '4', 'x-client': '140.107.89.113', 'message-id': 'ID:broker-46292-1448469945488-2:539:-1:1:1', 'subscription': 'ae9a6f4bb94345918d287e135e57c789'} {\"force\": true, \"job_id\": \"isomiRs_20151218165858\", \"repository\": \"scratch\", \"bioc_version\": \"3.3\", \"svn_url\": \"https://tracker.bioconductor.org/file6774/isomiRs_0.99.11.tar.gz\", \"r_version\": \"3.3\", \"client_id\": \"single_package_builder_autobuild:1108:isomiRs_0.99.11.tar.gz\", \"time\": \"Fri Dec 18 2015 16:58:58 GMT-0700 (PST)\"}.\r\nINFO: 12/18/2015 04:58:58 PM server.py - Message received\r\nDEBUG: 12/18/2015 04:58:58 PM server.py - on_message() job_dir = /home/pkgbuild/packagebuilder/workers/jobs/isomiRs_20151218165858.\r\nINFO: 12/18/2015 04:58:58 PM server.py - job_dir: '/home/pkgbuild/packagebuilder/workers/jobs/isomiRs_20151218165858'\r\nINFO: 12/18/2015 04:58:58 PM server.py - Attempting to run commands from directory: '/home/pkgbuild/packagebuilder'\r\nINFO: 12/18/2015 04:58:58 PM server.py - shell_cmd: '['python', '-m', 'workers.builder', u'/home/pkgbuild/packagebuilder/workers/jobs/isomiRs_20151218165858/manifest.json', u'3.3']'\r\nINFO: 12/18/2015 04:58:58 PM server.py - jobfilename: '/home/pkgbuild/packagebuilder/workers/jobs/isomiRs_20151218165858/manifest.json'\r\nINFO: 12/18/2015 04:58:58 PM server.py - builder_log: '<open file u'/home/pkgbuild/packagebuilder/workers/jobs/isomiRs_20151218165858/builder.log', mode 'w' at 0x7f54838068a0>'\r\nINFO: 12/18/2015 04:58:58 PM server.py - blderProcess: '<subprocess.Popen object at 0x7f548377f990>'\r\nDEBUG: 12/18/2015 04:58:58 PM server.py - on_send() SEND {'content-length': 213, 'destination': '/topic/builderevents', 'persistent': 'true'} {\"body\": \"Got build request...\", \"first_message\": true, \"job_id\": \"isomiRs_20151218165858\", \"bioc_version\": \"3.3\", \"builder_id\": \"zin2\", \"client_id\": \"single_package_builder_autobuild:1108:isomiRs_0.99.11.tar.gz\"}.\r\nINFO: 12/18/2015 04:58:58 PM server.py - Reply sent\r\n```\r\nI'm unsure what triggered this build, as I didn't kick it off.  However, we see that it's page (in the Django application) is available and that a build completed for all nodes: http://staging.bioconductor.org:8000/job/545/ .\r\n\r\nLooking at the running processes, we see that the server is still running.  However, it's interesting that there's a defunct sub-process : \r\n ```\r\npkgbuild@zin2:~/packagebuilder$ ps -ef |grep python|grep -v grep\r\npkgbuild  1891 29223  0 Dec18 ?        00:00:00 [python] <defunct>\r\npkgbuild 29223     1  0 Dec18 ?        00:00:00 python -m workers.server\r\n```\r\n\r\n##### On moscato2 (another build node)\r\nDissimilarly, on moscato2, we see that the message to start the build is received : \r\n```\r\n\r\nDEBUG: 12/21/2015 12:18:36 PM server.py - main() Waiting to do work.\r\nDEBUG: 12/21/2015 12:23:36 PM server.py - main() Waiting to do work.\r\nDEBUG: 12/21/2015 12:28:36 PM server.py - main() Waiting to do work.\r\nDEBUG: 12/21/2015 12:31:21 PM server.py - on_before_message() {'content-length': '331', 'expires': '0', 'timestamp': '1450730145147', 'destination': '/topic/buildjobs', 'priority': '4', 'message-id': 'ID:broker-46292-1448469945488-2:552:-1:1:1', 'subscription': 'c7bce2b6036c4a999926bc256ca85c66'} {\"force\": true, \"job_id\": \"psygenet2r_20151221153124\", \"repository\": \"scratch\", \"bioc_version\": \"3.3\", \"svn_url\": \"https://tracker.bioconductor.org/file6645/psygenet2r_0.9.0.tar.gz\", \"r_version\": \"3.3\", \"client_id\": \"single_package_builder_autobuild:1329:psygenet2r_0.9.0.tar.gz\", \"time\": \"Mon Dec 21 2015 15:31:24 GMT-0800 (PST)\"}.\r\nINFO: 12/21/2015 12:31:21 PM server.py - Message received\r\nDEBUG: 12/21/2015 12:31:21 PM server.py - on_message() job_dir = E:\\packagebuilder\\workers\\jobs\\psygenet2r_20151221153124.\r\nINFO: 12/21/2015 12:31:21 PM server.py - job_dir: 'E:\\packagebuilder\\workers\\jobs\\psygenet2r_20151221153124'\r\nINFO: 12/21/2015 12:31:21 PM server.py - Attempting to run commands from directory: 'E:\\packagebuilder'\r\nINFO: 12/21/2015 12:31:21 PM server.py - shell_cmd: '['python', '-m', 'workers.builder', u'E:\\\\packagebuilder\\\\workers\\\\jobs\\\\psygenet2r_20151221153124\\\\manifest.json', u'3.3']'\r\nINFO: 12/21/2015 12:31:21 PM server.py - jobfilename: 'E:\\packagebuilder\\workers\\jobs\\psygenet2r_20151221153124\\manifest.json'\r\nINFO: 12/21/2015 12:31:21 PM server.py - builder_log: '<open file u'E:\\\\packagebuilder\\\\workers\\\\jobs\\\\psygenet2r_20151221153124\\\\builder.log', mode 'w' at 0x017AAA18>'\r\nINFO: 12/21/2015 12:31:21 PM server.py - blderProcess: '<subprocess.Popen object at 0x017D8F90>'\r\nDEBUG: 12/21/2015 12:31:21 PM server.py - on_send() SEND {'content-length': 221, 'destination': '/topic/builderevents', 'persistent': 'true'} {\"body\": \"Got build request...\", \"first_message\": true, \"job_id\": \"psygenet2r_20151221153124\", \"bioc_version\": \"3.3\", \"builder_id\": \"moscato2\", \"client_id\": \"single_package_builder_autobuild:1329:psygenet2r_0.9.0.tar.gz\"}.\r\nDEBUG: 12/21/2015 12:31:21 PM transport.py - Sending frame ['SEND', '\\n', 'content-length:221\\n', 'destination:/topic/builderevents\\n', 'persistent:true\\n', '\\n', '{\"body\": \"Got build request...\", \"first_message\": true, \"job_id\": \"psygenet2r_20151221153124\", \"bioc_version\": \"3.3\", \"builder_id\": \"moscato2\", \"client_id\": \"single_package_builder_autobuild:1329:psygenet2r_0.9.0.tar.gz\"}', '\\x00']\r\nINFO: 12/21/2015 12:31:21 PM server.py - Reply sent\r\nDEBUG: 12/21/2015 12:31:21 PM transport.py - Received frame: 'MESSAGE', headers={'content-length': '331', 'expires': '0', 'timestamp': '1450730145147', 'destination': '/topic/buildjobs', 'priority': '4', 'message-id': 'ID:broker-46292-1448469945488-2:552:-1:1:1', 'subscription': 'c7bce2b6036c4a999926bc256ca85c66'}, body='{\"force\": true, \"job_id\": \"psygenet2r_20151221153124\", \"repository\": \"scratch\", \"bioc_version\": \"3.3\", \"svn_url\": \"https://tracker.bioconductor.org/file6645/psygenet2r_0.9.0.tar.gz\", \"r_version\": \"3.3\", \"client_id\": \"single_package_builder_autobuild:1329:psygenet2r_0.9.0.tar.gz\", \"time\": \"Mon Dec 21 2015 15:31:24 GMT-0800 (PST)\"}'\r\nDEBUG: 12/21/2015 12:33:36 PM server.py - main() Waiting to do work.\r\nDEBUG: 12/21/2015 12:38:36 PM server.py - main() Waiting to do work.\r\nDEBUG: 12/21/2015 12:43:36 PM server.py - main() Waiting to do work.\r\n```\r\n\r\nThere are no defunct processes (I'm not sure if this construct exists in Windows).  Also,\r\n`server.py` is still running.  The build seems to succeed, and we can see that by \r\nnavigating to the directory `E:\\packagebuilder\\workers\\jobs\\psygenet2r_20151221153124`.  \r\nA log file named `builder.log` contains the output below : \r\n```\r\nINFO: 12/21/2015 12:40:28 PM builder.py - Normal build completion, Build successful..\r\n```\r\n\r\nAlso, the file \r\n`E:\\packagebuilder\\workers\\jobs\\psygenet2r_2015122115312\\psygenet2r_0.9.0.tar.gz` is \r\ncreated.\r\n\r\nI'm beginning investigation now.  It may also be worth noting that the only sub-process started directly by `server.py` is [`builder.py`][2].  However, many sub-processes are started by `builder.py`.\r\n\r\n```\r\nblong@work:~/Documents/Work/REPOS__git/b-long/packagebuilder$ git grep \"subprocess\\.call\\|subprocess\\.Popen\" \r\nworkers/builder.py:            description = subprocess.Popen([\r\nworkers/builder.py:    packages = subprocess.Popen([\"curl\", \"-k\", \"-s\", repository_url],\r\nworkers/builder.py:    retcode = subprocess.call(svn_cmd, shell=True)\r\nworkers/builder.py:    retcode = subprocess.call(\"tar %s -zxf %s.orig\" %\r\nworkers/builder.py:    retcode = subprocess.call(cmd, shell=True)\r\nworkers/builder.py:    pope = subprocess.Popen(cmd, stdout=out_fh, stderr=subprocess.STDOUT,\r\nworkers/builder.py:    pope  = subprocess.Popen(cmd, stdout=out_fh, stderr=subprocess.STDOUT,\r\nworkers/builder.py:    svn_info = subprocess.Popen([\r\nworkers/builder.py:        retcode = subprocess.call(command)\r\nworkers/builder.py:        chmod_retcode = subprocess.call(\r\nworkers/builder.py:        retcode = subprocess.call(command)\r\nworkers/builder.py:        remote_chmod_retcode = subprocess.call(command)\r\nworkers/builder.py:        retcode = subprocess.call(command_str, shell=False, stdout=stdout_fh,\r\nworkers/builder.py:        return(subprocess.call(command_str, shell=shell))\r\nworkers/builder.py:    retcode = subprocess.call(command, shell=True)\r\nworkers/builder.py:        retcode = subprocess.call(command, shell=True)\r\nworkers/builder.py:    r_version_raw, stderr = subprocess.Popen([\r\nworkers/builder.py:            description = subprocess.Popen([\r\nworkers/server.py:            blderProcess = subprocess.Popen(shell_cmd, stdout=builder_log, stderr=builder_log)\r\n```\r\n\r\n[1]: https://github.com/Bioconductor/spb_history\r\n[2]: https://github.com/Bioconductor/packagebuilder/blob/6c5b13a9f071bc16d03e9102754c306aa6132e13/workers/server.py#L133\r\n \r\n \r\n \r\n \r\n \r\n \r\n \r\n"},"comment":{"url":"https://api.github.com/repos/Bioconductor/packagebuilder/issues/comments/168033366","html_url":"https://github.com/Bioconductor/packagebuilder/issues/31#issuecomment-168033366","issue_url":"https://api.github.com/repos/Bioconductor/packagebuilder/issues/31","id":168033366,"user":{"login":"b-long","id":66993,"avatar_url":"https://avatars.githubusercontent.com/u/66993?v=3","gravatar_id":"","url":"https://api.github.com/users/b-long","html_url":"https://github.com/b-long","followers_url":"https://api.github.com/users/b-long/followers","following_url":"https://api.github.com/users/b-long/following{/other_user}","gists_url":"https://api.github.com/users/b-long/gists{/gist_id}","starred_url":"https://api.github.com/users/b-long/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/b-long/subscriptions","organizations_url":"https://api.github.com/users/b-long/orgs","repos_url":"https://api.github.com/users/b-long/repos","events_url":"https://api.github.com/users/b-long/events{/privacy}","received_events_url":"https://api.github.com/users/b-long/received_events","type":"User","site_admin":false},"created_at":"2015-12-30T16:54:47Z","updated_at":"2015-12-30T16:54:47Z","body":"Ok, [that change](https://github.com/Bioconductor/packagebuilder/commit/991108814a10275b092f19d289d97b5d759a6bed) fixed the Traceback mentioned earlier.  \r\n\r\nI've re-run 1351 and 1328 for Jim J., and both have successfully finished all stages of the SPB's work.  I'm going to merge #33 and close this issue."}}