Weird problem connecting using AnyConnect 3.1.05152 under Windows

[Tony Zhou]

Hi all,

I have compiled the latest version of ocserv (0.3.0) and trying to use 
AnyConnect for Windows for it, however the authentication attempt failed 
after first try. Here's the log:

Jan 28 05:56:10 area11 ocserv[22819]: [main] initialized ocserv 0.3.0
Jan 28 05:56:10 area11 ocserv[22820]: sec-mod initialized (socket: 
/var/run/ocserv-socket.22819)
Jan 28 05:56:32 area11 ocserv[22823]: client.ip.address:49530 accepted 
connection
Jan 28 05:56:33 area11 ocserv[22820]: sec-mod received request from pid 
22823 and uid 65534
Jan 28 05:56:33 area11 ocserv[22823]: client.ip.address:49530 sending 
message 'resume data store request' to main
Jan 28 05:56:33 area11 ocserv[22819]: client.ip.address:49530 main 
received message 'resume data store request' of 258 bytes
Jan 28 05:56:33 area11 ocserv[22819]: client.ip.address:49530 TLS 
session DB storing 
a601d3a94a789f1499c0132ddf56c21a88b97f314661133c25cf75ddf53e7bfb
Jan 28 05:56:33 area11 ocserv[22823]: client.ip.address:49530 TLS 
handshake completed
Jan 28 05:56:33 area11 ocserv[22823]: client.ip.address:49530 error 
receiving client data
Jan 28 05:56:33 area11 ocserv[22819]: client.ip.address:49530 
main-misc.c:468: command socket closed
Jan 28 05:56:34 area11 ocserv[22824]: client.ip.address:49531 accepted 
connection
Jan 28 05:56:34 area11 ocserv[22824]: client.ip.address:49531 sending 
message 'resume data fetch request' to main
Jan 28 05:56:34 area11 ocserv[22819]: client.ip.address:49531 main 
received message 'resume data fetch request' of 34 bytes
Jan 28 05:56:34 area11 ocserv[22819]: client.ip.address:49531 TLS 
session DB resuming 
a601d3a94a789f1499c0132ddf56c21a88b97f314661133c25cf75ddf53e7bfb
Jan 28 05:56:34 area11 ocserv[22819]: client.ip.address:49531 sending 
message 'resume data fetch reply' to worker
Jan 28 05:56:34 area11 ocserv[22824]: client.ip.address:49531 TLS 
handshake completed
Jan 28 05:56:34 area11 ocserv[22824]: client.ip.address:49531 HTTP: 
Cache-Control: no-cache
Jan 28 05:56:34 area11 ocserv[22824]: client.ip.address:49531 HTTP: 
Connection: close
Jan 28 05:56:34 area11 ocserv[22824]: client.ip.address:49531 HTTP: 
Pragma: no-cache
Jan 28 05:56:34 area11 ocserv[22824]: client.ip.address:49531 HTTP: 
User-Agent: AnyConnect Windows 3.1.05152
Jan 28 05:56:34 area11 ocserv[22824]: client.ip.address:49531 HTTP: 
X-Transcend-Version: 1
Jan 28 05:56:34 area11 ocserv[22824]: client.ip.address:49531 HTTP: 
X-Aggregate-Auth: 1
Jan 28 05:56:34 area11 ocserv[22824]: client.ip.address:49531 HTTP: 
X-AnyConnect-Platform: win
Jan 28 05:56:34 area11 ocserv[22824]: client.ip.address:49531 HTTP: 
Content-Length: 487
Jan 28 05:56:34 area11 ocserv[22824]: client.ip.address:49531 HTTP: 
Host: server.ip.address
Jan 28 05:56:34 area11 ocserv[22824]: client.ip.address:49531 HTTP POST /
Jan 28 05:56:34 area11 ocserv[22824]: client.ip.address:49531 POST body: 
'<?xml version="1.0" encoding="UTF-8"?>#012<config-auth client="vpn" 
type="init" aggregate-auth-version="2">#012<version 
who="vpn">3.1.05152</version>#012<device-id device-type="Intel Pentium 
Processors= 2 x86" platform-version="6.1.7601 Service Pack 1" 
unique-id="F686710C220E63C9A20FD1FC073D117ED9526BE5E3A20C576606E5FD79106A26">win</device-id>#012<mac-address-list>#012<mac-address>00-16-ea-c0-04-a6</mac-address></mac-address-list>#012<group-access>https://server.ip.address</group-access>#012</config-auth>#012'
Jan 28 05:56:34 area11 ocserv[22824]: client.ip.address:49531 cannot 
find username in client XML message
Jan 28 05:56:34 area11 ocserv[22824]: client.ip.address:49531 cannot 
find password in client XML message
Jan 28 05:56:34 area11 ocserv[22824]: client.ip.address:49531 failed 
reading password as well
Jan 28 05:56:34 area11 ocserv[22824]: client.ip.address:49531 sent sid: 
someSID
Jan 28 05:56:35 area11 ocserv[22819]: client.ip.address:49531 
main-misc.c:468: command socket closed
Jan 28 05:56:36 area11 ocserv[22825]: client.ip.address:49532 accepted 
connection
Jan 28 05:56:36 area11 ocserv[22825]: client.ip.address:49532 sending 
message 'resume data fetch request' to main
Jan 28 05:56:36 area11 ocserv[22819]: client.ip.address:49532 main 
received message 'resume data fetch request' of 34 bytes
Jan 28 05:56:36 area11 ocserv[22819]: client.ip.address:49532 TLS 
session DB resuming 
a601d3a94a789f1499c0132ddf56c21a88b97f314661133c25cf75ddf53e7bfb
Jan 28 05:56:36 area11 ocserv[22819]: client.ip.address:49532 sending 
message 'resume data fetch reply' to worker
Jan 28 05:56:37 area11 ocserv[22825]: client.ip.address:49532 TLS 
handshake completed
Jan 28 05:56:37 area11 ocserv[22825]: client.ip.address:49532 HTTP: 
Cache-Control: no-cache
Jan 28 05:56:37 area11 ocserv[22825]: client.ip.address:49532 HTTP: 
Connection: Close
Jan 28 05:56:37 area11 ocserv[22825]: client.ip.address:49532 HTTP: 
Pragma: no-cache
Jan 28 05:56:37 area11 ocserv[22825]: client.ip.address:49532 HTTP: 
Cookie: webvpncontext=someSID;
Jan 28 05:56:37 area11 ocserv[22825]: client.ip.address:49532 HTTP: 
User-Agent: AnyConnect Windows 3.1.05152
Jan 28 05:56:37 area11 ocserv[22825]: client.ip.address:49532 HTTP: 
X-Transcend-Version: 1
Jan 28 05:56:37 area11 ocserv[22825]: client.ip.address:49532 HTTP: 
X-Aggregate-Auth: 1
Jan 28 05:56:37 area11 ocserv[22825]: client.ip.address:49532 HTTP: 
X-AnyConnect-Platform: win
Jan 28 05:56:37 area11 ocserv[22825]: client.ip.address:49532 HTTP: 
Content-Length: 13
Jan 28 05:56:37 area11 ocserv[22825]: client.ip.address:49532 HTTP: 
Host: server.ip.address
Jan 28 05:56:37 area11 ocserv[22825]: client.ip.address:49532 HTTP POST 
/auth
Jan 28 05:56:37 area11 ocserv[22825]: client.ip.address:49532 POST body: 
'username=someuser'
Jan 28 05:56:37 area11 ocserv[22825]: client.ip.address:49532 sending 
message 'auth init' to main
Jan 28 05:56:37 area11 ocserv[22819]: client.ip.address:49532 main 
received message 'auth init' of 12 bytes
Jan 28 05:56:37 area11 ocserv[22819]: client.ip.address:49532 auth init 
for user 'someuser' from 'client.ip.address:49532'
Jan 28 05:56:37 area11 ocserv[22819]: client.ip.address:49532 sending 
message 'auth reply' to worker
Jan 28 05:56:37 area11 ocserv[22825]: client.ip.address:49532 received 
auth reply message (value: 2)
Jan 28 05:56:37 area11 ocserv[22825]: client.ip.address:49532 continuing 
authentication for ''
Jan 28 05:56:37 area11 ocserv[22825]: client.ip.address:49532 sent sid: 
someSID
Jan 28 05:56:37 area11 ocserv[22819]: client.ip.address:49532 
main-misc.c:468: command socket closed
Jan 28 05:56:37 area11 ocserv[22819]: client.ip.address:49532 client 
disconnected, became zombie
Jan 28 05:56:39 area11 ocserv[22826]: client.ip.address:49533 accepted 
connection
Jan 28 05:56:39 area11 ocserv[22826]: client.ip.address:49533 sending 
message 'resume data fetch request' to main
Jan 28 05:56:39 area11 ocserv[22819]: client.ip.address:49533 main 
received message 'resume data fetch request' of 34 bytes
Jan 28 05:56:39 area11 ocserv[22819]: client.ip.address:49533 TLS 
session DB resuming 
a601d3a94a789f1499c0132ddf56c21a88b97f314661133c25cf75ddf53e7bfb
Jan 28 05:56:39 area11 ocserv[22819]: client.ip.address:49533 sending 
message 'resume data fetch reply' to worker
Jan 28 05:56:40 area11 ocserv[22826]: client.ip.address:49533 TLS 
handshake completed
Jan 28 05:56:40 area11 ocserv[22826]: client.ip.address:49533 HTTP: 
Cache-Control: no-cache
Jan 28 05:56:40 area11 ocserv[22826]: client.ip.address:49533 HTTP: 
Connection: Close
Jan 28 05:56:40 area11 ocserv[22826]: client.ip.address:49533 HTTP: 
Pragma: no-cache
Jan 28 05:56:40 area11 ocserv[22826]: client.ip.address:49533 HTTP: 
Cookie: webvpncontext=someSID;
Jan 28 05:56:40 area11 ocserv[22826]: client.ip.address:49533 HTTP: 
User-Agent: AnyConnect Windows 3.1.05152
Jan 28 05:56:40 area11 ocserv[22826]: client.ip.address:49533 HTTP: 
X-Transcend-Version: 1
Jan 28 05:56:40 area11 ocserv[22826]: client.ip.address:49533 HTTP: 
X-Aggregate-Auth: 1
Jan 28 05:56:40 area11 ocserv[22826]: client.ip.address:49533 HTTP: 
X-AnyConnect-Platform: win
Jan 28 05:56:40 area11 ocserv[22826]: client.ip.address:49533 HTTP: 
Content-Length: 17
Jan 28 05:56:40 area11 ocserv[22826]: client.ip.address:49533 HTTP: 
Host: server.ip.address
Jan 28 05:56:40 area11 ocserv[22826]: client.ip.address:49533 HTTP POST 
/auth
Jan 28 05:56:40 area11 ocserv[22826]: client.ip.address:49533 POST body: 
'password=somepass'
Jan 28 05:56:40 area11 ocserv[22826]: client.ip.address:49533 cannot 
find username in client message
Jan 28 05:56:40 area11 ocserv[22826]: client.ip.address:49533 sending 
message 'auth reinit' to main
Jan 28 05:56:40 area11 ocserv[22819]: client.ip.address:49533 main 
received message 'auth reinit' of 26 bytes
Jan 28 05:56:40 area11 ocserv[22819]: client.ip.address:49533 auth 
reinit received but does not match any session with SID someSID
Jan 28 05:56:40 area11 ocserv[22819]: client.ip.address:49533 failed 
authentication attempt for user ''
Jan 28 05:56:40 area11 ocserv[22819]: client.ip.address:49533 sending 
message 'auth reply' to worker
Jan 28 05:56:40 area11 ocserv[22826]: client.ip.address:49533 received 
auth reply message (value: 3)
Jan 28 05:56:40 area11 ocserv[22826]: client.ip.address:49533 
worker-auth.c:816: failed authentication for ''

It seems that ocserv failed to catch the username and password offered 
by the client. However strangely it works totally fine for iOS clients.

Thanks,
TZ