Jump to content


Photo

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


  • Please log in to reply
7 replies to this topic

#1 mage1982

mage1982

    Advanced Member

  • Members
  • PipPipPip
  • 68 posts

Posted 17 July 2014 - 06:18 AM

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.

#2 giganerd

giganerd

    I shall have no title

  • Members2
  • PipPipPip
  • 2687 posts
  • LocationGermany

Posted 17 July 2014 - 10:46 AM

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. :)


Always remember:
There's a guide to AirVPN,

Amazon IPs are not dangerous here,
running TOR exits is discouraged,

using spoilers for your logs helps us read your thread.

~ Furthermore, I propose that your paranoia is to be destroyed. ~

Instead of writing me a personal mail, consider contacting me via XMPP at gigan3rd@xmpp.airvpn.org or join the lounge@conference.xmpp.airvpn.org. I might read the mail too late whereas I'm always available on XMPP ;)


#3 mage1982

mage1982

    Advanced Member

  • Members
  • PipPipPip
  • 68 posts

Posted 17 July 2014 - 04:55 PM

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.)

#4 giganerd

giganerd

    I shall have no title

  • Members2
  • PipPipPip
  • 2687 posts
  • LocationGermany

Posted 17 July 2014 - 10:43 PM

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)

Always remember:
There's a guide to AirVPN,

Amazon IPs are not dangerous here,
running TOR exits is discouraged,

using spoilers for your logs helps us read your thread.

~ Furthermore, I propose that your paranoia is to be destroyed. ~

Instead of writing me a personal mail, consider contacting me via XMPP at gigan3rd@xmpp.airvpn.org or join the lounge@conference.xmpp.airvpn.org. I might read the mail too late whereas I'm always available on XMPP ;)


#5 mage1982

mage1982

    Advanced Member

  • Members
  • PipPipPip
  • 68 posts

Posted 18 July 2014 - 10:44 PM

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.

#6 giganerd

giganerd

    I shall have no title

  • Members2
  • PipPipPip
  • 2687 posts
  • LocationGermany

Posted 19 July 2014 - 11:11 AM

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? :o


Always remember:
There's a guide to AirVPN,

Amazon IPs are not dangerous here,
running TOR exits is discouraged,

using spoilers for your logs helps us read your thread.

~ Furthermore, I propose that your paranoia is to be destroyed. ~

Instead of writing me a personal mail, consider contacting me via XMPP at gigan3rd@xmpp.airvpn.org or join the lounge@conference.xmpp.airvpn.org. I might read the mail too late whereas I'm always available on XMPP ;)


#7 mage1982

mage1982

    Advanced Member

  • Members
  • PipPipPip
  • 68 posts

Posted 19 July 2014 - 03:37 PM

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".

#8 Staff

Staff

    Advanced Member

  • Staff
  • PipPipPip
  • 7856 posts

Posted 19 July 2014 - 08:52 PM

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







Similar Topics Collapse

0 user(s) are reading this topic

0 members, 0 guests, 0 anonymous users

Servers online. Online Sessions: 16174 - BW: 57966 Mbit/sYour IP: 3.91.79.74Guest Access.