oscserv error: "could not determine the owner of received UDP packet"

[İsmail Dönmez]

Hi,

On Mon, Nov 10, 2014 at 5:05 PM, Nikos Mavrogiannopoulos
<n.mavrogiannopoulos at gmail.com> wrote:
> On Mon, Nov 10, 2014 at 3:37 PM, İsmail Dönmez <ismail at donmez.ws> wrote:
>> Hi,
>>
>> I am using NetworkManager-openconnect (version 0.9.10.0) against
>> ocserv.git and after being connected for like ~30 minutes VPN stops
>> accepting any packets. Turns out that there is some weird stuff going
>> on.
>
> Hello,
>  From the log that you sent it seems that your firewall discarded the
> previous UDP session association. That is the new UDP traffic is being
> received from a different port, and the main server is now receiving
> the UDP traffic. This is harmless, as ocserv will forward the new
> session to worker.
>
>> Looking at the attached log first connection happens at 14:11:12 and
>> even though I don't click anything from the UI to reconnect etc a new
>> connection starts at 14:25:56 and this wreaks havoc. I am not sure if
>> this is a client bug or a server one.
>
> That is when the main process received the new session and forwarded
> it to the worker process, the worker process believed the previous was
> active (received some message from the previous session the last 30
> seconds). That should cancel out after 30 seconds. I've reduced the
> severity of these messages to avoid spamming the log.

This sounds fine but it never recovers it seems, here is the log when
openconnect clients detect the connection as dead and reconnects:

Nov 12 14:04:25 i10z ocserv[57992]: worker: 212.156.31.134:3351
accepted connection
Nov 12 14:04:25 i10z ocserv[54496]: sec-mod: received request from pid
57992 and uid 65534
Nov 12 14:04:25 i10z ocserv[54496]: sec-mod: cmd [size=55] sm: sign
Nov 12 14:04:25 i10z ocserv[57992]: worker: 212.156.31.134:3351
sending message 'resume data store request' to main
Nov 12 14:04:25 i10z ocserv[54495]: main: 212.156.31.134:3351 main
received message 'resume data store request' of 370 bytes
Nov 12 14:04:25 i10z ocserv[54495]: main: 212.156.31.134:3351 TLS
session DB storing
704172649867259ed82fc0f9509d3f3f16faddcb16f285f7089763d1ed153734
Nov 12 14:04:25 i10z ocserv[57992]: worker: 212.156.31.134:3351 TLS
handshake completed
Nov 12 14:04:25 i10z ocserv[57992]: worker: 212.156.31.134:3351
User-agent: 'Open AnyConnect VPN Agent v6.00-214-g17a18f1'
Nov 12 14:04:25 i10z ocserv[57992]: worker: 212.156.31.134:3351
sending message 'auth cookie request' to main
Nov 12 14:04:25 i10z ocserv[54495]: main: 212.156.31.134:3351 main
received message 'auth cookie request' of 126 bytes
Nov 12 14:04:25 i10z ocserv[54495]: main: 212.156.31.134:3351[ismail]
reusing cookie for 'ismail' (57992)
Nov 12 14:04:25 i10z ocserv[54495]: main: 212.156.31.134:8023[ismail]
disconnecting 'ismail' (57971) due to new cookie connection
Nov 12 14:04:25 i10z ocserv[54495]: main: 212.156.31.134:3351[ismail]
accepting user 'ismail'
Nov 12 14:04:25 i10z ocserv[54495]: main: 212.156.31.134:3351[ismail]
assigned IPv4 to 'ismail': 10.10.0.121
Nov 12 14:04:25 i10z ocserv[57971]: worker:
212.156.31.134:8023[ismail] sending message 'cli stats' to main
Nov 12 14:04:25 i10z ocserv[57971]: worker:
212.156.31.134:8023[ismail] sending stats (in: 1739039, out: 19196827)
to main
Nov 12 14:04:25 i10z ocserv[54495]: main: 212.156.31.134:3351[ismail]
assigning tun device vpns1
Nov 12 14:04:25 i10z ocserv[54495]: main: 212.156.31.134:3351[ismail]
user 'ismail' of group 'ismail' authenticated (using cookie)
Nov 12 14:04:25 i10z ocserv[54495]: main: 212.156.31.134:3351[ismail]
sending (socket) message 2 to worker
Nov 12 14:04:25 i10z ocserv[54495]: main: 212.156.31.134:8023[ismail]
main received message 'cli stats' of 9 bytes
Nov 12 14:04:25 i10z ocserv[57992]: worker: 212.156.31.134:3351
received auth reply message (value: 1)
Nov 12 14:04:25 i10z ocserv[57992]: worker:
212.156.31.134:3351[ismail] suggesting DPD of 440 secs
Nov 12 14:04:25 i10z ocserv[57992]: worker:
212.156.31.134:3351[ismail] sending IPv4 10.10.0.121
Nov 12 14:04:25 i10z ocserv[57992]: worker:
212.156.31.134:3351[ismail] TCP MSS is 1435
Nov 12 14:04:25 i10z ocserv[57992]: worker:
212.156.31.134:3351[ismail] reducing MTU due to TCP MSS to 1435
Nov 12 14:04:25 i10z ocserv[57992]: worker:
212.156.31.134:3351[ismail] CSTP Base MTU is 1435 bytes
Nov 12 14:04:25 i10z ocserv[57992]: worker:
212.156.31.134:3351[ismail] DTLS ciphersuite: OC-DTLS1_2-AES128-GCM
Nov 12 14:04:25 i10z ocserv[57992]: worker:
212.156.31.134:3351[ismail] DTLS overhead is 66
Nov 12 14:04:25 i10z ocserv[57992]: worker:
212.156.31.134:3351[ismail] suggesting DTLS MTU 1369
Nov 12 14:04:25 i10z ocserv[57992]: worker:
212.156.31.134:3351[ismail] sending message 'tun mtu change' to main
Nov 12 14:04:25 i10z ocserv[54495]: main: 212.156.31.134:3351[ismail]
main received message 'tun mtu change' of 3 bytes
Nov 12 14:04:25 i10z ocserv[54495]: main: 212.156.31.134:3351[ismail]
setting vpns1 MTU to 1369
Nov 12 14:04:25 i10z ocserv[57992]: worker:
212.156.31.134:3351[ismail] setting MTU to 1369
Nov 12 14:04:25 i10z ocserv[57992]: worker:
212.156.31.134:3351[ismail] sending message 'session info' to main
Nov 12 14:04:25 i10z ocserv[54495]: main: 212.156.31.134:3351[ismail]
main received message 'session info' of 94 bytes
Nov 12 14:04:25 i10z ocserv[54495]: main: 212.156.31.134:8023[ismail]
main-misc.c:425: command socket closed
Nov 12 14:04:25 i10z ocserv[54495]: main: 212.156.31.134:8023[ismail]
removing client 'ismail' with id '57971'
Nov 12 14:04:25 i10z ocserv[54495]: main: new DTLS session from
212.156.31.134:37353 (record v254.253, hello v0.1)
Nov 12 14:04:25 i10z ocserv[54495]: main: 212.156.31.134:37353:
unexpected DTLS content type: 23; a firewall disassociated a UDP
session
Nov 12 14:04:25 i10z ocserv[54495]: main: 212.156.31.134:3351[ismail]
sending (socket) message 10 to worker
Nov 12 14:04:25 i10z ocserv[54495]: main: 212.156.31.134:3351[ismail]
passed UDP socket from 212.156.31.134:37353
Nov 12 14:04:25 i10z ocserv[57992]: worker:
212.156.31.134:3351[ismail] worker received message udp fd of 2 bytes
Nov 12 14:04:25 i10z ocserv[57992]: worker:
212.156.31.134:3351[ismail] received UDP fd message but our session is
active!
Nov 12 14:04:25 i10z ocserv[54495]: main: new DTLS session from
212.156.31.134:37353 (record v254.253, hello v0.1)
Nov 12 14:04:25 i10z ocserv[54495]: main: 212.156.31.134:37353:
unexpected DTLS content type: 23; a firewall disassociated a UDP
session


Nov 12 14:04:25 i10z ocserv[54495]: main: 212.156.31.134:3351[ismail]
received UDP connection too soon from 212.156.31.134:37353
Nov 12 14:04:25 i10z ocserv[54495]: main: 212.156.31.134:37353: too short packet
Nov 12 14:04:25 i10z ocserv[54495]: main: new DTLS session from
212.156.31.134:37353 (record v254.253, hello v0.1)
Nov 12 14:04:25 i10z ocserv[54495]: main: 212.156.31.134:37353:
unexpected DTLS content type: 23; a firewall disassociated a UDP
session

Now the last 4 lines are repeated forever and connection never
recovers. Using openconnect.git didn't help.
Using ocserv.git atm.