Nextflow: Println operator output is not shown with ansi logging

[olgabot]

Hello,
Since upgrading to 19.04 and 19.04-edge I am unable to use Channel.fromFilePairs. Below is an example script showing that 19.03 properly finds the file pairs and 19.04+ does not. I wasn't able to see a mention of fromFilePairs in either the 19.04 and 19.03 changelogs - did something else affect this?
Thank you!
Warmest,
Olga

Bug report

Expected behavior and actual behavior

I expected Channel.fromFilePairs to return a name and a tuple of R1, R2 read pairs regardless of nextflow version. Unfortunately, the output is different whether I use version 19.03-edge, 19.04 and 19.04-edge.

Steps to reproduce the problem

Here is the workflow:

Channel
  .fromFilePairs('/Users/olgabot/code/nf-kmer-similarity/testing/fastqs/*{1,2}.fastq.gz')
  .println()

Channel
  .fromFilePairs('*_pass_{1,2}.fastq.gz')
  .println()

Channel
  .fromPath('*.fastq.gz')
  .println()

Channel
  .fromFilePairs("s3://kmer-hashing/rawdata/merkin2012/sra/*RNA-Seq{1,2}.fastq.gz")
  .println()

Program output

(Copy and paste here output produced by the failing execution. Please highlight it as a code block. Whenever possible upload the .nextflow.log file.)

19.03-edge works

File pairs are output:

(base)
 ♥ 59%  Thu  2 May - 15:36  ~/Downloads 
  ~/bin/nextflow-19.03-edge run scratch.nf
N E X T F L O W  ~  version 19.03.0-edge
Launching `scratch.nf` [zen_dijkstra] - revision: 6cd6d08932
[SRR4050379_pass, [/Users/olgabot/code/nf-kmer-similarity/testing/fastqs/SRR4050379_pass_1.fastq.gz, /Users/olgabot/code/nf-kmer-similarity/testing/fastqs/SRR4050379_pass_2.fastq.gz]]
[SRR4050380_pass, [/Users/olgabot/code/nf-kmer-similarity/testing/fastqs/SRR4050380_pass_1.fastq.gz, /Users/olgabot/code/nf-kmer-similarity/testing/fastqs/SRR4050380_pass_2.fastq.gz]]
/Users/olgabot/Downloads/SRR4050379_pass_2.fastq.gz
/Users/olgabot/Downloads/SRR4050380_pass_2.fastq.gz
/Users/olgabot/Downloads/SRR4050379_pass_1.fastq.gz
[SRR4050379, [/Users/olgabot/Downloads/SRR4050379_pass_1.fastq.gz, /Users/olgabot/Downloads/SRR4050379_pass_2.fastq.gz]]
/Users/olgabot/Downloads/SRR4050380_pass_1.fastq.gz
[SRR4050380, [/Users/olgabot/Downloads/SRR4050380_pass_1.fastq.gz, /Users/olgabot/Downloads/SRR4050380_pass_2.fastq.gz]]
Completed at: 02-May-2019 15:37:13
Duration    : 2.2s
CPU hours   : (a few seconds)
Succeeded   : 0

19.04 doesn't work

No file pairs are output:

(base)
 ♥ 60%  Thu  2 May - 15:35  ~/Downloads 
  export NXF_DEBUG=3 && nextflow run scratch.nf
N E X T F L O W  ~  version 19.04.0
Launching `scratch.nf` [disturbed_magritte] - revision: 577d9a8cb5
/Users/olgabot/Downloads/SRR4050379_pass_2.fastq.gz
/Users/olgabot/Downloads/SRR4050380_pass_2.fastq.gz
/Users/olgabot/Downloads/SRR4050379_pass_1.fastq.gz
/Users/olgabot/Downloads/SRR4050380_pass_1.fastq.gz

19.04-edge doesn't work

No file pairs are output:

(base)
 ♥ 55%  Thu  2 May - 15:45  ~/Downloads 
  ~/bin/nextflow-v19.04.0-edge run scratch.nf
CAPSULE: Downloading dependency io.nextflow:nf-commons:pom:19.04.0-edge
CAPSULE: Downloading dependency io.nextflow:nextflow:pom:19.04.0-edge
CAPSULE: Downloading dependency io.nextflow:nf-httpfs:pom:19.04.0-edge
CAPSULE: Downloading dependency io.nextflow:nf-commons:jar:19.04.0-edge
CAPSULE: Downloading dependency io.nextflow:nextflow:jar:19.04.0-edge
CAPSULE: Downloading dependency io.nextflow:nf-httpfs:jar:19.04.0-edge
N E X T F L O W  ~  version 19.04.0-edge
Launching `scratch.nf` [furious_curie] - revision: 6cd6d08932
/Users/olgabot/Downloads/SRR4050379_pass_2.fastq.gz
/Users/olgabot/Downloads/SRR4050380_pass_2.fastq.gz
/Users/olgabot/Downloads/SRR4050379_pass_1.fastq.gz
/Users/olgabot/Downloads/SRR4050380_pass_1.fastq.gz

Environment

• Nextflow version: 19.03, 19.04, 19.04-edge
• Java version: 1.8.0_131
• Operating system: macOS

[pditommaso]

It should be a glitch with the new log system. If you add the option -ansi-log false it should work.

[pditommaso]

Fixed and release with nextflow 19.04.1.

[szabogtamas]

Using version 19.07.0, we encountered a similar issue: if we want to print channel content for debugging purposes, the message is displayed for a few seconds, but then it is overwritten by the pipeline progress report. It happens only if we have multiple processes and adding a few newline characters to the message or using the suggested flag (-ansi-log false) prevents the problem.

The dummy script below can be used to reproduce the problem:

#!/usr/bin/env nextflow


params.foo = 'FOO'
params.bar = 'BAR'


process dummyProcess {

    input:
        val foo from params.foo
        val bar from params.bar

    output:
        stdout dummyout

    script:   
        """
        echo $foo $bar
        """
}

process anotherProcess {

    input:
        val dummyout

    output:
        val anotherout

    exec:   
        Channel
            .from(dummyout)
            //.map { '\n\n\n\n\n(' + it + ')' } //Adding some new lines will make the message visible
            .map { '(' + it + ')' }
            .set { anotherout }
}

anotherout.subscribe { println 'Hi: '+ it } 

launched with the command
nextflow run println_bug.nf

it returns

N E X T F L O W  ~  version 19.07.0
Launching `println_bug.nf` [hungry_meitner] - revision: 9a8eab6bfe
[-        ] process > dummyProcess   -
[-        ] process > anotherProcess -
executor >  local (2)
[86/7daa74] process > dummyProcess   [100%] 1 of 1 ✔
[cc/6a84a8] process > anotherProcess [100%] 1 of 1 ✔

with the command
nextflow run println_bug.nf -ansi-log false

I get the output:

N E X T F L O W  ~  version 19.07.0
Launching `println_bug.nf` [lonely_cantor] - revision: 9a8eab6bfe
[eb/77ae3e] Submitted process > dummyProcess
[cb/ad78fa] Submitted process > anotherProcess
HI: DataflowQueue(queue=[DataflowVariable(value=(FOO BAR
)), DataflowVariable(value=groovyx.gpars.dataflow.operator.PoisonPill@3f18eb6b)])

Any ideas why? Is this the intended behaviour? Should we always use this flag during test runs (pipeline finished message in production would still be eaten up maybe)?

Thanks in advance.

[hoelzer]

@szabogtamas yes, I also still experience the same issue (using 20.01.0). It would be great to print a final mssg to the user at the end of workflow completion but it only appears for a millisecond and is then lost.

[pditommaso]

To prevent this problem, use log.info instead of println.

[hoelzer]

works, thanks @pditommaso !

[hoelzer]

But any idea while colors are not working with log.info()?

c_blue = "\033[0;34m";
c_reset = "\033[0m";
workflow.onComplete { 
    log.info(" ")
    log.info("${c_blue}Results are reported here:")
    log.info("    $params.output/<prefix_of_your_fasta>/html/full_aln/index.html${c_reset}")
    log.info(" ")
}

results in

[0;34mResults are reported here:
results/<prefix_of_your_fasta>/html/full_aln/index.html