Hi Nikos, #A. I haven't came across such issues recently, while here is an old problem perhaps you could help me somehow. That is the ocserv sometimes just "temporarily closing session" when the just operates a manual disconnection immediately after a successful connection. #B. BTW a tricky way I try to implement to avoid acct-stop-time problems, is to modify the count query in freeradius to count distinct frameipaddress, because a device typically will launch a new session using the same local IP even with stall sessions before. However there are two defects: #1. the ocserv doesn't seem to send frameipaddress to the radius server in the initial connection. #2. A device might have more than one IP especially when it can connect with different ocserv instances in one server, such as ocserv1(office)(192.168.1.0/24), ocserv2(R&D)(10.10.0.0/24). My idea to deal with #2 defect is to assign them with one IP pool with ip-lease option. Is there going to be some unexpected risks? #C. Is it possible to invalidate cookies when the admin disconnects manually certain IP/ID via occtl? Because when I checked the problem with specified clients, they mobile devices may still try to connect the server using cookies automatically. Then I have to block that IP for a moment from iptables. Here is the log for #A: Jan 6 16:12:50 asian ocserv[10361]: worker: accepted connection Jan 6 16:12:50 asian ocserv[10361]: worker: tlslib.c:384: no certificate was found Jan 6 16:12:50 asian ocserv[10250]: sec-mod: received request from pid 10361 and uid 65534 Jan 6 16:12:50 asian ocserv[10250]: sec-mod: cmd [size=261] sm: decrypt Jan 6 16:12:50 asian ocserv[10361]: worker: sending message 'resume data store request' to main Jan 6 16:12:50 asian ocserv[10249]: main: 1xx.9x.x4.1x:56682 main received message 'resume data store request' of 337 bytes Jan 6 16:12:50 asian ocserv[10249]: main: 1xx.9x.x4.1x:56682 TLS session DB storing a1812a5f7e1321fe52ab992c18570205c2391ec6641cb8424023cadc5550b678 Jan 6 16:12:50 asian ocserv[10361]: worker: TLS handshake completed Jan 6 16:12:50 asian ocserv[10361]: worker: sending message 'session info' to main Jan 6 16:12:50 asian ocserv[10249]: main: 1xx.9x.x4.1x:56682 main received message 'session info' of 6 bytes Jan 6 16:12:50 asian ocserv[10361]: worker: 1xx.9x.x4.1x HTTP processing: Host: ********* Jan 6 16:12:50 asian ocserv[10361]: worker: 1xx.9x.x4.1x HTTP processing: User-Agent: Cisco AnyConnect VPN Agent for Apple iPhone 4.0.03016 Jan 6 16:12:50 asian ocserv[10361]: worker: 1xx.9x.x4.1x User-agent: 'Cisco AnyConnect VPN Agent for Apple iPhone 4.0' Jan 6 16:12:50 asian ocserv[10361]: worker: 1xx.9x.x4.1x HTTP processing: Cookie: webvpn=0a7gr/***** Jan 6 16:12:50 asian ocserv[10361]: worker: 1xx.9x.x4.1x HTTP processing: X-CSTP-Version: 1 Jan 6 16:12:50 asian ocserv[10361]: worker: 1xx.9x.x4.1x HTTP processing: X-CSTP-Hostname: iPhone-4S Jan 6 16:12:50 asian ocserv[10361]: worker: 1xx.9x.x4.1x HTTP processing: X-CSTP-MTU: 1500 Jan 6 16:12:50 asian ocserv[10361]: worker: 1xx.9x.x4.1x HTTP processing: X-CSTP-Address-Type: IPv6,IPv4 Jan 6 16:12:50 asian ocserv[10361]: worker: 1xx.9x.x4.1x HTTP processing: X-CSTP-License: mobile Jan 6 16:12:50 asian ocserv[10361]: worker: 1xx.9x.x4.1x HTTP processing: X-AnyConnect-Identifier-ClientVersion: 4.0.03016 Jan 6 16:12:50 asian ocserv[10361]: worker: 1xx.9x.x4.1x HTTP processing: X-AnyConnect-Identifier-Platform: apple-ios Jan 6 16:12:50 asian ocserv[10361]: worker: 1xx.9x.x4.1x HTTP processing: X-AnyConnect-Identifier-PlatformVersion: 7.1.2 Jan 6 16:12:50 asian ocserv[10361]: worker: 1xx.9x.x4.1x HTTP processing: X-AnyConnect-Identifier-DeviceType: iPhone4,1 Jan 6 16:12:50 asian ocserv[10361]: worker: 1xx.9x.x4.1x HTTP processing: X-AnyConnect-Identifier-Device-UniqueID: 55307d20b7d8b69b04f3d9a99f5d06d72e3b384b Jan 6 16:12:50 asian ocserv[10361]: worker: 1xx.9x.x4.1x HTTP processing: X-AnyConnect-Identifier-Device-MacAddress: unknown Jan 6 16:12:50 asian ocserv[10361]: worker: 1xx.9x.x4.1x HTTP processing: X-AnyConnect-Identifier-Device-Imei: UNKNOWN:unknown Jan 6 16:12:50 asian ocserv[10361]: worker: 1xx.9x.x4.1x HTTP processing: X-DTLS-Master-Secret: DD5AB4B356A42218A61EDDB1A5FD500C145FFB35E31402FDDDECFACB99F333F7BD0E8349DB443DE6A6A2A0CB9475EC72 Jan 6 16:12:50 asian ocserv[10361]: worker: 1xx.9x.x4.1x HTTP processing: X-DTLS-CipherSuite: AES256-SHA:AES128-SHA:DES-CBC3-SHA Jan 6 16:12:50 asian ocserv[10361]: worker: 1xx.9x.x4.1x HTTP processing: X-DTLS-Accept-Encoding: lzs Jan 6 16:12:50 asian ocserv[10361]: worker: 1xx.9x.x4.1x HTTP processing: X-DTLS-Header-Pad-Length: 0 Jan 6 16:12:50 asian ocserv[10361]: worker: 1xx.9x.x4.1x HTTP processing: X-CSTP-Accept-Encoding: lzs,deflate Jan 6 16:12:50 asian ocserv[10361]: worker: 1xx.9x.x4.1x HTTP processing: X-CSTP-Protocol: Copyright (c) 2004 Cisco Systems, Inc. Jan 6 16:12:50 asian ocserv[10361]: worker: 1xx.9x.x4.1x HTTP processing: X-CSTP-TCP-Keepalive: false Jan 6 16:12:50 asian ocserv[10361]: worker: 1xx.9x.x4.1x HTTP CONNECT /CSCOSSLC/tunnel Jan 6 16:12:50 asian ocserv[10361]: worker: 1xx.9x.x4.1x sending message 'auth cookie request' to main Jan 6 16:12:50 asian ocserv[10249]: main: 1xx.9x.x4.1x:56682 main received message 'auth cookie request' of 84 bytes Jan 6 16:12:50 asian ocserv[10249]: main[admin]: 1xx.9x.x4.1x:56682 sending msg sm: session open to sec-mod Jan 6 16:12:50 asian ocserv[10250]: sec-mod: received request sm: session open Jan 6 16:12:50 asian ocserv[10250]: sec-mod: cmd [size=108] sm: session open Jan 6 16:12:50 asian ocserv[10250]: radius-auth: opening session WedSfn6rJt83i10DhRuIPQ== Jan 6 16:12:50 asian ocserv[10250]: sec-mod: initiating session for user 'admin' (session: WedSf) Jan 6 16:12:50 asian ocserv[10249]: main[admin]: 1xx.9x.x4.1x:56682 new user session Jan 6 16:12:50 asian ocserv[10249]: main[admin]: 1xx.9x.x4.1x:56682 selected IP: 192.168.1.165 Jan 6 16:12:53 asian ocserv[10249]: main: pinged 192.168.1.165 and is not in use Jan 6 16:12:53 asian ocserv[10249]: main[admin]: 1xx.9x.x4.1x:56682 assigned IPv4: 192.168.1.165 Jan 6 16:12:53 asian ocserv[10249]: main[admin]: 1xx.9x.x4.1x:56682 assigning tun device ocserv-vpn1 Jan 6 16:12:53 asian ocserv[10249]: main[admin]: 1xx.9x.x4.1x:56682 user of group '[unknown]' authenticated (using cookie) Jan 6 16:12:53 asian ocserv[10249]: main[admin]: 1xx.9x.x4.1x:56682 sending (socket) message 2 to worker Jan 6 16:12:53 asian ocserv[10249]: main[admin]: 1xx.9x.x4.1x:56682 user logged in Jan 6 16:12:53 asian ocserv[10361]: worker: 1xx.9x.x4.1x received auth reply message (value: 1) Jan 6 16:12:53 asian ocserv[10361]: worker[admin]: 1xx.9x.x4.1x suggesting DPD of 190 secs Jan 6 16:12:53 asian ocserv[10361]: worker[admin]: 1xx.9x.x4.1x TCP MSS is 1427 Jan 6 16:12:53 asian ocserv[10361]: worker[admin]: 1xx.9x.x4.1x reducing MTU due to TCP MSS to 1427 Jan 6 16:12:53 asian ocserv[10361]: worker[admin]: 1xx.9x.x4.1x CSTP Base MTU is 1427 bytes Jan 6 16:12:53 asian ocserv[10361]: worker[admin]: 1xx.9x.x4.1x sending IPv4 192.168.1.165 Jan 6 16:12:53 asian ocserv[10361]: worker[admin]: 1xx.9x.x4.1x Exclude route 192.168.0.0/255.255.0.0 Jan 6 16:12:53 asian ocserv[10361]: worker[admin]: 1xx.9x.x4.1x DTLS ciphersuite: AES128-SHA Jan 6 16:12:53 asian ocserv[10361]: worker[admin]: 1xx.9x.x4.1x DTLS overhead is 94 Jan 6 16:12:53 asian ocserv[10361]: worker[admin]: 1xx.9x.x4.1x suggesting DTLS MTU 1333 Jan 6 16:12:53 asian ocserv[10361]: worker[admin]: 1xx.9x.x4.1x sending message 'tun mtu change' to main Jan 6 16:12:53 asian ocserv[10249]: main[admin]: 1xx.9x.x4.1x:56682 main received message 'tun mtu change' of 3 bytes Jan 6 16:12:53 asian ocserv[10249]: main[admin]: 1xx.9x.x4.1x:56682 setting ocserv-vpn1 MTU to 1333 Jan 6 16:12:53 asian ocserv[10361]: worker[admin]: 1xx.9x.x4.1x setting MTU to 1333 Jan 6 16:12:54 asian ocserv[10249]: main: new DTLS session from 1xx.9x.x4.1x:50115 (record v1.0, hello v1.0) Jan 6 16:12:54 asian ocserv[10249]: main[admin]: 1xx.9x.x4.1x:56682 sending (socket) message 10 to worker Jan 6 16:12:54 asian ocserv[10249]: main[admin]: 1xx.9x.x4.1x:56682 passed UDP socket from 1xx.9x.x4.1x:50115 Jan 6 16:12:54 asian ocserv[10361]: worker[admin]: 1xx.9x.x4.1x worker received message udp fd of 103 bytes Jan 6 16:12:54 asian ocserv[10361]: worker[admin]: 1xx.9x.x4.1x received new UDP fd and connected to peer Jan 6 16:12:54 asian ocserv[10361]: worker[admin]: 1xx.9x.x4.1x setting up DTLS connection Jan 6 16:12:54 asian ocserv[10249]: main: 1xx.9x.x4.1x:56679 command socket closed Jan 6 16:12:54 asian ocserv[10249]: main: 1xx.9x.x4.1x:56679 user disconnected Jan 6 16:12:54 asian ocserv[10361]: worker[admin]: 1xx.9x.x4.1x sending message 'tun mtu change' to main Jan 6 16:12:54 asian ocserv[10249]: main[admin]: 1xx.9x.x4.1x:56682 main received message 'tun mtu change' of 3 bytes Jan 6 16:12:54 asian ocserv[10249]: main[admin]: 1xx.9x.x4.1x:56682 setting ocserv-vpn1 MTU to 1333 Jan 6 16:12:54 asian ocserv[10361]: worker[admin]: 1xx.9x.x4.1x setting MTU to 1333 Jan 6 16:12:54 asian ocserv[10361]: worker[admin]: 1xx.9x.x4.1x DTLS handshake completed (plaintext MTU: 1333) Jan 6 16:12:54 asian ocserv[10361]: worker[admin]: 1xx.9x.x4.1x sending message 'session info' to main Jan 6 16:12:54 asian ocserv[10249]: main[admin]: 1xx.9x.x4.1x:56682 main received message 'session info' of 124 bytes Jan 6 16:12:57 asian ocserv[10361]: worker[admin]: 1xx.9x.x4.1x received BYE packet; exiting Jan 6 16:12:58 asian ocserv[10249]: main[admin]: 1xx.9x.x4.1x:56682 command socket closed Jan 6 16:12:58 asian ocserv[10249]: main[admin]: 1xx.9x.x4.1x:56682 user disconnected Jan 6 16:12:58 asian ocserv[10249]: main[admin]: 1xx.9x.x4.1x:56682 sending msg sm: session close to sec-mod Jan 6 16:12:58 asian ocserv[10250]: sec-mod: received request sm: session close Jan 6 16:12:58 asian ocserv[10250]: sec-mod: cmd [size=24] sm: session close Jan 6 16:12:58 asian ocserv[10250]: sec-mod: temporarily closing session for admin (session: WedSf) 2016-01-01 17:45 GMT+08:00 Nikos Mavrogiannopoulos <n.mavrogiannopoulos at gmail.com>: > On Thu, Dec 31, 2015 at 5:34 PM, Yick Xie <yick.xie at gmail.com> wrote: >> Hi everybody, >> Happy New Year! >> Here I found the ocserv sometimes failed to send "closing session" >> messages to the radius server, typically after the server did not >> receive DPD messages for a long time. It happened many times using >> ocserv-0.10.9 on my 3 servers. When I tried to disconnect this user >> via occtl, the occtl still displayed such user afterward. The only way >> I can do is to kill or stop the ocserv and clean stale sessions in the >> radius SQL. I set mobile-dpd to 600 and cookie to 1800, while the >> client was supposed to be android openconnect yet not 100% guarantee. >> Please check my latest logs. >> LOG1: >> LOG2: > > Hello Yick, > The logs are for multiple sessions and it is not clear which worker > has stuck. When you have a worker which is stuck like that do the > following: > > 1. run occtl show id xxx #(the id shown by occtl show users) > > 2. grep the log for the ID of the session (it corresponds to PID) > > 3. run > # gdb /usr/bin/ocserv xxx (again the ID) > bt full > > 4. post the logs and output of the previous commands. > > regards, > Nikos
