CRIN Trac: Ticket #75: Load spike and small downtime

hours changed; totalhours set

chris — Sun, 03 Jul 2016 18:00:35 GMT

hours changed from 0 to 0.25
totalhours set to 0.25

attachment set

chris — Sun, 03 Jul 2016 18:12:26 GMT

attachment set to memcached_rates-day.png

attachment set

chris — Sun, 03 Jul 2016 18:12:37 GMT

attachment set to memcached_bytes-day.png

attachment set

chris — Sun, 03 Jul 2016 18:12:52 GMT

attachment set to fw_conntrack-day.png

attachment set

chris — Sun, 03 Jul 2016 18:13:06 GMT

attachment set to if_eth0-day.png

attachment set

chris — Sun, 03 Jul 2016 18:13:19 GMT

attachment set to fw_packets-day.png

attachment set

chris — Sun, 03 Jul 2016 18:13:37 GMT

attachment set to nginx_request-day.png

attachment set

chris — Sun, 03 Jul 2016 18:13:48 GMT

attachment set to phpfpm_connections-day.png

attachment set

chris — Sun, 03 Jul 2016 18:14:20 GMT

attachment set to phpfpm_average-day.png

attachment set

chris — Sun, 03 Jul 2016 18:14:34 GMT

attachment set to phpfpm_status-day.png

attachment set

chris — Sun, 03 Jul 2016 18:14:51 GMT

attachment set to cpu-day.png

hours, totalhours changed

chris — Sun, 03 Jul 2016 18:27:37 GMT

hours changed from 0 to 0.25
totalhours changed from 0.25 to 0.5

The down email:

Subject: PROBLEM - CRIN2.webarch.net - http is CRITICAL
Date: Sun, 03 Jul 2016 18:33:56 +0100
***** Icinga  *****
Notification Type: PROBLEM
Service: http
Host: CRIN2.webarch.net
Address: 93.95.228.180
State: CRITICAL
Date/Time: 2016-07-03 18:33:56 +0100
Additional Info: CRITICAL - Socket timeout after 10 seconds

And the up email:

Subject: RECOVERY - CRIN2.webarch.net - http is OK
Date: Sun, 03 Jul 2016 18:34:17 +0100
***** Icinga  *****
Notification Type: RECOVERY
Service: http
Host: CRIN2.webarch.net
Address: 93.95.228.180
State: OK
Date/Time: 2016-07-03 18:34:17 +0100
Additional Info: HTTP OK: HTTP/1.1 200 OK - 76033 bytes in 0.516 second response time

Some of the munin graphs illustrating what is going on:

I have restarted nginx, memcache and php5-fpm and tried running strace on onve of the php5-fpm processes which was using 100% of one CPU (see also ticket:73):

date ; strace -c -p 11524 ; date
Sun Jul  3 18:23:38 GMT 2016
Process 11524 attached
^CProcess 11524 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 97.88    0.012495          46       272           brk
  1.60    0.000204           0      1014           sendto
  0.52    0.000066           0       861        37 access
  0.00    0.000000           0        72           read
  0.00    0.000000           0        13           write
  0.00    0.000000           0        27           open
  0.00    0.000000           0        45           close
  0.00    0.000000           0       235        16 stat
  0.00    0.000000           0        26           fstat
  0.00    0.000000           0        30         4 lstat
  0.00    0.000000           0       665           poll
  0.00    0.000000           0        28           lseek
  0.00    0.000000           0        23           mmap
  0.00    0.000000           0        23           munmap
  0.00    0.000000           0         4           rt_sigaction
  0.00    0.000000           0         4           rt_sigprocmask
  0.00    0.000000           0       671           ioctl
  0.00    0.000000           0       685           select
  0.00    0.000000           0        18           setitimer
  0.00    0.000000           0         8           socket
  0.00    0.000000           0         8         8 connect
  0.00    0.000000           0         4           accept
  0.00    0.000000           0      1716           recvfrom
  0.00    0.000000           0        10           shutdown
  0.00    0.000000           0        20           setsockopt
  0.00    0.000000           0         8           getsockopt
  0.00    0.000000           0        51           fcntl
  0.00    0.000000           0         4           getdents
  0.00    0.000000           0        52           getcwd
  0.00    0.000000           0         9           chdir
  0.00    0.000000           0       591           gettimeofday
  0.00    0.000000           0         9           times
  0.00    0.000000           0        27           clock_gettime
  0.00    0.000000           0         2           openat
------ ----------- ----------- --------- --------- ----------------
100.00    0.012765                  7235        65 total
Sun Jul  3 18:24:40 GMT 2016

I don't know if the cause of this is external (the firewall graph indicate that it might be) or not.

hours, totalhours changed

chris — Mon, 04 Jul 2016 11:03:08 GMT

hours changed from 0 to 0.45
totalhours changed from 0.5 to 0.95

The high load and increased bandwidth usage is ongoing and looking at the access logs one IP address stands out:

grep "149.202.198.122" crin.org.access.log | wc -l
36769
grep "149.202.198.122" crin.org.access.log.1 | wc -l
83084

This looks like a dynamic IP address:

dig -x 149.202.198.122 +short
ns3025239.ip-149-202-198.eu.

The total number of requests: 119,853

It is having an adverse impact on other users and after watching the logs for a while and ponding all the options I have blocked the IP address using iptables as it is basically abuse.

attachment set

chris — Mon, 04 Jul 2016 12:27:18 GMT

attachment set to 2016-06-04_load-day.png

attachment set

chris — Mon, 04 Jul 2016 12:27:31 GMT

attachment set to 2016-06-04_cpu-day.png

attachment set

chris — Mon, 04 Jul 2016 12:27:52 GMT

attachment set to 2016-06-04_phpfpm_connections-day.png

attachment set

chris — Mon, 04 Jul 2016 12:28:25 GMT

attachment set to 2016-06-04_fw_packets-day.png

attachment set

chris — Mon, 04 Jul 2016 12:29:21 GMT

attachment set to 2016-06-04_if_eth0-day.png

attachment set

chris — Mon, 04 Jul 2016 12:30:04 GMT

attachment set to 2016-06-04_fw_conntrack-day.png

attachment set

chris — Mon, 04 Jul 2016 12:30:50 GMT

attachment set to 2016-06-04_memcached_rates-day.png

hours, status, totalhours changed; resolution set

chris — Mon, 04 Jul 2016 12:33:54 GMT

hours changed from 0 to 0.25
status changed from new to closed
resolution set to fixed
totalhours changed from 0.95 to 1.2

Blocking that one abusive IP address appears to have solved this issue, see these graphs:

Closing this ticket.