Crypto Failure in ziti-edge-tunnel

janst · September 8, 2023, 12:45pm

Hi there,

I am currently experiencing issues with my OpenZiti setup. I configured a service within the OpenZiti ZAC to allow accessing an webpage remotely from my Windows machine and also installed WSL. This webpage is running on a bare metal Linux machine (Docker container with exposed port 80), here I have ziti-edge-tunnel for Linux installed.

The issue is now that randomly, when I try to access this webpage through OpenZiti, I get this error in the logs of the machine, that this actually hosting the webpage and running a Linux ziti-edge-tunnel:

Sep 08 13:36:21 service-vm ziti-edge-tunnel[137954]: (137954)[      857.489]   ERROR ziti-sdk:connect.c:845 conn_inbound_data_msg() /github/workspace/build/_deps/ziti-sdk-c-src/library/connect.c:836 - crypto_secretstream_xchacha20poly1305_pull(&conn->crypt_i, plain_text, &plain_len, &tag, msg->body, msg->header.body_len, NULL, 0) => -1 (Unknown error -1)
Sep 08 13:36:21 service-vm ziti-edge-tunnel[137954]: (137954)[      857.489]    WARN ziti-sdk:conn_bridge.c:303 on_ziti_data() br[0.27] closing bridge due to error: -23(crypto failure)
Sep 08 13:37:04 service-vm ziti-edge-tunnel[137954]: (137954)[      900.569]    WARN ziti-sdk:channel.c:489 dispatch_message() ch[0] received message without conn_id or for unknown connection ct[ED72] conn_id[27]
Sep 08 13:37:06 service-vm ziti-edge-tunnel[137954]: (137954)[      902.587]    WARN ziti-sdk:channel.c:489 dispatch_message() ch[0] received message without conn_id or for unknown connection ct[ED72] conn_id[22]
Sep 08 13:37:13 service-vm ziti-edge-tunnel[137954]: (137954)[      910.069]   ERROR ziti-sdk:connect.c:845 conn_inbound_data_msg() /github/workspace/build/_deps/ziti-sdk-c-src/library/connect.c:836 - crypto_secretstream_xchacha20poly1305_pull(&conn->crypt_i, plain_text, &plain_len, &tag, msg->body, msg->header.body_len, NULL, 0) => -1 (Unknown error -1)
Sep 08 13:37:13 service-vm ziti-edge-tunnel[137954]: (137954)[      910.069]    WARN ziti-sdk:conn_bridge.c:303 on_ziti_data() br[0.28] closing bridge due to error: -23(crypto failure)

How is this visible to a user then ?
-> The webpage does just not load in the browser or only after random retries.

This happens mostly when I have just reconfigured my Intercept config for this particular service, but also randomly from time to time. What I have noticed is that is seems to happen more often, when I try to reach the webpage from my windows client, than directly from the wsl ...

Here is my configuration of this setup:

Service

Host_HTTP

{
    "address":"127.0.0.1",
    "allowedSourceAddresses":[
    ],
    "listenOptions":{
      "bindUsingEdgeIdentity":false,
      "identity":"",
      "precedence":"default"
    },
    "port":80,
    "protocol":"tcp"
  }

Intercept-IPC-ALPS-HTTP

{
  "addresses":[
    "my-test.ziti"],
  "dialOptions":{
    "identity":""
  },
  "portRanges":[
    {
      "high":30000,
      "low":15000
    }],
  "protocols":[
    "tcp"],
  "sourceIp":""
}

Bind_Policy

Dial_Policy

ziti-edge-tunnel logs (linux) "IPC-ALPS"

Sep 08 13:22:03 service-vm systemd[1]: Started Ziti Edge Tunnel.
Sep 08 13:22:03 service-vm ziti-edge-tunnel[137954]: (137954)[        0.000]    INFO ziti-sdk:utils.c:188 ziti_log_set_level() set log level: root=6/TRACE
Sep 08 13:22:03 service-vm ziti-edge-tunnel[137954]: (137954)[        0.000]   TRACE ziti-edge-tunnel:instance-config.c:77 load_tunnel_status_from_file() config path exists at /var/lib/ziti
Sep 08 13:22:03 service-vm ziti-edge-tunnel[137954]: (137954)[        0.000]    INFO ziti-edge-tunnel:instance-config.c:86 load_tunnel_status_from_file() Loading config file from /var/lib/ziti/config.json
Sep 08 13:30:09 service-vm ziti-edge-tunnel[137954]: (137954)[      485.138]   ERROR ziti-sdk:connect.c:845 conn_inbound_data_msg() /github/workspace/build/_deps/ziti-sdk-c-src/library/connect.c:836 - crypto_secretstream_xchacha20poly1305_pull(&conn->crypt_i, plain_text, &plain_len, &tag, msg->body, msg->header.body_len, NULL, 0) => -1 (Unknown error -1)
Sep 08 13:30:09 service-vm ziti-edge-tunnel[137954]: (137954)[      485.138]    WARN ziti-sdk:conn_bridge.c:303 on_ziti_data() br[0.13] closing bridge due to error: -23(crypto failure)
Sep 08 13:31:22 service-vm ziti-edge-tunnel[137954]: (137954)[      558.229]    WARN ziti-sdk:channel.c:489 dispatch_message() ch[0] received message without conn_id or for unknown connection ct[ED72] conn_id[13]
Sep 08 13:32:08 service-vm ziti-edge-tunnel[137954]: (137954)[      604.845]   ERROR ziti-sdk:connect.c:845 conn_inbound_data_msg() /github/workspace/build/_deps/ziti-sdk-c-src/library/connect.c:836 - crypto_secretstream_xchacha20poly1305_pull(&conn->crypt_i, plain_text, &plain_len, &tag, msg->body, msg->header.body_len, NULL, 0) => -1 (Unknown error -1)
Sep 08 13:32:08 service-vm ziti-edge-tunnel[137954]: (137954)[      604.845]    WARN ziti-sdk:conn_bridge.c:303 on_ziti_data() br[0.16] closing bridge due to error: -23(crypto failure)
Sep 08 13:33:05 service-vm ziti-edge-tunnel[137954]: (137954)[      661.285]    WARN ziti-sdk:channel.c:489 dispatch_message() ch[0] received message without conn_id or for unknown connection ct[ED72] conn_id[16]
Sep 08 13:35:45 service-vm ziti-edge-tunnel[137954]: (137954)[      821.890]   ERROR ziti-sdk:connect.c:845 conn_inbound_data_msg() /github/workspace/build/_deps/ziti-sdk-c-src/library/connect.c:836 - crypto_secretstream_xchacha20poly1305_pull(&conn->crypt_i, plain_text, &plain_len, &tag, msg->body, msg->header.body_len, NULL, 0) => -1 (Unknown error -1)
Sep 08 13:35:45 service-vm ziti-edge-tunnel[137954]: (137954)[      821.890]    WARN ziti-sdk:conn_bridge.c:303 on_ziti_data() br[0.21] closing bridge due to error: -23(crypto failure)
Sep 08 13:35:58 service-vm ziti-edge-tunnel[137954]: (137954)[      834.663]    WARN ziti-sdk:channel.c:489 dispatch_message() ch[0] received message without conn_id or for unknown connection ct[ED72] conn_id[21]
Sep 08 13:35:59 service-vm ziti-edge-tunnel[137954]: (137954)[      835.744]   ERROR ziti-sdk:connect.c:845 conn_inbound_data_msg() /github/workspace/build/_deps/ziti-sdk-c-src/library/connect.c:836 - crypto_secretstream_xchacha20poly1305_pull(&conn->crypt_i, plain_text, &plain_len, &tag, msg->body, msg->header.body_len, NULL, 0) => -1 (Unknown error -1)
Sep 08 13:35:59 service-vm ziti-edge-tunnel[137954]: (137954)[      835.744]    WARN ziti-sdk:conn_bridge.c:303 on_ziti_data() br[0.22] closing bridge due to error: -23(crypto failure)
Sep 08 13:36:07 service-vm ziti-edge-tunnel[137954]: (137954)[      843.918]   ERROR ziti-sdk:connect.c:845 conn_inbound_data_msg() /github/workspace/build/_deps/ziti-sdk-c-src/library/connect.c:836 - crypto_secretstream_xchacha20poly1305_pull(&conn->crypt_i, plain_text, &plain_len, &tag, msg->body, msg->header.body_len, NULL, 0) => -1 (Unknown error -1)
Sep 08 13:36:07 service-vm ziti-edge-tunnel[137954]: (137954)[      843.918]    WARN ziti-sdk:conn_bridge.c:303 on_ziti_data() br[0.24] closing bridge due to error: -23(crypto failure)
Sep 08 13:36:14 service-vm ziti-edge-tunnel[137954]: (137954)[      850.245]   ERROR ziti-sdk:connect.c:845 conn_inbound_data_msg() /github/workspace/build/_deps/ziti-sdk-c-src/library/connect.c:836 - crypto_secretstream_xchacha20poly1305_pull(&conn->crypt_i, plain_text, &plain_len, &tag, msg->body, msg->header.body_len, NULL, 0) => -1 (Unknown error -1)
Sep 08 13:36:14 service-vm ziti-edge-tunnel[137954]: (137954)[      850.245]    WARN ziti-sdk:conn_bridge.c:303 on_ziti_data() br[0.25] closing bridge due to error: -23(crypto failure)
Sep 08 13:36:20 service-vm ziti-edge-tunnel[137954]: (137954)[      856.115]    WARN ziti-sdk:channel.c:489 dispatch_message() ch[0] received message without conn_id or for unknown connection ct[ED72] conn_id[25]
Sep 08 13:36:20 service-vm ziti-edge-tunnel[137954]: (137954)[      856.250]    WARN ziti-sdk:channel.c:489 dispatch_message() ch[0] received message without conn_id or for unknown connection ct[ED72] conn_id[24]
Sep 08 13:36:21 service-vm ziti-edge-tunnel[137954]: (137954)[      857.489]   ERROR ziti-sdk:connect.c:845 conn_inbound_data_msg() /github/workspace/build/_deps/ziti-sdk-c-src/library/connect.c:836 - crypto_secretstream_xchacha20poly1305_pull(&conn->crypt_i, plain_text, &plain_len, &tag, msg->body, msg->header.body_len, NULL, 0) => -1 (Unknown error -1)
Sep 08 13:36:21 service-vm ziti-edge-tunnel[137954]: (137954)[      857.489]    WARN ziti-sdk:conn_bridge.c:303 on_ziti_data() br[0.27] closing bridge due to error: -23(crypto failure)
Sep 08 13:37:04 service-vm ziti-edge-tunnel[137954]: (137954)[      900.569]    WARN ziti-sdk:channel.c:489 dispatch_message() ch[0] received message without conn_id or for unknown connection ct[ED72] conn_id[27]
Sep 08 13:37:06 service-vm ziti-edge-tunnel[137954]: (137954)[      902.587]    WARN ziti-sdk:channel.c:489 dispatch_message() ch[0] received message without conn_id or for unknown connection ct[ED72] conn_id[22]
Sep 08 13:37:13 service-vm ziti-edge-tunnel[137954]: (137954)[      910.069]   ERROR ziti-sdk:connect.c:845 conn_inbound_data_msg() /github/workspace/build/_deps/ziti-sdk-c-src/library/connect.c:836 - crypto_secretstream_xchacha20poly1305_pull(&conn->crypt_i, plain_text, &plain_len, &tag, msg->body, msg->header.body_len, NULL, 0) => -1 (Unknown error -1)
Sep 08 13:37:13 service-vm ziti-edge-tunnel[137954]: (137954)[      910.069]    WARN ziti-sdk:conn_bridge.c:303 on_ziti_data() br[0.28] closing bridge due to error: -23(crypto failure)

ziti-edge-tunnel (windows)

[2023-09-08T11:37:11.567Z]   DEBUG tunnel-sdk:tunnel_tcp.c:228 tunneler_tcp_close_write() closing write 00007ff7a8251858, state=4(ESTABLISHED) flags=0x100
[2023-09-08T11:37:11.567Z]   TRACE tunnel-sdk:netif_shim.c:34 netif_shim_output() writing packet TCP[100.64.0.13:20500 -> 100.64.0.1:50968] len=40
[2023-09-08T11:37:11.567Z]   DEBUG tunnel-sdk:tunnel_tcp.c:234 tunneler_tcp_close_write() closed write 00007ff7a8251858, state=5(FIN_WAIT_1) flags=0x120
[2023-09-08T11:37:11.567Z]   TRACE ziti-sdk:connect.c:805 flush_to_service() conn[0.18/Connected] flushed 0 messages
[2023-09-08T11:37:11.567Z]   TRACE ziti-sdk:connect.c:768 on_flush() conn[0.18/Connected] stopping flusher
[2023-09-08T11:37:11.567Z]   TRACE ziti-edge-tunnel:tun.c:303 tun_read() starting read
[2023-09-08T11:37:11.567Z]   TRACE tunnel-sdk:tunnel_tcp.c:344 recv_tcp() received segment 100.64.0.1:50968->100.64.0.13:20500
[2023-09-08T11:37:12.422Z]   TRACE ziti-edge-tunnel:tun.c:303 tun_read() starting read
[2023-09-08T11:37:12.422Z]   TRACE tunnel-sdk:tunnel_udp.c:183 recv_udp() received datagram 100.64.0.1:63060->100.64.0.1:5353
[2023-09-08T11:37:12.422Z]   TRACE tunnel-sdk:tunnel_udp.c:208 recv_udp() no intercepted addresses match udp:224.0.0.251:5353
[2023-09-08T11:37:12.535Z]   TRACE ziti-edge-tunnel:tun.c:303 tun_read() starting read
[2023-09-08T11:37:12.535Z]   TRACE tunnel-sdk:tunnel_tcp.c:344 recv_tcp() received segment 100.64.0.1:51030->100.64.0.13:13250
[2023-09-08T11:37:12.535Z] VERBOSE tunnel-sdk:intercept.c:130 port_match() matching port 13250 to range [15000-30000]
[2023-09-08T11:37:12.535Z]   TRACE tunnel-sdk:tunnel_tcp.c:356 recv_tcp() no intercepted addresses match tcp:100.64.0.13:13250
[2023-09-08T11:37:13.905Z]   TRACE ziti-edge-tunnel:tun.c:303 tun_read() starting read
[2023-09-08T11:37:13.905Z]   TRACE tunnel-sdk:tunnel_tcp.c:344 recv_tcp() received segment 100.64.0.1:50968->100.64.0.13:20500
[2023-09-08T11:37:13.905Z] VERBOSE tunnel-sdk:tunnel_tcp.c:134 on_tcp_client_data() status 0 00007ff7a8251858, state=10(TIME_WAIT) flags=0x123
[2023-09-08T11:37:13.905Z]   DEBUG tunnel-sdk:tunnel_tcp.c:138 on_tcp_client_data() client sent FIN: client=tcp:100.64.0.1:50968, service=Service_IPC-ALPS-HTTP
[2023-09-08T11:37:13.905Z]   DEBUG tunnel-sdk:tunnel_tcp.c:139 on_tcp_client_data() FIN received 00007ff7a8251858, state=10(TIME_WAIT) flags=0x123
[2023-09-08T11:37:13.905Z]   DEBUG tunnel-cbs:ziti_tunnel_cbs.c:157 ziti_sdk_c_close_write() closing ziti_conn tnlr_eof=0, ziti_eof=1
[2023-09-08T11:37:13.905Z]   DEBUG tunnel-cbs:ziti_tunnel_cbs.c:160 ziti_sdk_c_close_write() closing ziti_conn tnlr_eof=1, ziti_eof=1
[2023-09-08T11:37:13.906Z]   TRACE tunnel-sdk:netif_shim.c:34 netif_shim_output() writing packet TCP[100.64.0.13:20500 -> 100.64.0.1:50968] len=40
[2023-09-08T11:37:13.906Z]   TRACE ziti-sdk:channel.c:331 on_channel_send() ch[0] write delay = 0.000 q=1 qs=44
[2023-09-08T11:37:13.906Z]   TRACE ziti-sdk:connect.c:227 on_write_completed() conn[0.18/Connected] status 0
[2023-09-08T11:37:13.906Z] VERBOSE ziti-sdk:connect.c:101 conn_set_state() conn[0.18/Connected] transitioning Connected => Closed
[2023-09-08T11:37:13.906Z]   DEBUG ziti-sdk:channel.c:221 ziti_channel_rem_receiver() ch[0] removed receiver[18]
[2023-09-08T11:37:13.906Z]   DEBUG ziti-sdk:connect.c:169 close_conn_internal() conn[0.18/Closed] removing
[2023-09-08T11:37:13.906Z]   TRACE tunnel-cbs:ziti_tunnel_cbs.c:602 ziti_conn_close_cb() ziti_conn[00000243656ca040] is closed
[2023-09-08T11:37:13.906Z]   DEBUG tunnel-sdk:ziti_tunnel.c:434 ziti_tunneler_close() closing connection: client[tcp:100.64.0.1:50968] service[Service_IPC-ALPS-HTTP]
[2023-09-08T11:37:13.906Z]   DEBUG tunnel-sdk:tunnel_tcp.c:244 tunneler_tcp_close() closing 00007ff7a8251858, state=10(TIME_WAIT) flags=0x120
[2023-09-08T11:37:13.906Z]   DEBUG tunnel-sdk:tunnel_tcp.c:260 tunneler_tcp_close() closed 00007ff7a8251858, state=10(TIME_WAIT) flags=0x130
[2023-09-08T11:37:13.906Z] VERBOSE tunnel-cbs:ziti_tunnel_cbs.c:614 ziti_conn_close_cb() nulled data for ziti_conn[00000243656ca040]
[2023-09-08T11:37:13.906Z]   TRACE ziti-sdk:connect.c:144 free_ziti_listen_opts() refuse to free NULL listen_opts
[2023-09-08T11:37:13.906Z]   TRACE ziti-sdk:connect.c:212 close_conn_internal() conn[0.18/Closed] is being free()'d
[2023-09-08T11:37:13.906Z]   DEBUG ziti-sdk:ziti.c:1597 grim_reaper() ztx[0] reaped 1 closed (out of 7 total) connections
[2023-09-08T11:37:13.906Z]   TRACE ziti-edge-tunnel:tun.c:303 tun_read() starting read
[2023-09-08T11:37:13.906Z]   TRACE tunnel-sdk:tunnel_udp.c:183 recv_udp() received datagram 100.64.0.1:58485->100.64.0.1:53
[2023-09-08T11:37:13.906Z]   DEBUG tunnel-sdk:tunnel_udp.c:259 recv_udp() intercepted address[udp:100.64.0.2:53] client[udp:100.64.0.1:58485] service[ziti:dns-resolver]
[2023-09-08T11:37:13.906Z]   DEBUG tunnel-cbs:ziti_dns.c:238 on_dns_client() new DNS client
[2023-09-08T11:37:13.906Z]   DEBUG tunnel-sdk:ziti_tunnel.c:221 ziti_tunneler_dial_completed() ziti dial succeeded: client[udp:100.64.0.1:58485] service[ziti:dns-resolver]
[2023-09-08T11:37:13.906Z]   TRACE tunnel-sdk:tunnel_udp.c:51 to_ziti() no data to write
[2023-09-08T11:37:13.906Z] VERBOSE tunnel-sdk:tunnel_udp.c:107 on_udp_client_data() 30 bytes from 100.64.0.1:58485
[2023-09-08T11:37:13.906Z]   TRACE tunnel-sdk:tunnel_udp.c:58 to_ziti() writing 30 bytes to ziti
[2023-09-08T11:37:13.906Z]   TRACE tunnel-cbs:ziti_dns.c:675 on_dns_req() received DNS query q_len=30 id[0867] recursive[false] type[1] name[my-test.ziti]
[2023-09-08T11:37:13.906Z]    INFO tunnel-cbs:ziti_dns.c:500 format_resp() found record[100.64.0.13] for query[1:my-test.ziti]
[2023-09-08T11:37:13.906Z]   TRACE tunnel-sdk:netif_shim.c:34 netif_shim_output() writing packet UDP[100.64.0.2:53 -> 100.64.0.1:58485] len=85
[2023-09-08T11:37:13.906Z]   TRACE tunnel-cbs:ziti_dns.c:248 on_dns_close() DNS client close
[2023-09-08T11:37:13.906Z]   DEBUG tunnel-sdk:ziti_tunnel.c:434 ziti_tunneler_close() closing connection: client[udp:100.64.0.1:58485] service[ziti:dns-resolver]
[2023-09-08T11:37:13.906Z]   DEBUG tunnel-sdk:tunnel_udp.c:119 tunneler_udp_close() closing ziti:dns-resolver session
[2023-09-08T11:37:13.906Z]   TRACE ziti-edge-tunnel:tun.c:303 tun_read() starting read
[2023-09-08T11:37:13.906Z]   TRACE tunnel-sdk:tunnel_udp.c:183 recv_udp() received datagram 100.64.0.1:59231->100.64.0.1:53
[2023-09-08T11:37:13.906Z]   DEBUG tunnel-sdk:tunnel_udp.c:259 recv_udp() intercepted address[udp:100.64.0.2:53] client[udp:100.64.0.1:59231] service[ziti:dns-resolver]
[2023-09-08T11:37:13.906Z]   DEBUG tunnel-cbs:ziti_dns.c:238 on_dns_client() new DNS client
[2023-09-08T11:37:13.906Z]   DEBUG tunnel-sdk:ziti_tunnel.c:221 ziti_tunneler_dial_completed() ziti dial succeeded: client[udp:100.64.0.1:59231] service[ziti:dns-resolver]
[2023-09-08T11:37:13.906Z]   TRACE tunnel-sdk:tunnel_udp.c:51 to_ziti() no data to write
[2023-09-08T11:37:13.906Z] VERBOSE tunnel-sdk:tunnel_udp.c:107 on_udp_client_data() 30 bytes from 100.64.0.1:59231
[2023-09-08T11:37:13.906Z]   TRACE tunnel-sdk:tunnel_udp.c:58 to_ziti() writing 30 bytes to ziti
[2023-09-08T11:37:13.906Z]   TRACE tunnel-cbs:ziti_dns.c:675 on_dns_req() received DNS query q_len=30 id[4edd] recursive[false] type[28] name[my-test.ziti]
[2023-09-08T11:37:13.906Z]   TRACE tunnel-sdk:netif_shim.c:34 netif_shim_output() writing packet UDP[100.64.0.2:53 -> 100.64.0.1:59231] len=69
[2023-09-08T11:37:13.906Z]   TRACE tunnel-cbs:ziti_dns.c:248 on_dns_close() DNS client close
[2023-09-08T11:37:13.906Z]   DEBUG tunnel-sdk:ziti_tunnel.c:434 ziti_tunneler_close() closing connection: client[udp:100.64.0.1:59231] service[ziti:dns-resolver]
[2023-09-08T11:37:13.906Z]   DEBUG tunnel-sdk:tunnel_udp.c:119 tunneler_udp_close() closing ziti:dns-resolver session
[2023-09-08T11:37:13.907Z]   TRACE ziti-edge-tunnel:tun.c:303 tun_read() starting read
[2023-09-08T11:37:13.907Z]   TRACE tunnel-sdk:tunnel_tcp.c:344 recv_tcp() received segment 100.64.0.1:51034->100.64.0.13:18650
[2023-09-08T11:37:13.907Z] VERBOSE tunnel-sdk:intercept.c:130 port_match() matching port 18650 to range [15000-30000]
[2023-09-08T11:37:13.907Z] VERBOSE tunnel-sdk:intercept.c:133 port_match() port 18650 matches range [15000-30000] with score 15000
[2023-09-08T11:37:13.907Z] VERBOSE tunnel-sdk:intercept.c:135 port_match() port 18650 is best match so far
[2023-09-08T11:37:13.907Z]   DEBUG tunnel-sdk:tunnel_tcp.c:109 new_tcp_pcb() snd_wnd: 65535, snd_snd_max: 65535, mss: 32768
[2023-09-08T11:37:13.907Z]   DEBUG tunnel-sdk:tunnel_tcp.c:409 recv_tcp() intercepted address[tcp:100.64.0.13:18650] client[tcp:100.64.0.1:51034] service[Service_IPC-ALPS-HTTP]
[2023-09-08T11:37:13.907Z] VERBOSE tunnel-cbs:ziti_tunnel_cbs.c:286 ziti_sdk_c_dial() ziti_dial(name=Service_IPC-ALPS-HTTP)
[2023-09-08T11:37:13.907Z]   DEBUG tunnel-cbs:ziti_tunnel_cbs.c:357 ziti_sdk_c_dial() service[Service_IPC-ALPS-HTTP] app_data_json[172]='{"connType":null,"dst_protocol":"tcp","dst_hostname":"my-test.ziti","dst_ip":"100.64.0.13","dst_port":"18650","src_protocol":"tcp","src_ip":"100.64.0.1","src_port":"51034"}'
[2023-09-08T11:37:13.907Z] VERBOSE ziti-sdk:connect.c:101 conn_set_state() conn[0.23/Initial] transitioning Initial => Connecting
[2023-09-08T11:37:13.907Z] VERBOSE ziti-sdk:posture.c:198 ziti_send_posture_data() ztx[0] starting to send posture data
[2023-09-08T11:37:13.907Z]   DEBUG ziti-sdk:posture.c:208 ziti_send_posture_data() ztx[0] posture checks must_send set to TRUE, new_session_id[FALSE], must_send_every_time[TRUE], new_controller_instance[FALSE]
[2023-09-08T11:37:13.907Z] VERBOSE ziti-sdk:posture.c:236 ziti_send_posture_data() ztx[0] checking posture queries on 8 service(s)
[2023-09-08T11:37:13.907Z] VERBOSE ziti-sdk:posture.c:535 ziti_pr_send_bulk() ztx[0] no change in posture data, not sending
[2023-09-08T11:37:13.907Z]   DEBUG ziti-sdk:connect.c:531 process_connect() conn[0.23/Connecting] starting Dial connection for service[Service_IPC-ALPS-HTTP] with session[clmail66a00lw0e752tnxny7p]
[2023-09-08T11:37:13.907Z]   DEBUG ziti-sdk:connect.c:413 ziti_connect() conn[0.23/Connecting] selected ch[Router2@tls://router2.openziti.aws.contoso.com:443] for best latency(28 ms)
[2023-09-08T11:37:13.907Z]   DEBUG ziti-sdk:connect.c:301 on_channel_connected() conn[0.23/Connecting] selected ch[Router2@tls://router2.openziti.aws.contoso.com:443] status[0]
[2023-09-08T11:37:13.907Z]   TRACE ziti-sdk:connect.c:1037 ziti_channel_start_connection() conn[0.23/Connecting] ch[1] => Edge Connect request token[7ba273e5-9bd0-4fef-98c7-b16d8790b8c9]
[2023-09-08T11:37:13.907Z]   DEBUG ziti-sdk:channel.c:214 ziti_channel_add_receiver() ch[1] added receiver[23]
[2023-09-08T11:37:13.907Z]   TRACE ziti-sdk:channel.c:402 ziti_channel_send_for_reply() ch[1] => ct[ED6F] seq[14] len[36]
[2023-09-08T11:37:13.908Z]   TRACE ziti-sdk:channel.c:331 on_channel_send() ch[1] write delay = 0.000 q=1 qs=329
[2023-09-08T11:37:13.979Z]   TRACE ziti-sdk:channel.c:835 on_channel_data() ch[1] on_data [len=108]
[2023-09-08T11:37:13.979Z]   TRACE ziti-sdk:channel.c:520 process_inbound() ch[1] <= ct[ED70] seq[14] len[0] hdrs[88]
[2023-09-08T11:37:13.979Z]   TRACE ziti-sdk:channel.c:531 process_inbound() ch[1] completing msg seq[14] body+hrds=0+88, in_offset=0, want=88, got=88
[2023-09-08T11:37:13.979Z]   TRACE ziti-sdk:channel.c:542 process_inbound() ch[1] message is complete seq[14] ct[ED70]
[2023-09-08T11:37:13.979Z]   TRACE ziti-sdk:connect.c:973 connect_reply_cb() conn[0.23/Connecting] connected
[2023-09-08T11:37:13.979Z] VERBOSE ziti-sdk:connect.c:101 conn_set_state() conn[0.23/Connecting] transitioning Connecting => Connected
[2023-09-08T11:37:13.979Z] VERBOSE tunnel-cbs:ziti_tunnel_cbs.c:93 on_ziti_connect() on_ziti_connect status: 0
[2023-09-08T11:37:13.979Z]   DEBUG tunnel-sdk:ziti_tunnel.c:221 ziti_tunneler_dial_completed() ziti dial succeeded: client[tcp:100.64.0.1:51034] service[Service_IPC-ALPS-HTTP]
[2023-09-08T11:37:13.980Z]   TRACE tunnel-sdk:netif_shim.c:34 netif_shim_output() writing packet TCP[100.64.0.13:18650 -> 100.64.0.1:51034] len=48
[2023-09-08T11:37:13.980Z]   TRACE ziti-sdk:connect.c:775 flush_connection() conn[0.23/Connected] starting flusher
[2023-09-08T11:37:13.980Z]   TRACE ziti-sdk:channel.c:331 on_channel_send() ch[1] write delay = 0.000 q=1 qs=68
[2023-09-08T11:37:13.980Z]   TRACE ziti-sdk:connect.c:227 on_write_completed() conn[0.23/Connected] status 0
[2023-09-08T11:37:13.980Z] VERBOSE ziti-sdk:connect.c:818 flush_to_client() conn[0.23/Connected] 0 bytes available
[2023-09-08T11:37:13.980Z]   TRACE ziti-sdk:connect.c:805 flush_to_service() conn[0.23/Connected] flushed 0 messages
[2023-09-08T11:37:13.980Z]   TRACE ziti-sdk:connect.c:768 on_flush() conn[0.23/Connected] stopping flusher
[2023-09-08T11:37:13.980Z]   TRACE ziti-edge-tunnel:tun.c:303 tun_read() starting read
[2023-09-08T11:37:13.980Z]   TRACE tunnel-sdk:tunnel_tcp.c:344 recv_tcp() received segment 100.64.0.1:51034->100.64.0.13:18650
[2023-09-08T11:37:13.980Z]   DEBUG tunnel-sdk:tunnel_tcp.c:59 on_accept() on_accept: 0
[2023-09-08T11:37:13.980Z]   TRACE ziti-edge-tunnel:tun.c:303 tun_read() starting read
[2023-09-08T11:37:13.980Z]   TRACE tunnel-sdk:tunnel_tcp.c:344 recv_tcp() received segment 100.64.0.1:51034->100.64.0.13:18650
[2023-09-08T11:37:13.980Z] VERBOSE tunnel-sdk:tunnel_tcp.c:134 on_tcp_client_data() status 0 00007ff7a8251ee8, state=4(ESTABLISHED) flags=0x101
[2023-09-08T11:37:13.980Z]   TRACE ziti-sdk:connect.c:1306 ziti_write() conn[0.23/Connected] write 453 bytes
[2023-09-08T11:37:13.980Z]   TRACE ziti-sdk:connect.c:775 flush_connection() conn[0.23/Connected] starting flusher
[2023-09-08T11:37:13.980Z] VERBOSE ziti-sdk:connect.c:818 flush_to_client() conn[0.23/Connected] 0 bytes available
[2023-09-08T11:37:13.980Z]   TRACE ziti-sdk:connect.c:805 flush_to_service() conn[0.23/Connected] flushed 1 messages
[2023-09-08T11:37:13.980Z]   TRACE ziti-sdk:connect.c:768 on_flush() conn[0.23/Connected] stopping flusher
[2023-09-08T11:37:13.980Z]   TRACE ziti-sdk:channel.c:331 on_channel_send() ch[1] write delay = 0.000 q=1 qs=514
[2023-09-08T11:37:13.980Z]   TRACE ziti-sdk:connect.c:227 on_write_completed() conn[0.23/Connected] status 0
[2023-09-08T11:37:13.998Z]   TRACE ziti-sdk:channel.c:835 on_channel_data() ch[1] on_data [len=68]
[2023-09-08T11:37:13.998Z]   TRACE ziti-sdk:channel.c:520 process_inbound() ch[1] <= ct[ED72] seq[15] len[24] hdrs[24]
[2023-09-08T11:37:13.998Z]   TRACE ziti-sdk:channel.c:531 process_inbound() ch[1] completing msg seq[15] body+hrds=24+24, in_offset=0, want=48, got=48
[2023-09-08T11:37:13.998Z]   TRACE ziti-sdk:channel.c:542 process_inbound() ch[1] message is complete seq[15] ct[ED72]
[2023-09-08T11:37:13.998Z]   TRACE ziti-sdk:connect.c:775 flush_connection() conn[0.23/Connected] starting flusher
[2023-09-08T11:37:13.998Z]   TRACE ziti-sdk:connect.c:1448 process_edge_message() conn[0.23/Connected] <= ct[ED72] edge_seq[1] body[24]
[2023-09-08T11:37:13.998Z] VERBOSE ziti-sdk:connect.c:866 conn_inbound_data_msg() conn[0.23/Connected] processing crypto header(24 bytes)
[2023-09-08T11:37:13.998Z] VERBOSE ziti-sdk:connect.c:869 conn_inbound_data_msg() conn[0.23/Connected] processed crypto header
[2023-09-08T11:37:13.998Z] VERBOSE ziti-sdk:connect.c:818 flush_to_client() conn[0.23/Connected] 0 bytes available
[2023-09-08T11:37:13.998Z]   TRACE ziti-sdk:connect.c:805 flush_to_service() conn[0.23/Connected] flushed 0 messages
[2023-09-08T11:37:13.998Z]   TRACE ziti-sdk:connect.c:768 on_flush() conn[0.23/Connected] stopping flusher
[2023-09-08T11:37:14.120Z]   TRACE tunnel-sdk:netif_shim.c:34 netif_shim_output() writing packet TCP[100.64.0.13:18650 -> 100.64.0.1:51034] len=40
[2023-09-08T11:37:14.535Z]   TRACE ziti-edge-tunnel:tun.c:303 tun_read() starting read
[2023-09-08T11:37:14.535Z]   TRACE tunnel-sdk:tunnel_udp.c:183 recv_udp() received datagram 100.64.0.1:59236->100.64.0.1:5353
[2023-09-08T11:37:14.535Z]   TRACE tunnel-sdk:tunnel_udp.c:208 recv_udp() no intercepted addresses match udp:224.0.0.251:5353
[2023-09-08T11:37:14.586Z]   TRACE tunnel-cbs:ziti_tunnel_ctrl.c:198 process_cmd() processing command[GetMetrics] with data[{"Identifier":"C:\\WINDOWS\\system32\\config\\systemprofile\\AppData\\Roaming/NetFoundry/Laptop-Starkl.json"}]
[2023-09-08T11:37:14.586Z]   TRACE ziti-edge-tunnel:ziti-edge-tunnel.c:739 on_write_event() Events message is sent.
[2023-09-08T11:37:14.586Z]   TRACE ziti-edge-tunnel:ziti-edge-tunnel.c:739 on_write_event() Events message is sent.
[2023-09-08T11:37:14.648Z]   TRACE tunnel-sdk:netif_shim.c:34 netif_shim_output() writing packet TCP[100.64.0.13:19500 -> 100.64.0.1:65384] len=40
[2023-09-08T11:37:14.648Z]   TRACE ziti-edge-tunnel:tun.c:303 tun_read() starting read
[2023-09-08T11:37:14.648Z]   TRACE tunnel-sdk:tunnel_tcp.c:344 recv_tcp() received segment 100.64.0.1:65384->100.64.0.13:19500
[2023-09-08T11:37:14.679Z]   TRACE ziti-edge-tunnel:tun.c:303 tun_read() starting read
[2023-09-08T11:37:14.679Z]   TRACE tunnel-sdk:tunnel_tcp.c:344 recv_tcp() received segment 100.64.0.1:51010->100.64.0.13:13250
[2023-09-08T11:37:14.679Z] VERBOSE tunnel-sdk:intercept.c:130 port_match() matching port 13250 to range [15000-30000]
[2023-09-08T11:37:14.679Z]   TRACE tunnel-sdk:tunnel_tcp.c:356 recv_tcp() no intercepted addresses match tcp:100.64.0.13:13250
[2023-09-08T11:37:16.648Z]   TRACE ziti-edge-tunnel:tun.c:303 tun_read() starting read
[2023-09-08T11:37:16.648Z]   TRACE tunnel-sdk:tunnel_udp.c:183 recv_udp() received datagram 100.64.0.1:59241->100.64.0.1:5353
[2023-09-08T11:37:16.648Z]   TRACE tunnel-sdk:tunnel_udp.c:208 recv_udp() no intercepted addresses match udp:224.0.0.251:5353
[2023-09-08T11:37:17.796Z] VERBOSE ziti-sdk:ziti_ctrl.c:134 start_request() ctrl[client-api.openziti.aws.contoso.com] starting GET[/current-api-session/service-updates]
[2023-09-08T11:37:17.880Z] VERBOSE ziti-sdk:ziti_ctrl.c:169 ctrl_resp_cb() ctrl[client-api.openziti.aws.contoso.com] received headers GET[/current-api-session/service-updates]
[2023-09-08T11:37:17.880Z]   DEBUG ziti-sdk:ziti_ctrl.c:326 ctrl_body_cb() ctrl[client-api.openziti.aws.contoso.com] completed GET[/current-api-session/service-updates] in 0.084 s

I have also captured a raw tcpdump on the linux machine that is hosting the webpage and logs from both of my routers, as well as the control plane, all of them in verbose mode - but I would prefer to share them privately, because of compliance reasons

Best regards
Jan

smilindave26 · September 8, 2023, 1:15pm

It looks like this is the same issue @ekoby has been working to address. Note from @ekoby:

I believe we have a handle on the issue:

Stale terminator data can be caused when edge SDK(ziti-edge-tunnel) loses connection to the ER. Due to the nature of the disconnect ER may not notice that for a long time
When edge SDK(ziti-edge-tunnel) rebinds it creates a new terminator with new crypto material, but stale terminator data may be sent to the dialing client (see point 1)

to address this issue, we are doing the following:

Setting TCP keep-alive on inbound ER connections -- connection losses are detected much faster by ERs and stale terminators are cleanup much sooner enable TCP keep-alive on inbound connections by ekoby · Pull Request #57 · openziti/transport · GitHub
edge SDK (ziti-edge-tunnel) will keep crypto material between re-binds that way, even if the client gets data from a stale terminator, it should still be usable for end-to-end encryption preserve crypto material between rebinds by ekoby · Pull Request #546 · openziti/ziti-sdk-c · GitHub

janst · September 11, 2023, 6:39am

Hi @smilindave26,

thanks for the reply!
I totally forget to mention the versions I'm using:

ziti-edge-tunnel (linux): 0.22.7
ziti-desktop-edge (windows tunneler): App 2.1.16.0 / Service 2.1.16
ziti-router(s): 0.29.0
ziti-controller: 0.29.0

Are these fixes already merged into the versions I'm using ?

BR
Jan

smilindave26 · September 11, 2023, 12:25pm

enable TCP keep-alive on inbound connections by ekoby · Pull Request #57 · openziti/transport · GitHub was released in v0.30.32 (ziti controller/router)

preserve crypto material between rebinds by ekoby · Pull Request #546 · openziti/ziti-sdk-c · GitHub was released in v0.34.0 (ziti-edge-tunnel)

janst · September 11, 2023, 1:02pm

For ziti controller/router I can only see v0.30.3 as latest version available, see Releases · openziti/ziti · GitHub

For ziti-sdk-c I can also only see v0.33.4, see Releases · openziti/ziti-sdk-c · GitHub

I have also checked the ziti-tunnel-sdk repo and I saw that the latest release ziti-edge-tunnel v0.22.7 uses v0.33.4 of the ziti-sdk-c, see https://github.com/openziti/ziti-tunnel-sdk-c/blob/v0.22.7/CMakeLists.txt

smilindave26 · September 11, 2023, 1:25pm

Apologies - I meant v0.30.2 for openziti/ziti (Release v0.30.2 · openziti/ziti · GitHub). Going with the latest (v0.30.3) is generally a good idea.

Apologies again on ziti-sdk-c and ziti-tunnel-sdk-c! You're correct. v0.34.0 of ziti-sdk-c is only in draft-release. I'll pour myself another cup of coffee right now and get back to you on the status later today.

smilindave26 · September 11, 2023, 2:29pm

I spoke with @ekoby (back from vacation today). He still needs to do some testing on the ziti-sdk-c update with ziti-edge-tunnel. We hope to get this released later this week.

janst · September 12, 2023, 6:40am

Sounds great, thank you!

janst · September 14, 2023, 6:47am

Is the ziti windows tunnel also affected by this fix and if yes - will there be a new release ?

TheLumberjack · September 15, 2023, 11:57am

The Ziti Desktop Edge for Windows also uses the CSDK and Tunneler SDKs, so I would expect it to be similarly affected.

Yes, we plan to make a release for it as soon as we can.

Topic		Replies	Views
Ziti Edge Tunnel Docker container fails/exits Ziti Edge Tunnel	5	57	October 22, 2024
Missing or Invalid CSR General Questions	23	116	May 1, 2024
Launched openziti network using docker compose, but client not able to fetch simple blue service Building/Development	40	1373	May 27, 2022
Service fails in Ziti Edge Tunnels Gw setup Ziti Edge Tunnel	15	231	February 29, 2024
Issue with enrolling client using ziti-edge-tunnel Support	1	49	August 15, 2024

Crypto Failure in ziti-edge-tunnel

Related Topics