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