Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
nicola-lunghi opened this issue Mar 28, 2024 · 4 comments
Labels
feature New feature or request

Comments

@nicola-lunghi
Copy link

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

image

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/enterprise-server@3.8/rest

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

image

##[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/enterprise-server@3.8/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/enterprise-server@3.8/rest'
    }
  },
  attemptNumber: 4,
  retriesLeft: 0
}
Error: 'Expiration time' claim ('exp') is too far in the future - https://docs.github.com/enterprise-server@3.8/rest
##[debug]Node Action run completed with exit code 1
##[debug]Finishing: Generate a token
@nicola-lunghi
Copy link
Author

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

@gr2m
Copy link
Contributor

gr2m commented Mar 28, 2024

We implemented retries:

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.

@gr2m gr2m changed the title generate token fails but step status is not failing Clarify logs for failed requests that are retried, and add success log messages if previous attempts failed Mar 28, 2024
@gr2m gr2m added the feature New feature or request label Mar 28, 2024
@nicola-lunghi
Copy link
Author

nicola-lunghi commented Mar 28, 2024

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

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

@gr2m
Copy link
Contributor

gr2m commented Apr 1, 2024

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?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
feature New feature or request
Projects
None yet
Development

No branches or pull requests

2 participants