ANSWERED high latency / lost connection durring hourly TLS rekeying.

[gribib 4]

Hi experts,

 

i have a issue i wish to get enlightened a bit.

 

Every time openvpn does a TLS rekeying once a hour. Do I lose connection for 5-6 sek, can you guys explane to me why this happens and what i can do to avoid this??

 

The system is a dual core 1300Mhz running linux those specs shouldnt be a problem..

 

I have add the logfile for the rekeying process.

 

 

LOG:

Jan  3 21:25:00 -- daemon.notice ovpn-client[19xx]: VERIFY OK: depth=1, /C=IT/ST=IT/L=Perugia/O=airvpn.org/CN=airvpn.org_CA/emailAddress=info@airvpn.org
Jan  3 21:25:00 -- daemon.notice ovpn-client[19xx]: Validating certificate key usage
Jan  3 21:25:00 -- daemon.notice ovpn-client[19xx]: ++ Certificate has key usage  00a0, expects 00a0
Jan  3 21:25:00 -- daemon.notice ovpn-client[19xx]: VERIFY KU OK
Jan  3 21:25:00 -- daemon.notice ovpn-client[19xx]: Validating certificate extended key usage
Jan  3 21:25:00 -- daemon.notice ovpn-client[19xx]: ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Jan  3 21:25:00 -- daemon.notice ovpn-client[19xx]: VERIFY EKU OK
Jan  3 21:25:00 -- daemon.notice ovpn-client[19xx]: VERIFY OK: depth=0, /C=IT/ST=IT/L=Perugia/O=airvpn.org/CN=server/emailAddress=info@airvpn.org
Jan  3 21:25:06 -- daemon.notice ovpn-client[19xx]: Data Channel Encrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
Jan  3 21:25:06 -- daemon.notice ovpn-client[19xx]: Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Jan  3 21:25:06 -- daemon.notice ovpn-client[19xx]: Data Channel Decrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
Jan  3 21:25:06 -- daemon.notice ovpn-client[19xx]: Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Jan  3 21:25:06 -- daemon.notice ovpn-client[19xx]: Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 4096 bit RSA

 

Best Regards,

TM
 

[gribib 4]

still no one...?

 

after what have read it does obvious have something to do with the renegotiation of a new RSA key. On the openvpn webpage i found this section:

 

"Up to 4096-bit is accepted by nearly all RSA systems (including OpenVPN,) but use of keys this large will dramatically increase generation time, TLS handshake delays, and CPU usage for TLS operations; the benefit beyond 2048-bit keys is small enough not to be of great use at the current time. It is often a larger benefit to consider lower validity times than more bits past 2048, but that is for you to decide."

 

next thing i read from there webpage was following:

 

"During SSL/TLS rekeying, there is a transition-window parameter that permits overlap between old and new key usage, so there is no time pressure or latency bottleneck during SSL/TLS renegotiations."

 

from this i conclude that a larger key size, 4096 as airvpn uses, will take much longer to generate and use much CPU power. But it also tells me that the TLS renegotiation will not give any latency during this process. So why am i still experiance a 5-6sek drop in connectivity on the data line??

 

I have follow a edvice from another topic on this forum and tryed with the "-reneg <sek>" command to reduce the number of rekeying per day. But with no success

 

is there a command im missing im my configuration? (using a standard conf. from the configuration generator).

[rickjames 106]

The command to be included is.

reneg-sec 3600

3600 I'm fairly sure is the default.

 

Out of curiosity have you tried different servers?

[gribib 4]

yes and the result is the same no connectivity while TLS renegotiation is being done... 1000mSek can be acceptable but 5-6 sek at way to high.

 

im a bit unsure if its a TLS handshake delay problem, because i unsure how this process could interfer with datalink in the openvpn?

 

or if the transison window is maby 0 and the old key stops working the same time openvpn start the key renegotiation?

[rickjames 106]

Changing the delay won't really help your issue. It only changes how often reneg occurs.

 

You haven't stated what the cpu/chip is its running on so this is just a guess. But by the sounds of it the device is either underpowered or there's a routing issue.

 

Comparing chip Mhz speed really isn't apples to apples. So 1300Mhz on a chip without all the bells and whistles 'large cache's, aes-ni etc.' won't be the same as a decent processor loaded with features running at 1300Mhz.

 

On a little i3 running at 800Mhz 'using tweaked conservative power management' when reneg occurs it doesn't use enough cpu to raise the cpu speed up from 800Mhz. That's with a conservative up_threshold of 18 lol.

 

FWIT.

I have seen reneg crap out while seriously maxing out my bandwidth or if the routing between the machine running openvpn and the server was bad. I personally haven't seen it die due to cpu usage, but I also don't run consumer grade routers. I have however heard of people having cpu issues @ reneg with older nuc's and such.

 

Have you tried running the air client or openvpn on your pc for testing? Might be worth a try just to make sure its not routing or some other oddity.

[gribib 4]

thx for the info, and appreciate the feedback...

 

i have just switch the the openvpn client back into my router, a ac66u and the latency is more or less the same and it is equipped with a BCM4706 (600 MHz MIPS32® 74K superscalar CPU) the other was also a MIPS dual core cpu from Broadcom running at 1300Mhz.

 

and i do agree with you i dont beleave drop is because of cpu power.

 

i will try and run the client on a spare i5 laptop iv got and force reneg more often ....  I will be back.

[zhang888 1066]

I still don't understand why is this considered an issue...This should be done in an async channel and not interrupt your session.

You can verify this by pinging 8.8.8.8 for >3600 seconds and looking at the results.

[gribib 4]

welcome zhang888,

 

yes it does do it async and thats what pussels me, but take a look at the ping result....

 

64 bytes from 8.8.8.8: seq=211 ttl=55 time=18.242 ms
64 bytes from 8.8.8.8: seq=212 ttl=55 time=18.415 ms
64 bytes from 8.8.8.8: seq=213 ttl=55 time=18.266 ms
64 bytes from 8.8.8.8: seq=214 ttl=55 time=68.795 ms
64 bytes from 8.8.8.8: seq=215 ttl=55 time=4980.853 ms
64 bytes from 8.8.8.8: seq=216 ttl=55 time=3981.362 ms
64 bytes from 8.8.8.8: seq=217 ttl=55 time=2982.059 ms
64 bytes from 8.8.8.8: seq=218 ttl=55 time=2007.784 ms
64 bytes from 8.8.8.8: seq=219 ttl=55 time=1008.951 ms
64 bytes from 8.8.8.8: seq=220 ttl=55 time=43.213 ms
64 bytes from 8.8.8.8: seq=221 ttl=55 time=18.382 ms
64 bytes from 8.8.8.8: seq=222 ttl=55 time=18.044 ms

 

the latency happend at exatly at 19:45:31, see log from server...

Jan  9 17:45:31 openvpn[10735]: TLS: tls_process: killed expiring key
Jan  9 17:45:37 openvpn[10735]: VERIFY OK: depth=1, C=IT, ST=IT, L=Perugia, O=airvpn.org, CN=airvpn.org CA, emailAddress=info@airvpn.org
Jan  9 17:45:37 openvpn[10735]: Validating certificate key usage
Jan  9 17:45:37 openvpn[10735]: ++ Certificate has key usage  00a0, expects 00a0
Jan  9 17:45:37 openvpn[10735]: VERIFY KU OK
Jan  9 17:45:37 openvpn[10735]: Validating certificate extended key usage
Jan  9 17:45:37 openvpn[10735]: ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Jan  9 17:45:37 openvpn[10735]: VERIFY EKU OK
Jan  9 17:45:37 openvpn[10735]: VERIFY OK: depth=0, C=IT, ST=IT, L=Perugia, O=airvpn.org, CN=server, emailAddress=info@airvpn.org
Jan  9 17:45:43 openvpn[10735]: Data Channel Encrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
Jan  9 17:45:43 openvpn[10735]: Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Jan  9 17:45:43 openvpn[10735]: Data Channel Decrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
Jan  9 17:45:43 openvpn[10735]: Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Jan  9 17:45:43 openvpn[10735]: Control Channel: TLSv1.2, cipher TLSv1/SSLv3 DHE-RSA-AES256-GCM-SHA384, 4096 bit RSA

 

I am suspecting that the working key has been killed before the new key has been build, like the transition-window where both keys work are set at zero seconds.

[gribib 4]

så i was wrong....

 

the delay was here...

 

Jan  9 17:45:37 openvpn[10735]: VERIFY OK: depth=0, C=IT, ST=IT, L=Perugia, O=airvpn.org, CN=server, emailAddress=info@airvpn.org
Jan  9 17:45:43 openvpn[10735]: Data Channel Encrypt: Cipher 'AES-256-CBC' initialized with 256 bit key

 

the latency or drop happens every time rekeying enter this stage...

 

have tryed adding reneg 3500 and tran-window 1000 those values have nothing to do with the problem...

[zhang888 1066]

Then your CPU is overloaded during the rekey interval. The mhz means almost nothing, it depends on the architecture, OS, other software running etc.

[rickjames 106]

Then your CPU is overloaded during the rekey interval. The mhz means almost nothing, it depends on the architecture, OS, other software running etc.

This ^

 

Give the i5 laptop a go.

[gribib 4]

crap... it must be cpu power problem have no issue on the i5 laptop, cpu usage bearly reaches 3% when it doing the rekeying....

 

realy to bad cos i realy whanted to build it in the router to avoid extra equipment....:/

 

also bad luck  because the router has only uses 2% cpu power when data is going through openvpn. Its only the renegotiation process that screwing things up.

[zhang888 1066]

Aren't you being too negative?

A small latency peak for a few seconds every hour shouldn't be even noticed, unless you are running some very specific internet applications.

[gribib 4]

unfortunately i am...

 

so a secondary machine it is then....:/ now i have to build a second gateway and setup iptables.... :/

 

thanks for youre help guys...