Handshake fails with server running OpenSSL 1.0.2h-fips

jfrtree

Having trouble completing a connection when the server is running in FIPS mode. The following error is logged while executing HMAC_Init_ex

Tue Oct 04 12:12:32 2016 us=114821 10.2.14.215:1527 OpenSSL: error:060A80A3:digital envelope routines:FIPS_DIGESTINIT:disabled for fips

1. Does this mean the SSL keys need to be regenerated for the client cert? The keys we have are already using FIPS compliant algorithms and this seems unlikely

2. Or Is the digest in question being calculated by openvpn client code? The client is not running in FIPS mode, only the server is.

The below values are also configured in the client/server profiles in an attempt to avoid FIPS errors on the server side.

auth SHA256
cipher AES-256-CBC
tls-version-min 1.2
tls-cipher TLS-ECDHE-RSA-WITH-AES-128-GCM-SHA256:TLS-ECDHE-ECDSA-WITH-AES-128-GCM-SHA256:TLS-ECDHE-RSA-WITH-AES-256-GCM-SHA384:TLS-DHE-RSA-WITH-AES-256-CBC-SHA256

TinCanTech

jfrtree wrote The client is not running in FIPS mode, only the server is

Does that not break FIPS mode altogether ?

jfrtree

The mechanism is to enforce that the local crypto module rejects the use of algorithms that are not FIPS 140-2 compliant. If data is protected with an approved cipher, it should not matter whether it originated from an app running certified or non-certified code. The bytes should be identical in both cases.

But if someone can confirm that this is not the case with openvpn, that would be helpful.

TinCanTech

Do you know which versions of openvpn you are using ?

jfrtree

This is openvpn 2.3.11

TinCanTech

Server and Client configs and logs please.

https://forums.openvpn.net/viewtopic.php?f=30&t=21589#p61072

jfrtree

Tested again running exact same versions of client & server code.
OpenVPN 2.3.11 x86_64-w64-mingw32
OpenSSL 1.0.2h-fips

Still cannot connect. All certs & keys were generated using the same openssl version & fips mode. Again, same configs and certificates able to connect in non-fips mode.
port 1194
proto udp
dev tun
dev-node "OpenVPNTap"
topology subnet
persist-key
persist-tun
keepalive 10 60
auth SHA256
cipher AES-256-CBC
tls-version-min 1.2
tls-cipher TLS-ECDHE-RSA-WITH-AES-128-GCM-SHA256:TLS-ECDHE-ECDSA-WITH-AES-128-GCM-SHA256:TLS-ECDHE-RSA-WITH-AES-256-GCM-SHA384:TLS-DHE-RSA-WITH-AES-256-CBC-SHA256

# Configure server mode and supply a VPN subnet
# for OpenVPN to draw client addresses from.
# The server will take 10.8.0.1 for itself,
# the rest will be made available to clients.
# Each client will be able to reach the server
# on 10.8.0.1. Comment this line out if you are
# ethernet bridging. See the man page for more info.
#server 192.168.1.0 255.255.255.0
server 10.8.0.0 255.255.255.224

dh "C:\\Program Files\\OpenVPN\\config\\dh1024.pem"
ca "C:\\Program Files\\OpenVPN\\config\\ca.crt"
cert "C:\\Program Files\\OpenVPN\\config\\server.crt"
key "C:\\Program Files\\OpenVPN\\config\\server.key" # This file should be kept secret

verb 11
local 10.121.176.118
push "dhcp-option DNS 10.2.14.116"
push "redirect-gateway def1" client
dev tun
remote testlab.internal.com 1194 udp
redirect-gateway def1
nobind
persist-key
persist-tun
verb 15
auth none #SHA256
cipher AES-256-CBC
tls-version-min 1.2
tls-cipher TLS-ECDHE-RSA-WITH-AES-128-GCM-SHA256:TLS-ECDHE-ECDSA-WITH-AES-128-GCM-SHA256:TLS-ECDHE-RSA-WITH-AES-256-GCM-SHA384:TLS-DHE-RSA-WITH-AES-256-CBC-SHA256

Thu Oct 06 09:08:31 2016 us=815364 WIN32 I/O: Socket Completion success [14]
Thu Oct 06 09:08:31 2016 us=815364 UDPv4 read returned 14
Thu Oct 06 09:08:31 2016 us=815364 MULTI: multi_create_instance called
Thu Oct 06 09:08:31 2016 us=815364 10.2.14.215:9879 Re-using SSL/TLS context
Thu Oct 06 09:08:31 2016 us=815364 10.2.14.215:9879 crypto_adjust_frame_parameters: Adjusting frame parameters for crypto by zu bytes
Thu Oct 06 09:08:31 2016 us=815364 10.2.14.215:9879 TLS: tls_session_init: entry
Thu Oct 06 09:08:31 2016 us=815364 10.2.14.215:9879 PID packet_id_init tcp_mode=0 seq_backtrack=64 time_backtrack=15
Thu Oct 06 09:08:31 2016 us=815364 10.2.14.215:9879 PID packet_id_init tcp_mode=0 seq_backtrack=64 time_backtrack=15
Thu Oct 06 09:08:31 2016 us=815364 10.2.14.215:9879 TLS: tls_session_init: new session object, sid=3fa897b5 c4f5dcfd
Thu Oct 06 09:08:31 2016 us=815364 10.2.14.215:9879 TLS: tls_session_init: entry
Thu Oct 06 09:08:31 2016 us=815364 10.2.14.215:9879 PID packet_id_init tcp_mode=0 seq_backtrack=64 time_backtrack=15
Thu Oct 06 09:08:31 2016 us=815364 10.2.14.215:9879 PID packet_id_init tcp_mode=0 seq_backtrack=64 time_backtrack=15
Thu Oct 06 09:08:31 2016 us=815364 10.2.14.215:9879 TLS: tls_session_init: new session object, sid=e45c995e cf12217c
Thu Oct 06 09:08:31 2016 us=815364 10.2.14.215:9879 Control Channel MTU parms [ L:1569 D:1212 EF:38 EB:0 ET:0 EL:3 ]
Thu Oct 06 09:08:31 2016 us=815364 10.2.14.215:9879 MTU DYNAMIC mtu=1450, flags=2, 1569 -> 1450
Thu Oct 06 09:08:31 2016 us=815364 10.2.14.215:9879 Data Channel MTU parms [ L:1569 D:1450 EF:69 EB:12 ET:0 EL:3 ]
Thu Oct 06 09:08:31 2016 us=815364 10.2.14.215:9879 Local Options String: 'V4,dev-type tun,link-mtu 1569,tun-mtu 1500,proto UDPv4,cipher AES-256-CBC,auth SHA256,keysize 256,key-method 2,tls-server'
Thu Oct 06 09:08:31 2016 us=815364 10.2.14.215:9879 Expected Remote Options String: 'V4,dev-type tun,link-mtu 1569,tun-mtu 1500,proto UDPv4,cipher AES-256-CBC,auth SHA256,keysize 256,key-method 2,tls-client'
Thu Oct 06 09:08:31 2016 us=815364 10.2.14.215:9879 Local Options hash (VER=V4): '0400003e'
Thu Oct 06 09:08:31 2016 us=815364 10.2.14.215:9879 Expected Remote Options hash (VER=V4): '0400003e'
Thu Oct 06 09:08:31 2016 us=815364 10.2.14.215:9879 SENT PING
Thu Oct 06 09:08:31 2016 us=815364 10.2.14.215:9879 TIMER: coarse timer wakeup 1 seconds
Thu Oct 06 09:08:31 2016 us=815364 10.2.14.215:9879 TLS: tls_multi_process: i=0 state=S_INITIAL, mysid=3fa897b5 c4f5dcfd, stored-sid=00000000 00000000, stored-ip=[undef]
Thu Oct 06 09:08:31 2016 us=815364 10.2.14.215:9879 TLS: tls_multi_process: i=1 state=S_INITIAL, mysid=e45c995e cf12217c, stored-sid=00000000 00000000, stored-ip=[undef]
Thu Oct 06 09:08:31 2016 us=815364 10.2.14.215:9879 TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[undef]
Thu Oct 06 09:08:31 2016 us=815364 10.2.14.215:9879 RANDOM USEC=192746
Thu Oct 06 09:08:31 2016 us=815364 10.2.14.215:9879 SCHEDULE: schedule_add_modify wakeup=[Thu Oct 06 09:08:33 2016 us=8110] pri=0
Thu Oct 06 09:08:31 2016 us=815364 10.2.14.215:9879 GET INST BY REAL: 10.2.14.215:9879 [created]
Thu Oct 06 09:08:31 2016 us=816364 10.2.14.215:9879 UDPv4 READ [14] from [AF_INET]10.2.14.215:9879: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 sid=6ef2de50 551e6bae [ ] pid=0 DATA 
Thu Oct 06 09:08:31 2016 us=816364 10.2.14.215:9879 TLS: control channel, op=P_CONTROL_HARD_RESET_CLIENT_V2, IP=[AF_INET]10.2.14.215:9879
Thu Oct 06 09:08:31 2016 us=816364 10.2.14.215:9879 TLS: initial packet test, i=0 state=S_INITIAL, mysid=3fa897b5 c4f5dcfd, rec-sid=6ef2de50 551e6bae, rec-ip=[AF_INET]10.2.14.215:9879, stored-sid=00000000 00000000, stored-ip=[undef]
Thu Oct 06 09:08:31 2016 us=816364 10.2.14.215:9879 TLS: initial packet test, i=1 state=S_INITIAL, mysid=e45c995e cf12217c, rec-sid=6ef2de50 551e6bae, rec-ip=[AF_INET]10.2.14.215:9879, stored-sid=00000000 00000000, stored-ip=[undef]
Thu Oct 06 09:08:31 2016 us=816364 10.2.14.215:9879 TLS: initial packet test, i=2 state=S_UNDEF, mysid=00000000 00000000, rec-sid=6ef2de50 551e6bae, rec-ip=[AF_INET]10.2.14.215:9879, stored-sid=00000000 00000000, stored-ip=[undef]
Thu Oct 06 09:08:31 2016 us=816364 10.2.14.215:9879 TLS: Initial packet from [AF_INET]10.2.14.215:9879, sid=6ef2de50 551e6bae
Thu Oct 06 09:08:31 2016 us=816364 10.2.14.215:9879 TLS: received control channel packet s#=0 sid=6ef2de50 551e6bae
Thu Oct 06 09:08:31 2016 us=816364 10.2.14.215:9879 ACK reliable_schedule_now
Thu Oct 06 09:08:31 2016 us=816364 10.2.14.215:9879 ACK read ID 0 (buf->len=0)
Thu Oct 06 09:08:31 2016 us=816364 10.2.14.215:9879 ACK RWBS rel->size=8 rel->packet_id=00000000 id=00000000 ret=1

Thu Oct 06 09:08:31 2016 us=816364 10.2.14.215:9879 ACK mark active incoming ID 0
Thu Oct 06 09:08:31 2016 us=816364 10.2.14.215:9879 ACK acknowledge ID 0 (ack->len=1)
Thu Oct 06 09:08:31 2016 us=816364 10.2.14.215:9879 TLS: tls_multi_process: i=0 state=S_INITIAL, mysid=3fa897b5 c4f5dcfd, stored-sid=6ef2de50 551e6bae, stored-ip=[AF_INET]10.2.14.215:9879
Thu Oct 06 09:08:31 2016 us=816364 10.2.14.215:9879 TLS: tls_process: chg=0 ks=S_INITIAL lame=S_UNDEF to_link->len=0 wakeup=604800
Thu Oct 06 09:08:31 2016 us=816364 10.2.14.215:9879 ACK mark active outgoing ID 0
Thu Oct 06 09:08:31 2016 us=816364 10.2.14.215:9879 TLS: Initial Handshake, sid=3fa897b5 c4f5dcfd
Thu Oct 06 09:08:31 2016 us=816364 10.2.14.215:9879 ACK reliable_can_send active=1 current=1 : [1] 0
Thu Oct 06 09:08:31 2016 us=816364 10.2.14.215:9879 ACK reliable_send ID 0 (size=4 to=2)
Thu Oct 06 09:08:31 2016 us=816364 10.2.14.215:9879 ACK write ID 0 (ack->len=1, n=1)
Thu Oct 06 09:08:31 2016 us=816364 10.2.14.215:9879 Reliable -> TCP/UDP
Thu Oct 06 09:08:31 2016 us=816364 10.2.14.215:9879 ACK reliable_send_timeout 2 [1] 0
Thu Oct 06 09:08:31 2016 us=816364 10.2.14.215:9879 TLS: tls_process: timeout set to 2
Thu Oct 06 09:08:31 2016 us=816364 10.2.14.215:9879 TLS: tls_multi_process: i=1 state=S_INITIAL, mysid=e45c995e cf12217c, stored-sid=00000000 00000000, stored-ip=[undef]
Thu Oct 06 09:08:31 2016 us=816364 10.2.14.215:9879 TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[undef]
Thu Oct 06 09:08:31 2016 us=816364 SCHEDULE: schedule_find_least wakeup=[Thu Oct 06 09:08:33 2016 us=8110] pri=27756
Thu Oct 06 09:08:31 2016 us=816364 WE_CTL n=0 ev=00000000004D6BE8 rwflags=0x0001 arg=0x494080
Thu Oct 06 09:08:31 2016 us=816364 WE_CTL n=1 ev=0000000000C2F920 rwflags=0x0002 arg=0x4cf0a0
Thu Oct 06 09:08:31 2016 us=816364 WE_CTL n=2 ev=0000000000C052B8 rwflags=0x0000 arg=0x494084
Thu Oct 06 09:08:31 2016 us=816364 I/O WAIT TrQ|Tw0|Sr0|SW0 [1/191746]
Thu Oct 06 09:08:31 2016 us=816364 WE_WAIT enter n=2 to=1192
Thu Oct 06 09:08:31 2016 us=816364 [0] ev=0000000000000104 rwflags=0x0001 arg=0x494080
Thu Oct 06 09:08:31 2016 us=816364 [1] ev=0000000000000148 rwflags=0x0002 arg=0x4cf0a0
Thu Oct 06 09:08:31 2016 us=816364 WE_WAIT leave [1,0] rwflags=0x0002 arg=0x4cf0a0
Thu Oct 06 09:08:31 2016 us=816364  event_wait returned 1
Thu Oct 06 09:08:31 2016 us=816364 I/O WAIT status=0x0002
Thu Oct 06 09:08:31 2016 us=816364 10.2.14.215:9879 UDPv4 WRITE [26] to [AF_INET]10.2.14.215:9879: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 sid=3fa897b5 c4f5dcfd [ 0 sid=6ef2de50 551e6bae ] pid=0 DATA 
Thu Oct 06 09:08:31 2016 us=816364 10.2.14.215:9879 WIN32 I/O: Socket Send immediate return [26,26]
Thu Oct 06 09:08:31 2016 us=816364 10.2.14.215:9879 UDPv4 write returned 26
Thu Oct 06 09:08:31 2016 us=816364 10.2.14.215:9879 TLS: tls_multi_process: i=0 state=S_PRE_START, mysid=3fa897b5 c4f5dcfd, stored-sid=6ef2de50 551e6bae, stored-ip=[AF_INET]10.2.14.215:9879
Thu Oct 06 09:08:31 2016 us=816364 10.2.14.215:9879 TLS: tls_process: chg=0 ks=S_PRE_START lame=S_UNDEF to_link->len=0 wakeup=604800
Thu Oct 06 09:08:31 2016 us=816364 10.2.14.215:9879 ACK reliable_can_send active=1 current=0 : [1] 0
Thu Oct 06 09:08:31 2016 us=816364 10.2.14.215:9879 Incoming Ciphertext -> TLS
Thu Oct 06 09:08:31 2016 us=816364 10.2.14.215:9879 SSL state (accept): before/accept initialization
Thu Oct 06 09:08:31 2016 us=816364 10.2.14.215:9879 TLS: tls_process: chg=1 ks=S_PRE_START lame=S_UNDEF to_link->len=0 wakeup=604800
Thu Oct 06 09:08:31 2016 us=816364 10.2.14.215:9879 ACK reliable_can_send active=1 current=0 : [1] 0
Thu Oct 06 09:08:31 2016 us=816364 10.2.14.215:9879 ACK reliable_send_timeout 2 [1] 0
Thu Oct 06 09:08:31 2016 us=816364 10.2.14.215:9879 TLS: tls_process: timeout set to 2
Thu Oct 06 09:08:31 2016 us=816364 10.2.14.215:9879 TLS: tls_multi_process: i=1 state=S_INITIAL, mysid=e45c995e cf12217c, stored-sid=00000000 00000000, stored-ip=[undef]
Thu Oct 06 09:08:31 2016 us=816364 10.2.14.215:9879 TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[undef]
Thu Oct 06 09:08:31 2016 us=816364 WE_CTL n=0 ev=00000000004D6BE8 rwflags=0x0001 arg=0x494080
Thu Oct 06 09:08:31 2016 us=816364 WIN32 I/O: Socket Receive queued [1572]
Thu Oct 06 09:08:31 2016 us=816364 WE_CTL n=1 ev=0000000000C2F920 rwflags=0x0001 arg=0x4cf0a0
Thu Oct 06 09:08:31 2016 us=816364 WE_CTL n=2 ev=0000000000C052B8 rwflags=0x0001 arg=0x494084
Thu Oct 06 09:08:31 2016 us=816364 I/O WAIT TRQ|Tw0|SRQ|Sw1 [1/191746]
Thu Oct 06 09:08:31 2016 us=816364 WE_WAIT enter n=3 to=1192
Thu Oct 06 09:08:31 2016 us=816364 [0] ev=0000000000000104 rwflags=0x0001 arg=0x494080
Thu Oct 06 09:08:31 2016 us=816364 [1] ev=0000000000000184 rwflags=0x0001 arg=0x4cf0a0
Thu Oct 06 09:08:31 2016 us=816364 [2] ev=0000000000000120 rwflags=0x0001 arg=0x494084
Thu Oct 06 09:08:31 2016 us=882395 WE_WAIT leave rwflags=0x0001 arg=0x4cf0a0
Thu Oct 06 09:08:31 2016 us=882395  event_wait returned 1
Thu Oct 06 09:08:31 2016 us=882395 I/O WAIT status=0x0001
Thu Oct 06 09:08:31 2016 us=882395 WIN32 I/O: Socket Completion success [22]
Thu Oct 06 09:08:31 2016 us=882395 UDPv4 read returned 22
Thu Oct 06 09:08:31 2016 us=882395 GET INST BY REAL: 10.2.14.215:9879 [succeeded]
Thu Oct 06 09:08:31 2016 us=883397 10.2.14.215:9879 UDPv4 READ [22] from [AF_INET]10.2.14.215:9879: P_ACK_V1 kid=0 sid=6ef2de50 551e6bae [ 0 sid=3fa897b5 c4f5dcfd ]
Thu Oct 06 09:08:31 2016 us=883397 10.2.14.215:9879 TLS: control channel, op=P_ACK_V1, IP=[AF_INET]10.2.14.215:9879
Thu Oct 06 09:08:31 2016 us=883397 10.2.14.215:9879 TLS: initial packet test, i=0 state=S_PRE_START, mysid=3fa897b5 c4f5dcfd, rec-sid=6ef2de50 551e6bae, rec-ip=[AF_INET]10.2.14.215:9879, stored-sid=6ef2de50 551e6bae, stored-ip=[AF_INET]10.2.14.215:9879
Thu Oct 06 09:08:31 2016 us=883397 10.2.14.215:9879 TLS: found match, session[0], sid=6ef2de50 551e6bae
Thu Oct 06 09:08:31 2016 us=883397 10.2.14.215:9879 TLS: received control channel packet s#=0 sid=6ef2de50 551e6bae
Thu Oct 06 09:08:31 2016 us=883397 10.2.14.215:9879 ACK received for pid 0, deleting from send buffer
Thu Oct 06 09:08:31 2016 us=883397 10.2.14.215:9879 TLS: tls_multi_process: i=0 state=S_PRE_START, mysid=3fa897b5 c4f5dcfd, stored-sid=6ef2de50 551e6bae, stored-ip=[AF_INET]10.2.14.215:9879
Thu Oct 06 09:08:31 2016 us=883397 10.2.14.215:9879 TLS: tls_process: chg=0 ks=S_PRE_START lame=S_UNDEF to_link->len=0 wakeup=604800
Thu Oct 06 09:08:31 2016 us=883397 10.2.14.215:9879 STATE S_START
Thu Oct 06 09:08:31 2016 us=883397 10.2.14.215:9879 ACK reliable_can_send active=0 current=0 : [1]
Thu Oct 06 09:08:31 2016 us=883397 10.2.14.215:9879 TLS: tls_process: chg=1 ks=S_START lame=S_UNDEF to_link->len=0 wakeup=604800
Thu Oct 06 09:08:31 2016 us=883397 10.2.14.215:9879 ACK reliable_can_send active=0 current=0 : [1]
Thu Oct 06 09:08:31 2016 us=883397 10.2.14.215:9879 ACK reliable_send_timeout 604800 [1]
Thu Oct 06 09:08:31 2016 us=883397 10.2.14.215:9879 TLS: tls_process: timeout set to 60
Thu Oct 06 09:08:31 2016 us=883397 10.2.14.215:9879 TLS: tls_multi_process: i=1 state=S_INITIAL, mysid=e45c995e cf12217c, stored-sid=00000000 00000000, stored-ip=[undef]
Thu Oct 06 09:08:31 2016 us=883397 10.2.14.215:9879 TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[undef]
Thu Oct 06 09:08:31 2016 us=883397 WE_CTL n=0 ev=00000000004D6BE8 rwflags=0x0001 arg=0x494080
Thu Oct 06 09:08:31 2016 us=883397 WIN32 I/O: Socket Receive queued [1572]
Thu Oct 06 09:08:31 2016 us=883397 WE_CTL n=1 ev=0000000000C2F920 rwflags=0x0001 arg=0x4cf0a0
Thu Oct 06 09:08:31 2016 us=883397 WE_CTL n=2 ev=0000000000C052B8 rwflags=0x0001 arg=0x494084
Thu Oct 06 09:08:31 2016 us=883397 I/O WAIT TRQ|Tw0|SRQ|Sw1 [1/124713]
Thu Oct 06 09:08:31 2016 us=883397 WE_WAIT enter n=3 to=1125
Thu Oct 06 09:08:31 2016 us=883397 [0] ev=0000000000000104 rwflags=0x0001 arg=0x494080
Thu Oct 06 09:08:31 2016 us=883397 [1] ev=0000000000000184 rwflags=0x0001 arg=0x4cf0a0
Thu Oct 06 09:08:31 2016 us=883397 [2] ev=0000000000000120 rwflags=0x0001 arg=0x494084
Thu Oct 06 09:08:31 2016 us=884398 WE_WAIT leave rwflags=0x0001 arg=0x4cf0a0
Thu Oct 06 09:08:31 2016 us=884398  event_wait returned 1
Thu Oct 06 09:08:31 2016 us=884398 I/O WAIT status=0x0001
Thu Oct 06 09:08:31 2016 us=884398 WIN32 I/O: Socket Completion success [179]
Thu Oct 06 09:08:31 2016 us=884398 UDPv4 read returned 179
Thu Oct 06 09:08:31 2016 us=884398 GET INST BY REAL: 10.2.14.215:9879 [succeeded]
Thu Oct 06 09:08:31 2016 us=884398 10.2.14.215:9879 UDPv4 READ [179] from [AF_INET]10.2.14.215:9879: P_CONTROL_V1 kid=0 sid=6ef2de50 551e6bae [ ] pid=1 DATA 16030100 a0010000 9c0303fc 54d46706 50d09a2f c0d81378 85bbbc8b 501286d[more...]
Thu Oct 06 09:08:31 2016 us=884398 10.2.14.215:9879 TLS: control channel, op=P_CONTROL_V1, IP=[AF_INET]10.2.14.215:9879
Thu Oct 06 09:08:31 2016 us=884398 10.2.14.215:9879 TLS: initial packet test, i=0 state=S_START, mysid=3fa897b5 c4f5dcfd, rec-sid=6ef2de50 551e6bae, rec-ip=[AF_INET]10.2.14.215:9879, stored-sid=6ef2de50 551e6bae, stored-ip=[AF_INET]10.2.14.215:9879
Thu Oct 06 09:08:31 2016 us=884398 10.2.14.215:9879 TLS: found match, session[0], sid=6ef2de50 551e6bae
Thu Oct 06 09:08:31 2016 us=884398 10.2.14.215:9879 TLS: received control channel packet s#=0 sid=6ef2de50 551e6bae
Thu Oct 06 09:08:31 2016 us=884398 10.2.14.215:9879 ACK read ID 1 (buf->len=165)
Thu Oct 06 09:08:31 2016 us=884398 10.2.14.215:9879 ACK RWBS rel->size=8 rel->packet_id=00000001 id=00000001 ret=1

Thu Oct 06 09:08:31 2016 us=884398 10.2.14.215:9879 ACK mark active incoming ID 1
Thu Oct 06 09:08:31 2016 us=884398 10.2.14.215:9879 ACK acknowledge ID 1 (ack->len=1)
Thu Oct 06 09:08:31 2016 us=884398 10.2.14.215:9879 TLS: tls_multi_process: i=0 state=S_START, mysid=3fa897b5 c4f5dcfd, stored-sid=6ef2de50 551e6bae, stored-ip=[AF_INET]10.2.14.215:9879
Thu Oct 06 09:08:31 2016 us=884398 10.2.14.215:9879 TLS: tls_process: chg=0 ks=S_START lame=S_UNDEF to_link->len=0 wakeup=604800
Thu Oct 06 09:08:31 2016 us=884398 10.2.14.215:9879 ACK reliable_can_send active=0 current=0 : [1]
Thu Oct 06 09:08:31 2016 us=884398 10.2.14.215:9879 BIO write tls_write_ciphertext 165 bytes
Thu Oct 06 09:08:31 2016 us=884398 10.2.14.215:9879 Incoming Ciphertext -> TLS
Thu Oct 06 09:08:31 2016 us=884398 10.2.14.215:9879 SSL state (accept): SSLv3 read client hello A
Thu Oct 06 09:08:31 2016 us=884398 10.2.14.215:9879 SSL state (accept): SSLv3 write server hello A
Thu Oct 06 09:08:31 2016 us=885399 10.2.14.215:9879 SSL state (accept): SSLv3 write certificate A
Thu Oct 06 09:08:31 2016 us=888398 10.2.14.215:9879 SSL state (accept): SSLv3 write key exchange A
Thu Oct 06 09:08:31 2016 us=888398 10.2.14.215:9879 SSL state (accept): SSLv3 write certificate request A
Thu Oct 06 09:08:31 2016 us=888398 10.2.14.215:9879 SSL state (accept): SSLv3 flush data
Thu Oct 06 09:08:31 2016 us=888398 10.2.14.215:9879 BIO read tls_read_ciphertext 1174 bytes
Thu Oct 06 09:08:31 2016 us=888398 10.2.14.215:9879 ACK mark active outgoing ID 1
Thu Oct 06 09:08:31 2016 us=888398 10.2.14.215:9879 Outgoing Ciphertext -> Reliable
Thu Oct 06 09:08:31 2016 us=888398 10.2.14.215:9879 TLS: tls_process: chg=1 ks=S_START lame=S_UNDEF to_link->len=0 wakeup=604800
Thu Oct 06 09:08:31 2016 us=888398 10.2.14.215:9879 ACK reliable_can_send active=1 current=1 : [2] 1
Thu Oct 06 09:08:31 2016 us=888398 10.2.14.215:9879 ACK reliable_send ID 1 (size=1178 to=2)
Thu Oct 06 09:08:31 2016 us=888398 10.2.14.215:9879 ACK write ID 1 (ack->len=1, n=1)
Thu Oct 06 09:08:31 2016 us=888398 10.2.14.215:9879 Reliable -> TCP/UDP
Thu Oct 06 09:08:31 2016 us=888398 10.2.14.215:9879 ACK reliable_send_timeout 2 [2] 1
Thu Oct 06 09:08:31 2016 us=888398 10.2.14.215:9879 TLS: tls_process: timeout set to 2
Thu Oct 06 09:08:31 2016 us=888398 10.2.14.215:9879 TLS: tls_multi_process: i=1 state=S_INITIAL, mysid=e45c995e cf12217c, stored-sid=00000000 00000000, stored-ip=[undef]
Thu Oct 06 09:08:31 2016 us=888398 10.2.14.215:9879 TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[undef]
Thu Oct 06 09:08:31 2016 us=888398 WE_CTL n=0 ev=00000000004D6BE8 rwflags=0x0001 arg=0x494080
Thu Oct 06 09:08:31 2016 us=888398 WE_CTL n=1 ev=0000000000C2F920 rwflags=0x0002 arg=0x4cf0a0
Thu Oct 06 09:08:31 2016 us=888398 WE_CTL n=2 ev=0000000000C052B8 rwflags=0x0000 arg=0x494084
Thu Oct 06 09:08:31 2016 us=888398 I/O WAIT TrQ|Tw0|Sr0|SW1 [1/119712]
Thu Oct 06 09:08:31 2016 us=888398 WE_WAIT enter n=2 to=1120
Thu Oct 06 09:08:31 2016 us=888398 [0] ev=0000000000000104 rwflags=0x0001 arg=0x494080
Thu Oct 06 09:08:31 2016 us=888398 [1] ev=0000000000000148 rwflags=0x0002 arg=0x4cf0a0
Thu Oct 06 09:08:31 2016 us=888398 WE_WAIT leave [1,0] rwflags=0x0002 arg=0x4cf0a0
Thu Oct 06 09:08:31 2016 us=888398  event_wait returned 1
Thu Oct 06 09:08:31 2016 us=888398 I/O WAIT status=0x0002
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 UDPv4 WRITE [1200] to [AF_INET]10.2.14.215:9879: P_CONTROL_V1 kid=0 sid=3fa897b5 c4f5dcfd [ 1 sid=6ef2de50 551e6bae ] pid=1 DATA 16030300 36020000 32030392 da38feea 1a9fb7ac c54b1791 7b0996bb 2314b58[more...]
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 WIN32 I/O: Socket Completion non-queued success [26]
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 WIN32 I/O: Socket Send immediate return [1200,1200]
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 UDPv4 write returned 1200
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 TLS: tls_multi_process: i=0 state=S_START, mysid=3fa897b5 c4f5dcfd, stored-sid=6ef2de50 551e6bae, stored-ip=[AF_INET]10.2.14.215:9879
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 TLS: tls_process: chg=0 ks=S_START lame=S_UNDEF to_link->len=0 wakeup=604800
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 ACK reliable_can_send active=1 current=0 : [2] 1
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 BIO read tls_read_ciphertext 1174 bytes
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 ACK mark active outgoing ID 2
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 Outgoing Ciphertext -> Reliable
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 TLS: tls_process: chg=1 ks=S_START lame=S_UNDEF to_link->len=0 wakeup=604800
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 ACK reliable_can_send active=2 current=1 : [3] 1 2
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 ACK reliable_send ID 2 (size=1178 to=3)
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 Reliable -> TCP/UDP
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 ACK reliable_send_timeout 2 [3] 1 2
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 TLS: tls_process: timeout set to 2
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 TLS: tls_multi_process: i=1 state=S_INITIAL, mysid=e45c995e cf12217c, stored-sid=00000000 00000000, stored-ip=[undef]
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[undef]
Thu Oct 06 09:08:31 2016 us=889398 WE_CTL n=0 ev=00000000004D6BE8 rwflags=0x0001 arg=0x494080
Thu Oct 06 09:08:31 2016 us=889398 WE_CTL n=1 ev=0000000000C2F920 rwflags=0x0002 arg=0x4cf0a0
Thu Oct 06 09:08:31 2016 us=889398 WE_CTL n=2 ev=0000000000C052B8 rwflags=0x0000 arg=0x494084
Thu Oct 06 09:08:31 2016 us=889398 I/O WAIT TrQ|Tw0|Sr0|SW1 [1/118712]
Thu Oct 06 09:08:31 2016 us=889398 WE_WAIT enter n=2 to=1119
Thu Oct 06 09:08:31 2016 us=889398 [0] ev=0000000000000104 rwflags=0x0001 arg=0x494080
Thu Oct 06 09:08:31 2016 us=889398 [1] ev=0000000000000148 rwflags=0x0002 arg=0x4cf0a0
Thu Oct 06 09:08:31 2016 us=889398 WE_WAIT leave [1,0] rwflags=0x0002 arg=0x4cf0a0
Thu Oct 06 09:08:31 2016 us=889398  event_wait returned 1
Thu Oct 06 09:08:31 2016 us=889398 I/O WAIT status=0x0002
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 UDPv4 WRITE [1188] to [AF_INET]10.2.14.215:9879: P_CONTROL_V1 kid=0 sid=3fa897b5 c4f5dcfd [ ] pid=2 DATA 56504e54 6573742d 43413082 0122300d 06092a86 4886f70d 01010105 0003820[more...]
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 WIN32 I/O: Socket Completion non-queued success [1200]
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 WIN32 I/O: Socket Send immediate return [1188,1188]
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 UDPv4 write returned 1188
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 TLS: tls_multi_process: i=0 state=S_START, mysid=3fa897b5 c4f5dcfd, stored-sid=6ef2de50 551e6bae, stored-ip=[AF_INET]10.2.14.215:9879
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 TLS: tls_process: chg=0 ks=S_START lame=S_UNDEF to_link->len=0 wakeup=604800
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 ACK reliable_can_send active=2 current=0 : [3] 1 2
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 BIO read tls_read_ciphertext 176 bytes
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 ACK mark active outgoing ID 3
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 Outgoing Ciphertext -> Reliable
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 TLS: tls_process: chg=1 ks=S_START lame=S_UNDEF to_link->len=0 wakeup=604800
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 ACK reliable_can_send active=3 current=1 : [4] 1 2 3
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 ACK reliable_send ID 3 (size=180 to=4)
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 Reliable -> TCP/UDP
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 ACK reliable_send_timeout 2 [4] 1 2 3
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 TLS: tls_process: timeout set to 2
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 TLS: tls_multi_process: i=1 state=S_INITIAL, mysid=e45c995e cf12217c, stored-sid=00000000 00000000, stored-ip=[undef]
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[undef]
Thu Oct 06 09:08:31 2016 us=889398 WE_CTL n=0 ev=00000000004D6BE8 rwflags=0x0001 arg=0x494080
Thu Oct 06 09:08:31 2016 us=889398 WE_CTL n=1 ev=0000000000C2F920 rwflags=0x0002 arg=0x4cf0a0
Thu Oct 06 09:08:31 2016 us=889398 WE_CTL n=2 ev=0000000000C052B8 rwflags=0x0000 arg=0x494084
Thu Oct 06 09:08:31 2016 us=889398 I/O WAIT TrQ|Tw0|Sr0|SW1 [1/118712]
Thu Oct 06 09:08:31 2016 us=889398 WE_WAIT enter n=2 to=1119
Thu Oct 06 09:08:31 2016 us=889398 [0] ev=0000000000000104 rwflags=0x0001 arg=0x494080
Thu Oct 06 09:08:31 2016 us=889398 [1] ev=0000000000000148 rwflags=0x0002 arg=0x4cf0a0
Thu Oct 06 09:08:31 2016 us=889398 WE_WAIT leave [1,0] rwflags=0x0002 arg=0x4cf0a0
Thu Oct 06 09:08:31 2016 us=889398  event_wait returned 1
Thu Oct 06 09:08:31 2016 us=889398 I/O WAIT status=0x0002
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 UDPv4 WRITE [190] to [AF_INET]10.2.14.215:9879: P_CONTROL_V1 kid=0 sid=3fa897b5 c4f5dcfd [ ] pid=3 DATA 0d79898b fc337f28 2d0bd0cf 6fc47cf2 9d2e04ab 16030300 970d0000 8f05030[more...]
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 WIN32 I/O: Socket Completion non-queued success [1188]
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 WIN32 I/O: Socket Send immediate return [190,190]
Thu Oct 06 09:08:31 2016 us=889398 10.2.14.215:9879 UDPv4 write returned 190
Thu Oct 06 09:08:31 2016 us=890375 10.2.14.215:9879 TLS: tls_multi_process: i=0 state=S_START, mysid=3fa897b5 c4f5dcfd, stored-sid=6ef2de50 551e6bae, stored-ip=[AF_INET]10.2.14.215:9879
Thu Oct 06 09:08:31 2016 us=890375 10.2.14.215:9879 TLS: tls_process: chg=0 ks=S_START lame=S_UNDEF to_link->len=0 wakeup=604800
Thu Oct 06 09:08:31 2016 us=890375 10.2.14.215:9879 ACK reliable_can_send active=3 current=0 : [4] 1 2 3
Thu Oct 06 09:08:31 2016 us=890375 10.2.14.215:9879 ACK reliable_send_timeout 2 [4] 1 2 3
Thu Oct 06 09:08:31 2016 us=890375 10.2.14.215:9879 TLS: tls_process: timeout set to 2
Thu Oct 06 09:08:31 2016 us=890375 10.2.14.215:9879 TLS: tls_multi_process: i=1 state=S_INITIAL, mysid=e45c995e cf12217c, stored-sid=00000000 00000000, stored-ip=[undef]
Thu Oct 06 09:08:31 2016 us=890375 10.2.14.215:9879 TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[undef]
Thu Oct 06 09:08:31 2016 us=890375 WE_CTL n=0 ev=00000000004D6BE8 rwflags=0x0001 arg=0x494080
Thu Oct 06 09:08:31 2016 us=890375 WIN32 I/O: Socket Receive queued [1572]
Thu Oct 06 09:08:31 2016 us=890375 WE_CTL n=1 ev=0000000000C2F920 rwflags=0x0001 arg=0x4cf0a0
Thu Oct 06 09:08:31 2016 us=890375 WE_CTL n=2 ev=0000000000C052B8 rwflags=0x0001 arg=0x494084
Thu Oct 06 09:08:31 2016 us=890375 I/O WAIT TRQ|Tw0|SRQ|Sw1 [1/117735]
Thu Oct 06 09:08:31 2016 us=890375 WE_WAIT enter n=3 to=1118
Thu Oct 06 09:08:31 2016 us=890375 [0] ev=0000000000000104 rwflags=0x0001 arg=0x494080
Thu Oct 06 09:08:31 2016 us=890375 [1] ev=0000000000000184 rwflags=0x0001 arg=0x4cf0a0
Thu Oct 06 09:08:31 2016 us=890375 [2] ev=0000000000000120 rwflags=0x0001 arg=0x494084
Thu Oct 06 09:08:31 2016 us=955431 WE_WAIT leave rwflags=0x0001 arg=0x4cf0a0
Thu Oct 06 09:08:31 2016 us=955431  event_wait returned 1
Thu Oct 06 09:08:31 2016 us=955431 I/O WAIT status=0x0001
Thu Oct 06 09:08:31 2016 us=955431 WIN32 I/O: Socket Completion success [22]
Thu Oct 06 09:08:31 2016 us=955431 UDPv4 read returned 22
Thu Oct 06 09:08:31 2016 us=955431 GET INST BY REAL: 10.2.14.215:9879 [succeeded]
Thu Oct 06 09:08:31 2016 us=955431 10.2.14.215:9879 UDPv4 READ [22] from [AF_INET]10.2.14.215:9879: P_ACK_V1 kid=0 sid=6ef2de50 551e6bae [ 1 sid=3fa897b5 c4f5dcfd ]
Thu Oct 06 09:08:31 2016 us=955431 10.2.14.215:9879 TLS: control channel, op=P_ACK_V1, IP=[AF_INET]10.2.14.215:9879
Thu Oct 06 09:08:31 2016 us=955431 10.2.14.215:9879 TLS: initial packet test, i=0 state=S_START, mysid=3fa897b5 c4f5dcfd, rec-sid=6ef2de50 551e6bae, rec-ip=[AF_INET]10.2.14.215:9879, stored-sid=6ef2de50 551e6bae, stored-ip=[AF_INET]10.2.14.215:9879
Thu Oct 06 09:08:31 2016 us=955431 10.2.14.215:9879 TLS: found match, session[0], sid=6ef2de50 551e6bae
Thu Oct 06 09:08:31 2016 us=955431 10.2.14.215:9879 TLS: received control channel packet s#=0 sid=6ef2de50 551e6bae
Thu Oct 06 09:08:31 2016 us=955431 10.2.14.215:9879 ACK received for pid 1, deleting from send buffer
Thu Oct 06 09:08:31 2016 us=955431 10.2.14.215:9879 TLS: tls_multi_process: i=0 state=S_START, mysid=3fa897b5 c4f5dcfd, stored-sid=6ef2de50 551e6bae, stored-ip=[AF_INET]10.2.14.215:9879
Thu Oct 06 09:08:31 2016 us=955431 10.2.14.215:9879 TLS: tls_process: chg=0 ks=S_START lame=S_UNDEF to_link->len=0 wakeup=604800
Thu Oct 06 09:08:31 2016 us=955431 10.2.14.215:9879 ACK reliable_can_send active=2 current=0 : [4] 2 3
Thu Oct 06 09:08:31 2016 us=955431 10.2.14.215:9879 ACK reliable_send_timeout 3 [4] 2 3
Thu Oct 06 09:08:31 2016 us=955431 10.2.14.215:9879 TLS: tls_process: timeout set to 3
Thu Oct 06 09:08:31 2016 us=955431 10.2.14.215:9879 TLS: tls_multi_process: i=1 state=S_INITIAL, mysid=e45c995e cf12217c, stored-sid=00000000 00000000, stored-ip=[undef]
Thu Oct 06 09:08:31 2016 us=955431 10.2.14.215:9879 TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[undef]
Thu Oct 06 09:08:31 2016 us=955431 WE_CTL n=0 ev=00000000004D6BE8 rwflags=0x0001 arg=0x494080
Thu Oct 06 09:08:31 2016 us=955431 WIN32 I/O: Socket Receive queued [1572]
Thu Oct 06 09:08:31 2016 us=955431 WE_CTL n=1 ev=0000000000C2F920 rwflags=0x0001 arg=0x4cf0a0
Thu Oct 06 09:08:31 2016 us=955431 WE_CTL n=2 ev=0000000000C052B8 rwflags=0x0001 arg=0x494084
Thu Oct 06 09:08:31 2016 us=955431 I/O WAIT TRQ|Tw0|SRQ|Sw1 [1/52679]
Thu Oct 06 09:08:31 2016 us=955431 WE_WAIT enter n=3 to=1053
Thu Oct 06 09:08:31 2016 us=955431 [0] ev=0000000000000104 rwflags=0x0001 arg=0x494080
Thu Oct 06 09:08:31 2016 us=955431 [1] ev=0000000000000184 rwflags=0x0001 arg=0x4cf0a0
Thu Oct 06 09:08:31 2016 us=955431 [2] ev=0000000000000120 rwflags=0x0001 arg=0x494084
Thu Oct 06 09:08:31 2016 us=956432 WE_WAIT leave rwflags=0x0001 arg=0x4cf0a0
Thu Oct 06 09:08:31 2016 us=956432  event_wait returned 1
Thu Oct 06 09:08:31 2016 us=956432 I/O WAIT status=0x0001
Thu Oct 06 09:08:31 2016 us=956432 WIN32 I/O: Socket Completion success [22]
Thu Oct 06 09:08:31 2016 us=956432 UDPv4 read returned 22
Thu Oct 06 09:08:31 2016 us=956432 GET INST BY REAL: 10.2.14.215:9879 [succeeded]
Thu Oct 06 09:08:31 2016 us=956432 10.2.14.215:9879 UDPv4 READ [22] from [AF_INET]10.2.14.215:9879: P_ACK_V1 kid=0 sid=6ef2de50 551e6bae [ 2 sid=3fa897b5 c4f5dcfd ]
Thu Oct 06 09:08:31 2016 us=956432 10.2.14.215:9879 TLS: control channel, op=P_ACK_V1, IP=[AF_INET]10.2.14.215:9879
Thu Oct 06 09:08:31 2016 us=956432 10.2.14.215:9879 TLS: initial packet test, i=0 state=S_START, mysid=3fa897b5 c4f5dcfd, rec-sid=6ef2de50 551e6bae, rec-ip=[AF_INET]10.2.14.215:9879, stored-sid=6ef2de50 551e6bae, stored-ip=[AF_INET]10.2.14.215:9879
Thu Oct 06 09:08:31 2016 us=956432 10.2.14.215:9879 TLS: found match, session[0], sid=6ef2de50 551e6bae
Thu Oct 06 09:08:31 2016 us=956432 10.2.14.215:9879 TLS: received control channel packet s#=0 sid=6ef2de50 551e6bae
Thu Oct 06 09:08:31 2016 us=956432 10.2.14.215:9879 ACK received for pid 2, deleting from send buffer
Thu Oct 06 09:08:31 2016 us=956432 10.2.14.215:9879 TLS: tls_multi_process: i=0 state=S_START, mysid=3fa897b5 c4f5dcfd, stored-sid=6ef2de50 551e6bae, stored-ip=[AF_INET]10.2.14.215:9879
Thu Oct 06 09:08:31 2016 us=956432 10.2.14.215:9879 TLS: tls_process: chg=0 ks=S_START lame=S_UNDEF to_link->len=0 wakeup=604800
Thu Oct 06 09:08:31 2016 us=956432 10.2.14.215:9879 ACK reliable_can_send active=1 current=0 : [4] 3
Thu Oct 06 09:08:31 2016 us=956432 10.2.14.215:9879 ACK reliable_send_timeout 4 [4] 3
Thu Oct 06 09:08:31 2016 us=956432 10.2.14.215:9879 TLS: tls_process: timeout set to 4
Thu Oct 06 09:08:31 2016 us=956432 10.2.14.215:9879 TLS: tls_multi_process: i=1 state=S_INITIAL, mysid=e45c995e cf12217c, stored-sid=00000000 00000000, stored-ip=[undef]
Thu Oct 06 09:08:31 2016 us=956432 10.2.14.215:9879 TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[undef]
Thu Oct 06 09:08:31 2016 us=956432 WE_CTL n=0 ev=00000000004D6BE8 rwflags=0x0001 arg=0x494080
Thu Oct 06 09:08:31 2016 us=956432 WIN32 I/O: Socket Receive queued [1572]
Thu Oct 06 09:08:31 2016 us=956432 WE_CTL n=1 ev=0000000000C2F920 rwflags=0x0001 arg=0x4cf0a0
Thu Oct 06 09:08:31 2016 us=956432 WE_CTL n=2 ev=0000000000C052B8 rwflags=0x0001 arg=0x494084
Thu Oct 06 09:08:31 2016 us=956432 I/O WAIT TRQ|Tw0|SRQ|Sw1 [1/51678]
Thu Oct 06 09:08:31 2016 us=956432 WE_WAIT enter n=3 to=1052
Thu Oct 06 09:08:31 2016 us=956432 [0] ev=0000000000000104 rwflags=0x0001 arg=0x494080
Thu Oct 06 09:08:31 2016 us=956432 [1] ev=0000000000000184 rwflags=0x0001 arg=0x4cf0a0
Thu Oct 06 09:08:31 2016 us=956432 [2] ev=0000000000000120 rwflags=0x0001 arg=0x494084
Thu Oct 06 09:08:31 2016 us=966435 WE_WAIT leave rwflags=0x0001 arg=0x4cf0a0
Thu Oct 06 09:08:31 2016 us=966435  event_wait returned 1
Thu Oct 06 09:08:31 2016 us=966435 I/O WAIT status=0x0001
Thu Oct 06 09:08:31 2016 us=966435 WIN32 I/O: Socket Completion success [1200]
Thu Oct 06 09:08:31 2016 us=966435 UDPv4 read returned 1200
Thu Oct 06 09:08:31 2016 us=966435 GET INST BY REAL: 10.2.14.215:9879 [succeeded]
Thu Oct 06 09:08:31 2016 us=966435 10.2.14.215:9879 UDPv4 READ [1200] from [AF_INET]10.2.14.215:9879: P_CONTROL_V1 kid=0 sid=6ef2de50 551e6bae [ 3 sid=3fa897b5 c4f5dcfd ] pid=2 DATA 16030306 ec0b0006 e80006e5 00034230 82033e30 82022602 0104300d 06092a8[more...]
Thu Oct 06 09:08:31 2016 us=966435 10.2.14.215:9879 TLS: control channel, op=P_CONTROL_V1, IP=[AF_INET]10.2.14.215:9879
Thu Oct 06 09:08:31 2016 us=966435 10.2.14.215:9879 TLS: initial packet test, i=0 state=S_START, mysid=3fa897b5 c4f5dcfd, rec-sid=6ef2de50 551e6bae, rec-ip=[AF_INET]10.2.14.215:9879, stored-sid=6ef2de50 551e6bae, stored-ip=[AF_INET]10.2.14.215:9879
Thu Oct 06 09:08:31 2016 us=966435 10.2.14.215:9879 TLS: found match, session[0], sid=6ef2de50 551e6bae
Thu Oct 06 09:08:31 2016 us=966435 10.2.14.215:9879 TLS: received control channel packet s#=0 sid=6ef2de50 551e6bae
Thu Oct 06 09:08:31 2016 us=966435 10.2.14.215:9879 ACK received for pid 3, deleting from send buffer
Thu Oct 06 09:08:31 2016 us=966435 10.2.14.215:9879 ACK read ID 2 (buf->len=1174)
Thu Oct 06 09:08:31 2016 us=966435 10.2.14.215:9879 ACK RWBS rel->size=8 rel->packet_id=00000002 id=00000002 ret=1

Thu Oct 06 09:08:31 2016 us=966435 10.2.14.215:9879 ACK mark active incoming ID 2
Thu Oct 06 09:08:31 2016 us=966435 10.2.14.215:9879 ACK acknowledge ID 2 (ack->len=1)
Thu Oct 06 09:08:31 2016 us=966435 10.2.14.215:9879 TLS: tls_multi_process: i=0 state=S_START, mysid=3fa897b5 c4f5dcfd, stored-sid=6ef2de50 551e6bae, stored-ip=[AF_INET]10.2.14.215:9879
Thu Oct 06 09:08:31 2016 us=966435 10.2.14.215:9879 TLS: tls_process: chg=0 ks=S_START lame=S_UNDEF to_link->len=0 wakeup=604800
Thu Oct 06 09:08:31 2016 us=966435 10.2.14.215:9879 ACK reliable_can_send active=0 current=0 : [4]
Thu Oct 06 09:08:31 2016 us=966435 10.2.14.215:9879 BIO write tls_write_ciphertext 1174 bytes
Thu Oct 06 09:08:31 2016 us=966435 10.2.14.215:9879 Incoming Ciphertext -> TLS
Thu Oct 06 09:08:31 2016 us=966435 10.2.14.215:9879 TLS: tls_process: chg=1 ks=S_START lame=S_UNDEF to_link->len=0 wakeup=604800
Thu Oct 06 09:08:31 2016 us=966435 10.2.14.215:9879 ACK reliable_can_send active=0 current=0 : [4]
Thu Oct 06 09:08:31 2016 us=966435 10.2.14.215:9879 ACK write ID 2 (ack->len=1, n=1)
Thu Oct 06 09:08:31 2016 us=966435 10.2.14.215:9879 Dedicated ACK -> TCP/UDP
Thu Oct 06 09:08:31 2016 us=966435 10.2.14.215:9879 ACK reliable_send_timeout 604800 [4]
Thu Oct 06 09:08:31 2016 us=966435 10.2.14.215:9879 TLS: tls_process: timeout set to 60
Thu Oct 06 09:08:31 2016 us=966435 10.2.14.215:9879 TLS: tls_multi_process: i=1 state=S_INITIAL, mysid=e45c995e cf12217c, stored-sid=00000000 00000000, stored-ip=[undef]
Thu Oct 06 09:08:31 2016 us=967438 10.2.14.215:9879 TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[undef]
Thu Oct 06 09:08:31 2016 us=967438 WE_CTL n=0 ev=00000000004D6BE8 rwflags=0x0001 arg=0x494080
Thu Oct 06 09:08:31 2016 us=967438 WE_CTL n=1 ev=0000000000C2F920 rwflags=0x0002 arg=0x4cf0a0
Thu Oct 06 09:08:31 2016 us=967438 WE_CTL n=2 ev=0000000000C052B8 rwflags=0x0000 arg=0x494084
Thu Oct 06 09:08:31 2016 us=967438 I/O WAIT TrQ|Tw0|Sr0|SW1 [1/40672]
Thu Oct 06 09:08:31 2016 us=967438 WE_WAIT enter n=2 to=1041
Thu Oct 06 09:08:31 2016 us=967438 [0] ev=0000000000000104 rwflags=0x0001 arg=0x494080
Thu Oct 06 09:08:31 2016 us=967438 [1] ev=0000000000000148 rwflags=0x0002 arg=0x4cf0a0
Thu Oct 06 09:08:31 2016 us=967438 WE_WAIT leave [1,0] rwflags=0x0002 arg=0x4cf0a0
Thu Oct 06 09:08:31 2016 us=967438  event_wait returned 1
Thu Oct 06 09:08:31 2016 us=967438 I/O WAIT status=0x0002
Thu Oct 06 09:08:31 2016 us=967438 10.2.14.215:9879 UDPv4 WRITE [22] to [AF_INET]10.2.14.215:9879: P_ACK_V1 kid=0 sid=3fa897b5 c4f5dcfd [ 2 sid=6ef2de50 551e6bae ]
Thu Oct 06 09:08:31 2016 us=967438 10.2.14.215:9879 WIN32 I/O: Socket Completion non-queued success [190]
Thu Oct 06 09:08:31 2016 us=967438 10.2.14.215:9879 WIN32 I/O: Socket Send immediate return [22,22]
Thu Oct 06 09:08:31 2016 us=967438 10.2.14.215:9879 UDPv4 write returned 22
Thu Oct 06 09:08:31 2016 us=967438 10.2.14.215:9879 TLS: tls_multi_process: i=0 state=S_START, mysid=3fa897b5 c4f5dcfd, stored-sid=6ef2de50 551e6bae, stored-ip=[AF_INET]10.2.14.215:9879
Thu Oct 06 09:08:31 2016 us=967438 10.2.14.215:9879 TLS: tls_process: chg=0 ks=S_START lame=S_UNDEF to_link->len=0 wakeup=604800
Thu Oct 06 09:08:31 2016 us=967438 10.2.14.215:9879 ACK reliable_can_send active=0 current=0 : [4]
Thu Oct 06 09:08:31 2016 us=967438 10.2.14.215:9879 ACK reliable_send_timeout 604800 [4]
Thu Oct 06 09:08:31 2016 us=967438 10.2.14.215:9879 TLS: tls_process: timeout set to 60
Thu Oct 06 09:08:31 2016 us=967438 10.2.14.215:9879 TLS: tls_multi_process: i=1 state=S_INITIAL, mysid=e45c995e cf12217c, stored-sid=00000000 00000000, stored-ip=[undef]
Thu Oct 06 09:08:31 2016 us=967438 10.2.14.215:9879 TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[undef]
Thu Oct 06 09:08:31 2016 us=967438 WE_CTL n=0 ev=00000000004D6BE8 rwflags=0x0001 arg=0x494080
Thu Oct 06 09:08:31 2016 us=967438 WIN32 I/O: Socket Receive queued [1572]
Thu Oct 06 09:08:31 2016 us=967438 WE_CTL n=1 ev=0000000000C2F920 rwflags=0x0001 arg=0x4cf0a0
Thu Oct 06 09:08:31 2016 us=967438 WE_CTL n=2 ev=0000000000C052B8 rwflags=0x0001 arg=0x494084
Thu Oct 06 09:08:31 2016 us=967438 I/O WAIT TRQ|Tw0|SRQ|Sw1 [1/40672]
Thu Oct 06 09:08:31 2016 us=967438 WE_WAIT enter n=3 to=1041
Thu Oct 06 09:08:31 2016 us=967438 [0] ev=0000000000000104 rwflags=0x0001 arg=0x494080
Thu Oct 06 09:08:31 2016 us=967438 [1] ev=0000000000000184 rwflags=0x0001 arg=0x4cf0a0
Thu Oct 06 09:08:31 2016 us=967438 [2] ev=0000000000000120 rwflags=0x0001 arg=0x494084
Thu Oct 06 09:08:31 2016 us=971438 WE_WAIT leave rwflags=0x0001 arg=0x4cf0a0
Thu Oct 06 09:08:31 2016 us=971438  event_wait returned 1
Thu Oct 06 09:08:31 2016 us=971438 I/O WAIT status=0x0001
Thu Oct 06 09:08:31 2016 us=971438 WIN32 I/O: Socket Completion success [1116]
Thu Oct 06 09:08:31 2016 us=971438 UDPv4 read returned 1116
Thu Oct 06 09:08:31 2016 us=971438 GET INST BY REAL: 10.2.14.215:9879 [succeeded]
Thu Oct 06 09:08:31 2016 us=971438 10.2.14.215:9879 UDPv4 READ [1116] from [AF_INET]10.2.14.215:9879: P_CONTROL_V1 kid=0 sid=6ef2de50 551e6bae [ ] pid=3 DATA e8c975eb d0e8e4fa b3c569a6 8ba0aa5b a56cc41c bc46f20e 552717b9 a530b7a[more...]
Thu Oct 06 09:08:31 2016 us=971438 10.2.14.215:9879 TLS: control channel, op=P_CONTROL_V1, IP=[AF_INET]10.2.14.215:9879
Thu Oct 06 09:08:31 2016 us=971438 10.2.14.215:9879 TLS: initial packet test, i=0 state=S_START, mysid=3fa897b5 c4f5dcfd, rec-sid=6ef2de50 551e6bae, rec-ip=[AF_INET]10.2.14.215:9879, stored-sid=6ef2de50 551e6bae, stored-ip=[AF_INET]10.2.14.215:9879
Thu Oct 06 09:08:31 2016 us=971438 10.2.14.215:9879 TLS: found match, session[0], sid=6ef2de50 551e6bae
Thu Oct 06 09:08:31 2016 us=971438 10.2.14.215:9879 TLS: received control channel packet s#=0 sid=6ef2de50 551e6bae
Thu Oct 06 09:08:31 2016 us=971438 10.2.14.215:9879 ACK read ID 3 (buf->len=1102)
Thu Oct 06 09:08:31 2016 us=971438 10.2.14.215:9879 ACK RWBS rel->size=8 rel->packet_id=00000003 id=00000003 ret=1

Thu Oct 06 09:08:31 2016 us=971438 10.2.14.215:9879 ACK mark active incoming ID 3
Thu Oct 06 09:08:31 2016 us=971438 10.2.14.215:9879 ACK acknowledge ID 3 (ack->len=1)
Thu Oct 06 09:08:31 2016 us=971438 10.2.14.215:9879 TLS: tls_multi_process: i=0 state=S_START, mysid=3fa897b5 c4f5dcfd, stored-sid=6ef2de50 551e6bae, stored-ip=[AF_INET]10.2.14.215:9879
Thu Oct 06 09:08:31 2016 us=971438 10.2.14.215:9879 TLS: tls_process: chg=0 ks=S_START lame=S_UNDEF to_link->len=0 wakeup=604800
Thu Oct 06 09:08:31 2016 us=971438 10.2.14.215:9879 ACK reliable_can_send active=0 current=0 : [4]
Thu Oct 06 09:08:31 2016 us=971438 10.2.14.215:9879 BIO write tls_write_ciphertext 1102 bytes
Thu Oct 06 09:08:31 2016 us=971438 10.2.14.215:9879 Incoming Ciphertext -> TLS
Thu Oct 06 09:08:31 2016 us=972440 10.2.14.215:9879 VERIFY OK: depth=1, C=US, ST=PA, L=Blue Bell, O=IBM, OU=MaaS360, CN=VPNTest-CA
Thu Oct 06 09:08:31 2016 us=972440 10.2.14.215:9879 VERIFY OK: depth=0, C=US, ST=PA, L=Blue Bell, O=IBM, OU=MaaS360, CN=VPNTest-client
Thu Oct 06 09:08:31 2016 us=972440 10.2.14.215:9879 SSL state (accept): SSLv3 read client certificate A
Thu Oct 06 09:08:31 2016 us=973441 10.2.14.215:9879 SSL state (accept): SSLv3 read client key exchange A
Thu Oct 06 09:08:31 2016 us=973441 10.2.14.215:9879 SSL state (accept): SSLv3 read certificate verify A
Thu Oct 06 09:08:31 2016 us=973441 10.2.14.215:9879 SSL state (accept): SSLv3 read finished A
Thu Oct 06 09:08:31 2016 us=973441 10.2.14.215:9879 SSL state (accept): SSLv3 write change cipher spec A
Thu Oct 06 09:08:31 2016 us=973441 10.2.14.215:9879 SSL state (accept): SSLv3 write finished A
Thu Oct 06 09:08:31 2016 us=973441 10.2.14.215:9879 SSL state (accept): SSLv3 flush data
Thu Oct 06 09:08:31 2016 us=973441 10.2.14.215:9879 BIO read tls_read_ciphertext 91 bytes
Thu Oct 06 09:08:31 2016 us=973441 10.2.14.215:9879 ACK mark active outgoing ID 4
Thu Oct 06 09:08:31 2016 us=973441 10.2.14.215:9879 Outgoing Ciphertext -> Reliable
Thu Oct 06 09:08:31 2016 us=973441 10.2.14.215:9879 TLS: tls_process: chg=1 ks=S_START lame=S_UNDEF to_link->len=0 wakeup=604800
Thu Oct 06 09:08:31 2016 us=973441 10.2.14.215:9879 ACK reliable_can_send active=1 current=1 : [5] 4
Thu Oct 06 09:08:31 2016 us=973441 10.2.14.215:9879 ACK reliable_send ID 4 (size=95 to=2)
Thu Oct 06 09:08:31 2016 us=973441 10.2.14.215:9879 ACK write ID 3 (ack->len=1, n=1)
Thu Oct 06 09:08:31 2016 us=973441 10.2.14.215:9879 Reliable -> TCP/UDP
Thu Oct 06 09:08:31 2016 us=973441 10.2.14.215:9879 ACK reliable_send_timeout 2 [5] 4
Thu Oct 06 09:08:31 2016 us=973441 10.2.14.215:9879 TLS: tls_process: timeout set to 2
Thu Oct 06 09:08:31 2016 us=973441 10.2.14.215:9879 TLS: tls_multi_process: i=1 state=S_INITIAL, mysid=e45c995e cf12217c, stored-sid=00000000 00000000, stored-ip=[undef]
Thu Oct 06 09:08:31 2016 us=973441 10.2.14.215:9879 TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[undef]
Thu Oct 06 09:08:31 2016 us=973441 WE_CTL n=0 ev=00000000004D6BE8 rwflags=0x0001 arg=0x494080
Thu Oct 06 09:08:31 2016 us=973441 WE_CTL n=1 ev=0000000000C2F920 rwflags=0x0002 arg=0x4cf0a0
Thu Oct 06 09:08:31 2016 us=973441 WE_CTL n=2 ev=0000000000C052B8 rwflags=0x0000 arg=0x494084
Thu Oct 06 09:08:31 2016 us=973441 I/O WAIT TrQ|Tw0|Sr0|SW1 [1/34669]
Thu Oct 06 09:08:31 2016 us=973441 WE_WAIT enter n=2 to=1035
Thu Oct 06 09:08:31 2016 us=973441 [0] ev=0000000000000104 rwflags=0x0001 arg=0x494080
Thu Oct 06 09:08:31 2016 us=973441 [1] ev=0000000000000148 rwflags=0x0002 arg=0x4cf0a0
Thu Oct 06 09:08:31 2016 us=973441 WE_WAIT leave [1,0] rwflags=0x0002 arg=0x4cf0a0
Thu Oct 06 09:08:31 2016 us=973441  event_wait returned 1
Thu Oct 06 09:08:31 2016 us=973441 I/O WAIT status=0x0002
Thu Oct 06 09:08:31 2016 us=973441 10.2.14.215:9879 UDPv4 WRITE [117] to [AF_INET]10.2.14.215:9879: P_CONTROL_V1 kid=0 sid=3fa897b5 c4f5dcfd [ 3 sid=6ef2de50 551e6bae ] pid=4 DATA 14030300 01011603 030050b2 a5674cf2 894b4a4d 277d6b4d d6c0946e 056f1d1[more...]
Thu Oct 06 09:08:31 2016 us=973441 10.2.14.215:9879 WIN32 I/O: Socket Completion non-queued success [22]
Thu Oct 06 09:08:31 2016 us=973441 10.2.14.215:9879 WIN32 I/O: Socket Send immediate return [117,117]
Thu Oct 06 09:08:31 2016 us=973441 10.2.14.215:9879 UDPv4 write returned 117
Thu Oct 06 09:08:31 2016 us=974442 10.2.14.215:9879 TLS: tls_multi_process: i=0 state=S_START, mysid=3fa897b5 c4f5dcfd, stored-sid=6ef2de50 551e6bae, stored-ip=[AF_INET]10.2.14.215:9879
Thu Oct 06 09:08:31 2016 us=974442 10.2.14.215:9879 TLS: tls_process: chg=0 ks=S_START lame=S_UNDEF to_link->len=0 wakeup=604800
Thu Oct 06 09:08:31 2016 us=974442 10.2.14.215:9879 ACK reliable_can_send active=1 current=0 : [5] 4
Thu Oct 06 09:08:31 2016 us=974442 10.2.14.215:9879 ACK reliable_send_timeout 2 [5] 4
Thu Oct 06 09:08:31 2016 us=974442 10.2.14.215:9879 TLS: tls_process: timeout set to 2
Thu Oct 06 09:08:31 2016 us=974442 10.2.14.215:9879 TLS: tls_multi_process: i=1 state=S_INITIAL, mysid=e45c995e cf12217c, stored-sid=00000000 00000000, stored-ip=[undef]
Thu Oct 06 09:08:31 2016 us=974442 10.2.14.215:9879 TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[undef]
Thu Oct 06 09:08:31 2016 us=974442 WE_CTL n=0 ev=00000000004D6BE8 rwflags=0x0001 arg=0x494080
Thu Oct 06 09:08:31 2016 us=974442 WIN32 I/O: Socket Receive queued [1572]
Thu Oct 06 09:08:31 2016 us=974442 WE_CTL n=1 ev=0000000000C2F920 rwflags=0x0001 arg=0x4cf0a0
Thu Oct 06 09:08:31 2016 us=974442 WE_CTL n=2 ev=0000000000C052B8 rwflags=0x0001 arg=0x494084
Thu Oct 06 09:08:31 2016 us=974442 I/O WAIT TRQ|Tw0|SRQ|Sw1 [1/33668]
Thu Oct 06 09:08:31 2016 us=974442 WE_WAIT enter n=3 to=1034
Thu Oct 06 09:08:31 2016 us=974442 [0] ev=0000000000000104 rwflags=0x0001 arg=0x494080
Thu Oct 06 09:08:31 2016 us=974442 [1] ev=0000000000000184 rwflags=0x0001 arg=0x4cf0a0
Thu Oct 06 09:08:31 2016 us=974442 [2] ev=0000000000000120 rwflags=0x0001 arg=0x494084
Thu Oct 06 09:08:32 2016 us=42473 WE_WAIT leave rwflags=0x0001 arg=0x4cf0a0
Thu Oct 06 09:08:32 2016 us=42473  event_wait returned 1
Thu Oct 06 09:08:32 2016 us=42473 I/O WAIT status=0x0001
Thu Oct 06 09:08:32 2016 us=42473 MULTI: REAP range 48 -> 64
Thu Oct 06 09:08:32 2016 us=42473 WIN32 I/O: Socket Completion success [367]
Thu Oct 06 09:08:32 2016 us=42473 UDPv4 read returned 367
Thu Oct 06 09:08:32 2016 us=42473 GET INST BY REAL: 10.2.14.215:9879 [succeeded]
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 UDPv4 READ [367] from [AF_INET]10.2.14.215:9879: P_CONTROL_V1 kid=0 sid=6ef2de50 551e6bae [ 4 sid=3fa897b5 c4f5dcfd ] pid=4 DATA 17030301 50bfe614 31658008 1b94d18a 185c2386 e58ddb6a 8cea6b97 f4cfa24[more...]
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 TLS: control channel, op=P_CONTROL_V1, IP=[AF_INET]10.2.14.215:9879
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 TLS: initial packet test, i=0 state=S_START, mysid=3fa897b5 c4f5dcfd, rec-sid=6ef2de50 551e6bae, rec-ip=[AF_INET]10.2.14.215:9879, stored-sid=6ef2de50 551e6bae, stored-ip=[AF_INET]10.2.14.215:9879
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 TLS: found match, session[0], sid=6ef2de50 551e6bae
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 TLS: received control channel packet s#=0 sid=6ef2de50 551e6bae
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 ACK received for pid 4, deleting from send buffer
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 ACK read ID 4 (buf->len=341)
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 ACK RWBS rel->size=8 rel->packet_id=00000004 id=00000004 ret=1

Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 ACK mark active incoming ID 4
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 ACK acknowledge ID 4 (ack->len=1)
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 TIMER: coarse timer wakeup 1 seconds
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 TLS: tls_multi_process: i=0 state=S_START, mysid=3fa897b5 c4f5dcfd, stored-sid=6ef2de50 551e6bae, stored-ip=[AF_INET]10.2.14.215:9879
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 TLS: tls_process: chg=0 ks=S_START lame=S_UNDEF to_link->len=0 wakeup=604800
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 ACK reliable_can_send active=0 current=0 : [5]
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 BIO write tls_write_ciphertext 341 bytes
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 Incoming Ciphertext -> TLS
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 BIO read tls_read_plaintext 285 bytes
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 TLS -> Incoming Plaintext
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 STATE S_GOT_KEY
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 TLS: tls_process: chg=1 ks=S_GOT_KEY lame=S_UNDEF to_link->len=0 wakeup=604800
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 ACK reliable_can_send active=0 current=0 : [5]
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 Client pre_master: 4cc1681d 0031ca79 c0c62f24 7f5b8416 f044fcfa bc8fb75d dfedc4b4 b95b3fb2 df8503cc 3db03a63 d821cd9b fbef4fbb
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 Client random1: 43dd372d 8ff00745 0efff93e 7a7ddea1 2be2d71a ee79d242 a8da101f 52921535
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 Client random2: 388f43fe c2a528ff b644fdef a145f88f 0e681fc2 a5410a67 8b48125b 46d67b87
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 Server pre_master: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 Server random1: 49c64b03 9310265a d3f112b9 182cf493 9447ee71 5331ac71 e89e908b 9d93f7f2
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 Server random2: 1d1c18d4 74ffd9f1 4b3943b4 f473ec0e dca378a0 ceb3839b e3d1c25b 4ba4a594
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 tls1_P_hash sec: 4cc1681d 0031ca79 c0c62f24 7f5b8416 f044fcfa bc8fb75d
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 tls1_P_hash seed: 4f70656e 56504e20 6d617374 65722073 65637265 7443dd37 2d8ff007 450efff9 3e7a7dde a12be2d7 1aee79d2 42a8da10 1f529215 3549c64b 03931026 5ad3f112 b9182cf4 939447ee 715331ac 71e89e90 8b9d93f7 f2
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 jfr before hmac_ctx_init-1
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 CRYPTO INFO: jfr before HMAC_CTX_init
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 CRYPTO INFO: jfr before HMAC_Init_ex
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 OpenSSL: error:060A80A3:digital envelope routines:FIPS_DIGESTINIT:disabled for fips
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 CRYPTO INFO: jfr after HMAC_Init_ex
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 CRYPTO INFO: jfr key_len was large enough ?
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 jfr before hmac_ctx_init-2
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 CRYPTO INFO: jfr before HMAC_CTX_init
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 CRYPTO INFO: jfr before HMAC_Init_ex
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 OpenSSL: error:060A80A3:digital envelope routines:FIPS_DIGESTINIT:disabled for fips
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 CRYPTO INFO: jfr after HMAC_Init_ex
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 CRYPTO INFO: jfr key_len was large enough ?
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 jfr before hmac_ctx_update
Thu Oct 06 09:08:32 2016 us=42473 10.2.14.215:9879 jfr seed is 12768112
Thu Oct 06 09:08:32 2016 us=43473 10.2.14.215:9879 jfr seed_len is 85
Thu Oct 06 09:08:32 2016 us=43473 10.2.14.215:9879 CRYPTO INFO: jfr calling HMAC_Update

TinCanTech

Please set --verb 4 in your configs. (verb 11 and 15 are too high)

Please post details from both your server and client of:

openvpn --version