Format.cc

Go to the documentation of this file.

/*
 * Copyright (C) 1996-2023 The Squid Software Foundation and contributors
 *
 * Squid software is distributed under GPLv2+ license and includes
 * contributions from numerous individuals and organizations.
 * Please see the COPYING and CONTRIBUTORS files for details.
 */
 
#include "squid.h"
#include "AccessLogEntry.h"
#include "base64.h"
#include "client_side.h"
#include "comm/Connection.h"
#include "error/Detail.h"
#include "errorpage.h"
#include "fde.h"
#include "format/Format.h"
#include "format/Quoting.h"
#include "format/Token.h"
#include "http/Stream.h"
#include "HttpRequest.h"
#include "MemBuf.h"
#include "proxyp/Header.h"
#include "rfc1738.h"
#include "sbuf/Stream.h"
#include "sbuf/StringConvert.h"
#include "security/CertError.h"
#include "security/Certificate.h"
#include "security/NegotiationHistory.h"
#include "Store.h"
#include "tools.h"
#if USE_OPENSSL
#include "ssl/ErrorDetail.h"
#include "ssl/ServerBump.h"
#endif
 
#define strOrNull(s) ((s)==NULL||(s)[0]=='\0'?NULL:(s))
 
const SBuf Format::Dash("-");
 
Format::Format::Format(const char *n) :
    format(nullptr),
    next(nullptr)
{
    name = xstrdup(n);
}
 
Format::Format::~Format()
{
    // erase the list without consuming stack space
    while (next) {
        // unlink the next entry for deletion
        Format *temp = next;
        next = temp->next;
        temp->next = nullptr;
        delete temp;
    }
 
    // remove locals
    xfree(name);
    delete format;
}
 
bool
Format::Format::parse(const char *def)
{
    const char *cur, *eos;
    Token *new_lt, *last_lt;
    enum Quoting quote = LOG_QUOTE_NONE;
 
    debugs(46, 2, "got definition '" << def << "'");
 
    if (format) {
        debugs(46, DBG_IMPORTANT, "WARNING: existing format for '" << name << " " << def << "'");
        return false;
    }
 
    /* very inefficient parser, but who cares, this needs to be simple */
    /* First off, let's tokenize, we'll optimize in a second pass.
     * A token can either be a %-prefixed sequence (usually a dynamic
     * token but it can be an escaped sequence), or a string. */
    cur = def;
    eos = def + strlen(def);
    format = new_lt = last_lt = new Token;
    cur += new_lt->parse(cur, &quote);
 
    while (cur < eos) {
        new_lt = new Token;
        last_lt->next = new_lt;
        last_lt = new_lt;
        cur += new_lt->parse(cur, &quote);
    }
 
    return true;
}
 
size_t
Format::AssembleOne(const char *token, MemBuf &mb, const AccessLogEntryPointer &ale)
{
    Token tkn;
    enum Quoting quote = LOG_QUOTE_NONE;
    const auto tokenSize = tkn.parse(token, &quote);
    assert(tokenSize > 0);
    if (ale != nullptr) {
        Format fmt("SimpleToken");
        fmt.format = &tkn;
        fmt.assemble(mb, ale, 0);
        fmt.format = nullptr;
    } else {
        mb.append("-", 1);
    }
    return static_cast<size_t>(tokenSize);
}
 
void
Format::Format::dump(StoreEntry * entry, const char *directiveName, bool eol) const
{
    debugs(46, 4, MYNAME);
 
    // loop rather than recursing to conserve stack space.
    for (const Format *fmt = this; fmt; fmt = fmt->next) {
        debugs(46, 3, "Dumping format definition for " << fmt->name);
        if (directiveName)
            storeAppendPrintf(entry, "%s %s ", directiveName, fmt->name);
 
        for (Token *t = fmt->format; t; t = t->next) {
            if (t->type == LFT_STRING)
                storeAppendPrintf(entry, "%s", t->data.string);
            else {
                char argbuf[256];
                char *arg = nullptr;
                ByteCode_t type = t->type;
 
                switch (type) {
                /* special cases */
 
                case LFT_STRING:
                    break;
#if USE_ADAPTATION
                case LFT_ADAPTATION_LAST_HEADER_ELEM:
#endif
#if ICAP_CLIENT
                case LFT_ICAP_REQ_HEADER_ELEM:
                case LFT_ICAP_REP_HEADER_ELEM:
#endif
                case LFT_REQUEST_HEADER_ELEM:
                case LFT_ADAPTED_REQUEST_HEADER_ELEM:
                case LFT_REPLY_HEADER_ELEM:
 
                    if (t->data.header.separator != ',')
                        snprintf(argbuf, sizeof(argbuf), "%s:%c%s", t->data.header.header, t->data.header.separator, t->data.header.element);
                    else
                        snprintf(argbuf, sizeof(argbuf), "%s:%s", t->data.header.header, t->data.header.element);
 
                    arg = argbuf;
 
                    switch (type) {
                    case LFT_REQUEST_HEADER_ELEM:
                        type = LFT_REQUEST_HEADER_ELEM; // XXX: remove _ELEM?
                        break;
                    case LFT_ADAPTED_REQUEST_HEADER_ELEM:
                        type = LFT_ADAPTED_REQUEST_HEADER_ELEM; // XXX: remove _ELEM?
                        break;
                    case LFT_REPLY_HEADER_ELEM:
                        type = LFT_REPLY_HEADER_ELEM; // XXX: remove _ELEM?
                        break;
#if USE_ADAPTATION
                    case LFT_ADAPTATION_LAST_HEADER_ELEM:
                        type = LFT_ADAPTATION_LAST_HEADER;
                        break;
#endif
#if ICAP_CLIENT
                    case LFT_ICAP_REQ_HEADER_ELEM:
                        type = LFT_ICAP_REQ_HEADER;
                        break;
                    case LFT_ICAP_REP_HEADER_ELEM:
                        type = LFT_ICAP_REP_HEADER;
                        break;
#endif
                    default:
                        break;
                    }
 
                    break;
 
                case LFT_REQUEST_ALL_HEADERS:
                case LFT_ADAPTED_REQUEST_ALL_HEADERS:
                case LFT_REPLY_ALL_HEADERS:
 
#if USE_ADAPTATION
                case LFT_ADAPTATION_LAST_ALL_HEADERS:
#endif
#if ICAP_CLIENT
                case LFT_ICAP_REQ_ALL_HEADERS:
                case LFT_ICAP_REP_ALL_HEADERS:
#endif
 
                    switch (type) {
                    case LFT_REQUEST_ALL_HEADERS:
                        type = LFT_REQUEST_HEADER;
                        break;
                    case LFT_ADAPTED_REQUEST_ALL_HEADERS:
                        type = LFT_ADAPTED_REQUEST_HEADER;
                        break;
                    case LFT_REPLY_ALL_HEADERS:
                        type = LFT_REPLY_HEADER;
                        break;
#if USE_ADAPTATION
                    case LFT_ADAPTATION_LAST_ALL_HEADERS:
                        type = LFT_ADAPTATION_LAST_HEADER;
                        break;
#endif
#if ICAP_CLIENT
                    case LFT_ICAP_REQ_ALL_HEADERS:
                        type = LFT_ICAP_REQ_HEADER;
                        break;
                    case LFT_ICAP_REP_ALL_HEADERS:
                        type = LFT_ICAP_REP_HEADER;
                        break;
#endif
                    default:
                        break;
                    }
 
                    break;
 
                default:
                    if (t->data.string)
                        arg = t->data.string;
 
                    break;
                }
 
                entry->append("%", 1);
 
                switch (t->quote) {
 
                case LOG_QUOTE_QUOTES:
                    entry->append("\"", 1);
                    break;
 
                case LOG_QUOTE_MIMEBLOB:
                    entry->append("[", 1);
                    break;
 
                case LOG_QUOTE_URL:
                    entry->append("#", 1);
                    break;
 
                case LOG_QUOTE_RAW:
                    entry->append("'", 1);
                    break;
 
                case LOG_QUOTE_SHELL:
                    entry->append("/", 1);
                    break;
 
                case LOG_QUOTE_NONE:
                    break;
                }
 
                if (t->left)
                    entry->append("-", 1);
 
                if (t->zero)
                    entry->append("0", 1);
 
                if (t->widthMin >= 0)
                    storeAppendPrintf(entry, "%d", t->widthMin);
 
                if (t->widthMax >= 0)
                    storeAppendPrintf(entry, ".%d", t->widthMax);
 
                if (arg)
                    storeAppendPrintf(entry, "{%s}", arg);
 
                storeAppendPrintf(entry, "%s", t->label);
 
                if (t->space)
                    entry->append(" ", 1);
            }
        }
 
        if (eol)
            entry->append("\n", 1);
    }
 
}
 
static void
log_quoted_string(const char *str, char *out)
{
    char *p = out;
 
    while (*str) {
        int l = strcspn(str, "\"\\\r\n\t");
        memcpy(p, str, l);
        str += l;
        p += l;
 
        switch (*str) {
 
        case '\0':
            break;
 
        case '\r':
            *p = '\\';
            ++p;
            *p = 'r';
            ++p;
            ++str;
            break;
 
        case '\n':
            *p = '\\';
            ++p;
            *p = 'n';
            ++p;
            ++str;
            break;
 
        case '\t':
            *p = '\\';
            ++p;
            *p = 't';
            ++p;
            ++str;
            break;
 
        default:
            *p = '\\';
            ++p;
            *p = *str;
            ++p;
            ++str;
            break;
        }
    }
 
    *p = '\0';
}
 
static const Http::Message *
actualReplyHeader(const AccessLogEntry::Pointer &al)
{
    const Http::Message *msg = al->reply.getRaw();
#if ICAP_CLIENT
    // al->icap.reqMethod is methodNone in access.log context
    if (!msg && al->icap.reqMethod == Adaptation::methodReqmod)
        msg = al->adapted_request;
#endif
    return msg;
}
 
static const Http::Message *
actualRequestHeader(const AccessLogEntry::Pointer &al)
{
#if ICAP_CLIENT
    // al->icap.reqMethod is methodNone in access.log context
    if (al->icap.reqMethod == Adaptation::methodRespmod) {
        // XXX: for now AccessLogEntry lacks virgin response headers
        return nullptr;
    }
#endif
    return al->request;
}
 
void
Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logSequenceNumber) const
{
    static char tmp[1024];
    SBuf sb;
 
    for (Token *fmt = format; fmt; fmt = fmt->next) {   /* for each token */
        const char *out = nullptr;
        int quote = 0;
        long int outint = 0;
        int doint = 0;
        int dofree = 0;
        int64_t outoff = 0;
        int dooff = 0;
        struct timeval outtv = {};
        int doMsec = 0;
        int doSec = 0;
        bool doUint64 = false;
        uint64_t outUint64 = 0;
 
        switch (fmt->type) {
 
        case LFT_NONE:
            out = "";
            break;
 
        case LFT_BYTE:
            tmp[0] = static_cast<char>(fmt->data.byteValue);
            tmp[1] = '\0';
            out = tmp;
            break;
 
        case LFT_STRING:
            out = fmt->data.string;
            break;
 
        case LFT_CLIENT_IP_ADDRESS:
            al->getLogClientIp(tmp, sizeof(tmp));
            out = tmp;
            break;
 
        case LFT_CLIENT_FQDN:
            out = al->getLogClientFqdn(tmp, sizeof(tmp));
            break;
 
        case LFT_CLIENT_PORT:
            if (al->request) {
                outint = al->request->client_addr.port();
                doint = 1;
            } else if (al->tcpClient) {
                outint = al->tcpClient->remote.port();
                doint = 1;
            }
            break;
 
        case LFT_CLIENT_EUI:
#if USE_SQUID_EUI
            // TODO make the ACL checklist have a direct link to any TCP details.
            if (al->request && al->request->clientConnectionManager.valid() &&
                    al->request->clientConnectionManager->clientConnection) {
                const auto &conn = al->request->clientConnectionManager->clientConnection;
                if (conn->remote.isIPv4())
                    conn->remoteEui48.encode(tmp, sizeof(tmp));
                else
                    conn->remoteEui64.encode(tmp, sizeof(tmp));
                out = tmp;
            }
#endif
            break;
 
        case LFT_EXT_ACL_CLIENT_EUI48:
#if USE_SQUID_EUI
            if (al->request && al->request->clientConnectionManager.valid() &&
                    al->request->clientConnectionManager->clientConnection &&
                    al->request->clientConnectionManager->clientConnection->remote.isIPv4()) {
                al->request->clientConnectionManager->clientConnection->remoteEui48.encode(tmp, sizeof(tmp));
                out = tmp;
            }
#endif
            break;
 
        case LFT_EXT_ACL_CLIENT_EUI64:
#if USE_SQUID_EUI
            if (al->request && al->request->clientConnectionManager.valid() &&
                    al->request->clientConnectionManager->clientConnection &&
                    !al->request->clientConnectionManager->clientConnection->remote.isIPv4()) {
                al->request->clientConnectionManager->clientConnection->remoteEui64.encode(tmp, sizeof(tmp));
                out = tmp;
            }
#endif
            break;
 
        case LFT_SERVER_IP_ADDRESS:
            if (al->hier.tcpServer)
                out = al->hier.tcpServer->remote.toStr(tmp, sizeof(tmp));
            break;
 
        case LFT_SERVER_FQDN_OR_PEER_NAME:
            out = al->hier.host;
            break;
 
        case LFT_SERVER_PORT:
            if (al->hier.tcpServer) {
                outint = al->hier.tcpServer->remote.port();
                doint = 1;
            }
            break;
 
        case LFT_LOCAL_LISTENING_IP:
            if (const auto addr = FindListeningPortAddress(nullptr, al.getRaw()))
                out = addr->toStr(tmp, sizeof(tmp));
            break;
 
        case LFT_CLIENT_LOCAL_IP:
            if (al->tcpClient)
                out = al->tcpClient->local.toStr(tmp, sizeof(tmp));
            break;
 
        case LFT_CLIENT_LOCAL_TOS:
            if (al->tcpClient) {
                sb.appendf("0x%x", static_cast<uint32_t>(al->tcpClient->tos));
                out = sb.c_str();
            }
            break;
 
        case LFT_TRANSPORT_CLIENT_CONNECTION_ID:
            if (al->tcpClient) {
                outUint64 = al->tcpClient->id.value;
                doUint64 = true;
            }
            break;
 
        case LFT_CLIENT_LOCAL_NFMARK:
            if (al->tcpClient) {
                sb.appendf("0x%x", al->tcpClient->nfmark);
                out = sb.c_str();
            }
            break;
 
        case LFT_LOCAL_LISTENING_PORT:
            if (const auto port = FindListeningPortNumber(nullptr, al.getRaw())) {
                outint = *port;
                doint = 1;
            }
            break;
 
        case LFT_CLIENT_LOCAL_PORT:
            if (al->tcpClient) {
                outint = al->tcpClient->local.port();
                doint = 1;
            }
            break;
 
        case LFT_SERVER_LOCAL_IP_OLD_27:
        case LFT_SERVER_LOCAL_IP:
            if (al->hier.tcpServer)
                out = al->hier.tcpServer->local.toStr(tmp, sizeof(tmp));
            break;
 
        case LFT_SERVER_LOCAL_PORT:
            if (al->hier.tcpServer) {
                outint = al->hier.tcpServer->local.port();
                doint = 1;
            }
            break;
 
        case LFT_SERVER_LOCAL_TOS:
            if (al->hier.tcpServer) {
                sb.appendf("0x%x", static_cast<uint32_t>(al->hier.tcpServer->tos));
                out = sb.c_str();
            }
            break;
 
        case LFT_SERVER_LOCAL_NFMARK:
            if (al->hier.tcpServer) {
                sb.appendf("0x%x", al->hier.tcpServer->nfmark);
                out = sb.c_str();
            }
            break;
 
        case LFT_CLIENT_HANDSHAKE:
            if (al->request && al->request->clientConnectionManager.valid()) {
                const auto &handshake = al->request->clientConnectionManager->preservedClientData;
                if (const auto rawLength = handshake.length()) {
                    // add 1 byte to optimize the c_str() conversion below
                    char *buf = sb.rawAppendStart(base64_encode_len(rawLength) + 1);
 
                    struct base64_encode_ctx ctx;
                    base64_encode_init(&ctx);
                    auto encLength = base64_encode_update(&ctx, buf, rawLength, reinterpret_cast<const uint8_t*>(handshake.rawContent()));
                    encLength += base64_encode_final(&ctx, buf + encLength);
 
                    sb.rawAppendFinish(buf, encLength);
                    out = sb.c_str();
                }
            }
            break;
 
        case LFT_TIME_SECONDS_SINCE_EPOCH:
            // some platforms store time in 32-bit, some 64-bit...
            outoff = static_cast<int64_t>(current_time.tv_sec);
            dooff = 1;
            break;
 
        case LFT_TIME_SUBSECOND:
            outint = current_time.tv_usec / fmt->divisor;
            doint = 1;
            break;
 
        case LFT_TIME_LOCALTIME:
        case LFT_TIME_GMT: {
            const char *spec;
            struct tm *t;
            spec = fmt->data.string;
 
            if (fmt->type == LFT_TIME_LOCALTIME) {
                if (!spec)
                    spec = "%d/%b/%Y:%H:%M:%S %z";
                t = localtime(&squid_curtime);
            } else {
                if (!spec)
                    spec = "%d/%b/%Y:%H:%M:%S";
 
                t = gmtime(&squid_curtime);
            }
 
            strftime(tmp, sizeof(tmp), spec, t);
            out = tmp;
        }
        break;
 
        case LFT_TIME_START:
            outtv = al->cache.start_time;
            doSec = 1;
            break;
 
        case LFT_BUSY_TIME: {
            const auto &stopwatch = al->busyTime;
            if (stopwatch.ran()) {
                // make sure total() returns nanoseconds compatible with outoff
                using nanos = std::chrono::duration<decltype(outoff), std::nano>;
                const nanos n = stopwatch.total();
                outoff = n.count();
                dooff = true;
            }
        }
        break;
 
        case LFT_TIME_TO_HANDLE_REQUEST:
            outtv = al->cache.trTime;
            doMsec = 1;
            break;
 
        case LFT_PEER_RESPONSE_TIME:
            struct timeval peerResponseTime;
            if (al->hier.peerResponseTime(peerResponseTime)) {
                outtv = peerResponseTime;
                doMsec = 1;
            }
            break;
 
        case LFT_TOTAL_SERVER_SIDE_RESPONSE_TIME: {
            // XXX: al->hier.totalPeeringTime is not updated until prepareLogWithRequestDetails().
            // TODO: Avoid the need for updates by keeping totalPeeringTime (or even ALE::hier) in one place.
            const auto &timer = (!al->hier.totalPeeringTime.ran() && al->request) ?
                                al->request->hier.totalPeeringTime : al->hier.totalPeeringTime;
            if (timer.ran()) {
                using namespace std::chrono_literals;
                const auto duration = timer.total();
                outtv.tv_sec = std::chrono::duration_cast<std::chrono::seconds>(duration).count();
                const auto totalUsec = std::chrono::duration_cast<std::chrono::microseconds>(duration);
                outtv.tv_usec = (totalUsec % std::chrono::microseconds(1s)).count();
                doMsec = 1;
            }
        }
        break;
 
        case LFT_DNS_WAIT_TIME:
            if (al->request && al->request->dnsWait >= 0) {
                // TODO: microsecond precision for dns wait time.
                // Convert milliseconds to timeval struct:
                outtv.tv_sec = al->request->dnsWait / 1000;
                outtv.tv_usec = (al->request->dnsWait % 1000) * 1000;
                doMsec = 1;
            }
            break;
 
        case LFT_REQUEST_HEADER:
            if (const Http::Message *msg = actualRequestHeader(al)) {
                sb = StringToSBuf(msg->header.getByName(fmt->data.header.header));
                out = sb.c_str();
                quote = 1;
            }
            break;
 
        case LFT_ADAPTED_REQUEST_HEADER:
            if (al->adapted_request) {
                sb = StringToSBuf(al->adapted_request->header.getByName(fmt->data.header.header));
                out = sb.c_str();
                quote = 1;
            }
            break;
 
        case LFT_REPLY_HEADER:
            if (const Http::Message *msg = actualReplyHeader(al)) {
                sb = StringToSBuf(msg->header.getByName(fmt->data.header.header));
                out = sb.c_str();
                quote = 1;
            }
            break;
 
#if USE_ADAPTATION
        case LFT_ADAPTATION_SUM_XACT_TIMES:
            if (al->request) {
                Adaptation::History::Pointer ah = al->request->adaptHistory();
                if (ah) {
                    ah->sumLogString(fmt->data.string, sb);
                    out = sb.c_str();
                }
            }
            break;
 
        case LFT_ADAPTATION_ALL_XACT_TIMES:
            if (al->request) {
                Adaptation::History::Pointer ah = al->request->adaptHistory();
                if (ah) {
                    ah->allLogString(fmt->data.string, sb);
                    out = sb.c_str();
                }
            }
            break;
 
        case LFT_ADAPTATION_LAST_HEADER:
            if (al->request) {
                const Adaptation::History::Pointer ah = al->request->adaptHistory();
                if (ah) { // XXX: add adapt::<all_h but use lastMeta here
                    sb = StringToSBuf(ah->allMeta.getByName(fmt->data.header.header));
                    out = sb.c_str();
                    quote = 1;
                }
            }
            break;
 
        case LFT_ADAPTATION_LAST_HEADER_ELEM:
            if (al->request) {
                const Adaptation::History::Pointer ah = al->request->adaptHistory();
                if (ah) { // XXX: add adapt::<all_h but use lastMeta here
                    sb = ah->allMeta.getByNameListMember(fmt->data.header.header, fmt->data.header.element, fmt->data.header.separator);
                    out = sb.c_str();
                    quote = 1;
                }
            }
            break;
 
        case LFT_ADAPTATION_LAST_ALL_HEADERS:
            out = al->adapt.last_meta;
            quote = 1;
            break;
#endif
 
#if ICAP_CLIENT
        case LFT_ICAP_ADDR:
            out = al->icap.hostAddr.toStr(tmp, sizeof(tmp));
            break;
 
        case LFT_ICAP_SERV_NAME:
            out = al->icap.serviceName.termedBuf();
            break;
 
        case LFT_ICAP_REQUEST_URI:
            out = al->icap.reqUri.termedBuf();
            break;
 
        case LFT_ICAP_REQUEST_METHOD:
            out = Adaptation::Icap::ICAP::methodStr(al->icap.reqMethod);
            break;
 
        case LFT_ICAP_BYTES_SENT:
            outoff = al->icap.bytesSent;
            dooff = 1;
            break;
 
        case LFT_ICAP_BYTES_READ:
            outoff = al->icap.bytesRead;
            dooff = 1;
            break;
 
        case LFT_ICAP_BODY_BYTES_READ:
            if (al->icap.bodyBytesRead >= 0) {
                outoff = al->icap.bodyBytesRead;
                dooff = 1;
            }
            // else if icap.bodyBytesRead < 0, we do not have any http data,
            // so just print a "-" (204 responses etc)
            break;
 
        case LFT_ICAP_REQ_HEADER:
            if (al->icap.request) {
                sb = StringToSBuf(al->icap.request->header.getByName(fmt->data.header.header));
                out = sb.c_str();
                quote = 1;
            }
            break;
 
        case LFT_ICAP_REQ_HEADER_ELEM:
            if (al->icap.request) {
                sb = al->icap.request->header.getByNameListMember(fmt->data.header.header, fmt->data.header.element, fmt->data.header.separator);
                out = sb.c_str();
                quote = 1;
            }
            break;
 
        case LFT_ICAP_REQ_ALL_HEADERS:
            if (al->icap.request) {
                HttpHeaderPos pos = HttpHeaderInitPos;
                while (const HttpHeaderEntry *e = al->icap.request->header.getEntry(&pos)) {
                    sb.append(e->name);
                    sb.append(": ");
                    sb.append(StringToSBuf(e->value));
                    sb.append("\r\n");
                }
                out = sb.c_str();
                quote = 1;
            }
            break;
 
        case LFT_ICAP_REP_HEADER:
            if (al->icap.reply) {
                sb = StringToSBuf(al->icap.reply->header.getByName(fmt->data.header.header));
                out = sb.c_str();
                quote = 1;
            }
            break;
 
        case LFT_ICAP_REP_HEADER_ELEM:
            if (al->icap.reply) {
                sb = al->icap.reply->header.getByNameListMember(fmt->data.header.header, fmt->data.header.element, fmt->data.header.separator);
                out = sb.c_str();
                quote = 1;
            }
            break;
 
        case LFT_ICAP_REP_ALL_HEADERS:
            if (al->icap.reply) {
                HttpHeaderPos pos = HttpHeaderInitPos;
                while (const HttpHeaderEntry *e = al->icap.reply->header.getEntry(&pos)) {
                    sb.append(e->name);
                    sb.append(": ");
                    sb.append(StringToSBuf(e->value));
                    sb.append("\r\n");
                }
                out = sb.c_str();
                quote = 1;
            }
            break;
 
        case LFT_ICAP_TR_RESPONSE_TIME:
            outtv = al->icap.trTime;
            doMsec = 1;
            break;
 
        case LFT_ICAP_IO_TIME:
            outtv = al->icap.ioTime;
            doMsec = 1;
            break;
 
        case LFT_ICAP_STATUS_CODE:
            outint = al->icap.resStatus;
            doint  = 1;
            break;
 
        case LFT_ICAP_OUTCOME:
            out = al->icap.outcome;
            break;
 
        case LFT_ICAP_TOTAL_TIME:
            outtv = al->icap.processingTime;
            doMsec = 1;
            break;
#endif
        case LFT_REQUEST_HEADER_ELEM:
            if (const Http::Message *msg = actualRequestHeader(al)) {
                sb = msg->header.getByNameListMember(fmt->data.header.header, fmt->data.header.element, fmt->data.header.separator);
                out = sb.c_str();
                quote = 1;
            }
            break;
 
        case LFT_PROXY_PROTOCOL_RECEIVED_HEADER:
            if (al->proxyProtocolHeader) {
                sb = al->proxyProtocolHeader->getValues(fmt->data.headerId, fmt->data.header.separator);
                out = sb.c_str();
                quote = 1;
            }
            break;
 
        case LFT_PROXY_PROTOCOL_RECEIVED_ALL_HEADERS:
            if (al->proxyProtocolHeader) {
                sb = al->proxyProtocolHeader->toMime();
                out = sb.c_str();
                quote = 1;
            }
            break;
 
        case LFT_PROXY_PROTOCOL_RECEIVED_HEADER_ELEM:
            if (al->proxyProtocolHeader) {
                sb = al->proxyProtocolHeader->getElem(fmt->data.headerId, fmt->data.header.element, fmt->data.header.separator);
                out = sb.c_str();
                quote = 1;
            }
            break;
 
        case LFT_ADAPTED_REQUEST_HEADER_ELEM:
            if (al->adapted_request) {
                sb = al->adapted_request->header.getByNameListMember(fmt->data.header.header, fmt->data.header.element, fmt->data.header.separator);
                out = sb.c_str();
                quote = 1;
            }
            break;
 
        case LFT_REPLY_HEADER_ELEM:
            if (const Http::Message *msg = actualReplyHeader(al)) {
                sb = msg->header.getByNameListMember(fmt->data.header.header, fmt->data.header.element, fmt->data.header.separator);
                out = sb.c_str();
                quote = 1;
            }
            break;
 
        case LFT_REQUEST_ALL_HEADERS:
#if ICAP_CLIENT
            if (al->icap.reqMethod == Adaptation::methodRespmod) {
                // XXX: since AccessLogEntry::Headers lacks virgin response
                // headers, do nothing for now
                out = nullptr;
            } else
#endif
            {
                // just headers without start-line and CRLF
                // XXX: reconcile with '<h'
                out = al->headers.request;
                quote = 1;
            }
            break;
 
        case LFT_ADAPTED_REQUEST_ALL_HEADERS:
            // just headers without start-line and CRLF
            // XXX: reconcile with '<h'
            out = al->headers.adapted_request;
            quote = 1;
            break;
 
        case LFT_REPLY_ALL_HEADERS: {
            MemBuf allHeaders;
            allHeaders.init();
            // status-line + headers + CRLF
            // XXX: reconcile with '>h' and '>ha'
            al->packReplyHeaders(allHeaders);
            sb.assign(allHeaders.content(), allHeaders.contentSize());
            out = sb.c_str();
#if ICAP_CLIENT
            if (!out && al->icap.reqMethod == Adaptation::methodReqmod)
                out = al->headers.adapted_request;
#endif
            quote = 1;
        }
        break;
 
        case LFT_USER_NAME:
#if USE_AUTH
            if (al->request && al->request->auth_user_request)
                out = strOrNull(al->request->auth_user_request->username());
#endif
            if (!out && al->request && al->request->extacl_user.size()) {
                if (const char *t = al->request->extacl_user.termedBuf())
                    out = t;
            }
            if (!out)
                out = strOrNull(al->getExtUser());
#if USE_OPENSSL
            if (!out)
                out = strOrNull(al->cache.ssluser);
#endif
            break;
 
        case LFT_USER_LOGIN:
#if USE_AUTH
            if (al->request && al->request->auth_user_request)
                out = strOrNull(al->request->auth_user_request->username());
#endif
            break;
 
        case LFT_USER_EXTERNAL:
            out = strOrNull(al->getExtUser());
            break;
 
        /* case LFT_USER_REALM: */
        /* case LFT_USER_SCHEME: */
 
        // the fmt->type can not be LFT_HTTP_SENT_STATUS_CODE_OLD_30
        // but compiler complains if omitted
        case LFT_HTTP_SENT_STATUS_CODE_OLD_30:
        case LFT_HTTP_SENT_STATUS_CODE:
            outint = al->http.code;
            doint = 1;
            break;
 
        case LFT_HTTP_RECEIVED_STATUS_CODE:
            if (al->hier.peer_reply_status != Http::scNone) {
                outint = al->hier.peer_reply_status;
                doint = 1;
            }
            break;
        /* case LFT_HTTP_STATUS:
         *           out = statusline->text;
         *     quote = 1;
         *     break;
         */
        case LFT_HTTP_BODY_BYTES_READ:
            if (al->hier.bodyBytesRead >= 0) {
                outoff = al->hier.bodyBytesRead;
                dooff = 1;
            }
            // else if hier.bodyBytesRead < 0 we did not have any data exchange with
            // a peer server so just print a "-" (eg requests served from cache,
            // or internal error messages).
            break;
 
        case LFT_SQUID_STATUS:
            out = al->cache.code.c_str();
            break;
 
        case LFT_SQUID_ERROR:
            if (const auto error = al->error())
                out = errorPageName(error->category);
            break;
 
        case LFT_SQUID_ERROR_DETAIL:
            if (const auto error = al->error()) {
                if (!error->details.empty()) {
                    sb = ToSBuf(error->details);
                    out = sb.c_str();
                }
            }
            break;
 
        case LFT_SQUID_HIERARCHY:
            if (al->hier.ping.timedout)
                mb.append("TIMEOUT_", 8);
            out = hier_code_str[al->hier.code];
            break;
 
        case LFT_SQUID_REQUEST_ATTEMPTS:
            outint = al->requestAttempts;
            doint = 1;
            break;
 
        case LFT_MIME_TYPE:
            out = al->http.content_type;
            break;
 
        case LFT_CLIENT_REQ_METHOD:
            if (al->request) {
                sb = al->request->method.image();
                out = sb.c_str();
                quote = 1;
            }
            break;
 
        case LFT_CLIENT_REQ_URI:
            if (const auto uri = al->effectiveVirginUrl()) {
                sb = *uri;
                out = sb.c_str();
                quote = 1;
            }
            break;
 
        case LFT_CLIENT_REQ_URLSCHEME:
            if (al->request) {
                sb = al->request->url.getScheme().image();
                out = sb.c_str();
                quote = 1;
            }
            break;
 
        case LFT_CLIENT_REQ_URLDOMAIN:
            if (al->request) {
                out = al->request->url.host();
                quote = 1;
            }
            break;
 
        case LFT_CLIENT_REQ_URLPORT:
            if (al->request && al->request->url.port()) {
                outint = *al->request->url.port();
                doint = 1;
            }
            break;
 
        case LFT_REQUEST_URLPATH_OLD_31:
        case LFT_CLIENT_REQ_URLPATH:
            if (al->request) {
                sb = al->request->url.path();
                out = sb.c_str();
                quote = 1;
            }
            break;
 
        case LFT_CLIENT_REQ_VERSION:
            if (al->request) {
                sb.appendf("%u.%u", al->request->http_ver.major, al->request->http_ver.minor);
                out = sb.c_str();
            }
            break;
 
        case LFT_REQUEST_METHOD:
            if (al->hasLogMethod()) {
                sb = al->getLogMethod();
                out = sb.c_str();
                quote = 1;
            }
            break;
 
        case LFT_REQUEST_URI:
            if (!al->url.isEmpty()) {
                sb = al->url;
                out = sb.c_str();
            }
            break;
 
        case LFT_REQUEST_VERSION_OLD_2X:
        case LFT_REQUEST_VERSION:
            sb.appendf("%u.%u", al->http.version.major, al->http.version.minor);
            out = sb.c_str();
            break;
 
        case LFT_SERVER_REQ_METHOD:
            if (al->adapted_request) {
                sb = al->adapted_request->method.image();
                out = sb.c_str();
                quote = 1;
            }
            break;
 
        case LFT_SERVER_REQ_URI:
            // adapted request URI sent to server/peer
            if (al->adapted_request) {
                sb = al->adapted_request->effectiveRequestUri();
                out = sb.c_str();
                quote = 1;
            }
            break;
 
        case LFT_SERVER_REQ_URLSCHEME:
            if (al->adapted_request) {
                sb = al->adapted_request->url.getScheme().image();
                out = sb.c_str();
                quote = 1;
            }
            break;
 
        case LFT_SERVER_REQ_URLDOMAIN:
            if (al->adapted_request) {
                out = al->adapted_request->url.host();
                quote = 1;
            }
            break;
 
        case LFT_SERVER_REQ_URLPORT:
            if (al->adapted_request && al->adapted_request->url.port()) {
                outint = *al->adapted_request->url.port();
                doint = 1;
            }
            break;
 
        case LFT_SERVER_REQ_URLPATH:
            if (al->adapted_request) {
                sb = al->adapted_request->url.path();
                out = sb.c_str();
                quote = 1;
            }
            break;
 
        case LFT_SERVER_REQ_VERSION:
            if (al->adapted_request) {
                sb.appendf("%u.%u",
                           al->adapted_request->http_ver.major,
                           al->adapted_request->http_ver.minor);
                out = tmp;
            }
            break;
 
        case LFT_CLIENT_REQUEST_SIZE_TOTAL:
            outoff = al->http.clientRequestSz.messageTotal();
            dooff = 1;
            break;
 
        case LFT_CLIENT_REQUEST_SIZE_HEADERS:
            outoff = al->http.clientRequestSz.header;
            dooff =1;
            break;
 
        /*case LFT_REQUEST_SIZE_BODY: */
        /*case LFT_REQUEST_SIZE_BODY_NO_TE: */
 
        case LFT_ADAPTED_REPLY_SIZE_TOTAL:
            outoff = al->http.clientReplySz.messageTotal();
            dooff = 1;
            break;
 
        case LFT_REPLY_HIGHOFFSET:
            outoff = al->cache.highOffset;
            dooff = 1;
            break;
 
        case LFT_REPLY_OBJECTSIZE:
            outoff = al->cache.objectSize;
            dooff = 1;
            break;
 
        case LFT_ADAPTED_REPLY_SIZE_HEADERS:
            outint = al->http.clientReplySz.header;
            doint = 1;
            break;
 
        /*case LFT_REPLY_SIZE_BODY: */
        /*case LFT_REPLY_SIZE_BODY_NO_TE: */
 
        case LFT_CLIENT_IO_SIZE_TOTAL:
            outint = al->http.clientRequestSz.messageTotal() + al->http.clientReplySz.messageTotal();
            doint = 1;
            break;
        /*case LFT_SERVER_IO_SIZE_TOTAL: */
 
        case LFT_TAG:
            if (al->request) {
                out = al->request->tag.termedBuf();
                quote = 1;
            }
            break;
 
        case LFT_EXT_LOG:
            if (al->request) {
                out = al->request->extacl_log.termedBuf();
                quote = 1;
            }
            break;
 
        case LFT_SEQUENCE_NUMBER:
            outoff = logSequenceNumber;
            dooff = 1;
            break;
 
#if USE_OPENSSL
        case LFT_SSL_BUMP_MODE: {
            const Ssl::BumpMode mode = static_cast<Ssl::BumpMode>(al->ssl.bumpMode);
            // for Ssl::bumpEnd, Ssl::bumpMode() returns NULL and we log '-'
            out = Ssl::bumpMode(mode);
        }
        break;
 
        case LFT_EXT_ACL_USER_CERT_RAW:
            if (al->request) {
                ConnStateData *conn = al->request->clientConnectionManager.get();
                if (conn && Comm::IsConnOpen(conn->clientConnection)) {
                    if (const auto ssl = fd_table[conn->clientConnection->fd].ssl.get()) {
                        sb = sslGetUserCertificatePEM(ssl);
                        out = sb.c_str();
                    }
                }
            }
            break;
 
        case LFT_EXT_ACL_USER_CERTCHAIN_RAW:
            if (al->request) {
                ConnStateData *conn = al->request->clientConnectionManager.get();
                if (conn && Comm::IsConnOpen(conn->clientConnection)) {
                    if (const auto ssl = fd_table[conn->clientConnection->fd].ssl.get()) {
                        sb = sslGetUserCertificatePEM(ssl);
                        out = sb.c_str();
                    }
                }
            }
            break;
 
        case LFT_EXT_ACL_USER_CERT:
            if (al->request) {
                ConnStateData *conn = al->request->clientConnectionManager.get();
                if (conn && Comm::IsConnOpen(conn->clientConnection)) {
                    if (auto ssl = fd_table[conn->clientConnection->fd].ssl.get())
                        out = sslGetUserAttribute(ssl, fmt->data.header.header);
                }
            }
            break;
 
        case LFT_EXT_ACL_USER_CA_CERT:
            if (al->request) {
                ConnStateData *conn = al->request->clientConnectionManager.get();
                if (conn && Comm::IsConnOpen(conn->clientConnection)) {
                    if (auto ssl = fd_table[conn->clientConnection->fd].ssl.get())
                        out = sslGetCAAttribute(ssl, fmt->data.header.header);
                }
            }
            break;
 
        case LFT_SSL_USER_CERT_SUBJECT:
            if (const auto &cert = al->cache.sslClientCert) {
                sb = Security::SubjectName(*cert);
                out = sb.c_str();
            }
            break;
 
        case LFT_SSL_USER_CERT_ISSUER:
            if (const auto &cert = al->cache.sslClientCert) {
                sb = Security::IssuerName(*cert);
                out = sb.c_str();
            }
            break;
 
        case LFT_SSL_CLIENT_SNI:
            if (al->request && al->request->clientConnectionManager.valid()) {
                if (const ConnStateData *conn = al->request->clientConnectionManager.get()) {
                    if (!conn->tlsClientSni().isEmpty()) {
                        sb = conn->tlsClientSni();
                        out = sb.c_str();
                    }
                }
            }
            break;
 
        case LFT_SSL_SERVER_CERT_ERRORS:
            if (al->request && al->request->clientConnectionManager.valid()) {
                if (Ssl::ServerBump * srvBump = al->request->clientConnectionManager->serverBump()) {
                    const char *separator = fmt->data.string ? fmt->data.string : ":";
                    for (const Security::CertErrors *sslError = srvBump->sslErrors(); sslError; sslError = sslError->next) {
                        if (!sb.isEmpty())
                            sb.append(separator);
                        sb.append(Ssl::GetErrorName(sslError->element.code, true));
                        if (sslError->element.depth >= 0)
                            sb.appendf("@depth=%d", sslError->element.depth);
                    }
                    if (!sb.isEmpty())
                        out = sb.c_str();
                }
            }
            break;
 
        case LFT_SSL_SERVER_CERT_ISSUER:
        case LFT_SSL_SERVER_CERT_SUBJECT:
        case LFT_SSL_SERVER_CERT_WHOLE:
            if (al->request && al->request->clientConnectionManager.valid()) {
                if (Ssl::ServerBump * srvBump = al->request->clientConnectionManager->serverBump()) {
                    if (X509 *serverCert = srvBump->serverCert.get()) {
                        if (fmt->type == LFT_SSL_SERVER_CERT_SUBJECT)
                            out = Ssl::GetX509UserAttribute(serverCert, "DN");
                        else if (fmt->type == LFT_SSL_SERVER_CERT_ISSUER)
                            out = Ssl::GetX509CAAttribute(serverCert, "DN");
                        else {
                            assert(fmt->type == LFT_SSL_SERVER_CERT_WHOLE);
                            sb = Ssl::GetX509PEM(serverCert);
                            out = sb.c_str();
                            quote = 1;
                        }
                    }
                }
            }
            break;
 
        case LFT_TLS_CLIENT_NEGOTIATED_VERSION:
            if (al->tcpClient && al->tcpClient->hasTlsNegotiations())
                out = al->tcpClient->hasTlsNegotiations()->negotiatedVersion();
            break;
 
        case LFT_TLS_SERVER_NEGOTIATED_VERSION:
            if (al->hier.tcpServer && al->hier.tcpServer->hasTlsNegotiations())
                out = al->hier.tcpServer->hasTlsNegotiations()->negotiatedVersion();
            break;
 
        case LFT_TLS_CLIENT_RECEIVED_HELLO_VERSION:
            if (al->tcpClient && al->tcpClient->hasTlsNegotiations())
                out = al->tcpClient->hasTlsNegotiations()->helloVersion();
            break;
 
        case LFT_TLS_SERVER_RECEIVED_HELLO_VERSION:
            if (al->hier.tcpServer && al->hier.tcpServer->hasTlsNegotiations())
                out = al->hier.tcpServer->hasTlsNegotiations()->helloVersion();
            break;
 
        case LFT_TLS_CLIENT_SUPPORTED_VERSION:
            if (al->tcpClient && al->tcpClient->hasTlsNegotiations())
                out = al->tcpClient->hasTlsNegotiations()->supportedVersion();
            break;
 
        case LFT_TLS_SERVER_SUPPORTED_VERSION:
            if (al->hier.tcpServer && al->hier.tcpServer->hasTlsNegotiations())
                out = al->hier.tcpServer->hasTlsNegotiations()->supportedVersion();
            break;
 
        case LFT_TLS_CLIENT_NEGOTIATED_CIPHER:
            if (al->tcpClient && al->tcpClient->hasTlsNegotiations())
                out = al->tcpClient->hasTlsNegotiations()->cipherName();
            break;
 
        case LFT_TLS_SERVER_NEGOTIATED_CIPHER:
            if (al->hier.tcpServer && al->hier.tcpServer->hasTlsNegotiations())
                out = al->hier.tcpServer->hasTlsNegotiations()->cipherName();
            break;
#endif
 
        case LFT_REQUEST_URLGROUP_OLD_2X:
            assert(LFT_REQUEST_URLGROUP_OLD_2X == 0); // should never happen.
            break;
 
        case LFT_NOTE:
            tmp[0] = fmt->data.header.separator;
            tmp[1] = '\0';
            if (fmt->data.header.header && *fmt->data.header.header) {
                const char *separator = tmp;
                static SBuf note;
#if USE_ADAPTATION
                Adaptation::History::Pointer ah = al->request ? al->request->adaptHistory() : Adaptation::History::Pointer();
                if (ah && ah->metaHeaders) {
                    if (ah->metaHeaders->find(note, fmt->data.header.header, separator))
                        sb.append(note);
                }
#endif
                if (al->notes) {
                    if (al->notes->find(note, fmt->data.header.header, separator)) {
                        if (!sb.isEmpty())
                            sb.append(separator);
                        sb.append(note);
                    }
                }
                out = sb.c_str();
                quote = 1;
            } else {
                // No specific annotation requested. Report all annotations.
 
                // if no argument given use default "\r\n" as notes separator
                const char *separator = fmt->data.string ? tmp : "\r\n";
                SBufStream os;
#if USE_ADAPTATION
                Adaptation::History::Pointer ah = al->request ? al->request->adaptHistory() : Adaptation::History::Pointer();
                if (ah && ah->metaHeaders)
                    ah->metaHeaders->print(os, ": ", separator);
#endif
                if (al->notes)
                    al->notes->print(os, ": ", separator);
 
                sb = os.buf();
                out = sb.c_str();
                quote = 1;
            }
            break;
 
        case LFT_CREDENTIALS:
#if USE_AUTH
            if (al->request && al->request->auth_user_request)
                out = strOrNull(al->request->auth_user_request->credentialsStr());
#endif
            break;
 
        case LFT_PERCENT:
            out = "%";
            break;
 
        case LFT_EXT_ACL_NAME:
            if (!al->lastAclName.isEmpty())
                out = al->lastAclName.c_str();
            break;
 
        case LFT_EXT_ACL_DATA:
            if (!al->lastAclData.isEmpty())
                out = al->lastAclData.c_str();
            break;
 
        case LFT_MASTER_XACTION:
            if (al->request) {
                doUint64 = true;
                outUint64 = static_cast<uint64_t>(al->request->masterXaction->id.value);
                break;
            }
        }
 
        if (dooff) {
            sb.appendf("%0*" PRId64, fmt->zero && fmt->widthMin >= 0 ? fmt->widthMin : 0, outoff);
            out = sb.c_str();
 
        } else if (doint) {
            sb.appendf("%0*ld", fmt->zero && fmt->widthMin >= 0 ? fmt->widthMin : 0, outint);
            out = sb.c_str();
        } else if (doUint64) {
            sb.appendf("%0*" PRIu64, fmt->zero && fmt->widthMin >= 0 ? fmt->widthMin : 0, outUint64);
            out = sb.c_str();
        } else if (doMsec) {
            if (fmt->widthMax < 0) {
                sb.appendf("%0*ld", fmt->zero && fmt->widthMin >= 0 ? fmt->widthMin : 0, tvToMsec(outtv));
            } else {
                int precision = fmt->widthMax;
                sb.appendf("%0*" PRId64 ".%0*" PRId64 "", fmt->zero && (fmt->widthMin - precision - 1 >= 0) ? fmt->widthMin - precision - 1 : 0, static_cast<int64_t>(outtv.tv_sec * 1000 + outtv.tv_usec / 1000), precision, static_cast<int64_t>((outtv.tv_usec % 1000 )* (1000 / fmt->divisor)));
            }
            out = sb.c_str();
        } else if (doSec) {
            int precision = fmt->widthMax >=0 ? fmt->widthMax :3;
            sb.appendf("%0*" PRId64 ".%0*d", fmt->zero && (fmt->widthMin - precision - 1 >= 0) ? fmt->widthMin - precision - 1 : 0, static_cast<int64_t>(outtv.tv_sec), precision, (int)(outtv.tv_usec / fmt->divisor));
            out = sb.c_str();
        }
 
        if (out && *out) {
            if (quote || fmt->quote != LOG_QUOTE_NONE) {
                // Do not write to the tmp buffer because it may contain the to-be-quoted value.
                static char quotedOut[2 * sizeof(tmp)];
                static_assert(sizeof(quotedOut) > 0, "quotedOut has zero length");
                quotedOut[0] = '\0';
 
                char *newout = nullptr;
                int newfree = 0;
 
                switch (fmt->quote) {
 
                case LOG_QUOTE_NONE:
                    newout = rfc1738_escape_unescaped(out);
                    break;
 
                case LOG_QUOTE_QUOTES: {
                    size_t out_len = static_cast<size_t>(strlen(out)) * 2 + 1;
                    if (out_len >= sizeof(tmp)) {
                        newout = (char *)xmalloc(out_len);
                        newfree = 1;
                    } else
                        newout = quotedOut;
                    log_quoted_string(out, newout);
                }
                break;
 
                case LOG_QUOTE_MIMEBLOB:
                    newout = QuoteMimeBlob(out);
                    newfree = 1;
                    break;
 
                case LOG_QUOTE_URL:
                    newout = rfc1738_escape(out);
                    break;
 
                case LOG_QUOTE_SHELL: {
                    MemBuf mbq;
                    mbq.init();
                    strwordquote(&mbq, out);
                    newout = mbq.content();
                    mbq.stolen = 1;
                    newfree = 1;
                }
                break;
 
                case LOG_QUOTE_RAW:
                    break;
                }
 
                if (newout) {
                    if (dofree)
                        safe_free(out);
 
                    out = newout;
 
                    dofree = newfree;
                }
            }
 
            // enforce width limits if configured
            const bool haveMaxWidth = fmt->widthMax >=0 && !doint && !dooff && !doMsec && !doSec && !doUint64;
            if (haveMaxWidth || fmt->widthMin) {
                const int minWidth = fmt->widthMin >= 0 ?
                                     fmt->widthMin :0;
                const int maxWidth = haveMaxWidth ?
                                     fmt->widthMax : strlen(out);
 
                if (fmt->left)
                    mb.appendf("%-*.*s", minWidth, maxWidth, out);
                else
                    mb.appendf("%*.*s", minWidth, maxWidth, out);
            } else
                mb.append(out, strlen(out));
        } else {
            mb.append("-", 1);
        }
 
        if (fmt->space)
            mb.append(" ", 1);
 
        sb.clear();
 
        if (dofree)
            safe_free(out);
    }
}