On Sat, 2017-07-15 at 00:35 -0500, John Morris wrote: > In Fedora 24 about 2/3 of the time when I login the only item in > Computer was "File System" and inserted media (CD/USB) neither mounts or > appears. The other 1/3 of the time it worked. Not good. But the clock > is ticking on F24 now so I updated to Fedora 25 and it got worse. I get > entries for every mount point, tmp, sys, everything plus I get desktop > icons for them all too. This is on Mate if you are wondering why I have > icons on the desktop. But at least it is now consistent, it happens > every time. Ok, have dug into this some more. It isn't a problem in my account, it is a timing problem tied to my USB card reader. If I wait a minute after booting my account always works. But if I login quickly and it fails, logging out and waiting won't fit it, only a reboot will. Looks like the card reader is jamming things up for close to a minute and the timeout is 25 seconds. So two questions. 1. Where should I file the bug? UDev, GVFS or Caja? 2. The bit where it throws up every mount point seems vaguely worrying. It won't important mount points or anything but a USB insertion being able to destabilize the system this badly just screams exploitable. Any ideas where to try poking it to try breaking it? Here are the results of my digging so Google can index it for the next person to hit this. I cut it down to the important bits to avoid hitting max message size but I do have the whole /var/log/messages if somebody wants to see something I cut. And yes the reader works if I insert a card if I waited to login. /var/log/messages: -First message of boot Jul 29 12:35:42 bob kernel: Linux version 4.11.12-200.fc25.x86_64 (mockbuild@xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx) (gcc version 6.3.1 20161221 (Red Hat 6.3.1-1) (GCC) ) #1 SMP Fri Jul 21 16:41:43 UTC 2017 Jul 29 12:35:42 bob kernel: Command line: BOOT_IMAGE=/vmlinuz-4.11.12-200.fc25.x86_64 root=UUID=dee96c74-51d4-485a-9afe-0943e068ddb2 ro net.ifnames=0 biosdevname=0 iommu=soft resume=/dev/nvme0n1p5 quiet rhgb LANG=en_US.UTF-8 -skipping ahead a bit -See the USB card reader during early phase Jul 29 12:35:43 bob kernel: usb 11-3: New USB device found, idVendor=05e3, idProduct=0732 Jul 29 12:35:43 bob kernel: usb 11-3: New USB device strings: Mfr=0, Product=1, SerialNumber=2 Jul 29 12:35:43 bob kernel: usb 11-3: Product: USB Storage Jul 29 12:35:43 bob kernel: usb 11-3: SerialNumber: 000000000570 -snip some video Jul 29 12:35:43 bob kernel: usb-storage 11-3:1.0: USB Mass Storage device detected Jul 29 12:35:43 bob kernel: scsi host6: usb-storage 11-3:1.0 Jul 29 12:35:43 bob kernel: usbcore: registered new interface driver usb-storage Jul 29 12:35:43 bob kernel: usbcore: registered new interface driver uas -snip more radeon startup and other stuff, pick up story at pivot root Jul 29 12:35:44 bob systemd: Reached target Initrd Root File System. Jul 29 12:35:44 bob systemd: Starting Reload Configuration from the Real Root... Jul 29 12:35:44 bob systemd: Reloading. Jul 29 12:35:44 bob kernel: clocksource: Switched to clocksource tsc Jul 29 12:35:44 bob kernel: scsi 6:0:0:0: Direct-Access Generic STORAGE DEVICE 0570 PQ: 0 ANSI: 6 Jul 29 12:35:44 bob kernel: scsi 6:0:0:1: Direct-Access Generic STORAGE DEVICE 0570 PQ: 0 ANSI: 6 Jul 29 12:35:44 bob kernel: scsi 6:0:0:2: Direct-Access Generic STORAGE DEVICE 0570 PQ: 0 ANSI: 6 Jul 29 12:35:44 bob kernel: scsi 6:0:0:3: Direct-Access Generic STORAGE DEVICE 0570 PQ: 0 ANSI: 6 Jul 29 12:35:44 bob kernel: scsi 6:0:0:4: Direct-Access Generic STORAGE DEVICE 0570 PQ: 0 ANSI: 6 Jul 29 12:35:44 bob kernel: sd 6:0:0:0: Attached scsi generic sg3 type 0 Jul 29 12:35:44 bob kernel: sd 6:0:0:1: Attached scsi generic sg4 type 0 Jul 29 12:35:44 bob kernel: sd 6:0:0:2: Attached scsi generic sg5 type 0 Jul 29 12:35:44 bob kernel: sd 6:0:0:3: Attached scsi generic sg6 type 0 Jul 29 12:35:44 bob kernel: sd 6:0:0:4: Attached scsi generic sg7 type 0 Jul 29 12:35:44 bob systemd: Started Reload Configuration from the Real Root. Jul 29 12:35:44 bob audit: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=initrd-parse-etc comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 29 12:35:44 bob audit: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=initrd-parse-etc comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 29 12:35:44 bob systemd: Reached target Initrd Default Target. Jul 29 12:35:44 bob systemd: Starting dracut pre-pivot and cleanup hook... Jul 29 12:35:44 bob kernel: sd 6:0:0:3: [sdf] Attached SCSI removable disk Jul 29 12:35:44 bob kernel: sd 6:0:0:4: [sdg] Attached SCSI removable disk Jul 29 12:35:44 bob kernel: sd 6:0:0:0: [sdc] Attached SCSI removable disk Jul 29 12:35:44 bob kernel: sd 6:0:0:1: [sdd] Attached SCSI removable disk Jul 29 12:35:44 bob kernel: sd 6:0:0:2: [sde] Attached SCSI removable disk Jul 29 12:35:44 bob systemd: Started dracut pre-pivot and cleanup hook. -skip ahead a bit Jul 29 12:35:49 bob systemd: Started Light Display Manager. -more snippage Jul 29 12:35:51 bob systemd: Started D-Bus User Message Bus. -I login right after boot and trigger the bug Jul 29 12:35:57 bob systemd: Created slice User Slice of jmorris. Jul 29 12:35:57 bob systemd: Starting User Manager for UID 500... Jul 29 12:35:57 bob systemd-logind: New session 2 of user jmorris. Jul 29 12:35:57 bob systemd: Started D-Bus User Message Bus. Jul 29 12:36:01 bob dbus-daemon[1683]: [session uid=500 pid=1683] Activating via systemd: service name='org.gtk.vfs.Daemon' unit='gvfs-daemon.service' requested by ':1.4' (uid=500 pid=1753 comm="/usr/libexec/imsettings-daemon ") Jul 29 12:36:01 bob systemd: Starting Virtual filesystem service... Jul 29 12:36:01 bob dbus-daemon[1683]: [session uid=500 pid=1683] Successfully activated service 'org.gtk.vfs.Daemon' Jul 29 12:36:01 bob systemd: Started Virtual filesystem service. Jul 29 12:36:03 bob systemd: Starting Disk Manager (legacy version)... Jul 29 12:36:03 bob dbus-daemon[949]: [system] Successfully activated service 'org.freedesktop.UDisks' Jul 29 12:36:03 bob systemd: Started Disk Manager (legacy version). Jul 29 12:36:04 bob dbus-daemon[1683]: [session uid=500 pid=1683] Activating via systemd: service name='org.gtk.vfs.UDisks2VolumeMonitor' unit='gvfs-udisks2-volume-monitor.service' requested by ':1.32' (uid=500 pid=1884 comm="/usr/libexec/mate-settings-daemon ") Jul 29 12:36:04 bob systemd: Starting Virtual filesystem service - disk device monitor... Jul 29 12:36:04 bob dbus-daemon[949]: [system] Activating via systemd: service name='org.freedesktop.UDisks2' unit='udisks2.service' requested by ':1.66' (uid=500 pid=2139 comm="/usr/libexec/gvfs-udisks2-volume-monitor ") Jul 29 12:36:04 bob systemd: Starting Disk Manager... Jul 29 12:36:04 bob udisksd[2142]: udisks daemon version 2.6.2 starting Jul 29 12:36:04 bob caja: [N-A] Caja-Actions Tracker 1.8.3 initializing... Jul 29 12:36:07 bob cupsd: CreateDevice failed: org.freedesktop.DBus.Error.NoReply:Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the rep ly timeout expired, or the network connection was broken. -moved on to more messages about CUPS, eliminated Jul 29 12:36:17 bob dbus-daemon[949]: [system] Failed to activate service 'org.freedesktop.ColorManager': timed out (service_start_timeout=25000ms) Jul 29 12:36:28 bob kernel: xhci_hcd 0000:05:00.0: Timeout while waiting for setup device command Jul 29 12:36:29 bob dbus-daemon[949]: [system] Failed to activate service 'org.freedesktop.UDisks2': timed out (service_start_timeout=25000ms) Jul 29 12:36:29 bob journal: monitor says it's not supported Jul 29 12:36:29 bob dbus-daemon[1683]: [session uid=500 pid=1683] Successfully activated service 'org.gtk.vfs.UDisks2VolumeMonitor' Jul 29 12:36:29 bob systemd: Started Virtual filesystem service - disk device monitor. Jul 29 12:36:29 bob journal: monitor says it's not supported Jul 29 12:36:29 bob journal: monitor says it's not supported Jul 29 12:36:29 bob dbus-daemon[1683]: [session uid=500 pid=1683] Activating via systemd: service name='org.gtk.vfs.GPhoto2VolumeMonitor' unit='gvfs-gphoto2-volume-monitor.service' requested by ':1.46' (uid=500 pid=1906 comm="caja ") Jul 29 12:36:29 bob systemd: Starting Virtual filesystem service - digital camera monitor... Jul 29 12:36:29 bob dbus-daemon[1683]: [session uid=500 pid=1683] Successfully activated service 'org.gtk.vfs.GPhoto2VolumeMonitor' Jul 29 12:36:29 bob systemd: Started Virtual filesystem service - digital camera monitor. Jul 29 12:36:29 bob dbus-daemon[1683]: [session uid=500 pid=1683] Activating via systemd: service name='org.gtk.vfs.MTPVolumeMonitor' unit='gvfs-mtp-volume-monitor.service' requested by ':1.46' (uid=500 pid=1906 comm="caja ") Jul 29 12:36:29 bob systemd: Starting Virtual filesystem service - Media Transfer Protocol monitor... Jul 29 12:36:29 bob dbus-daemon[1683]: [session uid=500 pid=1683] Successfully activated service 'org.gtk.vfs.MTPVolumeMonitor' Jul 29 12:36:29 bob systemd: Started Virtual filesystem service - Media Transfer Protocol monitor. Jul 29 12:36:31 bob dbus-daemon[1683]: [session uid=500 pid=1683] Activating via systemd: service name='org.gtk.vfs.Metadata' unit='gvfs-metadata.service' requested by ':1.46' (uid=500 pid=1906 comm="caja ") Jul 29 12:36:31 bob systemd: Starting Virtual filesystem metadata service... Jul 29 12:36:31 bob dbus-daemon[1683]: [session uid=500 pid=1683] Successfully activated service 'org.gtk.vfs.Metadata' Jul 29 12:36:31 bob systemd: Started Virtual filesystem metadata service. Jul 29 12:36:34 bob kernel: xhci_hcd 0000:05:00.0: Timeout while waiting for setup device command Jul 29 12:36:34 bob kernel: usb 11-3: device not accepting address 2, error -62 Jul 29 12:36:34 bob blueman-mechanism: Exiting Jul 29 12:36:34 bob kernel: usb 11-3: reset SuperSpeed USB device number 2 using xhci_hcd Jul 29 12:36:35 bob audit: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=udisks2 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 29 12:36:35 bob systemd: Started Disk Manager. Jul 29 12:36:35 bob systemd: Startup finished in 1.444s (kernel) + 1.697s (initrd) + 47.161s (userspace) = 50.303s. Jul 29 12:36:35 bob udisksd[2142]: Acquired the name org.freedesktop.UDisks2 on the system message bus .xsession-errors: (mate-settings-daemon:1884): GVFS-RemoteVolumeMonitor-WARNING **: remote volume monitor with dbus name org.gtk.vfs.UDisks2VolumeMonitor is not supported dmesg: [ 1.805574] usbcore: registered new interface driver usb-storage [ 1.807791] usbcore: registered new interface driver uas [ 2.848358] scsi 6:0:0:0: Direct-Access Generic STORAGE DEVICE 0570 PQ: 0 ANSI: 6 [ 2.850137] sd 6:0:0:0: Attached scsi generic sg3 type 0 [ 2.877954] sd 6:0:0:3: [sdf] Attached SCSI removable disk [ 44.002152] xhci_hcd 0000:05:00.0: Timeout while waiting for setup device command [ 49.633997] xhci_hcd 0000:05:00.0: Timeout while waiting for setup device command [ 49.841917] usb 11-3: device not accepting address 2, error -62 [ 50.222513] usb 11-3: reset SuperSpeed USB device number 2 using xhci_hcd On a good login: /var/log/messages: Jul 29 14:57:45 bob systemd: Starting Disk Manager... Jul 29 14:57:45 bob udisksd[2132]: udisks daemon version 2.6.2 starting Jul 29 14:57:45 bob dbus-daemon[936]: [system] Successfully activated service 'org.freedesktop.UDisks2' Jul 29 14:57:45 bob audit: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=udisks2 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 29 14:57:45 bob udisksd[2132]: Acquired the name org.freedesktop.UDisks2 on the system message bus Jul 29 14:57:45 bob systemd: Started Disk Manager.
Attachment:
signature.asc
Description: This is a digitally signed message part
_______________________________________________ users mailing list -- users@xxxxxxxxxxxxxxxxxxxxxxx To unsubscribe send an email to users-leave@xxxxxxxxxxxxxxxxxxxxxxx
