Re: [Proftpd-user] MOD_SFTP failing first upload attempt

> I run multiple tests, and the only way to have the file successfully 
> uploaded is to have the file already present on SFTP server.
> I don't have this problem if I use another FTP client (like filezilla), 
> only with sftp (on ubuntu).

Which version of OpenSSH is being used?  I ask because this behavior seems to be related to the client implementation, and what it does.  Doing a "put filename" twice, where it fails one time and succeeds the next, suggests that the client is doing something different behind your back...

> 2022-06-23 12:43:00,843 FTP-PROD1 proftpd[45863] 172.18.128.128 
> (13.48.243.90[13.48.243.90]): retrieved UID 2001 for user 'cosmin'
> 2022-06-23 12:43:00,843 FTP-PROD1 proftpd[45863] 172.18.128.128 
> (13.48.243.90[13.48.243.90]): RELINQUISH PRIVS at auth.c:168
> 2022-06-23 12:43:00,843 FTP-PROD1 proftpd[45863] 172.18.128.128 
> (13.48.243.90[13.48.243.90]): set TZ environment variable to 'UTC'
> 2022-06-23 12:43:00,843 FTP-PROD1 proftpd[45863] 172.18.128.128 
> (13.48.243.90[13.48.243.90]): Preparing to chroot to directory 
> '/FTP/cosmin'

Here, we see that the session is chrooted to the "/FTP/cosmin/" directory.  That means that, on the client, "/" will map to "/FTP/cosmin/" on the server.  This is expected.

> 2022-06-23 12:43:00,849 FTP-PROD1 proftpd[45863] 172.18.128.128 
> (13.48.243.90[13.48.243.90]): dispatching PRE_CMD command 'REALPATH .' 
> to mod_core
> 2022-06-23 12:43:00,849 FTP-PROD1 proftpd[45863] 172.18.128.128 
> (13.48.243.90[13.48.243.90]): dispatching PRE_CMD command 'REALPATH .' 
> to mod_core
> 2022-06-23 12:43:00,849 FTP-PROD1 proftpd[45863] 172.18.128.128 
> (13.48.243.90[13.48.243.90]): in dir_check_full(): path = '/', fullpath 
> = '/FTP/cosmin/'

Here, the client is sending the REALPATH SFTP request; it's a way to ask the server "what's the absolute path, given this '.' relative path?".  I wonder if this is where things get tricky, and where we'll want to see just what the client does with this REALPATH response.

> *---first attempt failed*

> 2022-06-23 12:43:24,462 FTP-PROD1 proftpd[45863] 172.18.128.128 
> (13.48.243.90[13.48.243.90]): dispatching PRE_CMD command 'STOR 
> /check_nrpe.log' to mod_core
> 2022-06-23 12:43:24,462 FTP-PROD1 proftpd[45863] 172.18.128.128 
> (13.48.243.90[13.48.243.90]): dispatching PRE_CMD command 'STOR 
> /check_nrpe.log' to mod_core
> 2022-06-23 12:43:24,462 FTP-PROD1 proftpd[45863] 172.18.128.128 
> (13.48.243.90[13.48.243.90]): dispatching PRE_CMD command 'STOR 
> /check_nrpe.log' to mod_xfer
> 2022-06-23 12:43:24,465 FTP-PROD1 proftpd[45863] 172.18.128.128 
> (13.48.243.90[13.48.243.90]): in dir_check_full(): path = 
> '/check_nrpe.log', fullpath = '/FTP/cosmin/check_nrpe.log'
> 2022-06-23 12:43:24,465 FTP-PROD1 proftpd[45863] 172.18.128.128 
> (13.48.243.90[13.48.243.90]): in dir_check_full(): setting umask to 
> 0066 (was 0077)
> 2022-06-23 12:43:24,475 FTP-PROD1 proftpd[45863] 172.18.128.128 
> (13.48.243.90[13.48.243.90]): in dir_check_full(): path = 
> '/check_nrpe.log', fullpath = '/FTP/cosmin/check_nrpe.log'
> 2022-06-23 12:43:24,477 FTP-PROD1 proftpd[45863] 172.18.128.128 
> (13.48.243.90[13.48.243.90]): dispatching POST_CMD_ERR command 'STOR 
> /check_nrpe.log' to mod_sql

Here, we see the client attempting to upload

What's missing from these logs are the entries for the SFTP OPEN requests; the debug logging for OPEN requests should tell us the exact path that the client is sending.  I suspect there's a difference between the first and second OPEN requests -- looking through the logs (perhaps using debug level 10, and/or the SFTPLog) can show whether this is, in fact, the case or not.  Would it be possible to get that info?

Cheers,
TJ


_______________________________________________
ProFTPD Users List   <[email protected]>
Unsubscribe problems?
http://www.proftpd.org/list-unsub.html