Openhab.service: Failed to locate executable /usr/bin/rm: No such file or directory

jpalo · August 30, 2023, 12:16pm

Tried to update to 4.1 milestone to get few fixes, but at the beginning of the update process, it failed when restarting OH.

2023-08-30_17:05:53_EEST [openHABian] Restarting openHAB service to play it safe...
$ systemctl restart openhab.service
Job for openhab.service failed because the control process exited with error code.
See "systemctl status openhab.service" and "journalctl -xeu openhab.service" for details.
FAILED (restart service)

I post it here as I dont think it is a upgrade issue, just cannot figure out what is that /usr/bin/rm that has suddenly gone missing. Any idea what’s going on?

Platform information:
- Hardware: RasPi4
- OS: Bullseye
- Java Runtime Environment: 17
- openHAB version: 4.0.2

Aug 30 15:08:37 openhab systemd[1]: openhab.service: Scheduled restart job, restart counter is at 312.
Aug 30 15:08:37 openhab systemd[1]: Stopped openhab.service - openHAB - empowering the smart home.
Aug 30 15:08:37 openhab systemd[1]: Starting openhab.service - openHAB - empowering the smart home...
Aug 30 15:08:37 openhab systemd[14340]: openhab.service: Failed to locate executable /usr/bin/rm: No such file or directory
Aug 30 15:08:37 openhab systemd[14340]: openhab.service: Failed at step EXEC spawning /usr/bin/rm: No such file or directory
Aug 30 15:08:37 openhab systemd[1]: openhab.service: Control process exited, code=exited, status=203/EXEC
Aug 30 15:08:37 openhab systemd[1]: openhab.service: Failed with result 'exit-code'.
Aug 30 15:08:37 openhab systemd[1]: Failed to start openhab.service - openHAB - empowering the smart home.
Aug 30 15:08:42 openhab systemd[1]: openhab.service: Scheduled restart job, restart counter is at 313.
Aug 30 15:08:42 openhab systemd[1]: Stopped openhab.service - openHAB - empowering the smart home.
Aug 30 15:08:42 openhab systemd[1]: Starting openhab.service - openHAB - empowering the smart home...
Aug 30 15:08:42 openhab systemd[14354]: openhab.service: Failed to locate executable /usr/bin/rm: No such file or directory
Aug 30 15:08:42 openhab systemd[14354]: openhab.service: Failed at step EXEC spawning /usr/bin/rm: No such file or directory
Aug 30 15:08:42 openhab systemd[1]: openhab.service: Control process exited, code=exited, status=203/EXEC
Aug 30 15:08:42 openhab systemd[1]: openhab.service: Failed with result 'exit-code'.
Aug 30 15:08:42 openhab systemd[1]: Failed to start openhab.service - openHAB - empowering the smart home.

Tried to create rm symlink to that location, but then it just compained of too many nested symlinks.

As the opehab.service is attempting to start karaf, I tried to open the console, but it is not starting either:

openhabian@openhab:~ $ openhab-cli console -v -l 4

395 [main] DEBUG org.apache.sshd.common.util.security.SecurityUtils - register([BC, true, false]) not registered - enabled=null, supported={}
398 [main] DEBUG org.apache.sshd.common.util.security.SecurityUtils - register([EdDSA, true, false]) not registered - enabled=null, supported={}
Logging in as openhab
823 [main] TRACE org.apache.sshd.client.SshClient - addSessionListener(SshClient[15d943d])[org.apache.sshd.common.session.helpers.SessionTimeoutListener@14948e4] registered
825 [main] TRACE org.apache.sshd.common.util.threads.SshdThreadFactory - newThread(java.lang.ThreadGroup[name=main,maxpri=10])[sshd-SshClient[15d943d]-timer-thread-1] runnable=java.util.concurrent.ThreadPoolExecutor$Worker@1190526[State = -1, empty queue]
832 [main] INFO org.apache.sshd.common.io.DefaultIoServiceFactoryFactory - No detected/configured IoServiceFactoryFactory; using Nio2ServiceFactoryFactory
853 [main] TRACE org.apache.sshd.common.io.nio2.Nio2Connector - Creating Nio2Connector
854 [main] DEBUG org.apache.sshd.client.config.hosts.DefaultConfigFileHostEntryResolver - resolveEffectiveHost([openhab, 127.0.0.1, 8101, null, null]@null:{}/{}) => {}
855 [main] DEBUG org.apache.sshd.client.SshClient - connect([openhab, 127.0.0.1, 8101]@null:{}) no overrides
874 [main] DEBUG org.apache.sshd.common.io.nio2.Nio2Connector - Connecting to /127.0.0.1:8101
886 [main] DEBUG org.apache.sshd.common.io.nio2.Nio2Connector - setOption([SO_REUSEADDR, true, Property[socket-reuseaddr](Boolean]])[null] from property={}
890 [Thread-0] TRACE org.apache.sshd.common.util.threads.SshdThreadFactory - newThread(java.lang.ThreadGroup[name=main,maxpri=10])[sshd-SshClient[15d943d]-nio2-thread-1] runnable=java.util.concurrent.ThreadPoolExecutor$Worker@1d628bc[State = -1, empty queue]
896 [sshd-SshClient[15d943d]-nio2-thread-1] DEBUG org.apache.sshd.client.SshClient - operationComplete([openhab, /127.0.0.1:8101, ConnectException, Connection refused]@null) failed ({}): {}
897 [main] DEBUG org.apache.sshd.client.SshClient - close(SshClient[15d943d]) Closing immediately
905 [main] TRACE org.apache.sshd.common.util.closeable.SequentialCloseable - doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@14a2528) closing [DefaultCloseFuture[id=SshClient[15d943d]][value=null]] immediately=true
906 [main] TRACE org.apache.sshd.client.SshClient - removeSessionListener(SshClient[15d943d])[org.apache.sshd.common.session.helpers.SessionTimeoutListener@14948e4] removed
906 [main] TRACE org.apache.sshd.common.util.closeable.SequentialCloseable - doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@14a2528) closing org.apache.sshd.common.io.nio2.Nio2Connector@1e2a9e immediately=true
907 [main] DEBUG org.apache.sshd.common.io.nio2.Nio2Connector - close(org.apache.sshd.common.io.nio2.Nio2Connector@1e2a9e) Closing immediately
915 [main] TRACE org.apache.sshd.common.util.closeable.ParallelCloseable - doClose(true) completed pending: 0
918 [main] DEBUG org.apache.sshd.common.io.nio2.Nio2Connector - close(org.apache.sshd.common.io.nio2.Nio2Connector@1e2a9e)[Immediately] closed
918 [main] TRACE org.apache.sshd.common.util.closeable.SequentialCloseable - doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@14a2528) closing org.apache.sshd.common.io.nio2.Nio2ServiceFactory@83dc97 immediately=true
919 [main] DEBUG org.apache.sshd.common.io.nio2.Nio2ServiceFactory - close(org.apache.sshd.common.io.nio2.Nio2ServiceFactory@83dc97) Closing immediately
919 [main] DEBUG org.apache.sshd.common.io.nio2.Nio2ServiceFactory - Shutdown group
921 [main] DEBUG org.apache.sshd.common.io.nio2.Nio2ServiceFactory - Group successfully shut down
921 [main] DEBUG org.apache.sshd.common.io.nio2.Nio2ServiceFactory - Shutdown executor
922 [main] DEBUG org.apache.sshd.common.io.nio2.Nio2ServiceFactory - Shutdown complete
923 [main] DEBUG org.apache.sshd.common.io.nio2.Nio2ServiceFactory - close(org.apache.sshd.common.io.nio2.Nio2ServiceFactory@83dc97)[Immediately] closed
923 [main] TRACE org.apache.sshd.common.util.closeable.SequentialCloseable - doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@14a2528) closing [DefaultCloseFuture[id=SshClient[15d943d]][value=null]] immediately=true
924 [main] DEBUG org.apache.sshd.common.util.closeable.SequentialCloseable - doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@14a2528) signal close complete immediately=true
924 [main] DEBUG org.apache.sshd.client.SshClient - close(SshClient[15d943d])[Immediately] closed
org.apache.sshd.common.RuntimeSshException: Failed to get the session.
        at org.apache.sshd.client.future.DefaultConnectFuture.getSession(DefaultConnectFuture.java:59)
        at org.apache.sshd.client.future.DefaultConnectFuture.getSession(DefaultConnectFuture.java:34)
        at org.apache.karaf.client.Main.connectWithRetries(Main.java:373)
        at org.apache.karaf.client.Main.main(Main.java:169)
Caused by: java.net.ConnectException: Connection refused
        at java.base/sun.nio.ch.UnixAsynchronousSocketChannelImpl.checkConnect(Native Method)
        at java.base/sun.nio.ch.UnixAsynchronousSocketChannelImpl.finishConnect(UnixAsynchronousSocketChannelImpl.java:256)
        at java.base/sun.nio.ch.UnixAsynchronousSocketChannelImpl.finish(UnixAsynchronousSocketChannelImpl.java:202)
        at java.base/sun.nio.ch.UnixAsynchronousSocketChannelImpl.onEvent(UnixAsynchronousSocketChannelImpl.java:217)
        at java.base/sun.nio.ch.EPollPort$EventHandlerTask.run(EPollPort.java:306)
        at java.base/java.lang.Thread.run(Thread.java:833)
openhabian@openhab:~ $

Cleaning cache, restarting, fixing permissions doesn’t have any effect.

EDIT1:
Looks like the “/etc/systemd/system/openhab.service.d/override.conf” has a line

[Service]
ExecStartPre=+/usr/bin/rm -f /var/lock/LCK..ttyAMA0 /var/lock/LCK..ttyACM0

This must be related…

jpalo · August 30, 2023, 3:01pm

Oh well, updating the rm reference seems to have fixed it.

[Service]
ExecStartPre=+rm -f /var/lock/LCK..ttyAMA0 /var/lock/LCK..ttyACM0

Issue was introduced in early August 2023 in this commit: Remove serial lockfiles before start · openhab/openhabian@e0250ae (github.com)
where it is assumed that /usr/bin/rm exists.

UPDATE: Better solution is to copy the file from /bin to /usr/bin so updates will work in the future too.

mstormi · August 31, 2023, 11:31am

Well I don’t mind changing that but /usr/bin/rm does exist in current Raspi OS and on about any Debian system I know so you have done something special to yours. It wasn’t that commit to “introduce” your issue.

jpalo · August 31, 2023, 12:02pm

Thanks for the confirmation. I only had it in /bin but copied it to /usr/bin and will leave it to you to decide if/how to proceed.