How to debug Named Credential Refresh Token Issue

Question

I am implementing an integration with a third party that uses OAuth 2. I am using a 'Named Principal' Named Credential with an Open ID Connect Auth Provider. It works fine to authenticate and make callouts, until the token expires. The connection appears unable to get a refresh token, or if is getting one, it is not successfully using it. My problem is, I cannot figure out how to debug the process... is there any way to see if SF received a Refresh Token during the Auth Flow, and/or is there any way to see if it is getting an error back during the refresh token flow?

I have been working with someone at the third party, and we have reviewed all of the auth settings. They have insisted that their oauth implementation requires no special scope to provide a refresh token, and have conducted tests of their token endpoint using Postman to show that they receive both access and refresh tokens when authenticating. They have asked if I can "show logs or something that say a refresh token is attempted, and this is the outcome," which seems a reasonable request, but I can't figure out any way to obtain such logs. Named credentials are a black box.

The best I can find is the apex logging from a callout in my code; this is with both "Callouts" and "System" set to their maximum level (FINE/FINEST). The log excerpt is edited only to remove client name/url.

09:09:03.161 (168013691)|CALLOUT_REQUEST|[127]|System.HttpRequest[Endpoint=callout:Example_Dev/sal/v1/vendor/subscriptions/22, Method=GET]
09:09:03.263 (263031909)|UNKNOWN|NamedCallout[Named Credential Id=0XA8H000000007v, Named Credential Name=Example_Dev, Status Code=401, Content-Type=application/xml; charset=UTF-8, Response Size bytes=0, Overall Callout Time ms=77, Connect Time ms=0
09:09:03.435 (435277990)|UNKNOWN|NamedCallout[Named Credential Id=0XA8H000000007v, Named Credential Name=Example_Dev, Endpoint=https://test.example.com/sal/v1/vendor/subscriptions/22, Method=GET, External Credential Type=EXTERNAL, HTTP Header Authorization=Method: Bearer - Authorization Credential Hash: -308865696, Content-Type=null, Request Size bytes=-1, Retry on 401=True]
09:09:03.438 (438774228)|UNKNOWN|NamedCallout[Named Credential Id=0XA8H000000007v, Named Credential Name=Example_Dev, Status Code=401, Content-Type=application/xml; charset=UTF-8, Response Size bytes=260, Overall Callout Time ms=175, Connect Time ms=90
09:09:03.161 (568699923)|CALLOUT_RESPONSE|[127]|System.HttpResponse[Status=Unauthorized, StatusCode=401]
09:09:03.161 (589570978)|USER_DEBUG|[217]|DEBUG|ExamplePlatform.Connection.get: line 129, column 1: DEBUG: GET /sal/v1/vendor/subscriptions/22

Update: I ended up setting up a proxy, and changing the authorize and token endpoints in my Open ID Connect Auth Provider config to use the proxy, which forwarded the requests to the 3rd party endpoints. What I found:

• Upon initiating authentication from the Named Credentials, SF calls the auth endpoint which redirects the browser. I haven't logged that traffic yet, not sure it is relevant but that may be a next step.
• Then SF calls the token endpoint and receives an access_token and refresh_token. expired_in is 3600 (seconds; one hour) as expected, so after 65 minutes elapsed I made a request through the named credentials. It failed with 401 Unauthorized
• The proxy showed SF calling the endpoint with grant_type=refresh_token, and passing the wrong refresh token. This provider uses UUIDs as refresh tokens, and the value sent is not the one received an hour before, but it was a UUID, so I'm wondering if Salesforce has cached a stale refresh token?.
• To that end - when I first tried the proxy earlier in the day, prior to testing the authentication step, I had just received a 401 while using the named credential, so I setup the proxy and tried the named credential again. I got the same 401, and the grant_type=refresh_token request made by SF included the same incorrect refresh token as my later attempt.
• The proxy shows no other traffic between the first token request and the incorrect refresh token request.

So far I've not found any resources that reference SF sending the wrong refresh token. What else can I try?

Answer 1

As mentioned in updates to the question, I ended up debugging the issue by changing the "Authorize Endpoint URL" and "Token Endpoint URL" values on my Auth Provider to point to a proxy service that would forward the requests to the actual auth endpoints, while letting me see the traffic. This showed that SF was not sending the correct refresh tokens, at least by the time I started proxying the requests.

I opened a case with SF, but by the time we were able to set up call with a support engineer, the observed behavior had changed. Everything was on hold for about 10 days as I was out of office, so it is unclear why the original behavior changed, but here's what was observed after my return, should it help anyone.

Upon authentication (from the Named Credential Screen), SF would request an access token, and receive an access token and a refresh token. The auth tokens would time out (after 1 hour, as configured) and SF would exchange the correct refresh token for a new access token. This worked repeatedly. We eventually discovered the the authentication service (wso2) was configured by default to expire the refresh tokens after 24 hours. So anytime we had 24 hours with no activity in the sandbox generating callouts, the current refresh token would expire, requiring a user to manually re-authenticate via the Named Credential Screen. We are going to add a scheduled job to make a small API call several times per day to prevent this from happening in future.