Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Closed
NullIsNot0 opened this issue Apr 30, 2019 · 6 comments
Closed

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

NullIsNot0 opened this issue Apr 30, 2019 · 6 comments
Assignees
@maxidorius
Labels
bug Software behaviour is unexpected and/or broken and needs to be corrected

Comments

@NullIsNot0
Copy link

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 maxidorius self-assigned this May 4, 2019
@maxidorius maxidorius added the bug Software behaviour is unexpected and/or broken and needs to be corrected label May 4, 2019
@maxidorius
Copy link
Member

@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
Copy link
Author

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
Copy link
Member

Thank you for reporting back!

@NullIsNot0
Copy link
Author

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
Copy link
Member

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

@NullIsNot0
Copy link
Author

OK, just created #173 .

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@maxidorius maxidorius

Labels
bug Software behaviour is unexpected and/or broken and needs to be corrected
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@maxidorius @NullIsNot0