You are not logged in.

#1 2012-10-24 03:47:09

bhrgunatha
Member
Registered: 2009-12-16
Posts: 101

[SOLVED] systemd : services failing to start on boot

I have removed sysvinit completely as per the systemd wiki pages.
I don't usually re-boot very often so I'm not sure exactly when the problem started.
I only noticed this problem about 4 or 5 days ago.

But now whenever I reboot my machine 2 services fail consistently.
adsl.service
colord.service
They both start flawlessly once I can log in at a console.

I'm using kde and in the last couple of days, while trying to fix my problem, the kdm service has failed to start a couple of times too - saying there is no X server.

Before switching to systemd I never had any of these problems using the old rc.conf method. My DAEMONS array had the adsl service start after the network service.

I need some help and advice to find out what is causing the problem and how to fix it.

Last edited by bhrgunatha (2012-10-25 05:44:22)

Offline

#2 2012-10-24 05:52:43

Stebalien
Member
Registered: 2010-04-27
Posts: 1,237
Website

Re: [SOLVED] systemd : services failing to start on boot

Running 'systemctl status <service>' as root will give you the reason the service failed and the last few lines of log output from that service.


Steven [ web : git ]
GPG:  327B 20CE 21EA 68CF A7748675 7C92 3221 5899 410C
Do not email: honeypot@stebalien.com

Offline

#3 2012-10-24 06:11:06

bhrgunatha
Member
Registered: 2009-12-16
Posts: 101

Re: [SOLVED] systemd : services failing to start on boot

Running that on the two failed services gives:

adsl.service - ADSL Deamon
	  Loaded: loaded (/usr/lib/systemd/system/adsl.service; enabled)
	  Active: failed (Result: exit-code) since Wed, 24 Oct 2012 21:56:12 +0800; 1min 2s ago
	 Process: 391 ExecStart=/usr/sbin/pppoe-start (code=exited, status=1/FAILURE)
	  CGroup: name=systemd:/system/adsl.service

Oct 24 21:56:31 starch pppoe-start[391]: TIMED OUT
Oct 24 21:56:32 starch pppoe-start[391]: /usr/sbin/pppoe-start: line 193:   403 Terminated              $CONNECT "$@" > /dev/null 2>&1

colord.service - Manage, Install and Generate Color Profiles
	  Loaded: loaded (/usr/lib/systemd/system/colord.service; static)
	  Active: failed (Result: signal) since Wed, 24 Oct 2012 21:56:31 +0800; 43s ago
	 Process: 580 ExecStart=/usr/lib/colord/colord (code=killed, signal=ABRT)
	  CGroup: name=systemd:/system/colord.service

Oct 24 21:56:29 starch systemd[1]: Starting Manage, Install and Generate Color Profiles...
Oct 24 21:56:31 starch systemd[1]: Started Manage, Install and Generate Color Profiles.
Oct 24 21:56:32 starch colord[580]: **
Oct 24 21:56:32 starch colord[580]: Cd:ERROR:cd-main.c:205:cd_main_create_profile: assertion failed: (connection != NULL)

Offline

#4 2012-10-24 07:15:42

skunktrader
Member
From: Brisbane, Australia
Registered: 2010-02-14
Posts: 1,538

Re: [SOLVED] systemd : services failing to start on boot

I've had the same problem on a couple of machines here too.  Occasionally netcfg and alsa fail claiming that the hardware does not exist, but restarting the services always succeeds.  On another machine an nfs mount in fstab may sometimes fail (1 in 10 boots perhaps) but connects without any errors if restarted.

The problems occur randomly and not repeatable.  I suspect there is some bug buried deep within the guts of systemd that causes services to advertise themselves as ready prematurely.

Offline

#5 2012-10-24 08:50:26

bhrgunatha
Member
Registered: 2009-12-16
Posts: 101

Re: [SOLVED] systemd : services failing to start on boot

Well, I have the advantage then. Mine fail every time smile

Offline

#6 2012-10-24 15:24:07

Stebalien
Member
Registered: 2010-04-27
Posts: 1,237
Website

Re: [SOLVED] systemd : services failing to start on boot

skunktrader wrote:

I suspect there is some bug buried deep within the guts of systemd that causes services to advertise themselves as ready prematurely.

Not a bug; systemd can't magically determine when a service is ready. If a service needs to delay all dependencies from starting until after it is ready, it either has to use socket activation (implicit dependencies), sd_notify (tell systemd that it is ready), fork, or start listening on a designated dbus address.

As for colord, it appears to be a known bug (possibly a security vulnerability as the actual bug report is private): https://bugs.launchpad.net/ubuntu/+sour … ug/1041337

I don't know why the adsl service is failing (it might be because it is getting started before eth0 is available).


Steven [ web : git ]
GPG:  327B 20CE 21EA 68CF A7748675 7C92 3221 5899 410C
Do not email: honeypot@stebalien.com

Offline

#7 2012-10-25 01:32:34

bhrgunatha
Member
Registered: 2009-12-16
Posts: 101

Re: [SOLVED] systemd : services failing to start on boot

Thanks. That seems plausible. So I've been snooping at the journal.

journalctl -ab 
...
Oct 25 17:06:13 starch systemd[1]: Started Trigger Flushing of Journal to Persistent Storage.
Oct 25 17:06:14 starch systemd[1]: Started Recreate Volatile Files and Directories.
Oct 25 17:06:14 starch systemd[1]: Starting System Initialization.
Oct 25 17:06:14 starch systemd[1]: Reached target System Initialization.
Oct 25 17:06:14 starch systemd[1]: Starting CUPS Printing Service Sockets.
Oct 25 17:06:14 starch systemd[1]: Listening on CUPS Printing Service Sockets.
Oct 25 17:06:14 starch systemd[1]: Starting Console System Startup Logging...
Oct 25 17:06:14 starch systemd[1]: Starting Restore Sound Card State...
Oct 25 17:06:14 starch systemd[1]: Starting CUPS Printer Service Spool.
Oct 25 17:06:14 starch systemd[1]: Started CUPS Printer Service Spool.
Oct 25 17:06:14 starch systemd[1]: Starting D-Bus System Message Bus Socket.
Oct 25 17:06:16 starch ntpd[381]: ntpd 4.2.6p5@1.2349-o Tue Aug 21 15:06:24 UTC 2012 (1)
Oct 25 17:06:16 starch ntpd[413]: proto: precision = 0.156 usec
Oct 25 17:06:17 starch ntpd[413]: ntp_io: estimated max descriptors: 1024, initial socket boundary: 16
Oct 25 17:06:17 starch ntpd[413]: Listen and drop on 0 v4wildcard 0.0.0.0 UDP 123
Oct 25 17:06:18 starch ntpd[413]: Listen and drop on 1 v6wildcard :: UDP 123
Oct 25 17:06:18 starch ntpd[413]: Listen normally on 2 lo 127.0.0.1 UDP 123
Oct 25 17:06:18 starch ntpd[413]: Listen normally on 3 lo ::1 UDP 123
Oct 25 17:06:18 starch ntpd[413]: peers refreshed
Oct 25 17:06:18 starch ntpd[413]: Listening on routing socket on fd #20 for interface updates
Oct 25 17:06:18 starch dbus[384]: [system] Activating systemd to hand-off: service name='org.freedesktop.ColorManager' unit='colord.service'
Oct 25 17:06:18 starch dbus[384]: [system] Successfully activated service 'org.freedesktop.systemd1'
Oct 25 17:07:03 starch dbus[384]: [system] Successfully activated service 'org.freedesktop.ColorManager'
Oct 25 17:07:03 starch dbus[384]: [system] Activating via systemd: service name='org.freedesktop.ColorManager' unit='colord.service'
Oct 25 17:07:03 starch dbus[384]: [system] Successfully activated service 'org.freedesktop.ColorManager'
Oct 25 17:07:04 starch kernel: r8169 0000:02:00.0: eth0: link down
Oct 25 17:07:03 starch systemd[1]: Starting Manage, Install and Generate Color Profiles...
Oct 25 17:07:03 starch systemd[1]: Started Manage, Install and Generate Color Profiles.
Oct 25 17:07:03 starch systemd[1]: colord.service: main process exited, code=killed, status=6
Oct 25 17:07:03 starch systemd[1]: Unit colord.service entered failed state.
Oct 25 17:07:04 starch kernel: r8169 0000:02:00.0: eth0: link down
Oct 25 17:07:04 starch kernel: IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
Oct 25 17:07:04 starch kernel: PPP generic driver version 2.4.2
Oct 25 17:07:04 starch cupsd[380]: Unknown directive DefaultAuthType on line 26.
Oct 25 17:07:04 starch kernel: r8169 0000:02:00.0: eth0: link up
Oct 25 17:07:04 starch kernel: IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
Oct 25 17:07:04 starch pppoe-start[382]: TIMED OUT
Oct 25 17:07:04 starch kernel: NET: Registered protocol family 24
Oct 25 17:07:04 starch pppoe-start[382]: /usr/sbin/pppoe-start: line 193:   394 Terminated              $CONNECT "$@" > /dev/null 2>&1
...

That seems to confirm your theory.

eth0 link is not up when attempting to start colord and adsl

So the $64,000 question:

How do I defer them until eth0 is ready?
Or how can I force the eth0 link to be up before colord or adsl try to use it?

Last edited by bhrgunatha (2012-10-25 01:33:36)

Offline

#8 2012-10-25 05:42:58

bhrgunatha
Member
Registered: 2009-12-16
Posts: 101

Re: [SOLVED] systemd : services failing to start on boot

OK I've found a resolution to my problem.
I've disabled the adsl.service and simply used a single netcfg configuration for my pppoe provider.

Here are the steps I took:

# I didn't even have netcfg installed
pacman -S netcfg
# netcfg has a sample pppoe config file
cp  /etc/network.d/examples/pppoe /etc/network.d/mynetwork
# edit the new configuration file to enter my isp's user name and password
nano /etc/network.d/mynetwork
# edit the new configuration file to enter my isp's user name and password
systemctl enable netcfg@mynetwork.service

Now both adsl.service AND colord.service start at boot time!

Finally now my pppoe connection is handled by netcfg I don't need the adsl.service any more, so:

systemctl disable adsl.service

The main issue now is startup is slow:

systemd-analyze blame
 30191ms netcfg@mynetwork.service
 22570ms colord.service
  5485ms systemd-logind.service
  3501ms systemd-vconsole-setup.service
  2273ms systemd-remount-fs.service
  2080ms colord-sane.service
  1878ms dev-mqueue.mount
  1819ms dev-hugepages.mount
  1797ms sys-kernel-debug.mount
  1774ms systemd-modules-load.service
   883ms systemd-udev-trigger.service
   796ms media-win.mount
   751ms systemd-udevd.service
   573ms upower.service
   554ms dev-sda6.swap
   492ms console-kit-daemon.service
   439ms systemd-tmpfiles-setup.service
   426ms console-kit-log-system-start.service
   296ms systemd-user-sessions.service
   255ms ntpd.service
   142ms systemd-sysctl.service
    80ms media-terrabak.mount
    76ms udisks.service
    10ms tmp.mount
     0ms sys-fs-fuse-connections.mount

30s to connect my modem during boot?
If I try to re-connect it takes about 2 seconds - which is what I'd expect.

I think I will mark this as solved and try to work out why the hell my networking is taking so long to become active.

Offline

#9 2012-10-25 05:45:37

Stebalien
Member
Registered: 2010-04-27
Posts: 1,237
Website

Re: [SOLVED] systemd : services failing to start on boot

bhrgunatha wrote:

OK I've found a resolution to my problem.
I've disabled the adsl.service and simply used a single netcfg configuration for my pppoe provider.

Here are the steps I took:

# I didn't even have netcfg installed
pacman -S netcfg
# netcfg has a sample pppoe config file
cp  /etc/network.d/examples/pppoe /etc/network.d/mynetwork
# edit the new configuration file to enter my isp's user name and password
nano /etc/network.d/mynetwork
# edit the new configuration file to enter my isp's user name and password
systemctl enable netcfg@mynetwork.service

Now both adsl.service AND colord.service start at boot time!

Finally now my pppoe connection is handled by netcfg I don't need the adsl.service any more, so:

systemctl disable adsl.service

The main issue now is startup is slow:

systemd-analyze blame
 30191ms netcfg@mynetwork.service
 22570ms colord.service
  5485ms systemd-logind.service
  3501ms systemd-vconsole-setup.service
  2273ms systemd-remount-fs.service
  2080ms colord-sane.service
  1878ms dev-mqueue.mount
  1819ms dev-hugepages.mount
  1797ms sys-kernel-debug.mount
  1774ms systemd-modules-load.service
   883ms systemd-udev-trigger.service
   796ms media-win.mount
   751ms systemd-udevd.service
   573ms upower.service
   554ms dev-sda6.swap
   492ms console-kit-daemon.service
   439ms systemd-tmpfiles-setup.service
   426ms console-kit-log-system-start.service
   296ms systemd-user-sessions.service
   255ms ntpd.service
   142ms systemd-sysctl.service
    80ms media-terrabak.mount
    76ms udisks.service
    10ms tmp.mount
     0ms sys-fs-fuse-connections.mount

30s to connect my modem during boot?
If I try to re-connect it takes about 2 seconds - which is what I'd expect.

I think I will mark this as solved and try to work out why the hell my networking is taking so long to become active.

Post the plot produced by 'systemd-analyze plot'. Quite a few of those services are taking much longer than they should.


Steven [ web : git ]
GPG:  327B 20CE 21EA 68CF A7748675 7C92 3221 5899 410C
Do not email: honeypot@stebalien.com

Offline

#10 2012-10-25 06:14:31

bhrgunatha
Member
Registered: 2009-12-16
Posts: 101

Re: [SOLVED] systemd : services failing to start on boot

I agree sad

SVG on dropbox

I converted it to png but it is massive   (500KB about 5000x1000)

Offline

#11 2012-10-25 06:51:45

Stebalien
Member
Registered: 2010-04-27
Posts: 1,237
Website

Re: [SOLVED] systemd : services failing to start on boot

Instead of mounting things like /media/win etc., automount them (see the wiki). Your main problem is that you have a very slow disk. Also, colord should not be taking that long to start up; you should look through your journal for obvious delays.


Steven [ web : git ]
GPG:  327B 20CE 21EA 68CF A7748675 7C92 3221 5899 410C
Do not email: honeypot@stebalien.com

Offline

#12 2012-10-26 10:37:45

skunktrader
Member
From: Brisbane, Australia
Registered: 2010-02-14
Posts: 1,538

Re: [SOLVED] systemd : services failing to start on boot

It seems that the problem I experienced may actually be a bug and is currently being addressed https://mailman.archlinux.org/pipermail … 03331.html

Last edited by skunktrader (2012-10-26 10:59:45)

Offline

Board footer

Powered by FluxBB