Simulate a mysql connection error

In testing, we have to often simulate errors. How can we simulate a mysql connection error on a typical network that can be found in a corporate environment? Most times, the servers themselves are some place we have no physical access to and, what is more of a problem, shared by others. So we can't shut down the server, or unplug the cable.

There is a way we can simulate a mysql connection error using the swiss army knife of the hacker - netcat. netcat allows us to forward traffic coming to a particular port, to another one of our choosing. When we set up netcat this way, it starts listening on a port, and forwards all traffic received on this port to the other port.

Here is an example :

ncat -l 10.2.2.47 8080 --sh-exec "ncat 10.2.2.47 3306" 

This command will have netcat start listening on port 8080, you don't have to use port 8080, you can use any unused port on the machine. Then it forwards all traffic to port 8080 to port 3306. Now port 3306 is where mysql listens on. On the machine I ran this, the idea was to route all traffic to port 8080 to mysql on the same box. Now all you have to do is to change the connection string of your application being tested, to speak to port 8080 (instead of the default mysql port, 3306). Once you do that, port forwarding will still make the mysql calls work seamlessly. But now, when you want to simulate a mysql connection error, simply kill the ncat that is listening on port 8080. When you want to bring mysql back up, simply issue the ncat command again.

Here is how you'd use the mysql client to go via 8080:

mysql -uuser -ppass -h 10.2.2.47 --port 8080

(Make sure the host is specified as the IP. Specifying localhost will ignore the port and start using a socket file for communication.)

Voila, now you have a fairly painless way of simulating mysql errors. Of course the same technique can be used to simulate any errors generated by network calls where a server listens on a known port, which is all socket based applications.

Hadoop : Output of Combiner can be processed again by the Combiner

A combiner can be used in a map/reduce program to aggregate values locally at the mapper, before a call is made to the reducer. When a combiner is available, the output of the map() function is fed to the combine() function first. And the general understanding is that the output of the combine() function is sent over to the reduce() function on a reducer machine.

Except, it is not strictly correct. The output of combine() can be fed back into the combine() function for repeated aggregation. In general, this does not cause a problem, but one can write incorrect code, if one was not aware of this detail. An example would be a simple counting program.

This program counts the terms present in the given documents. In the reducer, the sum is incremented by 1 for each element in [c1, c2, ...] because, we know that all counts in this array are "1"s. That is because, the mapper always emits "1"s.

class Mapper
   method Map(docid id, doc d)
      for all term t in doc d do
         Emit(term t, count 1)

class Reducer
   method Reduce(term t, counts [c1, c2,...])
      sum = 0
      for all count c in [c1, c2,...] do
          sum = sum + 1
      Emit(term t, count sum)

Now let's add a combiner to aggregate the terms locally.

class Combiner
   method Combine(term t, [c1, c2,...])
      sum = 0
      for all count c in [c1, c2,...] do
          sum = sum + 1
      Emit(term t, count sum)

It is identical to the reducer. The sum is incremented by 1 for each "1" element in the array. But now, we see that we must change the reducer to not sum "1"s, as the combiner would be doing an aggregation first. So we change the reducer to this:

class Reducer
   method Reduce(term t, counts [c1, c2,...])
      sum = 0
      for all count c in [c1, c2,...] do
          sum = sum + c
      Emit(term t, count sum)

The thinking is that the array input into the combiner could never have values other than "1"s. But this is an incorrect assumption because, as we said, the output of a combiner, that would have produced aggregated values, other than "1"s, can be again input to the combine() function. Thus the correct combine() is as follows:

class Combiner
   method Combine(term t, [c1, c2,...])
      sum = 0
      for all count c in [c1, c2,...] do
          sum = sum + c
      Emit(term t, count sum)

In fact, this is identical to the reduce() function.

We can peek under the hood in Hadoop source code to see where this two step combining happens. Inside java.org.apache.hadoop.mapred.MapTask, a flush() method has two function calls of relevance.

sortAndSpill()
mergeParts()

sortAndSpill() is actually called early on by a spill thread as well. The flush() makes sure that any remaining data is properly spilled. flush() then interrupts the spill thread, waits for it to end, and then calls mergeParts().

sortAndSpill() is the section of code that runs as the mapper is writing the intermediate values into spill files. 

Inside sortAndSpill() :

            if (spstart != spindex) {
                combineCollector.setWriter(writer);
                RawKeyValueIterator kvIter =
                  new MRResultIterator(spstart, spindex);
                combinerRunner.combine(kvIter, combineCollector);
              }

This is where the combine() function is called first. But when data volume is high, Hadoop is unable to wait for all output from the mappers, before spilling the data to disk. When a threshold is reached, the buffers are spilled into a spill file. So it is quite possible, that one key gets spilled into two spill files. And if this happens, Hadoop can do yet another aggregation on running the data in spill files through the combiner. And that is partly what the mergeParts() function does:

         if (combinerRunner == null || numSpills < minSpillsForCombine) {
            Merger.writeFile(kvIter, writer, reporter, job);
          } else {
            combineCollector.setWriter(writer);
            combinerRunner.combine(kvIter, combineCollector);
          }

This is how combine() can be called twice, or more times, for the same key. So even if the mapper always emits a "1", the combiner could get values much larger than "1". It is always good practice to not assume the values coming into the combiner based on what is output from map().

Simulate Out Of Disk condition for a test (Linux)

We recently had a problem in production where a service was filling up the disk, happily swallowing the IOException that was thrown, and continuing on its merry and error prone way. Needless to say, it emptied the input (a high volume redis queue) and produced garbage. We fixed this and then before deployment, needed to create an Out of Disk scenario for testing. My first, clumsy attempt was to fill the disk with the dd command but a few hours later felt very sheepish, as it took quite a while to fill up a large disk (more than half a Terrabyte). The easiest way to do this is to create a loopback partition of a fixed size. Here are the steps I used :

mkdir /filesystems
dd if=/dev/zero of=/filesystems/tmp_fs seek=512 count=512 bs=1M
mkfs.ext4 /filesystems/tmp_fs
mkdir /mnt/small
mount -o loop /filesystems/tmp_fs /mnt/small

This creates a partition of about 1G that gets mounted to /mnt/small. In our scenario, we had to create the Lucene index inside this directory.

Escaping strings in bash

Good way to escape strings in bash.

Using this, I generated a script to push a number of URLs to a redis queue :

redis-cli LPUSH our_queue http\:\/\/zuvypyzulogu\.wordpress\.com\/2013\/02\/20\/bist\-du\-bei\-mir\-music\-download 
redis-cli LPUSH our_queue http\:\/\/zuvypyzulogu\.wordpress\.com\/2013\/02\/20\/top\-10\-free\-music\-download\-sites 
redis-cli LPUSH our_queue http\:\/\/zwingliusredivivus\.wordpress\.com\/2012\/02\/09\/where\-marc\-sees\-cause\-to\-lament\-i\-see\-reason\-to\-rejoice 
redis-cli LPUSH our_queue http\:\/\/zwingliusredivivus\.wordpress\.com\/2013\/02\/26\/a\-word\-to\-the\-emergents 
redis-cli LPUSH our_queue http\:\/\/zwischen\-uns\.forumactif\.com\/post 
redis-cli LPUSH our_queue http\:\/\/zx6r\.com\/zx6r\/19061\-normal\-tempature\-07\-zx6r\.html 
redis-cli LPUSH our_queue http\:\/\/zx6r\.com\/zx6r\/23572\-09\-zx6\-hid\-kit\.html redis-cli LPUSH our_queue http\:\/\/zx6r\.com\/zx6r\/9351\-06\-636\-build\-start\.html 
redis-cli LPUSH our_queue http\:\/\/zyngadeutschland\.wordpress\.com\/2013\/02\/26\/farmville\-2\-neue\-limitierte\-auflage\-kelten 
redis-cli LPUSH our_queue http\:\/\/zzmtokg\.wordpress\.com\/2011\/07\/09\/best\-price\-stok\-fyr\-torch\-for\-less  

Perl : Use Text::CSV instead of split for parsing CSV lines

When you have lines which have quoted fields delimited by commas, it is often easy to use the perl native split command to parse:

 perl -ne '@x=split(",");' file.csv  

But this will not parse this type of line :

"2013-02-15","478944","http://cdn.springboard.gozammer.com/mediaplayer/springboard/mediaplayer.swf?config={""externalConfiguration"":""http://www.springeagle.com/superconfig/sgv014.js"",""playlist"":""http://cms.springeagle.com/xml_feeds_advanced/index/683/rss3/668219/0/0/5/""}","1","0",""

Everything starting from "http://" and including the closing brace is a single field.

But within this field, we find the "," separator. This means that when our perl split does its work, we get the following as the 2nd field in the line:

http://cdn.springboard.gozammer.com/mediaplayer/springboard/mediaplayer.swf?config={""externalConfiguration"":""http://www.springeagle.com/superconfig/sgv014.js"

However, Text::CSV perl module is smart enough to recognize certain sub formats within the quoted fields and parse accordingly. It identifies the opening brace and searches for a closing brace, passing over any delimiters in between.

Here is an example:

cat /tmp/x | perl -ne 'BEGIN { use Text::CSV; $csv=Text::CSV->new();} chomp; $csv->parse($_); @x=$csv->fields(); for $x (@x) {print "$x ## "}; print "\n";'

2013-02-15 ## 478944 ##  http://cdn.springboard.gozammer.com/mediaplayer/springboard/mediaplayer.swf?config={"externalConfiguration":"http://www.springeagle.com/superconfig/sgv014.js","playlist":"http://cms.springeagle.com/xml_feeds_advanced/index/683/rss3/668219/0/0/5/"} ## 1 ## 0 ##  ## 

Tomcat : The Init loop

Tomcat can be configured so that the servlets initialize upon server startup, so that they are ready and primed for the subsequent GET requests. But if the init() method fails for whatever reason, then init() will be called again by Tomcat, upon a subsequent GET request.

It is not clear why Tomcat developers chose this method of calling init() again on a GET request. It may be that they wanted to coax the servlet to initialize on the second attempt, even if it failed upon startup. The reasoning might have been that the first failure was due to a race condition. Another reason I've seen posted is that this way, tomcat can return the full error with a stack trace from the init() call to the browser. The reasoning is that this will make it easier for a developer to fix the init() error as it is immediately visible upon the browser. (vs having to find it in the catalina.out file)

Well, neither of these explanations can be accepted without some misgivings. First, if the design goal of the servlet container was to reduce the chance of a race condition from affecting the serving of requests, the init() call could be repeated a configured number of times upon startup. Secondly, Tomcat could have been designed to store any error from init() locally, so that it can be returned upon the next GET request, without making another call to init().

Our complaints on the design of Tomcat server is not so much pedantic. If the servlet init() routine in fact has a race condition, this design of Tomcat, rather than resolving the race, under certain conditions, can cause Tomcat to race in a never ending series of calls to init().

In fact, this very thing happened recently on our production servers.

First, there was an extremely rare race that hit a portion of the init() code on the servlet. This caused init() to fail. Then tomcat dutifully called init() again, but this time, a component that had been created before the init() failure last time, threw an Exception as it was already created. (It was a singleton object). Now, since init() fails again, for a different reason, the next GET will make Tomcat call init() again, and again, init() will fail. This throws the server into an endless init() loop.

The problem is that now, the part of the code where we first encountered the race, never gets hit. So, the server is up without being properly initialized, and in any case, init() will never succeed as the singleton object will always throw an exception. So none of the GET requests will be served.

We can think of other unintended consequences also, due to this design. What if the servlet was accumulating some sort of a list in memory from the database upon startup? Calling init() more than once may increase the list size and possibly lead to bugs.

And then, what if the first error corrupted some data structure - or even some data on permanent storage ? Even if the second init() succeeded, the server might be corrupt at this point.

JDO : Beware when closing PreparedStatement Objects

Once you are done with a PreparedStatement, it is good practice to close it. But pain awaits you in unexpected moments, if you close a statement one too many times.

In standard code using JDO, it is not uncommon to find ResultSet and PreparedStatement objects that do not get closed. Things will work for a while before memory issues force developers to clean these up. This is what happened on our production systems recently. Unfortunately, we were somewhat overzealous and at one point, closed a statement twice. It ran on Q/A without a problem, so unnoticed to the gatekeepers, it slipped into production.

And there it crashed and burned, not in the close statement as one would imagine, but in stmt.get call with the following stack trace:

Processor.processFile: problem 
processing data from filename: /path/to/something.csv on:
com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: No operations allowed after statement closed.
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
        at com.mysql.jdbc.Util.handleNewInstance(Util.java:409)
        at com.mysql.jdbc.Util.getInstance(Util.java:384)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1015)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:989)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:984)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:929)
        at com.mysql.jdbc.StatementImpl.checkClosed(StatementImpl.java:406)
        at com.mysql.jdbc.ServerPreparedStatement.checkClosed(ServerPreparedStatement.java:546)
        at com.mysql.jdbc.ServerPreparedStatement.setLong(ServerPreparedStatement.java:2037)
        at com.solarmetric.jdbc.DelegatingPreparedStatement.setLong(DelegatingPreparedStatement.java:397)
        at com.solarmetric.jdbc.PoolConnection$PoolPreparedStatement.setLong(PoolConnection.java:448)
        at com.solarmetric.jdbc.DelegatingPreparedStatement.setLong(DelegatingPreparedStatement.java:397)
        at com.solarmetric.jdbc.DelegatingPreparedStatement.setLong(DelegatingPreparedStatement.java:397)
        at com.solarmetric.jdbc.DelegatingPreparedStatement.setLong(DelegatingPreparedStatement.java:397)
        at com.solarmetric.jdbc.LoggingConnectionDecorator$LoggingConnection$LoggingPreparedStatement.setLong(LoggingCo
nnectionDecorator.java:1265)
        at com.solarmetric.jdbc.DelegatingPreparedStatement.setLong(DelegatingPreparedStatement.java:397)
        at com.solarmetric.jdbc.DelegatingPreparedStatement.setLong(DelegatingPreparedStatement.java:397)
        at ourcode.getData(Manager.java:5435)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at ourcode.JDOProxy.invoke(JDOProxy.java:198)
        at $Proxy5.getData(Unknown Source)
        at ourcode.Processor.writeData(Processor.java:3185)
 

This is due to a bug in the mysql connector where if a statement is closed twice, and we create another statement (PreparedStatement) again with the same sql string, it retrieves the closed PreparedStatement object from an internal cache. Then any attempt to use that statement results in an exception. Here are the details of the mysql bug

Here is a bit of code showing the double close. If this function is called twice, it will throw the exception on the second call :

    private static void badsql(PersistenceManager pm) {
        Connection conn=null;
        ResultSet results =null;
        PreparedStatement stmt=null;

        try {
            conn = QUtil.getConn(pm);

            String[] urls = new String[] {"blingbling.com", "singsing.com", "soso.com"};

            stmt = conn.prepareStatement("select numhits from facttable where name = ?");

            for (String url : urls) {
                stmt.setString(1, url);
                results = stmt.executeQuery();
                if (results.next()) {
                    int numTerms = results.getInt(1);
                    System.out.println(url + "=>" + numTerms);
                }
                results.close();
            }
            //first close
            stmt.close();
            conn.close();

        } catch (Exception e) {

        } finally {
            CloseUtil.closeAndIgnore(results);
            //Here is the second close
            CloseUtil.closeAndIgnore(stmt);
            CloseUtil.closeAndIgnore(conn);
        }
    }

The problematic function was being called once for a large batch of records. Since there was not enough records in the Q/A environment, it was called just once and thus we never found the bug in Q/A.