Strange behavior from token discovery code

[jhiemstrawisc]

I'm working with our friends at JLab, and we're seeing some strange behavior related to the v7.21 client's token validation logic (on ap23 if that matters).

Consider this debug output from a successful transfer that was invoked with pelican object get osdf://jlab-osdf/gluex/<rest of the path> /dev/null:

time="2025-11-18T12:49:56-06:00" level=debug msg="Token is not acceptable; clearing cache"
time="2025-11-18T12:49:56-06:00" level=debug msg="Using token from XDG_RUNTIME_DIR"
time="2025-11-18T12:49:56-06:00" level=debug msg="Opening token file: <file redacted>"
time="2025-11-18T12:49:56-06:00" level=debug msg="Out of token locations to search"
time="2025-11-18T12:49:56-06:00" level=warning msg="Using provided token  even though it does not appear to be acceptable to perform transfer"

Two things to note:

1. There's an extra space in the last message at "token even". The line of code producing this error message lives here and it should be providing a token location. The first bug in this line is that the token location is empty, the second bug is that we should always be wrapping inputs to %s-formatted strings with quotes so it's obvious when the values are empty (better yet, use the %q formatter that @h2zh told me about recently, which does this automatically).
2. I was able to eyeball the token stored in the token file, and it appears completely valid (note that timestamps have been converted to human-readable form):

{
  "aud": "ANY",
  "sub": <redacted>,
  "ver": "scitoken:2.0",
  "nbf": "Tue Nov 18 12:12:21 PM CST 2025",
  "scope": "read:/gluex/ write:/gluex/",
  "iss": "https://cilogon.org/jlab",
  "exp": "Tue Nov 18 03:12:26 PM CST 2025",
  "iat": "Tue Nov 18 12:12:26 PM CST 2025",
  "jti": <redacted,
  "group": <redacted>
}

I double checked this against the information I can get via the Director and it all checks out. Furthermore, the token did work, so the bug must live in our token detection code.

[brianaydemir]

I thought we already had an issue for this? The "acceptable token" logic checks only WLCG scopes:

pelican/client/acquire_token.go

Lines 507 to 516 in 7a08b44

	var scopeOK bool
	if opts.Operation.IsEnabled(config.TokenWrite) || opts.Operation.IsEnabled(config.TokenSharedWrite) {
	scopeOK = (scope_info[0] == "storage.modify" || scope_info[0] == "storage.create")
	} else if opts.Operation.IsEnabled(config.TokenDelete) {
	scopeOK = (scope_info[0] == "storage.modify")
	} else if opts.Operation.IsEnabled(config.TokenRead) || opts.Operation.IsEnabled(config.TokenSharedRead) {
	scopeOK = (scope_info[0] == "storage.read")
	} else {
	scopeOK = false
	}

[brianaydemir]

Yeah, this issue is effectively a duplicate of #2130, whose PR apparently didn't fix the issue completely.

We might have caught this earlier had someone noticed the buggy unit test:

pelican/client/main_test.go

Lines 527 to 533 in e150be1

	// 2) Construct a SciToken JWT with ver="scitokens:2.0" and scope "storage.read:/bar"
	tc, err := token.NewTokenConfig(token.Scitokens2Profile{})
	require.NoError(t, err)
	tc.Lifetime = time.Hour
	tc.Issuer = "https://issuer.example"
	tc.AddAudienceAny()
	tc.AddResourceScopes(token_scopes.NewResourceScope(token_scopes.Wlcg_Storage_Read, "/bar"))

We're putting a WLCG scope into a SciTokens token.