Add trace logging for the DNS server

localstack/config.py

@@ -418,6 +418,10 @@ 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", "")
+
 # whether to enable debugpy
 DEVELOP = is_env_true("DEVELOP")
 

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,20 +375,37 @@ 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)
         except Exception as e:
             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)

localstack/logging/setup.py

@@ -4,6 +4,7 @@
 
 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,
@@ -25,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,
@@ -78,6 +80,24 @@ def setup_logging_from_config():
         for name, level in trace_internal_log_levels.items():
             logging.getLogger(name).setLevel(level)
 
+    raw_logging_override = config.LOGGING_OVERRIDE
+    if raw_logging_override:
+        try:
+            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:
+                    raise RuntimeError(
+                        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_logging_override})"
+            ) from e
+
 
 def create_default_handler(log_level: int):
     log_handler = logging.StreamHandler(stream=sys.stderr)

localstack/utils/collections.py

@@ -533,3 +533,24 @@ 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:
+    """
+    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("=")
+        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

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