Opened 3 years ago

Last modified 3 years ago

#967 new Bug / Defect

Server not initializing Encrypt/Decrypt keys

Reported by: ruisantos Owned by: Steffan Karger
Priority: major Milestone:
Component: Crypto Version: OpenVPN 2.4.4 (Community Ed)
Severity: Not set (select this one, unless your'e a OpenVPN developer) Keywords:
Cc: Steffan Karger

Description

Hello,

Following the email on openvpn-users list, https://sourceforge.net/p/openvpn/mailman/message/36155518/, here is the requested bug report:

I am experiencing an issue only reported, after the upgrade of servers to v2.4.4. It only happens on a few percentage of the users, and only on a few locations :|, so far. And even to make things worst, it does not even happen every time.

The issue, is that the server, sometimes, when a client is connecting for a first time, keeps reporting the following:
Fri Dec 8 10:49:34 2017 us=532606 MrAnderson?/2.2.2.2:49359 MULTI: primary virtual IP for MrAnderson?/2.2.2.2:49359: 100.120.128.3
Fri Dec 8 10:49:34 2017 us=532674 MrAnderson?/2.2.2.2:49359 SENT CONTROL [MrAnderson?]: 'PUSH_REPLY,dhcp-option DNS 100.120.0.1,redirect-gateway def1,ping 9,ping-restart 30,explicit-exit-notify 1,route-gateway 100.120.128.1,topology subnet,redirect-gateway def1,ifconfig-ipv6 2001:db8:123::2/64 2001:db8:123::1,route-ipv6 2000::/3 2001:db8:123::1,explicit-exit-notify 2,compress,ifconfig 100.120.128.3 255.255.252.0,peer-id 0,cipher AES-256-GCM' (status=1)
Fri Dec 8 10:49:34 2017 us=532783 MrAnderson?/2.2.2.2:49359 MULTI: modified fd 8, mask 32768
Fri Dec 8 10:49:34 2017 us=532831 MrAnderson?/2.2.2.2:49359 UDPv4 WRITE [399] to [AF_INET]2.2.2.2:49359: P_CONTROL_V1 kid=0 [ ] pid=7 DATA len=385
Fri Dec 8 10:49:34 2017 us=594533 GET INST BY REAL: 2.2.2.2:49359 [ok]
Fri Dec 8 10:49:34 2017 us=594583 MrAnderson?/2.2.2.2:49359 UDPv4 READ [22] from [AF_INET]2.2.2.2:49359: P_ACK_V1 kid=0 [ 7 ]
Fri Dec 8 10:49:34 2017 us=594690 GET INST BY REAL: 2.2.2.2:49359 [ok]
Fri Dec 8 10:49:34 2017 us=594718 MrAnderson?/2.2.2.2:49359 UDPv4 READ [73] from [AF_INET]2.2.2.2:49359: P_DATA_V2 kid=0 DATA len=72
Fri Dec 8 10:49:34 2017 us=594733 MrAnderson?/2.2.2.2:49359 Key [AF_INET]2.2.2.2:49359 [0] not initialized (yet), dropping packet.
Fri Dec 8 10:49:34 2017 us=594757 GET INST BY REAL: 2.2.2.2:49359 [ok]
Fri Dec 8 10:49:34 2017 us=594785 MrAnderson?/2.2.2.2:49359 UDPv4 READ [96] from [AF_INET]2.2.2.2:49359: P_DATA_V2 kid=0 DATA len=95
Fri Dec 8 10:49:34 2017 us=594803 MrAnderson?/2.2.2.2:49359 Key [AF_INET]2.2.2.2:49359 [0] not initialized (yet), dropping packet.
Fri Dec 8 10:49:34 2017 us=594825 GET INST BY REAL: 2.2.2.2:49359 [ok]
Fri Dec 8 10:49:34 2017 us=594841 MrAnderson?/2.2.2.2:49359 UDPv4 READ [77] from [AF_INET]2.2.2.2:49359: P_DATA_V2 kid=0 DATA len=76
Fri Dec 8 10:49:34 2017 us=594854 MrAnderson?/2.2.2.2:49359 Key [AF_INET]2.2.2.2:49359 [0] not initialized (yet), dropping packet.
Fri Dec 8 10:49:34 2017 us=606809 GET INST BY REAL: 2.2.2.2:49359 [ok]
Fri Dec 8 10:49:34 2017 us=606856 MrAnderson?/2.2.2.2:49359 UDPv4 READ [77] from [AF_INET]2.2.2.2:49359: P_DATA_V2 kid=0 DATA len=76
Fri Dec 8 10:49:34 2017 us=606872 MrAnderson?/2.2.2.2:49359 Key [AF_INET]2.2.2.2:49359 [0] not initialized (yet), dropping packet.
Fri Dec 8 10:49:34 2017 us=611257 GET INST BY REAL: 2.2.2.2:49359 [ok]
(Real IP and username replaced)

So, since the keys appear not to be initialized, there is no communication from the server to the client, and eventually, the ping-timeout occurs. When that happens, there is a reconnection, and
everything works as expected including the key definition.

I can pretty much replicate this, with the help of some colleagues.
What we were able to find out too, is that this issue does not occur, if the option --ncp-disable is set on the client's config file.

I've already searched through the bug report database, and found nothing to support this behavior.
Has anyone stumble upon this issue?

Both client and server are v2.4.4.

Please find the attached logs, for both server and client with --verb 7

Also, here are some specific answers for questions posted on the mailing list
Q: Specify what kind of authentication mechanisms you are using.
A: Both certs and username/password combination

Q: Any additional scripts/plugins?
A: --client-connect and --client-disconnect scripts are used. The --auth-user-pass-verify script is being executed on an plugin for deffered authentication. async push reply is also being used.

Please do let me know if you need any other information.

Thank you for you time.
Cheers,
Rui

Attachments (2)

server.log (233.5 KB) - added by ruisantos 3 years ago.
Server Log with --verb 7
client.log (90.8 KB) - added by ruisantos 3 years ago.
Client log with --verb 7 (no timestamps :( )

Download all attachments as: .zip

Change History (4)

Changed 3 years ago by ruisantos

Attachment: server.log added

Server Log with --verb 7

Changed 3 years ago by ruisantos

Attachment: client.log added

Client log with --verb 7 (no timestamps :( )

comment:1 Changed 3 years ago by Steffan Karger

Cc: Steffan Karger added
Component: Generic / unclassifiedCrypto
Owner: set to Steffan Karger
Version: OpenVPN 2.4.4 (Community Ed)

Thanks for creating the ticket and supplying the additional information.

As mentioned on the mailing list, this is likely related to NCP. Your answers wrt authentication further strengthen my initial suspicion: some bad interaction between deffered auth / async push and NCP.

Someone will need to further investigate. Any help or additional information is welcome.

comment:2 Changed 3 years ago by tincantech

CC

Note: See TracTickets for help on using tickets.