Re: [Proftpd-user] MOD_SFTP failing first upload attempt
Cosmin Neagu via Proftp-user <[email protected]> Mon, 27 Jun 2022 10:07:39 +0300
| Newsgroups | gmane.network.proftpd.user |
|---|---|
| Message-ID | <CAA8U1-9-11XsvHGn_ZvEn-a_0RAYSRzvamDjaumEJiANmc3qww@mail.gmail.com> |
Hi TJ,
Thanks for answering back. Seems like this user lists cuts of the message
if it's too long, I had all the outputs attached.
But after 3 days of googling around, I was kind of convinced as well that
is was an SFTP issue, and I found the fix on the documentation page of
mod_sftp: http://proftpd.org/docs/contrib/mod_sftp.html#SFTPOptions
This is what had to be added to make it work:
ubuntu@FTP-PROD1:~$ cat /opt/proftpd-sftp/etc/proftpd.conf | grep SFTPOption
*SFTPOptions IgnoreSFTPUploadPerms*
Seems like sftp client on linux is using some kind of Upload
permissions and that gives that Permission denied results.
One last question, would be, are there any security concerns I should be
aware of when SFTPUploadPerms are Ignored? Not sure exactly what
that option does, meaning what kind of permissions are ignored, not
documented under the mod_sftp page.
I'm attaching the last part of my initial message that was cut off.
*---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
2022-06-23 12:43:24,477 FTP-PROD1 proftpd[45863] 172.18.128.128
(13.48.243.90[13.48.243.90]): dispatching LOG_CMD_ERR command 'STOR
/check_nrpe.log' to mod_sql
2022-06-23 12:43:24,477 FTP-PROD1 proftpd[45863] 172.18.128.128
(13.48.243.90[13.48.243.90]): dispatching LOG_CMD_ERR command 'STOR
/check_nrpe.log' to mod_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 LOG_CMD_ERR command 'STOR
/check_nrpe.log' to mod_xfer
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 'OPEN
/check_nrpe.log' to mod_sql
2022-06-23 12:43:24,477 FTP-PROD1 proftpd[45863] 172.18.128.128
(13.48.243.90[13.48.243.90]): dispatching LOG_CMD_ERR command 'OPEN
/check_nrpe.log' to mod_sql
2022-06-23 12:43:24,477 FTP-PROD1 proftpd[45863] 172.18.128.128
(13.48.243.90[13.48.243.90]): dispatching LOG_CMD_ERR command 'OPEN
/check_nrpe.log' to mod_log
*---second attempt ok.*
2022-06-23 12:43:27,034 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:27,034 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:27,034 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:27,034 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:27,034 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 0066)
2022-06-23 12:43:27,035 FTP-PROD1 proftpd[45863] 172.18.128.128
(13.48.243.90[13.48.243.90]): dispatching POST_CMD command 'OPEN
/check_nrpe.log' to mod_sql
2022-06-23 12:43:27,035 FTP-PROD1 proftpd[45863] 172.18.128.128
(13.48.243.90[13.48.243.90]): dispatching LOG_CMD command 'OPEN
/check_nrpe.log' to mod_sql
2022-06-23 12:43:27,035 FTP-PROD1 proftpd[45863] 172.18.128.128
(13.48.243.90[13.48.243.90]): dispatching LOG_CMD command 'OPEN
/check_nrpe.log' to mod_log
2022-06-23 12:43:27,035 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:27,035 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 0066)
2022-06-23 12:43:27,035 FTP-PROD1 proftpd[45863] 172.18.128.128
(13.48.243.90[13.48.243.90]): dispatching POST_CMD command 'WRITE
eb2a339c8a841268 0 931' to mod_sql
2022-06-23 12:43:27,035 FTP-PROD1 proftpd[45863] 172.18.128.128
(13.48.243.90[13.48.243.90]): dispatching LOG_CMD command 'WRITE
eb2a339c8a841268 0 931' to mod_sql
2022-06-23 12:43:27,035 FTP-PROD1 proftpd[45863] 172.18.128.128
(13.48.243.90[13.48.243.90]): dispatching LOG_CMD command 'WRITE
eb2a339c8a841268 0 931' to mod_log
2022-06-23 12:43:27,046 FTP-PROD1 proftpd[45863] 172.18.128.128
(13.48.243.90[13.48.243.90]): dispatching POST_CMD command 'STOR
/check_nrpe.log' to mod_sql
2022-06-23 12:43:27,046 FTP-PROD1 proftpd[45863] 172.18.128.128
(13.48.243.90[13.48.243.90]): dispatching POST_CMD command 'STOR
/check_nrpe.log' to mod_sql
2022-06-23 12:43:27,046 FTP-PROD1 proftpd[45863] 172.18.128.128
(13.48.243.90[13.48.243.90]): dispatching POST_CMD command 'STOR
/check_nrpe.log' to mod_xfer
2022-06-23 12:43:27,046 FTP-PROD1 proftpd[45863] 172.18.128.128
(13.48.243.90[13.48.243.90]): dispatching LOG_CMD command 'STOR
/check_nrpe.log' to mod_sql
2022-06-23 12:43:27,046 FTP-PROD1 proftpd[45863] 172.18.128.128
(13.48.243.90[13.48.243.90]): dispatching LOG_CMD command 'STOR
/check_nrpe.log' to mod_log
2022-06-23 12:43:27,046 FTP-PROD1 proftpd[45863] 172.18.128.128
(13.48.243.90[13.48.243.90]): dispatching LOG_CMD command 'STOR
/check_nrpe.log' to mod_xfer
2022-06-23 12:43:27,046 FTP-PROD1 proftpd[45863] 172.18.128.128
(13.48.243.90[13.48.243.90]): Transfer completed: 931 bytes in 0.01 seconds
2022-06-23 12:43:27,046 FTP-PROD1 proftpd[45863] 172.18.128.128
(13.48.243.90[13.48.243.90]): dispatching POST_CMD command 'CLOSE
eb2a339c8a841268' to mod_sql
2022-06-23 12:43:27,046 FTP-PROD1 proftpd[45863] 172.18.128.128
(13.48.243.90[13.48.243.90]): dispatching LOG_CMD command 'CLOSE
eb2a339c8a841268' to mod_sql
2022-06-23 12:43:27,046 FTP-PROD1 proftpd[45863] 172.18.128.128
(13.48.243.90[13.48.243.90]): dispatching LOG_CMD command 'CLOSE
eb2a339c8a841268' to mod_log
2022-06-23 12:43:29,710 FTP-PROD1 proftpd[45863] 172.18.128.128
(13.48.243.90[13.48.243.90]): dispatching LOG_CMD command 'CHANNEL_EOF' to
mod_sql
2022-06-23 12:43:29,710 FTP-PROD1 proftpd[45863] 172.18.128.128
(13.48.243.90[13.48.243.90]): dispatching LOG_CMD command 'CHANNEL_EOF' to
mod_log
2022-06-23 12:43:29,710 FTP-PROD1 proftpd[45863] 172.18.128.128
(13.48.243.90[13.48.243.90]): dispatching LOG_CMD command 'CHANNEL_CLOSE'
to mod_sql
2022-06-23 12:43:29,710 FTP-PROD1 proftpd[45863] 172.18.128.128
(13.48.243.90[13.48.243.90]): dispatching LOG_CMD command 'CHANNEL_CLOSE'
to mod_log
2022-06-23 12:43:29,710 FTP-PROD1 proftpd[45863] 172.18.128.128
(13.48.243.90[13.48.243.90]): mod_sftp/1.0.1: scrubbing 2 passphrases from
memory
2022-06-23 12:43:29,710 FTP-PROD1 proftpd[45863] 172.18.128.128
(13.48.243.90[13.48.243.90]): SSH2 session closed.
#My settings:
ubuntu@FTP-PROD1:/opt/proftpd-sftp/sbin$ ./proftpd -V
Compile-time Settings:
Version: 1.3.7d (maint)
Platform: LINUX [Linux 5.13.0-1031-aws x86_64]
Built: Wed Jun 15 2022 10:05:45 UTC
Built With:
configure '--prefix=/opt/proftpd-sftp' '--enable-openssl'
'--with-modules=mod_sql:mod_sql_mysql:mod_sftp:mod_unique_id'
'--with-includes=/usr/include/mysql/'
'--with-libraries=/usr/lib/x86_64-linux-gnu'
CFLAGS: -g2 -O2 -Wall -fno-omit-frame-pointer -fno-strict-aliasing
LDFLAGS: -L$(top_srcdir)/lib -L$(top_builddir)/lib -rdynamic
-L/usr/lib/x86_64-linux-gnu -L/usr/lib/x86_64-linux-gnu
LIBS: -lssl -lcrypto -lm -lmysqlclient -lz -lcrypto -lsupp -lcrypt -ldl
-pthread
Files:
Configuration File:
/opt/proftpd-sftp/etc/proftpd.conf
Pid File:
/opt/proftpd-sftp/var/proftpd.pid
Scoreboard File:
/opt/proftpd-sftp/var/proftpd.scoreboard
Info:
+ Max supported UID: 4294967295
+ Max supported GID: 4294967295
Features:
- Autoshadow support
- Controls support
+ curses support
- Developer support
- DSO support
+ IPv6 support
+ Largefile support
- Lastlog support
- Memcache support
+ ncurses support
- NLS support
+ OpenSSL support (OpenSSL 1.1.1f 31 Mar 2020)
- PCRE support
- POSIX ACL support
- Redis support
+ Sendfile support
+ Shadow file support
- Sodium support
+ Trace support
+ xattr support
Tunable Options:
PR_TUNABLE_BUFFER_SIZE = 1024
PR_TUNABLE_DEFAULT_RCVBUFSZ = 8192
PR_TUNABLE_DEFAULT_SNDBUFSZ = 8192
PR_TUNABLE_ENV_MAX = 2048
PR_TUNABLE_GLOBBING_MAX_MATCHES = 100000
PR_TUNABLE_GLOBBING_MAX_RECURSION = 8
PR_TUNABLE_HASH_TABLE_SIZE = 40
PR_TUNABLE_LOGIN_MAX = 256
PR_TUNABLE_NEW_POOL_SIZE = 512
PR_TUNABLE_PATH_MAX = 4096
PR_TUNABLE_SCOREBOARD_BUFFER_SIZE = 80
PR_TUNABLE_SCOREBOARD_SCRUB_TIMER = 30
PR_TUNABLE_SELECT_TIMEOUT = 30
PR_TUNABLE_TIMEOUTIDENT = 10
PR_TUNABLE_TIMEOUTIDLE = 600
PR_TUNABLE_TIMEOUTLINGER = 10
PR_TUNABLE_TIMEOUTLOGIN = 300
PR_TUNABLE_TIMEOUTNOXFER = 300
PR_TUNABLE_TIMEOUTSTALLED = 3600
PR_TUNABLE_XFER_SCOREBOARD_UPDATES = 10
#My config file
ubuntu@FTP-PROD1:/opt/proftpd-sftp/etc$ cat proftpd.conf
DisplayConnect /opt/proftpd-sftp/etc/DisplayConnect
DisplayQuit /opt/proftpd-sftp/etc/DisplayQuit
DisplayLogin /opt/proftpd-sftp/etc/DisplayLogin
ServerIdent on "XXXX"
ServerName "XXXX"
UseReverseDNS off
MaxInstances 1000
MaxClients 999 "Max Clients reached!"
MaxClientsPerHost 50 "Max Clients per Host reached!"
MaxClientsPerUser 50 "Max Client per User reached!"
MaxLoginAttempts 3
TimeoutLogin 120
TimeoutIdle 300
TimeoutNoTransfer 300
TimeoutStalled 300
ServerType standalone
DefaultServer on
UseIPv6 off
Umask 066 077
User nobody
Group nogroup
DefaultRoot ~
AllowOverwrite on
AuthOrder mod_sql.c
SQLAuthenticate users
SQLConnectInfo PROFTPD@XXX XXX XXX
SQLUserInfo USERS USER PASS UID GID DIR NULL
SQLUserWhereClause "SFTP=1"
#SQLLogFile /var/log/proftpd/sftp-sql.log
SQLAuthTypes Crypt
SQLMinID 1999
SQLDefaultGID 2000
SQLLog PASS updatecount
SQLNamedQuery updatecount UPDATE "COUNT=COUNT+1,LAST=now() WHERE USER='%u'"
USERS
CreateHome on
<IfModule mod_unique_id.c>
LogFormat logformat "%{%Y-%m-%d %H:%M:%S}t.%{millisecs} %{UNIQUE_ID}e %a
%{remote-port} %u \"%r\" %s %S %bbytes %Tsec %{transfer-status}
%{transfer-type} %{protocol}"
ExtendedLog /var/log/proftpd/sftp-extended.log
AUTH,INFO,DIRS,READ,WRITE,MISC,SEC,EXIT logformat
</IfModule>
<IfModule mod_sftp.c>
Port 22
SFTPEngine on
SFTPHostKey /opt/proftpd-sftp/etc/sftp.azets.com.rsa.key
SFTPHostKey /opt/proftpd-sftp/etc/sftp.azets.com.ecdsa.key
SFTPAuthorizedUserKeys file:~/.sftp/authorized_keys
</IfModule>
<Limit SITE_CHMOD>
DenyAll
</Limit>
Best regards,
*Cosmin Neagu*
On Sat, Jun 25, 2022 at 2:46 AM TJ Saunders <[email protected]> wrote:
>
> > 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
>
_______________________________________________
ProFTPD Users List <[email protected]>
Unsubscribe problems?
http://www.proftpd.org/list-unsub.html