Anyconnect short lived connection

Jeff Genender jgenender at savoirtech.com
Tue May 9 06:58:47 PDT 2017 

Hi,

I have ocserv running on an ASUS Merlin platform and used the general opkg (entware) for install.  I followed several setups around the net and got ocserv to fire up and accept a VPN connection from Anyconnect clients on IOS and the Mac.  It connects just fine and the client even says that it has connected.  The connection lasts for about 10-15 seconds, then the client disconnects with the following message: “The secure gateway has rejected the connection attempt.  A new connection attempt to the same or another secure gateway is needed, which requires re-authentication.”  I try to reconnect, and of course it connects… but again, 10-15 seconds with the exact same message and results.  The log shows that it connects fine and you can see the TLS/worker/main packets going just fine.  After the 10-15 seconds (about when the disconnect occurs) I get this in the log (I scrubbed the file with xxxxxxxx for any potentially identifying sessions ids/cookies/etc):

ocserv[13469]: worker[lwk]: 63.197.197.76 received 44 byte(s) (TLS)
ocserv[13469]: worker[lwk]: 63.197.197.76 received BYE packet; exiting
ocserv[13465]: sec-mod: received request from pid 13469 and uid 65534
ocserv[13469]: worker[lwk]: 63.197.197.76 sending message 'sm: worker cli stats' to secmod
ocserv[13465]: sec-mod: cmd [size=75] sm: worker cli stats
ocserv[13469]: worker[lwk]: 63.197.197.76 sent periodic stats (in: 3620, out: 0) to sec-mod
ocserv[13464]: main: added 1 points (total 5) for IP '63.197.197.76' to ban list
ocserv[13475]: worker:  accepted connection
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Allocating epoch #0
ocserv[13475]: TLS[<3>]: ASSERT: constate.c[_gnutls_epoch_get]:600
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Allocating epoch #1
ocserv[13475]: TLS[<3>]: ASSERT: buffers.c[get_last_packet]:1159
ocserv[13475]: TLS[<5>]: REC[0x8e008]: SSL 3.1 Handshake packet received. Epoch 0, length: 135
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Expected Packet Handshake(22)
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Received Packet Handshake(22) with length: 135
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Decrypted Packet[0] Handshake(22) with length: 135
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: CLIENT HELLO (1) was received. Length 131[131], frag offset 0, frag length: 131, sequence: 0
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Client's version: 3.3
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Selected version TLS1.2
ocserv[13475]: TLS[<4>]: EXT[0x8e008]: Found extension 'Supported ECC Point Formats/11'
ocserv[13475]: TLS[<4>]: EXT[0x8e008]: Found extension 'Supported curves/10'
ocserv[13475]: TLS[<4>]: EXT[0x8e008]: Found extension 'Signature Algorithms/13'
ocserv[13475]: TLS[<3>]: ASSERT: db.c[_gnutls_server_restore_session]:272
ocserv[13475]: TLS[<4>]: EXT[0x8e008]: Found extension 'Supported ECC Point Formats/11'
ocserv[13475]: TLS[<4>]: EXT[0x8e008]: Found extension 'Supported curves/10'
ocserv[13475]: TLS[<4>]: EXT[0x8e008]: Found extension 'Signature Algorithms/13'
ocserv[13475]: TLS[<4>]: EXT[0x8e008]: Parsing extension 'Supported ECC Point Formats/11' (4 bytes)
ocserv[13475]: TLS[<4>]: EXT[0x8e008]: Parsing extension 'Supported curves/10' (10 bytes)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Selected ECC curve SECP521R1 (4)
ocserv[13475]: TLS[<4>]: EXT[0x8e008]: Parsing extension 'Signature Algorithms/13' (32 bytes)
ocserv[13475]: TLS[<4>]: EXT[0x8e008]: rcvd signature algo (6.1) RSA-SHA512
ocserv[13475]: TLS[<4>]: EXT[0x8e008]: rcvd signature algo (6.2) DSA-SHA512
ocserv[13475]: TLS[<4>]: EXT[0x8e008]: rcvd signature algo (6.3) ECDSA-SHA512
ocserv[13475]: TLS[<4>]: EXT[0x8e008]: rcvd signature algo (5.1) RSA-SHA384
ocserv[13475]: TLS[<4>]: EXT[0x8e008]: rcvd signature algo (5.2) DSA-SHA384
ocserv[13475]: TLS[<4>]: EXT[0x8e008]: rcvd signature algo (5.3) ECDSA-SHA384
ocserv[13475]: TLS[<4>]: EXT[0x8e008]: rcvd signature algo (4.1) RSA-SHA256
ocserv[13475]: TLS[<4>]: EXT[0x8e008]: rcvd signature algo (4.2) DSA-SHA256
ocserv[13475]: TLS[<4>]: EXT[0x8e008]: rcvd signature algo (4.3) ECDSA-SHA256
ocserv[13475]: TLS[<4>]: EXT[0x8e008]: rcvd signature algo (3.1) RSA-SHA224
ocserv[13475]: TLS[<4>]: EXT[0x8e008]: rcvd signature algo (3.2) DSA-SHA224
ocserv[13475]: TLS[<4>]: EXT[0x8e008]: rcvd signature algo (3.3) ECDSA-SHA224
ocserv[13475]: TLS[<4>]: EXT[0x8e008]: rcvd signature algo (2.1) RSA-SHA1
ocserv[13475]: TLS[<4>]: EXT[0x8e008]: rcvd signature algo (2.2) DSA-SHA1
ocserv[13475]: TLS[<4>]: EXT[0x8e008]: rcvd signature algo (2.3) ECDSA-SHA1
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Received safe renegotiation CS
ocserv[13475]: TLS[<3>]: ASSERT: server_name.c[gnutls_server_name_get]:310
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Requested server name: ''
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Requested PK algorithm: EC/ECDSA (4) -- ctype: X.509 (1)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: certificate[0] PK algorithm: RSA (1) - ctype: X.509 (1)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Requested PK algorithm: RSA (1) -- ctype: X.509 (1)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: certificate[0] PK algorithm: RSA (1) - ctype: X.509 (1)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_ECDHE_RSA_AES_256_GCM_SHA384 (C0.30)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_ECDHE_RSA_CAMELLIA_256_GCM_SHA384 (C0.8B)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_ECDHE_RSA_CHACHA20_POLY1305 (CC.A8)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_ECDHE_RSA_AES_256_CBC_SHA1 (C0.14)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_ECDHE_RSA_AES_256_CBC_SHA384 (C0.28)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_ECDHE_RSA_CAMELLIA_256_CBC_SHA384 (C0.77)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_ECDHE_RSA_AES_128_GCM_SHA256 (C0.2F)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_ECDHE_RSA_CAMELLIA_128_GCM_SHA256 (C0.8A)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_ECDHE_RSA_AES_128_CBC_SHA1 (C0.13)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_ECDHE_RSA_AES_128_CBC_SHA256 (C0.27)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_ECDHE_RSA_CAMELLIA_128_CBC_SHA256 (C0.76)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_ECDHE_RSA_3DES_EDE_CBC_SHA1 (C0.12)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_RSA_AES_256_GCM_SHA384 (00.9D)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_RSA_CAMELLIA_256_GCM_SHA384 (C0.7B)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_RSA_AES_256_CCM (C0.9D)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_RSA_AES_256_CBC_SHA1 (00.35)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_RSA_AES_256_CBC_SHA256 (00.3D)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_RSA_CAMELLIA_256_CBC_SHA1 (00.84)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_RSA_CAMELLIA_256_CBC_SHA256 (00.C0)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_RSA_AES_128_GCM_SHA256 (00.9C)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_RSA_CAMELLIA_128_GCM_SHA256 (C0.7A)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_RSA_AES_128_CCM (C0.9C)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_RSA_AES_128_CBC_SHA1 (00.2F)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_RSA_AES_128_CBC_SHA256 (00.3C)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_RSA_CAMELLIA_128_CBC_SHA1 (00.41)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_RSA_CAMELLIA_128_CBC_SHA256 (00.BA)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_RSA_3DES_EDE_CBC_SHA1 (00.0A)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_DHE_RSA_AES_256_GCM_SHA384 (00.9F)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_DHE_RSA_CAMELLIA_256_GCM_SHA384 (C0.7D)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_DHE_RSA_CHACHA20_POLY1305 (CC.AA)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_DHE_RSA_AES_256_CCM (C0.9F)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_DHE_RSA_AES_256_CBC_SHA1 (00.39)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_DHE_RSA_AES_256_CBC_SHA256 (00.6B)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_DHE_RSA_CAMELLIA_256_CBC_SHA1 (00.88)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_DHE_RSA_CAMELLIA_256_CBC_SHA256 (00.C4)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_DHE_RSA_AES_128_GCM_SHA256 (00.9E)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_DHE_RSA_CAMELLIA_128_GCM_SHA256 (C0.7C)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_DHE_RSA_AES_128_CCM (C0.9E)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_DHE_RSA_AES_128_CBC_SHA1 (00.33)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_DHE_RSA_AES_128_CBC_SHA256 (00.67)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_DHE_RSA_CAMELLIA_128_CBC_SHA1 (00.45)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_DHE_RSA_CAMELLIA_128_CBC_SHA256 (00.BE)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Keeping ciphersuite: GNUTLS_DHE_RSA_3DES_EDE_CBC_SHA1 (00.16)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Requested cipher suites[size: 32]: 
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Selected cipher suite: ECDHE_RSA_AES_256_GCM_SHA384
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Selected Compression Method: NULL
ocserv[13475]: TLS[<4>]: EXT[0x8e008]: Found extension 'Supported ECC Point Formats/11'
ocserv[13475]: TLS[<4>]: EXT[0x8e008]: Found extension 'Supported curves/10'
ocserv[13475]: TLS[<4>]: EXT[0x8e008]: Found extension 'Signature Algorithms/13'
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Safe renegotiation succeeded
ocserv[13475]: TLS[<4>]: EXT[0x8e008]: Sending extension Safe Renegotiation (1 bytes)
ocserv[13475]: TLS[<4>]: EXT[0x8e008]: Sending extension Supported ECC Point Formats (2 bytes)
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: SessionID: xxxxxxxxxxxxxx
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: SERVER HELLO was queued [87 bytes]
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: CERTIFICATE was queued [1111 bytes]
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: signing handshake data: using RSA-SHA512
ocserv[13465]: sec-mod: received request from pid 13475 and uid 65534
ocserv[13465]: sec-mod: cmd [size=87] sm: sign
ocserv[13464]: main[lwk]: 63.197.197.76:49562 worker terminated
ocserv[13464]: main[lwk]: 63.197.197.76:49562 sending msg sm: session close to sec-mod
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: SERVER KEY EXCHANGE was queued [529 bytes]
ocserv[13475]: TLS[<4>]: EXT[0x8e008]: sent signature algo (4.1) RSA-SHA256
ocserv[13475]: TLS[<4>]: EXT[0x8e008]: sent signature algo (4.3) ECDSA-SHA256
ocserv[13475]: TLS[<4>]: EXT[0x8e008]: sent signature algo (5.1) RSA-SHA384
ocserv[13475]: TLS[<4>]: EXT[0x8e008]: sent signature algo (5.3) ECDSA-SHA384
ocserv[13475]: TLS[<4>]: EXT[0x8e008]: sent signature algo (6.1) RSA-SHA512
ocserv[13475]: TLS[<4>]: EXT[0x8e008]: sent signature algo (6.3) ECDSA-SHA512
ocserv[13475]: TLS[<4>]: EXT[0x8e008]: sent signature algo (3.1) RSA-SHA224
ocserv[13475]: TLS[<4>]: EXT[0x8e008]: sent signature algo (3.3) ECDSA-SHA224
ocserv[13475]: TLS[<4>]: EXT[0x8e008]: sent signature algo (2.1) RSA-SHA1
ocserv[13475]: TLS[<4>]: EXT[0x8e008]: sent signature algo (2.3) ECDSA-SHA1
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: CERTIFICATE REQUEST was queued [68 bytes]
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: SERVER HELLO DONE was queued [4 bytes]
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Preparing Packet Handshake(22) with length: 87 and min pad: 0
ocserv[13475]: TLS[<9>]: ENC[0x8e008]: cipher: NULL, MAC: MAC-NULL, Epoch: 0
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Sent Packet[1] Handshake(22) in epoch 0 and length: 92
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Preparing Packet Handshake(22) with length: 1111 and min pad: 0
ocserv[13475]: TLS[<9>]: ENC[0x8e008]: cipher: NULL, MAC: MAC-NULL, Epoch: 0
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Sent Packet[2] Handshake(22) in epoch 0 and length: 1116
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Preparing Packet Handshake(22) with length: 529 and min pad: 0
ocserv[13475]: TLS[<9>]: ENC[0x8e008]: cipher: NULL, MAC: MAC-NULL, Epoch: 0
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Sent Packet[3] Handshake(22) in epoch 0 and length: 534
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Preparing Packet Handshake(22) with length: 68 and min pad: 0
ocserv[13475]: TLS[<9>]: ENC[0x8e008]: cipher: NULL, MAC: MAC-NULL, Epoch: 0
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Sent Packet[4] Handshake(22) in epoch 0 and length: 73
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Preparing Packet Handshake(22) with length: 4 and min pad: 0
ocserv[13475]: TLS[<9>]: ENC[0x8e008]: cipher: NULL, MAC: MAC-NULL, Epoch: 0
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Sent Packet[5] Handshake(22) in epoch 0 and length: 9
ocserv[13475]: TLS[<3>]: ASSERT: buffers.c[get_last_packet]:1159
ocserv[13465]: sec-mod: received request sm: session close
ocserv[13465]: sec-mod: cmd [size=40] sm: session close
ocserv[13464]: main[lwk]: 63.197.197.76:49562 user disconnected (reason: user disconnected, rx: 3620, tx: 0)
ocserv[13465]: sec-mod: invalidating session of user 'lwk' (session: dmdkdx)
ocserv[13465]: sec-mod: permamently closing session of user 'lwk' (session: dmdkdx)
ocserv[13475]: TLS[<5>]: REC[0x8e008]: SSL 3.3 Handshake packet received. Epoch 0, length: 7
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Expected Packet Handshake(22)
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Received Packet Handshake(22) with length: 7
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Decrypted Packet[1] Handshake(22) with length: 7
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: CERTIFICATE (11) was received. Length 3[3], frag offset 0, frag length: 3, sequence: 0
ocserv[13475]: TLS[<3>]: ASSERT: cert.c[_gnutls_proc_x509_server_crt]:1018
ocserv[13475]: worker:  tlslib.c:475: no certificate was found
ocserv[13475]: TLS[<3>]: ASSERT: buffers.c[get_last_packet]:1159
ocserv[13475]: TLS[<5>]: REC[0x8e008]: SSL 3.3 Handshake packet received. Epoch 0, length: 138
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Expected Packet Handshake(22)
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Received Packet Handshake(22) with length: 138
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Decrypted Packet[2] Handshake(22) with length: 138
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: CLIENT KEY EXCHANGE (16) was received. Length 134[134], frag offset 0, frag length: 134, sequence: 0
ocserv[13475]: TLS[<5>]: REC[0x8e008]: SSL 3.3 ChangeCipherSpec packet received. Epoch 0, length: 1
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Expected Packet ChangeCipherSpec(20)
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Received Packet ChangeCipherSpec(20) with length: 1
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Decrypted Packet[3] ChangeCipherSpec(20) with length: 1
ocserv[13475]: TLS[<9>]: INT: PREMASTER SECRET[66]: xxxxxxxxxxxxxxxxxx
ocserv[13475]: TLS[<9>]: INT: CLIENT RANDOM[32]: xxxxxxxxxxxxxxxxxx
ocserv[13475]: TLS[<9>]: INT: SERVER RANDOM[32]: xxxxxxxxxxxxxxxxxx
ocserv[13475]: TLS[<9>]: INT: MASTER SECRET: xxxxxxxxxxxxxxxxxxx
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Initializing epoch #1
ocserv[13475]: TLS[<9>]: INT: KEY BLOCK[72]: xxxxxxxxxxxxxxxxxx
ocserv[13475]: TLS[<9>]: INT: CLIENT WRITE KEY [32]: xxxxxxxxxxxxxxxxxx
ocserv[13475]: TLS[<9>]: INT: SERVER WRITE KEY [32]: xxxxxxxxxxxxxxxxxx
ocserv[13475]: TLS[<9>]: INT: CLIENT WRITE IV [4]: xxxxxxxxxxxxxxxxxx
ocserv[13475]: TLS[<9>]: INT: SERVER WRITE IV [4]: xxxxxxxxxxxxxxxxxx
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Epoch #1 ready
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Cipher Suite: ECDHE_RSA_AES_256_GCM_SHA384
ocserv[13475]: TLS[<3>]: ASSERT: buffers.c[get_last_packet]:1159
ocserv[13475]: TLS[<5>]: REC[0x8e008]: SSL 3.3 Handshake packet received. Epoch 0, length: 40
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Expected Packet Handshake(22)
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Received Packet Handshake(22) with length: 40
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Decrypted Packet[0] Handshake(22) with length: 16
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: FINISHED (20) was received. Length 12[12], frag offset 0, frag length: 12, sequence: 0
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: recording tls-unique CB (recv)
ocserv[13475]: TLS[<4>]: REC[0x8e008]: Sent ChangeCipherSpec
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Cipher Suite: ECDHE_RSA_AES_256_GCM_SHA384
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: Initializing internal [write] cipher sessions
ocserv[13475]: TLS[<4>]: HSK[0x8e008]: FINISHED was queued [16 bytes]
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Preparing Packet ChangeCipherSpec(20) with length: 1 and min pad: 0
ocserv[13475]: TLS[<9>]: ENC[0x8e008]: cipher: NULL, MAC: MAC-NULL, Epoch: 0
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Sent Packet[6] ChangeCipherSpec(20) in epoch 0 and length: 6
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Preparing Packet Handshake(22) with length: 16 and min pad: 0
ocserv[13475]: TLS[<9>]: ENC[0x8e008]: cipher: AES-256-GCM, MAC: AEAD, Epoch: 1
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Sent Packet[1] Handshake(22) in epoch 1 and length: 45
ocserv[13465]: sec-mod: received request from pid 13475 and uid 65534
ocserv[13475]: worker:  sending message 'resume data store request' to secmod
ocserv[13465]: sec-mod: cmd [size=363] resume data store request
ocserv[13465]: sec-mod: TLS session DB storing xxxxxxxxxxxxxxxxxx
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Start of epoch cleanup
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Epoch #0 freed
ocserv[13475]: TLS[<5>]: REC[0x8e008]: End of epoch cleanup
ocserv[13475]: worker:  TLS handshake completed
ocserv[13475]: worker:  sending message 'session info' to main
ocserv[13464]: main: 63.197.197.76:49563 main received worker's message 'session info' of 6 bytes
ocserv[13475]: TLS[<5>]: REC[0x8e008]: SSL 3.3 Application Data packet received. Epoch 0, length: 1197
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Expected Packet Application Data(23)
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Received Packet Application Data(23) with length: 1197
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Decrypted Packet[1] Application Data(23) with length: 1173
ocserv[13475]: worker: 63.197.197.76 HTTP processing: Host: moab.savoirtech.com
ocserv[13475]: worker: 63.197.197.76 HTTP processing: User-Agent: Cisco AnyConnect VPN Agent for Apple iPhone 4.0.05066
ocserv[13475]: worker: 63.197.197.76 User-agent: 'Cisco AnyConnect VPN Agent for Apple iPhone 4.0.05066'
ocserv[13475]: worker: 63.197.197.76 HTTP processing: Cookie: webvpn=xxxxxxxxxxxxxxxxxx=
ocserv[13475]: worker: 63.197.197.76 HTTP processing: X-CSTP-Version: 1
ocserv[13475]: worker: 63.197.197.76 HTTP processing: X-CSTP-Hostname: Virus
ocserv[13475]: worker: 63.197.197.76 HTTP processing: X-CSTP-MTU: 1184
ocserv[13475]: worker: 63.197.197.76 HTTP processing: X-CSTP-Address-Type: IPv6,IPv4
ocserv[13475]: worker: 63.197.197.76 HTTP processing: X-CSTP-Local-Address-IP4: 63.197.197.76
ocserv[13475]: worker: 63.197.197.76 HTTP processing: X-CSTP-Base-MTU: 1404
ocserv[13475]: worker: 63.197.197.76 HTTP processing: X-CSTP-Remote-Address-IP4: 67.82.83.84
ocserv[13475]: worker: 63.197.197.76 HTTP processing: X-CSTP-Full-IPv6-Capability: true
ocserv[13475]: worker: 63.197.197.76 HTTP processing: X-CSTP-License: mobile
ocserv[13475]: worker: 63.197.197.76 HTTP processing: X-AnyConnect-Identifier-ClientVersion: 4.0.05066
ocserv[13475]: worker: 63.197.197.76 HTTP processing: X-AnyConnect-Identifier-Platform: apple-ios
ocserv[13475]: worker: 63.197.197.76 Platform: 'apple-ios' (mobile)
ocserv[13475]: worker: 63.197.197.76 HTTP processing: X-AnyConnect-Identifier-PlatformVersion: 10.3.1
ocserv[13475]: worker: 63.197.197.76 HTTP processing: X-AnyConnect-Identifier-DeviceType: iPhone9,4
ocserv[13475]: worker: 63.197.197.76 Device-type: 'iPhone9,4'
ocserv[13475]: worker: 63.197.197.76 HTTP processing: X-AnyConnect-Identifier-Device-UniqueID: xxxxxxxxxxxxxxxxxx
ocserv[13475]: worker: 63.197.197.76 HTTP processing: X-AnyConnect-Identifier-Device-MacAddress: unknown
ocserv[13475]: worker: 63.197.197.76 HTTP processing: X-AnyConnect-Identifier-Device-Imei: unknown
ocserv[13475]: worker: 63.197.197.76 HTTP processing: X-DTLS-Master-Secret: xxxxxxxxxxxxxxxxxx
ocserv[13475]: worker: 63.197.197.76 HTTP processing: X-DTLS-CipherSuite: AES256-SHA:AES128-SHA:DES-CBC3-SHA
ocserv[13475]: worker: 63.197.197.76 HTTP processing: X-DTLS-Accept-Encoding: lzs
ocserv[13475]: worker: 63.197.197.76 HTTP processing: X-DTLS-Header-Pad-Length: 0
ocserv[13475]: worker: 63.197.197.76 HTTP processing: X-CSTP-Accept-Encoding: lzs
ocserv[13475]: worker: 63.197.197.76 HTTP processing: X-CSTP-Protocol: Copyright (c) 2004 Cisco Systems, Inc.
ocserv[13475]: worker: 63.197.197.76 HTTP processing: X-CSTP-TCP-Keepalive: false
ocserv[13475]: worker: 63.197.197.76 HTTP CONNECT /CSCOSSLC/tunnel
ocserv[13475]: worker: 63.197.197.76 sending message 'auth cookie request' to main
ocserv[13464]: main: 63.197.197.76:49563 main received worker's message 'auth cookie request' of 34 bytes
ocserv[13464]: main: 63.197.197.76:49563 sending msg sm: session open to sec-mod
ocserv[13465]: sec-mod: received request sm: session open
ocserv[13465]: sec-mod: cmd [size=34] sm: session open
ocserv[13465]: sec-mod: session open but with non-existing SID!
ocserv[13464]: main: 63.197.197.76:49563 could not initiate session
ocserv[13464]: main: 63.197.197.76:49563 could not open session
ocserv[13464]: main: 63.197.197.76:49563 failed authentication attempt for user ''
ocserv[13464]: main: 63.197.197.76:49563 sending message 'auth cookie reply' to worker
ocserv[13475]: worker: 63.197.197.76 received auth reply message (value: 3)
ocserv[13475]: worker: 63.197.197.76 error receiving cookie authentication reply
ocserv[13475]: worker: 63.197.197.76 failed cookie authentication attempt
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Preparing Packet Application Data(23) with length: 41 and min pad: 0
ocserv[13475]: TLS[<9>]: ENC[0x8e008]: cipher: AES-256-GCM, MAC: AEAD, Epoch: 1
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Sent Packet[2] Application Data(23) in epoch 1 and length: 70
ocserv[13475]: TLS[<5>]: REC: Sending Alert[2|49] - Access was denied
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Preparing Packet Alert(21) with length: 2 and min pad: 0
ocserv[13475]: TLS[<9>]: ENC[0x8e008]: cipher: AES-256-GCM, MAC: AEAD, Epoch: 1
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Sent Packet[3] Alert(21) in epoch 1 and length: 31
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Start of epoch cleanup
ocserv[13475]: TLS[<5>]: REC[0x8e008]: End of epoch cleanup
ocserv[13475]: TLS[<5>]: REC[0x8e008]: Epoch #1 freed
ocserv[13464]: main: 63.197.197.76:49563 worker terminated
ocserv[13464]: main: 63.197.197.76:49563 user disconnected (reason: unspecified, rx: 0, tx: 0)

Any ideas on how to fix this and keep the connection stable?  I am running ocserv 0.11.7 Compiled with: AnyConnect GnuTLS version: 3.5.9.

Thanks!

More information about the openconnect-devel mailing list