Huawei E3372 will not reconnect PPP after manual disconnect under status-->interfaces

bradtpt

Hi everyone, first post here.

I have a Shuttle DS57U machine here running pfsense 2.4.4 booting UEFI because the upgrade from 2.3.x --> 2.4.x broke the legacy bootloader on this hardware. I have successfully configured a Huawei E3372h 4G USB modem to operate in stick mode to connect to the internet using PPP within pfsense. That was a bit of a mission in itself requiring firmware updates, a custom init string and for the modem to be put into a suitable SETMODE to present the correct interfaces. The relevant bits are presented here in case they come into question:

Modem AT^SETPORT="FF;10,12,16"
Init string: &F&C1&D2E0S0=0

The issue I'm having now is if I disconnect the PPP session by going into status-->interfaces and hitting "Disconnect", it drops the connection as expected however when I hit "connect" to bring the connection back online it will not reconnect.

Here's a successful connection log:

Nov 11 05:26:31 pfSense ppp: Multi-link PPP daemon for FreeBSD
Nov 11 05:26:31 pfSense ppp:
Nov 11 05:26:31 pfSense ppp: process 44585 started, version 5.8 (nobody@pfSense_v2_4_4_amd64-pfSense_v2_4_4-job-04 23:36  4-Sep-2018)
Nov 11 05:26:31 pfSense ppp: caught fatal signal TERM
Nov 11 05:26:31 pfSense ppp: [opt1] IFACE: Close event
Nov 11 05:26:31 pfSense ppp: [opt1] IPCP: Close event
Nov 11 05:26:31 pfSense ppp: [opt1] IPV6CP: Close event
Nov 11 05:26:31 pfSense ppp: waiting for process 74210 to die...
Nov 11 05:26:32 pfSense ppp: waiting for process 74210 to die...
Nov 11 05:26:32 pfSense ppp: [opt1_link0] LCP: Close event
Nov 11 05:26:32 pfSense ppp: [opt1_link0] LCP: state change Starting --> Initial
Nov 11 05:26:32 pfSense ppp: [opt1_link0] LCP: LayerFinish
Nov 11 05:26:33 pfSense ppp: [opt1] Bundle: Shutdown
Nov 11 05:26:33 pfSense ppp: [opt1_link0] Link: Shutdown
Nov 11 05:26:33 pfSense ppp: process 74210 terminated
Nov 11 05:26:33 pfSense ppp: web: web is not running
Nov 11 05:26:33 pfSense ppp: [opt1] Bundle: Interface ng0 created
Nov 11 05:26:33 pfSense ppp: [opt1_link0] Link: OPEN event
Nov 11 05:26:33 pfSense ppp: [opt1_link0] LCP: Open event
Nov 11 05:26:33 pfSense ppp: [opt1_link0] LCP: state change Initial --> Starting
Nov 11 05:26:33 pfSense ppp: [opt1_link0] LCP: LayerStart
Nov 11 05:26:34 pfSense ppp: [opt1_link0] CHAT: +CGDCONT=1,"IP","connect"
Nov 11 05:26:34 pfSense ppp: [opt1_link0] CHAT: Detected Custom modem.
Nov 11 05:26:34 pfSense ppp: [opt1_link0] CHAT: Dialing server at *99#...
Nov 11 05:26:34 pfSense ppp: [opt1_link0] CHAT: ATDT*99#
Nov 11 05:26:34 pfSense ppp: [opt1_link0] CHAT: Connected at an unknown speed.
Nov 11 05:26:34 pfSense ppp: [opt1_link0] MODEM: chat script succeeded
Nov 11 05:26:34 pfSense ppp: [opt1_link0] Link: UP event
Nov 11 05:26:34 pfSense ppp: [opt1_link0] LCP: Up event
Nov 11 05:26:34 pfSense ppp: [opt1_link0] LCP: state change Starting --> Req-Sent
Nov 11 05:26:34 pfSense ppp: [opt1_link0] LCP: SendConfigReq #1
Nov 11 05:26:34 pfSense ppp: [opt1_link0]   ACFCOMP
Nov 11 05:26:34 pfSense ppp: [opt1_link0]   PROTOCOMP
Nov 11 05:26:34 pfSense ppp: [opt1_link0]   ACCMAP 0x000a0000
Nov 11 05:26:34 pfSense ppp: [opt1_link0]   MRU 1500
Nov 11 05:26:34 pfSense ppp: [opt1_link0]   MAGICNUM 0x047c23ac
Nov 11 05:26:34 pfSense ppp: [opt1_link0] LCP: rec'd Configure Request #1 (Req-Sent)
Nov 11 05:26:34 pfSense ppp: [opt1_link0]   ACFCOMP
Nov 11 05:26:34 pfSense ppp: [opt1_link0]   PROTOCOMP
Nov 11 05:26:34 pfSense ppp: [opt1_link0]   ACCMAP 0x00000000
Nov 11 05:26:34 pfSense ppp: [opt1_link0]   MRU 1500
Nov 11 05:26:34 pfSense ppp: [opt1_link0]   MAGICNUM 0x0000054d
Nov 11 05:26:34 pfSense ppp: [opt1_link0]   AUTHPROTO CHAP MD5
Nov 11 05:26:34 pfSense ppp: [opt1_link0] LCP: SendConfigAck #1
Nov 11 05:26:34 pfSense ppp: [opt1_link0]   ACFCOMP
Nov 11 05:26:34 pfSense ppp: [opt1_link0]   PROTOCOMP
Nov 11 05:26:34 pfSense ppp: [opt1_link0]   ACCMAP 0x00000000
Nov 11 05:26:34 pfSense ppp: [opt1_link0]   MRU 1500
Nov 11 05:26:34 pfSense ppp: [opt1_link0]   MAGICNUM 0x0000054d
Nov 11 05:26:34 pfSense ppp: [opt1_link0]   AUTHPROTO CHAP MD5
Nov 11 05:26:34 pfSense ppp: [opt1_link0] LCP: state change Req-Sent --> Ack-Sent
Nov 11 05:26:34 pfSense ppp: [opt1_link0] LCP: rec'd Configure Ack #1 (Ack-Sent)
Nov 11 05:26:34 pfSense ppp: [opt1_link0]   ACFCOMP
Nov 11 05:26:34 pfSense ppp: [opt1_link0]   PROTOCOMP
Nov 11 05:26:34 pfSense ppp: [opt1_link0]   ACCMAP 0x000a0000
Nov 11 05:26:34 pfSense ppp: [opt1_link0]   MRU 1500
Nov 11 05:26:34 pfSense ppp: [opt1_link0]   MAGICNUM 0x047c23ac
Nov 11 05:26:34 pfSense ppp: [opt1_link0] LCP: state change Ack-Sent --> Opened
Nov 11 05:26:34 pfSense ppp: [opt1_link0] LCP: auth: peer wants CHAP, I want nothing
Nov 11 05:26:34 pfSense ppp: [opt1_link0] LCP: LayerUp
Nov 11 05:26:34 pfSense ppp: [opt1_link0] CHAP: rec'd CHALLENGE #1 len: 37
Nov 11 05:26:34 pfSense ppp: [opt1_link0]   Name: "HUAWEI_CHAP_SRVR"
Nov 11 05:26:34 pfSense ppp: [opt1_link0] CHAP: Using authname "user"
Nov 11 05:26:34 pfSense ppp: [opt1_link0] CHAP: sending RESPONSE #1 len: 25
Nov 11 05:26:34 pfSense ppp: [opt1_link0] CHAP: rec'd SUCCESS #1 len: 13
Nov 11 05:26:34 pfSense ppp: [opt1_link0]   MESG: Welcome!!
Nov 11 05:26:34 pfSense ppp: [opt1_link0] LCP: authorization successful
Nov 11 05:26:34 pfSense ppp: [opt1_link0] Link: Matched action 'bundle "opt1" ""'
Nov 11 05:26:34 pfSense ppp: [opt1_link0] Link: Join bundle "opt1"
Nov 11 05:26:34 pfSense ppp: [opt1] Bundle: Status update: up 1 link, total bandwidth 28800 bps
Nov 11 05:26:34 pfSense ppp: [opt1] IPCP: Open event
Nov 11 05:26:34 pfSense ppp: [opt1] IPCP: state change Initial --> Starting
Nov 11 05:26:34 pfSense ppp: [opt1] IPCP: LayerStart
Nov 11 05:26:34 pfSense ppp: [opt1] IPV6CP: Open event
Nov 11 05:26:34 pfSense ppp: [opt1] IPV6CP: state change Initial --> Starting
Nov 11 05:26:34 pfSense ppp: [opt1] IPV6CP: LayerStart
Nov 11 05:26:34 pfSense ppp: [opt1] IPCP: Up event
Nov 11 05:26:34 pfSense ppp: [opt1] IPCP: state change Starting --> Req-Sent
Nov 11 05:26:34 pfSense ppp: [opt1] IPCP: SendConfigReq #1
Nov 11 05:26:34 pfSense ppp: [opt1]   IPADDR 0.0.0.0
Nov 11 05:26:34 pfSense ppp: [opt1]   COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Nov 11 05:26:34 pfSense ppp: [opt1]   PRIDNS 0.0.0.0
Nov 11 05:26:34 pfSense ppp: [opt1]   SECDNS 0.0.0.0
Nov 11 05:26:34 pfSense ppp: [opt1] IPV6CP: Up event
Nov 11 05:26:34 pfSense ppp: [opt1] IPV6CP: state change Starting --> Req-Sent
Nov 11 05:26:34 pfSense ppp: [opt1] IPV6CP: SendConfigReq #1
Nov 11 05:26:34 pfSense ppp: [opt1] IPCP: rec'd Configure Request #1 (Req-Sent)
Nov 11 05:26:34 pfSense ppp: [opt1] IPCP: SendConfigAck #1
Nov 11 05:26:34 pfSense ppp: [opt1] IPCP: state change Req-Sent --> Ack-Sent
Nov 11 05:26:34 pfSense ppp: [opt1] IPCP: rec'd Configure Nak #1 (Ack-Sent)
Nov 11 05:26:34 pfSense ppp: [opt1] IPCP: SendConfigReq #2
Nov 11 05:26:34 pfSense ppp: [opt1]   IPADDR 0.0.0.0
Nov 11 05:26:34 pfSense ppp: [opt1]   COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Nov 11 05:26:34 pfSense ppp: [opt1]   PRIDNS 0.0.0.0
Nov 11 05:26:34 pfSense ppp: [opt1]   SECDNS 0.0.0.0
Nov 11 05:26:34 pfSense ppp: [opt1_link0] LCP: rec'd Protocol Reject #2 (Opened)
Nov 11 05:26:34 pfSense ppp: [opt1_link0] LCP: protocol IPV6CP was rejected
Nov 11 05:26:34 pfSense ppp: [opt1] IPV6CP: protocol was rejected by peer
Nov 11 05:26:34 pfSense ppp: [opt1] IPV6CP: state change Req-Sent --> Stopped
Nov 11 05:26:34 pfSense ppp: [opt1] IPV6CP: LayerFinish
Nov 11 05:26:34 pfSense ppp: [opt1] IPCP: rec'd Configure Reject #2 (Ack-Sent)
Nov 11 05:26:34 pfSense ppp: [opt1]   COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Nov 11 05:26:34 pfSense ppp: [opt1] IPCP: SendConfigReq #3
Nov 11 05:26:34 pfSense ppp: [opt1]   IPADDR 0.0.0.0
Nov 11 05:26:34 pfSense ppp: [opt1]   PRIDNS 0.0.0.0
Nov 11 05:26:34 pfSense ppp: [opt1]   SECDNS 0.0.0.0
Nov 11 05:26:34 pfSense ppp: [opt1] IPCP: rec'd Configure Nak #3 (Ack-Sent)
Nov 11 05:26:34 pfSense ppp: [opt1]   IPADDR 10.122.201.121
Nov 11 05:26:34 pfSense ppp: [opt1]     10.122.201.121 is OK
Nov 11 05:26:34 pfSense ppp: [opt1]   PRIDNS 198.142.152.162
Nov 11 05:26:34 pfSense ppp: [opt1]   SECDNS 198.142.152.163
Nov 11 05:26:34 pfSense ppp: [opt1] IPCP: SendConfigReq #4
Nov 11 05:26:34 pfSense ppp: [opt1]   IPADDR 10.122.201.121
Nov 11 05:26:34 pfSense ppp: [opt1]   PRIDNS 198.142.152.162
Nov 11 05:26:34 pfSense ppp: [opt1]   SECDNS 198.142.152.163
Nov 11 05:26:34 pfSense ppp: [opt1] IPCP: rec'd Configure Ack #4 (Ack-Sent)
Nov 11 05:26:34 pfSense ppp: [opt1]   IPADDR 10.122.201.121
Nov 11 05:26:34 pfSense ppp: [opt1]   PRIDNS 198.142.152.162
Nov 11 05:26:34 pfSense ppp: [opt1]   SECDNS 198.142.152.163
Nov 11 05:26:34 pfSense ppp: [opt1] IPCP: state change Ack-Sent --> Opened
Nov 11 05:26:34 pfSense ppp: [opt1] IPCP: LayerUp
Nov 11 05:26:34 pfSense ppp: [opt1]   10.122.201.121 -> 10.64.64.0
Nov 11 05:26:35 pfSense ppp: [opt1] IFACE: Up event
Nov 11 05:26:35 pfSense ppp: [opt1] IFACE: Rename interface ng0 to ppp0

Hitting disconnect successfully brings the interface down:

Nov 11 05:52:07 pfSense ppp: caught fatal signal TERM
Nov 11 05:52:07 pfSense ppp: [opt1] IFACE: Close event
Nov 11 05:52:07 pfSense ppp: [opt1] IPCP: Close event
Nov 11 05:52:07 pfSense ppp: [opt1] IPCP: state change Opened --> Closing
Nov 11 05:52:07 pfSense ppp: [opt1] IPCP: SendTerminateReq #5
Nov 11 05:52:07 pfSense ppp: [opt1] IPCP: LayerDown
Nov 11 05:52:07 pfSense ppp: [opt1] IFACE: Down event
Nov 11 05:52:07 pfSense ppp: [opt1] IFACE: Rename interface ppp0 to ppp0
Nov 11 05:52:07 pfSense ppp: [opt1] IPV6CP: Close event
Nov 11 05:52:07 pfSense ppp: [opt1] IPV6CP: state change Stopped --> Closed
Nov 11 05:52:07 pfSense ppp: [opt1] IPCP: rec'd Terminate Ack #5 (Closing)
Nov 11 05:52:07 pfSense ppp: [opt1] IPCP: state change Closing --> Closed
Nov 11 05:52:07 pfSense ppp: [opt1] IPCP: LayerFinish
Nov 11 05:52:07 pfSense ppp: [opt1] Bundle: No NCPs left. Closing links...
Nov 11 05:52:07 pfSense ppp: [opt1] Bundle: closing link "opt1_link0"...
Nov 11 05:52:07 pfSense ppp: [opt1_link0] LCP: rec'd Terminate Request #2 (Opened)
Nov 11 05:52:07 pfSense ppp: [opt1_link0] LCP: state change Opened --> Stopping
Nov 11 05:52:07 pfSense ppp: [opt1_link0] Link: Leave bundle "opt1"
Nov 11 05:52:07 pfSense ppp: [opt1] Bundle: Status update: up 0 links, total bandwidth 9600 bps
Nov 11 05:52:07 pfSense ppp: [opt1] IPCP: Close event
Nov 11 05:52:07 pfSense ppp: [opt1] IPV6CP: Close event
Nov 11 05:52:07 pfSense ppp: [opt1] IPCP: Down event
Nov 11 05:52:07 pfSense ppp: [opt1] IPCP: state change Closed --> Initial
Nov 11 05:52:07 pfSense ppp: [opt1] IPV6CP: Down event
Nov 11 05:52:07 pfSense ppp: [opt1] IPV6CP: state change Closed --> Initial
Nov 11 05:52:07 pfSense ppp: [opt1_link0] LCP: SendTerminateAck #2
Nov 11 05:52:07 pfSense ppp: [opt1_link0] LCP: LayerDown
Nov 11 05:52:07 pfSense ppp: [opt1_link0] Link: CLOSE event
Nov 11 05:52:07 pfSense ppp: [opt1_link0] LCP: Close event
Nov 11 05:52:07 pfSense ppp: [opt1_link0] LCP: state change Stopping --> Closing
Nov 11 05:52:09 pfSense ppp: [opt1_link0] LCP: state change Closing --> Closed
Nov 11 05:52:09 pfSense ppp: [opt1_link0] LCP: LayerFinish
Nov 11 05:52:09 pfSense ppp: [opt1] Bundle: Shutdown
Nov 11 05:52:09 pfSense ppp: [opt1_link0] Link: Shutdown
Nov 11 05:52:09 pfSense ppp: process 44585 terminated

Now, when we attempt to reconnect by hitting the connect button the link never comes up and continually retries:

Nov 11 05:52:53 pfSense ppp: Multi-link PPP daemon for FreeBSD
Nov 11 05:52:53 pfSense ppp:
Nov 11 05:52:53 pfSense ppp: process 3602 started, version 5.8 (nobody@pfSense_v2_4_4_amd64-pfSense_v2_4_4-job-04 23:36  4-Sep-2018)
Nov 11 05:52:53 pfSense ppp: web: web is not running
Nov 11 05:52:53 pfSense ppp: [opt1] Bundle: Interface ng0 created
Nov 11 05:52:53 pfSense ppp: [opt1_link0] Link: OPEN event
Nov 11 05:52:53 pfSense ppp: [opt1_link0] LCP: Open event
Nov 11 05:52:53 pfSense ppp: [opt1_link0] LCP: state change Initial --> Starting
Nov 11 05:52:53 pfSense ppp: [opt1_link0] LCP: LayerStart
Nov 11 05:53:06 pfSense ppp: [opt1_link0] CHAT: The modem is not responding to "AT" at ModemCmd: label.
Nov 11 05:53:06 pfSense ppp: [opt1_link0] MODEM: chat script failed
Nov 11 05:53:06 pfSense ppp: [opt1_link0] Link: DOWN event
Nov 11 05:53:06 pfSense ppp: [opt1_link0] LCP: Down event
Nov 11 05:53:06 pfSense ppp: [opt1_link0] Link: reconnection attempt 1 in 4 seconds
Nov 11 05:53:11 pfSense ppp: [opt1_link0] Link: reconnection attempt 1
Nov 11 05:53:24 pfSense ppp: [opt1_link0] CHAT: The modem is not responding to "AT" at ModemCmd: label.
Nov 11 05:53:24 pfSense ppp: [opt1_link0] MODEM: chat script failed
Nov 11 05:53:24 pfSense ppp: [opt1_link0] Link: DOWN event
Nov 11 05:53:24 pfSense ppp: [opt1_link0] LCP: Down event
Nov 11 05:53:24 pfSense ppp: [opt1_link0] Link: reconnection attempt 2 in 4 seconds
Nov 11 05:53:28 pfSense ppp: [opt1_link0] Link: reconnection attempt 2

As you'd expect, rebooting the machine brings it back online, manually I am able to reset the usb port the E3372 is attached to either by unplugging and replugging it in, or by issuing a reset on the port which is the software way of doing the same thing:

[2.4.4-RELEASE][admin@pfSense.localdomain]/root: usbconfig
ugen0.1: <0x8086 XHCI root HUB> at usbus0, cfg=0 md=HOST spd=SUPER (5.0Gbps) pwr=SAVE (0mA)
ugen1.1: <Intel EHCI root HUB> at usbus1, cfg=0 md=HOST spd=HIGH (480Mbps) pwr=SAVE (0mA)
ugen0.2: <HUAWEIMOBILE HUAWEIMOBILE> at usbus0, cfg=0 md=HOST spd=HIGH (480Mbps) pwr=ON (2mA)
ugen0.3: <vendor 0x05e3 USB2.0 Hub> at usbus0, cfg=0 md=HOST spd=HIGH (480Mbps) pwr=SAVE (100mA)
ugen0.4: <Generic USB Storage> at usbus0, cfg=0 md=HOST spd=HIGH (480Mbps) pwr=ON (500mA)
ugen1.2: <vendor 0x8087 product 0x8001> at usbus1, cfg=0 md=HOST spd=HIGH (480Mbps) pwr=SAVE (0mA)

[2.4.4-RELEASE][admin@pfSense.localdomain]/root: usbconfig -d 0.2 reset

Immediately after the unplug/replug or usbconfig reset we see the modem is no longer present at the originally configured port in the PPP log:

Nov 11 05:56:23 pfSense ppp: [opt1_link0] Link: reconnection attempt 13
Nov 11 05:56:23 pfSense ppp: [opt1_link0] can't open /dev/cuaU5.0: Device not configured
Nov 11 05:56:23 pfSense ppp: [opt1_link0] MODEM: Fail to open serial port /dev/cuaU5.0 on speed 115200
Nov 11 05:56:23 pfSense ppp: [opt1_link0] Link: DOWN event
Nov 11 05:56:23 pfSense ppp: [opt1_link0] LCP: Down event

When the modem is removed and replugged or software reset, the /dev/cuaUx.y port it occupies has x incremented by 1. So now my PPP configuration is broken as /dev/cuaU5.0 no longer exists and to get it to reconnect I need to manually edit the PPP instance and specify the new port which will now appear in the list of link interfaces under PPP. In this instance it incremented to /dev/cuaU6.0. (on a fresh boot it's /dev/cuaU0.0) The moment I select the correct link interface, boom the link is back up and online immediately:

Nov 11 06:02:17 pfSense ppp: process 38317 started, version 5.8 (nobody@pfSense_v2_4_4_amd64-pfSense_v2_4_4-job-04 23:36  4-Sep-2018)
Nov 11 06:02:17 pfSense ppp: caught fatal signal TERM
Nov 11 06:02:17 pfSense ppp: [opt1] IFACE: Close event
Nov 11 06:02:17 pfSense ppp: [opt1] IPCP: Close event
Nov 11 06:02:17 pfSense ppp: [opt1] IPV6CP: Close event
Nov 11 06:02:17 pfSense ppp: waiting for process 3602 to die...
Nov 11 06:02:18 pfSense ppp: [opt1_link0] LCP: Close event
Nov 11 06:02:18 pfSense ppp: [opt1_link0] LCP: state change Starting --> Initial
Nov 11 06:02:18 pfSense ppp: [opt1_link0] LCP: LayerFinish
Nov 11 06:02:18 pfSense ppp: waiting for process 3602 to die...
Nov 11 06:02:19 pfSense ppp: [opt1] Bundle: Shutdown
Nov 11 06:02:19 pfSense ppp: [opt1_link0] Link: Shutdown
Nov 11 06:02:19 pfSense ppp: process 3602 terminated
Nov 11 06:02:19 pfSense ppp: web: web is not running
Nov 11 06:02:19 pfSense ppp: [opt1] Bundle: Interface ng0 created
Nov 11 06:02:19 pfSense ppp: [opt1_link0] Link: OPEN event
Nov 11 06:02:19 pfSense ppp: [opt1_link0] LCP: Open event
Nov 11 06:02:19 pfSense ppp: [opt1_link0] LCP: state change Initial --> Starting
Nov 11 06:02:19 pfSense ppp: [opt1_link0] LCP: LayerStart
Nov 11 06:02:20 pfSense ppp: [opt1_link0] CHAT: +CGDCONT=1,"IP","connect"
Nov 11 06:02:20 pfSense ppp: [opt1_link0] CHAT: Detected Custom modem.
Nov 11 06:02:20 pfSense ppp: [opt1_link0] CHAT: Dialing server at *99#...
Nov 11 06:02:20 pfSense ppp: [opt1_link0] CHAT: ATDT*99#
Nov 11 06:02:20 pfSense ppp: [opt1_link0] CHAT: Connected at an unknown speed.
Nov 11 06:02:20 pfSense ppp: [opt1_link0] MODEM: chat script succeeded
Nov 11 06:02:20 pfSense ppp: [opt1_link0] Link: UP event
Nov 11 06:02:20 pfSense ppp: [opt1_link0] LCP: Up event
Nov 11 06:02:20 pfSense ppp: [opt1_link0] LCP: state change Starting --> Req-Sent
Nov 11 06:02:20 pfSense ppp: [opt1_link0] LCP: SendConfigReq #1
Nov 11 06:02:20 pfSense ppp: [opt1_link0]   ACFCOMP
Nov 11 06:02:20 pfSense ppp: [opt1_link0]   PROTOCOMP
Nov 11 06:02:20 pfSense ppp: [opt1_link0]   ACCMAP 0x000a0000
Nov 11 06:02:20 pfSense ppp: [opt1_link0]   MRU 1500
Nov 11 06:02:20 pfSense ppp: [opt1_link0]   MAGICNUM 0xfa99d8e3
Nov 11 06:02:20 pfSense ppp: [opt1_link0] LCP: rec'd Configure Request #1 (Req-Sent)
Nov 11 06:02:20 pfSense ppp: [opt1_link0]   ACFCOMP
Nov 11 06:02:20 pfSense ppp: [opt1_link0]   PROTOCOMP
Nov 11 06:02:20 pfSense ppp: [opt1_link0]   ACCMAP 0x00000000
Nov 11 06:02:20 pfSense ppp: [opt1_link0]   MRU 1500
Nov 11 06:02:20 pfSense ppp: [opt1_link0]   MAGICNUM 0x0000054f
Nov 11 06:02:20 pfSense ppp: [opt1_link0]   AUTHPROTO CHAP MD5
Nov 11 06:02:20 pfSense ppp: [opt1_link0] LCP: SendConfigAck #1
Nov 11 06:02:20 pfSense ppp: [opt1_link0]   ACFCOMP
Nov 11 06:02:20 pfSense ppp: [opt1_link0]   PROTOCOMP
Nov 11 06:02:20 pfSense ppp: [opt1_link0]   ACCMAP 0x00000000
Nov 11 06:02:20 pfSense ppp: [opt1_link0]   MRU 1500
Nov 11 06:02:20 pfSense ppp: [opt1_link0]   MAGICNUM 0x0000054f
Nov 11 06:02:20 pfSense ppp: [opt1_link0]   AUTHPROTO CHAP MD5
Nov 11 06:02:20 pfSense ppp: [opt1_link0] LCP: state change Req-Sent --> Ack-Sent
Nov 11 06:02:20 pfSense ppp: [opt1_link0] LCP: rec'd Configure Ack #1 (Ack-Sent)
Nov 11 06:02:20 pfSense ppp: [opt1_link0]   ACFCOMP
Nov 11 06:02:20 pfSense ppp: [opt1_link0]   PROTOCOMP
Nov 11 06:02:20 pfSense ppp: [opt1_link0]   ACCMAP 0x000a0000
Nov 11 06:02:20 pfSense ppp: [opt1_link0]   MRU 1500
Nov 11 06:02:20 pfSense ppp: [opt1_link0]   MAGICNUM 0xfa99d8e3
Nov 11 06:02:20 pfSense ppp: [opt1_link0] LCP: state change Ack-Sent --> Opened
Nov 11 06:02:20 pfSense ppp: [opt1_link0] LCP: auth: peer wants CHAP, I want nothing
Nov 11 06:02:20 pfSense ppp: [opt1_link0] LCP: LayerUp
Nov 11 06:02:20 pfSense ppp: [opt1_link0] CHAP: rec'd CHALLENGE #1 len: 37
Nov 11 06:02:20 pfSense ppp: [opt1_link0]   Name: "HUAWEI_CHAP_SRVR"
Nov 11 06:02:20 pfSense ppp: [opt1_link0] CHAP: Using authname "user"
Nov 11 06:02:20 pfSense ppp: [opt1_link0] CHAP: sending RESPONSE #1 len: 25
Nov 11 06:02:20 pfSense ppp: [opt1_link0] CHAP: rec'd SUCCESS #1 len: 13
Nov 11 06:02:20 pfSense ppp: [opt1_link0]   MESG: Welcome!!
Nov 11 06:02:20 pfSense ppp: [opt1_link0] LCP: authorization successful
Nov 11 06:02:20 pfSense ppp: [opt1_link0] Link: Matched action 'bundle "opt1" ""'
Nov 11 06:02:20 pfSense ppp: [opt1_link0] Link: Join bundle "opt1"
Nov 11 06:02:20 pfSense ppp: [opt1] Bundle: Status update: up 1 link, total bandwidth 28800 bps
Nov 11 06:02:20 pfSense ppp: [opt1] IPCP: Open event
Nov 11 06:02:20 pfSense ppp: [opt1] IPCP: state change Initial --> Starting
Nov 11 06:02:20 pfSense ppp: [opt1] IPCP: LayerStart
Nov 11 06:02:20 pfSense ppp: [opt1] IPV6CP: Open event
Nov 11 06:02:20 pfSense ppp: [opt1] IPV6CP: state change Initial --> Starting
Nov 11 06:02:20 pfSense ppp: [opt1] IPV6CP: LayerStart
Nov 11 06:02:20 pfSense ppp: [opt1] IPCP: Up event
Nov 11 06:02:20 pfSense ppp: [opt1] IPCP: state change Starting --> Req-Sent
Nov 11 06:02:20 pfSense ppp: [opt1] IPCP: SendConfigReq #1
Nov 11 06:02:20 pfSense ppp: [opt1]   IPADDR 0.0.0.0
Nov 11 06:02:20 pfSense ppp: [opt1]   COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Nov 11 06:02:20 pfSense ppp: [opt1]   PRIDNS 0.0.0.0
Nov 11 06:02:20 pfSense ppp: [opt1]   SECDNS 0.0.0.0
Nov 11 06:02:20 pfSense ppp: [opt1] IPV6CP: Up event
Nov 11 06:02:20 pfSense ppp: [opt1] IPV6CP: state change Starting --> Req-Sent
Nov 11 06:02:20 pfSense ppp: [opt1] IPV6CP: SendConfigReq #1
Nov 11 06:02:20 pfSense ppp: [opt1] IPCP: rec'd Configure Request #1 (Req-Sent)
Nov 11 06:02:20 pfSense ppp: [opt1] IPCP: SendConfigAck #1
Nov 11 06:02:20 pfSense ppp: [opt1] IPCP: state change Req-Sent --> Ack-Sent
Nov 11 06:02:20 pfSense ppp: [opt1] IPCP: rec'd Configure Nak #1 (Ack-Sent)
Nov 11 06:02:20 pfSense ppp: [opt1] IPCP: SendConfigReq #2
Nov 11 06:02:20 pfSense ppp: [opt1]   IPADDR 0.0.0.0
Nov 11 06:02:20 pfSense ppp: [opt1]   COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Nov 11 06:02:20 pfSense ppp: [opt1]   PRIDNS 0.0.0.0
Nov 11 06:02:20 pfSense ppp: [opt1]   SECDNS 0.0.0.0
Nov 11 06:02:20 pfSense ppp: [opt1_link0] LCP: rec'd Protocol Reject #2 (Opened)
Nov 11 06:02:20 pfSense ppp: [opt1_link0] LCP: protocol IPV6CP was rejected
Nov 11 06:02:20 pfSense ppp: [opt1] IPV6CP: protocol was rejected by peer
Nov 11 06:02:20 pfSense ppp: [opt1] IPV6CP: state change Req-Sent --> Stopped
Nov 11 06:02:20 pfSense ppp: [opt1] IPV6CP: LayerFinish
Nov 11 06:02:20 pfSense ppp: [opt1] IPCP: rec'd Configure Reject #2 (Ack-Sent)
Nov 11 06:02:20 pfSense ppp: [opt1]   COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Nov 11 06:02:20 pfSense ppp: [opt1] IPCP: SendConfigReq #3
Nov 11 06:02:20 pfSense ppp: [opt1]   IPADDR 0.0.0.0
Nov 11 06:02:20 pfSense ppp: [opt1]   PRIDNS 0.0.0.0
Nov 11 06:02:20 pfSense ppp: [opt1]   SECDNS 0.0.0.0
Nov 11 06:02:20 pfSense ppp: [opt1] IPCP: rec'd Configure Nak #3 (Ack-Sent)
Nov 11 06:02:20 pfSense ppp: [opt1]   IPADDR 10.122.201.121
Nov 11 06:02:20 pfSense ppp: [opt1]     10.122.201.121 is OK
Nov 11 06:02:20 pfSense ppp: [opt1]   PRIDNS 198.142.152.162
Nov 11 06:02:20 pfSense ppp: [opt1]   SECDNS 198.142.152.163
Nov 11 06:02:20 pfSense ppp: [opt1] IPCP: SendConfigReq #4
Nov 11 06:02:20 pfSense ppp: [opt1]   IPADDR 10.122.201.121
Nov 11 06:02:20 pfSense ppp: [opt1]   PRIDNS 198.142.152.162
Nov 11 06:02:20 pfSense ppp: [opt1]   SECDNS 198.142.152.163
Nov 11 06:02:20 pfSense ppp: [opt1] IPCP: rec'd Configure Ack #4 (Ack-Sent)
Nov 11 06:02:20 pfSense ppp: [opt1]   IPADDR 10.122.201.121
Nov 11 06:02:20 pfSense ppp: [opt1]   PRIDNS 198.142.152.162
Nov 11 06:02:20 pfSense ppp: [opt1]   SECDNS 198.142.152.163
Nov 11 06:02:20 pfSense ppp: [opt1] IPCP: state change Ack-Sent --> Opened
Nov 11 06:02:20 pfSense ppp: [opt1] IPCP: LayerUp
Nov 11 06:02:20 pfSense ppp: [opt1]   10.122.201.121 -> 10.64.64.0
Nov 11 06:02:21 pfSense ppp: [opt1] IFACE: Up event
Nov 11 06:02:21 pfSense ppp: [opt1] IFACE: Rename interface ng0 to ppp0

I was testing the disconnect / reconnect functionality simply to validate the stability of the connection / solution. My concern is given it cannot recover from a manually triggered disconnect/reconnect I expect that in real world use a momentary 4G outage is going to mean connection down permanently until some user intervention takes place. In my experience pfsense normally does a pretty good of job staying online with other connections types (eg PPPoE, ethernet, OpenVPN etc) so I'm sure there's something here that can be done. As IT guys we like to automate things and deliver solid solutions so I'd be keen for some input on how this might be able to be achieved.

If you've made it this far, thank you!

AndrewZ

@bradtpt said in Huawei E3372 will not reconnect PPP after manual disconnect under status-->interfaces:

Modem AT^SETPORT="FF;12,16"

That looks wrong for me. For PPP you need '10' to be there, so you should have either from

AT^SETPORT="FF;10,12" 
AT^SETPORT="FF;10,12,16"

bradtpt

Hi AndrewZ,

I apologise, that's a mistake in my post, I copy and pasted that from a list where I had tried a few different SETPORT configurations. I am in fact using the string you suggested as it won't connect with 10 missing.

I've edited the above post to show the correct info for my config.

AT^SETPORT="FF;10,12,16"
^GETPORTMODE: TYPE: WCDMA: huawei,,modem:0,pcui:1,ncm:2

netblues

You are most probably out of luck here.
These ppp sticks don't behave well. I have played with a few in the past.
When they work, performane is nice etc.
However reconnecting was always a nightmare.
At some point everything worked, however if the stick was removed and pf was rebooted
then it would detect an interface missing and require a new text based interface setup.
I ended up using a small mikrotkik router housing the usb stick and providing pure ethernet to the pf. Rock solid

bradtpt

I hope we're not out of luck! I went with the direct PPP method as I require this device to host services over this interface and don't want the headache and pitfalls associated with double NAT if I were to put the pf box behind another router. To that end I initially configured the stick working hilink mode which presents itself to the pf box as a network interface, however there's no way to configure a DMZ in the stick firmware to pass through all the external traffic. In hilink mode the stick takes care of the 4G connection and the whole disconnect/reconnect through the firmware's webui in the stick works fine; however double NAT just doesn't cut it for this application.

Has anyone had similar experience with current 4G dongle successfully connecting, disconnecting and reconnecting using PPP?

netblues

@bradtpt Yes, its true that hilink mode doesn't have a dmz feature and that's a pitty. The thing is that usb management relies on the os and I doubt there is much to be done at the pf level.
I never found a reliable solution anyways.
And as you are at it, make sure that you get a working ip from 4g. Nowdays 4g carriers often do cgn, or just firewall their networks not allowing incoming connections.

bradtpt

I was hoping it was just something not quite right with the way the PPP session was being terminated as the logs show the modem no longer responding to commands after the session is terminated. You're correct regarding the NAT'd addresses most mobile providers dish out. I'm in Australia and in this example I was connecting using an Optus prepaid sim and that's exactly what we get, an IP of 10.x.x.x which isn't a public routable address. This box will end up with a Telstra sim in it using the 'telstra.extranet' apn which does provide us a public routable address which I have tested and does work. The headache is though they can't give us static IP so we'll be relying on dynamic DNS updates

In my further investigation I have found that I can terminal into the com ports it presents prior to making a connection (/dev/cuaU0.0 and /dev/cuaU0.1) and can query the modem with commands like ATI and get a response. Once the connection is up I can no longer terminal into the port the modem is using with a 'device is busy' error, this is expected behaviour. Whilst the connection is active I am able to cu -l /dev/cuaU0.1 and query the modem as this is the other port the modem presents and isn't used for the data connection. In the 0.1 port the modem reports network connection type, RSSI and a few other parameters every 20 seconds or so like follows:

[2.4.4-RELEASE][admin@pfSense.localdomain]/root: cu -l /dev/cuaU8.1
Connected

^HCSQ:"LTE",45,35,111,20

^HCSQ:"LTE",44,35,111,22

^RSSI:17

^RSSI:19

^RSSI:19

^RSSI:18

^RSSI:19

^RSSI:18

^RSSI:19

^RSSI:18

^RSSI:18

^RSSI:18

^RSSI:19

^RSSI:19

^RSSI:19

^HCSQ:"LTE",47,35,116,18

^RSSI:18

^HCSQ:"LTE",44,34,106,20

^HCSQ:"LTE",45,34,116,18

^HCSQ:"LTE",48,40,116,24

^HCSQ:"LTE",45,34,116,18

^HCSQ:"LTE",48,39,121,22

^HCSQ:"LTE",44,34,121,20

^HCSQ:"LTE",49,40,116,24

^HCSQ:"LTE",46,35,121,18

^HCSQ:"LTE",46,36,121,20

^HCSQ:"LTE",47,37,116,20

After bringing the connection down I can reconnect to /dev/cuaU0.0 with the following message about a stale lock:

[2.4.4-RELEASE][admin@pfSense.localdomain]/root: cu -l /dev/cuaU8.0
Stale lock on cuaU8.0 PID=34457... overriding.
Connected

However the modem doesn't reply to any command I issue eg ATI or AT&F etc. Those commands illicit a response when I connect to the .0 port prior to connecting, connecting to 0.1 after the disconnect works fine too.

My thought here is perhaps the PPP client is forcefully terminating the connection rather than sending a valid "hangup" code to the modem. Should I maybe have a dig around in the chat script that ppp runs to do the connection / disconnection? I've had a quick look as I recall finding where I could change a dial string from atdt to atd a few days ago but I can't seem to find it now (any hints? I've looked in places like /usr/local/sbin/ppp-linkdown)

I'll keep messing with it, but if anyone has any suggestions I'd be happy to hear them.

netblues

@bradtpt Lets hope there is a solution. (do try to reboot pf after removing the stick and see if it comes up nicely in any case. I have reasons to believe it will kick in into interfaces configuration mode).
As for dynamic dns, opt for an rfc2136 based solution. It requires administration over your ns's but works splendidly fast and reliable.
https://www.netgate.com/docs/pfsense/dns/rfc2136-dynamic-dns.html
I'm using it for years on a linux box with a simple script. On pf, no need for script

Now as for your further investigation, ppp by design talks to the modem with at commands asking it to make a dial connection. When the modem is connected it enters "transparent" mode and starts passing data
The modem is theoretically unaware of the data protocol used after that.
Sometimes there is an escape sequence that takes the modem into command mode and then you can issue an ATH (for hangap if i recall). However I doubt is used by ppp because it is device specific and due to the fact that ppp has a solid disconnection mechanism in place.
Supposedly, the modem would detect loss of carrier due to far end disconnection and return into command mode.
But in the wonderfull world of emulating things for backwards compatibility, this doesn't happen as it seems.

So, apart from disconnecting the stick physically or rebooting, is there a manual command that resets the modem into a working state? If yes, perhaps it can be scripted.

Long term even if it works this would need to be maintained among version updates. I'm not holding my breath.

bradtpt

If I reboot the box after disconnecting, it will boot up and connect without issue as the interface address remains at /dev/cuaU0.0 after the reboot. I'm up to about 8 or 9.0 now with my testing in my spare time today but with a reboot it'll come back to 0.0. So for a use case scenario where it's deployed and configured at 0.0, after a dropout a simple reboot will bring it back online.

That RFC2136 solution looks lovely, I run my own DNS server so this would tie in a treat, thanks for the tip!

Yes thinking back to my dialup days ATH or ATH0 will hangup the line, I'm not sure what's issued by the dialler script to terminate it but I've managed to find a Huawei based reference AT command set so I was hoping to check.

As for manually bringing the modem back online through software I need to do a "usbconfig -d 0.2 reset" which will increment the base device number by +1. This means that the PPP config needs updating with the link interface /dev/cuaU[x+1].0 (eg for the first disconnect from cuaU0.0 to cuaU1.0). Doing this brings it back without a reboot but it'd hardly what I'd consider ideal. I have visions of looking in the config one day and seeing it trying to connect on link interface /dev/cuaU28463.0 If I can work out a way to delete the stale locks on the ports after the reset, but prior to FreeBSD detecting the device after reset and it allocating interfaces to it the device should come back at the same address and if this were the case the PPP dialler would just pick it up and reconnect... I'll keep digging.

netblues

@bradtpt The thing is that ppp would never talk to the local modem. Disc will go to the far end.
Fiddling with low level usb detection on freebsd isn't very helpful to begin with.
ppp can't support full speed 4g speeds thus the "new" emulated ethernet interfaces.
But the hilink implementation om huawei sucks for not having a dmz, or port forward capability.
I would either opt for a mikrotik 4g router that might handle 4g better and provide an ethernet interface, or I would just create an outbound openvpn client connection to a reliable host and backhaul that traffic

bradtpt

Yeah I tore my hair out for far too many hours last night playing with init strings etc. I now know far more than I ever wanted or needed to about the GPRS AT command set. I actually implemented the openvpn idea a few weeks ago and it works for what we need, I was really just hoping for a much nicer solution.

Part of my frustration comes from the fact I can pull this stick from the pfbox and shove it into my Windows machine and it'll connect/disconnect/connect just fine using the Windows PPP client, likewise I can then throw it in an Ubuntu laptop I have here and it works flawlessly with the whole c/d/c cycle using the Ubuntu's built in PPP client in the network manager. Beside the laptop on my desk is a Draytek Vigor2862ac which I was setting up for another client that I decided to test it on and no surprise here, it works too. Just shits me I can't get pf to play ball on what I thought would be pretty simple functionality.

As for the speeds, I was expecting a max of about 20 - 25mbps, however I have seen 45mbps through it on the pfbox using PPP which is higher than what I'd read they were capable of using PPP. Do you have any experience or feedback regarding speeds as this far exceeded what I had been lead to believe I could achieve with PPP for the reasons you stated above.

netblues

@bradtpt I recall having stability i issues and in hilink mode. Probably something to do with usb at the bsd level. As for speed, when testing I could get up to 80/30 in hilink mode. It would max out at about 40-45 in ppp during my tests too.
I suspect processor speed might play a role here In practice, speeds over 20-30mbits are rare in 4g networks in urban areas due to heavy usage anyway.

stephenw10

I believed the maximum throughput was 42MBps for PPP lining up with HSDPA but I recently saw a report of >60Mbps so I guess it's possible if your carrier and hardware support it. I've personally seen ~32Mbps using a Sierra m.2 modem and PPP.

Steve