search

coldfix / udiskie

Automounter for removable media
MIT License
888 stars 54 forks source link

Auto unlocking LUKS drive fails #218

Open jasonwryan opened 3 years ago

jasonwryan commented 3 years ago

Udiskie 2.3.2

Udiskie is configured to auto-unlock a LUKS USB drive using a keyfile. This only works if I manually call udiskie-mount (either with the -a option, or specify the device, eg., /dev/sdf, OR if I have during the same session manually unlocked the device, ie., manually unlocked it, dismounted, and then some time later replugged it, then udiskie behaves as documented.

Using the debug switch, some output. First, when configured with -id_uuid: XXXXXX the device is not unlocked:

Mar 02 10:02:42 Centurion udiskie[559]: DEBUG [2021-03-02 10:02:42,230] udiskie.config: /org/freedesktop/UDisks2/drives/WDC_WDS120G2G0A_00JH30_180101461907 matched {!is_block} -> {ignore}
Mar 02 10:02:42 Centurion udiskie[559]: DEBUG [2021-03-02 10:02:42,333] udiskie.udisks2: +++ device_changed: /org/freedesktop/UDisks2/drives/WDC_WD10EZEX_00RKKA0_WD_WMC1S2775972
Mar 02 10:02:42 Centurion udiskie[559]: DEBUG [2021-03-02 10:02:42,333] udiskie.config: /org/freedesktop/UDisks2/drives/WDC_WD10EZEX_00RKKA0_WD_WMC1S2775972 matched {!is_block} -> {ignore}
Mar 02 10:02:42 Centurion udiskie[559]: DEBUG [2021-03-02 10:02:42,388] udiskie.udisks2: +++ device_changed: /org/freedesktop/UDisks2/drives/TS64GMTS800S_0134825CE11694220109
Mar 02 10:02:42 Centurion udiskie[559]: DEBUG [2021-03-02 10:02:42,388] udiskie.config: /org/freedesktop/UDisks2/drives/TS64GMTS800S_0134825CE11694220109 matched {!is_block} -> {ignore}
Mar 02 10:03:26 Centurion udiskie[559]: DEBUG [2021-03-02 10:03:26,434] udiskie.udisks2: +++ device_added: /org/freedesktop/UDisks2/drives/Seagate_Expansion_NAA3XGS2
Mar 02 10:03:26 Centurion udiskie[559]: DEBUG [2021-03-02 10:03:26,434] udiskie.config: /org/freedesktop/UDisks2/drives/Seagate_Expansion_NAA3XGS2 matched {!is_block} -> {ignore}
Mar 02 10:03:26 Centurion udiskie[559]: DEBUG [2021-03-02 10:03:26,435] udiskie.udisks2: +++ device_added: /org/freedesktop/UDisks2/block_devices/sdf
Mar 02 10:03:26 Centurion udiskie[559]: DEBUG [2021-03-02 10:03:26,436] udiskie.config: /dev/sdf matched {id_uuid=c45aae65-3d3a-4b33-b89a-2e6dfb451fed} -> {!ignore, automount, keyfile=/home/jason/.config/udiskie/zeppelin.key}
Mar 02 10:03:26 Centurion udiskie[559]: DEBUG [2021-03-02 10:03:26,436] udiskie.config: /dev/sdf matched {id_uuid=c45aae65-3d3a-4b33-b89a-2e6dfb451fed} -> {!ignore, automount, keyfile=/home/jason/.config/udiskie/zeppelin.key}

When the device is not unlocked, I call udiskie-mount -a and it is unlocked/mounted. After a dismount, replugging and the device is successfully unlocked/mounted:

Mar 02 09:10:27 Centurion udiskie[7816]: DEBUG [2021-03-02 09:10:27,605] udiskie.mount: mounting /org/freedesktop/UDisks2/block_devices/dm_2d3 with {'options': ['noatime', 'sync']}
Mar 02 09:10:27 Centurion udiskie[7816]: DEBUG [2021-03-02 09:10:27,911] udiskie.udisks2: +++ device_mounted: /org/freedesktop/UDisks2/block_devices/dm_2d3
Mar 02 09:10:27 Centurion udiskie[7816]: DEBUG [2021-03-02 09:10:27,912] udiskie.udisks2: +++ device_changed: /org/freedesktop/UDisks2/block_devices/dm_2d3
Mar 02 09:10:27 Centurion udiskie[7816]: DEBUG [2021-03-02 09:10:27,912] udiskie.config: /dev/sdf matched {id_uuid=c45aae65-3d3a-4b33-b89a-2e6dfb451fed} -> {!ignore, automount, keyfile=/home/jason/.config/udiskie/zeppelin.key}
Mar 02 09:10:27 Centurion udiskie[7816]: DEBUG [2021-03-02 09:10:27,912] udiskie.config: /dev/sdf matched {id_uuid=c45aae65-3d3a-4b33-b89a-2e6dfb451fed} -> {!ignore, automount, keyfile=/home/jason/.config/udiskie/zeppelin.key}
Mar 02 09:10:28 Centurion udiskie[7816]: DEBUG [2021-03-02 09:10:28,024] udiskie.udisks2: +++ device_changed: /org/freedesktop/UDisks2/block_devices/dm_2d3
Mar 02 09:10:28 Centurion udiskie[7816]: DEBUG [2021-03-02 09:10:28,024] udiskie.config: /dev/sdf matched {id_uuid=c45aae65-3d3a-4b33-b89a-2e6dfb451fed} -> {!ignore, automount, keyfile=/home/jason/.config/udiskie/zeppelin.key}
Mar 02 09:10:28 Centurion udiskie[7816]: DEBUG [2021-03-02 09:10:28,025] udiskie.config: /dev/sdf matched {id_uuid=c45aae65-3d3a-4b33-b89a-2e6dfb451fed} -> {!ignore, automount, keyfile=/home/jason/.config/udiskie/zeppelin.key}
Mar 02 09:10:28 Centurion udiskie[7816]: mounted /org/freedesktop/UDisks2/block_devices/dm_2d3 on /media/Zeppelin
Mar 02 09:10:28 Centurion udiskie[7816]: INFO [2021-03-02 09:10:28,064] udiskie.mount: mounted /org/freedesktop/UDisks2/block_devices/dm_2d3 on /media/Zeppelin

Config is pretty basic:

program_options:
     automount: true
     notify: false

device_config:
- id_uuid: c45aae65-3d3a-4b33-b89a-2e6dfb451fed
    keyfile: /home/jason/.config/udiskie/zeppelin.key
    automount: true
    ignore: false

  #mount_options:
 - id_type: vfat
    options: flush
 - id_type: ext4
   options: [noatime, sync]

Is there something I am missing here? Thanks!

coldfix commented 3 years ago

Hi,

many thanks for the report.

You're right, it should unlock normally. I did a quick check on a test device and it seems to work so far. Therefore some follow-up questions:

How did you setup the device?, i.e. can you give the fdisk/cryptsetup command that will reproduce the same behaviour on another device (if you have one around for testing)?

In any case, can you give the output of udisksctl info -b /dev/sdf

[...] if I have during the same session manually unlocked the device, ie., manually unlocked it, dismounted, and then some time later replugged it, then udiskie behaves as documented.

By "the same session", do you mean the same login session or the same udiskie instance? i.e. does the issue occur again after stopping and restarting udiskie, or do you have to logout or even reboot?

Using the debug switch, some output. First, when configured with -id_uuid: XXXXXX the device is not unlocked:

Mar 02 10:02:42 Centurion udiskie[559]: DEBUG [2021-03-02 10:02:42,230] udiskie.config: /org/freedesktop/UDisks2/drives/WDC_WDS120G2G0A_00JH30_180101461907 matched {!is_block} -> {ignore}
Mar 02 10:02:42 Centurion udiskie[559]: DEBUG [2021-03-02 10:02:42,333] udiskie.udisks2: +++ device_changed: /org/freedesktop/UDisks2/drives/WDC_WD10EZEX_00RKKA0_WD_WMC1S2775972
Mar 02 10:02:42 Centurion udiskie[559]: DEBUG [2021-03-02 10:02:42,333] udiskie.config: /org/freedesktop/UDisks2/drives/WDC_WD10EZEX_00RKKA0_WD_WMC1S2775972 matched {!is_block} -> {ignore}
Mar 02 10:02:42 Centurion udiskie[559]: DEBUG [2021-03-02 10:02:42,388] udiskie.udisks2: +++ device_changed: /org/freedesktop/UDisks2/drives/TS64GMTS800S_0134825CE11694220109
Mar 02 10:02:42 Centurion udiskie[559]: DEBUG [2021-03-02 10:02:42,388] udiskie.config: /org/freedesktop/UDisks2/drives/TS64GMTS800S_0134825CE11694220109 matched {!is_block} -> {ignore}
Mar 02 10:03:26 Centurion udiskie[559]: DEBUG [2021-03-02 10:03:26,434] udiskie.udisks2: +++ device_added: /org/freedesktop/UDisks2/drives/Seagate_Expansion_NAA3XGS2
Mar 02 10:03:26 Centurion udiskie[559]: DEBUG [2021-03-02 10:03:26,434] udiskie.config: /org/freedesktop/UDisks2/drives/Seagate_Expansion_NAA3XGS2 matched {!is_block} -> {ignore}
Mar 02 10:03:26 Centurion udiskie[559]: DEBUG [2021-03-02 10:03:26,435] udiskie.udisks2: +++ device_added: /org/freedesktop/UDisks2/block_devices/sdf
Mar 02 10:03:26 Centurion udiskie[559]: DEBUG [2021-03-02 10:03:26,436] udiskie.config: /dev/sdf matched {id_uuid=c45aae65-3d3a-4b33-b89a-2e6dfb451fed} -> {!ignore, automount, keyfile=/home/jason/.config/udiskie/zeppelin.key}
Mar 02 10:03:26 Centurion udiskie[559]: DEBUG [2021-03-02 10:03:26,436] udiskie.config: /dev/sdf matched {id_uuid=c45aae65-3d3a-4b33-b89a-2e6dfb451fed} -> {!ignore, automount, keyfile=/home/jason/.config/udiskie/zeppelin.key}

It's interesting that the "/dev/sdd matched" line occurs twice. In normal cases it should not. That may have to do with the problem in one or the other way (symptom, or cause). You luks-formatted the device directly (without partitioning), is that correct?

Is that all the output, even if waiting for another 30s or so?

When the device is not unlocked, I call udiskie-mount -a and it is unlocked/mounted. After a dismount, replugging and the device is successfully unlocked/mounted:

Mar 02 09:10:27 Centurion udiskie[7816]: DEBUG [2021-03-02 09:10:27,605] udiskie.mount: mounting /org/freedesktop/UDisks2/block_devices/dm_2d3 with {'options': ['noatime', 'sync']}
Mar 02 09:10:27 Centurion udiskie[7816]: DEBUG [2021-03-02 09:10:27,911] udiskie.udisks2: +++ device_mounted: /org/freedesktop/UDisks2/block_devices/dm_2d3
Mar 02 09:10:27 Centurion udiskie[7816]: DEBUG [2021-03-02 09:10:27,912] udiskie.udisks2: +++ device_changed: /org/freedesktop/UDisks2/block_devices/dm_2d3
Mar 02 09:10:27 Centurion udiskie[7816]: DEBUG [2021-03-02 09:10:27,912] udiskie.config: /dev/sdf matched {id_uuid=c45aae65-3d3a-4b33-b89a-2e6dfb451fed} -> {!ignore, automount, keyfile=/home/jason/.config/udiskie/zeppelin.key}
Mar 02 09:10:27 Centurion udiskie[7816]: DEBUG [2021-03-02 09:10:27,912] udiskie.config: /dev/sdf matched {id_uuid=c45aae65-3d3a-4b33-b89a-2e6dfb451fed} -> {!ignore, automount, keyfile=/home/jason/.config/udiskie/zeppelin.key}
Mar 02 09:10:28 Centurion udiskie[7816]: DEBUG [2021-03-02 09:10:28,024] udiskie.udisks2: +++ device_changed: /org/freedesktop/UDisks2/block_devices/dm_2d3
Mar 02 09:10:28 Centurion udiskie[7816]: DEBUG [2021-03-02 09:10:28,024] udiskie.config: /dev/sdf matched {id_uuid=c45aae65-3d3a-4b33-b89a-2e6dfb451fed} -> {!ignore, automount, keyfile=/home/jason/.config/udiskie/zeppelin.key}
Mar 02 09:10:28 Centurion udiskie[7816]: DEBUG [2021-03-02 09:10:28,025] udiskie.config: /dev/sdf matched {id_uuid=c45aae65-3d3a-4b33-b89a-2e6dfb451fed} -> {!ignore, automount, keyfile=/home/jason/.config/udiskie/zeppelin.key}
Mar 02 09:10:28 Centurion udiskie[7816]: mounted /org/freedesktop/UDisks2/block_devices/dm_2d3 on /media/Zeppelin
Mar 02 09:10:28 Centurion udiskie[7816]: INFO [2021-03-02 09:10:28,064] udiskie.mount: mounted /org/freedesktop/UDisks2/block_devices/dm_2d3 on /media/Zeppelin

This doesn't show that the device was unlocked at the beginning, which means either there is output missing at the beginning, or it was already unlocked before running udiskie?

Config is pretty basic: [...]

Taken literally, the config above has slightly inconsistent indentation which would lead to errors - but since it seems to work I guess it was messed up during posting.

jasonwryan commented 3 years ago

Thanks Tomas!

How did you setup the device?, i.e. can you give the fdisk/cryptsetup command that will reproduce the same behaviour on another device (if you have one around for testing)?

In any case, can you give the output of udisksctl info -b /dev/sdf

It was some time ago, but is just a standard whole-of-disk encryption. I probably did: cryptsetup luksFormat /dev/sdX.

udiskctl info -b /dev/sdf
/org/freedesktop/UDisks2/block_devices/sdf:
  org.freedesktop.UDisks2.Block:
    Configuration:              []
    CryptoBackingDevice:        '/'
    Device:                     /dev/sdf
    DeviceNumber:               2128
    Drive:                      '/org/freedesktop/UDisks2/drives/Seagate_Expansion_NAA3XGS2'
    HintAuto:                   true
    HintIconName:               
    HintIgnore:                 false
    HintName:                   
    HintPartitionable:          true
    HintSymbolicIconName:       
    HintSystem:                 false
    Id:                         by-id-usb-Seagate_Expansion_NAA3XGS2-0:0
    IdLabel:                    Zeppelin
    IdType:                     crypto_LUKS
    IdUUID:                     c45aae65-3d3a-4b33-b89a-2e6dfb451fed
    IdUsage:                    crypto
    IdVersion:                  1
    MDRaid:                     '/'
    MDRaidMember:               '/'
    PreferredDevice:            /dev/sdf
    ReadOnly:                   false
    Size:                       2000398933504
    Symlinks:                   /dev/disk/by-id/usb-Seagate_Expansion_NAA3XGS2-0:0
                                /dev/disk/by-path/pci-0000:00:14.0-usb-0:5:1.0-scsi-0:0:0:0
                                /dev/disk/by-uuid/c45aae65-3d3a-4b33-b89a-2e6dfb451fed
    UserspaceMountOptions:      
  org.freedesktop.UDisks2.Encrypted:
    ChildConfiguration:         []
    CleartextDevice:            '/'
    HintEncryptionType:         
    MetadataSize:               2097152

By "the same session", do you mean the same login session or the same udiskie instance? i.e. does the issue occur again after stopping and restarting udiskie, or do you have to logout or even reboot?

The same login session, wihout restarting the daemon. If I reboot, the unlocking fails.

Is that all the output, even if waiting for another 30s or so?

Yep.

This doesn't show that the device was unlocked at the beginning, which means either there is output missing at the beginning, or it was already unlocked before running udiskie?

That's all that was printed to the journal.

Config is pretty basic: [...]

Taken literally, the config above has slightly inconsistent indentation which would lead to errors - but since it seems to work I guess it was messed up during posting.

Yeah, I munged it while pasting :p

coldfix commented 3 years ago

Okay. Thanks for the info! Currently still no idea what the problem is.

It might be more insightful to get some information from udisks itself what is going on while the device is inserted (once with and once without udiskie running). You can monitor for detailed udisks device activity using the following command:

udisksctl monitor

and get access to the logs by:

journalctl -n 20 -f -u udisks2.service

Also, let me know if you run into the same problem with another device/another machine, and what your operating system is. It would greatly help if I could somehow reproduce the issue.

By "the same session", do you mean the same login session or the same udiskie instance? i.e. does the issue occur again after stopping and restarting udiskie, or do you have to logout or even reboot?

The same login session, wihout restarting the daemon. If I reboot, the unlocking fails.

What happens if you mount+unmount the device, and kill udiskie and start it again without rebooting the machine? Does the issue occur or does it work as expected?

This doesn't show that the device was unlocked at the beginning, which means either there is output missing at the beginning, or it was already unlocked before running udiskie?

That's all that was printed to the journal.

Did you just unmount the device or also "lock* it after the initial manual mount? The log seems to indicate that you didn't lock. If you didn't, what happens if you first manually unlock+muont and then unmount+lock, and then start udiskie again?

Best, Thomas

jasonwryan commented 3 years ago

Thanks Thomas!

The output of udisksctl monitor (first with udiskie service running, then after stopping it:

Monitoring the udisks daemon. Press Ctrl+C to exit.
10:22:25.053: The udisks-daemon is running (name-owner :1.15).
10:22:33.785: Added /org/freedesktop/UDisks2/drives/Seagate_Expansion_NAA3XGS2
  org.freedesktop.UDisks2.Drive:
    CanPowerOff:                true
    Configuration:              {}
    ConnectionBus:              usb
    Ejectable:                  false
    Id:                         Seagate-Expansion-NAA3XGS2
    Media:                      
    MediaAvailable:             true
    MediaChangeDetected:        true
    MediaCompatibility:         
    MediaRemovable:             false
    Model:                      Expansion
    Optical:                    false
    OpticalBlank:               false
    OpticalNumAudioTracks:      0
    OpticalNumDataTracks:       0
    OpticalNumSessions:         0
    OpticalNumTracks:           0
    Removable:                  true
    Revision:                   0708
    RotationRate:               -1
    Seat:                       seat0
    Serial:                     NAA3XGS2
    SiblingId:                  /sys/devices/pci0000:00/0000:00:14.0/usb2/2-5/2-5:1.0
    Size:                       2000398933504
    SortKey:                    01hotplug/1614979353783549
    TimeDetected:               1614979353783549
    TimeMediaDetected:          1614979353783549
    Vendor:                     Seagate
    WWN:                        
10:22:33.787: Added /org/freedesktop/UDisks2/block_devices/sdf
  org.freedesktop.UDisks2.Block:
    Configuration:              []
    CryptoBackingDevice:        '/'
    Device:                     /dev/sdf
    DeviceNumber:               2128
    Drive:                      '/org/freedesktop/UDisks2/drives/Seagate_Expansion_NAA3XGS2'
    HintAuto:                   true
    HintIconName:               
    HintIgnore:                 false
    HintName:                   
    HintPartitionable:          true
    HintSymbolicIconName:       
    HintSystem:                 false
    Id:                         by-id-usb-Seagate_Expansion_NAA3XGS2-0:0
    IdLabel:                    Zeppelin
    IdType:                     crypto_LUKS
    IdUUID:                     c45aae65-3d3a-4b33-b89a-2e6dfb451fed
    IdUsage:                    crypto
    IdVersion:                  1
    MDRaid:                     '/'
    MDRaidMember:               '/'
    PreferredDevice:            /dev/sdf
    ReadOnly:                   false
    Size:                       2000398933504
    Symlinks:                   /dev/disk/by-id/usb-Seagate_Expansion_NAA3XGS2-0:0
                                /dev/disk/by-path/pci-0000:00:14.0-usb-0:5:1.0-scsi-0:0:0:0
                                /dev/disk/by-uuid/c45aae65-3d3a-4b33-b89a-2e6dfb451fed
    UserspaceMountOptions:      
  org.freedesktop.UDisks2.Encrypted:
    ChildConfiguration:         []
    CleartextDevice:            '/'
    HintEncryptionType:         
    MetadataSize:               2097152
10:23:05.276: /org/freedesktop/UDisks2/drives/WDC_WD10EZEX_00WN4A0_WD_WMC6Y0F2EEE9: org.freedesktop.UDisks2.Drive.Ata: Properties Changed
  SmartTemperature:     299.15000000000003
  SmartUpdated:         1614979385
10:23:05.334: /org/freedesktop/UDisks2/drives/WDC_WDS120G2G0A_00JH30_180101461907: org.freedesktop.UDisks2.Drive.Ata: Properties Changed
  SmartPowerOnSeconds:          50684400
  SmartTemperature:             303.15000000000003
  SmartUpdated:                 1614979385
10:23:05.483: /org/freedesktop/UDisks2/drives/WDC_WD10EZEX_00RKKA0_WD_WMC1S2775972: org.freedesktop.UDisks2.Drive.Ata: Properties Changed
  SmartTemperature:     298.15000000000003
  SmartUpdated:         1614979385
10:23:05.538: /org/freedesktop/UDisks2/drives/TS64GMTS800S_0134825CE11694220109: org.freedesktop.UDisks2.Drive.Ata: Properties Changed
  SmartTemperature:     314.15000000000003
  SmartUpdated:         1614979385

--------------------------------------------------------------------------------------------------------
# After stopping the udiskie user service

Monitoring the udisks daemon. Press Ctrl+C to exit.
10:27:05.879: The udisks-daemon is running (name-owner :1.15).
10:27:21.056: Added /org/freedesktop/UDisks2/drives/Seagate_Expansion_NAA3XGS2
  org.freedesktop.UDisks2.Drive:
    CanPowerOff:                true
    Configuration:              {}
    ConnectionBus:              usb
    Ejectable:                  false
    Id:                         Seagate-Expansion-NAA3XGS2
    Media:                      
    MediaAvailable:             true
    MediaChangeDetected:        true
    MediaCompatibility:         
    MediaRemovable:             false
    Model:                      Expansion
    Optical:                    false
    OpticalBlank:               false
    OpticalNumAudioTracks:      0
    OpticalNumDataTracks:       0
    OpticalNumSessions:         0
    OpticalNumTracks:           0
    Removable:                  true
    Revision:                   0708
    RotationRate:               -1
    Seat:                       seat0
    Serial:                     NAA3XGS2
    SiblingId:                  /sys/devices/pci0000:00/0000:00:14.0/usb2/2-5/2-5:1.0
    Size:                       2000398933504
    SortKey:                    01hotplug/1614979641054464
    TimeDetected:               1614979641054464
    TimeMediaDetected:          1614979641054464
    Vendor:                     Seagate
    WWN:                        
10:27:21.058: Added /org/freedesktop/UDisks2/block_devices/sdf
  org.freedesktop.UDisks2.Block:
    Configuration:              []
    CryptoBackingDevice:        '/'
    Device:                     /dev/sdf
    DeviceNumber:               2128
    Drive:                      '/org/freedesktop/UDisks2/drives/Seagate_Expansion_NAA3XGS2'
    HintAuto:                   true
    HintIconName:               
    HintIgnore:                 false
    HintName:                   
    HintPartitionable:          true
    HintSymbolicIconName:       
    HintSystem:                 false
    Id:                         by-id-usb-Seagate_Expansion_NAA3XGS2-0:0
    IdLabel:                    Zeppelin
    IdType:                     crypto_LUKS
    IdUUID:                     c45aae65-3d3a-4b33-b89a-2e6dfb451fed
    IdUsage:                    crypto
    IdVersion:                  1
    MDRaid:                     '/'
    MDRaidMember:               '/'
    PreferredDevice:            /dev/sdf
    ReadOnly:                   false
    Size:                       2000398933504
    Symlinks:                   /dev/disk/by-id/usb-Seagate_Expansion_NAA3XGS2-0:0
                                /dev/disk/by-path/pci-0000:00:14.0-usb-0:5:1.0-scsi-0:0:0:0
                                /dev/disk/by-uuid/c45aae65-3d3a-4b33-b89a-2e6dfb451fed
    UserspaceMountOptions:      
  org.freedesktop.UDisks2.Encrypted:
    ChildConfiguration:         []
    CleartextDevice:            '/'
    HintEncryptionType:         
    MetadataSize:               2097152

Now this is weird. I restarted the systemd --user service to perform the next test (killing udiskie) and plugged the drive in and it mounted correctly:

systemctl --user status udiskie.service 
● udiskie.service - Automounting Daemon
     Loaded: loaded (/home/jason/.config/systemd/user/udiskie.service; enabled; vendor preset: enabled)
     Active: active (running) since Sat 2021-03-06 10:30:14 NZDT; 46s ago
   Main PID: 16668 (udiskie)
     CGroup: /user.slice/user-1000.slice/user@1000.service/app.slice/udiskie.service
             └─16668 /usr/bin/python /usr/bin/udiskie -vN

Mar 06 10:30:37 Centurion udiskie[16668]: DEBUG [2021-03-06 10:30:37,475] udiskie.mount: mounting /org/freedesktop/UDisks2/block_devices/dm_2d3 with {'options': ['noatime', 'sync']}
Mar 06 10:30:38 Centurion udiskie[16668]: DEBUG [2021-03-06 10:30:38,283] udiskie.udisks2: +++ device_mounted: /org/freedesktop/UDisks2/block_devices/dm_2d3
Mar 06 10:30:38 Centurion udiskie[16668]: DEBUG [2021-03-06 10:30:38,283] udiskie.udisks2: +++ device_changed: /org/freedesktop/UDisks2/block_devices/dm_2d3
Mar 06 10:30:38 Centurion udiskie[16668]: DEBUG [2021-03-06 10:30:38,283] udiskie.config: /dev/sdf matched {id_uuid=c45aae65-3d3a-4b33-b89a-2e6dfb451fed} -> {!ignore, automount, keyfile=/home/jason/.config/udiskie/zeppelin.key}
Mar 06 10:30:38 Centurion udiskie[16668]: DEBUG [2021-03-06 10:30:38,283] udiskie.config: /dev/sdf matched {id_uuid=c45aae65-3d3a-4b33-b89a-2e6dfb451fed} -> {!ignore, automount, keyfile=/home/jason/.config/udiskie/zeppelin.key}
Mar 06 10:30:38 Centurion udiskie[16668]: DEBUG [2021-03-06 10:30:38,445] udiskie.udisks2: +++ device_changed: /org/freedesktop/UDisks2/block_devices/dm_2d3
Mar 06 10:30:38 Centurion udiskie[16668]: DEBUG [2021-03-06 10:30:38,445] udiskie.config: /dev/sdf matched {id_uuid=c45aae65-3d3a-4b33-b89a-2e6dfb451fed} -> {!ignore, automount, keyfile=/home/jason/.config/udiskie/zeppelin.key}
Mar 06 10:30:38 Centurion udiskie[16668]: DEBUG [2021-03-06 10:30:38,446] udiskie.config: /dev/sdf matched {id_uuid=c45aae65-3d3a-4b33-b89a-2e6dfb451fed} -> {!ignore, automount, keyfile=/home/jason/.config/udiskie/zeppelin.key}
Mar 06 10:30:38 Centurion udiskie[16668]: mounted /org/freedesktop/UDisks2/block_devices/dm_2d3 on /media/Zeppelin
Mar 06 10:30:38 Centurion udiskie[16668]: INFO [2021-03-06 10:30:38,484] udiskie.mount: mounted /org/freedesktop/UDisks2/block_devices/dm_2d3 on /media/Zeppelin

So it seems it is related to how the service is initially instantiated on this machine (Arch Linux). I'll test on my laptop.

Edit: tested on my laptop (Arch Linux), and once I had whitelisted the device in usbguard, same behaviour. First load fails. Restart the service and autounlocking and mounting works. The service file is the same on both machines:

[Unit]
Description=Automounting Daemon

[Service]
ExecStart=/usr/bin/udiskie -qN
#ExecStart=/usr/bin/udiskie -vN (for testing)
[Install]
WantedBy=default.target
jasonwryan commented 3 years ago

OK, it's definitely an issue with the systemd --user service. I disabled the service and started udiskie from .xinitrc, rebooted and it unlocked and mounted the drive straight away.

There is obviously something in the environment that is picked up when the --user service is restarted that is not present at login. I'll have to dig in to how to try and debug that...

Edit:

Restarting the service adds some environment variables:

DISPLAY=:0
PASSWORD_STORE_DIR=/home/jason/Sync/pass/
XAUTHORITY=/home/jason/.Xauthority

Edit 2: Adding DISPLAY and XAUTHORITY to the --user service environment and rebooting made no difference (which is good, I guess, and I don't want it to depend on X).

Edit 3: Adding dbus-update-activation-environment --systemd --all to .profile imports all of the env vars into the systemd --user environment, so the results of systemctl --user show-environment are identical from boot and restarting the service, and it still fails the first time. So it isn't an environment issue. I'm out of ideas at this point (other than automating a forced restart of the udiskie --user service after login, which seems really ugly...)

coldfix commented 3 years ago

Oh you're starting from a unit file. The recommended way to start udiskie is from .xinitrc for now. As far as I know, there can also be some problems with the tray icon showing if starting as a .service.

Furthermore, it's possible that you might need a different set of polkit permissions, (xxx-other-seat), see Permissions.

jasonwryan commented 3 years ago

OK, Thanks Thomas.

I already have the polkit file on both machines. I wasn't aware that starting via a service file was unsupported.

siwyd commented 1 year ago

I don't have any new valuable information at this point, but I seem to be having the exact same issue. It seems weird that it would be related to environment somehow, because udiskie does show a popup (in Sway, using mako for showing the notifications) when the device has appeared. It just doesn't unlock it. I then have to to udiskie-mount -a to get it mounted. If I restart the systemd user service or start udiskie manually, it does seem to unlock automatically.

vejkse commented 1 year ago

I have noticed this phenomenon too. I’m not sure this is exactly the same situation as above, but if I start udiskie in .profile, it doesn’t auto unlock using the configured keyfile, unless I set XAUTHORITY and DISPLAY for it in .profile. If I start udiskie in .xinitrc, it always works. If I execute udiskie-mount by hand, it works in all cases.

With --verbose on, I see that the difference between the two behaviours is that when it fails, everything stops right before no cached key for /org/freedesktop/UDisks2/block_devices/sdc1 would normally be logged.

In the code, this message is logged in this method: https://github.com/coldfix/udiskie/blob/2497c2c2450c3e84c36d99dcc80ea443f36d9ad0/udiskie/mount.py#L243-L250 which is called in this other method: https://github.com/coldfix/udiskie/blob/2497c2c2450c3e84c36d99dcc80ea443f36d9ad0/udiskie/mount.py#L200-L222 which in turn is called either in https://github.com/coldfix/udiskie/blob/2497c2c2450c3e84c36d99dcc80ea443f36d9ad0/udiskie/mount.py#L319-L333 or in https://github.com/coldfix/udiskie/blob/2497c2c2450c3e84c36d99dcc80ea443f36d9ad0/udiskie/mount.py#L356-L378

If I understand correctly, the observed behaviour is what should be expected: when auto-unlocking, the method auto_add is called, which checks the existence of self._prompt before trying to unlock. I assume that in the absence of the proper graphical environment variables, the password prompt fails to be prepared, so that unlock is never executed.

Since unlock might succeed even if there is no password prompt available, for instance if a keyfile is configured, I wonder if that check shouldn’t occur at a later stage, just before the prompt is really needed?

In fact, as can be observed above, there is already such a prompt check inside the method unlock, but again before trying to unlock from a keyfile.