search

ma1uta / ma1sd

Federated Matrix Identity Server (formerly fork of kamax/mxisd)
GNU Affero General Public License v3.0
167 stars 56 forks source link

Token expiration issue #84

Open msaeedm opened 3 years ago

msaeedm commented 3 years ago

There might be an issue with token expiration. When I launch Element desktop app then go to settings, I see my email address listed under email addresses. I also see what appears to be appropriate lines in ma1sd logs.

2021-01-09T21:03:52.063862004Z [XNIO-1 task-20] INFO io.kamax.mxisd.auth.AccountManager - Found account for user: @user:my.domain
2021-01-09T21:03:52.063892772Z [XNIO-1 task-20] INFO io.kamax.mxisd.http.undertow.handler.term.v2.AcceptTermsHandler - User @user:my.domain accepts the term: https://path_to_privacy_notice
2021-01-09T21:03:52.108909479Z [XNIO-1 task-21] INFO io.kamax.mxisd.auth.AccountManager - Found account for user: @user:my.domain
2021-01-09T21:03:52.214037555Z [XNIO-1 task-23] INFO io.kamax.mxisd.auth.AccountManager - Found account for user: @user:my.domain
2021-01-09T21:03:52.214078385Z [XNIO-1 task-23] DEBUG io.kamax.mxisd.http.undertow.handler.identity.share.LookupHandler - XFF header: 10.0.25.79
2021-01-09T21:03:52.214084599Z [XNIO-1 task-23] INFO io.kamax.mxisd.http.undertow.handler.identity.v2.HashLookupHandler - Got bulk lookup request from 10.0.25.79 with client Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.7.16 Chrome/85.0.4183.121 Electron/10.1.6 Safari/537.36 - Is recursive? false
2021-01-09T21:03:52.214101641Z [XNIO-1 task-23] INFO io.kamax.mxisd.http.undertow.handler.identity.v2.HashLookupHandler - Finished bulk lookup request from 10.0.25.79

and this from the reverse proxy:

10.0.25.79 - - [09/Jan/2021:16:25:07 -0500] "OPTIONS /_matrix/client/r0/account/3pid HTTP/1.1" 204 0 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.7.16 Chrome/85.0.4183.121 Electron/10.1.6 Safari/537.36" "ip, ip2"
10.0.25.79 - - [09/Jan/2021:16:25:07 -0500] "GET /_matrix/identity/v2/terms HTTP/1.1" 200 150 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.7.16 Chrome/85.0.4183.121 Electron/10.1.6 Safari/537.36" "ip, ip3"
10.0.25.79 - - [09/Jan/2021:16:25:07 -0500] "GET /_matrix/client/r0/account/3pid HTTP/1.1" 200 230 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.7.16 Chrome/85.0.4183.121 Electron/10.1.6 Safari/537.36" "ip, ip2"
0.25.79 - - [09/Jan/2021:16:25:07 -0500] "OPTIONS /_matrix/identity/v2/terms HTTP/1.1" 200 0 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.7.16 Chrome/85.0.4183.121 Electron/10.1.6 Safari/537.36" "ip, ip3"
10.0.25.79 - - [09/Jan/2021:16:25:07 -0500] "POST /_matrix/identity/v2/terms HTTP/1.1" 200 2 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.7.16 Chrome/85.0.4183.121 Electron/10.1.6 Safari/537.36" "ip, ip3"
10.0.25.79 - - [09/Jan/2021:16:25:07 -0500] "OPTIONS /_matrix/identity/v2/hash_details HTTP/1.1" 200 0 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.7.16 Chrome/85.0.4183.121 Electron/10.1.6 Safari/537.36" "ip, ip3"
10.0.25.79 - - [09/Jan/2021:16:25:07 -0500] "GET /_matrix/identity/v2/hash_details HTTP/1.1" 200 71 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.7.16 Chrome/85.0.4183.121 Electron/10.1.6 Safari/537.36" "ip, ip3"
10.0.25.79 - - [09/Jan/2021:16:25:08 -0500] "OPTIONS /_matrix/identity/v2/lookup HTTP/1.1" 200 0 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.7.16 Chrome/85.0.4183.121 Electron/10.1.6 Safari/537.36" "ip, ip3"
10.0.25.79 - - [09/Jan/2021:16:25:08 -0500] "POST /_matrix/identity/v2/lookup HTTP/1.1" 200 162 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.7.16 Chrome/85.0.4183.121 Electron/10.1.6 Safari/537.36" "ip, ip3"

However, after a while (seems around 30 min), If I open the settings page I do not see my email listed under email addresses ??!! and the logs from ma1sd now show:

[XNIO-1 task-43] WARN io.kamax.mxisd.auth.AccountManager - Account not found.
[XNIO-1 task-43] ERROR io.kamax.mxisd.http.undertow.handler.AuthorizationHandler - Account not found from request from: my.domain
[XNIO-1 task-43] INFO io.kamax.mxisd.http.undertow.handler.BasicHttpHandler - Request GET http://my.domain/_matrix/identity/v2/hash_details - Error M_UNAUTHORIZED: Supplied credentials are invalid
[XNIO-1 task-44] WARN io.kamax.mxisd.auth.AccountManager - Account not found.
[XNIO-1 task-44] INFO io.kamax.mxisd.http.undertow.handler.BasicHttpHandler - Request POST http://my.domain/_matrix/identity/v2/terms - Error M_UNAUTHORIZED: Supplied credentials are invalid

and the reverse proxy:

10.0.25.79 - - [09/Jan/2021:18:51:47 -0500] "OPTIONS /_matrix/client/r0/account/3pid HTTP/1.1" 204 0 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.7.16 Chrome/85.0.4183.121 Electron/10.1.6 Safari/537.36" "ip, ip2"
10.0.25.79 - - [09/Jan/2021:18:51:47 -0500] "GET /_matrix/client/r0/account/3pid HTTP/1.1" 200 230 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.7.16 Chrome/85.0.4183.121 Electron/10.1.6 Safari/537.36" "ip, ip2"
10.0.25.79 - - [09/Jan/2021:18:51:47 -0500] "GET /_matrix/identity/v2/terms HTTP/1.1" 200 150 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.7.16 Chrome/85.0.4183.121 Electron/10.1.6 Safari/537.36" "ip, ip3"
10.0.25.79 - - [09/Jan/2021:18:51:47 -0500] "OPTIONS /_matrix/identity/v2/hash_details HTTP/1.1" 200 0 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.7.16 Chrome/85.0.4183.121 Electron/10.1.6 Safari/537.36" "ip, ip4"
10.0.25.79 - - [09/Jan/2021:18:51:47 -0500] "OPTIONS /_matrix/identity/v2/terms HTTP/1.1" 200 0 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.7.16 Chrome/85.0.4183.121 Electron/10.1.6 Safari/537.36" "ip, ip3"
10.0.25.79 - - [09/Jan/2021:18:51:47 -0500] "POST /_matrix/identity/v2/terms HTTP/1.1" 200 2 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.7.16 Chrome/85.0.4183.121 Electron/10.1.6 Safari/537.36" "ip, ip3"
10.0.25.79 - - [09/Jan/2021:18:51:47 -0500] "GET /_matrix/identity/v2/hash_details HTTP/1.1" 401 87 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.7.16 Chrome/85.0.4183.121 Electron/10.1.6 Safari/537.36" "ip, ip3"

If I completely exit Element app and open it again, then the problem disappears and I can see my email listed....the problem then recurs after about 30 min. On further testing, I noted the problem also occurs using the web client element.io. This problem is not there when using vector.im IS

Below are additional info about ma1sd config file and my locations in nginx.

matrix:
  domain: 'my.domain'
  v1: true # deprecated
  v2: true
  ## Remove the default matrix-org server
  identity:
    servers:
      myOtherServers: []

server:
  name: 'sub.my.domain'
  port: 8090
  publicUrl : 'https://sub.my.domain'

synapseSql:
  enabled: true
  type: postgresql
  connection: //postgres:5432/synapse?user=USER&password=PASS
  lookup:
    query: 'select user_id as mxid, medium, address from user_threepid_id_server'
  legacyRoomNames: false
  identity:
    enabled: true
    query: select user_id as uid, medium, address from user_threepids where medium = ? and address = ?

key:
  path: '/var/ma1sd/sign.key'

storage:
  backend: postgresql
  provider:
    postgresql:
      database: '//postgres:5432/ma1sd'
      username: 'USER'
      password: 'PASS'

register:
    allowed: false
    invite: true

threepid:
  medium:
    email:
      identity:
        from: 'no-reply@my.domain'
        name: 'Matrix'
      connectors:
        smtp:
          host: 'smtp_server_url'
          port: 587
          tls: 2
          login: "admin@my.domain"
          password: "PASS"
      generators:
        template:
          invite: '/etc/ma1sd/invite-template.eml'
          session:
            validation: '/etc/ma1sd/validate-template.eml'
          placeholder:
            REGISTER_URL: 'https://my_registration_url'

    msisdn:
      connectors:
        twilio:
          account_sid: 'SID'
          auth_token: 'TOKEN'
          number: 'PHONE'

dns:
  overwrite:
    homeserver:
      client:
        - name: 'my.domain'
          value: 'http://synapse:8008'
        - name: 'sub.my.domain'
          value: 'http://synapse:8008'
      federation:
        - name: 'my.domain'
          value: 'http://synapse:8008'
        - name: 'sub.my.domain'
          value: 'http://synapse:8008'

lookup:
   recursive:
     enabled: false
     allowedCidr:
      - '127.0.0.0/8'
      - '::1/128'
     bridge:
       enabled: true
       mappings:
         email: 'http://localhost:8090'

invite:
   resolution:
     recursive: false

logging:
  root: debug  
  app: debug   
  requests: false 

hashing:
  enabled: true
  rotationPolicy: per_seconds
  delay: 1m
  hashStorageType: sql
  algorithms:
    - none 
    - sha256

policy:
    policies:
      terms_of_service:
        version: 1.0
        terms:
          en:
            name: terms of service
            url: https://path_to_privacy_notice

nginx locations are:

/_matrix/client/r0/user_directory
/_matrix/client/r0/login
~* ^/_matrix/client/r0/register/(email|msisdn)/requestToken$
/_matrix/identity
T3chTobi commented 3 years ago

I have this issue as well

janonym1 commented 2 years ago

I have posted also posted this in a different issue88 because I wasnt sure where this fits best.

I have a similar issue with a similar setup. When I look my at my account information (displayname, email) in my element profile, I get empty fields and the following errors on the server:

Jan 05 16:48:21 matrix-ma1sd[1650401]: [XNIO-1 task-2] INFO io.kamax.mxisd.auth.AccountManager - Found account for user: @matrixuser.matrix.domain.com
Jan 05 16:48:21 matrix-ma1sd[1650401]: [XNIO-1 task-2] ERROR io.kamax.mxisd.http.undertow.handler.AuthorizationHandler - Account for '@matrixuser.matrix.domain.com' from: matrix.domain.com
Jan 05 16:48:21 matrix-ma1sd[1650401]: [XNIO-1 task-2] ERROR io.kamax.mxisd.http.undertow.handler.SaneHandler - Unauthorized:
Jan 05 16:48:21 matrix-ma1sd[1650401]: io.kamax.mxisd.exception.InvalidCredentialsException: Supplied credentials are invalid
Jan 05 16:48:21 matrix-ma1sd[1650401]:         at io.kamax.mxisd.http.undertow.handler.AuthorizationHandler.handleRequest(AuthorizationHandler.java:65)
Jan 05 16:48:21 matrix-ma1sd[1650401]:         at io.kamax.mxisd.http.undertow.handler.SaneHandler.handleRequest(SaneHandler.java:71)
Jan 05 16:48:21 matrix-ma1sd[1650401]:         at io.undertow.server.Connectors.executeRootHandler(Connectors.java:387)
Jan 05 16:48:21 matrix-ma1sd[1650401]:         at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:841)
Jan 05 16:48:21 matrix-ma1sd[1650401]:         at org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
Jan 05 16:48:21 matrix-ma1sd[1650401]:         at org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:2019)
Jan 05 16:48:21 matrix-ma1sd[1650401]:         at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1558)
Jan 05 16:48:21 matrix-ma1sd[1650401]:         at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1449)
Jan 05 16:48:21 matrix-ma1sd[1650401]:         at java.lang.Thread.run(Thread.java:748)
Jan 05 16:48:21 matrix-ma1sd[1650401]: [XNIO-1 task-2] INFO io.kamax.mxisd.http.undertow.handler.BasicHttpHandler - Request GET http://matrix.domain.com/_matrix/identity/v2/hash_details - Error M_UNAUTHORIZED: Supplied credentials are invalid

restarting the ma1sd-service by hand helps for some time but then the same error occurs again. Since element version 1.10, I dont need to relog anymore to see my profile data. Sometimes there are different errors (java.lang.RuntimeException: java.sql.SQLException: Connection has already been closed), so assuming it has to do with a session timer or similar makes sense imho