]> git.ipfire.org Git - thirdparty/squid.git/blobdiff - src/format/Format.cc
Fix logged request size (%http::>st) and other size-related %codes.
[thirdparty/squid.git] / src / format / Format.cc
index 3102da07e8948da0646b5e788aa5944378445653..f007e982c975eaa7007c609c42c8d30a1017f0c0 100644 (file)
@@ -1,3 +1,11 @@
+/*
+ * Copyright (C) 1996-2016 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 "client_side.h"
 #include "format/Quoting.h"
 #include "format/Token.h"
 #include "fqdncache.h"
+#include "http/Stream.h"
 #include "HttpRequest.h"
 #include "MemBuf.h"
 #include "rfc1738.h"
+#include "security/CertError.h"
+#include "security/NegotiationHistory.h"
 #include "SquidTime.h"
 #include "Store.h"
+#include "tools.h"
 #include "URL.h"
 #if USE_OPENSSL
 #include "ssl/ErrorDetail.h"
+#include "ssl/ServerBump.h"
 #endif
 
 /// Convert a string to NULL pointer if it is ""
 #define strOrNull(s) ((s)==NULL||(s)[0]=='\0'?NULL:(s))
 
+const SBuf Format::Dash("-");
+
 Format::Format::Format(const char *n) :
-        format(NULL),
-        next(NULL)
+    format(NULL),
+    next(NULL)
 {
     name = xstrdup(n);
 }
@@ -79,14 +94,15 @@ Format::Format::parse(const char *def)
 }
 
 void
-Format::Format::dump(StoreEntry * entry, const char *directiveName)
+Format::Format::dump(StoreEntry * entry, const char *directiveName, bool eol) const
 {
     debugs(46, 4, HERE);
 
     // loop rather than recursing to conserve stack space.
-    for (Format *fmt = this; fmt; fmt = fmt->next) {
+    for (const Format *fmt = this; fmt; fmt = fmt->next) {
         debugs(46, 3, HERE << "Dumping format definition for " << fmt->name);
-        storeAppendPrintf(entry, "%s %s ", directiveName, 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)
@@ -97,7 +113,7 @@ Format::Format::dump(StoreEntry * entry, const char *directiveName)
                 ByteCode_t type = t->type;
 
                 switch (type) {
-                    /* special cases */
+                /* special cases */
 
                 case LFT_STRING:
                     break;
@@ -216,6 +232,10 @@ Format::Format::dump(StoreEntry * entry, const char *directiveName)
                     entry->append("'", 1);
                     break;
 
+                case LOG_QUOTE_SHELL:
+                    entry->append("/", 1);
+                    break;
+
                 case LOG_QUOTE_NONE:
                     break;
                 }
@@ -242,7 +262,8 @@ Format::Format::dump(StoreEntry * entry, const char *directiveName)
             }
         }
 
-        entry->append("\n", 1);
+        if (eol)
+            entry->append("\n", 1);
     }
 
 }
@@ -300,13 +321,41 @@ log_quoted_string(const char *str, char *out)
     *p = '\0';
 }
 
+#if USE_OPENSSL
+static char *
+sslErrorName(Security::ErrorCode err, char *buf, size_t size)
+{
+    snprintf(buf, size, "SSL_ERR=%d", err);
+    return buf;
+}
+#endif
+
+static const HttpMsg *
+actualReplyHeader(const AccessLogEntry::Pointer &al)
+{
+    const HttpMsg *msg = al->reply;
+    if (!msg && al->icap.reqMethod == Adaptation::methodReqmod)
+        msg = al->adapted_request;
+    return msg;
+}
+
+static const HttpMsg *
+actualRequestHeader(const AccessLogEntry::Pointer &al)
+{
+    if (al->icap.reqMethod == Adaptation::methodRespmod) {
+        // XXX: for now AccessLogEntry lacks virgin response headers
+        return nullptr;
+    }
+    return al->request;
+}
+
 void
 Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logSequenceNumber) const
 {
     char tmp[1024];
     String sb;
 
-    for (Token *fmt = format; fmt != NULL; fmt = fmt->next) {  /* for each token */
+    for (Token *fmt = format; fmt != NULL; fmt = fmt->next) {   /* for each token */
         const char *out = NULL;
         int quote = 0;
         long int outint = 0;
@@ -314,6 +363,9 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
         int dofree = 0;
         int64_t outoff = 0;
         int dooff = 0;
+        struct timeval outtv = {0, 0};
+        int doMsec = 0;
+        int doSec = 0;
 
         switch (fmt->type) {
 
@@ -358,8 +410,28 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
                     al->request->clientConnectionManager->clientConnection->remoteEui64.encode(tmp, 1024);
                 out = tmp;
             }
-#else
-            out = "-";
+#endif
+            break;
+
+        case LFT_EXT_ACL_CLIENT_EUI48:
+#if USE_SQUID_EUI
+            if (al->request && al->request->clientConnectionManager.valid() &&
+                    al->request->clientConnectionManager->clientConnection != NULL &&
+                    al->request->clientConnectionManager->clientConnection->remote.isIPv4()) {
+                al->request->clientConnectionManager->clientConnection->remoteEui48.encode(tmp, 1024);
+                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 != NULL &&
+                    !al->request->clientConnectionManager->clientConnection->remote.isIPv4()) {
+                al->request->clientConnectionManager->clientConnection->remoteEui64.encode(tmp, 1024);
+                out = tmp;
+            }
 #endif
             break;
 
@@ -384,7 +456,7 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
             // avoid logging a dash if we have reliable info
             const bool interceptedAtKnownPort = al->request ?
                                                 (al->request->flags.interceptTproxy ||
-                                                 al->request->flags.intercepted) && al->cache.port :
+                                                 al->request->flags.intercepted) && al->cache.port != NULL :
                                                 false;
             if (interceptedAtKnownPort) {
                 const bool portAddressConfigured = !al->cache.port->s.isAnyAddr();
@@ -416,9 +488,12 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
             break;
 
         case LFT_LOCAL_LISTENING_PORT:
-            if (al->cache.port) {
+            if (al->cache.port != NULL) {
                 outint = al->cache.port->s.port();
                 doint = 1;
+            } else if (al->request) {
+                outint = al->request->my_addr.port();
+                doint = 1;
             }
             break;
 
@@ -475,7 +550,7 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
             const char *spec;
 
             struct tm *t;
-            spec = fmt->data.timespec;
+            spec = fmt->data.string;
 
             if (fmt->type == LFT_TIME_LOCALTIME) {
                 if (!spec)
@@ -495,47 +570,50 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
 
         break;
 
-        case LFT_TIME_START: {
-            int precision = fmt->widthMax >=0 ? fmt->widthMax :3;
-            snprintf(tmp, sizeof(tmp), "%0*" PRId64 ".%0*d", fmt->zero && (fmt->widthMin - precision - 1 >= 0) ? fmt->widthMin - precision - 1 : 0, static_cast<int64_t>(al->cache.start_time.tv_sec), precision, (int)(al->cache.start_time.tv_usec / fmt->divisor));
-            out = tmp;
-        }
-        break;
+        case LFT_TIME_START:
+            outtv = al->cache.start_time;
+            doSec = 1;
+            break;
 
         case LFT_TIME_TO_HANDLE_REQUEST:
-            outint = al->cache.msec;
-            doint = 1;
+            outtv = al->cache.trTime;
+            doMsec = 1;
             break;
 
         case LFT_PEER_RESPONSE_TIME:
-            if (al->hier.peer_response_time < 0) {
+            if (al->hier.peer_response_time.tv_sec ==  -1) {
                 out = "-";
             } else {
-                outoff = al->hier.peer_response_time;
-                dooff = 1;
+                outtv = al->hier.peer_response_time;
+                doMsec = 1;
             }
             break;
 
-        case LFT_TOTAL_SERVER_SIDE_RESPONSE_TIME:
-            if (al->hier.total_response_time < 0) {
+        case LFT_TOTAL_SERVER_SIDE_RESPONSE_TIME: {
+            timeval total_response_time;
+            al->hier.totalResponseTime(total_response_time);
+            if (total_response_time.tv_sec == -1) {
                 out = "-";
             } else {
-                outoff = al->hier.total_response_time;
-                dooff = 1;
+                outtv = total_response_time;
+                doMsec = 1;
             }
-            break;
+        }
+        break;
 
         case LFT_DNS_WAIT_TIME:
             if (al->request && al->request->dnsWait >= 0) {
-                outint = al->request->dnsWait;
-                doint = 1;
+                // TODO: microsecond precision for dns wait time.
+                // Convert miliseconds 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 (al->request)
-                sb = al->request->header.getByName(fmt->data.header.header);
+            if (const HttpMsg *msg = actualRequestHeader(al))
+                sb = msg->header.getByName(fmt->data.header.header);
 
             out = sb.termedBuf();
 
@@ -554,15 +632,15 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
 
             break;
 
-        case LFT_REPLY_HEADER:
-            if (al->reply)
-                sb = al->reply->header.getByName(fmt->data.header.header);
+        case LFT_REPLY_HEADER: {
+            if (const HttpMsg *msg = actualReplyHeader(al))
+                sb = msg->header.getByName(fmt->data.header.header);
 
             out = sb.termedBuf();
 
             quote = 1;
-
-            break;
+        }
+        break;
 
 #if USE_ADAPTATION
         case LFT_ADAPTATION_SUM_XACT_TIMES:
@@ -720,13 +798,13 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
             break;
 
         case LFT_ICAP_TR_RESPONSE_TIME:
-            outint = al->icap.trTime;
-            doint = 1;
+            outtv = al->icap.trTime;
+            doMsec = 1;
             break;
 
         case LFT_ICAP_IO_TIME:
-            outint = al->icap.ioTime;
-            doint = 1;
+            outtv = al->icap.ioTime;
+            doMsec = 1;
             break;
 
         case LFT_ICAP_STATUS_CODE:
@@ -739,13 +817,13 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
             break;
 
         case LFT_ICAP_TOTAL_TIME:
-            outint = al->icap.processingTime;
-            doint = 1;
+            outtv = al->icap.processingTime;
+            doMsec = 1;
             break;
 #endif
         case LFT_REQUEST_HEADER_ELEM:
-            if (al->request)
-                sb = al->request->header.getByNameListMember(fmt->data.header.header, fmt->data.header.element, fmt->data.header.separator);
+            if (const HttpMsg *msg = actualRequestHeader(al))
+                sb = msg->header.getByNameListMember(fmt->data.header.header, fmt->data.header.element, fmt->data.header.separator);
 
             out = sb.termedBuf();
 
@@ -763,18 +841,24 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
 
             break;
 
-        case LFT_REPLY_HEADER_ELEM:
-            if (al->reply)
-                sb = al->reply->header.getByNameListMember(fmt->data.header.header, fmt->data.header.element, fmt->data.header.separator);
+        case LFT_REPLY_HEADER_ELEM: {
+            if (const HttpMsg *msg = actualReplyHeader(al))
+                sb = msg->header.getByNameListMember(fmt->data.header.header, fmt->data.header.element, fmt->data.header.separator);
 
             out = sb.termedBuf();
 
             quote = 1;
-
-            break;
+        }
+        break;
 
         case LFT_REQUEST_ALL_HEADERS:
-            out = al->headers.request;
+            if (al->icap.reqMethod == Adaptation::methodRespmod) {
+                // XXX: since AccessLogEntry::Headers lacks virgin response
+                // headers, do nothing for now
+                out = nullptr;
+            } else {
+                out = al->headers.request;
+            }
 
             quote = 1;
 
@@ -789,6 +873,8 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
 
         case LFT_REPLY_ALL_HEADERS:
             out = al->headers.reply;
+            if (!out && al->icap.reqMethod == Adaptation::methodReqmod)
+                out = al->headers.adapted_request;
 
             quote = 1;
 
@@ -799,8 +885,14 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
             if (al->request && al->request->auth_user_request != NULL)
                 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->cache.extuser);
+
 #if USE_OPENSSL
             if (!out)
                 out = strOrNull(al->cache.ssluser);
@@ -821,14 +913,20 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
             break;
 
         case LFT_USER_EXTERNAL:
-            out = strOrNull(al->cache.extuser);
+            if (al->request && al->request->extacl_user.size()) {
+                if (const char *t = al->request->extacl_user.termedBuf())
+                    out = t;
+            }
+
+            if (!out)
+                out = strOrNull(al->cache.extuser);
             break;
 
-            /* case LFT_USER_REALM: */
-            /* case LFT_USER_SCHEME: */
+        /* 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 ommited
+        // the fmt->type can not be LFT_HTTP_SENT_STATUS_CODE_OLD_30
+        // but compiler complains if ommited
         case LFT_HTTP_SENT_STATUS_CODE_OLD_30:
         case LFT_HTTP_SENT_STATUS_CODE:
             outint = al->http.code;
@@ -845,11 +943,11 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
                 doint = 1;
             }
             break;
-            /* case LFT_HTTP_STATUS:
-             *           out = statusline->text;
-             *     quote = 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;
@@ -861,14 +959,7 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
             break;
 
         case LFT_SQUID_STATUS:
-            if (al->http.timedout || al->http.aborted) {
-                snprintf(tmp, sizeof(tmp), "%s%s", LogTags_str[al->cache.code],
-                         al->http.statusSfx());
-                out = tmp;
-            } else {
-                out = LogTags_str[al->cache.code];
-            }
-
+            out = al->cache.code.c_str();
             break;
 
         case LFT_SQUID_ERROR:
@@ -879,15 +970,12 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
         case LFT_SQUID_ERROR_DETAIL:
 #if USE_OPENSSL
             if (al->request && al->request->errType == ERR_SECURE_CONNECT_FAIL) {
-                if (! (out = Ssl::GetErrorName(al->request->errDetail))) {
-                    snprintf(tmp, sizeof(tmp), "SSL_ERR=%d", al->request->errDetail);
-                    out = tmp;
-                }
+                if (! (out = Ssl::GetErrorName(al->request->errDetail)))
+                    out = sslErrorName(al->request->errDetail, tmp, sizeof(tmp));
             } else
 #endif
                 if (al->request && al->request->errDetail != ERR_DETAIL_NONE) {
-                    if (al->request->errDetail > ERR_DETAIL_START  &&
-                            al->request->errDetail < ERR_DETAIL_MAX)
+                    if (al->request->errDetail > ERR_DETAIL_START && al->request->errDetail < ERR_DETAIL_MAX)
                         out = errorDetailName(al->request->errDetail);
                     else {
                         if (al->request->errDetail >= ERR_DETAIL_EXCEPTION_START)
@@ -926,22 +1014,41 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
         case LFT_CLIENT_REQ_URI:
             // original client URI
             if (al->request) {
-                out = urlCanonical(al->request);
+                const SBuf &s = al->request->effectiveRequestUri();
+                sb.append(s.rawContent(), s.length());
+                out = sb.termedBuf();
+                quote = 1;
+            }
+            break;
+
+        case LFT_CLIENT_REQ_URLSCHEME:
+            if (al->request) {
+                const SBuf s(al->request->url.getScheme().image());
+                sb.append(s.rawContent(), s.length());
+                out = sb.termedBuf();
                 quote = 1;
             }
             break;
 
         case LFT_CLIENT_REQ_URLDOMAIN:
             if (al->request) {
-                out = al->request->GetHost();
+                out = al->request->url.host();
                 quote = 1;
             }
             break;
 
+        case LFT_CLIENT_REQ_URLPORT:
+            if (al->request) {
+                outint = al->request->url.port();
+                doint = 1;
+            }
+            break;
+
         case LFT_REQUEST_URLPATH_OLD_31:
         case LFT_CLIENT_REQ_URLPATH:
             if (al->request) {
-                out = al->request->urlpath.termedBuf();
+                SBuf s = al->request->url.path();
+                out = s.c_str();
                 quote = 1;
             }
             break;
@@ -954,20 +1061,22 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
             break;
 
         case LFT_REQUEST_METHOD:
-            if (al->_private.method_str) // ICP, HTCP method code
-                out = al->_private.method_str;
-            else {
-                const SBuf &s = al->http.method.image();
+        {
+            const SBuf s(al->getLogMethod());
+            sb.append(s.rawContent(), s.length());
+            out = sb.termedBuf();
+            quote = 1;
+        }
+        break;
+
+        case LFT_REQUEST_URI:
+            if (!al->url.isEmpty()) {
+                const SBuf &s = al->url;
                 sb.append(s.rawContent(), s.length());
                 out = sb.termedBuf();
-                quote = 1;
             }
             break;
 
-        case LFT_REQUEST_URI:
-            out = al->url;
-            break;
-
         case LFT_REQUEST_VERSION_OLD_2X:
         case LFT_REQUEST_VERSION:
             snprintf(tmp, sizeof(tmp), "%d.%d", (int) al->http.version.major, (int) al->http.version.minor);
@@ -986,14 +1095,40 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
         case LFT_SERVER_REQ_URI:
             // adapted request URI sent to server/peer
             if (al->adapted_request) {
-                out = urlCanonical(al->adapted_request);
+                const SBuf &s = al->adapted_request->effectiveRequestUri();
+                sb.append(s.rawContent(), s.length());
+                out = sb.termedBuf();
+                quote = 1;
+            }
+            break;
+
+        case LFT_SERVER_REQ_URLSCHEME:
+            if (al->adapted_request) {
+                const SBuf s(al->adapted_request->url.getScheme().image());
+                sb.append(s.rawContent(), s.length());
+                out = sb.termedBuf();
                 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) {
+                outint = al->adapted_request->url.port();
+                doint = 1;
+            }
+            break;
+
         case LFT_SERVER_REQ_URLPATH:
             if (al->adapted_request) {
-                out = al->adapted_request->urlpath.termedBuf();
+                SBuf s = al->adapted_request->url.path();
+                out = s.c_str();
                 quote = 1;
             }
             break;
@@ -1017,8 +1152,8 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
             dooff =1;
             break;
 
-            /*case LFT_REQUEST_SIZE_BODY: */
-            /*case LFT_REQUEST_SIZE_BODY_NO_TE: */
+        /*case LFT_REQUEST_SIZE_BODY: */
+        /*case LFT_REQUEST_SIZE_BODY_NO_TE: */
 
         case LFT_ADAPTED_REPLY_SIZE_TOTAL:
             outoff = al->http.clientReplySz.messageTotal();
@@ -1044,14 +1179,14 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
             doint = 1;
             break;
 
-            /*case LFT_REPLY_SIZE_BODY: */
-            /*case LFT_REPLY_SIZE_BODY_NO_TE: */
+        /*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_SERVER_IO_SIZE_TOTAL: */
 
         case LFT_TAG:
             if (al->request)
@@ -1079,8 +1214,48 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
             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;
         }
+        break;
+
+        case LFT_EXT_ACL_USER_CERT_RAW:
+            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 = sslGetUserCertificatePEM(ssl);
+                }
+            }
+            break;
+
+        case LFT_EXT_ACL_USER_CERTCHAIN_RAW:
+            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 = sslGetUserCertificatePEM(ssl);
+                }
+            }
+            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, format->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, format->data.header.header);
+                }
+            }
+            break;
 
         case LFT_SSL_USER_CERT_SUBJECT:
             if (X509 *cert = al->cache.sslClientCert.get()) {
@@ -1099,8 +1274,96 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
                 }
             }
             break;
+
+        case LFT_SSL_CLIENT_SNI:
+            if (al->request && al->request->clientConnectionManager.valid()) {
+                if (Ssl::ServerBump * srvBump = al->request->clientConnectionManager->serverBump()) {
+                    if (!srvBump->clientSni.isEmpty())
+                        out = srvBump->clientSni.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 != nullptr; sslError = sslError->next) {
+                        if (sb.size())
+                            sb.append(separator);
+                        if (const char *errorName = Ssl::GetErrorName(sslError->element.code))
+                            sb.append(errorName);
+                        else
+                            sb.append(sslErrorName(sslError->element.code, tmp, sizeof(tmp)));
+                        if (sslError->element.depth >= 0) {
+                            snprintf(tmp, sizeof(tmp), "@depth=%d", sslError->element.depth);
+                            sb.append(tmp);
+                        }
+                    }
+                    if (sb.size())
+                        out = sb.termedBuf();
+                }
+            }
+            break;
+
+        case LFT_SSL_SERVER_CERT_ISSUER:
+        case LFT_SSL_SERVER_CERT_SUBJECT:
+            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
+                            out = Ssl::GetX509CAAttribute(serverCert, "DN");
+                    }
+                }
+            }
+            break;
+
+        case LFT_TLS_CLIENT_NEGOTIATED_VERSION:
+            if (al->tcpClient != nullptr && al->tcpClient->hasTlsNegotiations())
+                out = al->tcpClient->hasTlsNegotiations()->negotiatedVersion();
+            break;
+
+        case LFT_TLS_SERVER_NEGOTIATED_VERSION:
+            if (al->hier.tcpServer != nullptr && al->hier.tcpServer->hasTlsNegotiations())
+                out = al->hier.tcpServer->hasTlsNegotiations()->negotiatedVersion();
+            break;
+
+        case LFT_TLS_CLIENT_RECEIVED_HELLO_VERSION:
+            if (al->tcpClient != nullptr && al->tcpClient->hasTlsNegotiations())
+                out = al->tcpClient->hasTlsNegotiations()->helloVersion();
+            break;
+
+        case LFT_TLS_SERVER_RECEIVED_HELLO_VERSION:
+            if (al->hier.tcpServer != nullptr && al->hier.tcpServer->hasTlsNegotiations())
+                out = al->hier.tcpServer->hasTlsNegotiations()->helloVersion();
+            break;
+
+        case LFT_TLS_CLIENT_SUPPORTED_VERSION:
+            if (al->tcpClient != nullptr && al->tcpClient->hasTlsNegotiations())
+                out = al->tcpClient->hasTlsNegotiations()->supportedVersion();
+            break;
+
+        case LFT_TLS_SERVER_SUPPORTED_VERSION:
+            if (al->hier.tcpServer != nullptr && al->hier.tcpServer->hasTlsNegotiations())
+                out = al->hier.tcpServer->hasTlsNegotiations()->supportedVersion();
+            break;
+
+        case LFT_TLS_CLIENT_NEGOTIATED_CIPHER:
+            if (al->tcpClient != nullptr && al->tcpClient->hasTlsNegotiations())
+                out = al->tcpClient->hasTlsNegotiations()->cipherName();
+            break;
+
+        case LFT_TLS_SERVER_NEGOTIATED_CIPHER:
+            if (al->hier.tcpServer != nullptr && 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.
+
         case LFT_NOTE:
             tmp[0] = fmt->data.header.separator;
             tmp[1] = '\0';
@@ -1148,7 +1411,15 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
 
         case LFT_PERCENT:
             out = "%";
+            break;
 
+        case LFT_EXT_ACL_NAME:
+            out = al->lastAclName;
+            break;
+
+        case LFT_EXT_ACL_DATA:
+            if (!al->lastAclData.isEmpty())
+                out = al->lastAclData.c_str();
             break;
         }
 
@@ -1159,6 +1430,18 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
         } else if (doint) {
             snprintf(tmp, sizeof(tmp), "%0*ld", fmt->zero && fmt->widthMin >= 0 ? fmt->widthMin : 0, outint);
             out = tmp;
+        } else if (doMsec) {
+            if (fmt->widthMax < 0) {
+                snprintf(tmp, sizeof(tmp), "%0*ld", fmt->widthMin , tvToMsec(outtv));
+            } else {
+                int precision = fmt->widthMax;
+                snprintf(tmp, sizeof(tmp), "%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 = tmp;
+        } else if (doSec) {
+            int precision = fmt->widthMax >=0 ? fmt->widthMax :3;
+            snprintf(tmp, sizeof(tmp), "%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 = tmp;
         }
 
         if (out && *out) {
@@ -1192,6 +1475,16 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
                     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;
                 }
@@ -1207,7 +1500,7 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
             }
 
             // enforce width limits if configured
-            const bool haveMaxWidth = fmt->widthMax >=0 && !doint && !dooff && !fmt->divisor;
+            const bool haveMaxWidth = fmt->widthMax >=0 && !doint && !dooff && !doMsec && !doSec;
             if (haveMaxWidth || fmt->widthMin) {
                 const int minWidth = fmt->widthMin >= 0 ?
                                      fmt->widthMin :0;
@@ -1215,9 +1508,9 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
                                      fmt->widthMax : strlen(out);
 
                 if (fmt->left)
-                    mb.Printf("%-*.*s", minWidth, maxWidth, out);
+                    mb.appendf("%-*.*s", minWidth, maxWidth, out);
                 else
-                    mb.Printf("%*.*s", minWidth, maxWidth, out);
+                    mb.appendf("%*.*s", minWidth, maxWidth, out);
             } else
                 mb.append(out, strlen(out));
         } else {
@@ -1233,3 +1526,4 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
             safe_free(out);
     }
 }
+