LCP: timeout sending Config-Requests

Bob Mancker bmancker at gmail.com
Sat Apr 16 07:05:07 UTC 2005 

I've googled and been all over IRC with this. If anyone is on IRC and
wouldn't mind helping me on IRC let me know what server/channel you
are in. Anyhow, I can connect fine on ppp0, but when I have ppp1 or
another ppp connection I get LCP: timeout sending Config-Requests ...

In /var/log/messages I get:
Apr 16 14:56:14 rickp4a pppd[14664]: LCP: timeout sending Config-Requests

Here is the pppd debug file:
Apr 16 14:55:44 rickp4a pptpd[14663]: CTRL: Client 68.68.53.12 control
connection started
Apr 16 14:55:44 rickp4a pptpd[14663]: CTRL: Starting call (launching
pppd, opening GRE)
Apr 16 14:55:44 rickp4a pppd[14664]: Plugin radius.so loaded.
Apr 16 14:55:44 rickp4a pppd[14664]: RADIUS plugin initialized.
Apr 16 14:55:44 rickp4a pppd[14664]: Plugin
/usr/lib/pptpd/pptpd-logwtmp.so loaded.
Apr 16 14:55:44 rickp4a pppd[14664]: pptpd-logwtmp: $Version$
Apr 16 14:55:44 rickp4a pppd[14664]: pppd 2.4.3 started by root, uid 0
Apr 16 14:55:44 rickp4a pppd[14664]: using channel 301
Apr 16 14:55:44 rickp4a kernel: divert: not allocating divert_blk for
non-ethernet device ppp1
Apr 16 14:55:44 rickp4a pppd[14664]: Using interface ppp1
Apr 16 14:55:44 rickp4a pppd[14664]: Connect: ppp1 <--> /dev/pts/259
Apr 16 14:55:44 rickp4a pppd[14664]: sent [LCP ConfReq id=0x1
<asyncmap 0x0> <auth chap MS-v2> <magic 0xad37d929> <pcomp> <accomp>]
Apr 16 14:55:44 rickp4a pptpd[14663]: GRE: Bad checksum from pppd.
Apr 16 14:55:45 rickp4a pppd[14654]: rcvd [LCP ConfReq id=0xb <mru
1400> <magic 0x35d56d16> <pcomp> <accomp>]
Apr 16 14:55:45 rickp4a pppd[14654]: pptpd-logwtmp.so ip-down ppp0
Apr 16 14:55:45 rickp4a pppd[14654]: Connect time 4.8 minutes.
Apr 16 14:55:45 rickp4a pppd[14654]: Sent 610 bytes, received 4426 bytes.
Apr 16 14:55:45 rickp4a pppd[14654]: Script /etc/ppp/ip-down started (pid 14672)
Apr 16 14:55:45 rickp4a pppd[14654]: MPPE disabled
Apr 16 14:55:45 rickp4a pppd[14654]: sent [LCP TermReq id=0x4 "MPPE disabled"]
Apr 16 14:55:45 rickp4a pppd[14654]: sent [LCP ConfReq id=0x5
<asyncmap 0x0> <auth chap MS-v2> <magic 0xd885757> <pcomp> <accomp>]
Apr 16 14:55:45 rickp4a pppd[14654]: sent [LCP ConfAck id=0xb <mru
1400> <magic 0x35d56d16> <pcomp> <accomp>]
Apr 16 14:55:45 rickp4a pppd[14654]: rcvd [LCP ConfAck id=0x1
<asyncmap 0x0> <auth chap MS-v2> <magic 0xad37d929> <pcomp> <accomp>]
Apr 16 14:55:45 rickp4a pppd[14654]: Script /etc/ppp/ip-down finished
(pid 14672), status = 0x0
Apr 16 14:55:45 rickp4a pppd[14654]: rcvd [LCP ConfAck id=0x5
<asyncmap 0x0> <auth chap MS-v2> <magic 0xd885757> <pcomp> <accomp>]
Apr 16 14:55:45 rickp4a pppd[14654]: sent [CHAP Challenge id=0x14
<9ca0069c6e52773f36e1f60a86cd1cd9>, name = "pptpd"]
Apr 16 14:55:45 rickp4a pppd[14654]: rcvd [LCP TermAck id=0x4 "MPPE disabled"]
Apr 16 14:55:45 rickp4a pppd[14654]: sent [LCP ConfReq id=0x6
<asyncmap 0x0> <auth chap MS-v2> <magic 0xaa2944cf> <pcomp> <accomp>]
Apr 16 14:55:45 rickp4a pptpd[14653]: CTRL: Ignored a SET LINK INFO
packet with real ACCMs!
Apr 16 14:55:47 rickp4a pppd[14664]: sent [LCP ConfReq id=0x1
<asyncmap 0x0> <auth chap MS-v2> <magic 0xad37d929> <pcomp> <accomp>]
Apr 16 14:55:48 rickp4a pppd[14654]: sent [LCP ConfReq id=0x6
<asyncmap 0x0> <auth chap MS-v2> <magic 0xaa2944cf> <pcomp> <accomp>]
Apr 16 14:55:48 rickp4a pppd[14654]: sent [LCP ConfReq id=0x6
<asyncmap 0x0> <auth chap MS-v2> <magic 0xaa2944cf> <pcomp> <accomp>]
Apr 16 14:55:49 rickp4a pppd[14654]: Modem hangup
Apr 16 14:55:49 rickp4a pptpd[14653]: CTRL: Reaping child PPP[14654]
Apr 16 14:55:49 rickp4a pppd[14654]: Connection terminated.
Apr 16 14:55:49 rickp4a pppd[14654]: Exit.
Apr 16 14:55:49 rickp4a pptpd[14653]: CTRL: Client 68.68.53.12 control
connection finished
Apr 16 14:55:49 rickp4a kernel: divert: no divert_blk to free, ppp0 not ethernet
Apr 16 14:55:50 rickp4a pppd[14664]: sent [LCP ConfReq id=0x1
<asyncmap 0x0> <auth chap MS-v2> <magic 0xad37d929> <pcomp> <accomp>]
Apr 16 14:56:11 rickp4a last message repeated 7 times
Apr 16 14:56:14 rickp4a pppd[14664]: LCP: timeout sending Config-Requests
Apr 16 14:56:14 rickp4a pppd[14664]: Connection terminated.
Apr 16 14:56:14 rickp4a kernel: divert: no divert_blk to free, ppp1 not ethernet
Apr 16 14:56:14 rickp4a pppd[14664]: using channel 302
Apr 16 14:56:14 rickp4a pppd[14664]: Using interface ppp0
Apr 16 14:56:14 rickp4a pppd[14664]: Connect: ppp0 <--> /dev/pts/259
Apr 16 14:56:14 rickp4a pppd[14664]: sent [LCP ConfReq id=0x2
<asyncmap 0x0> <auth chap MS-v2> <magic 0xf5a4689d> <pcomp> <accomp>]
Apr 16 14:56:14 rickp4a pppd[14664]: tcflush failed: Bad file descriptor
Apr 16 14:56:14 rickp4a kernel: divert: not allocating divert_blk for
non-ethernet device ppp0
Apr 16 14:56:14 rickp4a kernel: divert: no divert_blk to free, ppp0 not ethernet
Apr 16 14:56:14 rickp4a pppd[14664]: tcsetattr: Invalid argument (line 1016)
Apr 16 14:56:14 rickp4a pppd[14664]: Exit.
Apr 16 14:56:14 rickp4a pptpd[14663]: GRE:
read(fd=6,buffer=804eb00,len=8196) from PTY failed: status = -1 error
= Input/output error, usually caused by unexpected termination of
pppd, check option syntax and pppd logs
Apr 16 14:56:14 rickp4a pptpd[14663]: CTRL: PTY read or GRE write
failed (pty,gre)=(6,7)
Apr 16 14:56:14 rickp4a pptpd[14663]: CTRL: Reaping child PPP[14664]
Apr 16 14:56:14 rickp4a pptpd[14663]: CTRL: Client 68.68.53.12 control
connection finished
Apr 16 15:01:00 rickp4a CROND[14708]: (root) CMD (run-parts /etc/cron.hourly)

And in the debugd -X for radius I get this:
rad_recv: Accounting-Request packet from host 127.0.0.1:32849, id=127,
length=146
        Acct-Session-Id = "4260B5D6393E00"
        User-Name = "test2"
        Acct-Status-Type = Stop
        Service-Type = Framed-User
        Framed-Protocol = PPP
        Acct-Authentic = RADIUS
        Acct-Session-Time = 283
        Acct-Output-Octets = 610
        Acct-Input-Octets = 4426
        Acct-Output-Packets = 3
        Acct-Input-Packets = 32
        Calling-Station-Id = "68.68.53.12"
        NAS-Port-Type = Async
        Acct-Terminate-Cause = User-Request
        Framed-IP-Address = 192.168.222.2
        NAS-IP-Address = 127.0.0.1
        NAS-Port = 0
        Acct-Delay-Time = 0
  Processing the preacct section of radiusd.conf
modcall: entering group preacct for request 19
  modcall[preacct]: module "preprocess" returns noop for request 19
rlm_acct_unique: Hashing 'NAS-Port = 0,Client-IP-Address =
127.0.0.1,NAS-IP-Address = 127.0.0.1,Acct-Session-Id =
"4260B5D6393E00",User-Name = "test2"'
rlm_acct_unique: Acct-Unique-Session-ID = "5f7f6aecf3d5f43a".
  modcall[preacct]: module "acct_unique" returns ok for request 19
    rlm_realm: No '@' in User-Name = "test2", looking up realm NULL
    rlm_realm: No such realm "NULL"
  modcall[preacct]: module "suffix" returns noop for request 19
  modcall[preacct]: module "files" returns noop for request 19
modcall: group preacct returns ok for request 19
  Processing the accounting section of radiusd.conf
modcall: entering group accounting for request 19
radius_xlat:  '/var/log/radius/radacct/127.0.0.1/detail-20050416'
rlm_detail: /var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d
expands to /var/log/radius/radacct/127.0.0.1/detail-20050416
  modcall[accounting]: module "detail" returns ok for request 19
  modcall[accounting]: module "unix" returns ok for request 19
radius_xlat:  '/var/log/radius/radutmp'
radius_xlat:  'test2'
  modcall[accounting]: module "radutmp" returns ok for request 19
modcall: group accounting returns ok for request 19
Sending Accounting-Response of id 127 to 127.0.0.1:32849
Finished request 19
Going to the next request
--- Walking the entire request list ---
Waking up in 6 seconds...
--- Walking the entire request list ---
Cleaning up request 19 ID 127 with timestamp 4260b6f1
Nothing to do.  Sleeping until we see a request.



Hmm... any advice?
Kinda strange.... and it's getting to me.

More information about the Pam-list mailing list