fail to send close messages to the radius server

Yick Xie yick.xie at gmail.com
Wed Jan 6 01:10:35 PST 2016 

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

More information about the openconnect-devel mailing list