Bug 972648

Summary: [RFE] Prefix log/assert messages called from beakerlib libraries
Product: [Fedora] Fedora Reporter: David Kutálek <dkutalek>
Component: beakerlibAssignee: Dalibor Pospíšil <dapospis>
Status: ASSIGNED --- QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: low    
Version: rawhideCC: azelinka, lzachar, mkyral, ohudlick, qa-errata-list
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard: Project: Easy
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 1208577    

Description David Kutálek 2013-06-10 10:35:43 UTC
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"

generates

:: [   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:

        phpMainPackage

generates

:: [   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 10:45:43 UTC
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 Lukáš Zachar 2013-06-10 13:59:33 UTC
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 14:33:38 UTC
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 15:15:30 UTC
I like the full stack approach

Comment 5 David Kutálek 2013-10-07 13:31:11 UTC
Me too

Comment 6 Fedora Admin XMLRPC Client 2014-09-02 12:13:38 UTC
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 14:59:45 UTC
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"

generates

:: [  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 17:19:01 UTC
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.