Current Mood: Here bugs…

This is more for my reference than a real post, but I’m doing sod all with the blog and typing this out will help me think it through.

When a hard drive errors the messages can be… cryptic, to say the least.  So lets interpret a few of them.

Other error? How very helpful.

The first port of call is your raid card’s status command, megasasctl is a good example.  Some times it will be helpful and say “Bazzilion media errors!!1″ or something with a similar meaning.  Other  times, not so much:

a0e252s1 558GiB a0d1 online errs: media:0 other:42

This tells us that the drive in slot 1 of adaptor 0 has suffered no media errors, but has suffered 42 “other” errors.  How wonderfully helpful.
Media errors here are simple enough.  Replace the drive and surface scan the faulty one.  ”Other” errors require more digging.

Sense key messages

One common message type looks something like this

04/18/12 15:01:58: EVT#01115-04/18/12 15:01:58: 113=Unexpected sense: PD 05(e0xfc/s1) Path 4433221101000000, CDB: 28 00 2c 9e c7 30 00 00 d0 00, Sense: b/00/00
04/18/12 15:01:58: Raw Sense for PD 5: 70 00 0b 00 00 00 00 0a 00 00 00 00 00 00 00 00 00 00

You can obtain similar messages from dmesg, but this one comes direct from the raid card’s logs. If you’re using a megaraid sas card such from the 9240/9260/9280 range,  megacli -FwTermLog -Dsply -a0is your friend. To explain the cryptic parts..

• PD 05(e0xfc/s1) = Physical Disk 05, enclosure 0xFC (that’s 252), slot 1.  Since this chassis has a multilane connection, it groups drives in to sets of 4… 0-3, 4-7, 8-11, 12-15 if it’s a 16 bay.
  It’s telling us disk 5 for slot 1 because the cables aren’t connected in order on both ends.  The enclosure ID does mean something, it refers to which physical box they’re in, but in this case it’s actually redundant since they’re all on the same back plane.
• Path 4433221101000000 = this is the SAS Address of the drive
• CDB: 28 00 2c 9e c7 30 00 00 d0 00 = Command Descriptor Block.  This is the request that the Sense Key relates to.
  The first byte, 28, is the main command.  Here we are dealing with an extended 10 byte read instruction that provides an LBA address to cope with drives up to 2TiB.
  It’s a 00 d0 read request from address 2c 9e c7 30, not super helpful, but it may hint at a problem.
  To make sense of the string you find the first byte on the table at http://en.wikipedia.org/wiki/SCSI_command#List_of_SCSI_commands and check out what extra data there is.
• Sense: b/00/00 = This is the Sense Key.  This is horribly cryptic.  The first is the type of error, the second two narrow down the actual fault.  See http://en.wikipedia.org/wiki/Key_Code_Qualifier for a pretty good list. In this case, b means an Aborted Command, the 00/00 means it doesn’t want to be more specific.
• Raw Sense = This is largely irrelevant, but it’s covered in detail at http://en.wikipedia.org/wiki/SCSI_Request_Sense_Command in addition to further expounding on the meaning of the first part of the Sense Key.
  The 70 appears to mean it is non-scsi current errors in fixed format.
  The 0b is 0 for the first 3 fields in byte 2 of the response and the first part of the sense key above.
  The 0a in byte 7 tells us how long the rest of the message is.. 0xa, so 10 bytes more.
  All the other fields are zeros … mostly indicating a lack of more information.

So we know that it’s an aborted read command with no special reasons.

Physical Drive information

Just a quick side note actually.
You probably want to grab a copy of the drive information at this point.  Good options for this include megacli -pdinfo -physdrv’[252:1]‘ -a0 for the MegaRAID cards mentioned above, hdparm -i /dev/sdc if it’s directly connected (doesn’t work if the drive in question is a raid logical drive), or perhaps smartctl -a /dev/sdc as a fall back.

Mainly you want the drive serial number of verifying the correct drive is being replaced, but it may possibly tell you something you didn’t already know.  Doesn’t this time, but ah well.
Oh, and since it’s worth mentioning… megacli doesn’t make the serial quite as obvious as one would like.  The line you need is the one labelled “Inquiry Data”… this, depending on what the drive actually has set, will contain some combination of the drive maker, the model number, the serial number, and the hardware revision.  Not firmware revision though, that is listed a few lines above. This particular drive is a 600GB raptor, so it looks something like this (I’ve redacted it, just on the off chance there is something that could be done with it…)

 Inquiry Data:      WD-WXL1C10*****WDC WD6000HLHX-01J****                  04.05G04

The serial number for this drive is the bit starting at WXL and ending with the bit I’ve replaced with asterisks.  ”WD-” and “WDC” are vendor references (Western Digital Corporation, obviously) and the WD6000HLHX is the model number.  The bit starting 01J is a hardware revision.  Not entirely sure what the 04.05G04 bit is, that string doesn’t show up anywhere on the label.

Linux Kernel errors

Usually drive errors are accompanied by errors from the storage layer… this is no exception:

[403034.114416] sd 4:2:1:0: [sdc] Unhandled error code
[403034.114422] sd 4:2:1:0: [sdc] Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK
[403034.114427] sd 4:2:1:0: [sdc] CDB: Read(10): 28 00 2c 9e c7 30 00 00 f8 00
[403034.114437] end_request: I/O error, dev sdc, sector 748603184

This actually tells us nothing of use, but lets break it down anyway.

• Event occured 403034 seconds after boot up.  Very close timestamps are a good indication of linked events. even if the text of the message doesn’t state such.
• sd 4:2:1:0 = This is actually the hardware path to the scsi device.  Only important thing about it is the 4… that means it’s on PCI ID 4.
• hostbyte=DID_ERROR = Defined in linux/include/scsi/scsi.h the hostbyte is the response from the low level kernel driver. In this case it’s an internal error.
  Since this error has come from megaraid_sas we can make an educated guess that it came from one of the two references in that driver.  It’s possible it came from elsewhere, but we’ll focus there for the moment.
  Both occur when a read or write attempt is made to a logical drive, the driver will emit DID_ERROR when doing so during array init, when scsi io results in a failure, and when the firmware produces a status it doesn’t understand. In this context I’m going to go with the IO Failure option.
• driverbyte=DRIVER_OK = Also defined in linux/include/scsi/scsi.h the driverbyte is the mid level kernel driver status.  Essentially one up from the hostbyte.  Not much to see here.
• CDB means exactly the same thing as the one we got from the raid card errors above.  The only difference is that this is being fed to the raid card.  The message is still a 28 extended read command, still for the same location, but it requested slightly more data.
• end_request: I/O error = quite possible the most unhelpful error message ever.  Interpret it literally.  The request ended because of an I/O error of some type.  This could be anything from a hammer to the drive to cutting the cables all the way up to a bug in the kernel’s adapter driver.

Summary

So class, what have we learnt?  That the drive stubbornly refused to read that one sector for no readily apparent reason.  Isn’t that nice of it.
We also learnt that the errors that look to have clear meanings actually mean little to nothing and the strings of unimportant looking numbers tell you lots.

From these messages I’m willing to accept the raid card’s statement that it was the drives fault, but it clearly isn’t a hardware fault.  There are quite a list of specifically stated sense codes to cover hardware failure.

Next stop will likely be hard drive firmware.  Again.  Urg.

I’m quite certain this will be a series “To Be Continued”

Addendum:

A full drive read test failed with a slew of b/00/00 senses and finally a 3/11/00 for CDB 28 00 2c 9e c6 e0 00 01 00 00.
Some of interesting messages to look at here:

• 04/18/12 23:40:56: EVT#01174-04/18/12 23:40:56: 113=Unexpected sense: PD 05(e0xfc/s1) Path 4433221101000000, CDB: 28 00 2c 9e c6 e0 00 01 00 00, Sense: 3/11/00

  Per the page I linked above… that’s a Medium Error – unrecovered read error.  You’ll notice that although the LBA is close, it is not the same. 2c 9e c6 e0 here and 2c 9e c7 30 before.  Since the requests are different sizes, the faulty address is going to be somewhere in the overlap.

• 04/18/12 23:40:56: Raw Sense for PD 5: f0 00 03 2c 9e c7 a5 0a 00 00 00 00 11 00 00 00 00 00

  This the f0 from the first byte deserves note.  Looking back to the Sense Response  you can see that the first bit of the first byte is actually a flag that states if the data is SCSI compliant.  The b/00/00 response had the first byte 0111 000 and so wasn’t compliant, where as this 3/11/00 has 1111 0000, same response code (Current error in fixed format) but with SCSI compatible data.
  Otherwise the response follows the same pattern as before.  70 for the response code, the sense code is in byte 2 and the additional data is visible later on, still remaining length 0x0a.  Helpfully this tells you the actual location of the fault in the information field.  2c 9e c7 a5, just inside the previous request.

• 04/18/12 23:40:56: DEV_REC:Medium Error DevId[5] devHandle c RDM=80875400 retires=5

  Not sure what RDM is… could be interesting to know.

•  04/18/12 23:40:56: MedErr is for: cmdId=b, ld=1, src=1, cmd=1, lba=2c9ec6e0, cnt=100, rmwOp=0

  Note the LBA here is the one requested…

•  04/18/12 23:40:56: ErrLBAOffset (c5) LBA(2c9ec6e0) BadLba=2c9ec7a5
  04/18/12 23:40:56: Read MED ERR!!! ErrLBA(c5) LBA(2c9ec6e0) TotalBlks (100)

  While these lines gives us both the request start and the actual bad address.  They even helpfully provided the offset of the bad block within the request.

• 04/18/12 23:40:56: MPTCMD: Issue Read ME Recovery RDM=80875400 Cmd 1 Flags 60000 Rec State 17 Retry 1
  04/18/12 23:40:56: DM_REC:Completing recovery SM DevId 5 pRdm 80875400 CQC 0 WQC 0

  There’s that RDM again.  I’ve not found anything about these messages.  Please leave a comment if you have any leads. RDM, CQC and WQC must have specific meanings, but the only hit I’ve found is that RDM might be Resource Description Message.

• 04/18/12 23:40:56: EVT#01175-04/18/12 23:40:56: 111=Unrecoverable medium error during recovery on PD 05(e0xfc/s1) at 2c9ec7a5

  I don’t like those words…. Unrecoverable medium error.  Time for a new disk me thinks.

• 04/18/12 23:40:56: ldbbmIssue: pd=5 pdLba=2c9ec7a5 ld=1 ldLba=2c9ec7a5

  One thing you’ll find about hard drive errors… they’re very repetitive.  One thing that is worth mentioning, this lists the LBA in terms of the physical disk and the logical disk it is part of.

• 04/18/12 23:40:56: EVT#01176-04/18/12 23:40:56: 271=Uncorrectable medium error logged for VD 01/1 at 2c9ec7a5 (on PD 05(e0xfc/s1) at 2c9ec7a5)
  04/18/12 23:40:56: GroupCmds: Fail cmd c=c0584260 ld=1 start_block=2c9ec6e0 num_blocks=100 cmd=1

  After this there are a few more assorted variations of the second of these two lines as it does various different read sizes around this area.  Remember, all numbers are in hex.

• 04/18/12 23:52:02: ldbbmListClear: clearing medErrlba=2c9ec7a5 for ld=1
  04/18/12 23:52:02: EVT#01177-04/18/12 23:52:02: 272=VD medium error corrected on VD 01/1 at 2c9ec7a5
  04/18/12 23:52:02: EVT#01178-04/18/12 23:52:02: 335=VD bad block table on VD 01/1 is cleared

  Hmmm, I’m not sure if I entirely believe it … we’ll see what the scan says.

In dmesg there is the following, most of which you should now be able to understand:

[10408.863522] sd 4:2:1:0: [sdc] Unhandled error code
[10408.863526] sd 4:2:1:0: [sdc] Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK
[10408.863531] sd 4:2:1:0: [sdc] CDB: Read(10): 28 00 2c 9e c6 e0 00 01 00 00
[10408.863540] end_request: I/O error, dev sdc, sector 748603104
[10408.863560] quiet_error: 48 callbacks suppressed
[10408.863562] Buffer I/O error on device sdc, logical block 93575388
[10408.863582] Buffer I/O error on device sdc, logical block 93575389
[10408.863599] Buffer I/O error on device sdc, logical block 93575390
[10408.863615] Buffer I/O error on device sdc, logical block 93575391
[10408.863631] Buffer I/O error on device sdc, logical block 93575392
[10408.863648] Buffer I/O error on device sdc, logical block 93575393
[10408.863664] Buffer I/O error on device sdc, logical block 93575394
[10408.863681] Buffer I/O error on device sdc, logical block 93575395
[10408.863697] Buffer I/O error on device sdc, logical block 93575396
[10408.863713] Buffer I/O error on device sdc, logical block 93575397
[10408.942534] sd 4:2:1:0: [sdc] Unhandled error code
[10408.942538] sd 4:2:1:0: [sdc] Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK
[10408.942542] sd 4:2:1:0: [sdc] CDB: Read(10): 28 00 2c 9e c7 a0 00 00 08 00
[10408.942551] end_request: I/O error, dev sdc, sector 748603296
[10408.991669] sd 4:2:1:0: [sdc] Unhandled error code
[10408.991673] sd 4:2:1:0: [sdc] Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK
[10408.991677] sd 4:2:1:0: [sdc] CDB: Read(10): 28 00 2c 9e c7 a0 00 00 08 00
[10408.991685] end_request: I/O error, dev sdc, sector 748603296
[10409.053380] sd 4:2:1:0: [sdc] Unhandled error code
[10409.053384] sd 4:2:1:0: [sdc] Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK
[10409.053387] sd 4:2:1:0: [sdc] CDB: Read(10): 28 00 2c 9e c7 a0 00 00 08 00
[10409.053396] end_request: I/O error, dev sdc, sector 748603296
[11073.849734] sd 4:2:1:0: [sdc] Unhandled error code
[11073.849742] sd 4:2:1:0: [sdc] Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK
[11073.849750] sd 4:2:1:0: [sdc] CDB: Read(10): 28 00 2c 9e c7 10 00 00 d0 00
[11073.849759] end_request: I/O error, dev sdc, sector 748603152
[11073.935696] raid5_end_read_request: 25 callbacks suppressed
[11073.935701] md/raid:md0: read error corrected (8 sectors at 748603152 on sdc)
[11073.935707] md/raid:md0: read error corrected (8 sectors at 748603160 on sdc)
[11073.935711] md/raid:md0: read error corrected (8 sectors at 748603168 on sdc)
[11073.935714] md/raid:md0: read error corrected (8 sectors at 748603176 on sdc)
[11073.935717] md/raid:md0: read error corrected (8 sectors at 748603184 on sdc)
[11073.935720] md/raid:md0: read error corrected (8 sectors at 748603192 on sdc)
[11073.935724] md/raid:md0: read error corrected (8 sectors at 748603200 on sdc)
[11073.935727] md/raid:md0: read error corrected (8 sectors at 748603208 on sdc)
[11073.935730] md/raid:md0: read error corrected (8 sectors at 748603216 on sdc)
[11073.935733] md/raid:md0: read error corrected (8 sectors at 748603224 on sdc)

The two green sections are variations on what has been covered in the earlier sections of this post.  These two portions I’ve highlighted blue suggest a reasonable scope for the unreadable area of the disk.
I’m not sure why they are listed as buffer areas, but you can clearly see  it covers block 93575388 to 93575397.
The second blue part is from soft raid trying to repair the dead blocks,  1 block being 8 sectors.  93,575,397 x 8 = 748,603,176 as it happens.

The two lines remaining uncoloured nicely demonstrate the ability of the kernel to rate limit it’s logging. Sadly in the process we’ve lost useful information, but we can surmise that those 25 callbacks from raid5 are corrections for 25 contiguous 8 sector blocks.  Can’t be sure what all the 48 call backs suppressed from quiet_error are, some will be further Buffer I/O errors though.

The final tally from megasasctl is 1 media error and 35 other errors.  That drive is definitely not happy.  Time to replace and break out the drive diagnostics.

Current Mood: Confused

Not quite…

Okie, so after large amounts of poking to actually post something … here is what’s currently happening in the land of me.

Our bedroom, after much work, is starting to look like a bedroom again.  It is decorated (mostly) and stuff has been moved out of much of the rest of the house (mostly).  Sadly stuff is now boxed awaiting sorting before being brought back in.
How much of an improvment that is …. is open to debate.

I’m sure photo’s will be forthcoming once things are looking respectable (we currently have no cupboard doors).

I’ve not been too useful recently due to random unwell, decorating, more unwell, and a minor mental breakdown.
Depression sucks.  Personality fragmentation is worse.
Attempting to reassemble a personality with duck tape is quackers.
I will refrain from further confusing you with tales of my messed up mind.

What else…

Work?  Well I suppose I’ll get further nagged if I start talking about the side projects that have been taking up my attention.
I have discovered that the core difficulty in writing good control panel software is that the things you generally do with control panel software are not, in themselves, things that are pleasant to think about.

That said, I’m starting to make progress with Make it funky.

I also note wonderful things happening in the world of audacious … spidy-sense says this new interface is gonna be awesome.  For that, I’m willing to put up with partially broken stuff for now :p

Hurm, it’s light outside.  I suppose I should consider making another trip in to the outdoors again shortly … see what’s happenning in the rest of the world.

Well maybe not, but if I keep this exercise and healthy eating lark up I might one day.

So yesturday was the first weigh in since starting…. 3 3/4lb gone, not bad hey.

I decided to increase my walk yesturday, got a bit lost on the new route, what with taking roads I have never been down before, but today I did the new route as it will be for the next couple of weeks or so. The route took me 25 mins today, thats an increase in time of nearly 15 mins from the last route, so I have probably nearly double the distance. If I don’t loss at least another 3lb by saturday I will be mightly miffed :p

No other news, still making arrows on Runescape so no real effort has been put into any of my projects, must remember to poke daniel about the Wii and his phone monday, I would like to play on the wii, but it’s not connected because it probably wants sending back to have the graphic problem fixed. I should also remind him that his brother wants some pics of his car done, those are probably wanted sooner rather than later… And should probably try and attack the tidying up stuff…. but probably not until I have finished these arrows…. I need a to do list.. :jeltz

Current Mood: Here bugs…

Progress continues… (esp for the benefit of Cew )

• Harmony:
  • Session manager now should have basic functionality working nicely, just awaiting some feedback on further upgrades.
  • The Security control panel is working, although a couple of it’s features aren’t fully wired in yet.
  • The Time control panel is also working nicely. The core now has timezones and smart date handling.
  • The bbcode system has had a major rework, providing greater flexibility and resilience … not to mention it should be faster.
  • The foundations of the new quicklink is in place and being used by the Time control panel.
  • Hopefully more updates on the control panel will be following soon.
• The dynamic images code has also seen some updates…
  • In it’s first steps from prototype to service, the whole setup has now moved to it’s own subdomain.
  • The runescape comparator now displays your progress through the level and indicates which skills have had recent xp gains
• After much consideration, I’ve decided the theme on Make it Funky needs further tweaking… some details about it have been annoying me.

That seems to be all I can think of for now heh.

Well Happy New year y’all.

I’m gonna make a kinda new year resolution. I’m going to try and be more commited and more controlled.

Probably doesn’t make sense to most people…

This last year has fealt more like I was in a rowing boat with no oars, I’ve pretty much just gone with the flow of things, not really accomplished much and gone nowhere.

So this year I want to change…. Change is hard and sucks, but I want to try, I don’t want to just go with the flow any more.

First task. More blogging…. On a friends Blog, I read a post where she was joining this post every day thing…. Interesting challange…. doubt I could manage that, but I want to try to post at least once a week… some weeks may suck but

Second task: Write more!! Stories that is, I have lots of “ideas” but no real progress in any of my writing, so I want to try and start some of my stories (maybe already exisitng ones, or new ideas)

Third task: Get life sorted out!!! Huge tasks, small steps first…. Put more effort into getting a job…. or generally earning income (ebaying maybe *ponder*)…. straighten out living space (it’s only two rooms!!! will tidy and keep tidy…. or die trying)… failing that… get place of own (council?) more space = less stress (I hope)…. Diet and exercise…. I’m sick of being like I am…. I want to get into shape…. I keep trying, but something always gets in the way… so real try this year (proper effort may have to wait a few days until we get home, but I’m at the least gonna try and not stuff my face so much.)

Hmm Think that is all on the planning front for now.