Messages still showing out of order #426

hloeung · 2021-04-09T21:26:29Z

Hi,

Thought it was fixed with #419 but it looks like it's still happening (as @axinojolais mentioned a few days ago):

Test one
```
Test two
Test three
```
Test four
Test five

With that, you can see that messages are received out of order below:

Even without code blocks, for example:

Test one
Test two
Test three
Test four
Test five

Produces this:

The text was updated successfully, but these errors were encountered:

42wim · 2021-04-14T22:30:34Z

Possible to run with debug and paste the output?

hloeung · 2021-04-22T09:25:44Z

Sure, planning to try reproduce it when I have time and see if it's easily fixed. It may even be to do with the introduction of an additional IRC client/proxy (for me, it's irssi client -> irssi proxy -> matterircd. For @axinojolais, it's irssi client -> bip (?!?) -> matterircd).

FWIW, I've been running matterircd reverting commit 2c3883a and so far haven't noticed out-of-order messages. Anyways, will keep digging.

guilhermepiccoli · 2021-04-22T15:44:58Z

I am also facing this issue. My setup is hexchat <-> ZNC <-> matterircd.
I do have debug enabled...will paste a "redacted" example below of the issue

guilhermepiccoli · 2021-04-22T16:48:50Z

ORIGINAL / Web-client

ONE
TWO
THREE
FOUR
FIVE
SIX

MATTERIRCD

[1d4] ONE
[1d5] TWO
[1d6] THREE
[1d7] FIVE
[1d8] FOUR
[1d9] SIX

Debug logs:

The issues seems to be that messages FOUR and FIVE got "glued" together, it shows as "FOUR\nFIVE" in the debug logs.
Then some parsing split them, but throw them in reverse order.

I hope this is useful for the issue debugging!
Cheers

redacted_dbg_logs.txt

hloeung · 2021-04-23T06:42:02Z

So I guess this is just fallout from switching to using buffered channels?

With the fix switching back to unbuffered channels, u.eventChan = make(chan *bridge.Event) or u.eventChan = make(chan *bridge.Event, 0)?

hloeung · 2021-04-23T10:21:23Z

IIUC, in handleWsActionPost() (https://github.com/42wim/matterircd/blob/master/bridge/mattermost/mattermost.go#L813), a single message with multiple lines is split into multiple messages and put into the buffered channel (#383). Unfortunately, per https://stackoverflow.com/a/25795236, with buffered channels, we can't guarantee order of messages (the delivery?).

Correct me if I'm wrong.

42wim · 2021-04-23T10:41:31Z

Well, we have 1 goroutine handling them and the get put in in order, so that's why I don't understand it or I must be missing something.

@guilhermepiccoli logs above show the issue, a LIFO problem :-)
I'm wondering why the FIVE and FOUR got glued together though.

hloeung · 2021-04-23T10:44:20Z

Well, we have 1 goroutine handling them and the get put in in order, so that's why I don't understand it or I must be missing something

Oh, just edited my previous comment as you were replying :)

I checked and we do indeed have only the 1 goroutine.

guilhermepiccoli · 2021-04-27T17:43:58Z

Thanks @42wim and @hloeung ! Is there anything else I can provide in order to get us to a resolution?
Unfortunately my time is really full the next 2 weeks, or else I'd try to fix myself, hopefully not too complex

42wim · 2021-04-28T21:14:39Z

@hloeung are you sure you were testing with the version that has #419 in it ? I talked to @guilhermepiccoli and he was using an older version that didn't had the fix.

I also can not reproduce it with current master

hloeung · 2021-04-30T04:22:43Z

Yeah, definitely using a version with #419 applied.

I wasn't able to easily reproduce it locally either. I'll have another go at reproducing it with debug/trace enabled this weekend.

hloeung · 2021-05-05T08:44:08Z

An update here, still haven't come across this yet and wasn't able to reproduce it myself.

I did stumble on #420 with a PR to fix that though so all is not in vein.

42wim · 2021-05-05T19:55:49Z

Ok, i'm going to close this, if someone can reproduce it, feel free to reopen.

hloeung · 2021-06-02T10:40:02Z

Seen it today, with the latest matterircd. Sadly, while running without debug/trace logging.

@guilhermepiccoli did you end up sanitising the logs you had?

guilhermepiccoli · 2021-06-09T19:06:39Z

Hey @42wim and @hloeung !
Finally I was able to sanitize the logs I have, which shows the issue with 0.24.1, trace enabled - hope this is helpful.

ooo_msg_0.24.1-sanitized.txt

guilhermepiccoli · 2021-06-09T19:07:49Z

Also, can we reopen the issue @42wim ? Saw this issue a lot past few days, but only have the above log collection with trace enabled. Have a bunch with just the debug logs though...

Cheers!

This should fix any unordered messages, but no idea why they are unordered in the first place...

42wim · 2021-06-09T22:41:35Z

@guilhermepiccoli and closed again.. no idea why it happens, I've now removed buffered channels for mattermost/slack.
master should fix it

guilhermepiccoli · 2021-06-10T12:01:53Z

Thanks a bunch @42wim , gonna try now (will run the artifact generated by the test build of this commit).

axinojolais · 2021-06-10T15:43:55Z

I'm running with the patch above, and so far, no out-of-order messages.

Thanks !

furai · 2021-06-11T13:04:02Z

@guilhermepiccoli and closed again.. no idea why it happens, I've now removed buffered channels for mattermost/slack.
master should fix it

I'll give it a try as well. I've been experiencing a lot of out of order messages lately.

As to why it got closed (if you were actually asking about it, if not, I'm sorry for providing explanation anyway) - it's because of the commit message. If you put in it keywords like Fixes #21312312 then when it's gets included in the main branch - it will automatically close the mentioned issue. Source.

guilhermepiccoli · 2021-06-16T12:52:27Z

Unfortunately, I'm still seeing the issues even with @42wim 's patch =/

furai · 2021-06-21T12:41:49Z

Yeah, I'm also experiencing out of order messages.
It's like if they get grouped by mattermost app into one then they appear in wrong order in matterircd. Probably enough to reproduce is to type 2 messages in quick succession on mattermost web or maybe inside the mattermost app. If they get grouped then they appear in IRC in reversed order.

furai · 2021-06-22T11:17:32Z

In web UI:

On IRC:

I'm using latest release build

furai · 2021-06-24T08:37:48Z

Adding to the above - the messages sent by this user were most likely sent using desktop mattermost app.

42wim · 2021-07-04T22:40:27Z

Can the people (@hloeung, @guilhermepiccoli, @furai ) that still have the issue download this special build: https://github.com/42wim/matterircd/pull/445/checks?check_run_id=2985395608 (and select your correct artifact)

https://github.com/42wim/matterircd/suites/3155567672/artifacts/72567237 should be a direct link to the 64-bit linux one.

Now add ootrace=true (same way as trace=true) in your matterircd.toml (so not under the mattermost header)
You don't need to run with full --debug, the ootrace option will show info messages with timestamps of every (multiline) message (and content) going to the eventchan and received from the eventchan on the irc side.

Hopefully this way we can see if there's a channel out of order issue or something else, if you get hit by the issue, paste the last OOTRACE lines here.

hloeung · 2021-07-04T23:02:20Z

Per IRC, I haven't come across or noticed it since the latest patch. I've pulled in the latest with OOTRACE logging anyways. Will update if I notice.

Thanks!

hloeung · 2021-07-07T08:38:57Z

Okay, here it is:

INFO[2021-07-07T08:20:07Z] OOTRACE: sending msg ${MSG1}  to eventChan on 1625646007267419568: 0
INFO[2021-07-07T08:20:07Z] OOTRACE: sending msg ``` to eventChan on 1625646007267530504: 0
INFO[2021-07-07T08:20:07Z] OOTRACE: sending msg ${MSG2} to eventChan on 1625646007267579861: 0
INFO[2021-07-07T08:20:07Z] OOTRACE: got msg ``` [@@mpdc9qt9zi88jjqnuartbkc8ec] on 1625646007268263014  module=matterircd
INFO[2021-07-07T08:20:07Z] OOTRACE: got msg ${MSG1} [@@mpdc9qt9zi88jjqnuartbkc8ec] on 1625646007268319657  module=matterircd
INFO[2021-07-07T08:20:07Z] OOTRACE: sending msg ``` to eventChan on 1625646007272937234: 0
INFO[2021-07-07T08:20:07Z] OOTRACE: got msg ${MSG2} [@@mpdc9qt9zi88jjqnuartbkc8ec] on 1625646007273574391  module=matterircd
INFO[2021-07-07T08:20:07Z] OOTRACE: ${USER} sent ${MSG1}
```
${MSG2}
```
INFO[2021-07-07T08:20:07Z] OOTRACE: got msg ``` [@@mpdc9qt9zi88jjqnuartbkc8ec] on 1625646007275923369  module=matterircd

hloeung · 2021-07-07T08:49:04Z

Another:

INFO[2021-07-07T05:31:43Z] OOTRACE: sending msg ${MSG1} to eventChan on 1625635903100315921: 0
INFO[2021-07-07T05:31:43Z] OOTRACE: sending msg ${MSG2} to eventChan on 1625635903100436639: 0
INFO[2021-07-07T05:31:43Z] OOTRACE: sending msg ${MSG3} to eventChan on 1625635903100489927: 0
INFO[2021-07-07T05:31:43Z] OOTRACE: got msg ${MSG2} [↪@@57z8xex4m78ijfuqke6yk6ha4e] on 1625635903101329460  module=matterircd
INFO[2021-07-07T05:31:43Z] OOTRACE: got msg ${MSG1} [↪@@57z8xex4m78ijfuqke6yk6ha4e] on 1625635903101347667  module=matterircd
INFO[2021-07-07T05:31:43Z] OOTRACE: ${USER} sent ${MSG1}

${MSG2}

${MSG3}

INFO[2021-07-07T05:31:43Z] OOTRACE: got msg ${MSG3} [↪@@57z8xex4m78ijfuqke6yk6ha4e] on 1625635903107285778  module=matterircd

42wim · 2021-07-11T22:02:02Z

@hloeung does MSG1 MSG2 or MSG3 contain ``` ?
or a reaction?

I have no idea btw how this is possible, msg's get set on the channel in order but get read out of order.

42wim · 2021-07-11T22:44:10Z

@hloeung and other peeps, can you try https://github.com/42wim/matterircd/pull/445/checks?check_run_id=3041968404 ?
https://github.com/42wim/matterircd/suites/3211116698/artifacts/74279412 direct linux 64-bit build.

The change here is to remove the buffered channel completely although this shouldn't make any difference because it's getting set to 0 when initializing mattermost/slack but maybe I'm missing something :)

If you're seeing OOTRACE: creating non-buffered eventchan on start-up when connected to mattermost you're running the correct version.

hloeung · 2021-07-12T22:04:50Z

Yep, upgraded yesterday and am running with the latest patch since then.

[ubuntu@irc-proxy mattermost]$ ./matterircd
INFO[2021-07-12T10:16:20Z] Running version 0.24.3-dev                    module=matterircd                                                                                                                                                              
INFO[2021-07-12T10:16:20Z] WARNING: THIS IS A DEVELOPMENT VERSION. Things may break.  module=matterircd
INFO[2021-07-12T10:16:20Z] Listening on 127.0.0.1:6697                   module=matterircd                                                                                                                                                              
INFO[2021-07-12T10:17:11Z] New connection: 127.0.0.1:44932               module=matterircd
INFO[2021-07-12T10:17:11Z] OOTRACE: creating non-buffered eventchan on start-up  module=matterircd                                                                                                                                                      
slack-go/slack2021/07/12 10:17:11 websocket_managed_conn.go:181: Connecting to RTM
...

I can see a difference in the logs already. Seems to be got, sending, got, sending, got, sending vs. previously it's bunch of gots followed by bunch of sendings.

Will keep watching.

42wim · 2021-07-20T21:31:23Z

so fixed now? I'll do a release tomorrow then.

hloeung · 2021-07-21T02:39:55Z

Yeah, I think so. Not noticed any more OOO messages.

hloeung · 2021-07-21T10:45:17Z

Spoke too soon.

On IRC:

|20:30 <user1> ```bash [ui1pfumdkf8nmkwd8zwc46zqch]
|20:30 <user1> mount error 110 = Connection timed out [ui1pfumdkf8nmkwd8zwc46zqch]
|20:30 <user1> msg1 [ui1pfumdkf8nmkwd8zwc46zqch]
|20:30 <user1> ``` [ui1pfumdkf8nmkwd8zwc46zqch]
|20:30 <user1> $ sudo mount -t ceph :/testdir /mnt/cephfs -o name=bootstacktest [ui1pfumdkf8nmkwd8zwc46zqch]

Matterircd OOTRACE logs:

INFO[2021-07-20T20:30:13Z] OOTRACE: sending msg msg1 to eventChan on 1626813013329295391: 0
INFO[2021-07-20T20:30:13Z] OOTRACE: sending msg ```bash to eventChan on 1626813013329423442: 0                                                                                                                                                          
INFO[2021-07-20T20:30:13Z] OOTRACE: sending msg $ sudo mount -t ceph :/testdir /mnt/cephfs -o name=bootstacktest to eventChan on 1626813013329487053: 0                                                                                                 
INFO[2021-07-20T20:30:13Z] OOTRACE: sending msg mount error 110 = Connection timed out to eventChan on 1626813013329544542: 0                                                                                                                           
INFO[2021-07-20T20:30:13Z] OOTRACE: got msg ```bash [@@ui1pfumdkf8nmkwd8zwc46zqch] on 1626813013331397999 module=matterircd
INFO[2021-07-20T20:30:13Z] OOTRACE: got msg msg1 [@@ui1pfumdkf8nmkwd8zwc46zqch] on 1626813013331004892 module=matterircd
INFO[2021-07-20T20:30:13Z] OOTRACE: got msg $ sudo mount -t ceph :/testdir /mnt/cephfs -o name=bootstacktest [@@ui1pfumdkf8nmkwd8zwc46zqch] on 1626813013331507745  module=matterircd
INFO[2021-07-20T20:30:13Z] OOTRACE: got msg mount error 110 = Connection timed out [@@ui1pfumdkf8nmkwd8zwc46zqch] on 1626813013341611377  module=matterircd
INFO[2021-07-20T20:30:13Z] OOTRACE: sending msg ``` to eventChan on 1626813013345213396: 0
INFO[2021-07-20T20:30:13Z] OOTRACE: user1 sent msg1
```bash
$ sudo mount -t ceph :/testdir /mnt/cephfs -o name=bootstacktest                                                                                                                                                                                        
mount error 110 = Connection timed out
```
INFO[2021-07-20T20:30:13Z] OOTRACE: got msg ``` [@@ui1pfumdkf8nmkwd8zwc46zqch] on 1626813013348128027  module=matterircd

So wtf?!?!?

hloeung · 2021-08-13T01:43:41Z

Still happening, a lot less frequent, but still seeing it. Most recent being:

INFO[2021-08-12T23:18:01Z] OOTRACE: #town-square: 3sbkx9gjypgg5d1f7frf79xfxc: sending  msg 39       2 ftpuser to eventChan on 1628810281942359650: 0
INFO[2021-08-12T23:18:01Z] OOTRACE: #town-square: 3sbkx9gjypgg5d1f7frf79xfxc: sent     msg 39       2 ftpuser to eventChan on 1628810281948257769: 0
INFO[2021-08-12T23:18:01Z] OOTRACE: #town-square: 3sbkx9gjypgg5d1f7frf79xfxc: sending  msg 40       2 deploy to eventChan on 1628810281948595596: 0
INFO[2021-08-12T23:18:01Z] OOTRACE: #town-square: 3sbkx9gjypgg5d1f7frf79xfxc: got      msg 40       2 deploy [@@3sbkx9gjypgg5d1f7frf79xfxc] on 1628810281953273716  module=matterircd
INFO[2021-08-12T23:18:01Z] OOTRACE: #town-square: 3sbkx9gjypgg5d1f7frf79xfxc: got      msg 39       2 ftpuser [@@3sbkx9gjypgg5d1f7frf79xfxc] on 1628810281954677351  module=matterircd
WARN[2021-08-12T23:18:01Z] OOTRACE: #town-square: 3sbkx9gjypgg5d1f7frf79xfxc: Message out of order, got msg 39       2 ftpuser [@@3sbkx9gjypgg5d1f7frf79xfxc] but seen 40  module=matterircd
INFO[2021-08-12T23:18:01Z] OOTRACE: #town-square: 3sbkx9gjypgg5d1f7frf79xfxc: sent     msg 40       2 deploy to eventChan on 1628810281955665837: 0                                                                                                     INFO[2021-08-12T23:18:01Z] OOTRACE: #town-square: 3sbkx9gjypgg5d1f7frf79xfxc: sending  msg 41       2 chia to eventChan on 1628810281955869657: 0
INFO[2021-08-12T23:18:01Z] OOTRACE: #town-square: 3sbkx9gjypgg5d1f7frf79xfxc: sent     msg 41       2 chia to eventChan on 1628810281955993984: 0                                                                                                       INFO[2021-08-12T23:18:01Z] OOTRACE: #town-square: 3sbkx9gjypgg5d1f7frf79xfxc: sending  msg 42       2 centos to eventChan on 1628810281956149911: 0

Weird, I'm at a loss at where this would be.

furai · 2021-10-14T12:24:27Z

Still no fix for this?

42wim · 2021-11-07T21:56:31Z

@furai well, if we don't know the root cause we can't fix it :(

This fixes #480 and as a bonus also fixes #426 as this is now just 1 big message for irc

42wim · 2022-10-15T15:31:02Z

#482 should fix this as we're not splitting the lines from mattermost anymore before sending it to irc
So anyone still interested, please try this PR :)

This fixes 42wim#480 and as a bonus also fixes 42wim#426 as this is now just 1 big message for irc

hloeung added a commit to hloeung/matterircd that referenced this issue Apr 23, 2021

Use unbuffered channels to avoid out-of-order msgs. Fixes 42wim#426

a905011

42wim closed this as completed May 5, 2021

42wim reopened this Jun 9, 2021

42wim added a commit that referenced this issue Jun 9, 2021

Use unbuffered eventChan for slack/mattermost. Fixes #426

90471e8

This should fix any unordered messages, but no idea why they are unordered in the first place...

42wim closed this as completed in e097242 Jun 9, 2021

42wim reopened this Jun 24, 2021

hloeung mentioned this issue Jul 21, 2021

Include additional info such as channel, msgid, and msg line # in OOTRACE #446

Closed

42wim added a commit that referenced this issue Oct 14, 2022

Do not split message on newlines

b5966fd

This fixes #480 and as a bonus also fixes #426 as this is now just 1 big message for irc

42wim mentioned this issue Oct 14, 2022

Do not split message on newlines #482

Merged

hloeung pushed a commit to hloeung/matterircd that referenced this issue Oct 16, 2022

Do not split message on newlines

f90ff9d

This fixes 42wim#480 and as a bonus also fixes 42wim#426 as this is now just 1 big message for irc

42wim closed this as completed in #482 Nov 1, 2022

42wim closed this as completed in e47926b Nov 1, 2022

Messages still showing out of order #426

Messages still showing out of order #426

Comments

hloeung commented Apr 9, 2021

42wim commented Apr 14, 2021

hloeung commented Apr 22, 2021

guilhermepiccoli commented Apr 22, 2021

guilhermepiccoli commented Apr 22, 2021

hloeung commented Apr 23, 2021

hloeung commented Apr 23, 2021 • edited Loading

42wim commented Apr 23, 2021 • edited Loading

hloeung commented Apr 23, 2021

guilhermepiccoli commented Apr 27, 2021

42wim commented Apr 28, 2021

hloeung commented Apr 30, 2021

hloeung commented May 5, 2021

42wim commented May 5, 2021

hloeung commented Jun 2, 2021 • edited Loading

guilhermepiccoli commented Jun 9, 2021

guilhermepiccoli commented Jun 9, 2021

42wim commented Jun 9, 2021

guilhermepiccoli commented Jun 10, 2021

axinojolais commented Jun 10, 2021

furai commented Jun 11, 2021

guilhermepiccoli commented Jun 16, 2021

furai commented Jun 21, 2021

furai commented Jun 22, 2021

furai commented Jun 24, 2021

42wim commented Jul 4, 2021 • edited Loading

hloeung commented Jul 4, 2021

hloeung commented Jul 7, 2021

hloeung commented Jul 7, 2021

42wim commented Jul 11, 2021 • edited Loading

42wim commented Jul 11, 2021 • edited Loading

hloeung commented Jul 12, 2021

42wim commented Jul 20, 2021

hloeung commented Jul 21, 2021

hloeung commented Jul 21, 2021

hloeung commented Aug 13, 2021

furai commented Oct 14, 2021

42wim commented Nov 7, 2021

42wim commented Oct 15, 2022

hloeung commented Apr 23, 2021 •

edited

Loading

42wim commented Apr 23, 2021 •

edited

Loading

hloeung commented Jun 2, 2021 •

edited

Loading

42wim commented Jul 4, 2021 •

edited

Loading

42wim commented Jul 11, 2021 •

edited

Loading

42wim commented Jul 11, 2021 •

edited

Loading