Bug 2083926 - Spawned process '/usr/libexec/nfsrahead 251:0' [2778] is taking longer than 59s to complete
Summary: Spawned process '/usr/libexec/nfsrahead 251:0' [2778] is taking longer than 5...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: nfs-utils
Version: rawhide
Hardware: aarch64
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Steve Dickson
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
: 2086693 (view as bug list)
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2022-05-11 03:47 UTC by Zhang Yi
Modified: 2022-06-01 01:24 UTC (History)
6 users (show)

Fixed In Version: nfs-utils-2.6.1-2.rc5.fc36
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2022-06-01 01:24:37 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)

Description Zhang Yi 2022-05-11 03:47:30 UTC
Description of problem:


Version-Release number of selected component (if applicable):

nfs-utils-2.6.1-2.rc4.fc37.aarch64
systemd-udev-251~rc2-1.fc37.aarch64
5.18.0-0.rc5.20220506gitfe27d189e3f42e3.44.fc37.aarch64

How reproducible:


Steps to Reproduce:
+ echo 'START: Tue May 10 10:37:04 PM EDT 2022'
+ rmmod null-blk
+ modprobe null-blk
+ udevadm settle

real	2m0.058s
user	0m0.221s
sys	0m8.414s
+ echo 'END: Tue May 10 10:39:04 PM EDT 2022'
+ sleep 120
+ journalctl --no-hostname -b -u systemd-udevd.service

Actual results:


Expected results:


Additional info:

joutnalctl log:
May 10 22:37:04 systemd-udevd[1142]: 251:0: Device is queued (SEQNUM=7881, ACTION=remove)
May 10 22:37:04 systemd-udevd[1142]: Validate module index
May 10 22:37:04 systemd-udevd[1142]: Check if link configuration needs reloading.
May 10 22:37:04 systemd-udevd[1142]: 251:0: Device ready for processing (SEQNUM=7881, ACTION=remove)
May 10 22:37:04 systemd-udevd[1142]: Successfully forked off 'n/a' as PID 2775.
May 10 22:37:04 systemd-udevd[1142]: 251:0: Worker [2775] is forked for processing SEQNUM=7881.
May 10 22:37:04 systemd-udevd[1142]: nullb0: Device is queued (SEQNUM=7882, ACTION=remove)
May 10 22:37:04 systemd-udevd[1142]: nullb0: Device ready for processing (SEQNUM=7882, ACTION=remove)
May 10 22:37:04 systemd-udevd[2775]: 251:0: Processing device (SEQNUM=7881, ACTION=remove)
May 10 22:37:04 systemd-udevd[1142]: Successfully forked off 'n/a' as PID 2776.
May 10 22:37:04 systemd-udevd[1142]: nullb0: Worker [2776] is forked for processing SEQNUM=7882.
May 10 22:37:04 systemd-udevd[2775]: 251:0: Device processed (SEQNUM=7881, ACTION=remove)
May 10 22:37:04 systemd-udevd[2775]: 251:0: sd-device-monitor: Passed 144 byte to netlink monitor
May 10 22:37:04 systemd-udevd[2776]: nullb0: Processing device (SEQNUM=7882, ACTION=remove)
May 10 22:37:04 systemd-udevd[2776]: nullb0: Failed to get watch handle, ignoring: No such file or directory
May 10 22:37:04 systemd-udevd[2776]: nullb0: Device processed (SEQNUM=7882, ACTION=remove)
May 10 22:37:04 systemd-udevd[2776]: nullb0: sd-device-monitor: Passed 278 byte to netlink monitor
May 10 22:37:04 systemd-udevd[1142]: No events are queued, removing /run/udev/queue.
May 10 22:37:04 systemd-udevd[1142]: null_blk: Device is queued (SEQNUM=7883, ACTION=remove)
May 10 22:37:04 systemd-udevd[1142]: null_blk: Device ready for processing (SEQNUM=7883, ACTION=remove)
May 10 22:37:04 systemd-udevd[1142]: null_blk: sd-device-monitor: Passed 137 byte to netlink monitor
May 10 22:37:04 systemd-udevd[2775]: null_blk: Processing device (SEQNUM=7883, ACTION=remove)
May 10 22:37:04 systemd-udevd[2775]: null_blk: Device processed (SEQNUM=7883, ACTION=remove)
May 10 22:37:04 systemd-udevd[2775]: null_blk: sd-device-monitor: Passed 137 byte to netlink monitor
May 10 22:37:04 systemd-udevd[1142]: No events are queued, removing /run/udev/queue.
May 10 22:37:04 systemd-udevd[1142]: 251:0: Device is queued (SEQNUM=7884, ACTION=add)
May 10 22:37:04 systemd-udevd[1142]: 251:0: Device ready for processing (SEQNUM=7884, ACTION=add)
May 10 22:37:04 systemd-udevd[1142]: 251:0: sd-device-monitor: Passed 141 byte to netlink monitor
May 10 22:37:04 systemd-udevd[2775]: 251:0: Processing device (SEQNUM=7884, ACTION=add)
May 10 22:37:04 systemd-udevd[1142]: nullb0: Device is queued (SEQNUM=7885, ACTION=add)
May 10 22:37:04 systemd-udevd[1142]: nullb0: Device ready for processing (SEQNUM=7885, ACTION=add)
May 10 22:37:04 systemd-udevd[1142]: nullb0: sd-device-monitor: Passed 208 byte to netlink monitor
May 10 22:37:04 systemd-udevd[2776]: nullb0: Processing device (SEQNUM=7885, ACTION=add)
May 10 22:37:04 systemd-udevd[2776]: nullb0: Failed to get watch handle, ignoring: No such file or directory
May 10 22:37:04 systemd-udevd[2776]: nullb0: /usr/lib/udev/rules.d/50-udev-default.rules:74 GROUP 6
May 10 22:37:04 systemd-udevd[2775]: 251:0: /usr/lib/udev/rules.d/99-nfs.rules:1 Running PROGRAM '/usr/libexec/nfsrahead 251:0'
May 10 22:37:04 systemd-udevd[2775]: 251:0: Starting '/usr/libexec/nfsrahead 251:0'
May 10 22:37:04 systemd-udevd[2776]: nullb0: Setting permissions /dev/nullb0, uid=0, gid=6, mode=0660
May 10 22:37:04 systemd-udevd[1142]: null_blk: Device is queued (SEQNUM=7886, ACTION=add)
May 10 22:37:04 systemd-udevd[1142]: null_blk: Device ready for processing (SEQNUM=7886, ACTION=add)
May 10 22:37:04 systemd-udevd[2776]: nullb0: Handling device node '/dev/nullb0', devnum=b251:0
May 10 22:37:04 systemd-udevd[2775]: Successfully forked off '(spawn)' as PID 2778.
May 10 22:37:04 systemd-udevd[2776]: nullb0: sd-device: Created db file '/run/udev/data/b251:0' for '/devices/virtual/block/nullb0'
May 10 22:37:04 systemd-udevd[2776]: nullb0: Failed to get watch handle, ignoring: No such file or directory
May 10 22:37:04 systemd-udevd[2776]: nullb0: Device processed (SEQNUM=7885, ACTION=add)
May 10 22:37:04 systemd-udevd[2776]: nullb0: sd-device-monitor: Passed 275 byte to netlink monitor
May 10 22:37:04 systemd-udevd[1142]: Successfully forked off 'n/a' as PID 2779.
May 10 22:37:04 systemd-udevd[1142]: null_blk: Worker [2779] is forked for processing SEQNUM=7886.
May 10 22:37:04 systemd-udevd[2779]: null_blk: Processing device (SEQNUM=7886, ACTION=add)
May 10 22:37:04 systemd-udevd[2779]: null_blk: Device processed (SEQNUM=7886, ACTION=add)
May 10 22:37:04 systemd-udevd[2779]: null_blk: sd-device-monitor: Passed 134 byte to netlink monitor
May 10 22:37:04 systemd-udevd[1142]: Received udev control message (PING)
May 10 22:38:04 systemd-udevd[1142]: 251:0: Worker [2775] processing SEQNUM=7884 is taking a long time
May 10 22:38:04 systemd-udevd[2775]: 251:0: Spawned process '/usr/libexec/nfsrahead 251:0' [2778] is taking longer than 59s to complete
May 10 22:38:04 systemd-udevd[1142]: Validate module index
May 10 22:38:04 systemd-udevd[1142]: Check if link configuration needs reloading.
May 10 22:40:04 systemd-udevd[2775]: 251:0: Spawned process '/usr/libexec/nfsrahead 251:0' [2778] timed out after 2min 59s, killing
May 10 22:40:04 systemd-udevd[1142]: 251:0: Worker [2775] processing SEQNUM=7884 killed
May 10 22:40:04 systemd-udevd[1142]: Validate module index
May 10 22:40:04 systemd-udevd[1142]: Check if link configuration needs reloading.
May 10 22:40:04 systemd-udevd[1142]: 251:0: Worker [2775] terminated by signal 9 (KILL).
May 10 22:40:04 systemd-udevd[1142]: 251:0: sd-device-monitor: Passed 212 byte to netlink monitor
May 10 22:40:04 systemd-udevd[1142]: No events are queued, removing /run/udev/queue.
May 10 22:40:08 systemd-udevd[1142]: Cleanup idle workers
May 10 22:40:08 systemd-udevd[2779]: Unload module index
May 10 22:40:08 systemd-udevd[2776]: Unload module index
May 10 22:40:08 systemd-udevd[2776]: Unloaded link configuration context.
May 10 22:40:08 systemd-udevd[2779]: Unloaded link configuration context.
May 10 22:40:08 systemd-udevd[1142]: Worker [2779] exited.
May 10 22:40:08 systemd-udevd[1142]: Worker [2776] exited.

Comment 1 Thiago Rafael Becker 2022-05-13 13:35:09 UTC
Unable to reproduce this in my environment. Attempting to get an aarch64 host for testing.

Comment 2 Thiago Rafael Becker 2022-05-13 19:21:39 UTC
Reproducible on aarch64. While setting up debugging, this happen:

main.c: In function ‘main’:
main.c:145:48: warning: comparison is always true due to limited range of data type [-Wtype-limits]
  145 |         while((opt = getopt(argc, argv, "dF")) != -1) {
      | 

char is unsigned for aarch64. https://developer.arm.com/documentation/den0013/d/Porting/Miscellaneous-C-porting-issues/unsigned-char-and-signed-char.

Sent the patch upstream.

Comment 4 Thiago Rafael Becker 2022-05-20 13:05:08 UTC
*** Bug 2086693 has been marked as a duplicate of this bug. ***

Comment 5 Steve Dickson 2022-05-26 18:55:34 UTC
The upstream commit:

commit f347c3c8c605b874733019685b7f8ae84e86b55e
Author: Thiago Becker <tbecker>
Date:   Thu May 26 12:05:08 2022 -0400

    nfsrahead: getopt return type is int

Comment 6 Fedora Update System 2022-05-28 14:21:34 UTC
FEDORA-2022-66e8427ba0 has been submitted as an update to Fedora 36. https://bodhi.fedoraproject.org/updates/FEDORA-2022-66e8427ba0

Comment 7 Fedora Update System 2022-05-29 02:40:01 UTC
FEDORA-2022-66e8427ba0 has been pushed to the Fedora 36 testing repository.
Soon you'll be able to install the update with the following command:
`sudo dnf upgrade --enablerepo=updates-testing --advisory=FEDORA-2022-66e8427ba0`
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2022-66e8427ba0

See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates.

Comment 8 Fedora Update System 2022-06-01 01:24:37 UTC
FEDORA-2022-66e8427ba0 has been pushed to the Fedora 36 stable repository.
If problem still persists, please make note of it in this bug report.


Note You need to log in before you can comment on or make changes to this bug.