Can't understand logfile

Hi,

i use WinSCP very often and normally i have no problem. But
sometimes i get some errors, but i am not able to interpret the
logfile. Perhaps somebody can help me.

In the logfile below i got an error, but i don't know what's the
real problem. The connection to the server is established, but
then something goes wrong. The error and request infos are not
helpful to me (Error code: 2, Request code: 3). He can not find
the directory, but i don't understand why. Of course i am sure
that the directory exists.

Please, can somebody explain it to me.

Thanks for help
Ron


. 2007-10-06 00:30:10.609 --------------------------------------------------------------------------
. 2007-10-06 00:30:10.609 WinSCP Version 3.8.2 (Build 330) (OS 5.2.3790 Service Pack 1)
. 2007-10-06 00:30:10.609 Login time: Samstag, 6. Oktober 2007 00:30:10
. 2007-10-06 00:30:10.609 --------------------------------------------------------------------------
. 2007-10-06 00:30:10.609 Session name: edi_pfi
. 2007-10-06 00:30:10.609 Host name: xyzhost (Port: 22)
. 2007-10-06 00:30:10.609 User name: edi (Password: Yes, Key file: No)
. 2007-10-06 00:30:10.609 Transfer Protocol: SFTP
. 2007-10-06 00:30:10.609 SSH protocol version: 2; Compression: No
. 2007-10-06 00:30:10.609 Agent forwarding: No; TIS/CryptoCard: No; KI: Yes; GSSAPI: No
. 2007-10-06 00:30:10.609 Ciphers: aes,blowfish,3des,WARN,des; Ssh2DES: No
. 2007-10-06 00:30:10.609 Ping type: -, Ping interval: 30 sec; Timeout: 15 sec
. 2007-10-06 00:30:10.609 SSH Bugs: -,-,-,-,-,-,-,-
. 2007-10-06 00:30:10.609 SFTP Bugs: -,-,-
. 2007-10-06 00:30:10.609 Proxy: none
. 2007-10-06 00:30:10.609 Return code variable: Autodetect; Lookup user groups: Yes
. 2007-10-06 00:30:10.609 Shell: default, EOL: 0
. 2007-10-06 00:30:10.609 Local directory: C:\sftp_rah, Remote directory: /tmp/sap/idoc/in/, Update: No, Cache: Yes
. 2007-10-06 00:30:10.609 Cache directory changes: Yes, Permanent: Yes
. 2007-10-06 00:30:10.609 Clear aliases: Yes, Unset nat.vars: Yes, Resolve symlinks: Yes
. 2007-10-06 00:30:10.609 Alias LS: No, Ign LS warn: Yes, Scp1 Comp: No
. 2007-10-06 00:30:10.609 --------------------------------------------------------------------------
. 2007-10-06 00:30:10.609 Looking up host "xyzhost"
. 2007-10-06 00:30:10.671 Connecting to 192.168.3.14 port 22
. 2007-10-06 00:30:10.687 Server version: SSH-2.0-OpenSSH_4.4p1-hpn12v11
. 2007-10-06 00:30:10.687 We claim version: SSH-2.0-WinSCP_release_3.8.2
. 2007-10-06 00:30:10.687 Using SSH protocol version 2
. 2007-10-06 00:30:10.687 Doing Diffie-Hellman group exchange
. 2007-10-06 00:30:10.843 Doing Diffie-Hellman key exchange
. 2007-10-06 00:30:10.984 Host key fingerprint is:
. 2007-10-06 00:30:10.984 ssh-rsa 1024 ...
. 2007-10-06 00:30:10.984 Initialised AES-256 client->server encryption
. 2007-10-06 00:30:10.984 Initialised HMAC-SHA1 client->server MAC algorithm
. 2007-10-06 00:30:10.984 Initialised AES-256 server->client encryption
. 2007-10-06 00:30:10.984 Initialised HMAC-SHA1 server->client MAC algorithm
! 2007-10-06 00:30:11.078 Using username "edi".
! 2007-10-06 00:30:11.125 Using keyboard-interactive authentication.
. 2007-10-06 00:30:11.125 Password: prompt from server
. 2007-10-06 00:30:11.125 Responding with stored password.
! 2007-10-06 00:30:11.125 Authenticating with pre-entered password.
. 2007-10-06 00:30:11.140 Access granted
. 2007-10-06 00:30:11.187 Opened channel for session
. 2007-10-06 00:30:11.187 Started a shell/command
. 2007-10-06 00:30:11.187 --------------------------------------------------------------------------
. 2007-10-06 00:30:11.203 Using SFTP protocol.
. 2007-10-06 00:30:11.203 Doing startup conversation with host.
> 2007-10-06 00:30:11.218 Type: SSH_FXP_INIT, Size: 5, Number: -1
< 2007-10-06 00:30:11.250 Type: SSH_FXP_VERSION, Size: 5, Number: -1
. 2007-10-06 00:30:11.250 SFTP version 3 negotiated.
. 2007-10-06 00:30:11.250 We believe the server has signed timestamps bug
. 2007-10-06 00:30:11.250 We will use UTF-8 strings for status messages only
. 2007-10-06 00:30:11.250 Limiting packet size to OpenSSH limit of 262148 bytes
. 2007-10-06 00:30:11.265 Changing directory to "/tmp/sap/idoc/in/".
. 2007-10-06 00:30:11.265 Getting real path for '/tmp/sap/idoc/in/'
> 2007-10-06 00:30:11.265 Type: SSH_FXP_REALPATH, Size: 26, Number: 16
< 2007-10-06 00:30:11.281 Type: SSH_FXP_STATUS, Size: 29, Number: 16
< 2007-10-06 00:30:11.281 Status/error code: 2, Message: 16, Server: No such file, Language:
* 2007-10-06 00:30:11.281 (ECommand) Error changing directory to '/tmp/sap/idoc/in/'.
* 2007-10-06 00:30:11.281 Cannot get real path for '/tmp/sap/idoc/in/'.
* 2007-10-06 00:30:11.281 No such file or directory.
* 2007-10-06 00:30:11.281 Error code: 2
* 2007-10-06 00:30:11.281 Error message from server: No such file
* 2007-10-06 00:30:11.281 Request code: 16
. 2007-10-06 00:30:11.296 Getting current directory name.
. 2007-10-06 00:30:11.296 Getting real path for '.'
> 2007-10-06 00:30:11.296 Type: SSH_FXP_REALPATH, Size: 10, Number: 272
< 2007-10-06 00:30:11.312 Type: SSH_FXP_NAME, Size: 39, Number: 272
. 2007-10-06 00:30:11.312 Real path is '/home/edi'
. 2007-10-06 00:30:11.312 Startup conversation with host finished.
. 2007-10-06 00:30:11.359 Copying 1 files/directories to remote directory "/tmp/sap/idoc/in/POS/"
. 2007-10-06 00:30:11.359 PrTime: Yes; PrRO: Yes; Rght: rw-r--r--; PrR: No (No); FnCs: N; RIC: 01; Resume: S (102400); CalcS: No; Mask: ACExport_Buchungsdaten_FI_AT_20071005.txt06102007003009.csv
. 2007-10-06 00:30:11.359 TM: A; ClAr: No; ExclM(No):
. 2007-10-06 00:30:11.359 AscM: *.*html; *.htm; *.txt; *.php*; *.cgi; *.c; *.cpp; *.h; *.pas; *.bas; *.tex; *.pl; .htaccess; *.xtml; *.css; *.cfg; *.ini; *.sh; *.xml
. 2007-10-06 00:30:11.359 File: "D:\txp\users\ediprod\syslog\files\a\6013"
. 2007-10-06 00:30:11.359 Copying "D:\txp\users\ediprod\syslog\files\a\6013" to remote directory started.
. 2007-10-06 00:30:11.359 Ascii transfer mode selected.
. 2007-10-06 00:30:11.359 Opening remote file.
> 2007-10-06 00:30:11.375 Type: SSH_FXP_OPEN, Size: 105, Number: 515
< 2007-10-06 00:30:11.375 Type: SSH_FXP_STATUS, Size: 29, Number: 515
< 2007-10-06 00:30:11.375 Status/error code: 2, Message: 515, Server: No such file, Language:
> 2007-10-06 00:30:11.375 Type: SSH_FXP_LSTAT, Size: 89, Number: 775
< 2007-10-06 00:30:11.375 Type: SSH_FXP_STATUS, Size: 29, Number: 775
< 2007-10-06 00:30:11.375 Status/error code: 2, Message: 775, Server: No such file, Language:
* 2007-10-06 00:30:11.421 (ETerminal) No such file or directory.
* 2007-10-06 00:30:11.421 Error code: 2
* 2007-10-06 00:30:11.421 Error message from server: No such file
* 2007-10-06 00:30:11.421 Request code: 3
. 2007-10-06 00:30:11.421 Asking user:
. 2007-10-06 00:30:11.421 Cannot create remote file '/tmp/sap/idoc/in/POS/ACExport_Buchungsdaten_FI_AT_20071005.txt06102007003009.csv'. ("No such file or directory.
. 2007-10-06 00:30:11.421 Error code: 2
. 2007-10-06 00:30:11.421 Error message from server: No such file
. 2007-10-06 00:30:11.421 Request code: 3")
* 2007-10-06 00:30:11.515 (EScpSkipFile) Cannot create remote file '/tmp/sap/idoc/in/POS/ACExport_Buchungsdaten_FI_AT_20071005.txt06102007003009.csv'.
* 2007-10-06 00:30:11.515 No such file or directory.
* 2007-10-06 00:30:11.515 Error code: 2
* 2007-10-06 00:30:11.515 Error message from server: No such file
* 2007-10-06 00:30:11.515 Request code: 3
. 2007-10-06 00:30:11.531 Closing connection.

Maybe filename is too long for the filesystem?

Hi,

no, that's not the problem. I transfer those files every day
with similar file names.

And i think the problem is earlier. I have the session edi_pfi
and in this session the i configured that the default remote
directory is "/tmp/sap/idoc/in/". First i connect to the server
with the session and it seems that he can't go into the remote
directory. The transfer of the file gets an error too, but it
is later in the logfile. Therefore in the first step he has a
problem which has nothing to do with the file or the filename.

. 2007-10-06 00:30:11.265 Getting real path for '/tmp/sap/idoc/in/'
> 2007-10-06 00:30:11.265 Type: SSH_FXP_REALPATH, Size: 26, Number: 16
< 2007-10-06 00:30:11.281 Type: SSH_FXP_STATUS, Size: 29, Number: 16
< 2007-10-06 00:30:11.281 Status/error code: 2, Message: 16, Server: No such file, Language:
* 2007-10-06 00:30:11.281 (ECommand) Error changing directory to '/tmp/sap/idoc/in/'.
* 2007-10-06 00:30:11.281 Cannot get real path for '/tmp/sap/idoc/in/'.
* 2007-10-06 00:30:11.281 No such file or directory.
* 2007-10-06 00:30:11.281 Error code: 2
* 2007-10-06 00:30:11.281 Error message from server: No such file

Kind regards
Ron

May I have a test account on the server? Are you sure you have read/execute permissions on all parent directories?

Hi,

a test account is not possible. The server is in my company and
we have security reasons.

I think the reason of the problem is not easy to find. And i think
WinSCP works fine. I use WinSCP to transfer many files per day
automatically (more than 1000 per day). I have aproximately 30
different types of files and the structure of the files and filenames
is always the same. The directories on the target-server are also
the same.

There are not many errors, i think i get 3 errors in a week. But i
don't know why. My assumption is, that the target-server sometimes
has a problem. Perhaps there is a running backup or something like
that. It seems that there are time spans in which the server has
more problems. But the error message "no such file" tells me nothing
about the real problem. In the servers-logfile is also nothing about
the real problem.

I don't know what to do now, but i will have a look at those
problems. Perhaps in a few month i know more about it.

Kind regards
Ron

Ron2 wrote:

But the error message "no such file" tells me nothing
about the real problem. In the servers-logfile is also nothing about
the real problem.

That's true. OpenSSH SFTP server has terrible error reporting :-(