Bug 10038 - [Upstream] Syslog fills with messages about assuming drive cache when SD card not present
Summary: [Upstream] Syslog fills with messages about assuming drive cache when SD card...
Status: RESOLVED FIXED
Alias: None
Product: Mageia
Classification: Unclassified
Component: RPM Packages (show other bugs)
Version: 6
Hardware: All Linux
Priority: Normal normal
Target Milestone: ---
Assignee: Kernel and Drivers maintainers
QA Contact:
URL: https://bugzilla.kernel.org/show_bug....
Whiteboard: MGA4TOO MGA5TOO
Keywords: UPSTREAM
Depends on:
Blocks:
 
Reported: 2013-05-09 14:47 CEST by Morgan Leijström
Modified: 2020-08-07 01:48 CEST (History)
1 user (show)

See Also:
Source RPM: 4.9.43-desktop-1.mga6
CVE:
Status comment:


Attachments
lspci (2.46 KB, text/plain)
2013-05-13 01:22 CEST, Morgan Leijström
Details

Description Morgan Leijström 2013-05-09 14:47:52 CEST
When a USB memory is plugged in but do not have its SD card inserted, logs fills rapidly with error messages.

It is known and assigned upstream: https://bugzilla.kernel.org/show_bug.cgi?id=43191 but i post here so we can keep track.

The error itself is not the problem, but when /var or / is fill, you know what happens...

For me the logs fills with a couple hundred iterations per second (!) of the lines:

May 09 14:19:32 svarten kernel: sd 12:0:0:0: [sdc] Test WP failed, assume Write Enabled
May 09 14:19:32 svarten kernel: sd 12:0:0:0: [sdc] Assuming drive cache: write through


Steps to Reproduce:
I plugged in Velleman CAMCOLVC8N1 keychain video camera without microSD inserted, and the next morning my computer had stopped working normally, / was full...

That computer ran mga1, it is still valid on current cauldron, so i assume mga2 as well.

Reproducible: 

Steps to Reproduce:
Morgan Leijström 2013-05-09 14:48:07 CEST

Whiteboard: (none) => MGA2TOO

Manuel Hiebel 2013-05-11 22:56:46 CEST

Keywords: (none) => UPSTREAM

Comment 1 Morgan Leijström 2013-05-13 01:21:09 CEST
It is worse than described earlier:

If i have the device plugged in when powering on my computer,  it spews that shit in the logs during boot even if SD is inserted.  And it boots very slow then.

If i then unplug it and plug it it mounts OK no problem.
Here is what /var/log/messages say when i then plug in the device:


May 13 01:18:58 svarten kernel: usb 1-1.1: new high-speed USB device number 5 using ehci-pci
May 13 01:18:58 svarten kernel: usb 1-1.1: New USB device found, idVendor=1b3f, idProduct=0c52
May 13 01:18:58 svarten kernel: usb 1-1.1: New USB device strings: Mfr=1, Product=1, SerialNumber=1
May 13 01:18:58 svarten kernel: usb 1-1.1: Product: Generic USB Mass Storage Device
May 13 01:18:58 svarten kernel: usb 1-1.1: Manufacturer: Generic USB Mass Storage Device
May 13 01:18:58 svarten kernel: usb 1-1.1: SerialNumber: Generic USB Mass Storage Device
May 13 01:19:02 svarten mtp-probe: checking bus 1, device 5: "/sys/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.1"
May 13 01:19:02 svarten mtp-probe: bus: 1, device: 5 was not an MTP device
May 13 01:18:58 svarten kernel: scsi12 : usb-storage 1-1.1:1.0
May 13 01:18:59 svarten kernel: scsi 12:0:0:0: Direct-Access     GENPLUS  USB-MSDC DISK A  1.00 PQ: 0 ANSI: 0
May 13 01:18:59 svarten kernel: sd 12:0:0:0: [sdb] 3842048 512-byte logical blocks: (1.96 GB/1.83 GiB)
May 13 01:18:59 svarten kernel: sd 12:0:0:0: [sdb] Write Protect is off
May 13 01:18:59 svarten kernel: sd 12:0:0:0: [sdb] No Caching mode page present
May 13 01:18:59 svarten kernel: sd 12:0:0:0: [sdb] Assuming drive cache: write through
May 13 01:18:59 svarten kernel: sd 12:0:0:0: [sdb] No Caching mode page present
May 13 01:18:59 svarten kernel: sd 12:0:0:0: [sdb] Assuming drive cache: write through
May 13 01:18:59 svarten kernel:  sdb: sdb1
May 13 01:18:59 svarten kernel: sd 12:0:0:0: [sdb] No Caching mode page present
May 13 01:18:59 svarten kernel: sd 12:0:0:0: [sdb] Assuming drive cache: write through
May 13 01:18:59 svarten kernel: sd 12:0:0:0: [sdb] Attached SCSI removable disk
Comment 2 Morgan Leijström 2013-05-13 01:22:44 CEST
Created attachment 3951 [details]
lspci
Comment 3 Samuel Verschelde 2015-05-06 21:04:41 CEST
Closing as OLD. Please reopen if needed.

Resolution: (none) => OLD
Status: NEW => RESOLVED

Comment 4 Morgan Leijström 2015-05-07 11:56:52 CEST
Upstream is still "assigned"

The messages are different now, but log fills quickly so I reopen;

When i plug in that device with medium not inserted,
i get in system log 30 lines per second of:

maj 07 11:48:34 svarten systemd-udevd[786]: error: /dev/sdc: No medium found


Even worse, when i unplug it i get high rate of repeating:

maj 07 11:54:02 svarten systemd-udevd[25550]: inotify_add_watch(7, /dev/sdc, 10) failed: No such file or directory
maj 07 11:54:02 svarten systemd-udevd[786]: error: /dev/sdc: No such file or directory


Need to reboot now...


$ uname -a
Linux svarten 3.19.4-desktop-2.mga5 #1 SMP Fri Apr 17 21:49:33 UTC 2015 x86_64 x86_64 x86_64 GNU/Linux

Resolution: OLD => (none)
Status: RESOLVED => REOPENED

Comment 5 Morgan Leijström 2015-05-07 12:13:08 CEST
Not same messages, but may be same cause.
The trig and result is the same: when user plugs in this kind of flash reader system logs get spammed heavily, and when user removes it the spam get even worse. - reboot needed not to fill up logs partition. ( / on a default install!)
If not so unusual reader (?) this would have earned critical status.

Whiteboard: MGA2TOO => MGA4TOO
Source RPM: kernel-desktop-3.8.12-1.mga3 => kernel-desktop-3.19.4-2.mga5

Samuel Verschelde 2016-10-15 22:53:32 CEST

Assignee: bugsquad => kernel

Comment 6 Morgan Leijström 2017-08-25 18:07:40 CEST
Still valid like comment 4 with, same device, same compouter, mga6-64, kernel 4.9.43-desktop-1.mga6
Nowadays both /var/log/messages and /var/log/syslog grows.

When i connect the camera to USB in without SD card spews to /var/log/messages a couple hundred lines of:

Aug 25 17:34:39 svarten systemd-udevd[31234]: inotify_add_watch(9, /dev/sdd, 10) failed: No such file or directory

End then:

Aug 25 17:34:39 svarten kernel: [ 9469.213241] scsi 10:0:0:0: Direct-Access     GENPLUS  USB-MSDC DISK A  1.00 PQ: 0 ANSI: 0
Aug 25 17:34:39 svarten systemd-udevd[31234]: inotify_add_watch(9, /dev/sdd, 10) failed: No such file or directory
Aug 25 17:34:39 svarten kernel: [ 9469.215607] sd 10:0:0:0: [sdd] Test WP failed, assume Write Enabled
Aug 25 17:34:39 svarten kernel: [ 9469.216735] sd 10:0:0:0: [sdd] Asking for cache data failed
Aug 25 17:34:39 svarten kernel: [ 9469.216737] sd 10:0:0:0: [sdd] Assuming drive cache: write through
Aug 25 17:34:39 svarten kernel: [ 9469.217102] sd 10:0:0:0: [sdd] Attached SCSI removable disk

And stops.   Acceptable so far.
But when i then unplug it from USB it starts again spewing lines like

Aug 25 17:37:41 svarten systemd-udevd[31234]: inotify_add_watch(9, /dev/sdd, 10) failed: No such file or directory

About a hundred lines per second.

Logging stops like above if i plug in the camera again - but interestingly systemd-udevd still occupies one CPU core 100%.

If i insert the SD card, and then plug in the camera, the SD is not found, and one CPU is still running full.

As this was a problem in mga2, 3, 4 and now in 6, i assume it is MGA5TOO
Also, still not solved upstream.

Source RPM: kernel-desktop-3.19.4-2.mga5 => 4.9.43-desktop-1.mga6
Whiteboard: MGA4TOO => MGA4TOO MGA5TOO

Comment 7 Morgan Leijström 2017-08-25 18:10:23 CEST
mga6 ; not tried in cauldron as i dont run Cauldron anywhere currently.

Version: Cauldron => 6

Comment 8 Morgan Leijström 2017-08-26 12:24:22 CEST
Current behaviour per comment 6 filed as https://bugzilla.kernel.org/show_bug.cgi?id=196781
Comment 9 Aurelien Oudelet 2020-08-05 15:44:59 CEST
Hi Morgan,

Does it still apply to Mageia 7 and Cauldron ?

CC: (none) => ouaurelien

Comment 10 Morgan Leijström 2020-08-05 21:15:55 CEST
Thank you for the reminder.
The bug about filling log seem gone now on current Mageia 7 !
(I have no mga8 yet)

# uname -a
Linux svarten.tribun 5.6.14-desktop-2.mga7 #1 SMP Wed May 20 23:14:20 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux

I run the same machine (but upgraded CPU as the former broke):
# journalctl -f
And when plugging in the same device as in Comment 0, with SD card ejected, i now get:

aug 05 19:08:54 svarten.tribun kernel: usb 2-1.1: new high-speed USB device number 6 using ehci-pci
aug 05 19:08:54 svarten.tribun kernel: usb 2-1.1: device descriptor read/64, error -71
aug 05 19:08:54 svarten.tribun kernel: usb 2-1.1: device descriptor read/64, error -71
aug 05 19:08:55 svarten.tribun kernel: usb 2-1.1: new high-speed USB device number 7 using ehci-pci
aug 05 19:08:55 svarten.tribun kernel: usb 2-1.1: device descriptor read/64, error -71
aug 05 19:08:55 svarten.tribun kernel: usb 2-1.1: device descriptor read/64, error -71
aug 05 19:08:55 svarten.tribun kernel: usb 2-1-port1: attempt power cycle

And no more messages about it.
But strange.  Let it charge, and also changed cable, then on new connect i get more action, still with no SD card in it:


aug 05 21:02:44 svarten.tribun kernel: usb 2-1.2: new high-speed USB device number 19 using ehci-pci
aug 05 21:02:44 svarten.tribun kernel: usb 2-1.2: New USB device found, idVendor=1b3f, idProduct=0c52, bcdDevice= 1.00
aug 05 21:02:44 svarten.tribun kernel: usb 2-1.2: New USB device strings: Mfr=1, Product=1, SerialNumber=1
aug 05 21:02:44 svarten.tribun kernel: usb 2-1.2: Product: Generic USB Mass Storage Device
aug 05 21:02:44 svarten.tribun kernel: usb 2-1.2: Manufacturer: Generic USB Mass Storage Device
aug 05 21:02:44 svarten.tribun kernel: usb 2-1.2: SerialNumber: Generic USB Mass Storage Device
aug 05 21:02:44 svarten.tribun kernel: usb-storage 2-1.2:1.0: USB Mass Storage device detected
aug 05 21:02:44 svarten.tribun kernel: scsi host10: usb-storage 2-1.2:1.0
aug 05 21:02:44 svarten.tribun mtp-probe[25101]: checking bus 2, device 19: "/sys/devices/pci0000:00/0000:00:1a.0/usb2/2-1/2-1.2"
aug 05 21:02:44 svarten.tribun mtp-probe[25101]: bus: 2, device: 19 was not an MTP device
aug 05 21:02:44 svarten.tribun krunner[28983]: UdevQt: unhandled device action "bind"
aug 05 21:02:44 svarten.tribun plasmashell[28986]: UdevQt: unhandled device action "bind"
aug 05 21:02:44 svarten.tribun dolphin[30492]: UdevQt: unhandled device action "bind"
aug 05 21:02:44 svarten.tribun dolphin[28808]: UdevQt: unhandled device action "bind"
aug 05 21:02:44 svarten.tribun org_kde_powerdevil[29071]: UdevQt: unhandled device action "bind"
aug 05 21:02:44 svarten.tribun mtp-probe[25119]: checking bus 2, device 19: "/sys/devices/pci0000:00/0000:00:1a.0/usb2/2-1/2-1.2"
aug 05 21:02:44 svarten.tribun mtp-probe[25119]: bus: 2, device: 19 was not an MTP device
aug 05 21:02:44 svarten.tribun plasmashell[28986]: UdevQt: unhandled device action "bind"
aug 05 21:02:44 svarten.tribun krunner[28983]: UdevQt: unhandled device action "bind"
aug 05 21:02:44 svarten.tribun org_kde_powerdevil[29071]: UdevQt: unhandled device action "bind"
aug 05 21:02:44 svarten.tribun dolphin[30492]: UdevQt: unhandled device action "bind"
aug 05 21:02:44 svarten.tribun dolphin[28808]: UdevQt: unhandled device action "bind"
aug 05 21:02:45 svarten.tribun kernel: logflags DROP IN=eno1 OUT= MAC=f4:6d:04:e4:c4:23:c4:a8:1d:8e:0d:40:08:00 SRC=96.127.206.179 DST=192.168.0.114 LEN=40 TOS=0x00 PREC=0x00 TTL=53 ID=56992 PROTO=TCP SPT=56202 DPT=57314 WINDOW=0 RES=0x00 ACK RST FIN URGP=0 
aug 05 21:02:45 svarten.tribun kernel: scsi 10:0:0:0: Direct-Access     GENPLUS  USB-MSDC DISK A  1.00 PQ: 0 ANSI: 0
aug 05 21:02:45 svarten.tribun kernel: sd 10:0:0:0: [sdc] 0 512-byte logical blocks: (0 B/0 B)
aug 05 21:02:45 svarten.tribun kernel: sd 10:0:0:0: [sdc] 0-byte physical blocks
aug 05 21:02:45 svarten.tribun kernel: sd 10:0:0:0: [sdc] Test WP failed, assume Write Enabled
aug 05 21:02:45 svarten.tribun kernel: sd 10:0:0:0: [sdc] Asking for cache data failed
aug 05 21:02:45 svarten.tribun kernel: sd 10:0:0:0: [sdc] Assuming drive cache: write through
aug 05 21:02:45 svarten.tribun kernel: sd 10:0:0:0: [sdc] Attached SCSI removable disk



>>>> 
   And no more logging, so that bug about filling up log seem gone.
<<<<


Ejected:

aug 05 21:06:03 svarten.tribun kernel: usb 2-1.2: USB disconnect, device number 19
aug 05 21:06:03 svarten.tribun kernel: scsi 10:0:0:0: rejecting I/O to dead device


Inserted SD-card, and connected device again:

aug 05 21:07:42 svarten.tribun kernel: usb 2-1.2: new high-speed USB device number 20 using ehci-pci
aug 05 21:07:42 svarten.tribun kernel: usb 2-1.2: New USB device found, idVendor=1b3f, idProduct=0c52, bcdDevice= 1.00
aug 05 21:07:42 svarten.tribun kernel: usb 2-1.2: New USB device strings: Mfr=1, Product=1, SerialNumber=1
aug 05 21:07:42 svarten.tribun kernel: usb 2-1.2: Product: Generic USB Mass Storage Device
aug 05 21:07:42 svarten.tribun kernel: usb 2-1.2: Manufacturer: Generic USB Mass Storage Device
aug 05 21:07:42 svarten.tribun kernel: usb 2-1.2: SerialNumber: Generic USB Mass Storage Device
aug 05 21:07:42 svarten.tribun kernel: usb-storage 2-1.2:1.0: USB Mass Storage device detected
aug 05 21:07:42 svarten.tribun kernel: scsi host10: usb-storage 2-1.2:1.0
aug 05 21:07:43 svarten.tribun kernel: scsi 10:0:0:0: Direct-Access     GENPLUS  USB-MSDC DISK A  1.00 PQ: 0 ANSI: 0
aug 05 21:07:43 svarten.tribun kernel: sd 10:0:0:0: [sdc] 31950848 512-byte logical blocks: (16.4 GB/15.2 GiB)
aug 05 21:07:43 svarten.tribun kernel: sd 10:0:0:0: [sdc] Write Protect is off
aug 05 21:07:43 svarten.tribun kernel: sd 10:0:0:0: [sdc] Mode Sense: 03 00 00 00
aug 05 21:07:43 svarten.tribun kernel: sd 10:0:0:0: [sdc] No Caching mode page found
aug 05 21:07:43 svarten.tribun kernel: sd 10:0:0:0: [sdc] Assuming drive cache: write through
aug 05 21:07:43 svarten.tribun kernel:  sdc: sdc1
aug 05 21:07:43 svarten.tribun kernel: sd 10:0:0:0: [sdc] Attached SCSI removable disk



I get no notification in systray, not visible in Dolphin :(
Gparted see it as /dev/sdc1, fat32
And it works to manually mount:
[morgan@svarten mnt]$ sudo mnt /dev/sdc1 /mnt/ext
sudo: mnt: kommandot hittades inte
[morgan@svarten mnt]$ sudo mount /dev/sdc1 /mnt/ext
[morgan@svarten mnt]$ ls ext
20090101/


When disconnecting:

aug 05 21:12:01 svarten.tribun kernel: sd 10:0:0:0: [sdc] tag#0 FAILED Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK cmd_age=0s
aug 05 21:12:01 svarten.tribun kernel: sd 10:0:0:0: [sdc] tag#0 CDB: Read(10) 28 00 01 e7 86 00 00 00 70 00
aug 05 21:12:01 svarten.tribun kernel: blk_update_request: I/O error, dev sdc, sector 31950336 op 0x0:(READ) flags 0x80700 phys_seg 13 prio class 0
aug 05 21:12:01 svarten.tribun kernel: sd 10:0:0:0: [sdc] tag#0 FAILED Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK cmd_age=0s
aug 05 21:12:01 svarten.tribun kernel: sd 10:0:0:0: [sdc] tag#0 CDB: Read(10) 28 00 01 e7 86 78 00 00 80 00
aug 05 21:12:01 svarten.tribun kernel: blk_update_request: I/O error, dev sdc, sector 31950456 op 0x0:(READ) flags 0x80700 phys_seg 9 prio class 0
aug 05 21:12:01 svarten.tribun kernel: usb 2-1.2: USB disconnect, device number 20
aug 05 21:12:01 svarten.tribun kernel: scsi 10:0:0:0: rejecting I/O to dead device
aug 05 21:12:01 svarten.tribun kernel: blk_update_request: I/O error, dev sdc, sector 31950336 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
aug 05 21:12:01 svarten.tribun kernel: Buffer I/O error on dev sdc, logical block 3993792, async page read

And that is it.

Resolution: (none) => FIXED
Status: REOPENED => RESOLVED

Comment 11 Morgan Leijström 2020-08-07 01:48:49 CEST
I said:
> I get no notification in systray, not visible in Dolphin :(

I noticed it works OK on my wifes machine, and also that the original bug do not show there.

It works now on my machine too, i see, testing kernel-desktop-5.7.13-3.mga7-1-1.mga7.x86_64.rpm 

All OK :)

Note You need to log in before you can comment on or make changes to this bug.