Red Hat Bugzilla – Bug 156832
automount hangs due to unsafe syslog call in signal handler
Last modified: 2007-11-30 17:11:05 EST
Description of problem: Been seeing some hangs of the automount daemon while trying to mount NFS partitions. In this case I have /data automounted via an NIS map. It hung trying to mount /data/sw1. I've included the debug logs below. System is still in hung state (cannot access any directories under /data). Let me know if you want another test while in this state. Version-Release number of selected component (if applicable): autofs-4.1.3-114 How reproducible: somewhat Additional info: Debug logs: May 4 04:07:14 cynosure automount[32752]: expiring path /data/backup1 May 4 04:07:14 cynosure automount[32752]: umount_multi: path=/data/backup1 incl=1 May 4 04:07:14 cynosure automount[32752]: umount_multi: unmounting dir=/data/backup1 May 4 04:07:15 cynosure automount[32752]: expired /data/backup1 May 4 04:07:15 cynosure automount[3907]: handle_child: got pid 32752, sig 0 (0), stat 0 May 4 04:07:15 cynosure automount[3907]: sig_child: found pending iop pid 32752: signalled 0 (sig 0), exit status 0 May 4 04:07:15 cynosure automount[3907]: send_ready: token=375 May 4 04:07:15 cynosure automount[3907]: handle_packet: type = 2 May 4 04:07:15 cynosure automount[3907]: handle_packet_expire_multi: token 376, name sw1 May 4 04:07:15 cynosure automount[32754]: expiring path /data/sw1 May 4 04:07:15 cynosure automount[32754]: umount_multi: path=/data/sw1 incl=1 May 4 04:07:15 cynosure automount[32754]: umount_multi: unmounting dir=/data/sw1 May 4 04:07:15 cynosure automount[32754]: expired /data/sw1 May 4 04:07:15 cynosure automount[3907]: handle_child: got pid 32754, sig 0 (0), stat 0 May 4 04:07:15 cynosure automount[3907]: sig_child: found pending iop pid 32754: signalled 0 (sig 0), exit status 0 May 4 04:07:15 cynosure automount[3907]: send_ready: token=376 May 4 04:07:15 cynosure automount[3907]: handle_child: got pid 32751, sig 0 (0), stat 0 May 4 04:07:15 cynosure automount[3907]: sigchld: exp 32751 finished, switching from 2 to 1 May 4 04:07:15 cynosure automount[3907]: get_pkt: state 2, next 1 May 4 04:07:15 cynosure automount[3907]: st_ready(): state = 2 May 4 04:07:30 cynosure automount[3907]: sig 14 switching from 1 to 2 May 4 04:07:30 cynosure automount[3907]: get_pkt: state 1, next 2 May 4 04:07:30 cynosure automount[3907]: st_expire(): state = 1 May 4 04:07:30 cynosure automount[3907]: expire_proc: exp_proc=310 May 4 04:07:30 cynosure automount[3907]: handle_child: got pid 310, sig 0 (0), stat 0 May 4 04:07:30 cynosure automount[3907]: sigchld: exp 310 finished, switching from 2 to 1 May 4 04:07:30 cynosure automount[3907]: get_pkt: state 2, next 1 May 4 04:07:30 cynosure automount[3907]: st_ready(): state = 2 May 4 04:07:45 cynosure automount[3907]: sig 14 switching from 1 to 2 May 4 04:07:45 cynosure automount[3907]: get_pkt: state 1, next 2 May 4 04:07:45 cynosure automount[3907]: st_expire(): state = 1 May 4 04:07:45 cynosure automount[3907]: expire_proc: exp_proc=378 May 4 04:07:45 cynosure automount[3907]: handle_child: got pid 378, sig 0 (0), stat 0 May 4 04:07:45 cynosure automount[3907]: sigchld: exp 378 finished, switching from 2 to 1 May 4 04:07:45 cynosure automount[3907]: get_pkt: state 2, next 1 May 4 04:07:45 cynosure automount[3907]: st_ready(): state = 2 May 4 04:08:00 cynosure automount[3907]: sig 14 switching from 1 to 2 May 4 04:08:00 cynosure automount[3907]: get_pkt: state 1, next 2 May 4 04:08:00 cynosure automount[3907]: st_expire(): state = 1 May 4 04:08:00 cynosure automount[3907]: expire_proc: exp_proc=788 May 4 04:08:00 cynosure automount[3907]: handle_child: got pid 788, sig 0 (0), stat 0 May 4 04:08:00 cynosure automount[3907]: sigchld: exp 788 finished, switching from 2 to 1 May 4 04:08:00 cynosure automount[3907]: get_pkt: state 2, next 1 May 4 04:08:00 cynosure automount[3907]: st_ready(): state = 2 May 4 04:08:01 cynosure automount[3907]: handle_packet: type = 0 May 4 04:08:01 cynosure automount[3907]: handle_packet_missing: token 377, name sw1 May 4 04:08:01 cynosure automount[3907]: attempting to mount entry /data/sw1 May 4 04:08:01 cynosure automount[849]: lookup(yp): looking up sw1 May 4 04:08:01 cynosure automount[849]: ret = 1 May 4 04:08:01 cynosure automount[849]: lookup(yp): sw1 -> -rsize=8192,wsize=8192 alexandria:/export/data1 May 4 04:08:01 cynosure automount[849]: parse(sun): expanded entry: -rsize=8192,wsize=8192 alexandria:/export/data1 May 4 04:08:01 cynosure automount[849]: parse(sun): dequote("rsize=8192,wsize=8192") -> rsize=8192,wsize=8192 May 4 04:08:01 cynosure automount[849]: parse(sun): gathered options: intr,,rsize=8192,wsize=8192 May 4 04:08:01 cynosure automount[849]: parse(sun): dequote("alexandria:/export/data1") -> alexandria:/export/data1 May 4 04:08:01 cynosure automount[849]: parse(sun): core of entry: options=intr,,rsize=8192,wsize=8192, loc=alexandria:/export/data1 May 4 04:08:01 cynosure automount[849]: parse(sun): mounting root /data, mountpoint sw1,what alexandria:/export/data1, fstype nfs, options intr,rsize=8192,wsize=8192 May 4 04:08:01 cynosure automount[3907]: handle_packet: type = 0 May 4 04:08:01 cynosure automount[3907]: handle_packet_missing: token 378, name backup1 May 4 04:08:01 cynosure automount[3907]: attempting to mount entry /data/backup1 May 4 04:08:01 cynosure automount[849]: mount(nfs): root=/data name=sw1 what=alexandria:/export/data1, fstype=nfs, options=intr,rsize=8192,wsize=8192 May 4 04:08:01 cynosure automount[851]: lookup(yp): looking up backup1 May 4 04:08:02 cynosure automount[849]: mount(nfs): nfs options="intr,rsize=8192,wsize=8192", nosymlink=0 May 4 04:08:02 cynosure automount[851]: ret = 1 May 4 04:08:02 cynosure automount[849]: mount(nfs): is_local_mount: alexandria:/export/data1 May 4 04:08:02 cynosure automount[851]: lookup(yp): backup1 -> -rsize=8192,wsize=8192 saga:/export/backup1 May 4 04:08:02 cynosure automount[849]: mount(nfs): from alexandria:/export/data1 elected alexandria:/export/data1 May 4 04:08:02 cynosure automount[851]: parse(sun): expanded entry: -rsize=8192,wsize=8192 saga:/export/backup1 May 4 04:08:02 cynosure automount[849]: mount(nfs): calling mkdir_path /data/sw1 May 4 04:08:02 cynosure automount[851]: parse(sun): dequote("rsize=8192,wsize=8192") -> rsize=8192,wsize=8192 May 4 04:08:02 cynosure automount[849]: mount(nfs): calling mount -t nfs -s -o intr,rsize=8192,wsize=8192 alexandria:/export/data1 /data/sw1 May 4 04:08:02 cynosure automount[851]: parse(sun): gathered options: intr,,rsize=8192,wsize=8192 May 4 04:08:02 cynosure automount[851]: parse(sun): dequote("saga:/export/backup1") -> saga:/export/backup1 May 4 04:08:02 cynosure automount[849]: mount(nfs): mounted alexandria:/export/data1 on /data/sw1 May 4 04:08:02 cynosure automount[851]: parse(sun): core of entry: options=intr,,rsize=8192,wsize=8192, loc=saga:/export/backup1 May 4 04:08:02 cynosure automount[3907]: handle_child: got pid 849, sig 0 (0), stat 0 May 4 04:08:02 cynosure automount[851]: parse(sun): mounting root /data, mountpoint backup1, what saga:/export/backup1, fstype nfs, options intr,rsize=8192,wsize=8192 May 4 04:08:02 cynosure automount[3907]: sig_child: found pending iop pid 849: signalled0 (sig 0), exit status 0 May 4 04:08:02 cynosure automount[851]: mount(nfs): root=/data name=backup1 what=saga:/export/backup1, fstype=nfs, options=intr,rsize=8192,wsize=8192 May 4 04:08:02 cynosure automount[3907]: send_ready: token=377 May 4 04:08:02 cynosure automount[851]: mount(nfs): nfs options="intr,rsize=8192,wsize=8192", nosymlink=0 May 4 04:08:02 cynosure automount[851]: mount(nfs): is_local_mount: saga:/export/backup1 May 4 04:08:02 cynosure automount[851]: mount(nfs): from saga:/export/backup1 elected saga:/export/backup1 May 4 04:08:02 cynosure automount[851]: mount(nfs): calling mkdir_path /data/backup1 May 4 04:08:02 cynosure automount[851]: mount(nfs): calling mount -t nfs -s -o intr,rsize=8192,wsize=8192 saga:/export/backup1 /data/backup1 May 4 04:08:02 cynosure automount[851]: mount(nfs): mounted saga:/export/backup1 on /data/backup1 May 4 04:08:02 cynosure automount[3907]: handle_child: got pid 851, sig 0 (0), stat 0 May 4 04:08:02 cynosure automount[3907]: sig_child: found pending iop pid 851: signalled0 (sig 0), exit status 0 May 4 04:08:02 cynosure automount[3907]: send_ready: token=378 May 4 04:08:15 cynosure automount[3907]: sig 14 switching from 1 to 2 May 4 04:08:15 cynosure automount[3907]: get_pkt: state 1, next 2 May 4 04:08:15 cynosure automount[3907]: st_expire(): state = 1 May 4 04:08:15 cynosure automount[3907]: expire_proc: exp_proc=1329 May 4 04:08:15 cynosure automount[1329]: expire_proc: 2 remaining in /data May 4 04:08:15 cynosure automount[3907]: handle_child: got pid 1329, sig 0 (0), stat 1 May 4 04:08:15 cynosure automount[3907]: sigchld: exp 1329 finished, switching from 2 to1 May 4 04:08:15 cynosure automount[3907]: get_pkt: state 2, next 1 May 4 04:08:15 cynosure automount[3907]: st_ready(): state = 2 May 4 04:08:30 cynosure automount[3907]: sig 14 switching from 1 to 2 May 4 04:08:30 cynosure automount[3907]: get_pkt: state 1, next 2 May 4 04:08:30 cynosure automount[3907]: st_expire(): state = 1 May 4 04:08:30 cynosure automount[3907]: expire_proc: exp_proc=1740 May 4 04:08:30 cynosure automount[1740]: expire_proc: 2 remaining in /data May 4 04:08:30 cynosure automount[3907]: handle_child: got pid 1740, sig 0 (0), stat 1 May 4 04:08:30 cynosure automount[3907]: sigchld: exp 1740 finished, switching from 2 to1 May 4 04:08:30 cynosure automount[3907]: get_pkt: state 2, next 1 May 4 04:08:30 cynosure automount[3907]: st_ready(): state = 2 May 4 04:08:45 cynosure automount[3907]: sig 14 switching from 1 to 2 May 4 04:08:45 cynosure automount[3907]: get_pkt: state 1, next 2 May 4 04:08:45 cynosure automount[3907]: st_expire(): state = 1 May 4 04:08:45 cynosure automount[3907]: expire_proc: exp_proc=2009 May 4 04:08:45 cynosure automount[2009]: expire_proc: 2 remaining in /data May 4 04:08:45 cynosure automount[3907]: handle_child: got pid 2009, sig 0 (0), stat 1 May 4 04:08:45 cynosure automount[3907]: sigchld: exp 2009 finished, switching from 2 to1 May 4 04:08:45 cynosure automount[3907]: get_pkt: state 2, next 1 May 4 04:08:45 cynosure automount[3907]: st_ready(): state = 2 May 4 04:09:00 cynosure automount[3907]: sig 14 switching from 1 to 2 May 4 04:09:00 cynosure automount[3907]: get_pkt: state 1, next 2 May 4 04:09:00 cynosure automount[3907]: st_expire(): state = 1 May 4 04:09:00 cynosure automount[3907]: expire_proc: exp_proc=2252 May 4 04:09:00 cynosure automount[2252]: expire_proc: 2 remaining in /data May 4 04:09:00 cynosure automount[3907]: handle_child: got pid 2252, sig 0 (0), stat 1 May 4 04:09:00 cynosure automount[3907]: sigchld: exp 2252 finished, switching from 2 to1 May 4 04:09:00 cynosure automount[3907]: get_pkt: state 2, next 1 May 4 04:09:00 cynosure automount[3907]: st_ready(): state = 2 May 4 04:09:15 cynosure automount[3907]: sig 14 switching from 1 to 2 May 4 04:09:15 cynosure automount[3907]: get_pkt: state 1, next 2 May 4 04:09:15 cynosure automount[3907]: st_expire(): state = 1 May 4 04:09:15 cynosure automount[3907]: expire_proc: exp_proc=2668 May 4 04:09:15 cynosure automount[3907]: handle_packet: type = 2 May 4 04:09:15 cynosure automount[3907]: handle_packet_expire_multi: token 379, name backup1 May 4 04:09:15 cynosure automount[2669]: expiring path /data/backup1 May 4 04:09:15 cynosure automount[2669]: umount_multi: path=/data/backup1 incl=1 May 4 04:09:15 cynosure automount[2669]: umount_multi: unmounting dir=/data/backup1 May 4 04:09:15 cynosure automount[2669]: expired /data/backup1 May 4 04:09:15 cynosure automount[3907]: handle_child: got pid 2669, sig 0 (0), stat 0 May 4 04:09:15 cynosure automount[3907]: sig_child: found pending iop pid 2669: signalled 0 (sig 0), exit status 0 May 4 04:09:15 cynosure automount[3907]: send_ready: token=379 May 4 04:09:15 cynosure automount[3907]: handle_packet: type = 2 May 4 04:09:15 cynosure automount[3907]: handle_packet_expire_multi: token 380, name sw1 May 4 04:09:15 cynosure automount[2676]: expiring path /data/sw1 May 4 04:09:15 cynosure automount[2676]: umount_multi: path=/data/sw1 incl=1 May 4 04:09:15 cynosure automount[2676]: umount_multi: unmounting dir=/data/sw1 May 4 04:09:15 cynosure automount[2676]: expired /data/sw1 May 4 04:09:15 cynosure automount[3907]: handle_child: got pid 2676, sig 0 (0), stat 0 May 4 04:09:15 cynosure automount[3907]: sig_child: found pending iop pid 2676: signalled 0 (sig 0), exit status 0 May 4 04:09:15 cynosure automount[3907]: send_ready: token=380 May 4 04:09:15 cynosure automount[3907]: handle_child: got pid 2668, sig 0 (0), stat 0 May 4 04:09:15 cynosure automount[3907]: sigchld: exp 2668 finished, switching from 2 to1 May 4 04:09:15 cynosure automount[3907]: get_pkt: state 2, next 1 May 4 04:09:15 cynosure automount[3907]: st_ready(): state = 2 May 4 04:09:30 cynosure automount[3907]: sig 14 switching from 1 to 2 May 4 04:09:30 cynosure automount[3907]: get_pkt: state 1, next 2 May 4 04:09:30 cynosure automount[3907]: st_expire(): state = 1 May 4 04:09:30 cynosure automount[3907]: expire_proc: exp_proc=3013 May 4 04:09:30 cynosure automount[3907]: handle_child: got pid 3013, sig 0 (0), stat 0 May 4 04:09:30 cynosure automount[3907]: sigchld: exp 3013 finished, switching from 2 to1 May 4 04:09:30 cynosure automount[3907]: get_pkt: state 2, next 1 May 4 04:09:30 cynosure automount[3907]: st_ready(): state = 2 May 4 04:09:45 cynosure automount[3907]: sig 14 switching from 1 to 2 May 4 04:09:45 cynosure automount[3907]: get_pkt: state 1, next 2 May 4 04:09:45 cynosure automount[3907]: st_expire(): state = 1 May 4 04:09:45 cynosure automount[3907]: expire_proc: exp_proc=3020 May 4 04:09:45 cynosure automount[3907]: handle_child: got pid 3020, sig 0 (0), stat 0 May 4 04:09:45 cynosure automount[3907]: sigchld: exp 3020 finished, switching from 2 to1 May 4 04:09:45 cynosure automount[3907]: get_pkt: state 2, next 1 May 4 04:09:45 cynosure automount[3907]: st_ready(): state = 2 May 4 04:10:00 cynosure automount[3907]: sig 14 switching from 1 to 2 May 4 04:10:00 cynosure automount[3907]: get_pkt: state 1, next 2 May 4 04:10:00 cynosure automount[3907]: st_expire(): state = 1 May 4 04:10:00 cynosure automount[3907]: expire_proc: exp_proc=3226 May 4 04:10:00 cynosure automount[3907]: handle_child: got pid 3226, sig 0 (0), stat 0 May 4 04:10:00 cynosure automount[3907]: sigchld: exp 3226 finished, switching from 2 to1 May 4 04:10:00 cynosure automount[3907]: get_pkt: state 2, next 1 May 4 04:10:00 cynosure automount[3907]: st_ready(): state = 2 May 4 04:10:01 cynosure automount[3907]: handle_packet: type = 0 May 4 04:10:01 cynosure automount[3907]: handle_packet_missing: token 381, name backup1 May 4 04:10:01 cynosure automount[3907]: attempting to mount entry /data/backup1 May 4 04:10:01 cynosure automount[3264]: lookup(yp): looking up backup1 May 4 04:10:01 cynosure automount[3264]: ret = 1 May 4 04:10:01 cynosure automount[3264]: lookup(yp): backup1 -> -rsize=8192,wsize=8192 saga:/export/backup1 May 4 04:10:01 cynosure automount[3264]: parse(sun): expanded entry: -rsize=8192,wsize=8192 saga:/export/backup1 May 4 04:10:01 cynosure automount[3264]: parse(sun): dequote("rsize=8192,wsize=8192") ->rsize=8192,wsize=8192 May 4 04:10:01 cynosure automount[3264]: parse(sun): gathered options: intr,,rsize=8192,wsize=8192 May 4 04:10:01 cynosure automount[3264]: parse(sun): dequote("saga:/export/backup1") -> saga:/export/backup1 May 4 04:10:01 cynosure automount[3264]: parse(sun): core of entry: options=intr,,rsize=8192,wsize=8192, loc=saga:/export/backup1 May 4 04:10:01 cynosure automount[3264]: parse(sun): mounting root /data, mountpoint backup1, what saga:/export/backup1, fstype nfs, options intr,rsize=8192,wsize=8192 May 4 04:10:01 cynosure automount[3264]: mount(nfs): root=/data name=backup1 what=saga:/export/backup1, fstype=nfs, options=intr,rsize=8192,wsize=8192 May 4 04:10:01 cynosure automount[3264]: mount(nfs): nfs options="intr,rsize=8192,wsize=8192", nosymlink=0 May 4 04:10:01 cynosure automount[3264]: mount(nfs): is_local_mount: saga:/export/backup1 May 4 04:10:01 cynosure automount[3264]: mount(nfs): from saga:/export/backup1 elected saga:/export/backup1 May 4 04:10:01 cynosure automount[3264]: mount(nfs): calling mkdir_path /data/backup1 May 4 04:10:01 cynosure automount[3264]: mount(nfs): calling mount -t nfs -s -o intr,rsize=8192,wsize=8192 saga:/export/backup1 /data/backup1 May 4 04:10:01 cynosure automount[3907]: handle_packet: type = 0 May 4 04:10:01 cynosure automount[3907]: handle_packet_missing: token 382, name sw1 May 4 04:10:01 cynosure automount[3264]: mount(nfs): mounted saga:/export/backup1 on /data/backup1
Hi, Are the posted logs truncated? Do you not get any further messages? Could you do an strace -p 3907, and post where it is hung up? Thanks.
No truncation, there are just no more automount messages in the log after these. # strace -p 3907 Process 3907 attached - interrupt to quit futex(0xb7fc328c, FUTEX_WAIT, 2, NULL
Ok, do you normally run with --debug enabled? If so, you shouldn't! What you have here is an unsafe call to syslog in an interrupt handler causing a deadlock. This is more likely to occur when debugging is enabled. I have a preliminary patch to work around this, but it hasn't seen extensive testing. I'll post it here.
I'm running in debug mode trying to track down bug 154393 and another issue that I've seen sometimes with automount that I haven't reported yet (hoping to capture debug output first).
Created attachment 114027 [details] defer syslog calls to non-signal handler context This patch is against autofs version 4.1.4. Once it has been finalized, I will backport it to the current version of autofs in FC3.
doesn't apply to the autofs in rawhide (4.1.4-5): + echo 'Patch #10 (autofs-4.1.4-deferred-syslog.patch):' Patch #10 (autofs-4.1.4-deferred-syslog.patch): + patch -p1 -s 1 out of 3 hunks FAILED -- saving rejects to file include/automount.h.rej 1 out of 2 hunks FAILED -- saving rejects to file lib/Makefile.rej Perhaps you could make a src.rpm available that I could build and test?
I'll work on getting the patch merged into a current tree. Is 4.1.4 preferable for you, or would you rather work off the 4.1.3 stream? Thanks.
I don't think I care which, as long as I can compile/install on otherwise stock FC3
Created attachment 114037 [details] Defer syslogs to non-signal handler context Here is the patch ported forward to my latest CVS version of autofs. I'll attach a source rpm for you to try, as well.
Created attachment 114038 [details] source rpm with the deferred syslog patch Here is the source rpm, as promised.
Compiled and am testing. So far so good.
This is most certainly fixed at this point. Closing.