AgoraIO / Signaling

18 stars 28 forks source link

Instant message duplicate & repeating #8

Open PrashantKT opened 5 years ago

PrashantKT commented 5 years ago

I have integrated signalling sdk now the issue is when user login. they are getting old messages. or some time they get messages two times

How to fix this ?

Here is a log When User start application and login

see the message END_CALL

LOG Optional("1558784913304 : usr user_logout") LOG Optional("1558784913305 : usr.cb onError logout 108 logout when logouted, ignore this action") LOG Optional("1558784913305 : usr user_login: [1.4.0.127_7abe670 1010400127] vid=\"5cbe1c\" account=\"800\" token=\"_no_ne\" uid=0 deviceID=\"\" ") LOG Optional("1558784913305 : [ net ] resolve_hostname : \"ulbs.sig.agora.io\" ") LOG Optional("1558784913309 : [ net ] uv_on_getaddrinfo_done2 status: ulbs.sig.agora.io 0") LOG Optional("1558784913309 : dns. dns_result lbs-sig.agora.io:52.221.229.66") LOG Optional("1558784913309 : [ net ] uv_udp_init") LOG Optional("1558784913309 : ulbs bind 0.0.0.0") LOG Optional("1558784913309 : ulbs send req 52.221.229.66 1 : 5cbe1c10637e4e9c820bdff3b62c433c") LOG Optional("1558784913385 : ulbs data recv ok {\"web2\": [], \"web\": [[\"47.90.4.18\", 8001], [\"47.91.136.74\", 8001], [\"47.90.91.211\", 8001], [\"47.90.104.122\", 8001], [\"47.90.89.116\", 8001]], \"http\": [[\"47.90.4.18\", 80], [\"47.90.2.175\", 80], [\"47.90.22.30\", 80], [\"47.90.91.211\", 80], [\"47.90.89.116\", 80]], \"tcp\": [[\"47.90.81.78\", 8182], [\"47.90.104.190\", 8184], [\"47.90.2.175\", 8183], [\"47.90.87.207\", 8181], [\"47.90.105.137\", 8181], [\"47.90.91.211\", 8188], [\"47.91.136.74\", 8183], [\"47.90.4.18\", 8184], [\"47.91.13") LOG Optional("1558784913385 : ulbs result {\"web2\": [], \"web\": [[\"47.90.4.18\", 8001], [\"47.91.136.74\", 8001], [\"47.90.91.211\", 8001], [\"47.90.104.122\", 8001], [\"47.90.89.1") LOG Optional("1558784913385 : tcp.1.0 connecting 47.91.136.74:8183") LOG Optional("1558784913385 : [ net ] connect to 47.91.136.74") LOG Optional("1558784913386 : tcp.1.1 connecting 47.90.81.78:8182") LOG Optional("1558784913386 : [ net ] connect to 47.90.81.78") LOG Optional("1558784913492 : tcp.1.1 connected 47.90.81.78:8182 0") LOG Optional("1558784913492 : tcp.1 send : [0 134] login {\"account\":\"800\",\"device\":\"\",\"ip\":\"\",\"token\":\"_no_need_token\",\"uid\":0,\"ver\":1010400127,\"vid\":\"") LOG Optional("1558784913508 : tcp.1.0 connected 47.91.136.74:8183 0") LOG Optional("1558784913509 : tcp.1.0 close on connected : work end 1 ") LOG Optional("1558784913674 : tcp.1.1 recv : [185, 0] login_res ok 2 {\"result\": \"ok\", \"config_call_timeout\": 60000, \"config_call_retry_time\": 10000, \"line") LOG Optional("1558784913674 : tcp.1 send : [1 22] line_ping:1") LOG Optional("1558784913674 : usr.cb onLoginSuccess 74309001 20") Login success 74309001 LOG Optional("1558784913679 : new rpt udp") LOG Optional("1558784913680 : [ net ] uv_udp_init") LOG Optional("1558784913680 : call_api 0 1 user_getmsg 0") LOG Optional("1558784913680 : tcp_call 1 user_getmsg {\"line\":\"ua_fs2_7:9181579086:2637515991796276617\",\"max\":30,\"ver_clear\":0}") LOG Optional("1558784913680 : tcp.1 send : [1 93] call user_getmsg 1 0 {\"line\":\"ua_fs2_7:9181579086:2637515991796276617\",\"max\":30,\"ver_clear\":0}") LOG Optional("1558784913808 : tcp.1.1 recv : [11, 0] line_pong:1") LOG Optional("1558784913907 : tcp.1.1 recv : [136, 0] call_ret user_getmsg 1 0 {\"ver_clear\": 39, \"result\": \"ok\", \"msgs\": [[40, \"msg-v2 123456 800 v1:E:259") LOG Optional("1558784914215 : call_ret 1 0 {\"msgs\":[[40,\"msg-v2 123456 800 v1:E:2592000 instant 1558784903 END_CALL\"]],\"result\":\"ok\",\"ver_clear ") LOG Optional("1558784914215 : msg.proc 123456 instant END_CALL") LOG Optional("1558784914215 : usr.cb onMessageInstantReceive 123456 0 END_CALL") INSTANT MESSAGE RECV. 0 FROM Optional("123456") message Optional("END_CALL") LOG Optional("1558784914215 : [ net ] resolve_hostname : \"rp.sig.agora.io\" ") LOG Optional("1558784914215 : call_api 0 2 user_getmsg 0") LOG Optional("1558784914215 : tcp_call 2 user_getmsg {\"line\":\"ua_fs2_7:9181579086:2637515991796276617\",\"max\":30,\"ver_clear\":40}") LOG Optional("1558784914215 : tcp.1 send : [1 94] call user_getmsg 2 0 {\"line\":\"ua_fs2_7:9181579086:2637515991796276617\",\"max\":30,\"ver_clear\":40}") LOG Optional("1558784914217 : [ net ] uv_on_getaddrinfo_done2 status: rp.sig.agora.io 0") LOG Optional("1558784914217 : rpt host rp.sig.agora.io 139.196.188.164") LOG Optional("1558784914319 : send rp 0 139.196.188.164") LOG Optional("1558784914343 : tcp.1.1 recv : [70, 0] call_ret user_getmsg 2 0 {\"ver_clear\": 40, \"result\": \"ok\", \"msgs\": []}") LOG Optional("1558784914343 : call_ret 2 0 {\"msgs\":[],\"result\":\"ok\",\"ver_clear\":40} ") LOG Optional("1558784924282 : tcp.1 send : [1 22] line_ping:2") LOG Optional("1558784924405 : tcp.1.1 recv : [11, 0] line_pong:2") LOG Optional("1558784934854 : tcp.1 send : [1 22] line_ping:3") LOG Optional("1558784934975 : tcp.1.1 recv : [11, 0] line_pong:3") LOG Optional("1558784945419 : tcp.1 send : [1 22] line_ping:4") LOG Optional("1558784945550 : tcp.1.1 recv : [11, 0] line_pong:4") LOG Optional("1558784955989 : tcp.1 send : [1 22] line_ping:5") LOG Optional("1558784956116 : tcp.1.1 recv : [11, 0] line_pong:5")

plutoless commented 5 years ago

i didn't see the END_CALL message duplicate though? you see it multiple times only because we log one message for several log lines.

PrashantKT commented 5 years ago

@plutoless My bad. I should add more explanation.

How we implemented calling using singling

1) When Push notification received with caller user ID. We First Login the current user (current user id is stored in preference when user signup) using signalling SDK. 2) OnLoginSuccess response we send instant message that Phone is ringing to caller user ID 3) On caller side when Instant message received that phone is ringing we perform some UI operations. 4) Now both side has end call button . On tap this button we send END_CALL message. and other side we again perform some UI operations to end call.

Sometime,

When user just login he got END_CALL message same as I have added log.

What I want is , is There any method to flush all pending messages ? Because we have added UI Operations on event of instant message received. So

if you want to anything from my side let me know

Thanks in advance for your help

plutoless commented 5 years ago

@PrashantKT thanks for the response. The reason you are receiving those is because we support p2p offline messages, i.e. if you sent a msg before while that person somehow never received it, he will receive the message as soon as he got online. This is the design and there's no way we can change it. My suggestion is to add a timestamp of expire mechanism to ignore that message when it's no longer needed.

PrashantKT commented 5 years ago

@plutoless Thanks for response. But we send the message when user is online and he already got this message once. so after that user again start app and login he sees message again that's the issue it is not often it occurs sometimes only. and could you guide how timestamp mechanism works ? and how can we implement it

plutoless commented 5 years ago

@PrashantKT just wrap your message as a JSON serializable string so that you can do what ever to create a json object structure. The ts and msg content can become properties of that json to be delivered to remote device. Could you pls do this first? Just attach the timestamp at the timepoint when you sent the message, check out the receiver side, if it indeed received two messages with the same timestamp, give me the log and i'll check with beckend devs.

PrashantKT commented 5 years ago

@plutoless In android I have collected some logs as you suggest. created a JSON with following format

{"MSG":"INCOMING_CALL_SHOWED","date":"Tue May 28 11:32:33 GMT+05:30 2019"}

Hope it helps

callLOg.txt recievelog.txt

plutoless commented 5 years ago

hi @PrashantKT i assume the callLog is sender's log, while receivelog is receiver's log? But those two logs has no time intersection. Is this the same device's log? Which message has issues? Also could you pls turn the date into milliseconds so it's easier for us to distinguish

PrashantKT commented 5 years ago

@plutoless Thanks for your response , I have generated iOS logs now. And you can clearly see duplicate messages there.

now following is the format

[ "MSG" : string,
            "account":account,
            "time_interval_milliseconds": time_interval ]

Please find the attachment both logs are from different devices.

Receiver.txt as name suggests log of receiver device CALL.txt caller device logs

CALL.txt Receiver.txt

PrashantKT commented 5 years ago

@plutoless I have one another question, What I assume is to send instant message user must be logged in. So I perform login operation and on login success call back I perform other tasks. So is it correct ? I assume that login should be called once.

I am asking because my onLoginSuccess Called two times.

----------didReceiveIncomingPushWith--------- 1559046148881 : ulbs data recv ok {"web2": [], "web": [["47.90.87.207", 8001], ["47.90.89.116", 8001], ["47.90.105.82", 8001], ["47.90.2.175", 8001], ["47.90.104.190", 8001]], "http": [["47.90.91.211", 80], ["47.90.104.190", 80], ["47.90.4.18", 80], ["47.90.81.78", 80], ["47.90.2.175", 80]], "tcp": [["47.90.104.122", 8181], ["47.90.91.211", 8183], ["47.90.105.137", 8182], ["47.90.87.207", 8182], ["47.90.89.116", 8188], ["47.90.2.175", 8182], ["47.90.4.18", 8181], ["47.91.136.74", 8186], ["47.91 1559046148888 : ulbs result {"web2": [], "web": [["47.90.87.207", 8001], ["47.90.89.116", 8001], ["47.90.105.82", 8001], ["47.90.2.175", 8001], ["47.90.104. 1559046148892 : tcp.1.0 connecting 47.90.4.18:8181 1559046148895 : [ net ] connect to 47.90.4.18 1559046148898 : tcp.1.1 connecting 47.90.104.122:8181 1559046148963 : [ net ] connect to 47.90.104.122 1559046149305 : tcp.1.1 connected 47.90.104.122:8181 0 1559046149317 : tcp.1 send : [0 135] login {"account":"3000","device":"","ip":"","token":"_no_need_token","uid":0,"ver":1010400127,"vid": 1559046149352 : tcp.1.0 connected 47.90.4.18:8181 0 1559046149360 : tcp.1.0 close on connected : work end 1 1559046149595 : [ net ] resolve_hostname : "rp.sig.agora.io" 1559046149606 : new rpt udp 1559046149615 : [ net ] uv_udp_init 1559046149620 : [ net ] uv_on_getaddrinfo_done2 status: rp.sig.agora.io 0 1559046149626 : rpt host rp.sig.agora.io 139.196.188.164 1559046149945 : tcp.1.1 recv : [186, 0] login_res ok 2 {"result": "ok", "config_call_timeout": 60000, "config_call_retry_time": 10000, "line 1559046149957 : tcp.1 send : [1 22] line_ping:1 1559046149966 : usr.cb onLoginSuccess 149273050 19 ----------APPDELEGATE - SIGNAL= LOGIN SUCCESS--------- 1559046149982 : usr user_logout 1559046149990 : call_api 0 1 user_logout 0 1559046149999 : tcp_call 1 user_logout {"line":"ua_fs2_8:9217532570:2275581747832142298","ver_clear":0} 1559046150006 : tcp.1 send : [1 87] call user_logout 1 0 {"line":"ua_fs2_8:9217532570:2275581747832142298","ver_clear":0} 1559046150019 : send rp 0 139.196.188.164 1559046150109 : call_api 0 2 user_getmsg 0 1559046150121 : tcp_call 2 user_getmsg {"line":"ua_fs2_8:9217532570:2275581747832142298","max":30,"ver_clear":0} 1559046150130 : tcp.1 send : [1 93] call user_getmsg 2 0 {"line":"ua_fs2_8:9217532570:2275581747832142298","max":30,"ver_clear":0} 1559046150585 : tcp.1.1 recv : [11, 0] line_pong:1 1559046151235 : tcp.1.1 recv : [41, 0] call_ret user_logout 1 0 {"result": "ok"} 1559046151247 : call_ret 1 0 {"result":"ok"} 1559046151254 : call_ret 2 -2 time out null 1559046151263 : call_ret 2 -2 time out null 1559046151270 : usr.cb onLogout 101 1559046151277 : tcp.1.1 recv : [74, 0] call_ret user_getmsg 2 0 {"reason": "can't find user", "result": "failed"} 1559046151284 : res : can't find call 2 1559046151292 : tcp.1.1 closed 1559046151319 : call_api 0 3 user_getmsg 0 1559046151326 : usr user_login: [1.4.0.127_7abe670 1010400127] vid="5cbe1c" account="3000" token="_no_ne" uid=0 deviceID="" 1559046151333 : call_ret 3 -2 time out null 1559046151342 : call_ret 3 -2 time out null 1559046151350 : [ net ] resolve_hostname : "ulbs.sig.agora.io" 1559046151362 : [ net ] uv_on_getaddrinfo_done2 status: ulbs.sig.agora.io 0 1559046151368 : dns. dns_result lbs-sig.agora.io:52.221.229.66 1559046151375 : [ net ] uv_udp_init 1559046151382 : ulbs bind 0.0.0.0 1559046151389 : ulbs send req 52.221.229.66 1 : 5cbe1c10637e4e9c820bdff3b62c433c 1559046151541 : ulbs data recv ok {"web2": [], "web": [["47.91.139.223", 8001], ["47.91.136.74", 8001], ["47.90.81.78", 8001], ["47.90.105.137", 8001], ["47.90.4.18", 8001]], "http": [["47.90.89.116", 80], ["47.90.104.190", 80], ["47.91.139.223", 80], ["47.90.81.78", 80], ["47.90.104.122", 80]], "tcp": [["47.91.139.223", 8185], ["47.90.105.82", 8181], ["47.91.136.74", 8185], ["47.91.139.223", 8186], ["47.90.87.207", 8184], ["47.91.139.223", 8184], ["47.90.91.211", 8185], ["47.90.105.137", 8181] 1559046151551 : ulbs result {"web2": [], "web": [["47.91.139.223", 8001], ["47.91.136.74", 8001], ["47.90.81.78", 8001], ["47.90.105.137", 8001], ["47.90.4. 1559046151560 : tcp.2.0 connecting 47.91.139.223:8185 1559046151567 : [ net ] connect to 47.91.139.223 1559046151576 : tcp.2.1 connecting 47.90.89.116:8188 1559046151583 : [ net ] connect to 47.90.89.116 1559046152177 : tcp.2.0 connected 47.91.139.223:8185 0 1559046152189 : tcp.2 send : [0 135] login {"account":"3000","device":"","ip":"","token":"_no_need_token","uid":0,"ver":1010400127,"vid": 1559046152199 : tcp.2.1 connected 47.90.89.116:8188 0 1559046152208 : tcp.2.1 close on connected : work end 2 1559046152826 : tcp.2.0 recv : [186, 0] login_res ok 2 {"result": "ok", "config_call_timeout": 60000, "config_call_retry_time": 10000, "line 1559046152836 : tcp.2 send : [1 22] line_ping:1 1559046152843 : usr.cb onLoginSuccess 149273050 20 ----------APPDELEGATE - SIGNAL= LOGIN SUCCESS--------- 1559046152858 : usr user_send_instant_msg account="2000" uid=0 msg="{ "MSG" : "INCOMING_CALL_SHOWED", "time_interval_milliseconds" : 1559046149982.571, "account" " msgID="" 1559046152868 : call_api 0 4 user_sendmsg 0 1559046152882 : tcp_call 4 user_sendmsg {"content":"{\n \"MSG\" : \"INCOMING_CALL_SHOWED\",\n \"time_interval_milliseconds\" : 15590461499 1559046152889 : tcp.2 send : [1 210] call user_sendmsg 4 0 {"content":"{\n \"MSG\" : \"INCOMING_CALL_SHOWED\",\n \"time_interval_millis

plutoless commented 5 years ago

@PrashantKT according to your log, apparently you have sent two different messages which seems duplicate, but you can notice the timestamp is in fact different.

The ts is added by you and we will not modify your message, therefore in most cases you have sent the message twice yourself.

1559043577132 : msg.proc 3000 instant { "MSG" : "INCOMING_CALL_SHOWED", "account" : "2000", "time_interval_milliseconds" : 155904357 1559043577133 : usr.cb onMessageInstantReceive 3000 0 { "MSG" : "INCOMING_CALL_SHOWED", "account" : "2000", "time_interval_milliseconds" : 155904357 1559043580994 : tcp.1.0 recv : [196, 0] notify recvmsg [12, "msg-v2 3000 2000 v1:E:2592000 instant 1559043578 {\n \"time_interval_milliseco 1559043580997 : msg.proc 3000 instant { "time_interval_milliseconds" : 1559043578095.021, "MSG" : "INCOMING_CALL_SHOWED", "account" 1559043580998 : usr.cb onMessageInstantReceive 3000 0 { "time_interval_milliseconds" : 1559043578095.021, "MSG" : "INCOMING_CALL_SHOWED", "account"

And in send log, you have definitely sent a message twice.

1559043578093 : usr user_send_instant_msg account="2000" uid=0 msg="{ "MSG" : "INCOMING_CALL_SHOWED", "account" : "2000", "time_interval_milliseconds" : 155904357" msgID="" 1559043578102 : call_api 0 4 user_sendmsg 0 1559043578108 : tcp_call 3 user_getmsg {"line":"","max":30,"ver_clear":0} 1559043578119 : tcp.2 send : [1 66] call user_getmsg 3 0 {"line":"","max":30,"ver_clear":0} 1559043578125 : tcp_call 4 user_sendmsg {"content":"{\n \"MSG\" : \"INCOMING_CALL_SHOWED\",\n \"account\" : \"2000\",\n \"time_interval_m 1559043578131 : tcp.2 send : [1 209] call user_sendmsg 4 0 {"content":"{\n \"MSG\" : \"INCOMING_CALL_SHOWED\",\n \"account\" : \"2000\" 1559043578177 : usr user_send_instant_msg account="2000" uid=0 msg="{ "time_interval_milliseconds" : 1559043578095.021, "MSG" : "INCOMING_CALL_SHOWED", "account" " msgID=""

plutoless commented 5 years ago

@PrashantKT to answer your other question, you will need to login to send a message yes. but if you have already logged in while not yet being logged out, you DO NOT need to login again.

PrashantKT commented 5 years ago

@plutoless Any updates on the issue ?

plutoless commented 5 years ago

@PrashantKT see above for answers.