QA » openQA Project

I checked some workers log message, seems when workers start, there will be this debug message. For example, the worker in openqaworker5 start successfully and without any network issue, also has this message:

Dec 30 06:28:42 openqaworker5 worker[37495]: [2020-12-30T06:28:42.667 CET] [debug] Unable to serialize fatal error: Can't open file "base_state.json": Permis>
Dec 30 06:28:42 openqaworker5 worker[37495]: [info] [pid:37495] worker 2:
Dec 30 06:28:42 openqaworker5 worker[37495]:  - config file:           /etc/openqa/workers.ini
Dec 30 06:28:42 openqaworker5 worker[37495]:  - worker hostname:       openqaworker5
Dec 30 06:28:42 openqaworker5 worker[37495]:  - isotovideo version:    20
Dec 30 06:28:42 openqaworker5 worker[37495]:  - websocket API version: 1
Dec 30 06:28:42 openqaworker5 worker[37495]:  - web UI hosts:          openqa.suse.de
Dec 30 06:28:42 openqaworker5 worker[37495]:  - class:                 qemu_x86_64,qemu_x86_64_staging,tap,openqaworker5
Dec 30 06:28:42 openqaworker5 worker[37495]:  - no cleanup:            no
Dec 30 06:28:42 openqaworker5 worker[37495]:  - pool directory:        /var/lib/openqa/pool/2
Dec 30 06:28:42 openqaworker5 worker[37495]: [info] [pid:37495] CACHE: caching is enabled, setting up /var/lib/openqa/cache/openqa.suse.de
Dec 30 06:28:42 openqaworker5 worker[37495]: [info] [pid:37495] Project dir for host openqa.suse.de is /var/lib/openqa/share
Dec 30 06:28:42 openqaworker5 worker[37495]: [info] [pid:37495] Registering with openQA openqa.suse.de
Dec 30 06:28:42 openqaworker5 worker[37495]: [info] [pid:37495] Establishing ws connection via ws://openqa.suse.de/api/v1/ws/961
Dec 30 06:28:43 openqaworker5 worker[37495]: [info] [pid:37495] Registered and connected via websockets with openQA host openqa.suse.de and worker ID 961
Dec 30 10:28:29 openqaworker5 worker[37495]: [debug] [pid:37495] Accepting job 5231041 from openqa.suse.de.
Dec 30 10:28:29 openqaworker5 worker[37495]: [debug] [pid:37495] Setting job 5231041 from openqa.suse.de up
Dec 30 10:28:29 openqaworker5 worker[37495]: [debug] [pid:37495] Preparing Mojo::IOLoop::ReadWriteProcess::Session
Dec 30 10:28:29 openqaworker5 worker[37495]: [info] [pid:37495] +++ setup notes +++

This function is called by https://github.com/os-autoinst/os-autoinst/blob/master/isotovideo#L433.
should the base_state.json be written in the working directory? such as /var/lib/openqa/pool/1. I am not sure if Mojo::File->new(STATE_FILE) will create the file in the working directory at that time.
And in my local environment, the information that should be written to base_state.json is:

Can\'t locate IO/Socket/Socks.pm in @INC (you may need to install the IO::Socket::Socks module) (@INC contains: /usr/lib/os-autoinst /usr/lib/perl5/site_perl/5.26.1/x86_64-linux-thread-multi /usr/lib/perl5/site_perl/5.26.1 /usr/lib/perl5/vendor_perl/5.26.1/x86_64-linux-thread-multi /usr/lib/perl5/5.26.1 /usr/lib/perl5/site_perl) at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/Client.pm line 19

1. could we install IO::Socket::Socks? or defined $ENV{MOJO_NO_SOCKS}? so seems the Can't locate message will disappear. but if there is another error message, the debug message will happen again.
2. could we simply remove this line https://github.com/os-autoinst/os-autoinst/blob/master/isotovideo#L433 and the related code about parameter $fatal_error?

Xiaojing_liu wrote:

This function is called by https://github.com/os-autoinst/os-autoinst/blob/master/isotovideo#L433. 
should the base_state.json be written in the working directory? such as `/var/lib/openqa/pool/1`. I am not sure if `Mojo::File->new(STATE_FILE)` will create the file in the working directory at that time.

This error Unable to serialize fatal error: Can't open file "base_state.json": Permission denied at /usr/lib/os-autoinst/bmwqemu.pm line 86. suggests the file can't be written due to missing permissions. So either it's indeed in the wrong folder, or the right folder is not setup correctly. I would suggest the first step is to include the folder in the error message.

And in my local environment, the information that should be written to base_state.json is:

Can\'t locate IO/Socket/Socks.pm in @INC (you may need to install the IO::Socket::Socks module) (@INC contains: /usr/lib/os-autoinst /usr/lib/perl5/site_perl/5.26.1/x86_64-linux-thread-multi /usr/lib/perl5/site_perl/5.26.1 /usr/lib/perl5/vendor_perl/5.26.1/x86_64-linux-thread-multi /usr/lib/perl5/5.26.1 /usr/lib/perl5/site_perl) at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/Client.pm line 19

1. could we install IO::Socket::Socks? or defined $ENV{MOJO_NO_SOCKS}? so seems the Can't locate message will disappear. but if there is another error message, the debug message will happen again.

How did you reproduce that? I guess Mojo might be using IO::Socket::Socks somewhere? Did you double-check that you have all of the dependencies we require installed?

1. could we simply remove this line https://github.com/os-autoinst/os-autoinst/blob/master/isotovideo#L433 and the related code about parameter $fatal_error?

That line ensures we save the failure to JSON, and if this fails it would failed everywhere we're trying to save state to disk. But see my remark regarding the directory above.

cdywan wrote:

Xiaojing_liu wrote:

This function is called by https://github.com/os-autoinst/os-autoinst/blob/master/isotovideo#L433. 
should the base_state.json be written in the working directory? such as `/var/lib/openqa/pool/1`. I am not sure if `Mojo::File->new(STATE_FILE)` will create the file in the working directory at that time.

This error Unable to serialize fatal error: Can't open file "base_state.json": Permission denied at /usr/lib/os-autoinst/bmwqemu.pm line 86. suggests the file can't be written due to missing permissions. So either it's indeed in the wrong folder, or the right folder is not setup correctly. I would suggest the first step is to include the folder in the error message.

It's in the wrong folder. Because this message occurs when doing openQA::Worker->new, the command isotovideo --version will be run at that code. So the working directory is not /var/lib/openqa/pool/x.

And in my local environment, the information that should be written to base_state.json is:

Can\'t locate IO/Socket/Socks.pm in @INC (you may need to install the IO::Socket::Socks module) (@INC contains: /usr/lib/os-autoinst /usr/lib/perl5/site_perl/5.26.1/x86_64-linux-thread-multi /usr/lib/perl5/site_perl/5.26.1 /usr/lib/perl5/vendor_perl/5.26.1/x86_64-linux-thread-multi /usr/lib/perl5/5.26.1 /usr/lib/perl5/site_perl) at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/Client.pm line 19

1. could we install IO::Socket::Socks? or defined $ENV{MOJO_NO_SOCKS}? so seems the Can't locate message will disappear. but if there is another error message, the debug message will happen again.

How did you reproduce that? I guess Mojo might be using IO::Socket::Socks somewhere? Did you double-check that you have all of the dependencies we require installed?

Just start openqa-worker service, and check the log message. it can be reproduced 100%. I don't find IO::Socket::Socks in openQA/dependencies.yaml. I guess we don't require it.

1. could we simply remove this line https://github.com/os-autoinst/os-autoinst/blob/master/isotovideo#L433 and the related code about parameter $fatal_error?

That line ensures we save the failure to JSON, and if this fails it would failed everywhere we're trying to save state to disk. But see my remark regarding the directory above.

I am not sure if it would failed everywhere, but it will not fail if the working directory is the correct directory.

Xiaojing_liu wrote:

cdywan wrote:

Xiaojing_liu wrote:

This function is called by https://github.com/os-autoinst/os-autoinst/blob/master/isotovideo#L433. 
should the base_state.json be written in the working directory? such as `/var/lib/openqa/pool/1`. I am not sure if `Mojo::File->new(STATE_FILE)` will create the file in the working directory at that time.

This error Unable to serialize fatal error: Can't open file "base_state.json": Permission denied at /usr/lib/os-autoinst/bmwqemu.pm line 86. suggests the file can't be written due to missing permissions. So either it's indeed in the wrong folder, or the right folder is not setup correctly. I would suggest the first step is to include the folder in the error message.

It's in the wrong folder. Because this message occurs when doing openQA::Worker->new, the command isotovideo --version will be run at that code. So the working directory is not /var/lib/openqa/pool/x.

This made me stop and think, why is this even relevant here? We're not executing a test, just getting the version number. We don't have any state to write.

https://github.com/os-autoinst/os-autoinst/pull/1611

Just a note about the Can't locate IO/Socket/Socks.pm error message: this appears because of $SIG{__DIE__} = sub { $fatal_error = shift }; in https://github.com/os-autoinst/os-autoinst/blob/master/isotovideo#L65
Normally it would be ignored, see https://metacpan.org/source/SRI/Mojolicious-8.70/lib%2FMojo%2FIOLoop%2FClient.pm#L19
So IO::Socket::Socks isn't required, but because of the global SIGDIE handler $fatal_error gets set.

tinita wrote:

Just a note about the Can't locate IO/Socket/Socks.pm error message: this appears because of $SIG{__DIE__} = sub { $fatal_error = shift }; in https://github.com/os-autoinst/os-autoinst/blob/master/isotovideo#L65
Normally it would be ignored, see https://metacpan.org/source/SRI/Mojolicious-8.70/lib%2FMojo%2FIOLoop%2FClient.pm#L19
So IO::Socket::Socks isn't required, but because of the global SIGDIE handler $fatal_error gets set.

That actually makes sense. My fix was more of a work-around in hindsight. I tested it out, and the file isn't written anymore after moving the handler down!

tinita wrote:

Just a note about the Can't locate IO/Socket/Socks.pm error message: this appears because of $SIG{__DIE__} = sub { $fatal_error = shift }; in https://github.com/os-autoinst/os-autoinst/blob/master/isotovideo#L65
Normally it would be ignored, see https://metacpan.org/source/SRI/Mojolicious-8.70/lib%2FMojo%2FIOLoop%2FClient.pm#L19
So IO::Socket::Socks isn't required, but because of the global SIGDIE handler $fatal_error gets set.

Ouch, that global $SIG{__DIE__} should really be fixed. So many ways that can backfire.

The SIGDIE handler was introduced as part of this issue: https://progress.opensuse.org/issues/63718#note-15