def test_log_dict_xray_is_updated_when_tracing_id_changes(
stdout, monkeypatch, service_name):
# GIVEN a logger is initialized within a Lambda function with X-Ray enabled
trace_id = "1-5759e988-bd862e3fe1be46a994272793"
trace_header = f"Root={trace_id};Parent=53995c3f42cd8ad8;Sampled=1"
monkeypatch.setenv(name="_X_AMZN_TRACE_ID", value=trace_header)
logger = Logger(service=service_name, stream=stdout)
# WHEN logging a message
logger.info("foo")
# and Trace ID changes to mimick a new invocation
trace_id_2 = "1-5759e988-bd862e3fe1be46a949393982437"
trace_header_2 = f"Root={trace_id_2};Parent=53995c3f42cd8ad8;Sampled=1"
monkeypatch.setenv(name="_X_AMZN_TRACE_ID", value=trace_header_2)
logger.info("foo bar")
log_dict, log_dict_2 = [
json.loads(line.strip()) for line in stdout.getvalue().split("\n")
if line
]
# THEN `xray_trace_id`` key should be different in both invocations
assert log_dict["xray_trace_id"] == trace_id
assert log_dict_2["xray_trace_id"] == trace_id_2
monkeypatch.delenv(name="_X_AMZN_TRACE_ID")
def test_logging_various_primitives(stdout, service_name, message):
# GIVEN a logger with default settings
logger = Logger(service=service_name, stream=stdout)
# WHEN logging a message of multiple common types
# THEN it should raise no serialization/deserialization error
logger.info(message)
json.loads(stdout.getvalue())
def test_with_json_message(stdout):
logger = Logger(stream=stdout)
msg = {"x": "isx"}
logger.info(json.dumps(msg))
log_dict = json.loads(stdout.getvalue())
assert msg == log_dict["message"]
def test_setup_no_service_name(stdout):
# GIVEN no service is explicitly defined
# WHEN logger is setup
# THEN service field should be "service_undefined"
logger = Logger(stream=stdout)
logger.info("Hello")
log = json.loads(stdout.getvalue())
assert "service_undefined" == log["service"]
def test_setup_no_service_name(stdout):
# GIVEN Logger is initialized
# WHEN no service is explicitly defined
logger = Logger(stream=stdout)
logger.info("Hello")
# THEN service field should be "service_undefined"
log = capture_logging_output(stdout)
assert "service_undefined" == log["service"]
def test_setup_service_name(stdout, service_name):
# GIVEN Logger is initialized
# WHEN service is explicitly defined
logger = Logger(service=service_name, stream=stdout)
logger.info("Hello")
# THEN service field should be equals service given
log = capture_logging_output(stdout)
assert service_name == log["service"]
def test_setup_service_name(root_logger, stdout):
# GIVEN service is explicitly defined
# WHEN logger is setup
# THEN service field should be equals service given
service_name = "payment"
logger = Logger(service=service_name, stream=stdout)
logger.info("Hello")
log = json.loads(stdout.getvalue())
assert service_name == log["service"]
def test_log_dict_key_custom_seq(stdout):
# GIVEN a logger configuration with log_record_order set to ["message"]
logger = Logger(stream=stdout, log_record_order=["message"])
# WHEN logging a message
logger.info("Message")
log_dict: dict = json.loads(stdout.getvalue())
# THEN the first key should be "message"
assert list(log_dict.keys())[0] == "message"
def test_log_dict_key_seq(stdout):
# GIVEN the default logger configuration
logger = Logger(stream=stdout)
# WHEN logging a message
logger.info("Message")
log_dict: dict = json.loads(stdout.getvalue())
# THEN the beginning key sequence must be `level,location,message,timestamp`
assert ",".join(list(log_dict.keys())[:4]) == "level,location,message,timestamp"
def test_log_formatting(stdout, service_name):
# GIVEN a logger with default settings
logger = Logger(service=service_name, stream=stdout)
# WHEN logging a message with formatting
logger.info('["foo %s %d %s", null]', "bar", 123, [1, None])
log_dict: dict = json.loads(stdout.getvalue())
# THEN the formatting should be applied (NB. this is valid json, but hasn't be parsed)
assert log_dict["message"] == '["foo bar 123 [1, None]", null]'
def test_log_dict_xray_is_not_present_when_tracing_is_disabled(stdout, monkeypatch):
# GIVEN a logger is initialized within a Lambda function with X-Ray disabled (default)
logger = Logger(stream=stdout)
# WHEN logging a message
logger.info("foo")
log_dict: dict = json.loads(stdout.getvalue())
# THEN `xray_trace_id`` key should not be present
assert "xray_trace_id" not in log_dict
def test_setup_service_env_var(monkeypatch, stdout, service_name):
# GIVEN Logger is initialized
# WHEN service is explicitly defined via POWERTOOLS_SERVICE_NAME env
monkeypatch.setenv("POWERTOOLS_SERVICE_NAME", service_name)
logger = Logger(stream=stdout)
logger.info("Hello")
# THEN service field should be equals POWERTOOLS_SERVICE_NAME value
log = capture_logging_output(stdout)
assert service_name == log["service"]
def test_log_dict_key_strip_nones(stdout):
# GIVEN a logger confirmation where we set `location` and `timestamp` to None
# Note: level, sampling_rate and service can not be suppressed
logger = Logger(stream=stdout, level=None, location=None, timestamp=None, sampling_rate=None, service=None)
# WHEN logging a message
logger.info("foo")
log_dict: dict = json.loads(stdout.getvalue())
# THEN the keys should only include `level`, `message`, `service`, `sampling_rate`
assert sorted(log_dict.keys()) == ["level", "message", "sampling_rate", "service"]
def test_log_custom_std_log_attribute(stdout, service_name):
# GIVEN a logger where we have a standard log attr process
# https://docs.python.org/3/library/logging.html#logrecord-attributes
logger = Logger(service=service_name, stream=stdout, process="%(process)d")
# WHEN logging a message
logger.info("foo")
log_dict: dict = json.loads(stdout.getvalue())
# THEN process key should be evaluated
assert "%" not in log_dict["process"]
def test_setup_service_env_var(monkeypatch, stdout):
# GIVEN service is explicitly defined via POWERTOOLS_SERVICE_NAME env
# WHEN logger is setup
# THEN service field should be equals POWERTOOLS_SERVICE_NAME value
service_name = "payment"
monkeypatch.setenv("POWERTOOLS_SERVICE_NAME", service_name)
logger = Logger(stream=stdout)
logger.info("Hello")
log = json.loads(stdout.getvalue())
assert service_name == log["service"]
def test_log_custom_formatting(stdout):
# GIVEN a logger where we have a custom `location`, 'datefmt' format
logger = Logger(stream=stdout, location="[%(funcName)s] %(module)s", datefmt="fake-datefmt")
# WHEN logging a message
logger.info("foo")
log_dict: dict = json.loads(stdout.getvalue())
# THEN the `location` and "timestamp" should match the formatting
assert log_dict["location"] == "[test_log_custom_formatting] test_aws_lambda_logging"
assert log_dict["timestamp"] == "fake-datefmt"
def test_logger_do_not_log_twice_when_root_logger_is_setup(stdout):
# GIVEN Lambda configures the root logger with a handler
root_logger = logging.getLogger()
root_logger.addHandler(logging.StreamHandler(stream=stdout))
# WHEN we create a new Logger and child Logger
logger = Logger(stream=stdout)
child_logger = Logger(child=True, stream=stdout)
logger.info("hello")
child_logger.info("hello again")
# THEN it should only contain only two log entries
# since child's log records propagated to root logger should be rejected
logs = list(stdout.getvalue().strip().split("\n"))
assert len(logs) == 2
def test_log_dict_xray_is_present_when_tracing_is_enabled(stdout, monkeypatch):
# GIVEN a logger is initialized within a Lambda function with X-Ray enabled
trace_id = "1-5759e988-bd862e3fe1be46a994272793"
trace_header = f"Root={trace_id};Parent=53995c3f42cd8ad8;Sampled=1"
monkeypatch.setenv(name="_X_AMZN_TRACE_ID", value=trace_header)
logger = Logger(stream=stdout)
# WHEN logging a message
logger.info("foo")
log_dict: dict = json.loads(stdout.getvalue())
# THEN `xray_trace_id`` key should be present
assert log_dict["xray_trace_id"] == trace_id
monkeypatch.delenv(name="_X_AMZN_TRACE_ID")
def test_logger_log_twice_when_log_filter_isnt_present_and_root_logger_is_setup(monkeypatch, stdout, service_name):
# GIVEN Lambda configures the root logger with a handler
root_logger = logging.getLogger()
root_logger.addHandler(logging.StreamHandler(stream=stdout))
# WHEN we create a new Logger and child Logger
# and log deduplication filter for child messages are disabled
# see #262 for more details on why this is needed for Pytest Live Log feature
monkeypatch.setenv(constants.LOGGER_LOG_DEDUPLICATION_ENV, "true")
logger = Logger(service=service_name, stream=stdout)
child_logger = Logger(service=service_name, child=True, stream=stdout)
logger.info("PARENT")
child_logger.info("CHILD")
# THEN it should only contain only two log entries
# since child's log records propagated to root logger should be rejected
logs = list(stdout.getvalue().strip().split("\n"))
assert len(logs) == 4
def test_logger_child_not_set_returns_same_logger(stdout):
# GIVEN two Loggers are initialized with the same service name
# WHEN child param isn't set
logger_one = Logger(service="something", stream=stdout)
logger_two = Logger(service="something", stream=stdout)
# THEN we should have two Logger instances
# however inner logger wise should be the same
assert id(logger_one) != id(logger_two)
assert logger_one._logger is logger_two._logger
assert logger_one.name is logger_two.name
# THEN we should also not see any duplicated logs
logger_one.info("One - Once")
logger_two.info("Two - Once")
logs = list(capture_multiple_logging_statements_output(stdout))
assert len(logs) == 2
def test_logger_children_propagate_changes(stdout, service_name):
# GIVEN Loggers are initialized
# create child logger before parent to mimick
# importing logger from another module/file
# as loggers are created in global scope
child = Logger(stream=stdout, service=service_name, child=True)
parent = Logger(stream=stdout, service=service_name)
# WHEN a child Logger adds an additional key
child.structure_logs(append=True, customer_id="value")
# THEN child Logger changes should propagate to parent
# and subsequent log statements should have the latest value
parent.info("Hello parent")
child.info("Hello child")
parent_log, child_log = capture_multiple_logging_statements_output(stdout)
assert "customer_id" in parent_log
assert "customer_id" in child_log
assert child.parent.name == service_name
if not case_id:
raise SupportCaseError("Missing case_id in create_case() response")
# Use the case ID to obtain further details from the case and in
# particular, the display ID.
try:
case = support_client.describe_cases(caseIdList=[case_id])
except botocore.exceptions.ClientError as describe_case_err:
raise SupportCaseError(describe_case_err) from describe_case_err
try:
display_id = case["cases"][0]["displayId"]
except KeyError as key_err:
raise SupportCaseError(key_err) from key_err
LOG.info(f"Case {display_id} opened")
return 0
def check_for_null_envvars(cc_list, communication_body, subject):
"""Check for missing requirement environment variables."""
if not cc_list:
msg = ("Environment variable 'CC_LIST' must provide at least one "
"email address to CC on this case.")
LOG.error(msg)
raise SupportCaseInvalidArgumentsError(msg)
if not subject:
msg = (
"Environment variable 'SUBJECT' must provide the 'Subject' text "
"for the communication sent to support.")
from aws_xray_sdk.ext.flask.middleware import XRayMiddleware
from pcluster.api.awslambda.serverless_wsgi import handle_request
from pcluster.api.flask_app import ParallelClusterFlaskApp
logger = Logger(service="pcluster", location="%(filename)s:%(lineno)s:%(funcName)s()")
tracer = Tracer(service="pcluster")
# Initialize as a global to re-use across Lambda invocations
pcluster_api = None # pylint: disable=invalid-name
profile = environ.get("PROFILE", "prod")
is_dev_profile = profile == "dev"
if is_dev_profile:
logger.info("Running with dev profile")
environ["FLASK_ENV"] = "development"
environ["FLASK_DEBUG"] = "1"
@tracer.capture_method
def _init_flask_app():
return ParallelClusterFlaskApp(swagger_ui=is_dev_profile, validate_responses=is_dev_profile)
@logger.inject_lambda_context(log_event=is_dev_profile)
@tracer.capture_lambda_handler
def lambda_handler(event: Dict[str, Any], context: LambdaContext) -> Dict[str, Any]:
try:
global pcluster_api # pylint: disable=global-statement,invalid-name
if not pcluster_api:
import json
import os
import re
import sys
import time
from functools import lru_cache, wraps
import boto3
from aws_lambda_powertools import Logger, Metrics
from aws_lambda_powertools.metrics import MetricUnit
import siem
from siem import geodb, utils
logger = Logger(stream=sys.stdout, log_record_order=["level", "message"])
logger.info('version: ' + __version__)
metrics = Metrics()
SQS_SPLITTED_LOGS_URL = None
if 'SQS_SPLITTED_LOGS_URL' in os.environ:
SQS_SPLITTED_LOGS_URL = os.environ['SQS_SPLITTED_LOGS_URL']
ES_HOSTNAME = utils.get_es_hostname()
def extract_logfile_from_s3(record):
if 's3' in record:
s3key = record['s3']['object']['key']
logger.structure_logs(append=True, s3_key=s3key)
logtype = utils.get_logtype_from_s3key(s3key, logtype_s3key_dict)
logconfig = create_logconfig(logtype)
logfile = siem.LogS3(record, logtype, logconfig, s3_client, sqs_queue)
if not case_id:
raise SupportCaseError("Missing case_id in create_case() response")
# Use the case ID to obtain further details from the case and in
# particular, the display ID.
try:
case = support_client.describe_cases(caseIdList=[case_id])
except botocore.exceptions.ClientError as describe_case_err:
raise SupportCaseError(describe_case_err) from describe_case_err
try:
display_id = case["cases"][0]["displayId"]
except KeyError as key_err:
raise SupportCaseError(key_err) from key_err
LOG.info("Case %s opened", display_id)
return 0
def check_for_null_envvars(cc_list, communication_body, subject):
"""Check for missing requirement environment variables."""
if not cc_list:
msg = (
"Environment variable 'CC_LIST' must provide at least one "
"email address to CC on this case."
)
LOG.error(msg)
raise SupportCaseInvalidArgumentsError(msg)
if not subject:
msg = (
import re
import sys
import time
import boto3
from aws_lambda_powertools import Metrics, Logger
from aws_lambda_powertools.metrics import MetricUnit
import siem
from siem import utils, geodb
__version__ = '2.2.0'
logger = Logger(stream=sys.stdout, log_record_order=["level", "message"])
logger.info('version: ' + __version__)
metrics = Metrics()
SQS_SPLITTED_LOGS_URL = None
if 'SQS_SPLITTED_LOGS_URL' in os.environ:
SQS_SPLITTED_LOGS_URL = os.environ['SQS_SPLITTED_LOGS_URL']
ES_HOSTNAME = utils.get_es_hostname()
def extract_logfile_from_s3(record):
if 's3' in record:
s3key = record['s3']['object']['key']
logger.structure_logs(append=True, s3_key=s3key)
logtype = utils.get_logtype_from_s3key(s3key, logtype_s3key_dict)
logconfig = create_logconfig(logtype)
logfile = siem.LogS3(record, logtype, logconfig, s3_client, sqs_queue)
