I take it the router run --extend option triggers getting a new client and server certificate for the same private key, and probaly refreshes the trust anchors too.
I wanted to make sure this works, so I changed my v0.30.3 router's run command to include --extend, but the cert's not-before timestamp didn't change.
These log lines indicate the renewal/extension timer was succesfully zeroed, but "no controller is available." Still, the router is online and packets are flowing through a service using the router. There are no other routers.
[ 0.005] INFO edge/router/xgress_edge.(*CertExpirationChecker).getWaitTime: enrollment extension was forced
[ 0.005] INFO edge/router/xgress_edge.(*CertExpirationChecker).Run: waiting 0s to renew certificates
[ 0.005] ERROR edge/router/xgress_edge.(*CertExpirationChecker).Run: could not extend enrollment: cannot request updates, no controller is available
My run command:
ziti router run /etc/ziti/config/ziti-router.yaml --extend --verbose
Could be a race condition connecting to the controller or the controller wasn't running. What does the rest of your log say about connecting to the controller?
Thanks @andrew.martinez! Here's the full DEBUG log for a single invocation of ziti router run /etc/ziti/config/ziti-router.yaml --extend --verbose for this 0.30.3 router.
[ 0.000] DEBUG ziti/ziti/util.LogReleaseVersionCheck: ZITI_CHECK_VERSION is not 'true'. skipping version check
[ 0.003] INFO ziti/ziti/router.run: {configFile=[/etc/ziti/config/ziti-router.yaml] routerId=[l8NXiYp8a] os=[linux] arch=[amd64] build-date=[2023-09-01T21:03:45Z] version=[v0.30.3] revision=[c7a0a41867c4] go-version=[go1.20.7]} starting ziti-router
[ 0.003] INFO fabric/common/metrics.GoroutinesPoolMetricsConfigF.func1.1: {minWorkers=[0] maxWorkers=[32] idleTime=[30s] poolType=[pool.link.dialer] maxQueueSize=[1000]} starting goroutine pool
[ 0.003] INFO fabric/common/metrics.GoroutinesPoolMetricsConfigF.func1.1: {idleTime=[30s] poolType=[pool.route.handler] minWorkers=[0] maxQueueSize=[1000] maxWorkers=[128]} starting goroutine pool
[ 0.003] INFO fabric/router/forwarder.(*Faulter).run: started
[ 0.003] INFO fabric/router/forwarder.(*Scanner).run: started
[ 0.004] WARNING edge/router/internal/edgerouter.(*Config).LoadConfigFromMap: Invalid heartbeat interval [0] (min: 60, max: 10), setting to default [60]
[ 0.004] WARNING edge/router/internal/edgerouter.parseEdgeListenerOptions: port in [listeners[0].options.advertise] must equal port in [listeners[0].address] for edge binding but did not. Got [443] [3022]
[ 0.004] DEBUG edge/router/internal/apiproxy.Start: API Proxy disabled
[ 0.004] INFO fabric/router.(*Router).showOptions: ctrl = {"OutQueueSize":4,"MaxQueuedConnects":1,"MaxOutstandingConnects":16,"ConnectTimeout":5000000000,"DelayRxStart":false,"WriteTimeout":0}
[ 0.004] INFO fabric/router.(*Router).showOptions: metrics = {"ReportInterval":60000000000,"IntervalAgeThreshold":0,"MessageQueueSize":10}
[ 0.004] INFO fabric/common/metrics.GoroutinesPoolMetricsConfigF.func1.1: {idleTime=[30s] maxQueueSize=[5000] minWorkers=[0] maxWorkers=[32] poolType=[pool.link.dialer]} starting goroutine pool
[ 0.004] INFO fabric/router.(*Router).initializeHealthChecks: starting health check with ctrl ping initially after 15s, then every 30s, timing out after 15s
[ 0.004] DEBUG xweb/v2.RegistryMap.Add: adding xweb factory with binding: health-checks
[ 0.004] INFO fabric/router.(*Router).startXlinkDialers: started Xlink dialer with binding [transport]
[ 0.007] WARNING fabric/router/xlink_transport.loadListenerConfig: {error=[no network interface found for 0.0.0.0] addr=[tls:0.0.0.0:10080]} unable to get interface for address
[ 0.007] INFO fabric/common/metrics.GoroutinesPoolMetricsConfigF.func1.1: {minWorkers=[1] maxQueueSize=[1] maxWorkers=[16] idleTime=[10s] poolType=[pool.listener.link]} starting goroutine pool
[ 0.007] INFO fabric/router.(*Router).startXlinkListeners: started Xlink listener with binding [transport] advertising [tls:miniziti-router-transport.192.168.58.2.sslip.io:443]
[ 0.007] DEBUG edge/router/xgress_edge.(*Factory).CreateListener: xgress edge listener options: mtu=65536
randomDrops=false
drop1InN=100
txQueueSize=1
txPortalStartSize=16384
txPortalMaxSize=4194304
txPortalMinSize=16384
txPortalIncreaseThresh=224
txPortalIncreaseScale=1
txPortalRetxThresh=64
txPortalRetxScale=0.75
txPortalDupAckThresh=64
txPortalDupAckScale=0.9
rxBufferSize=4194304
retxStartMs=200
retxScale=1.5
retxAddMs=0
maxCloseWait=30s
getCircuitTimeout=30s
lookupApiSessionTimeout=5s
lookupSessionTimeout=5s
channel.outQueueSize=4
channel.connectTimeout=1s
channel.maxOutstandingConnects=16
channel.maxQueuedConnects=1
[ 0.007] INFO edge/router/xgress_edge.(*listener).Listen: {address=[tls:0.0.0.0:3022]} starting channel listener
[ 0.007] INFO fabric/common/metrics.GoroutinesPoolMetricsConfigF.func1.1: {idleTime=[10s] maxQueueSize=[1] maxWorkers=[16] poolType=[pool.listener.xgress_edge] minWorkers=[1]} starting goroutine pool
[ 0.007] INFO fabric/router.(*Router).startXgressListeners: created xgress listener [edge] at [tls:0.0.0.0:3022]
[ 0.007] INFO fabric/router.(*Router).startXgressListeners: created xgress listener [tunnel] at []
[ 0.007] INFO fabric/router.(*Router).getInitialCtrlEndpoints: controller endpoints file [/etc/ziti/config/endpoints] doesn't exist. Using initial endpoints from config
[ 0.007] INFO fabric/router.(*Router).startControlPlane: router configured with 1 controller endpoints
[ 0.007] INFO edge/router/xgress_edge.(*Acceptor).Run: starting
[ 0.007] INFO fabric/router/env.(*networkControllers).UpdateControllerEndpoints: {endpoint=[map[tls:ziti-controller-ctrl.kentest1.svc:443:{}]]} adding new ctrl endpoint
[ 0.007] INFO fabric/router/env.(*networkControllers).connectToControllerWithBackoff: {endpoint=[tls:ziti-controller-ctrl.kentest1.svc:443]} starting connection attempts
[ 0.007] INFO edge/router/fabric.(*StateManagerImpl).StartHeartbeat: heartbeat starting
[ 0.007] INFO edge/router/xgress_edge_tunnel.(*tunneler).Start: {mode=[host]} creating interceptor
[ 0.007] INFO edge/router/xgress_edge.(*CertExpirationChecker).getWaitTime: enrollment extension was forced
[ 0.008] WARNING edge/tunnel/dns.flushDnsCaches: {error=[exec: "resolvectl": executable file not found in $PATH]} unable to find systemd-resolve or resolvectl in path, consider adding a dns flush to your restart process
[ 0.008] INFO edge/router/xgress_edge.(*CertExpirationChecker).Run: waiting 0s to renew certificates
[ 0.008] ERROR edge/router/xgress_edge.(*CertExpirationChecker).Run: could not extend enrollment: cannot request updates, no controller is available
[ 0.008] DEBUG channel/v2.(*reconnectingDialer).Create [tls:ziti-controller-ctrl.kentest1.svc:443]: started
[ 0.037] DEBUG transport/v2/tls.DialWithLocalBinding: {dest=[ziti-controller-ctrl.kentest1.svc:443]} server provided [3] certificates
[ 0.037] DEBUG channel/v2.(*reconnectingDialer).sendHello [u{reconnecting}->i{}]: started
[ 0.040] DEBUG channel/v2.(*reconnectingDialer).sendHello [u{reconnecting}->i{}]: exited
[ 0.040] DEBUG channel/v2.(*reconnectingDialer).Create [tls:ziti-controller-ctrl.kentest1.svc:443]: exited
[ 0.040] DEBUG edge/router/handler_edge_ctrl.NewHelloHandler: HelloHandler will contain supportedProtocols address: tls:0.0.0.0:3022 advertise: miniziti-router.192.168.58.2.sslip.io:443
[ 0.040] INFO fabric/router/env.(*networkControllers).connectToControllerWithBackoff.func3: {endpoint=[tls:ziti-controller-ctrl.kentest1.svc:443]} successfully connected to controller
[ 0.040] DEBUG channel/v2.(*channelImpl).txer [ch{ctrl}->u{reconnecting}->i{NOax}]: started
[ 0.040] DEBUG channel/v2.(*channelImpl).rxer [ch{ctrl}->u{reconnecting}->i{NOax}]: started
[ 0.041] DEBUG fabric/router/handler_ctrl.(*validateTerminatorsHandler).validateTerminators: validate terminators route request received: 1 terminators
[ 0.041] DEBUG edge/router/xgress_edge.(*dialer).IsTerminatorValid: looking up hosted service conn
[ 0.041] INFO fabric/router/handler_ctrl.(*validateTerminatorsHandler).validateTerminators: removing invalid terminator 4uUIp9DJ3mNPtMacc5VCfS with binding: edge. had dialer? true
[ 0.041] INFO fabric/router/handler_ctrl.(*validateTerminatorsHandler).validateTerminators: send batch of 1 terminator deletes
[ 0.042] INFO edge/router/handler_edge_ctrl.(*helloHandler).HandleReceive.func1: received server hello, replying
[ 0.042] INFO edge/router/fabric.(*StateManagerImpl).AddSignerPublicCert: {added=[1] received=[1] ignored=[0]} received signer public certificates
[ 0.043] DEBUG fabric/router/xgress.RemoveTerminators: successfully removed terminators
[ 0.044] DEBUG edge/router/fabric.(*StateManagerImpl).AddApiSession: {apiSessionId=[clmj7l1vb03hl0s4zz7k3esm4] apiSessionToken=[e0616390-b5f5-4444-b5d1-ab8944525c3a] apiSessionCertFingerprints=[[]]} adding apiSession
[ 0.044] DEBUG edge/router/fabric.(*StateManagerImpl).AddApiSession: {apiSessionId=[clmj7l42i03hp0s4zz593vkj9] apiSessionToken=[798fb972-c680-4ba4-ae34-8b11d2041466] apiSessionCertFingerprints=[[76761a21b11c0aa33094f9b3c58da83976f30e5b]]} adding apiSession
[ 0.044] DEBUG edge/router/fabric.(*StateManagerImpl).AddApiSession: {apiSessionId=[clmjfkhrd0du70s4z3jvgpo0x] apiSessionToken=[8a44c9cd-81b5-4379-9a6b-e61a1339cb3e] apiSessionCertFingerprints=[[]]} adding apiSession
[ 0.044] DEBUG edge/router/fabric.(*StateManagerImpl).AddApiSession: {apiSessionToken=[1d27cde1-a73a-46b1-876d-7cf369b02c10] apiSessionCertFingerprints=[[]] apiSessionId=[clmjfkiea0dub0s4zukvf1a67]} adding apiSession
[ 0.044] DEBUG edge/router/fabric.(*StateManagerImpl).AddApiSession: {apiSessionId=[clmjfkj1s0dud0s4z94bndb3m] apiSessionToken=[3707a950-1be2-427b-856f-f93fb0c8263a] apiSessionCertFingerprints=[[]]} adding apiSession
[ 0.044] DEBUG edge/router/fabric.(*StateManagerImpl).AddApiSession: {apiSessionId=[clmjfsfkf0e4n0s4z1a3kguwg] apiSessionToken=[a77ae8f3-0663-4053-bbe2-0e99f96a873c] apiSessionCertFingerprints=[[]]} adding apiSession
[ 0.044] DEBUG edge/router/fabric.(*StateManagerImpl).AddApiSession: {apiSessionToken=[09b682ac-b29c-4548-bd0e-72b6c26e792b] apiSessionCertFingerprints=[[]] apiSessionId=[clmjfsg6i0e4r0s4z7yk381s1]} adding apiSession
[ 0.044] DEBUG edge/router/fabric.(*StateManagerImpl).AddApiSession: {apiSessionId=[clmjfsgvm0e4t0s4z61dsnvpa] apiSessionToken=[abac920b-bf4b-4743-8e6f-e9bfe102974c] apiSessionCertFingerprints=[[]]} adding apiSession
[ 0.044] INFO edge/router/handler_edge_ctrl.(*apiSessionAddedHandler).instantSync: {strategy=[instant]} first api session syncId [clmjfsjyc0e4z0s4ztzdj5med], starting
[ 0.045] INFO edge/router/handler_edge_ctrl.(*apiSessionSyncTracker).Add: received api session sync chunk 0, isLast=true
[ 0.480] INFO edge/tunnel/intercept.SetDnsInterceptIpRange: dns intercept IP range: 100.64.0.1 - 100.127.255.254
[ 0.493] DEBUG edge/router/handler_edge_ctrl.(*ServiceListHandler).HandleReceive: received services list with 0 entries
[ 0.493] DEBUG edge/router/xgress_edge_tunnel.(*servicePoller).handleServiceListUpdate: procesing service updates with 0 services
[ 1.045] INFO edge/router/handler_edge_ctrl.(*apiSessionAddedHandler).applySync: finished sychronizing api sessions [count: 8, syncId: clmjfsjyc0e4z0s4ztzdj5med, duration: 59.026µs]
[ 2.763] DEBUG edge/router/fabric.(*StateManagerImpl).AddApiSession: {apiSessionId=[clmjfsm1o0e520s4zotd53bpq] apiSessionToken=[8aa51649-95ff-47ce-a53e-f0a13ee30205] apiSessionCertFingerprints=[[]]} adding apiSession
[ 4.322] DEBUG edge/router/fabric.(*StateManagerImpl).AddApiSession: {apiSessionId=[clmjfsn920e560s4zqyv0jeux] apiSessionToken=[3e2163c1-0abd-4e27-b72e-9cefb31eb962] apiSessionCertFingerprints=[[]]} adding apiSession
[ 5.113] DEBUG edge/router/fabric.(*StateManagerImpl).AddApiSession: {apiSessionId=[clmjfsnv40e5a0s4zp7ixclmf] apiSessionToken=[d59c7f8f-5172-412d-8a63-744461a6d21d] apiSessionCertFingerprints=[[]]} adding apiSession
[ 5.818] DEBUG transport/v2/tls.(*sharedListener).getConfig [tls:0.0.0.0:3022]: {client=[10.244.0.7:41464]} client requesting protocols = []
[ 5.818] DEBUG transport/v2/tls.(*sharedListener).getConfig [tls:0.0.0.0:3022]: {client=[10.244.0.7:41464]} found handler for proto[]
[ 5.857] DEBUG transport/v2/tls.(*sharedListener).processConn [tls:0.0.0.0:3022]: {client=[10.244.0.7:41464]} selected protocol = ''
[ 5.857] DEBUG channel/v2.(*classicListener).receiveHello [u{classic}->i{VEvw}]: started
[ 5.857] DEBUG channel/v2.(*classicListener).receiveHello [u{classic}->i{VEvw}]: exited
[ 5.858] DEBUG edge/router/xgress_edge.(*Acceptor).BindChannel: {token=[kpop4]} accepting edge connection
[ 5.858] DEBUG edge/router/xgress_edge.(*Acceptor).BindChannel: peer fingerprints map[76761a21b11c0aa33094f9b3c58da83976f30e5b:0xc000f90580]
[ 5.858] DEBUG channel/v2.(*channelImpl).txer [ch{edge}->u{classic}->i{VEvw}]: started
[ 5.858] DEBUG channel/v2.(*channelImpl).rxer [ch{edge}->u{classic}->i{VEvw}]: started
[ 5.858] DEBUG edge/router/xgress_edge.(*edgeClientConn).processBind [ch{edge}->u{classic}->i{VEvw}]: {sessionId=[169a1444-ca82-43d0-89a9-9b1c22f44c94] connId=[1] type=[EdgeBindType] chSeq=[1] edgeSeq=[0] routerId=[l8NXiYp8a]} binding service
[ 5.858] DEBUG edge/router/xgress_edge.(*edgeClientConn).processBind [ch{edge}->u{classic}->i{VEvw}]: {sessionId=[169a1444-ca82-43d0-89a9-9b1c22f44c94] connId=[1] type=[EdgeBindType] chSeq=[1] edgeSeq=[0] routerId=[l8NXiYp8a]} client requested router provided connection ids: true
[ 5.858] DEBUG edge/router/xgress_edge.(*edgeClientConn).processBind [ch{edge}->u{classic}->i{VEvw}]: {connId=[1] type=[EdgeBindType] chSeq=[1] edgeSeq=[0] routerId=[l8NXiYp8a] sessionId=[169a1444-ca82-43d0-89a9-9b1c22f44c94]} establishing listener
[ 5.860] DEBUG edge/router/xgress_edge.(*edgeClientConn).processBind [ch{edge}->u{classic}->i{VEvw}]: {type=[EdgeBindType] chSeq=[1] edgeSeq=[0] routerId=[l8NXiYp8a] sessionId=[169a1444-ca82-43d0-89a9-9b1c22f44c94] terminatorId=[] connId=[1]} registered listener for terminator
[ 5.860] DEBUG edge/router/xgress_edge.(*edgeClientConn).processBind [ch{edge}->u{classic}->i{VEvw}]: {chSeq=[1] edgeSeq=[0] routerId=[l8NXiYp8a] sessionId=[169a1444-ca82-43d0-89a9-9b1c22f44c94] terminatorId=[] connId=[1] type=[EdgeBindType]} returning connection state CONNECTED to client
[ 5.860] INFO edge/router/xgress_edge.(*edgeClientConn).processBind [ch{edge}->u{classic}->i{VEvw}]: {sessionId=[169a1444-ca82-43d0-89a9-9b1c22f44c94] terminatorId=[] connId=[1] type=[EdgeBindType] chSeq=[1] edgeSeq=[0] routerId=[l8NXiYp8a]} created terminator
[ 5.916] DEBUG edge/router/fabric.(*StateManagerImpl).AddApiSession: {apiSessionId=[clmjfsohf0e5c0s4ze68y27vs] apiSessionToken=[97e28d21-4a0a-4276-b04b-ef7fb1163eff] apiSessionCertFingerprints=[[]]} adding apiSession
[ 6.767] DEBUG edge/router/fabric.(*StateManagerImpl).AddApiSession: {apiSessionId=[clmjfsp530e5e0s4z0gvemkxd] apiSessionToken=[ccd2681a-e9cb-488e-a7b2-816d5c7edc96] apiSessionCertFingerprints=[[]]} adding apiSession
[ 7.539] DEBUG edge/router/fabric.(*StateManagerImpl).AddApiSession: {apiSessionId=[clmjfspqf0e5i0s4zir9n46py] apiSessionToken=[fc9a50f6-4eae-41cd-94ee-9c5d69f9177a] apiSessionCertFingerprints=[[]]} adding apiSession
[ 8.376] DEBUG edge/router/fabric.(*StateManagerImpl).AddApiSession: {apiSessionId=[clmjfsqdr0e5k0s4zjzgsgy1l] apiSessionToken=[fb14d4d4-883b-45ff-b883-328577422c64] apiSessionCertFingerprints=[[]]} adding apiSession
[ 9.193] DEBUG edge/router/fabric.(*StateManagerImpl).AddApiSession: {apiSessionId=[clmjfsr0e0e5o0s4zqkdrrvpz] apiSessionToken=[127a6950-d7f5-449d-a969-bc5032445e71] apiSessionCertFingerprints=[[]]} adding apiSession
[ 10.010] DEBUG edge/router/fabric.(*StateManagerImpl).AddApiSession: {apiSessionId=[clmjfsrn50e5q0s4zgyjhe3vl] apiSessionToken=[e5faae66-3b97-4c93-bbd3-492cbcfa97b6] apiSessionCertFingerprints=[[]]} adding apiSession
[ 10.810] DEBUG edge/router/fabric.(*StateManagerImpl).AddApiSession: {apiSessionId=[clmjfss990e5s0s4zs863x0e7] apiSessionToken=[d3d85ce1-4a79-4472-850b-12faaaeb880f] apiSessionCertFingerprints=[[]]} adding apiSession
[ 35.009] INFO edge/router/xgress_edge.(*CertExpirationChecker).Run: waiting 8600h5m24.813669292s to renew certificates
[ 60.004] DEBUG fabric/router/forwarder.(*Scanner).scan: scanning [0] circuits