Sorry, forgot to Cc: the BTS again.
-------- Original Message --------
Subject: Re: Bug#304990: Kernel Panic with kernel-patch-mppe and kernel-source-2.6.11
Date: Mon, 18 Apr 2005 22:03:14 +1000
From: Pete <[EMAIL PROTECTED]>
To: Baruch Even <[EMAIL PROTECTED]>
References: <[EMAIL PROTECTED]> <[EMAIL PROTECTED]> <[EMAIL PROTECTED]> <[EMAIL PROTECTED]>
Baruch Even wrote:
If it didn't get saved to /var/log/syslog than it most likely scrolled off the screen anyway, at least some important parts of it.
The best is to setup a serial console to another machine, but if you are not already setup with it, it would be too much of a bother.
I don't have a setup of MPPE any more, so I can't try the solution myself, I'll try to cook some patch for you tomorrow. You can try to do it yourself by taking the patches for 2.6 kernels and:
sed -i -e 's/unsigned long/u32/' patchfile
Try to rebuild the kernel afterwards to see if it helps.
Baruch
Hi again Baruch,
We have mixed results from applying what you have said above to do.
I can now "pon PEERNAME" without a kernel panic, so success there!
However, the connection does not get made, but it does try. I'm not sure now if it's further issues with the mppe patch or if it's config errors.
Here's what I get in the syslog now:
Apr 18 21:45:22 babe pppd[6421]: pppd options in effect:
Apr 18 21:45:22 babe pppd[6421]: debug^I^I# (from /etc/ppp/options.pptp)
Apr 18 21:45:22 babe pppd[6421]: dump^I^I# (from /etc/ppp/options.pptp)
Apr 18 21:45:22 babe pppd[6421]: noauth^I^I# (from /etc/ppp/options.pptp)
Apr 18 21:45:22 babe pppd[6421]: name USERNAME^I^I# (from /etc/ppp/peers/PEERNAME)
Apr 18 21:45:22 babe pppd[6421]: remotename PEERNAME^I^I# (from /etc/ppp/peers/PEERNAME)
Apr 18 21:45:22 babe pppd[6421]: ^I^I# (from /etc/ppp/options.pptp)
Apr 18 21:45:22 babe pppd[6421]: pty pptp aaa.bbb.ccc.ddd --nolaunchpppd^I^I# (from /etc/ppp/peers/PEERNAME)
Apr 18 21:45:22 babe pppd[6421]: crtscts^I^I# (from /etc/ppp/options)
Apr 18 21:45:22 babe pppd[6421]: ^I^I# (from /etc/ppp/options)
Apr 18 21:45:22 babe pppd[6421]: asyncmap 0^I^I# (from /etc/ppp/options)
Apr 18 21:45:23 babe pppd[6421]: mtu 996^I^I# (from /etc/ppp/options.pptp)
Apr 18 21:45:23 babe pppd[6421]: lcp-echo-failure 4^I^I# (from /etc/ppp/options)
Apr 18 21:45:23 babe pppd[6421]: lcp-echo-interval 30^I^I# (from /etc/ppp/options)
Apr 18 21:45:23 babe pppd[6421]: hide-password^I^I# (from /etc/ppp/options)
Apr 18 21:45:23 babe pppd[6421]: ipparam PEERNAME^I^I# (from /etc/ppp/peers/PEERNAME)
Apr 18 21:45:23 babe pppd[6421]: proxyarp^I^I# (from /etc/ppp/options)
Apr 18 21:45:23 babe pppd[6421]: nobsdcomp^I^I# (from /etc/ppp/options.pptp)
Apr 18 21:45:23 babe pppd[6421]: nodeflate^I^I# (from /etc/ppp/options.pptp)
Apr 18 21:45:23 babe pppd[6421]: require-mppe-128^I^I# (from /etc/ppp/peers/PEERNAME)
Apr 18 21:45:23 babe pppd[6421]: noipx^I^I# (from /etc/ppp/options)
Apr 18 21:45:23 babe pppd[6422]: pppd 2.4.3 started by root, uid 0
Apr 18 21:45:23 babe pppd[6422]: using channel 7
Apr 18 21:45:23 babe pppd[6422]: Using interface ppp0
Apr 18 21:45:23 babe pppd[6422]: Connect: ppp0 <--> /dev/pts/1
Apr 18 21:45:23 babe pptp[6423]: anon log[main:pptp.c:243]: The synchronous pptp option is NOT activated
Apr 18 21:45:23 babe pptp[6435]: anon log[ctrlp_rep:pptp_ctrl.c:243]: Sent control packet type is 1 'Start-Control-Connection-Request'
Apr 18 21:45:23 babe pptp[6435]: anon log[ctrlp_disp:pptp_ctrl.c:721]: Received Start Control Connection Reply
Apr 18 21:45:23 babe pptp[6435]: anon log[ctrlp_disp:pptp_ctrl.c:755]: Client connection established.
Apr 18 21:45:24 babe pppd[6422]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xbce7b785> <pcomp> <accomp>]
Apr 18 21:45:24 babe pptp[6435]: anon log[ctrlp_rep:pptp_ctrl.c:243]: Sent control packet type is 7 'Outgoing-Call-Request'
Apr 18 21:45:24 babe pptp[6435]: anon log[ctrlp_disp:pptp_ctrl.c:841]: Received Outgoing Call Reply.
Apr 18 21:45:24 babe pptp[6435]: anon log[ctrlp_disp:pptp_ctrl.c:880]: Outgoing call established (call ID 0, peer's call ID 51917).
Apr 18 21:45:27 babe pppd[6422]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xbce7b785> <pcomp> <accomp>]
Apr 18 21:45:51 babe last message repeated 8 times
Apr 18 21:45:54 babe pppd[6422]: LCP: timeout sending Config-Requests
Apr 18 21:45:54 babe pppd[6422]: Connection terminated.
Apr 18 21:45:54 babe pppd[6422]: using channel 8
Apr 18 21:45:54 babe pptp[6456]: anon log[main:pptp.c:243]: The synchronous pptp option is NOT activated
Apr 18 21:45:54 babe pptp[6435]: anon log[ctrlp_rep:pptp_ctrl.c:243]: Sent control packet type is 7 'Outgoing-Call-Request'
Apr 18 21:45:54 babe pppd[6422]: Using interface ppp0
Apr 18 21:45:54 babe pppd[6422]: Connect: ppp0 <--> /dev/pts/2
Apr 18 21:45:54 babe pppd[6422]: Waiting for 2 child processes...
Apr 18 21:45:54 babe pppd[6422]: script pptp aaa.bbb.ccc.ddd --nolaunchpppd, pid 6456
Apr 18 21:45:54 babe pppd[6422]: script pptp aaa.bbb.ccc.ddd --nolaunchpppd, pid 6423
Apr 18 21:45:54 babe pptp[6435]: anon log[ctrlp_disp:pptp_ctrl.c:841]: Received Outgoing Call Reply.
Apr 18 21:45:54 babe pptp[6435]: anon warn[ctrlp_disp:pptp_ctrl.c:853]: Unexpected(?) Outgoing Call Reply will be ignored.
Apr 18 21:45:59 babe pppd[6422]: sending SIGTERM to process 6456
Apr 18 21:45:59 babe pppd[6422]: sending SIGTERM to process 6423
Apr 18 21:45:59 babe pppd[6422]: tcflush failed: Bad file descriptor
Apr 18 21:45:59 babe pptp[6435]: anon log[callmgr_main:pptp_callmgr.c:228]: Closing connection
Apr 18 21:45:59 babe pptp[6435]: anon log[ctrlp_rep:pptp_ctrl.c:243]: Sent control packet type is 12 'Call-Clear-Request'
Apr 18 21:45:59 babe pptp[6435]: anon log[callmgr_main:pptp_callmgr.c:228]: Closing connection
Apr 18 21:45:59 babe pptp[6435]: anon log[ctrlp_rep:pptp_ctrl.c:243]: Sent control packet type is 12 'Call-Clear-Request'
Apr 18 21:45:59 babe pppd[6422]: Exit.
Apr 18 21:45:59 babe pptp[6435]: anon log[ctrlp_disp:pptp_ctrl.c:912]: Call disconnect notification received (call id 52173)
Apr 18 21:45:59 babe pptp[6435]: anon log[ctrlp_rep:pptp_ctrl.c:243]: Sent control packet type is 12 'Call-Clear-Request'
Apr 18 21:45:59 babe pptp[6435]: anon log[ctrlp_rep:pptp_ctrl.c:243]: Sent control packet type is 12 'Call-Clear-Request'
Apr 18 21:45:59 babe pptp[6435]: anon log[pptp_conn_close:pptp_ctrl.c:425]: Closing PPTP connection
Apr 18 21:45:59 babe pptp[6435]: anon log[ctrlp_rep:pptp_ctrl.c:243]: Sent control packet type is 3 'Stop-Control-Connection-Request'
Apr 18 21:45:59 babe pptp[6435]: anon log[ctrlp_disp:pptp_ctrl.c:912]: Call disconnect notification received (call id 65535)
Apr 18 21:46:01 babe pptp[6435]: anon log[call_callback:pptp_callmgr.c:77]: Closing connection
I might be on the wrong track, but the two bits that stick out to me are these:
Apr 18 21:45:54 babe pppd[6422]: Waiting for 2 child processes...
Apr 18 21:45:54 babe pppd[6422]: script pptp aaa.bbb.ccc.ddd --nolaunchpppd, pid 6456
Apr 18 21:45:54 babe pppd[6422]: script pptp aaa.bbb.ccc.ddd --nolaunchpppd, pid 6423
Apr 18 21:45:59 babe pppd[6422]: tcflush failed: Bad file descriptor
I'm not sure about the second one, but I don't think it's right that pppd should be launching two processes.
You'll also note that it times out at 21:45:54 sending Config-Requests.
Do you think this is still a bug with mppe or maybe a config error or even a bug in pppd perhaps?
This is what I did to apply the patch you suggested:
cd /usr/src/kernel-patches/all/apply sed -i -e 's/unsigned long/u32/' mppe
I then recompiled my kernel exactly the same way as I did initially, but adjusting the revision to 1.2.
I've logged in to work and checked the logs on the VPN server (which is a SnapGear), and the two attempted connections do appear to be causing a serious issue going by what is logged:
Apr 18 21:45:23 pptpd[21812]: CTRL: Client eee.fff.ggg.hhh control connection started Apr 18 21:45:24 pptpd[21812]: CTRL: Starting call (launching pppd, opening GRE) Apr 18 21:45:24 pptpd[21812]: CTRL: Allocating pty/tty pair Apr 18 21:45:24 pptpd[21812]: CTRL: Allocated pty/tty pair (/dev/ptyp0,/dev/ttyp0) Apr 18 21:45:24 pppd[21813]: Using interface ppp0 Apr 18 21:45:24 pppd[21813]: pppd create pidfile Apr 18 21:45:24 pppd[21813]: Connect: ppp0 <--> /dev/ttyp0 Apr 18 21:45:24 pppd[21813]: Will not do PAP for user PoPToP Apr 18 21:45:24 pppd[21813]: Will not do CHAP for user PoPToP Apr 18 21:45:54 pptpd[21812]: CTRL: Asked to allocate call id when call open, not handled well Apr 18 21:45:54 pptpd[21812]: CTRL: Request to open call when call is already open, closing Apr 18 21:45:54 pptpd[21812]: CTRL: Starting call (launching pppd, opening GRE) Apr 18 21:45:54 pptpd[21812]: CTRL: Allocating pty/tty pair Apr 18 21:45:54 pptpd[21812]: CTRL: Allocated pty/tty pair (/dev/ptyp1,/dev/ttyp1) Apr 18 21:45:54 klogd: ip_conntrack: max number of expected connections 2 of pptp reached for eee.fff.ggg.hhh->aaa.bbb.ccc.ddd, reusing Apr 18 21:45:54 pppd[21813]: Modem hangup Apr 18 21:45:54 pppd[21813]: Connection terminated. Apr 18 21:45:54 pppd[21813]: Exit. Apr 18 21:45:54 pppd[21814]: Using interface ppp0 Apr 18 21:45:54 pppd[21814]: pppd create pidfile Apr 18 21:45:54 pppd[21814]: Connect: ppp0 <--> /dev/ttyp1 Apr 18 21:45:54 pppd[21814]: Will not do PAP for user PoPToP Apr 18 21:45:54 pppd[21814]: Will not do CHAP for user PoPToP Apr 18 21:45:59 pppd[21814]: Modem hangup Apr 18 21:45:59 pppd[21814]: Connection terminated. Apr 18 21:45:59 pppd[21814]: Exit. Apr 18 21:45:59 pptpd[21812]: CTRL: Asked to free call when no call open, not handled well Apr 18 21:45:59 pptpd[21812]: CTRL: Could not free Call ID [call clear]! Apr 18 21:45:59 pptpd[21812]: CTRL: Request to close call but call not open Apr 18 21:45:59 pptpd[21812]: CTRL: Asked to free call when no call open, not handled well Apr 18 21:45:59 pptpd[21812]: CTRL: Could not free Call ID [call clear]! Apr 18 21:45:59 pptpd[21812]: CTRL: Request to close call but call not open Apr 18 21:45:59 pptpd[21812]: CTRL: Asked to free call when no call open, not handled well Apr 18 21:45:59 pptpd[21812]: CTRL: Could not free Call ID [call clear]! Apr 18 21:45:59 pptpd[21812]: CTRL: Request to close call but call not open Apr 18 21:45:59 pptpd[21812]: CTRL: Client eee.fff.ggg.hhh control connection finished
Once again, I've sensored the private information, and "aaa.bbb.ccc.ddd" is the server IP and "eee.fff.ggg.hhh" is my home IP.
I hope this helps somehow...
Pete
-- To UNSUBSCRIBE, email to [EMAIL PROTECTED] with a subject of "unsubscribe". Trouble? Contact [EMAIL PROTECTED]
