Comment # 11 on bug 1096401 from 
(In reply to Stefan Schubert from comment #9)
> [���]
> > 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<boost::exception_detail::error_info_injector<boost::lock_error>
>'
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: