OpenVPN tap interface disabled on boot



  • I created a OpenVPN tap 'tunnel' to bridge IPv6 to my home network, it works great but one issue.

    I found that the OpenVPN tap interfaces are always in "disabled" status when I reboot or upgrade the routers, then it works after I go to the interface configuration page and click save and then apply changes.

    All of routers are running recent RC snapshots.

    Server side system logs:

    Dec 11 21:48:06	syslogd: kernel boot file is /boot/kernel/kernel
    Dec 11 21:48:06	kernel: Copyright (c) 1992-2014 The FreeBSD Project.
    Dec 11 21:48:06	kernel: Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994
    Dec 11 21:48:06	kernel: The Regents of the University of California. All rights reserved.
    Dec 11 21:48:06	kernel: FreeBSD is a registered trademark of The FreeBSD Foundation.
    Dec 11 21:48:06	kernel: FreeBSD 10.1-RELEASE-p1 #0 fd28f0b(releng/10.1)-dirty: Thu Dec 11 04:15:15 CST 2014
    Dec 11 21:48:06	kernel: root@pfsense-22-amd64-builder:/usr/obj.amd64/usr/pfSensesrc/src/sys/pfSense_SMP.10 amd64
    Dec 11 21:48:06	kernel: FreeBSD clang version 3.4.1 (tags/RELEASE_34/dot1-final 208032) 20140512
    Dec 11 21:48:06	kernel: CPU: Intel(R) Pentium(R) CPU G3420 @ 3.20GHz (1968.88-MHz K8-class CPU)
    Dec 11 21:48:06	kernel: Origin = "GenuineIntel" Id = 0x306c3 Family = 0x6 Model = 0x3c Stepping = 3
    Dec 11 21:48:06	kernel: Features=0x1f83fbff <fpu,vme,de,pse,tsc,msr,pae,mce,cx8,apic,sep,mtrr,pge,mca,cmov,pat,pse36,mmx,fxsr,sse,sse2,ss,htt>Dec 11 21:48:06	kernel: Features2=0xccd82203 <sse3,pclmulqdq,ssse3,cx16,sse4.1,sse4.2,movbe,popcnt,xsave,osxsave,rdrand,hv>Dec 11 21:48:06	kernel: AMD Features=0x20100800 <syscall,nx,lm>Dec 11 21:48:06	kernel: AMD Features2=0x21 <lahf,abm>Dec 11 21:48:06	kernel: Structured Extended Features=0x2200 <erms>Dec 11 21:48:06	kernel: real memory = 1073741824 (1024 MB)
    Dec 11 21:48:06	kernel: avail memory = 999280640 (952 MB)
    Dec 11 21:48:06	kernel: Event timer "LAPIC" quality 400
    Dec 11 21:48:06	kernel: ACPI APIC Table: <vrtual microsft="">
    Dec 11 21:48:06	kernel: FreeBSD/SMP: Multiprocessor System Detected: 2 CPUs
    Dec 11 21:48:06	kernel: FreeBSD/SMP: 1 package(s) x 2 core(s)
    Dec 11 21:48:06	kernel: cpu0 (BSP): APIC ID: 0
    Dec 11 21:48:06	kernel: cpu1 (AP): APIC ID: 1
    Dec 11 21:48:06	kernel: ioapic0: Changing APIC ID to 0
    Dec 11 21:48:06	kernel: ioapic0 <version 1.1=""> irqs 0-23 on motherboard
    Dec 11 21:48:06	kernel: wlan: mac acl policy registered
    Dec 11 21:48:06	kernel: ipw_bss: You need to read the LICENSE file in /usr/share/doc/legal/intel_ipw/.
    Dec 11 21:48:06	kernel: ipw_bss: If you agree with the license, set legal.intel_ipw.license_ack=1 in /boot/loader.conf.
    Dec 11 21:48:06	kernel: module_register_init: MOD_LOAD (ipw_bss_fw, 0xffffffff80606640, 0) error 1
    Dec 11 21:48:06	kernel: ipw_ibss: You need to read the LICENSE file in /usr/share/doc/legal/intel_ipw/.
    Dec 11 21:48:06	kernel: ipw_ibss: If you agree with the license, set legal.intel_ipw.license_ack=1 in /boot/loader.conf.
    Dec 11 21:48:06	kernel: module_register_init: MOD_LOAD (ipw_ibss_fw, 0xffffffff806066f0, 0) error 1
    Dec 11 21:48:06	kernel: ipw_monitor: You need to read the LICENSE file in /usr/share/doc/legal/intel_ipw/.
    Dec 11 21:48:06	kernel: ipw_monitor: If you agree with the license, set legal.intel_ipw.license_ack=1 in /boot/loader.conf.
    Dec 11 21:48:06	kernel: module_register_init: MOD_LOAD (ipw_monitor_fw, 0xffffffff806067a0, 0) error 1
    Dec 11 21:48:06	kernel: iwi_bss: You need to read the LICENSE file in /usr/share/doc/legal/intel_iwi/.
    Dec 11 21:48:06	kernel: iwi_bss: If you agree with the license, set legal.intel_iwi.license_ack=1 in /boot/loader.conf.
    Dec 11 21:48:06	kernel: module_register_init: MOD_LOAD (iwi_bss_fw, 0xffffffff8062de10, 0) error 1
    Dec 11 21:48:06	kernel: iwi_ibss: You need to read the LICENSE file in /usr/share/doc/legal/intel_iwi/.
    Dec 11 21:48:06	kernel: iwi_ibss: If you agree with the license, set legal.intel_iwi.license_ack=1 in /boot/loader.conf.
    Dec 11 21:48:06	kernel: module_register_init: MOD_LOAD (iwi_ibss_fw, 0xffffffff8062dec0, 0) error 1
    Dec 11 21:48:06	kernel: iwi_monitor: You need to read the LICENSE file in /usr/share/doc/legal/intel_iwi/.
    Dec 11 21:48:06	kernel: iwi_monitor: If you agree with the license, set legal.intel_iwi.license_ack=1 in /boot/loader.conf.
    Dec 11 21:48:06	kernel: module_register_init: MOD_LOAD (iwi_monitor_fw, 0xffffffff8062df70, 0) error 1
    Dec 11 21:48:06	kernel: random: <software, yarrow=""> initialized
    Dec 11 21:48:06	kernel: kbd1 at kbdmux0
    Dec 11 21:48:06	kernel: vmbus0: <vmbus devices=""> on motherboard
    Dec 11 21:48:06	kernel: cryptosoft0: <software crypto=""> on motherboard
    Dec 11 21:48:06	kernel: padlock0: No ACE support.
    Dec 11 21:48:06	kernel: acpi0: <vrtual microsft=""> on motherboard
    Dec 11 21:48:06	kernel: acpi0: Power Button (fixed)
    Dec 11 21:48:06	kernel: acpi0: reservation of 0, a0000 (3) failed
    Dec 11 21:48:06	kernel: acpi0: reservation of 100000, f7f00000 (3) failed
    Dec 11 21:48:06	kernel: cpu0: <acpi cpu=""> on acpi0
    Dec 11 21:48:06	kernel: cpu1: <acpi cpu=""> on acpi0
    Dec 11 21:48:06	kernel: attimer0: <at timer=""> port 0x40-0x43 irq 0 on acpi0
    Dec 11 21:48:06	kernel: Timecounter "i8254" frequency 1193182 Hz quality 0
    Dec 11 21:48:06	kernel: Event timer "i8254" frequency 1193182 Hz quality 100
    Dec 11 21:48:06	kernel: atrtc0: <at realtime="" clock=""> port 0x70-0x71 irq 8 on acpi0
    Dec 11 21:48:06	kernel: Event timer "RTC" frequency 32768 Hz quality 0
    Dec 11 21:48:06	kernel: Timecounter "ACPI-fast" frequency 3579545 Hz quality 900
    Dec 11 21:48:06	kernel: acpi_timer0: <32-bit timer at 3.579545MHz> port 0x408-0x40b on acpi0
    Dec 11 21:48:06	kernel: pcib0: <acpi host-pci="" bridge=""> port 0xcf8-0xcff on acpi0
    Dec 11 21:48:06	kernel: pci0: <acpi pci="" bus=""> on pcib0
    Dec 11 21:48:06	kernel: isab0: <pci-isa bridge=""> at device 7.0 on pci0
    Dec 11 21:48:06	kernel: isa0: <isa bus=""> on isab0
    Dec 11 21:48:06	kernel: atapci0: <intel piix4="" udma33="" controller=""> port 0x1f0-0x1f7,0x3f6,0x170-0x177,0x376,0xffa0-0xffaf at device 7.1 on pci0
    Dec 11 21:48:06	kernel: ata0: <ata channel=""> at channel 0 on atapci0
    Dec 11 21:48:06	kernel: ata1: <ata channel=""> at channel 1 on atapci0
    Dec 11 21:48:06	kernel: pci0: <bridge> at device 7.3 (no driver attached)
    Dec 11 21:48:06	kernel: vgapci0: <vga-compatible display=""> mem 0xf8000000-0xfbffffff irq 11 at device 8.0 on pci0
    Dec 11 21:48:06	kernel: vgapci0: Boot video device
    Dec 11 21:48:06	kernel: atkbdc0: <keyboard controller="" (i8042)=""> port 0x60,0x64 irq 1 on acpi0
    Dec 11 21:48:06	kernel: atkbd0: <at keyboard=""> irq 1 on atkbdc0
    Dec 11 21:48:06	kernel: kbd0 at atkbd0
    Dec 11 21:48:06	kernel: atkbd0: [GIANT-LOCKED]
    Dec 11 21:48:06	kernel: psm0: <ps 2="" mouse=""> irq 12 on atkbdc0
    Dec 11 21:48:06	kernel: psm0: [GIANT-LOCKED]
    Dec 11 21:48:06	kernel: psm0: model IntelliMouse Explorer, device ID 4
    Dec 11 21:48:06	kernel: uart0: <16550 or compatible> port 0x3f8-0x3ff irq 4 flags 0x10 on acpi0
    Dec 11 21:48:06	kernel: uart0: console (115200,n,8,1)
    Dec 11 21:48:06	kernel: uart1: <16550 or compatible> port 0x2f8-0x2ff irq 3 on acpi0
    Dec 11 21:48:06	kernel: fdc0: <floppy drive="" controller="" (fde)=""> port 0x3f0-0x3f5,0x3f7 irq 6 drq 2 on acpi0
    Dec 11 21:48:06	kernel: fd0: <1440-KB 3.5" drive> on fdc0 drive 0
    Dec 11 21:48:06	kernel: orm0: <isa option="" rom=""> at iomem 0xc0000-0xcbfff on isa0
    Dec 11 21:48:06	kernel: sc0: <system console=""> at flags 0x100 on isa0
    Dec 11 21:48:06	kernel: sc0: VGA <16 virtual consoles, flags=0x100>
    Dec 11 21:48:06	kernel: vga0: <generic isa="" vga=""> at port 0x3c0-0x3df iomem 0xa0000-0xbffff on isa0
    Dec 11 21:48:06	kernel: ppc0: cannot reserve I/O port range
    Dec 11 21:48:06	kernel: Timecounter "Hyper-V" frequency 10000000 Hz quality 10000000
    Dec 11 21:48:06	kernel: Timecounters tick every 10.000 msec
    Dec 11 21:48:06	kernel: IPsec: Initialized Security Association Processing.
    Dec 11 21:48:06	kernel: storvsc0 on vmbus0
    Dec 11 21:48:06	kernel: ada0 at ata0 bus 0 scbus0 target 0 lun 0
    Dec 11 21:48:06	kernel: cd0 at ata1 bus 0 scbus1 target 0 lun 0
    Dec 11 21:48:06	kernel: cd0: <msft virtual="" cd="" rom="" 1.0=""> Removable CD-ROM SCSI-5 device
    Dec 11 21:48:06	kernel: cd0: 16.700MB/s transfers (PIO4, ATAPI 12bytes, PIO 65534bytes)
    Dec 11 21:48:06	kernel: cd0: Attempt to query device size failed: NOT READY, Medium not present
    Dec 11 21:48:06	kernel: ada0: <virtual hd="" 1.1.0=""> ATA-8 device
    Dec 11 21:48:06	kernel: ada0: 16.700MB/s transfers (PIO4, PIO 65536bytes)
    Dec 11 21:48:06	kernel: ada0: 1024MB (2097152 512 byte sectors: 16H 63S/T 2080C)
    Dec 11 21:48:06	kernel: ada0: Previously was known as ad0
    Dec 11 21:48:06	kernel: (ada0:ata0:0:0:0): SETFEATURES ENABLE WCACHE. ACB: ef 02 00 00 00 40 00 00 00 00 00 00
    Dec 11 21:48:06	kernel: (ada0:ata0:0:0:0): CAM status: ATA Status Error
    Dec 11 21:48:06	kernel: (ada0:ata0:0:0:0): ATA status: 51 (DRDY SERV ERR), error: 00 ()
    Dec 11 21:48:06	kernel: (ada0:ata0:0:0:0): RES: 51 00 00 00 00 00 00 00 00 00 00
    Dec 11 21:48:06	kernel: (ada0:ata0:0:0:0): Retrying command
    Dec 11 21:48:06	kernel: (ada0:ata0:0:0:0): SETFEATURES ENABLE WCACHE. ACB: ef 02 00 00 00 40 00 00 00 00 00 00
    Dec 11 21:48:06	kernel: (ada0:ata0:0:0:0): CAM status: ATA Status Error
    Dec 11 21:48:06	kernel: (ada0:ata0:0:0:0): ATA status: 51 (DRDY SERV ERR), error: 00 ()
    Dec 11 21:48:06	kernel: (ada0:ata0:0:0:0): RES: 51 00 00 00 00 00 00 00 00 00 00
    Dec 11 21:48:06	kernel: (ada0:ata0:0:0:hyperv-utils0 on vmbus0
    Dec 11 21:48:06	kernel: hyperv-utils0: Hyper-V Service attaching: Hyper-V Heartbeat Service
    Dec 11 21:48:06	kernel:
    Dec 11 21:48:06	kernel: 0): hyperv-utils1 on vmbus0
    Dec 11 21:48:06	kernel: hyperv-utils1: Hyper-V Service attaching: Hyper-V KVP Service
    Dec 11 21:48:06	kernel:
    Dec 11 21:48:06	kernel: Error 5, Retries exhausted
    Dec 11 21:48:06	kernel: hyperv-utils2 on vmbus0
    Dec 11 21:48:06	kernel: hyperv-utils2: Hyper-V Service attaching: Hyper-V Shutdown Service
    Dec 11 21:48:06	kernel:
    Dec 11 21:48:06	kernel: hn0: <synthetic network="" interface=""> on vmbus0
    Dec 11 21:48:06	kernel: da0 at blkvsc0 bus 0 scbus2 target 0 lun 0
    Dec 11 21:48:06	kernel: hn1: <synthetic network="" interface=""> on vmbus0
    Dec 11 21:48:06	kernel: da0: random: unblocking device.
    Dec 11 21:48:06	kernel: SMP: AP CPU #1 Launched!
    Dec 11 21:48:06	kernel: <msft virtual="" disk="" 1.0=""> Fixed Direct Access SCSI-4 device
    Dec 11 21:48:06	kernel: da0: 300.000MB/s transfers
    Dec 11 21:48:06	kernel: da0: Command Queueing enabled
    Dec 11 21:48:06	kernel: da0: 1024MB (2097152 512 byte sectors: 64H 32S/T 1024C)
    Dec 11 21:48:06	kernel: hn2: <synthetic network="" interface=""> on vmbus0
    Dec 11 21:48:06	kernel: hn3: <synthetic network="" interface=""> on vmbus0
    Dec 11 21:48:06	kernel: hn4: <synthetic network="" interface=""> on vmbus0
    Dec 11 21:48:06	kernel: hn5: <synthetic network="" interface=""> on vmbus0
    Dec 11 21:48:06	kernel: Trying to mount root from ufs:/dev/ufs/pfsense1 [ro,sync,noatime]...
    Dec 11 21:48:06	kernel:
    Dec 11 21:48:16	kernel:
    Dec 11 21:48:27	kernel:
    Dec 11 21:48:37	kernel: calcru: runtime went backwards from 21060 usec to 13376 usec for pid 9807 (mpd5)
    Dec 11 21:48:37	kernel: calcru: runtime went backwards from 29076 usec to 17931 usec for pid 9807 (mpd5)
    Dec 11 21:48:37	kernel: calcru: runtime went backwards from 29337 usec to 18226 usec for pid 5736 (mpd5)
    Dec 11 21:48:37	kernel: calcru: runtime went backwards from 31195 usec to 19237 usec for pid 5736 (mpd5)
    Dec 11 21:48:37	kernel: calcru: runtime went backwards from 61432 usec to 44584 usec for pid 5045 (syslogd)
    Dec 11 21:48:37	kernel: calcru: runtime went backwards from 753 usec to 582 usec for pid 318 (devd)
    Dec 11 21:48:37	kernel: calcru: runtime went backwards from 1372035 usec to 854958 usec for pid 308 (php)
    Dec 11 21:48:37	kernel: calcru: runtime went backwards from 895902 usec to 606539 usec for pid 308 (php)
    Dec 11 21:48:37	kernel: calcru: runtime went backwards from 1701 usec to 1049 usec for pid 304 (check_reload_status)
    Dec 11 21:48:37	kernel: calcru: runtime went backwards from 8342 usec to 5634 usec for pid 303 (check_reload_status)
    Dec 11 21:48:37	kernel: calcru: runtime went backwards from 577606 usec to 357235 usec for pid 287 (php-fpm)
    Dec 11 21:48:37	kernel: calcru: runtime went backwards from 64935 usec to 40045 usec for pid 287 (php-fpm)
    Dec 11 21:48:37	kernel: calcru: runtime went backwards from 8672 usec to 5763 usec for pid 286 (php-fpm)
    Dec 11 21:48:37	kernel: calcru: runtime went backwards from 71949 usec to 46265 usec for pid 54 (md1)
    Dec 11 21:48:37	kernel: calcru: runtime went backwards from 13229 usec to 8558 usec for pid 49 (md0)
    Dec 11 21:48:37	kernel: calcru: runtime went backwards from 115307 usec to 71110 usec for pid 21 (sh)
    Dec 11 21:48:37	kernel: calcru: runtime went backwards from 1770392 usec to 1091800 usec for pid 21 (sh)
    Dec 11 21:48:37	kernel: calcru: runtime went backwards from 181 usec to 162 usec for pid 20 (vnlru)
    Dec 11 21:48:37	kernel: calcru: runtime went backwards from 191 usec to 168 usec for pid 18 (bufdaemon)
    Dec 11 21:48:37	kernel: calcru: runtime went backwards from 24 usec to 14 usec for pid 17 (pagezero)
    Dec 11 21:48:37	kernel: calcru: runtime went backwards from 51 usec to 44 usec for pid 16 (idlepoll)
    Dec 11 21:48:37	kernel: calcru: runtime went backwards from 1483 usec to 1226 usec for pid 8 (pagedaemon)
    Dec 11 21:48:37	kernel: calcru: runtime went backwards from 56 usec to 46 usec for pid 7 (sctp_iterator)
    Dec 11 21:48:37	kernel: calcru: runtime went backwards from 14241 usec to 12953 usec for pid 6 (pf purge)
    Dec 11 21:48:37	kernel: calcru: runtime went backwards from 4058 usec to 2545 usec for pid 5 (fdc0)
    Dec 11 21:48:37	kernel: calcru: runtime went backwards from 388260 usec to 239502 usec for pid 4 (cam)
    Dec 11 21:48:38	kernel: calcru: runtime went backwards from 22231 usec to 18873 usec for pid 15 (rand_harvestq)
    Dec 11 21:48:38	kernel: calcru: runtime went backwards from 90638 usec to 55896 usec for pid 14 (geom)
    Dec 11 21:48:38	kernel: calcru: runtime went backwards from 853 usec to 819 usec for pid 13 (ng_queue)
    Dec 11 21:48:38	kernel: calcru: runtime went backwards from 3613764 usec to 2262625 usec for pid 12 (intr)
    Dec 11 21:48:38	kernel: calcru: runtime went backwards from 77163173 usec to 68611653 usec for pid 11 (idle)
    Dec 11 21:48:38	kernel: calcru: runtime went backwards from 33644 usec to 20760 usec for pid 1 (init)
    Dec 11 21:48:38	kernel: calcru: runtime went backwards from 17292 usec to 10664 usec for pid 1 (init)
    Dec 11 21:48:38	kernel: calcru: runtime went backwards from 179338 usec to 110613 usec for pid 0 (kernel)
    Dec 11 21:48:38	kernel:
    Dec 11 21:48:48	php: rc.bootup: Accept router advertisements on interface bridge0
    Dec 11 21:48:48	kernel: done.
    Dec 11 21:48:48	kernel: hn5: promiscuous mode enabled
    Dec 11 21:48:48	kernel: bridge0: link state changed to UP
    Dec 11 21:48:48	rtsold[22333]: <interface_up> get_llflag() failed, anyway I'll try
    Dec 11 21:48:48	php: rc.bootup: Resyncing OpenVPN instances.
    Dec 11 21:48:48	kernel: done.
    Dec 11 21:48:48	rtsold[22333]: <rtsock_input_ifannounce> interface tap1 removed
    Dec 11 21:48:48	kernel:
    Dec 11 21:48:48	kernel: tap1: changing name to 'ovpns1'
    Dec 11 21:48:48	kernel: ovpns1: link state changed to UP
    Dec 11 21:48:48	check_reload_status: Linkup starting ovpns1
    Dec 11 21:48:48	check_reload_status: rc.newwanip starting ovpns1
    Dec 11 21:48:48	kernel: pflog0: promiscuous mode enabled
    Dec 11 21:48:49	php: rc.bootup: Could not find IPv6 gateway for interface (opt4).
    Dec 11 21:48:49	kernel: .
    Dec 11 21:48:49	php: rc.bootup: Could not find IPv4 gateway for interface (opt4).
    Dec 11 21:48:49	php: rc.bootup: Could not find IPv4 gateway for interface (opt6).
    Dec 11 21:48:49	php: rc.bootup: Could not find IPv6 gateway for interface (opt6).
    Dec 11 21:48:49	php: rc.bootup: Could not find IPv4 gateway for interface (opt6).
    Dec 11 21:48:49	rtsold[22333]: <sendpacket> sendmsg on bridge0: Can't assign requested address
    Dec 11 21:48:49	kernel: ..
    Dec 11 21:48:49	kernel: .done.
    Dec 11 21:48:49	php: rc.bootup: Removing static route for monitor 58.215.152.10 and adding a new route through 117.84.144.1
    Dec 11 21:48:49	php: rc.bootup: Removing static route for monitor 58.215.152.6 and adding a new route through 117.84.144.1
    Dec 11 21:48:49	php: rc.bootup: Removing static route for monitor 58.215.152.5 and adding a new route through 117.84.144.1
    Dec 11 21:48:49	php: rc.bootup: Removing static route for monitor 58.215.152.9 and adding a new route through 117.84.144.1
    Dec 11 21:48:51	kernel: done.
    Dec 11 21:48:52	kernel: done.
    Dec 11 21:48:53	rtsold[22333]: <sendpacket> sendmsg on bridge0: Can't assign requested address
    Dec 11 21:48:53	php: rc.bootup: ROUTING: setting default route to 117.84.144.1
    Dec 11 21:48:53	kernel: done.
    Dec 11 21:48:53	kernel: done.
    Dec 11 21:48:53	check_reload_status: Updating all dyndns
    Dec 11 21:48:53	kernel: done.
    Dec 11 21:48:54	kernel: .
    Dec 11 21:48:54	php: rc.bootup: Could not find IPv6 gateway for interface (opt4).
    Dec 11 21:48:54	kernel: .
    Dec 11 21:48:54	php: rc.bootup: Could not find IPv4 gateway for interface (opt4).
    Dec 11 21:48:54	php: rc.bootup: Could not find IPv4 gateway for interface (opt6).
    Dec 11 21:48:54	php: rc.bootup: Could not find IPv6 gateway for interface (opt6).
    Dec 11 21:48:54	php: rc.bootup: Could not find IPv4 gateway for interface (opt6).
    Dec 11 21:48:54	kernel: ..
    Dec 11 21:48:54	kernel: .done.
    Dec 11 21:48:57	rtsold[22333]: <sendpacket> sendmsg on bridge0: Can't assign requested address
    Dec 11 21:49:06	php: rc.bootup: The command '/usr/bin/nice -n20 /usr/local/bin/rrdtool update /var/db/rrd/wan-traffic.rrd N:U:U:U:U:U:U:U:U' returned exit code '1', the output was 'ERROR: /var/db/rrd/wan-traffic.rrd: illegal attempt to update using time 1418305746 when last update time is 1418646087 (minimum one second step)'
    Dec 11 21:49:06	php: rc.bootup: The command '/usr/bin/nice -n20 /usr/local/bin/rrdtool update /var/db/rrd/wan-packets.rrd N:U:U:U:U:U:U:U:U' returned exit code '1', the output was 'ERROR: /var/db/rrd/wan-packets.rrd: illegal attempt to update using time 1418305746 when last update time is 1418646087 (minimum one second step)'
    Dec 11 21:49:06	php: rc.bootup: The command '/usr/bin/nice -n20 /usr/local/bin/rrdtool update /var/db/rrd/lan-traffic.rrd N:U:U:U:U:U:U:U:U' returned exit code '1', the output was 'ERROR: /var/db/rrd/lan-traffic.rrd: illegal attempt to update using time 1418305746 when last update time is 1418646087 (minimum one second step)'
    Dec 11 21:49:06	php: rc.bootup: The command '/usr/bin/nice -n20 /usr/local/bin/rrdtool update /var/db/rrd/lan-packets.rrd N:U:U:U:U:U:U:U:U' returned exit code '1', the output was 'ERROR: /var/db/rrd/lan-packets.rrd: illegal attempt to update using time 1418305746 when last update time is 1418646087 (minimum one second step)'
    Dec 11 21:49:06	php: rc.bootup: The command '/usr/bin/nice -n20 /usr/local/bin/rrdtool update /var/db/rrd/opt1-traffic.rrd N:U:U:U:U:U:U:U:U' returned exit code '1', the output was 'ERROR: /var/db/rrd/opt1-traffic.rrd: illegal attempt to update using time 1418305746 when last update time is 1418389413 (minimum one second step)'
    Dec 11 21:49:06	php: rc.bootup: The command '/usr/bin/nice -n20 /usr/local/bin/rrdtool update /var/db/rrd/opt1-packets.rrd N:U:U:U:U:U:U:U:U' returned exit code '1', the output was 'ERROR: /var/db/rrd/opt1-packets.rrd: illegal attempt to update using time 1418305746 when last update time is 1418389413 (minimum one second step)'
    Dec 11 21:49:06	php: rc.bootup: The command '/usr/bin/nice -n20 /usr/local/bin/rrdtool update /var/db/rrd/opt2-traffic.rrd N:U:U:U:U:U:U:U:U' returned exit code '1', the output was 'ERROR: /var/db/rrd/opt2-traffic.rrd: illegal attempt to update using time 1418305746 when last update time is 1418646087 (minimum one second step)'
    Dec 11 21:49:06	php: rc.bootup: The command '/usr/bin/nice -n20 /usr/local/bin/rrdtool update /var/db/rrd/opt2-packets.rrd N:U:U:U:U:U:U:U:U' returned exit code '1', the output was 'ERROR: /var/db/rrd/opt2-packets.rrd: illegal attempt to update using time 1418305746 when last update time is 1418646087 (minimum one second step)'
    Dec 11 21:49:06	php: rc.bootup: The command '/usr/bin/nice -n20 /usr/local/bin/rrdtool update /var/db/rrd/opt3-traffic.rrd N:U:U:U:U:U:U:U:U' returned exit code '1', the output was 'ERROR: /var/db/rrd/opt3-traffic.rrd: illegal attempt to update using time 1418305746 when last update time is 1418646087 (minimum one second step)'
    Dec 11 21:49:06	php: rc.bootup: The command '/usr/bin/nice -n20 /usr/local/bin/rrdtool update /var/db/rrd/opt3-packets.rrd N:U:U:U:U:U:U:U:U' returned exit code '1', the output was 'ERROR: /var/db/rrd/opt3-packets.rrd: illegal attempt to update using time 1418305746 when last update time is 1418646087 (minimum one second step)'
    Dec 11 21:49:06	php: rc.bootup: The command '/usr/bin/nice -n20 /usr/local/bin/rrdtool update /var/db/rrd/opt4-traffic.rrd N:U:U:U:U:U:U:U:U' returned exit code '1', the output was 'ERROR: /var/db/rrd/opt4-traffic.rrd: illegal attempt to update using time 1418305746 when last update time is 1418646087 (minimum one second step)'
    Dec 11 21:49:06	php: rc.bootup: The command '/usr/bin/nice -n20 /usr/local/bin/rrdtool update /var/db/rrd/opt4-packets.rrd N:U:U:U:U:U:U:U:U' returned exit code '1', the output was 'ERROR: /var/db/rrd/opt4-packets.rrd: illegal attempt to update using time 1418305746 when last update time is 1418646087 (minimum one second step)'
    Dec 11 21:49:06	php: rc.bootup: The command '/usr/bin/nice -n20 /usr/local/bin/rrdtool update /var/db/rrd/opt5-traffic.rrd N:U:U:U:U:U:U:U:U' returned exit code '1', the output was 'ERROR: /var/db/rrd/opt5-traffic.rrd: illegal attempt to update using time 1418305746 when last update time is 1418646087 (minimum one second step)'
    Dec 11 21:49:06	php: rc.bootup: The command '/usr/bin/nice -n20 /usr/local/bin/rrdtool update /var/db/rrd/opt5-packets.rrd N:U:U:U:U:U:U:U:U' returned exit code '1', the output was 'ERROR: /var/db/rrd/opt5-packets.rrd: illegal attempt to update using time 1418305746 when last update time is 1418646087 (minimum one second step)'
    Dec 11 21:49:07	php: rc.bootup: The command '/usr/bin/nice -n20 /usr/local/bin/rrdtool update /var/db/rrd/opt6-traffic.rrd N:U:U:U:U:U:U:U:U' returned exit code '1', the output was 'ERROR: /var/db/rrd/opt6-traffic.rrd: illegal attempt to update using time 1418305747 when last update time is 1418646087 (minimum one second step)'
    Dec 11 21:49:07	php: rc.bootup: The command '/usr/bin/nice -n20 /usr/local/bin/rrdtool update /var/db/rrd/opt6-packets.rrd N:U:U:U:U:U:U:U:U' returned exit code '1', the output was 'ERROR: /var/db/rrd/opt6-packets.rrd: illegal attempt to update using time 1418305747 when last update time is 1418646087 (minimum one second step)'
    Dec 11 21:49:07	php: rc.bootup: The command '/usr/bin/nice -n20 /usr/local/bin/rrdtool update /var/db/rrd/ipsec-traffic.rrd N:U:U:U:U:U:U:U:U' returned exit code '1', the output was 'ERROR: /var/db/rrd/ipsec-traffic.rrd: illegal attempt to update using time 1418305747 when last update time is 1418646087 (minimum one second step)'
    Dec 11 21:49:07	php: rc.bootup: The command '/usr/bin/nice -n20 /usr/local/bin/rrdtool update /var/db/rrd/ipsec-packets.rrd N:U:U:U:U:U:U:U:U' returned exit code '1', the output was 'ERROR: /var/db/rrd/ipsec-packets.rrd: illegal attempt to update using time 1418305747 when last update time is 1418646087 (minimum one second step)'
    Dec 11 21:49:07	php: rc.bootup: The command '/usr/bin/nice -n20 /usr/local/bin/rrdtool update /var/db/rrd/ovpns1-traffic.rrd N:U:U:U:U:U:U:U:U' returned exit code '1', the output was 'ERROR: /var/db/rrd/ovpns1-traffic.rrd: illegal attempt to update using time 1418305747 when last update time is 1418646087 (minimum one second step)'
    Dec 11 21:49:07	php: rc.bootup: The command '/usr/bin/nice -n20 /usr/local/bin/rrdtool update /var/db/rrd/ovpns1-packets.rrd N:U:U:U:U:U:U:U:U' returned exit code '1', the output was 'ERROR: /var/db/rrd/ovpns1-packets.rrd: illegal attempt to update using time 1418305747 when last update time is 1418646087 (minimum one second step)'
    Dec 11 21:49:07	php: rc.bootup: The command '/usr/bin/nice -n20 /usr/local/bin/rrdtool update /var/db/rrd/ovpns1-vpnusers.rrd N:U' returned exit code '1', the output was 'ERROR: /var/db/rrd/ovpns1-vpnusers.rrd: illegal attempt to update using time 1418305747 when last update time is 1418646088 (minimum one second step)'
    Dec 11 21:49:07	php: rc.bootup: The command '/usr/bin/nice -n20 /usr/local/bin/rrdtool update /var/db/rrd/system-states.rrd N:U:U:U:U:U' returned exit code '1', the output was 'ERROR: /var/db/rrd/system-states.rrd: illegal attempt to update using time 1418305747 when last update time is 1418646088 (minimum one second step)'
    Dec 11 21:49:07	php: rc.bootup: The command '/usr/bin/nice -n20 /usr/local/bin/rrdtool update /var/db/rrd/system-processor.rrd N:U:U:U:U:U' returned exit code '1', the output was 'ERROR: /var/db/rrd/system-processor.rrd: illegal attempt to update using time 1418305747 when last update time is 1418646089 (minimum one second step)'
    Dec 11 21:49:07	php: rc.bootup: The command '/usr/bin/nice -n20 /usr/local/bin/rrdtool update /var/db/rrd/system-memory.rrd N:U:U:U:U:U' returned exit code '1', the output was 'ERROR: /var/db/rrd/system-memory.rrd: illegal attempt to update using time 1418305747 when last update time is 1418646089 (minimum one second step)'
    Dec 11 21:49:07	php: rc.bootup: The command '/usr/bin/nice -n20 /usr/local/bin/rrdtool update /var/db/rrd/system-mbuf.rrd N:U:U:U:U' returned exit code '1', the output was 'ERROR: /var/db/rrd/system-mbuf.rrd: illegal attempt to update using time 1418305747 when last update time is 1418646089 (minimum one second step)'
    Dec 11 21:49:07	php: rc.bootup: Creating rrd update script
    Dec 11 21:49:07	php: rc.bootup: miniupnpd: Starting service on interface: lan
    Dec 11 21:49:07	kernel: done.
    Dec 11 21:49:07	kernel: done.
    Dec 11 21:49:07	php-fpm[47738]: /rc.start_packages: Restarting/Starting all packages.
    Dec 11 21:49:07	kernel: done.
    Dec 11 21:49:08	login: login on ttyv0 as root
    Dec 11 21:49:08	login: login on ttyu0 as root
    Dec 11 21:49:08	sshlockout[99484]: sshlockout/webConfigurator v3.0 starting up
    Dec 11 21:49:09	php-fpm[287]: /rc.dyndns.update: phpDynDNS: updating cache file /conf/dyndns_wannoip-free'**1.no-ip.org'0.cache: 117.84.146.212
    Dec 11 21:49:09	php-fpm[287]: /rc.dyndns.update: phpDynDNS (**1.no-ip.org): (Success) DNS hostname update successful.
    Dec 11 21:48:09	php-fpm[287]: /rc.dyndns.update: Curl error occurred: Operation timed out after 120000 milliseconds with 0 bytes received
    Dec 11 21:48:12	php-fpm[287]: /rc.dyndns.update: phpDynDNS: updating cache file /conf/dyndns_opt1he-net'**5.net'2.cache: 117.84.146.218
    Dec 11 21:48:12	php-fpm[287]: /rc.dyndns.update: phpDynDNS: (Success) IP Address Updated Successfully!
    Dec 11 21:48:19	php-fpm[287]: /rc.dyndns.update: phpDynDNS: updating cache file /conf/dyndns_opt3he-net'**4.net'3.cache: 117.84.146.228
    Dec 11 21:48:19	php-fpm[287]: /rc.dyndns.update: phpDynDNS: (Success) IP Address Updated Successfully!
    Dec 11 21:48:21	php-fpm[287]: /rc.dyndns.update: phpDynDNS: updating cache file /conf/dyndns_opt2he-net'**3.net'4.cache: 117.84.146.227
    Dec 11 21:48:21	php-fpm[287]: /rc.dyndns.update: phpDynDNS: (Success) IP Address Updated Successfully!
    Dec 11 21:48:28	php-fpm[287]: /rc.dyndns.update: phpDynDNS: updating cache file /conf/dyndns_opt2he-net-tunnelbroker'251224'5.cache: 117.84.146.227
    Dec 11 21:48:28	php-fpm[287]: /rc.dyndns.update: phpDynDNS: (Success) IP Address Updated Successfully!</sendpacket></sendpacket></sendpacket></rtsock_input_ifannounce></interface_up></synthetic></synthetic></synthetic></synthetic></msft></synthetic></synthetic></virtual></msft></generic></system></isa></floppy></ps></at></keyboard></vga-compatible></bridge></ata></ata></intel></isa></pci-isa></acpi></acpi></at></at></acpi></acpi></vrtual></software></vmbus></software,></version></vrtual></erms></lahf,abm></syscall,nx,lm></sse3,pclmulqdq,ssse3,cx16,sse4.1,sse4.2,movbe,popcnt,xsave,osxsave,rdrand,hv></fpu,vme,de,pse,tsc,msr,pae,mce,cx8,apic,sep,mtrr,pge,mca,cmov,pat,pse36,mmx,fxsr,sse,sse2,ss,htt>
    

    Server side OpenVPN logs:

    Dec 11 21:48:48	openvpn[24042]: OpenVPN 2.3.6 amd64-portbld-freebsd10.1 [SSL (OpenSSL)] [LZO] [MH] [IPv6] built on Dec 1 2014
    Dec 11 21:48:48	openvpn[24042]: library versions: OpenSSL 1.0.1i-freebsd 6 Aug 2014, LZO 2.08
    Dec 11 21:48:48	openvpn[25276]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
    Dec 11 21:48:48	openvpn[25276]: Initializing OpenSSL support for engine 'cryptodev'
    Dec 11 21:48:48	openvpn[25276]: TUN/TAP device ovpns1 exists previously, keep at program end
    Dec 11 21:48:48	openvpn[25276]: TUN/TAP device /dev/tap1 opened
    Dec 11 21:48:48	openvpn[25276]: /usr/local/sbin/ovpn-linkup ovpns1 1500 1593 init
    Dec 11 21:48:48	openvpn[25276]: UDPv4 link local (bound): [AF_INET]117.84.146.227:11960
    Dec 11 21:48:48	openvpn[25276]: UDPv4 link remote: [undef]
    Dec 11 21:55:46	openvpn[25276]: Peer Connection Initiated with [AF_INET]58.214.18.230:2123
    Dec 11 21:55:47	openvpn[25276]: Initialization Sequence Completed
    

    Please could you tell me where I am wrong, thanks.





  • Upgraded to latest snapshot, same result.




  • How is that tap configured? Looks like it's part of a bridge. What else is on that bridge?

    I'm curious if the issue is related to the fact that timing on Hyper-V is inaccurate upon initial boot (clock going backwards), or if it's a generally replicable issue in the circumstance you have.



  • It's a peer to peer (Shared Key) OpenVPN connection, the OpenVPN connection can be initiated successfully, but OpenVPN tap interfaces are always disabled on every boot(after upgrade or a normal reboot).

    On OpenVPN client side, I bridged a WAN(IPv6 only), VPN(OpenVPN tap interface) and LAN6(IPv6 only) together ,and on OpenVPN Server side, there are VPN6(OpenVPN tap interface) and LAN6(IPv6 only) which were bridged together.

    I've tried different nanobsd edtions, results are the same.

    I don't know if it's a Hyper-V timing related issue, I didn't try it on bare metal.



  • This is happening to me on bare metal as well. All OpenVPN tun instances are fine, the single tap instance is always down right after a boot.



  • Now the tap interface shows itself to be enabled after a upgrade or reboot, but still doesn't work until I enable it again.



  • @naras:

    Now the tap interface shows itself to be enabled after a upgrade or reboot, but still doesn't work until I enable it again.

    What do you mean "enable it again"?

    Renato found and fixed what seemed to be the source issue there and it looks to work.



  • Sorry, I didn't express myself clear.

    I just got the latest snapshot(Fri Jan 09 09:55:04 CST 2015), and all interfaces are up, but the tap interface still not work until I go to the "Interfaces" menu, save and apply OpenVPN tap interface without any changes, because I can get ping replies from the other side after that.


Log in to reply