[Proftpd-user] error unlinking: Device busy

[Hardt, Jon]

Hi All – I am intermittently encountering an error that I was hoping someone could help me decipher. We have a relatively busy ProFTPd 1.3.5b install with mod_sftp installed. An automated job will login via SFTP, copy a heartbeat file to the server, operate on one or other files in the same directory, then delete the heartbeat file right before the session closes. Every once in a while, we will see an error message in our logs that looks like this:

SFTP.LOG
2016-08-12 15:01:09,838 mod_sftp/0.9.9[5590]: error unlinking '/transfer_heartbeat.xml': Device busy

PARANOID.LOG
10.16.7.4 UNKNOWN - [12/Aug/2016:15:01:08 -0600] "KEXINIT" - -
10.16.7.4 UNKNOWN - [12/Aug/2016:15:01:08 -0600] "DH_GEX_REQUEST" - -
10.16.7.4 UNKNOWN - [12/Aug/2016:15:01:08 -0600] "DH_GEX_INIT" - -
10.16.7.4 UNKNOWN - [12/Aug/2016:15:01:08 -0600] "NEWKEYS" - -
10.16.7.4 UNKNOWN - [12/Aug/2016:15:01:08 -0600] "SERVICE_REQUEST" - -
10.16.7.4 UNKNOWN - [12/Aug/2016:15:01:08 -0600] "USER xxxxx" 331 -
10.16.7.4 UNKNOWN - [12/Aug/2016:15:01:08 -0600] "USERAUTH_REQUEST" - -
10.16.7.4 UNKNOWN - [12/Aug/2016:15:01:08 -0600] "USER xxxxx" 331 -
10.16.7.4 UNKNOWN svcOLBFTPEastT [12/Aug/2016:15:01:09 -0600] "PASS (hidden)" 230 -
10.16.7.4 UNKNOWN svcOLBFTPEastT [12/Aug/2016:15:01:09 -0600] "USERAUTH_REQUEST" - -
10.16.7.4 UNKNOWN svcOLBFTPEastT [12/Aug/2016:15:01:09 -0600] "CHANNEL_OPEN" - -
10.16.7.4 UNKNOWN svcOLBFTPEastT [12/Aug/2016:15:01:09 -0600] "CHANNEL_REQUEST" - -
10.16.7.4 UNKNOWN svcOLBFTPEastT [12/Aug/2016:15:01:09 -0600] "INIT 6" - -
10.16.7.4 UNKNOWN svcOLBFTPEastT [12/Aug/2016:15:01:09 -0600] "EXTENDED fs-multiple-roots-***@vandyke.com" - -
10.16.7.4 UNKNOWN svcOLBFTPEastT [12/Aug/2016:15:01:09 -0600] "EXTENDED vendor-id" 0 -
10.16.7.4 UNKNOWN svcOLBFTPEastT [12/Aug/2016:15:01:09 -0600] "REALPATH ." - -
10.16.7.4 UNKNOWN svcOLBFTPEastT [12/Aug/2016:15:01:09 -0600] "OPENDIR /" - 0
10.16.7.4 UNKNOWN svcOLBFTPEastT [12/Aug/2016:15:01:09 -0600] "READDIR 4bf2c1880a1f367b" - 830
10.16.7.4 UNKNOWN svcOLBFTPEastT [12/Aug/2016:15:01:09 -0600] "CHANNEL_WINDOW_ADJUST" - 830
10.16.7.4 UNKNOWN svcOLBFTPEastT [12/Aug/2016:15:01:09 -0600] "MLSD /" - 830
10.16.7.4 UNKNOWN svcOLBFTPEastT [12/Aug/2016:15:01:09 -0600] "CLOSE 4bf2c1880a1f367b" 0 0
10.16.7.4 UNKNOWN svcOLBFTPEastT [12/Aug/2016:15:01:09 -0600] "STAT /transfer_heartbeat.xml" - -
10.16.7.4 UNKNOWN svcOLBFTPEastT [12/Aug/2016:15:01:09 -0600] "OPEN /transfer_heartbeat.xml" - 0
10.16.7.4 UNKNOWN svcOLBFTPEastT [12/Aug/2016:15:01:09 -0600] "READ 4cd7b13824794da5" - 61
10.16.7.4 UNKNOWN svcOLBFTPEastT [12/Aug/2016:15:01:09 -0600] "READ 4cd7b13824794da5" 1 61
10.16.7.4 UNKNOWN svcOLBFTPEastT [12/Aug/2016:15:01:09 -0600] "READ 4cd7b13824794da5" 1 61
10.16.7.4 UNKNOWN svcOLBFTPEastT [12/Aug/2016:15:01:09 -0600] "READ 4cd7b13824794da5" 1 61
10.16.7.4 UNKNOWN svcOLBFTPEastT [12/Aug/2016:15:01:09 -0600] "READ 4cd7b13824794da5" 1 61
10.16.7.4 UNKNOWN svcOLBFTPEastT [12/Aug/2016:15:01:09 -0600] "READ 4cd7b13824794da5" 1 61
10.16.7.4 UNKNOWN svcOLBFTPEastT [12/Aug/2016:15:01:09 -0600] "CHANNEL_WINDOW_ADJUST" - 61
10.16.7.4 UNKNOWN svcOLBFTPEastT [12/Aug/2016:15:01:09 -0600] "RETR /transfer_heartbeat.xml" 226 61
10.16.7.4 UNKNOWN svcOLBFTPEastT [12/Aug/2016:15:01:09 -0600] "CLOSE 4cd7b13824794da5" 0 61
10.16.7.4 UNKNOWN svcOLBFTPEastT [12/Aug/2016:15:01:09 -0600] "DELE /transfer_heartbeat.xml" 550 61
10.16.7.4 UNKNOWN svcOLBFTPEastT [12/Aug/2016:15:01:09 -0600] "REMOVE /transfer_heartbeat.xml" 4 -
10.16.7.4 UNKNOWN svcOLBFTPEastT [12/Aug/2016:15:01:09 -0600] "CHANNEL_CLOSE" - -


The odd thing is there aren’t any other active sessions within at least 60 seconds either side of the transfer failure; the failures are very intermittent, maybe once every week or so and this particular job runs every 10 minutes, so the vast majority of the time, the job works as expected.

It kind of feels like a contention issue, but again, there aren’t any active sessions at the same time that the deletion failure occurs. Here is my mod_sftp config, it’s pretty basic.

<IfModule mod_sftp.c>

SFTPEngine on
Port 22
SFTPLog /var/log/sftp/sftp.log

# Configure both the RSA and DSA host keys, using the same host key
# files that OpenSSH uses.
SFTPHostKey /etc/ssh/ssh_host_rsa_key
SFTPHostKey /etc/ssh/ssh_host_dsa_key
SFTPAuthMethods publickey password
SFTPOptions IgnoreSFTPSetPerms IgnoreSFTPSetTimes

SFTPAuthorizedUserKeys file:~/.ssh/authorized_keys

# Enable compression
SFTPCompression delayed

</IfModule>

I am hoping there is some sort of ProFTPd directive that will either handle or ignore this condition if/when it occurs.

Unless specifically stated, (i) this email does not create a legal relationship between CoBank, ACB, including its subsidiaries and affiliates (collectively “CoBank”) and the recipient, and (ii) CoBank disclaims any liability for the content of this email or for the consequences of any actions taken on the basis of the information provided in this email or its attachments. This email is intended solely for the use of the intended recipient(s) and may contain information that is confidential, privileged or otherwise protected from disclosure. If you are not the intended recipient of this email, please notify the sender, and delete it from your system. In communicating via email with CoBank, you consent to the foregoing.

CoBank, 6340 S. Fiddlers Green Circle, Greenwood Village, CO 80111 www.cobank.com

[TJ Saunders]

Hi All – I am intermittently encountering an error that I was hoping
someone could help me decipher. We have a relatively busy ProFTPd 1.3.5b
install with mod_sftp installed. An automated job will login via SFTP,
copy a heartbeat file to the server, operate on one or other files in the
same directory, then delete the heartbeat file right before the session
closes. Every once in a while, we will see an error message in our logs
SFTP.LOG
2016-08-12 15:01:09,838 mod_sftp/0.9.9[5590]: error unlinking
'/transfer_heartbeat.xml': Device busy

Interesting. Is that directory on a network-mounted filesystem, by any
change? That particular error for the unlink(2) system call is quite
unusual...

I am hoping there is some sort of ProFTPd directive that will either
handle or ignore this condition if/when it occurs.

Unfortunately, no; it would be up to the client to ignore that value.

That said, it might be possible to patch mod_sftp to handle this
unlink(2) error condition more gracefully, once we get a little more
background/info on what/how it might happen.

Cheers,
TJ