I, [2024-08-08T13:38:20.156748 #82621] INFO -- net.ssh.transport.server_version[3548a0]: negotiating protocol version
I, [2024-08-08T13:38:20.196643 #82621] INFO -- net.ssh.transport.algorithms[3548b4]: sending KEXINIT
I, [2024-08-08T13:38:20.229909 #82621] INFO -- net.ssh.transport.algorithms[3548b4]: got KEXINIT from server
I, [2024-08-08T13:38:20.230078 #82621] INFO -- net.ssh.transport.algorithms[3548b4]: negotiating algorithms
I, [2024-08-08T13:38:20.467610 #82621] INFO -- net.ssh.authentication.session[3548dc]:
I, [2024-08-08T13:38:20.477660 #82621] INFO -- net.ssh.connection.session[354904]: channel_open_confirmation: 0 0 131072 32768
I, [2024-08-08T13:38:20.477808 #82621] INFO -- net.ssh.connection.channel[354918]: sending channel request "subsystem"
I, [2024-08-08T13:38:20.494146 #82621] INFO -- net.ssh.connection.session[354904]: channel_success: 0
I, [2024-08-08T13:38:20.509574 #82621] INFO -- net.ssh.connection.session[354904]: channel_window_adjust: 0 +65536
I, [2024-08-08T13:38:20.509990 #82621] INFO -- net.ssh.connection.session[354904]: channel_data: 0 410b
I, [2024-08-08T13:38:20.510070 #82621] INFO -- net.sftp.session[35492c]: negotiated version is 5
I, [2024-08-08T13:38:20.510152 #82621] INFO -- net.sftp.session[35492c]: sending opendir packet (0)
I, [2024-08-08T13:38:20.567739 #82621] INFO -- net.ssh.connection.session[354904]: channel_data: 0 17b
I, [2024-08-08T13:38:20.568139 #82621] INFO -- net.sftp.session[35492c]: sending readdir packet (1)
I, [2024-08-08T13:38:20.607793 #82621] INFO -- net.ssh.connection.session[354904]: channel_data: 0 221b
.
I, [2024-08-08T13:38:20.608770 #82621] INFO -- net.sftp.session[35492c]: sending close packet (2)
I, [2024-08-08T13:38:20.616574 #82621] INFO -- net.ssh.connection.session[354904]: channel_data: 0 25b
E, [2024-08-08T13:38:20.616913 #82621] ERROR -- net.ssh.transport.session[354940]: forcing connection closed
(irb):68:in `write': "\xBD" from ASCII-8BIT to UTF-8 (Encoding::UndefinedConversionError)
from (irb):68:in `puts'
from (irb):68:in `puts'
from (irb):68:in `block (2 levels) in <top (required)>'
from /Users/doug/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/net-sftp-4.0.0/lib/net/sftp/operations/dir.rb:33:in `block in foreach'
from /Users/doug/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/net-sftp-4.0.0/lib/net/sftp/operations/dir.rb:33:in `each'
from /Users/doug/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/net-sftp-4.0.0/lib/net/sftp/operations/dir.rb:33:in `foreach'
from (irb):68:in `block in <top (required)>'
from /Users/doug/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/net-sftp-4.0.0/lib/net/sftp/session.rb:941:in `block in do_version'
from /Users/doug/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/net-sftp-4.0.0/lib/net/sftp/session.rb:941:in `each'
from /Users/doug/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/net-sftp-4.0.0/lib/net/sftp/session.rb:941:in `do_version'
from /Users/doug/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/net-sftp-4.0.0/lib/net/sftp/session.rb:911:in `when_channel_polled'
from /Users/doug/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/net-ssh-7.2.3/lib/net/ssh/connection/channel.rb:325:in `process'
from /Users/doug/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/net-ssh-7.2.3/lib/net/ssh/connection/session.rb:250:in `block in ev_preprocess'
from /Users/doug/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/net-ssh-7.2.3/lib/net/ssh/connection/session.rb:540:in `each'
from /Users/doug/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/net-ssh-7.2.3/lib/net/ssh/connection/session.rb:540:in `each_channel'
from /Users/doug/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/net-ssh-7.2.3/lib/net/ssh/connection/session.rb:250:in `ev_preprocess'
... 14 levels...
When using this specifying SFTP V4:
I, [2024-08-08T13:57:02.785266 #81443] INFO -- net.ssh.transport.server_version[eeac]: negotiating protocol version
I, [2024-08-08T13:57:02.828671 #81443] INFO -- net.ssh.transport.algorithms[eec0]: sending KEXINIT
I, [2024-08-08T13:57:02.853908 #81443] INFO -- net.ssh.transport.algorithms[eec0]: got KEXINIT from server
I, [2024-08-08T13:57:02.853976 #81443] INFO -- net.ssh.transport.algorithms[eec0]: negotiating algorithms
I, [2024-08-08T13:57:03.112085 #81443] INFO -- net.ssh.authentication.session[eee8]:
I, [2024-08-08T13:57:03.119799 #81443] INFO -- net.ssh.connection.session[ef10]: channel_open_confirmation: 0 0 131072 32768
I, [2024-08-08T13:57:03.119935 #81443] INFO -- net.ssh.connection.channel[ef24]: sending channel request "subsystem"
I, [2024-08-08T13:57:03.139372 #81443] INFO -- net.ssh.connection.session[ef10]: channel_success: 0
I, [2024-08-08T13:57:03.167470 #81443] INFO -- net.ssh.connection.session[ef10]: channel_window_adjust: 0 +65536
I, [2024-08-08T13:57:03.167903 #81443] INFO -- net.ssh.connection.session[ef10]: channel_data: 0 397b
I, [2024-08-08T13:57:03.167981 #81443] INFO -- net.sftp.session[ef38]: negotiated version is 4
SSH-2.0-FileCOPA
I, [2024-08-08T13:57:03.168077 #81443] INFO -- net.sftp.session[ef38]: sending opendir packet (0)
I, [2024-08-08T13:57:03.227924 #81443] INFO -- net.ssh.connection.session[ef10]: channel_data: 0 17b
I, [2024-08-08T13:57:03.228178 #81443] INFO -- net.sftp.session[ef38]: sending readdir packet (1)
I, [2024-08-08T13:57:03.265323 #81443] INFO -- net.ssh.connection.session[ef10]: channel_data: 0 208b
.
..
out
I, [2024-08-08T13:57:03.265808 #81443] INFO -- net.sftp.session[ef38]: sending readdir packet (2)
I, [2024-08-08T13:57:03.274655 #81443] INFO -- net.ssh.connection.session[ef10]: channel_data: 0 41b
I, [2024-08-08T13:57:03.274887 #81443] INFO -- net.sftp.session[ef38]: sending close packet (3)
I, [2024-08-08T13:57:03.292830 #81443] INFO -- net.ssh.connection.session[ef10]: channel_data: 0 25b
I, [2024-08-08T13:57:03.292980 #81443] INFO -- net.ssh.connection.session[ef10]: closing remaining channels (1 open)
I, [2024-08-08T13:57:03.308525 #81443] INFO -- net.ssh.connection.session[ef10]: channel_close: 0
I, [2024-08-08T13:57:03.308554 #81443] INFO -- net.ssh.connection.session[ef10]: 192.168.5.104 delete channel 0 which closed locally and remotely
=> nil
with the patched version of net sftp:
D, [2024-08-09T10:48:26.442056 #94499] DEBUG -- net.ssh.transport.session[2b598]: establishing connection to 10.0.13.184:22
D, [2024-08-09T10:48:26.444975 #94499] DEBUG -- net.ssh.transport.session[2b598]: connection established
I, [2024-08-09T10:48:26.445251 #94499] INFO -- net.ssh.transport.server_version[2b5ac]: negotiating protocol version
D, [2024-08-09T10:48:26.445281 #94499] DEBUG -- net.ssh.transport.server_version[2b5ac]: local is `SSH-2.0-Ruby/Net::SSH_7.2.1 arm64-darwin23'
D, [2024-08-09T10:48:26.511223 #94499] DEBUG -- net.ssh.transport.server_version[2b5ac]: remote is `SSH-2.0-FileCOPA'
I, [2024-08-09T10:48:26.513760 #94499] INFO -- net.ssh.transport.algorithms[2b5c0]: sending KEXINIT
D, [2024-08-09T10:48:26.513984 #94499] DEBUG -- socket[2b5d4]: queueing packet nr 0 type 20 len 1484
D, [2024-08-09T10:48:26.514074 #94499] DEBUG -- socket[2b5d4]: sent 1488 bytes
D, [2024-08-09T10:48:26.549133 #94499] DEBUG -- socket[2b5d4]: read 1304 bytes
D, [2024-08-09T10:48:26.549216 #94499] DEBUG -- socket[2b5d4]: received packet nr 0 type 20 len 1300
I, [2024-08-09T10:48:26.549254 #94499] INFO -- net.ssh.transport.algorithms[2b5c0]: got KEXINIT from server
I, [2024-08-09T10:48:26.549306 #94499] INFO -- net.ssh.transport.algorithms[2b5c0]: negotiating algorithms
D, [2024-08-09T10:48:26.549358 #94499] DEBUG -- net.ssh.transport.algorithms[2b5c0]: negotiated:
* kex: diffie-hellman-group14-sha1
* host_key: ssh-rsa
* encryption_server: aes256-cbc
* encryption_client: aes256-cbc
* hmac_client: hmac-sha2-512
* hmac_server: hmac-sha2-512
* compression_client: none
* compression_server: none
* language_client:
* language_server:
D, [2024-08-09T10:48:26.549370 #94499] DEBUG -- net.ssh.transport.algorithms[2b5c0]: exchanging keys
D, [2024-08-09T10:48:26.551326 #94499] DEBUG -- socket[2b5d4]: queueing packet nr 1 type 30 len 268
D, [2024-08-09T10:48:26.551379 #94499] DEBUG -- socket[2b5d4]: sent 272 bytes
D, [2024-08-09T10:48:26.654075 #94499] DEBUG -- socket[2b5d4]: read 576 bytes
D, [2024-08-09T10:48:26.654133 #94499] DEBUG -- socket[2b5d4]: received packet nr 1 type 31 len 572
D, [2024-08-09T10:48:26.655984 #94499] DEBUG -- socket[2b5d4]: queueing packet nr 2 type 21 len 20
D, [2024-08-09T10:48:26.656013 #94499] DEBUG -- socket[2b5d4]: sent 24 bytes
D, [2024-08-09T10:48:26.673776 #94499] DEBUG -- socket[2b5d4]: read 16 bytes
D, [2024-08-09T10:48:26.673799 #94499] DEBUG -- socket[2b5d4]: received packet nr 2 type 21 len 12
D, [2024-08-09T10:48:26.673949 #94499] DEBUG -- net.ssh.authentication.session[2b5e8]: beginning authentication of `doug'
D, [2024-08-09T10:48:26.673997 #94499] DEBUG -- socket[2b5d4]: queueing packet nr 3 type 5 len 28
D, [2024-08-09T10:48:26.674019 #94499] DEBUG -- socket[2b5d4]: sent 96 bytes
D, [2024-08-09T10:48:26.705421 #94499] DEBUG -- socket[2b5d4]: read 96 bytes
D, [2024-08-09T10:48:26.705513 #94499] DEBUG -- socket[2b5d4]: received packet nr 3 type 6 len 28
D, [2024-08-09T10:48:26.705599 #94499] DEBUG -- net.ssh.authentication.session[2b5e8]: trying none
D, [2024-08-09T10:48:26.705661 #94499] DEBUG -- socket[2b5d4]: queueing packet nr 4 type 50 len 44
D, [2024-08-09T10:48:26.705696 #94499] DEBUG -- socket[2b5d4]: sent 112 bytes
D, [2024-08-09T10:48:26.720345 #94499] DEBUG -- socket[2b5d4]: read 112 bytes
D, [2024-08-09T10:48:26.720373 #94499] DEBUG -- socket[2b5d4]: received packet nr 4 type 51 len 44
D, [2024-08-09T10:48:26.720390 #94499] DEBUG -- net.ssh.authentication.session[2b5e8]: allowed methods: password,publickey
D, [2024-08-09T10:48:26.720410 #94499] DEBUG -- net.ssh.authentication.methods.none[2b5fc]: none failed
D, [2024-08-09T10:48:26.720429 #94499] DEBUG -- net.ssh.authentication.session[2b5e8]: trying publickey
D, [2024-08-09T10:48:26.721843 #94499] DEBUG -- net.ssh.authentication.agent[2b610]: connecting to ssh-agent
D, [2024-08-09T10:48:26.721918 #94499] DEBUG -- net.ssh.authentication.agent[2b610]: sending agent request 1 len 46
D, [2024-08-09T10:48:26.722085 #94499] DEBUG -- net.ssh.authentication.agent[2b610]: received agent packet 5 len 1
D, [2024-08-09T10:48:26.722119 #94499] DEBUG -- net.ssh.authentication.agent[2b610]: sending agent request 11 len 0
D, [2024-08-09T10:48:26.722173 #94499] DEBUG -- net.ssh.authentication.agent[2b610]: received agent packet 12 len 5
D, [2024-08-09T10:48:26.722238 #94499] DEBUG -- net.ssh.authentication.methods.publickey[2b638]: trying publickey (f1:03:bc:1d:c4:b9:64:25:d8:7f:49:b3:21:48:6b:84) alg ssh-ed25519
D, [2024-08-09T10:48:26.722306 #94499] DEBUG -- socket[2b5d4]: queueing packet nr 5 type 50 len 124
D, [2024-08-09T10:48:26.722334 #94499] DEBUG -- socket[2b5d4]: sent 192 bytes
D, [2024-08-09T10:48:26.736208 #94499] DEBUG -- socket[2b5d4]: read 112 bytes
D, [2024-08-09T10:48:26.736359 #94499] DEBUG -- socket[2b5d4]: received packet nr 5 type 51 len 44
D, [2024-08-09T10:48:26.736425 #94499] DEBUG -- net.ssh.authentication.session[2b5e8]: allowed methods: password,publickey
D, [2024-08-09T10:48:26.736519 #94499] DEBUG -- net.ssh.authentication.session[2b5e8]: trying password
D, [2024-08-09T10:48:26.736736 #94499] DEBUG -- socket[2b5d4]: queueing packet nr 6 type 50 len 60
D, [2024-08-09T10:48:26.736799 #94499] DEBUG -- socket[2b5d4]: sent 128 bytes
D, [2024-08-09T10:48:26.772888 #94499] DEBUG -- socket[2b5d4]: read 96 bytes
D, [2024-08-09T10:48:26.773083 #94499] DEBUG -- socket[2b5d4]: received packet nr 6 type 53 len 28
I, [2024-08-09T10:48:26.773153 #94499] INFO -- net.ssh.authentication.session[2b5e8]:
D, [2024-08-09T10:48:26.773196 #94499] DEBUG -- socket[2b5d4]: read 80 bytes
D, [2024-08-09T10:48:26.773246 #94499] DEBUG -- socket[2b5d4]: received packet nr 7 type 52 len 12
D, [2024-08-09T10:48:26.773338 #94499] DEBUG -- net.ssh.authentication.methods.password[2b64c]: password succeeded
D, [2024-08-09T10:48:26.773682 #94499] DEBUG -- socket[2b5d4]: queueing packet nr 7 type 90 len 44
D, [2024-08-09T10:48:26.773885 #94499] DEBUG -- socket[2b5d4]: sent 112 bytes
D, [2024-08-09T10:48:26.780645 #94499] DEBUG -- socket[2b5d4]: read 96 bytes
D, [2024-08-09T10:48:26.780785 #94499] DEBUG -- socket[2b5d4]: received packet nr 8 type 91 len 28
I, [2024-08-09T10:48:26.781117 #94499] INFO -- net.ssh.connection.session[2b660]: channel_open_confirmation: 0 0 131072 32768
D, [2024-08-09T10:48:26.781207 #94499] DEBUG -- net.sftp.session[2b674]: requesting sftp subsystem
I, [2024-08-09T10:48:26.781276 #94499] INFO -- net.ssh.connection.channel[2b688]: sending channel request "subsystem"
D, [2024-08-09T10:48:26.781397 #94499] DEBUG -- socket[2b5d4]: queueing packet nr 8 type 98 len 44
D, [2024-08-09T10:48:26.781503 #94499] DEBUG -- socket[2b5d4]: sent 112 bytes
D, [2024-08-09T10:48:26.797299 #94499] DEBUG -- socket[2b5d4]: read 80 bytes
D, [2024-08-09T10:48:26.797382 #94499] DEBUG -- socket[2b5d4]: received packet nr 9 type 99 len 12
I, [2024-08-09T10:48:26.797406 #94499] INFO -- net.ssh.connection.session[2b660]: channel_success: 0
D, [2024-08-09T10:48:26.797420 #94499] DEBUG -- net.sftp.session[2b674]: sftp subsystem successfully started
D, [2024-08-09T10:48:26.797496 #94499] DEBUG -- socket[2b5d4]: queueing packet nr 9 type 94 len 28
D, [2024-08-09T10:48:26.797551 #94499] DEBUG -- socket[2b5d4]: sent 96 bytes
D, [2024-08-09T10:48:26.830617 #94499] DEBUG -- socket[2b5d4]: read 96 bytes
D, [2024-08-09T10:48:26.830691 #94499] DEBUG -- socket[2b5d4]: received packet nr 10 type 93 len 28
I, [2024-08-09T10:48:26.830714 #94499] INFO -- net.ssh.connection.session[2b660]: channel_window_adjust: 0 +65536
D, [2024-08-09T10:48:26.830986 #94499] DEBUG -- socket[2b5d4]: read 496 bytes
D, [2024-08-09T10:48:26.831025 #94499] DEBUG -- socket[2b5d4]: received packet nr 11 type 94 len 428
I, [2024-08-09T10:48:26.831046 #94499] INFO -- net.ssh.connection.session[2b660]: channel_data: 0 410b
D, [2024-08-09T10:48:26.831102 #94499] DEBUG -- net.sftp.session[2b674]: received sftp packet 2 len 406
D, [2024-08-09T10:48:26.831119 #94499] DEBUG -- net.sftp.session[2b674]: negotiating sftp protocol version, mine is 6
D, [2024-08-09T10:48:26.831127 #94499] DEBUG -- net.sftp.session[2b674]: server reports sftp version 5
I, [2024-08-09T10:48:26.831134 #94499] INFO -- net.sftp.session[2b674]: negotiated version is 5
SSH-2.0-FileCOPA
I, [2024-08-09T10:48:26.831246 #94499] INFO -- net.sftp.session[2b674]: sending opendir packet (0)
D, [2024-08-09T10:48:26.831323 #94499] DEBUG -- socket[2b5d4]: queueing packet nr 10 type 94 len 28
D, [2024-08-09T10:48:26.831370 #94499] DEBUG -- socket[2b5d4]: sent 96 bytes
D, [2024-08-09T10:48:26.886497 #94499] DEBUG -- socket[2b5d4]: read 112 bytes
D, [2024-08-09T10:48:26.886774 #94499] DEBUG -- socket[2b5d4]: received packet nr 12 type 94 len 44
I, [2024-08-09T10:48:26.886855 #94499] INFO -- net.ssh.connection.session[2b660]: channel_data: 0 17b
D, [2024-08-09T10:48:26.886936 #94499] DEBUG -- net.sftp.session[2b674]: received sftp packet 102 len 13
I, [2024-08-09T10:48:26.887274 #94499] INFO -- net.sftp.session[2b674]: sending readdir packet (1)
D, [2024-08-09T10:48:26.887405 #94499] DEBUG -- socket[2b5d4]: queueing packet nr 11 type 94 len 44
D, [2024-08-09T10:48:26.887511 #94499] DEBUG -- socket[2b5d4]: sent 112 bytes
D, [2024-08-09T10:48:26.932866 #94499] DEBUG -- socket[2b5d4]: read 384 bytes
D, [2024-08-09T10:48:26.933032 #94499] DEBUG -- socket[2b5d4]: received packet nr 13 type 94 len 316
I, [2024-08-09T10:48:26.933071 #94499] INFO -- net.ssh.connection.session[2b660]: channel_data: 0 295b
D, [2024-08-09T10:48:26.933108 #94499] DEBUG -- net.sftp.session[2b674]: received sftp packet 104 len 291
.
..
another
out
I, [2024-08-09T10:48:26.933309 #94499] INFO -- net.sftp.session[2b674]: sending readdir packet (2)
D, [2024-08-09T10:48:26.933353 #94499] DEBUG -- socket[2b5d4]: queueing packet nr 12 type 94 len 44
D, [2024-08-09T10:48:26.933400 #94499] DEBUG -- socket[2b5d4]: sent 112 bytes
D, [2024-08-09T10:48:26.956113 #94499] DEBUG -- socket[2b5d4]: read 128 bytes
D, [2024-08-09T10:48:26.956342 #94499] DEBUG -- socket[2b5d4]: received packet nr 14 type 94 len 60
I, [2024-08-09T10:48:26.956420 #94499] INFO -- net.ssh.connection.session[2b660]: channel_data: 0 41b
D, [2024-08-09T10:48:26.956497 #94499] DEBUG -- net.sftp.session[2b674]: received sftp packet 101 len 37
I, [2024-08-09T10:48:26.956668 #94499] INFO -- net.sftp.session[2b674]: sending close packet (3)
D, [2024-08-09T10:48:26.956787 #94499] DEBUG -- socket[2b5d4]: queueing packet nr 13 type 94 len 44
D, [2024-08-09T10:48:26.956869 #94499] DEBUG -- socket[2b5d4]: sent 112 bytes
D, [2024-08-09T10:48:26.986522 #94499] DEBUG -- socket[2b5d4]: read 112 bytes
D, [2024-08-09T10:48:26.986625 #94499] DEBUG -- socket[2b5d4]: received packet nr 15 type 94 len 44
I, [2024-08-09T10:48:26.986662 #94499] INFO -- net.ssh.connection.session[2b660]: channel_data: 0 25b
D, [2024-08-09T10:48:26.986689 #94499] DEBUG -- net.sftp.session[2b674]: received sftp packet 101 len 21
I, [2024-08-09T10:48:26.986756 #94499] INFO -- net.ssh.connection.session[2b660]: closing remaining channels (1 open)
D, [2024-08-09T10:48:26.986811 #94499] DEBUG -- socket[2b5d4]: queueing packet nr 14 type 97 len 28
D, [2024-08-09T10:48:26.986851 #94499] DEBUG -- socket[2b5d4]: sent 96 bytes
D, [2024-08-09T10:48:27.001508 #94499] DEBUG -- socket[2b5d4]: read 80 bytes
D, [2024-08-09T10:48:27.001573 #94499] DEBUG -- socket[2b5d4]: received packet nr 16 type 97 len 12
I, [2024-08-09T10:48:27.001597 #94499] INFO -- net.ssh.connection.session[2b660]: channel_close: 0
I, [2024-08-09T10:48:27.001611 #94499] INFO -- net.ssh.connection.session[2b660]: 10.0.13.184 delete channel 0 which closed locally and remotely
D, [2024-08-09T10:48:27.001621 #94499] DEBUG -- net.sftp.session[2b674]: sftp channel closed
The Current implementation of SFTP v5 is missing the
access-bits
attributeExample issue: https://github.com/net-ssh/net-sftp/issues/78 https://github.com/net-ssh/net-sftp/issues/66 Stackoverflow: https://stackoverflow.com/questions/42124883/broken-filenames-with-ruby-when-connected-to-sftp-version-5
If you find a V5 server (there's a few out there, Windows: FileCOPA) and try to connect to it and run a file listing:
You get corrupted output:
When using this specifying SFTP V4:
with the patched version of net sftp: