心跳异常
香港心跳异常
现象
- 手表使用香港卡用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而言
- 遇到数据解析异常导致的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版本的程序更新，是在当前手表主干更
新的，目前还在提测阶段
网友评论