fail to send close messages to the radius server

[Yick Xie]

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:

Dec 31 17:57:11 asian ocserv[4473]: main[user1]: 12x.1xx.x44.x0:28081
re-using session
Dec 31 17:17:53 asian ocserv[4474]: radius-auth: sending session interim update
Dec 31 17:57:11 asian ocserv[4474]: sec-mod: initiating session for
user 'user1' (session: x+5c2)
Dec 31 17:57:14 asian ocserv[4473]: main: pinged 10.10.0.173 and is not in use
Dec 31 17:57:14 asian ocserv[4473]: main[user1]: 12x.1xx.x44.x0:28081
user logged in
Dec 31 17:59:16 asian ocserv[15461]: worker:  tlslib.c:379: no
certificate was found
Dec 31 17:59:16 asian ocserv[4456]: main: 11*.1*2.1*.*3:5713 user disconnected
Dec 31 18:00:32 asian ocserv[4474]: radius-auth: sending session interim update
Dec 31 18:01:21 asian ocserv[15381]: worker[user2]: 3x.x87.xx0.x5
worker-vpn.c:824: have not received TCP DPD for long (1214 secs)
Dec 31 18:01:42 asian ocserv[15443]: worker[user1]: 12x.1xx.x44.x0
worker-vpn.c:824: have not received TCP DPD for long (210 secs)
Dec 31 18:02:01 asian ocserv[15381]: worker[user2]: 3x.x87.xx0.x5
worker-vpn.c:824: have not received TCP DPD for long (1254 secs)
Dec 31 18:02:01 asian ocserv[4468]: main[user2]: 3x.x87.xx0.x5:51060
ioctl SIOCSIFMTU error: Invalid argument
Dec 31 18:02:12 asian ocserv[15443]: worker[user1]: 12x.1xx.x44.x0
worker-vpn.c:824: have not received TCP DPD for long (240 secs)
Dec 31 18:02:31 asian ocserv[15381]: worker[user2]: 3x.x87.xx0.x5
worker-vpn.c:824: have not received TCP DPD for long (1284 secs)
Dec 31 18:02:52 asian ocserv[15443]: worker[user1]: 12x.1xx.x44.x0
worker-vpn.c:824: have not received TCP DPD for long (280 secs)
Dec 31 18:02:52 asian ocserv[15443]: worker[user1]: 12x.1xx.x44.x0
worker-vpn.c:839: have not received TCP DPD for very long; tearing
down connection
Dec 31 18:02:52 asian ocserv[4473]: main[user1]: 12x.1xx.x44.x0:28081
user disconnected

LOG2:

Dec 31 12:16:10 US-LA ocserv[25498]: worker[user3]: 2*0.*02.1*2.2
worker-vpn.c:824: have not received TCP DPD for long (1244 secs)
Dec 31 12:16:40 US-LA ocserv[25498]: worker[user3]: 2*0.*02.1*2.2
worker-vpn.c:824: have not received TCP DPD for long (1274 secs)
Dec 31 12:16:40 US-LA ocserv[30941]: main[user3]: 2*0.*02.1*2.2:32544
ioctl SIOCSIFMTU error: Invalid argument
Dec 31 12:17:01 US-LA CRON[25695]: (root) CMD (   cd / && run-parts
--report /etc/cron.hourly)
Dec 31 12:17:10 US-LA ocserv[25498]: worker[user3]: 2*0.*02.1*2.2
worker-vpn.c:824: have not received TCP DPD for long (1304 secs)
Dec 31 12:17:39 US-LA ocserv[30942]: radius-auth: sending session interim update
Dec 31 12:17:39 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:809: have not received any UDP message or DPD for long
(1201 secs, DPD is 600)
Dec 31 12:17:39 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:824: have not received TCP DPD for long (1204 secs)
Dec 31 12:17:50 US-LA ocserv[25498]: worker[user3]: 2*0.*02.1*2.2
worker-vpn.c:824: have not received TCP DPD for long (1344 secs)
Dec 31 12:18:19 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:809: have not received any UDP message or DPD for long
(1241 secs, DPD is 600)
Dec 31 12:18:19 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:824: have not received TCP DPD for long (1244 secs)
Dec 31 12:18:30 US-LA ocserv[25498]: worker[user3]: 2*0.*02.1*2.2
worker-vpn.c:824: have not received TCP DPD for long (1384 secs)
Dec 31 12:18:49 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:809: have not received any UDP message or DPD for long
(1271 secs, DPD is 600)
Dec 31 12:18:49 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:824: have not received TCP DPD for long (1274 secs)
Dec 31 12:19:00 US-LA ocserv[25498]: worker[user3]: 2*0.*02.1*2.2
worker-vpn.c:824: have not received TCP DPD for long (1414 secs)
Dec 31 12:19:19 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:809: have not received any UDP message or DPD for long
(1301 secs, DPD is 600)
Dec 31 12:19:19 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:824: have not received TCP DPD for long (1304 secs)
Dec 31 12:19:19 US-LA ocserv[30941]: main[user3]: 1xx.3x.2x8.x4:41116
ioctl SIOCSIFMTU error: Invalid argument
Dec 31 12:19:30 US-LA ocserv[25498]: worker[user3]: 2*0.*02.1*2.2
worker-vpn.c:824: have not received TCP DPD for long (1444 secs)
Dec 31 12:19:49 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:809: have not received any UDP message or DPD for long
(1331 secs, DPD is 600)
Dec 31 12:19:49 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:824: have not received TCP DPD for long (1334 secs)
Dec 31 12:20:10 US-LA ocserv[25498]: worker[user3]: 2*0.*02.1*2.2
worker-vpn.c:824: have not received TCP DPD for long (1484 secs)
Dec 31 12:20:29 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:809: have not received any UDP message or DPD for long
(1371 secs, DPD is 600)
Dec 31 12:20:29 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:824: have not received TCP DPD for long (1374 secs)
Dec 31 12:20:40 US-LA ocserv[25498]: worker[user3]: 2*0.*02.1*2.2
worker-vpn.c:824: have not received TCP DPD for long (1514 secs)
Dec 31 12:21:09 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:809: have not received any UDP message or DPD for long
(1411 secs, DPD is 600)
Dec 31 12:21:09 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:824: have not received TCP DPD for long (1414 secs)
Dec 31 12:21:10 US-LA ocserv[25498]: worker[user3]: 2*0.*02.1*2.2
worker-vpn.c:824: have not received TCP DPD for long (1544 secs)
Dec 31 12:21:40 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:809: have not received any UDP message or DPD for long
(1442 secs, DPD is 600)
Dec 31 12:21:40 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:824: have not received TCP DPD for long (1445 secs)
Dec 31 12:21:40 US-LA ocserv[25498]: worker[user3]: 2*0.*02.1*2.2
worker-vpn.c:824: have not received TCP DPD for long (1574 secs)
Dec 31 12:22:10 US-LA ocserv[25498]: worker[user3]: 2*0.*02.1*2.2
worker-vpn.c:824: have not received TCP DPD for long (1604 secs)
Dec 31 12:22:20 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:809: have not received any UDP message or DPD for long
(1482 secs, DPD is 600)
Dec 31 12:22:20 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:824: have not received TCP DPD for long (1485 secs)
Dec 31 12:22:40 US-LA ocserv[25498]: worker[user3]: 2*0.*02.1*2.2
worker-vpn.c:824: have not received TCP DPD for long (1634 secs)
Dec 31 12:22:50 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:809: have not received any UDP message or DPD for long
(1512 secs, DPD is 600)
Dec 31 12:22:50 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:824: have not received TCP DPD for long (1515 secs)
Dec 31 12:22:54 US-LA ocserv[25498]: worker[user3]: 2*0.*02.1*2.2
worker-vpn.c:1082: GnuTLS error (at worker-vpn.c:1082): Error in the
pull function.
Dec 31 12:22:55 US-LA ocserv[30941]: main[user3]: 2*0.*02.1*2.2:32544
user disconnected
Dec 31 12:23:20 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:809: have not received any UDP message or DPD for long
(1542 secs, DPD is 600)
Dec 31 12:23:20 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:824: have not received TCP DPD for long (1545 secs)
Dec 31 12:23:50 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:809: have not received any UDP message or DPD for long
(1572 secs, DPD is 600)
Dec 31 12:23:50 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:824: have not received TCP DPD for long (1575 secs)
Dec 31 12:24:30 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:809: have not received any UDP message or DPD for long
(1612 secs, DPD is 600)
Dec 31 12:24:30 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:824: have not received TCP DPD for long (1615 secs)
Dec 31 12:25:10 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:809: have not received any UDP message or DPD for long
(1652 secs, DPD is 600)
Dec 31 12:25:10 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:824: have not received TCP DPD for long (1655 secs)
Dec 31 12:25:40 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:809: have not received any UDP message or DPD for long
(1682 secs, DPD is 600)
Dec 31 12:25:40 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:824: have not received TCP DPD for long (1685 secs)
Dec 31 12:26:10 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:809: have not received any UDP message or DPD for long
(1712 secs, DPD is 600)
Dec 31 12:26:10 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:824: have not received TCP DPD for long (1715 secs)
Dec 31 12:26:50 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:809: have not received any UDP message or DPD for long
(1752 secs, DPD is 600)
Dec 31 12:26:50 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:824: have not received TCP DPD for long (1755 secs)
Dec 31 12:27:30 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:809: have not received any UDP message or DPD for long
(1792 secs, DPD is 600)
Dec 31 12:27:30 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:824: have not received TCP DPD for long (1795 secs)
Dec 31 12:28:00 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:809: have not received any UDP message or DPD for long
(1822 secs, DPD is 600)
Dec 31 12:28:00 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:817: have not received UDP message or DPD for very long;
disabling UDP port
Dec 31 12:28:00 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:824: have not received TCP DPD for long (1825 secs)
Dec 31 12:28:00 US-LA ocserv[25557]: worker[user3]: 1xx.3x.2x8.x4
worker-vpn.c:839: have not received TCP DPD for very long; tearing
down connection
Dec 31 12:28:00 US-LA ocserv[30941]: main[user3]: 1xx.3x.2x8.x4:41116
user disconnected