http://bugzilla.suse.com/show_bug.cgi?id=1096401
http://bugzilla.suse.com/show_bug.cgi?id=1096401#c11
--- Comment #11 from Oliver Kurz
[…]
The three snaperd coredumps are available in the openQA provided tarball https://openqa.opensuse.org/tests/688332/file/gimp-problem_detection_logs. tar.xz Hm, this file does not exist anymore. Could you please point us to it again ?
openQA cleans up logs and then older openQA jobs after some time. I wonder why the one-month job already deleted its jobs but as a hint: Jobs are kept around longer than logs so the job https://openqa.opensuse.org/tests/688332 itself is still there. From there we can find the link to the always "latest": https://openqa.opensuse.org/tests/latest?flavor=NET&machine=64bit&arch=x86_64&distri=opensuse&version=Tumbleweed&test=update_Leap_42.3_gnome#previous this points me to the two latest failures https://openqa.opensuse.org/tests/700735 failing in gnucash and https://openqa.opensuse.org/tests/700420 failing in chromium. I think in both cases we would be able to find these logs.
Additional it would be nice if you point us to the point where it happens in this test. (The test is quite huge :-))
(directory coredumps)
In the aforementioned test failures I can find references to the core dump,
e.g. in https://openqa.opensuse.org/tests/700735/file/gnucash-journal.log I see
```
Jul 03 04:10:40 susetest org.opensuse.Snapper[729]: terminate called after
throwing an instance of
'boost::exception_detail::clone_impl
' Jul 03 04:10:40 susetest org.opensuse.Snapper[729]: what(): boost: mutex lock failed in pthread_mutex_lock: Invalid argument Jul 03 04:10:40 susetest systemd[1]: Created slice system-systemd\x2dcoredump.slice. Jul 03 04:10:40 susetest systemd[1]: Started Process Core Dump (PID 7421/UID 0). Jul 03 04:10:40 susetest systemd-coredump[7422]: Process 5743 (snapperd) of user 0 dumped core.
so to identify further at which point in time within the test this happens we
can take a look at the timestamp.
https://openqa.opensuse.org/tests/700735#step/keymap_or_locale/10 is at 03:56
so before, https://openqa.opensuse.org/tests/700735#step/consoletest_finish/17
is at 04:17 after that.
Taking a look into the journal again I can find the lines
Jul 03 04:09:56 susetest systemd[1]: Started The Salt Minion. Jul 03 04:10:19 susetest salt-minion[7008]: [ERROR ] The Salt Master has cached the public key for this node, this salt minion will wait for 10 seconds before attempting to re-authenticate Jul 03 04:10:29 susetest salt-minion[7008]: [ERROR ] The Salt Master has cached the public key for this node, this salt minion will wait for 10 seconds before attempting to re-authenticate ``` that is just 11 seconds before the above error message at 04:10:40 and the next message after the snapper error messages is ``` Jul 03 04:11:03 susetest systemd[1]: Stopping The Salt Master Server... ``` that is 23 seconds later. With this https://openqa.opensuse.org/tests/700735#step/salt/14 is the step just in before within the test module "salt", https://openqa.opensuse.org/tests/700735#step/salt/24 is the step afterwards. I have a suspicion that the snapper core dump is related to installing packages which should also trigger snapper to create snapshots, right? E.g. from https://openqa.opensuse.org/tests/700735/file/gnucash-y2logs_clone.tar.bz2 we can also find the zypper.log stating: ``` 2018-07-03 04:09:39 <2> susetest(6262) [PLUGIN] PluginScript.cc(~PluginDumpStderr):75 ! INFO:root:creating post snapshot 2018-07-03 04:09:39 <2> susetest(6262) [PLUGIN] PluginScript.cc(~PluginDumpStderr):75 ! DEBUG:root:created post snapshot 8 2018-07-03 04:09:39 <1> susetest(6262) [zypp::plugin++] PluginScript.cc(receive):426 PluginScript[6283] /usr/lib/zypp/plugins/commit/snapper.py <-PluginFrame[ACK](0){0} 2018-07-03 04:09:39 <1> susetest(6262) [zypp::plugin++] PluginExecutor.cc(send):94 --------------- send PluginFrame[COMMITEND](0){4556} 2018-07-03 04:09:39 <1> susetest(6262) [zypp] PathInfo.cc(dirForEach):553 readdir /etc/products.d 2018-07-03 04:09:39 <1> susetest(6262) [zypp] TargetImpl.cc(buildCache):850 Read cookie: /var/cache/zypp/solv/@System/cookie{- 0644 0/0 size 52} 2018-07-03 04:09:39 <1> susetest(6262) [zypp] TargetImpl.cc(buildCache):857 Read cookie: /var/cache/zypp/solv/@System/cookie says: outdated 2018-07-03 04:09:39 <1> susetest(6262) [zypp::exec++] ExternalProgram.cc(start_program):252 Executing 'rpmdb2solv' '-r' '/' '-X' '-A' '-p' '/etc/products.d' '/var/cache/zypp/solv/@System/solv' '-o' '/var/cache/zypp/solv/@System/solvP20RfW' 2018-07-03 04:09:39 <1> susetest(6262) [zypp::exec++] ExternalProgram.cc(start_program):415 pid 6943 launched 2018-07-03 04:09:39 <1> susetest(6262) [zypp::exec++] ExternalProgram.cc(checkStatus):516 Pid 6943 successfully completed 2018-07-03 04:09:39 <1> susetest(6262) [zypp] PathInfo.cc(rename):701 rename /var/cache/zypp/solv/@System/solvP20RfW -> /var/cache/zypp/solv/@System/solv 2018-07-03 04:09:39 <1> susetest(6262) [zypp] PathInfo.cc(chmod):1051 chmod /var/cache/zypp/solv/@System/solv 00644 2018-07-03 04:09:39 <1> susetest(6262) [zypp::plugin++] PluginExecutor.cc(load):53 +++++++++++++++ load /usr/lib/zypp/plugins/system{d 0755 0/0} 2018-07-03 04:09:39 <1> susetest(6262) [zypp] PathInfo.cc(dirForEach):553 readdir /usr/lib/zypp/plugins/system 2018-07-03 04:09:39 <1> susetest(6262) [zypp::plugin++] PluginExecutor.cc(load):80 --------------- load /usr/lib/zypp/plugins/system{d 0755 0/0} 2018-07-03 04:09:39 <1> susetest(6262) [zypp] TargetImpl.cc(commit):1338 TargetImpl::commit(<pool>, CommitPolicy( DownloadInHeaps )) returns: CommitResult (total 40, done 40, error 0, skipped 0, updateMessages 0) 2018-07-03 04:09:39 <1> susetest(6262) [zypp::plugin++] PluginExecutor.cc(send):85 +++++++++++++++ send PluginFrame[PLUGINEND](0){0} 2018-07-03 04:09:39 <1> susetest(6262) [zypp::plugin++] PluginScript.cc(send):272 PluginScript[6281] /usr/lib/zypp/plugins/commit/btrfs-defrag-plugin.py ->send PluginFrame[PLUGINEND](0){0} 2018-07-03 04:09:40 <1> susetest(6262) [zypp::plugin++] PluginScript.cc(receive):426 PluginScript[6281] /usr/lib/zypp/plugins/commit/btrfs-defrag-plugin.py <-PluginFrame[ACK](0){0} 2018-07-03 04:09:40 <1> susetest(6262) [zypp::plugin++] PluginScript.cc(send):272 PluginScript[6283] /usr/lib/zypp/plugins/commit/snapper.py ->send PluginFrame[PLUGINEND](0){0} 2018-07-03 04:09:40 <2> susetest(6262) [PLUGIN] PluginScript.cc(~PluginDumpStderr):75 ! INFO:root:PLUGINEND 2018-07-03 04:09:40 <1> susetest(6262) [zypp::plugin++] PluginScript.cc(receive):426 PluginScript[6283] /usr/lib/zypp/plugins/commit/snapper.py <-PluginFrame[ACK](0){0} 2018-07-03 04:09:40 <1> susetest(6262) [zypp::plugin++] PluginExecutor.cc(send):94 --------------- send PluginFrame[PLUGINEND](0){0} 2018-07-03 04:09:40 <1> susetest(6262) [zypp::plugin++] PluginScript.cc(close):229 Close:PluginScript[6281] /usr/lib/zypp/plugins/commit/btrfs-defrag-plugin.py 2018-07-03 04:09:40 <1> susetest(6262) [zypp::plugin++] PluginScript.cc(send):272 PluginScript[6281] /usr/lib/zypp/plugins/commit/btrfs-defrag-plugin.py ->send PluginFrame[_DISCONNECT](0){0} 2018-07-03 04:09:40 <1> susetest(6262) [zypp::plugin++] PluginScript.cc(receive):426 PluginScript[6281] /usr/lib/zypp/plugins/commit/btrfs-defrag-plugin.py <-PluginFrame[ACK](1){10} 2018-07-03 04:09:40 <1> susetest(6262) [zypp::plugin++] PluginScript.cc(close):251 PluginScript[6281] /usr/lib/zypp/plugins/commit/btrfs-defrag-plugin.py -> [0] Disconnect 2018-07-03 04:09:40 <1> susetest(6262) [zypp::plugin++] PluginScript.cc(close):229 Close:PluginScript[6283] /usr/lib/zypp/plugins/commit/snapper.py 2018-07-03 04:09:40 <1> susetest(6262) [zypp::plugin++] PluginScript.cc(send):272 PluginScript[6283] /usr/lib/zypp/plugins/commit/snapper.py ->send PluginFrame[_DISCONNECT](0){0} 2018-07-03 04:09:40 <1> susetest(6262) [zypp::plugin++] PluginScript.cc(receive):426 PluginScript[6283] /usr/lib/zypp/plugins/commit/snapper.py <-PluginFrame[ACK](1){10} 2018-07-03 04:09:40 <1> susetest(6262) [zypp::plugin++] PluginScript.cc(close):251 PluginScript[6283] /usr/lib/zypp/plugins/commit/snapper.py -> [0] Disconnect ``` so could that be https://bugzilla.suse.com/show_bug.cgi?id=1099494 "zypper calls snapper, snapshot creation failed while snapper already running"? Keep in mind that the test module "gnucash" failing is merely a coincidence. https://openqa.opensuse.org/tests/700420/file/chromium-journal.log is the journal from the second log and it shows the same symptoms, snapper core dumps next to salt services while the failing test module is actually chromium. -- You are receiving this mail because: You are on the CC list for the bug.