Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Hang after handshake (before auth) using SoftEther server #67

Open
2 tasks
eladlevin opened this issue Aug 27, 2018 · 2 comments
Open
2 tasks

Hang after handshake (before auth) using SoftEther server #67

eladlevin opened this issue Aug 27, 2018 · 2 comments

Comments

@eladlevin
Copy link

eladlevin commented Aug 27, 2018 •
edited
Loading

The server seems to be expecting something and nothing is sent by the client.
onTLSConnect() function is sending auth info and no reply is received. I am able to connect to this server with any other OpenVPN client (OpenVPN Connect for iOS, as well as Windows Client)

Steps to reproduce

  1. Install SoftEther Server - following this step-by-step guide
  2. Generate OpenVPN config file and CA file (also tried to install CA into iOS profiles and activate as valid trusted root CA)
  3. Embed CA into Demo code as instructed (.vanilla, .udp., 1194, .custom, cert contents)
  4. Attempt to connect to the server
  5. connection will fail (see attached logs)

What is the current bug behavior?

Client fails to connect to SoftEther (OpenVPN) server

What is the expected correct behavior?

Client should connect (Softether is compatible with OpenVPN 2.3+ negotiation)

Relevant logs and/or screenshots

default	22:14:26.839479 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.788 INFO PIATunnelProvider.startTunnel():138 - Starting tunnel...
default	22:14:26.846835 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.810 INFO PIATunnelProvider+Configuration.print():536 - Protocols: [UDP:1194]
default	22:14:26.846865 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.810 INFO PIATunnelProvider+Configuration.print():537 - Cipher: AES-128-CBC
default	22:14:26.846910 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.810 INFO PIATunnelProvider+Configuration.print():538 - Digest: SHA1
default	22:14:26.847314 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.811 INFO PIATunnelProvider+Configuration.print():539 - Handshake: Custom
default	22:14:26.847366 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.811 INFO PIATunnelProvider+Configuration.print():540 - MTU: 1350
default	22:14:26.847409 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.811 INFO PIATunnelProvider+Configuration.print():544 - Renegotiation: never
default	22:14:26.847456 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.812 INFO PIATunnelProvider+Configuration.print():546 - Debug: true
default	22:14:26.849712 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.815 DEBUG PIATunnelProvider.logCurrentSSID():492 - Current SSID: 'ASUS_5G'
default	22:14:26.850134 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.815 INFO PIATunnelProvider.connectTunnel():239 - Creating link session
default	22:14:26.850262 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.815 DEBUG ConnectionStrategy.createSocket():59 - DNS resolve hostname: 167.99.160.146
default	22:14:26.850344 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.816 DEBUG ConnectionStrategy.createSocket():66 - DNS resolved addresses: ["167.99.160.146"]
default	22:14:26.850386 -0700	BasicTunnelExtension-iOS	[1 <private> <private>] start
default	22:14:26.850775 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.817 INFO PIATunnelProvider.connectTunnel():258 - Will connect to 167.99.160.146:1194
default	22:14:26.850962 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.817 DEBUG PIATunnelProvider.connectTunnel():260 - Socket type is NEUDPInterface
default	22:14:26.851348 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.819 DEBUG NEUDPInterface.observeValueInTunnelQueue():117 - Socket state is preparing (endpoint: 167.99.160.146:1194 -> in progress)
default	22:14:26.857850 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.822 DEBUG NEUDPInterface.observeValueInTunnelQueue():115 - Socket state is ready (endpoint: 167.99.160.146:1194 -> 167.99.160.146:1194)
default	22:14:26.857891 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.827 DEBUG SessionProxy.setLink():277 - Starting VPN session
default	22:14:26.857932 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.834 DEBUG SessionProxy.hardReset():691 - Send hard reset
default	22:14:26.857973 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.834 DEBUG SessionProxy.hardReset():703 - Negotiation key index is 0
default	22:14:26.858017 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.835 DEBUG SessionProxy.enqueueControlPackets():1036 - Enqueued 1 control packet [0]
default	22:14:26.858057 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.835 DEBUG SessionProxy.flushControlQueue():1053 - Send control packet with code 7
default	22:14:26.858100 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.835 DEBUG SessionProxy.flushControlQueue():1059 - Control packet has payload (0 bytes)
default	22:14:26.858149 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.835 DEBUG SessionProxy.flushControlQueue():1064 - Send control packet (14 bytes): 38918e1e51d444f4570000000000
default	22:14:26.858193 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.835 DEBUG SessionProxy.flushControlQueue():1048 - Skip control packet with id 0 (sent on 2018-08-27 05:14:26 +0000, 3.89814376831055e-05 seconds ago)
default	22:14:26.866928 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.867 DEBUG SessionProxy.receiveLink():547 - Packet has code 8, key 0, sessionId 023b89cd264cb605 and 1 acks entries
default	22:14:26.867332 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.867 DEBUG SessionProxy.receiveLink():568 - Server acked packetIds [0] with remoteSessionId 918e1e51d444f457
default	22:14:26.867950 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.868 DEBUG SessionProxy.receiveLink():582 - Control packet has packetId 0
default	22:14:26.868181 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.868 DEBUG SessionProxy.sendAck():1218 - Send ack for received packetId 0
default	22:14:26.868253 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.868 DEBUG SessionProxy.handleControlPacket():812 - Handle control packet with code 8 and id 0
default	22:14:26.868569 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.868 DEBUG SessionProxy.handleControlPacket():839 - Remote sessionId is 023b89cd264cb605
default	22:14:26.868800 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.869 DEBUG SessionProxy.handleControlPacket():840 - Start TLS handshake
default	22:14:26.868870 -0700	BasicTunnelExtension-iOS	TLSBox initwithCaPath: /var/mobile/Containers/Data/PluginKitPlugin/5CF55F8C-B1FD-4D0F-8CD3-00593F8FBF80/Library/Caches/CA.pem
default	22:14:26.872187 -0700	BasicTunnelExtension-iOS	TLSBox peer verification is true
default	22:14:26.873793 -0700	BasicTunnelExtension-iOS	TLSBox - SSL_CTX_load_verify_locations succeeded
default	22:14:26.876706 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.875 DEBUG SessionProxy.handleControlPacket():855 - TLS.connect: Pulled ciphertext (178 bytes)
default	22:14:26.876754 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.876 DEBUG SessionProxy.enqueueControlPackets():1036 - Enqueued 1 control packet [1]
default	22:14:26.876800 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.876 DEBUG SessionProxy.flushControlQueue():1053 - Send control packet with code 4
default	22:14:26.876847 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.876 DEBUG SessionProxy.flushControlQueue():1059 - Control packet has payload (178 bytes)
default	22:14:26.878762 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.878 DEBUG SessionProxy.flushControlQueue():1064 - Send control packet (192 bytes): 20918e1e51d444f457000000000116030100ad010000a903036916b3e0f09de4ecfc5afe5a9eeeb99a901ba4891b08da6547758a9e78e3b6dc000038c02cc030009fcca9cca8ccaac02bc02f009ec024c028006bc023c0270067c00ac0140039c009c0130033009d009c003d003c0035002f00ff01000048000b000403000102000a000c000a001d0017001900180016002300000016000000170000000d0020001e060106020603050105020503040104020403030103020303020102020203
default	22:14:26.879401 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.879 DEBUG SessionProxy.sendAck():1234 - Ack successfully written to LINK for packetId 0
default	22:14:26.911005 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.910 DEBUG SessionProxy.receiveLink():547 - Packet has code 4, key 0, sessionId 023b89cd264cb605 and 1 acks entries
default	22:14:26.912071 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.910 DEBUG SessionProxy.receiveLink():568 - Server acked packetIds [1] with remoteSessionId 918e1e51d444f457
default	22:14:26.912202 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.910 DEBUG SessionProxy.receiveLink():582 - Control packet has packetId 1
default	22:14:26.912283 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.910 DEBUG SessionProxy.sendAck():1218 - Send ack for received packetId 1
default	22:14:26.912517 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.910 DEBUG SessionProxy.receiveLink():595 - Control packet payload (1200 bytes)
default	22:14:26.912594 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.911 DEBUG SessionProxy.handleControlPacket():812 - Handle control packet with code 4 and id 1
default	22:14:26.912883 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.911 DEBUG SessionProxy.handleControlPacket():876 - TLS.connect: Put received ciphertext (1200 bytes)
default	22:14:26.912928 -0700	BasicTunnelExtension-iOS	TLSBox - Peer verification successful!
default	22:14:26.912961 -0700	BasicTunnelExtension-iOS	TLSBox - pullRawPlainText failed (-1), checking should retry
default	22:14:26.913048 -0700	BasicTunnelExtension-iOS	TLSBox - BIO_should_read is true
default	22:14:26.913172 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.913 DEBUG SessionProxy.sendAck():1234 - Ack successfully written to LINK for packetId 1
default	22:14:26.913849 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.913 DEBUG SessionProxy.receiveLink():547 - Packet has code 4, key 0, sessionId 023b89cd264cb605 and 0 acks entries
default	22:14:26.914944 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.914 DEBUG SessionProxy.receiveLink():582 - Control packet has packetId 2
default	22:14:26.914984 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.914 DEBUG SessionProxy.sendAck():1218 - Send ack for received packetId 2
default	22:14:26.915038 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.914 DEBUG SessionProxy.receiveLink():595 - Control packet payload (206 bytes)
default	22:14:26.915087 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.915 DEBUG SessionProxy.handleControlPacket():812 - Handle control packet with code 4 and id 2
default	22:14:26.915196 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.915 DEBUG SessionProxy.handleControlPacket():876 - TLS.connect: Put received ciphertext (206 bytes)
default	22:14:26.916418 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.916 DEBUG SessionProxy.handleControlPacket():880 - TLS.connect: Send pulled ciphertext (126 bytes)
default	22:14:26.916904 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.916 DEBUG SessionProxy.enqueueControlPackets():1036 - Enqueued 1 control packet [2]
default	22:14:26.917029 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.917 DEBUG SessionProxy.flushControlQueue():1053 - Send control packet with code 4
default	22:14:26.917112 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.917 DEBUG SessionProxy.flushControlQueue():1059 - Control packet has payload (126 bytes)
default	22:14:26.918322 -0700	BasicTunnelExtension-iOS	TLSBox - pullRawPlainText failed (-1), checking should retry
default	22:14:26.918385 -0700	BasicTunnelExtension-iOS	TLSBox - BIO_should_read is true
default	22:14:26.918438 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.918 DEBUG SessionProxy.flushControlQueue():1064 - Send control packet (140 bytes): 20918e1e51d444f45700000000021603030046100000424104d85d0d94607fb26ae32242824fade932ba94132b5cb58067bee6a68a3868ffb8a938cf1e253d658c992f71d875fcfeac46ab431747d1eb84e4d388b3cb417bfe140303000101160303002811c93fadef318059cdc869e1c2df53ff72b5bcc6967669e961d1c22cbbb97b1b204667ca9d96504d
default	22:14:26.918746 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.918 DEBUG SessionProxy.sendAck():1234 - Ack successfully written to LINK for packetId 2
default	22:14:26.949259 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.948 DEBUG SessionProxy.receiveLink():547 - Packet has code 4, key 0, sessionId 023b89cd264cb605 and 1 acks entries
default	22:14:26.949624 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.948 DEBUG SessionProxy.receiveLink():568 - Server acked packetIds [2] with remoteSessionId 918e1e51d444f457
default	22:14:26.949900 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.948 DEBUG SessionProxy.receiveLink():582 - Control packet has packetId 3
default	22:14:26.950198 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.948 DEBUG SessionProxy.sendAck():1218 - Send ack for received packetId 3
default	22:14:26.950447 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.948 DEBUG SessionProxy.receiveLink():595 - Control packet payload (51 bytes)
default	22:14:26.950729 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.949 DEBUG SessionProxy.handleControlPacket():812 - Handle control packet with code 4 and id 3
default	22:14:26.950973 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.949 DEBUG SessionProxy.handleControlPacket():876 - TLS.connect: Put received ciphertext (51 bytes)
default	22:14:26.951071 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.949 DEBUG SessionProxy.onTLSConnect():728 - TLS.connect: Handshake is complete
default	22:14:26.951177 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.949 DEBUG Authenticator.putAuth():75 - TLS.auth: Put plaintext (161 bytes)
default	22:14:26.951352 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.950 DEBUG SessionProxy.onTLSConnect():745 - TLS.auth: Pulled ciphertext (190 bytes)
default	22:14:26.951452 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.950 DEBUG SessionProxy.enqueueControlPackets():1036 - Enqueued 1 control packet [3]
default	22:14:26.951557 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.950 DEBUG SessionProxy.flushControlQueue():1053 - Send control packet with code 4
default	22:14:26.951653 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.951 DEBUG SessionProxy.flushControlQueue():1059 - Control packet has payload (190 bytes)
default	22:14:26.952629 -0700	BasicTunnelExtension-iOS	TLSBox - pullRawPlainText failed (-1), checking should retry
default	22:14:26.952903 -0700	BasicTunnelExtension-iOS	TLSBox - BIO_should_read is true
default	22:14:26.953032 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.952 DEBUG SessionProxy.flushControlQueue():1064 - Send control packet (204 bytes): 20918e1e51d444f457000000000317030300b911c93fadef31805add56388d77db45cdf477fc6f54a949e5094505cf775ef75c50763eff303c1081a6084b41ec0ad721bca5fcec3ace736b60c4e5f1313940655958f7da716346dcab4a85ccec4681c562a8bd80573ad4758c23b4a3cc46eb8f5d0413a1472fb18e0ca9775fdb19c8d8b233b144637efb77d139483e6ad5b65deb25194a7ee2e8da4907f0478de2e461c737d00db58b7917c7bfbdc2f840f24e289cef2fc82bf4119e4adfebf6ee0aac176aae2adc29183ee7
default	22:14:26.953109 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.953 DEBUG SessionProxy.sendAck():1234 - Ack successfully written to LINK for packetId 3
default	22:14:26.980794 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.981 DEBUG SessionProxy.receiveLink():547 - Packet has code 5, key 0, sessionId 023b89cd264cb605 and 1 acks entries
default	22:14:26.981359 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:26.981 DEBUG SessionProxy.receiveLink():568 - Server acked packetIds [3] with remoteSessionId 918e1e51d444f457
default	22:14:37.053636 -0700	BasicTunnelExtension-iOS	[1 <private> datagram, pid: 594] cancelled
	[1 992F4AE8-1DD7-4081-B574-A19BE92C6FB5 <private>.50641<-><private>]
	Connected Path: satisfied (Path is satisfied), interface: en0, scoped, ipv4, dns
	Duration: 10.204s, , UDP @0.004s took 0.001s
default	22:14:37.056976 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:37.034 ERROR SessionProxy.doShutdown():1258 - Trigger shutdown (error: negotiationTimeout)
default	22:14:37.057243 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:37.035 INFO PIATunnelProvider.sessionDidStop():431 - Session did stop
default	22:14:37.057829 -0700	BasicTunnelExtension-iOS	2018-08-26 22:14:37.040 ERROR SessionProxy.loopLink():455 - Failed LINK read: Error Domain=NSPOSIXErrorDomain Code=89 "Operation canceled"

~bug
~ios11

%@ms

/cc @dev /assign @tester

  • Patched
  • Verified patch
@eladlevin
Copy link
Author

still an issue with the latest code.
Anyone looking at this ?

@samkerm
Copy link

samkerm commented Apr 21, 2020

@eladlevin How did you get the logs? I have a problem as described here that would probably be solved by the log.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@eladlevin @samkerm