Log-Level "INFO" of a Tool gives "WARN" in RCE

[StRuoff]

When a Tool writes Logs to the Console with logging, the logging level (in this case "INFO") is not preserved through RCE. It instead gives a "WARN" message. It then looks like this:

2019-12-02 10:57:25,873 WARN  - de.rcenvironment.core.component.execution.api.ConsoleRowUtils - INFO     __main__

This is especially confusing, since in the workflow console those messages appear in read, even though nothing went wrong in the tool.

Is this intended behavior? If so, it should be noted somewhere and I should use "DEBUG" instead of "INFO" for my logging levels for the RCE.

I tested it with RCE 10.0, my scripts are running python 3.7 using the logging module

[janflink]

An issue has been added to our internal issue tracker: https://mantis.sc.dlr.de/view.php?id=17073

[ArneBachmannDLR]

@StRuoff: I'm wondering what do you mean with "with logging"? What programming language and logging framework are we talking about? I would assume all tool output to be treated as "stdout" (=INFO?) or "stderr" (=ERROR?), and any log levels and printouts are solely defined by the tool implementation itself. Can you share some code?

[StRuoff]

I have a python-script wrapped around my Simulation, that is then called via the RCE. In the python (3) script I am using python logging (https://docs.python.org/3.7/library/logging.html) to give information about what happens in the python script. For that, I can specify a "log level" (CRITICAL, ERROR, WARNING ,INFO ,DEBUG ), depending on how severe the error/info is.

But I think you pointed to where the behavior comes from: If I get it right, the workflow console only checks if the message is printed to stderr or stdout, which of course does not preserve the python logging level. In this case, if have to define in my script, wheter the info-level is written to stderr (and thus treated as error) or to stdout (and thus treated as "normal" output).

However, there also is the "Log"-tab in RCE, which seems to have some sort of log-level (it shows checkboxes with ERROR, WARN and INFO), and here all messages coming from my script are treated as "WARN", as seen in the screenshot below.

[ArneBachmannDLR]

I assume that the Log tab uses some kind of Java logger system present throughout RCE like SL4J, tinylog, log4j etc. You would need to create a Java component instead of a wrapped tool to access it. Would be cool to pass Python log levels to the RCE log view, though!

[StRuoff]

Ok, thank you for the clarification. Then I will fix my script, so that the INFO wiil not look like an error in the workflow console (by writing to stdout instead of stderr). Otherwise, other users may treat it as if something went wrong, even though it didn't.

In this case, I think the issue can be closed, because it is not an error/a bug.

[StRuoff]

So, I just fixed the problem. Since the Java-Logger indeed only distinguished between stdout and stderr, I put this piece of code for my logger to write everything below ERROR to stdout using a filter:

class LessThanFilter(logging.Filter):
    def __init__( self, exclusive_maximum, name='' ):
        super( LessThanFilter, self ).__init__( name )
        self.max_level = exclusive_maximum

    def filter( self, record ):
        #non-zero return means we log this message
        return 1 if record.levelno < self.max_level else 0

# set formatting for logging output
LOGFILE_FORMAT = "%(levelname)-8s - %(asctime)-15s - %(name)-30s -%(funcName)-20s - l.%(lineno)-5s"\
                " - %(message)s"
CONSOLE_FORMAT = logging.Formatter("%(levelname)-8s %(name)-30s: %(message)s")
DATE_FORMAT    = "%Y-%m-%d  %H:%M:%S"
logging.basicConfig(level=logging.DEBUG, format=LOGFILE_FORMAT, datefmt=DATE_FORMAT, filename='driver.log', filemode='a')

# Write all log-messages below level "ERROR" to Stdout
# Level DEBUG is added if -v flag is set in main
out_handler = logging.StreamHandler( stream=sys.stdout )
out_handler.setLevel( logging.INFO )
out_handler.addFilter( LessThanFilter( logging.ERROR ) )
out_handler.setFormatter( CONSOLE_FORMAT )
logging.getLogger().addHandler( out_handler )

# Only write error and critical to stderr
err_handler = logging.StreamHandler( stream=sys.stderr )
err_handler.setLevel( logging.ERROR )
out_handler.setFormatter( CONSOLE_FORMAT )
logging.getLogger().addHandler( err_handler )

[ArneBachmannDLR]

Thanks for the solution! I will put it into the RCE wiki for future reference. But it would still be neat to map Python log levels to the respective Java logger levels. This might (?) have been possible using Jython, but probably not in Cython.