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.

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

fails on SailfishOS 4.0 #115

Open
fuchsmich opened this issue Feb 16, 2021 · 50 comments
Open

fails on SailfishOS 4.0 #115

fuchsmich opened this issue Feb 16, 2021 · 50 comments
Assignees
Labels
an sfos update broke it An update of SFOS broke this enhancement New feature or request help wanted Extra attention is needed open question(s) Further information is requested

Comments

@fuchsmich
Copy link

In journalctl I find:

systemd[1]: dev-crypto_luks_cc05650dx2d0126x2d4bc8x2db8e5x2da1fe25606f6f.device: Job dev-crypto_luks_cc05650dx2d0126x2d4bc8x2db8e5x2da1fe25606f6f.device/start failed with result 'timeout'.
systemd[1]: cryptosd-luks@crypto_luks_cc05650dx2d0126x2d4bc8x2db8e5x2da1fe25606f6f.service: Job cryptosd-luks@crypto_luks_cc05650dx2d0126x2d4bc8x2db8e5x2da1fe25606f6f.service/start failed with result 'dependenc
systemd[1]: Dependency failed for Open DM-Crypt LUKS on SD-card crypto_luks_cc05650dx2d0126x2d4bc8x2db8e5x2da1fe25606f6f.
systemd[1]: Timed out waiting for device dev-crypto_luks_cc05650dx2d0126x2d4bc8x2db8e5x2da1fe25606f6f.device.
systemd[1]: dev-crypto_luks_cc05650dx2d0126x2d4bc8x2db8e5x2da1fe25606f6f.device: Job dev-crypto_luks_cc05650dx2d0126x2d4bc8x2db8e5x2da1fe25606f6f.device/start timed out.

also I found this:

# systemctl --all --full -t device |grep luks
dev-crypto_luks_cc05650d\x2d0126\x2d4bc8\x2db8e5\x2da1fe25606f6f.device                                                                               loaded active   plugged /dev/crypto_luks_cc05650d-0126-4bc8-b8e5-a1fe25606f6f                                                         
dev-crypto_luks_cc05650dx2d0126x2d4bc8x2db8e5x2da1fe25606f6f.device                                                                                   loaded inactive dead    dev-crypto_luks_cc05650dx2d0126x2d4bc8x2db8e5x2da1fe25606f6f.device                                           
dev-disk-by\x2did-dm\x2dname\x2dluks\x2d3f058b38\x2d3100\x2d4fe8\x2da88e\x2dc5d9a8d3bfc7.device                                                       loaded active   plugged /dev/disk/by-id/dm-name-luks-3f058b38-3100-4fe8-a88e-c5d9a8d3bfc7                                             
dev-disk-by\x2did-dm\x2duuid\x2dCRYPT\x2dLUKS1\x2d3f058b3831004fe8a88ec5d9a8d3bfc7\x2dluks\x2d3f058b38\x2d3100\x2d4fe8\x2da88e\x2dc5d9a8d3bfc7.device loaded active   plugged /dev/disk/by-id/dm-uuid-CRYPT-LUKS1-3f058b3831004fe8a88ec5d9a8d3bfc7-luks-3f058b38-3100-4fe8-a88e-c5d9a8d3bfc7
dev-mapper-luks\x2d3f058b38\x2d3100\x2d4fe8\x2da88e\x2dc5d9a8d3bfc7.device                                                                            loaded active   plugged /dev/mapper/luks-3f058b38-3100-4fe8-a88e-c5d9a8d3bfc7   

my conclusion is, there is sth wrong in the udev-rule creating the cryptosd-luks@.service. Maybe the char escaping in newer systemd has changed.

@Olf0 Olf0 self-assigned this Feb 16, 2021
@Olf0
Copy link
Owner

Olf0 commented Feb 17, 2021

Thank you very much @fuchsmich for your report.

While the journal entries clearly show, that the crypto-sdcard's systemd units for mounting stumble across an incorrectly unescaped (as per systemd-escape) device path (all \x2d shall be unescaped to -, not to x2d!), the second output you provided is more interesting:

# systemctl --all --full -t device |grep luks
dev-crypto_luks_cc05650d\x2d0126\x2d4bc8\x2db8e5\x2da1fe25606f6f.device   loaded active plugged   /dev/crypto_luks_cc05650d-0126-4bc8-b8e5-a1fe25606f6f                                                         
dev-crypto_luks_cc05650dx2d0126x2d4bc8x2db8e5x2da1fe25606f6f.device   loaded inactive dead    dev-crypto_luks_cc05650dx2d0126x2d4bc8x2db8e5x2da1fe25606f6f.device                                           
[...]

The same device appears twice:

  • Once (first entry / line) correctly escaped, active, plugged and correctly unescaped at the the end of the line: This seems to be working fine!
  • Then (second entry / line) incorrectly escaped (the backslashes are missing), inactive, dead and incorrectly unescaped (i.e., not at all, due to the missing backslashes) at the the end of the line. Systemd also decided that this unescaping is not a a path conversion: The escaped "-" are not unescaped to "/" and the suffix (here: .device) is retained. This cannot work!

my conclusion is, there is sth wrong in the udev-rule creating the cryptosd-luks@.service. Maybe the char escaping in newer systemd has changed.

Well, it needed many weeks of research to discover the workaround in pull request #2 per systemd-escape in the udev-rules.
This also resulted in filing a Systemd RFE, in which the issue (neccessity for working around the inability to properly unescape in an instanciated unit file by "pre-escaping" per systemd-escape) was ultimately understood by a Systemd developer, acknowledged, filed as RFE ("request for engineering") and ... nothing.

Yes, something must have been changed (and the systemd package was altered and updated from v225 to v238 in SFOS 4.0.1: search for ### systemd in its changelog), I just checked on my production phone (XperiaX@SFOS3.2.1) and things look "normal" there.

I will try to upgrade one of my testing devices soon after SFOS 4.0.1 has reached GA (general availability) status and take a look at it, then.

@fuchsmich
Copy link
Author

How can I help you? Should I run any commands?

@Olf0
Copy link
Owner

Olf0 commented Feb 17, 2021

Well, IMO primarily you should try to help yourself, as nobody else seem to have run into this issue yet, presumably because noone of the ~20 crypto-sdcard users has subscribed the "Early Access (EA)" channel of SFOS with their production device.
As I know and see (above), that you are quite command line savvy and likely willing to read documentation (man pages etc.) properly, I rather provide some structural guidance.

As some things seem to run O.K., I would first follow that route: It may provide a workaround to get things going again, plus some analyses may provide more insights for a proper fix, even if not primarily pursuing this.
Side note: I am typing the following commands, without having tried them. There may be typos, thinkos, incorrect option names etc.!

  1. How do the "O.K." and other entries look like: ls -l /dev/crypto*
    -> Should be symbolic ("soft") links to their basic device / partition.
  2. Status of units creating them and the ones mounting them:
    1. systemctl list-units -l "*crypto*"
    2. systemctl status -l "*crypto*"
  3. Then look for decrypted devices: ls -l /dev/mapper/crypto*
  4. Is the correct (, presumably only) one mounted? mount | fgrep crypto

@fuchsmich
Copy link
Author

First of all, it's always a joy reading your detailed and well written posts!

Second: 4.0.1 isn't EA anymore since yesterday. ;) I switched from X to XA2, so it happend, that I flashed 4.0.1 to my phone yesterday, after the touchscreen had some problems.

Third: I wrote non-template systemd units replacing %i and %I manually. I modified the udev rule ot call this systemd unit. The mount service doesn't start automatically, but I had no time investigating that, yet. But the card mounts, when I run systemctl start mount-cryptosd-myluks.service. I'm glad I got my backups back.

# ls -l /dev/crypto*
ls: /dev/crypto*: No such file or directory
# systemctl list-units -l --all "*crypto*"
UNIT                                                                                                                                                      LOAD   ACTIVE   SUB     DESCRIPTION
dev-crypto_luks_cc05650d\x2d0126\x2d4bc8\x2db8e5\x2da1fe25606f6f.device                                                                                   loaded active   plugged /dev/crypto_luks_cc05650d-0126-4bc8-b8e5-a1fe25606f6f
dev-crypto_luks_cc05650dx2d0126x2d4bc8x2db8e5x2da1fe25606f6f.device                                                                                       loaded inactive dead    dev-crypto_luks_cc05650dx2d0126x2d4bc8x2db8e5x2da1fe25606f6f.device
dev-disk-by\x2did-dm\x2dname\x2dcrypto_luks_cc05650d\x2d0126\x2d4bc8\x2db8e5\x2da1fe25606f6f.device                                                       loaded active   plugged /dev/disk/by-id/dm-name-crypto_luks_cc05650d-0126-4bc8-b8e5-a1fe25606f6f
dev-disk-by\x2did-dm\x2duuid\x2dCRYPT\x2dLUKS1\x2dcc05650d01264bc8b8e5a1fe25606f6f\x2dcrypto_luks_cc05650d\x2d0126\x2d4bc8\x2db8e5\x2da1fe25606f6f.device loaded active   plugged /dev/disk/by-id/dm-uuid-CRYPT-LUKS1-cc05650d01264bc8b8e5a1fe25606f6f-crypto_luks_cc05650d-012
dev-disk-by\x2dlabel-jolla\x2dcrypto\x2dsd.device                                                                                                         loaded active   plugged /dev/disk/by-label/jolla-crypto-sd
dev-mapper-crypto_luks_cc05650d\x2d0126\x2d4bc8\x2db8e5\x2da1fe25606f6f.device                                                                            loaded active   plugged /dev/mapper/crypto_luks_cc05650d-0126-4bc8-b8e5-a1fe25606f6f
dev-mapper-crypto_luks_cc05650dx2d0126x2d4bc8x2db8e5x2da1fe25606f6f.device                                                                                loaded inactive dead    dev-mapper-crypto_luks_cc05650dx2d0126x2d4bc8x2db8e5x2da1fe25606f6f.device
run-media-defaultuser-jolla\x2dcrypto\x2dsd.mount                                                                                                         loaded active   mounted /run/media/defaultuser/jolla-crypto-sd
cryptosd-luks@crypto_luks_cc05650dx2d0126x2d4bc8x2db8e5x2da1fe25606f6f.service                                                                            loaded inactive dead    Open DM-Crypt LUKS on SD-card crypto_luks_cc05650dx2d0126x2d4bc8x2db8e5x2da1fe25606f6f
cryptosd-myluks.service                                                                                                                                   loaded active   exited  Open DM-Crypt LUKS on SD-card crypto_luks_cc05650d-0126-4bc8-b8e5-a1fe25606f6f
mount-cryptosd-luks@crypto_luks_cc05650dx2d0126x2d4bc8x2db8e5x2da1fe25606f6f.service                                                                      loaded inactive dead    Mount LUKS encrypted SD-card (crypto_luks_cc05650dx2d0126x2d4bc8x2db8e5x2da1fe25606f6f) with
mount-cryptosd-myluks.service                                                                                                                             loaded active   exited  Mount LUKS encrypted SD-card (crypto_luks_cc05650d-0126-4bc8-b8e5-a1fe25606f6f) with udisks
system-cryptosd\x2dluks.slice                                                                                                                             loaded active   active  system-cryptosd\x2dluks.slice
system-mount\x2dcryptosd\x2dluks.slice 
]# systemctl status -l "*crypto*"
● mount-cryptosd-myluks.service - Mount LUKS encrypted SD-card (crypto_luks_cc05650d-0126-4bc8-b8e5-a1fe25606f6f) with udisks
   Loaded: loaded (/etc/systemd/system/mount-cryptosd-myluks.service; static; vendor preset: enabled)
   Active: active (exited) since Wed 2021-02-17 15:05:32 CET; 5h 47min ago
     Docs: https://github.com/Olf0/crypto-sdcard
  Process: 9172 ExecStart=/usr/bin/udisksctl-user mount -b /dev/mapper/crypto_luks_cc05650d-0126-4bc8-b8e5-a1fe25606f6f (code=exited, status=0/SUCCESS)
  Process: 9158 ExecStartPre=/bin/sleep 1 (code=exited, status=0/SUCCESS)
 Main PID: 9172 (code=exited, status=0/SUCCESS)

Warning: Journal has been rotated since unit was started. Log output is incomplete or unavailable.

● system-mount\x2dcryptosd\x2dluks.slice
   Loaded: loaded
   Active: active since Wed 2021-02-17 15:02:04 CET; 5h 51min ago
   Memory: 0B
   CGroup: /system.slice/system-mount\x2dcryptosd\x2dluks.slice

Warning: Journal has been rotated since unit was started. Log output is incomplete or unavailable.

● cryptosd-myluks.service - Open DM-Crypt LUKS on SD-card crypto_luks_cc05650d-0126-4bc8-b8e5-a1fe25606f6f
   Loaded: loaded (/etc/systemd/system/cryptosd-myluks.service; static; vendor preset: enabled)
   Active: active (exited) since Wed 2021-02-17 15:02:04 CET; 5h 51min ago
     Docs: https://github.com/Olf0/crypto-sdcard
  Process: 2953 ExecStart=/usr/sbin/cryptsetup --allow-discards -d /etc/crypto-sdcard/crypto_luks_cc05650d-0126-4bc8-b8e5-a1fe25606f6f.key luksOpen /dev/crypto_luks_cc05650d-0126-4bc8-b8e5-a1fe25606f6f crypto_luks_cc05650d-0126-4bc8-b8e5-a1fe25606f6f (code=exited, status
 Main PID: 2953 (code=exited, status=0/SUCCESS)

Warning: Journal has been rotated since unit was started. Log output is incomplete or unavailable.

● run-media-defaultuser-jolla\x2dcrypto\x2dsd.mount - /run/media/defaultuser/jolla-crypto-sd
   Loaded: loaded (/proc/self/mountinfo)
   Active: active (mounted) since Wed 2021-02-17 15:05:32 CET; 5h 47min ago
    Where: /run/media/defaultuser/jolla-crypto-sd
     What: /dev/mapper/crypto_luks_cc05650d-0126-4bc8-b8e5-a1fe25606f6f

Warning: Journal has been rotated since unit was started. Log output is incomplete or unavailable.

● system-cryptosd\x2dluks.slice
   Loaded: loaded
   Active: active since Wed 2021-02-17 15:02:04 CET; 5h 51min ago
   Memory: 0B
   CGroup: /system.slice/system-cryptosd\x2dluks.slice
# ls -l /dev/mapper/crypto*
brw-rw----    1 root     disk      252,   2 Feb 17 15:02 /dev/mapper/crypto_luks_cc05650d-0126-4bc8-b8e5-a1fe25606f6f
# mount |fgrep crypto
/dev/mapper/crypto_luks_cc05650d-0126-4bc8-b8e5-a1fe25606f6f on /run/media/defaultuser/jolla-crypto-sd type ext4 (rw,nosuid,nodev,relatime,data=ordered,uhelper=udisks2)

...but I'm afraid my system is a mess now, as I left crypto-sdcard installed and modified the files like mentioned above. When I find some more time, I can run the commands with a fresh install of crypto-sdcard.

@Olf0
Copy link
Owner

Olf0 commented Feb 17, 2021

I'm glad I got my backups back.

Good!
This is why I was aiming at a workaround, first.
So since yesterday, this may also happen to a broader group of people and more likely on production devices. Now everyone affected can access their data manually, until a proper adaption to SFOS 4.0.1 is deployed.

Thank you for the command line outputs. They are helpful, even though a bit hard to interpret, because the effects of the units you manually fixed and the original ones failing are displayed.

I perceived the first ls-output as surprising: Yes, one might assume, that none of the rules in /etc/udev/rules.d/96-cryptosd.rules are run, because even the symlink in line 2 is not created. But wouldn't the effect be the same, if /usr/bin/systemd-escape fails somehow?

Output 2 displays the "usual" mix of correctly and incorrectly escaped paths, either (see suffix) to a .device or in the instance name of an instanciated .service unit. You see that both original service units (the unlocking and the mounting one) carry the same, faulty instance name, likely a result of the incorrectly escaped .device path. Again, this looks as if something in 96-cryptosd.rules became severely broken.
It would be easier to interpret, if only one set of service units is running while generating this output, either your patched ones or the original ones. You can easily disable a unit completely by appending a "~" to its file name, so it ends in ".service~".

Outputs 3, 4 and 5 show, that you have everything up and running, although by your patched units, plus by manually starting them.

@erikderzweite
Copy link

erikderzweite commented Feb 18, 2021

I would be the second one to run into that issue :)
I cannot start the systemd scripts though:
systemctl start mount-cryptosd-luks@nemo A dependency job for mount-cryptosd-luks@nemo.service failed. See 'journalctl -xe' for details.
need to luksOpen manually to access the data. Sailfish's GUI always asks for password even if no keys with password are set up.

@Olf0
Copy link
Owner

Olf0 commented Feb 18, 2021

I would be the second one to run into that issue :)

I am just upgrading my new testing device (an XA2+) to SFOS 4.0.1, because my old one dies (and became useless, anyway: it is a Jolla 1). It does not have an encrypted SD-card in it, yet (but I have some SD-cards around), so I may start my own efforts to analyse this issue this weekend.

[...] Sailfish's GUI always asks for password even if no keys with password are set up.

There are no "keys with password": You just input entropy, which is hashed then. The hash is then used as a "key value", which must match one saved in a "key slot" to unlock the real cryptographic key.
Technically it does not matter, from where this entropy is coming (e.g., file or terminal), but the source still makes a difference in how the input data is parsed: For LUKS (see special notes about that and option --key-file ff.: without this option reading stops at a newline) and subtly different for "plain" mode.
I once considered to alter the reading of a "key-file" to make it fully compatible to manually inputting it (at the SFOS GUI or in a terminal with cryptsetup or udisksctl unlock at the command line), but dropped the idea, because it would lower the entropy used (relevant to counteract brute force attacks), as it stops reading at the first newline character. Furthermore, it would break all extant "key-files", which contain newline characters, as they result in a different hash after such a change. As I advise to generate "key-files" with random content (by reading from /dev/[u]random), extant ones likely do contain newline characters.

So if your "key-file" does not contain newline characters and also only characters which can be entered per keyboard, you can just as well input its content at the SFOS GUI to unlock your encrypted partition.

@Olf0
Copy link
Owner

Olf0 commented Feb 19, 2021

Easier workaround to manually access the LUKS encrypted partitions (used with crypto-sdcard) at the GUI.
You may use this (works since SailfishOS 3.0.0), until a proper adaption for SFOS 4.0.1 is designed, implemented, tested and deployed.

devel-su
# Input NUMERIC "key" interactively, concluding by hitting the "Return (CR)" key (which emits a newline character):
cryptsetup LuksAddKey --key-file /etc/crypto-sdcard/crypto_luks_$(blkid -c /dev/null -s UUID -o value /dev/<device-name>).key /dev/<device-name>
# Mind to substitute <device-name> twice, e.g. with mmcblk1p2 

Side note: For details, see LUKS key management.
Then you should be able to unlock & mount (in one go) the encrypted partition at the SFOS GUI by using the freshly set numeric "key".

Can someone please check, that this works fine?

@Olf0
Copy link
Owner

Olf0 commented Feb 20, 2021

Looking for possibly relevant changes between Systemd 225 and 238, I found introduced in v236, "If a udev device has a SYSTEMD_WANTS= ...", and (more unlikely to cause this issue) in v233, "When units are about to be started ...". At least something worth investigating.

Edit:
Much more interesting are these entries from the udev changelog: In udev 138, "fix NAME= and OPTION+="string_escape=..." logic" and in udev 131, "fix handling of string_escape option", but both are historic (about a decade old; as udev follows the Systemd version numbers since its integration, SFOS always had way newer versions).
But these changelog entries led me to searching the web, finding e.g, "Why does udev ...?"@stackexchange, which is much more recent and also points to OPTIONS+="string_escape=none".

@fuchsmich
Copy link
Author

I reinstalled crypto-sdcard now.

udevadm test $(udevadm info --query=path --name=/dev/mmcblk1p1) 2>&1 |grep crypto
Reading rules file: /etc/udev/rules.d/96-cryptosd.rules
PROGRAM '/usr/bin/systemd-escape crypto_luks_cc05650d-0126-4bc8-b8e5-a1fe25606f6f' /etc/udev/rules.d/96-cryptosd.rules:2
starting '/usr/bin/systemd-escape crypto_luks_cc05650d-0126-4bc8-b8e5-a1fe25606f6f'
'/usr/bin/systemd-escape crypto_luks_cc05650d-0126-4bc8-b8e5-a1fe25606f6f'(out) 'crypto_luks_cc05650d\x2d0126\x2d4bc8\x2db8e5\x2da1fe25606f6f'
Process '/usr/bin/systemd-escape crypto_luks_cc05650d-0126-4bc8-b8e5-a1fe25606f6f' succeeded.
MODE 0660 /etc/udev/rules.d/96-cryptosd.rules:2
LINK 'crypto_luks_cc05650d-0126-4bc8-b8e5-a1fe25606f6f' /etc/udev/rules.d/96-cryptosd.rules:2
found 'b179:65' claiming '/run/udev/links/\x2fcrypto_luks_cc05650d-0126-4bc8-b8e5-a1fe25606f6f'
creating link '/dev/crypto_luks_cc05650d-0126-4bc8-b8e5-a1fe25606f6f' to '/dev/mmcblk1p1'
preserve already existing symlink '/dev/crypto_luks_cc05650d-0126-4bc8-b8e5-a1fe25606f6f' to 'mmcblk1p1'
DEVLINKS=/dev/disk/by-id/mmc-SC64G_0x51babdea-part1 /dev/disk/by-uuid/cc05650d-0126-4bc8-b8e5-a1fe25606f6f /dev/block/mmcblk1p1 /dev/disk/by-path/platform-c084000.sdhci-part1 /dev/crypto_luks_cc05650d-0126-4bc8-b8e5-a1fe25606f6f
ID_FS_TYPE=crypto_LUKS
ID_FS_USAGE=crypto
SYSTEMD_WANTS=cryptosd-luks@crypto_luks_cc05650d\x2d0126\x2d4bc8\x2db8e5\x2da1fe25606f6f.service

Full output: https://gist.github.com/fuchsmich/9aa70436de48a7bb811b13009cdb5b4c

@fuchsmich
Copy link
Author

fuchsmich commented Feb 20, 2021

#  ls -l /dev/crypto*
lrwxrwxrwx    1 root     root             9 Feb 20 12:53 /dev/crypto_luks_cc05650d-0126-4bc8-b8e5-a1fe25606f6f -> mmcblk1p1
# systemctl list-units -l --all "*crypto*"
UNIT                                                                           LOAD   ACTIVE   SUB     DESCRIPTION                                                 
dev-crypto_luks_cc05650d\x2d0126\x2d4bc8\x2db8e5\x2da1fe25606f6f.device        loaded active   plugged /dev/crypto_luks_cc05650d-0126-4bc8-b8e5-a1fe25606f6f       
dev-crypto_luks_cc05650dx2d0126x2d4bc8x2db8e5x2da1fe25606f6f.device            loaded inactive dead    dev-crypto_luks_cc05650dx2d0126x2d4bc8x2db8e5x2da1fe25606f6f
cryptosd-luks@crypto_luks_cc05650dx2d0126x2d4bc8x2db8e5x2da1fe25606f6f.service loaded inactive dead    Open DM-Crypt LUKS on SD-card crypto_luks_cc05650dx2d0126x2d
system-cryptosd\x2dluks.slice                                                  loaded active   active  system-cryptosd\x2dluks.slice                               

LOAD   = Reflects whether the unit definition was properly loaded.
ACTIVE = The high-level unit activation state, i.e. generalization of SUB.
SUB    = The low-level unit activation state, values depend on unit type.

4 loaded units listed.
To show all installed unit files use 'systemctl list-unit-files'.
# ls -l /dev/mapper/crypto*
ls: /dev/mapper/crypto*: No such file or directory
# mount |fgrep crypto
# systemctl status -l "*crypto*"
● system-cryptosd\x2dluks.slice
   Loaded: loaded
   Active: active since Sat 2021-02-20 12:40:32 CET; 21min ago
   Memory: 0B
   CGroup: /system.slice/system-cryptosd\x2dluks.slice

Warning: Journal has been rotated since unit was started. Log output is incomplete or unavailable.

@Olf0
Copy link
Owner

Olf0 commented Feb 20, 2021

udevadm test $(udevadm info --query=path --name=/dev/mmcblk1p1) 2>&1
Full output: https://gist.github.com/fuchsmich/9aa70436de48a7bb811b13009cdb5b4c

Thank you, this is interesting: All looks perfectly fine on udev level WRT /dev/mmcblk1p1!
Side note: I never saw found 'b179:65' claiming '/run/udev/links/\x2fcrypto_luks_cc05650d-0126-4bc8-b8e5-a1fe25606f6f (note the added "\x2f"), but likely never looked at this output before.

And there is nothing to observe with udevadm test $(udevadm info --query=path --name=/dev/mapper/crypto_luks_cc05650d-0126-4bc8-b8e5-a1fe25606f6f) 2>&1, because /dev/crypto_luks_cc05650d-0126-4bc8-b8e5-a1fe25606f6f is not successfully unlocked, anymore.

# systemctl list-units -l --all "*crypto*"
UNIT                                                                           LOAD   ACTIVE   SUB     DESCRIPTION                                                 
dev-crypto_luks_cc05650d\x2d0126\x2d4bc8\x2db8e5\x2da1fe25606f6f.device        loaded active   plugged /dev/crypto_luks_cc05650d-0126-4bc8-b8e5-a1fe25606f6f       
dev-crypto_luks_cc05650dx2d0126x2d4bc8x2db8e5x2da1fe25606f6f.device            loaded inactive dead    dev-crypto_luks_cc05650dx2d0126x2d4bc8x2db8e5x2da1fe25606f6f
cryptosd-luks@crypto_luks_cc05650dx2d0126x2d4bc8x2db8e5x2da1fe25606f6f.service loaded inactive dead    Open DM-Crypt LUKS on SD-card crypto_luks_cc05650dx2d0126x2d
...
  • Where is cryptosd-luks@dev-crypto_luks_cc05650d\x2d0126\x2d4bc8\x2db8e5\x2da1fe25606f6f.service, which successfully created the first entry: dev-crypto_luks_cc05650d\x2d0126\x2d4bc8\x2db8e5\x2da1fe25606f6f.device?
    -> Likely a statement in some line in udev rule 96-... did, but not a service unit.
  • What creates the broken cryptosd-luks@crypto_luks_cc05650dx2d0126x2d4bc8x2db8e5x2da1fe25606f6f.service (fourth line), which created the broken dev-crypto_luks_cc05650dx2d0126x2d4bc8x2db8e5x2da1fe25606f6f.device (third line)?
    -> Also likely a statement in some line in udev rule 96-...!

Still puzzled, but I think we're slowly encircling the core of this issue.

@Olf0
Copy link
Owner

Olf0 commented Feb 20, 2021

Oh, from your third posting, in its second command line output:

systemctl status -l "*crypto*"
...
● run-media-defaultuser-jolla\x2dcrypto\x2dsd.mount - /run/media/defaultuser/jolla-crypto-sd
  Loaded: loaded (/proc/self/mountinfo)
  Active: active (mounted) since Wed 2021-02-17 15:05:32 CET; 5h 47min ago
  Where: /run/media/defaultuser/jolla-crypto-sd
  What: /dev/mapper/crypto_luks_cc05650d-0126-4bc8-b8e5-a1fe25606f6f
...

Is that still there? That seems to have successfully mounted the unlocked partition (/dev/mapper/crypto_luks_cc05650d-0126-4bc8-b8e5-a1fe25606f6f, but what unlocked it?) at /run/media/defaultuser/jolla-crypto-sd.
It is a mount unit. You did not create one, correct?
Side note: Jolla stated long ago, that they consider making crypto-sdcard's functionality (automatic mounting) available in SailfishOS. Maybe their first steps in this direction interfere with crypto-sdcard.

Edit: Apparently not, see last listing in your latest post, above.

@fuchsmich
Copy link
Author

Is that still there? That seems to have successfully mounted the unlocked partition (/dev/mapper/crypto_luks_cc05650d-0126-4bc8-b8e5-a1fe25606f6f, but what unlocked it?)

AFAIR, back then I unlocked the sd manually before I ran the commands in my third post.

@Olf0
Copy link
Owner

Olf0 commented Feb 21, 2021

Well, first (yesterday) I could not really decide to either do some research (primarily reading documentation and searching the web) to gather ideas for reasons and fixes, or to perform some thorough, bottom-up and step-by-step analysis, which is tedious and also involves reading a lot of documentation. Ultimately I slipped into trying a few ideas ("educated guesses"), while also adopting / adapting the recent changes from mount-sdcard.
A goal was to only introduce changes, which do not pose a risk of destabilising crypto-sdcard's startup and shutdown behaviour (I have two of those in store, which should speed up startup and shutdown a bit), and either are well tested (per mount-sdcard), should make crypto-sdcard more robust (some of the former, plus some older ideas, which were never implemented, because it was working well), or are specifically aimed at (potentially) addressing this issue (OPTIONS+="string_escape=none" added to all rules in 96-cryptosd.rules). And I only added backward compatible changes, avoiding an sfos401 branch for now.
Although I became distracted today by this issue report for mount-sdcard (temporally and by its content, which may also be relevant here), I released crypto-sdcard 1.3.4 (only here at Github and as a pre-release, for now). It is tested on an XperiaX@SFOS3.2.1 (installs, automatically starts and mounts, plus reboots fine) and "install-tested" on an XperiaXA2+@SFOS4.0.1 (installs and reboots fine).

Please download and install the correct variant of crypto-sdcard 1.3.4-1.sfos*.noarch.rpm (e.g., for all Xperias@SFOS3.4.0) to check, if it makes a difference for its (automatic) starting and mounting behaviour on SFOS 4.0.1:

  • If it works, please remove all occurrences of , OPTIONS+="string_escape=none" in 96-cryptosd.rules (after backing it up) and reboot to check, if the change of this option's default has been the cause. E.g. by (not tested, just written down):
    devel-su
    cd /etc/udev/rules.d/
    mv 96-cryptosd.rules 96-cryptosd.rules.orig  # "backup"
    sed 's/, OPTIONS[+]="string_escape=none"//g' 96-cryptosd.rules.orig > 96-cryptosd.rules
    reboot
    
  • If it does not work, please take a quick look, if anything changed at all on <your device>@SFOS4.0.1.
    Though I have already carried out some scattered, initial steps of a bottom-up and step-by-step analysis, I will not be able to devote much time to that until maybe next weekend.

@Olf0 Olf0 added open question(s) Further information is requested an sfos update broke it An update of SFOS broke this labels Feb 23, 2021
@fuchsmich
Copy link
Author

fuchsmich commented Feb 23, 2021

I will not be able to devote much time to that until maybe next weekend.

No problem, I know now how to test your mods and restore my temporary solution.

In my case 1.3.4 doens't work. luks device won't be opened.

#  systemctl list-units -l --all "*crypto*"
UNIT                                                                           LOAD   ACTIVE   SUB     DESCRIPTION
dev-crypto_luks_cc05650d\x2d0126\x2d4bc8\x2db8e5\x2da1fe25606f6f.device        loaded active   plugged /dev/crypto_luk
dev-crypto_luks_cc05650dx2d0126x2d4bc8x2db8e5x2da1fe25606f6f.device            loaded inactive dead    dev-crypto_luks
cryptosd-luks@crypto_luks_cc05650dx2d0126x2d4bc8x2db8e5x2da1fe25606f6f.service loaded inactive dead    Open DM-Crypt L
system-cryptosd\x2dluks.slice                                                  loaded active   active  system-cryptosd

@Olf0
Copy link
Owner

Olf0 commented Feb 23, 2021

:-(

Well, my little analysis so far:

  • The first ("O.K."-) device is simply the one created by the SYMLINK+="crypto_luks_%E{ID_FS_UUID}" of the first rule in 96-cryptosd.rules
  • Every aspect of systemd-escape from Systemd 238 (in SFOS 4.0.1) seems to work as before (with Systemd 225 in SFOS 2.2.1 to 3.4.0): tested thoroughly
  • Something seems to strip all "\" from the argument string referenced per "%c" when calling units per ENV{SYSTEMD_WANTS}="%c", either the caller (udev) or the callee (Systemd).
    This is apparently where some change occurred between SFOS 3.4.0 and 4.0.1.
  • All effects / failures seen seem to stem from this (directly or indirectly).
  • My current theory is a bug in Systemd / udev (which has become a part of Systemd long ago). :-(

@fuchsmich
Copy link
Author

I'm quite sure this dead nonesense-device gets created by the systemd polling it incorrectly.

@Olf0
Copy link
Owner

Olf0 commented Feb 23, 2021

I'm quite sure this dead nonesense-device gets created by the systemd polling it incorrectly.

This is what I meant with:

  • All effects / failures seen seem to stem from this (directly or indirectly).

@Olf0 Olf0 added help wanted Extra attention is needed and removed open question(s) Further information is requested labels Feb 23, 2021
@Olf0
Copy link
Owner

Olf0 commented Feb 24, 2021

@fuchsmich, can you please try (on SFOS 4.0.1 with crypto-sdcard 1.3.4 installed):

devel-su
cd /etc/udev/rules.d/
mv 96-cryptosd.rules 96-cryptosd.rules.original  # "backup"
sed "s/%c/'%c'/g" 96-cryptosd.rules.original > 96-cryptosd.rules
reboot

Source of this idea: This Ubuntu bug matches exactly this issue and provides this solution (hard quoting of %c per ' ', as inserted above by sed).

Edit / P.S.: As usual, when knowing which search terms to use (because one has finally found something relevant), more "hits" are easy to achieve, e.g. in the Systemd issue 7109 and the ev3dev issue 1433!

Olf0 added a commit that referenced this issue Feb 25, 2021
Revert [commit \#2bf46d9](2bf46d9), because `OPTIONS+="string_escape=none"` should only affect "*strings used for device naming*" [per **udev** documentation](https://www.freedesktop.org/software/systemd/man/udev.html#string_escape=none%7Creplace), e.g. strings used for setting `NAME` and `SYMLINK`.<br />
Rationale:
  1. The strings *crypto-sdcard* generates and uses in [96-cryptosd.rules](https://github.com/Olf0/crypto-sdcard/blob/master/udev/rules.d/96-cryptosd.rules) for device naming should always be free of escape sequences and other "potentially dangerous" characters.  If some flaw causes this not to be true anymore (e.g., see issue #115), it is fine that *udev* might filter device strings (although this mechanism makes debugging such flaws harder).
  1. It did not alleviate the breakage SFOS 4.0.1. brought (issue #115).  This also might prove that `string_escape=none` is not applicable to evaluating "`%c`" or inserting a string into `ENV{SYSTEMD_WANTS}=""` / `ENV{SYSTEMD_USER_WANTS}=""` statements, because the strings generated by `systemd-escape` for *crypto-sdcard* contain a lot of C-style escape sequences (or they are not considered "dangerous").  Because OTOH manually calling (at the command line) instanciated Systemd units with pre-escaped instance names works (?does it still on SFOS 4.0.1?), it is apparently the call interface proper which filters (or just misinterprets, e.g. in one of its many automatic detections) the unit string (?or just the instance name?) when handing over the content of a `ENV{SYSTEMD_WANTS}=""` / `ENV{SYSTEMD_USER_WANTS}=""` statement.
Olf0 added a commit that referenced this issue Feb 25, 2021
Should resolve issue #115, see #115 (comment)
@Olf0
Copy link
Owner

Olf0 commented Feb 25, 2021

Analysis so far

Systemd explicitly calls its function extract_first_word with the attribute EXTRACT_UNQUOTE, hence the string handed over per ENV{SYSTEMD_*WANTS}="" from udev to Systemd (and then the separated instance string to the called unit) can be hard-quoted (per "'"), becomes unquoted by Systemd (then still including the unit name) and should ultimately arrive at the called unit (the instance string as "%i") as it was originally inserted into PROGRAM="".
In somebody else's words.

@Olf0 Olf0 added the bug Something isn't working label Feb 25, 2021
@fuchsmich
Copy link
Author

Sorry, still same result with udev rules in 1.4

@Olf0 Olf0 added the open question(s) Further information is requested label Mar 11, 2021
@Olf0
Copy link
Owner

Olf0 commented Mar 14, 2021

@fuchsmich, @erikderzweite et al, please check crypto-sdcard 1.4.2-1.sfos401regular on your devices with SailfishOS 4.0.1. It is working fine for me.
I will release v1.4.2 at OpenRepos after receiving positive feedback (hopefully) from you.

@Olf0 Olf0 added enhancement New feature or request and removed help wanted Extra attention is needed bug Something isn't working labels Mar 14, 2021
@carmenfdezb
Copy link

carmenfdezb commented Mar 16, 2021

Hi @Olf0! I've updated crypto-sdcard to last version released at OpenRepos (v1.4.2-1) but it doesn't work for me on my XA2 with SailfishOS 4.0.1: sd-card doesn't mount automatically.
If I do 'devel-su journalctl | grep -i crypto':

mar 13 00:06:51 XperiaXA2 [RPM][24722]: erase libblockdev-crypto-2.19+git1-1.3.4.jolla.armv7hl: success mar 13 00:06:51 XperiaXA2 [RPM][24722]: install libblockdev-crypto-2.19+git1-1.2.5.jolla.armv7hl: success mar 13 00:06:51 XperiaXA2 [RPM][24722]: erase libblockdev-crypto-2.19+git1-1.3.4.jolla.armv7hl: success mar 13 00:06:51 XperiaXA2 [RPM][24722]: install libblockdev-crypto-2.19+git1-1.2.5.jolla.armv7hl: success mar 13 00:08:48 XperiaXA2 systemd[1]: Stopping Mount LUKS encrypted SD-card (crypto_luks_4b8cf138-d701-41b3-a45f-729886a19bff) with udisks... mar 13 00:08:49 XperiaXA2 systemd[1]: mount-cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff.service: Control process exited, code=exited status=32 mar 13 00:08:49 XperiaXA2 systemd[1]: mount-cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff.service: Failed with result 'exit-code'. mar 13 00:08:49 XperiaXA2 unknown: type=1130 audit(1615590529.319:271): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=mount-cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed' mar 13 00:08:49 XperiaXA2 audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=mount-cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed' mar 13 00:08:49 XperiaXA2 systemd[1]: Stopped Mount LUKS encrypted SD-card (crypto_luks_4b8cf138-d701-41b3-a45f-729886a19bff) with udisks. mar 13 00:08:49 XperiaXA2 unknown: type=1130 audit(1615590529.319:271): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=mount-cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed' mar 13 00:08:51 XperiaXA2 systemd[1]: Starting Mount LUKS encrypted SD-card (crypto_luks_4b8cf138-d701-41b3-a45f-729886a19bff) with udisks... mar 13 00:08:52 XperiaXA2 unknown: type=1130 audit(1615590532.717:275): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=mount-cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' mar 13 00:08:52 XperiaXA2 systemd[1]: Started Mount LUKS encrypted SD-card (crypto_luks_4b8cf138-d701-41b3-a45f-729886a19bff) with udisks. mar 13 00:08:52 XperiaXA2 audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=mount-cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' mar 13 00:08:54 XperiaXA2 systemd-udevd[27742]: conflicting device node '/dev/mapper/crypto_luks_4b8cf138-d701-41b3-a45f-729886a19bff' found, link to '/dev/dm-2' will not be created mar 13 00:10:29 XperiaXA2 unknown: type=1130 audit(1615590532.717:275): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=mount-cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' mar 13 00:12:16 XperiaXA2 [RPM][32500]: erase libsailfishcryptopluginapi-0.2.20-1.14.10.jolla.armv7hl: success mar 13 00:12:16 XperiaXA2 [RPM][32500]: install libsailfishcryptopluginapi-0.2.21-1.15.20.jolla.armv7hl: success mar 13 00:12:16 XperiaXA2 [RPM][32500]: erase libsailfishcryptopluginapi-0.2.20-1.14.10.jolla.armv7hl: success mar 13 00:12:17 XperiaXA2 [RPM][32500]: install libsailfishcryptopluginapi-0.2.21-1.15.20.jolla.armv7hl: success mar 13 00:12:19 XperiaXA2 [RPM][32532]: erase libsailfishcrypto-0.2.20-1.14.10.jolla.armv7hl: success mar 13 00:12:19 XperiaXA2 [RPM][32532]: install libsailfishcrypto-0.2.21-1.15.20.jolla.armv7hl: success mar 13 00:12:20 XperiaXA2 [RPM][32532]: erase libsailfishcrypto-0.2.20-1.14.10.jolla.armv7hl: success mar 13 00:12:20 XperiaXA2 [RPM][32532]: install libsailfishcrypto-0.2.21-1.15.20.jolla.armv7hl: success mar 13 00:14:32 XperiaXA2 systemd[1]: Stopping Mount LUKS encrypted SD-card (crypto_luks_4b8cf138-d701-41b3-a45f-729886a19bff) with udisks... mar 13 00:14:33 XperiaXA2 systemd[1]: Stopping Cryptography Setup for luks-dc86b46b-ed41-4c65-8885-fed83b881400... mar 13 00:14:33 XperiaXA2 systemd[1]: Stopped Cryptography Setup for luks-dc86b46b-ed41-4c65-8885-fed83b881400. mar 13 00:14:34 XperiaXA2 umount[3201]: umount: /dev/crypto_luks_4b8cf138-d701-41b3-a45f-729886a19bff: no mount point specified. mar 13 00:14:34 XperiaXA2 systemd[1]: mount-cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff.service: Control process exited, code=exited status=32 mar 13 00:14:34 XperiaXA2 unknown: type=1130 audit(1615590874.166:364): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=mount-cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed' mar 13 00:14:34 XperiaXA2 systemd[1]: mount-cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff.service: Failed with result 'exit-code'. mar 13 00:14:34 XperiaXA2 audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=mount-cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed' mar 13 00:14:34 XperiaXA2 systemd[1]: Stopped Mount LUKS encrypted SD-card (crypto_luks_4b8cf138-d701-41b3-a45f-729886a19bff) with udisks. mar 13 00:14:34 XperiaXA2 systemd[1]: Stopping Open DM-Crypt LUKS on SD-card crypto_luks_4b8cf138-d701-41b3-a45f-729886a19bff... mar 13 00:14:34 XperiaXA2 systemd[1]: Removed slice system-mount\x2dcryptosd\x2dluks.slice. mar 13 00:14:34 XperiaXA2 systemd[1]: Stopped Open DM-Crypt LUKS on SD-card crypto_luks_4b8cf138-d701-41b3-a45f-729886a19bff. mar 13 00:14:34 XperiaXA2 unknown: type=1130 audit(1615590874.166:364): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=mount-cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed' mar 13 00:14:34 XperiaXA2 unknown: type=1130 audit(1615590874.234:365): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' mar 13 00:14:34 XperiaXA2 unknown: type=1130 audit(1615590874.234:365): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' mar 13 00:14:34 XperiaXA2 unknown: type=1131 audit(1615590874.234:366): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' mar 13 00:14:34 XperiaXA2 systemd[1]: Removed slice system-cryptosd\x2dluks.slice. mar 13 00:14:34 XperiaXA2 audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' mar 13 00:14:34 XperiaXA2 audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' mar 13 00:14:34 XperiaXA2 unknown: type=1131 audit(1615590874.234:366): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' mar 16 08:27:29 XperiaXA2 lipstick[6574]: [D] unknown:0 - Setting URL: 0 "https://github.com/Olf0/crypto-sdcard/issues/115" tabs open 3 mar 16 08:27:41 XperiaXA2 lipstick[6574]: [D] onLoadingChanged:143 - url: https://github.com/Olf0/crypto-sdcard/issues/115 0 mar 16 08:27:47 XperiaXA2 lipstick[6574]: [D] onLoadingChanged:143 - url: https://github.com/Olf0/crypto-sdcard/issues/115 2

What am I doing wrong?

@Olf0
Copy link
Owner

Olf0 commented Mar 16, 2021

@fuchsmich @carmenfdezb, I cannot see that ! ;)

  1. While you may have done something wrong, more likely it was me.
  2. I literally cannot see much in above output dump, because all linebreaks have gone overboard somewhere in your workflow from the terminal output to github. You may want to improve on that, i.e. identify and avoid the step which strips the linebreaks.
  3. I managed to browse through ca. the first half of the output dump twice (before the lines started "dancing"): This is mostly looking good, except for the umount[3201]: umount: /dev/crypto_luks_4b8cf138-d701-41b3-a45f-729886a19bff: no mount point specified. This was flaw in the fallback- (/ "safety"-) umount code-path. It should have been (and is now) ExecStopPost=/bin/umount -vrq /dev/mapper/%I, for directing the umount to the correct virtual device. Thanks for notifying me.
  4. The real question is (and what I did not gather from the dump), why was the fallback umount triggered?
    I suppose this is an extract from a boot-up process and the unencrypted partition was not sucessfully mounted (you did not denote either point clearly)?
  5. But all strings handed over from udev to the instanciated units are perfectly fine (hurray; assuming this is on SFOS 4.0.1, because you are posting in this issue thread), and obviously the unlocking and the triggering of the correct "mounting unit" (mount-cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff.service) worked, too.

Thus please update to crypto-sdcard 1.4.3-1.sfos401regular and debug:

  • For querying the journal, please use journalctl -r while having less installed: Search with \<regex> (e.g., \crypto), then look with the arrow keys at adjacent lines and line endings. Plus, the <PgUp> and <PgDn> keys scroll half a screen height, and pushing the n key searches for the next hit of the last search term.
  • Cutting & pasting from the terminal works fine for me on a Linux-PC and my SFOS devices (both with Firefox as browser for Github), preserving linebreaks.
  • Generic approaches for analysing failures of crypto-sdcard were discussed (a few times under varying aspects) above: Please use them, specifically the steps for an initial analysis and for manually starting crypto-sdcard's units.
  • To me "it looks as if" you captured an OS shutdown (the journal is to be maintained across reboots without being set to "persistent" since long ago), but likely the unit mount-cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff.service was not properly started before above journal extract starts.

@fuchsmich
Copy link
Author

@Olf0 I guess you wanted to address @carmenfdezb :)

Sorry, for not responding muhc lately. I got a lot of work these days, but I'm still following you. Yesterday I had trouble re-enabling my workaround. No idea why it broke first and how I fixed it in the end.

But then again there are a lot of frustrating things happening on my XA2... (Wifi, GPS, Camera, Calls, Bluetooth, ...)

@Olf0
Copy link
Owner

Olf0 commented Mar 18, 2021

@Olf0 I guess you wanted to address @carmenfdezb :)

Yes! Thanks for the notice. Rectified now.

Sorry, for not responding much lately. I got a lot of work these days, but I'm still following you. Yesterday I had trouble re-enabling my workaround. No idea why it broke first and how I fixed it in the end.

That's absolutely O.K., though feedback might be helpful (for me, and maybe for @carmenfdezb, too).

But then again there are a lot of frustrating things happening on my XA2... (Wifi, GPS, Camera, Calls, Bluetooth, ...)

Huh!?!

@Olf0 Olf0 added the help wanted Extra attention is needed label Mar 20, 2021
@Olf0
Copy link
Owner

Olf0 commented Mar 20, 2021

@carmenfdezb, apologies for not paying enough attention to who actually wrote, in my first reply to your comment. I was so absorbed by deciphering the convoluted journal output, that I completely missed it was not fuchsmich posting, because I hoped for a reply from him and up to that point he was the only one active in this thread (aside the issue confirmation by erikderzweite).

Nevertheless, I do need more information.

  • You are using a LUKS (not "plain", which only has niche use cases)? Yes, definitely, its in the journal.
  • Looking at your journal output again, I really think that these are only shutdown messages; not just from crypto-sdcard's units, but from all other units, too.
  • I remember having had similar issues (seeing only old journals / journal entries), which were caused by multiple journal log files (see journalctl --list-boots) in combination with a persistent journal (by setting Storage=persistent in /etc/systemd/journald.conf). The solution was to set Storage=volatile again (or alternatively to =auto), which is advised for FLASH-based mass storage anyway (if not debugging shutdown issues, which do not occur when rebooting), plus deleting all extant, persistent journal files.
    journalctl --disk-usage shall display all extant journals, journalctl --vacuum-files=1 will reduce the number of journals to the active ones.
    Note that looking for events in the journal, which happen at shutdown or startup is best done in a freshly rebooted device: These events will be relatively fresh (i.e., at the top when using journatctl -r) then.
  • It looks as if you are using the SFOS browser for accessing GitHub. This is "calling for trouble", but I sure support your intention (although I personally have given up long ago and just use Firefox / Fennec / IceCat from F-Droid).
    Taking that into account, please pipe whatever command line output to tee (so you can still see it live on the terminal (window)) and redirect it into a file. For example, devel-su Search="crypto"; pwd; journalctl -alru "*$Search*" | tee > journal-r_"$Search"_$(date +'%Ft%H-%M-%S').log.txt dumps a journal extract (named including the search string and a timestamp) to the directory displayed.
    Then you might either
    upload this file (see footer of a comment box at Github; but that did not work with older releases of the SFOS browser)
    or
    cut & paste it via any route which works for you (and linebreaks!) into a comment box, plus prepend and append a line with only three backticks ("```") before and after command line output. Cutting & pasting works a lot better with recent SFOS releases, but for me displaying text in an Android text viewer or editor, cutting it there and pasting it into a Github / Gitlab comment box per Firefox / Fennec / Icecat is still the most reliable route.

@carmenfdezb
Copy link

Hi @olf, sorry for the late answer. Let's see if we can know what go wrong.
I've updated crypto-sdcard to 1.4.3-1 from here: https://github.com/Olf0/crypto-sdcard/releases/tag/1.4.3-1.sfos401regular. I reboot my phone and sdcard doesn't unlock and mount automatically.

  1. Steps for initial analysis:
[root@XperiaXA2 nemo]# ls -l /dev/crypto*
lrwxrwxrwx    1 root     root             7 Mar 20 17:20 /dev/crypto_luks_4b8cf138-d701-41b3a45f-729886a19bff -> mmcblk1
[root@XperiaXA2 nemo]# systemctl list-units -l "*crypto*"
UNIT                          LOAD   ACTIVE SUB    DESCRIPTION                  
system-cryptosd\x2dluks.slice loaded active active system-cryptosd\x2dluks.slice

LOAD   = Reflects whether the unit definition was properly loaded.
ACTIVE = The high-level unit activation state, i.e. generalization of SUB.
SUB    = The low-level unit activation state, values depend on unit type.

1 loaded units listed. Pass --all to see loaded but inactive units, too.
To show all installed unit files use 'systemctl list-unit-files'.
[root@XperiaXA2 nemo]# systemctl status -l "*crypto*"
● system-cryptosd\x2dluks.slice
   Loaded: loaded
   Active: active since Sat 2021-03-20 17:20:36 CET; 47min ago
   Memory: 0B
   CGroup: /system.slice/system-cryptosd\x2dluks.slice

Warning: Journal has been rotated since unit was started. Log output is incomplete or unavailable.
[root@XperiaXA2 nemo]# ls -l /dev/mapper/crypto*
ls: /dev/mapper/crypto*: No such file or directory
  1. Manually starting crypto-sdcard's units
[root@XperiaXA2 nemo]# systemctl start cryptosd-luks@"$(systemd-escape "crypto_luks_$(blkid -c /dev/null -s UUID -o value /dev/mmcblk1)")"
[root@XperiaXA2 nemo]# systemctl start mount-cryptosd-luks@"$(systemd-escape "crypto_luks_$(blkid -c /dev/null -s UUID -o value /dev/mmcblk1)")"
[root@XperiaXA2 nemo]# systemctl list-units -l "*crypto*"  # Just to see what is already there (without --all)
UNIT                                                                                     LOAD   ACTIVE SUB
cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff.service       loaded active exi
mount-cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff.service loaded active exi
system-cryptosd\x2dluks.slice                                                            loaded active act
system-mount\x2dcryptosd\x2dluks.slice                                                   loaded active act

LOAD   = Reflects whether the unit definition was properly loaded.
ACTIVE = The high-level unit activation state, i.e. generalization of SUB.
SUB    = The low-level unit activation state, values depend on unit type.

4 loaded units listed. Pass --all to see loaded but inactive units, too.
To show all installed unit files use 'systemctl list-unit-files'.
[root@XperiaXA2 nemo]# systemctl list-units -l -all "*crypto*"  # Just to compare what already failed due to the broken startup
UNIT                                                                                                      
dev-crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff.device                                   
dev-disk-by\x2did-dm\x2dname\x2dcrypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff.device       
dev-disk-by\x2did-dm\x2duuid\x2dCRYPT\x2dLUKS1\x2d4b8cf138d70141b3a45f729886a19bff\x2dcrypto_luks_4b8cf138
dev-mapper-crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff.device                            
cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff.service                        
mount-cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff.service                  
system-cryptosd\x2dluks.slice                                                                             
system-mount\x2dcryptosd\x2dluks.slice                                                                    

LOAD   = Reflects whether the unit definition was properly loaded.
ACTIVE = The high-level unit activation state, i.e. generalization of SUB.
SUB    = The low-level unit activation state, values depend on unit type.

8 loaded units listed.
To show all installed unit files use 'systemctl list-unit-files'.
[root@XperiaXA2 nemo]# systemd-escape "$(blkid -c /dev/null -s UUID -o value /dev/mmcblk1)"  # Just to see the escaped UUID
4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff
[root@XperiaXA2 nemo]# systemctl start cryptosd-luks@"$(systemd-escape "crypto_luks_$(blkid -c /dev/null -s UUID -o value /dev/mmcblk1)")"
[root@XperiaXA2 nemo]# ls -l /dev/mapper/crypto*  # Is the decrypted device there?  If not, check per ...
brw-rw----    1 root     disk      252,   3 Mar 20 18:18 /dev/mapper/crypto_luks_4b8cf138-d701-41b3-a45f-729886a19bff
[root@XperiaXA2 nemo]# systemctl list-units -l -all "crypto*"
UNIT                                                                               LOAD   ACTIVE SUB    DE
cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff.service loaded active exited Op

LOAD   = Reflects whether the unit definition was properly loaded.
ACTIVE = The high-level unit activation state, i.e. generalization of SUB.
SUB    = The low-level unit activation state, values depend on unit type.

1 loaded units listed.
To show all installed unit files use 'systemctl list-unit-files'.
[root@XperiaXA2 nemo]# systemctl status -l -all "cryptosd-*"
● cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff.service - Open DM-Crypt LUKS 
   Loaded: loaded (/etc/systemd/system/cryptosd-luks@.service; static; vendor preset: enabled)
   Active: active (exited) since Sat 2021-03-20 18:18:04 CET; 13min ago
     Docs: https://github.com/Olf0/crypto-sdcard
  Process: 13694 ExecStart=/usr/sbin/cryptsetup --allow-discards -d /etc/crypto-sdcard/crypto_luks_4b8cf13
 Main PID: 13694 (code=exited, status=0/SUCCESS)

Warning: Journal has been rotated since unit was started. Log output is incomplete or unavailable.
[root@XperiaXA2 nemo]# systemctl start mount-cryptosd-luks@"$(systemd-escape "crypto_luks_$(blkid -c /dev/null -s UUID -o value /dev/mmcblk1)")"
[root@XperiaXA2 nemo]# mount | fgrep crypto  # Has it been successfully mounted?  If not, check per ...
/dev/mapper/crypto_luks_4b8cf138-d701-41b3-a45f-729886a19bff on /run/media/nemo/TarjetaSD type ext4 (rw,nosuid,nodev,relatime,data=ordered,uhelper=udisks2)
[root@XperiaXA2 nemo]# systemctl status -l -all "mount-cryptosd-*"
● mount-cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff.service - Mount LUKS en
   Loaded: loaded (/etc/systemd/system/mount-cryptosd-luks@.service; static; vendor preset: enabled)
   Active: active (exited) since Sat 2021-03-20 18:19:00 CET; 16min ago
     Docs: https://github.com/Olf0/crypto-sdcard
  Process: 13887 ExecStart=/usr/bin/udisksctl-user mount $UDISKS2_MOUNT_OPTIONS -b /dev/mapper/crypto_luks
 Main PID: 13887 (code=exited, status=0/SUCCESS)

Warning: Journal has been rotated since unit was started. Log output is incomplete or unavailable.
  1. I'm newbie with jounalctl, but I'll try to put here log in a readable way:
[root@XperiaXA2 nemo]# journalctl -r | grep -i crypto
mar 13 00:14:34 XperiaXA2 unknown: type=1131 audit(1615590874.234:366): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
mar 13 00:14:34 XperiaXA2 audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
mar 13 00:14:34 XperiaXA2 audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
mar 13 00:14:34 XperiaXA2 systemd[1]: Removed slice system-cryptosd\x2dluks.slice.
mar 13 00:14:34 XperiaXA2 unknown: type=1131 audit(1615590874.234:366): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
mar 13 00:14:34 XperiaXA2 unknown: type=1130 audit(1615590874.234:365): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
mar 13 00:14:34 XperiaXA2 unknown: type=1130 audit(1615590874.234:365): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
mar 13 00:14:34 XperiaXA2 unknown: type=1130 audit(1615590874.166:364): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=mount-cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'
mar 13 00:14:34 XperiaXA2 systemd[1]: Stopped Open DM-Crypt LUKS on SD-card crypto_luks_4b8cf138-d701-41b3-a45f-729886a19bff.
mar 13 00:14:34 XperiaXA2 systemd[1]: Removed slice system-mount\x2dcryptosd\x2dluks.slice.
mar 13 00:14:34 XperiaXA2 systemd[1]: Stopping Open DM-Crypt LUKS on SD-card crypto_luks_4b8cf138-d701-41b3-a45f-729886a19bff...
mar 13 00:14:34 XperiaXA2 systemd[1]: Stopped Mount LUKS encrypted SD-card (crypto_luks_4b8cf138-d701-41b3-a45f-729886a19bff) with udisks.
mar 13 00:14:34 XperiaXA2 audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=mount-cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'
mar 13 00:14:34 XperiaXA2 systemd[1]: mount-cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff.service: Failed with result 'exit-code'.
mar 13 00:14:34 XperiaXA2 unknown: type=1130 audit(1615590874.166:364): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=mount-cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'
mar 13 00:14:34 XperiaXA2 systemd[1]: mount-cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff.service: Control process exited, code=exited status=32
mar 13 00:14:34 XperiaXA2 umount[3201]: umount: /dev/crypto_luks_4b8cf138-d701-41b3-a45f-729886a19bff: no mount point specified.
mar 13 00:14:33 XperiaXA2 systemd[1]: Stopped Cryptography Setup for luks-dc86b46b-ed41-4c65-8885-fed83b881400.
mar 13 00:14:33 XperiaXA2 systemd[1]: Stopping Cryptography Setup for luks-dc86b46b-ed41-4c65-8885-fed83b881400...
mar 13 00:14:32 XperiaXA2 systemd[1]: Stopping Mount LUKS encrypted SD-card (crypto_luks_4b8cf138-d701-41b3-a45f-729886a19bff) with udisks...
mar 13 00:12:20 XperiaXA2 [RPM][32532]: install libsailfishcrypto-0.2.21-1.15.20.jolla.armv7hl: success
mar 13 00:12:20 XperiaXA2 [RPM][32532]: erase libsailfishcrypto-0.2.20-1.14.10.jolla.armv7hl: success
mar 13 00:12:19 XperiaXA2 [RPM][32532]: install libsailfishcrypto-0.2.21-1.15.20.jolla.armv7hl: success
mar 13 00:12:19 XperiaXA2 [RPM][32532]: erase libsailfishcrypto-0.2.20-1.14.10.jolla.armv7hl: success
mar 13 00:12:17 XperiaXA2 [RPM][32500]: install libsailfishcryptopluginapi-0.2.21-1.15.20.jolla.armv7hl: success
mar 13 00:12:16 XperiaXA2 [RPM][32500]: erase libsailfishcryptopluginapi-0.2.20-1.14.10.jolla.armv7hl: success
mar 13 00:12:16 XperiaXA2 [RPM][32500]: install libsailfishcryptopluginapi-0.2.21-1.15.20.jolla.armv7hl: success
mar 13 00:12:16 XperiaXA2 [RPM][32500]: erase libsailfishcryptopluginapi-0.2.20-1.14.10.jolla.armv7hl: success
mar 13 00:10:29 XperiaXA2 unknown: type=1130 audit(1615590532.717:275): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=mount-cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
mar 13 00:08:54 XperiaXA2 systemd-udevd[27742]: conflicting device node '/dev/mapper/crypto_luks_4b8cf138-d701-41b3-a45f-729886a19bff' found, link to '/dev/dm-2' will not be created
mar 13 00:08:52 XperiaXA2 audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=mount-cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
mar 13 00:08:52 XperiaXA2 systemd[1]: Started Mount LUKS encrypted SD-card (crypto_luks_4b8cf138-d701-41b3-a45f-729886a19bff) with udisks.
mar 13 00:08:52 XperiaXA2 unknown: type=1130 audit(1615590532.717:275): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=mount-cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
mar 13 00:08:51 XperiaXA2 systemd[1]: Starting Mount LUKS encrypted SD-card (crypto_luks_4b8cf138-d701-41b3-a45f-729886a19bff) with udisks...
mar 13 00:08:49 XperiaXA2 unknown: type=1130 audit(1615590529.319:271): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=mount-cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'
mar 13 00:08:49 XperiaXA2 systemd[1]: Stopped Mount LUKS encrypted SD-card (crypto_luks_4b8cf138-d701-41b3-a45f-729886a19bff) with udisks.
mar 13 00:08:49 XperiaXA2 audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=mount-cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'
mar 13 00:08:49 XperiaXA2 unknown: type=1130 audit(1615590529.319:271): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=mount-cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'
mar 13 00:08:49 XperiaXA2 systemd[1]: mount-cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff.service: Failed with result 'exit-code'.
mar 13 00:08:49 XperiaXA2 systemd[1]: mount-cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff.service: Control process exited, code=exited status=32
mar 13 00:08:48 XperiaXA2 systemd[1]: Stopping Mount LUKS encrypted SD-card (crypto_luks_4b8cf138-d701-41b3-a45f-729886a19bff) with udisks...
mar 13 00:06:51 XperiaXA2 [RPM][24722]: install libblockdev-crypto-2.19+git1-1.2.5.jolla.armv7hl: success
mar 13 00:06:51 XperiaXA2 [RPM][24722]: erase libblockdev-crypto-2.19+git1-1.3.4.jolla.armv7hl: success
mar 13 00:06:51 XperiaXA2 [RPM][24722]: install libblockdev-crypto-2.19+git1-1.2.5.jolla.armv7hl: success
mar 13 00:06:51 XperiaXA2 [RPM][24722]: erase libblockdev-crypto-2.19+git1-1.3.4.jolla.armv7hl: success

@Olf0
Copy link
Owner

Olf0 commented Mar 20, 2021

@fuchsmich, @carmenfdezb, @erikderzweite,

please download and update crypto-sdcard on your device with SFOS 4.0.1 to v1.5.0 (e.g., per devel-su curl -LO https://github.com/Olf0/crypto-sdcard/releases/download/1.5.0-1.sfos401regular/crypto-sdcard-1.5.0-1.sfos401regular.noarch.rpm && pkcon install-local crypto-sdcard-1.5.0-1.sfos401regular.noarch.rpm), reboot and check:

  • Quickly & easily, without analysis by you:
    devel-su Search="crypto"; journalctl -alru "*$Search*" | tee > journal-r_"$Search"_$(date +'%Ft%H-%M-%S').log.txt; echo; pwd dumps a journal extract (named including the search string and a timestamp) to the directory displayed.
  • But I would appreciate much, if you follow the simple steps for manual analysis:
    • For manually querying the journal, please use journalctl -ral while having less installed (per pkcon install less): Search with \<regex> (e.g., \crypto), then look with the arrow keys at adjacent lines and line endings. Plus, the <PgUp> and <PgDn> keys scroll half a screen height, and pushing the n key searches for the next hit of the last search term.
    • Please perform the steps for an initial analysis.
    • Also try manually starting crypto-sdcard's units, please.

Background:

  • The exact timing and ordering during a startup process of a Linux distribution with Systemd is highly variable.
    For SailfishOS specifically, it depends heavily on the SFOS release, if software is installed which alters the early or middle phase of the boot process (e.g., Defender), etc.
    Plus in general Systemd is free to reorder units as it likes, as long as it obeys the defined (temporal and functional, explicit and implicit) dependencies, and it does make use of this freedom: two consecutive boot-ups usually show slight variations of the order and timing in which units are started.
  • I may simply miss to notice things. By multiplying the eyes looking at this issue and the minds analysing it and thinking about it, we should reach to a working solution faster.
  • My primary device is still on SFOS 3.2.1, on which I usually test. In addition to that I test installing / updating of crypto-sdcard, followed by a reboot and a quick check on SFOS 4.0.1 and 2.2.1.

@Olf0
Copy link
Owner

Olf0 commented Mar 20, 2021

Hi @carmenfdezb,

Hi @olf, [...] Let's see if we can know what go wrong. [...]

This is looking good!
So everything is working fine, when you manually start the unlocking and mounting units, right?
Then the aforementioned v1.5.0 may work better for unlocking and mounting automatically while booting.

P.S.: I hope that Jolla's LUKS-mounting mechanisms were not altered with SFOS 4 and now subtly interfere.

@carmenfdezb
Copy link

carmenfdezb commented Mar 20, 2021

@fuchsmich, @carmenfdezb, @erikderzweite,

please download and update crypto-sdcard on your device with SFOS 4.0.1 to v1.5.0 (e.g., per devel-su curl -LO https://github.com/Olf0/crypto-sdcard/releases/download/1.5.0-1.sfos401regular/crypto-sdcard-1.5.0-1.sfos401regular.noarch.rpm && pkcon install-local crypto-sdcard-1.5.0-1.sfos401regular.noarch.rpm), reboot and check:

Done :)

* Quickly & easily, without analysis by you:
  `devel-su Search="crypto"; journalctl -alru "*$Search*" | tee > journal-r_"$Search"_$(date +'%Ft%H-%M-%S').log.txt; echo; pwd` dumps a journal extract (named including the search string and a timestamp) to the directory displayed.
-- Logs begin at Sat 2021-03-13 00:06:47 CET, end at Sat 2021-03-20 21:09:40 CET. --
mar 13 00:14:34 XperiaXA2 systemd[1]: Removed slice system-cryptosd\x2dluks.slice.
mar 13 00:14:34 XperiaXA2 systemd[1]: Stopped Open DM-Crypt LUKS on SD-card crypto_luks_4b8cf138-d701-41b3-a45f-729886a19bff.
mar 13 00:14:34 XperiaXA2 systemd[1]: Removed slice system-mount\x2dcryptosd\x2dluks.slice.
mar 13 00:14:34 XperiaXA2 systemd[1]: Stopping Open DM-Crypt LUKS on SD-card crypto_luks_4b8cf138-d701-41b3-a45f-729886a19bff...
mar 13 00:14:34 XperiaXA2 systemd[1]: Stopped Mount LUKS encrypted SD-card (crypto_luks_4b8cf138-d701-41b3-a45f-729886a19bff) with udisks.
mar 13 00:14:34 XperiaXA2 systemd[1]: mount-cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff.service: Failed with result 'exit-code'.
mar 13 00:14:34 XperiaXA2 systemd[1]: mount-cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff.service: Control process exited, code=exited status=32
mar 13 00:14:34 XperiaXA2 umount[3201]: umount: /dev/crypto_luks_4b8cf138-d701-41b3-a45f-729886a19bff: no mount point specified.
mar 13 00:14:34 XperiaXA2 udisksctl[3021]: Unmounted /dev/dm-2.
mar 13 00:14:32 XperiaXA2 systemd[1]: Stopping Mount LUKS encrypted SD-card (crypto_luks_4b8cf138-d701-41b3-a45f-729886a19bff) with udisks...
mar 13 00:08:52 XperiaXA2 systemd[1]: Started Mount LUKS encrypted SD-card (crypto_luks_4b8cf138-d701-41b3-a45f-729886a19bff) with udisks.
mar 13 00:08:52 XperiaXA2 udisksctl-user[27691]: Mounted /dev/dm-2 at /run/media/nemo/TarjetaSD.
mar 13 00:08:52 XperiaXA2 su[27702]: pam_systemd(su-l:session): Using 600s D-Bus method call timeout
mar 13 00:08:51 XperiaXA2 su[27702]: (to nemo) root on none
mar 13 00:08:51 XperiaXA2 systemd[1]: Starting Mount LUKS encrypted SD-card (crypto_luks_4b8cf138-d701-41b3-a45f-729886a19bff) with udisks...
mar 13 00:08:49 XperiaXA2 systemd[1]: Stopped Mount LUKS encrypted SD-card (crypto_luks_4b8cf138-d701-41b3-a45f-729886a19bff) with udisks.
mar 13 00:08:49 XperiaXA2 systemd[1]: mount-cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff.service: Failed with result 'exit-code'.
mar 13 00:08:49 XperiaXA2 systemd[1]: mount-cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff.service: Control process exited, code=exited status=32
mar 13 00:08:49 XperiaXA2 udisksctl[27544]: Unmounted /dev/dm-2.
mar 13 00:08:48 XperiaXA2 systemd[1]: Stopping Mount LUKS encrypted SD-card (crypto_luks_4b8cf138-d701-41b3-a45f-729886a19bff) with udisks...
* But I would appreciate much, if you follow the simple steps for manual analysis:
  
  * For manually querying the journal, please use `journalctl -ral` while having `less` installed (per `pkcon install less`): Search with `\<regex>` (e.g., `\crypto`), then look with the arrow keys at adjacent lines and line endings.  Plus, the <PgUp> and <PgDn> keys scroll half a screen height, and pushing the **n** key searches for the next hit of the last search term.
mar 20 22:31:03 XperiaXA2 systemd[1]: Started Mount crypto_luks_4b8cf138-d701-41b3-a45f-729886a19bff per u
mar 20 22:31:03 XperiaXA2 audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=mou
mar 20 22:31:03 XperiaXA2 unknown: type=1130 audit(1616275863.682:217): pid=1 uid=0 auid=4294967295 ses=42
mar 20 22:31:03 XperiaXA2 unknown: type=1130 audit(1616275817.917:216): pid=1 uid=0 auid=4294967295 ses=42
mar 20 22:31:03 XperiaXA2 su[19262]: pam_unix(su-l:session): session closed for user nemo
mar 20 22:31:03 XperiaXA2 systemd[4916]: Starting Tracker metadata database store and lookup manager...
mar 20 22:31:03 XperiaXA2 dbus-daemon[4929]: dbus-daemon[4929]: [session uid=100000 pid=4929] Activating v
mar 20 22:31:03 XperiaXA2 udisksctl-user[19254]: Mounted /dev/dm-3 at /run/media/nemo/TarjetaSD.
mar 20 22:31:03 XperiaXA2 udisksd[3049]: Mounted /dev/dm-3 at /run/media/nemo/TarjetaSD on behalf of uid 1
mar 20 22:31:03 XperiaXA2 kernel: EXT4-fs (dm-3): mounted filesystem with ordered data mode. Opts: (null)
mar 20 22:31:02 XperiaXA2 su[19262]: pam_unix(su-l:session): session opened for user nemo by (uid=0)
mar 20 22:31:02 XperiaXA2 systemd[1]: Started Session c7 of user nemo.
mar 20 22:31:02 XperiaXA2 su[19262]: pam_systemd(su-l:session): Using 600s D-Bus method call timeout
mar 20 22:31:02 XperiaXA2 su[19262]: (to nemo) root on none
mar 20 22:31:02 XperiaXA2 kernel: PM: suspend exit 2021-03-20 21:31:02.826234521 UTC
mar 20 22:31:02 XperiaXA2 kernel: Restarting tasks ... done.
mar 20 22:31:02 XperiaXA2 kernel: PM: resume of devices complete after 3.068 msecs
mar 20 22:31:02 XperiaXA2 kernel: R0: [kworker/u16:6][105564910338] [21:31:02.788323]  wlan: [454:I :HDD] 
mar 20 22:31:02 XperiaXA2 kernel: R0: [kworker/u16:6][105564908564] [21:31:02.788231]  wlan: [454:I :HDD] 
mar 20 22:31:02 XperiaXA2 kernel: R0: [kworker/u16:6][105564907817] [21:31:02.788192]  wlan: [454:I :HDD] 
mar 20 22:31:02 XperiaXA2 kernel: PM: Some devices failed to suspend, or early wake event detected
mar 20 22:31:02 XperiaXA2 kernel: PM: Device alarmtimer failed to suspend: error -16
mar 20 22:31:02 XperiaXA2 kernel: dpm_run_callback(): platform_pm_suspend+0x0/0x6c returns -16
mar 20 22:31:02 XperiaXA2 kernel: R0: [kworker/u16:8][105564587154] [21:31:02.771491]  wlan: [4205:I :HDD]
mar 20 22:31:02 XperiaXA2 kernel: R0: [kworker/u16:8][105564585929] [21:31:02.771427]  wlan: [4205:I :HDD]
mar 20 22:31:02 XperiaXA2 kernel: R0: [kworker/u16:8][105564585723] [21:31:02.771416]  wlan: [4205:I :HDD]
mar 20 22:31:02 XperiaXA2 kernel: Suspending console(s) (use no_console_suspend to debug)
mar 20 22:31:02 XperiaXA2 kernel: Freezing remaining freezable tasks ... (elapsed 0.003 seconds) done.
mar 20 22:31:02 XperiaXA2 kernel: Freezing user space processes ... (elapsed 0.008 seconds) done.
mar 20 22:31:02 XperiaXA2 kernel: PM: Syncing filesystems ... done.
mar 20 22:31:02 XperiaXA2 kernel: PM: suspend entry 2021-03-20 21:31:02.687901506 UTC
mar 20 22:31:02 XperiaXA2 systemd[1]: Starting Mount crypto_luks_4b8cf138-d701-41b3-a45f-729886a19bff per 
mar 20 22:31:02 XperiaXA2 kernel: PM: suspend exit 2021-03-20 21:31:02.659015164 UTC
mar 20 22:31:02 XperiaXA2 kernel: Restarting tasks ... done.
mar 20 22:31:02 XperiaXA2 kernel: PM: resume of devices complete after 5.701 msecs
  * Please perform the steps for [an initial analysis](https://github.com/Olf0/crypto-sdcard/issues/115#issuecomment-780786960).
[nemo@XperiaXA2 ~]$ ls -l /dev/crypto*
lrwxrwxrwx    1 root     root             7 Mar 20 20:59 /dev/crypto_luks_4b8cf138-d701-41b3-a45f-729886a19bff -> mmcblk1
[nemo@XperiaXA2 ~]$ systemctl list-units -l "*crypto*"         
UNIT                          LOAD   ACTIVE SUB    DESCRIPTION                  
system-cryptosd\x2dluks.slice loaded active active system-cryptosd\x2dluks.slice

LOAD   = Reflects whether the unit definition was properly loaded.
ACTIVE = The high-level unit activation state, i.e. generalization of SUB.
SUB    = The low-level unit activation state, values depend on unit type.

1 loaded units listed. Pass --all to see loaded but inactive units, too.
To show all installed unit files use 'systemctl list-unit-files'.
[nemo@XperiaXA2 ~]$ systemctl status -l "*crypto*"
● system-cryptosd\x2dluks.slice
   Loaded: loaded
   Active: active since Sat 2021-03-20 20:59:42 CET; 47min ago
   Memory: 0B
   CGroup: /system.slice/system-cryptosd\x2dluks.slice
[nemo@XperiaXA2 ~]$ ls -l /dev/mapper/crypto*
ls: /dev/mapper/crypto*: No such file or directory
[nemo@XperiaXA2 ~]$ mount | fgrep crypto
  * Also try [manually starting _crypto-sdcard's_ units](https://github.com/Olf0/crypto-sdcard/issues/115#issuecomment-792967656), please.
[root@XperiaXA2 nemo]# systemctl start cryptosd-luks@"$(systemd-escape "crypto_luks_$(blkid -c /dev/null -s UUID -o value /dev/mmcblk1)")"  
[root@XperiaXA2 nemo]# systemctl start mount-cryptosd-luks@"$(systemd-escape "crypto_luks_$(blkid -c /dev/null -s UUID -o value /dev/mmcblk1)")"  
[root@XperiaXA2 nemo]# systemctl list-units -l "*crypto*"  # Just to see what is already there (without --all)
UNIT                                                                                     LOAD   ACTIVE SUB
cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff.service       loaded active exi
mount-cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff.service loaded active exi
system-cryptosd\x2dluks.slice                                                            loaded active act
system-mount\x2dcryptosd\x2dluks.slice                                                   loaded active act

LOAD   = Reflects whether the unit definition was properly loaded.
ACTIVE = The high-level unit activation state, i.e. generalization of SUB.
SUB    = The low-level unit activation state, values depend on unit type.

4 loaded units listed. Pass --all to see loaded but inactive units, too.
To show all installed unit files use 'systemctl list-unit-files'.

[root@XperiaXA2 nemo]# systemctl list-units -l -all "*crypto*"  # Just to compare what already failed due to the broken startup
UNIT                                                                                                      
dev-crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff.device                                   
dev-disk-by\x2did-dm\x2dname\x2dcrypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff.device       
dev-disk-by\x2did-dm\x2duuid\x2dCRYPT\x2dLUKS1\x2d4b8cf138d70141b3a45f729886a19bff\x2dcrypto_luks_4b8cf138
dev-mapper-crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff.device                            
cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff.service                        
mount-cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff.service                  
system-cryptosd\x2dluks.slice                                                                             
system-mount\x2dcryptosd\x2dluks.slice                                                                    

LOAD   = Reflects whether the unit definition was properly loaded.
ACTIVE = The high-level unit activation state, i.e. generalization of SUB.
SUB    = The low-level unit activation state, values depend on unit type.

8 loaded units listed.
To show all installed unit files use 'systemctl list-unit-files'.
lines 1-16/16 (END) 
[root@XperiaXA2 nemo]# systemd-escape "$(blkid -c /dev/null -s UUID -o value /dev/mmcblk1)"  # Just to see the escaped UUID  
4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff
[root@XperiaXA2 nemo]# systemctl start cryptosd-luks@"$(systemd-escape "crypto_luks_$(blkid -c /dev/null -s UUID -o value /dev/mmcblk1)")"  
[root@XperiaXA2 nemo]# ls -l /dev/mapper/crypto*  # Is the decrypted device there?  If not, check per ...
brw-rw----    1 root     disk      252,   3 Mar 20 22:30 /dev/mapper/crypto_luks_4b8cf138-d701-41b3-a45f-729886a19bff
[root@XperiaXA2 nemo]# systemctl list-units -l -all "crypto*"
UNIT                                                                               LOAD   ACTIVE SUB    DE
cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff.service loaded active exited Op

LOAD   = Reflects whether the unit definition was properly loaded.
ACTIVE = The high-level unit activation state, i.e. generalization of SUB.
SUB    = The low-level unit activation state, values depend on unit type.

1 loaded units listed.
To show all installed unit files use 'systemctl list-unit-files'.

[root@XperiaXA2 nemo]# systemctl status -l -all "cryptosd-*"
● cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff.service - Open crypto_luks_4b
   Loaded: loaded (/etc/systemd/system/cryptosd-luks@.service; static; vendor preset: enabled)
   Active: active (exited) since Sat 2021-03-20 22:30:17 CET; 27min ago
     Docs: https://github.com/Olf0/crypto-sdcard
  Process: 19010 ExecStart=/bin/sleep 1 (code=exited, status=0/SUCCESS)
  Process: 18991 ExecStart=/usr/sbin/cryptsetup --allow-discards -d /etc/crypto-sdcard/crypto_luks_4b8cf13
 Main PID: 19010 (code=exited, status=0/SUCCESS)

Warning: Journal has been rotated since unit was started. Log output is incomplete or unavailable.

[root@XperiaXA2 nemo]# systemctl start mount-cryptosd-luks@"$(systemd-escape "crypto_luks_$(blkid -c /dev/null -s UUID -o value /dev/mmcblk1)")"
[root@XperiaXA2 nemo]# mount | fgrep crypto  # Has it been successfully mounted?  If not, check per ...
/dev/mapper/crypto_luks_4b8cf138-d701-41b3-a45f-729886a19bff on /run/media/nemo/TarjetaSD type ext4 (rw,nosuid,nodev,relatime,data=ordered,uhelper=udisks2)
[root@XperiaXA2 nemo]# systemctl list-units -l -all "*crypto*"
UNIT                                                                                                      
dev-crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff.device                                   
dev-disk-by\x2did-dm\x2dname\x2dcrypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff.device       
dev-disk-by\x2did-dm\x2duuid\x2dCRYPT\x2dLUKS1\x2d4b8cf138d70141b3a45f729886a19bff\x2dcrypto_luks_4b8cf138
dev-mapper-crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff.device                            
cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff.service                        
mount-cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff.service                  
system-cryptosd\x2dluks.slice                                                                             
system-mount\x2dcryptosd\x2dluks.slice                                                                    

LOAD   = Reflects whether the unit definition was properly loaded.
ACTIVE = The high-level unit activation state, i.e. generalization of SUB.
SUB    = The low-level unit activation state, values depend on unit type.

8 loaded units listed.
To show all installed unit files use 'systemctl list-unit-files'.
lines 1-16/16 (END) 
[root@XperiaXA2 nemo]# systemctl status -l -all "mount-cryptosd-*"
● mount-cryptosd-luks@crypto_luks_4b8cf138\x2dd701\x2d41b3\x2da45f\x2d729886a19bff.service - Mount crypto_
   Loaded: loaded (/etc/systemd/system/mount-cryptosd-luks@.service; static; vendor preset: enabled)
   Active: active (exited) since Sat 2021-03-20 22:31:03 CET; 28min ago
     Docs: https://github.com/Olf0/crypto-sdcard
  Process: 19254 ExecStart=/usr/bin/udisksctl-user mount $UDISKS2_MOUNT_OPTIONS -b /dev/mapper/crypto_luks
 Main PID: 19254 (code=exited, status=0/SUCCESS)

Warning: Journal has been rotated since unit was started. Log output is incomplete or unavailable.

@carmenfdezb
Copy link

carmenfdezb commented Mar 20, 2021

So everything is working fine, when you manually start the unlocking and mounting units, right?

Yes, no problem with unlocking and mounting sdcard manually, but it doesn't do automatically

@Olf0
Copy link
Owner

Olf0 commented Mar 28, 2021

@carmenfdezb, thank you very much for your feedback. Sorry, it has been a busy week, I just managed to take a closer look at it right now.

Side note: You do not have to use my command suggestions 1:1, if you have ideas to vary them sensibly. Though if they are helpful in the provided form, do use them as provided (i.e., "1:1").

  1. The output of

    Quickly & easily, without analysis by you:
    devel-su Search="crypto"; journalctl -alru "*$Search*" | tee > journal-r_"$Search"_$(date +'%Ft%H-%M-%S').log.txt; echo; pwd dumps a journal extract (named including the search string and a timestamp) to the directory displayed.

    still looks strange to me:
    The header states "-- Logs begin at Sat 2021-03-13 00:06:47 CET, end at Sat 2021-03-20 21:09:40 CET. --", but journalctl seems to only find two blocks of events at "mar 13 00:08" (looks like reboot, or manually restarting the units) and "mar 13 00:14" (looks like a shutdown). I assume you have rebooted or shutdown & started your device more often than just at these two occasions in the week between Sat 2021-03-13 00:06 and Sat 2021-03-20 21:09. Plus the next log shows exactly such events, AFAICS.
    Ideas:

  • Please check if grepping for "crypto" yields the same than looking for all units, which contain "crypto" (i.e., substituting journalctl -alru "*$Search*" by journalctl -alrg "$Search"). And devel-su's behaviour with long command lines is not well documented; just become root with it, before issuing these command lines:
    Search="crypto"; journalctl -alru "*$Search*" | tee > journal-r_"$Search"_$(date +'%Ft%H-%M-%S').log.txt versus
    Search="crypto"; journalctl -alrg "$Search" | tee > journal-r_"$Search"_$(date +'%Ft%H-%M-%S').log.txt
  • Please check, if there is more in the output file journal-r_*.log.txt than the single screen page with the two blocks of events at "mar 13 00:08" and "mar 13 00:14", e.g. per less journal-r_*.log.txt. If so, uploading that file may be easier then cutting and pasting its content.
  • Maybe your journals became mixed up (happened to me). If you have not set your journal to persistent (i.e, it is still on volatile), a shutdown followed by booting your device (but not necessarily a reboot) should cleanse old journals. If not, either delete old journals manually, or set volatile and shutdown. For details see the third bullet point here.
  1. The output of

    For manually querying the journal, please use journalctl -ral while having less installed (per pkcon install less): Search with \<regex> (e.g., \crypto), then look with the arrow keys at adjacent lines and line endings. Plus, the and keys scroll half a screen height, and pushing the n key searches for the next hit of the last search term.

    shows that went well and displays recent journal entries (in contrast to what we saw per step 1, this time), proving that current entries containing "*crypto*" are available in some journal.
    But it shows just a brief moment (one and a half seconds: mar 20 22:31:02 to 22:31:03) when waking up from a suspend.
    Originally I was about to write "Oh no, that was a misunderstanding: Manually looking at the journal (specifically at the context of what should have been found by step 1) is just for you!" (especially as the lines are unavoidably cut off, when cutting & pasting the terminal output; i.e., one cannot see the end of the lines by scrolling to the right, anymore).
    But even that brief moment has some interesting aspects, especially the "22:31:03 udisksctl-user[19254]: Mounted /dev/dm-3 at /run/media/nemo/TarjetaSD." and preceding lines (i.e., below) since the "22:31:02 XperiaXA2 kernel: PM: suspend exit 2021-03-20 21:31:02.826234521 UTC": This is the construct Jolla introduced and uses for mounting SD-cards since SFOS 3.2.1 and which I adopted for crypto-sdcard and mount-sdcard. But Jolla did not touch unlocked, but unmounted partitions before, /dev/dm-3 in your case. But if you have not patched crypto-sdcard, it does not mount "at /run/media/nemo/TargetSD", but at "/run/media/nemo/<UUID>". Assuming you have selected the Spanish localisation in the Settings (at the GUI), it looks like Jolla now automatically mounts unlocked, but unmounted partitions. Can you please take a quick look at the content of /run/media/nemo/TarjetaSD/?
    But OTOH the topmost (i.e., first) line looks, as if mount-cryptosd-luks@*.service did this mounting!?! It would have been really interesting to see the remainder of the second line (which may reveal that), but never mind: We should achieve that by a working implementation of step 1, next time.

  2. The third output was unfortunately performed as user nemo (as the command line prompt is [nemo@XperiaXA2 ~]$).

    Please perform the steps for an initial analysis.

    While it clearly shows that the udev rule for starting the cryptosd-luks@*.service unit was executed (because the symbolic link /dev/crypto_luks_* -> mmcblk1 exists), it is unclear (by looking at the output of the following command lines), if cryptosd_luks@*.service was not started or if nemo is just not allowed to obtain this information.
    The same goes for ls -l /dev/mapper/crypto*: It may really not be there, but as nemo is definitely not allowed to look at it, hence it might be just that (but it is there).
    Please perform these (and all other analysis steps, unless explicitly noted) as root user.

  3. Thanks, this nicely shows, that everything is working well, when manually starting crypto-sdcard's units.
    This also shows you how the output in step 3 should look like, if mounting on boot-up works. It sure will not, because obviously something is not working as intended, but either you (by quickly looking over it) or me (after you pasted / uploaded command line output here) should be able to detect differences between the output of steps 3 and 4 (because one fails and the other one succeeds).

It also makes sense to return to (i.e., rerun) steps 1 and / or 2 after starting crypto-sdcard manually (and successfully), because sometimes the journal does reveal more than the output of steps 3 and 4, especially by looking at context per step 2. Again, we are searching for differences between failing and successful starts of 'crypto-sdcard's* unlocking and mounting units.
But there is no need to stubbornly upload all that command line / journal output here, unless you suspect something to be relevant (if in doubt, do paste / upload it, but that is tedious for you).

@Olf0
Copy link
Owner

Olf0 commented Mar 29, 2021

@carmenfdezb, this (older) comment at git.sailfishos.org/mer-core/udisks2/ made me think of a very basic "check and balance" (because it hints that udev may have issues with auto-detecting LUKS headers directly on mmcblk1, i.e. not on a partition (e.g., mmcblk1p1)):

Do I assume correctly, that crypto-sdcard was working fine on your device, before you upgraded to SFOS 4 (as for @fuchsmich)?
I.e., that you did not perform the initial installation and configuration of crypto-sdcard on SFOS 4, and / or never had it working?

@carmenfdezb
Copy link

carmenfdezb commented Mar 31, 2021

Do I assume correctly, that crypto-sdcard was working fine on your device, before you upgraded to SFOS 4 (as for @fuchsmich)?
I.e., that you did not perform the initial installation and configuration of crypto-sdcard on SFOS 4, and / or never had it working?

Exactly, it worked fine before I upgraded to SFOS4 and I did't perform the initial installation and configuration of crypto-sdcard on SFOS 4

@Olf0
Copy link
Owner

Olf0 commented Apr 5, 2021

Thank you for your feedback, @carmenfdezb.
This was supposedly the last element of the initial "search for and try things"-phase ("phase 1"), during which I at least found the original issue (reported here along with an initial analysis by @fuchsmich), caused by the switch from Systemd v225 to v238 per SailfishOS 4. Well, in a way this was "easy", because this issue has been documented multiple times (due to SFOS usually lagging a bit behind with the software versions it deploys, compared to other Linux distros), even thought I have not found a solution for that documented elsewhere.

The issue we are hitting now (which has become visible due to eliminating the first issue), seems to be SFOS 4 specific (-> "phase 3", below).

After I while I also started to structurally and generally (i.e., not SFOS 4 specific) enhance crypto-sdcard ("phase 2"), concurrently to "phase 1" because I was gaining a much better understanding by re-reading various Systemd, udev and udisks documentation, guides and examples, especially how these three components interact. This result(ed|s) in the crypto-sdcard releases v1.4.0 to v1.6.0.
These structural enhancements may or may not help crypto-sdcard to work on SFOS 4 (up to now: rather the latter).
Stemming from these insights, I still have two points left over, but these are feature enhancements, not structural enhancements: To auto-detect devices capable of discards (i.e., the "trim" operation) and to allow users to eject media, if the device (e.g., an optical drive attached via USB) is capable of that.

So I started "phase 3": Thoroughly analysing what is going on by

  • retracing the changes in SFOS 4 proper and the software it deploys to its sources.
  • analysing and experimenting (by altering it) with the behaviour of crypto-sdcard on SFOS 4.

For that I prepared an old USB "thumb drive" with an unencrypted, a LUKS-encrypted and a "plain"-encrypted partition, with which I can test crypto-sdcard on my XperiaXA2+@SFOS401 and XperiaX@SFOS321 (the USB port of the Jolla1 does not support USB-OTG) much more easily: Plugging / unplugging should have the same effect as rebooting, and both can be tested with it.
So far I can tell that I can reproduce (at least) two more issues, one is specific to SFOS 4 and the other is likely specific to USB devices (i.e., SD-cards are not affected). What exactly causes them still needs to be analysed, plus fixes for that designed and implemented, tested and ultimately released.

If any SFOS 4 specific progress is made, I will either denote that here or release a new version, which states that in its release notes.
Still, I am glad if anyone else tests the upcoming release(s) before that happens and thankful for any feedback, because "I may simply miss to notice things. By multiplying the eyes looking at this issue and the minds analysing it and thinking about it, we should reach to a working solution faster.".

As a reminder, two easy routes allow you to use encrypted (partitions on) SD-cards / USB mass storage with SFOS 4 now, without uninstalling crypto-sdcard:

  • (Temporarily) populating another "key slot" with a numeric passphrase.
    This shall allow to unlock and mount the "Cryptsetup containers" on SD-cards / USB storage per SailfishOS' GUI.
  • Start crypto-sdcard manually. Since v1.5.x it should be sufficient to start the mounting unit only, it triggers the unlocking unit and wait with its mounting until that is finished, e.g.
    devel-su systemctl start "mount-cryptosd-luks@$(systemd-escape "$(blkid -s UUID -o value /dev/mmcblk1p2)")"
    Mind that the prefix crypto_luks_ / crypto_plain_ was eliminated from the instance string per v1.5.1 (and the symlink /dev/crypto_* is not created anymore, plus the DM_NAME and /dev/mapper/-symlink also lost the crypto_*-prefix), see its release notes.

@Olf0
Copy link
Owner

Olf0 commented May 23, 2021

Sorry folks, I became so frustrated with this in early April (due to the lack of progress, after fixing two blocker bugs for SFOS4), that I decided to first refactor and vastly enhance the Udev rule file and write the Polkit rule file anew. As a consequence crypto-sdcard was initially completely broken after that, which did not alleviate my mood at all.
So after some testing and minor bug fixes I let it be for a few weeks; only to discover yesterday that I was a single small bug away from having it working properly, again (this was on my XperiaX@SFOS3.2.1).

So I prepared a release v1.7.2 for all supported SFOS releases, this is the one for SFOS 4.
Please test it, after installing it per the usual procedure (starting as a regular user, e.g. nemo):

cd /tmp
curl -LO https://github.com/Olf0/crypto-sdcard/releases/download/1.7.2-1.sfos401regular/crypto-sdcard-1.7.2-1.sfos401regular.noarch.rpm
devel-su pkcon install-local crypto-sdcard-1.7.2-1.sfos401regular.noarch.rpm

@Olf0
Copy link
Owner

Olf0 commented May 23, 2021

Meanwhile I released crypto-sdcard 1.7.2 at Openrepos.net, so you can install it from there via Storeman.
Still I would really appreciate any feedback about your experience with it on SFOS 4.x.y!

Please report success or the lack of it here, including your phone model, SailfishOS 4.x.y release, if "LUKS"- or "plain"-encrypted, which local device (name only) was used, and what kind of mass storage this physically is.
My report is:
Successfully hot-plugging on XperiaXA2Plus@SFOS4.0.1, "plain"@sda3, USB-FLASH-Stick (Kingston DataTraveller G4, "32 GB").

@kivoli
Copy link

kivoli commented May 30, 2021

  • Model: Sony Xperia 10 Plus Dual Sim
  • Sailfish version: Sailfish OS 4.1.0.24 (Kvarken)
  • crypto-sdcard version: crypto-sdcard-1.7.2-1.sfos401regular.noarch.rpm
  • Type: LUKS
  • Device: /dev/mmcblk1
  • Device type: SD card
  • Status: Unlock on boot fails

You may notice that the device is used directly without a partition table.

But I’m not really sure if my problem is the same or even related to what is discussed in this thread. At the same time I’m not convinced it’s a entirely seperate thing. If you think so please let me know and I will open another issue or go looking for a solution upstream (you’ll understand in a second).

Even with earlier versions of crypto-sdcard I could manually start it - after I fixed a failed dependency after every boot:

# systemctl start cryptosd-luks@"$(systemd-escape "crypto_luks_$(blkid -c /dev/null -s UUID -o value /dev/mmcblk1)")"
A dependency job for cryptosd-luks@crypto_luks_[…].service failed. See 'journalctl -xe' for details.
# systemctl --failed
  UNIT          LOAD   ACTIVE SUB    DESCRIPTION                                                                                                                                                                                             
● dev-mtp.mount loaded failed failed FFS mount  
# systemctl status dev-mtp.mount
● dev-mtp.mount - FFS mount
   Loaded: loaded (/usr/lib/systemd/system/dev-mtp.mount; static; vendor preset: enabled)
   Active: failed (Result: exit-code) since Sun 2021-05-30 16:11:30 CEST; 52s ago
    Where: /dev/mtp
     What: mtp
     Docs: man:hier(7)
  Process: 685 ExecMount=/bin/mount mtp /dev/mtp -t functionfs -o mode=0770,gid=1024 (code=exited, status=32)

Mai 30 16:11:30 jolla mount[685]: mount: /dev/mtp: unknown filesystem type 'functionfs'.
Warning: Journal has been rotated since unit was started. Log output is incomplete or unavailable.

Fixing this is easy:

systemctl restart dev-mtp.mount
systemctl restart cryptosd-luks@"$(systemd-escape "$(blkid -c /dev/null -s UUID -o value /dev/mmcblk1)")"
systemctl restart mount-cryptosd-luks@"$(systemd-escape "$(blkid -c /dev/null -s UUID -o value /dev/mmcblk1)")"

I don’t quite know how to fix the "unknown filesystem type 'functionfs'" since it’s compiled into the kernel and my knowledge on how/if AOSP and/or Sailfish use kernel modules is non-existant.

So I’m very sorry if this is an unrelated issue.

@Olf0
Copy link
Owner

Olf0 commented May 30, 2021

@kivoli, thank you very much for this report!
@pcfe addressed the same case (encrypted mmcblk1 on an Xperia10II@SFSOS4.1.0 not being unlocked when booting by crypto-sdcard) via a different channel, but without a solution in sight. It is great that you seem to have identified the culprit.

I will try to analyse, if this is part of the original issue (which already turned out to be comprised of multiple, compounded / layered issues) or not. I cannot tell at the moment and my gut feeling tells me "Yes" and "No" at the same time, just as yours seems to.

If I understand correctly, you have not tested an encrypted partition (instead of the whole device / SD-card) with crypto-sdcard 1.7.2, yet?

@kivoli
Copy link

kivoli commented May 30, 2021

If I understand correctly, you have not tested an encrypted partition (instead of the whole device / SD-card) with crypto-sdcard 1.7.2, yet?

No. Unless I somehow find a fix for the “functionfs” error message or an indication that these two (error and partitioning) are somehow related (seems very unlikely) I do not see the point of doing that.

@pcfe
Copy link

pcfe commented Jun 2, 2021

test notes:

sadly is is also not auto-unlocking nor auto-mounting when I make a luks v1 partition on the SD card

[root@Xperia10II-DualSIM ~]# rpm -q crypto-sdcard
crypto-sdcard-1.7.2-1.sfos401regular.noarch
[root@Xperia10II-DualSIM ~]# lsblk /dev/mmcblk1
NAME        MAJ:MIN RM  SIZE RO TYPE MOUNTPOINT
mmcblk1     179:64   0 29.7G  0 disk 
└─mmcblk1p1 179:65   0 29.7G  0 part 
[root@Xperia10II-DualSIM ~]# cryptsetup luksDump /dev/mmcblk1p1 | head -n 6
LUKS header information for /dev/mmcblk1p1

Version:       	1
Cipher name:   	aes
Cipher mode:   	xts-plain64
Hash spec:     	sha256

But I can unlock it just fine with cryptsetup -v --allow-discards -d /etc/crypto-sdcard/crypto_luks_$(blkid -c /dev/null -s UUID -o value /dev/mmcblk1p1).key luksOpen /dev/mmcblk1p1 crypto-sd

side note: dev-mtp.mount failing might be a red herring because already before installing crypto-sdcard I got these failed units on boot

[root@Xperia10II-DualSIM ~]# systemctl --failed
  UNIT                   LOAD   ACTIVE SUB    DESCRIPTION                             
● dev-mtp.mount          loaded failed failed FFS mount                               
● product.mount          loaded failed failed Droid mount for /product                
● system.mount           loaded failed failed Droid mount for /system                 
● lxc@multi-user.service loaded failed failed LXC Container: multi-user               
● quota@home.service     loaded failed failed Enable quota and run quotacheck for home
● user@0.service         loaded failed failed User Manager for UID 0                  

LOAD   = Reflects whether the unit definition was properly loaded.
ACTIVE = The high-level unit activation state, i.e. generalization of SUB.
SUB    = The low-level unit activation state, values depend on unit type.

6 loaded units listed. Pass --all to see loaded but inactive units, too.
To show all installed unit files use 'systemctl list-unit-files'.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
an sfos update broke it An update of SFOS broke this enhancement New feature or request help wanted Extra attention is needed open question(s) Further information is requested
Projects
None yet
Development

No branches or pull requests

7 participants