search

tinode / chat

Instant messaging platform. Backend in Go. Clients: Swift iOS, Java Android, JS webapp, scriptable command line; chatbots
GNU General Public License v3.0
11.73k stars 1.84k forks source link

hub: missing both subscriptions for 'p2pxEtcnfc1MVZ3RBB_Vu_lgQ' (SHOULD NEVER HAPPEN!) #738

Closed gabriel-vasile closed 2 years ago

gabriel-vasile commented 2 years ago

tinode version: master To reproduce:

expected: user B subs successfully got: tinode | 2022/03/30 08:31:45 hub: missing both subscriptions for 'p2pxEtcnfc1MVZ3RBB_Vu_lgQ' (SHOULD NEVER HAPPEN!) tinode | 2022/03/30 08:31:45 init_topic: failed to load or create topic: p2pxEtcnfc1MVZ3RBB_Vu_lgQ internal

user A logs:

tinode        | 2022/03/30 08:45:54 in: '{"hi":{"id":"88142","ver":"0.18.3","ua":"tinodejs/0.18.3","lang":"en-US","platf":"web"}}' sid='zpVjNxkZhlc' uid=''
tinode        | 2022/03/30 08:44:03 in: '{"login":{"id":"88132","scheme":"sch","secret":"secr<...>' sid='zpVjNxkZhlc' uid=''
tinode        | 2022/03/30 08:44:08 in: '{"sub":{"id":"88133","topic":"me","get":{"what":"sub desc tags cred"}}}' sid='zpVjNxkZhlc' uid='RSpSx6akRu4'
tinode        | 2022/03/30 08:44:11 in: '{"sub":{"id":"88138","topic":"usrmaZcF8p7Z4Y","get":{"data":{"limit":24},"what":"data sub desc"}}}' sid='zpVjNxkZhlc' uid='RSpSx6akRu4'
tinode        | 2022/03/30 08:44:14 in: '{"del":{"id":"88140","topic":"usrmaZcF8p7Z4Y","what":"topic"}}' sid='zpVjNxkZhlc' uid='RSpSx6akRu4'

user B logs:

tinode        | 2022/03/30 08:45:54 in: '{"hi":{"id":"88142","ver":"0.18.3","ua":"tinodejs/0.18.3","lang":"en-US","platf":"web"}}' sid='EF28c-EArwA' uid=''
tinode        | 2022/03/30 08:45:54 in: '{"login":{"id":"88143","scheme":"sch","secret":"secr' sid='EF28c-EArwA' uid=''
tinode        | 2022/03/30 08:45:59 in: '{"sub":{"id":"88144","topic":"me","get":{"what":"sub desc tags cred"}}}' sid='EF28c-EArwA' uid='maZcF8p7Z4Y'
tinode        | 2022/03/30 08:46:02 in: '{"sub":{"id":"88145","topic":"usrRSpSx6akRu4","get":{"data":{"limit":24},"desc":{"ims":"2022-03-30T08:44:11.928Z"},"what":"data sub desc"}}}' sid='EF28c-EArwA' uid='maZcF8p7Z4Y'
tinode        | 2022/03/30 08:46:07 in: '{"del":{"id":"88147","topic":"usrRSpSx6akRu4","what":"topic"}}' sid='EF28c-EArwA' uid='maZcF8p7Z4Y'
tinode        | 2022/03/30 08:46:11 in: '{"sub":{"id":"88153","topic":"usrRSpSx6akRu4","get":{"data":{"limit":24},"desc":{"ims":"2022-03-30T08:42:42.610Z"},"what":"data sub desc"}}}' sid='EF28c-EArwA' uid='maZcF8p7Z4Y'
tinode        | 2022/03/30 08:46:11 hub: missing both subscriptions for 'p2pmaZcF8p7Z4ZFKlLHpqRG7g' (SHOULD NEVER HAPPEN!)
tinode        | 2022/03/30 08:46:11 init_topic: failed to load or create topic: p2pmaZcF8p7Z4ZFKlLHpqRG7g internal

The same problem appears if instead of {del}, {leave} unsub=true packets are used.

or-else commented 2 years ago

This issue should be fixed in https://github.com/tinode/chat/commit/a81440d0c87cbcd0130ee902b91bdd63bae3eacb. Please verify. Thanks.

gabriel-vasile commented 2 years ago

Fixed, thanks.

or-else commented 2 years ago

released in https://github.com/tinode/chat/releases/tag/v0.18.4

gabriel-vasile commented 2 years ago

This issue still happens. Tested with fresh install of master.

This HTML reproduces the problem:

<!DOCTYPE html>
<html lang="en">
<head>
    <script crossorigin="anonymous"
      src="https://cdn.jsdelivr.net/npm/tinode-sdk/umd/tinode.dev.js">
    </script>
    <meta charset="UTF-8">
</head>

<body id="home">
    <h1>HTML5 boilerplate</h1>
<script>
u1 = {
    u: "alice",
    p: "alice123",
}
u2 = {
    u: "bob",
    p: "bob123",
}

t1 = new Tinode({
    host: "localhost:6060",
    apiKey: "AQEAAAABAAD_rAp4DJh05a1HAwFT3A6K",
});
t2 = new Tinode({
    host: "localhost:6060",
    apiKey: "AQEAAAABAAD_rAp4DJh05a1HAwFT3A6K",
});

async function run() {
    await t1.connect()
    await t1.loginBasic(u1.u, u1.p)
    await t2.connect()
    await t2.loginBasic(u2.u, u2.p)
    await t1.subscribe(t2.getCurrentUserID())
    await t2.subscribe(t1.getCurrentUserID())
    await t1.delTopic(t2.getCurrentUserID())
    await t2.delTopic(t1.getCurrentUserID())
    await t1.subscribe(t2.getCurrentUserID())
}
run()
</script>
</body>
</html>

server logs:

I2022/04/18 16:18:24 ws: session started tSGTaHPI-mQ 127.0.0.1:47682 1
I2022/04/18 16:18:24 in: '{"hi":{"id":"99432","ver":"0.18.3","ua":"Undefined (Firefox/95.0; Linux x86_64); tinodejs/0.18.3","lang":"en-US","platf":"web"}}' sid='tSGTaHPI-mQ' uid=''
I2022/04/18 16:18:24 in: '{"login":{"id":"99433","scheme":"basic","secret":"YWxpY2U6YWxpY2UxMjM="}}' sid='tSGTaHPI-mQ' uid=''
I2022/04/18 16:18:24 ws: session started oJaYHBERnAk 127.0.0.1:47684 2
I2022/04/18 16:18:24 in: '{"hi":{"id":"107923","ver":"0.18.3","ua":"Undefined (Firefox/95.0; Linux x86_64); tinodejs/0.18.3","lang":"en-US","platf":"web"}}' sid='oJaYHBERnAk' uid=''
I2022/04/18 16:18:24 in: '{"login":{"id":"107924","scheme":"basic","secret":"Ym9iOmJvYjEyMw=="}}' sid='oJaYHBERnAk' uid=''
I2022/04/18 16:18:24 in: '{"sub":{"id":"99434","topic":"usrrv5fJHNe8N8"}}' sid='tSGTaHPI-mQ' uid='Krt1fadJ0rM'
I2022/04/18 16:18:24 in: '{"sub":{"id":"107925","topic":"usrKrt1fadJ0rM"}}' sid='oJaYHBERnAk' uid='rv5fJHNe8N8'
I2022/04/18 16:18:24 in: '{"del":{"id":"99435","topic":"usrrv5fJHNe8N8","what":"topic"}}' sid='tSGTaHPI-mQ' uid='Krt1fadJ0rM'
I2022/04/18 16:18:24 in: '{"del":{"id":"107926","topic":"usrKrt1fadJ0rM","what":"topic"}}' sid='oJaYHBERnAk' uid='rv5fJHNe8N8'
I2022/04/18 16:18:24 in: '{"sub":{"id":"99436","topic":"usrrv5fJHNe8N8"}}' sid='tSGTaHPI-mQ' uid='Krt1fadJ0rM'
E2022/04/18 16:18:24 hub: missing both subscriptions for 'p2pKrt1fadJ0rOu_l8kc17w3w' (SHOULD NEVER HAPPEN!)
E2022/04/18 16:18:24 init_topic: failed to load or create topic: p2pKrt1fadJ0rOu_l8kc17w3w internal
or-else commented 2 years ago

released in 0.18.4

gabriel-vasile commented 2 years ago

The tinode sdk from https://cdn.jsdelivr.net/npm/tinode-sdk/umd/tinode.dev.js is at 0.18.3. But the backend was 0.18.4 (latest master commit) when I tested. The problem is in backend.

gabriel-vasile commented 2 years ago

I think I know what happened. The fix in https://github.com/tinode/chat/commit/a81440d0c87cbcd0130ee902b91bdd63bae3eacb works for {leave} messages. The problem still happens with {del}.

or-else commented 2 years ago

The problem still happens with {del}.

Fixed in https://github.com/tinode/chat/commit/16be7373ef55ccfebd572082725e38892c0af0d2 Thanks.

or-else commented 2 years ago

Released in https://github.com/tinode/chat/releases/tag/v0.18.5-rc1

gabriel-vasile commented 2 years ago

This issue is still there in v0.18.5 and it happens for {del}. To reproduce:

  1. initialise tinode with sandbox data
  2. in browser, CTRL+O and select del.html

del.html:

<!DOCTYPE html>
<html lang="en">
<head>
    <script crossorigin="anonymous"
      src="https://cdn.jsdelivr.net/npm/tinode-sdk/umd/tinode.dev.js">
    </script>
    <meta charset="UTF-8">
</head>

<body id="home">
    <h1>HTML5 boilerplate</h1>
<script>
u1 = {
    u: "alice",
    p: "alice123",
}
u2 = {
    u: "bob",
    p: "bob123",
}

t1 = new Tinode({
    host: "localhost:6060",
    apiKey: "AQEAAAABAAD_rAp4DJh05a1HAwFT3A6K",
});
t2 = new Tinode({
    host: "localhost:6060",
    apiKey: "AQEAAAABAAD_rAp4DJh05a1HAwFT3A6K",
});

async function run() {
    await t1.connect()
    await t1.loginBasic(u1.u, u1.p)
    await t2.connect()
    await t2.loginBasic(u2.u, u2.p)
    await t1.subscribe(t2.getCurrentUserID())
    await t2.subscribe(t1.getCurrentUserID())
    await t1.delTopic(t2.getCurrentUserID())
    await t2.delTopic(t1.getCurrentUserID())
    await t1.subscribe(t2.getCurrentUserID())
}
run()
</script>
</body>
</html>
or-else commented 2 years ago

Fixed in devel:

I2022/05/11 12:21:14 ws: session started OH2O8qVYp2M [::1]:59541 1
I2022/05/11 12:21:14 in: '{"hi":{"id":"119993","ver":"0.18.3","ua":"Undefined (Chrome/100.0; MacIntel); tinodejs/0.18.3","lang":"en-US","platf":"web"}}' sid='OH2O8qVYp2M' uid=''
I2022/05/11 12:21:14 in: '{"login":{"id":"119994","scheme":"basic","secret":"YWxpY2U6YWxpY2UxMjM="}}' sid='OH2O8qVYp2M' uid=''
I2022/05/11 12:21:14 ws: session started s3AbCgp9pqU [::1]:59543 2
I2022/05/11 12:21:14 in: '{"hi":{"id":"129487","ver":"0.18.3","ua":"Undefined (Chrome/100.0; MacIntel); tinodejs/0.18.3","lang":"en-US","platf":"web"}}' sid='s3AbCgp9pqU' uid=''
I2022/05/11 12:21:14 in: '{"login":{"id":"129488","scheme":"basic","secret":"Ym9iOmJvYjEyMw=="}}' sid='s3AbCgp9pqU' uid=''
I2022/05/11 12:21:14 in: '{"sub":{"id":"119995","topic":"usrZUIjKqCiJRk"}}' sid='OH2O8qVYp2M' uid='WZ6fOvDA8OA'
I2022/05/11 12:21:14 in: '{"sub":{"id":"129489","topic":"usrWZ6fOvDA8OA"}}' sid='s3AbCgp9pqU' uid='ZUIjKqCiJRk'
I2022/05/11 12:21:14 in: '{"leave":{"id":"119996","topic":"usrZUIjKqCiJRk","unsub":true}}' sid='OH2O8qVYp2M' uid='WZ6fOvDA8OA'
I2022/05/11 12:21:14 in: '{"leave":{"id":"129490","topic":"usrWZ6fOvDA8OA","unsub":true}}' sid='s3AbCgp9pqU' uid='ZUIjKqCiJRk'
W2022/05/11 12:21:14 users: missing users cache entry after IO completion, uid ZUIjKqCiJRk
I2022/05/11 12:21:19 in: '{"sub":{"id":"119997","topic":"usrZUIjKqCiJRk"}}' sid='OH2O8qVYp2M' uid='WZ6fOvDA8OA'
gabriel-vasile commented 2 years ago

This issue still happens. Tested with fresh install of master.

This HTML reproduces the problem:

<!DOCTYPE html>
<html lang="en">
<head>
    <script crossorigin="anonymous"
      src="https://cdn.jsdelivr.net/npm/tinode-sdk/umd/tinode.dev.js">
    </script>
    <meta charset="UTF-8">
</head>

<body id="home">
  <h1>HTML5 boilerplate</h1>
<script>
u1 = {
    u: "alice",
    p: "alice123",
}
u2 = {
    u: "bob",
    p: "bob123",
}

t1 = new Tinode({
    host: "localhost:6060",
    apiKey: "AQEAAAABAAD_rAp4DJh05a1HAwFT3A6K",
});
t2 = new Tinode({
    host: "localhost:6060",
    apiKey: "AQEAAAABAAD_rAp4DJh05a1HAwFT3A6K",
});

async function run() {
    await t1.connect()
    await t1.loginBasic(u1.u, u1.p)
    await t2.connect()
    await t2.loginBasic(u2.u, u2.p)
    await t1.subscribe(t2.getCurrentUserID())
    await t2.subscribe(t1.getCurrentUserID())
    await t1.delTopic(t2.getCurrentUserID())
    await t2.delTopic(t1.getCurrentUserID())
    await t1.subscribe(t2.getCurrentUserID())
}
run()
</script>
</body>
</html>

server logs:

I2022/04/18 16:18:24 ws: session started tSGTaHPI-mQ 127.0.0.1:47682 1
I2022/04/18 16:18:24 in: '{"hi":{"id":"99432","ver":"0.18.3","ua":"Undefined (Firefox/95.0; Linux x86_64); tinodejs/0.18.3","lang":"en-US","platf":"web"}}' sid='tSGTaHPI-mQ' uid=''
I2022/04/18 16:18:24 in: '{"login":{"id":"99433","scheme":"basic","secret":"YWxpY2U6YWxpY2UxMjM="}}' sid='tSGTaHPI-mQ' uid=''
I2022/04/18 16:18:24 ws: session started oJaYHBERnAk 127.0.0.1:47684 2
I2022/04/18 16:18:24 in: '{"hi":{"id":"107923","ver":"0.18.3","ua":"Undefined (Firefox/95.0; Linux x86_64); tinodejs/0.18.3","lang":"en-US","platf":"web"}}' sid='oJaYHBERnAk' uid=''
I2022/04/18 16:18:24 in: '{"login":{"id":"107924","scheme":"basic","secret":"Ym9iOmJvYjEyMw=="}}' sid='oJaYHBERnAk' uid=''
I2022/04/18 16:18:24 in: '{"sub":{"id":"99434","topic":"usrrv5fJHNe8N8"}}' sid='tSGTaHPI-mQ' uid='Krt1fadJ0rM'
I2022/04/18 16:18:24 in: '{"sub":{"id":"107925","topic":"usrKrt1fadJ0rM"}}' sid='oJaYHBERnAk' uid='rv5fJHNe8N8'
I2022/04/18 16:18:24 in: '{"del":{"id":"99435","topic":"usrrv5fJHNe8N8","what":"topic"}}' sid='tSGTaHPI-mQ' uid='Krt1fadJ0rM'
I2022/04/18 16:18:24 in: '{"del":{"id":"107926","topic":"usrKrt1fadJ0rM","what":"topic"}}' sid='oJaYHBERnAk' uid='rv5fJHNe8N8'
I2022/04/18 16:18:24 in: '{"sub":{"id":"99436","topic":"usrrv5fJHNe8N8"}}' sid='tSGTaHPI-mQ' uid='Krt1fadJ0rM'
E2022/04/18 16:18:24 hub: missing both subscriptions for 'p2pKrt1fadJ0rOu_l8kc17w3w' (SHOULD NEVER HAPPEN!)
E2022/04/18 16:18:24 init_topic: failed to load or create topic: p2pKrt1fadJ0rOu_l8kc17w3w internal

{del} still gives hub: missing both subscriptions for 'p2pKrt1fadJ0rOu_l8kc17w3w' (SHOULD NEVER HAPPEN!). Tested with devel.

or-else commented 2 years ago

I cannot reproduce:

I2022/05/13 09:23:43 in: '{"hi":{"id":"75506","ver":"0.18.3","ua":"Undefined (Chrome/100.0; MacIntel); tinodejs/0.18.3","lang":"en-US","platf":"web"}}' sid='Kb1CJlx4ldU' uid=''
I2022/05/13 09:23:43 in: '{"login":{"id":"75507","scheme":"basic","secret":"ZXZlOmV2ZTEyMw=="}}' sid='Kb1CJlx4ldU' uid=''
I2022/05/13 09:23:43 ws: session started MIIcFkyDZ5A [::1]:63905 4
I2022/05/13 09:23:43 in: '{"hi":{"id":"114845","ver":"0.18.3","ua":"Undefined (Chrome/100.0; MacIntel); tinodejs/0.18.3","lang":"en-US","platf":"web"}}' sid='MIIcFkyDZ5A' uid=''
I2022/05/13 09:23:43 in: '{"login":{"id":"114846","scheme":"basic","secret":"ZGF2ZTpkYXZlMTIz"}}' sid='MIIcFkyDZ5A' uid=''
I2022/05/13 09:23:43 in: '{"sub":{"id":"75508","topic":"usr3mM3i2omMfE"}}' sid='Kb1CJlx4ldU' uid='s3dAxmjhwnY'
I2022/05/13 09:23:43 in: '{"sub":{"id":"114847","topic":"usrs3dAxmjhwnY"}}' sid='MIIcFkyDZ5A' uid='3mM3i2omMfE'
I2022/05/13 09:23:43 in: '{"leave":{"id":"75509","topic":"usr3mM3i2omMfE","unsub":true}}' sid='Kb1CJlx4ldU' uid='s3dAxmjhwnY'
I2022/05/13 09:23:43 in: '{"leave":{"id":"114848","topic":"usrs3dAxmjhwnY","unsub":true}}' sid='MIIcFkyDZ5A' uid='3mM3i2omMfE'
I2022/05/13 09:23:43 in: '{"sub":{"id":"75510","topic":"usr3mM3i2omMfE"}}' sid='Kb1CJlx4ldU' uid='s3dAxmjhwnY'
gabriel-vasile commented 2 years ago

Your test uses {leave}. I don't know how to get this across. I said it 3 times; it's {del} packets that still trigger the problem. Check the javascript in my previous message. It does await t1.delTopic(t2.getCurrentUserID())

or-else commented 2 years ago 
I2022/05/13 12:37:07 ws: session started 6ZzegBS8h_Y [::1]:53238 3
I2022/05/13 12:37:07 in: '{"hi":{"id":"124227","ver":"0.18.3","ua":"Undefined (Chrome/100.0; MacIntel); tinodejs/0.18.3","lang":"en-US","platf":"web"}}' sid='6ZzegBS8h_Y' uid=''
I2022/05/13 12:37:07 in: '{"login":{"id":"124228","scheme":"basic","secret":"YWxpY2U6YWxpY2UxMjM="}}' sid='6ZzegBS8h_Y' uid=''
I2022/05/13 12:37:07 ws: session started OffXq00A9P0 [::1]:53239 4
I2022/05/13 12:37:07 in: '{"hi":{"id":"79666","ver":"0.18.3","ua":"Undefined (Chrome/100.0; MacIntel); tinodejs/0.18.3","lang":"en-US","platf":"web"}}' sid='OffXq00A9P0' uid=''
I2022/05/13 12:37:07 in: '{"login":{"id":"79667","scheme":"basic","secret":"ZnJhbms6ZnJhbmsxMjM="}}' sid='OffXq00A9P0' uid=''
I2022/05/13 12:37:07 in: '{"sub":{"id":"124229","topic":"usriAtx05POgMQ"}}' sid='6ZzegBS8h_Y' uid='Ggmfb4-BoJE'
I2022/05/13 12:37:07 in: '{"sub":{"id":"79668","topic":"usrGgmfb4-BoJE"}}' sid='OffXq00A9P0' uid='iAtx05POgMQ'
I2022/05/13 12:37:07 in: '{"del":{"id":"124230","topic":"usriAtx05POgMQ","what":"topic"}}' sid='6ZzegBS8h_Y' uid='Ggmfb4-BoJE'
I2022/05/13 12:37:07 in: '{"del":{"id":"79669","topic":"usrGgmfb4-BoJE","what":"topic"}}' sid='OffXq00A9P0' uid='iAtx05POgMQ'
I2022/05/13 12:37:07 in: '{"sub":{"id":"124231","topic":"usriAtx05POgMQ"}}' sid='6ZzegBS8h_Y' uid='Ggmfb4-BoJE'
or-else commented 2 years ago

https://github.com/tinode/chat/releases/tag/v0.18.7