Intermitted fail to shutdown in 11.4

frozenpenguin · March 16, 2011, 6:13pm

Most of the time shutdown works normally, but sometimes the shutdown process reaches a point where the screen is off, the cooling fan stops, and it sounds like the HDD powers down, but the power and WiFi lights remain on (I have waited over 2 minutes). If I force a shutdown at this point when I next start up there are no file system checks run suggesting that the file system synced before I forced power off.

I have set the system to shutdown when the lid is closed. This problem has occurred with both a manual shutdown (from the KDE “Leave” menu) and with a lid closure. I always close all applications before I do a shutdown.

This is on an Acer Extensa 5220 with a fresh install of 11.4 - 64 bit as the only operating system. Installed using the net install disk. KDE installed as the desktop.

This same laptop has previously run Ubuntu (for several years) and then Debian and Fedora briefly before I decided on openSuse. None of these other versions of Linux had this problem.

frozenpenguin · March 18, 2011, 3:01pm

This problem is happening more often. Originally about 1 in 10 shutdowns failed, now it is closer to 1 in 2. My laptop is turned on and off multiple times each day, so this is a real problem for me. I would really like to keep using openSuse, it is a nice distro, but if no one can suggest a solution I shall have to move to another distro.

Thank you in advance to anyone who could shed some light on this issue.

DaaX · March 18, 2011, 3:07pm

Hi,

Did you check in verbose mode (press ESC when you see the shutdown screen appear) if there was errors ?

yasar11732 · March 18, 2011, 3:18pm

And also, you may want to check log files for anything unusual, so that you can get a lead on the issue. For list list for important log files, see: Linux log files location and how do I view logs files?

frozenpenguin · March 19, 2011, 1:19am

Thank you DaaX and yasar11732,

I managed to capture the logs for a good shutdown and a failed shutdown. The differences between the two are in the very end of the shutdown sequence. I have placed the sections below:

First a good shutdown:

Mar 18 16:50:48 linux-44a8 nm-dispatcher.action: Script '/etc/NetworkManager/dispatcher.d/autofs' exited with error status 1.
Mar 18 16:50:48 linux-44a8 shutdown[5660]: shutting down for system halt
Mar 18 16:50:48 linux-44a8 init: Switching to runlevel: 0
Mar 18 16:50:48 linux-44a8 kernel:   883.776457] bootsplash: status on console 0 changed to on
Mar 18 16:50:49 linux-44a8 smartd[2502]: smartd received signal 15: Terminated
Mar 18 16:50:49 linux-44a8 smartd[2502]: Device: /dev/sda [SAT], state written to /var/lib/smartmontools/smartd.ST9250315AS-6VC1BWT0.ata.state
Mar 18 16:50:49 linux-44a8 smartd[2502]: smartd is exiting (exit status 0)
Mar 18 16:50:49 linux-44a8 NetworkManager[1537]: <error> [1300492249.94794] [nm-manager.c:1368] user_proxy_init(): could not init user settings proxy: (3) Could not get owner of name 'org.freedesktop.NetworkManagerUserSettings': no such name
Mar 18 16:50:49 linux-44a8 NetworkManager[1537]: <error> [1300492249.95724] [nm-manager.c:1368] user_proxy_init(): could not init user settings proxy: (3) Could not get owner of name 'org.freedesktop.NetworkManagerUserSettings': no such name
Mar 18 16:50:49 linux-44a8 NetworkManager[1537]: <error> [1300492249.96536] [nm-manager.c:1368] user_proxy_init(): could not init user settings proxy: (3) Could not get owner of name 'org.freedesktop.NetworkManagerUserSettings': no such name
Mar 18 16:50:49 linux-44a8 auditd[1439]: The audit daemon is exiting.
Mar 18 16:50:49 linux-44a8 rpcbind: rpcbind terminating on signal. Restart with "rpcbind -w"
Mar 18 16:50:49 linux-44a8 acpid: exiting
Mar 18 16:50:49 linux-44a8 kernel: Kernel logging (proc) stopped.
Mar 18 16:50:49 linux-44a8 rsyslogd: [origin software="rsyslogd" swVersion="5.6.3" x-pid="1408" x-info="http://www.rsyslog.com"] exiting on signal 15.

and the failed shutdown:

Mar 18 16:33:38 linux-44a8 shutdown[5970]: shutting down for system halt
Mar 18 16:33:38 linux-44a8 nm-dispatcher.action: Script '/etc/NetworkManager/dispatcher.d/autofs' exited with error status 1.
Mar 18 16:33:39 linux-44a8 NetworkManager[1538]: <error> [1300491219.352801] [nm-manager.c:1368] user_proxy_init(): could not init user settings proxy: (3) Could not get owner of name 'org.freedesktop.NetworkManagerUserSettings': no such name
Mar 18 16:33:39 linux-44a8 NetworkManager[1538]: <error> [1300491219.353664] [nm-manager.c:1368] user_proxy_init(): could not init user settings proxy: (3) Could not get owner of name 'org.freedesktop.NetworkManagerUserSettings': no such name
Mar 18 16:33:39 linux-44a8 NetworkManager[1538]: <error> [1300491219.354274] [nm-manager.c:1368] user_proxy_init(): could not init user settings proxy: (3) Could not get owner of name 'org.freedesktop.NetworkManagerUserSettings': no such name
Mar 18 16:33:39 linux-44a8 avahi-daemon[1384]: Registering new address record for fe80::224:1dff:fef0:b03f on wlan0.*.
Mar 18 16:33:39 linux-44a8 init: Switching to runlevel: 0
Mar 18 16:33:39 linux-44a8 kernel:   706.765494] bootsplash: status on console 0 changed to on
Mar 18 16:33:39 linux-44a8 smartd[2432]: smartd received signal 15: Terminated
Mar 18 16:33:39 linux-44a8 smartd[2432]: Device: /dev/sda [SAT], state written to /var/lib/smartmontools/smartd.ST9250315AS-6VC1BWT0.ata.state
Mar 18 16:33:39 linux-44a8 smartd[2432]: smartd is exiting (exit status 0)
Mar 18 16:33:40 linux-44a8 auditd[1437]: The audit daemon is exiting.
Mar 18 16:33:40 linux-44a8 rpcbind: rpcbind terminating on signal. Restart with "rpcbind -w"
Mar 18 16:33:40 linux-44a8 kernel: Kernel logging (proc) stopped.
Mar 18 16:33:40 linux-44a8 rsyslogd: [origin software="rsyslogd" swVersion="5.6.3" x-pid="1406" x-info="http://www.rsyslog.com"] exiting on signal 15.

There is a little difference in the entry sequence which I assume is just the logging routine. The differences I note are:

In the failed shutdown the avahi-daemon registers a new address (not sure why given network should be shut down) at timestamp 16:33:39. There is no such action in the good shutdown

In the good shutdown the acpid exits at time stamp 16:50:49, but there is no such exit in the failed shutdown.

I don’t know enough if the two events are related. Certainly the acpi daemon failing to exit may be the cause of the shutdown issue.

So can anyone interpret this? Any suggestions for tweaks or additional tests I could do to help isolate the problem?

Thank you

frozenpenguin · March 21, 2011, 4:06pm

To check that there is not some config issue I did a fresh install of openSuse onto a separate hard drive. Again used Network install. This time chose Gnome desktop. No additional programs installed. Minimal config (set the system to shutdown on closing the lid). Problem still present.

frozenpenguin · March 24, 2011, 6:17pm

Well I have tried all sorts of testing with how and when I shut down, all to no benefit. I have tried shutting down just with lid closure, just with the menu, and various combinations. I can find no pattern. I also set the lid close back to default and this problem still occurs. I even tried running 32 bit in case there was some hardware issue with 64 bit. Still the problem occurs. The best I can suggest is that there is something in my hardware which is not compatible with openSuse.

I will try entering a bug report on this so hopefully it can be solved.

I guess it is time for me to start evaluating another distribution as not being able to shutdown reliably is just not acceptable performance from an OS.

sebadamus · August 26, 2011, 11:51pm

Hello Fronzenpenguin, and Linux Gurus

Could you solve your problem? I have now and then some similar problem… when I sleep my notebook sometimes everything stays frozen and the only way to restart is the power button or sysreq alt B (I have this enabled on kernel)

I made a simple forum search and I get to you post because this string “nm-dispatcher.action” that also fails just when my notebook hungs on sleep.

Here I post two failure logs from the last two times my notebook freezed on sleep (I mean, the screen stays on, the fan runs at its highst speed, and the only restart way is with the powerbutton or sysreq+ALT+B)

Please notice the time stamps, when it skips several hours is when I click on sleep and the notebook freezes and also the “nm-dispatcher.action” fails.

I have a hunch that it is something to do with the wireless driver or the network applet… can you help me trace the problem?

Here is my network hardware info, if there is anything else needed to get to a solution, please askme.

Thanks,


84: None 00.0: 10700 Loopback
  [Created at net.124]
  Unique ID: ZsBS.GQNx7L4uPNA
  SysFS ID: /class/net/lo
  Hardware Class: network interface
  Model: "Loopback network interface"
  Device File: lo
  Link detected: yes
  Config Status: cfg=no, avail=yes, need=no, active=unknown

85: None 00.0: 10701 Ethernet
  [Created at net.124]
  Unique ID: usDW.ndpeucax6V1
  Parent ID: rBUF.VKS72bhaJ_6
  SysFS ID: /class/net/eth0
  SysFS Device Link: /devices/pci0000:00/0000:00:1c.1/0000:03:00.0
  Hardware Class: network interface
  Model: "Ethernet network interface"
  Driver: "r8169"
  Driver Modules: "r8169"
  Device File: eth0
  HW Address: 60:eb:69:51:ae:72
  Link detected: no
  Config Status: cfg=no, avail=yes, need=no, active=unknown
  Attached to: #39 (Ethernet controller)

86: None 00.0: 1070a WLAN
  [Created at net.124]
  Unique ID: AYEt.QXn1l67RSa1
  Parent ID: y9sn.3Bbj30Yicg4
  SysFS ID: /class/net/wlan0
  SysFS Device Link: /devices/pci0000:00/0000:00:1c.0/0000:02:00.0
  Hardware Class: network interface
  Model: "WLAN network interface"
  Driver: "brcm80211"
  Driver Modules: "brcm80211"
  Device File: wlan0
  HW Address: 00:26:82:de:94:5c
  Link detected: yes
  Config Status: cfg=no, avail=yes, need=no, active=unknown
  Attached to: #38 (WLAN controller)

87: None 00.0: 10701 Ethernet
  [Created at net.124]
  Unique ID: sG1U.ndpeucax6V1
  SysFS ID: /class/net/vboxnet0
  Hardware Class: network interface
  Model: "Ethernet network interface"
  Device File: vboxnet0
  HW Address: 0a:00:27:00:00:00
  Config Status: cfg=no, avail=yes, need=no, active=unknown


08/25/11 06:09:55 PM	itsalive	NetworkManager[1536]	<info> (wlan0): cleaning up...
08/25/11 06:09:55 PM	itsalive	NetworkManager[1536]	<info> (wlan0): taking down device.
08/25/11 06:09:55 PM	itsalive	NetworkManager[1536]	<info> (eth0): now unmanaged
08/25/11 06:09:55 PM	itsalive	NetworkManager[1536]	<info> (eth0): device state change: 8 -> 1 (reason 37)
08/25/11 06:09:55 PM	itsalive	NetworkManager[1536]	<info> (eth0): deactivating device (reason: 37).
08/25/11 06:09:55 PM	itsalive	NetworkManager[1536]	<info> (eth0): canceled DHCP transaction, DHCP client pid 8763
08/25/11 06:09:55 PM	itsalive	NetworkManager[1536]	<info> (eth0): cleaning up...
08/25/11 06:09:55 PM	itsalive	NetworkManager[1536]	<info> (eth0): taking down device.
08/25/11 06:09:55 PM	itsalive	NetworkManager[1536]	<info> (eth0): carrier now OFF (device state 1)
08/25/11 06:09:55 PM	itsalive	nm-dispatcher.action	Script '/etc/NetworkManager/dispatcher.d/autofs' exited with error status 1.
08/25/11 07:26:47 PM	itsalive	NetworkManager[1527]	<info> NetworkManager (version 0.8.2) is starting...
08/25/11 07:26:47 PM	itsalive	NetworkManager[1527]	<info> Read config file /etc/NetworkManager/nm-system-settings.conf
08/25/11 07:26:48 PM	itsalive	NetworkManager[1527]	<info> VPN: loaded org.freedesktop.NetworkManager.pptp


08/25/11 11:29:56 AM	itsalive	NetworkManager[1524]	<info> (wlan0): supplicant connection state:  associating -> associated
08/25/11 11:29:56 AM	itsalive	NetworkManager[1524]	<info> (wlan0): supplicant connection state:  associated -> 4-way handshake
08/25/11 11:29:56 AM	itsalive	NetworkManager[1524]	<info> (wlan0): supplicant connection state:  4-way handshake -> group handshake
08/25/11 11:29:56 AM	itsalive	NetworkManager[1524]	<info> (wlan0): supplicant connection state:  group handshake -> completed
08/25/11 11:29:56 AM	itsalive	NetworkManager[1524]	<info> Activation (wlan0/wireless) Stage 2 of 5 (Device Configure) successful.  Connected to wireless network 'noname'.
08/25/11 11:29:56 AM	itsalive	NetworkManager[1524]	<info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) scheduled.
08/25/11 11:29:56 AM	itsalive	NetworkManager[1524]	<info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) started...
08/25/11 11:29:56 AM	itsalive	NetworkManager[1524]	<info> (wlan0): device state change: 5 -> 7 (reason 0)
08/25/11 11:29:56 AM	itsalive	NetworkManager[1524]	<info> Activation (wlan0) Beginning DHCPv4 transaction (timeout in 45 seconds)
08/25/11 11:29:56 AM	itsalive	NetworkManager[1524]	<info> dhclient started with pid 3774
08/25/11 11:29:56 AM	itsalive	NetworkManager[1524]	<info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) complete.
08/25/11 11:29:56 AM	itsalive	NetworkManager[1524]	<info> (wlan0): DHCPv4 state changed nbi -> preinit
08/25/11 11:30:01 AM	itsalive	NetworkManager[1524]	<info> (wlan0): DHCPv4 state changed preinit -> bound
08/25/11 11:30:01 AM	itsalive	NetworkManager[1524]	<info> Activation (wlan0) Stage 4 of 5 (IP4 Configure Get) scheduled...
08/25/11 11:30:01 AM	itsalive	NetworkManager[1524]	<info> Activation (wlan0) Stage 4 of 5 (IP4 Configure Get) started...
08/25/11 11:30:01 AM	itsalive	NetworkManager[1524]	<info>   address 20.0.0.120
08/25/11 11:30:01 AM	itsalive	NetworkManager[1524]	<info>   prefix 24 (255.255.255.0)
08/25/11 11:30:01 AM	itsalive	NetworkManager[1524]	<info>   gateway 20.0.0.100
08/25/11 11:30:01 AM	itsalive	NetworkManager[1524]	<info>   hostname 'itsaliveNBwireless'
08/25/11 11:30:01 AM	itsalive	NetworkManager[1524]	<info>   nameserver '20.0.0.100'
08/25/11 11:30:01 AM	itsalive	NetworkManager[1524]	<info> Activation (wlan0) Stage 5 of 5 (IP Configure Commit) scheduled...
08/25/11 11:30:01 AM	itsalive	NetworkManager[1524]	<info> Activation (wlan0) Stage 4 of 5 (IP4 Configure Get) complete.
08/25/11 11:30:01 AM	itsalive	NetworkManager[1524]	<info> Activation (wlan0) Stage 5 of 5 (IP Configure Commit) started...
08/25/11 11:30:02 AM	itsalive	NetworkManager[1524]	<info> Clearing nscd hosts cache.
08/25/11 11:30:02 AM	itsalive	NetworkManager[1524]	<info> (wlan0): device state change: 7 -> 8 (reason 0)
08/25/11 11:30:02 AM	itsalive	NetworkManager[1524]	<info> (wlan0): roamed from BSSID 00:14:BF:E2:80:34 (noname) to 00:14:BF:E2:80:34 (noname)
08/25/11 11:30:02 AM	itsalive	NetworkManager[1524]	<info> Policy set 'noname' (wlan0) as default for IPv4 routing and DNS.
08/25/11 11:30:02 AM	itsalive	NetworkManager[1524]	<info> Activation (wlan0) successful, device activated.
08/25/11 11:30:02 AM	itsalive	NetworkManager[1524]	<info> Activation (wlan0) Stage 5 of 5 (IP Configure Commit) complete.
08/25/11 11:30:02 AM	itsalive	nm-dispatcher.action	Script '/etc/NetworkManager/dispatcher.d/autofs' exited with error status 1.
08/25/11 11:30:03 AM	itsalive	nm-dispatcher.action	Script '/etc/NetworkManager/dispatcher.d/nfs' exited with error status 2.
08/25/11 12:03:43 PM	itsalive	NetworkManager[1524]	<info> (wlan0): supplicant connection state:  completed -> group handshake
08/25/11 12:03:43 PM	itsalive	NetworkManager[1524]	<info> (wlan0): supplicant connection state:  group handshake -> completed
08/25/11 12:09:53 PM	itsalive	NetworkManager[1524]	<info> (wlan0): supplicant connection state:  completed -> disconnected