trueos / trueos-core

59 stars 18 forks source link

Blackout after disconnection of a USB mass storage device, force required to stop the computer #190

Closed grahamperrin closed 7 years ago

grahamperrin commented 7 years ago

HP EliteBook 850 G2 in a dock, with a JVC camcorder at one of the two USB ports on the left of the notebook.

I made two, probably no more, mount tray attempts to mount the FAT32 volume that is offered by the camcorder. Both attempts failed and given other known issues affecting msdosfs, I decided to make no further attempt. With an assumption that mount had not occurred and that disconnection would be safe, I removed the USB plug from the port of the notebook.

A blackout occurred. From /var/log/messages here are lines from the time of the incident:

Friday, December 09, 2016 09:31:23 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  ugen0.12: <JVC GZ-MG361> at usbus0
Friday, December 09, 2016 09:31:23 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  umass0 on uhub1
Friday, December 09, 2016 09:31:23 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  umass0: <JVC GZ-MG361, class 0/0, rev 2.00/10.01, addr 11> on usbus0
Friday, December 09, 2016 09:31:23 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  umass0:  SCSI over Bulk-Only; quirks = 0xc000
Friday, December 09, 2016 09:31:23 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  umass0:1:0: Attached to scbus1
Friday, December 09, 2016 09:31:23 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  da0 at umass-sim0 bus 0 scbus1 target 0 lun 0
Friday, December 09, 2016 09:31:23 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  da0: <JVC GZ-MG361 1.1> Removable Direct Access SCSI-2 device
Friday, December 09, 2016 09:31:23 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  da0: 40.000MB/s transfers
Friday, December 09, 2016 09:31:23 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  da0: 57160MB (117065655 512 byte sectors)
Friday, December 09, 2016 09:31:23 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  da0: quirks=0x2<NO_6_BYTE>
Friday, December 09, 2016 09:31:23 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  da1 at umass-sim0 bus 0 scbus1 target 0 lun 1
Friday, December 09, 2016 09:31:23 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  da1: <JVC GZ-MG361 1.1> Removable Direct Access SCSI-2 device
Friday, December 09, 2016 09:31:23 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  da1: 40.000MB/s transfers
Friday, December 09, 2016 09:31:23 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  da1: Attempt to query device size failed: NOT READY, Medium not present
Friday, December 09, 2016 09:31:23 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  da1: quirks=0x2<NO_6_BYTE>
Friday, December 09, 2016 09:31:40 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  (da0:umass-sim0:0:0:0): WRITE(10). CDB: 2a 00 00 00 00 5f 00 00 08 00 
Friday, December 09, 2016 09:31:40 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  (da0:umass-sim0:0:0:0): CAM status: SCSI Status Error
Friday, December 09, 2016 09:31:40 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  (da0:umass-sim0:0:0:0): SCSI status: Check Condition
Friday, December 09, 2016 09:31:40 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  (da0:umass-sim0:0:0:0): SCSI sense: DATA PROTECT asc:27,0 (Write protected)
Friday, December 09, 2016 09:31:40 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  (da0:umass-sim0:0:0:0): Error 13, Unretryable error
Friday, December 09, 2016 09:31:40 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  g_vfs_done():da0s1[WRITE(offset=16384, length=4096)]error = 13
Friday, December 09, 2016 09:31:40 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  (da0:umass-sim0:0:0:0): WRITE(10). CDB: 2a 00 00 00 00 5f 00 00 08 00 
Friday, December 09, 2016 09:31:40 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  (da0:umass-sim0:0:0:0): CAM status: SCSI Status Error
Friday, December 09, 2016 09:31:40 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  (da0:umass-sim0:0:0:0): SCSI status: Check Condition
Friday, December 09, 2016 09:31:40 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  (da0:umass-sim0:0:0:0): SCSI sense: DATA PROTECT asc:27,0 (Write protected)
Friday, December 09, 2016 09:31:40 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  (da0:umass-sim0:0:0:0): Error 13, Unretryable error
Friday, December 09, 2016 09:31:40 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  g_vfs_done():da0s1[WRITE(offset=16384, length=4096)]error = 13
Friday, December 09, 2016 09:31:40 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  (da0:umass-sim0:0:0:0): WRITE(10). CDB: 2a 00 00 00 00 5f 00 00 08 00 
Friday, December 09, 2016 09:31:40 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  (da0:umass-sim0:0:0:0): CAM status: SCSI Status Error
Friday, December 09, 2016 09:31:40 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  (da0:umass-sim0:0:0:0): SCSI status: Check Condition
Friday, December 09, 2016 09:31:40 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  (da0:umass-sim0:0:0:0): SCSI sense: DATA PROTECT asc:27,0 (Write protected)
Friday, December 09, 2016 09:31:40 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  (da0:umass-sim0:0:0:0): Error 13, Unretryable error
Friday, December 09, 2016 09:31:40 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  g_vfs_done():da0s1[WRITE(offset=16384, length=4096)]error = 13
Friday, December 09, 2016 09:31:40 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  fsync: giving up on dirty 0xfffff802b85b53b0: tag devfs, type VCHR
Friday, December 09, 2016 09:31:40 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  usecount 1, writecount 0, refcount 1790 mountedhere 0xfffff8017817c200
Friday, December 09, 2016 09:31:40 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  flags (VI_ACTIVE)
Friday, December 09, 2016 09:31:40 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  v_object 0xfffff801f518ecc0 ref 0 pages 1788 cleanbuf 1787 dirtybuf 1
Friday, December 09, 2016 09:31:40 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  lock type devfs: UNLOCKED
Friday, December 09, 2016 09:31:40 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  dev da0s1
Friday, December 09, 2016 09:31:48 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  (da0:umass-sim0:0:0:0): WRITE(10). CDB: 2a 00 00 00 00 5f 00 00 08 00 
Friday, December 09, 2016 09:31:48 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  (da0:umass-sim0:0:0:0): CAM status: SCSI Status Error
Friday, December 09, 2016 09:31:48 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  (da0:umass-sim0:0:0:0): SCSI status: Check Condition
Friday, December 09, 2016 09:31:48 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  (da0:umass-sim0:0:0:0): SCSI sense: DATA PROTECT asc:27,0 (Write protected)
Friday, December 09, 2016 09:31:48 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  (da0:umass-sim0:0:0:0): Error 13, Unretryable error
Friday, December 09, 2016 09:31:48 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  g_vfs_done():da0s1[WRITE(offset=16384, length=4096)]error = 13
Friday, December 09, 2016 09:31:48 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  (da0:umass-sim0:0:0:0): WRITE(10). CDB: 2a 00 00 00 00 5f 00 00 08 00 
Friday, December 09, 2016 09:31:48 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  (da0:umass-sim0:0:0:0): CAM status: SCSI Status Error
Friday, December 09, 2016 09:31:48 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  (da0:umass-sim0:0:0:0): SCSI status: Check Condition
Friday, December 09, 2016 09:31:48 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  (da0:umass-sim0:0:0:0): SCSI sense: DATA PROTECT asc:27,0 (Write protected)
Friday, December 09, 2016 09:31:48 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  (da0:umass-sim0:0:0:0): Error 13, Unretryable error
Friday, December 09, 2016 09:31:48 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  g_vfs_done():da0s1[WRITE(offset=16384, length=4096)]error = 13
Friday, December 09, 2016 09:31:48 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  (da0:umass-sim0:0:0:0): WRITE(10). CDB: 2a 00 00 00 00 5f 00 00 08 00 
Friday, December 09, 2016 09:31:48 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  (da0:umass-sim0:0:0:0): CAM status: SCSI Status Error
Friday, December 09, 2016 09:31:48 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  (da0:umass-sim0:0:0:0): SCSI status: Check Condition
Friday, December 09, 2016 09:31:48 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  (da0:umass-sim0:0:0:0): SCSI sense: DATA PROTECT asc:27,0 (Write protected)
Friday, December 09, 2016 09:31:48 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  (da0:umass-sim0:0:0:0): Error 13, Unretryable error
Friday, December 09, 2016 09:31:48 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  g_vfs_done():da0s1[WRITE(offset=16384, length=4096)]error = 13
Friday, December 09, 2016 09:31:48 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  fsync: giving up on dirty 0xfffff802b85b53b0: tag devfs, type VCHR
Friday, December 09, 2016 09:31:48 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  usecount 1, writecount 0, refcount 1790 mountedhere 0xfffff8017817c200
Friday, December 09, 2016 09:31:48 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  flags (VI_ACTIVE)
Friday, December 09, 2016 09:31:48 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  v_object 0xfffff801f518ecc0 ref 0 pages 1788 cleanbuf 1787 dirtybuf 1
Friday, December 09, 2016 09:31:48 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  lock type devfs: UNLOCKED
Friday, December 09, 2016 09:31:48 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  dev da0s1
Friday, December 09, 2016 09:32:02 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  ugen0.12: <JVC GZ-MG361> at usbus0 (disconnected)
Friday, December 09, 2016 09:32:02 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  umass0: at uhub1, port 2, addr 11 (disconnected)
Friday, December 09, 2016 09:32:02 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  da0 at umass-sim0 bus 0 scbus1 target 0 lun 0
Friday, December 09, 2016 09:32:02 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  da0: <JVC GZ-MG361 1.1> detached
Friday, December 09, 2016 09:32:02 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  da1 at umass-sim0 bus 0 scbus1 target 0 lun 1
Friday, December 09, 2016 09:32:02 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  da1: <JVC GZ-MG361 1.1> detached
Friday, December 09, 2016 09:32:02 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  (da1:umass-sim0:0:0:1): Periph destroyed
Friday, December 09, 2016 09:32:02 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  (da0:umass-sim0:0:0:0): Periph destroyed
Friday, December 09, 2016 09:32:02 AM   momh167-gjp4-hpelitebook850g2-trueos    kernel  umass0: detached

The OS seemed unresponsive to a simple press on the power button, eventually I forced off the computer.

messages.txt

grahamperrin commented 7 years ago

With an assumption that mount had not occurred

In retrospect:

– now I see, the lines relating to fsync(1).

If false:

In any case:


I wonder what happens when a simple USB flash drive with msdosfs is hot unplugged. I'll test. …

$ date ; uptime ; uname -v 
Sat 10 Dec 2016 14:39:25 GMT
 2:39p.m.  up  8:51, 2 users, load averages: 1.29, 0.90, 0.87
FreeBSD 12.0-CURRENT #55 4fde044(drm-next-4.7): Fri Dec  9 20:03:40 UTC 2016     root@gauntlet:/usr/obj/usr/src/sys/GENERIC 
$ mount | grep msdosfs
/dev/da0s1 on /media/DOLLY (msdosfs, local)
$ ls -dl /media/DOLLY
ls: /media/DOLLY: No such file or directory
$ # hey ho but probably good enough for a test in relation to 
$ # https://github.com/trueos/trueos-core/issues/190#issuecomment-266210335
$ # -- I'll paste this to the issue and then pull the flash drive from the 
$ #    frontmost right-hand USB port of this HP EliteBook 850 G2 ...
$ 

Result

No blackout, although (above) let's note that the mounted file system was not browseable before this hot unplug:

$ date ; tail -n 28 /var/log/messages
Sat 10 Dec 2016 14:45:57 GMT
Dec 10 11:20:33 momh167-gjp4-hpelitebook850g2-trueos kernel: pid 58062 (WebKitWebProcess), uid 1004: exited on signal 11
Dec 10 12:06:15 momh167-gjp4-hpelitebook850g2-trueos kernel: ugen0.8: <JetFlash Mass Storage Device> at usbus0 (disconnected)
Dec 10 12:06:15 momh167-gjp4-hpelitebook850g2-trueos kernel: umass0: at uhub2, port 4, addr 7 (disconnected)
Dec 10 12:06:15 momh167-gjp4-hpelitebook850g2-trueos kernel: da0 at umass-sim0 bus 0 scbus1 target 0 lun 0
Dec 10 12:06:15 momh167-gjp4-hpelitebook850g2-trueos kernel: da0: <JetFlash Transcend 2GB 1100> s/n FTRR0IBTVZ58PPPJ detached
Dec 10 12:06:15 momh167-gjp4-hpelitebook850g2-trueos kernel: (da0:umass-sim0:0:0:0): Periph destroyed
Dec 10 12:06:15 momh167-gjp4-hpelitebook850g2-trueos kernel: umass0: detached
Dec 10 12:27:59 momh167-gjp4-hpelitebook850g2-trueos sshd[71242]: warning: /etc/hosts.allow, line 35: host name/address mismatch: 95.215.199.253 != ip-199-253.omega.net.pl
Dec 10 14:37:25 momh167-gjp4-hpelitebook850g2-trueos kernel: ugen0.9: <Android Android> at usbus0 (disconnected)
Dec 10 14:37:55 momh167-gjp4-hpelitebook850g2-trueos kernel: ugen0.8: <Verbatim STORE N GO> at usbus0
Dec 10 14:37:55 momh167-gjp4-hpelitebook850g2-trueos kernel: umass0 on uhub2
Dec 10 14:37:55 momh167-gjp4-hpelitebook850g2-trueos kernel: umass0: <Verbatim STORE N GO, class 0/0, rev 2.00/1.00, addr 9> on usbus0
Dec 10 14:37:55 momh167-gjp4-hpelitebook850g2-trueos kernel: umass0:  SCSI over Bulk-Only; quirks = 0xc100
Dec 10 14:37:55 momh167-gjp4-hpelitebook850g2-trueos kernel: umass0:1:0: Attached to scbus1
Dec 10 14:37:55 momh167-gjp4-hpelitebook850g2-trueos kernel: da0 at umass-sim0 bus 0 scbus1 target 0 lun 0
Dec 10 14:37:55 momh167-gjp4-hpelitebook850g2-trueos kernel: da0: <Verbatim STORE N GO 5.00> Removable Direct Access SCSI device
Dec 10 14:37:55 momh167-gjp4-hpelitebook850g2-trueos kernel: da0: Serial Number 070B29D2DF235960
Dec 10 14:37:55 momh167-gjp4-hpelitebook850g2-trueos kernel: da0: 40.000MB/s transfers
Dec 10 14:37:55 momh167-gjp4-hpelitebook850g2-trueos kernel: da0: 3815MB (7814304 512 byte sectors)
Dec 10 14:37:55 momh167-gjp4-hpelitebook850g2-trueos kernel: da0: quirks=0x2<NO_6_BYTE>
Dec 10 14:42:47 momh167-gjp4-hpelitebook850g2-trueos sshd[93769]: warning: /etc/hosts.allow, line 35: can't verify hostname: getaddrinfo(45.32.158.170.vultr.com, AF_INET) failed
Dec 10 14:42:52 momh167-gjp4-hpelitebook850g2-trueos sshd[93781]: warning: /etc/hosts.allow, line 35: can't verify hostname: getaddrinfo(45.32.158.170.vultr.com, AF_INET) failed
Dec 10 14:43:50 momh167-gjp4-hpelitebook850g2-trueos kernel: ugen0.8: <Verbatim STORE N GO> at usbus0 (disconnected)
Dec 10 14:43:50 momh167-gjp4-hpelitebook850g2-trueos kernel: umass0: at uhub2, port 4, addr 9 (disconnected)
Dec 10 14:43:50 momh167-gjp4-hpelitebook850g2-trueos kernel: da0 at umass-sim0 bus 0 scbus1 target 0 lun 0
Dec 10 14:43:50 momh167-gjp4-hpelitebook850g2-trueos kernel: da0: <Verbatim STORE N GO 5.00> s/n 070B29D2DF235960 detached
Dec 10 14:43:50 momh167-gjp4-hpelitebook850g2-trueos kernel: (da0:umass-sim0:0:0:0): Periph destroyed
Dec 10 14:43:50 momh167-gjp4-hpelitebook850g2-trueos kernel: umass0: detached
$ ls -al /media/
total 18
drwxr-xr-x   2 root  wheel   2 10 Dec 14:38 .
drwxr-xr-x  22 root  wheel  30 10 Dec 14:38 ..
$ 
pkgdemon commented 7 years ago

I was able to reproduce this with earlier builds. I am no longer able to reproduce. If it is still an issue let me know, and I will re-open.

grahamperrin commented 7 years ago

:+1:

Whilst I had no opportunity to retest with the same camcorder, over a period of around two weeks I did experiment with (ungraceful) hot unplugging of other devices, in various states, from USB. Not many, only a handful of experiments.

For me the blackout was a one-off.

pkgdemon commented 7 years ago

Reopened. I have encountered this as well recently. I think we can fix with the new mounting system.

pkgdemon commented 7 years ago

Mounttray is being depreciated this week. I have sent in the pull requests for the new devd based automounter to replace it.