From f443788fa767518a9e38141d2029039ee7762670 Mon Sep 17 00:00:00 2001 From: Simon Walker Date: Mon, 13 May 2024 12:54:12 +0100 Subject: [PATCH 1/7] Introduce LOGGING_OVERRIDE config var Co-Authored-By: Daniel Fangl --- localstack/config.py | 3 +++ localstack/logging/setup.py | 18 ++++++++++++++++++ 2 files changed, 21 insertions(+) diff --git a/localstack/config.py b/localstack/config.py index c98a9f6f8d264..b48e86e06b5ea 100644 --- a/localstack/config.py +++ b/localstack/config.py @@ -418,6 +418,9 @@ def in_docker(): LS_LOG = eval_log_type("LS_LOG") DEBUG = is_env_true("DEBUG") or LS_LOG in TRACE_LOG_LEVELS +# allow setting custom log levels for individual loggers +LOGGING_OVERRIDE = os.environ.get("LOGGING_OVERRIDE", "{}") + # whether to enable debugpy DEVELOP = is_env_true("DEVELOP") diff --git a/localstack/logging/setup.py b/localstack/logging/setup.py index 41f538ce59897..2037dbc3173e4 100644 --- a/localstack/logging/setup.py +++ b/localstack/logging/setup.py @@ -1,3 +1,4 @@ +import json import logging import sys import warnings @@ -78,6 +79,23 @@ def setup_logging_from_config(): for name, level in trace_internal_log_levels.items(): logging.getLogger(name).setLevel(level) + if raw_value := config.LOGGING_OVERRIDE: + try: + logging_overrides = json.loads(raw_value) + for logger, level_name in logging_overrides.items(): + level = getattr(logging, level_name, None) + if not level: + raise RuntimeError( + f"Failed to configure logging overrides ({raw_value}): '{level_name}' is not a valid log level" + ) + logging.getLogger(logger).setLevel(level) + except RuntimeError: + raise + except Exception as e: + raise RuntimeError( + f"Failed to configure logging overrides ({raw_value}): Malformed value. ({e})" + ) from e + def create_default_handler(log_level: int): log_handler = logging.StreamHandler(stream=sys.stderr) From 790994147127a942c959539285a2bf78333d6bec Mon Sep 17 00:00:00 2001 From: Simon Walker Date: Mon, 13 May 2024 16:15:25 +0100 Subject: [PATCH 2/7] Do not use walrus operator for python version compatibility --- localstack/logging/setup.py | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) diff --git a/localstack/logging/setup.py b/localstack/logging/setup.py index 2037dbc3173e4..96a47436f778d 100644 --- a/localstack/logging/setup.py +++ b/localstack/logging/setup.py @@ -79,21 +79,22 @@ def setup_logging_from_config(): for name, level in trace_internal_log_levels.items(): logging.getLogger(name).setLevel(level) - if raw_value := config.LOGGING_OVERRIDE: + raw_logging_override = config.LOGGING_OVERRIDE + if raw_logging_override: try: - logging_overrides = json.loads(raw_value) + logging_overrides = json.loads(raw_logging_override) for logger, level_name in logging_overrides.items(): level = getattr(logging, level_name, None) if not level: raise RuntimeError( - f"Failed to configure logging overrides ({raw_value}): '{level_name}' is not a valid log level" + f"Failed to configure logging overrides ({raw_logging_override}): '{level_name}' is not a valid log level" ) logging.getLogger(logger).setLevel(level) except RuntimeError: raise except Exception as e: raise RuntimeError( - f"Failed to configure logging overrides ({raw_value}): Malformed value. ({e})" + f"Failed to configure logging overrides ({raw_logging_override}): Malformed value. ({e})" ) from e From 356ad770f5adc37f2b90deaf395c62adb736ea12 Mon Sep 17 00:00:00 2001 From: Simon Walker Date: Mon, 13 May 2024 16:34:29 +0100 Subject: [PATCH 3/7] Convert envar to key-value pairs --- localstack/config.py | 2 +- localstack/logging/setup.py | 4 ++-- localstack/utils/collections.py | 15 +++++++++++++++ tests/unit/utils/test_collections.py | 26 ++++++++++++++++++++++++++ 4 files changed, 44 insertions(+), 3 deletions(-) diff --git a/localstack/config.py b/localstack/config.py index b48e86e06b5ea..f069dc79db140 100644 --- a/localstack/config.py +++ b/localstack/config.py @@ -419,7 +419,7 @@ def in_docker(): DEBUG = is_env_true("DEBUG") or LS_LOG in TRACE_LOG_LEVELS # allow setting custom log levels for individual loggers -LOGGING_OVERRIDE = os.environ.get("LOGGING_OVERRIDE", "{}") +LOGGING_OVERRIDE = os.environ.get("LOGGING_OVERRIDE", "") # whether to enable debugpy DEVELOP = is_env_true("DEVELOP") diff --git a/localstack/logging/setup.py b/localstack/logging/setup.py index 96a47436f778d..b210e28dab907 100644 --- a/localstack/logging/setup.py +++ b/localstack/logging/setup.py @@ -1,10 +1,10 @@ -import json import logging import sys import warnings from localstack import config, constants +from ..utils.collections import parse_key_value_pairs from .format import AddFormattedAttributes, DefaultFormatter # The log levels for modules are evaluated incrementally for logging granularity, @@ -82,7 +82,7 @@ def setup_logging_from_config(): raw_logging_override = config.LOGGING_OVERRIDE if raw_logging_override: try: - logging_overrides = json.loads(raw_logging_override) + logging_overrides = parse_key_value_pairs(raw_logging_override) for logger, level_name in logging_overrides.items(): level = getattr(logging, level_name, None) if not level: diff --git a/localstack/utils/collections.py b/localstack/utils/collections.py index c036bdc6b2bcd..965bbb36740cf 100644 --- a/localstack/utils/collections.py +++ b/localstack/utils/collections.py @@ -533,3 +533,18 @@ def is_comma_delimited_list(string: str, item_regex: Optional[str] = None) -> bo if pattern.match(string) is None: return False return True + + +def parse_key_value_pairs(raw_text: str) -> dict: + result = {} + for pair in raw_text.split(","): + items = pair.split("=", maxsplit=2) + if len(items) != 2: + raise ValueError(f"invalid key/value pair: '{pair}'") + raw_key, raw_value = items[0].strip(), items[1].strip() + if not raw_key: + raise ValueError(f"missing key: '{pair}'") + if not raw_value: + raise ValueError(f"missing value: '{pair}'") + result[raw_key] = raw_value + return result diff --git a/tests/unit/utils/test_collections.py b/tests/unit/utils/test_collections.py index adb2581e77460..2a92e12689a70 100644 --- a/tests/unit/utils/test_collections.py +++ b/tests/unit/utils/test_collections.py @@ -9,6 +9,7 @@ ImmutableList, convert_to_typed_dict, is_comma_delimited_list, + parse_key_value_pairs, select_from_typed_dict, ) @@ -193,3 +194,28 @@ def test_is_comma_limited_list(): assert not is_comma_delimited_list("foo, bar baz") assert not is_comma_delimited_list("foo,") assert not is_comma_delimited_list("") + + +@pytest.mark.parametrize( + "input_text,expected", + [ + ("a=b", {"a": "b"}), + ("a=b,c=d", {"a": "b", "c": "d"}), + ], +) +def test_parse_key_value_pairs(input_text, expected): + assert parse_key_value_pairs(input_text) == expected + + +@pytest.mark.parametrize( + "input_text,message", + [ + ("a=b,", "invalid key/value pair: ''"), + ("a=b,c=", "missing value: 'c='"), + ], +) +def test_parse_key_value_pairs_error_messages(input_text, message): + with pytest.raises(ValueError) as exc_info: + parse_key_value_pairs(input_text) + + assert str(exc_info.value) == message From cce4b2dc96c193fdd6da26018b504fa482369090 Mon Sep 17 00:00:00 2001 From: Simon Walker Date: Wed, 15 May 2024 16:39:22 +0100 Subject: [PATCH 4/7] Update localstack/config.py Co-authored-by: Dominik Schubert --- localstack/config.py | 1 + 1 file changed, 1 insertion(+) diff --git a/localstack/config.py b/localstack/config.py index f069dc79db140..5e806f62a724d 100644 --- a/localstack/config.py +++ b/localstack/config.py @@ -418,6 +418,7 @@ def in_docker(): LS_LOG = eval_log_type("LS_LOG") DEBUG = is_env_true("DEBUG") or LS_LOG in TRACE_LOG_LEVELS +# EXPERIMENTAL # allow setting custom log levels for individual loggers LOGGING_OVERRIDE = os.environ.get("LOGGING_OVERRIDE", "") From aa4269c4e81bae002f17540f4f9718b7d66b524e Mon Sep 17 00:00:00 2001 From: Simon Walker Date: Wed, 15 May 2024 16:47:05 +0100 Subject: [PATCH 5/7] Address review comments --- localstack/logging/setup.py | 2 +- localstack/utils/collections.py | 8 +++++++- 2 files changed, 8 insertions(+), 2 deletions(-) diff --git a/localstack/logging/setup.py b/localstack/logging/setup.py index b210e28dab907..c8cf5aad17c75 100644 --- a/localstack/logging/setup.py +++ b/localstack/logging/setup.py @@ -94,7 +94,7 @@ def setup_logging_from_config(): raise except Exception as e: raise RuntimeError( - f"Failed to configure logging overrides ({raw_logging_override}): Malformed value. ({e})" + f"Failed to configure logging overrides ({raw_logging_override})" ) from e diff --git a/localstack/utils/collections.py b/localstack/utils/collections.py index 965bbb36740cf..656a5f52e21cb 100644 --- a/localstack/utils/collections.py +++ b/localstack/utils/collections.py @@ -536,9 +536,15 @@ def is_comma_delimited_list(string: str, item_regex: Optional[str] = None) -> bo def parse_key_value_pairs(raw_text: str) -> dict: + """ + Parse a series of key-value pairs, in an environment variable format into a dictionary + + >>> input = "a=b,c=d" + >>> assert parse_key_value_pairs(input) == {"a": "b", "c": "d"} + """ result = {} for pair in raw_text.split(","): - items = pair.split("=", maxsplit=2) + items = pair.split("=") if len(items) != 2: raise ValueError(f"invalid key/value pair: '{pair}'") raw_key, raw_value = items[0].strip(), items[1].strip() From 82cc9db4a00c9bc4a22631a510e89f0be7b4b1a8 Mon Sep 17 00:00:00 2001 From: Simon Walker Date: Mon, 13 May 2024 12:55:16 +0100 Subject: [PATCH 6/7] Set default DNS logging level to INFO in debug mode --- localstack/logging/setup.py | 1 + 1 file changed, 1 insertion(+) diff --git a/localstack/logging/setup.py b/localstack/logging/setup.py index c8cf5aad17c75..951448b32dde7 100644 --- a/localstack/logging/setup.py +++ b/localstack/logging/setup.py @@ -26,6 +26,7 @@ "localstack.aws.accounts": logging.INFO, "localstack.aws.protocol.serializer": logging.INFO, "localstack.aws.serving.wsgi": logging.WARNING, + "localstack.dns": logging.INFO, "localstack.request": logging.INFO, "localstack.request.internal": logging.WARNING, "localstack.state.inspect": logging.INFO, From 7c9abb9798aaf198d8fa2f398b7b9df6ae6bbbb7 Mon Sep 17 00:00:00 2001 From: Simon Walker Date: Mon, 13 May 2024 12:55:27 +0100 Subject: [PATCH 7/7] Add debug logging for DNS --- localstack/dns/server.py | 38 +++++++++++++++++++++++++++++--------- 1 file changed, 29 insertions(+), 9 deletions(-) diff --git a/localstack/dns/server.py b/localstack/dns/server.py index d7b399441f65d..9ad66ff7b8967 100644 --- a/localstack/dns/server.py +++ b/localstack/dns/server.py @@ -5,6 +5,7 @@ import re import textwrap import threading +import time from datetime import datetime from functools import cache from ipaddress import IPv4Address, IPv4Interface @@ -374,6 +375,13 @@ def resolve(self, request: DNSRecord, handler: DNSHandler) -> DNSRecord | None: reply = request.reply() found = False + LOG.debug( + "[%s] received dns query: %s (type %s)", + request.header.id, + request.q.qname, + QTYPE.get(request.q.qtype, "??"), + ) + try: if not self._skip_local_resolution(request): found = self._resolve_name(request, reply, handler.client_address) @@ -381,13 +389,23 @@ def resolve(self, request: DNSRecord, handler: DNSHandler) -> DNSRecord | None: LOG.info("Unable to get DNS result: %s", e) if found: + LOG.debug("[%s] found name locally", request.header.id) return reply + LOG.debug("[%s] name not found locally, querying upstream", request.header.id) # If we did not find a matching record in our local zones, we forward to our upstream dns try: + start_time = time.perf_counter() req_parsed = dns.message.from_wire(bytes(request.pack())) r = dns.query.udp(req_parsed, self.upstream_dns, timeout=REQUEST_TIMEOUT_SECS) result = self._map_response_dnspython_to_dnslib(r) + end_time = time.perf_counter() + LOG.debug( + "[%s] name resolved upstream in %d ms (rcode %s)", + request.header.id, + (end_time - start_time) / 1000.0, + RCODE.get(result.header.rcode, "??"), + ) return result except Exception as e: LOG.info( @@ -401,11 +419,12 @@ def resolve(self, request: DNSRecord, handler: DNSHandler) -> DNSRecord | None: if not reply.rr and reply.header.get_rcode == RCODE.NOERROR: # setting this return code will cause commands like 'host' to try the next nameserver reply.header.set_rcode(RCODE.SERVFAIL) + LOG.debug("[%s] failed to resolve name", request.header.id) return None return reply - def _skip_local_resolution(self, request) -> bool: + def _skip_local_resolution(self, request: DNSRecord) -> bool: """ Check whether we should skip local resolution for the given request, and directly contact upstream @@ -415,6 +434,7 @@ def _skip_local_resolution(self, request) -> bool: request_name = to_str(str(request.q.qname)) for p in self.skip_patterns: if re.match(p, request_name): + LOG.debug("[%s] skipping local resolution of query", request.header.id) return True return False @@ -449,7 +469,7 @@ def _resolve_name( self, request: DNSRecord, reply: DNSRecord, client_address: ClientAddress ) -> bool: if alias_found := self._resolve_alias(request, reply, client_address): - LOG.debug("Alias found: %s", request.q.qname) + LOG.debug("[%s] alias found: %s", request.header.id, request.q.qname) return alias_found return self._resolve_name_from_zones(request, reply, client_address) @@ -671,7 +691,7 @@ def do_run(self): self.servers = self._get_servers() for server in self.servers: server.start_thread() - LOG.debug("DNS Server started") + LOG.info("DNS Server started") for server in self.servers: server.thread.join() @@ -780,7 +800,7 @@ def get_available_dns_server(): pass if result: - LOG.debug("Determined fallback dns: %s", result) + LOG.info("Determined fallback dns: %s", result) else: LOG.info( "Unable to determine fallback DNS. Please check if '%s' is reachable by your configured DNS servers" @@ -864,10 +884,10 @@ def start_server(upstream_dns: str, host: str, port: int = config.DNS_PORT): if DNS_SERVER: # already started - bail - LOG.debug("DNS servers are already started. Avoid starting again.") + LOG.info("DNS servers are already started. Avoid starting again.") return - LOG.debug("Starting DNS servers (tcp/udp port %s on %s)..." % (port, host)) + LOG.info("Starting DNS servers (tcp/udp port %s on %s)..." % (port, host)) dns_server = DnsServer(port, protocols=["tcp", "udp"], host=host, upstream_dns=upstream_dns) for name in NAME_PATTERNS_POINTING_TO_LOCALSTACK: @@ -904,7 +924,7 @@ def stop_servers(): def start_dns_server_as_sudo(port: int): global DNS_SERVER - LOG.debug( + LOG.info( "Starting the DNS on its privileged port (%s) needs root permissions. Trying to start DNS with sudo.", config.DNS_PORT, ) @@ -929,7 +949,7 @@ def start_dns_server(port: int, asynchronous: bool = False, standalone: bool = F # check if DNS server is disabled if not config.use_custom_dns(): - LOG.debug("Not starting DNS. DNS_ADDRESS=%s", config.DNS_ADDRESS) + LOG.info("Not starting DNS. DNS_ADDRESS=%s", config.DNS_ADDRESS) return upstream_dns = get_fallback_dns_server() @@ -949,7 +969,7 @@ def start_dns_server(port: int, asynchronous: bool = False, standalone: bool = F return if standalone: - LOG.debug("Already in standalone mode and port binding still fails.") + LOG.warning("Already in standalone mode and port binding still fails.") return start_dns_server_as_sudo(port)