Ugh. I I’m sorry. I’m glad you bumped the thread though. I’ll make sure me or Paul come back to this today. Sorry for dropping the ball on you, appreciate you posting though!
1 Like
@plorenz I’ve gotten access to the hosted router. There do seem like corresponding errors at that the time as reported above from @aepurvis. These are all the logs from the hosted router at the Mar 27 12:05 – Mar 27 12:07 timeframe.
Mar 27 12:05:04 ziti-router[61780]: {"_context":"tls:0.0.0.0:443","file":"github.com/openziti/channel/v2@v2.0.27/classic_listener.go:158","func":"github.com/openziti/channel/v2.(*classicListener).acceptConnection.func1","level":"error","msg":"error receiving hello from [tls:87.236.176.72:37431] (receive error (tls: first record does not look like a TLS handshake))","time":"2023-03-27T12:05:04.779Z"}
Mar 27 12:05:19 ziti-router[61780]: {"_context":"tls:0.0.0.0:443","file":"github.com/openziti/channel/v2@v2.0.27/classic_listener.go:158","func":"github.com/openziti/channel/v2.(*classicListener).acceptConnection.func1","level":"error","msg":"error receiving hello from [tls:87.236.176.56:38719] (receive error (tls: first record does not look like a TLS handshake))","time":"2023-03-27T12:05:19.992Z"}
Mar 27 12:05:35 ziti-router[61780]: {"_context":"tls:0.0.0.0:443","file":"github.com/openziti/channel/v2@v2.0.27/classic_listener.go:158","func":"github.com/openziti/channel/v2.(*classicListener).acceptConnection.func1","level":"error","msg":"error receiving hello from [tls:87.236.176.73:47487] (receive error (tls: first record does not look like a TLS handshake))","time":"2023-03-27T12:05:35.192Z"}
Mar 27 12:05:50 ziti-router[61780]: {"_context":"tls:0.0.0.0:443","file":"github.com/openziti/channel/v2@v2.0.27/classic_listener.go:158","func":"github.com/openziti/channel/v2.(*classicListener).acceptConnection.func1","level":"error","msg":"error receiving hello from [tls:87.236.176.63:35223] (receive error (tls: first record does not look like a TLS handshake))","time":"2023-03-27T12:05:50.364Z"}
Mar 27 12:05:58 ziti-router[61780]: {"circuitId":"paZWFReSu","ctrlId":"client","file":"github.com/openziti/fabric@v0.22.24/router/forwarder/scanner.go:85","func":"github.com/openziti/fabric/router/forwarder.(*Scanner).scan","idleThreshold":60000000000,"idleTime":19765315000000,"level":"warning","msg":"circuit exceeds idle threshold","time":"2023-03-27T12:05:58.682Z"}
Mar 27 12:05:58 ziti-router[61780]: {"circuitId":"40qseoFSy","ctrlId":"client","file":"github.com/openziti/fabric@v0.22.24/router/forwarder/scanner.go:85","func":"github.com/openziti/fabric/router/forwarder.(*Scanner).scan","idleThreshold":60000000000,"idleTime":19768720000000,"level":"warning","msg":"circuit exceeds idle threshold","time":"2023-03-27T12:05:58.682Z"}
Mar 27 12:05:58 ziti-router[61780]: {"circuitCount":2,"ctrlId":"client","file":"github.com/openziti/fabric@v0.22.24/router/forwarder/scanner.go:97","func":"github.com/openziti/fabric/router/forwarder.(*Scanner).scan","level":"warning","msg":"sent confirmation for circuits","time":"2023-03-27T12:05:58.682Z"}
Mar 27 12:06:05 ziti-router[61780]: {"_context":"tls:0.0.0.0:443","file":"github.com/openziti/channel/v2@v2.0.27/classic_listener.go:158","func":"github.com/openziti/channel/v2.(*classicListener).acceptConnection.func1","level":"error","msg":"error receiving hello from [tls:_ipredacted_:57221] (receive error (tls: first record does not look like a TLS handshake))","time":"2023-03-27T12:06:05.537Z"}
Mar 27 12:06:05 ziti-router[61780]: {"_context":"tls:0.0.0.0:443","file":"github.com/openziti/channel/v2@v2.0.27/classic_listener.go:158","func":"github.com/openziti/channel/v2.(*classicListener).acceptConnection.func1","level":"error","msg":"error receiving hello from [tls:_ipredacted_:56705] (receive error (tls: first record does not look like a TLS handshake))","time":"2023-03-27T12:06:05.709Z"}
Mar 27 12:06:58 ziti-router[61780]: {"circuitId":"40qseoFSy","ctrlId":"client","file":"github.com/openziti/fabric@v0.22.24/router/forwarder/scanner.go:85","func":"github.com/openziti/fabric/router/forwarder.(*Scanner).scan","idleThreshold":60000000000,"idleTime":19828721000000,"level":"warning","msg":"circuit exceeds idle threshold","time":"2023-03-27T12:06:58.683Z"}
Mar 27 12:06:58 ziti-router[61780]: {"circuitId":"paZWFReSu","ctrlId":"client","file":"github.com/openziti/fabric@v0.22.24/router/forwarder/scanner.go:85","func":"github.com/openziti/fabric/router/forwarder.(*Scanner).scan","idleThreshold":60000000000,"idleTime":19825316000000,"level":"warning","msg":"circuit exceeds idle threshold","time":"2023-03-27T12:06:58.683Z"}
Mar 27 12:06:58 ziti-router[61780]: {"circuitCount":2,"ctrlId":"client","file":"github.com/openziti/fabric@v0.22.24/router/forwarder/scanner.go:97","func":"github.com/openziti/fabric/router/forwarder.(*Scanner).scan","level":"warning","msg":"sent confirmation for circuits","time":"2023-03-27T12:06:58.683Z"}
It sure looks like the router is closing the connection but it looks like it is due to “receive error (tls: first record does not look like a TLS handshake)”.
It feels like we might need to find a way to emulate a satellite connection in order to figure out what’s happening here. That doesn’t seem like it’ll be easy to replicate, but maybe there’s another way to try to figure out how this is happening?
Would it help to have SSH access to the private router? That’s the only thing running on that VM.
If you wanted to provide that for a short amount of time, that would probably prove to be quite helpful. I was talking to Paul about this today and this sort of debugging is really hard when you can’t observe it directly. I’d be happy to arrange a time when you wanted to provide access. You can email me at clint at openziti.org if you want to send me an ip and i’ll reply with my pubkey (or you can give me user/pwd too)
Hi @aepurvis ,
Apologies from me as well for losing track of this. We’ve made some progress. For whatever reason (it’s being dug into), the config of the hosted router wasn’t correct. I’ve updated it and there’s now a link between your private router and the hosted edge router. There’s a connect timeout setting for both sides of the link, so I bumped the listener side to 10s as well. I’m thinking we should bump that from the default of 1s to maybe 5 seconds. That’s still relatively quick, while allowing for more slower networks to work without needed their config updated. We’ll follow up with what we find out about the incorrect config.
Cheers,
Paul
Hi @aepurvis,
Thanks for reporting the issue you’re having with your NetFoundry hosted network. We’ve confirmed that you have discovered a bug with the teams version of our hosted router. We have identified a solution, and we’re busy adding more tests before pushing the fix out to everyone next week.
Paul and TheLumberjack have taken care of your router configuration, so you don’t need to redeploy or anything after we’ve pushed the fix.
Thanks for digging into it. Happy to hear that there was an answer.
I’ve got everything set up again and remote access is working. I’ve got something off though. Local traffic is being routed out over the internet. The SSH appwan is associated with home and roaming endpoints. The home-network policy is associated with the private router and the home endpoints. The hosted router is associated with the roaming endpoints. I’ve tried associating the private router endpoint with home endpoint and no endpoint. The SSH services are hosted by the private router endpoint (I can’t connect at all locally if hosted by the target endpoint, eg raspi).
I’ve gone back through the original instructions and think I’ve got everything set properly.
The most obvious is ssh from the laptop (roaming and local network) to raspi1 although the page loads for the weather station and OpenHab (both on raspi1, but service hosted by the private router endpoint) seem slow enough that I’m sure they’re routing outside the local network.
As for the raspi1 to raspi2 scenario you mentioned in your email, that connection is being refused.
With logging set to 6 I dumped the identities and restarted the service on the laptop and attempted an ssh connection to raspi1. It doesn’t seem like the level of detail that I’d expect so not sure if I set the logging level correctly. Is there an actual log file somewhere?
andrew@ThinkPad-SL510:~$ sudo systemctl status --no-pager -l -n 50 ziti-edge-tunnel.service
● ziti-edge-tunnel.service - Ziti Edge Tunnel
Loaded: loaded (/etc/systemd/system/ziti-edge-tunnel.service; enabled; vendor preset: enabled)
Active: active (running) since Tue 2023-04-25 15:36:00 MST; 40s ago
Process: 110266 ExecStartPre=/opt/openziti/bin/ziti-edge-tunnel.sh (code=exited, status=0/SUCCESS)
Main PID: 110280 (ziti-edge-tunne)
Tasks: 5 (limit: 9258)
Memory: 6.9M
CPU: 343ms
CGroup: /system.slice/ziti-edge-tunnel.service
└─110280 /opt/openziti/bin/ziti-edge-tunnel run --verbose=6 --dns-ip-range=100.64.0.1/10 --identity-dir=/opt/openziti/etc/identities
Apr 25 15:35:59 ThinkPad-SL510 systemd[1]: Starting Ziti Edge Tunnel...
Apr 25 15:35:59 ThinkPad-SL510 ziti-edge-tunnel.sh[110266]: NOTICE: no new JWT files in /opt/openziti/etc/identities/*.jwt
Apr 25 15:36:00 ThinkPad-SL510 systemd[1]: Started Ziti Edge Tunnel.
Apr 25 15:36:00 ThinkPad-SL510 ziti-edge-tunnel[110280]: (110280)[ 0.000] INFO ziti-sdk:utils.c:176 ziti_log_set_level() set log level: root=6/TRACE
Apr 25 15:36:00 ThinkPad-SL510 ziti-edge-tunnel[110280]: (110280)[ 0.000] TRACE ziti-edge-tunnel:instance-config.c:77 load_tunnel_status_from_file() config path exists at /var/lib/ziti
Apr 25 15:36:00 ThinkPad-SL510 ziti-edge-tunnel[110280]: (110280)[ 0.000] INFO ziti-edge-tunnel:instance-config.c:86 load_tunnel_status_from_file() Loading config file from /var/lib/ziti/config.json
Apr 25 15:36:05 ThinkPad-SL510 ziti-edge-tunnel[110280]: (110280)[ 5.088] ERROR ziti-sdk:channel.c:859 on_channel_connect_internal() ch[1] failed to connect [-3008/unknown node or service]
Apr 25 15:36:06 ThinkPad-SL510 ziti-edge-tunnel[110280]: (110280)[ 6.929] ERROR ziti-sdk:channel.c:859 on_channel_connect_internal() ch[1] failed to connect [-3008/unknown node or service]
Apr 25 15:36:10 ThinkPad-SL510 ziti-edge-tunnel[110280]: (110280)[ 10.579] ERROR ziti-sdk:channel.c:859 on_channel_connect_internal() ch[1] failed to connect [-3008/unknown node or service]
Apr 25 15:36:28 ThinkPad-SL510 ziti-edge-tunnel[110280]: (110280)[ 28.747] ERROR ziti-sdk:channel.c:859 on_channel_connect_internal() ch[1] failed to connect [-3008/unknown node or service]
Apr 25 15:36:37 ThinkPad-SL510 ziti-edge-tunnel[110280]: (110280)[ 37.208] ERROR ziti-sdk:channel.c:489 dispatch_message() ch[0] received message without conn_id or for unknown connection ct[ED71] conn_id[0]
When running as a service, the log will dump into journald. You can get the logs out using journalctl and I like using --since.
Like this:
sudo journalctl -u ziti-edge-tunnel --since "12 hours ago"
You can direct that into a file and there's the logs. Please run ziti-edge-tunnel dump too and ensure you see the "ziti dump" output in the logs.
That'll be something we can look into next. There was no obvious answer to me in the 5 minutes I looked over your config or the lack of a service defined. We'll get there after we figure out why the edge is using that public router if that's ok?
Logs from starting tunnel, dumping identities, ssh to raspi1
Apr 25 19:14:45 ThinkPad-SL510 sudo[119313]: andrew : TTY=pts/0 ; PWD=/home/andrew ; USER=root ; COMMAND=/usr/bin/systemctl start ziti-edge-tunnel.service
Apr 25 19:14:45 ThinkPad-SL510 systemd[1]: Starting Ziti Edge Tunnel...
Apr 25 19:14:45 ThinkPad-SL510 ziti-edge-tunnel.sh[119317]: NOTICE: no new JWT files in /opt/openziti/etc/identities/*.jwt
Apr 25 19:14:45 ThinkPad-SL510 systemd[1]: Started Ziti Edge Tunnel.
Apr 25 19:14:45 ThinkPad-SL510 ziti-edge-tunnel[119318]: (119318)[ 0.000] INFO ziti-sdk:utils.c:176 ziti_log_set_level() set log level: root=6/TRACE
Apr 25 19:14:45 ThinkPad-SL510 ziti-edge-tunnel[119318]: (119318)[ 0.000] TRACE ziti-edge-tunnel:instance-config.c:77 load_tunnel_status_from_file() config path exists at /var/lib/ziti
Apr 25 19:14:45 ThinkPad-SL510 ziti-edge-tunnel[119318]: (119318)[ 0.000] INFO ziti-edge-tunnel:instance-config.c:86 load_tunnel_status_from_file() Loading config file from /var/lib/ziti/config.json
Apr 25 19:14:50 ThinkPad-SL510 sudo[119466]: andrew : TTY=pts/0 ; PWD=/home/andrew ; USER=root ; COMMAND=/opt/openziti/bin/ziti-edge-tunnel dump
Apr 25 19:14:50 ThinkPad-SL510 ziti-edge-tunnel[119318]: (119318)[ 4.284] WARN ziti-edge-tunnel:ziti-edge-tunnel.c:626 on_cmd() received from client - EOF. Closing connection.
Apr 25 19:14:50 ThinkPad-SL510 ziti-edge-tunnel[119318]: (119318)[ 4.284] WARN ziti-edge-tunnel:ziti-edge-tunnel.c:638 on_cmd() IPC client connection closed, count: 0
Apr 25 19:14:51 ThinkPad-SL510 ziti-edge-tunnel[119318]: (119318)[ 5.593] ERROR ziti-sdk:channel.c:859 on_channel_connect_internal() ch[1] failed to connect [-3008/unknown node or service]
Apr 25 19:14:55 ThinkPad-SL510 ziti-edge-tunnel[119318]: (119318)[ 10.201] ERROR ziti-sdk:channel.c:859 on_channel_connect_internal() ch[1] failed to connect [-3008/unknown node or service]
Apr 25 19:14:56 ThinkPad-SL510 ziti-edge-tunnel[119318]: (119318)[ 10.506] ERROR ziti-sdk:channel.c:859 on_channel_connect_internal() ch[1] failed to connect [-3008/unknown node or service]
Apr 25 19:14:56 ThinkPad-SL510 ziti-edge-tunnel[119318]: (119318)[ 11.192] ERROR ziti-sdk:channel.c:859 on_channel_connect_internal() ch[1] failed to connect [-3008/unknown node or service]
Apr 25 19:15:03 ThinkPad-SL510 ziti-edge-tunnel[119318]: (119318)[ 18.082] ERROR ziti-sdk:channel.c:859 on_channel_connect_internal() ch[1] failed to connect [-3008/unknown node or service]
Apr 25 19:15:28 ThinkPad-SL510 ziti-edge-tunnel[119318]: (119318)[ 42.904] ERROR ziti-sdk:channel.c:489 dispatch_message() ch[0] received message without conn_id or for unknown connection ct[ED71] conn_id[2]
Apr 25 19:15:35 ThinkPad-SL510 sudo[119538]: andrew : TTY=pts/0 ; PWD=/home/andrew ; USER=root ; COMMAND=/usr/bin/journalctl -u ziti-edge-tunnel -l --since '2 minutes ago'
I suspect raspi1 to raspi2 will correct itself once laptop is using the private router.
Ah. I think these logs tell me what we need and what is misconfigured. The advertise value used in the private routers configuration is incorrect. When I setup the config, i used the hostname of the VM but that hostname is probably not reachable from your laptop, nor from raspi1/raspi2… If thats the case it also explains perfectly whyt the traffic didn’t remain local. The address specified needs to be addressable by the other nodes on the local network, otherwise they can’t connect to the locally running router.
Unfortunately, I think this means we need to do the following:
- stop the router running on ‘antlet’
- remove OpenZiti2 from your CloudZiti instance (might as well remove the older OpenZIti too)
- create a new OpenZiti router, transfer the jwt to antlet
- update the config file, find the ‘advertise’ setting and change it from ‘antlet’ to something that your laptop/raspi1/rasp2 can address. and go down to the “sans.dns” field and replace the
antlet19there as well. - re/enroll the new router using
ziti router enroll /opt/openziti/edge-router/antlet19.ziti.yaml -j /home/andrew/OpenZiti3.jwt(or whatever you named that jwt) - start the router using systemctl
We need to do this because when the router enrolls, the entries specified in the “sans” block are used to create the certificate. I had just assumed that ‘antlet19’ would have been addressable on the underlay network, I should have asked about that.
Hopefully that makes sense?
That makes sense.
I’ve had issues getting my router (the physical one) to reliably provide name service so I work with ip addresses. Although, it been so long I can’t remember the details. I’ve added antlet19 as the hostname and everything seems to be working, including pi to pi, and allowing raspi1 to host it’s own services instead of the router endpoint. The phone can connect with wifi disabled, so the laptop should as well when I’m offsite.
Thanks for all the help
Hey that’s great and we solved the pi to pi problem too, excellent. Thanks for the report and trying out openziti! I’m interested to hear any feedback you have after using it for a bit.
Thanks again for bumping the thread. Cheers!