Skip to content
This repository has been archived by the owner on Apr 26, 2024. It is now read-only.

AS incoming events are not forwarded from Synapse to AS daemon port #5957

Closed
MurzNN opened this issue Sep 1, 2019 · 34 comments
Closed

AS incoming events are not forwarded from Synapse to AS daemon port #5957

MurzNN opened this issue Sep 1, 2019 · 34 comments
Labels
A-Application-Service Related to AS support T-Other Questions, user support, anything else. X-Needs-Info This issue is blocked awaiting information from the reporter z-question (Deprecated Label)

Comments

@MurzNN
Copy link

MurzNN commented Sep 1, 2019

I have problem, that Synapse 1.3.1 don't forward events to AS bot - try with two AS daemons - mautrix-whatsapp, and matrix-rocketchat.

In registration.yaml I have sender_localpart: whatsappbot, this means that all events to @whatsappbot:myhomeserver.org must be redirected to configured url: http://localhost:29318 automatically?

I create new room with this user, post messages to it, but see no events in mautrix-whatsapp service debug logs.

But port 29318 is open and I can telnet to it from synapse daemon user successfully.

Communication from AS side to Synapse works well, bridge was successfully changing user names to string from config file, here are events in logs:

2019-09-01 11:37:57,629 - synapse.config.appservice - 86 - INFO - None- Loaded application service: ApplicationService: {'token': '<redacted>', 'url': 'http://localhost:29318', 'hs_token': '<redacted>', 'sender': '@whatsappbot:ru-matrix.org', 'server_name': 'ru-matrix.org', 'namespaces': {'users': [{'regex': re.compile('^@whatsapp_[0-9]+:ru-matrix.org$'), 'exclusive': True}], 'aliases': [], 'rooms': []}, 'id': 'whatsapp', 'ip_range_whitelist': None, 'protocols': set(), 'rate_limited': False}
...
2019-09-01 11:39:58,918 - synapse.access.http.8008 - 302 - INFO - PUT-583- - - 8008 - {@whatsappbot:ru-matrix.org} Processed request: 0.027sec/0.001sec (0.004sec, 0.002sec) (0.003sec/0.015sec/7) 2B 200 "PUT /_matrix/client/r0/profile/@whatsappbot:ru-matrix.org/displayname?user_id=%40whatsappbot%3Aru-matrix.org HTTP/1.1" "mautrix-go v0.1.0" [0 dbevts]

and when I change as_token and hs_token to bad values, see errors in logs.

Can you please describe, how forwarding event to AS daemon processes (and all other AS talks) are represented in Synapse logs, for filter out it from many log records? And why in our server events are not forwarded to AS? Is this a Synapse bug?

@MurzNN MurzNN changed the title AS events are not forwarded to AS daemon AS incoming events are not forwarded from Synapse to AS daemon port Sep 1, 2019
@t3chguy
Copy link
Member

t3chguy commented Sep 1, 2019

In registration.yaml I have sender_localpart: whatsappbot , this means that all events to @whatsappbot :myhomeserver.org must be redirected to configured url: http://localhost:29318 automatically?

Nope, it only forwards messages for users matching the regex you specify in users regexes

@MurzNN
Copy link
Author

MurzNN commented Sep 1, 2019

@t3chguy thanks, so events to sender_localpart Matrix user must be handled on AS side manually, without auto-forwarding via Synapse? So AS daemon must listen them as regular matrix client, using standard client-server api, and hs_token for authorisation?

@t3chguy
Copy link
Member

t3chguy commented Sep 1, 2019

Or you add it to the regex I believe

@tulir
Copy link
Member

tulir commented Sep 1, 2019

Nope, it only forwards messages for users matching the regex you specify in users regexes

Empirically, that is not true (unless there's some recent change that doesn't apply to previously set up appservices?). All of my bridges default to <platform>bot as the sender_localpart with @<platform>_.+:server.name as the regex and all of them work fine.

@t3chguy
Copy link
Member

t3chguy commented Sep 1, 2019

Interesting, I retract my statements then. I must be misremembering my battles when writing AS's a year or so back

@MurzNN
Copy link
Author

MurzNN commented Sep 1, 2019

Looking at logs in other servers, all talks with AS sender part must be represented in logs via lines, containing AS id, for whatsapp id via something like:

2019-09-01 03:14:28,765 - synapse.http.client - 270 - INFO - as-sender-whatsapp-25- Sending request PUT http://mautrix-whatsapp:8080/transactions/2233?access_token=<redacted>
2019-09-01 03:14:29,093 - synapse.http.client - 295 - INFO - as-sender-whatsapp-25- Received response to PUT http://mautrix-whatsapp:8080/transactions/2233?access_token=<redacted>: 200

But on my Synapse instance there are no such lines in logs, grep 'as-sender-' /var/log/matrix-synapse/homeserver.log is empty.

@richvdh
Copy link
Member

richvdh commented Sep 2, 2019

Nope, it only forwards messages for users matching the regex you specify in users regexes

Empirically, that is not true (unless there's some recent change that doesn't apply to previously set up appservices?). All of my bridges default to bot as the sender_localpart with @_.+:server.name as the regex and all of them work fine.

I think you're both right? @MurzNN has to specify a regex matching @whatsappbot:myhomeserver.org if he wants to receive events for that user?

The code for determining which events to send to an AS starts here: https://github.com/matrix-org/synapse/blob/master/synapse/appservice/__init__.py#L223. Tracing it through is left as an exercise for the reader.

@richvdh
Copy link
Member

richvdh commented Sep 2, 2019

(this isn't a synapse bug)

@richvdh richvdh closed this as completed Sep 2, 2019
@tulir
Copy link
Member

tulir commented Sep 2, 2019

@MurzNN has to specify a regex matching @whatsappbot:myhomeserver.org if he wants to receive events for that user?

My point was I don't do that and my bridges work. I only have ^@whatsapp_[0-9]+:maunium.net$ in the user regexes in my registration and a private chat with @whatsappbot:maunium.net works fine.

The code for determining which events to send to an AS starts here: https://github.com/matrix-org/synapse/blob/master/synapse/appservice/__init__.py#L223. Tracing it through is left as an exercise for the reader.

https://github.com/matrix-org/synapse/blob/master/synapse/appservice/__init__.py#L244-L248 seems to be saying I'm right, specifically or user_id == self.sender

@richvdh
Copy link
Member

richvdh commented Sep 2, 2019

https://github.com/matrix-org/synapse/blob/master/synapse/appservice/__init__.py#L244-L248 seems to be saying I'm right, specifically or user_id == self.sender

oh right, yes. Hrm.

I still think this is probably a configuration error, but I don't immediately know what the problem is...

@richvdh richvdh reopened this Sep 2, 2019
@MurzNN
Copy link
Author

MurzNN commented Sep 2, 2019

I have configuration, near to default, and already try to comment out some specific features (rate limits, enable_metrics: False, metrics_port: 9092), so I can't understand which setting is prevent events forwarding to AS. Here is my config, excluding commented lines:

server_name: ru-matrix.org

registration_shared_secret: <redacted>
tls_certificate_path: "<redacted>"
tls_private_key_path: "<redacted>"

recaptcha_public_key: "<redacted>"
recaptcha_private_key: "<redacted>"
enable_registration_captcha: True

enable_registration: True

turn_uris: [ "turn:ru-matrix.org:3478?transport=udp", "turn:ru-matrix.ru:3478?transport=tcp" ]
turn_shared_secret: <redacted>
turn_user_lifetime: 86400000
turn_allow_guests: True

database:
    name: psycopg2
    args:
        user: <redacted>
        password: <redacted>
        database: <redacted>
        host: localhost
        cp_min: 5
        cp_max: 10

enable_group_creation: true

url_preview_enabled: True

url_preview_ip_range_blacklist:
 - '127.0.0.0/8'
 - '10.0.0.0/8'
 - '172.16.0.0/12'
 - '192.168.0.0/16'
 - '100.64.0.0/10'
 - '169.254.0.0/16'


enable_metrics: True

mau_stats_only: True

notify_appservices: True

app_service_config_files:
 - "/etc/matrix-synapse/as/mautrix-whatsapp_registration.yaml"

cleanup_extremities_with_dummy_events: True

and AS config mautrix-whatsapp_registration.yaml

id: whatsapp
url: http://localhost:29318
as_token: <redacted>
hs_token: <redacted>
sender_localpart: whatsappbot
rate_limited: false
namespaces:
  users:
  - regex: ^@whatsapp_[0-9]+:ru-matrix.org$
    exclusive: true

After restarting Synapse I see, that AS is initialized successfully:

2019-09-01 11:37:57,629 - synapse.config.appservice - 86 - INFO - None- Loaded application service: ApplicationService: {'token': '<redacted>', 'url': 'http://localhost:29318', 'hs_token': '<redacted>', 'sender': '@whatsappbot:ru-matrix.org', 'server_name': 'ru-matrix.org', 'namespaces': {'users': [{'regex': re.compile('^@whatsapp_[0-9]+:ru-matrix.org$'), 'exclusive': True}], 'aliases': [], 'rooms': []}, 'id': 'whatsapp', 'ip_range_whitelist': None, 'protocols': set(), 'rate_limited': False}

But when I create new room with @whatsappbot:ru-matrix.org and send messages to it, I see no transactions/ records in Synapse logs, like in #5957 (comment)

Even when AS daemon is totally dead and not responding, Synapse must inform about failed transaction queries to AS host:port in logs, yes?

@MurzNN
Copy link
Author

MurzNN commented Sep 3, 2019

If I try to start chat from other homeserver to @whatsappbot:ru-matrix.org - I see profile info and invite events in logs:

2019-09-03 14:16:12,873 - synapse.access.http.8008 - 233 - INFO - GET-162744- 94.237.60.124 - 8008 - Received request: GET /_matrix/federation/v1/query/profile?user_id=%40whatsappbot%3Aru-matrix.org&field=avatar_url
2019-09-03 14:16:12,877 - synapse.access.http.8008 - 302 - INFO - GET-162744- 94.237.60.124 - 8008 - {matrix.org} Processed request: 0.004sec/0.000sec (0.001sec, 0.000sec) (0.001sec/0.001sec/1) 60B 200 "GET /_matrix/federation/v1/query/profile?user_id=%40whatsappbot%3Aru-matrix.org&field=avatar_url HTTP/1.0" "Synapse/1.3.1 (b=matrix-org-hotfixes,b272e7345)" [0 dbevts]
2019-09-03 14:16:12,911 - synapse.access.http.8008 - 233 - INFO - PUT-162745- 94.237.60.124 - 8008 - Received request: PUT /_matrix/federation/v2/invite/%21NAuiSZlljbFlLdAdsD%3Amatrix.org/%24G3dsG0NeFGyWyh_8gXCwg1BKzAk7XXKr94EYaAIqf2Y
2019-09-03 14:16:12,949 - synapse.access.http.8008 - 302 - INFO - PUT-162745- 94.237.60.124 - 8008 - {matrix.org} Processed request: 0.037sec/0.000sec (0.002sec, 0.000sec) (0.001sec/0.005sec/3) 1428B 200 "PUT /_matrix/federation/v2/invite/%21NAuiSZlljbFlLdAdsD%3Amatrix.org/%24G3dsG0NeFGyWyh_8gXCwg1BKzAk7XXKr94EYaAIqf2Y HTTP/1.0" "Synapse/1.3.1 (b=matrix-org-hotfixes,b272e7345)" [0 dbevts]

but no other AS-related events :(

@MurzNN
Copy link
Author

MurzNN commented Sep 5, 2019

Maybe I enable some verbose logging in Synapse, for find source of this problem?

@MurzNN
Copy link
Author

MurzNN commented Sep 6, 2019

Same problem when I try to create new room with regex matched user, eg @whatsapp_123:ru-matrix.org

  • in logs I see only:
2019-09-06 11:48:55,018 - synapse.storage.events - 462 - INFO - persist_events-86595- Calculating state delta for room !INqIqiSdOkhiuiMuvu:ru-matrix.org
2019-09-06 11:48:55,147 - synapse.storage.events - 462 - INFO - persist_events-86597- Calculating state delta for room !INqIqiSdOkhiuiMuvu:ru-matrix.org
2019-09-06 11:48:55,243 - synapse.storage.events - 462 - INFO - persist_events-86598- Calculating state delta for room !INqIqiSdOkhiuiMuvu:ru-matrix.org
2019-09-06 11:48:55,334 - synapse.storage.events - 462 - INFO - persist_events-86599- Calculating state delta for room !INqIqiSdOkhiuiMuvu:ru-matrix.org
2019-09-06 11:48:55,391 - synapse.storage.events - 462 - INFO - persist_events-86600- Calculating state delta for room !INqIqiSdOkhiuiMuvu:ru-matrix.org
2019-09-06 11:48:55,504 - synapse.storage.events - 462 - INFO - persist_events-86601- Calculating state delta for room !INqIqiSdOkhiuiMuvu:ru-matrix.org
2019-09-06 11:48:55,571 - synapse.storage.events - 462 - INFO - persist_events-86602- Calculating state delta for room !INqIqiSdOkhiuiMuvu:ru-matrix.org
2019-09-06 11:48:55,589 - synapse.handlers.sync - 1473 - INFO - GET-1700107- Membership changes in !INqIqiSdOkhiuiMuvu:ru-matrix.org: [$Z5Z_a0ys1kD4z1DAxjW4QHcay2zVYXNxbOoO31dDs2k (join)]
2019-09-06 11:48:55,596 - synapse.handlers.sync - 1473 - INFO - GET-1700108- Membership changes in !INqIqiSdOkhiuiMuvu:ru-matrix.org: [$Z5Z_a0ys1kD4z1DAxjW4QHcay2zVYXNxbOoO31dDs2k (join)]
2019-09-06 11:48:55,547 - synapse.handlers.message - 348 - INFO - POST-1700111- Failed to get profile information for @whatsapp_123:ru-matrix.org: 404: Profile was not found

and no new events sent to AS daemon :(

@neilisfragile neilisfragile added the z-question (Deprecated Label) label Sep 13, 2019
@MurzNN
Copy link
Author

MurzNN commented Sep 18, 2019

@neilisfragile this is not a question, this is a Synapse issue, that break all AS (bridges) on our server :(

@juhovan
Copy link
Contributor

juhovan commented Sep 18, 2019

Might not be useful in this case but I had the same exact problem when referencing appservice-irc running in another container by the container name in appservice registration file.
After I changed the container name to it's IP address everything works but it'll of course break when the container is assigned another address.

Testing the url with another container's name with curl in synapse container works as one would expect.

@ma1uta
Copy link

ma1uta commented Sep 18, 2019

#4143 and #4310 ?

@MurzNN
Copy link
Author

MurzNN commented Oct 3, 2019

Replacing appservice url from name (localhost) to IP (127.0.0.1) not help. Upgrading to Synapse 1.4 not help too with solving this bug :(

@MurzNN
Copy link
Author

MurzNN commented Oct 24, 2019

Same problem with mautrix-telegram bridge - bridge daemon listen on port successfully, but don't receive any event from Synapse, and there are no /transactions/ records in logs :(

@MurzNN MurzNN closed this as completed Oct 24, 2019
@MurzNN MurzNN reopened this Oct 24, 2019
@MurzNN
Copy link
Author

MurzNN commented Oct 25, 2019

I tried to move synapse.app.appservice to separate worker, as @turt2live suggested, but this isn't help, it starts well, but don't see any events for forward to AS daemons, here is logs

2019-10-24 21:23:41,621 - synapse.replication.tcp.client - 224 - INFO - replication-POSITION-2- Finished connecting to server
2019-10-24 21:23:51,558 - synapse.storage.TIME - 391 - INFO - - Total database time: 0.034% {check_background_updates(1): 0.034%}
2019-10-24 21:24:01,558 - synapse.storage.TIME - 391 - INFO - - Total database time: 0.000% {check_background_updates(0): 0.000%}
2019-10-24 21:24:11,558 - synapse.storage.TIME - 391 - INFO - - Total database time: 0.000% {check_background_updates(0): 0.000%}
2019-10-24 21:24:12,105 - synapse.metrics - 462 - INFO - - Collecting gc 1
2019-10-24 21:24:21,558 - synapse.storage.TIME - 391 - INFO - - Total database time: 0.519% {get_new_events_for_appservice(38): 0.519%, check_background_updates(0): 0.000%}
2019-10-24 21:24:31,558 - synapse.storage.TIME - 391 - INFO - - Total database time: 0.000% {get_new_events_for_appservice(0): 0.000%, check_background_updates(0): 0.000%}
2019-10-24 21:24:41,558 - synapse.storage.TIME - 391 - INFO - - Total database time: 0.000% {get_new_events_for_appservice(0): 0.000%, check_background_updates(0): 0.000%}
2019-10-24 21:24:51,558 - synapse.storage.TIME - 391 - INFO - - Total database time: 0.267% {get_new_events_for_appservice(29): 0.267%, check_background_updates(0): 0.000%}
2019-10-24 21:24:52,918 - synapse.metrics - 462 - INFO - - Collecting gc 1
2019-10-24 21:25:01,558 - synapse.storage.TIME - 391 - INFO - - Total database time: 0.046% {get_new_events_for_appservice(4): 0.046%, check_background_updates(0): 0.000%}

So I go to lookup into SQL database tables, related to appservices, and see that all of them are empty: application_services_state, application_services_txns, appservice_room_list, appservice_stream_position. What else tables are related to appservice in synapse db?

As I understand, if appservice is activated, it must be added, at least, to application_services_state table - why in my setup it not added? I see no errors about this in synapse logs, only that appservice is initiated successfully:

2019-10-24 21:26:17,559 - synapse.config.appservice - 86 - INFO - None- Loaded application service: ApplicationService: {'token': '<redacted>', 'url': 'http://127.0.0.1:29318', 'hs_token': '<redacted>', 'sender': '@whatsappbot:ru-matrix.org', 'server_name': 'ru-matrix.org', 'namespaces': {'users': [{'regex': re.compile('^@whatsapp_[0-9]+:ru-matrix.org$'), 'exclusive': True}], 'aliases': [], 'rooms': []}, 'id': 'whatsapp', 'ip_range_whitelist': None, 'protocols': set(), 'rate_limited': False}
2019-10-24 21:26:17,563 - synapse.config.appservice - 86 - INFO - None- Loaded application service: ApplicationService: {'token': '<redacted>', 'url': 'http://localhost:8822', 'hs_token': '<redacted>', 'sender': '@rocketchat:ru-matrix.org', 'server_name': 'ru-matrix.org', 'namespaces': {'users': [{'regex': re.compile('^@rocketchat_[0-9]+:ru-matrix.org$'), 'exclusive': True}], 'aliases': [], 'rooms': []}, 'id': 'matrix-rocketchat', 'ip_range_whitelist': None, 'protocols': set(), 'rate_limited': False}

I even try to add "whatsapp|up|0" record manually to application_services_state database table, but this not help.

How can I debug this process and find the source, why appservices on my Synapse are not inited successfully?

@MurzNN
Copy link
Author

MurzNN commented Oct 25, 2019

Regarding to https://github.com/matrix-org/synapse/blob/master/synapse/storage/appservice.py - set_appservice_state function must add records to application_services_state database, but I can't see where it called to do this: https://github.com/matrix-org/synapse/search?q=set_appservice_state&unscoped_q=set_appservice_state - there are only one call (excluding tests) in synapse/appservice/scheduler.py, but it only mark them as up/down, not insert new services. In which place of code Synapse adds new services to database?

And I even don't see in logs record about starting scheduler, regarding to https://github.com/matrix-org/synapse/blob/master/synapse/appservice/scheduler.py#L78 :

cat /var/log/matrix-synapse/homeserver.log* | grep 'Starting appservice scheduler'

is empty. Does anybody have ideas, why it is not starting and how to debug this?

@kindlyfire
Copy link

I have the same issue, or at least it seems like it is. I run an IRC bridge, and IRC -> Matrix works fine, but Matrix -> IRC doesn't. Synapse doesn't seem to forward anything at all to the IRC AppService.

Grepping for "transactions" in my log file (set to debug) yields nothing, but when starting Synapse it does say that the appservice was registered.

My AS configuration file is as follows:

id: <redacted>
hs_token: <redacted>
as_token: <redacted>
namespaces:
  users:
    - exclusive: true
      regex: '@irc_.*:urlab\.be'
  aliases: []
  rooms:
    - exclusive: false
      regex: '!SuwujUkrdTTWJfvbwc:urlab.be'
    - exclusive: false
      regex: '!vUqhyekkwkoPYXLMCp:urlab.be'
url: 'http://127.0.0.1:8009'
sender_localpart: urlab-matrix
rate_limited: false
protocols:
  - irc

When I curl http://127.0.0.1:8009, I can see the request in the logs of the appservice, so if Synapse were sending events correctly I should see them in the logs as well, yet nothing.

Is there any way I can help further debugging this issue?

@kajdun
Copy link

kajdun commented Apr 25, 2020

Did you ever solve this?

@MurzNN
Copy link
Author

MurzNN commented Apr 25, 2020

No, problem is still here on last Synapse :(

@kindlyfire
Copy link

Yup, still haven't been able to get it to work either.

@kajdun
Copy link

kajdun commented Apr 29, 2020

Bummer. This breaks all bridges on our server. Even setting loglevel to debug gives no clues of whats going wrong.

@kajdun
Copy link

kajdun commented May 1, 2020

AMEN! I was able to fix it:
#1834

@richvdh
Copy link
Member

richvdh commented Oct 20, 2020

so is this a duplicate of #1834?

@MadLittleMods
Copy link
Contributor

@MurzNN Do you think this is still an issue? Was this possibly solved by the PR's closing #1834?

@DMRobertson DMRobertson added the T-Other Questions, user support, anything else. label Nov 18, 2021
@richvdh richvdh added the X-Needs-Info This issue is blocked awaiting information from the reporter label Dec 20, 2021
@richvdh
Copy link
Member

richvdh commented Dec 22, 2021

I'm going to assume this is fixed. Let us know if not.

@richvdh richvdh closed this as completed Dec 22, 2021
@aggieben
Copy link

aggieben commented Jun 27, 2022

I have a problem very similar to this (unsure if it's exactly the same). I'm trying to write an AS, and when I first started I was getting transaction requests. The request would fail (the AS I'm writing is very much WIP), and I'd see logs emitted by the scheduler indicating increased waiting periods for trying again. But now I'm in a state where it doesn't even try, and I haven't been able to figure out how to make it try. #1834 isn't my issue as appservice_stream_position.event_ordering is the same as events.stream_ordering in my case.

Similarly to #5957 (comment), I also don't have a row in application_services_state for my AS, even though synapse does seem to recognize it at startup:

2022-06-27 00:16:34,137 - synapse.config.appservice - 90 - INFO - main - Loaded application service: ApplicationService: {'token': '<redacted>', 'url': 'http://localhost:5000', 'hs_token': '<redacted>', 'sender': '@neofarkas:cit.chat', 'namespaces': {'users': [Namespace(exclusive=True, regex=re.compile('neofarkas.*'))], 'aliases': [], 'rooms': []}, 'id': 'dc863c3be4a6b4eac0d881b2df244920', 'ip_range_whitelist': None, 'supports_ephemeral': False, 'msc3202_transaction_extensions': False, 'protocols': set(), 'rate_limited': True}

I haven't yet even figured out a way to begin troubleshooting, really.

@MadLittleMods
Copy link
Contributor

@aggieben Create a new issue 🙂

@aggieben
Copy link

@MadLittleMods The guidance I'm getting is confusing. The repo says to ask for support in the matrix channel rather than by filing an issue, which I have on three occasions and not gotten a response. Should I file a support issue anyway? To clarify, I suppose it's possible that my issue could be due to a bug, but I'm assuming it's operator error.

@MadLittleMods
Copy link
Contributor

MadLittleMods commented Jun 29, 2022

@aggieben Your explanation sounds valid for an issue. And it's bound to a separate new problem given this issue is from a year or two ago.

The Matrix channel is meant "for support installing or managing Synapse" which is more on the administering, configuring, and deploying side. While it could be a user error, it does sound like it's not working with no easy way to debug. And I've seen a couple other people run into a similar problem to you.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
A-Application-Service Related to AS support T-Other Questions, user support, anything else. X-Needs-Info This issue is blocked awaiting information from the reporter z-question (Deprecated Label)
Projects
None yet
Development

No branches or pull requests