openvpn icon indicating copy to clipboard operation
openvpn copied to clipboard

dco counter update at multi_close_instance() needs work

Open cron2 opened this issue 5 months ago • 1 comments

So we have this in the log:

2025-07-18 12:12:02 us=277382 cron2-freebsd-tc-amd64/udp4:193.149.48.172:53644 peer-id=1 SIGTERM[soft,delayed-exit] received, client-instance exiting
2025-07-18 12:12:02 us=277467 MULTI: multi_close_instance called
2025-07-18 12:12:02 us=277551 GERT: multi_close_instance, closing peer_id=1   (my doing)
2025-07-18 12:12:02 us=277677 dco_get_peer_stats_multi
2025-07-18 12:12:02 us=277990 dco_parse_peer_multi: parsing message...
2025-07-18 12:12:02 us=278083 dco_parse_peer_multi: cannot store DCO stats for peer 1
2025-07-18 12:12:02 us=278204 register signal: SIGTERM (close_context)
2025-07-18 12:12:02 us=278322 dco_del_peer: peer-id 1

which I read as "when we close an instance, we want to get a final counter value, write to stats file and everything, and then forget about everything" - but it seems the order of things is not right, and when we actually reach dco_get_peer_stats_multi(), the "peer-id=1" instance has already been destroyed - so the whole excercise is not very useful.

Can we fix that?

cron2 avatar Jul 18 '25 10:07 cron2

Jul 25 19:20:51 ubuntu2004 tun-udp-p2mp[186147]: cron2-freebsd-tc-amd64/udp6:193.149.48.172:59979 peer-id=2 UDPv6 READ [105] from [AF_INET6]::ffff:193.149.48.172:59979: P_CONTROL_V1 kid=3 [ ] pid=8040 DATA len=91
Jul 25 19:20:51 ubuntu2004 tun-udp-p2mp[186147]: cron2-freebsd-tc-amd64/udp6:193.149.48.172:59979 peer-id=2 CC-EEN exit message received by peer
Jul 25 19:20:51 ubuntu2004 tun-udp-p2mp[186147]: cron2-freebsd-tc-amd64/udp6:193.149.48.172:59979 peer-id=2 Delayed exit in 5 seconds
Jul 25 19:20:51 ubuntu2004 tun-udp-p2mp[186147]: cron2-freebsd-tc-amd64/udp6:193.149.48.172:59979 peer-id=2 UDPv6 WRITE [86] to [AF_INET6]::ffff:193.149.48.172:59979: P_ACK_V1 kid=3 [ ] DATA len=76
Jul 25 19:20:51 ubuntu2004 kernel: [294985.807129] tun1: sending keepalive to peer 0
Jul 25 19:20:51 ubuntu2004 kernel: [294985.807197] tun1: scheduling keepalive work: now=1753464061 next_run=1753464051 delta=10
Jul 25 19:20:56 ubuntu2004 kernel: [294990.787667] tun1: del peer 2
Jul 25 19:20:56 ubuntu2004 kernel: [294990.787700] tun1: deleting peer with id 2, reason 1
Jul 25 19:20:56 ubuntu2004 tun-udp-p2mp[186147]: cron2-freebsd-tc-amd64/udp6:193.149.48.172:59979 peer-id=2 register signal: SIGTERM (delayed-exit)
Jul 25 19:20:56 ubuntu2004 tun-udp-p2mp[186147]: cron2-freebsd-tc-amd64/udp6:193.149.48.172:59979 peer-id=2 SIGTERM[soft,delayed-exit] received, client-instance exiting
Jul 25 19:20:56 ubuntu2004 tun-udp-p2mp[186147]: dco_get_peer_stats_multi
Jul 25 19:20:56 ubuntu2004 tun-udp-p2mp[186147]: ovpn-dco: received netlink message type=31 cmd=3 flags=0x0002
Jul 25 19:20:56 ubuntu2004 tun-udp-p2mp[186147]: ovpn_handle_peer_multi: parsing message...
Jul 25 19:20:56 ubuntu2004 tun-udp-p2mp[186147]: dco_update_peer_stat / dco_read_bytes(0): 616144
Jul 25 19:20:56 ubuntu2004 tun-udp-p2mp[186147]: dco_update_peer_stat / dco_write_bytes(0): 626320
Jul 25 19:20:56 ubuntu2004 tun-udp-p2mp[186147]: dco_update_peer_stat / tun_read_bytes(0): 562992
Jul 25 19:20:56 ubuntu2004 tun-udp-p2mp[186147]: dco_update_peer_stat / tun_write_bytes(0): 568872
Jul 25 19:20:56 ubuntu2004 tun-udp-p2mp[186147]: ovpn-dco: received netlink message type=31 cmd=3 flags=0x0002
Jul 25 19:20:56 ubuntu2004 tun-udp-p2mp[186147]: ovpn_handle_peer_multi: parsing message...
Jul 25 19:20:56 ubuntu2004 tun-udp-p2mp[186147]: ovpn_handle_peer_multi: cannot store DCO stats for peer 2
Jul 25 19:20:56 ubuntu2004 tun-udp-p2mp[186147]: register signal: SIGTERM (close_context)
Jul 25 19:20:56 ubuntu2004 tun-udp-p2mp[186147]: dco_del_peer: peer-id 2
Jul 25 19:20:56 ubuntu2004 tun-udp-p2p-tls-sha256[186220]: dco_do_read
Jul 25 19:20:56 ubuntu2004 tun-udp-p2p-tls-sha256[186220]: ovpn-dco: received netlink message type=31 cmd=5 flags=0000
Jul 25 19:20:56 ubuntu2004 tun-udp-p2p-tls-sha256[186220]: ovpn-dco: ignoring message for foreign ifindex 982
Jul 25 19:20:56 ubuntu2004 tun-udp-p2mp[186147]: ovpn-dco: received netlink message type=31 cmd=5 flags=0000
Jul 25 19:20:56 ubuntu2004 tun-udp-p2mp[186147]: ovpn-dco: received CMD_PEER_DEL_NTF, ifindex: 982, peer-id 2, reason: 1
Jul 25 19:20:56 ubuntu2004 tun-udp-p2mp[186147]: Sent warning SSL alert: close notify

easy to trigger with an incoming EEN - we proclaim that we kill the instance, then we go out and try to get final counters, but the instance is already gone, so we register another SIGTERM which is all a bit silly... (this is on master + 1100, with my (%d), id debugging enhancement)

cron2 avatar Jul 25 '25 17:07 cron2