search

ancwrd1 / snx-rs

Open Source Linux Client For Check Point VPN Tunnels
GNU Affero General Public License v3.0
112 stars 8 forks source link

Connection issues when using a certificate #26

Open vlzware opened 4 months ago

vlzware commented 4 months ago

I am connecting to a CheckPoint server for which I have no user/password, but a certificate. The server is on customer's premises and I have no control over it. The OS is Debian 12, a clean install in a VM.

The IP and the certificate seem to be fine, because the Windows client works with them. I use the following to connect with snx-rs:

sudo ./snx-rs -s <the-server-ip> --ignore-server-cert=true --login-type=vpn --cert-path <path-to-mycert.p12> --cert-password="<my_password>" --log-level=debug --tunnel-type=ssl

It fails with error 603, like this:

2024-06-26T14:34:31.124170Z DEBUG snx_rs: >>> Starting snx-rs client version 2.2.4
2024-06-26T14:34:31.124181Z DEBUG snx_rs: Running in standalone mode
2024-06-26T14:34:31.124204Z  WARN snxcore::ccc: Disabling all certificate checks!!!
2024-06-26T14:34:31.134127Z DEBUG hyper_util::client::legacy::connect::http: connecting to <the-server-ip>:443
2024-06-26T14:34:31.168729Z DEBUG hyper_util::client::legacy::connect::http: connected to <the-server-ip>:443
2024-06-26T14:34:31.267349Z DEBUG snxcore::tunnel::ssl::connector: Authenticating to endpoint: <the-server-ip>
2024-06-26T14:34:31.267446Z  WARN snxcore::ccc: Disabling all certificate checks!!!
2024-06-26T14:34:31.271690Z DEBUG hyper_util::client::legacy::connect::http: connecting to <the-server-ip>:443
2024-06-26T14:34:31.301413Z DEBUG hyper_util::client::legacy::connect::http: connected to <the-server-ip>:443
Error: Request failed, error code: 603

I assume snx-rs doesn't even get to the point where it authenticates, because the output is exactly the same if I omit all certificate-relevant options.

The server responds to "info" like this: sudo ./snx-rs -s <the-server-ip> --ignore-server-cert=true -m info

Supported tunnel protocols:
    IPSec
    SSL
    L2TP
Available login types:
    vpn (vpn)

What might be the reason I am getting rejected with 603? I can connect from the same computer with the Windows client, so the problem seems to be related to the client.

The same command used to work earlier, now it seems something on the server side was changed. What are my options in order to find more information about what exactly is happening?

ancwrd1 commented 4 months ago

There is a new parameter "cert-type" which you need to specify, please see the readme file, certificate authentication section.

vlzware commented 4 months ago

Thanks for your quick response. I added --cert-type pkcs12 and now I got Error: Request failed, error code: 599. Other than the new error code, nothing in the output changed.

ancwrd1 commented 4 months ago

So just to my understanding, was it working before with earlier version? If yes, could you please give me the version number?

ancwrd1 commented 4 months ago

Also please run the following command from the command line and attach the log here (you can redact any sensitive information from it):

curl -k -X POST -d '(CCCclientRequest :RequestHeader ( :id (0) :type (ClientHello)) :RequestData ( :client_info ( :client_type (TRAC) :client_version (1) :client_support_saml (true))))' https://YOUR_VPN_ADDRESS/clients
vlzware commented 4 months ago

The last version which I had was 2.0.2 while the path option was called --client-cert. For what is worth, I can't connect with it now as well - getting the same 599 error code.

The output from the curl request:

(CCCserverResponse
    :ResponseHeader (
        :id (0)
        :type (ClientHello)
        :session_id ()
        :return_code (600)
    )
    :ResponseData (
        :protocol_version (
            :protocol_version (100)
            :features (0x1)
        )
        :upgrade_configuration (
            :available_client_version (835000022)
            :client_upgrade_url ("/CSHELL/")
            :upgrade_mode (ask_user)
        )
        :connectivity_info (
            :default_authentication_method (client_decide)
            :client_enabled (true)
            :supported_data_tunnel_protocols (
                : (IPSec)
                : (SSL)
                : (L2TP)
            )
            :connectivity_type (IPSec)
            :server_ip (<redacted>)
            :ipsec_transport (auto_detect)
            :tcpt_port (443)
            :natt_port (4500)
            :connect_with_certificate_url ("/clients/cert/")
            :cookie_name (CPCVPN_SESSION_ID)
            :internal_ca_fingerprint (
                :1 (<redacted>)
            )
        )
        :end_point_security (
            :ics (
                :run_ics (false)
                :ics_base_url ("/clients/ICS/components")
                :ics_version (403006000)
                :ics_upgrade_url ("/clients/ICS/components/icsweb.cab")
                :ics_images_url ("/clients/ICS/components/ICS_images.cab")
                :ics_images_ver (403006000)
                :ics_cab_url ("/clients/ICS/components/cl_ics.cab")
                :ics_cab_version ("996000036
")
            )
        )
        :login_options_data (
            :login_options_list (
                :0 (
                    :id (vpn)
                    :secondary_realm_hash (<redacted>)
                    :display_name (vpn)
                    :show_realm (1)
                    :factors (
                        :0 (
                            :factor_type (user_defined)
                            :securid_card_type ()
                            :certificate_storage_type ()
                            :custom_display_labels ()
                        )
                    )
                )
            )
            :login_options_md5 (<redacted>)
        )
    )
)
ancwrd1 commented 4 months ago

My guess is some of the parameters to authentication call aren't accepted anymore and must be changed. You could perhaps use mitmproxy to intercept the requests from the official application and check what kind of data is sent. I cannot test it because my server doesn't accept certificate authentications. It's not too difficult, you can run mitmproxy on Linux host and let Windows official app to connect to it (instead of your VPN server):

Alternatively you could run mitmproxy on Windows as well.

ancwrd1 commented 4 months ago

And what about IPSec, did you try it?

vlzware commented 4 months ago

Thanks again for your help. This seems like a nice idea - to see what the Windows client does differently. In regards to IPSec - no, it never worked with this server. I'll try the mitm approach and report as soon as I have some data

vlzware commented 4 months ago

mitmproxy crashes when --ssl-insecure is enabled and I need this, because the server uses a self-signed certificate.

I am closing the issue, because as it is I can't provide you with the information you need to fix the problem.

ancwrd1 commented 4 months ago

If you can build the project with Rust compiler (cargo build --release --workspace --exclude snx-rs-gui) try to modify ccc.rs file, lines 66-78 as follows:

Instead of:

            data: RequestData::Auth(AuthRequest {
                client_type: self.params.tunnel_type.as_client_type().to_owned(),
                username,
                password,
                client_logging_data: Some(ClientLoggingData {
                    // Checkpoint gateway checks this and if it's missing or not "Android" the IPSec traffic is blocked
                    os_name: Some("Android".into()),
                    device_id: Some(Uuid::new_v5(&Uuid::NAMESPACE_OID, machine_uuid.as_bytes()).to_string()),
                    ..Default::default()
                }),
                selected_login_option: Some(self.params.login_type.clone()),
                endpoint_os: None,
            }),

Write this:

            data: RequestData::Auth(AuthRequest {
                client_type: "TRAC".to_owned(),
                username,
                password,
                client_logging_data: None,
                selected_login_option: Some(self.params.login_type.clone()),
                endpoint_os: None,
            }),

And see if it helps in any way.

vlzware commented 4 months ago

I applied your suggestion and got this:

2024-06-28T13:59:38.729353Z DEBUG snx_rs: >>> Starting snx-rs client version 2.2.4
2024-06-28T13:59:38.729364Z DEBUG snx_rs: Running in standalone mode
2024-06-28T13:59:38.729401Z  WARN snxcore::ccc: Disabling all certificate checks!!!
2024-06-28T13:59:38.758677Z DEBUG hyper_util::client::legacy::connect::http: connecting to <my_server_ip>:443
2024-06-28T13:59:38.788711Z DEBUG hyper_util::client::legacy::connect::http: connected to <my_server_ip>:443
2024-06-28T13:59:38.888846Z DEBUG snxcore::tunnel::ssl::connector: Authenticating to endpoint: <my_server_ip>
2024-06-28T13:59:38.888964Z  WARN snxcore::ccc: Disabling all certificate checks!!!
2024-06-28T13:59:38.905788Z DEBUG hyper_util::client::legacy::connect::http: connecting to <my_server_ip>:443
2024-06-28T13:59:38.932479Z DEBUG hyper_util::client::legacy::connect::http: connected to <my_server_ip>:443
2024-06-28T13:59:39.124278Z DEBUG snxcore::tunnel::ssl::connector: Authentication OK, session id: ebbbb64bf718060b8f31b5cf70a6d16e
2024-06-28T13:59:39.154084Z  WARN snxcore::tunnel::ssl: Disabling all certificate checks!!!
2024-06-28T13:59:39.235981Z DEBUG snxcore::tunnel::ssl: Tunnel connected
2024-06-28T13:59:39.238026Z DEBUG snxcore::tunnel::ssl: Running SSL tunnel for session ebbbb64bf718060b8f31b5cf70a6d16e
2024-06-28T13:59:39.240211Z DEBUG snxcore::platform::linux::net: NetworkManager state changed to ConnectedGlobal
Error: missing field `(hello_reply`
ancwrd1 commented 4 months ago

Run it please with trace log level, it will show requests and responses. I think we are close to nail it.

vlzware commented 4 months ago

Here is the output when run with log level "trace":

2024-06-28T20:02:55.364422Z DEBUG snx_rs: >>> Starting snx-rs client version 2.2.4
2024-06-28T20:02:55.364483Z DEBUG snx_rs: Running in standalone mode
2024-06-28T20:02:55.364521Z  WARN snxcore::ccc: Disabling all certificate checks!!!
2024-06-28T20:02:55.394621Z TRACE snxcore::ccc: Request to server: (CCCclientRequest
    :RequestData (
        :client_info (
            :client_support_saml (true)
            :client_type (SYMBIAN)
            :client_version (1)))
    :RequestHeader (
        :id (2)
        :type (ClientHello)))
2024-06-28T20:02:55.394761Z TRACE hyper_util::client::legacy::pool: checkout waiting for idle connection: ("https", <my_server_ip>)
2024-06-28T20:02:55.394782Z TRACE hyper_util::client::legacy::connect::http: Http::connect; scheme=Some("https"), host=Some("<my_server_ip>"), port=None
2024-06-28T20:02:55.394852Z DEBUG hyper_util::client::legacy::connect::http: connecting to <my_server_ip>:443
2024-06-28T20:02:55.426362Z DEBUG hyper_util::client::legacy::connect::http: connected to <my_server_ip>:443
2024-06-28T20:02:55.486200Z TRACE hyper_util::client::legacy::client: http1 handshake complete, spawning background dispatcher task
2024-06-28T20:02:55.486953Z TRACE hyper_util::client::legacy::pool: checkout dropped for ("https", <my_server_ip>)
2024-06-28T20:02:55.513462Z TRACE snxcore::ccc: Reply from server: (CCCserverResponse
    :ResponseHeader (
        :id (2)
        :type (ClientHello)
        :session_id ()
        :return_code (600)
    )
    :ResponseData (
        :protocol_version (
            :protocol_version (100)
            :features (0x1)
        )
        :upgrade_configuration (
            :available_client_version (0)
            :client_upgrade_url ()
            :upgrade_mode (ask_user)
        )
        :connectivity_info (
            :default_authentication_method (mixed)
            :client_enabled (false)
            :supported_data_tunnel_protocols (
                : (IPSec)
                : (SSL)
                : (L2TP)
            )
            :connectivity_type (IPSec)
            :server_ip (<my_server_ip>)
            :ipsec_transport (auto_detect)
            :tcpt_port (443)
            :natt_port (4500)
            :connect_with_certificate_url ("/clients/cert/")
            :cookie_name (CPCVPN_SESSION_ID)
            :internal_ca_fingerprint (
                :1 (<redacted>)
            )
        )
        :end_point_security (
            :ics (
                :run_ics (false)
                :ics_base_url ("/clients/ICS/components")
                :ics_version (403006000)
                :ics_upgrade_url ("/clients/ICS/components/icsweb.cab")
                :ics_images_url ("/clients/ICS/components/ICS_images.cab")
                :ics_images_ver (403006000)
                :ics_cab_url ("/clients/ICS/components/cl_ics.cab")
                :ics_cab_version ("996000036
")
            )
        )
        :login_options_data (
            :login_options_list (
                :0 (
                    :id (vpn)
                    :secondary_realm_hash (<redacted>)
                    :display_name (vpn)
                    :show_realm (1)
                    :factors (
                        :0 (
                            :factor_type (user_defined)
                            :securid_card_type ()
                            :certificate_storage_type ()
                            :custom_display_labels ()
                        )
                    )
                )
            )
            :login_options_md5 (<redacted>)
        )
    )
)

2024-06-28T20:02:55.514834Z DEBUG snxcore::tunnel::ssl::connector: Authenticating to endpoint: <my_server_ip>
2024-06-28T20:02:55.514940Z  WARN snxcore::ccc: Disabling all certificate checks!!!
2024-06-28T20:02:55.538364Z TRACE snxcore::ccc: Request to server: (CCCclientRequest
    :RequestData (
        :client_type (TRAC)
        :selectedLoginOption (vpn))
    :RequestHeader (
        :id (3)
        :type (CertAuth)))
2024-06-28T20:02:55.538469Z TRACE hyper_util::client::legacy::pool: checkout waiting for idle connection: ("https", <my_server_ip>)
2024-06-28T20:02:55.538716Z TRACE hyper_util::client::legacy::connect::http: Http::connect; scheme=Some("https"), host=Some("<my_server_ip>"), port=None
2024-06-28T20:02:55.538724Z DEBUG hyper_util::client::legacy::connect::http: connecting to <my_server_ip>:443
2024-06-28T20:02:55.565108Z DEBUG hyper_util::client::legacy::connect::http: connected to <my_server_ip>:443
2024-06-28T20:02:55.634224Z TRACE hyper_util::client::legacy::client: http1 handshake complete, spawning background dispatcher task
2024-06-28T20:02:55.635441Z TRACE hyper_util::client::legacy::pool: checkout dropped for ("https", <my_server_ip>)
2024-06-28T20:02:55.725678Z TRACE snxcore::ccc: Reply from server: (CCCserverResponse
    :ResponseHeader (
        :id (3)
        :type (CertAuth)
        :session_id ()
        :return_code (600)
    )
    :ResponseData (
        :authn_status (done)
        :is_authenticated (true)
        :active_key (<redacted>)
        :server_fingerprint ()
        :server_cn ()
        :session_id (<redacted>)
        :active_key_timeout (43200)
        :username ("CN=<redacted>,OU=users,O=<redacted>")
    )
)

2024-06-28T20:02:55.726287Z DEBUG snxcore::tunnel::ssl::connector: Authentication OK, session id: c4002b4ce5fddb86bab5ba19d34e3397
2024-06-28T20:02:55.761388Z  WARN snxcore::tunnel::ssl: Disabling all certificate checks!!!
2024-06-28T20:02:55.847323Z DEBUG snxcore::tunnel::ssl: Tunnel connected
2024-06-28T20:02:55.858457Z TRACE perform: zbus::connection::handshake::client: Initializing
2024-06-28T20:02:55.858709Z TRACE perform:authenticate: zbus::connection::handshake::client: Trying EXTERNAL mechanism
2024-06-28T20:02:55.871118Z TRACE perform:authenticate:write_command{command=Auth(Some(External), Some([48]))}:write_commands{commands=[Auth(Some(External), Some([48]))] extra_bytes=None}: zbus::connection::handshake::common: Wrote all commands
2024-06-28T20:02:55.871793Z TRACE perform:authenticate:read_command:read_commands{n_commands=1}: zbus::connection::handshake::common: Reading OK b220b2221fbc68fec6f1b3c9667f1680

2024-06-28T20:02:55.871811Z TRACE perform:authenticate: zbus::connection::handshake::client: Received OK from server
2024-06-28T20:02:55.871888Z TRACE perform:send_secondary_commands{challenge_response=None}:write_commands{commands=[NegotiateUnixFD, Begin] extra_bytes=Some([108, 1, 0, 1, 0, 0, 0, 0, 1, 0, 0, 0, 109, 0, 0, 0, 1, 1, 111, 0, 21, 0, 0, 0, 47, 111, 114, 103, 47, 102, 114, 101, 101, 100, 101, 115, 107, 116, 111, 112, 47, 68, 66, 117, 115, 0, 0, 0, 3, 1, 115, 0, 5, 0, 0, 0, 72, 101, 108, 108, 111, 0, 0, 0, 6, 1, 115, 0, 20, 0, 0, 0, 111, 114, 103, 46, 102, 114, 101, 101, 100, 101, 115, 107, 116, 111, 112, 46, 68, 66, 117, 115, 0, 0, 0, 0, 2, 1, 115, 0, 20, 0, 0, 0, 111, 114, 103, 46, 102, 114, 101, 101, 100, 101, 115, 107, 116, 111, 112, 46, 68, 66, 117, 115, 0, 0, 0, 0])}: zbus::connection::handshake::common: Wrote all commands
2024-06-28T20:02:55.872656Z TRACE perform:receive_secondary_responses{expected_n_responses=1}:read_commands{n_commands=1}: zbus::connection::handshake::common: Reading AGREE_UNIX_FD

2024-06-28T20:02:55.872722Z TRACE perform: zbus::connection::handshake::client: Handshake done
2024-06-28T20:02:55.901818Z DEBUG snxcore::tunnel::ssl: Running SSL tunnel for session c4002b4ce5fddb86bab5ba19d34e3397
2024-06-28T20:02:55.902350Z TRACE socket reader: zbus::connection::socket_reader: Waiting for message on the socket..
2024-06-28T20:02:55.903872Z TRACE socket reader: zbus::connection::socket_reader: Message received on the socket: Msg { type: Signal, serial: 2, sender: UniqueName("org.freedesktop.DBus"), path: ObjectPath("/org/freedesktop/DBus"), iface: InterfaceName("org.freedesktop.DBus"), member: MemberName("NameAcquired"), body: Signature("s"), fds: [] }
2024-06-28T20:02:55.903894Z TRACE socket reader: zbus::connection::socket_reader: Error broadcasting message to stream for `None`: SendError(..)
2024-06-28T20:02:55.903897Z TRACE socket reader: zbus::connection::socket_reader: Broadcasted to all streams: Ok(Msg { type: Signal, serial: 2, sender: UniqueName("org.freedesktop.DBus"), path: ObjectPath("/org/freedesktop/DBus"), iface: InterfaceName("org.freedesktop.DBus"), member: MemberName("NameAcquired"), body: Signature("s"), fds: [] })
2024-06-28T20:02:55.903901Z TRACE socket reader: zbus::connection::socket_reader: Waiting for message on the socket..
2024-06-28T20:02:55.901830Z TRACE snxcore::tunnel::ssl: Hello request: ClientHelloData { client_version: 1, protocol_version: 1, protocol_minor_version: 1, office_mode: OfficeMode { ipaddr: "0.0.0.0", keep_address: Some(false), dns_servers: None, dns_suffix: None }, optional: Some(OptionalRequest { client_type: "4" }), cookie: "0f1be99be52e66ffee002b24b77b99b14ff18957a4d14032be56fd0347fb9259" }
2024-06-28T20:02:55.905547Z TRACE new:{}{task_name="org.freedesktop.NetworkManager proxy caching"}: zbus::connection::socket: Sending message: Msg { type: MethodCall, serial: 2, sender: UniqueName(":1.72"), path: ObjectPath("/org/freedesktop/DBus"), iface: InterfaceName("org.freedesktop.DBus"), member: MemberName("AddMatch"), body: Signature("s"), fds: [] }
2024-06-28T20:02:55.905574Z TRACE new:{}{task_name="org.freedesktop.NetworkManager proxy caching"}: zbus::connection::socket: Sent message with serial: 2
2024-06-28T20:02:55.905948Z TRACE socket reader: zbus::connection::socket_reader: Message received on the socket: Msg { type: MethodReturn, serial: 3, sender: UniqueName("org.freedesktop.DBus"), reply-serial: 2, fds: [] }
2024-06-28T20:02:55.905961Z TRACE socket reader: zbus::connection::socket_reader: Error broadcasting message to stream for `None`: SendError(..)
2024-06-28T20:02:55.905966Z TRACE socket reader: zbus::connection::socket_reader: Broadcasted to all streams: Ok(Msg { type: MethodReturn, serial: 3, sender: UniqueName("org.freedesktop.DBus"), reply-serial: 2, fds: [] })
2024-06-28T20:02:55.905969Z TRACE socket reader: zbus::connection::socket_reader: Waiting for message on the socket..
2024-06-28T20:02:55.906066Z TRACE new:{}{task_name="org.freedesktop.NetworkManager proxy caching"}: zbus::connection::socket: Sending message: Msg { type: MethodCall, serial: 3, sender: UniqueName(":1.72"), path: ObjectPath("/org/freedesktop/DBus"), iface: InterfaceName("org.freedesktop.DBus"), member: MemberName("GetNameOwner"), body: Signature("s"), fds: [] }
2024-06-28T20:02:55.906082Z TRACE new:{}{task_name="org.freedesktop.NetworkManager proxy caching"}: zbus::connection::socket: Sent message with serial: 3
2024-06-28T20:02:55.906390Z TRACE socket reader: zbus::connection::socket_reader: Message received on the socket: Msg { type: MethodReturn, serial: 4, sender: UniqueName("org.freedesktop.DBus"), reply-serial: 3, body: Signature("s"), fds: [] }
2024-06-28T20:02:55.906426Z TRACE socket reader: zbus::connection::socket_reader: Error broadcasting message to stream for `None`: SendError(..)
2024-06-28T20:02:55.906429Z TRACE socket reader: zbus::connection::socket_reader: Broadcasted to all streams: Ok(Msg { type: MethodReturn, serial: 4, sender: UniqueName("org.freedesktop.DBus"), reply-serial: 3, body: Signature("s"), fds: [] })
2024-06-28T20:02:55.906432Z TRACE socket reader: zbus::connection::socket_reader: Waiting for message on the socket..
2024-06-28T20:02:55.906482Z TRACE new:{}{task_name="org.freedesktop.NetworkManager proxy caching"}: zbus::connection::socket: Sending message: Msg { type: MethodCall, serial: 4, sender: UniqueName(":1.72"), path: ObjectPath("/org/freedesktop/DBus"), iface: InterfaceName("org.freedesktop.DBus"), member: MemberName("AddMatch"), body: Signature("s"), fds: [] }
2024-06-28T20:02:55.906492Z TRACE new:{}{task_name="org.freedesktop.NetworkManager proxy caching"}: zbus::connection::socket: Sent message with serial: 4
2024-06-28T20:02:55.906568Z TRACE socket reader: zbus::connection::socket_reader: Message received on the socket: Msg { type: MethodReturn, serial: 5, sender: UniqueName("org.freedesktop.DBus"), reply-serial: 4, fds: [] }
2024-06-28T20:02:55.906582Z TRACE socket reader: zbus::connection::socket_reader: Error broadcasting message to stream for `None`: SendError(..)
2024-06-28T20:02:55.906588Z TRACE socket reader: zbus::connection::socket_reader: Broadcasted to all streams: Ok(Msg { type: MethodReturn, serial: 5, sender: UniqueName("org.freedesktop.DBus"), reply-serial: 4, fds: [] })
2024-06-28T20:02:55.906594Z TRACE socket reader: zbus::connection::socket_reader: Waiting for message on the socket..
2024-06-28T20:02:55.906631Z TRACE new:{}{task_name="org.freedesktop.NetworkManager proxy caching"}: zbus::connection::socket: Sending message: Msg { type: MethodCall, serial: 5, sender: UniqueName(":1.72"), path: ObjectPath("/org/freedesktop/NetworkManager"), iface: InterfaceName("org.freedesktop.DBus.Properties"), member: MemberName("GetAll"), body: Signature("s"), fds: [] }
2024-06-28T20:02:55.906692Z TRACE new:{}{task_name="org.freedesktop.NetworkManager proxy caching"}: zbus::connection::socket: Sent message with serial: 5
2024-06-28T20:02:55.907071Z TRACE socket reader: zbus::connection::socket_reader: Message received on the socket: Msg { type: MethodReturn, serial: 267, sender: UniqueName(":1.9"), reply-serial: 5, body: Signature("a{sv}"), fds: [] }
2024-06-28T20:02:55.907135Z TRACE socket reader: zbus::connection::socket_reader: Error broadcasting message to stream for `None`: SendError(..)
2024-06-28T20:02:55.907141Z TRACE socket reader: zbus::connection::socket_reader: Broadcasted to all streams: Ok(Msg { type: MethodReturn, serial: 267, sender: UniqueName(":1.9"), reply-serial: 5, body: Signature("a{sv}"), fds: [] })
2024-06-28T20:02:55.907145Z TRACE socket reader: zbus::connection::socket_reader: Waiting for message on the socket..
2024-06-28T20:02:55.907204Z TRACE new:{}{task_name="org.freedesktop.NetworkManager proxy caching"}: zbus::proxy: Property `org.freedesktop.NetworkManager.WirelessEnabled` updated
2024-06-28T20:02:55.907209Z TRACE new:{}{task_name="org.freedesktop.NetworkManager proxy caching"}: zbus::proxy: Property `org.freedesktop.NetworkManager.PrimaryConnectionType` updated
2024-06-28T20:02:55.907213Z TRACE new:{}{task_name="org.freedesktop.NetworkManager proxy caching"}: zbus::proxy: Property `org.freedesktop.NetworkManager.Checkpoints` updated
2024-06-28T20:02:55.907217Z TRACE new:{}{task_name="org.freedesktop.NetworkManager proxy caching"}: zbus::proxy: Property `org.freedesktop.NetworkManager.ActivatingConnection` updated
2024-06-28T20:02:55.907220Z TRACE new:{}{task_name="org.freedesktop.NetworkManager proxy caching"}: zbus::proxy: Property `org.freedesktop.NetworkManager.Connectivity` updated
2024-06-28T20:02:55.907223Z TRACE new:{}{task_name="org.freedesktop.NetworkManager proxy caching"}: zbus::proxy: Property `org.freedesktop.NetworkManager.State` updated
2024-06-28T20:02:55.907226Z TRACE new:{}{task_name="org.freedesktop.NetworkManager proxy caching"}: zbus::proxy: Property `org.freedesktop.NetworkManager.ActiveConnections` updated
2024-06-28T20:02:55.907229Z TRACE new:{}{task_name="org.freedesktop.NetworkManager proxy caching"}: zbus::proxy: Property `org.freedesktop.NetworkManager.Version` updated
2024-06-28T20:02:55.907236Z TRACE new:{}{task_name="org.freedesktop.NetworkManager proxy caching"}: zbus::proxy: Property `org.freedesktop.NetworkManager.Metered` updated
2024-06-28T20:02:55.907239Z TRACE new:{}{task_name="org.freedesktop.NetworkManager proxy caching"}: zbus::proxy: Property `org.freedesktop.NetworkManager.NetworkingEnabled` updated
2024-06-28T20:02:55.907241Z TRACE new:{}{task_name="org.freedesktop.NetworkManager proxy caching"}: zbus::proxy: Property `org.freedesktop.NetworkManager.AllDevices` updated
2024-06-28T20:02:55.907245Z TRACE new:{}{task_name="org.freedesktop.NetworkManager proxy caching"}: zbus::proxy: Property `org.freedesktop.NetworkManager.WwanHardwareEnabled` updated
2024-06-28T20:02:55.907247Z TRACE new:{}{task_name="org.freedesktop.NetworkManager proxy caching"}: zbus::proxy: Property `org.freedesktop.NetworkManager.WwanEnabled` updated
2024-06-28T20:02:55.907250Z TRACE new:{}{task_name="org.freedesktop.NetworkManager proxy caching"}: zbus::proxy: Property `org.freedesktop.NetworkManager.PrimaryConnection` updated
2024-06-28T20:02:55.907254Z TRACE new:{}{task_name="org.freedesktop.NetworkManager proxy caching"}: zbus::proxy: Property `org.freedesktop.NetworkManager.ConnectivityCheckUri` updated
2024-06-28T20:02:55.907259Z TRACE new:{}{task_name="org.freedesktop.NetworkManager proxy caching"}: zbus::proxy: Property `org.freedesktop.NetworkManager.GlobalDnsConfiguration` updated
2024-06-28T20:02:55.907262Z TRACE new:{}{task_name="org.freedesktop.NetworkManager proxy caching"}: zbus::proxy: Property `org.freedesktop.NetworkManager.Devices` updated
2024-06-28T20:02:55.907265Z TRACE new:{}{task_name="org.freedesktop.NetworkManager proxy caching"}: zbus::proxy: Property `org.freedesktop.NetworkManager.Startup` updated
2024-06-28T20:02:55.907268Z TRACE new:{}{task_name="org.freedesktop.NetworkManager proxy caching"}: zbus::proxy: Property `org.freedesktop.NetworkManager.VersionInfo` updated
2024-06-28T20:02:55.907270Z TRACE new:{}{task_name="org.freedesktop.NetworkManager proxy caching"}: zbus::proxy: Property `org.freedesktop.NetworkManager.RadioFlags` updated
2024-06-28T20:02:55.907273Z TRACE new:{}{task_name="org.freedesktop.NetworkManager proxy caching"}: zbus::proxy: Property `org.freedesktop.NetworkManager.WimaxHardwareEnabled` updated
2024-06-28T20:02:55.907276Z TRACE new:{}{task_name="org.freedesktop.NetworkManager proxy caching"}: zbus::proxy: Property `org.freedesktop.NetworkManager.WimaxEnabled` updated
2024-06-28T20:02:55.907278Z TRACE new:{}{task_name="org.freedesktop.NetworkManager proxy caching"}: zbus::proxy: Property `org.freedesktop.NetworkManager.WirelessHardwareEnabled` updated
2024-06-28T20:02:55.907281Z TRACE new:{}{task_name="org.freedesktop.NetworkManager proxy caching"}: zbus::proxy: Property `org.freedesktop.NetworkManager.Capabilities` updated
2024-06-28T20:02:55.907285Z TRACE new:{}{task_name="org.freedesktop.NetworkManager proxy caching"}: zbus::proxy: Property `org.freedesktop.NetworkManager.ConnectivityCheckEnabled` updated
2024-06-28T20:02:55.907288Z TRACE new:{}{task_name="org.freedesktop.NetworkManager proxy caching"}: zbus::proxy: Property `org.freedesktop.NetworkManager.ConnectivityCheckAvailable` updated
2024-06-28T20:02:55.907455Z TRACE new:{}{task_name="org.freedesktop.NetworkManager proxy caching"}:keep_updated: zbus::proxy: Listening for property changes on org.freedesktop.NetworkManager...
2024-06-28T20:02:55.907477Z DEBUG snxcore::platform::linux::net: NetworkManager state changed to ConnectedGlobal
2024-06-28T20:02:55.931918Z TRACE snxcore::tunnel::ssl: Hello reply: Object(Some("disconnect"), {"code": Value("205"), "message": QuotedValue("SSL Network Extender gateway is not available. Try to connect later.")})
Error: missing field `(hello_reply`

Just tried again with the official Windows client and it connected, no idea why it says "gateway not available".

ancwrd1 commented 4 months ago

My guess is that Windows uses IPSec connection and your server doesn't support SSL tunnel anymore. What error do you get when you try IPSec? Can you share trace log?

vlzware commented 4 months ago

It seems you are right in regards of IPSec - according to Wireshark the initial key exchange happens over SSL, then the all the packets are marked as ISAKMP and ESP, which Wireshark tags as UDP Encapsulation of IPsec Packets.

When running snx-rs with --tunnel-type=ipsec I get this:

2024-06-29T07:59:12.349673Z DEBUG snx_rs: >>> Starting snx-rs client version 2.2.4
2024-06-29T07:59:12.349720Z DEBUG snx_rs: Running in standalone mode
2024-06-29T07:59:12.352110Z  WARN snxcore::ccc: Disabling all certificate checks!!!
2024-06-29T07:59:12.375106Z TRACE snxcore::ccc: Request to server: (CCCclientRequest
    :RequestData (
        :client_info (
            :client_support_saml (true)
            :client_type (SYMBIAN)
            :client_version (1)))
    :RequestHeader (
        :id (2)
        :type (ClientHello)))
2024-06-29T07:59:12.382320Z TRACE hyper_util::client::legacy::pool: checkout waiting for idle connection: ("https", <my_server_ip>)
2024-06-29T07:59:12.382371Z TRACE hyper_util::client::legacy::connect::http: Http::connect; scheme=Some("https"), host=Some("<my_server_ip>"), port=None
2024-06-29T07:59:12.382376Z DEBUG hyper_util::client::legacy::connect::http: connecting to <my_server_ip>:443
2024-06-29T07:59:12.409740Z DEBUG hyper_util::client::legacy::connect::http: connected to <my_server_ip>:443
2024-06-29T07:59:12.478224Z TRACE hyper_util::client::legacy::client: http1 handshake complete, spawning background dispatcher task
2024-06-29T07:59:12.478918Z TRACE hyper_util::client::legacy::pool: checkout dropped for ("https", <my_server_ip>)
2024-06-29T07:59:12.506482Z TRACE snxcore::ccc: Reply from server: (CCCserverResponse
    :ResponseHeader (
        :id (2)
        :type (ClientHello)
        :session_id ()
        :return_code (600)
    )
    :ResponseData (
        :protocol_version (
            :protocol_version (100)
            :features (0x1)
        )
        :upgrade_configuration (
            :available_client_version (0)
            :client_upgrade_url ()
            :upgrade_mode (ask_user)
        )
        :connectivity_info (
            :default_authentication_method (mixed)
            :client_enabled (false)
            :supported_data_tunnel_protocols (
                : (IPSec)
                : (SSL)
                : (L2TP)
            )
            :connectivity_type (IPSec)
            :server_ip (<my_server_ip>)
            :ipsec_transport (auto_detect)
            :tcpt_port (443)
            :natt_port (4500)
            :connect_with_certificate_url ("/clients/cert/")
            :cookie_name (CPCVPN_SESSION_ID)
            :internal_ca_fingerprint (
                :1 (<redacted>)
            )
        )
        :end_point_security (
            :ics (
                :run_ics (false)
                :ics_base_url ("/clients/ICS/components")
                :ics_version (403006000)
                :ics_upgrade_url ("/clients/ICS/components/icsweb.cab")
                :ics_images_url ("/clients/ICS/components/ICS_images.cab")
                :ics_images_ver (403006000)
                :ics_cab_url ("/clients/ICS/components/cl_ics.cab")
                :ics_cab_version ("996000036
")
            )
        )
        :login_options_data (
            :login_options_list (
                :0 (
                    :id (vpn)
                    :secondary_realm_hash (<redacted>)
                    :display_name (vpn)
                    :show_realm (1)
                    :factors (
                        :0 (
                            :factor_type (user_defined)
                            :securid_card_type ()
                            :certificate_storage_type ()
                            :custom_display_labels ()
                        )
                    )
                )
            )
            :login_options_md5 (<redacted>)
        )
    )
)

2024-06-29T07:59:12.520321Z DEBUG snxcore::tunnel::ipsec::natt: Sending NAT-T probe to <my_server_ip>
2024-06-29T07:59:12.544640Z DEBUG snxcore::tunnel::ipsec::natt: Received NAT-T reply from <my_server_ip>: srcport: 4500, dstport: 4500, hash: <redacted>
2024-06-29T07:59:12.548895Z TRACE snxcore::util: Exec: "ip" ["-4", "route", "show", "default"]
2024-06-29T07:59:12.551535Z TRACE snxcore::util: Exec: "ip" ["-4", "-o", "addr", "show", "dev", "enp0s3"]
2024-06-29T07:59:12.553875Z DEBUG isakmp::ikev1::service: Begin SA proposal
2024-06-29T07:59:12.553935Z DEBUG isakmp::transport: Sending ISAKMP message of size 631 to <my_server_ip>:500
2024-06-29T07:59:12.579764Z DEBUG isakmp::transport: Parsing ISAKMP message of size 268
2024-06-29T07:59:12.579950Z TRACE isakmp::payload: Parsing payload: type=SecurityAssociation, size=56, next=VendorId
2024-06-29T07:59:12.579956Z TRACE isakmp::payload: Parsing payload: type=Proposal, size=44, next=None
2024-06-29T07:59:12.579959Z TRACE isakmp::payload: Parsing payload: type=Transform, size=36, next=None
2024-06-29T07:59:12.579966Z TRACE isakmp::payload: Parsing payload: type=VendorId, size=40, next=VendorId
2024-06-29T07:59:12.579968Z TRACE isakmp::payload: Parsing payload: type=VendorId, size=16, next=VendorId
2024-06-29T07:59:12.579969Z TRACE isakmp::payload: Parsing payload: type=VendorId, size=16, next=VendorId
2024-06-29T07:59:12.579971Z TRACE isakmp::payload: Parsing payload: type=VendorId, size=16, next=Notification
2024-06-29T07:59:12.579974Z TRACE isakmp::payload: Parsing payload: type=Notification, size=28, next=Notification
2024-06-29T07:59:12.579976Z TRACE isakmp::payload: Parsing payload: type=Notification, size=40, next=None
2024-06-29T07:59:12.579981Z DEBUG isakmp::ikev1::service: Negotiated SA hash algorithm: Sha
2024-06-29T07:59:12.579983Z DEBUG isakmp::ikev1::service: Negotiated SA key length: 32
2024-06-29T07:59:12.579984Z DEBUG isakmp::ikev1::service: Negotiated SA group: Oakley2
2024-06-29T07:59:12.583489Z DEBUG isakmp::ikev1::service: End SA proposal
2024-06-29T07:59:12.583549Z DEBUG isakmp::ikev1::service: Begin key exchange
2024-06-29T07:59:12.583563Z DEBUG isakmp::transport: Sending ISAKMP message of size 244 to <my_server_ip>:500
2024-06-29T07:59:12.608409Z DEBUG isakmp::transport: Parsing ISAKMP message of size 295
2024-06-29T07:59:12.608457Z TRACE isakmp::payload: Parsing payload: type=KeyExchange, size=128, next=Nonce
2024-06-29T07:59:12.608463Z TRACE isakmp::payload: Parsing payload: type=Nonce, size=20, next=CertificateRequest
2024-06-29T07:59:12.608466Z TRACE isakmp::payload: Parsing payload: type=CertificateRequest, size=30, next=CertificateRequest
2024-06-29T07:59:12.608468Z TRACE isakmp::payload: Parsing payload: type=CertificateRequest, size=1, next=Natd
2024-06-29T07:59:12.608470Z TRACE isakmp::payload: Parsing payload: type=Natd, size=20, next=Natd
2024-06-29T07:59:12.608472Z TRACE isakmp::payload: Parsing payload: type=Natd, size=20, next=Natd
2024-06-29T07:59:12.608474Z TRACE isakmp::payload: Parsing payload: type=Natd, size=20, next=None
2024-06-29T07:59:12.608476Z TRACE isakmp::ikev1::service: Responder's public key length: 128
2024-06-29T07:59:12.608478Z TRACE isakmp::ikev1::service: Responder's nonce length: 20
2024-06-29T07:59:12.609151Z TRACE isakmp::ikev1::service: COOKIE_i: <redacted>
2024-06-29T07:59:12.609220Z TRACE isakmp::ikev1::service: SKEYID_e: <redacted>
2024-06-29T07:59:12.609224Z DEBUG isakmp::ikev1::service: End key exchange
2024-06-29T07:59:12.609229Z DEBUG isakmp::ikev1::service: Begin identity protection
2024-06-29T07:59:12.610921Z DEBUG isakmp::transport: Sending ISAKMP message of size 2140 to <my_server_ip>:500
2024-06-29T07:59:14.609293Z TRACE isakmp::transport: Discarding already received message
2024-06-29T07:59:16.611280Z TRACE isakmp::transport: Discarding already received message
2024-06-29T07:59:18.612865Z TRACE isakmp::transport: Discarding already received message
2024-06-29T07:59:20.613601Z TRACE isakmp::transport: Discarding already received message
2024-06-29T07:59:22.615300Z TRACE isakmp::transport: Discarding already received message
2024-06-29T07:59:24.615591Z TRACE isakmp::transport: Discarding already received message
2024-06-29T07:59:28.619000Z TRACE isakmp::transport: Discarding already received message
2024-06-29T07:59:32.619275Z TRACE isakmp::transport: Discarding already received message
2024-06-29T07:59:36.622167Z TRACE isakmp::transport: Discarding already received message
2024-06-29T07:59:40.625062Z TRACE isakmp::transport: Discarding already received message
2024-06-29T07:59:44.629019Z TRACE isakmp::transport: Discarding already received message
2024-06-29T07:59:49.631699Z DEBUG isakmp::transport: Sending ISAKMP message of size 80 to <my_server_ip>:500
Error: deadline has elapsed
ancwrd1 commented 4 months ago

In file src/tunnel/ipsec/connector.rs, line 388, try changing client_mode parameter from "SYMBIAN" to "endpoint_security", "secure_connect" or "secure_remote". May be one of them will work.

vlzware commented 4 months ago

Thank you for not giving up on me :)

I tried all three suggestions without success. It is worth noting that the trace still reported "SYMBIAN" in the RequestData field, so I grepped for "SYMBIAN" and found it in "params.rs". I changed there as well, but this didn't help either. The output is the same as earlier with Error: deadline has elapsed at the end.

The CheckPoint client have an option for collecting logs, so I tried digging there and found this - maybe this can shed some more light:

[ 3612 4036][28 Jun  9:07:56][TR_CONN_MANAGER]  ConnGetInfo: vpn conn data:
(
    :gw-ipaddr (<my_server_ip>)
    :vpnd_ipaddr (<my_server_ip>)
    :authentication-method (p12-certificate)
    :is_saa (false)
    :transport (Auto-Detect)
    :display_name ("<redacted>")
    :gw_hostname (<my_server_ip>)
    :username ()
    :certificate_path ("path/to/my/certificate.p12")
    :cached (false)
    :cache_timeout (1440)
    :neo_always_connected (false)
    :neo_upgrade_mode (ask_user)
    :neo_check_crl (false)
    :neo_user_re_auth_timeout (720)
    :neo_always_connected_retry (1)
    :dgd_tunnel_idle_timeout (20)
    :dgd_burst_timeout (2000)
    :dgd_tunnel_test_rep_timeout (20)
    :connect_timeout (70000)
    :transport_connect_timeout (40000)
    :natt_transport_port (4500)
    :tcpt_transport_port (443)
    :gw_bc_mode (false)
    :enable_gw_resolving (true)
    :enable_natt_probing (true)
    :enable_dead_gw_detection (true)
    :secure_id_type (pin_pad)
    :gw_internal_ipaddr (<my_server_ip>)
    :user_upgrade_mode (ASK_USER)
    :site_uses_login_options (true)
    :realm_id (vpn)
    :def_gw_ipaddr (<my_server_ip>)
    :keep_alive (false)
    :keep_alive_interval (0)
    :log_tunnel_errors_to_helpdesk (1)
    :extended_connect_timeout_for_idp (115000)
    :conn_name ("<redacted>")
    :mac-address (<redacted>)
    :Multi-Site_Site_Enabled (0)
    :ConnState (0)
    :ConnHandle (1)
    :active_site (1)
    :GwHandle (2)
    :CredsInCache (0)
    :ConnGwCount (1)
)

as well as this:

[ 3612 4036][28 Jun  9:08:20][HelloRequest] HelloRequest::BuildHelloReq() hello request: (ClientHello
    :client_info (
        :client_type (TRAC)
        :client_version (986103912)
        :client_mode (endpoint_security)
        :gw_ip (<my_server_ip>)
        :client_support_saml (true)
    )
)

[ 3612 4036][28 Jun  9:08:20][HelloRequest] HelloRequest::SendHelloRequest(): req_set_str (ClientHello
    :client_info (
        :client_type (TRAC)
        :client_version (986103912)
        :client_mode (endpoint_security)
        :gw_ip (<my_server_ip>)
        :client_support_saml (true)
    )
)

Additionally, I found another server on some other place configured in a similar way - CheckPoint with a password and IPSec. snx-rs fails there in the same way.

ancwrd1 commented 4 months ago

Could you checkout branch 'issue26' and try it with IPSec?

vlzware commented 4 months ago

Still no luck. Tried with both servers with similar results.

command: sudo ./target/release/snx-rs -s <my_server_ip> --ignore-server-cert=true --login-type=vpn --cert-path /path/to/cert.p12 --cert-type pkcs12 --cert-password="<password>" --log-level=trace --tunnel-type=ipsec

result:

2024-06-29T18:41:06.139949Z DEBUG snx_rs: >>> Starting snx-rs client version 2.2.4
2024-06-29T18:41:06.140001Z DEBUG snx_rs: Running in standalone mode
2024-06-29T18:41:06.140027Z  WARN snxcore::ccc: Disabling all certificate checks!!!
2024-06-29T18:41:06.177901Z TRACE snxcore::ccc: Request to server: (CCCclientRequest
    :RequestData (
        :client_info (
            :client_support_saml (true)
            :client_type (TRAC)
            :client_version (1)))
    :RequestHeader (
        :id (2)
        :type (ClientHello)))
2024-06-29T18:41:06.178029Z TRACE hyper_util::client::legacy::pool: checkout waiting for idle connection: ("https", <my_server_ip>)
2024-06-29T18:41:06.178042Z TRACE hyper_util::client::legacy::connect::http: Http::connect; scheme=Some("https"), host=Some("<my_server_ip>"), port=None
2024-06-29T18:41:06.178046Z DEBUG hyper_util::client::legacy::connect::http: connecting to <my_server_ip>:443
2024-06-29T18:41:06.205982Z DEBUG hyper_util::client::legacy::connect::http: connected to <my_server_ip>:443
2024-06-29T18:41:06.278571Z TRACE hyper_util::client::legacy::client: http1 handshake complete, spawning background dispatcher task
2024-06-29T18:41:06.279133Z TRACE hyper_util::client::legacy::pool: checkout dropped for ("https", <my_server_ip>)
2024-06-29T18:41:06.306680Z TRACE snxcore::ccc: Reply from server: (CCCserverResponse
    :ResponseHeader (
        :id (2)
        :type (ClientHello)
        :session_id ()
        :return_code (600)
    )
    :ResponseData (
        :protocol_version (
            :protocol_version (100)
            :features (0x1)
        )
        :upgrade_configuration (
            :available_client_version (835000022)
            :client_upgrade_url ("/CSHELL/")
            :upgrade_mode (ask_user)
        )
        :connectivity_info (
            :default_authentication_method (client_decide)
            :client_enabled (true)
            :supported_data_tunnel_protocols (
                : (IPSec)
                : (SSL)
                : (L2TP)
            )
            :connectivity_type (IPSec)
            :server_ip (<my_server_ip>)
            :ipsec_transport (auto_detect)
            :tcpt_port (443)
            :natt_port (4500)
            :connect_with_certificate_url ("/clients/cert/")
            :cookie_name (CPCVPN_SESSION_ID)
            :internal_ca_fingerprint (
                :1 (<redacted>)
            )
        )
        :end_point_security (
            :ics (
                :run_ics (false)
                :ics_base_url ("/clients/ICS/components")
                :ics_version (403006000)
                :ics_upgrade_url ("/clients/ICS/components/icsweb.cab")
                :ics_images_url ("/clients/ICS/components/ICS_images.cab")
                :ics_images_ver (403006000)
                :ics_cab_url ("/clients/ICS/components/cl_ics.cab")
                :ics_cab_version ("996000036
")
            )
        )
        :login_options_data (
            :login_options_list (
                :0 (
                    :id (vpn)
                    :secondary_realm_hash (<redacted>)
                    :display_name (vpn)
                    :show_realm (1)
                    :factors (
                        :0 (
                            :factor_type (user_defined)
                            :securid_card_type ()
                            :certificate_storage_type ()
                            :custom_display_labels ()
                        )
                    )
                )
            )
            :login_options_md5 (<redacted>)
        )
    )
)

2024-06-29T18:41:06.308015Z DEBUG snxcore::tunnel::ipsec::natt: Sending NAT-T probe to <my_server_ip>
2024-06-29T18:41:06.337568Z DEBUG snxcore::tunnel::ipsec::natt: Received NAT-T reply from <my_server_ip>: srcport: 4500, dstport: 4500, hash: 4ae71336e44bf9bf79d2752e234818a5
2024-06-29T18:41:06.340466Z TRACE snxcore::util: Exec: "ip" ["-4", "route", "show", "default"]
2024-06-29T18:41:06.367235Z TRACE snxcore::util: Exec: "ip" ["-4", "-o", "addr", "show", "dev", "enp0s3"]
2024-06-29T18:41:06.369482Z DEBUG isakmp::ikev1::service: Begin SA proposal
2024-06-29T18:41:06.369544Z DEBUG isakmp::transport: Sending ISAKMP message of size 631 to <my_server_ip>:500
2024-06-29T18:41:06.397780Z DEBUG isakmp::transport: Parsing ISAKMP message of size 268
2024-06-29T18:41:06.397838Z TRACE isakmp::payload: Parsing payload: type=SecurityAssociation, size=56, next=VendorId
2024-06-29T18:41:06.397845Z TRACE isakmp::payload: Parsing payload: type=Proposal, size=44, next=None
2024-06-29T18:41:06.397850Z TRACE isakmp::payload: Parsing payload: type=Transform, size=36, next=None
2024-06-29T18:41:06.397859Z TRACE isakmp::payload: Parsing payload: type=VendorId, size=40, next=VendorId
2024-06-29T18:41:06.397864Z TRACE isakmp::payload: Parsing payload: type=VendorId, size=16, next=VendorId
2024-06-29T18:41:06.397867Z TRACE isakmp::payload: Parsing payload: type=VendorId, size=16, next=VendorId
2024-06-29T18:41:06.397871Z TRACE isakmp::payload: Parsing payload: type=VendorId, size=16, next=Notification
2024-06-29T18:41:06.397876Z TRACE isakmp::payload: Parsing payload: type=Notification, size=28, next=Notification
2024-06-29T18:41:06.397880Z TRACE isakmp::payload: Parsing payload: type=Notification, size=40, next=None
2024-06-29T18:41:06.397887Z DEBUG isakmp::ikev1::service: Negotiated SA hash algorithm: Sha
2024-06-29T18:41:06.397892Z DEBUG isakmp::ikev1::service: Negotiated SA key length: 32
2024-06-29T18:41:06.397895Z DEBUG isakmp::ikev1::service: Negotiated SA group: Oakley2
2024-06-29T18:41:06.400588Z DEBUG isakmp::ikev1::service: End SA proposal
2024-06-29T18:41:06.400643Z DEBUG isakmp::ikev1::service: Begin key exchange
2024-06-29T18:41:06.400658Z DEBUG isakmp::transport: Sending ISAKMP message of size 244 to <my_server_ip>:500
2024-06-29T18:41:06.422524Z DEBUG isakmp::transport: Parsing ISAKMP message of size 295
2024-06-29T18:41:06.422573Z TRACE isakmp::payload: Parsing payload: type=KeyExchange, size=128, next=Nonce
2024-06-29T18:41:06.422580Z TRACE isakmp::payload: Parsing payload: type=Nonce, size=20, next=CertificateRequest
2024-06-29T18:41:06.422583Z TRACE isakmp::payload: Parsing payload: type=CertificateRequest, size=30, next=CertificateRequest
2024-06-29T18:41:06.422585Z TRACE isakmp::payload: Parsing payload: type=CertificateRequest, size=1, next=Natd
2024-06-29T18:41:06.422587Z TRACE isakmp::payload: Parsing payload: type=Natd, size=20, next=Natd
2024-06-29T18:41:06.422589Z TRACE isakmp::payload: Parsing payload: type=Natd, size=20, next=Natd
2024-06-29T18:41:06.422590Z TRACE isakmp::payload: Parsing payload: type=Natd, size=20, next=None
2024-06-29T18:41:06.422593Z TRACE isakmp::ikev1::service: Responder's public key length: 128
2024-06-29T18:41:06.422595Z TRACE isakmp::ikev1::service: Responder's nonce length: 20
2024-06-29T18:41:06.422997Z TRACE isakmp::ikev1::service: COOKIE_i: 50ecdf7bd988a56f
2024-06-29T18:41:06.423033Z TRACE isakmp::ikev1::service: SKEYID_e: 5ea333904000d7c8ce90751f53d8ce2a7fd189d71b05a3cf3af3de310f8b3abb
2024-06-29T18:41:06.423040Z DEBUG isakmp::ikev1::service: End key exchange
2024-06-29T18:41:06.423871Z TRACE snxcore::tunnel::ipsec::connector: Authentication blob: (
    :clientType (TRAC)
    :client_logging_data (
        :device_id ("{<redacted>}")
        :os_name ("Windows"))
    :client_mode (secure_connect)
    :oldSessionId ()
    :protocolVersion (100)
    :selected_realm_id (vpn))
2024-06-29T18:41:06.423920Z DEBUG isakmp::ikev1::service: Begin identity protection
2024-06-29T18:41:06.425055Z DEBUG isakmp::transport: Sending ISAKMP message of size 2236 to <my_server_ip>:500
2024-06-29T18:41:08.429839Z TRACE isakmp::transport: Discarding already received message
2024-06-29T18:41:10.426714Z TRACE isakmp::transport: Discarding already received message
2024-06-29T18:41:12.430417Z TRACE isakmp::transport: Discarding already received message
2024-06-29T18:41:14.428595Z TRACE isakmp::transport: Discarding already received message
2024-06-29T18:41:16.428322Z TRACE isakmp::transport: Discarding already received message
2024-06-29T18:41:18.430161Z TRACE isakmp::transport: Discarding already received message
2024-06-29T18:41:22.430870Z TRACE isakmp::transport: Discarding already received message
2024-06-29T18:41:26.435323Z TRACE isakmp::transport: Discarding already received message
2024-06-29T18:41:30.437006Z TRACE isakmp::transport: Discarding already received message
2024-06-29T18:41:34.439087Z TRACE isakmp::transport: Discarding already received message
2024-06-29T18:41:38.442040Z TRACE isakmp::transport: Discarding already received message
2024-06-29T18:41:43.460538Z DEBUG isakmp::transport: Sending ISAKMP message of size 80 to <my_server_ip>:500
Error: deadline has elapsed
ancwrd1 commented 4 months ago

I think some fields are missing in the client_logging_data, checkpoint servers sometimes silently block communication when something is missing or unexpected. Let me try adding more fields there.

ancwrd1 commented 4 months ago

Added more client logging now, may be it will work. If not I can try one more thing.

vlzware commented 4 months ago

Same error occurs.

First server:

2024-06-30T06:33:25.912060Z DEBUG snx_rs: >>> Starting snx-rs client version 2.2.4
2024-06-30T06:33:25.912115Z DEBUG snx_rs: Running in standalone mode
2024-06-30T06:33:25.914033Z  WARN snxcore::ccc: Disabling all certificate checks!!!
2024-06-30T06:33:25.936463Z TRACE snxcore::ccc: Request to server: (CCCclientRequest
    :RequestData (
        :client_info (
            :client_support_saml (true)
            :client_type (TRAC)
            :client_version (1)))
    :RequestHeader (
        :id (2)
        :type (ClientHello)))
2024-06-30T06:33:25.940770Z TRACE hyper_util::client::legacy::pool: checkout waiting for idle connection: ("https", <my_server_ip>)
2024-06-30T06:33:25.940814Z TRACE hyper_util::client::legacy::connect::http: Http::connect; scheme=Some("https"), host=Some("<my_server_ip>"), port=None
2024-06-30T06:33:25.940819Z DEBUG hyper_util::client::legacy::connect::http: connecting to <my_server_ip>:443
2024-06-30T06:33:25.972301Z DEBUG hyper_util::client::legacy::connect::http: connected to <my_server_ip>:443
2024-06-30T06:33:26.040626Z TRACE hyper_util::client::legacy::client: http1 handshake complete, spawning background dispatcher task
2024-06-30T06:33:26.041244Z TRACE hyper_util::client::legacy::pool: checkout dropped for ("https", <my_server_ip>)
2024-06-30T06:33:26.071208Z TRACE snxcore::ccc: Reply from server: (CCCserverResponse
    :ResponseHeader (
        :id (2)
        :type (ClientHello)
        :session_id ()
        :return_code (600)
    )
    :ResponseData (
        :protocol_version (
            :protocol_version (100)
            :features (0x1)
        )
        :upgrade_configuration (
            :available_client_version (835000022)
            :client_upgrade_url ("/CSHELL/")
            :upgrade_mode (ask_user)
        )
        :connectivity_info (
            :default_authentication_method (client_decide)
            :client_enabled (true)
            :supported_data_tunnel_protocols (
                : (IPSec)
                : (SSL)
                : (L2TP)
            )
            :connectivity_type (IPSec)
            :server_ip (<my_server_ip>)
            :ipsec_transport (auto_detect)
            :tcpt_port (443)
            :natt_port (4500)
            :connect_with_certificate_url ("/clients/cert/")
            :cookie_name (CPCVPN_SESSION_ID)
            :internal_ca_fingerprint (
                :1 (<redacted>)
            )
        )
        :end_point_security (
            :ics (
                :run_ics (false)
                :ics_base_url ("/clients/ICS/components")
                :ics_version (403006000)
                :ics_upgrade_url ("/clients/ICS/components/icsweb.cab")
                :ics_images_url ("/clients/ICS/components/ICS_images.cab")
                :ics_images_ver (403006000)
                :ics_cab_url ("/clients/ICS/components/cl_ics.cab")
                :ics_cab_version ("996000036
")
            )
        )
        :login_options_data (
            :login_options_list (
                :0 (
                    :id (vpn)
                    :secondary_realm_hash (<redacted>)
                    :display_name (vpn)
                    :show_realm (1)
                    :factors (
                        :0 (
                            :factor_type (user_defined)
                            :securid_card_type ()
                            :certificate_storage_type ()
                            :custom_display_labels ()
                        )
                    )
                )
            )
            :login_options_md5 (<redacted>)
        )
    )
)

2024-06-30T06:33:26.074857Z DEBUG snxcore::tunnel::ipsec::natt: Sending NAT-T probe to <my_server_ip>
2024-06-30T06:33:26.101675Z DEBUG snxcore::tunnel::ipsec::natt: Received NAT-T reply from <my_server_ip>: srcport: 4500, dstport: 4500, hash: 4ae71336e44bf9bf79d2752e234818a5
2024-06-30T06:33:26.105550Z TRACE snxcore::util: Exec: "ip" ["-4", "route", "show", "default"]
2024-06-30T06:33:26.109109Z TRACE snxcore::util: Exec: "ip" ["-4", "-o", "addr", "show", "dev", "enp0s3"]
2024-06-30T06:33:26.111381Z DEBUG isakmp::ikev1::service: Begin SA proposal
2024-06-30T06:33:26.111440Z DEBUG isakmp::transport: Sending ISAKMP message of size 631 to <my_server_ip>:500
2024-06-30T06:33:26.143823Z DEBUG isakmp::transport: Parsing ISAKMP message of size 268
2024-06-30T06:33:26.143879Z TRACE isakmp::payload: Parsing payload: type=SecurityAssociation, size=56, next=VendorId
2024-06-30T06:33:26.143883Z TRACE isakmp::payload: Parsing payload: type=Proposal, size=44, next=None
2024-06-30T06:33:26.143886Z TRACE isakmp::payload: Parsing payload: type=Transform, size=36, next=None
2024-06-30T06:33:26.143893Z TRACE isakmp::payload: Parsing payload: type=VendorId, size=40, next=VendorId
2024-06-30T06:33:26.143894Z TRACE isakmp::payload: Parsing payload: type=VendorId, size=16, next=VendorId
2024-06-30T06:33:26.143896Z TRACE isakmp::payload: Parsing payload: type=VendorId, size=16, next=VendorId
2024-06-30T06:33:26.143897Z TRACE isakmp::payload: Parsing payload: type=VendorId, size=16, next=Notification
2024-06-30T06:33:26.143899Z TRACE isakmp::payload: Parsing payload: type=Notification, size=28, next=Notification
2024-06-30T06:33:26.143901Z TRACE isakmp::payload: Parsing payload: type=Notification, size=40, next=None
2024-06-30T06:33:26.143906Z DEBUG isakmp::ikev1::service: Negotiated SA hash algorithm: Sha
2024-06-30T06:33:26.143908Z DEBUG isakmp::ikev1::service: Negotiated SA key length: 32
2024-06-30T06:33:26.143909Z DEBUG isakmp::ikev1::service: Negotiated SA group: Oakley2
2024-06-30T06:33:26.146538Z DEBUG isakmp::ikev1::service: End SA proposal
2024-06-30T06:33:26.146619Z DEBUG isakmp::ikev1::service: Begin key exchange
2024-06-30T06:33:26.146636Z DEBUG isakmp::transport: Sending ISAKMP message of size 244 to <my_server_ip>:500
2024-06-30T06:33:26.168444Z DEBUG isakmp::transport: Parsing ISAKMP message of size 295
2024-06-30T06:33:26.168530Z TRACE isakmp::payload: Parsing payload: type=KeyExchange, size=128, next=Nonce
2024-06-30T06:33:26.168539Z TRACE isakmp::payload: Parsing payload: type=Nonce, size=20, next=CertificateRequest
2024-06-30T06:33:26.168543Z TRACE isakmp::payload: Parsing payload: type=CertificateRequest, size=30, next=CertificateRequest
2024-06-30T06:33:26.168546Z TRACE isakmp::payload: Parsing payload: type=CertificateRequest, size=1, next=Natd
2024-06-30T06:33:26.168549Z TRACE isakmp::payload: Parsing payload: type=Natd, size=20, next=Natd
2024-06-30T06:33:26.168553Z TRACE isakmp::payload: Parsing payload: type=Natd, size=20, next=Natd
2024-06-30T06:33:26.168555Z TRACE isakmp::payload: Parsing payload: type=Natd, size=20, next=None
2024-06-30T06:33:26.168559Z TRACE isakmp::ikev1::service: Responder's public key length: 128
2024-06-30T06:33:26.168562Z TRACE isakmp::ikev1::service: Responder's nonce length: 20
2024-06-30T06:33:26.169175Z TRACE isakmp::ikev1::service: COOKIE_i: 26d17c96682dd381
2024-06-30T06:33:26.169182Z TRACE isakmp::ikev1::service: SKEYID_e: f8ecfefde4c2c72c414f1cd957dfd6dc6525ba7b62120be34797ee63bca51419
2024-06-30T06:33:26.169185Z DEBUG isakmp::ikev1::service: End key exchange
2024-06-30T06:33:26.169248Z TRACE snxcore::tunnel::ipsec::connector: Authentication blob: (
    :clientType (TRAC)
    :client_logging_data (
        :device_id ("{<redacted>}")
        :os_name ("Windows"))
    :client_mode (secure_connect)
    :oldSessionId ()
    :protocolVersion (100)
    :selected_realm_id (vpn))
2024-06-30T06:33:26.169271Z DEBUG isakmp::ikev1::service: Begin identity protection
2024-06-30T06:33:26.171168Z DEBUG isakmp::transport: Sending ISAKMP message of size 2236 to <my_server_ip>:500
2024-06-30T06:33:28.168803Z TRACE isakmp::transport: Discarding already received message
2024-06-30T06:33:30.167843Z TRACE isakmp::transport: Discarding already received message
2024-06-30T06:33:32.167804Z TRACE isakmp::transport: Discarding already received message
2024-06-30T06:33:34.165936Z TRACE isakmp::transport: Discarding already received message
2024-06-30T06:33:36.165247Z TRACE isakmp::transport: Discarding already received message
2024-06-30T06:33:38.165424Z TRACE isakmp::transport: Discarding already received message
2024-06-30T06:33:42.163464Z TRACE isakmp::transport: Discarding already received message
2024-06-30T06:33:46.162158Z TRACE isakmp::transport: Discarding already received message
2024-06-30T06:33:50.162111Z TRACE isakmp::transport: Discarding already received message
2024-06-30T06:33:54.157979Z TRACE isakmp::transport: Discarding already received message
2024-06-30T06:33:58.157158Z TRACE isakmp::transport: Discarding already received message
2024-06-30T06:34:03.288067Z DEBUG isakmp::transport: Sending ISAKMP message of size 80 to <my_server_ip>:500
Error: deadline has elapsed

The second server has somewhat different output, but fails in the same way:

2024-06-30T06:42:20.186672Z DEBUG snx_rs: >>> Starting snx-rs client version 2.2.4
2024-06-30T06:42:20.189391Z DEBUG snx_rs: Running in standalone mode
2024-06-30T06:42:20.189424Z  WARN snxcore::ccc: Disabling all certificate checks!!!
2024-06-30T06:42:20.212023Z DEBUG snxcore::tunnel::ipsec::natt: Sending NAT-T probe to <my_server_ip>
2024-06-30T06:42:20.238220Z DEBUG snxcore::tunnel::ipsec::natt: Received NAT-T reply from <my_server_ip>: srcport: 4500, dstport: 4500, hash: <redacted>
2024-06-30T06:42:20.241366Z TRACE snxcore::util: Exec: "ip" ["-4", "route", "show", "default"]
2024-06-30T06:42:20.244102Z TRACE snxcore::util: Exec: "ip" ["-4", "-o", "addr", "show", "dev", "enp0s3"]
2024-06-30T06:42:20.246316Z DEBUG isakmp::ikev1::service: Begin SA proposal
2024-06-30T06:42:20.246391Z DEBUG isakmp::transport: Sending ISAKMP message of size 637 to <my_server_ip>:500
2024-06-30T06:42:20.276878Z DEBUG isakmp::transport: Parsing ISAKMP message of size 268
2024-06-30T06:42:20.276936Z TRACE isakmp::payload: Parsing payload: type=SecurityAssociation, size=56, next=VendorId
2024-06-30T06:42:20.276941Z TRACE isakmp::payload: Parsing payload: type=Proposal, size=44, next=None
2024-06-30T06:42:20.276943Z TRACE isakmp::payload: Parsing payload: type=Transform, size=36, next=None
2024-06-30T06:42:20.276951Z TRACE isakmp::payload: Parsing payload: type=VendorId, size=40, next=VendorId
2024-06-30T06:42:20.276954Z TRACE isakmp::payload: Parsing payload: type=VendorId, size=16, next=VendorId
2024-06-30T06:42:20.276955Z TRACE isakmp::payload: Parsing payload: type=VendorId, size=16, next=VendorId
2024-06-30T06:42:20.276956Z TRACE isakmp::payload: Parsing payload: type=VendorId, size=16, next=Notification
2024-06-30T06:42:20.276959Z TRACE isakmp::payload: Parsing payload: type=Notification, size=28, next=Notification
2024-06-30T06:42:20.276960Z TRACE isakmp::payload: Parsing payload: type=Notification, size=40, next=None
2024-06-30T06:42:20.276965Z DEBUG isakmp::ikev1::service: Negotiated SA hash algorithm: Sha
2024-06-30T06:42:20.276967Z DEBUG isakmp::ikev1::service: Negotiated SA key length: 32
2024-06-30T06:42:20.276968Z DEBUG isakmp::ikev1::service: Negotiated SA group: Oakley2
2024-06-30T06:42:20.279972Z DEBUG isakmp::ikev1::service: End SA proposal
2024-06-30T06:42:20.280031Z DEBUG isakmp::ikev1::service: Begin key exchange
2024-06-30T06:42:20.280046Z DEBUG isakmp::transport: Sending ISAKMP message of size 244 to <my_server_ip>:500
2024-06-30T06:42:20.302654Z DEBUG isakmp::transport: Parsing ISAKMP message of size 277
2024-06-30T06:42:20.304917Z TRACE isakmp::payload: Parsing payload: type=KeyExchange, size=128, next=Nonce
2024-06-30T06:42:20.304928Z TRACE isakmp::payload: Parsing payload: type=Nonce, size=20, next=CertificateRequest
2024-06-30T06:42:20.304931Z TRACE isakmp::payload: Parsing payload: type=CertificateRequest, size=36, next=CertificateRequest
2024-06-30T06:42:20.304933Z TRACE isakmp::payload: Parsing payload: type=CertificateRequest, size=1, next=Natd
2024-06-30T06:42:20.304939Z TRACE isakmp::payload: Parsing payload: type=Natd, size=20, next=Natd
2024-06-30T06:42:20.304942Z TRACE isakmp::payload: Parsing payload: type=Natd, size=20, next=None
2024-06-30T06:42:20.304946Z TRACE isakmp::ikev1::service: Responder's public key length: 128
2024-06-30T06:42:20.304948Z TRACE isakmp::ikev1::service: Responder's nonce length: 20
2024-06-30T06:42:20.305410Z TRACE isakmp::ikev1::service: COOKIE_i: 62c4625404094511
2024-06-30T06:42:20.305449Z TRACE isakmp::ikev1::service: SKEYID_e: 7d235e2c9d5a5f1eb52ca881039636804b0267144c1d71f1917c26881eda1abd
2024-06-30T06:42:20.305452Z DEBUG isakmp::ikev1::service: End key exchange
2024-06-30T06:42:20.305511Z TRACE snxcore::tunnel::ipsec::connector: Authentication blob: (
    :clientType (TRAC)
    :client_logging_data (
        :device_id ("{<redacted>}")
        :os_name ("Windows"))
    :client_mode (secure_connect)
    :oldSessionId ()
    :protocolVersion (100)
    :selected_realm_id (vpn))
2024-06-30T06:42:20.305527Z DEBUG isakmp::ikev1::service: Begin identity protection
2024-06-30T06:42:20.305828Z DEBUG isakmp::transport: Sending ISAKMP message of size 2012 to <my_server_ip>:500
2024-06-30T06:42:22.301851Z TRACE isakmp::transport: Discarding already received message
2024-06-30T06:42:24.301494Z TRACE isakmp::transport: Discarding already received message
2024-06-30T06:42:26.303268Z TRACE isakmp::transport: Discarding already received message
2024-06-30T06:42:28.299454Z TRACE isakmp::transport: Discarding already received message
2024-06-30T06:42:30.297463Z TRACE isakmp::transport: Discarding already received message
2024-06-30T06:42:32.297232Z TRACE isakmp::transport: Discarding already received message
2024-06-30T06:42:36.297616Z TRACE isakmp::transport: Discarding already received message
2024-06-30T06:42:40.293851Z TRACE isakmp::transport: Discarding already received message
2024-06-30T06:42:44.291724Z TRACE isakmp::transport: Discarding already received message
2024-06-30T06:42:48.289378Z TRACE isakmp::transport: Discarding already received message
2024-06-30T06:42:52.288710Z TRACE isakmp::transport: Discarding already received message
2024-06-30T06:42:57.295716Z DEBUG isakmp::transport: Sending ISAKMP message of size 80 to <my_server_ip>:500
Error: deadline has elapsed

PS: I am not certain which information can be used to uniquely identify some of the participants, I hope I am not redacting too much away.

ancwrd1 commented 4 months ago

I don't think you pulled recent changes from the branch. There will be much more fields in the client_logging_data.

vlzware commented 4 months ago

Well, I did pulled, but then didn't rebuild the binary because I was so eager to test it :) Excuse my ignorance.

Output first server:

2024-06-30T06:57:51.279031Z DEBUG snx_rs: >>> Starting snx-rs client version 2.2.4
2024-06-30T06:57:51.279071Z DEBUG snx_rs: Running in standalone mode
2024-06-30T06:57:51.279096Z  WARN snxcore::ccc: Disabling all certificate checks!!!
2024-06-30T06:57:51.296802Z TRACE snxcore::ccc: Request to server: (CCCclientRequest
    :RequestData (
        :client_info (
            :client_support_saml (true)
            :client_type (TRAC)
            :client_version (1)))
    :RequestHeader (
        :id (2)
        :type (ClientHello)))
2024-06-30T06:57:51.297037Z TRACE hyper_util::client::legacy::pool: checkout waiting for idle connection: ("https", <my_server_ip>)
2024-06-30T06:57:51.297064Z TRACE hyper_util::client::legacy::connect::http: Http::connect; scheme=Some("https"), host=Some("<my_server_ip>"), port=None
2024-06-30T06:57:51.297070Z DEBUG hyper_util::client::legacy::connect::http: connecting to <my_server_ip>:443
2024-06-30T06:57:51.328565Z DEBUG hyper_util::client::legacy::connect::http: connected to <my_server_ip>:443
2024-06-30T06:57:51.391585Z TRACE hyper_util::client::legacy::client: http1 handshake complete, spawning background dispatcher task
2024-06-30T06:57:51.392151Z TRACE hyper_util::client::legacy::pool: checkout dropped for ("https", <my_server_ip>)
2024-06-30T06:57:51.423954Z TRACE snxcore::ccc: Reply from server: (CCCserverResponse
    :ResponseHeader (
        :id (2)
        :type (ClientHello)
        :session_id ()
        :return_code (600)
    )
    :ResponseData (
        :protocol_version (
            :protocol_version (100)
            :features (0x1)
        )
        :upgrade_configuration (
            :available_client_version (835000022)
            :client_upgrade_url ("/CSHELL/")
            :upgrade_mode (ask_user)
        )
        :connectivity_info (
            :default_authentication_method (client_decide)
            :client_enabled (true)
            :supported_data_tunnel_protocols (
                : (IPSec)
                : (SSL)
                : (L2TP)
            )
            :connectivity_type (IPSec)
            :server_ip (<my_server_ip>)
            :ipsec_transport (auto_detect)
            :tcpt_port (443)
            :natt_port (4500)
            :connect_with_certificate_url ("/clients/cert/")
            :cookie_name (CPCVPN_SESSION_ID)
            :internal_ca_fingerprint (
                :1 (<redacted>)
            )
        )
        :end_point_security (
            :ics (
                :run_ics (false)
                :ics_base_url ("/clients/ICS/components")
                :ics_version (403006000)
                :ics_upgrade_url ("/clients/ICS/components/icsweb.cab")
                :ics_images_url ("/clients/ICS/components/ICS_images.cab")
                :ics_images_ver (403006000)
                :ics_cab_url ("/clients/ICS/components/cl_ics.cab")
                :ics_cab_version ("996000036
")
            )
        )
        :login_options_data (
            :login_options_list (
                :0 (
                    :id (vpn)
                    :secondary_realm_hash (<redacted>)
                    :display_name (vpn)
                    :show_realm (1)
                    :factors (
                        :0 (
                            :factor_type (user_defined)
                            :securid_card_type ()
                            :certificate_storage_type ()
                            :custom_display_labels ()
                        )
                    )
                )
            )
            :login_options_md5 (<redacted>)
        )
    )
)

2024-06-30T06:57:51.424876Z DEBUG snxcore::tunnel::ipsec::natt: Sending NAT-T probe to <my_server_ip>
2024-06-30T06:57:51.452884Z DEBUG snxcore::tunnel::ipsec::natt: Received NAT-T reply from <my_server_ip>: srcport: 4500, dstport: 4500, hash: 4ae71336e44bf9bf79d2752e234818a5
2024-06-30T06:57:51.456407Z TRACE snxcore::util: Exec: "ip" ["-4", "route", "show", "default"]
2024-06-30T06:57:51.458862Z TRACE snxcore::util: Exec: "ip" ["-4", "-o", "addr", "show", "dev", "enp0s3"]
2024-06-30T06:57:51.460982Z DEBUG isakmp::ikev1::service: Begin SA proposal
2024-06-30T06:57:51.461038Z DEBUG isakmp::transport: Sending ISAKMP message of size 631 to <my_server_ip>:500
2024-06-30T06:57:51.489825Z DEBUG isakmp::transport: Parsing ISAKMP message of size 268
2024-06-30T06:57:51.489877Z TRACE isakmp::payload: Parsing payload: type=SecurityAssociation, size=56, next=VendorId
2024-06-30T06:57:51.489881Z TRACE isakmp::payload: Parsing payload: type=Proposal, size=44, next=None
2024-06-30T06:57:51.489883Z TRACE isakmp::payload: Parsing payload: type=Transform, size=36, next=None
2024-06-30T06:57:51.489890Z TRACE isakmp::payload: Parsing payload: type=VendorId, size=40, next=VendorId
2024-06-30T06:57:51.489891Z TRACE isakmp::payload: Parsing payload: type=VendorId, size=16, next=VendorId
2024-06-30T06:57:51.489893Z TRACE isakmp::payload: Parsing payload: type=VendorId, size=16, next=VendorId
2024-06-30T06:57:51.489894Z TRACE isakmp::payload: Parsing payload: type=VendorId, size=16, next=Notification
2024-06-30T06:57:51.489896Z TRACE isakmp::payload: Parsing payload: type=Notification, size=28, next=Notification
2024-06-30T06:57:51.489898Z TRACE isakmp::payload: Parsing payload: type=Notification, size=40, next=None
2024-06-30T06:57:51.489902Z DEBUG isakmp::ikev1::service: Negotiated SA hash algorithm: Sha
2024-06-30T06:57:51.489904Z DEBUG isakmp::ikev1::service: Negotiated SA key length: 32
2024-06-30T06:57:51.489918Z DEBUG isakmp::ikev1::service: Negotiated SA group: Oakley2
2024-06-30T06:57:51.492412Z DEBUG isakmp::ikev1::service: End SA proposal
2024-06-30T06:57:51.492579Z DEBUG isakmp::ikev1::service: Begin key exchange
2024-06-30T06:57:51.492596Z DEBUG isakmp::transport: Sending ISAKMP message of size 244 to <my_server_ip>:500
2024-06-30T06:57:51.517931Z DEBUG isakmp::transport: Parsing ISAKMP message of size 295
2024-06-30T06:57:51.517975Z TRACE isakmp::payload: Parsing payload: type=KeyExchange, size=128, next=Nonce
2024-06-30T06:57:51.517983Z TRACE isakmp::payload: Parsing payload: type=Nonce, size=20, next=CertificateRequest
2024-06-30T06:57:51.517985Z TRACE isakmp::payload: Parsing payload: type=CertificateRequest, size=30, next=CertificateRequest
2024-06-30T06:57:51.517987Z TRACE isakmp::payload: Parsing payload: type=CertificateRequest, size=1, next=Natd
2024-06-30T06:57:51.517988Z TRACE isakmp::payload: Parsing payload: type=Natd, size=20, next=Natd
2024-06-30T06:57:51.517991Z TRACE isakmp::payload: Parsing payload: type=Natd, size=20, next=Natd
2024-06-30T06:57:51.517992Z TRACE isakmp::payload: Parsing payload: type=Natd, size=20, next=None
2024-06-30T06:57:51.517995Z TRACE isakmp::ikev1::service: Responder's public key length: 128
2024-06-30T06:57:51.517997Z TRACE isakmp::ikev1::service: Responder's nonce length: 20
2024-06-30T06:57:51.518382Z TRACE isakmp::ikev1::service: COOKIE_i: d388c7b8581ea451
2024-06-30T06:57:51.518416Z TRACE isakmp::ikev1::service: SKEYID_e: 6d0880928d556c4774ad3c9393028ce7fa060e24412bf7f81e61f7a2871295d7
2024-06-30T06:57:51.518419Z DEBUG isakmp::ikev1::service: End key exchange
2024-06-30T06:57:51.518472Z TRACE snxcore::tunnel::ipsec::connector: Authentication blob: (
    :clientType (TRAC)
    :client_logging_data (
        :client_build_number (986104605)
        :client_name ("Check Point Mobile")
        :client_ver (E87.20)
        :device_id ("{<redacted>}")
        :device_type (PC)
        :mac_address ("<redacted>")
        :machine_name (PC)
        :os_name ("Windows")
        :os_version (11)
        :physical_ip (10.0.2.15))
    :client_mode (secure_connect)
    :oldSessionId ()
    :protocolVersion (100)
    :selected_realm_id (vpn))
2024-06-30T06:57:51.518492Z DEBUG isakmp::ikev1::service: Begin identity protection
2024-06-30T06:57:51.519485Z DEBUG isakmp::transport: Sending ISAKMP message of size 2444 to <my_server_ip>:500
2024-06-30T06:57:53.518166Z TRACE isakmp::transport: Discarding already received message
2024-06-30T06:57:55.516730Z TRACE isakmp::transport: Discarding already received message
2024-06-30T06:57:57.515148Z TRACE isakmp::transport: Discarding already received message
2024-06-30T06:57:59.513756Z TRACE isakmp::transport: Discarding already received message
2024-06-30T06:58:01.513554Z TRACE isakmp::transport: Discarding already received message
2024-06-30T06:58:03.512994Z TRACE isakmp::transport: Discarding already received message
2024-06-30T06:58:07.511834Z TRACE isakmp::transport: Discarding already received message
2024-06-30T06:58:11.510725Z TRACE isakmp::transport: Discarding already received message
2024-06-30T06:58:15.507687Z TRACE isakmp::transport: Discarding already received message
2024-06-30T06:58:19.505002Z TRACE isakmp::transport: Discarding already received message
2024-06-30T06:58:23.503313Z TRACE isakmp::transport: Discarding already received message
2024-06-30T06:58:28.516058Z DEBUG isakmp::transport: Sending ISAKMP message of size 80 to <my_server_ip>:500
Error: deadline has elapsed

Output second server:

2024-06-30T07:01:38.946107Z DEBUG snx_rs: >>> Starting snx-rs client version 2.2.4
2024-06-30T07:01:38.946158Z DEBUG snx_rs: Running in standalone mode
2024-06-30T07:01:38.946199Z  WARN snxcore::ccc: Disabling all certificate checks!!!
2024-06-30T07:01:38.967269Z DEBUG snxcore::tunnel::ipsec::natt: Sending NAT-T probe to <my_server_ip>
2024-06-30T07:01:38.993861Z DEBUG snxcore::tunnel::ipsec::natt: Received NAT-T reply from <my_server_ip>: srcport: 4500, dstport: 4500, hash: 4ae71336e44bf9bf79d2752e234818a5
2024-06-30T07:01:38.996880Z TRACE snxcore::util: Exec: "ip" ["-4", "route", "show", "default"]
2024-06-30T07:01:38.999747Z TRACE snxcore::util: Exec: "ip" ["-4", "-o", "addr", "show", "dev", "enp0s3"]
2024-06-30T07:01:39.002156Z DEBUG isakmp::ikev1::service: Begin SA proposal
2024-06-30T07:01:39.002223Z DEBUG isakmp::transport: Sending ISAKMP message of size 637 to <my_server_ip>:500
2024-06-30T07:01:39.028790Z DEBUG isakmp::transport: Parsing ISAKMP message of size 268
2024-06-30T07:01:39.028838Z TRACE isakmp::payload: Parsing payload: type=SecurityAssociation, size=56, next=VendorId
2024-06-30T07:01:39.028843Z TRACE isakmp::payload: Parsing payload: type=Proposal, size=44, next=None
2024-06-30T07:01:39.028845Z TRACE isakmp::payload: Parsing payload: type=Transform, size=36, next=None
2024-06-30T07:01:39.028860Z TRACE isakmp::payload: Parsing payload: type=VendorId, size=40, next=VendorId
2024-06-30T07:01:39.028862Z TRACE isakmp::payload: Parsing payload: type=VendorId, size=16, next=VendorId
2024-06-30T07:01:39.028864Z TRACE isakmp::payload: Parsing payload: type=VendorId, size=16, next=VendorId
2024-06-30T07:01:39.028865Z TRACE isakmp::payload: Parsing payload: type=VendorId, size=16, next=Notification
2024-06-30T07:01:39.028867Z TRACE isakmp::payload: Parsing payload: type=Notification, size=28, next=Notification
2024-06-30T07:01:39.028869Z TRACE isakmp::payload: Parsing payload: type=Notification, size=40, next=None
2024-06-30T07:01:39.028874Z DEBUG isakmp::ikev1::service: Negotiated SA hash algorithm: Sha
2024-06-30T07:01:39.028876Z DEBUG isakmp::ikev1::service: Negotiated SA key length: 32
2024-06-30T07:01:39.028877Z DEBUG isakmp::ikev1::service: Negotiated SA group: Oakley2
2024-06-30T07:01:39.031699Z DEBUG isakmp::ikev1::service: End SA proposal
2024-06-30T07:01:39.031743Z DEBUG isakmp::ikev1::service: Begin key exchange
2024-06-30T07:01:39.031756Z DEBUG isakmp::transport: Sending ISAKMP message of size 244 to <my_server_ip>:500
2024-06-30T07:01:39.053491Z DEBUG isakmp::transport: Parsing ISAKMP message of size 277
2024-06-30T07:01:39.053551Z TRACE isakmp::payload: Parsing payload: type=KeyExchange, size=128, next=Nonce
2024-06-30T07:01:39.053558Z TRACE isakmp::payload: Parsing payload: type=Nonce, size=20, next=CertificateRequest
2024-06-30T07:01:39.053561Z TRACE isakmp::payload: Parsing payload: type=CertificateRequest, size=36, next=CertificateRequest
2024-06-30T07:01:39.053563Z TRACE isakmp::payload: Parsing payload: type=CertificateRequest, size=1, next=Natd
2024-06-30T07:01:39.053565Z TRACE isakmp::payload: Parsing payload: type=Natd, size=20, next=Natd
2024-06-30T07:01:39.053567Z TRACE isakmp::payload: Parsing payload: type=Natd, size=20, next=None
2024-06-30T07:01:39.053570Z TRACE isakmp::ikev1::service: Responder's public key length: 128
2024-06-30T07:01:39.053572Z TRACE isakmp::ikev1::service: Responder's nonce length: 20
2024-06-30T07:01:39.053989Z TRACE isakmp::ikev1::service: COOKIE_i: d343afbe83369ef2
2024-06-30T07:01:39.053992Z TRACE isakmp::ikev1::service: SKEYID_e: 52b999e073325b6797501b1cd1fdd86821440a1b1781af6b7202263bc95ad914
2024-06-30T07:01:39.053994Z DEBUG isakmp::ikev1::service: End key exchange
2024-06-30T07:01:39.054037Z TRACE snxcore::tunnel::ipsec::connector: Authentication blob: (
    :clientType (TRAC)
    :client_logging_data (
        :client_build_number (986104605)
        :client_name ("Check Point Mobile")
        :client_ver (E87.20)
        :device_id ("{<redacted>}")
        :device_type (PC)
        :mac_address ("<redacted>")
        :machine_name (PC)
        :os_name ("Windows")
        :os_version (11)
        :physical_ip (10.0.2.15))
    :client_mode (secure_connect)
    :oldSessionId ()
    :protocolVersion (100)
    :selected_realm_id (vpn))
2024-06-30T07:01:39.054071Z DEBUG isakmp::ikev1::service: Begin identity protection
2024-06-30T07:01:39.054350Z DEBUG isakmp::transport: Sending ISAKMP message of size 2236 to <my_server_ip>:500
2024-06-30T07:01:41.054113Z TRACE isakmp::transport: Discarding already received message
2024-06-30T07:01:43.052668Z TRACE isakmp::transport: Discarding already received message
2024-06-30T07:01:45.051501Z TRACE isakmp::transport: Discarding already received message
2024-06-30T07:01:47.051586Z TRACE isakmp::transport: Discarding already received message
2024-06-30T07:01:49.050195Z TRACE isakmp::transport: Discarding already received message
2024-06-30T07:01:51.048737Z TRACE isakmp::transport: Discarding already received message
2024-06-30T07:01:55.047421Z TRACE isakmp::transport: Discarding already received message
2024-06-30T07:01:59.044913Z TRACE isakmp::transport: Discarding already received message
2024-06-30T07:02:03.042543Z TRACE isakmp::transport: Discarding already received message
2024-06-30T07:02:07.041312Z TRACE isakmp::transport: Discarding already received message
2024-06-30T07:02:11.039474Z TRACE isakmp::transport: Discarding already received message
2024-06-30T07:02:16.126299Z DEBUG isakmp::transport: Sending ISAKMP message of size 80 to <my_server_ip>:500
Error: deadline has elapsed
ancwrd1 commented 4 months ago

Ok, I have added another field, now the request looks exactly like the one sent by my Windows client.

ancwrd1 commented 4 months ago

Another thing to check: in the log file (trac.log) of your Windows client, find the message similar to this:

Authentication blob: (
    :clientType (TRAC)
    :client_logging_data (
        :client_build_number (986104605)
        :client_name ("Check Point Mobile")
        :client_ver (E87.20)
        :device_id ("{<redacted>}")
        :device_type (PC)
        :mac_address ("<redacted>")
        :machine_name (PC)
        :os_name ("Windows")
        :os_version (11)
        :physical_ip (10.0.2.15))
    :client_mode (secure_connect)
    :oldSessionId ()
    :protocolVersion (100)
    :selected_realm_id (vpn))

And check is there any visible difference.

vlzware commented 4 months ago

Unfortunately, this didn't help either.

2024-06-30T09:07:49.775602Z DEBUG snx_rs: >>> Starting snx-rs client version 2.2.4
2024-06-30T09:07:49.775650Z DEBUG snx_rs: Running in standalone mode
2024-06-30T09:07:49.775712Z  WARN snxcore::ccc: Disabling all certificate checks!!!
2024-06-30T09:07:49.795900Z TRACE snxcore::ccc: Request to server: (CCCclientRequest
    :RequestData (
        :client_info (
            :client_support_saml (true)
            :client_type (TRAC)
            :client_version (1)))
    :RequestHeader (
        :id (2)
        :type (ClientHello)))
2024-06-30T09:07:49.796051Z TRACE hyper_util::client::legacy::pool: checkout waiting for idle connection: ("https", <my_server_ip>)
2024-06-30T09:07:49.803234Z TRACE hyper_util::client::legacy::connect::http: Http::connect; scheme=Some("https"), host=Some("<my_server_ip>"), port=None
2024-06-30T09:07:49.803285Z DEBUG hyper_util::client::legacy::connect::http: connecting to <my_server_ip>:443
2024-06-30T09:07:49.831744Z DEBUG hyper_util::client::legacy::connect::http: connected to <my_server_ip>:443
2024-06-30T09:07:49.906847Z TRACE hyper_util::client::legacy::client: http1 handshake complete, spawning background dispatcher task
2024-06-30T09:07:49.907477Z TRACE hyper_util::client::legacy::pool: checkout dropped for ("https", <my_server_ip>)
2024-06-30T09:07:49.936951Z TRACE snxcore::ccc: Reply from server: (CCCserverResponse
    :ResponseHeader (
        :id (2)
        :type (ClientHello)
        :session_id ()
        :return_code (600)
    )
    :ResponseData (
        :protocol_version (
            :protocol_version (100)
            :features (0x1)
        )
        :upgrade_configuration (
            :available_client_version (835000022)
            :client_upgrade_url ("/CSHELL/")
            :upgrade_mode (ask_user)
        )
        :connectivity_info (
            :default_authentication_method (client_decide)
            :client_enabled (true)
            :supported_data_tunnel_protocols (
                : (IPSec)
                : (SSL)
                : (L2TP)
            )
            :connectivity_type (IPSec)
            :server_ip (<my_server_ip>)
            :ipsec_transport (auto_detect)
            :tcpt_port (443)
            :natt_port (4500)
            :connect_with_certificate_url ("/clients/cert/")
            :cookie_name (CPCVPN_SESSION_ID)
            :internal_ca_fingerprint (
                :1 (<redacted>)
            )
        )
        :end_point_security (
            :ics (
                :run_ics (false)
                :ics_base_url ("/clients/ICS/components")
                :ics_version (403006000)
                :ics_upgrade_url ("/clients/ICS/components/icsweb.cab")
                :ics_images_url ("/clients/ICS/components/ICS_images.cab")
                :ics_images_ver (403006000)
                :ics_cab_url ("/clients/ICS/components/cl_ics.cab")
                :ics_cab_version ("996000036
")
            )
        )
        :login_options_data (
            :login_options_list (
                :0 (
                    :id (vpn)
                    :secondary_realm_hash (<redacted>)
                    :display_name (vpn)
                    :show_realm (1)
                    :factors (
                        :0 (
                            :factor_type (user_defined)
                            :securid_card_type ()
                            :certificate_storage_type ()
                            :custom_display_labels ()
                        )
                    )
                )
            )
            :login_options_md5 (<redacted>)
        )
    )
)

2024-06-30T09:07:49.938036Z DEBUG snxcore::tunnel::ipsec::natt: Sending NAT-T probe to <my_server_ip>
2024-06-30T09:07:49.969211Z DEBUG snxcore::tunnel::ipsec::natt: Received NAT-T reply from <my_server_ip>: srcport: 4500, dstport: 4500, hash: 4ae71336e44bf9bf79d2752e234818a5
2024-06-30T09:07:49.972190Z  WARN snxcore::ccc: Disabling all certificate checks!!!
2024-06-30T09:07:49.989182Z TRACE snxcore::ccc: Request to server: (CCCclientRequest
    :RequestData (
        :client_info (
            :client_support_saml (true)
            :client_type (TRAC)
            :client_version (1)))
    :RequestHeader (
        :id (3)
        :type (ClientHello)))
2024-06-30T09:07:49.989304Z TRACE hyper_util::client::legacy::pool: checkout waiting for idle connection: ("https", <my_server_ip>)
2024-06-30T09:07:49.989315Z TRACE hyper_util::client::legacy::connect::http: Http::connect; scheme=Some("https"), host=Some("<my_server_ip>"), port=None
2024-06-30T09:07:49.989325Z DEBUG hyper_util::client::legacy::connect::http: connecting to <my_server_ip>:443
2024-06-30T09:07:50.014978Z DEBUG hyper_util::client::legacy::connect::http: connected to <my_server_ip>:443
2024-06-30T09:07:50.079985Z TRACE hyper_util::client::legacy::client: http1 handshake complete, spawning background dispatcher task
2024-06-30T09:07:50.080588Z TRACE hyper_util::client::legacy::pool: checkout dropped for ("https", <my_server_ip>)
2024-06-30T09:07:50.109380Z TRACE snxcore::ccc: Reply from server: (CCCserverResponse
    :ResponseHeader (
        :id (3)
        :type (ClientHello)
        :session_id ()
        :return_code (600)
    )
    :ResponseData (
        :protocol_version (
            :protocol_version (100)
            :features (0x1)
        )
        :upgrade_configuration (
            :available_client_version (835000022)
            :client_upgrade_url ("/CSHELL/")
            :upgrade_mode (ask_user)
        )
        :connectivity_info (
            :default_authentication_method (client_decide)
            :client_enabled (true)
            :supported_data_tunnel_protocols (
                : (IPSec)
                : (SSL)
                : (L2TP)
            )
            :connectivity_type (IPSec)
            :server_ip (<my_server_ip>)
            :ipsec_transport (auto_detect)
            :tcpt_port (443)
            :natt_port (4500)
            :connect_with_certificate_url ("/clients/cert/")
            :cookie_name (CPCVPN_SESSION_ID)
            :internal_ca_fingerprint (
                :1 (<redacted>)
            )
        )
        :end_point_security (
            :ics (
                :run_ics (false)
                :ics_base_url ("/clients/ICS/components")
                :ics_version (403006000)
                :ics_upgrade_url ("/clients/ICS/components/icsweb.cab")
                :ics_images_url ("/clients/ICS/components/ICS_images.cab")
                :ics_images_ver (403006000)
                :ics_cab_url ("/clients/ICS/components/cl_ics.cab")
                :ics_cab_version ("996000036
")
            )
        )
        :login_options_data (
            :login_options_list (
                :0 (
                    :id (vpn)
                    :secondary_realm_hash (<redacted>)
                    :display_name (vpn)
                    :show_realm (1)
                    :factors (
                        :0 (
                            :factor_type (user_defined)
                            :securid_card_type ()
                            :certificate_storage_type ()
                            :custom_display_labels ()
                        )
                    )
                )
            )
            :login_options_md5 (<redacted>)
        )
    )
)

2024-06-30T09:07:50.110241Z TRACE snxcore::util: Exec: "ip" ["-4", "route", "show", "default"]
2024-06-30T09:07:50.112778Z TRACE snxcore::util: Exec: "ip" ["-4", "-o", "addr", "show", "dev", "enp0s3"]
2024-06-30T09:07:50.115110Z DEBUG isakmp::ikev1::service: Begin SA proposal
2024-06-30T09:07:50.115181Z DEBUG isakmp::transport: Sending ISAKMP message of size 631 to <my_server_ip>:500
2024-06-30T09:07:50.145609Z DEBUG isakmp::transport: Parsing ISAKMP message of size 268
2024-06-30T09:07:50.145655Z TRACE isakmp::payload: Parsing payload: type=SecurityAssociation, size=56, next=VendorId
2024-06-30T09:07:50.145660Z TRACE isakmp::payload: Parsing payload: type=Proposal, size=44, next=None
2024-06-30T09:07:50.145662Z TRACE isakmp::payload: Parsing payload: type=Transform, size=36, next=None
2024-06-30T09:07:50.145668Z TRACE isakmp::payload: Parsing payload: type=VendorId, size=40, next=VendorId
2024-06-30T09:07:50.145670Z TRACE isakmp::payload: Parsing payload: type=VendorId, size=16, next=VendorId
2024-06-30T09:07:50.145672Z TRACE isakmp::payload: Parsing payload: type=VendorId, size=16, next=VendorId
2024-06-30T09:07:50.145673Z TRACE isakmp::payload: Parsing payload: type=VendorId, size=16, next=Notification
2024-06-30T09:07:50.145675Z TRACE isakmp::payload: Parsing payload: type=Notification, size=28, next=Notification
2024-06-30T09:07:50.145677Z TRACE isakmp::payload: Parsing payload: type=Notification, size=40, next=None
2024-06-30T09:07:50.145695Z DEBUG isakmp::ikev1::service: Negotiated SA hash algorithm: Sha
2024-06-30T09:07:50.145697Z DEBUG isakmp::ikev1::service: Negotiated SA key length: 32
2024-06-30T09:07:50.145698Z DEBUG isakmp::ikev1::service: Negotiated SA group: Oakley2
2024-06-30T09:07:50.148162Z DEBUG isakmp::ikev1::service: End SA proposal
2024-06-30T09:07:50.148373Z DEBUG isakmp::ikev1::service: Begin key exchange
2024-06-30T09:07:50.148395Z DEBUG isakmp::transport: Sending ISAKMP message of size 244 to <my_server_ip>:500
2024-06-30T09:07:50.174068Z DEBUG isakmp::transport: Parsing ISAKMP message of size 295
2024-06-30T09:07:50.174149Z TRACE isakmp::payload: Parsing payload: type=KeyExchange, size=128, next=Nonce
2024-06-30T09:07:50.174156Z TRACE isakmp::payload: Parsing payload: type=Nonce, size=20, next=CertificateRequest
2024-06-30T09:07:50.174159Z TRACE isakmp::payload: Parsing payload: type=CertificateRequest, size=30, next=CertificateRequest
2024-06-30T09:07:50.174161Z TRACE isakmp::payload: Parsing payload: type=CertificateRequest, size=1, next=Natd
2024-06-30T09:07:50.174162Z TRACE isakmp::payload: Parsing payload: type=Natd, size=20, next=Natd
2024-06-30T09:07:50.174165Z TRACE isakmp::payload: Parsing payload: type=Natd, size=20, next=Natd
2024-06-30T09:07:50.174167Z TRACE isakmp::payload: Parsing payload: type=Natd, size=20, next=None
2024-06-30T09:07:50.174170Z TRACE isakmp::ikev1::service: Responder's public key length: 128
2024-06-30T09:07:50.174172Z TRACE isakmp::ikev1::service: Responder's nonce length: 20
2024-06-30T09:07:50.174925Z TRACE isakmp::ikev1::service: COOKIE_i: c4354ea7001a9d4e
2024-06-30T09:07:50.174935Z TRACE isakmp::ikev1::service: SKEYID_e: 8eba3990cb2bd254366fb54ddd58b7a9d7df4ffec40a87cd7db24da01e598c01
2024-06-30T09:07:50.174937Z DEBUG isakmp::ikev1::service: End key exchange
2024-06-30T09:07:50.174979Z TRACE snxcore::tunnel::ipsec::connector: Authentication blob: (
    :clientType (TRAC)
    :client_logging_data (
        :client_build_number (986104605)
        :client_name ("Check Point Mobile")
        :client_ver (E87.20)
        :device_id ("{<redacted>}")
        :device_type (PC)
        :mac_address ("<redacted>")
        :machine_name (PC)
        :os_name ("Windows")
        :os_version (11)
        :physical_ip (10.0.2.15))
    :client_mode (secure_connect)
    :oldSessionId ()
    :protocolVersion (100)
    :secondary_realm_hash (<redacted>)
    :selected_realm_id (vpn))
2024-06-30T09:07:50.175008Z DEBUG isakmp::ikev1::service: Begin identity protection
2024-06-30T09:07:50.175890Z DEBUG isakmp::transport: Sending ISAKMP message of size 2508 to <my_server_ip>:500
2024-06-30T09:07:52.171659Z TRACE isakmp::transport: Discarding already received message
2024-06-30T09:07:54.172398Z TRACE isakmp::transport: Discarding already received message
2024-06-30T09:07:56.170882Z TRACE isakmp::transport: Discarding already received message
2024-06-30T09:07:58.171914Z TRACE isakmp::transport: Discarding already received message
2024-06-30T09:08:00.171255Z TRACE isakmp::transport: Discarding already received message
2024-06-30T09:08:02.169404Z TRACE isakmp::transport: Discarding already received message
2024-06-30T09:08:06.166896Z TRACE isakmp::transport: Discarding already received message
2024-06-30T09:08:10.164558Z TRACE isakmp::transport: Discarding already received message
2024-06-30T09:08:14.162950Z TRACE isakmp::transport: Discarding already received message
2024-06-30T09:08:18.161688Z TRACE isakmp::transport: Discarding already received message
2024-06-30T09:08:22.158590Z TRACE isakmp::transport: Discarding already received message
2024-06-30T09:08:27.160504Z DEBUG isakmp::transport: Sending ISAKMP message of size 80 to <my_server_ip>:500
Error: deadline has elapsed

On the second server I even got an SSL error:

2024-06-30T09:15:59.693694Z DEBUG snx_rs: >>> Starting snx-rs client version 2.2.4
2024-06-30T09:15:59.693754Z DEBUG snx_rs: Running in standalone mode
2024-06-30T09:15:59.693788Z  WARN snxcore::ccc: Disabling all certificate checks!!!
2024-06-30T09:15:59.717764Z DEBUG snxcore::tunnel::ipsec::natt: Sending NAT-T probe to <my_server_ip>
2024-06-30T09:15:59.743127Z DEBUG snxcore::tunnel::ipsec::natt: Received NAT-T reply from <my_server_ip>: srcport: 4500, dstport: 4500, hash: <redacted>
2024-06-30T09:15:59.747341Z  WARN snxcore::ccc: Disabling all certificate checks!!!
Error: builder error

Caused by:
    error:0A00018F:SSL routines:SSL_CTX_use_certificate:ee key too small:../ssl/ssl_rsa.c:221:

In regards of the "Authentication blob" here is what I found in trac.log. This is from the VM at work:

[ 3612 4036][28 Jun  9:08:34][IKE] create_MM5(certificates authentication): authentication blob (
    :clientType (TRAC)
    :oldSessionId ()
    :protocolVersion (100)
    :client_mode (endpoint_security)
    :selected_realm_id (vpn)
    :secondary_realm_hash (<redacted>)
    :client_logging_data (
        :device_id ("{<redacted>}")
        :client_name ("Endpoint Security VPN")
        :client_ver (E86.40)
        :client_build_number (986103912)
        :device_type (PC)
        :os_name (Windows)
        :os_version (10)
        :os_edition (Professional)
        :os_service_pack ()
        :os_build (19045)
        :os_bits (64bit)
        :machine_domain (<redacted>)
        :machine_name (<redacted>)
        :physical_ip (<redacted>)
        :mac_address ("<redacted>,<redacted>,<redacted>,<redacted>,<redacted>,<redacted>")
    )
)

and this is from my local VM:

[ 3132 3604][30 Jun 11:19:10][IKE] create_MM5(certificates authentication): authentication blob (
    :clientType (TRAC)
    :oldSessionId ()
    :protocolVersion (100)
    :client_mode (secure_remote)
    :selected_realm_id (vpn)
    :secondary_realm_hash (<redacted>)
    :client_logging_data (
        :device_id ("{<redacted>}")
        :client_name (SecuRemote)
        :client_ver (E86.80)
        :client_build_number (986104309)
        :device_type (PC)
        :os_name (Windows)
        :os_version (11)
        :os_edition (Professional)
        :os_service_pack ()
        :os_build (22631)
        :os_bits (64bit)
        :machine_domain ()
        :machine_name (Win11)
        :physical_ip (10.0.2.15)
        :mac_address ("<redacted>,<redacted>")
    )
)

Edit: to clarify a bit - these are both Windows VMs with installed CheckPoint VPN clients and they both connect successfully.

ancwrd1 commented 4 months ago

Yeah I am not sure what else can I do here, may be you can try playing with various parameters of the AuthenticationRealm and ClientLoggingData in the source code to bring them closer to what your Windows client sends. For example replace "secure_connect" with "endpoint_security" (in the params.rs).

vlzware commented 4 months ago

No worries, you spend a lot of time already - I would try to play alone a bit and will report if I manage to achieve something.

An interesting observation is that the fields in both Windows clients are ordered in the same way but we send the fields sorted in an alphabetical order - could this be an issue - the server expecting the same order of fields?

ancwrd1 commented 4 months ago

Field order shouldn't matter, as well as whitespace formatting.

ancwrd1 commented 4 months ago

I have found an issue in the IPSec code, related to certificate authentication. Could you please try the latest main branch and see if it resolves the problem?

vlzware commented 4 months ago

Still no fun. At least the SSL error on my second server is gone. Now both go through the same and at the end is the Error: deadline has elapsed Currently on: 4e4b866 (HEAD -> main, origin/main, origin/HEAD) Updated isakmp dependency

ancwrd1 commented 4 months ago

Would be interesting to look in the trac.log from your Windows client, few seconds before and after that "Authentication blob" with client logging.

In particular I am interested in all lines which contain CLIPS::IKElogging category.

ancwrd1 commented 1 month ago

@Dennis-1978 please open a separate issue for this.