Hi Michael,

Michael Schmitt wrote:

> I tend to hotswap sata drives with a frameless-sata-hotswap-enclosure connected
> to a Silicon Image 3512 controller on a regular basis and have to report...
> broken again.
> The last 3.2 kernel did work, the first 3.3 image did break it. I had
> that problem once before (even if I do not find the ticket anymore) and it got
> fixed rather fast. I do not even know anymore if I did report it upstream or in
> the Debian BTS, but as I am not sure if a Debian patch may be responsible I
> report it here.

Thanks for reporting it. Weird --- can you say a little more about
the nature of the breakage? In particular, please indicate:

- steps to reproduce
- how reproducible this is (100% of the time? 80% of the time?)
- expected result, actual result, and how the difference indicates a bug
- full "dmesg" output from booting and reproducing the problem
- which kernel versions you have tested and what happened with each

There haven't been any changes to the sata_sil driver since v3.2.

Curious,
Jonathan



--
To UNSUBSCRIBE, email to debian-kernel-REQUEST@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listmaster@lists.debian.org
Archive: 20120506061859.GA26002@burratino">http://lists.debian.org/20120506061859.GA26002@burratino

Hi Jonathan,

Am 06.05.2012 08:18, schrieb Jonathan Nieder:

Hi Michael,

Michael Schmitt wrote:


I tend to hotswap sata drives with a frameless-sata-hotswap-enclosure connected
to a Silicon Image 3512 controller on a regular basis and have to report...
broken again.
The last 3.2 kernel did work, the first 3.3 image did break it. I had
that problem once before (even if I do not find the ticket anymore) and it got
fixed rather fast. I do not even know anymore if I did report it upstream or in
the Debian BTS, but as I am not sure if a Debian patch may be responsible I
report it here.

Thanks for reporting it. Weird --- can you say a little more about
the nature of the breakage? In particular, please indicate:

- steps to reproduce
- how reproducible this is (100% of the time? 80% of the time?)
- expected result, actual result, and how the difference indicates a bug
- full "dmesg" output from booting and reproducing the problem
- which kernel versions you have tested and what happened with each
Very simple, it is reproducible 100% of the time, but I must admit I did
just try it a few times and there it did always happen. But if it helps
I am willing to test that a bit further and let's say make 20 test-runs.


It happend like this. Installed 3.3.3 (iirc ) a few days back, did some
hdd shuffling a few days later, realized a modprobe -r; modprobe was
necessary all the time (maybe 5 hotswap events), rebooted to the last
3.2 kernel, worked like a charm (again maybe 5 hotswap events), wanted
to report it immediately but reportbug (madison) said there would be a
newer kernel available (3.3.4), installed that and it happend again with
this one and as it seemed this time even a reboot was necessary as the
module sata_sil was busy. The last thing for now... let's call it a
maybe, I did not test that very thoroughly as reboots are not that funny
as I am used to hibernate / suspend these days.



There haven't been any changes to the sata_sil driver since v3.2.
That is indeed strange... bottom line, I will get the last few 3.3.x
kernels from snapshot.d.o and test the whole issue a bit further and
report back then.


For a start of logs, see attached: dmesg_hotswap_3.2_3.2.16-1.txt (some
hotswap events with kernel image 3.2.0-2-686-pae (changelog indicates
3.2.16-1)


regards
Michael



Curious,
Jonathan


[ 4121.428002] ata5: exception Emask 0x10 SAct 0x0 SErr 0x50000 action 0xe frozen
[ 4121.428022] ata5: SError: { PHYRdyChg CommWake }
[ 4121.428039] ata5: hard resetting link
[ 4127.192021] ata5: link is slow to respond, please be patient (ready=-19)
[ 4129.208054] ata5: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
[ 4129.216331] ata5.00: ATA-7: SAMSUNG HD502IJ, 1AA01113, max UDMA7
[ 4129.216336] ata5.00: 976773168 sectors, multi 0: LBA48 NCQ (depth 0/32)
[ 4129.224310] ata5.00: configured for UDMA/100
[ 4129.224320] ata5: EH complete
[ 4129.224473] scsi 4:0:0:0: Direct-Access ATA SAMSUNG HD502IJ 1AA0 PQ: 0 ANSI: 5
[ 4129.224830] sd 4:0:0:0: [sdg] 976773168 512-byte logical blocks: (500 GB/465 GiB)
[ 4129.224900] sd 4:0:0:0: [sdg] Write Protect is off
[ 4129.224904] sd 4:0:0:0: [sdg] Mode Sense: 00 3a 00 00
[ 4129.224934] sd 4:0:0:0: [sdg] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[ 4129.234487] sdg: sdg1
[ 4129.234814] sd 4:0:0:0: [sdg] Attached SCSI disk
[ 4158.530545] Btrfs loaded
[ 4158.531219] device label samsung_S13TJ1CQC01999 devid 1 transid 9 /dev/mapper/udisks-luks-uuid-fdabd147-01a5-4a16-84a5-5a27a3cebebc-uid1000
[ 4158.531806] btrfs: disk space caching is enabled
[ 4180.809393] ata5: exception Emask 0x10 SAct 0x0 SErr 0x10000 action 0xe frozen
[ 4180.809399] ata5: SError: { PHYRdyChg }
[ 4180.809411] ata5: hard resetting link
[ 4181.532033] ata5: SATA link down (SStatus 0 SControl 310)
[ 4186.532026] ata5: hard resetting link
[ 4186.852027] ata5: SATA link down (SStatus 0 SControl 310)
[ 4191.852023] ata5: hard resetting link
[ 4192.172032] ata5: SATA link down (SStatus 0 SControl 310)
[ 4192.172043] ata5.00: disabled
[ 4192.172054] ata5: EH complete
[ 4192.172065] ata5.00: detaching (SCSI 4:0:0:0)
[ 4192.173078] sd 4:0:0:0: [sdg] Synchronizing SCSI cache
[ 4192.173113] sd 4:0:0:0: [sdg] Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK
[ 4192.173117] sd 4:0:0:0: [sdg] Stopping disk
[ 4192.173125] sd 4:0:0:0: [sdg] START_STOP FAILED
[ 4192.173127] sd 4:0:0:0: [sdg] Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK
[ 4237.416151] ata5: exception Emask 0x10 SAct 0x0 SErr 0x50000 action 0xe frozen
[ 4237.416157] ata5: SError: { PHYRdyChg CommWake }
[ 4237.416172] ata5: hard resetting link
[ 4243.180095] ata5: link is slow to respond, please be patient (ready=-19)
[ 4245.308041] ata5: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
[ 4245.316309] ata5.00: ATA-7: SAMSUNG HD502IJ, 1AA01113, max UDMA7
[ 4245.316314] ata5.00: 976773168 sectors, multi 0: LBA48 NCQ (depth 0/32)
[ 4245.324309] ata5.00: configured for UDMA/100
[ 4245.324319] ata5: EH complete
[ 4245.324464] scsi 4:0:0:0: Direct-Access ATA SAMSUNG HD502IJ 1AA0 PQ: 0 ANSI: 5
[ 4245.324827] sd 4:0:0:0: [sdg] 976773168 512-byte logical blocks: (500 GB/465 GiB)
[ 4245.324898] sd 4:0:0:0: [sdg] Write Protect is off
[ 4245.324902] sd 4:0:0:0: [sdg] Mode Sense: 00 3a 00 00
[ 4245.324932] sd 4:0:0:0: [sdg] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[ 4245.333449] sdg: sdg1
[ 4245.333758] sd 4:0:0:0: [sdg] Attached SCSI disk
[ 4562.887575] device label samsung_S13TJ90QB19095 devid 1 transid 10 /dev/mapper/udisks-luks-uuid-fd6f38f6-51be-4982-b5de-adf76a66b419-uid1000
[ 4562.888392] btrfs: disk space caching is enabled
[ 4590.033991] ata5: exception Emask 0x10 SAct 0x0 SErr 0x10000 action 0xe frozen
[ 4590.033997] ata5: SError: { PHYRdyChg }
[ 4590.034009] ata5: hard resetting link
[ 4590.756046] ata5: SATA link down (SStatus 0 SControl 310)
[ 4595.756036] ata5: hard resetting link
[ 4596.076030] ata5: SATA link down (SStatus 0 SControl 310)
[ 4601.076030] ata5: hard resetting link
[ 4601.396031] ata5: SATA link down (SStatus 0 SControl 310)
[ 4601.396044] ata5.00: disabled
[ 4601.396056] ata5: EH complete
[ 4601.396067] ata5.00: detaching (SCSI 4:0:0:0)
[ 4601.397768] sd 4:0:0:0: [sdg] Synchronizing SCSI cache
[ 4601.397810] sd 4:0:0:0: [sdg] Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK
[ 4601.397816] sd 4:0:0:0: [sdg] Stopping disk
[ 4601.397828] sd 4:0:0:0: [sdg] START_STOP FAILED
[ 4601.397831] sd 4:0:0:0: [sdg] Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK
[ 4803.529675] ata5: exception Emask 0x10 SAct 0x0 SErr 0x50000 action 0xe frozen
[ 4803.529681] ata5: SError: { PHYRdyChg CommWake }
[ 4803.529695] ata5: hard resetting link
[ 4809.292024] ata5: link is slow to respond, please be patient (ready=-19)
[ 4812.708038] ata5: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
[ 4812.732307] ata5.00: ATA-8: SAMSUNG HD501LJ, CR100-10, max UDMA7
[ 4812.732312] ata5.00: 976773168 sectors, multi 0: LBA48 NCQ (depth 0/32)
[ 4812.740300] ata5.00: configured for UDMA/100
[ 4812.740310] ata5: EH complete
[ 4812.740463] scsi 4:0:0:0: Direct-Access ATA SAMSUNG HD501LJ CR10 PQ: 0 ANSI: 5
[ 4812.740890] sd 4:0:0:0: [sdg] 976773168 512-byte logical blocks: (500 GB/465 GiB)
[ 4812.740960] sd 4:0:0:0: [sdg] Write Protect is off
[ 4812.740964] sd 4:0:0:0: [sdg] Mode Sense: 00 3a 00 00
[ 4812.740994] sd 4:0:0:0: [sdg] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[ 4812.749161] sdg: sdg1
[ 4812.749470] sd 4:0:0:0: [sdg] Attached SCSI disk
[ 4824.803410] device label samsung_S0MUJ1MP893478 devid 1 transid 9 /dev/mapper/udisks-luks-uuid-9875f298-b88e-4fce-b5d7-4830ed30a4d0-uid1000
[ 4824.803738] btrfs: disk space caching is enabled
[ 4878.228490] ata5: exception Emask 0x10 SAct 0x0 SErr 0x10000 action 0xe frozen
[ 4878.228496] ata5: SError: { PHYRdyChg }
[ 4878.228508] ata5: hard resetting link
[ 4878.952036] ata5: SATA link down (SStatus 0 SControl 310)
[ 4880.616869] ata5: hard resetting link
[ 4885.976021] ata5: link is slow to respond, please be patient (ready=-19)
[ 4887.096046] ata5: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
[ 4887.112304] ata5.00: configured for UDMA/100
[ 4887.112313] ata5: EH complete
[ 4996.917632] ata5: exception Emask 0x10 SAct 0x0 SErr 0x10000 action 0xe frozen
[ 4996.917638] ata5: SError: { PHYRdyChg }
[ 4996.917650] ata5: hard resetting link
[ 4997.640026] ata5: SATA link down (SStatus 0 SControl 310)
[ 5002.640026] ata5: hard resetting link
[ 5002.960030] ata5: SATA link down (SStatus 0 SControl 310)
[ 5007.960027] ata5: hard resetting link
[ 5008.280042] ata5: SATA link down (SStatus 0 SControl 310)
[ 5008.280055] ata5.00: disabled
[ 5008.280066] ata5: EH complete
[ 5008.280077] ata5.00: detaching (SCSI 4:0:0:0)
[ 5008.282263] sd 4:0:0:0: [sdg] Synchronizing SCSI cache
[ 5008.282300] sd 4:0:0:0: [sdg] Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK
[ 5008.282306] sd 4:0:0:0: [sdg] Stopping disk
[ 5008.282316] sd 4:0:0:0: [sdg] START_STOP FAILED
[ 5008.282319] sd 4:0:0:0: [sdg] Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK
[ 5095.205241] ata5: exception Emask 0x10 SAct 0x0 SErr 0x50000 action 0xe frozen
[ 5095.205247] ata5: SError: { PHYRdyChg CommWake }
[ 5095.205261] ata5: hard resetting link
[ 5100.968022] ata5: link is slow to respond, please be patient (ready=-19)
[ 5105.224024] ata5: COMRESET failed (errno=-16)
[ 5105.224035] ata5: hard resetting link
[ 5108.692064] ata5: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
[ 5108.728044] ata5.00: ATA-8: ST31000340NS, SN06, max UDMA/133
[ 5108.728048] ata5.00: 1953525168 sectors, multi 0: LBA48 NCQ (depth 0/32)
[ 5108.787809] ata5.00: configured for UDMA/100
[ 5108.787822] ata5: EH complete
[ 5108.787980] scsi 4:0:0:0: Direct-Access ATA ST31000340NS SN06 PQ: 0 ANSI: 5
[ 5108.788394] sd 4:0:0:0: [sdg] 1953525168 512-byte logical blocks: (1.00 TB/931 GiB)
[ 5108.788464] sd 4:0:0:0: [sdg] Write Protect is off
[ 5108.788468] sd 4:0:0:0: [sdg] Mode Sense: 00 3a 00 00
[ 5108.788498] sd 4:0:0:0: [sdg] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[ 5108.815022] sdg: sdg1
[ 5108.815338] sd 4:0:0:0: [sdg] Attached SCSI disk
[ 5119.160199] device label seagate_9QJ28AV9 devid 1 transid 13 /dev/mapper/udisks-luks-uuid-9744a2a1-b734-4791-874b-0da4e913b695-uid1000
[ 5119.160710] btrfs: disk space caching is enabled
[ 5705.342421] ata6: exception Emask 0x10 SAct 0x0 SErr 0x50000 action 0xe frozen
[ 5705.342427] ata6: SError: { PHYRdyChg CommWake }
[ 5705.342441] ata6: hard resetting link
[ 5711.104038] ata6: link is slow to respond, please be patient (ready=-19)
[ 5711.272031] ata6: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
[ 5711.281309] ata6.00: ATA-7: Maxtor 6B120M0, BANC1980, max UDMA/133
[ 5711.281314] ata6.00: 240121728 sectors, multi 0: LBA NCQ (not used)
[ 5711.297143] ata6.00: configured for UDMA/100
[ 5711.297153] ata6: EH complete
[ 5711.297297] scsi 5:0:0:0: Direct-Access ATA Maxtor 6B120M0 BANC PQ: 0 ANSI: 5
[ 5711.297557] sd 5:0:0:0: [sdh] 240121728 512-byte logical blocks: (122 GB/114 GiB)
[ 5711.297627] sd 5:0:0:0: [sdh] Write Protect is off
[ 5711.297631] sd 5:0:0:0: [sdh] Mode Sense: 00 3a 00 00
[ 5711.297661] sd 5:0:0:0: [sdh] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[ 5711.318990] sdh: sdh1
[ 5711.319263] sd 5:0:0:0: [sdh] Attached SCSI disk
[ 5719.198415] kjournald starting. Commit interval 5 seconds
[ 5719.204153] EXT3-fs (dm-6): using internal journal
[ 5719.204158] EXT3-fs (dm-6): mounted filesystem with ordered data mode
[ 5729.170484] device label seagate_9QJ28AV9 devid 1 transid 16 /dev/mapper/udisks-luks-uuid-9744a2a1-b734-4791-874b-0da4e913b695-uid1000
[ 5729.170833] btrfs: disk space caching is enabled
mschmitt@adrastea:~$

Hi,

sorry that it took so long, but now I have the time to test the
hotplugging with a kernel >= 3.3


dmesg logs directly pasted here. So first, booted with powered down
esata enclosure and now, poweron:


[36997.268364] ata5: exception Emask 0x10 SAct 0x0 SErr 0x50000 action
0xe frozen

[36997.268370] ata5: SError: { PHYRdyChg CommWake }
[36997.268383] ata5: hard resetting link
[37003.032028] ata5: link is slow to respond, please be patient (ready=-19)
[37003.088037] ata5: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
[37003.112203] ata5.00: ATA-8: VB0250EAVER, HPG0, max UDMA/100
[37003.112206] ata5.00: 488397168 sectors, multi 0: LBA48 NCQ (depth 0/32)
[37003.128213] ata5.00: configured for UDMA/100
[37003.128225] ata5: EH complete
[37003.128354] scsi 4:0:0:0: Direct-Access ATA VB0250EAVER
HPG0 PQ: 0 ANSI: 5
[37003.128550] sd 4:0:0:0: [sdg] 488397168 512-byte logical blocks: (250
GB/232 GiB)

[37003.128597] sd 4:0:0:0: [sdg] Write Protect is off
[37003.128599] sd 4:0:0:0: [sdg] Mode Sense: 00 3a 00 00
[37003.128620] sd 4:0:0:0: [sdg] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA

[37003.151147] sdg: sdg1
[37003.151688] sd 4:0:0:0: [sdg] Attached SCSI disk

Disk works.

[37339.909515] Btrfs loaded
[37339.921542] device label hp_VB0250EAVER devid 1 transid 107
/dev/mapper/udisks-luks-uuid-23ee789a-0138-4799-81a8-a7286119b712-uid1000

[37339.922224] btrfs: disk space caching is enabled

mounted.... and umount again, now powerdown.

[37437.877977] ata5: exception Emask 0x10 SAct 0x0 SErr 0x10000 action
0xe frozen

[37437.877982] ata5: SError: { PHYRdyChg }
[37437.877995] ata5: hard resetting link
[37438.600030] ata5: SATA link down (SStatus 0 SControl 310)
[37443.604027] ata5: hard resetting link
[37443.924127] ata5: SATA link down (SStatus 0 SControl 310)
[37448.924580] ata5: hard resetting link
[37449.244032] ata5: SATA link down (SStatus 0 SControl 310)
[37449.244043] ata5.00: disabled
[37449.244053] ata5: EH complete
[37449.244062] ata5.00: detaching (SCSI 4:0:0:0)
[37449.245755] sd 4:0:0:0: [sdg] Synchronizing SCSI cache
[37449.245788] sd 4:0:0:0: [sdg] Result: hostbyte=DID_BAD_TARGET
driverbyte=DRIVER_OK

[37449.245792] sd 4:0:0:0: [sdg] Stopping disk
[37449.245800] sd 4:0:0:0: [sdg] START_STOP FAILED
[37449.245802] sd 4:0:0:0: [sdg] Result: hostbyte=DID_BAD_TARGET
driverbyte=DRIVER_OK


Drive gone... now, power-up again.

adrastea:~# dmesg
adrastea:~#

Nothing. I did clear the kernel-message log in between... so module
modprobe-cycling...


[38290.316274] sata_sil 0000:01:01.0: version 2.4
[38290.319815] scsi7 : sata_sil
[38290.319986] scsi8 : sata_sil
[38290.320067] ata7: SATA max UDMA/100 mmio m512@0xbbeffc00 tf
0xbbeffc80 irq 21
[38290.320071] ata8: SATA max UDMA/100 mmio m512@0xbbeffc00 tf
0xbbeffcc0 irq 21

[38290.640039] ata7: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
[38290.648208] ata7.00: ATA-8: VB0250EAVER, HPG0, max UDMA/100
[38290.648213] ata7.00: 488397168 sectors, multi 0: LBA48 NCQ (depth 0/32)
[38290.664207] ata7.00: configured for UDMA/100
[38290.664381] scsi 7:0:0:0: Direct-Access ATA VB0250EAVER
HPG0 PQ: 0 ANSI: 5
[38290.664619] sd 7:0:0:0: [sdg] 488397168 512-byte logical blocks: (250
GB/232 GiB)

[38290.664678] sd 7:0:0:0: [sdg] Write Protect is off
[38290.664682] sd 7:0:0:0: [sdg] Mode Sense: 00 3a 00 00
[38290.664709] sd 7:0:0:0: [sdg] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA

[38290.674683] sdg: sdg1
[38290.674996] sd 7:0:0:0: [sdg] Attached SCSI disk
[38290.984031] ata8: SATA link down (SStatus 0 SControl 310)

and the drve is back. So first, the modprobe-cycling does work with the
neweset kernel 3.3. I guess there was some other hickup the last time
that did prevent the module unloading. But the thing with "notswap
broken" is definitely there. It works only ONE time and all subsequent
hotplug (powerdown or disk pluggin, tested both at least 5 times in a
row, two test-lines, with modprobe-cycling in between) events get ignored.


Running 3.3.0-trunk-686-pae (3.3-1~experimental.1) right now. Oops,
testing with 3.3.4-1~experimental.1 now, but I am sure it will happen
there as well. I will report back after the next reboot.


regards
Michael




--
To UNSUBSCRIBE, email to debian-kernel-REQUEST@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listmaster@lists.debian.org
Archive: 4FB6A7E2.5000206@gmail.com">http://lists.debian.org/4FB6A7E2.5000206@gmail.com

tags 671689 + upstream patch moreinfo
# regression
severity 671689 important
quit

Hi Michael,

Michael Schmitt wrote:

> sorry that it took so long, but now I have the time to test the
> hotplugging with a kernel >= 3.3

Awesome, thanks for the logs.

[...]
> dmesg logs directly pasted here. So first, booted with powered down
> esata enclosure and now, poweron:
>
> [36997.268364] ata5: exception Emask 0x10 SAct 0x0 SErr 0x50000 action 0xe frozen
> [36997.268370] ata5: SError: { PHYRdyChg CommWake }
> [36997.268383] ata5: hard resetting link
> [37003.032028] ata5: link is slow to respond, please be patient (ready=-19)
> [37003.088037] ata5: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
[...]
> [37003.151688] sd 4:0:0:0: [sdg] Attached SCSI disk
>
> Disk works.

As before. Good.

[...]
> mounted.... and umount again, now powerdown.
>
> [37437.877977] ata5: exception Emask 0x10 SAct 0x0 SErr 0x10000 action 0xe frozen
> [37437.877982] ata5: SError: { PHYRdyChg }
> [37437.877995] ata5: hard resetting link
> [37438.600030] ata5: SATA link down (SStatus 0 SControl 310)
> [37443.604027] ata5: hard resetting link
[...]
> [37449.244062] ata5.00: detaching (SCSI 4:0:0:0)
> [37449.245755] sd 4:0:0:0: [sdg] Synchronizing SCSI cache
> [37449.245788] sd 4:0:0:0: [sdg] Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK
> [37449.245792] sd 4:0:0:0: [sdg] Stopping disk
> [37449.245800] sd 4:0:0:0: [sdg] START_STOP FAILED
> [37449.245802] sd 4:0:0:0: [sdg] Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK
>
> Drive gone... now, power-up again.

Ok.

> adrastea:~# dmesg
> adrastea:~#
>
> Nothing. I did clear the kernel-message log in between...

By contrast in 3.2.y you got the following:

[ 4192.173127] sd 4:0:0:0: [sdg] Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK
[ 4237.416151] ata5: exception Emask 0x10 SAct 0x0 SErr 0x50000 action 0xe frozen
[ 4237.416157] ata5: SError: { PHYRdyChg CommWake }
[ 4237.416172] ata5: hard resetting link

So it looks like the PHYRdyChg CommWake exception is not arriving for
some reason.

> so module
> modprobe-cycling...
>
> [38290.316274] sata_sil 0000:01:01.0: version 2.4
> [38290.319815] scsi7 : sata_sil
> [38290.319986] scsi8 : sata_sil
> [38290.320067] ata7: SATA max UDMA/100 mmio m512@0xbbeffc00 tf 0xbbeffc80 irq 21
> [38290.320071] ata8: SATA max UDMA/100 mmio m512@0xbbeffc00 tf 0xbbeffcc0 irq 21
> [38290.640039] ata7: SATA link up 1.5 Gbps (SStatus 113 SControl 310)

And a workaround.

[...]
> and the drve is back. So first, the modprobe-cycling does work with
> the neweset kernel 3.3. I guess there was some other hickup the last
> time that did prevent the module unloading. But the thing with
> "notswap broken" is definitely there. It works only ONE time and all
> subsequent hotplug (powerdown or disk pluggin, tested both at least
> 5 times in a row, two test-lines, with modprobe-cycling in between)
> events get ignored.
>
> Running 3.3.0-trunk-686-pae (3.3-1~experimental.1) right now. Oops,
> testing with 3.3.4-1~experimental.1 now, but I am sure it will
> happen there as well. I will report back after the next reboot.

Please test the attached patch, for example following the instructions
from [1]. (Found at [2].)

Thanks,
Jonathan

[1] http://kernel-handbook.alioth.debian.org/ch-common-tasks.html#s-common-official
or the corresponding page in the debian-kernel-handbook package
[2] http://thread.gmane.org/gmane.linux.ide/51860/focus=51881

Am 18.05.2012 22:32, schrieb Jonathan Nieder:
Please test the attached patch, for example following the instructions
from [1]. (Found at [2].) Thanks, Jonathan [1]
http://kernel-handbook.alioth.debian.org/ch-common-tasks.html#s-common-official
or the corresponding page in the debian-kernel-handbook package [2]
http://thread.gmane.org/gmane.linux.ide/51860/focus=51881
[ 320.644432] ata5: exception Emask 0x10 SAct 0x0 SErr 0x10000 action
0xe frozen

[ 320.644437] ata5: SError: { PHYRdyChg }
[ 320.644449] ata5: hard resetting link
[ 321.368035] ata5: SATA link down (SStatus 0 SControl 310)
[ 326.368021] ata5: hard resetting link
[ 326.688028] ata5: SATA link down (SStatus 0 SControl 310)
[ 331.688034] ata5: hard resetting link
[ 332.008027] ata5: SATA link down (SStatus 0 SControl 310)
[ 332.008040] ata5.00: disabled
[ 332.008051] ata5: EH complete
[ 332.008060] ata5.00: detaching (SCSI 4:0:0:0)
[ 332.020060] sd 4:0:0:0: [sdc] Synchronizing SCSI cache
[ 332.020201] sd 4:0:0:0: [sdc] Result: hostbyte=DID_BAD_TARGET
driverbyte=DRIVER_OK

[ 332.020205] sd 4:0:0:0: [sdc] Stopping disk
[ 332.020213] sd 4:0:0:0: [sdc] START_STOP FAILED
[ 332.020215] sd 4:0:0:0: [sdc] Result: hostbyte=DID_BAD_TARGET
driverbyte=DRIVER_OK
[ 424.275712] ata5: exception Emask 0x10 SAct 0x0 SErr 0x50000 action
0xe frozen

[ 424.275718] ata5: SError: { PHYRdyChg CommWake }
[ 424.275731] ata5: hard resetting link
[ 429.980048] ata5: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
[ 430.004251] ata5.00: ATA-8: VB0250EAVER, HPG0, max UDMA/100
[ 430.004254] ata5.00: 488397168 sectors, multi 0: LBA48 NCQ (depth 0/32)
[ 430.044200] ata5.00: configured for UDMA/100
[ 430.044209] ata5: EH complete
[ 430.044319] scsi 4:0:0:0: Direct-Access ATA VB0250EAVER
HPG0 PQ: 0 ANSI: 5
[ 430.044544] sd 4:0:0:0: [sdh] 488397168 512-byte logical blocks: (250
GB/232 GiB)

[ 430.044590] sd 4:0:0:0: [sdh] Write Protect is off
[ 430.044593] sd 4:0:0:0: [sdh] Mode Sense: 00 3a 00 00
[ 430.044613] sd 4:0:0:0: [sdh] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA

[ 430.065793] sdh: sdh1
[ 430.066060] sd 4:0:0:0: [sdh] Attached SCSI disk
[ 457.213039] ata5: exception Emask 0x10 SAct 0x0 SErr 0x10000 action
0xe frozen

[ 457.213043] ata5: SError: { PHYRdyChg }
[ 457.213053] ata5: hard resetting link
[ 457.936036] ata5: SATA link down (SStatus 0 SControl 310)
[ 462.936071] ata5: hard resetting link
[ 463.256025] ata5: SATA link down (SStatus 0 SControl 310)
[ 468.256023] ata5: hard resetting link
[ 468.576029] ata5: SATA link down (SStatus 0 SControl 310)
[ 468.576042] ata5.00: disabled
[ 468.576054] ata5: EH complete
[ 468.576068] ata5.00: detaching (SCSI 4:0:0:0)
[ 468.577923] sd 4:0:0:0: [sdh] Synchronizing SCSI cache
[ 468.577975] sd 4:0:0:0: [sdh] Result: hostbyte=DID_BAD_TARGET
driverbyte=DRIVER_OK

[ 468.577981] sd 4:0:0:0: [sdh] Stopping disk
[ 468.577993] sd 4:0:0:0: [sdh] START_STOP FAILED
[ 468.577995] sd 4:0:0:0: [sdh] Result: hostbyte=DID_BAD_TARGET
driverbyte=DRIVER_OK
[ 488.174245] ata5: exception Emask 0x10 SAct 0x0 SErr 0x50000 action
0xe frozen

[ 488.174251] ata5: SError: { PHYRdyChg CommWake }
[ 488.174264] ata5: hard resetting link
[ 493.880034] ata5: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
[ 493.904203] ata5.00: ATA-8: VB0250EAVER, HPG0, max UDMA/100
[ 493.904206] ata5.00: 488397168 sectors, multi 0: LBA48 NCQ (depth 0/32)
[ 493.936239] ata5.00: configured for UDMA/100
[ 493.936249] ata5: EH complete
[ 493.936389] scsi 4:0:0:0: Direct-Access ATA VB0250EAVER
HPG0 PQ: 0 ANSI: 5
[ 493.936625] sd 4:0:0:0: [sdh] 488397168 512-byte logical blocks: (250
GB/232 GiB)

[ 493.936692] sd 4:0:0:0: [sdh] Write Protect is off
[ 493.936696] sd 4:0:0:0: [sdh] Mode Sense: 00 3a 00 00
[ 493.936726] sd 4:0:0:0: [sdh] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA

[ 493.964105] sdh: sdh1
[ 493.965270] sd 4:0:0:0: [sdh] Attached SCSI disk

That was three-time-hotplugging-in-a-row and it works! o/

So that is a general bug in libata and not driver specific? Is that fix
considered to be safe and will it most likely be included in upstream
kernel?


But first, thanks for the help, finding the patch and everything else,
greatly appreciated.


regards
Michael




--
To UNSUBSCRIBE, email to debian-kernel-REQUEST@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listmaster@lists.debian.org
Archive: 4FB81B12.8070501@gmail.com">http://lists.debian.org/4FB81B12.8070501@gmail.com

tags 671689 - moreinfo
quit

Michael Schmitt wrote:

> That was three-time-hotplugging-in-a-row and it works! o/

Thanks! Passed upstream, so hopefully the fix should be part of
3.3.y soon.



--
To UNSUBSCRIBE, email to debian-kernel-REQUEST@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listmaster@lists.debian.org
Archive: 20120520000045.GF4567@burratino">http://lists.debian.org/20120520000045.GF4567@burratino