Info missing for recv/read messages in p2p/grp

[dilshansdoq]

Subject of the issue

Hi,
This seems like a bug. So the scenario is more than 1 users are chatting in a topic(p2p/grp), and issue is that one of the users won't get info:what:read/recv against note:what:read/recv issued by the other user. We saw that even if single message is sent but at the same instance of time, info message is missing for one of the topic subscriber, although highly prevalent when users are typing at fast pace.

Thanks

Your environment

Server-side

• web.tinode.co, api.tinode.co
• sandbox.tinode.co
• Your own setup:
  • platform: Linux
  • version of Tinode server: 0.21.0
  • database: MongoDB
  • standalone

Client-side

• TinodeWeb/tinodejs: javascript client
  • Browser make and version: Microsoft edge Version 113.0.1774.35 (Official build) (64-bit)
• Tindroid: Android app
  • Android API level: 30,31,32,33
  • Hardware: Latest 2022-2023 flagships
• Tinodios: iOS app
  • iOS version:
  • Hardware: iPhone 6s plus, 12, 13
• Version of the client: 0.21.0

Steps to reproduce, Actual behaviour

Create a p2p topic, with two users UserA, UserB. Both send message to each other at same time. One of them will not receive info message of either recv or read. Single message might not be enough to reproduce. So they can keep sending messages to each other at high rate (2-3 rps). One of them will stop receiving info message of recv/read. (It happens mostly with read, recv info is sent by server most of times)

Expected behaviour

Both users should receive info:read/recv for all messages (or at least last one)

Server-side log, Client-side log

info-missing-fast-typing.zip
In this bug example, client-1 stopped receiving read messages, only received were sent by server, however client-2 was online and actively sending messages to client-1. Server is dropping info messages. These logs are from debug-panel with our hosted server. But it is easily replicable on sandbox.tinode.co as well

[or-else]

I'm not sure there is a bug. We do not guarantee that each message will be individually acknowledged. For instance, if "read" is ack-ed for seq=45, that mean all messages prior to seq=45 are also read and received even if there was no ack for seq=44.

Please point me to specific gaps in your logs. What exactly was not acknowledged in your session?

[dilshansdoq]

Yes, and i understand that "read" for seq 45, will mark read prior to seq 45.
The issue is that "read" or even "recv"(sometimes, not in this case) is not being marked for seq 45(just an example) for one of the user(because of not receiving info msg, but note sent by peer user).
If you see in the logs, of client1(who is facing this bug),

• has not received any info:read, but only info:recv 5 times
• client2 has sent note:read upto seq:45
• server logs also confirm to this that server has also not sent info:read:m8BcygGayyo(client1) but only info:recv

This issue is very easily replicable on sandbox.tinode.co, just get two users, and let them send messages at fast pace, one of them will stop receiving info:read/recv(and ui will show only double/single ticks, and not blue ticks even though other has subscribed to topic and marked note).

[or-else]

I'm looking at this part of your server log (I removed entries unrelated to seq=45)

I2023/05/31 08:20:58.767652 out: '{"data":{"topic":"usrMQHA4oE6F0E","from":"usrMQHA4oE6F0E","ts":"2023-05-31T08:20:55.881Z","seq":45,"content":"re"}}' sid='83MgEyejDvU' uid='m8BcygGayyo'
I2023/05/31 08:20:58.954776 in: '{"note":{"topic":"usrMQHA4oE6F0E","what":"recv","seq":45}}' sid='83MgEyejDvU' uid='m8BcygGayyo'
I2023/05/31 08:20:58.966120 in: '{"note":{"topic":"usrm8BcygGayyo","what":"recv","seq":45}}' sid='xRWQedhRy7k' uid='MQHA4oE6F0E'
I2023/05/31 08:20:59.061015 out: '{"info":{"topic":"usrm8BcygGayyo","from":"usrm8BcygGayyo","what":"recv","seq":45}}' sid='xRWQedhRy7k' uid='MQHA4oE6F0E'
I2023/05/31 08:20:59.292205 in: '{"note":{"topic":"usrMQHA4oE6F0E","what":"read","seq":45}}' sid='83MgEyejDvU' uid='m8BcygGayyo'
I2023/05/31 08:20:59.365452 out: '{"info":{"topic":"usrm8BcygGayyo","from":"usrm8BcygGayyo","what":"read","seq":45}}' sid='xRWQedhRy7k' uid='MQHA4oE6F0E'

Where exactly do you see the problem?

[or-else]

Please show me the part of the logs which illustrates the problem. Or list the line numbers in the attached logs.

[dilshansdoq]

I'm looking at this part of your server log (I removed entries unrelated to seq=45)

I2023/05/31 08:20:58.767652 out: '{"data":{"topic":"usrMQHA4oE6F0E","from":"usrMQHA4oE6F0E","ts":"2023-05-31T08:20:55.881Z","seq":45,"content":"re"}}' sid='83MgEyejDvU' uid='m8BcygGayyo'
I2023/05/31 08:20:58.954776 in: '{"note":{"topic":"usrMQHA4oE6F0E","what":"recv","seq":45}}' sid='83MgEyejDvU' uid='m8BcygGayyo'
I2023/05/31 08:20:58.966120 in: '{"note":{"topic":"usrm8BcygGayyo","what":"recv","seq":45}}' sid='xRWQedhRy7k' uid='MQHA4oE6F0E'
I2023/05/31 08:20:59.061015 out: '{"info":{"topic":"usrm8BcygGayyo","from":"usrm8BcygGayyo","what":"recv","seq":45}}' sid='xRWQedhRy7k' uid='MQHA4oE6F0E'
I2023/05/31 08:20:59.292205 in: '{"note":{"topic":"usrMQHA4oE6F0E","what":"read","seq":45}}' sid='83MgEyejDvU' uid='m8BcygGayyo'
I2023/05/31 08:20:59.365452 out: '{"info":{"topic":"usrm8BcygGayyo","from":"usrm8BcygGayyo","what":"read","seq":45}}' sid='xRWQedhRy7k' uid='MQHA4oE6F0E'

Where exactly do you see the problem?

A: session:-xRWQedhRy7k, user:-MQHA4oE6F0E
B: session:-83MgEyejDvU, user:-m8BcygGayyo
Info:read is only sent to session:A, user:A
The bug is with session:B, user:B
Server has not sent any info:read to session:B, user:B. This is the problem.

user:B's last pub message has id:91504(line:144), seqId:42 (line:199)
user:A marked recv:seq:42 (line:203), read:seq:43 (line:211)
Clearly, A has marked seq:43 as read (meaning 42 should also be read, sent by B), but server has not sent info:read:42 to B. There is not a single info:read sent to B, all info:read were sent to A. Hence B has not marked them as read (and stuck at recv status, i.e. double-ticks and not blue ticks)

[or-else]

In line 218 server notifies user B that user A received message seq=40. It's quite possible that you simply overwhelmed the server and the messages were backed up. If you wait long enough the notification for 42 will be sent as well.

I2023/05/31 08:20:58.840424 out: '{"info":{"topic":"usrMQHA4oE6F0E","from":"usrMQHA4oE6F0E","what":"recv","seq":40}}' sid='83MgEyejDvU' uid='m8BcygGayyo'

[dilshansdoq]

In line 218 server notifies user B that user A received message seq=40. It's quite possible that you simply overwhelmed the server and the messages were backed up. If you wait long enough the notification for 42 will be sent as well.

I2023/05/31 08:20:58.840424 out: '{"info":{"topic":"usrMQHA4oE6F0E","from":"usrMQHA4oE6F0E","what":"recv","seq":40}}' sid='83MgEyejDvU' uid='m8BcygGayyo'

I think you are missing point. The point i am trying to convey you is that server is not sending "read"(emphasis) for messages sent by B and marked as "read" by A. Server will not send info:read to B until another message is sent by B->A and A marks it as read(by sending note) -> and server issues a info:read to B, no matter wait. I get it that server is overwhelmed because of too many read/recv from both sides, but that is where bug lies. This is just a single p2p topic, and we are using standalone 4 core machine, and as i said earlier too this is replicable on sandbox.tinode.co .
Ok, tested just now on sandbox.tinode.co
client1: web
client2: tindroid
client1 didn;t receive a single info:read.
I waited for 2 mins, as you said that server might need time, but it didn't send any info. Then client1 sent pub(id:99067), and in response client2 issues note:read and server issues info:read to client1.(this is success case, but client1 was stuck at recv until it sent another message, take example if client1 sent 2 messages on day1, and client 2 has ack-ed them also(sent note:read), but server didn't sent info:read to client1, now only if client1 sends another message on day2(lets say), only then it will know that client2 had already seen his day1 messages)
info-missing-sandbox-tinode-client.zip

I think i have tried my best to explain you the problem.
Thanks

[or-else]

I think you are missing point.

It's quite possible that I'm missing the point because I'm unable to see the problem in the attached logs. Or you are unable to clearly demonstrate it.

You said in context of message 42:

Server has not sent any info:read to session:B, user:B. This is the problem.

No, that is not a problem because the server did not receive note=read seq=42 from anyone, consequently it did not send info read seq=42 to any client.

The server received note read seq=43 from usrm8BcygGayyo (line 206) and it forwarded it to usrMQHA4oE6F0E (line 220).

It's very difficult for me to follow your reasoning. Please give me the line number where client usrXXX sent note read seq=123 and then the server never followed with info read seq=123 to usrYYY.

Then client1 sent pub(id:99067),

I do not see a message with id=99067 in your logs.

[dilshansdoq]

Could you please clarify this so we could be on same page.
In this attachement, i have added a script which does the simulation of two users sending message to each other at same time.

• user A and B subs to each other and send a message at same time.

• Both of them marks it as recv and read as soon as they get {data} message.

• In the server logs, we could see that it dropped info:read for seq:106 (meant for sess:0b1Vfs6Gh0o, user:IoXH4yjUJMg)

• It only sent info:read for seq:107(to sess:0sog3gqfjGE, user:svxfCch7U5k)

• And (sess:0b1Vfs6Gh0o, user:IoXH4yjUJMg) is unable to determine that seq:106 message was read by (sess:0sog3gqfjGE, user:svxfCch7U5k) or not.

• Removing those if conditions will fix this, but this will result in a lot of info messages(for eg, in case of large group), that could have been dropped.

info-missing-issue.zip

Thanks

[or-else]

Yes, I see the problem now. Let me think about it.

[dilshans2k]

Thank you acknowledging the issue. Looking forward to it.

[or-else]

Here is the underlying reason.

Read and recv notifications make use of the fact that messages have a sequential ID seq. If message with seq=100 is received (or read), that means the client has also received all messages with seq<100. Client uses {note seq=...} to inform counterparties that the message was received or read.

If a client sends a message with seq=100 then obviously this client also received/read his own message.

And that's where the problem comes from:

1. Client receives message seq=100
2. Client sends a new message
3. Server receives message from step 2 and assigns seq=101 to it, sends {ctrl} to the client
4. Server marks client as having received and read all messages up to seq=101.
5. Client acks {note read seq=100}, server receives the ack and discards it because in step 4 client was marked as having received seq=101 already.

The most rational way to fix it is that if Client B received a message from Client A with seq=101, then Client B should assume that Client A has received all messages up to seq=101. I'm going to make these changes to the client.

[dilshansdoq]

Very interesting but obvious solution, it seems.

Thanks, this has fixed the issue.