Reshuffled logs to emit less info level logs (#604)

Reduced the number of excessive info logs to save on logging costs.

---------

Co-authored-by: Chris Raible <chris@ghost.org>

Author: JoeeGrigg

src/plugins/logging.ts

@@ -25,9 +25,14 @@ async function loggingPlugin(fastify: FastifyInstance) {
         const rawRequestId = request.headers['x-request-id'];
         const requestId = Array.isArray(rawRequestId) ? rawRequestId[0] : rawRequestId;
 
+        // Extract site UUID if present
+        const rawSiteUuid = request.headers['x-site-uuid'];
+        const siteUuid = Array.isArray(rawSiteUuid) ? rawSiteUuid[0] : rawSiteUuid;
+
         const childContext: Record<string, unknown> = {
             ...traceContext,
-            ...(requestId && {requestId})
+            ...(requestId && {requestId}),
+            ...(siteUuid && {siteUuid})
         };
 
         if (Object.keys(childContext).length > 0) {
@@ -61,7 +66,7 @@ async function loggingPlugin(fastify: FastifyInstance) {
     });
 
     fastify.addHook('onResponse', async (request, reply) => {
-        request.log.info({
+        request.log.debug({
             event: 'RequestCompleted',
             httpRequest: {
                 requestMethod: request.method,

src/services/batch-worker/BatchWorker.ts

@@ -88,16 +88,11 @@ class BatchWorker {
                 processedEvent: pageHitProcessed
             });
 
-            logger.info({
-                event: 'WorkerProcessedMessage',
-                messageId: message.id,
-                eventId: pageHitProcessed.payload.event_id
-            });
-
             logger.debug({
-                event: 'WorkerProcessedMessageDetails',
+                event: 'WorkerProcessedMessage',
                 messageId: message.id,
                 messageData: this.getMessageData(message),
+                eventId: pageHitProcessed.payload.event_id,
                 pageHitProcessed
             });
 

src/services/events/publisher.ts

@@ -33,7 +33,7 @@ class EventPublisher {
 
             const messageId = await this.pubsub.topic(topic).publishMessage(message);
 
-            logger.info({
+            logger.debug({
                 event: 'EventPublishSuccessful',
                 messageId,
                 topic,

src/services/events/publisherUtils.ts

@@ -4,12 +4,27 @@ import {publishEvent} from './publisher';
 export const publishPageHitRaw = async (request: PageHitRequestType, payload: PageHitRaw): Promise<void> => {
     const topic = process.env.PUBSUB_TOPIC_PAGE_HITS_RAW as string;
     if (topic) {
-        request.log.info({event: 'PublishingPageHitRawEvent', event_id: payload.payload.event_id});
-        request.log.debug({event: 'PublishingPageHitRawEventPayload', payload});
-        await publishEvent({
+        const eventId = payload.payload.event_id ?? 'unknown';
+        request.log.debug({
+            event: 'PublishingPageHitRawEvent',
+            event_id: eventId,
+            payload
+        });
+        const messageId = await publishEvent({
             topic,
             payload,
             logger: request.log
         });
+        request.log.info({
+            event: 'PublishedPageHitRawEvent',
+            message_id: messageId,
+            event_id: eventId
+        });
+        request.log.debug({
+            event: 'PublishedPageHitRawEventPayload',
+            event_id: eventId,
+            message_id: messageId,
+            payload
+        });
     }
 };

test/unit/plugins/logging.test.ts

@@ -154,6 +154,41 @@ describe('Logging Plugin', () => {
         });
     });
 
+    describe('x-site-uuid header', () => {
+        it('should include siteUuid in IncomingRequest log when x-site-uuid header is provided', async () => {
+            const siteUuid = '12345678-1234-1234-1234-123456789012';
+
+            await app.inject({
+                method: 'GET',
+                url: '/test',
+                headers: {
+                    'x-site-uuid': siteUuid
+                }
+            });
+
+            const incomingRequestLog = parseLogs().find(
+                log => log.event === 'IncomingRequest'
+            );
+
+            expect(incomingRequestLog).toBeDefined();
+            expect(incomingRequestLog?.siteUuid).toBe(siteUuid);
+        });
+
+        it('should not include siteUuid in IncomingRequest log when x-site-uuid header is not provided', async () => {
+            await app.inject({
+                method: 'GET',
+                url: '/test'
+            });
+
+            const incomingRequestLog = parseLogs().find(
+                log => log.event === 'IncomingRequest'
+            );
+
+            expect(incomingRequestLog).toBeDefined();
+            expect(incomingRequestLog).not.toHaveProperty('siteUuid');
+        });
+    });
+
     describe('request body logging', () => {
         it('should log request body for requests over 600 KB', async () => {
             const largeBody = {

test/unit/services/batch-worker/batch-worker.test.ts

@@ -145,8 +145,8 @@ describe('BatchWorker', () => {
 
             await (batchWorker as any).handleMessage(mockMessage);
 
-            // Should log info message with just event_id for successful processing
-            expect(logger.info).toHaveBeenCalledWith(
+            // Should log debug message with event details for successful processing
+            expect(logger.debug).toHaveBeenCalledWith(
                 expect.objectContaining({
                     event: 'WorkerProcessedMessage',
                     messageId: mockMessage.id,
@@ -157,7 +157,7 @@ describe('BatchWorker', () => {
             // Should log debug message with full payload
             expect(logger.debug).toHaveBeenCalledWith(
                 expect.objectContaining({
-                    event: 'WorkerProcessedMessageDetails',
+                    event: 'WorkerProcessedMessage',
                     messageId: mockMessage.id,
                     messageData: validPageHitRawData,
                     pageHitProcessed: expect.objectContaining({

test/unit/services/events/publisherUtils.test.ts

@@ -32,7 +32,7 @@ describe('publisherUtils', () => {
     });
 
     describe('publishPageHitRaw', () => {
-        it('should log info message with only event_id on successful publish', async () => {
+        it('should log debug payload details on successful publish', async () => {
             const payload = {
                 payload: {
                     event_id: 'test-event-123',
@@ -44,12 +44,12 @@ describe('publisherUtils', () => {
 
             await publishPageHitRaw(mockRequest, payload);
 
-            expect(mockRequest.log.info).toHaveBeenCalledWith(
-                {event: 'PublishingPageHitRawEvent', event_id: 'test-event-123'}
-            );
-            expect(mockRequest.log.info).not.toHaveBeenCalledWith(
-                expect.objectContaining({payload: expect.anything()}),
-                expect.anything()
+            expect(mockRequest.log.debug).toHaveBeenCalledWith(
+                {
+                    event: 'PublishingPageHitRawEvent',
+                    event_id: 'test-event-123',
+                    payload
+                }
             );
         });