Skip to content

Commit fc575a6

Browse files
chmouelchmouel
committed
feat: Add GitHub API log analyzer with structured logging
* Introduced `analyze_github_logs.py`, a new tool to analyze GitHub API request logs. * Modified GitHub API calls to emit structured log entries, including specific `operation` fields like `get_root_tree` and `get_pull_request`. * Included detailed call metadata such as `duration_ms`, `status_code`, `url_path`, and `rate_limit_remaining` in logs. * Added `analyze_github_logs.samples.txt` to provide example log data for the analyzer. * Updated logging documentation to reflect the new log message format, improving clarity for users. * Expanded unit tests for the GitHub profiler to validate the new structured log outputs. Signed-off-by: Chmouel Boudjnah <[email protected]>
1 parent 5b6da41 commit fc575a6

File tree

7 files changed

+195
-54
lines changed

7 files changed

+195
-54
lines changed

‎docs/content/docs/install/logging.md

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -76,7 +76,7 @@ The rate limit monitoring includes:
7676

7777
#### Example Log Messages
7878

79-
```
79+
```console
8080
# Debug level - normal API call logging
8181
DEBUG GitHub API call for repo myorg/myrepo to https://api.github.com/repos/myorg/myrepo/pulls took 245ms, ratelimit-remaining: 4850
8282

‎pkg/provider/github/acl.go

Lines changed: 6 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -20,7 +20,7 @@ func (v *Provider) CheckPolicyAllowing(ctx context.Context, event *info.Event, a
2020
// TODO: caching
2121
opt := github.ListOptions{PerPage: v.PaginedNumber}
2222
for {
23-
members, resp, err := Wrap(v, func() ([]*github.User, *github.Response, error) {
23+
members, resp, err := WrapWithContext(v, "list_team_members_by_slug", func() ([]*github.User, *github.Response, error) {
2424
return v.Client().Teams.ListTeamMembersBySlug(ctx, event.Organization, team, &github.TeamListTeamMembersOptions{ListOptions: opt})
2525
})
2626
if resp.StatusCode == http.StatusNotFound {
@@ -171,7 +171,7 @@ func (v *Provider) aclAllowedOkToTestFromAnOwner(ctx context.Context, event *inf
171171
// aclAllowedOkToTestCurrentEvent only check if this is issue comment event
172172
// have /ok-to-test regex and sender is allowed.
173173
func (v *Provider) aclAllowedOkToTestCurrentComment(ctx context.Context, revent *info.Event, id int64) (bool, error) {
174-
comment, _, err := Wrap(v, func() (*github.IssueComment, *github.Response, error) {
174+
comment, _, err := WrapWithContext(v, "get_issue_comment", func() (*github.IssueComment, *github.Response, error) {
175175
return v.Client().Issues.GetComment(ctx, revent.Organization, revent.Repository, id)
176176
})
177177
if err != nil {
@@ -239,7 +239,7 @@ func (v *Provider) aclCheckAll(ctx context.Context, rev *info.Event) (bool, erro
239239
//
240240
// ex: dependabot, *[bot] etc...
241241
func (v *Provider) checkPullRequestForSameURL(ctx context.Context, runevent *info.Event) (bool, error) {
242-
pr, resp, err := Wrap(v, func() (*github.PullRequest, *github.Response, error) {
242+
pr, resp, err := WrapWithContext(v, "get_pull_request", func() (*github.PullRequest, *github.Response, error) {
243243
return v.Client().PullRequests.Get(ctx, runevent.Organization, runevent.Repository, runevent.PullRequestNumber)
244244
})
245245
if err != nil {
@@ -264,7 +264,7 @@ func (v *Provider) checkSenderOrgMembership(ctx context.Context, runevent *info.
264264
}
265265

266266
for {
267-
users, resp, err := Wrap(v, func() ([]*github.User, *github.Response, error) {
267+
users, resp, err := WrapWithContext(v, "list_org_members", func() ([]*github.User, *github.Response, error) {
268268
return v.Client().Organizations.ListMembers(ctx, runevent.Organization, opt)
269269
})
270270
// If we are 404 it means we are checking a repo owner and not a org so let's bail out with grace
@@ -290,7 +290,7 @@ func (v *Provider) checkSenderOrgMembership(ctx context.Context, runevent *info.
290290

291291
// checkSenderRepoMembership check if user is allowed to run CI.
292292
func (v *Provider) checkSenderRepoMembership(ctx context.Context, runevent *info.Event) (bool, error) {
293-
isCollab, _, err := Wrap(v, func() (bool, *github.Response, error) {
293+
isCollab, _, err := WrapWithContext(v, "is_collaborator", func() (bool, *github.Response, error) {
294294
return v.Client().Repositories.IsCollaborator(ctx,
295295
runevent.Organization,
296296
runevent.Repository,
@@ -323,7 +323,7 @@ func (v *Provider) GetStringPullRequestComment(ctx context.Context, runevent *in
323323
ListOptions: github.ListOptions{PerPage: v.PaginedNumber},
324324
}
325325
for {
326-
comments, resp, err := Wrap(v, func() ([]*github.IssueComment, *github.Response, error) {
326+
comments, resp, err := WrapWithContext(v, "list_issue_comments", func() ([]*github.IssueComment, *github.Response, error) {
327327
return v.Client().Issues.ListComments(ctx, runevent.Organization, runevent.Repository,
328328
prNumber, opt)
329329
})

‎pkg/provider/github/github.go

Lines changed: 17 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -250,7 +250,7 @@ func parseTS(headerTS string) (time.Time, error) {
250250
// but this gives a nice hint to the user into their namespace event of where
251251
// the issue was.
252252
func (v *Provider) checkWebhookSecretValidity(ctx context.Context, cw clockwork.Clock) error {
253-
rl, resp, err := Wrap(v, func() (*github.RateLimits, *github.Response, error) {
253+
rl, resp, err := WrapWithContext(v, "check_rate_limit", func() (*github.RateLimits, *github.Response, error) {
254254
return v.Client().RateLimit.Get(ctx)
255255
})
256256
if resp != nil && resp.StatusCode == http.StatusNotFound {
@@ -340,7 +340,7 @@ func (v *Provider) GetTektonDir(ctx context.Context, runevent *info.Event, path,
340340
v.Logger.Infof("Using PipelineRun definition from source %s %s on commit SHA %s", runevent.TriggerTarget.String(), prInfo, runevent.SHA)
341341
}
342342

343-
rootobjects, _, err := Wrap(v, func() (*github.Tree, *github.Response, error) {
343+
rootobjects, _, err := WrapWithContext(v, "get_root_tree", func() (*github.Tree, *github.Response, error) {
344344
return v.Client().Git.GetTree(ctx, runevent.Organization, runevent.Repository, revision, false)
345345
})
346346
if err != nil {
@@ -364,7 +364,7 @@ func (v *Provider) GetTektonDir(ctx context.Context, runevent *info.Event, path,
364364
// there is a limit on this recursive calls to 500 entries, as documented here:
365365
// https://docs.github.com/en/rest/reference/git#get-a-tree
366366
// so we may need to address it in the future.
367-
tektonDirObjects, _, err := Wrap(v, func() (*github.Tree, *github.Response, error) {
367+
tektonDirObjects, _, err := WrapWithContext(v, "get_tekton_tree", func() (*github.Tree, *github.Response, error) {
368368
return v.Client().Git.GetTree(ctx, runevent.Organization, runevent.Repository, tektonDirSha,
369369
true)
370370
})
@@ -387,7 +387,7 @@ func (v *Provider) GetCommitInfo(ctx context.Context, runevent *info.Event) erro
387387
var commit *github.Commit
388388
sha := runevent.SHA
389389
if runevent.SHA == "" && runevent.HeadBranch != "" {
390-
branchinfo, _, err := Wrap(v, func() (*github.Branch, *github.Response, error) {
390+
branchinfo, _, err := WrapWithContext(v, "get_branch_info", func() (*github.Branch, *github.Response, error) {
391391
return v.Client().Repositories.GetBranch(ctx, runevent.Organization, runevent.Repository, runevent.HeadBranch, 1)
392392
})
393393
if err != nil {
@@ -396,7 +396,7 @@ func (v *Provider) GetCommitInfo(ctx context.Context, runevent *info.Event) erro
396396
sha = branchinfo.Commit.GetSHA()
397397
}
398398
var err error
399-
commit, _, err = Wrap(v, func() (*github.Commit, *github.Response, error) {
399+
commit, _, err = WrapWithContext(v, "get_commit", func() (*github.Commit, *github.Response, error) {
400400
return v.Client().Git.GetCommit(ctx, runevent.Organization, runevent.Repository, sha)
401401
})
402402
if err != nil {
@@ -421,7 +421,7 @@ func (v *Provider) GetFileInsideRepo(ctx context.Context, runevent *info.Event,
421421
ref = runevent.DefaultBranch
422422
}
423423

424-
fp, objects, _, err := WrapGetContents(v, func() (*github.RepositoryContent, []*github.RepositoryContent, *github.Response, error) {
424+
fp, objects, _, err := WrapGetContentsWithContext(v, "get_file_contents", func() (*github.RepositoryContent, []*github.RepositoryContent, *github.Response, error) {
425425
return v.Client().Repositories.GetContents(ctx, runevent.Organization,
426426
runevent.Repository, path, &github.RepositoryContentGetOptions{Ref: ref})
427427
})
@@ -465,7 +465,7 @@ func (v *Provider) concatAllYamlFiles(ctx context.Context, objects []*github.Tre
465465

466466
// getPullRequest get a pull request details.
467467
func (v *Provider) getPullRequest(ctx context.Context, runevent *info.Event) (*info.Event, error) {
468-
pr, _, err := Wrap(v, func() (*github.PullRequest, *github.Response, error) {
468+
pr, _, err := WrapWithContext(v, "get_pull_request", func() (*github.PullRequest, *github.Response, error) {
469469
return v.Client().PullRequests.Get(ctx, runevent.Organization, runevent.Repository, runevent.PullRequestNumber)
470470
})
471471
if err != nil {
@@ -506,7 +506,7 @@ func (v *Provider) GetFiles(ctx context.Context, runevent *info.Event) (changedf
506506
opt := &github.ListOptions{PerPage: v.PaginedNumber}
507507
changedFiles := changedfiles.ChangedFiles{}
508508
for {
509-
repoCommit, resp, err := Wrap(v, func() ([]*github.CommitFile, *github.Response, error) {
509+
repoCommit, resp, err := WrapWithContext(v, "list_pull_request_files", func() ([]*github.CommitFile, *github.Response, error) {
510510
return v.Client().PullRequests.ListFiles(ctx, runevent.Organization, runevent.Repository, runevent.PullRequestNumber, opt)
511511
})
512512
if err != nil {
@@ -537,7 +537,7 @@ func (v *Provider) GetFiles(ctx context.Context, runevent *info.Event) (changedf
537537

538538
if runevent.TriggerTarget == "push" {
539539
changedFiles := changedfiles.ChangedFiles{}
540-
rC, _, err := Wrap(v, func() (*github.RepositoryCommit, *github.Response, error) {
540+
rC, _, err := WrapWithContext(v, "get_commit_files", func() (*github.RepositoryCommit, *github.Response, error) {
541541
return v.Client().Repositories.GetCommit(ctx, runevent.Organization, runevent.Repository, runevent.SHA, &github.ListOptions{})
542542
})
543543
if err != nil {
@@ -565,7 +565,7 @@ func (v *Provider) GetFiles(ctx context.Context, runevent *info.Event) (changedf
565565

566566
// getObject Get an object from a repository.
567567
func (v *Provider) getObject(ctx context.Context, sha string, runevent *info.Event) ([]byte, error) {
568-
blob, _, err := Wrap(v, func() (*github.Blob, *github.Response, error) {
568+
blob, _, err := WrapWithContext(v, "get_blob", func() (*github.Blob, *github.Response, error) {
569569
return v.Client().Git.GetBlob(ctx, runevent.Organization, runevent.Repository, sha)
570570
})
571571
if err != nil {
@@ -589,7 +589,7 @@ func ListRepos(ctx context.Context, v *Provider) ([]string, error) {
589589
opt := &github.ListOptions{PerPage: v.PaginedNumber}
590590
repoURLs := []string{}
591591
for {
592-
repoList, resp, err := Wrap(v, func() (*github.ListRepositories, *github.Response, error) {
592+
repoList, resp, err := WrapWithContext(v, "list_app_repos", func() (*github.ListRepositories, *github.Response, error) {
593593
return v.Client().Apps.ListRepos(ctx, opt)
594594
})
595595
if err != nil {
@@ -609,7 +609,7 @@ func ListRepos(ctx context.Context, v *Provider) ([]string, error) {
609609
func (v *Provider) CreateToken(ctx context.Context, repository []string, event *info.Event) (string, error) {
610610
for _, r := range repository {
611611
split := strings.Split(r, "/")
612-
infoData, _, err := Wrap(v, func() (*github.Repository, *github.Response, error) {
612+
infoData, _, err := WrapWithContext(v, "get_repository", func() (*github.Repository, *github.Response, error) {
613613
return v.Client().Repositories.Get(ctx, split[0], split[1])
614614
})
615615
if err != nil {
@@ -647,7 +647,7 @@ func (v *Provider) isHeadCommitOfBranch(ctx context.Context, runevent *info.Even
647647
"exiting... (hint: did you forget setting a secret on your repo?)")
648648
}
649649

650-
branchInfo, _, err := Wrap(v, func() (*github.Branch, *github.Response, error) {
650+
branchInfo, _, err := WrapWithContext(v, "get_branch", func() (*github.Branch, *github.Response, error) {
651651
return v.Client().Repositories.GetBranch(ctx, runevent.Organization, runevent.Repository, branchName, 1)
652652
})
653653
if err != nil {
@@ -675,7 +675,7 @@ func (v *Provider) CreateComment(ctx context.Context, event *info.Event, commit,
675675

676676
// List last page of the comments of the PR
677677
if updateMarker != "" {
678-
comments, _, err := Wrap(v, func() ([]*github.IssueComment, *github.Response, error) {
678+
comments, _, err := WrapWithContext(v, "list_comments", func() ([]*github.IssueComment, *github.Response, error) {
679679
return v.Client().Issues.ListComments(ctx, event.Organization, event.Repository, event.PullRequestNumber, &github.IssueListCommentsOptions{
680680
ListOptions: github.ListOptions{
681681
Page: 1,
@@ -690,18 +690,19 @@ func (v *Provider) CreateComment(ctx context.Context, event *info.Event, commit,
690690
re := regexp.MustCompile(regexp.QuoteMeta(updateMarker))
691691
for _, comment := range comments {
692692
if re.MatchString(comment.GetBody()) {
693-
if _, _, err := Wrap(v, func() (*github.IssueComment, *github.Response, error) {
693+
if _, _, err := WrapWithContext(v, "edit_comment", func() (*github.IssueComment, *github.Response, error) {
694694
return v.Client().Issues.EditComment(ctx, event.Organization, event.Repository, comment.GetID(), &github.IssueComment{
695695
Body: &commit,
696696
})
697697
}); err != nil {
698698
return err
699699
}
700+
return nil
700701
}
701702
}
702703
}
703704

704-
_, _, err := Wrap(v, func() (*github.IssueComment, *github.Response, error) {
705+
_, _, err := WrapWithContext(v, "create-comment", func() (*github.IssueComment, *github.Response, error) {
705706
return v.Client().Issues.CreateComment(ctx, event.Organization, event.Repository, event.PullRequestNumber, &github.IssueComment{
706707
Body: &commit,
707708
})

‎pkg/provider/github/parse_payload.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -233,7 +233,7 @@ func (v *Provider) getPullRequestsWithCommit(ctx context.Context, sha, org, repo
233233

234234
for {
235235
// Use the "List pull requests associated with a commit" API to check if the commit is part of any open PR
236-
prs, resp, err := Wrap(v, func() ([]*github.PullRequest, *github.Response, error) {
236+
prs, resp, err := WrapWithContext(v, "list_pull_requests_with_commit", func() ([]*github.PullRequest, *github.Response, error) {
237237
return v.Client().PullRequests.ListPullRequestsWithCommit(ctx, org, repo, sha, opts)
238238
})
239239
if err != nil {

‎pkg/provider/github/profiler.go

Lines changed: 57 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -77,8 +77,8 @@ func (v *Provider) checkRateLimit(resp *github.Response) (remaining string) {
7777
return remaining
7878
}
7979

80-
// Wrap a GitHub API call with logging and metrics.
81-
func Wrap[T any](v *Provider, call func() (T, *github.Response, error)) (T, *github.Response, error) {
80+
// WrapWithContext wraps a GitHub API call with logging, metrics, and operation context.
81+
func WrapWithContext[T any](v *Provider, operation string, call func() (T, *github.Response, error)) (T, *github.Response, error) {
8282
// This check ensures we only profile if a logger is available.
8383
if v.Logger == nil {
8484
return call()
@@ -90,23 +90,43 @@ func Wrap[T any](v *Provider, call func() (T, *github.Response, error)) (T, *git
9090

9191
providerMetrics.RecordAPIUsage(v.Logger, v.providerName, v.triggerEvent, v.repo)
9292

93-
repoInfo := ""
93+
// Build structured logging context
94+
logFields := []interface{}{
95+
"operation", operation,
96+
"duration_ms", duration.Milliseconds(),
97+
"provider", "github",
98+
}
99+
100+
// Add repository context if available
94101
if v.repo != nil {
95-
repoInfo = fmt.Sprintf(" for repo %s/%s", v.repo.Namespace, v.repo.Name)
102+
logFields = append(logFields, "repo", fmt.Sprintf("%s/%s", v.repo.Namespace, v.repo.Name))
96103
}
97104

105+
// Add response context if available
98106
if resp != nil {
99107
remaining := v.checkRateLimit(resp)
100-
v.Logger.Debugf("GitHub API call%s to %s took %v, ratelimit-remaining: %s", repoInfo, resp.Request.URL, duration, remaining)
108+
logFields = append(logFields,
109+
"url_path", resp.Request.URL.Path,
110+
"rate_limit_remaining", remaining,
111+
)
112+
if resp.StatusCode > 0 {
113+
logFields = append(logFields, "status_code", resp.StatusCode)
114+
}
115+
}
116+
117+
// Log based on success/failure with appropriate level
118+
if err != nil {
119+
logFields = append(logFields, "error", err.Error())
120+
v.Logger.Errorw("GitHub API call failed", logFields...)
101121
} else {
102-
v.Logger.Debugf("GitHub API call%s took %v", repoInfo, duration)
122+
v.Logger.Debugw("GitHub API call completed", logFields...)
103123
}
104124

105125
return data, resp, err
106126
}
107127

108-
// WrapGetContents wraps the GetContents API call which has a different signature.
109-
func WrapGetContents(v *Provider, call func() (*github.RepositoryContent, []*github.RepositoryContent, *github.Response, error)) (*github.RepositoryContent, []*github.RepositoryContent, *github.Response, error) {
128+
// WrapGetContentsWithContext wraps the GetContents API call with operation context.
129+
func WrapGetContentsWithContext(v *Provider, operation string, call func() (*github.RepositoryContent, []*github.RepositoryContent, *github.Response, error)) (*github.RepositoryContent, []*github.RepositoryContent, *github.Response, error) {
110130
// This check ensures we only profile if a logger is available.
111131
if v.Logger == nil {
112132
return call()
@@ -118,17 +138,42 @@ func WrapGetContents(v *Provider, call func() (*github.RepositoryContent, []*git
118138

119139
providerMetrics.RecordAPIUsage(v.Logger, v.providerName, v.triggerEvent, v.repo)
120140

121-
repoInfo := ""
141+
// Build structured logging context
142+
logFields := []interface{}{
143+
"operation", operation,
144+
"duration_ms", duration.Milliseconds(),
145+
"provider", "github",
146+
}
147+
148+
// Add repository context if available
122149
if v.repo != nil {
123-
repoInfo = fmt.Sprintf(" for repo %s/%s", v.repo.Namespace, v.repo.Name)
150+
logFields = append(logFields, "repo", fmt.Sprintf("%s/%s", v.repo.Namespace, v.repo.Name))
124151
}
125152

153+
// Add response context if available
126154
if resp != nil {
127155
remaining := v.checkRateLimit(resp)
128-
v.Logger.Debugf("GitHub API call%s to %s took %v, ratelimit-remaining: %s", repoInfo, resp.Request.URL, duration, remaining)
156+
logFields = append(logFields,
157+
"url_path", resp.Request.URL.Path,
158+
"rate_limit_remaining", remaining,
159+
)
160+
if resp.StatusCode > 0 {
161+
logFields = append(logFields, "status_code", resp.StatusCode)
162+
}
163+
}
164+
165+
// Log based on success/failure with appropriate level
166+
if err != nil {
167+
logFields = append(logFields, "error", err.Error())
168+
v.Logger.Errorw("GitHub API call failed", logFields...)
129169
} else {
130-
v.Logger.Debugf("GitHub API call%s took %v", repoInfo, duration)
170+
v.Logger.Debugw("GitHub API call completed", logFields...)
131171
}
132172

133173
return file, dir, resp, err
134174
}
175+
176+
// WrapGetContents provides backward compatibility for existing code.
177+
func WrapGetContents(v *Provider, call func() (*github.RepositoryContent, []*github.RepositoryContent, *github.Response, error)) (*github.RepositoryContent, []*github.RepositoryContent, *github.Response, error) {
178+
return WrapGetContentsWithContext(v, "get_contents", call)
179+
}

0 commit comments

Comments
 (0)