Every once in a while, one of the orders placed through this ancient script I’m maintaining only makes is half-way through the Paypal process.
It processes the payment, but doesn’t email the seller, or log the transaction locally in the servers MySQL database.
The first thing I did was set up some logging:
file_put_contents('a_sqltest.txt', print_r($sql, true), FILE_APPEND | LOCK_EX);
So I can see some of what the code is generating.
Now am scanning the MySQL logs for details from the user who’s latest transaction failed. This is done here by piping the output of the find command into zgrep, which unlike grep, doesn’t seem to support a recursive search.
me@server:# find /var/log/mysql/ -name \*.log.*.gz -print0 | xargs -0 zgrep 'ggchamp'
Hmmm. MySQL logs are all empty:
me@server:~# zgrep 'ggchamp' /var/log/mysql/mysql.log.1.gz
me@server:~# zgrep 'a' /var/log/mysql/mysql.log.1.gz
me@server:~# ls -l /var/log/mysql/
-rw-r----- 1 mysql adm 0 Sep 5 06:25 error.log
-rw-r----- 1 mysql adm 20 Sep 4 06:25 error.log.1.gz
Apparently it’s not set to log queries. One can also set to only log slow queries:
[mysqld]
slow-query-log = 1
slow-query-log-file = /var/log/mysql/mysql-slow.log
long_query_time = 1
log-queries-not-using-indexes
I am afraid we are going to need to log all MySQL queries, which will slow the system down.
[mysqld]
sql_mode = "NO_ENGINE_SUBSTITUTION,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER"
SET global general_log = 1;
SET global log_output = 'table';
Restart: me@server:~# /etc/init.d/mysql restart
Restart failed. Let’s look journalctl -xe. Check the Docs.
Maybe just set logging to on at runtime by logging in and:
SET GLOBAL general_log = 'ON';
SET GLOBAL log_output = 'table';
Now make sure a query is run and check the logs in MySQL tables:
select command_type, argument from mysql.general_log;
or
select * from mysql.general_log
where event_time > (now() - INTERVAL 8 SECOND) and thread_id not in(9 , 628)
and argument <> "SELECT 1" and argument <> ""
and argument <> "SET NAMES 'UTF8'" and argument <> "SHOW STATUS"
and command_type = "Query" and argument <> "SET PROFILING=1"
Run the query which didn’t succeed:
INSERT INTO orders (order_id, user_id, billing_first_name, billing_last_name, billing_address1, billing_address2, billing_city, billing_state, billing_country, billing_zip, billing_fax, billing_email, billing_phone, shipping_first_name, shipping_last_name, shipping_address1, shipping_address2, shipping_city, shipping_state, shipping_country, shipping_zip, shipping_fax, shipping_email, shipping_phone, prefered_shippin_method, order_date, order_total_price, taxrate, order_status, transaction_id, vorder_currency, namount_paid, vpayment_status, buyer_comments, success_fee_percentage, success_fee_amount )
VALUES ( '8013', '35', 'First', 'Last', '', '', '', '', '', '', '', 'ggchampe@example.com', '', '', '', '', '', '', '', '', '', '', '', '', '', now(), '38.25', '0.00', '1', '', 'USD', '42.08', 'P', '', '10', '3.83' );
And
ERROR 1062 (23000): Duplicate entry '8013' for key 'PRIMARY'
Ah ha!
mysql> SELECT order_id, billing_first_name, order_date FROM orders WHERE order_id = 8013;
+----------+--------------------+------------+
| order_id | billing_first_name | order_date |
+----------+--------------------+------------+
| 8013 | diane | 2017-08-28 |
+----------+--------------------+------------+
1 row in set (0.01 sec)
Turn logging back off: mysql> SET GLOBAL general_log = 0;
The code seems to be creating duplicate order_ids. Where are these created?
$qry1="select max(order_id)+ 1 as Inv_id from " .$tableprefix. "orders ";
$excqry1=mysql_query($qry1);
if(mysql_num_rows($excqry1)>0) {
$row1=mysql_fetch_array($excqry1);
$Inv_id=$row1['Inv_id'] ;
}
else
{
$Inv_id =1;
}
Actually I bet what’s happening is that the database has gotten so large, that the queries are tripping over themselves. How big is this thing? show table status; (or show table status from myDatabaseName;). Or this way, perhaps:
Hmmm
+--------------------+------------------------------------------------------+------------+
| Database | Table | Size in MB |
+--------------------+------------------------------------------------------+------------+
| ismcfd2795 | product_impression | 5.77 |
| ismcfd2795 | order_details | 4.39 |
| ismcfd2795 | cart | 3.93 |
| far1114005361824 | wp_options | 3.78 |
| far1114005361824 | wp_wfHits | 2.80 |
| far1114005361824 | wp_rg_lead_detail | 2.18 |
| ismcfd2795 | artist_payments | 2.02 |
| mysql | help_topic | 1.58 |
| far1114005361824 | wp_wfConfig | 1.34 |
Those just aren’t all that huge.
mysql> select payment_date,artist_payment_id, payment_method, order_id, artist_id from artist_payments where order_id = 8013;
+--------------+-------------------+----------------+----------+-----------+
| payment_date | artist_payment_id | payment_method | order_id | artist_id |
+--------------+-------------------+----------------+----------+-----------+
| 2017-08-28 | 26002 | PAYPAL | 8013 | 3 |
| 2017-08-28 | 26001 | PAYPAL | 8013 | 44 |
| 2017-08-28 | 26000 | PAYPAL | 8013 | 1 |
+--------------+-------------------+----------------+----------+-----------+
Now Apache2 is crashing with errors:
[Wed Sep 06 18:08:19.841327 2017] [core:error] [pid 12399] AH00046: child process 7193 still did not exit, sending a SIGKILL
[Wed Sep 06 18:08:19.841344 2017] [core:error] [pid 12399] AH00046: child process 7196 still did not exit, sending a SIGKILL
[Wed Sep 06 18:08:20.847546 2017] [mpm_prefork:notice] [pid 12399] AH00169: caught SIGTERM, shutting down
Could be settings for Apache mpm_prefork, which could be tunes.
<IfModule mpm_worker_module>
StartServers 2
MinSpareThreads 25
MaxSpareThreads 75
ThreadLimit 64
ThreadsPerChild 25
MaxRequestWorkers 150
MaxConnectionsPerChild 0
</IfModule>
Want to clean out the old database rows, or at least count them.
mysql> SELECT COUNT(*) FROM product_impression;
+----------+
| COUNT(*) |
+----------+
| 112270 |
+----------+
Let’s clean this up, after backing up, of course.
mysql> SELECT * FROM product_impression WHERE visited_on > DATE_SUB(NOW() , INTERVAL 1 DAY);
135 rows in set (0.38 sec)
Okay that seems to work. Older than a year ago:
mysql> SELECT * FROM product_impression WHERE visited_on < DATE_SUB(NOW() , INTERVAL 1 YEAR);
70000 rows in set (0.38 sec)
Older than 2 years ago:
mysql> SELECT * FROM product_impression WHERE visited_on < DATE_SUB(NOW() , INTERVAL 2 YEAR);
26384
What about Six months ago?
mysql> SELECT * FROM product_impression WHERE visited_on < DATE_SUB(NOW() , INTERVAL 6 MONTH);
86680
Three months: 99141. One month: 107125.