Description: The stopping services log message is before VMs and Dockers are stopped.  It should be before the services are stopped.  This gives the wrong impression about when services are actually stopped.

 

How to reproduce: Shut down system and review log.

 

Expected results: Log message would be in the correct place.

 

Actual results: Log message is too early.

 

Other information: Snippet of log:

 

Oct 23 07:12:25 MediaServer emhttp: Stopping services...    <---- log message is here

Oct 23 07:12:25 MediaServer emhttp: shcmd (34187): /etc/rc.d/rc.libvirt stop |& logger

Oct 23 07:12:32 MediaServer root: Domain 81eda47a-12b8-2c11-e50f-7d36b9eba3a5 is being shutdown

Oct 23 07:12:32 MediaServer root:

Oct 23 07:12:38 MediaServer kernel: br0: port 2(vnet0) entered disabled state

Oct 23 07:12:38 MediaServer kernel: device vnet0 left promiscuous mode

Oct 23 07:12:38 MediaServer kernel: br0: port 2(vnet0) entered disabled state

Oct 23 07:12:38 MediaServer kernel: input: USB Optical Wheel Mouse as /devices/pci0000:00/0000:00:14.0/usb3/3-13/3-13:1.0/0003:1BCF:0002.000B/input/input15

Oct 23 07:12:38 MediaServer kernel: input: failed to attach handler evdev to device input15, error: -4

Oct 23 07:12:38 MediaServer kernel: hid-generic 0003:1BCF:0002.000B: input,hidraw1: USB HID v1.11 Mouse [uSB Optical Wheel Mouse] on usb-0000:00:14.0-13/input0

Oct 23 07:12:38 MediaServer kernel: usb-storage 3-3.4:1.0: USB Mass Storage device detected

Oct 23 07:12:38 MediaServer kernel: scsi host1: usb-storage 3-3.4:1.0

Oct 23 07:12:38 MediaServer kernel: input: KB Multimedia keyboard  as /devices/pci0000:00/0000:00:14.0/usb3/3-14/3-14:1.0/0003:05D5:0624.000C/input/input16

Oct 23 07:12:38 MediaServer kernel: hid-generic 0003:05D5:0624.000C: input,hidraw2: USB HID v1.10 Keyboard [KB Multimedia keyboard ] on usb-0000:00:14.0-14/input0

Oct 23 07:12:38 MediaServer kernel: input: KB Multimedia keyboard  as /devices/pci0000:00/0000:00:14.0/usb3/3-14/3-14:1.1/0003:05D5:0624.000D/input/input17

Oct 23 07:12:38 MediaServer kernel: hid-generic 0003:05D5:0624.000D: input,hidraw3: USB HID v1.10 Device [KB Multimedia keyboard ] on usb-0000:00:14.0-14/input1

Oct 23 07:12:38 MediaServer kernel: usblp 3-3.2:1.0: usblp0: USB Bidirectional printer dev 6 if 0 alt 0 proto 2 vid 0x04E8 pid 0x328F

Oct 23 07:12:39 MediaServer kernel: scsi 1:0:0:0: CD-ROM            HL-DT-ST DVDRAM GP50NB40  1.00 PQ: 0 ANSI: 0

Oct 23 07:12:39 MediaServer kernel: sr 1:0:0:0: [sr0] scsi3-mmc drive: 24x/24x writer dvd-ram cd/rw xa/form2 cdda tray

Oct 23 07:12:39 MediaServer kernel: sr 1:0:0:0: Attached scsi CD-ROM sr0

Oct 23 07:12:39 MediaServer kernel: sr 1:0:0:0: Attached scsi generic sg1 type 5

Oct 23 07:12:39 MediaServer kernel: vgaarb: device changed decodes: PCI:0000:01:00.0,olddecodes=io+mem,decodes=io+mem:owns=none

Oct 23 07:12:39 MediaServer root: Waiting on VMs to shutdown......

Oct 23 07:12:39 MediaServer root: Stopping libvirtd...

Oct 23 07:12:39 MediaServer dnsmasq[9446]: exiting on receipt of SIGTERM

Oct 23 07:12:39 MediaServer kernel: device virbr0-nic left promiscuous mode

Oct 23 07:12:39 MediaServer kernel: virbr0: port 1(virbr0-nic) entered disabled state

Oct 23 07:12:39 MediaServer avahi-daemon[4616]: Interface virbr0.IPv4 no longer relevant for mDNS.

Oct 23 07:12:39 MediaServer avahi-daemon[4616]: Leaving mDNS multicast group on interface virbr0.IPv4 with address 192.168.122.1.

Oct 23 07:12:39 MediaServer avahi-daemon[4616]: Withdrawing address record for 192.168.122.1 on virbr0.

Oct 23 07:12:39 MediaServer root: Network a4007147-6d28-4b27-8a73-0b1a1672c02b destroyed

Oct 23 07:12:39 MediaServer root:

Oct 23 07:12:42 MediaServer emhttp: shcmd (34188): umount /etc/libvirt

Oct 23 07:12:42 MediaServer emhttp: shcmd (34190): /etc/rc.d/rc.docker stop |& logger

Oct 23 07:12:42 MediaServer root: stopping docker ...

Oct 23 07:12:47 MediaServer root: 99b9f5eff972

Oct 23 07:12:47 MediaServer kernel: veth560e59e: renamed from eth0

Oct 23 07:12:47 MediaServer kernel: docker0: port 5(vethed0670f) entered disabled state

Oct 23 07:12:47 MediaServer kernel: docker0: port 5(vethed0670f) entered disabled state

Oct 23 07:12:47 MediaServer kernel: device vethed0670f left promiscuous mode

Oct 23 07:12:47 MediaServer kernel: docker0: port 5(vethed0670f) entered disabled state

Oct 23 07:12:47 MediaServer root: 09cf2aba6672

Oct 23 07:12:51 MediaServer kernel: veth644b2cf: renamed from eth0

Oct 23 07:12:51 MediaServer kernel: docker0: port 4(veth9c2e69d) entered disabled state

Oct 23 07:12:51 MediaServer kernel: docker0: port 4(veth9c2e69d) entered disabled state

Oct 23 07:12:51 MediaServer kernel: device veth9c2e69d left promiscuous mode

Oct 23 07:12:51 MediaServer kernel: docker0: port 4(veth9c2e69d) entered disabled state

Oct 23 07:12:51 MediaServer root: 7778a188a870

Oct 23 07:12:53 MediaServer kernel: veth6917eb1: renamed from eth0

Oct 23 07:12:53 MediaServer kernel: docker0: port 3(veth43a1dbd) entered disabled state

Oct 23 07:12:53 MediaServer kernel: docker0: port 3(veth43a1dbd) entered disabled state

Oct 23 07:12:53 MediaServer kernel: device veth43a1dbd left promiscuous mode

Oct 23 07:12:53 MediaServer kernel: docker0: port 3(veth43a1dbd) entered disabled state

Oct 23 07:12:53 MediaServer root: 63ea57a93fff

Oct 23 07:12:54 MediaServer kernel: docker0: port 2(veth88332d3) entered disabled state

Oct 23 07:12:54 MediaServer kernel: veth402b9d8: renamed from eth0

Oct 23 07:12:54 MediaServer kernel: docker0: port 2(veth88332d3) entered disabled state

Oct 23 07:12:54 MediaServer kernel: device veth88332d3 left promiscuous mode

Oct 23 07:12:54 MediaServer kernel: docker0: port 2(veth88332d3) entered disabled state

Oct 23 07:12:54 MediaServer root: 0660396c9877

Oct 23 07:12:55 MediaServer kernel: docker0: port 1(veth5d3868f) entered disabled state

Oct 23 07:12:55 MediaServer kernel: veth4feab14: renamed from eth0

Oct 23 07:12:55 MediaServer kernel: docker0: port 1(veth5d3868f) entered disabled state

Oct 23 07:12:55 MediaServer kernel: device veth5d3868f left promiscuous mode

Oct 23 07:12:55 MediaServer kernel: docker0: port 1(veth5d3868f) entered disabled state

Oct 23 07:12:55 MediaServer root: cbfda52d1c7d

Oct 23 07:12:56 MediaServer root: waiting for docker to die...

Oct 23 07:12:57 MediaServer ntpd[1940]: Deleting interface #6 docker0, 172.17.0.1#123, interface stats: received=0, sent=0, dropped=0, active_time=212516 secs

Oct 23 07:12:57 MediaServer avahi-daemon[4616]: Interface docker0.IPv4 no longer relevant for mDNS.

Oct 23 07:12:57 MediaServer avahi-daemon[4616]: Leaving mDNS multicast group on interface docker0.IPv4 with address 172.17.0.1.

Oct 23 07:12:57 MediaServer avahi-daemon[4616]: Withdrawing address record for 172.17.0.1 on docker0.

Oct 23 07:12:57 MediaServer emhttp: shcmd (34191): umount /var/lib/docker |& logger

Oct 23 07:12:57 MediaServer cache_dirs: Stopping cache_dirs process 5172    <---- should be just before here

Oct 23 07:12:57 MediaServer recycle.bin: Stopping Recycle Bin

Oct 23 07:12:57 MediaServer emhttp: Stopping Recycle Bin...

Oct 23 07:12:59 MediaServer unassigned.devices: Unmounting Devices...

"services" in this context refers to everything getting started after disks are mounted.  That message does not correspond to any event.

The log is of a shutdown, not a startup.

Technically, libvirt (the VMs) and Docker are services, and they are being shut down.

 

What you seek is a complex status, because you need to know whether all services that may be touching mounted filesystems have been stopped.

 

It sounds as if you would benefit from inserting yourself between each successive service shutdown event, and doing some lsof magic.

 

Per this Stack Exchange question...

 

lsof +f -- /mnt/some-volume

 

Returns a list of all file handles open on the specified volume, or an empty result if nothing is open. You could use polling of this to check for active handles on your partitions before unmounting them.

What I'm looking for here is an indication in the log when the event "stopping_services" is initiated to verify the proper flow of the shutdown with regard to plugins.  The events are a bit elusive and logging to show when each is initiated would be helpful.