Getting 500 server error on sending "totp_code"

[rostyk110]

Preflight checklist

• I could not find a solution in the existing issues, docs, nor discussions.
• I agree to follow this project's Code of Conduct.
• I have read and am following this repository's Contribution Guidelines.
• This issue affects my Ory Cloud project.
• I have joined the Ory Community Slack.
• I am signed up to the Ory Security Patch Newsletter.

Describe the bug

Auth app - Google Authenticator

When I try to add Auth app, I get 500 Server Error. It happens after: connect Auth App (successfully), disconnect (successfully), connect again (getting Error).

Response:

{
    "code": 500,
    "status": "Internal Server Error",
    "request": "65abe04a-f758-9d46-b662-36482f537b32",
    "reason": "Could not find they TOTP key in the internal context. This is a code bug and should be reported to https://github.com/ory/kratos/.",
    "message": "An internal server error occurred, please contact the system administrator"
}

Reproducing the bug

Sorry, recording is 24.2MB, so I compressed it.

Screen Recording 2022-08-22 at 22.09.45.mov.zip

Or here is youtube link:
https://www.youtube.com/watch?v=_37Fns4AkT0

Relevant log output

{
   "audience":"application",
   "error":{
      "debug":"",
      "message":"An internal server error occurred, please contact the system administrator",
      "reason":"Could not find they TOTP key in the internal context. This is a code bug and should be reported to https://github.com/ory/kratos/.",
      "status":"Internal Server Error",
      "status_code":500
   },
   "http_request":{
      "headers":{
         "accept":"application/json, text/plain, */*",
         "accept-encoding":"gzip, deflate, br",
         "content-length":"142",
         "content-type":"application/json",
         "cookie":"Value is sensitive and has been redacted. To see the value set config key \"log.leak_sensitive_values = true\" or environment variable \"LOG_LEAK_SENSITIVE_VALUES=true\".",
         "origin":"http://localhost:3000/",
         "referer":"http://localhost:3000/",
         "sec-ch-ua":"\"Chromium\";v=\"104\", \" Not A;Brand\";v=\"99\", \"Google Chrome\";v=\"104\"",
         "sec-ch-ua-mobile":"?0",
         "sec-ch-ua-platform":"\"macOS\"",
         "sec-fetch-dest":"empty",
         "sec-fetch-mode":"cors",
         "sec-fetch-site":"cross-site",
         "user-agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/104.0.0.0 Safari/537.36",
         "via":"2.0 e4bbc916b7f96771ed58c0d668318acc.cloudfront.net (CloudFront)",
         "x-amz-cf-id":"Vwgs-HOIWh0o5WJKHK6_9ciQSLaifwf0f9eY8p0pkOGmoYWad21yDw==",
         "x-amzn-trace-id":"Root=1-62fe293b-3de7faed303877921a841dcf",
         "x-forwarded-for":"[removed]",
         "x-forwarded-host":"[removed]",
         "x-forwarded-port":"443",
         "x-forwarded-proto":"https",
         "x-forwarded-scheme":"https",
         "x-original-forwarded-for":"[removed], [removed]",
         "x-real-ip":"[removed]",
         "x-request-id":"95b5058376e1b05312ed1685c9027fd5",
         "x-scheme":"https"
      },
      "host":"[removed]",
      "method":"POST",
      "path":"/self-service/settings",
      "query":"Value is sensitive and has been redacted. To see the value set config key \"log.leak_sensitive_values = true\" or environment variable \"LOG_LEAK_SENSITIVE_VALUES=true\".",
      "remote":"[removed]:43220",
      "scheme":"http"
   },
   "http_response":{
      "status_code":500
   },
   "level":"error",
   "msg":"An error occurred while handling a request",
   "service_name":"Ory Kratos",
   "service_version":"v0.10.1",
   "time":"2022-08-18T11:57:47Z"
}

Relevant configuration

No response

Version

v0.10.1

On which operating system are you observing this issue?

Linux

In which environment are you deploying?

Kubernetes

Additional Context

cURL:

curl 'http://localhost:3006/api/.ory/self-service/settings?flow=6469be6f-c9d8-49f4-826d-949fa43c8bad' \ -H 'Accept: application/json, text/plain, */*' \ -H 'Accept-Language: en-US,en;q=0.9,uk;q=0.8' \ -H 'Cache-Control: no-cache' \ -H 'Connection: keep-alive' \ -H 'Content-Type: application/json' \ -H 'Cookie: csrf_token_dc00b226a17ebfc20ec30276b3639d78899dea58cd5bfa217fda35d=knZgAiXII00Ai3yj/DR7W2ExgN3jrhVIBTKvnsYQ=; ory_session_playground=MTY2MTE5NTMyMnw3MVlXVVJOR0w1YUwwVlFBTXlNaHJfMVZEanVYYXdxRnl4Si1WWmJSTlVKM2otdXFjMXJnSTBpMEhrZS1fcVRrSzVLUGV4M09ORXhJS2Z1YwWmxITjQwZk1ZOUdjdlRoU3FSTDl6UUljWk5hYURyQS1NMkJ5YlZDNWpoTkc4d3pjN21qcEZjV3Z0WEVJZDZ2TWNPWloxbHBNR2xMNllOR0NWcExpMERsYVFQRXo5ek1sQURKWmdfeDRvaWRQcVhLSmsxdGJtcXktTWd1VFJmek5WSTVoYUE9PXx7X1LLIvbtYh5ngb01VhqlNOaqb9SULFuNSvS3XaXzhA==' \ -H 'Origin: http://localhost:3006' \ -H 'Pragma: no-cache' \ -H 'Referer: http://localhost:3006/settings?flow=6469be6f-c9d8-49f4-826d-949fa43c8bad' \ -H 'Sec-Fetch-Dest: empty' \ -H 'Sec-Fetch-Mode: cors' \ -H 'Sec-Fetch-Site: same-origin' \ -H 'User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/104.0.0.0 Safari/537.36' \ -H 'sec-ch-ua: "Chromium";v="104", " Not A;Brand";v="99", "Google Chrome";v="104"' \ -H 'sec-ch-ua-mobile: ?0' \ -H 'sec-ch-ua-platform: "macOS"' \ --data-raw '{"csrf_token":"iEUaHOidwsWWzNC7IpImB1yjpMpWuNOpBFGQQaVXhiJZOr5n9uvF4d1cPZIkF7UWxuEBYz/fZn==","totp_code":"650204","method":"totp"}' \ --compressed

[aeneasr]

Can you please include the log lines?

[rostyk110]

Can you please include the log lines?

Done!
You can see logs in Relevant log output

[aeneasr]

Thank you for the report, that is helpful! Looks like we forgot to do this

kratos/selfservice/strategy/totp/settings.go

Lines 263 to 272 in 39bb84d

	// No TOTP set up yet, add nodes allowing us to add it.
	key, err := NewKey(r.Context(), e.AccountName, s.d)
	if err != nil {
	return err
	}
	f.InternalContext, err = sjson.SetBytes(f.InternalContext, flow.PrefixInternalContextKey(s.ID(), InternalContextKeyURL), key.URL())
	if err != nil {
	return err
	}

around here:

kratos/selfservice/strategy/totp/settings.go

Line 229 in 39bb84d

As a workaround you can create a new settings flow after you have disconnected the app. It looks like we do not properly reset the TOTP state in the flow after disconnecting!

Fixes (with tests please :) ) highly appreciated!

[kszafran]

I'll see if I can reproduce this and devise a fix.

[kszafran]

@rostyk110 I set up Kratos and the selfservice UI locally and couldn't reproduce the issue. I noticed that whenever I link/unlink TOTP I get a new flow (the flow= param in the URL changes). In your case it stays the same. I wonder why 🤔. This would be in line with what @aeneasr suggested about creating a new settings flow after disconnecting the app.

Edit: I managed to reproduce it with https://github.com/ory/kratos-selfservice-ui-react-nextjs

[kszafran]

@aeneasr I looked into this more and I think I found the root cause. At the end of every successful settings submission, Kratos regenerates the UI nodes:

kratos/selfservice/flow/settings/hook.go

Lines 218 to 223 in 0856bd7

	newFlow, err := e.d.SettingsHandler().NewFlow(w, r, i, ctxUpdate.Flow.Type)
	if err != nil {
	return err
	}
	ctxUpdate.Flow.UI = newFlow.UI

Some flows modify the InternalContext in their PopulateSettingsMethod (TOTP and WebAuthn do that). However, while the UI nodes are copied into the current flow, InternalContext isn't.

If I add ctxUpdate.Flow.InternalContext = newFlow.InternalContext after the line I shared above, linking and unlinking TOTP works as expected. Of course, this will probably break other flows, and what we should really do is merge newFlow.InternalContext into ctxUpdate.Flow.InternalContext, not just overwrite it. I don't know if gjson/sjson can merge two JSONs, though.

I made some other observations, too, while looking at the code:

• It seems likely to me that WebAuthn has the same bug. However, we don't use it, so I wasn't able to test it.
• Some methods seem to modify the flow object unnecessarily. For example, lookup codes modify UI.Nodes and even persist the flow on continueSettingsFlowDisable:

  kratos/selfservice/strategy/lookup/settings.go

  Lines 182 to 198 in 0856bd7

  	for _, n := range allSettingsNodes {
  	ctxUpdate.Flow.UI.Nodes.Remove(n)
  	}
  	ctxUpdate.Flow.UI.Nodes.Upsert(NewRegenerateLookupNode())
  	ctxUpdate.Flow.InternalContext, err = sjson.SetBytes(ctxUpdate.Flow.InternalContext, flow.PrefixInternalContextKey(s.ID(), internalContextKeyRevealed), false)
  	if err != nil {
  	return err
  	}
  	ctxUpdate.Flow.InternalContext, err = sjson.SetRawBytes(ctxUpdate.Flow.InternalContext, flow.PrefixInternalContextKey(s.ID(), InternalContextKeyRegenerated), []byte("{}"))
  	if err != nil {
  	return err
  	}
  	if err := s.d.SettingsFlowPersister().UpdateSettingsFlow(r.Context(), ctxUpdate.Flow); err != nil {
  	return err
  	}

  But that seems pointless, because PostSettingsHook will overwrite those changes anyway.

How would you like to proceed with this? It seems to me that merging the InternalContexts in PostSettingsHook is the most generic solution, and one that's easy to maintain.

[rostyk110]

@aeneasr any chance to fix that next week? :(

[kszafran]

@aeneasr Could you comment on my findings? I want to contribute a fix once we agree on the proper solution. It would be nice to get a fix into the next release.

[aeneasr]

Sorry, my last comment was a bit quick to write. To be honest, I'm not sure. The code you linked though is using lookup_secrets and not totp (which is the issue linked here). I think in the end we are not setting the internal context after we remove the credentials.

I think the best option we have is to create go and cypress test cases that emulate this behavior and then fix it by working backwards in identifying the bug.

[kszafran]

As an update, I'm currently busy with other tasks. I won't be able to work on this for some time, unfortunately.