Synapse: AS incoming events are not forwarded from Synapse to AS daemon port

[MurzNN]

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?

[t3chguy]

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]

@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]

Or you add it to the regex I believe

[tulir]

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]

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

[MurzNN]

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]

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]

(this isn't a synapse bug)

[tulir]

@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]

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...

[MurzNN]

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 https://github.com/matrix-org/synapse/issues/5957#issuecomment-526915357

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]

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]

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

[MurzNN]

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 :(

[MurzNN]

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

[juhovan]

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]

https://github.com/matrix-org/synapse/issues/4143 and https://github.com/matrix-org/synapse/issues/4310 ?

[MurzNN]

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]

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]

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]

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]

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?

[viwainvestgmbh]

Did you ever solve this?

[MurzNN]

No, problem is still here on last Synapse :(

[kindlyfire]

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

[viwainvestgmbh]

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

[viwainvestgmbh]

AMEN! I was able to fix it:
https://github.com/matrix-org/synapse/issues/1834

[richvdh]

so is this a duplicate of #1834?