GetUserDevices returned unknown error type (M_UNAUTHORIZED: Failed to find any key to satisfy: _FetchKeyRequest)

[Guerteltier]

Background information

• Dendrite version or git SHA: bfa344e83191c49bdc9917ab7a8ec31b93c202e9
• Monolith or Polylith?: Monolith
• SQLite3 or Postgres?: Postgres 12.9
• Running in Docker?: No
• go version: go1.16.12 linux/amd64
• Client used (if applicable): N/A

Description

• What is the problem: Dendrite spams log messages like this: time="2022-05-04T13:41:50.560907000Z" level=warning msg="GetUserDevices returned unknown error type" func="github.com/matrix-org/dendrite/keyserver/internal.(*DeviceListUpdater).processServer" file="github.com/matrix-org/dendrite/keyserver/internal/device_list_update.go:402" context=missing error="contents=[123 34 101 114 114 99 111 100 101 34 58 34 77 95 85 78 65 85 84 72 79 82 73 90 69 68 34 44 34 101 114 114 111 114 34 58 34 70 97 105 108 101 100 32 116 111 32 102 105 110 100 32 97 110 121 32 107 101 121 32 116 111 32 115 97 116 105 115 102 121 58 32 95 70 101 116 99 104 75 101 121 82 101 113 117 101 115 116 40 115 101 114 118 101 114 95 110 97 109 101 61 39 97 115 111 122 105 97 108 46 111 114 103 39 44 32 109 105 110 105 109 117 109 95 118 97 108 105 100 95 117 110 116 105 108 95 116 115 61 49 54 53 49 54 55 49 55 48 57 53 55 49 44 32 107 101 121 95 105 100 115 61 91 39 101 100 50 53 53 49 57 58 77 101 73 122 87 69 39 93 41 34 125] msg=Failed to GET JSON (hostname \"matrix.org\" path \"/_matrix/federation/v1/user/devices/@machine_sinatra:matrix.org\") code=401 wrapped=M_UNAUTHORIZED: Failed to find any key to satisfy: _FetchKeyRequest(server_name='asozial.org', minimum_valid_until_ts=1651671709571, key_ids=['ed25519:MeIzWE'])" server_name=matrix.org user_id="@machine_sinatra:matrix.org" Additionally CPU usage is constantly at ~100%, but I don't know if this is related to this issue or if it's a separate issue.
• Who is affected:
• How is this bug manifesting: Lots of log messages
• When did this first appear: After upgrading from 0.5.1

My config:

version: 2

global:
  server_name: asozial.org
  private_key: matrix_key.pem
  key_validity_period: 168h0m0s
  well_known_server_name: "matrix.asozial.org:8448"
  trusted_third_party_id_servers:
    - matrix.org
    - vector.im
  disable_federation: false
  presence:
    enable_inbound: true
    enable_outbound: true
  server_notices:
    enabled: true
    local_part: "_server"
    display_name: "Server alerts"
    avatar_url: ""
    room_name: "Server Alerts"
  jetstream:
    addresses:
    - 127.0.0.1:4222
    in_memory: false
    storage_path: ./
    topic_prefix: Dendrite
  metrics:
    enabled: true
    basic_auth:
      username: metrics
      password: [REDACTED]
  dns_cache:
    enabled: true
    cache_size: 256
    cache_lifetime: "5m"

app_service_api:
  internal_api:
    listen: http://localhost:7777
    connect: http://localhost:7777
  database:
    connection_string: postgres://dendrite:[REDACTED]@localhost/dendrite_appservice?sslmode=disable
    max_open_conns: 10
    max_idle_conns: 2
    conn_max_lifetime: -1
  disable_tls_validation: false
  config_files: [cactus.yaml, mautrix-telegram.yaml, matrix-appservice-discord.yaml]

client_api:
  internal_api:
    listen: http://localhost:7771
    connect: http://localhost:7771
  external_api:
    listen: http://[::]:8071
  registration_disabled: false
  guests_disabled: false
  registration_shared_secret: "[REDACTED]"
  enable_registration_captcha: true
  recaptcha_public_key: "5a00096e-4097-441b-bddd-4e7613cf2560"
  recaptcha_private_key: "[REDACTED]"
  recaptcha_bypass_secret: "[REDACTED]"
  recaptcha_siteverify_api: "https://hcaptcha.com/siteverify"
  turn:
    turn_user_lifetime: ""
    turn_uris: ["turns:ice.friendup.cloud"]
    turn_shared_secret: ""
    turn_username: "TINA"
    turn_password: "TURNER"
  rate_limiting:
    enabled: true
    threshold: 20
    cooloff_ms: 500

federation_api:
  internal_api:
    listen: http://localhost:7772
    connect: http://localhost:7772
  external_api:
    listen: http://[::]:8072
  database:
    connection_string: postgres://dendrite:[REDACTED]@localhost/dendrite_federationapi?sslmode=disable
    max_open_conns: 10
    max_idle_conns: 2
    conn_max_lifetime: -1
  send_max_retries: 16
  disable_tls_validation: false
  key_perspectives:
    - server_name: matrix.org
      keys:
        - key_id: ed25519:auto
          public_key: Noi6WqcDj0QmPxCNQqgezwTlBKrfqehY1u2FyWP9uYw
        - key_id: ed25519:a_RXGa
          public_key: l8Hft5qXKn1vfHrg3p4+W8gELQVo8N13JkluMfmn2sQ
  prefer_direct_fetch: false

key_server:
  internal_api:
    listen: http://localhost:7779
    connect: http://localhost:7779
  database:
    connection_string: postgres://dendrite:[REDACTED]@localhost/dendrite_keyserver?sslmode=disable
    max_open_conns: 10
    max_idle_conns: 2
    conn_max_lifetime: -1

media_api:
  internal_api:
    listen: http://localhost:7774
    connect: http://localhost:7774
  external_api:
    listen: http://[::]:8074
  database:
    connection_string: postgres://dendrite:[REDACTED]@localhost/dendrite_mediaapi?sslmode=disable
    max_open_conns: 5
    max_idle_conns: 2
    conn_max_lifetime: -1
  base_path: ./media_store
  max_file_size_bytes: 10485760
  dynamic_thumbnails: false
  max_thumbnail_generators: 10
  thumbnail_sizes:
    - width: 32
      height: 32
      method: crop
    - width: 96
      height: 96
      method: crop
    - width: 640
      height: 480
      method: scale

mscs:
  mscs: [msc2444,msc2753,msc2836,msc2946]
  database:
    connection_string: postgres://dendrite:[REDACTED]@localhost/dendrite_mscs?sslmode=disable
    max_open_conns: 5
    max_idle_conns: 2
    conn_max_lifetime: -1

room_server:
  internal_api:
    listen: http://localhost:7770
    connect: http://localhost:7770
  database:
    connection_string: postgres://dendrite:[REDACTED]@localhost/dendrite_roomserver?sslmode=disable
    max_open_conns: 10
    max_idle_conns: 2
    conn_max_lifetime: -1

sync_api:
  internal_api:
    listen: http://localhost:7773
    connect: http://localhost:7773
  external_api:
    listen: http://[::]:8073
  database:
    connection_string: postgres://dendrite:[REDACTED]@localhost/dendrite_syncapi?sslmode=disable
    max_open_conns: 10
    max_idle_conns: 2
    conn_max_lifetime: -1

user_api:
  internal_api:
    listen: http://localhost:7781
    connect: http://localhost:7781
  account_database:
    connection_string: postgres://dendrite:[REDACTED]@localhost/dendrite_userapi_accounts?sslmode=disable
    max_open_conns: 10
    max_idle_conns: 2
    conn_max_lifetime: -1

tracing:
  enabled: false
  jaeger:
    serviceName: ""
    disabled: false
    rpc_metrics: false
    tags: []
    sampler: null
    reporter: null
    headers: null
    baggage_restrictions: null
    throttler: null

logging:
  - type: std
    level: info
  - type: file
    level: warn
    params:
      path: /var/log/dendrite

[S7evinK]

Looking at the config - a reason for ~100% usage could be enable_outbound set to true. This can result in quite a huge amount of outgoing federated requests, depending on the server count you are federating with.

[S7evinK]

Random question @Guerteltier, does hCaptcha work for you? https://github.com/matrix-org/dendrite/issues/2157 is asking to add support for it, but if it already works - great! :)

[Guerteltier]

Looking at the config - a reason for ~100% usage could be enable_outbound set to true. This can result in quite a huge amount of outgoing federated requests, depending on the server count you are federating with.

Disabling it fixed the high CPU usage. Maybe consider adding a warning to the config template?

Random question @Guerteltier, does hCaptcha work for you? #2157 is asking to add support for it, but if it already works - great! :)

It works with some simple changes:

diff --git a/clientapi/auth/authtypes/logintypes.go b/clientapi/auth/authtypes/logintypes.go
index f01e48f8..78e67755 100644
--- a/clientapi/auth/authtypes/logintypes.go
+++ b/clientapi/auth/authtypes/logintypes.go
@@ -8,7 +8,7 @@ const (
        LoginTypePassword           = "m.login.password"
        LoginTypeDummy              = "m.login.dummy"
        LoginTypeSharedSecret       = "org.matrix.login.shared_secret"
-       LoginTypeRecaptcha          = "m.login.recaptcha"
+       LoginTypeRecaptcha          = "org.asozial.login.hcaptcha"
        LoginTypeApplicationService = "m.login.application_service"
        LoginTypeToken              = "m.login.token"
 )
diff --git a/clientapi/routing/auth_fallback.go b/clientapi/routing/auth_fallback.go
index abfe830f..af10dc49 100644
--- a/clientapi/routing/auth_fallback.go
+++ b/clientapi/routing/auth_fallback.go
@@ -31,7 +31,7 @@ const recaptchaTemplate = `
 <title>Authentication</title>
 <meta name='viewport' content='width=device-width, initial-scale=1,
     user-scalable=no, minimum-scale=1.0, maximum-scale=1.0'>
-<script src="https://www.google.com/recaptcha/api.js"
+<script src="https://js.hcaptcha.com/1/api.js"
     async defer></script>
 <script src="//code.jquery.com/jquery-1.11.2.min.js"></script>
 <script>
@@ -51,7 +51,7 @@ function captchaDone() {
         Please verify that you're not a robot.
         </p>
                <input type="hidden" name="session" value="{{.session}}" />
-        <div class="g-recaptcha"
+        <div class="h-captcha"
             data-sitekey="{{.siteKey}}"
             data-callback="captchaDone">
         </div>
@@ -155,7 +155,7 @@ func AuthFallback(
                                return &res
                        }

-                       response := req.Form.Get("g-recaptcha-response")
+                       response := req.Form.Get("h-captcha-response")
                        if err := validateRecaptcha(cfg, response, clientIP); err != nil {
                                util.GetLogger(req.Context()).Error(err)
                                return err
diff --git a/clientapi/routing/register.go b/clientapi/routing/register.go
index 8253f315..65290530 100644
--- a/clientapi/routing/register.go
+++ b/clientapi/routing/register.go
@@ -20,6 +20,7 @@ import (
        "encoding/json"
        "fmt"
        "io/ioutil"
+       "net"
        "net/http"
        "net/url"
        "regexp"
@@ -255,7 +256,7 @@ type recaptchaResponse struct {
        Success     bool      `json:"success"`
        ChallengeTS time.Time `json:"challenge_ts"`
        Hostname    string    `json:"hostname"`
-       ErrorCodes  []int     `json:"error-codes"`
+       ErrorCodes  []string  `json:"error-codes"`
 }

 // validateUsername returns an error response if the username is invalid
@@ -333,12 +334,21 @@ func validateRecaptcha(
                }
        }

+       host, _, err := net.SplitHostPort(clientip)
+
+       if err != nil {
+               return &util.JSONResponse{
+                       Code: http.StatusInternalServerError,
+                       JSON: jsonerror.Unknown("net.SplitHostPort(" + clientip + ") failed!"),
+               }
+       }
+
        // Make a POST request to Google's API to check the captcha response
        resp, err := http.PostForm(cfg.RecaptchaSiteVerifyAPI,
                url.Values{
                        "secret":   {cfg.RecaptchaPrivateKey},
                        "response": {response},
-                       "remoteip": {clientip},
+                       "remoteip": {host},
                },
        )

[S7evinK]

Closing this for now, as with some recent changes this error message should be handled differently. If you're still seeing this, feel free to re-open.