Negotiation times out with SoftEther servers #67

keeshux · 2019-03-10T21:07:54Z

Reported by a few users. SoftEther is not officially supported, but this might be worth looking into.

ghost · 2019-03-12T18:48:04Z

SoftEther log at time of a connection attempt (not worried about IP addresses being hidden as this is a test server on a public hotspot) :) No idea if any of this is useful or not.

server_log
2019-03-12 18:41:36.639 On the TCP Listener (Port 443), a Client (IP address 85.241.205.47, Host name "bl8-205-47.dsl.telepac.pt", Port number 57656) has connected.
2019-03-12 18:41:36.639 For the client (IP address: 85.241.205.47, host name: "bl8-205-47.dsl.telepac.pt", port number: 57656), connection "CID-2" has been created.
2019-03-12 18:41:36.639 OpenVPN Module: The OpenVPN Server Module is starting.
2019-03-12 18:41:36.639 OpenVPN Session 1 (85.241.205.47:57656 -> 178.62.6.160:443): A new session is created. Protocol: TCP
2019-03-12 18:41:36.639 OpenVPN Session 1 (85.241.205.47:57656 -> 178.62.6.160:443) Channel 0: A new channel is created.
2019-03-12 18:41:46.673 OpenVPN Module: The OpenVPN Server Module is stopped.
2019-03-12 18:41:46.673 Connection "CID-2" has been terminated.
2019-03-12 18:41:46.673 The connection with the client (IP address 85.241.205.47, Port number 57656) has been disconnected.

packet_log
2019-03-12,18:41:38.986,SID-SECURENAT-1,-,00AC4A95E51D,FFFFFFFFFFFF,0x0800,80,UDPv4,-,192.168.30.1,echo(7),192.168.30.255,echo(7),-,-,-,FFFFFFFFFFFF00AC4A95E51D080045000042000F000080117C4BC0A81E01C0A81EF$
2019-03-12,18:41:38.986,SID-SECURENAT-1,-,00AC4A95E51D,FFFFFFFFFFFF,0x0806,42,ARPv4,Response,-,-,-,-,-,-,00AC4A95E51D has 192.168.30.1,FFFFFFFFFFFF00AC4A95E51D0806000108000604000200AC4A95E51DC0A81E01FFFF$
2019-03-12,18:41:44.043,SID-SECURENAT-1,-,00AC4A95E51D,FFFFFFFFFFFF,0x0800,80,UDPv4,-,192.168.30.1,echo(7),192.168.30.255,echo(7),-,-,-,FFFFFFFFFFFF00AC4A95E51D0800450000420010000080117C4AC0A81E01C0A81EF$
2019-03-12,18:41:44.043,SID-SECURENAT-1,-,00AC4A95E51D,FFFFFFFFFFFF,0x0806,42,ARPv4,Response,-,-,-,-,-,-,00AC4A95E51D has 192.168.30.1,FFFFFFFFFFFF00AC4A95E51D0806000108000604000200AC4A95E51DC0A81E01FFFF$
2019-03-12,18:41:49.182,SID-SECURENAT-1,-,00AC4A95E51D,FFFFFFFFFFFF,0x0800,80,UDPv4,-,192.168.30.1,echo(7),192.168.30.255,echo(7),-,-,-,FFFFFFFFFFFF00AC4A95E51D0800450000420011000080117C49C0A81E01C0A81EF$
2019-03-12,18:41:49.182,SID-SECURENAT-1,-,00AC4A95E51D,FFFFFFFFFFFF,0x0806,42,ARPv4,Response,-,-,-,-,-,-,00AC4A95E51D has 192.168.30.1,FFFFFFFFFFFF00AC4A95E51D0806000108000604000200AC4A95E51DC0A81E01FFFF$

iOS App Debug Log
App: Passepartout 1.0.2 (1)
OS: iOS 12.1
Device: iPhone

18:41:35 - Starting tunnel...
18:41:35 - App version: Passepartout 1.0.2 (1)
18:41:35 - Protocols: [TCP:443]
18:41:35 - Cipher: AES-128-CBC
18:41:35 - Digest: HMAC-SHA1
18:41:35 - Client verification: enabled
18:41:35 - Server EKU verification: disabled
18:41:35 - MTU: 1250
18:41:35 - Compression framing: disabled
18:41:35 - Keep-alive: never
18:41:35 - Renegotiation: never
18:41:35 - TLS wrapping: disabled
18:41:35 - Debug: true
18:41:35 - Current SSID: none (disconnected from WiFi)
18:41:35 - Creating link session
18:41:35 - DNS resolve hostname: #7d8766fff07665c5#
18:41:35 - DNS resolved addresses: ["#8a3be26221bc8d32#"]
18:41:35 - Will connect to #40b2e033500e4119#:443
18:41:35 - Socket type is NETCPSocket
18:41:35 - Socket state is connecting (endpoint: #959148ec99e0d15f# -> in progress)
18:41:36 - Socket state is connected (endpoint: #8240113ec28599b7# -> #8240113ec28599b7#)
18:41:36 - Starting VPN session
18:41:36 - Send hard reset
18:41:36 - Negotiation key index is 0
18:41:36 - Control: Enqueued 1 packet [0]
18:41:36 - Control: Write control packet {HARD_RESET_CLIENT_V2 | 0, sid: 30af864c221d9864, pid: 0, [0 bytes]}
18:41:36 - Send control packet (14 bytes): 3830af864c221d98640000000000
18:41:36 - Control: Try read packet with code HARD_RESET_SERVER_V2 and key 0
18:41:36 - Control: Read packet {HARD_RESET_SERVER_V2 | 0, sid: 6df84cb3add55afa, acks: {[0], 30af864c221d9864}, pid: 0}
18:41:36 - Send ack for received packetId 0
18:41:36 - Control: Write ack packet {ACK_V1 | 0, sid: 30af864c221d9864, acks: {[0], 6df84cb3add55afa}}
18:41:36 - Control: Remote sessionId is 6df84cb3add55afa
18:41:36 - Start TLS handshake
18:41:36 - TLS.connect: Pulled ciphertext (176 bytes)
18:41:36 - Control: Enqueued 1 packet [1]
18:41:36 - Control: Write control packet {CONTROL_V1 | 0, sid: 30af864c221d9864, pid: 1, [176 bytes]}
18:41:36 - Send control packet (190 bytes): 2030af864c221d9864000000000116030100ab010000a70303a41a0887b91b4e77325bcd9dd0401c664e56eff36c36bbbc5b673d4eefcd0a62000038c02cc030009fcca9cca8ccaac02bc02f009ec024c028006bc023c0270067c00ac0140039c009c0130033009d009c003d003c0035002f00ff01000046000b000403000102000a000a0008001d001700190018002300000016000000170000000d0020001e060106020603050105020503040104020403030103020303020102020203
18:41:36 - Ack successfully written to LINK for packetId 0
18:41:39 - Control: Try read packet with code CONTROL_V1 and key 0
18:41:39 - Control: Read packet {CONTROL_V1 | 0, sid: 6df84cb3add55afa, acks: {[1], 30af864c221d9864}, pid: 1, [1200 bytes]}
18:41:39 - Send ack for received packetId 1
18:41:39 - Control: Write ack packet {ACK_V1 | 0, sid: 30af864c221d9864, acks: {[1], 6df84cb3add55afa}}
18:41:39 - TLS.connect: Put received ciphertext (1200 bytes)
18:41:39 - Control: Try read packet with code CONTROL_V1 and key 0
18:41:39 - Control: Read packet {CONTROL_V1 | 0, sid: 6df84cb3add55afa, pid: 2, [328 bytes]}
18:41:39 - Send ack for received packetId 2
18:41:39 - Control: Write ack packet {ACK_V1 | 0, sid: 30af864c221d9864, acks: {[2], 6df84cb3add55afa}}
18:41:39 - TLS.connect: Put received ciphertext (328 bytes)
18:41:39 - TLS.connect: Send pulled ciphertext (126 bytes)
18:41:39 - Control: Enqueued 1 packet [2]
18:41:39 - Control: Write control packet {CONTROL_V1 | 0, sid: 30af864c221d9864, pid: 2, [126 bytes]}
18:41:39 - Send control packet (140 bytes): 2030af864c221d9864000000000216030300461000004241049a13f7e8cc0fa8ce614be06d8a87f4082fa974bb56b0482fec6907eb26d49e9d75d0dc57912745f0a0267cfa1530003c014c7b161b622359a8bd716111cc9ca91403030001011603030028f60c8acb27ff6ac76ada624c7f1a27a0f862417a938c11ac644f5a45084fd43f9905b10f189fd7af
18:41:39 - Ack successfully written to LINK for packetId 1
18:41:39 - Ack successfully written to LINK for packetId 2
18:41:39 - Control: Try read packet with code CONTROL_V1 and key 0
18:41:39 - Control: Read packet {CONTROL_V1 | 0, sid: 6df84cb3add55afa, acks: {[2], 30af864c221d9864}, pid: 3, [51 bytes]}
18:41:39 - Send ack for received packetId 3
18:41:39 - Control: Write ack packet {ACK_V1 | 0, sid: 30af864c221d9864, acks: {[3], 6df84cb3add55afa}}
18:41:39 - TLS.connect: Put received ciphertext (51 bytes)
18:41:39 - TLS.connect: Handshake is complete
18:41:39 - TLS.auth: Put plaintext (277 bytes)
18:41:39 - TLS.auth: Pulled ciphertext (306 bytes)
18:41:39 - Control: Enqueued 1 packet [3]
18:41:39 - Control: Write control packet {CONTROL_V1 | 0, sid: 30af864c221d9864, pid: 3, [306 bytes]}
18:41:39 - Send control packet (320 bytes): 2030af864c221d98640000000003170303012df60c8acb27ff6ac872d0d8c9603dec70a6e242903a94f248d88068f52d04e7f7da75cd5586e0c6bc8a1b14f0b113200bb5c9f5525167be223437088ff1451e3c4d474c6cef4a9192a255eed06566b772fa34a5b511be463a962730ca3f85137cfd9a890f704f3332186479bdbc9c920d58457312213c29e64a92f377db09e9805d171f7dace033385440eb49a5eb256f5f4cefb7b78fb50f24dbb64ebfc0735af167c3cb4ba5a78e04305faa6db6e99d84784d9d4dd38e2363643f743bffed70fbaed1e31b35714a16dcbaee20635940f7ba8a79354bf2fc65774b04ccfb6b0869280594f439efcb412947966a461d3fe76cea7635d64467d9f3b92d8478dff5dfdb6f59b42adf8c3cc1b93191e29652b21be5e39496f76386ca87b00d2ef0f790bce38bc0c3fda6c4a4164937
18:41:39 - Ack successfully written to LINK for packetId 3
18:41:39 - Control: Try read packet with code ACK_V1 and key 0
18:41:39 - Control: Read packet {ACK_V1 | 0, sid: 6df84cb3add55afa, acks: {[3], 30af864c221d9864}}
18:41:46 - Trigger shutdown (error: negotiationTimeout)
18:41:46 - Session did stop
18:41:46 - Failed LINK read: Error Domain=kNWErrorDomainPOSIX Code=89 "Operation canceled" UserInfo={NSDescription=Operation canceled}
18:41:46 - Socket state is cancelled (endpoint: #0f52f196983ae483# -> in progress)
18:41:46 - Cleaning up...
18:41:46 - Tunnel did stop (error: negotiationTimeout)
18:41:46 - No more protocols available
18:41:46 - Flushing log...

ghost · 2019-03-12T18:56:59Z

Section 3.10.4 of this page shows the format of the packet log: https://www.softether.org/4-docs/1-manual/3._SoftEther_VPN_Server_Manual/3.A_Logging_Service

keeshux · 2019-03-13T21:40:45Z

Yes it is somewhat helpful. The client sends credentials over a correctly established TLS channel, in fact the server acks their receipt (packetId 3). At that point, the client normally expects the server to reply with either the random material or AUTH_FAILED. Nevertheless, the server stands still.

It seems to expect something more after the auth message, and that's exactly where you want to inspect the differences between SoftEther and vanilla OpenVPN.

ghost · 2019-03-14T09:37:07Z

@keeshux I can give you root access to the server and the ovpn config if it would help investigate?

keeshux · 2019-03-14T09:39:50Z

I wouldn't mind, but it won't be any soon.

keeshux · 2019-03-22T16:51:57Z

@VinylCarbon I see that you're using TCP. Do you have any luck with UDP?

I ask because this issue might be related to another weird one I'm facing, and knowing whether it's related to TCP could be crucial to fix both.

ghost · 2019-03-22T20:12:51Z

@keeshux nope, unfortunately it appears to be the same with both TCP and UDP.

ghost · 2019-04-12T08:30:33Z

@keeshux it may be worth looking at this library - https://github.com/ss-abramchuk/OpenVPNAdapter as this works with SoftEther, so you may be able to see the differences in this vs tunnelkit.

keeshux · 2019-04-12T17:52:10Z

@VinylCarbon gotcha, thanks! I was clearing my personal TODO list before picking this up, just saying that I haven't forgotten. 🙂

ghost · 2019-04-12T19:15:52Z

@keeshux yeah don't worry, just been playing around with it and got it working so thought it was worth sending over :)

keeshux · 2019-04-13T08:46:07Z

@keeshux I can give you root access to the server and the ovpn config if it would help investigate?

@VinylCarbon would you send me an email with instructions? I now have some time to look into this issue.

keeshux · 2019-04-13T08:58:07Z

@keeshux it may be worth looking at this library - https://github.com/ss-abramchuk/OpenVPNAdapter as this works with SoftEther, so you may be able to see the differences in this vs tunnelkit.

I see it uses the official OpenVPN library internally, so I'd rather look at that directly. Thanks anyway. :)

ghost · 2019-04-13T16:56:40Z

@keeshux sorry just to clarify, do you want the server details then? :-)

keeshux · 2019-04-13T17:13:27Z

Yes, any means except setting up my own server..!

ghost · 2019-04-13T17:14:44Z

No problem, email on the way (just checking the server is still running!)

keeshux added the question Further information is requested label Mar 10, 2019

keeshux added the bug Something isn't working label Mar 22, 2019

keeshux self-assigned this Mar 22, 2019

keeshux modified the milestones: 1.5.1, 1.5.2 Mar 22, 2019

keeshux mentioned this issue Mar 22, 2019

On TCP, no PUSH_REPLY unless PUSH_REQUEST is sent repeatedly #73

Closed

keeshux removed this from the 1.5.2 milestone Apr 1, 2019

keeshux added this to the 1.6.2 milestone Apr 13, 2019

keeshux closed this as completed in 322242d Apr 13, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Negotiation times out with SoftEther servers #67

Negotiation times out with SoftEther servers #67

keeshux commented Mar 10, 2019

ghost commented Mar 12, 2019

ghost commented Mar 12, 2019

keeshux commented Mar 13, 2019 •

edited

Loading

ghost commented Mar 14, 2019

keeshux commented Mar 14, 2019

keeshux commented Mar 22, 2019

ghost commented Mar 22, 2019

ghost commented Apr 12, 2019

keeshux commented Apr 12, 2019

ghost commented Apr 12, 2019

keeshux commented Apr 13, 2019

keeshux commented Apr 13, 2019

ghost commented Apr 13, 2019

keeshux commented Apr 13, 2019

ghost commented Apr 13, 2019

Negotiation times out with SoftEther servers #67

Negotiation times out with SoftEther servers #67

Comments

keeshux commented Mar 10, 2019

ghost commented Mar 12, 2019

ghost commented Mar 12, 2019

keeshux commented Mar 13, 2019 • edited Loading

ghost commented Mar 14, 2019

keeshux commented Mar 14, 2019

keeshux commented Mar 22, 2019

ghost commented Mar 22, 2019

ghost commented Apr 12, 2019

keeshux commented Apr 12, 2019

ghost commented Apr 12, 2019

keeshux commented Apr 13, 2019

keeshux commented Apr 13, 2019

ghost commented Apr 13, 2019

keeshux commented Apr 13, 2019

ghost commented Apr 13, 2019

keeshux commented Mar 13, 2019 •

edited

Loading