PPP WAN on 4G drops randomly and does not reconnect
-
Hi guys,
I'm experiencing random drops in 4G connectivity without successful restore of the connection. The connection drops happen randomly once a month, beside the connection is rocket stable. Maybe the connection drop is triggered by an issue on the carrier side, however, I'd expect that pfSense successfully reconnects afterwards. It seems that it tries without success.
Unfortunately I'm not a wireless expert :( As soon as the device is restarted, the modem connects fine again.
My setup is as follows: PC Engines APU2 with Sierra MC7710 on German Telekom network in a remote location (good coverage).
Please find the ppp log below. If there is anything else required, I'm happy to supply.
Thank you for any input!
Mar 4 05:54:56 pvob ppp: [wan_link0] LCP: no reply to 1 echo request(s) Mar 4 05:55:06 pvob ppp: [wan_link0] LCP: no reply to 2 echo request(s) Mar 4 05:55:16 pvob ppp: [wan_link0] LCP: no reply to 3 echo request(s) Mar 4 05:55:26 pvob ppp: [wan_link0] LCP: no reply to 4 echo request(s) Mar 4 05:55:36 pvob ppp: [wan_link0] LCP: no reply to 5 echo request(s) Mar 4 05:55:36 pvob ppp: [wan_link0] LCP: peer not responding to echo requests Mar 4 05:55:36 pvob ppp: [wan_link0] LCP: state change Opened --> Stopping Mar 4 05:55:36 pvob ppp: [wan_link0] Link: Leave bundle "wan" Mar 4 05:55:36 pvob ppp: [wan] Bundle: Status update: up 0 links, total bandwidth 9600 bps Mar 4 05:55:36 pvob ppp: [wan] IPCP: Close event Mar 4 05:55:36 pvob ppp: [wan] IPCP: state change Opened --> Closing Mar 4 05:55:36 pvob ppp: [wan] IPCP: SendTerminateReq #22 Mar 4 05:55:36 pvob ppp: [wan] IPCP: LayerDown Mar 4 05:55:36 pvob check_reload_status: Rewriting resolv.conf Mar 4 05:55:36 pvob ppp: [wan] IFACE: Down event Mar 4 05:55:36 pvob ppp: [wan] IFACE: Rename interface ppp0 to ppp0 Mar 4 05:55:36 pvob ppp: [wan] IPV6CP: Close event Mar 4 05:55:36 pvob ppp: [wan] IPV6CP: state change Stopped --> Closed Mar 4 05:55:36 pvob ppp: [wan] IPCP: Down event Mar 4 05:55:36 pvob ppp: [wan] IPCP: LayerFinish Mar 4 05:55:36 pvob ppp: [wan] Bundle: No NCPs left. Closing links... Mar 4 05:55:36 pvob ppp: [wan] IPCP: state change Closing --> Initial Mar 4 05:55:36 pvob ppp: [wan] IPV6CP: Down event Mar 4 05:55:36 pvob ppp: [wan] IPV6CP: state change Closed --> Initial Mar 4 05:55:36 pvob ppp: [wan_link0] LCP: SendTerminateReq #8 Mar 4 05:55:36 pvob ppp: [wan_link0] LCP: LayerDown Mar 4 05:55:38 pvob ppp: [wan_link0] LCP: SendTerminateReq #9 Mar 4 05:55:40 pvob ppp: [wan_link0] LCP: state change Stopping --> Stopped Mar 4 05:55:40 pvob ppp: [wan_link0] LCP: LayerFinish Mar 4 05:55:40 pvob ppp: [wan_link0] Link: DOWN event Mar 4 05:55:40 pvob ppp: [wan_link0] LCP: Down event Mar 4 05:55:40 pvob ppp: [wan_link0] LCP: state change Stopped --> Starting Mar 4 05:55:40 pvob ppp: [wan_link0] LCP: LayerStart Mar 4 05:55:40 pvob ppp: [wan_link0] Link: reconnection attempt 1 in 4 seconds Mar 4 05:55:44 pvob ppp: [wan_link0] Link: reconnection attempt 1 Mar 4 05:55:44 pvob ppp: [wan_link0] CHAT: Detected Hayes compatible modem. Mar 4 05:55:47 pvob ppp: [wan_link0] CHAT: The modem is not responding to "AT&F&C1&D2E0S0=0M1" at ModemCmd: label. Mar 4 05:55:47 pvob ppp: [wan_link0] MODEM: chat script failed Mar 4 05:55:47 pvob ppp: [wan_link0] Link: DOWN event Mar 4 05:55:47 pvob ppp: [wan_link0] LCP: Down event Mar 4 05:55:47 pvob ppp: [wan_link0] Link: reconnection attempt 2 in 2 seconds Mar 4 05:55:49 pvob ppp: [wan_link0] Link: reconnection attempt 2 Mar 4 05:56:03 pvob ppp: [wan_link0] CHAT: The modem is not responding to "AT" at ModemCmd: label. Mar 4 05:56:03 pvob ppp: [wan_link0] MODEM: chat script failed Mar 4 05:56:03 pvob ppp: [wan_link0] Link: DOWN event Mar 4 05:56:03 pvob ppp: [wan_link0] LCP: Down event Mar 4 05:56:03 pvob ppp: [wan_link0] Link: reconnection attempt 3 in 3 seconds Mar 4 05:56:06 pvob ppp: [wan_link0] Link: reconnection attempt 3 Mar 4 05:56:20 pvob ppp: [wan_link0] CHAT: The modem is not responding to "AT" at ModemCmd: label. Mar 4 05:56:20 pvob ppp: [wan_link0] MODEM: chat script failed Mar 4 05:56:20 pvob ppp: [wan_link0] Link: DOWN event Mar 4 05:56:20 pvob ppp: [wan_link0] LCP: Down event Mar 4 05:56:20 pvob ppp: [wan_link0] Link: reconnection attempt 4 in 2 seconds Mar 4 05:56:22 pvob ppp: [wan_link0] Link: reconnection attempt 4 Mar 4 05:56:23 pvob ppp: [wan_link0] CHAT: +CGDCONT=1,"IP","Internet.t-d1.de" Mar 4 05:56:23 pvob ppp: [wan_link0] CHAT: Detected Hayes compatible modem. Mar 4 05:56:23 pvob ppp: [wan_link0] CHAT: Dialing server at *99#... Mar 4 05:56:23 pvob ppp: [wan_link0] CHAT: ATDT*99# Mar 4 05:56:23 pvob ppp: [wan_link0] CHAT: Connected at 100000000. Mar 4 05:56:23 pvob ppp: [wan_link0] MODEM: chat script succeeded Mar 4 05:56:23 pvob ppp: [wan_link0] Link: UP event Mar 4 05:56:23 pvob ppp: [wan_link0] LCP: Up event Mar 4 05:56:23 pvob ppp: [wan_link0] LCP: state change Starting --> Req-Sent Mar 4 05:56:23 pvob ppp: [wan_link0] LCP: SendConfigReq #10 Mar 4 05:56:23 pvob ppp: [wan_link0] ACFCOMP Mar 4 05:56:23 pvob ppp: [wan_link0] PROTOCOMP Mar 4 05:56:23 pvob ppp: [wan_link0] ACCMAP 0x000a0000 Mar 4 05:56:23 pvob ppp: [wan_link0] MRU 1500 Mar 4 05:56:23 pvob ppp: [wan_link0] MAGICNUM 0x8f0c9bf1 Mar 4 05:56:23 pvob ppp: [wan_link0] LCP: rec'd Configure Request #11 (Req-Sent) Mar 4 05:56:23 pvob ppp: [wan_link0] ACCMAP 0x00000000 Mar 4 05:56:23 pvob ppp: [wan_link0] AUTHPROTO CHAP MD5 Mar 4 05:56:23 pvob ppp: [wan_link0] MAGICNUM 0x4f1e7b2c Mar 4 05:56:23 pvob ppp: [wan_link0] PROTOCOMP Mar 4 05:56:23 pvob ppp: [wan_link0] ACFCOMP Mar 4 05:56:23 pvob ppp: [wan_link0] LCP: SendConfigAck #11 Mar 4 05:56:23 pvob ppp: [wan_link0] ACCMAP 0x00000000 Mar 4 05:56:23 pvob ppp: [wan_link0] AUTHPROTO CHAP MD5 Mar 4 05:56:23 pvob ppp: [wan_link0] MAGICNUM 0x4f1e7b2c Mar 4 05:56:23 pvob ppp: [wan_link0] PROTOCOMP Mar 4 05:56:23 pvob ppp: [wan_link0] ACFCOMP Mar 4 05:56:23 pvob ppp: [wan_link0] LCP: state change Req-Sent --> Ack-Sent Mar 4 05:56:23 pvob ppp: [wan_link0] LCP: rec'd Configure Ack #10 (Ack-Sent) Mar 4 05:56:23 pvob ppp: [wan_link0] ACFCOMP Mar 4 05:56:23 pvob ppp: [wan_link0] PROTOCOMP Mar 4 05:56:23 pvob ppp: [wan_link0] ACCMAP 0x000a0000 Mar 4 05:56:23 pvob ppp: [wan_link0] MRU 1500 Mar 4 05:56:23 pvob ppp: [wan_link0] MAGICNUM 0x8f0c9bf1 Mar 4 05:56:23 pvob ppp: [wan_link0] LCP: state change Ack-Sent --> Opened Mar 4 05:56:23 pvob ppp: [wan_link0] LCP: auth: peer wants CHAP, I want nothing Mar 4 05:56:23 pvob ppp: [wan_link0] LCP: LayerUp Mar 4 05:56:23 pvob ppp: [wan_link0] LCP: rec'd Discard Request #12 (Opened) Mar 4 05:56:23 pvob ppp: [wan_link0] CHAP: rec'd CHALLENGE #1 len: 35 Mar 4 05:56:23 pvob ppp: [wan_link0] Name: "UMTS_CHAP_SRVR" Mar 4 05:56:23 pvob ppp: [wan_link0] CHAP: Using authname "t-mobile" Mar 4 05:56:23 pvob ppp: [wan_link0] CHAP: sending RESPONSE #1 len: 29 Mar 4 05:56:23 pvob ppp: [wan_link0] CHAP: rec'd SUCCESS #1 len: 4 Mar 4 05:56:23 pvob ppp: [wan_link0] LCP: authorization successful Mar 4 05:56:23 pvob ppp: [wan_link0] Link: Matched action 'bundle "wan" ""' Mar 4 05:56:23 pvob ppp: [wan_link0] Link: Join bundle "wan" Mar 4 05:56:23 pvob ppp: [wan] Bundle: Status update: up 1 link, total bandwidth 100000000 bps Mar 4 05:56:23 pvob ppp: [wan] IPCP: Open event Mar 4 05:56:23 pvob ppp: [wan] IPCP: state change Initial --> Starting Mar 4 05:56:23 pvob ppp: [wan] IPCP: LayerStart Mar 4 05:56:23 pvob ppp: [wan] IPV6CP: Open event Mar 4 05:56:23 pvob ppp: [wan] IPV6CP: state change Initial --> Starting Mar 4 05:56:23 pvob ppp: [wan] IPV6CP: LayerStart Mar 4 05:56:23 pvob ppp: [wan] IPCP: Up event Mar 4 05:56:23 pvob ppp: [wan] IPCP: state change Starting --> Req-Sent Mar 4 05:56:23 pvob ppp: [wan] IPCP: SendConfigReq #23 Mar 4 05:56:23 pvob ppp: [wan] IPADDR 0.0.0.0 Mar 4 05:56:23 pvob ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Mar 4 05:56:23 pvob ppp: [wan] IPV6CP: Up event Mar 4 05:56:23 pvob ppp: [wan] IPV6CP: state change Starting --> Req-Sent Mar 4 05:56:23 pvob ppp: [wan] IPV6CP: SendConfigReq #31 Mar 4 05:56:24 pvob ppp: [wan] IPCP: rec'd Configure Nak #23 (Req-Sent) Mar 4 05:56:24 pvob ppp: [wan] IPCP: SendConfigReq #24 Mar 4 05:56:24 pvob ppp: [wan] IPADDR 0.0.0.0 Mar 4 05:56:24 pvob ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Mar 4 05:56:25 pvob ppp: [wan] IPV6CP: SendConfigReq #32 Mar 4 05:56:25 pvob ppp: [wan] IPCP: rec'd Configure Nak #24 (Req-Sent) Mar 4 05:56:25 pvob ppp: [wan] IPCP: SendConfigReq #25 Mar 4 05:56:25 pvob ppp: [wan] IPADDR 0.0.0.0 Mar 4 05:56:25 pvob ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Mar 4 05:56:26 pvob ppp: [wan] IPCP: rec'd Configure Nak #25 (Req-Sent) Mar 4 05:56:26 pvob ppp: [wan] IPCP: SendConfigReq #26 Mar 4 05:56:26 pvob ppp: [wan] IPADDR 0.0.0.0 Mar 4 05:56:26 pvob ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Mar 4 05:56:27 pvob ppp: [wan] IPV6CP: SendConfigReq #33 Mar 4 05:56:27 pvob ppp: [wan] IPCP: rec'd Configure Nak #26 (Req-Sent) Mar 4 05:56:27 pvob ppp: [wan] IPCP: SendConfigReq #27 Mar 4 05:56:27 pvob ppp: [wan] IPADDR 0.0.0.0 Mar 4 05:56:27 pvob ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Mar 4 05:56:27 pvob ppp: [wan] IPCP: SendConfigReq #27 Mar 4 05:56:27 pvob ppp: [wan] IPADDR 0.0.0.0 Mar 4 05:56:27 pvob ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Mar 4 05:56:28 pvob ppp: [wan] IPCP: rec'd Configure Nak #27 (Req-Sent) Mar 4 05:56:28 pvob ppp: [wan] IPCP: SendConfigReq #28 Mar 4 05:56:28 pvob ppp: [wan] IPADDR 0.0.0.0 Mar 4 05:56:28 pvob ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Mar 4 05:56:29 pvob ppp: [wan] IPV6CP: SendConfigReq #34 Mar 4 05:56:29 pvob ppp: [wan] IPCP: rec'd Configure Nak #28 (Req-Sent) Mar 4 05:56:29 pvob ppp: [wan] IPCP: SendConfigReq #29 Mar 4 05:56:29 pvob ppp: [wan] IPADDR 0.0.0.0 Mar 4 05:56:29 pvob ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Mar 4 05:56:30 pvob ppp: [wan] IPCP: rec'd Configure Nak #29 (Req-Sent) Mar 4 05:56:30 pvob ppp: [wan] IPCP: SendConfigReq #30 Mar 4 05:56:30 pvob ppp: [wan] IPADDR 0.0.0.0 Mar 4 05:56:30 pvob ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Mar 4 05:56:31 pvob ppp: [wan] IPV6CP: SendConfigReq #35 Mar 4 05:56:31 pvob ppp: [wan] IPCP: rec'd Configure Nak #30 (Req-Sent) Mar 4 05:56:31 pvob ppp: [wan] IPCP: SendConfigReq #31 Mar 4 05:56:31 pvob ppp: [wan] IPADDR 0.0.0.0 Mar 4 05:56:31 pvob ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Mar 4 05:56:32 pvob ppp: [wan] IPCP: rec'd Configure Nak #31 (Req-Sent) Mar 4 05:56:32 pvob ppp: [wan] IPCP: SendConfigReq #32 Mar 4 05:56:32 pvob ppp: [wan] IPADDR 0.0.0.0 Mar 4 05:56:32 pvob ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Mar 4 05:56:33 pvob ppp: [wan] IPV6CP: SendConfigReq #36 Mar 4 05:56:33 pvob ppp: [wan] IPCP: rec'd Configure Nak #32 (Req-Sent) Mar 4 05:56:33 pvob ppp: [wan] IPCP: not converging Mar 4 05:56:33 pvob ppp: [wan] IPCP: parameter negotiation failed Mar 4 05:56:33 pvob ppp: [wan] IPCP: state change Req-Sent --> Stopped Mar 4 05:56:33 pvob ppp: [wan] IPCP: LayerFinish Mar 4 05:56:35 pvob ppp: [wan] IPV6CP: SendConfigReq #37 Mar 4 05:56:37 pvob ppp: [wan] IPV6CP: SendConfigReq #38 Mar 4 05:56:39 pvob ppp: [wan] IPV6CP: SendConfigReq #39 Mar 4 05:56:41 pvob ppp: [wan] IPV6CP: SendConfigReq #40 Mar 4 05:56:43 pvob ppp: [wan] IPV6CP: parameter negotiation failed Mar 4 05:56:43 pvob ppp: [wan] IPV6CP: state change Req-Sent --> Stopped Mar 4 05:56:43 pvob ppp: [wan] IPV6CP: LayerFinish Mar 4 05:56:43 pvob ppp: [wan] Bundle: No NCPs left. Closing links... Mar 4 05:56:43 pvob ppp: [wan] Bundle: closing link "wan_link0"... Mar 4 05:56:43 pvob ppp: [wan_link0] Link: CLOSE event Mar 4 05:56:43 pvob ppp: [wan_link0] LCP: Close event Mar 4 05:56:43 pvob ppp: [wan_link0] LCP: state change Opened --> Closing Mar 4 05:56:43 pvob ppp: [wan_link0] Link: Leave bundle "wan" Mar 4 05:56:43 pvob ppp: [wan] Bundle: Status update: up 0 links, total bandwidth 9600 bps Mar 4 05:56:43 pvob ppp: [wan] IPCP: Close event Mar 4 05:56:43 pvob ppp: [wan] IPCP: state change Stopped --> Closed Mar 4 05:56:43 pvob ppp: [wan] IPV6CP: Close event Mar 4 05:56:43 pvob ppp: [wan] IPV6CP: state change Stopped --> Closed Mar 4 05:56:43 pvob ppp: [wan] IPCP: Down event Mar 4 05:56:43 pvob ppp: [wan] IPCP: state change Closed --> Initial Mar 4 05:56:43 pvob ppp: [wan] IPV6CP: Down event Mar 4 05:56:43 pvob ppp: [wan] IPV6CP: state change Closed --> Initial Mar 4 05:56:43 pvob ppp: [wan_link0] LCP: SendTerminateReq #11 Mar 4 05:56:43 pvob ppp: [wan_link0] LCP: LayerDown Mar 4 05:56:43 pvob ppp: [wan_link0] LCP: rec'd Terminate Ack #11 (Closing) Mar 4 05:56:43 pvob ppp: [wan_link0] LCP: state change Closing --> Closed Mar 4 05:56:43 pvob ppp: [wan_link0] LCP: LayerFinish Mar 4 05:56:43 pvob ppp: [wan_link0] Link: DOWN event Mar 4 05:56:43 pvob ppp: [wan_link0] LCP: Down event Mar 4 05:56:43 pvob ppp: [wan_link0] LCP: state change Closed --> Initial Mar 5 01:01:01 pvob php-cgi: rc.dyndns.update: Dynamic DNS (xxx.xxx.xxx) There was an error trying to determine the public IP for interface - wan (ppp0 ). Mar 5 06:46:41 pvob syslogd: kernel boot file is /boot/kernel/kernel -
@rsdu said in PPP WAN on 4G drops randomly and does not reconnect:
Mar 4 05:56:33 pvob ppp: [wan] IPCP: not converging
Mar 4 05:56:33 pvob ppp: [wan] IPCP: parameter negotiation failed
Mar 4 05:56:33 pvob ppp: [wan] IPCP: state change Req-Sent --> Stopped
Mar 4 05:56:33 pvob ppp: [wan] IPCP: LayerFinishLooks like it is talking to the other end but they are not responding with anything useful after the re-connection so it fails out.
What do you have to do to get it to connect again?
Steve
-
Hi Steve,
I rebooted the device to get it working again. No manual action was required after reboot, it connected automatically. Not sure, whether a manual reconnect would be sufficient. I never tried it, as calling someone to replug power is the only possibility without remote access :(
Thanks for your opinion on this,
Marvin -
Hi guys,
an update: I updated the device to pfSense 2.5.0 and had another drop in connection some days ago. These are the logs:
Apr 16 22:19:57 pvob ppp[7631]: [wan_link0] LCP: no reply to 1 echo request(s) Apr 16 22:20:07 pvob ppp[7631]: [wan_link0] LCP: no reply to 2 echo request(s) Apr 16 22:20:17 pvob ppp[7631]: [wan_link0] LCP: no reply to 3 echo request(s) Apr 16 22:20:27 pvob ppp[7631]: [wan_link0] LCP: no reply to 4 echo request(s) Apr 16 22:20:38 pvob ppp[7631]: [wan_link0] LCP: no reply to 5 echo request(s) Apr 16 22:20:38 pvob ppp[7631]: [wan_link0] LCP: peer not responding to echo requests Apr 16 22:20:38 pvob ppp[7631]: [wan_link0] LCP: state change Opened --> Stopping Apr 16 22:20:38 pvob ppp[7631]: [wan_link0] Link: Leave bundle "wan" Apr 16 22:20:38 pvob ppp[7631]: [wan] Bundle: Status update: up 0 links, total bandwidth 9600 bps Apr 16 22:20:38 pvob ppp[7631]: [wan] IPCP: Close event Apr 16 22:20:38 pvob ppp[7631]: [wan] IPCP: state change Opened --> Closing Apr 16 22:20:38 pvob ppp[7631]: [wan] IPCP: SendTerminateReq #41 Apr 16 22:20:38 pvob ppp[7631]: [wan] IPCP: LayerDown Apr 16 22:20:38 pvob ppp[7631]: [wan] IFACE: Down event Apr 16 22:20:38 pvob ppp[7631]: [wan] IFACE: Rename interface ppp0 to ppp0 Apr 16 22:20:38 pvob ppp[7631]: [wan] IPV6CP: Close event Apr 16 22:20:38 pvob ppp[7631]: [wan] IPV6CP: state change Stopped --> Closed Apr 16 22:20:38 pvob ppp[7631]: [wan] IPCP: Down event Apr 16 22:20:38 pvob ppp[7631]: [wan] IPCP: LayerFinish Apr 16 22:20:38 pvob ppp[7631]: [wan] Bundle: No NCPs left. Closing links... Apr 16 22:20:38 pvob ppp[7631]: [wan] IPCP: state change Closing --> Initial Apr 16 22:20:38 pvob ppp[7631]: [wan] IPV6CP: Down event Apr 16 22:20:38 pvob ppp[7631]: [wan] IPV6CP: state change Closed --> Initial Apr 16 22:20:38 pvob ppp[7631]: [wan_link0] LCP: SendTerminateReq #21 Apr 16 22:20:38 pvob ppp[7631]: [wan_link0] LCP: LayerDown Apr 16 22:20:40 pvob ppp[7631]: [wan_link0] LCP: SendTerminateReq #22 Apr 16 22:20:42 pvob ppp[7631]: [wan_link0] LCP: state change Stopping --> Stopped Apr 16 22:20:42 pvob ppp[7631]: [wan_link0] LCP: LayerFinish Apr 16 22:20:42 pvob ppp[7631]: [wan_link0] Link: DOWN event Apr 16 22:20:42 pvob ppp[7631]: [wan_link0] LCP: Down event Apr 16 22:20:42 pvob ppp[7631]: [wan_link0] LCP: state change Stopped --> Starting Apr 16 22:20:42 pvob ppp[7631]: [wan_link0] LCP: LayerStart Apr 16 22:20:42 pvob ppp[7631]: [wan_link0] LCP: state change Stopped --> Starting Apr 16 22:20:42 pvob ppp[7631]: [wan_link0] LCP: LayerStart Apr 16 22:20:42 pvob ppp[7631]: [wan_link0] Link: reconnection attempt 1 in 3 seconds Apr 16 22:20:45 pvob ppp[7631]: [wan_link0] Link: reconnection attempt 1 Apr 16 22:20:45 pvob ppp[7631]: [wan_link0] CHAT: Detected Hayes compatible modem. Apr 16 22:20:48 pvob ppp[7631]: [wan_link0] CHAT: The modem is not responding to "AT&F&C1&D2E0S0=0M1" at ModemCmd: label. Apr 16 22:20:48 pvob ppp[7631]: [wan_link0] MODEM: chat script failed Apr 16 22:20:48 pvob ppp[7631]: [wan_link0] Link: DOWN event Apr 16 22:20:48 pvob ppp[7631]: [wan_link0] LCP: Down event Apr 16 22:20:48 pvob ppp[7631]: [wan_link0] Link: reconnection attempt 2 in 2 seconds Apr 16 22:20:50 pvob ppp[7631]: [wan_link0] Link: reconnection attempt 2 Apr 16 22:20:52 pvob ppp[7631]: [wan_link0] CHAT: The modem is not responding to "AT" at ModemCmd: label. Apr 16 22:20:52 pvob ppp[7631]: [wan_link0] MODEM: chat script failed Apr 16 22:20:52 pvob ppp[7631]: [wan_link0] Link: DOWN event Apr 16 22:20:52 pvob ppp[7631]: [wan_link0] LCP: Down event Apr 16 22:20:52 pvob ppp[7631]: [wan_link0] Link: reconnection attempt 3 in 2 seconds Apr 16 22:20:54 pvob ppp[7631]: [wan_link0] Link: reconnection attempt 3 Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] CHAT: +CGDCONT=1,"IP","Internet.t-d1.de" Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] CHAT: Detected Hayes compatible modem. Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] CHAT: Dialing server at *99#... Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] CHAT: ATDT*99# Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] CHAT: Connected at 100000000. Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] MODEM: chat script succeeded Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] Link: UP event Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] LCP: Up event Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] LCP: state change Starting --> Req-Sent Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] LCP: SendConfigReq #23 Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] ACFCOMP Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] PROTOCOMP Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] ACCMAP 0x000a0000 Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] MRU 1500 Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] MAGICNUM 0xaff5169c Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] LCP: rec'd Configure Request #7 (Req-Sent) Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] ACCMAP 0x00000000 Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] AUTHPROTO CHAP MD5 Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] MAGICNUM 0x3d461fdb Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] PROTOCOMP Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] ACFCOMP Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] LCP: SendConfigAck #7 Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] ACCMAP 0x00000000 Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] AUTHPROTO CHAP MD5 Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] MAGICNUM 0x3d461fdb Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] PROTOCOMP Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] ACFCOMP Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] LCP: state change Req-Sent --> Ack-Sent Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] LCP: rec'd Configure Ack #23 (Ack-Sent) Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] ACFCOMP Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] PROTOCOMP Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] ACCMAP 0x000a0000 Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] MRU 1500 Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] MAGICNUM 0xaff5169c Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] LCP: state change Ack-Sent --> Opened Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] LCP: auth: peer wants CHAP, I want nothing Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] LCP: LayerUp Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] LCP: rec'd Discard Request #8 (Opened) Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] CHAP: rec'd CHALLENGE #1 len: 35 Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] Name: "UMTS_CHAP_SRVR" Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] CHAP: Using authname "t-mobile" Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] CHAP: sending RESPONSE #1 len: 29 Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] CHAP: rec'd SUCCESS #1 len: 4 Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] LCP: authorization successful Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] Link: Matched action 'bundle "wan" ""' Apr 16 22:20:55 pvob ppp[7631]: [wan_link0] Link: Join bundle "wan" Apr 16 22:20:55 pvob ppp[7631]: [wan] Bundle: Status update: up 1 link, total bandwidth 100000000 bps Apr 16 22:20:55 pvob ppp[7631]: [wan] IPCP: Open event Apr 16 22:20:55 pvob ppp[7631]: [wan] IPCP: state change Initial --> Starting Apr 16 22:20:55 pvob ppp[7631]: [wan] IPCP: LayerStart Apr 16 22:20:55 pvob ppp[7631]: [wan] IPV6CP: Open event Apr 16 22:20:55 pvob ppp[7631]: [wan] IPV6CP: state change Initial --> Starting Apr 16 22:20:55 pvob ppp[7631]: [wan] IPV6CP: LayerStart Apr 16 22:20:55 pvob ppp[7631]: [wan] IPCP: Up event Apr 16 22:20:55 pvob ppp[7631]: [wan] IPCP: state change Starting --> Req-Sent Apr 16 22:20:55 pvob ppp[7631]: [wan] IPCP: SendConfigReq #42 Apr 16 22:20:55 pvob ppp[7631]: [wan] IPADDR 0.0.0.0 Apr 16 22:20:55 pvob ppp[7631]: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Apr 16 22:20:55 pvob ppp[7631]: [wan] IPV6CP: Up event Apr 16 22:20:55 pvob ppp[7631]: [wan] IPV6CP: state change Starting --> Req-Sent Apr 16 22:20:55 pvob ppp[7631]: [wan] IPV6CP: SendConfigReq #81 Apr 16 22:20:56 pvob ppp[7631]: [wan] IPCP: rec'd Configure Nak #42 (Req-Sent) Apr 16 22:20:56 pvob ppp[7631]: [wan] IPCP: SendConfigReq #43 Apr 16 22:20:56 pvob ppp[7631]: [wan] IPADDR 0.0.0.0 Apr 16 22:20:56 pvob ppp[7631]: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Apr 16 22:20:57 pvob ppp[7631]: [wan] IPV6CP: SendConfigReq #82 Apr 16 22:20:57 pvob ppp[7631]: [wan] IPCP: rec'd Configure Nak #43 (Req-Sent) Apr 16 22:20:57 pvob ppp[7631]: [wan] IPCP: SendConfigReq #44 Apr 16 22:20:57 pvob ppp[7631]: [wan] IPADDR 0.0.0.0 Apr 16 22:20:57 pvob ppp[7631]: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Apr 16 22:20:58 pvob ppp[7631]: [wan] IPCP: rec'd Configure Request #2 (Req-Sent) Apr 16 22:20:58 pvob ppp[7631]: [wan] IPCP: SendConfigAck #2 Apr 16 22:20:58 pvob ppp[7631]: [wan] IPCP: state change Req-Sent --> Ack-Sent Apr 16 22:20:58 pvob ppp[7631]: [wan] IPCP: rec'd Configure Reject #44 (Ack-Sent) Apr 16 22:20:58 pvob ppp[7631]: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Apr 16 22:20:58 pvob ppp[7631]: [wan] IPCP: SendConfigReq #45 Apr 16 22:20:58 pvob ppp[7631]: [wan] IPADDR 0.0.0.0 Apr 16 22:20:58 pvob ppp[7631]: [wan] IPCP: rec'd Configure Nak #45 (Ack-Sent) Apr 16 22:20:58 pvob ppp[7631]: [wan] IPADDR xxx.xxx.xxx.xxx Apr 16 22:20:58 pvob ppp[7631]: [wan] xxx.xxx.xxx.xxx is OK Apr 16 22:20:58 pvob ppp[7631]: [wan] IPCP: SendConfigReq #46 Apr 16 22:20:58 pvob ppp[7631]: [wan] IPADDR xxx.xxx.xxx.xxx Apr 16 22:20:58 pvob ppp[7631]: [wan] IPCP: rec'd Configure Ack #46 (Ack-Sent) Apr 16 22:20:58 pvob ppp[7631]: [wan] IPADDR xxx.xxx.xxx.xxx Apr 16 22:20:58 pvob ppp[7631]: [wan] IPCP: state change Ack-Sent --> Opened Apr 16 22:20:58 pvob ppp[7631]: [wan] IPCP: LayerUp Apr 16 22:20:58 pvob ppp[7631]: [wan] xxx.xxx.xxx.xxx -> 10.64.64.0 Apr 16 22:20:58 pvob ppp[7631]: [wan] IFACE: Up event Apr 16 22:20:58 pvob ppp[7631]: [wan] IFACE: Rename interface ng0 to ppp0 Apr 16 22:20:59 pvob ppp[7631]: [wan] IPV6CP: SendConfigReq #83 Apr 16 22:21:01 pvob ppp[7631]: [wan] IPV6CP: SendConfigReq #84 Apr 16 22:21:03 pvob ppp[7631]: [wan] IPV6CP: SendConfigReq #85 Apr 16 22:21:05 pvob ppp[7631]: [wan] IPV6CP: SendConfigReq #86 Apr 16 22:21:07 pvob ppp[7631]: [wan] IPV6CP: SendConfigReq #87 Apr 16 22:21:09 pvob ppp[7631]: [wan] IPV6CP: SendConfigReq #88 Apr 16 22:21:11 pvob ppp[7631]: [wan] IPV6CP: SendConfigReq #89 Apr 16 22:21:13 pvob ppp[7631]: [wan] IPV6CP: SendConfigReq #90 Apr 16 22:21:15 pvob ppp[7631]: [wan] IPV6CP: parameter negotiation failed Apr 16 22:21:15 pvob ppp[7631]: [wan] IPV6CP: state change Req-Sent --> Stopped Apr 16 22:21:15 pvob ppp[7631]: [wan] IPV6CP: LayerFinishThis time, I initiated a WAN reconnect through the web interface and got the following PPP log:
Apr 17 11:03:07 pvob ppp[7631]: caught fatal signal TERM Apr 17 11:03:07 pvob ppp[7631]: [wan] IFACE: Close event Apr 17 11:03:07 pvob ppp[7631]: [wan] IPCP: Close event Apr 17 11:03:07 pvob ppp[7631]: [wan] IPCP: state change Opened --> Closing Apr 17 11:03:07 pvob ppp[7631]: [wan] IPCP: SendTerminateReq #47 Apr 17 11:03:07 pvob ppp[7631]: [wan] IPCP: LayerDown Apr 17 11:03:07 pvob ppp[7631]: [wan] IFACE: Down event Apr 17 11:03:07 pvob ppp[7631]: [wan] IFACE: Rename interface ppp0 to ppp0 Apr 17 11:03:07 pvob ppp[7631]: [wan] IPV6CP: Close event Apr 17 11:03:07 pvob ppp[7631]: [wan] IPV6CP: state change Stopped --> Closed Apr 17 11:03:07 pvob ppp[7631]: [wan] IPCP: rec'd Terminate Ack #47 (Closing) Apr 17 11:03:07 pvob ppp[7631]: [wan] IPCP: state change Closing --> Closed Apr 17 11:03:07 pvob ppp[7631]: [wan] IPCP: LayerFinish Apr 17 11:03:07 pvob ppp[7631]: [wan] Bundle: No NCPs left. Closing links... Apr 17 11:03:07 pvob ppp[7631]: [wan] Bundle: closing link "wan_link0"... Apr 17 11:03:07 pvob ppp[7631]: [wan_link0] Link: CLOSE event Apr 17 11:03:07 pvob ppp[7631]: [wan_link0] LCP: Close event Apr 17 11:03:07 pvob ppp[7631]: [wan_link0] LCP: state change Opened --> Closing Apr 17 11:03:07 pvob ppp[7631]: [wan_link0] Link: Leave bundle "wan" Apr 17 11:03:07 pvob ppp[7631]: [wan] Bundle: Status update: up 0 links, total bandwidth 9600 bps Apr 17 11:03:07 pvob ppp[7631]: [wan] IPCP: Close event Apr 17 11:03:07 pvob ppp[7631]: [wan] IPV6CP: Close event Apr 17 11:03:07 pvob ppp[7631]: [wan] IPCP: Down event Apr 17 11:03:07 pvob ppp[7631]: [wan] IPCP: state change Closed --> Initial Apr 17 11:03:07 pvob ppp[7631]: [wan] IPV6CP: Down event Apr 17 11:03:07 pvob ppp[7631]: [wan] IPV6CP: state change Closed --> Initial Apr 17 11:03:07 pvob ppp[7631]: [wan_link0] LCP: SendTerminateReq #24 Apr 17 11:03:07 pvob ppp[7631]: [wan_link0] LCP: LayerDown Apr 17 11:03:07 pvob ppp[7631]: [wan_link0] LCP: rec'd Terminate Ack #24 (Closing) Apr 17 11:03:07 pvob ppp[7631]: [wan_link0] LCP: state change Closing --> Closed Apr 17 11:03:07 pvob ppp[7631]: [wan_link0] LCP: LayerFinish Apr 17 11:03:07 pvob ppp[7631]: [wan_link0] Link: DOWN event Apr 17 11:03:07 pvob ppp[7631]: [wan_link0] LCP: Down event Apr 17 11:03:07 pvob ppp[7631]: [wan_link0] LCP: state change Closed --> Initial Apr 17 11:03:09 pvob ppp[7631]: [wan] Bundle: Shutdown Apr 17 11:03:09 pvob ppp[7631]: [wan_link0] Link: Shutdown Apr 17 11:03:09 pvob ppp[7631]: process 7631 terminated Apr 17 11:03:14 pvob ppp[39865]: Multi-link PPP daemon for FreeBSD Apr 17 11:03:14 pvob ppp[39865]: Apr 17 11:03:14 pvob ppp[39865]: process 39865 started, version 5.9 Apr 17 11:03:14 pvob ppp[39865]: web: web is not running Apr 17 11:03:14 pvob ppp[39865]: [wan] Bundle: Interface ng0 created Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] Link: OPEN event Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] LCP: Open event Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] LCP: state change Initial --> Starting Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] LCP: LayerStart Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] CHAT: +CGDCONT=1,"IP","Internet.t-d1.de" Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] CHAT: Detected Hayes compatible modem. Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] CHAT: Dialing server at *99#... Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] CHAT: ATDT*99# Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] CHAT: Connected at 100000000. Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] MODEM: chat script succeeded Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] Link: UP event Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] LCP: Up event Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] LCP: state change Starting --> Req-Sent Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] LCP: SendConfigReq #1 Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] ACFCOMP Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] PROTOCOMP Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] ACCMAP 0x000a0000 Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] MRU 1500 Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] MAGICNUM 0xd2d06e1f Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] LCP: rec'd Configure Request #9 (Req-Sent) Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] ACCMAP 0x00000000 Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] AUTHPROTO CHAP MD5 Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] MAGICNUM 0x40000b17 Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] AUTHPROTO CHAP MD5 Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] MAGICNUM 0x40000b17 Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] PROTOCOMP Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] ACFCOMP Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] LCP: SendConfigAck #9 Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] ACCMAP 0x00000000 Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] AUTHPROTO CHAP MD5 Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] MAGICNUM 0x40000b17 Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] PROTOCOMP Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] ACFCOMP Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] LCP: state change Req-Sent --> Ack-Sent Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] LCP: rec'd Configure Ack #1 (Ack-Sent) Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] ACFCOMP Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] PROTOCOMP Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] ACCMAP 0x000a0000 Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] MRU 1500 Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] MAGICNUM 0xd2d06e1f Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] LCP: state change Ack-Sent --> Opened Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] LCP: auth: peer wants CHAP, I want nothing Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] LCP: LayerUp Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] LCP: rec'd Discard Request #10 (Opened) Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] CHAP: rec'd CHALLENGE #1 len: 35 Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] Name: "UMTS_CHAP_SRVR" Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] CHAP: Using authname "t-mobile" Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] CHAP: sending RESPONSE #1 len: 29 Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] CHAP: rec'd SUCCESS #1 len: 4 Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] LCP: authorization successful Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] Link: Matched action 'bundle "wan" ""' Apr 17 11:03:14 pvob ppp[39865]: [wan_link0] Link: Join bundle "wan" Apr 17 11:03:14 pvob ppp[39865]: [wan] Bundle: Status update: up 1 link, total bandwidth 100000000 bps Apr 17 11:03:14 pvob ppp[39865]: [wan] IPCP: Open event Apr 17 11:03:14 pvob ppp[39865]: [wan] IPCP: state change Initial --> Starting Apr 17 11:03:14 pvob ppp[39865]: [wan] IPCP: LayerStart Apr 17 11:03:14 pvob ppp[39865]: [wan] IPV6CP: Open event Apr 17 11:03:14 pvob ppp[39865]: [wan] IPV6CP: state change Initial --> Starting Apr 17 11:03:14 pvob ppp[39865]: [wan] IPV6CP: LayerStart Apr 17 11:03:14 pvob ppp[39865]: [wan] IPCP: Up event Apr 17 11:03:14 pvob ppp[39865]: [wan] IPCP: state change Starting --> Req-Sent Apr 17 11:03:14 pvob ppp[39865]: [wan] IPCP: SendConfigReq #1 Apr 17 11:03:14 pvob ppp[39865]: [wan] IPADDR 0.0.0.0 Apr 17 11:03:14 pvob ppp[39865]: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Apr 17 11:03:14 pvob ppp[39865]: [wan] IPV6CP: Up event Apr 17 11:03:14 pvob ppp[39865]: [wan] IPV6CP: state change Starting --> Req-Sent Apr 17 11:03:14 pvob ppp[39865]: [wan] IPV6CP: SendConfigReq #1 Apr 17 11:03:14 pvob ppp[39865]: [wan] IPCP: rec'd Configure Request #3 (Req-Sent) Apr 17 11:03:14 pvob ppp[39865]: [wan] IPCP: SendConfigAck #3 Apr 17 11:03:14 pvob ppp[39865]: [wan] IPCP: state change Req-Sent --> Ack-Sent Apr 17 11:03:14 pvob ppp[39865]: [wan] IPCP: rec'd Configure Reject #1 (Ack-Sent) Apr 17 11:03:14 pvob ppp[39865]: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Apr 17 11:03:14 pvob ppp[39865]: [wan] IPCP: SendConfigReq #2 Apr 17 11:03:14 pvob ppp[39865]: [wan] IPADDR 0.0.0.0 Apr 17 11:03:14 pvob ppp[39865]: [wan] IPCP: rec'd Configure Nak #2 (Ack-Sent) Apr 17 11:03:14 pvob ppp[39865]: [wan] IPADDR xxx.xxx.xxx.xxx Apr 17 11:03:14 pvob ppp[39865]: [wan] xxx.xxx.xxx.xxx is OK Apr 17 11:03:14 pvob ppp[39865]: [wan] IPCP: SendConfigReq #3 Apr 17 11:03:14 pvob ppp[39865]: [wan] IPADDR xxx.xxx.xxx.xxx Apr 17 11:03:14 pvob ppp[39865]: [wan] IPCP: rec'd Configure Ack #3 (Ack-Sent) Apr 17 11:03:14 pvob ppp[39865]: [wan] IPADDR xxx.xxx.xxx.xxx Apr 17 11:03:14 pvob ppp[39865]: [wan] IPCP: state change Ack-Sent --> Opened Apr 17 11:03:14 pvob ppp[39865]: [wan] IPCP: LayerUp Apr 17 11:03:14 pvob ppp[39865]: [wan] xxx.xxx.xxx.xxx -> 10.64.64.0 Apr 17 11:03:14 pvob ppp[39865]: [wan] IFACE: Up event Apr 17 11:03:14 pvob ppp[39865]: [wan] IFACE: Rename interface ng0 to ppp0 Apr 17 11:03:16 pvob ppp[39865]: [wan] IPV6CP: SendConfigReq #2 Apr 17 11:03:18 pvob ppp[39865]: [wan] IPV6CP: SendConfigReq #3 Apr 17 11:03:20 pvob ppp[39865]: [wan] IPV6CP: SendConfigReq #4 Apr 17 11:03:22 pvob ppp[39865]: [wan] IPV6CP: SendConfigReq #5 Apr 17 11:03:24 pvob ppp[39865]: [wan] IPV6CP: SendConfigReq #6 Apr 17 11:03:26 pvob ppp[39865]: [wan] IPV6CP: SendConfigReq #7 Apr 17 11:03:28 pvob ppp[39865]: [wan] IPV6CP: SendConfigReq #8 Apr 17 11:03:30 pvob ppp[39865]: [wan] IPV6CP: SendConfigReq #9 Apr 17 11:03:32 pvob ppp[39865]: [wan] IPV6CP: SendConfigReq #10 Apr 17 11:03:34 pvob ppp[39865]: [wan] IPV6CP: parameter negotiation failed Apr 17 11:03:34 pvob ppp[39865]: [wan] IPV6CP: state change Req-Sent --> Stopped Apr 17 11:03:34 pvob ppp[39865]: [wan] IPV6CP: LayerFinish Apr 17 11:15:38 pvob ppp[39865]: caught fatal signal TERM Apr 17 11:15:38 pvob ppp[39865]: [wan] IFACE: Close event Apr 17 11:15:38 pvob ppp[39865]: [wan] IPCP: Close event Apr 17 11:15:38 pvob ppp[39865]: [wan] IPCP: state change Opened --> Closing Apr 17 11:15:38 pvob ppp[39865]: [wan] IPCP: SendTerminateReq #4 Apr 17 11:15:38 pvob ppp[39865]: [wan] IPCP: LayerDown Apr 17 11:18:03 pvob ppp[10783]: Multi-link PPP daemon for FreeBSD Apr 17 11:18:03 pvob ppp[10783]: Apr 17 11:18:03 pvob ppp[10783]: process 10783 started, version 5.9 Apr 17 11:18:03 pvob ppp[10783]: web: web is not running Apr 17 11:18:03 pvob ppp[10783]: [wan] Bundle: Interface ng0 created Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] Link: OPEN event Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] LCP: Open event Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] LCP: state change Initial --> Starting Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] LCP: LayerStart Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] CHAT: +CGDCONT=1,"IP","Internet.t-d1.de" Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] CHAT: Detected Hayes compatible modem. Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] CHAT: +CGDCONT=1,"IP","Internet.t-d1.de" Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] CHAT: Detected Hayes compatible modem. Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] CHAT: Dialing server at *99#... Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] CHAT: ATDT*99# Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] CHAT: Connected at 100000000. Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] MODEM: chat script succeeded Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] Link: UP event Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] LCP: Up event Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] LCP: state change Starting --> Req-Sent Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] LCP: SendConfigReq #1 Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] ACFCOMP Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] PROTOCOMP Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] ACCMAP 0x000a0000 Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] MRU 1500 Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] MAGICNUM 0x57c42c5c Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] LCP: rec'd Configure Request #11 (Req-Sent) Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] ACCMAP 0x00000000 Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] AUTHPROTO CHAP MD5 Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] MAGICNUM 0x400d999a Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] PROTOCOMP Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] ACFCOMP Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] LCP: SendConfigAck #11 Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] ACCMAP 0x00000000 Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] AUTHPROTO CHAP MD5 Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] MAGICNUM 0x400d999a Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] PROTOCOMP Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] ACFCOMP Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] LCP: state change Req-Sent --> Ack-Sent Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] LCP: rec'd Configure Ack #1 (Ack-Sent) Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] ACFCOMP Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] PROTOCOMP Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] ACCMAP 0x000a0000 Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] MRU 1500 Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] MAGICNUM 0x57c42c5c Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] LCP: state change Ack-Sent --> Opened Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] LCP: auth: peer wants CHAP, I want nothing Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] LCP: LayerUp Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] LCP: rec'd Discard Request #12 (Opened) Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] CHAP: rec'd CHALLENGE #1 len: 35 Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] Name: "UMTS_CHAP_SRVR" Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] CHAP: Using authname "t-mobile" Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] CHAP: sending RESPONSE #1 len: 29 Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] CHAP: rec'd SUCCESS #1 len: 4 Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] LCP: authorization successful Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] Link: Matched action 'bundle "wan" ""' Apr 17 11:18:03 pvob ppp[10783]: [wan_link0] Link: Join bundle "wan" Apr 17 11:18:03 pvob ppp[10783]: [wan] Bundle: Status update: up 1 link, total bandwidth 100000000 bps Apr 17 11:18:03 pvob ppp[10783]: [wan] IPCP: Open event Apr 17 11:18:03 pvob ppp[10783]: [wan] IPCP: state change Initial --> Starting Apr 17 11:18:03 pvob ppp[10783]: [wan] IPCP: LayerStart Apr 17 11:18:03 pvob ppp[10783]: [wan] IPV6CP: Open event Apr 17 11:18:03 pvob ppp[10783]: [wan] IPV6CP: state change Initial --> Starting Apr 17 11:18:03 pvob ppp[10783]: [wan] IPV6CP: LayerStart Apr 17 11:18:03 pvob ppp[10783]: [wan] IPCP: Up event Apr 17 11:18:03 pvob ppp[10783]: [wan] IPCP: state change Starting --> Req-Sent Apr 17 11:18:03 pvob ppp[10783]: [wan] IPCP: SendConfigReq #1 Apr 17 11:18:03 pvob ppp[10783]: [wan] IPADDR 0.0.0.0 Apr 17 11:18:03 pvob ppp[10783]: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Apr 17 11:18:03 pvob ppp[10783]: [wan] IPV6CP: Up event Apr 17 11:18:03 pvob ppp[10783]: [wan] IPV6CP: state change Starting --> Req-Sent Apr 17 11:18:03 pvob ppp[10783]: [wan] IPV6CP: SendConfigReq #1 Apr 17 11:18:03 pvob ppp[10783]: [wan] IPCP: rec'd Configure Request #4 (Req-Sent) Apr 17 11:18:03 pvob ppp[10783]: [wan] IPCP: SendConfigAck #4 Apr 17 11:18:03 pvob ppp[10783]: [wan] IPCP: state change Req-Sent --> Ack-Sent Apr 17 11:18:03 pvob ppp[10783]: [wan] IPCP: rec'd Configure Reject #1 (Ack-Sent) Apr 17 11:18:03 pvob ppp[10783]: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Apr 17 11:18:03 pvob ppp[10783]: [wan] IPCP: SendConfigReq #2 Apr 17 11:18:03 pvob ppp[10783]: [wan] IPADDR 0.0.0.0 Apr 17 11:18:03 pvob ppp[10783]: [wan] IPCP: rec'd Configure Nak #2 (Ack-Sent) Apr 17 11:18:03 pvob ppp[10783]: [wan] IPADDR xxx.xxx.xxx.xxx Apr 17 11:18:03 pvob ppp[10783]: [wan] xxx.xxx.xxx.xxx is OK Apr 17 11:18:03 pvob ppp[10783]: [wan] IPCP: SendConfigReq #3 Apr 17 11:18:03 pvob ppp[10783]: [wan] IPADDR xxx.xxx.xxx.xxx Apr 17 11:18:03 pvob ppp[10783]: [wan] IPCP: rec'd Configure Ack #3 (Ack-Sent) Apr 17 11:18:03 pvob ppp[10783]: [wan] IPADDR xxx.xxx.xxx.xxx Apr 17 11:18:03 pvob ppp[10783]: [wan] IPCP: state change Ack-Sent --> Opened Apr 17 11:18:03 pvob ppp[10783]: [wan] IPCP: LayerUp Apr 17 11:18:03 pvob ppp[10783]: [wan] xxx.xxx.xxx.xxx -> 10.64.64.0 Apr 17 11:18:03 pvob ppp[10783]: [wan] IFACE: Up event Apr 17 11:18:03 pvob ppp[10783]: [wan] IFACE: Rename interface ng0 to ppp0 Apr 17 11:18:05 pvob ppp[10783]: [wan] IPV6CP: SendConfigReq #2 Apr 17 11:18:07 pvob ppp[10783]: [wan] IPV6CP: SendConfigReq #3 Apr 17 11:18:09 pvob ppp[10783]: [wan] IPV6CP: SendConfigReq #4 Apr 17 11:18:11 pvob ppp[10783]: [wan] IPV6CP: SendConfigReq #5 Apr 17 11:18:13 pvob ppp[10783]: [wan] IPV6CP: SendConfigReq #6 Apr 17 11:18:15 pvob ppp[10783]: [wan] IPV6CP: SendConfigReq #7 Apr 17 11:18:17 pvob ppp[10783]: [wan] IPV6CP: SendConfigReq #8 Apr 17 11:18:19 pvob ppp[10783]: [wan] IPV6CP: SendConfigReq #9 Apr 17 11:18:21 pvob ppp[10783]: [wan] IPV6CP: SendConfigReq #10 Apr 17 11:18:23 pvob ppp[10783]: [wan] IPV6CP: parameter negotiation failed Apr 17 11:18:23 pvob ppp[10783]: [wan] IPV6CP: state change Req-Sent --> Stopped Apr 17 11:18:23 pvob ppp[10783]: [wan] IPV6CP: LayerFinishI was not able to spot any relevant difference between the successful and unsuccessful attempt, even the assigned IP is the same. To me it seems that the issue seems to be located somewhere else than in WAN connectivity.
I'll investigate further...
