Topic: dhcpcd being naughty

[spkelly]

I am getting the following :
Jun 30 16:29:14 bambi dhcpcd[2465]: dhcpStart: interface ppp0 is not Ethernet or 802.2 Token Ring
repeated every second on my server (sme 6.0.1-01)... It does this after it dials up PPP0 (hence the error).

I can stop the error messages by issuing a "service dhcpcd stop" on the server's console, but that is a messy human-interaction thing that should not be necessary.

Can anyone tell me how to stop this?

Regards,

Sean

[Dexter Hansen]

I have the same symtoms on my SME 6.0 box. ("Jul  2 23:40:21 old486 dhcpcd[10889]: dhcpStart: interface ppp0 is not Ethernet or 802.2 Token Ring" in the messages log.

In preparation for a Roadrinner hooked up, I did change the setup to use two nic's instead of the eth0 and an externial dialup on com1 (and then changed back to dialup).  It started showing up in the message log after that.  

I'm probably going to just reinstall. From what I've seen for posts, a nic is suspect, however, this message seem to be complaining about running ppp0 over the modem.  May be a low priority bug :>(.

Seems the rr folks hosed and it's going to be a week before they get the install done anyway so I have time to reload everything.

[spkelly]

Dexter,

The entries in my messages log are intermittent. By that I mean I could do a couple of boots, and each boot could have a couple of redials and it won't log the dhcpcd-on-ppp0 error. But then I could also have one reboot and it'll do it on the first dialup. Or it might do it on the second one.

Another possible symptom is that the diald/accounting.log often shows that it is calling and connected to "site 0.0.0.0", rather than to "site x.y.z.a" at the ISP's site.

I have not yet determined a correlation, but there may be. If there is I don't know whether the bug will be in diald, pppd or dhcpcd. Or the binding script.

My machine has only one NIC and an external MODEM. I have another test box which has two NICs and an internal MODEM, but that rarely if ever dials anything.

These errors (both the diald and dhcpcd) don't seem to stop traffic from coming or going, but they _are_ annoying.

Sean

[Dexter Hansen]

Hi Sean:

I looked up my messeage log and right after I had changed the setup back to dialup, the error started to occur (seems a couple of times a minute)  My logs for the last two days are full of the same message.

I shut the service off for now and will probably re-install, though I thought I saw a bug in SME 6.0 that was with dhcpc that said to put a

modprobe eth0
modprobe eth1

in the dhcpc script, though I'm not sure if they were talking about the /etc/dhcpc.conf or some other file.

Might have to try the 6.0.1 if I can't get it to go away.  Seems my power supply also died today (at least the fan stopped working - only been running since 1992 - think they'd make things to last) and the HD also picked up an error.  The power supply  could have wiped something else so I'll be doing some upgrades to make sure it's on solid ground before I let it front for me on a cable modem line.  Who knows, it could still be the nic.

Regards,

Dexter

[Anonymous]

Hi Dexter,

I just did a reboot to confirm my suspicions and the messages log shows this:
--------8<--------
Jul  3 17:14:41 bambi pppd[2462]: Using interface ppp0
Jul  3 17:14:41 bambi pppd[2462]: Connect: ppp0 <--> /dev/ttyS0
Jul  3 17:14:41 bambi /etc/hotplug/net.agent: assuming ppp0 is already up
Jul  3 17:14:41 bambi dhcpcd[2481]: dhcpStart: interface ppp0 is not Ethernet or 802.2 Token Ring
Jul  3 17:14:42 bambi pppd[2462]: Remote message: ^@
Jul  3 17:14:42 bambi pppd[2462]: CHAP authentication succeeded
Jul  3 17:14:42 bambi kernel: PPP BSD Compression module registered
Jul  3 17:14:42 bambi kernel: PPP Deflate Compression module registered
Jul  3 17:14:42 bambi dhcpcd[2502]: dhcpStart: interface ppp0 is not Ethernet or 802.2 Token Ring
Jul  3 17:14:42 bambi pppd[2462]: local  IP address 1.2.3.4
Jul  3 17:14:42 bambi pppd[2462]: remote IP address 5.6.7.8
--------8<--------
... so pppd dials up, inits /etc/hotplug/net.agent, then dhcpcd spits the dummy. Every second it spits the dummy. And it never runs out of dummies.

Coincidentally the diald/accounting.log shows this:
--------8<--------
Sat Jul  3 17:14:17 2004 EST: Calling site 0.0.0.0.
Sat Jul  3 17:14:40 2004 EST: Connected to site 0.0.0.0.
Sat Jul  3 17:43:32 2004 EST: Disconnected. Call duration 1732 seconds.
      IP transmitted 1301408 bytes and received 579263 bytes.
Sat Jul  3 17:43:34 2004 EST: Calling site 5.6.7.8.
Sat Jul  3 17:43:57 2004 EST: Connected to site 5.6.7.8.
--------8<--------

and for that redial at 17:43:34, the messages log shows (apologies for the verbosity, but someone might see something good in here):
--------8<--------

Jul  3 17:43:27 bambi pppd[2462]: Hangup (SIGHUP)
Jul  3 17:43:27 bambi pppd[2462]: Modem hangup
Jul  3 17:43:27 bambi pppd[2462]: Connection terminated.
Jul  3 17:43:27 bambi pppd[2462]: Connect time 28.8 minutes.
Jul  3 17:43:27 bambi pppd[2462]: Sent 1301471 bytes, received 579305 bytes.
Jul  3 17:43:27 bambi kernel: divert: no divert_blk to free, ppp0 not ethernet
Jul  3 17:43:27 bambi /etc/hotplug/net.agent: NET unregister event not supported
Jul  3 17:43:28 bambi e-smith[10193]: Processing event: ip-down ppp0 /dev/ttyS0 115200 1.2.3.4 5.6.7.8 diald
Jul  3 17:43:28 bambi e-smith[10193]: Running event handler: /etc/e-smith/events/ip-down/S50isdn-down-notify
Jul  3 17:43:28 bambi e-smith[10193]: S50isdn-down-notify=action|Event|ip-down|Action|S50isdn-down-notify|Start|1088840608 8072|End|1088840608 547995|Elapsed|0.539923
Jul  3 17:43:28 bambi e-smith[10193]: Running event handler: /etc/e-smith/events/ip-down/S70pptp-interface-access
Jul  3 17:43:29 bambi e-smith[10193]: Use of uninitialized value in split at /etc/e-smith/events/ip-down/S70pptp-interface-access line 37.
Jul  3 17:43:29 bambi e-smith[10193]: S70pptp-interface-access=action|Event|ip-down|Action|S70pptp-interface-access|Start|1088840608 548426|End|1088840609 95330|Elapsed|0.546904
Jul  3 17:43:29 bambi e-smith[10193]: Running event handler: /etc/e-smith/events/ip-down/S80conf-masq
Jul  3 17:43:30 bambi e-smith[10193]: S80conf-masq=action|Event|ip-down|Action|S80conf-masq|Start|1088840609 95734|End|1088840610 351566|Elapsed|1.255832
Jul  3 17:43:30 bambi e-smith[10193]: Running event handler: /etc/e-smith/events/ip-down/S85adjust-masq
Jul  3 17:43:32 bambi e-smith[10193]: S85adjust-masq=action|Event|ip-down|Action|S85adjust-masq|Start|1088840610 351964|End|1088840612 43637|Elapsed|1.691673
Jul  3 17:43:32 bambi pppd[2462]: Connect time 28.8 minutes.
Jul  3 17:43:32 bambi pppd[2462]: Sent 1301471 bytes, received 579305 bytes.
Jul  3 17:43:32 bambi pppd[2462]: Exit.
Jul  3 17:43:32 bambi diald[1879]: Link died on remote end.
Jul  3 17:43:32 bambi diald[1879]: stop ppp0: Cannot find device "ppp0"
Jul  3 17:43:32 bambi diald[1879]: stop ppp0: SIOCSIFADDR: No such device
Jul  3 17:43:32 bambi diald[1879]: stop ppp0: ppp0: unknown interface: No such device
Jul  3 17:43:32 bambi diald[1879]: down ppp0: ppp0: unknown interface: No such device
Jul  3 17:43:32 bambi diald[1879]: Disconnected. Call duration 1732 seconds.
Jul  3 17:43:32 bambi diald[1879]: IP transmitted 1301408 bytes and received 579263 bytes.
Jul  3 17:43:34 bambi diald[1879]: Calling site 5.6.7.8
Jul  3 17:43:35 bambi chat[10398]: abort on (BUSY)
Jul  3 17:43:35 bambi chat[10398]: abort on (ERROR)
Jul  3 17:43:35 bambi chat[10398]: abort on (NO CARRIER)
Jul  3 17:43:35 bambi chat[10398]: abort on (NO DIALTONE)
Jul  3 17:43:35 bambi chat[10398]: abort on (Invalid Login)
Jul  3 17:43:35 bambi chat[10398]: abort on (Login incorrect)
Jul  3 17:43:35 bambi chat[10398]: report (CONNECT)
Jul  3 17:43:35 bambi chat[10398]: send (ATZ^M)
Jul  3 17:43:35 bambi chat[10398]: expect (OK)
Jul  3 17:43:36 bambi chat[10398]: ATZ^M^M
Jul  3 17:43:36 bambi chat[10398]: OK
Jul  3 17:43:36 bambi chat[10398]:  -- got it
Jul  3 17:43:36 bambi chat[10398]: send (ATL1M1^M)
Jul  3 17:43:36 bambi chat[10398]: expect (OK)
Jul  3 17:43:36 bambi chat[10398]: ^M
Jul  3 17:43:36 bambi chat[10398]: ATL1M1^M^M
Jul  3 17:43:36 bambi chat[10398]: OK
Jul  3 17:43:36 bambi chat[10398]:  -- got it
Jul  3 17:43:36 bambi chat[10398]: send (ATX4DT12345678^M)
Jul  3 17:43:36 bambi chat[10398]: expect (CONNECT)
Jul  3 17:43:36 bambi chat[10398]: ^M
Jul  3 17:43:57 bambi chat[10398]: ATX4DT12345678^M^M
Jul  3 17:43:57 bambi chat[10398]: CONNECT
Jul  3 17:43:57 bambi chat[10398]:  -- got it
Jul  3 17:43:57 bambi diald[1879]: connector: chat:  Jul 03 17:43:57 CONNECT 24000
Jul  3 17:43:57 bambi diald[1879]: Connected to site 5.6.7.8
Jul  3 17:43:57 bambi diald[1879]: Running pppd (pid = 10399).
Jul  3 17:43:57 bambi diald[10399]: Running pppd: /usr/sbin/pppd -defaultroute -detach modem crtscts mtu 1500 mru 1500 name myusername noauth noipdefault ipparam diald
Jul  3 17:43:57 bambi pppd[10399]: pppd 2.4.2b1 started by root, uid 0
Jul  3 17:43:57 bambi kernel: divert: not allocating divert_blk for non-ethernet device ppp0
Jul  3 17:43:57 bambi pppd[10399]: Using interface ppp0
Jul  3 17:43:57 bambi pppd[10399]: Connect: ppp0 <--> /dev/ttyS0
Jul  3 17:43:57 bambi /etc/hotplug/net.agent: assuming ppp0 is already up
Jul  3 17:44:01 bambi pppd[10399]: Remote message: ^@
Jul  3 17:44:01 bambi pppd[10399]: CHAP authentication succeeded
Jul  3 17:44:01 bambi pppd[10399]: local  IP address 1.2.3.4
Jul  3 17:44:01 bambi pppd[10399]: remote IP address 5.6.7.8
Jul  3 17:44:02 bambi e-smith[10437]: Processing event: ip-up ppp0 /dev/ttyS0 115200 1.2.3.4 5.6.7.8 diald
Jul  3 17:44:02 bambi e-smith[10437]: Running event handler: /etc/e-smith/events/ip-up/S20email-ipup
Jul  3 17:44:02 bambi e-smith[10437]: S20email-ipup=action|Event|ip-up|Action|S20email-ipup|Start|1088840642 84439|End|1088840642 302363|Elapsed|0.217924
Jul  3 17:44:02 bambi e-smith[10437]: Running event handler: /etc/e-smith/events/ip-up/S55set-gateway-ip
Jul  3 17:44:02 bambi diald[1879]: New addresses: local 1.2.3.4, remote 5.6.7.8, broadcast 0.0.0.0
Jul  3 17:44:02 bambi e-smith[10437]: S55set-gateway-ip=action|Event|ip-up|Action|S55set-gateway-ip|Start|1088840642 302775|End|1088840642 888829|Elapsed|0.586054
--------8<--------

Interestingly, the link initially on boot connected to the 0.0.0.0, then 28 minutes later kicked itself. As it is set to continuous connection it redialled immediately.

The SIGHUP caused:

Jul  3 17:43:28 bambi e-smith[10193]: Running event handler: /etc/e-smith/events/ip-down/S70pptp-interface-access
Jul  3 17:43:29 bambi e-smith[10193]: Use of uninitialized value in split at /etc/e-smith/events/ip-down/S70pptp-interface-access line 37.

so something is wrong in line 37 of S70pptp-interface-access at the very least.

Bear in mind that in that last log snippet I had already done a "service dhcpcd stop" so no dhcpcd errors got logged. To satiate my curiosity I did turn dhcpcd back on and the same old errors came back again. So I turned it back off - it doesn't seem necessary anyway.

Oops, it just redialled _again_! Back to the 5.6.7.8... good for it!

Sean

[spkelly]

Hmmm.

Just had a look at the dhcpcd bug in the bugs section - it appears to be not applicable to this case. I am not using eth0 and eth1, but eth0 and ppp0. No eth1 in the machine at all.

Maybe this is a bug? Does anyone else's SME exhibit the _same_ behaviour from a base install?

Sean

[Dexter Hansen]

dhcpc is now running and no errors.

I can't say I did anything to correct anything other than I found out my drive error (after my power supply replacement) was a pushed power supply pin going to the CDROM drive and then did about 4 reboots.

The only thing I can think of that I did differently was to allow the server to dial out from a request on it's own (lynx msn.com) rather than to use the "Force" option using DailMon 0.7.  That's a Win95 program set to Win95 compatibility in XP. I use it to kick the modem on, though if,  or rather when, I get a cable modem hookup next week, diald and dialmon will bopefully be a moot point, though it doesn't solve the problem for you.

Tryed some DialMon Forces/Down Links and still couldn't repeat either.

[ryan]

I also have this problem.  I used g4u to image a Dell PE400 SME server with 2 nic cards.  This image was applied to 2 additional Dell PE400s..but they have only the single onboard nic installed.  The 2 additional Dells are using 56K USRobotics modems.  

For now, I have removed the dhcpcd service from rc7.d and the servers seem to be fine.  When high speed is available, I will add this service back after a second nic is installed in the machine.

Can anyone confirm this problem on a stock install to a server with a single nic card?  This will tell me if my imaging is the problem here.

Thanks,

ryan