Random issues with USB modem disconnects
-
Sorry if I am posting this in the wrong forum, but here is a rundown of the situation. I use a multi-wan setup (DSL and 4g USB modem). The multi-wan part works great. Load balancing and failover work awesome. However, I seem to have a random issue with my Pantech UML290 USB modem. Basically, it works great for a few days, then I have to 'toy' with it to get it to work again. My router will have an uptime of about 2-3 days, then the modem drops connection and can never seem to reconnect. Restarting pfsense seems to make no difference. I have to move my modem from one USB port to another port, then it starts working again. It sounds almost like a hardware problem with the modem, and moving it to another USB port resolves the issue by 'power-cycling' the usb modem…but the odd part is that it looks like from the PPP log I can still communicate with the modem, but I am not getting an IP address. Could that indicate something being wrong with the tower in my area or some signal fluctuations?
I am running this version of pfsense:
Version 2.0.2-RELEASE (i386)
built on Fri Dec 7 16:30:38 EST 2012FreeBSD 8.1-RELEASE-p13
Here is a snip of my PPP log, from the beginning of a reconnect until it stops retrying.
Jan 6 22:48:21 ppp: [opt1_link0] LCP: state change Closed –> Initial
Jan 6 22:48:21 ppp: [opt1_link0] LCP: Down event
Jan 6 22:48:21 ppp: [opt1_link0] Link: DOWN event
Jan 6 22:48:21 ppp: [opt1_link0] LCP: LayerFinish
Jan 6 22:48:21 ppp: [opt1_link0] LCP: state change Closing –> Closed
Jan 6 22:48:21 ppp: [opt1_link0] LCP: rec'd Terminate Ack #2 (Closing)
Jan 6 22:48:21 ppp: [opt1_link0] LCP: LayerDown
Jan 6 22:48:21 ppp: [opt1_link0] LCP: SendTerminateReq #2
Jan 6 22:48:21 ppp: [opt1] IPCP: state change Closed –> Initial
Jan 6 22:48:21 ppp: [opt1] IPCP: Down event
Jan 6 22:48:21 ppp: [opt1] IPCP: state change Stopped –> Closed
Jan 6 22:48:21 ppp: [opt1] IPCP: Close event
Jan 6 22:48:21 ppp: [opt1] Bundle: Status update: up 0 links, total bandwidth 9600 bps
Jan 6 22:48:21 ppp: [opt1_link0] Link: Leave bundle "opt1"
Jan 6 22:48:21 ppp: [opt1_link0] LCP: state change Opened –> Closing
Jan 6 22:48:21 ppp: [opt1_link0] LCP: Close event
Jan 6 22:48:21 ppp: [opt1_link0] Link: CLOSE event
Jan 6 22:48:21 ppp: [opt1] Bundle: closing link "opt1_link0"…
Jan 6 22:48:21 ppp: [opt1] Bundle: No NCPs left. Closing links…
Jan 6 22:48:21 ppp: [opt1] IPCP: LayerFinish
Jan 6 22:48:21 ppp: [opt1] IPCP: state change Req-Sent –> Stopped
Jan 6 22:48:21 ppp: [opt1] IPCP: parameter negotiation failed
Jan 6 22:48:21 ppp: [opt1] IPCP: not converging
Jan 6 22:48:21 ppp: [opt1] IPCP: rec'd Configure Nak #10 (Req-Sent)
Jan 6 22:48:20 ppp: [opt1] SECDNS 0.0.0.0
Jan 6 22:48:20 ppp: [opt1] PRIDNS 0.0.0.0
Jan 6 22:48:20 ppp: [opt1] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Jan 6 22:48:20 ppp: [opt1] IPADDR 0.0.0.0
Jan 6 22:48:20 ppp: [opt1] IPCP: SendConfigReq #10
Jan 6 22:48:20 ppp: [opt1] IPCP: rec'd Configure Nak #9 (Req-Sent)
Jan 6 22:48:19 ppp: [opt1] SECDNS 0.0.0.0
Jan 6 22:48:19 ppp: [opt1] PRIDNS 0.0.0.0
Jan 6 22:48:19 ppp: [opt1] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Jan 6 22:48:19 ppp: [opt1] IPADDR 0.0.0.0
Jan 6 22:48:19 ppp: [opt1] IPCP: SendConfigReq #9
Jan 6 22:48:19 ppp: [opt1] IPCP: rec'd Configure Nak #8 (Req-Sent)
Jan 6 22:48:18 ppp: [opt1] SECDNS 0.0.0.0
Jan 6 22:48:18 ppp: [opt1] PRIDNS 0.0.0.0
Jan 6 22:48:18 ppp: [opt1] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Jan 6 22:48:18 ppp: [opt1] IPADDR 0.0.0.0
Jan 6 22:48:18 ppp: [opt1] IPCP: SendConfigReq #8
Jan 6 22:48:18 ppp: [opt1] IPCP: rec'd Configure Nak #7 (Req-Sent)
Jan 6 22:48:17 ppp: [opt1] SECDNS 0.0.0.0
Jan 6 22:48:17 ppp: [opt1] PRIDNS 0.0.0.0
Jan 6 22:48:17 ppp: [opt1] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Jan 6 22:48:17 ppp: [opt1] IPADDR 0.0.0.0
Jan 6 22:48:17 ppp: [opt1] IPCP: SendConfigReq #7
Jan 6 22:48:17 ppp: [opt1] IPCP: rec'd Configure Nak #6 (Req-Sent)
Jan 6 22:48:16 ppp: [opt1] SECDNS 0.0.0.0
Jan 6 22:48:16 ppp: [opt1] PRIDNS 0.0.0.0
Jan 6 22:48:16 ppp: [opt1] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Jan 6 22:48:16 ppp: [opt1] IPADDR 0.0.0.0
Jan 6 22:48:16 ppp: [opt1] IPCP: SendConfigReq #6
Jan 6 22:48:16 ppp: [opt1] IPCP: rec'd Configure Nak #5 (Req-Sent)
Jan 6 22:48:15 ppp: [opt1] SECDNS 0.0.0.0
Jan 6 22:48:15 ppp: [opt1] PRIDNS 0.0.0.0
Jan 6 22:48:15 ppp: [opt1] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Jan 6 22:48:15 ppp: [opt1] IPADDR 0.0.0.0
Jan 6 22:48:15 ppp: [opt1] IPCP: SendConfigReq #5
Jan 6 22:48:15 ppp: [opt1] IPCP: rec'd Configure Nak #4 (Req-Sent)
Jan 6 22:48:14 ppp: [opt1] SECDNS 0.0.0.0
Jan 6 22:48:14 ppp: [opt1] PRIDNS 0.0.0.0
Jan 6 22:48:14 ppp: [opt1] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Jan 6 22:48:14 ppp: [opt1] IPADDR 0.0.0.0
Jan 6 22:48:14 ppp: [opt1] IPCP: SendConfigReq #4
Jan 6 22:48:14 ppp: [opt1] IPCP: rec'd Configure Nak #3 (Req-Sent)
Jan 6 22:48:13 ppp: [opt1] SECDNS 0.0.0.0
Jan 6 22:48:13 ppp: [opt1] PRIDNS 0.0.0.0
Jan 6 22:48:13 ppp: [opt1] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Jan 6 22:48:13 ppp: [opt1] IPADDR 0.0.0.0
Jan 6 22:48:13 ppp: [opt1] IPCP: SendConfigReq #3
Jan 6 22:48:13 ppp: [opt1] IPCP: rec'd Configure Nak #2 (Req-Sent)
Jan 6 22:48:12 ppp: [opt1] SECDNS 0.0.0.0
Jan 6 22:48:12 ppp: [opt1] PRIDNS 0.0.0.0
Jan 6 22:48:12 ppp: [opt1] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Jan 6 22:48:12 ppp: [opt1] IPADDR 0.0.0.0
Jan 6 22:48:12 ppp: [opt1] IPCP: SendConfigReq #2
Jan 6 22:48:12 ppp: [opt1] IPCP: rec'd Configure Nak #1 (Req-Sent)
Jan 6 22:48:11 ppp: [opt1] SECDNS 0.0.0.0
Jan 6 22:48:11 ppp: [opt1] PRIDNS 0.0.0.0
Jan 6 22:48:11 ppp: [opt1] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Jan 6 22:48:11 ppp: [opt1] IPADDR 0.0.0.0
Jan 6 22:48:11 ppp: [opt1] IPCP: SendConfigReq #1
Jan 6 22:48:11 ppp: [opt1] IPCP: state change Starting –> Req-Sent
Jan 6 22:48:11 ppp: [opt1] IPCP: Up event
Jan 6 22:48:11 ppp: [opt1] IPCP: LayerStart
Jan 6 22:48:11 ppp: [opt1] IPCP: state change Initial –> Starting
Jan 6 22:48:11 ppp: [opt1] IPCP: Open event
Jan 6 22:48:11 ppp: [opt1] Bundle: Status update: up 1 link, total bandwidth 100000000 bps
Jan 6 22:48:11 ppp: [opt1_link0] Link: Join bundle "opt1"
Jan 6 22:48:11 ppp: [opt1_link0] Link: Matched action 'bundle "opt1" ""'
Jan 6 22:48:11 ppp: [opt1_link0] LCP: authorization successful
Jan 6 22:48:11 ppp: [opt1_link0] CHAP: rec'd SUCCESS #1 len: 4
Jan 6 22:48:11 ppp: [opt1_link0] CHAP: sending RESPONSE #1 len: 41
Jan 6 22:48:11 ppp: [opt1_link0] CHAP: Using authname "484xxxxxxx@vzw4g.com"
Jan 6 22:48:11 ppp: [opt1_link0] Name: "UMTS_CHAP_SRVR"
Jan 6 22:48:11 ppp: [opt1_link0] CHAP: rec'd CHALLENGE #1 len: 35
Jan 6 22:48:11 ppp: [opt1_link0] LCP: rec'd Discard Request #15 (Opened)
Jan 6 22:48:11 ppp: [opt1_link0] LCP: LayerUp
Jan 6 22:48:11 ppp: [opt1_link0] LCP: auth: peer wants CHAP, I want nothing
Jan 6 22:48:11 ppp: [opt1_link0] LCP: state change Ack-Sent –> Opened
Jan 6 22:48:11 ppp: [opt1_link0] MAGICNUM 9c1e2ecf
Jan 6 22:48:11 ppp: [opt1_link0] MRU 1500
Jan 6 22:48:11 ppp: [opt1_link0] ACCMAP 0x000a0000
Jan 6 22:48:11 ppp: [opt1_link0] PROTOCOMP
Jan 6 22:48:11 ppp: [opt1_link0] ACFCOMP
Jan 6 22:48:11 ppp: [opt1_link0] LCP: rec'd Configure Ack #1 (Ack-Sent)
Jan 6 22:48:11 ppp: [opt1_link0] LCP: state change Req-Sent –> Ack-Sent
Jan 6 22:48:11 ppp: [opt1_link0] ACFCOMP
Jan 6 22:48:11 ppp: [opt1_link0] PROTOCOMP
Jan 6 22:48:11 ppp: [opt1_link0] MAGICNUM 859f8444
Jan 6 22:48:11 ppp: [opt1_link0] AUTHPROTO CHAP MD5
Jan 6 22:48:11 ppp: [opt1_link0] ACCMAP 0x00000000
Jan 6 22:48:11 ppp: [opt1_link0] LCP: SendConfigAck #14
Jan 6 22:48:11 ppp: [opt1_link0] ACFCOMP
Jan 6 22:48:11 ppp: [opt1_link0] PROTOCOMP
Jan 6 22:48:11 ppp: [opt1_link0] MAGICNUM 859f8444
Jan 6 22:48:11 ppp: [opt1_link0] AUTHPROTO CHAP MD5
Jan 6 22:48:11 ppp: [opt1_link0] ACCMAP 0x00000000
Jan 6 22:48:11 ppp: [opt1_link0] LCP: rec'd Configure Request #14 (Req-Sent)
Jan 6 22:48:11 ppp: [opt1_link0] MAGICNUM 9c1e2ecf
Jan 6 22:48:11 ppp: [opt1_link0] MRU 1500
Jan 6 22:48:11 ppp: [opt1_link0] ACCMAP 0x000a0000
Jan 6 22:48:11 ppp: [opt1_link0] PROTOCOMP
Jan 6 22:48:11 ppp: [opt1_link0] ACFCOMP
Jan 6 22:48:11 ppp: [opt1_link0] LCP: SendConfigReq #1
Jan 6 22:48:11 ppp: [opt1_link0] LCP: state change Starting –> Req-Sent
Jan 6 22:48:11 ppp: [opt1_link0] LCP: Up event
Jan 6 22:48:11 ppp: [opt1_link0] Link: UP event
Jan 6 22:48:11 ppp: [opt1_link0] MODEM: chat script succeeded
Jan 6 22:48:11 ppp: [opt1_link0] CHAT: Connected at 100000000.
Jan 6 22:48:11 ppp: [opt1_link0] CHAT: Dialing server at 99**3#…
Jan 6 22:48:11 ppp: [opt1_link0] CHAT: Detected Hayes compatible modem.
Jan 6 22:48:11 ppp: [opt1_link0] Link: reconnection attempt 1
Jan 6 22:48:07 ppp: [opt1_link0] Link: reconnection attempt 1 in 4 seconds
Jan 6 22:48:07 ppp: [opt1_link0] LCP: Down event
Jan 6 22:48:07 ppp: [opt1_link0] Link: DOWN event
Jan 6 22:48:07 ppp: [opt1_link0] MODEM: chat script failed
Jan 6 22:48:07 ppp: [opt1_link0] CHAT: The modem is not responding to "AT" at ModemCmd: label.
Jan 6 22:48:06 ppp: [opt1_link0] LCP: LayerStart
Jan 6 22:48:06 ppp: [opt1_link0] LCP: state change Initial –> Starting
Jan 6 22:48:06 ppp: [opt1_link0] LCP: Open event
Jan 6 22:48:06 ppp: [opt1_link0] Link: OPEN event
Jan 6 22:48:06 ppp: [opt1] Bundle: Interface ng0 created
Jan 6 22:48:06 ppp: web: web is not running
Jan 6 22:48:06 ppp: process 21449 terminated
Jan 6 22:48:06 ppp: [opt1_link0] Link: Shutdown
Jan 6 22:48:06 ppp: [opt1] Bundle: Shutdown
Jan 6 22:48:05 ppp: waiting for process 21449 to die…
Jan 6 22:48:04 ppp: waiting for process 21449 to die...
Jan 6 22:48:04 ppp: [opt1] IPCP: Close event
Jan 6 22:48:04 ppp: [opt1] IFACE: Close event
Jan 6 22:48:04 ppp: caught fatal signal term
Jan 6 22:48:04 ppp: process 18723 started, version 5.6 (root@base-8_1-i386.builders.pfsense.org 21:25 6-Aug-2012)
Jan 6 22:48:04 ppp:
Jan 6 22:48:04 ppp: Multi-link PPP daemon for FreeBSD -
Hello,
I have this same issue. I have used these modems before with pfsense and they were working great. I even had 4 at a time setup and load balancing. I still have to retrieve the logs but something in pfsense has changed.
To get the connection working usually all I have to do is log into pfsense and hit connect.
Why is ppp not restarting? I am about to reconfigure to dial on demand.
Is the web interface writing the right config file?
Anyone think I should do a reinstall?
What should I be looking at?
-
I really think it has something to do with 2.0.2. Have you tried 2.0 or 2.01? I may have to.
-
I configured pfsense with dial on demand and idle timeout zero and it seems to be working. The checkbox instructions are misleading.
Web.