1 Reply Latest reply: Jun 4, 2013 8:44 AM by Scot Ohl
Arty Admin Level 1 Level 1 (0 points)
I'm using an Xserve as a file server for a small workgroup . It has a Raid 1 set which is being backed up via Time Machine to an attached disk array.

Whenever Time Machine runs (every hour), I get two notifications from Server Monitor that the drive status has changed:
*Reason(s) for notification:*
*Drive status changed*

The timestamps on the notifications coincide with these messages in system.log

Feb 2 11:28:05 ciesaxserve2 Server Monitor[854]: * _NSSocket.m:243 read() failed; socket=0x197060 error=(NSPOSIXErrorDomain,61)
Feb 2 11:28:05 ciesaxserve2 Server Monitor[854]: * _NSSocket.m:243 write() failed; socket=0x197060 error=(NSPOSIXErrorDomain,61)
Feb 2 11:28:05 ciesaxserve2 Server Monitor[854]: * _NSSocket.m:243 read() failed; socket=0x2090e90 error=(NSPOSIXErrorDomain,61)
Feb 2 11:28:05 ciesaxserve2 Server Monitor[854]: * _NSSocket.m:243 write() failed; socket=0x2090e90 error=(NSPOSIXErrorDomain,61)

and:
Feb 2 11:28:55 ciesaxserve2 servermgrd[78]: servermgr_backup: TimeMachinePostBackupHook called.
Feb 2 11:28:55 ciesaxserve2 servermgrd[78]: servermgr_backup: TimeMachinePostBackupHook done.


The notifications simply report that all is normal, and the number of available drives goes from 6, to 7, back to 6. Something to do with making the backup volume available, I presume.

I would like to disable these specific messages. I realize I can disable all messages from server monitor regarding disk statuses, but then I would be turning off messages about failures and actual problems.

Is there a config I can edit which will only alert me to actual problems? I'd like to stop getting 48 emails each day; reduce the noise and increase the signal.

Mac Mini through Xserve, Mac OS X (10.6.6)
  • Scot Ohl Level 1 Level 1 (0 points)

    I know this post is old but this has recently cropped up for me. I have been backing up with Time Machine for months without a single alert. It started happening after I replaced the failed battery on my RAID card. A coincidence...however the prolonged down time surely caused an SMC (and perhaps PRAM) reset which I assume triggered the change in behavior.

     

    I've pinned it down to Time Machine backing up service settings, in particular the Open Directory archive. Time Machine backs up all the service data independently from the rest of the data on your server startup volume.

     

    http://support.apple.com/kb/ht5139

     

    You can see this data in Terminal.

     

    serveradmin$ cd /Volumes/[YourBackupVolume]/Backups.backupdb/[YourServerName]/Latest/[YourBootVolume]/.ServerBackups

    serveradmin$ ls -al

    total 16

    drwxr-xr-x@  2 root  admin    68  4 Jun 14:44 (null)

    drwxr-xr-x@ 14 root  admin   476  4 Jun 14:44 .

    drwxrwxr-t@ 43 root  admin  1462  4 Jun 14:43 ..

    -rw-r--r--@  1 root  admin    37  4 Jun 14:44 .serverBackupSignature

    drwxr-xr-x@  2 root  admin    68  4 Jun 14:44 addressBookServer

    drwxr-xr-x@  2 root  admin    68  4 Jun 14:44 calendarServer

    drwxr-xr-x@  5 root  admin   170  4 Jun 14:44 iChatServer

    drwxr-xr-x@  6 root  admin   204  4 Jun 14:44 mailServer

    -rw-r--r--@  1 root  admin  3826  4 Jun 14:44 master.browse.plist

    drwxr-xr-x@  4 root  admin   136  4 Jun 14:43 openDirectory

    drwxr-xr-x@ 61 root  admin  2074  4 Jun 14:44 serverSettings

    drwxr-xr-x@ 23 root  admin   782  4 Jun 14:44 sharePoints

    drwxr-xr-x@  8 root  admin   272  4 Jun 14:44 webServer

    drwxr-xr-x@  2 root  admin    68  4 Jun 14:44 wikiServer

     

    If you take a look inside the openDirectory folder you should see this:

     

    serveradmin$ cd openDirectory

    serveradmin$ ls -al

    total 81936

    drwxr-xr-x@  4 root  admin       136  4 Jun 15:32 .

    drwxr-xr-x@ 14 root  admin       476  4 Jun 15:33 ..

    -rw-rw----@  1 root  admin  41947136  4 Jun 15:32 ServerBackup_OpenDirectoryMaster.sparseimage

    -rw-r--r--@  1 root  admin       249  4 Jun 15:32 openDirectory.browse.plist

     

    The ServerBackup_OpenDirectoryMaster.sparseimage contains an archive of your Open Directory database like the one you create from Server Admin. The only difference is that it appears to be unencrypted. This is a bit worrying since Snow Leopard, as far as I know, does not have an option to encrypt your Time Machine backup. This image seems to invisibly mount whenever a Time Machine backup is triggered. This can be verified by checking /private/var/log/system.log and filtering for backup

     

    serveradmin$ tail -b 100 /var/log/system.log | grep backup

    Jun  4 16:00:56 yourservername com.apple.backupd[25117]: Starting standard backup

    Jun  4 16:00:56 yourservername com.apple.backupd[25117]: Backing up to: /Volumes/YourBackupVolume/Backups.backupdb

    Jun  4 16:00:56 yourservername servermgrd[75]: servermgr_backup: TimeMachinePreBackupHook called.

    Jun  4 16:09:26 yourservername servermgrd[75]: servermgr_backup: TimeMachinePreBackupHook done.

    Jun  4 16:09:44 yourservername com.apple.backupd[25117]: No pre-backup thinning needed: 4.60 GB requested (including padding), 8.40 GB available

    Jun  4 16:10:14 yourservername com.apple.backupd[25117]: Copied 744 files (364.4 MB) from volume YourBootDrive.

    Jun  4 16:10:14 yourservername com.apple.backupd[25117]: No pre-backup thinning needed: 4.09 GB requested (including padding), 8.04 GB available

    Jun  4 16:10:17 yourservername com.apple.backupd[25117]: Copied 87 files (877 KB) from volume YourBootDrive.

    Jun  4 16:10:18 yourservername servermgrd[75]: servermgr_backup: TimeMachinePostBackupHook called.

    Jun  4 16:10:18 yourservername servermgrd[75]: servermgr_backup: TimeMachinePostBackupHook done.

    Jun  4 16:10:18 yourservername com.apple.backupd[25117]: Starting post-backup thinning

    Jun  4 16:10:29 yourservername com.apple.backupd[25117]: Deleted backup /Volumes/YourBackupVolume/Backups.backupdb/yourservername/2013-06-03-155910: 8.40 GB now available

    Jun  4 16:10:29 yourservername com.apple.backupd[25117]: Post-back up thinning complete: 1 expired backups removed

    Jun  4 16:10:29 yourservername com.apple.backupd[25117]: Backup completed successfully.

     

    You can see at 16:00:56 Server Manager got a call from Time Machine to start the services backup and finished at 16:09:26. Open Directory would have been backed up during that process. Take a look at /private/var/log/hwmond.log


    serveradmin$ tail /private/var/log/hwmond.log

    Tue Jun  4 16:08:36 BST 2013 - Number of drives change from 4 to 5.

    Tue Jun  4 16:08:48 BST 2013 - Number of drives change from 5 to 4.

     

    You'll see that both drive change warnings from Server Monitor occured just before the services backup completed. You can also use the sudo diskarbitrationd -d command along with tail /private/var/log/diskarbitrationd.log in another terminal window, trigger a Time Machine backup manually and watch this disk image mount during the backup process. Compare the mount times with the above logs to see if they all match up.

     

    Although I have discovered the cause (which thankfully seems harmless) I have not discovered a way to stop it from generating pointless alerts. I'll post here if I figure it out. I am in the process of upgrading all of my servers to Mountain Lion so it may be a moot point. I am hopeful this information may help someone out there even though it is thoroughly out of date.

     

    Scot