On Tue, Mar 16, 2021 at 1:11 PM Yedidyah Bar David <[email protected]> wrote: > > On Tue, Mar 16, 2021 at 12:50 PM Dana Elfassy <[email protected]> wrote: > > > > About [5] https://bugzilla.redhat.com/show_bug.cgi?id=1917707, I have found > > that when executing the http request of the playbook, sometimes in the > > response there are some events that are missing. The way we handle the > > events is via while loop, where in each loop we continue from the > > lastEventId. Since not all events were listed, the lastEventId (which is > > returned as total number of events) is smaller than the actual eventId that > > was handled. Thus, in the next iteration the last events are handled again. > > It seems that this comes from Ansible Runner, and I'm investigating that > > area now > > Thanks > > > I'm not sure if it's the same issue as you get with the logs, though, as > > I'm not familiar with this area in the OSTs. Is the creation of the 2 logs > > done by different threads? > > I have no idea either. > > > > > Regarding the initial error (' directory is not empty.non-zero return > > code') I'm not sure, will have to loop more into it. Martin, do you have > > any idea? > > I think it's quite obvious that the reason for this is that we run two > ovirt-log-collector processes in parallel. Why we (sometimes) do this > is an open question, but unrelated to ovirt-log-collector (or the > specific error message it emits).
I now did this: 1. Wrote a trivial dummy module [1] to test this 2. Ran it on an already finished basic-suite env with lagofy/run_tc [2]. As you can see, if you pipe [2] through grep -Ev 'do_something_2.*something 2|do_something_1.*something 1', in some cases do_something_1 actually ran the ansible code of do_something_2. I currently think it's some kind of race condition in ansible-runner, causing it to misbehave when ran in parallel, as we do in test_metrics_and_log_collector. I still didn't try to check its code and/or add debugging stuff to it to try and find the exact location. 2021-03-16 20:54:18+0200,681 INFO [test_003_01_dummy] do_something_1: Tue Mar 16 19:54:18 CET 2021 lago-basic-suite-master-engine something 2 (test_003_01_dummy:39) 2021-03-16 20:55:41+0200,155 INFO [test_003_01_dummy] do_something_1: Tue Mar 16 19:55:40 CET 2021 lago-basic-suite-master-engine something 2 (test_003_01_dummy:39) 2021-03-16 20:56:56+0200,196 INFO [test_003_01_dummy] do_something_1: Tue Mar 16 19:56:55 CET 2021 lago-basic-suite-master-engine something 2 (test_003_01_dummy:39) 2021-03-16 20:58:19+0200,665 INFO [test_003_01_dummy] do_something_1: Tue Mar 16 19:58:19 CET 2021 lago-basic-suite-master-engine something 2 (test_003_01_dummy:39) [1] https://github.com/didib/ovirt-system-tests/commit/6a5327976eaf5bc27e352723bf5c17dab4e60fa4 [2] https://gist.github.com/didib/fe1b3bc28b8364cf6976d3d93e6cd9b6 > > > > > On Mon, Mar 15, 2021 at 9:59 AM Yedidyah Bar David <[email protected]> wrote: > >> > >> On Mon, Mar 15, 2021 at 7:55 AM Yedidyah Bar David <[email protected]> wrote: > >> > > >> > Hi all, > >> > > >> > This started a few days ago [1] and randomly happens since then: > >> > > >> > E DEBUG: Configuration: > >> > E DEBUG: command: collect > >> > E DEBUG: Traceback (most recent call last): > >> > E DEBUG: File > >> > "/usr/lib/python3.6/site-packages/ovirt_log_collector/__main__.py", > >> > line 2067, in <module> > >> > E DEBUG: '%s directory is not empty.' % > >> > (conf["local_tmp_dir"]) > >> > E DEBUG: Exception: /dev/shm/log directory is not > >> > empty.ERROR: /dev/shm/log directory is not empty.non-zero return code > >> > > >> > Michal tried to fix this by using a random directory but it still fails > >> > [2]: > >> > > >> > DEBUG: command: collect > >> > DEBUG: Traceback (most recent call last): > >> > DEBUG: File > >> > "/usr/lib/python3.6/site-packages/ovirt_log_collector/__main__.py", > >> > line 2067, in <module> > >> > DEBUG: '%s directory is not empty.' % (conf["local_tmp_dir"]) > >> > DEBUG: Exception: /dev/shm/kaN7uY directory is not empty.ERROR: > >> > /dev/shm/kaN7uY directory is not empty.non-zero return code > >> > > >> > Since I suppose that the randomness of mktemp is good enough, it must > >> > be something else. Also, the last successful run before [1] used the > >> > same OST git commit (same code), so I do not think it's something in > >> > OST's code. > >> > > >> > Any idea? > >> > > >> > I think I'll push a patch to create and use the directory right before > >> > calling ovirt-log-collector, which is probably better in other ways. > >> > >> My patch [1] still fails, with a somewhat different error message, but > >> this made me check further, and while I still do not understand, I have > >> this to add: > >> > >> In the failing runs, ovirt-log-collector is called *twice* in parallel. > >> E.g. > >> in [2] (the check-patch of [1]): > >> > >> Mar 15 07:38:59 lago-basic-suite-master-engine platform-python[59099]: > >> ansible-command Invoked with _raw_params=lctmp=$(mktemp -d -p > >> /dev/shm); ovirt-log-collector --verbose --batch --no-hypervisors > >> --local-tmp="${lctmp}" --conf-file=/root/ovirt-log-collector.conf > >> _uses_shell=True warn=True stdin_add_newline=True > >> strip_empty_ends=True argv=None chdir=None executable=None > >> creates=None removes=None stdin=None > >> Mar 15 07:38:59 lago-basic-suite-master-engine platform-python[59124]: > >> ansible-command Invoked with _raw_params=lctmp=$(mktemp -d -p > >> /dev/shm); ovirt-log-collector --verbose --batch --no-hypervisors > >> --local-tmp="${lctmp}" --conf-file=/root/ovirt-log-collector.conf > >> _uses_shell=True warn=True stdin_add_newline=True > >> strip_empty_ends=True argv=None chdir=None executable=None > >> creates=None removes=None stdin=None > >> > >> It also generates two logs, which you can check/compare. > >> > >> It's the same for previous ones, e.g. latest nightly [3][4]: > >> > >> Mar 15 06:23:30 lago-basic-suite-master-engine platform-python[59343]: > >> ansible-command Invoked with _raw_params=ovirt-log-collector --verbose > >> --batch --no-hypervisors --conf-file=/root/ovirt-log-collector.conf > >> _uses_shell=True warn=True stdin_add_newline=True > >> strip_empty_ends=True argv=None chdir=None executable=None > >> creates=None removes=None stdin=None > >> Mar 15 06:23:30 lago-basic-suite-master-engine setroubleshoot[58889]: > >> SELinux is preventing /usr/lib/systemd/systemd from unlink access on > >> the sock_file ansible-ssh-lago-basic-suite-master-host-1-22-root. For > >> complete SELinux messages run: sealert -l > >> d03a8655-9430-4fcf-9892-3b4df1939899 > >> Mar 15 06:23:30 lago-basic-suite-master-engine setroubleshoot[58889]: > >> SELinux is preventing /usr/lib/systemd/systemd from unlink access on > >> the sock_file > >> ansible-ssh-lago-basic-suite-master-host-1-22-root.#012#012***** > >> Plugin catchall (100. confidence) suggests > >> **************************#012#012If you believe that systemd should > >> be allowed unlink access on the > >> ansible-ssh-lago-basic-suite-master-host-1-22-root sock_file by > >> default.#012Then you should report this as a bug.#012You can generate > >> a local policy module to allow this access.#012Do#012allow this access > >> for now by executing:#012# ausearch -c 'systemd' --raw | audit2allow > >> -M my-systemd#012# semodule -X 300 -i my-systemd.pp#012 > >> Mar 15 06:23:30 lago-basic-suite-master-engine platform-python[59361]: > >> ansible-command Invoked with _raw_params=ovirt-log-collector --verbose > >> --batch --no-hypervisors --conf-file=/root/ovirt-log-collector.conf > >> _uses_shell=True warn=True stdin_add_newline=True > >> strip_empty_ends=True argv=None chdir=None executable=None > >> creates=None removes=None stdin=None > >> > >> Any idea what might have caused this to start happening? Perhaps > >> a bug in ansible, or ansible-runner? It reminds me of [5]. > >> Adding Dana and Martin. > >> > >> I think [5] is quite a serious bug, btw, should be a 4.4.5 blocker. > >> > >> Best regards, > >> > >> [1] https://gerrit.ovirt.org/c/ovirt-system-tests/+/113875 > >> > >> [2] > >> https://jenkins.ovirt.org/job/ovirt-system-tests_standard-check-patch/15980/artifact/check-patch.basic_suite_master.el8.x86_64/test_logs/lago-basic-suite-master-engine/var/log/messages/*view* > >> > >> [3] > >> https://jenkins.ovirt.org/job/ovirt-system-tests_basic-suite-master_nightly/959/ > >> > >> [4] > >> https://jenkins.ovirt.org/job/ovirt-system-tests_basic-suite-master_nightly/959/artifact/exported-artifacts/test_logs/lago-basic-suite-master-engine/var/log/messages/*view* > >> > >> [5] https://bugzilla.redhat.com/show_bug.cgi?id=1917707 > >> > >> > > >> > Best regards, > >> > > >> > [1] > >> > https://jenkins.ovirt.org/job/ovirt-system-tests_basic-suite-master_nightly/949/ > >> > > >> > [2] > >> > https://jenkins.ovirt.org/job/ovirt-system-tests_basic-suite-master_nightly/959/ > >> > > >> > > >> > -- > >> > Didi > >> > >> > >> > >> -- > >> Didi > >> > > > -- > Didi -- Didi _______________________________________________ Infra mailing list -- [email protected] To unsubscribe send an email to [email protected] Privacy Statement: https://www.ovirt.org/privacy-policy.html oVirt Code of Conduct: https://www.ovirt.org/community/about/community-guidelines/ List Archives: https://lists.ovirt.org/archives/list/[email protected]/message/WELCRK27TK7LT6BZVCMZDS66NNE73TTO/
