Improve log style consistency (#148)

* Improve log style

* Use runWithContext, inline messages

* Make heartbeat message explicit

packages/airnode-feed/src/api-requests/data-provider.test.ts

@@ -36,7 +36,7 @@ describe(makeTemplateRequests.name, () => {
     await makeTemplateRequests(config.triggers.signedApiUpdates[0]!);
 
     expect(logger.warn).toHaveBeenCalledTimes(1);
-    expect(logger.warn).toHaveBeenCalledWith('Failed to make API call', {
+    expect(logger.warn).toHaveBeenCalledWith('Failed to make API call.', {
       endpointName: 'feed',
       errorMessage: 'Invalid API key',
       oisTitle: 'Nodary',

packages/airnode-feed/src/api-requests/data-provider.ts

@@ -18,35 +18,36 @@ export const callApi = async (
   endpointParameters: EndpointParameters,
   apiCredentials: node.ApiCredentials[]
 ) => {
-  return go(async () => {
-    const logContext = { endpointName: endpoint.name, oisTitle: ois.title };
-    logger.debug('Preprocessing API call payload', logContext);
-    const { endpointParameters: processedEndpointParameters } = await preProcessEndpointParameters(
-      endpoint,
-      endpointParameters
-    );
-    logger.debug('Performing API call', { ...logContext, processedEndpointParameters });
-
-    const response = await buildAndExecuteRequest(
-      {
-        endpointName: endpoint.name,
-        ois: ois as BuildRequestOptions['ois'], // TS doesn't realize the types are the same because of https://github.com/microsoft/TypeScript/issues/26627#issuecomment-416046113.
-        parameters: processedEndpointParameters,
-        metadata: null,
-        apiCredentials,
-      },
-      { timeout: API_CALL_TIMEOUT }
-    );
-
-    return response.data;
-  });
+  return go(async () =>
+    logger.runWithContext({ endpointName: endpoint.name, oisTitle: ois.title }, async () => {
+      logger.debug('Preprocessing API call payload.');
+      const { endpointParameters: processedEndpointParameters } = await preProcessEndpointParameters(
+        endpoint,
+        endpointParameters
+      );
+      logger.debug('Performing API call.', { processedEndpointParameters });
+
+      const response = await buildAndExecuteRequest(
+        {
+          endpointName: endpoint.name,
+          ois: ois as BuildRequestOptions['ois'], // TS doesn't realize the types are the same because of https://github.com/microsoft/TypeScript/issues/26627#issuecomment-416046113.
+          parameters: processedEndpointParameters,
+          metadata: null,
+          apiCredentials,
+        },
+        { timeout: API_CALL_TIMEOUT }
+      );
+
+      return response.data;
+    })
+  );
 };
 
 export const makeTemplateRequests = async (signedApiUpdate: SignedApiUpdate): Promise<TemplateResponse[]> => {
   const {
     config: { endpoints, templates, ois: oises, apiCredentials },
   } = getState();
-  logger.debug('Making template requests', signedApiUpdate);
+  logger.debug('Making template requests.', signedApiUpdate);
   const { templateIds } = signedApiUpdate;
 
   // Because each template has the same operation, just take first one as operational template. See the validation logic
@@ -66,7 +67,7 @@ export const makeTemplateRequests = async (signedApiUpdate: SignedApiUpdate): Pr
   const goCallApi = await callApi(ois, operationOisEndpoint, endpointParameters, apiCredentials);
 
   if (!goCallApi.success) {
-    logger.warn(`Failed to make API call`, {
+    logger.warn(`Failed to make API call.`, {
       ...operationEndpoint,
       operationTemplateId,
       errorMessage: goCallApi.error.message,
@@ -87,11 +88,14 @@ export const makeTemplateRequests = async (signedApiUpdate: SignedApiUpdate): Pr
       };
     }, {});
 
-    logger.debug('Processing successful API call', { templateId, operationTemplateId });
+    logger.debug('Processing successful API call.', { templateId, operationTemplateId });
     const goPostProcess = await go(async () => postProcessResponse(apiCallResponse, oisEndpoint, endpointParameters));
     if (!goPostProcess.success) {
-      const message = `Failed to post process successful API call`;
-      logger.warn(message, { templateId, operationTemplateId, errorMessage: goPostProcess.error.message });
+      logger.warn(`Failed to post process successful API call`, {
+        templateId,
+        operationTemplateId,
+        errorMessage: goPostProcess.error.message,
+      });
       return null;
     }
 
@@ -107,7 +111,7 @@ export const makeTemplateRequests = async (signedApiUpdate: SignedApiUpdate): Pr
       });
     });
     if (!goEncodedResponse.success) {
-      logger.error(`Failed to encode response`, {
+      logger.error(`Failed to encode response.`, {
         templateId,
         operationTemplateId,
         response: goPostProcess.data.response,

packages/airnode-feed/src/api-requests/signed-api.test.ts

@@ -53,8 +53,6 @@ describe(postSignedApiData.name, () => {
           message: 'Required',
         },
       ]),
-      signedApiName: 'localhost',
-      updateDelay: 5,
     });
   });
 
@@ -78,8 +76,6 @@ describe(postSignedApiData.name, () => {
     expect(logger.warn).toHaveBeenCalledWith('Failed to make update signed API request.', {
       errorMessage: 'simulated-network-error',
       axiosResponse: {},
-      signedApiName: 'localhost',
-      updateDelay: 5,
     });
   });
 });

packages/airnode-feed/src/api-requests/signed-api.ts

@@ -15,63 +15,66 @@ export const postSignedApiData = async (group: SignedApiNameUpdateDelayGroup) =>
     airnodeWallet,
   } = getState();
   const { signedApiName, templateIds, updateDelay } = group;
-  const logContext = { signedApiName, updateDelay };
 
-  const airnode = airnodeWallet.address;
-  const batchPayloadOrNull = templateIds.map((templateId): SignedApiPayload | null => {
-    // Calculate the reference timestamp based on the current time and update delay.
-    const referenceTimestamp = Date.now() / 1000 - updateDelay;
-    const delayedSignedData = templateValues[templateId]!.get(referenceTimestamp);
-    logger.debug('Getting delayed signed data.', { ...logContext, templateId, referenceTimestamp, delayedSignedData });
-    templateValues[templateId]!.prune();
-    if (isNil(delayedSignedData)) return null;
+  return logger.runWithContext({ signedApiName, updateDelay }, async () => {
+    const airnode = airnodeWallet.address;
+    const batchPayloadOrNull = templateIds.map((templateId): SignedApiPayload | null => {
+      // Calculate the reference timestamp based on the current time and update delay.
+      const referenceTimestamp = Date.now() / 1000 - updateDelay;
+      const delayedSignedData = templateValues[templateId]!.get(referenceTimestamp);
+      logger.debug('Getting delayed signed data.', {
+        templateId,
+        referenceTimestamp,
+        delayedSignedData,
+      });
+      templateValues[templateId]!.prune();
+      if (isNil(delayedSignedData)) return null;
 
-    return { airnode, templateId, beaconId: deriveBeaconId(airnode, templateId), ...delayedSignedData };
-  });
+      return { airnode, templateId, beaconId: deriveBeaconId(airnode, templateId), ...delayedSignedData };
+    });
 
-  const batchPayload = batchPayloadOrNull.filter((payload): payload is SignedApiPayload => !isNil(payload));
+    const batchPayload = batchPayloadOrNull.filter((payload): payload is SignedApiPayload => !isNil(payload));
 
-  if (isEmpty(batchPayload)) {
-    logger.debug('No batch payload found to post. Skipping.', logContext);
-    return { success: true, count: 0 };
-  }
+    if (isEmpty(batchPayload)) {
+      logger.debug('No batch payload found to post. Skipping.');
+      return { success: true, count: 0 };
+    }
 
-  logger.debug('Posting signed API data.', { group, ...logContext });
-  const provider = signedApis.find((a) => a.name === signedApiName)!;
-  const goAxiosRequest = await go<Promise<unknown>, AxiosError>(async () => {
-    logger.debug('Posting batch payload.', { ...logContext, batchPayload });
-    const axiosResponse = await axios.post(provider.url, batchPayload, {
-      headers: {
-        'Content-Type': 'application/json',
-      },
-    });
+    logger.debug('Posting signed API data.', { group });
+    const provider = signedApis.find((a) => a.name === signedApiName)!;
+    const goAxiosRequest = await go<Promise<unknown>, AxiosError>(async () => {
+      logger.debug('Posting batch payload.', { batchPayload });
+      const axiosResponse = await axios.post(provider.url, batchPayload, {
+        headers: {
+          'Content-Type': 'application/json',
+        },
+      });
 
-    return axiosResponse.data;
-  });
-  if (!goAxiosRequest.success) {
-    logger.warn(
-      `Failed to make update signed API request.`,
-      // See: https://axios-http.com/docs/handling_errors
-      {
-        ...logContext,
-        axiosResponse: pick(goAxiosRequest.error.response, ['data', 'status', 'headers']),
-        errorMessage: goAxiosRequest.error.message,
-      }
-    );
-    return { success: false };
-  }
-
-  logger.debug('Parsing response from the signed API.', { ...logContext, axiosResponse: goAxiosRequest.data });
-  const parsedResponse = signedApiResponseSchema.safeParse(goAxiosRequest.data);
-  if (!parsedResponse.success) {
-    logger.warn('Failed to parse response from the signed API.', {
-      ...logContext,
-      errors: parsedResponse.error,
+      return axiosResponse.data;
     });
-    return { success: false };
-  }
+    if (!goAxiosRequest.success) {
+      logger.warn(
+        `Failed to make update signed API request.`,
+        // See: https://axios-http.com/docs/handling_errors
+        {
+          axiosResponse: pick(goAxiosRequest.error.response, ['data', 'status', 'headers']),
+          errorMessage: goAxiosRequest.error.message,
+        }
+      );
+      return { success: false };
+    }
+
+    logger.debug('Parsing response from the signed API.', { axiosResponse: goAxiosRequest.data });
+    const parsedResponse = signedApiResponseSchema.safeParse(goAxiosRequest.data);
+    if (!parsedResponse.success) {
+      logger.warn('Failed to parse response from the signed API.', {
+        errors: parsedResponse.error,
+      });
+      return { success: false };
+    }
 
-  const { count } = parsedResponse.data;
-  logger.info(`Pushed signed data updates to the signed API.`, { ...logContext, count });
-  return { success: true, count };
+    const { count } = parsedResponse.data;
+    logger.info(`Pushed signed data updates to the signed API.`, { count });
+    return { success: true, count };
+  });
 };

packages/airnode-feed/src/fetch-beacon-data.ts

@@ -8,7 +8,7 @@ import { sleep } from './utils';
 import type { SignedApiUpdate } from './validation/schema';
 
 export const initiateFetchingBeaconData = () => {
-  logger.debug('Initiating fetching all beacon data');
+  logger.debug('Initiating fetching all beacon data.');
   const { config } = getState();
 
   return config.triggers.signedApiUpdates.map(async (element) => fetchBeaconDataInLoop(element));
@@ -28,7 +28,11 @@ const fetchBeaconDataInLoop = async (signedApiUpdate: SignedApiUpdate) => {
         // Because there can be multiple triggers for the same template ID it is possible that a race condition occurs,
         // where the (newer) response from a different trigger is put first. This throws, because the signed data must
         // be inserted increasingly by timestamp.
-        logger.warn(`Could not put signed response`, { templateId, signedResponse, errorMessage: goPut.error.message });
+        logger.warn(`Could not put signed response.`, {
+          templateId,
+          signedResponse,
+          errorMessage: goPut.error.message,
+        });
       }
     });
 
@@ -37,7 +41,7 @@ const fetchBeaconDataInLoop = async (signedApiUpdate: SignedApiUpdate) => {
     // delay is taken for each interval, so if the system runs for a sufficiently long time, the requests should happen
     // at random intervals.
     const extraTime = Math.random() * signedApiUpdate.fetchInterval * 1000 * 0.1;
-    logger.debug('Adding extra time to fetch interval', {
+    logger.debug('Adding extra time to fetch interval.', {
       extraTime,
       fetchInterval: signedApiUpdate.fetchInterval * 1000,
     });

packages/airnode-feed/src/heartbeat/heartbeat.test.ts

@@ -41,7 +41,7 @@ describe(logHeartbeat.name, () => {
 
     await logHeartbeat();
 
-    expect(heartbeatLogger.info).toHaveBeenCalledWith('Sending heartbeat log', expectedLogMessage);
+    expect(heartbeatLogger.info).toHaveBeenCalledWith('Sending heartbeat log.', expectedLogMessage);
   });
 });
 

packages/airnode-feed/src/heartbeat/heartbeat.ts

@@ -7,11 +7,15 @@ import { loadRawConfig } from '../validation/config';
 
 import { heartbeatLogger } from './logger';
 
+// Intentionally making the message as constant so that it is not accidentally changed. API integrations team (and maybe
+// other teams, such as monitoring) will listen for this exact message to parse the heartbeat.
+const HEARTBEAT_LOG_MESSAGE = 'Sending heartbeat log.';
+
 export const initiateHeartbeat = () => {
-  logger.debug('Initiating heartbeat loop');
+  logger.debug('Initiating heartbeat loop.');
   setInterval(async () => {
     const goLogHeartbeat = await go(logHeartbeat);
-    if (!goLogHeartbeat.success) logger.error('Failed to log heartbeat', goLogHeartbeat.error);
+    if (!goLogHeartbeat.success) logger.error('Failed to log heartbeat.', goLogHeartbeat.error);
   }, 1000 * 60); // Frequency is hardcoded to 1 minute.
 };
 export interface HeartbeatPayload {
@@ -32,15 +36,15 @@ export const signHeartbeat = async (
   airnodeWallet: ethers.Wallet,
   unsignedHeartbeatPayload: Omit<HeartbeatPayload, 'signature'>
 ) => {
-  logger.debug('Signing heartbeat payload');
+  logger.debug('Signing heartbeat payload.');
   const messageToSign = ethers.utils.arrayify(createHash(stringifyUnsignedHeartbeatPayload(unsignedHeartbeatPayload)));
   return airnodeWallet.signMessage(messageToSign);
 };
 
 export const createHash = (value: string) => ethers.utils.keccak256(ethers.utils.toUtf8Bytes(value));
 
 export const logHeartbeat = async () => {
-  logger.debug('Creating heartbeat log');
+  logger.debug('Creating heartbeat log.');
 
   const rawConfig = loadRawConfig(); // We want to log the raw config, not the one with interpolated secrets.
   const configHash = createHash(JSON.stringify(rawConfig));
@@ -52,7 +56,7 @@ export const logHeartbeat = async () => {
     },
   } = getState();
 
-  logger.debug('Creating heartbeat payload');
+  logger.debug('Creating heartbeat payload.');
   const currentTimestamp = Math.floor(Date.now() / 1000).toString();
   const unsignedHeartbeatPayload = {
     airnode: airnodeWallet.address,
@@ -67,5 +71,5 @@ export const logHeartbeat = async () => {
 
   // The logs are sent to API3 for validation (that the data provider deployed deployed the correct configuration) and
   // monitoring purposes (whether the instance is running).
-  heartbeatLogger.info('Sending heartbeat log', heartbeatPayload);
+  heartbeatLogger.info(HEARTBEAT_LOG_MESSAGE, heartbeatPayload);
 };

packages/airnode-feed/src/sign-template-data.ts

@@ -12,7 +12,7 @@ export type SignedResponse = [TemplateId, SignedData];
 export type TemplateResponse = [TemplateId, ExtractedAndEncodedResponse];
 
 export const signTemplateResponses = async (templateResponses: TemplateResponse[]) => {
-  logger.debug('Signing template responses', { templateResponses });
+  logger.debug('Signing template responses.', { templateResponses });
 
   const signPromises = templateResponses.map(async ([templateId, response]) => {
     const { encodedValue } = response;
@@ -22,9 +22,9 @@ export const signTemplateResponses = async (templateResponses: TemplateResponse[
       signWithTemplateId(getState().airnodeWallet, templateId, timestamp, encodedValue)
     );
     if (!goSignWithTemplateId.success) {
-      const message = `Failed to sign response. Error: "${goSignWithTemplateId.error.message}"`;
-      logger.warn(message, {
+      logger.warn(`Failed to sign response.`, {
         templateId,
+        cause: goSignWithTemplateId.error.message,
       });
       return null;
     }

packages/airnode-feed/src/update-signed-api.ts

@@ -17,7 +17,7 @@ export interface SignedApiNameUpdateDelayGroup {
 }
 
 export const initiateUpdatingSignedApi = () => {
-  logger.debug('Initiating updating signed API');
+  logger.debug('Initiating updating signed API.');
   const { config } = getState();
 
   const signedApiUpdateDelayTemplateIdsMap =

packages/api/src/config.ts

@@ -45,13 +45,13 @@ const fetchConfigFromS3 = async (): Promise<any> => {
     Key: env.AWS_S3_BUCKET_PATH,
   };
 
-  logger.info(`Fetching config from AWS S3 region:${region}...`);
+  logger.info(`Fetching config from AWS S3 region.`, { region });
   const res = await go(async () => s3.getObject(params), { retries: 1 });
   if (!res.success) {
-    logger.error('Error fetching config from AWS S3:', res.error);
+    logger.error('Error fetching config from AWS S3.', res.error);
     throw res.error;
   }
-  logger.info('Config fetched successfully from AWS S3');
+  logger.info('Config fetched successfully from AWS S3.');
   const stringifiedConfig = await res.data.Body!.transformToString();
   return JSON.parse(stringifiedConfig);
 };

packages/api/src/dev-server.ts

@@ -8,7 +8,7 @@ const portSchema = z.coerce.number().int().positive();
 
 const startDevServer = async () => {
   const config = await fetchAndCacheConfig();
-  logger.info('Using configuration', config);
+  logger.info('Using configuration.', config);
 
   const parsedPort = portSchema.safeParse(process.env.DEV_SERVER_PORT);
   let port: number;

packages/api/src/handlers.test.ts

@@ -100,7 +100,7 @@ describe(batchInsertData.name, () => {
       statusCode: 201,
     });
     expect(logger.debug).toHaveBeenCalledWith(
-      'Not storing signed data because signed data with the same timestamp already exists',
+      'Not storing signed data because signed data with the same timestamp already exists.',
       expect.any(Object)
     );
     expect(cacheModule.getCache()[storedSignedData.airnode]![storedSignedData.templateId]!).toHaveLength(1);