IM TCP网络问题分析

心跳异常

香港心跳异常

现象

手表使用香港卡用80端口连接到IM服务器出现心跳急剧下降到60秒的异

常

出现异常的都是使用80端口，如果是使用8000端口就恢复正常

原因

80端口是Http的常用端口号，连接到IM服务器之后，由于服务器并没有

把Http和TCP连接服务做区分导致IM的TCP使用80端口连接进来的时候被误

识别成是一个Http请求，所以就对IM的TCP数据流（TLV格式）进行解析导

致报错返回了一个Http请求报错的网页的Html数据，具体返回的数据格式

客户端打印是：

<body bgcolor="white">
<center><h1>400 Bad Request</h1></center>
<hr><center>nginx/1.8.0</center>

以上是客户端TCP数据流read到100字节打印出来的数据，是一个Http请求

失败返回Http状态码为400的网页Html数据

image.png

以上是tcpdump抓包信息，从抓包信息中可以得知返回的数据确实是一个

Http请求失败的网页，对比客户端程序log打印是吻合的

客户端的TCP流读取到上述数据的时候以为是IM服务器正常返回的TLV格

式的数据，所以对read到的数据进行常规的TLV数据解析导致程序解析报错

(数组越界)：

{ConnectionService$6.onRead--1} 
com.xtc.sync.b.b: decode data 

error:java.lang.ArrayIndexOutOfBoundsException: src.length=45 

srcPos=2 dst.length=121 dstPos=0 length=121
at com.xtc.sync.push.common.f.a(Unknown Source)
at com.xtc.sync.push.common.ConnectionService$6.onRead(Unknown 

Source)
at com.xtc.sync.push.common.m.b(Unknown Source)
at com.xtc.sync.push.common.m.a(Unknown Source)
at com.xtc.sync.push.common.m.run(Unknown Source)

客户端发生数据解析报错之后会认为当前接收到的数据已经不正确，同时

也会认为后面接续读取的数据也将不正确，所以会把socket连接关闭重连

：

java.net.SocketException: Socket closed
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:151)
at java.net.SocketInputStream.read(SocketInputStream.java:120)
at java.net.SocketInputStream.read(SocketInputStream.java:106)
at com.xtc.sync.push.common.m.run(Unknown Source)

对于客户端IM SDK而言

遇到数据解析异常导致的TCP连接断开跟网络NAT超时时间无关，因此不

应该下调心跳周期，但是旧版（1.0.1Realease-1.0.6Realease版本）存在

不足，并没有对此做过滤处理，所以会不断的下调心跳

在遇到数据解析异常断开重连的时候没有做时间间隔递增的重连，所以

断线后会马上重连

客户端IM SDK在断线重连之前没有先切换域名或者端口，选择拿原来连

接断开的域名和端口再次尝试重连，在重试重连失败的时候才会去切换域

名或者端口，而遇到这种情况，每次尝试重连TCP都能连接成功，连接成功

之后，数据解析失败又把TCP连接断开，然后再拿原来的域名和端口，再重

连，再断开，如此陷入死循环，无法切换域名或者端口，断线重连频率很

高：

Line 12623: 07-16 16:46:31.097  2772  3511 W SYNC-PUSH: 

{ConnectionService$5.onDisconnected--1} connection is 

disconnected
    Line 12860: 07-16 16:46:31.424  2772  3515 W SYNC-PUSH: 

{ConnectionService$5.onDisconnected--1} connection is 

disconnected
    Line 13074: 07-16 16:46:31.758  2772  3519 W SYNC-PUSH: 

{ConnectionService$5.onDisconnected--1} connection is 

disconnected
    Line 13307: 07-16 16:46:32.054  2772  3524 W SYNC-PUSH: 

{ConnectionService$5.onDisconnected--1} connection is 

disconnected
    Line 13560: 07-16 16:46:32.360  2772  3529 W SYNC-PUSH: 

{ConnectionService$5.onDisconnected--1} connection is 

disconnected
    Line 13789: 07-16 16:46:32.687  2772  3531 W SYNC-PUSH: 

{ConnectionService$5.onDisconnected--1} connection is 

disconnected
    Line 14002: 07-16 16:46:32.987  2772  3537 W SYNC-PUSH: 

{ConnectionService$5.onDisconnected--1} connection is 

disconnected
    Line 14214: 07-16 16:46:33.293  2772  3541 W SYNC-PUSH: 

{ConnectionService$5.onDisconnected--1} connection is 

disconnected
    Line 14430: 07-16 16:46:33.648  2772  3545 W SYNC-PUSH: 

{ConnectionService$5.onDisconnected--1} connection is 

disconnected

完整的连接成功，读取数据，数据解析失败，断线重连的log：

07-16 16:46:31.501  2772  2950 I SYNC-PUSH: {p.a--1} 

inetSocketAddress时间间隔(ms):0
07-16 16:46:31.505  2556  2556 D SYNC-PUSH: 

{BaseHandleService.onCreate--1} 

PushConnStatusChangedHandleService created...
07-16 16:46:31.507  2556  2556 I SYNC-PUSH: 

{BaseHandleService.onStartCommand--1} 

PushConnStatusChangedHandleService startId:1
07-16 16:46:31.508  2556  3518 D SYNC-PUSH: 

{BaseHandleService.onHandleIntent--1} 

PushConnStatusChangedHandleService onHandleIntent...
07-16 16:46:31.509  2556  3518 I SYNC-PUSH: 

{PushConnStatusChangedHandleService.a--1} receive 

action:com.xtc.sync.connecting
07-16 16:46:31.513  2556  2556 D SYNC-PUSH: 

{BaseHandleService.onDestroy--1} 

PushConnStatusChangedHandleService destroy...
07-16 16:46:31.578  2772  2950 I SYNC-PUSH: {p.a--1} connect时间

间隔(ms):77
07-16 16:46:31.579  2772  2950 D SYNC-PUSH: {r.a--1} cancel task 

executor
07-16 16:46:31.580  2772  2950 I SYNC-PUSH: {p.r--1} 

lastConnectPeriod:229
07-16 16:46:31.580  2772  2950 W SYNC-PUSH: {p.r--1} connected 

and disconnected is too frequently,do not reset 

reconnectPeriodTag:30000
07-16 16:46:31.582  2772  2950 I SYNC-PUSH: {ConnectionService

$5.onConnected--1} connect to server 

success,hostname:gw.im.okii.com,port:80
07-16 16:46:31.583  2772  2950 D SYNC-PUSH: {ConnectionService

$5.onConnected--1} on thread:Task-Thread#1
07-16 16:46:31.583  2772  2950 D SYNC-PUSH: {r.d--1} start task 

executor
07-16 16:46:31.586  2772  2950 I SYNC-PUSH: 

{AppUtil.isAppActive--1} com.xtc.i3launcher app is active
07-16 16:46:31.587  2772  2950 W ContextImpl: Calling a method in 

the system process without a qualified user: 

android.app.ContextImpl.startService:1357 

android.content.ContextWrapper.startService:613 

com.xtc.sync.push.common.g.a:-1 com.xtc.sync.push.common.k.a:-1 

com.xtc.sync.push.common.ConnectionService$5.onConnected:-1 
07-16 16:46:31.591  2772  2950 I SYNC-PUSH: {g.a--1} notify on 

push connected 

PushConnStatusChangedHandleServicesuccessfully,pkgName:com.xtc.i3

launcher
07-16 16:46:31.597  2556  2556 D SYNC-PUSH: 

{BaseHandleService.onCreate--1} 

PushConnStatusChangedHandleService created...
07-16 16:46:31.598  2556  2556 I SYNC-PUSH: 

{BaseHandleService.onStartCommand--1} 

PushConnStatusChangedHandleService startId:1
07-16 16:46:31.600  2556  3520 D SYNC-PUSH: 

{BaseHandleService.onHandleIntent--1} 

PushConnStatusChangedHandleService onHandleIntent...
07-16 16:46:31.601  2556  3520 I SYNC-PUSH: 

{PushConnStatusChangedHandleService.a--1} receive 

action:com.xtc.sync.connected
07-16 16:46:31.601  2556  3520 I SYNC-PUSH: 

{PushConnStatusChangedHandleService$1.a--1} handle 

action:com.xtc.sync.connected
07-16 16:46:31.602  2556  3520 D SYNC-PUSH: 

{PushConnStatusChangedHandleService.b--1} handleSyncPushConnected
07-16 16:46:31.603  2556  3520 I SYNC-PUSH: 

{StoreUtil.readPublicKey--1} sync 

publicKey:MIGfMA0GCSqGSIb3DQEBAQUAA4GNADCBiQKBgQDC6kMRGBPWhWvU0Do

HIn6UJgttdmxEZGmRqz1vlE9xAwXIoNbOOuEtKK9YYP4zbMB7xk319Xt1uI9no8Yy

x4cBneRD+3tiBlX6SBLTxDkR1uXxGOPg+agzQ9b29n3FNtFQqyuTTTB4y7FcxKHi

+ndammhtBrMEOwm+LrwRAaD3EQIDAQAB
07-16 16:46:31.604  2772  2950 I SYNC-PUSH: {ConnectionService

$5.onConnected--1} 预埋IP信息:

[{"connectCount":1,"connectFailedCount":0,"connectedSuccessCount"

:1,"disconnectedCount":1,"dns":false,"hostname":"gw.im.okii.com",

"lastConnectFailedCount":0,"port":8000,"start":1500194721268,"ttl

":0,"update":1500194758177}, 

{"connectCount":8,"connectFailedCount":0,"connectedSuccessCount":

7,"disconnectedCount":7,"dns":false,"hostname":"gw.im.okii.com","

lastConnectFailedCount":0,"port":80,"start":1500194721364,"ttl":0

,"update":1500194791500}, 

{"connectCount":0,"connectFailedCount":0,"connectedSuccessCount":

0,"disconnectedCount":0,"dns":false,"hostname":"120.25.129.142","

lastConnectFailedCount":0,"port":1883,"start":1500194721275,"ttl"

:0,"update":0}, 

{"connectCount":0,"connectFailedCount":0,"connectedSuccessCount":

0,"disconnectedCount":0,"dns":false,"hostname":"120.25.129.142","

lastConnectFailedCount":0,"port":8000,"start":1500194721318,"ttl"

:0,"update":0}]
07-16 16:46:31.607  2556  3520 D SYNC-PUSH: {l.b--1} create 

EncryptSetRequestEntity:d:{"a":100021,"b":1,"c":null}
07-16 16:46:31.608  2556  3520 D SYNC-PUSH: {d.a--1} add a 

request,RID:100021
07-16 16:46:31.609  2556  3520 W SYNC-PUSH: {e.a--1} request 

sweeper is started.
07-16 16:46:31.610  2556  3520 D SYNC-PUSH: {d$21.b--1} execute 

enqueueRequest on aidl
07-16 16:46:31.612  2772  2950 I SYNC-PUSH: 

{NetUtil.getSIMType--1} getSIMType:45400,simOperatorName:csl.
07-16 16:46:31.613  2556  3520 I SYNC-PUSH: {d$21.b--1} enqueue 

request entity:d:{"a":100021,"b":1,"c":null}
07-16 16:46:31.613  2772  2950 I SYNC-PUSH: 

{NetUtil.getSIMType--1} getSIMType:csl.
07-16 16:46:31.616  2556  3520 W SYNC-PUSH: {TLVObjectUtil.a--1} 

formatdata error(value is null),name:c,type:class [B
07-16 16:46:31.616  2772  2950 I SYNC-PUSH: 

{NetUtil.getNetworkTag--1} Network tag:csl.-4G
07-16 16:46:31.617  2772  2950 D SYNC-PUSH: {a.a--1} record push 

socket info
07-16 16:46:31.618  2772  2946 D SYNC-PUSH: {ConnectionService

$a.a--1} enqueueSingleSendTask:Binder:2772_4
07-16 16:46:31.618  2772  2950 I SYNC-PUSH: {p.a--1} connect to 

server success {remoteAddress=gw.im.okii.com,remotePort=80}
07-16 16:46:31.622  2772  2946 I SYNC-PUSH: 

{TLVObjectUtil.parseEntity--1} TLVDecodeResult:TLVDecodeResult 

[frameType=0, dataType=32, tagValue=33, length=9, value=

[TLVDecodeResult [frameType=0, dataType=0, tagValue=1, length=4, 

value=[0, 1, -122, -75]], TLVDecodeResult [frameType=0, 

dataType=0, tagValue=10, length=1, value=[1]]]]
07-16 16:46:31.623  2772  2950 W SYNC-PUSH: {p.a--1} cancel 

alarm.
07-16 16:46:31.626  2772  3462 D SYNC-PUSH: {o.h--1} execute the 

send task...
07-16 16:46:31.626  2772  2950 W SYNC-PUSH: {h.a--1} There is a 

hostinfo 

({"connectCount":8,"connectFailedCount":0,"connectedSuccessCount"

:8,"disconnectedCount":7,"dns":false,"hostname":"gw.im.okii.com",

"lastConnectFailedCount":0,"port":80,"start":1500194721364,"ttl":

0,"update":1500194791618}) with the same hostname and port in the 

hostinfo list.
07-16 16:46:31.627  2772  3462 D SYNC-PUSH: 

{ConnectionService.c--1} sendOnBefore
07-16 16:46:31.629  2772  3462 I SYNC-PUSH: {ConnectionService

$6.onWrite--1} write [144] bytes.
07-16 16:46:31.630  2772  2950 I SYNC-PUSH: {b.run--1} connect 

success,network type:4G
07-16 16:46:31.631  1890  2596 D PowerManagerService: 

releaseWakeLockInternal: lock=234890036 [ConnectTask@WakeLock-

21], flags=0x0
07-16 16:46:31.631  1890  2596 D PowerManagerService: 

updateWakeLockSummaryLocked: mWakefulness=Asleep, 

mWakeLockSummary=0x0
07-16 16:46:31.631  1890  2596 D PowerManagerService: Releasing 

suspend blocker "PowerManagerService.WakeLocks".
07-16 16:46:31.632  2772  2950 I SYNC-PUSH: {b.b--1} release a 

connect task wake lock,tag:ConnectTask@WakeLock-

21,acquireDuration:249
07-16 16:46:31.632  2772  3462 D SYNC-PUSH: 

{ConnectionService.b--1} data sent successfully.
07-16 16:46:31.633  2772  2946 D SYNC-PUSH: {r.a--1} execute a 

task,size:0
07-16 16:46:31.636  2556  2556 D SYNC-PUSH: 

{BaseHandleService.onDestroy--1} 

PushConnStatusChangedHandleService destroy...
07-16 16:46:31.638  2772  3462 I SYNC-PUSH: {o.h--1} send data 

success,data:d:{"a":100021,"b":1,"c":[-103,13,105,59,21,-

90,69,86,22,-85,55,-67,66,77,-73,8,-66,96,-124,26,-119,-

61,33,12,120,46,8,76,117,-76,119,57,-21,95,-81,-84,91,-19,-122,-

94,-28,-74,-32,-66,25,-18,84,-46,-88,92,-54,90,0,-75,-

38,23,34,10,-11,-95,-28,32,-37,5,11,-12,20,28,-97,-127,63,-

109,66,-86,-48,-124,8,-95,22,-57,-34,-16,127,17,-42,-93,90,-94,-

43,-123,68,11,-32,-62,33,-79,-72,51,12,62,72,3,87,-28,-108,-52,-

47,-127,77,45,101,-78,-53,-99,90,47,31,12,19,90,27,-57,-1,-69,-

5,-73,-59,100]}
07-16 16:46:31.667  1890  2403 D PowerManagerService: 

acquireWakeLockInternal: lock=228675774, flags=0x1, 

tag="ReadData@WakeLock-1", ws=null, uid=1000, pid=2772
07-16 16:46:31.667  1890  2403 D PowerManagerService: 

updateWakeLockSummaryLocked: mWakefulness=Asleep, 

mWakeLockSummary=0x1
07-16 16:46:31.667  1890  2403 D PowerManagerService: Acquiring 

suspend blocker "PowerManagerService.WakeLocks".
07-16 16:46:31.668  2772  3519 I SYNC-PUSH: {n.a--1} acquire the 

read data wake lock,tag:ReadData@WakeLock-

1,acquireTime:1500194791668
07-16 16:46:31.669  2772  3519 I SYNC-PUSH: {m.run--1} read [323] 

bytes,all buffer bytes:323
07-16 16:46:31.670  2772  3519 I SYNC-PUSH: {m.run--1} read data 

hex:485454502F312E31203430302042616420526571756573740D0A536572766

5723A206E67696E782F312E382E300D0A446174653A2053756E2C203136204A75

6C20323031372030383A34363A333420474D540D0A436F6E74656E742D5479706

53A20746578742F68746D6C0D0A436F6E74656E742D4C656E6774683A20313732

0D0A436F6E6E656374696F6E3A20636C6F73650D0A0D0A3C68746D6C3E0D0A3C6

86561643E3C7469746C653E3430302042616420526571756573743C2F7469746C

653E3C2F686561643E0D0A3C626F6479206267636F6C6F723D227768697465223

E0D0A3C63656E7465723E3C68313E3430302042616420526571756573743C2F68

313E3C2F63656E7465723E0D0A3C68723E3C63656E7465723E6E67696E782F312

E382E303C2F63656E7465723E0D0A3C2F626F64793E0D0A3C2F68746D6C3E0D0A
07-16 16:46:31.671  2772  3519 I SYNC-PUSH: {m.run--1} read data 

binary:[72, 84, 84, 80, 47, 49, 46, 49, 32, 52, 48, 48, 32, 66, 

97, 100, 32, 82, 101, 113, 117, 101, 115, 116, 13, 10, 83, 101, 

114, 118, 101, 114, 58, 32, 110, 103, 105, 110, 120, 47, 49, 46, 

56, 46, 48, 13, 10, 68, 97, 116, 101, 58, 32, 83, 117, 110, 44, 

32, 49, 54, 32, 74, 117, 108, 32, 50, 48, 49, 55, 32, 48, 56, 58, 

52, 54, 58, 51, 52, 32, 71, 77, 84, 13, 10, 67, 111, 110, 116, 

101, 110, 116, 45, 84, 121, 112, 101, 58, 32, 116, 101, 120, 116, 

47, 104, 116, 109, 108, 13, 10, 67, 111, 110, 116, 101, 110, 116, 

45, 76, 101, 110, 103, 116, 104, 58, 32, 49, 55, 50, 13, 10, 67, 

111, 110, 110, 101, 99, 116, 105, 111, 110, 58, 32, 99, 108, 111, 

115, 101, 13, 10, 13, 10, 60, 104, 116, 109, 108, 62, 13, 10, 60, 

104, 101, 97, 100, 62, 60, 116, 105, 116, 108, 101, 62, 52, 48, 

48, 32, 66, 97, 100, 32, 82, 101, 113, 117, 101, 115, 116, 60, 

47, 116, 105, 116, 108, 101, 62, 60, 47, 104, 101, 97, 100, 62, 

13, 10, 60, 98, 111, 100, 121, 32, 98, 103, 99, 111, 108, 111, 

114, 61, 34, 119, 104, 105, 116, 101, 34, 62, 13, 10, 60, 99, 

101, 110, 116, 101, 114, 62, 60, 104, 49, 62, 52, 48, 48, 32, 66, 

97, 100, 32, 82, 101, 113, 117, 101, 115, 116, 60, 47, 104, 49, 

62, 60, 47, 99, 101, 110, 116, 101, 114, 62, 13, 10, 60, 104, 

114, 62, 60, 99, 101, 110, 116, 101, 114, 62, 110, 103, 105, 110, 

120, 47, 49, 46, 56, 46, 48, 60, 47, 99, 101, 110, 116, 101, 114, 

62, 13, 10, 60, 47, 98, 111, 100, 121, 62, 13, 10, 60, 47, 104, 

116, 109, 108, 62, 13, 10]
07-16 16:46:31.672  2772  3519 I SYNC-PUSH: {m.run--1} read data 

test format:HTTP/1.1 400 Bad Request
07-16 16:46:31.672  2772  3519 I SYNC-PUSH: Server: nginx/1.8.0
07-16 16:46:31.672  2772  3519 I SYNC-PUSH: Date: Sun, 16 Jul 

2017 08:46:34 GMT
07-16 16:46:31.672  2772  3519 I SYNC-PUSH: Content-Type: 

text/html
07-16 16:46:31.672  2772  3519 I SYNC-PUSH: Content-Length: 172
07-16 16:46:31.672  2772  3519 I SYNC-PUSH: Connection: close
07-16 16:46:31.672  2772  3519 I SYNC-PUSH: 
07-16 16:46:31.672  2772  3519 I SYNC-PUSH: <html>
07-16 16:46:31.672  2772  3519 I SYNC-PUSH: <head><title>400 Bad 

Request</title></head>
07-16 16:46:31.672  2772  3519 I SYNC-PUSH: <body 

bgcolor="white">
07-16 16:46:31.672  2772  3519 I SYNC-PUSH: <center><h1>400 Bad 

Request</h1></center>
07-16 16:46:31.672  2772  3519 I SYNC-PUSH: 

<hr><center>nginx/1.8.0</center>
07-16 16:46:31.672  2772  3519 I SYNC-PUSH: </body>
07-16 16:46:31.672  2772  3519 I SYNC-PUSH: </html>
07-16 16:46:31.673  2772  3519 I SYNC-PUSH: {m.a--1} cut data[86] 

bytes,rest buffer bytes:237
07-16 16:46:31.674  2772  3519 I SYNC-PUSH: {m.a--1} 

hex:485454502F312E31203430302042616420526571756573740D0A536572766

5723A206E67696E782F312E382E300D0A446174653A2053756E2C203136204A75

6C20323031372030383A34363A333420474D540D0A436F
07-16 16:46:31.675  2772  3519 I SYNC-PUSH: {m.a--1} binary:[72, 

84, 84, 80, 47, 49, 46, 49, 32, 52, 48, 48, 32, 66, 97, 100, 32, 

82, 101, 113, 117, 101, 115, 116, 13, 10, 83, 101, 114, 118, 101, 

114, 58, 32, 110, 103, 105, 110, 120, 47, 49, 46, 56, 46, 48, 13, 

10, 68, 97, 116, 101, 58, 32, 83, 117, 110, 44, 32, 49, 54, 32, 

74, 117, 108, 32, 50, 48, 49, 55, 32, 48, 56, 58, 52, 54, 58, 51, 

52, 32, 71, 77, 84, 13, 10, 67, 111]
07-16 16:46:31.675  2772  3519 I SYNC-PUSH: {ConnectionService

$6.onRead--1} read [86] bytes
07-16 16:46:31.677  2772  3519 I SYNC-PUSH: 

{TLVObjectUtil.parseEntity--1} TLVDecodeResult:TLVDecodeResult 

[frameType=64, dataType=0, tagValue=8, length=84, value=[84, 80, 

47, 49, 46, 49, 32, 52, 48, 48, 32, 66, 97, 100, 32, 82, 101, 

113, 117, 101, 115, 116, 13, 10, 83, 101, 114, 118, 101, 114, 58, 

32, 110, 103, 105, 110, 120, 47, 49, 46, 56, 46, 48, 13, 10, 68, 

97, 116, 101, 58, 32, 83, 117, 110, 44, 32, 49, 54, 32, 74, 117, 

108, 32, 50, 48, 49, 55, 32, 48, 56, 58, 52, 54, 58, 51, 52, 32, 

71, 77, 84, 13, 10, 67, 111]]
07-16 16:46:31.679  2772  3519 D :       : {f.a--1} decode no 

encrypt data
07-16 16:46:31.680  2772  3519 I SYNC-PUSH: {f.a--1} decode 

data:e:{"b":0}
07-16 16:46:31.682  2772  3519 I SYNC-PUSH: 

{ConnectionService.a--1} receive response entity:e:{"b":0}
07-16 16:46:31.683  1890  1902 D PowerManagerService: 

releaseWakeLockInternal: lock=228675774 [ReadData@WakeLock-1], 

flags=0x0
07-16 16:46:31.684  1890  1902 D PowerManagerService: 

updateWakeLockSummaryLocked: mWakefulness=Asleep, 

mWakeLockSummary=0x0
07-16 16:46:31.684  1890  1902 D PowerManagerService: Releasing 

suspend blocker "PowerManagerService.WakeLocks".
07-16 16:46:31.685  2772  3519 I SYNC-PUSH: {n.a--1} release read 

data wake lock,tag:ReadData@WakeLock-1,acquireDuration:17
07-16 16:46:31.686  2772  3519 W SYNC-PUSH: {b.e--1} heartbeat 

scheduler is not started
07-16 16:46:31.688  2772  3519 D SYNC-PUSH: 

{ConnectionService.A--1} heartbeat response on time:08:00:00
07-16 16:46:31.691  2772  3519 I SYNC-PUSH: {m.a--1} cut data

[118] bytes,rest buffer bytes:119
07-16 16:46:31.692  2772  3519 I SYNC-PUSH: {m.a--1} 

hex:6E74656E742D547970653A20746578742F68746D6C0D0A436F6E74656E742

D4C656E6774683A203137320D0A436F6E6E656374696F6E3A20636C6F73650D0A

0D0A3C68746D6C3E0D0A3C686561643E3C7469746C653E3430302042616420526

571756573743C2F7469746C653E3C2F686561643E0D0A
07-16 16:46:31.692  2772  3519 I SYNC-PUSH: {m.a--1} binary:[110, 

116, 101, 110, 116, 45, 84, 121, 112, 101, 58, 32, 116, 101, 120, 

116, 47, 104, 116, 109, 108, 13, 10, 67, 111, 110, 116, 101, 110, 

116, 45, 76, 101, 110, 103, 116, 104, 58, 32, 49, 55, 50, 13, 10, 

67, 111, 110, 110, 101, 99, 116, 105, 111, 110, 58, 32, 99, 108, 

111, 115, 101, 13, 10, 13, 10, 60, 104, 116, 109, 108, 62, 13, 

10, 60, 104, 101, 97, 100, 62, 60, 116, 105, 116, 108, 101, 62, 

52, 48, 48, 32, 66, 97, 100, 32, 82, 101, 113, 117, 101, 115, 

116, 60, 47, 116, 105, 116, 108, 101, 62, 60, 47, 104, 101, 97, 

100, 62, 13, 10]
07-16 16:46:31.693  2772  3519 I SYNC-PUSH: {ConnectionService

$6.onRead--1} read [118] bytes
07-16 16:46:31.699  2772  3519 E SYNC-PUSH: {f.a--1} 
07-16 16:46:31.699  2772  3519 E SYNC-PUSH: 

java.lang.ArrayIndexOutOfBoundsException: src.length=45 srcPos=2 

dst.length=121 dstPos=0 length=121
07-16 16:46:31.699  2772  3519 E SYNC-PUSH:     at 

java.lang.System.arraycopy(Native Method)
07-16 16:46:31.699  2772  3519 E SYNC-PUSH:     at 

com.xtc.sync.c.d.a(Unknown Source)
07-16 16:46:31.699  2772  3519 E SYNC-PUSH:     at 

com.xtc.sync.c.d.a(Unknown Source)
07-16 16:46:31.699  2772  3519 E SYNC-PUSH:     at 

com.xtc.sync.c.d.a(Unknown Source)
07-16 16:46:31.699  2772  3519 E SYNC-PUSH:     at 

com.xtc.sync.c.d.a(Unknown Source)
07-16 16:46:31.699  2772  3519 E SYNC-PUSH:     at 

com.xtc.sync.c.d.a(Unknown Source)
07-16 16:46:31.699  2772  3519 E SYNC-PUSH:     at 

com.xtc.sync.c.d.a(Unknown Source)
07-16 16:46:31.699  2772  3519 E SYNC-PUSH:     at 

com.xtc.sync.c.d.a(Unknown Source)
07-16 16:46:31.699  2772  3519 E SYNC-PUSH:     at 

com.xtc.sync.c.d.a(Unknown Source)
07-16 16:46:31.699  2772  3519 E SYNC-PUSH:     at 

com.xtc.sync.util.TLVObjectUtil.parseEntity(Unknown Source)
07-16 16:46:31.699  2772  3519 E SYNC-PUSH:     at 

com.xtc.sync.push.common.f.a(Unknown Source)
07-16 16:46:31.699  2772  3519 E SYNC-PUSH:     at 

com.xtc.sync.push.common.ConnectionService$6.onRead(Unknown 

Source)
07-16 16:46:31.699  2772  3519 E SYNC-PUSH:     at 

com.xtc.sync.push.common.m.b(Unknown Source)
07-16 16:46:31.699  2772  3519 E SYNC-PUSH:     at 

com.xtc.sync.push.common.m.a(Unknown Source)
07-16 16:46:31.699  2772  3519 E SYNC-PUSH:     at 

com.xtc.sync.push.common.m.run(Unknown Source)
07-16 16:46:31.700  2772  3519 E SYNC-PUSH: {f.a--1} error 

data,length:118,content 

hex:6E74656E742D547970653A20746578742F68746D6C0D0A436F6E74656E742

D4C656E6774683A203137320D0A436F6E6E656374696F6E3A20636C6F73650D0A

0D0A3C68746D6C3E0D0A3C686561643E3C7469746C653E3430302042616420526

571756573743C2F7469746C653E3C2F686561643E0D0A
07-16 16:46:31.701  2556  2756 D SYNC-PUSH: {e.c--1} sweep 

request...
07-16 16:46:31.701  2772  3519 E SYNC-PUSH: {f.a--1} error 

data,length:118,content binary:[110, 116, 101, 110, 116, 45, 84, 

121, 112, 101, 58, 32, 116, 101, 120, 116, 47, 104, 116, 109, 

108, 13, 10, 67, 111, 110, 116, 101, 110, 116, 45, 76, 101, 110, 

103, 116, 104, 58, 32, 49, 55, 50, 13, 10, 67, 111, 110, 110, 

101, 99, 116, 105, 111, 110, 58, 32, 99, 108, 111, 115, 101, 13, 

10, 13, 10, 60, 104, 116, 109, 108, 62, 13, 10, 60, 104, 101, 97, 

100, 62, 60, 116, 105, 116, 108, 101, 62, 52, 48, 48, 32, 66, 97, 

100, 32, 82, 101, 113, 117, 101, 115, 116, 60, 47, 116, 105, 116, 

108, 101, 62, 60, 47, 104, 101, 97, 100, 62, 13, 10]
07-16 16:46:31.702  2772  3519 E SYNC-PUSH: {f.a--1} error data 

test format:ntent-Type: text/html
07-16 16:46:31.702  2772  3519 E SYNC-PUSH: Content-Length: 172
07-16 16:46:31.702  2772  3519 E SYNC-PUSH: Connection: close
07-16 16:46:31.702  2772  3519 E SYNC-PUSH: 
07-16 16:46:31.702  2772  3519 E SYNC-PUSH: <html>
07-16 16:46:31.702  2772  3519 E SYNC-PUSH: <head><title>400 Bad 

Request</title></head>
07-16 16:46:31.703  2772  3519 D SYNC-PUSH: {p.c--1} connection 

has release.
07-16 16:46:31.704  2772  3519 W SYNC-PUSH: {p.a--1} cancel 

connect
07-16 16:46:31.707  2772  3519 W SYNC-PUSH: {p.a--1} cancel 

alarm.
07-16 16:46:31.708  2772  3519 D SYNC-PUSH: {r.a--1} cancel task 

executor
07-16 16:46:31.709  2772  3519 D SYNC-PUSH: {r.a--1} execute a 

task,size:0
07-16 16:46:31.709  2772  2950 D SYNC-PUSH: {b.run--1} run 

connect task...
07-16 16:46:31.710  1890  2596 D PowerManagerService: 

acquireWakeLockInternal: lock=18235040, flags=0x1, 

tag="ConnectTask@WakeLock-23", ws=null, uid=1000, pid=2772
07-16 16:46:31.710  1890  2596 D PowerManagerService: 

updateWakeLockSummaryLocked: mWakefulness=Asleep, 

mWakeLockSummary=0x1
07-16 16:46:31.711  1890  2596 D PowerManagerService: Acquiring 

suspend blocker "PowerManagerService.WakeLocks".
07-16 16:46:31.714  2772  3519 I SYNC-PUSH: {p.a--1} enqueue a 

connect task:b{hostInfo:

{"connectCount":8,"connectFailedCount":0,"connectedSuccessCount":

8,"disconnectedCount":7,"dns":false,"hostname":"gw.im.okii.com","

lastConnectFailedCount":0,"port":80,"start":1500194721364,"ttl":0

,"update":1500194791618},isAlarm:true}
07-16 16:46:31.717  2772  3519 I SYNC-PUSH: 

{ConnectionService.a--1} connect status:false
07-16 16:46:31.718  2772  2950 I SYNC-PUSH: {b.a--1} acquire a 

connect task wake lock,tag:ConnectTask@WakeLock-23
07-16 16:46:31.718  2772  2950 D SYNC-PUSH: {p.a--1} to close the 

previous socket before create a new socket...
07-16 16:46:31.719  2772  2950 D SYNC-PUSH: {p.c--1} connection 

has release.
07-16 16:46:31.724  2772  3519 E SYNC-PUSH: {ConnectionService

$6.onRead--1} 
07-16 16:46:31.724  2772  3519 E SYNC-PUSH: com.xtc.sync.b.b: 

decode data error:java.lang.ArrayIndexOutOfBoundsException: 

src.length=45 srcPos=2 dst.length=121 dstPos=0 length=121
07-16 16:46:31.724  2772  3519 E SYNC-PUSH:     at 

com.xtc.sync.push.common.f.a(Unknown Source)
07-16 16:46:31.724  2772  3519 E SYNC-PUSH:     at 

com.xtc.sync.push.common.ConnectionService$6.onRead(Unknown 

Source)
07-16 16:46:31.724  2772  3519 E SYNC-PUSH:     at 

com.xtc.sync.push.common.m.b(Unknown Source)
07-16 16:46:31.724  2772  3519 E SYNC-PUSH:     at 

com.xtc.sync.push.common.m.a(Unknown Source)
07-16 16:46:31.724  2772  3519 E SYNC-PUSH:     at 

com.xtc.sync.push.common.m.run(Unknown Source)
07-16 16:46:31.728  2772  3519 I SYNC-PUSH: {m.a--1} cut data

[100] bytes,rest buffer bytes:19
07-16 16:46:31.730  2772  3519 I SYNC-PUSH: {m.a--1} 

hex:3C626F6479206267636F6C6F723D227768697465223E0D0A3C63656E74657

23E3C68313E3430302042616420526571756573743C2F68313E3C2F63656E7465

723E0D0A3C68723E3C63656E7465723E6E67696E782F312E382E303C2F63656E7

465723E0D
07-16 16:46:31.731  2772  3519 I SYNC-PUSH: {m.a--1} binary:[60, 

98, 111, 100, 121, 32, 98, 103, 99, 111, 108, 111, 114, 61, 34, 

119, 104, 105, 116, 101, 34, 62, 13, 10, 60, 99, 101, 110, 116, 

101, 114, 62, 60, 104, 49, 62, 52, 48, 48, 32, 66, 97, 100, 32, 

82, 101, 113, 117, 101, 115, 116, 60, 47, 104, 49, 62, 60, 47, 

99, 101, 110, 116, 101, 114, 62, 13, 10, 60, 104, 114, 62, 60, 

99, 101, 110, 116, 101, 114, 62, 110, 103, 105, 110, 120, 47, 49, 

46, 56, 46, 48, 60, 47, 99, 101, 110, 116, 101, 114, 62, 13]
07-16 16:46:31.732  2772  3519 I SYNC-PUSH: {ConnectionService

$6.onRead--1} read [100] bytes
07-16 16:46:31.736  2772  3519 E SYNC-PUSH: {f.a--1} 
07-16 16:46:31.736  2772  3519 E SYNC-PUSH: 

java.lang.ArrayIndexOutOfBoundsException: src.length=98 srcPos=2 

dst.length=100 dstPos=0 length=100
07-16 16:46:31.736  2772  3519 E SYNC-PUSH:     at 

java.lang.System.arraycopy(Native Method)
07-16 16:46:31.736  2772  3519 E SYNC-PUSH:     at 

com.xtc.sync.c.d.a(Unknown Source)
07-16 16:46:31.736  2772  3519 E SYNC-PUSH:     at 

com.xtc.sync.c.d.a(Unknown Source)
07-16 16:46:31.736  2772  3519 E SYNC-PUSH:     at 

com.xtc.sync.c.d.a(Unknown Source)
07-16 16:46:31.736  2772  3519 E SYNC-PUSH:     at 

com.xtc.sync.c.d.a(Unknown Source)
07-16 16:46:31.736  2772  3519 E SYNC-PUSH:     at 

com.xtc.sync.util.TLVObjectUtil.parseEntity(Unknown Source)
07-16 16:46:31.736  2772  3519 E SYNC-PUSH:     at 

com.xtc.sync.push.common.f.a(Unknown Source)
07-16 16:46:31.736  2772  3519 E SYNC-PUSH:     at 

com.xtc.sync.push.common.ConnectionService$6.onRead(Unknown 

Source)
07-16 16:46:31.736  2772  3519 E SYNC-PUSH:     at 

com.xtc.sync.push.common.m.b(Unknown Source)
07-16 16:46:31.736  2772  3519 E SYNC-PUSH:     at 

com.xtc.sync.push.common.m.a(Unknown Source)
07-16 16:46:31.736  2772  3519 E SYNC-PUSH:     at 

com.xtc.sync.push.common.m.run(Unknown Source)
07-16 16:46:31.737  2772  3519 E SYNC-PUSH: {f.a--1} error 

data,length:100,content 

hex:3C626F6479206267636F6C6F723D227768697465223E0D0A3C63656E74657

23E3C68313E3430302042616420526571756573743C2F68313E3C2F63656E7465

723E0D0A3C68723E3C63656E7465723E6E67696E782F312E382E303C2F63656E7

465723E0D
07-16 16:46:31.738  2772  3519 E SYNC-PUSH: {f.a--1} error 

data,length:100,content binary:[60, 98, 111, 100, 121, 32, 98, 

103, 99, 111, 108, 111, 114, 61, 34, 119, 104, 105, 116, 101, 34, 

62, 13, 10, 60, 99, 101, 110, 116, 101, 114, 62, 60, 104, 49, 62, 

52, 48, 48, 32, 66, 97, 100, 32, 82, 101, 113, 117, 101, 115, 

116, 60, 47, 104, 49, 62, 60, 47, 99, 101, 110, 116, 101, 114, 

62, 13, 10, 60, 104, 114, 62, 60, 99, 101, 110, 116, 101, 114, 

62, 110, 103, 105, 110, 120, 47, 49, 46, 56, 46, 48, 60, 47, 99, 

101, 110, 116, 101, 114, 62, 13]
07-16 16:46:31.739  2772  3519 E SYNC-PUSH: {f.a--1} error data 

test format:<body bgcolor="white">
07-16 16:46:31.739  2772  3519 E SYNC-PUSH: <center><h1>400 Bad 

Request</h1></center>
07-16 16:46:31.739  2772  3519 E SYNC-PUSH: 

<hr><center>nginx/1.8.0</center>
07-16 16:46:31.739  2772  3519 W SYNC-PUSH: {p.a--1} cancel 

connect
07-16 16:46:31.742  2772  3519 W SYNC-PUSH: {p.a--1} cancel 

alarm.
07-16 16:46:31.743  2772  3519 D SYNC-PUSH: {r.a--1} cancel task 

executor
07-16 16:46:31.745  2772  3519 D SYNC-PUSH: {r.a--1} execute a 

task,size:1
07-16 16:46:31.748  2772  3519 I SYNC-PUSH: {p.a--1} enqueue a 

connect task:b{hostInfo:

{"connectCount":8,"connectFailedCount":0,"connectedSuccessCount":

8,"disconnectedCount":7,"dns":false,"hostname":"gw.im.okii.com","

lastConnectFailedCount":0,"port":80,"start":1500194721364,"ttl":0

,"update":1500194791618},isAlarm:true}
07-16 16:46:31.749  2772  3519 I SYNC-PUSH: 

{ConnectionService.a--1} connect status:false
07-16 16:46:31.750  2772  3519 E SYNC-PUSH: {ConnectionService

$6.onRead--1} 
07-16 16:46:31.750  2772  3519 E SYNC-PUSH: com.xtc.sync.b.b: 

decode data error:java.lang.ArrayIndexOutOfBoundsException: 

src.length=98 srcPos=2 dst.length=100 dstPos=0 length=100
07-16 16:46:31.750  2772  3519 E SYNC-PUSH:     at 

com.xtc.sync.push.common.f.a(Unknown Source)
07-16 16:46:31.750  2772  3519 E SYNC-PUSH:     at 

com.xtc.sync.push.common.ConnectionService$6.onRead(Unknown 

Source)
07-16 16:46:31.750  2772  3519 E SYNC-PUSH:     at 

com.xtc.sync.push.common.m.b(Unknown Source)
07-16 16:46:31.750  2772  3519 E SYNC-PUSH:     at 

com.xtc.sync.push.common.m.a(Unknown Source)
07-16 16:46:31.750  2772  3519 E SYNC-PUSH:     at 

com.xtc.sync.push.common.m.run(Unknown Source)
07-16 16:46:31.755  2772  3519 E SYNC-PUSH: {m.run--1} 
07-16 16:46:31.755  2772  3519 E SYNC-PUSH: 

java.net.SocketException: Socket closed
07-16 16:46:31.755  2772  3519 E SYNC-PUSH:     at 

java.net.SocketInputStream.socketRead0(Native Method)
07-16 16:46:31.755  2772  3519 E SYNC-PUSH:     at 

java.net.SocketInputStream.read(SocketInputStream.java:151)
07-16 16:46:31.755  2772  3519 E SYNC-PUSH:     at 

java.net.SocketInputStream.read(SocketInputStream.java:120)
07-16 16:46:31.755  2772  3519 E SYNC-PUSH:     at 

java.net.SocketInputStream.read(SocketInputStream.java:106)
07-16 16:46:31.755  2772  3519 E SYNC-PUSH:     at 

com.xtc.sync.push.common.m.run(Unknown Source)
07-16 16:46:31.755  2772  3519 I SYNC-PUSH: {m.run--1} buffer 

size == 19,continue to read buffer...
07-16 16:46:31.756  2772  3519 W SYNC-PUSH: {m.run--1} 

onInterrupt:false
07-16 16:46:31.757  2772  3519 D SYNC-PUSH: {p$1.onInterrupt--1} 

reconnect:false
07-16 16:46:31.757  2772  3519 W SYNC-PUSH: {p.s--1} connection 

is disconnected,connected time is:1500194791579,disconnected time 

is:1500194791757,connected time of duration 

is:178,minConnectPeriod format:00:00:01
07-16 16:46:31.758  2772  3519 W SYNC-PUSH: {ConnectionService

$5.onDisconnected--1} connection is disconnected
07-16 16:46:31.759  2772  3519 D SYNC-PUSH: {ConnectionService

$5.onDisconnected--1} on thread:Socket-Thread
07-16 16:46:31.759  2772  3519 D SYNC-PUSH: {r.e--1} stop task 

executor
07-16 16:46:31.761  2772  3519 D SYNC-PUSH: {PhoneStore.put--1} 

commit:false
07-16 16:46:31.762  2772  3519 I SYNC-PUSH: 

{StoreUtil.saveRegistInfo--1} save registInfo 

finished,regist_info:

{"login":false,"registId":25776307,"registToken":"bd642bf2aef4433

0a9102284b9e5fd8b"}
07-16 16:46:31.769  2772  3519 I SYNC-PUSH: 

{SDCardUtil.saveSyncRegistInfo--1} save syncRegistInfo to sdcard 

successful,syncRegistInfo:SyncRegistInfo{registId=25776307, 

registToken='bd642bf2aef44330a9102284b9e5fd8b', login=false}
07-16 16:46:31.777  2772  3519 I SYNC-PUSH: 

{NetUtil.getSIMType--1} getSIMType:45400,simOperatorName:csl.
07-16 16:46:31.778  2772  3519 I SYNC-PUSH: 

{NetUtil.getSIMType--1} getSIMType:csl.
07-16 16:46:31.780  2772  3519 I SYNC-PUSH: 

{NetUtil.getNetworkTag--1} Network tag:csl.-4G
07-16 16:46:31.781  2772  3519 W SYNC-PUSH: {ConnectionService

$5.onDisconnected--1} connected duration is 178 which is too 

short,so do not adjust heartbeat on connection disconnected
07-16 16:46:31.788  2772  3519 I SYNC-PUSH: 

{NetUtil.getSIMType--1} getSIMType:45400,simOperatorName:csl.
07-16 16:46:31.789  2772  3519 I SYNC-PUSH: 

{NetUtil.getSIMType--1} getSIMType:csl.
07-16 16:46:31.793  2772  3519 I SYNC-PUSH: 

{NetUtil.getNetworkTag--1} Network tag:csl.-4G
07-16 16:46:31.796  2772  3519 D SYNC-PUSH: {f.h--1} cancel 

heartbeat,requestCode:37457
07-16 16:46:31.796  2772  3519 D SYNC-PUSH: {f.b--1} stop 

heartbeat...

具体log分析流程

connect to server success,hostname:gw.im.okii.com,port:80代表

TCP连接IM服务器gw.im.okii.com成功，连接端口为80

read [323] bytes,all buffer bytes:323表示客户端杜渠道服务端写

入的TCP数据为323个字节

cut data[86] bytes,rest buffer bytes:237表示客户端开始对读取到

的数据进行解析

java.lang.ArrayIndexOutOfBoundsException: src.length=45

srcPos=2 dst.length=121 dstPos=0 length=121表示数据解析报错，数组

越界

对与解析错误的数据做打印输出，然后关闭TCP连接进行重连：

07-16 16:46:31.702  2772  3519 E SYNC-PUSH: {f.a--1} error data 

test format:ntent-Type: text/html
07-16 16:46:31.702  2772  3519 E SYNC-PUSH: Content-Length: 172
07-16 16:46:31.702  2772  3519 E SYNC-PUSH: Connection: close
07-16 16:46:31.702  2772  3519 E SYNC-PUSH: 
07-16 16:46:31.702  2772  3519 E SYNC-PUSH: <html>
07-16 16:46:31.702  2772  3519 E SYNC-PUSH: <head><title>400 Bad 

Request</title></head>
07-16 16:46:31.703  2772  3519 D SYNC-PUSH: {p.c--1} connection 

has release.
07-16 16:46:31.704  2772  3519 W SYNC-PUSH: {p.a--1} cancel 

connect
07-16 16:46:31.707  2772  3519 W SYNC-PUSH: {p.a--1} cancel 

alarm.
07-16 16:46:31.708  2772  3519 D SYNC-PUSH: {r.a--1} cancel task 

executor

解决方案

服务器把Http和TCP服务做区分，避免对使用80端口连接进来的IM服务错

误的识别成Http短连接

客户端优化心跳下调策略，在遇到数据解析错误导致的TCP断开的时候，

不下调心跳间隔，避免心跳误下调，影响心跳探测的准确性

客户端优化重连策略，在遇到数据解析错误导致的断开重连的时候要做

时间间隔递增重连，避免频繁的重连

客户端新程序不再允许使用80端口去连接IM服务器，不单单是80端口，

一些常用的端口，例如8080，443，1000一下的端口等都不能使用，避免出

现类似的问题

客户端在每一次重连之前首先切换下域名或者端口，避免用同一个域名

和端口去再次连接IM服务器导致无法跳出这个域名和端口连接造成的异常

，如果客户端有成功切换域名或者端口，那么遇到上述情况会立即切换到

8000端口，次数连接就会恢复正常

解决效果

服务器在对Http和TCP服务做了区分之后，从大数据分析来看，香港几台

有上传大数据的手表分析来看全部都恢复正常使用

等待客户端的新版IM程序测试更新

青海心跳异常

现象

青海心跳周期异常的现象和香港的现象一模一样

原因

客户端使用80端口连接gw.im.okii.com域名的时候被运营商劫持到了

111.44.228.186这个地址（正确的应该是106.75.86.52），而被误识别成

Http短链接，然后返回一个错误的网页html数据，然后客户端接收到数据

后解析报错，导致频繁的断线重连和心跳下调

客户端的心跳下调策略和重连策略存在缺陷，遇到这种情况后会导致心

跳误下调，重连频繁，与香港的原因类似

{TCPConnection.a--1} local 

dns,hostname:gw.im.okii.com,ip:111.44.228.186

gw.im.okii.com本地dns解析出来的ip为111.44.228.186，由此确认是被劫

持了

07-27 16:35:52.384  2740  8726 E SYNC-PUSH: {DataCoder.a--1} 
07-27 16:35:52.384  2740  8726 E SYNC-PUSH: 

java.lang.ArrayIndexOutOfBoundsException: src.length=13 srcPos=2 

dst.length=67 dstPos=0 length=67
07-27 16:35:52.384  2740  8726 E SYNC-PUSH:     at 

java.lang.System.arraycopy(Native Method)
07-27 16:35:52.384  2740  8726 E SYNC-PUSH:     at 

com.xtc.sync.tlv.TLVDecoder.a(Unknown Source)
07-27 16:35:52.384  2740  8726 E SYNC-PUSH:     at 

com.xtc.sync.tlv.TLVDecoder.a(Unknown Source)
07-27 16:35:52.384  2740  8726 E SYNC-PUSH:     at 

com.xtc.sync.tlv.TLVDecoder.a(Unknown Source)
07-27 16:35:52.384  2740  8726 E SYNC-PUSH:     at 

com.xtc.sync.tlv.TLVDecoder.a(Unknown Source)
07-27 16:35:52.384  2740  8726 E SYNC-PUSH:     at 

com.xtc.sync.util.TLVObjectUtil.parseEntity(Unknown Source)
07-27 16:35:52.384  2740  8726 E SYNC-PUSH:     at 

com.xtc.sync.push.common.DataCoder.a(Unknown Source)
07-27 16:35:52.384  2740  8726 E SYNC-PUSH:     at 

com.xtc.sync.push.common.ConnectionService$6.onRead(Unknown 

Source)
07-27 16:35:52.384  2740  8726 E SYNC-PUSH:     at 

com.xtc.sync.push.common.ReadAndWriteDataThread.b(Unknown Source)
07-27 16:35:52.384  2740  8726 E SYNC-PUSH:     at 

com.xtc.sync.push.common.ReadAndWriteDataThread.a(Unknown Source)
07-27 16:35:52.384  2740  8726 E SYNC-PUSH:     at 

com.xtc.sync.push.common.ReadAndWriteDataThread.run(Unknown 

Source)

07-27 16:35:52.405  2740  8726 E SYNC-PUSH: 

com.xtc.sync.exception.DecodeException: decode data 

error:java.lang.ArrayIndexOutOfBoundsException: src.length=13 

srcPos=2 dst.length=67 dstPos=0 length=67
07-27 16:35:52.405  2740  8726 E SYNC-PUSH:     at 

com.xtc.sync.push.common.DataCoder.a(Unknown Source)
07-27 16:35:52.405  2740  8726 E SYNC-PUSH:     at 

com.xtc.sync.push.common.ConnectionService$6.onRead(Unknown 

Source)
07-27 16:35:52.405  2740  8726 E SYNC-PUSH:     at 

com.xtc.sync.push.common.ReadAndWriteDataThread.b(Unknown Source)
07-27 16:35:52.405  2740  8726 E SYNC-PUSH:     at 

com.xtc.sync.push.common.ReadAndWriteDataThread.a(Unknown Source)
07-27 16:35:52.405  2740  8726 E SYNC-PUSH:     at 

com.xtc.sync.push.common.ReadAndWriteDataThread.run(Unknown 

Source)

客户端对接收到的TCP数据解析异常ArrayIndexOutOfBoundsException，数

组越界

07-27 16:35:54.479  2740  8737 E SYNC-PUSH: 

java.net.SocketException: Socket closed
07-27 16:35:54.479  2740  8737 E SYNC-PUSH:     at 

java.net.SocketInputStream.socketRead0(Native Method)
07-27 16:35:54.479  2740  8737 E SYNC-PUSH:     at 

java.net.SocketInputStream.read(SocketInputStream.java:151)
07-27 16:35:54.479  2740  8737 E SYNC-PUSH:     at 

java.net.SocketInputStream.read(SocketInputStream.java:120)
07-27 16:35:54.479  2740  8737 E SYNC-PUSH:     at 

java.net.SocketInputStream.read(SocketInputStream.java:106)
07-27 16:35:54.479  2740  8737 E SYNC-PUSH:     at 

com.xtc.sync.push.common.ReadAndWriteDataThread.run(Unknown 

Source)
07-27 16:35:54.480  2740  8737 I SYNC-PUSH: 

{ReadAndWriteDataThread.run--1} buffer size == 11,continue to 

read buffer...
07-27 16:35:54.480  2740  2753 D SYNC-PUSH: {ConnectionService

$ConnectionServiceBinder.a--1} enqueueSendTask:Binder:2740_2
07-27 16:35:54.480  2740  8737 W SYNC-PUSH: 

{ReadAndWriteDataThread.run--1} onInterrupt:false
07-27 16:35:54.481  2740  8737 D SYNC-PUSH: {TCPConnection

$1.onInterrupt--1} reconnect:false
07-27 16:35:54.481  2740  2753 D SYNC-PUSH: {TaskExecutor.a--1} 

execute a task,size:1
07-27 16:35:54.482  2740  8737 W SYNC-PUSH: {TCPConnection.u--1} 

connection is disconnected,connected time 

is:1501144554215,disconnected time is:1501144554481,connected 

time of duration is:266,minConnectPeriod format:00:00:01
07-27 16:35:54.482  2740  8737 W SYNC-PUSH: {ConnectionService

$5.onDisconnected--1} connection is disconnected
07-27 16:35:54.483  2740  8737 D SYNC-PUSH: {ConnectionService

$5.onDisconnected--1} on thread:Socket-Thread

客户端在数据解析异常后断线

07-27 16:35:52.623  2740  8726 I SYNC-PUSH: 

{WatchHearbeatScheduler.c--1} 失败心跳向下探测达到极

值,heartbeatDetail:{"a":"CMCC-

4G","b":false,"c":240,"d":80,"e":0,"f":0,"g":240,"h":240,"i":1501

144552593,"j":[]}
07-27 16:35:52.625  2542  2739 D SYNC-PUSH: 

{ResponseDispatcher.a--1} timeout request,trigger a heartbeat 

request to test the connection...
07-27 16:35:52.627  2740  8726 I SYNC-PUSH: 

{WatchHearbeatScheduler.c--1} 失败心跳调整结果,heartbeatDetail:

{"a":"CMCC-

4G","b":false,"c":240,"d":80,"e":0,"f":0,"g":240,"h":240,"i":1501

144552593,"j":[]}
07-27 16:35:52.627  2542  2739 W SYNC-PUSH: 

{TimeoutErrorHandler.a--1} timeout 

request:PublicKeyRequestEntity:{"RID":102914}
07-27 16:35:52.628  2740  8726 I SYNC-PUSH: 

{WatchHearbeatScheduler.d--1} after success is [false] 

adjusted,heartbeat.curHeart:240,networkTag:CMCC-4G

连接断开后心跳下调

07-27 16:35:54.727  2740  2876 I SYNC-PUSH: {TCPConnection.a--1} 

connect时间间隔(ms):85
07-27 16:35:54.728  2740  2876 D SYNC-PUSH: {TaskExecutor.a--1} 

cancel task executor
07-27 16:35:54.729  2740  2876 I SYNC-PUSH: {TCPConnection.t--1} 

lastConnectPeriod:400
07-27 16:35:54.730  2740  2876 W SYNC-PUSH: {TCPConnection.t--1} 

connected and disconnected is too frequently,do not reset 

reconnectPeriodTag:120000
07-27 16:35:54.731  2740  2876 I SYNC-PUSH: {ConnectionService

$5.onConnected--1} connect to server 

success,hostname:gw.im.okii.com,port:80
07-27 16:35:54.732  2740  2876 D SYNC-PUSH: {ConnectionService

$5.onConnected--1} on thread:Task-Thread#1
07-27 16:35:54.733  2740  2876 D SYNC-PUSH: {TaskExecutor.d--1} 

start task executor
07-27 16:35:54.733  2740  5302 D SYNC-PUSH: {SendTask.j--1} 

execute the send task...
07-27 16:35:54.734  2740  5302 D SYNC-PUSH: 

{ConnectionService.c--1} sendOnBefore
07-27 16:35:54.735  2740  5302 I SYNC-PUSH: {ConnectionService

$6.onWrite--1} write [8] bytes.
07-27 16:35:54.735  2740  2876 I SYNC-PUSH: 

{AppUtil.isAppActive--1} com.xtc.i3launcher app is active
07-27 16:35:54.736  2740  2876 W ContextImpl: Calling a method in 

the system process without a qualified user: 

android.app.ContextImpl.startService:1357 

android.content.ContextWrapper.startService:613 

com.xtc.sync.push.common.HandleServiceNotify.a:-1 

com.xtc.sync.push.common.NotifyExecutor.a:-1 

com.xtc.sync.push.common.ConnectionService$5.onConnected:-1 
07-27 16:35:54.737  2740  5302 I SYNC-PUSH: 

{ConnectionService.e--1} remove a timeout request 

entity:PublicKeyRequestEntity:{"RID":102939},size:147
07-27 16:35:54.739  2740  5302 I SYNC-PUSH: 

{ConnectionService.e--1} remove a timeout request 

entity:PublicKeyRequestEntity:{"RID":102940},size:146
07-27 16:35:54.742  2740  2876 I SYNC-PUSH: 

{HandleServiceNotify.a--1} notify on push connected 

PushConnStatusChangedHandleServicesuccessfully,pkgName:com.xtc.i3

launcher
07-27 16:35:54.745  2740  5302 D SYNC-PUSH: 

{ConnectionService.b--1} data sent successfully.
07-27 16:35:54.745  2542  2542 D SYNC-PUSH: 

{BaseHandleService.onCreate--1} 

PushConnStatusChangedHandleService created...
07-27 16:35:54.746  2542  2542 I SYNC-PUSH: 

{BaseHandleService.onStartCommand--1} 

PushConnStatusChangedHandleService startId:1
07-27 16:35:54.747  2740  5302 I SYNC-PUSH: {SendTask.j--1} send 

data success,data:PublicKeyRequestEntity:{"RID":103141}
07-27 16:35:54.749  2740  5308 D SYNC-PUSH: {SendTask.j--1} 

execute the send task...
07-27 16:35:54.750  2740  5308 D SYNC-PUSH: 

{ConnectionService.c--1} sendOnBefore
07-27 16:35:54.750  2542  8743 D SYNC-PUSH: 

{BaseHandleService.onHandleIntent--1} 

PushConnStatusChangedHandleService onHandleIntent...
07-27 16:35:54.751  2542  8743 I SYNC-PUSH: 

{PushConnStatusChangedHandleService.a--1} receive 

action:com.xtc.sync.connected
07-27 16:35:54.751  2740  5308 I SYNC-PUSH: {ConnectionService

$6.onWrite--1} write [8] bytes.
07-27 16:35:54.752  2542  8743 I SYNC-PUSH: 

{PushConnStatusChangedHandleService$1.a--1} handle 

action:com.xtc.sync.connected
07-27 16:35:54.752  2542  8743 D SYNC-PUSH: 

{PushConnStatusChangedHandleService.b--1} handleSyncPushConnected
07-27 16:35:54.753  2542  8743 D SYNC-PUSH: 

{ConnectionServiceManager$7.c--1} execute hasPublicKey on aidl
07-27 16:35:54.754  2740  2753 D SYNC-PUSH: {ConnectionService

$ConnectionServiceBinder.k--1} hasPublicKey:Binder:2740_2
07-27 16:35:54.755  2740  5308 D SYNC-PUSH: 

{ConnectionService.b--1} data sent successfully.
07-27 16:35:54.756  2740  2876 I SYNC-PUSH: 

{NetUtil.getSIMType--1} getSIMType:46007,simOperatorName:CMCC
07-27 16:35:54.757  2740  2876 I SYNC-PUSH: 

{NetUtil.getSIMType--1} getSIMType:CMCC
07-27 16:35:54.757  2740  5308 I SYNC-PUSH: {SendTask.j--1} send 

data success,data:PublicKeyRequestEntity:{"RID":103142}
07-27 16:35:54.759  2740  5291 D SYNC-PUSH: {SendTask.j--1} 

execute the send task...
07-27 16:35:54.760  2740  5291 D SYNC-PUSH: 

{ConnectionService.c--1} sendOnBefore
07-27 16:35:54.760  2542  8743 D SYNC-PUSH: 

{RequestEntityFactory.createPublicKeyRequestEntity--1} create 

PublicKeyRequestEntity:PublicKeyRequestEntity:{"RID":103145}
07-27 16:35:54.761  2740  5291 I SYNC-PUSH: {ConnectionService

$6.onWrite--1} write [8] bytes.
07-27 16:35:54.761  2542  8743 D SYNC-PUSH: {RequestManager.a--1} 

add a request,RID:103145
07-27 16:35:54.763  2740  2876 I SYNC-PUSH: 

{NetUtil.getNetworkTag--1} Network tag:CMCC-4G
07-27 16:35:54.763  2740  5291 I SYNC-PUSH: 

{ConnectionService.e--1} remove a timeout request 

entity:PublicKeyRequestEntity:{"RID":102941},size:147
07-27 16:35:54.765  2542  8743 W SYNC-PUSH: {RequestSweeper.a--1} 

request sweeper is started.
07-27 16:35:54.766  1853  1863 V AlarmManager: set(PendingIntent

{ba4a156: PendingIntentRecord{6975513 com.xtc.i3launcher 

broadcastIntent}}) : type=0 triggerAtTime=1501144794765 win=0 

tElapsed=2996778 maxElapsed=2996778 interval=0 flags=0x9
07-27 16:35:54.767  2740  2876 I SYNC-PUSH: 

{WatchHearbeatScheduler.g--1} start heartbeat,curHeart 

[240],heart [240000],requestCode:83523235,stabled:false
07-27 16:35:54.770  2740  5291 D SYNC-PUSH: 

{ConnectionService.b--1} data sent successfully.
07-27 16:35:54.772  2740  5291 I SYNC-PUSH: {SendTask.j--1} send 

data success,data:PublicKeyRequestEntity:{"RID":103143}
07-27 16:35:54.773  2542  8743 D SYNC-PUSH: 

{ConnectionServiceManager$9.b--1} execute enqueueSendTask on aidl
07-27 16:35:54.774  2740  5293 D SYNC-PUSH: {SendTask.j--1} 

execute the send task...
07-27 16:35:54.775  2740  5293 D SYNC-PUSH: 

{ConnectionService.c--1} sendOnBefore
07-27 16:35:54.775  2542  8743 I SYNC-PUSH: 

{ConnectionServiceManager$9.b--1} enqueue request 

entity:PublicKeyRequestEntity:{"RID":103145}
07-27 16:35:54.776  2740  5293 I SYNC-PUSH: {ConnectionService

$6.onWrite--1} write [8] bytes.
07-27 16:35:54.777  2740  2752 D SYNC-PUSH: {ConnectionService

$ConnectionServiceBinder.a--1} enqueueSendTask:Binder:2740_1
07-27 16:35:54.778  2740  2876 I SYNC-PUSH: 

{NetUtil.getSIMType--1} getSIMType:46007,simOperatorName:CMCC
07-27 16:35:54.779  2740  5293 D SYNC-PUSH: 

{ConnectionService.b--1} data sent successfully.
07-27 16:35:54.780  2740  2752 D SYNC-PUSH: {TaskExecutor.a--1} 

execute a task,size:1
07-27 16:35:54.781  2740  2876 I SYNC-PUSH: 

{NetUtil.getSIMType--1} getSIMType:CMCC
07-27 16:35:54.782  2740  5293 I SYNC-PUSH: {SendTask.j--1} send 

data success,data:PublicKeyRequestEntity:{"RID":103144}
07-27 16:35:54.783  2542  8743 D SYNC-PUSH: {AIDLHelper.d--1} run 

aidl task...
07-27 16:35:54.784  2740  5313 D SYNC-PUSH: {SendTask.j--1} 

execute the send task...
07-27 16:35:54.784  2740  5313 D SYNC-PUSH: 

{ConnectionService.c--1} sendOnBefore
07-27 16:35:54.786  2740  5313 I SYNC-PUSH: {ConnectionService

$6.onWrite--1} write [8] bytes.
07-27 16:35:54.787  2740  2876 I SYNC-PUSH: 

{NetUtil.getNetworkTag--1} Network tag:CMCC-4G
07-27 16:35:54.788  2542  2542 D SYNC-PUSH: 

{BaseHandleService.onDestroy--1} 

PushConnStatusChangedHandleService destroy...
07-27 16:35:54.793  2740  2876 I SYNC-PUSH: 

{WatchHearbeatScheduler.a--1} start heartbeat,networkTag:CMCC-4G
07-27 16:35:54.799  2740  5313 D SYNC-PUSH: 

{ConnectionService.b--1} data sent successfully.
07-27 16:35:54.800  2740  5313 I SYNC-PUSH: {SendTask.j--1} send 

data success,data:PublicKeyRequestEntity:{"RID":103145}
07-27 16:35:54.816  2740  2876 I SYNC-PUSH: {ConnectionService

$5.onConnected--1} 预埋IP信息:

[{"connectCount":19,"connectFailedCount":19,"connectedSuccessCoun

t":0,"disconnectedCount":0,"dns":false,"hostname":"gw.im.okii.com

","lastConnectFailedCount":19,"port":8000,"start":1501141844507,"

ttl":0,"update":1501144081255}, 

{"connectCount":682,"connectFailedCount":1,"connectedSuccessCount

":680,"disconnectedCount":680,"dns":false,"hostname":"gw.im.okii.

com","lastConnectFailedCount":0,"port":80,"start":1501141844632,"

ttl":0,"update":1501144554639}, 

{"connectCount":0,"connectFailedCount":0,"connectedSuccessCount":

0,"disconnectedCount":0,"dns":false,"hostname":"120.25.129.142","

lastConnectFailedCount":0,"port":1883,"start":1501141844602,"ttl"

:0,"update":0}, 

{"connectCount":0,"connectFailedCount":0,"connectedSuccessCount":

0,"disconnectedCount":0,"dns":false,"hostname":"120.25.129.142","

lastConnectFailedCount":0,"port":8000,"start":1501141844614,"ttl"

:0,"update":0}]
07-27 16:35:54.822  2740  2876 I SYNC-PUSH: 

{NetUtil.getSIMType--1} getSIMType:46007,simOperatorName:CMCC
07-27 16:35:54.823  2740  2876 I SYNC-PUSH: 

{NetUtil.getSIMType--1} getSIMType:CMCC
07-27 16:35:54.826  2740  2876 I SYNC-PUSH: 

{NetUtil.getNetworkTag--1} Network tag:CMCC-4G
07-27 16:35:54.827  2740  2876 D SYNC-PUSH: {DataCollector.a--1} 

record push socket info
07-27 16:35:54.828  2740  2876 I SYNC-PUSH: {TCPConnection.a--1} 

connect to server success 

{remoteAddress=gw.im.okii.com,remotePort=80}

客户端在不切换域名和端口的情况下断线重连成功

解决方案

客户端禁止使用80端口
针对以上香港问题分析出的客户端在心跳下调策略，重连策略存在的缺

陷进行修复（主要是在重连的时候要确保域名或者端口的切换，不要拿旧

的域名和端口再次尝试连接）

解决效果

青海域名劫持问题，TCP连接80端口可以成功，但是不确定8000端口是否

能成功，如果8000端口无法连接成功，那么1.0.4Release或以上版本（去

掉80端口）程序在遇到域名被劫持的时候，再次尝试连接不成功，这时候

就会去跑常规的httpdns流程

新修改的IM的Httpdns方案无论是否使用80端口，都可以解决劫持的

问题，目前并没有在1.0.+Release版本的程序更新，是在当前手表主干更

新的，目前还在提测阶段

最后编辑于：2017.12.10 07:05:11

人面猴
序言：七十年代末，一起剥皮案震惊了整个滨河市，随后出现的几起案子，更是在滨河造成了极大的恐慌，老刑警刘岩，带你破解...
沈念sama阅读 212,332评论 6赞 493
死咒
序言：滨河连续发生了三起死亡事件，死亡现场离奇诡异，居然都是意外死亡，警方通过查阅死者的电脑和手机，发现死者居然都...
沈念sama阅读 90,508评论 3赞 385
救了他两次的神仙让他今天三更去死
文/潘晓璐我一进店门，熙熙楼的掌柜王于贵愁眉苦脸地迎上来，“玉大人，你说我怎么就摊上这事。” “怎么了？”我有些...
开封第一讲书人阅读 157,812评论 0赞 348
道士缉凶录：失踪的卖姜人
文/不坏的土叔我叫张陵，是天一观的道长。经常有香客问我，道长，这世上最难降的妖魔是什么？我笑而不...
开封第一讲书人阅读 56,607评论 1赞 284
港岛之恋（遗憾婚礼）
正文为了忘掉前任，我火速办了婚礼，结果婚礼上，老公的妹妹穿的比我还像新娘。我一直安慰自己，他们只是感情好，可当我...
茶点故事阅读 65,728评论 6赞 386
恶毒庶女顶嫁案：这布局不是一般人想出来的
文/花漫我一把揭开白布。她就那样静静地躺着，像睡着了一般。火红的嫁衣衬着肌肤如雪。梳的纹丝不乱的头发上，一...
开封第一讲书人阅读 49,919评论 1赞 290
城市分裂传说
那天，我揣着相机与录音，去河边找鬼。笑死，一个胖子当着我的面吹牛，可吹牛的内容都是我干的。我是一名探鬼主播，决...
沈念sama阅读 39,071评论 3赞 410
双鸳鸯连环套：你想象不到人心有多黑
文/苍兰香墨我猛地睁开眼，长吁一口气：“原来是场噩梦啊……” “哼！你这毒妇竟也来了？” 一声冷哼从身侧响起，我...
开封第一讲书人阅读 37,802评论 0赞 268
万荣杀人案实录
序言：老挝万荣一对情侣失踪，失踪者是张志新（化名）和其女友刘颖，没想到半个月后，有当地人在树林里发现了一具尸体，经...
沈念sama阅读 44,256评论 1赞 303
护林员之死
正文独居荒郊野岭守林人离奇死亡，尸身上长有42处带血的脓包…… 初始之章·张勋以下内容为张勋视角年9月15日...
茶点故事阅读 36,576评论 2赞 327
白月光启示录
正文我和宋清朗相恋三年，在试婚纱的时候发现自己被绿了。大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
茶点故事阅读 38,712评论 1赞 341
活死人
序言：一个原本活蹦乱跳的男人离奇死亡，死状恐怖，灵堂内的尸体忽然破棺而出，到底是诈尸还是另有隐情，我是刑警宁泽，带...
沈念sama阅读 34,389评论 4赞 332
日本核电站爆炸内幕
正文年R本政府宣布，位于F岛的核电站，受9级特大地震影响，放射性物质发生泄漏。R本人自食恶果不足惜，却给世界环境...
茶点故事阅读 40,032评论 3赞 316
男人毒药：我在死后第九天来索命
文/蒙蒙一、第九天我趴在偏房一处隐蔽的房顶上张望。院中可真热闹，春花似锦、人声如沸。这庄子的主人今日做“春日...
开封第一讲书人阅读 30,798评论 0赞 21
一桩弑父案，背后竟有这般阴谋
文/苍兰香墨我抬头看了看天上的太阳。三九已至，却和暖如春，着一层夹袄步出监牢的瞬间，已是汗流浃背。一阵脚步声响...
开封第一讲书人阅读 32,026评论 1赞 266
情欲美人皮
我被黑心中介骗来泰国打工，没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留，地道东北人。一个月前我还...
沈念sama阅读 46,473评论 2赞 360
代替公主和亲
正文我出身青楼，却偏偏与公主长得像，于是被迫代替她去往敌国和亲。传闻我的和亲对象是个残疾皇子，可洞房花烛夜当晚...
茶点故事阅读 43,606评论 2赞 350

IM TCP网络问题分析

心跳异常

香港心跳异常

现象

原因

解决方案

解决效果

青海心跳异常

现象

原因

解决方案

解决效果

推荐阅读更多精彩内容