Bug 712300 - systemd: service startup order not blocking
Summary: systemd: service startup order not blocking
Status: RESOLVED FIXED
: 712028 (view as bug list)
Alias: None
Product: openSUSE 12.1
Classification: openSUSE
Component: Basesystem (show other bugs)
Version: Factory
Hardware: Other Other
: P5 - None : Major (vote)
Target Milestone: ---
Assignee: Frederic Crozat
QA Contact: E-mail List
URL:
Whiteboard:
Keywords:
Depends on:
Blocks: 696902
  Show dependency treegraph
 
Reported: 2011-08-15 18:04 UTC by Dominique Leuenberger
Modified: 2011-08-18 10:05 UTC (History)
5 users (show)

See Also:
Found By: Community User
Services Priority:
Business Priority:
Blocker: ---
Marketing QA Status: ---
IT Deployment: ---


Attachments
list of installed service files (4.96 KB, text/plain)
2011-08-15 20:54 UTC, Bruno Friedmann
Details
Graph systemd (456.73 KB, image/svg+xml)
2011-08-15 20:56 UTC, Bruno Friedmann
Details
/bin/systemd --test --system --log-level=debug output (321.30 KB, application/octet-stream)
2011-08-16 08:44 UTC, Andreas Jaeger
Details
/bin/systemd --test --system --log-level=debug output - after insserv -r boot.cycle (318.88 KB, application/octet-stream)
2011-08-16 08:45 UTC, Andreas Jaeger
Details
don't start NM under systemd (1.32 KB, patch)
2011-08-16 11:59 UTC, Frederic Crozat
Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Dominique Leuenberger 2011-08-15 18:04:41 UTC
Seems a vast of users is seeing this issue:

There are 'two' scenarios, this bug us about the '2nd one':
1) Boot takes 5 minutes (This is the 'known' NM_ONLINE_TIMEOUT)
2) Once NM_ONLINE_TIMEOUT is set to 0, the boot is 'fast' but it does not come up grapical.

At least those two services are missing:
NetworkManager.service
xdm.service

The issue for both is that they are started in parallel or before dbus is running.
(NM is 'tried' to be started from /etc/init.d/network) and xdm is a 'traditional' start script anyway.

As a result, the boot 'ends with a login' prompt.
Logging in and then
  systemctl start NetworkManager.service
  systemctl start xdm.service
brings up a fully functional Environment for me. (Perfectly suitable for me now as a workaround).
Comment 1 Bjørn Lie 2011-08-15 18:24:54 UTC
Try this.

chkconfig -f network off

systemctl enable NetworkManager.service


Reboot

btw systemd-analyze plot > filename.svg

is a great tool to see whats taking so long.
Comment 2 Bruno Friedmann 2011-08-15 19:37:43 UTC
Bjorn we agree that destroy totally boot with system V ? 
As mostly without -f I will loose 
chkconfig network off
insserv: FATAL: service network has to be enabled to use service apache
insserv: FATAL: service network has to be enabled to use service nfs
insserv: FATAL: service network has to be enabled to use service smtp
insserv: FATAL: service network has to be enabled to use service dnsmasq
insserv: FATAL: service network has to be enabled to use service portmap
insserv: FATAL: service network has to be enabled to use service smpppd
insserv: FATAL: service network has to be enabled to use service libvirt-guests
insserv: FATAL: service network has to be enabled to use service libvirtd
insserv: FATAL: service network has to be enabled to use service avahi
insserv: FATAL: service network has to be enabled to use service SuSEfirewall2_setup
insserv: FATAL: service network has to be enabled to use service network-remotefs
insserv: FATAL: service network has to be enabled to use service postgresql
insserv: FATAL: service network has to be enabled to use service bacula-fd
insserv: FATAL: service network has to be enabled to use service kerneloops
insserv: FATAL: service network has to be enabled to use service mysql
insserv: FATAL: service network has to be enabled to use service sshd
insserv: FATAL: service network has to be enabled to use service fam
insserv: exiting now!
/sbin/insserv failed, exit code 1
Comment 3 Bjørn Lie 2011-08-15 19:52:53 UTC
@ Bruno

Sure :-)

My bad, I wasn't aware that it's a goal to keep sysv as a possibility/fallback.
I assumed we were going for full switch to systemd.
Comment 4 Bruno Friedmann 2011-08-15 20:53:03 UTC
@Borjn no pb, if we can drop sysv.

Here's what I get whitout the full understanding (yet) of why.

Once I boot with systemd, all stop during long time before I'm dropped to a tty.
Then I realized dbus is not started at all. 
systemctl start dbus.service
systemctl start NetworkManager.service
systemctl start xdm.service
and I get a Xorg running, and a 80% kde 4.7 running (some daemons like keyboard shortcuts etc seems to be killed somewhere )

But I've one service apache2 start refuse absolutely to start 

Find in attachement a output of all service installed here 
Was a fresh install of factory 12.1 when systemd was at release 28 or 30
I didn't tweak anything concerning systemd and just have ulimit raised in /etc/sysconfig/apache2 (but this is working at 100% with sysV )
Comment 5 Bruno Friedmann 2011-08-15 20:54:04 UTC
Created attachment 445865 [details]
list of installed service files
Comment 6 Bruno Friedmann 2011-08-15 20:56:24 UTC
Created attachment 445866 [details]
Graph systemd

The graph of the boot
Comment 7 Bruno Friedmann 2011-08-15 20:57:21 UTC
dmesg | grep systemd
[    0.000000] Command line: init=/bin/systemd root=/dev/vgsys/lvsuse keyboard=fr-ch-latin1 resume=/dev/vgsys/lvswap lang=fr_CH keytable=us splash=verbose verbose elevator=cfq rootfstype=ext4 rootflags=data=writeback video.allow_duplicates=1 file_caps=1 nomodeset nomodset blacklist=nouveau,radeon reboot=pci vga=0x34d
[    0.000000] Kernel command line: init=/bin/systemd root=/dev/vgsys/lvsuse keyboard=fr-ch-latin1 resume=/dev/vgsys/lvswap lang=fr_CH keytable=us splash=verbose verbose elevator=cfq rootfstype=ext4 rootflags=data=writeback video.allow_duplicates=1 file_caps=1 nomodeset nomodset blacklist=nouveau,radeon reboot=pci vga=0x34d
[   26.445817] systemd[1]: systemd 33 running in system mode. (+PAM +LIBWRAP +AUDIT +SELINUX +SYSVINIT +LIBCRYPTSETUP; suse)
[   26.817224] systemd[1]: Set hostname to <c-3po.vellerat.ioda.net>.
[   27.350760] systemd[1]: [/etc/init.d/postfix:12] Failed to add LSB Provides name sendmail.service, ignoring: File exists
[   27.545982] systemd[1]: Cannot add dependency job for unit crypto.service, ignoring: Unit crypto.service is masked.
[   27.573333] systemd[1]: Found ordering cycle on NetworkManager.service/start
[   27.600177] systemd[1]: Walked on cycle path to syslog.target/start
[   27.626630] systemd[1]: Walked on cycle path to syslog.service/start
[   27.652494] systemd[1]: Walked on cycle path to network.target/start
[   27.677788] systemd[1]: Walked on cycle path to NetworkManager.service/start
[   27.677793] systemd[1]: Breaking ordering cycle by deleting job syslog.target/start
[   27.677814] systemd[1]: Found ordering cycle on basic.target/start
[   27.677818] systemd[1]: Walked on cycle path to sockets.target/start
[   27.677822] systemd[1]: Walked on cycle path to dbus.socket/start
[   27.677826] systemd[1]: Walked on cycle path to sysinit.target/start
[   27.677829] systemd[1]: Walked on cycle path to cycle.service/start
[   27.677832] systemd[1]: Walked on cycle path to localfs.service/start
[   27.677836] systemd[1]: Walked on cycle path to basic.target/start
[   27.677840] systemd[1]: Breaking ordering cycle by deleting job dbus.socket/start
[   27.677850] systemd[1]: Found ordering cycle on basic.target/start
[   27.677853] systemd[1]: Walked on cycle path to sysinit.target/start
[   27.677857] systemd[1]: Walked on cycle path to cycle.service/start
[   27.677861] systemd[1]: Walked on cycle path to localfs.service/start
[   27.677865] systemd[1]: Walked on cycle path to basic.target/start
[   27.677868] systemd[1]: Breaking ordering cycle by deleting job cycle.service/start
[   29.614050] systemd-fsck[572]: Root directory is writable, skipping check.
[   34.860754] systemd-fsck[900]: lvhome\xffffffc2\xffffffa0\xffffffa0: propre, 765823/37158912 fichiers, 56161077/148635648 blocs
[   35.094636] systemd-fsck[984]: lvsrv\xffffffc2\xffffffa0\xffffffa0: propre, 27483/4456448 fichiers, 7960529/17825792 blocs
[   36.552473] systemd-fsck[1112]: boot\xffffffc2\xffffffa0\xffffffa0: propre, 53/68272 fichiers, 98207/272372 blocs
[   54.446205] systemd[1]: network-remotefs.service: main process exited, code=exited, status=1
[  356.225956] systemd[1]: apache2.service operation timed out. Terminating.
[  356.294531] systemd[1]: Unit apache2.service entered failed state.
[  356.380574] systemd[1]: Startup finished in 26s 628ms 933us (kernel) + 5min 29s 693ms 331us (userspace) = 5min 56s 322ms 264us.
[  443.855711] systemd[1]: Cannot add dependency job for unit crypto.service, ignoring: Unit crypto.service is masked.
[  446.293184] systemd[1]: Cannot add dependency job for unit crypto.service, ignoring: Unit crypto.service is masked.
[  479.285386] systemd[1]: Cannot add dependency job for unit crypto.service, ignoring: Unit crypto.service is masked.
[  498.203261] systemd[1]: Cannot add dependency job for unit crypto.service, ignoring: Unit crypto.service is masked.
[  507.382488] systemd[1]: Cannot add dependency job for unit crypto.service, ignoring: Unit crypto.service is masked.
[  689.546560] systemd[1]: Cannot add dependency job for unit crypto.service, ignoring: Unit crypto.service is masked.
[  702.735145] systemd[1]: Cannot add dependency job for unit crypto.service, ignoring: Unit crypto.service is masked.
[  710.646325] dbus[3205]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.Avahi.service': Unit dbus-org.freedesktop.Avahi.service failed to load: No such file or directory. See system logs and 'systemctl status dbus-org.freedesktop.Avahi.service' for details.
[  798.050036] systemd[1]: apache2.service operation timed out. Terminating.
[  798.112586] systemd[1]: Unit apache2.service entered failed state.
[  899.779611] systemd[1]: Cannot add dependency job for unit crypto.service, ignoring: Unit crypto.service is masked.
[  942.076315] systemd[1]: Cannot add dependency job for unit crypto.service, ignoring: Unit crypto.service is masked.
[ 1094.203777] systemd[1]: rsyslog.service: main process exited, code=exited, status=1
[ 1094.231793] systemd[1]: Unit rsyslog.service entered failed state.
[ 1216.007032] systemd[1]: Cannot add dependency job for unit crypto.service, ignoring: Unit crypto.service is masked.
Comment 8 Andreas Jaeger 2011-08-16 08:29:25 UTC
Same problem here - but only on my 32-bit system that uses NetworkManager.
It works fine on my 64-bit x86-64 system without NetworkManager.

Both run factory.

I don't know what else is different that it only hits one of my systems.
Disabling NetworkManager did not help.

For me the cycle looks like:
Found ordering cycle on basic.target/start
Walked on cycle path to sockets.target/start
Walked on... dbus.socket/start
... sysinit.target/start
... cycle.service/start
... localfs.service/start
... basic.target.start
Breaking ordering cycle by deleting job dbus.socket/start
Found ordering cycle on basic.target/start
Walked on cycle path to sysinit.target/start
... cycle.service/start
... localfs.service/start
... basic.target.start
Breaking ordering cycle by deleting job cycle.service/start
Comment 9 Andreas Jaeger 2011-08-16 08:39:04 UTC
I looked further at the loop and run:
insserv -r boot.cycle

This fixed the problem for me.

Looking at the requires on my cycle, I'm not seeing the cycle :-(
basic.target has:
Requires=sysinit.target sockets.target
After=sysinit.target sockets.target

sysinit.target has:
Wants=local-fs.target swap.target
After=local-fs.target swap.target emergency.service emergency.target

/etc/init.d/boot.cycle has
# Required-Start:    boot.localfs
# Should-Start:      boot.loadmodules

The others have no dependency
Comment 10 Andreas Jaeger 2011-08-16 08:44:08 UTC
Created attachment 445920 [details]
/bin/systemd --test --system --log-level=debug output

I have now a complete log file with the cycle in it - with boot.cycle enabled.
Comment 11 Andreas Jaeger 2011-08-16 08:45:21 UTC
Created attachment 445921 [details]
/bin/systemd --test --system --log-level=debug output - after insserv -r boot.cycle

The debug output after running insserv -r boot.cycle does not contain cycles and looks sane to me.
Comment 12 Andreas Jaeger 2011-08-16 08:49:14 UTC
# ls  /etc/rc.d/rc3.d/S*
/etc/rc.d/rc3.d/S01acpid               /etc/rc.d/rc3.d/S04auditd            /etc/rc.d/rc3.d/S08sshd
/etc/rc.d/rc3.d/S01dbus                /etc/rc.d/rc3.d/S04rpcbind           /etc/rc.d/rc3.d/S09ntp
/etc/rc.d/rc3.d/S01earlysyslog         /etc/rc.d/rc3.d/S04splash_early      /etc/rc.d/rc3.d/S10cups
/etc/rc.d/rc3.d/S01fbset               /etc/rc.d/rc3.d/S05nfs               /etc/rc.d/rc3.d/S10nscd
/etc/rc.d/rc3.d/S01microcode.ctl       /etc/rc.d/rc3.d/S06cifs              /etc/rc.d/rc3.d/S10postfix
/etc/rc.d/rc3.d/S01purge-kernels       /etc/rc.d/rc3.d/S07kbd               /etc/rc.d/rc3.d/S10sbl
/etc/rc.d/rc3.d/S01random              /etc/rc.d/rc3.d/S08alsasound         /etc/rc.d/rc3.d/S10smpppd
/etc/rc.d/rc3.d/S01SuSEfirewall2_init  /etc/rc.d/rc3.d/S08bluez-coldplug    /etc/rc.d/rc3.d/S11cron
/etc/rc.d/rc3.d/S02haldaemon           /etc/rc.d/rc3.d/S08brld              /etc/rc.d/rc3.d/S11smartd
/etc/rc.d/rc3.d/S02network             /etc/rc.d/rc3.d/S08network-remotefs  /etc/rc.d/rc3.d/S12stoppreload
/etc/rc.d/rc3.d/S03syslog              /etc/rc.d/rc3.d/S08splash            /etc/rc.d/rc3.d/S12SuSEfirewall2_setup
Comment 13 Frederic Crozat 2011-08-16 11:58:47 UTC
for the network part, we have two issues :
- tell /etc/init.d/network to handle start NetworkManager when running under systemd (patch is done, pending review, I'll attach it)
- enable NetworkManager systemd .service on both fresh install and upgrade (the upgrade part is tricky, due to the way OBS changes %release, ideas welcome)

for the graphical interface not starting, it looks like bnc#707418
Comment 14 Frederic Crozat 2011-08-16 11:59:43 UTC
Created attachment 445952 [details]
don't start NM under systemd
Comment 15 Frederic Crozat 2011-08-16 14:51:46 UTC
after more digging, cycles are caused by :
- first cycle : syslog LSB service : we should probably replace it with rsyslog.service (which is disabled by default) 
- two other cycles : caused by /etc/insserv.conf parsing (which adds dependencies to current .services), more precisely $local_fs line. It shouldn't be a issue (since the two added dependencies are "ghost" entries) but it is causing the problem.
Comment 16 Frederic Crozat 2011-08-16 17:16:42 UTC
please test systemd from Base:System I just committed, it should fix localfs.service dependencies which were causing the various cycles.
Comment 17 Andreas Jaeger 2011-08-17 07:58:22 UTC
Thanks, the new systemd works for me. I pushed it to Factory now before more people run into it.
Comment 18 Frederic Crozat 2011-08-17 16:11:37 UTC
*** Bug 712028 has been marked as a duplicate of this bug. ***
Comment 19 Dominique Leuenberger 2011-08-17 16:40:11 UTC
(In reply to comment #16)
> please test systemd from Base:System I just committed, it should fix
> localfs.service dependencies which were causing the various cycles.

Same for me: the systemd version from Base:system addresses my issue and X is getting started up properly again. Login and Network were no issue.
Comment 20 Bruno Friedmann 2011-08-17 20:02:50 UTC
Same here, even without Base:System (I'm on factory)
systemd now work with the given solution

The only service that crash (didn't start) is apache2 
To have it working I need to do
cd /etc/init.d/
./apache2 start 

and then it goes up 
???
Comment 21 Andreas Jaeger 2011-08-18 07:21:42 UTC
Bruno, please file a separate bug for Apache.
Comment 22 Frederic Crozat 2011-08-18 10:05:09 UTC
closing as fixed