src/format/Format.cc

   1 /*
   2  * Copyright (C) 1996-2015 The Squid Software Foundation and contributors
   3  *
   4  * Squid software is distributed under GPLv2+ license and includes
   5  * contributions from numerous individuals and organizations.
   6  * Please see the COPYING and CONTRIBUTORS files for details.
   7  */
   8
   9 #include "squid.h"
  10 #include "AccessLogEntry.h"
  11 #include "client_side.h"
  12 #include "comm/Connection.h"
  13 #include "err_detail_type.h"
  14 #include "errorpage.h"
  15 #include "fde.h"
  16 #include "format/Format.h"
  17 #include "format/Quoting.h"
  18 #include "format/Token.h"
  19 #include "fqdncache.h"
  20 #include "HttpRequest.h"
  21 #include "MemBuf.h"
  22 #include "rfc1738.h"
  23 #include "SquidTime.h"
  24 #include "Store.h"
  25 #include "URL.h"
  26 #if USE_OPENSSL
  27 #include "ssl/ErrorDetail.h"
  28 #include "ssl/ServerBump.h"
  29 #endif
  30
  31 /// Convert a string to NULL pointer if it is ""
  32 #define strOrNull(s) ((s)==NULL||(s)[0]=='\0'?NULL:(s))
  33
  34 Format::Format::Format(const char *n) :
  35     format(NULL),
  36     next(NULL)
  37 {
  38     name = xstrdup(n);
  39 }
  40
  41 Format::Format::~Format()
  42 {
  43     // erase the list without consuming stack space
  44     while (next) {
  45         // unlink the next entry for deletion
  46         Format *temp = next;
  47         next = temp->next;
  48         temp->next = NULL;
  49         delete temp;
  50     }
  51
  52     // remove locals
  53     xfree(name);
  54     delete format;
  55 }
  56
  57 bool
  58 Format::Format::parse(const char *def)
  59 {
  60     const char *cur, *eos;
  61     Token *new_lt, *last_lt;
  62     enum Quoting quote = LOG_QUOTE_NONE;
  63
  64     debugs(46, 2, HERE << "got definition '" << def << "'");
  65
  66     if (format) {
  67         debugs(46, DBG_IMPORTANT, "WARNING: existing format for '" << name << " " << def << "'");
  68         return false;
  69     }
  70
  71     /* very inefficent parser, but who cares, this needs to be simple */
  72     /* First off, let's tokenize, we'll optimize in a second pass.
  73      * A token can either be a %-prefixed sequence (usually a dynamic
  74      * token but it can be an escaped sequence), or a string. */
  75     cur = def;
  76     eos = def + strlen(def);
  77     format = new_lt = last_lt = new Token;
  78     cur += new_lt->parse(cur, &quote);
  79
  80     while (cur < eos) {
  81         new_lt = new Token;
  82         last_lt->next = new_lt;
  83         last_lt = new_lt;
  84         cur += new_lt->parse(cur, &quote);
  85     }
  86
  87     return true;
  88 }
  89
  90 void
  91 Format::Format::dump(StoreEntry * entry, const char *directiveName)
  92 {
  93     debugs(46, 4, HERE);
  94
  95     // loop rather than recursing to conserve stack space.
  96     for (Format *fmt = this; fmt; fmt = fmt->next) {
  97         debugs(46, 3, HERE << "Dumping format definition for " << fmt->name);
  98         storeAppendPrintf(entry, "%s %s ", directiveName, fmt->name);
  99
 100         for (Token *t = fmt->format; t; t = t->next) {
 101             if (t->type == LFT_STRING)
 102                 storeAppendPrintf(entry, "%s", t->data.string);
 103             else {
 104                 char argbuf[256];
 105                 char *arg = NULL;
 106                 ByteCode_t type = t->type;
 107
 108                 switch (type) {
 109                 /* special cases */
 110
 111                 case LFT_STRING:
 112                     break;
 113 #if USE_ADAPTATION
 114                 case LFT_ADAPTATION_LAST_HEADER_ELEM:
 115 #endif
 116 #if ICAP_CLIENT
 117                 case LFT_ICAP_REQ_HEADER_ELEM:
 118                 case LFT_ICAP_REP_HEADER_ELEM:
 119 #endif
 120                 case LFT_REQUEST_HEADER_ELEM:
 121                 case LFT_ADAPTED_REQUEST_HEADER_ELEM:
 122                 case LFT_REPLY_HEADER_ELEM:
 123
 124                     if (t->data.header.separator != ',')
 125                         snprintf(argbuf, sizeof(argbuf), "%s:%c%s", t->data.header.header, t->data.header.separator, t->data.header.element);
 126                     else
 127                         snprintf(argbuf, sizeof(argbuf), "%s:%s", t->data.header.header, t->data.header.element);
 128
 129                     arg = argbuf;
 130
 131                     switch (type) {
 132                     case LFT_REQUEST_HEADER_ELEM:
 133                         type = LFT_REQUEST_HEADER_ELEM; // XXX: remove _ELEM?
 134                         break;
 135                     case LFT_ADAPTED_REQUEST_HEADER_ELEM:
 136                         type = LFT_ADAPTED_REQUEST_HEADER_ELEM; // XXX: remove _ELEM?
 137                         break;
 138                     case LFT_REPLY_HEADER_ELEM:
 139                         type = LFT_REPLY_HEADER_ELEM; // XXX: remove _ELEM?
 140                         break;
 141 #if USE_ADAPTATION
 142                     case LFT_ADAPTATION_LAST_HEADER_ELEM:
 143                         type = LFT_ADAPTATION_LAST_HEADER;
 144                         break;
 145 #endif
 146 #if ICAP_CLIENT
 147                     case LFT_ICAP_REQ_HEADER_ELEM:
 148                         type = LFT_ICAP_REQ_HEADER;
 149                         break;
 150                     case LFT_ICAP_REP_HEADER_ELEM:
 151                         type = LFT_ICAP_REP_HEADER;
 152                         break;
 153 #endif
 154                     default:
 155                         break;
 156                     }
 157
 158                     break;
 159
 160                 case LFT_REQUEST_ALL_HEADERS:
 161                 case LFT_ADAPTED_REQUEST_ALL_HEADERS:
 162                 case LFT_REPLY_ALL_HEADERS:
 163
 164 #if USE_ADAPTATION
 165                 case LFT_ADAPTATION_LAST_ALL_HEADERS:
 166 #endif
 167 #if ICAP_CLIENT
 168                 case LFT_ICAP_REQ_ALL_HEADERS:
 169                 case LFT_ICAP_REP_ALL_HEADERS:
 170 #endif
 171
 172                     switch (type) {
 173                     case LFT_REQUEST_ALL_HEADERS:
 174                         type = LFT_REQUEST_HEADER;
 175                         break;
 176                     case LFT_ADAPTED_REQUEST_ALL_HEADERS:
 177                         type = LFT_ADAPTED_REQUEST_HEADER;
 178                         break;
 179                     case LFT_REPLY_ALL_HEADERS:
 180                         type = LFT_REPLY_HEADER;
 181                         break;
 182 #if USE_ADAPTATION
 183                     case LFT_ADAPTATION_LAST_ALL_HEADERS:
 184                         type = LFT_ADAPTATION_LAST_HEADER;
 185                         break;
 186 #endif
 187 #if ICAP_CLIENT
 188                     case LFT_ICAP_REQ_ALL_HEADERS:
 189                         type = LFT_ICAP_REQ_HEADER;
 190                         break;
 191                     case LFT_ICAP_REP_ALL_HEADERS:
 192                         type = LFT_ICAP_REP_HEADER;
 193                         break;
 194 #endif
 195                     default:
 196                         break;
 197                     }
 198
 199                     break;
 200
 201                 default:
 202                     if (t->data.string)
 203                         arg = t->data.string;
 204
 205                     break;
 206                 }
 207
 208                 entry->append("%", 1);
 209
 210                 switch (t->quote) {
 211
 212                 case LOG_QUOTE_QUOTES:
 213                     entry->append("\"", 1);
 214                     break;
 215
 216                 case LOG_QUOTE_MIMEBLOB:
 217                     entry->append("[", 1);
 218                     break;
 219
 220                 case LOG_QUOTE_URL:
 221                     entry->append("#", 1);
 222                     break;
 223
 224                 case LOG_QUOTE_RAW:
 225                     entry->append("'", 1);
 226                     break;
 227
 228                 case LOG_QUOTE_NONE:
 229                     break;
 230                 }
 231
 232                 if (t->left)
 233                     entry->append("-", 1);
 234
 235                 if (t->zero)
 236                     entry->append("0", 1);
 237
 238                 if (t->widthMin >= 0)
 239                     storeAppendPrintf(entry, "%d", t->widthMin);
 240
 241                 if (t->widthMax >= 0)
 242                     storeAppendPrintf(entry, ".%d", t->widthMax);
 243
 244                 if (arg)
 245                     storeAppendPrintf(entry, "{%s}", arg);
 246
 247                 storeAppendPrintf(entry, "%s", t->label);
 248
 249                 if (t->space)
 250                     entry->append(" ", 1);
 251             }
 252         }
 253
 254         entry->append("\n", 1);
 255     }
 256
 257 }
 258
 259 static void
 260 log_quoted_string(const char *str, char *out)
 261 {
 262     char *p = out;
 263
 264     while (*str) {
 265         int l = strcspn(str, "\"\\\r\n\t");
 266         memcpy(p, str, l);
 267         str += l;
 268         p += l;
 269
 270         switch (*str) {
 271
 272         case '\0':
 273             break;
 274
 275         case '\r':
 276             *p = '\\';
 277             ++p;
 278             *p = 'r';
 279             ++p;
 280             ++str;
 281             break;
 282
 283         case '\n':
 284             *p = '\\';
 285             ++p;
 286             *p = 'n';
 287             ++p;
 288             ++str;
 289             break;
 290
 291         case '\t':
 292             *p = '\\';
 293             ++p;
 294             *p = 't';
 295             ++p;
 296             ++str;
 297             break;
 298
 299         default:
 300             *p = '\\';
 301             ++p;
 302             *p = *str;
 303             ++p;
 304             ++str;
 305             break;
 306         }
 307     }
 308
 309     *p = '\0';
 310 }
 311
 312 #if USE_OPENSSL
 313 static char *
 314 sslErrorName(Ssl::ssl_error_t err, char *buf, size_t size)
 315 {
 316     snprintf(buf, size, "SSL_ERR=%d", err);
 317     return buf;
 318 }
 319 #endif
 320
 321 void
 322 Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logSequenceNumber) const
 323 {
 324     char tmp[1024];
 325     String sb;
 326
 327     for (Token *fmt = format; fmt != NULL; fmt = fmt->next) {   /* for each token */
 328         const char *out = NULL;
 329         int quote = 0;
 330         long int outint = 0;
 331         int doint = 0;
 332         int dofree = 0;
 333         int64_t outoff = 0;
 334         int dooff = 0;
 335         struct timeval outtv = {0, 0};
 336         int doMsec = 0;
 337         int doSec = 0;
 338
 339         switch (fmt->type) {
 340
 341         case LFT_NONE:
 342             out = "";
 343             break;
 344
 345         case LFT_STRING:
 346             out = fmt->data.string;
 347             break;
 348
 349         case LFT_CLIENT_IP_ADDRESS:
 350             al->getLogClientIp(tmp, sizeof(tmp));
 351             out = tmp;
 352             break;
 353
 354         case LFT_CLIENT_FQDN:
 355             if (al->cache.caddr.isAnyAddr()) // e.g., ICAP OPTIONS lack client
 356                 out = "-";
 357             else
 358                 out = fqdncache_gethostbyaddr(al->cache.caddr, FQDN_LOOKUP_IF_MISS);
 359             if (!out) {
 360                 out = al->cache.caddr.toStr(tmp,1024);
 361             }
 362
 363             break;
 364
 365         case LFT_CLIENT_PORT:
 366             if (al->request) {
 367                 outint = al->request->client_addr.port();
 368                 doint = 1;
 369             }
 370             break;
 371
 372         case LFT_CLIENT_EUI:
 373 #if USE_SQUID_EUI
 374             // TODO make the ACL checklist have a direct link to any TCP details.
 375             if (al->request && al->request->clientConnectionManager.valid() && al->request->clientConnectionManager->clientConnection != NULL) {
 376                 if (al->request->clientConnectionManager->clientConnection->remote.isIPv4())
 377                     al->request->clientConnectionManager->clientConnection->remoteEui48.encode(tmp, 1024);
 378                 else
 379                     al->request->clientConnectionManager->clientConnection->remoteEui64.encode(tmp, 1024);
 380                 out = tmp;
 381             }
 382 #else
 383             out = "-";
 384 #endif
 385             break;
 386
 387         case LFT_SERVER_IP_ADDRESS:
 388             if (al->hier.tcpServer != NULL) {
 389                 out = al->hier.tcpServer->remote.toStr(tmp,sizeof(tmp));
 390             }
 391             break;
 392
 393         case LFT_SERVER_FQDN_OR_PEER_NAME:
 394             out = al->hier.host;
 395             break;
 396
 397         case LFT_SERVER_PORT:
 398             if (al->hier.tcpServer != NULL) {
 399                 outint = al->hier.tcpServer->remote.port();
 400                 doint = 1;
 401             }
 402             break;
 403
 404         case LFT_LOCAL_LISTENING_IP: {
 405             // avoid logging a dash if we have reliable info
 406             const bool interceptedAtKnownPort = al->request ?
 407                                                 (al->request->flags.interceptTproxy ||
 408                                                  al->request->flags.intercepted) && al->cache.port != NULL :
 409                                                 false;
 410             if (interceptedAtKnownPort) {
 411                 const bool portAddressConfigured = !al->cache.port->s.isAnyAddr();
 412                 if (portAddressConfigured)
 413                     out = al->cache.port->s.toStr(tmp, sizeof(tmp));
 414             } else if (al->tcpClient != NULL)
 415                 out = al->tcpClient->local.toStr(tmp, sizeof(tmp));
 416         }
 417         break;
 418
 419         case LFT_CLIENT_LOCAL_IP:
 420             if (al->tcpClient != NULL) {
 421                 out = al->tcpClient->local.toStr(tmp,sizeof(tmp));
 422             }
 423             break;
 424
 425         case LFT_CLIENT_LOCAL_TOS:
 426             if (al->tcpClient != NULL) {
 427                 snprintf(tmp, sizeof(tmp), "0x%x", (uint32_t)al->tcpClient->tos);
 428                 out = tmp;
 429             }
 430             break;
 431
 432         case LFT_CLIENT_LOCAL_NFMARK:
 433             if (al->tcpClient != NULL) {
 434                 snprintf(tmp, sizeof(tmp), "0x%x", al->tcpClient->nfmark);
 435                 out = tmp;
 436             }
 437             break;
 438
 439         case LFT_LOCAL_LISTENING_PORT:
 440             if (al->cache.port != NULL) {
 441                 outint = al->cache.port->s.port();
 442                 doint = 1;
 443             }
 444             break;
 445
 446         case LFT_CLIENT_LOCAL_PORT:
 447             if (al->tcpClient != NULL) {
 448                 outint = al->tcpClient->local.port();
 449                 doint = 1;
 450             }
 451             break;
 452
 453         case LFT_SERVER_LOCAL_IP_OLD_27:
 454         case LFT_SERVER_LOCAL_IP:
 455             if (al->hier.tcpServer != NULL) {
 456                 out = al->hier.tcpServer->local.toStr(tmp,sizeof(tmp));
 457             }
 458             break;
 459
 460         case LFT_SERVER_LOCAL_PORT:
 461             if (al->hier.tcpServer != NULL) {
 462                 outint = al->hier.tcpServer->local.port();
 463                 doint = 1;
 464             }
 465
 466             break;
 467
 468         case LFT_SERVER_LOCAL_TOS:
 469             if (al->hier.tcpServer != NULL) {
 470                 snprintf(tmp, sizeof(tmp), "0x%x", (uint32_t)al->hier.tcpServer->tos);
 471                 out = tmp;
 472             }
 473             break;
 474
 475         case LFT_SERVER_LOCAL_NFMARK:
 476             if (al->hier.tcpServer != NULL) {
 477                 snprintf(tmp, sizeof(tmp), "0x%x", al->hier.tcpServer->nfmark);
 478                 out = tmp;
 479             }
 480             break;
 481
 482         case LFT_TIME_SECONDS_SINCE_EPOCH:
 483             // some platforms store time in 32-bit, some 64-bit...
 484             outoff = static_cast<int64_t>(current_time.tv_sec);
 485             dooff = 1;
 486             break;
 487
 488         case LFT_TIME_SUBSECOND:
 489             outint = current_time.tv_usec / fmt->divisor;
 490             doint = 1;
 491             break;
 492
 493         case LFT_TIME_LOCALTIME:
 494
 495         case LFT_TIME_GMT: {
 496             const char *spec;
 497
 498             struct tm *t;
 499             spec = fmt->data.string;
 500
 501             if (fmt->type == LFT_TIME_LOCALTIME) {
 502                 if (!spec)
 503                     spec = "%d/%b/%Y:%H:%M:%S %z";
 504                 t = localtime(&squid_curtime);
 505             } else {
 506                 if (!spec)
 507                     spec = "%d/%b/%Y:%H:%M:%S";
 508
 509                 t = gmtime(&squid_curtime);
 510             }
 511
 512             strftime(tmp, sizeof(tmp), spec, t);
 513
 514             out = tmp;
 515         }
 516
 517         break;
 518
 519         case LFT_TIME_START:
 520             outtv = al->cache.start_time;
 521             doSec = 1;
 522             break;
 523
 524         case LFT_TIME_TO_HANDLE_REQUEST:
 525             outtv = al->cache.trTime;
 526             doMsec = 1;
 527             break;
 528
 529         case LFT_PEER_RESPONSE_TIME:
 530             if (al->hier.peer_response_time.tv_sec ==  -1) {
 531                 out = "-";
 532             } else {
 533                 outtv = al->hier.peer_response_time;
 534                 doMsec = 1;
 535             }
 536             break;
 537
 538         case LFT_TOTAL_SERVER_SIDE_RESPONSE_TIME: {
 539             timeval total_response_time;
 540             al->hier.totalResponseTime(total_response_time);
 541             if (total_response_time.tv_sec == -1) {
 542                 out = "-";
 543             } else {
 544                 outtv = total_response_time;
 545                 doMsec = 1;
 546             }
 547         }
 548         break;
 549
 550         case LFT_DNS_WAIT_TIME:
 551             if (al->request && al->request->dnsWait >= 0) {
 552                 // TODO: microsecond precision for dns wait time.
 553                 // Convert miliseconds to timeval struct:
 554                 outtv.tv_sec = al->request->dnsWait / 1000;
 555                 outtv.tv_usec = (al->request->dnsWait % 1000) * 1000;
 556                 doMsec = 1;
 557             }
 558             break;
 559
 560         case LFT_REQUEST_HEADER:
 561
 562             if (al->request)
 563                 sb = al->request->header.getByName(fmt->data.header.header);
 564
 565             out = sb.termedBuf();
 566
 567             quote = 1;
 568
 569             break;
 570
 571         case LFT_ADAPTED_REQUEST_HEADER:
 572
 573             if (al->adapted_request)
 574                 sb = al->adapted_request->header.getByName(fmt->data.header.header);
 575
 576             out = sb.termedBuf();
 577
 578             quote = 1;
 579
 580             break;
 581
 582         case LFT_REPLY_HEADER:
 583             if (al->reply)
 584                 sb = al->reply->header.getByName(fmt->data.header.header);
 585
 586             out = sb.termedBuf();
 587
 588             quote = 1;
 589
 590             break;
 591
 592 #if USE_ADAPTATION
 593         case LFT_ADAPTATION_SUM_XACT_TIMES:
 594             if (al->request) {
 595                 Adaptation::History::Pointer ah = al->request->adaptHistory();
 596                 if (ah != NULL)
 597                     ah->sumLogString(fmt->data.string, sb);
 598                 out = sb.termedBuf();
 599             }
 600             break;
 601
 602         case LFT_ADAPTATION_ALL_XACT_TIMES:
 603             if (al->request) {
 604                 Adaptation::History::Pointer ah = al->request->adaptHistory();
 605                 if (ah != NULL)
 606                     ah->allLogString(fmt->data.string, sb);
 607                 out = sb.termedBuf();
 608             }
 609             break;
 610
 611         case LFT_ADAPTATION_LAST_HEADER:
 612             if (al->request) {
 613                 const Adaptation::History::Pointer ah = al->request->adaptHistory();
 614                 if (ah != NULL) // XXX: add adapt::<all_h but use lastMeta here
 615                     sb = ah->allMeta.getByName(fmt->data.header.header);
 616             }
 617
 618             // XXX: here and elsewhere: move such code inside the if guard
 619             out = sb.termedBuf();
 620
 621             quote = 1;
 622
 623             break;
 624
 625         case LFT_ADAPTATION_LAST_HEADER_ELEM:
 626             if (al->request) {
 627                 const Adaptation::History::Pointer ah = al->request->adaptHistory();
 628                 if (ah != NULL) // XXX: add adapt::<all_h but use lastMeta here
 629                     sb = ah->allMeta.getByNameListMember(fmt->data.header.header, fmt->data.header.element, fmt->data.header.separator);
 630             }
 631
 632             out = sb.termedBuf();
 633
 634             quote = 1;
 635
 636             break;
 637
 638         case LFT_ADAPTATION_LAST_ALL_HEADERS:
 639             out = al->adapt.last_meta;
 640
 641             quote = 1;
 642
 643             break;
 644 #endif
 645
 646 #if ICAP_CLIENT
 647         case LFT_ICAP_ADDR:
 648             if (!out)
 649                 out = al->icap.hostAddr.toStr(tmp,1024);
 650             break;
 651
 652         case LFT_ICAP_SERV_NAME:
 653             out = al->icap.serviceName.termedBuf();
 654             break;
 655
 656         case LFT_ICAP_REQUEST_URI:
 657             out = al->icap.reqUri.termedBuf();
 658             break;
 659
 660         case LFT_ICAP_REQUEST_METHOD:
 661             out = Adaptation::Icap::ICAP::methodStr(al->icap.reqMethod);
 662             break;
 663
 664         case LFT_ICAP_BYTES_SENT:
 665             outoff = al->icap.bytesSent;
 666             dooff = 1;
 667             break;
 668
 669         case LFT_ICAP_BYTES_READ:
 670             outoff = al->icap.bytesRead;
 671             dooff = 1;
 672             break;
 673
 674         case LFT_ICAP_BODY_BYTES_READ:
 675             if (al->icap.bodyBytesRead >= 0) {
 676                 outoff = al->icap.bodyBytesRead;
 677                 dooff = 1;
 678             }
 679             // else if icap.bodyBytesRead < 0, we do not have any http data,
 680             // so just print a "-" (204 responses etc)
 681             break;
 682
 683         case LFT_ICAP_REQ_HEADER:
 684             if (NULL != al->icap.request) {
 685                 sb = al->icap.request->header.getByName(fmt->data.header.header);
 686                 out = sb.termedBuf();
 687                 quote = 1;
 688             }
 689             break;
 690
 691         case LFT_ICAP_REQ_HEADER_ELEM:
 692             if (al->icap.request)
 693                 sb = al->icap.request->header.getByNameListMember(fmt->data.header.header, fmt->data.header.element, fmt->data.header.separator);
 694
 695             out = sb.termedBuf();
 696
 697             quote = 1;
 698
 699             break;
 700
 701         case LFT_ICAP_REQ_ALL_HEADERS:
 702             if (al->icap.request) {
 703                 HttpHeaderPos pos = HttpHeaderInitPos;
 704                 while (const HttpHeaderEntry *e = al->icap.request->header.getEntry(&pos)) {
 705                     sb.append(e->name);
 706                     sb.append(": ");
 707                     sb.append(e->value);
 708                     sb.append("\r\n");
 709                 }
 710                 out = sb.termedBuf();
 711                 quote = 1;
 712             }
 713             break;
 714
 715         case LFT_ICAP_REP_HEADER:
 716             if (NULL != al->icap.reply) {
 717                 sb = al->icap.reply->header.getByName(fmt->data.header.header);
 718                 out = sb.termedBuf();
 719                 quote = 1;
 720             }
 721             break;
 722
 723         case LFT_ICAP_REP_HEADER_ELEM:
 724             if (NULL != al->icap.reply)
 725                 sb = al->icap.reply->header.getByNameListMember(fmt->data.header.header, fmt->data.header.element, fmt->data.header.separator);
 726
 727             out = sb.termedBuf();
 728
 729             quote = 1;
 730
 731             break;
 732
 733         case LFT_ICAP_REP_ALL_HEADERS:
 734             if (al->icap.reply) {
 735                 HttpHeaderPos pos = HttpHeaderInitPos;
 736                 while (const HttpHeaderEntry *e = al->icap.reply->header.getEntry(&pos)) {
 737                     sb.append(e->name);
 738                     sb.append(": ");
 739                     sb.append(e->value);
 740                     sb.append("\r\n");
 741                 }
 742                 out = sb.termedBuf();
 743                 quote = 1;
 744             }
 745             break;
 746
 747         case LFT_ICAP_TR_RESPONSE_TIME:
 748             outtv = al->icap.trTime;
 749             doMsec = 1;
 750             break;
 751
 752         case LFT_ICAP_IO_TIME:
 753             outtv = al->icap.ioTime;
 754             doMsec = 1;
 755             break;
 756
 757         case LFT_ICAP_STATUS_CODE:
 758             outint = al->icap.resStatus;
 759             doint  = 1;
 760             break;
 761
 762         case LFT_ICAP_OUTCOME:
 763             out = al->icap.outcome;
 764             break;
 765
 766         case LFT_ICAP_TOTAL_TIME:
 767             outtv = al->icap.processingTime;
 768             doMsec = 1;
 769             break;
 770 #endif
 771         case LFT_REQUEST_HEADER_ELEM:
 772             if (al->request)
 773                 sb = al->request->header.getByNameListMember(fmt->data.header.header, fmt->data.header.element, fmt->data.header.separator);
 774
 775             out = sb.termedBuf();
 776
 777             quote = 1;
 778
 779             break;
 780
 781         case LFT_ADAPTED_REQUEST_HEADER_ELEM:
 782             if (al->adapted_request)
 783                 sb = al->adapted_request->header.getByNameListMember(fmt->data.header.header, fmt->data.header.element, fmt->data.header.separator);
 784
 785             out = sb.termedBuf();
 786
 787             quote = 1;
 788
 789             break;
 790
 791         case LFT_REPLY_HEADER_ELEM:
 792             if (al->reply)
 793                 sb = al->reply->header.getByNameListMember(fmt->data.header.header, fmt->data.header.element, fmt->data.header.separator);
 794
 795             out = sb.termedBuf();
 796
 797             quote = 1;
 798
 799             break;
 800
 801         case LFT_REQUEST_ALL_HEADERS:
 802             out = al->headers.request;
 803
 804             quote = 1;
 805
 806             break;
 807
 808         case LFT_ADAPTED_REQUEST_ALL_HEADERS:
 809             out = al->headers.adapted_request;
 810
 811             quote = 1;
 812
 813             break;
 814
 815         case LFT_REPLY_ALL_HEADERS:
 816             out = al->headers.reply;
 817
 818             quote = 1;
 819
 820             break;
 821
 822         case LFT_USER_NAME:
 823 #if USE_AUTH
 824             if (al->request && al->request->auth_user_request != NULL)
 825                 out = strOrNull(al->request->auth_user_request->username());
 826 #endif
 827             if (!out)
 828                 out = strOrNull(al->cache.extuser);
 829 #if USE_OPENSSL
 830             if (!out)
 831                 out = strOrNull(al->cache.ssluser);
 832 #endif
 833             if (!out)
 834                 out = strOrNull(al->cache.rfc931);
 835             break;
 836
 837         case LFT_USER_LOGIN:
 838 #if USE_AUTH
 839             if (al->request && al->request->auth_user_request != NULL)
 840                 out = strOrNull(al->request->auth_user_request->username());
 841 #endif
 842             break;
 843
 844         case LFT_USER_IDENT:
 845             out = strOrNull(al->cache.rfc931);
 846             break;
 847
 848         case LFT_USER_EXTERNAL:
 849             out = strOrNull(al->cache.extuser);
 850             break;
 851
 852         /* case LFT_USER_REALM: */
 853         /* case LFT_USER_SCHEME: */
 854
 855         // the fmt->type can not be LFT_HTTP_SENT_STATUS_CODE_OLD_30
 856         // but compiler complains if ommited
 857         case LFT_HTTP_SENT_STATUS_CODE_OLD_30:
 858         case LFT_HTTP_SENT_STATUS_CODE:
 859             outint = al->http.code;
 860
 861             doint = 1;
 862
 863             break;
 864
 865         case LFT_HTTP_RECEIVED_STATUS_CODE:
 866             if (al->hier.peer_reply_status == Http::scNone) {
 867                 out = "-";
 868             } else {
 869                 outint = al->hier.peer_reply_status;
 870                 doint = 1;
 871             }
 872             break;
 873         /* case LFT_HTTP_STATUS:
 874          *           out = statusline->text;
 875          *     quote = 1;
 876          *     break;
 877          */
 878         case LFT_HTTP_BODY_BYTES_READ:
 879             if (al->hier.bodyBytesRead >= 0) {
 880                 outoff = al->hier.bodyBytesRead;
 881                 dooff = 1;
 882             }
 883             // else if hier.bodyBytesRead < 0 we did not have any data exchange with
 884             // a peer server so just print a "-" (eg requests served from cache,
 885             // or internal error messages).
 886             break;
 887
 888         case LFT_SQUID_STATUS:
 889             out = al->cache.code.c_str();
 890             break;
 891
 892         case LFT_SQUID_ERROR:
 893             if (al->request && al->request->errType != ERR_NONE)
 894                 out = errorPageName(al->request->errType);
 895             break;
 896
 897         case LFT_SQUID_ERROR_DETAIL:
 898 #if USE_OPENSSL
 899             if (al->request && al->request->errType == ERR_SECURE_CONNECT_FAIL) {
 900                 if (! (out = Ssl::GetErrorName(al->request->errDetail)))
 901                     out = sslErrorName(al->request->errDetail, tmp, sizeof(tmp));
 902             } else
 903 #endif
 904                 if (al->request && al->request->errDetail != ERR_DETAIL_NONE) {
 905                     if (al->request->errDetail > ERR_DETAIL_START  &&
 906                             al->request->errDetail < ERR_DETAIL_MAX)
 907                         out = errorDetailName(al->request->errDetail);
 908                     else {
 909                         if (al->request->errDetail >= ERR_DETAIL_EXCEPTION_START)
 910                             snprintf(tmp, sizeof(tmp), "%s=0x%X",
 911                                      errorDetailName(al->request->errDetail), (uint32_t) al->request->errDetail);
 912                         else
 913                             snprintf(tmp, sizeof(tmp), "%s=%d",
 914                                      errorDetailName(al->request->errDetail), al->request->errDetail);
 915                         out = tmp;
 916                     }
 917                 }
 918             break;
 919
 920         case LFT_SQUID_HIERARCHY:
 921             if (al->hier.ping.timedout)
 922                 mb.append("TIMEOUT_", 8);
 923
 924             out = hier_code_str[al->hier.code];
 925
 926             break;
 927
 928         case LFT_MIME_TYPE:
 929             out = al->http.content_type;
 930
 931             break;
 932
 933         case LFT_CLIENT_REQ_METHOD:
 934             if (al->request) {
 935                 const SBuf &s = al->request->method.image();
 936                 sb.append(s.rawContent(), s.length());
 937                 out = sb.termedBuf();
 938                 quote = 1;
 939             }
 940             break;
 941
 942         case LFT_CLIENT_REQ_URI:
 943             // original client URI
 944             if (al->request) {
 945                 const SBuf &s = al->request->effectiveRequestUri();
 946                 sb.append(s.rawContent(), s.length());
 947                 out = sb.termedBuf();
 948                 quote = 1;
 949             }
 950             break;
 951
 952         case LFT_CLIENT_REQ_URLSCHEME:
 953             if (al->request) {
 954                 out = al->request->url.getScheme().c_str();
 955                 quote = 1;
 956             }
 957             break;
 958
 959         case LFT_CLIENT_REQ_URLDOMAIN:
 960             if (al->request) {
 961                 out = al->request->url.host();
 962                 quote = 1;
 963             }
 964             break;
 965
 966         case LFT_CLIENT_REQ_URLPORT:
 967             if (al->request) {
 968                 outint = al->request->url.port();
 969                 doint = 1;
 970             }
 971             break;
 972
 973         case LFT_REQUEST_URLPATH_OLD_31:
 974         case LFT_CLIENT_REQ_URLPATH:
 975             if (al->request) {
 976                 SBuf s = al->request->url.path();
 977                 out = s.c_str();
 978                 quote = 1;
 979             }
 980             break;
 981
 982         case LFT_CLIENT_REQ_VERSION:
 983             if (al->request) {
 984                 snprintf(tmp, sizeof(tmp), "%d.%d", (int) al->request->http_ver.major, (int) al->request->http_ver.minor);
 985                 out = tmp;
 986             }
 987             break;
 988
 989         case LFT_REQUEST_METHOD:
 990             if (al->_private.method_str) // ICP, HTCP method code
 991                 out = al->_private.method_str;
 992             else {
 993                 const SBuf &s = al->http.method.image();
 994                 sb.append(s.rawContent(), s.length());
 995                 out = sb.termedBuf();
 996                 quote = 1;
 997             }
 998             break;
 999
1000         case LFT_REQUEST_URI:
1001             out = al->url;
1002             break;
1003
1004         case LFT_REQUEST_VERSION_OLD_2X:
1005         case LFT_REQUEST_VERSION:
1006             snprintf(tmp, sizeof(tmp), "%d.%d", (int) al->http.version.major, (int) al->http.version.minor);
1007             out = tmp;
1008             break;
1009
1010         case LFT_SERVER_REQ_METHOD:
1011             if (al->adapted_request) {
1012                 const SBuf &s = al->adapted_request->method.image();
1013                 sb.append(s.rawContent(), s.length());
1014                 out = sb.termedBuf();
1015                 quote = 1;
1016             }
1017             break;
1018
1019         case LFT_SERVER_REQ_URI:
1020             // adapted request URI sent to server/peer
1021             if (al->adapted_request) {
1022                 const SBuf &s = al->adapted_request->effectiveRequestUri();
1023                 sb.append(s.rawContent(), s.length());
1024                 out = sb.termedBuf();
1025                 quote = 1;
1026             }
1027             break;
1028
1029         case LFT_SERVER_REQ_URLSCHEME:
1030             if (al->adapted_request) {
1031                 out = al->adapted_request->url.getScheme().c_str();
1032                 quote = 1;
1033             }
1034             break;
1035
1036         case LFT_SERVER_REQ_URLDOMAIN:
1037             if (al->adapted_request) {
1038                 out = al->adapted_request->url.host();
1039                 quote = 1;
1040             }
1041             break;
1042
1043         case LFT_SERVER_REQ_URLPORT:
1044             if (al->adapted_request) {
1045                 outint = al->adapted_request->url.port();
1046                 doint = 1;
1047             }
1048             break;
1049
1050         case LFT_SERVER_REQ_URLPATH:
1051             if (al->adapted_request) {
1052                 SBuf s = al->adapted_request->url.path();
1053                 out = s.c_str();
1054                 quote = 1;
1055             }
1056             break;
1057
1058         case LFT_SERVER_REQ_VERSION:
1059             if (al->adapted_request) {
1060                 snprintf(tmp, sizeof(tmp), "%d.%d",
1061                          (int) al->adapted_request->http_ver.major,
1062                          (int) al->adapted_request->http_ver.minor);
1063                 out = tmp;
1064             }
1065             break;
1066
1067         case LFT_CLIENT_REQUEST_SIZE_TOTAL:
1068             outoff = al->http.clientRequestSz.messageTotal();
1069             dooff = 1;
1070             break;
1071
1072         case LFT_CLIENT_REQUEST_SIZE_HEADERS:
1073             outoff = al->http.clientRequestSz.header;
1074             dooff =1;
1075             break;
1076
1077         /*case LFT_REQUEST_SIZE_BODY: */
1078         /*case LFT_REQUEST_SIZE_BODY_NO_TE: */
1079
1080         case LFT_ADAPTED_REPLY_SIZE_TOTAL:
1081             outoff = al->http.clientReplySz.messageTotal();
1082             dooff = 1;
1083             break;
1084
1085         case LFT_REPLY_HIGHOFFSET:
1086             outoff = al->cache.highOffset;
1087
1088             dooff = 1;
1089
1090             break;
1091
1092         case LFT_REPLY_OBJECTSIZE:
1093             outoff = al->cache.objectSize;
1094
1095             dooff = 1;
1096
1097             break;
1098
1099         case LFT_ADAPTED_REPLY_SIZE_HEADERS:
1100             outint = al->http.clientReplySz.header;
1101             doint = 1;
1102             break;
1103
1104         /*case LFT_REPLY_SIZE_BODY: */
1105         /*case LFT_REPLY_SIZE_BODY_NO_TE: */
1106
1107         case LFT_CLIENT_IO_SIZE_TOTAL:
1108             outint = al->http.clientRequestSz.messageTotal() + al->http.clientReplySz.messageTotal();
1109             doint = 1;
1110             break;
1111         /*case LFT_SERVER_IO_SIZE_TOTAL: */
1112
1113         case LFT_TAG:
1114             if (al->request)
1115                 out = al->request->tag.termedBuf();
1116
1117             quote = 1;
1118
1119             break;
1120
1121         case LFT_EXT_LOG:
1122             if (al->request)
1123                 out = al->request->extacl_log.termedBuf();
1124
1125             quote = 1;
1126
1127             break;
1128
1129         case LFT_SEQUENCE_NUMBER:
1130             outoff = logSequenceNumber;
1131             dooff = 1;
1132             break;
1133
1134 #if USE_OPENSSL
1135         case LFT_SSL_BUMP_MODE: {
1136             const Ssl::BumpMode mode = static_cast<Ssl::BumpMode>(al->ssl.bumpMode);
1137             // for Ssl::bumpEnd, Ssl::bumpMode() returns NULL and we log '-'
1138             out = Ssl::bumpMode(mode);
1139             break;
1140         }
1141
1142         case LFT_SSL_USER_CERT_SUBJECT:
1143             if (X509 *cert = al->cache.sslClientCert.get()) {
1144                 if (X509_NAME *subject = X509_get_subject_name(cert)) {
1145                     X509_NAME_oneline(subject, tmp, sizeof(tmp));
1146                     out = tmp;
1147                 }
1148             }
1149             break;
1150
1151         case LFT_SSL_USER_CERT_ISSUER:
1152             if (X509 *cert = al->cache.sslClientCert.get()) {
1153                 if (X509_NAME *issuer = X509_get_issuer_name(cert)) {
1154                     X509_NAME_oneline(issuer, tmp, sizeof(tmp));
1155                     out = tmp;
1156                 }
1157             }
1158             break;
1159         case LFT_SSL_CLIENT_SNI:
1160             if (al->request && al->request->clientConnectionManager.valid()) {
1161                 if (Ssl::ServerBump * srvBump = al->request->clientConnectionManager->serverBump()) {
1162                     if (!srvBump->clientSni.isEmpty())
1163                         out = srvBump->clientSni.c_str();
1164                 }
1165             }
1166             break;
1167
1168         case LFT_SSL_SERVER_CERT_ERRORS:
1169             if (al->request && al->request->clientConnectionManager.valid()) {
1170                 if (Ssl::ServerBump * srvBump = al->request->clientConnectionManager->serverBump()) {
1171                     const char *separator = fmt->data.string ? fmt->data.string : ":";
1172                     for (Ssl::CertErrors *sslError = srvBump->sslErrors; sslError != NULL;  sslError = sslError->next) {
1173                         if (sb.size())
1174                             sb.append(separator);
1175                         if (const char *errorName = Ssl::GetErrorName(sslError->element.code))
1176                             sb.append(errorName);
1177                         else
1178                             sb.append(sslErrorName(sslError->element.code, tmp, sizeof(tmp)));
1179                     }
1180                     if (sb.size())
1181                         out = sb.termedBuf();
1182                 }
1183             }
1184             break;
1185
1186         case LFT_SSL_SERVER_CERT_ISSUER:
1187         case LFT_SSL_SERVER_CERT_SUBJECT:
1188             // Not implemented
1189             break;
1190 #endif
1191
1192         case LFT_REQUEST_URLGROUP_OLD_2X:
1193             assert(LFT_REQUEST_URLGROUP_OLD_2X == 0); // should never happen.
1194
1195         case LFT_NOTE:
1196             tmp[0] = fmt->data.header.separator;
1197             tmp[1] = '\0';
1198             if (fmt->data.header.header && *fmt->data.header.header) {
1199                 const char *separator = tmp;
1200 #if USE_ADAPTATION
1201                 Adaptation::History::Pointer ah = al->request ? al->request->adaptHistory() : Adaptation::History::Pointer();
1202                 if (ah != NULL && ah->metaHeaders != NULL) {
1203                     if (const char *meta = ah->metaHeaders->find(fmt->data.header.header, separator))
1204                         sb.append(meta);
1205                 }
1206 #endif
1207                 if (al->notes != NULL) {
1208                     if (const char *note = al->notes->find(fmt->data.header.header, separator)) {
1209                         if (sb.size())
1210                             sb.append(separator);
1211                         sb.append(note);
1212                     }
1213                 }
1214                 out = sb.termedBuf();
1215                 quote = 1;
1216             } else {
1217                 // if no argument given use default "\r\n" as notes separator
1218                 const char *separator = fmt->data.string ? tmp : "\r\n";
1219 #if USE_ADAPTATION
1220                 Adaptation::History::Pointer ah = al->request ? al->request->adaptHistory() : Adaptation::History::Pointer();
1221                 if (ah != NULL && ah->metaHeaders != NULL && !ah->metaHeaders->empty())
1222                     sb.append(ah->metaHeaders->toString(separator));
1223 #endif
1224                 if (al->notes != NULL && !al->notes->empty())
1225                     sb.append(al->notes->toString(separator));
1226
1227                 out = sb.termedBuf();
1228                 quote = 1;
1229             }
1230             break;
1231
1232         case LFT_CREDENTIALS:
1233 #if USE_AUTH
1234             if (al->request && al->request->auth_user_request != NULL)
1235                 out = strOrNull(al->request->auth_user_request->credentialsStr());
1236 #endif
1237
1238             break;
1239
1240         case LFT_PERCENT:
1241             out = "%";
1242             break;
1243
1244         // XXX: external_acl_type format tokens which are not output by logformat.
1245         // They are listed here because the switch requires
1246         // every ByteCode_t to be explicitly enumerated.
1247         // But do not output due to lack of access to the values.
1248         case LFT_EXT_ACL_USER_CERT_RAW:
1249         case LFT_EXT_ACL_USER_CERTCHAIN_RAW:
1250         case LFT_EXT_ACL_USER_CERT:
1251         case LFT_EXT_ACL_USER_CA_CERT:
1252         case LFT_EXT_ACL_CLIENT_EUI48:
1253         case LFT_EXT_ACL_CLIENT_EUI64:
1254         case LFT_EXT_ACL_NAME:
1255         case LFT_EXT_ACL_DATA:
1256             break;
1257         }
1258
1259         if (dooff) {
1260             snprintf(tmp, sizeof(tmp), "%0*" PRId64, fmt->zero && fmt->widthMin >= 0 ? fmt->widthMin : 0, outoff);
1261             out = tmp;
1262
1263         } else if (doint) {
1264             snprintf(tmp, sizeof(tmp), "%0*ld", fmt->zero && fmt->widthMin >= 0 ? fmt->widthMin : 0, outint);
1265             out = tmp;
1266         } else if (doMsec) {
1267             if (fmt->widthMax < 0) {
1268                 snprintf(tmp, sizeof(tmp), "%0*ld", fmt->widthMin , tvToMsec(outtv));
1269             } else {
1270                 int precision = fmt->widthMax;
1271                 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)));
1272             }
1273             out = tmp;
1274         } else if (doSec) {
1275             int precision = fmt->widthMax >=0 ? fmt->widthMax :3;
1276             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));
1277             out = tmp;
1278         }
1279
1280         if (out && *out) {
1281             if (quote || fmt->quote != LOG_QUOTE_NONE) {
1282                 char *newout = NULL;
1283                 int newfree = 0;
1284
1285                 switch (fmt->quote) {
1286
1287                 case LOG_QUOTE_NONE:
1288                     newout = rfc1738_escape_unescaped(out);
1289                     break;
1290
1291                 case LOG_QUOTE_QUOTES: {
1292                     size_t out_len = static_cast<size_t>(strlen(out)) * 2 + 1;
1293                     if (out_len >= sizeof(tmp)) {
1294                         newout = (char *)xmalloc(out_len);
1295                         newfree = 1;
1296                     } else
1297                         newout = tmp;
1298                     log_quoted_string(out, newout);
1299                 }
1300                 break;
1301
1302                 case LOG_QUOTE_MIMEBLOB:
1303                     newout = QuoteMimeBlob(out);
1304                     newfree = 1;
1305                     break;
1306
1307                 case LOG_QUOTE_URL:
1308                     newout = rfc1738_escape(out);
1309                     break;
1310
1311                 case LOG_QUOTE_RAW:
1312                     break;
1313                 }
1314
1315                 if (newout) {
1316                     if (dofree)
1317                         safe_free(out);
1318
1319                     out = newout;
1320
1321                     dofree = newfree;
1322                 }
1323             }
1324
1325             // enforce width limits if configured
1326             const bool haveMaxWidth = fmt->widthMax >=0 && !doint && !dooff && !doMsec && !doSec;
1327             if (haveMaxWidth || fmt->widthMin) {
1328                 const int minWidth = fmt->widthMin >= 0 ?
1329                                      fmt->widthMin :0;
1330                 const int maxWidth = haveMaxWidth ?
1331                                      fmt->widthMax : strlen(out);
1332
1333                 if (fmt->left)
1334                     mb.appendf("%-*.*s", minWidth, maxWidth, out);
1335                 else
1336                     mb.appendf("%*.*s", minWidth, maxWidth, out);
1337             } else
1338                 mb.append(out, strlen(out));
1339         } else {
1340             mb.append("-", 1);
1341         }
1342
1343         if (fmt->space)
1344             mb.append(" ", 1);
1345
1346         sb.clean();
1347
1348         if (dofree)
1349             safe_free(out);
1350     }
1351 }
1352