Display variable content in log file that are passed to a keyword as argument

[Heiko Thiery]

Hi,

is there an easy way to show the content of a variable that is passed to a keyword as argument. Currently i have to open the log hirachy until i find a keyword that does an ouput where i can see the content of the variable.

Example output in the log: Telnet.Open Connection ${serialHost}, port=${serialPort}

Increasing the loglevel to TRACE isnt a good way, because the log file will explode.

Any hints?

BR,

Heiko

[Tatu Aalto]

Sorry for the spam, did forget press Reply all button

-Tatu

---------- Forwarded message ----------
From: Tatu Aalto <aalto...@gmail.com>
Date: Tue, Nov 4, 2014 at 10:50 PM
Subject: Re: Display variable content in log file that are passed to a keyword as argument
To: heiko....@gmail.com

Ugh

Well, it depends. Where you would like to see the variable and would you like to see the variable(s) from all keywords or just some one keyword. Perhaps if you describe your problem and your needs more accurately we could point you in the right direction.

But in my opinion, increasing the log level to TRACE is the most easiest option. It is true that log size will increase on TRACE level and size of the log was a big problem before the 2.6 release [1]. But after that release the log size should not be a problem, I did have tests that did take +12h to complete and the size of the log was not problem (nor was the really long for loop) after the 2.6 release.

In practice, I always run my test with TRACE level, because when error is found, finding the root cause of the problem from log is just more easier. 

-Tatu

[1] https://code.google.com/p/robotframework/wiki/ReleaseNotes26#Most_important_enhancements_and_new_features

--
You received this message because you are subscribed to the Google Groups "robotframework-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to robotframework-u...@googlegroups.com.
To post to this group, send email to robotframe...@googlegroups.com.
Visit this group at http://groups.google.com/group/robotframework-users.
For more options, visit https://groups.google.com/d/optout.

[Tatu Aalto]

Ugh

Did forget to mention that you can control loglevel dynamically during the test execution by Set Log Level [1] keyword.

-Tatu
Send from my mobile
[1] http://robotframework.org/robotframework/latest/libraries/BuiltIn.html#Set%20Log%20Level

[Jussi Malinen]

Besides the solutions Tatu proposed, you can also implement a listener that listens to start_keyword(name, attrs) and log_message(message) events. The start_keyword is called always before keyword call and the attrs contains the arguments. The variables are not yet expanded there though. But I think always the first log_message -call after start_keyword is the TRACE level message containing the expanded variables.

So you could implement a listener that uses the logging api to relog with loglevel INFO the first TRACE message after start_keyword.

Here more about listereners: http://robotframework.org/robotframework/latest/RobotFrameworkUserGuide.html#using-listener-interface

- Jussi

[Heiko Thiery]

Hi,

thanks for your responses. I hoped to find a solution that prints the variable values in the standard log ouput of robot. As I mentioned I have to open the log until the variable is expanded somewhere deeper.

Maybe it is possible to extend the log generation to have an output like:

"Keyword  ${argument1=value1}  ${argument2=value2}"

Or add an extra option to rebot to do this. E.g. "--expandvariables"

What do you think about that?

BR,

Heiko

[Pekka Klärck]

2014-11-04 22:52 GMT+02:00 Tatu Aalto <aalto...@gmail.com>:
>
> But in my opinion, increasing the log level to TRACE is the most easiest
> option. It is true that log size will increase on TRACE level and size of
> the log was a big problem before the 2.6 release [1]. But after that release
> the log size should not be a problem

Log size can still be a problem on TRACE level. For example, if you
read a massive file into a variable like

${content} = Get File ${path}

the value of ${content} will still be big in the current logs. This is
the main reason variable values are not shown by default.

My general recommendation is not to run tests using TRACE by default.
Even if the aforementioned problem wouldn't be an issue now, log file
size can cause problems in the future and the log level must be
raised. Dealing that situation can be hard if no care has been taken
to log values when needed earlier. Anyway, this is just my general
recommendation and definitely does not apply to all context.

My general recommendation how to handle logging variable values is this:

- Library keywords should logs values themselves using INFO or DEBUG
level, unless there's a change a value is big. For example,
Selenium(2)Library logs messages like `Typing text 'foo' into text
field 'example'.

- If library keywords don't log values themselves, user keywords using
them can easily do that using `Log` or `Log Many` keywords.

- If a certain value is important to see during execution, keywords
can log it to console. Library keywords can use `robot.api.logger` or
`sys.__stdout__.write` for that purpose, and user keywords can use
`Log To Console` or `Log` with `console=yes`.

- If a certain value is important to easily see after execution,
keywords can dynamically add it to test message or documentation.
There are `Set Test Message` and `Set Test Documentation` keywords for
this purpose. Library keywords can use them by using `BuiltIn`
programmatically.

Cheers,
.peke
--
Agile Tester/Developer/Consultant :: http://eliga.fi
Lead Developer of Robot Framework :: http://robotframework.org

[Pekka Klärck]

2014-11-05 9:57 GMT+02:00 Heiko Thiery <heiko....@gmail.com>:
> Hi,
>
> thanks for your responses. I hoped to find a solution that prints the
> variable values in the standard log ouput of robot. As I mentioned I have to
> open the log until the variable is expanded somewhere deeper.
>
> Maybe it is possible to extend the log generation to have an output like:
> "Keyword ${argument1=value1} ${argument2=value2}"

This is definitely not a suitable default because your values can be
both huge and totally uninteresting. Consider seeing, for example, a
few gigabyte disk image there.

> Or add an extra option to rebot to do this. E.g. "--expandvariables"

What benefits would this bring compared to the current `--loglevel TRACE`?

[Heiko Thiery]

> What benefits would this bring compared to the current `--loglevel TRACE`?

In my opinion the main benefit would be to see the values that are delivered into the keyword at the same line in the log.

When enabling TRACE currently the log shows the values at the bottom of the output when unfold the keyword in the log. That means in case I'm interested in the variable content I have to scroll down (sometimes) several screens to see this information.

e.g. 

Keyword1  ${variable}

  Another Keyword2

  Another Keyword3

  Another Keyword4

   :

  Another Keyword1000

  Arguments: [ ${variable}=u'testvalue' ]

[Pekka Klärck]

2014-11-05 11:31 GMT+02:00 Heiko Thiery <heiko....@gmail.com>:
>> What benefits would this bring compared to the current `--loglevel TRACE`?
>
> In my opinion the main benefit would be to see the values that are delivered
> into the keyword at the same line in the log.

It's true that you wouldn't need to open that keyword, but I don't
think that's a big enough benefit to warrant a new command line
option.

> When enabling TRACE currently the log shows the values at the bottom of the
> output when unfold the keyword in the log. That means in case I'm interested
> in the variable content I have to scroll down (sometimes) several screens to
> see this information.
>
> e.g.
>
> Keyword1 ${variable}
> Another Keyword2
> Another Keyword3
> Another Keyword4
> :
> Another Keyword1000
>
> Arguments: [ ${variable}=u'testvalue' ]

It is generally a problem that all log messages of a keyword are
listed after all keywords that it executes internally. It would be
much better to show log messages and keywords in the order they
actually occurred, in which case the `Arguments:` line above would be
first. This is something I'd like to see fixed but I know it's not
trivial. Anyone interested to take a look?

[Michael Walle]

Am 2014-11-05 10:11, schrieb Pekka Klärck:
> 2014-11-05 9:57 GMT+02:00 Heiko Thiery <heiko....@gmail.com>:
>> Hi,
>>
>> thanks for your responses. I hoped to find a solution that prints the
>> variable values in the standard log ouput of robot. As I mentioned I
>> have to
>> open the log until the variable is expanded somewhere deeper.
>>
>> Maybe it is possible to extend the log generation to have an output
>> like:
>> "Keyword ${argument1=value1} ${argument2=value2}"
>
> This is definitely not a suitable default because your values can be
> both huge and totally uninteresting. Consider seeing, for example, a
> few gigabyte disk image there.

ok understood.

>> Or add an extra option to rebot to do this. E.g. "--expandvariables"
>
> What benefits would this bring compared to the current `--loglevel
> TRACE`?

In our case, we use the TelnetLibrary a lot and, IMO, this library spams
the log with unrelated stuff like "IAC DO" and "IAC DONT" if you enable
trace. So we switched from TRACE to DEBUG but then we don't see the
expansion of the variables anymore.

Therefore, you could consider to make the telnet library a little less
noisy if trace is enabled.

Your TelnetConnection which is a subclass of telnetlib.Telnet overwrites
the msg() method with the following:

def msg(self, msg, *args):
# Forward telnetlib's debug messages to log
logger.trace(msg % args)

and the Telnet class do the logging of the "IAC DO" and "IAC DONT".

Maybe we can introduce a runtime switch which can disable this
forwarding. Something like a "Enable/Disable Log Forwarding" in the
Telnet library.

-michael

[Pekka Klärck]

2014-11-05 12:30 GMT+02:00 Michael Walle <mic...@walle.cc>:
>
> In our case, we use the TelnetLibrary a lot and, IMO, this library spams the
> log with unrelated stuff like "IAC DO" and "IAC DONT" if you enable trace.
> So we switched from TRACE to DEBUG but then we don't see the expansion of
> the variables anymore.
>
> Therefore, you could consider to make the telnet library a little less noisy
> if trace is enabled.
>
> Your TelnetConnection which is a subclass of telnetlib.Telnet overwrites the
> msg() method with the following:
>
> def msg(self, msg, *args):
> # Forward telnetlib's debug messages to log
> logger.trace(msg % args)
>
> and the Telnet class do the logging of the "IAC DO" and "IAC DONT".

Yep, this functionality was added somewhat recently to make lower
level stuff visible in logs if needed.

> Maybe we can introduce a runtime switch which can disable this forwarding.
> Something like a "Enable/Disable Log Forwarding" in the Telnet library.

Sure, that can be made configurable. I think we though about it when
added this functionality, but decided it wasn't worth the effort.
Instead of enabling/disabling this feature, I'd rather see a way to
configure the log level of these debug messages. Using e.g. `NONE`
could disable debug logging altogether, but I can see being able to
use `DEBUG` or even `INFO` would sometimes be useful too.