bin/djbdns-logparse.py

   1 #!/usr/bin/python3
   2 """
   3 Convert tinydns and dnscache logs to human-readable form
   4 """
   5
   6 import re, typing
   7 from struct import pack
   8 from time import strftime, gmtime
   9
  10
  11 ## Regular expressions for matching tinydns/dnscache log lines. We
  12 ## compile these once here rather than within the corresponding
  13 ## matching functions, because the latter get executed repeatedly.
  14
  15 # This first pattern is used to match the timestamp format that the
  16 # tai64nlocal program produces. It appears in both dnscache and
  17 # tinydns lines, after they've been piped through tai64nlocal, of
  18 # course.
  19 timestamp_pat = r'[\d-]+ [\d:\.]+'
  20
  21 # The regex to match dnscache log lines.
  22 dnscache_log_re = re.compile(fr'({timestamp_pat}) (\w+)(.*)')
  23
  24 # The "hex4" pattern matches a string of four hexadecimal digits. This
  25 # is used, for example, by tinydns to encode the query type
  26 # identifier.
  27 hex4_pat = r'[0-9a-f]{4}'
  28
  29 # The IP pattern matches a string of either 8 or 32 hexadecimal
  30 # characters, which correspond to IPv4 and IPv6 addresses,
  31 # respectively, in tinydns logs.
  32 ip_pat = r'[0-9a-f]{8,32}'
  33
  34 # The regex to match tinydns log lines.
  35 tinydns_log_re = re.compile(
  36     rf'({timestamp_pat}) ({ip_pat}):({hex4_pat}):({hex4_pat}) ([\+\-IC/]) ({hex4_pat}) (.*)'
  37 )
  38
  39 # A dictionary mapping query type identifiers, in decimal, to their
  40 # friendly names for tinydns. Reference:
  41 #
  42 #   https://en.wikipedia.org/wiki/List_of_DNS_record_types
  43 #
  44 # Note that mapping here is non-exhaustive, and that tinydns will
  45 # log responses for record types that it does not know about.
  46 query_type = {
  47       1: "a",
  48       2: "ns",
  49       5: "cname",
  50       6: "soa",
  51      12: "ptr",
  52      13: "hinfo",
  53      15: "mx",
  54      16: "txt",
  55      17: "rp",
  56      24: "sig",
  57      25: "key",
  58      28: "aaaa",
  59      33: "srv",
  60      35: "naptr",
  61      38: "a6",
  62      48: "dnskey",
  63      52: "tlsa",
  64      65: "https",
  65     252: "axfr",
  66     255: "any",
  67     257: "caa"
  68 }
  69
  70 # tinydns can drop a query for one of three reasons; this dictionary
  71 # maps the symbol that gets logged in each case to a human-readable
  72 # reason. We include the "+" case here, indicating that the query was
  73 # NOT dropped, to avoid a special case later on when we're formatting
  74 # the human-readable output.
  75 query_drop_reason = {
  76     "+": None,
  77     "-": "no authority",
  78     "I": "invalid query",
  79     "C": "invalid class",
  80     "/": "couldn't parse"
  81 }
  82
  83
  84 def convert_ip(ip : str) -> str:
  85     """
  86     Convert a hex string representing an IP address to
  87     human-readable form.
  88
  89     Parameters
  90     ----------
  91
  92     ip : str
  93         The hexadecimal representation of either an IPv4 or an IPv6
  94         address.
  95
  96     Returns
  97     -------
  98
  99     The usual decimal dotted-quad representation is returned for an
 100     IPv4 address. IPv6 addresses are returned almost as-is, but with
 101     colons inserted in the appropriate places, between every four
 102     characters.
 103
 104     Examples
 105     --------
 106
 107         >>> convert_ip("7f000001")
 108         '127.0.0.1'
 109         >>> convert_ip("00000000000000000000ffff7f000001")
 110         '0000:0000:0000:0000:0000:ffff:7f00:0001'
 111     """
 112     if len(ip) == 8:
 113         # IPv4, eg. "7f000001" -> "7f 00 00 01" -> "127.0.0.1"
 114         return ".".join(map(str, pack(">L", int(ip, 16))))
 115     elif len(ip) == 32:
 116         # IPv6 is actually simpler -- it's just a string-slicing operation.
 117         return ":".join([ip[(4*i) : (4*i+4)] for i in range(8)])
 118
 119
 120 def decode_client(words : list, i : int):
 121     r"""
 122     Helper function to decode the client field in a dnscache log
 123     entry.
 124
 125     There are two possible formats for the client field,
 126
 127       1. clientip:clientport, used by tcpopen/tcpclose entries,
 128       2. clientip:clientport:id, used by "query" entries.
 129
 130     Parameters
 131     ----------
 132
 133     words : list
 134         The ``words`` list (a list of fields) from
 135         :func:`handle_dnscache_log`.
 136
 137     i : int
 138         The index of the client field within ``words``
 139
 140     Returns
 141     -------
 142
 143     Nothing; the ``i``th entry in the ``words`` list is modified
 144     in-place.
 145
 146     Examples
 147     --------
 148
 149         >>> words = ["foo", "bar", "7f000001:9253", "quux"]
 150         >>> decode_client(words, 2)
 151         >>> words
 152         ['foo', 'bar', '127.0.0.1:37459', 'quux']
 153
 154         >>> words = ["foo", "7f000001:a3db:4fb9", "bar", "quux"]
 155         >>> decode_client(words, 1)
 156         >>> words
 157         ['foo', '127.0.0.1:41947 (id 20409)', 'bar', 'quux']
 158
 159     """
 160     chunks = words[i].split(":")
 161
 162     ip = convert_ip(chunks[0])
 163     port = int(chunks[1], 16)
 164     words[i] = f"{ip}:{port}"
 165
 166     if len(chunks) == 3:
 167         # For a "query" entry's clientip:clientport:id field.
 168         id = int(chunks[2], 16)
 169         words[i] += f" (id {id})"
 170
 171 def decode_ip(words, i):
 172     words[i] = convert_ip(words[i])
 173
 174 def decode_ttl(words, i):
 175     words[i] = f"TTL={words[i]}"
 176
 177 def decode_serial(words, i):
 178     serial = int(words[i])
 179     words[i] = f"#{serial}"
 180
 181 def decode_type(words, i):
 182     qt = words[i]
 183     words[i] = query_type.get(int(qt), qt)
 184
 185 def handle_dnscache_log(line) -> typing.Optional[str]:
 186     """
 187     Handle a single log line if it matches the ``dnscache_log_re`` regex.
 188
 189     Parameters
 190     ----------
 191
 192     line : string
 193         The log line that might match ``dnscache_log_re``.
 194
 195     Returns
 196     -------
 197
 198     Either the human-readable string if the log line was handled (that
 199     is, if it was really a dnscache log line), or ``None`` if it was
 200     not.
 201
 202     Examples
 203     --------
 204
 205         >>> line = "2022-09-15 18:37:33.863805500 query 1 7f000001:a3db:4fb9 1 www.example.com."
 206         >>> handle_dnscache_log(line)
 207         '2022-09-15 18:37:33.863805500 query #1 127.0.0.1:41947 (id 20409) a www.example.com.'
 208
 209         >>> line = "2022-09-15 18:37:33.863874500 tx 0 1 www.example.com. . c0a80101"
 210         >>> handle_dnscache_log(line)
 211         '2022-09-15 18:37:33.863874500 tx g=0 a www.example.com. . 192.168.1.1'
 212
 213         >>> line = "2022-09-15 18:37:33.878529500 rr c0a80101 20865 1 www.example.com. 5db8d822"
 214         >>> handle_dnscache_log(line)
 215         '2022-09-15 18:37:33.878529500 rr 192.168.1.1 TTL=20865 a www.example.com. 93.184.216.34'
 216
 217         >>> line = "2022-09-15 18:37:33.878532500 stats 1 43 1 0"
 218         >>> handle_dnscache_log(line)
 219         '2022-09-15 18:37:33.878532500 stats count=1 motion=43 udp-active=1 tcp-active=0'
 220
 221         >>> line = "2022-09-15 18:37:33.878602500 sent 1 49"
 222         >>> handle_dnscache_log(line)
 223         '2022-09-15 18:37:33.878602500 sent #1 49'
 224
 225         >>> line = "this line is nonsense"
 226         >>> handle_dnscache_log(line)
 227
 228     """
 229     match = dnscache_log_re.match(line)
 230     if not match:
 231         return None
 232
 233     (timestamp, event, data) = match.groups()
 234
 235     words = data.split()
 236     if event == "cached":
 237         if words[0] not in ("cname", "ns", "nxdomain"):
 238             decode_type(words, 0)
 239
 240     elif event == "drop":
 241         decode_serial(words, 0)
 242
 243     elif event == "lame":
 244         decode_ip(words, 0)
 245
 246     elif event == "nodata":
 247         decode_ip(words, 0)
 248         decode_ttl(words, 1)
 249         decode_type(words, 2)
 250
 251     elif event == "nxdomain":
 252         decode_ip(words, 0)
 253         decode_ttl(words, 1)
 254
 255     elif event == "query":
 256         decode_serial(words, 0)
 257         decode_client(words, 1)
 258         decode_type(words, 2)
 259
 260     elif event == "rr":
 261         decode_ip(words, 0)
 262         decode_ttl(words, 1)
 263         if words[2] not in ("cname", "mx", "ns", "ptr", "soa"):
 264             decode_type(words, 2)
 265             if words[2] == "a":         # decode answer to an A query
 266                 decode_ip(words, 4)
 267             if words[2] == "txt":       # text record
 268                 response = words[4]
 269                 if response.endswith("..."):
 270                     ellipsis = "..."
 271                     response = response[0:-3]
 272                 else:
 273                     ellipsis = ""
 274                 length = int(response[0:2], 16)
 275                 chars = []
 276                 for i in range(1, len(response)//2):
 277                     chars.append(chr(int(response[2*i : (2*i)+2], 16)))
 278                 txt = "".join(chars)
 279                 words[4] = f"{length}:\"{txt}{ellipsis}\""
 280
 281     elif event == "sent":
 282         decode_serial(words, 0)
 283
 284     elif event == "stats":
 285         words[0] = f"count={words[0]}"
 286         words[1] = f"motion={words[1]}"
 287         words[2] = f"udp-active={words[2]}"
 288         words[3] = f"tcp-active={words[3]}"
 289
 290     elif event == "tx":
 291         words[0] = f"g={words[0]}"
 292         decode_type(words, 1)
 293         # words[2] = name
 294         # words[3] = control (domain for which these servers are believed
 295         #            to be authoritative)
 296         for i in range(4, len(words)):
 297             decode_ip(words, i)
 298
 299     elif event in ("tcpopen", "tcpclose"):
 300         decode_client(words, 0)
 301
 302     return f"{timestamp} {event} " + " ".join(words)
 303
 304
 305
 306 def handle_tinydns_log(line : str) -> typing.Optional[str]:
 307     """
 308     Handle a single log line if it matches the ``tinydns_log_re`` regex.
 309
 310     Parameters
 311     ----------
 312
 313     line : string
 314         The log line that might match ``tinydns_log_re``.
 315
 316     Returns
 317     -------
 318
 319     Either the human-readable string if the log line was handled (that
 320     is, if it was really a tinydns log line), or ``None`` if it was
 321     not.
 322
 323     Examples
 324     --------
 325
 326         >>> line = "2022-09-14 21:04:40.206516500 7f000001:9d61:be69 - 0001 www.example.com"
 327         >>> handle_tinydns_log(line)
 328         '2022-09-14 21:04:40.206516500 dropped query (no authority) from 127.0.0.1:40289 (id 48745): a www.example.com'
 329
 330         >>> line = "this line is nonsense"
 331         >>> handle_tinydns_log(line)
 332
 333     """
 334     match = tinydns_log_re.match(line)
 335     if not match:
 336         return None
 337
 338     (timestamp, ip, port, id, code, type, name) = match.groups()
 339     ip = convert_ip(ip)
 340     port = int(port, 16)
 341     id = int(id, 16)
 342
 343     # Convert the "type" field to a human-readable record type name
 344     # using the query_type dictionary. If the right name isn't present
 345     # in the dictionary, we use the (decimal) type id instead.
 346     type = int(type, 16)                # "001c" -> 28
 347     type = query_type.get(type, type)   # 28 -> "aaaa"
 348
 349     line_tpl = "{timestamp} "
 350
 351     reason = query_drop_reason[code]
 352     if code == "+":
 353         line_tpl += "sent response to {ip}:{port} (id {id}): {type} {name}"
 354     else:
 355         line_tpl += "dropped query ({reason}) from {ip}:{port}"
 356         if code != "/":
 357             # If the query can actually be parsed, the log line is a
 358             # bit more informative than it would have been otherwise.
 359             line_tpl += " (id {id}): {type} {name}"
 360
 361     return line_tpl.format(timestamp=timestamp,
 362                            reason=reason,
 363                            ip=ip,
 364                            port=port,
 365                            id=id,
 366                            type=type,
 367                            name=name)
 368
 369
 370 def parse_logfile(file : typing.TextIO):
 371     r"""
 372     Process a single log ``file``.
 373
 374     Parameters
 375     ----------
 376
 377     file : typing.TextIO
 378         An open log file, or stdin.
 379
 380     Examples
 381     --------
 382
 383         >>> line = "@4000000063227a320c4f3114 7f000001:9d61:be69 - 0001 www.example.com\n"
 384         >>> from tempfile import NamedTemporaryFile
 385         >>> with NamedTemporaryFile(mode="w", delete=False) as f:
 386         ...     _ = f.write(line)
 387         >>> f = open(f.name, 'r')
 388         >>> parse_logfile(f)
 389         2022-09-14 21:04:40.206516500 dropped query (no authority) from 127.0.0.1:40289 (id 48745): a www.example.com
 390         >>> f.close()
 391         >>> from os import remove
 392         >>> remove(f.name)
 393
 394     """
 395     # Open a pipe to tai64nlocal. We'll write lines of our input file
 396     # (the log file) to it, and read back the same lines but with
 397     # friendly timestamps in them.
 398     from subprocess import Popen, PIPE
 399     tai = Popen(["tai64nlocal"], stdin=PIPE, stdout=PIPE, text=True, bufsize=0)
 400
 401     for line in file:
 402         tai.stdin.write(line)
 403         line = tai.stdout.readline()
 404
 405         friendly_line = handle_tinydns_log(line)
 406         if not friendly_line:
 407             friendly_line = handle_dnscache_log(line)
 408             if not friendly_line:
 409                 friendly_line = line
 410
 411         print(friendly_line)
 412
 413 def main():
 414     r"""
 415     The entry point to the program.
 416
 417     This function is responsible only for parsing any command-line
 418     arguments, and then calling :func`parse_logfile` on them.
 419     """
 420     # Create an argument parser using the file's docsctring as its
 421     # description.
 422     from argparse import ArgumentParser, FileType
 423     parser = ArgumentParser(description = __doc__)
 424
 425     # Parse zero or more positional arguments into a list of
 426     # "logfiles". If none are given, read from stdin instead.
 427     from sys import stdin
 428     parser.add_argument("logfiles",
 429                         metavar="LOGFILE",
 430                         type=FileType("r"),
 431                         nargs="*",
 432                         default=[stdin],
 433                         help="djbdns logfile to process (default: stdin)")
 434
 435     # Warning: argparse automatically opens its file arguments here,
 436     # and they only get closed when the program terminates. There's no
 437     # real benefit to closing them one-at-a-time after calling
 438     # parse_logfile(), because the "scarce" resource of open file
 439     # descriptors gets consumed immediately, before any processing has
 440     # happened. In other words, if you're going to run out of file
 441     # descriptors, it's going to happen right now.
 442     #
 443     # So anyway, don't run this on several million logfiles.
 444     args = parser.parse_args()
 445     for f in args.logfiles:
 446         parse_logfile(f)
 447
 448
 449 if __name__ == "__main__":
 450     main()