Το νήμα του Gentoo, version 1.0

[GoofyX]

έχεις ήχο με το bin? εγώ δεν έχω μόνο με compile

Ναι, κανονικά.

[Gentoo]

έχεις ήχο με το bin? εγώ δεν έχω μόνο με compile

Έχεις απενεργοποιήσει το pulseaudio μήπως;

[pap]

Θα το κοιταξω, ευχαριστω παιδια.

[GoofyX]

Παιδιά, έχω το θέμα που περιγράφω στο forum του Gentoo: https://forums.gentoo.org/viewtopic-t-1103832.html

Εν ολίγοις, μέχρι πρόσφατα όλα οκ. Έχω το /home encrypted πάνω από ένα RAID1 volume και στην εκκίνηση το cryptsetup μου ζητάει το password για να φτιάξει το encrypted volume κάτω από το /dev/md και στη συνέχει να κάνει mount το /home. Αυτό εδώ και χρόνια δούλευε μια χαρά. Έχει μερικές μέρες που στην εκκίνηση χτυπάει το systemd-cryptsetup και με πετάει σε maintenance mode. Από εκεί το ξεκινάω όμως κανονικά, μου ζητάει το pass και δημιουργεί το volume. Μετά μπορώ να συνεχίσω κανονικά χωρίς θέμα (να μπω σε γραφικό, να γίνει mount το /home, κτλ.).

Δείτε και το post στα αγγλικά για περισσότερες λεπτομέρειες. Αν έχει κάποιος καμιά ιδέα, ας μου το πει να δω τι μπορεί να φταίει.

Thanks!

[imitheos]

Δεν έχω κάτι σίγουρο να σου πω χωρίς παραπάνω πληροφορίες αλλά μήπως η assembly του array από τον mdadm αργεί για ένα μικρό διάστημα στο οποίο πάει να τρέξει το cryptsetup και δεν την βρίσκει ;

Όλα αυτά που περιγράφεις γίνονται στο initramfs ή στο κανονικό init ; Μερικές φορές γίνονται μ.κίες κατά την ετοιμασία του initramfs από τα genkernel / dracut.

[GoofyX]

Στο κανονικό init γίνεται, όχι στο initramfs.

[imitheos]

Δεν είναι σίγουρο ότι θα σε διαφωτίσει αλλά δοκίμασε να προσθέσεις προσωρινά στην εκκίνηση την παράμετρο systemd.log_level=debug (ή το σκέτο debug το οποίο θα δείξει και μηνύματα του πυρήνα και όλων των υποσυστημάτων). Έχω παρατηρήσει ότι ενώ με την debug τα μηνύματα που δίνει ο systemd είναι άπειρα και πρέπει να ψάξεις σε μια θάλασσα να βρεις αυτό που θέλεις, αντίθετα χωρίς την debug δίνει πολύ λίγες πληροφορίες που δεν σε βοηθάνε στην περίπτωση προβλήματος.

Εκτός από αυτό μπορείς να αλλάξεις προσωρινά και το αρχείο του service ώστε να τρέχει και το cryptsetup με την παράμετρο --debug.

[GoofyX]

Αυτό που βλέπω μετά το debug log είναι το εξής:

Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Acquiring read lock for device /dev/md/sysresccd:HOME_ARRAY.
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: WARNING: Locking directory /run/cryptsetup is missing!
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Opening lock resource file /run/cryptsetup/L_9:126
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Verifying lock handle for /dev/md/sysresccd:HOME_ARRAY.
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Device /dev/md/sysresccd:HOME_ARRAY READ lock taken.
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Trying to read primary LUKS2 header at offset 0x0.
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Opening locked device /dev/md/sysresccd:HOME_ARRAY
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Veryfing locked device handle (bdev)
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Trying to read secondary LUKS2 header at offset 0x4000.
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Reusing open ro fd on device /dev/md/sysresccd:HOME_ARRAY
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Trying to read secondary LUKS2 header at offset 0x8000.
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Reusing open ro fd on device /dev/md/sysresccd:HOME_ARRAY
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Trying to read secondary LUKS2 header at offset 0x10000.
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Reusing open ro fd on device /dev/md/sysresccd:HOME_ARRAY
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Trying to read secondary LUKS2 header at offset 0x20000.
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Reusing open ro fd on device /dev/md/sysresccd:HOME_ARRAY
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Trying to read secondary LUKS2 header at offset 0x40000.
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Reusing open ro fd on device /dev/md/sysresccd:HOME_ARRAY
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Trying to read secondary LUKS2 header at offset 0x80000.
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Reusing open ro fd on device /dev/md/sysresccd:HOME_ARRAY
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Trying to read secondary LUKS2 header at offset 0x100000.
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Reusing open ro fd on device /dev/md/sysresccd:HOME_ARRAY
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Trying to read secondary LUKS2 header at offset 0x200000.
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Reusing open ro fd on device /dev/md/sysresccd:HOME_ARRAY
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Trying to read secondary LUKS2 header at offset 0x400000.
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Reusing open ro fd on device /dev/md/sysresccd:HOME_ARRAY
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: LUKS2 header read failed (-5).
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Device /dev/md/sysresccd:HOME_ARRAY READ lock released.
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Failed to load LUKS superblock on device /dev/md/sysresccd:HOME_ARRAY: Input/output error
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Releasing crypt device /dev/md/sysresccd:HOME_ARRAY context.
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Releasing device-mapper backend.

Είναι σαν να πάει να διαβάσει το volume ως LUKS2, κάτι που δεν ισχύει, είναι στο παλιό format, το LUKS. Μπορώ να περάσω ως παράμετρο κάπου το format του volume (LUKS αντί για LUKS2);

[imitheos]

Αυτό που βλέπω μετά το debug log είναι το εξής:

Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Acquiring read lock for device /dev/md/sysresccd:HOME_ARRAY.
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: WARNING: Locking directory /run/cryptsetup is missing!
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Opening lock resource file /run/cryptsetup/L_9:126
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Verifying lock handle for /dev/md/sysresccd:HOME_ARRAY.
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Device /dev/md/sysresccd:HOME_ARRAY READ lock taken.
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Trying to read primary LUKS2 header at offset 0x0.
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Opening locked device /dev/md/sysresccd:HOME_ARRAY
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Veryfing locked device handle (bdev)
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Trying to read secondary LUKS2 header at offset 0x4000.
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Reusing open ro fd on device /dev/md/sysresccd:HOME_ARRAY
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Trying to read secondary LUKS2 header at offset 0x8000.
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Reusing open ro fd on device /dev/md/sysresccd:HOME_ARRAY
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Trying to read secondary LUKS2 header at offset 0x10000.
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Reusing open ro fd on device /dev/md/sysresccd:HOME_ARRAY
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Trying to read secondary LUKS2 header at offset 0x20000.
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Reusing open ro fd on device /dev/md/sysresccd:HOME_ARRAY
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Trying to read secondary LUKS2 header at offset 0x40000.
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Reusing open ro fd on device /dev/md/sysresccd:HOME_ARRAY
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Trying to read secondary LUKS2 header at offset 0x80000.
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Reusing open ro fd on device /dev/md/sysresccd:HOME_ARRAY
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Trying to read secondary LUKS2 header at offset 0x100000.
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Reusing open ro fd on device /dev/md/sysresccd:HOME_ARRAY
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Trying to read secondary LUKS2 header at offset 0x200000.
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Reusing open ro fd on device /dev/md/sysresccd:HOME_ARRAY
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Trying to read secondary LUKS2 header at offset 0x400000.
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Reusing open ro fd on device /dev/md/sysresccd:HOME_ARRAY
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: LUKS2 header read failed (-5).
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Device /dev/md/sysresccd:HOME_ARRAY READ lock released.
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Failed to load LUKS superblock on device /dev/md/sysresccd:HOME_ARRAY: Input/output error
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Releasing crypt device /dev/md/sysresccd:HOME_ARRAY context.
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Releasing device-mapper backend.

Είναι σαν να πάει να διαβάσει το volume ως LUKS2, κάτι που δεν ισχύει, είναι στο παλιό format, το LUKS. Μπορώ να περάσω ως παράμετρο κάπου το format του volume (LUKS αντί για LUKS2);

Όντως έτσι δείχνει αλλά είναι παράξενο. Εφόσον απέτυχε το probing για ένα format θα έπρεπε να πάει στο επόμενο format. Ίσως να είναι και άσχετο το probing του luks2 αλλιώς γιατί να πετυχαίνει 3 δευτερόλεπτα μετά που το τρέχεις χειροκίνητα.

Στο σκέτο cryptsetup μπορείς να του πεις open --type luks1 αντί για το κλασικό open --type luks. Στην manpage των systemd-cryptsetup-generator, crypttab υπάρχουν διάφορες επιλογές αλλά δεν βλέπω κάπου να υπάρχει επιλογή για force luks mode σε 1 ή 2.

[GoofyX]

Οπότε μία λύση είναι να κάνω μετατροπή το volume σε LUKS2 (ήδη παίρνω αυτή τη στιγμή backup σε εξωτερικό για σίγουρα) ή να βρεθεί παράμετρος που να κάνει force το σκέτο LUKS.

Βασικά θα δοκιμάσω μετά το backup να κάνω umount το home και να μετατρέψω το volume online σε LUKS2 που υποτίθεται έχει το νέο cryptsetup.

[imitheos]

Οπότε μία λύση είναι να κάνω μετατροπή το volume σε LUKS2 (ήδη παίρνω αυτή τη στιγμή backup σε εξωτερικό για σίγουρα) ή να βρεθεί παράμετρος που να κάνει force το σκέτο LUKS.

Βασικά θα δοκιμάσω μετά το backup να κάνω umount το home και να μετατρέψω το volume online σε LUKS2 που υποτίθεται έχει το νέο cryptsetup.

Πριν κάνεις κάτι τέτοιο, ψάξε το πρώτα. Αποκλείεται να γίνεται κάτι τόσο χαζό με το cryptsetup. Έκανα μια δοκιμή σε ένα δικό μου image. Δες παρακάτω τι παίρνω:

# cryptsetup --debug open disk.img lll            
# Running command open.
# Locking memory.
# Installing SIGINT/SIGTERM handler.
# Unblocking interruption on signal.
# Allocating context for crypt device disk.img.
# Trying to open and read device disk.img with direct-io.
# Initialising device-mapper backend library.
# Trying to load any crypt type from device disk.img.
# Crypto backend (OpenSSL 1.1.1c  28 May 2019) initialized in cryptsetup library version 2.1.0.
# Detected kernel Linux 5.3.9 x86_64.
# Loading LUKS2 header (repair disabled).
# Acquiring read lock for device disk.img.
# Verifying read lock handle for device disk.img.
# Device disk.img READ lock taken.
# Trying to read primary LUKS2 header at offset 0x0.
# Opening locked device disk.img
# Veryfing locked device handle (regular file)
# Trying to read secondary LUKS2 header at offset 0x4000.
# Opening locked device disk.img
# Veryfing locked device handle (regular file)
# Trying to read secondary LUKS2 header at offset 0x8000.
# Opening locked device disk.img
# Veryfing locked device handle (regular file)
# Trying to read secondary LUKS2 header at offset 0x10000.
# Opening locked device disk.img
# Veryfing locked device handle (regular file)
# Trying to read secondary LUKS2 header at offset 0x20000.
# Opening locked device disk.img
# Veryfing locked device handle (regular file)
# Trying to read secondary LUKS2 header at offset 0x40000.
# Opening locked device disk.img
# Veryfing locked device handle (regular file)
# Trying to read secondary LUKS2 header at offset 0x80000.
# Opening locked device disk.img
# Veryfing locked device handle (regular file)
# Trying to read secondary LUKS2 header at offset 0x100000.
# Opening locked device disk.img
# Veryfing locked device handle (regular file)
# Trying to read secondary LUKS2 header at offset 0x200000.
# Opening locked device disk.img
# Veryfing locked device handle (regular file)
# Trying to read secondary LUKS2 header at offset 0x400000.
# Opening locked device disk.img
# Veryfing locked device handle (regular file)
# LUKS2 header read failed (-22).
# Device disk.img READ lock released.
Device disk.img is not a valid LUKS device.
# Releasing crypt device disk.img context.
# Releasing device-mapper backend.
# Unlocking memory.
Command failed with code -1 (wrong or missing parameters).

Ακριβώς αυτό που παίρνεις και εσύ με το debug.

Βάζοντας χειροκίνητα --type luks1 παίρνω το παρακάτω:

# cryptsetup --debug open --type luks1 disk.img lll
# Running command open.
# Locking memory.
# Installing SIGINT/SIGTERM handler.
# Unblocking interruption on signal.
# Allocating context for crypt device tisk.img.
# Trying to open and read device disk.img with direct-io.
# Initialising device-mapper backend library.
# Trying to load LUKS1 crypt type from device disk.img.
# Crypto backend (OpenSSL 1.1.1c  28 May 2019) initialized in cryptsetup library version 2.1.0.
# Detected kernel Linux 5.3.9 x86_64.
# PBKDF pbkdf2, hash sha256, time_ms 2000 (iterations 0), max_memory_kb 0, parallel_threads 0.
# Reading LUKS header of size 1024 from device disk.img
# LUKS header not detected.
Device disk.img is not a valid LUKS device.
# Releasing crypt device disk.img context.
# Releasing device-mapper backend.
# Unlocking memory.
Command failed with code -1 (wrong or missing parameters).

Ώπα, πάλι δεν το βρήκε. Μετά σκέφτηκα ότι το image μου έχει MBR και το luks partition βρίσκεται πιο μέσα οπότε έδινα λάθος image. Δίνοντας το σωστό offset μέσα στο image, το βρίσκει από μόνο του ότι είναι LUKS1 χωρίς να κάνω τίποτα. Αν βάλω επίτηδες να ψάξει σαν LUKS2, τότε παίρνω το παρακάτω.

# cryptsetup --debug open --type luks2 /dev/loop0 lll
# cryptsetup 2.1.0 processing "cryptsetup --debug open --type luks2 /dev/loop0 lll"
# Running command open.
# Locking memory.
# Installing SIGINT/SIGTERM handler.
# Unblocking interruption on signal.
# Allocating context for crypt device /dev/loop0.
# Trying to open and read device /dev/loop0 with direct-io.
# Initialising device-mapper backend library.
# Trying to load LUKS2 crypt type from device /dev/loop0.
# Crypto backend (OpenSSL 1.1.1c  28 May 2019) initialized in cryptsetup library version 2.1.0.
# Detected kernel Linux 5.3.9 x86_64.
Device /dev/loop0 is not a valid LUKS device.
# Releasing crypt device /dev/loop0 context.
# Releasing device-mapper backend.
# Unlocking memory.
Command failed with code -1 (wrong or missing parameters).

Όπως βλέπεις, καμμία σχέση με το αρχικό μήνυμα. Βρήκε με την μία το header και απλά μου είπε ότι δεν είναι LUKS2.

Δηλαδή με 90% σιγουριά, εκείνα τα probing μηνύματα τα δίνει το cryptsetup μόνο όταν δεν βρίσκει κάποιο header. Μήπως λοιπόν το πρόβλημα είναι στο προηγούμενο layer το οποίο δεν ανοίγει σωστά ή έγκαιρα το RAID1;

[GoofyX]

Ναι, είναι αυτό που λες. Δεν προλαβαίνει να δει το mirror πριν το cryptsetup. Βλέπω στο log:

Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Device /dev/md/sysresccd:HOME_ARRAY READ lock released.
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Failed to load LUKS superblock on device /dev/md/sysresccd:HOME_ARRAY: Input/output error
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Releasing crypt device /dev/md/sysresccd:HOME_ARRAY context.
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Releasing device-mapper backend.
Νοε 07 14:53:37 helios systemd-cryptsetup[438]: Closing read only fd for /dev/md/sysresccd:HOME_ARRAY.
Νοε 07 14:53:37 helios systemd[1]: dev-disk-by\x2dpath-pci\x2d0000:00:17.0\x2data\x2d4\x2dpart2.device: Changed dead -> plugged
Νοε 07 14:53:37 helios systemd[1]: dev-disk-by\x2did-wwn\x2d0x50014ee205d69f45\x2dpart2.device: Changed dead -> plugged
Νοε 07 14:53:37 helios systemd[1]: dev-disk-by\x2dlabel-EXT1.device: Changed dead -> plugged
Νοε 07 14:53:37 helios systemd[1]: dev-disk-by\x2dpartuuid-f0929fde\x2d4666\x2d4943\x2da605\x2ddbd5371e78bd.device: Changed dead -> plugged
Νοε 07 14:53:37 helios systemd[1]: dev-sdd2.device: Changed dead -> plugged
Νοε 07 14:53:37 helios systemd[1]: sys-devices-pci0000:00-0000:00:17.0-ata4-host3-target3:0:0-3:0:0:0-block-sdd-sdd2.device: Changed dead -> plugged
Νοε 07 14:53:37 helios systemd[1]: dev-disk-by\x2dpartlabel-Linux\x5cx20swap.device: Device dev-disk-by\x2dpartlabel-Linux\x5cx20swap.device appeared twice with different sysfs paths /sys/devices/pci0000:00/0000:00:17.0/ata2/host1/target1:0:0/1:0:0:0/block/sdb/sdb3 and /sys/devices/pci0000:00/0000:00:17.0/ata4/host3/target3:0:0/3:0:0:0/block/sdd/sdd3, ignoring the latter.
Νοε 07 14:53:37 helios systemd[1]: dev-disk-by\x2did-wwn\x2d0x50014ee205d69f45\x2dpart3.device: Changed dead -> plugged
Νοε 07 14:53:37 helios systemd[1]: dev-disk-by\x2dpartuuid-aa1ac287\x2d2e8a\x2d477b\x2da2d2\x2da248d9fe0662.device: Changed dead -> plugged
Νοε 07 14:53:37 helios systemd[1]: dev-disk-by\x2dpath-pci\x2d0000:00:17.0\x2data\x2d4\x2dpart3.device: Changed dead -> plugged
Νοε 07 14:53:37 helios systemd[1]: dev-disk-by\x2did-ata\x2dWDC_WD7502AAEX\x2d00Y9A0_WD\x2dWCAW31966887\x2dpart3.device: Changed dead -> plugged
Νοε 07 14:53:37 helios systemd[1]: dev-disk-by\x2duuid-de0565ce\x2d4ec0\x2d453b\x2da5aa\x2d9893a6085bf4.device: Changed dead -> plugged
Νοε 07 14:53:37 helios systemd[1]: dev-disk-by\x2duuid-de0565ce\x2d4ec0\x2d453b\x2da5aa\x2d9893a6085bf4.device: Job 71 dev-disk-by\x2duuid-de0565ce\x2d4ec0\x2d453b\x2da5aa\x2d9893a6085bf4.device/start finished, result=done
Νοε 07 14:53:37 helios systemd[1]: Found device WDC_WD7502AAEX-00Y9A0 Linux\x20swap.
Νοε 07 14:53:37 helios systemd[1]: dev-sdd3.device: Changed dead -> plugged
Νοε 07 14:53:37 helios systemd[1]: sys-devices-pci0000:00-0000:00:17.0-ata4-host3-target3:0:0-3:0:0:0-block-sdd-sdd3.device: Changed dead -> plugged
Νοε 07 14:53:37 helios systemd[1]: Received SIGCHLD from PID 438 (systemd-cryptse).
Νοε 07 14:53:37 helios systemd[1]: Child 438 (systemd-cryptse) died (code=exited, status=1/FAILURE)
Νοε 07 14:53:37 helios systemd[1]: systemd-cryptsetup@home.service: Child 438 belongs to systemd-cryptsetup@home.service.
Νοε 07 14:53:37 helios systemd[1]: systemd-cryptsetup@home.service: Main process exited, code=exited, status=1/FAILURE
Νοε 07 14:53:37 helios systemd[1]: systemd-cryptsetup@home.service: Failed with result 'exit-code'.
Νοε 07 14:53:37 helios systemd[1]: systemd-cryptsetup@home.service: Changed start -> failed
Νοε 07 14:53:37 helios systemd[1]: systemd-cryptsetup@home.service: Job 17 systemd-cryptsetup@home.service/start finished, result=failed
Νοε 07 14:53:37 helios systemd[1]: Failed to start Cryptography Setup for home.
Νοε 07 14:53:37 helios kernel: md/raid1:md127: active with 2 out of 2 mirrors
Νοε 07 14:53:37 helios kernel: md127: detected capacity change from 0 to 37545115648
Νοε 07 14:53:37 helios kernel: md/raid1:md126: active with 2 out of 2 mirrors
Νοε 07 14:53:37 helios systemd[1]: home.mount: Job 46 home.mount/start finished, result=dependency
Νοε 07 14:53:37 helios systemd[1]: Dependency failed for /home.
Νοε 07 14:53:37 helios systemd[1]: local-fs.target: Job 32 local-fs.target/start finished, result=dependency
Νοε 07 14:53:37 helios systemd[1]: Dependency failed for Local File Systems.
Νοε 07 14:53:37 helios systemd[1]: local-fs.target: Job local-fs.target/start failed with result 'dependency'.
Νοε 07 14:53:37 helios systemd[1]: local-fs.target: Triggering OnFailure= dependencies.
Νοε 07 14:53:37 helios systemd[1]: emergency.target: Trying to enqueue job emergency.target/start/replace-irreversibly
Νοε 07 14:53:37 helios systemd[1]: Added job emergency.target/start to transaction.

Βέβαια η παραπάνω υπόθεση προϋποθέτει ότι τα events log-άρονται με τη σειρά που έγιναν. Το array είναι το md126 που φαίνεται ότι είναι πιο κάτω.

Οπότε η ερώτηση είναι: WTF έγινε και άλλαξε; Έτσι έπαιζε χρόνια τώρα.

[imitheos]

Ναι, είναι αυτό που λες. Δεν προλαβαίνει να δει το mirror πριν το cryptsetup. Βλέπω στο log:

Νοε 07 14:53:37 helios systemd[1]: Child 438 (systemd-cryptse) died (code=exited, status=1/FAILURE)
Νοε 07 14:53:37 helios systemd[1]: systemd-cryptsetup@home.service: Child 438 belongs to systemd-cryptsetup@home.service.
Νοε 07 14:53:37 helios systemd[1]: systemd-cryptsetup@home.service: Main process exited, code=exited, status=1/FAILURE
Νοε 07 14:53:37 helios systemd[1]: systemd-cryptsetup@home.service: Failed with result 'exit-code'.
Νοε 07 14:53:37 helios systemd[1]: systemd-cryptsetup@home.service: Changed start -> failed
Νοε 07 14:53:37 helios systemd[1]: systemd-cryptsetup@home.service: Job 17 systemd-cryptsetup@home.service/start finished, result=failed
Νοε 07 14:53:37 helios systemd[1]: Failed to start Cryptography Setup for home.
Νοε 07 14:53:37 helios kernel: md/raid1:md127: active with 2 out of 2 mirrors
Νοε 07 14:53:37 helios kernel: md127: detected capacity change from 0 to 37545115648
Νοε 07 14:53:37 helios kernel: md/raid1:md126: active with 2 out of 2 mirrors

Βέβαια η παραπάνω υπόθεση προϋποθέτει ότι τα events log-άρονται με τη σειρά που έγιναν. Το array είναι το md126 που φαίνεται ότι είναι πιο κάτω.

Οπότε η ερώτηση είναι: WTF έγινε και άλλαξε; Έτσι έπαιζε χρόνια τώρα.

File ./usr/lib/systemd/system/mdadm-last-resort@.service
[Unit]
Description=Activate md array %I even though degraded
DefaultDependencies=no
ConditionPathExists=!/sys/devices/virtual/block/%i/md/sync_action

[Service]
Type=oneshot
ExecStart=/sbin/mdadm --run /dev/%i

File ./usr/lib/systemd/system/mdadm-last-resort@.timer
[Unit]
Description=Timer to wait for more drives before activating degraded array %I.
DefaultDependencies=no
Conflicts=sys-devices-virtual-block-%i.device

[Timer]
OnActiveSec=30

File ./usr/lib/udev/rules.d/64-md-raid-assembly.rules
# remember you can limit what gets auto/incrementally assembled by
# mdadm.conf(5)'s 'AUTO' and selectively whitelist using 'ARRAY'
ACTION=="add|change", IMPORT{program}="/sbin/mdadm --incremental --export $devnode --offroot $env{DEVLINKS}"
ACTION=="add|change", ENV{MD_STARTED}=="*unsafe*", ENV{MD_FOREIGN}=="no", ENV{SYSTEMD_WANTS}+="mdadm-last-resort@$env{MD_DEVICE}.timer"

Αν ερμήνευσα σωστά τα services, ο τρόπος που κάνει assemble ο systemd τα arrays είναι τελείως διαφορετικός από τα άλλα init. Κάθε φορά που εμφανίζεται μια συσκευή, τρέχει ο αντίστοιχος udev κανόνας ο οποίος κάνει incremental add την συσκευή στο array. Μπορεί δηλαδή να έχεις ένα RAID6 με 8 συσκευές και να έχουν γίνει assemble οι 6 από τις 8 γιατί οι άλλες δεν εμφανίστηκαν ακόμη. Για να αποφευχθεί ο κίνδυνος να τρέξει το systemd service πριν εμφανιστούν όλες οι συσκευές και να έχεις έτσι ένα degraded mount, υπάρχει ένα timer που κάνει conflict.

Έτσι λοιπόν υπάρχουν πιθανότητες να δημιουργηθεί κάποιο race. Θυμάμαι ότι το είχα διαβάσει κιόλας παλαιότερα στο blog του Chris. Αυτό είναι το άρθρο που το εξηγεί καλύτερα από εμένα.

Τώρα γιατί δούλευε και ξαφνικά δεν δουλεύει δεν το ξέρω και με την debugging λειτουργικότητα του systemd δεν ξέρω πόσο εύκολο θα σου είναι να το βρεις. Σε major εκδόσεις του systemd μερικές φορές αλλάζει ο αλγόριθμος της παραλληλίας και οι υπηρεσίες εκτελούνται με διαφορετική σειρά (στο opensuse έχω παρατηρήσει μέχρι και από επανεκκίνηση σε επανεκκίνηση να αλλάζει η σειρά χωρίς να αλλάξει κανένα πρόγραμμα). Ή μπορεί να άλλαξες πυρήνα και κάποιο pci probe να αργεί και να πηδάει και τον Χ σκληρό. Ή μπορεί να αργεί να απαντήσει λίγο ο ένας δίσκος.

Για καλό και για κακό τρέξε ένα smartctl -a /dev/sdX και στους δύο δίσκους και δες αν έχουν τίποτα ανησυχητικό. Λυπάμαι που δεν μπορώ να δώσω κάτι πιο χειροπιαστό αλλά δεν έχω ιδέα από systemd.

[famous-walker]

Δεν είναι απίθανο. Και μένα σε κάποιο update κάποιο κόλλημα έφαγε και έπρεπε να δηλώσω χειροκίνητα η "προβληματική" υπηρεσία να ξεκινά μετά από συγκεκριμένη υπηρεσία.

[GoofyX]

File ./usr/lib/systemd/system/mdadm-last-resort@.service
[Unit]
Description=Activate md array %I even though degraded
DefaultDependencies=no
ConditionPathExists=!/sys/devices/virtual/block/%i/md/sync_action

[Service]
Type=oneshot
ExecStart=/sbin/mdadm --run /dev/%i

File ./usr/lib/systemd/system/mdadm-last-resort@.timer
[Unit]
Description=Timer to wait for more drives before activating degraded array %I.
DefaultDependencies=no
Conflicts=sys-devices-virtual-block-%i.device

[Timer]
OnActiveSec=30

File ./usr/lib/udev/rules.d/64-md-raid-assembly.rules
# remember you can limit what gets auto/incrementally assembled by
# mdadm.conf(5)'s 'AUTO' and selectively whitelist using 'ARRAY'
ACTION=="add|change", IMPORT{program}="/sbin/mdadm --incremental --export $devnode --offroot $env{DEVLINKS}"
ACTION=="add|change", ENV{MD_STARTED}=="*unsafe*", ENV{MD_FOREIGN}=="no", ENV{SYSTEMD_WANTS}+="mdadm-last-resort@$env{MD_DEVICE}.timer"

Αν ερμήνευσα σωστά τα services, ο τρόπος που κάνει assemble ο systemd τα arrays είναι τελείως διαφορετικός από τα άλλα init. Κάθε φορά που εμφανίζεται μια συσκευή, τρέχει ο αντίστοιχος udev κανόνας ο οποίος κάνει incremental add την συσκευή στο array. Μπορεί δηλαδή να έχεις ένα RAID6 με 8 συσκευές και να έχουν γίνει assemble οι 6 από τις 8 γιατί οι άλλες δεν εμφανίστηκαν ακόμη. Για να αποφευχθεί ο κίνδυνος να τρέξει το systemd service πριν εμφανιστούν όλες οι συσκευές και να έχεις έτσι ένα degraded mount, υπάρχει ένα timer που κάνει conflict.

Έτσι λοιπόν υπάρχουν πιθανότητες να δημιουργηθεί κάποιο race. Θυμάμαι ότι το είχα διαβάσει κιόλας παλαιότερα στο blog του Chris. Αυτό είναι το άρθρο που το εξηγεί καλύτερα από εμένα.

Τώρα γιατί δούλευε και ξαφνικά δεν δουλεύει δεν το ξέρω και με την debugging λειτουργικότητα του systemd δεν ξέρω πόσο εύκολο θα σου είναι να το βρεις. Σε major εκδόσεις του systemd μερικές φορές αλλάζει ο αλγόριθμος της παραλληλίας και οι υπηρεσίες εκτελούνται με διαφορετική σειρά (στο opensuse έχω παρατηρήσει μέχρι και από επανεκκίνηση σε επανεκκίνηση να αλλάζει η σειρά χωρίς να αλλάξει κανένα πρόγραμμα). Ή μπορεί να άλλαξες πυρήνα και κάποιο pci probe να αργεί και να πηδάει και τον Χ σκληρό. Ή μπορεί να αργεί να απαντήσει λίγο ο ένας δίσκος.

Για καλό και για κακό τρέξε ένα smartctl -a /dev/sdX και στους δύο δίσκους και δες αν έχουν τίποτα ανησυχητικό. Λυπάμαι που δεν μπορώ να δώσω κάτι πιο χειροπιαστό αλλά δεν έχω ιδέα από systemd.

Τελικά το πρόβλημα λύθηκε ως εξής:

Έτρεξα το /lib/systemd/system-generators/systemd-cryptsetup-generator το οποίο δημιουργεί στο /tmp το systemd-cryptsetup@home.service (το systemctl δείχνει μεν το αρχείο του service, αλλά δεν υπάρχει, δημιουργείται δυναμικά). Το αντιγράφω στο /etc/systemd/system κι εκεί προσθέτω κάτω από το section [Service] το εξής:

ExecStartPre=/bin/sleep 0.3

Με αυτό τον τρόπο πριν ξεκινήσει το service, περιμένει 300ms και μετά ξεκινάει. Με την επανεκκίνηση φαίνεται να παίζει.

Όσο έψαξα (βασικά το τελευταίο διάστημα έχω κουραστεί λίγο με κάποια πράματα στο Linux...) δε βρήκα άλλο τρόπο να γίνεται αυτό, να προσθέτει μια μικρή καθυστέρηση στην εκκίνηση του service. Το λογικό είναι να μην ξεκινάει το service αν δεν βρει πρώτα το dm volume, αλλά...

- - - Updated - - -

Βασικά τώρα που το βλέπω, το αρχείο όλο έχει ως εξής:

# Automatically generated by systemd-cryptsetup-generator

[Unit]
Description=Cryptography Setup for %I
Documentation=man:crypttab(5) man:systemd-cryptsetup-generator(8) man:systemd-cryptsetup@.service(8)
SourcePath=/etc/crypttab
DefaultDependencies=no
Conflicts=umount.target
IgnoreOnIsolate=true
After=cryptsetup-pre.target
Before=cryptsetup.target
BindsTo=dev-md-sysresccd:HOME_ARRAY.device
After=dev-md-sysresccd:HOME_ARRAY.device
Before=umount.target

[Service]
Type=oneshot
RemainAfterExit=yes
TimeoutSec=0
KeyringMode=shared
OOMScoreAdjust=500
ExecStartPre=/bin/sleep 0.3
ExecStart=/lib/systemd/systemd-cryptsetup attach 'home' '/dev/md/sysresccd:HOME_ARRAY' 'none' 'timeout=300'
ExecStop=/lib/systemd/systemd-cryptsetup detach 'home'

Η γραμμή με bold είναι αυτή που λέει ότι το service πρέπει να ξεκινήσει μετά την ύπαρξη του /dev/md/sysresccd:HOME_ARRAY, που δεν συμβαίνει. Μήπως είναι κάποιο bug σε αυτή την έκδοση του systemd; Τι λέτε;