sshd doesn't start properly because dhcp client doesn't get ip address

[Wawrzyniec Niewodniczański]

Binary package hint: openssh-server

The sshd server doesn't start properly:

niewod@madryt:~$ps axf | grep ssh
 4885 ? Ss 0:00 /usr/sbin/sshd

Restarting it helps:

niewod@madryt:~$sudo /etc/init.d/ssh restart
[sudo] password for niewod:
 * Restarting OpenBSD Secure Shell server sshd
   ...done.
niewod@madryt:~$ps axf | grep ssh
 6683 pts/0 S+ 0:00 \_ grep ssh
 6678 ? Ss 0:00 /usr/sbin/sshd

ssh server working again.

[Marcus Asshauer (mcas)]

Thank you for reporting this bug. Please add your ubuntu version and the output of apt-cache policy openssh-server.

[Wawrzyniec Niewodniczański (wawrzek)]

niewod@madryt:~$apt-cache policy openssh-server
openssh-server:
  Installed: 1:4.7p1-8ubuntu1.2
  Candidate: 1:4.7p1-8ubuntu1.2
  Version table:
 *** 1:4.7p1-8ubuntu1.2 0
        500 http://gb.archive.ubuntu.com hardy-updates/main Packages
        500 http://security.ubuntu.com hardy-security/main Packages
        100 /var/lib/dpkg/status
     1:4.7p1-8ubuntu1 0
        500 http://gb.archive.ubuntu.com hardy/main Packages
niewod@madryt:~$

[Wawrzyniec Niewodniczański (wawrzek)]

The sshd is working fine now.

I've change few things.

First I figured out that I can connect to localhost by not to madryt

Next I've changed order of ListenAddress in /etc/ssh/sshd_config

ListenAddress 192.168.1.66
ListenAddress 127.0.0.1

After some times I understood that ssh complains about bind and found that I had made a mistake in /etc/hosts
I'm not sure what was earlier probably

127.0.0.1 localhost madyt

or sth. similar but now I have

127.0.0.1 localhost madryt
192.168.1.66 madryt.home madryt

I'm not sure if I was blind and I didn't see message about problems with bind or I change something and this message started to appear. I also don't understand why manually restart of ssh demon were resolving the issue...

[Wawrzyniec Niewodniczański (wawrzek)]

I change loglevel of sshd, restart the machine and I think I've got him!

The problem is start sequence, the sshd starts before dhcp finishes procedure of getting IP address from router (the standard BT broadband router).

Please compare following lines from
/var/log/auth:

Jul 22 21:35:05 madryt sshd[5612]: debug1: Bind to port 22 on 192.168.1.66.
Jul 22 21:35:05 madryt sshd[5612]: error: Bind to port 22 on 192.168.1.66 failed: Cannot assign requested address.
Jul 22 21:35:05 madryt sshd[5612]: debug1: Bind to port 22 on 127.0.0.1.
Jul 22 21:35:05 madryt sshd[5612]: Server listening on 127.0.0.1 port 22.

and
/var/log/syslog:

Jul 22 21:35:13 madryt dhclient: DHCPREQUEST of 192.168.1.66 on eth0 to 255.255.255.255 port 67
Jul 22 21:35:13 madryt dhclient: DHCPACK of 192.168.1.66 from 192.168.1.254
Jul 22 21:35:13 madryt avahi-daemon[5633]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.1.66.
Jul 22 21:35:13 madryt avahi-daemon[5633]: New relevant interface eth0.IPv4 for mDNS.
Jul 22 21:35:13 madryt avahi-daemon[5633]: Registering new address record for 192.168.1.66 on eth0.IPv4.
Jul 22 21:35:13 madryt kernel: [ 137.075467] [drm] Initialized drm 1.1.0 20060810
Jul 22 21:35:13 madryt kernel: [ 137.125180] ACPI: PCI Interrupt 0000:01:00.0[A] -> GSI 16 (level, low) -> IRQ 21
Jul 22 21:35:13 madryt kernel: [ 137.125543] [drm] Initialized r128 2.5.0 20030725 on minor 0
Jul 22 21:35:13 madryt kernel: [ 137.127323] agpgart: Found an AGP 2.0 compliant device at 0000:00:00.0.
Jul 22 21:35:13 madryt kernel: [ 137.127364] agpgart: Putting AGP V2 device at 0000:00:00.0 into 1x mode
Jul 22 21:35:13 madryt kernel: [ 137.127389] agpgart: Putting AGP V2 device at 0000:01:00.0 into 1x mode
Jul 22 21:35:13 madryt NetworkManager: <debug> [1216758913.209118] nm_hal_device_added(): New device added (hal udi is '/org/freedesktop/Hal/devices/pci_1002_5446_drm_r128_card0').
Jul 22 21:35:13 madryt NetworkManager: <info> DHCP daemon state is now 4 (reboot) for interface eth0
Jul 22 21:35:13 madryt NetworkManager: <info> Activation (eth0) Stage 4 of 5 (IP Configure Get) scheduled...
Jul 22 21:35:13 madryt NetworkManager: <info> Activation (eth0) Stage 4 of 5 (IP Configure Get) started...
Jul 22 21:35:13 madryt dhcdbd: message_handler: message handler not found under /com/redhat/dhcp/eth0 for sub-path eth0.dbus.get.host_name
Jul 22 21:35:13 madryt dhcdbd: message_handler: message handler not found under /com/redhat/dhcp/eth0 for sub-path eth0.dbus.get.nis_domain
Jul 22 21:35:13 madryt dhcdbd: message_handler: message handler not found under /com/redhat/dhcp/eth0 for sub-path eth0.dbus.get.nis_servers
Jul 22 21:35:13 madryt NetworkManager: <info> Retrieved the following IP4 configuration from the DHCP daemon:
Jul 22 21:35:13 madryt NetworkManager: <info> address 192.168.1.66
Jul 22 21:35:13 madryt NetworkManager: <info> netmask 255.255.255.0
Jul 22 21:35:13 madryt NetworkManager: <info> broadcast 192.168.1.255
Jul 22 21:35:13 madryt NetworkManager: <info> gateway 192.168.1.254
Jul 22 21:35:13 madryt NetworkManager: <info> nameserver 192.168.1.254
Jul 22 21:35:13 madryt NetworkManager: <info> domain name 'ho...

[Wawrzyniec Niewodniczański (wawrzek)]

Few more lines from
/var/log/syslog:

Jul 22 21:35:10 madryt NetworkManager: <info> Activation (eth0) Beginning DHCP transaction.
Jul 22 21:35:10 madryt NetworkManager: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) complete.
Jul 22 21:35:10 madryt NetworkManager: <info> DHCP daemon state is now 12 (successfully started) for interface eth0
Jul 22 21:35:12 madryt NetworkManager: <info> DHCP daemon state is now 1 (starting) for interface eth0
Jul 22 21:35:12 madryt kernel: [ 136.070878] NET: Registered protocol family 17

Activation of eth0 started 5 seconds after sshd attempt to use it (if I understands logs properly).

[Wawrzyniec Niewodniczański (wawrzek)]

I wrote a patch for /etc/init.d/ssh which make scrpit waiting for a eth0 interface:

#My patch
check_for_eth() {
   eth=0
   while [ $eth -eq 0 ]
   do
       if [ `ifconfig | grep -c addr:192.168.1.66` -eq 0 ]
           then
               sleep 10
           else
               eth=1
       fi
   done
}

After applying it I found that the system froze during start. I checked /etc/network/interfaces and figured out that eth0 hadn't been set in the file!!!

After adding eth0 (with patch in /etc/init.d/ssh) system start fine

Current /etc/network/interfaces is very standard:

auto lo eth0
iface lo inet loopback
iface eth0 inet dhcp

[Wawrzyniec Niewodniczański (wawrzek)]

Please feel free to close the bug. I created another bug report against installer (bug 267929).

[Wawrzyniec Niewodniczański (wawrzek)]

I reopen the bug. The bug against installer is not so important.

I make clean installation of U8.10 and could somebody from the openssh or network-manager teams can explain who decided that sshd should start before dhcp client finish (and actually start) process of retrieving ip address?

relevant lines from
a) auth.log:
Nov 25 00:38:26 madryt sshd[4999]: debug1: Bind to port 22 on 192.168.1.65.
Nov 25 00:38:26 madryt sshd[4999]: error: Bind to port 22 on 192.168.1.65 failed: Cannot assign requested address.
Nov 25 00:38:26 madryt sshd[4999]: debug1: Bind to port 22 on 127.0.1.1.
Nov 25 00:38:26 madryt sshd[4999]: Server listening on 127.0.1.1 port 22.
Nov 25 00:38:26 madryt sshd[4999]: debug1: Bind to port 22 on 127.0.0.1.
Nov 25 00:38:26 madryt sshd[4999]: Server listening on 127.0.0.1 port 22.

b) daemon.log:
Nov 25 00:38:36 madryt dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 4
Nov 25 00:38:36 madryt dhclient: DHCPOFFER of 192.168.1.65 from 192.168.1.254
Nov 25 00:38:36 madryt dhclient: DHCPREQUEST of 192.168.1.65 on eth0 to 255.255.255.255 port 67
Nov 25 00:38:36 madryt dhclient: DHCPACK of 192.168.1.65 from 192.168.1.254
Nov 25 00:38:36 madryt NetworkManager: <info> DHCP: device eth0 state changed preinit -> bound
Nov 25 00:38:36 madryt NetworkManager: <info> Activation (eth0) Stage 4 of 5 (IP Configure Get) scheduled...
Nov 25 00:38:36 madryt NetworkManager: <info> Activation (eth0) Stage 4 of 5 (IP Configure Get) started...
Nov 25 00:38:36 madryt NetworkManager: <info> address 192.168.1.65
Nov 25 00:38:36 madryt NetworkManager: <info> prefix 24 (255.255.255.0)
Nov 25 00:38:36 madryt NetworkManager: <info> gateway 192.168.1.254
Nov 25 00:38:36 madryt NetworkManager: <info> nameserver '192.168.1.254'
Nov 25 00:38:36 madryt NetworkManager: <info> domain name 'lan'

[Wawrzyniec Niewodniczański (wawrzek)]

related to bug 267929

[Wawrzyniec Niewodniczański (wawrzek)]

Another workaround is to set in sshd_config to
 ListenAddress 0.0.0.0

[Cyril Bouthors (cyril)]

A nice work-around is to restart sshd each time NM changes addresses and/or network interfaces, using NM dispatcher:

echo /etc/init.d/ssh restart > /etc/NetworkManager/dispatcher.d/10ssh
chmod 755 /etc/NetworkManager/dispatcher.d/10ssh

This was inspired from http://<email address hidden>/msg08077.html

[Alexander Sack (asac)]

I use network manager with sshd regularly on intrepid/jaunty. If you want to do the workaround to restart sshd you can add a script into /etc/NetworkManager/dispatcher.d/ that does that.