search

rabix / bunny

[Legacy] Executor for CWL workflows. Executes sbg:draft-2 and CWL 1.0
http://rabix.io
Apache License 2.0
74 stars 28 forks source link

python basecommand fails to execute #204

Closed jeremiahsavage closed 7 years ago

jeremiahsavage commented 7 years ago

git clone https://github.com/jeremiahsavage/cwl_python_command.git

cwltool:

(cwl) [jeremiah@localhost ~]$ cwltool cwl_python_command/get_uuid.cwl cwl_python_command/get_uuid.json 
/home/jeremiah/.virtualenvs/cwl/bin/cwltool 1.0.20170309164828
Resolved 'cwl_python_command/get_uuid.cwl' to 'file:///home/jeremiah/cwl_python_command/get_uuid.cwl'
['docker', 'pull', 'python:3.6.0-slim']
Trying to pull repository docker.io/library/python ... 
sha256:ed16e4e6ee97ad893c5be1a22aae0de95b996b0a21e544d9b8a4625f66d1d49e: Pulling from docker.io/library/python

Digest: sha256:ed16e4e6ee97ad893c5be1a22aae0de95b996b0a21e544d9b8a4625f66d1d49e
Status: Image is up to date for docker.io/python:3.6.0-slim
[job get_uuid.cwl] /tmp/tmpYn7Zai$ docker \
    run \
    -i \
    --volume=/tmp/tmpYn7Zai:/var/spool/cwl:rw \
    --volume=/tmp/tmpWHD69s:/tmp:rw \
    --workdir=/var/spool/cwl \
    --read-only=true \
    --log-driver=none \
    --user=1000 \
    --rm \
    --env=TMPDIR=/tmp \
    --env=HOME=/var/spool/cwl \
    python:3.6.0-slim \
    /usr/local/bin/python3 \
    -c \
    'import uuid; import sys; sys.stdout.write(str(uuid.uuid4()));' > /tmp/tmpYn7Zai/output
[job get_uuid.cwl] completed success
{
    "output": {
        "checksum": "sha1$3690d3fef1beca035bd081d1c920bc19f0ff7c60", 
        "basename": "output", 
        "location": "file:///home/jeremiah/output", 
        "path": "/home/jeremiah/output", 
        "class": "File", 
        "size": 36
    }
}
Final process status is success

bunny:

(cwl) [jeremiah@localhost ~]$ java -jar ~/code/bunny/rabix-backend-local/target/rabix-backend-local-1.0.0-rc3.jar cwl_python_command/get_uuid.cwl cwl_python_command/get_uuid.json 
15:41:20.317 [main] DEBUG o.r.backend.local.BackendCommandLine - Config path: /home/jeremiah/code/bunny/rabix-backend-local/config
15:41:20.319 [main] DEBUG o.r.backend.local.BackendCommandLine - Configuration directory found localy.
15:41:21.180 [main] DEBUG org.rabix.engine.lru.dag.DAGCache - DAGCache initialized with size=16
15:41:21.181 [main] DEBUG org.rabix.engine.lru.app.AppCache - ApplicationCache initialized with size=16
15:41:21.209 [main] INFO  o.r.e.s.impl.BackendServiceImpl - Backend 64eb1477-4b89-499d-88e0-0cb6fca9e531 registered.
15:41:21.217 [pool-7-thread-1] DEBUG o.r.e.s.impl.StoreCleanupServiceImpl - Deleted 0 completed Jobs
15:41:21.216 [main] DEBUG o.r.e.service.impl.JobServiceImpl - Start Job Job [id=null, parentId=null, rootId=4a00d371-b42a-47f6-91cc-e78a57fb7b58, name=null, status=PENDING, message=null, config=null, inputs={}, outputs=null]
15:41:21.367 [main] DEBUG o.r.e.p.impl.MultiEventProcessorImpl - Root Job 4371b900-e8c7-48cb-ba5e-0ebf11e998aa goes to EventProcessor 2
15:41:21.368 [main] DEBUG o.r.e.p.impl.MultiEventProcessorImpl - Root Job 4371b900-e8c7-48cb-ba5e-0ebf11e998aa goes to EventProcessor 2
15:41:21.393 [pool-4-thread-1] DEBUG org.rabix.engine.lru.dag.DAGCache - DAGNode rootId=4371b900-e8c7-48cb-ba5e-0ebf11e998aa, id=root found in cache
15:41:21.393 [pool-4-thread-1] DEBUG org.rabix.engine.lru.dag.DAGCache - Cache size=1
15:41:21.396 [pool-4-thread-1] DEBUG o.r.e.p.impl.MultiEventProcessorImpl - Root Job 4371b900-e8c7-48cb-ba5e-0ebf11e998aa goes to EventProcessor 2
15:41:21.397 [pool-4-thread-1] DEBUG org.rabix.engine.lru.dag.DAGCache - DAGNode rootId=4371b900-e8c7-48cb-ba5e-0ebf11e998aa, id=root found in cache
15:41:21.397 [pool-4-thread-1] DEBUG org.rabix.engine.lru.dag.DAGCache - Cache size=1
15:41:21.397 [pool-4-thread-1] DEBUG o.r.e.p.h.impl.JobStatusEventHandler -  --- JobRecord root is ready. Job isBlocking=false
 --- All scatter ports []

15:41:21.398 [pool-4-thread-1] DEBUG org.rabix.engine.lru.dag.DAGCache - DAGNode rootId=4371b900-e8c7-48cb-ba5e-0ebf11e998aa, id=root found in cache
15:41:21.398 [pool-4-thread-1] DEBUG org.rabix.engine.lru.dag.DAGCache - Cache size=1
15:41:21.413 [pool-4-thread-1] DEBUG org.rabix.engine.JobHelper - 
 ---- JobRecord root

15:41:21.414 [pool-4-thread-1] DEBUG org.rabix.engine.cache.Cache - org.rabix.engine.memory.impl.InMemoryJobRecordRepository@38237341 flushed 1 item(s). Cache hits 1.
15:41:21.414 [pool-4-thread-1] DEBUG org.rabix.engine.cache.Cache - org.rabix.engine.memory.impl.InMemoryVariableRecordRepository@4a708159 flushed 1 item(s). Cache hits 0.
15:41:22.221 [pool-8-thread-1] INFO  o.r.e.s.impl.SchedulerServiceImpl - Message sent to 64eb1477-4b89-499d-88e0-0cb6fca9e531.
15:41:22.235 [pool-16-thread-1] DEBUG o.r.e.s.impl.ExecutorServiceImpl - start(id=4371b900-e8c7-48cb-ba5e-0ebf11e998aa, important={}, uploadOutputs={})
15:41:22.340 [pool-12-thread-1] DEBUG c.s.docker.client.DockerCertificates - /home/jeremiah/.docker/ca.pem, /home/jeremiah/.docker/key.pem or /home/jeremiah/.docker/cert.pem does not exist, not using SSL
15:41:22.526 [pool-12-thread-1] INFO  o.r.e.e.JobHandlerCommandDispatcher - JobHandlerRunnable created for 4371b900-e8c7-48cb-ba5e-0ebf11e998aa.
15:41:22.526 [JobHandler-Thread-0] INFO  o.r.e.execution.JobHandlerRunnable - JobHandlerRunnable JobHandler-Thread-0 started.
15:41:22.527 [JobHandler-Thread-0] DEBUG o.r.e.execution.JobHandlerRunnable - Command START found. Start execution.
15:41:22.527 [JobHandler-Thread-0] INFO  o.r.e.handler.impl.JobHandlerImpl - Start command line tool for id=4371b900-e8c7-48cb-ba5e-0ebf11e998aa
15:41:22.527 [JobHandler-Thread-0] DEBUG o.r.e.s.i.NoOpExecutorStatusCallback - onJobReady(jobId=4371b900-e8c7-48cb-ba5e-0ebf11e998aa)
15:41:22.535 [JobHandler-Thread-0] INFO  o.r.executor.service.CacheService - Trying to find cached results in the directory /Users/janko/Desktop/Archive/varscan/.root.meta
15:41:22.535 [JobHandler-Thread-0] INFO  o.r.executor.service.CacheService - Cache directory doesn't exist. Directory /Users/janko/Desktop/Archive/varscan/.root.meta
15:41:22.542 [JobHandler-Thread-0] DEBUG o.r.e.s.i.NoOpExecutorStatusCallback - onInputFilesDownloadStarted(jobId=4371b900-e8c7-48cb-ba5e-0ebf11e998aa)
15:41:22.545 [JobHandler-Thread-0] DEBUG o.r.e.s.i.NoOpExecutorStatusCallback - onInputFilesDownloadCompleted(jobId=4371b900-e8c7-48cb-ba5e-0ebf11e998aa)
15:41:22.554 [JobHandler-Thread-0] DEBUG o.r.e.c.impl.DockerContainerHandler - Pulling docker image
15:41:22.555 [JobHandler-Thread-0] INFO  verbose - Pulling docker image python:3.6.0-slim
15:41:22.555 [JobHandler-Thread-0] DEBUG o.r.e.s.i.NoOpExecutorStatusCallback - onContainerImagePullStarted(jobId=4371b900-e8c7-48cb-ba5e-0ebf11e998aa, image=python:3.6.0-slim)
15:41:22.555 [JobHandler-Thread-0] DEBUG c.s.d.client.messages.AuthConfig - Using configfile: /home/jeremiah/.docker/config.json
15:41:23.311 [pool-1-thread-1] INFO  c.s.docker.client.LoggingPullHandler - pull python:3.6.0-slim: ProgressMessage{id=null, status=Trying to pull repository docker.io/library/python ... , stream=null, error=null, progress=null, progressDetail=null}
15:41:24.126 [pool-1-thread-1] INFO  c.s.docker.client.LoggingPullHandler - pull python:3.6.0-slim: ProgressMessage{id=sha256:ed16e4e6ee97ad893c5be1a22aae0de95b996b0a21e544d9b8a4625f66d1d49e, status=Pulling from docker.io/library/python, stream=null, error=null, progress=null, progressDetail=null}
15:41:24.127 [pool-1-thread-1] INFO  c.s.docker.client.LoggingPullHandler - pull python:3.6.0-slim: ProgressMessage{id=null, status=Digest: sha256:ed16e4e6ee97ad893c5be1a22aae0de95b996b0a21e544d9b8a4625f66d1d49e, stream=null, error=null, progress=null, progressDetail=null}
15:41:24.130 [pool-1-thread-1] INFO  c.s.docker.client.LoggingPullHandler - pull python:3.6.0-slim: ProgressMessage{id=null, status=Status: Image is up to date for docker.io/python:3.6.0-slim, stream=null, error=null, progress=null, progressDetail=null}
15:41:24.133 [JobHandler-Thread-0] DEBUG o.r.e.s.i.NoOpExecutorStatusCallback - onContainerImagePullCompleted(jobId=4371b900-e8c7-48cb-ba5e-0ebf11e998aa, image=python:3.6.0-slim)
15:41:24.147 [JobHandler-Thread-0] INFO  o.r.b.cwl.CWLCommandLineBuilder - Building command line parts...
15:41:24.158 [JobHandler-Thread-0] INFO  o.r.b.cwl.CWLCommandLineBuilder - Command line built. CommandLine = CommandLine [parts=[/usr/local/bin/python3, -c, import uuid; import sys; sys.stdout.write(str(uuid.uuid4()));], standardIn=null, standardOut=/home/jeremiah/cwl_python_command/4371b900-e8c7-48cb-ba5e-0ebf11e998aa/root/output, standardError=null]
15:41:24.162 [JobHandler-Thread-0] INFO  verbose - Running command line: /usr/local/bin/python3 -c import uuid; import sys; sys.stdout.write(str(uuid.uuid4())); > /home/jeremiah/cwl_python_command/4371b900-e8c7-48cb-ba5e-0ebf11e998aa/root/output
15:41:24.162 [pool-1-thread-2] INFO  c.s.d.client.DefaultDockerClient - Creating container with ContainerConfig: ContainerConfig{hostname=null, domainname=null, username=null, attachStdin=null, attachStdout=null, attachStderr=null, portSpecs=null, exposedPorts=null, tty=null, openStdin=null, stdinOnce=null, env=[HOME=/home/jeremiah/cwl_python_command/4371b900-e8c7-48cb-ba5e-0ebf11e998aa/root, TMPDIR=/home/jeremiah/cwl_python_command/4371b900-e8c7-48cb-ba5e-0ebf11e998aa/root], cmd=[/bin/sh, -c, /usr/local/bin/python3 -c import uuid; import sys; sys.stdout.write(str(uuid.uuid4())); > /home/jeremiah/cwl_python_command/4371b900-e8c7-48cb-ba5e-0ebf11e998aa/root/output], image=python:3.6.0-slim, volumes=[/home/jeremiah/cwl_python_command], workingDir=/home/jeremiah/cwl_python_command/4371b900-e8c7-48cb-ba5e-0ebf11e998aa/root, entrypoint=null, networkDisabled=null, onBuild=null, labels=null, macAddress=null, hostConfig=HostConfig{binds=[/home/jeremiah/cwl_python_command:/home/jeremiah/cwl_python_command:rw], containerIDFile=null, lxcConf=null, privileged=null, portBindings=null, links=null, publishAllPorts=null, dns=null, dnsSearch=null, extraHosts=null, volumesFrom=null, networkMode=null, securityOpt=null, memory=null, memorySwap=null, cpuShares=null, cpusetCpus=null, cpuQuota=null, cgroupParent=null, restartPolicy=null, logConfig=null}, stopSignal=null}
15:41:24.504 [pool-1-thread-3] INFO  c.s.d.client.DefaultDockerClient - Starting container with Id: 815706614fd8ce6fdec332df2b79830d0052f1d38bdfed7f1165b3fb60ddcf1e
15:41:24.814 [JobHandler-Thread-0] INFO  o.r.e.c.impl.DockerContainerHandler - Docker container 815706614fd8ce6fdec332df2b79830d0052f1d38bdfed7f1165b3fb60ddcf1e has started.
15:41:24.814 [JobHandler-Thread-0] INFO  o.r.e.execution.command.StartCommand - Job 4371b900-e8c7-48cb-ba5e-0ebf11e998aa started successfully.
15:41:24.814 [JobHandler-Thread-0] DEBUG o.r.e.s.i.NoOpExecutorStatusCallback - onJobStarted(jobId=4371b900-e8c7-48cb-ba5e-0ebf11e998aa)
15:41:24.815 [JobHandler-Thread-0] INFO  verbose - Job root has started
15:41:24.816 [pool-14-thread-1] DEBUG o.r.e.service.impl.JobServiceImpl - Update Job 4371b900-e8c7-48cb-ba5e-0ebf11e998aa
15:41:24.816 [JobHandler-Thread-0] DEBUG o.r.e.execution.JobHandlerRunnable - Command STATUS found. Start execution.
15:41:24.816 [JobHandler-Thread-0] DEBUG o.r.e.execution.JobHandlerRunnable - Command STATUS is repeatable. Delay and put it back to queue.
15:41:24.817 [pool-14-thread-1] DEBUG o.r.e.p.impl.MultiEventProcessorImpl - Root Job 4371b900-e8c7-48cb-ba5e-0ebf11e998aa goes to EventProcessor 2
15:41:24.817 [pool-14-thread-1] DEBUG o.r.e.p.impl.MultiEventProcessorImpl - Root Job 4371b900-e8c7-48cb-ba5e-0ebf11e998aa goes to EventProcessor 2
15:41:24.818 [pool-4-thread-1] DEBUG org.rabix.engine.cache.Cache - org.rabix.engine.memory.impl.InMemoryJobRecordRepository@38237341 flushed 1 item(s). Cache hits 1.
15:41:25.217 [pool-7-thread-1] DEBUG o.r.e.s.impl.StoreCleanupServiceImpl - Deleted 0 completed Jobs
15:41:25.816 [JobHandler-Thread-0] DEBUG o.r.e.e.command.StatusCommand - Check status for 4371b900-e8c7-48cb-ba5e-0ebf11e998aa command line tool.
15:41:25.862 [JobHandler-Thread-0] DEBUG o.r.e.handler.impl.JobHandlerImpl - postprocess(id=4371b900-e8c7-48cb-ba5e-0ebf11e998aa)
15:41:25.866 [JobHandler-Thread-0] INFO  o.r.executor.service.CacheService - Trying to find cached results in the directory /Users/janko/Desktop/Archive/varscan/.root.meta
15:41:25.867 [JobHandler-Thread-0] INFO  o.r.executor.service.CacheService - Cache directory doesn't exist. Directory /Users/janko/Desktop/Archive/varscan/.root.meta
15:41:25.868 [JobHandler-Thread-0] DEBUG o.r.e.c.impl.DockerContainerHandler - Saving standard error files for id=4371b900-e8c7-48cb-ba5e-0ebf11e998aa
15:41:26.639 [JobHandler-Thread-0] DEBUG o.r.e.handler.impl.JobHandlerImpl - isSuccessful()
15:41:26.639 [JobHandler-Thread-0] DEBUG o.r.e.handler.impl.JobHandlerImpl - getExitStatus()
15:41:26.647 [JobHandler-Thread-0] DEBUG o.r.e.handler.impl.JobHandlerImpl - isSuccessful()
15:41:26.647 [JobHandler-Thread-0] DEBUG o.r.e.handler.impl.JobHandlerImpl - getExitStatus()
15:41:26.655 [JobHandler-Thread-0] DEBUG o.r.e.handler.impl.JobHandlerImpl - getExitStatus()
15:41:26.660 [JobHandler-Thread-0] ERROR o.r.e.e.command.StatusCommand - Job 4371b900-e8c7-48cb-ba5e-0ebf11e998aa failed with exit code 2.
15:41:26.660 [JobHandler-Thread-0] DEBUG o.r.e.s.i.NoOpExecutorStatusCallback - onJobFailed(jobId=4371b900-e8c7-48cb-ba5e-0ebf11e998aa)
15:41:26.661 [pool-18-thread-1] DEBUG o.r.e.service.impl.JobServiceImpl - Update Job 4371b900-e8c7-48cb-ba5e-0ebf11e998aa
15:41:26.662 [pool-18-thread-1] DEBUG o.r.e.p.impl.MultiEventProcessorImpl - Root Job 4371b900-e8c7-48cb-ba5e-0ebf11e998aa goes to EventProcessor 2
15:41:26.662 [pool-18-thread-1] DEBUG o.r.e.p.impl.MultiEventProcessorImpl - Root Job 4371b900-e8c7-48cb-ba5e-0ebf11e998aa goes to EventProcessor 2
15:41:26.662 [JobHandler-Thread-0] INFO  verbose - Job 4371b900-e8c7-48cb-ba5e-0ebf11e998aa failed with exit code 2.
15:41:26.662 [JobHandler-Thread-0] DEBUG o.r.e.c.impl.DockerContainerHandler - Removing container with id 815706614fd8ce6fdec332df2b79830d0052f1d38bdfed7f1165b3fb60ddcf1e
15:41:26.720 [pool-4-thread-1] DEBUG org.rabix.engine.lru.dag.DAGCache - DAGNode rootId=4371b900-e8c7-48cb-ba5e-0ebf11e998aa, id=root found in cache
15:41:26.720 [pool-4-thread-1] DEBUG org.rabix.engine.lru.dag.DAGCache - Cache size=1
15:41:26.721 [pool-4-thread-1] DEBUG o.r.e.s.i.DefaultEngineStatusCallback - onJobFailed(jobId=4371b900-e8c7-48cb-ba5e-0ebf11e998aa)
15:41:26.721 [pool-4-thread-1] DEBUG o.r.e.p.impl.MultiEventProcessorImpl - Root Job 4371b900-e8c7-48cb-ba5e-0ebf11e998aa goes to EventProcessor 2
15:41:26.899 [JobHandler-Thread-0] DEBUG o.r.e.execution.JobHandlerRunnable - Command STATUS is last command. Stop thread.
15:41:26.899 [JobHandler-Thread-0] INFO  o.r.e.execution.JobHandlerRunnable - JobHandlerRunnable JobHandler-Thread-0 stopped.
15:41:26.900 [JobHandler-Thread-0] INFO  o.r.e.execution.JobHandlerRunnable - JobHandlerRunnable JobHandler-Thread-0 finished.
15:41:27.369 [Thread-1] INFO  verbose - Failed to execute a Job
jeremiahsavage commented 7 years ago

Actually, this is probably a duplicate of https://github.com/rabix/bunny/issues/165

If so, feel free to close.

jeremiahsavage commented 7 years ago

Thanks. The fix works for me.