Messages

Code Select Expand

root@wellington:~ # sockstat -l | grep ':546'
root     dhcp6c     34498 8  udp6   *:546                 *:*
root     dhcp6c     29911 7  udp6   *:546                 *:*


Ok, no other process is listening on that port ... then I have no idea ... maybe a network trace helps  to see if the provider really offers you a prefix ...

Best regards,

     Jochen

Hi,

can you post the output of  the following command?

Code Select Expand

sockstat -l | grep ':546'

Best regards,

    Jochen

And if you are using OpenVPN ... please try to disable the OpenVPN service.

Whenever I boot up my OPNsense box or do an action that forces a save of the interfaces I have to stop the OpenVPN service. Then the router advertisements are received by dhcp6c and the IPv6 is then set on the LAN interface and apinger, ntpd and OpenVPN services are started again automatically afterwards.

@Franco: do you think there is an option to stop OpenVPN like ntpd and apinger are stopped until IPv6 is up and running? Or do you have an idea why OpenVPN is listening on port 546 and intercepts the packets that dhcp6c should get? See the issue I opened some time ago: https://github.com/opnsense/core/issues/1668.

Thanks,

    Jochen

Hi,

is there an option on the router to specify the prefix size that it can hand out? I am not sure if it's sufficient for OPNsense to get an address with /64 ... I would try /62 or /60 ...

Best regards,

    Jochen

Hi,

if you check the interfaces ... on which interface do you see an IPv6 address? Is it on WAN or LAN?

What messages do you see in the dhcp log?
Best regards,

    Jochen

The connection issue towards https://www.heise.de remains though ... http connection is possible (I see the redirect to https), https connection is not possible ... the last thing I see in a trace is the "CLIENT HELLO" of ssl. If I test via curl https from OPNsense it works, from LAN only http works.

To follow up on this as well ... I have found out why https connection was not possible to some sites ... once I had reduced the MTU on my Linux system to 1486 even the https connection works without issues. So I guess the PMTU discovery fails at some point ... since it works fine if I run the curl on the OPNsense box, could this be an issue in OPNsense?

Thanks and best regards,

    Space

Funny thing is: after OpenVPN was disabled and the interface got the IP from the Fritzbox ... there are lot's more processes listening on port 546:

Code Select Expand

root@OPNvirt:~ # sockstat -l -6 | grep :546
root     sleep      89181 8  udp6   *:546                 *:*
root     sh         47212 8  udp6   *:546                 *:*
root     radvd      30324 8  udp6   *:546                 *:*
dhcpd    dhcpd      26396 8  udp6   *:546                 *:*
root     dhcp6c     91012 8  udp6   *:546                 *:*


sleep and sh belong to this one:

Code Select Expand

root   47212   0.0  0.1 1078840   3168  -  Ss   14:01    0:00.06 |-- /bin/sh /var/db/rrd/updaterrd.sh
root   89181   0.0  0.1 1073972   2376  -  S    14:10    0:00.00 | `-- sleep 60


Not sure if all of them should be listening to :546 as well :)

Best regards,

    Jochen

Hm, could the issue be caused by OpenVPN also listening on 546?

Code Select Expand

root@OPNvirt:/var/log # sockstat -l | grep :546
root     dhcp6c     33878 5  udp6   *:546                 *:*
root     openvpn    22884 5  udp6   *:546                 *:*

EDIT: yes! I stopped OpenVPN and after next solicit IP address was immediately set!

Best regards,

    Jochen

The firewall logs show both packets as PASS:

Code Select Expand

Jun  2 11:24:28 OPNvirt filterlog: 53,,,0,em1,match,pass,out,6,0x00,0x00000,1,UDP,17,89,fe80::21f:29ff:fe59:d8b4,ff02::1:2,546,547,89
Jun  2 11:24:28 OPNvirt filterlog: 69,,,0,lo0,match,pass,in,6,0x00,0x00000,1,UDP,17,89,fe80::21f:29ff:fe59:d8b4,ff02::1:2,546,547,89
Jun  2 11:24:28 OPNvirt filterlog: 52,,,0,em1,match,pass,in,6,0x00,0x00000,64,UDP,17,134,fe80::2665:11ff:fe6c:3714,fe80::21f:29ff:fe59:d8b4,547,546,134

Best regards,

    Jochen

Ok, you can use something like truss ... so I traced it dhcp6c. It opens the following sockets / files

Code Select Expand

Following sockets/files are opened:

55890: socket(PF_LOCAL,SOCK_DGRAM|SOCK_CLOEXEC,0) = 3 (0x3)
55890: connect(3,{ AF_UNIX "/var/run/logpriv" },106) = 0 (0x0)

55890: socket(PF_INET6,SOCK_DGRAM,17)            = 4 (0x4)
55890: fcntl(4,F_GETFL,)                         = 2 (0x2)
55890: fcntl(4,F_SETFL,0x3)                      = 0 (0x0)
55890: bind(4,{ AF_INET6 [::]:546 },28)          = 0 (0x0)

55890: open("/var/etc/dhcp6c_wan.conf",O_RDONLY,0666) = 5 (0x5)
55890: ioctl(5,TIOCGETA,0x53dce490)              ERR#25 'Inappropriate ioctl for device'

And then you can see the following repeating all the time:

Code Select Expand

55959: clock_gettime(13,{ 1496394429.000000000 }) = 0 (0x0)
55959: getpid()                                  = 55959 (0xda97)
55959: sendto(3,"<30>Jun  2 11:07:09 dhcp6c[55959"...,50,0x0,NULL,0x0) = 50 (0x32)
55959: gettimeofday({ 1496394429.744324 },0x0)   = 0 (0x0)
55959: sendto(4,"\^A*a]\0\^A\0\^N\0\^A\0\^A\^_u"...,81,0x0,{ AF_INET6 [ff02::1:2]:547 },0x1c) = 81 (0x51)
55959: __sysctl(0x6a0c53dcdce0,0x6,0x0,0x6a0c53dcdcd8,0x0,0x0) = 0 (0x0)
55959: __sysctl(0x6a0c53dcdce0,0x6,0x46583c3d400,0x6a0c53dcdcd8,0x0,0x0) = 0 (0x0)
55959: gettimeofday({ 1496394429.744816 },0x0)   = 0 (0x0)
55959: select(5,{ 4 },0x0,0x0,{ 123.337096 })    = 0 (0x0)
55959: gettimeofday({ 1496394553.093143 },0x0)   = 0 (0x0)
55959: clock_gettime(13,{ 1496394553.000000000 }) = 0 (0x0)

Shouldn't it read sometimes from 4 as well if it did receive the Advertise packet? Maybe the advertise package really does not reach the dhcp6c.

Best regards,

     Jochen

I have compared the Advertise packages sent by the Fritzbox in the working and non-working case. The only difference (except of timestamps and stream IDs of Wireshark) is the transaction ID ...

So the Fritzbox sends the same response ... sometimes the dhcp6c answers with a REQUEST and sometimes not ...

How can we trace the packages that dhcp6c sees. Is there something like strace available to trace the dhcp6c client?

Best regards,

    Jochen

Hi,

maybe it has something to do with the lease time? Or with network packages being discarded before they reach the dhcp6c ... Trying to do some tests now ... Have noticed that the dhcp6c recovered after some time and got an address.

So I tried to reproduce the issue and clicked SAVE on WAN interface ... after about 1m it got it's new address (Network trace is available):

Code Select Expand

Jun  2 10:12:27 OPNvirt dhcp6c[88237]: Start address release
Jun  2 10:12:27 OPNvirt dhcp6c[88237]: Sending Release
Jun  2 10:12:27 OPNvirt dhcp6c[88237]: remove an address 2a03:f580:c883:bcfc:21f:29ff:fe59:d8b5/64 on em0
Jun  2 10:12:27 OPNvirt dhcp6c[88237]: dhcp6c Received RELEASE
Jun  2 10:12:27 OPNvirt dhcp6c[88237]: status code: success
Jun  2 10:12:27 OPNvirt dhcp6c[88237]: exiting
Jun  2 10:12:27 OPNvirt dhcp6c[31202]: failed to open /usr/local/etc/dhcp6cctlkey: No such file or directory
Jun  2 10:12:27 OPNvirt dhcp6c[31202]: failed initialize control message authentication
Jun  2 10:12:27 OPNvirt dhcp6c[31202]: skip opening control port
Jun  2 10:12:28 OPNvirt dhcp6c[31503]: Sending Solicit
Jun  2 10:12:29 OPNvirt dhcp6c[31503]: Sending Solicit
Jun  2 10:12:30 OPNvirt dhcpd: Internet Systems Consortium DHCP Server 4.3.5
Jun  2 10:12:30 OPNvirt dhcpd: Copyright 2004-2016 Internet Systems Consortium.
Jun  2 10:12:30 OPNvirt dhcpd: All rights reserved.
Jun  2 10:12:30 OPNvirt dhcpd: For info, please visit https://www.isc.org/software/dhcp/
Jun  2 10:12:30 OPNvirt dhcpd: Config file: /etc/dhcpd.conf
Jun  2 10:12:30 OPNvirt dhcpd: Database file: /var/db/dhcpd.leases
Jun  2 10:12:30 OPNvirt dhcpd: PID file: /var/run/dhcpd.pid
Jun  2 10:12:30 OPNvirt dhcpd: Internet Systems Consortium DHCP Server 4.3.5
Jun  2 10:12:30 OPNvirt dhcpd: Copyright 2004-2016 Internet Systems Consortium.
Jun  2 10:12:30 OPNvirt dhcpd: All rights reserved.
Jun  2 10:12:30 OPNvirt dhcpd: For info, please visit https://www.isc.org/software/dhcp/
Jun  2 10:12:30 OPNvirt dhcpd: Wrote 0 deleted host decls to leases file.
Jun  2 10:12:30 OPNvirt dhcpd: Wrote 0 new dynamic host decls to leases file.
Jun  2 10:12:30 OPNvirt dhcpd: Wrote 4 leases to leases file.
Jun  2 10:12:30 OPNvirt dhcpd: Listening on BPF/em0/00:1f:29:59:d8:b5/192.168.42.0/24
Jun  2 10:12:30 OPNvirt dhcpd: Sending on   BPF/em0/00:1f:29:59:d8:b5/192.168.42.0/24
Jun  2 10:12:30 OPNvirt dhcpd: Sending on   Socket/fallback/fallback-net
Jun  2 10:12:30 OPNvirt dhcpd: Server starting service.
Jun  2 10:12:31 OPNvirt dhcp6c[31503]: Sending Solicit
Jun  2 10:12:35 OPNvirt dhcp6c[31503]: Sending Solicit
Jun  2 10:12:43 OPNvirt dhcp6c[31503]: Sending Solicit
Jun  2 10:13:00 OPNvirt dhcp6c[31503]: Sending Solicit
Jun  2 10:13:32 OPNvirt dhcp6c[31503]: Sending Solicit
Jun  2 10:13:32 OPNvirt dhcp6c[31503]: unknown or unexpected DHCP6 option opt_86, len 16
Jun  2 10:13:33 OPNvirt dhcp6c[31503]: Sending Request
Jun  2 10:13:33 OPNvirt dhcp6c[31503]: unknown or unexpected DHCP6 option opt_86, len 16
Jun  2 10:13:33 OPNvirt dhcp6c[31503]: dhcp6c Received REQUEST
Jun  2 10:13:33 OPNvirt dhcp6c[31503]: add an address 2a03:f580:c883:bcfd:21f:29ff:fe59:d8b5/64 on em0


Since I could not match the timestamp in the trace to the logfile I wanted to do the same thing again with a specific action done at a specific time (to know the relative time in the trace) ... but now it's running for 15m without new address ...

Code Select Expand

[Jun  2 10:22:46 OPNvirt dhcp6c[31503]: Start address release
Jun  2 10:22:46 OPNvirt dhcp6c[31503]: Sending Release
Jun  2 10:22:46 OPNvirt dhcp6c[31503]: remove an address 2a03:f580:c883:bcfd:21f:29ff:fe59:d8b5/64 on em0
Jun  2 10:22:46 OPNvirt dhcp6c[31503]: dhcp6c Received RELEASE
Jun  2 10:22:46 OPNvirt dhcp6c[31503]: status code: success
Jun  2 10:22:46 OPNvirt dhcp6c[31503]: exiting
Jun  2 10:22:46 OPNvirt dhcp6c[84727]: failed to open /usr/local/etc/dhcp6cctlkey: No such file or directory
Jun  2 10:22:46 OPNvirt dhcp6c[84727]: failed initialize control message authentication
Jun  2 10:22:46 OPNvirt dhcp6c[84727]: skip opening control port
Jun  2 10:22:47 OPNvirt dhcp6c[84913]: Sending Solicit
Jun  2 10:22:48 OPNvirt dhcp6c[84913]: Sending Solicit
Jun  2 10:22:49 OPNvirt dhcpd: Internet Systems Consortium DHCP Server 4.3.5
Jun  2 10:22:49 OPNvirt dhcpd: Copyright 2004-2016 Internet Systems Consortium.
Jun  2 10:22:49 OPNvirt dhcpd: All rights reserved.
Jun  2 10:22:49 OPNvirt dhcpd: For info, please visit https://www.isc.org/software/dhcp/
Jun  2 10:22:49 OPNvirt dhcpd: Config file: /etc/dhcpd.conf
Jun  2 10:22:49 OPNvirt dhcpd: Database file: /var/db/dhcpd.leases
Jun  2 10:22:49 OPNvirt dhcpd: PID file: /var/run/dhcpd.pid
Jun  2 10:22:49 OPNvirt dhcpd: Internet Systems Consortium DHCP Server 4.3.5
Jun  2 10:22:49 OPNvirt dhcpd: Copyright 2004-2016 Internet Systems Consortium.
Jun  2 10:22:49 OPNvirt dhcpd: All rights reserved.
Jun  2 10:22:49 OPNvirt dhcpd: For info, please visit https://www.isc.org/software/dhcp/
Jun  2 10:22:49 OPNvirt dhcpd: Wrote 0 deleted host decls to leases file.
Jun  2 10:22:49 OPNvirt dhcpd: Wrote 0 new dynamic host decls to leases file.
Jun  2 10:22:49 OPNvirt dhcpd: Wrote 4 leases to leases file.
Jun  2 10:22:49 OPNvirt dhcpd: Listening on BPF/em0/00:1f:29:59:d8:b5/192.168.42.0/24
Jun  2 10:22:49 OPNvirt dhcpd: Sending on   BPF/em0/00:1f:29:59:d8:b5/192.168.42.0/24
Jun  2 10:22:49 OPNvirt dhcpd: Sending on   Socket/fallback/fallback-net
Jun  2 10:22:49 OPNvirt dhcpd: Server starting service.
Jun  2 10:22:50 OPNvirt dhcp6c[84913]: Sending Solicit
Jun  2 10:22:54 OPNvirt dhcp6c[84913]: Sending Solicit
Jun  2 10:23:02 OPNvirt dhcp6c[84913]: Sending Solicit
Jun  2 10:23:19 OPNvirt dhcp6c[84913]: Sending Solicit
Jun  2 10:23:51 OPNvirt dhcp6c[84913]: Sending Solicit
Jun  2 10:24:55 OPNvirt dhcp6c[84913]: Sending Solicit
Jun  2 10:26:54 OPNvirt dhcp6c[84913]: Sending Solicit
Jun  2 10:28:47 OPNvirt dhcp6c[84913]: Sending Solicit
Jun  2 10:30:50 OPNvirt dhcp6c[84913]: Sending Solicit
Jun  2 10:32:41 OPNvirt dhcp6c[84913]: Sending Solicit
Jun  2 10:34:42 OPNvirt dhcp6c[84913]: Sending Solicit
Jun  2 10:36:30 OPNvirt dhcp6c[84913]: Sending Solicit


Can I provide you the traces in some way?

Best regards,

    Jochen

Hi Franco,

hm, I asked because I did not see any related entries there ... but I am not sure if everything that is dropped is logged there ...

But even when I had disabled IPS it took a long time to renew the IPv6 address.

Best regards,

    Jochen

Hi Franco,

in which logfile can I check this? Because I also have this weird issue that e.g. heise.de does not work via https if I try the connection from LAN ... wondering if the SERVER_HELLO get's dropped by Suricata ...

Best regards,

    Jochen

Should I open an issue for this on github?

Thanks and best regards,

    Jochen