Redact JWT signature blocks in logs

[brianaydemir]

Pelican was already redacting JWT signature blocks in server logs. This PR adds the same functionality to the client.

In addition, the client no longer logs the contents of the refresh token it receives from the device code flow. (As far as I'm aware, the refresh token can be an arbitrary string, so we have to parse through the response from the server.)

[jhiemstrawisc]

Similar to #2828, I think the real bug here is that we've identified something that should happen for both Client/Server initialization, but we still perform that initialization separately in each component, leaving room for skew. It seems like initFilterLogging really belongs somewhere central like InitConfigInternal().

[brianaydemir]

It seems like initFilterLogging really belongs somewhere central like InitConfigInternal().

@jhiemstrawisc You might believe in this. It might be a good idea. Perhaps a great one, even. Heavens knows I gave it a try.

But I'm too naïve to make it work. Empirically, FlushLogs must be called before initFilterLogging (or cannot be called after it?) in order for the regex filter to actually be applied to the logs' output.

There must be something I'm not grokking that explains why the ordering of these two functions matters here.

[brianaydemir]

In the meantime, I've rebased this PR on the current main.

Assuming you're starting from a completely fresh setup (in particular, no browser cookies associated with your origin), the minimal test for this functionality is something like:

1. Build the client and the origin.

2. Start up a federation. Make sure debug logging is enabled for the origin.

3. Invoke the client and put an object:

    pelican object put <name> pelican://director:8444/private/data/<name>.$(date +"%s") --debug
   

   The --debug flag is important.

In the client's output, check for lines like the following (watch as I nonchalantly copy my output verbatim, which is the entire point of this PR):

DEBUG[2025-12-30T23:56:11Z] Access token from server response: eyJraWQiOiJXSWVoRjh2OHNfTVhBWFNpY01VWW1ZYWRWNy1yWnRXVnhkS05GS2RQbGk4IiwidHlwIjoiSldUIiwiYWxnIjoiRVMyNTYifQ.eyJ3bGNnLnZlciI6IjEuMCIsImF1ZCI6Imh0dHBzOi8vd2xjZy5jZXJuLmNoL2p3dC92MS9hbnkiLCJzdWIiOiJodHRwOi8vY2lsb2dvbi5vcmcvc2VydmVyQS91c2Vycy8yNzk1MjEiLCJuYmYiOjE3NjcxMzg5NjYsInNjb3BlIjoic3RvcmFnZS5jcmVhdGU6L2RhdGEiLCJpc3MiOiJodHRwczovL29yaWdpbi0wOjg0NDQiLCJleHAiOjE3NjcxMzk5ODAsImlhdCI6MTc2NzEzODk3MSwid2xjZy5ncm91cHMiOnt9LCJqdGkiOiJodHRwczovL29yaWdpbi0wOjg0NDQvYXBpL3YxLjAvaXNzdWVyLzJhMWZmNTYzNzcwZGYxNTU3NDZlY2MwNzZjZTBmMzRlP3R5cGU9YWNjZXNzVG9rZW4mdHM9MTc2NzEzODk3MTQzMyZ2ZXJzaW9uPXYyLjAmbGlmZXRpbWU9MTAwOTAwMCJ9.REDACTED
...
DEBUG[2025-12-30T23:56:11Z] Dumping request: PUT /private/data/go.mod.1767138932?oss.asize=9638 HTTP/1.1                                                         
Host: origin-0:8443                                                                                                                                              
User-Agent: pelican-client/7.19.4                                                                                                                                
Transfer-Encoding: chunked                                                      
Authorization: Bearer eyJraWQiOiJXSWVoRjh2OHNfTVhBWFNpY01VWW1ZYWRWNy1yWnRXVnhkS05GS2RQbGk4IiwidHlwIjoiSldUIiwiYWxnIjoiRVMyNTYifQ.eyJ3bGNnLnZlciI6IjEuMCIsImF1ZCI6Imh0dHBzOi8vd2xjZy5jZXJuLmNoL2p3dC92MS9hbnkiLCJzdWIiOiJodHRwOi8vY2lsb2dvbi5vcmcvc2VydmVyQS91c2Vycy8yNzk1MjEiLCJuYmYiOjE3NjcxMzg5NjYsInNjb3BlIjoic3RvcmFnZS5jcmVhdGU6L2RhdGEiLCJpc3MiOiJodHRwczovL29yaWdpbi0wOjg0NDQiLCJleHAiOjE3NjcxMzk5ODAsImlhdCI6MTc2NzEzODk3MSwid2xjZy5ncm91cHMiOnt9LCJqdGkiOiJodHRwczovL29yaWdpbi0wOjg0NDQvYXBpL3YxLjAvaXNzdWVyLzJhMWZmNTYzNzcwZGYxNTU3NDZlY2MwNzZjZTBmMzRlP3R5cGU9YWNjZXNzVG9rZW4mdHM9MTc2NzEzODk3MTQzMyZ2ZXJzaW9uPXYyLjAmbGlmZXRpbWU9MTAwOTAwMCJ9.REDACTED
Accept-Encoding: gzip

In the server's logs, check for lines like the following:

time="2025-12-30T23:55:52Z" level=debug msg="ID token from auth provider: eyJraWQiOiIyNDRCMjM1RjZCMjhFMzQxMDhEMTAxRUFDNzM2MkM0RSIsInR5cCI6IkpXVCIsImFsZyI6IlJTMjU2In0.eyJzdWIiOiJodHRwOi8vY2lsb2dvbi5vcmcvc2VydmVyQS91c2Vycy8yNzk1MjEiLCJpZHBfbmFtZSI6IlVuaXZlcnNpdHkgb2YgV2lzY29uc2luLU1hZGlzb24iLCJlcHBuIjoiYmF5ZGVtaXJAd2lzYy5lZHUiLCJlcHRpZCI6Imh0dHBzOi8vbG9naW4ud2lzYy5lZHUvaWRwL3NoaWJib2xldGghaHR0cHM6Ly9jaWxvZ29uLm9yZy9zaGliYm9sZXRoIXdwZjk1bzlaMXAxSGVrcC9JdWZOYlMycVJHRT0iLCJpc3MiOiJodHRwczovL2NpbG9nb24ub3JnIiwiZ3JvdXBzIjpbIkNPOm1lbWJlcnM6YWxsIiwiQ086bWVtYmVyczphY3RpdmUiLCJodWItYWRtaW5zIiwiQ086YWRtaW5zIiwidGlnZXItbW9uaXRvcmluZyIsIm9zZy1jby1zcG9uc29ycyIsIkNPOkNPVTpPU1Bvb2wgVXNlzzzzzzElidedBecuaseMyTestUserHasAMillionGroupsZZZZZZ.REDACTED"
...
time="2025-12-30T23:56:06Z" level=info msg=" login=eyJhbGciOiJFUzI1NiIsImtpZCI6IldJZWhGOHY4c19NWEFYU2ljTVVZbVlhZFY3LXJadFdWeGRLTkZLZFBsaTgiLCJ0eXAiOiJKV1QifQ.eyJhdWQiOlsiaHR0cHM6Ly9vcmlnaW4tMDo4NDQ0Il0sImV4cCI6MTc2NzE5NjU1MiwiaWF0IjoxNzY3MTM4OTUyLCJpc3MiOiJodHRwczovL29yaWdpbi0wOjg0NDQiLCJqdGkiOiJ2X3FMbHZkYkRXSVBFcjFoeHRQcFJnIiwibmJmIjoxNzY3MTM4OTUyLCJvaWRjX2lzcyI6Imh0dHBzOi8vY2lsb2dvbi5vcmciLCJvaWRjX3N1YiI6Imh0dHA6Ly9jaWxvZ29uLm9yZy9zZXJ2ZXJBL3VzZXJzLzI3OTUyMSIsInNjb3BlIjoid2ViX3VpLmFjY2VzcyIsInN1YiI6Imh0dHA6Ly9jaWxvZ29uLm9yZy9zZXJ2ZXJBL3VzZXJzLzI3OTUyMSIsInVzZXJfaWQiOiJiMmVlMjc4MSIsIndsY2cudmVyIjoiMS4wIn0.REDACTED" daemon=oa4mp
...
time="2025-12-30T23:56:11Z" level=info msg=" | <origin-0> | OA2ATServlet | trace: jwt has at handler: at=AccessTokenImpl[jti=https://origin-0:8444/api/v1.0/issuer/2a1ff563770df155746ecc076ce0f34e?type=accessToken&ts=1767138971433&version=v2.0&lifetime=1009000, token=eyJraWQiOiJXSWVoRjh2OHNfTVhBWFNpY01VWW1ZYWRWNy1yWnRXVnhkS05GS2RQbGk4IiwidHlwIjoiSldUIiwiYWxnIjoiRVMyNTYifQ.eyJ3bGNnLnZlciI6IjEuMCIsImF1ZCI6Imh0dHBzOi8vd2xjZy5jZXJuLmNoL2p3dC92MS9hbnkiLCJzdWIiOiJodHRwOi8vY2lsb2dvbi5vcmcvc2VydmVyQS91c2Vycy8yNzk1MjEiLCJuYmYiOjE3NjcxMzg5NjYsInNjb3BlIjoic3RvcmFnZS5jcmVhdGU6L2RhdGEiLCJpc3MiOiJodHRwczovL29yaWdpbi0wOjg0NDQiLCJleHAiOjE3NjcxMzk5ODAsImlhdCI6MTc2NzEzODk3MSwid2xjZy5ncm91cHMiOnt9LCJqdGkiOiJodHRwczovL29yaWdpbi0wOjg0NDQvYXBpL3YxLjAvaXNzdWVyLzJhMWZmNTYzNzcwZGYxNTU3NDZlY2MwNzZjZTBmMzRlP3R5cGU9YWNjZXNzVG9rZW4mdHM9MTc2NzEzODk3MTQzMyZ2ZXJzaW9uPXYyLjAmbGlmZXRpbWU9MTAwOTAwMCJ9.REDACTED, lifetime=1009000, type=accessToken, version=v2.0, ts=1767138971433], for claims {" daemon=oa4mp

[brianaydemir]

Another useful test here is to try out the functionality from #2897, e.g., pelican-server server set-logging-level debug 10m.

[jhiemstrawisc]

@brianaydemir I think I got to the bottom of at least one of these GHA failures...

The crux of the failing CI test in the logs is here. The lines following that, up until the ***, hinted that something about this change started dumping Pelican version information into the token file, which means it cannot be passed directly to the client via -t.

Why, you might ask? The initFilterLogging() function cranks up the log level to Debug here to ensure the filter hooks see all messages, but I think this has the side effect of causing the version info to be printed to stdout during client operations like token create (see here). Perhaps the solution is to use config/logging.go::GetEffectiveLogLevel() instead of log.GetLevel()?

Thoughts?

[brianaydemir]

So, it looks like we want the client to print out version information as a diagnostic when debug logging is enabled. Reasonable enough.

I'm not sure I entirely understand how GetEffectiveLogLevel works, but it appears to resolve the immediate issue. But as long as I'm here… I've also made the comparison to the log level a bit more robust, and more importantly, switched the version information to go to the same location as other log messages — which includes the client's configuration dump.

This instance of printing out the client's version is for diagnostic purposes; the output should go to the same location as other diagnostic output (logs), and not clutter stdout — which, as we saw, makes token create harder to use in a script.

[jhiemstrawisc]

This looks good to me. I had a quick chat with @patrickbrophy about the choice to send version info to the log instead of stdout (I recall Patrick working on that last, haven't checked git blame), and he said the change seems reasonable.

I built locally and confirmed version info is logged and that my token signature is being redacted (per the instructions) in the debug output.