tools/scraper/parser.py

#!/usr/bin/env python

#
# Licensed to the Apache Software Foundation (ASF) under one
# or more contributor license agreements.  See the NOTICE file
# distributed with this work for additional information
# regarding copyright ownership.  The ASF licenses this file
# to you under the Apache License, Version 2.0 (the
# "License"); you may not use this file except in compliance
# with the License.  You may obtain a copy of the License at
#
#   http://www.apache.org/licenses/LICENSE-2.0
#
# Unless required by applicable law or agreed to in writing,
# software distributed under the License is distributed on an
# "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
# KIND, either express or implied.  See the License for the
# specific language governing permissions and limitations
# under the License.
#

from __future__ import unicode_literals
from __future__ import division
from __future__ import absolute_import
from __future__ import print_function

import re
import sys
import traceback
from datetime import datetime

import test_data as td
import common
import text
import router

"""
Sequence output copies the tailing end of transfers to a second display line.
Define how many characters to show.
"""
SEQUENCE_TRANSFER_SIZE = 50


def colorize_bg(what):
    # TODO: use the real colorize_bg
    return what


def proton_split(line):
    """
    Split a log line into fields.
     * allow commas and spaces in quoted strings.
     * split on ', ' and on ' '.
       strip trailing commas between fields.
     * quoted fields must have both quotes
    :param line:
    :return:
    """
    result = []
    indqs = False
    pending_comma = False
    res = ""
    for i in range(len(line)):
        c = line[i]
        if c == '\"':
            if pending_comma:
                res += ','
                pending_comma = False
            indqs = not indqs
            res += c
        elif c == ',':
            if pending_comma:
                res += c
            pending_comma = True
        elif c == ' ':
            if indqs:
                if pending_comma:
                    res += ','
                    pending_comma = False
                res += c
            else:
                if res != '':
                    if pending_comma:
                        pending_comma = False
                    result.append(res)
                    res = ''
        else:
            res += c
    if res != '':
        result.append(str(res))
    if indqs:
        raise ValueError("SPLIT ODD QUOTES: %s", line)
    # print ("SPLIT: line: %s" % line)
    # print ("SPLIT: flds: %s" % result)
    return result


class LogLineData:

    def direction_is_in(self):
        return self.direction == text.direction_in()

    def direction_is_out(self):
        return self.direction == text.direction_out()

    def __init__(self):
        self.web_show_str = ""
        self.sdorg_str = ""  # text for sequence diagram source
        self.name = ""
        self.conn_num = ""  # source router's undecorated conn num
        self.conn_id = ""  # decorated routerPrefixLetter'instanceNumber-conn_num
        self.conn_peer = ""  # display name of peer in seen in Open 'A - routerId.Test'
        self.channel = ""  # undecorated number - '0'
        self.direction = ""  # '<-' IN, or '->' OUT, or '--'
        self.described_type = DescribedType()  # DescribedType object
        self.handle = ""  # undecorated number - '1'
        self.delivery_id = ""  # "0"
        self.delivery_tag = ""  # "00:00:00:00"
        self.remote = ""  # undecorated number - '2'
        self.channel_handle = ""  # decorated - '[0,0]'
        self.channel_remote = ""  # decorated - '[1,2]'
        self.flow_deliverycnt = ""  # undecorated number - '50'
        self.flow_linkcredit = ""  # undecorated number - '100'
        self.flow_cnt_credit = ""  # decorated - '(50,100)'
        self.flow_drain = False
        self.transfer_id = ""
        self.role = ""
        self.is_receiver = False
        self.source = ""
        self.target = ""
        self.first = ""  # undecorated number - '10'
        self.last = ""  # undecorated number - '20'
        self.settled = ""  # Disposition or Transfer settled field from log line
        self.disposition_state = "?absent?"
        self.snd_settle_mode = ""  # Attach
        self.rcv_settle_mode = ""  # Attach
        self.transfer = False
        self.transfer_data = ""  # protonized transfer data value
        self.transfer_bare = ""  # bare message from transfer_data
        self.transfer_hdr_annos = ""  # header and annotation sections
        self.transfer_size = ""  # size declared by number in parenthesis
        self.transfer_short_name = ""
        self.transfer_settled = False
        self.transfer_presettled = False
        self.transfer_more = False
        self.transfer_resume = False
        self.transfer_aborted = False
        self.transfer_exhausted_credit = False
        self.link_short_name = ""
        self.link_short_name_popup = ""
        self.is_policy_trace = False  # line is POLICY (trace)
        self.is_server_info = False  # line is SERVER (info)
        self.is_router_ls = False  # line is ROUTER_LS (info)
        self.is_scraper = False  # line is SCRAPER (any-level)
        self.fid = ""  # Log line (frame) id as used in javascript code
        self.amqp_error = False
        self.link_class = "client"  # attach sees: normal, router, router-data (, management?)
        self.disposition_display = ""
        self.final_disposition = None
        self.no_parent_link = False


class DescribedType:
    """
    Given a line like:
        @typename(00) [key1=val1, ...]
    Extract the typename and create a map of the key-val pairs
    May recursively find embedded described types
    """

    @staticmethod
    def is_dtype_name(name):
        """
        Return true if the name is a pn_trace described type name
        :param name:
        :return:
        """
        return (name.startswith('@') and
                '(' in name and
                name.endswith(')'))

    @staticmethod
    def get_key_and_val(kvp):
        eqi = kvp.find('=')
        return kvp[:eqi], kvp[eqi + 1:]

    @staticmethod
    def dtype_name(name):
        if not DescribedType.is_dtype_name(name):
            raise ValueError("Name '%s' is not a described type name" % name)
        return name[1: name.find('(')]

    @staticmethod
    def dtype_number(name):
        if not DescribedType.is_dtype_name(name):
            raise ValueError("Name '%s' is not a described type name" % name)
        return int(name[name.find('(') + 1: -1])

    def __init__(self):
        self.dict = {}
        self.dtype_name = "unparsed"
        self.dtype_number = 0

    def __repr__(self):
        return self._representation()

    def _representation(self):
        return "DescribedType %s( %d ) : %s" % (self.dtype_name, self.dtype_number, self.dict)

    def add_field_to_dict(self, f_text, expected_key=None):
        if '=' not in f_text:
            raise ValueError("Field does not contain equal sign '%s'" % self.line)
        if expected_key is not None and not f_text.startswith(expected_key):
            raise ValueError("Transfer field %s not in order from line: %s" % (expected_key, self.line))
        key, val = DescribedType.get_key_and_val(f_text)
        if val.endswith(','):
            val = val[:-1]
        self.dict[key] = val

    def process_transfer_tail_key(self):
        keys = ["batchable", "aborted", "resume", "state", "rcv-settle-mode", "more", "settled", "message-format"]
        for key in keys:
            idx = self.line.rfind(key)
            if idx != -1:
                field = self.line[idx:]
                self.add_field_to_dict(field, key)
                self.line = self.line[:idx].strip()
                return True
        return False

    def parseTransfer(self):
        """
        Figure out the described type fields for the transfer.
        Transfers are handled specially with the ill-formatted binary delivery-tag field
        :return:
        """
        # strip leading '[' and trailing ']'
        if not (self.line.startswith('[') and self.line.endswith(']')):
            raise ValueError("Described type not delimited with square brackets: '%s'" % self.line)
        self.line = self.line[1:]
        self.line = self.line[:-1]

        # process fields from head
        fHandle = self.line.split()[0]
        self.add_field_to_dict(fHandle)
        self.line = self.line[(len(fHandle) + 1):]

        try:
            fDelId = self.line.split()[0]
            self.add_field_to_dict(fDelId)
            self.line = self.line[(len(fDelId) + 1):]

            # process fields from tail
            while len(self.line) > 0 and self.process_transfer_tail_key():
                pass

            # the remainder, no matter how unlikely, must be the delivery-tag
            self.add_field_to_dict(self.line, "delivery-tag")
        except:
            # delivery-id and delivery-tag are optional in subsequent transfers
            # when more=true.
            pass

    def parse_dtype_line(self, _dtype, _line):
        """
        Figure out the fields for the described type.
        The line format is:

        Transfers are handled specially with the ill-formatted binary delivery-tag field
        Note other performatives with ill-formatted binary data might get rejected. We
        only struggle figuring out the delivery-tag because it happens so often.
        :param _dtype: @describedtypename(num)
        :param _line: [key=val [, key=val]...]
        :return:
        """
        self.dtype = _dtype
        self.line = str(_line)
        self.dtype_name = DescribedType.dtype_name(self.dtype)
        self.dtype_number = DescribedType.dtype_number(self.dtype)

        # Process transfers separately..
        # Transfer perfomatives will not call parse recursively while others might
        if self.dtype_name == "transfer":
            self.parseTransfer()
            return

        # strip leading '[' and trailing ']'
        if not (self.line.startswith('[') and self.line.endswith(']')):
            raise ValueError("Described type not delimited with square brackets: '%s'" % _line)
        self.line = self.line[1:]
        self.line = self.line[:-1]

        # process fields
        fields = proton_split(self.line)
        while len(fields) > 0 and len(fields[0]) > 0:
            if '=' not in fields[0]:
                raise ValueError("Field does not contain equal sign '%s'" % fields[0])
            key, val = DescribedType.get_key_and_val(fields[0])
            # New proton logging uses hex strings. Convert to decimal strings.
            if val.startswith("0x"):
                val = str(int(val, 0))
            del fields[0]
            if DescribedType.is_dtype_name(val):
                # recursing to process subtype
                # pull subtype's data out of fields. The fields list belongs to parent.
                subfields = []
                if fields[0] == "[]":
                    # degenerate case of empty subtype closing parent type
                    #  @disposition .. state=@accepted(36) []]
                    subfields.append("[]")
                    del fields[0]
                else:
                    # While extracting this type's fields, include nested described types
                    # and PN_SYMBOL data enclosed in brackets. Current type ends when close
                    # bracket seen and nest level is zero.
                    nest = 0
                    while len(fields) > 0:
                        if "=@" in fields[0] and "]" not in fields[0] and "=@:" not in fields[0]:
                            nest += 1
                        if nest == 0:
                            if fields[0].endswith('],'):
                                subfields.append(fields[0][:-2])
                                subfields.append(']')
                                del fields[0]
                                break
                            if fields[0].endswith(']'):
                                subfields.append(fields[0][:-1])
                                subfields.append(']')
                                del fields[0]
                                break
                        elif fields[0].endswith('],') or fields[0].endswith(']'):
                            nest -= 1
                        if fields[0].endswith(']]'):
                            subfields.append(fields[0])
                            del fields[0]
                            break
                        subfields.append(fields[0])
                        del fields[0]

                subtype = DescribedType()
                subtype.parse_dtype_line(val, ' '.join(subfields))
                self.dict[key] = subtype
            elif val.startswith("@PN_SYMBOL"):
                # symbols may end in first field or some later field
                while not val.endswith(']'):
                    val += fields[0]
                    del fields[0]
                self.dict[key] = val
            elif val.startswith('{'):
                # handle some embedded map: properties={:product=\"qpid-dispatch-router\", :version=\"1.3.0-SNAPSHOT\"}
                # pull subtype's data out of fields. The fields list belongs to parent.
                submap = {}
                fields.insert(0, val)
                skey, sval = DescribedType.get_key_and_val(fields[0][1:])
                submap[skey] = sval
                del fields[0]
                while len(fields) > 0:
                    if fields[0].endswith('},'):
                        skey, sval = DescribedType.get_key_and_val(fields[0][:-2])
                        submap[skey] = sval
                        del fields[0]
                        break
                    if fields[0].endswith('}'):
                        skey, sval = DescribedType.get_key_and_val(fields[0][:-1])
                        submap[skey] = sval
                        del fields[0]
                        break
                    skey, sval = DescribedType.get_key_and_val(fields[0])
                    submap[skey] = sval
                    del fields[0]
                self.dict[key] = submap

            else:
                self.dict[key] = val


class ParsedLogLine:
    """
    Grind through the log line and record some facts about it.
    * Constructor returns Null if the log line is to be ignored
    * Constructor args:
    ** log_index          0 for 'A', 1 for 'B'
    ** routerInstance     which instance in log file
    ** lineno             line number
    ** line               the log line
    ** common             common block object
    """
    server_trace_key = "SERVER (trace) ["
    protocol_trace_key = "PROTOCOL (trace) ["
    server_info_key = "SERVER (info) ["
    policy_trace_key = "POLICY (trace) ["
    router_ls_key = "ROUTER_LS (info)"
    transfer_key = "@transfer(20)"
    proton_frame_key = "FRAME: "

    def sender_settle_mode_of(self, value):
        if value == "0":
            return "unsettled(0)"
        elif value == "1":
            return "settled(1)"
        elif value == "2":
            return "mixed(2)"  # default
        else:
            return "unknown(%s) % value"

    def receiver_settle_mode_of(self, value):
        if value == "0":
            return "first(0)"
        elif value == "1":
            return "second(1)"
        else:
            return "unknown(%s) % value"

    def resdict_value(self, resdict, key, if_absent):
        return resdict[key] if key in resdict else if_absent

    def highlighted(self, name, value, color):
        result = ""
        if value:
            result = "<span style=\"background-color:%s\">%s</span>" % (color, name)
        return result

    def unhighlighted(self, name, value):
        return name if value else ""

    def extract_facts(self):
        perf = self.data.described_type.dtype_number
        res = self.data
        resdict = self.data.described_type.dict
        res.sdorg_str = "HELP I'M A ROCK - Unknown performative: %s" % perf

        # the performatives
        # Note: res.channel is already populated
        if perf == 0x10:
            # Performative: open [0] always channel 0
            res.name = "open"
            res.channel = "0"
            res.web_show_str = "<strong>%s</strong> [%s]" % (res.name, res.channel)
            res.sdorg_str = "OPEN"
            if res.direction == text.direction_in():
                res.conn_peer = self.resdict_value(resdict, "container-id", "unknown")
                res.web_show_str += (" (peer: %s)" % res.conn_peer)
                res.sdorg_str += (" (peer: %s)" % res.conn_peer)

        elif perf == 0x11:
            # Performative: begin [channel,remoteChannel]
            # TODO: This has a bug where the local and remote channel numbers are confused.
            #       Usually they are the same. See if anyone notices!
            # res.channel
            res.name = "begin"
            res.remote = self.resdict_value(resdict, "remote-channel", "None)")
            res.channel_remote = "[%s,%s]" % (res.channel, res.remote)
            res.web_show_str = "<strong>%s</strong> %s" % (res.name, res.channel_remote)
            res.sdorg_str = "BEGIN %s" % (res.channel_remote)

        elif perf == 0x12:
            # Performative:  attach [channel,handle] role name (source: src, target: tgt)
            res.name = "attach"
            res.handle = resdict["handle"]
            res.role = "receiver" if resdict["role"] == "true" else "sender"
            res.is_receiver = res.role == "receiver"
            # translated names handled later
            name = self.resdict_value(resdict, "name", "None")
            self.shorteners.short_link_names.register(name, self)
            tmpsrc = self.resdict_value(resdict, "source", None)
            tmptgt = self.resdict_value(resdict, "target", None)
            res.snd_settle_mode = self.sender_settle_mode_of(
                resdict["snd-settle-mode"]) if "snd-settle-mode" in resdict else "mixed"
            res.rcv_settle_mode = self.receiver_settle_mode_of(
                resdict["rcv-settle-mode"]) if "rcv-settle-mode" in resdict else "first"
            caps = ""
            if tmpsrc is not None:
                res.source = self.resdict_value(tmpsrc.dict, "address", "none")
                caps = self.resdict_value(tmpsrc.dict, "capabilities", "")
            else:
                res.source = "none"
            if tmptgt is not None:
                res.target = self.resdict_value(tmptgt.dict, "address", "none")
                if caps == "":
                    caps = self.resdict_value(tmptgt.dict, "capabilities", "")
            else:
                res.target = "none"
            res.channel_handle = "[%s,%s]" % (res.channel, res.handle)

            if 'qd.router-data' in caps:
                res.link_class = 'router-data'
            elif 'qd.router' in caps:
                res.link_class = 'router'
            """
            TODO:
            res.source = short_endp_names.translate(res.source)
            res.target = short_endp_names.translate(res.target)
            res.snd_settle_mode = extract_name(tmpssm)
            res.rcv_settle_mode = extract_name(tmprsm)
            """
            # show_str handled in post_extract

        elif perf == 0x13:
            # Performative: flow [channel,handle]
            res.name = "flow"
            res.handle = resdict["handle"]
            res.flow_deliverycnt = self.resdict_value(resdict, "delivery-count", "0")
            res.flow_linkcredit = self.resdict_value(resdict, "link-credit", "0")
            res.flow_drain = resdict.get("drain", "") == "true"
            res.channel_handle = "[%s,%s]" % (res.channel, res.handle)
            res.flow_cnt_credit = "(%s,%s)" % (res.flow_deliverycnt, res.flow_linkcredit)
            res.web_show_str = "<strong>%s</strong> %s (%s,%s) %s" % (
                res.name, colorize_bg(res.channel_handle), res.flow_deliverycnt, res.flow_linkcredit,
                self.highlighted("drain", res.flow_drain, common.color_of("drain")))
            res.sdorg_str = "FLOW %s (%s,%s)" % (res.channel_handle, res.flow_deliverycnt, res.flow_linkcredit)  # TODO: Add drain

        elif perf == 0x14:
            # Performative: transfer [channel,handle] (id)
            res.name = "transfer"
            res.transfer = True
            res.handle = resdict["handle"]
            res.channel_handle = "[%s,%s]" % (res.channel, res.handle)
            res.delivery_id = self.resdict_value(resdict, "delivery-id", "none")
            res.delivery_tag = self.resdict_value(resdict, "delivery-tag", "none")
            res.settled = self.resdict_value(resdict, "settled", "false")
            res.transfer_settled = resdict.get("settled", "") == "true"
            res.transfer_more = resdict.get("more", "") == "true"
            res.transfer_resume = resdict.get("resume", "") == "true"
            res.transfer_aborted = resdict.get("aborted", "") == "true"
            # translated names handled in post_extract
            self.shorteners.short_data_names.register(res.transfer_bare, self)

        elif perf == 0x15:
            # Performative: disposition [channel] (role first-last)
            res.name = "disposition"
            res.role = "receiver" if resdict["role"] == "true" else "sender"
            res.is_receiver = res.role == "receiver"
            res.first = self.resdict_value(resdict, "first", "0")
            res.last = self.resdict_value(resdict, "last", res.first)
            res.settled = self.resdict_value(resdict, "settled", "false")
            state = resdict.get("state")
            if state is not None:
                res.disposition_state = state.dtype_name
            ###    colorize_dispositions_not_accepted(proto, res, global_vars, count_anomalies)
            res.web_show_str = ("<strong>%s</strong>  [%s] (%s %s-%s settled=%s state=%s)" %
                                (res.name, res.channel, res.role, res.first, res.last, res.settled, res.disposition_state))
            res.sdorg_str = ("%s  [%s] (%s %s-%s settled=%s state=%s)" %
                             (res.name, res.channel, res.role, res.first, res.last, res.settled, res.disposition_state))

        elif perf == 0x16:
            # Performative: detach [channel, handle]
            res.name = "detach"
            res.handle = resdict["handle"]
            ### TODO: colorize_performative_error(proto, res, global_vars, count_anomalies)
            res.channel_handle = "[%s,%s]" % (res.channel, res.handle)
            res.web_show_str = "<strong>%s</strong> %s" % (res.name, colorize_bg(res.channel_handle))
            res.sdorg_str = "DETACH %s" % (res.channel_handle)

        elif perf == 0x17:
            # Performative: end [channel]
            res.name = "end"
            ### TODO: colorize_performative_error(proto, res, global_vars, count_anomalies)
            res.web_show_str = "<strong>%s</strong> [%s]" % (res.name, res.channel)
            res.sdorg_str = "END [%s]" % (res.channel)

        elif perf == 0x18:
            # Performative: close [0] always channel 0
            res.channel = "0"
            res.name = "close"
            ### colorize_performative_error(proto, res, global_vars, count_anomalies)
            res.web_show_str = "<strong>%s</strong> [%s]" % (res.name, res.channel)
            res.sdorg_str = "CLOSE [%s]" % (res.channel)

        elif perf == 0x1d:
            # transport:definitions error
            res.name = "error"
            descr = self.resdict_value(resdict, "description", "none")
            res.web_show_str = "<strong>%s</strong> [%s] %s" % (res.name, res.channel, descr)

        elif perf == 0x23:
            # messaging:delivery-state received
            res.name = "received"
            res.web_show_str = "<strong>%s</strong> [%s]" % (res.name, res.channel)

        elif perf == 0x24:
            # messaging:delivery-state accepted
            res.name = "accepted"
            res.web_show_str = "<strong>%s</strong> [%s]" % (res.name, res.channel)

        elif perf == 0x25:
            # messaging:delivery-state rejected
            res.name = "rejected"
            res.web_show_str = "<strong>%s</strong> [%s]" % (res.name, res.channel)

        elif perf == 0x26:
            # messaging:delivery-state released
            res.name = "released"
            res.web_show_str = "<strong>%s</strong> [%s]" % (res.name, res.channel)

        elif perf == 0x27:
            # messaging:delivery-state modified
            res.name = "modified"
            res.web_show_str = "<strong>%s</strong> [%s]" % (res.name, res.channel)

        elif perf == 0x28:
            # messaging:addressing source
            res.name = "source"
            res.web_show_str = "<strong>%s</strong> [%s]" % (res.name, res.channel)

        elif perf == 0x29:
            # messaging:addressing target
            res.name = "target"
            res.web_show_str = "<strong>%s</strong> [%s]" % (res.name, res.channel)

        elif perf == 0x2b:
            # messaging:addressing delete-on-close
            res.name = "delete-on-close"
            res.web_show_str = "<strong>%s</strong> [%s]" % (res.name, res.channel)

        elif perf == 0x2c:
            # messaging:addressing delete-on-no-links
            res.name = "delete-on-no-links"
            res.web_show_str = "<strong>%s</strong> [%s]" % (res.name, res.channel)

        elif perf == 0x2d:
            # messaging:addressing delete-on-no-messages
            res.name = "delete-on-no-messages"
            res.web_show_str = "<strong>%s</strong> [%s]" % (res.name, res.channel)

        elif perf == 0x2e:
            # messaging:addressing delete-on-no-links-or-messages
            res.name = "delete-on-no-links-or-messages"
            res.web_show_str = "<strong>%s</strong> [%s]" % (res.name, res.channel)

        elif perf == 0x30:
            # transactions:coordination coordinator
            res.name = "coordinator"
            res.web_show_str = "<strong>%s</strong> [%s]" % (res.name, res.channel)

        elif perf == 0x31:
            # transactions:coordination declare
            res.name = "declare"
            res.web_show_str = "<strong>%s</strong> [%s]" % (res.name, res.channel)

        elif perf == 0x32:
            # transactions:coordination discharge
            res.name = "discharge"
            res.web_show_str = "<strong>%s</strong> [%s]" % (res.name, res.channel)

        elif perf == 0x33:
            # transactions:coordination declared
            res.name = "declared"
            res.web_show_str = "<strong>%s</strong> [%s]" % (res.name, res.channel)

        elif perf == 0x34:
            # transactions:coordination transactional-state
            res.name = "transactional-state"
            res.web_show_str = "<strong>%s</strong> [%s]" % (res.name, res.channel)

        elif perf == 0x40:
            # security:sasl sasl-mechanisms
            res.name = "sasl-mechanisms"
            mechs = self.resdict_value(resdict, "sasl-server-mechanisms", "none")
            res.web_show_str = "<strong>%s</strong> [%s] %s" % (res.name, res.channel, mechs)

        elif perf == 0x41:
            # security:sasl sasl-init
            res.name = "sasl-init"
            mech = self.resdict_value(resdict, "mechanism", "none")
            res.web_show_str = "<strong>%s</strong> [%s] %s" % (res.name, res.channel, mech)

        elif perf == 0x42:
            # security:sasl sasl-challenge
            res.name = "sasl-challenge"
            res.web_show_str = "<strong>%s</strong> [%s]" % (res.name, res.channel)

        elif perf == 0x43:
            # security:sasl sasl-response
            res.name = "sasl-response"
            res.web_show_str = "<strong>%s</strong> [%s]" % (res.name, res.channel)

        elif perf == 0x44:
            # security:sasl sasl-outcome
            res.name = "sasl-outcome"
            code = self.resdict_value(resdict, "code", "none")
            res.web_show_str = "<strong>%s</strong> [%s] code=%s" % (res.name, res.channel, code)

        elif perf == 0x70:
            # messaging:message-format header
            res.name = "header"
            res.web_show_str = "<strong>%s</strong> [%s]" % (res.name, res.channel)

        elif perf == 0x71:
            # messaging:message-format delivery-annotations
            res.name = "delivery-annotations"
            res.web_show_str = "<strong>%s</strong> [%s]" % (res.name, res.channel)

        elif perf == 0x72:
            # messaging:message-format message-annotations
            res.name = "message-annotations"
            res.web_show_str = "<strong>%s</strong> [%s]" % (res.name, res.channel)

        elif perf == 0x73:
            # messaging:message-format properties
            res.name = "properties"
            res.web_show_str = "<strong>%s</strong> [%s]" % (res.name, res.channel)

        elif perf == 0x74:
            # messaging:message-format application-properties
            res.name = "application-properties"
            res.web_show_str = "<strong>%s</strong> [%s]" % (res.name, res.channel)

        elif perf == 0x75:
            # messaging:message-format data
            res.name = "data"
            res.web_show_str = "<strong>%s</strong> [%s]" % (res.name, res.channel)

        elif perf == 0x76:
            # messaging:message-format amqp-sequence
            res.name = "amqp-sequence"
            res.web_show_str = "<strong>%s</strong> [%s]" % (res.name, res.channel)

        elif perf == 0x77:
            # messaging:message-format amqp-value
            res.name = "amqp-value"
            res.web_show_str = "<strong>%s</strong> [%s]" % (res.name, res.channel)

        elif perf == 0x78:
            # messaging:message-format footer
            res.name = "footer"
            res.web_show_str = "<strong>%s</strong> [%s]" % (res.name, res.channel)

        else:
            res.web_show_str = "HELP I'M A ROCK - Unknown performative: %s" % perf

        if "error" in resdict:
            res.amqp_error = True
            dct = resdict["error"].dict
            condi = dct["condition"]
            descr = dct["description"] if "description" in dct else ""
            res.web_show_str += (" <span style=\"background-color:%s\">error</span> "
                                 "%s %s" % (common.color_of("errors"), condi, descr))

    def post_extract_names(self):
        perf = self.data.described_type.dtype_number
        res = self.data
        resdict = self.data.described_type.dict
        if perf == 0x12:
            # Performative:  attach [channel,handle] role name (source: src, target: tgt)
            name = self.resdict_value(resdict, "name", "None")
            res.link_short_name_popup = self.shorteners.short_link_names.translate(name, True, customer=self)
            res.link_short_name = self.shorteners.short_link_names.translate(name, False)
            res.web_show_str = ("<strong>%s</strong> %s %s %s (source: %s, target: %s, class: %s)" %
                                (res.name, colorize_bg(res.channel_handle), res.role, res.link_short_name_popup,
                                 res.source, res.target, res.link_class))
            res.sdorg_str =  ("%s %s %s %s (src: %s, tgt: %s)" %
                              (res.name, res.channel_handle, res.role, res.link_short_name,
                               res.source, res.target))
        elif perf == 0x14:
            # Performative: transfer [channel,handle] (id)
            self.transfer_short_name = self.shorteners.short_data_names.translate(res.transfer_bare, customer=self)
            showdat = "<a href=\"#%s_dump\">%s</a>" % (self.transfer_short_name, self.transfer_short_name)
            spl = common.strings_of_proton_log(res.transfer_bare)
            to_strip = "\"... (truncated)"
            if spl.endswith(to_strip):
                spl = spl[:-len(to_strip)]
            res.web_show_str = "<strong>%s</strong>  %s (%s) %s %s %s %s %s %s - %s bytes" % (
                res.name, colorize_bg(res.channel_handle), res.delivery_id,
                self.highlighted("settled", res.transfer_settled, common.color_of("presettled")),
                self.highlighted("more", res.transfer_more, common.color_of("more")),
                self.highlighted("resume", res.transfer_resume, common.color_of("aborted")),
                self.highlighted("aborted", res.transfer_aborted, common.color_of("aborted")),
                showdat, common.html_escape(spl[-SEQUENCE_TRANSFER_SIZE:]),
                res.transfer_size)
            res.sdorg_str = "%s %s (%s) %s (%s%s%s%s)\\n%s" % (
                res.name, res.channel_handle, res.delivery_id, res.transfer_size,
                self.unhighlighted(" settled", res.transfer_settled),
                self.unhighlighted(" more", res.transfer_more),
                self.unhighlighted(" resume", res.transfer_resume),
                self.unhighlighted(" aborted", res.transfer_aborted),
                spl[-SEQUENCE_TRANSFER_SIZE:])

    def adverbl_link_to(self):
        """
        :return: html link to the main adverbl data display for this line
        """
        return "<a href=\"#%s\">%s</a>" % (self.fid, "%s%d_%s" %
                                           (common.log_letter_of(self.index), self.instance, str(self.lineno)))

    def __init__(self, _log_index, _instance, _lineno, _line, _comn, _router, opaque=None):
        """
        Process a naked qpid-dispatch log line
        A log line looks like this:
          2018-07-20 10:58:40.179187 -0400 SERVER (trace) [2]:0 -> @begin(17) [next-outgoing-id=0, incoming-window=2147483647, outgoing-window=2147483647] (/home/chug/git/qpid-dispatch/src/server.c:106)
        The process is:
         1. If the line ends with a filename:fileline then strip that away
         2. Peel off the leading time of day and put that into data.datetime.
            Lines with no datetime are presumed start-of-epoch.
         3. Find (SERVER) or (POLICY). If absent then raise to reject message.
         4. If connection number in square brackets '[2]' is missing then raise.
         5. Extract connection number; save in data.conn_num
         6. Create decorated data.conn_id "A0_2"
         7. Extract data.channel if present. Raise if malformed.
         8. Create a web_show_str for lines that may not parse any further. Like policy lines.
         9. Extract the direction arrows

        The log line is now reduced to a described type:
          @describedtypename(num) [key=val [, key=val ...]]
            except for transfers that have the funky transfer data at end.

        :param _log_index:   The router prefix index 0 for A, 1 for B, ...
        :param _instance     The router instance
        :param _lineno:
        :param _line:
        :param _comn:
        :param _router:
        """
        verbatim_module = None
        if len(_comn.verbatim_include_list) > 0:
            for modx in _comn.verbatim_include_list:
                if _comn.module_key_in_line(modx, _line):
                    verbatim_module = modx
                    break
        if not (_comn.module_key_in_line(self.server_trace_key, _line) or
                _comn.module_key_in_line(self.protocol_trace_key, _line) or
                (_comn.module_key_in_line(self.policy_trace_key, _line) and "lookup_user:" in _line) or  # open (not begin, attach)
                _comn.module_key_in_line(self.server_info_key, _line) or
                _comn.module_key_in_line(self.router_ls_key, _line) or
                verbatim_module is not None):
            raise ValueError("Line is not a candidate for parsing")
        self.index = _log_index  # router prefix 0 for A, 1 for B
        self.instance = _instance  # router instance in log file
        self.lineno = _lineno  # log line number
        self.comn = _comn
        self.router = _router
        self.opaque = opaque
        self.prefixi = common.log_letter_of(self.index) + str(self.instance)  # prefix+instance A0
        self.fid = "f_" + self.prefixi + "_" + str(self.lineno)  # frame id A0_100
        self.shorteners = _comn.shorteners  # name shorteners

        self.line = _line  # working line chopped, trimmed

        self.data = LogLineData()  # parsed line fact store

        # strip optional trailing file:line field
        self.line = self.line.rstrip()
        hasFileLine = False
        if self.line.endswith(')'):
            idxOP = self.line.rfind('(')
            idxColon = self.line.rfind(':')
            if idxOP != -1 and idxColon != -1:
                if idxColon > idxOP:
                    lNumStr = self.line[(idxColon + 1): (-1)]
                    try:
                        lnum = int(lNumStr)
                        hasFileLine = True
                    except:
                        pass
        if hasFileLine:
            self.line = self.line[:self.line.rfind('(')].rstrip()

        # Handle optional timestamp
        # This whole project is brain dead without a timestamp. Just sayin'.
        self.datetime = None
        try:
            self.datetime = datetime.strptime(self.line[:26], '%Y-%m-%d %H:%M:%S.%f')
        except:
            # old routers flub the timestamp and don't print leading zero in uS time
            # 2018-11-18 11:31:08.269 should be 2018-11-18 11:31:08.000269
            td = self.line[:26]
            parts = td.split('.')
            us = parts[1]
            parts_us = us.split(' ')
            if len(parts_us[0]) < 6:
                parts_us[0] = '0' * (6 - len(parts_us[0])) + parts_us[0]
            parts[1] = ' '.join(parts_us)
            td = '.'.join(parts)
            try:
                self.datetime = datetime.strptime(td[:26], '%Y-%m-%d %H:%M:%S.%f')
            except:
                self.datetime = datetime(1970, 1, 1)

        # Apply time-of-day filters
        if self.datetime is not None:
            if self.comn.args.time_start is not None:
                if self.datetime < self.comn.args.time_start:
                    raise ValueError("Line too early outside time-of-day limits")
            if self.comn.args.time_end is not None:
                if self.datetime > self.comn.args.time_end:
                    raise ValueError("Line too late outside time-of-day limits")

        # Pull out scraper literal logs
        if verbatim_module is not None:
            sti = self.line.find(verbatim_module)
            if sti > 0:
                # strip datetime and show literal string
                sti += len(verbatim_module)
                self.data.is_scraper = True
                self.data.web_show_str = ("<strong>%s</strong> %s" % (verbatim_module, common.html_escape(self.line[sti:])))
                stcp = self.line[sti:].find(')')  # close paren after log level
                if stcp <  0:
                    stcp = 0
                self.data.sdorg_str = self.line[sti + stcp + 1:]
                return
            else:
                assert False  # verbatim module was found only moments ago...

        # extract connection number
        sti = self.line.find(self.server_trace_key)
        if sti < 0:
            sti = self.line.find(self.protocol_trace_key)
            if sti < 0:
                sti = self.line.find(self.policy_trace_key)
                if sti < 0:
                    sti = self.line.find(self.server_info_key)
                    if sti < 0:
                        sti = self.line.find(self.router_ls_key)
                        if sti < 0:
                            raise ValueError("Log keyword/level not found in line %s" % (self.line))
                        else:
                            self.line = self.line[sti + len(self.router_ls_key):]
                            self.data.is_router_ls = True
                            # this has no relationship to AMQP log lines
                            return
                    else:
                        self.line = self.line[sti + len(self.server_info_key):]
                        self.data.is_server_info = True
                else:
                    self.line = self.line[sti + len(self.policy_trace_key):]
                    self.data.is_policy_trace = True
            else:
                self.line = self.line[sti + len(self.protocol_trace_key):]
        else:
            self.line = self.line[sti + len(self.server_trace_key):]
        ste = self.line.find(']')
        if ste < 0:
            print("Failed to parse line ", _lineno, " : ", _line)
            traceback.print_exc()
            raise ValueError("'%s' not found in line %s" % ("]", self.line))
        self.data.conn_num = self.line[:ste]
        if self.data.conn_num.startswith("C"):
            self.data.conn_num = self.data.conn_num[1:]
        self.line = self.line[ste + 1:]

        # create decorated connection id
        self.data.conn_id = self.prefixi + "_" + self.data.conn_num

        # get the session (channel) number
        if self.line.startswith(':'):
            self.line = self.line[1:]
        if self.line.startswith(self.proton_frame_key):
            self.line = self.line[len(self.proton_frame_key):]

        sti = self.line.find(' ')
        if sti < 0:
            raise ValueError("space not found after channel number at head of line %s" % (self.line))
        if sti > 0:
            self.data.channel = self.line[:sti]
        self.line = self.line[sti + 1:]
        self.line = self.line.lstrip()

        # cover for traces that don't get any better
        self.data.web_show_str = ("<strong>%s</strong>" % self.line)

        # policy lines have no direction and described type fields
        if self.data.is_policy_trace or self.data.is_server_info:
            return

        # direction
        if self.line.startswith('<') or self.line.startswith('-'):
            self.data.direction = self.line[:2]
            self.line = self.line[3:]
            self.data.web_show_str = ("<strong>%s</strong>" % self.line)

        # The log line is now reduced to a described type:
        #  @describedtypename(num) [key=val [, key=val ...]]
        # extract descriptor name
        dname = self.line.split()[0]
        self.line = self.line[(len(dname) + 1):]

        # Dispose of the transfer data
        if dname == self.transfer_key:
            # Look for the '] (NNN) "' that separates the described type fields
            # from the '(size) "data"'. Stick the required '(size) data' into
            # data.transfer_data and delete it from the line.
            rz = re.compile(r'\] \(\d+\) \"').search(self.line)
            # aborted transfers may or may not have size/data in the log line
            if rz is not None and len(rz.regs) > 0:
                splitSt, splitTo = rz.regs[0]
                self.data.transfer_size = self.line[splitSt + 3: splitTo - 3]
                self.data.transfer_data = self.line[splitTo - 1:]  # discard (NNN) size field
                self.line = self.line[: splitSt + 1]
                # try to isolate the bare message
                sti = self.data.transfer_data.find(r"\x00Ss")
                if sti > 0:
                    self.data.transfer_hdr_annos = self.data.transfer_data[:sti]
                    self.data.transfer_bare = self.data.transfer_data[sti:]
                else:
                    self.data.transfer_hdr_annos = ''
                    self.data.transfer_bare = self.data.transfer_data
            else:
                self.data.transfer_size = "0"
                self.data.transfer_data = "(none)"

        if DescribedType.is_dtype_name(dname):
            self.data.described_type.parse_dtype_line(dname, self.line)
            # data fron incoming line is now parsed out into facts in .data
            # Now cook the data to get useful displays
            self.extract_facts()


def parse_log_file(fn, log_index, comn):
    """
    Given a file name, return an array of Routers that hold the parsed lines.
    Lines that don't parse are identified on stderr and then discarded.
    :param fn: file name
    :param log_index: router id 0 for 'A', 1 for 'B', ...
    :param comn: common data
    :return: list of Routers
    """
    instance = 0
    lineno = 0
    search_for_in_progress = True
    rtrs = []
    rtr = None
    key1 = "SERVER (trace) ["  # AMQP traffic
    key2 = "SERVER (info) Container Name:"  # Normal 'router is starting' restart discovery line
    key3 = "ROUTER_LS (info)"  # a log line placed in separate pool of lines
    keys = [key1, key3]
    key4 = "ROUTER (info) Version:"  # router version line
    key5 = "ROUTER (info) Router started in "  # router mode
    with open(fn, 'r') as infile:
        for line in infile:
            if search_for_in_progress:
                # What if the log file has no record of the router starting?
                # This is an in_progress router and it is a pre-existing router instance
                # and not one found by restart discovery.
                # Any key or AMQP line indicates a router in-progress
                if any(s in line for s in keys) or ("[" in line and "]" in line):
                    assert rtr is None
                    rtr = router.Router(fn, log_index, instance)
                    rtrs.append(rtr)
                    search_for_in_progress = False
                    rtr.restart_rec = router.RestartRecord(rtr, line, lineno + 1)
            lineno += 1
            verbatim_module = None
            if len(comn.verbatim_include_list) > 0:
                for modx in comn.verbatim_include_list:
                    if comn.module_key_in_line(modx, line):
                        verbatim_module = modx
                        break
            if key2 in line:
                # This line closes the current router, if any, and opens a new one
                if rtr is not None:
                    instance += 1
                rtr = router.Router(fn, log_index, instance)
                rtrs.append(rtr)
                rtr.restart_rec = router.RestartRecord(rtr, line, lineno)
                search_for_in_progress = False
                rtr.container_name = line[(line.find(key2) + len(key2)):].strip().split()[0]
            elif key3 in line:
                pl = None
                try:
                    pl = ParsedLogLine(log_index, instance, lineno, line, comn, rtr)
                except ValueError as ve:
                    pass
                except Exception as e:
                    # t, v, tb = sys.exc_info()
                    if hasattr(e, 'message'):
                        traceback.print_exc()
                        sys.stderr.write("Failed to parse file '%s', line %d : %s. Analysis continuing...\n" % (fn, lineno, e.message))
                    else:
                        traceback.print_exc()
                        sys.stderr.write("Failed to parse file '%s', line %d : %s. Analysis continuing...\n" % (fn, lineno, e))
                if pl is not None:
                    if pl.data.is_router_ls:
                        rtr.router_ls.append(pl)
            elif key4 in line:
                rtr.version = line[(line.find(key4) + len(key4)):].strip().split()[0]
            elif key5 in line:
                rtr.mode = line[(line.find(key5) + len(key5)):].strip().split()[0].lower()
            elif verbatim_module is not None:
                pl = ParsedLogLine(log_index, instance, lineno, line, comn, rtr)
                rtr.lines.append(pl)
            elif "[" in line and "]" in line:
                try:
                    do_this = True if not hasattr(comn.args, 'skip_all_data') else not comn.args.skip_all_data
                    if not do_this:
                        # not indexing data. maybe do this line anyway
                        do_this = not any(s in line for s in [' @transfer', ' @disposition', ' @flow', 'EMPTY FRAME'])
                    if do_this:
                        pl = ParsedLogLine(log_index, instance, lineno, line, comn, rtr)
                        if pl is not None:
                            rtr.lines.append(pl)
                    else:
                        comn.data_skipped += 1
                except ValueError as ve:
                    pass
                except Exception as e:
                    # t, v, tb = sys.exc_info()
                    if hasattr(e, 'message'):
                        traceback.print_exc()
                        sys.stderr.write("Failed to parse file '%s', line %d : %s. Analysis continuing...\n" % (fn, lineno, e.message))
                    else:
                        traceback.print_exc()
                        sys.stderr.write("Failed to parse file '%s', line %d : %s. Analysis continuing...\n" % (fn, lineno, e))
                    # raise t, v, tb
            else:
                # ignore this log line
                pass
    return rtrs


if __name__ == "__main__":
    class dummy_args():
        skip_all_data = False
        skip_detail = False
        skip_msg_progress = False
        split = False
        time_start = None
        time_end = None

    print("Line-by-line split test")
    try:
        for line in td.TestData().data():
            if "transfer" not in line:
                print(proton_split(line))
            else:
                pass  # splitter does not split transfers
        pass
    except:
        traceback.print_exc(file=sys.stdout)
        pass

    print("Canned data parse test")
    data = td.TestData().data()
    log_index = 0  # from file for router A
    instance = 0  # all from router instance 0
    comn = common.Common()
    comn.args = dummy_args()
    try:
        for i in range(len(data)):
            temp = ParsedLogLine(log_index, instance, i, data[i], comn, None)
            print(temp.datetime, temp.data.conn_id, temp.data.direction, temp.data.web_show_str)
        pass
    except:
        traceback.print_exc(file=sys.stdout)
        pass
    comn.shorteners.short_data_names.sort_customers()

    print("Read two-instance file test")
    comn2 = common.Common()
    comn2.args = dummy_args()
    routers = parse_log_file('test_data/A-two-instances.log', 0, comn2)
    if len(routers) != 2:
        print("ERROR: Expected two router instances in log file")

    t_b4_0 = datetime.strptime('2018-10-15 10:57:32.151673', '%Y-%m-%d %H:%M:%S.%f')
    t_in_0 = datetime.strptime('2018-10-15 10:57:32.338183', '%Y-%m-%d %H:%M:%S.%f')
    t_in_1 = datetime.strptime('2018-10-15 10:59:07.584498', '%Y-%m-%d %H:%M:%S.%f')
    t_af_1 = datetime.strptime('2019-10-15 10:59:07.584498', '%Y-%m-%d %H:%M:%S.%f')

    rtr, idx = router.which_router_tod(routers, t_b4_0)
    assert rtr is routers[0] and idx == 0
    rtr, idx = router.which_router_tod(routers, t_in_0)
    assert rtr is routers[0] and idx == 0
    rtr, idx = router.which_router_tod(routers, t_in_1)
    assert rtr is routers[1] and idx == 1
    rtr, idx = router.which_router_tod(routers, t_af_1)
    assert rtr is routers[1] and idx == 1

    pass