[已回复] MobileIMSDK服务端onVerifyUserCallBack()返回非0值，导致空指针异常？

在ServerEventListenerImpl.onVerifyUserCallBack() 方法添加用户登录验证时，如果用户登录失败，返回非0值时会抛如下异常,是不是应该在某个位置添加一个非空盘算啥的，本人一直做PHP开发，初次解决java问题不知如何下手，求大神帮忙。

[INFO] - [22:59:41.127][IMCORE-netty] 基于MobileIMSDK的UDP服务正在端口7901上监听中... | (ServerLauncher^startup:263)
[DEBUG] - [22:59:47.019]-Dio.netty.recycler.maxCapacityPerThread: 32768 | (Slf4JLogger^debug:76)
[DEBUG] - [22:59:47.019]-Dio.netty.recycler.maxSharedCapacityFactor: 2 | (Slf4JLogger^debug:76)
[DEBUG] - [22:59:47.019]-Dio.netty.recycler.linkCapacity: 16 | (Slf4JLogger^debug:76)
[DEBUG] - [22:59:47.019]-Dio.netty.recycler.ratio: 8 | (Slf4JLogger^debug:76)
[DEBUG] - [22:59:47.029]-Dio.netty.buffer.bytebuf.checkAccessible: true | (Slf4JLogger^debug:81)
[DEBUG] - [22:59:47.031]Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@74842946 | (Slf4JLogger^debug:76)
[INFO] - [22:59:47.048][IMCORE-netty]与{uid:null}/127.0.0.1:49263的会话建立(channelActive)了... | (ServerCoreHandler^sessionCreated:377)
[INFO] - [22:59:47.096][IMCORE]>> 客户端{uid:null}/127.0.0.1:49263发过来的登陆信息内容是：loginInfo=1|getToken=aaa | (LogicProcessor^processLogin:235)
[DEBUG] - [22:59:47.096]【DEBUG_回调通知】正在调用回调方法：OnVerifyUserCallBack...(userId= 1 extra=null) | (ServerEventListenerImpl^onVerifyUserCallBack:61)
[DEBUG] - [22:59:47.173]Logging initialized using 'class org.apache.ibatis.logging.slf4j.Slf4jImpl' adapter. | (LogFactory^setImplementation:135)
[DEBUG] - [22:59:47.274]PooledDataSource forcefully closed/removed all connections. | (PooledDataSource^forceCloseAll:335)
[DEBUG] - [22:59:47.275]PooledDataSource forcefully closed/removed all connections. | (PooledDataSource^forceCloseAll:335)
[DEBUG] - [22:59:47.275]PooledDataSource forcefully closed/removed all connections. | (PooledDataSource^forceCloseAll:335)
[DEBUG] - [22:59:47.275]PooledDataSource forcefully closed/removed all connections. | (PooledDataSource^forceCloseAll:335)
[DEBUG] - [22:59:47.354]Opening JDBC Connection | (JdbcTransaction^openConnection:137)
Loading class `com.mysql.jdbc.Driver'. This is deprecated. The new driver class is `com.mysql.cj.jdbc.Driver'. The driver is automatically registered via the SPI and manual loading of the driver class is generally unnecessary.
Thu Jun 07 22:59:47 CST 2018 WARN: Establishing SSL connection without server's identity verification is not recommended. According to MySQL 5.5.45+, 5.6.26+ and 5.7.6+ requirements SSL connection must be established by default if explicit option isn't set. For compliance with existing applications not using SSL the verifyServerCertificate property is set to 'false'. You need either to explicitly disable SSL by setting useSSL=false, or set useSSL=true and provide truststore for server certificate verification.
[DEBUG] - [22:59:47.622]Created connection 2069515672. | (PooledDataSource^popConnection:406)
[DEBUG] - [22:59:47.622]Setting autocommit to false on JDBC Connection [com.mysql.cj.jdbc.ConnectionImpl@7b5a4d98] | (JdbcTransaction^setDesiredAutoCommit:101)
[DEBUG] - [22:59:47.625]==>  Preparing: select * from Users where mobile=?  | (BaseJdbcLogger^debug:159)
[DEBUG] - [22:59:47.657]==> Parameters: 1(String) | (BaseJdbcLogger^debug:159)
[DEBUG] - [22:59:47.679]<==      Total: 0 | (BaseJdbcLogger^debug:159)
[DEBUG] - [22:59:47.680]【DEBUG_回调通知】正在调用回调方法：OnVerifyUserCallBack...(未查询到用户信息，登录失败) | (ServerEventListenerImpl^onVerifyUserCallBack:77)
[DEBUG] - [22:59:50.866]【IMCORE-netty-本机QoS】【QoS发送方】=========== 消息发送质量保证线程运行中, 当前需要处理的列表长度为1... | (QoS4SendDaemonRoot^doTaskOnece:149)
[INFO] - [22:59:50.867][IMCORE-netty]toSession==null >> id=0的用户尝试发给客户端-1的消息：str={"code":2000}因接收方的id已不在线，此次实时发送没有继续(此消息应考虑作离线处理哦). | (LocalSendHelper^sendData:214)
[WARN] - [22:59:50.868]【IMCORE-netty-本机QoS】【QoS发送方】指纹为93f8a13f-5523-48cf-ab60-afcc10cdaf7e的消息包重传失败，它的重传次数之前已累计为0(最多1次). | (QoS4SendDaemonRoot$1^update:214)
[DEBUG] - [22:59:55.868]【IMCORE-netty-本机QoS】【QoS发送方】=========== 消息发送质量保证线程运行中, 当前需要处理的列表长度为1... | (QoS4SendDaemonRoot^doTaskOnece:149)
[DEBUG] - [22:59:55.871]【IMCORE-netty-本机QoS】【QoS发送方】指纹为93f8a13f-5523-48cf-ab60-afcc10cdaf7e的消息包重传次数已达1(最多1次)上限，将判定为丢包！ | (QoS4SendDaemonRoot^doTaskOnece:170)
[WARN] - [22:59:55.872]【IMCORE-netty-本机QoS】【QoS发送方】指纹为93f8a13f-5523-48cf-ab60-afcc10cdaf7e的消息已成功从发送质量保证队列中移除(可能是收到接收方的应答也可能是达到了重传的次数上限)，重试次数=1 | (QoS4SendDaemonRoot^remove:407)
[DEBUG] - [22:59:55.872]【DEBUG_QoS_S2C事件】收到系统的未实时送达事件通知，当前共有1个包QoS保证机制结束，判定为【无法实时送达】！ | (MessageQoSEventS2CListnerImpl^messagesLost:38)
[DEBUG] - [22:59:57.700][IMCORE-netty]此客户端的Channel抛出了exceptionCaught，原因是：null，可以提前close掉了哦！ | (ServerCoreHandler^exceptionCaught:157)
io.netty.handler.timeout.ReadTimeoutException
[DEBUG] - [22:59:57.703][IMCORE-netty]此客户端的Channel抛出了exceptionCaught，原因是：null，可以提前close掉了哦！ | (ServerCoreHandler^exceptionCaught:157)
java.lang.NullPointerException
        at java.util.concurrent.ConcurrentHashMap.get(ConcurrentHashMap.java:936)
        at net.openmob.mobileimsdk.server.processor.OnlineProcessor.getOnlineSession(OnlineProcessor.java:146)
        at net.openmob.mobileimsdk.server.ServerCoreHandler.sessionClosed(ServerCoreHandler.java:304)
        at net.nettime.mobileimsdk.server.netty.MBUDPClientInboundHandler.channelInactive(MBUDPClientInboundHandler.java:88)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:245)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:231)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:224)
        at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:75)
        at io.netty.handler.timeout.IdleStateHandler.channelInactive(IdleStateHandler.java:277)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:245)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:231)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:224)
        at io.netty.channel.DefaultChannelPipeline$HeadContext.channelInactive(DefaultChannelPipeline.java:1354)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:245)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:231)
        at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:917)
        at io.netty.channel.AbstractChannel$AbstractUnsafe$8.run(AbstractChannel.java:822)
        at io.netty.channel.DefaultEventLoop.run(DefaultEventLoop.java:54)
        at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858)
        at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:138)
        at java.lang.Thread.run(Thread.java:748)

引用：JackJiang 发表于 2018-06-08 19:59
你看看这是我模拟你同样的错误码的服务端log，不会出现你那个异常：

好的，谢谢老大。

引用：师傅不见了 发表于 2018-06-08 18:12
重新下载了之后，一行代码不改直接运行 客户端和server 都是ok的

然后修改server 端  onVerifyUserCa ...

你看看这是我模拟你同样的错误码的服务端log，不会出现你那个异常：


所以你这个异常，真是费解。你可以用源码跟踪一下，看看为何会在你的环境下出现这个异常。但实际上这个异常不影响什么，因为你客户端的会话已经被关闭了，服务端的这些代码只是在清理这个会话所占用的资源，而实际上这个会话还没占用什么资源。

另外，我刚抽了2个小时时间，按照你报告的这个问题作了更健壮的代码优化，你可以下载最新版MobileIMSDK v3.3，你的环境下应该不会再报这个问题了，你试试看。

问题定位到了，今天学了下IDEA的断点调试，找到问题原因了将红框中的代码移到if 内就ok了
因为  user_id 为 null 导致 getOnlineSession抛异常




谢谢 老大耐心回复。

引用：JackJiang 发表于 2018-06-08 14:52
JDK1.8不会有什么问题。

我建议你这样来排查：

重新下载了之后，一行代码不改直接运行 客户端和server 都是ok的

然后修改server 端  onVerifyUserCallBack 返回值 之后重新运行 还是报一样的错误，客户端同样能收到错误码

会不会是QOS 线程 没有判断用户登录失败？

引用：师傅不见了 发表于 2018-06-08 14:49
我这边是mac 自带的JDK  版本是  jdk1.8.0_161

JDK1.8不会有什么问题。

我建议你这样来排查：
1）把客户端demo和服务端demo一行代码一改，原样运行，看看在你这环境下能不能正常；
2）如果第1）步正常，则其它任何代码也别改，只把错误码改成10再来看看结果（这一次要注意一下客户端的log ，另外建议下次贴Log时把日志贴的全一点，不只是异常的那段。）

你重新下载最新版，不要用你现在的代码，就怕你不小心改过了但已记不起是否改过。

引用：JackJiang 发表于 2018-06-08 14:14
按你设置的错误码，我专门帮你验证了一遍，没有任何问题（看我的第2张图里，表示已经正常拿到了服务端返回 ...

我这边是mac 自带的JDK  版本是  jdk1.8.0_161

红色的是点击登录后打印的日志，同时客户端收到提示

绿色的是2秒后打印的

蓝色的是我觉得有问题的日志

按你设置的错误码，我专门帮你验证了一遍，没有任何问题（看我的第2张图里，表示已经正常拿到了服务端返回的码）：


顺便问一句，你的客户端和服务端分别运行在什么版本的JDK上的？

引用：JackJiang 发表于 2018-06-08 12:31
你的MobileIMSDK版本是多少？

引用：师傅不见了 发表于 2018-06-08 11:04
客户端我使用的是 MobileIMSDK >demos > client>  MobileIMSDKDemo-Java.jar 在mac 上直接点击运行的没做 ...

你的MobileIMSDK版本是多少？

引用：JackJiang 发表于 2018-06-08 09:54
那肯定是另有原因，我怀疑你用的代码有不合理的地方。

你这样做：

客户端我使用的是 MobileIMSDK >demos > client>  MobileIMSDKDemo-Java.jar 在mac 上直接点击运行的没做任何改动，

server 端使用IDEA 导入的，保留了如下的结构  


代码只修改了 onVerifyUserCallBack 的return  把0 改为10

引用：师傅不见了 发表于 2018-06-07 22:58
MINA 版也报同样的异常

[DEBUG] - [22:49:40.588]【IMCORE-本机QoS】【QoS发送方】=========== 消息发 ...

那肯定是另有原因，我怀疑你用的代码有不合理的地方。

你这样做：
1）把你自已加的或改的客户端端代码，贴出来，主要是跟demo相比，不同的地方；
2）参照1），同样把加的或动过的代码贴出来。

我帮你分析 分析 。用了这久，你的问题第一次看见，肯定有奇怪的地方。

引用：JackJiang 发表于 2018-06-07 22:02
理论上你描述的问题不应该发生，而且这个异常基本不可能是你说的这种情况下发生的。

我建议你换成MINA版 ...

MINA 版也报同样的异常

[DEBUG] - [22:49:40.588]【IMCORE-本机QoS】【QoS发送方】=========== 消息发送质量保证线程已成功启动 | (QoS4SendDaemonRoot^startup:292)
[INFO] - [22:49:40.592][IMCORE] 配置项：未开启与MobileIMSDK Web的互通. | (ServerLauncher^startup:223)
[INFO] - [22:49:40.704][IMCORE] 基于MobileIMSDK的UDP服务正在端口7901上监听中... | (ServerLauncher^startup:232)
[INFO] - [22:51:20.117][IMCORE]与{uid:null}/127.0.0.1:52874的会话建立(sessionCreated)了... | (ServerCoreHandler^sessionCreated:374)
[INFO] - [22:51:20.123][IMCORE]与{uid:null}/127.0.0.1:52874的会话(sessionOpened)打开了... | (ServerCoreHandler^sessionOpened:387)
[INFO] - [22:51:20.171][IMCORE]>> 客户端{uid:null}/127.0.0.1:52874发过来的登陆信息内容是：loginInfo=1|getToken=aaa | (LogicProcessor^processLogin:206)
[DEBUG] - [22:51:20.172]【DEBUG_回调通知】正在调用回调方法：OnVerifyUserCallBack...(extra=null) | (ServerEventListenerImpl^onVerifyUserCallBack:55)
[DEBUG] - [22:51:20.591]【IMCORE-本机QoS】【QoS发送方】=========== 消息发送质量保证线程运行中, 当前需要处理的列表长度为1... | (QoS4SendDaemonRoot^doTaskOnece:148)
[WARN] - [22:51:20.592]【IMCORE-本机QoS】【QoS发送方】指纹为9639182f-3cbb-4c18-83e2-db0c37ffabbd的包距"刚刚"发出才401ms(<=2000ms将被认定是"刚刚"), 本次不需要重传哦. | (QoS4SendDaemonRoot^doTaskOnece:187)
[DEBUG] - [22:51:25.591]【IMCORE-本机QoS】【QoS发送方】=========== 消息发送质量保证线程运行中, 当前需要处理的列表长度为1... | (QoS4SendDaemonRoot^doTaskOnece:148)
[INFO] - [22:51:25.592][IMCORE]toSession==null >> id=0的用户尝试发给客户端-1的消息：str={"code":2000}因接收方的id已不在线，此次实时发送没有继续(此消息应考虑作离线处理哦). | (LocalSendHelper^sendData:182)
[WARN] - [22:51:25.592]【IMCORE-本机QoS】【QoS发送方】指纹为9639182f-3cbb-4c18-83e2-db0c37ffabbd的消息包重传失败，它的重传次数之前已累计为1(最多1次). | (QoS4SendDaemonRoot^doTaskOnece:216)
[ERROR] - [22:51:30.155][IMCORE]exceptionCaught捕获到错了，原因是：null | (ServerCoreHandler^exceptionCaught:153)
java.lang.NullPointerException
        at java.util.concurrent.ConcurrentHashMap.get(ConcurrentHashMap.java:936)
        at net.openmob.mobileimsdk.server.processor.OnlineProcessor.getOnlineSession(OnlineProcessor.java:140)
        at net.openmob.mobileimsdk.server.ServerCoreHandler.sessionClosed(ServerCoreHandler.java:302)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.sessionClosed(DefaultIoFilterChain.java:797)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextSessionClosed(DefaultIoFilterChain.java:504)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$900(DefaultIoFilterChain.java:48)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.sessionClosed(DefaultIoFilterChain.java:927)
        at org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:108)
        at org.apache.mina.core.session.IoEvent.run(IoEvent.java:63)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
[DEBUG] - [22:51:30.590]【IMCORE-本机QoS】【QoS发送方】=========== 消息发送质量保证线程运行中, 当前需要处理的列表长度为1... | (QoS4SendDaemonRoot^doTaskOnece:148)
[DEBUG] - [22:51:30.591]【IMCORE-本机QoS】【QoS发送方】指纹为9639182f-3cbb-4c18-83e2-db0c37ffabbd的消息包重传次数已达1(最多1次)上限，将判定为丢包！ | (QoS4SendDaemonRoot^doTaskOnece:169)
[WARN] - [22:51:30.591]【IMCORE-本机QoS】【QoS发送方】指纹为9639182f-3cbb-4c18-83e2-db0c37ffabbd的消息已成功从发送质量保证队列中移除(可能是收到接收方的应答也可能是达到了重传的次数上限)，重试次数=1 | (QoS4SendDaemonRoot^remove:393)
[DEBUG] - [22:51:30.594]【DEBUG_QoS_S2C事件】收到系统的未实时送达事件通知，当前共有1个包QoS保证机制结束，判定为【无法实时送达】！ | (MessageQoSEventS2CListnerImpl^messagesLost:40)
[DEBUG] - [22:54:40.589]【IMCORE-本机QoS】【QoS接收方】++++++++++ START 暂存处理线程正在运行中，当前长度0. | (QoS4ReciveDaemonRoot^doTaskOnece:105)
[DEBUG] - [22:54:40.591]【IMCORE-本机QoS】【QoS接收方】++++++++++ END 暂存处理线程正在运行中，当前长度0. | (QoS4ReciveDaemonRoot^doTaskOnece:142)

引用：JackJiang 发表于 2018-06-07 22:02
理论上你描述的问题不应该发生，而且这个异常基本不可能是你说的这种情况下发生的。

我建议你换成MINA版 ...

好的我先试试

理论上你描述的问题不应该发生，而且这个异常基本不可能是你说的这种情况下发生的。

我建议你换成MINA版，用你同样的代码试试，看看MINA版什么效果，因为MINA版是久经考验的，可以用它来作参考基准，再来排查netty版的问题。
另外，建议你把Log贴的全面一点。

你按我说的来试试，然后有情况再贴出来，我会帮你看看