OPNsense Forum

English Forums => Tutorials and FAQs => Topic started by: guest24551 on May 19, 2020, 08:19:51 am

Title: Config Problems? DHCP leases, unexpected "sleep", ntopng and telemetry
Post by: guest24551 on May 19, 2020, 08:19:51 am
Hello everyone,
At first, I have to sorry for the Subject. I have more Topics I would like to talk about, but I dont want to open more than 1 topic on my first visit.
I am very new to this project. I also never used pfsense before.
Since the installation on "china Intel NUC like Hardware" everything works, but sometimes it doesn't work as expected.

Every day I check out a new service that should improve my homesecurity, since I am not that experienced with Firewall assets. I understand many of the basic features every IT admin should know..
Sometimes I encounter Problems where only opnsene is responsible for.

Problem 1: DHCP couldn't reprovide a lease my client used before. It worked after I changed my config, but it stopped when I had to reboot multiple times because of the next problem I want to mention.
I restarted my client, unplugged ethernet and much more, but the only thing that helped, was recovering opnsense from the last backup. Unfortunately there is no dhcpd.conf under /etc/ I could provide. Just the log...

Code: [Select]
May 18 12:54:39 Styx dhcpd: Database file: /var/db/dhcpd.leases
May 18 12:54:39 Styx dhcpd: PID file: /var/run/dhcpd.pid
May 18 12:54:39 Styx dhcpd: Internet Systems Consortium DHCP Server 4.4.2
May 18 12:54:39 Styx dhcpd: Copyright 2004-2020 Internet Systems Consortium.
May 18 12:54:39 Styx dhcpd: All rights reserved.
May 18 12:54:39 Styx dhcpd: For info, please visit https://www.isc.org/software/dhcp/
May 18 12:54:39 Styx dhcpd: Wrote 2 leases to leases file.
May 18 12:54:39 Styx dhcpd: Listening on BPF/igb2/00:90:27:e5:36:86/192.168.4.0/25
May 18 12:54:39 Styx dhcpd: Sending on   BPF/igb2/00:90:27:e5:36:86/192.168.4.0/25
May 18 12:54:39 Styx dhcpd: Listening on BPF/igb1/00:90:27:e5:36:85/192.168.1.0/24
May 18 12:54:39 Styx dhcpd: Sending on   BPF/igb1/00:90:27:e5:36:85/192.168.1.0/24
May 18 12:54:39 Styx dhcpd: Sending on   Socket/fallback/fallback-net
May 18 12:54:39 Styx dhcpd: Server starting service.
May 18 12:54:40 Styx dhcpd: reuse_lease: lease age 165 (secs) under 25% threshold, reply with unaltered, existing lease for 192.168.1.100
May 18 12:54:40 Styx dhcpd: DHCPDISCOVER from 00:50:b6:6e:b6:1a (Minerva) via igb1
May 18 12:54:40 Styx dhcpd: DHCPOFFER on 192.168.1.100 to 00:50:b6:6e:b6:1a (Minerva) via igb1
May 18 12:54:44 Styx dhcpd: reuse_lease: lease age 169 (secs) under 25% threshold, reply with unaltered, existing lease for 192.168.1.100
May 18 12:54:44 Styx dhcpd: DHCPREQUEST for 192.168.1.100 from 00:50:b6:6e:b6:1a (Minerva) via igb1
May 18 12:54:44 Styx dhcpd: DHCPACK on 192.168.1.100 to 00:50:b6:6e:b6:1a (Minerva) via igb1
May 18 12:54:46 Styx dhcpd: reuse_lease: lease age 171 (secs) under 25% threshold, reply with unaltered, existing lease for 192.168.1.100
May 18 12:54:46 Styx dhcpd: DHCPDISCOVER from 00:50:b6:6e:b6:1a (Minerva) via igb1
May 18 12:54:46 Styx dhcpd: DHCPOFFER on 192.168.1.100 to 00:50:b6:6e:b6:1a (Minerva) via igb1
May 18 12:54:48 Styx dhcpd: reuse_lease: lease age 173 (secs) under 25% threshold, reply with unaltered, existing lease for 192.168.1.100
May 18 12:54:48 Styx dhcpd: DHCPDISCOVER from 00:50:b6:6e:b6:1a (Minerva) via igb1
May 18 12:54:48 Styx dhcpd: DHCPOFFER on 192.168.1.100 to 00:50:b6:6e:b6:1a (Minerva) via igb1
May 18 12:54:51 Styx dhcpd: reuse_lease: lease age 176 (secs) under 25% threshold, reply with unaltered, existing lease for 192.168.1.100
May 18 12:54:51 Styx dhcpd: DHCPREQUEST for 192.168.1.100 from 00:50:b6:6e:b6:1a (Minerva) via igb1
May 18 12:54:51 Styx dhcpd: DHCPACK on 192.168.1.100 to 00:50:b6:6e:b6:1a (Minerva) via igb1
May 18 12:54:53 Styx dhcpd: reuse_lease: lease age 178 (secs) under 25% threshold, reply with unaltered, existing lease for 192.168.1.100

Problem 2: ntopng (The reason I had to restart)
Every time opnsense boots up, it tells me that it's unable to start ntopng and I have to set "ntopng_enable=YES" in /etc/rc.conf, or I have to set "onestart" instead of "start". But I have no clue where I can define onestart.
I had to do the same with c-icap and it worked by editing rc.conf. But for ntopng it doesn't. I still receive the same message everyday.

Problem 3: Unexpected sleep.
Yesterday I had the above mentioned problems, but today when I started my notebook, I wondered why I couldnt connect. Turned out, Opnsense just hibernated somehow. I have no idea where to investigate it. I am connected via ssh and dmesg or system.log isn't that helpful though...
Here a short cat from system.log:

Code: [Select]
ay 18 18:44:01 Styx dhcp6c[75522]: Sending Solicit

May 18 18:45:38 Styx opnsense: user ^[[C^[[A^[[2~^[[A^[[B^[[C^[[C could not authenticate for login. [using OPNsense\Auth\Services\System + OPNsense\Auth\Local]
May 18 18:45:48 Styx login: 1 LOGIN FAILURE ON ttyv0
May 18 18:45:48 Styx login: 1 LOGIN FAILURE ON ttyv0
May 18 18:45:48 Styx login: 1 LOGIN FAILURE ON ttyv0, ^[[C^[[A^[[2~^[[A^[[B^[[C^[[C
May 18 18:45:48 Styx login: 1 LOGIN FAILURE ON ttyv0, ^[[C^[[A^[[2~^[[A^[[B^[[C^[[C
May 18 18:45:49 Styx kernel: ugen0.3: <Fujitsu Fujitsu Keyboard> at usbus0 (disconnected)
May 18 18:45:49 Styx kernel: ukbd0: at uhub1, port 2, addr 3 (disconnected)
May 18 18:45:49 Styx kernel: ukbd0: detached
May 18 18:45:49 Styx kernel: uhid0: at uhub1, port 2, addr 3 (disconnected)
May 18 18:45:49 Styx kernel: uhid0: detached
May 18 18:45:50 Styx kernel:
May 18 18:45:50 Styx kernel: igb0: link state changed to DOWN
May 18 18:45:50 Styx opnsense: /usr/local/etc/rc.linkup: DEVD Ethernet detached event for wan
May 18 18:45:50 Styx dhclient[28598]: connection closed
May 18 18:45:50 Styx dhclient[28598]: exiting.
May 18 18:45:50 Styx opnsense: plugins_configure dhcp (,inet6,Array)
May 18 18:45:50 Styx opnsense: plugins_configure dhcp (execute task : dhcpd_dhcp_configure(,inet6,Array))
May 18 18:45:50 Styx dhcp6c[75522]: exiting
May 18 18:45:50 Styx opnsense: /usr/local/etc/rc.linkup: Clearing states for stale wan route on igb0
May 18 18:45:51 Styx kernel: ..done
May 18 18:45:51 Styx kernel:
May 18 18:45:51 Styx kernel: pflog0: promiscuous mode disabled
May 18 18:45:51 Styx kernel: pflog0: promiscuous mode enabled
May 18 18:45:51 Styx kernel: igb1: link state changed to DOWN
May 18 18:45:51 Styx opnsense: /usr/local/etc/rc.linkup: DEVD Ethernet detached event for lan
May 18 18:45:52 Styx kernel: pflog0: promiscuous mode disabled
May 18 18:45:52 Styx kernel: pflog0: promiscuous mode enabled
May 18 18:45:54 Styx kernel: igb0: link state changed to UP
May 18 18:45:55 Styx opnsense: /usr/local/etc/rc.linkup: DEVD Ethernet attached event for wan
May 18 18:45:55 Styx opnsense: /usr/local/etc/rc.linkup: HOTPLUG: Configuring interface wan
May 18 18:45:55 Styx dhclient: Starting delete_old_states()
May 18 18:45:55 Styx dhclient: Comparing IPs: Old: 192.168.2.65 New:
May 18 18:45:55 Styx dhclient: Removing states from old IP '192.168.2.65' (new IP '')
May 18 18:45:55 Styx dhclient[73956]: DHCPREQUEST on igb0 to 255.255.255.255 port 67
May 18 18:45:55 Styx dhclient[73956]: DHCPACK from 192.168.2.1
May 18 18:45:55 Styx dhclient: Starting delete_old_states()
May 18 18:45:55 Styx dhclient: Comparing IPs: Old: 192.168.2.65 New: 192.168.2.65
May 18 18:45:55 Styx dhclient: New IP Address (igb0): 192.168.2.65
May 18 18:45:55 Styx dhclient: New Subnet Mask (igb0): 255.255.255.0
May 18 18:45:55 Styx dhclient: New Broadcast Address (igb0): 192.168.2.255
May 18 18:45:55 Styx dhclient: New Routers (igb0): 192.168.2.1
May 18 18:45:55 Styx dhclient: route add default 192.168.2.1
May 18 18:45:55 Styx dhclient: Creating resolv.conf
May 18 18:45:55 Styx opnsense: /usr/local/etc/rc.newwanip: IP renewal is starting on 'igb0'
May 18 18:45:55 Styx opnsense: /usr/local/etc/rc.newwanip: On (IP address: 192.168.2.65) (interface: WAN[wan]) (real interface: igb0).
May 18 18:45:55 Styx kernel: igb1: link state changed to UP
May 18 18:45:55 Styx opnsense: plugins_configure hosts ()
May 18 18:45:55 Styx opnsense: plugins_configure hosts (execute task : dnsmasq_hosts_generate())
May 18 18:45:55 Styx opnsense: plugins_configure hosts (execute task : unbound_hosts_generate())
May 18 18:45:55 Styx opnsense: /usr/local/etc/rc.newwanip: ROUTING: entering configure using 'wan'
May 18 18:45:55 Styx opnsense: /usr/local/etc/rc.newwanip: ROUTING: IPv4 default gateway set to wan
May 18 18:45:55 Styx opnsense: /usr/local/etc/rc.newwanip: ROUTING: setting IPv4 default route to 192.168.2.1
May 18 18:45:55 Styx opnsense: /usr/local/etc/rc.newwanip: ROUTING: keeping current default gateway '192.168.2.1'
May 18 18:45:55 Styx opnsense: /usr/local/etc/rc.newwanip: ROUTING: IPv6 default gateway set to wan
May 18 18:45:55 Styx opnsense: /usr/local/etc/rc.newwanip: ROUTING: skipping IPv6 default route
May 18 18:45:55 Styx opnsense: plugins_configure monitor ()
May 18 18:45:55 Styx opnsense: plugins_configure monitor (execute task : dpinger_configure_do())
May 18 18:45:55 Styx opnsense: /usr/local/etc/rc.newwanip: Removing static route for monitor 192.168.1.252 via 192.168.2.1
May 18 18:45:55 Styx opnsense: /usr/local/etc/rc.newwanip: The WAN_DHCP6 monitor address is empty, skipping.
May 18 18:45:56 Styx opnsense: plugins_configure vpn (,wan)
May 18 18:45:56 Styx kernel: pflog0: promiscuous mode disabled
May 18 18:45:56 Styx kernel: pflog0: promiscuous mode enabled
May 18 18:45:56 Styx opnsense: plugins_configure vpn (execute task : ipsec_configure_do(,wan))
May 18 18:45:56 Styx opnsense: plugins_configure vpn (execute task : openvpn_configure_do(,wan))
May 18 18:45:56 Styx opnsense: plugins_configure newwanip (,wan)
May 18 18:45:56 Styx opnsense: plugins_configure newwanip (execute task : dyndns_configure_do(,wan))
May 18 18:45:56 Styx opnsense: plugins_configure newwanip (execute task : ntpd_configure_defer())
May 18 18:45:56 Styx opnsense: plugins_configure newwanip (execute task : opendns_configure_do())
May 18 18:45:57 Styx opnsense: opendns response : good 1.2.3.4
May 18 18:45:57 Styx opnsense: plugins_configure newwanip (execute task : openssh_configure_do(,wan))
May 18 18:45:57 Styx opnsense: plugins_configure newwanip (execute task : unbound_configure_do(,wan))
May 18 18:45:57 Styx opnsense: plugins_configure newwanip (execute task : vxlan_configure_interface())
May 18 18:45:57 Styx opnsense: plugins_configure newwanip (execute task : webgui_configure_do(,wan))
May 18 18:45:57 Styx dhclient[73956]: bound to 192.168.2.65 -- renewal in 432000 seconds.
May 18 18:45:57 Styx opnsense: /usr/local/etc/rc.linkup: Accept router advertisements on interface igb0
May 18 18:45:57 Styx dhcp6c: RTSOLD script - Starting dhcp6 client for interface wan(igb0)
May 18 18:45:57 Styx opnsense: /usr/local/etc/rc.linkup: ROUTING: entering configure using 'wan'
May 18 18:45:57 Styx opnsense: /usr/local/etc/rc.linkup: ROUTING: IPv4 default gateway set to wan
May 18 18:45:57 Styx opnsense: /usr/local/etc/rc.linkup: ROUTING: setting IPv4 default route to 192.168.2.1
May 18 18:45:57 Styx opnsense: /usr/local/etc/rc.linkup: ROUTING: keeping current default gateway '192.168.2.1'
May 18 18:45:57 Styx opnsense: /usr/local/etc/rc.linkup: ROUTING: IPv6 default gateway set to wan
May 18 18:45:57 Styx opnsense: /usr/local/etc/rc.linkup: ROUTING: skipping IPv6 default route
May 18 18:45:57 Styx opnsense: plugins_configure ipsec (,wan)
May 18 18:45:57 Styx opnsense: plugins_configure ipsec (execute task : ipsec_configure_do(,wan))
May 18 18:45:57 Styx opnsense: plugins_configure dhcp ()
May 18 18:45:57 Styx opnsense: plugins_configure dhcp (execute task : dhcpd_dhcp_configure())
May 18 18:45:57 Styx opnsense: /usr/local/etc/rc.linkup: Warning! dhcpd_dhcp4_configure() found no suitable IPv4 address on lan
May 18 18:45:58 Styx opnsense: /usr/local/etc/rc.linkup: Warning! dhcpd_radvd_configure(auto) found no suitable IPv6 address on igb1
May 18 18:45:58 Styx opnsense: plugins_configure dns ()
May 18 18:45:58 Styx opnsense: plugins_configure dns (execute task : dnsmasq_configure_do())
May 18 18:45:58 Styx opnsense: plugins_configure dns (execute task : unbound_configure_do())
May 18 18:45:58 Styx dhcp6c[52958]: Sending Solicit
May 18 18:45:59 Styx dhcp6c[52958]: Sending Solicit
May 18 18:46:01 Styx /send_telemetry.py: telemetry data collected 685 records in 0.30 seconds @2020-05-18 12:12:39.208819
May 18 18:46:01 Styx dhcp6c[52958]: Sending Solicit
May 18 18:46:03 Styx kernel: pflog0: promiscuous mode disabled
May 18 18:46:03 Styx kernel: pflog0: promiscuous mode enabled
May 18 18:46:03 Styx opnsense: /usr/local/etc/rc.linkup: DEVD Ethernet attached event for lan
May 18 18:46:03 Styx opnsense: /usr/local/etc/rc.linkup: HOTPLUG: Configuring interface lan
May 18 18:46:03 Styx dhcp6c[52958]: restarting
May 18 18:46:03 Styx opnsense: /usr/local/etc/rc.linkup: ROUTING: entering configure using 'lan'
May 18 18:46:03 Styx opnsense: /usr/local/etc/rc.linkup: ROUTING: IPv4 default gateway set to wan
May 18 18:46:03 Styx opnsense: /usr/local/etc/rc.linkup: ROUTING: skipping IPv4 default route
May 18 18:46:03 Styx opnsense: /usr/local/etc/rc.linkup: ROUTING: IPv6 default gateway set to wan
May 18 18:46:03 Styx opnsense: /usr/local/etc/rc.linkup: ROUTING: skipping IPv6 default route
May 18 18:46:03 Styx opnsense: plugins_configure ipsec (,lan)
May 18 18:46:03 Styx opnsense: plugins_configure ipsec (execute task : ipsec_configure_do(,lan))
May 18 18:46:04 Styx opnsense: plugins_configure dhcp ()
May 18 18:46:04 Styx opnsense: plugins_configure dhcp (execute task : dhcpd_dhcp_configure())
May 18 18:46:04 Styx dhcp6c[52958]: Sending Solicit
May 18 18:46:04 Styx opnsense: /usr/local/etc/rc.linkup: Warning! dhcpd_radvd_configure(auto) found no suitable IPv6 address on igb1
May 18 18:46:04 Styx opnsense: plugins_configure dns ()
May 18 18:46:04 Styx opnsense: plugins_configure dns (execute task : dnsmasq_configure_do())
May 18 18:46:04 Styx opnsense: plugins_configure dns (execute task : unbound_configure_do())
May 18 18:46:05 Styx dhcp6c[52958]: Sending Solicit
May 18 18:46:07 Styx dhcp6c[52958]: Sending Solicit
May 18 18:46:09 Styx kernel: .
May 18 18:46:09 Styx kernel:
May 18 18:46:09 Styx kernel: pflog0: promiscuous mode disabled
May 18 18:46:09 Styx kernel: pflog0: promiscuous mode enabled
May 18 18:46:11 Styx dhcp6c[52958]: Sending Solicit
May 18 18:46:14 Styx syslogd: exiting on signal 15
May 19 06:53:54 Styx syslogd: kernel boot file is /boot/kernel/kernel
May 19 06:53:54 Styx kernel: Copyright (c) 2013-2018 The HardenedBSD Project.
May 19 06:53:54 Styx kernel: Copyright (c) 1992-2018 The FreeBSD Project.

Problem 4: telemetry 403
My log is spammed with this error. (Seems like a client config problem, but I have no clue on how and why)

Code: [Select]
May 18 18:44:01 Styx /send_telemetry.py: telemetry data collected 685 records in 0.30 seconds @2020-05-18 12:12:39.208819
May 18 18:44:08 Styx /send_telemetry.py: unexpected result from https://opnsense.emergingthreats.net/api/v1/event (http_code 403)
May 18 18:45:01 Styx /send_telemetry.py: telemetry data collected 685 records in 0.31 seconds @2020-05-18 12:12:39.208819
May 18 18:45:30 Styx /send_telemetry.py: unexpected result from https://opnsense.emergingthreats.net/api/v1/event (http_code 403)

I appreciate any help here!
Thanks forward :)

Kind regards