Bugzilla will be upgraded to version 5.0 on a still to be determined date in the near future. The original upgrade date has been delayed.
Bug 972648 - [RFE] Prefix log/assert messages called from beakerlib libraries
[RFE] Prefix log/assert messages called from beakerlib libraries
Product: Fedora
Classification: Fedora
Component: beakerlib (Show other bugs)
Unspecified Unspecified
low Severity unspecified
: ---
: ---
Assigned To: Dalibor Pospíšil
Fedora Extras Quality Assurance
Project: Easy
Depends On:
Blocks: 1208577
  Show dependency treegraph
Reported: 2013-06-10 06:35 EDT by David Kutálek
Modified: 2018-01-29 18:53 EST (History)
5 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Last Closed:
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---

Attachments (Terms of Use)

  None (edit)
Description David Kutálek 2013-06-10 06:35:43 EDT
Description of problem:

Beakerlib libraries started to emerge and I noticed that sometimes it can be confusing when library user calls its function, which generates bunch of logs / asserts, without notice that these logs/asserts are called from that function. Example:

        rlRun "postgresqlDropDB test"


:: [   FAIL   ] :: Running 'postgresqlQuery template1 'DROP DATABASE \\\"test\\\";'' (Expected 0, got 127)
:: [   FAIL   ] :: Running 'postgresqlDropDB test' (Expected 0, got 127)

When I created my own library, I implemented prefixing to be more readable:



:: [   PASS   ] :: phpMainPackage: php_RPM=php53
:: [   PASS   ] :: phpMainPackage: php_INI=/etc/php.ini
:: [   PASS   ] :: phpMainPackage: php_MOD_PHP_CONF=/etc/httpd/conf.d/php.conf

So that user see instantly what asserts are produced by which library function.

We could left such a rule as a best practice, but I would like to discuss an automated way in this bug.

In Bash, it is possible to use FUNCNAME and BASH_SOURCE variables to create prefixes automatically. 

A simple rule could be to display only first library function frame, if it is from lib.sh:

( (${BASH_SOURCE[1]} =~ '^.*/lib.sh$') || (${BASH_SOURCE[1]} =~ '^lib.sh$') ) && \
    local prefix="${FUNCNAME[1]}: " 

Which means more depth won't be tracked, but imho it is not common to call (public) library functions another library function. But of course, more depth levels could be provided if needed.

Do you like such idea? 

Should this behaviour be on by default, or switched on somehow when needed?
Comment 1 David Kutálek 2013-06-10 06:45:43 EDT
Please note that the code above for prefix setting is over simplified and not completely correct. In fact, BASH_SOURCE array have to be iterated to find out first possible lib.sh occurrence.
Comment 2 Lukas Zachar 2013-06-10 09:59:33 EDT
I like the idea, but I would like to see the real library owner in the output, in other words to respect nested library calls.

You usually want to know the details about failed assert so the knowledge of the top library will not help you that much. 

It is true that nested calls are not that common (yet) but I think some wrapper library to get apache+mariadb+php server running might become valid use case. 

IMHO journal could add the closest function name to the log in the format same in the description, based on some control envar. If this envar is switched on by first (any) rlImport call, the consequent logs will get the full report format. 
If one want to get the full format for logs before rlImport it should be enough to set the variable manually.
Comment 3 Jakub Prokes 2013-09-30 10:33:38 EDT
I added to my library some prefixing long time ago. I'm interesting for your opinion about form of prefixing because my implementation show all stack for a given assert.

:: [   PASS   ] :: postgresqlUDB->rlRun->postgresqlCreateDB: Internal assert (Expected 0, got 0)
:: [   PASS   ] :: postgresqlUDB: Internal assert (Expected 0, got 0)
:: [   PASS   ] :: postgresqlUDB->rlRun->postgresqlAddUser: Internal assert (Expected 0, got 0)
:: [   PASS   ] :: postgresqlUDB: Internal assert (Expected 0, got 0)
:: [   PASS   ] :: postgresqlUDB: Internal assert (Expected 0, got 0)

I'm open to suggestions.
Comment 4 Petr Muller 2013-09-30 11:15:30 EDT
I like the full stack approach
Comment 5 David Kutálek 2013-10-07 09:31:11 EDT
Me too
Comment 6 Fedora Admin XMLRPC Client 2014-09-02 08:13:38 EDT
This package has changed ownership in the Fedora Package Database.  Reassigning to the new owner of this component.
Comment 7 Dalibor Pospíšil 2014-09-02 10:59:45 EDT
The full stack is nice but I would prefer it only in DEBUG mode.

Currently beakerlib since v1.9-3 produces something like:

# rlRun "postgresqlDropDB test"


:: [  BEGIN   ] :: Running 'postgresqlDropDB test' (Expected 0, got 127)
:: [   FAIL   ] :: Running 'postgresqlQuery template1 'DROP DATABASE \\\"test\\\";'' (Expected 0, got 127)
:: [   FAIL   ] :: Command 'postgresqlDropDB test' (Expected 0, got 127)

With tcfRun from library library(distribution/tcf) you can get

:: [  BEGIN   ] :: Running 'postgresqlDropDB test' (Expected 0, got 127)
:: [   FAIL   ] ::   Running 'postgresqlQuery template1 'DROP DATABASE \\\"test\\\";'' (Expected 0, got 127)
:: [   FAIL   ] :: Running 'postgresqlDropDB test' (Expected 0, got 127)

Sometimes the stack can be really big and I think it could produce very long lines so the orientation would be again hard.

If we do not print all stack how would we handle nested calls though more libraries?
Comment 8 Jakub Prokes 2015-04-02 13:19:01 EDT
We decided to not change default behaviour but add this kind of logging conditionally on some configuration.

I'm adding this bug ass blocker to tracking bug where we can discus format of enabling these features.

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