Java SDK - `failed to dispatch: decryption failure`

SDK Questions
1

Hi,

I’m running into some wired issues with the java SDK: I get failed to dispatch: decryption failure messages on about 50% of my connections. The other 50% are working fine. Is there a quick hint on this where to look?

As hint: In our environment we use the Jetty server. Jetty usually relies on java.nio.channels.ServerSocketChannel, the SDK is build on java.nio.channels.AsynchronousServerSocketChannel. I implement an own AsynchronousServerConnector and an AsynchronousSocketChannelEndPoint to connect it with the ziti SDK properly.

thinking - might the issue be related to some timing stuff realted to the async callbacks? There should be no blocking stuff on the callbacks but okay, lets try to run stuff in other threads… :wink:

Bye,
Chris

2

When I have a problem like this and it’s “about 50%” of my connections, it’s usually because I have instructed two different identities to host the same service and one is setup properly and one is not. Could that be the case?

For example, it’s common, and somewhat easy, to have the same identity which dials a service, also be able to bind the service by an overly agressive/naiive/mistaken use of service policies. Then, add in the service you “expect” to do the bind, and you find 1/2 of your requests fail. Why? It’s because 1/2 of those requests are routed to the proper ‘binder’ and half are routed right back to the dialer, where the request fails. OpenZiti can does load balancing through that mechanism.

I’ve also done this to myself when first testing with tunnelers binding the service and then moving to the sdk, only to forget I’ve left the tunneler on and now I have two "bind"ing identities and the same issue happens.

I don’t know that this is the case but I’ve done it to myself before.

A nice way to start is with policy advisor. ziti edge policy-advisor identities -q will show you the identities you have and what services they can dial/bind and ziti edge policy-advisor service -q will show you the same information but by ‘service’ (not identity, obviously).

If none of that helps, I would look in the logs for both ends to see if there’s any clue in the SDK logs.

Hope that helps

3

Thank you for your feedback and inspiration. I’ve double checked, there is only one client bound to this service. The ‘decryption failure’-message is seen on the server bound to the service after the accept - So I assume the connection is wired properly to this specific ‘server’ - otherwise I thik we wouldn’t see the accept for the connection.
Some status-update:

  • The tests with decoupling things from the callback didn’t bring any improvement.
  • I created a separate / stand alone sample app (Just Jetty & Ziti) and in this setup I wasn’t able to reproduce the issue. So it might to enterfere with something else I have in somwhere else in my framework. Things are getting wired…

Never the less I’ve started collecting logs:
This are the ziti logs from the app startup:

2023-01-22T09:06:57.709Z DEBUG 77920 --- [-1 @coroutine#1] org.openziti.impl.ZitiContextImpl        : p6wiijikj[null]@https://ziti-devel.home.net:1280 transitioned to Loading
Loading
2023-01-22T09:06:57.737Z DEBUG 77920 --- [aks.de:1280/...] org.openziti.api.Controller              : GET https://ziti-devel.home.net:1280/version session=null t[OkHttp https://ziti-devel.home.net:1280/...]
2023-01-22T09:06:57.938Z  INFO 77920 --- [-3 @coroutine#2] org.openziti.api.Controller              : controller[https://ziti-devel.home.net:1280/] version(v0.27.2/7de87562b20d)
2023-01-22T09:06:57.954Z DEBUG 77920 --- [aks.de:1280/...] org.openziti.api.Controller              : POST https://ziti-devel.home.net:1280/edge/client/v1/authenticate?method=cert session=null t[OkHttp https://ziti-devel.home.net:1280/...]
2023-01-22T09:06:58.024Z DEBUG 77920 --- [-1 @coroutine#1] org.openziti.impl.ZitiContextImpl        : camdb-devel-1[P6WiijIKJ]@https://ziti-devel.home.net:1280 transitioned to Active
2023-01-22T09:06:58.026Z DEBUG 77920 --- [-1 @coroutine#5] org.openziti.impl.ZitiContextImpl        : waiting for refresh 1790 seconds
2023-01-22T09:06:58.026Z DEBUG 77920 --- [-2 @coroutine#7] org.openziti.impl.ZitiContextImpl        : [p6wiijikj] slept and restarting on t[DefaultDispatcher-worker-2 @coroutine#7]
2023-01-22T09:06:58.028Z DEBUG 77920 --- [aks.de:1280/...] org.openziti.api.Controller              : GET https://ziti-devel.home.net:1280/edge/client/v1/current-identity/edge-routers session=cld75ofx2fj1n018swgjcl9lf t[OkHttp https://ziti-devel.home.net:1280/...]
2023-01-22T09:06:58.029Z DEBUG 77920 --- [aks.de:1280/...] org.openziti.api.Controller              : GET https://ziti-devel.home.net:1280/edge/client/v1/current-api-session/service-updates session=cld75ofx2fj1n018swgjcl9lf t[OkHttp https://ziti-devel.home.net:1280/...]
2023-01-22T09:06:58.037Z DEBUG 77920 --- [-1 @coroutine#6] org.openziti.impl.ZitiContextImpl        : current edge routers = [EdgeRouter(name=core-router, hostname=, supportedProtocols={tls=tls://ziti-devel.home.net:1290}, urls=null)]
2023-01-22T09:06:58.049Z DEBUG 77920 --- [aks.de:1280/...] org.openziti.api.Controller              : GET https://ziti-devel.home.net:1280/edge/client/v1/services?offset=0&limit=25 session=cld75ofx2fj1n018swgjcl9lf t[OkHttp https://ziti-devel.home.net:1280/...]
2023-01-22T09:06:58.078Z DEBUG 77920 --- [-1 @coroutine#7] org.openziti.impl.ZitiContextImpl        : [p6wiijikj] got 1 services on t[DefaultDispatcher-worker-1 @coroutine#7]
2023-01-22T09:06:58.079Z DEBUG 77920 --- [-1 @coroutine#6] org.openziti.impl.ZitiContextImpl        : delaying service refresh for 60000ms
2023-01-22T09:06:58.079Z DEBUG 77920 --- [2 @coroutine#10] o.openziti.net.ZitiServerSocketChannel   : starting bind
2023-01-22T09:06:58.084Z  INFO 77920 --- [           main] org.eclipse.jetty.server.Server          : jetty-11.0.13; built: 2022-12-07T20:47:15.149Z; git: a04bd1ccf844cf9bebc12129335d7493111cbff6; jvm 17.0.5+1-b653.23
2023-01-22T09:06:58.139Z  INFO 77920 --- [           main] o.e.j.s.h.ContextHandler.application     : Initializing Spring embedded WebApplicationContext
2023-01-22T09:06:58.139Z  INFO 77920 --- [           main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 3937 ms
[...]
2023-01-22T09:06:58.795Z DEBUG 77920 --- [2 @coroutine#10] org.openziti.impl.ZitiContextImpl        : getNetworkSession(svc.java-server.home.net)
2023-01-22T09:06:58.799Z DEBUG 77920 --- [aks.de:1280/...] org.openziti.api.Controller              : POST https://ziti-devel.home.net:1280/edge/client/v1/sessions session=cld75ofx2fj1n018swgjcl9lf t[OkHttp https://ziti-devel.home.net:1280/...]
2023-01-22T09:06:58.973Z DEBUG 77920 --- [4 @coroutine#10] org.openziti.impl.ZitiContextImpl        : selected Channel[tls://ziti-devel.home.net:1290]
2023-01-22T09:06:58.974Z DEBUG 77920 --- [4 @coroutine#10] o.openziti.net.ZitiServerSocketChannel   : starting network connection cld75ogjjfj1r018s56y1wsy0/1
2023-01-22T09:06:59.001Z  INFO 77920 --- [           main] o.e.jetty.server.handler.ContextHandler  : Started o.s.b.w.e.j.JettyEmbeddedWebAppContext@4960b819{application,/,[file:///private/var/folders/[...]/target-eclipse/classes/META-INF/resources/],AVAILABLE}
2023-01-22T09:06:59.001Z DEBUG 77920 --- [6 @coroutine#10] o.openziti.net.ZitiServerSocketChannel   : network connection established cld75ogjjfj1r018s56y1wsy0/1
2023-01-22T09:06:59.003Z  INFO 77920 --- [           main] org.eclipse.jetty.server.Server          : Started Server@51efdb72{STARTING}[11.0.13,sto=0] @6176ms
[...]
2023-01-22T09:07:08.431Z  INFO 77920 --- [           main] o.e.j.s.h.ContextHandler.application     : Initializing Spring DispatcherServlet 'dispatcherServlet'
2023-01-22T09:07:08.431Z  INFO 77920 --- [           main] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2023-01-22T09:07:08.433Z  INFO 77920 --- [           main] o.s.web.servlet.DispatcherServlet        : Completed initialization in 2 ms
2023-01-22T09:07:08.441Z  INFO 77920 --- [           main] o.e.jetty.server.AbstractConnector       : Started ServerConnector@67c2b55d{HTTP/1.1, (http/1.1)}{0.0.0.0:4088}
2023-01-22T09:07:08.443Z  INFO 77920 --- [           main] o.s.s.j.LoadBalancerRequestCustomizer    : Started..
2023-01-22T09:07:08.443Z  INFO 77920 --- [           main] o.e.jetty.server.AbstractConnector       : Started AdminConnector@5cf33d25{HTTP/1.1, (http/1.1)}{0.0.0.0:4080}
2023-01-22T09:07:08.463Z  INFO 77920 --- [           main] o.e.jetty.util.ssl.SslContextFactory     : x509=X509@6c303cdc(1,h=[localhost],a=[],w=[]) for Server@5df3f854[provider=null,keyStore=file:///Users/christian.niessner/src/eclipse/workspace-saCamDB-master-sb3/saCamDB/saCamDB-application/config/localhost.p12,trustStore=null]
2023-01-22T09:07:08.471Z  INFO 77920 --- [           main] o.s.s.j.LoadBalancerRequestCustomizer    : Started..
2023-01-22T09:07:08.472Z  INFO 77920 --- [           main] o.e.jetty.server.AbstractConnector       : Started AdminSSLConnector@2c224096{SSL, (ssl, http/1.1)}{0.0.0.0:4443}
2023-01-22T09:07:08.472Z DEBUG 77920 --- [8 @coroutine#18] o.openziti.net.ZitiServerSocketChannel   : starting bind
2023-01-22T09:07:08.472Z  INFO 77920 --- [           main] o.e.jetty.server.AbstractConnector       : Started ziti.ZitiServerConnector@3ab70d34{svc.java-server.home.net via camdb-devel-1[P6WiijIKJ]@https://ziti-devel.home.net:1280:*}
2023-01-22T09:07:08.473Z DEBUG 77920 --- [8 @coroutine#18] org.openziti.impl.ZitiContextImpl        : getNetworkSession(svc.java-server.home.net)
2023-01-22T09:07:08.474Z DEBUG 77920 --- [8 @coroutine#18] o.openziti.net.ZitiServerSocketChannel   : starting network connection cld75ogjjfj1r018s56y1wsy0/2
2023-01-22T09:07:08.475Z  INFO 77920 --- [           main] o.s.b.web.embedded.jetty.JettyWebServer  : Jetty started on port(s) 4088 (http/1.1), 4080 (http/1.1), 4443 (ssl, http/1.1), -1 (http/1.1) with context path '/'
2023-01-22T09:07:08.513Z DEBUG 77920 --- [6 @coroutine#18] o.openziti.net.ZitiServerSocketChannel   : network connection established cld75ogjjfj1r018s56y1wsy0/2

2023-01-22T09:07:58.083Z DEBUG 77920 --- [6 @coroutine#21] org.openziti.impl.ZitiContextImpl        : [p6wiijikj] slept and restarting on t[DefaultDispatcher-worker-6 @coroutine#21]
2023-01-22T09:07:58.083Z DEBUG 77920 --- [aks.de:1280/...] org.openziti.api.Controller              : GET https://ziti-devel.home.net:1280/edge/client/v1/current-identity/edge-routers session=cld75ofx2fj1n018swgjcl9lf t[OkHttp https://ziti-devel.home.net:1280/...]
2023-01-22T09:07:58.084Z DEBUG 77920 --- [aks.de:1280/...] org.openziti.api.Controller              : GET https://ziti-devel.home.net:1280/edge/client/v1/current-api-session/service-updates session=cld75ofx2fj1n018swgjcl9lf t[OkHttp https://ziti-devel.home.net:1280/...]
2023-01-22T09:07:58.163Z DEBUG 77920 --- [-6 @coroutine#6] org.openziti.impl.ZitiContextImpl        : current edge routers = [EdgeRouter(name=core-router, hostname=, supportedProtocols={tls=tls://ziti-devel.home.net:1290}, urls=null)]
2023-01-22T09:07:58.164Z DEBUG 77920 --- [-6 @coroutine#6] org.openziti.impl.ZitiContextImpl        : delaying service refresh for 60000ms

A Working request:

2023-01-22T09:20:27.548Z DEBUG 77920 --- [1 @coroutine#44] o.openziti.net.ZitiServerSocketChannel   : accepting child conn[5] on parent[2]
2023-01-22T09:20:27.557Z DEBUG 77920 --- [p1222272242-256] o.e.b.j.z.AsynchronousServerConnector    : ZitiServerConnector@3ab70d34{svc.java-server.home.net via camdb-devel-1[P6WiijIKJ]@https://ziti-devel.home.net:1280:*}: New channel connected: ZitiSocketChannel[connected](Bind(service=svc.java-server.home.net, identity=null, useEdgeId=false) -> Session(id=2, service=svc.java-server.home.net, callerId=marvin.macbook-m1))
2023-01-22T09:20:27.557Z DEBUG 77920 --- [p1222272242-256] .b.j.z.AsynchronousSocketChannelEndPoint : AsynchronousSocketChannelEndPoint@118bc323[{l=null,r=Session(id=2, service=svc.java-server.home.net, callerId=marvin.macbook-m1),OPEN,fill=FI,flush=-,to=0/30000}]->[HttpConnection@1dc1ca42[p=HttpParser{s=START,0 of -1},g=HttpGenerator@4747fcc0{s=START}]=>HttpChannelOverHttp@45d22ab1{s=HttpChannelState@a8f6bf3{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=0,c=false/false,a=IDLE,uri=null,age=0}] needsFillInterest EOF=false null
2023-01-22T09:20:27.584Z DEBUG 77920 --- [3 @coroutine#50] .b.j.z.AsynchronousSocketChannelEndPoint : AsynchronousSocketChannelEndPoint$ReadCompletionHandler@7f4e5d38: read completed: 108
2023-01-22T09:20:27.584Z DEBUG 77920 --- [3 @coroutine#50] .b.j.z.AsynchronousSocketChannelEndPoint : AsynchronousSocketChannelEndPoint$ReadCompletionHandler@7f4e5d38 addInputAndRun=true HeapByteBuffer@20ce1fed[p=108,l=2048,c=2048,r=1940]={GET /.mon...*/*\r\n\r\n<<<\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00>>>}
2023-01-22T09:20:27.585Z DEBUG 77920 --- [p1222272242-256] .b.j.z.AsynchronousSocketChannelEndPoint : AsynchronousSocketChannelEndPoint@118bc323[{l=null,r=Session(id=2, service=svc.java-server.home.net, callerId=marvin.macbook-m1),OPEN,fill=-,flush=-,to=27/30000}]->[HttpConnection@1dc1ca42[p=HttpParser{s=START,0 of -1},g=HttpGenerator@4747fcc0{s=START}]=>HttpChannelOverHttp@45d22ab1{s=HttpChannelState@a8f6bf3{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=0,c=false/false,a=IDLE,uri=null,age=0}]: fill requiested
2023-01-22T09:20:27.585Z DEBUG 77920 --- [p1222272242-256] .b.j.z.AsynchronousSocketChannelEndPoint : AsynchronousSocketChannelEndPoint@118bc323[{l=null,r=Session(id=2, service=svc.java-server.home.net, callerId=marvin.macbook-m1),OPEN,fill=-,flush=-,to=0/30000}]->[HttpConnection@1dc1ca42[p=HttpParser{s=START,0 of -1},g=HttpGenerator@4747fcc0{s=START}]=>HttpChannelOverHttp@45d22ab1{s=HttpChannelState@a8f6bf3{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=0,c=false/false,a=IDLE,uri=null,age=0}]: fill completed: 108
2023-01-22T09:20:27.633Z DEBUG 77920 --- [p1222272242-256] .b.j.z.AsynchronousSocketChannelEndPoint : AsynchronousSocketChannelEndPoint@118bc323[{l=null,r=Session(id=2, service=svc.java-server.home.net, callerId=marvin.macbook-m1),OPEN,fill=-,flush=W,to=47/30000}]->[HttpConnection@1dc1ca42[p=HttpParser{s=CONTENT,0 of -1},g=HttpGenerator@4747fcc0{s=COMMITTED}]=>HttpChannelOverHttp@45d22ab1{s=HttpChannelState@a8f6bf3{s=HANDLING rs=BLOCKING os=COMMITTED is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=HANDLING,uri=http://java-server.home.net/.monitoring/NodeStatus,age=46}]: flush requested: [java.nio.DirectByteBuffer[pos=0 lim=314 cap=8192], java.nio.DirectByteBuffer[pos=0 lim=128 cap=32768]]
2023-01-22T09:20:27.633Z DEBUG 77920 --- [p1222272242-256] .b.j.z.AsynchronousSocketChannelEndPoint : AsynchronousSocketChannelEndPoint$WriteHandler@3c980308: start writing buffer: java.nio.DirectByteBuffer[pos=0 lim=314 cap=8192]
2023-01-22T09:20:27.634Z DEBUG 77920 --- [p1222272242-256] .b.j.z.AsynchronousSocketChannelEndPoint : AsynchronousSocketChannelEndPoint@118bc323[{l=null,r=Session(id=2, service=svc.java-server.home.net, callerId=marvin.macbook-m1),OPEN,fill=-,flush=W,to=0/30000}]->[HttpConnection@1dc1ca42[p=HttpParser{s=CONTENT,0 of -1},g=HttpGenerator@4747fcc0{s=COMMITTED}]=>HttpChannelOverHttp@45d22ab1{s=HttpChannelState@a8f6bf3{s=HANDLING rs=BLOCKING os=COMMITTED is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=HANDLING,uri=http://java-server.home.net/.monitoring/NodeStatus,age=47}]: flush requested: [java.nio.DirectByteBuffer[pos=0 lim=128 cap=32768]]
2023-01-22T09:20:27.634Z DEBUG 77920 --- [2 @coroutine#52] .b.j.z.AsynchronousSocketChannelEndPoint : AsynchronousSocketChannelEndPoint$WriteHandler@3c980308: writing next buffer: java.nio.DirectByteBuffer[pos=0 lim=128 cap=32768]
2023-01-22T09:20:27.635Z DEBUG 77920 --- [7 @coroutine#53] .b.j.z.AsynchronousSocketChannelEndPoint : AsynchronousSocketChannelEndPoint$WriteHandler@3c980308: writing next buffer: java.nio.DirectByteBuffer[pos=128 lim=128 cap=32768]
2023-01-22T09:20:27.635Z DEBUG 77920 --- [7 @coroutine#54] .b.j.z.AsynchronousSocketChannelEndPoint : AsynchronousSocketChannelEndPoint$WriteHandler@3c980308: write completed!
2023-01-22T09:20:27.635Z DEBUG 77920 --- [p1222272242-257] .b.j.z.AsynchronousSocketChannelEndPoint : AsynchronousSocketChannelEndPoint@118bc323[{l=null,r=Session(id=2, service=svc.java-server.home.net, callerId=marvin.macbook-m1),OPEN,fill=-,flush=C,to=0/30000}]->[HttpConnection@1dc1ca42[p=HttpParser{s=CONTENT,0 of -1},g=HttpGenerator@4747fcc0{s=COMMITTED}]=>HttpChannelOverHttp@45d22ab1{s=HttpChannelState@a8f6bf3{s=HANDLING rs=BLOCKING os=COMMITTED is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=HANDLING,uri=http://java-server.home.net/.monitoring/NodeStatus,age=48}]: flush requested: [java.nio.DirectByteBuffer[pos=128 lim=128 cap=32768]]
2023-01-22T09:20:27.636Z DEBUG 77920 --- [p1222272242-256] .b.j.z.AsynchronousSocketChannelEndPoint : AsynchronousSocketChannelEndPoint@118bc323[{l=null,r=Session(id=2, service=svc.java-server.home.net, callerId=marvin.macbook-m1),OPEN,fill=-,flush=W,to=1/30000}]->[HttpConnection@1dc1ca42[p=HttpParser{s=CONTENT,0 of -1},g=HttpGenerator@4747fcc0{s=COMPLETING}]=>HttpChannelOverHttp@45d22ab1{s=HttpChannelState@a8f6bf3{s=HANDLING rs=BLOCKING os=COMMITTED is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=HANDLING,uri=http://java-server.home.net/.monitoring/NodeStatus,age=49}]: flush requested: [java.nio.DirectByteBuffer[pos=0 lim=7 cap=16]]
2023-01-22T09:20:27.636Z DEBUG 77920 --- [p1222272242-256] .b.j.z.AsynchronousSocketChannelEndPoint : AsynchronousSocketChannelEndPoint$WriteHandler@3c980308: start writing buffer: java.nio.DirectByteBuffer[pos=0 lim=7 cap=16]
2023-01-22T09:20:27.636Z DEBUG 77920 --- [7 @coroutine#55] .b.j.z.AsynchronousSocketChannelEndPoint : AsynchronousSocketChannelEndPoint$WriteHandler@3c980308: write completed!
2023-01-22T09:20:27.637Z DEBUG 77920 --- [p1222272242-257] .b.j.z.AsynchronousSocketChannelEndPoint : AsynchronousSocketChannelEndPoint@118bc323[{l=null,r=Session(id=2, service=svc.java-server.home.net, callerId=marvin.macbook-m1),OPEN,fill=-,flush=C,to=0/30000}]->[HttpConnection@1dc1ca42[p=HttpParser{s=CONTENT,0 of -1},g=HttpGenerator@4747fcc0{s=COMPLETING}]=>HttpChannelOverHttp@45d22ab1{s=HttpChannelState@a8f6bf3{s=HANDLING rs=BLOCKING os=COMMITTED is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=HANDLING,uri=http://java-server.home.net/.monitoring/NodeStatus,age=50}]: flush requested: [java.nio.DirectByteBuffer[pos=7 lim=7 cap=16]]
2023-01-22T09:20:27.638Z DEBUG 77920 --- [p1222272242-256] .b.j.z.AsynchronousSocketChannelEndPoint : AsynchronousSocketChannelEndPoint@118bc323[{l=null,r=Session(id=2, service=svc.java-server.home.net, callerId=marvin.macbook-m1),OPEN,fill=-,flush=-,to=1/30000}]->[HttpConnection@1dc1ca42[p=HttpParser{s=START,0 of -1},g=HttpGenerator@4747fcc0{s=START}]=>HttpChannelOverHttp@45d22ab1{s=HttpChannelState@a8f6bf3{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=null,age=0}]: fill requiested
2023-01-22T09:20:27.638Z DEBUG 77920 --- [p1222272242-256] .b.j.z.AsynchronousSocketChannelEndPoint : AsynchronousSocketChannelEndPoint@118bc323[{l=null,r=Session(id=2, service=svc.java-server.home.net, callerId=marvin.macbook-m1),OPEN,fill=-,flush=-,to=2/30000}]->[HttpConnection@1dc1ca42[p=HttpParser{s=START,0 of -1},g=HttpGenerator@4747fcc0{s=START}]=>HttpChannelOverHttp@45d22ab1{s=HttpChannelState@a8f6bf3{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=null,age=0}]: fill completed: 0
2023-01-22T09:20:27.638Z DEBUG 77920 --- [p1222272242-256] .b.j.z.AsynchronousSocketChannelEndPoint : AsynchronousSocketChannelEndPoint@118bc323[{l=null,r=Session(id=2, service=svc.java-server.home.net, callerId=marvin.macbook-m1),OPEN,fill=-,flush=-,to=2/30000}]->[HttpConnection@1dc1ca42[p=HttpParser{s=START,0 of -1},g=HttpGenerator@4747fcc0{s=START}]=>HttpChannelOverHttp@45d22ab1{s=HttpChannelState@a8f6bf3{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=null,age=0}]: fill requiested
2023-01-22T09:20:27.638Z DEBUG 77920 --- [p1222272242-256] .b.j.z.AsynchronousSocketChannelEndPoint : AsynchronousSocketChannelEndPoint@118bc323[{l=null,r=Session(id=2, service=svc.java-server.home.net, callerId=marvin.macbook-m1),OPEN,fill=-,flush=-,to=2/30000}]->[HttpConnection@1dc1ca42[p=HttpParser{s=START,0 of -1},g=HttpGenerator@4747fcc0{s=START}]=>HttpChannelOverHttp@45d22ab1{s=HttpChannelState@a8f6bf3{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=null,age=0}]: fill completed: 0
2023-01-22T09:20:27.638Z DEBUG 77920 --- [p1222272242-256] .b.j.z.AsynchronousSocketChannelEndPoint : AsynchronousSocketChannelEndPoint@118bc323[{l=null,r=Session(id=2, service=svc.java-server.home.net, callerId=marvin.macbook-m1),OPEN,fill=FI,flush=-,to=0/30000}]->[HttpConnection@1dc1ca42[p=HttpParser{s=START,0 of -1},g=HttpGenerator@4747fcc0{s=START}]=>HttpChannelOverHttp@45d22ab1{s=HttpChannelState@a8f6bf3{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=null,age=0}] needsFillInterest EOF=false null
2023-01-22T09:20:27.649Z DEBUG 77920 --- [4 @coroutine#51] .b.j.z.AsynchronousSocketChannelEndPoint : AsynchronousSocketChannelEndPoint$ReadCompletionHandler@7f4e5d38: read completed: -1
2023-01-22T09:20:27.650Z DEBUG 77920 --- [4 @coroutine#51] .b.j.z.AsynchronousSocketChannelEndPoint : AsynchronousSocketChannelEndPoint$ReadCompletionHandler@7f4e5d38 addEOFAndRun=true
2023-01-22T09:20:27.650Z DEBUG 77920 --- [p1222272242-257] .b.j.z.AsynchronousSocketChannelEndPoint : AsynchronousSocketChannelEndPoint@118bc323[{l=null,r=Session(id=2, service=svc.java-server.home.net, callerId=marvin.macbook-m1),OPEN,fill=-,flush=-,to=11/30000}]->[HttpConnection@1dc1ca42[p=HttpParser{s=START,0 of -1},g=HttpGenerator@4747fcc0{s=START}]=>HttpChannelOverHttp@45d22ab1{s=HttpChannelState@a8f6bf3{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=null,age=0}]: fill requiested
2023-01-22T09:20:27.650Z DEBUG 77920 --- [p1222272242-257] .b.j.z.AsynchronousSocketChannelEndPoint : AsynchronousSocketChannelEndPoint@118bc323[{l=null,r=Session(id=2, service=svc.java-server.home.net, callerId=marvin.macbook-m1),ISHUT,fill=-,flush=-,to=11/30000}]->[HttpConnection@1dc1ca42[p=HttpParser{s=START,0 of -1},g=HttpGenerator@4747fcc0{s=START}]=>HttpChannelOverHttp@45d22ab1{s=HttpChannelState@a8f6bf3{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=null,age=0}]: fill completed: -1

Post limit exeeded - The failed connection is in the next post :wink:

4

Part two of the message. Oh, just got a mail my first message got quarantined.

This is a failed request (Java side):

2023-01-22T09:25:53.536Z DEBUG 77920 --- [8 @coroutine#49] o.openziti.net.ZitiServerSocketChannel   : accepting child conn[6] on parent[2]
2023-01-22T09:25:53.547Z DEBUG 77920 --- [p1222272242-290] o.e.b.j.z.AsynchronousServerConnector    : ZitiServerConnector@3ab70d34{svc.java-server.home.net via camdb-devel-1[P6WiijIKJ]@https://ziti-devel.home.net:1280:*}: New channel connected: ZitiSocketChannel[connected](Bind(service=svc.java-server.home.net, identity=null, useEdgeId=false) -> Session(id=2, service=svc.java-server.home.net, callerId=marvin.macbook-m1))
2023-01-22T09:25:53.548Z DEBUG 77920 --- [p1222272242-290] .b.j.z.AsynchronousSocketChannelEndPoint : AsynchronousSocketChannelEndPoint@1af82c9[{l=null,r=Session(id=2, service=svc.java-server.home.net, callerId=marvin.macbook-m1),OPEN,fill=FI,flush=-,to=0/30000}]->[HttpConnection@f686c8c[p=HttpParser{s=START,0 of -1},g=HttpGenerator@b57e9b9{s=START}]=>HttpChannelOverHttp@4e5566b7{s=HttpChannelState@33111c7e{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=0,c=false/false,a=IDLE,uri=null,age=0}] needsFillInterest EOF=false null
2023-01-22T09:25:53.559Z  WARN 77920 --- [4 @coroutine#15] Channel[tls://ziti-devel.home.net:1290]     : failed to dispatch: decryption failure
[ removed unrelated service refresh ]
2023-01-22T09:26:23.550Z DEBUG 77920 --- [uler-3ab70d34-1] .b.j.z.AsynchronousSocketChannelEndPoint : AsynchronousSocketChannelEndPoint@1af82c9[{l=null,r=Session(id=2, service=svc.java-server.home.net, callerId=marvin.macbook-m1),OSHUT,fill=FI,flush=-,to=0/30000}]->[HttpConnection@f686c8c[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@b57e9b9{s=START}]=>HttpChannelOverHttp@4e5566b7{s=HttpChannelState@33111c7e{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=0,c=false/false,a=IDLE,uri=null,age=0}] needsFillInterest EOF=false null
2023-01-22T09:26:23.615Z DEBUG 77920 --- [4 @coroutine#65] .b.j.z.AsynchronousSocketChannelEndPoint : AsynchronousSocketChannelEndPoint$ReadCompletionHandler@5f11132a: read completed: -1
2023-01-22T09:26:23.617Z DEBUG 77920 --- [4 @coroutine#65] .b.j.z.AsynchronousSocketChannelEndPoint : AsynchronousSocketChannelEndPoint$ReadCompletionHandler@5f11132a addEOFAndRun=true
2023-01-22T09:26:23.619Z DEBUG 77920 --- [p1222272242-290] .b.j.z.AsynchronousSocketChannelEndPoint : AsynchronousSocketChannelEndPoint@1af82c9[{l=null,r=Session(id=2, service=svc.java-server.home.net, callerId=marvin.macbook-m1),OSHUT,fill=-,flush=-,to=67/30000}]->[HttpConnection@f686c8c[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@b57e9b9{s=START}]=>HttpChannelOverHttp@4e5566b7{s=HttpChannelState@33111c7e{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=0,c=false/false,a=IDLE,uri=null,age=0}]: fill requiested
2023-01-22T09:26:23.620Z DEBUG 77920 --- [p1222272242-290] .b.j.z.AsynchronousSocketChannelEndPoint : AsynchronousSocketChannelEndPoint@1af82c9[{l=null,r=Session(id=2, service=svc.java-server.home.net, callerId=marvin.macbook-m1),CLOSED,fill=-,flush=-,to=67/30000}]->[HttpConnection@f686c8c[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@b57e9b9{s=START}]=>HttpChannelOverHttp@4e5566b7{s=HttpChannelState@33111c7e{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=0,c=false/false,a=IDLE,uri=null,age=0}]: fill completed: -1

And the logs from the desktop edge:

[2023-01-22T09:25:53.475Z]   TRACE tunnel-sdk:tunnel_udp.c:175 recv_udp() received datagram 100.64.0.2:60118->100.64.0.2:53
[2023-01-22T09:25:53.475Z]   DEBUG tunnel-sdk:tunnel_udp.c:251 recv_udp() intercepted address[udp:100.64.0.2:53] client[udp:100.64.0.1:60118] service[ziti:dns-resolver]
[2023-01-22T09:25:53.475Z]   DEBUG tunnel-cbs:ziti_dns.c:211 on_dns_client() new DNS client
[2023-01-22T09:25:53.475Z]   DEBUG tunnel-sdk:ziti_tunnel.c:221 ziti_tunneler_dial_completed() ziti dial succeeded: client[udp:100.64.0.1:60118] service[ziti:dns-resolver]
[2023-01-22T09:25:53.475Z]   TRACE tunnel-sdk:tunnel_udp.c:51 to_ziti() no data to write
[2023-01-22T09:25:53.475Z] VERBOSE tunnel-sdk:tunnel_udp.c:100 on_udp_client_data() 40 bytes from 100.64.0.1:60118
[2023-01-22T09:25:53.475Z]   TRACE tunnel-sdk:tunnel_udp.c:58 to_ziti() writing 40 bytes to ziti
[2023-01-22T09:25:53.475Z]   TRACE tunnel-cbs:ziti_dns.c:642 on_dns_req() received DNS query q_len=40 id[9f50] recursive[false] type[1] name[java-server.home.net]
[2023-01-22T09:25:53.475Z]    INFO tunnel-cbs:ziti_dns.c:465 format_resp() found record[100.64.0.29] for query[1:java-server.home.net]
[2023-01-22T09:25:53.475Z]   TRACE tunnel-sdk:netif_shim.c:34 netif_shim_output() writing packet UDP[100.64.0.2:53 -> 100.64.0.1:60118] len=95
[2023-01-22T09:25:53.479Z]   TRACE tunnel-sdk:tunnel_tcp.c:325 recv_tcp() received segment 100.64.0.1:54378->100.64.0.29:80
[2023-01-22T09:25:53.479Z]   DEBUG tunnel-sdk:tunnel_tcp.c:109 new_tcp_pcb() snd_wnd: 65535, snd_snd_max: 65535, mss: 3960
[2023-01-22T09:25:53.479Z]   DEBUG tunnel-sdk:tunnel_tcp.c:390 recv_tcp() intercepted address[tcp:100.64.0.29:80] client[tcp:100.64.0.1:54378] service[svc.java-server.home.net]
[2023-01-22T09:25:53.479Z] VERBOSE tunnel-cbs:ziti_tunnel_cbs.c:298 ziti_sdk_c_dial() ziti_dial(name=svc.java-server.home.net)
[2023-01-22T09:25:53.479Z]   DEBUG tunnel-cbs:ziti_tunnel_cbs.c:364 ziti_sdk_c_dial() service[svc.java-server.home.net] app_data_json[179]='{"connType":null,"dst_protocol":"tcp","dst_hostname":"java-server.home.net","dst_ip":"100.64.0.29","dst_port":"80","src_protocol":"tcp","src_ip":"100.64.0.1","src_port":"54378"}'
[2023-01-22T09:25:53.479Z] VERBOSE ziti-sdk:connect.c:101 conn_set_state() conn[0.1951/Initial] transitioning Initial => Connecting
[2023-01-22T09:25:53.479Z] VERBOSE ziti-sdk:posture.c:178 ziti_send_posture_data() ztx[0] starting to send posture data
[2023-01-22T09:25:53.479Z]   DEBUG ziti-sdk:posture.c:191 ziti_send_posture_data() ztx[0] posture checks must_send set to TRUE, new_session_id[FALSE], must_send_every_time[TRUE], new_controller_instance[FALSE]
[2023-01-22T09:25:53.479Z] VERBOSE ziti-sdk:posture.c:216 ziti_send_posture_data() ztx[0] checking posture queries on 14 service(s)
[2023-01-22T09:25:53.479Z]   DEBUG ziti-sdk:posture.c:506 ziti_pr_send_bulk() ztx[0] no change in posture data, not sending
[2023-01-22T09:25:53.479Z]   DEBUG ziti-sdk:connect.c:514 process_connect() conn[0.1951/Connecting] starting Dial connection for service[svc.java-server.home.net] with session[cld75lq6nfiy4018skuitq0zs]
[2023-01-22T09:25:53.479Z]   DEBUG ziti-sdk:connect.c:409 ziti_connect() conn[0.1951/Connecting] selected ch[core-router@tls://ziti-devel.home.net:1290] for best latency(6 ms)
[2023-01-22T09:25:53.479Z]   DEBUG ziti-sdk:connect.c:297 on_channel_connected() conn[0.1951/Connecting] selected ch[core-router@tls://ziti-devel.home.net:1290] status[0]
[2023-01-22T09:25:53.479Z]   TRACE ziti-sdk:connect.c:1015 ziti_channel_start_connection() conn[0.1951/Connecting] ch[1] => Edge Connect request token[195baffd-62dd-43ef-897c-81837f78652b]
[2023-01-22T09:25:53.479Z]   DEBUG ziti-sdk:channel.c:211 ziti_channel_add_receiver() ch[1] added receiver[1951]
[2023-01-22T09:25:53.479Z]   TRACE ziti-sdk:channel.c:383 ziti_channel_send_for_reply() ch[1] => ct[ED6F] seq[1270] len[36]
[2023-01-22T09:25:53.480Z]   TRACE ziti-sdk:channel.c:788 on_write() on_write(0x15883a0c0,0)
[2023-01-22T09:25:53.553Z]   TRACE ziti-sdk:channel.c:851 on_channel_data() ch[1] on_data [len=176]
[2023-01-22T09:25:53.553Z]   TRACE ziti-sdk:channel.c:539 process_inbound() ch[1] <= ct[ED70] seq[1169] len[0] hdrs[88]
[2023-01-22T09:25:53.553Z]   TRACE ziti-sdk:channel.c:549 process_inbound() ch[1] completing msg seq[1169] body+hrds=0+88, in_offset=0, want=88, got=88
[2023-01-22T09:25:53.553Z]   TRACE ziti-sdk:channel.c:560 process_inbound() ch[1] message is complete seq[1169] ct[ED70]
[2023-01-22T09:25:53.553Z]   TRACE ziti-sdk:connect.c:951 connect_reply_cb() conn[0.1951/Connecting] connected
[2023-01-22T09:25:53.553Z]   TRACE ziti-sdk:channel.c:333 ziti_channel_send() ch[1] => ct[ED72] seq[1271] len[24]
[2023-01-22T09:25:53.553Z] VERBOSE ziti-sdk:connect.c:101 conn_set_state() conn[0.1951/Connecting] transitioning Connecting => Connected
[2023-01-22T09:25:53.553Z] VERBOSE tunnel-cbs:ziti_tunnel_cbs.c:94 on_ziti_connect() on_ziti_connect status: 0
[2023-01-22T09:25:53.553Z]   DEBUG tunnel-sdk:ziti_tunnel.c:221 ziti_tunneler_dial_completed() ziti dial succeeded: client[tcp:100.64.0.1:54378] service[svc.java-server.home.net]
[2023-01-22T09:25:53.553Z]   TRACE tunnel-sdk:netif_shim.c:34 netif_shim_output() writing packet TCP[100.64.0.29:80 -> 100.64.0.1:54378] len=48
[2023-01-22T09:25:53.553Z]   TRACE ziti-sdk:connect.c:753 flush_connection() conn[0.1951/Connected] starting flusher
[2023-01-22T09:25:53.553Z]   TRACE ziti-sdk:channel.c:539 process_inbound() ch[1] <= ct[ED72] seq[1170] len[24] hdrs[24]
[2023-01-22T09:25:53.553Z]   TRACE ziti-sdk:channel.c:549 process_inbound() ch[1] completing msg seq[1170] body+hrds=24+24, in_offset=0, want=48, got=48
[2023-01-22T09:25:53.553Z]   TRACE ziti-sdk:channel.c:560 process_inbound() ch[1] message is complete seq[1170] ct[ED72]
[2023-01-22T09:25:53.553Z]   TRACE ziti-sdk:connect.c:753 flush_connection() conn[0.1951/Connected] starting flusher
[2023-01-22T09:25:53.554Z]   TRACE ziti-sdk:connect.c:226 on_write_completed() conn[0.1951/Connected] status 0
[2023-01-22T09:25:53.554Z]   TRACE ziti-sdk:connect.c:1423 process_edge_message() conn[0.1951/Connected] <= ct[ED72] edge_seq[1] body[24]
[2023-01-22T09:25:53.554Z] VERBOSE ziti-sdk:connect.c:844 conn_inbound_data_msg() conn[0.1951/Connected] processing crypto header(24 bytes)
[2023-01-22T09:25:53.554Z] VERBOSE ziti-sdk:connect.c:847 conn_inbound_data_msg() conn[0.1951/Connected] processed crypto header
[2023-01-22T09:25:53.554Z] VERBOSE ziti-sdk:connect.c:796 flush_to_client() conn[0.1951/Connected] 0 bytes available
[2023-01-22T09:25:53.554Z]   TRACE ziti-sdk:connect.c:783 flush_to_service() conn[0.1951/Connected] flushed 0 messages
[2023-01-22T09:25:53.554Z]   TRACE ziti-sdk:connect.c:746 on_flush() conn[0.1951/Connected] stopping flusher
[2023-01-22T09:25:53.554Z]   TRACE tunnel-sdk:tunnel_tcp.c:325 recv_tcp() received segment 100.64.0.1:54378->100.64.0.29:80
[2023-01-22T09:25:53.554Z]   DEBUG tunnel-sdk:tunnel_tcp.c:59 on_accept() on_accept: 0
[2023-01-22T09:25:53.554Z]   TRACE tunnel-sdk:tunnel_tcp.c:325 recv_tcp() received segment 100.64.0.1:54378->100.64.0.29:80
[2023-01-22T09:25:53.554Z] VERBOSE tunnel-sdk:tunnel_tcp.c:134 on_tcp_client_data() status 0 0x102e42630, state=4(ESTABLISHED) flags=0x101
[2023-01-22T09:25:53.554Z]   TRACE ziti-sdk:connect.c:1284 ziti_write() conn[0.1951/Connected] write 108 bytes
[2023-01-22T09:25:53.554Z]   TRACE ziti-sdk:connect.c:753 flush_connection() conn[0.1951/Connected] starting flusher
[2023-01-22T09:25:53.554Z] VERBOSE ziti-sdk:connect.c:796 flush_to_client() conn[0.1951/Connected] 0 bytes available
[2023-01-22T09:25:53.554Z]   TRACE ziti-sdk:channel.c:333 ziti_channel_send() ch[1] => ct[ED72] seq[1272] len[125]
[2023-01-22T09:25:53.554Z]   TRACE ziti-sdk:connect.c:783 flush_to_service() conn[0.1951/Connected] flushed 1 messages
[2023-01-22T09:25:53.554Z]   TRACE ziti-sdk:connect.c:746 on_flush() conn[0.1951/Connected] stopping flusher
[2023-01-22T09:25:53.554Z]   TRACE ziti-sdk:connect.c:226 on_write_completed() conn[0.1951/Connected] status 0
[2023-01-22T09:25:53.626Z]   TRACE tunnel-sdk:netif_shim.c:34 netif_shim_output() writing packet TCP[100.64.0.29:80 -> 100.64.0.1:54378] len=40

{removed quite a lot DNS and some Service Refresh logs}

[2023-01-22T09:26:23.577Z]   TRACE ziti-sdk:channel.c:851 on_channel_data() ch[1] on_data [len=56]
[2023-01-22T09:26:23.577Z]   TRACE ziti-sdk:channel.c:539 process_inbound() ch[1] <= ct[ED72] seq[1173] len[0] hdrs[36]
[2023-01-22T09:26:23.577Z]   TRACE ziti-sdk:channel.c:549 process_inbound() ch[1] completing msg seq[1173] body+hrds=0+36, in_offset=0, want=36, got=36
[2023-01-22T09:26:23.577Z]   TRACE ziti-sdk:channel.c:560 process_inbound() ch[1] message is complete seq[1173] ct[ED72]
[2023-01-22T09:26:23.577Z]   TRACE ziti-sdk:connect.c:753 flush_connection() conn[0.1951/Connected] starting flusher
[2023-01-22T09:26:23.577Z]   TRACE ziti-sdk:connect.c:1423 process_edge_message() conn[0.1951/Connected] <= ct[ED72] edge_seq[2] body[0]
[2023-01-22T09:26:23.577Z] VERBOSE ziti-sdk:connect.c:796 flush_to_client() conn[0.1951/Connected] 0 bytes available
[2023-01-22T09:26:23.577Z]   TRACE tunnel-cbs:ziti_tunnel_cbs.c:112 on_ziti_data() got -18 bytes from ziti
[2023-01-22T09:26:23.577Z]   DEBUG tunnel-cbs:ziti_tunnel_cbs.c:127 on_ziti_data() ziti connection sent EOF (ziti_eof=0, tnlr_eof=0)
[2023-01-22T09:26:23.577Z]   DEBUG tunnel-sdk:ziti_tunnel.c:466 ziti_tunneler_close_write() closing write connection: client[tcp:100.64.0.1:54378] service[svc.java-server.home.net]
[2023-01-22T09:26:23.577Z]   DEBUG tunnel-sdk:tunnel_tcp.c:217 tunneler_tcp_close_write() closing write 0x102e42630, state=4(ESTABLISHED) flags=0x100
[2023-01-22T09:26:23.577Z]   TRACE tunnel-sdk:netif_shim.c:34 netif_shim_output() writing packet TCP[100.64.0.29:80 -> 100.64.0.1:54378] len=40
[2023-01-22T09:26:23.577Z]   DEBUG tunnel-sdk:tunnel_tcp.c:223 tunneler_tcp_close_write() closed write 0x102e42630, state=5(FIN_WAIT_1) flags=0x120
[2023-01-22T09:26:23.577Z]   TRACE ziti-sdk:connect.c:783 flush_to_service() conn[0.1951/Connected] flushed 0 messages
[2023-01-22T09:26:23.577Z]   TRACE ziti-sdk:connect.c:746 on_flush() conn[0.1951/Connected] stopping flusher
[2023-01-22T09:26:23.577Z]   TRACE tunnel-sdk:tunnel_tcp.c:325 recv_tcp() received segment 100.64.0.1:54378->100.64.0.29:80
[2023-01-22T09:26:23.595Z]   TRACE tunnel-sdk:tunnel_tcp.c:325 recv_tcp() received segment 100.64.0.1:54378->100.64.0.29:80
[2023-01-22T09:26:23.595Z] VERBOSE tunnel-sdk:tunnel_tcp.c:134 on_tcp_client_data() status 0 0x102e42630, state=10(TIME_WAIT) flags=0x123
[2023-01-22T09:26:23.595Z]   DEBUG tunnel-sdk:tunnel_tcp.c:138 on_tcp_client_data() client sent FIN: client=tcp:100.64.0.1:54378, service=svc.java-server.home.net
[2023-01-22T09:26:23.595Z]   DEBUG tunnel-sdk:tunnel_tcp.c:139 on_tcp_client_data() FIN received 0x102e42630, state=10(TIME_WAIT) flags=0x123
[2023-01-22T09:26:23.595Z]   DEBUG tunnel-cbs:ziti_tunnel_cbs.c:159 ziti_sdk_c_close_write() closing ziti_conn tnlr_eof=0, ziti_eof=1
[2023-01-22T09:26:23.595Z]   DEBUG tunnel-cbs:ziti_tunnel_cbs.c:162 ziti_sdk_c_close_write() closing ziti_conn tnlr_eof=1, ziti_eof=1
[2023-01-22T09:26:23.595Z]   TRACE ziti-sdk:channel.c:333 ziti_channel_send() ch[1] => ct[ED71] seq[1276] len[0]
[2023-01-22T09:26:23.595Z]   TRACE tunnel-sdk:netif_shim.c:34 netif_shim_output() writing packet TCP[100.64.0.29:80 -> 100.64.0.1:54378] len=40
[2023-01-22T09:26:23.595Z]   TRACE ziti-sdk:connect.c:226 on_write_completed() conn[0.1951/Connected] status 0
[2023-01-22T09:26:23.595Z] VERBOSE ziti-sdk:connect.c:101 conn_set_state() conn[0.1951/Connected] transitioning Connected => Closed
[2023-01-22T09:26:23.595Z]   DEBUG ziti-sdk:connect.c:169 close_conn_internal() conn[0.1951/Closed] removing
[2023-01-22T09:26:23.595Z]   TRACE tunnel-cbs:ziti_tunnel_cbs.c:592 ziti_conn_close_cb() ziti_conn[0x158b6fb20] is closed
[2023-01-22T09:26:23.595Z]   DEBUG tunnel-sdk:ziti_tunnel.c:435 ziti_tunneler_close() closing connection: client[tcp:100.64.0.1:54378] service[svc.java-server.home.net]
[2023-01-22T09:26:23.595Z]   DEBUG tunnel-sdk:tunnel_tcp.c:233 tunneler_tcp_close() closing 0x102e42630, state=10(TIME_WAIT) flags=0x120
[2023-01-22T09:26:23.595Z]   DEBUG tunnel-sdk:tunnel_tcp.c:244 tunneler_tcp_close() closed 0x102e42630, state=10(TIME_WAIT) flags=0x130
[2023-01-22T09:26:23.595Z] VERBOSE tunnel-cbs:ziti_tunnel_cbs.c:604 ziti_conn_close_cb() nulled data for ziti_conn[0x158b6fb20]
[2023-01-22T09:26:23.595Z]   DEBUG ziti-sdk:channel.c:218 ziti_channel_rem_receiver() ch[1] removed receiver[1951]
[2023-01-22T09:26:23.595Z]   TRACE ziti-sdk:connect.c:144 free_ziti_listen_opts() refuse to free NULL listen_opts
[2023-01-22T09:26:23.595Z]   TRACE ziti-sdk:connect.c:211 close_conn_internal() conn[0.1951/Closed] is being free()'d
[2023-01-22T09:26:23.595Z]   DEBUG ziti-sdk:ziti.c:1531 grim_reaper() ztx[0] reaped 1 closed (out of 56 total) connections
[2023-01-22T09:26:26.264Z]   TRACE tunnel-sdk:tunnel_udp.c:175 recv_udp() received datagram 100.64.0.2:52228->100.64.0.2:53
[2023-01-22T09:26:26.264Z] VERBOSE tunnel-sdk:tunnel_udp.c:100 on_udp_client_data() 47 bytes from 100.64.0.1:52228

I Hope the logs bring up a idea where I can dig into. In the real project there a bunch of additional components, some of them making heavy usage of the java.nio stuff like netty, jgroups and so on. This is currenlty my only idea I have... :ziggy_question:

5

Hi,

I tried to dig deeper into where the issue occures, but it is hard as I’m working on eclipse and it seems kotlin support for eclipse is not very good - no breakpoints and so on.
Never the less it seems the error occurs during libsodium decrypt here in StreamImpl.kt - libsodium just refuses to decrypt the package.

As lazysodium is implemented in Java I was able to put some additional logging hooks in place. libsodium refuses to decode the stuff - but why? It seems to be the first packet received in the session is failing…

This is from a working session:

TRACE 81487 --- [andler-executor] tlschannel.impl.TlsChannelImpl           : Read from channel; response: 0, buffer: java.nio.HeapByteBuffer[pos=0 lim=4096 cap=4096]
TRACE 81487 --- [andler-executor] tlschannel.impl.TlsChannelImpl           : engine.unwrap() result [status=BUFFER_UNDERFLOW,handshakeStatus=NOT_HANDSHAKING,bytesProduced=0,bytesConsumed=0]. engine status: NOT_HANDSHAKING; inEncrypted BufferHolder{name='inEncrypted', allocator=tlschannel.TrackingAllocator@4dc9b0ea, plainData=false, maxSize=17408, opportunisticDispose=true, buffer=java.nio.HeapByteBuffer[pos=0 lim=0 cap=4096], lastSize=4096}; inPlain: ByteBufferSet[[java.nio.HeapByteBuffer[pos=0 lim=20 cap=20]]:0:1]
TRACE 81487 --- [andler-executor] tlschannel.impl.TlsChannelImpl           : Reading from channel
TRACE 81487 --- [andler-executor] tlschannel.impl.TlsChannelImpl           : Read from channel; response: 97, buffer: java.nio.HeapByteBuffer[pos=97 lim=4096 cap=4096]
TRACE 81487 --- [andler-executor] tlschannel.impl.TlsChannelImpl           : engine.unwrap() result [status=BUFFER_OVERFLOW,handshakeStatus=NOT_HANDSHAKING,bytesProduced=0,bytesConsumed=0]. engine status: NOT_HANDSHAKING; inEncrypted BufferHolder{name='inEncrypted', allocator=tlschannel.TrackingAllocator@4dc9b0ea, plainData=false, maxSize=17408, opportunisticDispose=true, buffer=java.nio.HeapByteBuffer[pos=0 lim=97 cap=4096], lastSize=4096}; inPlain: ByteBufferSet[[java.nio.HeapByteBuffer[pos=0 lim=20 cap=20]]:0:1]
TRACE 81487 --- [andler-executor] tlschannel.impl.TlsChannelImpl           : engine.unwrap() result [status=OK,handshakeStatus=NOT_HANDSHAKING,bytesProduced=68,bytesConsumed=97]. engine status: NOT_HANDSHAKING; inEncrypted BufferHolder{name='inEncrypted', allocator=tlschannel.TrackingAllocator@4dc9b0ea, plainData=false, maxSize=17408, opportunisticDispose=true, buffer=java.nio.HeapByteBuffer[pos=97 lim=97 cap=4096], lastSize=4096}; inPlain: ByteBufferSet[[java.nio.HeapByteBuffer[pos=68 lim=4096 cap=4096]]:0:1]
TRACE 81487 --- [5 @coroutine#15] Channel[tls://ziti-devel.home.net:1290]  : got m = ct: Data, seq: 57, repTo: -1, connId: 10, body 24 bytes
TRACE 81487 --- [5 @coroutine#15] ziti-conn[p6wiijikj/10]                  : conn[10] received message[Data] with seq[1]
TRACE 81487 --- [5 @coroutine#15] ziti-conn[p6wiijikj/10]                  : received data(24 bytes) for conn[10]
DEBUG 81487 --- [5 @coroutine#15] com.goterl.lazysodium.LazySodium         : cryptoSecretStreamInitPull[true]: header: 2f6242e1b9637016bc6629befa0c3b52c7d8ab953030c838 key: 243c9bee9248a7ddb5b52293550a021e6d684abacd5b834923257322fada36bb
DEBUG 81487 --- [5 @coroutine#15] ziti-conn[p6wiijikj/10]                  : crypto init finished conn[10]
TRACE 81487 --- [andler-executor] tlschannel.impl.TlsChannelImpl           : engine.unwrap() result [status=BUFFER_UNDERFLOW,handshakeStatus=NOT_HANDSHAKING,bytesProduced=0,bytesConsumed=0]. engine status: NOT_HANDSHAKING; inEncrypted BufferHolder{name='inEncrypted', allocator=tlschannel.TrackingAllocator@4dc9b0ea, plainData=false, maxSize=17408, opportunisticDispose=true, buffer=java.nio.HeapByteBuffer[pos=0 lim=0 cap=4096], lastSize=4096}; inPlain: ByteBufferSet[[java.nio.HeapByteBuffer[pos=0 lim=20 cap=20]]:0:1]
TRACE 81487 --- [andler-executor] tlschannel.impl.TlsChannelImpl           : Reading from channel
TRACE 81487 --- [andler-executor] tlschannel.impl.TlsChannelImpl           : Read from channel; response: 198, buffer: java.nio.HeapByteBuffer[pos=198 lim=4096 cap=4096]
TRACE 81487 --- [andler-executor] tlschannel.impl.TlsChannelImpl           : engine.unwrap() result [status=BUFFER_OVERFLOW,handshakeStatus=NOT_HANDSHAKING,bytesProduced=0,bytesConsumed=0]. engine status: NOT_HANDSHAKING; inEncrypted BufferHolder{name='inEncrypted', allocator=tlschannel.TrackingAllocator@4dc9b0ea, plainData=false, maxSize=17408, opportunisticDispose=true, buffer=java.nio.HeapByteBuffer[pos=0 lim=198 cap=4096], lastSize=4096}; inPlain: ByteBufferSet[[java.nio.HeapByteBuffer[pos=0 lim=20 cap=20]]:0:1]
TRACE 81487 --- [andler-executor] tlschannel.impl.TlsChannelImpl           : engine.unwrap() result [status=OK,handshakeStatus=NOT_HANDSHAKING,bytesProduced=169,bytesConsumed=198]. engine status: NOT_HANDSHAKING; inEncrypted BufferHolder{name='inEncrypted', allocator=tlschannel.TrackingAllocator@4dc9b0ea, plainData=false, maxSize=17408, opportunisticDispose=true, buffer=java.nio.HeapByteBuffer[pos=198 lim=198 cap=4096], lastSize=4096}; inPlain: ByteBufferSet[[java.nio.HeapByteBuffer[pos=169 lim=4096 cap=4096]]:0:1]
TRACE 81487 --- [5 @coroutine#15] Channel[tls://ziti-devel.home.net:1290]  : got m = ct: Data, seq: 58, repTo: -1, connId: 10, body 125 bytes
TRACE 81487 --- [5 @coroutine#15] ziti-conn[p6wiijikj/10]                  : conn[10] received message[Data] with seq[2]
TRACE 81487 --- [5 @coroutine#15] ziti-conn[p6wiijikj/10]                  : received data(125 bytes) for conn[10]
DEBUG 81487 --- [5 @coroutine#15] com.goterl.lazysodium.LazySodium         : cryptoSecretStreamPull[true]: msg: 474554202f2e6d6f6e69746f72696e672f4e6f646553746174757320485454502f312e310d0a486f73743a206a756d70792d646576656c2e73656361646d2e6f72670d0a557365722d4167656e743a206375726c2f372e38352e300d0a4163636570743a202a2f2a0d0a0d0a tag: null cipher: 4b7f8a506d7fa3845bc5f6b44d3de6054319a8527da4d90f6c7ac5ef77381f5e90c92fa984019e182c99639842c14c4c1fa0615dd4506c415d43534a14978f417e375407b2ae6443486edc69a8a62f6549de37970f86be8b0a506a1aac9b6c786c8577385ce8e7766544f098202fa65e9a4737004c124f352d5057d44f cipherlen: 125

and this for a failing session:

TRACE 81487 --- [andler-executor] tlschannel.impl.TlsChannelImpl           : Read from channel; response: 0, buffer: java.nio.HeapByteBuffer[pos=0 lim=4096 cap=4096]
TRACE 81487 --- [andler-executor] tlschannel.impl.TlsChannelImpl           : engine.unwrap() result [status=BUFFER_UNDERFLOW,handshakeStatus=NOT_HANDSHAKING,bytesProduced=0,bytesConsumed=0]. engine status: NOT_HANDSHAKING; inEncrypted BufferHolder{name='inEncrypted', allocator=tlschannel.TrackingAllocator@4dc9b0ea, plainData=false, maxSize=17408, opportunisticDispose=true, buffer=java.nio.HeapByteBuffer[pos=0 lim=0 cap=4096], lastSize=4096}; inPlain: ByteBufferSet[[java.nio.HeapByteBuffer[pos=0 lim=20 cap=20]]:0:1]
TRACE 81487 --- [andler-executor] tlschannel.impl.TlsChannelImpl           : Reading from channel
TRACE 81487 --- [andler-executor] tlschannel.impl.TlsChannelImpl           : Read from channel; response: 295, buffer: java.nio.HeapByteBuffer[pos=295 lim=4096 cap=4096]
TRACE 81487 --- [andler-executor] tlschannel.impl.TlsChannelImpl           : engine.unwrap() result [status=BUFFER_OVERFLOW,handshakeStatus=NOT_HANDSHAKING,bytesProduced=0,bytesConsumed=0]. engine status: NOT_HANDSHAKING; inEncrypted BufferHolder{name='inEncrypted', allocator=tlschannel.TrackingAllocator@4dc9b0ea, plainData=false, maxSize=17408, opportunisticDispose=true, buffer=java.nio.HeapByteBuffer[pos=0 lim=295 cap=4096], lastSize=4096}; inPlain: ByteBufferSet[[java.nio.HeapByteBuffer[pos=0 lim=20 cap=20]]:0:1]
TRACE 81487 --- [andler-executor] tlschannel.impl.TlsChannelImpl           : engine.unwrap() result [status=OK,handshakeStatus=NOT_HANDSHAKING,bytesProduced=68,bytesConsumed=97]. engine status: NOT_HANDSHAKING; inEncrypted BufferHolder{name='inEncrypted', allocator=tlschannel.TrackingAllocator@4dc9b0ea, plainData=false, maxSize=17408, opportunisticDispose=true, buffer=java.nio.HeapByteBuffer[pos=97 lim=295 cap=4096], lastSize=4096}; inPlain: ByteBufferSet[[java.nio.HeapByteBuffer[pos=68 lim=4096 cap=4096]]:0:1]
TRACE 81487 --- [2 @coroutine#15] Channel[tls://ziti-devel.home.net:1290]  : got m = ct: Data, seq: 62, repTo: -1, connId: 11, body 24 bytes
TRACE 81487 --- [2 @coroutine#15] ziti-conn[p6wiijikj/11]                  : conn[11] received message[Data] with seq[1]
TRACE 81487 --- [2 @coroutine#15] ziti-conn[p6wiijikj/11]                  : received data(24 bytes) for conn[11]
DEBUG 81487 --- [2 @coroutine#15] com.goterl.lazysodium.LazySodium         : cryptoSecretStreamInitPull[true]: header: f42f70f7f8f45d2566f4e0d6c46f1674db8e31bf772c7817 key: 3d1c8b03fce2818bde381a9be9b41ecf3eac9cbdc66618cec42a6edb1750b360
DEBUG 81487 --- [2 @coroutine#15] ziti-conn[p6wiijikj/11]                  : crypto init finished conn[11]
TRACE 81487 --- [andler-executor] tlschannel.impl.TlsChannelImpl           : engine.unwrap() result [status=BUFFER_OVERFLOW,handshakeStatus=NOT_HANDSHAKING,bytesProduced=0,bytesConsumed=0]. engine status: NOT_HANDSHAKING; inEncrypted BufferHolder{name='inEncrypted', allocator=tlschannel.TrackingAllocator@4dc9b0ea, plainData=false, maxSize=17408, opportunisticDispose=true, buffer=java.nio.HeapByteBuffer[pos=0 lim=198 cap=4096], lastSize=4096}; inPlain: ByteBufferSet[[java.nio.HeapByteBuffer[pos=0 lim=20 cap=20]]:0:1]
TRACE 81487 --- [andler-executor] tlschannel.impl.TlsChannelImpl           : engine.unwrap() result [status=OK,handshakeStatus=NOT_HANDSHAKING,bytesProduced=169,bytesConsumed=198]. engine status: NOT_HANDSHAKING; inEncrypted BufferHolder{name='inEncrypted', allocator=tlschannel.TrackingAllocator@4dc9b0ea, plainData=false, maxSize=17408, opportunisticDispose=true, buffer=java.nio.HeapByteBuffer[pos=198 lim=198 cap=4096], lastSize=4096}; inPlain: ByteBufferSet[[java.nio.HeapByteBuffer[pos=169 lim=4096 cap=4096]]:0:1]
TRACE 81487 --- [2 @coroutine#15] Channel[tls://ziti-devel.home.net:1290]  : got m = ct: Data, seq: 63, repTo: -1, connId: 11, body 125 bytes
TRACE 81487 --- [2 @coroutine#15] ziti-conn[p6wiijikj/11]                  : conn[11] received message[Data] with seq[2]
TRACE 81487 --- [2 @coroutine#15] ziti-conn[p6wiijikj/11]                  : received data(125 bytes) for conn[11]
DEBUG 81487 --- [2 @coroutine#15] com.goterl.lazysodium.LazySodium         : cryptoSecretStreamPull[false]: msg: 000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000 tag: null cipher: b6e3ffbc8f78d7af67ace5f374b61ed5475107edcfe75b19d138693b22eadc2930ff37dce9733d0db64cee0bd69db3bee8d6c0dc984da9e11878251b0a4b6da8439c37d92c91afc8f4350612a7e9d98a641858ee82b5d4a53ae118ad3d48d1b90a1aef84bf8adeaf8cf0fe20f9fa5938ca2eeb4fbedf6b1f980768f720 cipherlen: 125
 WARN 81487 --- [2 @coroutine#15] Channel[tls://ziti-devel.home.net:1290]  : failed to dispatch: decryption failure
6

Okay I found the issue! @TheLumberjack you have been right with your guess - it was a double binding. But the client did both bindings:

Due to a ‘refresh loop’ the server executed

        val zitiServer = zitiContext.openServer()
        zitiServer.bind(ZitiAddress.Bind(service))

twice - And I guess so it was bound multiple times to the service, with different sessions. But for whatever reasons both bind call’s ended up on the 2nd ‘bind’, but it was only able to decrypt half of the calls. Maybe I accidentally found a bug by ‘wrong usage’ :rofl:

So for everybody finding this thread bo looking for the decryption failure - double check if bind was called twice!

7

Ah yeah, that makes sense too. Glad to hear you got it sorted!