Problem with token reservation

giorgiobazzo · March 9, 2024, 3:28pm

I'm facing an issue with reserved share tokens.

Steps to reproduce the issue:

1 - Activate the environment: zrok enable --redacted--

2 - Reserve a token: zrok reserve public http://localhost:9496
Token obtained: b1bo38twnrz2

3 - Start the tunnel: zrok share reserved b1bo38twnrz2 --override-endpoint http://localhost:9496

So far, everything is working fine.
The endpoint https://b1bo38twnrz2.share.zrok.io is responding.

4 - Log in to your account at: https://api.zrok.io

5 - Remove the environment created in step 1 id: i0nfvLD2ldmh

6 - Disable the environment on the server: zrok disable

7 - Activate the environment again: zrok enable i0nfvLD2ldmh

8 - Reserve the same token obtained previously: zrok reserve public http://localhost:9496 -n b1bo38twnrz2

9 - Start the tunnel again: zrok share reserved b1bo38twnrz2 --override-endpoint http://localhost:9496

Apparently everything seems to work as expected, no errors are displayed. However, the endpoint https://b1bo38twnrz2.share.zrok.io no longer responds. always returning a 404 error.

qrkourier · March 9, 2024, 8:36pm

That's unexpected. It should work that way. I followed your script and was able to use the reserved share both ways:

starting with a unique name, disable, enable, reserve same name
starting with a random reservation, disable, enable, reserve same unique name that was randomly generated the first time

The reservation is linked to the account, and disabling the environment should cause all of that env's reservations to be released. You can also release a reservation individually with the CLI, zrok release {token}.

The 404 is observed in the frontend or backend? You can run zrok share reserved {token} --headless --verbose to get the debug output.

giorgiobazzo · March 9, 2024, 8:54pm

This is the output after trying to use the reserved one again:

D:\PROJETO-DX10\PCA\Build\Win64\Release\Bin>zrok share reserved qm9gzzhzf096 --headless --verbose
[ 0.761] INFO main.(*shareReservedCommand).run: sharing target: 'http://localhost:9496'
[ 0.765] INFO main.(*shareReservedCommand).run: using existing backend proxy endpoint: http://localhost:9496
[ 0.765] DEBUG sdk-golang/ziti.(*ContextImpl).authenticate: attempting to authenticate
[ 1.689] DEBUG sdk-golang/ziti.(*ContextImpl).refreshServices: checking if service updates available
[ 1.833] DEBUG sdk-golang/ziti.(*ContextImpl).refreshServices: refreshing services
[ 1.978] DEBUG sdk-golang/ziti.(*ContextImpl).processServiceUpdates: processing service updates with 1 services
[ 1.978] DEBUG sdk-golang/ziti/edge.ParseServiceConfig: {serviceId=[45GroR0YVbWIpDMvNnrx0C] serviceName=[0xc0004ab8c0]} no service config of type intercept.v1 defined for service
[ 1.978] DEBUG sdk-golang/ziti/edge.ParseServiceConfig: {serviceId=[45GroR0YVbWIpDMvNnrx0C] serviceName=[0xc0004ab8c0]} no service config of type ziti-tunneler-client.v1 defined for service
[ 1.978] DEBUG sdk-golang/ziti.(*ContextImpl).createSession: establishing Bind session to service qm9gzzhzf096
[ 2.125] DEBUG sdk-golang/ziti.(*ContextImpl).createSession: successfully created Bind session to service qm9gzzhzf096 in 147ms
[ 2.127] INFO sdk-golang/ziti.(*listenerManager).createSessionWithBackoff: {session token=[9b9667d3-6136-4cd3-8423-2d82877937e5]} new service session
[ 2.127] DEBUG sdk-golang/ziti.(*ContextImpl).connectEdgeRouter: connection to edge router using api session token [99 54 102 52 98 52 102 99 45 49 55 57 101 45 52 53 51 97 45 97 100 55 48 45 56 54 52 49 100 50 52 49 101 101 98 97]
[ 2.127] DEBUG sdk-golang/ziti.(*ContextImpl).connectEdgeRouter: connection to edge router using api session token [99 54 102 52 98 52 102 99 45 49 55 57 101 45 52 53 51 97 45 97 100 55 48 45 56 54 52 49 100 50 52 49 101 101 98 97]
[ 2.127] DEBUG sdk-golang/ziti.(*ContextImpl).connectEdgeRouter: connection to edge router using api session token [99 54 102 52 98 52 102 99 45 49 55 57 101 45 52 53 51 97 45 97 100 55 48 45 56 54 52 49 100 50 52 49 101 101 98 97]
[ 2.127] DEBUG channel/v2.(*classicDialer).Create [tls:ed9935f5-5d9d-4898-a3cf-4a8a05b4e4a6.production.netfoundry.io:443]: started
[ 2.127] DEBUG channel/v2.(*classicDialer).Create [tls:ed9935f5-5d9d-4898-a3cf-4a8a05b4e4a6.production.netfoundry.io:443]: Attempting to dial with bind:
[ 2.127] DEBUG channel/v2.(*classicDialer).Create [tls:92c34dbe-a505-48d8-81f9-ae47bdcad1fe.production.netfoundry.io:443]: started
[ 2.127] DEBUG channel/v2.(*classicDialer).Create [tls:92c34dbe-a505-48d8-81f9-ae47bdcad1fe.production.netfoundry.io:443]: Attempting to dial with bind:
[ 2.128] DEBUG sdk-golang/ziti.(*ContextImpl).connectEdgeRouter: connection to edge router using api session token [99 54 102 52 98 52 102 99 45 49 55 57 101 45 52 53 51 97 45 97 100 55 48 45 56 54 52 49 100 50 52 49 101 101 98 97]
[ 2.129] DEBUG sdk-golang/ziti.(*ContextImpl).connectEdgeRouter: connection to edge router using api session token [99 54 102 52 98 52 102 99 45 49 55 57 101 45 52 53 51 97 45 97 100 55 48 45 56 54 52 49 100 50 52 49 101 101 98 97]
[ 2.129] DEBUG channel/v2.(*classicDialer).Create [tls:1ba54d52-ffdb-4ac1-8e32-dc39ca0f89a1.production.netfoundry.io:443]: started
[ 2.130] DEBUG channel/v2.(*classicDialer).Create [tls:1ba54d52-ffdb-4ac1-8e32-dc39ca0f89a1.production.netfoundry.io:443]: Attempting to dial with bind:
[ 2.131] DEBUG channel/v2.(*classicDialer).Create [tls:60042e42-5eef-4378-9ade-538b5cde57a0.production.netfoundry.io:443]: started
[ 2.131] DEBUG channel/v2.(*classicDialer).Create [tls:60042e42-5eef-4378-9ade-538b5cde57a0.production.netfoundry.io:443]: Attempting to dial with bind:
[ 2.131] DEBUG sdk-golang/ziti.(*ContextImpl).connectEdgeRouter: connection to edge router using api session token [99 54 102 52 98 52 102 99 45 49 55 57 101 45 52 53 51 97 45 97 100 55 48 45 56 54 52 49 100 50 52 49 101 101 98 97]
[ 2.132] DEBUG channel/v2.(*classicDialer).Create [tls:def60534-ff9a-44db-bb9e-46b65c67b5ce.production.netfoundry.io:443]: started
[ 2.134] DEBUG sdk-golang/ziti.(*ContextImpl).connectEdgeRouter: connection to edge router using api session token [99 54 102 52 98 52 102 99 45 49 55 57 101 45 52 53 51 97 45 97 100 55 48 45 56 54 52 49 100 50 52 49 101 101 98 97]
[ 2.134] DEBUG sdk-golang/ziti.(*ContextImpl).connectEdgeRouter: connection to edge router using api session token [99 54 102 52 98 52 102 99 45 49 55 57 101 45 52 53 51 97 45 97 100 55 48 45 56 54 52 49 100 50 52 49 101 101 98 97]
[ 2.134] DEBUG sdk-golang/ziti.(*ContextImpl).connectEdgeRouter: connection to edge router using api session token [99 54 102 52 98 52 102 99 45 49 55 57 101 45 52 53 51 97 45 97 100 55 48 45 56 54 52 49 100 50 52 49 101 101 98 97]
[ 2.137] DEBUG channel/v2.(*classicDialer).Create [tls:db67f324-69ab-4c7a-a258-36566b387b90.production.netfoundry.io:443]: started
[ 2.137] DEBUG channel/v2.(*classicDialer).Create [tls:db67f324-69ab-4c7a-a258-36566b387b90.production.netfoundry.io:443]: Attempting to dial with bind:
[ 2.137] DEBUG channel/v2.(*classicDialer).Create [tls:f12da3a5-c651-4dbe-ace0-67723a5dda65.production.netfoundry.io:443]: started
[ 2.137] DEBUG channel/v2.(*classicDialer).Create [tls:def60534-ff9a-44db-bb9e-46b65c67b5ce.production.netfoundry.io:443]: Attempting to dial with bind:
[ 2.137] DEBUG channel/v2.(*classicDialer).Create [tls:f12da3a5-c651-4dbe-ace0-67723a5dda65.production.netfoundry.io:443]: Attempting to dial with bind:
[ 2.138] DEBUG channel/v2.(*classicDialer).Create [tls:8a458215-47d2-4a51-a854-d974443e7851.production.netfoundry.io:443]: started
[ 2.138] DEBUG channel/v2.(*classicDialer).Create [tls:8a458215-47d2-4a51-a854-d974443e7851.production.netfoundry.io:443]: Attempting to dial with bind:
[ 2.138] DEBUG channel/v2.(*classicDialer).Create [tls:69e048d6-5988-4dd6-886b-fb1f33cdff4f.production.netfoundry.io:443]: started
[ 2.138] DEBUG channel/v2.(*classicDialer).Create [tls:69e048d6-5988-4dd6-886b-fb1f33cdff4f.production.netfoundry.io:443]: Attempting to dial with bind:
[ 2.439] DEBUG transport/v2/tls.DialWithLocalBinding: {dest=[def60534-ff9a-44db-bb9e-46b65c67b5ce.production.netfoundry.io:443]} server provided [1] certificates
[ 2.439] DEBUG channel/v2.(*classicDialer).sendHello [u{classic}->i{}]: started
[ 2.446] DEBUG transport/v2/tls.DialWithLocalBinding: {dest=[92c34dbe-a505-48d8-81f9-ae47bdcad1fe.production.netfoundry.io:443]} server provided [1] certificates
[ 2.446] DEBUG channel/v2.(*classicDialer).sendHello [u{classic}->i{}]: started
[ 2.450] DEBUG transport/v2/tls.DialWithLocalBinding: {dest=[8a458215-47d2-4a51-a854-d974443e7851.production.netfoundry.io:443]} server provided [1] certificates
[ 2.450] DEBUG channel/v2.(*classicDialer).sendHello [u{classic}->i{}]: started
[ 2.569] DEBUG transport/v2/tls.DialWithLocalBinding: {dest=[db67f324-69ab-4c7a-a258-36566b387b90.production.netfoundry.io:443]} server provided [1] certificates
[ 2.571] DEBUG channel/v2.(*classicDialer).sendHello [u{classic}->i{}]: started
[ 2.571] DEBUG channel/v2.(*classicDialer).sendHello [u{classic}->i{}]: exited
[ 2.571] DEBUG channel/v2.(*classicDialer).Create [tls:def60534-ff9a-44db-bb9e-46b65c67b5ce.production.netfoundry.io:443]: exited
[ 2.571] DEBUG sdk-golang/ziti.(*ContextImpl).connectEdgeRouter: routerConn[Public OCI US East(custom config)@tls:def60534-ff9a-44db-bb9e-46b65c67b5ce.production.netfoundry.io:443] connected in 438 ms
[ 2.571] DEBUG sdk-golang/ziti.(*ContextImpl).connectEdgeRouter: {buildDate=[2020-01-01 01:01:01] os=[linux] arch=[amd64] version=[v0.32.2] revision=[local]} connected to edge router
[ 2.571] DEBUG channel/v2.(*channelImpl).rxer [ch{ziti-sdk[router=tls:def60534-ff9a-44db-bb9e-46b65c67b5ce.production.netfoundry.io:443]}->u{classic}->i{qDGj}]: started
[ 2.571] DEBUG sdk-golang/ziti.(*ContextImpl).connectEdgeRouter: connected to tls:def60534-ff9a-44db-bb9e-46b65c67b5ce.production.netfoundry.io:443
[ 2.571] DEBUG sdk-golang/ziti.(*listenerManager).handleRouterConnectResult: {listenerCount=[1] serviceName=[qm9gzzhzf096]} establishing listener to tls:def60534-ff9a-44db-bb9e-46b65c67b5ce.production.netfoundry.io:443
[ 2.571] DEBUG sdk-golang/ziti/edge/network.(*routerConn).NewListenConn: {serviceId=[45GroR0YVbWIpDMvNnrx0C] routerName=[Public OCI US East(custom config)] connId=[1] serviceName=[qm9gzzhzf096]} created new listener connection
[ 2.571] DEBUG sdk-golang/ziti/edge/network.(*edgeConn).listen [ch{ziti-sdk[router=tls:def60534-ff9a-44db-bb9e-46b65c67b5ce.production.netfoundry.io:443]}->u{classic}->i{qDGj}]: {serviceName=[qm9gzzhzf096] sessionId=[cltkk3oz3nwm63xqc244yeufs] connId=[1]} adding listener for session
[ 2.571] DEBUG sdk-golang/ziti/edge/network.(*edgeConn).listen [ch{ziti-sdk[router=tls:def60534-ff9a-44db-bb9e-46b65c67b5ce.production.netfoundry.io:443]}->u{classic}->i{qDGj}]: {connId=[1] serviceName=[qm9gzzhzf096] sessionId=[cltkk3oz3nwm63xqc244yeufs]} sending bind request to edge router
[ 2.571] DEBUG channel/v2.(*channelImpl).txer [ch{ziti-sdk[router=tls:def60534-ff9a-44db-bb9e-46b65c67b5ce.production.netfoundry.io:443]}->u{classic}->i{qDGj}]: started
[ 2.571] DEBUG channel/v2/latency.ProbeLatencyConfigurable [ch{ziti-sdk[router=tls:def60534-ff9a-44db-bb9e-46b65c67b5ce.production.netfoundry.io:443]}->u{classic}->i{qDGj}]: started
[ 2.577] DEBUG transport/v2/tls.DialWithLocalBinding: {dest=[60042e42-5eef-4378-9ade-538b5cde57a0.production.netfoundry.io:443]} server provided [1] certificates
[ 2.578] DEBUG channel/v2.(*classicDialer).sendHello [u{classic}->i{}]: started
[ 2.581] DEBUG transport/v2/tls.DialWithLocalBinding: {dest=[69e048d6-5988-4dd6-886b-fb1f33cdff4f.production.netfoundry.io:443]} server provided [1] certificates
[ 2.582] DEBUG channel/v2.(*classicDialer).sendHello [u{classic}->i{}]: started
[ 2.585] DEBUG channel/v2.(*classicDialer).sendHello [u{classic}->i{}]: exited
[ 2.586] DEBUG channel/v2.(*classicDialer).Create [tls:92c34dbe-a505-48d8-81f9-ae47bdcad1fe.production.netfoundry.io:443]: exited
[ 2.586] DEBUG sdk-golang/ziti.(*ContextImpl).connectEdgeRouter: routerConn[AWS US East 1-1(custom config)@tls:92c34dbe-a505-48d8-81f9-ae47bdcad1fe.production.netfoundry.io:443] connected in 458 ms
[ 2.586] DEBUG channel/v2.(*channelImpl).rxer [ch{ziti-sdk[router=tls:92c34dbe-a505-48d8-81f9-ae47bdcad1fe.production.netfoundry.io:443]}->u{classic}->i{3n9J}]: started
[ 2.586] DEBUG sdk-golang/ziti.(*ContextImpl).connectEdgeRouter: {os=[linux] arch=[amd64] version=[v0.32.2] buildDate=[2020-01-01 01:01:01] revision=[local]} connected to edge router
[ 2.586] DEBUG sdk-golang/ziti.(*ContextImpl).connectEdgeRouter: connected to tls:92c34dbe-a505-48d8-81f9-ae47bdcad1fe.production.netfoundry.io:443
[ 2.586] DEBUG channel/v2.(*channelImpl).txer [ch{ziti-sdk[router=tls:92c34dbe-a505-48d8-81f9-ae47bdcad1fe.production.netfoundry.io:443]}->u{classic}->i{3n9J}]: started
[ 2.586] DEBUG sdk-golang/ziti.(*listenerManager).handleRouterConnectResult: ignoring connection to tls:92c34dbe-a505-48d8-81f9-ae47bdcad1fe.production.netfoundry.io:443, already have max connections 1
[ 2.586] DEBUG channel/v2/latency.ProbeLatencyConfigurable [ch{ziti-sdk[router=tls:92c34dbe-a505-48d8-81f9-ae47bdcad1fe.production.netfoundry.io:443]}->u{classic}->i{3n9J}]: started
[ 2.589] DEBUG channel/v2.(*classicDialer).sendHello [u{classic}->i{}]: exited
[ 2.589] DEBUG channel/v2.(*classicDialer).Create [tls:8a458215-47d2-4a51-a854-d974443e7851.production.netfoundry.io:443]: exited
[ 2.589] DEBUG sdk-golang/ziti.(*ContextImpl).connectEdgeRouter: routerConn[AWS US East 1-2(custom config)@tls:8a458215-47d2-4a51-a854-d974443e7851.production.netfoundry.io:443] connected in 460 ms
[ 2.589] DEBUG sdk-golang/ziti.(*ContextImpl).connectEdgeRouter: {arch=[amd64] version=[v0.32.2] os=[linux] revision=[local] buildDate=[2020-01-01 01:01:01]} connected to edge router
[ 2.589] DEBUG sdk-golang/ziti.(*ContextImpl).connectEdgeRouter: connected to tls:8a458215-47d2-4a51-a854-d974443e7851.production.netfoundry.io:443
[ 2.589] DEBUG sdk-golang/ziti.(*listenerManager).handleRouterConnectResult: ignoring connection to tls:8a458215-47d2-4a51-a854-d974443e7851.production.netfoundry.io:443, already have max connections 1
[ 2.589] DEBUG channel/v2.(*channelImpl).rxer [ch{ziti-sdk[router=tls:8a458215-47d2-4a51-a854-d974443e7851.production.netfoundry.io:443]}->u{classic}->i{xLg6o}]: started
[ 2.589] DEBUG channel/v2.(*channelImpl).txer [ch{ziti-sdk[router=tls:8a458215-47d2-4a51-a854-d974443e7851.production.netfoundry.io:443]}->u{classic}->i{xLg6o}]: started
[ 2.589] DEBUG channel/v2/latency.ProbeLatencyConfigurable [ch{ziti-sdk[router=tls:8a458215-47d2-4a51-a854-d974443e7851.production.netfoundry.io:443]}->u{classic}->i{xLg6o}]: started
[ 2.629] DEBUG transport/v2/tls.DialWithLocalBinding: {dest=[f12da3a5-c651-4dbe-ace0-67723a5dda65.production.netfoundry.io:443]} server provided [1] certificates
[ 2.629] DEBUG channel/v2.(*classicDialer).sendHello [u{classic}->i{}]: started
[ 2.700] DEBUG sdk-golang/ziti/edge/network.(*edgeConn).listen [ch{ziti-sdk[router=tls:def60534-ff9a-44db-bb9e-46b65c67b5ce.production.netfoundry.io:443]}->u{classic}->i{qDGj}]: {connId=[1] serviceName=[qm9gzzhzf096] sessionId=[cltkk3oz3nwm63xqc244yeufs]} connected
[ 2.700] DEBUG sdk-golang/ziti/edge/network.(*routerConn).Listen: {serviceId=[45GroR0YVbWIpDMvNnrx0C] serviceName=[qm9gzzhzf096] connId=[1] router=[Public OCI US East(custom config)]} established listener
[ 2.700] DEBUG sdk-golang/ziti.(*listenerManager).createListener: {serviceName=[qm9gzzhzf096]} listener established to tls:def60534-ff9a-44db-bb9e-46b65c67b5ce.production.netfoundry.io:443 in 129ms
[ 2.768] DEBUG channel/v2.(*classicDialer).sendHello [u{classic}->i{}]: exited
[ 2.768] DEBUG channel/v2.(*classicDialer).Create [tls:db67f324-69ab-4c7a-a258-36566b387b90.production.netfoundry.io:443]: exited
[ 2.768] DEBUG sdk-golang/ziti.(*ContextImpl).connectEdgeRouter: routerConn[Azure Public London(custom config)@tls:db67f324-69ab-4c7a-a258-36566b387b90.production.netfoundry.io:443] connected in 634 ms
[ 2.768] DEBUG channel/v2.(*channelImpl).rxer [ch{ziti-sdk[router=tls:db67f324-69ab-4c7a-a258-36566b387b90.production.netfoundry.io:443]}->u{classic}->i{v1pq4}]: started
[ 2.768] DEBUG sdk-golang/ziti.(*ContextImpl).connectEdgeRouter: {arch=[amd64] version=[v0.32.2] revision=[local] buildDate=[2020-01-01 01:01:01] os=[linux]} connected to edge router
[ 2.768] DEBUG sdk-golang/ziti.(*ContextImpl).connectEdgeRouter: connected to tls:db67f324-69ab-4c7a-a258-36566b387b90.production.netfoundry.io:443
[ 2.768] DEBUG channel/v2.(*channelImpl).txer [ch{ziti-sdk[router=tls:db67f324-69ab-4c7a-a258-36566b387b90.production.netfoundry.io:443]}->u{classic}->i{v1pq4}]: started
[ 2.768] DEBUG sdk-golang/ziti.(*listenerManager).handleRouterConnectResult: ignoring connection to tls:db67f324-69ab-4c7a-a258-36566b387b90.production.netfoundry.io:443, already have max connections 1
[ 2.769] DEBUG channel/v2/latency.ProbeLatencyConfigurable [ch{ziti-sdk[router=tls:db67f324-69ab-4c7a-a258-36566b387b90.production.netfoundry.io:443]}->u{classic}->i{v1pq4}]: started
[ 2.781] DEBUG channel/v2.(*classicDialer).sendHello [u{classic}->i{}]: exited
[ 2.782] DEBUG channel/v2.(*classicDialer).Create [tls:60042e42-5eef-4378-9ade-538b5cde57a0.production.netfoundry.io:443]: exited
[ 2.782] DEBUG channel/v2.(*channelImpl).rxer [ch{ziti-sdk[router=tls:60042e42-5eef-4378-9ade-538b5cde57a0.production.netfoundry.io:443]}->u{classic}->i{xBJ6}]: started
[ 2.782] DEBUG sdk-golang/ziti.(*ContextImpl).connectEdgeRouter: routerConn[AWS US-West-1-1(custom config)@tls:60042e42-5eef-4378-9ade-538b5cde57a0.production.netfoundry.io:443] connected in 654 ms
[ 2.782] DEBUG channel/v2.(*channelImpl).txer [ch{ziti-sdk[router=tls:60042e42-5eef-4378-9ade-538b5cde57a0.production.netfoundry.io:443]}->u{classic}->i{xBJ6}]: started
[ 2.782] DEBUG sdk-golang/ziti.(*ContextImpl).connectEdgeRouter: {buildDate=[2020-01-01 01:01:01] version=[v0.32.2] revision=[local] os=[linux] arch=[amd64]} connected to edge router
[ 2.782] DEBUG sdk-golang/ziti.(*ContextImpl).connectEdgeRouter: connected to tls:60042e42-5eef-4378-9ade-538b5cde57a0.production.netfoundry.io:443
[ 2.782] DEBUG channel/v2/latency.ProbeLatencyConfigurable [ch{ziti-sdk[router=tls:60042e42-5eef-4378-9ade-538b5cde57a0.production.netfoundry.io:443]}->u{classic}->i{xBJ6}]: started
[ 2.782] DEBUG sdk-golang/ziti.(*listenerManager).handleRouterConnectResult: ignoring connection to tls:60042e42-5eef-4378-9ade-538b5cde57a0.production.netfoundry.io:443, already have max connections 1
[ 2.784] DEBUG channel/v2.(*classicDialer).sendHello [u{classic}->i{}]: exited
[ 2.784] DEBUG channel/v2.(*classicDialer).Create [tls:69e048d6-5988-4dd6-886b-fb1f33cdff4f.production.netfoundry.io:443]: exited
[ 2.784] DEBUG sdk-golang/ziti.(*ContextImpl).connectEdgeRouter: routerConn[AWS US-West-1-2(custom config)@tls:69e048d6-5988-4dd6-886b-fb1f33cdff4f.production.netfoundry.io:443] connected in 647 ms
[ 2.784] DEBUG channel/v2.(*channelImpl).rxer [ch{ziti-sdk[router=tls:69e048d6-5988-4dd6-886b-fb1f33cdff4f.production.netfoundry.io:443]}->u{classic}->i{rRGq}]: started
[ 2.784] DEBUG sdk-golang/ziti.(*ContextImpl).connectEdgeRouter: {os=[linux] arch=[amd64] version=[v0.32.2] revision=[7c53aa006529] buildDate=[2024-02-10T05:53:17Z]} connected to edge router
[ 2.784] DEBUG channel/v2.(*channelImpl).txer [ch{ziti-sdk[router=tls:69e048d6-5988-4dd6-886b-fb1f33cdff4f.production.netfoundry.io:443]}->u{classic}->i{rRGq}]: started
[ 2.784] DEBUG sdk-golang/ziti.(*ContextImpl).connectEdgeRouter: connected to tls:69e048d6-5988-4dd6-886b-fb1f33cdff4f.production.netfoundry.io:443
[ 2.784] DEBUG sdk-golang/ziti.(*listenerManager).handleRouterConnectResult: ignoring connection to tls:69e048d6-5988-4dd6-886b-fb1f33cdff4f.production.netfoundry.io:443, already have max connections 1
[ 2.784] DEBUG channel/v2/latency.ProbeLatencyConfigurable [ch{ziti-sdk[router=tls:69e048d6-5988-4dd6-886b-fb1f33cdff4f.production.netfoundry.io:443]}->u{classic}->i{rRGq}]: started
[ 2.838] INFO main.(*shareReservedCommand).run: access your zrok share: https://qm9gzzhzf096.share.zrok.io
[ 2.854] DEBUG channel/v2.(*classicDialer).sendHello [u{classic}->i{}]: exited
[ 2.855] DEBUG channel/v2.(*classicDialer).Create [tls:f12da3a5-c651-4dbe-ace0-67723a5dda65.production.netfoundry.io:443]: exited
[ 2.855] DEBUG sdk-golang/ziti.(*ContextImpl).connectEdgeRouter: routerConn[AWS EU-Central-2(custom config)@tls:f12da3a5-c651-4dbe-ace0-67723a5dda65.production.netfoundry.io:443] connected in 717 ms
[ 2.855] DEBUG channel/v2.(*channelImpl).rxer [ch{ziti-sdk[router=tls:f12da3a5-c651-4dbe-ace0-67723a5dda65.production.netfoundry.io:443]}->u{classic}->i{K22ql}]: started
[ 2.855] DEBUG channel/v2.(*channelImpl).txer [ch{ziti-sdk[router=tls:f12da3a5-c651-4dbe-ace0-67723a5dda65.production.netfoundry.io:443]}->u{classic}->i{K22ql}]: started
[ 2.855] DEBUG sdk-golang/ziti.(*ContextImpl).connectEdgeRouter: {os=[linux] arch=[amd64] buildDate=[2020-01-01 01:01:01] revision=[local] version=[v0.32.2]} connected to edge router
[ 2.855] DEBUG sdk-golang/ziti.(*ContextImpl).connectEdgeRouter: connected to tls:f12da3a5-c651-4dbe-ace0-67723a5dda65.production.netfoundry.io:443
[ 2.855] DEBUG channel/v2/latency.ProbeLatencyConfigurable [ch{ziti-sdk[router=tls:f12da3a5-c651-4dbe-ace0-67723a5dda65.production.netfoundry.io:443]}->u{classic}->i{K22ql}]: started
[ 2.855] DEBUG sdk-golang/ziti.(*listenerManager).handleRouterConnectResult: ignoring connection to tls:f12da3a5-c651-4dbe-ace0-67723a5dda65.production.netfoundry.io:443, already have max connections 1
[ 2.901] DEBUG transport/v2/tls.DialWithLocalBinding: {dest=[ed9935f5-5d9d-4898-a3cf-4a8a05b4e4a6.production.netfoundry.io:443]} server provided [1] certificates
[ 2.901] DEBUG channel/v2.(*classicDialer).sendHello [u{classic}->i{}]: started
[ 2.990] DEBUG transport/v2/tls.DialWithLocalBinding: {dest=[1ba54d52-ffdb-4ac1-8e32-dc39ca0f89a1.production.netfoundry.io:443]} server provided [1] certificates
[ 2.990] DEBUG channel/v2.(*classicDialer).sendHello [u{classic}->i{}]: started
[ 3.272] DEBUG channel/v2.(*classicDialer).sendHello [u{classic}->i{}]: exited
[ 3.272] DEBUG channel/v2.(*classicDialer).Create [tls:ed9935f5-5d9d-4898-a3cf-4a8a05b4e4a6.production.netfoundry.io:443]: exited
[ 3.272] DEBUG sdk-golang/ziti.(*ContextImpl).connectEdgeRouter: routerConn[Public OCI Singapore(custom config)@tls:ed9935f5-5d9d-4898-a3cf-4a8a05b4e4a6.production.netfoundry.io:443] connected in 1145 ms
[ 3.273] DEBUG sdk-golang/ziti.(*ContextImpl).connectEdgeRouter: {revision=[local] buildDate=[2020-01-01 01:01:01] os=[linux] arch=[amd64] version=[v0.32.2]} connected to edge router
[ 3.273] DEBUG channel/v2.(*channelImpl).txer [ch{ziti-sdk[router=tls:ed9935f5-5d9d-4898-a3cf-4a8a05b4e4a6.production.netfoundry.io:443]}->u{classic}->i{VkZbW}]: started
[ 3.273] DEBUG sdk-golang/ziti.(*ContextImpl).connectEdgeRouter: connected to tls:ed9935f5-5d9d-4898-a3cf-4a8a05b4e4a6.production.netfoundry.io:443
[ 3.273] DEBUG channel/v2.(*channelImpl).rxer [ch{ziti-sdk[router=tls:ed9935f5-5d9d-4898-a3cf-4a8a05b4e4a6.production.netfoundry.io:443]}->u{classic}->i{VkZbW}]: started
[ 3.273] DEBUG sdk-golang/ziti.(*listenerManager).handleRouterConnectResult: ignoring connection to tls:ed9935f5-5d9d-4898-a3cf-4a8a05b4e4a6.production.netfoundry.io:443, already have max connections 1
[ 3.273] DEBUG channel/v2/latency.ProbeLatencyConfigurable [ch{ziti-sdk[router=tls:ed9935f5-5d9d-4898-a3cf-4a8a05b4e4a6.production.netfoundry.io:443]}->u{classic}->i{VkZbW}]: started
[ 3.398] DEBUG channel/v2.(*classicDialer).sendHello [u{classic}->i{}]: exited
[ 3.399] DEBUG channel/v2.(*classicDialer).Create [tls:1ba54d52-ffdb-4ac1-8e32-dc39ca0f89a1.production.netfoundry.io:443]: exited
[ 3.399] DEBUG sdk-golang/ziti.(*ContextImpl).connectEdgeRouter: routerConn[Public AWS India(custom config)@tls:1ba54d52-ffdb-4ac1-8e32-dc39ca0f89a1.production.netfoundry.io:443] connected in 1270 ms
[ 3.399] DEBUG sdk-golang/ziti.(*ContextImpl).connectEdgeRouter: {buildDate=[2020-01-01 01:01:01] os=[linux] arch=[amd64] version=[v0.32.2] revision=[local]} connected to edge router
[ 3.399] DEBUG channel/v2.(*channelImpl).rxer [ch{ziti-sdk[router=tls:1ba54d52-ffdb-4ac1-8e32-dc39ca0f89a1.production.netfoundry.io:443]}->u{classic}->i{6de43}]: started
[ 3.399] DEBUG sdk-golang/ziti.(*ContextImpl).connectEdgeRouter: connected to tls:1ba54d52-ffdb-4ac1-8e32-dc39ca0f89a1.production.netfoundry.io:443
[ 3.399] DEBUG channel/v2.(*channelImpl).txer [ch{ziti-sdk[router=tls:1ba54d52-ffdb-4ac1-8e32-dc39ca0f89a1.production.netfoundry.io:443]}->u{classic}->i{6de43}]: started
[ 3.399] DEBUG sdk-golang/ziti.(*listenerManager).handleRouterConnectResult: ignoring connection to tls:1ba54d52-ffdb-4ac1-8e32-dc39ca0f89a1.production.netfoundry.io:443, already have max connections 1
[ 3.399] DEBUG channel/v2/latency.ProbeLatencyConfigurable [ch{ziti-sdk[router=tls:1ba54d52-ffdb-4ac1-8e32-dc39ca0f89a1.production.netfoundry.io:443]}->u{classic}->i{6de43}]: started
[ 301.689] DEBUG sdk-golang/ziti.(*ContextImpl).runRefreshes: refreshing services
[ 301.689] DEBUG sdk-golang/ziti.(*ContextImpl).refreshServices: checking if service updates available
[ 473.706] DEBUG sdk-golang/ziti/edge/network.(*edgeConn).Accept: {connId=[1] type=[EdgeDialType] chSeq=[19] edgeSeq=[0]} received dial request
[ 473.707] DEBUG sdk-golang/ziti/edge/network.(*edgeConn).newChildConnection: {connId=[1] token=[9b9667d3-6136-4cd3-8423-2d82877937e5]} looking up listener
[ 473.710] DEBUG sdk-golang/ziti/edge/network.(*edgeConn).newChildConnection: {connId=[1] token=[9b9667d3-6136-4cd3-8423-2d82877937e5]} listener found. checking for router provided connection id
[ 473.710] DEBUG sdk-golang/ziti/edge/network.(*edgeConn).newChildConnection: {connId=[1] token=[9b9667d3-6136-4cd3-8423-2d82877937e5]} using router provided connection id 2147483648
[ 473.710] DEBUG sdk-golang/ziti/edge/network.(*edgeConn).newChildConnection: {parentConnId=[1] token=[9b9667d3-6136-4cd3-8423-2d82877937e5] marker=[GkJdfMYi] connId=[2147483648]} setting up crypto
[ 473.710] DEBUG sdk-golang/ziti/edge/network.(*newConnHandler).dialSucceeded: {parentConnId=[1] token=[9b9667d3-6136-4cd3-8423-2d82877937e5] connId=[2147483648] marker=[GkJdfMYi]} new connection established
[ 473.711] DEBUG sdk-golang/ziti/edge/network.(*newConnHandler).dialSucceeded: {parentConnId=[1] token=[9b9667d3-6136-4cd3-8423-2d82877937e5] connId=[2147483648] marker=[GkJdfMYi]} sending crypto header
[ 473.711] DEBUG sdk-golang/ziti/edge.(*MsgChannel).WriteTraced: {edgeSeq=[1] connId=[2147483648] type=[EdgeDataType] chSeq=[-1]} writing 24 bytes
[ 473.711] DEBUG sdk-golang/ziti/edge/network.(*newConnHandler).dialSucceeded: {token=[9b9667d3-6136-4cd3-8423-2d82877937e5] connId=[2147483648] marker=[GkJdfMYi] parentConnId=[1]} tx crypto established
[ 473.847] DEBUG sdk-golang/ziti/edge/network.(*edgeConn).Accept: {chSeq=[20] edgeSeq=[1] connId=[2147483648] type=[EdgeDataType]} received 24 bytes (msg type: 60786)
[ 473.848] DEBUG sdk-golang/ziti/edge/network.(*edgeConn).Accept: {connId=[2147483648] type=[EdgeDataType] chSeq=[21] edgeSeq=[2]} received 436 bytes (msg type: 60786)
[ 473.848] DEBUG sdk-golang/ziti/edge/network.(*edgeConn).Read: {connId=[2147483648] marker=[GkJdfMYi]} reading 419 bytes
[ 473.848] INFO main.(*shareReservedCommand).run: -> GET /
[ 473.893] DEBUG sdk-golang/ziti/edge.(*MsgChannel).WriteTraced: {connId=[2147483648] type=[EdgeDataType] chSeq=[-1] edgeSeq=[2]} writing 4113 bytes
[ 473.893] DEBUG sdk-golang/ziti/edge.(*MsgChannel).WriteTraced: {connId=[2147483648] type=[EdgeDataType] chSeq=[-1] edgeSeq=[3]} writing 6683 bytes
[ 473.893] DEBUG sdk-golang/ziti/edge/network.(*edgeConn).Read: {connId=[2147483648] marker=[GkJdfMYi]} unexpected sequencer err (read timed out)
[ 564.021] DEBUG sdk-golang/ziti/edge/network.(*edgeConn).Read: {connId=[2147483648] marker=[GkJdfMYi]} received ConnState_CLOSED message, closing connection
[ 564.022] DEBUG sdk-golang/ziti/edge/network.(*edgeConn).close: {connId=[2147483648] marker=[GkJdfMYi]} close: begin
[ 564.022] DEBUG sdk-golang/ziti/edge/network.(*edgeConn).close: {connId=[2147483648] marker=[GkJdfMYi]} close: end
[ 564.022] DEBUG sdk-golang/ziti/edge/network.(*edgeConn).Accept: {connId=[2147483648] type=[EdgeStateClosedType] chSeq=[25] edgeSeq=[3]} received 12 bytes (msg type: 60785)
[ 601.698] DEBUG sdk-golang/ziti.(*ContextImpl).runRefreshes: refreshing services
[ 601.698] DEBUG sdk-golang/ziti.(*ContextImpl).refreshServices: checking if service updates available

Sometimes error 504 also occurs

And I create a new token instead of using the previous one, everything works again

giorgiobazzo · March 9, 2024, 9:14pm

You tested by deleting the environment in the web panel: https://api.zrok.io/
before disabling the first time? (as per: steps 4 and 5)

For me, the release isn't working either.

I reserved a custom token:
zrok reserve public http://localhost:9496 -n pca4444
after:
zrok share reserved pca4444 --headless --verbose

So I accessed: https://pca4444.share.zrok.io
And everything worked.

After:
zrok release pca4444
zrok reserve public http://localhost:9496 -n pca4444
zrok share reserved pca4444 --headless --verbose

the debug stops at:
[ 3,359] DEBUG channel/v2.(*channelImpl).txer [ch{ziti-sdk[router=tls:1ba54d52-ffdb-4ac1-8e32-dc39ca0f89a1.production.netfoundry.io:443]}->u{classic} ->i{xjQjw}]: started
[ 3,359] DEBUG channel/v2/latency.ProbeLatencyConfigurable [ch{ziti-sdk[router=tls:1ba54d52-ffdb-4ac1-8e32-dc39ca0f89a1.production.netfoundry.io:443]}->u{classic}->i {xjQjw}]: started

and nothing else happens, it seems that the requests no longer reach my application.

so I create a new token:
zrok release pca5555
zrok reserve public http://localhost:9496 -n pca5555
zrok share reserved pca5555 --headless --verbose

Access: https://pca5555.share.zrok.io
And everything is working again.

In short, when I release a token, or remove an environment with a certain token, I am unable to reuse it.

qrkourier · March 9, 2024, 9:50pm

In fact, I used zrok disable only (not the console) and I was able to re-use the reserved token, but when I first disabled the environment with the console, then did zrok disable, I seem to have the same issue you reported: no errors, and eventually the frontend responds with a gateway timeout code (HTTP 504).

When this is happening I captured the DEBUG logs from the backend that were emitted at the same time I tried to connect to the frontend.

[  63.450]   DEBUG sdk-golang/ziti/edge/network.(*edgeConn).Accept: {connId=[2147483648] type=[EdgeStateClosedType] chSeq=[9] edgeSeq=[3]} received 12 bytes (msg type: 60785)
[  63.486]   DEBUG sdk-golang/ziti/edge/network.(*edgeConn).Accept: {connId=[1] type=[EdgeDialType] chSeq=[10] edgeSeq=[0]} received dial request
[  63.486]   DEBUG sdk-golang/ziti/edge/network.(*edgeConn).newChildConnection: {connId=[1] token=[8bb33e81-62c7-4e07-b80a-3d1d1a199865]} looking up listener
[  63.486]   DEBUG sdk-golang/ziti/edge/network.(*edgeConn).newChildConnection: {token=[8bb33e81-62c7-4e07-b80a-3d1d1a199865] connId=[1]} listener found. checking for router provided connection id
[  63.486]   DEBUG sdk-golang/ziti/edge/network.(*edgeConn).newChildConnection: {connId=[1] token=[8bb33e81-62c7-4e07-b80a-3d1d1a199865]} using router provided connection id 2147483649
[  63.486]   DEBUG sdk-golang/ziti/edge/network.(*edgeConn).newChildConnection: {parentConnId=[1] token=[8bb33e81-62c7-4e07-b80a-3d1d1a199865] marker=[8lmHkmf1] connId=[2147483649]} setting up crypto
[  63.486]   DEBUG sdk-golang/ziti/edge/network.(*newConnHandler).dialSucceeded: {marker=[8lmHkmf1] parentConnId=[1] connId=[2147483649] token=[8bb33e81-62c7-4e07-b80a-3d1d1a199865]} new connection established
[  63.487]   DEBUG sdk-golang/ziti/edge/network.(*newConnHandler).dialSucceeded: {parentConnId=[1] connId=[2147483649] token=[8bb33e81-62c7-4e07-b80a-3d1d1a199865] marker=[8lmHkmf1]} sending crypto header
[  63.487]   DEBUG sdk-golang/ziti/edge.(*MsgChannel).WriteTraced: {connId=[2147483649] type=[EdgeDataType] chSeq=[-1] edgeSeq=[1]} writing 24 bytes
[  63.487]   DEBUG sdk-golang/ziti/edge/network.(*newConnHandler).dialSucceeded: {token=[8bb33e81-62c7-4e07-b80a-3d1d1a199865] marker=[8lmHkmf1] parentConnId=[1] connId=[2147483649]} tx crypto established
[  63.509]   DEBUG sdk-golang/ziti/edge/network.(*edgeConn).Accept: {type=[EdgeDataType] chSeq=[11] edgeSeq=[1] connId=[2147483649]} received 24 bytes (msg type: 60786)
[  63.509]   DEBUG sdk-golang/ziti/edge/network.(*edgeConn).Accept: {edgeSeq=[2] connId=[2147483649] type=[EdgeDataType] chSeq=[12]} received 1269 bytes (msg type: 60786)

I did not have the same problem with zrok release instead of zrok disable:

enable
reserve random
share reserved OK
release
reserve unique name same as random
share reserved OK

EDIT: now I think this condition is happening frequently, and not only when the share token is released one way or the other, i.e., disable env with CLI vs. console, or release individually, because I am seeing the HTTP 504 response for a proxy backend even after trying all of the above methods to re-use the reserved token, and after eliminating all other shares from the account to ensure I'm not hitting any hard limits.

giorgiobazzo · March 9, 2024, 10:06pm

I don't know if this could influence it, but I'm using rzro.exe for Windows.

I just cleaned all the environments in my console, and tried to use tokens that I had already used before, and they no longer work, I don't get errors in debug, but the requests don't reach the backend.

qrkourier · March 9, 2024, 10:35pm

I hit the same issue in a couple of test instances of zrok, separate from the main one you're using.

I narrowed down the versions where I can consistently reproduce this symptom.

To validate on Windows, will you try running your reserved share backend with the zrok.exe from v0.4.19?

For the record, I don't see this issue with an OpenZiti controller/router v0.31.4, but I do see it with the version we're running in zrok prod: v0.32.2.

As mentioned, the issue does not manifest when the zrok backend is <= 0.4.19, pending @giorgiobazzo confirmation the same is true for Windows.

giorgiobazzo · March 9, 2024, 11:06pm

I tested again with version 0.4.19...

The console was clean, without any environment enabled.
So I ran zrok enable XXXXXXX
and I reserved a token that I had already used.

Everything worked. (before I couldn't do this)

Then I removed the environment via the web console.

I disabled the environment with zrok disable
I activated it again with zrok enable XXXXXXX

I tried to reserve and use the memo token, the problem happened again.
Now I'm in the same situation as before and using version 0.4.19.

qrkourier · March 9, 2024, 11:15pm

Thank you for testing the 0.4.19 zrok.exe. While you were doing that, I, too, found that I could reproduce the issue with older versions of zrok, but I didn't find it necessary to release and re-reserve the token to trigger the problem.

Do you see this problem when you merely stop and re-start the zrok share reserved backend command?

When I tested, the front end responded successfully on the first run of the backend, but if I canceled and re-ran the backend, it would stall, and eventually, I got the HTTP 504 timeout.

giorgiobazzo · March 9, 2024, 11:29pm

I don't see this problem when I stop and restart the same share. This has always worked for me.

The problem is that I'm testing an environment restoration, something that was in production, and for some reason needs to be reconfigured as it was before, with the same url as the front-end.
In these cases it may be necessary to reactivate the entire environment, and not just restart the share. And this is where the problems happen.

Could this not be something related to DNS propagation? I say this because it seems that after some time, I tried to use a token that I had already used, everything worked, when I tested with version 0.4.19 as you asked me, but I only did it after a certain time. So I suspect that it was not version 0.4.19 that allowed it to work, but rather the time we waited. It's just an idea!

giorgiobazzo · March 11, 2024, 11:12am

Hello @qrkourier,

Today I'm doing some more tests, and I noticed something different. After releasing and then reserving a token, the problems occurred as we were observing before. But I left a share running anyway, so every 2 or 3 minutes I tried to reload the front-end page. After about 10 minutes I noticed that some requests started to work, and different things in the debug started to appear, but I still received 404 errors, "NOT FOUND" with the zrok mascot in some requests. I continued performing tests every 2 minutes, after about 30 minutes that the sharing was active, everything apparently returned to normal, and everything appears to be working as expected.

giorgiobazzo · March 11, 2024, 1:11pm

I think the desired behavior would be for the share to become working again immediately after being released and reserved again.
But if this is not possible, due to some technical limitation, or something like that, I would like to know if the normal behavior will be having to wait around 30 minutes for things to normalize.

qrkourier · March 11, 2024, 1:30pm

You're expecting the correct behavior: the served public share should work as soon as it's shared. It shouldn't matter whether this is the first time it was reserved or shared. By design, there's no warm-up period for new zrok shares.

I'll investigate further today.

qrkourier · March 20, 2024, 6:37pm

This may have been caused by a known issue: Released Reserved Share Stickiness on Public Frontend · Issue #529 · openziti/zrok · GitHub

Topic		Replies	Views
401 shareUnauthorized	3	66	June 25, 2024
Trying to get zrok to work with Docker Share zrok	2	47	August 8, 2024
Zrok stopped working (401 Unauthorized error) zrok	10	497	August 22, 2024
Unable to create share error 401 zrok	3	257	June 11, 2024
Unable to create share	3	59	June 25, 2024

Problem with token reservation

Related topics