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.
