Running 4.5.4 for a few and did a parity check after upgrade, everything seemed fine. Noticed some strange noises coming from the box occasionally and thought that it was my iTunes drive, but from the log it seems the culprit is my parity drive:

 

[..]

Jun 26 00:20:18 Zaphod last message repeated 3 times

Jun 26 05:36:47 Zaphod last message repeated 3 times

Jun 26 05:36:52 Zaphod last message repeated 5 times

Jun 26 05:37:16 Zaphod afpd[2710]: server_child[1] 7000 exited 1

Jun 26 05:37:16 Zaphod afpd[7001]: ASIP session:548(5) from 192.168.0.2:49154(7)

Jun 26 05:37:16 Zaphod afpd[2710]: server_child[1] 7001 done

Jun 26 05:37:16 Zaphod afpd[7002]: ASIP session:548(5) from 192.168.0.2:49155(7)

Jun 26 05:37:16 Zaphod afpd[7002]: dhx login: cbehrens

Jun 26 05:37:16 Zaphod afpd[7002]: login cbehrens (uid 1000, gid 100) AFP3.1

Jun 26 05:37:16 Zaphod afpd[7002]: Setting uid/gid to 1000/100

Jun 26 05:37:16 Zaphod afpd[7002]: CNID DB initialized using Sleepycat Software: Berkeley DB 4.4.20: (January 10, 2006)

Jun 26 05:37:22 Zaphod afpd[7002]: ipc_write: command: 2, pid: 7002, msglen: 24

Jun 26 05:37:22 Zaphod afpd[2710]: ipc_read: command: 2, pid: 7002, len: 24

Jun 26 05:37:22 Zaphod afpd[2710]: Setting clientid (len 16) for 7002, boottime 4C25F47C

Jun 26 05:37:22 Zaphod afpd[2710]: ipc_get_session: len: 24, idlen 16, time 4c25f47c

Jun 26 05:37:22 Zaphod afpd[2710]: server_child[1] 7004 exited 1

Jun 26 05:37:22 Zaphod afpd[7005]: ASIP session:548(5) from 192.168.0.2:49160(7)

Jun 26 05:37:22 Zaphod afpd[2710]: server_child[1] 7005 done

Jun 26 05:37:23 Zaphod afpd[2710]: server_child[1] 7006 exited 1

Jun 26 05:37:23 Zaphod afpd[7007]: ASIP session:548(5) from 192.168.0.2:49162(7)

Jun 26 05:37:23 Zaphod afpd[2710]: server_child[1] 7007 done

Jun 26 05:37:55 Zaphod avahi-daemon[2722]: Invalid query packet.

Jun 26 05:44:30 Zaphod last message repeated 3 times

Jun 26 05:44:30 Zaphod last message repeated 2 times

Jun 26 05:51:58 Zaphod afpd[2710]: server_child[1] 7016 exited 1

Jun 26 05:51:58 Zaphod afpd[7017]: ASIP session:548(5) from 192.168.0.2:50611(7)

Jun 26 05:51:58 Zaphod afpd[2710]: server_child[1] 7017 done

Jun 26 05:51:58 Zaphod afpd[7002]: Setting uid/gid to 1000/100

Jun 26 05:52:10 Zaphod last message repeated 2 times

Jun 26 05:52:17 Zaphod afpd[7002]: ipc_write: command: 2, pid: 7002, msglen: 24

Jun 26 05:52:17 Zaphod afpd[2710]: ipc_read: command: 2, pid: 7002, len: 24

Jun 26 05:52:17 Zaphod afpd[2710]: Setting clientid (len 16) for 7002, boottime 4C25F47C

Jun 26 05:52:17 Zaphod afpd[2710]: ipc_get_session: len: 24, idlen 16, time 4c25f47c

Jun 26 05:52:17 Zaphod afpd[2710]: server_child[1] 7020 exited 1

Jun 26 05:52:17 Zaphod afpd[7021]: ASIP session:548(5) from 192.168.0.2:50615(7)

Jun 26 05:52:17 Zaphod afpd[2710]: server_child[1] 7021 done

Jun 26 05:52:17 Zaphod afpd[2710]: server_child[1] 7022 exited 1

Jun 26 05:52:17 Zaphod afpd[7023]: ASIP session:548(5) from 192.168.0.2:50617(7)

Jun 26 05:52:17 Zaphod afpd[2710]: server_child[1] 7023 done

Jun 26 05:52:17 Zaphod afpd[2710]: server_child[1] 7024 exited 1

Jun 26 05:52:17 Zaphod afpd[7025]: ASIP session:548(5) from 192.168.0.2:50619(7)

Jun 26 05:52:17 Zaphod afpd[2710]: server_child[1] 7025 done

Jun 26 05:52:17 Zaphod afpd[2710]: server_child[1] 7026 exited 1

Jun 26 05:52:17 Zaphod afpd[7027]: ASIP session:548(5) from 192.168.0.2:50621(7)

Jun 26 05:52:17 Zaphod afpd[2710]: server_child[1] 7027 done

Jun 26 05:52:36 Zaphod kernel: ata3.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0

Jun 26 05:52:36 Zaphod kernel: ata3.00: irq_stat 0x40000001

Jun 26 05:52:36 Zaphod kernel: ata3.00: failed command: READ DMA

Jun 26 05:52:36 Zaphod kernel: ata3.00: cmd c8/00:08:bf:b3:03/00:00:00:00:00/ec tag 0 dma 4096 in

Jun 26 05:52:36 Zaphod kernel:          res 51/40:00:c0:b3:03/00:00:0c:00:00/ec Emask 0x9 (media error)

Jun 26 05:52:36 Zaphod kernel: ata3.00: status: { DRDY ERR }

Jun 26 05:52:36 Zaphod kernel: ata3.00: error: { UNC }

Jun 26 05:52:36 Zaphod kernel: ata3.00: configured for UDMA/133

Jun 26 05:52:36 Zaphod kernel: ata3: EH complete

 

[..] About a dozen more media errors

 

Jun 26 05:56:44 Zaphod kernel: ata3.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0

Jun 26 05:56:44 Zaphod kernel: ata3.00: irq_stat 0x40000001

Jun 26 05:56:44 Zaphod kernel: ata3.00: failed command: READ DMA EXT

Jun 26 05:56:44 Zaphod kernel: ata3.00: cmd 25/00:08:a7:37:75/00:03:0e:00:00/e0 tag 0 dma 397312 in

Jun 26 05:56:44 Zaphod kernel:          res 51/40:f7:a8:37:75/00:02:0e:00:00/e0 Emask 0x9 (media error)

Jun 26 05:56:44 Zaphod kernel: ata3.00: status: { DRDY ERR }

Jun 26 05:56:44 Zaphod kernel: ata3.00: error: { UNC }

Jun 26 05:56:44 Zaphod kernel: ata3.00: configured for UDMA/133

Jun 26 05:56:44 Zaphod kernel: sd 3:0:0:0: [sdb] Unhandled sense code

Jun 26 05:56:44 Zaphod kernel: sd 3:0:0:0: [sdb] Result: hostbyte=0x00 driverbyte=0x08

Jun 26 05:56:44 Zaphod kernel: sd 3:0:0:0: [sdb] Sense Key : 0x3 [current] [descriptor]

Jun 26 05:56:44 Zaphod kernel: Descriptor sense data with sense descriptors (in hex):

Jun 26 05:56:44 Zaphod kernel:         72 03 11 04 00 00 00 0c 00 0a 80 00 00 00 00 00

Jun 26 05:56:44 Zaphod kernel:         0e 75 37 a8

Jun 26 05:56:44 Zaphod kernel: sd 3:0:0:0: [sdb] ASC=0x11 ASCQ=0x4

Jun 26 05:56:44 Zaphod kernel: sd 3:0:0:0: [sdb] CDB: cdb[0]=0x28: 28 00 0e 75 37 a7 00 03 08 00

Jun 26 05:56:44 Zaphod kernel: end_request: I/O error, dev sdb, sector 242562984

Jun 26 05:56:44 Zaphod kernel: ata3: EH complete

Jun 26 05:56:44 Zaphod kernel: md: disk0 read error

Jun 26 05:56:44 Zaphod kernel: handle_stripe read error: 242562920/0, count: 1

Jun 26 05:56:44 Zaphod kernel: md: disk0 read error

Jun 26 05:56:44 Zaphod kernel: handle_stripe read error: 242562928/0, count: 1

[..] Tons more of the same error message

Jun 26 05:56:44 Zaphod kernel: md: disk0 read error

Jun 26 05:56:44 Zaphod kernel: handle_stripe read error: 242563688/0, count: 1

Jun 26 05:56:47 Zaphod kernel: ata3.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0

Jun 26 05:56:47 Zaphod kernel: ata3.00: irq_stat 0x40000001

Jun 26 05:56:47 Zaphod kernel: ata3.00: failed command: READ DMA

Jun 26 05:56:47 Zaphod kernel: ata3.00: cmd c8/00:08:af:3a:75/00:00:00:00:00/ee tag 0 dma 4096 in

Jun 26 05:56:47 Zaphod kernel:          res 51/40:00:b1:3a:75/00:00:0e:00:00/ee Emask 0x9 (media error)

Jun 26 05:56:47 Zaphod kernel: ata3.00: status: { DRDY ERR }

Jun 26 05:56:47 Zaphod kernel: ata3.00: error: { UNC }

Jun 26 05:56:47 Zaphod kernel: ata3.00: configured for UDMA/133

Jun 26 05:56:47 Zaphod kernel: ata3: EH complete

Jun 26 05:56:52 Zaphod kernel: ata3.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0

Jun 26 05:56:52 Zaphod kernel: ata3.00: irq_stat 0x40000001

Jun 26 05:56:52 Zaphod kernel: ata3.00: failed command: READ DMA EXT

Jun 26 05:56:52 Zaphod kernel: ata3.00: cmd 25/00:50:bf:3a:75/00:03:0e:00:00/e0 tag 0 dma 434176 in

Jun 26 05:56:52 Zaphod kernel:          res 51/40:2f:d8:3a:75/00:03:0e:00:00/e0 Emask 0x9 (media error)

Jun 26 05:56:52 Zaphod kernel: ata3.00: status: { DRDY ERR }

Jun 26 05:56:52 Zaphod kernel: ata3.00: error: { UNC }

Jun 26 05:56:52 Zaphod kernel: ata3.00: configured for UDMA/133

Jun 26 05:56:52 Zaphod kernel: ata3: EH complete

Jun 26 05:56:58 Zaphod kernel: ata3.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0

Jun 26 05:56:58 Zaphod kernel: ata3.00: irq_stat 0x40000001

Jun 26 05:56:58 Zaphod kernel: ata3.00: failed command: READ DMA EXT

Jun 26 05:56:58 Zaphod kernel: ata3.00: cmd 25/00:50:bf:3a:75/00:03:0e:00:00/e0 tag 0 dma 434176 in

Jun 26 05:56:58 Zaphod kernel:          res 51/40:3f:c7:3a:75/00:03:0e:00:00/e0 Emask 0x9 (media error)

Jun 26 05:56:58 Zaphod kernel: ata3.00: status: { DRDY ERR }

Jun 26 05:56:58 Zaphod kernel: ata3.00: error: { UNC }

Jun 26 05:56:58 Zaphod kernel: ata3.00: configured for UDMA/133

Jun 26 05:56:58 Zaphod kernel: ata3: EH complete

Jun 26 05:57:06 Zaphod kernel: ata3.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0

Jun 26 05:57:06 Zaphod kernel: ata3.00: irq_stat 0x40000001

Jun 26 05:57:06 Zaphod kernel: ata3.00: failed command: READ DMA EXT

Jun 26 05:57:06 Zaphod kernel: ata3.00: cmd 25/00:50:bf:3a:75/00:03:0e:00:00/e0 tag 0 dma 434176 in

Jun 26 05:57:06 Zaphod kernel:          res 51/40:af:55:3b:75/00:02:0e:00:00/e0 Emask 0x9 (media error)

Jun 26 05:57:06 Zaphod kernel: ata3.00: status: { DRDY ERR }

Jun 26 05:57:06 Zaphod kernel: ata3.00: error: { UNC }

Jun 26 05:57:06 Zaphod kernel: ata3.00: configured for UDMA/133

Jun 26 05:57:06 Zaphod kernel: ata3: EH complete

Jun 26 05:57:13 Zaphod kernel: ata3.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0

Jun 26 05:57:13 Zaphod kernel: ata3.00: irq_stat 0x40000001

Jun 26 05:57:13 Zaphod kernel: ata3.00: failed command: READ DMA EXT

Jun 26 05:57:13 Zaphod kernel: ata3.00: cmd 25/00:50:bf:3a:75/00:03:0e:00:00/e0 tag 0 dma 434176 in

Jun 26 05:57:13 Zaphod kernel:          res 51/40:bf:4d:3b:75/00:02:0e:00:00/e0 Emask 0x9 (media error)

Jun 26 05:57:13 Zaphod kernel: ata3.00: status: { DRDY ERR }

Jun 26 05:57:13 Zaphod kernel: ata3.00: error: { UNC }

Jun 26 05:57:13 Zaphod kernel: ata3.00: configured for UDMA/133

Jun 26 05:57:13 Zaphod kernel: ata3: EH complete

Jun 26 05:57:17 Zaphod afpd[7029]: ASIP session:548(5) from 192.168.0.2:50816(7)

[..]

 

Later this morning I also got these kind of messages; does that mean there is a problem with that data drive as well? This is used in a purely Mac environment, i.e. AFP shares:

 

[..]

Jun 26 06:38:30 Zaphod avahi-daemon[2722]: Invalid query packet.

Jun 26 06:43:16 Zaphod last message repeated 3 times

Jun 26 06:43:16 Zaphod last message repeated 2 times

Jun 26 06:46:52 Zaphod afpd[7078]: cnid_lookup: Unable to get CNID did 0x17000000, name 61: DB_PAGE_NOTFOUND: Requested page not found

Jun 26 06:46:52 Zaphod afpd[7078]: cnid_add: Failed to add CNID for 61 to database using hint 124518: DB_PAGE_NOTFOUND: Requested page not found

Jun 26 06:46:52 Zaphod afpd[7078]: cnid_lookup: Unable to get CNID did 0x17000000, name 61: DB_PAGE_NOTFOUND: Requested page not found

Jun 26 06:46:52 Zaphod afpd[7078]: cnid_add: Failed to add CNID for 61 to database using hint 124519: DB_PAGE_NOTFOUND: Requested page not found

Jun 26 06:46:52 Zaphod afpd[7078]: cnid_lookup: Unable to get CNID did 0x17000000, name 61: DB_PAGE_NOTFOUND: Requested page not found

Jun 26 06:46:52 Zaphod afpd[7078]: cnid_add: Failed to add CNID for 61 to database using hint 124520: DB_PAGE_NOTFOUND: Requested page not found

Jun 26 06:46:52 Zaphod afpd[7078]: cnid_lookup: Unable to get CNID did 0x17000000, name 61: DB_PAGE_NOTFOUND: Requested page not found

Jun 26 06:46:52 Zaphod afpd[7078]: cnid_add: Failed to add CNID for 61 to database using hint 124521: DB_PAGE_NOTFOUND: Requested page not found

Jun 26 06:47:04 Zaphod afpd[7078]: cnid_lookup: Unable to get CNID did 0x17000000, name 61: DB_RUNRECOVERY: Fatal error, run database recovery

Jun 26 06:47:04 Zaphod afpd[7078]: get_cnid: Unable to get a cursor: DB_RUNRECOVERY: Fatal error, run database recovery

[..]

Jun 26 07:37:31 Zaphod afpd[7118]: Setting uid/gid to 1000/100

Jun 26 07:37:31 Zaphod afpd[7118]: CNID DB initialized using Sleepycat Software: Berkeley DB 4.4.20: (January 10, 2006)

Jun 26 07:37:32 Zaphod afpd[7118]: cnid_open: dbenv->open (rw) of /mnt/disk1/.AppleDB failed: DB_RUNRECOVERY: Fatal error, run database recovery

Jun 26 07:37:32 Zaphod afpd[7118]: cnid_open: CATASTROPHIC ERROR opening database environment /mnt/disk1/.AppleDB.  Run db_recovery -c immediately

Jun 26 07:37:32 Zaphod afpd[7118]: Cannot open CNID db at [/mnt/disk1].

Jun 26 07:37:32 Zaphod afpd[7118]: Fatal error: cannot open CNID or invalid CNID backend for /mnt/disk1: cdb

[..]

 

So it seems to be clear that I have to replace the parity drive, what about my disk1? Anything to be done for that drive?

 

Thanks everyone,

 

-Christian

The "media" errors are sectors that were un-readable on the parity drive.  They do not indicate the drive has failed.  Drives typically have several thousand spare sectors and when an un-readable one is found the drive marks it for re-allocation when it is next written.

 

To learn the health of the drive you need to run a smartctl report on it.  Otherwise, you'll be replacing a perfectly good drive.

 

Interestingly, after shutting down the server yesterday and booting it up today again, none of the read errors appeared in the log again, the only error is that apparently my Apple user DB is shut (the CNID error in the log I posted). Guess I'll have to recreate the user part of the netatalk install. Will AFP (netatalk) support be somewhat improved in the next big release?

 

I also ran smartctl as Joe suggested, and all seems to be fine?!? The strange part is that one of the drives clearly made some unusual sounds yesterday, but today so far it looks like everything is hunky dory...

 

And finally, I never had a beta version, I started out with 4.5.3, then a few weeks back went to 4.5.4, but I didn't have smartctl anywhere on my system. From the Wiki it sounded like it should be there by default.

 

-Christian

It is in /usr/sbin

 

type

which smartctl

and it will tell you if it is in the search path

 

Type

ls -l /usr/sbin/smartctl

and you'll see if it is there

Heh, you're right, it was there. Not sure how I screwed up my "find" command, because I didn't see it . Newer than the one I downloaded, too.

 

For the CNID messages, all I had to do was remove the files on disk1 in the .AppleDB directory, stop and restart the afpd daemon, and they were re-generated, then I was able to log in and it seems like it's working normally again.

 

I'm still wary about the sounds that were coming from the box, shortly before all those error messages started appearing in the log. But right now, all seems fine. Fingers crossed...

 

Thanks for listening! 

 

-Christian