Odd log entries in existing session: "incoming connection" and "handshake failed"

[mage1982 15]

In a session that has been up for a while (days), I suddenly see some unexpected things in the log output from OpenVPN. I noticed some ongoing HTTP connections going over the VPN also shut down unexpectedly. Someone at AirVPN messing about with the server or something else?

 

Sorry for vomiting up pages of logs, I'll point out the interesting lines below.

 

Thu Jul 17 06:16:08 2014 VERIFY OK: depth=0, C=IT, ST=IT, L=Perugia, 0=airvpn.org, CN=server, emailAddress=info@airvpn.org

Thu Jul 17 06:16:24 2014 Data Channel Encrypt: Cipher 'AES-256-CBC' initialized with 256 bit key

Thu Jul 17 06:16:24 2014 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication

Thu Jul 17 06:16:24 2014 Data Channel Decrypt: Cipher 'AES-256-CBC' initialized with 256 bit key

Thu Jul 17 06:16:24 2014 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication

Thu Jul 17 06:16:24 2014 Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 4096 bit RSA

Thu Jul 17 07:16:08 2014 TLS: tls_process: killed expiring key

Thu Jul 17 07:16:24 2014 TLS: soft reset sec=0 bytes=333383635/0 pkts=391961/0

Thu Jul 17 07:16:24 2014 VERIFY OK: depth=1, C=IT, ST=IT, L=Perugia, O=airvpn.org, CN=airvpn.org CA, emailAddress=info@airvpn.org

Thu Jul 17 07:16:24 2014 Validating certificate key usage

Thu Jul 17 07:16:24 2014 ++ Certificate has key usage 00a0, expects 00a0

Thu Jul 17 07:16:24 2014 VERIFY KU OK

Thu Jul 17 07:16:24 2014 Validating certificate extended key usage

Thu Jul 17 07:16:24 2014 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication

Thu Jul 17 07:16:24 2014 VERIFY EKU OK

Thu Jul 17 07:16:24 2014 VERIFY OK: depth=0, C=IT, ST=IT, L=Perugia, O=airvpn.org, CN=server, emailAddress=info@airvpn.org

Thu Jul 17 07:18:06 2014 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)

Thu Jul 17 07:18:06 2014 TLS Error: TLS handshake failed

Thu Jul 17 07:18:06 2014 TLS: move_session: dest=TM_LAME_DUCK src=TM_ACTIVE reinit_src=1

Thu Jul 17 07:18:07 2014 TLS ERROR: received control packet with stale session-id=a2c377d7 6ea5974c

Thu Jul 17 07:18:07 2014 TLS ERROR: received control packet with stale session-id=a2c377d7 6ea5974c

Thu Jul 17 07:18:07 2014 TLS ERROR: received control packet with stale session-id=a2c377d7 6ea5974c

Thu Jul 17 07:18:07 2014 TLS ERROR: received control packet with stale session-id=a2c377d7 6ea5974c

Thu Jul 17 07:18:07 2014 TLS: Initial packet from [AF_INET]62.212.72.175:443, sid=01d68ee5 1e093b39

Thu Jul 17 07:18:10 2014 VERIFY OK: depth=1, C=IT, ST=IT, L=Perugia, O=airvpn.org, CN=airvpn.org CA, emailAddress=info@airvpn.org

Thu Jul 17 07:18:10 2014 Validating certificate key usage

Thu Jul 17 07:18:10 2014 ++ Certificate has key usage 00a0, expects 00a0

Thu Jul 17 07:18:10 2014 VERIFY KU OK

Thu Jul 17 07:18:10 2014 Validating certificate extended key usage

Thu Jul 17 07:18:10 2014 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication

Thu Jul 17 07:18:10 2014 VERIFY EKU OK

Thu Jul 17 07:18:10 2014 VERIFY OK: depth=0, C=IT, ST=IT, L=Perugia, O=airvpn.org, CN=server, emailAddress=info@airvpn.org

Thu Jul 17 07:19:01 2014 TLS: new session incoming connection from [AF_INET]62.212.72.175:443

Thu Jul 17 07:19:03 2014 VERIFY OK: depth=1, C=IT, ST=IT, L=Perugia, O=airvpn.org, CN=airvpn.org CA, emailAddress=info@airvpn.org

Thu Jul 17 07:19:03 2014 Validating certificate key usage

Thu Jul 17 07:19:03 2014 ++ Certificate has key usage 00a0, expects 00a0

Thu Jul 17 07:19:03 2014 VERIFY KU OK

Thu Jul 17 07:19:03 2014 Validating certificate extended key usage

Thu Jul 17 07:19:03 2014 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication

Thu Jul 17 07:19:03 2014 VERIFY EKU OK

Thu Jul 17 07:19:03 2014 VERIFY OK: depth=0, C=IT, ST=IT, L=Perugia, O=airvpn.org, CN=server, emailAddress=info@airvpn.org

Thu Jul 17 07:19:38 2014 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)

Thu Jul 17 07:19:38 2014 TLS Error: TLS handshake failed

Thu Jul 17 07:19:38 2014 TLS: Initial packet from [AF_INET]62.212.72.175:443, sid=7badb579 e57e0569

Thu Jul 17 07:19:40 2014 VERIFY OK: depth=1, C=IT, ST=IT, L=Perugia, O=airvpn.org, CN=airvpn.org CA, emailAddress=info@airvpn.org

Thu Jul 17 07:19:40 2014 Validating certificate key usage

Thu Jul 17 07:19:40 2014 ++ Certificate has key usage 00a0, expects 00a0

Thu Jul 17 07:19:40 2014 VERIFY KU OK

Thu Jul 17 07:19:40 2014 Validating certificate extended key usage

Thu Jul 17 07:19:40 2014 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication

Thu Jul 17 07:19:40 2014 VERIFY EKU OK

Thu Jul 17 07:19:40 2014 VERIFY OK: depth=0, C=IT, ST=IT, L=Perugia, O=airvpn.org, CN=server, emailAddress=info@airvpn.org

Thu Jul 17 07:20:18 2014 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)

Thu Jul 17 07:20:18 2014 TLS Error: TLS handshake failed

Thu Jul 17 07:20:18 2014 TLS: new session incoming connection from [AF_INET]62.212.72.175:443

Thu Jul 17 07:20:20 2014 VERIFY OK: depth=1, C=IT, ST=IT, L=Perugia, O=airvpn.org, CN=airvpn.org CA, emailAddress=info@airvpn.org

Thu Jul 17 07:20:20 2014 Validating certificate key usage

Thu Jul 17 07:20:20 2014 ++ Certificate has key usage 00a0, expects 00a0

Thu Jul 17 07:20:20 2014 VERIFY KU OK

Thu Jul 17 07:20:20 2014 Validating certificate extended key usage

Thu Jul 17 07:20:20 2014 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication

Thu Jul 17 07:20:20 2014 VERIFY EKU OK

Thu Jul 17 07:20:20 2014 VERIFY OK: depth=0, C=IT, ST=IT, L=Perugia, O=airvpn.org, CN=server, emailAddress=info@airvpn.org

Thu Jul 17 07:20:58 2014 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)

Thu Jul 17 07:20:58 2014 TLS Error: TLS handshake failed

Thu Jul 17 07:20:58 2014 TLS Error: Unroutable control packet received from [AF_INET]62.212.72.175:443 (si=3 op=P_ACK_V1)

Thu Jul 17 07:20:58 2014 TLS Error: Unroutable control packet received from [AF_INET]62.212.72.175:443 (si=3 op=P_ACK_V1)

Thu Jul 17 07:20:58 2014 TLS Error: Unroutable control packet received from [AF_INET]62.212.72.175:443 (si=3 op=P_ACK_V1)

Thu Jul 17 07:20:58 2014 TLS Error: Unroutable control packet received from [AF_INET]62.212.72.175:443 (si=3 op=P_ACK_V1)

Thu Jul 17 07:20:58 2014 TLS: Initial packet from [AF_INET]62.212.72.175:443, sid=21a8c3fb 50eadad4

Thu Jul 17 07:20:59 2014 VERIFY OK: depth=1, C=IT, ST=IT, L=Perugia, O=airvpn.org, CN=airvpn.org CA, emailAddress=info@airvpn.org

Thu Jul 17 07:20:59 2014 Validating certificate key usage

Thu Jul 17 07:20:59 2014 ++ Certificate has key usage 00a0, expects 00a0

Thu Jul 17 07:20:59 2014 VERIFY KU OK

Thu Jul 17 07:20:59 2014 Validating certificate extended key usage

Thu Jul 17 07:20:59 2014 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication

Thu Jul 17 07:20:59 2014 VERIFY EKU OK

Thu Jul 17 07:20:59 2014 VERIFY OK: depth=0, C=IT, ST=IT, L=Perugia, O=airvpn.org, CN=server, emailAddress=info@airvpn.org

Thu Jul 17 07:21:08 2014 Data Channel Encrypt: Cipher 'AES-256-CBC' initialized with 256 bit key

Thu Jul 17 07:21:08 2014 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication

Thu Jul 17 07:21:08 2014 Data Channel Decrypt: Cipher 'AES-256-CBC' initialized with 256 bit key

Thu Jul 17 07:21:08 2014 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication

Thu Jul 17 07:21:08 2014 Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 4096 bit RSA

Thu Jul 17 07:21:18 2014 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)

Thu Jul 17 07:21:18 2014 TLS Error: TLS handshake failed

 

 

Ok, now the blow-by-blow version.

 

So first we have an existing connection, and at 7:16 the usual key renegotiation occurs. Certificate validates OK, but then "TLS key negotiation failed to occur". (And what's this business with "move_session"? Just state keeping on the server?)

 

Thu Jul 17 07:16:24 2014 VERIFY OK: depth=0, C=IT, ST=IT, L=Perugia, O=airvpn.org, CN=server, emailAddress=info@airvpn.org

Thu Jul 17 07:18:06 2014 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)

Thu Jul 17 07:18:06 2014 TLS Error: TLS handshake failed

Thu Jul 17 07:18:06 2014 TLS: move_session: dest=TM_LAME_DUCK src=TM_ACTIVE reinit_src=1

Thu Jul 17 07:18:07 2014 TLS ERROR: received control packet with stale session-id=a2c377d7 6ea5974c

Thu Jul 17 07:18:07 2014 TLS ERROR: received control packet with stale session-id=a2c377d7 6ea5974c

Thu Jul 17 07:18:07 2014 TLS ERROR: received control packet with stale session-id=a2c377d7 6ea5974c

Thu Jul 17 07:18:07 2014 TLS ERROR: received control packet with stale session-id=a2c377d7 6ea5974c

Thu Jul 17 07:18:07 2014 TLS: Initial packet from [AF_INET]62.212.72.175:443, sid=01d68ee5 1e093b39

Thu Jul 17 07:18:10 2014 VERIFY OK: depth=1, C=IT, ST=IT, L=Perugia, O=airvpn.org, CN=airvpn.org CA, emailAddress=info@airvpn.org

 

..and then it seems to shake loose and continue.

 

Then this, right after:

 

Thu Jul 17 07:19:01 2014 TLS: new session incoming connection from [AF_INET]62.212.72.175:443

Thu Jul 17 07:19:03 2014 VERIFY OK: depth=1, C=IT, ST=IT, L=Perugia, O=airvpn.org, CN=airvpn.org CA, emailAddress=info@airvpn.org

 

Huh? The Air server is initiating a connection? Certificate validates OK, again, then some further errors:

 

Thu Jul 17 07:20:58 2014 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)

Thu Jul 17 07:20:58 2014 TLS Error: TLS handshake failed

Thu Jul 17 07:20:58 2014 TLS Error: Unroutable control packet received from [AF_INET]62.212.72.175:443 (si=3 op=P_ACK_V1)

Thu Jul 17 07:20:58 2014 TLS Error: Unroutable control packet received from [AF_INET]62.212.72.175:443 (si=3 op=P_ACK_V1)

Thu Jul 17 07:20:58 2014 TLS Error: Unroutable control packet received from [AF_INET]62.212.72.175:443 (si=3 op=P_ACK_V1)

Thu Jul 17 07:20:58 2014 TLS Error: Unroutable control packet received from [AF_INET]62.212.72.175:443 (si=3 op=P_ACK_V1)

 

Followed by a normal "initial packet" and the usual handshake.

 

Thu Jul 17 07:20:58 2014 TLS: Initial packet from [AF_INET]62.212.72.175:443, sid=21a8c3fb 50eadad4

 

[handshake]

 

Thu Jul 17 07:21:18 2014 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)

Thu Jul 17 07:21:18 2014 TLS Error: TLS handshake failed

 

Then more errors.

 

But the connection is still up!

 

What's going on, is something here attempting to set up two connections simultaneously? That could explain the "unroutable" errors. But how come my connection is still going when I see "handshake failed"?

 

I have not touched anything while this was happening. Using OpenVPN 2.3.0.

[OpenSourcerer 1441]

I'm connected to the server in question right now. My logs are clean.

Are you able to update OpenVPN? Current version is 2.3.4. If you are using Windows, replacing openvpn.exe in the bin folder of your client is enough. Here's the exe file.

 

Report, please.

[mage1982 15]

If you are using Windows, replacing openvpn.exe

Windows? Don't insult me. :-)

 

Are you saying something changed between 2.3.0 and 2.3.4 that could explain this?

 

(2.3.2 seems to be the latest version that is currently available to me, for what it's worth.)

[OpenSourcerer 1441]

I don't know about relevant changes, but updating software often saved me from more frustration in the past.

Since I'm able to connect using my client on Windows, it is not an error on AirVPN's site.

 

 

If you are using Windows, replacing openvpn.exe

Windows? Don't insult me. :-)

I don't, I'm using Windows myself.

 

(Sent via Tapatalk 4)

[mage1982 15]

Since I'm able to connect using my client on Windows, it is not an error on AirVPN's site.

To be clear, it is definitely not an error - OpenVPN never stopped working, and in fact has kept going through the incident and after - but rather the issue are the strange things in the log that probably shouldn't be there.

 

So as I see it, either Air was doing something out of the ordinary that was confusing OpenVPN (which could be something as trivial as restarting a server process, say), or something or someone else is doing something weird. And in that case I'd like to know.

 

I do appreciate the fact that you are trying to help. Unfortunately there's just nothing here to really fix, as such.

[OpenSourcerer 1441]

So as I see it, either Air was doing something out of the ordinary that was confusing OpenVPN (which could be something as trivial as restarting a server process, say), or something or someone else is doing something weird. And in that case I'd like to know

 

So, the issue is gone now?

[mage1982 15]

The issue is still unsolved.

 

The mystery double connection hasn't shown up in the logs again since I first posted, if that's what you mean.

 

 

Can I just reiterate, in case anyone from Air is keeping an eye on the forums, that I'd really like to know if there's anything you can say?

 

I realize it's hard to know what's going on when you don't keep logs, but if this is something that's come up before or if it could be related to something else it would be useful to know. Even just "we don't know".

[Staff 10014]

Hello mage1982,

 

we do not detect any problem neither on our side nor on your side. The problem in your logs does not look worrying, it looks like just a temporary line problem.

 

Kind regards