search

ancwrd1 / snx-rs

Open source Linux client for Checkpoint VPN tunnels
GNU Affero General Public License v3.0
57 stars 5 forks source link

TOTP+password auth does not work after intoducing SAML authentication #13

Closed nut-3 closed 3 months ago

nut-3 commented 4 months ago

Hi! As I said in #11, after introducing SAML, TOTP+password auth with indeed key stopped working both in ipsec and ssl. I think mainly this is because of every auth request starts without pre-populating password (except when password is stored in config file). With debug logs I can see that when using ipsec tunnel server first requests TOTP. After receiving password from user input it then asks for domain password, but this request is not forwarded to user:

Ipsec log

``` 2024-03-06T06:32:41.504310Z DEBUG snx_rs::tunnel::ipsec::natt: Sending NAT-T probe to SOME.IP.ADDR.1 2024-03-06T06:32:41.510443Z DEBUG snx_rs::tunnel::ipsec::natt: Received NAT-T reply from Pe 92 to SOME.IP.ADDR.1:500 2024-03-06T06:32:42.069910Z DEBUG isakmp::transport: Parsing ISAKMP message of size 412 2024-03-06T06:32:42.069963Z DEBUG isakmp::ikev1: Message ID: 84b0068c 2024-03-06T06:32:42.069975Z DEBUG isakmp::ikev1: Response message ID: 84b0068c 2024-03-06T06:32:42.069985Z DEBUG snx_rs::tunnel::connector: No status in reply, requested challenge for: UserPassword 2024-03-06T06:32:42.070008Z DEBUG snx_rs::tunnel::connector: Challenge msg: password: 2024-03-06T06:32:42.070236Z DEBUG snx_rs::tunnel::connector: Challenge ID: CPSC_RADIUS_ENTER_PASSWORD 2024-03-06T06:32:42.070247Z DEBUG snx_rs::tunnel::connector: Challenge prompt: password: 2024-03-06T06:32:42.070270Z DEBUG snx_rs::server: Pending multi-factor, awaiting for it 2024-03-06T06:32:50.711982Z DEBUG snx_rs::server: Handling challenge code command 2024-03-06T06:32:50.712019Z DEBUG isakmp::ikev1: Sending auth attribute: UserPassword, timeout: Some(120) seconds 2024-03-06T06:32:50.712147Z DEBUG isakmp::transport: Sending ISAKMP message of size 92 to SOME.IP.ADDR.1:500 2024-03-06T06:32:53.097102Z DEBUG isakmp::transport: Parsing ISAKMP message of size 860 2024-03-06T06:32:53.097200Z DEBUG isakmp::ikev1: Message ID: 84b0068c 2024-03-06T06:32:53.097213Z DEBUG isakmp::ikev1: Response message ID: 84b0068c 2024-03-06T06:32:53.097231Z DEBUG snx_rs::tunnel::connector: No status in reply, requested challenge for: UserPassword 2024-03-06T06:32:53.097275Z DEBUG snx_rs::tunnel::connector: Challenge msg: User USERNAME authenticated by Radius authentication password: <--- second password request from server 2024-03-06T06:32:53.098024Z DEBUG isakmp::transport: Sending ISAKMP message of size 92 to SOME.IP.ADDR.1:500 2024-03-06T06:32:53.098617Z DEBUG snx_rs::server: Handling disconnect command ```

With SSL tunnel it seems that auth process somehow enters an infinite loop without notifying user:

SSL log

``` 2024-03-06T06:39:49.557466Z DEBUG snx_rs::tunnel::connector: Authenticating to endpoint: vpn.server.host 2024-03-06T06:39:49.557709Z WARN snx_rs::ccc: Disabling all certificate checks!!! 2024-03-06T06:39:49.564949Z DEBUG hyper::client::connect::dns: resolving host="vpn.server.host" 2024-03-06T06:39:49.566016Z DEBUG hyper::client::connect::http: connecting to SOME.IP.ADDR.1:443 2024-03-06T06:39:49.573586Z DEBUG hyper::client::connect::http: connected to SOME.IP.ADDR.1:443 2024-03-06T06:39:49.606018Z DEBUG hyper::proto::h1::io: flushed 323 bytes 2024-03-06T06:39:49.619436Z DEBUG hyper::proto::h1::io: parsed 8 headers 2024-03-06T06:39:49.619460Z DEBUG hyper::proto::h1::conn: incoming body is content-length (404 bytes) 2024-03-06T06:39:49.619492Z DEBUG hyper::proto::h1::conn: incoming body completed 2024-03-06T06:39:49.620705Z DEBUG snx_rs::server: Pending multi-factor, awaiting for it 2024-03-06T06:39:57.675471Z DEBUG snx_rs::server: Handling challenge code command 2024-03-06T06:39:57.675503Z DEBUG snx_rs::tunnel::connector: Authenticating with challenge code to endpoint: vpn.server.host 2024-03-06T06:39:57.675598Z WARN snx_rs::ccc: Disabling all certificate checks!!! 2024-03-06T06:39:57.683806Z DEBUG hyper::client::connect::dns: resolving host="vpn.server.host" 2024-03-06T06:39:57.693372Z DEBUG hyper::client::connect::http: connecting to SOME.IP.ADDR.1:443 2024-03-06T06:39:57.701278Z DEBUG hyper::client::connect::http: connected to SOME.IP.ADDR.1:443 2024-03-06T06:39:57.732601Z DEBUG hyper::proto::h1::io: flushed 395 bytes 2024-03-06T06:40:00.331861Z DEBUG hyper::proto::h1::io: parsed 8 headers 2024-03-06T06:40:00.331918Z DEBUG hyper::proto::h1::conn: incoming body is content-length (475 bytes) 2024-03-06T06:40:00.331969Z DEBUG hyper::proto::h1::conn: incoming body completed 2024-03-06T06:40:00.333318Z DEBUG snx_rs::server: Pending multi-factor, awaiting for it 2024-03-06T06:40:00.333891Z DEBUG snx_rs::server: Handling challenge code command 2024-03-06T06:40:00.333912Z DEBUG snx_rs::tunnel::connector: Authenticating with challenge code to endpoint: vpn.server.host 2024-03-06T06:40:00.333979Z WARN snx_rs::ccc: Disabling all certificate checks!!! 2024-03-06T06:40:00.339161Z DEBUG hyper::client::connect::dns: resolving host="vpn.server.host" 2024-03-06T06:40:00.339581Z DEBUG hyper::client::connect::http: connecting to SOME.IP.ADDR.1:443 2024-03-06T06:40:00.347822Z DEBUG hyper::client::connect::http: connected to SOME.IP.ADDR.1:443 2024-03-06T06:40:00.384533Z DEBUG hyper::proto::h1::io: flushed 395 bytes 2024-03-06T06:40:00.398837Z DEBUG hyper::proto::h1::io: parsed 8 headers 2024-03-06T06:40:00.398859Z DEBUG hyper::proto::h1::conn: incoming body is content-length (621 bytes) 2024-03-06T06:40:00.398906Z DEBUG hyper::proto::h1::conn: incoming body completed 2024-03-06T06:40:00.400723Z DEBUG snx_rs::server: Pending multi-factor, awaiting for it 2024-03-06T06:40:00.401406Z DEBUG snx_rs::server: Handling challenge code command 2024-03-06T06:40:00.401423Z DEBUG snx_rs::tunnel::connector: Authenticating with challenge code to endpoint: vpn.server.host 2024-03-06T06:40:00.401501Z WARN snx_rs::ccc: Disabling all certificate checks!!! 2024-03-06T06:40:00.408627Z DEBUG hyper::client::connect::dns: resolving host="vpn.server.host" 2024-03-06T06:40:00.409168Z DEBUG hyper::client::connect::http: connecting to SOME.IP.ADDR.1:443 2024-03-06T06:40:00.417396Z DEBUG hyper::client::connect::http: connected to SOME.IP.ADDR.1:443 2024-03-06T06:40:00.451930Z DEBUG hyper::proto::h1::io: flushed 395 bytes 2024-03-06T06:40:00.466927Z DEBUG hyper::proto::h1::io: parsed 8 headers 2024-03-06T06:40:00.466967Z DEBUG hyper::proto::h1::conn: incoming body is content-length (621 bytes) 2024-03-06T06:40:00.467022Z DEBUG hyper::proto::h1::conn: incoming body completed 2024-03-06T06:40:00.469062Z DEBUG snx_rs::server: Pending multi-factor, awaiting for it 2024-03-06T06:40:00.469800Z DEBUG snx_rs::server: Handling challenge code command 2024-03-06T06:40:00.469816Z DEBUG snx_rs::tunnel::connector: Authenticating with challenge code to endpoint: vpn.server.host 2024-03-06T06:40:00.469916Z WARN snx_rs::ccc: Disabling all certificate checks!!! 2024-03-06T06:40:00.477118Z DEBUG hyper::client::connect::dns: resolving host="vpn.server.host" 2024-03-06T06:40:00.477670Z DEBUG hyper::client::connect::http: connecting to SOME.IP.ADDR.1:443 2024-03-06T06:40:00.485327Z DEBUG hyper::client::connect::http: connected to SOME.IP.ADDR.1:443 2024-03-06T06:40:00.516463Z DEBUG hyper::proto::h1::io: flushed 395 bytes 2024-03-06T06:40:00.531351Z DEBUG hyper::proto::h1::io: parsed 8 headers 2024-03-06T06:40:00.531369Z DEBUG hyper::proto::h1::conn: incoming body is content-length (448 bytes) 2024-03-06T06:40:00.531398Z DEBUG hyper::proto::h1::conn: incoming body completed 2024-03-06T06:40:00.532995Z WARN snx_rs::tunnel::connector: [101 CPSC_INTERNAL_ACCESS_DENIED] Access denied - wrong user name or password 2024-03-06T06:40:00.533375Z DEBUG snx_rs::server: Handling disconnect command ```

Not to mention the fact that the functionality of the server prompts is completely disabled in code, but that's not so important right now. )))

ancwrd1 commented 4 months ago

Hi, would you be able to build and run it in trace debug mode from the issue-13 branch? I have added an additional logging for ipsec tunnel. What I am interested is the trace log with "msg_obj: xxx" for ipsec and the "reply from server: xxx" for ssl, in particular when MFA challenges are sent. I think the issue is easy to fix, probably just an s-expression which isn't understood.

nut-3 commented 4 months ago

I'll gather logs later today. If it's trivial enough, I'll make a PR.

ancwrd1 commented 4 months ago

Sorry about MFA prompts, I deleted them accidentally when resolving conflicts with other branch. Re-added now in the ServiceController. You can use main branch for testing, that separate one is not needed.

nut-3 commented 3 months ago

So yesterday I tried to figure out what's wrong with Indeed auth, but with no luck. Logs:

IPSec

``` 2024-03-06T16:46:24.034993Z TRACE snx_rs::server: Command received 2024-03-06T16:46:24.035095Z TRACE snx_rs::server: Handling get status command 2024-03-06T16:46:24.035108Z TRACE snx_rs::server: Response: ConnectionStatus(ConnectionStatus { connected_since: None, mfa: None }) 2024-03-06T16:46:24.148331Z TRACE snx_rs::server: Command received 2024-03-06T16:46:24.148474Z TRACE snx_rs::server: Handling connect command 2024-03-06T16:46:24.154732Z DEBUG snx_rs::tunnel::ipsec::natt: Sending NAT-T probe to SOME.IP.ADDR.1 2024-03-06T16:46:24.162714Z DEBUG snx_rs::tunnel::ipsec::natt: Received NAT-T reply from SOME.IP.ADDR.1: srcport: 4500, dstport: 4500, hash: 4ae71336e44bf9bf79d2752e234818a5 2024-03-06T16:46:24.162853Z TRACE snx_rs::util: Exec: "ip" ["-4", "route", "show", "default"] 2024-03-06T16:46:24.168693Z TRACE snx_rs::util: Exec: "ip" ["-4", "-o", "addr", "show", "dev", "wlp1s0"] 2024-03-06T16:46:24.170296Z DEBUG isakmp::ikev1: Begin SA proposal 2024-03-06T16:46:24.170448Z DEBUG isakmp::transport: Sending ISAKMP message of size 152 to SOME.IP.ADDR.1:500 2024-03-06T16:46:24.184837Z DEBUG isakmp::transport: Parsing ISAKMP message of size 268 2024-03-06T16:46:24.184907Z TRACE isakmp::payload: Parsing payload: type=SecurityAssociation, size=56, next=VendorId 2024-03-06T16:46:24.184921Z TRACE isakmp::payload: Parsing payload: type=Proposal, size=44, next=None 2024-03-06T16:46:24.184932Z TRACE isakmp::payload: Parsing payload: type=Transform, size=36, next=None 2024-03-06T16:46:24.184959Z TRACE isakmp::payload: Parsing payload: type=VendorId, size=40, next=VendorId 2024-03-06T16:46:24.184969Z TRACE isakmp::payload: Parsing payload: type=VendorId, size=16, next=VendorId 2024-03-06T16:46:24.184976Z TRACE isakmp::payload: Parsing payload: type=VendorId, size=16, next=VendorId 2024-03-06T16:46:24.184985Z TRACE isakmp::payload: Parsing payload: type=VendorId, size=16, next=Notification 2024-03-06T16:46:24.184996Z TRACE isakmp::payload: Parsing payload: type=Notification, size=28, next=Notification 2024-03-06T16:46:24.185007Z TRACE isakmp::payload: Parsing payload: type=Notification, size=40, next=None 2024-03-06T16:46:24.185029Z DEBUG isakmp::ikev1: End SA proposal 2024-03-06T16:46:24.185040Z DEBUG isakmp::ikev1: Begin key exchange 2024-03-06T16:46:24.185074Z DEBUG isakmp::transport: Sending ISAKMP message of size 268 to SOME.IP.ADDR.1:500 2024-03-06T16:46:24.201550Z DEBUG isakmp::transport: Parsing ISAKMP message of size 256 2024-03-06T16:46:24.201593Z TRACE isakmp::payload: Parsing payload: type=KeyExchange, size=128, next=Nonce 2024-03-06T16:46:24.201616Z TRACE isakmp::payload: Parsing payload: type=Nonce, size=20, next=Natd 2024-03-06T16:46:24.201624Z TRACE isakmp::payload: Parsing payload: type=Natd, size=32, next=Natd 2024-03-06T16:46:24.201634Z TRACE isakmp::payload: Parsing payload: type=Natd, size=32, next=None 2024-03-06T16:46:24.201656Z TRACE isakmp::ikev1: Responder's public key length: 128 2024-03-06T16:46:24.201672Z TRACE isakmp::ikev1: Responder's nonce length: 20 2024-03-06T16:46:24.202263Z TRACE isakmp::ikev1: COOKIE_i: 20bae60fd2b7fade 2024-03-06T16:46:24.202289Z TRACE isakmp::ikev1: SKEYID_e: 9ea59aaa1bf6b3bcc7ef8ac79c5ffc53217768129953b7275a1b2dd68cb29bea 2024-03-06T16:46:24.202298Z DEBUG isakmp::ikev1: End key exchange 2024-03-06T16:46:24.202312Z DEBUG isakmp::ikev1: Begin identity protection 2024-03-06T16:46:24.202384Z DEBUG isakmp::transport: Sending ISAKMP message of size 252 to SOME.IP.ADDR.1:500 2024-03-06T16:46:24.225267Z DEBUG isakmp::transport: Parsing ISAKMP message of size 2044 2024-03-06T16:46:24.225341Z TRACE isakmp::payload: Parsing payload: type=Identification, size=8, next=Certificate 2024-03-06T16:46:24.225362Z TRACE isakmp::payload: Parsing payload: type=Certificate, size=960, next=Certificate 2024-03-06T16:46:24.225373Z TRACE isakmp::payload: Parsing payload: type=Certificate, size=772, next=Signature 2024-03-06T16:46:24.225384Z TRACE isakmp::payload: Parsing payload: type=Signature, size=256, next=None 2024-03-06T16:46:24.325298Z TRACE isakmp::transport: Discarding already received message 2024-03-06T16:46:24.425087Z TRACE isakmp::transport: Discarding already received message 2024-03-06T16:46:24.725805Z DEBUG isakmp::transport: Parsing ISAKMP message of size 92 2024-03-06T16:46:24.725939Z TRACE isakmp::payload: Parsing payload: type=Hash, size=32, next=Attributes 2024-03-06T16:46:24.725961Z TRACE isakmp::payload: Parsing payload: type=Attributes, size=12, next=None 2024-03-06T16:46:24.725985Z DEBUG isakmp::ikev1: Response message ID: 59f1b47f 2024-03-06T16:46:24.726003Z DEBUG isakmp::ikev1: End identity protection 2024-03-06T16:46:24.726018Z DEBUG snx_rs::tunnel::connector: No status in reply, requested challenge for: UserName 2024-03-06T16:46:24.726104Z DEBUG isakmp::ikev1: Sending auth attribute: UserName, timeout: Some(120) seconds 2024-03-06T16:46:24.726242Z DEBUG isakmp::transport: Sending ISAKMP message of size 92 to SOME.IP.ADDR.1:500 2024-03-06T16:46:24.745573Z DEBUG isakmp::transport: Parsing ISAKMP message of size 412 2024-03-06T16:46:24.745643Z TRACE isakmp::payload: Parsing payload: type=Hash, size=32, next=Attributes 2024-03-06T16:46:24.745673Z TRACE isakmp::payload: Parsing payload: type=Attributes, size=338, next=None 2024-03-06T16:46:24.745699Z DEBUG isakmp::ikev1: Message ID: 59f1b47f 2024-03-06T16:46:24.745719Z DEBUG isakmp::ikev1: Response message ID: 59f1b47f 2024-03-06T16:46:24.745735Z DEBUG snx_rs::tunnel::connector: No status in reply, requested challenge for: UserPassword 2024-03-06T16:46:24.745792Z DEBUG snx_rs::tunnel::connector: Challenge msg: password: 2024-03-06T16:46:24.745809Z TRACE snx_rs::tunnel::connector: msg_obj: (msg_obj :format (1.0) :id (VPN_CUMULATE_PROMPT) :def_msg ("password: ") :arguments ( :0 ( :type (msg_obj) :val (msg_obj :format (1.0) :id (CPSC_RADIUS_ENTER_PASSWORD) :def_msg ("password: ") :arguments () ) :def_text ("password: ") ) ) :authentication_state (challenge) ) 2024-03-06T16:46:24.746140Z DEBUG snx_rs::tunnel::connector: Challenge ID: CPSC_RADIUS_ENTER_PASSWORD 2024-03-06T16:46:24.746151Z DEBUG snx_rs::tunnel::connector: Challenge prompt: password: 2024-03-06T16:46:24.746175Z DEBUG snx_rs::server: Pending multi-factor, awaiting for it 2024-03-06T16:46:24.746190Z TRACE snx_rs::server: Response: Ok 2024-03-06T16:46:24.746512Z TRACE snx_rs::server: Command received 2024-03-06T16:46:24.746527Z TRACE snx_rs::server: Handling get status command 2024-03-06T16:46:24.746532Z TRACE snx_rs::server: Response: ConnectionStatus(ConnectionStatus { connected_since: None, mfa: Some(MfaChallenge { mfa_type: UserInput, prompt: "password: " }) }) 2024-03-06T16:47:06.944317Z TRACE snx_rs::server: Command received 2024-03-06T16:47:06.944509Z DEBUG snx_rs::server: Handling challenge code command 2024-03-06T16:47:06.944546Z DEBUG isakmp::ikev1: Sending auth attribute: UserPassword, timeout: Some(120) seconds 2024-03-06T16:47:06.944823Z DEBUG isakmp::transport: Sending ISAKMP message of size 92 to SOME.IP.ADDR.1:500 2024-03-06T16:47:06.944886Z TRACE isakmp::transport: Discarding already received message 2024-03-06T16:47:06.944915Z TRACE isakmp::transport: Discarding already received message 2024-03-06T16:47:06.944929Z TRACE isakmp::transport: Discarding already received message 2024-03-06T16:47:06.944941Z TRACE isakmp::transport: Discarding already received message 2024-03-06T16:47:06.944959Z TRACE isakmp::transport: Discarding already received message 2024-03-06T16:47:06.944977Z TRACE isakmp::transport: Discarding already received message 2024-03-06T16:47:06.944990Z TRACE isakmp::transport: Discarding already received message 2024-03-06T16:47:06.945003Z TRACE isakmp::transport: Discarding already received message 2024-03-06T16:47:06.945014Z TRACE isakmp::transport: Discarding already received message 2024-03-06T16:47:06.945027Z TRACE isakmp::transport: Discarding already received message 2024-03-06T16:47:06.945039Z TRACE isakmp::transport: Discarding already received message 2024-03-06T16:47:08.053729Z DEBUG isakmp::transport: Parsing ISAKMP message of size 860 2024-03-06T16:47:08.053801Z TRACE isakmp::payload: Parsing payload: type=Hash, size=32, next=Attributes 2024-03-06T16:47:08.053823Z TRACE isakmp::payload: Parsing payload: type=Attributes, size=778, next=None 2024-03-06T16:47:08.053846Z DEBUG isakmp::ikev1: Message ID: 59f1b47f 2024-03-06T16:47:08.053858Z DEBUG isakmp::ikev1: Response message ID: 59f1b47f 2024-03-06T16:47:08.053872Z DEBUG snx_rs::tunnel::connector: No status in reply, requested challenge for: UserPassword 2024-03-06T16:47:08.053918Z DEBUG snx_rs::tunnel::connector: Challenge msg: User USER_NAME authenticated by Radius authentication password: 2024-03-06T16:47:08.053926Z TRACE snx_rs::tunnel::connector: msg_obj: (msg_obj :format (1.0) :id (VPN_CUMULATE_PROMPT) :def_msg ("User USER_NAME authenticated by Radius authentication password: ") :arguments ( :0 ( :type (msg_obj) :val (msg_obj :format (1.0) :id (CPSC_RADIUS_USER_AUTHENTICATED) :def_msg ("User USER_NAME authenticated by Radius authentication ") :arguments ( :0 ( :type (string) :val (USER_NAME) ) ) ) :def_text ("User USER_NAME authenticated by Radius authentication ") ) :1 ( :type (msg_obj) :val (msg_obj :format (1.0) :id (CPSC_INTERNAL_ENTER_PASSWORD) :def_msg ("password: ") :arguments () ) :def_text ("password: ") ) ) :authentication_state (new_factor) ) 2024-03-06T16:47:08.054420Z WARN snx_rs::server: Not a challenge state! 2024-03-06T16:47:08.054910Z DEBUG isakmp::transport: Sending ISAKMP message of size 92 to SOME.IP.ADDR.1:500 2024-03-06T16:47:08.055155Z TRACE snx_rs::server: Response: Error("Not a challenge state!") 2024-03-06T16:47:08.055537Z TRACE snx_rs::server: Command received 2024-03-06T16:47:08.055557Z DEBUG snx_rs::server: Handling disconnect command 2024-03-06T16:47:08.055564Z TRACE snx_rs::server: Response: Ok ```

Details

``` 2024-03-06T16:59:54.244846Z TRACE snx_rs::server: Command received 2024-03-06T16:59:54.244888Z TRACE snx_rs::server: Handling get status command 2024-03-06T16:59:54.244911Z TRACE snx_rs::server: Response: ConnectionStatus(ConnectionStatus { connected_since: None, mfa: None }) 2024-03-06T16:59:54.314892Z TRACE snx_rs::server: Command received 2024-03-06T16:59:54.314981Z TRACE snx_rs::server: Handling connect command 2024-03-06T16:59:54.315004Z DEBUG snx_rs::tunnel::connector: Authenticating to endpoint: vpn.server.host 2024-03-06T16:59:54.315258Z WARN snx_rs::ccc: Disabling all certificate checks!!! 2024-03-06T16:59:54.321016Z TRACE snx_rs::ccc: Request to server: (CCCclientRequest :RequestData ( :client_logging_data ( :os_name ("Android")) :client_type (SYMBIAN) :password () :selectedLoginOption (vpn_Indeed) :username (0f0f1178091078)) :RequestHeader ( :id (2) :type (UserPass))) 2024-03-06T16:59:54.321317Z TRACE hyper::client::pool: checkout waiting for idle connection: ("https", vpn.server.host) 2024-03-06T16:59:54.321435Z TRACE hyper::client::connect::http: Http::connect; scheme=Some("https"), host=Some("vpn.server.host"), port=None 2024-03-06T16:59:54.321555Z DEBUG hyper::client::connect::dns: resolving host="vpn.server.host" 2024-03-06T16:59:54.321981Z DEBUG hyper::client::connect::http: connecting to SOME.IP.ADDR.1:443 2024-03-06T16:59:54.331385Z DEBUG hyper::client::connect::http: connected to SOME.IP.ADDR.1:443 2024-03-06T16:59:54.363562Z TRACE hyper::client::conn: client handshake Http1 2024-03-06T16:59:54.363675Z TRACE hyper::client::client: handshake complete, spawning background dispatcher task 2024-03-06T16:59:54.364083Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Busy } 2024-03-06T16:59:54.364113Z TRACE hyper::client::pool: checkout dropped for ("https", vpn.server.host) 2024-03-06T16:59:54.364323Z TRACE encode_headers: hyper::proto::h1::role: Client::encode method=POST, body=Some(Known(238)) 2024-03-06T16:59:54.364411Z TRACE hyper::proto::h1::encode: sized write, len = 238 2024-03-06T16:59:54.364422Z TRACE hyper::proto::h1::io: buffer.flatten self.len=85 buf.len=238 2024-03-06T16:59:54.364473Z DEBUG hyper::proto::h1::io: flushed 323 bytes 2024-03-06T16:59:54.364482Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy } 2024-03-06T16:59:54.376975Z TRACE hyper::proto::h1::conn: Conn::read_head 2024-03-06T16:59:54.377067Z TRACE hyper::proto::h1::io: received 686 bytes 2024-03-06T16:59:54.377155Z TRACE parse_headers: hyper::proto::h1::role: Response.parse bytes=686 2024-03-06T16:59:54.377212Z TRACE parse_headers: hyper::proto::h1::role: Response.parse Complete(282) 2024-03-06T16:59:54.377304Z DEBUG hyper::proto::h1::io: parsed 8 headers 2024-03-06T16:59:54.377315Z DEBUG hyper::proto::h1::conn: incoming body is content-length (404 bytes) 2024-03-06T16:59:54.377323Z TRACE hyper::proto::h1::conn: remote disabling keep-alive 2024-03-06T16:59:54.377356Z TRACE hyper::proto::h1::decode: decode; state=Length(404) 2024-03-06T16:59:54.377368Z DEBUG hyper::proto::h1::conn: incoming body completed 2024-03-06T16:59:54.377376Z TRACE hyper::proto::h1::conn: try_keep_alive({role=client}): could keep-alive, but status = Disabled 2024-03-06T16:59:54.377384Z TRACE hyper::proto::h1::conn: State::close() 2024-03-06T16:59:54.377406Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Closed, writing: Closed, keep_alive: Disabled } 2024-03-06T16:59:54.377469Z TRACE hyper::proto::h1::conn: shut down IO complete 2024-03-06T16:59:54.377657Z TRACE snx_rs::ccc: Reply from server: (CCCserverResponse :ResponseHeader ( :id (2) :type (UserPass) :session_id () :return_code (600) ) :ResponseData ( :authn_status (continue) :prompt (771c203726313a372e5d) :prompt_id (101b780316160963060617111e0a0d63026fff041b190a171f6e) :session_id (1204df0cbd72a9ff8d8423fe23c2e393cf9cc06fdb180ff983601ce4d5f2551b) :auth_state (new_challenge) :error_message () :error_id () ) ) 2024-03-06T16:59:54.378701Z DEBUG snx_rs::server: Pending multi-factor, awaiting for it 2024-03-06T16:59:54.378720Z TRACE snx_rs::server: Response: Ok 2024-03-06T16:59:54.379088Z TRACE snx_rs::server: Command received 2024-03-06T16:59:54.379105Z TRACE snx_rs::server: Handling get status command 2024-03-06T16:59:54.379113Z TRACE snx_rs::server: Response: ConnectionStatus(ConnectionStatus { connected_since: None, mfa: Some(MfaChallenge { mfa_type: UserInput, prompt: "password: " }) }) 2024-03-06T17:00:05.530360Z TRACE snx_rs::server: Command received 2024-03-06T17:00:05.530456Z DEBUG snx_rs::server: Handling challenge code command 2024-03-06T17:00:05.530479Z DEBUG snx_rs::tunnel::connector: Authenticating with challenge code to endpoint: vpn.server.host 2024-03-06T17:00:05.530616Z WARN snx_rs::ccc: Disabling all certificate checks!!! 2024-03-06T17:00:05.536172Z TRACE snx_rs::ccc: Request to server: (CCCclientRequest :RequestData ( :auth_session_id (1204df0cbd72a9ff8d8423fe23c2e393cf9cc06fdb180ff983601ce4d5f2551b) :client_type (SYMBIAN) :user_input (7e7f7d737d1a)) :RequestHeader ( :id (3) :session_id (1204df0cbd72a9ff8d8423fe23c2e393cf9cc06fdb180ff983601ce4d5f2551b) :type (MultiChallange))) 2024-03-06T17:00:05.536382Z TRACE hyper::client::pool: checkout waiting for idle connection: ("https", vpn.server.host) 2024-03-06T17:00:05.536447Z TRACE hyper::client::connect::http: Http::connect; scheme=Some("https"), host=Some("vpn.server.host"), port=None 2024-03-06T17:00:05.536580Z DEBUG hyper::client::connect::dns: resolving host="vpn.server.host" 2024-03-06T17:00:05.537099Z DEBUG hyper::client::connect::http: connecting to SOME.IP.ADDR.1:443 2024-03-06T17:00:05.546073Z DEBUG hyper::client::connect::http: connected to SOME.IP.ADDR.1:443 2024-03-06T17:00:05.574865Z TRACE hyper::client::conn: client handshake Http1 2024-03-06T17:00:05.574909Z TRACE hyper::client::client: handshake complete, spawning background dispatcher task 2024-03-06T17:00:05.575061Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Busy } 2024-03-06T17:00:05.575087Z TRACE hyper::client::pool: checkout dropped for ("https", vpn.server.host) 2024-03-06T17:00:05.575289Z TRACE encode_headers: hyper::proto::h1::role: Client::encode method=POST, body=Some(Known(310)) 2024-03-06T17:00:05.575378Z TRACE hyper::proto::h1::encode: sized write, len = 310 2024-03-06T17:00:05.575390Z TRACE hyper::proto::h1::io: buffer.flatten self.len=85 buf.len=310 2024-03-06T17:00:05.575450Z DEBUG hyper::proto::h1::io: flushed 395 bytes 2024-03-06T17:00:05.575460Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy } 2024-03-06T17:00:06.736298Z TRACE hyper::proto::h1::conn: Conn::read_head 2024-03-06T17:00:06.736452Z TRACE hyper::proto::h1::io: received 757 bytes 2024-03-06T17:00:06.736618Z TRACE parse_headers: hyper::proto::h1::role: Response.parse bytes=757 2024-03-06T17:00:06.736664Z TRACE parse_headers: hyper::proto::h1::role: Response.parse Complete(282) 2024-03-06T17:00:06.736760Z DEBUG hyper::proto::h1::io: parsed 8 headers 2024-03-06T17:00:06.736769Z DEBUG hyper::proto::h1::conn: incoming body is content-length (475 bytes) 2024-03-06T17:00:06.736778Z TRACE hyper::proto::h1::conn: remote disabling keep-alive 2024-03-06T17:00:06.736809Z TRACE hyper::proto::h1::decode: decode; state=Length(475) 2024-03-06T17:00:06.736821Z DEBUG hyper::proto::h1::conn: incoming body completed 2024-03-06T17:00:06.736829Z TRACE hyper::proto::h1::conn: try_keep_alive({role=client}): could keep-alive, but status = Disabled 2024-03-06T17:00:06.736836Z TRACE hyper::proto::h1::conn: State::close() 2024-03-06T17:00:06.736860Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Closed, writing: Closed, keep_alive: Disabled } 2024-03-06T17:00:06.736942Z TRACE hyper::proto::h1::conn: shut down IO complete 2024-03-06T17:00:06.737142Z TRACE snx_rs::ccc: Reply from server: (CCCserverResponse :ResponseHeader ( :id (3) :type (MultiChallange) :session_id (1204df0cbd72a9ff8d8423fe23c2e393cf9cc06fdb180ff983601ce4d5f2551b) :return_code (600) ) :ResponseData ( :authn_status (continue) :prompt (771c203726313a372e5d) :prompt_id (6b1a1b1e6407041517611cff1cff0f03137e0563100bff190a171f6e) :session_id (4dc0234a5279fb11b754c1f768cbe412b0e0bf9cc1b23fa4ecb7d924e17d7f6b) :auth_state (new_factor) :error_message () :error_id () ) ) 2024-03-06T17:00:06.738208Z DEBUG snx_rs::server: Pending multi-factor, awaiting for it 2024-03-06T17:00:06.738226Z TRACE snx_rs::server: Response: Ok 2024-03-06T17:00:06.738544Z TRACE snx_rs::server: Command received 2024-03-06T17:00:06.738558Z TRACE snx_rs::server: Handling get status command 2024-03-06T17:00:06.738565Z TRACE snx_rs::server: Response: ConnectionStatus(ConnectionStatus { connected_since: None, mfa: Some(MfaChallenge { mfa_type: UserInput, prompt: "password: " }) }) 2024-03-06T17:00:06.738784Z TRACE snx_rs::server: Command received 2024-03-06T17:00:06.738824Z DEBUG snx_rs::server: Handling challenge code command 2024-03-06T17:00:06.738833Z DEBUG snx_rs::tunnel::connector: Authenticating with challenge code to endpoint: vpn.server.host 2024-03-06T17:00:06.738892Z WARN snx_rs::ccc: Disabling all certificate checks!!! 2024-03-06T17:00:06.744555Z TRACE snx_rs::ccc: Request to server: (CCCclientRequest :RequestData ( :auth_session_id (4dc0234a5279fb11b754c1f768cbe412b0e0bf9cc1b23fa4ecb7d924e17d7f6b) :client_type (SYMBIAN) :user_input (7e7f7d737d1a)) :RequestHeader ( :id (4) :session_id (4dc0234a5279fb11b754c1f768cbe412b0e0bf9cc1b23fa4ecb7d924e17d7f6b) :type (MultiChallange))) 2024-03-06T17:00:06.744802Z TRACE hyper::client::pool: checkout waiting for idle connection: ("https", vpn.server.host) 2024-03-06T17:00:06.744873Z TRACE hyper::client::connect::http: Http::connect; scheme=Some("https"), host=Some("vpn.server.host"), port=None 2024-03-06T17:00:06.744947Z DEBUG hyper::client::connect::dns: resolving host="vpn.server.host" 2024-03-06T17:00:06.745468Z DEBUG hyper::client::connect::http: connecting to SOME.IP.ADDR.1:443 2024-03-06T17:00:06.753062Z DEBUG hyper::client::connect::http: connected to SOME.IP.ADDR.1:443 2024-03-06T17:00:06.781301Z TRACE hyper::client::conn: client handshake Http1 2024-03-06T17:00:06.781336Z TRACE hyper::client::client: handshake complete, spawning background dispatcher task 2024-03-06T17:00:06.781510Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Busy } 2024-03-06T17:00:06.781549Z TRACE hyper::client::pool: checkout dropped for ("https", vpn.server.host) 2024-03-06T17:00:06.781753Z TRACE encode_headers: hyper::proto::h1::role: Client::encode method=POST, body=Some(Known(310)) 2024-03-06T17:00:06.781821Z TRACE hyper::proto::h1::encode: sized write, len = 310 2024-03-06T17:00:06.781832Z TRACE hyper::proto::h1::io: buffer.flatten self.len=85 buf.len=310 2024-03-06T17:00:06.781872Z DEBUG hyper::proto::h1::io: flushed 395 bytes 2024-03-06T17:00:06.781884Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy } 2024-03-06T17:00:06.797248Z TRACE hyper::proto::h1::conn: Conn::read_head 2024-03-06T17:00:06.797291Z TRACE hyper::proto::h1::io: received 903 bytes 2024-03-06T17:00:06.797392Z TRACE parse_headers: hyper::proto::h1::role: Response.parse bytes=903 2024-03-06T17:00:06.797489Z TRACE parse_headers: hyper::proto::h1::role: Response.parse Complete(282) 2024-03-06T17:00:06.797597Z DEBUG hyper::proto::h1::io: parsed 8 headers 2024-03-06T17:00:06.797613Z DEBUG hyper::proto::h1::conn: incoming body is content-length (621 bytes) 2024-03-06T17:00:06.797624Z TRACE hyper::proto::h1::conn: remote disabling keep-alive 2024-03-06T17:00:06.797679Z TRACE hyper::proto::h1::decode: decode; state=Length(621) 2024-03-06T17:00:06.797696Z DEBUG hyper::proto::h1::conn: incoming body completed 2024-03-06T17:00:06.797708Z TRACE hyper::proto::h1::conn: try_keep_alive({role=client}): could keep-alive, but status = Disabled 2024-03-06T17:00:06.797718Z TRACE hyper::proto::h1::conn: State::close() 2024-03-06T17:00:06.797742Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Closed, writing: Closed, keep_alive: Disabled } 2024-03-06T17:00:06.797790Z TRACE hyper::proto::h1::conn: shut down IO complete 2024-03-06T17:00:06.798018Z TRACE snx_rs::ccc: Reply from server: (CCCserverResponse :ResponseHeader ( :id (4) :type (MultiChallange) :session_id (4dc0234a5279fb11b754c1f768cbe412b0e0bf9cc1b23fa4ecb7d924e17d7f6b) :return_code (600) ) :ResponseData ( :authn_status (continue) :prompt (771c203726313a372e5d) :prompt_id (6b1a1b1e6407041517611cff1cff0f03137e0563100bff190a171f6e) :session_id (998c71e1333ddf0aec1a193950b0a5b894ad84ea0ff37e66edd11e3b699056fe) :auth_state (failed_attempt) :error_message (01405e5044575a3535653a5c652d594a4168262c44216522265c2b237268702b3759394320653a352c272c6c) :error_id (0c11ff7911011a1b601c1711040f03137e0563100bff190a171f6e) ) ) 2024-03-06T17:00:06.799155Z DEBUG snx_rs::server: Pending multi-factor, awaiting for it 2024-03-06T17:00:06.799173Z TRACE snx_rs::server: Response: Ok 2024-03-06T17:00:06.799509Z TRACE snx_rs::server: Command received 2024-03-06T17:00:06.799523Z TRACE snx_rs::server: Handling get status command 2024-03-06T17:00:06.799529Z TRACE snx_rs::server: Response: ConnectionStatus(ConnectionStatus { connected_since: None, mfa: Some(MfaChallenge { mfa_type: UserInput, prompt: "password: " }) }) 2024-03-06T17:00:06.799817Z TRACE snx_rs::server: Command received 2024-03-06T17:00:06.799856Z DEBUG snx_rs::server: Handling challenge code command 2024-03-06T17:00:06.799865Z DEBUG snx_rs::tunnel::connector: Authenticating with challenge code to endpoint: vpn.server.host 2024-03-06T17:00:06.799934Z WARN snx_rs::ccc: Disabling all certificate checks!!! 2024-03-06T17:00:06.804804Z TRACE snx_rs::ccc: Request to server: (CCCclientRequest :RequestData ( :auth_session_id (998c71e1333ddf0aec1a193950b0a5b894ad84ea0ff37e66edd11e3b699056fe) :client_type (SYMBIAN) :user_input (7e7f7d737d1a)) :RequestHeader ( :id (5) :session_id (998c71e1333ddf0aec1a193950b0a5b894ad84ea0ff37e66edd11e3b699056fe) :type (MultiChallange))) 2024-03-06T17:00:06.804927Z TRACE hyper::client::pool: checkout waiting for idle connection: ("https", vpn.server.host) 2024-03-06T17:00:06.804964Z TRACE hyper::client::connect::http: Http::connect; scheme=Some("https"), host=Some("vpn.server.host"), port=None 2024-03-06T17:00:06.805027Z DEBUG hyper::client::connect::dns: resolving host="vpn.server.host" 2024-03-06T17:00:06.805487Z DEBUG hyper::client::connect::http: connecting to SOME.IP.ADDR.1:443 2024-03-06T17:00:06.813059Z DEBUG hyper::client::connect::http: connected to SOME.IP.ADDR.1:443 2024-03-06T17:00:06.844699Z TRACE hyper::client::conn: client handshake Http1 2024-03-06T17:00:06.844741Z TRACE hyper::client::client: handshake complete, spawning background dispatcher task 2024-03-06T17:00:06.844918Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Busy } 2024-03-06T17:00:06.844940Z TRACE hyper::client::pool: checkout dropped for ("https", vpn.server.host) 2024-03-06T17:00:06.845140Z TRACE encode_headers: hyper::proto::h1::role: Client::encode method=POST, body=Some(Known(310)) 2024-03-06T17:00:06.845222Z TRACE hyper::proto::h1::encode: sized write, len = 310 2024-03-06T17:00:06.845236Z TRACE hyper::proto::h1::io: buffer.flatten self.len=85 buf.len=310 2024-03-06T17:00:06.845292Z DEBUG hyper::proto::h1::io: flushed 395 bytes 2024-03-06T17:00:06.845308Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy } 2024-03-06T17:00:06.859372Z TRACE hyper::proto::h1::conn: Conn::read_head 2024-03-06T17:00:06.859410Z TRACE hyper::proto::h1::io: received 903 bytes 2024-03-06T17:00:06.859436Z TRACE parse_headers: hyper::proto::h1::role: Response.parse bytes=903 2024-03-06T17:00:06.859483Z TRACE parse_headers: hyper::proto::h1::role: Response.parse Complete(282) 2024-03-06T17:00:06.859556Z DEBUG hyper::proto::h1::io: parsed 8 headers 2024-03-06T17:00:06.859566Z DEBUG hyper::proto::h1::conn: incoming body is content-length (621 bytes) 2024-03-06T17:00:06.859574Z TRACE hyper::proto::h1::conn: remote disabling keep-alive 2024-03-06T17:00:06.859599Z TRACE hyper::proto::h1::decode: decode; state=Length(621) 2024-03-06T17:00:06.859610Z DEBUG hyper::proto::h1::conn: incoming body completed 2024-03-06T17:00:06.859616Z TRACE hyper::proto::h1::conn: try_keep_alive({role=client}): could keep-alive, but status = Disabled 2024-03-06T17:00:06.859623Z TRACE hyper::proto::h1::conn: State::close() 2024-03-06T17:00:06.859641Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Closed, writing: Closed, keep_alive: Disabled } 2024-03-06T17:00:06.859682Z TRACE hyper::proto::h1::conn: shut down IO complete 2024-03-06T17:00:06.859891Z TRACE snx_rs::ccc: Reply from server: (CCCserverResponse :ResponseHeader ( :id (5) :type (MultiChallange) :session_id (998c71e1333ddf0aec1a193950b0a5b894ad84ea0ff37e66edd11e3b699056fe) :return_code (600) ) :ResponseData ( :authn_status (continue) :prompt (771c203726313a372e5d) :prompt_id (6b1a1b1e6407041517611cff1cff0f03137e0563100bff190a171f6e) :session_id (c3fef5b5c6e3a11c0dbc07022aaeab5455200006e8c9b3d139bf471824b1ccee) :auth_state (failed_attempt) :error_message (01405e5044575a3535653a5c652d594a4168262c44216522265c2b237268702b3759394320653a352c272c6c) :error_id (0c11ff7911011a1b601c1711040f03137e0563100bff190a171f6e) ) ) 2024-03-06T17:00:06.861090Z DEBUG snx_rs::server: Pending multi-factor, awaiting for it 2024-03-06T17:00:06.861109Z TRACE snx_rs::server: Response: Ok 2024-03-06T17:00:06.861451Z TRACE snx_rs::server: Command received 2024-03-06T17:00:06.861470Z TRACE snx_rs::server: Handling get status command 2024-03-06T17:00:06.861477Z TRACE snx_rs::server: Response: ConnectionStatus(ConnectionStatus { connected_since: None, mfa: Some(MfaChallenge { mfa_type: UserInput, prompt: "password: " }) }) 2024-03-06T17:00:06.861732Z TRACE snx_rs::server: Command received 2024-03-06T17:00:06.861773Z DEBUG snx_rs::server: Handling challenge code command 2024-03-06T17:00:06.861782Z DEBUG snx_rs::tunnel::connector: Authenticating with challenge code to endpoint: vpn.server.host 2024-03-06T17:00:06.861841Z WARN snx_rs::ccc: Disabling all certificate checks!!! 2024-03-06T17:00:06.866944Z TRACE snx_rs::ccc: Request to server: (CCCclientRequest :RequestData ( :auth_session_id (c3fef5b5c6e3a11c0dbc07022aaeab5455200006e8c9b3d139bf471824b1ccee) :client_type (SYMBIAN) :user_input (7e7f7d737d1a)) :RequestHeader ( :id (6) :session_id (c3fef5b5c6e3a11c0dbc07022aaeab5455200006e8c9b3d139bf471824b1ccee) :type (MultiChallange))) 2024-03-06T17:00:06.867060Z TRACE hyper::client::pool: checkout waiting for idle connection: ("https", vpn.server.host) 2024-03-06T17:00:06.867095Z TRACE hyper::client::connect::http: Http::connect; scheme=Some("https"), host=Some("vpn.server.host"), port=None 2024-03-06T17:00:06.867147Z DEBUG hyper::client::connect::dns: resolving host="vpn.server.host" 2024-03-06T17:00:06.867615Z DEBUG hyper::client::connect::http: connecting to SOME.IP.ADDR.1:443 2024-03-06T17:00:06.873970Z DEBUG hyper::client::connect::http: connected to SOME.IP.ADDR.1:443 2024-03-06T17:00:06.904301Z TRACE hyper::client::conn: client handshake Http1 2024-03-06T17:00:06.904332Z TRACE hyper::client::client: handshake complete, spawning background dispatcher task 2024-03-06T17:00:06.904458Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Busy } 2024-03-06T17:00:06.904490Z TRACE hyper::client::pool: checkout dropped for ("https", vpn.server.host) 2024-03-06T17:00:06.904672Z TRACE encode_headers: hyper::proto::h1::role: Client::encode method=POST, body=Some(Known(310)) 2024-03-06T17:00:06.904733Z TRACE hyper::proto::h1::encode: sized write, len = 310 2024-03-06T17:00:06.904744Z TRACE hyper::proto::h1::io: buffer.flatten self.len=85 buf.len=310 2024-03-06T17:00:06.904791Z DEBUG hyper::proto::h1::io: flushed 395 bytes 2024-03-06T17:00:06.904812Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy } 2024-03-06T17:00:06.919176Z TRACE hyper::proto::h1::conn: Conn::read_head 2024-03-06T17:00:06.919223Z TRACE hyper::proto::h1::io: received 730 bytes 2024-03-06T17:00:06.919260Z TRACE parse_headers: hyper::proto::h1::role: Response.parse bytes=730 2024-03-06T17:00:06.919305Z TRACE parse_headers: hyper::proto::h1::role: Response.parse Complete(282) 2024-03-06T17:00:06.919381Z DEBUG hyper::proto::h1::io: parsed 8 headers 2024-03-06T17:00:06.919390Z DEBUG hyper::proto::h1::conn: incoming body is content-length (448 bytes) 2024-03-06T17:00:06.919396Z TRACE hyper::proto::h1::conn: remote disabling keep-alive 2024-03-06T17:00:06.919421Z TRACE hyper::proto::h1::decode: decode; state=Length(448) 2024-03-06T17:00:06.919430Z DEBUG hyper::proto::h1::conn: incoming body completed 2024-03-06T17:00:06.919437Z TRACE hyper::proto::h1::conn: try_keep_alive({role=client}): could keep-alive, but status = Disabled 2024-03-06T17:00:06.919444Z TRACE hyper::proto::h1::conn: State::close() 2024-03-06T17:00:06.919462Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Closed, writing: Closed, keep_alive: Disabled } 2024-03-06T17:00:06.919503Z TRACE hyper::proto::h1::conn: shut down IO complete 2024-03-06T17:00:06.919706Z TRACE snx_rs::ccc: Reply from server: (CCCserverResponse :ResponseHeader ( :id (6) :type (MultiChallange) :session_id (c3fef5b5c6e3a11c0dbc07022aaeab5455200006e8c9b3d139bf471824b1ccee) :return_code (600) ) :ResponseData ( :authn_status (done) :is_authenticated (false) :error_message (01405e5044575a3535653a5c652d594a4168262c44216522265c2b237268702b3759394320653a352c272c6c) :error_id (0c11ff7911011a1b601c1711040f03137e0563100bff190a171f6e) :error_code (101) ) ) 2024-03-06T17:00:06.920735Z WARN snx_rs::tunnel::connector: [101 CPSC_INTERNAL_ACCESS_DENIED] Access denied - wrong user name or password 2024-03-06T17:00:06.920752Z WARN snx_rs::server: [101 CPSC_INTERNAL_ACCESS_DENIED] Access denied - wrong user name or password 2024-03-06T17:00:06.920770Z TRACE snx_rs::server: Response: Error("[101 CPSC_INTERNAL_ACCESS_DENIED] Access denied - wrong user name or password ") 2024-03-06T17:00:06.921103Z TRACE snx_rs::server: Command received 2024-03-06T17:00:06.921129Z DEBUG snx_rs::server: Handling disconnect command 2024-03-06T17:00:06.921136Z TRACE snx_rs::server: Response: Ok ```

Then I discovered that mfa_promps are not populated from server_info request. This is due to migration to sexpr2 - serde can not process parsed sexpr2 json in SExpression::try_into(). Using unwrap_or_default() in ServiceController::fill_mfa_prompts() played a bad joke, as parsing error got transformed into an empty VecDeque. I think sexpr2 generates maps instead of arrays in login_options_list field:

Details

```json { "connectivity_info": { "client_enabled": true, "connect_with_certificate_url": "\"/clients/cert/\"", "connectivity_type": "IPSec", "cookie_name": "CPCVPN_SESSION_ID", "default_authentication_method": "mixed", "internal_ca_fingerprint": { "1": "687c6e71107e67747e106d657f1f716b657409ff077d650f7b630f031a1c7f740d0201607918ff10126f02750706100c05661b050a69" }, "ipsec_transport": "auto_detect", "natt_port": 4500, "server_ip": "217.12.96.114", "supported_data_tunnel_protocols": [ "IPSec", "SSL", "L2TP" ], "tcpt_port": 443 }, "end_point_security": { "ics": { "ics_base_url": "\"/clients/ICS/components\"", "ics_cab_url": "\"/clients/ICS/components/cl_ics.cab\"", "ics_cab_version": "\"996000036\n\"", "ics_images_url": "\"/clients/ICS/components/ICS_images.cab\"", "ics_images_ver": 403006000, "ics_upgrade_url": "\"/clients/ICS/components/icsweb.cab\"", "ics_version": 403006000, "run_ics": false } }, "login_options_data": { "login_options_list": { "0": { "display_name": "RSA", "factors": { "0": { "certificate_storage_type": "", "custom_display_labels": { "header": "\"Please provide User name, PIN Code and Tokencode from your RSA application\"", "password": "\"Pin Code\"", "username": "\"User name\"" }, "factor_type": "securid", "securid_card_type": "keyfob" } }, "id": "vpn_RSA", "secondary_realm_hash": "a87ff679a2f3e71d9181a67b7542122c", "show_realm": 1 }, "1": { "display_name": "Indeed", "factors": { "0": { "certificate_storage_type": "", "custom_display_labels": { "header": "\"Additional authentication required, please provide password to authenticate\"", "password": "\"OTP from your indeed app\"", "username": "\"User name\"" }, "factor_type": "password", "securid_card_type": "" }, "1": { "certificate_storage_type": "", "custom_display_labels": { "header": "\"Необходимо ввести пароль от учетной записи AD\"", "password": "\"Domain Password\"", "username": "\"Domain Password\"" }, "factor_type": "password", "securid_card_type": "" } }, "id": "vpn_Indeed", "secondary_realm_hash": "32bb90e8976aab5298d5da10fe66f21d", "show_realm": 1 }, "2": { "display_name": "Standard", "factors": { "0": { "certificate_storage_type": "", "custom_display_labels": "", "factor_type": "securid", "securid_card_type": "any" } }, "id": "vpn", "secondary_realm_hash": "a87ff679a2f3e71d9181a67b7542122c", "show_realm": 1 } }, "login_options_md5": "57e96a578f4b21b58a5353c9edfcfbec" }, "protocol_version": { "features": 1, "protocol_version": 100 }, "upgrade_configuration": { "available_client_version": 0, "client_upgrade_url": "", "upgrade_mode": "ask_user" } } ```

ancwrd1 commented 3 months ago

Thanks, try recent main branch for a fix. What about SSL tunnel? There was an issue also there, no?

ancwrd1 commented 3 months ago

The reason for transitioning to sexpr2 is that those Checkpoint Lisp-like expressions are not consistent and don't always map correctly into Rust or JSON data structures, so the values could be either integers, strings or even empty. So there is now a generic SExpression which can be accessed via value path (e.g. expr.get("msg_obj:arguments:0:val:msg").

nut-3 commented 3 months ago

Now filling mfa_prompts works, thanks. Indeed auth does not work though, getting same error.

SSL tunnel log with latest changes

``` 2024-03-07T08:26:35.966462Z TRACE snx_rs::server: Command received 2024-03-07T08:26:35.966515Z TRACE snx_rs::server: Handling get status command 2024-03-07T08:26:35.966525Z TRACE snx_rs::server: Response: ConnectionStatus(ConnectionStatus { connected_since: None, mfa: None }) 2024-03-07T08:26:36.037627Z TRACE snx_rs::server: Command received 2024-03-07T08:26:36.037706Z TRACE snx_rs::server: Handling connect command 2024-03-07T08:26:36.037733Z DEBUG snx_rs::tunnel::connector: Authenticating to endpoint: vpn.server.host 2024-03-07T08:26:36.037978Z WARN snx_rs::ccc: Disabling all certificate checks!!! 2024-03-07T08:26:36.045744Z TRACE snx_rs::ccc: Request to server: (CCCclientRequest :RequestData ( :client_logging_data ( :os_name ("Android")) :client_type (SYMBIAN) :password () :selectedLoginOption (vpn_Indeed) :username (xxx)) :RequestHeader ( :id (2) :type (UserPass))) 2024-03-07T08:26:36.045962Z TRACE hyper::client::pool: checkout waiting for idle connection: ("https", vpn.server.host) 2024-03-07T08:26:36.046023Z TRACE hyper::client::connect::http: Http::connect; scheme=Some("https"), host=Some("vpn.server.host"), port=None 2024-03-07T08:26:36.046181Z DEBUG hyper::client::connect::dns: resolving host="vpn.server.host" 2024-03-07T08:26:36.047237Z DEBUG hyper::client::connect::http: connecting to SOME.IP.ADDR.1:443 2024-03-07T08:26:36.054868Z DEBUG hyper::client::connect::http: connected to SOME.IP.ADDR.1:443 2024-03-07T08:26:36.086707Z TRACE hyper::client::conn: client handshake Http1 2024-03-07T08:26:36.086762Z TRACE hyper::client::client: handshake complete, spawning background dispatcher task 2024-03-07T08:26:36.086890Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Busy } 2024-03-07T08:26:36.086920Z TRACE hyper::client::pool: checkout dropped for ("https", vpn.server.host) 2024-03-07T08:26:36.087062Z TRACE encode_headers: hyper::proto::h1::role: Client::encode method=POST, body=Some(Known(238)) 2024-03-07T08:26:36.087122Z TRACE hyper::proto::h1::encode: sized write, len = 238 2024-03-07T08:26:36.087135Z TRACE hyper::proto::h1::io: buffer.flatten self.len=85 buf.len=238 2024-03-07T08:26:36.087177Z DEBUG hyper::proto::h1::io: flushed 323 bytes 2024-03-07T08:26:36.087185Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy } 2024-03-07T08:26:36.106268Z TRACE hyper::proto::h1::conn: Conn::read_head 2024-03-07T08:26:36.106371Z TRACE hyper::proto::h1::io: received 686 bytes 2024-03-07T08:26:36.106462Z TRACE parse_headers: hyper::proto::h1::role: Response.parse bytes=686 2024-03-07T08:26:36.106558Z TRACE parse_headers: hyper::proto::h1::role: Response.parse Complete(282) 2024-03-07T08:26:36.106725Z DEBUG hyper::proto::h1::io: parsed 8 headers 2024-03-07T08:26:36.106744Z DEBUG hyper::proto::h1::conn: incoming body is content-length (404 bytes) 2024-03-07T08:26:36.106762Z TRACE hyper::proto::h1::conn: remote disabling keep-alive 2024-03-07T08:26:36.106825Z TRACE hyper::proto::h1::decode: decode; state=Length(404) 2024-03-07T08:26:36.106849Z DEBUG hyper::proto::h1::conn: incoming body completed 2024-03-07T08:26:36.106863Z TRACE hyper::proto::h1::conn: try_keep_alive({role=client}): could keep-alive, but status = Disabled 2024-03-07T08:26:36.106877Z TRACE hyper::proto::h1::conn: State::close() 2024-03-07T08:26:36.106935Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Closed, writing: Closed, keep_alive: Disabled } 2024-03-07T08:26:36.107044Z TRACE hyper::proto::h1::conn: shut down IO complete 2024-03-07T08:26:36.107292Z TRACE snx_rs::ccc: Reply from server: (CCCserverResponse :ResponseHeader ( :id (2) :type (UserPass) :session_id () :return_code (600) ) :ResponseData ( :authn_status (continue) :prompt (771c203726313a372e5d) :prompt_id (101b780316160963060617111e0a0d63026fff041b190a171f6e) :session_id (178e61cd5226468ab278ca8ba787fe8d0f7b58ed74d119857165d04e593527b1) :auth_state (new_challenge) :error_message () :error_id () ) ) 2024-03-07T08:26:36.108676Z DEBUG snx_rs::server: Pending multi-factor, awaiting for it 2024-03-07T08:26:36.108700Z TRACE snx_rs::server: Response: Ok 2024-03-07T08:26:36.111302Z TRACE snx_rs::server: Command received 2024-03-07T08:26:36.111339Z TRACE snx_rs::server: Handling get status command 2024-03-07T08:26:36.111352Z TRACE snx_rs::server: Response: ConnectionStatus(ConnectionStatus { connected_since: None, mfa: Some(MfaChallenge { mfa_type: UserInput, prompt: "password: " }) }) 2024-03-07T08:26:52.563949Z TRACE snx_rs::server: Command received 2024-03-07T08:26:52.564034Z DEBUG snx_rs::server: Handling challenge code command 2024-03-07T08:26:52.564051Z DEBUG snx_rs::tunnel::connector: Authenticating with challenge code to endpoint: vpn.server.host 2024-03-07T08:26:52.564182Z WARN snx_rs::ccc: Disabling all certificate checks!!! 2024-03-07T08:26:52.569552Z TRACE snx_rs::ccc: Request to server: (CCCclientRequest :RequestData ( :auth_session_id (178e61cd5226468ab278ca8ba787fe8d0f7b58ed74d119857165d04e593527b1) :client_type (SYMBIAN) :user_input (yyy)) :RequestHeader ( :id (3) :session_id (178e61cd5226468ab278ca8ba787fe8d0f7b58ed74d119857165d04e593527b1) :type (MultiChallange))) 2024-03-07T08:26:52.569705Z TRACE hyper::client::pool: checkout waiting for idle connection: ("https", vpn.server.host) 2024-03-07T08:26:52.569764Z TRACE hyper::client::connect::http: Http::connect; scheme=Some("https"), host=Some("vpn.server.host"), port=None 2024-03-07T08:26:52.569928Z DEBUG hyper::client::connect::dns: resolving host="vpn.server.host" 2024-03-07T08:26:52.570386Z DEBUG hyper::client::connect::http: connecting to SOME.IP.ADDR.1:443 2024-03-07T08:26:52.578692Z DEBUG hyper::client::connect::http: connected to SOME.IP.ADDR.1:443 2024-03-07T08:26:52.611397Z TRACE hyper::client::conn: client handshake Http1 2024-03-07T08:26:52.611450Z TRACE hyper::client::client: handshake complete, spawning background dispatcher task 2024-03-07T08:26:52.611570Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Busy } 2024-03-07T08:26:52.611592Z TRACE hyper::client::pool: checkout dropped for ("https", vpn.server.host) 2024-03-07T08:26:52.611723Z TRACE encode_headers: hyper::proto::h1::role: Client::encode method=POST, body=Some(Known(310)) 2024-03-07T08:26:52.611789Z TRACE hyper::proto::h1::encode: sized write, len = 310 2024-03-07T08:26:52.611800Z TRACE hyper::proto::h1::io: buffer.flatten self.len=85 buf.len=310 2024-03-07T08:26:52.611843Z DEBUG hyper::proto::h1::io: flushed 395 bytes 2024-03-07T08:26:52.611856Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy } 2024-03-07T08:26:53.625277Z TRACE hyper::proto::h1::conn: Conn::read_head 2024-03-07T08:26:53.625362Z TRACE hyper::proto::h1::io: received 757 bytes 2024-03-07T08:26:53.625429Z TRACE parse_headers: hyper::proto::h1::role: Response.parse bytes=757 2024-03-07T08:26:53.625476Z TRACE parse_headers: hyper::proto::h1::role: Response.parse Complete(282) 2024-03-07T08:26:53.625558Z DEBUG hyper::proto::h1::io: parsed 8 headers 2024-03-07T08:26:53.625567Z DEBUG hyper::proto::h1::conn: incoming body is content-length (475 bytes) 2024-03-07T08:26:53.625577Z TRACE hyper::proto::h1::conn: remote disabling keep-alive 2024-03-07T08:26:53.625608Z TRACE hyper::proto::h1::decode: decode; state=Length(475) 2024-03-07T08:26:53.625620Z DEBUG hyper::proto::h1::conn: incoming body completed 2024-03-07T08:26:53.625627Z TRACE hyper::proto::h1::conn: try_keep_alive({role=client}): could keep-alive, but status = Disabled 2024-03-07T08:26:53.625634Z TRACE hyper::proto::h1::conn: State::close() 2024-03-07T08:26:53.625657Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Closed, writing: Closed, keep_alive: Disabled } 2024-03-07T08:26:53.625710Z TRACE hyper::proto::h1::conn: shut down IO complete 2024-03-07T08:26:53.625869Z TRACE snx_rs::ccc: Reply from server: (CCCserverResponse :ResponseHeader ( :id (3) :type (MultiChallange) :session_id (178e61cd5226468ab278ca8ba787fe8d0f7b58ed74d119857165d04e593527b1) :return_code (600) ) :ResponseData ( :authn_status (continue) :prompt (771c203726313a372e5d) :prompt_id (6b1a1b1e6407041517611cff1cff0f03137e0563100bff190a171f6e) :session_id (5d4a104e713255b2cd2ccdb2875c7ed54139bbf9d434ea9f64defeb0d3f53ffe) :auth_state (new_factor) :error_message () :error_id () ) ) 2024-03-07T08:26:53.627006Z DEBUG snx_rs::server: Pending multi-factor, awaiting for it 2024-03-07T08:26:53.627026Z TRACE snx_rs::server: Response: Ok 2024-03-07T08:26:53.627310Z TRACE snx_rs::server: Command received 2024-03-07T08:26:53.627323Z TRACE snx_rs::server: Handling get status command 2024-03-07T08:26:53.627328Z TRACE snx_rs::server: Response: ConnectionStatus(ConnectionStatus { connected_since: None, mfa: Some(MfaChallenge { mfa_type: UserInput, prompt: "password: " }) }) 2024-03-07T08:26:53.627519Z TRACE snx_rs::server: Command received 2024-03-07T08:26:53.627556Z DEBUG snx_rs::server: Handling challenge code command 2024-03-07T08:26:53.627564Z DEBUG snx_rs::tunnel::connector: Authenticating with challenge code to endpoint: vpn.server.host 2024-03-07T08:26:53.627623Z WARN snx_rs::ccc: Disabling all certificate checks!!! 2024-03-07T08:26:53.632581Z TRACE snx_rs::ccc: Request to server: (CCCclientRequest :RequestData ( :auth_session_id (5d4a104e713255b2cd2ccdb2875c7ed54139bbf9d434ea9f64defeb0d3f53ffe) :client_type (SYMBIAN) :user_input (yyy)) :RequestHeader ( :id (4) :session_id (5d4a104e713255b2cd2ccdb2875c7ed54139bbf9d434ea9f64defeb0d3f53ffe) :type (MultiChallange))) 2024-03-07T08:26:53.632714Z TRACE hyper::client::pool: checkout waiting for idle connection: ("https", vpn.server.host) 2024-03-07T08:26:53.632754Z TRACE hyper::client::connect::http: Http::connect; scheme=Some("https"), host=Some("vpn.server.host"), port=None 2024-03-07T08:26:53.632799Z DEBUG hyper::client::connect::dns: resolving host="vpn.server.host" 2024-03-07T08:26:53.633209Z DEBUG hyper::client::connect::http: connecting to SOME.IP.ADDR.1:443 2024-03-07T08:26:53.640981Z DEBUG hyper::client::connect::http: connected to SOME.IP.ADDR.1:443 2024-03-07T08:26:53.676229Z TRACE hyper::client::conn: client handshake Http1 2024-03-07T08:26:53.676271Z TRACE hyper::client::client: handshake complete, spawning background dispatcher task 2024-03-07T08:26:53.676414Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Busy } 2024-03-07T08:26:53.676436Z TRACE hyper::client::pool: checkout dropped for ("https", vpn.server.host) 2024-03-07T08:26:53.676569Z TRACE encode_headers: hyper::proto::h1::role: Client::encode method=POST, body=Some(Known(310)) 2024-03-07T08:26:53.676646Z TRACE hyper::proto::h1::encode: sized write, len = 310 2024-03-07T08:26:53.676658Z TRACE hyper::proto::h1::io: buffer.flatten self.len=85 buf.len=310 2024-03-07T08:26:53.676700Z DEBUG hyper::proto::h1::io: flushed 395 bytes 2024-03-07T08:26:53.676712Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy } 2024-03-07T08:26:53.696508Z TRACE hyper::proto::h1::conn: Conn::read_head 2024-03-07T08:26:53.696594Z TRACE hyper::proto::h1::io: received 903 bytes 2024-03-07T08:26:53.696629Z TRACE parse_headers: hyper::proto::h1::role: Response.parse bytes=903 2024-03-07T08:26:53.696671Z TRACE parse_headers: hyper::proto::h1::role: Response.parse Complete(282) 2024-03-07T08:26:53.696740Z DEBUG hyper::proto::h1::io: parsed 8 headers 2024-03-07T08:26:53.696749Z DEBUG hyper::proto::h1::conn: incoming body is content-length (621 bytes) 2024-03-07T08:26:53.696757Z TRACE hyper::proto::h1::conn: remote disabling keep-alive 2024-03-07T08:26:53.696785Z TRACE hyper::proto::h1::decode: decode; state=Length(621) 2024-03-07T08:26:53.696795Z DEBUG hyper::proto::h1::conn: incoming body completed 2024-03-07T08:26:53.696803Z TRACE hyper::proto::h1::conn: try_keep_alive({role=client}): could keep-alive, but status = Disabled 2024-03-07T08:26:53.696810Z TRACE hyper::proto::h1::conn: State::close() 2024-03-07T08:26:53.696830Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Closed, writing: Closed, keep_alive: Disabled } 2024-03-07T08:26:53.696870Z TRACE hyper::proto::h1::conn: shut down IO complete 2024-03-07T08:26:53.697034Z TRACE snx_rs::ccc: Reply from server: (CCCserverResponse :ResponseHeader ( :id (4) :type (MultiChallange) :session_id (5d4a104e713255b2cd2ccdb2875c7ed54139bbf9d434ea9f64defeb0d3f53ffe) :return_code (600) ) :ResponseData ( :authn_status (continue) :prompt (771c203726313a372e5d) :prompt_id (6b1a1b1e6407041517611cff1cff0f03137e0563100bff190a171f6e) :session_id (1bc16c9b272893f99cfae40858815d2dd1f3efe3cc17a59d5c646e3fcbb2b8ed) :auth_state (failed_attempt) :error_message (01405e5044575a3535653a5c652d594a4168262c44216522265c2b237268702b3759394320653a352c272c6c) :error_id (0c11ff7911011a1b601c1711040f03137e0563100bff190a171f6e) ) ) 2024-03-07T08:26:53.698258Z DEBUG snx_rs::server: Pending multi-factor, awaiting for it 2024-03-07T08:26:53.698276Z TRACE snx_rs::server: Response: Ok 2024-03-07T08:26:53.698565Z TRACE snx_rs::server: Command received 2024-03-07T08:26:53.698579Z TRACE snx_rs::server: Handling get status command 2024-03-07T08:26:53.698585Z TRACE snx_rs::server: Response: ConnectionStatus(ConnectionStatus { connected_since: None, mfa: Some(MfaChallenge { mfa_type: UserInput, prompt: "password: " }) }) 2024-03-07T08:26:53.698796Z TRACE snx_rs::server: Command received 2024-03-07T08:26:53.698835Z DEBUG snx_rs::server: Handling challenge code command 2024-03-07T08:26:53.698844Z DEBUG snx_rs::tunnel::connector: Authenticating with challenge code to endpoint: vpn.server.host 2024-03-07T08:26:53.698915Z WARN snx_rs::ccc: Disabling all certificate checks!!! 2024-03-07T08:26:53.703942Z TRACE snx_rs::ccc: Request to server: (CCCclientRequest :RequestData ( :auth_session_id (1bc16c9b272893f99cfae40858815d2dd1f3efe3cc17a59d5c646e3fcbb2b8ed) :client_type (SYMBIAN) :user_input (yyy)) :RequestHeader ( :id (5) :session_id (1bc16c9b272893f99cfae40858815d2dd1f3efe3cc17a59d5c646e3fcbb2b8ed) :type (MultiChallange))) 2024-03-07T08:26:53.704064Z TRACE hyper::client::pool: checkout waiting for idle connection: ("https", vpn.server.host) 2024-03-07T08:26:53.704102Z TRACE hyper::client::connect::http: Http::connect; scheme=Some("https"), host=Some("vpn.server.host"), port=None 2024-03-07T08:26:53.704141Z DEBUG hyper::client::connect::dns: resolving host="vpn.server.host" 2024-03-07T08:26:53.704526Z DEBUG hyper::client::connect::http: connecting to SOME.IP.ADDR.1:443 2024-03-07T08:26:53.714531Z DEBUG hyper::client::connect::http: connected to SOME.IP.ADDR.1:443 2024-03-07T08:26:53.747596Z TRACE hyper::client::conn: client handshake Http1 2024-03-07T08:26:53.747633Z TRACE hyper::client::client: handshake complete, spawning background dispatcher task 2024-03-07T08:26:53.747757Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Busy } 2024-03-07T08:26:53.747781Z TRACE hyper::client::pool: checkout dropped for ("https", vpn.server.host) 2024-03-07T08:26:53.747918Z TRACE encode_headers: hyper::proto::h1::role: Client::encode method=POST, body=Some(Known(310)) 2024-03-07T08:26:53.747996Z TRACE hyper::proto::h1::encode: sized write, len = 310 2024-03-07T08:26:53.748008Z TRACE hyper::proto::h1::io: buffer.flatten self.len=85 buf.len=310 2024-03-07T08:26:53.748050Z DEBUG hyper::proto::h1::io: flushed 395 bytes 2024-03-07T08:26:53.748059Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy } 2024-03-07T08:26:53.764099Z TRACE hyper::proto::h1::conn: Conn::read_head 2024-03-07T08:26:53.764143Z TRACE hyper::proto::h1::io: received 903 bytes 2024-03-07T08:26:53.764173Z TRACE parse_headers: hyper::proto::h1::role: Response.parse bytes=903 2024-03-07T08:26:53.764208Z TRACE parse_headers: hyper::proto::h1::role: Response.parse Complete(282) 2024-03-07T08:26:53.764274Z DEBUG hyper::proto::h1::io: parsed 8 headers 2024-03-07T08:26:53.764284Z DEBUG hyper::proto::h1::conn: incoming body is content-length (621 bytes) 2024-03-07T08:26:53.764292Z TRACE hyper::proto::h1::conn: remote disabling keep-alive 2024-03-07T08:26:53.764321Z TRACE hyper::proto::h1::decode: decode; state=Length(621) 2024-03-07T08:26:53.764338Z DEBUG hyper::proto::h1::conn: incoming body completed 2024-03-07T08:26:53.764349Z TRACE hyper::proto::h1::conn: try_keep_alive({role=client}): could keep-alive, but status = Disabled 2024-03-07T08:26:53.764361Z TRACE hyper::proto::h1::conn: State::close() 2024-03-07T08:26:53.764386Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Closed, writing: Closed, keep_alive: Disabled } 2024-03-07T08:26:53.764433Z TRACE hyper::proto::h1::conn: shut down IO complete 2024-03-07T08:26:53.764591Z TRACE snx_rs::ccc: Reply from server: (CCCserverResponse :ResponseHeader ( :id (5) :type (MultiChallange) :session_id (1bc16c9b272893f99cfae40858815d2dd1f3efe3cc17a59d5c646e3fcbb2b8ed) :return_code (600) ) :ResponseData ( :authn_status (continue) :prompt (771c203726313a372e5d) :prompt_id (6b1a1b1e6407041517611cff1cff0f03137e0563100bff190a171f6e) :session_id (df9c91596f1743b19f257a1cbbc2fc2294e0181fa208a35ebb6146ad460f2c9c) :auth_state (failed_attempt) :error_message (01405e5044575a3535653a5c652d594a4168262c44216522265c2b237268702b3759394320653a352c272c6c) :error_id (0c11ff7911011a1b601c1711040f03137e0563100bff190a171f6e) ) ) 2024-03-07T08:26:53.765728Z DEBUG snx_rs::server: Pending multi-factor, awaiting for it 2024-03-07T08:26:53.765746Z TRACE snx_rs::server: Response: Ok 2024-03-07T08:26:53.766041Z TRACE snx_rs::server: Command received 2024-03-07T08:26:53.766055Z TRACE snx_rs::server: Handling get status command 2024-03-07T08:26:53.766062Z TRACE snx_rs::server: Response: ConnectionStatus(ConnectionStatus { connected_since: None, mfa: Some(MfaChallenge { mfa_type: UserInput, prompt: "password: " }) }) 2024-03-07T08:26:53.766277Z TRACE snx_rs::server: Command received 2024-03-07T08:26:53.766313Z DEBUG snx_rs::server: Handling challenge code command 2024-03-07T08:26:53.766322Z DEBUG snx_rs::tunnel::connector: Authenticating with challenge code to endpoint: vpn.server.host 2024-03-07T08:26:53.766380Z WARN snx_rs::ccc: Disabling all certificate checks!!! 2024-03-07T08:26:53.771318Z TRACE snx_rs::ccc: Request to server: (CCCclientRequest :RequestData ( :auth_session_id (df9c91596f1743b19f257a1cbbc2fc2294e0181fa208a35ebb6146ad460f2c9c) :client_type (SYMBIAN) :user_input (yyy)) :RequestHeader ( :id (6) :session_id (df9c91596f1743b19f257a1cbbc2fc2294e0181fa208a35ebb6146ad460f2c9c) :type (MultiChallange))) 2024-03-07T08:26:53.771468Z TRACE hyper::client::pool: checkout waiting for idle connection: ("https", vpn.server.host) 2024-03-07T08:26:53.771511Z TRACE hyper::client::connect::http: Http::connect; scheme=Some("https"), host=Some("vpn.server.host"), port=None 2024-03-07T08:26:53.771557Z DEBUG hyper::client::connect::dns: resolving host="vpn.server.host" 2024-03-07T08:26:53.771983Z DEBUG hyper::client::connect::http: connecting to SOME.IP.ADDR.1:443 2024-03-07T08:26:53.780513Z DEBUG hyper::client::connect::http: connected to SOME.IP.ADDR.1:443 2024-03-07T08:26:53.812507Z TRACE hyper::client::conn: client handshake Http1 2024-03-07T08:26:53.812542Z TRACE hyper::client::client: handshake complete, spawning background dispatcher task 2024-03-07T08:26:53.812651Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Busy } 2024-03-07T08:26:53.812683Z TRACE hyper::client::pool: checkout dropped for ("https", vpn.server.host) 2024-03-07T08:26:53.812839Z TRACE encode_headers: hyper::proto::h1::role: Client::encode method=POST, body=Some(Known(310)) 2024-03-07T08:26:53.812918Z TRACE hyper::proto::h1::encode: sized write, len = 310 2024-03-07T08:26:53.812933Z TRACE hyper::proto::h1::io: buffer.flatten self.len=85 buf.len=310 2024-03-07T08:26:53.812978Z DEBUG hyper::proto::h1::io: flushed 395 bytes 2024-03-07T08:26:53.812988Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy } 2024-03-07T08:26:53.827596Z TRACE hyper::proto::h1::conn: Conn::read_head 2024-03-07T08:26:53.827667Z TRACE hyper::proto::h1::io: received 730 bytes 2024-03-07T08:26:53.827714Z TRACE parse_headers: hyper::proto::h1::role: Response.parse bytes=730 2024-03-07T08:26:53.827760Z TRACE parse_headers: hyper::proto::h1::role: Response.parse Complete(282) 2024-03-07T08:26:53.827846Z DEBUG hyper::proto::h1::io: parsed 8 headers 2024-03-07T08:26:53.827856Z DEBUG hyper::proto::h1::conn: incoming body is content-length (448 bytes) 2024-03-07T08:26:53.827864Z TRACE hyper::proto::h1::conn: remote disabling keep-alive 2024-03-07T08:26:53.827907Z TRACE hyper::proto::h1::decode: decode; state=Length(448) 2024-03-07T08:26:53.827917Z DEBUG hyper::proto::h1::conn: incoming body completed 2024-03-07T08:26:53.827925Z TRACE hyper::proto::h1::conn: try_keep_alive({role=client}): could keep-alive, but status = Disabled 2024-03-07T08:26:53.827932Z TRACE hyper::proto::h1::conn: State::close() 2024-03-07T08:26:53.827958Z TRACE hyper::proto::h1::conn: flushed({role=client}): State { reading: Closed, writing: Closed, keep_alive: Disabled } 2024-03-07T08:26:53.828007Z TRACE hyper::proto::h1::conn: shut down IO complete 2024-03-07T08:26:53.828162Z TRACE snx_rs::ccc: Reply from server: (CCCserverResponse :ResponseHeader ( :id (6) :type (MultiChallange) :session_id (df9c91596f1743b19f257a1cbbc2fc2294e0181fa208a35ebb6146ad460f2c9c) :return_code (600) ) :ResponseData ( :authn_status (done) :is_authenticated (false) :error_message (01405e5044575a3535653a5c652d594a4168262c44216522265c2b237268702b3759394320653a352c272c6c) :error_id (0c11ff7911011a1b601c1711040f03137e0563100bff190a171f6e) :error_code (101) ) ) 2024-03-07T08:26:53.829304Z WARN snx_rs::tunnel::connector: [101 CPSC_INTERNAL_ACCESS_DENIED] Access denied - wrong user name or password 2024-03-07T08:26:53.829325Z WARN snx_rs::server: [101 CPSC_INTERNAL_ACCESS_DENIED] Access denied - wrong user name or password 2024-03-07T08:26:53.829343Z TRACE snx_rs::server: Response: Error("[101 CPSC_INTERNAL_ACCESS_DENIED] Access denied - wrong user name or password ") 2024-03-07T08:26:53.829652Z TRACE snx_rs::server: Command received 2024-03-07T08:26:53.829666Z DEBUG snx_rs::server: Handling disconnect command 2024-03-07T08:26:53.829673Z TRACE snx_rs::server: Response: Ok ```

ancwrd1 commented 3 months ago

Should be fixed now. The same challenge code was sent for subsequent requests.

nut-3 commented 3 months ago

Thanks. now both ssl and ipsec work with Indeed auth.

nut-3 commented 3 months ago

@ancwrd1, could you assemble an RC with latest changes, pls?

ancwrd1 commented 3 months ago

Yes will do a final 1.0 a bit later today, need to fix few things first.