|
1
|
$ arvados-cwl-runner --debug msa.cwl msa_arv.yaml
|
|
2
|
INFO /home/michael/src/2020-covid-19-bh/env3.7/bin/arvados-cwl-runner 2.1.0.dev20200407192516, arvados-python-client 2.0.1, cwltool 3.0.20200324120055
|
|
3
|
INFO Resolved 'msa.cwl' to 'file:///home/michael/src/2020-covid-19-bh/msa/msa.cwl'
|
|
4
|
DEBUG Creating collection reader for 2a91d4d78e99ce298b380799f5aeae87+579
|
|
5
|
INFO Using empty collection d41d8cd98f00b204e9800998ecf8427e+0
|
|
6
|
INFO Using empty collection d41d8cd98f00b204e9800998ecf8427e+0
|
|
7
|
INFO Using empty collection d41d8cd98f00b204e9800998ecf8427e+0
|
|
8
|
INFO Using empty collection d41d8cd98f00b204e9800998ecf8427e+0
|
|
9
|
INFO Using collection cache size 256 MiB
|
|
10
|
DEBUG ENTER jobiter 1587747830.3973134
|
|
11
|
DEBUG EXIT jobiter 1587747830.398803 0.0014896392822265625
|
|
12
|
DEBUG ENTER run 1587747830.3988857
|
|
13
|
INFO Uploading Docker image arvados/jobs:2.1.0.dev20200407192516
|
|
14
|
2020-04-24 19:03:54 arvados.arv_put[223608] INFO: Creating new cache file at /home/michael/.cache/arvados/arv-put/bd0e10119db97007dbc105c8dcc5aeea
|
|
15
|
0M / 261M 0.0% 2020-04-24 19:03:55 arvados.keep[223608] DEBUG: {'lugli-bi6l4-76544aa6dc97b808': OrderedDict([('href', '/keep_services/lugli-bi6l4-76544aa6dc97b808'), ('kind', 'arvados#keepService'), ('etag', '44f8ew7lqh8lexeyflhpsytlc'), ('uuid', 'lugli-bi6l4-76544aa6dc97b808'), ('owner_uuid', 'lugli-tpzed-000000000000000'), ('created_at', '2020-04-14T19:53:21.720990000Z'), ('modified_by_client_uuid', None), ('modified_by_user_uuid', 'lugli-tpzed-000000000000000'), ('modified_at', '2020-04-14T19:53:21.720990000Z'), ('service_host', 'keep.lugli.arvadosapi.com'), ('service_port', 443), ('service_ssl_flag', True), ('service_type', 'proxy'), ('read_only', False), ('_service_root', 'https://keep.lugli.arvadosapi.com:443/')])} (X-Request-Id: req-knwmai3k8jkwzya8p0mc)
|
|
16
|
2020-04-24 19:03:55 arvados.keep[223608] DEBUG: 42ccf9c5663306c85f9bf29c879a35d9+67108864: ['https://keep.lugli.arvadosapi.com:443/']
|
|
17
|
2020-04-24 19:03:55 arvados.keep[223608] DEBUG: Pool max threads is 1
|
|
18
|
2020-04-24 19:03:55 arvados.keep[223608] DEBUG: Request: PUT https://keep.lugli.arvadosapi.com:443/42ccf9c5663306c85f9bf29c879a35d9
|
|
19
|
2020-04-24 19:03:55 arvados.keep[223608] DEBUG: {'lugli-bi6l4-76544aa6dc97b808': OrderedDict([('href', '/keep_services/lugli-bi6l4-76544aa6dc97b808'), ('kind', 'arvados#keepService'), ('etag', '44f8ew7lqh8lexeyflhpsytlc'), ('uuid', 'lugli-bi6l4-76544aa6dc97b808'), ('owner_uuid', 'lugli-tpzed-000000000000000'), ('created_at', '2020-04-14T19:53:21.720990000Z'), ('modified_by_client_uuid', None), ('modified_by_user_uuid', 'lugli-tpzed-000000000000000'), ('modified_at', '2020-04-14T19:53:21.720990000Z'), ('service_host', 'keep.lugli.arvadosapi.com'), ('service_port', 443), ('service_ssl_flag', True), ('service_type', 'proxy'), ('read_only', False), ('_service_root', 'https://keep.lugli.arvadosapi.com:443/')])}
|
|
20
|
2020-04-24 19:03:55 arvados.keep[223608] DEBUG: 956670374e4ac80b022a71ea124ae60a+5466624: ['https://keep.lugli.arvadosapi.com:443/']
|
|
21
|
2020-04-24 19:03:55 arvados.keep[223608] DEBUG: Pool max threads is 1
|
|
22
|
2020-04-24 19:03:55 arvados.keep[223608] DEBUG: Request: PUT https://keep.lugli.arvadosapi.com:443/956670374e4ac80b022a71ea124ae60a
|
|
23
|
2020-04-24 19:03:56 arvados.keep[223608] DEBUG: {'lugli-bi6l4-76544aa6dc97b808': OrderedDict([('href', '/keep_services/lugli-bi6l4-76544aa6dc97b808'), ('kind', 'arvados#keepService'), ('etag', '44f8ew7lqh8lexeyflhpsytlc'), ('uuid', 'lugli-bi6l4-76544aa6dc97b808'), ('owner_uuid', 'lugli-tpzed-000000000000000'), ('created_at', '2020-04-14T19:53:21.720990000Z'), ('modified_by_client_uuid', None), ('modified_by_user_uuid', 'lugli-tpzed-000000000000000'), ('modified_at', '2020-04-14T19:53:21.720990000Z'), ('service_host', 'keep.lugli.arvadosapi.com'), ('service_port', 443), ('service_ssl_flag', True), ('service_type', 'proxy'), ('read_only', False), ('_service_root', 'https://keep.lugli.arvadosapi.com:443/')])}
|
|
24
|
2020-04-24 19:03:56 arvados.keep[223608] DEBUG: 1205e70178f09a5b4bd0a88b327ff3bf+67108864: ['https://keep.lugli.arvadosapi.com:443/']
|
|
25
|
2020-04-24 19:03:56 arvados.keep[223608] DEBUG: Pool max threads is 1
|
|
26
|
2020-04-24 19:03:56 arvados.keep[223608] DEBUG: Request: PUT https://keep.lugli.arvadosapi.com:443/1205e70178f09a5b4bd0a88b327ff3bf
|
|
27
|
2020-04-24 19:04:13 arvados.keep[223608] INFO: PUT 200: 5466624 bytes in 17895.527839660645 msec (0.291 MiB/sec)
|
|
28
|
2020-04-24 19:04:13 arvados.keep[223608] DEBUG: KeepWriterThread <KeepWriterThread(Thread-7, started daemon 23025616185088)> succeeded 956670374e4ac80b022a71ea124ae60a+5466624 https://keep.lugli.arvadosapi.com:443/
|
|
29
|
2020-04-24 19:04:40 arvados.keep[223608] DEBUG: Request fail: PUT https://keep.lugli.arvadosapi.com:443/42ccf9c5663306c85f9bf29c879a35d9 => <class 'arvados.errors.HttpError'>: (413, 'HTTP/2 413 \r\n')
|
|
30
|
2020-04-24 19:04:40 arvados.keep[223608] DEBUG: Request fail: PUT 42ccf9c5663306c85f9bf29c879a35d9 => 413 Could not write sufficient replicas: [0] Put http://keep0.lugli.arvadosapi.com:25107/42ccf9c5663306c85f9bf29c879a35d9: net/http: request
|
|
31
|
|
|
32
|
2020-04-24 19:04:41 arvados.keep[223608] DEBUG: {'lugli-bi6l4-76544aa6dc97b808': OrderedDict([('href', '/keep_services/lugli-bi6l4-76544aa6dc97b808'), ('kind', 'arvados#keepService'), ('etag', '44f8ew7lqh8lexeyflhpsytlc'), ('uuid', 'lugli-bi6l4-76544aa6dc97b808'), ('owner_uuid', 'lugli-tpzed-000000000000000'), ('created_at', '2020-04-14T19:53:21.720990000Z'), ('modified_by_client_uuid', None), ('modified_by_user_uuid', 'lugli-tpzed-000000000000000'), ('modified_at', '2020-04-14T19:53:21.720990000Z'), ('service_host', 'keep.lugli.arvadosapi.com'), ('service_port', 443), ('service_ssl_flag', True), ('service_type', 'proxy'), ('read_only', False), ('_service_root', 'https://keep.lugli.arvadosapi.com:443/')])}
|
|
33
|
2020-04-24 19:04:41 arvados.keep[223608] DEBUG: 42ccf9c5663306c85f9bf29c879a35d9+67108864: ['https://keep.lugli.arvadosapi.com:443/']
|
|
34
|
2020-04-24 19:04:41 arvados.keep[223608] DEBUG: Pool max threads is 1
|
|
35
|
2020-04-24 19:04:41 arvados.keep[223608] INFO: No more Keep services to try; giving up
|
|
36
|
2020-04-24 19:04:41 arvados.arv_put[223608] WARNING: Abnormal termination:
|
|
37
|
Traceback (most recent call last):
|
|
38
|
File "/home/michael/src/2020-covid-19-bh/env3.7/lib/python3.7/site-packages/arvados/arvfile.py", line 712, in commit_bufferblock
|
|
39
|
block.set_state(_BufferBlock.PENDING)
|
|
40
|
File "/home/michael/src/2020-covid-19-bh/env3.7/lib/python3.7/site-packages/arvados/arvfile.py", line 270, in synchronized_wrapper
|
|
41
|
return orig_func(self, *args, **kwargs)
|
|
42
|
File "/home/michael/src/2020-covid-19-bh/env3.7/lib/python3.7/site-packages/arvados/arvfile.py", line 360, in set_state
|
|
43
|
raise StateChangeError("Invalid state change from %s to %s" % (self._state, nextstate), self._state, nextstate)
|
|
44
|
arvados.arvfile.StateChangeError: Invalid state change from 1 to 1
|
|
45
|
|
|
46
|
During handling of the above exception, another exception occurred:
|
|
47
|
|
|
48
|
Traceback (most recent call last):
|
|
49
|
File "/home/michael/src/2020-covid-19-bh/env3.7/lib/python3.7/site-packages/arvados/commands/put.py", line 606, in start
|
|
50
|
self._upload_files()
|
|
51
|
File "/home/michael/src/2020-covid-19-bh/env3.7/lib/python3.7/site-packages/arvados/commands/put.py", line 835, in _upload_files
|
|
52
|
output.close(flush=False)
|
|
53
|
File "/home/michael/src/2020-covid-19-bh/env3.7/lib/python3.7/site-packages/arvados/arvfile.py", line 1360, in close
|
|
54
|
self.arvadosfile.remove_writer(self, flush)
|
|
55
|
File "/home/michael/src/2020-covid-19-bh/env3.7/lib/python3.7/site-packages/arvados/arvfile.py", line 270, in synchronized_wrapper
|
|
56
|
return orig_func(self, *args, **kwargs)
|
|
57
|
File "/home/michael/src/2020-covid-19-bh/env3.7/lib/python3.7/site-packages/arvados/arvfile.py", line 1038, in remove_writer
|
|
58
|
self.flush()
|
|
59
|
File "/home/michael/src/2020-covid-19-bh/env3.7/lib/python3.7/site-packages/arvados/arvfile.py", line 270, in synchronized_wrapper
|
|
60
|
return orig_func(self, *args, **kwargs)
|
|
61
|
File "/home/michael/src/2020-covid-19-bh/env3.7/lib/python3.7/site-packages/arvados/arvfile.py", line 1192, in flush
|
|
62
|
self.parent._my_block_manager().commit_bufferblock(bb, sync=True)
|
|
63
|
File "/home/michael/src/2020-covid-19-bh/env3.7/lib/python3.7/site-packages/arvados/arvfile.py", line 722, in commit_bufferblock
|
|
64
|
raise block.error
|
|
65
|
File "/home/michael/src/2020-covid-19-bh/env3.7/lib/python3.7/site-packages/arvados/arvfile.py", line 560, in _commit_bufferblock_worker
|
|
66
|
loc = self._keep.put(bufferblock.buffer_view[0:bufferblock.write_pointer].tobytes(), num_retries=self.num_retries, copies=self.copies)
|
|
67
|
File "/home/michael/src/2020-covid-19-bh/env3.7/lib/python3.7/site-packages/arvados/retry.py", line 177, in num_retries_setter
|
|
68
|
return orig_func(self, *args, **kwargs)
|
|
69
|
File "/home/michael/src/2020-covid-19-bh/env3.7/lib/python3.7/site-packages/arvados/keep.py", line 1200, in put
|
|
70
|
data_hash, loop.attempts_str(), copies, writer_pool.done()), service_errors, label="service")
|
|
71
|
arvados.errors.KeepWriteError: failed to write 42ccf9c5663306c85f9bf29c879a35d9 after 2 attempts (wanted 2 copies but wrote 0): service https://keep.lugli.arvadosapi.com:443/ responded with 413 HTTP/2 413
|
|
72
|
|
|
73
|
|
|
74
|
261M / 261M 100.0% 2020-04-24 19:04:41 arvados.cwl-runner.metrics[223608] DEBUG: EXIT run 1587747881.1374114 50.73852562904358
|
|
75
|
2020-04-24 19:04:41 cwltool[223608] ERROR: Workflow execution failed
|
|
76
|
Traceback (most recent call last):
|
|
77
|
File "/home/michael/src/2020-covid-19-bh/env3.7/lib/python3.7/site-packages/arvados/arvfile.py", line 712, in commit_bufferblock
|
|
78
|
block.set_state(_BufferBlock.PENDING)
|
|
79
|
File "/home/michael/src/2020-covid-19-bh/env3.7/lib/python3.7/site-packages/arvados/arvfile.py", line 270, in synchronized_wrapper
|
|
80
|
return orig_func(self, *args, **kwargs)
|
|
81
|
File "/home/michael/src/2020-covid-19-bh/env3.7/lib/python3.7/site-packages/arvados/arvfile.py", line 360, in set_state
|
|
82
|
raise StateChangeError("Invalid state change from %s to %s" % (self._state, nextstate), self._state, nextstate)
|
|
83
|
arvados.arvfile.StateChangeError: Invalid state change from 1 to 1
|
|
84
|
|
|
85
|
During handling of the above exception, another exception occurred:
|
|
86
|
|
|
87
|
Traceback (most recent call last):
|
|
88
|
File "/home/michael/src/arvados/sdk/cwl/arvados_cwl/arvdocker.py", line 64, in arv_docker_get_image
|
|
89
|
arvados.commands.keepdocker.main(args, stdout=sys.stderr, install_sig_handlers=False, api=api_client)
|
|
90
|
File "/home/michael/src/2020-covid-19-bh/env3.7/lib/python3.7/site-packages/arvados/commands/keepdocker.py", line 506, in main
|
|
91
|
install_sig_handlers=install_sig_handlers).strip()
|
|
92
|
File "/home/michael/src/2020-covid-19-bh/env3.7/lib/python3.7/site-packages/arvados/commands/put.py", line 1304, in main
|
|
93
|
writer.start(save_collection=not(args.stream or args.raw))
|
|
94
|
File "/home/michael/src/2020-covid-19-bh/env3.7/lib/python3.7/site-packages/arvados/commands/put.py", line 606, in start
|
|
95
|
self._upload_files()
|
|
96
|
File "/home/michael/src/2020-covid-19-bh/env3.7/lib/python3.7/site-packages/arvados/commands/put.py", line 835, in _upload_files
|
|
97
|
output.close(flush=False)
|
|
98
|
File "/home/michael/src/2020-covid-19-bh/env3.7/lib/python3.7/site-packages/arvados/arvfile.py", line 1360, in close
|
|
99
|
self.arvadosfile.remove_writer(self, flush)
|
|
100
|
File "/home/michael/src/2020-covid-19-bh/env3.7/lib/python3.7/site-packages/arvados/arvfile.py", line 270, in synchronized_wrapper
|
|
101
|
return orig_func(self, *args, **kwargs)
|
|
102
|
File "/home/michael/src/2020-covid-19-bh/env3.7/lib/python3.7/site-packages/arvados/arvfile.py", line 1038, in remove_writer
|
|
103
|
self.flush()
|
|
104
|
File "/home/michael/src/2020-covid-19-bh/env3.7/lib/python3.7/site-packages/arvados/arvfile.py", line 270, in synchronized_wrapper
|
|
105
|
return orig_func(self, *args, **kwargs)
|
|
106
|
File "/home/michael/src/2020-covid-19-bh/env3.7/lib/python3.7/site-packages/arvados/arvfile.py", line 1192, in flush
|
|
107
|
self.parent._my_block_manager().commit_bufferblock(bb, sync=True)
|
|
108
|
File "/home/michael/src/2020-covid-19-bh/env3.7/lib/python3.7/site-packages/arvados/arvfile.py", line 722, in commit_bufferblock
|
|
109
|
raise block.error
|
|
110
|
File "/home/michael/src/2020-covid-19-bh/env3.7/lib/python3.7/site-packages/arvados/arvfile.py", line 560, in _commit_bufferblock_worker
|
|
111
|
loc = self._keep.put(bufferblock.buffer_view[0:bufferblock.write_pointer].tobytes(), num_retries=self.num_retries, copies=self.copies)
|
|
112
|
File "/home/michael/src/2020-covid-19-bh/env3.7/lib/python3.7/site-packages/arvados/retry.py", line 177, in num_retries_setter
|
|
113
|
return orig_func(self, *args, **kwargs)
|
|
114
|
File "/home/michael/src/2020-covid-19-bh/env3.7/lib/python3.7/site-packages/arvados/keep.py", line 1200, in put
|
|
115
|
data_hash, loop.attempts_str(), copies, writer_pool.done()), service_errors, label="service")
|
|
116
|
arvados.errors.KeepWriteError: failed to write 42ccf9c5663306c85f9bf29c879a35d9 after 2 attempts (wanted 2 copies but wrote 0): service https://keep.lugli.arvadosapi.com:443/ responded with 413 HTTP/2 413
|
|
117
|
|
|
118
|
|
|
119
|
The above exception was the direct cause of the following exception:
|
|
120
|
|
|
121
|
Traceback (most recent call last):
|
|
122
|
File "/home/michael/src/arvados/sdk/cwl/arvados_cwl/runner.py", line 548, in arvados_jobs_image
|
|
123
|
return arvados_cwl.arvdocker.arv_docker_get_image(arvrunner.api, {"dockerPull": img}, True, arvrunner.project_uuid)
|
|
124
|
File "/home/michael/src/arvados/sdk/cwl/arvados_cwl/arvdocker.py", line 80, in arv_docker_get_image
|
|
125
|
cached_lookups[dockerRequirement["dockerImageId"]] = pdh
|
|
126
|
File "/home/michael/src/2020-covid-19-bh/env3.7/lib/python3.7/site-packages/schema_salad/sourceline.py", line 305, in __exit__
|
|
127
|
raise self.makeError(str(exc_value)) from exc_value
|
|
128
|
cwltool.errors.WorkflowException: failed to write 42ccf9c5663306c85f9bf29c879a35d9 after 2 attempts (wanted 2 copies but wrote 0): service https://keep.lugli.arvadosapi.com:443/ responded with 413 HTTP/2 413
|
|
129
|
|
|
130
|
|
|
131
|
During handling of the above exception, another exception occurred:
|
|
132
|
|
|
133
|
Traceback (most recent call last):
|
|
134
|
File "/home/michael/src/arvados/sdk/cwl/arvados_cwl/executor.py", line 703, in arv_executor
|
|
135
|
self.start_run(runnable, runtimeContext)
|
|
136
|
File "/home/michael/src/arvados/sdk/cwl/arvados_cwl/executor.py", line 232, in start_run
|
|
137
|
self.workflow_eval_lock, self.stop_polling)
|
|
138
|
File "/home/michael/src/arvados/sdk/cwl/arvados_cwl/task_queue.py", line 49, in add
|
|
139
|
task()
|
|
140
|
File "/home/michael/src/arvados/sdk/cwl/arvados_cwl/arvcontainer.py", line 508, in run
|
|
141
|
job_spec = self.arvados_job_spec(runtimeContext)
|
|
142
|
File "/home/michael/src/arvados/sdk/cwl/arvados_cwl/arvcontainer.py", line 408, in arvados_job_spec
|
|
143
|
"container_image": arvados_jobs_image(self.arvrunner, self.jobs_image),
|
|
144
|
File "/home/michael/src/arvados/sdk/cwl/arvados_cwl/runner.py", line 550, in arvados_jobs_image
|
|
145
|
raise Exception("Docker image %s is not available\n%s" % (img, e) )
|
|
146
|
Exception: Docker image arvados/jobs:2.1.0.dev20200407192516 is not available
|
|
147
|
failed to write 42ccf9c5663306c85f9bf29c879a35d9 after 2 attempts (wanted 2 copies but wrote 0): service https://keep.lugli.arvadosapi.com:443/ responded with 413 HTTP/2 413
|
|
148
|
|
|
149
|
2020-04-24 19:04:41 cwltool[223608] ERROR: Workflow error:
|
|
150
|
Workflow did not return a result.
|
|
151
|
Traceback (most recent call last):
|
|
152
|
File "/home/michael/src/2020-covid-19-bh/env3.7/lib/python3.7/site-packages/cwltool/main.py", line 1105, in main
|
|
153
|
tool, initialized_job_order_object, runtimeContext, logger=_logger
|
|
154
|
File "/home/michael/src/arvados/sdk/cwl/arvados_cwl/executor.py", line 756, in arv_executor
|
|
155
|
raise WorkflowException("Workflow did not return a result.")
|
|
156
|
cwltool.errors.WorkflowException: Workflow did not return a result.
|
|
157
|
|