Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Auto unlocking LUKS drive fails #218

Open
jasonwryan opened this issue Mar 1, 2021 · 9 comments
Open

Auto unlocking LUKS drive fails #218

jasonwryan opened this issue Mar 1, 2021 · 9 comments

Comments

@jasonwryan
Copy link

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
Copy link
Owner

coldfix commented Mar 2, 2021

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
Copy link
Author

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
Copy link
Owner

coldfix commented Mar 5, 2021

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
Copy link
Author

jasonwryan commented Mar 5, 2021 •
edited
Loading

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/[email protected]/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
Copy link
Author

jasonwryan commented Mar 6, 2021 •
edited
Loading

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
Copy link
Owner

coldfix commented Mar 6, 2021

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
Copy link
Author

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
Copy link

siwyd commented Jan 30, 2023

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
Copy link

vejkse commented Jul 18, 2023 •
edited
Loading

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:

udiskie/udiskie/mount.py

Lines 243 to 250 in 2497c2c

async def _unlock_from_cache(self, device):
if not self._cache:
return False
try:
password = self._cache[device]
except KeyError:
self._log.debug(_("no cached key for {0}", device))
return False
which is called in this other method:

udiskie/udiskie/mount.py

Lines 200 to 222 in 2497c2c

async def unlock(self, device):
"""
Unlock the device if not already unlocked.
:param device: device object, block device path or mount path
:returns: whether the device is unlocked
"""
device = self._find_device(device)
if not self.is_handleable(device) or not device.is_crypto:
self._log.warn(_('not unlocking {0}: unhandled device', device))
return False
if device.is_unlocked:
self._log.info(_('not unlocking {0}: already unlocked', device))
return True
if not self._prompt:
self._log.error(_('not unlocking {0}: no password prompt', device))
return False
unlocked = await self._unlock_from_cache(device)
if unlocked:
return True
unlocked = await self._unlock_from_keyfile(device)
if unlocked:
return True
which in turn is called either in

udiskie/udiskie/mount.py

Lines 319 to 333 in 2497c2c

async def add(self, device, recursive=None):
"""
Mount or unlock the device depending on its type.
:param device: device object, block device path or mount path
:param bool recursive: recursively mount and unlock child devices
:returns: whether all attempted operations succeeded
"""
device, created = await self._find_device_losetup(device)
if created and recursive is False:
return device
if device.is_filesystem:
success = await self.mount(device)
elif device.is_crypto:
success = await self.unlock(device)
or in

udiskie/udiskie/mount.py

Lines 356 to 378 in 2497c2c

async def auto_add(self, device, recursive=None, automount=True):
"""
Automatically attempt to mount or unlock a device, but be quiet if the
device is not supported.
:param device: device object, block device path or mount path
:param bool recursive: recursively mount and unlock child devices
:returns: whether all attempted operations succeeded
"""
device, created = await self._find_device_losetup(device)
if created and recursive is False:
return device
if device.is_luks_cleartext and self.udisks.version_info >= (2, 7, 0):
await sleep(1.5) # temporary workaround for #153, unreliable
success = True
if not self.is_automount(device, automount):
pass
elif device.is_filesystem:
if not device.is_mounted:
success = await self.mount(device)
elif device.is_crypto:
if self._prompt and not device.is_unlocked:
success = await self.unlock(device)

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@jasonwryan @siwyd @coldfix @vejkse