Singularity: verify command outputs to STDERR and STDOUT

[rherban]

Version of Singularity:

3.4.0

Expected behavior

only errors should go to STDERR, INFO should go to STDOUT

Actual behavior

Have to show this backwards, but the 2>/dev/null sends STDERR to /dev/null and should have the full output. But when you do a 1>/dev/null, you still see an INFO line.

[rherban@test]:~/webinar$ singularity verify signed_latest.sif 2>/dev/null
Container is signed by 1 key(s):

Verifying signature F: 772BC38DA898E4CFBC8AE254CF70553FE8DC8912:
[LOCAL]   Randy Herban <[email protected]>
[OK]      Data integrity verified

[rherban@test]:~/webinar$ singularity verify signed_latest.sif 1>/dev/null
INFO:    Container verified: signed_latest.sif

[WestleyK]

Afaik, sylog.Infof() will output to stderr. Maybe that can be configured...

CC @ikaneshiro

[sashayakovtseva]

Well, I don't think I agree here with you @rherban.
It is a convention that logs go to stderr, and I don't think we should break this convention.

If the information is necessary to display, then it is not logs, but an actual output to stdout.
I.e. don't use sylog.Infof if you are not logging.

[pisarukv]

info, warn and debug messages are usually written into stderr, so, I believe it's not a bug

[dtrudg]

as this is going to invite some philosophical discussion it's been untagged from 3.4.1 with @rherban 's approval, but let's keep discussing :-)

I've just been thinking about it and have hopped across the fence from one side to the other a couple of times... considering past experience, and interactive vs scripted use etc.... I certainly need more time to formulate a cogent opinion.

[jmstover]

I agree with @rherban here. In this context, Infof() should go to stdout. I would say any output besides Fatalf() should go to stdout, with Fatalf() going to stderr as that's the only actual error.

Warningf() to me could be either... depending on its usage.

The others are all informational. Not error conditions.

[sashayakovtseva]

We should not call it log package then IMO.

[jmstover]

@sashayakovtseva Nah... Like @dctrud said... this becomes philosophical. Calling it a log package is fine, if you look at syslog you can control where stuff is output to, even critical errors that default logging to consoles you can change. Some folks consider any output from a program that is not the program output as "error" (stderr) output. But stderr is for error output (diagnostic really... can't open file, file doesn't exist, permission denied, incorrect usage... etc.).

If you want to be evil, open another random file descriptor attached to stdout, and have your log output print to that random descriptor. ;)

Philosophical Rambling here...
By doing all output to stderr you're also breaking some pipe processing. stderr doesn't get passed by default, so if you need to process any of that normal output you need to redirect stderr to stdout like:

mycmd 2>&1 | mycmd2 2>&1 | mycmd3

This can get more complicated... Say you pass an invalid option. The help message from the invalid option should be printed to stderr (you passed an invalid option... that's an error). Bad things can happen if you were to do something like:

cat Package | grep -k ^pkg | awk '{print($2)}' | xargs yum -y install 

and the error went to stdout. Above, -k is an invalid option, so if error output went to stdout, you would end up trying to do (for example) yum -y install invalid from the output of grep: invalid option -- 'k'

But, normal help output should go to stdout so you can do:

mycmd --help | grep 'myoption'

In my opinion, the Infof() and Verbosef() messages are normal _Singularity_ output. There's a reason the -q and -s options exist. This normal output should happen on stdout. If you don't want to see the normal singularity output, use the -q or -s flag.

Warningf() is debatable depending on usage, but I'd generally call that going to stderr acceptable. Sometimes the Warnings printed are more informational than diagnostic. The -q option doesn't suppress Warningf() output, but -s does.

If you want to consider all Singularity output as diagnostic, then I'll agree you don't need a log package. All output is then equivalent at that point. But we aren't doing that, so our output isn't equivalent. A Infof() call isn't the same as a Debugf(), which isn't the same as a Errorf() or Fatalf() call.

[dtrudg]

I'm leaning more toward a certain position here, but I don't want to say what that is. Instead I think I want to suggest we should actively seek feedback from users here (slack, dev mailing list etc.), and understand which scenarios the behavior / changes would impact. JMS's stuff touches on this, but before changing this behavior, or committing to the existing, we need to consider:

• How does it affect people using singularity interactively, maybe piping to a pager etc?
• How does it affect people using a traditional HPC batch job scheduler which by default writes stderr and stdout into different files? What makes most sense to be able to easily find errors, and /or handle any output that might be needed downstream there.
• How does it affect people who are using singularity in workflow systems such as Nextflow and Snakemake, which have certain stderr/stdout handling. I know these are in common use with Singularity.
• How does it affect people who are trying to use singularity in e.g. CI build pipelines?

Likely there's no one best solution for all of these, but we need to understand/consider what the most important needs of users are.

Lastly.... we do need to stay pragmatic and try to avoid becoming trapped in philosophical arguments. log is a bit of an overloaded term. Singularity's messages are often information during interactive execution, rather than 'logs' in the sense of a continuous stream of record that is written to throughout the life of a long-lived service/server daemon etc. I don't think that would warrant renaming our packages. There are doubtless situations around instances etc. where we do, or may in future, emit logs in that other sense :-)

[DrDaveD]

I think most of us at least could agree that the normal output of commands line singularity verify should go to stdout. The key question is whether or not the output should go through the log system. If yes, then the log system has to send that through stdout, if not, then the log system isn't involved and log messages can continue to go to stderr.

Personally I don't think that commands that are asked to show information should use the log system. It's strange to have the messages show up with the INFO: prefix.

[mem]

I agree with @sashayakovtseva here.

It's useful / desirable to keep output necessary for user interaction separate from output that is meant to serve as a record of what happened (a log).

Conventionally that means using at least two streams: one for user interaction (stdout) and one for logs (stderr).

If you (the developer) are using INFO because you know it's going to stdout you shouldn't be thinking of that as a log in the first place. Same goes for selecting a level based on whatever it's going to be seen by the user by default or not.

[dtrudg]

There was a discussion of this issue in the singularity developer call today. To summarize (hopefully accurately):

• There was some general agreement that 'normal' output should go to STDOUT, not to a STDERR logstream
• Some people don't think that normal informational messages should be prefixed with the INFO loglevel
• Our help messages are going to STDERR, this is considered a significant issue by some ( | less does not work as expected), while others stated this is often the case in other tools.
• There was a general feeling that none of this is critical, and may be 'overthought' by developers, and relatively unimportant to most users.

Please feel free to correct / append for my mistakes / omissions :-)

[dtrudg]

This initial issue was fixed in the re-work in the signing/verification that took place for 3.6.0

dave@dev-fedora:~
05:50 PM $ singularity verify test.sif 2> /dev/null
Verifying image: test.sif
[LOCAL]   Signing entity: David Trudgian (local) <[email protected]>
[LOCAL]   Fingerprint: D5A350A60FDD2101D6D2A2E5B251BFDC2A740579
Objects verified:
ID  |GROUP   |LINK    |TYPE
------------------------------------------------
1   |1       |NONE    |Def.FILE
2   |1       |NONE    |JSON.Generic
3   |1       |NONE    |FS
Container verified: test.sif
dave@dev-fedora:~
05:50 PM $ singularity verify test.sif 1> /dev/null
dave@dev-fedora:~
05:50 PM $ 

This doesn't necessarily address points raised in the discussion, but it does make verify consistent with expectations.