{"id":1523,"date":"2012-11-06T22:36:53","date_gmt":"2012-11-06T20:36:53","guid":{"rendered":"http:\/\/www.void.gr\/kargig\/blog\/?p=1523"},"modified":"2012-11-06T22:40:43","modified_gmt":"2012-11-06T20:40:43","slug":"when-in-doubt-always-blame-the-application","status":"publish","type":"post","link":"https:\/\/www.void.gr\/kargig\/blog\/2012\/11\/06\/when-in-doubt-always-blame-the-application\/","title":{"rendered":"When in doubt, always blame the application"},"content":{"rendered":"

When you have a misbehaving system and you are not sure what the problem is, always bet on a poorly written application.<\/p>\n

Here’s a small example of how another poorly written web application caused system issues.<\/p>\n

I was sitting at my office today I when I got this nagios alert for a host.<\/p>\n

Date\/Time: Tue Nov 6 19:15:11 EET 2012
\nAdditional Info:
\nSWAP CRITICAL – 0% free (0 MB out of 509 MB)<\/p><\/blockquote>\n

Logging in actually showed all the swap’s been used and so was RAM, 0.95\/1Gb. Lots of apache2 server instances were running. I did a netstat and I saw a lot of ESTABLISHED connections:<\/p>\n

tcp6       0      0 2001:DB8:f00::1:35571 2001:DB8:bar::100:80 ESTABLISHED 9631\/apache2    \ntcp6       0      0 2001:DB8:f00::1:35777 2001:DB8:bar::100:80 ESTABLISHED 9656\/apache2    \ntcp6       0      0 2001:DB8:f00::1:36531 2001:DB8:bar::100:80 ESTABLISHED 11578\/apache2   \ntcp6       0      0 2001:DB8:f00::1:36481 2001:DB8:bar::100:80 ESTABLISHED 11158\/apache2   \ntcp6       0      0 2001:DB8:f00::1:36295 2001:DB8:bar::100:80 ESTABLISHED 11115\/apache2   \ntcp6       0      0 2001:DB8:f00::1:34831 2001:DB8:bar::100:80 ESTABLISHED 8312\/apache2  <\/code2><\/pre>  <\/p>\n
2001:DB8:f00::1   -> my server
\n2001:DB8:bar::100 -> dst server<\/p>\n
As one can easily see my server is connecting to port 80 of dst, possibly asking for something over HTTP.<\/p>\n
# netstat -antpW | grep 2001:DB8:bar::100 | wc -l\n111<\/code2><\/pre><\/p>\n
# dig -x 2001:DB8:bar::100 +short                                 \ncrl.randomcertauthority.com.<\/code2><\/pre><\/p>\n
tailing the log files didn’t show anything weird happening. I run a tcpdump for that dst server but there wasn’t at that time any traffic going on.<\/p>\n
So, I took a look at munin to see when this problem started developing.<\/p>\n
\"\"<\/a>
\n\"\"<\/a>
\n\"\"<\/a><\/p>\n
As it’s obvious from the above graphs, the problem started around 14:00. So I took another look at the apache logs and I saw a bot crawling a specific url from my server. I visited that url on my server  using curl and I saw traffic flowing through tcpdump going from my server to dst server. So visiting that URL was definitely causing problems. But why?<\/p>\n
I restarted apache, swap and memory were released, all the stale ESTABLISHED connections went away and I saw hundreds of FIN\/RST packets going back and forth at tcpdump.<\/p>\n
I tried to open a few concurrent connections from my PC to my server’s url using curl. After a couple of tries netstat showed that I had managed to create stale ESTABLISHED connections towards dst server. It was an HTTP connection asking for a crl. So I was both able to reproduce the problem and I also knew the specific url of the dst server that caused the connection hanging issues.
\nNext thing I did was to try to open direct HTTP connections from my server to the dst url using curl. After a few concurrent connections I managed to make curl hang. So the problem was definitely not on my server, but at the dst server.<\/p>\n
Since it was already quite late, my first (re)action was to install mod_evasive to try and minimize the problem so I could take a better look the next day.
\n
# aptitude install libapache2-mod-evasive\n# a2enmod mod_evasive\n### edit \/etc\/apache2\/sites-enabled\/site-name and add the following\n       <IfModule mod_evasive20.c>\n            DOSHashTableSize    3097\n            DOSPageCount        1   \n            DOSSiteCount        50  \n            DOSPageInterval     1   \n            DOSSiteInterval     1   \n            DOSBlockingPeriod   10  \n            DOSEmailNotify myemail@mydomain.gr\n        <\/IfModule>\n# \/etc\/init.d\/apache2 reload\n<\/code2><\/pre><\/p>\n
I tried to curl my server’s URL from my PC and I got blocked after the second concurrent try. But after some repetitions I was still able to create one or two stale ESTABLISHED connections from my server to the dst server. Far fewer than before but the problem was still somewhat reproducible.<\/p>\n
Then I decided to take a look at the site’s PHP code. Finding the culprit was quite easy, I just had to find the code segment where PHP requested the dst server’s url.
\nHere’s the code segment:
\n
$ch = curl_init($this->crl_url);\ncurl_setopt($ch, CURLOPT_RETURNTRANSFER,true);\n$crl_content = curl_exec($ch);\n<\/code2><\/pre><\/p>\n
The developer had never thought that the remove server might keep the connection open for whatever reason (rate limiting anyone?)<\/p>\n
Patching it was quite simple:
\n
$ch = curl_init($this->crl_url);\ncurl_setopt($ch, CURLOPT_RETURNTRANSFER,true);\ncurl_setopt($ch, CURLOPT_CONNECTTIMEOUT,'60');\ncurl_setopt($ch, CURLOPT_TIMEOUT,'60');\n$crl_content = curl_exec($ch);\n<\/code2><\/pre><\/p>\n
After this everything worked fine again. Connections were getting ESTABLISHED but after 60 seconds they got torn down, automagically. No more stale ESTABLISHED connections. Hooray!<\/p>\n
A letter to every developer:<\/p>\n
Dear developer,<\/p>\n
please test your code before shipping. Pretty please take corner cases into account. We know you’re competent enough, don’t be lazy.<\/p>\n
Your kind sysadmin<\/p><\/blockquote>\n","protected":false},"excerpt":{"rendered":"
When you have a misbehaving system and you are not sure what the problem is, always bet on a poorly written application. Here’s a small example of how another poorly written web application caused system issues. I was sitting at my office today I when I got this nagios alert for a host. Date\/Time: Tue […]<\/p>\n","protected":false},"author":1,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"ep_exclude_from_search":false,"footnotes":""},"categories":[5,414,3,8],"tags":[182,37,225,33,509,508,595,507,490,505,277,506],"class_list":["post-1523","post","type-post","status-publish","format-standard","hentry","category-internet","category-ipv6-networking","category-linux","category-networking","tag-apache2","tag-bug","tag-curl","tag-debian","tag-http","tag-libcurl","tag-linux","tag-mod_evasive","tag-munin","tag-nagios3","tag-php","tag-tcpdump"],"aioseo_notices":[],"views":9360,"_links":{"self":[{"href":"https:\/\/www.void.gr\/kargig\/blog\/wp-json\/wp\/v2\/posts\/1523","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/www.void.gr\/kargig\/blog\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/www.void.gr\/kargig\/blog\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/www.void.gr\/kargig\/blog\/wp-json\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"https:\/\/www.void.gr\/kargig\/blog\/wp-json\/wp\/v2\/comments?post=1523"}],"version-history":[{"count":6,"href":"https:\/\/www.void.gr\/kargig\/blog\/wp-json\/wp\/v2\/posts\/1523\/revisions"}],"predecessor-version":[{"id":1532,"href":"https:\/\/www.void.gr\/kargig\/blog\/wp-json\/wp\/v2\/posts\/1523\/revisions\/1532"}],"wp:attachment":[{"href":"https:\/\/www.void.gr\/kargig\/blog\/wp-json\/wp\/v2\/media?parent=1523"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/www.void.gr\/kargig\/blog\/wp-json\/wp\/v2\/categories?post=1523"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/www.void.gr\/kargig\/blog\/wp-json\/wp\/v2\/tags?post=1523"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}