What's Chris been doing?

While I was away on a week’s holiday I left a small lab full of Dell GX745 machines testing lcfg-sleep. When I came back I found that half of them had frozen at suspend-time. This has been happening on and off for months and really I’m no nearer to curing the problem. By contrast, the few new HP dc7900s that have been running lcfg-sleep have been as good as gold, suspending and resuming several times a day quite happily, waking up perfectly well both automatically and on a press of the power button – no problems there.

Since effort is short and I’ve been bashing my head against the Dell problems for far too long now, and I’m utterly sick of it, I’ve now disabled sleep on the final two remaining Dell models it was operating on, the GX745 and the 755. The only supported model is therefore the HP dc7900. Happily this is the PC du jour and we’re deploying a lot of them in the student labs right now, so if things go well in my wee HP sleep test lab we can fairly rapidly spread lcfg-sleep to the rest of the student lab HPs. A few months after that, if things seem as reliable as I hope they will, we could perhaps think of spreading lcfg-sleep to HPs in offices too. After all the original point of the project was to cut the Forum’s electricity bill, and the Forum has no student labs.

This isn’t necessarily the end for the hopes of automatic sleep on the Dells. I may well go back and test sleep on a Dell from time to time, or even fix the problem if inspiration strikes, but I won’t spend much more effort on it at the moment: there are more important things to be getting on with.

Just a quick note. Following the discovery of changes needed to support sleep on 745s, this morning I tested some 755s with various sleep quirks. With the i810 driver, which is what the machines are currently using, no single sleep quirk does the job. The best I can do is get the machine to resume with a totally dead screen. At some point perhaps I should test them to see if the intel driver suffers from the same nastiness as on 745s. In the meantime no sleep for 755s.

Sigh. Spoke too soon. Yesterday’s reboot seems to have unsettled something: the test machine slept twice and woke twice last night, as normal, but the third time was a failure: I got the “going to sleep” message at 04:21 but it failed to wake up on schedule at 07:44.

The machine now needs some personal attention to examine its state and to get it up single user to copy all the logs before booting into normal running. Oh well; it can wait until I’m next in the building.

I’m wondering if there was something special happening at that time of the morning to make the machine unhappy. I’ll take a look when the machine’s up again.

Meanwhile back to TiBS, whose config I’ve been automating with LCFG and which will no doubt be mentioned more fully here soon.

My test 755 had been up for 17 days before I had to reboot it today for a software update. In those 17 days it had been sleeping three times each night and several times during the day at weekends too. And no hangs! And no failures to wake up! All of which is very good. I’m now willing to let the sleep component loose on a test student lab. This’ll have to wait until they’re upgraded to SL5.3 but that’s due to happen this month sometime I think.

I’ve come back today from a week’s holiday to find that – to my amazement – the sleep test machine has successfully suspended and resumed a full 48 times without any problems at all. This is incredible considering that this is the machine that can hardly go a night or two without getting into some sort of sticky hang-type situation. Ten nights, three sleeps a night and more at the weekends. Am I just lucky or was this due to something being different? OK, this is what was different:

• I wasn’t here. I normally use the machine remotely for shell access during the day. I can’t see a remote user login session being a cause of suspend problems, particularly when there’s no session on the go during the night which is when the machine does its sleep thing anyway (I have sleep disabled during working hours)?
• The client component wasn’t running. This follows the problem we spotted a week or two ago whereby something else would grab the client component’s port before the client component got to it. (Understandably, as Simon pointed out.) I had started the machine up without the client component as I looked into this problem and had forgotten to start the component before going on holiday. So the machine has been running in ultra-stable mode with no profile changes and no RPM changes. This seems to suit the power management stuff down to the ground. I wonder why…?

I think I’ll leave it another week or so with client running this time, and we’ll see if the stability continues.

The run of good luck meant that I don’t currently have a chance of trying out Simon’s diagnostic suggestions in his comment on my previous entry, but no doubt I shall get to try them out soon enough.

In other news, I’ve solved a couple of problems that were plaguing me before the holiday. Both solutions were really stupid and probably show how much I was needing the holiday:

1. I’d been trying to get a new multipath SAN partition up on one of the web servers. When I tried to make a filesystem on the new partition I’d get “this partition is busy” errors. The solution: I was using the partition’s sd entry in /dev when I should have been using its entry with a big long name in /dev/mpath. It was the system’s own multipath code which was keeping the partition “busy”. The new partition is now happily mounted and filling up with data.
2. The sleep test machines had been configured to mail me the sleep log files every week when logrotate ran. They did this, but they mailed me stuff which was a month out of date. Who wants that…? Turns out that this is the rather odd default behaviour of logrotate: it mails you the logs it’s about to delete – the ones that fall off the end of the weekly conveyor belt – rather than the most recent logs. Adding the logrotate keyword mailfirst to the logrotate recipe has hopefully cured this.

Sleep failed again on my test 755 last night. It’s been happily sleeping and waking for several days, four times per night, but last night it failed to wake from its second nap. This time it looks as if the machine hung at the point of powering off, or on again.

The power management suspend log (/var/log/pm/suspend.log) has all the suspend messages one could expect to see in it and none of the resume messages:

Fri Jun 12 00:03:03 BST 2009: running suspend hooks.
===== Fri Jun 12 00:03:03 BST 2009: running hook: /usr/lib/pm-utils/sleep.d/00clear =====
===== Fri Jun 12 00:03:03 BST 2009: running hook: /usr/lib/pm-utils/sleep.d/05led =====
===== Fri Jun 12 00:03:03 BST 2009: running hook: /usr/lib/pm-utils/sleep.d/15_915resolution =====
===== Fri Jun 12 00:03:03 BST 2009: running hook: /usr/lib/pm-utils/sleep.d/20video =====
kernel.acpi_video_flags = 0
===== Fri Jun 12 00:03:03 BST 2009: running hook: /usr/lib/pm-utils/sleep.d/49bluetooth =====
===== Fri Jun 12 00:03:03 BST 2009: running hook: /usr/lib/pm-utils/sleep.d/50modules =====
===== Fri Jun 12 00:03:03 BST 2009: running hook: /usr/lib/pm-utils/sleep.d/55battery =====
===== Fri Jun 12 00:03:03 BST 2009: running hook: /usr/lib/pm-utils/sleep.d/60sysfont =====
===== Fri Jun 12 00:03:03 BST 2009: running hook: /usr/lib/pm-utils/sleep.d/65alsa =====
===== Fri Jun 12 00:03:03 BST 2009: running hook: /usr/lib/pm-utils/sleep.d/94cpufreq =====
===== Fri Jun 12 00:03:03 BST 2009: running hook: /usr/lib/pm-utils/sleep.d/95led =====
===== Fri Jun 12 00:03:03 BST 2009: running hook: /usr/lib/pm-utils/sleep.d/98lcfgsleep =====
===== Fri Jun 12 00:03:08 BST 2009: running hook: /usr/lib/pm-utils/sleep.d/99video =====
Fri Jun 12 00:03:08 BST 2009: done running suspend hooks.

No problem there. But there’s a possible clue in *syslog*. This is what it looks like when the machine sleeps – this is from the previous, successful sleep last night, from 18:00 to 23:52:

Jun 11 18:00:08 orkney kernel: Disabling non-boot CPUs ...
Jun 11 18:00:09 orkney kernel: CPU 1 is now offline
Jun 11 18:00:09 orkney kernel: SMP alternatives: switching to UP code
Jun 11 23:52:32 orkney kernel: CPU1 is down

I’ve checked through the logs (grep -A 2 -B 2 'now offline' /var/lcfg/log/syslog*) and every time the machine successfully suspended and resumed, it managed to write CPU 1 is now offline and then SMP alternatives: switching to UP code to syslog before suspending. But at last night’s unsuccessful sleep it didn’t – these are the last syslog entries in syslog before the hang:

Jun 12 00:03:08 orkney kernel: Disabling non-boot CPUs ...
Jun 12 00:03:09 orkney kernel: CPU 1 is now offline

SMP alternatives: switching to UP code is missing. Kernel bug? Time to do some internet searching perhaps.

The test 755 slept happily last night, three times, and was fine when it woke up this morning.

However on reboot it again got stuck starting the client component. I’ve entered this as bug 146 in the LCFG bug tracker.

I’ve written some guidelines on how to go about debugging sleep-related problems.

The test 755′s most recent difficulty turned out to be not a crash or a total machine hang, but something that happened the last time I rebooted it. I can’t now remember why it was necessary to reboot the machine, but anyway, I had started the reboot then departed for pleasanter climes. When I got back to it today the machine was half-booted and showing “LCFG mailng [OK]” at the bottom of a list of startup messages. Which means that it had completed mailng and was starting the next thing on the list: the client component. I later retrieved the client log and at the hang it was saying:

01/06/09 16:42:53: >> context
01/06/09 16:43:16: >> start
01/06/09 16:43:16: configuration changed
01/06/09 16:43:16: starting daemon [4283/732] version 2.2.37 04/17/09 13:53:56
01/06/09 16:43:16: warnings: conflict,context,dirs,error,localprofile,notify,parse,rpms,server
01/06/09 16:43:16: ** can’t bind UDP socket
01/06/09 16:43:16: ** Address already in use

When I restarted the machine today the client component started OK and the machine booted successfully. This time the client log said:

03/06/09 12:31:57: >> context
03/06/09 12:32:19: >> start
03/06/09 12:32:19: configuration changed
03/06/09 12:32:19: starting daemon [4291/732] version 2.2.37 04/17/09 13:53:56
03/06/09 12:32:19: warnings: conflict,context,dirs,error,localprofile,notify,parse,rpms,server
03/06/09 12:32:19: context check requested
03/06/09 12:32:19: new context: booting=true
03/06/09 12:32:23: profile accepted: 2921cae88f21209cf706dec15bafd4b5
03/06/09 12:33:27: >> context
03/06/09 12:33:27: context check requested
03/06/09 12:33:27: new context: default
03/06/09 12:33:30: profile accepted: 2921cae88f21209cf706dec15bafd4b5

This morning’s development meeting went well, a big improvement on previous ones I think: it helps far more to talk briefly about the real progress on each project than to go on about deadlines.

Following George’s comment that it looked to him like amd that was hanging rather than ntp, I’ve switched round the order of the resume hooks so that ntp should start up before amd. That way hopefully amd will start up with a sensible date/time. I’ve not seen the amd component failing to start up before and I haven’t seen the clock going haywire before either, so I’m hoping that the one was the cause of the other. We’ll see if it happens again.

Meanwhile, the very next time the test 755 went to sleep it also didn’t wake up. This time it didn’t seem to be hung in the same way: the last time it happened the client component was managing to report back to the LCFG server, and I could ping the machine, but this time the machine’s LCFG status page reported

Last acknowledgement: 29/05/09 17:50:24

and ping returned “destination unreachable”.

Saving the log files and rebooting, this is what /var/log/pm/suspend.log says this time:

Fri May 29 18:00:03 BST 2009: running suspend hooks.
===== Fri May 29 18:00:03 BST 2009: running hook: /usr/lib/pm-utils/sleep.d/00clear =====
===== Fri May 29 18:00:03 BST 2009: running hook: /usr/lib/pm-utils/sleep.d/05led =====
===== Fri May 29 18:00:03 BST 2009: running hook: /usr/lib/pm-utils/sleep.d/15_915resolution =====
===== Fri May 29 18:00:03 BST 2009: running hook: /usr/lib/pm-utils/sleep.d/20video =====
kernel.acpi_video_flags = 0
===== Fri May 29 18:00:03 BST 2009: running hook: /usr/lib/pm-utils/sleep.d/49bluetooth =====
===== Fri May 29 18:00:03 BST 2009: running hook: /usr/lib/pm-utils/sleep.d/50modules =====
===== Fri May 29 18:00:03 BST 2009: running hook: /usr/lib/pm-utils/sleep.d/55battery =====
===== Fri May 29 18:00:03 BST 2009: running hook: /usr/lib/pm-utils/sleep.d/60sysfont =====
===== Fri May 29 18:00:03 BST 2009: running hook: /usr/lib/pm-utils/sleep.d/65alsa =====
===== Fri May 29 18:00:03 BST 2009: running hook: /usr/lib/pm-utils/sleep.d/94cpufreq =====
===== Fri May 29 18:00:03 BST 2009: running hook: /usr/lib/pm-utils/sleep.d/95led =====
===== Fri May 29 18:00:03 BST 2009: running hook: /usr/lib/pm-utils/sleep.d/98lcfgsleep =====
===== Fri May 29 18:00:09 BST 2009: running hook: /usr/lib/pm-utils/sleep.d/99video =====
Fri May 29 18:00:09 BST 2009: done running suspend hooks.

So all the suspend hooks ran successfully, but then – it hung? When I got to it this morning the machine wasn’t sleeping, as the power button wasn’t flashing, so it’s not simply a case of it not waking up on cue. The power button was solidly on, which is the case when the machine is either hung or running normally. And it wasn’t running normally…

Meanwhile I’ve been trying to upgrade the bios on the test 755. I’ve been trying the method described in the Dell Linux wiki but when I reboot it says that it can’t find the bios.hdr file I’ve loaded in memory.

I think I need to do a “warm boot” rather than the usual (apparently) “cold” one.
The instructions tell you to add “reboot=bios” to the end of your kernel command line, then reboot, then try loading your bios.hdr again then rebooting (when the actual upgrade will then happen). Tried that, get the “can’t find your bios.hdr in memory” message.

Perhaps I should have edited the kernel command line rather than appended to it? Maybe I’ll try that tomorrow.

More suspend weirdness – but this looks like another new case. (This project begins to seem like an epidemic of power management bugs.)

This time it’s the test 755 that’s affected. It was hung when I came in this morning: it went to sleep at 00:21 but failed to wake up again at 03:54. It wasn’t totally hung, it seemed to be stuck in a sort of partially up mode where some things were working OK but you couldn’t login to it. I’ve had a stunningly dozy day, my brain seems to have spent most of the day in low power mode, possibly because of the hot weather – so I’ve only just thought to consult the machine’s /var/log/pm/suspend.log (I got the machine going again this morning.)
And it looks interesting. Firstly here’s what you get when you do ls -l on it:

-rw-r--r-- 1 root lcfg 1565 Jun 27  1922 suspend.log

1922? And here are the contents:

Fri May 29 00:21:02 BST 2009: running suspend hooks.
===== Fri May 29 00:21:02 BST 2009: running hook: /usr/lib/pm-utils/sleep.d/00clear =====
===== Fri May 29 00:21:02 BST 2009: running hook: /usr/lib/pm-utils/sleep.d/05led =====
===== Fri May 29 00:21:02 BST 2009: running hook: /usr/lib/pm-utils/sleep.d/15_915resolution =====
===== Fri May 29 00:21:02 BST 2009: running hook: /usr/lib/pm-utils/sleep.d/20video =====
kernel.acpi_video_flags = 0
===== Fri May 29 00:21:02 BST 2009: running hook: /usr/lib/pm-utils/sleep.d/49bluetooth =====
===== Fri May 29 00:21:02 BST 2009: running hook: /usr/lib/pm-utils/sleep.d/50modules =====
===== Fri May 29 00:21:02 BST 2009: running hook: /usr/lib/pm-utils/sleep.d/55battery =====
===== Fri May 29 00:21:02 BST 2009: running hook: /usr/lib/pm-utils/sleep.d/60sysfont =====
===== Fri May 29 00:21:02 BST 2009: running hook: /usr/lib/pm-utils/sleep.d/65alsa =====
===== Fri May 29 00:21:02 BST 2009: running hook: /usr/lib/pm-utils/sleep.d/94cpufreq =====
===== Fri May 29 00:21:02 BST 2009: running hook: /usr/lib/pm-utils/sleep.d/95led =====
===== Fri May 29 00:21:02 BST 2009: running hook: /usr/lib/pm-utils/sleep.d/98lcfgsleep =====
===== Fri May 29 00:21:08 BST 2009: running hook: /usr/lib/pm-utils/sleep.d/99video =====
Fri May 29 00:21:08 BST 2009: done running suspend hooks.
Tue Jun 27 01:26:46 BST 1922: running resume hooks.
===== Tue Jun 27 01:26:46 BST 1922: running hook: /usr/lib/pm-utils/sleep.d/99video =====
===== Tue Jun 27 01:26:46 BST 1922: running hook: /usr/lib/pm-utils/sleep.d/98lcfgsleep =====

Here’s that 98lcfgsleep script in full:

#!/bin/bash

. /usr/lib/pm-utils/functions

case "$1" in
        hibernate|suspend)
                
                /usr/bin/om ntp stop

                /bin/echo "`/bin/date` : Suspend" >> /var/lcfg/log/sleep.activity

                /bin/grep `/bin/date +%d/%m/%y` /var/lcfg/log/sleep | /bin/grep `/bin/date +%H:%M` | /bin/mail -s "Falling asleep" [Chris's mail address]

                sleep 5

                ;;
        thaw|resume)
                /bin/touch /var/tmp/lcfg-sleep-waketime
                
                /usr/bin/om amd restart

                /usr/bin/om ntp start

                /bin/echo "`/bin/date` : Resume" >> /var/lcfg/log/sleep.activity

                /bin/mail -s "Waking up" [Chris's mail address] < /dev/null

                ;;
        *)
                ;;
esac

exit $?

I got the falling asleep mail, and the ntp and sleep.activity log files were both updated at the right time, so all of the suspend-time stuff appears to have happened properly.
The resume-time stuff doesn’t though, and somewhere here seems to be where the machine got stuck for seven hours until I power-cycled it. The “touch” command seems to have happened – but look, here’s a familiar date:

-rw-r--r-- 1 root root 0 Jun 27  1922 /var/tmp/lcfg-sleep-waketime

Here are the last three entries in the amd log:

28/05/09 23:52:32: >> restart
27/06/22 01:26:46: >> restart
29/05/09 10:33:56: >> start

I suppose that means just that it did in fact restart but at some point between 23:52 yesterday and 10:33 today.

There’s no sign of any entry for this resume-time start in the ntp log. The most recent entry in the sleep.activity log is from the suspend script, and the file is dated 00:21 today, when the machine suspended, so that didn’t appear to run. I also received no mail at resume time.

So it looks like the machine went down in 2009 and came up in 1922, which made ntp hang indefinitely on startup.