Problem with establishing VPN connections with client

Thu Nov 14 13:12:39 EST 2013

I don't think the problem is from ipv6 since neither my box nor my phone 
has ipv6 connection. And ipv6 entries were commented out in the conf file.

I'm not quite sure about what does this log tell, does it look legit?

Nov 15 03:07:00 hostname ocserv[2861]: [client.ip.addr]:31328 passed UDP 
socket
Nov 15 03:07:00 hostname ocserv[2864]: [client.ip.addr]:31328 TCP MSS is 499
Nov 15 03:07:00 hostname ocserv[2864]: [client.ip.addr]:31328 reducing 
MTU due to TCP MSS to 470
Nov 15 03:07:00 hostname ocserv[2864]: [client.ip.addr]:31328 setting 
MTU to 470
Nov 15 03:07:00 hostname ocserv[2861]: [client.ip.addr]:31328 setting 
vpns0 MTU to 469
Nov 15 03:07:00 hostname ocserv[2864]: [client.ip.addr]:31328 received 
new UDP fd and connected to peer
Nov 15 03:07:00 hostname ocserv[2864]: [client.ip.addr]:31328 setting up 
DTLS connection
Nov 15 03:07:00 hostname ocserv[2864]: TLS[<4>]: REC[0x8919a00]: 
Allocating epoch #0
Nov 15 03:07:00 hostname ocserv[2864]: TLS[<2>]: ASSERT: 
gnutls_constate.c:581
Nov 15 03:07:00 hostname ocserv[2864]: TLS[<4>]: REC[0x8919a00]: 
Allocating epoch #1
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<2>]: ASSERT: 
gnutls_buffers.c:1022
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<4>]: REC[0x8919a00]: SSL 1.0 
Handshake packet received. Epoch 0, length: 101
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<4>]: REC[0x8919a00]: 
Expected Packet Handshake(22)
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<4>]: REC[0x8919a00]: 
Received Packet Handshake(22) with length: 101
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<4>]: REC[0x8919a00]: 
Decrypted Packet[0.0] Handshake(22) with length: 101
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<3>]: HSK[0x8919a00]: CLIENT 
HELLO (1) was received. Length 89[89], frag offset 0, frag length: 89, 
sequence: 0
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<3>]: HSK[0x8919a00]: 
Client's version: 1.0
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<3>]: EXT[0x8919a00]: Found 
extension 'STATUS REQUEST/5'
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<3>]: EXT[0x8919a00]: Parsing 
extension 'SESSION TICKET/35' (0 bytes)
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<2>]: ASSERT: 
safe_renegotiation.c:100
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<2>]: ASSERT: 
safe_renegotiation.c:374
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<3>]: HSK[0x8919a00]: 
SessionID: session-id
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<3>]: HSK[0x8919a00]: SERVER 
HELLO was queued [82 bytes]
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<3>]: REC[0x8919a00]: Sent 
ChangeCipherSpec
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<9>]: INT: PREMASTER 
SECRET[48]: premaster-secret
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<9>]: INT: CLIENT RANDOM[32]: 
client-random
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<9>]: INT: SERVER RANDOM[32]: 
server-random
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<9>]: INT: MASTER SECRET: 
master-secret
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<4>]: REC[0x8919a00]: 
Initializing epoch #1
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<9>]: INT: KEY BLOCK[104]: 
key-block
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<9>]: INT: CLIENT WRITE KEY 
[16]: client-write-key
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<9>]: INT: SERVER WRITE KEY 
[16]: server-write-key
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<4>]: REC[0x8919a00]: Epoch 
#1 ready
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<3>]: HSK[0x8919a00]: Cipher 
Suite: RSA_AES_128_CBC_SHA1
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<3>]: HSK[0x8919a00]: 
Initializing internal [write] cipher sessions
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<3>]: HSK[0x8919a00]: 
recording tls-unique CB (send)
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<3>]: HSK[0x8919a00]: 
FINISHED was queued [24 bytes]
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<6>]: DTLS[0x8919a00]: Start 
of flight transmission.
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<6>]: DTLS[0x8919a00]: 
Sending Packet[0] fragment SERVER HELLO(2) with length: 70, offset: 0, 
fragment length: 70
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<4>]: REC[0x8919a00]: 
Preparing Packet Handshake(22) with length: 82 and target length: 82
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<9>]: ENC[0x8919a00]: cipher: 
NULL, MAC: MAC-NULL, Epoch: 0
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<4>]: REC[0x8919a00]: Sent 
Packet[1] Handshake(22) in epoch 0 and length: 95
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<6>]: DTLS[0x8919a00]: 
Sending Packet[1] fragment CHANGE CIPHER SPEC(254)
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<4>]: REC[0x8919a00]: 
Preparing Packet ChangeCipherSpec(20) with length: 3 and target length: 3
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<9>]: ENC[0x8919a00]: cipher: 
NULL, MAC: MAC-NULL, Epoch: 0
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<4>]: REC[0x8919a00]: Sent 
Packet[2] ChangeCipherSpec(20) in epoch 0 and length: 16
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<6>]: DTLS[0x8919a00]: 
Sending Packet[2] fragment FINISHED(20) with length: 12, offset: 0, 
fragment length: 12
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<4>]: REC[0x8919a00]: 
Preparing Packet Handshake(22) with length: 24 and target length: 24
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<9>]: ENC[0x8919a00]: cipher: 
AES-128-CBC, MAC: SHA1, Epoch: 1
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<2>]: ASSERT: mac.c:253
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<4>]: REC[0x8919a00]: Sent 
Packet[1] Handshake(22) in epoch 1 and length: 77
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<2>]: ASSERT: 
gnutls_buffers.c:171
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<2>]: ASSERT: 
gnutls_buffers.c:511
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<2>]: ASSERT: 
gnutls_record.c:1046
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<2>]: ASSERT: 
gnutls_record.c:1158
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<2>]: ASSERT: 
gnutls_record.c:1295
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<2>]: ASSERT: 
gnutls_record.c:1388
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<2>]: ASSERT: 
gnutls_handshake.c:2996
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<2>]: ASSERT: 
gnutls_buffers.c:515
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<2>]: ASSERT: 
gnutls_record.c:1046
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<2>]: ASSERT: 
gnutls_record.c:1158
Nov 15 03:07:01 hostname ocserv[2864]: TLS[<2>]: ASSERT: 
gnutls_record.c:1388
Nov 15 03:07:01 hostname ocserv[2864]: [client.ip.addr]:31328 received 
-110 byte(s) (TLS)
Nov 15 03:07:01 hostname ocserv[2864]: GnuTLS error (at 
worker-vpn.c:1161): The TLS connection was non-properly terminated.

Thanks,
TZ

On 11/14/2013 12:13 PM, Nikos Mavrogiannopoulos wrote:
> On Thu, 2013-11-14 at 11:19 -0500, Tony Zhou wrote:
>> Hi Nikos,
>> SmoothConnect is based on Openconnect (as it claims), so I guess it
>> behaves similarly... It prompts in client log after connected:
>> Connected (null) as 192.168.1.1+ipv6 addr, using SSL
>> Error: opening vpnc socket
>
> I downloaded that smoothconnect app, and I could connect to ocserv with
> the default sample.conf included in the distribution. You could start
> with that and find out which option smoothconnect doesn't like (could it
> be ipv6?).
>
> regards,
> Nikos
>
>