Hi Nikos,
Speaking of the devil, it comes. I just rechecked the server and found
the problem I mentioned in the first thread. The situation is far too
complicated than I imagined. This user got 2 stall session in this
ocserv instance, but only today's one was not set acct-stop-time in
the radius SQL. So I only had the today's log, sorry. As for the
record, the radius server only got messages until today 14:20, yet
actually the session was still active before 16:04:17, then again
nothing changed in the radius server. The radius server and ocserv
were deployed in one server.
> show users
id user group ip vpn-ip device
since dtls-cipher status
62297 user1 (none) 21x.14x.9x.7x oc-compat-vpn2
2h:06m (no dtls) connected
30080 user1 (none) 11x.21x.3x.x 10.x.1x.1xx oc-compat-vpn0
4days (no dtls) connected
> show id 30080
ID: 30080
Username: user1 Groupname: (none)
State: connected
Device: oc-compat-vpn0 MTU: 1358
Remote IP: 11x.21x.3x.x Local Device IP: *.*.*.*
IPv4: 10.x.1x.1xx P-t-P IPv4: 10.x.x.x
RX: 102489 (102.5 KB) TX: 809952 (810.0 KB)
Average bandwidth RX: 0 bytes/sec TX: 2 bytes/sec
Connected at: 2016-01-02 15:01 ( 4days)
DNS: 208.67.222.222
8.8.8.8
Routes: defaultroute
No-routes: 192.168.0.0/255.255.0.0
> show id 62297
ID: 62297
Username: user1 Groupname: (none)
State: connected
Device: oc-compat-vpn2 MTU: 1370
Remote IP: 21x.14x.9x.7x Local Device IP: *.*.*.*
RX: 838 (838 bytes) TX: 0 (0 bytes)
Average bandwidth RX: 0 bytes/sec TX: 0 bytes/sec
Connected at: 2016-01-06 16:02 ( 2h:07m)
DNS: 208.67.222.222
8.8.8.8
Routes: defaultroute
No-routes: 192.168.0.0/255.255.0.0
>
gdb /usr/bin/ocserv 30080
(gdb) bt full
#0 0x00007f9d0a80538d in __libc_recv (fd=0, buf=0x118ea96, n=154,
flags=-1) at ../sysdeps/unix/sysv/linux/x86_64/recv.c:29
resultvar = 18446744073709551104
oldtype = 18409920
#1 0x00007f9d0b570415 in _gnutls_stream_read (ms=0x7fff2fc283fc,
pull_func=0x7f9d0b58d790 <system_read>, size=288, bufel=<synthetic
pointer>, session=0x1177f40) at gnutls_buffers.c:341
left = 154
max_size = <optimized out>
t2 = {tv_sec = 15, tv_nsec = 140733994664891}
diff = <optimized out>
ptr = 0x118ea10
"\006\317UI8\241\255A\273\215y=\273\263\032\353\250\371\234\226L3?\002\212\313E\361Z\035\310k\227Sl?R!Iz\203\212\v\220
\203&Xmu4\236\071\216\267\232aONr
\363J7\274\217\213\232\035\253\370\060"
fd = 0x0
ret = <optimized out>
i = <optimized out>
t1 = {tv_sec = 15, tv_nsec = 4}
#2 _gnutls_read (ms=0x7fff2fc283fc, pull_func=0x7f9d0b58d790
<system_read>, size=288, bufel=<synthetic pointer>, session=0x1177f40)
at gnutls_buffers.c:421
No locals.
#3 _gnutls_io_read_buffered (session=session at entry=0x1177f40,
total=293, recv_type=<optimized out>, ms=ms at entry=0x7fff2fc283fc) at
gnutls_buffers.c:564
ret = <optimized out>
min = <optimized out>
bufel = 0x118e9c0
recvdata = 288
readsize = 288
#4 0x00007f9d0b56b24c in _gnutls_recv_in_buffers
(session=session at entry=0x1177f40,
type=type at entry=GNUTLS_APPLICATION_DATA, htype=htype at entry=4294967295,
ms=ms at entry=0)
at gnutls_record.c:1191
packet_sequence = 0x11877f0
ciphertext = {data = 0x1187500 "\001", size = 190228348}
bufel = <optimized out>
decrypted = 0x0
t = {data = 0x1187500 "\001", size = 175698073}
ret = <optimized out>
empty_fragments = 0
record_params = 0x1187500
record_state = 0x1187728
record = {header_size = 5, version = "\003\003", sequence = {i
= "\000\000\000\000\000\000\000"}, length = 288, packet_size = 293,
type = GNUTLS_APPLICATION_DATA, epoch = 0,
v2 = 0}
#5 0x00007f9d0b56c4cc in _gnutls_recv_int (session=0x1177f40,
type=GNUTLS_APPLICATION_DATA, htype=4294967295, packet=0x7fff2fc28588,
data=0x0, data_size=<optimized out>, seq=0x0, ms=0)
at gnutls_record.c:1439
ret = <optimized out>
ms = 0
seq = 0x0
data = 0x0
packet = 0x7fff2fc28588
type = GNUTLS_APPLICATION_DATA
data_size = <optimized out>
htype = 4294967295
session = 0x1177f40
#6 0x00007f9d0b56c96e in gnutls_record_recv_packet
(session=<optimized out>, packet=packet at entry=0x7fff2fc28588) at
gnutls_record.c:1519
No locals.
#7 0x000000000040b5eb in tls_mainloop (tnow=0x7fff2fc285a0,
ws=0x117ed30) at worker-vpn.c:1068
---Type <return> to continue, or q <return> to quit---
ret = <optimized out>
data = {data = 0x118a060 "\027\003\003\001
\326\nD)%\242\346jt\003", size = 245}
packet = 0x0
#8 connect_handler (ws=ws at entry=0x117ed30) at worker-vpn.c:1953
req = 0x117ed60
rfds = {fds_bits = {3, 0 <repeats 15 times>}}
e = <optimized out>
max = 12
ret = <optimized out>
t = 13580
p = <optimized out>
rnd = 2536214708
tv = {tv_sec = 10, tv_nsec = 0}
tls_pending = 0
dtls_pending = 0
i = <optimized out>
tnow = {tv_sec = 1451718149, tv_nsec = 919547788}
ip6 = <optimized out>
sl = 4
emptyset = {__val = {0 <repeats 16 times>}}
blockset = {__val = {16384, 0 <repeats 15 times>}}
#9 0x000000000040d2bc in vpn_server (ws=ws at entry=0x117ed30) at worker-vpn.c:571
buf = "CONNECT /CSCOSSLC/tunnel HTTP/1.1\r\nHost:
***.***.***.com\r\nUser-Agent: Cisco AnyConnect VPN Agent for Apple
iPhone 4.0.03016\r\nCookie:
webvpn=aKxN97SSqlZsRhHYe2QU67iHpDq3xJij"...
ret = <optimized out>
nparsed = <optimized out>
nrecvd = <optimized out>
session = 0x1177f40
parser = {type = 0, flags = 0, state = 18, header_state = 0,
index = 0, nread = 0, content_length = 18446744073709551615,
http_major = 1, http_minor = 1, status_code = 0,
method = 5, http_errno = 0, upgrade = 1, data = 0x117ed30}
settings = {on_message_begin = 0x0, on_url = 0x41d570
<http_url_cb>, on_status = 0x0, on_header_field = 0x41d5c0
<http_header_field_cb>,
on_header_value = 0x41d6d0 <http_header_value_cb>,
on_headers_complete = 0x41d7d0 <http_header_complete_cb>, on_body =
0x41d860 <http_body_cb>,
on_message_complete = 0x41d840 <http_message_complete_cb>}
fn = <optimized out>
requests_left = 15
#10 0x0000000000407b4a in main (argc=<optimized out>, argv=<optimized
out>) at main.c:1254
stype = 0
fd = 0
pid = <optimized out>
e = <optimized out>
ltmp = <optimized out>
ctmp = <optimized out>
cpos = <optimized out>
rd_set = {fds_bits = {16, 0 <repeats 15 times>}}
wr_set = {fds_bits = {0 <repeats 16 times>}}
n = <optimized out>
ret = <optimized out>
flags = <optimized out>
p = <optimized out>
---Type <return> to continue, or q <return> to quit---
ts = {tv_sec = 30, tv_nsec = 0}
cmd_fd = {11, 12}
ws = <optimized out>
worker_pool = <optimized out>
main_pool = <optimized out>
set = <optimized out>
s = 0x1170640
emptyset = {__val = {0 <repeats 16 times>}}
blockset = {__val = {90115, 0 <repeats 15 times>}}
creds = {xcred = 0x1171820, cprio = 0x11719f0, dh_params = 0x0}
gdb /usr/bin/ocserv 62297
(gdb)bt full
#0 0x00007f9d0a80538d in __libc_recv (fd=0, buf=0x118ea56, n=42,
flags=-1) at ../sysdeps/unix/sysv/linux/x86_64/recv.c:29
resultvar = 18446744073709551104
oldtype = 18409920
#1 0x00007f9d0b570415 in _gnutls_stream_read (ms=0x7fff2fc283fc,
pull_func=0x7f9d0b58d790 <system_read>, size=112, bufel=<synthetic
pointer>, session=0x1177f40) at gnutls_buffers.c:341
left = 42
max_size = <optimized out>
t2 = {tv_sec = 18382336, tv_nsec = 1}
diff = <optimized out>
ptr = 0x118ea10
"\037/29/q\225'\202=\215\033\304?y\301\244\026]m\370c\327??\373\346i\036\207\213\022\253l@\027\267\232\bn\016\065\354\336Y\263\217,i\017?=\355\064\067\061V
\003\301\350\002t\020\370\002\245\061\360\261\357o\350[$Pg=\017\247P\241\202\307u\237\356\351?@\272\337\367\213\367G8o\265\246\312\063\367\070\313\344\017\272\071\364\347m\a'\aGq\212\027\a
(\371)\332%/\fr5\273*\244\070-_\352W\f\220\262[6\375\026\242\025;\251\235?\345\307Ns\247?\332q\240Iu\201\323\303S\030u\352?\266hKP\314i&\360-\177\060\327H\307\063O\204?\367\341F"...
fd = 0x0
ret = <optimized out>
i = <optimized out>
t1 = {tv_sec = 18319360, tv_nsec = 0}
#2 _gnutls_read (ms=0x7fff2fc283fc, pull_func=0x7f9d0b58d790
<system_read>, size=112, bufel=<synthetic pointer>, session=0x1177f40)
at gnutls_buffers.c:421
No locals.
#3 _gnutls_io_read_buffered (session=session at entry=0x1177f40,
total=117, recv_type=<optimized out>, ms=ms at entry=0x7fff2fc283fc) at
gnutls_buffers.c:564
ret = <optimized out>
min = <optimized out>
bufel = 0x118e9c0
recvdata = 112
readsize = 112
#4 0x00007f9d0b56b24c in _gnutls_recv_in_buffers
(session=session at entry=0x1177f40,
type=type at entry=GNUTLS_APPLICATION_DATA, htype=htype at entry=4294967295,
ms=ms at entry=0)
at gnutls_record.c:1191
packet_sequence = 0x11877f0
ciphertext = {data = 0x21000 <error: Cannot access memory at
address 0x21000>, size = 179079096}
bufel = <optimized out>
decrypted = 0x0
t = {data = 0x20000 <error: Cannot access memory at address
0x20000>, size = 175698073}
ret = <optimized out>
empty_fragments = 0
record_params = 0x1187500
record_state = 0x1187728
record = {header_size = 5, version = "\003\003", sequence = {i
= "\000\000\000\000\000\000\000"}, length = 112, packet_size = 117,
type = GNUTLS_APPLICATION_DATA, epoch = 0,
v2 = 0}
#5 0x00007f9d0b56c4cc in _gnutls_recv_int (session=0x1177f40,
type=GNUTLS_APPLICATION_DATA, htype=4294967295, packet=0x7fff2fc28588,
data=0x0, data_size=<optimized out>, seq=0x0, ms=0)
at gnutls_record.c:1439
ret = <optimized out>
ms = 0
seq = 0x0
data = 0x0
packet = 0x7fff2fc28588
type = GNUTLS_APPLICATION_DATA
data_size = <optimized out>
htype = 4294967295
session = 0x1177f40
#6 0x00007f9d0b56c96e in gnutls_record_recv_packet
(session=<optimized out>, packet=packet at entry=0x7fff2fc28588) at
gnutls_record.c:1519
No locals.
---Type <return> to continue, or q <return> to quit---
#7 0x000000000040b5eb in tls_mainloop (tnow=0x7fff2fc285a0,
ws=0x117ed30) at worker-vpn.c:1068
ret = <optimized out>
data = {data = 0x118a060 "\027\003\003", size = 134}
packet = 0x0
#8 connect_handler (ws=ws at entry=0x117ed30) at worker-vpn.c:1953
req = 0x117ed60
rfds = {fds_bits = {1, 0 <repeats 15 times>}}
e = <optimized out>
max = 12
ret = <optimized out>
t = 13700
p = <optimized out>
rnd = 3151354389
tv = {tv_sec = 10, tv_nsec = 0}
tls_pending = 0
dtls_pending = 0
i = <optimized out>
tnow = {tv_sec = 1452067384, tv_nsec = 242553751}
ip6 = <optimized out>
sl = 4
emptyset = {__val = {0 <repeats 16 times>}}
blockset = {__val = {16384, 0 <repeats 15 times>}}
#9 0x000000000040d2bc in vpn_server (ws=ws at entry=0x117ed30) at worker-vpn.c:571
buf = "CONNECT /CSCOSSLC/tunnel HTTP/1.1\r\nHost:
***.***.***.com\r\nUser-Agent: Cisco AnyConnect VPN Agent for Apple
iPhone 4.0.03016\r\nCookie:
webvpn=SwgLw4LCr8SbANUg6YVlGxnRtNHTGKwq"...
ret = <optimized out>
nparsed = <optimized out>
nrecvd = <optimized out>
session = 0x1177f40
parser = {type = 0, flags = 0, state = 18, header_state = 0,
index = 0, nread = 0, content_length = 18446744073709551615,
http_major = 1, http_minor = 1, status_code = 0,
method = 5, http_errno = 0, upgrade = 1, data = 0x117ed30}
settings = {on_message_begin = 0x0, on_url = 0x41d570
<http_url_cb>, on_status = 0x0, on_header_field = 0x41d5c0
<http_header_field_cb>,
on_header_value = 0x41d6d0 <http_header_value_cb>,
on_headers_complete = 0x41d7d0 <http_header_complete_cb>, on_body =
0x41d860 <http_body_cb>,
on_message_complete = 0x41d840 <http_message_complete_cb>}
fn = <optimized out>
requests_left = 15
#10 0x0000000000407b4a in main (argc=<optimized out>, argv=<optimized
out>) at main.c:1254
stype = 0
fd = 0
pid = <optimized out>
e = <optimized out>
ltmp = <optimized out>
ctmp = <optimized out>
cpos = <optimized out>
rd_set = {fds_bits = {16, 0 <repeats 15 times>}}
wr_set = {fds_bits = {0 <repeats 16 times>}}
n = <optimized out>
ret = <optimized out>
flags = <optimized out>
---Type <return> to continue, or q <return> to quit---
p = <optimized out>
ts = {tv_sec = 30, tv_nsec = 0}
cmd_fd = {1, 12}
ws = <optimized out>
worker_pool = <optimized out>
main_pool = <optimized out>
set = <optimized out>
s = 0x1170640
emptyset = {__val = {0 <repeats 16 times>}}
blockset = {__val = {90115, 0 <repeats 15 times>}}
creds = {xcred = 0x1171820, cprio = 0x11719f0, dh_params = 0x0}
2016-01-06 11:22:22 2 hours, 58 minutes, 16 seconds
Jan 6 14:25:19 asain ocserv[60657]: worker[user1]: 22x.10x.x.20x
worker-vpn.c:1082: GnuTLS error (at worker-vpn.c:1082): The TLS
connection was non-properly terminated.
Jan 6 14:25:19 asain ocserv[19349]: main[user1]: 22x.10x.x.20x:13305
user disconnected
Jan 6 14:25:19 asain ocserv[19350]: radius-auth: sending session interim update
Jan 6 14:25:19 asain ocserv[19350]: sec-mod: temporarily closing
session for user1 (session: bdTxS)
Jan 6 14:25:24 asain ocserv[19350]: radius-auth: sending session interim update
Jan 6 14:27:01 asain ocserv[60706]: worker: tlslib.c:379: no
certificate was found
Jan 6 14:27:01 asain ocserv[19349]: main[user1]: 22x.10x.x.20x:3536
new user session
Jan 6 14:27:01 asain ocserv[19350]: sec-mod: initiating session for
user 'user1' (session: bdTxS)
Jan 6 14:27:04 asain ocserv[19349]: main: pinged 10.x.19x.6x and is not in use
Jan 6 14:27:04 asain ocserv[19349]: main[user1]: 22x.10x.x.20x:3536
user logged in
Jan 6 14:27:15 asain ocserv[60706]: worker[user1]: 22x.10x.x.20x
worker-vpn.c:1082: GnuTLS error (at worker-vpn.c:1082): The TLS
connection was non-properly terminated.
Jan 6 14:27:15 asain ocserv[19350]: radius-auth: sending session interim update
Jan 6 14:27:15 asain ocserv[19349]: main[user1]: 22x.10x.x.20x:3536
user disconnected
Jan 6 14:27:15 asain ocserv[19350]: sec-mod: temporarily closing
session for user1 (session: bdTxS)
Jan 6 14:27:23 asain ocserv[60722]: worker: tlslib.c:379: no
certificate was found
Jan 6 14:27:23 asain ocserv[19349]: main[user1]: 22x.10x.x.20x:11899
new user session
Jan 6 14:27:23 asain ocserv[19350]: sec-mod: initiating session for
user 'user1' (session: bdTxS)
Jan 6 14:27:26 asain ocserv[19349]: main: pinged 10.x.19x.6x and is not in use
Jan 6 14:27:26 asain ocserv[19349]: main[user1]: 22x.10x.x.20x:11899
user logged in
Jan 6 14:28:35 asain ocserv[60732]: worker: tlslib.c:379: no
certificate was found
Jan 6 14:28:36 asain ocserv[19349]: main[user1]: 22x.10x.x.23x:27109
re-using session
Jan 6 14:28:36 asain ocserv[19349]: main[user1]: 22x.10x.x.23x:27109
user logged in
Jan 6 14:28:36 asain ocserv[19349]: main[user1]: 22x.10x.x.20x:11899
user disconnected
Jan 6 14:28:36 asain ocserv[19350]: sec-mod: initiating session for
user 'user1' (session: bdTxS)
Jan 6 14:28:36 asain ocserv[19350]: radius-auth: sending session interim update
.....................................................................
Jan 6 15:57:37 asain ocserv[19349]: main[user1]: 22x.10x.x.23x:7587
user disconnected
Jan 6 15:57:37 asain ocserv[19350]: radius-auth: sending session interim update
Jan 6 15:57:37 asain ocserv[19350]: sec-mod: temporarily closing
session for user1 (session: bdTxS)
Jan 6 15:57:39 asain ocserv[62240]: worker: tlslib.c:379: no
certificate was found
Jan 6 15:57:39 asain ocserv[19349]: main[user1]: 21x.14x.9x.7x:64991
new user session
Jan 6 15:57:39 asain ocserv[19350]: sec-mod: initiating session for
user 'user1' (session: bdTxS)
Jan 6 15:57:42 asain ocserv[19349]: main: pinged 10.x.19x.6x and is not in use
Jan 6 15:57:42 asain ocserv[19349]: main[user1]: 21x.14x.9x.7x:64991
user logged in
Jan 6 16:01:04 asain ocserv[19350]: radius-auth: sending session interim update
Jan 6 16:01:52 asain ocserv[62240]: worker[user1]: 21x.14x.9x.7x
worker-vpn.c:1082: GnuTLS error (at worker-vpn.c:1082): The TLS
connection was non-properly terminated.
Jan 6 16:01:52 asain ocserv[19349]: main[user1]: 21x.14x.9x.7x:64991
user disconnected
Jan 6 16:01:52 asain ocserv[19350]: radius-auth: sending session interim update
Jan 6 16:01:52 asain ocserv[19350]: sec-mod: temporarily closing
session for user1 (session: bdTxS)
Jan 6 16:02:58 asain ocserv[62297]: worker: tlslib.c:379: no
certificate was found
Jan 6 16:02:58 asain ocserv[19349]: main[user1]: 21x.14x.9x.7x:65060
new user session
Jan 6 16:02:58 asain ocserv[19350]: sec-mod: initiating session for
user 'user1' (session: bdTxS)
Jan 6 16:03:01 asain ocserv[19349]: main: pinged 10.x.19x.6x and is not in use
Jan 6 16:03:01 asain ocserv[19349]: main[user1]: 21x.14x.9x.7x:65060
user logged in
Jan 6 16:03:23 asain ocserv[62307]: worker: tlslib.c:379: no
certificate was found
Jan 6 16:03:23 asain ocserv[19349]: main[user1]: 22x.10x.x.23x:22780
re-using session
Jan 6 16:03:23 asain ocserv[19349]: main[user1]: 22x.10x.x.23x:22780
user logged in
Jan 6 16:03:23 asain ocserv[19350]: sec-mod: initiating session for
user 'user1' (session: bdTxS)
Jan 6 16:04:17 asain ocserv[19350]: radius-auth: sending session interim update
Jan 6 16:04:17 asain ocserv[19349]: main[user1]: 22x.10x.x.23x:22780
user disconnected
2016-01-06 17:10 GMT+08:00 Yick Xie <yick.xie at gmail.com>:
> 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
