ERROR ziti-sdk:connect.c:990

1

Hi there, I'm back again.

I've been continuing my work on a Controller cluster in HA mode. Still based on these installation scripts. I'm now on Controller/Router version 1.4.3 and ZET version 1.5.2.

See my services configuration here.

I've ran into the following error in ZET since i started my HA project on previous versions.

The issue can be resolved by restarting the Edge Router that the Client is connected to.

When i attempt to SSH to a remote ZET client i get the following error on the local client.

Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.928]   TRACE ziti-sdk:connect.c:312 send_message() conn[0.9/8RRCNCMS/Connected](example.ssh) => ct[DataType] uuid[39fe024e:00000001:4fbc76] edge_seq[1] len[57] hash[39fe024e:a6a7499e:95f972ff:dd11f101:4a140bda:2ad5597e:347726df:44ceec71]
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.928]   TRACE ziti-sdk:channel.c:421 ziti_channel_send_message() ch[0] => ct[DataType] seq[41] len[57]
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.928]   TRACE ziti-sdk:channel.c:391 on_channel_send() ch[0] write delay = 0.000d q=1 qs=125
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.928]   TRACE ziti-sdk:connect.c:241 on_write_completed() conn[0.9/8RRCNCMS/Connected](example.ssh) status 0
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.928]   TRACE ziti-sdk:connect.c:882 flush_to_service() conn[0.9/8RRCNCMS/Connected](example.ssh) flushed 1 messages
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.928]   TRACE ziti-sdk:connect.c:806 on_flush() conn[0.9/8RRCNCMS/Connected](example.ssh) stopping flusher
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.928]   TRACE ziti-sdk:channel.c:927 on_channel_data() ch[0] on_data [len=104]
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.928]   TRACE ziti-sdk:channel.c:597 process_inbound() ch[0] <= ct[DataType] seq[39] len[24] hdrs[60]
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.928]   TRACE ziti-sdk:channel.c:608 process_inbound() ch[0] completing msg seq[39] body+hrds=24+60, in_offset=0, want=84, got=84
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.928]   TRACE ziti-sdk:channel.c:622 process_inbound() ch[0] message is complete seq[39] ct[DataType]
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.928]   TRACE ziti-sdk:message.c:91 parse_hdrs() parsing headers len[60]
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.928]   TRACE ziti-sdk:message.c:104 parse_hdrs() hdr[0] id[128] len[16]
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.928]   TRACE ziti-sdk:message.c:104 parse_hdrs() hdr[1] id[1010] len[4]
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.928]   TRACE ziti-sdk:message.c:104 parse_hdrs() hdr[2] id[1000] len[4]
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.928]   TRACE ziti-sdk:message.c:104 parse_hdrs() hdr[3] id[1001] len[4]
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.928]   TRACE ziti-sdk:connect.c:813 flush_connection() conn[0.9/8RRCNCMS/Connected](example.ssh) starting flusher
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.928]   TRACE ziti-sdk:channel.c:922 on_channel_data() ch[0] read no data
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.928]   DEBUG ziti-sdk:connect.c:1415 process_edge_message() conn[0.9/8RRCNCMS/Connected](example.ssh) peer capability: stream[N] multipart[Y] trace[Y]
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.928]   TRACE ziti-sdk:connect.c:1425 process_edge_message() conn[0.9/8RRCNCMS/Connected](example.ssh) <= ct[DataType] uuid[36bedf47:00000000:4eba0e] edge_seq[1] len[24]
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.928] VERBOSE ziti-sdk:connect.c:953 conn_inbound_data_msg() conn[0.9/8RRCNCMS/Connected](example.ssh) processing crypto header(24 bytes)
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.928] VERBOSE ziti-sdk:connect.c:956 conn_inbound_data_msg() conn[0.9/8RRCNCMS/Connected](example.ssh) processed crypto header
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.928] VERBOSE ziti-sdk:connect.c:900 flush_to_client() conn[0.9/8RRCNCMS/Connected](example.ssh) 0 bytes available
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.928]   TRACE ziti-sdk:connect.c:882 flush_to_service() conn[0.9/8RRCNCMS/Connected](example.ssh) flushed 0 messages
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.928]   TRACE ziti-sdk:connect.c:806 on_flush() conn[0.9/8RRCNCMS/Connected](example.ssh) stopping flusher
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.941] VERBOSE ziti-sdk:ziti_ctrl.c:200 ctrl_resp_cb() ctrl[controller.az.example.ziti:443] received headers GET[/sessions/292745bf-8106-4f47-b592-e2eeb3c70642]
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.941] VERBOSE ziti-sdk:ziti_ctrl.c:426 ctrl_body_cb() ctrl[controller.az.example.ziti:443] HTTP RESPONSE: {"error":{"cause":{"code":"UNHANDLED","message":"session with id 292745bf-8106-4f47-b592-e2eeb3c70642 not found"},"code":"NOT_FOUND","message":"The resource requested was not found or is no longer available","requestId":"8SG6awtJE"},"meta":{"apiEnrollmentVersion":"0.0.1","apiVersion":"0.0.1"}}
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.941]   DEBUG ziti-sdk:ziti_ctrl.c:499 ctrl_body_cb() ctrl[controller.az.example.ziti:443] completed GET[/sessions/292745bf-8106-4f47-b592-e2eeb3c70642] in 0.053 s
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.941]   ERROR ziti-sdk:ziti_ctrl.c:521 ctrl_body_cb() ctrl[controller.az.example.ziti:443] API request[/sessions/292745bf-8106-4f47-b592-e2eeb3c70642] failed code[NOT_FOUND] message[The resource requested was not found or is no longer available]
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.941]    WARN ziti-sdk:connect.c:455 refresh_session_cb() failed to refresh session
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.951]   TRACE ziti-sdk:channel.c:927 on_channel_data() ch[0] on_data [len=125]
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.951]   TRACE ziti-sdk:channel.c:597 process_inbound() ch[0] <= ct[DataType] seq[40] len[57] hdrs[48]
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.951]   TRACE ziti-sdk:channel.c:608 process_inbound() ch[0] completing msg seq[40] body+hrds=57+48, in_offset=0, want=105, got=105
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.951]   TRACE ziti-sdk:channel.c:622 process_inbound() ch[0] message is complete seq[40] ct[DataType]
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.951]   TRACE ziti-sdk:message.c:91 parse_hdrs() parsing headers len[48]
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.951]   TRACE ziti-sdk:message.c:104 parse_hdrs() hdr[0] id[1001] len[4]
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.951]   TRACE ziti-sdk:message.c:104 parse_hdrs() hdr[1] id[128] len[16]
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.951]   TRACE ziti-sdk:message.c:104 parse_hdrs() hdr[2] id[1000] len[4]
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.951]   TRACE ziti-sdk:connect.c:813 flush_connection() conn[0.9/8RRCNCMS/Connected](example.ssh) starting flusher
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.951]   TRACE ziti-sdk:channel.c:922 on_channel_data() ch[0] read no data
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.951]   TRACE ziti-sdk:connect.c:1425 process_edge_message() conn[0.9/8RRCNCMS/Connected](example.ssh) <= ct[DataType] uuid[bb65a970:00000001:4eba1a] edge_seq[2] len[57]
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.951] VERBOSE ziti-sdk:connect.c:963 conn_inbound_data_msg() conn[0.9/8RRCNCMS/Connected](example.ssh) decrypting 57 bytes
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.951]   ERROR ziti-sdk:connect.c:975 conn_inbound_data_msg() conn[0.9/8RRCNCMS/Connected](example.ssh) uuid[bb65a970:00000001:4eba1a] crypto state corruption hash[bb65a970:b8362129:a66f053d:e86b1ad7:8bc368aa:a5225306:37adb042:6f3dfc82]
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.951]   ERROR ziti-sdk:connect.c:990 conn_inbound_data_msg() /github/workspace/build/_deps/ziti-sdk-c-src/library/connect.c:985 - crypto_rc => -1 (Unknown error -1)
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.951] VERBOSE ziti-sdk:connect.c:128 conn_set_state() conn[0.9/8RRCNCMS/Connected](example.ssh) transitioning Connected => Disconnected
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.951]   TRACE tunnel-cbs:ziti_tunnel_cbs.c:111 on_ziti_data() got -23 bytes from ziti
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.951]   DEBUG tunnel-cbs:ziti_tunnel_cbs.c:137 on_ziti_data() ziti connection is closed due to [-23](crypto failure)
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.951] VERBOSE ziti-sdk:connect.c:128 conn_set_state() conn[0.9/8RRCNCMS/Disconnected](example.ssh) transitioning Disconnected => Closed
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.951]   DEBUG ziti-sdk:connect.c:896 flush_to_client() conn[0.9/8RRCNCMS/Closed](example.ssh) no data_cb: can't flush, 0 bytes available
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.951]   TRACE ziti-sdk:connect.c:882 flush_to_service() conn[0.9/8RRCNCMS/Closed](example.ssh) flushed 0 messages
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.951]   TRACE ziti-sdk:connect.c:806 on_flush() conn[0.9/8RRCNCMS/Closed](example.ssh) stopping flusher
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.951]   DEBUG ziti-sdk:connect.c:185 close_conn_internal() conn[0.9/8RRCNCMS/Closed](example.ssh) removing
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.951]   TRACE tunnel-cbs:ziti_tunnel_cbs.c:598 ziti_conn_close_cb() ziti_conn[0x5610ce541840] is closed
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.951]   DEBUG tunnel-sdk:ziti_tunnel.c:434 ziti_tunneler_close() closing connection: client[tcp:100.64.0.1:37282] service[example.ssh]
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.951]   DEBUG tunnel-sdk:tunnel_tcp.c:251 tunneler_tcp_close() closing src[tcp:100.64.0.1:37282] dst[tcp:100.64.0.3:22] state[4/ESTABLISHED] flags[0x101] service[example.ssh]
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.951]   TRACE tunnel-sdk:netif_shim.c:34 netif_shim_output() writing packet TCP[100.64.0.3:22 -> 100.64.0.1:37282] len=40
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.951]   DEBUG tunnel-sdk:tunnel_tcp.c:268 tunneler_tcp_close() closed src[] dst[] state[5/FIN_WAIT_1] flags[0x130] service[]
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.951] VERBOSE tunnel-cbs:ziti_tunnel_cbs.c:611 ziti_conn_close_cb() nulled data for ziti_conn[0x5610ce541840]
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.951]   DEBUG ziti-sdk:channel.c:254 ziti_channel_rem_receiver() ch[0] removed receiver[9]
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.951]   TRACE ziti-sdk:connect.c:226 close_conn_internal() conn[0.9/8RRCNCMS/Closed](example.ssh) is being free()'d
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.951]   DEBUG ziti-sdk:ziti.c:1688 grim_reaper() ztx[0] reaped 1 closed (out of 2 total) connections
Mar 07 15:00:04 client-vm-1 ziti-edge-tunnel[3964]: (3964)[      524.952]   TRACE tunnel-sdk:netif_shim.c:65 netif_shim_input() received packet TCP[100.64.0.1:37282 -> 100.64.0.3:22] len=40

And on the remote client i get the following error.

Mar 07 14:52:22 client-vm-2 ziti-edge-tunnel[2140]: (2140)[       48.751]   TRACE ziti-sdk:channel.c:922 on_channel_data() ch[0] read no data
Mar 07 14:52:22 client-vm-2 ziti-edge-tunnel[2140]: (2140)[       48.751]   DEBUG ziti-sdk:connect.c:1415 process_edge_message() conn[0.2/JHVdUWYR/Connected]((null)) peer capability: stream[Y] multipart[N] trace[Y]
Mar 07 14:52:22 client-vm-2 ziti-edge-tunnel[2140]: (2140)[       48.751]   TRACE ziti-sdk:connect.c:1425 process_edge_message() conn[0.2/JHVdUWYR/Connected]((null)) <= ct[DataType] uuid[a3be8b2b:00000000:48ad42] edge_seq[1] len[24]
Mar 07 14:52:22 client-vm-2 ziti-edge-tunnel[2140]: (2140)[       48.751] VERBOSE ziti-sdk:connect.c:953 conn_inbound_data_msg() conn[0.2/JHVdUWYR/Connected]((null)) processing crypto header(24 bytes)
Mar 07 14:52:22 client-vm-2 ziti-edge-tunnel[2140]: (2140)[       48.751] VERBOSE ziti-sdk:connect.c:956 conn_inbound_data_msg() conn[0.2/JHVdUWYR/Connected]((null)) processed crypto header
Mar 07 14:52:22 client-vm-2 ziti-edge-tunnel[2140]: (2140)[       48.751] VERBOSE ziti-sdk:connect.c:900 flush_to_client() conn[0.2/JHVdUWYR/Connected]((null)) 0 bytes available
Mar 07 14:52:22 client-vm-2 ziti-edge-tunnel[2140]: (2140)[       48.751]   TRACE ziti-sdk:connect.c:882 flush_to_service() conn[0.2/JHVdUWYR/Connected]((null)) flushed 0 messages
Mar 07 14:52:22 client-vm-2 ziti-edge-tunnel[2140]: (2140)[       48.751]   TRACE ziti-sdk:connect.c:806 on_flush() conn[0.2/JHVdUWYR/Connected]((null)) stopping flusher
Mar 07 14:52:22 client-vm-2 ziti-edge-tunnel[2140]: (2140)[       48.773]   TRACE ziti-sdk:channel.c:927 on_channel_data() ch[0] on_data [len=125]
Mar 07 14:52:22 client-vm-2 ziti-edge-tunnel[2140]: (2140)[       48.773]   TRACE ziti-sdk:channel.c:597 process_inbound() ch[0] <= ct[DataType] seq[12] len[57] hdrs[48]
Mar 07 14:52:22 client-vm-2 ziti-edge-tunnel[2140]: (2140)[       48.773]   TRACE ziti-sdk:channel.c:608 process_inbound() ch[0] completing msg seq[12] body+hrds=57+48, in_offset=0, want=105, got=105
Mar 07 14:52:22 client-vm-2 ziti-edge-tunnel[2140]: (2140)[       48.773]   TRACE ziti-sdk:channel.c:622 process_inbound() ch[0] message is complete seq[12] ct[DataType]
Mar 07 14:52:22 client-vm-2 ziti-edge-tunnel[2140]: (2140)[       48.773]   TRACE ziti-sdk:message.c:91 parse_hdrs() parsing headers len[48]
Mar 07 14:52:22 client-vm-2 ziti-edge-tunnel[2140]: (2140)[       48.773]   TRACE ziti-sdk:message.c:104 parse_hdrs() hdr[0] id[1000] len[4]
Mar 07 14:52:22 client-vm-2 ziti-edge-tunnel[2140]: (2140)[       48.773]   TRACE ziti-sdk:message.c:104 parse_hdrs() hdr[1] id[1001] len[4]
Mar 07 14:52:22 client-vm-2 ziti-edge-tunnel[2140]: (2140)[       48.773]   TRACE ziti-sdk:message.c:104 parse_hdrs() hdr[2] id[128] len[16]
Mar 07 14:52:22 client-vm-2 ziti-edge-tunnel[2140]: (2140)[       48.773]   TRACE ziti-sdk:connect.c:813 flush_connection() conn[0.2/JHVdUWYR/Connected]((null)) starting flusher
Mar 07 14:52:22 client-vm-2 ziti-edge-tunnel[2140]: (2140)[       48.773]   TRACE ziti-sdk:channel.c:922 on_channel_data() ch[0] read no data
Mar 07 14:52:22 client-vm-2 ziti-edge-tunnel[2140]: (2140)[       48.774]   TRACE ziti-sdk:connect.c:1425 process_edge_message() conn[0.2/JHVdUWYR/Connected]((null)) <= ct[DataType] uuid[a42933fc:00000001:48ad42] edge_seq[2] len[57]
Mar 07 14:52:22 client-vm-2 ziti-edge-tunnel[2140]: (2140)[       48.774] VERBOSE ziti-sdk:connect.c:963 conn_inbound_data_msg() conn[0.2/JHVdUWYR/Connected]((null)) decrypting 57 bytes
Mar 07 14:52:22 client-vm-2 ziti-edge-tunnel[2140]: (2140)[       48.774]   ERROR ziti-sdk:connect.c:975 conn_inbound_data_msg() conn[0.2/JHVdUWYR/Connected]((null)) uuid[a42933fc:00000001:48ad42] crypto state corruption hash[a42933fc:ee45b5f7:3df0e1a1:1f21750f:196ae46e:e7e4c0a8:8996750c:5ca1672a]
Mar 07 14:52:22 client-vm-2 ziti-edge-tunnel[2140]: (2140)[       48.774]   ERROR ziti-sdk:connect.c:990 conn_inbound_data_msg() /github/workspace/build/_deps/ziti-sdk-c-src/library/connect.c:985 - crypto_rc => -1 (Unknown error -1)
Mar 07 14:52:22 client-vm-2 ziti-edge-tunnel[2140]: (2140)[       48.774] VERBOSE ziti-sdk:connect.c:128 conn_set_state() conn[0.2/JHVdUWYR/Connected]((null)) transitioning Connected => Disconnected
Mar 07 14:52:22 client-vm-2 ziti-edge-tunnel[2140]: (2140)[       48.774]    WARN ziti-sdk:conn_bridge.c:317 on_ziti_data() br[0.2] closing bridge due to error: -23(crypto failure)
Mar 07 14:52:22 client-vm-2 ziti-edge-tunnel[2140]: (2140)[       48.774]   DEBUG ziti-sdk:conn_bridge.c:237 close_bridge() br[0.2] closing
Mar 07 14:52:22 client-vm-2 ziti-edge-tunnel[2140]: (2140)[       48.774]   DEBUG tunnel-cbs:ziti_hosting.c:986 on_bridge_close() closing local_addr[127.0.0.1:34772] fd[16]
Mar 07 14:52:22 client-vm-2 ziti-edge-tunnel[2140]: (2140)[       48.774] VERBOSE ziti-sdk:connect.c:128 conn_set_state() conn[0.2/JHVdUWYR/Disconnected]((null)) transitioning Disconnected => Closed
Mar 07 14:52:22 client-vm-2 ziti-edge-tunnel[2140]: (2140)[       48.774]   DEBUG ziti-sdk:connect.c:896 flush_to_client() conn[0.2/JHVdUWYR/Closed]((null)) no data_cb: can't flush, 0 bytes available
Mar 07 14:52:22 client-vm-2 ziti-edge-tunnel[2140]: (2140)[       48.774]   TRACE ziti-sdk:connect.c:882 flush_to_service() conn[0.2/JHVdUWYR/Closed]((null)) flushed 0 messages
Mar 07 14:52:22 client-vm-2 ziti-edge-tunnel[2140]: (2140)[       48.774]   TRACE ziti-sdk:connect.c:806 on_flush() conn[0.2/JHVdUWYR/Closed]((null)) stopping flusher
Mar 07 14:52:22 client-vm-2 ziti-edge-tunnel[2140]: (2140)[       48.774]   DEBUG ziti-sdk:connect.c:185 close_conn_internal() conn[0.2/JHVdUWYR/Closed]((null)) removing
Mar 07 14:52:22 client-vm-2 ziti-edge-tunnel[2140]: (2140)[       48.774]   DEBUG ziti-sdk:channel.c:254 ziti_channel_rem_receiver() ch[0] removed receiver[2]
Mar 07 14:52:22 client-vm-2 ziti-edge-tunnel[2140]: (2140)[       48.774]   TRACE ziti-sdk:connect.c:226 close_conn_internal() conn[0.2/JHVdUWYR/Closed]((null)) is being free()'d
Mar 07 14:52:22 client-vm-2 ziti-edge-tunnel[2140]: (2140)[       48.774]   DEBUG ziti-sdk:ziti.c:1688 grim_reaper() ztx[0] reaped 1 closed (out of 2 total) connections

Thanks again in advance !

2

Hi @farmhouse, just wanted to let you know that we've seen your issue and aren't trying to ignore it. We just need to find the time to be able to reproduce the issue and confirm it's a problem and fix it if it is...

We appreciate the post and we'll see if we can find some time soon to get to this. Thanks again

1 Like
3

Hi, Thanks @TheLumberjack ! I don't expect anything over the weekend ! :smiling_face_with_sunglasses:

4

I've been working through this issue over the past few days and updated some of my scripts

I'm now using v1.5.0 on Controllers and Edge Routers. and 1.5.3 on ZET.

I think it's being caused by my use of a haproxy load balancer in front of my two edge-routers.

The reason i'm using a load balancer in front of my HA controllers and my edge-routers is because i want the HA Controller API's to be publicly addressable via a single FQDN https://controllers.foo.bar:443 and the the edge-routers to be all be publicly addressable via a single FQDN tls:routers.foo.bar:443.

My haproxy load balancer config for the router is here.

I've added a full trace log from the ZET client here. Maybe there are some clues in there.

From looking at the ZET logs it seems like it connects to one of my edge-routers via tls://router.az.lifeboat.ziti:443 and then wants to connect to the second one . It's not obvious to me by looking at the logs if it does connect to the second one or not. It seems to keep retrying.

Eventually, the ZET client goes into a "good" state and i'm able to initiate a connection to the device from a different ZET client however if i restart the ZET service on the client, it goes through the aforementioned process again.

If i take one of my edge-routers offline the whole system works perfectly, clients are reachable instantly after a restart.

5

Oh interesting. That's definitely possible. That's not a deployment that we typically see people using but it surely might be somehow causing issues as the LB round robins between routers. I actually don't know how OpenZiti would react to that scenario. Typically, you wouldn't need to do that. I'd be curious to know if you remove the LB entirely from the topology if you'd still have the problem. I must have missed that when I looked at your original deployment script. I admit I did not look too closely. It feels like a hard problem to reproduce and I've been dragging my feet on trying to set things up the way you have.

Would you try taking the LB out of the equation for the routers? Or use the LB but provide two discreet paths for "router1" and "router2" and advertise them as such just to see if that is where the problem is coming from?

6

Thanks @TheLumberjack.

I have been using source IP balancing as I anticipated these kind of issues but the operation seems to be the same if I use round robin too.

I’ll try these suggestions.

Another question I had… is it possible to somehow configure that the ZET client only connects to a single Edge Router ? In our use case we don’t necessarily need the benefits of the client being connected to two ER’s so long as it fails over to another if the connected ER goes inaccessible.

Thanks again for your feedback !

7

Sure you can influence this using edge-router-policies. You can ensure a given identity can only connect to a single edge router if that's what you want. Generally speaking though, what you describe is what will happen....

The c sdk will reach out to all the routers it's allowed to connect to and as I recall, the first three that reply will be chosen to have connections to, but whatever one returns first will be "the one" that is used.

8

Thanks @TheLumberjack.

Removing the load balancer from in front of the Edge Routers worked as expected. ZET clients operate as expected now although they are obviously addressing Edge Routers individually E.G tls:router1.foo.bar:443, tls:router2.foo.bar:443.

9

I'm not quite sure what you mean by the following though. Can you explain please ?

10

Oh. I was just saying have the LB provide one solitary "non-load balanced" passthrough path for each router. I didn't know if you were forced to use the LB or not. Basically, assign a path through the LB for a particular host.

You seem to have bypassed the LB entirely (which is what I'd do as well) but if you want to go through the LB, you can just assign a single IP to a single hostname and ensure a 1:1 route.

That make more sense? Hopefully. :slight_smile:

1 Like
11

Can the maxConnections host.v1 config option described here be used to limit the number of edge routers that the ZET client creates terminators on ?

I set this value to 1 in my host.v1 config but i still see a terminator for each of my identities on all of my Edge Routers.

{
  "name": "lifeboat.ssh.cfg.host",
  "configTypeId": "NH5p4FpGR",
  "data": {
    "protocol": "tcp",
    "address": "127.0.0.1",
    "port": 22,
    "httpChecks": [],
    "listenOptions": {
      "identity": "$tunneler_id.name",
      "maxConnections": 1
    },
    "portChecks": []
  },
  "tags": {}
}

root@ziti-controller-1:~# ziti edge list terminators
╭────────────────────────┬──────────────┬───────────────────┬─────────┬────────────────────────┬─────────────────────────────┬──────┬────────────┬──────────────╮
│ ID                     │ SERVICE      │ ROUTER            │ BINDING │ ADDRESS                │ IDENTITY                    │ COST │ PRECEDENCE │ DYNAMIC COST │
├────────────────────────┼──────────────┼───────────────────┼─────────┼────────────────────────┼─────────────────────────────┼──────┼────────────┼──────────────┤
│ 2emO6wJhTIU0pAT6n9w3KA │ lifeboat.ssh │ edge-router-ctkym │ edge    │ 2emO6wJhTIU0pAT6n9w3KA │ device1.lifeboat.controller │    0 │ default    │            0 │
│ 3YTK957TihO4N3Mur3IYmJ │ lifeboat.ssh │ edge-router-yecog │ edge    │ 3YTK957TihO4N3Mur3IYmJ │ user2.lifeboat.controller   │    0 │ default    │            0 │
│ 3a3juZ4a0mpvSgcuxC42P9 │ lifeboat.ssh │ edge-router-yecog │ edge    │ 3a3juZ4a0mpvSgcuxC42P9 │ user1.lifeboat.controller   │    0 │ default    │            0 │
│ 47VyNJETmA1vv43U6PJBND │ lifeboat.ssh │ edge-router-ctkym │ edge    │ 47VyNJETmA1vv43U6PJBND │ user1.lifeboat.controller   │    0 │ default    │            0 │
│ 66v78FCMkFEdr0wRicYc1Q │ lifeboat.ssh │ edge-router-yecog │ edge    │ 66v78FCMkFEdr0wRicYc1Q │ device1.lifeboat.controller │    0 │ default    │            0 │
│ hgrSCctpELOwbAe1X0qmN  │ lifeboat.ssh │ edge-router-ctkym │ edge    │ hgrSCctpELOwbAe1X0qmN  │ user2.lifeboat.controller   │    0 │ default    │            0 │
╰────────────────────────┴──────────────┴───────────────────┴─────────┴────────────────────────┴─────────────────────────────┴──────┴────────────┴──────────────╯
12

Looking at the code, it looks like that's what it's supposed to be doing to me. I might be reading it wrong. I think we'll need @ekoby to confirm if this is the expected behavior but that won't be until next week, fyi.

13

Thanks @TheLumberjack. Have a good weekend !

14

it is a bug in tunneler code

1 Like