Log the X-GitHub-Delivery Header

Author: hexa2k9

app/routes/webhook.py

@@ -18,13 +18,15 @@ def webhook():
     """Handle incoming GitHub webhook events."""
     # https://docs.github.com/en/webhooks/webhook-events-and-payloads
     event_type = request.headers.get('X-GitHub-Event')
+    # https://docs.github.com/en/webhooks/webhook-events-and-payloads#delivery-headers
+    delivery_id = request.headers.get('X-GitHub-Delivery')
 
     # Validate event type
     if not event_type or not isinstance(event_type, str):
         logger.error("Missing or invalid X-GitHub-Event header")
         return jsonify({'status': 'error', 'message': 'Invalid event type'}), 400
 
-    logger.info("Received webhook event: %s", event_type)
+    logger.info("Received webhook event: %s, delivery_id: %s", event_type, delivery_id)
 
     # Handle ping event
     if event_type == 'ping':
@@ -34,32 +36,51 @@ def webhook():
     signature = request.headers.get('X-Hub-Signature-256')
 
     if not verify_github_signature(request.data, signature):
-        logger.error("GitHub webhook signature not successfully verified! Ignoring webhook event.")
+        logger.error(
+            "GitHub webhook signature not successfully verified! "
+            "Ignoring webhook event. delivery_id: %s",
+            delivery_id,
+        )
         return jsonify({'status': 'forbidden', 'message': 'Invalid signature'}), 403
 
     # Validate JSON payload
     try:
         payload = request.json
         if not payload:
-            logger.error("Empty or invalid JSON payload")
+            logger.error("Empty or invalid JSON payload, delivery_id: %s", delivery_id)
             return jsonify({'status': 'error', 'message': 'Invalid JSON payload'}), 400
     except Exception as e:
-        logger.error("Failed to parse JSON payload: %s", str(e))
+        logger.error(
+            "Failed to parse JSON payload: %s, delivery_id: %s",
+            str(e),
+            delivery_id,
+        )
         return jsonify({'status': 'error', 'message': 'Invalid JSON'}), 400
 
     # https://docs.github.com/en/webhooks/webhook-events-and-payloads#workflow_job
     if event_type == 'workflow_job':
-        return handle_workflow_job_event(payload)
+        return handle_workflow_job_event(payload, delivery_id)
     else:
-        logger.warning("Received unknown event type: %s", event_type)
+        logger.warning(
+            "Received unknown event type: %s, delivery_id: %s",
+            event_type,
+            delivery_id,
+        )
         return jsonify({'status': 'ignored'}), 200
 
 
-def handle_workflow_job_event(payload):
+def handle_workflow_job_event(payload, delivery_id=None):
     """Handle workflow_job event."""
     try:
         webhook_service = WebhookService()
         result = webhook_service.handle_workflow_job(payload)
+        logger.info(
+            "Webhook processed successfully, action: %s, runner_name: %s, "
+            "delivery_id: %s",
+            result.get("action"),
+            result.get("runner_name"),
+            delivery_id,
+        )
         return (
             jsonify(
                 {
@@ -71,8 +92,16 @@ def handle_workflow_job_event(payload):
             200,
         )
     except ValueError as e:
-        logger.error("[Webhook] Validation error: %s", str(e))
+        logger.error(
+            "[Webhook] Validation error: %s, delivery_id: %s",
+            str(e),
+            delivery_id,
+        )
         return jsonify({'status': 'error', 'message': 'Invalid payload'}), 400
     except Exception as e:
-        logger.error("[Webhook] Error handling webhook: %s", str(e))
+        logger.error(
+            "[Webhook] Error handling webhook: %s, delivery_id: %s",
+            str(e),
+            delivery_id,
+        )
         return jsonify({'status': 'error', 'message': 'Internal error'}), 500

tests/unit/test_routes_webhook.py

@@ -1,4 +1,5 @@
 import json
+import logging
 from unittest.mock import patch
 
 
@@ -18,7 +19,10 @@ def test_workflow_job_webhook(self, mock_webhook_service, mock_verify, client, s
             '/webhook',
             data=json.dumps(sample_workflow_job_payload),
             content_type='application/json',
-            headers={'X-GitHub-Event': 'workflow_job'}
+            headers={
+                'X-GitHub-Event': 'workflow_job',
+                'X-GitHub-Delivery': 'abc-123-def'
+            }
         )
 
         assert response.status_code == 200
@@ -51,7 +55,10 @@ def test_workflow_job_webhook_created_response(self, mock_webhook_service, mock_
             '/webhook',
             data=json.dumps(payload),
             content_type='application/json',
-            headers={'X-GitHub-Event': 'workflow_job'}
+            headers={
+                'X-GitHub-Event': 'workflow_job',
+                'X-GitHub-Delivery': 'delivery-created-001'
+            }
         )
 
         assert response.status_code == 200
@@ -79,7 +86,10 @@ def test_workflow_job_webhook_deleted_response(self, mock_webhook_service, mock_
             '/webhook',
             data=json.dumps(payload),
             content_type='application/json',
-            headers={'X-GitHub-Event': 'workflow_job'}
+            headers={
+                'X-GitHub-Event': 'workflow_job',
+                'X-GitHub-Delivery': 'delivery-deleted-001'
+            }
         )
 
         assert response.status_code == 200
@@ -111,7 +121,10 @@ def test_workflow_job_webhook_ignored_response(self, mock_webhook_service, mock_
             '/webhook',
             data=json.dumps(payload),
             content_type='application/json',
-            headers={'X-GitHub-Event': 'workflow_job'}
+            headers={
+                'X-GitHub-Event': 'workflow_job',
+                'X-GitHub-Delivery': 'delivery-ignored-001'
+            }
         )
 
         assert response.status_code == 200
@@ -128,7 +141,10 @@ def test_installation_webhook(self, mock_verify, client, sample_installation_pay
             '/webhook',
             data=json.dumps(sample_installation_payload),
             content_type='application/json',
-            headers={'X-GitHub-Event': 'installation'}
+            headers={
+                'X-GitHub-Event': 'installation',
+                'X-GitHub-Delivery': 'delivery-install-001'
+            }
         )
 
         assert response.status_code == 200
@@ -144,7 +160,10 @@ def test_unknown_webhook_event(self, mock_verify, client):
             '/webhook',
             data=json.dumps(payload),
             content_type='application/json',
-            headers={'X-GitHub-Event': 'unknown_event'}
+            headers={
+                'X-GitHub-Event': 'unknown_event',
+                'X-GitHub-Delivery': 'delivery-unknown-001'
+            }
         )
 
         assert response.status_code == 200
@@ -162,7 +181,10 @@ def test_workflow_job_webhook_error(self, mock_webhook_service, mock_verify, cli
             '/webhook',
             data=json.dumps(sample_workflow_job_payload),
             content_type='application/json',
-            headers={'X-GitHub-Event': 'workflow_job'}
+            headers={
+                'X-GitHub-Event': 'workflow_job',
+                'X-GitHub-Delivery': 'delivery-error-001'
+            }
         )
 
         assert response.status_code == 500
@@ -181,7 +203,8 @@ def test_webhook_invalid_signature(self, mock_verify, client):
             content_type='application/json',
             headers={
                 'X-GitHub-Event': 'workflow_job',
-                'X-Hub-Signature-256': 'invalid'
+                'X-Hub-Signature-256': 'invalid',
+                'X-GitHub-Delivery': 'delivery-sig-001'
             }
         )
 
@@ -194,8 +217,168 @@ def test_webhook_ping_event(self, client):
             '/webhook',
             data=json.dumps({'zen': 'test'}),
             content_type='application/json',
-            headers={'X-GitHub-Event': 'ping'}
+            headers={
+                'X-GitHub-Event': 'ping',
+                'X-GitHub-Delivery': 'delivery-ping-001'
+            }
         )
 
         assert response.status_code == 200
         assert response.json['status'] == 'success'
+
+
+class TestWebhookDeliveryIdLogging:
+    """Tests to verify that X-GitHub-Delivery header is logged for correlation."""
+
+    @patch('app.routes.webhook.verify_github_signature')
+    @patch('app.routes.webhook.WebhookService')
+    def test_delivery_id_logged_on_workflow_job(
+        self, mock_webhook_service, mock_verify, client, caplog
+    ):
+        """Test that delivery_id is logged when processing a workflow_job event."""
+        mock_verify.return_value = True
+        mock_service_instance = mock_webhook_service.return_value
+        mock_service_instance.handle_workflow_job.return_value = {
+            "action": "created",
+            "runner_name": "runner-abc123"
+        }
+
+        payload = {
+            'action': 'queued',
+            'workflow_job': {'labels': ['gcp-ubuntu-24.04']},
+            'repository': {
+                'html_url': 'https://github.com/owner/repo',
+                'full_name': 'owner/repo'
+            }
+        }
+
+        with caplog.at_level(logging.INFO, logger='app.routes.webhook'):
+            client.post(
+                '/webhook',
+                data=json.dumps(payload),
+                content_type='application/json',
+                headers={
+                    'X-GitHub-Event': 'workflow_job',
+                    'X-GitHub-Delivery': 'f47ac10b-58cc-4372-a567-0e02b2c3d479'
+                }
+            )
+
+        assert any(
+            'f47ac10b-58cc-4372-a567-0e02b2c3d479' in record.message
+            for record in caplog.records
+        ), "delivery_id was not found in log output"
+
+    @patch('app.routes.webhook.verify_github_signature')
+    def test_delivery_id_logged_on_unknown_event(self, mock_verify, client, caplog):
+        """Test that delivery_id is logged for unknown event types."""
+        mock_verify.return_value = True
+
+        with caplog.at_level(logging.WARNING, logger='app.routes.webhook'):
+            client.post(
+                '/webhook',
+                data=json.dumps({'action': 'test'}),
+                content_type='application/json',
+                headers={
+                    'X-GitHub-Event': 'unknown_event',
+                    'X-GitHub-Delivery': 'aaaabbbb-cccc-dddd-eeee-ffffffffffff'
+                }
+            )
+
+        assert any(
+            'aaaabbbb-cccc-dddd-eeee-ffffffffffff' in record.message
+            for record in caplog.records
+        ), "delivery_id was not found in log output for unknown event"
+
+    @patch('app.routes.webhook.verify_github_signature')
+    def test_delivery_id_logged_on_invalid_signature(self, mock_verify, client, caplog):
+        """Test that delivery_id is logged when signature verification fails."""
+        mock_verify.return_value = False
+
+        with caplog.at_level(logging.ERROR, logger='app.routes.webhook'):
+            client.post(
+                '/webhook',
+                data=json.dumps({'test': 'data'}),
+                content_type='application/json',
+                headers={
+                    'X-GitHub-Event': 'workflow_job',
+                    'X-Hub-Signature-256': 'invalid',
+                    'X-GitHub-Delivery': '11112222-3333-4444-5555-666677778888'
+                }
+            )
+
+        assert any(
+            '11112222-3333-4444-5555-666677778888' in record.message
+            for record in caplog.records
+        ), "delivery_id was not found in log output for invalid signature"
+
+    @patch('app.routes.webhook.verify_github_signature')
+    @patch('app.routes.webhook.WebhookService')
+    def test_delivery_id_logged_on_webhook_error(
+        self, mock_webhook_service, mock_verify, client, caplog
+    ):
+        """Test that delivery_id is logged when webhook processing fails."""
+        mock_verify.return_value = True
+        mock_service_instance = mock_webhook_service.return_value
+        mock_service_instance.handle_workflow_job.side_effect = Exception("boom")
+
+        payload = {
+            'action': 'queued',
+            'workflow_job': {'labels': ['gcp-ubuntu-24.04']},
+            'repository': {
+                'html_url': 'https://github.com/owner/repo',
+                'full_name': 'owner/repo'
+            }
+        }
+
+        with caplog.at_level(logging.ERROR, logger='app.routes.webhook'):
+            client.post(
+                '/webhook',
+                data=json.dumps(payload),
+                content_type='application/json',
+                headers={
+                    'X-GitHub-Event': 'workflow_job',
+                    'X-GitHub-Delivery': 'error-delivery-id-999'
+                }
+            )
+
+        assert any(
+            'error-delivery-id-999' in record.message
+            for record in caplog.records
+        ), "delivery_id was not found in error log output"
+
+    @patch('app.routes.webhook.verify_github_signature')
+    @patch('app.routes.webhook.WebhookService')
+    def test_delivery_id_none_when_header_missing(
+        self, mock_webhook_service, mock_verify, client, caplog
+    ):
+        """Test that delivery_id is logged as None when header is missing."""
+        mock_verify.return_value = True
+        mock_service_instance = mock_webhook_service.return_value
+        mock_service_instance.handle_workflow_job.return_value = {
+            "action": "created",
+            "runner_name": "runner-no-delivery"
+        }
+
+        payload = {
+            'action': 'queued',
+            'workflow_job': {'labels': ['gcp-ubuntu-24.04']},
+            'repository': {
+                'html_url': 'https://github.com/owner/repo',
+                'full_name': 'owner/repo'
+            }
+        }
+
+        with caplog.at_level(logging.INFO, logger='app.routes.webhook'):
+            response = client.post(
+                '/webhook',
+                data=json.dumps(payload),
+                content_type='application/json',
+                headers={'X-GitHub-Event': 'workflow_job'}
+            )
+
+        assert response.status_code == 200
+        # delivery_id should be None in the log since header was not sent
+        assert any(
+            'delivery_id: None' in record.message
+            for record in caplog.records
+        ), "delivery_id: None was not found in log output when header is missing"