feat: Enable detailed GitHub API logging for debugging

docs/content/docs/install/logging.md

@@ -0,0 +1,102 @@
+---
+title: Logging
+weight: 4
+---
+
+## Logging Configuration
+
+Pipelines-as-Code uses a ConfigMap named `pac-config-logging` in its namespace (by default, `pipelines-as-code`) to configure the logging behavior of its controllers.
+
+To view the ConfigMap, use the following command:
+
+```bash
+kubectl get configmap pac-config-logging -n pipelines-as-code
+```
+
+To see the full content of the ConfigMap, run:
+
+```bash
+kubectl get configmap pac-config-logging -n pipelines-as-code -o yaml
+```
+
+The `data` section of the ConfigMap contains the following keys:
+
+* `loglevel.pipelinesascode`: The log level for the `pipelines-as-code-controller` component.
+* `loglevel.pipelines-as-code-webhook`: The log level for the `pipelines-as-code-webhook` component.
+* `loglevel.pac-watcher`: The log level for the `pipelines-as-code-watcher` component.
+
+You can change the log level from `info` to `debug` or any other supported value. For example, to set the log level for the `pipelines-as-code-watcher` to `debug`, run:
+
+```bash
+kubectl patch configmap pac-config-logging -n pipelines-as-code --type json -p '[{"op": "replace", "path": "/data/loglevel.pac-watcher", "value":"debug"}]'
+```
+
+The watcher will automatically pick up the new log level.
+
+If you want to use the same log level for all Pipelines-as-Code components, you can remove the individual `loglevel.*` keys. In this case, all components will use the log level defined in the `level` field of the `zap-logger-config`.
+
+```bash
+kubectl patch configmap pac-config-logging -n pipelines-as-code --type json -p '[{"op": "remove", "path": "/data/loglevel.pac-watcher"}, {"op": "remove", "path": "/data/loglevel.pipelines-as-code-webhook"}, {"op": "remove", "path": "/data/loglevel.pipelinesascode"}]'
+```
+
+The `zap-logger-config` supports the following log levels:
+
+* `debug`: Fine-grained debugging information.
+* `info`: Normal operational logging.
+* `warn`: Unexpected but non-critical errors.
+* `error`: Critical errors that are unexpected during normal operation.
+* `dpanic`: Triggers a panic (crash) in development mode.
+* `panic`: Triggers a panic (crash).
+* `fatal`: Immediately exits with a status of 1.
+
+For more details, see the [Knative logging documentation](https://knative.dev/docs/serving/observability/logging/config-logging).
+
+## Debugging API Interactions
+
+If you need to troubleshoot interactions with the Git provider API (e.g., GitHub), you can enable detailed API request logging. This is useful for debugging permission issues or unexpected API responses.
+
+To enable this feature, set the log level for the `pipelines-as-code-controller` to `debug`. This will cause the controller to log the duration, URL, and remaining rate-limit for each API call it makes.
+
+You can enable this for the main controller with the following `kubectl` command:
+
+```bash
+kubectl patch configmap pac-config-logging -n pipelines-as-code --type json -p '[{"op": "replace", "path": "/data/loglevel.pipelinesascode", "value":"debug"}]'
+```
+
+### Rate Limit Monitoring
+
+When debug logging is enabled, Pipelines-as-Code automatically monitors GitHub API rate limits and provides intelligent warnings when limits are running low. This helps prevent API quota exhaustion and provides early warning for potential service disruptions.
+
+The rate limit monitoring includes:
+
+* **Debug level**: All API calls log their duration, URL, and remaining rate limit count
+* **Info level**: When remaining calls drop below 500, logs include additional context like total limit and reset time
+* **Warning level**: When remaining calls drop below 100, warnings are logged to alert administrators
+* **Error level**: When remaining calls drop below 50, critical alerts are logged indicating immediate attention is needed
+
+#### Example Log Messages
+
+```console
+# Debug level - normal API call logging
+{"level":"debug","ts":"...","caller":"...","msg":"GitHub API call completed","operation":"get_pull_request","duration_ms":23,"provider":"github","repo":"myorg/myrepo","url_path":"/repos/myorg/myrepo/pulls/1","rate_limit_remaining":"4850","status_code":200}
+# Info level - moderate rate limit usage
+{"level":"info","ts":"...","caller":"...","msg":"GitHub API rate limit moderate","repo":"myorg/myrepo","remaining":350,"limit":"5000","reset":"1672531200 (15:30:00 UTC)"}
+# Warning level - low rate limit
+{"level":"warn","ts":"...","caller":"...","msg":"GitHub API rate limit running low","repo":"myorg/myrepo","remaining":75,"limit":"5000","reset":"1672531200 (15:30:00 UTC)"}
+# Error level - critically low rate limit
+{"level":"error","ts":"...","caller":"...","msg":"GitHub API rate limit critically low","repo":"myorg/myrepo","remaining":25,"limit":"5000","reset":"1672531200 (15:30:00 UTC)"}
+```
+
+The rate limit information includes:
+
+* **Remaining calls**: Number of API calls left in the current rate limit window
+* **Total limit**: The maximum number of calls allowed (typically 5000 for authenticated requests)
+* **Reset time**: When the rate limit window resets (shown as Unix timestamp and human-readable time)
+* **Repository context**: Which repository triggered the API call (when available)
+
+This monitoring helps administrators:
+
+* **Prevent service disruptions**: Early warnings allow proactive measures before hitting rate limits
+* **Optimize API usage**: Identify repositories or operations that consume excessive API calls
+* **Plan maintenance windows**: Schedule intensive operations around rate limit reset times
+* **Debug authentication issues**: Rate limit headers can indicate token validity and permissions

docs/content/docs/install/settings.md

@@ -416,91 +416,3 @@ A few settings are available to configure this feature:
   The provider set to `GitHub App` by tkn pac bootstrap, used to detect if a
   GitHub App is already configured when a user runs the bootstrap command a
   second time or the `webhook add` command.
-
-## Logging Configuration
-
-  Pipelines-as-Code uses the ConfigMap named `pac-config-logging` in the same namespace (`pipelines-as-code` by default) as the controllers. To get the ConfigMap use the following command:
-
-  ```bash
-  $ kubectl get configmap pac-config-logging -n pipelines-as-code
-
-  NAME                 DATA   AGE
-  pac-config-logging   4      9m44s
-  ```
-
-  To retrieve the content of the ConfigMap:
-
-  ```bash
-  $ kubectl get configmap pac-config-logging -n pipelines-as-code -o yaml
-
-  apiVersion: v1
-  kind: ConfigMap
-  metadata:
-    labels:
-      app.kubernetes.io/instance: default
-      app.kubernetes.io/part-of: pipelines-as-code
-    name: pac-config-logging
-    namespace: pipelines-as-code
-  data:
-    loglevel.pac-watcher: info
-    loglevel.pipelines-as-code-webhook: info
-    loglevel.pipelinesascode: info
-    zap-logger-config: |
-      {
-        "level": "info",
-        "development": false,
-        "sampling": {
-          "initial": 100,
-          "thereafter": 100
-        },
-        "outputPaths": ["stdout"],
-        "errorOutputPaths": ["stderr"],
-        "encoding": "json",
-        "encoderConfig": {
-          "timeKey": "ts",
-          "levelKey": "level",
-          "nameKey": "logger",
-          "callerKey": "caller",
-          "messageKey": "msg",
-          "stacktraceKey": "stacktrace",
-          "lineEnding": "",
-          "levelEncoder": "",
-          "timeEncoder": "iso8601",
-          "durationEncoder": "",
-          "callerEncoder": ""
-        }
-      }
-  ```
-
-The `loglevel.*` fields define the log level for the controllers:
-
-* loglevel.pipelinesascode - the log level for the pipelines-as-code-controller component
-* loglevel.pipelines-as-code-webhook - the log level for the pipelines-as-code-webhook component
-* loglevel.pac-watcher - the log level for the pipelines-as-code-watcher component
-
-You can change the log level from `info` to `debug` or any other supported values. For example, select the `debug` log level for the pipelines-as-code-watcher component:
-
-```bash
-kubectl patch configmap pac-config-logging -n pipelines-as-code --type json -p '[{"op": "replace", "path": "/data/loglevel.pac-watcher", "value":"debug"}]'
-```
-
-After this command, the controller gets a new log level value.
-If you want to use the same log level for all Pipelines-as-Code components, delete `level.*` values from configmap:
-
-```bash
-kubectl patch configmap pac-config-logging -n pipelines-as-code --type json -p '[  {"op": "remove", "path": "/data/loglevel.pac-watcher"},  {"op": "remove", "path": "/data/loglevel.pipelines-as-code-webhook"},  {"op": "remove", "path": "/data/loglevel.pipelinesascode"}]'
-```
-
-In this case, all Pipelines-as-Code components get a common log level from `zap-logger-config` - `level` field from the json.
-
-`zap-logger-config` supports the following log levels:
-
-* debug - fine-grained debugging
-* info - normal logging
-* warn - unexpected but non-critical errors
-* error - critical errors; unexpected during normal operation
-* dpanic - in debug mode, trigger a panic (crash)
-* panic - trigger a panic (crash)
-* fatal - immediately exit with exit status 1 (failure)
-
-See more: <https://knative.dev/docs/serving/observability/logging/config-logging>

hack/dev/kind/install.sh

@@ -197,6 +197,7 @@ function configure_pac() {
     kubectl patch configmap -n pipelines-as-code -p \
       '{"data":{"catalog-1-type": "artifacthub", "catalog-1-id": "pachub", "catalog-1-name": "pipelines-as-code", "catalog-1-url": "https://artifacthub.io"}}' \
       --type merge pipelines-as-code
+  kubectl patch configmap pac-config-logging -n pipelines-as-code --type json -p '[{"op": "replace", "path": "/data/loglevel.pipelinesascode", "value":"debug"}]'
   set +x
   if [[ -n ${PAC_PASS_SECRET_FOLDER} ]]; then
     echo "Installing PAC secrets"

hack/gh-workflow-ci.sh

@@ -3,6 +3,8 @@
 # Helper script for GitHub Actions CI, used from e2e tests.
 set -exufo pipefail
 
+export PAC_API_INSTRUMENTATION_DIR=/tmp/api-instrumentation
+
 create_pac_github_app_secret() {
   # Read from environment variables instead of arguments
   local app_private_key="${PAC_GITHUB_PRIVATE_KEY}"
@@ -93,7 +95,7 @@ run_e2e_tests() {
 
 output_logs() {
   if command -v "snazy" >/dev/null 2>&1; then
-    snazy --skip-line-regexp="^(Reconcile (succeeded|error)|Updating webhook)" /tmp/logs/pac-pods.log
+    snazy --extra-fields --skip-line-regexp="^(Reconcile (succeeded|error)|Updating webhook)" /tmp/logs/pac-pods.log
   else
     # snazy for the poors
     python -c "import sys,json,datetime; [print(f'• { (lambda t: datetime.datetime.fromisoformat(t.rstrip(\"Z\")).strftime(\"%H:%M:%S\") if isinstance(t,str) else datetime.datetime.fromtimestamp(t).strftime(\"%H:%M:%S\"))(json.loads(l.strip())[\"ts\"] )} {json.loads(l.strip()).get(\"msg\",\"\")}') if l.strip().startswith('{') else print(l.strip()) for l in sys.stdin]" \
@@ -127,6 +129,11 @@ collect_logs() {
     kubectl -n ${ns} get events >/tmp/logs/ns/${ns}/events
   done
 
+  if [[ -d ${PAC_API_INSTRUMENTATION_DIR} && -n "$(ls -A ${PAC_API_INSTRUMENTATION_DIR})" ]]; then
+    echo "Copying API instrumentation logs from ${PAC_API_INSTRUMENTATION_DIR}"
+    cp -a ${PAC_API_INSTRUMENTATION_DIR} /tmp/logs/$(basename ${PAC_API_INSTRUMENTATION_DIR})
+  fi
+
   for url in "${test_gitea_smee_url}" "${github_ghe_smee_url}"; do
     find /tmp/logs -type f -exec grep -l "${url}" {} \; | xargs -r sed -i "s|${url}|SMEE_URL|g"
   done

pkg/provider/github/acl.go

@@ -20,7 +20,9 @@ func (v *Provider) CheckPolicyAllowing(ctx context.Context, event *info.Event, a
 		// TODO: caching
 		opt := github.ListOptions{PerPage: v.PaginedNumber}
 		for {
-			members, resp, err := v.Client().Teams.ListTeamMembersBySlug(ctx, event.Organization, team, &github.TeamListTeamMembersOptions{ListOptions: opt})
+			members, resp, err := wrapAPI(v, "list_team_members_by_slug", func() ([]*github.User, *github.Response, error) {
+				return v.Client().Teams.ListTeamMembersBySlug(ctx, event.Organization, team, &github.TeamListTeamMembersOptions{ListOptions: opt})
+			})
 			if resp.StatusCode == http.StatusNotFound {
 				// we explicitly disallow the policy when the team is not found
 				// maybe we should ignore it instead? i'd rather keep this explicit
@@ -169,7 +171,9 @@ func (v *Provider) aclAllowedOkToTestFromAnOwner(ctx context.Context, event *inf
 // aclAllowedOkToTestCurrentEvent only check if this is issue comment event
 // have /ok-to-test regex and sender is allowed.
 func (v *Provider) aclAllowedOkToTestCurrentComment(ctx context.Context, revent *info.Event, id int64) (bool, error) {
-	comment, _, err := v.Client().Issues.GetComment(ctx, revent.Organization, revent.Repository, id)
+	comment, _, err := wrapAPI(v, "get_issue_comment", func() (*github.IssueComment, *github.Response, error) {
+		return v.Client().Issues.GetComment(ctx, revent.Organization, revent.Repository, id)
+	})
 	if err != nil {
 		return false, err
 	}
@@ -235,7 +239,9 @@ func (v *Provider) aclCheckAll(ctx context.Context, rev *info.Event) (bool, erro
 //
 //	ex: dependabot, *[bot] etc...
 func (v *Provider) checkPullRequestForSameURL(ctx context.Context, runevent *info.Event) (bool, error) {
-	pr, resp, err := v.Client().PullRequests.Get(ctx, runevent.Organization, runevent.Repository, runevent.PullRequestNumber)
+	pr, resp, err := wrapAPI(v, "get_pull_request", func() (*github.PullRequest, *github.Response, error) {
+		return v.Client().PullRequests.Get(ctx, runevent.Organization, runevent.Repository, runevent.PullRequestNumber)
+	})
 	if err != nil {
 		return false, err
 	}
@@ -258,7 +264,9 @@ func (v *Provider) checkSenderOrgMembership(ctx context.Context, runevent *info.
 	}
 
 	for {
-		users, resp, err := v.Client().Organizations.ListMembers(ctx, runevent.Organization, opt)
+		users, resp, err := wrapAPI(v, "list_org_members", func() ([]*github.User, *github.Response, error) {
+			return v.Client().Organizations.ListMembers(ctx, runevent.Organization, opt)
+		})
 		// If we are 404 it means we are checking a repo owner and not a org so let's bail out with grace
 		if resp != nil && resp.StatusCode == http.StatusNotFound {
 			return false, nil
@@ -282,10 +290,12 @@ func (v *Provider) checkSenderOrgMembership(ctx context.Context, runevent *info.
 
 // checkSenderRepoMembership check if user is allowed to run CI.
 func (v *Provider) checkSenderRepoMembership(ctx context.Context, runevent *info.Event) (bool, error) {
-	isCollab, _, err := v.Client().Repositories.IsCollaborator(ctx,
-		runevent.Organization,
-		runevent.Repository,
-		runevent.Sender)
+	isCollab, _, err := wrapAPI(v, "is_collaborator", func() (bool, *github.Response, error) {
+		return v.Client().Repositories.IsCollaborator(ctx,
+			runevent.Organization,
+			runevent.Repository,
+			runevent.Sender)
+	})
 
 	return isCollab, err
 }
@@ -313,8 +323,10 @@ func (v *Provider) GetStringPullRequestComment(ctx context.Context, runevent *in
 		ListOptions: github.ListOptions{PerPage: v.PaginedNumber},
 	}
 	for {
-		comments, resp, err := v.Client().Issues.ListComments(ctx, runevent.Organization, runevent.Repository,
-			prNumber, opt)
+		comments, resp, err := wrapAPI(v, "list_issue_comments", func() ([]*github.IssueComment, *github.Response, error) {
+			return v.Client().Issues.ListComments(ctx, runevent.Organization, runevent.Repository,
+				prNumber, opt)
+		})
 		if err != nil {
 			return nil, err
 		}