search

kamax-matrix / mxisd

Federated Matrix Identity Server
GNU Affero General Public License v3.0
220 stars 112 forks source link

Request failed: 403 - M_FORBIDDEN - Appservice not in room #172

Closed NullIsNot0 closed 5 years ago

NullIsNot0 commented 5 years ago

Managed to set up new Mxisd AppSvc in version 1.4.2 (#171) to notify (by e-mail) corporate users about invitations to conversations. At first e-mail notifications worked well, but after about 2 hours they stopped working. I started to investigate and found out that there is a task with ID 39694 which fails to process. Found out first apperance of failing event in logs:

[XNIO-1 task-4] INFO io.kamax.mxisd.as.AppSvcManager - Processing AS Transaction 39694: start
[XNIO-1 task-4] INFO io.kamax.mxisd.as.AppSvcManager - Processing transaction events: start
[XNIO-1 task-4] INFO io.kamax.mxisd.as.processor.event.MembershipEventProcessor - Got membership event from @mgordx:mydomain.com to @mgordx:mydomain.com for room !GdPBNbLTeTdZSkTYGF:mydomain.com
2019-04-30 12:01:18,000 - synapse.access.http.8008 - 233 - INFO - GET-11884 - - - 8008 - Received request: GET /_matrix/client/r0/rooms/!GdPBNbLTeTdZSkTYGF:mydomain.com/joined_members
2019-04-30 12:01:18,002 - synapse.http.server - 85 - INFO - GET-11884 - <XForwardedForRequest at 0x7f69c3ad8d30 method='GET' uri='/_matrix/client/r0/rooms/!GdPBNbLTeTdZSkTYGF:mydomain.com/joined_members' clientproto='HTTP/1.1' site=8008> SynapseError: 403 - Appservice not in room
2019-04-30 12:01:18,002 - synapse.access.http.8008 - 302 - INFO - GET-11884 - - - 8008 - {@mxisd:mydomain.com} Processed request: 0.002sec/0.000sec (0.002sec, 0.000sec) (0.000sec/0.000sec/0) 58B 403 "GET /_matrix/client/r0/rooms/!GdPBNbLTeTdZSkTYGF:mydomain.com/joined_members HTTP/1.1" "okhttp/3.11.0" [0 dbevts]
2019-04-30 12:01:18,003 - synapse.metrics - 372 - INFO -  - Collecting gc 0
2019-04-30 12:01:18,009 - synapse.handlers.message - 613 - WARNING - POST-11863 - Denying new event <FrozenEvent event_id='$155662567730ngOYn:mydomain.com', type='m.room.history_visibility', state_key=''> because 403: User @mgordx:mydomain.com not in room !GdPBNbLTeTdZSkTYGF:mydomain.com (None)
[XNIO-1 task-4] ERROR io.kamax.mxisd.as.AppSvcManager - Unable to properly process transaction 39694
io.kamax.matrix.client.MatrixClientRequestException: Request failed: 403 - M_FORBIDDEN - Appservice not in room
at io.kamax.matrix.client.AMatrixHttpClient.handleError(AMatrixHttpClient.java:267)
at io.kamax.matrix.client.AMatrixHttpClient.execute(AMatrixHttpClient.java:217)
at io.kamax.matrix.client.AMatrixHttpClient.execute(AMatrixHttpClient.java:200)
at io.kamax.matrix.client.AMatrixHttpClient.executeAuthenticated(AMatrixHttpClient.java:191)
at io.kamax.matrix.client.MatrixHttpRoom.getJoinedUsers(MatrixHttpRoom.java:216)
at io.kamax.mxisd.as.processor.event.MembershipEventProcessor.process(MembershipEventProcessor.java:112)
at io.kamax.mxisd.as.AppSvcManager.lambda$processTransaction$0(AppSvcManager.java:282)
at java.util.ArrayList.forEach(ArrayList.java:1257)
at io.kamax.mxisd.as.AppSvcManager.processTransaction(AppSvcManager.java:252)
at io.kamax.mxisd.as.AppSvcManager.processTransaction(AppSvcManager.java:225)
at io.kamax.mxisd.http.undertow.handler.as.v1.AsTransactionHandler.handleRequest(AsTransactionHandler.java:43)
at io.kamax.mxisd.http.undertow.handler.SaneHandler.handleRequest(SaneHandler.java:71)
at io.undertow.server.Connectors.executeRootHandler(Connectors.java:360)
at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:830)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
[XNIO-1 task-4] INFO io.kamax.mxisd.as.AppSvcManager - Processing AS Transaction 39694: end
2019-04-30 12:01:18,009 - synapse.http.server - 85 - INFO - POST-11863 - <XForwardedForRequest at 0x7f69c399c5f8 method='POST' uri='/_matrix/client/r0/createRoom' clientproto='HTTP/1.0' site=8008> SynapseError: 403 - User @mgordx:mydomain.com not in room !GdPBNbLTeTdZSkTYGF:mydomain.com (None)
2019-04-30 12:01:18,012 - synapse.http.client - 295 - INFO - as-sender-appservice-mxisd-24 - Received response to PUT http://matrix-mxisd:8090/transactions/39694?access_token=<redacted>: 200
2019-04-30 12:01:18,013 - synapse.appservice.api - 249 - WARNING - as-sender-appservice-mxisd-24 - push_bulk to http://matrix-mxisd:8090/transactions/39694 threw exception Expecting value: line 1 column 1 (char 0)
[XNIO-1 task-4] ERROR io.undertow.request - UT005071: Undertow request failed HttpServerExchange{ PUT /transactions/39694 request {Accept-Encoding=[gzip], Content-Length=[1654], Content-Type=[application/json], User-Agent=[Synapse/0.99.3], Host=[matrix-mxisd:8090]} response {Connection=[keep-alive], Access-Control-Allow-Origin=[*], Access-Control-Allow-Headers=[Origin, X-Requested-With, Content-Type, Accept, Authorization], Content-Length=[0], Access-Control-Allow-Methods=[GET, POST, PUT, DELETE, OPTIONS], Date=[Tue, 30 Apr 2019 12:01:18 GMT]}}
java.util.concurrent.ExecutionException: io.kamax.matrix.client.MatrixClientRequestException: Request failed: 403 - M_FORBIDDEN - Appservice not in room
at java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:357)
at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1895)
at io.kamax.mxisd.http.undertow.handler.as.v1.AsTransactionHandler.handleRequest(AsTransactionHandler.java:43)
at io.kamax.mxisd.http.undertow.handler.SaneHandler.handleRequest(SaneHandler.java:71)
at io.undertow.server.Connectors.executeRootHandler(Connectors.java:360)
at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:830)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Caused by: io.kamax.matrix.client.MatrixClientRequestException: Request failed: 403 - M_FORBIDDEN - Appservice not in room
at io.kamax.matrix.client.AMatrixHttpClient.handleError(AMatrixHttpClient.java:267)
at io.kamax.matrix.client.AMatrixHttpClient.execute(AMatrixHttpClient.java:217)
at io.kamax.matrix.client.AMatrixHttpClient.execute(AMatrixHttpClient.java:200)
at io.kamax.matrix.client.AMatrixHttpClient.executeAuthenticated(AMatrixHttpClient.java:191)
at io.kamax.matrix.client.MatrixHttpRoom.getJoinedUsers(MatrixHttpRoom.java:216)

2019-04-30 12:01:18,028 - synapse.appservice.scheduler - 193 - INFO - as-sender-appservice-mxisd-24 - Application service falling behind. Starting recoverer. AS ID appservice-mxisd
2019-04-30 12:01:18,028 - synapse.appservice.scheduler - 182 - INFO - as-sender-appservice-mxisd-24 - New active recoverers: 1
at io.kamax.mxisd.as.processor.event.MembershipEventProcessor.process(MembershipEventProcessor.java:112)
at io.kamax.mxisd.as.AppSvcManager.lambda$processTransaction$0(AppSvcManager.java:282)
at java.util.ArrayList.forEach(ArrayList.java:1257)
at io.kamax.mxisd.as.AppSvcManager.processTransaction(AppSvcManager.java:252)
at io.kamax.mxisd.as.AppSvcManager.processTransaction(AppSvcManager.java:225)
... 7 more

And from now on these lines frequently appear in mxisd log:

Apr 30 15:43:56 srv-matrix-riot docker[32305]: [XNIO-1 task-24] INFO io.kamax.mxisd.as.AppSvcManager - Returning future for transaction 39694
Apr 30 15:43:56 srv-matrix-riot docker[32305]: [XNIO-1 task-24] ERROR io.undertow.request - UT005071: Undertow request failed HttpServerExchange{ PUT /transactions/39694 request {Accept-Encoding=[gzip], Content-Length=[1678], Content-Type=[application/json], User-Agent=[Synapse/0.99.3], Host=[matrix-mxisd:8090]} response {Connection=[keep-alive], Access-Control-Allow-Origin=[*], Access-Control-Allow-Headers=[Origin, X-Requested-With, Content-Type, Accept, Authorization], Content-Length=[0], Access-Control-Allow-Methods=[GET, POST, PUT, DELETE, OPTIONS], Date=[Tue, 30 Apr 2019 12:43:56 GMT]}}
Apr 30 15:43:56 srv-matrix-riot docker[32305]: java.util.concurrent.ExecutionException: io.kamax.matrix.client.MatrixClientRequestException: Request failed: 403 - M_FORBIDDEN - Appservice not in room
Apr 30 15:43:56 srv-matrix-riot docker[32305]: at java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:357)
Apr 30 15:43:56 srv-matrix-riot docker[32305]: at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1895)
Apr 30 15:43:56 srv-matrix-riot docker[32305]: at io.kamax.mxisd.http.undertow.handler.as.v1.AsTransactionHandler.handleRequest(AsTransactionHandler.java:43)
Apr 30 15:43:56 srv-matrix-riot docker[32305]: at io.kamax.mxisd.http.undertow.handler.SaneHandler.handleRequest(SaneHandler.java:71)
Apr 30 15:43:56 srv-matrix-riot docker[32305]: at io.undertow.server.Connectors.executeRootHandler(Connectors.java:360)
Apr 30 15:43:56 srv-matrix-riot docker[32305]: at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:830)
Apr 30 15:43:56 srv-matrix-riot docker[32305]: at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
Apr 30 15:43:56 srv-matrix-riot docker[32305]: at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
Apr 30 15:43:56 srv-matrix-riot docker[32305]: at java.lang.Thread.run(Thread.java:748)
Apr 30 15:43:56 srv-matrix-riot docker[32305]: Caused by: io.kamax.matrix.client.MatrixClientRequestException: Request failed: 403 - M_FORBIDDEN - Appservice not in room
Apr 30 15:43:56 srv-matrix-riot docker[32305]: at io.kamax.matrix.client.AMatrixHttpClient.handleError(AMatrixHttpClient.java:267)
Apr 30 15:43:56 srv-matrix-riot docker[32305]: at io.kamax.matrix.client.AMatrixHttpClient.execute(AMatrixHttpClient.java:217)
Apr 30 15:43:56 srv-matrix-riot docker[32305]: at io.kamax.matrix.client.AMatrixHttpClient.execute(AMatrixHttpClient.java:200)
Apr 30 15:43:56 srv-matrix-riot docker[32305]: at io.kamax.matrix.client.AMatrixHttpClient.executeAuthenticated(AMatrixHttpClient.java:191)
Apr 30 15:43:56 srv-matrix-riot docker[32305]: at io.kamax.matrix.client.MatrixHttpRoom.getJoinedUsers(MatrixHttpRoom.java:216)
Apr 30 15:43:56 srv-matrix-riot docker[32305]: at io.kamax.mxisd.as.processor.event.MembershipEventProcessor.process(MembershipEventProcessor.java:112)
Apr 30 15:43:56 srv-matrix-riot docker[32305]: at io.kamax.mxisd.as.AppSvcManager.lambda$processTransaction$0(AppSvcManager.java:282)
Apr 30 15:43:56 srv-matrix-riot docker[32305]: at java.util.ArrayList.forEach(ArrayList.java:1257)
Apr 30 15:43:56 srv-matrix-riot docker[32305]: at io.kamax.mxisd.as.AppSvcManager.processTransaction(AppSvcManager.java:252)
Apr 30 15:43:56 srv-matrix-riot docker[32305]: at io.kamax.mxisd.as.AppSvcManager.processTransaction(AppSvcManager.java:225)
Apr 30 15:43:56 srv-matrix-riot docker[32305]: ... 7 more

Is there a chance that I configured Mxisd's AppSvc incorrectly? mxisd.yaml:

appsvc:
    enabled: true
    registration:
      synapse:
        id: 'appservice-mxisd'
    endpoint:
      toHS:
        url: '{{ matrix_mxisd_dns_overwrite_homeserver_client_value }}'
        token: '{{ matrix_synapse_as_token }}'
      toAS:
        url: 'http://{{ matrix_nginx_proxy_proxy_matrix_identity_api_addr_with_container }}'
        token: '{{ matrix_synapse_hs_token }}'
synapseSql:
    enabled: true ## Do not use this line if Synapse is used as an Identity Store
    type: 'postgresql'
    connection: '//{{ matrix_postgres_connection_hostname }}/{{ matrix_postgres_db_name }}?user={{ matrix_postgres_connection_username }}&password={{ matrix_postgres_connection_password }}'

Sorry for lengthy post, but I tried to explain and provide logs as detailed as I could. For now I'm back on kamax/mxisd:1.3.1-1-gc636500 Docker image where e-mail notifications work well, but I would like to sort out this problem, so my mxisd's version can be kept up to date.

maxidorius commented 5 years ago

@NullIsNot0 The following docker image should fix it: kamax/mxisd:1.4.2-2-g8243354 Can you give it a try and let me know please?

NullIsNot0 commented 5 years ago

Today I set up kamax/mxisd:1.4.2-2-g8243354 and invitation e-mails seem to work correctly. I'll leave this version and report back in few days if it's still working. Thank you for fixing this issue!

maxidorius commented 5 years ago

Thank you for reporting back!

NullIsNot0 commented 5 years ago

Mxisd version: kamax/mxisd:1.4.2-2-g8243354 appservice-mxisd.yaml service file for synapse is:

id: appservice-mxisd
url: http://matrix-mxisd:8090
as_token: "<AS_TOKEN_REDUCTED>"
hs_token: "<HS_TOKEN_REDUCTED>"
sender_localpart: mxisd
namespaces:
  aliases: []
  rooms: []
  users:
  - {exclusive: false, regex: '@*'}

Invites are working fine, but when I try to create new room, I get error in Riot, and mxisd logs say:

May 07 11:07:06 srv-matrix-riot docker[28524]: [XNIO-1 task-18] INFO io.kamax.mxisd.as.AppSvcManager - Processing AS Transaction 41158: start
May 07 11:07:06 srv-matrix-riot docker[28524]: [XNIO-1 task-18] INFO io.kamax.mxisd.as.AppSvcManager - Processing transaction events: start
May 07 11:07:06 srv-matrix-riot docker[28524]: [XNIO-1 task-18] INFO io.kamax.mxisd.as.processor.event.MembershipEventProcessor - Got membership event from @mike:myserv.com to @mike:myserv.com for room !pdiZaTFSmoXqtFYBXM:myserv.com
May 07 11:07:06 srv-matrix-riot docker[28524]: [XNIO-1 task-18] WARN io.kamax.mxisd.as.processor.event.MembershipEventProcessor - We joined the room !pdiZaTFSmoXqtFYBXM:myserv.com for another identity as the main user, which is not supported. Leaving...
May 07 11:07:06 srv-matrix-riot docker[28524]: [XNIO-1 task-18] INFO io.kamax.mxisd.as.AppSvcManager - Processing transaction events: end
May 07 11:07:06 srv-matrix-riot docker[28524]: [XNIO-1 task-18] INFO io.kamax.mxisd.as.AppSvcManager - Saving transaction details to store
May 07 11:07:06 srv-matrix-riot docker[28524]: [XNIO-1 task-18] INFO io.kamax.mxisd.as.AppSvcManager - Processed AS transaction 41158 in 280 ms

When I change appservice-mxisd.yaml to (only last line changes):

id: appservice-mxisd
url: http://matrix-mxisd:8090
as_token: "<AS_TOKEN_REDUCTED>"
hs_token: "<HS_TOKEN_REDUCTED>"
sender_localpart: mxisd
namespaces:
  aliases: []
  rooms: []
  users:
  - {exclusive: true, regex: '@_mxisd_invite-expired:myserv.com'}

then room creation works OK, but I get no more e-mails about invitations in rooms.

maxidorius commented 5 years ago

@nullisnot0 Could you open a new issue for this, to be sure we track the individual problems

NullIsNot0 commented 5 years ago

OK, just created #173 .