3proxy/tests/cases/logs.py

"""Logs: one for each log string, shared by every service naming it, kept
over a reload while something uses it and closed once nothing does. A log
which cannot be written passes its lines to standard error."""

import os
import time


def _read(path):
    try:
        with open(path, "rb") as fp:
            return fp.read().decode("utf-8", "replace")
    except OSError:
        return ""


def _proxied(path, mark):
    """Whether a proxy, not the origin, logged the request marked so."""
    return any(line.startswith("LOG PROXY") and mark in line
               for line in _read(path).splitlines())


def _wait(cond, timeout=10.0):
    deadline = time.time() + timeout
    while time.time() < deadline:
        if cond():
            return True
        time.sleep(0.05)
    return cond()


def _opened(pid, path):
    """How many times the process has the file open, None without /proc."""
    fds = f"/proc/{pid}/fd"
    if not os.path.isdir(fds):
        return None
    n = 0
    for fd in os.listdir(fds):
        try:
            if os.readlink(os.path.join(fds, fd)) == path:
                n += 1
        except OSError:
            pass
    return n


def config(origin, p1, p2, p3, adm, main, shared=None):
    """p2 and p3 log to shared with -l, if it is given, or are not there."""
    lines = [f"log {main}", 'logformat "LLOG %N %T"', "auth iponly", "allow *",
             "http data * /data", f"httpsrv -p{origin}", f"proxy -p{p1}"]
    if shared:
        lines += [f"proxy -p{p2} -l{shared}", f"proxy -p{p3} -l{shared}"]
    lines.append(f"admin -p{adm}")
    return "\n".join(lines) + "\n"


def run(t):
    origin, p1, p2, p3, adm = (t.free_port() for _ in range(5))
    first = os.path.join(t.tmpdir, "logs-first.log")
    second = os.path.join(t.tmpdir, "logs-second.log")
    shared = os.path.join(t.tmpdir, "logs-shared.log")

    server = t.start("logs", config(origin, p1, p2, p3, adm, first, shared),
                     ports=[origin, p1, p2, p3, adm])
    pid = server.proc.pid

    def get(port, mark):
        return t.http(f"http://127.0.0.1:{origin}/data?size=10&{mark}",
                      proxy=f"127.0.0.1:{port}").status

    # --- the log command and -l ----------------------------------------
    t.eq(200, get(p1, "one"), "a request through the first proxy")
    t.eq(200, get(p2, "two"), "one through the second")
    t.eq(200, get(p3, "three"), "one through the third")
    t.eq(True, _wait(lambda: _proxied(first, "one")), "the log command's file gets its line")
    t.eq(True, _wait(lambda: _proxied(shared, "two") and _proxied(shared, "three")),
         "the two services with the same -l write to the same file")
    t.eq(False, _proxied(first, "two"), "and not to the log command's")
    t.eq(False, _proxied(shared, "one"), "nor the other way round")
    n = _opened(pid, shared)
    if n is not None:
        t.eq(1, n, "the file named by both is opened once")
        t.eq(1, _opened(pid, first), "the log command's file is open")

    def reload(main, until):
        t.write_config("logs", config(origin, p1, p2, p3, adm, main))
        t.http(f"http://127.0.0.1:{adm}/R")
        return _wait(until)

    # --- a reload to another file: the old one is closed once unused -----
    t.eq(True, reload(second, lambda: "Accepting connections" in _read(second)),
         "the new configuration logs to the new file")
    t.eq(200, get(p1, "four"), "a request after the reload")
    t.eq(True, _wait(lambda: _proxied(second, "four")), "goes to the new file")
    t.eq(False, _proxied(first, "four"), "not to the old one")
    if n is not None:
        t.eq(True, _wait(lambda: _opened(pid, first) == 0),
             "the old file is closed once its services are gone")
        t.eq(True, _wait(lambda: _opened(pid, shared) == 0),
             "and so is the file of -l nobody names any more")
        t.eq(1, _opened(pid, second), "the new one is open")

    # --- the same file, rotated daily: reopened under the day's name -----
    dated = second + "." + time.strftime("%Y.%m.%d")
    t.eq(True, reload(second + " D", lambda: os.path.exists(dated)),
         "a rotation given to the log reopens it under the dated name")
    t.eq(200, get(p1, "five"), "a request after that")
    t.eq(True, _wait(lambda: _proxied(dated, "five")), "goes to the dated file")
    t.eq(False, _proxied(second, "five"), "not to the undated one")

    # --- a log which fails ------------------------------------------------
    if os.path.exists("/dev/full"):
        o2, q = t.free_port(), t.free_port()
        full = t.start("logs_full", f"""
            log /dev/full
            logformat "LLOG %N %T"
            auth iponly
            allow *
            http data * /data
            httpsrv -p{o2}
            proxy -p{q}
        """, ports=[o2, q])
        # a buffer's worth, at least, before writing it fails
        for i in range(80):
            t.http(f"http://127.0.0.1:{o2}/data?size=10&{'x' * 40}{i}",
                   proxy=f"127.0.0.1:{q}")
        t.eq(True, _wait(lambda: "LOG PROXY" in full.output()),
             "the lines a full device refuses go to standard error")

    # --- a log which cannot be opened is an error in the configuration ---
    out = t.run_config("logs_bad", f"""
        log {os.path.join(t.tmpdir, "no", "such", "dir", "x.log")}
        proxy -p{t.free_port()}
    """)
    t.contains(out, "x.log", "a log which cannot be opened is named")