Intermittent NPE during application startup

[shasmish]

Expected behavior
No exception during startup

Actual behavior
Intermittently application startup fails due to a NPE in redis.clients.jedis.BinaryJedisPubSub.subscribe() method call.

Stacktrace:

[09-24-2020 07:50:17.170 +0000] [ERROR] [prod] [] [ main] [work.web.context.ContextLoader] Context initialization failed org.springframework.context.ApplicationContextException: Failed to start bean 'broadcastMessageBO'; nested exception is java.lang.NullPointerException 
at org.springframework.context.support.DefaultLifecycleProcessor.doStart(DefaultLifecycleProcessor.java:185) ~[spring-context-5.2.6.RELEASE.jar:5.2.6.RELEASE] 
at org.springframework.context.support.DefaultLifecycleProcessor.access$200(DefaultLifecycleProcessor.java:53) ~[spring-context-5.2.6.RELEASE.jar:5.2.6.RELEASE] 
at org.springframework.context.support.DefaultLifecycleProcessor$LifecycleGroup.start(DefaultLifecycleProcessor.java:360) ~[spring-context-5.2.6.RELEASE.jar:5.2.6.RELEASE] 
at org.springframework.context.support.DefaultLifecycleProcessor.startBeans(DefaultLifecycleProcessor.java:158) ~[spring-context-5.2.6.RELEASE.jar:5.2.6.RELEASE] 
at org.springframework.context.support.DefaultLifecycleProcessor.onRefresh(DefaultLifecycleProcessor.java:122) ~[spring-context-5.2.6.RELEASE.jar:5.2.6.RELEASE] 
at org.springframework.context.support.AbstractApplicationContext.finishRefresh(AbstractApplicationContext.java:894) ~[spring-context-5.2.6.RELEASE.jar:5.2.6.RELEASE] 
at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:553) ~[spring-context-5.2.6.RELEASE.jar:5.2.6.RELEASE] 
at org.springframework.web.context.ContextLoader.configureAndRefreshWebApplicationContext(ContextLoader.java:401) ~[spring-web-5.2.6.RELEASE.jar:5.2.6.RELEASE] 
at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:292) ~[spring-web-5.2.6.RELEASE.jar:5.2.6.RELEASE] 
at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:103) ~[spring-web-5.2.6.RELEASE.jar:5.2.6.RELEASE] 
at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:4683) ~[catalina.jar:9.0.31] 
at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5146) ~[catalina.jar:9.0.31] 
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183) ~[catalina.jar:9.0.31] 
at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:717) ~[catalina.jar:9.0.31] 
at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:690) ~[catalina.jar:9.0.31] 
at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:705) ~[catalina.jar:9.0.31] 
at org.apache.catalina.startup.HostConfig.deployWAR(HostConfig.java:978) ~[catalina.jar:9.0.31] 
at org.apache.catalina.startup.HostConfig$DeployWar.run(HostConfig.java:1849) ~[catalina.jar:9.0.31] 
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:1.8.0_202] 
at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_202] 
at org.apache.tomcat.util.threads.InlineExecutorService.execute(InlineExecutorService.java:75) ~[tomcat-util.jar:9.0.31] 
at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:112) ~[?:1.8.0_202] 
at org.apache.catalina.startup.HostConfig.deployWARs(HostConfig.java:773) ~[catalina.jar:9.0.31] 
at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:427) ~[catalina.jar:9.0.31] 
at org.apache.catalina.startup.HostConfig.start(HostConfig.java:1576) ~[catalina.jar:9.0.31] 
at org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:309) ~[catalina.jar:9.0.31] 
at org.apache.catalina.util.LifecycleBase.fireLifecycleEvent(LifecycleBase.java:123) ~[catalina.jar:9.0.31] 
at org.apache.catalina.util.LifecycleBase.setStateInternal(LifecycleBase.java:423) ~[catalina.jar:9.0.31] 
at org.apache.catalina.util.LifecycleBase.setState(LifecycleBase.java:366) ~[catalina.jar:9.0.31] 
at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:936) ~[catalina.jar:9.0.31] 
at org.apache.catalina.core.StandardHost.startInternal(StandardHost.java:841) ~[catalina.jar:9.0.31] 
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183) ~[catalina.jar:9.0.31] 
at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1384) ~[catalina.jar:9.0.31] 
at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1374) ~[catalina.jar:9.0.31] 
at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_202] 
at org.apache.tomcat.util.threads.InlineExecutorService.execute(InlineExecutorService.java:75) ~[tomcat-util.jar:9.0.31] 
at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:134) ~[?:1.8.0_202] 
at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:909) ~[catalina.jar:9.0.31] 
at org.apache.catalina.core.StandardEngine.startInternal(StandardEngine.java:262) ~[catalina.jar:9.0.31] 
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183) ~[catalina.jar:9.0.31] 
at org.apache.catalina.core.StandardService.startInternal(StandardService.java:421) ~[catalina.jar:9.0.31] 
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183) ~[catalina.jar:9.0.31] 
at org.apache.catalina.core.StandardServer.startInternal(StandardServer.java:930) ~[catalina.jar:9.0.31] 
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183) ~[catalina.jar:9.0.31] 
at org.apache.catalina.startup.Catalina.start(Catalina.java:633) ~[catalina.jar:9.0.31] 
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_202] 
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_202] 
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_202] 
at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_202] 
at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:343) ~[bootstrap.jar:9.0.31] 
at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:474) ~[bootstrap.jar:9.0.31] Caused by: java.lang.NullPointerException at redis.clients.jedis.BinaryJedisPubSub.subscribe(BinaryJedisPubSub.java:48) ~[jedis-3.3.0.jar:?] 
at org.springframework.data.redis.connection.jedis.JedisSubscription.doSubscribe(JedisSubscription.java:61) ~[spring-data-redis-2.2.7.RELEASE.jar:2.2.7.RELEASE] 
at org.springframework.data.redis.connection.util.AbstractSubscription.subscribe(AbstractSubscription.java:155) ~[spring-data-redis-2.2.7.RELEASE.jar:2.2.7.RELEASE] 
at org.springframework.data.redis.listener.RedisMessageListenerContainer$SubscriptionTask.subscribeChannel(RedisMessageListenerContainer.java:909) ~[spring-data-redis-2.2.7.RELEASE.jar:2.2.7.RELEASE] 
at org.springframework.data.redis.listener.RedisMessageListenerContainer.addListener(RedisMessageListenerContainer.java:542) ~[spring-data-redis-2.2.7.RELEASE.jar:2.2.7.RELEASE] 
at org.springframework.data.redis.listener.RedisMessageListenerContainer.addMessageListener(RedisMessageListenerContainer.java:383) ~[spring-data-redis-2.2.7.RELEASE.jar:2.2.7.RELEASE] 
at org.springframework.data.redis.listener.RedisMessageListenerContainer.addMessageListener(RedisMessageListenerContainer.java:395) ~[spring-data-redis-2.2.7.RELEASE.jar:2.2.7.RELEASE] 
at com.adobe.ffc.core.bo.BroadcastMessageBO.start(BroadcastMessageBO.java:84) ~[classes/:?] 
at org.springframework.context.support.DefaultLifecycleProcessor.doStart(DefaultLifecycleProcessor.java:182) ~[spring-context-5.2.6.RELEASE.jar:5.2.6.RELEASE] ... 50 more

Steps to reproduce:
Redis / Jedis Configuration
Jedis version:
3.3.0

Redis version:
spring-data-redis - 2.2.7.RELEASE/2.3.4.RELEASE

Java version:
JDK - 1.8.0_202/1.8.0_261

[shasmish]

Logged a corresponding bug on Jedis as well, their recommendation was to consult spring-data-redis team. More details here - redis/jedis#2308

[mp911de]

Can you provide a minimal sample that reproduces the problem? We can't really reproduce the issue.

[aygoyal912]

The bean is created using SmartLifeCycle interface of Spring framework as we need it to be intiated in a particular order.

@Bean
    public BroadcastMessageBO broadcastMessageBO() {
        return new BroadcastMessageBO();
    }
```

```
@Bean
    public RedisMessageListenerContainer redisMessageListenerContainer() throws IOException {
        final RedisMessageListenerContainer container = new RedisMessageListenerContainer();
        container.setConnectionFactory(replicaJedisConnectionFactory());
        return container;
    }
```

--------------------------------------------------------------------------------------------------------------------------
Following is the snippet of the class - 


import org.springframework.context.SmartLifecycle;
import org.springframework.data.redis.connection.Message;
import org.springframework.data.redis.connection.MessageListener;
import org.springframework.data.redis.listener.ChannelTopic;
import org.springframework.data.redis.listener.RedisMessageListenerContainer;

import javax.inject.Inject;
import java.io.IOException;
import java.nio.charset.Charset;
import java.util.*;

public class BroadcastMessageBO implements MessageListener, SmartLifecycle {

    private static final Logger logger = LoggerFactory.getLogger(BroadcastMessageBO.class);

    @Inject
    private RedisMessageListenerContainer redisMessageListenerContainer;

    @Inject
    private String broadcastTopicName;

    @Override
    public boolean isAutoStartup() {
        return true;
    }

    @Override
    public void stop(Runnable callback) {
        stop();
        callback.run();
    }

    @Override
    public void start() {
        ChannelTopic broadcastTopic = new ChannelTopic(broadcastTopicName);
        redisMessageListenerContainer.addMessageListener(this, broadcastTopic);
        logger.info("Registered broadcast message listener with redis container for topic [{}]", broadcastTopicName);
    }

    @Override
    public void stop() {
        // There is nothing to stop in this class.
    }

    @Override
    public boolean isRunning() {
        return false;
    }

    @Override
    public int getPhase() {
        return 5000;
    }

}
`

[shasmish]

@mp911de this is intermittent in nature, and we have not been able to reproduce this at will. Which is why we need you help, why this could be happening and how this could be mitigated.

[mp911de]

At first sight, this looks pretty much like a race condition/visibility issue. I'd advise to create the message listener container first and then register MessageListener's before returning the RedisMessageListenerContainer bean.

RedisMessageListenerContainer.start launches a thread that does the actual subscription. Adding additional listeners after calling RedisMessageListenerContainer.start can lead to the issue.