Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

snapshot-pre flake on daily-iso: "gi.overrides.BlockDev.LVMError: Failed to call the 'Snapshot' method on the '/com/redhat/lvmdbus1/Lv/1' object: Timeout was reached" #869

Closed
rvykydal opened this issue Jan 16, 2023 · 5 comments
Closed

snapshot-pre flake on daily-iso: "gi.overrides.BlockDev.LVMError: Failed to call the 'Snapshot' method on the '/com/redhat/lvmdbus1/Lv/1' object: Timeout was reached" #869

rvykydal opened this issue Jan 16, 2023 · 5 comments
Labels
test flake A test flake worth tracking (for more investigation, potenital bug, or to see if more come...)

Comments

@rvykydal
Copy link
Contributor

01/13/2023

kstest.log
virt-install.log
@rvykydal rvykydal added the test flake A test flake worth tracking (for more investigation, potenital bug, or to see if more come...) label Jan 16, 2023
@VladimirSlavik
Copy link
Contributor

VladimirSlavik commented Jan 17, 2023 •
edited
Loading

Looks like something is borked with SELinux? It seems to be forbidding things right off the bat:

05:07:05,623 INFO systemd:Successfully loaded SELinux policy in 895.153ms.
05:07:05,623 NOTICE kernel:audit: type=1400 audit(1673586419.945:73): avc:  denied  { map } for  pid=1 comm="systemd" path="/sys/fs/selinux/status" dev="selinuxfs" ino=19 scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:object_r:security_t:s0 tclass=file permissive=1
05:07:05,623 NOTICE kernel:audit: type=1400 audit(1673586419.966:74): avc:  denied  { map } for  pid=1 comm="systemd" path="/etc/selinux/targeted/contexts/files/file_contexts.bin" dev="dm-0" ino=30104 scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:object_r:unlabeled_t:s0 tclass=file permissive=1
05:07:05,628 NOTICE kernel:audit: type=1400 audit(1673586420.024:75): avc:  denied  { write } for  pid=1 comm="systemd" name="core_pattern" dev="proc" ino=13137 scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:object_r:usermodehelper_t:s0 tclass=file permissive=1
05:07:05,628 NOTICE kernel:audit: type=1400 audit(1673586420.030:76): avc:  denied  { read } for  pid=1 comm="systemd" name="net" dev="proc" ino=4026531845 scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:object_r:proc_net_t:s0 tclass=lnk_file permissive=1
(...)
05:07:05,835 NOTICE audit:AVC avc:  denied  { create } for  pid=1473 comm="mkdir" name="anaconda.target.wants" scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:object_r:unlabeled_t:s0 tclass=dir permissive=1

The log is then spammed with rsyslog errors a lot, presumably also borked by SElinux.

05:09:40,465 ERR rsyslogd:imjournal: fopen() failed for path: '/imjournal.state.tmp': Permission denied [v8.2210.0-2.fc38 try https://www.rsyslog.com/e/2013 ]

And then we also get:

05:09:40,731 DEBUG anaconda:anaconda: modules.payloads.payload.dnf.tree_info: Load treeinfo metadata for 'http://dl.fedoraproject.org/pub/fedora/linux/development/rawhide/Everything/$basearch/os/'.
05:09:40,808 NOTICE audit:AVC avc:  denied  { name_connect } for  pid=1849 comm="anaconda" dest=80 scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:object_r:http_port_t:s0 tclass=tcp_socket permissive=1
05:09:40,809 NOTICE kernel:audit: type=1400 audit(1673586580.806:654): avc:  denied  { name_connect } for  pid=1849 comm="anaconda" dest=80 scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:object_r:http_port_t:s0 tclass=tcp_socket permissive=1
05:09:40,846 DEBUG anaconda:anaconda: modules.payloads.payload.dnf.tree_info: Failed to download '.treeinfo': 404 Client Error: Not Found for url: http://dl.fedoraproject.org/pub/fedora/linux/development/rawhide/Everything/$basearch/os//.treeinfo
05:09:40,867 DEBUG anaconda:anaconda: modules.payloads.payload.dnf.tree_info: Failed to download 'treeinfo': 404 Client Error: Not Found for url: http://dl.fedoraproject.org/pub/fedora/linux/development/rawhide/Everything/$basearch/os//treeinfo
05:09:40,870 DEBUG anaconda:packaging: No treeinfo metadata to use: No treeinfo metadata found (404).
(...)
05:09:51,009 WARNING org.fedoraproject.Anaconda.Modules.Storage:INFO:anaconda.threading:Thread Failed: AnaTaskThread-SnapshotCreateTask-1 (140223056410304)
05:09:51,021 WARNING org.fedoraproject.Anaconda.Modules.Storage:ERROR:anaconda.modules.common.task.task:Thread AnaTaskThread-SnapshotCreateTask-1 has failed: Traceback (most recent call last):
05:09:51,021 WARNING org.fedoraproject.Anaconda.Modules.Storage:  File "/usr/lib64/python3.11/site-packages/gi/overrides/BlockDev.py", line 1200, in wrapped
05:09:51,021 WARNING org.fedoraproject.Anaconda.Modules.Storage:    ret = orig_obj(*args, **kwargs)
05:09:51,021 WARNING org.fedoraproject.Anaconda.Modules.Storage:          ^^^^^^^^^^^^^^^^^^^^^^^^^
05:09:51,021 WARNING org.fedoraproject.Anaconda.Modules.Storage:  File "/usr/lib64/python3.11/site-packages/gi/overrides/BlockDev.py", line 849, in lvm_thsnapshotcreate
05:09:51,021 WARNING org.fedoraproject.Anaconda.Modules.Storage:    return _lvm_thsnapshotcreate(vg_name, origin_name, snapshot_name, pool_name, extra)
05:09:51,021 WARNING org.fedoraproject.Anaconda.Modules.Storage:           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
05:09:51,021 WARNING org.fedoraproject.Anaconda.Modules.Storage:gi.repository.GLib.GError: g-io-error-quark: Failed to call the 'Snapshot' method on the '/com/redhat/lvmdbus1/Lv/1' object: Timeout was reached (24)
05:09:51,021 WARNING org.fedoraproject.Anaconda.Modules.Storage:During handling of the above exception, another exception occurred:
05:09:51,021 WARNING org.fedoraproject.Anaconda.Modules.Storage:Traceback (most recent call last):
05:09:51,021 WARNING org.fedoraproject.Anaconda.Modules.Storage:  File "/usr/lib64/python3.11/site-packages/pyanaconda/threading.py", line 275, in run
05:09:51,021 WARNING org.fedoraproject.Anaconda.Modules.Storage:    threading.Thread.run(self)
05:09:51,021 WARNING org.fedoraproject.Anaconda.Modules.Storage:  File "/usr/lib64/python3.11/threading.py", line 975, in run
05:09:51,021 WARNING org.fedoraproject.Anaconda.Modules.Storage:    self._target(*self._args, **self._kwargs)
05:09:51,021 WARNING org.fedoraproject.Anaconda.Modules.Storage:  File "/usr/lib64/python3.11/site-packages/pyanaconda/modules/common/task/task.py", line 96, in _thread_run_callback
05:09:51,021 WARNING org.fedoraproject.Anaconda.Modules.Storage:    self._task_run_callback()
05:09:51,021 WARNING org.fedoraproject.Anaconda.Modules.Storage:  File "/usr/lib64/python3.11/site-packages/pyanaconda/modules/common/task/task.py", line 109, in _task_run_callback
05:09:51,021 WARNING org.fedoraproject.Anaconda.Modules.Storage:    self._set_result(self.run())
05:09:51,021 WARNING org.fedoraproject.Anaconda.Modules.Storage:                     ^^^^^^^^^^
05:09:51,021 WARNING org.fedoraproject.Anaconda.Modules.Storage:  File "/usr/lib64/python3.11/site-packages/pyanaconda/modules/storage/snapshot/create.py", line 52, in run
05:09:51,021 WARNING org.fedoraproject.Anaconda.Modules.Storage:    self._create_snapshots(self._storage, self._requests, self._when)
05:09:51,021 WARNING org.fedoraproject.Anaconda.Modules.Storage:  File "/usr/lib64/python3.11/site-packages/pyanaconda/modules/storage/snapshot/create.py", line 65, in _create_snapshots
05:09:51,021 WARNING org.fedoraproject.Anaconda.Modules.Storage:    self._create_snapshot(storage, request)
05:09:51,021 WARNING org.fedoraproject.Anaconda.Modules.Storage:  File "/usr/lib64/python3.11/site-packages/pyanaconda/modules/storage/snapshot/create.py", line 83, in _create_snapshot
05:09:51,021 WARNING org.fedoraproject.Anaconda.Modules.Storage:    device.create()
05:09:51,021 WARNING org.fedoraproject.Anaconda.Modules.Storage:  File "/usr/lib/python3.11/site-packages/blivet/threads.py", line 53, in run_with_lock
05:09:51,021 WARNING org.fedoraproject.Anaconda.Modules.Storage:    return m(*args, **kwargs)
05:09:51,021 WARNING org.fedoraproject.Anaconda.Modules.Storage:           ^^^^^^^^^^^^^^^^^^
05:09:51,024 WARNING org.fedoraproject.Anaconda.Modules.Storage:  File "/usr/lib/python3.11/site-packages/blivet/devices/storage.py", line 493, in create
05:09:51,024 WARNING org.fedoraproject.Anaconda.Modules.Storage:    self._create()
05:09:51,024 WARNING org.fedoraproject.Anaconda.Modules.Storage:  File "/usr/lib/python3.11/site-packages/blivet/threads.py", line 53, in run_with_lock
05:09:51,024 WARNING org.fedoraproject.Anaconda.Modules.Storage:    return m(*args, **kwargs)
05:09:51,024 WARNING org.fedoraproject.Anaconda.Modules.Storage:           ^^^^^^^^^^^^^^^^^^
05:09:51,024 WARNING org.fedoraproject.Anaconda.Modules.Storage:  File "/usr/lib/python3.11/site-packages/blivet/devices/lvm.py", line 2468, in decorated
05:09:51,024 WARNING org.fedoraproject.Anaconda.Modules.Storage:    found, ret = self._try_specific_call(meth.__name__, *args, **kwargs)  # pylint: disable=no-member
05:09:51,024 WARNING org.fedoraproject.Anaconda.Modules.Storage:                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
05:09:51,024 WARNING org.fedoraproject.Anaconda.Modules.Storage:  File "/usr/lib/python3.11/site-packages/blivet/threads.py", line 53, in run_with_lock
05:09:51,024 WARNING org.fedoraproject.Anaconda.Modules.Storage:    return m(*args, **kwargs)
05:09:51,024 WARNING org.fedoraproject.Anaconda.Modules.Storage:           ^^^^^^^^^^^^^^^^^^
05:09:51,024 WARNING org.fedoraproject.Anaconda.Modules.Storage:  File "/usr/lib/python3.11/site-packages/blivet/devices/lvm.py", line 2453, in _try_specific_call
05:09:51,024 WARNING org.fedoraproject.Anaconda.Modules.Storage:    ret = getattr(cls, name)(self, *args, **kwargs)
05:09:51,024 WARNING org.fedoraproject.Anaconda.Modules.Storage:          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
05:09:51,024 WARNING org.fedoraproject.Anaconda.Modules.Storage:  File "/usr/lib/python3.11/site-packages/blivet/devices/lvm.py", line 1547, in _create
05:09:51,024 WARNING org.fedoraproject.Anaconda.Modules.Storage:    blockdev.lvm.thsnapshotcreate(self.vg.name, self.origin.lvname, self._name,
05:09:51,024 WARNING org.fedoraproject.Anaconda.Modules.Storage:  File "/usr/lib64/python3.11/site-packages/gi/overrides/BlockDev.py", line 1222, in wrapped
05:09:51,024 WARNING org.fedoraproject.Anaconda.Modules.Storage:    raise transform[1](msg)
05:09:51,024 WARNING org.fedoraproject.Anaconda.Modules.Storage:gi.overrides.BlockDev.LVMError: Failed to call the 'Snapshot' method on the '/com/redhat/lvmdbus1/Lv/1' object: Timeout was reached
05:09:51,027 WARNING org.fedoraproject.Anaconda.Modules.Storage:INFO:anaconda.threading:Thread Done: AnaTaskThread-SnapshotCreateTask-1 (140223056410304)

@jstodola
Copy link
Contributor

The log is then spammed with rsyslog errors a lot, presumably also borked by SElinux.

05:09:40,465 ERR rsyslogd:imjournal: fopen() failed for path: '/imjournal.state.tmp': Permission denied [v8.2210.0-2.fc38 try https://www.rsyslog.com/e/2013 ]

It will be fixed by lorax, see weldr/lorax#1299

@VladimirSlavik
Copy link
Contributor

Good catch, thanks! Still does not answer the rest though.

@rvykydal
Copy link
Contributor Author

rvykydal commented Oct 30, 2023 •
edited
Loading

Hit again on 10/26/2023, added to the script: #1020

@rvykydal rvykydal mentioned this issue Oct 8, 2024
Open
@rvykydal
Copy link
Contributor Author

rvykydal commented Oct 8, 2024

Closing, will be tracked in #1311

@rvykydal rvykydal closed this as completed Oct 8, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
test flake A test flake worth tracking (for more investigation, potenital bug, or to see if more come...)
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@rvykydal @jstodola @VladimirSlavik