PPP/LTE USB Modem Not Connecting on Boot
-
I have set up an LTE/USB modem (Huawei E397 E397u-53) with pfsense 2.3.2-RELEASE. I plan
to use it as a failover WAN connection. It is configured as a ppp0 interface on /dev/cuaU0.0. It
connected fine when I first created the configuration in the GUI. However,
it won't start up on boot. If I edit and re-save the ppp configuration for it, it will again connect
without an issue. This seems similar to an unresolved thread from a few years back:https://forum.pfsense.org/index.php?topic=66911.0
I did some troubleshooting. In /etc/inc/interfaces.inc, I added some [DEBUG] logging in the interface_configure function (lines starting 3175) and got this (see last 15 lines here):
Feb 12 00:19:24 pfsense kernel: Copyright (c) 1992-2016 The FreeBSD Project. Feb 12 00:19:24 pfsense kernel: Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994 Feb 12 00:19:24 pfsense kernel: The Regents of the University of California. All rights reserved. Feb 12 00:19:24 pfsense kernel: FreeBSD is a registered trademark of The FreeBSD Foundation. Feb 12 00:19:24 pfsense kernel: FreeBSD 10.3-RELEASE-p9 #1 5fc1b19(RELENG_2_3_2): Tue Sep 27 12:26:06 CDT 2016 Feb 12 00:19:24 pfsense kernel: root@ce23-amd64-builder:/builder/pfsense-232/tmp/obj/builder/pfsense-232/tmp/FreeBSD-src/sys/pfSense amd64 Feb 12 00:19:24 pfsense kernel: FreeBSD clang version 3.4.1 (tags/RELEASE_34/dot1-final 208032) 20140512 Feb 12 00:19:24 pfsense kernel: CPU: Pentium(R) Dual-Core CPU E5300 @ 2.60GHz (2593.55-MHz K8-class CPU) Feb 12 00:19:24 pfsense kernel: Origin="GenuineIntel" Id=0x1067a Family=0x6 Model=0x17 Stepping=10 Feb 12 00:19:24 pfsense kernel: Features=0xbfebfbff <fpu,vme,de,pse,tsc,msr,pae,mce,cx8,apic,sep,mtrr,pge,mca,cmov,pat,pse36,clflush,dts,acpi,mmx,fxsr,sse,sse2,ss,htt,tm,pbe>Feb 12 00:19:24 pfsense kernel: Features2=0xc00e3bd <sse3,dtes64,mon,ds_cpl,vmx,est,tm2,ssse3,cx16,xtpr,pdcm,xsave,osxsave>Feb 12 00:19:24 pfsense kernel: AMD Features=0x20100800 <syscall,nx,lm>Feb 12 00:19:24 pfsense kernel: AMD Features2=0x1 <lahf>Feb 12 00:19:24 pfsense kernel: VT-x: HLT,PAUSE Feb 12 00:19:24 pfsense kernel: TSC: P-state invariant, performance statistics Feb 12 00:19:24 pfsense kernel: real memory = 3221225472 (3072 MB) Feb 12 00:19:24 pfsense kernel: avail memory = 3043532800 (2902 MB) Feb 12 00:19:24 pfsense kernel: Event timer "LAPIC" quality 400 Feb 12 00:19:24 pfsense kernel: ACPI APIC Table: <072309 APIC1648> Feb 12 00:19:24 pfsense kernel: FreeBSD/SMP: Multiprocessor System Detected: 2 CPUs Feb 12 00:19:24 pfsense kernel: FreeBSD/SMP: 1 package(s) x 2 core(s) Feb 12 00:19:24 pfsense kernel: cpu0 (BSP): APIC ID: 0 Feb 12 00:19:24 pfsense kernel: cpu1 (AP): APIC ID: 1 Feb 12 00:19:24 pfsense kernel: random: <software, yarrow="">initialized Feb 12 00:19:24 pfsense kernel: ioapic0 <version 2.0="">irqs 0-23 on motherboard Feb 12 00:19:24 pfsense kernel: wlan: mac acl policy registered Feb 12 00:19:24 pfsense kernel: ipw_bss: You need to read the LICENSE file in /usr/share/doc/legal/intel_ipw/. Feb 12 00:19:24 pfsense kernel: ipw_bss: If you agree with the license, set legal.intel_ipw.license_ack=1 in /boot/loader.conf. Feb 12 00:19:24 pfsense kernel: module_register_init: MOD_LOAD (ipw_bss_fw, 0xffffffff80620930, 0) error 1 Feb 12 00:19:24 pfsense kernel: ipw_ibss: You need to read the LICENSE file in /usr/share/doc/legal/intel_ipw/. Feb 12 00:19:24 pfsense kernel: ipw_ibss: If you agree with the license, set legal.intel_ipw.license_ack=1 in /boot/loader.conf. Feb 12 00:19:24 pfsense kernel: module_register_init: MOD_LOAD (ipw_ibss_fw, 0xffffffff806209e0, 0) error 1 Feb 12 00:19:24 pfsense kernel: ipw_monitor: You need to read the LICENSE file in /usr/share/doc/legal/intel_ipw/. Feb 12 00:19:24 pfsense kernel: ipw_monitor: If you agree with the license, set legal.intel_ipw.license_ack=1 in /boot/loader.conf. Feb 12 00:19:24 pfsense kernel: module_register_init: MOD_LOAD (ipw_monitor_fw, 0xffffffff80620a90, 0) error 1 Feb 12 00:19:24 pfsense kernel: iwi_bss: You need to read the LICENSE file in /usr/share/doc/legal/intel_iwi/. Feb 12 00:19:24 pfsense kernel: iwi_bss: If you agree with the license, set legal.intel_iwi.license_ack=1 in /boot/loader.conf. Feb 12 00:19:24 pfsense kernel: module_register_init: MOD_LOAD (iwi_bss_fw, 0xffffffff80647c30, 0) error 1 Feb 12 00:19:24 pfsense kernel: iwi_ibss: You need to read the LICENSE file in /usr/share/doc/legal/intel_iwi/. Feb 12 00:19:24 pfsense kernel: iwi_ibss: If you agree with the license, set legal.intel_iwi.license_ack=1 in /boot/loader.conf. Feb 12 00:19:24 pfsense kernel: module_register_init: MOD_LOAD (iwi_ibss_fw, 0xffffffff80647ce0, 0) error 1 Feb 12 00:19:24 pfsense kernel: iwi_monitor: You need to read the LICENSE file in /usr/share/doc/legal/intel_iwi/. Feb 12 00:19:24 pfsense kernel: iwi_monitor: If you agree with the license, set legal.intel_iwi.license_ack=1 in /boot/loader.conf. Feb 12 00:19:24 pfsense kernel: module_register_init: MOD_LOAD (iwi_monitor_fw, 0xffffffff80647d90, 0) error 1 Feb 12 00:19:24 pfsense kernel: netmap: loaded module Feb 12 00:19:24 pfsense kernel: kbd1 at kbdmux0 Feb 12 00:19:24 pfsense kernel: cryptosoft0: <software crypto="">on motherboard Feb 12 00:19:24 pfsense kernel: padlock0: No ACE support. Feb 12 00:19:24 pfsense kernel: acpi0: <dell ecs ="" ="">on motherboard Feb 12 00:19:24 pfsense kernel: acpi0: Power Button (fixed) Feb 12 00:19:24 pfsense kernel: cpu0: <acpi cpu="">on acpi0 Feb 12 00:19:24 pfsense kernel: cpu1: <acpi cpu="">on acpi0 Feb 12 00:19:24 pfsense kernel: attimer0: <at timer="">port 0x40-0x43 irq 0 on acpi0 Feb 12 00:19:24 pfsense kernel: Timecounter "i8254" frequency 1193182 Hz quality 0 Feb 12 00:19:24 pfsense kernel: Event timer "i8254" frequency 1193182 Hz quality 100 Feb 12 00:19:24 pfsense kernel: atrtc0: <at realtime="" clock="">port 0x70-0x71 irq 8 on acpi0 Feb 12 00:19:24 pfsense kernel: Event timer "RTC" frequency 32768 Hz quality 0 Feb 12 00:19:24 pfsense kernel: hpet0: <high precision="" event="" timer="">iomem 0xfed00000-0xfed003ff on acpi0 Feb 12 00:19:24 pfsense kernel: Timecounter "HPET" frequency 14318180 Hz quality 950 Feb 12 00:19:24 pfsense kernel: Event timer "HPET" frequency 14318180 Hz quality 450 Feb 12 00:19:24 pfsense kernel: Event timer "HPET1" frequency 14318180 Hz quality 440 Feb 12 00:19:24 pfsense kernel: Event timer "HPET2" frequency 14318180 Hz quality 440 Feb 12 00:19:24 pfsense kernel: Timecounter "ACPI-fast" frequency 3579545 Hz quality 900 Feb 12 00:19:24 pfsense kernel: acpi_timer0: <24-bit timer at 3.579545MHz> port 0x808-0x80b on acpi0 Feb 12 00:19:24 pfsense kernel: pcib0: <acpi host-pci="" bridge="">port 0xcf8-0xcff on acpi0 Feb 12 00:19:24 pfsense kernel: pci0: <acpi pci="" bus="">on pcib0 Feb 12 00:19:24 pfsense kernel: pcib1: <acpi pci-pci="" bridge="">irq 16 at device 1.0 on pci0 Feb 12 00:19:24 pfsense kernel: pci1: <acpi pci="" bus="">on pcib1 Feb 12 00:19:24 pfsense kernel: re0: <realtek 8111="" 8168="" b="" c="" cp="" d="" dp="" e="" f="" g="" pcie="" gigabit="" ethernet="">port 0xb800-0xb8ff mem 0xfe8ff000-0xfe8fffff,0xfddfc000-0xfddfffff irq 16 at device 0.0 on pci1 Feb 12 00:19:24 pfsense kernel: re0: Using 1 MSI-X message Feb 12 00:19:24 pfsense kernel: re0: Chip rev. 0x2c000000 Feb 12 00:19:24 pfsense kernel: re0: MAC rev. 0x00200000 Feb 12 00:19:24 pfsense kernel: miibus0: <mii bus="">on re0 Feb 12 00:19:24 pfsense kernel: rgephy0: <rtl8169s 8211="" 8110s="" 1000base-t="" media="" interface="">PHY 1 on miibus0 Feb 12 00:19:24 pfsense kernel: rgephy0: none, 10baseT, 10baseT-FDX, 10baseT-FDX-flow, 100baseTX, 100baseTX-FDX, 100baseTX-FDX-flow, 1000baseT, 1000baseT-master, 1000baseT-FDX, 1000baseT-FDX-master, 1000baseT-FDX-flow, 1000baseT-FDX-flow-master, auto, auto-flow Feb 12 00:19:24 pfsense kernel: re0: Using defaults for TSO: 65518/35/2048 Feb 12 00:19:24 pfsense kernel: re0: Ethernet address: a0:f3:c1:01:a1:fb Feb 12 00:19:24 pfsense kernel: re0: netmap queues/slots: TX 1/256, RX 1/256 Feb 12 00:19:24 pfsense kernel: vgapci0: <vga-compatible display="">port 0xac00-0xac07 mem 0xfe400000-0xfe7fffff,0xd0000000-0xdfffffff irq 16 at device 2.0 on pci0 Feb 12 00:19:24 pfsense kernel: agp0: <intel g41="" svga="" controller="">on vgapci0 Feb 12 00:19:24 pfsense kernel: agp0: aperture size is 256M, detected 32764k stolen memory Feb 12 00:19:24 pfsense kernel: vgapci0: Boot video device Feb 12 00:19:24 pfsense kernel: hdac0: <intel 82801g="" hda="" controller="">mem 0xfe3f8000-0xfe3fbfff irq 16 at device 27.0 on pci0 Feb 12 00:19:24 pfsense kernel: pcib2: <acpi pci-pci="" bridge="">irq 16 at device 28.0 on pci0 Feb 12 00:19:24 pfsense kernel: pci2: <acpi pci="" bus="">on pcib2 Feb 12 00:19:24 pfsense kernel: re1: <realtek 8111="" 8168="" b="" c="" cp="" d="" dp="" e="" f="" g="" pcie="" gigabit="" ethernet="">port 0xc800-0xc8ff mem 0xfe9ff000-0xfe9fffff,0xfdefc000-0xfdefffff irq 16 at device 0.0 on pci2 Feb 12 00:19:24 pfsense kernel: re1: Using 1 MSI-X message Feb 12 00:19:24 pfsense kernel: re1: Chip rev. 0x28000000 Feb 12 00:19:24 pfsense kernel: re1: MAC rev. 0x00100000 Feb 12 00:19:24 pfsense kernel: miibus1: <mii bus="">on re1 Feb 12 00:19:24 pfsense kernel: rgephy1: <rtl8169s 8211="" 8110s="" 1000base-t="" media="" interface="">PHY 1 on miibus1 Feb 12 00:19:24 pfsense kernel: rgephy1: none, 10baseT, 10baseT-FDX, 10baseT-FDX-flow, 100baseTX, 100baseTX-FDX, 100baseTX-FDX-flow, 1000baseT, 1000baseT-master, 1000baseT-FDX, 1000baseT-FDX-master, 1000baseT-FDX-flow, 1000baseT-FDX-flow-master, auto, auto-flow Feb 12 00:19:24 pfsense kernel: re1: Using defaults for TSO: 65518/35/2048 Feb 12 00:19:24 pfsense kernel: re1: Ethernet address: 00:0a:cd:1a:f1:71 Feb 12 00:19:24 pfsense kernel: re1: netmap queues/slots: TX 1/256, RX 1/256 Feb 12 00:19:24 pfsense kernel: pcib3: <acpi pci-pci="" bridge="">irq 17 at device 28.1 on pci0 Feb 12 00:19:24 pfsense kernel: pci3: <acpi pci="" bus="">on pcib3 Feb 12 00:19:24 pfsense kernel: re2: <realtek 10="" 810xe="" pcie="" 100basetx="">port 0xd800-0xd8ff mem 0xfdfff000-0xfdffffff,0xfdfe0000-0xfdfeffff irq 17 at device 0.0 on pci3 Feb 12 00:19:24 pfsense kernel: re2: Using 1 MSI-X message Feb 12 00:19:24 pfsense kernel: re2: Chip rev. 0x34800000 Feb 12 00:19:24 pfsense kernel: re2: MAC rev. 0x00400000 Feb 12 00:19:24 pfsense kernel: miibus2: <mii bus="">on re2 Feb 12 00:19:24 pfsense kernel: rlphy0: <rtl8201l 10="" 100="" media="" interface="">PHY 1 on miibus2 Feb 12 00:19:24 pfsense kernel: rlphy0: 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto, auto-flow Feb 12 00:19:24 pfsense kernel: re2: Using defaults for TSO: 65518/35/2048 Feb 12 00:19:24 pfsense kernel: re2: Ethernet address: 00:25:64:04:eb:3e Feb 12 00:19:24 pfsense kernel: re2: netmap queues/slots: TX 1/256, RX 1/256 Feb 12 00:19:24 pfsense kernel: uhci0: <intel 82801g="" (ich7)="" usb="" controller="" usb-a="">port 0xa880-0xa89f irq 23 at device 29.0 on pci0 Feb 12 00:19:24 pfsense kernel: usbus0 on uhci0 Feb 12 00:19:24 pfsense kernel: uhci1: <intel 82801g="" (ich7)="" usb="" controller="" usb-b="">port 0xa800-0xa81f irq 19 at device 29.1 on pci0 Feb 12 00:19:24 pfsense kernel: usbus1 on uhci1 Feb 12 00:19:24 pfsense kernel: uhci2: <intel 82801g="" (ich7)="" usb="" controller="" usb-c="">port 0xa480-0xa49f irq 18 at device 29.2 on pci0 Feb 12 00:19:24 pfsense kernel: usbus2 on uhci2 Feb 12 00:19:24 pfsense kernel: uhci3: <intel 82801g="" (ich7)="" usb="" controller="" usb-d="">port 0xa400-0xa41f irq 16 at device 29.3 on pci0 Feb 12 00:19:24 pfsense kernel: usbus3 on uhci3 Feb 12 00:19:24 pfsense kernel: ehci0: <intel 82801gb="" r="" (ich7)="" usb="" 2.0="" controller="">mem 0xfe3f7c00-0xfe3f7fff irq 23 at device 29.7 on pci0 Feb 12 00:19:24 pfsense kernel: usbus4: EHCI version 1.0 Feb 12 00:19:24 pfsense kernel: usbus4 on ehci0 Feb 12 00:19:24 pfsense kernel: pcib4: <acpi pci-pci="" bridge="">at device 30.0 on pci0 Feb 12 00:19:24 pfsense kernel: pci4: <acpi pci="" bus="">on pcib4 Feb 12 00:19:24 pfsense kernel: em0: <intel(r) 1000="" pro="" legacy="" network="" connection="" 1.1.0="">port 0xec00-0xec3f mem 0xfebe0000-0xfebfffff,0xfebc0000-0xfebdffff irq 18 at device 1.0 on pci4 Feb 12 00:19:24 pfsense kernel: em0: Ethernet address: 00:07:e9:66:02:91 Feb 12 00:19:24 pfsense kernel: em0: netmap queues/slots: TX 1/256, RX 1/256 Feb 12 00:19:24 pfsense kernel: isab0: <pci-isa bridge="">at device 31.0 on pci0 Feb 12 00:19:24 pfsense kernel: isa0: <isa bus="">on isab0 Feb 12 00:19:24 pfsense kernel: atapci0: <intel ich7="" sata300="" controller="">port 0xa080-0xa087,0xa000-0xa003,0x9c00-0x9c07,0x9880-0x9883,0x9800-0x980f irq 19 at device 31.2 on pci0 Feb 12 00:19:24 pfsense kernel: ata2: <ata channel="">at channel 0 on atapci0 Feb 12 00:19:24 pfsense kernel: ata3: <ata channel="">at channel 1 on atapci0 Feb 12 00:19:24 pfsense kernel: acpi_button0: <power button="">on acpi0 Feb 12 00:19:24 pfsense kernel: acpi_tz0: <thermal zone="">on acpi0 Feb 12 00:19:24 pfsense kernel: fdc0: <floppy drive="" controller="" (fde)="">port 0x3f0-0x3f5,0x3f7 irq 6 drq 2 on acpi0 Feb 12 00:19:24 pfsense kernel: orm0: <isa option="" rom="">at iomem 0xcc800-0xcd7ff on isa0 Feb 12 00:19:24 pfsense kernel: sc0: <system console="">at flags 0x100 on isa0 Feb 12 00:19:24 pfsense kernel: sc0: VGA <16 virtual consoles, flags=0x300> Feb 12 00:19:24 pfsense kernel: vga0: <generic isa="" vga="">at port 0x3c0-0x3df iomem 0xa0000-0xbffff on isa0 Feb 12 00:19:24 pfsense kernel: atkbdc0: <keyboard controller="" (i8042)="">at port 0x60,0x64 on isa0 Feb 12 00:19:24 pfsense kernel: atkbd0: <at keyboard="">irq 1 on atkbdc0 Feb 12 00:19:24 pfsense kernel: kbd0 at atkbd0 Feb 12 00:19:24 pfsense kernel: atkbd0: [GIANT-LOCKED] Feb 12 00:19:24 pfsense kernel: ppc0: cannot reserve I/O port range Feb 12 00:19:24 pfsense kernel: est0: <enhanced speedstep="" frequency="" control="">on cpu0 Feb 12 00:19:24 pfsense kernel: est1: <enhanced speedstep="" frequency="" control="">on cpu1 Feb 12 00:19:24 pfsense kernel: Timecounters tick every 1.000 msec Feb 12 00:19:24 pfsense kernel: hdacc0: <realtek alc662="" hda="" codec="">at cad 0 on hdac0 Feb 12 00:19:24 pfsense kernel: hdaa0: <realtek alc662="" audio="" function="" group="">at nid 1 on hdacc0 Feb 12 00:19:24 pfsense kernel: pcm0: <realtek alc662="" (analog="" 2.0+hp="" 2.0)="">at nid 20,27 and 24,25,26 on hdaa0 Feb 12 00:19:24 pfsense kernel: random: unblocking device. Feb 12 00:19:24 pfsense kernel: usbus0: 12Mbps Full Speed USB v1.0 Feb 12 00:19:24 pfsense kernel: usbus1: 12Mbps Full Speed USB v1.0 Feb 12 00:19:24 pfsense kernel: usbus2: 12Mbps Full Speed USB v1.0 Feb 12 00:19:24 pfsense kernel: usbus3: 12Mbps Full Speed USB v1.0 Feb 12 00:19:24 pfsense kernel: usbus4: 480Mbps High Speed USB v2.0 Feb 12 00:19:24 pfsense kernel: ugen0.1: <intel>at usbus0 Feb 12 00:19:24 pfsense kernel: uhub0: <intel 1="" 9="" uhci="" root="" hub,="" class="" 0,="" rev="" 1.00="" 1.00,="" addr="">on usbus0 Feb 12 00:19:24 pfsense kernel: ugen2.1: <intel>at usbus2 Feb 12 00:19:24 pfsense kernel: uhub1: <intel 1="" 9="" uhci="" root="" hub,="" class="" 0,="" rev="" 1.00="" 1.00,="" addr="">on usbus2 Feb 12 00:19:24 pfsense kernel: ugen1.1: <intel>at usbus1 Feb 12 00:19:24 pfsense kernel: uhub2: <intel 1="" 9="" uhci="" root="" hub,="" class="" 0,="" rev="" 1.00="" 1.00,="" addr="">on usbus1 Feb 12 00:19:24 pfsense kernel: ugen4.1: <intel>at usbus4 Feb 12 00:19:24 pfsense kernel: uhub3: <intel 1="" 9="" ehci="" root="" hub,="" class="" 0,="" rev="" 2.00="" 1.00,="" addr="">on usbus4 Feb 12 00:19:24 pfsense kernel: ugen3.1: <intel>at usbus3 Feb 12 00:19:24 pfsense kernel: uhub4: <intel 1="" 9="" uhci="" root="" hub,="" class="" 0,="" rev="" 1.00="" 1.00,="" addr="">on usbus3 Feb 12 00:19:24 pfsense kernel: uhub0: 2 ports with 2 removable, self powered Feb 12 00:19:24 pfsense kernel: uhub1: 2 ports with 2 removable, self powered Feb 12 00:19:24 pfsense kernel: uhub2: 2 ports with 2 removable, self powered Feb 12 00:19:24 pfsense kernel: uhub4: 2 ports with 2 removable, self powered Feb 12 00:19:24 pfsense kernel: uhub3: 8 ports with 8 removable, self powered Feb 12 00:19:24 pfsense kernel: ugen4.2: <huawei technologies="">at usbus4 Feb 12 00:19:24 pfsense kernel: u3g0: <huawei 0="" 2="" technologies="" huawei="" mobile,="" class="" 0,="" rev="" 2.00="" 0.00,="" addr="">on usbus4 Feb 12 00:19:24 pfsense kernel: u3g0: Found 5 ports. Feb 12 00:19:24 pfsense kernel: umass0: <huawei 0="" 2="" technologies="" huawei="" mobile,="" class="" 0,="" rev="" 2.00="" 0.00,="" addr="">on usbus4 Feb 12 00:19:24 pfsense kernel: umass1: <huawei 0="" 2="" technologies="" huawei="" mobile,="" class="" 0,="" rev="" 2.00="" 0.00,="" addr="">on usbus4 Feb 12 00:19:24 pfsense kernel: ugen2.2: <logitech>at usbus2 Feb 12 00:19:24 pfsense kernel: ukbd0: <logitech 0="" 2="" usb="" receiver,="" class="" 0,="" rev="" 2.00="" 29.00,="" addr="">on usbus2 Feb 12 00:19:24 pfsense kernel: kbd2 at ukbd0 Feb 12 00:19:24 pfsense kernel: ada0 at ata2 bus 0 scbus0 target 0 lun 0 Feb 12 00:19:24 pfsense kernel: ada0: <intel ssdsc2cw120a3="" 400i="">ACS-2 ATA SATA 2.x device Feb 12 00:19:24 pfsense kernel: cd1 at umass-sim0 bus 0 scbus2 target 0 lun 0 Feb 12 00:19:24 pfsense kernel: cd1: <huawei mass="" storage="" 2.31="">Removable CD-ROM SCSI device Feb 12 00:19:24 pfsense kernel: cd1: 40.000MB/s transfers Feb 12 00:19:24 pfsense kernel: cd1: 179MB (91840 2048 byte sectors) Feb 12 00:19:24 pfsense kernel: cd1: quirks=0x10<10_BYTE_ONLY> Feb 12 00:19:24 pfsense kernel: ada0: Serial Number CVCV229502MD120BGN Feb 12 00:19:24 pfsense kernel: ada0: 150.000MB/s transfers (SATA, UDMA5, PIO 8192bytes) Feb 12 00:19:24 pfsense kernel: ada0: 114473MB (234441648 512 byte sectors) Feb 12 00:19:24 pfsense kernel: ada0: Previously was known as ad4 Feb 12 00:19:24 pfsense kernel: cd0 at ata2 bus 0 scbus0 target 1 lun 0 Feb 12 00:19:24 pfsense kernel: cd0: <plds dvd+-rw="" dh-16aas="" jd12="">Removable CD-ROM SCSI device Feb 12 00:19:24 pfsense kernel: cd0: Serial Number CN0H344R550819AB43HR Feb 12 00:19:24 pfsense kernel: cd0: 150.000MB/s transfers (SATA, UDMA5, ATAPI 12bytes, PIO 8192bytes) Feb 12 00:19:24 pfsense kernel: cd0: Attempt to query device size failed: NOT READY, Medium not present - tray closed Feb 12 00:19:24 pfsense kernel: da0 at umass-sim1 bus 1 scbus3 target 0 lun 0 Feb 12 00:19:24 pfsense kernel: da0: <huawei sd="" storage="" 2.31="">Removable Direct Access SCSI-2 device Feb 12 00:19:24 pfsense kernel: da0: 40.000MB/s transfers Feb 12 00:19:24 pfsense kernel: da0: Attempt to query device size failed: NOT READY, Medium not present Feb 12 00:19:24 pfsense kernel: da0: quirks=0x2 <no_6_byte>Feb 12 00:19:24 pfsense kernel: SMP: AP CPU #1 Launched! Feb 12 00:19:24 pfsense kernel: Trying to mount root from ufs:/dev/ufsid/5898f7872972c6e7 [rw]... Feb 12 00:19:24 pfsense php-cgi: rc.bootup: [DEBUG] Configuring interfaces of type wan Feb 12 00:19:24 pfsense php-cgi: rc.bootup: [DEBUG] Real interface is em0 Feb 12 00:19:24 pfsense php-cgi: rc.bootup: [DEBUG] Real HW interface is em0 Feb 12 00:19:24 pfsense php-cgi: rc.bootup: [DEBUG] Bringing up interface, because wancfg[if] exists Feb 12 00:19:24 pfsense php-cgi: rc.bootup: [DEBUG] Configuring connection with wancfg[ipaddr] = 'dhcp'. If this equals ppp then interface_ppps_configure will be called Feb 12 00:19:25 pfsense sshd[6169]: Server listening on :: port 22. Feb 12 00:19:25 pfsense sshd[6169]: Server listening on 0.0.0.0 port 22. Feb 12 00:19:25 pfsense sshlockout[6267]: sshlockout/webConfigurator v3.0 starting up Feb 12 00:19:28 pfsense check_reload_status: Linkup starting em0 Feb 12 00:19:28 pfsense kernel: Feb 12 00:19:28 pfsense kernel: em0: link state changed to UP Feb 12 00:19:28 pfsense check_reload_status: rc.newwanip starting em0 Feb 12 00:19:28 pfsense php-cgi: rc.bootup: Accept router advertisements on interface em0 Feb 12 00:19:28 pfsense php-cgi: rc.bootup: [DEBUG] Configuring interfaces of type lan Feb 12 00:19:28 pfsense php-cgi: rc.bootup: [DEBUG] Real interface is re0 Feb 12 00:19:28 pfsense php-cgi: rc.bootup: [DEBUG] Real HW interface is re0 Feb 12 00:19:28 pfsense php-cgi: rc.bootup: [DEBUG] Bringing up interface, because wancfg[if] exists Feb 12 00:19:28 pfsense php-cgi: rc.bootup: [DEBUG] Configuring connection with wancfg[ipaddr] = '192.168.1.13'. If this equals ppp then interface_ppps_configure will be called Feb 12 00:19:28 pfsense kernel: Feb 12 00:19:28 pfsense kernel: re0: link state changed to DOWN Feb 12 00:19:28 pfsense check_reload_status: Linkup starting re0 Feb 12 00:19:28 pfsense php-cgi: rc.bootup: [DEBUG] Configuring interfaces of type opt1 Feb 12 00:19:28 pfsense php-cgi: rc.bootup: [DEBUG] Real interface is ppp0 Feb 12 00:19:28 pfsense php-cgi: rc.bootup: [DEBUG] Real HW interface is ppp0 Feb 12 00:19:28 pfsense php-cgi: rc.bootup: [DEBUG] Configuring connection with wancfg[ipaddr] = ''. If this equals ppp then interface_ppps_configure will be called Feb 11 23:20:48 pfsense php-cgi: rc.bootup: The command '/sbin/ifconfig 'ppp0' -staticarp ' returned exit code '1', the output was 'ifconfig: interface ppp0 does not exist' Feb 11 23:20:48 pfsense php-cgi: rc.bootup: The command '/usr/sbin/arp -d -i 'ppp0' -a > /dev/null 2>&1 ' returned exit code '1', the output was ''</no_6_byte></huawei></plds></huawei></intel></logitech></logitech></huawei></huawei></huawei></huawei></intel></intel></intel></intel></intel></intel></intel></intel></intel></intel></realtek></realtek></realtek></enhanced></enhanced></at></keyboard></generic></system></isa></floppy></thermal></power></ata></ata></intel></isa></pci-isa></intel(r)></acpi></acpi></intel></intel></intel></intel></intel></rtl8201l></mii></realtek></acpi></acpi></rtl8169s></mii></realtek></acpi></acpi></intel></intel></vga-compatible></rtl8169s></mii></realtek></acpi></acpi></acpi></acpi></high></at></at></acpi></acpi></dell></software></version></software,></lahf></syscall,nx,lm></sse3,dtes64,mon,ds_cpl,vmx,est,tm2,ssse3,cx16,xtpr,pdcm,xsave,osxsave></fpu,vme,de,pse,tsc,msr,pae,mce,cx8,apic,sep,mtrr,pge,mca,cmov,pat,pse36,clflush,dts,acpi,mmx,fxsr,sse,sse2,ss,htt,tm,pbe>
It looks like $wancfg['ipaddr'] is blank, not 'ppp', and this prevents ppp initialization from happening. Also, not sure if it matters, but ppp0 is being
checked on interfaces of type 'lan', not 'wan'.As a test, I edited the script and forced a call to interface_ppps_configure when it is configuring the ppp0 interface. It connected on boot without issue:
Feb 12 00:19:28 pfsense php-cgi: rc.bootup: [DEBUG] Configuring interfaces of type opt1 Feb 12 00:19:28 pfsense php-cgi: rc.bootup: [DEBUG] Real interface is ppp0 Feb 12 00:19:28 pfsense php-cgi: rc.bootup: [DEBUG] Real HW interface is ppp0 Feb 12 00:19:28 pfsense php-cgi: rc.bootup: [DEBUG] Configuring connection with wancfg[ipaddr] = ''. If this equals ppp then interface_ppps_configure will be called Feb 12 00:19:28 pfsense php-cgi: rc.bootup: Setting up PPP interfaces Feb 12 00:19:28 pfsense ppp: Multi-link PPP daemon for FreeBSD Feb 12 00:19:28 pfsense ppp: Feb 12 00:19:28 pfsense ppp: process 14006 started, version 5.8 (root@pfSense_v2_3_2_amd64-pfSense_v2_3_2-job-04 16:03 19-Jul-2016) Feb 12 00:19:28 pfsense ppp: web: web is not running Feb 12 00:19:28 pfsense ppp: [opt1] Bundle: Interface ng0 created Feb 12 00:19:28 pfsense ppp: [opt1_link0] Link: OPEN event Feb 12 00:19:28 pfsense kernel: Feb 12 00:19:28 pfsense kernel: ng0: changing name to 'ppp0' Feb 12 00:19:28 pfsense ppp: [opt1_link0] LCP: Open event Feb 12 00:19:28 pfsense rtsold[11956]: <rtsock_input_ifannounce>interface ng0 removed Feb 12 00:19:28 pfsense ppp: [opt1_link0] LCP: state change Initial --> Starting Feb 12 00:19:28 pfsense ppp: [opt1_link0] LCP: LayerStart Feb 12 00:19:28 pfsense ppp: [opt1_link0] CHAT: +CGDCONT=1,"IP","fast.t-mobile.com" Feb 12 00:19:28 pfsense ppp: [opt1_link0] CHAT: Detected Hayes compatible modem. Feb 12 00:19:28 pfsense ppp: [opt1_link0] CHAT: Dialing server at *99#... Feb 12 00:19:28 pfsense ppp: [opt1_link0] CHAT: ATDT*99# Feb 12 00:19:28 pfsense ppp: [opt1_link0] CHAT: Connected at 100000000. Feb 12 00:19:28 pfsense ppp: [opt1_link0] MODEM: chat script succeeded Feb 12 00:19:28 pfsense ppp: [opt1_link0] Link: UP event Feb 12 00:19:28 pfsense ppp: [opt1_link0] LCP: Up event Feb 12 00:19:28 pfsense ppp: [opt1_link0] LCP: state change Starting --> Req-Sent Feb 12 00:19:28 pfsense ppp: [opt1_link0] LCP: SendConfigReq #1 Feb 12 00:19:28 pfsense ppp: [opt1_link0] ACFCOMP Feb 12 00:19:28 pfsense ppp: [opt1_link0] PROTOCOMP Feb 12 00:19:28 pfsense ppp: [opt1_link0] ACCMAP 0x000a0000 Feb 12 00:19:28 pfsense ppp: [opt1_link0] MRU 1500 Feb 12 00:19:28 pfsense ppp: [opt1_link0] MAGICNUM 0xd0fffffc Feb 12 00:19:28 pfsense ppp: [opt1_link0] LCP: rec'd Configure Request #6 (Req-Sent) Feb 12 00:19:28 pfsense ppp: [opt1_link0] MRU 1428 Feb 12 00:19:28 pfsense ppp: [opt1_link0] ACCMAP 0x00000000 Feb 12 00:19:28 pfsense ppp: [opt1_link0] AUTHPROTO CHAP MD5 Feb 12 00:19:28 pfsense ppp: [opt1_link0] MAGICNUM 0xa35fd7b9 Feb 12 00:19:28 pfsense ppp: [opt1_link0] PROTOCOMP Feb 12 00:19:28 pfsense ppp: [opt1_link0] ACFCOMP Feb 12 00:19:28 pfsense ppp: [opt1_link0] LCP: SendConfigAck #6 Feb 12 00:19:28 pfsense ppp: [opt1_link0] MRU 1428 Feb 12 00:19:28 pfsense ppp: [opt1_link0] ACCMAP 0x00000000 Feb 12 00:19:28 pfsense ppp: [opt1_link0] AUTHPROTO CHAP MD5 Feb 12 00:19:28 pfsense ppp: [opt1_link0] MAGICNUM 0xa35fd7b9 Feb 12 00:19:28 pfsense ppp: [opt1_link0] PROTOCOMP Feb 12 00:19:28 pfsense ppp: [opt1_link0] ACFCOMP Feb 12 00:19:28 pfsense ppp: [opt1_link0] LCP: state change Req-Sent --> Ack-Sent Feb 12 00:19:28 pfsense ppp: [opt1_link0] LCP: rec'd Configure Ack #1 (Ack-Sent) Feb 12 00:19:28 pfsense ppp: [opt1_link0] ACFCOMP Feb 12 00:19:28 pfsense ppp: [opt1_link0] PROTOCOMP Feb 12 00:19:28 pfsense ppp: [opt1_link0] ACCMAP 0x000a0000 Feb 12 00:19:28 pfsense ppp: [opt1_link0] MRU 1500 Feb 12 00:19:28 pfsense ppp: [opt1_link0] MAGICNUM 0xd0fffffc Feb 12 00:19:28 pfsense ppp: [opt1_link0] LCP: state change Ack-Sent --> Opened Feb 12 00:19:28 pfsense ppp: [opt1_link0] LCP: auth: peer wants CHAP, I want nothing Feb 12 00:19:28 pfsense ppp: [opt1_link0] LCP: LayerUp Feb 12 00:19:28 pfsense ppp: [opt1_link0] LCP: rec'd Discard Request #7 (Opened) Feb 12 00:19:28 pfsense ppp: [opt1_link0] CHAP: rec'd CHALLENGE #1 len: 35 Feb 12 00:19:28 pfsense ppp: [opt1_link0] Name: "UMTS_CHAP_SRVR" Feb 12 00:19:28 pfsense ppp: [opt1_link0] CHAP: Using authname "user" Feb 12 00:19:28 pfsense ppp: [opt1_link0] CHAP: sending RESPONSE #1 len: 25 Feb 12 00:19:28 pfsense ppp: [opt1_link0] CHAP: rec'd SUCCESS #1 len: 4 Feb 12 00:19:28 pfsense ppp: [opt1_link0] LCP: authorization successful Feb 12 00:19:28 pfsense ppp: [opt1_link0] Link: Matched action 'bundle "opt1" ""' Feb 12 00:19:28 pfsense ppp: [opt1_link0] Link: Join bundle "opt1" Feb 12 00:19:28 pfsense ppp: [opt1] Bundle: Status update: up 1 link, total bandwidth 100000000 bps Feb 12 00:19:28 pfsense ppp: [opt1] IPCP: Open event Feb 12 00:19:28 pfsense ppp: [opt1] IPCP: state change Initial --> Starting Feb 12 00:19:28 pfsense ppp: [opt1] IPCP: LayerStart Feb 12 00:19:28 pfsense ppp: [opt1] IPV6CP: Open event Feb 12 00:19:28 pfsense ppp: [opt1] IPV6CP: state change Initial --> Starting Feb 12 00:19:28 pfsense ppp: [opt1] IPV6CP: LayerStart Feb 12 00:19:28 pfsense ppp: [opt1] IPCP: Up event Feb 12 00:19:28 pfsense ppp: [opt1] IPCP: state change Starting --> Req-Sent Feb 12 00:19:28 pfsense ppp: [opt1] IPCP: SendConfigReq #1 Feb 12 00:19:28 pfsense ppp: [opt1] IPADDR 0.0.0.0 Feb 12 00:19:28 pfsense ppp: [opt1] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Feb 12 00:19:28 pfsense ppp: [opt1] PRIDNS 0.0.0.0 Feb 12 00:19:28 pfsense ppp: [opt1] SECDNS 0.0.0.0 Feb 12 00:19:28 pfsense ppp: [opt1] IPV6CP: Up event Feb 12 00:19:28 pfsense ppp: [opt1] IPV6CP: state change Starting --> Req-Sent Feb 12 00:19:28 pfsense ppp: [opt1] IPV6CP: SendConfigReq #1 Feb 12 00:19:29 pfsense ppp: [opt1] IPCP: rec'd Configure Request #3 (Req-Sent) Feb 12 00:19:29 pfsense ppp: [opt1] IPCP: SendConfigAck #3 Feb 12 00:19:29 pfsense ppp: [opt1] IPCP: state change Req-Sent --> Ack-Sent Feb 12 00:19:29 pfsense ppp: [opt1] IPCP: rec'd Configure Reject #1 (Ack-Sent) Feb 12 00:19:29 pfsense ppp: [opt1] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Feb 12 00:19:29 pfsense ppp: [opt1] IPCP: SendConfigReq #2 Feb 12 00:19:29 pfsense ppp: [opt1] IPADDR 0.0.0.0 Feb 12 00:19:29 pfsense ppp: [opt1] PRIDNS 0.0.0.0 Feb 12 00:19:29 pfsense ppp: [opt1] SECDNS 0.0.0.0 Feb 12 00:19:29 pfsense ppp: [opt1] IPCP: rec'd Configure Nak #2 (Ack-Sent) Feb 12 00:19:29 pfsense ppp: [opt1] IPADDR *.*.*.* Feb 12 00:19:29 pfsense ppp: [opt1] *.*.*.* is OK Feb 12 00:19:29 pfsense ppp: [opt1] PRIDNS *.*.*.* Feb 12 00:19:29 pfsense ppp: [opt1] SECDNS *.*.*.* Feb 12 00:19:29 pfsense ppp: [opt1] IPCP: SendConfigReq #3 Feb 12 00:19:29 pfsense ppp: [opt1] IPADDR *.*.*.* Feb 12 00:19:29 pfsense ppp: [opt1] PRIDNS *.*.*.* Feb 12 00:19:29 pfsense ppp: [opt1] SECDNS *.*.*.* Feb 12 00:19:29 pfsense ppp: [opt1] IPCP: rec'd Configure Ack #3 (Ack-Sent) Feb 12 00:19:29 pfsense ppp: [opt1] IPADDR *.*.*.* Feb 12 00:19:29 pfsense ppp: [opt1] PRIDNS *.*.*.* Feb 12 00:19:29 pfsense ppp: [opt1] SECDNS *.*.*.* Feb 12 00:19:29 pfsense ppp: [opt1] IPCP: state change Ack-Sent --> Opened Feb 12 00:19:29 pfsense ppp: [opt1] IPCP: LayerUp Feb 12 00:19:29 pfsense ppp: [opt1] *.*.*.* -> *.*.*.* Feb 12 00:19:29 pfsense check_reload_status: Rewriting resolv.conf Feb 12 00:19:29 pfsense php-fpm[278]: /rc.newwanip: rc.newwanip: Info: starting on em0. Feb 12 00:19:29 pfsense php-fpm[278]: /rc.newwanip: rc.newwanip: on (IP address: 192.168.1.134) (interface: WAN[wan]) (real interface: em0). Feb 12 00:19:29 pfsense php-fpm[278]: /rc.newwanip: Removing static route for monitor 8.8.4.4 and adding a new route through 10.64.64.0 Feb 12 00:19:29 pfsense php-fpm[278]: /rc.newwanip: Removing static route for monitor 8.8.8.8 and adding a new route through 192.168.1.2 Feb 12 00:19:30 pfsense check_reload_status: rc.newwanip starting ppp0 Feb 12 00:19:30 pfsense ppp: [opt1] IFACE: Up event Feb 12 00:19:30 pfsense ppp: [opt1] IFACE: Rename interface ng0 to ppp0 Feb 12 00:19:30 pfsense ppp: [opt1] IPV6CP: SendConfigReq #2 Feb 12 00:19:31 pfsense php-fpm[278]: /rc.newwanip: rc.newwanip: Info: starting on ppp0. Feb 12 00:19:31 pfsense php-fpm[278]: /rc.newwanip: rc.newwanip: on (IP address: *.*.*.*) (interface: WAN_GSM[opt1]) (real interface: ppp0). Feb 12 00:19:31 pfsense php-fpm[278]: /rc.newwanip: Removing static route for monitor 8.8.4.4 and adding a new route through 10.64.64.0 Feb 12 00:19:31 pfsense php-fpm[278]: /rc.newwanip: Removing static route for monitor 8.8.8.8 and adding a new route through 192.168.1.2 Feb 12 00:19:31 pfsense check_reload_status: Linkup starting re0 Feb 12 00:19:31 pfsense kernel: re0: link state changed to UP Feb 12 00:19:32 pfsense ppp: [opt1] IPV6CP: SendConfigReq #3 Feb 12 00:19:34 pfsense ppp: [opt1] IPV6CP: SendConfigReq #4 Feb 12 00:19:36 pfsense ppp: [opt1] IPV6CP: SendConfigReq #5 Feb 12 00:19:38 pfsense php-cgi: rc.bootup: Starting 3gstats.php on device 'cuaU0.4' for interface 'opt1' Feb 12 00:19:38 pfsense php-cgi: rc.bootup: Resyncing OpenVPN instances. Feb 12 00:19:38 pfsense kernel: done. Feb 12 00:19:38 pfsense kernel: pflog0: promiscuous mode enabled Feb 12 00:19:38 pfsense xinetd[24646]: xinetd Version 2.3.15 started with libwrap loadavg options compiled in. Feb 12 00:19:38 pfsense kernel: . Feb 12 00:19:38 pfsense xinetd[24646]: Started working: 1 available service Feb 12 00:19:38 pfsense php-cgi: rc.bootup: Removing static route for monitor 8.8.4.4 and adding a new route through 10.64.64.0 Feb 12 00:19:38 pfsense kernel: ...done. Feb 12 00:19:38 pfsense php-cgi: rc.bootup: Removing static route for monitor 8.8.8.8 and adding a new route through 192.168.1.2 Feb 12 00:19:38 pfsense kernel: done. Feb 12 00:19:38 pfsense ppp: [opt1] IPV6CP: SendConfigReq #6 Feb 12 00:19:38 pfsense kernel: done. Feb 12 00:19:39 pfsense php-cgi: rc.bootup: ROUTING: setting default route to 192.168.1.2 Feb 12 00:19:39 pfsense kernel: done. Feb 12 00:19:40 pfsense kernel: done. Feb 12 00:19:40 pfsense php-cgi: rc.bootup: NTPD is starting up. Feb 12 00:19:40 pfsense kernel: done. Feb 12 00:19:40 pfsense check_reload_status: Updating all dyndns Feb 12 00:19:40 pfsense xinetd[24646]: Starting reconfiguration Feb 12 00:19:40 pfsense kernel: . Feb 12 00:19:40 pfsense xinetd[24646]: Swapping defaults Feb 12 00:19:40 pfsense kernel: . Feb 12 00:19:40 pfsense xinetd[24646]: readjusting service 6969-udp Feb 12 00:19:40 pfsense xinetd[24646]: Reconfigured: new=0 old=1 dropped=0 (services) Feb 12 00:19:40 pfsense kernel: ...done. Feb 12 00:19:40 pfsense kernel: done Feb 12 00:19:40 pfsense ppp: [opt1] IPV6CP: SendConfigReq #7 Feb 12 00:19:43 pfsense php-cgi: rc.bootup: Creating rrd update script Feb 12 00:19:43 pfsense root: /etc/rc.d/ip6addrctl: DEBUG: checkyesno: ip6addrctl_enable is set to YES. Feb 12 00:19:43 pfsense kernel: done. Feb 12 00:19:43 pfsense root: /etc/rc.d/ip6addrctl: DEBUG: run_rc_command: doit: ip6addrctl_prefer_ipv6 Feb 12 00:19:43 pfsense ppp: [opt1] IPV6CP: SendConfigReq #8 Feb 12 00:19:43 pfsense root: /etc/rc.d/hostid: DEBUG: checkyesno: hostid_enable is set to YES. Feb 12 00:19:43 pfsense root: /etc/rc.d/hostid: DEBUG: run_rc_command: doit: hostid_start Feb 12 00:19:43 pfsense syslogd: exiting on signal 15 Feb 12 00:19:44 pfsense syslogd: kernel boot file is /boot/kernel/kernel Feb 12 00:19:44 pfsense php-fpm[278]: /rc.start_packages: Restarting/Starting all packages. Feb 12 00:19:44 pfsense kernel: done. Feb 12 00:19:45 pfsense ppp: [opt1] IPV6CP: SendConfigReq #9 Feb 12 00:19:45 pfsense login: login on ttyv0 as root Feb 12 00:19:45 pfsense sshlockout[16078]: sshlockout/webConfigurator v3.0 starting up Feb 12 00:19:47 pfsense ppp: [opt1] IPV6CP: SendConfigReq #10 Feb 12 00:19:49 pfsense ppp: [opt1] IPV6CP: parameter negotiation failed Feb 12 00:19:49 pfsense ppp: [opt1] IPV6CP: state change Req-Sent --> Stopped Feb 12 00:19:49 pfsense ppp: [opt1] IPV6CP: LayerFinish</rtsock_input_ifannounce>
Here is the config.xml definition for this interface
<opt1><if>ppp0</if> <enable><spoofmac></spoofmac></enable></opt1>
Any thoughts?
-
I installed a shellcmd
php -r 'require_once("shaper.inc"); require_once("filter.inc"); interface_ppps_configure('opt2');'
to fix this issue.
Replace opt2 with the optx you are using.