search

openziti / ziti-tunnel-sdk-c

Apache License 2.0
43 stars 17 forks source link

Suspected issue of DNS collision #575

Closed mikegorman-nf closed 1 year ago

mikegorman-nf commented 1 year ago

Odd bug in a client. It looks to me like a new service was added that is a new port on the same address as other services. A new DNS entry was added, but the the old one remained, so the new service wasn't reachable because it wasn't attached properly.

44 min. ago

[2022-12-26T04:38:36.984Z]   ERROR tunnel-sdk:tunnel_tcp.c:170 on_tcp_client_err() client=tcp:100.64.0.1:57702 err=-14, terminating connection
[2022-12-26T04:39:51.578Z]    INFO tunnel-cbs:ziti_dns.c:500 format_resp() found record[100.64.0.104] for query[1:EBSLWARCNV29.ramco]
[2022-12-26T04:41:51.475Z]    INFO tunnel-cbs:ziti_tunnel_cbs.c:562 ziti_sdk_c_on_service() service unavailable: BEBSL_DC_EBSLWARCNV29_80-NEW
[2022-12-26T04:41:51.478Z]    INFO tunnel-cbs:ziti_dns.c:375 ziti_dns_deregister_intercept() DNS mapping ebslwarncv29.ramco -> 100.64.0.93 is now inactive
**[2022-12-26T04:41:51.479Z]    INFO tunnel-cbs:ziti_tunnel_cbs.c:403 new_ziti_intercept() creating intercept for service[BEBSL_DC_EBSLWARCNV29_80-New] with intercept.v1 = {"addresses":["EBSLWARNCV29.ramco"],"portRanges":[{"high":80,"low":80}],"protocols":["tcp"]}
[2022-12-26T04:41:51.479Z]    INFO tunnel-cbs:ziti_dns.c:296 new_ipv4_entry() registered DNS entry ebslwarncv29.ramco -> 100.64.0.153**
[2022-12-26T04:41:51.479Z]    INFO tunnel-cbs:ziti_tunnel_ctrl.c:686 on_service() starting intercepting for service[BEBSL_DC_EBSLWARCNV29_80-New]
[2022-12-26T04:41:51.479Z]    INFO ziti-edge-tunnel:ziti-edge-tunnel.c:1238 on_event() =============== service event (removed) - BEBSL_DC_EBSLWARCNV29_80-NEW:gK.t8TyoX ===============
[2022-12-26T04:41:51.479Z]    INFO ziti-edge-tunnel:ziti-edge-tunnel.c:1262 on_event() =============== service event (added) - BEBSL_DC_EBSLWARCNV29_80-New:gK.t8TyoX ===============
[2022-12-26T04:41:58.148Z]    INFO tunnel-cbs:ziti_dns.c:500 format_resp() found record[100.64.0.104] for query[1:ebslwarcnv29.ramco]
[2022-12-26T04:41:58.153Z]    INFO tunnel-cbs:ziti_dns.c:500 format_resp() found record[100.64.0.104] for query[1:ebslwarcnv29.ramco]
[2022-12-26T04:42:41.053Z]    WARN ziti-edge-tunnel:tun.c:453 refresh_routes() failed to create exclusion route[13.71.66.115]: 1168(The operation completed successfully.
)
[2022-12-26T04:42:41.053Z]    WARN ziti-edge-tunnel:tun.c:453 refresh_routes() failed to create exclusion route[104.211.224.160]: 1168(The operation completed successfully.
)
[2022-12-26T04:42:41.053Z]    WARN ziti-edge-tunnel:tun.c:453 refresh_routes() failed to create exclusion route[13.126.79.88]: 1168(The operation completed successfully.
)
[2022-12-26T04:42:41.053Z]    WARN ziti-edge-tunnel:tun.c:453 refresh_routes() failed to create exclusion route[13.71.94.246]: 1168(The operation completed successfully.
)
[2022-12-26T04:44:17.426Z]    INFO tunnel-cbs:ziti_dns.c:500 format_resp() found record[100.64.0.104] for query[1:ebslwarcnv29.ramco]
**[2022-12-26T04:44:17.429Z]    INFO tunnel-cbs:ziti_dns.c:500 format_resp() found record[100.64.0.104] for query[1:ebslwarcnv29.ramco]**
[2022-12-26T04:44:39.675Z]   ERROR tunnel-sdk:tunnel_tcp.c:170 on_tcp_client_err() client=tcp:100.64.0.1:50672 err=-14, terminating connection
[2022-12-26T04:44:39.677Z]    WARN ziti-sdk:connect.c:1501 process_edge_message() conn[0.114/Closed] data[10257 bytes] received in state[Closed]
[2022-12-26T04:44:39.679Z]   ERROR ziti-sdk:channel.c:496 dispatch_message() ch[3] received message without conn_id or for unknown connection ct[ED72] conn_id[114]
[2022-12-26T04:44:39.681Z]   ERROR ziti-sdk:channel.c:496 dispatch_message() ch[3] received message without conn_id or for unknown connection ct[ED72] conn_id[114]
[2022-12-26T04:44:39.681Z]   ERROR ziti-sdk:channel.c:496 dispatch_message() ch[3] received message without conn_id or for unknown connection ct[ED71] conn_id[114]
scareything commented 1 year ago

Everything in the log excerpt looks normal to me.

The service (or its intercept configuration) was updated. The tSDK handles this as a remove/add, which explains the "service unavailable" and subsequent "ziti_dns_deregister_hostname()" logs.

Prior to the service update, the hostname "ebslwarncv29.ramco" was mapped to 100.64.0.93. This mapping was dropped when the "remove" step of the update occurred:

[2022-12-26T04:41:51.478Z]    INFO tunnel-cbs:ziti_dns.c:375 ziti_dns_deregister_intercept() DNS mapping ebslwarncv29.ramco -> 100.64.0.93 is now inactive

Since that mapping was made, the dns server's internal counter that it uses for the next IP assignment was incremented a few times, so when the mapping is (re)made the IP is 100.64.0.153.

Note: the query for "ebslwarcnv29.ramco" at t=04:44:17.429Z and the associated record concerned me for a while, until I realized that it is a different hostname than the one in the service that was updated.