fcron icon indicating copy to clipboard operation
fcron copied to clipboard

fcron (randomly?) fails running jobs after systemupdate

Open castilma opened this issue 3 years ago • 5 comments

Recently I noticed fcron to be unable to run jobs again, and I had to restart it.

2022-02-15 21:14:16  INFO fcron[961] 3.2.1 started
2022-02-15 21:14:16  INFO updating configuration from /var/spool/fcron
2022-02-15 21:14:16  INFO adding file mcd
2022-02-15 21:14:16  INFO adding file systab
2022-02-15 21:14:36  INFO Job '/usr/bin/run-parts --report /etc/cron.daily' started for user systab (pid 1124)
2022-02-15 21:15:00  INFO Job './backup/dns/doit; ./backup/dns/clean;' started for user mcd (pid 1157)
2022-02-15 21:15:00  INFO Job '~/backup/hausdok/doit' started for user mcd (pid 1160)
2022-02-15 21:15:01  INFO Job '~/backup/hausdok/doit' completed
2022-02-15 21:15:03  INFO Job './backup/dns/doit; ./backup/dns/clean;' completed
2022-02-15 21:15:47  INFO Job '/usr/bin/run-parts --report /etc/cron.daily' completed
2022-02-15 21:15:47  INFO Job '/usr/bin/run-parts /etc/cron.weekly' started for user systab (pid 1228)
2022-02-15 21:15:47  INFO Job '/usr/bin/run-parts /etc/cron.weekly' completed
2022-02-15 22:42:04 ERROR read_write_pipe(): read/write returned 0: retrying... (size: 4, size_processed: 0, num_retry: 1): Success
2022-02-15 22:42:05 ERROR read_write_pipe(): read/write returned 0: retrying... (size: 4, size_processed: 0, num_retry: 2): Success
2022-02-15 22:42:06 ERROR read_write_pipe(): read/write returned 0: retrying... (size: 4, size_processed: 0, num_retry: 3): Success
2022-02-15 22:42:07 ERROR Could not read job pid because of closed pipe: setting it to -1
2022-02-15 23:01:40 ERROR read_write_pipe(): read/write returned 0: retrying... (size: 4, size_processed: 0, num_retry: 1): Success
2022-02-15 23:01:41 ERROR read_write_pipe(): read/write returned 0: retrying... (size: 4, size_processed: 0, num_retry: 2): Success
2022-02-15 23:01:42 ERROR read_write_pipe(): read/write returned 0: retrying... (size: 4, size_processed: 0, num_retry: 3): Success
2022-02-15 23:01:43 ERROR Could not read job pid because of closed pipe: setting it to -1
2022-02-15 23:02:00 ERROR read_write_pipe(): read/write returned 0: retrying... (size: 4, size_processed: 0, num_retry: 1): Success
2022-02-15 23:02:01 ERROR read_write_pipe(): read/write returned 0: retrying... (size: 4, size_processed: 0, num_retry: 2): Success
2022-02-15 23:02:02 ERROR read_write_pipe(): read/write returned 0: retrying... (size: 4, size_processed: 0, num_retry: 3): Success
2022-02-15 23:02:03 ERROR Could not read job pid because of closed pipe: setting it to -1
2022-02-15 23:12:14 ERROR read_write_pipe(): read/write returned 0: retrying... (size: 4, size_processed: 0, num_retry: 1): Success
2022-02-15 23:12:15 ERROR read_write_pipe(): read/write returned 0: retrying... (size: 4, size_processed: 0, num_retry: 2): Success
2022-02-15 23:12:16 ERROR read_write_pipe(): read/write returned 0: retrying... (size: 4, size_processed: 0, num_retry: 3): Success
2022-02-15 23:12:17 ERROR Could not read job pid because of closed pipe: setting it to -1
2022-02-15 23:42:12 ERROR read_write_pipe(): read/write returned 0: retrying... (size: 4, size_processed: 0, num_retry: 1): Success
2022-02-15 23:42:13 ERROR read_write_pipe(): read/write returned 0: retrying... (size: 4, size_processed: 0, num_retry: 2): Success
2022-02-15 23:42:14 ERROR read_write_pipe(): read/write returned 0: retrying... (size: 4, size_processed: 0, num_retry: 3): Success
2022-02-15 23:42:15 ERROR Could not read job pid because of closed pipe: setting it to -1
2022-02-15 23:50:40  INFO SIGTERM signal received
2022-02-15 23:50:40  INFO Exiting with code 0
2022-02-15 23:50:40  INFO fcron[15196] 3.2.1 started

I get error mails (without subject) about the failed jobs. Here are 2 examples:

Date: 15 Feb 2022 22:42:12 -0000
From: fcron <[email protected]>
Cc: recipient list not shown:

2022-02-15 23:42:12 ERROR Could not init PAM account management for user 'mcd': Module is unknown
2022-02-15 23:42:12 ERROR Job 'cd rrd/df && ./measure' has *not* run.
From: mcd@arctic (fcron)
To: mcd@arctic
Subject: fcron <mcd@arctic> Could not run fcron job: cd rrd/df && ./measure
Content-Type: text/plain; charset=ANSI_X3.4-1968
Auto-Submitted: auto-generated
X-Cron-Env: <USER=mcd>
X-Cron-Env: <LOGNAME=mcd>
X-Cron-Env: <HOME=/home/mcd>
X-Cron-Env: <PATH=/usr/bin:/usr/sbin>
X-Cron-Env: <SHELL=/usr/bin/sh>
Date: 15 Feb 2022 22:01:40 -0000
From: fcron <[email protected]>
Cc: recipient list not shown:

2022-02-15 23:01:40 ERROR Could not init PAM account management for user 'root': Module is unknown
2022-02-15 23:01:40 ERROR Job '/usr/bin/run-parts /etc/cron.hourly' has *not* run.
From: root@arctic (fcron)
To: root@arctic
Subject: fcron <systab@arctic> Could not run fcron job: /usr/bin/run-parts /etc/cron.hourly
Content-Type: text/plain; charset=ANSI_X3.4-1968
Auto-Submitted: auto-generated
X-Cron-Env: <USER=root>
X-Cron-Env: <LOGNAME=root>
X-Cron-Env: <HOME=/root>
X-Cron-Env: <PATH=/usr/bin:/usr/sbin>
X-Cron-Env: <SHELL=/usr/bin/sh>

The only thing that might correlate is a system update I ran before:

[2022-02-15T22:12:41+0100] [PACMAN] Running 'pacman -Syu'
[2022-02-15T22:12:41+0100] [PACMAN] synchronizing package lists
[2022-02-15T22:12:54+0100] [PACMAN] starting full system upgrade
[2022-02-15T22:18:15+0100] [ALPM] running '60-mkinitcpio-remove.hook'...
[2022-02-15T22:18:15+0100] [ALPM] transaction started
[2022-02-15T22:18:15+0100] [ALPM] upgraded alsa-ucm-conf (1.2.6.2-2 -> 1.2.6.3-1)
[2022-02-15T22:18:15+0100] [ALPM] upgraded amd-ucode (20220119.0c6a7b3-2 -> 20220209.6342082-1)
[2022-02-15T22:18:15+0100] [ALPM] upgraded linux-api-headers (5.12.3-1 -> 5.16.8-1)
[2022-02-15T22:18:15+0100] [ALPM] upgraded iana-etc (20220110-1 -> 20220205-1)
[2022-02-15T22:18:15+0100] [ALPM] warning: /etc/locale.gen installed as /etc/locale.gen.pacnew
[2022-02-15T22:18:16+0100] [ALPM] upgraded glibc (2.33-5 -> 2.35-2)
[2022-02-15T22:18:16+0100] [ALPM-SCRIPTLET] Generating locales...
[2022-02-15T22:18:18+0100] [ALPM-SCRIPTLET]   de_DE.UTF-8... done
[2022-02-15T22:18:20+0100] [ALPM-SCRIPTLET]   en_US.UTF-8... done
[2022-02-15T22:18:20+0100] [ALPM-SCRIPTLET] Generation complete.
[2022-02-15T22:18:21+0100] [ALPM] upgraded libcap-ng (0.8.2-6 -> 0.8.2-7)
[2022-02-15T22:18:21+0100] [ALPM] upgraded util-linux-libs (2.37.3-2 -> 2.37.4-1)
[2022-02-15T22:18:22+0100] [ALPM] upgraded gcc-libs (11.1.0-3 -> 11.2.0-3)
[2022-02-15T22:18:22+0100] [ALPM] upgraded ncurses (6.3-1 -> 6.3-2)
[2022-02-15T22:18:22+0100] [ALPM] upgraded gdbm (1.22-1 -> 1.23-1)
[2022-02-15T22:18:22+0100] [ALPM] upgraded libnsl (2.0.0-1 -> 2.0.0-2)
[2022-02-15T22:18:34+0100] [ALPM] upgraded apparmor (3.0.3-3 -> 3.0.4-1)
[2022-02-15T22:18:34+0100] [ALPM] warning: /etc/pacman.d/mirrorlist installed as /etc/pacman.d/mirrorlist.pacnew
[2022-02-15T22:18:34+0100] [ALPM] upgraded artix-mirrorlist (20220103-1 -> 20220214-2)
[2022-02-15T22:18:34+0100] [ALPM] upgraded findutils (4.8.0-1 -> 4.9.0-1)
[2022-02-15T22:18:34+0100] [ALPM] upgraded libcap (2.63-1 -> 2.63-2)
[2022-02-15T22:18:35+0100] [ALPM] upgraded lib32-glibc (2.33-5 -> 2.35-2)
[2022-02-15T22:18:35+0100] [ALPM] upgraded ca-certificates-mozilla (3.74-1 -> 3.75-1)
[2022-02-15T22:18:35+0100] [ALPM] upgraded libelf (0.186-4 -> 0.186-5)
[2022-02-15T22:18:35+0100] [ALPM] upgraded binutils (2.36.1-3 -> 2.38-3)
[2022-02-15T22:18:35+0100] [ALPM] upgraded btrfs-progs (5.16-1 -> 5.16.1-1)
[2022-02-15T22:18:35+0100] [ALPM] upgraded libsysprof-capture (3.42.1-2 -> 3.42.1-3)
[2022-02-15T22:18:35+0100] [ALPM] upgraded glib2 (2.70.3-1 -> 2.70.4-1)
[2022-02-15T22:18:35+0100] [ALPM] upgraded harfbuzz (3.3.2-1 -> 3.4.0-1)
[2022-02-15T22:18:35+0100] [ALPM] upgraded pango (1:1.50.3-1 -> 1:1.50.4-1)
[2022-02-15T22:18:36+0100] [ALPM] upgraded llvm-libs (13.0.0-6 -> 13.0.1-1)
[2022-02-15T22:18:36+0100] [ALPM] upgraded xkeyboard-config (2.34-1 -> 2.35.1-1)
[2022-02-15T22:18:36+0100] [ALPM] upgraded xorg-server-common (21.1.3-1 -> 21.1.3-2)
[2022-02-15T22:18:36+0100] [ALPM] upgraded hwdata (0.355-1 -> 0.356-1)
[2022-02-15T22:18:36+0100] [ALPM] upgraded util-linux (2.37.3-2 -> 2.37.4-1)
[2022-02-15T22:18:36+0100] [ALPM] upgraded libwacom (2.0.0-2 -> 2.1.0-1)
[2022-02-15T22:18:36+0100] [ALPM] upgraded xorg-server (21.1.3-1 -> 21.1.3-2)
[2022-02-15T22:18:38+0100] [ALPM] upgraded nvidia-utils (495.46-2 -> 510.47.03-3)
[2022-02-15T22:18:38+0100] [ALPM-SCRIPTLET] If you run into trouble with CUDA not being available, run nvidia-modprobe first.
[2022-02-15T22:18:39+0100] [ALPM] upgraded mesa (21.3.5-1 -> 21.3.6-1)
[2022-02-15T22:18:39+0100] [ALPM] upgraded gtk-update-icon-cache (1:4.6.0-3 -> 1:4.6.1-2)
[2022-02-15T22:18:39+0100] [ALPM] upgraded gtk3 (1:3.24.31-1 -> 1:3.24.31-3)
[2022-02-15T22:18:39+0100] [ALPM] upgraded libtool (2.4.6+42+gb88cebd5-16 -> 2.4.6+59+gb55b1cc8-2)
[2022-02-15T22:18:39+0100] [ALPM] upgraded opus (1.3.1-2.1 -> 1.3.1-3)
[2022-02-15T22:18:39+0100] [ALPM] upgraded libcheese (41.1-1 -> 41.1-2)
[2022-02-15T22:18:39+0100] [ALPM] upgraded libavtp (0.1.0-2.1 -> 0.2.0-1)
[2022-02-15T22:18:39+0100] [ALPM] upgraded x265 (3.5-1 -> 3.5-2)
[2022-02-15T22:18:39+0100] [ALPM] upgraded imlib2 (1.7.5-1 -> 1.8.0-1)
[2022-02-15T22:18:39+0100] [ALPM] upgraded nss (3.74-1 -> 3.75-1)
[2022-02-15T22:18:40+0100] [ALPM] upgraded imagemagick (7.1.0.23-1 -> 7.1.0.24-1)
[2022-02-15T22:18:40+0100] [ALPM] upgraded cheese (41.1-1 -> 41.1-2)
[2022-02-15T22:18:40+0100] [ALPM] upgraded mpfr (4.1.0.p13-1 -> 4.1.0.p13-2)
[2022-02-15T22:18:40+0100] [ALPM] upgraded libmpc (1.2.1-1 -> 1.2.1-2)
[2022-02-15T22:18:41+0100] [ALPM] upgraded gcc (11.1.0-3 -> 11.2.0-3)
[2022-02-15T22:18:41+0100] [ALPM] upgraded compiler-rt (13.0.0-2 -> 13.0.1-1)
[2022-02-15T22:18:43+0100] [ALPM] upgraded clang (13.0.0-4 -> 13.0.1-1)
[2022-02-15T22:18:43+0100] [ALPM] upgraded device-mapper (2.03.14-2 -> 2.03.15-1)
[2022-02-15T22:18:43+0100] [ALPM] upgraded elfutils (0.186-4 -> 0.186-5)
[2022-02-15T22:18:43+0100] [ALPM] upgraded espeak-ng (1.50-4 -> 1.50-5)
[2022-02-15T22:18:43+0100] [ALPM] upgraded exempi (2.5.2-1 -> 2.6.1-1)
[2022-02-15T22:18:43+0100] [ALPM] upgraded faudio (22.01-1 -> 22.02-1)
[2022-02-15T22:18:43+0100] [ALPM] upgraded feh (3.8-1 -> 3.8-2.1)
[2022-02-15T22:18:44+0100] [ALPM] upgraded firefox (96.0.3-1 -> 97.0-1.5)
[2022-02-15T22:18:44+0100] [ALPM] upgraded firefox-i18n-de (96.0.3-1 -> 97.0-1)
[2022-02-15T22:18:45+0100] [ALPM] upgraded freeglut (3.2.1-2.1 -> 3.2.2-1)
[2022-02-15T22:18:45+0100] [ALPM] upgraded gcc-fortran (11.1.0-3 -> 11.2.0-3)
[2022-02-15T22:18:45+0100] [ALPM] upgraded upower (0.99.14-1 -> 0.99.15-1)
[2022-02-15T22:18:45+0100] [ALPM] upgraded libgdm (41.3-1.1 -> 41.3-2)
[2022-02-15T22:18:45+0100] [ALPM] upgraded gjs (2:1.70.0-3 -> 2:1.70.1-2)
[2022-02-15T22:18:45+0100] [ALPM] upgraded gtk4 (1:4.6.0-3 -> 1:4.6.1-2)
[2022-02-15T22:18:45+0100] [ALPM] upgraded libical (3.0.13-1 -> 3.0.14-1)
[2022-02-15T22:18:46+0100] [ALPM] upgraded geocode-glib (3.26.2-1.1 -> 3.26.2+r9+g6047da3-1.1)
[2022-02-15T22:18:46+0100] [ALPM] upgraded libgweather (40.0-1 -> 40.0+r87+g80e5a652-1)
[2022-02-15T22:18:46+0100] [ALPM] upgraded libmm-glib (1.18.4-1 -> 1.18.6-1)
[2022-02-15T22:18:46+0100] [ALPM] upgraded libarchive (3.5.2-3 -> 3.6.0-1)
[2022-02-15T22:18:46+0100] [ALPM] upgraded lvm2 (2.03.14-2 -> 2.03.15-1)
[2022-02-15T22:18:46+0100] [ALPM] upgraded gpgme (1.16.0-3 -> 1.17.0-2)
[2022-02-15T22:18:46+0100] [ALPM] upgraded harfbuzz-icu (3.3.2-1 -> 3.4.0-1)
[2022-02-15T22:18:46+0100] [ALPM] upgraded xdg-dbus-proxy (0.1.2-3 -> 0.1.3-1)
[2022-02-15T22:18:47+0100] [ALPM] upgraded webkit2gtk (2.34.4-1 -> 2.34.5-1)
[2022-02-15T22:18:47+0100] [ALPM] upgraded gdm (41.3-1.1 -> 41.3-2)
[2022-02-15T22:18:48+0100] [ALPM] upgraded glib2-docs (2.70.3-1 -> 2.70.4-1)
[2022-02-15T22:18:48+0100] [ALPM] upgraded gnome-control-center (41.2-3 -> 41.4-1)
[2022-02-15T22:18:49+0100] [ALPM] upgraded gnome-terminal (3.42.2-1 -> 3.42.2-2)
[2022-02-15T22:18:52+0100] [ALPM] upgraded go (2:1.17.6-2 -> 2:1.17.7-1)
[2022-02-15T22:18:52+0100] [ALPM] upgraded grim (1.3.2-1 -> 1.4.0-1)
[2022-02-15T22:18:53+0100] [ALPM] upgraded gwenhywfar (5.6.0-1 -> 5.8.2-1)
[2022-02-15T22:18:53+0100] [ALPM] upgraded qt5-translations (5.15.2+kde+r20-2 -> 5.15.2+kde+r22-1)
[2022-02-15T22:18:54+0100] [ALPM] upgraded qt5-base (5.15.2+kde+r297-1 -> 5.15.2+kde+r298-1)
[2022-02-15T22:18:54+0100] [ALPM] upgraded qt5-declarative (5.15.2+kde+r45-1 -> 5.15.2+kde+r46-1)
[2022-02-15T22:18:54+0100] [ALPM] upgraded qt5-wayland (5.15.2+kde+r48-1 -> 5.15.2+kde+r52-1)
[2022-02-15T22:18:54+0100] [ALPM] upgraded kwayland (5.90.0-1 -> 5.91.0-1)
[2022-02-15T22:18:55+0100] [ALPM] upgraded lib32-gcc-libs (11.1.0-3 -> 11.2.0-3)
[2022-02-15T22:18:55+0100] [ALPM] upgraded lib32-util-linux (2.37.3-1 -> 2.37.4-1)
[2022-02-15T22:18:55+0100] [ALPM] upgraded lib32-glib2 (2.70.3-1 -> 2.70.4-1)
[2022-02-15T22:18:55+0100] [ALPM] upgraded lib32-harfbuzz (3.3.2-1 -> 3.4.0-1)
[2022-02-15T22:18:55+0100] [ALPM] upgraded lib32-lcms2 (2.12-1 -> 2.13.1-1)
[2022-02-15T22:18:56+0100] [ALPM] upgraded lib32-llvm-libs (13.0.0-1 -> 13.0.1-1)
[2022-02-15T22:18:56+0100] [ALPM] upgraded lib32-mesa (21.3.5-1 -> 21.3.6-1)
[2022-02-15T22:18:56+0100] [ALPM] upgraded lib32-pango (1:1.50.3-1 -> 1:1.50.4-1)
[2022-02-15T22:18:56+0100] [ALPM] upgraded libbpf (0.6.1-1 -> 0.7.0-1)
[2022-02-15T22:18:56+0100] [ALPM] upgraded libpcap (1.10.1-1 -> 1.10.1-2)
[2022-02-15T22:18:56+0100] [ALPM] upgraded libsigc++ (2.10.7-2 -> 2.10.8-1)
[2022-02-15T22:18:56+0100] [ALPM] upgraded libspectre (0.2.9-2 -> 0.2.10-1)
[2022-02-15T22:18:56+0100] [ALPM] upgraded libspeechd (0.10.2-1 -> 0.11.1-2)
[2022-02-15T22:18:56+0100] [ALPM] upgraded libva-mesa-driver (21.3.5-1 -> 21.3.6-1)
[2022-02-15T22:18:56+0100] [ALPM] upgraded libvips (8.12.1-1 -> 8.12.2-1)
[2022-02-15T22:18:56+0100] [ALPM] upgraded mkinitcpio-busybox (1.34.1-1 -> 1.35.0-1)
[2022-02-15T22:19:02+0100] [ALPM] upgraded linux (5.16.3.artix1-1 -> 5.16.8.artix1-2)
[2022-02-15T22:19:02+0100] [ALPM] upgraded linux-firmware-whence (20220119.0c6a7b3-2 -> 20220209.6342082-1)
[2022-02-15T22:19:08+0100] [ALPM] upgraded linux-firmware (20220119.0c6a7b3-2 -> 20220209.6342082-1)
[2022-02-15T22:19:13+0100] [ALPM] upgraded linux-lts (5.15.16-1 -> 5.15.22-2)
[2022-02-15T22:19:24+0100] [ALPM] upgraded llvm (13.0.0-6 -> 13.0.1-1)
[2022-02-15T22:19:24+0100] [ALPM] upgraded mako (1.6-2 -> 1.6-3)
[2022-02-15T22:19:24+0100] [ALPM] upgraded man-db (2.9.4-2 -> 2.10.1-1)
[2022-02-15T22:19:24+0100] [ALPM] upgraded mesa-vdpau (21.3.5-1 -> 21.3.6-1)
[2022-02-15T22:19:24+0100] [ALPM] upgraded mongo-c-driver (1.20.1-1 -> 1.21.0-1)
[2022-02-15T22:19:25+0100] [ALPM] upgraded mutt (2.1.5-1 -> 2.2-1)
[2022-02-15T22:19:25+0100] [ALPM] upgraded nano (6.0-1 -> 6.1-1)
[2022-02-15T22:19:25+0100] [ALPM] upgraded notmuch-runtime (0.34.3-1 -> 0.35-1)
[2022-02-15T22:19:25+0100] [ALPM] upgraded neomutt (20211029-1 -> 20211029-2)
[2022-02-15T22:19:25+0100] [ALPM] upgraded sundials (6.1.0-2 -> 6.1.1-1)
[2022-02-15T22:19:25+0100] [ALPM] upgraded qt5-tools (5.15.2+kde+r17-5 -> 5.15.2+kde+r17-6)
[2022-02-15T22:19:26+0100] [ALPM] upgraded octave (6.4.0-3 -> 6.4.0-4)
[2022-02-15T22:19:26+0100] [ALPM] upgraded perl-http-message (6.35-1 -> 6.36-1)
[2022-02-15T22:19:26+0100] [ALPM] upgraded perl-json (4.04-1 -> 4.05-1)
[2022-02-15T22:19:26+0100] [ALPM] upgraded python-idna (3.3-3 -> 3.3-4)
[2022-02-15T22:19:27+0100] [ALPM] upgraded python-numpy (1.21.5-2 -> 1.22.2-1)
[2022-02-15T22:19:27+0100] [ALPM] upgraded qpdf (10.5.0-1 -> 10.6.1-1)
[2022-02-15T22:19:27+0100] [ALPM] upgraded python-pikepdf (4.4.1-1 -> 4.5.0-1)
[2022-02-15T22:19:27+0100] [ALPM] upgraded python-requests (2.26.0-5 -> 2.27.0-1)
[2022-02-15T22:19:27+0100] [ALPM] upgraded python-ruamel-yaml (0.17.20-1 -> 0.17.21-1)
[2022-02-15T22:19:30+0100] [ALPM] upgraded python-scipy (1.7.3-3.1 -> 1.8.0-1)
[2022-02-15T22:19:30+0100] [ALPM] upgraded python-setuptools (1:59.1.1-1 -> 1:59.3.0-1)
[2022-02-15T22:19:30+0100] [ALPM] upgraded python-tomlkit (0.9.0-1 -> 0.9.2-1)
[2022-02-15T22:19:30+0100] [ALPM] upgraded python-typing_extensions (4.0.1-1 -> 4.1.0-1)
[2022-02-15T22:19:30+0100] [ALPM] upgraded remmina (1:1.4.23-3 -> 1:1.4.24-1)
[2022-02-15T22:19:30+0100] [ALPM] upgraded seatd (0.6.3-2 -> 0.6.3-3)
[2022-02-15T22:19:46+0100] [ALPM] upgraded signal-desktop (5.30.0-1 -> 5.31.1-1)
[2022-02-15T22:19:46+0100] [ALPM] upgraded slurp (1.3.2-1 -> 1.3.2-2)
[2022-02-15T22:19:46+0100] [ALPM] upgraded squashfs-tools (4.5-1 -> 4.5-2)
[2022-02-15T22:19:46+0100] [ALPM] upgraded swaybg (1.1-2 -> 1.1-3)
[2022-02-15T22:19:46+0100] [ALPM] upgraded wlroots (0.15.0-4 -> 0.15.1-2)
[2022-02-15T22:19:46+0100] [ALPM] upgraded sway (1:1.7-1 -> 1:1.7-2)
[2022-02-15T22:19:46+0100] [ALPM] upgraded swayidle (1.7.1-1 -> 1.7.1-2)
[2022-02-15T22:19:46+0100] [ALPM] upgraded swaylock (1.5-2 -> 1.5-3)
[2022-02-15T22:19:53+0100] [ALPM] upgraded thunderbird (91.5.1-1 -> 91.6.0-1.1)
[2022-02-15T22:19:53+0100] [ALPM] installed libb64 (1.2.1-4)
[2022-02-15T22:19:53+0100] [ALPM] installed miniupnpc (2.2.2-2)
[2022-02-15T22:19:53+0100] [ALPM] installed libnatpmp (20150609-3)
[2022-02-15T22:19:53+0100] [ALPM] upgraded transmission-gtk (3.00-2 -> 3.00-3)
[2022-02-15T22:19:53+0100] [ALPM] upgraded vala (0.54.6-1 -> 0.54.7-1)
[2022-02-15T22:19:57+0100] [ALPM] upgraded valgrind (3.18.1-2 -> 3.18.1-3)
[2022-02-15T22:20:01+0100] [ALPM] upgraded webkit2gtk-4.1 (2.34.4-1 -> 2.34.5-1)
[2022-02-15T22:20:13+0100] [ALPM] upgraded wine (7.1-1 -> 7.2-1)
[2022-02-15T22:20:21+0100] [ALPM] upgraded wine-mono (7.0.0-2 -> 7.1.1-1)
[2022-02-15T22:20:21+0100] [ALPM] upgraded wpa_supplicant (2:2.10-1 -> 2:2.10-2)
[2022-02-15T22:20:21+0100] [ALPM] upgraded xfce4-notifyd (0.6.2-2 -> 0.6.3-1)
[2022-02-15T22:20:21+0100] [ALPM] upgraded xorg-server-devel (21.1.3-1 -> 21.1.3-2)
[2022-02-15T22:20:21+0100] [ALPM] upgraded xorg-server-xephyr (21.1.3-1 -> 21.1.3-2)
[2022-02-15T22:20:21+0100] [ALPM] upgraded xorg-server-xnest (21.1.3-1 -> 21.1.3-2)
[2022-02-15T22:20:21+0100] [ALPM] upgraded xorg-server-xvfb (21.1.3-1 -> 21.1.3-2)
[2022-02-15T22:20:23+0100] [ALPM] transaction completed
[2022-02-15T22:20:26+0100] [ALPM] running '20-sysusers.hook'...
[2022-02-15T22:20:28+0100] [ALPM] running '30-binfmt.hook'...
[2022-02-15T22:20:28+0100] [ALPM-SCRIPTLET] (B[m[1m[34m:: (B[m[1mRunning binfmt(B[m    (B[m[1m[34m[(B[m[36mbusy(B[m[1m[34m](B[m    (B[m[1m[34m[(B[m[1mdone(B[m[1m[34m](B[m 
[2022-02-15T22:20:28+0100] [ALPM] running '30-tmpfiles.hook'...
[2022-02-15T22:20:28+0100] [ALPM] running '30-udev-hwdb.hook'...
[2022-02-15T22:20:32+0100] [ALPM] running '30-udev-reload.hook'...
[2022-02-15T22:20:32+0100] [ALPM] running '30-update-mime-database.hook'...
[2022-02-15T22:20:43+0100] [ALPM] running '40-update-ca-trust.hook'...
[2022-02-15T22:20:45+0100] [ALPM] running '60-depmod.hook'...
[2022-02-15T22:20:51+0100] [ALPM] running '90-mkinitcpio-install.hook'...
[2022-02-15T22:20:51+0100] [ALPM-SCRIPTLET] ==> Building image from preset: /etc/mkinitcpio.d/linux-lts.preset: 'default'
[2022-02-15T22:20:51+0100] [ALPM-SCRIPTLET]   -> -k /boot/vmlinuz-linux-lts -c /etc/mkinitcpio.conf -g /boot/initramfs-linux-lts.img
[2022-02-15T22:20:52+0100] [ALPM-SCRIPTLET] ==> Starting build: 5.15.22-2-lts
[2022-02-15T22:20:52+0100] [ALPM-SCRIPTLET]   -> Running build hook: [base]
[2022-02-15T22:20:53+0100] [ALPM-SCRIPTLET]   -> Running build hook: [udev]
[2022-02-15T22:20:54+0100] [ALPM-SCRIPTLET]   -> Running build hook: [autodetect]
[2022-02-15T22:20:54+0100] [ALPM-SCRIPTLET]   -> Running build hook: [modconf]
[2022-02-15T22:20:55+0100] [ALPM-SCRIPTLET]   -> Running build hook: [block]
[2022-02-15T22:20:55+0100] [ALPM-SCRIPTLET] ==> WARNING: Possibly missing firmware for module: xhci_pci
[2022-02-15T22:20:55+0100] [ALPM-SCRIPTLET]   -> Running build hook: [filesystems]
[2022-02-15T22:20:55+0100] [ALPM-SCRIPTLET]   -> Running build hook: [keyboard]
[2022-02-15T22:20:56+0100] [ALPM-SCRIPTLET]   -> Running build hook: [resume]
[2022-02-15T22:20:56+0100] [ALPM-SCRIPTLET]   -> Running build hook: [fsck]
[2022-02-15T22:20:56+0100] [ALPM-SCRIPTLET] ==> Generating module dependencies
[2022-02-15T22:20:57+0100] [ALPM-SCRIPTLET] ==> Creating zstd-compressed initcpio image: /boot/initramfs-linux-lts.img
[2022-02-15T22:20:57+0100] [ALPM-SCRIPTLET] ==> Image generation successful
[2022-02-15T22:20:57+0100] [ALPM-SCRIPTLET] ==> Building image from preset: /etc/mkinitcpio.d/linux-lts.preset: 'fallback'
[2022-02-15T22:20:57+0100] [ALPM-SCRIPTLET]   -> -k /boot/vmlinuz-linux-lts -c /etc/mkinitcpio.conf -g /boot/initramfs-linux-lts-fallback.img -S autodetect
[2022-02-15T22:20:57+0100] [ALPM-SCRIPTLET] ==> Starting build: 5.15.22-2-lts
[2022-02-15T22:20:57+0100] [ALPM-SCRIPTLET]   -> Running build hook: [base]
[2022-02-15T22:20:58+0100] [ALPM-SCRIPTLET]   -> Running build hook: [udev]
[2022-02-15T22:20:58+0100] [ALPM-SCRIPTLET]   -> Running build hook: [modconf]
[2022-02-15T22:20:58+0100] [ALPM-SCRIPTLET]   -> Running build hook: [block]
[2022-02-15T22:20:58+0100] [ALPM-SCRIPTLET] ==> WARNING: Possibly missing firmware for module: wd719x
[2022-02-15T22:20:58+0100] [ALPM-SCRIPTLET] ==> WARNING: Possibly missing firmware for module: aic94xx
[2022-02-15T22:20:58+0100] [ALPM-SCRIPTLET] ==> WARNING: Possibly missing firmware for module: qla1280
[2022-02-15T22:20:58+0100] [ALPM-SCRIPTLET] ==> WARNING: Possibly missing firmware for module: qed
[2022-02-15T22:20:59+0100] [ALPM-SCRIPTLET] ==> WARNING: Possibly missing firmware for module: bfa
[2022-02-15T22:20:59+0100] [ALPM-SCRIPTLET] ==> WARNING: Possibly missing firmware for module: qla2xxx
[2022-02-15T22:20:59+0100] [ALPM-SCRIPTLET] ==> WARNING: Possibly missing firmware for module: xhci_pci
[2022-02-15T22:21:00+0100] [ALPM-SCRIPTLET]   -> Running build hook: [filesystems]
[2022-02-15T22:21:01+0100] [ALPM-SCRIPTLET]   -> Running build hook: [keyboard]
[2022-02-15T22:21:02+0100] [ALPM-SCRIPTLET]   -> Running build hook: [resume]
[2022-02-15T22:21:02+0100] [ALPM-SCRIPTLET]   -> Running build hook: [fsck]
[2022-02-15T22:21:03+0100] [ALPM-SCRIPTLET] ==> Generating module dependencies
[2022-02-15T22:21:04+0100] [ALPM-SCRIPTLET] ==> Creating zstd-compressed initcpio image: /boot/initramfs-linux-lts-fallback.img
[2022-02-15T22:21:04+0100] [ALPM-SCRIPTLET] ==> Image generation successful
[2022-02-15T22:21:04+0100] [ALPM-SCRIPTLET] ==> Building image from preset: /etc/mkinitcpio.d/linux.preset: 'default'
[2022-02-15T22:21:04+0100] [ALPM-SCRIPTLET]   -> -k /boot/vmlinuz-linux -c /etc/mkinitcpio.conf -g /boot/initramfs-linux.img
[2022-02-15T22:21:04+0100] [ALPM-SCRIPTLET] ==> Starting build: 5.16.8-artix1-2
[2022-02-15T22:21:04+0100] [ALPM-SCRIPTLET]   -> Running build hook: [base]
[2022-02-15T22:21:05+0100] [ALPM-SCRIPTLET]   -> Running build hook: [udev]
[2022-02-15T22:21:05+0100] [ALPM-SCRIPTLET]   -> Running build hook: [autodetect]
[2022-02-15T22:21:05+0100] [ALPM-SCRIPTLET]   -> Running build hook: [modconf]
[2022-02-15T22:21:05+0100] [ALPM-SCRIPTLET]   -> Running build hook: [block]
[2022-02-15T22:21:05+0100] [ALPM-SCRIPTLET] ==> WARNING: Possibly missing firmware for module: xhci_pci
[2022-02-15T22:21:05+0100] [ALPM-SCRIPTLET]   -> Running build hook: [filesystems]
[2022-02-15T22:21:06+0100] [ALPM-SCRIPTLET]   -> Running build hook: [keyboard]
[2022-02-15T22:21:06+0100] [ALPM-SCRIPTLET]   -> Running build hook: [resume]
[2022-02-15T22:21:06+0100] [ALPM-SCRIPTLET]   -> Running build hook: [fsck]
[2022-02-15T22:21:06+0100] [ALPM-SCRIPTLET] ==> Generating module dependencies
[2022-02-15T22:21:06+0100] [ALPM-SCRIPTLET] ==> Creating zstd-compressed initcpio image: /boot/initramfs-linux.img
[2022-02-15T22:21:06+0100] [ALPM-SCRIPTLET] ==> Image generation successful
[2022-02-15T22:21:06+0100] [ALPM-SCRIPTLET] ==> Building image from preset: /etc/mkinitcpio.d/linux.preset: 'fallback'
[2022-02-15T22:21:06+0100] [ALPM-SCRIPTLET]   -> -k /boot/vmlinuz-linux -c /etc/mkinitcpio.conf -g /boot/initramfs-linux-fallback.img -S autodetect
[2022-02-15T22:21:06+0100] [ALPM-SCRIPTLET] ==> Starting build: 5.16.8-artix1-2
[2022-02-15T22:21:07+0100] [ALPM-SCRIPTLET]   -> Running build hook: [base]
[2022-02-15T22:21:07+0100] [ALPM-SCRIPTLET]   -> Running build hook: [udev]
[2022-02-15T22:21:07+0100] [ALPM-SCRIPTLET]   -> Running build hook: [modconf]
[2022-02-15T22:21:07+0100] [ALPM-SCRIPTLET]   -> Running build hook: [block]
[2022-02-15T22:21:07+0100] [ALPM-SCRIPTLET] ==> WARNING: Possibly missing firmware for module: wd719x
[2022-02-15T22:21:08+0100] [ALPM-SCRIPTLET] ==> WARNING: Possibly missing firmware for module: aic94xx
[2022-02-15T22:21:08+0100] [ALPM-SCRIPTLET] ==> WARNING: Possibly missing firmware for module: qla1280
[2022-02-15T22:21:08+0100] [ALPM-SCRIPTLET] ==> WARNING: Possibly missing firmware for module: qed
[2022-02-15T22:21:08+0100] [ALPM-SCRIPTLET] ==> WARNING: Possibly missing firmware for module: bfa
[2022-02-15T22:21:08+0100] [ALPM-SCRIPTLET] ==> WARNING: Possibly missing firmware for module: qla2xxx
[2022-02-15T22:21:09+0100] [ALPM-SCRIPTLET] ==> WARNING: Possibly missing firmware for module: xhci_pci
[2022-02-15T22:21:09+0100] [ALPM-SCRIPTLET]   -> Running build hook: [filesystems]
[2022-02-15T22:21:10+0100] [ALPM-SCRIPTLET]   -> Running build hook: [keyboard]
[2022-02-15T22:21:11+0100] [ALPM-SCRIPTLET]   -> Running build hook: [resume]
[2022-02-15T22:21:11+0100] [ALPM-SCRIPTLET]   -> Running build hook: [fsck]
[2022-02-15T22:21:12+0100] [ALPM-SCRIPTLET] ==> Generating module dependencies
[2022-02-15T22:21:13+0100] [ALPM-SCRIPTLET] ==> Creating zstd-compressed initcpio image: /boot/initramfs-linux-fallback.img
[2022-02-15T22:21:14+0100] [ALPM-SCRIPTLET] ==> Image generation successful
[2022-02-15T22:21:14+0100] [ALPM] running 'detect-old-perl-modules.hook'...
[2022-02-15T22:21:14+0100] [ALPM] running 'fontconfig.hook'...
[2022-02-15T22:21:15+0100] [ALPM] running 'fontconfig-32.hook'...
[2022-02-15T22:21:15+0100] [ALPM] running 'glib-compile-schemas.hook'...
[2022-02-15T22:21:15+0100] [ALPM] running 'gtk-query-immodules-3.0.hook'...
[2022-02-15T22:21:16+0100] [ALPM] running 'gtk-update-icon-cache.hook'...
[2022-02-15T22:21:16+0100] [ALPM] running 'gtk4-querymodules.hook'...
[2022-02-15T22:21:17+0100] [ALPM] running 'texinfo-install.hook'...
[2022-02-15T22:21:20+0100] [ALPM] running 'update-desktop-database.hook'...

I'm on artixlinux with runit. I should have older logs from another time this happened. Tell me, if you need them.

castilma avatar Feb 17 '22 11:02 castilma

The message ERROR Could not init PAM account management for user 'root': Module is unknown should be more verbose, i.e. state which module could not be loaded.

2022-02-15 23:12:17 ERROR Could not read job pid because of closed pipe: setting it to -1
2022-02-15 23:42:12 ERROR read_write_pipe(): read/write returned 0: retrying... (size: 4, size_processed: 0, num_retry: 1): Success

To debug this, it would be a start to find out, how the pipe could have been closed. And, why read_write_pipe seemingly tries to read from a closed pipe/invalid file descriptor(?) returning 0 bytes instead of an error. If it reads from somewhere else, it would be good to know why that failed.

castilma avatar Mar 01 '22 21:03 castilma

Today I noticed the error again, this time on my laptop, but with the same os.

2022-08-03 00:01:00  INFO Job '/usr/bin/run-parts /etc/cron.hourly' started for user systab (pid 7316)
2022-08-03 00:01:00  INFO Job '/usr/bin/run-parts /etc/cron.hourly' completed
2022-08-03 00:02:00  INFO Job '/usr/bin/run-parts /etc/cron.daily' started for user systab (pid 7417)
2022-08-03 00:03:11  INFO Job '/usr/bin/run-parts /etc/cron.daily' completed
2022-08-03 01:01:00 ERROR read_write_pipe(): read/write returned 0: retrying... (size: 4, size_processed: 0, num_retry: 1): Success
2022-08-03 01:01:01 ERROR read_write_pipe(): read/write returned 0: retrying... (size: 4, size_processed: 0, num_retry: 2): Success
2022-08-03 01:01:02 ERROR read_write_pipe(): read/write returned 0: retrying... (size: 4, size_processed: 0, num_retry: 3): Success
2022-08-03 01:01:03 ERROR Could not read job pid because of closed pipe: setting it to -1
2022-08-03 11:37:09  INFO suspend/hibernate detected: we woke up after 37999s instead of 1800s. The system was suspended for 36927s.
2022-08-03 11:37:09 ERROR read_write_pipe(): read/write returned 0: retrying... (size: 4, size_processed: 0, num_retry: 1): Success
2022-08-03 11:37:10 ERROR read_write_pipe(): read/write returned 0: retrying... (size: 4, size_processed: 0, num_retry: 2): Success
2022-08-03 11:37:11 ERROR read_write_pipe(): read/write returned 0: retrying... (size: 4, size_processed: 0, num_retry: 3): Success
2022-08-03 11:37:12 ERROR Could not read job pid because of closed pipe: setting it to -1
2022-08-03 12:01:00 ERROR read_write_pipe(): read/write returned 0: retrying... (size: 4, size_processed: 0, num_retry: 1): Success
2022-08-03 12:01:01 ERROR read_write_pipe(): read/write returned 0: retrying... (size: 4, size_processed: 0, num_retry: 2): Success
2022-08-03 12:01:02 ERROR read_write_pipe(): read/write returned 0: retrying... (size: 4, size_processed: 0, num_retry: 3): Success
2022-08-03 12:01:03 ERROR Could not read job pid because of closed pipe: setting it to -1
2022-08-03 13:01:00 ERROR read_write_pipe(): read/write returned 0: retrying... (size: 4, size_processed: 0, num_retry: 1): Success
2022-08-03 13:01:01 ERROR read_write_pipe(): read/write returned 0: retrying... (size: 4, size_processed: 0, num_retry: 2): Success
2022-08-03 13:01:02 ERROR read_write_pipe(): read/write returned 0: retrying... (size: 4, size_processed: 0, num_retry: 3): Success
2022-08-03 13:01:03 ERROR Could not read job pid because of closed pipe: setting it to -1
2022-08-03 14:01:00 ERROR read_write_pipe(): read/write returned 0: retrying... (size: 4, size_processed: 0, num_retry: 1): Success
2022-08-03 14:01:01 ERROR read_write_pipe(): read/write returned 0: retrying... (size: 4, size_processed: 0, num_retry: 2): Success
2022-08-03 14:01:02 ERROR read_write_pipe(): read/write returned 0: retrying... (size: 4, size_processed: 0, num_retry: 3): Success
2022-08-03 14:01:03 ERROR Could not read job pid because of closed pipe: setting it to -1
2022-08-03 14:13:41  INFO suspend/hibernate detected: we woke up after 392s instead of 1800s. The system was suspended for 168s.

and theres been a system upgrade prior to the error:

[2022-08-03T00:40:35+0200] [ALPM] running '60-mkinitcpio-remove.hook'...
[2022-08-03T00:40:35+0200] [ALPM] transaction started
[2022-08-03T00:40:36+0200] [ALPM] upgraded linux-api-headers (5.17.5-2 -> 5.18.15-1)
[2022-08-03T00:40:38+0200] [ALPM] warning: /etc/locale.gen installed as /etc/locale.gen.pacnew
[2022-08-03T00:40:38+0200] [ALPM] upgraded glibc (2.35-6 -> 2.36-1)
[2022-08-03T00:40:38+0200] [ALPM-SCRIPTLET] Generating locales...
[2022-08-03T00:40:41+0200] [ALPM-SCRIPTLET]   de_DE.UTF-8... done
[2022-08-03T00:40:41+0200] [ALPM-SCRIPTLET] Generation complete.
[2022-08-03T00:40:43+0200] [ALPM] upgraded gcc-libs (12.1.0-3 -> 12.1.1-4)
[2022-08-03T00:40:43+0200] [ALPM] upgraded lib32-glibc (2.35-6 -> 2.36-1)
[2022-08-03T00:40:43+0200] [ALPM] upgraded libelf (0.187-1 -> 0.187-2)
[2022-08-03T00:40:44+0200] [ALPM] upgraded binutils (2.38-6 -> 2.38-7)
[2022-08-03T00:40:44+0200] [ALPM] upgraded mpfr (4.1.0.p13-2 -> 4.1.0.p13-3)
[2022-08-03T00:41:20+0200] [ALPM] upgraded linux (5.18.14.artix1-1 -> 5.18.15.artix1-2)
[2022-08-03T00:41:20+0200] [ALPM] upgraded acpi_call (1.2.2-57 -> 1.2.2-60)
[2022-08-03T00:41:21+0200] [ALPM] upgraded elfutils (0.187-1 -> 0.187-2)
[2022-08-03T00:41:21+0200] [ALPM] upgraded libsysprof-capture (3.44.0-1 -> 3.44.0-2)
[2022-08-03T00:41:21+0200] [ALPM] upgraded gsm (1.0.20-1 -> 1.0.21-1)
[2022-08-03T00:41:21+0200] [ALPM] upgraded opencore-amr (0.1.5-5 -> 0.1.6-1)
[2022-08-03T00:41:23+0200] [ALPM] upgraded libtiff (4.4.0-1 -> 4.4.0-3)
[2022-08-03T00:41:32+0200] [ALPM] upgraded firefox (103.0-1 -> 103.0.1-1)
[2022-08-03T00:41:32+0200] [ALPM] upgraded firefox-i18n-de (103.0-1 -> 103.0.1-1)
[2022-08-03T00:41:36+0200] [ALPM] upgraded gcc (12.1.0-3 -> 12.1.1-4)
[2022-08-03T00:41:52+0200] [ALPM] upgraded gcc-fortran (12.1.0-3 -> 12.1.1-4)
[2022-08-03T00:42:23+0200] [ALPM] upgraded libtool (2.4.7-2 -> 2.4.7-3)
[2022-08-03T00:42:26+0200] [ALPM] upgraded imagemagick (7.1.0.44-1 -> 7.1.0.45-1)
[2022-08-03T00:42:27+0200] [ALPM] upgraded iptables (1:1.8.8-1 -> 1:1.8.8-2)
[2022-08-03T00:42:30+0200] [ALPM] upgraded jre8-openjdk-headless (8.342.u07-1 -> 8.345.u01-1)
[2022-08-03T00:42:31+0200] [ALPM] upgraded lib32-gcc-libs (12.1.0-3 -> 12.1.1-4)
[2022-08-03T00:42:31+0200] [ALPM] upgraded lib32-libxcrypt (4.4.28-1 -> 4.4.28-2)
[2022-08-03T00:42:42+0200] [ALPM] upgraded libreoffice-fresh (7.3.4-2 -> 7.3.5-1)
[2022-08-03T00:42:52+0200] [ALPM] upgraded libreoffice-fresh-de (7.3.4-1 -> 7.3.5-1)
[2022-08-03T00:42:52+0200] [ALPM] upgraded libwpe (1.12.0-2 -> 1.12.2-1)
[2022-08-03T00:43:05+0200] [ALPM] upgraded sddm (0.19.0-8 -> 0.19.0-8.1)
[2022-08-03T00:43:05+0200] [ALPM] upgraded tp_smapi (0.43-410 -> 0.43-413)
[2022-08-03T00:43:05+0200] [ALPM] upgraded wavpack (5.4.0-1 -> 5.5.0-1)
[2022-08-03T00:43:05+0200] [ALPM] upgraded wayland-protocols (1.25-1 -> 1.26-1)
[2022-08-03T00:43:06+0200] [ALPM] upgraded webkit2gtk (2.36.5-1 -> 2.36.5-2)
[2022-08-03T00:43:07+0200] [ALPM] upgraded webkit2gtk-4.1 (2.36.5-1 -> 2.36.5-2)
[2022-08-03T00:43:08+0200] [ALPM] transaction completed
[2022-08-03T00:43:09+0200] [ALPM] running '20-sysusers.hook'...
[2022-08-03T00:43:10+0200] [ALPM] running '30-tmpfiles.hook'...
[2022-08-03T00:43:10+0200] [ALPM] running '30-update-mime-database.hook'...
[2022-08-03T00:43:11+0200] [ALPM] running '60-depmod.hook'...
[2022-08-03T00:45:48+0200] [ALPM] running '90-mkinitcpio-install.hook'...
[2022-08-03T00:45:49+0200] [ALPM-SCRIPTLET] ==> Building image from preset: /etc/mkinitcpio.d/linux.preset: 'default'
[2022-08-03T00:45:49+0200] [ALPM-SCRIPTLET]   -> -k /boot/vmlinuz-linux -c /etc/mkinitcpio.conf -g /boot/initramfs-linux.img
[2022-08-03T00:45:49+0200] [ALPM-SCRIPTLET] ==> Starting build: 5.18.15-artix1-2
[2022-08-03T00:45:49+0200] [ALPM-SCRIPTLET]   -> Running build hook: [base]
[2022-08-03T00:45:50+0200] [ALPM-SCRIPTLET]   -> Running build hook: [udev]
[2022-08-03T00:45:51+0200] [ALPM-SCRIPTLET]   -> Running build hook: [autodetect]
[2022-08-03T00:45:51+0200] [ALPM-SCRIPTLET]   -> Running build hook: [keyboard]
[2022-08-03T00:45:52+0200] [ALPM-SCRIPTLET]   -> Running build hook: [keymap]
[2022-08-03T00:45:52+0200] [ALPM-SCRIPTLET]   -> Running build hook: [consolefont]
[2022-08-03T00:45:52+0200] [ALPM-SCRIPTLET] ==> WARNING: consolefont: no font found in configuration
[2022-08-03T00:45:52+0200] [ALPM-SCRIPTLET]   -> Running build hook: [modconf]
[2022-08-03T00:45:52+0200] [ALPM-SCRIPTLET]   -> Running build hook: [block]
[2022-08-03T00:45:53+0200] [ALPM-SCRIPTLET]   -> Running build hook: [encrypt]
[2022-08-03T00:45:54+0200] [ALPM-SCRIPTLET] ==> WARNING: Possibly missing firmware for module: qat_4xxx
[2022-08-03T00:45:58+0200] [ALPM-SCRIPTLET]   -> Running build hook: [lvm2]
[2022-08-03T00:46:01+0200] [ALPM-SCRIPTLET]   -> Running build hook: [filesystems]
[2022-08-03T00:46:01+0200] [ALPM-SCRIPTLET]   -> Running build hook: [resume]
[2022-08-03T00:46:01+0200] [ALPM-SCRIPTLET]   -> Running build hook: [fsck]
[2022-08-03T00:46:01+0200] [ALPM-SCRIPTLET] ==> Generating module dependencies
[2022-08-03T00:46:01+0200] [ALPM-SCRIPTLET] ==> Creating zstd-compressed initcpio image: /boot/initramfs-linux.img
[2022-08-03T00:46:02+0200] [ALPM-SCRIPTLET] ==> Image generation successful
[2022-08-03T00:46:02+0200] [ALPM-SCRIPTLET] ==> Building image from preset: /etc/mkinitcpio.d/linux.preset: 'fallback'
[2022-08-03T00:46:02+0200] [ALPM-SCRIPTLET]   -> -k /boot/vmlinuz-linux -c /etc/mkinitcpio.conf -g /boot/initramfs-linux-fallback.img -S autodetect
[2022-08-03T00:46:02+0200] [ALPM-SCRIPTLET] ==> Starting build: 5.18.15-artix1-2
[2022-08-03T00:46:02+0200] [ALPM-SCRIPTLET]   -> Running build hook: [base]
[2022-08-03T00:46:02+0200] [ALPM-SCRIPTLET]   -> Running build hook: [udev]
[2022-08-03T00:46:03+0200] [ALPM-SCRIPTLET]   -> Running build hook: [keyboard]
[2022-08-03T00:46:03+0200] [ALPM-SCRIPTLET] ==> WARNING: Possibly missing firmware for module: xhci_pci
[2022-08-03T00:46:04+0200] [ALPM-SCRIPTLET]   -> Running build hook: [keymap]
[2022-08-03T00:46:04+0200] [ALPM-SCRIPTLET]   -> Running build hook: [consolefont]
[2022-08-03T00:46:04+0200] [ALPM-SCRIPTLET] ==> WARNING: consolefont: no font found in configuration
[2022-08-03T00:46:04+0200] [ALPM-SCRIPTLET]   -> Running build hook: [modconf]
[2022-08-03T00:46:04+0200] [ALPM-SCRIPTLET]   -> Running build hook: [block]
[2022-08-03T00:46:07+0200] [ALPM-SCRIPTLET] ==> WARNING: Possibly missing firmware for module: qla2xxx
[2022-08-03T00:46:07+0200] [ALPM-SCRIPTLET] ==> WARNING: Possibly missing firmware for module: aic94xx
[2022-08-03T00:46:08+0200] [ALPM-SCRIPTLET] ==> WARNING: Possibly missing firmware for module: qed
[2022-08-03T00:46:09+0200] [ALPM-SCRIPTLET] ==> WARNING: Possibly missing firmware for module: bfa
[2022-08-03T00:46:12+0200] [ALPM-SCRIPTLET] ==> WARNING: Possibly missing firmware for module: wd719x
[2022-08-03T00:46:13+0200] [ALPM-SCRIPTLET] ==> WARNING: Possibly missing firmware for module: qla1280
[2022-08-03T00:46:17+0200] [ALPM-SCRIPTLET]   -> Running build hook: [encrypt]
[2022-08-03T00:46:17+0200] [ALPM-SCRIPTLET] ==> WARNING: Possibly missing firmware for module: qat_4xxx
[2022-08-03T00:46:18+0200] [ALPM-SCRIPTLET]   -> Running build hook: [lvm2]
[2022-08-03T00:46:18+0200] [ALPM-SCRIPTLET]   -> Running build hook: [filesystems]
[2022-08-03T00:46:20+0200] [ALPM-SCRIPTLET]   -> Running build hook: [resume]
[2022-08-03T00:46:20+0200] [ALPM-SCRIPTLET]   -> Running build hook: [fsck]
[2022-08-03T00:46:21+0200] [ALPM-SCRIPTLET] ==> Generating module dependencies
[2022-08-03T00:46:22+0200] [ALPM-SCRIPTLET] ==> Creating zstd-compressed initcpio image: /boot/initramfs-linux-fallback.img
[2022-08-03T00:46:24+0200] [ALPM-SCRIPTLET] ==> Image generation successful
[2022-08-03T00:46:24+0200] [ALPM] running 'detect-old-perl-modules.hook'...
[2022-08-03T00:46:24+0200] [ALPM] running 'gtk-update-icon-cache.hook'...
[2022-08-03T00:46:24+0200] [ALPM] running 'texinfo-install.hook'...
[2022-08-03T00:46:28+0200] [ALPM] running 'update-desktop-database.hook'...

If you give me concrete steps, I could debug it with gdb or something.

The following packages were update/installed both times:

binutils
elfutils
firefox
firefox-i18n-de
gcc
gcc-fortran
gcc-libs
glibc
imagemagick
lib32-gcc-libs
lib32-glibc
libelf
libsysprof-capture
libtool
linux
linux-api-headers
mpfr
webkit2gtk
webkit2gtk-4.1

Before the error printing code is a comment, asking, whether writing to a closed pipe is really an error, and that it should never happen. (job.c). Writing to a closed pipe is indicative of an error, and it can happen. The 'real' errror message is available in the mail or syslog:

cron.notice: Aug  3 00:03:11 fcron[7416]: Job '/usr/bin/run-parts /etc/cron.daily' completed
cron.err: Aug  3 01:01:00 fcron[18828]: Could not init PAM account management for user 'root': Module is unknown
cron.err: Aug  3 01:01:00 fcron[18828]: Job '/usr/bin/run-parts /etc/cron.hourly' has *not* run.
cron.err: Aug  3 01:01:00 fcron[18828]: Couldn't exec '/usr/bin/sendmail': No such file or directory
cron.err: Aug  3 01:01:00 fcron[18828]: fcron child aborted: this does not affect the main fcron daemon, but this may prevent a job from being run or an email from being sent.
cron.err: Aug  3 01:01:00 fcron[1015]: read_write_pipe(): read/write returned 0: retrying... (size: 4, size_processed: 0, num_retry: 1): Success
cron.err: Aug  3 01:01:01 fcron[1015]: read_write_pipe(): read/write returned 0: retrying... (size: 4, size_processed: 0, num_retry: 2): Success
cron.err: Aug  3 01:01:02 fcron[1015]: read_write_pipe(): read/write returned 0: retrying... (size: 4, size_processed: 0, num_retry: 3): Success
cron.err: Aug  3 01:01:03 fcron[1015]: Could not read job pid because of closed pipe: setting it to -1

castilma avatar Aug 08 '22 12:08 castilma

Here are the open files of fcron

lr-x------ 1 root root 64  8. Aug 14:31 0 -> /dev/null
l-wx------ 1 root root 64  8. Aug 14:31 1 -> 'pipe:[17223]'
l-wx------ 1 root root 64  8. Aug 14:31 2 -> 'pipe:[17223]'
lrwx------ 1 root root 64  8. Aug 14:31 3 -> /run/fcron.pid
lrwx------ 1 root root 64  8. Aug 14:31 4 -> 'socket:[17652]'
lrwx------ 1 root root 64  8. Aug 14:31 5 -> 'socket:[17653]'
lrwx------ 1 root root 64  8. Aug 14:31 6 -> 'anon_inode:[timerfd]'

and an strace:

pselect6(7, [5 6], NULL, NULL, {tv_sec=49, tv_nsec=223536660}, NULL) = 0 (Timeout)
pipe2([7, 8], 0)                        = 0
clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7fb77d372e90) = 14791
close(8)                                = 0
read(7, "", 4)                          = 0
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=14791, si_uid=1000, si_status=2, si_utime=0, si_stime=0} ---
rt_sigreturn({mask=[]})                 = 0
getpid()                                = 1015
sendto(4, "<75>Aug  8 15:07:00 fcron[1015]:"..., 138, MSG_NOSIGNAL, NULL, 0) = 138
newfstatat(AT_FDCWD, "/etc/localtime", {st_mode=S_IFREG|0644, st_size=2298, ...}, 0) = 0
write(2, "2022-08-08 15:07:00 ERROR ", 26) = 26
write(2, "read_write_pipe(): read/write re"..., 106) = 106
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=1, tv_nsec=0}, 0x7ffda95bf740) = 0
read(7, "", 4)                          = 0
getpid()                                = 1015
sendto(4, "<75>Aug  8 15:07:01 fcron[1015]:"..., 138, MSG_NOSIGNAL, NULL, 0) = 138
newfstatat(AT_FDCWD, "/etc/localtime", {st_mode=S_IFREG|0644, st_size=2298, ...}, 0) = 0
write(2, "2022-08-08 15:07:01 ERROR ", 26) = 26
write(2, "read_write_pipe(): read/write re"..., 106) = 106
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=1, tv_nsec=0}, 0x7ffda95bf740) = 0
read(7, "", 4)                          = 0
getpid()                                = 1015
sendto(4, "<75>Aug  8 15:07:02 fcron[1015]:"..., 138, MSG_NOSIGNAL, NULL, 0) = 138
newfstatat(AT_FDCWD, "/etc/localtime", {st_mode=S_IFREG|0644, st_size=2298, ...}, 0) = 0
write(2, "2022-08-08 15:07:02 ERROR ", 26) = 26
write(2, "read_write_pipe(): read/write re"..., 106) = 106
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=1, tv_nsec=0}, 0x7ffda95bf740) = 0
read(7, "", 4)                          = 0
getpid()                                = 1015
sendto(4, "<75>Aug  8 15:07:03 fcron[1015]:"..., 96, MSG_NOSIGNAL, NULL, 0) = 96
newfstatat(AT_FDCWD, "/etc/localtime", {st_mode=S_IFREG|0644, st_size=2298, ...}, 0) = 0
write(2, "2022-08-08 15:07:03 ERROR ", 26) = 26
write(2, "Could not read job pid because o"..., 64) = 64
close(7)                                = 0

castilma avatar Aug 08 '22 12:08 castilma

now I looked at syslog again:

authpriv.err: Aug  3 01:01:00 fcron[18828]: PAM unable to dlopen(/usr/lib/security/pam_unix.so): /usr/lib/libc.so.6: version `GLIBC_ABI_DT_RELR' not found (required by /usr/lib/libpthread.so.0)
authpriv.err: Aug  3 01:01:00 fcron[18828]: PAM adding faulty module: /usr/lib/security/pam_unix.so

I guess it's the glibc update which brakes the ABI of something?

So, is this an fcron bug? I never experienced any daemon problems with PAM after an update. So maybe fcron is doing something more vulnerable. But I'm not sure how many daemons I'm using, that use PAM...

I wonder who's at fault: An update causes already running processes to continue running with an outdated libc, which breaks dlopen with newer libraries (I think that's the problem).

castilma avatar Aug 08 '22 13:08 castilma

There is an archlinux forum post with a similar error message. Also, restarting fcron fixes it. So, even though the problem doesn't seem to be a fcron bug, maybe fcron should restart itself to fix this.

castilma avatar Aug 08 '22 13:08 castilma

@yo8192 Could you please mention the commit, that fixed this?

Two weeks ago I only find this, which seems to fix #23, but not this issue.

castilma avatar Jun 13 '24 10:06 castilma

@castilma I did a clean-up of issues then and I assumed this one was old and probably no longer relevant. I should have put a comment to say so, apologies for the confusion.

What you described here looks more like a distribution issue than a fcron issue. Also no one else has reported this on other distributions.

I see fcron is packaged under Artix Linux: https://packages.artixlinux.org/details/fcron. Did you use the distribution package to install fcron? If so I think it would be best to contact the Artix package maintainer to investigate and possibly to add some auto-restart in that scenario if that seems to help.

Also your original message mentions fcron 3.2.1... have you seen this problem with the latest fcron version 3.3.1?

yo8192 avatar Jun 16 '24 09:06 yo8192

I installed the one distributed by artix. No, I haven't seen it since.

castilma avatar Jun 16 '24 14:06 castilma