Bug 483014 - rlLog* commands log differently to stdout
rlLog* commands log differently to stdout
Status: NEW
Product: Fedora
Classification: Fedora
Component: beakerlib (Show other bugs)
26
All Linux
low Severity medium
: ---
: ---
Assigned To: Dalibor Pospíšil
Fedora Extras Quality Assurance
:
Depends On: bl-journal-overhaul
Blocks: 1250080
  Show dependency treegraph
 
Reported: 2009-01-29 05:51 EST by Petr Šplíchal
Modified: 2017-02-28 04:28 EST (History)
6 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2015-02-18 06:58:27 EST
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)

  None (edit)
Description Petr Šplíchal 2009-01-29 05:51:15 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
Comment 1 Ales Zelinka 2009-12-15 11:51:38 EST
+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.
Comment 2 Jan Hutař 2009-12-16 03:52:43 EST
+1 to unified output on stdout
+1 to timestamps on stdout - useful when debugging failed test
+1 to have timestamps in journal
Comment 3 Martin Cermak 2010-01-11 07:12:52 EST
After consultation with psplichal I'm going to write patch for this issue.
Comment 4 Martin Cermak 2010-01-12 05:18:38 EST
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.
Comment 5 Petr Šplíchal 2010-01-14 06:33:21 EST
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.
Comment 6 Martin Cermak 2010-02-03 10:59:46 EST
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.
Comment 7 Petr Šplíchal 2010-02-04 06:20:42 EST
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.
Comment 8 Martin Cermak 2010-02-09 11:45:02 EST
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::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::"
Comment 9 Petr Muller 2010-10-20 11:39:06 EDT
I'm starting to work on the journal again and I will take care of this too.
Comment 10 James Laska 2012-06-14 08:30:16 EDT
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)?
Comment 12 Fedora End Of Life 2013-04-03 16:12:20 EDT
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
Comment 13 Fedora Admin XMLRPC Client 2014-09-02 08:14:05 EDT
This package has changed ownership in the Fedora Package Database.  Reassigning to the new owner of this component.
Comment 14 Dalibor Pospíšil 2014-09-02 11:27:51 EDT
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.
Comment 15 Fedora End Of Life 2015-01-09 16:38:14 EST
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.
Comment 16 Fedora End Of Life 2015-02-18 06:58:27 EST
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.
Comment 17 Dalibor Pospíšil 2015-06-12 12:56:46 EDT
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.
Comment 18 Jan Kurik 2015-07-15 11:22:22 EDT
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
Comment 20 Fedora End Of Life 2016-11-24 05:23:16 EST
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.
Comment 21 Fedora End Of Life 2017-02-28 04:28:25 EST
This bug appears to have been reported against 'rawhide' during the Fedora 26 development cycle.
Changing version to '26'.

Note You need to log in before you can comment on or make changes to this bug.