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
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而言
  1. 遇到数据解析异常导致的TCP连接断开跟网络NAT超时时间无关,因此不

应该下调心跳周期,但是旧版(1.0.1Realease-1.0.6Realease版本)存在

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

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

断线后会马上重连

  1. 客户端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分析流程
  1. connect to server success,hostname:gw.im.okii.com,port:80代表

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

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

入的TCP数据为323个字节

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

的数据进行解析

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

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

越界

  1. 对与解析错误的数据做打印输出,然后关闭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版本的程序更新,是在当前手表主干更

新的,目前还在提测阶段

推荐阅读更多精彩内容

  • 主目录见:Android高级进阶知识(这是总目录索引)[written by 无心追求] 心跳异常 香港心跳异常 ...
    ZJ_Rocky阅读 861评论 0 3
  • Spring Cloud为开发人员提供了快速构建分布式系统中一些常见模式的工具(例如配置管理,服务发现,断路器,智...
    卡卡罗2017阅读 122,057评论 17 134
  • 儿子昨天生病了,前婆婆给我来的电话,说她不懂得带孩子看医生,叫我带孩子去看医生。听到宝宝毫无生气的声音,我一面着急...
    榴莲妄凡阅读 115评论 0 0