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_with_unserializable_value_in_message(stdout, service_name): logger = Logger(service=service_name, level="DEBUG", stream=stdout) class Unserializable: pass msg = {"x": Unserializable()} logger.debug(msg) log_dict = json.loads(stdout.getvalue()) assert log_dict["message"]["x"].startswith("<")
def test_log_dict_xray_is_not_present_when_tracing_is_disabled( stdout, monkeypatch, service_name): # GIVEN a logger is initialized within a Lambda function with X-Ray disabled (default) logger = Logger(service=service_name, 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): # 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_setup_service_env_var(monkeypatch, stdout): service_name = "payment" # 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_seq(stdout, service_name): # GIVEN the default logger configuration logger = Logger(service=service_name, 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_dict_key_custom_seq(stdout, service_name): # GIVEN a logger configuration with log_record_order set to ["message"] logger = Logger(service=service_name, 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_logging_exception_traceback(stdout): logger = Logger(level="DEBUG", stream=stdout) try: raise ValueError("Boom") except ValueError: logger.exception("A value error occurred") log_dict = json.loads(stdout.getvalue()) check_log_dict(log_dict) assert "ERROR" == log_dict["level"] assert "exception" in log_dict
def test_setup_sampling_rate_env_var(monkeypatch, stdout, service_name): # GIVEN Logger is initialized # WHEN samping rate is explicitly set to 100% via POWERTOOLS_LOGGER_SAMPLE_RATE env sampling_rate = "1" monkeypatch.setenv("POWERTOOLS_LOGGER_SAMPLE_RATE", sampling_rate) logger = Logger(service=service_name, stream=stdout) logger.debug("I am being sampled") # THEN sampling rate should be equals POWERTOOLS_LOGGER_SAMPLE_RATE value # log level should be DEBUG # and debug log statements should be in stdout log = capture_logging_output(stdout) assert sampling_rate == log["sampling_rate"] assert "DEBUG" == log["level"] assert "I am being sampled" == log["message"]
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_logging_exception_traceback(stdout): logger = Logger(level="DEBUG", stream=stdout, request_id="request id!", another="value") try: raise Exception("Boom") except Exception: logger.exception("This is a test") log_dict = json.loads(stdout.getvalue()) check_log_dict(log_dict) assert "exception" in log_dict
def test_with_unserializable_value_in_message_custom(stdout): class Unserializable: pass # GIVEN a custom json_default logger = Logger(level="DEBUG", stream=stdout, json_default=lambda o: f"<non-serializable: {type(o).__name__}>") # WHEN we log a message logger.debug({"x": Unserializable()}) log_dict = json.loads(stdout.getvalue()) # THEN json_default should not be in the log message and the custom unserializable handler should be used assert log_dict["message"]["x"] == "<non-serializable: Unserializable>" assert "json_default" not in log_dict
def test_inject_lambda_context_with_structured_log(lambda_context, stdout, service_name): # GIVEN Logger is initialized logger = Logger(service=service_name, stream=stdout) # WHEN structure_logs has been used to add an additional key upfront # and a lambda function is decorated with logger.inject_lambda_context logger.structure_logs(append=True, additional_key="test") @logger.inject_lambda_context def handler(event, context): logger.info("Hello") handler({}, lambda_context) # THEN lambda contextual info should always be in the logs log = capture_logging_output(stdout) expected_logger_context_keys = ( "function_name", "function_memory_size", "function_arn", "function_request_id", "additional_key", ) for key in expected_logger_context_keys: assert key in log
def test_log_custom_formatting(stdout, service_name): # GIVEN a logger where we have a custom `location`, 'datefmt' format logger = Logger(service=service_name, 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_setup_with_valid_log_levels(stdout, level): logger = Logger(level=level, stream=stdout, request_id="request id!", another="value") msg = "This is a test" log_command = { "INFO": logger.info, "ERROR": logger.error, "WARNING": logger.warning, "DEBUG": logger.debug, "CRITICAL": logger.critical, } log_message = log_command[level] log_message(msg) log_dict = json.loads(stdout.getvalue().strip()) check_log_dict(log_dict) assert level == log_dict["level"] assert "This is a test" == log_dict["message"] assert "request id!" == log_dict["request_id"] assert "exception" not in log_dict
def test_logger_level_not_set(service_name): # GIVEN a Loggers is initialized # WHEN no log level was passed logger = Logger(service=service_name) # THEN we should default to INFO assert logger.level == logging.INFO
def test_inject_lambda_context_log_event_request_env_var( monkeypatch, lambda_context, stdout): # GIVEN a lambda function is decorated with logger instructed to log event # via POWERTOOLS_LOGGER_LOG_EVENT env # WHEN logger is setup # THEN logger should log event received from Lambda lambda_event = {"greeting": "hello"} monkeypatch.setenv("POWERTOOLS_LOGGER_LOG_EVENT", "true") logger = Logger(stream=stdout) @logger.inject_lambda_context def handler(event, context): logger.info("Hello") handler(lambda_event, lambda_context) # Given that our string buffer has many log statements separated by newline \n # We need to clean it before we can assert on logs = [ json.loads(line.strip()) for line in stdout.getvalue().split("\n") if line ] event = {} for log in logs: if "greeting" in log["message"]: event = log["message"] assert event == lambda_event
def test_inject_lambda_context_log_no_request_by_default( monkeypatch, lambda_context, stdout): # GIVEN a lambda function is decorated with logger # WHEN logger is setup # THEN logger should not log event received by lambda handler lambda_event = {"greeting": "hello"} logger = Logger(stream=stdout) @logger.inject_lambda_context def handler(event, context): logger.info("Hello") handler(lambda_event, lambda_context) # Given that our string buffer has many log statements separated by newline \n # We need to clean it before we can assert on logs = [ json.loads(line.strip()) for line in stdout.getvalue().split("\n") if line ] event = {} for log in logs: if "greeting" in log["message"]: event = log["message"] assert event != lambda_event
def test_logger_level_as_int(service_name): # GIVEN a Loggers is initialized # WHEN log level is int logger = Logger(service=service_name, level=logging.INFO) # THEN we should be expected int (20, in this case) assert logger.level == logging.INFO
def test_setup_sampling_rate(monkeypatch, stdout): # GIVEN samping rate is explicitly defined via POWERTOOLS_LOGGER_SAMPLE_RATE env # WHEN logger is setup # THEN sampling rate should be equals POWERTOOLS_LOGGER_SAMPLE_RATE value and should sample debug logs sampling_rate = "1" monkeypatch.setenv("POWERTOOLS_LOGGER_SAMPLE_RATE", sampling_rate) monkeypatch.setenv("LOG_LEVEL", "INFO") logger = Logger(stream=stdout) logger.debug("I am being sampled") log = json.loads(stdout.getvalue()) assert sampling_rate == log["sampling_rate"] assert "DEBUG" == log["level"] assert "I am being sampled" == log["message"]
def test_logger_level_case_insensitive(service_name): # GIVEN a Loggers is initialized # WHEN log level is set as "info" instead of "INFO" logger = Logger(service=service_name, level="info") # THEN we should correctly set log level as INFO assert logger.level == logging.INFO
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_log_dict_key_strip_nones(stdout, service_name): # GIVEN a logger confirmation where we set `location` and `timestamp` to None # Note: level and service cannot 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` assert sorted(log_dict.keys()) == ["level", "message", "service"] assert log_dict["service"] == "service_undefined"
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_level_env_var_as_int(monkeypatch, service_name): # GIVEN Logger is initialized # WHEN log level is explicitly defined via LOG_LEVEL env as int # THEN Logger should propagate ValueError # since env vars can only be string # and '50' is not a correct log level monkeypatch.setenv("LOG_LEVEL", 50) with pytest.raises(ValueError, match="Unknown level: '50'"): Logger(service=service_name)
def test_logger_get_correlation_id(lambda_context, stdout, service_name): # GIVEN a logger with a correlation_id set logger = Logger(service=service_name, stream=stdout) logger.set_correlation_id("foo") # WHEN calling get_correlation_id correlation_id = logger.get_correlation_id() # THEN it should return the correlation_id assert "foo" == correlation_id
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
def test_logger_append_duplicated(stdout, service_name): # GIVEN Logger is initialized with request_id field logger = Logger(service=service_name, stream=stdout, request_id="value") # WHEN `request_id` is appended to the existing structured log # using a different value logger.structure_logs(append=True, request_id="new_value") logger.info("log") # THEN subsequent log statements should have the latest value log = capture_logging_output(stdout) assert "new_value" == log["request_id"]
def test_logger_record_caller_location(stdout, service_name): # GIVEN Logger is initialized logger = Logger(service=service_name, stream=stdout) # WHEN log statement is run logger.info("log") # THEN 'location' field should have # the correct caller resolution caller_fn_name = inspect.currentframe().f_code.co_name log = capture_logging_output(stdout) assert caller_fn_name in log["location"]
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")