search

atsign-foundation / noports

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

feat: Ensure npd will work on as many platforms as possible, with pure dart ssh client being ultimate fallback #299

Open JeremyTubongbanua opened 1 year ago

JeremyTubongbanua commented 1 year ago

Describe the bug

I'm only able to reproduce this bug on my VPS.

SSHNP:

./sshnp -f @client_0 -t @server_0 -h @rv_am -d vps -s id_ed25519.pub -v
...
Remote sshnpd error: Failed to establish connection - exit code 255 (use --local-port to specify unused port)

SSHNPD:

./sshnpd -a @server_0 -m @client_0 -d vps -s -u -v
...
WARNING|2023-08-03 23:15:52.135333| sshnpd |Failed to establish connection - exit code 255

Steps to reproduce

  1. Use installer script (curl...) on Device and Client from installer guide
  2. SSHNPD is automatically started on Device (VPS Linuxx64) because of installer script
  3. Use SSHNP on Client (Mac Arm64)
  4. Get the exit code 255

Expected behavior

Works just fine in my two docker containers when I test v3.4.0 as it is now

Screenshots

Client (sshnp) - Mac Arm64 M2 (Sanoma 14.0)

jeremytubongbanua@Jeremys-M2-Air bin % ls
at_activate sshnp       sshnp@server_0  sshrv
jeremytubongbanua@Jeremys-M2-Air bin % ./sshnp
Version : 3.4.0
-k, --key-file             Sending atSign's atKeys file if not in ~/.atsign/keys/
-f, --from (mandatory)     Sending (a.k.a. client) atSign
-t, --to (mandatory)       Receiving device atSign
-d, --device               Receiving device name
                           (defaults to "default")
-h, --host (mandatory)     atSign of sshrvd daemon or FQDN/IP address to connect back to
-p, --port                 TCP port to connect back to (only required if --host specified a FQDN/IP)
                           (defaults to "22")
-l, --local-port           Reverse ssh port to listen on, on your local machine, by sshnp default finds a spare port
                           (defaults to "0")
-s, --ssh-public-key       Public key file from ~/.ssh to be appended to authorized_hosts on the remote device
                           (defaults to "false")
-o, --local-ssh-options    Add these commands to the local ssh command
-v, --[no-]verbose         More logging
-r, --[no-]rsa             Use RSA 4096 keys rather than the default ED25519 keys
-u, --remote-user-name     username to use in the ssh session on the remote host
    --config-file          Read args from a config file
                           Mandatory args are not required if already supplied in the config file

Invalid argument(s): Option from is mandatory.
jeremytubongbanua@Jeremys-M2-Air bin % ./sshnp -f @client_0 -t @server_0 -h @rv_am -d vps -s id_ed25519.pub -v   
INFO|2023-08-03 19:15:48.677560|AtClientManager|setCurrentAtSign called with atSign @client_0 
INFO|2023-08-03 19:15:48.677631|AtClientManager|Switching atSigns from null to @client_0 
INFO|2023-08-03 19:15:48.678576|HiveBase|commit_log_d75a51c1003c996d4592b57407ea6b3f21a2e1163891d3612cb54a41aa363a01 initialized successfully 
INFO|2023-08-03 19:15:48.679465|HiveBase|d75a51c1003c996d4592b57407ea6b3f21a2e1163891d3612cb54a41aa363a01 initialized successfully 
INFO|2023-08-03 19:15:48.679493|AtClientCommitLogCompaction (@client_0)|Starting commit log compaction job running for every 11 minute(s) 
INFO|2023-08-03 19:15:48.680152|AtClientManager|setCurrentAtSign complete 
INFO|2023-08-03 19:15:48.680165|AtLookup|Creating new connection 
INFO|2023-08-03 19:15:49.007991|AtLookup|New connection created OK 
INFO|2023-08-03 19:15:49.148701|AtLookup|auth success 
INFO|2023-08-03 19:15:49.203843| sshnp |Subscribing to notifications on 08cfec9c-45f0-4aec-a089-c630b2406d3e.vps.sshnp@ 
INFO|2023-08-03 19:15:49.525238|AbstractAtKeyEncryption (@client_0)|Encrypted shared symmetric key for @client_0 not found in local storage 
INFO|2023-08-03 19:15:49.525294|AbstractAtKeyEncryption (@client_0)|Deleting @rv_am:shared_key@client_0 from LocalSecondary 
INFO|2023-08-03 19:15:49.525454|AbstractAtKeyEncryption (@client_0)|Fetching shared symmetric key for @client_0 from atServer 
INFO|2023-08-03 19:15:49.556308|Monitor (@client_0)|monitor started for @client_0 with last notification time: null 
INFO|2023-08-03 19:15:49.582291|AbstractAtKeyEncryption (@client_0)|Retrieved my encrypted copy of shared symmetric key for @rv_am from atServer - saving to local storage 
INFO|2023-08-03 19:15:49.590993|AbstractAtKeyEncryption (@client_0)|'Their' copy of shared symmetric key for @rv_am not found in local storage - will check atServer 
INFO|2023-08-03 19:15:49.639716|AbstractAtKeyEncryption (@client_0)|Found 'their' copy of shared symmetric key for @rv_am in atServer - saving to local storage 
INFO|2023-08-03 19:15:50.310675| sshnp |SUCCESS:id: c41eb13e-18de-4105-9601-faf53206d6e3 status: NotificationStatusEnum.delivered @rv_am:vps.sshrvd@client_0 
INFO|2023-08-03 19:15:50.493121|AbstractAtKeyEncryption (@client_0)|Encrypted shared symmetric key for @client_0 not found in local storage 
INFO|2023-08-03 19:15:50.493196|AbstractAtKeyEncryption (@client_0)|Deleting @server_0:shared_key@client_0 from LocalSecondary 
INFO|2023-08-03 19:15:50.493378|AbstractAtKeyEncryption (@client_0)|Fetching shared symmetric key for @client_0 from atServer 
INFO|2023-08-03 19:15:50.540406|AbstractAtKeyEncryption (@client_0)|Retrieved my encrypted copy of shared symmetric key for @server_0 from atServer - saving to local storage 
INFO|2023-08-03 19:15:50.548459|AbstractAtKeyEncryption (@client_0)|'Their' copy of shared symmetric key for @server_0 not found in local storage - will check atServer 
INFO|2023-08-03 19:15:50.596336|AbstractAtKeyEncryption (@client_0)|Found 'their' copy of shared symmetric key for @server_0 in atServer - saving to local storage 
INFO|2023-08-03 19:15:51.264113| sshnp |SUCCESS:id: 1b3bd292-cb13-474a-b46c-a53b881d5eef status: NotificationStatusEnum.delivered 
INFO|2023-08-03 19:15:51.930424| sshnp |SUCCESS:id: d1c3987c-3769-4ce4-9169-745db31c3d12 status: NotificationStatusEnum.delivered 
INFO|2023-08-03 19:15:52.249759| sshnp |Received 08cfec9c-45f0-4aec-a089-c630b2406d3e notification 
Remote sshnpd error: Failed to establish connection - exit code 255 (use --local-port to specify unused port)
INFO|2023-08-03 19:15:52.583145| sshnp |SUCCESS:id: 8b01a6f3-3bcd-4864-9ae8-e23868ed1b93 status: NotificationStatusEnum.delivered 57271 33141 jeremytubongbanua 85.239.53.170 08cfec9c-45f0-4aec-a089-c630b2406d3e 
INFO|2023-08-03 19:15:52.583218| sshnp |Tidying up files

Device (VPS Linux Arm64)

jeremyvps@debian:~/.local/bin$ ./sshnpd -a @server_0 -m @client_0 -d vps -s -u -v
INFO|2023-08-03 23:15:14.979536|AtClientManager|setCurrentAtSign called with atSign @server_0 
INFO|2023-08-03 23:15:14.979701|AtClientManager|Switching atSigns from null to @server_0 
INFO|2023-08-03 23:15:14.980509|HiveBase|commit_log_055719601711c762ce6bc501676e84468ea43ee6a20f32649e09e7cf951c9526 initialized successfully 
INFO|2023-08-03 23:15:14.981591|HiveBase|055719601711c762ce6bc501676e84468ea43ee6a20f32649e09e7cf951c9526 initialized successfully 
INFO|2023-08-03 23:15:14.983428|AtClientCommitLogCompaction (@server_0)|Starting commit log compaction job running for every 11 minute(s) 
INFO|2023-08-03 23:15:14.984333|AtClientManager|setCurrentAtSign complete 
INFO|2023-08-03 23:15:14.984371|AtLookup|Creating new connection 
INFO|2023-08-03 23:15:15.446247|AtLookup|New connection created OK 
INFO|2023-08-03 23:15:15.560977|AtLookup|auth success 
INFO|2023-08-03 23:15:15.898065| sshnpd |Starting connectivity listener 
INFO|2023-08-03 23:15:15.898354| sshnpd |Subscribing to vps\.sshnp@ 
INFO|2023-08-03 23:15:15.898396| sshnpd |Done 
WARNING|2023-08-03 23:15:15.900662| sshnpd |connection available 
INFO|2023-08-03 23:15:16.205073|Monitor (@server_0)|monitor started for @server_0 with last notification time: null 
INFO|2023-08-03 23:15:50.799746| sshnpd |Received: privatekey 
INFO|2023-08-03 23:15:50.800469| sshnpd |Private Key received from @client_0 notification id : 1b3bd292-cb13-474a-b46c-a53b881d5eef 
INFO|2023-08-03 23:15:51.465807| sshnpd |Received: sshpublickey 
INFO|2023-08-03 23:15:51.465877| sshnpd |ssh Public Key received from @client_0 notification id : d1c3987c-3769-4ce4-9169-745db31c3d12 
INFO|2023-08-03 23:15:52.126821| sshnpd |Received: sshd 
INFO|2023-08-03 23:15:52.126891| sshnpd |ssh callback request received from @client_0 notification id : 8b01a6f3-3bcd-4864-9ae8-e23868ed1b93 
INFO|2023-08-03 23:15:52.126929| sshnpd |Starting ssh session for jeremytubongbanua to 85.239.53.170 on port 33141 using localhost:57271 on 85.239.53.170  
SHOUT|2023-08-03 23:15:52.126941| sshnpd |Starting ssh session using hostSsh (/usr/bin/ssh) from: @client_0 session: 08cfec9c-45f0-4aec-a089-c630b2406d3e 
INFO|2023-08-03 23:15:52.130109| sshnpd |08cfec9c-45f0-4aec-a089-c630b2406d3e | Executing /usr/bin/ssh jeremytubongbanua@85.239.53.170 -p 33141 -i /tmp/.aeff58c0-1054-454a-8d04-a9e98d638c63 -R 57271:localhost:22 -o LogLevel=VERBOSE -t -t -o StrictHostKeyChecking=accept-new -o IdentitiesOnly=yes -o BatchMode=yes -o ExitOnForwardFailure=yes -o ForkAfterAuthentication=yes sleep 15 
INFO|2023-08-03 23:15:52.134912| sshnpd |08cfec9c-45f0-4aec-a089-c630b2406d3e | sshStdErr | command-line: line 0: Bad configuration option: forkafterauthentication

SHOUT|2023-08-03 23:15:52.135285| sshnpd |08cfec9c-45f0-4aec-a089-c630b2406d3e | Exit code 255 from /usr/bin/ssh jeremytubongbanua@85.239.53.170 -p 33141 -i /tmp/.aeff58c0-1054-454a-8d04-a9e98d638c63 -R 57271:localhost:22 -o LogLevel=VERBOSE -t -t -o StrictHostKeyChecking=accept-new -o IdentitiesOnly=yes -o BatchMode=yes -o ExitOnForwardFailure=yes -o ForkAfterAuthentication=yes sleep 15 
WARNING|2023-08-03 23:15:52.135333| sshnpd |Failed to establish connection - exit code 255 
INFO|2023-08-03 23:15:52.763217| sshnpd |SUCCESS:id: 3c376b2a-5e69-4854-ab1e-3724d2c2c2b5 status: NotificationStatusEnum.delivered for: 08cfec9c-45f0-4aec-a089-c630b2406d3e with value: Failed to establish connection - exit code 255 (use --local-port to specify unused port)

Smartphones

Client is MacOS Sanoma 14.0 M2 (Arm Chip) MacOS Arm64 Device is an IONOS VPS running Linux x64

Were you using an atApplication when the bug was found?

No response

Additional context

When I use docker containers, everything works just fine. So this means that trunk is working fine.

I've tested v3.3.0 client and device as well..

So my VPS (as sshnpd) does not like v3.4.0 for some reason

JeremyTubongbanua commented 1 year ago

Important detail: Device (VPS Linux Arm64) running Debian 10

@cconstab thinks it's because Debian 10 has outdated ssh

JeremyTubongbanua commented 1 year ago

The fix to this bug was running SSHNPD with the --ssh-client=pure-dart flag

jeremyvps@debian:~/.local/bin$ ./sshnpd -a @server_0 -m @client_0 -d e2e -s -u -v --ssh-client=pure-dart

Logs of it working:

SSHNP

jeremytubongbanua@Jeremys-M2-Air bin % ./sshnp -f @client_0 -t @server_0 -d e2e -s id_ed25519.pub -v -h @rv_am
INFO|2023-08-03 20:01:04.923882|AtClientManager|setCurrentAtSign called with atSign @client_0 
INFO|2023-08-03 20:01:04.923946|AtClientManager|Switching atSigns from null to @client_0 
INFO|2023-08-03 20:01:04.925659|HiveBase|commit_log_d75a51c1003c996d4592b57407ea6b3f21a2e1163891d3612cb54a41aa363a01 initialized successfully 
INFO|2023-08-03 20:01:04.926818|HiveBase|d75a51c1003c996d4592b57407ea6b3f21a2e1163891d3612cb54a41aa363a01 initialized successfully 
INFO|2023-08-03 20:01:04.926850|AtClientCommitLogCompaction (@client_0)|Starting commit log compaction job running for every 11 minute(s) 
INFO|2023-08-03 20:01:04.927503|AtClientManager|setCurrentAtSign complete 
INFO|2023-08-03 20:01:04.927519|AtLookup|Creating new connection 
INFO|2023-08-03 20:01:05.254824|AtLookup|New connection created OK 
INFO|2023-08-03 20:01:05.369083|AtLookup|auth success 
INFO|2023-08-03 20:01:05.418566| sshnp |Subscribing to notifications on 5245e3a6-c8f6-4f69-92be-74ef3285387d.e2e.sshnp@ 
INFO|2023-08-03 20:01:05.681990|AbstractAtKeyEncryption (@client_0)|Encrypted shared symmetric key for @client_0 not found in local storage 
INFO|2023-08-03 20:01:05.682043|AbstractAtKeyEncryption (@client_0)|Deleting @rv_am:shared_key@client_0 from LocalSecondary 
INFO|2023-08-03 20:01:05.682291|AbstractAtKeyEncryption (@client_0)|Fetching shared symmetric key for @client_0 from atServer 
INFO|2023-08-03 20:01:05.737836|AbstractAtKeyEncryption (@client_0)|Retrieved my encrypted copy of shared symmetric key for @rv_am from atServer - saving to local storage 
INFO|2023-08-03 20:01:05.743224|AbstractAtKeyEncryption (@client_0)|'Their' copy of shared symmetric key for @rv_am not found in local storage - will check atServer 
INFO|2023-08-03 20:01:05.749753|Monitor (@client_0)|monitor started for @client_0 with last notification time: null 
INFO|2023-08-03 20:01:05.800831|AbstractAtKeyEncryption (@client_0)|Found 'their' copy of shared symmetric key for @rv_am in atServer - saving to local storage 
INFO|2023-08-03 20:01:06.467464| sshnp |SUCCESS:id: fbff867f-195b-4c65-b85d-db7a4333532b status: NotificationStatusEnum.delivered @rv_am:e2e.sshrvd@client_0 
INFO|2023-08-03 20:01:06.652914|AbstractAtKeyEncryption (@client_0)|Encrypted shared symmetric key for @client_0 not found in local storage 
INFO|2023-08-03 20:01:06.652964|AbstractAtKeyEncryption (@client_0)|Deleting @server_0:shared_key@client_0 from LocalSecondary 
INFO|2023-08-03 20:01:06.653072|AbstractAtKeyEncryption (@client_0)|Fetching shared symmetric key for @client_0 from atServer 
INFO|2023-08-03 20:01:06.713546|AbstractAtKeyEncryption (@client_0)|Retrieved my encrypted copy of shared symmetric key for @server_0 from atServer - saving to local storage 
INFO|2023-08-03 20:01:06.719041|AbstractAtKeyEncryption (@client_0)|'Their' copy of shared symmetric key for @server_0 not found in local storage - will check atServer 
INFO|2023-08-03 20:01:06.765747|AbstractAtKeyEncryption (@client_0)|Found 'their' copy of shared symmetric key for @server_0 in atServer - saving to local storage 
INFO|2023-08-03 20:01:07.422481| sshnp |SUCCESS:id: cec47b31-3b59-445a-8afc-e6ca6d80dd0a status: NotificationStatusEnum.delivered 
INFO|2023-08-03 20:01:08.086856| sshnp |SUCCESS:id: 700fd594-1753-4491-8482-c603aab51750 status: NotificationStatusEnum.delivered 
INFO|2023-08-03 20:01:08.770126| sshnp |SUCCESS:id: adba83d0-25c5-4ecd-800b-328a90c77e89 status: NotificationStatusEnum.delivered 58745 41143 jeremytubongbanua 85.239.53.170 5245e3a6-c8f6-4f69-92be-74ef3285387d 
INFO|2023-08-03 20:01:09.388435| sshnp |Received 5245e3a6-c8f6-4f69-92be-74ef3285387d notification 
INFO|2023-08-03 20:01:09.388497| sshnp |Session 5245e3a6-c8f6-4f69-92be-74ef3285387d connected successfully 
INFO|2023-08-03 20:01:09.388591| sshnp |Tidying up files 
ssh -p 58745 jeremyvps@localhost -o StrictHostKeyChecking=accept-new -o IdentitiesOnly=yes -i /Users/jeremytubongbanua/.ssh/id_ed25519
jeremytubongbanua@Jeremys-M2-Air bin % ssh -p 58745 jeremyvps@localhost -o StrictHostKeyChecking=accept-new -o IdentitiesOnly=yes -i /Users/jeremytubongbanua/.ssh/id_ed25519
Warning: Permanently added '[localhost]:58745' (ED25519) to the list of known hosts.
Linux debian 4.19.0-21-cloud-amd64 #1 SMP Debian 4.19.249-2 (2022-06-30) x86_64

The programs included with the Debian GNU/Linux system are free software;
the exact distribution terms for each program are described in the
individual files in /usr/share/doc/*/copyright.

Debian GNU/Linux comes with ABSOLUTELY NO WARRANTY, to the extent
permitted by applicable law.
Last login: Thu Aug  3 23:53:08 2023 from 127.0.0.1
jeremyvps@debian:~$ logout
Connection to localhost closed.
jeremytubongbanua@Jeremys-M2-Air bin %

SSHNPD:

jeremyvps@debian:~/.local/bin$ ./sshnpd -a @server_0 -m @client_0 -d e2e -s -u -v --ssh-client=pure-dart
INFO|2023-08-04 00:00:57.728873|AtClientManager|setCurrentAtSign called with atSign @server_0 
INFO|2023-08-04 00:00:57.729037|AtClientManager|Switching atSigns from null to @server_0 
INFO|2023-08-04 00:00:57.730114|HiveBase|commit_log_055719601711c762ce6bc501676e84468ea43ee6a20f32649e09e7cf951c9526 initialized successfully 
INFO|2023-08-04 00:00:57.730994|HiveBase|055719601711c762ce6bc501676e84468ea43ee6a20f32649e09e7cf951c9526 initialized successfully 
INFO|2023-08-04 00:00:57.732774|AtClientCommitLogCompaction (@server_0)|Starting commit log compaction job running for every 11 minute(s) 
INFO|2023-08-04 00:00:57.733722|AtClientManager|setCurrentAtSign complete 
INFO|2023-08-04 00:00:57.733768|AtLookup|Creating new connection 
INFO|2023-08-04 00:00:58.196159|AtLookup|New connection created OK 
INFO|2023-08-04 00:00:58.310970|AtLookup|auth success 
INFO|2023-08-04 00:00:58.645065| sshnpd |Starting connectivity listener 
INFO|2023-08-04 00:00:58.645351| sshnpd |Subscribing to e2e\.sshnp@ 
INFO|2023-08-04 00:00:58.645396| sshnpd |Done 
WARNING|2023-08-04 00:00:58.647606| sshnpd |connection available 
INFO|2023-08-04 00:00:58.931012|Monitor (@server_0)|monitor started for @server_0 with last notification time: null 
INFO|2023-08-04 00:01:07.019815| sshnpd |Received: privatekey 
INFO|2023-08-04 00:01:07.019870| sshnpd |Private Key received from @client_0 notification id : cec47b31-3b59-445a-8afc-e6ca6d80dd0a 
INFO|2023-08-04 00:01:07.676175| sshnpd |Received: sshpublickey 
INFO|2023-08-04 00:01:07.676232| sshnpd |ssh Public Key received from @client_0 notification id : 700fd594-1753-4491-8482-c603aab51750 
INFO|2023-08-04 00:01:08.347895| sshnpd |Received: sshd 
INFO|2023-08-04 00:01:08.347947| sshnpd |ssh callback request received from @client_0 notification id : adba83d0-25c5-4ecd-800b-328a90c77e89 
INFO|2023-08-04 00:01:08.347993| sshnpd |Starting ssh session for jeremytubongbanua to 85.239.53.170 on port 41143 using localhost:58745 on 85.239.53.170  
SHOUT|2023-08-04 00:01:08.348011| sshnpd |Starting ssh session using pureDart (pure-dart) from: @client_0 session: 5245e3a6-c8f6-4f69-92be-74ef3285387d 
INFO|2023-08-04 00:01:09.314805| sshnpd | sshnpd connected notification sent to:from "@client_0:5245e3a6-c8f6-4f69-92be-74ef3285387d.e2e.sshnp@server_0 
INFO|2023-08-04 00:01:09.931175| sshnpd |SUCCESS:id: afbf2626-64ae-40a3-9442-b67448a7654b status: NotificationStatusEnum.delivered for: 5245e3a6-c8f6-4f69-92be-74ef3285387d with value: connected 
SHOUT|2023-08-04 00:01:24.315313| sshnpd |5245e3a6-c8f6-4f69-92be-74ef3285387d | ssh session complete
cconstab commented 1 year ago

I suspect the option we use is in a newer version of ssh. Try also upgrading the os and see if it persists.

sudo apt update sudo apt upgrade

JeremyTubongbanua commented 1 year ago

SSHNPD on Debian 12 Linux x64 works

SSHNPD

jeremyvps@localhost:~/.local/bin$ ./sshnpd -a @server_0 -m @client_0 -s -u -v -d e2e
INFO|2023-08-04 00:15:00.404931|AtClientManager|setCurrentAtSign called with atSign @server_0 
INFO|2023-08-04 00:15:00.405291|AtClientManager|Switching atSigns from null to @server_0 
INFO|2023-08-04 00:15:00.406059|HiveBase|commit_log_055719601711c762ce6bc501676e84468ea43ee6a20f32649e09e7cf951c9526 initialized successfully 
INFO|2023-08-04 00:15:00.407023|HiveBase|055719601711c762ce6bc501676e84468ea43ee6a20f32649e09e7cf951c9526 initialized successfully 
INFO|2023-08-04 00:15:00.408584|AtClientCommitLogCompaction (@server_0)|Starting commit log compaction job running for every 11 minute(s) 
INFO|2023-08-04 00:15:00.409928|AtClientManager|setCurrentAtSign complete 
INFO|2023-08-04 00:15:00.410057|AtLookup|Creating new connection 
INFO|2023-08-04 00:15:00.738197|AtLookup|New connection created OK 
INFO|2023-08-04 00:15:00.852924|AtLookup|auth success 
INFO|2023-08-04 00:15:01.152077| sshnpd |Starting connectivity listener 
INFO|2023-08-04 00:15:01.152547| sshnpd |Subscribing to e2e\.sshnp@ 
INFO|2023-08-04 00:15:01.152673| sshnpd |Done 
WARNING|2023-08-04 00:15:01.155494| sshnpd |connection available 
INFO|2023-08-04 00:15:01.410185|Monitor (@server_0)|monitor started for @server_0 with last notification time: null 
INFO|2023-08-04 00:15:23.310843| sshnpd |Received: privatekey 
INFO|2023-08-04 00:15:23.311079| sshnpd |Private Key received from @client_0 notification id : ad1400d7-e1e4-44b6-818f-855e036c710e 
INFO|2023-08-04 00:15:23.965582| sshnpd |Received: sshpublickey 
INFO|2023-08-04 00:15:23.965807| sshnpd |ssh Public Key received from @client_0 notification id : 7e60e0cf-b711-4155-b6fe-f66733bdb4c0 
INFO|2023-08-04 00:15:24.594506| sshnpd |Received: sshd 
INFO|2023-08-04 00:15:24.594567| sshnpd |ssh callback request received from @client_0 notification id : 7e33be6d-9340-43a7-bb78-07964007c982 
INFO|2023-08-04 00:15:24.594615| sshnpd |Starting ssh session for jeremytubongbanua to 85.239.53.170 on port 44289 using localhost:59097 on 85.239.53.170  
SHOUT|2023-08-04 00:15:24.594633| sshnpd |Starting ssh session using hostSsh (/usr/bin/ssh) from: @client_0 session: 4c23cf9b-5cf6-42fa-9daa-165676550823 
INFO|2023-08-04 00:15:24.597543| sshnpd |4c23cf9b-5cf6-42fa-9daa-165676550823 | Executing /usr/bin/ssh jeremytubongbanua@85.239.53.170 -p 44289 -i /tmp/.9bb96174-2ad4-4a29-b822-005ede3ceff5 -R 59097:localhost:22 -o LogLevel=VERBOSE -t -t -o StrictHostKeyChecking=accept-new -o IdentitiesOnly=yes -o BatchMode=yes -o ExitOnForwardFailure=yes -o ForkAfterAuthentication=yes sleep 15 
INFO|2023-08-04 00:15:25.136798| sshnpd |4c23cf9b-5cf6-42fa-9daa-165676550823 | sshStdErr | Warning: Permanently added '[85.239.53.170]:44289' (ED25519) to the list of known hosts.

INFO|2023-08-04 00:15:25.869579| sshnpd |4c23cf9b-5cf6-42fa-9daa-165676550823 | sshStdErr | Authenticated to 85.239.53.170 ([85.239.53.170]:44289) using "publickey".

INFO|2023-08-04 00:15:26.054092| sshnpd | sshnpd connected notification sent to:from "@client_0:4c23cf9b-5cf6-42fa-9daa-165676550823.e2e.sshnp@server_0 
INFO|2023-08-04 00:15:26.356215| sshnpd |4c23cf9b-5cf6-42fa-9daa-165676550823 | sshStdOut | ssh session complete

INFO|2023-08-04 00:15:26.729137| sshnpd |SUCCESS:id: a5217cdd-31a7-4a9c-84aa-d052bd48e170 status: NotificationStatusEnum.delivered for: 4c23cf9b-5cf6-42fa-9daa-165676550823 with value: connected
JeremyTubongbanua commented 1 year ago

I will try Debian 10 again without doing apt upgrade and apt update

JeremyTubongbanua commented 1 year ago

@cconstab tried doing sudo apt-get update && sudo apt-get upgrade and still getting the same error

Debian 10

SSHNPD

jeremyvps@debian:~/.local/bin$ sudo apt-get update && sudo apt-get upgrade
...

jeremyvps@debian:~/.local/bin$ ./sshnpd -a @server_0 -m @client_0 -d e2e -s -u -v
INFO|2023-08-04 00:25:49.259380|AtClientManager|setCurrentAtSign called with atSign @server_0 
INFO|2023-08-04 00:25:49.259525|AtClientManager|Switching atSigns from null to @server_0 
INFO|2023-08-04 00:25:49.260527|HiveBase|commit_log_055719601711c762ce6bc501676e84468ea43ee6a20f32649e09e7cf951c9526 initialized successfully 
INFO|2023-08-04 00:25:49.261319|HiveBase|055719601711c762ce6bc501676e84468ea43ee6a20f32649e09e7cf951c9526 initialized successfully 
INFO|2023-08-04 00:25:49.262239|AtClientCommitLogCompaction (@server_0)|Starting commit log compaction job running for every 11 minute(s) 
INFO|2023-08-04 00:25:49.263061|AtClientManager|setCurrentAtSign complete 
INFO|2023-08-04 00:25:49.263093|AtLookup|Creating new connection 
INFO|2023-08-04 00:25:49.741647|AtLookup|New connection created OK 
INFO|2023-08-04 00:25:49.856447|AtLookup|auth success 
INFO|2023-08-04 00:25:50.271444| sshnpd |Starting connectivity listener 
INFO|2023-08-04 00:25:50.271783| sshnpd |Subscribing to e2e\.sshnp@ 
INFO|2023-08-04 00:25:50.271838| sshnpd |Done 
WARNING|2023-08-04 00:25:50.274064| sshnpd |connection available 
INFO|2023-08-04 00:25:50.563484|Monitor (@server_0)|monitor started for @server_0 with last notification time: null 
INFO|2023-08-04 00:25:53.488257| sshnpd |Received: privatekey 
INFO|2023-08-04 00:25:53.488321| sshnpd |Private Key received from @client_0 notification id : 381e6a9f-eafb-42e4-b61a-a46927ffd422 
INFO|2023-08-04 00:25:54.262124| sshnpd |Received: sshpublickey 
INFO|2023-08-04 00:25:54.262193| sshnpd |ssh Public Key received from @client_0 notification id : 4439edf2-a975-491e-ba5c-b89a82c0a89e 
INFO|2023-08-04 00:25:54.898681| sshnpd |Received: sshd 
INFO|2023-08-04 00:25:54.898878| sshnpd |ssh callback request received from @client_0 notification id : ce0e876f-fff1-4019-a6d0-630343ffeb69 
INFO|2023-08-04 00:25:54.898977| sshnpd |Starting ssh session for jeremytubongbanua to 85.239.53.170 on port 33273 using localhost:59304 on 85.239.53.170  
SHOUT|2023-08-04 00:25:54.899050| sshnpd |Starting ssh session using hostSsh (/usr/bin/ssh) from: @client_0 session: 35cfd932-98b9-43f1-a942-a7396bc3ab08 
INFO|2023-08-04 00:25:54.902001| sshnpd |35cfd932-98b9-43f1-a942-a7396bc3ab08 | Executing /usr/bin/ssh jeremytubongbanua@85.239.53.170 -p 33273 -i /tmp/.3e1d14f2-0fff-4fef-b5bc-562ff96d7083 -R 59304:localhost:22 -o LogLevel=VERBOSE -t -t -o StrictHostKeyChecking=accept-new -o IdentitiesOnly=yes -o BatchMode=yes -o ExitOnForwardFailure=yes -o ForkAfterAuthentication=yes sleep 15 
INFO|2023-08-04 00:25:54.905800| sshnpd |35cfd932-98b9-43f1-a942-a7396bc3ab08 | sshStdErr | command-line: line 0: Bad configuration option: forkafterauthentication

SHOUT|2023-08-04 00:25:54.906259| sshnpd |35cfd932-98b9-43f1-a942-a7396bc3ab08 | Exit code 255 from /usr/bin/ssh jeremytubongbanua@85.239.53.170 -p 33273 -i /tmp/.3e1d14f2-0fff-4fef-b5bc-562ff96d7083 -R 59304:localhost:22 -o LogLevel=VERBOSE -t -t -o StrictHostKeyChecking=accept-new -o IdentitiesOnly=yes -o BatchMode=yes -o ExitOnForwardFailure=yes -o ForkAfterAuthentication=yes sleep 15 
WARNING|2023-08-04 00:25:54.906299| sshnpd |Failed to establish connection - exit code 255 
INFO|2023-08-04 00:25:55.579558| sshnpd |SUCCESS:id: 058af9bf-4b0d-4197-b3ef-03c219142a2e status: NotificationStatusEnum.delivered for: 35cfd932-98b9-43f1-a942-a7396bc3ab08 with value: Failed to establish connection - exit code 255 (use --local-port to specify unused port)

SSHNP

jeremytubongbanua@Jeremys-M2-Air bin % ./sshnp -f @client_0 -t @server_0 -s id_ed25519.pub -h @rv_am -v -d e2e
INFO|2023-08-03 20:25:51.117096|AtClientManager|setCurrentAtSign called with atSign @client_0 
INFO|2023-08-03 20:25:51.117150|AtClientManager|Switching atSigns from null to @client_0 
INFO|2023-08-03 20:25:51.118105|HiveBase|commit_log_d75a51c1003c996d4592b57407ea6b3f21a2e1163891d3612cb54a41aa363a01 initialized successfully 
INFO|2023-08-03 20:25:51.119140|HiveBase|d75a51c1003c996d4592b57407ea6b3f21a2e1163891d3612cb54a41aa363a01 initialized successfully 
INFO|2023-08-03 20:25:51.119171|AtClientCommitLogCompaction (@client_0)|Starting commit log compaction job running for every 11 minute(s) 
INFO|2023-08-03 20:25:51.119777|AtClientManager|setCurrentAtSign complete 
INFO|2023-08-03 20:25:51.119790|AtLookup|Creating new connection 
INFO|2023-08-03 20:25:51.469885|AtLookup|New connection created OK 
INFO|2023-08-03 20:25:51.608707|AtLookup|auth success 
INFO|2023-08-03 20:25:51.676059| sshnp |Subscribing to notifications on 35cfd932-98b9-43f1-a942-a7396bc3ab08.e2e.sshnp@ 
INFO|2023-08-03 20:25:52.028396|AbstractAtKeyEncryption (@client_0)|Encrypted shared symmetric key for @client_0 not found in local storage 
INFO|2023-08-03 20:25:52.028565|AbstractAtKeyEncryption (@client_0)|Deleting @rv_am:shared_key@client_0 from LocalSecondary 
INFO|2023-08-03 20:25:52.028877|AbstractAtKeyEncryption (@client_0)|Fetching shared symmetric key for @client_0 from atServer 
INFO|2023-08-03 20:25:52.032794|Monitor (@client_0)|monitor started for @client_0 with last notification time: null 
INFO|2023-08-03 20:25:52.087535|AbstractAtKeyEncryption (@client_0)|Retrieved my encrypted copy of shared symmetric key for @rv_am from atServer - saving to local storage 
INFO|2023-08-03 20:25:52.096125|AbstractAtKeyEncryption (@client_0)|'Their' copy of shared symmetric key for @rv_am not found in local storage - will check atServer 
INFO|2023-08-03 20:25:52.167652|AbstractAtKeyEncryption (@client_0)|Found 'their' copy of shared symmetric key for @rv_am in atServer - saving to local storage 
INFO|2023-08-03 20:25:52.851344| sshnp |SUCCESS:id: 7c73cb09-b5f8-43ea-98f2-a21f34f8b859 status: NotificationStatusEnum.delivered @rv_am:e2e.sshrvd@client_0 
INFO|2023-08-03 20:25:53.029865|AbstractAtKeyEncryption (@client_0)|Encrypted shared symmetric key for @client_0 not found in local storage 
INFO|2023-08-03 20:25:53.029984|AbstractAtKeyEncryption (@client_0)|Deleting @server_0:shared_key@client_0 from LocalSecondary 
INFO|2023-08-03 20:25:53.030244|AbstractAtKeyEncryption (@client_0)|Fetching shared symmetric key for @client_0 from atServer 
INFO|2023-08-03 20:25:53.099977|AbstractAtKeyEncryption (@client_0)|Retrieved my encrypted copy of shared symmetric key for @server_0 from atServer - saving to local storage 
INFO|2023-08-03 20:25:53.108795|AbstractAtKeyEncryption (@client_0)|'Their' copy of shared symmetric key for @server_0 not found in local storage - will check atServer 
INFO|2023-08-03 20:25:53.168048|AbstractAtKeyEncryption (@client_0)|Found 'their' copy of shared symmetric key for @server_0 in atServer - saving to local storage 
INFO|2023-08-03 20:25:53.899316| sshnp |SUCCESS:id: 381e6a9f-eafb-42e4-b61a-a46927ffd422 status: NotificationStatusEnum.delivered 
INFO|2023-08-03 20:25:54.600380| sshnp |SUCCESS:id: 4439edf2-a975-491e-ba5c-b89a82c0a89e status: NotificationStatusEnum.delivered 
INFO|2023-08-03 20:25:55.066179| sshnp |Received 35cfd932-98b9-43f1-a942-a7396bc3ab08 notification 
Remote sshnpd error: Failed to establish connection - exit code 255 (use --local-port to specify unused port)
INFO|2023-08-03 20:25:55.200615| sshnp |Received 35cfd932-98b9-43f1-a942-a7396bc3ab08 notification 
Remote sshnpd error: Failed to establish connection - exit code 255 (use --local-port to specify unused port)
INFO|2023-08-03 20:25:55.303854| sshnp |SUCCESS:id: ce0e876f-fff1-4019-a6d0-630343ffeb69 status: NotificationStatusEnum.delivered 59304 33273 jeremytubongbanua 85.239.53.170 35cfd932-98b9-43f1-a942-a7396bc3ab08 
INFO|2023-08-03 20:25:55.303957| sshnp |Tidying up files
JeremyTubongbanua commented 1 year ago

@cconstab --ssh-client=pure-dart fixes it still in Debian 10..

The two fixes right now:

  1. Use Debian 10 but --ssh-client=pure-dart
  2. Use Debian 12
cconstab commented 1 year ago

I suspect the option we use is in a newer version of ssh. Try also upgrading the os and see if it persists.

sudo apt update sudo apt upgrade

cconstab commented 1 year ago

Thanks so much for the research!

cpswan commented 1 year ago

Debian 10 is still maintained, and we will no doubt encounter customer situations that try to use older distros that are officially out of maintenance.

What version of OpenSSH do you get from the package manager?

gkc commented 1 year ago

Meanwhile, I'll add a startup check to verify that the available ssh command on the host supports what we need and, if not, prints a helpful error message explaining and instructing to use the pure-dart flag

cpswan commented 1 year ago

@gkc if we detect that the native SSH is insufficient then we should just fail over directly to pure-dart (with an appropriate log message to say so). We could even say run with --ssh-client=pure-dart to supress this message or whatever.

I hate error messages that scold me on how to make the right incantations. JFDI for me!

gkc commented 1 year ago

@cpswan 👍

gkc commented 1 year ago

Looking through the openssh release notes, the ssh client's ForkAfterAuthentication flag was added in openssh version 8.7 released on 2021-08-20

The version of openssh supported on debian 10 is, I think, version 7.9, released on 2018-10-19 and as best I can tell, of the flags that sshnpd currently uses, only the ForkAfterAuthentication flag was added after that version

@JeremyTubongbanua can you confirm the version please by running ssh -V on your Debian 10 host?

However, looking more into command-line flags, looks like the capability of forking after authentication was also in version 7.9 by using the -f flag - indeed, reading man 5 ssh_config, setting ForkAfterAuthentication=yes has the same behaviour as using the -f flag. So if we use -f then we can support Debian 10 also

So I think there are three things to do

  1. Replace -o ForkAfterAuthentication=yes with -f in the args that sshnpd passes when it spawns the ssh, and verify this works on Debian 10
  2. Check the actual minimum version we require. I believe it is version 7.6, released 2017-10-03, which is when the accept-new setting was made available for the StrictHostKeyChecking option
  3. Have sshnpd, when running in --ssh-client=/usr/bin/ssh mode (which will remain the default), check the available version, and fall back to using pure-dart mode if /usr/bin/ssh is unavailable, or is not openssh at or above version 7.6

@cpswan make sense to you?

cpswan commented 1 year ago

@gkc all makes sense to me.

Some other thoughts...

JeremyTubongbanua commented 1 year ago

After I ssh'd into a fresh installation of Debian 10

root@debian:~# apt list openssh
Listing... Done

@cpswan

apt-get update && apt-get install -y sudo sudo wget curl openssh-server nano vim iproute2 nmap tmux
root@debian:~# apt list openssh-server
Listing... Done
openssh-server/oldoldstable,now 1:7.9p1-10+deb10u2 amd64 [installed]
N: There is 1 additional version. Please use the '-a' switch to see it

root@debian:~# apt list -a openssh-server
Listing... Done
openssh-server/buster-backports 1:8.4p1-2~bpo10+1 amd64
openssh-server/oldoldstable,now 1:7.9p1-10+deb10u2 amd64 [installed]
openssh-server/oldoldstable 1:7.9p1-10+deb10u1 amd64

@gkc 

root@debian:~# ssh -V
OpenSSH_7.9p1 Debian-10+deb10u2, OpenSSL 1.1.1n  15 Mar 2022
gkc commented 1 year ago

@JeremyTubongbanua could you pick this up this sprint?

gkc commented 1 year ago

I will note that this is not P0 because this only occurs where we have the need to run a double ssh (i.e. the daemon starts an ssh to the client host) and within a week or so we will support direct ssh as the default option when using an rvd. Perhaps it's not even a P1? @cpswan wdyt?

JeremyTubongbanua commented 1 year ago

Check version of usr/bin/ssh check with ssh -V

XavierChanth commented 1 year ago

We can revisit this ticket after the 4.0.0 launch

XavierChanth commented 10 months ago

Your choice of ssh server should be entirely your own. So if we want to support different clients, they should have to specify via an ssh-client flag, similar to how sshnp does it. I don't think this is urgent, moving to P3