Bug#850855: [rtkit] rtkit daemon fails to start

[Bogdan Vatra]

Package: rtkit
Version: 0.11-4
Severity: important

--- Please enter the report below this line. ---

This bug is pretty annoying because it makes pulseaudio unusable (see
#850806).

Here are the logs:
bogdan@zmeu:~$ sudo systemctl status rtkit-daemon.service
● rtkit-daemon.service - RealtimeKit Scheduling Policy Service
Loaded: loaded (/lib/systemd/system/rtkit-daemon.service; disabled; vendor
preset: enabled)
Active: failed (Result: exit-code) since Tue 2017-01-10 20:54:59 EET; 5min
ago
Main PID: 17917 (code=exited, status=203/EXEC)

ian 10 20:54:59 zmeu systemd[1]: Starting RealtimeKit Scheduling Policy
Service...
ian 10 20:54:59 zmeu systemd[1]: rtkit-daemon.service: Main process exited,
code=exited, status=203/EXEC
ian 10 20:54:59 zmeu systemd[1]: Failed to start RealtimeKit Scheduling Policy
Service.
ian 10 20:54:59 zmeu systemd[1]: rtkit-daemon.service: Unit entered failed
state.
ian 10 20:54:59 zmeu systemd[1]: rtkit-daemon.service: Failed with result
'exit-code'.
bogdan@zmeu:~$ sudo systemctl start rtkit-daemon.service
Job for rtkit-daemon.service failed because the control process exited with
error code.
See "systemctl status rtkit-daemon.service" and "journalctl -xe" for details.
bogdan@zmeu:~$ sudo systemctl status rtkit-daemon.service
● rtkit-daemon.service - RealtimeKit Scheduling Policy Service
Loaded: loaded (/lib/systemd/system/rtkit-daemon.service; disabled; vendor
preset: enabled)
Active: failed (Result: exit-code) since Tue 2017-01-10 21:00:32 EET; 10s
ago
Process: 19342 ExecStart=/usr/lib/rtkit/rtkit-daemon (code=exited, status=1/
FAILURE)
Main PID: 19342 (code=exited, status=1/FAILURE)

ian 10 21:00:32 zmeu systemd[1]: Starting RealtimeKit Scheduling Policy
Service...
ian 10 21:00:32 zmeu systemd[1]: rtkit-daemon.service: Main process exited,
code=exited, status=1/FAILURE
ian 10 21:00:32 zmeu systemd[1]: Failed to start RealtimeKit Scheduling Policy
Service.
ian 10 21:00:32 zmeu systemd[1]: rtkit-daemon.service: Unit entered failed
state.
ian 10 21:00:32 zmeu systemd[1]: rtkit-daemon.service: Failed with result
'exit-code'.
bogdan@zmeu:~$ sudo journalctl -xe
ian 10 21:00:16 zmeu systemd[1]: Reloading.
ian 10 21:00:16 zmeu systemd[1]: apt-daily.timer: Adding 5h 21min 32.698921s
random time.
ian 10 21:00:16 zmeu sudo[19309]: pam_unix(sudo:session): session closed for
user root
ian 10 21:00:23 zmeu sudo[19328]: bogdan : TTY=pts/10 ; PWD=/home/bogdan ;
USER=root ; COMMAND=/bin/systemctl status rtkit-daemon.service
ian 10 21:00:23 zmeu sudo[19328]: pam_unix(sudo:session): session opened for
user root by bogdan(uid=0)
ian 10 21:00:23 zmeu sudo[19328]: pam_unix(sudo:session): session closed for
user root
ian 10 21:00:27 zmeu sudo[19331]: bogdan : TTY=pts/10 ; PWD=/home/bogdan ;
USER=root ; COMMAND=/bin/systemctl stop rtkit-daemon.service
ian 10 21:00:27 zmeu sudo[19331]: pam_unix(sudo:session): session opened for
user root by bogdan(uid=0)
ian 10 21:00:27 zmeu sudo[19331]: pam_unix(sudo:session): session closed for
user root
ian 10 21:00:28 zmeu sudo[19334]: bogdan : TTY=pts/10 ; PWD=/home/bogdan ;
USER=root ; COMMAND=/bin/systemctl status rtkit-daemon.service
ian 10 21:00:28 zmeu sudo[19334]: pam_unix(sudo:session): session opened for
user root by bogdan(uid=0)
ian 10 21:00:28 zmeu sudo[19334]: pam_unix(sudo:session): session closed for
user root
ian 10 21:00:32 zmeu sudo[19339]: bogdan : TTY=pts/10 ; PWD=/home/bogdan ;
USER=root ; COMMAND=/bin/systemctl start rtkit-daemon.service
ian 10 21:00:32 zmeu sudo[19339]: pam_unix(sudo:session): session opened for
user root by bogdan(uid=0)
ian 10 21:00:32 zmeu systemd[1]: Starting RealtimeKit Scheduling Policy
Service...
-- Subject: Unit rtkit-daemon.service has begun start-up
-- Defined-By: systemd
-- Support: https://www.debian.org/support
--
-- Unit rtkit-daemon.service has begun starting up.
ian 10 21:00:32 zmeu rtkit-daemon[19342]: Failed to connect to system bus:
Failed to connect to socket /var/run/dbus/system_bus_socket: No su
ian 10 21:00:32 zmeu rtkit-daemon[19342]: Demoting known real-time threads.
ian 10 21:00:32 zmeu rtkit-daemon[19342]: Demoted 0 threads.
ian 10 21:00:32 zmeu systemd[1]: rtkit-daemon.service: Main process exited,
code=exited, status=1/FAILURE
ian 10 21:00:32 zmeu systemd[1]: Failed to start RealtimeKit Scheduling Policy
Service.
-- Subject: Unit rtkit-daemon.service has failed
-- Defined-By: systemd
-- Support: https://www.debian.org/support
--
-- Unit rtkit-daemon.service has failed.
--
-- The result is failed.
ian 10 21:00:32 zmeu systemd[1]: rtkit-daemon.service: Unit entered failed
state.
ian 10 21:00:32 zmeu systemd[1]: rtkit-daemon.service: Failed with result
'exit-code'.
ian 10 21:00:32 zmeu sudo[19339]: pam_unix(sudo:session): session closed for
user root
ian 10 21:00:43 zmeu sudo[19348]: bogdan : TTY=pts/10 ; PWD=/home/bogdan ;
USER=root ; COMMAND=/bin/systemctl status rtkit-daemon.service
ian 10 21:00:43 zmeu sudo[19348]: pam_unix(sudo:session): session opened for
user root by bogdan(uid=0)
ian 10 21:00:43 zmeu sudo[19348]: pam_unix(sudo:session): session closed for
user root
ian 10 21:00:52 zmeu sudo[19351]: bogdan : TTY=pts/10 ; PWD=/home/bogdan ;
USER=root ; COMMAND=/bin/journalctl -xe
ian 10 21:00:52 zmeu sudo[19351]: pam_unix(sudo:session): session opened for
user root by bogdan(uid=0)


--- System information. ---
Architecture:
Kernel: Linux 4.8.0-2-amd64

Debian Release: stretch/sid
500 unstable-debug deb.debian.org
500 unstable ftp.debian.org
500 stable repo.skype.com
500 stable dl.google.com

--- Package information. ---
Depends (Version) | Installed
===========================-+-============
adduser | 3.115
libc6 (>= 2.8) |
libcap2 (>= 1:2.10) |
libdbus-1-3 (>= 1.9.14) |


Recommends (Version) | Installed
==========================-+-===========
dbus | 1.10.14-1
policykit-1 | 0.105-17


Package's Suggests field is empty.

[Felipe Sateler]

Hi,

On 10 January 2017 at 16:05, Bogdan Vatra <bogdan...@kdab.com> wrote:
> Package: rtkit
> Version: 0.11-4
> Severity: important
>
> --- Please enter the report below this line. ---
>
> This bug is pretty annoying because it makes pulseaudio unusable (see
> #850806).
>
> Here are the logs:

<snip>

> -- Unit rtkit-daemon.service has begun starting up.
> ian 10 21:00:32 zmeu rtkit-daemon[19342]: Failed to connect to system bus:
> Failed to connect to socket /var/run/dbus/system_bus_socket: No su

This suggests that dbus is not running. Could that be the case? Do
other dbus-interacting apps misbehave?

--

Saludos,
Felipe Sateler

[Bogdan Vatra]

I think that's a wrong message ... because :

$ ls -l /var/run/dbus/system_bus_socket
srw-rw-rw- 1 root root 0 ian 10 09:42 /var/run/dbus/system_bus_socket

That file exists and dbus works fine (all my KDE/Qt apps works ok).

BogDan.

[Bogdan Vatra]

If I manually run "/usr/lib/rtkit/rtkit-daemon" it works just fine...
The only problem is when I start it with "systemctl start rtkit-
daemon.service".
I strace it and from the log it seems it succeeds to open dbus socket:
[...]
connect(3, {sa_family=AF_UNIX, sun_path="/var/run/dbus/system_bus_socket"},
33) = 0
getsockopt(3, SOL_SOCKET, SO_PEERCRED, {pid=1, uid=0, gid=0}, [12]) = 0
fstat(3, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
getsockopt(3, SOL_SOCKET, SO_ACCEPTCONN, [0], [4]) = 0
getsockname(3, {sa_family=AF_UNIX}, [128->2]) = 0
geteuid() = 1000
sendmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\0AUTH EXTERNAL
", iov_len=15}, {iov_base="31303030", iov_len=8}, {iov_base="\r
\nNEGOTIATE_UNIX_FD\r\nBEGIN\r\n", iov_len=28}], msg_iovlen=3,
msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 51
[...]

BogDan.

[Felipe Sateler]

Control: tags -1 moreinfo unreproducible

Weird. Could you repeat the same with the daemon as started by systemd?

Use `systemctl edit --full rtkit-daemon` to edit the ExecStart line.

--

Saludos,
Felipe Sateler

[Bogdan Vatra]

It is the same thing ... :
[...]
ExecStart=/usr/lib/rtkit/rtkit-daemon
[...]
Actually I was inspired from that file to exec "/usr/lib/rtkit/rtkit-daemon"
manually :).

It there any way to debug it ?

[Felipe Sateler]

Sorry, I was not clear. I meant stracing the daemon.

--

Saludos,
Felipe Sateler

[Bogdan Vatra]

Attached the log.

[Felipe Sateler]

Hmm. I guess it's not my day, I can't explain myself :(

Please run the rtkit-daemon under strace, with systemd: edit the
systemd service like so:

ExecStart=/usr/bin/strace -o /tmp/strace.log -ff /usr/lib/rtkit/rtkit-daemon

then do a `systemctl daemon-reload` and a restart of the rtkit-daemon.
Then please attach the /tmp/strace.log.$PID file.



--

Saludos,
Felipe Sateler

[Bogdan Vatra]

Ah, sorry probably is me not you.
I edit as you requested but there is not /tmp/strace.log file, this is the
commands I used:

bogdan@zmeu:~$ sudo systemctl daemon-reload

bogdan@zmeu:~$ sudo systemctl start rtkit-daemon

Job for rtkit-daemon.service failed because the control process exited with
error code.
See "systemctl status rtkit-daemon.service" and "journalctl -xe" for details.

bogdan@zmeu:~$ systemctl status rtkit-daemon.service

● rtkit-daemon.service - RealtimeKit Scheduling Policy Service

Loaded: loaded (/etc/systemd/system/rtkit-daemon.service; disabled; vendor
preset: enabled)
Active: failed (Result: exit-code) since Wed 2017-01-11 18:42:42 EET; 6s
ago
Process: 26573 ExecStart=/usr/bin/strace -o /tmp/strace.log -ff /usr/lib/
rtkit/rtkit-daemon (code=exited, status=1/FAILURE)
Main PID: 26573 (code=exited, status=1/FAILURE)



What "Loaded: loaded (/etc/systemd/system/rtkit-daemon.service; disabled;
vendor preset: enabled)" *disabled means in the log?

BogDan.

[Bogdan Vatra]

Hi,

I have an update, some time ago (~1year) I run out of space on my system
partition and I decide to move /var folder to another partition and symlink it
back to / partition. Today I just moved back my var folder and rtkit daemon
started to work ... :)

Cheers,
BogDan.

[Felipe Sateler]

Control: tags -1 - unreproducible moreinfo
Control: reassign -1 systemd
Control: affects -1 rtkit
Control: retitle -1 Units with PrivateTmp fail when /var is a symlink
Control: severity -1 normal

This is a bug in systemd. A related issue is
https://github.com/systemd/systemd/issues/3867 , but that is
supposedly fixed in 232. BogDan, do you have version 232 installed? It
may be that the issue is not fully fixed yet.

--

Saludos,
Felipe Sateler

[Bogdan Vatra]

I have whatever is in debian sid (which is 232-10).
As I said, moving back var folder fixed the problem for me ;-). If you want to
test it I can tell you how to reproduce it:
- you'll need at least 2 partitions one for / and one for some data.
- install everything (but /home) into a single partition.
- mount the other partition to e.g. /mnt/sdb1
- boot a live linux
- move you /var folder to another partition into some folder (e.g.) /mnt/
sdb1/folder/var
- symlink it to /var

BogDan.

[Michael Biebl]

On Fri, 20 Jan 2017 11:38:54 -0300 Felipe Sateler <fsat...@debian.org>
wrote:

If /var is a relative symlink to say mnt/var, it seems to work fine.
If /var is an absolute symlink to /mnt/var, rtkit-daemon fails to start
(complaining about /var/run/dbus/system_bus_socket not being available).
Tested with 232-18.

That all said, I'm not sure if supporting such a setup is actually worth it.
If you need to move /var to a separate location, ideally you make it a
separate mount point. If that is not possible, I would suggest you bind
mount the directory. This works fine.

Felipe, do you think this is worth investigating and spending time on?


--
Why is it that all of the instruments seeking intelligent life in the
universe are pointed away from Earth?

[Felipe Sateler]

If this only affects PrivateTmp when /var is a symlink, I agree it is
a corner case not worth spending much time on. My guess was that this
would be a bug in a more common part of the code, and that it may
affect other mount-related settings (RootDirectory=,
WorkingDirectory=). I haven't been able to cause similar errors with
those settings though.


--

Saludos,
Felipe Sateler

[Michael Biebl]

Am 06.03.2017 um 14:03 schrieb Felipe Sateler:
> If this only affects PrivateTmp when /var is a symlink, I agree it is
> a corner case not worth spending much time on. My guess was that this
> would be a bug in a more common part of the code, and that it may
> affect other mount-related settings (RootDirectory=,
> WorkingDirectory=). I haven't been able to cause similar errors with
> those settings though.

Fwiw, I haven't tested other settings like RootDirectory.

What I noticed is that if /var is a symlink, services like
systemd-random-seed.service failed to start during boot.

I assume RequiresMountsFor=/var/lib/systemd/random-seed will not work
properly if /var is a symlink.

Using a bind mount I had a clean boot and shutdown (no failed services
or errors in the journal)

[Michael Biebl]

Control: tags -1 + fixed-upstream

Should be fixed by https://github.com/systemd/systemd/pull/8708 which
will be part of v239.