Wednesday, February 06, 2013

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.

Wednesday, November 23, 2011

HDFS namenode won't start after disk full error

If you have trouble restarting the NameNode in a Hadoop cluster after a disk full error, if you don't mind losing some data, you can do the following to get it back up.

Find the 'edits' file in the hadoop dfs.name.dir/current and write this sequence to it :

printf "\xff\xff\xff\xee\xff" > edits

After that, you should be able to start hadoop. Credit here.

Friday, November 04, 2011

Bash - prevent multiple copies of script from running

Since bash commands each spawn its own process, we can't lock files to achieve single copy running semantics. Why? Because file locks are per process and they are automatically cleared when the process dies. Thus it is nonsensical to expect a linux command to lock a file, why, when that command returns, the lock file will be automatically unlocked defeating the purpose of the lock completely!

One easy way to prevent multiple copies running is to find an atomic Linux command that can both do a certain operation and return whether that operation succeeded atomically. This command must fail on the second time. The command to make a directory - mkdir - is one such command.

So the script could try to mkdir a particular directory - let's call this the lock directory. If it fails, we don't start. Now if it works, we must remove the lock directory when the script ends so that the script can run again. We do this using the trap command - trap will make sure a given command will execute when the script exits at any point.

Here is the code:

#!/bin/bash                                                                                                                                                                                        
mkdir /tmp/locka 2>/dev/null || {
    exit
}
trap "rmdir /tmp/locka" EXIT
#script work, the sleep 10 below is to test this
#without having a real script.
sleep 10

Thursday, July 28, 2011

Java : write binary data to a mysql out file

I had the need to generate - within Java code - a mysql out file with both text and binary data. The binary data is for some content that has been gzipped and stored as a blob in a mysql table. While it is trivial to write binary data to a blob field directly using JDO, for performance reasons, we had to use the "load infile" approach. Thus the first step was to create an outfile.

Here is the function that would convert binary data to a form that can be written to an out file. It follows the algorithm implemented by mysql for its "SELECT INTO outfile" functionality as described here.

    public static byte[] getEscapedBlob(byte[] blob) {
        ByteArrayOutputStream bos = new ByteArrayOutputStream();
        for (int i=0; i<blob.length; i++) {
            if (blob[i]=='\t' || blob[i]=='\n' || blob[i]=='\\') {
                bos.write('\\');
                bos.write(blob[i]);
            } else if (blob[i] == 0) {
                bos.write('\\');
                bos.write('0');
            } else {
                bos.write(blob[i]);
            }
        }
        return bos.toByteArray();
    }

This is how you would use this function to generate a mysql outfile.

                //gen infile for mysql
                byte[] out = getEscapedBlob(data);
                BufferedOutputStream f = new BufferedOutputStream(new FileOutputStream("/path/to/data.csv")) ;
                String nonBlobFields = "\\N\t10\t20100301\t18\t1102010\t2010-03-01 00:00:00\t";
                byte[] nonBlobData = nonBlobFields.getBytes("UTF-8");
                f.write(nonBlobData, 0, nonBlobData.length);
                f.write(out, 0, out.length);
                f.write('\n');
                f.close();


This writes some integer data followed by the blob data to the outfile, which can then be loaded back using "LOAD INFILE".