[已回复] 请教RainbowChat的的android端登陆超时问题

[INFO] - [17/10/06 12:01:34.335]基于EVA.EPC平台的J2EE模块已经被被始化了! | (WebListener^contextInitialized:28)
[DEBUG] - [17/10/06 12:01:34.845]【IMCORE-本机QoS】【QoS发送方】=========== 消息发送质量保证线程已成功启动 | (QoS4SendDaemonRoot^startup:290)
[INFO] - [17/10/06 12:01:34.846][IMCORE] 配置项：未开启与MobileIMSDK Web的互通. | (ServerLauncher^startup:195)
[INFO] - [17/10/06 12:01:34.954][IMCORE] UDP服务器正在端口9901上监听中... | (ServerLauncher^startup:204)
         [INFO] - [17/10/06 12:01:56.150]Hello EVA.EPC,init ok...  | (HttpPotal^init:43)
[DEBUG] - [17/10/06 12:01:56.154]>>S 客户端Cookie=null ip=110.54.182.178:20986 | (HttpPotal^process:98)
[DEBUG] - [17/10/06 12:01:56.154]【-->>>> 收到客户端的请求原型】:{"actionId":-9999999,"device":0,"doInput":true,"jobDispatchId":-9999999,"newData":"{\"clientVersion\":\"114\",\"deviceInfo\":\"{\\n\t\\\"device\\\":\\\"a8ltechn\\\",\\n\t\\\"deviceId\\\":\\\"352324071938839\\\",\\n\t\\\"sdk\\\":\\\"22\\\",\\n\t\\\"frimware\\\":\\\"5.1.1\\\",\\n\t\\\"phoneType\\\":1,\\n\t\\\"networkCountryIso\\\":\\\"ph\\\",\\n\t\\\"simOperator\\\":\\\"\\\",\\n\t\\\"networkOperator\\\":\\\"51502\\\",\\n\t\\\"simState\\\":1,\\n\t\\\"manufacturer\\\":\\\"samsung\\\",\\n\t\\\"networkRoaming\\\":false,\\n\t\\\"networkType\\\":0,\\n\t\\\"deviceSoftwareVersion\\\":\\\"01\\\",\\n\t\\\"appVersionCode\\\":114,\\n\t\\\"simCountryIso\\\":\\\"\\\",\\n\t\\\"networkOperatorName\\\":\\\"\\\",\\n\t\\\"display\\\":\\\"LMY47X.A8000ZCU2AOL3\\\",\\n\t\\\"callState\\\":0,\\n\t\\\"simOperatorName\\\":\\\"\\\",\\n\t\\\"product\\\":\\\"a8ltezc\\\",\\n\t\\\"model\\\":\\\"SM-A8000\\\"\\n}\",\"loginName\":\"400075\",\"loginPsw\":\"123123\",\"osType\":\"0\"}","processorId":1009,"token":"N/A"} | (MyControllerJSON^recieveFromClient:389)
[DEBUG] - [17/10/06 12:01:56.180]【【[HTTP][OS:0] 捕获REST[接口1009]的请求，token=N/A】】 | (MyControllerJSON^dispatch:99)
[DEBUG] - [17/10/06 12:01:56.195][HTTP]<版本检查START> ..................用户：400075 | (MyControllerJSON^dispatch:124)
[DEBUG] - [17/10/06 12:01:56.196]<客户端版本检查> 配置文件路径：/usr/local/tomcat/webapps/rainbowchat/WEB-INF/classes/apk_version.properties | (ClientAPKVersionChecker^getPropertyMan:130)
[DEBUG] - [17/10/06 12:01:56.197]<客户端版本检查> 客户端版本：114，服务端版本：114，客户端是否需要更新？false | (ClientAPKVersionChecker^checkClientAPKVersion:62)
[DEBUG] - [17/10/06 12:01:56.197][HTTP]<登陆时：登陆验证START> 400075，接下来将进入真正的登陆验证流程. | (MyControllerJSON^dispatch:140)
[DEBUG] - [17/10/06 12:01:56.198]queryData{SQL: select         user_uid        ,user_mail        ,nickname        ,user_sex        ,register_time        ,latest_login_time2        ,user_psw        ,is_online        ,user_avatar_file_name        ,what_s_up        ,max_friend        ,user_desc    ,user_type from missu_users  where user_status = 1        and user_uid=400075        and user_psw='4297f44b13955235245b2497399d7a93'} | (DBShell^queryData:277)
[DEBUG] - [17/10/06 12:01:56.230]【--<<<< 返回给客户端的JSON】:{"success":true,"returnValue":"{\"update_info\":\"{\\\"latestClientAPKFileSize\\\":0,\\\"needUpdate\\\":false,\\\"latestClientAPKVercionCode\\\":\\\"0\\\"}\",\"authed_info\":\"{\\\"register_time\\\":\\\"2017-10-06 06:43\\\",\\\"latest_login_time\\\":\\\"1507291197840\\\",\\\"liveStatus\\\":0,\\\"man\\\":false,\\\"mustVersion4A\\\":\\\"110\\\",\\\"mustVersionDesc4A\\\":\\\"This version includes important updates, you must complete update before login!\\\",\\\"userAvatarFileName\\\":\\\"\\\",\\\"whatsUp\\\":\\\"\\\",\\\"maxFriend\\\":\\\"20\\\",\\\"userDesc\\\":\\\"\\\",\\\"userType\\\":\\\"0\\\",\\\"token\\\":\\\"N\\\\\\/A\\\",\\\"user_uid\\\":\\\"400075\\\",\\\"online\\\":false,\\\"user_mail\\\":\\\"bessie@163.com\\\",\\\"nickname\\\":\\\"qwer\\\",\\\"user_sex\\\":\\\"0\\\"}\"}"} | (MyControllerJSON^sendToClient:364)
[DEBUG] - [17/10/06 12:01:56.230]>>E 处理完成,客户端 ip=110.54.182.178:20986 的请处理成功了?true - ret=class java.lang.String | (HttpPotal^process:129)
[INFO] - [17/10/06 12:01:56.473][IMCORE]与{uid:null}/110.54.182.178:60361的会话建立(sessionCreated)了... | (ServerCoreHandler^sessionCreated:304)
[INFO] - [17/10/06 12:01:56.476][IMCORE]与{uid:null}/110.54.182.178:60361的会话(sessionOpened)打开了... | (ServerCoreHandler^sessionOpened:317)
[INFO] - [17/10/06 12:01:56.483][IMCORE]>> 客户端{uid:null}/110.54.182.178:60361发过来的登陆信息内容是：loginInfo=400075|getToken=N/A | (LogicProcessor^processLogin:192)
[DEBUG] - [17/10/06 12:01:56.487]【@】当前在线用户共(1)人-------------------> | (OnlineProcessor^__printOnline:99)
[INFO] - [17/10/06 12:01:56.487][RBChat]用户登录成功--用户ID:400075,远程登录IP:/0.0.0.0:9901 | (ChatServerEventListener^onUserLoginAction_CallBack:65)
[DEBUG] - [17/10/06 12:01:56.493][RBChat]<----------当前在线用户共(1)人---------> | (UsersStatusManager^printLiveUsers:71)
[DEBUG] - [17/10/06 12:01:56.494]queryData{SQL: select a.friend_user_uid,c.user_mail,a.user_uid         from missu_roster a         left join missu_users b on a.user_uid = b.user_uid         left join missu_users c on a.friend_user_uid = c.user_uid         where a.user_uid='400075'} | (DBShell^queryData:277)
[DEBUG] - [17/10/06 12:01:59.845]【IMCORE-本机QoS】【QoS发送方】=========== 消息发送质量保证线程运行中, 当前需要处理的列表长度为1... | (QoS4SendDaemonRoot^doTaskOnece:146)
[DEBUG] - [17/10/06 12:01:59.847]【IMCORE-本机QoS】【QoS发送方】指纹为87516cda-7c0f-4329-b90a-e29db6564fe9的消息包已成功进行重传，此次之后重传次数已达1(最多1次). | (QoS4SendDaemonRoot^doTaskOnece:207)
[DEBUG] - [17/10/06 12:02:04.845]【IMCORE-本机QoS】【QoS发送方】=========== 消息发送质量保证线程运行中, 当前需要处理的列表长度为1... | (QoS4SendDaemonRoot^doTaskOnece:146)
[DEBUG] - [17/10/06 12:02:04.846]【IMCORE-本机QoS】【QoS发送方】指纹为87516cda-7c0f-4329-b90a-e29db6564fe9的消息包重传次数已达1(最多1次)上限，将判定为丢包！ | (QoS4SendDaemonRoot^doTaskOnece:167)
[WARN] - [17/10/06 12:02:04.846]【IMCORE-本机QoS】【QoS发送方】指纹为87516cda-7c0f-4329-b90a-e29db6564fe9的消息已成功从发送质量保证队列中移除(可能是收到接收方的应答也可能是达到了重传的次数上限)，重试次数=1 | (QoS4SendDaemonRoot^remove:391)
[INFO] - [17/10/06 12:02:06.473][IMCORE]与{uid:400075}/110.54.182.178:60361的会话关闭(user_id=400075)了... | (ServerCoreHandler^sessionClosed:268)
[INFO] - [17/10/06 12:02:06.473][RBChat]用户注销登录--用户ID:400075 | (ChatServerEventListener^onUserLogoutAction_CallBack:73)
[DEBUG] - [17/10/06 12:02:06.473]queryData{SQL: select a.friend_user_uid,c.user_mail,a.user_uid         from missu_roster a         left join missu_users b on a.user_uid = b.user_uid         left join missu_users c on a.friend_user_uid = c.user_uid         where a.user_uid='400075'} | (DBShell^queryData:277)
[DEBUG] - [17/10/06 12:02:06.481][RBChat]<----------当前在线用户共(0)人---------> | (UsersStatusManager^printLiveUsers:71)

以上是RainbowChat的服务端启动日志和登陆日志，检查过端口都是没有问题的，tcp的8080端口跟udp的9901端口。

就是登陆的时候一直提示登陆超时。

你这个日志是RainbowChat服务端的日志，不过底层的MobileIMSDK是一样的分析，没有区别。
从日志上看，这毫无疑问又是一例服务端跟客户端的网络没有双向互通而导致的。

首先RainbowChat的服务端很简单：就是http服务+im服务，而从你的日志上看，http服务很正常，我们不用讨论。

IM服务的日志，这两条就能说明问题：

[INFO] - [17/10/06 12:01:56.473][IMCORE]与{uid:null}/110.54.182.178:60361的会话建立(sessionCreated)了...
[INFO] - [17/10/06 12:02:06.473][IMCORE]与{uid:400075}/110.54.182.178:60361的会话关闭(user_id=400075)了...

第一条是服务端MINA网络层建立的时间（12:01:56秒），第二条是断开的时间（12:02:06秒），算下来刚好相差10秒，其实这并不是巧合。

MobileIMSDK服务端底层（也就是MINA框架层），默认设定的当客户端10秒无响应（没有心跳包过来）就意味着这个客户端网络可能掉线了（不能正常通信嘛），也就自动把它断掉了，正常情况下这是用于当客户端崩溃等非正常情况下的网络资源释放时使用。但你的日志表明：你的客户端能向服务端通信（IM连接建立的日志就能说明）、但服务端返回的登陆结果给客户端时客户端收不到（导致客户端一直认为服务端不响应，就是你看到的那个超时对话框出现的时候）。

综上分析：你的客户端到服务端这条链路是通的，但服务端到客户端这个方向是不通的。也就是手机能向服务器发送数据，但服务器向手机发送的数据手机收不到。

解决方法建议：你应该想办法来验证服务端向手机端这个方向的UDP通信为何不通：比如检查服务端的UDP防火墙策略（有无阻止9901的UDP端口的outbond方向通信）、检查一下机房的防火墙或路由器策略、或者让手机换个网络（从而排除手机的网络原因导致收不到udp数据等）等等手段来找到真正的原因。

网络通信程序最怕的就是这种网络不通或不全通的情况，但也是必须要具备解决这类问题的能力，因为它很普遍。如果你怀疑是代码没有部署对，你还可以找个最简单的UDP程序demo，直接跑起来验证（比如MINA或netty的官方demo就有，直接用这种简单的小程序轻量级的跑起来看看），从而找到真正的问题所在。

另外，如果你怀疑是手机这边的网络原因导致收不到udp数据，还有一个简单的验证方法：
那就是下一个MobileIMSDK的服务端放到你现在这台服务器上（直接部署运行的那个，在开源的MobileIMSDk的demo/server文件夹下），然后在你的个人电脑上运行一下java的demo客户端，来看看你这台服务器跟电脑上的客户端能否正常双向通信（因为个人电脑的网络不会像手机网络那样可能会因为无线路由问题或者3、4g运营商的网络问题而使得问题复杂化），如果能就表示服务端的网络环境应该没什么问题，而是手机的网络导致的，否则就应该还是服务器这边的网络问题。

我防火墙是关着的，也找过机房了，机房那边也说没有做任何封udp的策略，我也下载了mobileIMsdk测试过了，问题是一样的，所以基本扣除是手机网络的问题，就是java服务器的环境问题，同样的部署在我本地局域网里面是一切正常的，我把它部署到线上就出现登陆超时，真是没折了。还有什么可以做的吗？

[INFO] - [12:47:52.112][IMCORE]与{uid:null}/61.28.172.14:61963的会话建立(sessionCreated)了... | (ServerCoreHandler^sessionCreated:301)
[INFO] - [12:47:52.112][IMCORE]与{uid:null}/61.28.172.14:61963的会话(sessionOpened)打开了... | (ServerCoreHandler^sessionOpened:314)
[INFO] - [12:47:52.113][IMCORE]>> 客户端{uid:null}/61.28.172.14:61963发过来的登陆信息内容是：loginInfo=weq|getToken=wewew | (LogicProcessor^processLogin:206)
[DEBUG] - [12:47:52.113]【DEBUG_回调通知】正在调用回调方法：OnVerifyUserCallBack...(extra=null) | (ServerEventListenerImpl^onVerifyUserCallBack:55)
[DEBUG] - [12:47:52.114]【@】当前在线用户共(1)人-------------------> | (OnlineProcessor^__printOnline:98)
[DEBUG] - [12:47:52.114]【IM_回调通知OnUserLoginAction_CallBack】用户：weq 上线了！ | (ServerEventListenerImpl^onUserLoginAction_CallBack:73)
[DEBUG] - [12:47:53.607]【IMCORE-本机QoS】【QoS发送方】=========== 消息发送质量保证线程运行中, 当前需要处理的列表长度为1... | (QoS4SendDaemonRoot^doTaskOnece:148)
[WARN] - [12:47:53.607]【IMCORE-本机QoS】【QoS发送方】指纹为68945460-433c-4f70-b075-c72955189ae8的包距"刚刚"发出才1493ms(<=2000ms将被认定是"刚刚"), 本次不需要重传哦. | (QoS4SendDaemonRoot^doTaskOnece:187)
[DEBUG] - [12:47:58.607]【IMCORE-本机QoS】【QoS发送方】=========== 消息发送质量保证线程运行中, 当前需要处理的列表长度为1... | (QoS4SendDaemonRoot^doTaskOnece:148)
[DEBUG] - [12:47:58.608]【IMCORE-本机QoS】【QoS发送方】指纹为68945460-433c-4f70-b075-c72955189ae8的消息包已成功进行重传，此次之后重传次数已达1(最多1次). | (QoS4SendDaemonRoot^doTaskOnece:209)
[INFO] - [12:48:02.138][IMCORE]与{uid:weq}/61.28.172.14:61963的会话关闭(user_id=weq)了... | (ServerCoreHandler^sessionClosed:265)
[DEBUG] - [12:48:02.138]【DEBUG_回调通知OnUserLogoutAction_CallBack】用户：weq 离线了！ | (ServerEventListenerImpl^onUserLogoutAction_CallBack:88)
[DEBUG] - [12:48:03.607]【IMCORE-本机QoS】【QoS发送方】=========== 消息发送质量保证线程运行中, 当前需要处理的列表长度为1... | (QoS4SendDaemonRoot^doTaskOnece:148)
[DEBUG] - [12:48:03.607]【IMCORE-本机QoS】【QoS发送方】指纹为68945460-433c-4f70-b075-c72955189ae8的消息包重传次数已达1(最多1次)上限，将判定为丢包！ | (QoS4SendDaemonRoot^doTaskOnece:169)
[WARN] - [12:48:03.608]【IMCORE-本机QoS】【QoS发送方】指纹为68945460-433c-4f70-b075-c72955189ae8的消息已成功从发送质量保证队列中移除(可能是收到接收方的应答也可能是达到了重传的次数上限)，重试次数=1 | (QoS4SendDaemonRoot^remove:393)
[DEBUG] - [12:48:03.608]【DEBUG_QoS_S2C事件】收到系统的未实时送达事件通知，当前共有1个包QoS保证机制结束，判定为【无法实时送达】！ | (MessageQoSEventS2CListnerImpl^messagesLost:40)
[DEBUG] - [12:51:48.606]【IMCORE-本机QoS】【QoS接收方】++++++++++ START 暂存处理线程正在运行中，当前长度0. | (QoS4ReciveDaemonRoot^doTaskOnece:105)
[DEBUG] - [12:51:48.606]【IMCORE-本机QoS】【QoS接收方】++++++++++ END 暂存处理线程正在运行中，当前长度0. | (QoS4ReciveDaemonRoot^doTaskOnece:142)

引用：wayne 发表于 2017-10-10 20:51
我防火墙是关着的，也找过机房了，机房那边也说没有做任何封udp的策略，我也下载了mobileIMsdk测试过了，问 ...

我在3楼回复你的已经足够让你找到解决问题的灵感了。。。

你照着我在3楼的回复，想办法逐一排除除问题，或者你还有其它服务器吗，换台试试看吧。这一定是服务器或者什么地方的网络配置没弄好。建议你可以随便找个java的网络编程demo跑一下，一样是不通的，但不能认为这就没办法跑java的udp网络代码了，所以问题肯定还是在你的服务器，这种基本的服务器系统网络配置问题好难帮的上你的忙