March 30, 201610 yr This set of messages appears in my log file roughly twice a day. I am running Unraid v6.1.9 on a Supermicro x9scm-f with a xeon 1240 and 16 GBs of ram and a Dell H310 that has been flashed to IT mode. Mar 30 01:38:47 Media kernel: mdcmd (184): spindown 0 Mar 30 01:38:47 Media kernel: mdcmd (185): spindown 5 Mar 30 02:02:05 Media kernel: sd 1:0:1:0: attempting task abort! scmd(ffff8805de88aa80) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: [sdh] CDB: opcode=0x28 28 00 00 0a 30 a0 00 00 20 00 Mar 30 02:02:05 Media kernel: scsi target1:0:1: handle(0x000a), sas_address(0x4433221101000000), phy(1) Mar 30 02:02:05 Media kernel: scsi target1:0:1: enclosure_logical_id(0x590b11c03b4adc04), slot(2) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: task abort: SUCCESS scmd(ffff8805de88aa80) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: attempting task abort! scmd(ffff8805de88b080) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: [sdh] CDB: opcode=0x28 28 00 06 9e 70 98 00 00 08 00 Mar 30 02:02:05 Media kernel: scsi target1:0:1: handle(0x000a), sas_address(0x4433221101000000), phy(1) Mar 30 02:02:05 Media kernel: scsi target1:0:1: enclosure_logical_id(0x590b11c03b4adc04), slot(2) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: task abort: SUCCESS scmd(ffff8805de88b080) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: attempting task abort! scmd(ffff8805de88ac00) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: [sdh] CDB: opcode=0x28 28 00 06 ce de a8 00 00 18 00 Mar 30 02:02:05 Media kernel: scsi target1:0:1: handle(0x000a), sas_address(0x4433221101000000), phy(1) Mar 30 02:02:05 Media kernel: scsi target1:0:1: enclosure_logical_id(0x590b11c03b4adc04), slot(2) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: task abort: SUCCESS scmd(ffff8805de88ac00) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: attempting task abort! scmd(ffff8805de88be00) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: [sdh] CDB: opcode=0x28 28 00 06 ce de c8 00 00 10 00 Mar 30 02:02:05 Media kernel: scsi target1:0:1: handle(0x000a), sas_address(0x4433221101000000), phy(1) Mar 30 02:02:05 Media kernel: scsi target1:0:1: enclosure_logical_id(0x590b11c03b4adc04), slot(2) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: task abort: SUCCESS scmd(ffff8805de88be00) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: attempting task abort! scmd(ffff8805de88ad80) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: [sdh] CDB: opcode=0x28 28 00 06 d6 bc 48 00 00 20 00 Mar 30 02:02:05 Media kernel: scsi target1:0:1: handle(0x000a), sas_address(0x4433221101000000), phy(1) Mar 30 02:02:05 Media kernel: scsi target1:0:1: enclosure_logical_id(0x590b11c03b4adc04), slot(2) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: task abort: SUCCESS scmd(ffff8805de88ad80) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: attempting task abort! scmd(ffff8800678d0300) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: [sdh] CDB: opcode=0x28 28 00 18 5d 9d 10 00 00 08 00 Mar 30 02:02:05 Media kernel: scsi target1:0:1: handle(0x000a), sas_address(0x4433221101000000), phy(1) Mar 30 02:02:05 Media kernel: scsi target1:0:1: enclosure_logical_id(0x590b11c03b4adc04), slot(2) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: task abort: SUCCESS scmd(ffff8800678d0300) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: attempting task abort! scmd(ffff8800678d0900) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: [sdh] CDB: opcode=0x28 28 00 28 69 b4 20 00 00 10 00 Mar 30 02:02:05 Media kernel: scsi target1:0:1: handle(0x000a), sas_address(0x4433221101000000), phy(1) Mar 30 02:02:05 Media kernel: scsi target1:0:1: enclosure_logical_id(0x590b11c03b4adc04), slot(2) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: task abort: SUCCESS scmd(ffff8800678d0900) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: attempting task abort! scmd(ffff8800678d0f00) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: [sdh] CDB: opcode=0x28 28 00 31 34 1b c8 00 03 b0 00 Mar 30 02:02:05 Media kernel: scsi target1:0:1: handle(0x000a), sas_address(0x4433221101000000), phy(1) Mar 30 02:02:05 Media kernel: scsi target1:0:1: enclosure_logical_id(0x590b11c03b4adc04), slot(2) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: task abort: SUCCESS scmd(ffff8800678d0f00) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: attempting task abort! scmd(ffff8800678d1c80) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: [sdh] CDB: opcode=0x28 28 00 31 34 1f 80 00 00 d8 00 Mar 30 02:02:05 Media kernel: scsi target1:0:1: handle(0x000a), sas_address(0x4433221101000000), phy(1) Mar 30 02:02:05 Media kernel: scsi target1:0:1: enclosure_logical_id(0x590b11c03b4adc04), slot(2) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: task abort: SUCCESS scmd(ffff8800678d1c80) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: attempting task abort! scmd(ffff8800678d1980) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: [sdh] CDB: opcode=0x28 28 00 31 34 20 60 00 00 e0 00 Mar 30 02:02:05 Media kernel: scsi target1:0:1: handle(0x000a), sas_address(0x4433221101000000), phy(1) Mar 30 02:02:05 Media kernel: scsi target1:0:1: enclosure_logical_id(0x590b11c03b4adc04), slot(2) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: task abort: SUCCESS scmd(ffff8800678d1980) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: attempting task abort! scmd(ffff8800678d1380) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: [sdh] CDB: opcode=0x28 28 00 31 34 21 48 00 00 80 00 Mar 30 02:02:05 Media kernel: scsi target1:0:1: handle(0x000a), sas_address(0x4433221101000000), phy(1) Mar 30 02:02:05 Media kernel: scsi target1:0:1: enclosure_logical_id(0x590b11c03b4adc04), slot(2) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: task abort: SUCCESS scmd(ffff8800678d1380) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: attempting task abort! scmd(ffff8800678d1080) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: [sdh] CDB: opcode=0x28 28 00 31 34 21 d0 00 02 18 00 Mar 30 02:02:05 Media kernel: scsi target1:0:1: handle(0x000a), sas_address(0x4433221101000000), phy(1) Mar 30 02:02:05 Media kernel: scsi target1:0:1: enclosure_logical_id(0x590b11c03b4adc04), slot(2) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: task abort: SUCCESS scmd(ffff8800678d1080) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: attempting task abort! scmd(ffff8800678d0c00) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: [sdh] CDB: opcode=0x28 28 00 31 34 23 f0 00 00 10 00 Mar 30 02:02:05 Media kernel: scsi target1:0:1: handle(0x000a), sas_address(0x4433221101000000), phy(1) Mar 30 02:02:05 Media kernel: scsi target1:0:1: enclosure_logical_id(0x590b11c03b4adc04), slot(2) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: task abort: SUCCESS scmd(ffff8800678d0c00) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: attempting task abort! scmd(ffff8800678d0000) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: [sdh] CDB: opcode=0x28 28 00 31 34 24 20 00 00 88 00 Mar 30 02:02:05 Media kernel: scsi target1:0:1: handle(0x000a), sas_address(0x4433221101000000), phy(1) Mar 30 02:02:05 Media kernel: scsi target1:0:1: enclosure_logical_id(0x590b11c03b4adc04), slot(2) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: task abort: SUCCESS scmd(ffff8800678d0000) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: attempting task abort! scmd(ffff8800678d0d80) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: [sdh] CDB: opcode=0x28 28 00 31 34 24 b0 00 00 10 00 Mar 30 02:02:05 Media kernel: scsi target1:0:1: handle(0x000a), sas_address(0x4433221101000000), phy(1) Mar 30 02:02:05 Media kernel: scsi target1:0:1: enclosure_logical_id(0x590b11c03b4adc04), slot(2) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: task abort: SUCCESS scmd(ffff8800678d0d80) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: attempting task abort! scmd(ffff8800678d0780) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: [sdh] CDB: opcode=0x28 28 00 31 34 24 d0 00 00 18 00 Mar 30 02:02:05 Media kernel: scsi target1:0:1: handle(0x000a), sas_address(0x4433221101000000), phy(1) Mar 30 02:02:05 Media kernel: scsi target1:0:1: enclosure_logical_id(0x590b11c03b4adc04), slot(2) Mar 30 02:02:05 Media kernel: sd 1:0:1:0: task abort: SUCCESS scmd(ffff8800678d0780) Here are the full log files: media-syslog-20160330-0822.zip
March 30, 201610 yr Those are typical messages from a SAS card when it's having issues, in this case with your Cache drive, an SSD. A number of times when I've seen similar messages, drives attached to the SAS card dropped off, only recoverable by a reboot. Yours appear to be more benign, no lost drives, just the SAS card hiccuping, but still a bit scary with their resemblance to more serious behavior. I would check for a firmware update. In the syslog, I see "mpt2sas0: LSISAS2008: FWVersion(17.00.01.00)", but not positive that's an accurate representation of the firmware version. Much of the activity itself is interesting, and seems highly suggestive of an association with human activity. Perhaps you can figure out what you or someone on your network is doing that is coincident? - Mar 27 22:18:01 to 22:23:51 (~5.9 minutes) - Mar 28 22:12:24 to 22:23:25 (11 minutes) - Mar 29 06:50:56 to 06:50:56 (<1 second) - Mar 29 22:13:42 to 22:19:08 (~5.5 minutes) - Mar 30 02:02:05 to 02:02:05 (<1 second) - Mar 30 08:07:56 to 08:07:56 (<1 second) Looks like certain work is done each evening after 10pm, then a quick check in the morning.
March 30, 201610 yr Author @RobJ Thank you for looking at my logs and taking the time to write your reply. At 22:00 each night I have a script that rsyncs my "can't afford to lose" shares to another unraid server. From the timestamps, it looks like the problem is triggered at the end of the rsync. The last line of the script basically uses an ipmi command to turn off the backup server. As for the timestamps at 6:50 am, 2:02 am, and 7:56 am, they look like times I was accessing the UR server after all the disks had spun down. The cache drive is a PNY 480Gb formated as BTRFS SSD. The only change I've made recently is updating to Unraid 6.1.9 from 6.1.8. I don't recall seeing these messages with 6.1.8. Is there anything in 6.1.9 that might explain these error messages? I think I will stop my backup script and see if that clears up the events happening during the 22:00 hour.
March 30, 201610 yr The only change I've made recently is updating to Unraid 6.1.9 from 6.1.8. I don't recall seeing these messages with 6.1.8. Is there anything in 6.1.9 that might explain these error messages? Sorry, I don't see anything obvious that could affect you, in the release notes. The kernel went from 4.1.17 to 4.1.18, supposed to be just bug fixes.
March 30, 201610 yr Author @RobJ Thanks again. I think I'm going to make 1 change at a time until I can isolate the cause. As it seems that the issue occurs on the SSD when the server is accessed after all the drives have been spun down, the first thing I'll try is setting the SSD to never spin down. I don't know if an SSD can "spin down" anyway. Maybe that's the task that the log shows attempting to abort.
March 31, 201610 yr Author Setting the spindown parameter for the ssd to never resulted in no further episodes. However, upon reboot, the same set of error messages appeared in the log. Since the rsync script does not run at bootup, I am concluding that the rsync script has nothing to do with these error messages. It seems that when UR first connects to the drive, whether upon boot or spinup, it tries to execute a command on the ssd that fails, then retries a bunch of times, and them fails. After that, as long as the ssd does not "spin down" there are no further error messages. It doesn't look like it affects the operation of the cache drive. But still, these error messages worry me.
Archived
This topic is now archived and is closed to further replies.