Random 500 errors, nothing in log

[ingenium]

I'm getting random 500 internal server errors on POST requests, only during checkout when the order is finalized. There's no real pattern to it, sometimes 15 orders will go through without issue, then 5 in a row will get the error, then 10 more go through, then 1 errors, then 5 more are OK, then 2 give errors, etc.

 

The apache access log shows the 500 error, but the apache error log shows nothing, nor does the PHP log. I'm using fcgi with apache. I tried switching to regular CGI but that didn't help. I tried enabling and disabling suhosin and it also had no effect.

 

Turning on html error reporting (so the user sees more detail with the 500 error) won't help, since this is usually caused by a callback from the credit card processor and no one will see it:

64.94.118.193 - - [20/Aug/2013:12:01:05 -0700] "POST /module/authorizedotnet/validationdpn HTTP/1.1" 500 4086 "-" "-"

 

My apache configuration contains the following to prevent the usual reason for fcgi and php giving this error:

FcgidInitialEnv PHP_FCGI_MAX_REQUESTS 99999
FcgidMaxRequestsPerProcess 99999
IPCCommTimeout 601
FcgidMaxRequestLen 1073741824
...
<IfModule mpm_worker_module>
StartServers		  2  
MinSpareThreads	  25  
MaxSpareThreads	  75  
ThreadLimit		  64  
ThreadsPerChild	  25  
MaxClients		  150
MaxRequestsPerChild   0  
</IfModule>

 

I've watched it happen once and apache's server-status showed 48 idle workers, so it's not resource exhaustion from Apache.

 

php.ini contains:

error_reporting = E_ALL | E_STRICT
display_errors = stderr
error_log = /var/log/php.log

 

My fcgi wrapper:

#!/bin/bash
PHPRC=$PWD/../etc/php5
export PHPRC
umask 022
export PHP_FCGI_CHILDREN
PHP_FCGI_MAX_REQUESTS=99999
export PHP_FCGI_MAX_REQUESTS
SCRIPT_FILENAME=$PATH_TRANSLATED
export SCRIPT_FILENAME
exec /usr/bin/php5-cgi

 

PHP Version 5.3.3-7+squeeze16
Server Version: Apache/2.2.16 (Debian) DAV/2 SVN/1.6.12 mod_fcgid/2.3.6 mod_ruby/1.2.6 Ruby/1.8.7(2010-08-16) mod_ssl/2.2.16 OpenSSL/0.9.8o

 

I need the specific error to be logged to a file somewhere. Does anyone have any ideas? Is Prestashop somehow intercepting PHP errors so that they don't get logged?

[vekia]

log line that you attached to your message:

64.94.118.193 - - [20/Aug/2013:12:01:05 -0700] "POST /module/authorizedotnet/validationdpn HTTP/1.1" 500 4086 "-" "-"

 

looks like APACHE log, maybe you've got separate file for PHP parsing errors, can you check it?

[ingenium]

log line that you attached to your message:

64.94.118.193 - - [20/Aug/2013:12:01:05 -0700] "POST /module/authorizedotnet/validationdpn HTTP/1.1" 500 4086 "-" "-"

 

looks like APACHE log, maybe you've got separate file for PHP parsing errors, can you check it?

 

There is nothing relevant in the PHP error log. My original post shows I define the php error log as being /var/log/php.log, but it contains nothing within the timeframe of the error. The only thing it contains are notices about PHP Strict Standards and "PHP Notice: Undefined index" and "PHP Notice: Trying to get property of non-object" about smarty cached objects.

 

It also gives the following error on every order (regardless of whether it gets the 500 error):

[21-Aug-2013 21:50:31] PHP Warning:  Invalid argument supplied for foreach() in /home/domain/public_html/modules/mailalerts/MailAlert.php on line 172

 

I also turned up the error level for apache. I just had the error occur again and this was all that was in the error log (domain.com replacing my domain name):

[Thu Aug 22 00:16:44 2013] [info] [client 64.94.118.193] Connection to child 20 established (server domain.com:443)
[Thu Aug 22 00:16:44 2013] [info] Seeding PRNG with 656 bytes of entropy
[Thu Aug 22 00:16:44 2013] [info] Initial (No.1) HTTPS request received for child 20 (server domain.com:443)
[Thu Aug 22 00:16:44 2013] [info] [client 64.94.118.193] Connection closed to child 20 with standard shutdown (server domain.com:443)

 

EDIT: I turned on error logging in config/defines.inc.php and the following showed up when a transaction failed:

Cart cannot be loaded or an order has already been placed using this cart

Edited August 22, 2013 by ingenium (see edit history)

[ingenium]

I finally was able to locate a Prestashop specific log, and it showed

*ERROR* 2013/08/22 - 20:06:02: Property CartRule->date_add is not valid at line 837 in file classes/ObjectModel.php

 

I was then able to find this post http://forge.prestas...owse/PSCFV-5755 and it seems that a customer using a voucher originally created with an older version of Prestashop would cause this error. I ran the following SQL query to fix it:

UPDATE ps_cart_rule SET date_add = date_from WHERE date_add = '0000-00-00 00:00:00';
UPDATE ps_cart_rule SET date_upd = date_from WHERE date_upd = '0000-00-00 00:00:00';

 

I haven't had any orders placed yet that used one of these vouchers, but looking at the Prestashop source it looks like this was indeed the cause.

 

The autoupgrade script should run the above query when coming from an older version of Prestashop!

Edited August 23, 2013 by ingenium (see edit history)