{"action":"created","issue":{"url":"https://api.github.com/repos/PacificBiosciences/pbsmrtpipe/issues/120","labels_url":"https://api.github.com/repos/PacificBiosciences/pbsmrtpipe/issues/120/labels{/name}","comments_url":"https://api.github.com/repos/PacificBiosciences/pbsmrtpipe/issues/120/comments","events_url":"https://api.github.com/repos/PacificBiosciences/pbsmrtpipe/issues/120/events","html_url":"https://github.com/PacificBiosciences/pbsmrtpipe/pull/120","id":108590650,"number":120,"title":"Alternative way to get a stack-trace","user":{"login":"pb-cdunn","id":12086299,"avatar_url":"https://avatars.githubusercontent.com/u/12086299?v=3","gravatar_id":"","url":"https://api.github.com/users/pb-cdunn","html_url":"https://github.com/pb-cdunn","followers_url":"https://api.github.com/users/pb-cdunn/followers","following_url":"https://api.github.com/users/pb-cdunn/following{/other_user}","gists_url":"https://api.github.com/users/pb-cdunn/gists{/gist_id}","starred_url":"https://api.github.com/users/pb-cdunn/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/pb-cdunn/subscriptions","organizations_url":"https://api.github.com/users/pb-cdunn/orgs","repos_url":"https://api.github.com/users/pb-cdunn/repos","events_url":"https://api.github.com/users/pb-cdunn/events{/privacy}","received_events_url":"https://api.github.com/users/pb-cdunn/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":2,"created_at":"2015-09-28T05:18:57Z","updated_at":"2015-09-28T06:39:39Z","closed_at":null,"pull_request":{"url":"https://api.github.com/repos/PacificBiosciences/pbsmrtpipe/pulls/120","html_url":"https://github.com/PacificBiosciences/pbsmrtpipe/pull/120","diff_url":"https://github.com/PacificBiosciences/pbsmrtpipe/pull/120.diff","patch_url":"https://github.com/PacificBiosciences/pbsmrtpipe/pull/120.patch"},"body":"This is *much* simpler, and what I recommend.\r\n\r\nInstead of fussing with async i/o, we simply tell the subprocess to write stderr/stdout into specific files. We periodically check those files for new output, like `tail -f`, and we look anything new.\r\n\r\nHere is the result on the run which had been hanging indefinitely:\r\n```python\r\n Failed to run workflow.\r\nTraceback (most recent call last):\r\n  File \"/lustre/hpcprod/cdunn/repo/gh/FALCON-integrate/fc_env/bin/pbsmrtpipe\", line 9, in <module>\r\n    load_entry_point('pbsmrtpipe==0.34.2', 'console_scripts', 'pbsmrtpipe')()\r\n  File \"/lustre/hpcprod/cdunn/repo/gh/FALCON-integrate/pbsmrtpipe/pbsmrtpipe/cli.py\", line 635, in main\r\n    return main_runner(argv_[1:], parser, args_executer, _pbsmrtipe_setup_log, log)\r\n  File \"/lustre/hpcprod/cdunn/repo/gh/FALCON-integrate/pbsmrtpipe/pbsmrtpipe/cli_utils.py\", line 120, in main_runner\r\n    rcode = exe_runner_func(args)\r\n  File \"/lustre/hpcprod/cdunn/repo/gh/FALCON-integrate/pbsmrtpipe/pbsmrtpipe/cli_utils.py\", line 89, in args_executer\r\n    return_code = args.func(args)\r\n  File \"/lustre/hpcprod/cdunn/repo/gh/FALCON-integrate/pbsmrtpipe/pbsmrtpipe/cli.py\", line 379, in _args_run_pipeline\r\n    force_distribute=force_distribute, force_chunk_mode=force_chunk, debug_mode=args.debug)\r\n  File \"/lustre/hpcprod/cdunn/repo/gh/FALCON-integrate/pbsmrtpipe/pbsmrtpipe/driver.py\", line 880, in _wrapper\r\n    state = func(*args, **kwargs)\r\n  File \"/lustre/hpcprod/cdunn/repo/gh/FALCON-integrate/pbsmrtpipe/pbsmrtpipe/driver.py\", line 977, in run_pipeline\r\n    workflow_level_opts, output_dir, service_uri)\r\n  File \"/lustre/hpcprod/cdunn/repo/gh/FALCON-integrate/pbsmrtpipe/pbsmrtpipe/driver.py\", line 847, in exe_workflow\r\n    workers, shutdown_event, service_uri)\r\n  File \"/lustre/hpcprod/cdunn/repo/gh/FALCON-integrate/pbsmrtpipe/pbsmrtpipe/driver.py\", line 466, in __exe_workflow\r\n    _update_analysis_reports_and_datastore(tnode_, task_)\r\n  File \"/lustre/hpcprod/cdunn/repo/gh/FALCON-integrate/pbsmrtpipe/pbsmrtpipe/driver.py\", line 322, in _update_analysis_reports_and_datastore\r\n    ds_uuid = _get_dataset_uuid_or_create_uuid(path_)\r\n  File \"/lustre/hpcprod/cdunn/repo/gh/FALCON-integrate/pbsmrtpipe/pbsmrtpipe/driver.py\", line 123, in _get_dataset_uuid_or_create_uuid\r\n    ds = DataSet(path)\r\nKeyboardInterrupt\r\n```\r\nThose lines appear in both the `*.stderr` file for the subprocess and in the log of the parent, where it is preceded by something like this:\r\n\r\n    [INFO] 2015-09-27 18:13:40,585Z [status.pbsmrtpipe.engine run_command_async 195] subcommand: `pbsmrtpipe pipeline /tmp/cdunn/polished_falcon/workflow_id.xml  --debug  -e e_01:/tmp/cdunn/polished_falcon/fc_run.cfg  -e eid_subread:/mnt/secondary-siv/testdata/SA3-DS/ecoli/2590956/0003_small/Analysis_Results/m140913_222218_42240_c100699952400000001823139203261564_s1_p0.1.small.subreadset.xml --preset-xml=/tmp/cdunn/polished_falcon/preset.xml    --output-dir=/tmp/cdunn/polished_falcon/job_output` in /tmp/cdunn/polished_falcon/\r\n\r\nThis is a tremendous aid to debugging, and it suffers none of the risks of async i/o. We just read stdout/err files passively, iff they exist. Otherwise, we wait for a return-code. "},"comment":{"url":"https://api.github.com/repos/PacificBiosciences/pbsmrtpipe/issues/comments/143653013","html_url":"https://github.com/PacificBiosciences/pbsmrtpipe/pull/120#issuecomment-143653013","issue_url":"https://api.github.com/repos/PacificBiosciences/pbsmrtpipe/issues/120","id":143653013,"user":{"login":"pb-cdunn","id":12086299,"avatar_url":"https://avatars.githubusercontent.com/u/12086299?v=3","gravatar_id":"","url":"https://api.github.com/users/pb-cdunn","html_url":"https://github.com/pb-cdunn","followers_url":"https://api.github.com/users/pb-cdunn/followers","following_url":"https://api.github.com/users/pb-cdunn/following{/other_user}","gists_url":"https://api.github.com/users/pb-cdunn/gists{/gist_id}","starred_url":"https://api.github.com/users/pb-cdunn/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/pb-cdunn/subscriptions","organizations_url":"https://api.github.com/users/pb-cdunn/orgs","repos_url":"https://api.github.com/users/pb-cdunn/repos","events_url":"https://api.github.com/users/pb-cdunn/events{/privacy}","received_events_url":"https://api.github.com/users/pb-cdunn/received_events","type":"User","site_admin":false},"created_at":"2015-09-28T06:39:39Z","updated_at":"2015-09-28T06:39:39Z","body":"Beautiful! With the last commit, we finally have the full stack-trace at the slowest moment:\r\n```python\r\n  File \"/lustre/hpcprod/cdunn/repo/gh/FALCON-integrate/pbsmrtpipe/pbsmrtpipe/driver.py\", line 466, in __exe_workflow\r\n    _update_analysis_reports_and_datastore(tnode_, task_)\r\n  File \"/lustre/hpcprod/cdunn/repo/gh/FALCON-integrate/pbsmrtpipe/pbsmrtpipe/driver.py\", line 322, in _update_analysis_reports_and_datastore\r\n    ds_uuid = _get_dataset_uuid_or_create_uuid(path_)\r\n  File \"/lustre/hpcprod/cdunn/repo/gh/FALCON-integrate/pbsmrtpipe/pbsmrtpipe/driver.py\", line 123, in _get_dataset_uuid_or_create_uuid\r\n    ds = DataSet(path)\r\n  File \"/lustre/hpcprod/cdunn/repo/gh/FALCON-integrate/pbcore/pbcore/io/dataset/DataSetIO.py\", line 266, in __init__\r\n    populateDataSet(self, files)\r\n  File \"/lustre/hpcprod/cdunn/repo/gh/FALCON-integrate/pbcore/pbcore/io/dataset/DataSetReader.py\", line 31, in populateDataSet\r\n    _addFile(dset, filename)\r\n  File \"/lustre/hpcprod/cdunn/repo/gh/FALCON-integrate/pbcore/pbcore/io/dataset/DataSetReader.py\", line 53, in _addFile\r\n    handledTypes[fileType](dset, fileLocation)\r\n  File \"/lustre/hpcprod/cdunn/repo/gh/FALCON-integrate/pbcore/pbcore/io/dataset/DataSetReader.py\", line 88, in _addUnknownFile\r\n    return _addFofnFile(dset, path)\r\n  File \"/lustre/hpcprod/cdunn/repo/gh/FALCON-integrate/pbcore/pbcore/io/dataset/DataSetReader.py\", line 78, in _addFofnFile\r\n    populateDataSet(dset, files)\r\n  File \"/lustre/hpcprod/cdunn/repo/gh/FALCON-integrate/pbcore/pbcore/io/dataset/DataSetReader.py\", line 31, in populateDataSet\r\n    _addFile(dset, filename)\r\n  File \"/lustre/hpcprod/cdunn/repo/gh/FALCON-integrate/pbcore/pbcore/io/dataset/DataSetReader.py\", line 53, in _addFile\r\n    handledTypes[fileType](dset, fileLocation)\r\n  File \"/lustre/hpcprod/cdunn/repo/gh/FALCON-integrate/pbcore/pbcore/io/dataset/DataSetReader.py\", line 90, in _addUnknownFile\r\n    return _addGenericFile(dset, path)\r\n  File \"/lustre/hpcprod/cdunn/repo/gh/FALCON-integrate/pbcore/pbcore/io/dataset/DataSetReader.py\", line 100, in _addGenericFile\r\n    dset.addExternalResources(extRess, updateCount=False)\r\n  File \"/lustre/hpcprod/cdunn/repo/gh/FALCON-integrate/pbcore/pbcore/io/dataset/DataSetIO.py\", line 1209, in addExternalResources\r\n    self.externalResources.merge(newExtResources)\r\n  File \"/lustre/hpcprod/cdunn/repo/gh/FALCON-integrate/pbcore/pbcore/io/dataset/DataSetMembers.py\", line 731, in merge\r\n    curIds = [res.resourceId for res in self]\r\n  File \"/lustre/hpcprod/cdunn/repo/gh/FALCON-integrate/pbcore/pbcore/io/dataset/DataSetMembers.py\", line 727, in __iter__\r\n    yield ExternalResource(child)\r\n  File \"/lustre/hpcprod/cdunn/repo/gh/FALCON-integrate/pbcore/pbcore/io/dataset/DataSetMembers.py\", line 792, in __init__\r\n    self.attrib.setdefault('UniqueId', newUuid(self.record))\r\n  File \"/lustre/hpcprod/cdunn/repo/gh/FALCON-integrate/pbcore/pbcore/io/dataset/DataSetMembers.py\", line 71, in newUuid\r\n    return str(uuid.uuid4())\r\n  File \"/opt/python-2.7.9/lib/python2.7/uuid.py\", line 586, in uuid4\r\n    return UUID(bytes=_buffer.raw)\r\n  File \"/opt/python-2.7.9/lib/python2.7/uuid.py\", line 145, in __init__\r\n    int = long(('%02x'*16) % tuple(map(ord, bytes)), 16)\r\nKeyboardInterrupt\r\n```"}}