After a month of not seeing the problem it has returned for me. Though perhaps not identical to the first time I suffered the issue here are my last observations.
- Screen would not awake from mouse click, Magic Trackpad click, or keyboard.
- Keyboard caps lock does NOT light up (engage) when pressed.
- If I switch a BT device off, when I turn it back on it fails to connect.
At this point I reach around and press the ON button briefly - Unlike the first time I witnessed this the screen came on. Thus perhaps its a different issue. the BT devices still do not interact with iMac.
- Using ssh I connect to imac from MBP.
- dtruss of blued does not seem to show anything happening.
- /var/log/system.log reports for last few hours:
Feb 1 06:03:04 iMac kernel[0]: AFPSleepWakeHandler: going to sleep
Feb 1 06:46:26 iMac configd[15]: PMConnection AirPort configd plug-in com.apple.powermanagement.applicationresponse.slowresponse 13786 ms
Feb 1 06:46:26 iMac configd[15]: PMConnection IPConfiguration com.apple.powermanagement.applicationresponse.slowresponse 13825 ms
Feb 1 05:51:25 iMac configd[15]: PMConnection mDNSResponder com.apple.powermanagement.applicationresponse.timedout 25423 ms
Feb 1 05:51:25 iMac configd[15]: PMConnection IPConfiguration com.apple.powermanagement.applicationresponse.timedout 25423 ms
Feb 1 05:51:30 iMac loginwindow[1316]: handleUnlockResult, Currenttime:2/1/2011 5:51:30.998 AM - Waketime:2/1/2011 5:50:46.000 AM = Deltatime:44.
997963965
Feb 1 05:51:36 iMac KernelEventAgent[43]: tid 00000000 received event(s) VQ_DEAD (32)
Feb 1 05:51:36 iMac KernelEventAgent[43]: tid 00000000 type 'afpfs', mounted on '/Volumes/Share', from 'afp_35BfsQ35BfsQ35BfsQ35BfsQ-2.2e000006',
dead
Feb 1 05:51:36 iMac KernelEventAgent[43]: tid 00000000 found 1 filesystem(s) with problem(s)
That is NAS that switches itself off - so no big surprise there.
Feb 1 05:51:36 iMac /System/Library/CoreServices/Finder.app/Contents/MacOS/Finder[1337]: BonjourBrowser::DNSServiceQueryRecord returned -65540
Feb 1 05:51:37: --- last message repeated 5 times ---
Feb 1 05:51:36 iMac loginwindow[1316]: AFP error -1 mapped to EIO
What's that? A quick look through logs shows that hasn't happend in last few days.
# (cat system.log; bzcat system.log.{0,1,2,3,4,5,6,7}.bz2) | grep 'AFP error'
Feb 1 05:51:36 iMac loginwindow[1316]: AFP error -1 mapped to EIO
#
Feb 1 05:51:37 iMac kernel[0]: afpfs_DoReconnect: max reconnect time reached 35 > 30 (Connecting 61) /Volumes/Share Feb 1 06:03:03 iMac loginwindow[1316]: loginwindow SleepWakeCallback WILL sleep
Feb 1 06:03:04 iMac kernel[0]: AFPSleepWakeHandler: going to sleep
Feb 1 06:46:26 iMac configd[15]: PMConnection AirPort configd plug-in com.apple.powermanagement.applicationresponse.slowresponse 13786 ms
Feb 1 06:46:26 iMac configd[15]: PMConnection IPConfiguration com.apple.powermanagement.applicationresponse.slowresponse 13825 ms
Feb 1 06:46:26 iMac configd[15]: network configuration changed.
Why does this keep changing - will take a look at new Virgin Super Hub
it seems to have a short IP lease.
Feb 1 06:46:28: --- last message repeated 1 time ---
Feb 1 06:46:28 iMac mDNSResponder[16]: RegisterInterface: Frequent transitions for interface en0 (192.168.0.4)
Feb 1 06:46:29 iMac mDNSResponder[16]: DeregisterInterface: Frequent transitions for interface en0 (192.168.0.4)
Feb 1 06:46:29 iMac configd[15]: PMConnection mDNSResponder com.apple.powermanagement.applicationresponse.slowresponse 2179 ms
Feb 1 06:46:32 iMac configd[15]: network configuration changed.
Feb 1 06:46:32 iMac configd[15]: arp
clienttransmit(en0) failed, Network is down (50)
Feb 1 06:46:32 iMac configd[15]: bootp
sessiontransmit: bpf_write(en0) failed: Network is down (50)Feb 1 06:46:32 iMac configd[15]: DHCP en0: INIT-REBOOT transmit failed
Feb 1 06:46:32 iMac configd[15]: DHCP en0: ARP detect ROUTER failed, arp
clienttransmit(en0) failed, Network is down (50)Feb 1 07:40:29 iMac com.apple.launchd[1] (com.apple.newsyslog): Throttling respawn: Will start in 4 seconds
Feb 1 07:40:34 iMac ntpd[30]: bind() fd 25, family 30, port 123, scope 4, addr fe80::c62c:3ff:fe2e:f52e, in6
is_addrmulticast=0 flags=0x11 fails
: Can't assign requested addressFeb 1 07:40:34 iMac ntpd[30]: unable to create socket on en0 (29) for fe80::c62c:3ff:fe2e:f52e#123
Feb 1 07:40:42 iMac configd[15]: network configuration changed.
Feb 1 07:40:44 iMac ntpd[30]: time reset +1.346055 s
Wow! Is that right iMac lost over a whole second since the last network time, how often does that occur:
# grep 'time reset' system.log
Feb 1 02:14:01 iMac ntpd[30]: time reset +0.581813 s
Feb 1 03:08:08 iMac ntpd[30]: time reset +0.541685 s
Feb 1 04:02:27 iMac ntpd[30]: time reset +0.500688 s
Feb 1 04:56:36 iMac ntpd[30]: time reset +0.467584 s
Feb 1 05:51:02 iMac ntpd[30]: time reset +0.422586 s
Feb 1 07:40:44 iMac ntpd[30]: time reset +1.346055 s
Feb 1 07:49:51 iMac ntpd[30]: time reset +0.133139 s
Feb 1 07:40:44 iMac configd[15]: PMConnection IPConfiguration com.apple.powermanagement.applicationresponse.slowresponse 1642 ms
Feb 1 07:40:46 iMac configd[15]: PMConnection mDNSResponder com.apple.powermanagement.applicationresponse.slowresponse 3488 ms
Feb 1 07:40:50 iMac configd[15]: network configuration changed.
Feb 1 07:40:50 iMac configd[15]: arp
clienttransmit(en0) failed, Network is down (50)
Feb 1 07:40:50 iMac configd[15]: bootp
sessiontransmit: bpf_write(en0) failed: Network is down (50)
Feb 1 07:40:50 iMac configd[15]: DHCP en0: INIT-REBOOT transmit failedFeb 1 07:40:50 iMac configd[15]: DHCP en0: ARP detect ROUTER failed, arp
clienttransmit(en0) failed, Network is down (50)
Feb 1 07:49:39 iMac loginwindow[1316]: loginwindow SleepWakeCallback will power on, Currenttime:2/1/2011 7:49:39.009 AM - Waketime:2/1/2011 7:49:
39.000 AM = Deltatime:0.009039104
Feb 1 07:49:39 iMac loginwindow[1316]: askForPasswordBuiltIn after makekey, Currenttime:2/1/2011 7:49:39.618 AM - Waketime:2/1/2011 7:49:39.000 A
M = Deltatime:0.618426085
Feb 1 07:49:44 iMac ntpd[30]: sendto(17.72.255.12) (fd=24): Network is unreachable
Feb 1 07:49:44 iMac ntpd[30]: bind() fd 25, family 30, port 123, scope 4, addr fe80::c62c:3ff:fe2e:f52e, in6
is_addrmulticast=0 flags=0x11 fails
: Can't assign requested address
Feb 1 07:49:44 iMac ntpd[30]: unable to create socket on en0 (32) for fe80::c62c:3ff:fe2e:f52e#123
Feb 1 07:49:51 iMac ntpd[30]: time reset +0.133139 s
Feb 1 07:49:52 iMac configd[15]: network configuration changed.
Feb 1 07:49:52 iMac configd[15]: Sleep: Success - AC - Maintenance Sleep
Feb 1 07:49:52 iMac configd[15]: Wake: Success - AC - PWRB
Feb 1 07:49:52 iMac configd[15]: Hibernate StatisticsFeb 1 07:49:52 iMac kernel[0]: AFPSleepWakeHandler: waking up
Feb 1 07:50:09 iMac loginwindow[1316]: handleUnlockResult, Currenttime:2/1/2011 7:50:09.755 AM - Waketime:2/1/2011 7:49:39.000 AM = Deltatime:30.755416095
Thas was me waking the machine, I presume from ON/OFF button?
Feb 1 07:51:14 iMac sshd[2167]: USER_PROCESS: 2169 ttys001
Feb 1 07:53:04 iMac sudo[2191]: stacey : TTY=ttys001 ; PWD=/Users/stacey ; USER=root ; COMMAND=/bin/ksh
MBP was a little slow to awake - must wake it first next time and see
if I can connect before pressing power button. I have tried that before without success!
Feb 1 07:55:06 iMac sshd[2199]: USER_PROCESS: 2201 ttys002
Feb 1 07:55:24 iMac sudo[2206]: stacey : TTY=ttys002 ; PWD=/Users/stacey ; USER=root ; COMMAND=/bin/kshFeb 1 07:55:30 iMac com.apple.launchd[1] (com.apple.blued[512]): Exited: Terminated
At this point I uttered 'dtruss -a -n blued' but only got:
PID/THRD RELATIVE ELAPSD CPU SYSCALL(args) = return
512/0xd8a: 24097 1412 32 workq_kernreturn(0x1, 0x101004B90, 0x0) = 0 0
512/0xd8a: 24117 1665 15 kevent(0x3, 0x0, 0x0) = 1 0
512/0xd776: 48 1388 11 thread_selfid(0x7FFF704C4640, 0x0, 0xFFFFFFFF) = 55158 0
512/0xd776: 103 7 3 kevent(0x3, 0x100680DB0, 0x1) = 1 0
512/0xd776: 125 1343 7
_disablethreadsignal(0x1, 0x0, 0x0) = 0 0
^C
CALL COUNT
_disablethreadsignal 1
bsdthread_terminate 1
thread_selfid 1
workq_kernreturn 2
kevent 3
As I suspect bluetooth I start a new dtruss and kill blued, and POW - keyboard works 🙂
Feb 1 07:55:30 iMac blued[2207]: Apple Bluetooth daemon started
Feb 1 07:55:30 iMac loginwindow[1316]: askForPasswordBuiltIn after makekey
Feb 1 07:55:30 iMac loginwindow[1316]: in pam
smauthenticate(): Failed to determine Kerberos principal name.
Feb 1 07:55:31 iMac loginwindow[1316]: builtInAuthWindowDidResignKey
Feb 1 07:55:31 iMac loginwindow[1316]: handleUnlockResult
Feb 1 07:56:01 iMac loginwindow[1316]: no spins reported for this wake
Feb 1 07:56:01 iMac [0x0-0x142142].backupd-helper[2208]: Not starting Time Machine backup after wake - failed to resolve alias to backup volume
(Its that disk connected by USB cable - it keeps forgetting that too).
Feb 1 07:57:29 iMac fseventsd[46]: disk logger: failed to open output file /Volumes/iMac TM/.fseventsd/63657336dfdcb958 (No such file or directory). mount point /Volumes/iMac TM/.fseventsd
Feb 1 08:01:11 iMac com.apple.backupd-auto[2229]: Not starting scheduled Time Machine backup - time machine destination not resolvable.
Feb 1 08:02:36 iMac System Preferences[2236]: .scriptSuite warning for result type of command 'timedLoad' in suite 'SystemPreferences': the type NSNumber ('long') doesn't match the result Apple event code ('doub').
That's all for the messages....
What happened when launchd restarted blued.... you ask?
I have saved that to public dropbox
http://dl.dropbox.com/u/8800767/blued.dtruss
I've then started a background dtruss:
# nohup dtruss -a -n blued >/var/tmp/blued&
Will look and see when next this happens.