BASH Cures Cancer

A few days ago, esofthub over at My SysAd Blog wrote about using FTP in a shell script. I recently had an issue where an application malfunctioned and an automated process started two ftp sessions for the same file at the same time. Both processes were writing to the file and thus the file ended up corrupt and twice as large as it should have been.

As such, I planned to write up a demo showing that this problem should be considered when ftp’ing in scripts. However, when doing the demo, vsftpd blocked the second session until the first was done, indicating that file locking was being done. Sure enough vsftpd added file locking in 2.0.3:

At this point: v2.0.3 released! (need to get about three important fixes out)
- Add optional file locking support via lock_upload_files (default on).

My demo was wrecked…. Then, I noticed that the file was corrupt. In my test, I started two ftp processes (notice how you can use curl to upload files via the command line) in two different terminals:

$ date; curl -s -T bigfile --user noland:password ftp://localhost/vsftpd-file-locking; date
Mon Jan 14 19:06:51 CST 2008
Mon Jan 14 19:07:20 CST 2008

$ date; curl -s -T bigfile --user noland:password ftp://localhost/vsftpd-file-locking; date
Mon Jan 14 19:06:52 CST 2008
Mon Jan 14 19:07:50 CST 2008

After the upload, the file is corrupt:

$ ls -l vsftpd-file-locking bigfile
-rw-r--r-- 1 noland users  512000000 2008-01-14 18:17 bigfile
-rw-r--r-- 1 noland users 1019576320 2008-01-14 19:07 vsftpd-file-locking

Being curious and hoping to fix a bug, I investigated. I downloaded the latest version, 2.0.5 and looked over the source files. The file “postlogin.c” looked like a candidate. Sure enough, I eventually found the function:

handle_upload_common(struct vsf_session* p_sess, int is_append, int is_unique)

This is where the magic appeared to be happening. Simple printf statements wouldn’t work since vsftpd daemonizes itself. As such, I decided to use syslog. I included syslog.h after the last include statement in “postlogin.c”:

27  #include "vsftpver.h"
#include <syslog.h>

The two variables “is_append” and “offset” looked interesting and decided the flow of the file write operation. Thus I added the two syslog statements below, above the code with line numbers specified:

syslog(LOG_INFO, "is_append = %d", is_append);
syslog(LOG_INFO, "offset = %d", (int) offset);
967      /* For non-anonymous, allow open() to overwrite or append existing files */
968      if (!is_append && offset == 0)
969      {
970         new_file_fd = str_create_overwrite(p_filename);
971      }
972      else
973      {
974          new_file_fd = str_create_append(p_filename);
975      }

I then built vsftp by typing “make” and as root started it, “./vsftpd /etc/vsftpd/vsftpd.conf”. I retried my test and the following was logged to /var/log/messages:

Jan 11 22:24:21 test1 vsftpd: is_append = 0
Jan 11 22:24:21 test1 vsftpd: offset = 0
Jan 11 22:24:24 test1 vsftpd: is_append = 0
Jan 11 22:24:24 test1 vsftpd: offset = 0

Unfortunately this meant the second session was not starting at some offset in the file as I had hoped. I decided to follow the function that opened the file where the upload was saved, “str_create_overwrite.” This function’s definition is in “sysstr.c”:

95  int
96  str_create_overwrite(const struct mystr* p_str)
97  {
98    return vsf_sysutil_create_overwrite_file(str_getbuf(p_str));
99  }

I then found “vsf_sysutil_create_overwrite_file” in “sysutil.c”:

1058  vsf_sysutil_create_overwrite_file(const char* p_filename)
1059  {
1060    return open(p_filename, O_CREAT | O_TRUNC | O_WRONLY |
1061                            O_APPEND | O_NONBLOCK,
1062                tunable_file_open_mode);
1063  }

I thought it curious that the function had the word “overwrite” in it and yet used the O_APPEND flag. In addition, using both the O_TRUNC and O_APPEND flags seemed odd. I commented out the original code and removed the O_APPEND flag:

1058  vsf_sysutil_create_overwrite_file(const char* p_filename)
1059  {
1060  //  return open(p_filename, O_CREAT | O_TRUNC | O_WRONLY |
1061  //                          O_APPEND | O_NONBLOCK,
1062  //              tunable_file_open_mode);
1063    return open(p_filename, O_CREAT | O_TRUNC | O_WRONLY |
1064                            O_NONBLOCK,
1065                tunable_file_open_mode);
1066  }

After recompiling via “make” and restarting as root via “./vsftpd /etc/vsftpd/vsftpd.conf” I tested again:

$ date; curl -s -T bigfile --user noland:password ftp://localhost/vsftpd-file-locking; date
Fri Jan 11 22:57:41 EST 2008
Fri Jan 11 22:59:26 EST 2008

$ date; curl -s -T bigfile --user noland:password ftp://localhost/vsftpd-file-locking; date
Fri Jan 11 22:57:42 EST 2008
Fri Jan 11 23:00:58 EST 2008

And…after the test, the file was not corrupt:

$ ls -l vsftpd-file-locking bigfile
-rw-r--r-- 1 noland noland 512000000 Jan 11 22:22 bigfile
-rw-r--r-- 1 noland noland 512000000 Jan 11 23:00 vsftpd-file-locking

$ md5sum vsftpd-file-locking bigfile
651db2470e6473a7f35d1879a5632c58  vsftpd-file-locking
651db2470e6473a7f35d1879a5632c58  bigfile

Yay!! I emailed the problem and possible fix to the maintainer. This is why I love free software.

Notes:

1. I tested the newest release version of pure-ftpd and proftpd and file locking appeared to work correctly.
2. I created the test file with “dd if=/dev/urandom of=bigfile count=1000000″