LinuxQuestions.org

LinuxQuestions.org (/questions/)
-   Linux - General (https://www.linuxquestions.org/questions/linux-general-1/)
-   -   systemd[1]: Failed to start OpenBSD Secure Shell server during boot (https://www.linuxquestions.org/questions/linux-general-1/systemd%5B1%5D-failed-to-start-openbsd-secure-shell-server-during-boot-4175556430/)

pan64 10-17-2015 11:59 AM

systemd[1]: Failed to start OpenBSD Secure Shell server during boot
 
So during boot sshd failed to start. It occurred every time I switched on my linux. But I can start sshd any time by hand: service sshd start.
I can find lines like this in syslog:
Code:

syslog.1:Oct 17 15:16:05 host systemd[1]: ssh.service: main process exited, code=exited, status=255/n/a
syslog.1:Oct 17 15:16:05 host systemd[1]: Unit ssh.service entered failed state.
syslog.1:Oct 17 15:16:05 host systemd[1]: ssh.service: main process exited, code=exited, status=255/n/a
syslog.1:Oct 17 15:16:05 host systemd[1]: Unit ssh.service entered failed state.
syslog.1:Oct 17 15:16:05 host systemd[1]: ssh.service: main process exited, code=exited, status=255/n/a
syslog.1:Oct 17 15:16:05 host systemd[1]: Unit ssh.service entered failed state.
syslog.1:Oct 17 15:16:05 host systemd[1]: ssh.service: main process exited, code=exited, status=255/n/a
syslog.1:Oct 17 15:16:05 host systemd[1]: Unit ssh.service entered failed state.
syslog.1:Oct 17 15:16:06 host systemd[1]: ssh.service: main process exited, code=exited, status=255/n/a
syslog.1:Oct 17 15:16:06 host systemd[1]: Unit ssh.service entered failed state.
syslog.1:Oct 17 15:16:06 host systemd[1]: ssh.service start request repeated too quickly, refusing to start.
syslog.1:Oct 17 15:16:06 host systemd[1]: Unit ssh.service entered failed state.

Do you have any idea how to make it work?
(Debian 3.16.7-ckt11-1+deb8u4 (2015-09-19) x86_64 GNU/Linux)

TobiSGD 10-17-2015 03:47 PM

What do you get from
Code:

systemctl status ssh
and
Code:

journalctl -b -xn

pan64 10-18-2015 03:23 AM

Code:

# systemctl status -l ssh
● ssh.service - OpenBSD Secure Shell server
  Loaded: loaded (/lib/systemd/system/ssh.service; enabled)
  Active: failed (Result: start-limit) since Sun 2015-10-18 10:07:44 CEST; 7min ago
  Process: 1647 ExecStart=/usr/sbin/sshd -D $SSHD_OPTS (code=exited, status=255)
 Main PID: 1647 (code=exited, status=255)

Oct 18 10:07:44 host systemd[1]: ssh.service: main process exited, code=exited, status=255/n/a
Oct 18 10:07:44 host systemd[1]: Unit ssh.service entered failed state.
Oct 18 10:07:44 host systemd[1]: ssh.service start request repeated too quickly, refusing to start.
Oct 18 10:07:44 host systemd[1]: Failed to start OpenBSD Secure Shell server.
Oct 18 10:07:44 host systemd[1]: Unit ssh.service entered failed state.

there is nothing related using journalctl:
Code:

# journalctl -b -xn
-- Logs begin at Sun 2015-10-18 10:07:40 CEST, end at Sun 2015-10-18 10:14:41 CEST. --
Oct 18 10:12:45 host colord[1655]: Profile added: Deskjet-F4500-Gray..
Oct 18 10:12:45 host colord[1655]: Profile added: Deskjet-F4500-RGB..
Oct 18 10:12:45 host colord[1655]: (colord:1655): Cd-WARNING **: failed to get session [pid 3290]: Unknown error -2
Oct 18 10:12:45 host colord[1655]: Device added: cups-Deskjet-F4500
Oct 18 10:12:45 host colord[1655]: (colord:1655): Cd-WARNING **: failed to get session [pid 3290]: Unknown error -2
Oct 18 10:12:46 host smbd[3367]: Reloading /etc/samba/smb.conf: smbd.
Oct 18 10:13:25 host anacron[958]: Job `cron.daily' terminated
Oct 18 10:13:25 host anacron[958]: Normal exit (1 job run)
Oct 18 10:14:41 host sudo[3439]: user : TTY=pts/0 ; PWD=/home/user ; USER=root ; COMMAND=/bin/bash
Oct 18 10:14:41 host sudo[3439]: pam_unix(sudo:session): session opened for user root by user(uid=0)

after service sshd start:
Code:

# systemctl status -l ssh
● ssh.service - OpenBSD Secure Shell server
  Loaded: loaded (/lib/systemd/system/ssh.service; enabled)
  Active: active (running) since Sun 2015-10-18 10:19:58 CEST; 3s ago
 Main PID: 3534 (sshd)
  CGroup: /system.slice/ssh.service
          └─3534 /usr/sbin/sshd -D

Oct 18 10:19:58 host sshd[3534]: Server listening on 192.168.2.211 port 2223.

(yes, it is set to listen on port 2223)

TobiSGD 10-18-2015 03:45 AM

So it starts when you use the service command (which is just a wrapper to systemctl, if I am not mistaken), but not at boot, but the logs show no clue why this is the case and I couldn't find any hint on what exit code 255 means.
Sorry, I am out of clues.

pan64 10-18-2015 04:44 AM

yes, there will be a
exec systemctl ${ACTION} ${UNIT}
in that script (/usr/sbin/service)
setting debug mode I will get the following:
Code:

Oct 18 11:35:05 host sshd[1232]: Set /proc/self/oom_score_adj from 0 to -1000
Oct 18 11:35:05 host sshd[1232]: debug1: Bind to port 2223 on 192.168.2.211.
Oct 18 11:35:05 host sshd[1232]: error: Bind to port 2223 on 192.168.2.211 failed: Cannot assign requested address.
Oct 18 11:35:05 host sshd[1232]: fatal: Cannot bind any address.
Oct 18 11:35:05 host sshd[1292]: Set /proc/self/oom_score_adj from 0 to -1000
Oct 18 11:35:05 host sshd[1292]: debug1: Bind to port 2223 on 192.168.2.211.
Oct 18 11:35:05 host sshd[1292]: error: Bind to port 2223 on 192.168.2.211 failed: Cannot assign requested address.
Oct 18 11:35:05 host sshd[1292]: fatal: Cannot bind any address.
Oct 18 11:35:05 host sshd[1584]: Set /proc/self/oom_score_adj from 0 to -1000
Oct 18 11:35:05 host sshd[1584]: debug1: Bind to port 2223 on 192.168.2.211.
Oct 18 11:35:05 host sshd[1584]: error: Bind to port 2223 on 192.168.2.211 failed: Cannot assign requested address.
Oct 18 11:35:05 host sshd[1584]: fatal: Cannot bind any address.
Oct 18 11:35:06 host sshd[1592]: Set /proc/self/oom_score_adj from 0 to -1000
Oct 18 11:35:06 host sshd[1592]: debug1: Bind to port 2223 on 192.168.2.211.
Oct 18 11:35:06 host sshd[1592]: error: Bind to port 2223 on 192.168.2.211 failed: Cannot assign requested address.
Oct 18 11:35:06 host sshd[1592]: fatal: Cannot bind any address.


TobiSGD 10-18-2015 05:03 AM

Stupid question, but do you have anything else listening on port 2223?
Have you tried using a different port from the dynamic range (49152-65535) instead of one of the registered ones (1024-49151)? Maybe this port is used at bootup for something that isn't running later on.

Edit: Just looked it up, port 2223 is registered by Brian Batke for use with Rockwell CSP2, though I have no clue what that is.

pan64 10-18-2015 06:12 AM

I have now tried port 55555 and sshd produced exactly the same result:
cannot assign requested address during boot but works properly using systemctl.
I thought sshd was started too early, but I have no idea how to check/modify it.

TobiSGD 10-18-2015 08:12 AM

Quote:

Originally Posted by pan64 (Post 5436301)
I thought sshd was started too early, but I have no idea how to check/modify it.

You may be right on this, the sshd service obviously should only be started once the network.target is reached.
To check it use systemd-analyze to produce a boot chart:
Code:

systemd-analyze plot >boot.svg
This will generate a file called boot.svg that can be viewed in your browser (or any other program capable of displaying SVG images).

pan64 10-20-2015 11:23 AM

Thanks
I do not really understand what's happening, but:
Code:

1. by dmesg the last message is:
[    7.150528] r8169 0000:02:00.0: firmware: direct-loading firmware rtl_nic/rtl8168f-1.fw
[    7.260124] r8169 0000:02:00.0 eth0: link down
[    7.260137] r8169 0000:02:00.0 eth0: link down
[    8.889648] r8169 0000:02:00.0 eth0: link up

almost 9 seconds to have an ip address
and sshd started at about 6.55 seconds and tried more that 6 seconds long to start but failed.

TobiSGD 10-20-2015 12:39 PM

On my rather slow homeserver the final "link up" is about the 20 seconds mark, but SSH is started directly after that. What do you use to set up the network?

pan64 10-21-2015 01:51 AM

dhcp on router running openwrt (ipv6 not in use)

TobiSGD 10-21-2015 06:45 AM

No, I meant which technique (systemd-networkd, NetworkManager, ...) do use use on the machine in question?

pan64 10-24-2015 10:53 AM

systemd and NetworkManager are running. NetworkManager executed dhclient which configured eth0.

TobiSGD 10-24-2015 12:14 PM

Well, then that is the difference between our setups, I use systemd-networkd for setting up the network, maybe give that a try and look if it solves the problem.

pan64 10-31-2015 05:14 AM

so sshd now works but I have still no any idea what went wrong with NetworkManager.
Thanks anyway


All times are GMT -5. The time now is 04:35 PM.