TCP conn limit is 512 -- ZET not allowing sufficient conns

scareything · July 28, 2023, 1:35pm

Hey John,

Thanks again for the logs and captures. I had some time to look at the latest yesterday. I see evidence of connections being stuck in FIN_WAIT_1 (on the gateway side). I was hoping that keepalives would help with this, but for some reason I see no sign of keepalive activity in your logs. For example, I see lots of this when I run the same build that you ran:

tcp_keepalive: sending KEEPALIVE probe to 100.64.10.1
tcp_keepalive: tcp_ticks 34282   pcb->tmr 34221 pcb->keep_cnt_sent 0
tcp_keepalive: seqno 4033391 ackno 2627159563 err 0.

But I don’t see it at all in your logs. I’ll dive into the lwip logic that leads to keepalives being sent today.

I also saw something that could be packet loss at/in ziti-edge-tunnel’s packet reader. Here’s an example where the ziti connection closes first:

[      249.523]   DEBUG tunnel-cbs:ziti_tunnel_cbs.c:126 on_ziti_data() ziti connection sent EOF (ziti_eof=0, tnlr_eof=0)
[      249.523]   DEBUG tunnel-sdk:ziti_tunnel.c:466 ziti_tunneler_close_write() closing write connection: client[tcp:#.#.179.#:58804] service[ZITI_SERVICE]
[      249.523]   DEBUG tunnel-sdk:tunnel_tcp.c:243 tunneler_tcp_close_write() closing write tcp local=#.#.171.#:8301 remote=#.#.179.#:58804 state=4(ESTABLISHED) flags=0x100 service=ZITI_SERVICE
[      249.523]   DEBUG tunnel-sdk:tunnel_tcp.c:255 tunneler_tcp_close_write() closed write tcp local=#.#.171.#:8301 remote=#.#.179.#:58804 state=5(FIN_WAIT_1) flags=0x120 service=ZITI_SERVICE

This sequence of log messages basically means that ziti-edge-tunnel sent FIN to the client and is waiting for an ACK. There is no sign in the logs of that ACK, but the capture shows it (frame 2378):

No.   Time.       Source     Destination  Proto Len Info
2285  236.448286  #.#.179.#  #.#.171.#    TCP   60  58804 → 8301 [SYN] Seq=845976624 Win=62727 Len=0 MSS=8460 SACK_PERM TSval=1766677971 TSecr=0 WS=128
2286  236.479739  #.#.171.#  #.#.179.#    TCP   48  8301 → 58804 [SYN, ACK] Seq=13233 Ack=845976625 Win=65535 Len=0 MSS=32768 WS=16384
2287  236.480851  #.#.179.#  #.#.171.#    TCP   40  58804 → 8301 [ACK] Seq=845976625 Ack=13234 Win=62848 Len=0
2288  236.481697  #.#.179.#  #.#.171.#    TCP   743 [TCP Previous segment not captured] 58804 → 8301 [PSH, ACK] Seq=845985586 Ack=13234 Win=62848 Len=703
2289  236.481712  #.#.171.#  #.#.179.#    TCP   40  [TCP Window Update] 8301 → 58804 [ACK] Seq=13234 Ack=845976625 Win=49152 Len=0
2376  246.479420  #.#.171.#  #.#.179.#    TCP   40  8301 → 58804 [FIN, ACK] Seq=13234 Ack=845976625 Win=49152 Len=0
2377  246.480506  #.#.179.#  #.#.171.#    TCP   40  58804 → 8301 [FIN, ACK] Seq=845986289 Ack=13235 Win=62848 Len=0
2378  246.480550  #.#.171.#  #.#.179.#    TCP   40  [TCP Dup ACK 2286#1] 8301 → 58804 [ACK] Seq=13235 Ack=845976625 Win=49152 Len=0

So tcpdump apparently sees the FIN that should advance the lwip connection out of FIN_WAIT_1.

Unfortunately I didn’t enable the logs that would show the packets that ziti-edge-tunnel receives in this build. Nor did I enable the tcp state machine logs. Both of these are incredibly voluminous, but that may end up being necessary to understand whether the packet simply isn’t being read or if it’s being ignored by lwip for some reason. I’m still exploring options, but wanted to give you a quick update.

johnalotoski · July 29, 2023, 5:19am

Thank you very much Shawn! Wow, that’s some deep and challenging digging. I think the slow leak rate is about 1 tcp conn per 2 minutes IIRC, so if we need more logs, maybe we can reduce the time window further. Odd about the keepalives. I don’t think there would be any OS level tuning that would affect or interfere with that, but I’ll think about it a bit more also.

scareything · July 31, 2023, 12:52pm

Hey John, yeah I agree that we can get what we need from a shorter timespan. I’ll get a more verbose build together this morning for you to run when you can. Stand by.

scareything · July 31, 2023, 4:55pm

Ok, the latest build includes these changes:

ziti-edge-tunnel will log IP packets as they are received and TCP segments that are processed by LWIP:
```
DEBUG tunnel-sdk:netif_shim.c:58 netif_shim_input() received packet TCP[100.64.10.1:49876 -> 100.64.10.3:443] len=40 count=1
DEBUG tunnel-sdk:tunnel_tcp.c:381 recv_tcp() received segment 100.64.10.1:49876->100.64.10.3:443 flags[ACK]
```
Between these two messages we should be able to determine if ziti-edge-tunnel’s packet reader is simply not seeing the ACK segments, or if some logic in LWIP is causing the ACKs to be ignored.

The content of the ziti-edge-tunnel dump command will now include TCP (and UDP) stats and connections that lwip is currently managing:

=================
TCP Stats:
TCP handles used:3 max:17 limit:4096
=================
TCP Connections:
TCP local=100.64.10.3/32:443 remote=100.64.10.1/32:63976 state=ESTABLISHED ziti_service=ZITI_SERVICE
TCP local=100.64.10.3/32:443 remote=100.64.10.1/32:50875 state=ESTABLISHED ziti_service=ZITI_SERVICE
TCP local=100.64.10.3/32:443 remote=100.64.10.1/32:51142 state=ESTABLISHED ziti_service=ZITI_SERVICE

=================
UDP Stats:
UDP handles used:0 max:1 limit:512
=================
UDP Connections:

More of the LWIP logging options for TCP have been enabled:

TCP_INPUT_DEBUG will log something like this for every segment that LWIP handles:

TCP header:
+-------------------------------+
|    49876      |      443      | (src port, dest port)
+-------------------------------+
|           0685113833          | (seq no)
+-------------------------------+
|           0000761018          | (ack no)
+-------------------------------+
|  5 |   |010000|      8934     | (hdrlen, flags (ACK), win)
+-------------------------------+
|    0x2456     |         0     | (chksum, urgp)
+-------------------------------+
+-+-+-+-+-+-+-+-+-+-+-+-+-+- tcp_input: flags ACK 
-+-+-+-+-+-+-+-+-+-+-+-+-+-+
State: ESTABLISHED
tcp_receive: pcb->rttest 0 rtseq 759423 ackno 761018

This is very chatty and theoretically conveys the same information as the TCP segment logging above, but then reinforcement shouldn’t hurt and maybe we will be surprised.

TCP_OUTPUT_DEBUG will log all segments that ziti-edge-tunnel sends to clients:

tcp_write(pcb=0x102c0b0b0, data=0x15bc0d670, len=247, apiflags=1)
tcp_write: queueing 1363205:1363452
tcp_output_segment: rtseq 1363205
tcp_output_segment: 1363205:1363452
tcp_output: sending ACK for 685174762

TCP_RTO_DEBUG (and TCP_FR_DEBUG) enables logging for retransmission:

tcp_receive: experienced rtt 0 ticks (0 msec).
tcp_receive: RTO 3 (1500 milliseconds)

Could you please run this build when you have the time, along with tcpdump and ziti-edge-tunnel dump outputs?

Thanks,
-Shawn

johnalotoski · August 16, 2023, 3:16pm

Yes, thank you, will get to it shortly!

johnalotoski · September 6, 2023, 8:25pm

Ok, so not so shortly after all

This issue was observed with a fairly large cluster of 83 machines on Network A and just 3 machines on Network B side. Since last having pulled logs from the ZET gateway on Network A, we've shrunk the cluster on Network A to ~30 machines. Looking at the logs today on the ZET gateway over the past several hours, I'm no longer seeing any TCP leakage anymore and previously we were seeing about 1 tcp conn leaked every one or two minutes continuously until we hit the ZET tcp allocation limit. So it looks like the issue was related to either scale, or something about the machines we removed, or both; I'm not sure which.

In any case, the issue doesn't seem to be occurring now, I'll collect some more data over the next day or two, but if it remains stable, probably no point in further log analysis. We are unlikely to rescale up to the previous size the cluster was at, so perhaps we won't be hitting this issue again.

Thanks very much for all the help and deep diving on this challenging-to-nail-down issue. Apologies for being unable to get back to pulling logs before the issue disappeared; would have been nice to discover root cause.

scareything · September 11, 2023, 4:49pm

Thanks for the update! We did get some useful fixes for TCP tail cases from the early days of this thread, so it's all good! FYI I was leaving those fixes in a branch until we completely plugged the leaks that you were seeing. I'll pull those fixes together and get them into an upcoming release soon.

johnalotoski · September 12, 2023, 12:10am

Awesome, thanks much!

Guardiant314 · March 3, 2025, 1:57am

Hi, scareything

I am currently using a tunneler on an AArch64 architecture OpenWrt device. Our company deploys multiple high-definition cameras with configurations: 16384kbps bitrate and 1840 * 2200 resolution for surveillance. At a low bitrate configuration of 256kbps with 1280 * 720p resolution, the video feed remains smooth. However, when switching to a high bitrate, the video stream starts stuttering and eventually crashes.

I have observed the following error logs during the issue:

(26438)[      218.240]   ERROR tunnel-cbs:ziti_tunnel_cbs.c:371 on_ziti_write() ziti_write(ziti_conn[0x5aa03f2a38c0]) failed: connection is closed  
(26438)[      218.240]   ERROR tunnel-cbs:ziti_tunnel_cbs.c:371 on_ziti_write() ziti_write(ziti_conn[0x5aa03f2a38c0]) failed: connection is closed  
(26438)[      218.240]   ERROR tunnel-cbs:ziti_tunnel_cbs.c:371 on_ziti_write() ziti_write(ziti_conn[0x5aa03f2a38c0]) failed: connection is closed

This might be the root cause of UDP packet loss. I tried adjusting the buffer size to 1024, but the video still crashes after approximately 3 minutes. Are there any existing tunnelers that can resolve this situation? If code modifications are mandatory, where should I begin?

Guardiant314 · March 3, 2025, 10:09am

Encountered a program crash issue，

(1014)[      252.663]   DEBUG tunnel-sdk:ziti_tunnel.c:257 ziti_tunneler_dial_completed() ziti dial succeeded: client[udp:172.16.7.151:15060] service[gbs-svc]
(1014)[      252.663]   TRACE ziti-sdk:channel.c:900 on_channel_data() ch[0] read no data
(1014)[      252.663] VERBOSE ziti-sdk:connect.c:896 flush_to_client() conn[0.36/9yKDTWQF/Connected] 0 bytes available
(1014)[      252.663]   TRACE ziti-sdk:connect.c:309 send_message() conn[0.36/9yKDTWQF/Connected] => ct[ED72] uuid[de8e169d:00000000:5b87e] edge_seq[0] len[24] hash[de8e169d:c374bd5e:bc2b6794:29bbeb0a:c8434465:c237cdc8:0f5b6a95:ee9e5b85]
(1014)[      252.663]   TRACE ziti-sdk:channel.c:413 ziti_channel_send_message() ch[0] => ct[ED72] seq[156575] len[24]
(1014)[      252.663]   TRACE ziti-sdk:channel.c:383 on_channel_send() ch[0] write delay = 0.000d q=1 qs=104
(1014)[      252.663]   TRACE ziti-sdk:connect.c:238 on_write_completed() conn[0.36/9yKDTWQF/Connected] status 0
(1014)[      252.663]   TRACE ziti-sdk:connect.c:309 send_message() conn[0.36/9yKDTWQF/Connected] => ct[ED72] uuid[0b22abdb:00000001:5b87e] edge_seq[1] len[1289] hash[0b22abdb:9842ab53:68673732:ec4eed9c:2600549d:4b6c13b5:2d865f92:c18a3706]
(1014)[      252.663]   TRACE ziti-sdk:channel.c:413 ziti_channel_send_message() ch[0] => ct[ED72] seq[156576] len[1289]
(1014)[      252.663]   TRACE ziti-sdk:channel.c:383 on_channel_send() ch[0] write delay = 0.000d q=1 qs=1357
(1014)[      252.663]   TRACE ziti-sdk:connect.c:238 on_write_completed() conn[0.36/9yKDTWQF/Connected] status 0
(1014)[      252.663]   TRACE ziti-sdk:connect.c:309 send_message() conn[0.36/9yKDTWQF/Connected] => ct[ED72] uuid[7264157e:00000002:5b87e] edge_seq[2] len[157] hash[7264157e:527b3e05:9994de4f:0c064fe1:55dc4a93:b7f3ba86:9fb5adc6:56ea56bb]
(1014)[      252.663]   TRACE ziti-sdk:channel.c:413 ziti_channel_send_message() ch[0] => ct[ED72] seq[156577] len[157]
(1014)[      252.663]   TRACE ziti-sdk:channel.c:383 on_channel_send() ch[0] write delay = 0.000d q=1 qs=225
(1014)[      252.663]   TRACE ziti-sdk:connect.c:238 on_write_completed() conn[0.36/9yKDTWQF/Connected] status 0
Assertion "pbuf_free: p->ref > 0" failed at line 755 in /~/ziti-tunnel-sdk-c-1.2.7/build/_deps/lwip-src/src/core/pbuf.c

scareything · March 3, 2025, 11:43am

Hello,

Can you please update to the latest ziti-edge-tunnel (currently v1.4.5), and can you share a complete log (showing the startup messages) of both the intercepting and hosting tunnelers?

Thanks

Guardiant314 · March 4, 2025, 2:56am

Yes, I have updated to tunneler version 1.4.5. Here are some logs:

// startup messages
(1058)[        0.000]    INFO ziti-sdk:utils.c:198 ziti_log_set_level() set log level: root=6/TRACE
(1058)[        0.000]    INFO ziti-sdk:utils.c:169 ziti_log_init() Ziti C SDK version 1.4.4 @g9a16a32(HEAD) starting at (2025-03-04T01:32:11.356)
(1058)[        0.000]   DEBUG ziti-edge-tunnel:ziti-edge-tunnel.c:1167 init_proxy_connector() proxy_url not set
(1058)[        0.000]   DEBUG ziti-edge-tunnel:tun.c:325 init_dns_maintainer() setting up NETLINK listener
(1058)[        0.000]   DEBUG ziti-edge-tunnel:utils.c:33 run_command_va() system(ip route add 100.64.0.0/10 dev ziti0) returned 0
(1058)[        0.000]    INFO tunnel-sdk:ziti_tunnel.c:60 create_tunneler_ctx() Ziti Tunneler SDK (v1.4.5)
(1058)[        0.000]    INFO tunnel-cbs:ziti_dns.c:176 seed_dns() DNS configured with range 100.64.0.0 - 100.127.255.255 (4194302 ips)
(1058)[        0.000]   DEBUG tunnel-sdk:ziti_tunnel.c:321 ziti_tunneler_intercept() intercepting address[udp:100.64.0.2/32:53] service[ziti:dns-resolver]
(1058)[        0.000]    DEBUG ziti-edge-tunnel:ziti-edge-tunnel.c:1801 make_socket_path() local group 'ziti' exists, gid=1001
(1058)[        0.000]    INFO ziti-edge-tunnel:ziti-edge-tunnel.c:1803 make_socket_path() effective group set to 'ziti' (gid=1001)
(1058)[        0.014]   DEBUG ziti-edge-tunnel:tun.c:301 on_dns_update_time() queuing DNS update
(1058)[        0.014]    INFO ziti-edge-tunnel:resolvers.c:68 init_libsystemd() Initializing libsystemd
(1058)[        0.014]    WARN ziti-edge-tunnel:instance.c:51 find_tunnel_identity() Identity ztx[./gateway.json] is not loaded yet or already removed.
(1058)[        0.014]   DEBUG ziti-edge-tunnel:resolvers.c:96 init_libsystemd() Dynamically loaded libsystemd
(1058)[        0.014]   DEBUG ziti-edge-tunnel:resolvers.c:388 try_libsystemd_resolver() Detected systemd is init system
(1058)[        0.014]   DEBUG ziti-edge-tunnel:resolvers.c:395 try_libsystemd_resolver() Connected to system DBus
(1058)[        0.014]   DEBUG ziti-edge-tunnel:resolvers.c:339 wait_for_tun() waiting 3000 ms for systemd path '/org/freedesktop/systemd1/unit/sys_2dsubsystem_2dnet_2ddevices_2dziti0_2edevice' to become active
(1058)[        0.014]   DEBUG ziti-edge-tunnel:resolvers.c:365 wait_for_tun() device state (c=0): active
(1058)[        0.014]    INFO tunnel-cbs:ziti_tunnel_ctrl.c:1162 load_ziti_async() attempting to load ziti instance[./gateway.json]
(1058)[        0.014]    INFO tunnel-cbs:ziti_tunnel_ctrl.c:1169 load_ziti_async() loading ziti instance[./gateway.json]
(1058)[        0.014]    INFO ziti-edge-tunnel:ziti-edge-tunnel.c:420 load_id_cb() identity[./gateway.json] loaded
(1058)[        0.014]   TRACE tunnel-sdk:netif_shim.c:69 netif_shim_input() done after reading 2 packets

(1058)[        0.015]    INFO ziti-sdk:ziti.c:519 ziti_start_internal() ztx[0] enabling Ziti Context
(1058)[        0.015]    INFO ziti-sdk:ziti.c:537 ziti_start_internal() ztx[0] using tlsuv[v0.33.6/OpenSSL 3.3.1 4 Jun 2024]
(1058)[        0.015]    INFO ziti-sdk:ziti_ctrl.c:626 ziti_ctrl_init() ctrl[(null):] using https://ctrl_test.com:1280
(1058)[        0.015]   DEBUG ziti-sdk:ziti_ctrl.c:640 ziti_ctrl_init() ctrl[ctrl_test.com:1280] ziti controller client initialized
(1058)[        0.015] VERBOSE ziti-sdk:ziti_ctrl.c:145 start_request() ctrl[ctrl_test.com:1280] starting GET[/version]
(1058)[        0.015]    INFO ziti-sdk:ziti.c:614 ztx_init_controller() ztx[0] Loading ziti context with controller[https://ctrl_test.com:1280]
(1058)[        0.015]   DEBUG ziti-sdk:ziti.c:545 ziti_start_internal() ztx[0] using metrics interval: 0
(1058)[        0.015]   DEBUG ziti-sdk:ziti.c:218 ziti_set_unauthenticated() ztx[0] setting auth_state[0] to 0
(1058)[        0.015]   DEBUG ziti-sdk:ziti_ctrl.c:379 ziti_ctrl_clear_api_session() ctrl[ctrl_test.com:1280] clearing api session token for ziti_controller
(1058)[        0.015]   DEBUG ziti-sdk:ziti_ctrl.c:1065 ctrl_paging_req() ctrl[ctrl_test.com:1280] starting paging request GET[/external-jwt-signers]
(1058)[        0.015] VERBOSE ziti-sdk:ziti_ctrl.c:1070 ctrl_paging_req() ctrl[ctrl_test.com:1280] requesting /external-jwt-signers?limit=25&offset=0
(1058)[        0.015] VERBOSE ziti-sdk:ziti_ctrl.c:145 start_request() ctrl[ctrl_test.com:1280] starting GET[/external-jwt-signers?limit=25&offset=0]
(1058)[        0.077] VERBOSE ziti-sdk:ziti_ctrl.c:200 ctrl_resp_cb() ctrl[ctrl_test.com:1280] received headers GET[/version]
(1058)[        0.077] VERBOSE ziti-sdk:ziti_ctrl.c:426 ctrl_body_cb() ctrl[ctrl_test.com:1280] HTTP RESPONSE: {"data":{"apiVersions":{"edge":{"v1":{"apiBaseUrls":["https://ctrl_test.com:1280/edge/client/v1"],"path":"/edge/client/v1"}},"edge-client":{"v1":{"apiBaseUrls":["https://ctrl_test.com:1280/edge/client/v1"],"path":"/edge/client/v1"}},"edge-management":{"v1":{"apiBaseUrls":["https://ctrl_test.com:1280/edge/management/v1"],"path":"/edge/management/v1"}}},"buildDate":"2020-01-01 01:01:01","capabilities":[],"revision":"local","runtimeVersion":"go1.23.1","version":"v1.1.15"},"meta":{}}
(1058)[        0.077]   DEBUG ziti-sdk:ziti_ctrl.c:500 ctrl_body_cb() ctrl[ctrl_test.com:1280] completed GET[/version] in 0.042 s
(1058)[        0.077]    INFO ziti-sdk:ziti.c:1930 version_pre_auth_cb() ztx[0] connected to Legacy controller https://ctrl_test.com:1280 version v1.1.15(local 2020-01-01 01:01:01)
(1058)[        0.077] VERBOSE ziti-sdk:ziti_ctrl.c:145 start_request() ctrl[ctrl_test.com:1280] starting POST[/authenticate?method=cert]
(1058)[        0.079] VERBOSE ziti-sdk:ziti_ctrl.c:200 ctrl_resp_cb() ctrl[ctrl_test.com:1280] received headers GET[/external-jwt-signers?limit=25&offset=0]
(1058)[        0.079] VERBOSE ziti-sdk:ziti_ctrl.c:426 ctrl_body_cb() ctrl[ctrl_test.com:1280] HTTP RESPONSE: {"data":[{"_links":{"self":{"href":"./external-jwt-signers/6aPtLr3suXURAckKkTiOe4"}},"createdAt":"2025-01-06T07:54:35.503Z","id":"6aPtLr3suXURAckKkTiOe4","tags":{},"updatedAt":"2025-01-06T07:54:35.503Z","externalAuthUrl":null,"name":"ext_jwt_signer","scopes":null}],"meta":{"filterableFields":["isSystem","notBefore","clientId","kid","issuer","notAfter","claimsProperty","scopes","commonName","enabled","id","createdAt","updatedAt","tags","fingerprint","name","certPem","useExternalId","audience"],"pagination":{"limit":25,"offset":0,"totalCount":1}}}
(1058)[        0.079]   DEBUG ziti-sdk:ziti_ctrl.c:485 ctrl_body_cb() ctrl[ctrl_test.com:1280] received 1/1 for paging request GET[/external-jwt-signers]
(1058)[        0.079]   DEBUG ziti-sdk:ziti_ctrl.c:495 ctrl_body_cb() ctrl[ctrl_test.com:1280] completed paging request GET[/external-jwt-signers] in 0.044 s
(1058)[        0.079]    INFO ziti-sdk:ziti.c:664 ext_jwt_singers_cb() ztx[0] ext signer[ext_jwt_signer] cannot be used: provider_url and client_id are required
(1058)[        0.079]   DEBUG ziti-sdk:ziti.c:675 ext_jwt_singers_cb() ztx[0] 0 external auth providers available
(1058)[        0.105] VERBOSE ziti-sdk:ziti_ctrl.c:200 ctrl_resp_cb() ctrl[ctrl_test.com:1280] received headers POST[/authenticate?method=cert]
(1058)[        0.105] VERBOSE ziti-sdk:ziti_ctrl.c:426 ctrl_body_cb() ctrl[ctrl_test.com:1280] HTTP RESPONSE: {"data":{"_links":{"self":{"href":"./api-sessions/cm7ttd8256wl3jin1oi33pf3r"},"sessions":{"href":"./api-sessions/cm7ttd8256wl3jin1oi33pf3r/sessions"}},"createdAt":"2025-03-04T01:32:11.405Z","id":"cm7ttd8256wl3jin1oi33pf3r","tags":{},"updatedAt":"2025-03-04T01:32:11.405Z","authQueries":[],"authenticatorId":"Yyk31HjH-","cachedLastActivityAt":"2025-03-04T01:32:11.406Z","configTypes":["all"],"identity":{"_links":{"auth-policies":{"href":"./auth-policies/default"},"authenticators":{"href":"./identities/mDUFxH6Wz/authenticators"},"edge-router-policies":{"href":"./identities/mDUFxH6Wz/edge-router-policies"},"edge-routers":{"href":"./identities/mDUFxH6Wz/edge-routers"},"enrollments":{"href":"./identities/mDUFxH6Wz/enrollments"},"failed-service-requests":{"href":"./identities/mDUFxH6Wz/failed-service-requests"},"posture-data":{"href":"./identities/mDUFxH6Wz/posture-data"},"self":{"href":"./identities/mDUFxH6Wz"},"service-configs":{"href":"./identities/mDUFxH6Wz/ser
(1058)[        0.105]   DEBUG ziti-sdk:ziti_ctrl.c:500 ctrl_body_cb() ctrl[ctrl_test.com:1280] completed POST[/authenticate?method=cert] in 0.027 s
(1058)[        0.105]   DEBUG ziti-sdk:ziti_ctrl.c:393 ctrl_login_cb() ctrl[ctrl_test.com:1280] authenticated successfully session[cm7ttd8256wl3jin1oi33pf3r]
(1058)[        0.105]   DEBUG ziti-sdk:legacy_auth.c:171 login_cb() logged in successfully => api_session[cm7ttd8256wl3jin1oi33pf3r]
(1058)[        0.105]   DEBUG ziti-sdk:ziti.c:372 ziti_set_fully_authenticated() ztx[0] setting auth_state[0] to 3

// set intercept
(1058)[        0.187]   DEBUG tunnel-cbs:ziti_tunnel_ctrl.c:940 on_service() service[video-gbs-svc]
(1058)[        0.187]    INFO tunnel-cbs:ziti_tunnel_cbs.c:414 new_ziti_intercept() creating intercept for service[video-gbs-svc] with intercept.v1 = { "addresses": [ "172.16.117.3" ], "dialOptions": { "connectTimeoutSeconds": 0 }, "portRanges": [ { "high": 5061, "low": 5061 }, { "high": 30250, "low": 30000 }, { "high": 10000, "low": 10000 }, { "high": 8000, "low": 8000 } ], "protocols": [ "tcp", "udp" ], "sourceIp": "" }
(1058)[        0.187]   DEBUG tunnel-sdk:ziti_tunnel.c:321 ziti_tunneler_intercept() intercepting address[tcp:172.16.117.3/32:5061] service[video-gbs-svc]
(1058)[        0.187]   DEBUG tunnel-sdk:ziti_tunnel.c:321 ziti_tunneler_intercept() intercepting address[tcp:172.16.117.3/32:[30000-30250]] service[video-gbs-svc]
(1058)[        0.187]   DEBUG tunnel-sdk:ziti_tunnel.c:321 ziti_tunneler_intercept() intercepting address[tcp:172.16.117.3/32:10000] service[video-gbs-svc]
(1058)[        0.187]   DEBUG tunnel-sdk:ziti_tunnel.c:321 ziti_tunneler_intercept() intercepting address[tcp:172.16.117.3/32:8000] service[video-gbs-svc]
(1058)[        0.187]   DEBUG tunnel-sdk:ziti_tunnel.c:321 ziti_tunneler_intercept() intercepting address[udp:172.16.117.3/32:5061] service[video-gbs-svc]
(1058)[        0.187]   DEBUG tunnel-sdk:ziti_tunnel.c:321 ziti_tunneler_intercept() intercepting address[udp:172.16.117.3/32:[30000-30250]] service[video-gbs-svc]
(1058)[        0.187]   DEBUG tunnel-sdk:ziti_tunnel.c:321 ziti_tunneler_intercept() intercepting address[udp:172.16.117.3/32:10000] service[video-gbs-svc]
(1058)[        0.187]   DEBUG tunnel-sdk:ziti_tunnel.c:321 ziti_tunneler_intercept() intercepting address[udp:172.16.117.3/32:8000] service[video-gbs-svc]
(1058)[        0.187]    INFO tunnel-cbs:ziti_tunnel_ctrl.c:943 on_service() starting intercepting for service[video-gbs-svc]
(1058)[        0.187]   DEBUG tunnel-cbs:ziti_tunnel_ctrl.c:940 on_service() service[openwrt-svc]

// router connected
(1058)[        0.221]    INFO ziti-sdk:channel.c:717 hello_reply_cb() ch[0] connected. EdgeRouter version: v1.1.15|local|2020-01-01 01:01:01|linux|amd64
(1058)[        0.221]    INFO tunnel-cbs:ziti_tunnel_ctrl.c:1061 on_ziti_event() ztx[camera-p2] router router_test.com connected
(1058)[        0.221]   DEBUG ziti-sdk:bind.c:138 process_bindings() server[0.0](openwrt-svc) checking router[router_test.com]
(1058)[        0.221]   DEBUG ziti-sdk:bind.c:529 start_binding() server[0.0](openwrt-svc) requesting BIND on ch[router_test.com]
(1058)[        0.221]   TRACE ziti-sdk:bind.c:530 start_binding() server[0.0](openwrt-svc) ch[0] => Edge Bind request token[aa306285-a3d1-4db1-8f69-67d357540ac8]

// dropping UDP packet 
(1058)[       16.601]   TRACE tunnel-sdk:netif_shim.c:65 netif_shim_input() received packet UDP[172.16.7.151:15060 -> 172.16.117.3:30134] len=1300
(1058)[       16.601]   TRACE tunnel-sdk:netif_shim.c:65 netif_shim_input() received packet UDP[172.16.7.151:17249 -> 172.16.117.3:40558] len=160
(1058)[       16.601]   TRACE tunnel-sdk:tunnel_udp.c:156 recv_udp() received datagram src[172.16.7.151:15060] dst[172.16.117.3:30134]
(1058)[       16.601] VERBOSE tunnel-sdk:tunnel_udp.c:84 on_udp_client_data() 1272 bytes from 172.16.7.151:15060
(1058)[       16.601]   TRACE tunnel-sdk:tunnel_udp.c:54 to_ziti() writing 1272 bytes to ziti src[udp:172.16.7.151:15060] dst[udp:172.16.117.3:30134] service[video-gbs-svc]
(1058)[       16.601] VERBOSE tunnel-cbs:ziti_tunnel_cbs.c:395 ziti_sdk_c_write() applying backpressure 129904 pending bytes
(1058)[       16.601]    WARN tunnel-sdk:tunnel_udp.c:66 to_ziti() ziti_write stalled: dropping UDP packet service=video-gbs-svc, client=udp:172.16.7.151:15060, ret=-7
(1058)[       16.601]   TRACE tunnel-sdk:netif_shim.c:69 netif_shim_input() done after reading 2 packets
(1058)[       16.601]   TRACE tunnel-sdk:netif_shim.c:65 netif_shim_input() received packet UDP[172.16.7.151:15060 -> 172.16.117.3:30134] len=1300
(1058)[       16.601]   TRACE tunnel-sdk:netif_shim.c:65 netif_shim_input() received packet UDP[172.16.7.151:12876 -> 172.16.117.3:64710] len=160
(1058)[       16.601]   TRACE tunnel-sdk:tunnel_udp.c:156 recv_udp() received datagram src[172.16.7.151:15060] dst[172.16.117.3:30134]
(1058)[       16.601] VERBOSE tunnel-sdk:tunnel_udp.c:84 on_udp_client_data() 1272 bytes from 172.16.7.151:15060
(1058)[       16.601]   TRACE tunnel-sdk:tunnel_udp.c:54 to_ziti() writing 1272 bytes to ziti src[udp:172.16.7.151:15060] dst[udp:172.16.117.3:30134] service[video-gbs-svc]
(1058)[       16.601] VERBOSE tunnel-cbs:ziti_tunnel_cbs.c:395 ziti_sdk_c_write() applying backpressure 129904 pending bytes
(1058)[       16.601]    WARN tunnel-sdk:tunnel_udp.c:66 to_ziti() ziti_write stalled: dropping UDP packet service=video-gbs-svc, client=udp:172.16.7.151:15060, ret=-7
(1058)[       16.601]   TRACE tunnel-sdk:netif_shim.c:69 netif_shim_input() done after reading 2 packets

// Encountered a program crash issue
(1058)[       16.601]   TRACE tunnel-sdk:netif_shim.c:65 netif_shim_input() received packet UDP[172.16.7.151:15060 -> 172.16.117.3:30134] len=1300
(1058)[       16.601]   TRACE tunnel-sdk:netif_shim.c:69 netif_shim_input() done after reading 1 packets
(1058)[       16.601]   TRACE ziti-sdk:channel.c:925 on_channel_data() ch[0] on_data [len=125]
(1058)[       16.601]   TRACE ziti-sdk:channel.c:597 process_inbound() ch[0] <= ct[ED70] seq[50] len[0] hdrs[105]
(1058)[       16.601]   TRACE ziti-sdk:channel.c:607 process_inbound() ch[0] completing msg seq[50] body+hrds=0+105, in_offset=0, want=105, got=105
(1058)[       16.601]   TRACE ziti-sdk:channel.c:621 process_inbound() ch[0] message is complete seq[50] ct[ED70]
(1058)[       16.601]   TRACE ziti-sdk:message.c:91 parse_hdrs() parsing headers len[105]
(1058)[       16.601]   TRACE ziti-sdk:message.c:104 parse_hdrs() hdr[0] id[1101] len[4]
(1058)[       16.601]   TRACE ziti-sdk:message.c:104 parse_hdrs() hdr[1] id[1000] len[4]
(1058)[       16.601]   TRACE ziti-sdk:message.c:104 parse_hdrs() hdr[2] id[1001] len[4]
(1058)[       16.601]   TRACE ziti-sdk:message.c:104 parse_hdrs() hdr[3] id[1026] len[9]
(1058)[       16.601]   TRACE ziti-sdk:message.c:104 parse_hdrs() hdr[4] id[1] len[4]
(1058)[       16.601]   TRACE ziti-sdk:message.c:104 parse_hdrs() hdr[5] id[1003] len[32]
(1058)[       16.601]   TRACE ziti-sdk:connect.c:1081 connect_reply_cb() conn[0.11/7PZyd4nD/Connecting](video-gbs-svc) connected
(1058)[       16.601]   TRACE ziti-sdk:connect.c:811 flush_connection() conn[0.11/7PZyd4nD/Connecting](video-gbs-svc) starting flusher
(1058)[       16.601] VERBOSE ziti-sdk:connect.c:127 conn_set_state() conn[0.11/7PZyd4nD/Connecting](video-gbs-svc) transitioning Connecting => Connected
(1058)[       16.601] VERBOSE tunnel-cbs:ziti_tunnel_cbs.c:93 on_ziti_connect() on_ziti_connect status: 0
(1058)[       16.601]   DEBUG tunnel-sdk:ziti_tunnel.c:221 ziti_tunneler_dial_completed() ziti dial succeeded: client[udp:172.16.7.151:15060] service[video-gbs-svc]
(1058)[       16.601]   TRACE ziti-sdk:channel.c:920 on_channel_data() ch[0] read no data
(1058)[       16.601] VERBOSE ziti-sdk:connect.c:898 flush_to_client() conn[0.11/7PZyd4nD/Connected](video-gbs-svc) 0 bytes available
(1058)[       16.601]   TRACE ziti-sdk:connect.c:312 send_message() conn[0.11/7PZyd4nD/Connected](video-gbs-svc) => ct[ED72] uuid[53cd8b78:00000000:20e27] edge_seq[0] len[24] hash[53cd8b78:4646f9a9:b8afd0af:597ac30d:1641f46b:bd40a1a6:6b94fd82:503e939d]
(1058)[       16.601]   TRACE ziti-sdk:channel.c:420 ziti_channel_send_message() ch[0] => ct[ED72] seq[482] len[24]
(1058)[       16.601]   TRACE ziti-sdk:channel.c:391 on_channel_send() ch[0] write delay = 0.000d q=1 qs=104
(1058)[       16.601]   TRACE ziti-sdk:connect.c:240 on_write_completed() conn[0.11/7PZyd4nD/Connected](video-gbs-svc) status 0
(1058)[       16.601]   TRACE ziti-sdk:connect.c:312 send_message() conn[0.11/7PZyd4nD/Connected](video-gbs-svc) => ct[ED72] uuid[12305f2c:00000001:20e27] edge_seq[1] len[1289] hash[12305f2c:8a4baa58:1e8cc29c:92304a78:100a4b0e:917b026e:af3e22b9:c597549e]
(1058)[       16.601]   TRACE ziti-sdk:channel.c:420 ziti_channel_send_message() ch[0] => ct[ED72] seq[483] len[1289]
(1058)[       16.601]   TRACE ziti-sdk:channel.c:391 on_channel_send() ch[0] write delay = 0.000d q=1 qs=1357
(1058)[       16.601]   TRACE ziti-sdk:connect.c:240 on_write_completed() conn[0.11/7PZyd4nD/Connected](video-gbs-svc) status 0
(1058)[       16.601]   TRACE ziti-sdk:connect.c:312 send_message() conn[0.11/7PZyd4nD/Connected](video-gbs-svc) => ct[ED72] uuid[e6166c10:00000002:20e27] edge_seq[2] len[157] hash[e6166c10:a34ce0b2:377b229c:da788642:b75bfb40:cccc183a:e317e3d6:777c2e31]
(1058)[       16.601]   TRACE ziti-sdk:channel.c:420 ziti_channel_send_message() ch[0] => ct[ED72] seq[484] len[157]
(1058)[       16.601]   TRACE ziti-sdk:channel.c:391 on_channel_send() ch[0] write delay = 0.000d q=1 qs=225
(1058)[       16.601]   TRACE ziti-sdk:connect.c:240 on_write_completed() conn[0.11/7PZyd4nD/Connected](video-gbs-svc) status 0
Assertion "pbuf_free: p->ref > 0" failed at line 755 in /github/workspace/build/_deps/lwip-src/src/core/pbuf.c

scareything · March 4, 2025, 2:18pm

Thanks. These excerpts give me something to look at, but it would be really helpful if you could send the entire log including the process startup.

Could you also start a new thread/discussion here, because the issue that you're seeing is different from the one that this thread was started for.

Thanks!

Guardiant314 · March 4, 2025, 3:13pm

sure， thank you very much

Guardiant314 · March 5, 2025, 2:17am

I couldn’t upload the log here due to its large size, so I’ve sent it to you via email. Could you please confirm if you’ve received it?
I’m looking forward to your analysis and suggestions.
The new discussion thread can be found here:[The tunnel device failed to forward the high-bitrate video stream]

Topic		Replies	Views
Ziti tunnel - reduce traffic consumption General Questions	9	333	July 17, 2023
Edge Tunnel Keep Alice Timeout zrok	2	21	December 12, 2024
Connection closed errors between Ziti-Edge-Tunnels	4	236	November 11, 2024
ZET random loss of connection during usage Ziti Edge Tunnel	4	289	November 23, 2022
Router connection load balancing General Questions	3	39	April 3, 2025

TCP conn limit is 512 -- ZET not allowing sufficient conns

Related topics