search

DataBiosphere / toil

A scalable, efficient, cross-platform (Linux/macOS) and easy-to-use workflow engine in pure Python.
http://toil.ucsc-cgl.org/.
Apache License 2.0
894 stars 241 forks source link

test_kubernetes_cwl_conformance is failing on master #3888

Closed mr-c closed 2 years ago

mr-c commented 2 years ago

But not the normally run CWL conformance tests

Failed twice: https://ucsc-ci.com/databiosphere/toil/-/jobs/1159#L907 https://ucsc-ci.com/databiosphere/toil/-/jobs/1102#L907

Anything thoughts @adamnovak ?

┆Issue is synchronized with this Jira Task ┆Issue Number: TOIL-1075

DailyDreaming commented 2 years ago

I think that the relevant error may be:

cwltool.errors.WorkflowException: Singularity is not available for this tool, try --no-container to disable Singularity, or install a user space Docker replacement like uDocker with --user-space-docker-cmd.: Command '['singularity', 'pull', '--force', '--name', 'debian:stretch-slim.sif', 'docker://debian:stretch-slim']' returned non-zero exit status 255.

So singularity may need some extra tweaking.

adamnovak commented 2 years ago

I'm not sure where you got that message from @DailyDreaming.

This looks like the same basic problem as I'm complaining about in https://github.com/DataBiosphere/toil/pull/3802#issuecomment-964646207

Some of the CWL tests are timing out:

Test 258 timed out: toil-cwl-runner --disableCaching=True --clean=always --logDebug --setEnv=SINGULARITY_DOCKER_HUB_MIRROR --batchSystem=kubernetes --outdir=/tmp/tmpbemuf758 --quiet tests/string-interpolation/bash-line-continuation.cwl
Line continuations in bash scripts should behave correctly
Terminating lingering process
Test 291 timed out: toil-cwl-runner --disableCaching=True --clean=always --logDebug --setEnv=SINGULARITY_DOCKER_HUB_MIRROR --batchSystem=kubernetes --outdir=/tmp/tmpnsm2kvzl --quiet tests/conditionals/cond-wf-003.1_nojs.cwl tests/conditionals/second-true.yml
pickValue: first_non_null second item is non null; no javascript
Test 80 timed out: toil-cwl-runner --disableCaching=True --clean=always --logDebug --setEnv=SINGULARITY_DOCKER_HUB_MIRROR --batchSystem=kubernetes --outdir=/tmp/tmp30r2oy9y --quiet 'tests/scatter-valuefrom-wf3.cwl#main' tests/scatter-valuefrom-job2.json
Test workflow scatter with two scatter parameters and flat_crossproduct join method and valueFrom on step input
Terminating lingering process
Test 191 timed out: toil-cwl-runner --disableCaching=True --clean=always --logDebug --setEnv=SINGULARITY_DOCKER_HUB_MIRROR --batchSystem=kubernetes --outdir=/tmp/tmpmlrcye6p --quiet tests/cat-from-dir.cwl tests/cat-from-dir-job.yaml
Pipe to stdin from user provided local File via a Directory literal
Terminating lingering process

It looks like different tests time out in different runs, and the test run as a whole is getting to what looks like the right total number of tests.

The only thing I can think of to blame here is how I recently changed the GI Kubernetes scheduler to put jobs on busier nodes instead of less busy nodes, to prepare for autoscaling. We could try and revert that change and see if the Toil CI tests start passing? We could also watch Kubernetes while one of these runs is running to see if jobs are sitting around in queue.

@mr-c How long does the CWL test harness give each test to run, and how accurate are the resource requirements on all the CWL test jobs? Will they all finish in time if given the resources they ask for (with cores really being hyperthread half-cores) and no more?

We might need to remove the --quiet from the cwl-toil invocations to actually get the logs for the timed-out tests, so we can see what if anything is going wrong. I'm not sure if those logs will clobber each other given that we're running several of these tests in parallel; I don't know if the CWL test harness does anything to de-interleave the logs from multiple tests.

adamnovak commented 2 years ago

@mr-c I think --quiet is coming from cwltest, but it shouldn't be because we are passing --verbose to cwltest. Can you figure out if we're just using an old cwltest version or something?

DailyDreaming commented 2 years ago

@adamnovak The message came not from master but a branch where I reverted the last commit (TES): https://ucsc-ci.com/databiosphere/toil/-/jobs/1310/raw

We might just be hitting docker limits (as a separate issue) there then. Hopefully the mirror is working but we'll see if the error re-occurs in testing future commits.

adamnovak commented 2 years ago

My PR #3891 where I break --quiet to get logs didn't actually have any CWL Kubernetes timeouts. But the Google job store tests in the next stage also fail:

______________________ GoogleJobStoreTest.testBatchCreate ______________________
Traceback (most recent call last):
  File "/builds/TnycNQM8/2/databiosphere/toil/src/toil/test/jobStores/jobStoreTest.py", line 125, in setUp
    self.jobstore_initialized.initialize(self.config)
  File "/builds/TnycNQM8/2/databiosphere/toil/src/toil/jobStores/googleJobStore.py", line 81, in wrapper
    return f(*args, **kwargs)
  File "/builds/TnycNQM8/2/databiosphere/toil/src/toil/jobStores/googleJobStore.py", line 134, in initialize
    self.bucket = self.storageClient.create_bucket(self.bucketName)
  File "/builds/TnycNQM8/2/databiosphere/toil/venv/lib/python3.8/site-packages/google/cloud/storage/client.py", line 229, in create_bucket
    bucket.create(client=self)
  File "/builds/TnycNQM8/2/databiosphere/toil/venv/lib/python3.8/site-packages/google/cloud/storage/bucket.py", line 276, in create
    api_response = client._connection.api_request(
  File "/builds/TnycNQM8/2/databiosphere/toil/venv/lib/python3.8/site-packages/google/cloud/_http.py", line 293, in api_request
    raise exceptions.from_http_response(response)
google.api_core.exceptions.Forbidden: 403 POST https://www.googleapis.com/storage/v1/b?project=toil-dev: toil-498@toil-dev.iam.gserviceaccount.com does not have storage.buckets.create access to the Google Cloud project.

Looks like the new credentials we issued don't have the permissions they need.

mr-c commented 2 years ago

@mr-c I think --quiet is coming from cwltest, but it shouldn't be because we are passing --verbose to cwltest. Can you figure out if we're just using an old cwltest version or something?

Hmm.. toil is using latest cwltest, 2.2.20210901154959, so I don't know where that is coming from

adamnovak commented 2 years ago

Turning down the parallelism made this less likely to happen, I think, but it still happens.

@mr-c fixed the XML generation, so here's the log from Simple scatter: Add conditional variable to scatter; no javascript timing out in https://ucsc-ci.com/databiosphere/toil/-/jobs/2448:

Logs ``` [2021-11-19T14:07:37+0000] [MainThread] [D] [toil.statsAndLogging] Suppressing the following loggers: {'google', 'dill', 'asyncio', 'urllib3', 'cachecontrol', 'salad', 'galaxy', 'rdflib', 'docker', 'concurrent', 'requests', 'charset_normalizer', 'humanfriendly', 'bcdocs', 'botocore', 'requests_oauthlib', 'boto', 'rsa', 'boto3', 'websocket', 's3transfer', 'pyasn1', 'kubernetes', 'oauthlib', 'prov'} [2021-11-19T14:07:37+0000] [MainThread] [D] [toil.statsAndLogging] Root logger is at level 'DEBUG', 'toil' logger at level 'DEBUG'. [2021-11-19T14:07:37+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Instantiating for region us-west-2 and name prefix 'toil-cwl-19398c8c-4067-4302-964d-e727a203e592' [2021-11-19T14:07:37+0000] [MainThread] [D] [toil] Attempting to read cached credentials from /root/.cache/aws/cached_temporary_credentials. [2021-11-19T14:07:37+0000] [MainThread] [D] [toil] /root/.cache/aws/cached_temporary_credentials is empty. Credentials are not temporary. [2021-11-19T14:07:37+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Binding to job store domain 'toil-registry'. [2021-11-19T14:07:37+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Binding to job store domain 'toil-registry'. [2021-11-19T14:07:37+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Binding to job store domain 'toil-cwl-19398c8c-4067-4302-964d-e727a203e592--jobs'. [2021-11-19T14:07:38+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Binding to job store domain 'toil-cwl-19398c8c-4067-4302-964d-e727a203e592--files'. [2021-11-19T14:07:38+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Binding to job store bucket 'toil-cwl-19398c8c-4067-4302-964d-e727a203e592--files'. [2021-11-19T14:07:38+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Bucket 'toil-cwl-19398c8c-4067-4302-964d-e727a203e592--files' does not exist. [2021-11-19T14:07:38+0000] [MainThread] [D] [toil.lib.aws.utils] Creating bucket 'toil-cwl-19398c8c-4067-4302-964d-e727a203e592--files' in region us-west-2. [2021-11-19T14:07:41+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Created new job store bucket 'toil-cwl-19398c8c-4067-4302-964d-e727a203e592--files' with versioning state True. [2021-11-19T14:07:41+0000] [MainThread] [D] [toil.jobStores.abstractJobStore] The workflow ID is: '746138fc-5905-467c-9004-51d26fe56f42' [2021-11-19T14:07:41+0000] [Thread-1 ] [D] [toil.jobStores.aws.jobStore] Starting sha1 checksum to match None [2021-11-19T14:07:41+0000] [Thread-1 ] [D] [toil.jobStores.aws.jobStore] Updating checksum with 1769 bytes [2021-11-19T14:07:41+0000] [Thread-1 ] [D] [toil.jobStores.aws.jobStore] Starting multipart upload [2021-11-19T14:07:41+0000] [Thread-1 ] [D] [toil.jobStores.aws.jobStore] Multipart upload started as Br.WhTLnm8Z9yqrkL8yIXWoM3lPd8fWgz13PyFQz0M1AB7LVkN_3r7bqL3jQ5ys4mksTJyqF_BXOMUFDlGlA6NfRXet5OwHXgc1sobXGn7D5QolGXHZxFfmaAlsJ9S.Y [2021-11-19T14:07:41+0000] [Thread-1 ] [D] [toil.jobStores.aws.jobStore] Multipart upload visible as Br.WhTLnm8Z9yqrkL8yIXWoM3lPd8fWgz13PyFQz0M1AB7LVkN_3r7bqL3jQ5ys4mksTJyqF_BXOMUFDlGlA6NfRXet5OwHXgc1sobXGn7D5QolGXHZxFfmaAlsJ9S.Y [2021-11-19T14:07:41+0000] [Thread-1 ] [D] [toil.jobStores.aws.jobStore] Uploading part 1 of 1769 bytes to Br.WhTLnm8Z9yqrkL8yIXWoM3lPd8fWgz13PyFQz0M1AB7LVkN_3r7bqL3jQ5ys4mksTJyqF_BXOMUFDlGlA6NfRXet5OwHXgc1sobXGn7D5QolGXHZxFfmaAlsJ9S.Y [2021-11-19T14:07:41+0000] [Thread-1 ] [D] [toil.jobStores.aws.jobStore] Completed checksum with hash 50153d85fa8f2a165693570a21082d7eeaa91097 vs. expected None [2021-11-19T14:07:41+0000] [Thread-1 ] [D] [toil.jobStores.aws.jobStore] Attempting to complete upload... [2021-11-19T14:07:41+0000] [Thread-1 ] [D] [toil.jobStores.aws.jobStore] Completed upload object of type : {'ResponseMetadata': {'RequestId': '40JAGC8VYXHHE7TR', 'HostId': 'zG4LycazYdOAqLZy3zXEfIeH4H8bvezQ3DwXVVMx+Ec5RZ2siytvqmUIYyEg1bRx72BgbL2bJWc=', 'HTTPStatusCode': 200, 'HTTPHeaders': {'x-amz-id-2': 'zG4LycazYdOAqLZy3zXEfIeH4H8bvezQ3DwXVVMx+Ec5RZ2siytvqmUIYyEg1bRx72BgbL2bJWc=', 'x-amz-request-id': '40JAGC8VYXHHE7TR', 'date': 'Fri, 19 Nov 2021 14:07:42 GMT', 'x-amz-version-id': 'CUc2YbYW.xHk8Kv612QyawA2Kwf6alPH', 'content-type': 'application/xml', 'transfer-encoding': 'chunked', 'server': 'AmazonS3'}, 'RetryAttempts': 0}, 'VersionId': 'CUc2YbYW.xHk8Kv612QyawA2Kwf6alPH', 'Location': 'https://toil-cwl-19398c8c-4067-4302-964d-e727a203e592--files.s3.us-west-2.amazonaws.com/a77581f6-ad82-5142-acb7-5a6b01eab3fb', 'Bucket': 'toil-cwl-19398c8c-4067-4302-964d-e727a203e592--files', 'Key': 'a77581f6-ad82-5142-acb7-5a6b01eab3fb', 'ETag': '"3dede7b3f97ed27f256545502a294977-1"'} [2021-11-19T14:07:41+0000] [Thread-1 ] [D] [toil.jobStores.aws.jobStore] Completed upload with version CUc2YbYW.xHk8Kv612QyawA2Kwf6alPH [2021-11-19T14:07:41+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Wrote FileInfo(fileID='a77581f6-ad82-5142-acb7-5a6b01eab3fb', ownerID='891f7db6-e4d9-4221-a58e-ab6cc4395f94', encrypted=False, version='CUc2YbYW.xHk8Kv612QyawA2Kwf6alPH', previousVersion='CUc2YbYW.xHk8Kv612QyawA2Kwf6alPH', content=None, checksum='sha1$50153d85fa8...a21082d7eeaa91097', _numContentChunks=0) bound to for shared file 'config.pickle'. [2021-11-19T14:07:41+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Binding to job store domain 'toil-registry'. [2021-11-19T14:07:41+0000] [MainThread] [I] [cwltool] Resolved 'tests/conditionals/cond-wf-010_nojs.cwl' to 'file:///builds/TnycNQM8/7/databiosphere/toil/src/toil/test/cwl/spec_v12/tests/conditionals/cond-wf-010_nojs.cwl' [2021-11-19T14:07:45+0000] [MainThread] [W] [cwltool] Workflow checker warning: tests/conditionals/cond-wf-010_nojs.cwl:19:11: Source 'out1' of type ["null", {"type": "array", "items": "string"}] may be incompatible tests/conditionals/cond-wf-010_nojs.cwl:25:5: with sink 'out1' of type {"type": "array", "items": "string"} pickValue is used but only a single input source is declared tests/conditionals/cond-wf-010_nojs.cwl:19:11: Source 'out1' of type ["null", {"type": "array", "items": "string"}] may be incompatible tests/conditionals/cond-wf-010_nojs.cwl:25:5: with sink 'out1' of type {"type": "array", "items": "string"} Source is from conditional step and may produce `null` tests/conditionals/cond-wf-010_nojs.cwl:19:11: Source 'out1' of type ["null", {"type": "array", "items": "string"}] may be incompatible tests/conditionals/cond-wf-010_nojs.cwl:25:5: with sink 'out1' of type {"type": "array", "items": "string"} pickValue is: all_non_null [2021-11-19T14:07:45+0000] [MainThread] [D] [toil.cwl.cwltoil] Importing files for ordereddict([('test', [False, False, False, True, True, True]), ('val', [1, 2, 3, 4, 5, 6])]) [2021-11-19T14:07:45+0000] [MainThread] [D] [toil.cwl.cwltoil] Importing files for file:///builds/TnycNQM8/7/databiosphere/toil/src/toil/test/cwl/spec_v12/tests/conditionals/cond-wf-010_nojs.cwl#step1 [2021-11-19T14:07:45+0000] [MainThread] [D] [toil.cwl.cwltoil] Importing files for file:///builds/TnycNQM8/7/databiosphere/toil/src/toil/test/cwl/spec_v12/tests/conditionals/foo.cwl [2021-11-19T14:07:45+0000] [MainThread] [D] [toil.cwl.cwltoil] Make job for tool: [2021-11-19T14:07:45+0000] [MainThread] [D] [toil.resource] Module dir is /builds/TnycNQM8/7/databiosphere/toil/src, our prefix is /builds/TnycNQM8/7/databiosphere/toil/venv, virtualenv: True [2021-11-19T14:07:45+0000] [MainThread] [D] [toil.resource] Module dir is /builds/TnycNQM8/7/databiosphere/toil/src, our prefix is /builds/TnycNQM8/7/databiosphere/toil/venv, virtualenv: True [2021-11-19T14:07:45+0000] [Thread-2 ] [D] [toil.jobStores.aws.jobStore] Inlining content of 5 bytes [2021-11-19T14:07:45+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Wrote FileInfo(fileID='79bad63b-c331-5212-a0d2-d06a788c4b3c', ownerID='891f7db6-e4d9-4221-a58e-ab6cc4395f94', encrypted=False, version='', previousVersion='', content=b'56347', checksum='', _numContentChunks=1) bound to for shared file 'pid.log'. [2021-11-19T14:07:45+0000] [MainThread] [D] [toil.common] Using the kubernetes batch system [2021-11-19T14:07:45+0000] [MainThread] [D] [toil.common] Obtained node ID 2be9d21dd2f7a450ea7b7fea618779d1 from file /var/lib/dbus/machine-id [2021-11-19T14:07:45+0000] [MainThread] [D] [toil.common] Created the workflow directory for this machine at /var/lib/toil/d6f7b2f2da0c53e9909e3a68ec923a5a [2021-11-19T14:07:45+0000] [Thread-3 ] [D] [toil.batchSystems.singleMachine] Started daddy thread for batch system 140197334541264. [2021-11-19T14:07:45+0000] [MainThread] [D] [toil.batchSystems.singleMachine] Started batch system 140197334541264 in normal mode. [2021-11-19T14:07:45+0000] [MainThread] [I] [toil] Overriding docker registry of quay.io/ucsc_cgl with quay.io/ucsc_cgl from TOIL_DOCKER_REGISTRY. [2021-11-19T14:07:45+0000] [MainThread] [I] [toil] Overriding docker name of toil with toil from TOIL_DOCKER_NAME. [2021-11-19T14:07:45+0000] [MainThread] [I] [toil] Overriding docker appliance of quay.io/ucsc_cgl/toil:5.6.0a1-604176544d7178bb415a1dd98f0084d1a1b7f65b-py3.8 with quay.io/ucsc_cgl/toil:5.6.0a1-604176544d7178bb415a1dd98f0084d1a1b7f65b-py3.8 from TOIL_APPLIANCE_SELF. [2021-11-19T14:07:45+0000] [MainThread] [D] [toil.common] User script ModuleDescriptor(dirPath='/builds/TnycNQM8/7/databiosphere/toil/src', name='toil.cwl.cwltoil', fromVirtualEnv=False) belongs to Toil. No need to auto-deploy it. [2021-11-19T14:07:45+0000] [MainThread] [D] [toil.common] No user script to auto-deploy. [2021-11-19T14:07:45+0000] [Thread-4 ] [D] [toil.jobStores.aws.jobStore] Starting sha1 checksum to match None [2021-11-19T14:07:45+0000] [Thread-4 ] [D] [toil.jobStores.aws.jobStore] Updating checksum with 15625 bytes [2021-11-19T14:07:45+0000] [Thread-4 ] [D] [toil.jobStores.aws.jobStore] Starting multipart upload [2021-11-19T14:07:45+0000] [Thread-4 ] [D] [toil.jobStores.aws.jobStore] Multipart upload started as tyILjoQBhyGyjZKZCaUQMN6.ddpHh7Aip4Tnl4onwQ9oaTL4yEJxJVP9Gg169QhxSzVkWyvQGaXKUq.dFcGkaOlnPdkAyPmp_0eE7n8AWSvgHRVj0j.1peRB2xIMCCN7 [2021-11-19T14:07:45+0000] [Thread-4 ] [D] [toil.jobStores.aws.jobStore] Multipart upload visible as tyILjoQBhyGyjZKZCaUQMN6.ddpHh7Aip4Tnl4onwQ9oaTL4yEJxJVP9Gg169QhxSzVkWyvQGaXKUq.dFcGkaOlnPdkAyPmp_0eE7n8AWSvgHRVj0j.1peRB2xIMCCN7 [2021-11-19T14:07:45+0000] [Thread-4 ] [D] [toil.jobStores.aws.jobStore] Uploading part 1 of 15625 bytes to tyILjoQBhyGyjZKZCaUQMN6.ddpHh7Aip4Tnl4onwQ9oaTL4yEJxJVP9Gg169QhxSzVkWyvQGaXKUq.dFcGkaOlnPdkAyPmp_0eE7n8AWSvgHRVj0j.1peRB2xIMCCN7 [2021-11-19T14:07:45+0000] [Thread-4 ] [D] [toil.jobStores.aws.jobStore] Completed checksum with hash 826e5b08649553c26056dd62ed9102c916135798 vs. expected None [2021-11-19T14:07:45+0000] [Thread-4 ] [D] [toil.jobStores.aws.jobStore] Attempting to complete upload... [2021-11-19T14:07:46+0000] [Thread-4 ] [D] [toil.jobStores.aws.jobStore] Completed upload object of type : {'ResponseMetadata': {'RequestId': 'FSZHX7G1NXX771NN', 'HostId': 'TUZ21HrLyS2a9B/i6I3Lmewr/Xhrpl+ciJBMGPoT2jRoyNP0KdXy/UkoLNLreKIJF8k9sLeMKpY=', 'HTTPStatusCode': 200, 'HTTPHeaders': {'x-amz-id-2': 'TUZ21HrLyS2a9B/i6I3Lmewr/Xhrpl+ciJBMGPoT2jRoyNP0KdXy/UkoLNLreKIJF8k9sLeMKpY=', 'x-amz-request-id': 'FSZHX7G1NXX771NN', 'date': 'Fri, 19 Nov 2021 14:07:46 GMT', 'x-amz-version-id': 'UUo7vOfUjtlCSuYlNVmOFxxMuUHa339.', 'content-type': 'application/xml', 'transfer-encoding': 'chunked', 'server': 'AmazonS3'}, 'RetryAttempts': 0}, 'VersionId': 'UUo7vOfUjtlCSuYlNVmOFxxMuUHa339.', 'Location': 'https://toil-cwl-19398c8c-4067-4302-964d-e727a203e592--files.s3.us-west-2.amazonaws.com/01c37f76-e635-5f9c-ad18-6ed1ae1b2e2a', 'Bucket': 'toil-cwl-19398c8c-4067-4302-964d-e727a203e592--files', 'Key': '01c37f76-e635-5f9c-ad18-6ed1ae1b2e2a', 'ETag': '"a8fe3c04355a546059c4347000ec36d3-1"'} [2021-11-19T14:07:46+0000] [Thread-4 ] [D] [toil.jobStores.aws.jobStore] Completed upload with version UUo7vOfUjtlCSuYlNVmOFxxMuUHa339. [2021-11-19T14:07:46+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Wrote FileInfo(fileID='01c37f76-e635-5f9c-ad18-6ed1ae1b2e2a', ownerID='891f7db6-e4d9-4221-a58e-ab6cc4395f94', encrypted=False, version='UUo7vOfUjtlCSuYlNVmOFxxMuUHa339.', previousVersion='UUo7vOfUjtlCSuYlNVmOFxxMuUHa339.', content=None, checksum='sha1$826e5b08649...2ed9102c916135798', _numContentChunks=0) bound to for shared file 'environment.pickle'. [2021-11-19T14:07:46+0000] [MainThread] [D] [toil.common] Written the environment for the jobs to the environment file [2021-11-19T14:07:46+0000] [MainThread] [D] [toil.common] Caching all jobs in job store [2021-11-19T14:07:46+0000] [MainThread] [D] [toil.common] 0 jobs downloaded. [2021-11-19T14:07:46+0000] [MainThread] [D] [toil.job] Issuing promise e6e60d4e-e30c-43df-9df9-a63fda4e3c99 for result of 'CWLWorkflow' TemporaryID(e07127f1-fc5e-4e93-9e94-f164a1741cf3) v0 [2021-11-19T14:07:46+0000] [Thread-6 ] [D] [toil.jobStores.aws.jobStore] Inlining content of 200 bytes [2021-11-19T14:07:46+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Wrote FileInfo(fileID='e6e60d4e-e30c-43df-9df9-a63fda4e3c99', ownerID=None, encrypted=False, version='', previousVersion='', content=b"\x80\x05\x9...4e3c99\x94ub.", checksum='', _numContentChunks=1) bound to . [2021-11-19T14:07:46+0000] [Thread-5 ] [D] [toil.jobStores.aws.jobStore] Inlining content of 140 bytes [2021-11-19T14:07:46+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Wrote FileInfo(fileID='de90cdf4-4065-5763-8ae2-b71758c6f931', ownerID='891f7db6-e4d9-4221-a58e-ab6cc4395f94', encrypted=False, version='', previousVersion='', content=b'\x80\x05\x9...x86\x94R\x94.', checksum='', _numContentChunks=1) bound to for shared file 'rootJobReturnValue'. [2021-11-19T14:07:46+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Assigning ID to job 6cb53f56-3b3e-4ebb-9b19-f29b16af34f9 for '' [2021-11-19T14:07:46+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Assigning ID to job 0179c56a-f96f-413b-ac72-37d805f0448d for '' [2021-11-19T14:07:46+0000] [MainThread] [I] [toil.job] Saving graph of 2 jobs, 2 new [2021-11-19T14:07:46+0000] [MainThread] [I] [toil.job] Processing job 'ResolveIndirect' 0179c56a-f96f-413b-ac72-37d805f0448d v0 [2021-11-19T14:07:46+0000] [MainThread] [D] [toil.job] Issuing promise 37d45eab-08dc-48fc-b636-d3b6b338b243 for result of 'CWLWorkflow' 6cb53f56-3b3e-4ebb-9b19-f29b16af34f9 v0 [2021-11-19T14:07:46+0000] [Thread-8 ] [D] [toil.jobStores.aws.jobStore] Inlining content of 187 bytes [2021-11-19T14:07:46+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Wrote FileInfo(fileID='37d45eab-08dc-48fc-b636-d3b6b338b243', ownerID=None, encrypted=False, version='', previousVersion='', content=b"\x80\x05\x9...38b243\x94ub.", checksum='', _numContentChunks=1) bound to . [2021-11-19T14:07:46+0000] [Thread-7 ] [D] [toil.jobStores.aws.jobStore] Starting sha1 checksum to match None [2021-11-19T14:07:46+0000] [Thread-7 ] [D] [toil.jobStores.aws.jobStore] Updating checksum with 510 bytes [2021-11-19T14:07:46+0000] [Thread-7 ] [D] [toil.jobStores.aws.jobStore] Starting multipart upload [2021-11-19T14:07:46+0000] [Thread-7 ] [D] [toil.jobStores.aws.jobStore] Multipart upload started as CZnJtST.fhkUZaSiHlRzWk_hWjjqgAWtAAvTq9zdVILwUtSb1HoXRVYkwAic8gpuK1x198PqIFQLZ2krDUtiDlF.PrOdWtihIvvxLm2WopO0plWERZxgyNBAJgOj1k1H [2021-11-19T14:07:46+0000] [Thread-7 ] [D] [toil.jobStores.aws.jobStore] Multipart upload visible as CZnJtST.fhkUZaSiHlRzWk_hWjjqgAWtAAvTq9zdVILwUtSb1HoXRVYkwAic8gpuK1x198PqIFQLZ2krDUtiDlF.PrOdWtihIvvxLm2WopO0plWERZxgyNBAJgOj1k1H [2021-11-19T14:07:46+0000] [Thread-7 ] [D] [toil.jobStores.aws.jobStore] Uploading part 1 of 510 bytes to CZnJtST.fhkUZaSiHlRzWk_hWjjqgAWtAAvTq9zdVILwUtSb1HoXRVYkwAic8gpuK1x198PqIFQLZ2krDUtiDlF.PrOdWtihIvvxLm2WopO0plWERZxgyNBAJgOj1k1H [2021-11-19T14:07:46+0000] [Thread-7 ] [D] [toil.jobStores.aws.jobStore] Completed checksum with hash 905d4f536a3a004cb0fc9b45581e2bc59767d890 vs. expected None [2021-11-19T14:07:46+0000] [Thread-7 ] [D] [toil.jobStores.aws.jobStore] Attempting to complete upload... [2021-11-19T14:07:46+0000] [Thread-7 ] [D] [toil.jobStores.aws.jobStore] Completed upload object of type : {'ResponseMetadata': {'RequestId': 'PCSNFW26RFH56RXT', 'HostId': 'aZefzNvyTpVNcis+rrh2rJieaWUg3fqeAGBteHqgQrDMuxBED2tQrdW7Sy9o96nW3sNzOptFc+A=', 'HTTPStatusCode': 200, 'HTTPHeaders': {'x-amz-id-2': 'aZefzNvyTpVNcis+rrh2rJieaWUg3fqeAGBteHqgQrDMuxBED2tQrdW7Sy9o96nW3sNzOptFc+A=', 'x-amz-request-id': 'PCSNFW26RFH56RXT', 'date': 'Fri, 19 Nov 2021 14:07:47 GMT', 'x-amz-version-id': 'x1RyQSs.OuljFH7io3ym345fCqjn5Gac', 'content-type': 'application/xml', 'transfer-encoding': 'chunked', 'server': 'AmazonS3'}, 'RetryAttempts': 0}, 'VersionId': 'x1RyQSs.OuljFH7io3ym345fCqjn5Gac', 'Location': 'https://toil-cwl-19398c8c-4067-4302-964d-e727a203e592--files.s3.us-west-2.amazonaws.com/9cca3b9a-397a-42a2-ac94-8d95d14e2bfa', 'Bucket': 'toil-cwl-19398c8c-4067-4302-964d-e727a203e592--files', 'Key': '9cca3b9a-397a-42a2-ac94-8d95d14e2bfa', 'ETag': '"6f06819d001486169edd9dd672d225fb-1"'} [2021-11-19T14:07:46+0000] [Thread-7 ] [D] [toil.jobStores.aws.jobStore] Completed upload with version x1RyQSs.OuljFH7io3ym345fCqjn5Gac [2021-11-19T14:07:46+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Wrote FileInfo(fileID='9cca3b9a-397a-42a2-ac94-8d95d14e2bfa', ownerID='0179c56a-f96f-413b-ac72-37d805f0448d', encrypted=False, version='x1RyQSs.OuljFH7io3ym345fCqjn5Gac', previousVersion='x1RyQSs.OuljFH7io3ym345fCqjn5Gac', content=None, checksum='sha1$905d4f536a3...5581e2bc59767d890', _numContentChunks=0) bound to . [2021-11-19T14:07:46+0000] [MainThread] [I] [toil.job] Processing job 'CWLWorkflow' 6cb53f56-3b3e-4ebb-9b19-f29b16af34f9 v0 [2021-11-19T14:07:46+0000] [Thread-9 ] [D] [toil.jobStores.aws.jobStore] Starting sha1 checksum to match None [2021-11-19T14:07:46+0000] [Thread-9 ] [D] [toil.jobStores.aws.jobStore] Updating checksum with 221262 bytes [2021-11-19T14:07:46+0000] [Thread-9 ] [D] [toil.jobStores.aws.jobStore] Starting multipart upload [2021-11-19T14:07:46+0000] [Thread-9 ] [D] [toil.jobStores.aws.jobStore] Multipart upload started as BrwDIOisgP2vTGY6CB9lReZ.GomVPqiFNNgYRLp_9BAKT3IAXx.Qs5jKht09vK41u3wNu5axqRJyqv3nEWWwfkrrc4mHG9cCnoUQwV.qYAZyp5JTPiCzcf1B1EyD6i2N [2021-11-19T14:07:46+0000] [Thread-9 ] [D] [toil.jobStores.aws.jobStore] Multipart upload visible as BrwDIOisgP2vTGY6CB9lReZ.GomVPqiFNNgYRLp_9BAKT3IAXx.Qs5jKht09vK41u3wNu5axqRJyqv3nEWWwfkrrc4mHG9cCnoUQwV.qYAZyp5JTPiCzcf1B1EyD6i2N [2021-11-19T14:07:46+0000] [Thread-9 ] [D] [toil.jobStores.aws.jobStore] Uploading part 1 of 221262 bytes to BrwDIOisgP2vTGY6CB9lReZ.GomVPqiFNNgYRLp_9BAKT3IAXx.Qs5jKht09vK41u3wNu5axqRJyqv3nEWWwfkrrc4mHG9cCnoUQwV.qYAZyp5JTPiCzcf1B1EyD6i2N [2021-11-19T14:07:46+0000] [Thread-9 ] [D] [toil.jobStores.aws.jobStore] Completed checksum with hash f1c157e17e10fa9be59711b26664ba36e5cac2f7 vs. expected None [2021-11-19T14:07:46+0000] [Thread-9 ] [D] [toil.jobStores.aws.jobStore] Attempting to complete upload... [2021-11-19T14:07:46+0000] [Thread-9 ] [D] [toil.jobStores.aws.jobStore] Completed upload object of type : {'ResponseMetadata': {'RequestId': 'PCSVY2P3NT8T24SE', 'HostId': 'WCYoSSrbyICbIKoPqgz6OK1i+MPanZgAyehzUtRLQvsorrD+20k4qLyfrDOSAdIi1bv49w0d2Q4=', 'HTTPStatusCode': 200, 'HTTPHeaders': {'x-amz-id-2': 'WCYoSSrbyICbIKoPqgz6OK1i+MPanZgAyehzUtRLQvsorrD+20k4qLyfrDOSAdIi1bv49w0d2Q4=', 'x-amz-request-id': 'PCSVY2P3NT8T24SE', 'date': 'Fri, 19 Nov 2021 14:07:47 GMT', 'x-amz-version-id': '3RzoVJsOdSovGcHugLQ.MBD4Bnp_ydgb', 'content-type': 'application/xml', 'transfer-encoding': 'chunked', 'server': 'AmazonS3'}, 'RetryAttempts': 0}, 'VersionId': '3RzoVJsOdSovGcHugLQ.MBD4Bnp_ydgb', 'Location': 'https://toil-cwl-19398c8c-4067-4302-964d-e727a203e592--files.s3.us-west-2.amazonaws.com/89042a97-fc15-4aa5-ab55-16817e29df3a', 'Bucket': 'toil-cwl-19398c8c-4067-4302-964d-e727a203e592--files', 'Key': '89042a97-fc15-4aa5-ab55-16817e29df3a', 'ETag': '"049ec3987916f4e438b49cf85e12f39f-1"'} [2021-11-19T14:07:46+0000] [Thread-9 ] [D] [toil.jobStores.aws.jobStore] Completed upload with version 3RzoVJsOdSovGcHugLQ.MBD4Bnp_ydgb [2021-11-19T14:07:46+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Wrote FileInfo(fileID='89042a97-fc15-4aa5-ab55-16817e29df3a', ownerID='6cb53f56-3b3e-4ebb-9b19-f29b16af34f9', encrypted=False, version='3RzoVJsOdSovGcHugLQ.MBD4Bnp_ydgb', previousVersion='3RzoVJsOdSovGcHugLQ.MBD4Bnp_ydgb', content=None, checksum='sha1$f1c157e17e1...26664ba36e5cac2f7', _numContentChunks=0) bound to . [2021-11-19T14:07:46+0000] [MainThread] [D] [toil.job] New job version: 'ResolveIndirect' 0179c56a-f96f-413b-ac72-37d805f0448d v1 [2021-11-19T14:07:46+0000] [MainThread] [D] [toil.job] New job version: 'CWLWorkflow' 6cb53f56-3b3e-4ebb-9b19-f29b16af34f9 v1 [2021-11-19T14:07:46+0000] [Thread-10 ] [D] [toil.jobStores.aws.jobStore] Inlining content of 36 bytes [2021-11-19T14:07:47+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Wrote FileInfo(fileID='a09ece78-f7f5-580e-bcf3-59b8e4b7c1fa', ownerID='891f7db6-e4d9-4221-a58e-ab6cc4395f94', encrypted=False, version='', previousVersion='', content=b'6cb53f56-3b...-f29b16af34f9', checksum='', _numContentChunks=1) bound to for shared file 'rootJobStoreID'. [2021-11-19T14:07:47+0000] [MainThread] [I] [toil] Running Toil version 5.6.0a1-604176544d7178bb415a1dd98f0084d1a1b7f65b on host runner-tnycnqm8-project-3-concurrent-75jcr5. [2021-11-19T14:07:47+0000] [MainThread] [D] [toil] Configuration: {'workflowID': '746138fc-5905-467c-9004-51d26fe56f42', 'workflowAttemptNumber': 0, 'jobStore': 'aws:us-west-2:toil-cwl-19398c8c-4067-4302-964d-e727a203e592', 'logLevel': 'DEBUG', 'workDir': None, 'noStdOutErr': False, 'stats': False, 'clean': 'always', 'cleanWorkDir': 'always', 'clusterStats': None, 'restart': False, 'batchSystem': 'kubernetes', 'disableAutoDeployment': False, 'maxLocalJobs': 4, 'manualMemArgs': False, 'coalesceStatusCalls': False, 'statePollingWait': None, 'parasolCommand': 'parasol', 'parasolMaxBatches': 10000, 'scale': 1.0, 'allocate_mem': False, 'tes_endpoint': 'http://10.244.1.58:8000', 'tes_user': None, 'tes_password': None, 'tes_bearer_token': None, 'kubernetes_host_path': '/data/scratch', 'kubernetes_owner': 'toiltest', 'runCwlInternalJobsOnWorkers': False, 'disableCaching': False, 'linkImports': True, 'moveExports': False, 'provisioner': None, 'nodeTypes': [], 'minNodes': None, 'maxNodes': [10], 'targetTime': 1800, 'betaInertia': 0.1, 'scaleInterval': 60, 'preemptableCompensation': 0.0, 'nodeStorage': 50, 'nodeStorageOverrides': [], 'metrics': False, 'maxPreemptableServiceJobs': 9223372036854775807, 'maxServiceJobs': 9223372036854775807, 'deadlockWait': 60, 'deadlockCheckInterval': 30, 'defaultMemory': 2147483648, 'defaultCores': 1, 'defaultDisk': 2147483648, 'readGlobalFileMutableByDefault': False, 'defaultPreemptable': False, 'maxCores': 9223372036854775807, 'maxMemory': 9223372036854775807, 'maxDisk': 9223372036854775807, 'retryCount': 1, 'enableUnlimitedPreemptableRetries': False, 'doubleMem': False, 'maxJobDuration': 9223372036854775807, 'rescueJobsFrequency': 3600, 'environment': {'SINGULARITY_DOCKER_HUB_MIRROR': None}, 'disableChaining': False, 'disableJobStoreChecksumVerification': False, 'maxLogFileSize': 64000, 'writeLogs': None, 'writeLogsGzip': None, 'writeLogsFromAllJobs': False, 'sseKey': None, 'servicePollingInterval': 60, 'useAsync': True, 'forceDockerAppliance': False, 'statusWait': 3600, 'disableProgress': False, 'debugWorker': False, 'disableWorkerOutputCapture': False, 'badWorker': 0.0, 'badWorkerFailInterval': 0.01, 'cwl': False} [2021-11-19T14:07:47+0000] [MainThread] [D] [toil.realtimeLogger] Real-time logging disabled [2021-11-19T14:07:47+0000] [MainThread] [D] [toil.toilState] Found job to run: 6cb53f56-3b3e-4ebb-9b19-f29b16af34f9, with command: True, with checkpoint: False, with services: False, with no next successors: False [2021-11-19T14:07:47+0000] [MainThread] [D] [toil.bus] _buildToilState sent: JobUpdatedMessage(job_id='6cb53f56-3b3e-4ebb-9b19-f29b16af34f9', result_status=0) [2021-11-19T14:07:47+0000] [MainThread] [D] [toil.leader] Found 1 jobs to start and 0 jobs with successors to run [2021-11-19T14:07:47+0000] [MainThread] [D] [toil.leader] Checked batch system has no running jobs and no updated jobs [2021-11-19T14:07:47+0000] [MainThread] [D] [toil.serviceManager] Initializing service manager [2021-11-19T14:07:47+0000] [MainThread] [D] [toil.leader] Built the jobs list, currently have 1 jobs to update and 0 jobs issued [2021-11-19T14:07:47+0000] [MainThread] [D] [toil.leader] Updating status of job 'CWLWorkflow' 6cb53f56-3b3e-4ebb-9b19-f29b16af34f9 v1 with result status: 0 [2021-11-19T14:07:47+0000] [MainThread] [D] [toil.batchSystems.singleMachine] Issuing the command: _toil_worker CWLWorkflow aws:us-west-2:toil-cwl-19398c8c-4067-4302-964d-e727a203e592 6cb53f56-3b3e-4ebb-9b19-f29b16af34f9 --context gASVzAAAAAAAAACMIXRvaWwuYmF0Y2hTeXN0ZW1zLmNsZWFudXBfc3VwcG9ydJSMFFdvcmtlckNsZWFudXBDb250ZXh0lJOUKYGUfZSMEXdvcmtlckNsZWFudXBJbmZvlIwldG9pbC5iYXRjaFN5c3RlbXMuYWJzdHJhY3RCYXRjaFN5c3RlbZSMEVdvcmtlckNsZWFudXBJbmZvlJOUTowkNzQ2MTM4ZmMtNTkwNS00NjdjLTkwMDQtNTFkMjZmZTU2ZjQylIwGYWx3YXlzlIeUgZRzYi4= with memory: 1073741824, cores: 1.0, disk: 1048576 [2021-11-19T14:07:47+0000] [MainThread] [D] [toil.leader] Issued job 'CWLWorkflow' 6cb53f56-3b3e-4ebb-9b19-f29b16af34f9 v1 with job batch system ID: 0 and cores: 1, disk: 1.0 Mi, and memory: 1.0 Gi [2021-11-19T14:07:47+0000] [Thread-3 ] [D] [toil.batchSystems.singleMachine] Launched job 0 as child 56547 [2021-11-19T14:07:49+0000] [MainThread] [I] [toil.leader] 1 jobs are running, 0 jobs are issued and waiting to run [2021-11-19T14:07:49+0000] [MainThread] [D] [toil.statsAndLogging] Suppressing the following loggers: {'rdflib', 's3transfer', 'pyasn1', 'concurrent', 'boto3', 'requests', 'urllib3', 'kubernetes', 'dill', 'bcdocs', 'requests_oauthlib', 'botocore', 'boto', 'salad', 'websocket', 'charset_normalizer', 'cachecontrol', 'docker', 'humanfriendly', 'galaxy', 'oauthlib', 'prov', 'rsa', 'google'} [2021-11-19T14:07:49+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Reading FileInfo(fileID='01c37f76-e635-5f9c-ad18-6ed1ae1b2e2a', ownerID='891f7db6-e4d9-4221-a58e-ab6cc4395f94', encrypted=False, version='UUo7vOfUjtlCSuYlNVmOFxxMuUHa339.', previousVersion='UUo7vOfUjtlCSuYlNVmOFxxMuUHa339.', content=None, checksum='sha1$826e5b08649...2ed9102c916135798', _numContentChunks=0) bound to for shared file 'environment.pickle' into stream. [2021-11-19T14:07:49+0000] [Thread-4 ] [D] [toil.jobStores.aws.jobStore] Starting sha1 checksum to match 826e5b08649553c26056dd62ed9102c916135798 [2021-11-19T14:07:49+0000] [Thread-4 ] [D] [toil.jobStores.aws.jobStore] Completed checksum with hash 826e5b08649553c26056dd62ed9102c916135798 vs. expected 826e5b08649553c26056dd62ed9102c916135798 [2021-11-19T14:07:49+0000] [MainThread] [D] [toil.common] Obtained node ID 2be9d21dd2f7a450ea7b7fea618779d1 from file /var/lib/dbus/machine-id [2021-11-19T14:07:49+0000] [MainThread] [I] [toil.worker] Redirecting logging to /var/lib/toil/d6f7b2f2da0c53e9909e3a68ec923a5a/a375/worker_log.txt [2021-11-19T14:07:51+0000] [Thread-15 ] [D] [toil.jobStores.aws.jobStore] Starting sha1 checksum to match None [2021-11-19T14:07:51+0000] [Thread-15 ] [D] [toil.jobStores.aws.jobStore] Completed checksum with hash 6895eb01b516adf0c193260a23b2e5edfc3083bb vs. expected None [2021-11-19T14:07:51+0000] [Thread-15 ] [D] [toil.jobStores.aws.jobStore] Uploading single part of 24839 bytes [2021-11-19T14:07:51+0000] [Thread-15 ] [D] [toil.jobStores.aws.jobStore] Upload received version c7TMFwi1Df9YevnF_oEnXb9_7vHhmuXY [2021-11-19T14:07:51+0000] [MainThread] [D] [toil.deferred] Deleting /var/lib/toil/d6f7b2f2da0c53e9909e3a68ec923a5a/deferred/func1azfhsnm [2021-11-19T14:07:51+0000] [MainThread] [D] [toil.lib.threading] Leaving arena /var/lib/toil/746138fc-5905-467c-9004-51d26fe56f42-cleanup-arena-members [2021-11-19T14:07:51+0000] [MainThread] [D] [toil.lib.threading] PID 56548 acquiring mutex /var/lib/toil/toil-mutex-746138fc-5905-467c-9004-51d26fe56f42-cleanup-arena-lock [2021-11-19T14:07:51+0000] [MainThread] [D] [toil.lib.threading] PID 56548 now holds mutex /var/lib/toil/toil-mutex-746138fc-5905-467c-9004-51d26fe56f42-cleanup-arena-lock [2021-11-19T14:07:51+0000] [MainThread] [D] [toil.lib.threading] We are the Last Process Standing in arena /var/lib/toil/746138fc-5905-467c-9004-51d26fe56f42-cleanup-arena-members [2021-11-19T14:07:51+0000] [MainThread] [D] [toil.batchSystems.cleanup_support] Cleaning up worker [2021-11-19T14:07:51+0000] [MainThread] [D] [toil.common] Obtained node ID 2be9d21dd2f7a450ea7b7fea618779d1 from file /var/lib/dbus/machine-id [2021-11-19T14:07:51+0000] [MainThread] [D] [toil.deferred] Cleaning up deferred functions system [2021-11-19T14:07:51+0000] [MainThread] [D] [toil.deferred] Running for file /var/lib/toil/d6f7b2f2da0c53e9909e3a68ec923a5a/deferred/funcxico2gye [2021-11-19T14:07:51+0000] [MainThread] [D] [toil.deferred] Running orphaned deferred functions [2021-11-19T14:07:51+0000] [MainThread] [D] [toil.deferred] Deleting /var/lib/toil/d6f7b2f2da0c53e9909e3a68ec923a5a/deferred/funcxico2gye [2021-11-19T14:07:51+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Connecting to latest caching database cache-0.db for cleanup [2021-11-19T14:07:51+0000] [MainThread] [D] [toil.lib.threading] PID 56548 releasing mutex /var/lib/toil/toil-mutex-746138fc-5905-467c-9004-51d26fe56f42-cleanup-arena-lock [2021-11-19T14:07:51+0000] [MainThread] [D] [toil.lib.threading] Now out of arena /var/lib/toil/746138fc-5905-467c-9004-51d26fe56f42-cleanup-arena-members [2021-11-19T14:07:51+0000] [Thread-14 ] [D] [toil.jobStores.aws.jobStore] Starting sha1 checksum to match 6895eb01b516adf0c193260a23b2e5edfc3083bb [2021-11-19T14:07:51+0000] [Thread-14 ] [D] [toil.jobStores.aws.jobStore] Completed checksum with hash 6895eb01b516adf0c193260a23b2e5edfc3083bb vs. expected 6895eb01b516adf0c193260a23b2e5edfc3083bb [2021-11-19T14:07:51+0000] [Thread-12 ] [D] [toil.statsAndLogging] Got message from job at time 11-19-2021 14:07:51: Job 'CWLWorkflow' 6cb53f56-3b3e-4ebb-9b19-f29b16af34f9 v1 used 0.00% disk (0 bB [0B] used, 1.0 MiB [1048576B] requested). [2021-11-19T14:07:51+0000] [Thread-12 ] [D] [toil.statsAndLogging] Received Toil worker log. Disable debug level logging to hide this output [2021-11-19T14:07:51+0000] [Thread-12 ] [D] [toil.statsAndLogging] Log from job "'CWLWorkflow' 6cb53f56-3b3e-4ebb-9b19-f29b16af34f9 v1" follows: =========> [2021-11-19T14:07:49+0000] [MainThread] [I] [toil.worker] ---TOIL WORKER OUTPUT LOG--- [2021-11-19T14:07:49+0000] [MainThread] [I] [toil] Running Toil version 5.6.0a1-604176544d7178bb415a1dd98f0084d1a1b7f65b on host runner-tnycnqm8-project-3-concurrent-75jcr5. [2021-11-19T14:07:49+0000] [MainThread] [D] [toil] Configuration: {'workflowID': '746138fc-5905-467c-9004-51d26fe56f42', 'workflowAttemptNumber': 0, 'jobStore': 'aws:us-west-2:toil-cwl-19398c8c-4067-4302-964d-e727a203e592', 'logLevel': 'DEBUG', 'workDir': None, 'noStdOutErr': False, 'stats': False, 'clean': 'always', 'cleanWorkDir': 'always', 'clusterStats': None, 'restart': False, 'batchSystem': 'kubernetes', 'disableAutoDeployment': False, 'maxLocalJobs': 4, 'manualMemArgs': False, 'coalesceStatusCalls': False, 'statePollingWait': None, 'parasolCommand': 'parasol', 'parasolMaxBatches': 10000, 'scale': 1.0, 'allocate_mem': False, 'tes_endpoint': 'http://10.244.1.58:8000', 'tes_user': None, 'tes_password': None, 'tes_bearer_token': None, 'kubernetes_host_path': '/data/scratch', 'kubernetes_owner': 'toiltest', 'runCwlInternalJobsOnWorkers': False, 'disableCaching': False, 'linkImports': True, 'moveExports': False, 'provisioner': None, 'nodeTypes': [], 'minNodes': None, 'maxNodes': [10], 'targetTime': 1800, 'betaInertia': 0.1, 'scaleInterval': 60, 'preemptableCompensation': 0.0, 'nodeStorage': 50, 'nodeStorageOverrides': [], 'metrics': False, 'maxPreemptableServiceJobs': 9223372036854775807, 'maxServiceJobs': 9223372036854775807, 'deadlockWait': 60, 'deadlockCheckInterval': 30, 'defaultMemory': 2147483648, 'defaultCores': 1, 'defaultDisk': 2147483648, 'readGlobalFileMutableByDefault': False, 'defaultPreemptable': False, 'maxCores': 9223372036854775807, 'maxMemory': 9223372036854775807, 'maxDisk': 9223372036854775807, 'retryCount': 1, 'enableUnlimitedPreemptableRetries': False, 'doubleMem': False, 'maxJobDuration': 9223372036854775807, 'rescueJobsFrequency': 3600, 'environment': {'SINGULARITY_DOCKER_HUB_MIRROR': None}, 'disableChaining': False, 'disableJobStoreChecksumVerification': False, 'maxLogFileSize': 64000, 'writeLogs': None, 'writeLogsGzip': None, 'writeLogsFromAllJobs': False, 'sseKey': None, 'servicePollingInterval': 60, 'useAsync': True, 'forceDockerAppliance': False, 'statusWait': 3600, 'disableProgress': False, 'debugWorker': False, 'disableWorkerOutputCapture': False, 'badWorker': 0.0, 'badWorkerFailInterval': 0.01, 'cwl': False} [2021-11-19T14:07:49+0000] [MainThread] [D] [toil.deferred] Running for file /var/lib/toil/d6f7b2f2da0c53e9909e3a68ec923a5a/deferred/func1azfhsnm [2021-11-19T14:07:49+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Loaded job 6cb53f56-3b3e-4ebb-9b19-f29b16af34f9 [2021-11-19T14:07:49+0000] [MainThread] [D] [toil.worker] Parsed job description [2021-11-19T14:07:49+0000] [MainThread] [I] [toil.worker] Working on job 'CWLWorkflow' 6cb53f56-3b3e-4ebb-9b19-f29b16af34f9 v1 [2021-11-19T14:07:49+0000] [MainThread] [D] [toil.worker] Got a command to run: _toil 89042a97-fc15-4aa5-ab55-16817e29df3a /builds/TnycNQM8/7/databiosphere/toil/src toil.cwl.cwltoil False [2021-11-19T14:07:49+0000] [MainThread] [D] [toil.job] Loading user module ModuleDescriptor(dirPath='/builds/TnycNQM8/7/databiosphere/toil/src', name='toil.cwl.cwltoil', fromVirtualEnv=False). [2021-11-19T14:07:49+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Reading FileInfo(fileID='89042a97-fc15-4aa5-ab55-16817e29df3a', ownerID='6cb53f56-3b3e-4ebb-9b19-f29b16af34f9', encrypted=False, version='3RzoVJsOdSovGcHugLQ.MBD4Bnp_ydgb', previousVersion='3RzoVJsOdSovGcHugLQ.MBD4Bnp_ydgb', content=None, checksum='sha1$f1c157e17e1...26664ba36e5cac2f7', _numContentChunks=0) bound to into stream. [2021-11-19T14:07:49+0000] [Thread-6 ] [D] [toil.jobStores.aws.jobStore] Starting sha1 checksum to match f1c157e17e10fa9be59711b26664ba36e5cac2f7 [2021-11-19T14:07:49+0000] [Thread-6 ] [D] [toil.jobStores.aws.jobStore] Completed checksum with hash f1c157e17e10fa9be59711b26664ba36e5cac2f7 vs. expected f1c157e17e10fa9be59711b26664ba36e5cac2f7 [2021-11-19T14:07:49+0000] [MainThread] [I] [toil.worker] Loaded body Job('CWLWorkflow' 6cb53f56-3b3e-4ebb-9b19-f29b16af34f9 v1) from description 'CWLWorkflow' 6cb53f56-3b3e-4ebb-9b19-f29b16af34f9 v1 [2021-11-19T14:07:49+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Starting job ('CWLWorkflow' 6cb53f56-3b3e-4ebb-9b19-f29b16af34f9 v1) with ID (6cb53f56-3b3e-4ebb-9b19-f29b16af34f9). [2021-11-19T14:07:49+0000] [MainThread] [D] [toil.deferred] Running orphaned deferred functions [2021-11-19T14:07:49+0000] [MainThread] [D] [toil.deferred] Running job [2021-11-19T14:07:49+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Actually running job ('CWLWorkflow' 6cb53f56-3b3e-4ebb-9b19-f29b16af34f9 v1) with ID (6cb53f56-3b3e-4ebb-9b19-f29b16af34f9) which wants 1048576 of our 2671377055744 bytes. [2021-11-19T14:07:49+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Max space: 2671377055744 [2021-11-19T14:07:49+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Total file size: 0 [2021-11-19T14:07:49+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Total job disk requirement size: 1048576 [2021-11-19T14:07:49+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Total immutable reference size: 0 [2021-11-19T14:07:49+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Available space with job: 2671376007168 bytes [2021-11-19T14:07:49+0000] [MainThread] [D] [toil.resource] Module dir is /builds/TnycNQM8/7/databiosphere/toil/src, our prefix is /builds/TnycNQM8/7/databiosphere/toil/venv, virtualenv: True [2021-11-19T14:07:49+0000] [MainThread] [D] [toil.resource] Module dir is /builds/TnycNQM8/7/databiosphere/toil/src, our prefix is /builds/TnycNQM8/7/databiosphere/toil/venv, virtualenv: True [2021-11-19T14:07:49+0000] [MainThread] [D] [toil.cwl.cwltoil] Ready to make job for workflow step file:///builds/TnycNQM8/7/databiosphere/toil/src/toil/test/cwl/spec_v12/tests/conditionals/cond-wf-010_nojs.cwl#step1 [2021-11-19T14:07:49+0000] [MainThread] [D] [toil.cwl.cwltoil] Takes input: file:///builds/TnycNQM8/7/databiosphere/toil/src/toil/test/cwl/spec_v12/tests/conditionals/cond-wf-010_nojs.cwl#step1/a_new_var [2021-11-19T14:07:49+0000] [MainThread] [D] [toil.cwl.cwltoil] Takes input: file:///builds/TnycNQM8/7/databiosphere/toil/src/toil/test/cwl/spec_v12/tests/conditionals/cond-wf-010_nojs.cwl#step1/in1 [2021-11-19T14:07:49+0000] [MainThread] [D] [toil.resource] Module dir is /builds/TnycNQM8/7/databiosphere/toil/src, our prefix is /builds/TnycNQM8/7/databiosphere/toil/venv, virtualenv: True [2021-11-19T14:07:49+0000] [MainThread] [D] [toil.resource] Module dir is /builds/TnycNQM8/7/databiosphere/toil/src, our prefix is /builds/TnycNQM8/7/databiosphere/toil/venv, virtualenv: True [2021-11-19T14:07:49+0000] [MainThread] [D] [toil.cwl.cwltoil] Is scatter with job Job('CWLScatter' TemporaryID(9ee1e208-eb30-46cc-bbc5-2786ea58b3c3) v0) and follow-on Job('CWLGather' TemporaryID(fddc734d-b34b-4379-8032-99448e4f2add) v0) [2021-11-19T14:07:49+0000] [MainThread] [D] [toil.cwl.cwltoil] Connect as child based on need for file:///builds/TnycNQM8/7/databiosphere/toil/src/toil/test/cwl/spec_v12/tests/conditionals/cond-wf-010_nojs.cwl#test from Job('SelfJob' TemporaryID(052104bc-14f7-41e0-b146-d2c8c00f6523) v0) [2021-11-19T14:07:49+0000] [MainThread] [D] [toil.cwl.cwltoil] Provides file:///builds/TnycNQM8/7/databiosphere/toil/src/toil/test/cwl/spec_v12/tests/conditionals/cond-wf-010_nojs.cwl#step1/out1 from Job('CWLGather' TemporaryID(fddc734d-b34b-4379-8032-99448e4f2add) v0) [2021-11-19T14:07:49+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Assigning ID to job 95cfa3be-cbb1-4ce0-a750-9a66ddff6118 for '' [2021-11-19T14:07:49+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Assigning ID to job 016db249-7148-46af-8ac9-9c46fdfa0cae for '' [2021-11-19T14:07:49+0000] [MainThread] [I] [toil.job] Saving graph of 3 jobs, 2 new [2021-11-19T14:07:49+0000] [MainThread] [D] [toil.job] Resolve promise e6e60d4e-e30c-43df-9df9-a63fda4e3c99 from Job('CWLWorkflow' 6cb53f56-3b3e-4ebb-9b19-f29b16af34f9 v1) with a [2021-11-19T14:07:49+0000] [MainThread] [D] [toil.job] Issuing promise c0868425-2aba-49c3-8ab1-f158c0791040 for result of 'CWLGather' 016db249-7148-46af-8ac9-9c46fdfa0cae v0 [2021-11-19T14:07:49+0000] [Thread-8 ] [D] [toil.jobStores.aws.jobStore] Inlining content of 185 bytes [2021-11-19T14:07:49+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Wrote FileInfo(fileID='c0868425-2aba-49c3-8ab1-f158c0791040', ownerID=None, encrypted=False, version='', previousVersion='', content=b"\x80\x05\x9...791040\x94ub.", checksum='', _numContentChunks=1) bound to . [2021-11-19T14:07:49+0000] [Thread-7 ] [D] [toil.jobStores.aws.jobStore] Starting sha1 checksum to match None [2021-11-19T14:07:49+0000] [Thread-7 ] [D] [toil.jobStores.aws.jobStore] Updating checksum with 967 bytes [2021-11-19T14:07:49+0000] [Thread-7 ] [D] [toil.jobStores.aws.jobStore] Starting multipart upload [2021-11-19T14:07:49+0000] [Thread-7 ] [D] [toil.jobStores.aws.jobStore] Multipart upload started as vtntNzUQJBWtEYet1E2_iGbUfaivb6vX6HUL8sxcRdXAvCzbuTscsN9S2G3Y4GpB08zFx0LtEU0xYwbhklnTV3AEFo0UJYHMqYVbxiajNd3mB2NHrjlWiOO_R8iU0R6A [2021-11-19T14:07:49+0000] [Thread-7 ] [D] [toil.jobStores.aws.jobStore] Multipart upload visible as vtntNzUQJBWtEYet1E2_iGbUfaivb6vX6HUL8sxcRdXAvCzbuTscsN9S2G3Y4GpB08zFx0LtEU0xYwbhklnTV3AEFo0UJYHMqYVbxiajNd3mB2NHrjlWiOO_R8iU0R6A [2021-11-19T14:07:49+0000] [Thread-7 ] [D] [toil.jobStores.aws.jobStore] Uploading part 1 of 967 bytes to vtntNzUQJBWtEYet1E2_iGbUfaivb6vX6HUL8sxcRdXAvCzbuTscsN9S2G3Y4GpB08zFx0LtEU0xYwbhklnTV3AEFo0UJYHMqYVbxiajNd3mB2NHrjlWiOO_R8iU0R6A [2021-11-19T14:07:49+0000] [Thread-7 ] [D] [toil.jobStores.aws.jobStore] Completed checksum with hash a41f50671ceba331cfecb3dd9993024b248ec060 vs. expected None [2021-11-19T14:07:49+0000] [Thread-7 ] [D] [toil.jobStores.aws.jobStore] Attempting to complete upload... [2021-11-19T14:07:49+0000] [Thread-7 ] [D] [toil.jobStores.aws.jobStore] Completed upload object of type : {'ResponseMetadata': {'RequestId': 'BHK1T2FCX25F2SA4', 'HostId': 'ptbavnKzY3z8xFPOGUjdPmbdEfHM5K9h70xT9fvCQIzz89VsIZ0P8SUxz3+7G1KDDQgTLwcCPfk=', 'HTTPStatusCode': 200, 'HTTPHeaders': {'x-amz-id-2': 'ptbavnKzY3z8xFPOGUjdPmbdEfHM5K9h70xT9fvCQIzz89VsIZ0P8SUxz3+7G1KDDQgTLwcCPfk=', 'x-amz-request-id': 'BHK1T2FCX25F2SA4', 'date': 'Fri, 19 Nov 2021 14:07:50 GMT', 'x-amz-version-id': 'TYnH86bkic6D53H7eS4BIu3wuuUUwwxw', 'content-type': 'application/xml', 'transfer-encoding': 'chunked', 'server': 'AmazonS3'}, 'RetryAttempts': 0}, 'VersionId': 'TYnH86bkic6D53H7eS4BIu3wuuUUwwxw', 'Location': 'https://toil-cwl-19398c8c-4067-4302-964d-e727a203e592--files.s3.us-west-2.amazonaws.com/e6e60d4e-e30c-43df-9df9-a63fda4e3c99', 'Bucket': 'toil-cwl-19398c8c-4067-4302-964d-e727a203e592--files', 'Key': 'e6e60d4e-e30c-43df-9df9-a63fda4e3c99', 'ETag': '"9f5cb0fda95077966fa1af8a672adced-1"'} [2021-11-19T14:07:49+0000] [Thread-7 ] [D] [toil.jobStores.aws.jobStore] Completed upload with version TYnH86bkic6D53H7eS4BIu3wuuUUwwxw [2021-11-19T14:07:49+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Wrote FileInfo(fileID='e6e60d4e-e30c-43df-9df9-a63fda4e3c99', ownerID='None', encrypted=False, version='TYnH86bkic6D53H7eS4BIu3wuuUUwwxw', previousVersion='TYnH86bkic6D53H7eS4BIu3wuuUUwwxw', content=None, checksum='sha1$a41f50671ce...d9993024b248ec060', _numContentChunks=0) bound to from stream. [2021-11-19T14:07:49+0000] [MainThread] [D] [toil.job] Resolve promise 37d45eab-08dc-48fc-b636-d3b6b338b243 from Job('CWLWorkflow' 6cb53f56-3b3e-4ebb-9b19-f29b16af34f9 v1) with a [2021-11-19T14:07:49+0000] [MainThread] [D] [toil.job] Issuing promise 3b1c3570-8cac-446b-8c70-bba03a90cf9d for result of 'CWLGather' 016db249-7148-46af-8ac9-9c46fdfa0cae v0 [2021-11-19T14:07:49+0000] [Thread-10 ] [D] [toil.jobStores.aws.jobStore] Inlining content of 185 bytes [2021-11-19T14:07:50+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Wrote FileInfo(fileID='3b1c3570-8cac-446b-8c70-bba03a90cf9d', ownerID=None, encrypted=False, version='', previousVersion='', content=b"\x80\x05\x9...90cf9d\x94ub.", checksum='', _numContentChunks=1) bound to . [2021-11-19T14:07:50+0000] [Thread-9 ] [D] [toil.jobStores.aws.jobStore] Starting sha1 checksum to match None [2021-11-19T14:07:50+0000] [Thread-9 ] [D] [toil.jobStores.aws.jobStore] Updating checksum with 967 bytes [2021-11-19T14:07:50+0000] [Thread-9 ] [D] [toil.jobStores.aws.jobStore] Starting multipart upload [2021-11-19T14:07:50+0000] [Thread-9 ] [D] [toil.jobStores.aws.jobStore] Multipart upload started as zkG7no8Rm5nt9hySH9PmpxZTpD5dtyHTkTlcArqHkK3iCw5RgkWc3q8b6M8uHPcps9aCIzRFQXKjukNGqT5kBzWp0PXMdM9iK.3eSpTHLqTmk8BCeUHHxiuONoWfElw4 [2021-11-19T14:07:50+0000] [Thread-9 ] [D] [toil.jobStores.aws.jobStore] Multipart upload visible as zkG7no8Rm5nt9hySH9PmpxZTpD5dtyHTkTlcArqHkK3iCw5RgkWc3q8b6M8uHPcps9aCIzRFQXKjukNGqT5kBzWp0PXMdM9iK.3eSpTHLqTmk8BCeUHHxiuONoWfElw4 [2021-11-19T14:07:50+0000] [Thread-9 ] [D] [toil.jobStores.aws.jobStore] Uploading part 1 of 967 bytes to zkG7no8Rm5nt9hySH9PmpxZTpD5dtyHTkTlcArqHkK3iCw5RgkWc3q8b6M8uHPcps9aCIzRFQXKjukNGqT5kBzWp0PXMdM9iK.3eSpTHLqTmk8BCeUHHxiuONoWfElw4 [2021-11-19T14:07:50+0000] [Thread-9 ] [D] [toil.jobStores.aws.jobStore] Completed checksum with hash da6d1b9c0e8e7b6e15a28c3e70e569372f2c3d5d vs. expected None [2021-11-19T14:07:50+0000] [Thread-9 ] [D] [toil.jobStores.aws.jobStore] Attempting to complete upload... [2021-11-19T14:07:50+0000] [Thread-9 ] [D] [toil.jobStores.aws.jobStore] Completed upload object of type : {'ResponseMetadata': {'RequestId': '7AQMMPCN81H8TVSW', 'HostId': 'V8pS7UWyuc1NtS8b+HigCTK+O215Rm62xiEKDDwBTb8YitCXuWdjGqD73R9XwQgOVH6BgDtZVW8=', 'HTTPStatusCode': 200, 'HTTPHeaders': {'x-amz-id-2': 'V8pS7UWyuc1NtS8b+HigCTK+O215Rm62xiEKDDwBTb8YitCXuWdjGqD73R9XwQgOVH6BgDtZVW8=', 'x-amz-request-id': '7AQMMPCN81H8TVSW', 'date': 'Fri, 19 Nov 2021 14:07:51 GMT', 'x-amz-version-id': 'aJ.0Hb6iQNJVvzcXwrmeGMlPfUKalLhC', 'content-type': 'application/xml', 'transfer-encoding': 'chunked', 'server': 'AmazonS3'}, 'RetryAttempts': 0}, 'VersionId': 'aJ.0Hb6iQNJVvzcXwrmeGMlPfUKalLhC', 'Location': 'https://toil-cwl-19398c8c-4067-4302-964d-e727a203e592--files.s3.us-west-2.amazonaws.com/37d45eab-08dc-48fc-b636-d3b6b338b243', 'Bucket': 'toil-cwl-19398c8c-4067-4302-964d-e727a203e592--files', 'Key': '37d45eab-08dc-48fc-b636-d3b6b338b243', 'ETag': '"7e036bc26fa1c90b92c2f55409ab6ca0-1"'} [2021-11-19T14:07:50+0000] [Thread-9 ] [D] [toil.jobStores.aws.jobStore] Completed upload with version aJ.0Hb6iQNJVvzcXwrmeGMlPfUKalLhC [2021-11-19T14:07:50+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Wrote FileInfo(fileID='37d45eab-08dc-48fc-b636-d3b6b338b243', ownerID='None', encrypted=False, version='aJ.0Hb6iQNJVvzcXwrmeGMlPfUKalLhC', previousVersion='aJ.0Hb6iQNJVvzcXwrmeGMlPfUKalLhC', content=None, checksum='sha1$da6d1b9c0e8...e70e569372f2c3d5d', _numContentChunks=0) bound to from stream. [2021-11-19T14:07:50+0000] [MainThread] [I] [toil.job] Processing job 'CWLGather' 016db249-7148-46af-8ac9-9c46fdfa0cae v0 [2021-11-19T14:07:50+0000] [MainThread] [D] [toil.job] Issuing promise 4e733285-8a77-4f40-a6ae-bc74df4c540f for result of 'CWLScatter' 95cfa3be-cbb1-4ce0-a750-9a66ddff6118 v0 [2021-11-19T14:07:50+0000] [Thread-12 ] [D] [toil.jobStores.aws.jobStore] Inlining content of 186 bytes [2021-11-19T14:07:50+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Wrote FileInfo(fileID='4e733285-8a77-4f40-a6ae-bc74df4c540f', ownerID=None, encrypted=False, version='', previousVersion='', content=b"\x80\x05\x9...4c540f\x94ub.", checksum='', _numContentChunks=1) bound to . [2021-11-19T14:07:50+0000] [Thread-11 ] [D] [toil.jobStores.aws.jobStore] Starting sha1 checksum to match None [2021-11-19T14:07:50+0000] [Thread-11 ] [D] [toil.jobStores.aws.jobStore] Updating checksum with 196599 bytes [2021-11-19T14:07:50+0000] [Thread-11 ] [D] [toil.jobStores.aws.jobStore] Starting multipart upload [2021-11-19T14:07:50+0000] [Thread-11 ] [D] [toil.jobStores.aws.jobStore] Multipart upload started as CvCnLw7BWSBGxuElTlGDj9kR_gNa9sXa.DHXd388cDizipc7A2PEuesJ_zmS3Z9MceR.TiA1e0J5I1sg.4tXTZSIZD1qv9S9SQ65JbTbjS0GTUQSZdYGYnGX8MUmTnE8 [2021-11-19T14:07:50+0000] [Thread-11 ] [D] [toil.jobStores.aws.jobStore] Multipart upload visible as CvCnLw7BWSBGxuElTlGDj9kR_gNa9sXa.DHXd388cDizipc7A2PEuesJ_zmS3Z9MceR.TiA1e0J5I1sg.4tXTZSIZD1qv9S9SQ65JbTbjS0GTUQSZdYGYnGX8MUmTnE8 [2021-11-19T14:07:50+0000] [Thread-11 ] [D] [toil.jobStores.aws.jobStore] Uploading part 1 of 196599 bytes to CvCnLw7BWSBGxuElTlGDj9kR_gNa9sXa.DHXd388cDizipc7A2PEuesJ_zmS3Z9MceR.TiA1e0J5I1sg.4tXTZSIZD1qv9S9SQ65JbTbjS0GTUQSZdYGYnGX8MUmTnE8 [2021-11-19T14:07:50+0000] [Thread-11 ] [D] [toil.jobStores.aws.jobStore] Completed checksum with hash fff2df07fee4f3b07e8a41b9e7d6aa394978ff99 vs. expected None [2021-11-19T14:07:50+0000] [Thread-11 ] [D] [toil.jobStores.aws.jobStore] Attempting to complete upload... [2021-11-19T14:07:50+0000] [Thread-11 ] [D] [toil.jobStores.aws.jobStore] Completed upload object of type : {'ResponseMetadata': {'RequestId': '7AQPFVCX1FVGS6ZQ', 'HostId': 'ZF871qAHwfHeHVLOWB4qZZ90qBHieg2E3vHtyYBeUed4dUkTFzj7vvC0cRHngHtd/9HVyDe5lj4=', 'HTTPStatusCode': 200, 'HTTPHeaders': {'x-amz-id-2': 'ZF871qAHwfHeHVLOWB4qZZ90qBHieg2E3vHtyYBeUed4dUkTFzj7vvC0cRHngHtd/9HVyDe5lj4=', 'x-amz-request-id': '7AQPFVCX1FVGS6ZQ', 'date': 'Fri, 19 Nov 2021 14:07:51 GMT', 'x-amz-version-id': '8.5FS4o0XimQOWt0FayOMEOELPRl8vuB', 'content-type': 'application/xml', 'transfer-encoding': 'chunked', 'server': 'AmazonS3'}, 'RetryAttempts': 0}, 'VersionId': '8.5FS4o0XimQOWt0FayOMEOELPRl8vuB', 'Location': 'https://toil-cwl-19398c8c-4067-4302-964d-e727a203e592--files.s3.us-west-2.amazonaws.com/f1af8906-715e-4ce1-a45c-6920c4b12b2d', 'Bucket': 'toil-cwl-19398c8c-4067-4302-964d-e727a203e592--files', 'Key': 'f1af8906-715e-4ce1-a45c-6920c4b12b2d', 'ETag': '"9bf84ed19d95b5b6f0afed9729269e07-1"'} [2021-11-19T14:07:50+0000] [Thread-11 ] [D] [toil.jobStores.aws.jobStore] Completed upload with version 8.5FS4o0XimQOWt0FayOMEOELPRl8vuB [2021-11-19T14:07:50+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Wrote FileInfo(fileID='f1af8906-715e-4ce1-a45c-6920c4b12b2d', ownerID='016db249-7148-46af-8ac9-9c46fdfa0cae', encrypted=False, version='8.5FS4o0XimQOWt0FayOMEOELPRl8vuB', previousVersion='8.5FS4o0XimQOWt0FayOMEOELPRl8vuB', content=None, checksum='sha1$fff2df07fee...9e7d6aa394978ff99', _numContentChunks=0) bound to . [2021-11-19T14:07:50+0000] [MainThread] [I] [toil.job] Processing job 'CWLScatter' 95cfa3be-cbb1-4ce0-a750-9a66ddff6118 v0 [2021-11-19T14:07:50+0000] [Thread-13 ] [D] [toil.jobStores.aws.jobStore] Starting sha1 checksum to match None [2021-11-19T14:07:50+0000] [Thread-13 ] [D] [toil.jobStores.aws.jobStore] Updating checksum with 200854 bytes [2021-11-19T14:07:50+0000] [Thread-13 ] [D] [toil.jobStores.aws.jobStore] Starting multipart upload [2021-11-19T14:07:50+0000] [Thread-13 ] [D] [toil.jobStores.aws.jobStore] Multipart upload started as FhzCDN4nQ9VR22XiJoPjvTzXZarGT5GuPHzt2SZl5xrEZ_rA1j4Sodp9tHLCb3Dj1a_aF6nzo_m.oK2BC5tMYt53PgObHYFznu5v3zKwYjNDy6b3vcOQsAAABefkcRkT [2021-11-19T14:07:50+0000] [Thread-13 ] [D] [toil.jobStores.aws.jobStore] Multipart upload visible as FhzCDN4nQ9VR22XiJoPjvTzXZarGT5GuPHzt2SZl5xrEZ_rA1j4Sodp9tHLCb3Dj1a_aF6nzo_m.oK2BC5tMYt53PgObHYFznu5v3zKwYjNDy6b3vcOQsAAABefkcRkT [2021-11-19T14:07:50+0000] [Thread-13 ] [D] [toil.jobStores.aws.jobStore] Uploading part 1 of 200854 bytes to FhzCDN4nQ9VR22XiJoPjvTzXZarGT5GuPHzt2SZl5xrEZ_rA1j4Sodp9tHLCb3Dj1a_aF6nzo_m.oK2BC5tMYt53PgObHYFznu5v3zKwYjNDy6b3vcOQsAAABefkcRkT [2021-11-19T14:07:51+0000] [Thread-13 ] [D] [toil.jobStores.aws.jobStore] Completed checksum with hash 159b2cce59da8dee9a8f6a4f66b9cc6dcc7f6900 vs. expected None [2021-11-19T14:07:51+0000] [Thread-13 ] [D] [toil.jobStores.aws.jobStore] Attempting to complete upload... [2021-11-19T14:07:51+0000] [Thread-13 ] [D] [toil.jobStores.aws.jobStore] Completed upload object of type : {'ResponseMetadata': {'RequestId': '9HKCTRSZX5FNZXY6', 'HostId': 'uXu84IHYJyF0ka/v18DfZTZV6TLS8j0NTicVqGcxZw8flmTue1qrBVYRkKMsK5ZC1TR4rSWn6vo=', 'HTTPStatusCode': 200, 'HTTPHeaders': {'x-amz-id-2': 'uXu84IHYJyF0ka/v18DfZTZV6TLS8j0NTicVqGcxZw8flmTue1qrBVYRkKMsK5ZC1TR4rSWn6vo=', 'x-amz-request-id': '9HKCTRSZX5FNZXY6', 'date': 'Fri, 19 Nov 2021 14:07:52 GMT', 'x-amz-version-id': 'Wm4LgZ0YIwFmj9sv8am_QC4ExP3JHRC.', 'content-type': 'application/xml', 'transfer-encoding': 'chunked', 'server': 'AmazonS3'}, 'RetryAttempts': 0}, 'VersionId': 'Wm4LgZ0YIwFmj9sv8am_QC4ExP3JHRC.', 'Location': 'https://toil-cwl-19398c8c-4067-4302-964d-e727a203e592--files.s3.us-west-2.amazonaws.com/5401125e-3a47-4682-b71c-c645020763af', 'Bucket': 'toil-cwl-19398c8c-4067-4302-964d-e727a203e592--files', 'Key': '5401125e-3a47-4682-b71c-c645020763af', 'ETag': '"9e48911d92569e91ddcbf52a6cd527e9-1"'} [2021-11-19T14:07:51+0000] [Thread-13 ] [D] [toil.jobStores.aws.jobStore] Completed upload with version Wm4LgZ0YIwFmj9sv8am_QC4ExP3JHRC. [2021-11-19T14:07:51+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Wrote FileInfo(fileID='5401125e-3a47-4682-b71c-c645020763af', ownerID='95cfa3be-cbb1-4ce0-a750-9a66ddff6118', encrypted=False, version='Wm4LgZ0YIwFmj9sv8am_QC4ExP3JHRC.', previousVersion='Wm4LgZ0YIwFmj9sv8am_QC4ExP3JHRC.', content=None, checksum='sha1$159b2cce59d...f66b9cc6dcc7f6900', _numContentChunks=0) bound to . [2021-11-19T14:07:51+0000] [MainThread] [I] [toil.job] Processing job 'CWLWorkflow' 6cb53f56-3b3e-4ebb-9b19-f29b16af34f9 v1 [2021-11-19T14:07:51+0000] [MainThread] [D] [toil.job] New job version: 'CWLGather' 016db249-7148-46af-8ac9-9c46fdfa0cae v1 [2021-11-19T14:07:51+0000] [MainThread] [D] [toil.job] New job version: 'CWLScatter' 95cfa3be-cbb1-4ce0-a750-9a66ddff6118 v1 [2021-11-19T14:07:51+0000] [MainThread] [D] [toil.fileStores.abstractFileStore] LOG-TO-MASTER: Job 'CWLWorkflow' 6cb53f56-3b3e-4ebb-9b19-f29b16af34f9 v1 used 0.00% disk (0 bB [0B] used, 1.0 MiB [1048576B] requested). [2021-11-19T14:07:51+0000] [MainThread] [D] [toil.deferred] Running own deferred functions [2021-11-19T14:07:51+0000] [MainThread] [D] [toil.deferred] Out of deferred functions! [2021-11-19T14:07:51+0000] [MainThread] [D] [toil.deferred] Running orphaned deferred functions [2021-11-19T14:07:51+0000] [MainThread] [I] [toil.worker] Completed body for 'CWLWorkflow' 6cb53f56-3b3e-4ebb-9b19-f29b16af34f9 v1 [2021-11-19T14:07:51+0000] [Thread-14 ] [D] [toil.fileStores.cachingFileStore] Committing file uploads asynchronously [2021-11-19T14:07:51+0000] [MainThread] [D] [toil.worker] Stopping running chain of jobs because job has both children and follow-ons [2021-11-19T14:07:51+0000] [MainThread] [I] [toil.worker] Not chaining from job 'CWLWorkflow' 6cb53f56-3b3e-4ebb-9b19-f29b16af34f9 v1 [2021-11-19T14:07:51+0000] [MainThread] [I] [toil.worker] Worker log can be found at /var/lib/toil/d6f7b2f2da0c53e9909e3a68ec923a5a/a375. Set --cleanWorkDir to retain this log [2021-11-19T14:07:51+0000] [MainThread] [I] [toil.worker] Finished running the chain of jobs on this node, we ran for a total of 1.820929 seconds [2021-11-19T14:07:51+0000] [Thread-14 ] [D] [toil.fileStores.cachingFileStore] Committing file deletes and job state changes asynchronously [2021-11-19T14:07:51+0000] [Thread-14 ] [D] [toil.jobStores.aws.jobStore] Updating job 6cb53f56-3b3e-4ebb-9b19-f29b16af34f9 [2021-11-19T14:07:51+0000] [Thread-14 ] [D] [toil.job] New job version: 'CWLWorkflow' 6cb53f56-3b3e-4ebb-9b19-f29b16af34f9 v2 <========= [2021-11-19T14:07:51+0000] [Thread-3 ] [D] [toil.batchSystems.singleMachine] Child 56547 for job 0 succeeded [2021-11-19T14:07:52+0000] [MainThread] [D] [toil.batchSystems.singleMachine] Ran jobID: 0 with exit value: 0 [2021-11-19T14:07:52+0000] [MainThread] [D] [toil.leader] Job ended: 'CWLWorkflow' 6cb53f56-3b3e-4ebb-9b19-f29b16af34f9 v1 [2021-11-19T14:07:52+0000] [MainThread] [D] [toil.leader] Job 'CWLWorkflow' 6cb53f56-3b3e-4ebb-9b19-f29b16af34f9 v1 continues to exist (i.e. has more to do) [2021-11-19T14:07:52+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Loaded job 6cb53f56-3b3e-4ebb-9b19-f29b16af34f9 [2021-11-19T14:07:52+0000] [MainThread] [D] [toil.bus] processFinishedJob sent: JobUpdatedMessage(job_id='6cb53f56-3b3e-4ebb-9b19-f29b16af34f9', result_status=0) [2021-11-19T14:07:52+0000] [MainThread] [D] [toil.leader] Added job: 'CWLWorkflow' 6cb53f56-3b3e-4ebb-9b19-f29b16af34f9 v2 to updated jobs [2021-11-19T14:07:52+0000] [MainThread] [D] [toil.leader] Built the jobs list, currently have 1 jobs to update and 0 jobs issued [2021-11-19T14:07:52+0000] [MainThread] [D] [toil.leader] Updating status of job 'CWLWorkflow' 6cb53f56-3b3e-4ebb-9b19-f29b16af34f9 v2 with result status: 0 [2021-11-19T14:07:52+0000] [MainThread] [D] [toil.leader] Job: 6cb53f56-3b3e-4ebb-9b19-f29b16af34f9 has 1 successors to schedule [2021-11-19T14:07:52+0000] [MainThread] [D] [toil.toilState] Successors: 1 more for 6cb53f56-3b3e-4ebb-9b19-f29b16af34f9, now have 1 [2021-11-19T14:07:52+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Loaded job 95cfa3be-cbb1-4ce0-a750-9a66ddff6118 [2021-11-19T14:07:52+0000] [MainThread] [D] [toil.leader] Added job 'CWLScatter' 95cfa3be-cbb1-4ce0-a750-9a66ddff6118 v1 as coming after job 'CWLWorkflow' 6cb53f56-3b3e-4ebb-9b19-f29b16af34f9 v2 [2021-11-19T14:07:52+0000] [MainThread] [D] [toil.batchSystems.singleMachine] Issuing the command: _toil_worker CWLScatter aws:us-west-2:toil-cwl-19398c8c-4067-4302-964d-e727a203e592 95cfa3be-cbb1-4ce0-a750-9a66ddff6118 --context gASVzAAAAAAAAACMIXRvaWwuYmF0Y2hTeXN0ZW1zLmNsZWFudXBfc3VwcG9ydJSMFFdvcmtlckNsZWFudXBDb250ZXh0lJOUKYGUfZSMEXdvcmtlckNsZWFudXBJbmZvlIwldG9pbC5iYXRjaFN5c3RlbXMuYWJzdHJhY3RCYXRjaFN5c3RlbZSMEVdvcmtlckNsZWFudXBJbmZvlJOUTowkNzQ2MTM4ZmMtNTkwNS00NjdjLTkwMDQtNTFkMjZmZTU2ZjQylIwGYWx3YXlzlIeUgZRzYi4= with memory: 1073741824, cores: 1.0, disk: 1048576 [2021-11-19T14:07:52+0000] [MainThread] [D] [toil.leader] Issued job 'CWLScatter' 95cfa3be-cbb1-4ce0-a750-9a66ddff6118 v1 with job batch system ID: 1 and cores: 1, disk: 1.0 Mi, and memory: 1.0 Gi [2021-11-19T14:07:52+0000] [Thread-3 ] [D] [toil.batchSystems.singleMachine] Launched job 1 as child 56643 [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.statsAndLogging] Suppressing the following loggers: {'requests_oauthlib', 'salad', 'cachecontrol', 'charset_normalizer', 'urllib3', 'docker', 'rsa', 'humanfriendly', 'botocore', 'oauthlib', 'rdflib', 'boto3', 'requests', 'pyasn1', 'google', 'prov', 'bcdocs', 'kubernetes', 'dill', 's3transfer', 'boto', 'concurrent', 'websocket', 'galaxy'} [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Reading FileInfo(fileID='01c37f76-e635-5f9c-ad18-6ed1ae1b2e2a', ownerID='891f7db6-e4d9-4221-a58e-ab6cc4395f94', encrypted=False, version='UUo7vOfUjtlCSuYlNVmOFxxMuUHa339.', previousVersion='UUo7vOfUjtlCSuYlNVmOFxxMuUHa339.', content=None, checksum='sha1$826e5b08649...2ed9102c916135798', _numContentChunks=0) bound to for shared file 'environment.pickle' into stream. [2021-11-19T14:07:54+0000] [Thread-4 ] [D] [toil.jobStores.aws.jobStore] Starting sha1 checksum to match 826e5b08649553c26056dd62ed9102c916135798 [2021-11-19T14:07:54+0000] [Thread-4 ] [D] [toil.jobStores.aws.jobStore] Completed checksum with hash 826e5b08649553c26056dd62ed9102c916135798 vs. expected 826e5b08649553c26056dd62ed9102c916135798 [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.common] Obtained node ID 2be9d21dd2f7a450ea7b7fea618779d1 from file /var/lib/dbus/machine-id [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.common] Created the workflow directory for this machine at /var/lib/toil/d6f7b2f2da0c53e9909e3a68ec923a5a [2021-11-19T14:07:54+0000] [MainThread] [I] [toil.worker] Redirecting logging to /var/lib/toil/d6f7b2f2da0c53e9909e3a68ec923a5a/158e/worker_log.txt [2021-11-19T14:07:57+0000] [Thread-21 ] [D] [toil.jobStores.aws.jobStore] Starting sha1 checksum to match None [2021-11-19T14:07:57+0000] [Thread-21 ] [D] [toil.jobStores.aws.jobStore] Completed checksum with hash ddfda51052522f6da5b18e6bbb1a8db0f00a9191 vs. expected None [2021-11-19T14:07:57+0000] [Thread-21 ] [D] [toil.jobStores.aws.jobStore] Uploading single part of 37139 bytes [2021-11-19T14:07:57+0000] [Thread-21 ] [D] [toil.jobStores.aws.jobStore] Upload received version 1jCKQneRCjtVWoYT96dz.Ikl8eYcmXG6 [2021-11-19T14:07:57+0000] [MainThread] [D] [toil.deferred] Deleting /var/lib/toil/d6f7b2f2da0c53e9909e3a68ec923a5a/deferred/func57b5hb60 [2021-11-19T14:07:57+0000] [MainThread] [D] [toil.lib.threading] Leaving arena /var/lib/toil/746138fc-5905-467c-9004-51d26fe56f42-cleanup-arena-members [2021-11-19T14:07:57+0000] [MainThread] [D] [toil.lib.threading] PID 56644 acquiring mutex /var/lib/toil/toil-mutex-746138fc-5905-467c-9004-51d26fe56f42-cleanup-arena-lock [2021-11-19T14:07:57+0000] [MainThread] [D] [toil.lib.threading] PID 56644 now holds mutex /var/lib/toil/toil-mutex-746138fc-5905-467c-9004-51d26fe56f42-cleanup-arena-lock [2021-11-19T14:07:57+0000] [MainThread] [D] [toil.lib.threading] We are the Last Process Standing in arena /var/lib/toil/746138fc-5905-467c-9004-51d26fe56f42-cleanup-arena-members [2021-11-19T14:07:57+0000] [MainThread] [D] [toil.batchSystems.cleanup_support] Cleaning up worker [2021-11-19T14:07:57+0000] [MainThread] [D] [toil.common] Obtained node ID 2be9d21dd2f7a450ea7b7fea618779d1 from file /var/lib/dbus/machine-id [2021-11-19T14:07:57+0000] [MainThread] [D] [toil.deferred] Cleaning up deferred functions system [2021-11-19T14:07:57+0000] [MainThread] [D] [toil.deferred] Running for file /var/lib/toil/d6f7b2f2da0c53e9909e3a68ec923a5a/deferred/funcifknm3ct [2021-11-19T14:07:57+0000] [MainThread] [D] [toil.deferred] Running orphaned deferred functions [2021-11-19T14:07:57+0000] [MainThread] [D] [toil.deferred] Deleting /var/lib/toil/d6f7b2f2da0c53e9909e3a68ec923a5a/deferred/funcifknm3ct [2021-11-19T14:07:57+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Connecting to latest caching database cache-0.db for cleanup [2021-11-19T14:07:57+0000] [MainThread] [D] [toil.lib.threading] PID 56644 releasing mutex /var/lib/toil/toil-mutex-746138fc-5905-467c-9004-51d26fe56f42-cleanup-arena-lock [2021-11-19T14:07:57+0000] [MainThread] [D] [toil.lib.threading] Now out of arena /var/lib/toil/746138fc-5905-467c-9004-51d26fe56f42-cleanup-arena-members [2021-11-19T14:07:57+0000] [Thread-16 ] [D] [toil.jobStores.aws.jobStore] Starting sha1 checksum to match ddfda51052522f6da5b18e6bbb1a8db0f00a9191 [2021-11-19T14:07:57+0000] [Thread-16 ] [D] [toil.jobStores.aws.jobStore] Completed checksum with hash ddfda51052522f6da5b18e6bbb1a8db0f00a9191 vs. expected ddfda51052522f6da5b18e6bbb1a8db0f00a9191 [2021-11-19T14:07:57+0000] [Thread-12 ] [D] [toil.statsAndLogging] Got message from job at time 11-19-2021 14:07:57: Job 'CWLScatter' 95cfa3be-cbb1-4ce0-a750-9a66ddff6118 v1 used 0.00% disk (0 bB [0B] used, 1.0 MiB [1048576B] requested). [2021-11-19T14:07:57+0000] [Thread-12 ] [D] [toil.statsAndLogging] Received Toil worker log. Disable debug level logging to hide this output [2021-11-19T14:07:57+0000] [Thread-12 ] [D] [toil.statsAndLogging] Log from job "'CWLScatter' 95cfa3be-cbb1-4ce0-a750-9a66ddff6118 v1" follows: =========> [2021-11-19T14:07:54+0000] [MainThread] [I] [toil.worker] ---TOIL WORKER OUTPUT LOG--- [2021-11-19T14:07:54+0000] [MainThread] [I] [toil] Running Toil version 5.6.0a1-604176544d7178bb415a1dd98f0084d1a1b7f65b on host runner-tnycnqm8-project-3-concurrent-75jcr5. [2021-11-19T14:07:54+0000] [MainThread] [D] [toil] Configuration: {'workflowID': '746138fc-5905-467c-9004-51d26fe56f42', 'workflowAttemptNumber': 0, 'jobStore': 'aws:us-west-2:toil-cwl-19398c8c-4067-4302-964d-e727a203e592', 'logLevel': 'DEBUG', 'workDir': None, 'noStdOutErr': False, 'stats': False, 'clean': 'always', 'cleanWorkDir': 'always', 'clusterStats': None, 'restart': False, 'batchSystem': 'kubernetes', 'disableAutoDeployment': False, 'maxLocalJobs': 4, 'manualMemArgs': False, 'coalesceStatusCalls': False, 'statePollingWait': None, 'parasolCommand': 'parasol', 'parasolMaxBatches': 10000, 'scale': 1.0, 'allocate_mem': False, 'tes_endpoint': 'http://10.244.1.58:8000', 'tes_user': None, 'tes_password': None, 'tes_bearer_token': None, 'kubernetes_host_path': '/data/scratch', 'kubernetes_owner': 'toiltest', 'runCwlInternalJobsOnWorkers': False, 'disableCaching': False, 'linkImports': True, 'moveExports': False, 'provisioner': None, 'nodeTypes': [], 'minNodes': None, 'maxNodes': [10], 'targetTime': 1800, 'betaInertia': 0.1, 'scaleInterval': 60, 'preemptableCompensation': 0.0, 'nodeStorage': 50, 'nodeStorageOverrides': [], 'metrics': False, 'maxPreemptableServiceJobs': 9223372036854775807, 'maxServiceJobs': 9223372036854775807, 'deadlockWait': 60, 'deadlockCheckInterval': 30, 'defaultMemory': 2147483648, 'defaultCores': 1, 'defaultDisk': 2147483648, 'readGlobalFileMutableByDefault': False, 'defaultPreemptable': False, 'maxCores': 9223372036854775807, 'maxMemory': 9223372036854775807, 'maxDisk': 9223372036854775807, 'retryCount': 1, 'enableUnlimitedPreemptableRetries': False, 'doubleMem': False, 'maxJobDuration': 9223372036854775807, 'rescueJobsFrequency': 3600, 'environment': {'SINGULARITY_DOCKER_HUB_MIRROR': None}, 'disableChaining': False, 'disableJobStoreChecksumVerification': False, 'maxLogFileSize': 64000, 'writeLogs': None, 'writeLogsGzip': None, 'writeLogsFromAllJobs': False, 'sseKey': None, 'servicePollingInterval': 60, 'useAsync': True, 'forceDockerAppliance': False, 'statusWait': 3600, 'disableProgress': False, 'debugWorker': False, 'disableWorkerOutputCapture': False, 'badWorker': 0.0, 'badWorkerFailInterval': 0.01, 'cwl': False} [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.deferred] Running for file /var/lib/toil/d6f7b2f2da0c53e9909e3a68ec923a5a/deferred/func57b5hb60 [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Loaded job 95cfa3be-cbb1-4ce0-a750-9a66ddff6118 [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.worker] Parsed job description [2021-11-19T14:07:54+0000] [MainThread] [I] [toil.worker] Working on job 'CWLScatter' 95cfa3be-cbb1-4ce0-a750-9a66ddff6118 v1 [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.worker] Got a command to run: _toil 5401125e-3a47-4682-b71c-c645020763af /builds/TnycNQM8/7/databiosphere/toil/src toil.cwl.cwltoil False [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.job] Loading user module ModuleDescriptor(dirPath='/builds/TnycNQM8/7/databiosphere/toil/src', name='toil.cwl.cwltoil', fromVirtualEnv=False). [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Reading FileInfo(fileID='5401125e-3a47-4682-b71c-c645020763af', ownerID='95cfa3be-cbb1-4ce0-a750-9a66ddff6118', encrypted=False, version='Wm4LgZ0YIwFmj9sv8am_QC4ExP3JHRC.', previousVersion='Wm4LgZ0YIwFmj9sv8am_QC4ExP3JHRC.', content=None, checksum='sha1$159b2cce59d...f66b9cc6dcc7f6900', _numContentChunks=0) bound to into stream. [2021-11-19T14:07:54+0000] [Thread-6 ] [D] [toil.jobStores.aws.jobStore] Starting sha1 checksum to match 159b2cce59da8dee9a8f6a4f66b9cc6dcc7f6900 [2021-11-19T14:07:54+0000] [Thread-6 ] [D] [toil.jobStores.aws.jobStore] Completed checksum with hash 159b2cce59da8dee9a8f6a4f66b9cc6dcc7f6900 vs. expected 159b2cce59da8dee9a8f6a4f66b9cc6dcc7f6900 [2021-11-19T14:07:54+0000] [MainThread] [I] [toil.worker] Loaded body Job('CWLScatter' 95cfa3be-cbb1-4ce0-a750-9a66ddff6118 v1) from description 'CWLScatter' 95cfa3be-cbb1-4ce0-a750-9a66ddff6118 v1 [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Starting job ('CWLScatter' 95cfa3be-cbb1-4ce0-a750-9a66ddff6118 v1) with ID (95cfa3be-cbb1-4ce0-a750-9a66ddff6118). [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.deferred] Running orphaned deferred functions [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.deferred] Running job [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Actually running job ('CWLScatter' 95cfa3be-cbb1-4ce0-a750-9a66ddff6118 v1) with ID (95cfa3be-cbb1-4ce0-a750-9a66ddff6118) which wants 1048576 of our 2671377055744 bytes. [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Max space: 2671377055744 [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Total file size: 0 [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Total job disk requirement size: 1048576 [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Total immutable reference size: 0 [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Available space with job: 2671376007168 bytes [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.cwl.cwltoil] Make job for tool: ToilCommandLineTool('file:///builds/TnycNQM8/7/databiosphere/toil/src/toil/test/cwl/spec_v12/tests/conditionals/foo.cwl') [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.resource] Module dir is /builds/TnycNQM8/7/databiosphere/toil/src, our prefix is /builds/TnycNQM8/7/databiosphere/toil/venv, virtualenv: True [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.cwl.cwltoil] Make job for tool: ToilCommandLineTool('file:///builds/TnycNQM8/7/databiosphere/toil/src/toil/test/cwl/spec_v12/tests/conditionals/foo.cwl') [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.resource] Module dir is /builds/TnycNQM8/7/databiosphere/toil/src, our prefix is /builds/TnycNQM8/7/databiosphere/toil/venv, virtualenv: True [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.cwl.cwltoil] Make job for tool: ToilCommandLineTool('file:///builds/TnycNQM8/7/databiosphere/toil/src/toil/test/cwl/spec_v12/tests/conditionals/foo.cwl') [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.resource] Module dir is /builds/TnycNQM8/7/databiosphere/toil/src, our prefix is /builds/TnycNQM8/7/databiosphere/toil/venv, virtualenv: True [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.cwl.cwltoil] Make job for tool: ToilCommandLineTool('file:///builds/TnycNQM8/7/databiosphere/toil/src/toil/test/cwl/spec_v12/tests/conditionals/foo.cwl') [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.resource] Module dir is /builds/TnycNQM8/7/databiosphere/toil/src, our prefix is /builds/TnycNQM8/7/databiosphere/toil/venv, virtualenv: True [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.cwl.cwltoil] Make job for tool: ToilCommandLineTool('file:///builds/TnycNQM8/7/databiosphere/toil/src/toil/test/cwl/spec_v12/tests/conditionals/foo.cwl') [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.resource] Module dir is /builds/TnycNQM8/7/databiosphere/toil/src, our prefix is /builds/TnycNQM8/7/databiosphere/toil/venv, virtualenv: True [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.cwl.cwltoil] Make job for tool: ToilCommandLineTool('file:///builds/TnycNQM8/7/databiosphere/toil/src/toil/test/cwl/spec_v12/tests/conditionals/foo.cwl') [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.resource] Module dir is /builds/TnycNQM8/7/databiosphere/toil/src, our prefix is /builds/TnycNQM8/7/databiosphere/toil/venv, virtualenv: True [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Assigning ID to job 83f640fe-9544-49ac-b0d9-936c7a275ea3 for '' [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Assigning ID to job 692c58c7-3a47-4eb7-85c8-e0985f57f305 for '' [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Assigning ID to job 9eb39b4a-6641-4a16-990c-761c5e880ad1 for '' [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Assigning ID to job ec12b4e1-6da8-42aa-8e7f-18d43b243743 for '' [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Assigning ID to job a9f944fe-525a-4718-b868-05ef26e0411c for '' [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Assigning ID to job 6ca66447-352c-4e3a-970d-6b483ec82646 for '' [2021-11-19T14:07:54+0000] [MainThread] [I] [toil.job] Saving graph of 7 jobs, 6 new [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.job] Resolve promise 4e733285-8a77-4f40-a6ae-bc74df4c540f from Job('CWLScatter' 95cfa3be-cbb1-4ce0-a750-9a66ddff6118 v1) with a [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.job] Issuing promise f56d8f36-d5f0-4af7-8073-d794c2d2a0a3 for result of 'CWLJob' echo 83f640fe-9544-49ac-b0d9-936c7a275ea3 v0 [2021-11-19T14:07:54+0000] [Thread-8 ] [D] [toil.jobStores.aws.jobStore] Inlining content of 187 bytes [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Wrote FileInfo(fileID='f56d8f36-d5f0-4af7-8073-d794c2d2a0a3', ownerID=None, encrypted=False, version='', previousVersion='', content=b"\x80\x05\x9...d2a0a3\x94ub.", checksum='', _numContentChunks=1) bound to . [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.job] Issuing promise d88dfda4-5d8a-4a6d-acfd-697de89b74b2 for result of 'CWLJob' echo 692c58c7-3a47-4eb7-85c8-e0985f57f305 v0 [2021-11-19T14:07:54+0000] [Thread-9 ] [D] [toil.jobStores.aws.jobStore] Inlining content of 187 bytes [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Wrote FileInfo(fileID='d88dfda4-5d8a-4a6d-acfd-697de89b74b2', ownerID=None, encrypted=False, version='', previousVersion='', content=b"\x80\x05\x9...9b74b2\x94ub.", checksum='', _numContentChunks=1) bound to . [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.job] Issuing promise 85c4ac5e-051c-40ee-8101-582b088f5c1f for result of 'CWLJob' echo 9eb39b4a-6641-4a16-990c-761c5e880ad1 v0 [2021-11-19T14:07:54+0000] [Thread-10 ] [D] [toil.jobStores.aws.jobStore] Inlining content of 187 bytes [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Wrote FileInfo(fileID='85c4ac5e-051c-40ee-8101-582b088f5c1f', ownerID=None, encrypted=False, version='', previousVersion='', content=b"\x80\x05\x9...8f5c1f\x94ub.", checksum='', _numContentChunks=1) bound to . [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.job] Issuing promise 334da90e-9222-4921-937c-256038c38164 for result of 'CWLJob' echo ec12b4e1-6da8-42aa-8e7f-18d43b243743 v0 [2021-11-19T14:07:54+0000] [Thread-11 ] [D] [toil.jobStores.aws.jobStore] Inlining content of 187 bytes [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Wrote FileInfo(fileID='334da90e-9222-4921-937c-256038c38164', ownerID=None, encrypted=False, version='', previousVersion='', content=b"\x80\x05\x9...c38164\x94ub.", checksum='', _numContentChunks=1) bound to . [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.job] Issuing promise 4b8a2991-085d-4493-a163-75849885e075 for result of 'CWLJob' echo a9f944fe-525a-4718-b868-05ef26e0411c v0 [2021-11-19T14:07:54+0000] [Thread-12 ] [D] [toil.jobStores.aws.jobStore] Inlining content of 187 bytes [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Wrote FileInfo(fileID='4b8a2991-085d-4493-a163-75849885e075', ownerID=None, encrypted=False, version='', previousVersion='', content=b"\x80\x05\x9...85e075\x94ub.", checksum='', _numContentChunks=1) bound to . [2021-11-19T14:07:54+0000] [MainThread] [D] [toil.job] Issuing promise bd458e00-c135-418b-bd2c-3cc500e6a182 for result of 'CWLJob' echo 6ca66447-352c-4e3a-970d-6b483ec82646 v0 [2021-11-19T14:07:54+0000] [Thread-13 ] [D] [toil.jobStores.aws.jobStore] Inlining content of 187 bytes [2021-11-19T14:07:55+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Wrote FileInfo(fileID='bd458e00-c135-418b-bd2c-3cc500e6a182', ownerID=None, encrypted=False, version='', previousVersion='', content=b"\x80\x05\x9...e6a182\x94ub.", checksum='', _numContentChunks=1) bound to . [2021-11-19T14:07:55+0000] [Thread-7 ] [D] [toil.jobStores.aws.jobStore] Starting sha1 checksum to match None [2021-11-19T14:07:55+0000] [Thread-7 ] [D] [toil.jobStores.aws.jobStore] Updating checksum with 379 bytes [2021-11-19T14:07:55+0000] [Thread-7 ] [D] [toil.jobStores.aws.jobStore] Starting multipart upload [2021-11-19T14:07:55+0000] [Thread-7 ] [D] [toil.jobStores.aws.jobStore] Multipart upload started as pqdFAHqqs4eFfFVFB4V5AJ7W6nQcHA0Jjg2i4NsLbgYwCRDpMh6r1fhEFKpxFHIY72oreWJ9Ayx2.tEizFC6C24ZNIQkr9jX3etb9iaohzniWDJVl4G2RNjd71_Nde9t [2021-11-19T14:07:55+0000] [Thread-7 ] [D] [toil.jobStores.aws.jobStore] Multipart upload visible as pqdFAHqqs4eFfFVFB4V5AJ7W6nQcHA0Jjg2i4NsLbgYwCRDpMh6r1fhEFKpxFHIY72oreWJ9Ayx2.tEizFC6C24ZNIQkr9jX3etb9iaohzniWDJVl4G2RNjd71_Nde9t [2021-11-19T14:07:55+0000] [Thread-7 ] [D] [toil.jobStores.aws.jobStore] Uploading part 1 of 379 bytes to pqdFAHqqs4eFfFVFB4V5AJ7W6nQcHA0Jjg2i4NsLbgYwCRDpMh6r1fhEFKpxFHIY72oreWJ9Ayx2.tEizFC6C24ZNIQkr9jX3etb9iaohzniWDJVl4G2RNjd71_Nde9t [2021-11-19T14:07:55+0000] [Thread-7 ] [D] [toil.jobStores.aws.jobStore] Completed checksum with hash 2528e99884e181cab5124d386d2dd64407ec8667 vs. expected None [2021-11-19T14:07:55+0000] [Thread-7 ] [D] [toil.jobStores.aws.jobStore] Attempting to complete upload... [2021-11-19T14:07:55+0000] [Thread-7 ] [D] [toil.jobStores.aws.jobStore] Completed upload object of type : {'ResponseMetadata': {'RequestId': '5Q5JEVDV1A1M5YX2', 'HostId': 'ThwTYs6QasXfZ0X38UvFyHNHtPctrJIqCWShL+7NPkA/9SkHVCnenqHlt0R0KquJgtB5O60KlPk=', 'HTTPStatusCode': 200, 'HTTPHeaders': {'x-amz-id-2': 'ThwTYs6QasXfZ0X38UvFyHNHtPctrJIqCWShL+7NPkA/9SkHVCnenqHlt0R0KquJgtB5O60KlPk=', 'x-amz-request-id': '5Q5JEVDV1A1M5YX2', 'date': 'Fri, 19 Nov 2021 14:07:56 GMT', 'x-amz-version-id': 'A3psdpfbvmgTV_W2_StIQV5CcHHuGTQP', 'content-type': 'application/xml', 'transfer-encoding': 'chunked', 'server': 'AmazonS3'}, 'RetryAttempts': 0}, 'VersionId': 'A3psdpfbvmgTV_W2_StIQV5CcHHuGTQP', 'Location': 'https://toil-cwl-19398c8c-4067-4302-964d-e727a203e592--files.s3.us-west-2.amazonaws.com/4e733285-8a77-4f40-a6ae-bc74df4c540f', 'Bucket': 'toil-cwl-19398c8c-4067-4302-964d-e727a203e592--files', 'Key': '4e733285-8a77-4f40-a6ae-bc74df4c540f', 'ETag': '"2e964a5380b6517222fcf942f3582dd1-1"'} [2021-11-19T14:07:55+0000] [Thread-7 ] [D] [toil.jobStores.aws.jobStore] Completed upload with version A3psdpfbvmgTV_W2_StIQV5CcHHuGTQP [2021-11-19T14:07:55+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Wrote FileInfo(fileID='4e733285-8a77-4f40-a6ae-bc74df4c540f', ownerID='None', encrypted=False, version='A3psdpfbvmgTV_W2_StIQV5CcHHuGTQP', previousVersion='A3psdpfbvmgTV_W2_StIQV5CcHHuGTQP', content=None, checksum='sha1$2528e99884e...86d2dd64407ec8667', _numContentChunks=0) bound to from stream. [2021-11-19T14:07:55+0000] [MainThread] [I] [toil.job] Processing job 'CWLJob' echo ec12b4e1-6da8-42aa-8e7f-18d43b243743 v0 [2021-11-19T14:07:55+0000] [Thread-14 ] [D] [toil.jobStores.aws.jobStore] Starting sha1 checksum to match None [2021-11-19T14:07:55+0000] [Thread-14 ] [D] [toil.jobStores.aws.jobStore] Updating checksum with 181521 bytes [2021-11-19T14:07:55+0000] [Thread-14 ] [D] [toil.jobStores.aws.jobStore] Starting multipart upload [2021-11-19T14:07:55+0000] [Thread-14 ] [D] [toil.jobStores.aws.jobStore] Multipart upload started as ZNGE_ZBu_OT37sYitQPWRVa0B5j5H10wt9wvMEdAf6VcnBFcV31CBvq5FU16qYhQWB9mb3FyYOJH8ws5HBKqSgB9HeGIso9Xgld8Qk8EuO3bjV6fdzX65FtItqpcQEFY [2021-11-19T14:07:55+0000] [Thread-14 ] [D] [toil.jobStores.aws.jobStore] Multipart upload visible as ZNGE_ZBu_OT37sYitQPWRVa0B5j5H10wt9wvMEdAf6VcnBFcV31CBvq5FU16qYhQWB9mb3FyYOJH8ws5HBKqSgB9HeGIso9Xgld8Qk8EuO3bjV6fdzX65FtItqpcQEFY [2021-11-19T14:07:55+0000] [Thread-14 ] [D] [toil.jobStores.aws.jobStore] Uploading part 1 of 181521 bytes to ZNGE_ZBu_OT37sYitQPWRVa0B5j5H10wt9wvMEdAf6VcnBFcV31CBvq5FU16qYhQWB9mb3FyYOJH8ws5HBKqSgB9HeGIso9Xgld8Qk8EuO3bjV6fdzX65FtItqpcQEFY [2021-11-19T14:07:55+0000] [Thread-14 ] [D] [toil.jobStores.aws.jobStore] Completed checksum with hash 9fd9514ef889f172c007144f1e61201e0afb7775 vs. expected None [2021-11-19T14:07:55+0000] [Thread-14 ] [D] [toil.jobStores.aws.jobStore] Attempting to complete upload... [2021-11-19T14:07:55+0000] [Thread-14 ] [D] [toil.jobStores.aws.jobStore] Completed upload object of type : {'ResponseMetadata': {'RequestId': '5Q5PRH9X60D8GXN1', 'HostId': 'qJT3Q5bVqnSfXigSIEoUpcyteCF/3RQdNcBfjd1f5Z415qSHs2qdzBxk7mvahYgHbU8oJF57/bw=', 'HTTPStatusCode': 200, 'HTTPHeaders': {'x-amz-id-2': 'qJT3Q5bVqnSfXigSIEoUpcyteCF/3RQdNcBfjd1f5Z415qSHs2qdzBxk7mvahYgHbU8oJF57/bw=', 'x-amz-request-id': '5Q5PRH9X60D8GXN1', 'date': 'Fri, 19 Nov 2021 14:07:56 GMT', 'x-amz-version-id': 'rQX9_kmCgq2X3DOoPMIJGLcg3.uy23Mv', 'content-type': 'application/xml', 'transfer-encoding': 'chunked', 'server': 'AmazonS3'}, 'RetryAttempts': 0}, 'VersionId': 'rQX9_kmCgq2X3DOoPMIJGLcg3.uy23Mv', 'Location': 'https://toil-cwl-19398c8c-4067-4302-964d-e727a203e592--files.s3.us-west-2.amazonaws.com/45a91c47-52cb-46e7-b231-49eaa6ca72d9', 'Bucket': 'toil-cwl-19398c8c-4067-4302-964d-e727a203e592--files', 'Key': '45a91c47-52cb-46e7-b231-49eaa6ca72d9', 'ETag': '"c17aaadde7ae3649336b8d288b2826f9-1"'} [2021-11-19T14:07:55+0000] [Thread-14 ] [D] [toil.jobStores.aws.jobStore] Completed upload with version rQX9_kmCgq2X3DOoPMIJGLcg3.uy23Mv [2021-11-19T14:07:55+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Wrote FileInfo(fileID='45a91c47-52cb-46e7-b231-49eaa6ca72d9', ownerID='ec12b4e1-6da8-42aa-8e7f-18d43b243743', encrypted=False, version='rQX9_kmCgq2X3DOoPMIJGLcg3.uy23Mv', previousVersion='rQX9_kmCgq2X3DOoPMIJGLcg3.uy23Mv', content=None, checksum='sha1$9fd9514ef88...f1e61201e0afb7775', _numContentChunks=0) bound to . [2021-11-19T14:07:55+0000] [MainThread] [I] [toil.job] Processing job 'CWLJob' echo a9f944fe-525a-4718-b868-05ef26e0411c v0 [2021-11-19T14:07:55+0000] [Thread-15 ] [D] [toil.jobStores.aws.jobStore] Starting sha1 checksum to match None [2021-11-19T14:07:55+0000] [Thread-15 ] [D] [toil.jobStores.aws.jobStore] Updating checksum with 181521 bytes [2021-11-19T14:07:55+0000] [Thread-15 ] [D] [toil.jobStores.aws.jobStore] Starting multipart upload [2021-11-19T14:07:55+0000] [Thread-15 ] [D] [toil.jobStores.aws.jobStore] Multipart upload started as O0Ks4qVK_1Wym.DYsy.rhIIFjPd9Dj5_tNAqRGa839vTGTwKZa4djtcCTlHJYG.tIusdnyBIa4b9K6NezxG3G1h1G4UTZvo4wI4naIbyC_CzuF_Fk70dEDjQbhQx_Xuj [2021-11-19T14:07:55+0000] [Thread-15 ] [D] [toil.jobStores.aws.jobStore] Multipart upload visible as O0Ks4qVK_1Wym.DYsy.rhIIFjPd9Dj5_tNAqRGa839vTGTwKZa4djtcCTlHJYG.tIusdnyBIa4b9K6NezxG3G1h1G4UTZvo4wI4naIbyC_CzuF_Fk70dEDjQbhQx_Xuj [2021-11-19T14:07:55+0000] [Thread-15 ] [D] [toil.jobStores.aws.jobStore] Uploading part 1 of 181521 bytes to O0Ks4qVK_1Wym.DYsy.rhIIFjPd9Dj5_tNAqRGa839vTGTwKZa4djtcCTlHJYG.tIusdnyBIa4b9K6NezxG3G1h1G4UTZvo4wI4naIbyC_CzuF_Fk70dEDjQbhQx_Xuj [2021-11-19T14:07:55+0000] [Thread-15 ] [D] [toil.jobStores.aws.jobStore] Completed checksum with hash 68decd3898434c797c205371ef9b57c5521a6dd0 vs. expected None [2021-11-19T14:07:55+0000] [Thread-15 ] [D] [toil.jobStores.aws.jobStore] Attempting to complete upload... [2021-11-19T14:07:55+0000] [Thread-15 ] [D] [toil.jobStores.aws.jobStore] Completed upload object of type : {'ResponseMetadata': {'RequestId': '5Q5ST3RV1WZDSV77', 'HostId': 'wHv7j5GVLjTiKB9IcbzRYUWcpn2/ulodm09Ju3nFb93X3ftSGo60Lv/bBwo3HopnEk23Zb4Tgag=', 'HTTPStatusCode': 200, 'HTTPHeaders': {'x-amz-id-2': 'wHv7j5GVLjTiKB9IcbzRYUWcpn2/ulodm09Ju3nFb93X3ftSGo60Lv/bBwo3HopnEk23Zb4Tgag=', 'x-amz-request-id': '5Q5ST3RV1WZDSV77', 'date': 'Fri, 19 Nov 2021 14:07:56 GMT', 'x-amz-version-id': '.T20XzvnoD41oYOOfQQBfsxgL3TfROku', 'content-type': 'application/xml', 'transfer-encoding': 'chunked', 'server': 'AmazonS3'}, 'RetryAttempts': 0}, 'VersionId': '.T20XzvnoD41oYOOfQQBfsxgL3TfROku', 'Location': 'https://toil-cwl-19398c8c-4067-4302-964d-e727a203e592--files.s3.us-west-2.amazonaws.com/4de04405-2cfc-4156-ad54-dec8dfb43715', 'Bucket': 'toil-cwl-19398c8c-4067-4302-964d-e727a203e592--files', 'Key': '4de04405-2cfc-4156-ad54-dec8dfb43715', 'ETag': '"383615ba686d2e9395fc3162736c8dff-1"'} [2021-11-19T14:07:55+0000] [Thread-15 ] [D] [toil.jobStores.aws.jobStore] Completed upload with version .T20XzvnoD41oYOOfQQBfsxgL3TfROku [2021-11-19T14:07:55+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Wrote FileInfo(fileID='4de04405-2cfc-4156-ad54-dec8dfb43715', ownerID='a9f944fe-525a-4718-b868-05ef26e0411c', encrypted=False, version='.T20XzvnoD41oYOOfQQBfsxgL3TfROku', previousVersion='.T20XzvnoD41oYOOfQQBfsxgL3TfROku', content=None, checksum='sha1$68decd38984...1ef9b57c5521a6dd0', _numContentChunks=0) bound to . [2021-11-19T14:07:55+0000] [MainThread] [I] [toil.job] Processing job 'CWLJob' echo 692c58c7-3a47-4eb7-85c8-e0985f57f305 v0 [2021-11-19T14:07:55+0000] [Thread-16 ] [D] [toil.jobStores.aws.jobStore] Starting sha1 checksum to match None [2021-11-19T14:07:55+0000] [Thread-16 ] [D] [toil.jobStores.aws.jobStore] Updating checksum with 181521 bytes [2021-11-19T14:07:55+0000] [Thread-16 ] [D] [toil.jobStores.aws.jobStore] Starting multipart upload [2021-11-19T14:07:55+0000] [Thread-16 ] [D] [toil.jobStores.aws.jobStore] Multipart upload started as QGF3JEgjpB.5jngHvxTVhkjg7utZb0Bt6QuzQ8oAPaxi.3b9aDq8oN0N3vEzuoLYxFin98YGIZwnB5EWMYyn6EpD9GVqwv7BCnm8NJPhPqmA1CFuEOvQhchjNTRfc.8A [2021-11-19T14:07:55+0000] [Thread-16 ] [D] [toil.jobStores.aws.jobStore] Multipart upload visible as QGF3JEgjpB.5jngHvxTVhkjg7utZb0Bt6QuzQ8oAPaxi.3b9aDq8oN0N3vEzuoLYxFin98YGIZwnB5EWMYyn6EpD9GVqwv7BCnm8NJPhPqmA1CFuEOvQhchjNTRfc.8A [2021-11-19T14:07:55+0000] [Thread-16 ] [D] [toil.jobStores.aws.jobStore] Uploading part 1 of 181521 bytes to QGF3JEgjpB.5jngHvxTVhkjg7utZb0Bt6QuzQ8oAPaxi.3b9aDq8oN0N3vEzuoLYxFin98YGIZwnB5EWMYyn6EpD9GVqwv7BCnm8NJPhPqmA1CFuEOvQhchjNTRfc.8A [2021-11-19T14:07:56+0000] [Thread-16 ] [D] [toil.jobStores.aws.jobStore] Completed checksum with hash fd46a2918ba5a962f009e096143f82ca1d8ad2c4 vs. expected None [2021-11-19T14:07:56+0000] [Thread-16 ] [D] [toil.jobStores.aws.jobStore] Attempting to complete upload... [2021-11-19T14:07:56+0000] [Thread-16 ] [D] [toil.jobStores.aws.jobStore] Completed upload object of type : {'ResponseMetadata': {'RequestId': '9E1AEG3JXH8Y6099', 'HostId': '84UnFNA8qfVj9371jbI9xWVupqnI1npWoXsheoRTNrgdxbjxHSfYQiQeJybyFwodNv5UWcC58WY=', 'HTTPStatusCode': 200, 'HTTPHeaders': {'x-amz-id-2': '84UnFNA8qfVj9371jbI9xWVupqnI1npWoXsheoRTNrgdxbjxHSfYQiQeJybyFwodNv5UWcC58WY=', 'x-amz-request-id': '9E1AEG3JXH8Y6099', 'date': 'Fri, 19 Nov 2021 14:07:57 GMT', 'x-amz-version-id': 'WsjYbW0qNs8X3bgkD5xlvEHTm3NjE6bG', 'content-type': 'application/xml', 'transfer-encoding': 'chunked', 'server': 'AmazonS3'}, 'RetryAttempts': 0}, 'VersionId': 'WsjYbW0qNs8X3bgkD5xlvEHTm3NjE6bG', 'Location': 'https://toil-cwl-19398c8c-4067-4302-964d-e727a203e592--files.s3.us-west-2.amazonaws.com/03110d45-a199-4570-8db2-f81a4b939ddb', 'Bucket': 'toil-cwl-19398c8c-4067-4302-964d-e727a203e592--files', 'Key': '03110d45-a199-4570-8db2-f81a4b939ddb', 'ETag': '"071422231daad42d82bfa10483b7b3a8-1"'} [2021-11-19T14:07:56+0000] [Thread-16 ] [D] [toil.jobStores.aws.jobStore] Completed upload with version WsjYbW0qNs8X3bgkD5xlvEHTm3NjE6bG [2021-11-19T14:07:56+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Wrote FileInfo(fileID='03110d45-a199-4570-8db2-f81a4b939ddb', ownerID='692c58c7-3a47-4eb7-85c8-e0985f57f305', encrypted=False, version='WsjYbW0qNs8X3bgkD5xlvEHTm3NjE6bG', previousVersion='WsjYbW0qNs8X3bgkD5xlvEHTm3NjE6bG', content=None, checksum='sha1$fd46a2918ba...6143f82ca1d8ad2c4', _numContentChunks=0) bound to . [2021-11-19T14:07:56+0000] [MainThread] [I] [toil.job] Processing job 'CWLJob' echo 6ca66447-352c-4e3a-970d-6b483ec82646 v0 [2021-11-19T14:07:56+0000] [Thread-17 ] [D] [toil.jobStores.aws.jobStore] Starting sha1 checksum to match None [2021-11-19T14:07:56+0000] [Thread-17 ] [D] [toil.jobStores.aws.jobStore] Updating checksum with 181521 bytes [2021-11-19T14:07:56+0000] [Thread-17 ] [D] [toil.jobStores.aws.jobStore] Starting multipart upload [2021-11-19T14:07:56+0000] [Thread-17 ] [D] [toil.jobStores.aws.jobStore] Multipart upload started as aG3LeRb_gcXGWYCoayB2G9SDoELqCCurfFwwpwZyIxJqqjgLM7jHXRoLIVDt5cf_vskStfinRgskxNGoSGt60vgHSI2yp1BMHmhOC1XxQOsd41Jpr_fk7sIHoB406Zba [2021-11-19T14:07:56+0000] [Thread-17 ] [D] [toil.jobStores.aws.jobStore] Multipart upload visible as aG3LeRb_gcXGWYCoayB2G9SDoELqCCurfFwwpwZyIxJqqjgLM7jHXRoLIVDt5cf_vskStfinRgskxNGoSGt60vgHSI2yp1BMHmhOC1XxQOsd41Jpr_fk7sIHoB406Zba [2021-11-19T14:07:56+0000] [Thread-17 ] [D] [toil.jobStores.aws.jobStore] Uploading part 1 of 181521 bytes to aG3LeRb_gcXGWYCoayB2G9SDoELqCCurfFwwpwZyIxJqqjgLM7jHXRoLIVDt5cf_vskStfinRgskxNGoSGt60vgHSI2yp1BMHmhOC1XxQOsd41Jpr_fk7sIHoB406Zba [2021-11-19T14:07:56+0000] [Thread-17 ] [D] [toil.jobStores.aws.jobStore] Completed checksum with hash b6458b7f606aec4302a89daaa8cc99d9e74a288b vs. expected None [2021-11-19T14:07:56+0000] [Thread-17 ] [D] [toil.jobStores.aws.jobStore] Attempting to complete upload... [2021-11-19T14:07:56+0000] [Thread-17 ] [D] [toil.jobStores.aws.jobStore] Completed upload object of type : {'ResponseMetadata': {'RequestId': '9E146GKSDTH95RWR', 'HostId': 'qEiEG2Fy1JNH9d6FOGoSGB59tF3e9d22Sl3yP9LClcoMmHsnkd3vOpL55GfrmsbjOI6q3Enuhm0=', 'HTTPStatusCode': 200, 'HTTPHeaders': {'x-amz-id-2': 'qEiEG2Fy1JNH9d6FOGoSGB59tF3e9d22Sl3yP9LClcoMmHsnkd3vOpL55GfrmsbjOI6q3Enuhm0=', 'x-amz-request-id': '9E146GKSDTH95RWR', 'date': 'Fri, 19 Nov 2021 14:07:57 GMT', 'x-amz-version-id': 'p0ixZxAbeChX2NnnBz_GVr.tP9tminuW', 'content-type': 'application/xml', 'transfer-encoding': 'chunked', 'server': 'AmazonS3'}, 'RetryAttempts': 0}, 'VersionId': 'p0ixZxAbeChX2NnnBz_GVr.tP9tminuW', 'Location': 'https://toil-cwl-19398c8c-4067-4302-964d-e727a203e592--files.s3.us-west-2.amazonaws.com/e13d6055-c7b7-4c69-a1b1-9eac24c52d08', 'Bucket': 'toil-cwl-19398c8c-4067-4302-964d-e727a203e592--files', 'Key': 'e13d6055-c7b7-4c69-a1b1-9eac24c52d08', 'ETag': '"1b0a2182688f833611a44893e91aff88-1"'} [2021-11-19T14:07:56+0000] [Thread-17 ] [D] [toil.jobStores.aws.jobStore] Completed upload with version p0ixZxAbeChX2NnnBz_GVr.tP9tminuW [2021-11-19T14:07:56+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Wrote FileInfo(fileID='e13d6055-c7b7-4c69-a1b1-9eac24c52d08', ownerID='6ca66447-352c-4e3a-970d-6b483ec82646', encrypted=False, version='p0ixZxAbeChX2NnnBz_GVr.tP9tminuW', previousVersion='p0ixZxAbeChX2NnnBz_GVr.tP9tminuW', content=None, checksum='sha1$b6458b7f606...aa8cc99d9e74a288b', _numContentChunks=0) bound to . [2021-11-19T14:07:56+0000] [MainThread] [I] [toil.job] Processing job 'CWLJob' echo 9eb39b4a-6641-4a16-990c-761c5e880ad1 v0 [2021-11-19T14:07:56+0000] [Thread-18 ] [D] [toil.jobStores.aws.jobStore] Starting sha1 checksum to match None [2021-11-19T14:07:56+0000] [Thread-18 ] [D] [toil.jobStores.aws.jobStore] Updating checksum with 181521 bytes [2021-11-19T14:07:56+0000] [Thread-18 ] [D] [toil.jobStores.aws.jobStore] Starting multipart upload [2021-11-19T14:07:56+0000] [Thread-18 ] [D] [toil.jobStores.aws.jobStore] Multipart upload started as 3CqndGNPEncRRkSnIp8lgMIfuhotWFB6Z9CA73aTrXyOpFljK8zcBd0YM09CLzMtOX1IH2ke8ZriBIxo5sQlUXJIfTkWrI7ot1I0RYLdP2W.bxKaBiO0eh0Brj9gppkI [2021-11-19T14:07:56+0000] [Thread-18 ] [D] [toil.jobStores.aws.jobStore] Multipart upload visible as 3CqndGNPEncRRkSnIp8lgMIfuhotWFB6Z9CA73aTrXyOpFljK8zcBd0YM09CLzMtOX1IH2ke8ZriBIxo5sQlUXJIfTkWrI7ot1I0RYLdP2W.bxKaBiO0eh0Brj9gppkI [2021-11-19T14:07:56+0000] [Thread-18 ] [D] [toil.jobStores.aws.jobStore] Uploading part 1 of 181521 bytes to 3CqndGNPEncRRkSnIp8lgMIfuhotWFB6Z9CA73aTrXyOpFljK8zcBd0YM09CLzMtOX1IH2ke8ZriBIxo5sQlUXJIfTkWrI7ot1I0RYLdP2W.bxKaBiO0eh0Brj9gppkI [2021-11-19T14:07:56+0000] [Thread-18 ] [D] [toil.jobStores.aws.jobStore] Completed checksum with hash eab2a69360c5438bfe6de8ddfa2056d3bc25d5b2 vs. expected None [2021-11-19T14:07:56+0000] [Thread-18 ] [D] [toil.jobStores.aws.jobStore] Attempting to complete upload... [2021-11-19T14:07:56+0000] [Thread-18 ] [D] [toil.jobStores.aws.jobStore] Completed upload object of type : {'ResponseMetadata': {'RequestId': '9E170729FF56GNKJ', 'HostId': 'cJLjWM1PkmEBkNrohCcpWN9UUqFe1R6HSyDRB6D4V5LSaQPY2boMZPNT16M9l4H60ViQXJx6x0c=', 'HTTPStatusCode': 200, 'HTTPHeaders': {'x-amz-id-2': 'cJLjWM1PkmEBkNrohCcpWN9UUqFe1R6HSyDRB6D4V5LSaQPY2boMZPNT16M9l4H60ViQXJx6x0c=', 'x-amz-request-id': '9E170729FF56GNKJ', 'date': 'Fri, 19 Nov 2021 14:07:57 GMT', 'x-amz-version-id': 'hIg2D.WGkXoZwXtNHrsgUWvMnJxNl9Jy', 'content-type': 'application/xml', 'transfer-encoding': 'chunked', 'server': 'AmazonS3'}, 'RetryAttempts': 0}, 'VersionId': 'hIg2D.WGkXoZwXtNHrsgUWvMnJxNl9Jy', 'Location': 'https://toil-cwl-19398c8c-4067-4302-964d-e727a203e592--files.s3.us-west-2.amazonaws.com/551af678-3422-4dec-b5de-02491df40074', 'Bucket': 'toil-cwl-19398c8c-4067-4302-964d-e727a203e592--files', 'Key': '551af678-3422-4dec-b5de-02491df40074', 'ETag': '"695b05e48628edccc022cb3c7d2885ae-1"'} [2021-11-19T14:07:56+0000] [Thread-18 ] [D] [toil.jobStores.aws.jobStore] Completed upload with version hIg2D.WGkXoZwXtNHrsgUWvMnJxNl9Jy [2021-11-19T14:07:56+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Wrote FileInfo(fileID='551af678-3422-4dec-b5de-02491df40074', ownerID='9eb39b4a-6641-4a16-990c-761c5e880ad1', encrypted=False, version='hIg2D.WGkXoZwXtNHrsgUWvMnJxNl9Jy', previousVersion='hIg2D.WGkXoZwXtNHrsgUWvMnJxNl9Jy', content=None, checksum='sha1$eab2a69360c...dfa2056d3bc25d5b2', _numContentChunks=0) bound to . [2021-11-19T14:07:56+0000] [MainThread] [I] [toil.job] Processing job 'CWLJob' echo 83f640fe-9544-49ac-b0d9-936c7a275ea3 v0 [2021-11-19T14:07:56+0000] [Thread-19 ] [D] [toil.jobStores.aws.jobStore] Starting sha1 checksum to match None [2021-11-19T14:07:56+0000] [Thread-19 ] [D] [toil.jobStores.aws.jobStore] Updating checksum with 181521 bytes [2021-11-19T14:07:56+0000] [Thread-19 ] [D] [toil.jobStores.aws.jobStore] Starting multipart upload [2021-11-19T14:07:56+0000] [Thread-19 ] [D] [toil.jobStores.aws.jobStore] Multipart upload started as EIaaABtjr1SjOeP.uwuh8JM.cXnEYxAnyQqre6kLO26gW89JkQ4mXPwA9Cp702xy7PGai94f3RTqqel5TUbTR2h6.Ik2cCj_V5MOV0Rdco_iNn1yu1OuSN8CkYwxIVn9 [2021-11-19T14:07:56+0000] [Thread-19 ] [D] [toil.jobStores.aws.jobStore] Multipart upload visible as EIaaABtjr1SjOeP.uwuh8JM.cXnEYxAnyQqre6kLO26gW89JkQ4mXPwA9Cp702xy7PGai94f3RTqqel5TUbTR2h6.Ik2cCj_V5MOV0Rdco_iNn1yu1OuSN8CkYwxIVn9 [2021-11-19T14:07:56+0000] [Thread-19 ] [D] [toil.jobStores.aws.jobStore] Uploading part 1 of 181521 bytes to EIaaABtjr1SjOeP.uwuh8JM.cXnEYxAnyQqre6kLO26gW89JkQ4mXPwA9Cp702xy7PGai94f3RTqqel5TUbTR2h6.Ik2cCj_V5MOV0Rdco_iNn1yu1OuSN8CkYwxIVn9 [2021-11-19T14:07:56+0000] [Thread-19 ] [D] [toil.jobStores.aws.jobStore] Completed checksum with hash 5a559a67fc9c900afe3b9ddaf78b1bae3d0132ca vs. expected None [2021-11-19T14:07:56+0000] [Thread-19 ] [D] [toil.jobStores.aws.jobStore] Attempting to complete upload... [2021-11-19T14:07:57+0000] [Thread-19 ] [D] [toil.jobStores.aws.jobStore] Completed upload object of type : {'ResponseMetadata': {'RequestId': '9E1DCFY4NS7F757C', 'HostId': 'vOVoBxkLrfMYH9SCYQaDGLEJTSYH7UlOkhtifGpKq/GDrccOjfPyiHtAMxUobxlY+CBQIMw5/XY=', 'HTTPStatusCode': 200, 'HTTPHeaders': {'x-amz-id-2': 'vOVoBxkLrfMYH9SCYQaDGLEJTSYH7UlOkhtifGpKq/GDrccOjfPyiHtAMxUobxlY+CBQIMw5/XY=', 'x-amz-request-id': '9E1DCFY4NS7F757C', 'date': 'Fri, 19 Nov 2021 14:07:57 GMT', 'x-amz-version-id': 'sVTjJJPecpd1g0tLgVmS0e__PJwMf1wo', 'content-type': 'application/xml', 'transfer-encoding': 'chunked', 'server': 'AmazonS3'}, 'RetryAttempts': 0}, 'VersionId': 'sVTjJJPecpd1g0tLgVmS0e__PJwMf1wo', 'Location': 'https://toil-cwl-19398c8c-4067-4302-964d-e727a203e592--files.s3.us-west-2.amazonaws.com/3d2dfd8e-7710-4bbc-b9c6-6b9de5444df1', 'Bucket': 'toil-cwl-19398c8c-4067-4302-964d-e727a203e592--files', 'Key': '3d2dfd8e-7710-4bbc-b9c6-6b9de5444df1', 'ETag': '"af111ac11d3132544d5cd584da58ee0a-1"'} [2021-11-19T14:07:57+0000] [Thread-19 ] [D] [toil.jobStores.aws.jobStore] Completed upload with version sVTjJJPecpd1g0tLgVmS0e__PJwMf1wo [2021-11-19T14:07:57+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Wrote FileInfo(fileID='3d2dfd8e-7710-4bbc-b9c6-6b9de5444df1', ownerID='83f640fe-9544-49ac-b0d9-936c7a275ea3', encrypted=False, version='sVTjJJPecpd1g0tLgVmS0e__PJwMf1wo', previousVersion='sVTjJJPecpd1g0tLgVmS0e__PJwMf1wo', content=None, checksum='sha1$5a559a67fc9...af78b1bae3d0132ca', _numContentChunks=0) bound to . [2021-11-19T14:07:57+0000] [MainThread] [I] [toil.job] Processing job 'CWLScatter' 95cfa3be-cbb1-4ce0-a750-9a66ddff6118 v1 [2021-11-19T14:07:57+0000] [MainThread] [D] [toil.job] New job version: 'CWLJob' echo ec12b4e1-6da8-42aa-8e7f-18d43b243743 v1 [2021-11-19T14:07:57+0000] [MainThread] [D] [toil.job] New job version: 'CWLJob' echo a9f944fe-525a-4718-b868-05ef26e0411c v1 [2021-11-19T14:07:57+0000] [MainThread] [D] [toil.job] New job version: 'CWLJob' echo 692c58c7-3a47-4eb7-85c8-e0985f57f305 v1 [2021-11-19T14:07:57+0000] [MainThread] [D] [toil.job] New job version: 'CWLJob' echo 6ca66447-352c-4e3a-970d-6b483ec82646 v1 [2021-11-19T14:07:57+0000] [MainThread] [D] [toil.job] New job version: 'CWLJob' echo 9eb39b4a-6641-4a16-990c-761c5e880ad1 v1 [2021-11-19T14:07:57+0000] [MainThread] [D] [toil.job] New job version: 'CWLJob' echo 83f640fe-9544-49ac-b0d9-936c7a275ea3 v1 [2021-11-19T14:07:57+0000] [MainThread] [D] [toil.fileStores.abstractFileStore] LOG-TO-MASTER: Job 'CWLScatter' 95cfa3be-cbb1-4ce0-a750-9a66ddff6118 v1 used 0.00% disk (0 bB [0B] used, 1.0 MiB [1048576B] requested). [2021-11-19T14:07:57+0000] [MainThread] [D] [toil.deferred] Running own deferred functions [2021-11-19T14:07:57+0000] [MainThread] [D] [toil.deferred] Out of deferred functions! [2021-11-19T14:07:57+0000] [MainThread] [D] [toil.deferred] Running orphaned deferred functions [2021-11-19T14:07:57+0000] [MainThread] [I] [toil.worker] Completed body for 'CWLScatter' 95cfa3be-cbb1-4ce0-a750-9a66ddff6118 v1 [2021-11-19T14:07:57+0000] [Thread-20 ] [D] [toil.fileStores.cachingFileStore] Committing file uploads asynchronously [2021-11-19T14:07:57+0000] [MainThread] [D] [toil.worker] Stopping running chain of jobs because job has both children and follow-ons [2021-11-19T14:07:57+0000] [MainThread] [I] [toil.worker] Not chaining from job 'CWLScatter' 95cfa3be-cbb1-4ce0-a750-9a66ddff6118 v1 [2021-11-19T14:07:57+0000] [MainThread] [I] [toil.worker] Worker log can be found at /var/lib/toil/d6f7b2f2da0c53e9909e3a68ec923a5a/158e. Set --cleanWorkDir to retain this log [2021-11-19T14:07:57+0000] [MainThread] [I] [toil.worker] Finished running the chain of jobs on this node, we ran for a total of 2.656147 seconds [2021-11-19T14:07:57+0000] [Thread-20 ] [D] [toil.fileStores.cachingFileStore] Committing file deletes and job state changes asynchronously [2021-11-19T14:07:57+0000] [Thread-20 ] [D] [toil.jobStores.aws.jobStore] Updating job 95cfa3be-cbb1-4ce0-a750-9a66ddff6118 [2021-11-19T14:07:57+0000] [Thread-20 ] [D] [toil.job] New job version: 'CWLScatter' 95cfa3be-cbb1-4ce0-a750-9a66ddff6118 v2 <========= [2021-11-19T14:07:57+0000] [Thread-3 ] [D] [toil.batchSystems.singleMachine] Child 56643 for job 1 succeeded [2021-11-19T14:07:58+0000] [MainThread] [D] [toil.batchSystems.singleMachine] Ran jobID: 1 with exit value: 0 [2021-11-19T14:07:58+0000] [MainThread] [D] [toil.leader] Job ended: 'CWLScatter' 95cfa3be-cbb1-4ce0-a750-9a66ddff6118 v1 [2021-11-19T14:07:58+0000] [MainThread] [D] [toil.leader] Job 'CWLScatter' 95cfa3be-cbb1-4ce0-a750-9a66ddff6118 v1 continues to exist (i.e. has more to do) [2021-11-19T14:07:58+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Loaded job 95cfa3be-cbb1-4ce0-a750-9a66ddff6118 [2021-11-19T14:07:58+0000] [MainThread] [D] [toil.bus] processFinishedJob sent: JobUpdatedMessage(job_id='95cfa3be-cbb1-4ce0-a750-9a66ddff6118', result_status=0) [2021-11-19T14:07:58+0000] [MainThread] [D] [toil.leader] Added job: 'CWLScatter' 95cfa3be-cbb1-4ce0-a750-9a66ddff6118 v2 to updated jobs [2021-11-19T14:07:58+0000] [MainThread] [D] [toil.leader] Built the jobs list, currently have 1 jobs to update and 0 jobs issued [2021-11-19T14:07:58+0000] [MainThread] [D] [toil.leader] Updating status of job 'CWLScatter' 95cfa3be-cbb1-4ce0-a750-9a66ddff6118 v2 with result status: 0 [2021-11-19T14:07:58+0000] [MainThread] [D] [toil.leader] Job: 95cfa3be-cbb1-4ce0-a750-9a66ddff6118 has 6 successors to schedule [2021-11-19T14:07:58+0000] [MainThread] [D] [toil.toilState] Successors: 6 more for 95cfa3be-cbb1-4ce0-a750-9a66ddff6118, now have 6 [2021-11-19T14:07:58+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Loaded job 9eb39b4a-6641-4a16-990c-761c5e880ad1 [2021-11-19T14:07:58+0000] [MainThread] [D] [toil.leader] Added job 'CWLJob' echo 9eb39b4a-6641-4a16-990c-761c5e880ad1 v1 as coming after job 'CWLScatter' 95cfa3be-cbb1-4ce0-a750-9a66ddff6118 v2 [2021-11-19T14:07:58+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Loaded job 83f640fe-9544-49ac-b0d9-936c7a275ea3 [2021-11-19T14:07:58+0000] [MainThread] [D] [toil.leader] Added job 'CWLJob' echo 83f640fe-9544-49ac-b0d9-936c7a275ea3 v1 as coming after job 'CWLScatter' 95cfa3be-cbb1-4ce0-a750-9a66ddff6118 v2 [2021-11-19T14:07:58+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Loaded job 6ca66447-352c-4e3a-970d-6b483ec82646 [2021-11-19T14:07:58+0000] [MainThread] [D] [toil.leader] Added job 'CWLJob' echo 6ca66447-352c-4e3a-970d-6b483ec82646 v1 as coming after job 'CWLScatter' 95cfa3be-cbb1-4ce0-a750-9a66ddff6118 v2 [2021-11-19T14:07:58+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Loaded job 692c58c7-3a47-4eb7-85c8-e0985f57f305 [2021-11-19T14:07:58+0000] [MainThread] [D] [toil.leader] Added job 'CWLJob' echo 692c58c7-3a47-4eb7-85c8-e0985f57f305 v1 as coming after job 'CWLScatter' 95cfa3be-cbb1-4ce0-a750-9a66ddff6118 v2 [2021-11-19T14:07:58+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Loaded job a9f944fe-525a-4718-b868-05ef26e0411c [2021-11-19T14:07:58+0000] [MainThread] [D] [toil.leader] Added job 'CWLJob' echo a9f944fe-525a-4718-b868-05ef26e0411c v1 as coming after job 'CWLScatter' 95cfa3be-cbb1-4ce0-a750-9a66ddff6118 v2 [2021-11-19T14:07:58+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Loaded job ec12b4e1-6da8-42aa-8e7f-18d43b243743 [2021-11-19T14:07:58+0000] [MainThread] [D] [toil.leader] Added job 'CWLJob' echo ec12b4e1-6da8-42aa-8e7f-18d43b243743 v1 as coming after job 'CWLScatter' 95cfa3be-cbb1-4ce0-a750-9a66ddff6118 v2 [2021-11-19T14:07:58+0000] [MainThread] [D] [toil.batchSystems.kubernetes] Launched job: toiltest-toil-1065dcea-65fd-4642-9515-d3d93cdb6134-2 [2021-11-19T14:07:58+0000] [MainThread] [I] [toil.leader] Issued job 'CWLJob' echo 9eb39b4a-6641-4a16-990c-761c5e880ad1 v1 with job batch system ID: 2 and cores: 1, disk: 3.0 Gi, and memory: 2.0 Gi [2021-11-19T14:07:58+0000] [MainThread] [D] [toil.batchSystems.kubernetes] Launched job: toiltest-toil-1065dcea-65fd-4642-9515-d3d93cdb6134-3 [2021-11-19T14:07:58+0000] [MainThread] [I] [toil.leader] Issued job 'CWLJob' echo 83f640fe-9544-49ac-b0d9-936c7a275ea3 v1 with job batch system ID: 3 and cores: 1, disk: 3.0 Gi, and memory: 2.0 Gi [2021-11-19T14:07:58+0000] [MainThread] [D] [toil.batchSystems.kubernetes] Launched job: toiltest-toil-1065dcea-65fd-4642-9515-d3d93cdb6134-4 [2021-11-19T14:07:58+0000] [MainThread] [I] [toil.leader] Issued job 'CWLJob' echo 6ca66447-352c-4e3a-970d-6b483ec82646 v1 with job batch system ID: 4 and cores: 1, disk: 3.0 Gi, and memory: 2.0 Gi [2021-11-19T14:07:58+0000] [MainThread] [D] [toil.batchSystems.kubernetes] Launched job: toiltest-toil-1065dcea-65fd-4642-9515-d3d93cdb6134-5 [2021-11-19T14:07:58+0000] [MainThread] [I] [toil.leader] Issued job 'CWLJob' echo 692c58c7-3a47-4eb7-85c8-e0985f57f305 v1 with job batch system ID: 5 and cores: 1, disk: 3.0 Gi, and memory: 2.0 Gi [2021-11-19T14:07:58+0000] [MainThread] [D] [toil.batchSystems.kubernetes] Launched job: toiltest-toil-1065dcea-65fd-4642-9515-d3d93cdb6134-6 [2021-11-19T14:07:58+0000] [MainThread] [I] [toil.leader] Issued job 'CWLJob' echo a9f944fe-525a-4718-b868-05ef26e0411c v1 with job batch system ID: 6 and cores: 1, disk: 3.0 Gi, and memory: 2.0 Gi [2021-11-19T14:07:58+0000] [MainThread] [D] [toil.batchSystems.kubernetes] Launched job: toiltest-toil-1065dcea-65fd-4642-9515-d3d93cdb6134-7 [2021-11-19T14:07:58+0000] [MainThread] [I] [toil.leader] Issued job 'CWLJob' echo ec12b4e1-6da8-42aa-8e7f-18d43b243743 v1 with job batch system ID: 7 and cores: 1, disk: 3.0 Gi, and memory: 2.0 Gi [2021-11-19T14:08:02+0000] [Thread-18 ] [D] [toil.jobStores.aws.jobStore] Starting sha1 checksum to match d6d69788966e8ed1e893b5db865fe8db77feadfc [2021-11-19T14:08:02+0000] [Thread-18 ] [D] [toil.jobStores.aws.jobStore] Completed checksum with hash d6d69788966e8ed1e893b5db865fe8db77feadfc vs. expected d6d69788966e8ed1e893b5db865fe8db77feadfc [2021-11-19T14:08:02+0000] [Thread-12 ] [D] [toil.statsAndLogging] Got message from job at time 11-19-2021 14:08:02: Job 'CWLJob' echo 83f640fe-9544-49ac-b0d9-936c7a275ea3 v1 used 0.00% disk (0 bB [0B] used, 3.0 GiB [3221225472B] requested). [2021-11-19T14:08:02+0000] [Thread-12 ] [D] [toil.statsAndLogging] Received Toil worker log. Disable debug level logging to hide this output [2021-11-19T14:08:02+0000] [Thread-12 ] [D] [toil.statsAndLogging] Log from job "'CWLJob' echo 83f640fe-9544-49ac-b0d9-936c7a275ea3 v1" follows: =========> [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] ---TOIL WORKER OUTPUT LOG--- [2021-11-19T14:08:01+0000] [MainThread] [I] [toil] Running Toil version 5.6.0a1-604176544d7178bb415a1dd98f0084d1a1b7f65b on host toiltest-toil-1065dcea-65fd-4642-9515-d3d93cdb6134-3-xs6br. [2021-11-19T14:08:01+0000] [MainThread] [D] [toil] Configuration: {'workflowID': '746138fc-5905-467c-9004-51d26fe56f42', 'workflowAttemptNumber': 0, 'jobStore': 'aws:us-west-2:toil-cwl-19398c8c-4067-4302-964d-e727a203e592', 'logLevel': 'DEBUG', 'workDir': None, 'noStdOutErr': False, 'stats': False, 'clean': 'always', 'cleanWorkDir': 'always', 'clusterStats': None, 'restart': False, 'batchSystem': 'kubernetes', 'disableAutoDeployment': False, 'maxLocalJobs': 4, 'manualMemArgs': False, 'coalesceStatusCalls': False, 'statePollingWait': None, 'parasolCommand': 'parasol', 'parasolMaxBatches': 10000, 'scale': 1.0, 'allocate_mem': False, 'tes_endpoint': 'http://10.244.1.58:8000', 'tes_user': None, 'tes_password': None, 'tes_bearer_token': None, 'kubernetes_host_path': '/data/scratch', 'kubernetes_owner': 'toiltest', 'runCwlInternalJobsOnWorkers': False, 'disableCaching': False, 'linkImports': True, 'moveExports': False, 'provisioner': None, 'nodeTypes': [], 'minNodes': None, 'maxNodes': [10], 'targetTime': 1800, 'betaInertia': 0.1, 'scaleInterval': 60, 'preemptableCompensation': 0.0, 'nodeStorage': 50, 'nodeStorageOverrides': [], 'metrics': False, 'maxPreemptableServiceJobs': 9223372036854775807, 'maxServiceJobs': 9223372036854775807, 'deadlockWait': 60, 'deadlockCheckInterval': 30, 'defaultMemory': 2147483648, 'defaultCores': 1, 'defaultDisk': 2147483648, 'readGlobalFileMutableByDefault': False, 'defaultPreemptable': False, 'maxCores': 9223372036854775807, 'maxMemory': 9223372036854775807, 'maxDisk': 9223372036854775807, 'retryCount': 1, 'enableUnlimitedPreemptableRetries': False, 'doubleMem': False, 'maxJobDuration': 9223372036854775807, 'rescueJobsFrequency': 3600, 'environment': {'SINGULARITY_DOCKER_HUB_MIRROR': None}, 'disableChaining': False, 'disableJobStoreChecksumVerification': False, 'maxLogFileSize': 64000, 'writeLogs': None, 'writeLogsGzip': None, 'writeLogsFromAllJobs': False, 'sseKey': None, 'servicePollingInterval': 60, 'useAsync': True, 'forceDockerAppliance': False, 'statusWait': 3600, 'disableProgress': False, 'debugWorker': False, 'disableWorkerOutputCapture': False, 'badWorker': 0.0, 'badWorkerFailInterval': 0.01, 'cwl': False} [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.deferred] Running for file /var/lib/toil/8c043326cea05f40bb60b580ef09859a/deferred/func6tbmfm0a [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Loaded job 83f640fe-9544-49ac-b0d9-936c7a275ea3 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.worker] Parsed job description [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] Working on job 'CWLJob' echo 83f640fe-9544-49ac-b0d9-936c7a275ea3 v1 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.worker] Got a command to run: _toil 3d2dfd8e-7710-4bbc-b9c6-6b9de5444df1 /builds/TnycNQM8/7/databiosphere/toil/src toil.cwl.cwltoil False [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.job] Loading user module ModuleDescriptor(dirPath='/builds/TnycNQM8/7/databiosphere/toil/src', name='toil.cwl.cwltoil', fromVirtualEnv=False). [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Reading FileInfo(fileID='3d2dfd8e-7710-4bbc-b9c6-6b9de5444df1', ownerID='83f640fe-9544-49ac-b0d9-936c7a275ea3', encrypted=False, version='sVTjJJPecpd1g0tLgVmS0e__PJwMf1wo', previousVersion='sVTjJJPecpd1g0tLgVmS0e__PJwMf1wo', content=None, checksum='sha1$5a559a67fc9...af78b1bae3d0132ca', _numContentChunks=0) bound to into stream. [2021-11-19T14:08:01+0000] [Thread-6 ] [D] [toil.jobStores.aws.jobStore] Starting sha1 checksum to match 5a559a67fc9c900afe3b9ddaf78b1bae3d0132ca [2021-11-19T14:08:01+0000] [Thread-6 ] [D] [toil.jobStores.aws.jobStore] Completed checksum with hash 5a559a67fc9c900afe3b9ddaf78b1bae3d0132ca vs. expected 5a559a67fc9c900afe3b9ddaf78b1bae3d0132ca [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] Loaded body Job('CWLJob' echo 83f640fe-9544-49ac-b0d9-936c7a275ea3 v1) from description 'CWLJob' echo 83f640fe-9544-49ac-b0d9-936c7a275ea3 v1 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Starting job ('CWLJob' echo 83f640fe-9544-49ac-b0d9-936c7a275ea3 v1) with ID (83f640fe-9544-49ac-b0d9-936c7a275ea3). [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.deferred] Running orphaned deferred functions [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.deferred] Running job [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Actually running job ('CWLJob' echo 83f640fe-9544-49ac-b0d9-936c7a275ea3 v1) with ID (83f640fe-9544-49ac-b0d9-936c7a275ea3) which wants 3221225472 of our 2671373074432 bytes. [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Max space: 2671373074432 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Total file size: 0 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Total job disk requirement size: 3221225472 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Total immutable reference size: 0 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Available space with job: 2668151848960 bytes [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.cwl.cwltoil] Loaded order: {'a_new_var': False, 'in1': 1} [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.job] Saving graph of 1 jobs, 0 new [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.job] Resolve promise f56d8f36-d5f0-4af7-8073-d794c2d2a0a3 from Job('CWLJob' echo 83f640fe-9544-49ac-b0d9-936c7a275ea3 v1) with a [2021-11-19T14:08:01+0000] [Thread-7 ] [D] [toil.jobStores.aws.jobStore] Inlining content of 57 bytes [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Wrote FileInfo(fileID='f56d8f36-d5f0-4af7-8073-d794c2d2a0a3', ownerID='None', encrypted=False, version='', previousVersion='', content=b'\x80\x05\x9...94)\x81\x94s.', checksum='', _numContentChunks=1) bound to from stream. [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.job] Processing job 'CWLJob' echo 83f640fe-9544-49ac-b0d9-936c7a275ea3 v1 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.abstractFileStore] LOG-TO-MASTER: Job 'CWLJob' echo 83f640fe-9544-49ac-b0d9-936c7a275ea3 v1 used 0.00% disk (0 bB [0B] used, 3.0 GiB [3221225472B] requested). [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.deferred] Running own deferred functions [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.deferred] Out of deferred functions! [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.deferred] Running orphaned deferred functions [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] Completed body for 'CWLJob' echo 83f640fe-9544-49ac-b0d9-936c7a275ea3 v1 [2021-11-19T14:08:01+0000] [Thread-8 ] [D] [toil.fileStores.cachingFileStore] Committing file uploads asynchronously [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.worker] Stopping running chain of jobs: length of stack: 0, services: 0, checkpoint: False [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] Not chaining from job 'CWLJob' echo 83f640fe-9544-49ac-b0d9-936c7a275ea3 v1 [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] Worker log can be found at /var/lib/toil/8c043326cea05f40bb60b580ef09859a/edf2. Set --cleanWorkDir to retain this log [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] Finished running the chain of jobs on this node, we ran for a total of 0.186268 seconds [2021-11-19T14:08:01+0000] [Thread-8 ] [D] [toil.fileStores.cachingFileStore] Committing file deletes and job state changes asynchronously [2021-11-19T14:08:01+0000] [Thread-8 ] [D] [toil.jobStores.aws.jobStore] Updating job 83f640fe-9544-49ac-b0d9-936c7a275ea3 [2021-11-19T14:08:01+0000] [Thread-8 ] [D] [toil.job] New job version: 'CWLJob' echo 83f640fe-9544-49ac-b0d9-936c7a275ea3 v2 <========= [2021-11-19T14:08:02+0000] [Thread-20 ] [D] [toil.jobStores.aws.jobStore] Starting sha1 checksum to match f25e78caad951fa36d37dea1ada27acfdff94749 [2021-11-19T14:08:02+0000] [Thread-20 ] [D] [toil.jobStores.aws.jobStore] Completed checksum with hash f25e78caad951fa36d37dea1ada27acfdff94749 vs. expected f25e78caad951fa36d37dea1ada27acfdff94749 [2021-11-19T14:08:02+0000] [Thread-12 ] [D] [toil.statsAndLogging] Got message from job at time 11-19-2021 14:08:02: Job 'CWLJob' echo a9f944fe-525a-4718-b868-05ef26e0411c v1 used 0.00% disk (0 bB [0B] used, 3.0 GiB [3221225472B] requested). [2021-11-19T14:08:02+0000] [Thread-12 ] [D] [toil.statsAndLogging] Received Toil worker log. Disable debug level logging to hide this output [2021-11-19T14:08:02+0000] [Thread-12 ] [D] [toil.statsAndLogging] Log from job "'CWLJob' echo a9f944fe-525a-4718-b868-05ef26e0411c v1" follows: =========> [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] ---TOIL WORKER OUTPUT LOG--- [2021-11-19T14:08:01+0000] [MainThread] [I] [toil] Running Toil version 5.6.0a1-604176544d7178bb415a1dd98f0084d1a1b7f65b on host toiltest-toil-1065dcea-65fd-4642-9515-d3d93cdb6134-6-m8rht. [2021-11-19T14:08:01+0000] [MainThread] [D] [toil] Configuration: {'workflowID': '746138fc-5905-467c-9004-51d26fe56f42', 'workflowAttemptNumber': 0, 'jobStore': 'aws:us-west-2:toil-cwl-19398c8c-4067-4302-964d-e727a203e592', 'logLevel': 'DEBUG', 'workDir': None, 'noStdOutErr': False, 'stats': False, 'clean': 'always', 'cleanWorkDir': 'always', 'clusterStats': None, 'restart': False, 'batchSystem': 'kubernetes', 'disableAutoDeployment': False, 'maxLocalJobs': 4, 'manualMemArgs': False, 'coalesceStatusCalls': False, 'statePollingWait': None, 'parasolCommand': 'parasol', 'parasolMaxBatches': 10000, 'scale': 1.0, 'allocate_mem': False, 'tes_endpoint': 'http://10.244.1.58:8000', 'tes_user': None, 'tes_password': None, 'tes_bearer_token': None, 'kubernetes_host_path': '/data/scratch', 'kubernetes_owner': 'toiltest', 'runCwlInternalJobsOnWorkers': False, 'disableCaching': False, 'linkImports': True, 'moveExports': False, 'provisioner': None, 'nodeTypes': [], 'minNodes': None, 'maxNodes': [10], 'targetTime': 1800, 'betaInertia': 0.1, 'scaleInterval': 60, 'preemptableCompensation': 0.0, 'nodeStorage': 50, 'nodeStorageOverrides': [], 'metrics': False, 'maxPreemptableServiceJobs': 9223372036854775807, 'maxServiceJobs': 9223372036854775807, 'deadlockWait': 60, 'deadlockCheckInterval': 30, 'defaultMemory': 2147483648, 'defaultCores': 1, 'defaultDisk': 2147483648, 'readGlobalFileMutableByDefault': False, 'defaultPreemptable': False, 'maxCores': 9223372036854775807, 'maxMemory': 9223372036854775807, 'maxDisk': 9223372036854775807, 'retryCount': 1, 'enableUnlimitedPreemptableRetries': False, 'doubleMem': False, 'maxJobDuration': 9223372036854775807, 'rescueJobsFrequency': 3600, 'environment': {'SINGULARITY_DOCKER_HUB_MIRROR': None}, 'disableChaining': False, 'disableJobStoreChecksumVerification': False, 'maxLogFileSize': 64000, 'writeLogs': None, 'writeLogsGzip': None, 'writeLogsFromAllJobs': False, 'sseKey': None, 'servicePollingInterval': 60, 'useAsync': True, 'forceDockerAppliance': False, 'statusWait': 3600, 'disableProgress': False, 'debugWorker': False, 'disableWorkerOutputCapture': False, 'badWorker': 0.0, 'badWorkerFailInterval': 0.01, 'cwl': False} [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.deferred] Running for file /var/lib/toil/8c043326cea05f40bb60b580ef09859a/deferred/funcat491bvu [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Loaded job a9f944fe-525a-4718-b868-05ef26e0411c [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.worker] Parsed job description [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] Working on job 'CWLJob' echo a9f944fe-525a-4718-b868-05ef26e0411c v1 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.worker] Got a command to run: _toil 4de04405-2cfc-4156-ad54-dec8dfb43715 /builds/TnycNQM8/7/databiosphere/toil/src toil.cwl.cwltoil False [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.job] Loading user module ModuleDescriptor(dirPath='/builds/TnycNQM8/7/databiosphere/toil/src', name='toil.cwl.cwltoil', fromVirtualEnv=False). [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Reading FileInfo(fileID='4de04405-2cfc-4156-ad54-dec8dfb43715', ownerID='a9f944fe-525a-4718-b868-05ef26e0411c', encrypted=False, version='.T20XzvnoD41oYOOfQQBfsxgL3TfROku', previousVersion='.T20XzvnoD41oYOOfQQBfsxgL3TfROku', content=None, checksum='sha1$68decd38984...1ef9b57c5521a6dd0', _numContentChunks=0) bound to into stream. [2021-11-19T14:08:01+0000] [Thread-6 ] [D] [toil.jobStores.aws.jobStore] Starting sha1 checksum to match 68decd3898434c797c205371ef9b57c5521a6dd0 [2021-11-19T14:08:01+0000] [Thread-6 ] [D] [toil.jobStores.aws.jobStore] Completed checksum with hash 68decd3898434c797c205371ef9b57c5521a6dd0 vs. expected 68decd3898434c797c205371ef9b57c5521a6dd0 [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] Loaded body Job('CWLJob' echo a9f944fe-525a-4718-b868-05ef26e0411c v1) from description 'CWLJob' echo a9f944fe-525a-4718-b868-05ef26e0411c v1 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Starting job ('CWLJob' echo a9f944fe-525a-4718-b868-05ef26e0411c v1) with ID (a9f944fe-525a-4718-b868-05ef26e0411c). [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.deferred] Running orphaned deferred functions [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.deferred] Running job [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Actually running job ('CWLJob' echo a9f944fe-525a-4718-b868-05ef26e0411c v1) with ID (a9f944fe-525a-4718-b868-05ef26e0411c) which wants 3221225472 of our 2671373074432 bytes. [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Max space: 2671373074432 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Total file size: 0 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Total job disk requirement size: 12884901888 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Total immutable reference size: 0 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Available space with job: 2658488172544 bytes [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.cwl.cwltoil] Loaded order: {'a_new_var': True, 'in1': 5} [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.cwl.cwltoil] Output disposition: move [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.cwl.cwltoil] Running tool ToilCommandLineTool('file:///builds/TnycNQM8/7/databiosphere/toil/src/toil/test/cwl/spec_v12/tests/conditionals/foo.cwl') with order: {'a_new_var': True, 'in1': 5} [2021-11-19T14:08:01+0000] [MainThread] [D] [cwltool] [job foo.cwl] initializing from file:///builds/TnycNQM8/7/databiosphere/toil/src/toil/test/cwl/spec_v12/tests/conditionals/foo.cwl [2021-11-19T14:08:01+0000] [MainThread] [D] [cwltool] [job foo.cwl] { "in1": 5 } [2021-11-19T14:08:01+0000] [MainThread] [D] [cwltool] [job foo.cwl] path mappings is {} [2021-11-19T14:08:01+0000] [MainThread] [D] [cwltool] [job foo.cwl] command line bindings is [ { "position": [ -1000000, 0 ], "datum": "echo" } ] [2021-11-19T14:08:01+0000] [MainThread] [D] [cwltool] [job foo.cwl] initial work dir {} [2021-11-19T14:08:01+0000] [MainThread] [I] [cwltool] [job foo.cwl] /var/lib/toil/8c043326cea05f40bb60b580ef09859a/9e94/b461/tmp0fac0feh/tmp-out4lwexq8o$ echo [2021-11-19T14:08:01+0000] [MainThread] [D] [cwltool] Could not collect memory usage, job ended before monitoring began. [2021-11-19T14:08:01+0000] [MainThread] [I] [cwltool] [job foo.cwl] completed success [2021-11-19T14:08:01+0000] [MainThread] [D] [cwltool] [job foo.cwl] outputs { "out1": "foo 5" } [2021-11-19T14:08:01+0000] [MainThread] [D] [cwltool] [job foo.cwl] Removing input staging directory /var/lib/toil/8c043326cea05f40bb60b580ef09859a/9e94/b461/tmpriebupsiu228071_ [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.cwl.cwltoil] Importing files for {'out1': 'foo 5'} [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.cwl.cwltoil] Emitting output: {'out1': 'foo 5'} [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.job] Saving graph of 1 jobs, 0 new [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.job] Resolve promise 4b8a2991-085d-4493-a163-75849885e075 from Job('CWLJob' echo a9f944fe-525a-4718-b868-05ef26e0411c v1) with a [2021-11-19T14:08:01+0000] [Thread-8 ] [D] [toil.jobStores.aws.jobStore] Inlining content of 30 bytes [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Wrote FileInfo(fileID='4b8a2991-085d-4493-a163-75849885e075', ownerID='None', encrypted=False, version='', previousVersion='', content=b'\x80\x05\x9...05foo 5\x94s.', checksum='', _numContentChunks=1) bound to from stream. [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.job] Processing job 'CWLJob' echo a9f944fe-525a-4718-b868-05ef26e0411c v1 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.abstractFileStore] LOG-TO-MASTER: Job 'CWLJob' echo a9f944fe-525a-4718-b868-05ef26e0411c v1 used 0.00% disk (0 bB [0B] used, 3.0 GiB [3221225472B] requested). [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.deferred] Running own deferred functions [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.deferred] Out of deferred functions! [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.deferred] Running orphaned deferred functions [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] Completed body for 'CWLJob' echo a9f944fe-525a-4718-b868-05ef26e0411c v1 [2021-11-19T14:08:01+0000] [Thread-9 ] [D] [toil.fileStores.cachingFileStore] Committing file uploads asynchronously [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.worker] Stopping running chain of jobs: length of stack: 0, services: 0, checkpoint: False [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] Not chaining from job 'CWLJob' echo a9f944fe-525a-4718-b868-05ef26e0411c v1 [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] Worker log can be found at /var/lib/toil/8c043326cea05f40bb60b580ef09859a/9e94. Set --cleanWorkDir to retain this log [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] Finished running the chain of jobs on this node, we ran for a total of 0.180491 seconds [2021-11-19T14:08:01+0000] [Thread-9 ] [D] [toil.fileStores.cachingFileStore] Committing file deletes and job state changes asynchronously [2021-11-19T14:08:01+0000] [Thread-9 ] [D] [toil.jobStores.aws.jobStore] Updating job a9f944fe-525a-4718-b868-05ef26e0411c [2021-11-19T14:08:01+0000] [Thread-9 ] [D] [toil.job] New job version: 'CWLJob' echo a9f944fe-525a-4718-b868-05ef26e0411c v2 <========= [2021-11-19T14:08:02+0000] [Thread-22 ] [D] [toil.jobStores.aws.jobStore] Starting sha1 checksum to match 8a45fcb6d2e1cc26f690b9905a0ee4b3994cc4f2 [2021-11-19T14:08:02+0000] [Thread-22 ] [D] [toil.jobStores.aws.jobStore] Completed checksum with hash 8a45fcb6d2e1cc26f690b9905a0ee4b3994cc4f2 vs. expected 8a45fcb6d2e1cc26f690b9905a0ee4b3994cc4f2 [2021-11-19T14:08:02+0000] [Thread-12 ] [D] [toil.statsAndLogging] Got message from job at time 11-19-2021 14:08:02: Job 'CWLJob' echo 692c58c7-3a47-4eb7-85c8-e0985f57f305 v1 used 0.00% disk (0 bB [0B] used, 3.0 GiB [3221225472B] requested). [2021-11-19T14:08:02+0000] [Thread-12 ] [D] [toil.statsAndLogging] Received Toil worker log. Disable debug level logging to hide this output [2021-11-19T14:08:02+0000] [Thread-12 ] [D] [toil.statsAndLogging] Log from job "'CWLJob' echo 692c58c7-3a47-4eb7-85c8-e0985f57f305 v1" follows: =========> [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] ---TOIL WORKER OUTPUT LOG--- [2021-11-19T14:08:01+0000] [MainThread] [I] [toil] Running Toil version 5.6.0a1-604176544d7178bb415a1dd98f0084d1a1b7f65b on host toiltest-toil-1065dcea-65fd-4642-9515-d3d93cdb6134-5-ncrfk. [2021-11-19T14:08:01+0000] [MainThread] [D] [toil] Configuration: {'workflowID': '746138fc-5905-467c-9004-51d26fe56f42', 'workflowAttemptNumber': 0, 'jobStore': 'aws:us-west-2:toil-cwl-19398c8c-4067-4302-964d-e727a203e592', 'logLevel': 'DEBUG', 'workDir': None, 'noStdOutErr': False, 'stats': False, 'clean': 'always', 'cleanWorkDir': 'always', 'clusterStats': None, 'restart': False, 'batchSystem': 'kubernetes', 'disableAutoDeployment': False, 'maxLocalJobs': 4, 'manualMemArgs': False, 'coalesceStatusCalls': False, 'statePollingWait': None, 'parasolCommand': 'parasol', 'parasolMaxBatches': 10000, 'scale': 1.0, 'allocate_mem': False, 'tes_endpoint': 'http://10.244.1.58:8000', 'tes_user': None, 'tes_password': None, 'tes_bearer_token': None, 'kubernetes_host_path': '/data/scratch', 'kubernetes_owner': 'toiltest', 'runCwlInternalJobsOnWorkers': False, 'disableCaching': False, 'linkImports': True, 'moveExports': False, 'provisioner': None, 'nodeTypes': [], 'minNodes': None, 'maxNodes': [10], 'targetTime': 1800, 'betaInertia': 0.1, 'scaleInterval': 60, 'preemptableCompensation': 0.0, 'nodeStorage': 50, 'nodeStorageOverrides': [], 'metrics': False, 'maxPreemptableServiceJobs': 9223372036854775807, 'maxServiceJobs': 9223372036854775807, 'deadlockWait': 60, 'deadlockCheckInterval': 30, 'defaultMemory': 2147483648, 'defaultCores': 1, 'defaultDisk': 2147483648, 'readGlobalFileMutableByDefault': False, 'defaultPreemptable': False, 'maxCores': 9223372036854775807, 'maxMemory': 9223372036854775807, 'maxDisk': 9223372036854775807, 'retryCount': 1, 'enableUnlimitedPreemptableRetries': False, 'doubleMem': False, 'maxJobDuration': 9223372036854775807, 'rescueJobsFrequency': 3600, 'environment': {'SINGULARITY_DOCKER_HUB_MIRROR': None}, 'disableChaining': False, 'disableJobStoreChecksumVerification': False, 'maxLogFileSize': 64000, 'writeLogs': None, 'writeLogsGzip': None, 'writeLogsFromAllJobs': False, 'sseKey': None, 'servicePollingInterval': 60, 'useAsync': True, 'forceDockerAppliance': False, 'statusWait': 3600, 'disableProgress': False, 'debugWorker': False, 'disableWorkerOutputCapture': False, 'badWorker': 0.0, 'badWorkerFailInterval': 0.01, 'cwl': False} [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.deferred] Running for file /var/lib/toil/8c043326cea05f40bb60b580ef09859a/deferred/func4hm05qd5 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Loaded job 692c58c7-3a47-4eb7-85c8-e0985f57f305 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.worker] Parsed job description [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] Working on job 'CWLJob' echo 692c58c7-3a47-4eb7-85c8-e0985f57f305 v1 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.worker] Got a command to run: _toil 03110d45-a199-4570-8db2-f81a4b939ddb /builds/TnycNQM8/7/databiosphere/toil/src toil.cwl.cwltoil False [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.job] Loading user module ModuleDescriptor(dirPath='/builds/TnycNQM8/7/databiosphere/toil/src', name='toil.cwl.cwltoil', fromVirtualEnv=False). [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Reading FileInfo(fileID='03110d45-a199-4570-8db2-f81a4b939ddb', ownerID='692c58c7-3a47-4eb7-85c8-e0985f57f305', encrypted=False, version='WsjYbW0qNs8X3bgkD5xlvEHTm3NjE6bG', previousVersion='WsjYbW0qNs8X3bgkD5xlvEHTm3NjE6bG', content=None, checksum='sha1$fd46a2918ba...6143f82ca1d8ad2c4', _numContentChunks=0) bound to into stream. [2021-11-19T14:08:01+0000] [Thread-6 ] [D] [toil.jobStores.aws.jobStore] Starting sha1 checksum to match fd46a2918ba5a962f009e096143f82ca1d8ad2c4 [2021-11-19T14:08:01+0000] [Thread-6 ] [D] [toil.jobStores.aws.jobStore] Completed checksum with hash fd46a2918ba5a962f009e096143f82ca1d8ad2c4 vs. expected fd46a2918ba5a962f009e096143f82ca1d8ad2c4 [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] Loaded body Job('CWLJob' echo 692c58c7-3a47-4eb7-85c8-e0985f57f305 v1) from description 'CWLJob' echo 692c58c7-3a47-4eb7-85c8-e0985f57f305 v1 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Starting job ('CWLJob' echo 692c58c7-3a47-4eb7-85c8-e0985f57f305 v1) with ID (692c58c7-3a47-4eb7-85c8-e0985f57f305). [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.deferred] Running orphaned deferred functions [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.deferred] Running job [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Actually running job ('CWLJob' echo 692c58c7-3a47-4eb7-85c8-e0985f57f305 v1) with ID (692c58c7-3a47-4eb7-85c8-e0985f57f305) which wants 3221225472 of our 2671373074432 bytes. [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Max space: 2671373074432 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Total file size: 0 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Total job disk requirement size: 9663676416 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Total immutable reference size: 0 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Available space with job: 2661709398016 bytes [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.cwl.cwltoil] Loaded order: {'a_new_var': False, 'in1': 2} [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.job] Saving graph of 1 jobs, 0 new [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.job] Resolve promise d88dfda4-5d8a-4a6d-acfd-697de89b74b2 from Job('CWLJob' echo 692c58c7-3a47-4eb7-85c8-e0985f57f305 v1) with a [2021-11-19T14:08:01+0000] [Thread-7 ] [D] [toil.jobStores.aws.jobStore] Inlining content of 57 bytes [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Wrote FileInfo(fileID='d88dfda4-5d8a-4a6d-acfd-697de89b74b2', ownerID='None', encrypted=False, version='', previousVersion='', content=b'\x80\x05\x9...94)\x81\x94s.', checksum='', _numContentChunks=1) bound to from stream. [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.job] Processing job 'CWLJob' echo 692c58c7-3a47-4eb7-85c8-e0985f57f305 v1 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.abstractFileStore] LOG-TO-MASTER: Job 'CWLJob' echo 692c58c7-3a47-4eb7-85c8-e0985f57f305 v1 used 0.00% disk (0 bB [0B] used, 3.0 GiB [3221225472B] requested). [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.deferred] Running own deferred functions [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.deferred] Out of deferred functions! [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.deferred] Running orphaned deferred functions [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] Completed body for 'CWLJob' echo 692c58c7-3a47-4eb7-85c8-e0985f57f305 v1 [2021-11-19T14:08:01+0000] [Thread-8 ] [D] [toil.fileStores.cachingFileStore] Committing file uploads asynchronously [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.worker] Stopping running chain of jobs: length of stack: 0, services: 0, checkpoint: False [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] Not chaining from job 'CWLJob' echo 692c58c7-3a47-4eb7-85c8-e0985f57f305 v1 [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] Worker log can be found at /var/lib/toil/8c043326cea05f40bb60b580ef09859a/e476. Set --cleanWorkDir to retain this log [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] Finished running the chain of jobs on this node, we ran for a total of 0.187729 seconds [2021-11-19T14:08:01+0000] [Thread-8 ] [D] [toil.fileStores.cachingFileStore] Committing file deletes and job state changes asynchronously [2021-11-19T14:08:01+0000] [Thread-8 ] [D] [toil.jobStores.aws.jobStore] Updating job 692c58c7-3a47-4eb7-85c8-e0985f57f305 [2021-11-19T14:08:01+0000] [Thread-8 ] [D] [toil.job] New job version: 'CWLJob' echo 692c58c7-3a47-4eb7-85c8-e0985f57f305 v2 <========= [2021-11-19T14:08:02+0000] [Thread-24 ] [D] [toil.jobStores.aws.jobStore] Starting sha1 checksum to match bbca8f7e28ea37d30d10c365033711223ed497ed [2021-11-19T14:08:02+0000] [Thread-24 ] [D] [toil.jobStores.aws.jobStore] Completed checksum with hash bbca8f7e28ea37d30d10c365033711223ed497ed vs. expected bbca8f7e28ea37d30d10c365033711223ed497ed [2021-11-19T14:08:02+0000] [Thread-12 ] [D] [toil.statsAndLogging] Got message from job at time 11-19-2021 14:08:02: Job 'CWLJob' echo 6ca66447-352c-4e3a-970d-6b483ec82646 v1 used 0.00% disk (0 bB [0B] used, 3.0 GiB [3221225472B] requested). [2021-11-19T14:08:02+0000] [Thread-12 ] [D] [toil.statsAndLogging] Received Toil worker log. Disable debug level logging to hide this output [2021-11-19T14:08:02+0000] [Thread-12 ] [D] [toil.statsAndLogging] Log from job "'CWLJob' echo 6ca66447-352c-4e3a-970d-6b483ec82646 v1" follows: =========> [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] ---TOIL WORKER OUTPUT LOG--- [2021-11-19T14:08:01+0000] [MainThread] [I] [toil] Running Toil version 5.6.0a1-604176544d7178bb415a1dd98f0084d1a1b7f65b on host toiltest-toil-1065dcea-65fd-4642-9515-d3d93cdb6134-4-2m5x7. [2021-11-19T14:08:01+0000] [MainThread] [D] [toil] Configuration: {'workflowID': '746138fc-5905-467c-9004-51d26fe56f42', 'workflowAttemptNumber': 0, 'jobStore': 'aws:us-west-2:toil-cwl-19398c8c-4067-4302-964d-e727a203e592', 'logLevel': 'DEBUG', 'workDir': None, 'noStdOutErr': False, 'stats': False, 'clean': 'always', 'cleanWorkDir': 'always', 'clusterStats': None, 'restart': False, 'batchSystem': 'kubernetes', 'disableAutoDeployment': False, 'maxLocalJobs': 4, 'manualMemArgs': False, 'coalesceStatusCalls': False, 'statePollingWait': None, 'parasolCommand': 'parasol', 'parasolMaxBatches': 10000, 'scale': 1.0, 'allocate_mem': False, 'tes_endpoint': 'http://10.244.1.58:8000', 'tes_user': None, 'tes_password': None, 'tes_bearer_token': None, 'kubernetes_host_path': '/data/scratch', 'kubernetes_owner': 'toiltest', 'runCwlInternalJobsOnWorkers': False, 'disableCaching': False, 'linkImports': True, 'moveExports': False, 'provisioner': None, 'nodeTypes': [], 'minNodes': None, 'maxNodes': [10], 'targetTime': 1800, 'betaInertia': 0.1, 'scaleInterval': 60, 'preemptableCompensation': 0.0, 'nodeStorage': 50, 'nodeStorageOverrides': [], 'metrics': False, 'maxPreemptableServiceJobs': 9223372036854775807, 'maxServiceJobs': 9223372036854775807, 'deadlockWait': 60, 'deadlockCheckInterval': 30, 'defaultMemory': 2147483648, 'defaultCores': 1, 'defaultDisk': 2147483648, 'readGlobalFileMutableByDefault': False, 'defaultPreemptable': False, 'maxCores': 9223372036854775807, 'maxMemory': 9223372036854775807, 'maxDisk': 9223372036854775807, 'retryCount': 1, 'enableUnlimitedPreemptableRetries': False, 'doubleMem': False, 'maxJobDuration': 9223372036854775807, 'rescueJobsFrequency': 3600, 'environment': {'SINGULARITY_DOCKER_HUB_MIRROR': None}, 'disableChaining': False, 'disableJobStoreChecksumVerification': False, 'maxLogFileSize': 64000, 'writeLogs': None, 'writeLogsGzip': None, 'writeLogsFromAllJobs': False, 'sseKey': None, 'servicePollingInterval': 60, 'useAsync': True, 'forceDockerAppliance': False, 'statusWait': 3600, 'disableProgress': False, 'debugWorker': False, 'disableWorkerOutputCapture': False, 'badWorker': 0.0, 'badWorkerFailInterval': 0.01, 'cwl': False} [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.deferred] Running for file /var/lib/toil/8c043326cea05f40bb60b580ef09859a/deferred/func576q4dl1 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Loaded job 6ca66447-352c-4e3a-970d-6b483ec82646 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.worker] Parsed job description [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] Working on job 'CWLJob' echo 6ca66447-352c-4e3a-970d-6b483ec82646 v1 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.worker] Got a command to run: _toil e13d6055-c7b7-4c69-a1b1-9eac24c52d08 /builds/TnycNQM8/7/databiosphere/toil/src toil.cwl.cwltoil False [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.job] Loading user module ModuleDescriptor(dirPath='/builds/TnycNQM8/7/databiosphere/toil/src', name='toil.cwl.cwltoil', fromVirtualEnv=False). [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Reading FileInfo(fileID='e13d6055-c7b7-4c69-a1b1-9eac24c52d08', ownerID='6ca66447-352c-4e3a-970d-6b483ec82646', encrypted=False, version='p0ixZxAbeChX2NnnBz_GVr.tP9tminuW', previousVersion='p0ixZxAbeChX2NnnBz_GVr.tP9tminuW', content=None, checksum='sha1$b6458b7f606...aa8cc99d9e74a288b', _numContentChunks=0) bound to into stream. [2021-11-19T14:08:01+0000] [Thread-6 ] [D] [toil.jobStores.aws.jobStore] Starting sha1 checksum to match b6458b7f606aec4302a89daaa8cc99d9e74a288b [2021-11-19T14:08:01+0000] [Thread-6 ] [D] [toil.jobStores.aws.jobStore] Completed checksum with hash b6458b7f606aec4302a89daaa8cc99d9e74a288b vs. expected b6458b7f606aec4302a89daaa8cc99d9e74a288b [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] Loaded body Job('CWLJob' echo 6ca66447-352c-4e3a-970d-6b483ec82646 v1) from description 'CWLJob' echo 6ca66447-352c-4e3a-970d-6b483ec82646 v1 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Starting job ('CWLJob' echo 6ca66447-352c-4e3a-970d-6b483ec82646 v1) with ID (6ca66447-352c-4e3a-970d-6b483ec82646). [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.deferred] Running orphaned deferred functions [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.deferred] Running job [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Actually running job ('CWLJob' echo 6ca66447-352c-4e3a-970d-6b483ec82646 v1) with ID (6ca66447-352c-4e3a-970d-6b483ec82646) which wants 3221225472 of our 2671373074432 bytes. [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Max space: 2671373074432 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Total file size: 0 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Total job disk requirement size: 6442450944 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Total immutable reference size: 0 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Available space with job: 2664930623488 bytes [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.cwl.cwltoil] Loaded order: {'a_new_var': True, 'in1': 6} [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.cwl.cwltoil] Output disposition: move [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.cwl.cwltoil] Running tool ToilCommandLineTool('file:///builds/TnycNQM8/7/databiosphere/toil/src/toil/test/cwl/spec_v12/tests/conditionals/foo.cwl') with order: {'a_new_var': True, 'in1': 6} [2021-11-19T14:08:01+0000] [MainThread] [D] [cwltool] [job foo.cwl] initializing from file:///builds/TnycNQM8/7/databiosphere/toil/src/toil/test/cwl/spec_v12/tests/conditionals/foo.cwl [2021-11-19T14:08:01+0000] [MainThread] [D] [cwltool] [job foo.cwl] { "in1": 6 } [2021-11-19T14:08:01+0000] [MainThread] [D] [cwltool] [job foo.cwl] path mappings is {} [2021-11-19T14:08:01+0000] [MainThread] [D] [cwltool] [job foo.cwl] command line bindings is [ { "position": [ -1000000, 0 ], "datum": "echo" } ] [2021-11-19T14:08:01+0000] [MainThread] [D] [cwltool] [job foo.cwl] initial work dir {} [2021-11-19T14:08:01+0000] [MainThread] [I] [cwltool] [job foo.cwl] /var/lib/toil/8c043326cea05f40bb60b580ef09859a/1454/05dc/tmp993e157v/tmp-outvf32xi__$ echo [2021-11-19T14:08:01+0000] [MainThread] [D] [cwltool] Could not collect memory usage, job ended before monitoring began. [2021-11-19T14:08:01+0000] [MainThread] [I] [cwltool] [job foo.cwl] completed success [2021-11-19T14:08:01+0000] [MainThread] [D] [cwltool] [job foo.cwl] outputs { "out1": "foo 6" } [2021-11-19T14:08:01+0000] [MainThread] [D] [cwltool] [job foo.cwl] Removing input staging directory /var/lib/toil/8c043326cea05f40bb60b580ef09859a/1454/05dc/tmpei0rzpl_y1hkggot [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.cwl.cwltoil] Importing files for {'out1': 'foo 6'} [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.cwl.cwltoil] Emitting output: {'out1': 'foo 6'} [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.job] Saving graph of 1 jobs, 0 new [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.job] Resolve promise bd458e00-c135-418b-bd2c-3cc500e6a182 from Job('CWLJob' echo 6ca66447-352c-4e3a-970d-6b483ec82646 v1) with a [2021-11-19T14:08:01+0000] [Thread-8 ] [D] [toil.jobStores.aws.jobStore] Inlining content of 30 bytes [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Wrote FileInfo(fileID='bd458e00-c135-418b-bd2c-3cc500e6a182', ownerID='None', encrypted=False, version='', previousVersion='', content=b'\x80\x05\x9...05foo 6\x94s.', checksum='', _numContentChunks=1) bound to from stream. [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.job] Processing job 'CWLJob' echo 6ca66447-352c-4e3a-970d-6b483ec82646 v1 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.abstractFileStore] LOG-TO-MASTER: Job 'CWLJob' echo 6ca66447-352c-4e3a-970d-6b483ec82646 v1 used 0.00% disk (0 bB [0B] used, 3.0 GiB [3221225472B] requested). [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.deferred] Running own deferred functions [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.deferred] Out of deferred functions! [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.deferred] Running orphaned deferred functions [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] Completed body for 'CWLJob' echo 6ca66447-352c-4e3a-970d-6b483ec82646 v1 [2021-11-19T14:08:01+0000] [Thread-9 ] [D] [toil.fileStores.cachingFileStore] Committing file uploads asynchronously [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.worker] Stopping running chain of jobs: length of stack: 0, services: 0, checkpoint: False [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] Not chaining from job 'CWLJob' echo 6ca66447-352c-4e3a-970d-6b483ec82646 v1 [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] Worker log can be found at /var/lib/toil/8c043326cea05f40bb60b580ef09859a/1454. Set --cleanWorkDir to retain this log [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] Finished running the chain of jobs on this node, we ran for a total of 0.205865 seconds [2021-11-19T14:08:01+0000] [Thread-9 ] [D] [toil.fileStores.cachingFileStore] Committing file deletes and job state changes asynchronously [2021-11-19T14:08:01+0000] [Thread-9 ] [D] [toil.jobStores.aws.jobStore] Updating job 6ca66447-352c-4e3a-970d-6b483ec82646 [2021-11-19T14:08:01+0000] [Thread-9 ] [D] [toil.job] New job version: 'CWLJob' echo 6ca66447-352c-4e3a-970d-6b483ec82646 v2 <========= [2021-11-19T14:08:02+0000] [Thread-26 ] [D] [toil.jobStores.aws.jobStore] Starting sha1 checksum to match 22202a02d69080d8efb27b3ac75ef61cff33dcb2 [2021-11-19T14:08:02+0000] [Thread-26 ] [D] [toil.jobStores.aws.jobStore] Completed checksum with hash 22202a02d69080d8efb27b3ac75ef61cff33dcb2 vs. expected 22202a02d69080d8efb27b3ac75ef61cff33dcb2 [2021-11-19T14:08:02+0000] [Thread-12 ] [D] [toil.statsAndLogging] Got message from job at time 11-19-2021 14:08:02: Job 'CWLJob' echo 9eb39b4a-6641-4a16-990c-761c5e880ad1 v1 used 0.00% disk (0 bB [0B] used, 3.0 GiB [3221225472B] requested). [2021-11-19T14:08:02+0000] [Thread-12 ] [D] [toil.statsAndLogging] Received Toil worker log. Disable debug level logging to hide this output [2021-11-19T14:08:02+0000] [Thread-12 ] [D] [toil.statsAndLogging] Log from job "'CWLJob' echo 9eb39b4a-6641-4a16-990c-761c5e880ad1 v1" follows: =========> [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] ---TOIL WORKER OUTPUT LOG--- [2021-11-19T14:08:01+0000] [MainThread] [I] [toil] Running Toil version 5.6.0a1-604176544d7178bb415a1dd98f0084d1a1b7f65b on host toiltest-toil-1065dcea-65fd-4642-9515-d3d93cdb6134-2-56rtf. [2021-11-19T14:08:01+0000] [MainThread] [D] [toil] Configuration: {'workflowID': '746138fc-5905-467c-9004-51d26fe56f42', 'workflowAttemptNumber': 0, 'jobStore': 'aws:us-west-2:toil-cwl-19398c8c-4067-4302-964d-e727a203e592', 'logLevel': 'DEBUG', 'workDir': None, 'noStdOutErr': False, 'stats': False, 'clean': 'always', 'cleanWorkDir': 'always', 'clusterStats': None, 'restart': False, 'batchSystem': 'kubernetes', 'disableAutoDeployment': False, 'maxLocalJobs': 4, 'manualMemArgs': False, 'coalesceStatusCalls': False, 'statePollingWait': None, 'parasolCommand': 'parasol', 'parasolMaxBatches': 10000, 'scale': 1.0, 'allocate_mem': False, 'tes_endpoint': 'http://10.244.1.58:8000', 'tes_user': None, 'tes_password': None, 'tes_bearer_token': None, 'kubernetes_host_path': '/data/scratch', 'kubernetes_owner': 'toiltest', 'runCwlInternalJobsOnWorkers': False, 'disableCaching': False, 'linkImports': True, 'moveExports': False, 'provisioner': None, 'nodeTypes': [], 'minNodes': None, 'maxNodes': [10], 'targetTime': 1800, 'betaInertia': 0.1, 'scaleInterval': 60, 'preemptableCompensation': 0.0, 'nodeStorage': 50, 'nodeStorageOverrides': [], 'metrics': False, 'maxPreemptableServiceJobs': 9223372036854775807, 'maxServiceJobs': 9223372036854775807, 'deadlockWait': 60, 'deadlockCheckInterval': 30, 'defaultMemory': 2147483648, 'defaultCores': 1, 'defaultDisk': 2147483648, 'readGlobalFileMutableByDefault': False, 'defaultPreemptable': False, 'maxCores': 9223372036854775807, 'maxMemory': 9223372036854775807, 'maxDisk': 9223372036854775807, 'retryCount': 1, 'enableUnlimitedPreemptableRetries': False, 'doubleMem': False, 'maxJobDuration': 9223372036854775807, 'rescueJobsFrequency': 3600, 'environment': {'SINGULARITY_DOCKER_HUB_MIRROR': None}, 'disableChaining': False, 'disableJobStoreChecksumVerification': False, 'maxLogFileSize': 64000, 'writeLogs': None, 'writeLogsGzip': None, 'writeLogsFromAllJobs': False, 'sseKey': None, 'servicePollingInterval': 60, 'useAsync': True, 'forceDockerAppliance': False, 'statusWait': 3600, 'disableProgress': False, 'debugWorker': False, 'disableWorkerOutputCapture': False, 'badWorker': 0.0, 'badWorkerFailInterval': 0.01, 'cwl': False} [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.deferred] Running for file /var/lib/toil/8c043326cea05f40bb60b580ef09859a/deferred/funcp8770oni [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Loaded job 9eb39b4a-6641-4a16-990c-761c5e880ad1 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.worker] Parsed job description [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] Working on job 'CWLJob' echo 9eb39b4a-6641-4a16-990c-761c5e880ad1 v1 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.worker] Got a command to run: _toil 551af678-3422-4dec-b5de-02491df40074 /builds/TnycNQM8/7/databiosphere/toil/src toil.cwl.cwltoil False [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.job] Loading user module ModuleDescriptor(dirPath='/builds/TnycNQM8/7/databiosphere/toil/src', name='toil.cwl.cwltoil', fromVirtualEnv=False). [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Reading FileInfo(fileID='551af678-3422-4dec-b5de-02491df40074', ownerID='9eb39b4a-6641-4a16-990c-761c5e880ad1', encrypted=False, version='hIg2D.WGkXoZwXtNHrsgUWvMnJxNl9Jy', previousVersion='hIg2D.WGkXoZwXtNHrsgUWvMnJxNl9Jy', content=None, checksum='sha1$eab2a69360c...dfa2056d3bc25d5b2', _numContentChunks=0) bound to into stream. [2021-11-19T14:08:01+0000] [Thread-6 ] [D] [toil.jobStores.aws.jobStore] Starting sha1 checksum to match eab2a69360c5438bfe6de8ddfa2056d3bc25d5b2 [2021-11-19T14:08:01+0000] [Thread-6 ] [D] [toil.jobStores.aws.jobStore] Completed checksum with hash eab2a69360c5438bfe6de8ddfa2056d3bc25d5b2 vs. expected eab2a69360c5438bfe6de8ddfa2056d3bc25d5b2 [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] Loaded body Job('CWLJob' echo 9eb39b4a-6641-4a16-990c-761c5e880ad1 v1) from description 'CWLJob' echo 9eb39b4a-6641-4a16-990c-761c5e880ad1 v1 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Starting job ('CWLJob' echo 9eb39b4a-6641-4a16-990c-761c5e880ad1 v1) with ID (9eb39b4a-6641-4a16-990c-761c5e880ad1). [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.deferred] Running orphaned deferred functions [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.deferred] Running job [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Actually running job ('CWLJob' echo 9eb39b4a-6641-4a16-990c-761c5e880ad1 v1) with ID (9eb39b4a-6641-4a16-990c-761c5e880ad1) which wants 3221225472 of our 2671373074432 bytes. [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Max space: 2671373074432 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Total file size: 0 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Total job disk requirement size: 16106127360 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Total immutable reference size: 0 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Available space with job: 2655266947072 bytes [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.cwl.cwltoil] Loaded order: {'a_new_var': False, 'in1': 3} [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.job] Saving graph of 1 jobs, 0 new [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.job] Resolve promise 85c4ac5e-051c-40ee-8101-582b088f5c1f from Job('CWLJob' echo 9eb39b4a-6641-4a16-990c-761c5e880ad1 v1) with a [2021-11-19T14:08:01+0000] [Thread-7 ] [D] [toil.jobStores.aws.jobStore] Inlining content of 57 bytes [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Wrote FileInfo(fileID='85c4ac5e-051c-40ee-8101-582b088f5c1f', ownerID='None', encrypted=False, version='', previousVersion='', content=b'\x80\x05\x9...94)\x81\x94s.', checksum='', _numContentChunks=1) bound to from stream. [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.job] Processing job 'CWLJob' echo 9eb39b4a-6641-4a16-990c-761c5e880ad1 v1 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.abstractFileStore] LOG-TO-MASTER: Job 'CWLJob' echo 9eb39b4a-6641-4a16-990c-761c5e880ad1 v1 used 0.00% disk (0 bB [0B] used, 3.0 GiB [3221225472B] requested). [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.deferred] Running own deferred functions [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.deferred] Out of deferred functions! [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.deferred] Running orphaned deferred functions [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] Completed body for 'CWLJob' echo 9eb39b4a-6641-4a16-990c-761c5e880ad1 v1 [2021-11-19T14:08:01+0000] [Thread-8 ] [D] [toil.fileStores.cachingFileStore] Committing file uploads asynchronously [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.worker] Stopping running chain of jobs: length of stack: 0, services: 0, checkpoint: False [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] Not chaining from job 'CWLJob' echo 9eb39b4a-6641-4a16-990c-761c5e880ad1 v1 [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] Worker log can be found at /var/lib/toil/8c043326cea05f40bb60b580ef09859a/d408. Set --cleanWorkDir to retain this log [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] Finished running the chain of jobs on this node, we ran for a total of 0.213401 seconds [2021-11-19T14:08:01+0000] [Thread-8 ] [D] [toil.fileStores.cachingFileStore] Committing file deletes and job state changes asynchronously [2021-11-19T14:08:01+0000] [Thread-8 ] [D] [toil.jobStores.aws.jobStore] Updating job 9eb39b4a-6641-4a16-990c-761c5e880ad1 [2021-11-19T14:08:01+0000] [Thread-8 ] [D] [toil.job] New job version: 'CWLJob' echo 9eb39b4a-6641-4a16-990c-761c5e880ad1 v2 <========= [2021-11-19T14:08:02+0000] [Thread-28 ] [D] [toil.jobStores.aws.jobStore] Starting sha1 checksum to match a2186b2bbd53aaef61812be032cbcacc9c2a462c [2021-11-19T14:08:02+0000] [Thread-28 ] [D] [toil.jobStores.aws.jobStore] Completed checksum with hash a2186b2bbd53aaef61812be032cbcacc9c2a462c vs. expected a2186b2bbd53aaef61812be032cbcacc9c2a462c [2021-11-19T14:08:02+0000] [Thread-12 ] [D] [toil.statsAndLogging] Got message from job at time 11-19-2021 14:08:02: Job 'CWLJob' echo ec12b4e1-6da8-42aa-8e7f-18d43b243743 v1 used 0.00% disk (0 bB [0B] used, 3.0 GiB [3221225472B] requested). [2021-11-19T14:08:02+0000] [Thread-12 ] [D] [toil.statsAndLogging] Received Toil worker log. Disable debug level logging to hide this output [2021-11-19T14:08:02+0000] [Thread-12 ] [D] [toil.statsAndLogging] Log from job "'CWLJob' echo ec12b4e1-6da8-42aa-8e7f-18d43b243743 v1" follows: =========> [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] ---TOIL WORKER OUTPUT LOG--- [2021-11-19T14:08:01+0000] [MainThread] [I] [toil] Running Toil version 5.6.0a1-604176544d7178bb415a1dd98f0084d1a1b7f65b on host toiltest-toil-1065dcea-65fd-4642-9515-d3d93cdb6134-7-mtncb. [2021-11-19T14:08:01+0000] [MainThread] [D] [toil] Configuration: {'workflowID': '746138fc-5905-467c-9004-51d26fe56f42', 'workflowAttemptNumber': 0, 'jobStore': 'aws:us-west-2:toil-cwl-19398c8c-4067-4302-964d-e727a203e592', 'logLevel': 'DEBUG', 'workDir': None, 'noStdOutErr': False, 'stats': False, 'clean': 'always', 'cleanWorkDir': 'always', 'clusterStats': None, 'restart': False, 'batchSystem': 'kubernetes', 'disableAutoDeployment': False, 'maxLocalJobs': 4, 'manualMemArgs': False, 'coalesceStatusCalls': False, 'statePollingWait': None, 'parasolCommand': 'parasol', 'parasolMaxBatches': 10000, 'scale': 1.0, 'allocate_mem': False, 'tes_endpoint': 'http://10.244.1.58:8000', 'tes_user': None, 'tes_password': None, 'tes_bearer_token': None, 'kubernetes_host_path': '/data/scratch', 'kubernetes_owner': 'toiltest', 'runCwlInternalJobsOnWorkers': False, 'disableCaching': False, 'linkImports': True, 'moveExports': False, 'provisioner': None, 'nodeTypes': [], 'minNodes': None, 'maxNodes': [10], 'targetTime': 1800, 'betaInertia': 0.1, 'scaleInterval': 60, 'preemptableCompensation': 0.0, 'nodeStorage': 50, 'nodeStorageOverrides': [], 'metrics': False, 'maxPreemptableServiceJobs': 9223372036854775807, 'maxServiceJobs': 9223372036854775807, 'deadlockWait': 60, 'deadlockCheckInterval': 30, 'defaultMemory': 2147483648, 'defaultCores': 1, 'defaultDisk': 2147483648, 'readGlobalFileMutableByDefault': False, 'defaultPreemptable': False, 'maxCores': 9223372036854775807, 'maxMemory': 9223372036854775807, 'maxDisk': 9223372036854775807, 'retryCount': 1, 'enableUnlimitedPreemptableRetries': False, 'doubleMem': False, 'maxJobDuration': 9223372036854775807, 'rescueJobsFrequency': 3600, 'environment': {'SINGULARITY_DOCKER_HUB_MIRROR': None}, 'disableChaining': False, 'disableJobStoreChecksumVerification': False, 'maxLogFileSize': 64000, 'writeLogs': None, 'writeLogsGzip': None, 'writeLogsFromAllJobs': False, 'sseKey': None, 'servicePollingInterval': 60, 'useAsync': True, 'forceDockerAppliance': False, 'statusWait': 3600, 'disableProgress': False, 'debugWorker': False, 'disableWorkerOutputCapture': False, 'badWorker': 0.0, 'badWorkerFailInterval': 0.01, 'cwl': False} [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.deferred] Running for file /var/lib/toil/8c043326cea05f40bb60b580ef09859a/deferred/funcidhbv87g [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Loaded job ec12b4e1-6da8-42aa-8e7f-18d43b243743 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.worker] Parsed job description [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] Working on job 'CWLJob' echo ec12b4e1-6da8-42aa-8e7f-18d43b243743 v1 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.worker] Got a command to run: _toil 45a91c47-52cb-46e7-b231-49eaa6ca72d9 /builds/TnycNQM8/7/databiosphere/toil/src toil.cwl.cwltoil False [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.job] Loading user module ModuleDescriptor(dirPath='/builds/TnycNQM8/7/databiosphere/toil/src', name='toil.cwl.cwltoil', fromVirtualEnv=False). [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Reading FileInfo(fileID='45a91c47-52cb-46e7-b231-49eaa6ca72d9', ownerID='ec12b4e1-6da8-42aa-8e7f-18d43b243743', encrypted=False, version='rQX9_kmCgq2X3DOoPMIJGLcg3.uy23Mv', previousVersion='rQX9_kmCgq2X3DOoPMIJGLcg3.uy23Mv', content=None, checksum='sha1$9fd9514ef88...f1e61201e0afb7775', _numContentChunks=0) bound to into stream. [2021-11-19T14:08:01+0000] [Thread-6 ] [D] [toil.jobStores.aws.jobStore] Starting sha1 checksum to match 9fd9514ef889f172c007144f1e61201e0afb7775 [2021-11-19T14:08:01+0000] [Thread-6 ] [D] [toil.jobStores.aws.jobStore] Completed checksum with hash 9fd9514ef889f172c007144f1e61201e0afb7775 vs. expected 9fd9514ef889f172c007144f1e61201e0afb7775 [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] Loaded body Job('CWLJob' echo ec12b4e1-6da8-42aa-8e7f-18d43b243743 v1) from description 'CWLJob' echo ec12b4e1-6da8-42aa-8e7f-18d43b243743 v1 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Starting job ('CWLJob' echo ec12b4e1-6da8-42aa-8e7f-18d43b243743 v1) with ID (ec12b4e1-6da8-42aa-8e7f-18d43b243743). [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.deferred] Running orphaned deferred functions [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.deferred] Running job [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Actually running job ('CWLJob' echo ec12b4e1-6da8-42aa-8e7f-18d43b243743 v1) with ID (ec12b4e1-6da8-42aa-8e7f-18d43b243743) which wants 3221225472 of our 2671373074432 bytes. [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Max space: 2671373074432 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Total file size: 0 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Total job disk requirement size: 19327352832 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Total immutable reference size: 0 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.cachingFileStore] Available space with job: 2652045721600 bytes [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.cwl.cwltoil] Loaded order: {'a_new_var': True, 'in1': 4} [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.cwl.cwltoil] Output disposition: move [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.cwl.cwltoil] Running tool ToilCommandLineTool('file:///builds/TnycNQM8/7/databiosphere/toil/src/toil/test/cwl/spec_v12/tests/conditionals/foo.cwl') with order: {'a_new_var': True, 'in1': 4} [2021-11-19T14:08:01+0000] [MainThread] [D] [cwltool] [job foo.cwl] initializing from file:///builds/TnycNQM8/7/databiosphere/toil/src/toil/test/cwl/spec_v12/tests/conditionals/foo.cwl [2021-11-19T14:08:01+0000] [MainThread] [D] [cwltool] [job foo.cwl] { "in1": 4 } [2021-11-19T14:08:01+0000] [MainThread] [D] [cwltool] [job foo.cwl] path mappings is {} [2021-11-19T14:08:01+0000] [MainThread] [D] [cwltool] [job foo.cwl] command line bindings is [ { "position": [ -1000000, 0 ], "datum": "echo" } ] [2021-11-19T14:08:01+0000] [MainThread] [D] [cwltool] [job foo.cwl] initial work dir {} [2021-11-19T14:08:01+0000] [MainThread] [I] [cwltool] [job foo.cwl] /var/lib/toil/8c043326cea05f40bb60b580ef09859a/d8aa/4501/tmpz_zf05ab/tmp-out3a6zvd2p$ echo [2021-11-19T14:08:01+0000] [MainThread] [D] [cwltool] Could not collect memory usage, job ended before monitoring began. [2021-11-19T14:08:01+0000] [MainThread] [I] [cwltool] [job foo.cwl] completed success [2021-11-19T14:08:01+0000] [MainThread] [D] [cwltool] [job foo.cwl] outputs { "out1": "foo 4" } [2021-11-19T14:08:01+0000] [MainThread] [D] [cwltool] [job foo.cwl] Removing input staging directory /var/lib/toil/8c043326cea05f40bb60b580ef09859a/d8aa/4501/tmpyu8cueljyhcrzyw6 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.cwl.cwltoil] Importing files for {'out1': 'foo 4'} [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.cwl.cwltoil] Emitting output: {'out1': 'foo 4'} [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.job] Saving graph of 1 jobs, 0 new [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.job] Resolve promise 334da90e-9222-4921-937c-256038c38164 from Job('CWLJob' echo ec12b4e1-6da8-42aa-8e7f-18d43b243743 v1) with a [2021-11-19T14:08:01+0000] [Thread-8 ] [D] [toil.jobStores.aws.jobStore] Inlining content of 30 bytes [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.jobStores.aws.jobStore] Wrote FileInfo(fileID='334da90e-9222-4921-937c-256038c38164', ownerID='None', encrypted=False, version='', previousVersion='', content=b'\x80\x05\x9...05foo 4\x94s.', checksum='', _numContentChunks=1) bound to from stream. [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.job] Processing job 'CWLJob' echo ec12b4e1-6da8-42aa-8e7f-18d43b243743 v1 [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.fileStores.abstractFileStore] LOG-TO-MASTER: Job 'CWLJob' echo ec12b4e1-6da8-42aa-8e7f-18d43b243743 v1 used 0.00% disk (0 bB [0B] used, 3.0 GiB [3221225472B] requested). [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.deferred] Running own deferred functions [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.deferred] Out of deferred functions! [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.deferred] Running orphaned deferred functions [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] Completed body for 'CWLJob' echo ec12b4e1-6da8-42aa-8e7f-18d43b243743 v1 [2021-11-19T14:08:01+0000] [Thread-9 ] [D] [toil.fileStores.cachingFileStore] Committing file uploads asynchronously [2021-11-19T14:08:01+0000] [MainThread] [D] [toil.worker] Stopping running chain of jobs: length of stack: 0, services: 0, checkpoint: False [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] Not chaining from job 'CWLJob' echo ec12b4e1-6da8-42aa-8e7f-18d43b243743 v1 [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] Worker log can be found at /var/lib/toil/8c043326cea05f40bb60b580ef09859a/d8aa. Set --cleanWorkDir to retain this log [2021-11-19T14:08:01+0000] [MainThread] [I] [toil.worker] Finished running the chain of jobs on this node, we ran for a total of 0.208929 seconds [2021-11-19T14:08:01+0000] [Thread-9 ] [D] [toil.fileStores.cachingFileStore] Committing file deletes and job state changes asynchronously [2021-11-19T14:08:01+0000] [Thread-9 ] [D] [toil.jobStores.aws.jobStore] Updating job ec12b4e1-6da8-42aa-8e7f-18d43b243743 [2021-11-19T14:08:01+0000] [Thread-9 ] [D] [toil.job] New job version: 'CWLJob' echo ec12b4e1-6da8-42aa-8e7f-18d43b243743 v2 <========= [2021-11-19T14:08:04+0000] [MainThread] [D] [toil.leader] Job ended: 'CWLJob' echo ec12b4e1-6da8-42aa-8e7f-18d43b243743 v1 [2021-11-19T14:08:04+0000] [MainThread] [D] [toil.leader] Cleaning the predecessors of ec12b4e1-6da8-42aa-8e7f-18d43b243743 [2021-11-19T14:08:04+0000] [MainThread] [D] [toil.toilState] Successors: one fewer for 95cfa3be-cbb1-4ce0-a750-9a66ddff6118, now have 5 [2021-11-19T14:08:04+0000] [MainThread] [D] [toil.leader] Job ended: 'CWLJob' echo 9eb39b4a-6641-4a16-990c-761c5e880ad1 v1 [2021-11-19T14:08:04+0000] [MainThread] [D] [toil.leader] Cleaning the predecessors of 9eb39b4a-6641-4a16-990c-761c5e880ad1 [2021-11-19T14:08:04+0000] [MainThread] [D] [toil.toilState] Successors: one fewer for 95cfa3be-cbb1-4ce0-a750-9a66ddff6118, now have 4 [2021-11-19T14:08:05+0000] [MainThread] [D] [toil.leader] Job ended: 'CWLJob' echo a9f944fe-525a-4718-b868-05ef26e0411c v1 [2021-11-19T14:08:05+0000] [MainThread] [D] [toil.leader] Cleaning the predecessors of a9f944fe-525a-4718-b868-05ef26e0411c [2021-11-19T14:08:05+0000] [MainThread] [D] [toil.toilState] Successors: one fewer for 95cfa3be-cbb1-4ce0-a750-9a66ddff6118, now have 3 [2021-11-19T14:08:06+0000] [MainThread] [D] [toil.leader] Job ended: 'CWLJob' echo 692c58c7-3a47-4eb7-85c8-e0985f57f305 v1 [2021-11-19T14:08:06+0000] [MainThread] [D] [toil.leader] Cleaning the predecessors of 692c58c7-3a47-4eb7-85c8-e0985f57f305 [2021-11-19T14:08:06+0000] [MainThread] [D] [toil.toilState] Successors: one fewer for 95cfa3be-cbb1-4ce0-a750-9a66ddff6118, now have 2 [2021-11-19T14:08:06+0000] [MainThread] [D] [toil.leader] Job ended: 'CWLJob' echo 6ca66447-352c-4e3a-970d-6b483ec82646 v1 [2021-11-19T14:08:06+0000] [MainThread] [D] [toil.leader] Cleaning the predecessors of 6ca66447-352c-4e3a-970d-6b483ec82646 [2021-11-19T14:08:06+0000] [MainThread] [D] [toil.toilState] Successors: one fewer for 95cfa3be-cbb1-4ce0-a750-9a66ddff6118, now have 1 ```
adamnovak commented 2 years ago

I have some evidence from #3936 that this might be caused by jobs getting lost. I got a log that looks like this:

[2021-11-19T20:58:03+0000] [MainThread] [I] [toil.leader] 1 jobs are running, 0 jobs are issued and waiting to run
[2021-11-19T20:58:04+0000] [Thread-12 ] [D] [toil.jobStores.aws.jobStore] Starting sha1 checksum to match 9bf88d90e19feff90e116296b35668040cabac00
[2021-11-19T20:58:04+0000] [Thread-12 ] [D] [toil.jobStores.aws.jobStore] Completed checksum with hash 9bf88d90e19feff90e116296b35668040cabac00 vs. expected 9bf88d90e19feff90e116296b35668040cabac00
[2021-11-19T20:58:04+0000] [Thread-10 ] [D] [toil.statsAndLogging] Got message from job at time 11-19-2021 20:58:04: Job 'CWLJob' echo c9609463-4cf4-4433-aaeb-9537648405e3 v1 used 0.00% disk (4.0 KiB [4096B] used, 3.0 GiB [3221225472B] requested).
[2021-11-19T20:58:04+0000] [Thread-10 ] [D] [toil.statsAndLogging] Received Toil worker log. Disable debug level logging to hide this output
[2021-11-19T20:58:04+0000] [Thread-10 ] [D] [toil.statsAndLogging] Log from job "'CWLJob' echo c9609463-4cf4-4433-aaeb-9537648405e3 v1" follows:
=========>
...
<=========
[2021-11-19T20:58:13+0000] [MainThread] [I] [toil.leader] 0 jobs are running, 1 jobs are issued and waiting to run
[2021-11-19T20:58:23+0000] [MainThread] [I] [toil.leader] 0 jobs are running, 1 jobs are issued and waiting to run
[2021-11-19T20:58:34+0000] [MainThread] [I] [toil.leader] 0 jobs are running, 1 jobs are issued and waiting to run

We have a job sent to run on Kubernetes, and it returns an (apparently successful) log, and stops showing up in the list of running jobs, but the Kubernetes batch system never spits it out as an "updated" job when it finishes. I think something happens to the job on the Kubernetes side, and it gets dropped from Kubernetes after it finishes despite not having a TTL set on it, because it's not showing up in my code that's supposed to show me a job that exists.

I'm now trying setting the missing job rescuer to run frequently enough that the CWL tests will actually have it operate on them, and I've expanded logging a bit more. Perhaps this will produce some new insights.

adamnovak commented 2 years ago

I did some experiments with manually created jobs, and they are definitely getting cleaned up after a few minutes on our cluster, with no TTL. Our admin Erich Weiler says we do have a job cleanup bot, but it is supposed to strike when the job has been sitting around completed for days.

rm -f jobs.yaml
for ITER in {1..1} ; do
echo "Add ${ITER}"
cat >>jobs.yaml <<EOF
apiVersion: batch/v1
kind: Job
metadata:
  generateName: adamnovak-floodtest-
  labels:
    app: adamnovak-test
spec:
  template:
    spec:
      containers:
      - name: main
        image: mirror.gcr.io/library/ubuntu:20.04
        command: ["echo",  "test"]
        resources:
          limits:
            memory: 100M
            cpu: 100m
            ephemeral-storage: 1G
          requests:
            memory: 100M
            cpu: 100m
            ephemeral-storage: 1G
      restartPolicy: Never
  backoffLimit: 0
---
EOF
done
kubectl create -n toil -f jobs.yaml >create-log.txt 2>&1

cat create-log.txt | while read LINE ; do
    JOB_NAME=$(echo ${LINE} | grep -o "adamnovak-floodtest-[0-9a-zA-Z]*")
    TIMES_SEEN=1
    while true ; do
        kubectl -n toil get job "${JOB_NAME}" -o yaml >job-seen.tmp
        if [[ "${?}" != "0" ]] ; then
            echo "Job ${JOB_NAME} reported as created but is missing"
            rm job-seen.tmp
            break
        else
            echo "Job ${JOB_NAME} still exists; seen ${TIMES_SEEN} times"
            mv job-seen.tmp job-seen.yaml
            sleep 1
            TIMES_SEEN=$((TIMES_SEEN+1))
        fi
    done
done

Actually adding a ttlSecondsAfterFinished to the job spec seems to protect them from being cleaned up before then, so I'm trying teaching Toil to set a long enough TTL that it has time to get back to the finished jobs before they are cleaned up.

adamnovak commented 2 years ago

This is back again in https://ucsc-ci.com/databiosphere/toil/-/jobs/3545

I think adding the TTL helped, and our cluster just has a chaos gremlin that deletes some finished jobs no matter what we do. We could switch the whole Kubernetes batch system over to using a watcher thread and subscribing to updates, or we can just make the lost job rescue code run often enough that it can kick in in the CWL conformance tests.