Clarify logs for failed requests that are retried, and add success log messages if previous attempts failed

[nicola-lunghi]

I have the following step in my workflow

   - name: Generate a token
        id: generate-token
        uses: actions/create-github-app-token@v1
        with:
          github-api-url: "https://custom.gitenterprise.com/api/v3"
          app-id: ${{ vars.APP_ID }}
          private-key: ${{ secrets.APP_PRIVATE_KEY }}
          owner: ${{ github.repository_owner }}

The action fails but the step result is not failure

Error from the step
repositories not set, creating token for all repositories for given owner ""
Failed to create token for "" (attempt 1): 'Expiration time' claim ('exp') is too far in the future - https://docs.github.com/[email protected]/rest

The issue seems to be random as relaunching the job with debug enabled now it show the step as failed

##[debug]Evaluating condition for step: 'Generate a token'
##[debug]Evaluating: success()
##[debug]Evaluating success:
##[debug]=> true
##[debug]Result: true
##[debug]Starting: Generate a token
##[debug]Register post job cleanup for action: actions/create-github-app-token@v1
##[debug]Loading inputs
##[debug]Evaluating: vars.APP_ID
##[debug]Evaluating Index:
##[debug]..Evaluating vars:
##[debug]..=> Object
##[debug]..Evaluating String:
##[debug]..=> 'APP_ID'
##[debug]=> '35'
##[debug]Result: '35'
##[debug]Evaluating: secrets.APP_PRIVATE_KEY
##[debug]Evaluating Index:
##[debug]..Evaluating secrets:
##[debug]..=> Object
##[debug]..Evaluating String:
##[debug]..=> 'APP_PRIVATE_KEY'
##[debug]=> '***
##[debug]***
##[debug]***
##[debug]***
##[debug]***
##[debug]***
##[debug]***
##[debug]***
##[debug]***
##[debug]***
##[debug]***
##[debug]***
##[debug]***
##[debug]***
##[debug]***
##[debug]***
##[debug]***
##[debug]***
##[debug]***
##[debug]***
##[debug]***
##[debug]***
##[debug]***
##[debug]***
##[debug]***
##[debug]***
##[debug]***
##[debug]'
RequestError [HttpError]: 'Expiration time' claim ('exp') is too far in the future - https://docs.github.com/[email protected]/rest
    at /scratch/ghe-runners/1/_work/_actions/actions/create-github-app-token/v1/dist/main.cjs:30470:21
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
    at async hook (/scratch/ghe-runners/1/_work/_actions/actions/create-github-app-token/v1/dist/main.cjs:12119:22)
    at async getTokenFromOwner (/scratch/ghe-runners/1/_work/_actions/actions/create-github-app-token/v1/dist/main.cjs:29956:20)
    at async RetryOperation._fn (/scratch/ghe-runners/1/_work/_actions/actions/create-github-app-token/v1/dist/main.cjs:29856:24) {
  status: 401,
  request: {
    method: 'GET',
    url: 'https://custom.gitenterprise.com/api/v3/orgs/XAE/installation',
    headers: {
      accept: 'application/vnd.github.v3+json',
      'user-agent': 'actions/create-github-app-token',
      authorization: 'bearer [REDACTED]'
    },
    request: { hook: [Function: bound hook] AsyncFunction }
  },
  response: {
    url: 'https://custom.gitenterprise.com/api/v3/orgs/XAE/installation',
    status: 401,
    headers: {
      'access-control-allow-origin': '*',
      'access-control-expose-headers': 'ETag, Link, Location, Retry-After, X-GitHub-OTP, X-RateLimit-Limit, X-RateLimit-Remaining, X-RateLimit-Used, X-RateLimit-Resource, X-RateLimit-Reset, X-OAuth-Scopes, X-Accepted-OAuth-Scopes, X-Poll-Interval, X-GitHub-Media-Type, X-GitHub-SSO, X-GitHub-Request-Id, Deprecation, Sunset',
      'content-length': '143',
      'content-security-policy': "default-src 'none'",
      'content-type': 'application/json; charset=utf-8',
      date: 'Thu, 28 Mar 2024 14:36:18 GMT',
      'referrer-policy': 'origin-when-cross-origin, strict-origin-when-cross-origin',
      server: 'GitHub.com',
      'strict-transport-security': 'max-age=31536000; includeSubdomains',
      'x-content-type-options': 'nosniff',
      'x-frame-options': 'deny',
      'x-github-enterprise-version': '3.8.12',
      'x-github-media-type': 'github.v3; format=json',
      'x-github-request-id': '3f6bbd2b-182c-4923-8446-19f93fff227f',
      'x-runtime-rack': '0.018151',
      'x-xss-protection': '0'
    },
    data: {
      message: "'Expiration time' claim ('exp') is too far in the future",
      documentation_url: 'https://docs.github.com/[email protected]/rest'
    }
  },
  attemptNumber: 4,
  retriesLeft: 0
}
Error: 'Expiration time' claim ('exp') is too far in the future - https://docs.github.com/[email protected]/rest
##[debug]Node Action run completed with exit code 1
##[debug]Finishing: Generate a token

[nicola-lunghi]

confirmed without debug the error is printed twice and the step succeed

[gr2m]

We implemented retries:

create-github-app-token/lib/main.js

Lines 79 to 81 in 78e5f2d

	core.info(
	`Failed to create token for "${parsedRepositoryNames}" (attempt ${error.attemptNumber}): ${error.message}`
	);

The messages that are logged out are info logs, they occur multiple times due to the multiple retries. The messages include a the "attempt" not. In the end it worked out, hence the successful step.

But I agree we can make this less confusing by making clear that this error occurred but that we are retrying and also log out when it succeeded.

[nicola-lunghi]

hi
the issue here is that even if the step fails in getting a token the jobs continues as the step is marked as successful (the job fail later because there's no token)

if i enable the debug run instead the step is correctly marked as failed (rerun action -> enable debug logging)

it's not an issue with the error message

if you look at this picture the step is marked as passed

[gr2m]

the job fail later because there's no token

Okay in that case something is definitely broken 🤔 Can you reliably reproduce it? Or do you see the problem intermittently?