Weird problem connecting using AnyConnect 3.1.05152 under Windows

Tony Zhou tonytzhou at gmail.com
Mon Jan 27 17:17:01 EST 2014 

Hi Nikos,

In this case "someSID" refers to the exactly same SID in the log.

Jan 28 07:15:30 area11 ocserv[23037]: client.ip.address:54323 accepted 
connection
Jan 28 07:15:30 area11 ocserv[22820]: sec-mod received request from pid 
23037 and uid 65534
Jan 28 07:15:30 area11 ocserv[23037]: client.ip.address:54323 sending 
message 'resume data store request' to main
Jan 28 07:15:30 area11 ocserv[22819]: client.ip.address:54323 main 
received message 'resume data store request' of 258 bytes
Jan 28 07:15:30 area11 ocserv[22819]: client.ip.address:54323 TLS 
session DB storing 
4ced978b675fa2a954aa9613802c41b2e62a495304f2306b691c024b199560fb
Jan 28 07:15:30 area11 ocserv[23037]: client.ip.address:54323 TLS 
handshake completed
Jan 28 07:15:30 area11 ocserv[23037]: client.ip.address:54323 error 
receiving client data
Jan 28 07:15:30 area11 ocserv[22819]: client.ip.address:54323 
main-misc.c:468: command socket closed
Jan 28 07:15:32 area11 ocserv[23038]: client.ip.address:54324 accepted 
connection
Jan 28 07:15:32 area11 ocserv[23038]: client.ip.address:54324 sending 
message 'resume data fetch request' to main
Jan 28 07:15:32 area11 ocserv[22819]: client.ip.address:54324 main 
received message 'resume data fetch request' of 34 bytes
Jan 28 07:15:32 area11 ocserv[22819]: client.ip.address:54324 TLS 
session DB resuming 
4ced978b675fa2a954aa9613802c41b2e62a495304f2306b691c024b199560fb
Jan 28 07:15:32 area11 ocserv[22819]: client.ip.address:54324 sending 
message 'resume data fetch reply' to worker
Jan 28 07:15:32 area11 ocserv[23038]: client.ip.address:54324 TLS 
handshake completed
Jan 28 07:15:32 area11 ocserv[23038]: client.ip.address:54324 HTTP: 
Cache-Control: no-cache
Jan 28 07:15:32 area11 ocserv[23038]: client.ip.address:54324 HTTP: 
Connection: close
Jan 28 07:15:32 area11 ocserv[23038]: client.ip.address:54324 HTTP: 
Pragma: no-cache
Jan 28 07:15:32 area11 ocserv[23038]: client.ip.address:54324 HTTP: 
User-Agent: AnyConnect Windows 3.1.05152
Jan 28 07:15:32 area11 ocserv[23038]: client.ip.address:54324 HTTP: 
X-Transcend-Version: 1
Jan 28 07:15:32 area11 ocserv[23038]: client.ip.address:54324 HTTP: 
X-Aggregate-Auth: 1
Jan 28 07:15:32 area11 ocserv[23038]: client.ip.address:54324 HTTP: 
X-AnyConnect-Platform: win
Jan 28 07:15:32 area11 ocserv[23038]: client.ip.address:54324 HTTP: 
Content-Length: 238
Jan 28 07:15:32 area11 ocserv[23038]: client.ip.address:54324 HTTP: 
Host: server.ip.address
Jan 28 07:15:32 area11 ocserv[23038]: client.ip.address:54324 HTTP POST /
Jan 28 07:15:32 area11 ocserv[23038]: client.ip.address:54324 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>win</device-id>#012<group-access>https://server.ip.address</group-access>#012</config-auth>#012'
Jan 28 07:15:32 area11 ocserv[23038]: client.ip.address:54324 cannot 
find username in client XML message
Jan 28 07:15:32 area11 ocserv[23038]: client.ip.address:54324 cannot 
find password in client XML message
Jan 28 07:15:32 area11 ocserv[23038]: client.ip.address:54324 failed 
reading password as well
Jan 28 07:15:32 area11 ocserv[23038]: client.ip.address:54324 sent sid: 
FCwcG8aB8lCeQ2Mp
Jan 28 07:15:32 area11 ocserv[22819]: client.ip.address:54324 
main-misc.c:468: command socket closed
Jan 28 07:15:34 area11 ocserv[23039]: client.ip.address:54325 accepted 
connection
Jan 28 07:15:34 area11 ocserv[23039]: client.ip.address:54325 sending 
message 'resume data fetch request' to main
Jan 28 07:15:34 area11 ocserv[22819]: client.ip.address:54325 main 
received message 'resume data fetch request' of 34 bytes
Jan 28 07:15:34 area11 ocserv[22819]: client.ip.address:54325 TLS 
session DB resuming 
4ced978b675fa2a954aa9613802c41b2e62a495304f2306b691c024b199560fb
Jan 28 07:15:34 area11 ocserv[22819]: client.ip.address:54325 sending 
message 'resume data fetch reply' to worker
Jan 28 07:15:34 area11 ocserv[23039]: client.ip.address:54325 TLS 
handshake completed
Jan 28 07:15:34 area11 ocserv[23039]: client.ip.address:54325 HTTP: 
Cache-Control: no-cache
Jan 28 07:15:34 area11 ocserv[23039]: client.ip.address:54325 HTTP: 
Connection: Close
Jan 28 07:15:34 area11 ocserv[23039]: client.ip.address:54325 HTTP: 
Pragma: no-cache
Jan 28 07:15:34 area11 ocserv[23039]: client.ip.address:54325 HTTP: 
Cookie: webvpncontext=FCwcG8aB8lCeQ2Mp;
Jan 28 07:15:34 area11 ocserv[23039]: client.ip.address:54325 HTTP: 
User-Agent: AnyConnect Windows 3.1.05152
Jan 28 07:15:34 area11 ocserv[23039]: client.ip.address:54325 HTTP: 
X-Transcend-Version: 1
Jan 28 07:15:34 area11 ocserv[23039]: client.ip.address:54325 HTTP: 
X-Aggregate-Auth: 1
Jan 28 07:15:34 area11 ocserv[23039]: client.ip.address:54325 HTTP: 
X-AnyConnect-Platform: win
Jan 28 07:15:34 area11 ocserv[23039]: client.ip.address:54325 HTTP: 
Content-Length: 13
Jan 28 07:15:34 area11 ocserv[23039]: client.ip.address:54325 HTTP: 
Host: server.ip.address
Jan 28 07:15:34 area11 ocserv[23039]: client.ip.address:54325 HTTP POST 
/auth
Jan 28 07:15:34 area11 ocserv[23039]: client.ip.address:54325 POST body: 
'username=someuser'
Jan 28 07:15:34 area11 ocserv[23039]: client.ip.address:54325 sending 
message 'auth init' to main
Jan 28 07:15:34 area11 ocserv[22819]: client.ip.address:54325 main 
received message 'auth init' of 12 bytes
Jan 28 07:15:34 area11 ocserv[22819]: client.ip.address:54325 auth init 
for user 'someuser' from 'client.ip.address:54325'
Jan 28 07:15:34 area11 ocserv[22819]: client.ip.address:54325 sending 
message 'auth reply' to worker
Jan 28 07:15:34 area11 ocserv[23039]: client.ip.address:54325 received 
auth reply message (value: 2)
Jan 28 07:15:34 area11 ocserv[23039]: client.ip.address:54325 continuing 
authentication for ''
Jan 28 07:15:34 area11 ocserv[23039]: client.ip.address:54325 sent sid: 
FCwcG8aB8lCeQ2Mp
Jan 28 07:15:35 area11 ocserv[22819]: client.ip.address:54325 
main-misc.c:468: command socket closed
Jan 28 07:15:35 area11 ocserv[22819]: client.ip.address:54325 client 
disconnected, became zombie
Jan 28 07:15:37 area11 ocserv[23040]: client.ip.address:54326 accepted 
connection
Jan 28 07:15:37 area11 ocserv[23040]: client.ip.address:54326 sending 
message 'resume data fetch request' to main
Jan 28 07:15:37 area11 ocserv[22819]: client.ip.address:54326 main 
received message 'resume data fetch request' of 34 bytes
Jan 28 07:15:37 area11 ocserv[22819]: client.ip.address:54326 TLS 
session DB resuming 
4ced978b675fa2a954aa9613802c41b2e62a495304f2306b691c024b199560fb
Jan 28 07:15:37 area11 ocserv[22819]: client.ip.address:54326 sending 
message 'resume data fetch reply' to worker
Jan 28 07:15:37 area11 ocserv[23040]: client.ip.address:54326 TLS 
handshake completed
Jan 28 07:15:37 area11 ocserv[23040]: client.ip.address:54326 HTTP: 
Cache-Control: no-cache
Jan 28 07:15:37 area11 ocserv[23040]: client.ip.address:54326 HTTP: 
Connection: Close
Jan 28 07:15:37 area11 ocserv[23040]: client.ip.address:54326 HTTP: 
Pragma: no-cache
Jan 28 07:15:37 area11 ocserv[23040]: client.ip.address:54326 HTTP: 
Cookie: webvpncontext=FCwcG8aB8lCeQ2Mp;
Jan 28 07:15:37 area11 ocserv[23040]: client.ip.address:54326 HTTP: 
User-Agent: AnyConnect Windows 3.1.05152
Jan 28 07:15:37 area11 ocserv[23040]: client.ip.address:54326 HTTP: 
X-Transcend-Version: 1
Jan 28 07:15:37 area11 ocserv[23040]: client.ip.address:54326 HTTP: 
X-Aggregate-Auth: 1
Jan 28 07:15:37 area11 ocserv[23040]: client.ip.address:54326 HTTP: 
X-AnyConnect-Platform: win
Jan 28 07:15:37 area11 ocserv[23040]: client.ip.address:54326 HTTP: 
Content-Length: 17
Jan 28 07:15:37 area11 ocserv[23040]: client.ip.address:54326 HTTP: 
Host: server.ip.address
Jan 28 07:15:37 area11 ocserv[23040]: client.ip.address:54326 HTTP POST 
/auth
Jan 28 07:15:37 area11 ocserv[23040]: client.ip.address:54326 POST body: 
'password=somepass'
Jan 28 07:15:37 area11 ocserv[23040]: client.ip.address:54326 cannot 
find username in client message
Jan 28 07:15:37 area11 ocserv[23040]: client.ip.address:54326 sending 
message 'auth reinit' to main
Jan 28 07:15:37 area11 ocserv[22819]: client.ip.address:54326 main 
received message 'auth reinit' of 26 bytes
Jan 28 07:15:37 area11 ocserv[22819]: client.ip.address:54326 auth 
reinit received but does not match any session with SID FCwcG8aB8lCeQ2Mp
Jan 28 07:15:37 area11 ocserv[22819]: client.ip.address:54326 failed 
authentication attempt for user ''
Jan 28 07:15:37 area11 ocserv[22819]: client.ip.address:54326 sending 
message 'auth reply' to worker
Jan 28 07:15:37 area11 ocserv[23040]: client.ip.address:54326 received 
auth reply message (value: 3)
Jan 28 07:15:37 area11 ocserv[23040]: client.ip.address:54326 
worker-auth.c:816: failed authentication for ''

Thanks,
TZ

On 1/27/2014 5:04 PM, Nikos Mavrogiannopoulos wrote:
> On 01/27/2014 09:58 PM, Tony Zhou wrote:
>> 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:34 area11 ocserv[22824]: client.ip.address:49531 sent sid:
>> someSID
>> 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 sending
>> message 'auth init' to main
> [...]
>> Jan 28 05:56:37 area11 ocserv[22825]: client.ip.address:49532 sent sid:
>> someSID
> Hello,
>   Unfortunately you have stripped all the information that could be
> helpful in tracking the issue. It seems that in your case the server
> isn't able to associate the multiple client connections using the SID
> (or webvpncontext - that is just a unique identifier for the connection).
>
> regards,
> Nikos
>

More information about the openconnect-devel mailing list