Can't open PID file /run/ksmbd.lock (yet?)

[martinbu]

Does everyone else noticed this error message? I am using the most recent version of ksmbd-tools 3.4.9

ksmbd.service: Can't open PID file /run/ksmbd.lock (yet?) after start: Operation not permitted

I found an issue on the systemd github page: systemd/systemd#16636
But as explained there, it seems to be an application issue not a systemd problem.

[atheik]

@martinbu,

Did you get your ksmbd.service from upstream or from the person who packaged ksmbd-tools for your distribution?
If the former, then what systemd version do you have and how can I reproduce this?

[martinbu]

I am on Debian 11.7 with systemd version 247 (systemd 247 (247.3-7+deb11u2).
I compiled the ksmbd-tools from source, so the upstream version is used.

The "Error" is only shown if the service is restarted. (systemctl restart ksmbd.service - or stop and later on start it again). Everything is fine in the case of a cold start.

systemd[1]: Stopping ksmbd userspace daemon...
ksmbd[386]: [ksmbd-worker/386]: INFO: Worker received signal 15 (Terminated)
ksmbd.control[691]: [ksmbd.control/691]: INFO: Terminated ksmbd.mountd
ksmbd.control[691]: [ksmbd.control/691]: INFO: Killed ksmbd
systemd[1]: ksmbd.service: Succeeded.
systemd[1]: Stopped ksmbd userspace daemon.
systemd[1]: Starting ksmbd userspace daemon...
systemd[1]: ksmbd.service: Can't open PID file /run/ksmbd.lock (yet?) after start: Operation not permitted
systemd[1]: Started ksmbd userspace daemon.

And the content of the service file

[Unit]
Description=ksmbd userspace daemon
Requires=modprobe@ksmbd.service
Wants=network-online.target
After=modprobe@ksmbd.service network.target network-online.target

[Service]
Type=forking
PIDFile=/run/ksmbd.lock
ExecStart=/usr/local/sbin/ksmbd.mountd
ExecReload=/usr/local/sbin/ksmbd.control --reload
ExecStop=/usr/local/sbin/ksmbd.control --shutdown

[Install]
WantedBy=multi-user.target

[atheik]

@martinbu,

Reproduced this on Debian 11.7 as described.

A high system load seems to be a prerequisite:

( while :; do :; done ) &
( while :; do :; done ) &
( while :; do :; done ) &
( while :; do :; done ) &
# repeat as needed

systemctl restart ksmbd

kill $(jobs -p)

[atheik]

On systemd 254, with high system load, the PID file message seems more intermittent and is ENOENT instead of EPERM:

2023-08-25T14:58:55.030200+0300 pohjola systemd[1]: Starting ksmbd userspace daemon...
2023-08-25T14:58:55.032143+0300 pohjola systemd[1]: ksmbd.service: Can't open PID file /run/ksmbd.lock (yet?) after start: No such file or directory
2023-08-25T14:58:55.035302+0300 pohjola systemd[1]: Started ksmbd userspace daemon.

[atheik]

@martinbu,

If systemd cannot yet open the PID file, it will retry after a delay.
As per the log you posted, I assume the retry succeeded since the Started ... . message follows.
Did seeing the PID file message prompt this issue, or was there noticeable delay (or some other issue) when restarting?

If the latter, then how long is the delay between systemd failing to open the PID file and it succeeding?
You can check the timestamps likes this:

journalctl -o short-iso-precise -eu ksmbd

Thank you for the report. This is likely a ksmbd-tools bug caused by racyness in the creation of the PID file.

[martinbu]

You are right. The pid file can be found at /run/ksmbd.lock and everything is working fine after a restarting of the service as I can tell. Just the message has irritated me and I want to ask here.

You also wrote that a high system load is a prerequisite: I can also confirm that, my system is an embedded system with only a single core and quite a high system load.

Here are the logs with precise timestamps:

2023-08-28T08:15:43.355371+0000 systemd[1]: Stopping ksmbd userspace daemon...
2023-08-28T08:15:43.442555+0000 ksmbd[482]: [ksmbd-worker/482]: INFO: Worker received signal 15 (Terminated)
2023-08-28T08:15:43.491784+0000 ksmbd.control[696]: [ksmbd.control/696]: INFO: Terminated ksmbd.mountd
2023-08-28T08:15:43.491784+0000 ksmbd.control[696]: [ksmbd.control/696]: INFO: Killed ksmbd
2023-08-28T08:15:43.505745+0000 systemd[1]: ksmbd.service: Succeeded.
2023-08-28T08:15:43.530896+0000 systemd[1]: Stopped ksmbd userspace daemon.
2023-08-28T08:15:43.870167+0000 systemd[1]: Starting ksmbd userspace daemon...
2023-08-28T08:15:43.939098+0000 systemd[1]: ksmbd.service: Can't open PID file /run/ksmbd.lock (yet?) after start: Operation not permitted
2023-08-28T08:15:43.995245+0000 systemd[1]: Started ksmbd userspace daemon.

So the delay is very short and not an issue at all.

[atheik]

@martinbu,

This should now be fixed in the master branch (commit 7376c82). Thank you again for reporting this issue.