missing timestamps in ROBOT verbose (-vv) logs

[jclerman]

Looks like this has actually likely been an issue since v1.8.3, but I just noticed it today, when I updated from v1.8.1 to 1.9.2.

Previously, verbose ROBOT log (console) output included timestamps; now it doesn't. E.g.:

Before (v1.8.1)

2023-02-10 21:32:44,920 INFO  org.obolibrary.robot.CommandLineHelper - Reasoner: hermit
2023-02-10 21:32:44,938 INFO  org.obolibrary.robot.ReasonOperation - Ontology has 56843 axioms.
2023-02-10 21:32:46,492 INFO  org.obolibrary.robot.ReasonOperation - Starting reasoning...
2023-02-10 21:32:46,493 INFO  org.obolibrary.robot.ReasonerHelper - Checking for inconsistencies
2023-02-10 21:32:46,570 INFO  org.obolibrary.robot.ReasonerHelper - Checking for unsatisfiable classes...
2023-02-10 21:37:30,172 INFO  org.obolibrary.robot.ReasonerHelper - Checking for unsatisfiable object properties...
2023-02-10 22:02:53,083 INFO  org.obolibrary.robot.ReasonOperation - Precomputing class hierarchy...

After (v1.9.2)

INFO  Reasoner: hermit
INFO  Ontology has 56843 axioms.
INFO  Starting reasoning...
INFO  Checking for inconsistencies
INFO  Checking for unsatisfiable classes...
INFO  Checking for unsatisfiable object properties...
INFO  Precomputing class hierarchy...

Looks like the essential issue might be that logback.xml is not found by java. Further, looks like that file was removed from robot-command/src/main/resources at some point after @beckyjackson added it. I was able to "fix" the issue by copying the file that used to be there (https://github.com/ontodev/robot/blob/5c03178e563a24fe633609bd9c701f25e31b8df5/robot-command/src/main/resources/logback.xml) to my local machine and then updating the robot shell script locally, so that the 2nd-to-last line is now:

    exec java $ROBOT_JAVA_ARGS -Dlogback.configurationFile="$DIR/logback.xml" -jar "$DIR/robot.jar" "$@"

that's a hack... is there a better way?

[jamesaoverton]

Thanks for the report! This seems to have been related to the Log4Shell debacle, and we were trying to move fast. The main PR was #948, and then with cleanup in #953. I retraced the history as:

1. in 5c03178 we added two logback.xml configs
2. in 1d204f1 we removed the two log4j.properties files
3. in b8af9d7 I removed robot-command/src/main/resources/logback.xml -- I think that was the mistake; there was no discussion of simplifying the log output

So the fix would be git checkout 1d204f139fa975e16466281f5f9417b569ffd95f -- robot-command/src/main/resources/logback.xml

@matentzn Would restoring more detailed logging to ROBOT CLI (not library operations) cause any problems for ODK?

[matentzn]

As long as there is more detail in rows, and not more rows, there wont be a problem!

The issue is not ODK per se - the issue is that if the LOG length will be enormous, GitHub actions will strike!

[jamesaoverton]

Just a note: I think that I removed the robot-command/src/main/resources/logback.xml file because maven-shade-plugin was complaining about an overlapping resource. I didn't notice at the time that there were two different logging patterns.