error: failed to authorize: no active session for <session-id>: context deadline exceeded

[maxlaverse]

Hi!
Every day we have some builds failing with the following error:

#25 exporting cache
#25 preparing build cache for export
#25 preparing build cache for export 73.8s done
#25 writing layer sha256:somesha
#25 78.76 error: failed to authorize: no active session for d64hnddm9jssidwj6f9vv2w37: context deadline exceeded
#25 78.76 retrying in 1s
#25 84.76 error: failed to authorize: no active session for d64hnddm9jssidwj6f9vv2w37: context deadline exceeded
#25 84.76 retrying in 2s
#25 91.76 error: failed to authorize: no active session for d64hnddm9jssidwj6f9vv2w37: context deadline exceeded
#25 91.76 retrying in 4s
#25 writing layer sha256:somesha 27.0s done
#25 100.8 error: failed to authorize: no active session for d64hnddm9jssidwj6f9vv2w37: context deadline exceeded
#25 ERROR: error writing layer blob: failed to authorize: no active session for d64hnddm9jssidwj6f9vv2w37: context deadline exceeded
#26 ** export finalization failed - continuing anyway: error writing layer blob: failed to authorize: no active session for d64hnddm9jssidwj6f9vv2w37: context deadline exceeded (that's custom code)
#26 DONE 0.0s   

It affected 36 builds out of 883 in the past 24 hours (approx. 4%). This is likely related to docker/buildx#456 but I believe it deserves an issue in this project since it’s where the error is coming from.

Timeline

The session identifiers are legit. The problem is that is the session is gone when trying to fetch registry credentials, from a couple of seconds up to a couple of minutes. Here is an example of timeline:

• 00:14.578Z controller.Solve() is called for job z63yeomm82pcvp171rd4zyk3q, session d64hnddm9jssidwj6f9vv2w37
• 00:14.578Z controller.Status() is called for job z63yeomm82pcvp171rd4zyk3q
• 00:14.578Z llbsolver.Status() tries to retrieve job z63yeomm82pcvp171rd4zyk3q and waits
• 00:14.578Z sessionmanager.handleConn() session d64hnddm9jssidwj6f9vv2w37 is created
• 00:14.578Z sessionmanager.handleConn() waits for session d64hnddm9jssidwj6f9vv2w37's client context to finish
• 00:14.579Z llbsolver.Solve() new job z63yeomm82pcvp171rd4zyk3q, session d64hnddm9jssidwj6f9vv2w37
• 00:14.579Z llbsolver.Status() found job z63yeomm82pcvp171rd4zyk3q
• 00:18.963Z authHandler.doBearerAuth() fetching token for session d64hnddm9jssidwj6f9vv2w37
• 00:19.317Z authHandler.doBearerAuth() fetched token for session d64hnddm9jssidwj6f9vv2w37
• 00:36.549Z llbsolver.Solve() starts export for session d64hnddm9jssidwj6f9vv2w37, job z63yeomm82pcvp171rd4zyk3q
• 01:15.139Z llbsolver.Solve() export done for session d64hnddm9jssidwj6f9vv2w37, job z63yeomm82pcvp171rd4zyk3q
• 01:15.139Z llbsolver.Solve() preparing build cache export for session d64hnddm9jssidwj6f9vv2w37, job z63yeomm82pcvp171rd4zyk3q
• 01:29.499Z llbsolver.Solve() discards job z63yeomm82pcvp171rd4zyk3q, session: d64hnddm9jssidwj6f9vv2w37
• 01:29.500Z sessionmanager.handleConn() client context for session d64hnddm9jssidwj6f9vv2w37 is done: context canceled
• 01:29.500Z sessionmanager.handleConn() session d64hnddm9jssidwj6f9vv2w37 is deleted
• 06:26.926Z llbsolver.Solve() finalizing export
• 06:26.926Z authHandler.doBearerAuth() fetching token for session d64hnddm9jssidwj6f9vv2w37
• 06:31.927Z sessionmanager.Any() err: no active session for d64hnddm9jssidwj6f9vv2w37: context deadline exceeded
• 06:37.929Z sessionmanager.Any() err: no active session for d64hnddm9jssidwj6f9vv2w37: context deadline exceeded
• 06:44.930Z sessionmanager.Any() err: no active session for d64hnddm9jssidwj6f9vv2w37: context deadline exceeded
• 06:53.932Z sessionmanager.Any() err: no active session for d64hnddm9jssidwj6f9vv2w37: context deadline exceeded
• 06:53.932Z llbsolver.Solve() writes the custom line ** export finalization failed - continuing anyway

Why the session is gone is not entirely clear, but we're doing a lot of concurrent builds that share part of their stages. I hope I didn't made an error when wrapping up the timeline. If anything seems weird, don't hesitate to ask for verification or additional traces. We're using version 0.9.0 on linux/amd64.

Any idea what the approach should be to recover from such an error ?

Workaround

For the time being, we came up with a workaround which is to ignore errors when exporting the cache images, instead of failing our pipelines. We achieved adding something like the following snippet around

buildkit/solver/llbsolver/solver.go

Line 241 in b055d2d

cacheExporterResponse, err = e.Finalize(ctx)

if exportFinalizationFailure {
       inBuilderContext(ctx, j, fmt.Sprintf("** export finalization failed - continuing anyway: %v", err), "", func(_ context.Context, _ session.Group) error { return nil })
} else {
       return nil, err
}

[tonistiigi]

01:29.499Z llbsolver.Solve() discards job
06:26.926Z llbsolver.Solve() finalizing export

These don't seem to be in a logical order based on code. So are they from different jobs? What is the session for second job then and did first job finish cleanly. If there are 2 sessions then what is the start/end time of that session.

[maxlaverse]

I just noticed I shouldn't have truncated the custom message we're printing, as if the message is right, that would link to another job/session:

** export finalization failed - continuing anyway for session ozav3696vj6w6waxervso7krc, job 09rbqwca39q5gee7hxigsz9ad, group: [ozav3696vj6w6waxervso7krc]: error writing layer blob: failed to authorize: no active session for d64hnddm9jssidwj6f9vv2w37: context deadline exceeded

The error we get when calling e.Finalize(ctx) for session ozav3696vj6w6waxervso7krc and job 09rbqwca39q5gee7hxigsz9ad (not mentioned until yet), complains about not being able to refresh registry tokens using the session d64hnddm9jssidwj6f9vv2w37 that was already gone.

Here is a new timeline extended with both jobs and sessions. One pair is referenced as [1] and the other one as [2].

Short version, just by looking at llbsolver.Solve():

• 00:14.162Z [1] starts
• 00:14.578Z [2] starts
• 00:36.549Z [2] export starts
• 01:15.139Z [2] export done
• 01:15.139Z [2] build cache export preparation
• 01:29.499Z [2] exits
• 04:40.201Z [1] export starts
• 05:13.165Z [1] export done
• 05:13.166Z [1] build cache export preparation
• 06:26.926Z [1] fails with no active session when fetching credentials, mentioning session [2] in the actual error

Long version:

• 00:14.162Z [1] controller.Solve() for job 09rbqwca39q5gee7hxigsz9ad, session ozav3696vj6w6waxervso7krc
• 00:14.162Z [1] controller.Status() for job 09rbqwca39q5gee7hxigsz9ad
• 00:14.162Z [1] llbsolver.Solve() new 09rbqwca39q5gee7hxigsz9ad, session ozav3696vj6w6waxervso7krc
• 00:14.162Z [1] llbsolver.Status() found job 09rbqwca39q5gee7hxigsz9ad
• 00:14.162Z [1] sessionmanager.handleConn() session ozav3696vj6w6waxervso7krc is created
• 00:14.578Z [2] controller.Solve() is called for job z63yeomm82pcvp171rd4zyk3q, session d64hnddm9jssidwj6f9vv2w37
• 00:14.578Z [2] controller.Status() is called for job z63yeomm82pcvp171rd4zyk3q
• 00:14.578Z [2] llbsolver.Status() tries to retrieve job z63yeomm82pcvp171rd4zyk3q and waits
• 00:14.578Z [2] sessionmanager.handleConn() session d64hnddm9jssidwj6f9vv2w37 is created
• 00:14.578Z [2] sessionmanager.handleConn() waits for session d64hnddm9jssidwj6f9vv2w37's client context to finish
• 00:14.579Z [2] llbsolver.Solve() new job z63yeomm82pcvp171rd4zyk3q, session d64hnddm9jssidwj6f9vv2w37
• 00:14.579Z [2] llbsolver.Status() found job z63yeomm82pcvp171rd4zyk3q
• 00:18.963Z [2] authHandler.doBearerAuth() fetching token for session d64hnddm9jssidwj6f9vv2w37
• 00:19.317Z [2] authHandler.doBearerAuth() fetched token for session d64hnddm9jssidwj6f9vv2w37
• 00:36.549Z [2] llbsolver.Solve() starts export for session d64hnddm9jssidwj6f9vv2w37, job z63yeomm82pcvp171rd4zyk3q
• 01:15.139Z [2] llbsolver.Solve() export done for session d64hnddm9jssidwj6f9vv2w37, job z63yeomm82pcvp171rd4zyk3q
• 01:15.139Z [2] llbsolver.Solve() preparing build cache export for session d64hnddm9jssidwj6f9vv2w37, job z63yeomm82pcvp171rd4zyk3q
• 01:29.499Z [2] llbsolver.Solve() discards job z63yeomm82pcvp171rd4zyk3q, session: d64hnddm9jssidwj6f9vv2w37
• 01:29.500Z [2] sessionmanager.handleConn() client context for session d64hnddm9jssidwj6f9vv2w37 is done: context canceled
• 01:29.500Z [2] sessionmanager.handleConn() session d64hnddm9jssidwj6f9vv2w37 is deleted
• 04:40.201Z [1] llbsolver.Solve() starts export for session ozav3696vj6w6waxervso7krc, job 09rbqwca39q5gee7hxigsz9ad
• 05:05.571Z [1] authHandler.doBearerAuth() fetching token for session ozav3696vj6w6waxervso7krc
• 05:05.951Z [1] authHandler.doBearerAuth() fetched token for session ozav3696vj6w6waxervso7krc
• 05:05.952Z [1] authHandler.doBearerAuth() fetching token for session ozav3696vj6w6waxervso7krc
• 05:06.054Z [1] authHandler.doBearerAuth() fetched token for session ozav3696vj6w6waxervso7krc
• 05:06.058Z [1] authHandler.doBearerAuth() fetching token for session ozav3696vj6w6waxervso7krc
• 05:06.162Z [1] authHandler.doBearerAuth() fetched token for session ozav3696vj6w6waxervso7krc
• 05:13.165Z [1] llbsolver.Solve() export done for session ozav3696vj6w6waxervso7krc, job 09rbqwca39q5gee7hxigsz9ad
• 05:13.166Z [1] llbsolver.Solve() preparing build cache export for session ozav3696vj6w6waxervso7krc, job 09rbqwca39q5gee7hxigsz9ad
• 06:26.926Z [X] llbsolver.Solve() finalizing export (no explicit identifier here)
• 06:26.926Z [2] authHandler.doBearerAuth() fetching token for session d64hnddm9jssidwj6f9vv2w37
• 06:31.927Z [2] sessionmanager.Any() err: no active session for d64hnddm9jssidwj6f9vv2w37: context deadline exceeded
• 06:32.929Z [2] authHandler.doBearerAuth() fetching token for session d64hnddm9jssidwj6f9vv2w37
• 06:37.929Z [2] sessionmanager.Any() err: no active session for d64hnddm9jssidwj6f9vv2w37: context deadline exceeded
• 06:39.930Z [2] authHandler.doBearerAuth() fetching token for session d64hnddm9jssidwj6f9vv2w37
• 06:44.930Z [2] sessionmanager.Any() err: no active session for d64hnddm9jssidwj6f9vv2w37: context deadline exceeded
• 06:48.932Z [2] authHandler.doBearerAuth() fetching token for session d64hnddm9jssidwj6f9vv2w37
• 06:53.932Z [1&2] llbsolver.Solve() ** export finalization failed - continuing anyway for session ozav3696vj6w6waxervso7krc, job 09rbqwca39q5gee7hxigsz9ad, group: [ozav3696vj6w6waxervso7krc]: error writing layer blob: failed to authorize: no active session for d64hnddm9jssidwj6f9vv2w37: context deadline exceeded
• 06:53.932Z [2] sessionmanager.Any() err: no active session for d64hnddm9jssidwj6f9vv2w37: context deadline exceeded
• 06:53.932Z [1] llbsolver.Solve() discards job 09rbqwca39q5gee7hxigsz9ad discarded, session ozav3696vj6w6waxervso7krc
• 06:53.933Z [1] sessionmanager.handleConn() client context for session ozav3696vj6w6waxervso7krc is done: context canceled
• 06:53.933Z [1] sessionmanager.handleConn() session ozav3696vj6w6waxervso7krc is deleted

[tonistiigi]

06:26.926Z [X] llbsolver.Solve() finalizing export (no explicit identifier here)
06:26.926Z [2] authHandler.doBearerAuth() fetching token for session d64hnddm9jssidwj6f9vv2w37
06:31.927Z [2] sessionmanager.Any() err: no active session for d64hnddm9jssidwj6f9vv2w37: context deadline exceeded
06:32.929Z [2] authHandler.doBearerAuth() fetching token for session d64hnddm9jssidwj6f9vv2w37
06:37.929Z [2] sessionmanager.Any() err: no active session for d64hnddm9jssidwj6f9vv2w37: context deadline exceeded
06:39.930Z [2] authHandler.doBearerAuth() fetching token for session d64hnddm9jssidwj6f9vv2w37
06:44.930Z [2] sessionmanager.Any() err: no active session for d64hnddm9jssidwj6f9vv2w37: context deadline exceeded
06:48.932Z [2] authHandler.doBearerAuth() fetching token for session d64hnddm9jssidwj6f9vv2w37
06:53.932Z [1&2] llbsolver.Solve() ** export finalization failed - continuing anyway for session ozav3696vj6w6waxervso7krc, job 09rbqwca39q5gee7hxigsz9ad, group: [ozav3696vj6w6waxervso7krc]: error writing layer blob: failed to authorize: no active session for d64hnddm9jssidwj6f9vv2w37: context deadline exceeded

I guess all of these need to be [1] as none of this code should run after job.Discard.

Can you explain more what the 1 and 2 builds are doing. Mostly what kind of images they use as issue seems to be in the shared resolver. How is the image that is the target of the cache export used in other builds or other parts where GetResolver could be called?

It looks like [1] reuses the resolver from pool for [2] and therefore when it requires new tokens, goes to use the wrong session. But I don't quite understand how atm. Only object that stores session is newDockerAuthorizer https://github.com/moby/buildkit/blob/master/util/resolver/pool.go#L153 but that should never be shared between GetResolver calls. The .handler is shared but it doesn't store the session and asks one to be provided by caller.

[tonistiigi]

This is my only idea for now if you can check if it changes anything:

diff --git a/util/resolver/pool.go b/util/resolver/pool.go
index 5706ddb7..cdb9fed5 100644
--- a/util/resolver/pool.go
+++ b/util/resolver/pool.go
@@ -146,10 +146,13 @@ func (r *Resolver) HostsFunc(host string) ([]docker.RegistryHost, error) {
 		if err != nil || v == nil {
 			return nil, err
 		}
-		res := v.([]docker.RegistryHost)
-		if len(res) == 0 {
+		vv := v.([]docker.RegistryHost)
+		if len(vv) == 0 {
 			return nil, nil
 		}
+		// make a copy so authorizer is set on unique instance
+		res := make([]docker.RegistryHost, len(vv))
+		copy(res, vv)
 		auth := newDockerAuthorizer(res[0].Client, r.handler, r.sm, r.g)
 		for i := range res {
 			res[i].Authorizer = auth

[maxlaverse]

Trying out the patch @tonistiigi! I should be able to tell if #2369 already fixes the issue within 24h

[maxlaverse]

We only had 600 builds so far but none of them failed because of a no active session error. Could be a day with less concurrent builds but I'd like to think this change actually fixes it.

[tonistiigi]

@maxlaverse any update?

[maxlaverse]

We had some Docker authentication errors (401) but I think they were unrelated to that change. I'll probably know for sure tomorrow or Monday. No more no active session in the meantime.

I wanted to tried out a fresh build from upstream, with almost none of our patches but a workaround tentative for #2296, just to be sure I'm testing the exact same code as here. I'm not sure why yet, but all builds immediately failed with moby.buildkit.v1.Control/Solve returned error: rpc error: code = Unknown desc = failed to read dockerfile: failed to mount aig0peelx0scbvxoeo9a8jyir: snapshot does not exist: not found. I have to give it a try again later.

[maxlaverse]

Still no occurrence of no active session errors 24 hours later.