search

michaellukashov / Far-NetBox

SFTP/SCP/FTP/FTPS/WebDAV/S3 client for Far Manager 3 (http://farmanager.com/)
https://forum.farmanager.com/viewtopic.php?t=6317
GNU General Public License v2.0
155 stars 52 forks source link

Can not create a remote folder #485

Open relictMarauder opened 1 week ago

relictMarauder commented 1 week ago

By creating remote folder i receive the following error:

Cannot get real path for "/share/CACHEDEV1_DATA/Download/Kodi/12"

The log:

2024-06-25 08:46:19.799 . NetBox Version 24.6.0 beta (Build Build 603) (OS 10.0.22631 – Windows 10 Pro) 2024-06-25 08:46:19.800 . Configuration: NetBox 3\ 2024-06-25 08:46:19.800 . Log level: Debug 2 2024-06-25 08:46:19.800 . Local account: xxxxxxxx 2024-06-25 08:46:19.800 . Working directory: D:\ 2024-06-25 08:46:19.800 . Process ID: 42388 2024-06-25 08:46:19.800 . Ancestor processes: 2024-06-25 08:46:19.800 . Command-line: 2024-06-25 08:46:19.800 . Time zone: Current: GMT+2, Standard: GMT+1 (Mitteleuropäische Zeit), DST: GMT+2 (Mitteleuropäische Sommerzeit), DST Start: 31.03.2024, DST End: 27.10.2024 2024-06-25 08:46:19.800 . Login time: 25.06.2024 08:46:19 2024-06-25 08:46:19.800 . -------------------------------------------------------------------------- 2024-06-25 08:46:19.800 . Session name: xxx/xxxxx (Modified site) 2024-06-25 08:46:19.800 . Host name: 192.168.xxx.xxx (Port: 22) 2024-06-25 08:46:19.800 . User name: admin (Password: No, Key file: Yes, Passphrase: No) 2024-06-25 08:46:19.800 . Tunnel: No 2024-06-25 08:46:19.800 . Transfer Protocol: SFTP (SCP) 2024-06-25 08:46:19.800 . Ping type: Off, Ping interval: 30 sec; Timeout: 15 sec 2024-06-25 08:46:19.800 . Disable Nagle: Yes 2024-06-25 08:46:19.800 . Proxy: None 2024-06-25 08:46:19.800 . Send buffer: 262144 2024-06-25 08:46:19.800 . Compression: No 2024-06-25 08:46:19.800 . Bypass authentication: No 2024-06-25 08:46:19.800 . Try agent: Yes; Agent forwarding: No; KI: Yes; GSSAPI: No 2024-06-25 08:46:19.800 . Ciphers: des,aes,chacha20,blowfish,3des,aesgcm,WARN,arcfour; Ssh2DES: Yes 2024-06-25 08:46:19.800 . KEX: ntru-curve25519,ecdh,dh-gex-sha1,dh-group18-sha512,dh-group17-sha512,dh-group16-sha512,dh-group15-sha512,dh-group14-sha1,rsa,WARN,dh-group1-sha1 2024-06-25 08:46:19.800 . SSH Bugs: Auto,Auto,Auto,Auto,Auto,Auto,Auto,Auto,Auto,Auto 2024-06-25 08:46:19.800 . Simple channel: Yes 2024-06-25 08:46:19.800 . Return code variable: Autodetect; Lookup user groups: On 2024-06-25 08:46:19.800 . Shell: default 2024-06-25 08:46:19.800 . EOL: LF, UTF: Off 2024-06-25 08:46:19.800 . Clear aliases: Yes, Unset nat.vars: Yes, Resolve symlinks: No; Follow directory symlinks: Yes 2024-06-25 08:46:19.800 . LS: ls -la, Ign LS warn: Yes, Scp1 Comp: No; Exit code 1 is error: No 2024-06-25 08:46:19.800 . SFTP Bugs: Auto,Auto 2024-06-25 08:46:19.800 . SFTP Server: default 2024-06-25 08:46:19.800 . Local directory: default, Remote directory: /share/CACHEDEV1_DATA/Download/Kodi, Update: Yes, Cache: No 2024-06-25 08:46:19.800 . Cache directory changes: No, Permanent: No 2024-06-25 08:46:19.800 . Recycle bin: Delete to: No, Overwritten to: No, Bin path: 2024-06-25 08:46:19.800 . DST mode: Unix 2024-06-25 08:46:19.800 . -------------------------------------------------------------------------- 2024-06-25 08:46:19.801 . Looking up host "192.168.xxx.xxx" for SSH connection 2024-06-25 08:46:19.801 . Connecting to 192.168.xxx.xxx port 22 2024-06-25 08:46:19.802 . Connected to 192.168.xxx.xxx 2024-06-25 08:46:19.802 . Selecting events 63 for socket 1128 2024-06-25 08:46:19.802 . Waiting for the server to continue with the initialization 2024-06-25 08:46:19.802 . Looking for incoming data 2024-06-25 08:46:19.802 . We claim version: SSH-2.0-NetBox_Far_24.6.0 2024-06-25 08:46:19.802 . Detected network event 2024-06-25 08:46:19.802 . Enumerating network events for socket 1128 2024-06-25 08:46:19.802 . Enumerated 18 network events making 18 cumulative events for socket 1128 2024-06-25 08:46:19.802 . Handling network write event on socket 1128 with error 0 2024-06-25 08:46:19.802 . Handling network connect event on socket 1128 with error 0 2024-06-25 08:46:19.802 . Connected to 192.168.xxx.xxx 2024-06-25 08:46:19.807 . Detected network event 2024-06-25 08:46:19.807 . Enumerating network events for socket 1128 2024-06-25 08:46:19.807 . Enumerated 1 network events making 1 cumulative events for socket 1128 2024-06-25 08:46:19.807 . Handling network read event on socket 1128 with error 0 2024-06-25 08:46:19.807 . Waiting for the server to continue with the initialization 2024-06-25 08:46:19.807 . Looking for incoming data 2024-06-25 08:46:19.807 . Remote version: SSH-2.0-OpenSSH_8.0 2024-06-25 08:46:19.807 . Using SSH protocol version 2 2024-06-25 08:46:19.815 . Have a known host key of type rsa2 2024-06-25 08:46:19.820 . Detected network event 2024-06-25 08:46:19.820 . Enumerating network events for socket 1128 2024-06-25 08:46:19.820 . Enumerated 1 network events making 1 cumulative events for socket 1128 2024-06-25 08:46:19.820 . Handling network read event on socket 1128 with error 0 2024-06-25 08:46:19.820 . Waiting for the server to continue with the initialization 2024-06-25 08:46:19.820 . Looking for incoming data 2024-06-25 08:46:19.821 . Doing ECDH key exchange with curve Curve25519, using hash SHA-256 2024-06-25 08:46:19.830 . Detected network event 2024-06-25 08:46:19.830 . Enumerating network events for socket 1128 2024-06-25 08:46:19.830 . Enumerated 1 network events making 1 cumulative events for socket 1128 2024-06-25 08:46:19.830 . Handling network read event on socket 1128 with error 0 2024-06-25 08:46:19.830 . Waiting for the server to continue with the initialization 2024-06-25 08:46:19.830 . Looking for incoming data 2024-06-25 08:46:19.832 . Host key fingerprint is: 2024-06-25 08:46:19.832 . ssh-rsa 2048 SHA256:xxxxxxxxxxxxxxxx 2024-06-25 08:46:19.832 . Verifying host key rxxxxxxx . Host key matches cached key 2024-06-25 08:46:19.839 . Initialised AES-256 SDCTR (AES-NI accelerated) [aes256-ctr] outbound encryption 2024-06-25 08:46:19.839 . Initialised HMAC-SHA-256 outbound MAC algorithm 2024-06-25 08:46:19.839 . Initialised AES-256 SDCTR (AES-NI accelerated) [aes256-ctr] inbound encryption 2024-06-25 08:46:19.839 . Initialised HMAC-SHA-256 inbound MAC algorithm 2024-06-25 08:46:19.839 . Detected network event 2024-06-25 08:46:19.839 . Enumerating network events for socket 1128 2024-06-25 08:46:19.839 . Enumerated 1 network events making 1 cumulative events for socket 1128 2024-06-25 08:46:19.839 . Handling network read event on socket 1128 with error 0 2024-06-25 08:46:19.839 . Waiting for the server to continue with the initialization 2024-06-25 08:46:19.839 . Looking for incoming data 2024-06-25 08:46:19.839 . Reading key file "p:\xxxxxx 2024-06-25 08:46:19.848 . Detected network event 2024-06-25 08:46:19.848 . Enumerating network events for socket 1128 2024-06-25 08:46:19.848 . Enumerated 1 network events making 1 cumulative events for socket 1128 2024-06-25 08:46:19.848 . Handling network read event on socket 1128 with error 0 2024-06-25 08:46:19.848 . Waiting for the server to continue with the initialization 2024-06-25 08:46:19.848 . Looking for incoming data 2024-06-25 08:46:19.848 . Server offered these authentication methods: publickey,password,keyboard-interactive 2024-06-25 08:46:19.848 . Offered public key 2024-06-25 08:46:19.849 . Detected network event 2024-06-25 08:46:19.849 . Enumerating network events for socket 1128 2024-06-25 08:46:19.849 . Enumerated 1 network events making 1 cumulative events for socket 1128 2024-06-25 08:46:19.849 . Handling network read event on socket 1128 with error 0 2024-06-25 08:46:19.849 . Waiting for the server to continue with the initialization 2024-06-25 08:46:19.849 . Looking for incoming data 2024-06-25 08:46:19.849 . Offer of public key accepted 2024-06-25 08:46:19.849 ! Using username "admin".Authenticating with public key "imported-openssh-key" 2024-06-25 08:46:19.854 . Sent public key signature 2024-06-25 08:46:19.865 . Detected network event 2024-06-25 08:46:19.865 . Enumerating network events for socket 1128 2024-06-25 08:46:19.865 . Enumerated 1 network events making 1 cumulative events for socket 1128 2024-06-25 08:46:19.865 . Handling network read event on socket 1128 with error 0 2024-06-25 08:46:19.865 . Waiting for the server to continue with the initialization 2024-06-25 08:46:19.865 . Looking for incoming data 2024-06-25 08:46:19.865 . Access granted 2024-06-25 08:46:19.865 . Opening main session channel 2024-06-25 08:46:19.872 . Detected network event 2024-06-25 08:46:19.872 . Enumerating network events for socket 1128 2024-06-25 08:46:19.872 . Enumerated 1 network events making 1 cumulative events for socket 1128 2024-06-25 08:46:19.872 . Handling network read event on socket 1128 with error 0 2024-06-25 08:46:19.872 . Waiting for the server to continue with the initialization 2024-06-25 08:46:19.872 . Looking for incoming data 2024-06-25 08:46:19.872 . Remote debug message: /root/.ssh/authorized_keys:1: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding 2024-06-25 08:46:19.918 . Detected network event 2024-06-25 08:46:19.918 . Enumerating network events for socket 1128 2024-06-25 08:46:19.918 . Enumerated 1 network events making 1 cumulative events for socket 1128 2024-06-25 08:46:19.918 . Handling network read event on socket 1128 with error 0 2024-06-25 08:46:19.918 . Waiting for the server to continue with the initialization 2024-06-25 08:46:19.918 . Looking for incoming data 2024-06-25 08:46:19.918 . Remote debug message: /root/.ssh/authorized_keys:1: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding 2024-06-25 08:46:19.918 . Opened main channel 2024-06-25 08:46:19.918 . Detected network event 2024-06-25 08:46:19.918 . Enumerating network events for socket 1128 2024-06-25 08:46:19.918 . Enumerated 1 network events making 1 cumulative events for socket 1128 2024-06-25 08:46:19.918 . Handling network read event on socket 1128 with error 0 2024-06-25 08:46:19.918 . Waiting for the server to continue with the initialization 2024-06-25 08:46:19.918 . Looking for incoming data 2024-06-25 08:46:19.918 . Started a shell/command 2024-06-25 08:46:19.919 . -------------------------------------------------------------------------- 2024-06-25 08:46:19.919 . Using SFTP protocol. 2024-06-25 08:46:19.919 . Doing startup conversation with host. 2024-06-25 08:46:19.919 . Skipped packets 2024-06-25 08:46:19.919 > Type: SSH_FXP_INIT, Size: 5, Number: -1 2024-06-25 08:46:19.919 > 01,00,00,00,06, 2024-06-25 08:46:19.919 . Sent 9 bytes 2024-06-25 08:46:19.919 . There are 0 bytes remaining in the send buffer 2024-06-25 08:46:19.919 . Waiting for another 4 bytes 2024-06-25 08:46:19.919 . Looking for incoming data 2024-06-25 08:46:19.958 . Detected network event 2024-06-25 08:46:19.958 . Enumerating network events for socket 1128 2024-06-25 08:46:19.958 . Enumerated 1 network events making 1 cumulative events for socket 1128 2024-06-25 08:46:19.958 . Handling network read event on socket 1128 with error 0 2024-06-25 08:46:19.958 . Waiting for another 4 bytes 2024-06-25 08:46:19.958 . Looking for incoming data 2024-06-25 08:46:19.958 . Received 183 bytes 2024-06-25 08:46:19.958 . Read 4 bytes (179 pending) 2024-06-25 08:46:19.958 . Read 179 bytes (0 pending) 2024-06-25 08:46:19.958 . Skipped packets 2024-06-25 08:46:19.958 < Type: SSH_FXP_VERSION, Size: 179, Number: -1 2024-06-25 08:46:19.958 < 02,00,00,00,03,00,00,00,18,70,6F,73,69,78,2D,72,65,6E,61,6D,65,40,6F,70,65, 2024-06-25 08:46:19.958 < 6E,73,73,68,2E,63,6F,6D,00,00,00,01,31,00,00,00,13,73,74,61,74,76,66,73,40, 2024-06-25 08:46:19.958 < 6F,70,65,6E,73,73,68,2E,63,6F,6D,00,00,00,01,32,00,00,00,14,66,73,74,61,74, 2024-06-25 08:46:19.958 < 76,66,73,40,6F,70,65,6E,73,73,68,2E,63,6F,6D,00,00,00,01,32,00,00,00,14,68, 2024-06-25 08:46:19.958 < 61,72,64,6C,69,6E,6B,40,6F,70,65,6E,73,73,68,2E,63,6F,6D,00,00,00,01,31,00, 2024-06-25 08:46:19.958 < 00,00,11,66,73,79,6E,63,40,6F,70,65,6E,73,73,68,2E,63,6F,6D,00,00,00,01,31, 2024-06-25 08:46:19.958 < 00,00,00,14,6C,73,65,74,73,74,61,74,40,6F,70,65,6E,73,73,68,2E,63,6F,6D,00, 2024-06-25 08:46:19.958 < 00,00,01,31, 2024-06-25 08:46:19.958 . SFTP version 3 negotiated. 2024-06-25 08:46:19.958 . Supports extension posix-rename@openssh.com="1" 2024-06-25 08:46:19.958 . Supports statvfs@openssh.com extension version 2 2024-06-25 08:46:19.958 . Unknown server extension fstatvfs@openssh.com="2" 2024-06-25 08:46:19.958 . Supports hardlink@openssh.com extension version 1 2024-06-25 08:46:19.958 . Unknown server extension fsync@openssh.com="1" 2024-06-25 08:46:19.958 . Unknown server extension lsetstat@openssh.com="1" 2024-06-25 08:46:19.958 . We believe the server has signed timestamps bug 2024-06-25 08:46:19.958 . We will not use UTF-8 strings as configured 2024-06-25 08:46:19.958 . Limiting packet size to OpenSSH sftp-server limit of 262148 bytes 2024-06-25 08:46:19.958 . Changing directory to "/share/CACHEDEV1_DATA/Download/Kodi". 2024-06-25 08:46:19.958 . Getting real path for '/share/CACHEDEV1_DATA/Download/Kodi' 2024-06-25 08:46:19.958 . Skipped packets 2024-06-25 08:46:19.958 > Type: SSH_FXP_REALPATH, Size: 44, Number: 922896 2024-06-25 08:46:19.958 > 10,00,0E,15,10,00,00,00,23,2F,73,68,61,72,65,2F,43,41,43,48,45,44,45,56,31, 2024-06-25 08:46:19.958 > 5F,44,41,54,41,2F,44,6F,77,6E,6C,6F,61,64,2F,4B,6F,64,69, 2024-06-25 08:46:19.958 . Sent 48 bytes 2024-06-25 08:46:19.958 . There are 0 bytes remaining in the send buffer 2024-06-25 08:46:19.958 . Waiting for another 4 bytes 2024-06-25 08:46:19.958 . Looking for incoming data 2024-06-25 08:46:19.959 . Detected network event 2024-06-25 08:46:19.959 . Enumerating network events for socket 1128 2024-06-25 08:46:19.959 . Enumerated 1 network events making 1 cumulative events for socket 1128 2024-06-25 08:46:19.959 . Handling network read event on socket 1128 with error 0 2024-06-25 08:46:19.959 . Waiting for another 4 bytes 2024-06-25 08:46:19.959 . Looking for incoming data 2024-06-25 08:46:19.959 . Received 95 bytes 2024-06-25 08:46:19.959 . Read 4 bytes (91 pending) 2024-06-25 08:46:19.959 . Read 91 bytes (0 pending) 2024-06-25 08:46:19.959 . Skipped packets 2024-06-25 08:46:19.959 < Type: SSH_FXP_NAME, Size: 91, Number: 922896 2024-06-25 08:46:19.959 < 68,00,0E,15,10,00,00,00,01,00,00,00,23,2F,73,68,61,72,65,2F,43,41,43,48,45, 2024-06-25 08:46:19.959 < 44,45,56,31,5F,44,41,54,41,2F,44,6F,77,6E,6C,6F,61,64,2F,4B,6F,64,69,00,00, 2024-06-25 08:46:19.959 < 00,23,2F,73,68,61,72,65,2F,43,41,43,48,45,44,45,56,31,5F,44,41,54,41,2F,44, 2024-06-25 08:46:19.959 < 6F,77,6E,6C,6F,61,64,2F,4B,6F,64,69,00,00,00,00, 2024-06-25 08:46:19.959 . Real path is '/share/CACHEDEV1_DATA/Download/Kodi'

2024-06-25 08:43:54.709 . Creating directory "12". 2024-06-25 08:43:54.709 . Getting real path for '/share/CACHEDEV1_DATA/Download/Kodi/12' 2024-06-25 08:43:54.709 . Skipped packets 2024-06-25 08:43:54.709 > Type: SSH_FXP_REALPATH, Size: 47, Number: 922640 2024-06-25 08:43:54.709 > 10,00,0E,14,10,00,00,00,26,2F,73,68,61,72,65,2F,43,41,43,48,45,44,45,56,31, 2024-06-25 08:43:54.709 > 5F,44,41,54,41,2F,44,6F,77,6E,6C,6F,61,64,2F,4B,6F,64,69,2F,31,32, 2024-06-25 08:43:54.709 . Sent 51 bytes 2024-06-25 08:43:54.709 . There are 0 bytes remaining in the send buffer 2024-06-25 08:43:54.709 . Waiting for another 4 bytes 2024-06-25 08:43:54.709 . Looking for incoming data 2024-06-25 08:43:54.710 . Detected network event 2024-06-25 08:43:54.710 . Enumerating network events for socket 1452 2024-06-25 08:43:54.710 . Enumerated 1 network events making 1 cumulative events for socket 1452 2024-06-25 08:43:54.710 . Handling network read event on socket 1452 with error 0 2024-06-25 08:43:54.710 . Waiting for another 4 bytes 2024-06-25 08:43:54.710 . Looking for incoming data 2024-06-25 08:43:54.710 . Received 33 bytes 2024-06-25 08:43:54.710 . Read 4 bytes (29 pending) 2024-06-25 08:43:54.710 . Read 29 bytes (0 pending) 2024-06-25 08:43:54.710 . Skipped packets 2024-06-25 08:43:54.710 < Type: SSH_FXP_STATUS, Size: 29, Number: 922640 2024-06-25 08:43:54.710 < 65,00,0E,14,10,00,00,00,02,00,00,00,0C,4E,6F,20,73,75,63,68,20,66,69,6C,65, 2024-06-25 08:43:54.710 < 00,00,00,00, 2024-06-25 08:43:54.710 < Status code: 2, Message: 922640, Server: No such file, Language:

ssvine commented 1 week ago

Seems unrelated to NetBox. SSH_FXP_STATUS - it's the response from the sftp server. Try to check the remote end

relictMarauder commented 1 week ago

The are no such problems with old versions of NetBox(2.4.x) and WinScp

Log from WinSCP:

. 2024-06-26 19:50:58.275 WinSCP Version 6.3.4 (Build 14955 2024-06-17) (OS 10.0.22631 – Windows 10 Enterprise)
. 2024-06-26 19:50:58.275 Configuration: HKCU\Software\Martin Prikryl\WinSCP 2\
. 2024-06-26 19:50:58.275 Log level: Debug 2
. 2024-06-26 19:50:58.275 Local account: RELICT-PC\Relict
. 2024-06-26 19:50:58.275 Working directory: C:\Program Files (x86)\WinSCP
. 2024-06-26 19:50:58.275 Process ID: 52488
. 2024-06-26 19:50:58.286 Ancestor processes: explorer, ...
. 2024-06-26 19:50:58.286 Command-line: "C:\Program Files (x86)\WinSCP\WinSCP.exe" 
. 2024-06-26 19:50:58.286 Time zone: Current: GMT+2, Standard: GMT+1 (Mitteleuropäische Zeit), DST: GMT+2 (Mitteleuropäische Sommerzeit), DST Start: 31.03.2024, DST End: 27.10.2024
. 2024-06-26 19:50:58.286 Login time: Mittwoch, 26. Juni 2024 19:50:58
. 2024-06-26 19:50:58.286 --------------------------------------------------------------------------
. 2024-06-26 19:50:58.286 Session name: admi@192.168.xxx.xxx (Ad-Hoc site)
. 2024-06-26 19:50:58.286 Host name: 192.168.xxx.xxx (Port: 22)
. 2024-06-26 19:50:58.286 User name: admi (Password: No, Key file: Yes, Passphrase: No)
. 2024-06-26 19:50:58.286 Tunnel: No
. 2024-06-26 19:50:58.286 Transfer Protocol: SFTP (SCP)
. 2024-06-26 19:50:58.286 Ping type: Off, Ping interval: 30 sec; Timeout: 15 sec
. 2024-06-26 19:50:58.286 Disable Nagle: No
. 2024-06-26 19:50:58.286 Proxy: None
. 2024-06-26 19:50:58.286 Send buffer: 262144
. 2024-06-26 19:50:58.286 Compression: No
. 2024-06-26 19:50:58.286 Bypass authentication: No
. 2024-06-26 19:50:58.286 Try agent: Yes; Agent forwarding: No; KI: Yes; GSSAPI: Yes
. 2024-06-26 19:50:58.286 GSSAPI: KEX: No; Forwarding: No; Libs: gssapi32,sspi,custom; Custom: 
. 2024-06-26 19:50:58.286 Ciphers: aes,chacha20,aesgcm,3des,WARN,des,blowfish,arcfour; Ssh2DES: No
. 2024-06-26 19:50:58.286 KEX: ntru-curve25519,ecdh,dh-gex-sha1,dh-group18-sha512,dh-group17-sha512,dh-group16-sha512,dh-group15-sha512,dh-group14-sha1,rsa,WARN,dh-group1-sha1
. 2024-06-26 19:50:58.286 SSH Bugs: Auto,Auto,Auto,Auto,Auto,Auto,Auto,Auto,Auto,Auto
. 2024-06-26 19:50:58.286 Simple channel: Yes
. 2024-06-26 19:50:58.286 Return code variable: Autodetect; Lookup user groups: Auto
. 2024-06-26 19:50:58.286 Shell: default
. 2024-06-26 19:50:58.286 EOL: LF, UTF: Auto
. 2024-06-26 19:50:58.286 Clear aliases: Yes, Unset nat.vars: Yes, Resolve symlinks: Yes; Follow directory symlinks: No
. 2024-06-26 19:50:58.286 LS: ls -la, Ign LS warn: Yes, Scp1 Comp: No; Exit code 1 is error: No
. 2024-06-26 19:50:58.286 SFTP Bugs: Auto,Auto
. 2024-06-26 19:50:58.286 SFTP Server: default
. 2024-06-26 19:50:58.286 Local directory: default, Remote directory: home, Update: Yes, Cache: Yes
. 2024-06-26 19:50:58.286 Cache directory changes: Yes, Permanent: Yes
. 2024-06-26 19:50:58.286 Recycle bin: Delete to: No, Overwritten to: No, Bin path: 
. 2024-06-26 19:50:58.286 DST mode: Unix
. 2024-06-26 19:50:58.286 --------------------------------------------------------------------------
. 2024-06-26 19:50:58.311 Looking up host "192.168.xxx.xxx" for SSH connection
. 2024-06-26 19:50:58.311 Connecting to 192.168.xxx.xxx port 22
. 2024-06-26 19:50:58.311 Connected to 192.168.xxx.xxx
. 2024-06-26 19:50:58.311 Selecting events 63 for socket 3036
. 2024-06-26 19:50:58.339 Waiting for the server to continue with the initialization
. 2024-06-26 19:50:58.339 Looking for incoming data
. 2024-06-26 19:50:58.339 Looking for network events
. 2024-06-26 19:50:58.339 We claim version: SSH-2.0-WinSCP_release_6.3.4
. 2024-06-26 19:50:58.339 Detected network event
. 2024-06-26 19:50:58.339 Enumerating network events for socket 3036
. 2024-06-26 19:50:58.339 Enumerated 19 network events making 19 cumulative events for socket 3036
. 2024-06-26 19:50:58.339 Handling network write event on socket 3036 with error 0
. 2024-06-26 19:50:58.339 Handling network connect event on socket 3036 with error 0
. 2024-06-26 19:50:58.339 Connected to 192.168.xxx.xxx
. 2024-06-26 19:50:58.339 Handling network read event on socket 3036 with error 0
. 2024-06-26 19:50:58.339 Waiting for the server to continue with the initialization
. 2024-06-26 19:50:58.339 Looking for incoming data
. 2024-06-26 19:50:58.339 Looking for network events
. 2024-06-26 19:50:58.339 Remote version: SSH-2.0-OpenSSH_8.0
. 2024-06-26 19:50:58.339 Using SSH protocol version 2
. 2024-06-26 19:50:58.339 Have a known host key of type rsa2
. 2024-06-26 19:50:58.339 Detected network event
. 2024-06-26 19:50:58.339 Enumerating network events for socket 3036
. 2024-06-26 19:50:58.339 Enumerated 1 network events making 1 cumulative events for socket 3036
. 2024-06-26 19:50:58.339 Handling network read event on socket 3036 with error 0
. 2024-06-26 19:50:58.339 Waiting for the server to continue with the initialization
. 2024-06-26 19:50:58.339 Looking for incoming data
. 2024-06-26 19:50:58.339 Looking for network events
. 2024-06-26 19:50:58.343 Doing ECDH key exchange with curve Curve25519, using hash SHA-256
. 2024-06-26 19:50:58.352 Detected network event
. 2024-06-26 19:50:58.352 Enumerating network events for socket 3036
. 2024-06-26 19:50:58.352 Enumerated 1 network events making 1 cumulative events for socket 3036
. 2024-06-26 19:50:58.352 Handling network read event on socket 3036 with error 0
. 2024-06-26 19:50:58.352 Waiting for the server to continue with the initialization
. 2024-06-26 19:50:58.352 Looking for incoming data
. 2024-06-26 19:50:58.352 Looking for network events
....

. 2024-06-26 19:51:32.882 Creating directory "12".
. 2024-06-26 19:51:32.882 Canonifying: "12"
. 2024-06-26 19:51:32.882 Getting real path for '/share/CACHEDEV1_DATA/Download/Kodi/12'
> 2024-06-26 19:51:32.882 Type: SSH_FXP_REALPATH, Size: 47, Number: 23568
> 2024-06-26 19:51:32.882 10,00,00,5C,10,00,00,00,26,2F,73,68,61,72,65,2F,43,41,43,48,45,44,45,56,31,
> 2024-06-26 19:51:32.882 5F,44,41,54,41,2F,44,6F,77,6E,6C,6F,61,64,2F,4B,6F,64,69,2F,31,32,
. 2024-06-26 19:51:32.882 Sent 51 bytes
. 2024-06-26 19:51:32.882 There are 0 bytes remaining in the send buffer
. 2024-06-26 19:51:32.882 Looking for network events
. 2024-06-26 19:51:32.888 Timeout waiting for network events
. 2024-06-26 19:51:32.888 Read 4 bytes (24 pending)
. 2024-06-26 19:51:32.888 Read 24 bytes (0 pending)
< 2024-06-26 19:51:32.888 Type: SSH_FXP_STATUS, Size: 24, Number: 23044
< 2024-06-26 19:51:32.888 65,00,00,5A,04,00,00,00,00,00,00,00,07,53,75,63,63,65,73,73,00,00,00,00,
. 2024-06-26 19:51:32.888 Discarding reserved response
. 2024-06-26 19:51:32.888 Waiting for another 4 bytes
. 2024-06-26 19:51:32.888 Looking for incoming data
. 2024-06-26 19:51:32.888 Looking for network events
. 2024-06-26 19:51:32.888 Detected network event
. 2024-06-26 19:51:32.888 Enumerating network events for socket 2096
. 2024-06-26 19:51:32.888 Enumerated 1 network events making 1 cumulative events for socket 2096
. 2024-06-26 19:51:32.888 Handling network read event on socket 2096 with error 0
. 2024-06-26 19:51:32.888 Waiting for another 4 bytes
. 2024-06-26 19:51:32.888 Looking for incoming data
. 2024-06-26 19:51:32.888 Looking for network events
. 2024-06-26 19:51:32.888 Received 33 bytes
. 2024-06-26 19:51:32.888 Timeout waiting for network events
. 2024-06-26 19:51:32.888 Read 4 bytes (29 pending)
. 2024-06-26 19:51:32.888 Read 29 bytes (0 pending)
< 2024-06-26 19:51:32.888 Type: SSH_FXP_STATUS, Size: 29, Number: 23568
< 2024-06-26 19:51:32.888 65,00,00,5C,10,00,00,00,02,00,00,00,0C,4E,6F,20,73,75,63,68,20,66,69,6C,65,
< 2024-06-26 19:51:32.888 00,00,00,00,
< 2024-06-26 19:51:32.888 Status code: 2, Message: 23568, Server: No such file, Language:  
. 2024-06-26 19:51:32.888 Getting real path for '/share/CACHEDEV1_DATA/Download/Kodi/'
> 2024-06-26 19:51:32.888 Type: SSH_FXP_REALPATH, Size: 45, Number: 23824
> 2024-06-26 19:51:32.888 10,00,00,5D,10,00,00,00,24,2F,73,68,61,72,65,2F,43,41,43,48,45,44,45,56,31,
> 2024-06-26 19:51:32.888 5F,44,41,54,41,2F,44,6F,77,6E,6C,6F,61,64,2F,4B,6F,64,69,2F,
. 2024-06-26 19:51:32.888 Sent 49 bytes
. 2024-06-26 19:51:32.888 There are 0 bytes remaining in the send buffer
. 2024-06-26 19:51:32.888 Looking for network events
. 2024-06-26 19:51:32.888 Timeout waiting for network events
. 2024-06-26 19:51:32.888 Waiting for another 4 bytes
. 2024-06-26 19:51:32.888 Looking for incoming data
. 2024-06-26 19:51:32.888 Looking for network events
. 2024-06-26 19:51:32.888 Detected network event
. 2024-06-26 19:51:32.888 Enumerating network events for socket 2096
. 2024-06-26 19:51:32.888 Enumerated 1 network events making 1 cumulative events for socket 2096
. 2024-06-26 19:51:32.888 Handling network read event on socket 2096 with error 0
. 2024-06-26 19:51:32.888 Waiting for another 4 bytes
. 2024-06-26 19:51:32.888 Looking for incoming data
. 2024-06-26 19:51:32.888 Looking for network events
. 2024-06-26 19:51:32.888 Received 95 bytes
. 2024-06-26 19:51:32.888 Timeout waiting for network events
. 2024-06-26 19:51:32.888 Read 4 bytes (91 pending)
. 2024-06-26 19:51:32.888 Read 91 bytes (0 pending)
< 2024-06-26 19:51:32.888 Type: SSH_FXP_NAME, Size: 91, Number: 23824
< 2024-06-26 19:51:32.888 68,00,00,5D,10,00,00,00,01,00,00,00,23,2F,73,68,61,72,65,2F,43,41,43,48,45,
< 2024-06-26 19:51:32.888 44,45,56,31,5F,44,41,54,41,2F,44,6F,77,6E,6C,6F,61,64,2F,4B,6F,64,69,00,00,
< 2024-06-26 19:51:32.888 00,23,2F,73,68,61,72,65,2F,43,41,43,48,45,44,45,56,31,5F,44,41,54,41,2F,44,
< 2024-06-26 19:51:32.888 6F,77,6E,6C,6F,61,64,2F,4B,6F,64,69,00,00,00,00,
. 2024-06-26 19:51:32.888 Real path is '/share/CACHEDEV1_DATA/Download/Kodi'
. 2024-06-26 19:51:32.888 Canonified: "/share/CACHEDEV1_DATA/Download/Kodi/12"
> 2024-06-26 19:51:32.888 Type: SSH_FXP_MKDIR, Size: 51, Number: 23310
> 2024-06-26 19:51:32.888 0E,00,00,5B,0E,00,00,00,26,2F,73,68,61,72,65,2F,43,41,43,48,45,44,45,56,31,
> 2024-06-26 19:51:32.888 5F,44,41,54,41,2F,44,6F,77,6E,6C,6F,61,64,2F,4B,6F,64,69,2F,31,32,00,00,00,
> 2024-06-26 19:51:32.888 00,
ssvine commented 1 week ago

Can you provide the full log? The first one is creepy enough with time going back (you create folder at 08:43:54.709 before opening the connection at 08:46:19.918). Also, users are different.

Does this problem occur in any directories, e.g. in /tmp, or only in /share/CACHEDEV1_DATA/Download/Kodi? Does your path have any symlinks? You can try to set [x] Resolve symbolic links option.

For now I cannot reproduce your problem, so it's better to provide a minimal reproducible example.

relictMarauder commented 1 week ago

Thank you for analyse. I can reproduce same behavior for all folders hier is full log for one folder in /tmp by trying to create a subfloder over NetBox -> folder can't be created net-box.log hier is full log for one folder in /tmp by trying to create a subfloder over WinScp(same user/server as for NetBox) -> folder can be created the are not winscp.log synmlinks in whole path

ssvine commented 1 week ago

Still cannot reproduce the problem. Does NetBox show any error messages?

Have you tried to reproduce the problem on other servers?

Have you tried to use different windows machine with fresh far installation when connecting to the problematic server?

Can you export netbox session and show it here (use F5 key from the session list)?

relictMarauder commented 1 week ago

Hi i looked deeply in differences between WinScp and NetBox at places which are envolwed in this use case and found this place:

WinScp(https://github.com/winscp/winscp/blob/d7286a7ae7d7911c2e5dc41c47f2b93c73d905d2/source/core/Terminal.cpp):

void __fastcall TTerminal::DoCreateDirectory(const UnicodeString & DirName, bool Encrypt)
{
  TRetryOperationLoop RetryLoop(this);
  do
  {
    TMkdirSessionAction Action(ActionLog, AbsolutePath(DirName, true));
    try
    {
      DebugAssert(FFileSystem);
      FFileSystem->CreateDirectory(DirName, Encrypt);
    }
    catch(Exception & E)
    {
      RetryLoop.Error(E, Action, FMTLOAD(CREATE_DIR_ERROR, (DirName)));
    }
  }
  while (RetryLoop.Retry());
}

NetBox(https://github.com/michaellukashov/Far-NetBox/blob/7c7a41c04e98151c568639f3c76cf0ecda71ce7f/src/core/Terminal.cpp):

void TTerminal::DoCreateDirectory(const UnicodeString & ADirName, bool Encrypt)
{
  TRetryOperationLoop RetryLoop(this);
  do
  {
    TMkdirSessionAction Action(GetActionLog(), GetAbsolutePath(ADirName, false));
    try
    {
      DebugAssert(FFileSystem);
      // DEBUG_PRINTF("ADirName: %s", ADirName);
      FFileSystem->CreateDirectory(ADirName, Encrypt);
    }
    catch(Exception & E)
    {
      RetryLoop.Error(E, Action, FMTLOAD(CREATE_DIR_ERROR, ADirName));
    }
  }
  while (RetryLoop.Retry());
}

The difference is in second parameter in the call of AbsolutePath function. NetScp use 'false' and WinScp use 'true'

This difference seems to produce the exception by calling GetAbsolutePath, becouse the ADirName is not exist at this time.

After i change this param from "false" to "true" this problem could not be reproduced any more.

I hope this helps.

nextbox-session:

xxxxx-qnap@admin.netbox.txt

ssvine commented 1 week ago

Thanks, I'll check your findings