<div dir="ltr">Thanks Felipe to assist me with this and sorry for the late reply!<div class="gmail_extra"><br><div class="gmail_quote">On Thu, Feb 25, 2016 at 7:19 PM, Felipe Sateler <span dir="ltr"><<a href="mailto:fsateler@debian.org" target="_blank">fsateler@debian.org</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div class="HOEnZb"><div class="h5">On 24 February 2016 at 09:29, Sandro Tosi <<a href="mailto:morph@debian.org">morph@debian.org</a>> wrote:<br>
> Hey Felipe, thanks a lot for your help!<br>
><br>
><br>
> On Tue, Feb 23, 2016 at 10:16 PM, Felipe Sateler <<a href="mailto:fsateler@debian.org">fsateler@debian.org</a>><br>
> wrote:<br>
>><br>
>> On 23 February 2016 at 12:12, Sandro Tosi <<a href="mailto:morph@debian.org">morph@debian.org</a>> wrote:<br>
>> > On Tue, Feb 23, 2016 at 9:19 AM, Sandro Tosi <<a href="mailto:morph@debian.org">morph@debian.org</a>> wrote:<br>
>> >> quick update: we had a couple of (real) nfs issues and<br>
>> >> misconfiguration (meeh) that made the script fail even if it shouldnt<br>
>> >> have, so no news yet; the reboot loop just restarted and will<br>
>> >> periodically check it and report back if something comes up.<br>
>> ><br>
>> > so well, we just needed to wait a bit :)<br>
>> ><br>
>> > here it is:<br>
>> ><br>
>> > # journalctl -alb | grep -nE "cron|NFSSERVER"<br>
>> > 1012:Feb 23 06:50:42 SERVER systemd[1]: Installed new job<br>
>> > mnt-NFSSERVER_VOL.mount/start as 99<br>
>> > 1014:Feb 23 06:50:42 SERVER systemd[1]: Installed new job<br>
>> > cron.service/start<br>
>> > as 101<br>
>> > 1714:Feb 23 06:50:43 SERVER systemd[1]: Mounting /mnt/NFSSERVER_VOL...<br>
>> > 1716:Feb 23 06:50:43 SERVER systemd[1]: About to execute: /bin/mount -n<br>
>> > XXX.YYY.32.75:/vol/VOL /mnt/NFSSERVER_VOL -t nfs -o<br>
>> > ro,intr,nolock,tcp,rdirplus,noatime,_netdev<br>
>> > 1718:Feb 23 06:50:43 SERVER systemd[1]: mnt-NFSSERVER_VOL.mount changed<br>
>> > dead<br>
>> > -> mounting<br>
>> > 1720:Feb 23 06:50:43 SERVER systemd[574]: Executing: /bin/mount -n<br>
>> > XXX.YYY.32.75:/vol/VOL /mnt/NFSSERVER_VOL -t nfs -o<br>
>> > ro,intr,nolock,tcp,rdirplus,noatime,_netdev<br>
>> > 1905:Feb 23 06:52:13 SERVER systemd[1]: mnt-NFSSERVER_VOL.mount mounting<br>
>> > timed out. Stopping.<br>
>> > 1906:Feb 23 06:52:13 SERVER systemd[1]: mnt-NFSSERVER_VOL.mount changed<br>
>> > mounting -> mounting-sigterm<br>
>> > 1915:Feb 23 06:52:13 SERVER systemd[1]: Child 574 belongs to<br>
>> > mnt-NFSSERVER_VOL.mount<br>
>> > 1916:Feb 23 06:52:13 SERVER systemd[1]: mnt-NFSSERVER_VOL.mount mount<br>
>> > process exited, code=killed status=15<br>
>> > 1917:Feb 23 06:52:13 SERVER systemd[1]: mnt-NFSSERVER_VOL.mount changed<br>
>> > mounting-sigterm -> mounted<br>
>> > 1918:Feb 23 06:52:13 SERVER systemd[1]: Job<br>
>> > mnt-NFSSERVER_VOL.mount/start<br>
>> > finished, result=done<br>
>> > 1919:Feb 23 06:52:13 SERVER systemd[1]: Mounted /mnt/NFSSERVER_VOL.<br>
>> > 2025:Feb 23 06:52:13 SERVER systemd[1]: About to execute: /usr/sbin/cron<br>
>> > -f<br>
>> > $EXTRA_OPTS<br>
>> > 2026:Feb 23 06:52:13 SERVER systemd[1]: Forked /usr/sbin/cron as 786<br>
>> > 2027:Feb 23 06:52:13 SERVER systemd[1]: cron.service changed dead -><br>
>> > running<br>
>> > 2028:Feb 23 06:52:13 SERVER systemd[1]: Job cron.service/start finished,<br>
>> > result=done<br>
>> > 2029:Feb 23 06:52:13 SERVER systemd[786]: Executing: /usr/sbin/cron -f<br>
>> > 2038:Feb 23 06:52:13 SERVER cron[786]: (CRON) INFO (pidfile fd = 3)<br>
>> > 2128:Feb 23 06:52:13 SERVER cron[786]: (CRON) INFO (Running @reboot<br>
>> > jobs)<br>
>> > 2300:Feb 23 06:52:13 SERVER systemd[1]: mnt-NFSSERVER_VOL.mount changed<br>
>> > mounted -> failed<br>
>> > 2301:Feb 23 06:52:13 SERVER systemd[1]: Failed to destroy cgroup<br>
>> > /system.slice/mnt-NFSSERVER_VOL.mount: Device or resource busy<br>
>> > 2302:Feb 23 06:52:13 SERVER systemd[1]: Unit mnt-NFSSERVER_VOL.mount<br>
>> > entered<br>
>> > failed state.<br>
>> > 2303:Feb 23 06:52:13 SERVER systemd[1]: Sent message type=signal<br>
>> > sender=n/a<br>
>> > destination=n/a<br>
>> > object=/org/freedesktop/systemd1/unit/mnt_2dNFSSERVER_5fVOL_2emount<br>
>> > interface=org.freedesktop.DBus.Properties member=PropertiesChanged<br>
>> > cookie=30<br>
>> > reply_cookie=0 error=n/a<br>
>> > 2304:Feb 23 06:52:13 SERVER systemd[1]: Sent message type=signal<br>
>> > sender=n/a<br>
>> > destination=n/a<br>
>> > object=/org/freedesktop/systemd1/unit/mnt_2dNFSSERVER_5fVOL_2emount<br>
>> > interface=org.freedesktop.DBus.Properties member=PropertiesChanged<br>
>> > cookie=31<br>
>> > reply_cookie=0 error=n/a<br>
>> ><br>
>> > so 1m30s passed and the mount didnt come up, which is (one of) the<br>
>> > original<br>
>> > issue (usually, running mount -t nfs -a will bring it up, even just<br>
>> > right<br>
>> > after the failure at boot, so it seems like it's not retried?). i check<br>
>> > in<br>
>> > the journalctl output around those lines, there was additional msg<br>
>> > relevant<br>
>> > to this.<br>
>><br>
>> Is the network up at this point?<br>
><br>
> i think so (and the other 11 NFS mounts were correctly mounted at this point<br>
> anyway): here's some logs of the network and the failing mount:<br>
><br>
> # journalctl -alb | grep -inE "network|NFSSERVER"<br>
> 653:Feb 23 06:50:42 SERVER kernel: igb: Intel(R) Gigabit Ethernet Network<br>
> Driver - version 5.2.15-k<br>
> 656:Feb 23 06:50:42 SERVER kernel: igb 0000:01:00.0: Intel(R) Gigabit<br>
> Ethernet Network Connection<br>
> 661:Feb 23 06:50:42 SERVER kernel: igb 0000:01:00.1: Intel(R) Gigabit<br>
> Ethernet Network Connection<br>
> 678:Feb 23 06:50:42 SERVER kernel: drop_monitor: Initializing network drop<br>
> monitor service<br>
> 962:Feb 23 06:50:42 SERVER systemd[1]: Installed new job<br>
> networking.service/start as 46<br>
> 963:Feb 23 06:50:42 SERVER systemd[1]: Installed new job<br>
> network.target/start as 47<br>
> 969:Feb 23 06:50:42 SERVER systemd[1]: Installed new job<br>
> network-online.target/start as 53<br>
> 1012:Feb 23 06:50:42 SERVER systemd[1]: Installed new job<br>
> mnt-NFSSERVER_VOL.mount/start as 99<br>
> 1548:Feb 23 06:50:42 SERVER systemd[1]: Starting LSB: Raise network<br>
> interfaces....<br>
> 1550:Feb 23 06:50:42 SERVER systemd[1]: About to execute:<br>
> /etc/init.d/networking start<br>
> 1551:Feb 23 06:50:42 SERVER systemd[1]: Forked /etc/init.d/networking as 407<br>
> 1552:Feb 23 06:50:42 SERVER systemd[1]: networking.service changed dead -><br>
> start<br>
> 1553:Feb 23 06:50:42 SERVER systemd[407]: Executing: /etc/init.d/networking<br>
> start<br>
> 1591:Feb 23 06:50:43 SERVER networking[407]: Configuring network<br>
> interfaces...Cannot get EEE settings: Operation not supported<br>
> 1648:Feb 23 06:50:43 SERVER networking[407]: done.<br>
> 1649:Feb 23 06:50:43 SERVER systemd[1]: Received SIGCHLD from PID 407<br>
> (networking).<br>
> 1650:Feb 23 06:50:43 SERVER systemd[1]: Child 407 (networking) died<br>
> (code=exited, status=0/SUCCESS)<br>
> 1651:Feb 23 06:50:43 SERVER systemd[1]: Child 407 belongs to<br>
> networking.service<br>
> 1652:Feb 23 06:50:43 SERVER systemd[1]: networking.service: control process<br>
> exited, code=exited status=0<br>
> 1653:Feb 23 06:50:43 SERVER systemd[1]: networking.service got final SIGCHLD<br>
> for state start<br>
> 1654:Feb 23 06:50:43 SERVER systemd[1]: networking.service changed start -><br>
> running<br>
> 1655:Feb 23 06:50:43 SERVER systemd[1]: Job networking.service/start<br>
> finished, result=done<br>
> 1656:Feb 23 06:50:43 SERVER systemd[1]: Started LSB: Raise network<br>
> interfaces..<br>
> 1657:Feb 23 06:50:43 SERVER systemd[1]: Starting Network.<br>
> 1658:Feb 23 06:50:43 SERVER systemd[1]: network.target changed dead -><br>
> active<br>
> 1659:Feb 23 06:50:43 SERVER systemd[1]: Job network.target/start finished,<br>
> result=done<br>
> 1660:Feb 23 06:50:43 SERVER systemd[1]: Reached target Network.<br>
> 1661:Feb 23 06:50:43 SERVER systemd[1]: Starting Network is Online.<br>
> 1662:Feb 23 06:50:43 SERVER systemd[1]: network-online.target changed dead<br>
> -> active<br>
> 1663:Feb 23 06:50:43 SERVER systemd[1]: Job network-online.target/start<br>
> finished, result=done<br>
> 1664:Feb 23 06:50:43 SERVER systemd[1]: Reached target Network is Online.<br>
> 1714:Feb 23 06:50:43 SERVER systemd[1]: Mounting /mnt/NFSSERVER_VOL...<br>
> 1716:Feb 23 06:50:43 SERVER systemd[1]: About to execute: /bin/mount -n<br>
> XXX.YYY.32.75:/vol/VOL /mnt/NFSSERVER_VOL -t nfs -o<br>
> ro,intr,nolock,tcp,rdirplus,noatime,_netdev<br>
> 1718:Feb 23 06:50:43 SERVER systemd[1]: mnt-NFSSERVER_VOL.mount changed dead<br>
> -> mounting<br>
> 1720:Feb 23 06:50:43 SERVER systemd[574]: Executing: /bin/mount -n<br>
> XXX.YYY.32.75:/vol/VOL /mnt/NFSSERVER_VOL -t nfs -o<br>
> ro,intr,nolock,tcp,rdirplus,noatime,_netdev<br>
> 1877:Feb 23 06:50:58 SERVER systemd[1]: Child 489 belongs to<br>
> networking.service<br>
> 1879:Feb 23 06:50:58 SERVER systemd[1]: Child 501 belongs to<br>
> networking.service<br>
> 1891:Feb 23 06:51:19 SERVER systemd[1]: Child 539 belongs to<br>
> networking.service<br>
<br>
</div></div>This is weird. Why would there be lingering processes of<br>
networking.service? Note that these processes exit after the nfs<br>
mounts are started.<br>
<span class=""><br>
> 1892:Feb 23 06:51:19 SERVER systemd[1]: networking.service: cgroup is empty<br>
> 1893:Feb 23 06:51:19 SERVER systemd[1]: networking.service changed running<br>
> -> exited<br>
> 1905:Feb 23 06:52:13 SERVER systemd[1]: mnt-NFSSERVER_VOL.mount mounting<br>
> timed out. Stopping.<br>
> 1906:Feb 23 06:52:13 SERVER systemd[1]: mnt-NFSSERVER_VOL.mount changed<br>
> mounting -> mounting-sigterm<br>
> 1915:Feb 23 06:52:13 SERVER systemd[1]: Child 574 belongs to<br>
> mnt-NFSSERVER_VOL.mount<br>
> 1916:Feb 23 06:52:13 SERVER systemd[1]: mnt-NFSSERVER_VOL.mount mount<br>
> process exited, code=killed status=15<br>
> 1917:Feb 23 06:52:13 SERVER systemd[1]: mnt-NFSSERVER_VOL.mount changed<br>
> mounting-sigterm -> mounted<br>
<br>
</span>This is definitely weird.<br>
<div><div class="h5"><br>
> 1918:Feb 23 06:52:13 SERVER systemd[1]: Job mnt-NFSSERVER_VOL.mount/start<br>
> finished, result=done<br>
> 1919:Feb 23 06:52:13 SERVER systemd[1]: Mounted /mnt/NFSSERVER_VOL.<br>
> 2300:Feb 23 06:52:13 SERVER systemd[1]: mnt-NFSSERVER_VOL.mount changed<br>
> mounted -> failed<br>
> 2301:Feb 23 06:52:13 SERVER systemd[1]: Failed to destroy cgroup<br>
> /system.slice/mnt-NFSSERVER_VOL.mount: Device or resource busy<br>
> 2302:Feb 23 06:52:13 SERVER systemd[1]: Unit mnt-NFSSERVER_VOL.mount entered<br>
> failed state.<br>
> 2303:Feb 23 06:52:13 SERVER systemd[1]: Sent message type=signal sender=n/a<br>
> destination=n/a<br>
> object=/org/freedesktop/systemd1/unit/mnt_2dNFSSERVER_5fVOL_2emount<br>
> interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=30<br>
> reply_cookie=0 error=n/a<br>
> 2304:Feb 23 06:52:13 SERVER systemd[1]: Sent message type=signal sender=n/a<br>
> destination=n/a<br>
> object=/org/freedesktop/systemd1/unit/mnt_2dNFSSERVER_5fVOL_2emount<br>
> interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=31<br>
> reply_cookie=0 error=n/a<br>
> 2449:Feb 23 06:52:13 SERVER systemd[1]: Starting Host and Network Name<br>
> Lookups.<br>
> 2452:Feb 23 06:52:13 SERVER systemd[1]: Reached target Host and Network Name<br>
> Lookups.<br>
><br>
> in particular<br>
><br>
> 1664:Feb 23 06:50:43 SERVER systemd[1]: Reached target Network is Online.<br>
> 1714:Feb 23 06:50:43 SERVER systemd[1]: Mounting /mnt/NFSSERVER_VOL...<br>
><br>
> so the net online target is reached (if we believe systemd :) from man<br>
> systemd.special for network-online.target, "What precisely this requires is<br>
> left to the implementation of the network managing service.", how can we<br>
> know how this is implemented, and so what is meant here as 'online'?) before<br>
> attempting the mount.<br>
><br>
> I checked at what point the /mnt/NFSSERVER_VOL is executed, and it was the<br>
> very last one NFS mount attempted (dunno if it's useful, i was expecting to<br>
> be the first, so with a possibly network still unstable), here below what I<br>
> called before /mnt/NFSSERVER_VOL is /mnt/NFSSERVER1_VOL (as i included also<br>
> the other NFS mounts):<br>
><br>
> 1665:Feb 23 06:50:43 SERVER systemd[1]: Mounting /mnt/NFSSERVER12_VOL...<br>
> 1669:Feb 23 06:50:43 SERVER systemd[1]: Mounting /mnt/NFSSERVER7_VOL...<br>
> 1674:Feb 23 06:50:43 SERVER systemd[1]: Mounting /mnt/NFSSERVER10...<br>
> 1679:Feb 23 06:50:43 SERVER systemd[1]: Mounting /mnt/NFSSERVER7_VOL...<br>
> 1684:Feb 23 06:50:43 SERVER systemd[1]: Mounting /mnt/NFSSERVER8...<br>
> 1689:Feb 23 06:50:43 SERVER systemd[1]: Mounting /mnt/NFSSERVER7_VOL...<br>
> 1694:Feb 23 06:50:43 SERVER systemd[1]: Mounting /mnt/NFSSERVER5...<br>
> 1699:Feb 23 06:50:43 SERVER systemd[1]: Mounting /mnt/NFSSERVER4...<br>
> 1704:Feb 23 06:50:43 SERVER systemd[1]: Mounting /mnt/NFSSERVER3...<br>
> 1709:Feb 23 06:50:43 SERVER systemd[1]: Mounting /mnt/NFSSERVER2...<br>
> 1714:Feb 23 06:50:43 SERVER systemd[1]: Mounting /mnt/NFSSERVER1_VOL...<br>
> 1757:Feb 23 06:50:46 SERVER systemd[1]: mnt-NFSSERVER12_VOL.mount changed<br>
> mounting -> mounting-done<br>
> 1759:Feb 23 06:50:46 SERVER systemd[1]: Mounted /mnt/NFSSERVER12_VOL.<br>
> 1777:Feb 23 06:50:47 SERVER systemd[1]: mnt-NFSSERVER8.mount changed<br>
> mounting -> mounting-done<br>
> 1779:Feb 23 06:50:47 SERVER systemd[1]: Mounted /mnt/NFSSERVER8.<br>
> 1780:Feb 23 06:50:47 SERVER systemd[1]: mnt-NFSSERVER7_VOL.mount changed<br>
> mounting -> mounting-done<br>
> 1782:Feb 23 06:50:47 SERVER systemd[1]: Mounted /mnt/NFSSERVER7_VOL.<br>
> 1783:Feb 23 06:50:47 SERVER systemd[1]: mnt-NFSSERVER3.mount changed<br>
> mounting -> mounting-done<br>
> 1785:Feb 23 06:50:47 SERVER systemd[1]: Mounted /mnt/NFSSERVER3.<br>
> 1786:Feb 23 06:50:47 SERVER systemd[1]: mnt-NFSSERVER5.mount changed<br>
> mounting -> mounting-done<br>
> 1788:Feb 23 06:50:47 SERVER systemd[1]: Mounted /mnt/NFSSERVER5.<br>
> 1789:Feb 23 06:50:47 SERVER systemd[1]: mnt-NFSSERVER7_VOL.mount changed<br>
> mounting -> mounting-done<br>
> 1791:Feb 23 06:50:47 SERVER systemd[1]: Mounted /mnt/NFSSERVER7_VOL.<br>
> 1792:Feb 23 06:50:47 SERVER systemd[1]: mnt-NFSSERVER7_VOL.mount changed<br>
> mounting -> mounting-done<br>
> 1794:Feb 23 06:50:47 SERVER systemd[1]: Mounted /mnt/NFSSERVER7_VOL.<br>
> 1795:Feb 23 06:50:47 SERVER systemd[1]: mnt-NFSSERVER10.mount changed<br>
> mounting -> mounting-done<br>
> 1797:Feb 23 06:50:47 SERVER systemd[1]: Mounted /mnt/NFSSERVER10.<br>
> 1830:Feb 23 06:50:47 SERVER systemd[1]: mnt-NFSSERVER4.mount changed<br>
> mounting -> mounted<br>
> 1832:Feb 23 06:50:47 SERVER systemd[1]: Mounted /mnt/NFSSERVER4.<br>
> 1836:Feb 23 06:50:47 SERVER systemd[1]: mnt-NFSSERVER2.mount changed<br>
> mounting -> mounted<br>
> 1838:Feb 23 06:50:47 SERVER systemd[1]: Mounted /mnt/NFSSERVER2.<br>
> 1906:Feb 23 06:52:13 SERVER systemd[1]: mnt-NFSSERVER1_VOL.mount changed<br>
> mounting -> mounting-sigterm<br>
> 1919:Feb 23 06:52:13 SERVER systemd[1]: Mounted /mnt/NFSSERVER1_VOL.<br>
><br>
> but it is the first one defined in /etc/fstab:<br>
><br>
> XXX.YYY.32.75:/vol/vol3 /mnt/NFSSERVER1_VOL nfs<br>
> ro,intr,nolock,tcp,rdirplus,noatime,_netdev<br>
> XXX.YYY.26.132:/ifs /mnt/NFSSERVER2 nfs<br>
> rw,intr,tcp,rdirplus,noatime,_netdev<br>
> XXX.YYY.20.176:/ifs /mnt/NFSSERVER3 nfs<br>
> ro,tcp,rdirplus,noatime,_netdev<br>
> XXX.YYY.16.226:/ifs /mnt/NFSSERVER4 nfs<br>
> rw,intr,tcp,rdirplus,noatime,_netdev<br>
> XXX.YYY.21.22:/ifs/scratcho /mnt/NFSSERVER5 nfs<br>
> rw,intr,tcp,rdirplus,noatime,_netdev<br>
> XXX.YYY.27.74:/vol/vol5 /mnt/NFSSERVER7_VOL nfs<br>
> rw,intr,tcp,rdirplus,noatime,_netdev<br>
> XXX.YYY.32.111:/buildcache /mnt/NFSSERVER8 nfs<br>
> ro,soft,intr,tcp,rdirplus,noatime,_netdev<br>
> XXX.YYY.27.74:/vol/vol1 /mnt/NFSSERVER7_VOL nfs<br>
> ro,soft,intr,tcp,rdirplus,noatime,_netdev<br>
> XXX.YYY.20.176:/ifs /mnt/NFSSERVER10 nfs<br>
> ro,nocto,actimeo=600,tcp,rdirplus,noatime,_netdev<br>
> XXX.YYY.27.74:/vol/vol6 /mnt/NFSSERVER7_VOL nfs<br>
> ro,soft,intr,tcp,rdirplus,noatime,_netdev<br>
> XXX.YYY.20.14:/vol/vol3 /mnt/NFSSERVER12_VOL nfs<br>
> ro,intr,nolock,tcp,rdirplus,noatime,_netdev<br>
><br>
> something else that sounds fishy is:<br>
><br>
> Feb 23 06:50:43 SERVER systemd[1]: Mounting /mnt/NFSSERVER1_VOL...<br>
> Feb 23 06:50:43 SERVER systemd[1]: About to execute: /bin/mount -n<br>
> XXX.YYY.32.75:/vol/vol3 /mnt/NFSSERVER1_VOL -t nfs -o<br>
> ro,intr,nolock,tcp,rdirplus,noatime,_netdev<br>
> Feb 23 06:50:43 SERVER systemd[1]: mnt-NFSSERVER1_VOL.mount changed dead -><br>
> mounting<br>
> Feb 23 06:50:43 SERVER systemd[574]: Executing: /bin/mount -n<br>
> XXX.YYY.32.75:/vol/vol3 /mnt/NFSSERVER1_VOL -t nfs -o<br>
> ro,intr,nolock,tcp,rdirplus,noatime,_netdev<br>
> Feb 23 06:52:13 SERVER systemd[1]: mnt-NFSSERVER1_VOL.mount mounting timed<br>
> out. Stopping.<br>
> Feb 23 06:52:13 SERVER systemd[1]: mnt-NFSSERVER1_VOL.mount changed mounting<br>
> -> mounting-sigterm<br>
> Feb 23 06:52:13 SERVER systemd[1]: Child 574 belongs to<br>
> mnt-NFSSERVER1_VOL.mount<br>
> Feb 23 06:52:13 SERVER systemd[1]: mnt-NFSSERVER1_VOL.mount mount process<br>
> exited, code=killed status=15<br>
> Feb 23 06:52:13 SERVER systemd[1]: mnt-NFSSERVER1_VOL.mount changed<br>
> mounting-sigterm -> mounted<br>
> Feb 23 06:52:13 SERVER systemd[1]: Job mnt-NFSSERVER1_VOL.mount/start<br>
> finished, result=done<br>
> Feb 23 06:52:13 SERVER systemd[1]: Mounted /mnt/NFSSERVER1_VOL.<br>
> Feb 23 06:52:13 SERVER systemd[1]: Starting Remote File Systems.<br>
> Feb 23 06:52:13 SERVER systemd[1]: remote-fs.target changed dead -> active<br>
> Feb 23 06:52:13 SERVER systemd[1]: Job remote-fs.target/start finished,<br>
> result=done<br>
> Feb 23 06:52:13 SERVER systemd[1]: Reached target Remote File Systems.<br>
> Feb 23 06:52:13 SERVER systemd[1]: mnt-NFSSERVER1_VOL.mount changed mounted<br>
> -> failed<br>
><br>
> so it is actually marked as done/mounted (?!?): "mnt-NFSSERVER1_VOL.mount<br>
> changed mounting-sigterm -> mounted", which triggers "Job<br>
> remote-fs.target/start finished, result=done" - but that seems wrong, it was<br>
> sigterm'ed, why systemd thinks this is actually completed correctly? at the<br>
> end it doesnt, as it's marked as failed, but that "mounting-sigterm -><br>
> mounted" transition appears to be a mistake<br>
<br>
</div></div>Yes, that is definitely weird.<br>
<div><div class="h5"><br>
><br>
><br>
>><br>
>> ><br>
>> > also note like cron.service is started, even if we configured:<br>
>> ><br>
>> > # grep remote-fs /etc/systemd/system/cron.service<br>
>> > Requires=remote-fs.target<br>
>> > After=remote-fs.target<br>
>><br>
>> What does `systemctl show remote-fs.target` say?<br>
><br>
> Id=remote-fs.target<br>
> Names=remote-fs.target<br>
> Requires=mnt-NFSSERVER12_VOL.mount mnt-NFSSERVER7_vol6.mount<br>
> mnt-NFSSERVER32.mount mnt-NFSSERVER9_vol1.mount mnt-NFSSERVER8.mount<br>
> mnt-NFSSERVER11_vol5.mount mnt-NFSSERVER5.mount mnt-NFSSERVER4.mount<br>
> mnt-gonzo.mount mnt-NFSSERVER2.mount mnt-NFSSERVER1_vol3.mount<br>
> Wants=remote-fs-pre.target<br>
> RequiredBy=cron.service<br>
> WantedBy=multi-user.target<br>
> Conflicts=shutdown.target<br>
> Before=console-setup.service kbd.service systemd-journal-flush.service<br>
> systemd-user-sessions.service mcelog.service ntp.service ipmidetectd.service<br>
> kexec-load.service nagios-nrpe-server.service nutcracker.service<br>
> lsyncd.service irqbalance.service ipwatchd.service ganglia-monitor.service<br>
> unbound.service bmc-watchdog.service setup_hugetlbfs.service sysstat.service<br>
> postfix.service cron.service<br>
> After=remote-fs-pre.target local-fs.target mnt-NFSSERVER1_VOL.mount<br>
> mnt-NFSSERVER2.mount mnt-NFSSERVER3.mount mnt-NFSSERVER4.mount<br>
> mnt-NFSSERVER5.mount mnt-NFSSERVER7_vol5.mount mnt-NFSSERVER8.mount<br>
> mnt-NFSSERVER9_vol1.mount mnt-NFSSERVER10.mount mnt-NFSSERVER11_vol6.mount<br>
> mnt-NFSSERVER12_vol3.mount<br>
> Documentation=man:systemd.special(7)<br>
> Description=Remote File Systems<br>
> LoadState=loaded<br>
> ActiveState=active<br>
> SubState=active<br>
> FragmentPath=/lib/systemd/system/remote-fs.target<br>
> DropInPaths=/run/systemd/generator/remote-fs.target.d/50-insserv.conf.conf<br>
> UnitFileState=enabled<br>
> InactiveExitTimestamp=Tue 2016-02-23 06:52:13 EST<br>
> InactiveExitTimestampMonotonic=104052746<br>
> ActiveEnterTimestamp=Tue 2016-02-23 06:52:13 EST<br>
> ActiveEnterTimestampMonotonic=104052746<br>
> ActiveExitTimestampMonotonic=0<br>
> InactiveEnterTimestampMonotonic=0<br>
> CanStart=yes<br>
> CanStop=yes<br>
> CanReload=no<br>
> CanIsolate=no<br>
> StopWhenUnneeded=no<br>
> RefuseManualStart=no<br>
> RefuseManualStop=no<br>
> AllowIsolate=no<br>
> DefaultDependencies=no<br>
> OnFailureJobMode=replace<br>
> IgnoreOnIsolate=no<br>
> IgnoreOnSnapshot=no<br>
> NeedDaemonReload=no<br>
> JobTimeoutUSec=0<br>
> ConditionResult=yes<br>
> ConditionTimestamp=Tue 2016-02-23 06:52:13 EST<br>
> ConditionTimestampMonotonic=104052734<br>
> Transient=no<br>
><br>
>><br>
>> ><br>
>> > checking the status of that target:<br>
>> ><br>
>> > # systemctl status remote-fs.target<br>
>> > ● remote-fs.target - Remote File Systems<br>
>> > Loaded: loaded (/lib/systemd/system/remote-fs.target; enabled)<br>
>> > Drop-In: /run/systemd/generator/remote-fs.target.d<br>
>> > └─50-insserv.conf.conf<br>
>> > Active: active since Tue 2016-02-23 06:52:13 EST; 3h 15min ago<br>
>> > Docs: man:systemd.special(7)<br>
>> ><br>
>> > Feb 23 06:52:13 SERVER systemd[1]: Starting Remote File Systems.<br>
>> > Feb 23 06:52:13 SERVER systemd[1]: Job remote-fs.target/start finished,<br>
>> > result=done<br>
>> > Feb 23 06:52:13 SERVER systemd[1]: Reached target Remote File Systems.<br>
>> ><br>
>> > so at the same time when mnt-NFSSERVER_VOL.mount is marked as failed,<br>
>> > the<br>
>> > remote-fs.target is marked as loaded successfully (which seems the wrong<br>
>> > status to me), and in fact the only failed unit is:<br>
>> ><br>
>> > # systemctl --failed<br>
>> > UNIT LOAD ACTIVE SUB DESCRIPTION<br>
>> > ● mnt-NFSSERVER_VOL.mount loaded failed failed /mnt/NFSSERVER_VOL<br>
>> ><br>
>> > 1 loaded units listed. Pass --all to see loaded but inactive units, too.<br>
>><br>
>> Looks like remote-fs.target does not Require its mounts, only Wants.<br>
><br>
> from the 'show' command above it seems it actually Requires the mount, where<br>
> did you find the info about only 'Want'ing the mounts?<br>
<br>
</div></div>I was guessing, but your output suggests the relation is correct. I am<br>
very confused...<br>
<span class=""><br>
><br>
>><br>
>> ><br>
>> ><br>
>> > can I provide more logs/info? do you see anything wrong on this<br>
>> > configuration that we might want to change?<br>
>><br>
>> It seems strange that the mount fails.<br>
><br>
> yeah I agree it's strange, but there might be situations when the particular<br>
> nfs server is overloaded, and/or the network path is a bit congested, and<br>
> the mount might take a while to come up; we consider a slow mount acceptable<br>
> (we dont reboot machines that often, and servers are already slow beasts to<br>
> start, a few secs more is not an issue), we just feel like if something goes<br>
> a bit out of the usual, the mount is never retried and it's just left it<br>
> there, dying<br>
<br>
</span>Maybe the timeout is just too short. Maybe adding<br>
x-systemd.device-timeout=90s helps?<br></blockquote><div><br></div><div>i think that's already 90s by default? at least we see the mount fail after 90s, so maybe we should set to a lower or higher value? I'm unsure if that's what could trigger a "retry" of the mount, because as soon as I see the machine online, i can login and issue a mount -t nfs -a and all the missing mountpoints (still pending for systemd) are promptly mounted, so it's like if they are "frozen" and a retry would just make them successful.</div><div> </div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
<br>
A completely different alternative is to setup the nfs mounts as<br>
automounts instead of real mounts (ie, set x-systemd.automount<br>
option). This would have the aditional benefit of removing the need to<br>
specify dependency against remote-fs.target.<br></blockquote><div><br></div><div>i dont think we want that: we prefer (for various reason) to have all the mountpoint, services and processes running at the machine boot, and be already there when we want to use them</div><div> </div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
<br>
This option will cause systemd to attempt to mount whenever a subpath<br>
is accessed and the mount is not yet active.<br>
<div><div class="h5"><br>
><br>
>> Any logs which might shed some<br>
>> light on why the mount command fails (especially network status)?<br>
><br>
> sadly i cant find anything relevant: dmesg has nothing, journalctl contains<br>
> nothing helpful/related, ad so do syslog or messages - any other place you<br>
> want me to look?<br>
><br>
>> Does<br>
>> the mount complete successfully if started via systemd post-boot ?<br>
>> that is, `systemctl start mnt-NFSSERVER_VOL.mount`.<br>
><br>
> it usually does, up to the point that we setup a "mount -t nfs -a" as an<br>
> @reboot cronjob just to get the mounts up<br>
><br>
> on this specific machine. I'm running that command now, so 24hrs after when<br>
> that happened, and it completes just fine (but i have no doubts it would<br>
> have succeeded even just after the boot failure):<br>
><br>
> # systemctl --failed --no-legend<br>
> mnt-NFSSERVER_VOL.mount loaded failed failed /mnt/NFSSERVER_VOL<br>
> # systemctl start mnt-NFSSERVER_VOL.mount<br>
><br>
> Feb 24 07:24:21 SERVER systemd[1]: Trying to enqueue job<br>
> mnt-NFSSERVER1_VOL.mount/start/replace<br>
> Feb 24 07:24:21 SERVER systemd[1]: Installed new job<br>
> mnt-NFSSERVER1_VOL.mount/start as 565<br>
> Feb 24 07:24:21 SERVER systemd[1]: Enqueued job<br>
> mnt-NFSSERVER1_VOL.mount/start as 565<br>
> Feb 24 07:24:21 SERVER systemd[1]: Mounting /mnt/NFSSERVER1_VOL...<br>
> Feb 24 07:24:21 SERVER systemd[1]: mnt-NFSSERVER1_VOL.mount: Directory<br>
> /mnt/majestix_vol3 to mount over is not empty, mounting anyway.<br>
> Feb 24 07:24:21 SERVER systemd[1]: About to execute: /bin/mount -n<br>
> XXX.YYY.32.75:/vol/vol3 /mnt/NFSSERVER1_VOL -t nfs -o<br>
> ro,intr,nolock,tcp,rdirplus,noatime,_netdev<br>
> Feb 24 07:24:21 SERVER systemd[1]: mnt-NFSSERVER1_VOL.mount changed failed<br>
> -> mounting<br>
> Feb 24 07:24:21 SERVER systemd[1]: Sent message type=signal sender=n/a<br>
> destination=n/a<br>
> object=/org/freedesktop/systemd1/unit/mnt_2dNFSSERVER1_5fvol3_2emount<br>
> interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=3<br>
> reply_cookie=0 error=n/a<br>
> Feb 24 07:24:21 SERVER systemd[1]: Sent message type=signal sender=n/a<br>
> destination=n/a<br>
> object=/org/freedesktop/systemd1/unit/mnt_2dNFSSERVER1_5fvol3_2emount<br>
> interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=4<br>
> reply_cookie=0 error=n/a<br>
> Feb 24 07:24:21 SERVER systemd[1]: Got message type=method_call sender=n/a<br>
> destination=org.freedesktop.systemd1<br>
> object=/org/freedesktop/systemd1/unit/mnt_2dNFSSERVER1_5fvol3_2emount<br>
> interface=org.freedesktop.DBus.Properties member=Get cookie=3 reply_cookie=0<br>
> error=n/a<br>
> Feb 24 07:24:21 SERVER systemd[27575]: Executing: /bin/mount -n<br>
> XXX.YYY.32.75:/vol/vol3 /mnt/NFSSERVER1_VOL -t nfs -o<br>
> ro,intr,nolock,tcp,rdirplus,noatime,_netdev<br>
> Feb 24 07:24:21 SERVER systemd[1]: Child 27575 belongs to<br>
> mnt-NFSSERVER1_VOL.mount<br>
> Feb 24 07:24:21 SERVER systemd[1]: mnt-NFSSERVER1_VOL.mount mount process<br>
> exited, code=exited status=0<br>
> Feb 24 07:24:21 SERVER systemd[1]: mnt-NFSSERVER1_VOL.mount changed mounting<br>
> -> mounted<br>
> Feb 24 07:24:21 SERVER systemd[1]: Job mnt-NFSSERVER1_VOL.mount/start<br>
> finished, result=done<br>
> Feb 24 07:24:21 SERVER systemd[1]: Mounted /mnt/NFSSERVER1_VOL.<br>
><br>
> # systemctl status | head<br>
> ● SERVER<br>
> State: running<br>
> Jobs: 0 queued<br>
> Failed: 0 units<br>
><br>
<br>
</div></div>OK, so no systemd-specific environment snafu, and more likely just a<br>
timing issue.<br>
<br>
I have to confess I don't have much more ideas on where to look...<span class="HOEnZb"><font color="#888888"><br>
</font></span></blockquote></div><div class="gmail_extra"><br></div>ok, at least we are not alone in not understanding what's going on :)</div><div class="gmail_extra"><br></div><div class="gmail_extra">but as you can imagine, this is a rather nasty issue and -while we are moving forward with the adoption of jessie- is making a lot of people uncomfortable and skeptical (i just want to express the feelings we have not any complains on the quality of systemd or debian :) )</div><div class="gmail_extra"><br></div><div class="gmail_extra">would you think it might be viable to contact systemd upstream about this? Jessie runs 215 while upstream released 229 so the risk of a "get the latest version and report back" is high, and it's not something easily doable i guess (?). would you prefer to start this discussion yourself, as you might have a well established relationship with systemd upstream? i can trigger the discussion myself as well, and copying the systemd debiam maint ml, as you prefer</div><div class="gmail_extra"><br></div><div class="gmail_extra">do we have any other option to explore here? the first thing that comes to mind is to go back to sysv but i really really dont want to do it (it's looking at the past not towards the future), is there something else?</div><div class="gmail_extra"><br></div><div class="gmail_extra">thanks for your continuous support!<br><br clear="all"><div><br></div>-- <br><div class="gmail_signature">Sandro "morph" Tosi<br>My website: <a href="http://sandrotosi.me/" target="_blank">http://sandrotosi.me/</a><br>Me at Debian: <a href="http://wiki.debian.org/SandroTosi" target="_blank">http://wiki.debian.org/SandroTosi</a><br>G+: <a href="https://plus.google.com/u/0/+SandroTosi" target="_blank">https://plus.google.com/u/0/+SandroTosi</a></div>
</div></div>