[systemd-devel] need to run systemctl --user daemon-reload to get USB device properly recognized

Fri Jul 6 20:54:36 UTC 2018

Greetings,

I'm seeing some unexpected behavior for my systemd --user process.
Background:

I've setup udev rules to fire off systemd --user units to download photos
when my camera (PTP device) or my phone (MTP device) get plugged in. They
are both USB devices:

==> /etc/udev/rules.d/90-canon-60d.rules <==
# Download photos from Canon 60D
ACTION=="add" \
ENV{GPHOTO2_DRIVER}=="PTP" \
ENV{ID_VENDOR_ID}=="04a9" \
ENV{ID_MODEL_ID}=="3215" \
TAG+="systemd" \
PROGRAM="/bin/systemd-escape --template=download-photos at .service
Canon_60D_$env{ID_VENDOR_ID}_$env{ID_MODEL_ID}" \
ENV{SYSTEMD_USER_WANTS}+="%c"

==> /etc/udev/rules.d/90-galaxy-note-3.rules <==
# Download photos from Galaxy Note 3
ACTION=="add" \
ENV{ID_MTP_DEVICE}=="1" \
ENV{ID_VENDOR_ID}=="04e8" \
ENV{ID_MODEL_ID}=="6860" \
ENV{ID_SERIAL_SHORT}=="17b765cc" \
TAG+="systemd" \
PROGRAM="/bin/systemd-escape --template=download-photos at .service
$env{ID_SERIAL}" \
ENV{SYSTEMD_USER_WANTS}+="%c"

==> ~/.config/systemd/user/download-photos at .service <==
[Service]
Type=oneshot
ExecStart=/usr/bin/mate-terminal --maximize --command '/usr/bin/imagdo
--config-file %h/.imagdo/conf/%I.yaml'
SuccessExitStatus=0 255

However, after plugging in my phone, I need to run:

systemctl --user daemon-reload

in order to get udev/systemd to recognize my camera being plugged in and
fire off the "download" script.

Here are the logs from the journal of the download working for my phone:

Jul 06 13:54:08 eruke kernel: usb 3-2: USB disconnect, device number 5
Jul 06 13:54:08 eruke kernel: pktcdvd: pktcdvd0: writer unmapped
Jul 06 13:54:08 eruke upowerd[1619]: unhandled action 'unbind' on
/sys/devices/pci0000:00/0000:00:14.0/usb3/3-2/3-2:1.0
Jul 06 13:54:08 eruke upowerd[1619]: unhandled action 'unbind' on
/sys/devices/pci0000:00/0000:00:14.0/usb3/3-2
Jul 06 13:54:08 eruke kernel: usb 3-2: new high-speed USB device number 6
using xhci_hcd
Jul 06 13:54:08 eruke kernel: usb 3-2: New USB device found, idVendor=04e8,
idProduct=6860
Jul 06 13:54:08 eruke kernel: usb 3-2: New USB device strings: Mfr=1,
Product=2, SerialNumber=3
Jul 06 13:54:08 eruke kernel: usb 3-2: Product: SAMSUNG_Android
Jul 06 13:54:08 eruke kernel: usb 3-2: Manufacturer: SAMSUNG
Jul 06 13:54:08 eruke kernel: usb 3-2: SerialNumber: 17b765cc
Jul 06 13:54:08 eruke systemd[1340]: Created slice download\x2dphotos.slice.
Jul 06 13:54:08 eruke systemd[1340]: Starting
download-photos at SAMSUNG_SAMSUNG_Android_17b765cc.service...
Jul 06 13:54:08 eruke upowerd[1619]: unhandled action 'bind' on
/sys/devices/pci0000:00/0000:00:14.0/usb3/3-2
Jul 06 13:54:09 eruke upowerd[1619]: unhandled action 'bind' on
/sys/devices/pci0000:00/0000:00:14.0/usb3/3-2/3-2:1.0
Jul 06 13:54:10 eruke kernel: fuse init (API version 7.26)
Jul 06 13:54:10 eruke systemd[1]: Mounting FUSE Control File System...
Jul 06 13:54:10 eruke systemd[1]: Mounted FUSE Control File System.
Jul 06 13:54:11 eruke upowerd[1619]: unhandled action 'unbind' on
/sys/devices/pci0000:00/0000:00:14.0/usb3/3-2/3-2:1.0
Jul 06 13:54:13 eruke pkexec[19143]: pam_unix(polkit-1:session): session
opened for user root by (uid=1000)
Jul 06 13:54:13 eruke pkexec[19143]: mzagrabe: Executing command
[USER=root] [TTY=unknown] [CWD=/home/mzagrabe]
[COMMAND=/usr/sbin/mate-power-backlight-helper --set-brightness 3093]
Jul 06 13:54:13 eruke systemd[1340]: Started
download-photos at SAMSUNG_SAMSUNG_Android_17b765cc.service.
Jul 06 13:54:18 eruke kernel: usb 3-2: USB disconnect, device number 6
Jul 06 13:54:18 eruke upowerd[1619]: unhandled action 'unbind' on
/sys/devices/pci0000:00/0000:00:14.0/usb3/3-2
Jul 06 13:54:23 eruke pkexec[19157]: pam_unix(polkit-1:session): session
opened for user root by (uid=1000)

Here are the journal logs of the download __not__ working for my camera:

Jul 06 13:55:02 eruke kernel: usb 3-2: new high-speed USB device number 7
using xhci_hcd
Jul 06 13:55:02 eruke kernel: usb 3-2: New USB device found, idVendor=04a9,
idProduct=3215
Jul 06 13:55:02 eruke kernel: usb 3-2: New USB device strings: Mfr=1,
Product=2, SerialNumber=0
Jul 06 13:55:02 eruke kernel: usb 3-2: Product: Canon Digital Camera
Jul 06 13:55:02 eruke kernel: usb 3-2: Manufacturer: Canon Inc.
Jul 06 13:55:02 eruke mtp-probe[19173]: checking bus 3, device 7:
"/sys/devices/pci0000:00/0000:00:14.0/usb3/3-2"
Jul 06 13:55:02 eruke mtp-probe[19173]: bus: 3, device: 7 was not an MTP
device
Jul 06 13:55:02 eruke upowerd[1619]: unhandled action 'bind' on
/sys/devices/pci0000:00/0000:00:14.0/usb3/3-2
Jul 06 13:55:03 eruke upowerd[1619]: unhandled action 'bind' on
/sys/devices/pci0000:00/0000:00:14.0/usb3/3-2/3-2:1.0
Jul 06 13:55:03 eruke upowerd[1619]: unhandled action 'unbind' on
/sys/devices/pci0000:00/0000:00:14.0/usb3/3-2/3-2:1.0

Here is the daemon-reload:

Jul 06 13:55:24 eruke systemd[1340]: Reloading.

And here are the journal logs of the download working for the camera being
plugged in:

Jul 06 13:55:30 eruke kernel: usb 3-2: new high-speed USB device number 8
using xhci_hcd
Jul 06 13:55:30 eruke kernel: usb 3-2: New USB device found, idVendor=04a9,
idProduct=3215
Jul 06 13:55:30 eruke kernel: usb 3-2: New USB device strings: Mfr=1,
Product=2, SerialNumber=0
Jul 06 13:55:30 eruke kernel: usb 3-2: Product: Canon Digital Camera
Jul 06 13:55:30 eruke kernel: usb 3-2: Manufacturer: Canon Inc.
Jul 06 13:55:30 eruke mtp-probe[19275]: checking bus 3, device 8:
"/sys/devices/pci0000:00/0000:00:14.0/usb3/3-2"
Jul 06 13:55:30 eruke mtp-probe[19275]: bus: 3, device: 8 was not an MTP
device
Jul 06 13:55:30 eruke systemd[1340]: Starting
download-photos at Canon_60D_04a9_3215.service...
Jul 06 13:55:30 eruke upowerd[1619]: unhandled action 'bind' on
/sys/devices/pci0000:00/0000:00:14.0/usb3/3-2
Jul 06 13:55:30 eruke upowerd[1619]: unhandled action 'bind' on
/sys/devices/pci0000:00/0000:00:14.0/usb3/3-2/3-2:1.0
Jul 06 13:55:30 eruke upowerd[1619]: unhandled action 'unbind' on
/sys/devices/pci0000:00/0000:00:14.0/usb3/3-2/3-2:1.0
Jul 06 13:55:31 eruke upowerd[1619]: unhandled action 'bind' on
/sys/devices/pci0000:00/0000:00:14.0/usb3/3-2/3-2:1.0
Jul 06 13:55:34 eruke pkexec[19322]: pam_unix(polkit-1:session): session
opened for user root by (uid=1000)
Jul 06 13:55:34 eruke pkexec[19322]: mzagrabe: Executing command
[USER=root] [TTY=unknown] [CWD=/home/mzagrabe]
[COMMAND=/usr/sbin/mate-power-backlight-helper --set-brightness 945]
Jul 06 13:55:37 eruke dring[1794]: NAT-PMP: can't send request
Jul 06 13:56:18 eruke upowerd[1619]: unhandled action 'unbind' on
/sys/devices/pci0000:00/0000:00:14.0/usb3/3-2/3-2:1.0
Jul 06 13:56:20 eruke pkexec[19432]: pam_unix(polkit-1:session): session
opened for user root by (uid=1000)
Jul 06 13:56:20 eruke pkexec[19432]: mzagrabe: Executing command
[USER=root] [TTY=unknown] [CWD=/home/mzagrabe]
[COMMAND=/usr/sbin/mate-power-backlight-helper --set-brightness 3093]
Jul 06 13:56:21 eruke systemd[1340]: Started
download-photos at Canon_60D_04a9_3215.service.
Jul 06 13:56:23 eruke kernel: usb 3-2: USB disconnect, device number 8
Jul 06 13:56:23 eruke upowerd[1619]: unhandled action 'unbind' on
/sys/devices/pci0000:00/0000:00:14.0/usb3/3-2

Any ideas what to look for or how to fix the need to run the daemon-reload
between plugging in the two USB devices?

Thanks!

-m
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/systemd-devel/attachments/20180706/dc689ca8/attachment-0001.html>