Stdout and Stderr are required for ComanndLine Option

[suecharo]

Expected Behavior

• I want to specify it as a runtime parameter as below

cwltool --stdout stdout.log --stderr stderr.log workflow.yml job-order.json

Actual Behavior

When cwltool is executed, standard output of cwltool, standard error output, output of each tool is dumped.
When log is collected by redirect,

• stdout: stdout of cwltool
• stderr: stderr of cwltool and output of each tool
  This is not supposed to be the expected behavior.
  Of course, the output of each tool should be written in the tool definition. However, if we prepare log collecting methods other than redirects, will not logs get mixed up?

---

When collected by redirect

cwltool Workflows/test-workflow.cwl Jobs/small.ERR034597.test-workflow.yml 1> ./stdout.log 2> ./stderr.log

stdout.log

{
    "oqc1": {
        "size": 224797,
        "class": "File",
        "path": "/home/ubuntu/cwl-test/small.ERR034597_1_fastqc.html",
        "checksum": "sha1$56265b5dfc6293e49f9a115d2cc6ad56229eb349",
        "location": "file:///home/ubuntu/cwl-test/small.ERR034597_1_fastqc.html",
        "basename": "small.ERR034597_1_fastqc.html"
    },
    "oqc2": { ...

stderr.log

/home/ubuntu/.local/bin/cwltool 1.0.20181217162649
Resolved '/home/ubuntu/SAPPORO/SAPPORO-service/workflow/workflow/test-workflow.cwl' to 'file:///home/ubuntu/SAPPORO/SAPPORO-service/workflow/workflow/test-workflow.cwl'
[workflow ] start
[workflow ] starting step trimPE
[step trimPE] start
[job trimPE] /tmp/kqyrl7z2$ docker \
    run \
    -i \
    --volume=/tmp/kqyrl7z2:/rZSzwS:rw \
    --volume=/tmp/f64g9d9p:/tmp:rw \
    --volume=/home/ubuntu/SAPPORO/SAPPORO-service/data/test_data/small.ERR034597_1.fastq:/var/lib/cwl/stgaa122340-9d37-4b3b-9570-8343026d2525/small.ERR034597_1.fastq:ro \
    --volume=/home/ubuntu/SAPPORO/SAPPORO-service/data/test_data/small.ERR034597_2.fastq:/var/lib/cwl/stg6fb2fbfd-dc7e-4c56-949d-320523db43ef/small.ERR034597_2.fastq:ro \
    --workdir=/rZSzwS \
    --read-only=true \
    --user=1000:1000 \
    --rm \
    --env=TMPDIR=/tmp \
    --env=HOME=/rZSzwS \
    --cidfile=/tmp/tmp3sta2sf6/20190105211108-510329.cid \
    quay.io/biocontainers/trimmomatic:0.38--1 \
    java \
    -jar \
    /usr/local/share/trimmomatic/trimmomatic.jar \
    PE \
    -threads \
    2 \
    /var/lib/cwl/stgaa122340-9d37-4b3b-9570-8343026d2525/small.ERR034597_1.fastq \
    /var/lib/cwl/stg6fb2fbfd-dc7e-4c56-949d-320523db43ef/small.ERR034597_2.fastq \
    small.ERR034597_1.fastq.trim.1P.fastq \
    small.ERR034597_1.fastq.trim.1U.fastq \
    small.ERR034597_2.fastq.trim.2P.fastq \
    small.ERR034597_2.fastq.trim.2U.fastq \
    ILLUMINACLIP:/usr/local/share/trimmomatic/adapters/TruSeq2-PE.fa:2:40:15
TrimmomaticPE: Started with arguments:
 -threads 2 /var/lib/cwl/stgaa122340-9d37-4b3b-9570-8343026d2525/small.ERR034597_1.fastq /var/lib/cwl/stg6fb2fbfd-dc7e-4c56-949d-320523db43ef/small.ERR034597_2.fastq small.ERR034597_1.fastq.trim.1P.fastq small.ERR034597_1.fastq.trim.1U.fastq small.ERR034597_2.fastq.trim.2P.fastq small.ERR034597_2.fastq.trim.2U.fastq ILLUMINACLIP:/usr/local/share/trimmomatic/adapters/TruSeq2-PE.fa:2:40:15
Using PrefixPair: 'AATGATACGGCGACCACCGAGATCTACACTCTTTCCCTACACGACGCTCTTCCGATCT' and 'CAAGCAGAAGACGGCATACGAGATCGGTCTCGGCATTCCTGCTGAACCGCTCTTCCGATCT'
Using Long Clipping Sequence: 'AGATCGGAAGAGCGTCGTGTAGGGAAAGAGTGTAGATCTCGGTGGTCGCCGTATCATT'
Using Long Clipping Sequence: 'AGATCGGAAGAGCGGTTCAGCAGGAATGCCGAGACCGATCTCGTATGCCGTCTTCTGCTTG'
Using Long Clipping Sequence: 'TTTTTTTTTTAATGATACGGCGACCACCGAGATCTACAC'
Using Long Clipping Sequence: 'TTTTTTTTTTCAAGCAGAAGACGGCATACGA'
Using Long Clipping Sequence: 'CAAGCAGAAGACGGCATACGAGATCGGTCTCGGCATTCCTGCTGAACCGCTCTTCCGATCT'
Using Long Clipping Sequence: 'AATGATACGGCGACCACCGAGATCTACACTCTTTCCCTACACGACGCTCTTCCGATCT'
ILLUMINACLIP: Using 1 prefix pairs, 6 forward/reverse sequences, 0 forward only sequences, 0 reverse only sequences
Quality encoding detected as phred33
Input Read Pairs: 25000 Both Surviving: 24996 (99.98%) Forward Only Surviving: 4 (0.02%) Reverse Only Surviving: 0 (0.00%) Dropped: 0 (0.00%)
TrimmomaticPE: Completed successfully
[job trimPE] Max memory used: 0MiB
[job trimPE] completed success
[step trimPE] completed success ...

---

When collecting using main.py directly

from cwltool.main import main

WORKFLOW_FILE = "/home/ubuntu/cwl-test/CWL-workflows/Workflows/test-workflow.cwl"
JOB_ORDER_FILE = "/home/ubuntu/cwl-test/CWL-workflows/Jobs/small.ERR034597.test-workflow.yml"

if __name__ == "__main__":
    f_out = open("/home/ubuntu/cwl-test/stdout.log", "w")
    f_err = open("/home/ubuntu/cwl-test/stdout.err", "w")
    main(
        [
            WORKFLOW_FILE,
            JOB_ORDER_FILE,
        ],
        stdout=f_out,
        stderr=f_err,
    )

stdout.log

{
    "oqc1": {
        "size": 224797,
        "class": "File",
        "path": "/home/ubuntu/cwl-test/small.ERR034597_1_fastqc.html",
        "checksum": "sha1$56265b5dfc6293e49f9a115d2cc6ad56229eb349",
        "location": "file:///home/ubuntu/cwl-test/small.ERR034597_1_fastqc.html",
        "basename": "small.ERR034597_1_fastqc.html"
    },
    "oqc2": { ...

stderr.log

Resolved '/home/ubuntu/SAPPORO/SAPPORO-service/workflow/workflow/test-workflow.cwl' to 'file:///home/ubuntu/SAPPORO/SAPPORO-service/workflow/workflow/test-workflow.cwl'
[workflow ] start
[workflow ] starting step trimPE
[step trimPE] start
[job trimPE] /tmp/s99ri3j7$ docker \
    run \
    -i \
    --volume=/tmp/s99ri3j7:/lchkYz:rw \
    --volume=/tmp/63x1fysd:/tmp:rw \
    --volume=/home/ubuntu/SAPPORO/SAPPORO-service/data/test_data/small.ERR034597_2.fastq:/var/lib/cwl/stg373eaf3c-f19c-48af-99d6-c79cb9509b4e/small.ERR034597_2.fastq:ro \
    --volume=/home/ubuntu/SAPPORO/SAPPORO-service/data/test_data/small.ERR034597_1.fastq:/var/lib/cwl/stg13bf749b-a9e2-43d3-9d2a-e01f467d36cb/small.ERR034597_1.fastq:ro \
    --workdir=/lchkYz \
    --read-only=true \
    --user=1000:1000 \
    --rm \
    --env=TMPDIR=/tmp \
    --env=HOME=/lchkYz \
    --cidfile=/tmp/tmpkt8_ijst/20190105220951-852769.cid \
    quay.io/biocontainers/trimmomatic:0.38--1 \
    java \
    -jar \
    /usr/local/share/trimmomatic/trimmomatic.jar \
    PE \
    -threads \
    2 \
    /var/lib/cwl/stg13bf749b-a9e2-43d3-9d2a-e01f467d36cb/small.ERR034597_1.fastq \
    /var/lib/cwl/stg373eaf3c-f19c-48af-99d6-c79cb9509b4e/small.ERR034597_2.fastq \
    small.ERR034597_1.fastq.trim.1P.fastq \
    small.ERR034597_1.fastq.trim.1U.fastq \
    small.ERR034597_2.fastq.trim.2P.fastq \
    small.ERR034597_2.fastq.trim.2U.fastq \
    ILLUMINACLIP:/usr/local/share/trimmomatic/adapters/TruSeq2-PE.fa:2:40:15
[job trimPE] Max memory used: 0MiB
[job trimPE] completed success
[step trimPE] completed success ...

---

As described above, the log output in the case of collecting by using main.py directly is originally supposed. Therefore, it seems to be necessary to prepare a log collection method other than redirect.

Workflow Code

Using https://github.com/hacchy1983/CWL-workflows

Your Environment

Ubuntu: 16.04

$ python3 -V
Python 3.5.2
$ cwltool --version
/home/ubuntu/.local/bin/cwltool 1.0.20181217162649

[inutano]

Though I don't know if the current behavior of cwltool to output the mixed stderr log of each tool and cwltool itself is intentional, it'd be good if users can specify files to write the stderr separately.

If there's no blocker to implement these options, @suecharo would help to implement it ;) Any idea for logging, @mr-c @tetron ?

[mr-c]

Better logging options are welcome, yes!

[cwl-bot]

This issue has been mentioned on Common Workflow Language Discourse. There might be relevant details there:

https://cwl.discourse.group/t/stdout-and-log-file/128/2