search

atsign-foundation / noports

Connect to any device with no external listening ports open
https://noports.com
BSD 3-Clause "New" or "Revised" License
266 stars 15 forks source link

chore (dart sshnpd): Display Better Error Message #1341

Open JeremyTubongbanua opened 2 weeks ago

JeremyTubongbanua commented 2 weeks ago

Background

Here's an error I ran into with my Raspberry Pi. See logs below.

Initially, I had my /etc/ssh/sshd_config set up as so:

#Port 22
#AddressFamily any
ListenAddress 0.0.0.0
#ListenAddress ::

For some reason, this was causing issues because SSHD wasn't setup "properly"

The solution was setting it up like this:

#Port 22
#AddressFamily any
# ListenAddress 0.0.0.0
#ListenAddress ::

Proposal

Logs

SSHNPD v5.6.1 Dart

The authenticity of host 'localhost (127.0.0.1)' can't be established.
ED25519 key fingerprint is SHA256:xsswbuEV1wdqoPGnfFFLSzyEIz5AX9YqJIh6SEz23t4.
This key is not known by any other names.
Are you sure you want to continue connecting (yes/no/[fingerprint])? ^C
jeremy@raspberrypi8:/etc/systemd/system $ ~/.local/bin/sshnpd -a @soccer99 -m @soccer0 -d pi8_main -s -v
[WARN] -u, --un-hide is deprecated, since it is now on by default. Use --hide if you want to disable device information sharing.
INFO|2024-09-11 08:43:49.848806|AtLookup|Creating new connection 
INFO|2024-09-11 08:43:50.086861|AtLookup|New connection created OK 
INFO|2024-09-11 08:43:50.180790|AtLookup|auth success 
INFO|2024-09-11 08:43:50.181012|AtClientManager|setCurrentAtSign called with atSign @soccer99 
INFO|2024-09-11 08:43:50.181132|AtClientManager|Switching atSigns from null to @soccer99 
INFO|2024-09-11 08:43:50.183520|HiveBase|commit_log_c34ac8fb9f673d74260de552401a780deb0ca24a5024821b20dd473a617857df initialized successfully 
INFO|2024-09-11 08:43:50.186604|HiveBase|c34ac8fb9f673d74260de552401a780deb0ca24a5024821b20dd473a617857df initialized successfully 
INFO|2024-09-11 08:43:50.191995|AtClientCommitLogCompaction (@soccer99)|Starting commit log compaction job running for every 11 minute(s) 
INFO|2024-09-11 08:43:50.195938|AtClientManager|setCurrentAtSign complete 
INFO|2024-09-11 08:43:50.211731| sshnpd |Starting sshnpd with addSshPublicKeys on, using permissions: '' 
INFO|2024-09-11 08:43:50.212006| sshnpd |Sharing username jeremy with @soccer0 
INFO|2024-09-11 08:43:50.406510|AtLookup|Creating new connection 
INFO|2024-09-11 08:43:50.667584|AtLookup|New connection created OK 
INFO|2024-09-11 08:43:50.782814|AtLookup|auth success 
INFO|2024-09-11 08:43:50.870830| sshnpd |Starting heartbeat 
INFO|2024-09-11 08:43:50.870981| sshnpd |Subscribing to pi8_main\.sshnp@ 
INFO|2024-09-11 08:43:50.871145| sshnpd |Sharing device info for pi8_main with @soccer0 
INFO|2024-09-11 08:43:50.984920| sshnpd |Done 
INFO|2024-09-11 08:43:51.037867|Monitor (@soccer99)|monitor started for @soccer99 with last notification time: null 
INFO|2024-09-11 08:43:57.140797| sshnpd |Received: ping 
INFO|2024-09-11 08:43:57.142497| sshnpd |ping received from @soccer0 ( ping ) 
INFO|2024-09-11 08:43:57.142609| sshnpd |ping received from @soccer0 notification id : 5d490de3-a462-4daa-a9e5-bc1a10b0897f 
INFO|2024-09-11 08:44:00.330842| sshnpd |Received: ssh_request 
INFO|2024-09-11 08:44:00.330929| sshnpd |ssh_request received from @soccer0 ( {"payload":{"direct":true,"sessionId":"510585c3-fd48-4410-a970-9940c8cfe373","host":"85.239.63.180","port":39845,"authenticateToRvd":true,"clientNonce":"2024-09-11T08:43:56.422767","rvdNonce":"2024-09-11T12:35:36.510899","encryptRvdTraffic":true,"clientEphemeralPK":"MIIBIjANBgkqhkiG9w0BAQEFAAOCAQ8AMIIBCgKCAQEAljVNpspledG9igG+bR4oBd1sVjteivEzMON83KJ43C1DHIyZfrUYmSTz0iByPS7DUAcnrLOsNSFWXxNexKv8wZOHIO/MX5TmaqaS7NpEnbT2Ynpbtgh6tL2o0+TGzAbpHOBsJfK9CiDJsHrzbbCi0ExjsUG/SiMiVAKrwgkWKec50PMOOiiSzbtFI48jRO0KPmxoeFPFKAKIDgSNnAD81g81THzT3HPpXLfd5XFwGcxeRTZ1DnxQzWFEMeYQadvvVeQPCzfS8wwZo4+AdoqfbjGoEJt5hYW9UtJoK1PAfFaCYbNVWIyvTLSqH+UrzrB52BiN7IDE6r19UTaHJwzLzwIDAQAB","clientEphemeralPKType":"rsa2048"},"signature":"bq3/eRpCIqrocdqdPkfz7EmCN+jACTa0/oDXJ/mwvLnKyNKVJb/NcTJXSGlPu8YH3Qi0xX763+krnJefvr14VyQzOiCQ25bekSakQH8kHXyXxR4g96c9ze0R0HjpSGnuZuE/cuNokG1g7GJ+5oDkep9Z0N6q4lSxcDaMtY/Xxj1Lv97235rq1TcICabN4JaRESl7laxxlVBJMRduSoci1gRstH/vlbU328K5oqbX6PqvkiqGTa7ZmplkoF6c8Vng+AvNWqxDLd+z1qxPCBUw7Y5XnxkgLweT23ZOiIIgd+whAfcxoPAH/dS2vKLkaKLLZ0Mm3tOngB2kDzarMhxFdg==","hashingAlgo":"sha256","signingAlgo":"rsa2048"} ) 
INFO|2024-09-11 08:44:00.334399| sshnpd |Signing Verification Result: ResultType: bool, Result: true, SigningMetadata: {HashingAlgo: sha256, SigningAlgo: rsa2048, SignatureTimestamp: 2024-09-11 12:44:00.333354Z} 
INFO|2024-09-11 08:44:00.334537| sshnpd |svr.result is a bool 
INFO|2024-09-11 08:44:00.334572| sshnpd |svr.result is true 
INFO|2024-09-11 08:44:00.334636| sshnpd |Setting up ports for direct ssh session using openssh (openssh) from: @soccer0 session: 510585c3-fd48-4410-a970-9940c8cfe373 
INFO|2024-09-11 08:44:00.349413|SrvImplExec|SrvImplExec.run(): executing /usr/local/bin/srv -h 85.239.63.180 -p 39845 --local-port 22 --local-host localhost --timeout 30 --rv-auth --rv-e2ee 
INFO|2024-09-11 08:44:00.372382|SrvImplExec|rv stderr | INFO|2024-09-11 08:44:00.371493| SrvImplDart |New SrvImplDart - localPort 22 
INFO|2024-09-11 08:44:00.375022|SrvImplExec|rv stderr | SEVERE|2024-09-11 08:44:00.374404| SrvImplDart |SocketException: Connection refused (OS Error: Connection refused, errno = 111), address = localhost, port = 44254  
INFO|2024-09-11 08:44:00.375112|SrvImplExec|rv stderr | SHOUT|2024-09-11 08:44:00.374753| srv.main |Unhandled exception SocketException: Connection refused (OS Error: Connection refused, errno = 111), address = localhost, port = 44254; stackTrace follows 
INFO|2024-09-11 08:44:00.375148|SrvImplExec|rv stderr | #0      _NativeSocket.startConnect (dart:io-patch/socket_patch.dart:721) 
INFO|2024-09-11 08:44:00.375170|SrvImplExec|rv stderr | #1      _NativeSocket.connect (dart:io-patch/socket_patch.dart:984) 
INFO|2024-09-11 08:44:00.375211|SrvImplExec|rv stderr | #2      _RawSocket.connect (dart:io-patch/socket_patch.dart:1908) 
INFO|2024-09-11 08:44:00.376366|SrvImplExec|rv stderr | #3      RawSocket.connect (dart:io-patch/socket_patch.dart:21) 
INFO|2024-09-11 08:44:00.376674|SrvImplExec|rv stderr | #4      Socket._connect (dart:io-patch/socket_patch.dart:2134) 
INFO|2024-09-11 08:44:00.376756|SrvImplExec|rv stderr | #5      Socket.connect (dart:io/socket.dart:809) 
INFO|2024-09-11 08:44:00.376795|SrvImplExec|rv stderr | #6      SocketConnector.socketToSocket (package:socket_connector/src/socket_connector.dart:362) 
INFO|2024-09-11 08:44:00.376838|SrvImplExec|rv stderr | #7      SrvImplDart._runDaemonSideSingle (package:noports_core/src/srv/srv_impl.dart:696) 
INFO|2024-09-11 08:44:00.376875|SrvImplExec|rv stderr | <asynchronous suspension> 
INFO|2024-09-11 08:44:00.376912|SrvImplExec|rv stderr | #8      SrvImplDart.run (package:noports_core/src/srv/srv_impl.dart:429) 
INFO|2024-09-11 08:44:00.376947|SrvImplExec|rv stderr | <asynchronous suspension> 
INFO|2024-09-11 08:44:00.376979|SrvImplExec|rv stderr | #9      main.<anonymous closure> (file:///sshnoports/sshnoports/bin/srv.dart:122) 
INFO|2024-09-11 08:44:00.377260|SrvImplExec|rv stderr | <asynchronous suspension> 
INFO|2024-09-11 08:44:00.377311|SrvImplExec|rv stderr | #10     main (file:///sshnoports/sshnoports/bin/srv.dart:84) 
INFO|2024-09-11 08:44:00.377349|SrvImplExec|rv stderr | <asynchronous suspension> 
INFO|2024-09-11 08:44:00.377451|SrvImplExec|rv stderr | SHOUT|2024-09-11 08:44:00.374953| srv.main |Exception running srv : SocketException: Connection refused (OS Error: Connection refused, errno = 111), address = localhost, port = 44254 
SEVERE|2024-09-11 08:44:00.377544| sshnpd |startDirectSsh failed with unexpected error : SHOUT|2024-09-11 08:44:00.374953| srv.main |Exception running srv : SocketException: Connection refused (OS Error: Connection refused, errno = 111), address = localhost, port = 44254

Client Mac v5.5.0

INFO|2024-09-11 08:43:56.422810|Sshnp|Finding a spare local port 
INFO|2024-09-11 08:43:56.423550|Sshnp|Initializing SshnpLocalSshKeyHandler 
INFO|2024-09-11 08:43:56.423578|Sshnp|Initializing SshnpCore 
INFO|2024-09-11 08:43:56.423589| SshnpdChannel |Starting monitor for notifications with regex: "510585c3-fd48-4410-a970-9940c8cfe373.pi8_main.sshnp@soccer99" 
INFO|2024-09-11 08:43:56.423599| SshnpdChannel |Subscribing to notifications with regex: "510585c3-fd48-4410-a970-9940c8cfe373.pi8_main.sshnp@soccer99" 
INFO|2024-09-11 08:43:56.423727| SshnpdChannel |Subscribing to notifications with regex: "heartbeat.pi8_main.sshnp" 
INFO|2024-09-11 08:43:56.423747| SshnpdChannel |Sending ping to sshnpd 
INFO|2024-09-11 08:43:56.553516|AbstractAtKeyEncryption (@soccer0)|Encrypted shared symmetric key for @soccer0 not found in local storage 
INFO|2024-09-11 08:43:56.553616|AbstractAtKeyEncryption (@soccer0)|Deleting @soccer99:shared_key@soccer0 from LocalSecondary 
INFO|2024-09-11 08:43:56.554101|AbstractAtKeyEncryption (@soccer0)|Fetching shared symmetric key for @soccer0 from atServer 
INFO|2024-09-11 08:43:56.835116| SshnpdChannel |Skipped sharing public key with sshnpd: sendSshPublicKey=false 
INFO|2024-09-11 08:43:56.835197| SrvdChannel |Subscribing to notifications with regex: "510585c3-fd48-4410-a970-9940c8cfe373.sshrvd@" 
INFO|2024-09-11 08:43:56.835228| SrvdChannel |Started listening for srvd response 
INFO|2024-09-11 08:43:56.835263| SrvdChannel |Sending notification to srvd with key @rv_eu:pi8_main.request_ports.sshrvd@soccer0 and value {"sessionId":"510585c3-fd48-4410-a970-9940c8cfe373","atSignA":"@soccer0","atSignB":"@soccer99","authenticateSocketA":true,"authenticateSocketB":true,"clientNonce":"2024-09-11T08:43:56.422767"} 
INFO|2024-09-11 08:43:56.884241|AbstractAtKeyEncryption (@soccer0)|Retrieved my encrypted copy of shared symmetric key for @soccer99 from atServer - saving to local storage 
INFO|2024-09-11 08:43:56.892660|AbstractAtKeyEncryption (@soccer0)|'Their' copy of shared symmetric key for @soccer99 not found in local storage - will check atServer 
INFO|2024-09-11 08:43:56.959917|AbstractAtKeyEncryption (@soccer0)|Found 'their' copy of shared symmetric key for @soccer99 in atServer - saving to local storage 
INFO|2024-09-11 08:43:56.982798|AbstractAtKeyEncryption (@soccer0)|Encrypted shared symmetric key for @soccer0 not found in local storage 
INFO|2024-09-11 08:43:56.982868|AbstractAtKeyEncryption (@soccer0)|Deleting @rv_eu:shared_key@soccer0 from LocalSecondary 
INFO|2024-09-11 08:43:56.983082|AbstractAtKeyEncryption (@soccer0)|Fetching shared symmetric key for @soccer0 from atServer 
INFO|2024-09-11 08:43:57.053144|AbstractAtKeyEncryption (@soccer0)|Retrieved my encrypted copy of shared symmetric key for @rv_eu from atServer - saving to local storage 
INFO|2024-09-11 08:43:57.062670|AbstractAtKeyEncryption (@soccer0)|'Their' copy of shared symmetric key for @rv_eu not found in local storage - will check atServer 
INFO|2024-09-11 08:43:57.159858|AbstractAtKeyEncryption (@soccer0)|Found 'their' copy of shared symmetric key for @rv_eu in atServer - saving to local storage 
INFO|2024-09-11 08:43:57.460776| SshnpdChannel |Received ping response from @soccer99 : @soccer0:heartbeat.pi8_main.sshnp@soccer99 : {"devicename":"pi8_main","version":"5.6.1","corePackageVersion":"6.1.0","supportedFeatures":{"srAuth":true,"srE2ee":true,"acceptsPublicKeys":true,"supportsPortChoice":true,"adjustableTimeout":true},"allowedServices":["localhost:22","127.0.0.1:22"]} 
INFO|2024-09-11 08:43:57.460864| SshnpdChannel |Completing the future 
INFO|2024-09-11 08:43:57.670949| SshnpdChannel |Received ping response from @soccer99 : @soccer0:heartbeat.pi8_main.sshnp@soccer99 : {"devicename":"pi8_main","version":"5.6.1","corePackageVersion":"6.1.0","supportedFeatures":{"srAuth":true,"srE2ee":true,"acceptsPublicKeys":true,"supportsPortChoice":true,"adjustableTimeout":true},"allowedServices":["localhost:22","localhost:3389"]} 
INFO|2024-09-11 08:43:59.210173| SrvdChannel |Still waiting for srvd response 
INFO|2024-09-11 08:43:59.834313| SrvdChannel |Received from srvd: 85.239.63.180,45083,39845,2024-09-11T12:35:36.510899 
INFO|2024-09-11 08:43:59.834392| SrvdChannel |Received from srvd: rvdHost:clientPort:daemonPort 85.239.63.180:45083:39845 rvdNonce: 2024-09-11T12:35:36.510899 
INFO|2024-09-11 08:43:59.834404| SrvdChannel |Daemon will connect to: 85.239.63.180:39845 
INFO|2024-09-11 08:43:59.924844|Sshnp|Sending session request to the device daemon 
INFO|2024-09-11 08:44:00.609570| SshnpdChannel |Received 510585c3-fd48-4410-a970-9940c8cfe373.pi8_main.sshnp@soccer99 notification 
SHOUT|2024-09-11 08:44:00.609660| SshnpdChannel |invalid daemon response: Failed to start up the daemon side of the srv socket tunnel : SHOUT|2024-09-11 08:44:00.374916| srv.main |Exception running srv : SocketException: Connection refused (OS Error: Connection refused, errno = 111), address = localhost, port = 44256 
INFO|2024-09-11 08:44:00.610629| SshnpdChannel |sshnpdAck: SshnpdAck.acknowledgedWithErrors 

Error : No response from the device daemon

Stack Trace: #0      SshnpOpensshLocalImpl.run (package:noports_core/src/sshnp/impl/sshnp_openssh_local_impl.dart:88)
<asynchronous suspension>
#1      main.<anonymous closure> (file:///Users/runner/work/noports/noports/packages/dart/sshnoports/bin/sshnp.dart:188)
<asynchronous suspension>
#2      main (file:///Users/runner/work/noports/noports/packages/dart/sshnoports/bin/sshnp.dart:96)
<asynchronous suspension
JeremyTubongbanua commented 2 weeks ago

@XavierChanth Asked me to write up this ticket and write down my findings