Red Hat Bugzilla – Bug 483014
rlLog* commands log differently to stdout
Last modified: 2018-01-15 16:37:52 EST
When logging with rlLog command there appears some ancient format of the log line on the standard output. :: [ PASS ] :: Testing pamtodjvurle on test-low.pgm :: [ PASS ] :: Testing pamtodjvurle on test-high.pgm :: [ PASS ] :: Testing pamtodjvurle on test-low.ppm :: [11:32:16] :: Skipping pamtodjvurle on test-high.ppm :: [ PASS ] :: Testing pamtofits on test-low.pbm :: [ PASS ] :: Testing pamtofits on test-high.pbm Similar inconsistency is with all rlLog* commmands: :: [ PASS ] :: Running 'true' :: [ PASS ] :: Checking for the presence of kernel rpm :: [11:40:39] :: rlLog :: [11:40:39] :: [ INFO ] :: rlLogInfo :: [11:40:39] :: [ ERROR ] :: rlLogError :: [11:40:40] :: [ WARNING ] :: rlLogWarning :: [11:40:40] :: [ DEBUG ] :: rlLogDebug We should make the logging to stdout consistent. The question is whether the timestamp should be present in the output. I suggest to keep current brief output for rlJournalPrintText and include timestamps in stdout, perhaps something like this: :: [11:40:38 PASS ] :: Testing pamtodjvurle on test-low.ppm :: [11:40:39 ERROR ] :: rlLogError :: [11:40:40 WARNING ] :: rlLogWarning :: [11:40:40 DEBUG ] :: rlLogDebug
+1 to unified output on stdout +1 to timestamps on stdout - useful when debugging failed test And I vote for having the timestamps in journal (having them printed by rlJournalPrintText is another question) - I hate it when I can't find all necessary information in journal/its human-readable dump and pray to find it in TESTOUT.log.
+1 to unified output on stdout +1 to timestamps on stdout - useful when debugging failed test +1 to have timestamps in journal
After consultation with psplichal I'm going to write patch for this issue.
It will probably be necessary to reserve a new attribute to store timestamps in the journal. Do we have some specification of the journal xml? I just noticed that some tags like "phase" have their "starttime" and "endtime" attributes. For this purpose I probably need a new attribute. Maybe "time", "perftime", "logtime" or even "starttime" could be used. Also "endtime" could be used depending on when we are logging :-) I vote for "time" attribute.
I suggest to use the consistent time-related attributes naming throughout the journal, for example: <assert message="Comment" result="PASS" starttime="..." endtime="..."> See bug 555302 for the whole picture of the suggested journal update.
According to https://bugzilla.redhat.com/show_bug.cgi?id=555302#c1 it seems pmuller is working on new journalling mechanism, so I'm not sure if this bug is up to date.
The bug is mainly about making a system & order in the way how the logging is handled by the shell functions. That is: not to log differently to stdout (with/without timestamps) and use consistent way how to pass the logged information to both standard output and the journal. For now rlLog* use __INTERNAL_LogText for separate stdout logging while the asserting functions use just "__INTERNAL_JOURNALIST test" which takes care of the stdout. This should be made more clear/clean. Once we agree on the new journalling API this could be nicely fixed.
Here are my suggested changes: git diff logging.sh diff --git a/beakerlib/logging.sh b/beakerlib/logging.sh index 071e4bf..08f9dfe 100644 --- a/beakerlib/logging.sh +++ b/beakerlib/logging.sh @@ -98,9 +98,11 @@ Priority of the log. rlLog() { - __INTERNAL_LogText ":: [`date +%H:%M:%S`] :: $3 $1" "$2" - if [ "$3" == "" ] + if [ "$3" != "" ] then + __INTERNAL_LogText ":: [ `date +%H:%M:%S` ] :: $3 $1" "$2" + else + __INTERNAL_LogText ":: [ `date +%H:%M:%S` ] :: [ LOG ] :: $1" "$2" rljAddMessage "$1" "LOG" fi } git diff journalling.py diff --git a/beakerlib/python/journalling.py b/beakerlib/python/journalling.py index 3e67da4..4344cc0 100755 --- a/beakerlib/python/journalling.py +++ b/beakerlib/python/journalling.py @@ -58,7 +58,7 @@ def printPurpose(message): def printLog(message, prefix="LOG"): for line in message.split("\n"): - _print(":: [%s] :: %s" % (prefix.center(10), line)) + _print(":: [ %s ] :: [ %s ] :: %s" % (time.strftime("%H:%M:%S", time.localtime()) ,prefix.ljust(7), line)) def printHeadLog(message): print "\n::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::"
I'm starting to work on the journal again and I will take care of this too.
Just ran into this and psss directed me to this bug. Are there any plans on accepting the patch noted in comment#8 (or some other solution)?
This bug appears to have been reported against 'rawhide' during the Fedora 19 development cycle. Changing version to '19'. (As we did not run this process for some time, it could affect also pre-Fedora 19 development cycle bugs. We are very sorry. It will help us with cleanup during Fedora 19 End Of Life. Thank you.) More information and reason for this action is here: https://fedoraproject.org/wiki/BugZappers/HouseKeeping/Fedora19
This package has changed ownership in the Fedora Package Database. Reassigning to the new owner of this component.
I would also propose to put all those messages to STDERR and it is useful in function returning some test for post processing as such functions can also use logging and debugging functions without breaking the data.
This message is a notice that Fedora 19 is now at end of life. Fedora has stopped maintaining and issuing updates for Fedora 19. It is Fedora's policy to close all bug reports from releases that are no longer maintained. Approximately 4 (four) weeks from now this bug will be closed as EOL if it remains open with a Fedora 'version' of '19'. Package Maintainer: If you wish for this bug to remain open because you plan to fix it in a currently maintained version, simply change the 'version' to a later Fedora version. Thank you for reporting this issue and we are sorry that we were not able to fix it before Fedora 19 is end of life. If you would still like to see this bug fixed and are able to reproduce it against a later version of Fedora, you are encouraged change the 'version' to a later Fedora version prior this bug is closed as described in the policy above. Although we aim to fix as many bugs as possible during every release's lifetime, sometimes those efforts are overtaken by events. Often a more recent Fedora release includes newer upstream software that fixes bugs or makes them obsolete.
Fedora 19 changed to end-of-life (EOL) status on 2015-01-06. Fedora 19 is no longer maintained, which means that it will not receive any further security or bug fix updates. As a result we are closing this bug. If you can reproduce this bug against a currently maintained version of Fedora please feel free to reopen this bug against that version. If you are unable to reopen this bug, please file a new report against the current release. If you experience problems, please add a comment to this bug. Thank you for reporting this bug and we are sorry it could not be fixed.
Different formats are caused by different producers of the logs. It would be also nice to have it all on one place. Meaning to print all messages either by bash side or python side. It would be much better maintainable. And also changing the journalling background would not cause change of messages format.
This bug appears to have been reported against 'rawhide' during the Fedora 23 development cycle. Changing version to '23'. (As we did not run this process for some time, it could affect also pre-Fedora 23 development cycle bugs. We are very sorry. It will help us with cleanup during Fedora 23 End Of Life. Thank you.) More information and reason for this action is here: https://fedoraproject.org/wiki/BugZappers/HouseKeeping/Fedora23
This message is a reminder that Fedora 23 is nearing its end of life. Approximately 4 (four) weeks from now Fedora will stop maintaining and issuing updates for Fedora 23. It is Fedora's policy to close all bug reports from releases that are no longer maintained. At that time this bug will be closed as EOL if it remains open with a Fedora 'version' of '23'. Package Maintainer: If you wish for this bug to remain open because you plan to fix it in a currently maintained version, simply change the 'version' to a later Fedora version. Thank you for reporting this issue and we are sorry that we were not able to fix it before Fedora 23 is end of life. If you would still like to see this bug fixed and are able to reproduce it against a later version of Fedora, you are encouraged change the 'version' to a later Fedora version prior this bug is closed as described in the policy above. Although we aim to fix as many bugs as possible during every release's lifetime, sometimes those efforts are overtaken by events. Often a more recent Fedora release includes newer upstream software that fixes bugs or makes them obsolete.
This bug appears to have been reported against 'rawhide' during the Fedora 26 development cycle. Changing version to '26'.