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
Launched openziti network using docker compose, but client not able to fetch simple blue service Building/Development	40	1059	May 27, 2022
Service fails in Ziti Edge Tunnels Gw setup Ziti Edge Tunnel	15	107	February 29, 2024
Problem with one specific service and one specific identity Ziti Edge Tunnel	4	160	June 2, 2023
Tunnel unable to reach local router General Questions	3	193	October 25, 2023
Android Tunneler connection errors Tunneler Apps	10	116	March 5, 2024

Crypto Failure in ziti-edge-tunnel

Related Topics