Opened 10 months ago

Last modified 9 months ago

#990 accepted Bug / Defect

iOS: AUTH_FAILED on every WAKEUP event

Reported by: deepsweet Owned by: Antonio
Priority: major Milestone:
Component: OpenVPN Connect Version: OpenVPN Connect for iOS v1.2.6
Severity: Not set (select this one, unless your'e a OpenVPN developer) Keywords:
Cc:

Description

Hi.

OpenVPN Connect v1.2.6, seamless tunnel, reconnect on wakeup, connection timeout: none, network state detection: active, layer 2 reachability.

This happens every time my iPhone goes to sleep and then wakes up:

psy-rd=0.4,0:level=4.0:ref=6:deblock=1,1:bframes=5:aq-strength=0.6:vbv-bufsize=31250:vbv-maxrate=25000
 psy-rd=0.4,0:level=4.0:ref=6:deblock=1,1:bfr
2018-01-17 11:27:29 OS Event: SLEEP
2018-01-17 11:27:29 EVENT: PAUSE
2018-01-17 11:27:30 OS Event: WAKEUP
2018-01-17 11:27:33 RESUME TEST: Internet:ReachableViaWiFi/-R t------
2018-01-17 11:27:33 STANDARD RESUME
2018-01-17 11:27:33 EVENT: RESUME
2018-01-17 11:27:33 EVENT: RECONNECTING
2018-01-17 11:27:33 Contacting [1.2.3.4]:443/UDP via UDP
2018-01-17 11:27:33 EVENT: WAIT
2018-01-17 11:27:33 Connecting to [some.vpn.server]:443 (1.2.3.4) via UDPv4
2018-01-17 11:27:33 EVENT: CONNECTING
2018-01-17 11:27:33 Tunnel Options:V4,dev-type tun,link-mtu 1601,tun-mtu 1500,proto UDPv4,cipher AES-256-CBC,auth SHA512,keysize 256,key-method 2,tls-client
2018-01-17 11:27:33 Creds: Username/Password
2018-01-17 11:27:33 Peer Info:
IV_GUI_VER=net.openvpn.connect.ios 1.2.6-4
IV_VER=3.1.2
IV_PLAT=ios
IV_IPv6=0
IV_AUTO_SESS=1

2018-01-17 11:27:33 VERIFY OK : depth=0
cert. version     : 3
serial number     : 00
issuer name       : CN=some.vpn.server
subject name      : CN=some.vpn.server
issued  on        : 2015-10-06 12:15:26
expires on        : 2025-10-03 12:15:26
signed using      : RSA with SHA-256
RSA key size      : 2048 bits
basic constraints : CA=true
key usage         : Digital Signature, Non Repudiation, Key Encipherment, Data Encipherment, Key Cert Sign, CRL Sign
ext key usage     : TLS Web Server Authentication, TLS Web Client Authentication, Code Signing, E-mail Protection, ???, ???, ???, Time Stamping, OCSP Signing

2018-01-17 11:27:33 SSL Handshake: TLSv1.0/TLS-DHE-RSA-WITH-AES-256-CBC-SHA
2018-01-17 11:27:33 Session is ACTIVE
2018-01-17 11:27:33 EVENT: GET_CONFIG
2018-01-17 11:27:33 Sending PUSH_REQUEST to server...
2018-01-17 11:27:33 AUTH_FAILED
2018-01-17 11:27:33 EVENT: AUTH_FAILED [ERR]
2018-01-17 11:27:33 EVENT: DISCONNECTED
2018-01-17 11:27:33 Raw stats on disconnect:
  BYTES_IN : 38595074
  BYTES_OUT : 2287186
  PACKETS_IN : 29534
  PACKETS_OUT : 13646
  TUN_BYTES_IN : 1014731
  TUN_BYTES_OUT : 35604484
  TUN_PACKETS_IN : 13143
  TUN_PACKETS_OUT : 28934
  AUTH_FAILED : 1
  N_PAUSE : 36
  N_RECONNECT : 36
2018-01-17 11:27:33 Performance stats on disconnect:
  CPU usage (microseconds): 5649999
  Tunnel compression ratio (uplink): 2.25398
  Tunnel compression ratio (downlink): 1.08399
  Network bytes per CPU second: 7235799
  Tunnel bytes per CPU second: 6481278
2018-01-17 11:27:33 OS Event: SLEEP
2018-01-17 11:28:25 ----- OpenVPN Start -----
OpenVPN core 3.1.2 ios arm64 64-bit built on Jan 14 2018 14:23:32
2018-01-17 11:28:25 Frame=512/2048/512 mssfix-ctrl=1250
2018-01-17 11:28:25 UNUSED OPTIONS
5 [resolv-retry] [infinite] 
6 [nobind] 
7 [persist-key] 
9 [verb] [3] 
11 [verify-x509-name] [some.vpn.server] [name] 
ames=5:aq-strength=0.6:vbv-bufsize=31250:vbv-maxrate=25000

I have an "autologin profile" using "userpass.txt" so it seems to be impossible to have wrong credentials. Also it connects perfectly when I'm doing it manually – never seen a single AUTH_FAILED in this case. My "some.vpn.server" has a limitation of 3 simultaneous connections but only one has been used for sure.

The same happened before with v1.1.1 but much less often, maybe few times in a day, but not on every WAKEUP event.

Attachments (6)

disconnect-logs.txt (4.3 KB) - added by nullbandit 10 months ago.
attaching my logs to the case
IMG_0085.jpg (205.5 KB) - added by nullbandit 10 months ago.
Watch how the credentials go missing from the app in the bottom half. This is after force closing and reopening the app.
disconnect-logs-2.txt (63.7 KB) - added by nullbandit 10 months ago.
These logs are from different Device, watch the "KEV_NEGOTIATE_ERROR" when the app is force closed after a sleep.
IMG_0225.jpg (248.4 KB) - added by nullbandit 10 months ago.
This is screenshot from another device, look how the labels get mismatched. Here the tunnel is already dead by "KEV_NEGOTIATE_ERROR" and creds are gone from the app.
explicit-exit-notify-log.txt (7.0 KB) - added by deepsweet 10 months ago.
explicit-exit-notify
full_log.txt (14.7 KB) - added by deepsweet 10 months ago.
Here is a full log using v1.2.7. So far I have temporarily switched to another VPN service and there I have no such an issue.

Download all attachments as: .zip

Change History (33)

comment:1 Changed 10 months ago by Antonio

Owner: set to Antonio
Status: newaccepted
Version: OpenVPN Connect for iOS v1.2.6

Hi and thanks for the report. Can you please attach your profile (after removing any sensible data of course)? This way we can better understand your configuration.

Thanks

comment:2 Changed 10 months ago by deepsweet

Sure.

Content of my OVPN file:

dev tun
proto udp
remote some.vpn.server 443
;http-proxy-retry
;http-proxy [proxy server] [proxy port]
cipher AES-256-CBC
auth SHA512
#auth-nocache
resolv-retry infinite
nobind
persist-key
client
verb 3
auth-user-pass userpass.txt
verify-x509-name some.vpn.server name
#remote-cert-tls server
#remote-cert-ku f6
dhcp-option DNS 1.2.3.4
dhcp-option DNS 5.6.7.8

<ca>
-----BEGIN CERTIFICATE-----
qwerty=
-----END CERTIFICATE-----

</ca>
###############################################################################
# The client certificate file (dummy).
# 
# In some implementations of OpenVPN Client software
# (for example: OpenVPN Client for iOS),
# a pair of client certificate and private key must be included on the
# configuration file due to the limitation of the client.
# So this sample configuration file has a dummy pair of client certificate
# and private key as follows.

<cert>
-----BEGIN CERTIFICATE-----
qwerty=
-----END CERTIFICATE-----

</cert>

<key>
-----BEGIN RSA PRIVATE KEY-----
qwerty=
-----END RSA PRIVATE KEY-----

</key>
Last edited 10 months ago by deepsweet (previous) (diff)

comment:3 Changed 10 months ago by deepsweet

"qwerty" in certificates section were real long keys... Not sure what they mean by "dummy" in the last section.

comment:4 Changed 10 months ago by Antonio

Thanks! Next time, please, remove the comments, so it's much easier to read :-)
This needs further investigation.

comment:5 Changed 10 months ago by nullbandit

Adding a note here as I have seen this often, for

"EVENT: AUTH_FAILED [ERR]"

Usually this results because of "Max concurrent Connections to the VPN server reached"
Most VPN vendors have set limits of max 5 active connections to the server 10 in case of protonvpn. When that is reached the vendor disconnects the new in coming connections. If the VPN is not IKEV2 this is very much possible that, the client kept the existing connection alive while trying to establish a new connection where by reaching the limit of max concurrent sessions.

But this is not the case with v1.2.5 or v1.2.6. Most sleep on the device leaves the session dead. Only option is to disconnect and reconnect.

When this happened to me in 1.1.1 I usually switched to free vpn profile from protonvpn, let the stay for a few minutes disconnect and then move on to paid profile which kept my session active forever. But with v1.2.6, this hack doesn't work anymore.

QQ to @ORDEX, when a session is put on sleep do you reuse the session on wakeup (it Appears you reuse based on logs)? If the attempt reuse fails do you terminate the session and attempt to create a new session ?

comment:6 Changed 10 months ago by deepsweet

That was exactly my thoughts because my VPN provider has a limitation of 3 simultaneous connections. But then I tried it with a single iOS device using VPN at the same time, so even if one connection got stuck as "dead session", there should be another 2 available. But I still like the idea, stuck and/or not properly killed connections might be the reason of our issue.

The only way to use OpenVPN on iOS for me now is to constantly play music to prevent device sleep, otherwise I always have AUTH_FAILED on WAKEUP.

comment:7 Changed 10 months ago by deepsweet

Hmmm. I just tried to manually connect/disconnect very fast (using the switcher in OpenVPN UI) many times and eventually got the same AUTH_FAILED. After a while, like 5 seconds or so it has finally connected.

Maybe providing some "reconnect delay" option could fix the issue?

Changed 10 months ago by nullbandit

Attachment: disconnect-logs.txt added

attaching my logs to the case

Changed 10 months ago by nullbandit

Attachment: IMG_0085.jpg added

Watch how the credentials go missing from the app in the bottom half. This is after force closing and reopening the app.

Changed 10 months ago by nullbandit

Attachment: disconnect-logs-2.txt added

These logs are from different Device, watch the "KEV_NEGOTIATE_ERROR" when the app is force closed after a sleep.

Changed 10 months ago by nullbandit

Attachment: IMG_0225.jpg added

This is screenshot from another device, look how the labels get mismatched. Here the tunnel is already dead by "KEV_NEGOTIATE_ERROR" and creds are gone from the app.

comment:8 in reply to:  5 ; Changed 10 months ago by Antonio

Replying to nullbandit:

QQ to @ORDEX, when a session is put on sleep do you reuse the session on wakeup (it Appears you reuse based on logs)? If the attempt reuse fails do you terminate the session and attempt to create a new session ?

Hi, sorry for the delay.

When you say "SLEEP" I assume you are referring to iOS going to sleep. In that case the VPN connection is closed completely (the app can't keep the connection alive while sleeping because the app is totally frozen by iOS).

Upon "WAKEUP" the connection is re-established from scratch. Not sure what "session" you are referring to, but the client has to reauthenticate like the first time it connected. The bug might probably be here.

comment:9 Changed 10 months ago by novaflash

With AUTH_FAILED errors on the client side, it would now be most beneficial to get the reason of this authentication failure from the server side. The server may be reporting something like "Session token invalid (may have expired)" or something like that. The server is the one saying that the authentication has failed, so now we need to know why the server thinks that, what the reason for that is. Any chance you can get that information from the server side?

comment:10 in reply to:  9 Changed 10 months ago by deepsweet

Replying to novaflash:

Any chance you can get that information from the server side?

Not in my case for sure, I don't own the server and it should have no logs in any way.

Btw what is your opinion on that I can "reproduce" the issue by doing connect/reconnect manually and very fast? I still think that it's somehow related to 1) max connections limit or 2) lack of some delay between disconnect and connect.

And again, I've never seen such an issue while my device is awake, it only happens during the sleep/wake flow. I mean I can disconnect-wait-connect manually as many times as I want.

Last edited 10 months ago by deepsweet (previous) (diff)

comment:11 Changed 10 months ago by deepsweet

I have more specific details now: if I try to disconnect while it's not connected yet but in "pulling settings from server" status then next time I want to connect I have to wait some seconds first, otherwise I get the same AUTH_FAILED.

Last edited 10 months ago by deepsweet (previous) (diff)

comment:12 Changed 10 months ago by Antonio

I think what you are seeing in these tests is just "expected".
Meaning that either the client is not always sending the "disconnection message" (aka exit notify) or the server is not able to handle it that fast. (the latter is more likely because the server may need to report the session to some external component)

As a consequence you are consuming your allowed sessions.

The original problem, as far as I understood, does not mention any fast reconnection, but just AUTH_FAILED upon wakeup.

The fact that both behaviours lead to the same symptom does not mean that they are connected.

My (wild) guess is that the client is somehow forgetting the credentials when going to sleep and not sending anything upon reconnect.

As novaflash said, having the server log would help clarifying. I guess we need to reproduce the issue in a controlled client-server environment in order to understand what's wrong.

Last edited 10 months ago by Antonio (previous) (diff)

comment:13 in reply to:  description ; Changed 10 months ago by Antonio

Replying to deepsweet:

I have an "autologin profile" using "userpass.txt" so it seems to be impossible to have wrong credentials. Also it connects perfectly when I'm doing it manually – never seen a single AUTH_FAILED in this case. My "some.vpn.server" has a limitation of 3 simultaneous connections but only one has been used for sure.

What do you mean with "doing it manually"? I am trying to grasp the difference that might be triggering this behaviour..

comment:14 in reply to:  12 ; Changed 10 months ago by Antonio

Replying to ordex:

My (wild) guess is that the client is somehow forgetting the credentials when going to sleep and not sending anything upon reconnect.

As novaflash said, having the server log would help clarifying. I guess we need to reproduce the issue in a controlled client-server environment in order to understand what's wrong.

Just performed some tests and it seems that the client is properly sending user and pass after reconnection. I am wondering if the server is using some particular option that might be creating the issue..

comment:15 in reply to:  13 Changed 10 months ago by deepsweet

Replying to ordex:

What do you mean with "doing it manually"? I am trying to grasp the difference that might be triggering this behaviour..

By manually I mean connect/disconnect UI switcher in OpenVPN app, so the issue happens only in "auto" mode not triggered by me.

comment:16 in reply to:  14 ; Changed 10 months ago by deepsweet

Replying to ordex:

Just performed some tests and it seems that the client is properly sending user and pass after reconnection. I am wondering if the server is using some particular option that might be creating the issue..

Happens both with credentials saved in keychain and using "userpass.txt" mode. There is a huge confusion with AUTH_FAILED error for me because as far as I see it happens not only with wrong credentials but with connections limit as well.

comment:17 in reply to:  16 Changed 10 months ago by Antonio

Replying to deepsweet:

Replying to ordex:

Just performed some tests and it seems that the client is properly sending user and pass after reconnection. I am wondering if the server is using some particular option that might be creating the issue..

Happens both with credentials saved in keychain and using "userpass.txt" mode. There is a huge confusion with AUTH_FAILED error for me because as far as I see it happens not only with wrong credentials but with connections limit as well.

Yeah, that's because when sending the credential (from client to server) the server can only say OK or FAIL. While the OK is pretty clear, the reason for "FAIL" might be several and only the server knows what it is (i.e. maximum number of session reached, wrong password, anything else you can come up with....).

This is why understanding what the server is doing might be beneficial. However, I understand in this case it might not be easy to get access to that information.

comment:18 Changed 10 months ago by deepsweet

Yes, getting server logs is impossible, sorry. I understand how hard it's to debug this, but I can't help other than testing client-side.

comment:19 Changed 10 months ago by nullbandit

Just noticed your is UDP ovpn, can you add the following in your client config ?

explicit-exit-notify 2

It usually helps in getting resolution to closing the tunnel when reconnecting.

comment:20 in reply to:  8 ; Changed 10 months ago by nullbandit

Replying to ordex:

Replying to nullbandit:

QQ to @ORDEX, when a session is put on sleep do you reuse the session on wakeup (it Appears you reuse based on logs)? If the attempt reuse fails do you terminate the session and attempt to create a new session ?

Hi, sorry for the delay.

When you say "SLEEP" I assume you are referring to iOS going to sleep. In that case the VPN connection is closed completely (the app can't keep the connection alive while sleeping because the app is totally frozen by iOS).

I meant yes IOS going to sleep. If the "OpenVPN Connect" has no way to inform the server that its going to die, the server might keep the connection alive, which could lead to reaching max connections active when reconnecting by the client, thus one can get AUTH_FAILED. Unless the client has ping* directives and server strictly maintains the TCP session based on those directives.

In UDP if the explicit-exit-notify directive is used, it can tell the server that I am going to be dead by so and so time if I dont respond.

Upon "WAKEUP" the connection is re-established from scratch. Not sure what "session" you are referring to, but the client has to reauthenticate like the first time it connected. The bug might probably be here.

If "WAKEUP" uses same steps in connection re-establishment why does the log says "Session is ACTIVE", "EVENT: Resume" its kind of misleading, because I thought its session resume (like tcp session resume of ssl session resume).

One thing I noticed in the logs were, the session gets connected after wake up in case of "UDP" but the traffic doesnt flow, "Bytes In" and "Bytes Out" remain static no change in counters, except "Packet Received" keeps updating. Does that mean traffic is leaking outside the tunnel ? Or the app forgets to set the "routes" Something is missing here imo as well.

Changed 10 months ago by deepsweet

explicit-exit-notify

comment:21 in reply to:  20 Changed 10 months ago by Antonio

Replying to nullbandit:

In UDP if the explicit-exit-notify directive is used, it can tell the server that I am going to be dead by so and so time if I dont respond.

if you look up in the log (right after start) you should see explicit-exit-notify under the UNUSED OPTIONS, because OpenVPN Connect should already sends it by default.

Last edited 10 months ago by Antonio (previous) (diff)

comment:22 Changed 10 months ago by Antonio

Can somebody here post the full log from the first working connection until the reconnection failing due to AUTH_FAIL, please?

Basically everything from the -----OpenVPN Start---- (or similar) message

comment:23 in reply to:  22 Changed 10 months ago by nullbandit

Replying to ordex:

Can somebody here post the full log from the first working connection until the reconnection failing due to AUTH_FAIL, please?

Basically everything from the -----OpenVPN Start---- (or similar) message

On V1.2.6-4, (at least on my VPN service) I don't see this issue happening on UDP/TCP (i don't have auth-user-pass profile), I am hit with the DNS resolve bug.

But my guess is

auth-user-pass userpass.txt

The file content may not accessible during WAKEUP and RESUME to OpenVPN Connect. Does the code check if the file is accessible when resuming from WAKEUP ?

comment:24 Changed 10 months ago by Antonio

Yeah it is. I have tested it myself and it works fine. Thus it must be some other setting interfering (i.e. token generation on the server side). This is why I wanted to see the complete log.

Changed 10 months ago by deepsweet

Attachment: full_log.txt added

Here is a full log using v1.2.7. So far I have temporarily switched to another VPN service and there I have no such an issue.

comment:25 Changed 10 months ago by Antonio

From the log it looks like the device is doing the sleep/wake cycle 6 times in one minute.
Do you know why that is happening?

Every time it wakes up the app is attempting a connection, until the last time when it gets AUTH_FAILED. It may well be that the failure is triggered on the server by the too many reconnections in the short time.

comment:26 Changed 9 months ago by deepsweet

Unfortunately I have no idea. But it's totally reproducible every time only with this VPN service provide. I'm using another one from time to time and it sleeps/wakes without any issues according to the logs.

The only potentially helpful information – I've completely disabled "Background App Refresh" on my iPhone.

comment:27 Changed 9 months ago by hunterx1

just watching, but this is my info...

I had this issue in the past on what I believe to be version 1.1.1. It could be rapid connections, but I never got a chance to duplicate on demand. I was using 3/5 connections (MAX), but 2 are iOS (disconnects quickly), one is a PC (always on). I reduced my usage to just PC + iPhone and the issue went away. In some cases, I may have only been using 2, though the 2 iOS devices may have been reconnecting briefly to show notifications causing a wake? I sometimes notice that just waking the screen causes a reconnect without the need to unlock, so maybe that could contribute to the quick reconnect/disconnects. When I get notifications, they get sent to all my devices at the same time. seamless tunnel ON.

EDIT: AUTH_FAILED was random rather than every wakeup like bug title. Frequency was ~1/day. It only seemed to occur with seamless tunnel ON. Never occurred using stock app either. I would recommend turning seamless tunnel OFF if it is still occurring.

Last edited 9 months ago by hunterx1 (previous) (diff)
Note: See TracTickets for help on using tickets.