Strange dashboard/php-fpm/rc.linkup/(UE) usb ethernet interface/problem



  • I have a strange problem with a USB ethernet interface that is fine until I open the pfSense dashboard page.

    While I have the dashboard open, there will be many DEVD interface detach/attach events that begin happening after about a minute and they will continue until I go to another page or close the page.

    The syslog errors are from the php-fpm process:

    
    Jan 30 14:53:37 pfs check_reload_status: Syncing firewall
    Jan 30 14:53:40 pfs check_reload_status: Reloading filter
    Jan 30 14:53:41 pfs xinetd[33689]: Starting reconfiguration
    Jan 30 14:53:41 pfs xinetd[33689]: Swapping defaults
    Jan 30 14:53:41 pfs xinetd[33689]: readjusting service 6969-udp
    Jan 30 14:53:41 pfs xinetd[33689]: Reconfigured: new=0 old=1 dropped=0 (services)
    Jan 30 15:34:08 pfs check_reload_status: Linkup starting ue0
    Jan 30 15:34:08 pfs kernel: [82757] ue0: link state changed to DOWN
    Jan 30 15:34:08 pfs kernel: [82757] ue0: link state changed to UP
    Jan 30 15:34:09 pfs php-fpm[62307]: /rc.linkup: DEVD Ethernet detached event for opt1
    Jan 30 15:34:09 pfs check_reload_status: Linkup starting ue0
    Jan 30 15:34:10 pfs php-fpm[62307]: /rc.linkup: DEVD Ethernet attached event for opt1
    Jan 30 15:34:10 pfs php-fpm[62307]: /rc.linkup: HOTPLUG: Configuring interface opt1
    Jan 30 15:34:10 pfs check_reload_status: Restarting ipsec tunnels
    Jan 30 15:34:10 pfs php-fpm[72761]: /rc.newwanipv6: rc.newwanipv6: Info: starting on em1.
    Jan 30 15:34:10 pfs php-fpm[72761]: /rc.newwanipv6: rc.newwanipv6: Failed to update WAN[wan] IPv6, restarting...
    Jan 30 15:34:11 pfs php-fpm[82166]: /rc.newwanipv6: rc.newwanipv6: Info: starting on em1.
    Jan 30 15:34:11 pfs php-fpm[82166]: /rc.newwanipv6: rc.newwanipv6: Failed to update WAN[wan] IPv6, restarting...
    Jan 30 15:34:11 pfs kernel: [82761] ue0: link state changed to DOWN
    Jan 30 15:34:11 pfs check_reload_status: Linkup starting ue0
    Jan 30 15:34:11 pfs kernel: [82761] ue0: link state changed to UP
    Jan 30 15:34:11 pfs check_reload_status: Linkup starting ue0
    Jan 30 15:34:11 pfs php-fpm[82166]: /rc.newwanipv6: rc.newwanipv6: Info: starting on em1.
    Jan 30 15:34:11 pfs php-fpm[82166]: /rc.newwanipv6: rc.newwanipv6: on (IP address: 2001:558:6017:a8:35e5:7886:f1a5:4ce0) (interface: wan) (real interface: em1).
    Jan 30 15:34:13 pfs php-fpm[82166]: /rc.newwanipv6: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1454186053] unbound[97807:0] error: bind: address already in use [1454186053] unbound[97807:0] fatal error: could not open ports'
    Jan 30 15:34:13 pfs php-fpm[62307]: /rc.linkup: The command '/usr/local/sbin/dhcpd -user dhcpd -group _dhcp -chroot /var/dhcpd -cf /etc/dhcpd.conf -pf /var/run/dhcpd.pid em0 ue0' returned exit code '1', the output was 'Internet Systems Consortium DHCP Server 4.2.8 Copyright 2004-2015 Internet Systems Consortium. All rights reserved. For info, please visit https://www.isc.org/software/dhcp/ Wrote 0 deleted host decls to leases file. Wrote 0 new dynamic host decls to leases file. Wrote 1 leases to leases file. Listening on BPF/ue0/a0:ce:c8:01:c6:ca/172.22.23.0/24 Sending on   BPF/ue0/a0:ce:c8:01:c6:ca/172.22.23.0/24 Listening on BPF/em0/00:90:fb:38:84:96/172.22.22.0/24 Sending on   BPF/em0/00:90:fb:38:84:96/172.22.22.0/24 Can't bind to dhcp address: Address already in use Please make sure there is no other dhcp server running and that there's no entry for dhcp or bootp in /etc/inetd.conf.   Also make sure you are not running HP JetAdmin software, which includes a bootp server.  If you did not get this software
    Jan 30 15:34:14 pfs php-fpm[82166]: /rc.newwanipv6: The command '/usr/local/sbin/dhcpd -user dhcpd -group _dhcp -chroot /var/dhcpd -cf /etc/dhcpd.conf -pf /var/run/dhcpd.pid em0 ue0' returned exit code '1', the output was 'Internet Systems Consortium DHCP Server 4.2.8 Copyright 2004-2015 Internet Systems Consortium. All rights reserved. For info, please visit https://www.isc.org/software/dhcp/ Wrote 0 deleted host decls to leases file. Wrote 0 new dynamic host decls to leases file. Wrote 1 leases to leases file. Listening on BPF/ue0/a0:ce:c8:01:c6:ca/172.22.23.0/24 Sending on   BPF/ue0/a0:ce:c8:01:c6:ca/172.22.23.0/24 Listening on BPF/em0/00:90:fb:38:84:96/172.22.22.0/24 Sending on   BPF/em0/00:90:fb:38:84:96/172.22.22.0/24 Can't bind to dhcp address: Address already in use Please make sure there is no other dhcp server running and that there's no entry for dhcp or bootp in /etc/inetd.conf.   Also make sure you are not running HP JetAdmin software, which includes a bootp server.  If you did not get this softw
    Jan 30 15:34:14 pfs check_reload_status: updating dyndns opt1
    Jan 30 15:34:14 pfs php-fpm[88850]: /rc.linkup: DEVD Ethernet detached event for opt1
    Jan 30 15:34:14 pfs php-fpm[72761]: /rc.linkup: DEVD Ethernet attached event for opt1
    Jan 30 15:34:14 pfs php-fpm[72761]: /rc.linkup: HOTPLUG: Configuring interface opt1
    Jan 30 15:34:14 pfs check_reload_status: Restarting ipsec tunnels
    
    

    I started usbdump and then navigated to the dashboard and the two ERR=TIMEOUT errors below are the only errors I ever see and they only ever happen when I am on the dashboard page.  If I am not on the dashboard page there are never any errors:

    
    15:34:06.181180 usbus0.4 SUBM-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=8,IVAL=0
    15:34:06.181420 usbus0.4 DONE-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=4,IVAL=0,ERR=0
    15:34:06.181431 usbus0.4 SUBM-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=8,IVAL=0
    15:34:06.181795 usbus0.4 DONE-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=4,IVAL=0,ERR=0
    15:34:06.181808 usbus0.4 SUBM-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=8,IVAL=0
    15:34:06.182045 usbus0.4 DONE-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=4,IVAL=0,ERR=0
    15:34:06.182056 usbus0.4 SUBM-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=8,IVAL=0
    15:34:06.182294 usbus0.4 DONE-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=4,IVAL=0,ERR=0
    15:34:07.179848 usbus0.4 SUBM-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=8,IVAL=0
    15:34:07.180097 usbus0.4 DONE-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=4,IVAL=0,ERR=0
    15:34:07.180115 usbus0.4 SUBM-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=8,IVAL=0
    15:34:08.174814 usbus0.4 DONE-CTRL-EP=00000080,SPD=HIGH,NFR=0,SLEN=0,IVAL=0,ERR=TIMEOUT
    15:34:08.237819 usbus0.4 SUBM-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=8,IVAL=0
    15:34:08.238143 usbus0.4 DONE-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=4,IVAL=0,ERR=0
    15:34:08.238162 usbus0.4 SUBM-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=8,IVAL=0
    15:34:08.238389 usbus0.4 DONE-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=4,IVAL=0,ERR=0
    15:34:08.238401 usbus0.4 SUBM-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=8,IVAL=0
    15:34:08.238639 usbus0.4 DONE-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=4,IVAL=0,ERR=0
    15:34:08.238650 usbus0.4 SUBM-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=8,IVAL=0
    15:34:08.238890 usbus0.4 DONE-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=4,IVAL=0,ERR=0
    15:34:08.238901 usbus0.4 SUBM-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=8,IVAL=0
    15:34:08.239139 usbus0.4 DONE-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=4,IVAL=0,ERR=0
    15:34:08.239150 usbus0.4 SUBM-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=8,IVAL=0
    15:34:08.239389 usbus0.4 DONE-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=4,IVAL=0,ERR=0
    15:34:08.239412 usbus0.4 SUBM-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=8,IVAL=0
    15:34:08.239770 usbus0.4 DONE-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=4,IVAL=0,ERR=0
    15:34:08.239791 usbus0.4 SUBM-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=8,IVAL=0
    15:34:08.240015 usbus0.4 DONE-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=4,IVAL=0,ERR=0
    15:34:08.240032 usbus0.4 SUBM-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=8,IVAL=0
    15:34:08.240265 usbus0.4 DONE-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=4,IVAL=0,ERR=0
    15:34:08.240280 usbus0.4 SUBM-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=8,IVAL=0
    15:34:08.240514 usbus0.4 DONE-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=4,IVAL=0,ERR=0
    15:34:08.240529 usbus0.4 SUBM-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=8,IVAL=0
    15:34:08.240763 usbus0.4 DONE-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=4,IVAL=0,ERR=0
    15:34:08.240778 usbus0.4 SUBM-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=8,IVAL=0
    15:34:08.241138 usbus0.4 DONE-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=4,IVAL=0,ERR=0
    15:34:08.241154 usbus0.4 SUBM-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=8,IVAL=0
    15:34:08.241388 usbus0.4 DONE-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=4,IVAL=0,ERR=0
    15:34:08.241402 usbus0.4 SUBM-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=8,IVAL=0
    15:34:08.241638 usbus0.4 DONE-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=4,IVAL=0,ERR=0
    15:34:08.241656 usbus0.4 SUBM-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=8,IVAL=0
    15:34:08.241891 usbus0.4 DONE-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=4,IVAL=0,ERR=0
    15:34:08.241907 usbus0.4 SUBM-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=8,IVAL=0
    15:34:08.242138 usbus0.4 DONE-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=4,IVAL=0,ERR=0
    15:34:08.242149 usbus0.4 SUBM-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=8,IVAL=0
    15:34:08.242512 usbus0.4 DONE-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=4,IVAL=0,ERR=0
    15:34:08.242522 usbus0.4 SUBM-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=8,IVAL=0
    15:34:08.242762 usbus0.4 DONE-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=4,IVAL=0,ERR=0
    15:34:08.242772 usbus0.4 SUBM-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=8,IVAL=0
    15:34:08.243012 usbus0.4 DONE-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=4,IVAL=0,ERR=0
    15:34:08.243022 usbus0.4 SUBM-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=8,IVAL=0
    15:34:08.243261 usbus0.4 DONE-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=4,IVAL=0,ERR=0
    15:34:08.243271 usbus0.4 SUBM-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=8,IVAL=0
    15:34:08.243512 usbus0.4 DONE-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=4,IVAL=0,ERR=0
    15:34:08.245630 usbus0.4 SUBM-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=8,IVAL=0
    15:34:08.245890 usbus0.4 DONE-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=4,IVAL=0,ERR=0
    15:34:08.245901 usbus0.4 SUBM-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=8,IVAL=0
    15:34:09.233815 usbus0.4 DONE-CTRL-EP=00000080,SPD=HIGH,NFR=0,SLEN=0,IVAL=0,ERR=TIMEOUT
    15:34:09.233841 usbus0.4 SUBM-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=8,IVAL=0
    15:34:09.234062 usbus0.4 DONE-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=4,IVAL=0,ERR=0
    15:34:09.234074 usbus0.4 SUBM-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=8,IVAL=0
    15:34:09.234310 usbus0.4 DONE-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=4,IVAL=0,ERR=0
    15:34:09.234321 usbus0.4 SUBM-CTRL-EP=00000080,SPD=HIGH,NFR=2,SLEN=8,IVAL=0
    
    

    Here is the corresponding syslog for that time from Mac OSX cosole:

    
    1/30/16 15:33:59.000 pfs.dv.loc nginx[-1]: 172.22.22.10 - - [30/Jan/2016:15:33:59 -0500] "GET /ifstats.php?if=em1 HTTP/1.1" 200 48 "https://pfs.dv.loc/graph.php?ifnum=wan&ifname=WAN&timeint=10&initdelay=2" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.10; rv:44.0) Gecko/20100101 Firefox/44.0"
    1/30/16 15:33:59.000 pfs.dv.loc nginx[-1]: 172.22.22.10 - - [30/Jan/2016:15:33:59 -0500] "POST /widgets/widgets/interface_statistics.widget.php HTTP/1.1" 200 658 "https://pfs.dv.loc/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.10; rv:44.0) Gecko/20100101 Firefox/44.0"
    1/30/16 15:34:00.000 pfs.dv.loc nginx[-1]: 172.22.22.10 - - [30/Jan/2016:15:34:00 -0500] "GET /widgets/widgets/thermal_sensors.widget.php?getThermalSensorsData=11454186040475 HTTP/1.1" 200 126 "https://pfs.dv.loc/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.10; rv:44.0) Gecko/20100101 Firefox/44.0"
    1/30/16 15:34:00.000 pfs.dv.loc nginx[-1]: 172.22.22.10 - - [30/Jan/2016:15:34:00 -0500] "GET /ifstats.php?if=em0 HTTP/1.1" 200 48 "https://pfs.dv.loc/graph.php?ifnum=lan&ifname=LAN&timeint=10&initdelay=4" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.10; rv:44.0) Gecko/20100101 Firefox/44.0"
    1/30/16 15:34:01.000 pfs.dv.loc nginx[-1]: 172.22.22.10 - - [30/Jan/2016:15:34:01 -0500] "GET /getstats.php HTTP/1.1" 200 783 "https://pfs.dv.loc/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.10; rv:44.0) Gecko/20100101 Firefox/44.0"
    1/30/16 15:34:01.000 pfs.dv.loc nginx[-1]: 172.22.22.10 - - [30/Jan/2016:15:34:01 -0500] "POST /widgets/widgets/gateways.widget.php HTTP/1.1" 200 401 "https://pfs.dv.loc/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.10; rv:44.0) Gecko/20100101 Firefox/44.0"
    1/30/16 15:34:03.000 pfs.dv.loc nginx[-1]: 172.22.22.10 - - [30/Jan/2016:15:34:03 -0500] "GET /ifstats.php?if=ue0 HTTP/1.1" 200 46 "https://pfs.dv.loc/graph.php?ifnum=opt1&ifname=WL1&timeint=10&initdelay=6" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.10; rv:44.0) Gecko/20100101 Firefox/44.0"
    1/30/16 15:34:05.000 pfs.dv.loc nginx[-1]: 172.22.22.10 - - [30/Jan/2016:15:34:05 -0500] "POST /widgets/widgets/interface_statistics.widget.php HTTP/1.1" 200 658 "https://pfs.dv.loc/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.10; rv:44.0) Gecko/20100101 Firefox/44.0"
    1/30/16 15:34:06.000 pfs.dv.loc nginx[-1]: 172.22.22.10 - - [30/Jan/2016:15:34:06 -0500] "POST /widgets/widgets/gateways.widget.php HTTP/1.1" 200 401 "https://pfs.dv.loc/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.10; rv:44.0) Gecko/20100101 Firefox/44.0"
    1/30/16 15:34:08.000 check_reload_status[-1]: Linkup starting ue0
    1/30/16 15:34:08.000 Unknown[-1]: [82757] ue0: link state changed to DOWN
    1/30/16 15:34:08.000 Unknown[-1]: [82757] ue0: link state changed to UP
    1/30/16 15:34:09.000 php-fpm[62307]: /rc.linkup: DEVD Ethernet detached event for opt1
    1/30/16 15:34:09.000 check_reload_status[-1]: Linkup starting ue0
    1/30/16 15:34:09.000 pfs.dv.loc nginx[-1]: 172.22.22.10 - - [30/Jan/2016:15:34:09 -0500] "GET /ifstats.php?if=em1 HTTP/1.1" 200 48 "https://pfs.dv.loc/graph.php?ifnum=wan&ifname=WAN&timeint=10&initdelay=2" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.10; rv:44.0) Gecko/20100101 Firefox/44.0"
    1/30/16 15:34:10.000 php-fpm[62307]: /rc.linkup: DEVD Ethernet attached event for opt1
    1/30/16 15:34:10.000 php-fpm[62307]: /rc.linkup: HOTPLUG: Configuring interface opt1
    1/30/16 15:34:10.000 dhcp6c[24158]: failed to remove an address on ue0: Can't assign requested address
    1/30/16 15:34:10.000 check_reload_status[-1]: Restarting ipsec tunnels
    1/30/16 15:34:10.000 unbound[-1]: [53720:0] info: service stopped (unbound 1.5.5).
    
    


  • So you have assigned & enabled interface ue0 as OPT1, and there is nothing plugged on it or to do ?



  • @hda:

    So you have assigned & enabled interface ue0 as OPT1, and there is nothing plugged on it or to do ?

    There is just a Wireless AP connected to it via a POE injector that is constantly trying to connect to the syslog server on LAN and up to 3 wireless clients connected at any one time.  So not that busy but that interface also participates in the DHCPv6 setup with prefix ID 1 from WAN interface which goes down when ue0 drops and it takes all IPv6 with it.

    I have been monitoring the usbdump since I posted this and there have been a few single ERR=TIMEOUT events and I do see an extra dhcpleases6 and dhcpd -6 process now (meaning there must have been some event that started another copy of those without killing the current ones) but I haven't seen IPv6 drop since I posted last…

    If the verdict is that USB is too flaky for full time use I am fine with that.  I had this cheapo interface laying around so I have been trying it out.  I also have a mini-pcix slot I could use to get another interface if I had to...