Hide string from logs in type_string when using secret=1 #2054

jlausuch · 2022-05-12T13:08:46Z

Background: #2002

This PR is printing $string on the logs regardless if it's a secret or not.

https://progress.opensuse.org/issues/111010

This should avoid things like

[2022-05-12T15:59:08.330771+02:00] [debug] tests/jeos/firstrun.pm:116 called testapi::type_password
[2022-05-12T15:59:08.331044+02:00] [debug] <<< testapi::type_string(string="nots3cr3t", max_interval=100, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47, secret=1)

github-actions · 2022-05-12T13:09:03Z

Great PR! Please pay attention to the following items before merging:

Files matching testapi.pm:

Consider bumping the version number in OpenQA/Isotovideo/Interface.pm for changes in behaviour

This is an automatically generated QA checklist based on modified files

codecov · 2022-05-12T13:20:12Z

Codecov Report

Merging #2054 (187b99b) into master (28ee862) will not change coverage.
The diff coverage is 100.00%.

@@           Coverage Diff           @@
##           master    #2054   +/-   ##
=======================================
  Coverage   79.84%   79.84%           
=======================================
  Files          70       70           
  Lines        7292     7292           
=======================================
  Hits         5822     5822           
  Misses       1470     1470

Impacted Files	Coverage Δ
bmwqemu.pm	`100.00% <100.00%> (ø)`
testapi.pm	`64.07% <100.00%> (ø)`

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 28ee862...187b99b. Read the comment docs.

Martchus

It would be nice to extend unit tests but it looks generally good.

jlausuch · 2022-05-12T14:00:34Z

It would be nice to extend unit tests but it looks generally good.

Actually there are plenty of UT for type_string and type_password, I wonder why this wasn't caught before...

jlausuch · 2022-05-12T14:06:46Z

@asmorodskyi @okurz ^

bmwqemu.pm

cfconrad · 2022-05-12T14:41:03Z

bmwqemu.pm

        while (my ($key, $value) = splice(@args, 0, 2)) {
            if ($key =~ tr/0-9a-zA-Z_//c) {
                # only quote if needed
                $key = pp($key);
            }
-            $value = "[masked]" if ($key eq 'text' && $should_hide);


I would suggest not doing this here. This is something which should be done inside the caller.

But if we wanna keep it. it looks better then before 👍 .

hm, I didn't checked all log_call() calles. There might be some who use text as the key for secret value!
As I say, this is just bad code and should not be done in this function!

Why would you want to handle that in the caller and not here?

It was originally changed here: https://github.com/os-autoinst/os-autoinst/pull/2002/files#diff-3420c7e01f73caee7d97053af39990e3297daf42d06e0fc8848f78af1a5e009eL1464
and it was accepted, I'm just correcting it

Why would you want to handle that in the caller and not here?

Imagine code like this:

sub setup_secret { my (%args) = @_; bmwqemu::log_call(@_, secret => 1); my $my_super_secret_password_is = $args{psk}; }

I understand the log_call() function in that way, that it log parameters which are given. And there is just no format of them.

A workaround for me could be something like:

sub setup_secret { my (%args) = @_; bmwqemu::log_call(@_, -mask => ['psk']); my $my_super_secret_password_is = $args{psk}; }

And hope that no one will use -mask as parameters for the calling function :).

I am not exactly sure I understand your implementation proposal but it sounds like a better approach to explicitly pass a secret string around in an explicitly called variable rather than passing a string or text around and relying on an additional boolean variable to be correctly evaluated

I am not exactly sure I understand your implementation proposal but it sounds like a better approach to explicitly pass a secret string around in an explicitly called variable rather than passing a string or text around and relying on an additional boolean variable to be correctly evaluated

Is this a question for me?

My comment was a response to @cfconrad. That implicitly includes a suggestion to you that you could try to implement it like that, if you can :)

Agreed with @cfconrad that he will provide a PR with his implementation so we can compare better an decide what works better for us.

here are my 5cent of this: #2062

cfconrad · 2022-05-12T14:42:54Z

testapi.pm

    bmwqemu::log_call(string => $string, max_interval => $max_interval, wait_screen_changes => $wait, wait_still_screen => $wait_still,
-        timeout => $wait_timeout, similarity_level => $wait_sim_level);
+        timeout => $wait_timeout, similarity_level => $wait_sim_level, secret => $args{secret});


Suggested change

bmwqemu::log_call(string => $string, max_interval => $max_interval, wait_screen_changes => $wait, wait_still_screen => $wait_still,

timeout => $wait_timeout, similarity_level => $wait_sim_level);

timeout => $wait_timeout, similarity_level => $wait_sim_level, secret => $args{secret});

bmwqemu::log_call(string => ($args{secret}?'[masked]' : $string), max_interval => $max_interval, wait_screen_changes => $wait, wait_still_screen => $wait_still,

timeout => $wait_timeout, similarity_level => $wait_sim_level);

please don't repeat the logic again which should already be handled within bmwqemu.

Either we put the logic here or bmwqemu. I don't know which place is better.. so, I'm gonna think loud...

The good thing of having it here would be that we don't need to care about text|string in log_call(), but the problem is if we call log_call from some other place than here is that we don't have the ability to hide a secret.

So, if we keep this logic in bmwqemu, we make sure that any call to log_call with secret => 1 will be hidden, which is probably better..

okurz

The good thing about our tests is that they show an effect of your change. See https://github.com/os-autoinst/os-autoinst/runs/6407456296?check_suite_focus=true#step:3:637

7: 
7:     #   Failed test 'log_call hides sensitive info'
7:     #   at ./12-bmwqemu.t line 68.
7:     # STDERR:
7:     # [2022-05-12T14:10:27.956610Z] [debug] <<< main::log_call_test_secret(text="passwd\n", secret=1)
7:     # 
7:     # doesn't match:
7:     # (?^u:\<\<\<\ main\:\:log_call_test_secret\(text\=\"\[masked\]\"\,\ secret\=1\))
7:     # as expected
7:     # Looks like you failed 1 test of 5.
7: 
7: #   Failed test 'log_call'
7: #   at ./12-bmwqemu.t line 69.

To reproduce you should be able to simply call prove -I. t/12-bmwqemu.t, then extend the test according to your expectations.

Likely you want to extend t/03-testapi.t if bmwqemu.pm itself is behaving fine but calling log_call incorrectly.

okurz · 2022-05-12T15:00:55Z

bmwqemu.pm

        while (my ($key, $value) = splice(@args, 0, 2)) {
            if ($key =~ tr/0-9a-zA-Z_//c) {
                # only quote if needed
                $key = pp($key);
            }
-            $value = "[masked]" if ($key eq 'text' && $should_hide);


Why would you want to handle that in the caller and not here?

okurz · 2022-05-12T15:00:59Z

testapi.pm

    bmwqemu::log_call(string => $string, max_interval => $max_interval, wait_screen_changes => $wait, wait_still_screen => $wait_still,
-        timeout => $wait_timeout, similarity_level => $wait_sim_level);
+        timeout => $wait_timeout, similarity_level => $wait_sim_level, secret => $args{secret});


please don't repeat the logic again which should already be handled within bmwqemu.

asmorodskyi · 2022-05-12T15:25:52Z

is someone understands why #2002 stop working ? because I remember that it was certainly hiding secrets just after #2002 . From changes which Jose is doing I am suspecting that parameter which holding what we actually typing was renamed from "string" to "text" is that the case ?

asmorodskyi · 2022-05-12T15:27:14Z

I think it is important to not only understand how to fix this but also why we doing this second time ...

jlausuch · 2022-05-12T17:27:11Z

The good thing about our tests is that they show an effect of your change. See https://github.com/os-autoinst/os-autoinst/runs/6407456296?check_suite_focus=true#step:3:637
7: 
7:     #   Failed test 'log_call hides sensitive info'
7:     #   at ./12-bmwqemu.t line 68.
7:     # STDERR:
7:     # [2022-05-12T14:10:27.956610Z] [debug] <<< main::log_call_test_secret(text="passwd\n", secret=1)
7:     # 
7:     # doesn't match:
7:     # (?^u:\<\<\<\ main\:\:log_call_test_secret$text\=\"\[masked\]\"\,\ secret\=1$)
7:     # as expected
7:     # Looks like you failed 1 test of 5.
7: 
7: #   Failed test 'log_call'
7: #   at ./12-bmwqemu.t line 69.
To reproduce you should be able to simply call prove -I. t/12-bmwqemu.t, then extend the test according to your expectations.

Likely you want to extend t/03-testapi.t if bmwqemu.pm itself is behaving fine but calling log_call incorrectly.

jlausuch · 2022-05-12T17:30:18Z

is someone understands why #2002 stop working ? because I remember that it was certainly hiding secrets just after #2002 . From changes which Jose is doing I am suspecting that parameter which holding what we actually typing was renamed from "string" to "text" is that the case ?

The funny thing is that the only place where we are passing text as parameter is from the UT... The rest of the places use string as the parameter name. For instance, type_password use string :

type_string $string, secret => 1, max_interval => ($args{max_interval} // 100), %args;

and I would say this is the most sensitive case where we should consider... I have added a regex for text|string in log_call... so we handle both parameters...

Background: os-autoinst#2002 This PR is printing $string on the logs regardless if it's a secret or not.

jlausuch · 2022-05-12T17:56:22Z

BTW, if type_password is used with serial_terminal, the string will be printed in serial_terminal.txt anyway, so this method should be used only with root-console. Cause I guess there is no workaround for that case

    if (is_serial_terminal) {
        query_isotovideo('backend_type_string', {text => $string, %args});
        return;
    }

asmorodskyi · 2022-05-12T19:32:16Z

BTW, if type_password is used with serial_terminal, the string will be printed in serial_terminal.txt anyway, so this method should be used only with root-console. Cause I guess there is no workaround for that case

you can not state this , for example when you really entering password it won't be displayed . e.g

#sudo -s                                                                                           
[sudo] password for root:

asmorodskyi · 2022-05-12T19:37:59Z

is someone understands why #2002 stop working ? because I remember that it was certainly hiding secrets just after #2002 . From changes which Jose is doing I am suspecting that parameter which holding what we actually typing was renamed from "string" to "text" is that the case ?

The funny thing is that the only place where we are passing text as parameter is from the UT... The rest of the places use string as the parameter name. For instance, type_password use string :
type_string $string, secret => 1, max_interval => ($args{max_interval} // 100), %args;
and I would say this is the most sensitive case where we should consider... I have added a regex for text|string in log_call... so we handle both parameters...

if this is the case than I would assume single line https://github.com/os-autoinst/os-autoinst/pull/2054/files#diff-443ffbdc622ec9236041884826df475d69e3fa8ce40ec03c043c3ba66fae921bR222 would do the job and fix the problem . All other changes which comes together is a refactoring of existing approach and IMHO very questionable one . I really like initial approach suggested by Yannis the only missing piece in it is the fact that we have not only "text" but also "string" ...

jlausuch · 2022-05-12T19:46:54Z

is someone understands why #2002 stop working ? because I remember that it was certainly hiding secrets just after #2002 . From changes which Jose is doing I am suspecting that parameter which holding what we actually typing was renamed from "string" to "text" is that the case ?

The funny thing is that the only place where we are passing text as parameter is from the UT... The rest of the places use string as the parameter name. For instance, type_password use string :
type_string $string, secret => 1, max_interval => ($args{max_interval} // 100), %args;
and I would say this is the most sensitive case where we should consider... I have added a regex for text|string in log_call... so we handle both parameters...
if this is the case than I would assume single line https://github.com/os-autoinst/os-autoinst/pull/2054/files#diff-443ffbdc622ec9236041884826df475d69e3fa8ce40ec03c043c3ba66fae921bR222 would do the job and fix the problem . All other changes which comes together is a refactoring of existing approach and IMHO very questionable one . I really like initial approach suggested by Yannis the only missing piece in it is the fact that we have not only "text" but also "string" ...

Not only that.
In Yannis approach, secret was never an argument to log_call, so the condition he had here was never hit, because type_string was never passing any parameter secret to it. This is what I'm trying to solve here.

jlausuch · 2022-05-12T19:48:33Z

BTW, if type_password is used with serial_terminal, the string will be printed in serial_terminal.txt anyway, so this method should be used only with root-console. Cause I guess there is no workaround for that case

you can not state this , for example when you really entering password it won't be displayed . e.g
#sudo -s                                                                                           
[sudo] password for root: 

yes, you are right, it was some misunderstanding of mine, please ignore this comment :)

asmorodskyi · 2022-05-12T20:14:44Z

is someone understands why #2002 stop working ? because I remember that it was certainly hiding secrets just after #2002 . From changes which Jose is doing I am suspecting that parameter which holding what we actually typing was renamed from "string" to "text" is that the case ?

The funny thing is that the only place where we are passing text as parameter is from the UT... The rest of the places use string as the parameter name. For instance, type_password use string :
type_string $string, secret => 1, max_interval => ($args{max_interval} // 100), %args;
and I would say this is the most sensitive case where we should consider... I have added a regex for text|string in log_call... so we handle both parameters...
if this is the case than I would assume single line https://github.com/os-autoinst/os-autoinst/pull/2054/files#diff-443ffbdc622ec9236041884826df475d69e3fa8ce40ec03c043c3ba66fae921bR222 would do the job and fix the problem . All other changes which comes together is a refactoring of existing approach and IMHO very questionable one . I really like initial approach suggested by Yannis the only missing piece in it is the fact that we have not only "text" but also "string" ...
Not only that. In Yannis approach, secret was never an argument to log_call, so the condition he had here was never hit, because type_string was never passing any parameter secret to it. This is what I'm trying to solve here.

than how it is working here https://openqa.suse.de/tests/8736413/logfile?filename=autoinst-log.txt ? ( if you look for [maksed] you will find all occasions of define_secret_variable calls which calling type_password )

jlausuch · 2022-05-13T06:47:37Z

than how it is working here https://openqa.suse.de/tests/8736413/logfile?filename=autoinst-log.txt ? ( if you look for [maksed] you will find all occasions of define_secret_variable calls which calling type_password )

Right. I don't know. But take a look here:

https://openqa.suse.de/tests/8405529/logfile?filename=autoinst-log.txt (2 months ago)

[2022-03-26T12:33:40.095557+01:00] [debug] tests/jeos/firstrun.pm:116 called testapi::type_password
[2022-03-26T12:33:40.095850+01:00] [debug] <<< testapi::type_string(string="SECRET STRING", max_interval=100, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)

https://openqa.suse.de/tests/8738443/logfile?filename=autoinst-log.txt (recent)

[2022-05-12T06:09:58.666172+02:00] [debug] tests/jeos/firstrun.pm:116 called testapi::type_password
[2022-05-12T06:09:58.666561+02:00] [debug] <<< testapi::type_string(string="nots3cr3t", max_interval=100, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)

asmorodskyi · 2022-05-13T07:36:50Z

I don't like that we don't have clear understanding what is going on but trying to "fix" something. You showing me place where password is exposed and I showing another where it is hidden without understanding why it happening like this there is no way to say if your patch make sense or not . I was looking closer into "my" "positive case " and it looks really strange , there is NO logging of type_password at all :

[2022-05-12T01:01:24.032685+02:00] [debug] <<< consoles::serial_screen::type_string(text="read -sp \"enter value: \" ARM_SUBSCRIPTION_ID", cmd="backend_type_string", json_cmd_token="wottTNYz")
[2022-05-12T01:01:24.032970+02:00] [debug] tests/publiccloud/prepare_instance.pm:68 called publiccloud::basetest::provider_factory -> lib/publiccloud/basetest.pm:99 called publiccloud::azure::init -> lib/publiccloud/azure.pm:29 called publiccloud::azure_client::init -> lib/publiccloud/azure_client.pm:31 called publiccloud::utils::define_secret_variable -> lib/publiccloud/utils.pm:208 called testapi::script_run
[2022-05-12T01:01:24.033092+02:00] [debug] <<< testapi::send_key(key="ret", wait_screen_change=0, do_wait=0)
[2022-05-12T01:01:24.033569+02:00] [debug] <<< consoles::serial_screen::type_string(key="ret", text="\n", json_cmd_token="KbwqPoRP", cmd="backend_send_key")
[2022-05-12T01:01:24.034206+02:00] [debug] <<< consoles::serial_screen::type_string(max_interval=100, secret=1, text="[masked]", cmd="backend_type_string", json_cmd_token="BfskvBUj")
[2022-05-12T01:01:24.034495+02:00] [debug] tests/publiccloud/prepare_instance.pm:68 called publiccloud::basetest::provider_factory -> lib/publiccloud/basetest.pm:99 called publiccloud::azure::init -> lib/publiccloud/azure.pm:29 called publiccloud::azure_client::init -> lib/publiccloud/azure_client.pm:31 called publiccloud::utils::define_secret_variable -> lib/publiccloud/utils.pm:210 called testapi::script_run
[2022-05-12T01:01:24.034650+02:00] [debug] <<< testapi::script_run(cmd="set +a", timeout=30, quiet=undef, output="", die_on_timeout=1)
[2022-05-12T01:01:24.034809+02:00] [debug] tests/publiccloud/prepare_instance.pm:68 called publiccloud::basetest::provider_factory -> lib/publiccloud/basetest.pm:99 called publiccloud::azure::init -> lib/publiccloud/azure.pm:29 called publiccloud::azure_client::init -> lib/publiccloud/azure_client.pm:31 called publiccloud::utils::define_secret_variable -> lib/publiccloud/utils.pm:210 called testapi::script_run
[2022-05-12T01:01:24.034966+02:00] [debug] <<< testapi::wait_serial(regexp="# ", record_output=undef, no_regex=1, expect_not_found=0, buffer_size=undef, timeout=90, quiet=undef)
[2022-05-12T01:01:24.035646+02:00] [debug] <<< consoles::serial_screen::read_until(buffer_size=undef, timeout=90, quiet=undef, regexp="# ", record_output=undef, json_cmd_token="twGmJvzQ", expect_not_found=0, no_regex=1, cmd="backend_wait_serial", pattern=[
    "# "
  ])

type_password is called at line 209 https://github.com/os-autoinst/os-autoinst-distri-opensuse/blob/master/lib/publiccloud/utils.pm#L209 . Only what I notice that I am actually passing password as param and also adding \n at the end which actually not necessary and in all cases where password is exposed function called w/o parameters , but I don't know if it is important or not ...

okurz · 2022-05-13T10:24:16Z

BTW, if type_password is used with serial_terminal, the string will be printed in serial_terminal.txt anyway, so this method should be used only with root-console. Cause I guess there is no workaround for that case

you can not state this , for example when you really entering password it won't be displayed . e.g
#sudo -s                                                                                           
[sudo] password for root: 

Correct. Same as for the case of VNC consoles: If you use type_password to type the password literally into a shell prompt then the password will be visible in the screenshot.

mergify · 2022-05-19T06:49:38Z

This pull request is now in conflicts. Could you fix it? 🙏

okurz · 2022-05-19T06:50:22Z

#2062 should replace this. Please bring in new changes with tests in case something is still missing

jlausuch marked this pull request as draft May 12, 2022 13:10

jlausuch force-pushed the type_string_hide_secret branch from fbd149e to 9f30edd Compare May 12, 2022 13:14

Martchus reviewed May 12, 2022

View reviewed changes

jlausuch force-pushed the type_string_hide_secret branch from 9f30edd to 2c6114a Compare May 12, 2022 13:58

jlausuch force-pushed the type_string_hide_secret branch 2 times, most recently from cecf1c5 to 8aa9ce2 Compare May 12, 2022 14:06

jlausuch marked this pull request as ready for review May 12, 2022 14:06

cfconrad reviewed May 12, 2022

View reviewed changes

bmwqemu.pm Show resolved Hide resolved

cfconrad reviewed May 12, 2022

View reviewed changes

okurz requested changes May 12, 2022

View reviewed changes

jlausuch force-pushed the type_string_hide_secret branch from 8aa9ce2 to 182c12e Compare May 12, 2022 17:26

jlausuch closed this May 12, 2022

jlausuch reopened this May 12, 2022

Hide string from logs in type_string when using secret=1

187b99b

Background: os-autoinst#2002 This PR is printing $string on the logs regardless if it's a secret or not.

jlausuch force-pushed the type_string_hide_secret branch from 182c12e to 187b99b Compare May 12, 2022 17:36

cfconrad mentioned this pull request May 18, 2022

bmwqemu: Hide secrets on log output with log_call() #2062

Merged

okurz closed this May 19, 2022

okurz mentioned this pull request Jul 7, 2022

Prevent passwords leaked to log by redundant log-message #2110

Merged

Hide string from logs in type_string when using secret=1 #2054

Hide string from logs in type_string when using secret=1 #2054

Conversation

jlausuch commented May 12, 2022 • edited

github-actions bot commented May 12, 2022

codecov bot commented May 12, 2022 • edited

Codecov Report

Martchus left a comment

Choose a reason for hiding this comment

jlausuch commented May 12, 2022

jlausuch commented May 12, 2022

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

cfconrad May 12, 2022 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

okurz left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

asmorodskyi commented May 12, 2022 • edited

asmorodskyi commented May 12, 2022

jlausuch commented May 12, 2022

jlausuch commented May 12, 2022

jlausuch commented May 12, 2022

asmorodskyi commented May 12, 2022

asmorodskyi commented May 12, 2022

jlausuch commented May 12, 2022 • edited

jlausuch commented May 12, 2022

asmorodskyi commented May 12, 2022

jlausuch commented May 13, 2022

asmorodskyi commented May 13, 2022

okurz commented May 13, 2022

mergify bot commented May 19, 2022

okurz commented May 19, 2022

jlausuch commented May 12, 2022 •

edited

codecov bot commented May 12, 2022 •

edited

cfconrad May 12, 2022 •

edited

asmorodskyi commented May 12, 2022 •

edited

jlausuch commented May 12, 2022 •

edited