Missing Terminators after Controller reboot

Support
1

Hello everyone,

First of all, thank you for your work, you have put together a cool project.
I've been testing Openziti for our environment for a few weeks now.

I have noticed one big problem.

My setup looks like the following:

One controller, two edge routers and 2 private routers, all based on the “Prod” deployments, no quickstart.
All services are currently connected to the private Routers.

Everything works great until the controller is restarted.
All routers and tunnelers then reconnect, but no more terminators are created.

I get the following messages on the routers:

> Apr 30 12:39:14 ziti-private-2 ziti[1563]: {"ctrlId":"NetFoundry Inc. Client KbTdMRSoa","file":"github.com/openziti/ziti/router/state/manager.go:256","func":"github.com/openziti/ziti/router/state.(*ManagerImpl).checkRouterDataModelSubscription","level":"info","msg":"no current data model subscription active, subscribing","prevCtrlId":"NetFoundry Inc. Client KbTdMRSoa","time":"2025-04-30T12:39:14.705Z"}
> Apr 30 12:39:14 ziti-private-2 ziti[1563]: {"ctrlId":"NetFoundry Inc. Client KbTdMRSoa","currentIndex":121,"file":"github.com/openziti/ziti/router/state/manager.go:306","func":"github.com/openziti/ziti/router/state.(*ManagerImpl).subscribeToDataModelUpdates","level":"info","msg":"subscribed to new controller for router data model changes","renew":true,"time":"2025-04-30T12:39:14.705Z"}
> Apr 30 12:39:44 ziti-private-2 ziti[1563]: {"ctrlId":"NetFoundry Inc. Client KbTdMRSoa","file":"github.com/openziti/ziti/router/state/manager.go:256","func":"github.com/openziti/ziti/router/state.(*ManagerImpl).checkRouterDataModelSubscription","level":"info","msg":"no current data model subscription active, subscribing","prevCtrlId":"NetFoundry Inc. Client KbTdMRSoa","time":"2025-04-30T12:39:44.706Z"}
> Apr 30 12:39:44 ziti-private-2 ziti[1563]: {"ctrlId":"NetFoundry Inc. Client KbTdMRSoa","currentIndex":121,"file":"github.com/openziti/ziti/router/state/manager.go:306","func":"github.com/openziti/ziti/router/state.(*ManagerImpl).subscribeToDataModelUpdates","level":"info","msg":"subscribed to new controller for router data model changes","renew":true,"time":"2025-04-30T12:39:44.706Z"}
> Apr 30 12:40:14 ziti-private-2 ziti[1563]: {"ctrlId":"NetFoundry Inc. Client KbTdMRSoa","file":"github.com/openziti/ziti/router/state/manager.go:256","func":"github.com/openziti/ziti/router/state.(*ManagerImpl).checkRouterDataModelSubscription","level":"info","msg":"no current data model subscription active, subscribing","prevCtrlId":"NetFoundry Inc. Client KbTdMRSoa","time":"2025-04-30T12:40:14.706Z"}
> Apr 30 12:40:14 ziti-private-2 ziti[1563]: {"ctrlId":"NetFoundry Inc. Client KbTdMRSoa","currentIndex":121,"file":"github.com/openziti/ziti/router/state/manager.go:306","func":"github.com/openziti/ziti/router/state.(*ManagerImpl).subscribeToDataModelUpdates","level":"info","msg":"subscribed to new controller for router data model changes","renew":true,"time":"2025-04-30T12:40:14.706Z"}
> Apr 30 12:40:44 ziti-private-2 ziti[1563]: {"ctrlId":"NetFoundry Inc. Client KbTdMRSoa","file":"github.com/openziti/ziti/router/state/manager.go:256","func":"github.com/openziti/ziti/router/state.(*ManagerImpl).checkRouterDataModelSubscription","level":"info","msg":"no current data model subscription active, subscribing","prevCtrlId":"NetFoundry Inc. Client KbTdMRSoa","time":"2025-04-30T12:40:44.706Z"}
> Apr 30 12:40:44 ziti-private-2 ziti[1563]: {"ctrlId":"NetFoundry Inc. Client KbTdMRSoa","currentIndex":121,"file":"github.com/openziti/ziti/router/state/manager.go:306","func":"github.com/openziti/ziti/router/state.(*ManagerImpl).subscribeToDataModelUpdates","level":"info","msg":"subscribed to new controller for router data model changes","renew":true,"time":"2025-04-30T12:40:44.706Z"}
> Apr 30 12:41:14 ziti-private-2 ziti[1563]: {"ctrlId":"NetFoundry Inc. Client KbTdMRSoa","file":"github.com/openziti/ziti/router/state/manager.go:256","func":"github.com/openziti/ziti/router/state.(*ManagerImpl).checkRouterDataModelSubscription","level":"info","msg":"no current data model subscription active, subscribing","prevCtrlId":"NetFoundry Inc. Client KbTdMRSoa","time":"2025-04-30T12:41:14.706Z"}
> Apr 30 12:41:14 ziti-private-2 ziti[1563]: {"ctrlId":"NetFoundry Inc. Client KbTdMRSoa","currentIndex":121,"file":"github.com/openziti/ziti/router/state/manager.go:306","func":"github.com/openziti/ziti/router/state.(*ManagerImpl).subscribeToDataModelUpdates","level":"info","msg":"subscribed to new controller for router data model changes","renew":true,"time":"2025-04-30T12:41:14.706Z"}

I have to restart all the routers first, sometimes I even have to restart the individual tunnelers.

It gets really weird when I only restart the private routers, the terminators are created again. If I try to access a service, I see the following error message on the edge routers: No Controllers available, cannot create circuit (I could not reproduce this part, so no log extract), although I can see in the ZAC that the routers are connected.

The commands ziti edge policy-advisor services and ziti edge policy-advisor identities show no errors.

The error is not 100% reproducible, but I would say at least 50%.

Do you know the problem and is there perhaps a command that ensures that the routers “reboot”?

Thank you and best regards
Jonas

2

Hi @jnsfndr, welcome to the community and to OpenZiti!

That's truly bizzare and certainlly should not be happening. Out of curiosity how long do you wait? This should of course immediately fix itself, but I'm just curious if it ever seems to recover.

I'll have a look and also see if we can reproduce the issue on our side. Thanks again for lettign us know, it's cleary not the expected behavior. Can you also confirm the exact version of ziti you're using and confirm that all the components are at that same level? Lastly, you didn't modify the config generated by the controller deployment in any meaningful way, correct?

3

Thanks for the quick reply.

I am using the latest version 1.5.4 on all routers and the controller. The infrastructure was also only set up 4 days ago. All servers are running the latest Debian 12.

Correct, I am currently still using the generated config without any adjustments.

I waited about 18 hours

Here is the log when the controller was accessible again, after that only the part I have already shared above came every minute:

> Apr 29 19:08:55 ziti-private-2 ziti[1563]: {"_context":"u{reconnecting}-\u003ei{NetFoundry Inc. Client OiRjad2na/K8pK}","file":"github.com/openziti/channel/v3@v3.0.39/reconnecting_impl.go:54","func":"github.com/openziti/channel/v3.(*reconnectingImpl).Rx","level":"info","msg":"reconnected","time":"2025-04-29T19:08:55.572Z"}
> Apr 29 19:08:55 ziti-private-2 ziti[1563]: {"file":"github.com/openziti/ziti/router/xgress_edge/factory.go:90","func":"github.com/openziti/ziti/router/xgress_edge.(*Factory).NotifyOfReconnect","level":"info","msg":"control channel reconnected, re-establishing hosted services","time":"2025-04-29T19:08:55.572Z"}
> Apr 29 19:08:55 ziti-private-2 ziti[1563]: {"ctrlId":"NetFoundry Inc. Client GJ2C1.EU1","file":"github.com/openziti/ziti/router/link/link_registry.go:386","func":"github.com/openziti/ziti/router/link.(*linkRegistryImpl).NotifyOfReconnect","level":"info","msg":"resending link states after reconnect","time":"2025-04-29T19:08:55.572Z"}
> Apr 29 19:08:55 ziti-private-2 ziti[1563]: {"_context":"u{reconnecting}-\u003ei{NetFoundry Inc. Client GJ2C1.EU1/maLv}","file":"github.com/openziti/channel/v3@v3.0.39/reconnecting_impl.go:171","func":"github.com/openziti/channel/v3.(*reconnectingImpl).pingInstance","level":"info","msg":"starting","time":"2025-04-29T19:08:55.572Z"}
> Apr 29 19:08:55 ziti-private-2 ziti[1563]: {"_context":"u{reconnecting}-\u003ei{NetFoundry Inc. Client GJ2C1.EU1/maLv}","file":"github.com/openziti/channel/v3@v3.0.39/reconnecting_impl.go:178","func":"github.com/openziti/channel/v3.(*reconnectingImpl).pingInstance","level":"info","msg":"exiting","time":"2025-04-29T19:08:55.572Z"}
> Apr 29 19:08:55 ziti-private-2 ziti[1563]: {"_context":"u{reconnecting}-\u003ei{NetFoundry Inc. Client OiRjad2na/K8pK}","file":"github.com/openziti/channel/v3@v3.0.39/reconnecting_impl.go:81","func":"github.com/openziti/channel/v3.(*reconnectingImpl).Tx","level":"info","msg":"reconnected","time":"2025-04-29T19:08:55.572Z"}
> Apr 29 19:08:55 ziti-private-2 ziti[1563]: {"address":"tls:ziti-edge-1.xyz:3022","file":"github.com/openziti/ziti/router/link/link_events.go:123","func":"github.com/openziti/ziti/router/link.(*linkDestUpdate).ApplyListenerChanges","level":"info","linkKey":"default-\u003etls:sGfyfz0vJ-\u003edefault","msg":"link already known","routerId":"sGfyfz0vJ","time":"2025-04-29T19:08:55.574Z"}
> Apr 29 19:08:55 ziti-private-2 ziti[1563]: {"file":"github.com/openziti/ziti/router/handler_edge_ctrl/hello.go:82","func":"github.com/openziti/ziti/router/handler_edge_ctrl.(*helloHandler).HandleReceive.func1","level":"info","msg":"received server hello, replying","time":"2025-04-29T19:08:55.574Z"}
> Apr 29 19:08:55 ziti-private-2 ziti[1563]: {"file":"github.com/openziti/ziti/router/state/apiSessionAdded.go:212","func":"github.com/openziti/ziti/router/state.(*apiSessionAddedHandler).instantSync","level":"info","msg":"first api session syncId [cma2rhkt90006ric4cbpc7mju], starting","strategy":"instant","time":"2025-04-29T19:08:55.586Z"}
> Apr 29 19:08:55 ziti-private-2 ziti[1563]: {"file":"github.com/openziti/ziti/router/state/apiSessionAdded.go:277","func":"github.com/openziti/ziti/router/state.(*apiSessionSyncTracker).Add","level":"info","msg":"received api session sync chunk 0, isLast=true","time":"2025-04-29T19:08:55.586Z"}

(1/2) I have to split, because of new user and the limitation to 10 links

4

(2/2)

> Apr 29 19:08:55 ziti-private-2 ziti[1563]: {"address":"tls:ziti-private-1.xyz:3022","file":"github.com/openziti/ziti/router/link/link_events.go:123","func":"github.com/openziti/ziti/router/link.(*linkDestUpdate).ApplyListenerChanges","level":"info","linkKey":"default-\u003etls:fWosG.3c0y-\u003edefault","msg":"link already known","routerId":"fWosG.3c0y","time":"2025-04-29T19:08:55.586Z"}
> Apr 29 19:08:56 ziti-private-2 ziti[1563]: {"file":"github.com/openziti/ziti/router/state/apiSessionAdded.go:131","func":"github.com/openziti/ziti/router/state.(*apiSessionAddedHandler).applySync","level":"info","msg":"finished synchronizing api sessions [count: 3, syncId: cma2rhkt90006ric4cbpc7mju, duration: 19.86µs]","time":"2025-04-29T19:08:56.586Z"}
> Apr 29 19:08:57 ziti-private-2 ziti[1563]: {"file":"github.com/openziti/ziti/router/xgress_edge/hosted.go:204","func":"github.com/openziti/ziti/router/xgress_edge.(*hostedServiceRegistry).evaluateDeleteQueue","level":"info","msg":"added terminator to batch delete","state":3,"terminatorId":"7KTLWthpRCmQxujCSuk6YT","time":"2025-04-29T19:08:57.510Z","token":"105414a3-26c0-4aa8-9a60-3d627a3596cc"}
> Apr 29 19:08:57 ziti-private-2 ziti[1563]: {"file":"github.com/openziti/ziti/router/xgress_edge/hosted.go:263","func":"github.com/openziti/ziti/router/xgress_edge.(*hostedServiceRegistry).RemoveTerminatorsRateLimited.func1","level":"info","msg":"remove terminator succeeded","terminatorId":"7KTLWthpRCmQxujCSuk6YT","time":"2025-04-29T19:08:57.521Z"}
> Apr 29 19:08:57 ziti-private-2 ziti[1563]: {"file":"github.com/openziti/ziti/router/xgress_edge/hosted.go:267","func":"github.com/openziti/ziti/router/xgress_edge.(*hostedServiceRegistry).RemoveTerminatorsRateLimited.func1","level":"error","msg":"terminator was replaced after being put into deleting state?!","terminatorId":"7KTLWthpRCmQxujCSuk6YT","time":"2025-04-29T19:08:57.521Z"}
> Apr 29 19:09:04 ziti-private-2 ziti[1563]: {"_context":"ch{edge}-\u003eu{classic}-\u003ei{ziti-sdk-c[2]@debianAirflow/k8Lk}","chSeq":2,"connId":0,"edgeSeq":0,"file":"github.com/openziti/ziti/router/xgress_edge/listener.go:286","func":"github.com/openziti/ziti/router/xgress_edge.(*edgeClientConn).processBind","level":"error","msg":"no controller available, cannot create terminator","routerId":"5A.lC.aQ0","time":"2025-04-29T19:09:04.928Z","token":"105414a3-26c0-4aa8-9a60-3d627a3596cc",">
> Apr 29 19:09:14 ziti-private-2 ziti[1563]: {"ctrlId":"NetFoundry Inc. Client GJ2C1.EU1","file":"github.com/openziti/ziti/router/state/manager.go:256","func":"github.com/openziti/ziti/router/state.(*ManagerImpl).checkRouterDataModelSubscription","level":"info","msg":"no current data model subscription active, subscribing","prevCtrlId":"","time":"2025-04-29T19:09:14.705Z"}
> Apr 29 19:09:14 ziti-private-2 ziti[1563]: {"ctrlId":"NetFoundry Inc. Client GJ2C1.EU1","currentIndex":121,"file":"github.com/openziti/ziti/router/state/manager.go:306","func":"github.com/openziti/ziti/router/state.(*ManagerImpl).subscribeToDataModelUpdates","level":"info","msg":"subscribed to new controller for router data model changes","renew":false,"time":"2025-04-29T19:09:14.705Z"}
> Apr 29 19:09:44 ziti-private-2 ziti[1563]: {"ctrlId":"NetFoundry Inc. Client GJ2C1.EU1","file":"github.com/openziti/ziti/router/state/manager.go:256","func":"github.com/openziti/ziti/router/state.(*ManagerImpl).checkRouterDataModelSubscription","level":"info","msg":"no current data model subscription active, subscribing","prevCtrlId":"NetFoundry Inc. Client GJ2C1.EU1","time":"2025-04-29T19:09:44.705Z"}
> Apr 29 19:09:44 ziti-private-2 ziti[1563]: {"ctrlId":"NetFoundry Inc. Client GJ2C1.EU1","currentIndex":121,"file":"github.com/openziti/ziti/router/state/manager.go:306","func":"github.com/openziti/ziti/router/state.(*ManagerImpl).subscribeToDataModelUpdates","level":"info","msg":"subscribed to new controller for router data model changes","renew":true,"time":"2025-04-29T19:09:44.705Z"}

(edited by clint, added code fences)

5

Hi @jnsfndr, logs and such are best viewed as pure 'code' text blocks by using the 'tick' characrter. This character `.

I updated your posts to use triple ticks as you can see.

Thanks for following up. We'll have a peek and reply in a bit. cheers

6

I was now able to reproduce the second error. One of the private routers was restarted, the terminators now exist and then I get the following error message on the edge router:

Apr 30 14:42:10 ziti-edge-1 ziti[852]: {"ctrlId":"NetFoundry Inc. Client KbTdMRSoa","currentIndex":121,"file":"github.com/openziti/ziti/router/state/manager.go:306","func":"github.com/openziti/ziti/router/state.(*ManagerImpl).subscribeToDataModelUpdates","level":"info","msg":"subscribed to new controller for router data model changes","renew":true,"time":"2025-04-30T14:42:10.621Z"}
Apr 30 14:42:14 ziti-edge-1 ziti[852]: {"file":"github.com/openziti/ziti/common/router_data_model.go:913","func":"github.com/openziti/ziti/router/state.(*ManagerImpl).StartRouterModelSave.func1.(*RouterDataModel).Save.1","level":"debug","msg":"no changes to router model, nothing to save","time":"2025-04-30T14:42:14.841Z"}
Apr 30 14:42:15 ziti-edge-1 ziti[852]: {"_context":"ch{edge}-\u003eu{classic}-\u003ei{ziti-sdk-c[0]@localhost/zq5z}","chSeq":3,"connId":0,"edgeSeq":0,"file":"github.com/openziti/ziti/router/xgress_edge/listener.go:143","func":"github.com/openziti/ziti/router/xgress_edge.(*edgeClientConn).processConnect","level":"error","msg":"no controller available, cannot create circuit","time":"2025-04-30T14:42:15.330Z","token":"abc-xyz","type":"EdgeConnectType"}
Apr 30 14:42:15 ziti-edge-1 ziti[852]: {"_context":"ch{edge}-\u003eu{classic}-\u003ei{ziti-sdk-c[0]@localhost/zq5z}","chSeq":4,"connId":1,"edgeSeq":0,"file":"github.com/openziti/ziti/router/xgress_edge/listener.go:143","func":"github.com/openziti/ziti/router/xgress_edge.(*edgeClientConn).processConnect","level":"error","msg":"no controller available, cannot create circuit","time":"2025-04-30T14:42:15.363Z","token":"abc-xyz","type":"EdgeConnectType"}
Apr 30 14:42:15 ziti-edge-1 ziti[852]: {"file":"github.com/openziti/sdk-golang@v0.25.1/ziti/edge/msg_mux.go:103","func":"github.com/openziti/sdk-golang/ziti/edge.(*CowMapMsgMux).HandleReceive","level":"debug","msg":"unable to dispatch msg received for unknown edge conn id: 0","time":"2025-04-30T14:42:15.386Z"}
Apr 30 14:42:15 ziti-edge-1 ziti[852]: {"file":"github.com/openziti/sdk-golang@v0.25.1/ziti/edge/msg_mux.go:103","func":"github.com/openziti/sdk-golang/ziti/edge.(*CowMapMsgMux).HandleReceive","level":"debug","msg":"unable to dispatch msg received for unknown edge conn id: 1","time":"2025-04-30T14:42:15.452Z"}
Apr 30 14:42:16 ziti-edge-1 ziti[852]: {"_context":"ch{edge}-\u003eu{classic}-\u003ei{ziti-sdk-c[0]@localhost/zq5z}","chSeq":7,"connId":2,"edgeSeq":0,"file":"github.com/openziti/ziti/router/xgress_edge/listener.go:143","func":"github.com/openziti/ziti/router/xgress_edge.(*edgeClientConn).processConnect","level":"error","msg":"no controller available, cannot create circuit","time":"2025-04-30T14:42:16.532Z","token":"abc-xyz","type":"EdgeConnectType"}
Apr 30 14:42:16 ziti-edge-1 ziti[852]: {"file":"github.com/openziti/sdk-golang@v0.25.1/ziti/edge/msg_mux.go:103","func":"github.com/openziti/sdk-golang/ziti/edge.(*CowMapMsgMux).HandleReceive","level":"debug","msg":"unable to dispatch msg received for unknown edge conn id: 2","time":"2025-04-30T14:42:16.559Z"}
Apr 30 14:42:21 ziti-edge-1 ziti[852]: {"_context":"ch{edge}-\u003eu{classic}-\u003ei{ziti-sdk-c[0]@localhost/zq5z}","chSeq":9,"connId":3,"edgeSeq":0,"file":"github.com/openziti/ziti/router/xgress_edge/listener.go:143","func":"github.com/openziti/ziti/router/xgress_edge.(*edgeClientConn).processConnect","level":"error","msg":"no controller available, cannot create circuit","time":"2025-04-30T14:42:21.678Z","token":"abc-xyz","type":"EdgeConnectType"}
Apr 30 14:42:21 ziti-edge-1 ziti[852]: {"file":"github.com/openziti/sdk-golang@v0.25.1/ziti/edge/msg_mux.go:103","func":"github.com/openziti/sdk-golang/ziti/edge.(*CowMapMsgMux).HandleReceive","level":"debug","msg":"unable to dispatch msg received for unknown edge conn id: 3","time":"2025-04-30T14:42:21.702Z"}
7

Hi @jnsfndr

Can you clarify if the hosting is directly on the private routers, using an edge-router with tunneling enabled, or if you're hosting using a standalone tunneler?

Thank you,
Paul

8

I have installed Linux Tunneler(also on Debian 12) version 1.6.1 on each of the servers hosting the service and these connect to the two private routers.
The servers that host the service are different from the servers that host the router

9

Hi @TheLumberjack
I have tested a bit more, if I restart the server on which the controller is running, the terminators remain and everything works perfectly after the restart. At least I can't reproduce the problem this way

I was able to force the issue with the following command:
systemctl restart ziti-controller.service
After that, the Terminator disappeared and the error messages as described above were again visible in the logs.
I added more services, one of the services also kept its terminator with the systemctl command (no idea why exactly that one). I replaced one of the edge routers with an edge router based on Docker, there the same error message came up until the restart

10

this sounds like a bug that has been recently fixed and should be in the next release