1. Firewire Compact Flash (CF) card reader is connected. 2. CF card is inserted into the card reader. operates normally 3. remove CF card 4. reinsert the same or a new CF card Errors Work around, unplug FW card reader, plug-in FW card reader. Now it works again. Thus no ability to use the card reader while it's persistently plugged in. [ 32.971078] firewire_core 0000:04:00.0: phy config: new root=ffc1, gap_count=5 [ 33.475998] firewire_core 0000:04:00.0: created device fw1: GUID 0030ffb40001656d, S400 [ 33.484183] scsi host6: SBP-2 IEEE-1394 [ 33.684705] firewire_sbp2 fw1.0: logged in to LUN 0000 (0 retries) [ 33.685810] scsi 6:0:0:0: Direct-Access OXSEMI FWIRE CF READER 1.0 PQ: 0 ANSI: 4 [ 33.688709] sd 6:0:0:0: Attached scsi generic sg2 type 0 [ 33.690726] sd 6:0:0:0: [sdb] Attached SCSI removable disk [ 54.295154] firewire_core 0000:04:00.0: phy config: new root=ffc1, gap_count=5 [ 54.797653] sd 6:0:0:0: [sdb] Stopping disk [ 54.827664] sd 6:0:0:0: [sdb] START_STOP FAILED [ 54.827674] sd 6:0:0:0: [sdb] [ 54.827679] Result: hostbyte=DID_BUS_BUSY driverbyte=DRIVER_OK [ 56.835563] firewire_sbp2 fw1.0: ORB reply timed out, rcode 0x11 [ 56.838909] firewire_sbp2 fw1.0: released target 6:0:0 [ 56.846910] scsi host7: SBP-2 IEEE-1394 [ 56.847170] firewire_core 0000:04:00.0: refreshed device fw1 [ 57.047114] firewire_sbp2 fw1.0: logged in to LUN 0000 (0 retries) [ 57.048835] scsi 7:0:0:0: Direct-Access OXSEMI FWIRE CF READER 1.0 PQ: 0 ANSI: 4 [ 57.053761] sd 7:0:0:0: Attached scsi generic sg2 type 0 [ 57.055007] sd 7:0:0:0: [sdb] 7831152 512-byte logical blocks: (4.00 GB/3.73 GiB) [ 57.056808] sd 7:0:0:0: [sdb] Write Protect is off [ 57.056817] sd 7:0:0:0: [sdb] Mode Sense: 11 00 00 00 [ 57.057346] sd 7:0:0:0: [sdb] Cache data unavailable [ 57.057351] sd 7:0:0:0: [sdb] Assuming drive cache: write through [ 57.065666] sdb: unknown partition table [ 57.072448] sd 7:0:0:0: [sdb] Attached SCSI removable disk [ 147.790934] sdb: unknown partition table [ 152.361735] sdb: unknown partition table [ 171.106625] sdb: unknown partition table [ 173.569275] firewire_core 0000:04:00.0: phy config: new root=ffc1, gap_count=5 [ 174.070890] firewire_sbp2 fw1.0: error status: 0:9 [ 174.070905] firewire_sbp2 fw1.0: failed to reconnect [ 174.270880] firewire_sbp2 fw1.0: error status: 0:9 [ 174.272098] firewire_sbp2 fw1.0: logged in to LUN 0000 (0 retries) [ 242.872897] firewire_sbp2 fw1.0: error status: 0:9 [ 242.872912] firewire_sbp2 fw1.0: failed to reconnect [ 243.073049] firewire_sbp2 fw1.0: error status: 0:9 [ 244.512902] firewire_sbp2 fw1.0: error status: 1:0 [ 244.713162] firewire_sbp2 fw1.0: error status: 0:9 [ 266.483734] firewire_core 0000:04:00.0: phy config: new root=ffc1, gap_count=5 [ 266.994460] scsi host8: SBP-2 IEEE-1394 [ 266.994748] firewire_core 0000:04:00.0: created device fw2: GUID 0030ffb40001656d, S400 [ 268.625863] firewire_sbp2 fw2.0: logged in to LUN 0000 (0 retries) [ 268.627625] scsi 8:0:0:0: Direct-Access OXSEMI FWIRE CF READER 1.0 PQ: 0 ANSI: 4 [ 268.632093] sd 8:0:0:0: Attached scsi generic sg3 type 0 [ 268.633492] sd 8:0:0:0: [sdc] 7831152 512-byte logical blocks: (4.00 GB/3.73 GiB) [ 268.634588] sd 8:0:0:0: [sdc] Write Protect is off [ 268.634599] sd 8:0:0:0: [sdc] Mode Sense: 11 00 00 00 [ 268.635224] sd 8:0:0:0: [sdc] Cache data unavailable [ 268.635235] sd 8:0:0:0: [sdc] Assuming drive cache: write through [ 268.643356] sdc: sdc1 [ 268.650435] sd 8:0:0:0: [sdc] Attached SCSI removable disk [ 274.699786] firewire_sbp2 fw1.0: ORB reply timed out, rcode 0x11 [ 274.701672] sd 7:0:0:0: [sdb] Stopping disk [ 274.731839] sd 7:0:0:0: [sdb] START_STOP FAILED [ 274.731850] sd 7:0:0:0: [sdb] [ 274.731854] Result: hostbyte=DID_BUS_BUSY driverbyte=DRIVER_OK [ 274.747153] firewire_sbp2 fw1.0: released target 7:0:0 [ 499.881911] firewire_core 0000:04:00.0: rediscovered device fw0 [ 501.408216] sd 8:0:0:0: [sdc] Stopping disk [ 501.440328] sd 8:0:0:0: [sdc] START_STOP FAILED [ 501.440340] sd 8:0:0:0: [sdc] [ 501.440344] Result: hostbyte=DID_BUS_BUSY driverbyte=DRIVER_OK [ 501.440448] scsi 8:0:0:0: rejecting I/O to offline device [ 501.440457] scsi 8:0:0:0: killing request [ 501.467494] firewire_sbp2 fw2.0: released target 8:0:0 [ 560.108401] firewire_core 0000:04:00.0: phy config: new root=ffc1, gap_count=5 [ 560.617135] scsi host9: SBP-2 IEEE-1394 [ 560.617308] firewire_core 0000:04:00.0: created device fw1: GUID 0030ffb40001656d, S400 [ 562.256798] firewire_sbp2 fw1.0: logged in to LUN 0000 (0 retries) [ 562.258579] scsi 9:0:0:0: Direct-Access OXSEMI FWIRE CF READER 1.0 PQ: 0 ANSI: 4 [ 562.262930] sd 9:0:0:0: Attached scsi generic sg2 type 0 [ 562.264425] sd 9:0:0:0: [sdb] 7831152 512-byte logical blocks: (4.00 GB/3.73 GiB) [ 562.265525] sd 9:0:0:0: [sdb] Write Protect is off [ 562.265536] sd 9:0:0:0: [sdb] Mode Sense: 11 00 00 00 [ 562.266076] sd 9:0:0:0: [sdb] Cache data unavailable [ 562.266084] sd 9:0:0:0: [sdb] Assuming drive cache: write through [ 562.274617] sdb: sdb1 [ 562.281292] sd 9:0:0:0: [sdb] Attached SCSI removable disk
Created attachment 162331 [details] dmesg
Created attachment 162341 [details] lspci lspci -vvnn (firewire excerpt)
Created attachment 162351 [details] journal-3.18.1.txt Reboot with 3.18.1, used journalctl -o short-monotonic -f (attached) while making notes of what I'm doing related to monotonic time. The line numbers below are monotonic time, and apply only to this attached journal. 295 plug-in CF card reader with CF card already in it 335 eject CF card icon in Nautilus 357 physically remove CF card from reader, the reader is still plugged into the FW port 387 insert CF card (Nautilus finds and mounts it) 445 eject CF card in Nautilus 453 physically remove CF card from reader, again reader itself remains connected 461 insert CF card (this time it does not appear in Nautilus) no further user action taken from this point on, I literally walked away from the computer for 10+ minutes.
Created attachment 162361 [details] journal-3.11.10.txt Similar results with kernel 3.11.10-300.fc20.x86_64.
According to the GUID of your card reader, it is made by DataFab. I have a different 1394b CF reader (hama Traveldrive CF IEEE 1394b) with which I cannot reproduce the issue, unfortunately. [The hama reader behaves in the following manner: While no card is inserted, all requests are responded to with RCODE_BUSY. When a card is inserted, the reader generates a bus reset, then begins to respond normally. When the card is pulled out, the reader generates a bus reset and returns to respond with RCODE_BUSY again. And so on. This works reasonably well with the Linux driver stack, provided that one waits long enough between removing one card and inserting another different card: The "busy" period needs to be long enough to cause firewire-core to shut down the SBP-2 unit before the next card is inserted.] Regarding your comment 3 (attachment 162351 [details]): Do I understand correctly that the desirable behavior (detect an exchange of cards while the reader remains plugged in) actually worked from 357 to 387, but failed from 453 to 461? If my understanding is correct, do you have a suggestion what was different between the exchange at 357--387 and the one at 453--461?
(In reply to Stefan Richter from comment #5) > According to the GUID of your card reader, it is made by DataFab. > > I have a different 1394b CF reader (hama Traveldrive CF IEEE 1394b) with > which I cannot reproduce the issue, unfortunately. > > [The hama reader behaves in the following manner: While no card is > inserted, all requests are responded to with RCODE_BUSY. When a card is > inserted, the reader generates a bus reset, then begins to respond normally. > When the card is pulled out, the reader generates a bus reset and returns to > respond with RCODE_BUSY again. And so on. This works reasonably well with > the Linux driver stack, provided that one waits long enough between removing > one card and inserting another different card: The "busy" period needs to > be long enough to cause firewire-core to shut down the SBP-2 unit before the > next card is inserted.] > > Regarding your comment 3 (attachment 162351 [details]): Do I understand > correctly that the desirable behavior (detect an exchange of cards while the > reader remains plugged in) actually worked from 357 to 387, but failed from > 453 to 461? If my understanding is correct, do you have a suggestion what > was different between the exchange at 357--387 and the one at 453--461? In order: Yes. No. It seems non-deterministic, but mainly it fails and I have to completely disconnect the reader. Reader is a Lexar RW019 Rev B. The same behavior is never reproducible on OS X, i.e. it always works as expected. So I don't know if it's the card reader itself, or maybe something with the particular FireWire hardware in this system that Apple knows something about that we don't know.
Please attach /sys/bus/firewire/devices/fw1/config_rom. (This is a binary file. If you prefer you can convert it into an annotated hexdump with a python script called "crpp" from http://me.in-berlin.de/~s5r6/linux1394/utils/, but I can do that conversion too.) Also, when your time permits, please create another kernel log after enabling self-ID packet logging: $ sudo dd of=/sys/module/firewire_ohci/parameters/debug <<< 2 This is supposed to add lines similar to the following ones to the kernel log whenever the FireWire bus is reset: firewire_ohci 0000:12:03.0: 2 selfIDs, generation 12, local node ID ffc1 firewire_ohci 0000:12:03.0: selfID 0: 807f8f80, phy 0 [p..] S400 gc=63 -3..-10W Lc firewire_ohci 0000:12:03.0: selfID 0: 817f8cd2, phy 1 [c-.] S400 gc=63 -3W Lci Best would be such a debug log with incidences not only of unsuccessful card replugs, but also with one or another of the rare successful replugs.