Random Musings of an Insane Mind

A few months ago we had a client that wanted to run Nginx/FastCGI rather than Apache because it was known to be faster. While we’ve had extensive experience performance tuning various webserver combinations, the workload proposed would really have been better served with Apache. While we inherited this problem from another hosting company — he moved because they couldn’t fix the performance issues — he maintained that Nginx/FastCGI for PHP was the fastest because of all of the benchmarks that had been run on the internet.

While the conversion to or from one server to another is usually painful, much of the pain can be avoided by running Apache on an alternate port, testing, then, swapping the configuration around. The graph below shows when we changed from Nginx to Apache:

We made the conversion from Nginx to Apache on Friday. Once we made the conversion, there were issues with the machine which was running an older kernel. After reviewing the workload, we migrated from 2.6.31.1 with the Anticipatory Scheduler to 2.6.34 with the Deadline Scheduler. Three other machines had been running 2.6.33.1 with the CFQ scheduler and showed no issues at the 10mb/sec mark, but, we felt that we might benchmark his workload using deadline. We’ve run a number of high-end webservers with both Anticipatory and CFQ prior to 2.6.33 and for most of our workloads, Anticipatory seemed to win. With 2.6.33, Anticipatory was removed, leaving NOOP, CFQ and Deadline. While we have a few MySQL servers running Deadline, this is probably the first heavy-use webserver that we’ve moved from CFQ/AS to Deadline.

The dips in the daily graph were during times where a cron job was running. The two final dips were during the kernel installation.

All in all, the conversion went well. The machine never really appeared to be slow, but, it is obvious that it is now handling more traffic. The load averages are roughly the same as they were before. CPU utilization is roughly the same, but, more importantly, Disk I/O is about half what it was and System now hovers around 3-4%. During the hourly cron job, the machine is not having issues like it was before.

Nginx isn’t always the best solution. In this case, 100% of the traffic is serving an 8k-21k php script to each visitor. Static content is served from another machine running Nginx.

While I do like Nginx, it is always best to use the right tool for the job. In this case, Apache happened to be the right tool.

This morning a client’s machine alerted several times due to high load. As the machine runs roughly 50 wordpress powered sites and rarely has issues, we did some investigation. Evidently a bot called SEOProfiler was hitting the machine and causing problems.

From SEOProfiler’s page, http://www.seoprofiler.com/bot/,

The spbot is bandwidth-friendly. It tries to wait at least 5 minutes until it visits another page of your domain. In general, it takes days or weeks until spbot visits another page of your website.

Oh really?

In a three hour period on a machine with 50 domains:

# grep -l '+http://www.seoprofiler.com/bot/' *.log|wc -l
50
# grep '+http://www.seoprofiler.com/bot/' *.log|wc -l
375938

In a period of three and a half hours, I calculate that to be roughly two pages per second requested.

Let’s see how friendly they really are:

# grep seoprofiler.com xxxxxx.com-access.log | grep 'GET /robots.txt ' | wc -l
2005

2005 requests for robots.txt in three and a half hours, well, at least they are checking.

# grep seoprofiler.com xxxxxx.com-access.log | grep -v 'GET /robots.txt ' |wc -l
1883

1883 requests for documents in that same period. They actually requested robots.txt more frequently than pages on this particular domain. Here are the first 50 lines from one of the sites on this machine with robots.txt requests excluded:

67.202.41.44 - - [07/Feb/2010:06:38:13 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 11857 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
75.101.214.118 - - [07/Feb/2010:06:38:15 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 10214 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
174.129.65.79 - - [07/Feb/2010:06:38:41 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 71830 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
72.44.54.185 - - [07/Feb/2010:06:38:45 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 20829 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
67.202.48.58 - - [07/Feb/2010:06:38:48 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 19576 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
174.129.172.253 - - [07/Feb/2010:06:39:32 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 73199 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
174.129.65.79 - - [07/Feb/2010:06:39:47 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 60596 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
174.129.191.9 - - [07/Feb/2010:06:39:50 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 21406 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
204.236.242.36 - - [07/Feb/2010:06:39:51 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 24076 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
72.44.48.77 - - [07/Feb/2010:06:40:10 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 29957 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
174.129.65.79 - - [07/Feb/2010:06:40:15 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 9871 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
204.236.242.36 - - [07/Feb/2010:06:40:40 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 11748 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
174.129.172.253 - - [07/Feb/2010:06:40:43 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 10781 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
75.101.197.161 - - [07/Feb/2010:06:40:44 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 14995 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
174.129.93.177 - - [07/Feb/2010:06:40:45 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 72244 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
204.236.197.86 - - [07/Feb/2010:06:40:57 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 13103 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
174.129.172.253 - - [07/Feb/2010:06:40:58 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 12032 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
67.202.0.47 - - [07/Feb/2010:06:41:05 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 17798 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
75.101.254.111 - - [07/Feb/2010:06:41:22 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 38199 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
174.129.65.79 - - [07/Feb/2010:06:41:38 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 17484 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
204.236.197.86 - - [07/Feb/2010:06:41:41 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 23264 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
174.129.103.67 - - [07/Feb/2010:06:41:47 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 17145 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
72.44.42.173 - - [07/Feb/2010:06:41:48 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 23440 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
204.236.244.231 - - [07/Feb/2010:06:41:50 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 29496 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
75.101.214.118 - - [07/Feb/2010:06:41:52 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 69694 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
174.129.140.41 - - [07/Feb/2010:06:41:56 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 14958 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
72.44.48.77 - - [07/Feb/2010:06:42:41 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 12272 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
72.44.54.185 - - [07/Feb/2010:06:42:55 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 60345 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
67.202.16.163 - - [07/Feb/2010:06:43:03 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 16470 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
204.236.242.36 - - [07/Feb/2010:06:43:04 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 21739 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
174.129.103.67 - - [07/Feb/2010:06:43:05 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 59288 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
174.129.152.208 - - [07/Feb/2010:06:43:05 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 11407 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
72.44.42.173 - - [07/Feb/2010:06:43:09 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 14459 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
67.202.0.47 - - [07/Feb/2010:06:43:31 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 10561 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
174.129.93.177 - - [07/Feb/2010:06:43:46 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 14947 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
174.129.152.208 - - [07/Feb/2010:06:43:50 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 19598 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
174.129.140.41 - - [07/Feb/2010:06:43:55 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 12090 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
174.129.140.41 - - [07/Feb/2010:06:44:05 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 11853 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
75.101.254.111 - - [07/Feb/2010:06:44:16 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 11612 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
67.202.41.44 - - [07/Feb/2010:06:44:15 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 71920 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
67.202.0.47 - - [07/Feb/2010:06:44:22 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 14007 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
174.129.191.9 - - [07/Feb/2010:06:44:31 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 130288 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
75.101.254.111 - - [07/Feb/2010:06:45:01 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 21739 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
204.236.242.36 - - [07/Feb/2010:06:45:26 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 18281 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
174.129.65.79 - - [07/Feb/2010:06:45:32 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 59638 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
174.129.103.67 - - [07/Feb/2010:06:45:40 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 12372 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
174.129.65.79 - - [07/Feb/2010:06:46:04 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 14353 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
72.44.54.185 - - [07/Feb/2010:06:46:07 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 27416 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
174.129.152.208 - - [07/Feb/2010:06:46:13 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 22271 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
75.101.197.161 - - [07/Feb/2010:06:46:13 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 14548 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"

While we don’t see many duplicate IPs here, let’s analyze the one that has six hits:

174.129.65.79 - - [07/Feb/2010:06:38:41 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 71830 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
174.129.65.79 - - [07/Feb/2010:06:39:47 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 60596 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
174.129.65.79 - - [07/Feb/2010:06:40:15 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 9871 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
174.129.65.79 - - [07/Feb/2010:06:41:38 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 17484 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
174.129.65.79 - - [07/Feb/2010:06:45:32 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 59638 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
174.129.65.79 - - [07/Feb/2010:06:46:04 -0500] "GET /xxxxx/xxxxx/xxxxx.html HTTP/1.1" 200 14353 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"

The longest delay between page fetches is 3 minutes, 54 seconds, with a minimum of 28 seconds.

In that same period of time, you can see that they used a number of Amazon ECS instances:

  10655 67.202.0.47
  10454 204.236.242.36
  10353 174.129.103.67
  10343 75.101.254.111
  10295 204.236.197.86
  10128 174.129.65.79
   9908 174.129.191.9
   9883 75.101.214.118
   9835 72.44.54.185
   9833 72.44.42.173
   9769 174.129.136.94
   9718 75.101.197.161
   9290 174.129.106.91
   9063 72.44.48.77
   9017 174.129.152.208
   8850 204.236.212.138
   8712 174.129.93.177
   8423 174.129.140.41
   8415 67.202.41.44
   8302 67.202.16.163
   8116 72.44.57.92
   7923 204.236.245.5
   7633 75.101.219.131
   7519 67.202.48.58
   7510 174.129.72.66
   7429 67.202.2.164
   7356 174.129.155.12
   7335 174.129.172.253
   7036 75.101.214.102
   6998 67.202.42.161
   6835 174.129.159.143
   6109 204.236.244.231
   6002 174.129.127.87
   5961 75.101.168.14
   5841 174.129.84.116
   5201 174.129.163.50
   5114 72.44.49.238
   4744 174.129.153.52
   4654 75.101.241.159
   4615 204.236.241.141
   4585 75.101.179.97
   4463 174.129.61.74
   4387 75.101.179.141
   4379 72.44.56.37
   4332 75.101.187.208
   4169 67.202.56.227
   4106 204.236.211.119
   4075 174.129.93.123
   3722 204.236.242.141
   3332 67.202.11.26
   3276 67.202.0.31
   3097 174.129.171.75
   2360 75.101.234.148
   1837 174.129.136.47
   1689 67.202.56.158
    853 67.202.10.125
     67 75.101.204.87
     14 204.236.212.231
     12 174.129.144.34
      6 174.129.106.64

Even if we look at only one of the domains that was spidered:

    125 72.44.48.77
    123 174.129.140.41
    112 174.129.65.79
    109 75.101.254.111
    108 174.129.172.253
    104 75.101.197.161
    104 174.129.93.177
    104 174.129.103.67
    102 204.236.197.86
    102 174.129.136.94
    101 67.202.2.164
     99 75.101.214.118
     98 67.202.0.47
     96 67.202.48.58
     95 204.236.212.138
     93 174.129.106.91
     86 67.202.41.44
     85 72.44.54.185
     84 204.236.242.36
     82 75.101.219.131
     82 72.44.42.173
     76 67.202.42.161
     76 174.129.191.9
     75 174.129.152.208
     73 72.44.57.92
     73 67.202.16.163
     71 75.101.168.14
     71 174.129.159.143
     68 204.236.245.5
     68 174.129.72.66
     61 174.129.155.12
     60 204.236.244.231
     60 204.236.211.119
     59 174.129.153.52
     58 72.44.49.238
     54 72.44.56.37
     54 174.129.93.123
     54 174.129.61.74
     51 75.101.179.141
     51 174.129.163.50
     50 204.236.242.141
     47 174.129.127.87
     45 75.101.241.159
     44 75.101.214.102
     43 67.202.56.227
     42 174.129.171.75
     41 67.202.11.26
     40 67.202.0.31
     39 75.101.187.208
     39 204.236.241.141
     36 174.129.84.116
     32 75.101.179.97
     30 75.101.234.148
     22 174.129.136.47
     19 67.202.56.158
     12 67.202.10.125

While their goals stated on their page are admirable, it is clear that they lack some understanding of how ECS works. Writing code to run across distributed instances is not a simple process, so, I can see where handing out spider assignments to nodes could run into problems. But, looking at a single IP address, we can see that their bot probably doesn’t maintain state between fetches since it fetches robots.txt prior to each URL and then violates their ‘no more than one page every five minutes’.

72.44.48.77 - - [07/Feb/2010:06:40:10 -0500] "GET /robots.txt HTTP/1.1" 200 2631 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
72.44.48.77 - - [07/Feb/2010:06:40:10 -0500] "GET / HTTP/1.1" 200 29957 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
72.44.48.77 - - [07/Feb/2010:06:42:40 -0500] "GET /robots.txt HTTP/1.1" 200 2631 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
72.44.48.77 - - [07/Feb/2010:06:42:41 -0500] "GET /xxxxxx/xxxxxx/xxxxxx.html HTTP/1.1" 200 12272 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
72.44.48.77 - - [07/Feb/2010:06:49:26 -0500] "GET /robots.txt HTTP/1.1" 200 2631 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
72.44.48.77 - - [07/Feb/2010:06:49:26 -0500] "GET /xxxxxx/xxxxxx/xxxxxx.html HTTP/1.1" 200 16855 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
72.44.48.77 - - [07/Feb/2010:06:53:11 -0500] "GET /robots.txt HTTP/1.1" 200 2631 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"
72.44.48.77 - - [07/Feb/2010:06:53:11 -0500] "GET /xxxxxx/xxxxxx/xxxxxx.html HTTP/1.1" 200 68020 "-" "Mozilla/5.0 (compatible; spbot/1.0; +http://www.seoprofiler.com/bot/ )"

Based on the times, I don’t believe they could have spun up a new ECS instance on the same IP address which leads me to believe that they are spidering links from the site and requesting robots.txt each time.

While I believe using cloud services is a good thing, companies like this that abuse it are going to cause problems for other people that adopt the same methods. Amazon’s ECS instances have already hit numerous anti-spam blacklists due to Amazon’s lax policy or inability to quickly track down spam. While I have resisted the temptation to block ECS instances for inbound email, this client requested that we block the IP addresses that SEOProfilerBot was coming from – which means that any other search engine that comes along that uses Amazon’s ECS will not be able to reach his sites.

Cuill did the same thing to his sites a while back and we altered the robots.txt file, but, that didn’t stop the constant pounding from their spiders that had already fetched the robots.txt.

At some point, Amazon ECS and other cloud vendors will be firewalled from large portions of the net — limiting the usefulness of writing applications that run on the cloud.

After building a system for the new backup servers that utilized an Adaptec 31205 controller, I always prefer to use a kernel that we’ve tuned inhouse.

Upon booting into the kernel I had built, I received:

unable to mount root fs on unknown-block(0,0)

Since the drive size on the array was very large, the Debian Installer automatically created an EFI GUID Partition table, which my kernel was not set up for.

In the kernel makemenu, File Systems, Partition Types, enable Advanced partition selection. Near the bottom is EFI GUID Partition support. Enable that, recompile your kernel and you should be set.

One reboot later and voila:

st1:/colobk1# uname -a
Linux st1 2.6.32.7 #1 SMP Fri Jan 29 21:43:32 EST 2010 x86_64 GNU/Linux
st1:/colobk1# df -h
Filesystem            Size  Used Avail Use% Mounted on
/dev/sda1             462M  232M  207M  53% /
tmpfs                 2.0G     0  2.0G   0% /lib/init/rw
udev                   10M   60K   10M   1% /dev
tmpfs                 2.0G     0  2.0G   0% /dev/shm
/dev/sda8              19T  305G   18T   2% /colobk1
/dev/sda5             1.9G   55M  1.8G   3% /home
/dev/sda4             949M  4.2M  945M   1% /tmp
/dev/sda6             2.4G  204M  2.2G   9% /usr
/dev/sda7             9.4G  237M  9.1G   3% /var

With a few words of warning, we upgraded one of our clusters from 2.2 to 3.0.4. While this is normally a seamless project, it needed to be coordinated with both storage nodes in the cluster since the changes from 2.2 to 3.0 in openais were incompatible. Some minor changes to the cluster config file were needed which results in a cleaner file, and, a new dependency for rgmanager was added for the upgrade to 3.0.

This meant some downtime while openais was upgraded. Since we run behind a pair of load balancers, we were able to shut down the first filesystem, disconnect it from cman, upgrade one side, shut off the services on the other, bring this side up, bring up services, then upgrade the second node.

While this should have worked, cman on the primary node had no problem, but the secondary node refused to start dlm_controld.

Dec 10 12:29:20 dlm_controld dlm_controld 3.0.4 started
Dec 10 12:29:30 dlm_controld cannot find device /dev/misc/lock_dlm_plock with minor 58

For some odd reason, lock_dlm_plock was created in /dev rather than /dev/misc after the udev upgrade. Moving it into place allowed cman to start on the second node, and, allowed the cluster to run in non-degraded mode.

Why lock_dlm_plock was in the wrong place on one node and in the correct place on the other node, I’m not sure. I think prior to rgmanager being installed, the init script for cman didn’t stop when dlm couldn’t be loaded, and since the /dev/misc folder hadn’t been created, it created the lock file in /dev. Subsequent restarts of the machine have resulted in it coming up without an issue, so, it appears to be an issue somewhere in one of the startup scripts.

After installing Varnish 2.0.5 on a machine, ESI Includes didn’t work. When using varnishlog, the first error that occurred when debugging was:

No ESI processing, first char not ‘< '

   12 SessionClose – timeout
   12 StatSess     – 124.177.181.149 50662 4 0 0 0 0 0 0 0
   12 SessionOpen  c 68.212.183.136 60087 66.244.147.44:80
   12 ReqStart     c 68.212.183.136 60087 409391565
   12 RxRequest    c GET
   12 RxURL        c /esi.html
   12 RxProtocol   c HTTP/1.1
   12 RxHeader     c Host: cd34.colocdn.com
   12 RxHeader     c User-Agent: Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10.6; en-US; rv:1.9.2b4) Gecko/20091124 Firefox/3.6b4
   12 RxHeader     c Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
   12 RxHeader     c Accept-Language: en-us,en;q=0.5
   12 RxHeader     c Accept-Encoding: gzip,deflate
   12 RxHeader     c Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
   12 RxHeader     c Keep-Alive: 115
   12 RxHeader     c Connection: keep-alive
   12 RxHeader     c X-lori-time-1: 1259718658980
   12 RxHeader     c Cache-Control: max-age=0
   12 VCL_call     c recv
   12 VCL_return   c lookup
   12 VCL_call     c hash
   12 VCL_return   c hash
   12 VCL_call     c miss
   12 VCL_return   c fetch
   12 Backend      c 14 cd34_com cd34_com
   12 ObjProtocol  c HTTP/1.1
   12 ObjStatus    c 200
   12 ObjResponse  c OK
   12 ObjHeader    c Date: Wed, 02 Dec 2009 01:50:59 GMT
   12 ObjHeader    c Server: Apache
   12 ObjHeader    c Vary: Accept-Encoding
   12 ObjHeader    c Content-Encoding: gzip
   12 ObjHeader    c Content-Type: text/html
   12 TTL          c 409391565 RFC 120 1259718659 0 0 0 0
   12 VCL_call     c fetch
   12 TTL          c 409391565 VCL 43200 1259718659
   12 ESI_xmlerror c No ESI processing, first char not ‘< '
   12 TTL          c 409391565 VCL 0 1259718659
   12 VCL_info     c XID 409391565: obj.prefetch (-30) less than ttl (-1), ignored.
   12 VCL_return   c deliver
   12 Length       c 68
   12 VCL_call     c deliver
   12 VCL_return   c deliver
   12 TxProtocol   c HTTP/1.1
   12 TxStatus     c 200
   12 TxResponse   c OK
   12 TxHeader     c Server: Apache
   12 TxHeader     c Vary: Accept-Encoding
   12 TxHeader     c Content-Encoding: gzip
   12 TxHeader     c Content-Type: text/html
   12 TxHeader     c Content-Length: 68
   12 TxHeader     c Date: Wed, 02 Dec 2009 01:50:59 GMT
   12 TxHeader     c X-Varnish: 409391565
   12 TxHeader     c Age: 0
   12 TxHeader     c Via: 1.1 varnish
   12 TxHeader     c Connection: keep-alive
   12 TxHeader     c X-Cache: MISS
   12 ReqEnd       c 409391565 1259718659.088263512 1259718659.127703667 0.000059366 0.039401770 0.000038385
   12 Debug        c "herding"

ESI received significant performance enhancements in 2.0.4 and 2.0.5 so, it seemed something was incompatible. Downgrading to 2.0.3 and using the VCL from another machine still resulted in ESI not working.

In this case, mod_deflate was running on the backend which was causing the issue. However, in reading the source code, it appears that message could also occur if your ESI include wasn’t handing back properly formed XML/HTML content. If your include doesn’t contain valid content and is only returning a small snippet, you might consider passing:

-p esi_syntax=0x1

on the command line that starts Varnish.

The changes in Varnish address the issue of ESI being enabled on binary content. Since the first character isn’t an < in almost all binary files (jpg, mpg, gif) and isn't the start of most .css/.js files, varnish doesn't need to spend extra time checking those files for includes. While you can and should selectively enable esi processing, this is just an added safeguard and a performance boost to compensate for vcl that might have an esi directive on static/binary content. Since Varnish 2.0.3 now worked properly with the new machine, we upgraded to Varnish 2.0.5 which introduced a very odd issue:

[Tue Dec 01 20:58:11 2009] [error] [client 66.244.147.40] File does not exist: /gfs/www/cd/cd34.com/index.htmlt
[Tue Dec 01 20:58:13 2009] [error] [client 66.244.147.40] File does not exist: /gfs/www/cd/cd34.com/index.html7
[Tue Dec 01 20:58:24 2009] [error] [client 66.244.147.40] File does not exist: /gfs/www/cd/cd34.com/index.html\xfa
[Tue Dec 01 20:59:01 2009] [error] [client 66.244.147.40] File does not exist: /gfs/www/cd/cd34.com/index.html\xb5
[Tue Dec 01 20:59:06 2009] [error] [client 66.244.147.40] File does not exist: /gfs/www/cd/cd34.com/index.html\xe7
[Tue Dec 01 20:59:07 2009] [error] [client 66.244.147.40] File does not exist: /gfs/www/cd/cd34.com/index.html\xd4
[Tue Dec 01 20:59:08 2009] [error] [client 66.244.147.40] File does not exist: /gfs/www/cd/cd34.com/index.html\x1c

This generated 404s on the piece of the page that contained the ESI include. Downgrading to 2.0.4 fixed the issue and the issue appears to already be fixed in Trunk. Varnish Ticket #585

Varnish 2.0.4 and mod_deflate disabled addressed the two issues that prevented ESI from working correctly on this new installation.