SFTP error out on first upload.

[iamola]

I have noticed this for a while now. Over a year even.
When i connect using SFTP and i upload a document, i get a fail on the first upload. My FTP client (Transmit) would say ... make sure you have permission blah blah.
The second time i upload that same document it will then work.

Can anyone help?

[Jocko]

Hi iamola,

I have two questions:
- do you have only this error message at the first upload attempt on a session or at each file on its first upload attempt ?
- do you have also the error message if you use another ftp client (like filezilla which supports Mac OS X) ?

I think also transmit ftp client should have a debug level feature. Then what is the content of its log if you enable it.

[iamola]

I get this error.
This is from WHM backup in the FTP log.

2017-05-14 02:20:40,210 XXX.local proftpd[31108] 192.168.1.41 (XXX[XXX]): USER XXX: Login successful.
2017-05-14 02:20:40,280 mod_sftp/0.9.9[31108]: 'subsystem' channel request for 'sftp' subsystem
2017-05-14 02:20:40,282 mod_sftp/0.9.9[31108]: using SFTP protocol version 3 for this session (channel ID 0)
2017-05-14 02:20:41,139 mod_sftp/0.9.9[31108]: chmod of '/XXX/Backups/weekly/2017-05-14/XXX.tar.gz' blocked by <Limit> configuration
2017-05-14 02:20:41,139 mod_sftp/0.9.9[31108]: error changing permissions of '/XXX/Backups/weekly/2017-05-14/XXX.tar.gz' to 0600: Permission denied

[Jocko]

Ok iamola,

and if you use another ftp client ?

The issue is CHMOD feature is disabled on our sftp server and I assume your FTP client when it tries to upload a file it want to set temporary permissions on the uploaded file as long as the file is uploading.

[Jocko]

Attached a patch.

This patch adds some options on the sftp server so that it ignores some commands sent by a sftp client on upload event.

Check if it fixes your issue.
(after installing it you need to stop the ftp server and then restart it)

[iamola]

Still not working. I still get an error on first upload.

Code: Select all

2017-05-17 12:46:40,529 mod_sftp/0.9.9[1624]: 'subsystem' channel request for 'sftp' subsystem
2017-05-17 12:46:40,555 mod_sftp/0.9.9[1624]: using SFTP protocol version 3 for this session (channel ID 0)
2017-05-17 12:46:40,718 mod_sftp/0.9.9[1624]: STAT of '/' blocked by <Limit> configuration
2017-05-17 12:46:47,205 mod_sftp/0.9.9[1624]: chmod of '/fvdw/fvdw-sl-16.1-SFTP-SCP-Upload-Ignored-14may2017.zip' blocked by <Limit> configuration
2017-05-17 12:46:47,205 mod_sftp/0.9.9[1624]: error changing permissions of '/fvdw/fvdw-sl-16.1-SFTP-SCP-Upload-Ignored-14may2017.zip' to 0644: Permission denied


[Jocko]

Ok but if you use another ftp client like I suggest you.

here a trace with another ftpclient when I upload changelist.zip

Code: Select all

2017-05-17 19:10:12,954 Acrab.local proftpd[19610] 192.168.1.99 (192.168.1.13[192.168.1.13]): USER Jocko: Login successful.
2017-05-17 19:10:12,955 mod_sftp/0.9.9[19610]: client sent SSH_MSG_IGNORE message (144 bytes)
2017-05-17 19:10:12,958 mod_sftp/0.9.9[19610]: unsupported 'simple@putty.projects.tartarus.org' channel requested, ignoring
2017-05-17 19:10:12,990 mod_sftp/0.9.9[19610]: 'subsystem' channel request for 'sftp' subsystem
2017-05-17 19:10:12,992 mod_sftp/0.9.9[19610]: using SFTP protocol version 6 for this session (channel ID 0)
2017-05-17 19:10:12,994 mod_sftp/0.9.9[19610]: client sent 'vendor-id' extension: { vendorName = 'Martin Prikryl', productName = 'WinSCP', productVersion = '5.9.5', buildNumber = 7441 }
2017-05-17 19:10:13,078 mod_sftp/0.9.9[19610]: client set modification time of '/1100/essai/changelist.zip' to Tue May  9 17:24:05 2017

[iamola]

Transmit does the same, the only one that i think i don't get the error with is CyberDuck.
But the problem is not the FTP client.
I am trying to use it to backup VPS, which is done by WHM/cPanel automatically so i cannot use a different FTP client with that when its done automatically by the system itself.

[Jocko]

Hi iamola,

Unlike FTP protocol, there is not a single SFTP protocol (it exists 6 versions that do not have the same features).
It is the sftp client which defines which protocol it is used and with which parameters (for example the channel window size it wishes).
So for example between the clients filezilla and Winscp, it is not always possible to do the same things!
or if the sftp client want to use sftp protocol version 6 you will fail to create a new folder with proftpd (but yes with version 3 or 4)

So in short, it's a bit of a mess with this protocol and the sftp servers try to adapt but do not always succeed to do it.

In conclusion, I do not share your opinion and the problem is well between the SFTP client and the server where I have not yet identified on which parameter to act.

Attach a new version to test.

Note I need to have a full extract of your ftp log (since you try to open a session). I want to read them to detect how stp server detects your sftp client

Code: Select all

 sent server version 'SSH-2.0-FTP Server ready'
received client version 'SSH-2.0-WinSCP_release_5.9.3'
handling connection from SSH2 client 'WinSCP_release_5.9.3'
...
sending acceptable userauth methods: password
SSH2 session opened.
client sent SSH_MSG_IGNORE message (96 bytes)
unsupported 'simple@putty.projects.tartarus.org' channel requested, ignoring
'subsystem' channel request for 'sftp' subsystem
using SFTP protocol version 3 for this session (channel ID 0)
...

[iamola]

That worked better. No errors. Attached the log after validating:

Code: Select all

2017-05-18 09:59:16,141 XXX.local proftpd[6342] XXX (XXX[XXX]): SSH2 session opened.
2017-05-18 09:59:16,141 mod_sftp/0.9.9[6342]: sent server version 'SSH-2.0-FTP Server ready'
2017-05-18 09:59:16,177 mod_sftp/0.9.9[6342]: received client version 'SSH-2.0-OpenSSH_5.3'
2017-05-18 09:59:16,177 mod_sftp/0.9.9[6342]: handling connection from SSH2 client 'OpenSSH_5.3'
2017-05-18 09:59:16,213 mod_sftp/0.9.9[6342]:  + Session key exchange: diffie-hellman-group-exchange-sha256
2017-05-18 09:59:16,213 mod_sftp/0.9.9[6342]:  + Session server hostkey: ssh-rsa
2017-05-18 09:59:16,213 mod_sftp/0.9.9[6342]:  + Session client-to-server encryption: aes128-ctr
2017-05-18 09:59:16,213 mod_sftp/0.9.9[6342]:  + Session server-to-client encryption: aes128-ctr
2017-05-18 09:59:16,213 mod_sftp/0.9.9[6342]:  + Session client-to-server MAC: hmac-sha1
2017-05-18 09:59:16,213 mod_sftp/0.9.9[6342]:  + Session server-to-client MAC: hmac-sha1
2017-05-18 09:59:16,213 mod_sftp/0.9.9[6342]:  + Session client-to-server compression: none
2017-05-18 09:59:16,213 mod_sftp/0.9.9[6342]:  + Session server-to-client compression: none
2017-05-18 09:59:16,742 mod_sftp/0.9.9[6342]: sending acceptable userauth methods: password
2017-05-18 09:59:16,794 XXX.local proftpd[6342] XXX (XXX[XXX]): USER XXX: Login successful
2017-05-18 09:59:16,794 mod_sftp/0.9.9[6342]: sending userauth success
2017-05-18 09:59:16,795 mod_sftp/0.9.9[6342]: user 'XXX' authenticated via 'password' method
2017-05-18 09:59:16,796 XXX.local proftpd[6342] XXX (XXX[XXX]): USER XXX: Login successful.
2017-05-18 09:59:16,867 mod_sftp/0.9.9[6342]: 'subsystem' channel request for 'sftp' subsystem
2017-05-18 09:59:16,869 mod_sftp/0.9.9[6342]: using SFTP protocol version 3 for this session (channel ID 0)
2017-05-18 09:59:17,083 mod_sftp/0.9.9[6342]: client set permissions on '/XXX/Backups/validate.tmp-30924-1495115955.txt' to 0644
2017-05-18 09:59:17,121 mod_sftp/0.9.9[6342]: client set permissions on '/XXX/Backups/validate.tmp-30924-1495115955.txt' to 0644
2017-05-18 09:59:17,258 mod_sftp/0.9.9[6342]: client set access time of '/XXX/Backups/validate.tmp-30924-1495115955.txt' to Thu May 18 13:59:15 2017, modification time to Thu May 18 13:59:15 2017
2017-05-18 09:59:17,409 mod_sftp/0.9.9[6342]: requested read offset (32768 bytes) greater than size of '/XXX/Backups/validate.tmp-30924-1495115955.txt' (84 bytes)
2017-05-18 09:59:17,722 mod_sftp/0.9.9[6342]: client at XXX sent SSH_DISCONNECT message: disconnected by user (Application error)
2017-05-18 09:59:17,724 XXX.local proftpd[6342] XXX (XXX[XXX]): SSH2 session closed.


Also had another question, why cant i hide the fvdw folder in samba from version 16? Its always greyed out. Deleting it causes problems with my Btsync on restart. For some reason if i delete the fvdw folder, then i have to reinstall btsync on restart.