Hey, Internet, Can You Maybe Solve My Problem

Submitted by C B Wright on

NOTE: This has been fixed. See comments for explanation. Thanks all!

Remember when I said my site upgrade from Ubuntu Lucid (10.04) to Precise (12.04) went flawlessly? Well, I'm not sure that's true. I've been trying to solve a funny little problem that I can't figure out, without success. I was just on the verge of descending into despair (I still might get a series of Mark vs. Computer comics out of it) when it occurred to me: my readers are, by and large, a lot smarter than I am. So follow me below the cut where I relate to you my tale of woe, in the hopes that one of you knows exactly what is going on...

Drupal 6 uses a plugin called CCK FileField to allow people to attach files to nodes.1 Since I converted over to Drupal, I've used FileField to load my webcomics into Drupal, and custom graphics into articles. Since the beginning of last year (January 2011) I've also used FileField to publish podcasts of the individual chapters I publish in the Fiction area.

Thursday night I attempted to publish a new podcast, and nothing happened.

Firefox doesn't give you a lot of information about what it's doing when it tries to upload a file, but Chromium (the Ubuntu version of Google's Chrome browser) actually reports a % status as the file is being uploaded. According to Chromium, it reached 1% and then the page crashed.

At first I thought it was just specific to the podcasts, but I've since come to learn that it depends on the size of the file--the crash is triggered by a file with a minimum size of somewhere between 125kb and 230kb (a 122kb file loads fine, a 230kb file hangs).

The last successful podcast was published on May 10th. Every file I've uploaded after that has been under 125kb, so I don't know specifically when this problem started. However, on May 12 I upgraded my server from Ubuntu Lucid (10.04) to Ubuntu Precise (12.04) in what I described, at the time, as an (Apparently) Flawless Upgrade.

Well that's it then! It must be a problem with the upgrade. Something changed, or something had to be changed that wasn't, that introduced this problem. Right? Well, wait. It's less obvious than that.

If you're having problems uploading a file using a php-based form, the most obvious culprit is usually sitting in one of your php.ini configuration files. PHP uses a number of settings that places limitations on how large the files can be and how many system resources can be reserved for handling the processing of files. The most obvious entries control the Maximum memory allocation, Maximum file upload size, and the Maximum HTTP POST size. Secondary culprits are entries that control how much time the system allows for input to be parsed, and how much time the system allows PHP to execute what's being brought in (Maximum input parsing time and Maximum execution time).

These usual suspects are all set well above the threshold needed to bring in the files. They are, in fact, the same values they were back when everything worked.

On top of that, if the problem had something to do with the server itself, it would be reasonable to expect the problem could be duplicated outside of Drupal, in other interfaces that use php-based forms to upload files. So I logged into phpmyadmin2, created a test database, and tried to import a 35mb sql file.

It worked flawlessly.

Meanwhile, on my test server--which also runs Lucid, is running the same version of Drupal, and uses a backup of the database that is as recent as this morning, can use filefield to upload files of any size without any difficulty whatsoever.

Based on this, I don't think the problem is Apache, or PHP, or mySQL. If it were, the problem should have occurred when I was importing a 35mb file in phpmyadmin, and probably would have occurred when I tried it on my dev machine.

Except there are a few differences between my dev server and my live server:

  • My live server is running in a virtual environment set up by Prgmr.com, with a set and finite amount of resources. However, I can track those resources, and I'm not close to filling them up yet.
  • My local server is running on localhost on my laptop, which means even though I'm using filefield to upload files in my tests, it's still grabbing files locally. There's very little if anything getting between the file and its destination.
  • My live server is SSL enabled, so these uploads are occurring through https. My dev server isn't.

So there are a few other things I can think of that might be the problem:

  • My ISP is capping the size of files going outward. I don't think this is the case, because I can sftp files of any size to my server, and I was able to add that 35mb sql file to mysql.
  • Prgmr.com is capping the size of files coming in to my site. I don't think this is the case for the same reason -- I can sftp, and was able to import the 35mb database file.
  • It's a file permissions issue. However, the directory that I upload the file to has exactly the same permissions as the directory where I upload the comics, and uploading a 122kb mp3 file (that's about five to seven seconds of audio, if you're curious) works just fine. It's the size of the file that triggers it, not the location.

So, as you can probably guess, I'm stumped. And until I'm un-stumped the podcasting portion of this site is going to stop, which probably doesn't affect the majority of my site visitors but it does affect those of you who listen to the podcasts.

I'm hoping that one of you out there will read this and understand exactly what's going on. For my part I have no freakin' clue. It appears to be filefield-specific, because it doesn't occur in phpmyadmin, but there isn't any reason for it that I can find.

Anyone? Anyone at all?

  • 1. A "node" is what Drupal calls an individual piece of content--a webcomic, an article, a page, etc.
  • 2. A front end to mySQL that makes database administration a little easier for us n00bs.

Comments

Comments are active for 30 days after publication. If you wish to comment after 30 days please use the Forums.

I hate to bring up the

I hate to bring up the obvious, but it looks like you've made no attempt to look at the logs. /var/log/apache2/error.log for apache, /var/log/nginx/error.log for nginx. By default PHP will report all errors, so if it is a PHP issue then it will be listed in those logs. If it is a http server issue, those errors will for sure be in their logs.

You should ask your host if they are capping files sizes. Just because a transfer over ssh works fine DOES NOT mean a transfer over http will be just fine. They are entirely different protocols and can easily be handled differently by various routers and black boxes.

Feel free to stick your error logs up on a pastebin and email me the link.

Good luck!

What he said...

I think to help look at this we will need to see if there are errors in apache logs or in the system error logs (like broken connections and such). It may be that the server is not thinking it is getting data fast enough and cutting the connection or some similar issue.

So...

So I'm using apache, and I just tried to upload a podcast (which ended in failure, of course), which means I should have a recent entry in the error.log file if something is going on, right? The last entry was about an hour and a half ago (13:25:07).

Also, if my host was capping file sizes then uploading the 35mb sql file should have failed, right?

--
Writer, former musician, occasional cartoonist, and noted authority on his own opinions.

Error logs...

I don't have any experience with pastebins, so... here are the contents of error.log:


[Sun May 27 06:25:10 2012] [notice] Digest: generating secret for digest authentication ...
[Sun May 27 06:25:10 2012] [notice] Digest: done
[Sun May 27 06:25:10 2012] [notice] Apache/2.2.22 (Ubuntu) DAV/2 SVN/1.6.17 mod_fcgid/2.3.6 PHP/5.3.10-1ubuntu3.1 with Suhosin-Patch mod_ruby/1.2.6 Ruby/1.8.7(2011-06-30) mod_ssl/2.2.22 OpenSSL/1.0.1 configured -- resuming normal operations
[Sun May 27 06:25:12 2012] [notice] Graceful restart requested, doing restart
[Sun May 27 06:25:15 2012] [notice] Digest: generating secret for digest authentication ...
[Sun May 27 06:25:15 2012] [notice] Digest: done
[Sun May 27 06:25:15 2012] [notice] Apache/2.2.22 (Ubuntu) DAV/2 SVN/1.6.17 mod_fcgid/2.3.6 PHP/5.3.10-1ubuntu3.1 with Suhosin-Patch mod_ruby/1.2.6 Ruby/1.8.7(2011-06-30) mod_ssl/2.2.22 OpenSSL/1.0.1 configured -- resuming normal operations
[Sun May 27 09:13:55 2012] [warn] mod_fcgid: cleanup zombie process 12501
[Sun May 27 10:32:08 2012] [warn] mod_fcgid: cleanup zombie process 15518
[Sun May 27 12:56:04 2012] [warn] mod_fcgid: cleanup zombie process 20707
[Sun May 27 14:26:08 2012] [warn] mod_fcgid: cleanup zombie process 24469
[Sun May 27 15:11:08 2012] [warn] mod_fcgid: cleanup zombie process 27714
[Sun May 27 15:29:39 2012] [notice] Graceful restart requested, doing restart
[Sun May 27 15:29:39 2012] [notice] Digest: generating secret for digest authentication ...
[Sun May 27 15:29:39 2012] [notice] Digest: done
[Sun May 27 15:29:39 2012] [notice] Apache/2.2.22 (Ubuntu) DAV/2 SVN/1.6.17 mod_fcgid/2.3.6 PHP/5.3.10-1ubuntu3.1 with Suhosin-Patch mod_ruby/1.2.6 Ruby/1.8.7(2011-06-30) mod_ssl/2.2.22 OpenSSL/1.0.1 configured -- resuming normal operations
[Sun May 27 15:29:50 2012] [notice] caught SIGTERM, shutting down
[Sun May 27 15:29:55 2012] [notice] suEXEC mechanism enabled (wrapper: /usr/lib/apache2/suexec)
[Sun May 27 15:29:55 2012] [notice] Digest: generating secret for digest authentication ...
[Sun May 27 15:29:55 2012] [notice] Digest: done
[Sun May 27 15:29:55 2012] [notice] Apache/2.2.22 (Ubuntu) DAV/2 SVN/1.6.17 mod_fcgid/2.3.6 PHP/5.3.10-1ubuntu3.1 with Suhosin-Patch mod_ruby/1.2.6 Ruby/1.8.7(2011-06-30) mod_ssl/2.2.22 OpenSSL/1.0.1 configured -- resuming normal operations
[Sun May 27 16:25:54 2012] [warn] mod_fcgid: cleanup zombie process 30372
[Sun May 27 17:48:31 2012] [notice] Graceful restart requested, doing restart
[Sun May 27 17:48:35 2012] [notice] Digest: generating secret for digest authentication ...
[Sun May 27 17:48:35 2012] [notice] Digest: done
[Sun May 27 17:48:35 2012] [notice] Apache/2.2.22 (Ubuntu) DAV/2 SVN/1.6.17 mod_fcgid/2.3.6 PHP/5.3.10-1ubuntu3.1 with Suhosin-Patch mod_ruby/1.2.6 Ruby/1.8.7(2011-06-30) mod_ssl/2.2.22 OpenSSL/1.0.1 configured -- resuming normal operations
[Sun May 27 17:51:51 2012] [notice] caught SIGTERM, shutting down
[Sun May 27 17:52:05 2012] [notice] suEXEC mechanism enabled (wrapper: /usr/lib/apache2/suexec)
[Sun May 27 17:52:05 2012] [notice] Digest: generating secret for digest authentication ...
[Sun May 27 17:52:05 2012] [notice] Digest: done
[Sun May 27 17:52:06 2012] [notice] Apache/2.2.22 (Ubuntu) DAV/2 SVN/1.6.17 mod_fcgid/2.3.6 PHP/5.3.10-1ubuntu3.1 with Suhosin-Patch mod_ruby/1.2.6 Ruby/1.8.7(2011-06-30) mod_ssl/2.2.22 OpenSSL/1.0.1 configured -- resuming normal operations
[Sun May 27 18:10:46 2012] [notice] caught SIGTERM, shutting down
[Sun May 27 18:10:47 2012] [notice] suEXEC mechanism enabled (wrapper: /usr/lib/apache2/suexec)
[Sun May 27 18:10:47 2012] [notice] Digest: generating secret for digest authentication ...
[Sun May 27 18:10:47 2012] [notice] Digest: done
[Sun May 27 18:10:47 2012] [notice] Apache/2.2.22 (Ubuntu) DAV/2 SVN/1.6.17 mod_fcgid/2.3.6 PHP/5.3.10-1ubuntu3.1 with Suhosin-Patch mod_ruby/1.2.6 Ruby/1.8.7(2011-06-30) mod_ssl/2.2.22 OpenSSL/1.0.1 configured -- resuming normal operations
[Sun May 27 19:29:17 2012] [notice] caught SIGTERM, shutting down
[Sun May 27 19:29:19 2012] [notice] suEXEC mechanism enabled (wrapper: /usr/lib/apache2/suexec)
[Sun May 27 19:29:19 2012] [notice] Digest: generating secret for digest authentication ...
[Sun May 27 19:29:19 2012] [notice] Digest: done
[Sun May 27 19:29:19 2012] [notice] Apache/2.2.22 (Ubuntu) DAV/2 SVN/1.6.17 mod_fcgid/2.3.6 PHP/5.3.10-1ubuntu3.1 with Suhosin-Patch mod_ruby/1.2.6 Ruby/1.8.7(2011-06-30) mod_ssl/2.2.22 OpenSSL/1.0.1 configured -- resuming normal operations
[Sun May 27 22:24:55 2012] [warn] mod_fcgid: cleanup zombie process 11139
[Mon May 28 00:05:33 2012] [warn] mod_fcgid: cleanup zombie process 13896
[Mon May 28 02:54:04 2012] [warn] mod_fcgid: cleanup zombie process 21745
[Mon May 28 07:56:48 2012] [warn] mod_fcgid: cleanup zombie process 2188
[Mon May 28 08:55:01 2012] [warn] mod_fcgid: cleanup zombie process 4408
[Mon May 28 09:29:53 2012] [warn] mod_fcgid: cleanup zombie process 5896
[Mon May 28 10:28:00 2012] [notice] Graceful restart requested, doing restart
[Mon May 28 10:28:04 2012] [notice] Digest: generating secret for digest authentication ...
[Mon May 28 10:28:04 2012] [notice] Digest: done
[Mon May 28 10:28:04 2012] [notice] Apache/2.2.22 (Ubuntu) DAV/2 SVN/1.6.17 mod_fcgid/2.3.6 PHP/5.3.10-1ubuntu3.1 with Suhosin-Patch mod_ruby/1.2.6 Ruby/1.8.7(2011-06-30) mod_ssl/2.2.22 OpenSSL/1.0.1 configured -- resuming normal operations
[Mon May 28 11:22:11 2012] [warn] mod_fcgid: cleanup zombie process 10745
[Mon May 28 11:32:02 2012] [warn] mod_fcgid: cleanup zombie process 10954
[Mon May 28 12:20:01 2012] [warn] mod_fcgid: cleanup zombie process 13904
[Mon May 28 13:10:09 2012] [warn] mod_fcgid: cleanup zombie process 15628
[Mon May 28 13:17:33 2012] [notice] caught SIGTERM, shutting down
[Mon May 28 13:25:05 2012] [notice] suEXEC mechanism enabled (wrapper: /usr/lib/apache2/suexec)
[Mon May 28 13:25:05 2012] [notice] Digest: generating secret for digest authentication ...
[Mon May 28 13:25:05 2012] [notice] Digest: done
[Mon May 28 13:25:07 2012] [notice] Apache/2.2.22 (Ubuntu) DAV/2 SVN/1.6.17 mod_fcgid/2.3.6 PHP/5.3.10-1ubuntu3.1 with Suhosin-Patch mod_ruby/1.2.6 Ruby/1.8.7(2011-06-30) mod_ssl/2.2.22 OpenSSL/1.0.1 configured -- resuming normal operations
[Mon May 28 15:19:36 2012] [warn] mod_fcgid: cleanup zombie process 8873

It looks like the only warnings have to do with cleaning up zombie processes, and they don't occur during the times I've tried to upload files today.

--
Writer, former musician, occasional cartoonist, and noted authority on his own opinions.

SSL error log

If you're using SSL, the error log would be ssl_error_log, on the same location. The error_log would have only the "unencrypted" transactions, whereas the ssl_error_log will show everything that happens once the ssl tunnel is established.

There isn't one...

no ssl_error_log, just an ssl_access.log, ssl_access.log.1, .2.gz, .3.gz, etc...

--
Writer, former musician, occasional cartoonist, and noted authority on his own opinions.

You could try checking your

You could try checking your apache configuration file (usually /etc/httpd/conf/httpd.conf and|or /etc/httpd/conf.d/*.conf, particularly the ssl.conf file) for the following lines:

ErrorLog logs/ssl_error_log
TransferLog logs/ssl_access_log
LogLevel warn

You can also change LogLevel to debug, which will be really verbose, but might output something useful.

Restart apache after changing configs :)

Ah, you're on the Red Hat side...

in Ubuntu/Kubuntu the apache conf file is /etc/apache2/apache2.conf -- at least, I think that's what it is. I know juuuuuust enough to get me into serious trouble and then my knowledge drops off like a... rapidly... dropping... thing...

Anyway, "ssl_error_log" doesn't occur anywhere in the conf file. The only occurrence of "ssl" is an entry for SSLPassPhraseDialog...

--
Writer, former musician, occasional cartoonist, and noted authority on his own opinions.

Red Hat indeed :)

I'm not familiar with the layout of the config files in a Ubuntu server, but my guess is that in one of those files you must have a "ssl_access_log" directive. You could grep the tree to find out where (grep ssl_access /etc/apache2/*)

Otherwise, simply add the lines somewhere after you feel ssl would have been activated already. Either after that SSLPassPhraseDialog directive, or in a /etc/apache2/z_sslerrorlog.conf file (the z_ is so that it's read last).

OK, I need to be cautious about this.

So... I can't find an ssl error log, but I *can* find an ssl access log. However, I can't find either of them in any of the configuration files, so I think I need to figure out where the ssl access log is being defined before I start modifying things...

--
Writer, former musician, occasional cartoonist, and noted authority on his own opinions.

Found it!

I think I found the error message.

It was in a completely different error log that virtualmin set up without telling me.

So I just tried to upload a podcast, and I get this message:


[Mon May 28 21:15:23 2012] [warn] [client 184.13.31.170] mod_fcgid: HTTP request length 139258 (so far) exceeds MaxRequestLen (131072), referer: https://www.eviscerati.org/node/add/podcast

I guess the MaxRequestLen setting isn't big enough. Time to hunt for that one in the php config files... unless it's not a php variable. Maybe it's apache-specific? Anyone know anything about this one?

--
Writer, former musician, occasional cartoonist, and noted authority on his own opinions.

FIXED!

The answer is here:

http://www.goeszen.com/request-length-exceeds-maxrequestlen-apache2-debi...

Basically a variable changed from Lenny to Squeeze, so I assume the Ubuntu settings changed as well. So it WAS a byproduct of having upgraded from Lucid to Precise. I wonder why phpmyadmin wasn't affected, though?

Anyway, I've followed the suggestion above and the podcast is now updating. Problem solved.

... and now I know what logs are for.

Thanks everyone for your help!

--
Writer, former musician, occasional cartoonist, and noted authority on his own opinions.

Google says it's a mod_fcgid

Google says it's a mod_fcgid setting: http://httpd.apache.org/mod_fcgid/mod/mod_fcgid.html#fcgidmaxrequestlen says "Before 2.3.6, this defaulted to 1GB. Most users of earlier versions should use this directive to set a more reasonable limit."

So, try adding

# Set a 20M request limit
FcgidMaxRequestLen 20971520

or something higher to the Apache configuration for your vhost or the general Apache config in /etc as mentioned above. If you're not concerned about potential DoS you could set it back to 1G, I suppose.

Ah...

... perhaps I should set it lower than I did, then. I suppose the question becomes "what is a reasonable request limit?" How does request limit correlate with the size of the file? Does it? I don't have many podcasts that go over 20mb at present, but if I ever did a half-hour podcast I would.

--
Writer, former musician, occasional cartoonist, and noted authority on his own opinions.

The limit on file size would

The limit on file size would be a bit under the request limit, but fairly close (perhaps 1,000 or 2,000 bytes under, depending on how many cookies, request headers and other fields are sent to the server in the upload request). So maybe 20M is too low, but 50M would be reasonable. Or maybe it's fine where it is -- it would allow an attacker to fill memory (and possibly disk space) up to the request limit, but to do that they'd have to use the same amount of bandwidth, so it wouldn't be a very efficient attack.