[Play 2.4-M2] Shutdownhook triggers before the test finishes

[Hossein Kazemi]

Hi,

We have cooked up some code using Guice in Play 2.4-M2 to save some stuff in a Redis database:

public class JedisPoolProvider implements Provider<JedisPool> {
    private static final String KEY_CONFIG = "jedis";
    private static final String SUBKEY_HOST = "host";
    private static final String SUBKEY_PORT = "port";
    private static final String SUBKEY_PASSWORD = "password";
    private static final String SUBKEY_TIMEOUT = "timeout";
    private static final String SUBKEY_POOL = "pool";

    JedisPool pool;

    Logger.ALogger logger = Logger.of(JedisPoolProvider.class);

    @Inject
    JedisPoolProvider(ApplicationLifecycle applicationLifecycle) {
        Configuration config = Play.application().configuration().getConfig(KEY_CONFIG);

        final String host = config.getString(SUBKEY_HOST);
        int timeout = config.getInt(SUBKEY_TIMEOUT, 20);
        String password = config.getString(SUBKEY_PASSWORD, "");
        int port = config.getInt(SUBKEY_PORT, 6379);

        if(host == null ) {
            // FIXME: crap out in a very spectacular way, without having to wait for 1st request
        }

        if(password.equals("")) {
            password = null;
        }
        final JedisPoolConfig poolConfig = getJedisPoolConfig(config.getConfig(SUBKEY_POOL));

        pool = new JedisPool(poolConfig, host, port, timeout, password);

        logger.debug("JedisPoolProvider(), jedisPool configured with host {}, config {}", host, config);

      applicationLifecycle.addStopHook(()->{
            logger.info("Shutting down Redis client");
            pool.destroy();
            return F.Promise.pure(null);
      });

    }

}

public class JedisPoolProviderModule extends AbstractModule {
    @Override
    protected void configure() {
        bind(JedisPool.class).toProvider(JedisPoolProvider.class).in(Singleton.class);
    }
}

public class RedisRepositoryImpl implements RedisRepository {
    private final static Logger.ALogger logger = Logger.of(RedisRepositoryImpl.class);
    private final static String GAME = "game-%s";

    @Inject
    private JedisPool jedisPool;

    @Override
    public F.Promise<Boolean> storeGameAndCreateIndexes(final FlatGame flatGame) {
        return F.Promise.promise(()->{
            // convert to json, save
            final String jsonString = Json.toJson(flatGame).toString();
            final Jedis resource = jedisPool.getResource();
            try {
               final Transaction transaction = resource.multi();
                transaction.set(String.format(GAME, flatGame.id), jsonString);
                //.....
                transaction.exec();
            }
            finally{
                jedisPool.returnResource(resource);
            }

            return Boolean.TRUE;
        }).recoverWith(throwable -> F.Promise.promise(()->{
            logger.error("Failed to connect to Redis:", throwable);
            return Boolean.FALSE;
        }));
    }
}

This above code work perfectly fine when you run the application. However, the issue pops up while testing. Here is our test:

public class RedisRepositoryImplTest{
    private static final Logger.ALogger logger = Logger.of(RedisRepositoryImplTest.class);

    FakeApplication fakeApplication;

    public FakeApplication getFakeApplication(){
        return fakeApplication();
    }

    @After
    public void after(){

    }

    @Before
    public void before(){
        fakeApplication = getFakeApplication();
    }

    @Test
    public void testStoreGameAndCreateIndexes() throws Exception {
        running(fakeApplication, () -> {
            Game game = new Game();
            game.id = 123L;
            game.name = ImmutableMap.of(Lang.forCode("nl"), "vogel", Lang.forCode("en"), "bird", Lang.forCode("fa"), "پرنده");
            game.categoryIds = Arrays.asList(1000, 1001, 1002);

            final Converter converter = new Converter();
            final FlatGame converted = converter.convert(game);
            final RedisRepository repository = fakeApplication.injector().instanceOf(RedisRepository.class);

            /*final Boolean aBoolean = repository.storeGameAndCreateIndexes(converted).get(10000);
            assertTrue("saving game in redis was not successful", aBoolean);*/
            //Logger.debug("resource1: {}", repository.resource);

            repository.storeGameAndCreateIndexes(converted).onRedeem(result -> {
                assertTrue("saving game in redis was not successful", result);
            });
            repository.storeGameAndCreateIndexes(converted).onFailure(failed->{
                throw new IllegalArgumentException(failed);
            });
        });

    }
}

This will end up with a nasty exception being thrown:

redis.clients.jedis.exceptions.JedisConnectionException: Could not get a resource from the pool
	at redis.clients.util.Pool.getResource(Pool.java:50) ~[jedis-2.6.2.jar:na]
	at redis.clients.jedis.JedisPool.getResource(JedisPool.java:88) ~[jedis-2.6.2.jar:na]
	at repositories.redis.RedisRepositoryImpl.lambda$storeGameAndCreateIndexes$1(RedisRepositoryImpl.java:35) ~[classes/:na]
	at repositories.redis.RedisRepositoryImpl$$Lambda$9/1558498217.apply(Unknown Source) ~[na:na]
	at play.core.j.FPromiseHelper$$anonfun$promise$2.apply(FPromiseHelper.scala:36) [play_2.11-2.4.0-M2.jar:2.4.0-M2]
	at scala.concurrent.impl.Future$PromiseCompletingRunnable.liftedTree1$1(Future.scala:24) [scala-library-2.11.1.jar:na]
	at scala.concurrent.impl.Future$PromiseCompletingRunnable.run(Future.scala:24) [scala-library-2.11.1.jar:na]
	at play.core.j.HttpExecutionContext$$anon$2.run(HttpExecutionContext.scala:40) [play_2.11-2.4.0-M2.jar:2.4.0-M2]
	at akka.dispatch.TaskInvocation.run(AbstractDispatcher.scala:41) [akka-actor_2.11-2.3.5.jar:na]
	at akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinTask.exec(AbstractDispatcher.scala:393) [akka-actor_2.11-2.3.5.jar:na]
Caused by: java.lang.IllegalStateException: Pool not open
	at org.apache.commons.pool2.impl.BaseGenericObjectPool.assertOpen(BaseGenericObjectPool.java:605) ~[commons-pool2-2.0.jar:2.0]
	at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:405) ~[commons-pool2-2.0.jar:2.0]
	at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:360) ~[commons-pool2-2.0.jar:2.0]
	at redis.clients.util.Pool.getResource(Pool.java:48) ~[jedis-2.6.2.jar:na]
	at redis.clients.jedis.JedisPool.getResource(JedisPool.java:88) ~[jedis-2.6.2.jar:na]
	at repositories.redis.RedisRepositoryImpl.lambda$storeGameAndCreateIndexes$1(RedisRepositoryImpl.java:35) ~[classes/:na]
	at repositories.redis.RedisRepositoryImpl$$Lambda$9/1558498217.apply(Unknown Source) ~[na:na]
	at play.core.j.FPromiseHelper$$anonfun$promise$2.apply(FPromiseHelper.scala:36) [play_2.11-2.4.0-M2.jar:2.4.0-M2]
	at scala.concurrent.impl.Future$PromiseCompletingRunnable.liftedTree1$1(Future.scala:24) [scala-library-2.11.1.jar:na]
	at scala.concurrent.impl.Future$PromiseCompletingRunnable.run(Future.scala:24) [scala-library-2.11.1.jar:na]

Which basically means the jedis pool is closed by the time the test wants to do the actual redis operation. Digging in, We thought this might be a concurrency issue. So we decided to do the actual redis operation test in a blocking mode. If you look at the code above for our test, there is a few line commented out:

final Boolean aBoolean = repository.storeGameAndCreateIndexes(converted).get(10000);
assertTrue("saving game in redis was not successful", aBoolean);

By doing a get and blocking the whole thread to get the result, test runs smoothly. After more digging in, it became suspicious of the shutdownhook that we have defined in the code. This time, we commented out the shutdownhook part and ran the test without using blocking. To out surprise the test ran successfully. 

So the conclusion was that what is written in the body of the shutdownhook is triggered before the test finishes or maybe the fakeapplication stops before the test is finished. Has anyone had the same issue?