Matterbridge: [Zulip->*] Messages not sent over bridge

Created on 21 Mar 2020  ·  21Comments  ·  Source: 42wim/matterbridge

Describe the bug
Messages are not read from Zulip streams into IRC channel.

To Reproduce

  1. Set up matterbridge on docker with the instruction on the wiki or use the binary locally.
  2. Make a Zulip<->IRC bridge.
  3. Run the container/program.

Expected behavior
Messages are transmitted to the IRC channel from the Zulip stream.
NOTE: IRC messages reach the Zulip stream properly.
Also, adding, I had to run it on Docker because using the binary directly was not working for me (unsure why), if the instructions were more clearer I could clarify that as well.
Tested without a container and same issue persists. Note that for this, I used the current release (and not development).

Debug logs

user@user-MacBook-Pro:matterbridge % docker run -ti -v ~/matterbridge/matterbridge.toml:/matterbridge.toml 42wim/matterbridge -debug
[0000]  INFO main:         Enabling debug logging.
[0000]  INFO main:         Running version 1.16.6-dev 6b017b22
[0000]  INFO main:         WARNING: THIS IS A DEVELOPMENT VERSION. Things may break.
[0000]  INFO router:       Parsing gateway zulipirc
[0000]  INFO router:       Starting bridge: irc.freenode 
[0000]  INFO irc:          Connecting irc.freenode.net:6697
[0000] DEBUG irc:          "CLIENT_INIT irc.freenode.net:6697"
[0001] DEBUG irc:          ":card.freenode.net NOTICE * :*** Looking up your hostname..."
[0001] DEBUG irc:          ":card.freenode.net NOTICE * :*** Checking Ident"
[0001] DEBUG irc:          ":card.freenode.net NOTICE * :*** Couldn't look up your hostname"
[0010] DEBUG irc:          ":card.freenode.net NOTICE * :*** No Ident response"
[0010] DEBUG irc:          ":card.freenode.net CAP * LS :account-notify away-notify cap-notify chghost extended-join identify-msg multi-prefix sasl tls"
[0010] DEBUG irc:          ":card.freenode.net CAP zulipbridgebot ACK :cap-notify chghost multi-prefix account-notify extended-join sasl away-notify "
[0017] DEBUG irc:          "AUTHENTICATE +"
[0018] DEBUG irc:          ":card.freenode.net 900 zulipbridgebot [email protected] zulipbridgebot :You are now logged in as zulipbridgebot."
[0018] DEBUG irc:          ":card.freenode.net 903 zulipbridgebot :SASL authentication successful"
[0018] DEBUG irc:          ":card.freenode.net 001 zulipbridgebot :Welcome to the freenode Internet Relay Chat Network zulipbridgebot"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          Registering callbacks
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0018] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0019] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0019] DEBUG irc:          "CLIENT_GENERAL_UPDATED"
[0020] DEBUG irc:          "CLIENT_CONNECTED irc.freenode.net:6697"
[0024] DEBUG irc:          ":zulipbridgebot MODE zulipbridgebot +Zi"
[0024]  INFO irc:          Connection succeeded
[0024]  INFO irc:          irc.freenode: joining #wikimedia-test (ID: #wikimedia-testirc.freenode)
[0024]  INFO router:       Starting bridge: zulip.bot 
[0024] DEBUG irc:          handle girc.Event{Source:(*girc.Source)(0xc000527b90), Tags:girc.Tags(nil), Timestamp:time.Time{wall:0xbf95ad53d4d50867, ext:24734955744, loc:(*time.Location)(0x55feb8ff64e0)}, Command:"JOIN", Params:[]string{"#wikimedia-test", "zulipbridgebot", "zulipbridgebot"}, Sensitive:false, Echo:false}
[0025]  INFO zulip:        Connection succeeded
[0025]  INFO zulip:        zulip.bot: joining bot/topic:IRC (ID: bot/topic:IRCzulip.bot)
[0025]  INFO main:         Gateway(s) started succesfully. Now relaying messages
[0025] DEBUG zulip:        receiving error: &errors.errorString{s:"Error was unknown"}
[0026] DEBUG zulip:        receiving error: &errors.errorString{s:"Error was unknown"}
[0026] DEBUG zulip:        receiving error: &errors.errorString{s:"Error was unknown"}
[0026] DEBUG zulip:        receiving error: &errors.errorString{s:"Error was unknown"}
[0026] DEBUG zulip:        receiving error: &errors.errorString{s:"Error was unknown"}
[0027] DEBUG zulip:        receiving error: &errors.errorString{s:"Error was unknown"}
[0028] DEBUG zulip:        receiving error: &errors.errorString{s:"Error was unknown"}
[0028] DEBUG zulip:        receiving error: &errors.errorString{s:"Error was unknown"}
[0029] DEBUG zulip:        receiving error: &errors.errorString{s:"Error was unknown"}
[0029] DEBUG zulip:        receiving error: &errors.errorString{s:"Error was unknown"}
[0029] DEBUG zulip:        receiving error: &errors.errorString{s:"Error was unknown"}
[0030] DEBUG zulip:        receiving error: &errors.errorString{s:"Error was unknown"}

Environment (please complete the following information):

  • OS: Mac OS X Catalina 10.15.2
  • Matterbridge version: master (1.16.6-dev 6b017b22)

Additional context

[irc]
    [irc.freenode]
    Server="irc.freenode.net:6697"
    Nick="zulipbridgebot"
    NickServNick="zulipbridgebot"
    NickServPassword=""
    UseTLS=true
    UseSASL=true
    SkipTLSVerify=false
    RemoteNickFormat="[{PROTOCOL}] <{NICK}> "

[zulip]
    [zulip.bot]
    Token=""
    Login=""
    Server=""
    RemoteNickFormat="[{PROTOCOL}] <{NICK}>"

[[gateway]]
name="zulipirc"
enable=true
    [[gateway.inout]]
    account="irc.freenode"
    channel="#wikimedia-test"
    [[gateway.inout]]
    account="zulip.bot"
    channel=""
bug help wanted
Source
picture QEDK

Most helpful comment

@rht should be fixed in master now, I can't reproduce it anymore.

picture 42wim on 25 Aug 2020
🎉2

All 21 comments

You do actually have a channel filled in for zulip.bot ?

42wim picture 42wim on 22 Mar 2020

You do actually have a channel filled in for zulip.bot ?

Yep I do, in the format, "streamname/topic:mytopicname" (otherwise it throws an error anyway, so yep!)
Also on a side note, I was unable to understand if the parameter name (as in key) should be "channel:topic/mytopic" or the value name, eventually had to keep experimenting and read the code, to understand that the value given has to match the format specified in the error. Got it now tho!

QEDK picture QEDK on 22 Mar 2020

I've got something similar using docker image 42wim/matterbridge:1.17.4, trying to bridge slack and zulip :

[0000]  INFO main:         Enabling debug logging.
[0000]  INFO main:         Running version 1.17.4 6c442e23
[0000]  INFO router:       Parsing gateway stream-name
[0000]  INFO router:       Starting bridge: zulip.myzulip
[0000]  INFO zulip:        Connection succeeded
[0000]  INFO zulip:        zulip.myzulip: joining stream-name/topic:slack (ID: stream-name/topic:slackzulip.myzulip)
[0000]  INFO router:       Starting bridge: slack.myslack
[0000]  INFO slack:        Connecting using token
[0000]  INFO slack:        slack.myslack: joining ID:XXXXXXXXX (ID: ID:XXXXXXXXXslack.myslack)
[0000] DEBUG slack:        Choosing token based receiving
[0000] DEBUG slack:        == Receiving event &slack.ConnectingEvent{Attempt:1, ConnectionCount:0}
[0000] DEBUG zulip:        receiving error: &errors.errorString{s:"Error was unknown"}
[0000]  INFO main:         Gateway(s) started succesfully. Now relaying messages
[0000] DEBUG zulip:        receiving error: &errors.errorString{s:"Error was unknown"}
[0000] DEBUG slack:        == Receiving event &slack.ConnectedEvent{ConnectionCount:0, Info:(*slack.Info)(0xc0003d4100)}
[0000] DEBUG zulip:        receiving error: &errors.errorString{s:"Error was unknown"}
[0001] DEBUG zulip:        receiving error: &errors.errorString{s:"Error was unknown"}
[0001] DEBUG slack:        Start listening for Slack messages
[0001] DEBUG zulip:        receiving error: &errors.errorString{s:"Error was unknown"}
[0001] DEBUG slack:        getting 40 users
[0061] DEBUG zulip:        receiving error: &errors.errorString{s:"Error was unknown"}
[0062] DEBUG zulip:        receiving error: &errors.errorString{s:"Error was unknown"}
...

(duplicated or similar lines has been stripped)

With a config file looking like :

[zulip]
[zulip.myzulip]
Token="XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX"
Login="[email protected]"
Server="https://xxxxxx.com"
RemoteNickFormat="[{PROTOCOL}] <{NICK}> "

[slack]
[slack.myslack]
Token="xoxb-XXXXXXXXXX-XXXXXXXXXXXX-XXXXXXXXXXXXXXXXXXXXXXXX"
RemoteNickFormat="{BRIDGE} - @{NICK}"

[[gateway]]
name="stream-name"
enable=true

[[gateway.inout]]
account="zulip.myzulip"
channel="stream-name/topic:slack"

[[gateway.inout]]
account="slack.myslack"
channel="ID:XXXXXXXXX"

On Zulip side (self-hosted v2.1.4), I see some successfull requests (status 200) from matterbridge on these endpoints :

POST /api/v1/register HTTP/2.0
GET /api/v1/streams HTTP/2.0

But many 400 (Bad Request) on requests like :

GET /api/v1/events?last_event_id=113&queue_id=1588007974%3A7 HTTP/2.0

Also many 429 (too many requests) if i don't disable zulip's rate limiting

nicph picture nicph on 27 Apr 2020

To complete my comment, here is (a prettified&cleaned version of) what i get with tcpdump on zulip side. This sequence begins when i start matterbridge, and continues up to the first 400-response :

POST /api/v1/register HTTP/1.1
event_types=["message"]&all_public_streams=true

response:
HTTP/1.1 200 OK
{
    "last_event_id": -1,
    "max_message_id": 113,
    "msg": "",
    "queue_id": "1588011382:81",
    "result": "success"
}

GET /api/v1/streams HTTP/1.1

response:
HTTP/1.1 200 OK
{
    "msg": "",
    "result": "success",
    "streams": [
        {
            "description": "Everyone is added to this stream by default. Welcome! :octopus:",
            "first_message_id": 8,
            "history_public_to_subscribers": true,
            "invite_only": false,
            "is_announcement_only": false,
            "is_web_public": false,
            "name": "general",
            "rendered_description": "<p>Everyone is added to this stream by default. Welcome! <span aria-label=\"octopus\" class=\"emoji emoji-1f419\" role=\"img\" title=\"octopus\">:octopus:</span></p>",
            "stream_id": 1
        },
        {
            "description": "",
            "first_message_id": 13,
            "history_public_to_subscribers": true,
            "invite_only": false,
            "is_announcement_only": false,
            "is_web_public": false,
            "name": "random",
            "rendered_description": "",
            "stream_id": 4
        }
    ]
}

GET /api/v1/events?last_event_id=113&queue_id=1588011382%3A81 HTTP/1.1

response:
HTTP/1.1 400 Bad Request
{
    "code": "BAD_REQUEST",
    "msg": "Event 113 was not in this queue",
    "result": "error"
}

Could it be related to this change in zulip : https://github.com/zulip/zulip/commit/86a7fdddd7776cc225f888f30f040524274ac24b ?

nicph picture nicph on 28 Apr 2020

To complete my comment, here is (a prettified&cleaned version of) what i get with tcpdump on zulip side. This sequence begins when i start matterbridge, and continues up to the first 400-response :

POST /api/v1/register HTTP/1.1
event_types=["message"]&all_public_streams=true

response:
HTTP/1.1 200 OK
{
    "last_event_id": -1,
    "max_message_id": 113,
    "msg": "",
    "queue_id": "1588011382:81",
    "result": "success"
}

GET /api/v1/streams HTTP/1.1

response:
HTTP/1.1 200 OK
{
    "msg": "",
    "result": "success",
    "streams": [
        {
            "description": "Everyone is added to this stream by default. Welcome! :octopus:",
            "first_message_id": 8,
            "history_public_to_subscribers": true,
            "invite_only": false,
            "is_announcement_only": false,
            "is_web_public": false,
            "name": "general",
            "rendered_description": "<p>Everyone is added to this stream by default. Welcome! <span aria-label=\"octopus\" class=\"emoji emoji-1f419\" role=\"img\" title=\"octopus\">:octopus:</span></p>",
            "stream_id": 1
        },
        {
            "description": "",
            "first_message_id": 13,
            "history_public_to_subscribers": true,
            "invite_only": false,
            "is_announcement_only": false,
            "is_web_public": false,
            "name": "random",
            "rendered_description": "",
            "stream_id": 4
        }
    ]
}

GET /api/v1/events?last_event_id=113&queue_id=1588011382%3A81 HTTP/1.1

response:
HTTP/1.1 400 Bad Request
{
    "code": "BAD_REQUEST",
    "msg": "Event 113 was not in this queue",
    "result": "error"
}

Could it be related to this change in zulip : zulip/zulip@86a7fdd ?

It is possibly https://github.com/zulip/zulip/commit/86a7fdddd7776cc225f888f30f040524274ac24b#diff-52b98ee8e21b7e156f3b6ad3f793a710R542 as the error definitely stems from https://github.com/zulip/zulip/commit/86a7fdddd7776cc225f888f30f040524274ac24b#diff-52b98ee8e21b7e156f3b6ad3f793a710R546
If you want an alternative solution, take a look at https://zulipchat.com/integrations/doc/slack and build your own solution. ¯_(ツ)_/¯

QEDK picture QEDK on 29 Apr 2020

Hi I have a similar issue in a Zulip / Slack gateway. matterbridge version is 1.17.5. When Slack sends a message to Zulip it is fine but the other way around get a bunch of [handleQueue:bridge/zulip/zulip.go:127] receiving error: &errors.errorString{s:"Error was unknown"}
in matterbridge debug output and in Zulip tornado log:

2020-06-13 16:17:03.016 INFO [zr] status=400, data=b'{"result":"error","msg":"Event 54 was not in this queue","code":"BAD_REQUEST"}\n', [email protected]
2020-06-13 16:17:03.021 INFO [zr] 127.0.0.1       GET     400   2ms /api/v1/events ([email protected] via Go-http-client)

Now it seems this only occurs when the zulip sender is not the owner of the zulip bot.

delahondes picture delahondes on 13 Jun 2020

To further explicit my bug, here are larger extracts of the logs:

[0058] DEBUG zulip:        [handleQueue:bridge/zulip/zulip.go:147] <= Message is config.Message{Text:"test 15", Channel:"clients/topic:gv", Username:"Raynald de Lahondès", UserID:"9", Avatar:"https://secure.gravatar.com/avatar/96776765d2baf0eb597138f88ca75424?d=identicon&version=1", Account:"zulip.gv", Event:"", Protocol:"", Gateway:"", ParentID:"", Timestamp:time.Time{wall:0x0, ext:0, loc:(*time.Location)(nil)}, ID:"", Extra:map[string][]interface {}(nil)}
[0058] DEBUG gateway:      [SendMessage:gateway/gateway.go:421] => Sending config.Message{Text:"test 15", Channel:"clients/topic:gv", Username:"Raynald de Lahondès", UserID:"9", Avatar:"https://secure.gravatar.com/avatar/96776765d2baf0eb597138f88ca75424?d=identicon&version=1", Account:"zulip.gv", Event:"", Protocol:"zulip", Gateway:"gvgw", ParentID:"", Timestamp:time.Time{wall:0xbfb15cdefb2a295f, ext:58697495122, loc:(*time.Location)(0x311d640)}, ID:"", Extra:map[string][]interface {}(nil)} from zulip.gv (clients/topic:gv) to slack.myslack (bio-it)
[0058] DEBUG slack:        [Send:bridge/slack/slack.go:195] => Receiving config.Message{Text:"test 15", Channel:"XXXX", Username:"gv - @Raynald de Lahondès", UserID:"9", Avatar:"https://secure.gravatar.com/avatar/96776765d2baf0eb597138f88ca75424?d=identicon&version=1", Account:"zulip.gv", Event:"", Protocol:"zulip", Gateway:"gvgw", ParentID:"", Timestamp:time.Time{wall:0xbfb15cdefb2a295f, ext:58697495122, loc:(*time.Location)(0x311d640)}, ID:"", Extra:map[string][]interface {}(nil)}
[0058] DEBUG slack:        [handleSlackClient:bridge/slack/handlers.go:52] == Receiving event &slack.MessageEvent{Msg:slack.Msg{ClientMsgID:"", Type:"message", Channel:"XXXX", User:"", Text:"test 15", Timestamp:"1592065020.048200", ThreadTimestamp:"", IsStarred:false, PinnedTo:[]string(nil), Attachments:[]slack.Attachment(nil), Edited:(*slack.Edited)(nil), LastRead:"", Subscribed:false, UnreadCount:0, SubType:"bot_message", Hidden:false, DeletedTimestamp:"", EventTimestamp:"1592065020.048200", BotID:"XXXX", Username:"gv - @Raynald de Lahondès", Icons:(*slack.Icon)(0xc00000db40), Inviter:"", Topic:"", Purpose:"", Name:"", OldName:"", Members:[]string(nil), ReplyCount:0, Replies:[]slack.Reply(nil), ParentUserId:"", Files:[]slack.File(nil), Upload:false, Comment:(*slack.Comment)(nil), ItemType:"", ReplyTo:0, Team:"XXXX", Reactions:[]slack.ItemReaction(nil), ResponseType:"", ReplaceOriginal:false, DeleteOriginal:false, Blocks:slack.Blocks{BlockSet:[]slack.Block{(*slack.SectionBlock)(0xc00039ca00)}}}, SubMessage:(*slack.Msg)(nil), PreviousMessage:(*slack.Msg)(nil)}
[0058] DEBUG slack:        [handleSlackClient:bridge/slack/handlers.go:70] Skipped message: &slack.MessageEvent{Msg:slack.Msg{ClientMsgID:"", Type:"message", Channel:"XXXX", User:"", Text:"test 15", Timestamp:"1592065020.048200", ThreadTimestamp:"", IsStarred:false, PinnedTo:[]string(nil), Attachments:[]slack.Attachment(nil), Edited:(*slack.Edited)(nil), LastRead:"", Subscribed:false, UnreadCount:0, SubType:"bot_message", Hidden:false, DeletedTimestamp:"", EventTimestamp:"1592065020.048200", BotID:"XXXX", Username:"gv - @Raynald de Lahondès", Icons:(*slack.Icon)(0xc00000db40), Inviter:"", Topic:"", Purpose:"", Name:"", OldName:"", Members:[]string(nil), ReplyCount:0, Replies:[]slack.Reply(nil), ParentUserId:"", Files:[]slack.File(nil), Upload:false, Comment:(*slack.Comment)(nil), ItemType:"", ReplyTo:0, Team:"XXXX", Reactions:[]slack.ItemReaction(nil), ResponseType:"", ReplaceOriginal:false, DeleteOriginal:false, Blocks:slack.Blocks{BlockSet:[]slack.Block{(*slack.SectionBlock)(0xc00039ca00)}}}, SubMessage:(*slack.Msg)(nil), PreviousMessage:(*slack.Msg)(nil)}
[0058] DEBUG gateway:      [SendMessage:gateway/gateway.go:464] mID slack.myslack: 1592065020.048200
[0061] DEBUG zulip:        [handleQueue:bridge/zulip/zulip.go:127] receiving error:  &errors.errorString{s:"Error was unknown"}
[...same error repeating...]
[0061] DEBUG zulip:        [handleQueue:bridge/zulip/zulip.go:127] receiving error: &errors.errorString{s:"Error was unknown"}

And zulip log during same period:

2020-06-13 16:16:55.617 INFO [] Tornado 9993   0.2% busy over the past 60.0 seconds2020-06-13 16:16:56.978 INFO [zr] 127.0.0.1       GET     200   5ms /api/v1/events [1591898320:333/1/message] ([email protected] via Go-http-client)
2020-06-13 16:16:57.446 INFO [zr] 90.23.172.51     GET     200   4ms (lp: 26.4s) /json/events [1591898320:328/1/message] ([email protected] via website)
2020-06-13 16:16:57.447 INFO [zr] 90.23.172.51     GET     200   3ms (lp: 6.7s) /json/events [1591898320:327/1/message] ([email protected] via website)
2020-06-13 16:16:57.449 INFO [zr] 90.23.172.51     SOCKET  200   1ms (lp: 25ms) /socket/service_request [transport=websocket, queue_delay: 3ms/3ms, service_time: 18ms] ([email protected] via ?)
2020-06-13 16:16:59.989 INFO [zr] 127.0.0.1       GET     200   5ms /api/v1/events [1591898320:333/2] ([email protected] via Go-http-client)
2020-06-13 16:17:01.617 INFO [] Tornado 9993   0.3% busy over the past 59.0 seconds
2020-06-13 16:17:02.999 INFO [zr] 127.0.0.1       GET     400   3ms /api/v1/events ([email protected] via Go-http-client)
2020-06-13 16:17:03.000 INFO [zr] status=400, data=b'{"result":"error","msg":"Event 54 was not in this queue","code":"BAD_REQUEST"}\n', [email protected] 
2020-06-13 16:17:03.005 INFO [zr] 127.0.0.1       GET     400   3ms /api/v1/events ([email protected] via Go-http-client)
[...same two lines repeating...]
2020-06-13 16:17:03.038 INFO [zr] 127.0.0.1       GET     400   2ms /api/v1/events ([email protected] via Go-http-client)
2020-06-13 16:17:03.039 INFO [zr] status=400, data=b'{"result":"error","msg":"Event 54 was not in this queue","code":"BAD_REQUEST"}\n', [email protected]

Looking in go code: in bridge/zulip/zulip.go, I see that this particular error is not properly trapped just as 'Unknown error' and that lead to an immediate retry which is not apropriate in that case. This seems to come from this: vendor/github.com/matterbridge/gozulipbot/queue.go, on function "GetEvents" line 137 and further down to "ParseError" line 190. It look faisible to correctly catch this type of error. Unfortunately I am not a go programmer and I do not know in that context if we can reset the q.LastEventID that seems to be sent by RawGetEvents (same piece of code, line 175) to some default sensible value when actual value is rejected by Zulip.

delahondes picture delahondes on 14 Jun 2020

Possibly Zulip->* bridges are affected but just retitling it to Zulip->IRC/Slack for now.

QEDK picture QEDK on 14 Jun 2020

Another detail which is not really good news: this is unstable, sometimes it works, sometimes not, so I think really the good way to go is primarily not to retry too much the getevent loop and to reset it at some point. When relaunching matterbridge, first sending is always ok.

delahondes picture delahondes on 16 Jun 2020

Unfortunately the library (https://github.com/ifo/gozulipbot) matterbridge uses hasn't seen any updates for a long time.
And no other Go projects that have zulip protocol implement.

If you don't know Go but are good in another language you can always try to make a better bridge in another language using the matterbridge API (https://github.com/42wim/matterbridge/wiki/Api)

42wim picture 42wim on 28 Jun 2020

Alternative solution for now is to use https://github.com/zulip/python-zulip-api/tree/master/zulip/integrations/bridge_with_irc or https://github.com/zulip/python-zulip-api/tree/master/zulip/integrations/bridge_with_matrix. I have used the IRC<->Zulip bridge for a while, but only am using the old version of Matrix<->Zulip bridge in julialang.zulipchat.com. In the new version of the Matrix<->Zulip bridge, I discovered this bug: https://github.com/zulip/python-zulip-api/issues/612.

rht picture rht on 3 Aug 2020

The gozulipbot author, @ifo had kindly fixed the getEvents bug (see https://github.com/ifo/gozulipbot/issues/2). I tested the latest master of https://github.com/ifo/gozulipbot after patching these errors

bridge/zulip/zulip.go:62:18: b.bot.UpdateMessage undefined (type *gozulipbot.Bot has no field or method UpdateMessage)
bridge/zulip/zulip.go:78:18: b.bot.UpdateMessage undefined (type *gozulipbot.Bot has no field or method UpdateMessage)
bridge/zulip/zulip.go:90:23: b.bot.GetRawStreams undefined (type *gozulipbot.Bot has no field or method GetRawStreams)
bridge/zulip/zulip.go:110:8: undefined: gozulipbot.NoJSONError
bridge/zulip/zulip.go:113:8: undefined: gozulipbot.BadEventQueueError
bridge/zulip/zulip.go:141:29: m.StreamID undefined (type gozulipbot.EventMessage has no field or method StreamID)

using https://github.com/42wim/matterbridge/tree/master/vendor/github.com/matterbridge/gozulipbot as a reference.

Messages from IRC are being correctly relayed to Zulip, but still not the other way around.

Maybe @42wim can test the bugfixes better than me.

rht picture rht on 10 Aug 2020

Hey, just wanted to say that we are experimenting the same errors for Zulip to Gitter, I don't know if that's useful, but you might want to update the issue title.

vigoux picture vigoux on 10 Aug 2020

Hey, just wanted to say that we are experimenting the same errors for Zulip to Gitter, I don't know if that's useful, but you might want to update the issue title.

Done.

Alternative solution for now is to use https://github.com/zulip/python-zulip-api/tree/master/zulip/integrations/bridge_with_irc or https://github.com/zulip/python-zulip-api/tree/master/zulip/integrations/bridge_with_matrix. I have used the IRC<->Zulip bridge for a while, but only am using the old version of Matrix<->Zulip bridge in julialang.zulipchat.com. In the new version of the Matrix<->Zulip bridge, I discovered this bug: zulip/python-zulip-api#612.

Indeed, that's what I'm doing. It works fine but it has a few quirks with AioReactor and reconnecting strategies. I rewrote it for my project here: https://github.com/QEDK/goodbot/blob/master/bots/ircbot.py

QEDK picture QEDK on 11 Aug 2020

Indeed, that's what I'm doing. It works fine but it has a few quirks with AioReactor and reconnecting strategies. I rewrote it for my project here: https://github.com/QEDK/goodbot/blob/master/bots/ircbot.py

@QEDK can you push your fixes to upstream https://github.com/zulip/python-zulip-api so that it can better benefit everyone?

rht picture rht on 11 Aug 2020
👍1

@rht I've just merged the upstream fixes in matterbridge, could you retry master?

42wim picture 42wim on 21 Aug 2020

@42wim I just tested on current master. Only works once (i.e. message being relayed Zulip -> IRC only once), then subsequent messages are not relayed. IRC -> Zulip works flawlessly. So the issue remains unsolved.

I noticed that https://github.com/matterbridge/gozulipbot hasn't been updated yet? Did you only update the vendor dir inside https://github.com/42wim/matterbridge/tree/master/vendor ?

rht picture rht on 21 Aug 2020

@rht you're barking at the wrong branch ;-)
https://github.com/matterbridge/gozulipbot/tree/work is the one matterbridge uses

42wim picture 42wim on 21 Aug 2020

Indeed, that's what I'm doing. It works fine but it has a few quirks with AioReactor and reconnecting strategies. I rewrote it for my project here: https://github.com/QEDK/goodbot/blob/master/bots/ircbot.py

@QEDK can you push your fixes to upstream https://github.com/zulip/python-zulip-api so that it can better benefit everyone?

Will do.

QEDK picture QEDK on 21 Aug 2020

@rht should be fixed in master now, I can't reproduce it anymore.

42wim picture 42wim on 25 Aug 2020
🎉2

Confirmed, it works now! Thank you for finally fixing this!

rht picture rht on 25 Aug 2020
🎉1
Was this page helpful?
0 / 5 - 0 ratings

Related issues

patcon picture patcon  ·  4Comments
benrob0329 picture benrob0329  ·  3Comments
Wouter0100 picture Wouter0100  ·  4Comments
cwchristerw picture cwchristerw  ·  6Comments
jheiselman picture jheiselman  ·  4Comments