Project

General

Profile

Actions

action #29399

closed

Escape function parameter before logging them

Added by nicksinger almost 7 years ago. Updated almost 5 years ago.

Status:
Resolved
Priority:
Normal
Assignee:
Category:
Feature requests
Target version:
Start date:
2017-12-14
Due date:
% Done:

0%

Estimated time:

Description

Observation

While reviewing some jobs, I stumbled over this line in the autoinst-log.txt:

[Thu Dec 14 04:10:45 2017] [12032:debug] <<< testapi::type_string(string='root
', max_interval=250, wait_screen_changes=0, wait_still_screen=0)

The line break after root in the logs is because the parameter of type_string is actually "root\n" in the code.
This is kind of obscure for reviewers that want to know what happened there.

Acceptance criteria

  • AC1: Control characters within command strings within os-autoinst are not evaluated by the logging mechanism

Suggestions

IMHO it would be better if the parameter from type_string gets escaped before printing it to the log so it would show up as this:

[Thu Dec 14 04:10:45 2017] [12032:debug] <<< testapi::type_string(string='root\n', max_interval=250, wait_screen_changes=0, wait_still_screen=0)

This is especially beneficial if the string only consists of one control character (e.g. type_string('\t')).


Related issues 1 (0 open1 closed)

Copied to openQA Project (public) - action #63808: Improve bmwqemu::log_call() function outputResolvedtinita2017-12-14

Actions
Actions #1

Updated by coolo almost 7 years ago

... and it would be aweful for longer commands

Actions #2

Updated by nicksinger almost 7 years ago

artificial line-breaks for readability could always be introduced. Even though I think it's not the job of a log to look pretty but to deliver relevant information fast and understandable.
Does the current logging-code only print "\n" un-escaped? If so, I'd close this ticket again - one can guess line-breaks.

Actions #3

Updated by okurz almost 5 years ago

  • Description updated (diff)
  • Status changed from New to Workable
Actions #4

Updated by tinita almost 5 years ago

  • Status changed from Workable to In Progress
  • Assignee set to tinita
Actions #5

Updated by tinita almost 5 years ago

Created PR https://github.com/os-autoinst/os-autoinst/pull/1322 - Escape parameters in log calls

I added the option Useqq to the Data::Dumper call.

Values will now show with double quotes and all unprintable characters will be escaped.

Actions #6

Updated by tinita almost 5 years ago

There are still other things not escaped, for example this:

[2019-12-12T12:50:38.049 UTC] [debug] <<< distribution::script_output(Content of /tmp/scriptXXX.sh :
"cat > /tmp/scriptXXX.sh << 'EOT_XXX'; echo XXX-$?-" 
=undef)

This might actually be a problem of how log_call is called (with just one argument).
What should happen with those calls?

Actions #7

Updated by tinita almost 5 years ago

  • Status changed from In Progress to Feedback
Actions #8

Updated by okurz almost 5 years ago

  • Target version set to Current Sprint

hm, where does the =undef) on its own line come from?

Actions #9

Updated by tinita almost 5 years ago

That's because log_call is called with only one parameter.
Usually it expects key/value pairs, and only escapes the values.
Here the key is the script content with the newline, and the value is undef.

Actions #10

Updated by okurz almost 5 years ago

sounds like it could be a regression introduced when the parameter parsing for the functions was adapted.

Actions #11

Updated by livdywan almost 5 years ago

  • Status changed from Feedback to Resolved
Actions #12

Updated by tinita almost 5 years ago

The issue itself is resolved, but we should think about making two functions (logging key/value pairs, and logging one string).
Or we check the number of arguments and then do the logging differently.

Actions #13

Updated by tinita almost 5 years ago

  • Copied to action #63808: Improve bmwqemu::log_call() function output added
Actions

Also available in: Atom PDF