Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
gabriel-vasile opened this issue Mar 30, 2022 · 16 comments
Labels

Comments

@gabriel-vasile
Copy link
Contributor

gabriel-vasile commented Mar 30, 2022

tinode version: master
To reproduce:

  • 2 users that haven't talked to each other before
  • user A attaches to user B (2 p2p subs are created)
  • user A deletes his subscription to user B
  • user B deletes his subscription to user A
  • user B tries to sub to user A

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 added a commit that referenced this issue Mar 31, 2022
@or-else or-else added the bug label Mar 31, 2022
@or-else
Copy link
Contributor

or-else commented Mar 31, 2022

This issue should be fixed in a81440d. Please verify. Thanks.

@gabriel-vasile
Copy link
Contributor Author

Fixed, thanks.

@or-else
Copy link
Contributor

or-else commented Apr 4, 2022

@or-else or-else closed this as completed Apr 4, 2022
@gabriel-vasile
Copy link
Contributor Author

gabriel-vasile commented Apr 18, 2022

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
Copy link
Contributor

or-else commented Apr 18, 2022

released in 0.18.4

@gabriel-vasile
Copy link
Contributor Author

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
Copy link
Contributor Author

I think I know what happened.
The fix in a81440d works for {leave} messages.
The problem still happens with {del}.

@or-else or-else reopened this Apr 19, 2022
or-else added a commit that referenced this issue Apr 23, 2022
@or-else
Copy link
Contributor

or-else commented Apr 23, 2022

The problem still happens with {del}.

Fixed in 16be737
Thanks.

@or-else
Copy link
Contributor

or-else commented Apr 26, 2022

@or-else or-else closed this as completed Apr 26, 2022
@gabriel-vasile
Copy link
Contributor Author

gabriel-vasile commented May 3, 2022

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
Copy link
Contributor

or-else commented May 11, 2022

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'

@or-else or-else closed this as completed May 12, 2022
@gabriel-vasile
Copy link
Contributor Author

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
Copy link
Contributor

or-else commented May 13, 2022

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
Copy link
Contributor Author

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 or-else reopened this May 13, 2022
or-else added a commit that referenced this issue May 13, 2022
@or-else
Copy link
Contributor

or-else commented May 13, 2022

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 or-else closed this as completed May 18, 2022
@or-else
Copy link
Contributor

or-else commented May 18, 2022

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

2 participants