[gentoo-user] MySQL startup problem - interface does not have an address yet.

[Manuel McLure]

I'm having a problem with booting my Gentoo system due to MySQL
hanging at startup. My system is up-to-date stable (including
udev-197, although I believe the problem started while I was still on
171) except for the kernel, which is at 3.1.10 because I can't seem to
get lirc to work correctly on newer kernels. The problem started after
a large system update just before the udev 171 to 197 migration. Among
other upgrades dhcpcd was upgraded from 5.2.12 to 5.6.4, net-tools was
upgraded from 1.60_p20110409135728 to 1.60_p20120127084908, and openrc
was upgraded from 0.9.8.4 to 0.11.8.

For historical reasons, this system has two ethernet adapters, eth0
and eth1. eth0 is not configured any more (it used to be used for IPTV
connectivity to my cable provider for MythTV before they changes their
system.) eth1 is configured via DHCP to an RFC 1918 10.x.x.x address -
the DHCP server is always configured to provide the same IP address
for this system. net.eth1 is symlinked to /etc/runlevels/default.

The boot process starts, configures eth1, starts LCDd, and then
attempts to start MySQL - and hangs for about 15 minutes before
continuing with the boot.

I added several debugging statements to /etc/init.d/mysql and found
that even though the log shows that eth1 got its IP address, when
MySQL attempts to start the interface does not have an IP address
assigned. It's like the net.eth1 script exits before the interface is
completely up.

After the 15 minute hang, the system boots up as usual, except for
MySQL not running. If I then start mysql manually it comes up
immediately.

Here's the rc.log output:

 * Starting D-BUS system messagebus ...
 [ ok ]
 * Bringing up interface eth1
 *   dhcp ...
 *     Running dhcpcd ...
dhcpcd[8400]: version 5.6.4 starting
dhcpcd[8400]: eth1: waiting for carrier
dhcpcd[8400]: eth1: carrier acquired
dhcpcd[8400]: eth1: sending IPv6 Router Solicitation
dhcpcd[8400]: eth1: sendmsg: Cannot assign requested address
dhcpcd[8400]: eth1: rebinding lease of 10.x.y.14
dhcpcd[8400]: eth1: acknowledged 10.x.y.14 from 10.x.y.1
dhcpcd[8400]: eth1: checking for 10.x.y.14
dhcpcd[8400]: eth1: Router Advertisement from NNNN::NNNN:NNNN:NNNN:NNNN
dhcpcd[8400]: forked to background, child pid 8454
 [ ok ]
 *     received address
 [ ok ]
 *   Adding routes
 *     239.0.0.0/8 ...
 [ ok ]
 * Starting LCDd ...
 [ ok ]
 * Starting mysql ...
 [ !! ]
 * ERROR: mysql failed to start
 * Starting syslog-ng ...
 [ ok ]
 * Mounting network filesystems ...
 [ ok ]

I added the following commands before the start-stop-daemon line in
/etc/init.d/mysql:

        date >/var/log/mysqlstart.log
        netstat -anp | grep 3306 >>/var/log/mysqlstart.log
        ps -efl | grep mysql >>/var/log/mysqlstart.log
        lsof -i @10.x.y.14:3306 >>/var/log/mysqlstart.log
        ifconfig -a >>/var/log/mysqlstart.log

The output of this was:

Wed Jan 23 09:56:03 PST 2013
0 S root      8497  8290  0  80   0 -  4301 poll_s 09:56 ?
00:00:00 /sbin/runscript /etc/init.d/mysql --lockfd 10 start
4 S root      8498  8497  1  80   0 -  3425 wait   09:56 ?
00:00:00 /bin/sh /lib64/rc/sh/runscript.sh /etc/init.d/mysql start
0 S root      8537  8498  0  80   0 -  2142 pipe_w 09:56 ?
00:00:00 grep mysql
eth0: flags=4098<BROADCAST,MULTICAST>  mtu 1500
        ether 00:22:15:b7:ff:bc  txqueuelen 1000  (Ethernet)
        RX packets 0  bytes 0 (0.0 B)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 0  bytes 0 (0.0 B)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0
        device interrupt 22  base 0xa000

eth1: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500
        inet6 NNNN:NNNN:NNNN:NNNN:NNNN:NNNN:NNNN:NNNN  prefixlen 64
scopeid 0x0<global>
        inet6 NNNN::NNNN:NNNN:NNNN:NNNN  prefixlen 64  scopeid 0x20<link>
        ether 00:1b:21:b1:cb:bb  txqueuelen 1000  (Ethernet)
        RX packets 9  bytes 1149 (1.1 KiB)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 8  bytes 936 (936.0 B)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0
        device interrupt 18  memory 0xfebe0000-fec00000

lo: flags=73<UP,LOOPBACK,RUNNING>  mtu 16436
        inet 127.0.0.1  netmask 255.0.0.0
        inet6 ::1  prefixlen 128  scopeid 0x10<host>
        loop  txqueuelen 0  (Local Loopback)
        RX packets 0  bytes 0 (0.0 B)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 0  bytes 0 (0.0 B)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

As you can see, eth1 has no IPV4 address assigned. Once the server
boots (after the 15 minute mysql timeout ends) ifconfig shows the
following:


eth1: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500
        inet 10.x.y.14  netmask 255.255.255.0  broadcast 10.x.y.255
        inet6 NNNN:NNNN:NNNN:NNNN:NNNN:NNNN:NNNN:NNNN  prefixlen 64
scopeid 0x0<global>
        inet6 NNNN::NNNN:NNNN:NNNN:NNNN  prefixlen 64  scopeid 0x20<link>
        ether 00:1b:21:b1:cb:bb  txqueuelen 1000  (Ethernet)
        RX packets 2732  bytes 496650 (485.0 KiB)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 1853  bytes 277789 (271.2 KiB)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0
        device interrupt 18  memory 0xfebe0000-fec00000

In rc.conf I have rc_depend_strict set to YES. I do *not* have
rc_parallel set. I attempted adding "need net" to the depend() section
of the mysql init script with no effect.

The entries for eth1 in /etc/conf.d/net are:

config_eth1="dhcp"
routes_eth1="239.0.0.0/8"

I also tested adding

dhcpcd_eth1="--waitip"

to /etc/conf.d/net again to no avail.

I could add a delay to the mysql script to ensure startup, but I'd
rather figure out why the IP address is not yet available even though
the net.eth1 script has completed. Does anyone have any hints on what
could be going wrong?

Thanks!
-- 
Manuel A. McLure WW1FA <manuel@××××××.org> <http://www.mclure.org>
...for in Ulthar, according to an ancient and significant law,
no man may kill a cat.                       -- H.P. Lovecraft