Bug 725622

Summary: systemd breaks startup (crypted home?)
Product: [openSUSE] openSUSE 12.1 Reporter: Harald Koenig <koenig>
Component: BasesystemAssignee: Ludwig Nussel <lnussel>
Status: RESOLVED DUPLICATE QA Contact: E-mail List <qa-bugs>
Severity: Critical    
Priority: P5 - None CC: lnussel, werner
Version: Factory   
Target Milestone: ---   
Hardware: x86-64   
OS: Other   
Whiteboard:
Found By: --- Services Priority:
Business Priority: Blocker: ---
Marketing QA Status: --- IT Deployment: ---
Attachments: fstab
crypttab
console dump
hwinfo --block output
systemd debug output
screen dump after boot in emergency mode
more debug output
dmesg with debug output
before mount
after mount

Description Harald Koenig 2011-10-20 21:23:53 UTC
last "zypper dup" of my 12.1-beta notebook installed systemd-sysvinit-37-2.1.x86_64 and sysvinit-2.88+-65.1.x86_64 (before it was running fine with old style sysvinit-2.88-37.47.1).

now the system startup hangs, maybe due to my crypted home ?!

/home passphrase gets requested, but then after timeout I end in "emergency mode" and /home is not mounted.  exiting "emergency mode" asks again for /home passphrase, and I end in "emergency mode" again -- looks like ground hog day :-(((


this is the console output:

                                                                                                                                                                                                                                 unused
Waiting for udev to settle...
Scanning for LVM volume groups...
  Reading all physical volumes.  This may take a while...
  Found volume group "system" using metadata type lvm2
Activating LVM volume groups...
  7 logical volume(s) in volume group "system" now active
                                                                                                                                                                                                                                 done
[ 1791.563301] systemd[1]: Job tmpfs.device/start timed out.
[ 1791.598992] systemd[1]: Job remote-fs.target/start failed with result 'dependency'.
[ 1791.634034] systemd[1]: Job local-fs.target/start failed with result 'dependency'.
[ 1791.669280] systemd[1]: Triggering OnFailure= dependencies of local-fs.target.
[ 1791.704659] systemd[1]: Job var-run-nscd.mount/start failed with result 'dependency'.
[ 1791.740064] systemd[1]: Job fsck@tmpfs.service/start failed with result 'dependency'.
[ 1791.775067] systemd[1]: Job tmpfs.device/start failed with result 'timeout'.
Welcome to emergency mode. Use "systemctl default" or ^D to activate default mode.
Give root password for login: [ 1792.062344] dhcpcd[5680]: wlan0: exiting
  Can't deactivate volume group "system" with 5 open logical volume(s)
                                                                                                                                                                                                                                 skipped
Not shutting down MD RAID - reboot/halt scripts do this.                                                                                                                                                                         missing
[ 1792.323473] systemd[1]: md.service: control process exited, code=exited status=3
[ 1792.364160] systemd[1]: Unit md.service entered failed state.



I'm totally new to systemd -- now to I debug/test/workaround/... (or just get rid of systemd and use sysvinit again) ?!?
Comment 1 Frederic Crozat 2011-10-24 13:47:04 UTC
please attach /etc/fstab and /etc/crypttab and describe a little bit your partition setup.
Comment 2 Harald Koenig 2011-10-24 13:58:12 UTC
Created attachment 458492 [details]
fstab
Comment 3 Harald Koenig 2011-10-24 13:58:37 UTC
Created attachment 458493 [details]
crypttab
Comment 4 Frederic Crozat 2011-10-24 14:11:41 UTC
could you test package available at home:fcrozat:systemd / systemd ?

I think it will fix your issue.
Comment 5 Harald Koenig 2011-10-24 15:27:21 UTC
(In reply to comment #4)
> could you test package available at home:fcrozat:systemd / systemd ?
> 
> I think it will fix your issue.

NAK: did not help.

RPMs installed now:
systemd-sysvinit-37-268.2.x86_64
systemd-37-268.2.x86_64
systemd-32bit-37-268.2.x86_64
systemd-presets-branding-openSUSE-0.1.0-5.1.noarch

/home still not mounted after root login.

attached "screen.dump-6" shows console messages after root login
Comment 6 Harald Koenig 2011-10-24 15:27:41 UTC
Created attachment 458514 [details]
console dump
Comment 7 Harald Koenig 2011-10-24 15:34:25 UTC
# systemctl  -a  --failed | cat
UNIT       LOAD   ACTIVE SUB    JOB DESCRIPTION
md.service loaded failed failed     LSB: Multiple Device RAID

how can I trigger a 2nd test without rebooting ?

systemctl start  md.service
systemctl reset-fail  md.service

don't seem to be the right way ?!
Comment 8 Frederic Crozat 2011-10-24 15:40:07 UTC
how is your /dev/system/home volume created ?

is it RAID, lvm, both, etc.. ?
Comment 9 Frederic Crozat 2011-10-24 15:42:07 UTC
try attaching hwinfo --block output, when everything is working (ie booting with sysvinit)
Comment 10 Harald Koenig 2011-10-24 15:57:19 UTC
some more input:

# dmesg  | egrep 'systemd|home|crypt'
[    1.087928] lib80211_crypt: registered algorithm 'NULL'
[    5.706112] systemd[1]: systemd 37 running in system mode. (+PAM +LIBWRAP +AUDIT +SELINUX +SYSVINIT +LIBCRYPTSETUP; suse)
[    6.795078] systemd[1]: Set hostname to <harald.science-computing.de>.
[   12.079343] systemd[1]: Found ordering cycle on basic.target/start
[   12.115332] systemd[1]: Walked on cycle path to sockets.target/start
[   12.151028] systemd[1]: Walked on cycle path to dbus.socket/start
[   12.186423] systemd[1]: Walked on cycle path to sysinit.target/start
[   12.221705] systemd[1]: Walked on cycle path to open-iscsi.service/start
[   12.256771] systemd[1]: Walked on cycle path to network.target/start
[   12.291863] systemd[1]: Walked on cycle path to NetworkManager-wait-online.service/start
[   12.326800] systemd[1]: Walked on cycle path to NetworkManager.service/verify-active
[   12.361300] systemd[1]: Walked on cycle path to basic.target/start
[   12.395360] systemd[1]: Breaking ordering cycle by deleting job dbus.socket/start
[   12.429382] systemd[1]: Found ordering cycle on basic.target/start
[   12.463470] systemd[1]: Walked on cycle path to sysinit.target/start
[   12.497336] systemd[1]: Walked on cycle path to open-iscsi.service/start
[   12.530869] systemd[1]: Walked on cycle path to network.target/start
[   12.564183] systemd[1]: Walked on cycle path to NetworkManager-wait-online.service/start
[   12.597540] systemd[1]: Walked on cycle path to NetworkManager.service/verify-active
[   12.630993] systemd[1]: Walked on cycle path to basic.target/start
[   12.664235] systemd[1]: Breaking ordering cycle by deleting job open-iscsi.service/start
[   21.418975] systemd-fsck[889]: root4: clean, 1008464/2293760 files, 8529514/9175040 blocks
[   21.496497] systemd-fsck[874]: root2: clean, 6789/1966080 files, 6220530/7864320 blocks (check after next mount)
[   23.642533] systemd-fsck[960]: boot121: clean, 222/328656 files, 128791/1313305 blocks
[   24.348445] systemd-fsck[954]: VMs: clean, 28918/5232640 files, 19271222/20971520 blocks (check in 2 mounts)
[   25.071420] systemd-fsck[958]: scr: clean, 385868/6471680 files, 24346997/25874682 blocks
[   25.143200] systemd-fsck[956]: kiwi: clean, 184689/3276800 files, 12024329/13107200 blocks (check after next mount)
[   25.421089] systemd-fsck[962]: boot2: clean, 197/261040 files, 245238/1060224 blocks
[   49.232140] systemd-cryptsetup[865]: Set cipher aes, mode cbc-essiv:sha256, key size 128 bits for device /dev/system/home.
[   50.320303] modprobe[1051]: FATAL: Error inserting padlock_sha (/lib/modules/3.1.0-rc9-1-desktop/kernel/drivers/crypto/padlock-sha.ko): No such device
[  102.698042] systemd[1]: Job tmpfs.device/start timed out.
[  102.798527] systemd[1]: Job remote-fs.target/start failed with result 'dependency'.
[  102.831952] systemd[1]: Job local-fs.target/start failed with result 'dependency'.
[  102.865760] systemd[1]: Triggering OnFailure= dependencies of local-fs.target.
[  102.901157] systemd[1]: Job var-run-nscd.mount/start failed with result 'dependency'.
[  102.935924] systemd[1]: Job fsck@tmpfs.service/start failed with result 'dependency'.
[  102.970732] systemd[1]: Job tmpfs.device/start failed with result 'timeout'.
[  104.084649] systemd[1]: md.service: control process exited, code=exited status=3
[  104.135107] systemd[1]: Unit md.service entered failed state.
[  104.190263] systemd[1]: Startup finished in 6s 842ms 955us (kernel) + 1min 37s 347ms 241us (userspace) = 1min 44s 190ms 196us.


I noticed (due to bug #725656) the 

[   12.664235] systemd[1]: Breaking ordering cycle by deleting job open-iscsi.service/start

and tried

rpm -e open-iscsi

but it did not really help:

dmesg  | egrep 'systemd|home|crypt'
[    1.089556] lib80211_crypt: registered algorithm 'NULL'
[    5.581125] systemd[1]: systemd 37 running in system mode. (+PAM +LIBWRAP +AUDIT +SELINUX +SYSVINIT +LIBCRYPTSETUP; suse)
[    6.555596] systemd[1]: Set hostname to <harald.science-computing.de>.
[   18.935300] systemd-fsck[846]: root4: clean, 1008464/2293760 files, 8529514/9175040 blocks
[   19.012606] systemd-fsck[851]: root2 has been mounted 21 times without being checked, check forced.
[   20.298464] systemd-fsck[851]: root2: 6789/1966080 files (0.1% non-contiguous), 6220530/7864320 blocks
[   21.534904] systemd-fsck[924]: boot2: clean, 197/261040 files, 245238/1060224 blocks
[   21.992289] systemd-fsck[922]: boot121: clean, 222/328656 files, 128791/1313305 blocks
[   22.214720] systemd-fsck[918]: kiwi has been mounted 26 times without being checked, check forced.
[   22.302176] systemd-fsck[916]: VMs: clean, 28918/5232640 files, 19271222/20971520 blocks (check after next mount)
[   23.388103] systemd-fsck[920]: scr: clean, 385868/6471680 files, 24346997/25874682 blocks
[   23.919422] systemd-cryptsetup[849]: Set cipher aes, mode cbc-essiv:sha256, key size 128 bits for device /dev/system/home.
[   24.956347] modprobe[998]: FATAL: Error inserting padlock_sha (/lib/modules/3.1.0-rc9-1-desktop/kernel/drivers/crypto/padlock-sha.ko): No such device
[  101.674982] systemd[1]: Job tmpfs.device/start timed out.
[  101.784041] systemd[1]: Job remote-fs.target/start failed with result 'dependency'.
[  101.819767] systemd[1]: Job local-fs.target/start failed with result 'dependency'.
[  101.854587] systemd[1]: Triggering OnFailure= dependencies of local-fs.target.
[  101.890530] systemd[1]: Job var-run-nscd.mount/start failed with result 'dependency'.
[  101.925567] systemd[1]: Job fsck@tmpfs.service/start failed with result 'dependency'.
[  101.960741] systemd[1]: Job tmpfs.device/start failed with result 'timeout'.
[  102.869068] systemd[1]: md.service: control process exited, code=exited status=3
[  102.918103] systemd[1]: Unit md.service entered failed state.
[  102.975273] systemd[1]: Startup finished in 6s 562ms 59us (kernel) + 1min 36s 413ms 145us (userspace) = 1min 42s 975ms 204us.


what next ?


btw:

	cryptsetup  luksOpen /dev/system/home cr_home
	mount /home

works just fine...

is it possbile that this is a tmpfs problem ?!

[  101.674982] systemd[1]: Job tmpfs.device/start timed out.
Comment 11 Harald Koenig 2011-10-24 15:59:51 UTC
(In reply to comment #8)
> how is your /dev/system/home volume created ?
> 
> is it RAID, lvm, both, etc.. ?

this is a Lenovo T61p notebook with a single harddisk (sda).

sda4 and sda8 are 2 PVs for the single VG "system",
home is a LV:

  LV Name                /dev/system/home
  VG Name                system
  LV UUID                ...
  LV Write Access        read/write
  LV Status              available
  # open                 1
  LV Size                100.00 GiB
  Current LE             25600
  Segments               6
  Allocation             inherit
  Read ahead sectors     auto
  - currently set to     256
  Block device           253:0
Comment 12 Harald Koenig 2011-10-24 16:05:52 UTC
(In reply to comment #9)
> try attaching hwinfo --block output, when everything is working (ie booting
> with sysvinit)

see end of comment #10: access to home and manual start/mount in emerency shell is no problem.

how do I boot 12.1 with sysvinit ?
or shall I boot 11.4, or will INIT=/sbin/sysvinit work as expected ?!

the attached hwinfo--block.output is from 12.1 emergency shell after manual mounting of /home (so everything is "working" -- until I try to leave that shell or reboot;)
Comment 13 Harald Koenig 2011-10-24 16:06:25 UTC
Created attachment 458525 [details]
hwinfo --block output
Comment 14 Frederic Crozat 2011-10-24 16:17:02 UTC
it looks like you are dup of bnc#661401

to reboot under sysvinit :
-if you have graphical boot, press f5 and choose systemv
- or add "init=/sbin/sysvinit" to kernel boot command

if you aren't using iscsi at all, try uninstalling open-iscsi package to see if it fixes the issue for you.
Comment 15 Harald Koenig 2011-10-24 16:20:29 UTC
(In reply to comment #14)
> it looks like you are dup of bnc#661401
> 
> to reboot under sysvinit :
> -if you have graphical boot, press f5 and choose systemv
> - or add "init=/sbin/sysvinit" to kernel boot command
> 
> if you aren't using iscsi at all, try uninstalling open-iscsi package to see if
> it fixes the issue for you.

I already did this (see middle of comment #10):

and tried

   rpm -e open-iscsi

but it did not really help


I'll reboot...
Comment 16 Harald Koenig 2011-10-24 16:31:15 UTC
(In reply to comment #14)
> it looks like you are dup of bnc#661401
> 
> to reboot under sysvinit :
> -if you have graphical boot, press f5 and choose systemv

hmm, I only see F1 (help) F2 (language) and F4 (keyboard).
pressing F5 does nothing...

what am I missing??
this is an update from 11.4 to 12.1-factory some time ago (after beta-1).
any special tweeks needed to activate the F5 setup function ?


> - or add "init=/sbin/sysvinit" to kernel boot command

ACK, boots with sysvinit, and lots of fscks later: home shows up as before!
(no bug surprise, is it ?)
Comment 17 Frederic Crozat 2011-10-26 07:59:26 UTC
please test package from home:fcrozat:systemd / systemd
Comment 18 Harald Koenig 2011-10-26 09:49:11 UTC
(In reply to comment #17)
> please test package from home:fcrozat:systemd / systemd

please read my comment #5: 
I've already tested and reported that -- it did not help!


I can't see a new version of systemd there right now ?!?

[   ] systemd-37-268.2.x86_64.rpm                             24-Oct-2011 08:44  807K   Details
Comment 19 Frederic Crozat 2011-10-26 10:46:36 UTC
yes, but now, you have uninstalled open-iscsi which was breaking dependencies.
Comment 20 Harald Koenig 2011-10-26 12:09:03 UTC
(In reply to comment #19)
> yes, but now, you have uninstalled open-iscsi which was breaking dependencies.

only later.

first I only updated to your systemd and rebooted (#5).
result: not working (/home not mounted, emergency shell).

only then U removed open-iscsi (#10): still not working (but no cycle errors anymore).  but still no /home, systemd does not startup my 12.1 system.

right now I boot with sysvinit to be operational....


to be clear: your systemd does not work for me, neither with nor without open-iscsi!

what else shall I test, which data do you need ?
Comment 21 Frederic Crozat 2011-10-26 12:42:55 UTC
please reboot under systemd (using init=/sbin/systemd systemd.log_level=debug systemd.log_target=kmsg) and attach dmesg output (you will probably not be able to access /home when using systemd)
Comment 22 Harald Koenig 2011-10-26 13:13:18 UTC
Created attachment 458967 [details]
systemd debug output
Comment 23 Harald Koenig 2011-10-26 13:13:55 UTC
Created attachment 458968 [details]
screen dump after boot in emergency mode
Comment 24 Frederic Crozat 2011-10-26 13:25:40 UTC
one thing you can also try :

- commenting the tmpfs line in your fstab (just to be sure)

-when running under systemd:
cp /run/systemd/generator/cryptsetup*.service /etc/systemd/system

then, for cryptsetup\@*.service files (not sure how they are named on your
system) in /etc/systemd/system, add 
After=lvm.service

in the section [Unit]

and reboot (under systemd)
Comment 25 Frederic Crozat 2011-10-26 13:31:03 UTC
you forgot one parameter to kernel command line.

use :

systemd.log_level=debug systemd.log_target=kmsg

(but right now, I don't need it, I'm more interested in the test with the After=lvm.service line)

for the suggestion I gave above, the file name is probably cryptsetup\@cr_home.service
Comment 26 Harald Koenig 2011-10-26 13:51:22 UTC
Created attachment 458970 [details]
more debug output

sorry, didn't notice that 2nd kernel option...
Comment 27 Harald Koenig 2011-10-27 09:05:42 UTC
(In reply to comment #24)
> one thing you can also try :
> 
> - commenting the tmpfs line in your fstab (just to be sure)

ACK, you're right!  mount point /var/run/nscd did not exist anymore.
and after creating and rebooting, it's vanished again:-(

so: I've comment that fstab line and -- drum roll -- the system came up includung X11 and network!

BUT: /home still is not mounted.

I noticed that (at least now)  /dev/mapper/cr_home already exists after boot,
so only the "mount /home" does not work (or happen at wrong time) yet.

running "mount /home" manually works fine as expected...


> -when running under systemd:
> cp /run/systemd/generator/cryptsetup*.service /etc/systemd/system
> 
> then, for cryptsetup\@*.service files (not sure how they are named on your
> system) in /etc/systemd/system, add 
> After=lvm.service
> 
> in the section [Unit]
> 
> and reboot (under systemd)

so I tried that one -- but no change. 
/dev/mapper/cr_home exists but does not get mounted to /home yet...


I'll attach another dmesg output with debug logs...
Comment 28 Harald Koenig 2011-10-27 09:08:08 UTC
Created attachment 459112 [details]
dmesg with debug output

only the execution of 

    mount /home

is missing for perfection
Comment 29 Frederic Crozat 2011-10-27 14:28:27 UTC
until you have the fix for tmpfs, try replacing the last parameter for tmpfs line in /etc/fstab from 2 to 0 and test again.
Comment 30 Harald Koenig 2011-10-27 15:07:12 UTC
(In reply to comment #29)
> until you have the fix for tmpfs, try replacing the last parameter for tmpfs
> line in /etc/fstab from 2 to 0 and test again.

I've commented out that line, as it's not needed anymore (as /var/run is a tmpfs now anyway..., see comment #27)

FYI: I've commented out the SWAP line too, as that swap partition does not exist right now.  but the missing swap only caused some timeout at boot, it did not cause running into emerceny mode (and emergency loops).

so the only remaining real problem in this thread for me right now is the fact, that the /home does not get mounted after /dev/mapper/cr_home shows up (got unlocked by cryptsetup)...
Comment 31 Frederic Crozat 2011-10-27 15:16:19 UTC
please attach systemctl show home.mount output before you "manually" mount /home
Comment 32 Harald Koenig 2011-10-27 19:58:09 UTC
Created attachment 459226 [details]
before mount
Comment 33 Harald Koenig 2011-10-27 19:58:58 UTC
Created attachment 459227 [details]
after mount
Comment 34 Frederic Crozat 2011-10-31 16:12:12 UTC
found it : you have "noauto" specified for /home in your fstab : so systemd doesn't try to mount it at startup ...
Comment 35 Harald Koenig 2011-10-31 17:05:35 UTC
(In reply to comment #34)
> found it : you have "noauto" specified for /home in your fstab : so systemd
> doesn't try to mount it at startup ...

interesting!!  that's from yast2 when creating that setup many releases back (likely opensuse 11.1).

so I removed the "noauto" and did reboot -- but first again with sysvinit ;-) and surprise: without "noauto" runs into some timeout 


	<notice -- Oct 31 17:48:32.191688000> service boot.localfs start
	Waiting for /dev/mapper/cr_home .............................. timeout! 
	Checking file systems...
	fsck from util-linux 2.20
	root2: clean, 6789/1966080 files, 6220530/7864320 blocks
	...
	/dev on /11.4/dev type none (rw,bind)
	failedActivating crypto devices using /etc/crypttab ... 
	<notice -- Oct 31 17:49:10.687659000> service boot.localfs done

and only later the crypto stuff gets started and /home shows up:

	<notice -- Oct 31 17:49:10.687851000> service boot.crypto start
	Loading console font lat9w-16.psfu  -m trivial G0:loadable
	doneLoading keymap i386/qwerty/us.map.gz
	doneStart Unicode mode
	doneUnlocking cr_home (/dev/system/home)
	modprobe: FATAL: Error inserting padlock_sha (/lib/modules/3.1.0-rc9-1-desktop/kernel/drivers/crypto/padlock-sha.ko): No such device
	
	cr_home...done
	<notice -- Oct 31 17:50:01.665185000> service boot.crypto done


so there seems to be a good reason for the "noauto" -- at least for the sysvinit case...


now, next reboot with systemd (without "noauto") -- and /home/ got mounted as expected!


GREAT!!!  I'm glad to see/understand what's going on!
except for the sysvinit case  ;-))
Comment 36 Frederic Crozat 2011-11-02 10:55:35 UTC
so, not a systemd bug after all
Comment 37 Ludwig Nussel 2011-11-02 12:09:41 UTC
- enable boot.crypto-early
- replace 'noauto' with 'nofail'

*** This bug has been marked as a duplicate of bug 724113 ***