search

pwmt / zathura

Document viewer
https://pwmt.org/projects/zathura
zlib License
2.05k stars 142 forks source link

[SOLVED] suspend and wake closes zathura #406

Closed sebastinas closed 5 months ago

sebastinas commented 1 year ago

On GitLab by @asklow on Jul 15, 2023, 10:30

Suspending and waking up the system closes all zathura instances.

system: archlinux
kernel: zen-6.4.3
wm: i3 & sway
drivers: nvidia-dkms

How to diagnose this situation ?

SOLUTION: disable strict sandboxing from config.

sebastinas commented 1 year ago

On GitLab by @asklow on Jul 22, 2023, 10:30

Can anyone look into this ? What's the issue ?

Jul 22 13:52:07 arch dbus-daemon[651]: [session uid=1000 pid=651] Activating via systemd: service name='org.a11y.Bus' unit='at-spi-dbus-bus.service' requested by ':1.5' (uid=1000 pid=919 comm="zathura /home/mpk/doc/books/[Robert Langdon 2 ] Br")
Jul 22 13:52:07 arch systemd[578]: Starting Accessibility services bus...
Jul 22 13:52:07 arch dbus-daemon[651]: [session uid=1000 pid=651] Successfully activated service 'org.a11y.Bus'
Jul 22 13:52:07 arch systemd[578]: Started Accessibility services bus.
Jul 22 13:52:07 arch dbus-daemon[651]: [session uid=1000 pid=651] Activating via systemd: service name='org.gtk.vfs.Daemon' unit='gvfs-daemon.service' requested by ':1.7' (uid=1000 pid=919 comm="zathura /home/mpk/doc/books/[Robert Langdon 2 ] Br")
Jul 22 13:52:07 arch systemd[578]: Starting Virtual filesystem service...
Jul 22 13:52:07 arch dbus-daemon[651]: [session uid=1000 pid=651] Successfully activated service 'org.gtk.vfs.Daemon'
Jul 22 13:52:07 arch systemd[578]: Started Virtual filesystem service.
Jul 22 13:52:07 arch at-spi-bus-launcher[927]: dbus-daemon[927]: Activating service name='org.a11y.atspi.Registry' requested by ':1.0' (uid=1000 pid=919 comm="zathura /home/mpk/doc/books/[Robert Langdon 2 ] Br")
Jul 22 13:52:07 arch at-spi-bus-launcher[927]: dbus-daemon[927]: Successfully activated service 'org.a11y.atspi.Registry'
Jul 22 13:52:07 arch at-spi-bus-launcher[956]: SpiRegistry daemon is running with well-known name - org.a11y.atspi.Registry
Jul 22 13:52:10 arch systemd-timesyncd[535]: Contacted time server 139.59.15.185:123 (2.arch.pool.ntp.org).
Jul 22 13:52:10 arch systemd-timesyncd[535]: Initial clock synchronization to Sat 2023-07-22 13:52:10.213603 IST.
Jul 22 13:52:10 arch systemd[1]: systemd-hostnamed.service: Deactivated successfully.
Jul 22 13:52:16 arch systemd-logind[542]: The system will suspend now!
Jul 22 13:52:16 arch NetworkManager[543]: <info>  [1690014136.9978] manager: sleep: sleep requested (sleeping: no  enabled: yes)
Jul 22 13:52:16 arch NetworkManager[543]: <info>  [1690014136.9978] manager: NetworkManager state is now ASLEEP
Jul 22 13:52:16 arch NetworkManager[543]: <info>  [1690014136.9979] device (enp4s0): state change: activated -> deactivating (reason 'sleeping', sys-iface-state: 'managed')
Jul 22 13:52:16 arch dbus-daemon[540]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.5' (uid=0 pid=543 comm="/usr/bin/NetworkManager --no-daemon")
Jul 22 13:52:17 arch systemd[1]: Starting Network Manager Script Dispatcher Service...
Jul 22 13:52:17 arch dbus-daemon[540]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Jul 22 13:52:17 arch systemd[1]: Started Network Manager Script Dispatcher Service.
Jul 22 13:52:17 arch NetworkManager[543]: <info>  [1690014137.0175] device (enp4s0): state change: deactivating -> disconnected (reason 'sleeping', sys-iface-state: 'managed')
Jul 22 13:52:17 arch NetworkManager[543]: <info>  [1690014137.0258] dhcp4 (enp4s0): canceled DHCP transaction
Jul 22 13:52:17 arch NetworkManager[543]: <info>  [1690014137.0259] dhcp4 (enp4s0): activation: beginning transaction (timeout in 45 seconds)
Jul 22 13:52:17 arch NetworkManager[543]: <info>  [1690014137.0259] dhcp4 (enp4s0): state changed no lease
Jul 22 13:52:17 arch NetworkManager[543]: <info>  [1690014137.0260] dhcp6 (enp4s0): canceled DHCP transaction
Jul 22 13:52:17 arch NetworkManager[543]: <info>  [1690014137.0260] dhcp6 (enp4s0): state changed no lease
Jul 22 13:52:17 arch NetworkManager[543]: <info>  [1690014137.0456] device (enp4s0): state change: disconnected -> unmanaged (reason 'sleeping', sys-iface-state: 'managed')
Jul 22 13:52:17 arch kernel: r8169 0000:04:00.0 enp4s0: Link is Down
Jul 22 13:52:17 arch systemd[1]: Reached target Sleep.
Jul 22 13:52:17 arch systemd[1]: Starting System Suspend...
Jul 22 13:52:17 arch systemd-sleep[992]: Entering sleep state 'suspend'...
Jul 22 13:52:17 arch kernel: PM: suspend entry (deep)
Jul 22 13:52:17 arch kernel: Filesystems sync: 0.007 seconds
Jul 22 13:53:09 arch kernel: Freezing user space processes
Jul 22 13:53:09 arch kernel: Freezing user space processes completed (elapsed 0.001 seconds)
Jul 22 13:53:09 arch kernel: OOM killer disabled.
Jul 22 13:53:09 arch kernel: Freezing remaining freezable tasks
Jul 22 13:53:09 arch kernel: Freezing remaining freezable tasks completed (elapsed 0.000 seconds)
Jul 22 13:53:09 arch kernel: printk: Suspending console(s) (use no_console_suspend to debug)
Jul 22 13:53:09 arch kernel: serial 00:02: disabled
Jul 22 13:53:09 arch kernel: parport_pc 00:01: disabled
Jul 22 13:53:09 arch kernel: ACPI: PM: Preparing to enter system sleep state S3
Jul 22 13:53:09 arch kernel: ACPI: PM: Saving platform NVS memory
Jul 22 13:53:09 arch kernel: Disabling non-boot CPUs ...
Jul 22 13:53:09 arch kernel: smpboot: CPU 1 is now offline
Jul 22 13:53:09 arch kernel: smpboot: CPU 2 is now offline
Jul 22 13:53:09 arch kernel: smpboot: CPU 3 is now offline
Jul 22 13:53:09 arch kernel: smpboot: CPU 4 is now offline
Jul 22 13:53:09 arch kernel: smpboot: CPU 5 is now offline
Jul 22 13:53:09 arch kernel: ACPI: PM: Low-level resume complete
Jul 22 13:53:09 arch kernel: ACPI: PM: Restoring platform NVS memory
Jul 22 13:53:09 arch kernel: Enabling non-boot CPUs ...
Jul 22 13:53:09 arch kernel: x86: Booting SMP configuration:
Jul 22 13:53:09 arch kernel: smpboot: Booting Node 0 Processor 1 APIC 0x2
Jul 22 13:53:09 arch kernel: CPU1 is up
Jul 22 13:53:09 arch kernel: smpboot: Booting Node 0 Processor 2 APIC 0x4
Jul 22 13:53:09 arch kernel: CPU2 is up
Jul 22 13:53:09 arch kernel: smpboot: Booting Node 0 Processor 3 APIC 0x6
Jul 22 13:53:09 arch kernel: CPU3 is up
Jul 22 13:53:09 arch kernel: smpboot: Booting Node 0 Processor 4 APIC 0x8
Jul 22 13:53:09 arch kernel: CPU4 is up
Jul 22 13:53:09 arch kernel: smpboot: Booting Node 0 Processor 5 APIC 0xa
Jul 22 13:53:09 arch kernel: CPU5 is up
Jul 22 13:53:09 arch kernel: ACPI: PM: Waking up from system sleep state S3
Jul 22 13:53:09 arch kernel: parport_pc 00:01: activated
Jul 22 13:53:09 arch kernel: serial 00:02: activated
Jul 22 13:53:09 arch kernel: xhci_hcd 0000:01:00.2: xHC error in resume, USBSTS 0x401, Reinit
Jul 22 13:53:09 arch kernel: usb usb3: root hub lost power or was reset
Jul 22 13:53:09 arch kernel: usb usb4: root hub lost power or was reset
Jul 22 13:53:09 arch kernel: nvme nvme0: 6/0/0 default/read/poll queues
Jul 22 13:53:09 arch kernel: OOM killer enabled.
Jul 22 13:53:09 arch kernel: Restarting tasks ... 
Jul 22 13:53:09 arch kernel: audit: type=1326 audit(1690014189.730:2): auid=1000 uid=1000 gid=1000 ses=1 pid=919 comm="zathura" exe="/usr/bin/zathura" sig=31 arch=c000003e syscall=219 compat=0 ip=0x7fefe99a2c0f code=0x80000000
Jul 22 13:53:09 arch kernel: done.
Jul 22 13:53:09 arch kernel: random: crng reseeded on system resumption
Jul 22 13:53:09 arch bluetoothd[539]: Controller resume with wake event 0x0
Jul 22 13:53:09 arch systemd-sleep[992]: System returned from sleep state.
Jul 22 13:53:09 arch kernel: PM: suspend exit
Jul 22 13:53:09 arch systemd[1]: systemd-suspend.service: Deactivated successfully.
Jul 22 13:53:09 arch systemd[1]: Finished System Suspend.
Jul 22 13:53:09 arch systemd[1]: Stopped target Sleep.
Jul 22 13:53:09 arch systemd[1]: Reached target Suspend.
Jul 22 13:53:09 arch systemd[1]: Stopped target Suspend.
Jul 22 13:53:09 arch systemd-logind[542]: Operation 'sleep' finished.
sebastinas commented 1 year ago

On GitLab by @valoq on Jul 26, 2023, 13:26

This journal log has nothing about zathura in it. I suspect the issue is unrelated to zathura but if not there might be something in the trace logs.

try:

strace -o logfile -f /usr/bin/zathura targetfile

And attach the logfile here please

sebastinas commented 1 year ago

On GitLab by @asklow on Jul 26, 2023, 15:53

$ strace -o log -f /bin/zathura targetfile  
Bad system call

https://pastebin.com/nrisNxYj

sebastinas commented 1 year ago

On GitLab by @asklow on Jul 26, 2023, 16:00

I don't think it's my system issue. Only zathura instances close after resume. No other program I've used as of now, behaved this way.

sebastinas commented 1 year ago

On GitLab by @valoq on Jul 26, 2023, 16:24

This might be caused by the sandbox. Do you have it set to strict? Please try running zathura with the following setting in ~/.config/zathura/zathurarc

set sandbox none

If that works, you could try uncommenting the following line https://git.pwmt.org/pwmt/zathura/-/blob/develop/zathura/seccomp-filters.c#L222 and rebuild zathura with that modification to see if that solves it.

meson build
cd build
ninja
./zathura --plugins-dir=/usr/lib/zathura/ testfile.pdf
sebastinas commented 1 year ago

On GitLab by @asklow on Jul 27, 2023, 05:37

Oh, I haven't noticed it. I've set sandbox strict in my zathura config, somehow thinking sandboxing gives more safety. Haven't thought it'll be this strict :rofl:

sebastinas commented 1 year ago

On GitLab by @valoq on Jul 27, 2023, 12:01

It should not prevent the recovery from suspense. Did you try the change I suggested? It would be good to know if allowing the restart syscall solves the issue for you.

sebastinas commented 1 year ago

mentioned in commit 6154ef705097b1a8eb5d381c365058aeeb2c5141

sebastinas commented 1 year ago

On GitLab by @asklow on Jul 28, 2023, 01:57

Haven't tried. Might wanna try some other time, as the current issue is solved caz of desandboxing.