#!/usr/bin/python3
#
# Copyright (c) 2020 Intel Corporation
# SPDX-License-Identifier: Apache-2.0

import os
import sys
import time
import mmap

# Log reader for the trace output buffer on a ADSP device.
#
# When run with no arguments, it will detect the device, dump the
# contents of the trace buffer and continue to poll for more output.
# The "--no-history" argument can be passed to suppress emission of the
# history, and emit only new output.  This can be useful for test
# integration where the user does not want to see any previous runs in
# the log output.
#
# The trace buffer is inside a shared memory region exposed by the
# audio PCI device as a BAR at index 4.  The hardware provides 4 128k
# "windows" starting at 512kb in the BAR which the DSP firmware can
# map to 4k-aligned locations within its own address space.  By
# protocol convention log output is an 8k region at window index 3.
#
# The 8k window is treated as an array of 64-byte "slots", each of
# which is prefixed by a magic number, which should be 0x55aa for log
# data, followed a 16 bit "ID" number, followed by a null-terminated
# string in the final 60 bytes (or 60 non-null bytes of log data).
# The DSP firmware will write sequential IDs into the buffer starting
# from an ID of zero in the first slot, and wrapping at the end.

MAP_SIZE = 8192
SLOT_SIZE = 64
NUM_SLOTS = int(MAP_SIZE / SLOT_SIZE)
SLOT_MAGIC = 0x55aa
WIN_OFFSET = 0x80000
WIN_IDX = 3
WIN_SIZE = 0x20000
LOG_OFFSET = WIN_OFFSET + WIN_IDX * WIN_SIZE

mem = None
sys_devices = "/sys/bus/pci/devices"

reset_logged = False

for dev_addr in os.listdir(sys_devices):
    class_file = sys_devices + "/" + dev_addr + "/class"
    pciclass = open(class_file).read()

    vendor_file = sys_devices + "/" + dev_addr + "/vendor"
    pcivendor = open(vendor_file).read()

    if not "0x8086" in pcivendor:
        continue

    # Intel Multimedia audio controller
    #   0x040100 -> DSP is present
    #   0x040380 -> DSP is present but optional
    if "0x040100" in pciclass or "0x040380" in pciclass:
        barfile = sys_devices + "/" + dev_addr + "/resource4"

        fd = open(barfile)
        mem = mmap.mmap(fd.fileno(), MAP_SIZE, offset=LOG_OFFSET,
                    prot=mmap.PROT_READ)
        break

if mem is None:
    sys.stderr.write("ERROR: No ADSP device found.\n")
    sys.exit(1)

# Returns a tuple of (id, msg) if the slot is valid, or (-1, "") if
# the slot does not contain firmware trace data
def read_slot(slot, mem):
    off = slot * SLOT_SIZE

    magic = (mem[off + 1] << 8) | mem[off]
    sid = (mem[off + 3] << 8) | mem[off + 2]

    if magic != SLOT_MAGIC:
        return (-1, "")

    # This dance because indexing large variable-length slices of
    # the mmap() array seems to produce garbage....
    msgbytes = []
    for i in range(4, SLOT_SIZE):
        b = mem[off+i]
        if b == 0:
            break
        msgbytes.append(b)
    msg = bytearray(len(msgbytes))
    for i, elem in enumerate(msgbytes):
        msg[i] = elem

    return (sid, msg.decode(encoding="utf-8", errors="ignore"))

def read_hist(start_slot):
    global reset_logged
    id0, msg = read_slot(start_slot, mem)

    # An invalid slot zero means no data has ever been placed in the
    # trace buffer, which is likely a system reset condition.  Back
    # off for one second, because continuing to read the buffer has
    # been observed to hang the flash process (which I think can only
    # be a hardware bug).
    if start_slot == 0 and id0 < 0:
        if not reset_logged:
            sys.stdout.write("===\n=== [ADSP Device Reset?]\n===\n")
            sys.stdout.flush()
        reset_logged = True
        time.sleep(0.1)
        return (0, 0, "")

    reset_logged = False

    # Start at zero and read forward to get the last data in the
    # buffer.  We are always guaranteed that slot zero will contain
    # valid data if any slot contains valid data.
    last_id = id0
    final_slot = start_slot
    for i in range(start_slot + 1, NUM_SLOTS):
        id, s = read_slot(i, mem)
        if id != ((last_id + 1) & 0xffff):
            break
        msg += s
        final_slot = i
        last_id = id

    final_id = last_id

    # Now read backwards from the end to get the prefix blocks from
    # the last wraparound
    last_id = id0
    for i in range(NUM_SLOTS - 1, final_slot, -1):
        id, s = read_slot(i, mem)
        if id < 0:
            break

        # Race protection: the other side might have clobbered the
        # data after we read the ID, make sure it hasn't changed.
        id_check = read_slot(i, mem)[0]
        if id_check != id:
            break

        if ((id + 1) & 0xffff) == last_id:
            msg = s + msg
        last_id = id

    # If we were unable to read forward from slot zero, but could read
    # backward, then this is a wrapped buffer being currently updated
    # into slot zero.  See comment below.
    if final_slot == start_slot and last_id != id0:
        return None

    return ((final_slot + 1) % NUM_SLOTS, (final_id + 1) & 0xffff, msg)

# Returns a tuple containing the next slot to expect data in, the ID
# that slot should hold, and the full string history of trace data
# from the buffer.  Start with slot zero (which is always part of the
# current string if there is any data at all) and scan forward and
# back to find the maximum extent.
def trace_history():
    # This loop is a race protection for the situation where the
    # buffer has wrapped and new data is currently being placed into
    # slot zero.  In those circumstances, slot zero will have a valid
    # magic number but its sequence ID will not correlate with the
    # previous and next slots.
    ret = None
    while ret is None:
        ret = read_hist(0)
        if ret is None:
            ret = read_hist(1)
    return ret


# Loop, reading the next slot if it has new data.  Otherwise check the
# full buffer and see if history is discontiguous (i.e. what is in the
# buffer should be a proper suffix of what we have stored).  If it
# doesn't match, then just print it (it's a reboot or a ring buffer
# overrun).  If nothing has changed, then sleep a bit and keep
# polling.
def main():
    next_slot, next_id, last_hist = trace_history()

    # We only have one command line argument, to suppress the history
    # dump at the start (so CI runs don't see e.g. a previous device
    # state containing logs from another test, and get confused)
    if len(sys.argv) < 2 or sys.argv[1] != "--no-history":
        sys.stdout.write(last_hist)

    while True:
        id, smsg = read_slot(next_slot, mem)

        if id == next_id:
            next_slot = int((next_slot + 1) % NUM_SLOTS)
            next_id = (id + 1) & 0xffff
            last_hist += smsg
            sys.stdout.write(smsg)
        else:
            slot2, id2, msg2 = trace_history()

            # Device reset:
            if slot2 == 0 and id2 == 0 and msg2 == "":
                next_id = 1
                next_slot = slot2
                last_hist = ""

            if not last_hist.endswith(msg2):
                # On a mismatch, go back and check one last time to
                # address the race where a new slot wasn't present
                # just JUST THEN but is NOW.
                id3, s3 = read_slot(next_slot, mem)
                if id3 == next_id:
                    next_slot = int((next_slot + 1) % NUM_SLOTS)
                    next_id = (next_id + 1) & 0xffff
                    last_hist += s3
                    sys.stdout.write(s3)
                    continue

                # Otherwise it represents discontiguous data, either a
                # reset of an overrun, just dump what we have and
                # start over.
                next_slot = slot2
                last_hist = msg2
                sys.stdout.write(msg2)
            else:
                sys.stdout.flush()
                time.sleep(0.10)

if __name__ == "__main__":
    main()