Hi there,
We're running a few instances of Roundcube/Postfix/Nginx/Dovecot...
We've been facing high CPU usage on almost all our mail servers at the same time. Sometimes these spikes bog down the servers to unresponsiveness for up to some minutes.
These spikes occur at random times even at odd hours when no one could possibly be checking their emails.
After investigation the problem was tracked down to MySQL. Then after monitoring MySQL slow log we found these kind of entries at peak CPU usage times:
# User@Host: roundcube-user@server[roundcube-user@server] @ localhost []
# Thread_id: 50891 Schema: roundcube-db QC_hit: No
# Query_time: 2.376512 Lock_time: 0.000102 Rows_sent: 0 Rows_examined: 0
# Rows_affected: 1 Bytes_sent: 11
SET timestamp=1583135347;
INSERT INTO `session` (`sess_id`, `vars`, `ip`, `changed`) VALUES ('mq6aaf4kdtkj41bjs8q20923t9', 'dGVtcHxiOjE7bGFuZ3VhZ2V8czo1OiJlbl9VUyI7dGFza3xzOjU6ImxvZ2luIjtza2luX2NvbmZpZ3xhOjU6e3M6NjoibGF5b3V0IjtzOjEwOiJ3aWRlc2NyZWVuIjtzOjIyOiJqcXVlcnlfdWlfY29sb3JzX3RoZW1lIjtzOjk6ImJvb3RzdHJhcCI7czoxODoiZW1iZWRfY3NzX2xvY2F0aW9uIjtzOjE3OiIvc3R5bGVzL2VtYmVkLmNzcyI7czoxOToiZWRpdG9yX2Nzc19sb2NhdGlvbiI7czoxNzoiL3N0eWxlcy9lbWJlZC5jc3MiO3M6MjY6Im1lZGlhX2Jyb3dzZXJfY3NzX2xvY2F0aW9uIjtzOjQ6Im5vbmUiO31yZXF1ZXN0X3Rva2VufHM6MzI6IlY5eFRNWVlaQWVkMnR6eEdxaHcxQ0xtMGs4U1JxUnBEIjs=', '45.76.202.144', now());
# Time: 200302 12:49:23
# User@Host: roundcube-user@server[roundcube-user@server] @ localhost []
# Thread_id: 50900 Schema: roundcube-db QC_hit: No
# Query_time: 2.530787 Lock_time: 0.000058 Rows_sent: 0 Rows_examined: 0
# Rows_affected: 1 Bytes_sent: 11
SET timestamp=1583135363;
INSERT INTO `session` (`sess_id`, `vars`, `ip`, `changed`) VALUES ('vrq7rabdlkhqkon2qs7dcnnp7o', 'dGVtcHxiOjE7bGFuZ3VhZ2V8czo1OiJlbl9VUyI7dGFza3xzOjU6ImxvZ2luIjtza2luX2NvbmZpZ3xhOjU6e3M6NjoibGF5b3V0IjtzOjEwOiJ3aWRlc2NyZWVuIjtzOjIyOiJqcXVlcnlfdWlfY29sb3JzX3RoZW1lIjtzOjk6ImJvb3RzdHJhcCI7czoxODoiZW1iZWRfY3NzX2xvY2F0aW9uIjtzOjE3OiIvc3R5bGVzL2VtYmVkLmNzcyI7czoxOToiZWRpdG9yX2Nzc19sb2NhdGlvbiI7czoxNzoiL3N0eWxlcy9lbWJlZC5jc3MiO3M6MjY6Im1lZGlhX2Jyb3dzZXJfY3NzX2xvY2F0aW9uIjtzOjQ6Im5vbmUiO31yZXF1ZXN0X3Rva2VufHM6MzI6IjhmRDRQd3ZQRXh2Uk00V0JjQ0ExSzdhc1lIeHlYaUxlIjs=', '138.197.17.201', now());
All these IPs don't belong to any valid mail user, but belong to our tracking software from hetrixtools.com: https://docs.hetrixtools.com/uptime-monitoring-ip-addresses/
Here's an entry from Roundcube access log:
Uptime Monitoring Bot. https://hetrix.tools/uptime-monitoring-bot.html" "-"
138.197.17.201 - - [02/Mar/2020:13:57:16 +0500] "GET / HTTP/1.1" 200 5163 "-" "HetrixTools Uptime Monitoring Bot. https://hetrix.tools/uptime-monitoring-bot.html" "-"
We're using the latest versions of Roundcube with the new mobile theme.
On Hetrixtools we're monitoring the Roundcube Hompage and accepted http codes are: 200 & 401
Can you please look into this issue?
Thanks in advance.
Well, the resolution was simple. Now instead of monitoring Roundcube Login page, we're monitoring the server default home page.
But still we're unable to find why such simple queries which should not take more than a few seconds took more than 100 seconds:
# Time: 200302 12:17:46
# User@Host: roundcube-user[roundcube-user] @ localhost []
# Thread_id: 50484 Schema: roundcube-db QC_hit: No
# Query_time: 104.395986 Lock_time: 0.000098 Rows_sent: 0 Rows_examined: 0
# Rows_affected: 1 Bytes_sent: 11
SET timestamp=1583133466;
INSERT INTO `session` (`sess_id`, `vars`, `ip`, `changed`) VALUES ('tce17vg4sm2ircs63uhq1leomt', 'dGVtcHxiOjE7bGFuZ3VhZ2V8czo1OiJlbl9VUyI7dGFza3xzOjU6ImxvZ2luIjtza2luX2NvbmZpZ3xhOjU6e3M6NjoibGF5b3V0IjtzOjEwOiJ3aWRlc2NyZWVuIjtzOjIyOiJqcXVlcnlfdWlfY29sb3JzX3RoZW1lIjtzOjk6ImJvb3RzdHJhcCI7czoxODoiZW1iZWRfY3NzX2xvY2F0aW9uIjtzOjE3OiIvc3R5bGVzL2VtYmVkLmNzcyI7czoxOToiZWRpdG9yX2Nzc19sb2NhdGlvbiI7czoxNzoiL3N0eWxlcy9lbWJlZC5jc3MiO3M6MjY6Im1lZGlhX2Jyb3dzZXJfY3NzX2xvY2F0aW9uIjtzOjQ6Im5vbmUiO31yZXF1ZXN0X3Rva2VufHM6MzI6Im9tdHdIa0tzbWJPczhlTFo4OUQzcVVlcGZVcHBLZGw4Ijs=', '52.23.120.125', now());
# User@Host: roundcube-user[roundcube-user] @ localhost []
# Thread_id: 50485 Schema: roundcube-db QC_hit: No
# Query_time: 102.024901 Lock_time: 0.000089 Rows_sent: 0 Rows_examined: 0
# Rows_affected: 1 Bytes_sent: 11
SET timestamp=1583133466;
INSERT INTO `session` (`sess_id`, `vars`, `ip`, `changed`) VALUES ('ok02o7otd3af6pi05cdps0lfso', 'dGVtcHxiOjE7bGFuZ3VhZ2V8czo1OiJlbl9VUyI7dGFza3xzOjU6ImxvZ2luIjtza2luX2NvbmZpZ3xhOjU6e3M6NjoibGF5b3V0IjtzOjEwOiJ3aWRlc2NyZWVuIjtzOjIyOiJqcXVlcnlfdWlfY29sb3JzX3RoZW1lIjtzOjk6ImJvb3RzdHJhcCI7czoxODoiZW1iZWRfY3NzX2xvY2F0aW9uIjtzOjE3OiIvc3R5bGVzL2VtYmVkLmNzcyI7czoxOToiZWRpdG9yX2Nzc19sb2NhdGlvbiI7czoxNzoiL3N0eWxlcy9lbWJlZC5jc3MiO3M6MjY6Im1lZGlhX2Jyb3dzZXJfY3NzX2xvY2F0aW9uIjtzOjQ6Im5vbmUiO31yZXF1ZXN0X3Rva2VufHM6MzI6ImZSVmUzM2xxbkVmVk1JUHVKR01wMkl3VHJGT3B6ZkdXIjs=', '178.62.11.90', now());
# User@Host: roundcube-user[roundcube-user] @ localhost []
# Thread_id: 50486 Schema: roundcube-db QC_hit: No
# Query_time: 101.761692 Lock_time: 0.000082 Rows_sent: 0 Rows_examined: 0
# Rows_affected: 1 Bytes_sent: 11
SET timestamp=1583133466;
INSERT INTO `session` (`sess_id`, `vars`, `ip`, `changed`) VALUES ('hqfr247seta2ia8ir2ejnira4g', 'dGVtcHxiOjE7bGFuZ3VhZ2V8czo1OiJlbl9VUyI7dGFza3xzOjU6ImxvZ2luIjtza2luX2NvbmZpZ3xhOjU6e3M6NjoibGF5b3V0IjtzOjEwOiJ3aWRlc2NyZWVuIjtzOjIyOiJqcXVlcnlfdWlfY29sb3JzX3RoZW1lIjtzOjk6ImJvb3RzdHJhcCI7czoxODoiZW1iZWRfY3NzX2xvY2F0aW9uIjtzOjE3OiIvc3R5bGVzL2VtYmVkLmNzcyI7czoxOToiZWRpdG9yX2Nzc19sb2NhdGlvbiI7czoxNzoiL3N0eWxlcy9lbWJlZC5jc3MiO3M6MjY6Im1lZGlhX2Jyb3dzZXJfY3NzX2xvY2F0aW9uIjtzOjQ6Im5vbmUiO31yZXF1ZXN0X3Rva2VufHM6MzI6Ims4Qm1oaDFOdkRsQmp2a3FwV3dKWFZXSWhYem1FcmFvIjs=', '45.76.202.144', now());
# User@Host: roundcube-user[roundcube-user] @ localhost []
# Thread_id: 50487 Schema: roundcube-db QC_hit: No
# Query_time: 94.440567 Lock_time: 0.000131 Rows_sent: 0 Rows_examined: 0
# Rows_affected: 1 Bytes_sent: 11