Process logs don't include R stdout/stderr and don't respect line breaks #1705

wclose · 2020-08-13T17:18:38Z

Bug report

Expected behavior and actual behavior

Expected:
Logs created using a markdown template should include stdout/stderr from R scripts. They should also maintain the line breaks found in the .command.out and .command.err files so the logs are human readable.

Actual:
When creating a process log using a markdown template as outlined here: https://www.nextflow.io/blog/2019/easy-provenance-report.html, the log does not incorporate stdout/stderr from R scripts. Additonally, any included stdout/stderr for any process is output to only a single line in the log which is not human readable, particularly for long running processes.

Steps to reproduce the problem

MWE can be found here: https://github.com/wclose/nextflow_log

Includes example workflow and outputs showing issue
Log file was generated using nextflow log last -t log_template.md > log_test.md

Program output

`nextflow run main.nf`

N E X T F L O W  ~  version 20.07.1
Launching `main.nf` [backstabbing_curran] - revision: 7c751f9c5e
executor >  local (2)
[af/80ee2c] process > exampleRScript    [100%] 1 of 1 ✔
[19/676b67] process > exampleBashScript [100%] 1 of 1 ✔
this is one line
this is another line
this is the last line


rd.csv> ## using count.fields to handle unknown maximum number of fields
rd.csv> ## when fill = TRUE
rd.csv> test1 <- c(1:5, "6,7", "8,9,10")

rd.csv> tf <- tempfile()

rd.csv> writeLines(test1, tf)

rd.csv> read.csv(tf, fill = TRUE) # 1 column
  X1
1  2
2  3
3  4
4  5
5  6
6  7
7  8
8  9
9 10

rd.csv> ncol <- max(count.fields(tf, sep = ","))

rd.csv> read.csv(tf, fill = TRUE, header = FALSE,
rd.csv+          col.names = paste0("V", seq_len(ncol)))
  V1 V2 V3
1  1 NA NA
2  2 NA NA
3  3 NA NA
4  4 NA NA
5  5 NA NA
6  6  7 NA
7  8  9 10

rd.csv> unlink(tf)

rd.csv> ## "Inline" data set, using text=
rd.csv> ## Notice that leading and trailing empty lines are auto-trimmed
rd.csv> 
rd.csv> read.table(header = TRUE, text = "
rd.csv+ a b
rd.csv+ 1 2
rd.csv+ 3 4
rd.csv+ ")
  a b
1 1 2
2 3 4

.command.out (example.sh)

this is one line
this is another line
this is the last line

.command.out (example.R)


rd.csv> ## using count.fields to handle unknown maximum number of fields
rd.csv> ## when fill = TRUE
rd.csv> test1 <- c(1:5, "6,7", "8,9,10")

rd.csv> tf <- tempfile()

rd.csv> writeLines(test1, tf)

rd.csv> read.csv(tf, fill = TRUE) # 1 column
  X1
1  2
2  3
3  4
4  5
5  6
6  7
7  8
8  9
9 10

rd.csv> ncol <- max(count.fields(tf, sep = ","))

rd.csv> read.csv(tf, fill = TRUE, header = FALSE,
rd.csv+          col.names = paste0("V", seq_len(ncol)))
  V1 V2 V3
1  1 NA NA
2  2 NA NA
3  3 NA NA
4  4 NA NA
5  5 NA NA
6  6  7 NA
7  8  9 10

rd.csv> unlink(tf)

rd.csv> ## "Inline" data set, using text=
rd.csv> ## Notice that leading and trailing empty lines are auto-trimmed
rd.csv> 
rd.csv> read.table(header = TRUE, text = "
rd.csv+ a b
rd.csv+ 1 2
rd.csv+ 3 4
rd.csv+ ")
  a b
1 1 2
2 3 4

log_template.md

## $name

script: 

    $script

    $stdout

    $stderr

exist status: $exit
task status: $status

log_test.md

## exampleRScript

script: 

    
  example.R
  

    -

    -

exist status: 0
task status: COMPLETED


## exampleBashScript

script: 

    
  example.sh
  

    this is one linethis is another linethis is the last line

    -

exist status: 0
task status: COMPLETED

.nextflow.log

Aug-13 17:12:01.553 [main] DEBUG nextflow.cli.Launcher - $> nextflow run main.nf
Aug-13 17:12:01.619 [main] INFO  nextflow.cli.CmdRun - N E X T F L O W  ~  version 20.07.1
Aug-13 17:12:01.629 [main] INFO  nextflow.cli.CmdRun - Launching `main.nf` [backstabbing_curran] - revision: 7c751f9c5e
Aug-13 17:12:01.762 [main] DEBUG nextflow.Session - Session uuid: cd790887-22ac-4cc0-b1c6-65b86a7b33d7
Aug-13 17:12:01.762 [main] DEBUG nextflow.Session - Run name: backstabbing_curran
Aug-13 17:12:01.764 [main] DEBUG nextflow.Session - Executor pool size: 8
Aug-13 17:12:01.827 [main] DEBUG nextflow.cli.CmdRun - 
  Version: 20.07.1 build 5412
  Created: 24-07-2020 15:18 UTC 
  System: Linux 4.15.0-1057-aws
  Runtime: Groovy 2.5.11 on OpenJDK 64-Bit Server VM 11.0.8-internal+0-adhoc..src
  Encoding: UTF-8 (UTF-8)
  Process: 8817@ip-172-31-16-128 [172.31.16.128]
  CPUs: 8 - Mem: 62.1 GB (32.4 GB) - Swap: 0 (0)
Aug-13 17:12:01.863 [main] DEBUG nextflow.Session - Work-dir: /analysis/nextflow_test/work [ext2/ext3]
Aug-13 17:12:01.930 [main] DEBUG nextflow.Session - Observer factory: TowerFactory
Aug-13 17:12:01.933 [main] DEBUG nextflow.Session - Observer factory: DefaultObserverFactory
Aug-13 17:12:02.078 [main] DEBUG nextflow.Session - Session start invoked
Aug-13 17:12:02.456 [main] DEBUG nextflow.script.ScriptRunner - > Launching execution
Aug-13 17:12:02.475 [main] DEBUG nextflow.Session - Workflow process names [dsl1]: exampleBashScript, exampleRScript
Aug-13 17:12:02.511 [main] DEBUG nextflow.executor.ExecutorFactory - << taskConfig executor: null
Aug-13 17:12:02.512 [main] DEBUG nextflow.executor.ExecutorFactory - >> processorType: 'local'
Aug-13 17:12:02.515 [main] DEBUG nextflow.executor.Executor - [warm up] executor > local
Aug-13 17:12:02.520 [main] DEBUG n.processor.LocalPollingMonitor - Creating local task monitor for executor 'local' > cpus=8; memory=62.1 GB; capacity=8; pollInterval=100ms; dumpInterval=5m
Aug-13 17:12:02.673 [main] DEBUG nextflow.executor.ExecutorFactory - << taskConfig executor: null
Aug-13 17:12:02.673 [main] DEBUG nextflow.executor.ExecutorFactory - >> processorType: 'local'
Aug-13 17:12:02.677 [main] DEBUG nextflow.script.ScriptRunner - > Await termination 
Aug-13 17:12:02.677 [main] DEBUG nextflow.Session - Session await
Aug-13 17:12:02.843 [Task submitter] DEBUG nextflow.executor.LocalTaskHandler - Launch cmd line: /bin/bash -ue .command.run
Aug-13 17:12:02.850 [Task submitter] INFO  nextflow.Session - [af/80ee2c] Submitted process > exampleRScript
Aug-13 17:12:02.865 [Task submitter] DEBUG nextflow.executor.LocalTaskHandler - Launch cmd line: /bin/bash -ue .command.run
Aug-13 17:12:02.866 [Task submitter] INFO  nextflow.Session - [19/676b67] Submitted process > exampleBashScript
Aug-13 17:12:02.903 [Task monitor] DEBUG n.processor.TaskPollingMonitor - Task completed > TaskHandler[id: 1; name: exampleBashScript; status: COMPLETED; exit: 0; error: -; workDir: /analysis/nextflow_test/work/19/676b673dc7e2d9569680bc1dbfe7bc]
Aug-13 17:12:03.133 [Task monitor] DEBUG n.processor.TaskPollingMonitor - Task completed > TaskHandler[id: 2; name: exampleRScript; status: COMPLETED; exit: 0; error: -; workDir: /analysis/nextflow_test/work/af/80ee2c17ac72c682b092ccc57d692d]
Aug-13 17:12:03.135 [main] DEBUG nextflow.Session - Session await > all process finished
Aug-13 17:12:03.137 [main] DEBUG nextflow.Session - Session await > all barriers passed
Aug-13 17:12:03.148 [main] DEBUG nextflow.trace.WorkflowStatsObserver - Workflow completed > WorkflowStats[succeededCount=2; failedCount=0; ignoredCount=0; cachedCount=0; pendingCount=0; submittedCount=0; runningCount=0; retriesCount=0; abortedCount=0; succeedDuration=245ms; failedDuration=0ms; cachedDuration=0ms;loadCpus=0; loadMemory=0; peakRunning=2; peakCpus=2; peakMemory=0; ]
Aug-13 17:12:03.330 [main] DEBUG nextflow.CacheDB - Closing CacheDB done
Aug-13 17:12:03.345 [main] DEBUG nextflow.script.ScriptRunner - > Execution complete -- Goodbye

Environment

Nextflow version: 20.07.1 build 5412
Java version: openjdk 11.0.8-internal 2020-07-14
Operating system: Linux
Bash version: GNU bash, version 4.4.20(1)-release (x86_64-pc-linux-gnu)

Additional context

N/A

The text was updated successfully, but these errors were encountered:

pditommaso · 2020-08-14T13:28:45Z

Spotted ☝️! thanks for reporting this issue.

wclose · 2020-08-14T15:23:42Z

Awesome, thanks again!

pditommaso added a commit that referenced this issue Aug 14, 2020

Fix missing newline on cmd log stdout/err #1705

1416a38

pditommaso closed this as completed Aug 14, 2020

pditommaso added this to the v20.10.0 milestone Aug 14, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Process logs don't include R stdout/stderr and don't respect line breaks #1705

Process logs don't include R stdout/stderr and don't respect line breaks #1705

wclose commented Aug 13, 2020

pditommaso commented Aug 14, 2020

wclose commented Aug 14, 2020

Process logs don't include R stdout/stderr and don't respect line breaks #1705

Process logs don't include R stdout/stderr and don't respect line breaks #1705

Comments

wclose commented Aug 13, 2020

Bug report

Expected behavior and actual behavior

Steps to reproduce the problem

Program output

nextflow run main.nf

.command.out (example.sh)

.command.out (example.R)

log_template.md

log_test.md

.nextflow.log

Environment

Additional context

pditommaso commented Aug 14, 2020

wclose commented Aug 14, 2020

`nextflow run main.nf`