Bug 2083926

Summary: Spawned process '/usr/libexec/nfsrahead 251:0' [2778] is taking longer than 59s to complete
Product: [Fedora] Fedora Reporter: Zhang Yi <yizhan>
Component: nfs-utilsAssignee: Steve Dickson <steved>
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: rawhideCC: bfields, dwrobel, luk.claes, mironov.ivan, steved, tbecker
Target Milestone: ---   
Target Release: ---   
Hardware: aarch64   
OS: Unspecified   
Whiteboard:
Fixed In Version: nfs-utils-2.6.1-2.rc5.fc36 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2022-06-01 01:24:37 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

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 3 Thiago Rafael Becker 2022-05-13 19:23:05 UTC 
https://lore.kernel.org/linux-nfs/20220513191808.2930668-1-tbecker@redhat.com/T/#u
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.