You are not logged in.

Pages: 1

#1 2022-11-26 19:44:44

eda2z
Member
From: Woodstock, IL
Registered: 2015-04-21
Posts: 69

[Solved] systemd daemon-reload hang - netplan bridge mul net daemons

Recently I noticed that after updating my system (sudo pacman -Syu) when the post install task (reloading system manager configuration...) ran that there was a noticeable delay of over 1 minute. I determined that this pacman hook called systemctl daemon-reload and if I ran this I got the same delay. I also noticed the same delay if I ran either enable or disable. For example:

[root@spike ~]# time systemctl disable postgresql.service
Removed "/etc/systemd/system/multi-user.target.wants/postgresql.service".

real	1m0.507s
user	0m0.009s
sys	0m0.004s

[root@spike ~]# time systemctl enable postgresql.service
Created symlink /etc/systemd/system/multi-user.target.wants/postgresql.service -> /usr/lib/systemd/system/postgresql.service.

real	1m0.254s
user	0m0.004s
sys	0m0.009

In both cases the message was displayed immediately. I could not find anything with journalctl. Any ideas?

Last edited by eda2z (2022-11-28 20:14:54)

Offline

#2 2022-11-26 20:28:30

Maniaxx
Member
Registered: 2014-05-14
Posts: 757

Re: [Solved] systemd daemon-reload hang - netplan bridge mul net daemons

Systemd has been updated. As a core component it probably needs a reboot to finish properly.
Also check that '/etc/mkinitcpio.conf.pacnew' is solved (don't forget to regenerate initramfs).

Last edited by Maniaxx (2022-11-26 20:35:13)

sys2064

Offline

#3 2022-11-26 21:30:58

eda2z
Member
From: Woodstock, IL
Registered: 2015-04-21
Posts: 69

Re: [Solved] systemd daemon-reload hang - netplan bridge mul net daemons

Thanks but it made no difference. My system was updated but I still regenerated initramfs. Some other weirdness - I have a laptop which has the same packages installed and it does not exhibit the problem; and when the system is hanging on an enable/disable I can open another terminal window (Gnome) but I cannot even enter "ls" in the window.

Offline

#4 2022-11-27 00:33:18

Maniaxx
Member
Registered: 2014-05-14
Posts: 757

Re: [Solved] systemd daemon-reload hang - netplan bridge mul net daemons

Maybe do a fsck on the drive.
What happens when you create the link manually?
Check the drive/filesystem for free space (especially free inodes).

Last edited by Maniaxx (2022-11-27 00:36:57)

sys2064

Offline

#5 2022-11-27 04:00:30

cfr
Member
From: Cymru
Registered: 2011-11-27
Posts: 7,148

Re: [Solved] systemd daemon-reload hang - netplan bridge mul net daemons

eda2z wrote:

I could not find anything with journalctl. Any ideas?

In that case, only if you are not both an expert and infallible would it be worthwhile to post the journal. wink
People are likely to have more ideas if you provide them with the information. Presumably, you're asking because you hope somebody will spot something you haven't. The less you provide, the less there is to spot.

Last edited by cfr (2022-11-27 04:02:31)

CLI Paste | How To Ask Questions

Arch Linux | x86_64 | GPT | EFI boot | refind | stub loader | systemd | LVM2 on LUKS
Lenovo x270 | Intel(R) Core(TM) i5-7200U CPU @ 2.50GHz | Intel Wireless 8265/8275 | US keyboard w/ Euro | 512G NVMe INTEL SSDPEKKF512G7L

Offline

#6 2022-11-27 15:47:21

eda2z
Member
From: Woodstock, IL
Registered: 2015-04-21
Posts: 69

Re: [Solved] systemd daemon-reload hang - netplan bridge mul net daemons

fsck on the drive showed no errors.

creation and removal of the link returns instantly.

free space on the drive looks good:

[ed@spike ~]$ stat -f /dev/nvme0n1p2
  File: "/dev/nvme0n1p2"
    ID: aded86dbe1adc2f1 Namelen: 255     Type: tmpfs
Block size: 4096       Fundamental block size: 4096
Blocks: Total: 2007883    Free: 2007883    Available: 2007883
Inodes: Total: 2007883    Free: 2007270

If I re-run the tests:

[root@spike ~]# date
Sun Nov 27 09:15:48 AM CST 2022
[root@spike ~]# time systemctl disable postgresql.service
Removed "/etc/systemd/system/multi-user.target.wants/postgresql.service".

real	1m0.424s
user	0m0.006s
sys	0m0.009s
[root@spike ~]# time systemctl enable postgresql.service
Created symlink /etc/systemd/system/multi-user.target.wants/postgresql.service -> /usr/lib/systemd/system/postgresql.service.

real	1m0.325s
user	0m0.012s
sys	0m0.003s
[root@spike ~]# date
Sun Nov 27 09:18:13 AM CST 2022

I get the following journal for that time period:

Nov 27 09:15:35 spike gnome-character[1736]: JS LOG: Characters Application exiting
Nov 27 09:15:42 spike audit[2215]: USER_AUTH pid=2215 uid=1000 auid=1000 ses=4 msg='op=PAM:authentication grantors=pam_unix acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=/dev/pts/0 res=success'
Nov 27 09:15:42 spike audit[2215]: USER_ACCT pid=2215 uid=1000 auid=1000 ses=4 msg='op=PAM:accounting grantors=pam_unix acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=/dev/pts/0 res=success'
Nov 27 09:15:42 spike su[2215]: (to root) ed on pts/0
Nov 27 09:15:42 spike kernel: audit: type=1100 audit(1669562142.728:100): pid=2215 uid=1000 auid=1000 ses=4 msg='op=PAM:authentication grantors=pam_unix acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=/dev/pts/0 res=success'
Nov 27 09:15:42 spike kernel: audit: type=1101 audit(1669562142.728:101): pid=2215 uid=1000 auid=1000 ses=4 msg='op=PAM:accounting grantors=pam_unix acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=/dev/pts/0 res=success'
Nov 27 09:15:42 spike kernel: audit: type=1103 audit(1669562142.728:102): pid=2215 uid=1000 auid=1000 ses=4 msg='op=PAM:setcred grantors=pam_unix acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=/dev/pts/0 res=success'
Nov 27 09:15:42 spike kernel: audit: type=1105 audit(1669562142.728:103): pid=2215 uid=1000 auid=1000 ses=4 msg='op=PAM:session_open grantors=pam_unix acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=/dev/pts/0 res=success'
Nov 27 09:15:42 spike audit[2215]: CRED_ACQ pid=2215 uid=1000 auid=1000 ses=4 msg='op=PAM:setcred grantors=pam_unix acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=/dev/pts/0 res=success'
Nov 27 09:15:42 spike audit[2215]: USER_START pid=2215 uid=1000 auid=1000 ses=4 msg='op=PAM:session_open grantors=pam_unix acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=/dev/pts/0 res=success'
Nov 27 09:15:42 spike su[2215]: pam_unix(su-l:session): session opened for user root(uid=0) by (uid=1000)
Nov 27 09:15:47 spike systemd[1]: systemd-localed.service: Deactivated successfully.
Nov 27 09:15:47 spike audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-localed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 27 09:15:47 spike kernel: audit: type=1131 audit(1669562147.344:104): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-localed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 27 09:15:47 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:15:47 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:15:47 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:15:47 spike kernel: audit: type=1334 audit(1669562147.448:105): prog-id=0 op=UNLOAD
Nov 27 09:15:47 spike kernel: audit: type=1334 audit(1669562147.448:106): prog-id=0 op=UNLOAD
Nov 27 09:15:47 spike kernel: audit: type=1334 audit(1669562147.448:107): prog-id=0 op=UNLOAD
Nov 27 09:15:54 spike systemd[1]: systemd-hostnamed.service: Deactivated successfully.
Nov 27 09:15:54 spike audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 27 09:15:54 spike kernel: audit: type=1131 audit(1669562154.598:108): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 27 09:15:54 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:15:54 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:15:54 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:15:54 spike kernel: audit: type=1334 audit(1669562154.694:109): prog-id=0 op=UNLOAD
Nov 27 09:15:54 spike kernel: audit: type=1334 audit(1669562154.694:110): prog-id=0 op=UNLOAD
Nov 27 09:15:54 spike kernel: audit: type=1334 audit(1669562154.694:111): prog-id=0 op=UNLOAD
Nov 27 09:15:55 spike systemd[1]: systemd-timedated.service: Deactivated successfully.
Nov 27 09:15:55 spike audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-timedated comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 27 09:15:55 spike kernel: audit: type=1131 audit(1669562155.441:112): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-timedated comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 27 09:15:55 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:15:55 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:15:55 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:15:55 spike kernel: audit: type=1334 audit(1669562155.478:113): prog-id=0 op=UNLOAD
Nov 27 09:15:55 spike kernel: audit: type=1334 audit(1669562155.478:114): prog-id=0 op=UNLOAD
Nov 27 09:15:55 spike kernel: audit: type=1334 audit(1669562155.478:115): prog-id=0 op=UNLOAD
Nov 27 09:15:55 spike systemd-timesyncd[476]: Contacted time server 209.51.161.238:123 (0.arch.pool.ntp.org).
Nov 27 09:15:55 spike systemd-timesyncd[476]: Initial clock synchronization to Sun 2022-11-27 09:15:55.985275 CST.
Nov 27 09:15:57 spike systemd[1]: Reloading.
Nov 27 09:16:58 spike audit: BPF prog-id=31 op=LOAD
Nov 27 09:16:58 spike kernel: audit: type=1334 audit(1669562218.370:116): prog-id=31 op=LOAD
Nov 27 09:16:58 spike kernel: audit: type=1334 audit(1669562218.370:117): prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike audit: BPF prog-id=32 op=LOAD
Nov 27 09:16:58 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike audit: BPF prog-id=33 op=LOAD
Nov 27 09:16:58 spike audit: BPF prog-id=34 op=LOAD
Nov 27 09:16:58 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike audit: BPF prog-id=35 op=LOAD
Nov 27 09:16:58 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike audit: BPF prog-id=36 op=LOAD
Nov 27 09:16:58 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike audit: BPF prog-id=37 op=LOAD
Nov 27 09:16:58 spike kernel: audit: type=1334 audit(1669562218.373:118): prog-id=32 op=LOAD
Nov 27 09:16:58 spike kernel: audit: type=1334 audit(1669562218.373:119): prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike kernel: audit: type=1334 audit(1669562218.373:120): prog-id=33 op=LOAD
Nov 27 09:16:58 spike kernel: audit: type=1334 audit(1669562218.373:121): prog-id=34 op=LOAD
Nov 27 09:16:58 spike kernel: audit: type=1334 audit(1669562218.373:122): prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike kernel: audit: type=1334 audit(1669562218.373:123): prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike kernel: audit: type=1334 audit(1669562218.373:124): prog-id=35 op=LOAD
Nov 27 09:16:58 spike kernel: audit: type=1334 audit(1669562218.373:125): prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike audit: BPF prog-id=38 op=LOAD
Nov 27 09:16:58 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike audit: BPF prog-id=39 op=LOAD
Nov 27 09:16:58 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike audit: BPF prog-id=40 op=LOAD
Nov 27 09:16:58 spike audit: BPF prog-id=41 op=LOAD
Nov 27 09:16:58 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike audit: BPF prog-id=42 op=LOAD
Nov 27 09:16:58 spike audit: BPF prog-id=43 op=LOAD
Nov 27 09:16:58 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike audit: BPF prog-id=44 op=LOAD
Nov 27 09:16:58 spike audit: BPF prog-id=45 op=LOAD
Nov 27 09:16:58 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike audit: BPF prog-id=46 op=LOAD
Nov 27 09:16:58 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:17:02 spike systemd[1]: libvirtd.service: Deactivated successfully.
Nov 27 09:17:01 spike audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=libvirtd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 27 09:17:08 spike systemd[1]: Reloading.
Nov 27 09:18:09 spike audit: BPF prog-id=47 op=LOAD
Nov 27 09:18:09 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike audit: BPF prog-id=48 op=LOAD
Nov 27 09:18:09 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike audit: BPF prog-id=49 op=LOAD
Nov 27 09:18:09 spike audit: BPF prog-id=50 op=LOAD
Nov 27 09:18:09 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike audit: BPF prog-id=51 op=LOAD
Nov 27 09:18:09 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike kernel: kauditd_printk_skb: 23 callbacks suppressed
Nov 27 09:18:09 spike kernel: audit: type=1334 audit(1669562289.119:149): prog-id=47 op=LOAD
Nov 27 09:18:09 spike kernel: audit: type=1334 audit(1669562289.119:150): prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike kernel: audit: type=1334 audit(1669562289.119:151): prog-id=48 op=LOAD
Nov 27 09:18:09 spike kernel: audit: type=1334 audit(1669562289.119:152): prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike kernel: audit: type=1334 audit(1669562289.119:153): prog-id=49 op=LOAD
Nov 27 09:18:09 spike kernel: audit: type=1334 audit(1669562289.119:154): prog-id=50 op=LOAD
Nov 27 09:18:09 spike kernel: audit: type=1334 audit(1669562289.119:155): prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike kernel: audit: type=1334 audit(1669562289.119:156): prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike kernel: audit: type=1334 audit(1669562289.119:157): prog-id=51 op=LOAD
Nov 27 09:18:09 spike kernel: audit: type=1334 audit(1669562289.119:158): prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike audit: BPF prog-id=52 op=LOAD
Nov 27 09:18:09 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike audit: BPF prog-id=53 op=LOAD
Nov 27 09:18:09 spike audit: BPF prog-id=54 op=LOAD
Nov 27 09:18:09 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike audit: BPF prog-id=55 op=LOAD
Nov 27 09:18:09 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike audit: BPF prog-id=56 op=LOAD
Nov 27 09:18:09 spike audit: BPF prog-id=57 op=LOAD
Nov 27 09:18:09 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike audit: BPF prog-id=58 op=LOAD
Nov 27 09:18:09 spike audit: BPF prog-id=59 op=LOAD
Nov 27 09:18:09 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike audit: BPF prog-id=60 op=LOAD
Nov 27 09:18:09 spike audit: BPF prog-id=61 op=LOAD
Nov 27 09:18:09 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike audit: BPF prog-id=62 op=LOAD
Nov 27 09:18:09 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:18:32 spike systemd[951]: Started Application launched by gnome-shell.
Nov 27 09:18:33 spike systemd[951]: Started VTE child process 2320 launched by gnome-terminal-server process 1747.
Nov 27 09:19:05 spike dbus-daemon[968]: [session uid=1000 pid=968] Activating via systemd: service name='org.freedesktop.Tracker3.Miner.Extract' unit='tracker-extract-3.service' requested by ':1.71' (uid=1000 pid=1766 comm="/usr/lib/tracker-miner-fs-3")
Nov 27 09:19:05 spike systemd[951]: Starting Tracker metadata extractor...
Nov 27 09:19:05 spike dbus-daemon[968]: [session uid=1000 pid=968] Successfully activated service 'org.freedesktop.Tracker3.Miner.Extract'
Nov 27 09:19:05 spike systemd[951]: Started Tracker metadata extractor.
Nov 27 09:19:16 spike audit[2524]: USER_AUTH pid=2524 uid=1000 auid=1000 ses=4 msg='op=PAM:authentication grantors=pam_unix acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=/dev/pts/1 res=success'
Nov 27 09:19:16 spike kernel: kauditd_printk_skb: 22 callbacks suppressed
Nov 27 09:19:16 spike kernel: audit: type=1100 audit(1669562356.186:181): pid=2524 uid=1000 auid=1000 ses=4 msg='op=PAM:authentication grantors=pam_unix acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=/dev/pts/1 res=success'
Nov 27 09:19:16 spike kernel: audit: type=1101 audit(1669562356.186:182): pid=2524 uid=1000 auid=1000 ses=4 msg='op=PAM:accounting grantors=pam_unix acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=/dev/pts/1 res=success'
Nov 27 09:19:16 spike kernel: audit: type=1103 audit(1669562356.189:183): pid=2524 uid=1000 auid=1000 ses=4 msg='op=PAM:setcred grantors=pam_unix acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=/dev/pts/1 res=success'
Nov 27 09:19:16 spike kernel: audit: type=1105 audit(1669562356.189:184): pid=2524 uid=1000 auid=1000 ses=4 msg='op=PAM:session_open grantors=pam_unix acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=/dev/pts/1 res=success'
Nov 27 09:19:16 spike audit[2524]: USER_ACCT pid=2524 uid=1000 auid=1000 ses=4 msg='op=PAM:accounting grantors=pam_unix acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=/dev/pts/1 res=success'
Nov 27 09:19:16 spike audit[2524]: CRED_ACQ pid=2524 uid=1000 auid=1000 ses=4 msg='op=PAM:setcred grantors=pam_unix acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=/dev/pts/1 res=success'
Nov 27 09:19:16 spike audit[2524]: USER_START pid=2524 uid=1000 auid=1000 ses=4 msg='op=PAM:session_open grantors=pam_unix acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=/dev/pts/1 res=success'
Nov 27 09:19:16 spike su[2524]: (to root) ed on pts/1
Nov 27 09:19:16 spike su[2524]: pam_unix(su-l:session): session opened for user root(uid=0) by (uid=1000)
Nov 27 09:21:02 spike systemd[1]: Reloading.
Nov 27 09:22:03 spike audit: BPF prog-id=63 op=LOAD
Nov 27 09:22:03 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike audit: BPF prog-id=64 op=LOAD
Nov 27 09:22:03 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike audit: BPF prog-id=65 op=LOAD
Nov 27 09:22:03 spike kernel: audit: type=1334 audit(1669562523.121:185): prog-id=63 op=LOAD
Nov 27 09:22:03 spike kernel: audit: type=1334 audit(1669562523.121:186): prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike kernel: audit: type=1334 audit(1669562523.121:187): prog-id=64 op=LOAD
Nov 27 09:22:03 spike kernel: audit: type=1334 audit(1669562523.121:188): prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike kernel: audit: type=1334 audit(1669562523.121:189): prog-id=65 op=LOAD
Nov 27 09:22:03 spike kernel: audit: type=1334 audit(1669562523.124:190): prog-id=66 op=LOAD
Nov 27 09:22:03 spike kernel: audit: type=1334 audit(1669562523.124:191): prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike kernel: audit: type=1334 audit(1669562523.124:192): prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike audit: BPF prog-id=66 op=LOAD
Nov 27 09:22:03 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike audit: BPF prog-id=67 op=LOAD
Nov 27 09:22:03 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike audit: BPF prog-id=68 op=LOAD
Nov 27 09:22:03 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike audit: BPF prog-id=69 op=LOAD
Nov 27 09:22:03 spike audit: BPF prog-id=70 op=LOAD
Nov 27 09:22:03 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike kernel: audit: type=1334 audit(1669562523.124:193): prog-id=67 op=LOAD
Nov 27 09:22:03 spike kernel: audit: type=1334 audit(1669562523.124:194): prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike audit: BPF prog-id=71 op=LOAD
Nov 27 09:22:03 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike audit: BPF prog-id=72 op=LOAD
Nov 27 09:22:03 spike audit: BPF prog-id=73 op=LOAD
Nov 27 09:22:03 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike audit: BPF prog-id=74 op=LOAD
Nov 27 09:22:03 spike audit: BPF prog-id=75 op=LOAD
Nov 27 09:22:03 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike audit: BPF prog-id=76 op=LOAD
Nov 27 09:22:03 spike audit: BPF prog-id=77 op=LOAD
Nov 27 09:22:03 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike audit: BPF prog-id=78 op=LOAD
Nov 27 09:22:03 spike audit: BPF prog-id=0 op=UNLOAD

Offline

#7 2022-11-27 23:28:31

cfr
Member
From: Cymru
Registered: 2011-11-27
Posts: 7,148

Re: [Solved] systemd daemon-reload hang - netplan bridge mul net daemons

eda2z wrote:

free space on the drive looks good:

[ed@spike ~]$ stat -f /dev/nvme0n1p2
  File: "/dev/nvme0n1p2"
    ID: aded86dbe1adc2f1 Namelen: 255     Type: tmpfs
Block size: 4096       Fundamental block size: 4096
Blocks: Total: 2007883    Free: 2007883    Available: 2007883
Inodes: Total: 2007883    Free: 2007270

Read that output again. You can see it isn't telling you anything about your root partition: *all* of the blocks are free and the file system type is tmpfs. 

df -h
lsblk -f

will tell you how much space you have, though I don't think it will report inodes.

The journal snippet you posted shows nothing about manipulating the postgresql.service.

Last edited by cfr (2022-11-27 23:32:38)

CLI Paste | How To Ask Questions

Arch Linux | x86_64 | GPT | EFI boot | refind | stub loader | systemd | LVM2 on LUKS
Lenovo x270 | Intel(R) Core(TM) i5-7200U CPU @ 2.50GHz | Intel Wireless 8265/8275 | US keyboard w/ Euro | 512G NVMe INTEL SSDPEKKF512G7L

Offline

#8 2022-11-28 00:10:58

eda2z
Member
From: Woodstock, IL
Registered: 2015-04-21
Posts: 69

Re: [Solved] systemd daemon-reload hang - netplan bridge mul net daemons

free space and inode info:

root@spike ~]# df -h
Filesystem      Size  Used Avail Use% Mounted on
dev             7.7G     0  7.7G   0% /dev
run             7.7G  1.9M  7.7G   1% /run
/dev/nvme0n1p2  468G  141G  304G  32% /
tmpfs           7.7G  183M  7.6G   3% /dev/shm
tmpfs           7.7G  2.2M  7.7G   1% /tmp
/dev/sdb1       916G  363G  507G  42% /mnt/xdrive
/dev/sda1       916G  251G  620G  29% /spare
/dev/nvme0n1p1  746M   52M  695M   7% /efi
tmpfs           1.6G   72K  1.6G   1% /run/user/1000
[root@spike ~]# df -ih
Filesystem     Inodes IUsed IFree IUse% Mounted on
dev              2.0M   613  2.0M    1% /dev
run              2.0M  1.1K  2.0M    1% /run
/dev/nvme0n1p2    30M  633K   30M    3% /
tmpfs            2.0M   845  2.0M    1% /dev/shm
tmpfs            1.0M    40  1.0M    1% /tmp
/dev/sdb1         59M  323K   58M    1% /mnt/xdrive
/dev/sda1         59M   85K   59M    1% /spare
/dev/nvme0n1p1      0     0     0     - /efi
tmpfs            394K   115  394K    1% /run/user/1000
[root@spike ~]# lsblk -f
NAME        FSTYPE FSVER LABEL  UUID                                 FSAVAIL FSUSE% MOUNTPOINTS
sda                                                                                 
└─sda1      ext4   1.0          ea8cb5f3-1cee-45ea-857c-da18d070ccd5    619G    27% /spare
sdb                                                                                 
└─sdb1      ext4   1.0   MyBook dbf35e43-9443-4931-afd4-39bd32aef8b3  506.5G    40% /mnt/xdrive
sr0                                                                                 
nvme0n1                                                                             
├─nvme0n1p1 vfat   FAT32 ESP    1455-F4BB                             694.1M     7% /efi
└─nvme0n1p2 ext4   1.0          165f0ea0-97d7-4e1e-9756-c1f01c099c38  303.5G    30% /

postgresql specific journal entries for today:

[root@spike ~]# journalctl -S today -u postgresql.service
Nov 27 08:45:24 spike systemd[1]: Stopping PostgreSQL database server...
Nov 27 08:45:24 spike postgres[556]: 2022-11-27 08:45:24.137 CST [556] LOG:  received fast shutdown request
Nov 27 08:45:24 spike postgres[556]: 2022-11-27 08:45:24.144 CST [556] LOG:  aborting any active transactions
Nov 27 08:45:24 spike postgres[556]: 2022-11-27 08:45:24.150 CST [556] LOG:  background worker "logical replication launcher" (PID 606) exited with exit code 1
Nov 27 08:45:24 spike postgres[601]: 2022-11-27 08:45:24.150 CST [601] LOG:  shutting down
Nov 27 08:45:24 spike postgres[556]: 2022-11-27 08:45:24.196 CST [556] LOG:  database system is shut down
Nov 27 08:45:24 spike systemd[1]: postgresql.service: Deactivated successfully.
Nov 27 08:45:24 spike systemd[1]: Stopped PostgreSQL database server.
Nov 27 08:45:24 spike systemd[1]: postgresql.service: Consumed 22.039s CPU time.
-- Boot daa53010c29b4192b71957cbfba1b335 --
Nov 27 08:50:36 spike systemd[1]: Starting PostgreSQL database server...
Nov 27 08:50:36 spike postgres[547]: 2022-11-27 08:50:36.483 CST [547] LOG:  starting PostgreSQL 14.6 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 12.2.0, 64-bit
Nov 27 08:50:36 spike postgres[547]: 2022-11-27 08:50:36.485 CST [547] LOG:  listening on IPv6 address "::1", port 5432
Nov 27 08:50:36 spike postgres[547]: 2022-11-27 08:50:36.485 CST [547] LOG:  listening on IPv4 address "127.0.0.1", port 5432
Nov 27 08:50:36 spike postgres[547]: 2022-11-27 08:50:36.490 CST [547] LOG:  listening on Unix socket "/run/postgresql/.s.PGSQL.5432"
Nov 27 08:50:36 spike postgres[592]: 2022-11-27 08:50:36.503 CST [592] LOG:  database system was shut down at 2022-11-27 08:45:24 CST
Nov 27 08:50:36 spike postgres[547]: 2022-11-27 08:50:36.513 CST [547] LOG:  database system is ready to accept connections
Nov 27 08:50:36 spike systemd[1]: Started PostgreSQL database server.
Nov 27 09:14:16 spike postgres[547]: 2022-11-27 09:14:16.003 CST [547] LOG:  received fast shutdown request
Nov 27 09:14:16 spike systemd[1]: Stopping PostgreSQL database server...
Nov 27 09:14:16 spike postgres[547]: 2022-11-27 09:14:16.007 CST [547] LOG:  aborting any active transactions
Nov 27 09:14:16 spike postgres[547]: 2022-11-27 09:14:16.009 CST [547] LOG:  background worker "logical replication launcher" (PID 602) exited with exit code 1
Nov 27 09:14:16 spike postgres[597]: 2022-11-27 09:14:16.013 CST [597] LOG:  shutting down
Nov 27 09:14:16 spike postgres[547]: 2022-11-27 09:14:16.056 CST [547] LOG:  database system is shut down
Nov 27 09:14:16 spike systemd[1]: postgresql.service: Deactivated successfully.
Nov 27 09:14:16 spike systemd[1]: Stopped PostgreSQL database server.
-- Boot 1ee61d59969f4531b03a0d4d6abfaab4 --
Nov 27 09:15:02 spike systemd[1]: Starting PostgreSQL database server...
Nov 27 09:15:02 spike postgres[546]: 2022-11-27 09:15:02.392 CST [546] LOG:  starting PostgreSQL 14.6 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 12.2.0, 64-bit
Nov 27 09:15:02 spike postgres[546]: 2022-11-27 09:15:02.395 CST [546] LOG:  listening on IPv6 address "::1", port 5432
Nov 27 09:15:02 spike postgres[546]: 2022-11-27 09:15:02.395 CST [546] LOG:  listening on IPv4 address "127.0.0.1", port 5432
Nov 27 09:15:02 spike postgres[546]: 2022-11-27 09:15:02.399 CST [546] LOG:  listening on Unix socket "/run/postgresql/.s.PGSQL.5432"
Nov 27 09:15:02 spike postgres[585]: 2022-11-27 09:15:02.409 CST [585] LOG:  database system was shut down at 2022-11-27 09:14:16 CST
Nov 27 09:15:02 spike postgres[546]: 2022-11-27 09:15:02.419 CST [546] LOG:  database system is ready to accept connections
Nov 27 09:15:02 spike systemd[1]: Started PostgreSQL database server.
Nov 27 09:25:35 spike systemd[1]: Stopping PostgreSQL database server...
Nov 27 09:25:35 spike postgres[546]: 2022-11-27 09:25:35.209 CST [546] LOG:  received fast shutdown request
Nov 27 09:25:35 spike postgres[546]: 2022-11-27 09:25:35.213 CST [546] LOG:  aborting any active transactions
Nov 27 09:25:35 spike postgres[546]: 2022-11-27 09:25:35.214 CST [546] LOG:  background worker "logical replication launcher" (PID 592) exited with exit code 1
Nov 27 09:25:35 spike postgres[587]: 2022-11-27 09:25:35.221 CST [587] LOG:  shutting down
Nov 27 09:25:35 spike postgres[546]: 2022-11-27 09:25:35.261 CST [546] LOG:  database system is shut down
Nov 27 09:25:35 spike systemd[1]: postgresql.service: Deactivated successfully.
Nov 27 09:25:35 spike systemd[1]: Stopped PostgreSQL database server.
-- Boot dae7d0d44d3c4304a74d5f682aac0104 --
Nov 27 09:26:21 spike systemd[1]: Starting PostgreSQL database server...
Nov 27 09:26:21 spike postgres[563]: 2022-11-27 09:26:21.398 CST [563] LOG:  starting PostgreSQL 14.6 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 12.2.0, 64-bit
Nov 27 09:26:21 spike postgres[563]: 2022-11-27 09:26:21.400 CST [563] LOG:  listening on IPv6 address "::1", port 5432
Nov 27 09:26:21 spike postgres[563]: 2022-11-27 09:26:21.400 CST [563] LOG:  listening on IPv4 address "127.0.0.1", port 5432
Nov 27 09:26:21 spike postgres[563]: 2022-11-27 09:26:21.403 CST [563] LOG:  listening on Unix socket "/run/postgresql/.s.PGSQL.5432"
Nov 27 09:26:21 spike postgres[601]: 2022-11-27 09:26:21.415 CST [601] LOG:  database system was shut down at 2022-11-27 09:25:35 CST
Nov 27 09:26:21 spike postgres[563]: 2022-11-27 09:26:21.427 CST [563] LOG:  database system is ready to accept connections
Nov 27 09:26:21 spike systemd[1]: Started PostgreSQL database server.
Nov 27 09:28:43 spike postgres[563]: 2022-11-27 09:28:43.427 CST [563] LOG:  received fast shutdown request
Nov 27 09:28:43 spike systemd[1]: Stopping PostgreSQL database server...
Nov 27 09:28:43 spike postgres[563]: 2022-11-27 09:28:43.430 CST [563] LOG:  aborting any active transactions
Nov 27 09:28:43 spike postgres[563]: 2022-11-27 09:28:43.431 CST [563] LOG:  background worker "logical replication launcher" (PID 609) exited with exit code 1
Nov 27 09:28:43 spike postgres[604]: 2022-11-27 09:28:43.431 CST [604] LOG:  shutting down
Nov 27 09:28:43 spike postgres[563]: 2022-11-27 09:28:43.465 CST [563] LOG:  database system is shut down
Nov 27 09:28:43 spike systemd[1]: postgresql.service: Deactivated successfully.
Nov 27 09:28:43 spike systemd[1]: Stopped PostgreSQL database server.

If my understanding of systemctl enable/disable is correct then all it should be doing in creating and removing a link and thus there should be no journal entries for that - which there are not. Also if all systemd is doing in creating/removing a link why can I do it instantly but systemd hangs for almost a minute *after* displaying what it has done.

Offline

#9 2022-11-28 00:41:12

Maniaxx
Member
Registered: 2014-05-14
Posts: 757

Re: [Solved] systemd daemon-reload hang - netplan bridge mul net daemons

Try an 'strace -v -f -s 256 -o /tmp/strace.log systemctl disable postgresql.service' and post the strace.log file. Let it run for the minute until it ends properly.

sys2064

Offline

#10 2022-11-28 10:58:38

seth
Member
Registered: 2012-09-03
Posts: 58,705

Re: [Solved] systemd daemon-reload hang - netplan bridge mul net daemons

systemctl will IPC talk to the damon and we already know that the dameon-reload is the slow part.

systemctl log-level # to note the original loglevel
systemctl log-level debug
systemctl daemon-reload
systemctl log-level info # i guess

Then inspect the system journal

Also if all systemd is doing in creating/removing a link why can I do it instantly but systemd hangs for almost a minute *after* displaying what it has done.

man systemctl wrote:

       --no-reload
           When used with enable and disable, do not implicitly reload daemon configuration after
           executing the changes.

How to upload text · How to boot w/o GUI · Disable Windows Fast-Start! · Fix your xinitrc

Online

#11 2022-11-28 17:10:11

eda2z
Member
From: Woodstock, IL
Registered: 2015-04-21
Posts: 69

Re: [Solved] systemd daemon-reload hang - netplan bridge mul net daemons

The strace log can be found at: https://0x0.st/o0bY.log

And the journal for running systemctl in debug mode can be found at: https://0x0.st/o0bg.txt

Thanks for the tip about --no-reload. I tried it and enable/disable worked instantly. I definitely need to read the man pages more closely.

Offline

#12 2022-11-28 17:19:15

seth
Member
Registered: 2012-09-03
Posts: 58,705

Re: [Solved] systemd daemon-reload hang - netplan bridge mul net daemons

Nov 28 09:32:29 spike systemd[2550]: /usr/lib/systemd/system-generators/systemd-system-update-generator succeeded.
Nov 28 09:33:29 spike systemd[2550]: /usr/lib/systemd/system-generators/netplan succeeded.

Somethingsomethingnetwork.

From the debug output it looks like there're multiple network daemons:

find /etc/systemd -type l -exec test -f {} \; -print | awk -F'/' '{ printf ("%-40s | %s\n", $(NF-0), $(NF-1)) }' | sort -f

How to upload text · How to boot w/o GUI · Disable Windows Fast-Start! · Fix your xinitrc

Online

#13 2022-11-28 18:58:56

eda2z
Member
From: Woodstock, IL
Registered: 2015-04-21
Posts: 69

Re: [Solved] systemd daemon-reload hang - netplan bridge mul net daemons

[root@spike ~]# find /etc/systemd -type l -exec test -f {} \; -print | awk -F'/' '{ printf ("%-40s | %s\n", $(NF-0), $(NF-1)) }' | sort -f
atd.service                              | multi-user.target.wants
bluetooth.service                        | bluetooth.target.wants
cups.socket                              | sockets.target.wants
dbus-org.bluez.service                   | system
dbus-org.freedesktop.nm-dispatcher.service | system
dbus-org.freedesktop.timesync1.service   | system
display-manager.service                  | system
fstrim.timer                             | timers.target.wants
gcr-ssh-agent.socket                     | sockets.target.wants
getty@tty1.service                       | getty.target.wants
gnome-keyring-daemon.socket              | sockets.target.wants
httpd.service                            | multi-user.target.wants
libvirtd-ro.socket                       | sockets.target.wants
libvirtd.service                         | multi-user.target.wants
libvirtd.socket                          | sockets.target.wants
lm_sensors.service                       | multi-user.target.wants
NetworkManager.service                   | multi-user.target.wants
NetworkManager-wait-online.service       | network-online.target.wants
p11-kit-server.socket                    | sockets.target.wants
pipewire-media-session.service           | pipewire.service.wants
pipewire-session-manager.service         | user
pipewire.socket                          | sockets.target.wants
pulseaudio.socket                        | sockets.target.wants
qxserver.service                         | multi-user.target.wants
reflector.timer                          | timers.target.wants
remote-fs.target                         | multi-user.target.wants
sshd.service                             | multi-user.target.wants
systemd-timesyncd.service                | sysinit.target.wants
virtlockd.socket                         | sockets.target.wants
virtlogd.socket                          | sockets.target.wants
xdg-user-dirs-update.service             | default.target.wants

Offline

#14 2022-11-28 19:16:30

seth
Member
Registered: 2012-09-03
Posts: 58,705

Re: [Solved] systemd daemon-reload hang - netplan bridge mul net daemons

Nope.
Temporarily get rid of https://archlinux.org/packages/communit … 4/netplan/ and see what happens.

How to upload text · How to boot w/o GUI · Disable Windows Fast-Start! · Fix your xinitrc

Online

#15 2022-11-28 19:42:23

eda2z
Member
From: Woodstock, IL
Registered: 2015-04-21
Posts: 69

Re: [Solved] systemd daemon-reload hang - netplan bridge mul net daemons

Thank you. That fixed the problem. daemon-reload returns immediately. I installed netplan to create a network bridge so that I could have my kvm guests on the same subnet as my host. It's weird since I installed netplan and created the bridge back on 9/18 but this problem only started occurring several weeks ago.

I was able to start the bridge with virsh and run a VM but I noticed that after a certain amount of time virsh showed the bridge becoming inactive by itself. I can easily do without the bridge if there is no way around it. Please let me know what you think.

Offline

#16 2022-11-28 19:53:28

seth
Member
Registered: 2012-09-03
Posts: 58,705

Re: [Solved] systemd daemon-reload hang - netplan bridge mul net daemons

netplan was updated Aug 22, 2022 - you could try to downgrade it to 0.104-1 from the ALA (or your cache)
I've never used netplan and no idea how it's related to a bridge.

https://wiki.archlinux.org/title/Network_bridge and configure your VM to use the bridge device (eg. br0), https://wiki.archlinux.org/title/Libvirt#Networking ??

Edit: either way please always remember to mark resolved threads by editing your initial posts subject - so others will know that there's no task left, but maybe a solution to find.
Thanks.
And in this case, maybe even mention the cause in the subject - netplan seems fringe (I wasn't even aware that it exists…)

Last edited by seth (2022-11-28 19:55:21)

How to upload text · How to boot w/o GUI · Disable Windows Fast-Start! · Fix your xinitrc

Online

#17 2022-11-28 20:09:39

eda2z
Member
From: Woodstock, IL
Registered: 2015-04-21
Posts: 69

Re: [Solved] systemd daemon-reload hang - netplan bridge mul net daemons

I'll clean-up my networking setup and check into the 2 links you mentioned. I'll admit that I got lazy and googled how to get the guests on the same subnet as the host. If you're curious - https://serverfault.com/questions/10754 … s-the-host. Thanks again.

Offline

#18 2022-12-04 05:19:00

babudro
Member
Registered: 2022-12-04
Posts: 1

Re: [Solved] systemd daemon-reload hang - netplan bridge mul net daemons

I appreciate the help on figuring out this 60s delay issue.  During that 60s a lot of things are blocked, even things like loading of web pages from that server, so that delay makes server administration during business hours a real problem.

For those like me who are using Arch on a VM:  I found that cloud-init pulls in netplan, so my solution was to take the static IP details in /etc/netplan/50-cloud-init.yaml and created a /etc/systemd/network/eth0.network to have all the same details in systemd format.  Then I did

pacman -R cloud-init netplan

and following that there was no more 60s delay when enabling and disabling services.

Offline

#19 2022-12-09 16:56:17

boris64
Member
Registered: 2015-08-06
Posts: 6

Re: [Solved] systemd daemon-reload hang - netplan bridge mul net daemons

babudro wrote:

I appreciate the help on figuring out this 60s delay issue.  During that 60s a lot of things are blocked, even things like loading of web pages from that server, so that delay makes server administration during business hours a real problem.

For those like me who are using Arch on a VM:  I found that cloud-init pulls in netplan, so my solution was to take the static IP details in /etc/netplan/50-cloud-init.yaml and created a /etc/systemd/network/eth0.network to have all the same details in systemd format.  Then I did

pacman -R cloud-init netplan

and following that there was no more 60s delay when enabling and disabling services.

Baah, that's it damned. Where can i get my lifetime back?
-> https://gitlab.archlinux.org/archlinux/ … issues/156

Offline

#20 2022-12-10 19:21:53

zoltix
Member
Registered: 2019-09-06
Posts: 17

Re: [Solved] systemd daemon-reload hang - netplan bridge mul net daemons

Hello, I had the same problem. In my case, netplan was installed by cloud-init(https://cloud-init.io/) with a dependency. In fact, my arch was installed by OVH and apparently they use cloud-init to configure it. I uninstalled cloud-init and that solved my problem. yay -rns cloud-init.  thank for this post.

Offline

Pages: 1

Board footer

Powered by FluxBB