Issue - n8n Docker container crash - SSH to Windows machine

ansred · August 9, 2022, 11:11pm

Describe the issue/error/question

When I use SSH (SSH Server installed on Windows 10 Pro), the entire n8n docker container crashes

When I ssh from anywhere else MacOS, Windows, Linux, everything works fine, it’s just the n8n SSH node crashes when trying to connect to SSH Windows (SSH Linux works fine)

SSH Server on Windows

What is the error message (if any)?

The moment I run the SSH node (I have SSH Server installed on a Windows 10 Pro machine), n8n docker container crashes

Logs from the n8n docker container

today at 7:03:19 PMnode:events:505
today at 7:03:19 PM      throw er; // Unhandled 'error' event
today at 7:03:19 PM      ^
today at 7:03:19 PM
today at 7:03:19 PMError: read ECONNRESET
today at 7:03:19 PM    at TCP.onStreamRead (node:internal/stream_base_commons:217:20)
today at 7:03:19 PMEmitted 'error' event on Client instance at:
today at 7:03:19 PM    at Socket.<anonymous> (/usr/local/lib/node_modules/n8n/node_modules/ssh2/lib/client.js:745:12)
today at 7:03:19 PM    at Socket.emit (node:events:527:28)
today at 7:03:19 PM    at Socket.emit (node:domain:475:12)
today at 7:03:19 PM    at emitErrorNT (node:internal/streams/destroy:157:8)
today at 7:03:19 PM    at emitErrorCloseNT (node:internal/streams/destroy:122:3)
today at 7:03:19 PM    at processTicksAndRejections (node:internal/process/task_queues:83:21) {
today at 7:03:19 PM  errno: -104,
today at 7:03:19 PM  code: 'ECONNRESET',
today at 7:03:23 PMContainer started
today at 7:03:19 PM  code: 'ECONNRESET',
today at 7:03:19 PM  syscall: 'read',
today at 7:03:19 PM  level: 'client-socket'
today at 7:03:19 PM}
today at 7:03:26 PMInitializing n8n process
today at 7:03:31 PMn8n ready on 0.0.0.0, port 5678
today at 7:03:31 PMVersion: 0.189.1

Please share the workflow

Share the output returned by the last node

no output, as the entire n8n docker container crashes

Information on your n8n setup

n8n version: 0.189.1
Database you’re using (default: SQLite): yes default
Running n8n with the execution process [own(default), main]:
Running n8n via [Docker, npm, n8n.cloud, desktop app]: Docker on Synology NAS DSM Intel

MutedJam · August 10, 2022, 8:15am

Hi @ansred, I am sorry you’re having trouble.

The ECONNRESET error you are seeing indicates a network problem which is usually outside of n8n’s control, see Errors | Node.js v16.16.0 Documentation (nodejs.org):

(Connection reset by peer): A connection was forcibly closed by a peer. This normally results from a loss of the connection on the remote socket due to a timeout or reboot. Commonly encountered via the http and net modules.

So this might be a problem with the firewall configuration on your ssh destination. Also, from looking at the article you have shared it seems the Windows OpenSSH Server requires a domain membership (seeing there are no instructions on how to connect to a Windows machine on a Workgroup). So this might be another thing you want to check here.

ansred · August 10, 2022, 1:16pm

Hi @MutedJam ,

Thanks for the response.

I can confirm that the Firewall is allowed on the destination Windows machine and I have a dedicated Inbound rule to allow SSH 22 traffic.

The destination machine is not a domain joined, and I can SSH to it the Windows SSH server from other machines without issues and without using any domains.

Example from the Synology NAS, where I have n8n installed as docker container.

anas@ds1520:~$ ssh [email protected]
[email protected]'s password:

Connection established without issue as below to the Windows 10 as destination SSH Server and showing me the PowerShell

Windows PowerShell
Copyright (C) Microsoft Corporation. All rights reserved.

Try the new cross-platform PowerShell https://aka.ms/pscore6

PS C:\Users\n8n> ls


    Directory: C:\Users\n8n


Mode                 LastWriteTime         Length Name
----                 -------------         ------ ----
d-r---         9/29/2017   9:46 AM                Desktop
d-r---          8/9/2022   7:01 PM                Documents
d-r---         9/29/2017   9:46 AM                Downloads
d-r---         9/29/2017   9:46 AM                Favorites
d-r---         9/29/2017   9:46 AM                Links
d-r---         9/29/2017   9:46 AM                Music
d-r---         6/10/2022  10:28 PM                OneDrive
d-r---         9/29/2017   9:46 AM                Pictures
d-----         9/29/2017   9:46 AM                Saved Games
d-----          8/9/2022  10:50 PM                Test-SFTP-Folder
d-----         8/10/2022  12:58 AM                Test-SFTP-Folder-2
d-r---         9/29/2017   9:46 AM                Videos

Any other ideas on how to get that to work by any chance?

Thanks

MutedJam · August 10, 2022, 1:57pm

Thanks for confirming!

I set up the OpenSSH server on my Windows machine, started the service and am not running into the network issue you have described.

It’s still not working as it should for me though as I am having trouble specifying a suitable working directory though:

I’ll see if I can get this to work and will report back.

MutedJam · August 10, 2022, 2:18pm

Okay, got it working by forcing a working directory of null like so:

This works as expected against a Windows host:

So as suspected initially, this would appear to be caused by the specific network you are operating in, perhaps something specific to the Synology NAS (I don’t have such a device available, so won’t be able to test this myself unfortunately).

Perhaps you can narrow down the cause by running n8n outside of your Synology NAS (using something like docker run -it --rm -p 5678:5678 --name n8n n8nio/n8n:0.190.0 should fire up a temporary docker container allowing you to test this).

ansred · August 10, 2022, 3:24pm

@MutedJam Good ideas.

Let me install a second docker instance on Raspberry Pi 4 and a third docker instance on another Synology NAS and test it out …

Update:
It crashes the docker container on the Pi as well.

today at 12:14:26 PMnode:events:505
today at 12:14:26 PM      throw er; // Unhandled 'error' event
today at 12:14:26 PM      ^
today at 12:14:26 PM
today at 12:14:26 PMError: read ECONNRESET
today at 12:14:26 PM    at TCP.onStreamRead (node:internal/stream_base_commons:217:20)
today at 12:14:26 PMEmitted 'error' event on Client instance at:
today at 12:14:26 PM    at Socket.<anonymous> (/usr/local/lib/node_modules/n8n/node_modules/ssh2/lib/client.js:745:12)
today at 12:14:26 PM    at Socket.emit (node:events:527:28)
today at 12:14:26 PM    at Socket.emit (node:domain:475:12)
today at 12:14:26 PM    at emitErrorNT (node:internal/streams/destroy:157:8)
today at 12:14:26 PM    at emitErrorCloseNT (node:internal/streams/destroy:122:3)
today at 12:14:26 PM    at processTicksAndRejections (node:internal/process/task_queues:83:21) {
today at 12:14:26 PM  errno: -104,
today at 12:14:26 PM  code: 'ECONNRESET',
today at 12:14:26 PM  syscall: 'read',
today at 12:14:26 PM  level: 'client-socket'
today at 12:14:26 PM}
today at 12:14:26 PMContainer stopped
today at 12:14:29 PMContainer started
today at 12:14:26 PM}
today at 12:14:36 PMInitializing n8n process
today at 12:14:46 PMn8n ready on 0.0.0.0, port 5678
today at 12:14:46 PMVersion: 0.190.0
today at 12:14:46 PM
today at 12:14:46 PMEditor is now accessible via:
today at 12:14:46 PMhttp://localhost:5678/
today at 12:14:26 PM}
today at 12:14:36 PMInitializing n8n process
today at 12:14:46 PMn8n ready on 0.0.0.0, port 5678
today at 12:14:46 PMVersion: 0.190.0
today at 12:14:46 PM
today at 12:14:46 PMEditor is now accessible via:
today at 12:14:46 PMhttp://localhost:5678/

Quick question, are you able enter a command for example to run script.ps1 that is sitting on the Windows host?

Thanks for testing out btw!

ansred · August 12, 2022, 3:06pm

Update:

I was able to do a workaround since the direct SSH to Windows machine from n8n breaks the entire n8n itself.

So, I am using a jump box linux machine with the following command to ssh to the windows machine and then gets the output

sshpass -p 'TypeYourPassword' ssh [email protected] "cd C:\Users\n8n\PROJECTS\PowerShell\test-random-ps1-commands ; .\random-ps-commands.ps1""

Still I think that there is something not right in n8n and it should be handling better errors instead of crashing the entire n8n docker container.

Jon · August 12, 2022, 7:45pm

Hey @ansred,

What version of OpenSSH is it and is there any extra configuration happening to it for hardening or on the base OS itself?

The connection error isn’t great and in theory should be handled already so something is causing the library under it to crash out. My gut feel is it is failing during the handshake possible something with KEX, any chance you could enable debug logging in the openssh server config file and fire it over?

ansred · August 13, 2022, 10:23pm

Hi @Jon

Installed OpenSSH from the Optional Features with the latest available for Windows 10 Pro.

Using Basic Authentication, no custom settings.

Is there anything specific you need to check by any chance steps?

Thanks

ansred · September 6, 2022, 6:41pm

Any ideas on this?

Thanks!

Jon · September 6, 2022, 7:13pm

Hey @ansred,

Looking at it the only other thing that would be useful is logs from the openssh server so we can see what the server is doing the handshake. I am still fairly sure this is going to be a KEX issue though and may be something that can be sorted in the openssh config.

Having said that though it is working for Tom when he tested so it could be environmental and something specific to your environment.

Have you tried connecting to the ssh server from a container directly?

ansred · September 6, 2022, 10:06pm

Hey @Jon

I can confirm that I can SSH to the Windows server from a fresh installed Ubuntu docker container with SSH installed on it directly without issues.

I used both SSH + SSHPASS and both worked fine.

Screenshots:

Screen Shot 2022-09-06 at 6.04.15 PM

Is there is something else I should consider in the n8n docker container to have it working like the Ubuntu I just tested with?

Jon · September 7, 2022, 8:22am

Hey @ansred,

There shouldn’t be, As a test from n8n can you try adding an execute command node and using…

nc -zv 10.0.12.88 22

This will give an idea if the container can connect to the server, If it is able to connect it will be something like this in the response.

[
  {
    "exitCode": 0,
    "stderr": "10.0.12.88 (10.0.12.88:22) open",
    "stdout": ""
  }
]

If it can connect then we will need you to check the ssh server logs so we can see what the handshake is doing. As we can’t reproduce it and the node doesn’t have a debug option the only info we will be able to get is from the server.

ansred · September 7, 2022, 6:09pm

Hi @Jon

It worked the node as you asked

[

{

"exitCode": 0,

"stderr": "10.0.12.88 (10.0.12.88:22) open",

"stdout": ""

}

]

Jon · September 7, 2022, 7:57pm

Perfect that rules out a lot of the normal network issues, it looks like we will need to that handshake from the ssh server logs to try and work out what we need to configure to reproduce then fix the issue.

ansred · September 7, 2022, 8:40pm

@Jon good troubleshooting steps.

One thing, per MSFT KB # OpenSSH Server configuration for Windows | Microsoft Docs

logs should exists in # C:\ProgramData\ssh\logs

However, it’s completely empty, does it show any logs on your side?

I checked two windows machines, both are the same

UPDATE:
I had to change the sshd_config to enable logging

# Logging
SyslogFacility LOCAL0
LogLevel VERBOSE

here are the logs when connecting directly via SSH node from n8n to the Windows SSH Server

13968 2022-09-07 18:27:57.819 Connection from 10.0.12.201 port 55096 on 10.0.12.88 port 22
13968 2022-09-07 18:27:57.961 Accepted password for n8n from 10.0.12.201 port 55096 ssh2
13968 2022-09-07 18:27:58.018 User child is on pid 26512
26512 2022-09-07 18:27:58.108 Starting session: command for n8n from 10.0.12.201 port 55096 id 0
26512 2022-09-07 18:27:58.848 Close session: user n8n from 10.0.12.201 port 55096 id 0
26512 2022-09-07 18:27:58.850 Received disconnect from 10.0.12.201 port 55096:11: 
26512 2022-09-07 18:27:58.850 Disconnected from 10.0.12.201 port 55096

here is the most available logging level debug3

17028 2022-09-07 18:36:24.220 debug2: fd 3 setting O_NONBLOCK
17028 2022-09-07 18:36:24.221 debug3: sock_set_v6only: set socket 3 IPV6_V6ONLY
17028 2022-09-07 18:36:24.221 debug1: Bind to port 22 on ::.
17028 2022-09-07 18:36:24.221 Server listening on :: port 22.
17028 2022-09-07 18:36:24.221 debug2: fd 4 setting O_NONBLOCK
17028 2022-09-07 18:36:24.221 debug1: Bind to port 22 on 0.0.0.0.
17028 2022-09-07 18:36:24.222 Server listening on 0.0.0.0 port 22.
17028 2022-09-07 18:37:09.046 debug3: fd 5 is not O_NONBLOCK
17028 2022-09-07 18:37:09.052 debug3: spawning "C:\\WINDOWS\\System32\\OpenSSH\\sshd.exe" -R
17028 2022-09-07 18:37:09.059 debug3: send_rexec_state: entering fd = 8 config len 315
17028 2022-09-07 18:37:09.060 debug3: ssh_msg_send: type 0
17028 2022-09-07 18:37:09.060 debug3: send_rexec_state: done
25044 2022-09-07 18:37:09.132 debug1: inetd sockets after dupping: 4, 4
25044 2022-09-07 18:37:09.132 Connection from 10.0.12.201 port 35384 on 10.0.12.88 port 22
25044 2022-09-07 18:37:09.132 debug1: Local version string SSH-2.0-OpenSSH_for_Windows_8.1
25044 2022-09-07 18:37:09.132 error: kex_exchange_identification: Connection closed by remote host
17028 2022-09-07 18:37:34.824 debug3: fd 5 is not O_NONBLOCK
17028 2022-09-07 18:37:34.824 debug3: spawning "C:\\WINDOWS\\System32\\OpenSSH\\sshd.exe" -R
17028 2022-09-07 18:37:34.832 debug3: send_rexec_state: entering fd = 8 config len 315
17028 2022-09-07 18:37:34.832 debug3: ssh_msg_send: type 0
17028 2022-09-07 18:37:34.832 debug3: send_rexec_state: done
18848 2022-09-07 18:37:34.902 debug1: inetd sockets after dupping: 4, 4
18848 2022-09-07 18:37:34.902 Connection from 10.0.12.201 port 57182 on 10.0.12.88 port 22
18848 2022-09-07 18:37:34.902 debug1: Local version string SSH-2.0-OpenSSH_for_Windows_8.1
18848 2022-09-07 18:37:34.902 debug1: Remote protocol version 2.0, remote software version ssh2js1.11.0
18848 2022-09-07 18:37:34.902 debug1: no match: ssh2js1.11.0
18848 2022-09-07 18:37:34.902 debug2: fd 4 setting O_NONBLOCK
18848 2022-09-07 18:37:34.913 debug3: spawning "C:\\WINDOWS\\System32\\OpenSSH\\sshd.exe" -y
18848 2022-09-07 18:37:34.920 debug2: Network child is on pid 18512
18848 2022-09-07 18:37:34.920 debug3: send_rexec_state: entering fd = 6 config len 315
18848 2022-09-07 18:37:34.920 debug3: ssh_msg_send: type 0
18848 2022-09-07 18:37:34.920 debug3: send_rexec_state: done
18848 2022-09-07 18:37:34.920 debug3: ssh_msg_send: type 0
18848 2022-09-07 18:37:34.920 debug3: ssh_msg_send: type 0
18848 2022-09-07 18:37:34.920 debug3: preauth child monitor started
18848 2022-09-07 18:37:34.973 debug1: list_hostkey_types: rsa-sha2-512,rsa-sha2-256,ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
18848 2022-09-07 18:37:34.973 debug3: send packet: type 20 [preauth]
18848 2022-09-07 18:37:34.973 debug1: SSH2_MSG_KEXINIT sent [preauth]
18848 2022-09-07 18:37:34.973 debug3: receive packet: type 20 [preauth]
18848 2022-09-07 18:37:34.973 debug1: SSH2_MSG_KEXINIT received [preauth]
18848 2022-09-07 18:37:34.973 debug2: local server KEXINIT proposal [preauth]
18848 2022-09-07 18:37:34.973 debug2: KEX algorithms: curve25519-sha256,[email protected],ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1 [preauth]
18848 2022-09-07 18:37:34.973 debug2: host key algorithms: rsa-sha2-512,rsa-sha2-256,ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
18848 2022-09-07 18:37:34.974 debug2: ciphers ctos: [email protected],aes128-ctr,aes192-ctr,aes256-ctr,[email protected],[email protected] [preauth]
18848 2022-09-07 18:37:34.974 debug2: ciphers stoc: [email protected],aes128-ctr,aes192-ctr,aes256-ctr,[email protected],[email protected] [preauth]
18848 2022-09-07 18:37:34.974 debug2: MACs ctos: [email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
18848 2022-09-07 18:37:34.974 debug2: MACs stoc: [email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
18848 2022-09-07 18:37:34.974 debug2: compression ctos: none,[email protected] [preauth]
18848 2022-09-07 18:37:34.974 debug2: compression stoc: none,[email protected] [preauth]
18848 2022-09-07 18:37:34.974 debug2: languages ctos:  [preauth]
18848 2022-09-07 18:37:34.974 debug2: languages stoc:  [preauth]
18848 2022-09-07 18:37:34.974 debug2: first_kex_follows 0  [preauth]
18848 2022-09-07 18:37:34.974 debug2: reserved 0  [preauth]
18848 2022-09-07 18:37:34.974 debug2: peer client KEXINIT proposal [preauth]
18848 2022-09-07 18:37:34.974 debug2: KEX algorithms: [email protected],curve25519-sha256,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group14-sha256,diffie-hellman-group15-sha512,diffie-hellman-group16-sha512,diffie-hellman-group17-sha512,diffie-hellman-group18-sha512 [preauth]
18848 2022-09-07 18:37:34.974 debug2: host key algorithms: ssh-ed25519,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,rsa-sha2-512,rsa-sha2-256,ssh-rsa [preauth]
18848 2022-09-07 18:37:34.974 debug2: ciphers ctos: [email protected],[email protected],aes128-ctr,aes192-ctr,aes256-ctr,[email protected] [preauth]
18848 2022-09-07 18:37:34.974 debug2: ciphers stoc: [email protected],[email protected],aes128-ctr,aes192-ctr,aes256-ctr,[email protected] [preauth]
18848 2022-09-07 18:37:34.975 debug2: MACs ctos: [email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
18848 2022-09-07 18:37:34.975 debug2: MACs stoc: [email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
18848 2022-09-07 18:37:34.975 debug2: compression ctos: none,[email protected],zlib [preauth]
18848 2022-09-07 18:37:34.975 debug2: compression stoc: none,[email protected],zlib [preauth]
18848 2022-09-07 18:37:34.975 debug2: languages ctos:  [preauth]
18848 2022-09-07 18:37:34.975 debug2: languages stoc:  [preauth]
18848 2022-09-07 18:37:34.975 debug2: first_kex_follows 0  [preauth]
18848 2022-09-07 18:37:34.975 debug2: reserved 0  [preauth]
18848 2022-09-07 18:37:34.975 debug1: kex: algorithm: [email protected] [preauth]
18848 2022-09-07 18:37:34.975 debug1: kex: host key algorithm: ssh-ed25519 [preauth]
18848 2022-09-07 18:37:34.975 debug1: kex: client->server cipher: [email protected] MAC: <implicit> compression: none [preauth]
18848 2022-09-07 18:37:34.975 debug1: kex: server->client cipher: [email protected] MAC: <implicit> compression: none [preauth]
18848 2022-09-07 18:37:34.975 debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]
18848 2022-09-07 18:37:34.979 debug3: receive packet: type 30 [preauth]
18848 2022-09-07 18:37:34.996 debug3: mm_sshkey_sign entering [preauth]
18848 2022-09-07 18:37:34.996 debug3: mm_request_send entering: type 6 [preauth]
18848 2022-09-07 18:37:34.996 debug3: mm_sshkey_sign: waiting for MONITOR_ANS_SIGN [preauth]
18848 2022-09-07 18:37:34.996 debug3: mm_request_receive_expect entering: type 7 [preauth]
18848 2022-09-07 18:37:34.997 debug3: mm_request_receive entering [preauth]
18848 2022-09-07 18:37:34.997 debug3: mm_request_receive entering
18848 2022-09-07 18:37:34.997 debug3: monitor_read: checking request 6
18848 2022-09-07 18:37:34.997 debug3: mm_answer_sign
18848 2022-09-07 18:37:35.000 debug3: mm_answer_sign: KEX signature 0000021A8C779460(83)
18848 2022-09-07 18:37:35.000 debug3: mm_request_send entering: type 7
18848 2022-09-07 18:37:35.000 debug2: monitor_read: 6 used once, disabling now
18848 2022-09-07 18:37:35.000 debug3: send packet: type 31 [preauth]
18848 2022-09-07 18:37:35.000 debug3: send packet: type 21 [preauth]
18848 2022-09-07 18:37:35.000 debug2: set_newkeys: mode 1 [preauth]
18848 2022-09-07 18:37:35.001 debug1: rekey out after 4294967296 blocks [preauth]
18848 2022-09-07 18:37:35.001 debug1: SSH2_MSG_NEWKEYS sent [preauth]
18848 2022-09-07 18:37:35.001 debug1: expecting SSH2_MSG_NEWKEYS [preauth]
18848 2022-09-07 18:37:35.002 debug3: receive packet: type 21 [preauth]
18848 2022-09-07 18:37:35.002 debug1: SSH2_MSG_NEWKEYS received [preauth]
18848 2022-09-07 18:37:35.002 debug2: set_newkeys: mode 0 [preauth]
18848 2022-09-07 18:37:35.003 debug1: rekey in after 4294967296 blocks [preauth]
18848 2022-09-07 18:37:35.003 debug1: KEX done [preauth]
18848 2022-09-07 18:37:35.012 debug3: receive packet: type 5 [preauth]
18848 2022-09-07 18:37:35.012 debug3: send packet: type 6 [preauth]
18848 2022-09-07 18:37:35.015 debug3: receive packet: type 50 [preauth]
18848 2022-09-07 18:37:35.015 debug1: userauth-request for user n8n service ssh-connection method none [preauth]
18848 2022-09-07 18:37:35.015 debug1: attempt 0 failures 0 [preauth]
18848 2022-09-07 18:37:35.015 debug3: mm_getpwnamallow entering [preauth]
18848 2022-09-07 18:37:35.015 debug3: mm_request_send entering: type 8 [preauth]
18848 2022-09-07 18:37:35.015 debug3: mm_getpwnamallow: waiting for MONITOR_ANS_PWNAM [preauth]
18848 2022-09-07 18:37:35.015 debug3: mm_request_receive_expect entering: type 9 [preauth]
18848 2022-09-07 18:37:35.015 debug3: mm_request_receive entering [preauth]
18848 2022-09-07 18:37:35.015 debug3: mm_request_receive entering
18848 2022-09-07 18:37:35.015 debug3: monitor_read: checking request 8
18848 2022-09-07 18:37:35.015 debug3: mm_answer_pwnamallow
18848 2022-09-07 18:37:35.017 debug2: parse_server_config: config reprocess config len 315
18848 2022-09-07 18:37:35.017 debug3: checking match for 'Group administrators' user n8n host 10.0.12.201 addr 10.0.12.201 laddr 10.0.12.88 lport 22
18848 2022-09-07 18:37:35.021 debug3: LsaLogonUser Succeeded (Impersonation: 0)
18848 2022-09-07 18:37:35.023 debug1: user n8n matched group list administrators at line 87
18848 2022-09-07 18:37:35.023 debug3: match found
18848 2022-09-07 18:37:35.023 debug3: reprocess config:88 setting AuthorizedKeysFile __PROGRAMDATA__/ssh/administrators_authorized_keys
18848 2022-09-07 18:37:35.025 debug3: mm_answer_pwnamallow: sending MONITOR_ANS_PWNAM: 1
18848 2022-09-07 18:37:35.025 debug3: mm_request_send entering: type 9
18848 2022-09-07 18:37:35.025 debug2: monitor_read: 8 used once, disabling now
18848 2022-09-07 18:37:35.026 debug2: input_userauth_request: setting up authctxt for n8n [preauth]
18848 2022-09-07 18:37:35.026 debug3: mm_inform_authserv entering [preauth]
18848 2022-09-07 18:37:35.026 debug3: mm_request_send entering: type 4 [preauth]
18848 2022-09-07 18:37:35.026 debug2: input_userauth_request: try method none [preauth]
18848 2022-09-07 18:37:35.026 debug3: mm_request_receive entering
18848 2022-09-07 18:37:35.026 debug3: monitor_read: checking request 4
18848 2022-09-07 18:37:35.026 debug3: mm_answer_authserv: service=ssh-connection, style=
18848 2022-09-07 18:37:35.026 debug2: monitor_read: 4 used once, disabling now
18848 2022-09-07 18:37:35.028 debug3: user_specific_delay: user specific delay 0.000ms [preauth]
18848 2022-09-07 18:37:35.028 debug3: ensure_minimum_time_since: elapsed 11.981ms, delaying 11.554ms (requested 5.884ms) [preauth]
18848 2022-09-07 18:37:35.047 debug3: userauth_finish: failure partial=0 next methods="publickey,password,keyboard-interactive" [preauth]
18848 2022-09-07 18:37:35.047 debug3: send packet: type 51 [preauth]
18848 2022-09-07 18:37:35.064 debug3: receive packet: type 50 [preauth]
18848 2022-09-07 18:37:35.064 debug1: userauth-request for user n8n service ssh-connection method password [preauth]
18848 2022-09-07 18:37:35.064 debug1: attempt 1 failures 0 [preauth]
18848 2022-09-07 18:37:35.064 debug2: input_userauth_request: try method password [preauth]
18848 2022-09-07 18:37:35.064 debug3: mm_auth_password entering [preauth]
18848 2022-09-07 18:37:35.064 debug3: mm_request_send entering: type 12 [preauth]
18848 2022-09-07 18:37:35.064 debug3: mm_auth_password: waiting for MONITOR_ANS_AUTHPASSWORD [preauth]
18848 2022-09-07 18:37:35.064 debug3: mm_request_receive_expect entering: type 13 [preauth]
18848 2022-09-07 18:37:35.065 debug3: mm_request_receive entering [preauth]
18848 2022-09-07 18:37:35.065 debug3: mm_request_receive entering
18848 2022-09-07 18:37:35.065 debug3: monitor_read: checking request 12
18848 2022-09-07 18:37:35.097 debug3: mm_answer_authpassword: sending result 1
18848 2022-09-07 18:37:35.097 debug3: mm_request_send entering: type 13
18848 2022-09-07 18:37:35.097 Accepted password for n8n from 10.0.12.201 port 57182 ssh2
18848 2022-09-07 18:37:35.097 debug1: monitor_child_preauth: n8n has been authenticated by privileged process
18848 2022-09-07 18:37:35.098 debug3: mm_get_keystate: Waiting for new keys
18848 2022-09-07 18:37:35.098 debug3: mm_request_receive_expect entering: type 26
18848 2022-09-07 18:37:35.098 debug3: mm_request_receive entering
18848 2022-09-07 18:37:35.124 debug3: mm_get_keystate: GOT new keys
18848 2022-09-07 18:37:35.124 debug3: mm_auth_password: user authenticated [preauth]
18848 2022-09-07 18:37:35.124 debug3: user_specific_delay: user specific delay 0.000ms [preauth]
18848 2022-09-07 18:37:35.125 debug3: ensure_minimum_time_since: elapsed 33.944ms, delaying 13.125ms (requested 5.884ms) [preauth]
18848 2022-09-07 18:37:35.125 debug3: send packet: type 52 [preauth]
18848 2022-09-07 18:37:35.125 debug3: mm_request_send entering: type 26 [preauth]
18848 2022-09-07 18:37:35.125 debug3: mm_send_keystate: Finished sending state [preauth]
18848 2022-09-07 18:37:35.128 debug1: monitor_read_log: child log fd closed
18848 2022-09-07 18:37:35.144 debug3: spawning "C:\\WINDOWS\\System32\\OpenSSH\\sshd.exe" -z
18848 2022-09-07 18:37:35.151 User child is on pid 7468
18848 2022-09-07 18:37:35.151 debug3: send_rexec_state: entering fd = 5 config len 315
18848 2022-09-07 18:37:35.151 debug3: ssh_msg_send: type 0
18848 2022-09-07 18:37:35.151 debug3: send_rexec_state: done
18848 2022-09-07 18:37:35.151 debug3: ssh_msg_send: type 0
18848 2022-09-07 18:37:35.151 debug3: ssh_msg_send: type 0
18848 2022-09-07 18:37:35.151 debug3: ssh_msg_send: type 0
18848 2022-09-07 18:37:35.151 debug3: ssh_msg_send: type 0
18848 2022-09-07 18:37:35.151 debug3: ssh_msg_send: type 0
7468 2022-09-07 18:37:35.190 debug3: recv_idexch_state: entering fd = 3
7468 2022-09-07 18:37:35.190 debug3: ssh_msg_recv entering
7468 2022-09-07 18:37:35.190 debug3: recv_idexch_state: done
7468 2022-09-07 18:37:35.190 debug2: fd 4 setting O_NONBLOCK
7468 2022-09-07 18:37:35.190 debug3: recv_autxctx_state: entering fd = 3
7468 2022-09-07 18:37:35.190 debug3: ssh_msg_recv entering
7468 2022-09-07 18:37:35.190 debug3: recv_autxctx_state: done
7468 2022-09-07 18:37:35.192 debug2: parse_server_config: config reprocess config len 315
7468 2022-09-07 18:37:35.192 debug3: checking match for 'Group administrators' user n8n host 10.0.12.201 addr 10.0.12.201 laddr 10.0.12.88 lport 22
7468 2022-09-07 18:37:35.194 debug3: get_user_token - i am running as n8n, returning process token
7468 2022-09-07 18:37:35.194 debug1: user n8n matched group list administrators at line 87
7468 2022-09-07 18:37:35.194 debug3: match found
7468 2022-09-07 18:37:35.194 debug3: reprocess config:88 setting AuthorizedKeysFile __PROGRAMDATA__/ssh/administrators_authorized_keys
7468 2022-09-07 18:37:35.198 debug3: monitor_recv_keystate: entering 
7468 2022-09-07 18:37:35.198 debug3: ssh_msg_recv entering
7468 2022-09-07 18:37:35.198 debug3: monitor_recv_keystate: done
7468 2022-09-07 18:37:35.198 debug3: monitor_apply_keystate: packet_set_state
7468 2022-09-07 18:37:35.198 debug2: set_newkeys: mode 0
7468 2022-09-07 18:37:35.198 debug1: rekey in after 4294967296 blocks
7468 2022-09-07 18:37:35.198 debug2: set_newkeys: mode 1
7468 2022-09-07 18:37:35.198 debug1: rekey out after 4294967296 blocks
7468 2022-09-07 18:37:35.198 debug1: ssh_packet_set_postauth: called
7468 2022-09-07 18:37:35.198 debug3: ssh_packet_set_state: done
7468 2022-09-07 18:37:35.198 debug3: monitor_recv_authopt: entering 
7468 2022-09-07 18:37:35.198 debug3: ssh_msg_recv entering
7468 2022-09-07 18:37:35.198 debug3: monitor_recv_authopt: done
7468 2022-09-07 18:37:35.198 debug3: notify_hostkeys: key 0: ssh-rsa SHA256:gvdltPpA7YeDJOaVxvvRKhMjdrrWIxZ9h808wsjgtUU
7468 2022-09-07 18:37:35.198 debug3: notify_hostkeys: key 1: ecdsa-sha2-nistp256 SHA256:cR4XDnWURIrDQCY+IVa+naXF3sytubpItOoRxmiK160
7468 2022-09-07 18:37:35.198 debug3: notify_hostkeys: key 2: ssh-ed25519 SHA256:E2kg/k3CJSVMZrKzusT+hg6fnHgYcCq4xK3Q+Wk+RC4
7468 2022-09-07 18:37:35.198 debug3: notify_hostkeys: sent 3 hostkeys
7468 2022-09-07 18:37:35.198 debug3: send packet: type 80
7468 2022-09-07 18:37:35.198 debug1: active: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
7468 2022-09-07 18:37:35.198 debug1: Entering interactive session for SSH2.
7468 2022-09-07 18:37:35.198 debug2: fd 7 setting O_NONBLOCK
7468 2022-09-07 18:37:35.198 debug2: fd 8 setting O_NONBLOCK
7468 2022-09-07 18:37:35.198 debug1: server_init_dispatch
7468 2022-09-07 18:37:35.199 debug3: receive packet: type 90
7468 2022-09-07 18:37:35.199 debug1: server_input_channel_open: ctype session rchan 0 win 2097152 max 32768
7468 2022-09-07 18:37:35.199 debug1: input_session_request
7468 2022-09-07 18:37:35.199 debug1: channel 0: new [server-session]
7468 2022-09-07 18:37:35.199 debug2: session_new: allocate (allocated 0 max 10)
7468 2022-09-07 18:37:35.199 debug3: session_unused: session id 0 unused
7468 2022-09-07 18:37:35.199 debug1: session_new: session 0
7468 2022-09-07 18:37:35.199 debug1: session_open: channel 0
7468 2022-09-07 18:37:35.199 debug1: session_open: session 0: link with channel 0
7468 2022-09-07 18:37:35.199 debug1: server_input_channel_open: confirm session
7468 2022-09-07 18:37:35.199 debug3: send packet: type 91
7468 2022-09-07 18:37:35.243 debug3: receive packet: type 98
7468 2022-09-07 18:37:35.243 debug1: server_input_channel_req: channel 0 request exec reply 1
7468 2022-09-07 18:37:35.243 debug1: session_by_channel: session 0 channel 0
7468 2022-09-07 18:37:35.243 debug1: session_input_channel_req: session 0 req exec
7468 2022-09-07 18:37:35.243 Starting session: command for n8n from 10.0.12.201 port 57182 id 0
7468 2022-09-07 18:37:35.244 debug2: fd 9 setting O_NONBLOCK
7468 2022-09-07 18:37:35.244 debug2: fd 10 setting O_NONBLOCK
7468 2022-09-07 18:37:35.244 debug2: fd 11 setting O_NONBLOCK
7468 2022-09-07 18:37:35.244 debug2: fd 12 setting O_NONBLOCK
7468 2022-09-07 18:37:35.244 debug2: fd 13 setting O_NONBLOCK
7468 2022-09-07 18:37:35.244 debug2: fd 14 setting O_NONBLOCK
7468 2022-09-07 18:37:35.245 debug3: shell: "c:\\windows\\system32\\windowspowershell\\v1.0\\powershell.exe"
7468 2022-09-07 18:37:35.245 debug3: shell_option: -c
7468 2022-09-07 18:37:35.245 debug3: exec_command: cd '\\' ; 
7468 2022-09-07 18:37:35.245 debug3: arg escape option: TRUE
7468 2022-09-07 18:37:35.245 debug3: spawn_argv[0]: "c:\\windows\\system32\\windowspowershell\\v1.0\\powershell.exe"
7468 2022-09-07 18:37:35.245 debug3: spawning "c:\\windows\\system32\\windowspowershell\\v1.0\\powershell.exe" -c "cd '\\' ; "
7468 2022-09-07 18:37:35.254 debug2: fd 4 setting TCP_NODELAY
7468 2022-09-07 18:37:35.254 debug3: fd 11 is O_NONBLOCK
7468 2022-09-07 18:37:35.254 debug3: fd 10 is O_NONBLOCK
7468 2022-09-07 18:37:35.254 debug3: fd 13 is O_NONBLOCK
7468 2022-09-07 18:37:35.254 debug3: send packet: type 99
7468 2022-09-07 18:37:35.257 debug3: receive packet: type 96
7468 2022-09-07 18:37:35.257 debug2: channel 0: rcvd eof
7468 2022-09-07 18:37:35.257 debug2: channel 0: output open -> drain
7468 2022-09-07 18:37:35.257 debug2: channel 0: obuf empty
7468 2022-09-07 18:37:35.257 debug2: channel 0: chan_shutdown_write (i0 o1 sock -1 wfd 10 efd 13 [read])
7468 2022-09-07 18:37:35.257 debug2: channel 0: output drain -> closed
7468 2022-09-07 18:37:35.969 debug2: channel 0: read<=0 rfd 11 len 0
7468 2022-09-07 18:37:35.969 debug2: channel 0: read failed
7468 2022-09-07 18:37:35.969 debug2: channel 0: chan_shutdown_read (i0 o3 sock -1 wfd 11 efd 13 [read])
7468 2022-09-07 18:37:35.969 debug2: channel 0: input open -> drain
7468 2022-09-07 18:37:35.969 debug2: channel 0: read 0 from efd 13
7468 2022-09-07 18:37:35.970 debug2: channel 0: closing read-efd 13
7468 2022-09-07 18:37:35.970 debug2: channel 0: ibuf empty
7468 2022-09-07 18:37:35.970 debug2: channel 0: send eof
7468 2022-09-07 18:37:35.970 debug3: send packet: type 96
7468 2022-09-07 18:37:35.970 debug2: channel 0: input drain -> closed
7468 2022-09-07 18:37:35.974 debug3: receive packet: type 97
7468 2022-09-07 18:37:35.974 debug2: channel 0: rcvd close
7468 2022-09-07 18:37:35.974 debug3: channel 0: will not send data after close
7468 2022-09-07 18:37:35.974 debug2: channel 0: almost dead
7468 2022-09-07 18:37:35.974 debug2: channel 0: gc: notify user
7468 2022-09-07 18:37:35.974 debug1: session_by_channel: session 0 channel 0
7468 2022-09-07 18:37:35.974 debug1: session_close_by_channel: channel 0 child 20176
7468 2022-09-07 18:37:35.974 debug1: session_close_by_channel: channel 0: has child, ttyfd -1
7468 2022-09-07 18:37:35.989 debug1: Received SIGCHLD.
7468 2022-09-07 18:37:35.989 debug1: session_by_pid: pid 20176
7468 2022-09-07 18:37:35.989 debug1: session_exit_message: session 0 channel 0 pid 20176
7468 2022-09-07 18:37:35.989 debug2: channel 0: request exit-status confirm 0
7468 2022-09-07 18:37:35.989 debug3: send packet: type 98
7468 2022-09-07 18:37:35.989 debug1: session_exit_message: release channel 0
7468 2022-09-07 18:37:35.989 debug2: channel 0: send close
7468 2022-09-07 18:37:35.989 debug3: send packet: type 97
7468 2022-09-07 18:37:35.989 debug2: channel 0: is dead
7468 2022-09-07 18:37:35.989 debug2: channel 0: gc: notify user
7468 2022-09-07 18:37:35.990 debug1: session_by_channel: session 0 channel 0
7468 2022-09-07 18:37:35.990 debug1: session_close_by_channel: channel 0 child 0
7468 2022-09-07 18:37:35.990 Close session: user n8n from 10.0.12.201 port 57182 id 0
7468 2022-09-07 18:37:35.990 debug3: session_unused: session id 0 unused
7468 2022-09-07 18:37:35.990 debug2: channel 0: gc: user detached
7468 2022-09-07 18:37:35.990 debug2: channel 0: is dead
7468 2022-09-07 18:37:35.990 debug2: channel 0: garbage collecting
7468 2022-09-07 18:37:35.990 debug1: channel 0: free: server-session, nchannels 1
7468 2022-09-07 18:37:35.990 debug3: channel 0: status: The following connections are open:\r\n  #0 server-session (t4 r0 i3/0 o3/0 e[closed]/0 fd -1/-1/-1 sock -1 cc -1)\r\n
7468 2022-09-07 18:37:35.990 debug2: notify_done: reading
7468 2022-09-07 18:37:35.994 debug3: receive packet: type 1
7468 2022-09-07 18:37:35.994 Received disconnect from 10.0.12.201 port 57182:11: 
7468 2022-09-07 18:37:35.994 Disconnected from 10.0.12.201 port 57182
7468 2022-09-07 18:37:35.994 debug1: do_cleanup
18848 2022-09-07 18:37:36.000 debug3: mm_request_receive entering
18848 2022-09-07 18:37:36.001 debug1: do_cleanup

ansred · October 24, 2022, 7:46pm

@Jon any ideas by any chance that you could see from the logs above?
Thanks!

Jon · October 24, 2022, 8:23pm

Hey @ansred,

To be honest I have not had a chance to have a proper look. After doing some testing though on other issues there does appear to be a general issue with with OpenSSH on windows that causes an issue in the library we use.

I have an internal ticket opened to look into it more and as part of that I want to add extra debug logging to our node so we can see what is going on more clearly.

ansred · October 24, 2022, 11:43pm

Thanks for the update, yeah, it’s only an issue so far between n8n and OpenSSH Windows.

I tested with MacOS terminal and Linux, also Remote Desktop Manager + CyberDuck SFTP and all are working fine, it just keeps crashing on n8n.

TomSpidge · August 8, 2023, 11:43am

Did you ever get any further with this? I’m struggling with the same problem and would like to avoid a jump box if possible.