aws-powertools / powertools-lambda-typescript

Powertools is a developer toolkit to implement Serverless best practices and increase developer velocity.
https://docs.powertools.aws.dev/lambda/typescript/latest/
MIT No Attribution
1.56k stars 137 forks source link

Bug: LOG_LEVEL does not work in nodejs lambda #1626

Closed amliuyong closed 1 year ago

amliuyong commented 1 year ago

Expected Behaviour

set ENV of LOG_LEVEL = WARN in lambda function, only WARN or above should be printed, but INFO and DEBUG logs are printed.

Current Behaviour

set ENV of LOG_LEVEL = WARN in lambda function, only WARN or above should be printed, but INFO and DEBUG logs are printed.

Code snippet

const POWERTOOLS_ENVS = {
  POWERTOOLS_SERVICE_NAME: 'ClickStreamAnalyticsOnAWS',
  POWERTOOLS_LOGGER_SAMPLE_RATE: '1',
  POWERTOOLS_LOGGER_LOG_EVENT: 'true',
  LOG_LEVEL: 'WARN',
};

import {
  Logger,
} from '@aws-lambda-powertools/logger';

const logger = new Logger();

public static async start(event: any, context: Context): Promise<EMRJobInfo> {
    try {
      logger.info('enter start');
      const config = this.getConfig();
      logger.info('config', { config });
      if (!config.appIds) {
        logger.warn('appIds is empty, please check env: APP_IDS');
        return {
          jobId: '',
        };
      }
      const jobId = await EMRServerlessUtil.startJobRun(
        event,
        config,
        context,
      );
      logger.info('started job:', { jobId });

      return {
        jobId,
      };
    } catch (error) {
      logger.error(
        'Unexpected error occurred while trying to start EMR Serverless Application',
        error as Error,
      );
      throw error;
    }
  }

Steps to Reproduce

  1. deploy nodejs lambda from CDK
  2. print log using the logger from powertool

Possible Solution

No response

Powertools for AWS Lambda (TypeScript) version

latest

AWS Lambda function runtime

16.x

Packaging format used

npm

Execution logs

timestamp,message
1690253511740,"INIT_START Runtime Version: nodejs:16.v16    Runtime Version ARN: arn:aws:lambda:us-west-2::runtime:c1983f4e9ce3930d3093fa38128e12edac2324f4fe99adfb8e0d5fb6b6afadbc
"
1690253512440,"START RequestId: f0bcdb70-08c1-40ba-a0df-597ba6086f73 Version: $LATEST
"
1690253512607,"{""level"":""INFO"",""message"":""Triggered from schedule event"",""sampling_rate"":1,""service"":""ClickStreamAnalyticsOnAWS"",""timestamp"":""2023-07-25T02:51:52.548Z"",""xray_trace_id"":""1-64bf38c7-750fc2db7678d4ba164b68a1"",""event"":{""version"":""0"",""id"":""19cfafe4-7ebc-f00d-f0da-6034b19a094b"",""detail-type"":""Scheduled Event"",""source"":""aws.events"",""account"":""432014048474"",""time"":""2023-07-25T02:51:45Z"",""region"":""us-west-2"",""resources"":[""arn:aws:events:us-west-2:432014048474:rule/Clickstream-DataProcessin-NestedStackjobSubmitterS-1KWAWONEERPML""],""detail"":{}}}
"
1690253512627,"{""level"":""INFO"",""message"":""enter start"",""sampling_rate"":1,""service"":""ClickStreamAnalyticsOnAWS"",""timestamp"":""2023-07-25T02:51:52.627Z"",""xray_trace_id"":""1-64bf38c7-750fc2db7678d4ba164b68a1""}
"
1690253512628,"{""level"":""INFO"",""message"":""config"",""sampling_rate"":1,""service"":""ClickStreamAnalyticsOnAWS"",""timestamp"":""2023-07-25T02:51:52.627Z"",""xray_trace_id"":""1-64bf38c7-750fc2db7678d4ba164b68a1"",""config"":{""saveInfoToWarehouse"":""false"",""emrServerlessApplicationId"":""00fbt3csunf1ma0l"",""stackId"":""9e2c00e0"",""projectId"":""sensor_test_gycy"",""appIds"":""sensorTest"",""roleArn"":""arn:aws:iam::432014048474:role/Clickstream-DataProcessin-EmrSparkJobSubmitterLamb-17O23DD5E7YE2"",""catalogId"":""432014048474"",""databaseName"":""sensor_test_gycy_9e2c00e0"",""sourceTableName"":""ingestion_events"",""sourceBucketName"":""clickstream-sensor-test-us-west-2"",""sourceS3Prefix"":""clickstream/sensor_test_gycy/data/buffer/"",""sinkBucketName"":""clickstream-sensor-test-us-west-2"",""sinkS3Prefix"":""clickstream/sensor_test_gycy/data/ods/"",""pipelineS3BucketName"":""clickstream-sensor-test-us-west-2"",""pipelineS3Prefix"":""clickstream/sensor_test_gycy/data/pipeline-temp/"",""dataFreshnessInHour"":""7200"",""dataBufferedSeconds"":""30"",""scheduleExpression"":""rate(20 minutes)"",""transformerAndEnrichClassNames"":""software.aws.thirdparty.sesnorsdata.SensorsDataTransformer,software.aws.solution.clickstream.UAEnrichment,software.aws.solution.clickstream.IPEnrichment"",""s3PathPluginJars"":""s3://clickstream-sensor-test-us-west-2/clickstream/sensor_test_gycy/data/pipeline-temp/plugins/9e2c00e0/sensor_test_gycy/built-in/spark-etl-1.1.0.jar,s3://clickstream-sensor-test-us-west-2/clickstream/sensor_test_gycy/data/pipeline-temp/9e2c00e0/sensor_test_gycy/custom-plugins/jars/sensors-data-transformer-1.0.0_20230725105016.jar"",""s3PathPluginFiles"":""s3://clickstream-sensor-test-us-west-2/clickstream/sensor_test_gycy/data/pipeline-temp/plugins/9e2c00e0/sensor_test_gycy/built-in/GeoLite2-City.mmdb,"",""entryPointJar"":""s3://clickstream-sensor-test-us-west-2/clickstream/sensor_test_gycy/data/pipeline-temp/plugins/9e2c00e0/sensor_test_gycy/built-in/spark-etl-1.1.0.jar"",""outputFormat"":""parquet"",""sinkTableName"":""ods_events"",""outputPartitions"":""-1"",""rePartitions"":""200""}}
"
1690253512949,"{""level"":""INFO"",""message"":""funcTags"",""sampling_rate"":1,""service"":""ClickStreamAnalyticsOnAWS"",""timestamp"":""2023-07-25T02:51:52.949Z"",""xray_trace_id"":""1-64bf38c7-750fc2db7678d4ba164b68a1"",""funcTags"":{""aws-solution/clickstream/project"":""sensor_test_gycy"",""aws-solution/name"":""Clickstream"",""aws-solution/version"":""v1.1.0-dev-main-202307231306-fe5c9ff""}}
"
1690253512949,"{""level"":""INFO"",""message"":""readS3ObjectAsJson: s3://clickstream-sensor-test-us-west-2/clickstream/sensor_test_gycy/data/pipeline-temp/sensor_test_gycy/config/spark-config.json"",""sampling_rate"":1,""service"":""ClickStreamAnalyticsOnAWS"",""timestamp"":""2023-07-25T02:51:52.949Z"",""xray_trace_id"":""1-64bf38c7-750fc2db7678d4ba164b68a1""}
"
1690253513088,"{""level"":""WARN"",""message"":""file does not exist"",""sampling_rate"":1,""service"":""ClickStreamAnalyticsOnAWS"",""timestamp"":""2023-07-25T02:51:53.088Z"",""xray_trace_id"":""1-64bf38c7-750fc2db7678d4ba164b68a1""}
"
1690253513088,"{""level"":""INFO"",""message"":""getJobTimestamps enter"",""sampling_rate"":1,""service"":""ClickStreamAnalyticsOnAWS"",""timestamp"":""2023-07-25T02:51:53.088Z"",""xray_trace_id"":""1-64bf38c7-750fc2db7678d4ba164b68a1""}
"
1690253513108,"{""level"":""INFO"",""message"":""readS3ObjectAsJson: s3://clickstream-sensor-test-us-west-2/clickstream/sensor_test_gycy/data/pipeline-temp/job-info/sensor_test_gycy/job-latest.json"",""sampling_rate"":1,""service"":""ClickStreamAnalyticsOnAWS"",""timestamp"":""2023-07-25T02:51:53.107Z"",""xray_trace_id"":""1-64bf38c7-750fc2db7678d4ba164b68a1""}
"
1690253513146,"{""level"":""INFO"",""message"":""found previous job, set startTimestamp to previousTimestamp.endTimestamp"",""sampling_rate"":1,""service"":""ClickStreamAnalyticsOnAWS"",""timestamp"":""2023-07-25T02:51:53.146Z"",""xray_trace_id"":""1-64bf38c7-750fc2db7678d4ba164b68a1""}
"
1690253513146,"{""level"":""INFO"",""message"":""getJobTimestamps return startTimestamp: 1690252283075, endTimestamp: 1690253483088"",""sampling_rate"":1,""service"":""ClickStreamAnalyticsOnAWS"",""timestamp"":""2023-07-25T02:51:53.146Z"",""xray_trace_id"":""1-64bf38c7-750fc2db7678d4ba164b68a1""}
"
1690253513148,"{""level"":""INFO"",""message"":""startJobRunCommandInput"",""sampling_rate"":1,""service"":""ClickStreamAnalyticsOnAWS"",""timestamp"":""2023-07-25T02:51:53.147Z"",""xray_trace_id"":""1-64bf38c7-750fc2db7678d4ba164b68a1"",""startJobRunCommandInput"":{""applicationId"":""00fbt3csunf1ma0l"",""executionRoleArn"":""arn:aws:iam::432014048474:role/Clickstream-DataProcessin-EmrSparkJobSubmitterLamb-17O23DD5E7YE2"",""name"":""1690252283075-b9f86938-8963-4072-a5f0-3718576851fa"",""jobDriver"":{""sparkSubmit"":{""entryPoint"":""s3://clickstream-sensor-test-us-west-2/clickstream/sensor_test_gycy/data/pipeline-temp/plugins/9e2c00e0/sensor_test_gycy/built-in/spark-etl-1.1.0.jar"",""entryPointArguments"":[""false"",""sensor_test_gycy_9e2c00e0"",""ingestion_events"",""1690252283075"",""1690253483088"",""s3://clickstream-sensor-test-us-west-2/clickstream/sensor_test_gycy/data/buffer/"",""s3://clickstream-sensor-test-us-west-2/clickstream/sensor_test_gycy/data/pipeline-temp/sensor_test_gycy/job-data/1690252283075-b9f86938-8963-4072-a5f0-3718576851fa"",""software.aws.thirdparty.sesnorsdata.SensorsDataTransformer,software.aws.solution.clickstream.UAEnrichment,software.aws.solution.clickstream.IPEnrichment"",""s3://clickstream-sensor-test-us-west-2/clickstream/sensor_test_gycy/data/ods/sensor_test_gycy/ods_events/"",""sensor_test_gycy"",""sensorTest"",""7200"",""parquet"",""-1"",""200""],""sparkSubmitParameters"":""--class software.aws.solution.clickstream.DataProcessor --jars s3://clickstream-sensor-test-us-west-2/clickstream/sensor_test_gycy/data/pipeline-temp/plugins/9e2c00e0/sensor_test_gycy/built-in/spark-etl-1.1.0.jar,s3://clickstream-sensor-test-us-west-2/clickstream/sensor_test_gycy/data/pipeline-temp/9e2c00e0/sensor_test_gycy/custom-plugins/jars/sensors-data-transformer-1.0.0_20230725105016.jar --files s3://clickstream-sensor-test-us-west-2/clickstream/sensor_test_gycy/data/pipeline-temp/plugins/9e2c00e0/sensor_test_gycy/built-in/GeoLite2-City.mmdb --conf spark.hadoop.hive.metastore.client.factory.class=com.amazonaws.glue.catalog.metastore.AWSGlueDataCatalogHiveClientFactory --conf spark.driver.cores=4 --conf spark.driver.memory=14g --conf spark.executor.cores=4 --conf spark.executor.memory=14g""}},""configurationOverrides"":{""monitoringConfiguration"":{""s3MonitoringConfiguration"":{""logUri"":""s3://clickstream-sensor-test-us-west-2/clickstream/sensor_test_gycy/data/pipeline-temp/pipeline-logs/sensor_test_gycy/""}}},""tags"":{""aws-solution/clickstream/project"":""sensor_test_gycy"",""aws-solution/name"":""Clickstream"",""aws-solution/version"":""v1.1.0-dev-main-202307231306-fe5c9ff""}}}
"
1690253513567,"{""level"":""INFO"",""message"":""save content to s3://clickstream-sensor-test-us-west-2/clickstream/sensor_test_gycy/data/pipeline-temp/job-info/sensor_test_gycy/job-00fbtmpkdm3sag0m.json"",""sampling_rate"":1,""service"":""ClickStreamAnalyticsOnAWS"",""timestamp"":""2023-07-25T02:51:53.566Z"",""xray_trace_id"":""1-64bf38c7-750fc2db7678d4ba164b68a1""}
"
1690253513606,"{""level"":""INFO"",""message"":""save content to s3://clickstream-sensor-test-us-west-2/clickstream/sensor_test_gycy/data/pipeline-temp/job-info/sensor_test_gycy/job-latest.json"",""sampling_rate"":1,""service"":""ClickStreamAnalyticsOnAWS"",""timestamp"":""2023-07-25T02:51:53.606Z"",""xray_trace_id"":""1-64bf38c7-750fc2db7678d4ba164b68a1""}
"
1690253513606,"{""level"":""INFO"",""message"":""jobInfo"",""sampling_rate"":1,""service"":""ClickStreamAnalyticsOnAWS"",""timestamp"":""2023-07-25T02:51:53.606Z"",""xray_trace_id"":""1-64bf38c7-750fc2db7678d4ba164b68a1"",""jobInfo"":{""$metadata"":{""httpStatusCode"":200,""requestId"":""aaea06e6-b9ed-4fc8-ae1f-4d206bcb1699"",""attempts"":1,""totalRetryDelay"":0},""applicationId"":""00fbt3csunf1ma0l"",""arn"":""arn:aws:emr-serverless:us-west-2:432014048474:/applications/00fbt3csunf1ma0l/jobruns/00fbtmpkdm3sag0m"",""jobRunId"":""00fbtmpkdm3sag0m""}}
"
1690253513607,"{""level"":""INFO"",""message"":""started job:"",""sampling_rate"":1,""service"":""ClickStreamAnalyticsOnAWS"",""timestamp"":""2023-07-25T02:51:53.607Z"",""xray_trace_id"":""1-64bf38c7-750fc2db7678d4ba164b68a1"",""jobId"":""00fbtmpkdm3sag0m""}
"
1690253513607,"{""level"":""INFO"",""message"":""Started Application"",""sampling_rate"":1,""service"":""ClickStreamAnalyticsOnAWS"",""timestamp"":""2023-07-25T02:51:53.607Z"",""xray_trace_id"":""1-64bf38c7-750fc2db7678d4ba164b68a1"",""jobInfo"":{""jobId"":""00fbtmpkdm3sag0m""}}
"
1690253513627,"END RequestId: f0bcdb70-08c1-40ba-a0df-597ba6086f73
"
1690253513627,"REPORT RequestId: f0bcdb70-08c1-40ba-a0df-597ba6086f73   Duration: 1187.78 ms    Billed Duration: 1188 ms    Memory Size: 256 MB Max Memory Used: 124 MB Init Duration: 699.03 ms    
XRAY TraceId: 1-64bf38c7-750fc2db7678d4ba164b68a1   SegmentId: 02aa45772d906a7b Sampled: true   
"
boring-cyborg[bot] commented 1 year ago

Thanks for opening your first issue here! We'll come back to you as soon as we can. In the meantime, check out the #typescript channel on our Powertools for AWS Lambda Discord: Invite link

dreamorosi commented 1 year ago

Hi @amliuyong thank you for opening the issue.

Could you please confirm how you are setting these variables:

const POWERTOOLS_ENVS = {
  POWERTOOLS_SERVICE_NAME: 'ClickStreamAnalyticsOnAWS',
  POWERTOOLS_LOGGER_SAMPLE_RATE: '1',
  POWERTOOLS_LOGGER_LOG_EVENT: 'true',
  LOG_LEVEL: 'WARN',
};

Based on the snippet you have shared it seems that they are in an object and that the constructor below (const logger = new Logger();) has no argument.

In order to set the log level, you have three options:

dreamorosi commented 1 year ago

I have taken the liberty of creating a sample repo to try to reproduce the issue. I wasn't able to reproduce the behavior described as long as the log level is set via one of the three methods I described.

You can find the sample repo here: https://github.com/dreamorosi/repro-1626

If you'd like to try it, you can follow these steps:

Then invoke the three functions and check the logs, which should look like the ones in the image below:

image

github-actions[bot] commented 1 year ago

This issue has not received a response in 2 weeks. If you still think there is a problem, please leave a comment to avoid the issue from automatically closing.

github-actions[bot] commented 1 year ago

Greetings! We are closing this issue because it has been open a long time and hasn’t been updated in a while and may not be getting the attention it deserves. We encourage you to check if this is still an issue in the latest release and if you find that this is still a problem, please feel free to comment or reopen the issue.