1 /*
2 * Copyright (c) 2014-2016 DeNA Co., Ltd., Kazuho Oku
3 *
4 * Permission is hereby granted, free of charge, to any person obtaining a copy
5 * of this software and associated documentation files (the "Software"), to
6 * deal in the Software without restriction, including without limitation the
7 * rights to use, copy, modify, merge, publish, distribute, sublicense, and/or
8 * sell copies of the Software, and to permit persons to whom the Software is
9 * furnished to do so, subject to the following conditions:
10 *
11 * The above copyright notice and this permission notice shall be included in
12 * all copies or substantial portions of the Software.
13 *
14 * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
15 * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
16 * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
17 * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
18 * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING
19 * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS
20 * IN THE SOFTWARE.
21 */
22 #include <inttypes.h>
23 #include <stdio.h>
24 #include <stdlib.h>
25 #include "h2o.h"
26
27 enum {
28 ELEMENT_TYPE_EMPTY, /* empty element (with suffix only) */
29 ELEMENT_TYPE_LOCAL_ADDR, /* %A */
30 ELEMENT_TYPE_BYTES_SENT, /* %b */
31 ELEMENT_TYPE_PROTOCOL, /* %H */
32 ELEMENT_TYPE_REMOTE_ADDR, /* %h */
33 ELEMENT_TYPE_LOGNAME, /* %l */
34 ELEMENT_TYPE_METHOD, /* %m */
35 ELEMENT_TYPE_LOCAL_PORT, /* %p, %{local}p */
36 ELEMENT_TYPE_REMOTE_PORT, /* %{remote}p */
37 ELEMENT_TYPE_ENV_VAR, /* %{..}e */
38 ELEMENT_TYPE_QUERY, /* %q */
39 ELEMENT_TYPE_REQUEST_LINE, /* %r */
40 ELEMENT_TYPE_STATUS, /* %s */
41 ELEMENT_TYPE_TIMESTAMP, /* %t */
42 ELEMENT_TYPE_TIMESTAMP_STRFTIME, /* %{...}t */
43 ELEMENT_TYPE_TIMESTAMP_SEC_SINCE_EPOCH, /* %{sec}t */
44 ELEMENT_TYPE_TIMESTAMP_MSEC_SINCE_EPOCH, /* %{msec}t */
45 ELEMENT_TYPE_TIMESTAMP_USEC_SINCE_EPOCH, /* %{usec}t */
46 ELEMENT_TYPE_TIMESTAMP_MSEC_FRAC, /* %{msec_frac}t */
47 ELEMENT_TYPE_TIMESTAMP_USEC_FRAC, /* %{usec_frac}t */
48 ELEMENT_TYPE_URL_PATH, /* %U */
49 ELEMENT_TYPE_REMOTE_USER, /* %u */
50 ELEMENT_TYPE_AUTHORITY, /* %V */
51 ELEMENT_TYPE_HOSTCONF, /* %v */
52 ELEMENT_TYPE_IN_HEADER_TOKEN, /* %{data.header_token}i */
53 ELEMENT_TYPE_IN_HEADER_STRING, /* %{data.name}i */
54 ELEMENT_TYPE_OUT_HEADER_TOKEN, /* %{data.header_token}o */
55 ELEMENT_TYPE_OUT_HEADER_STRING, /* %{data.name}o */
56 ELEMENT_TYPE_OUT_HEADER_TOKEN_CONCATENATED, /* %{data.header_token}o */
57 ELEMENT_TYPE_EXTENDED_VAR, /* %{data.name}x */
58 ELEMENT_TYPE_CONNECTION_ID, /* %{connection-id}x */
59 ELEMENT_TYPE_CONNECT_TIME, /* %{connect-time}x */
60 ELEMENT_TYPE_REQUEST_HEADER_TIME, /* %{request-header-time}x */
61 ELEMENT_TYPE_REQUEST_BODY_TIME, /* %{request-body-time}x */
62 ELEMENT_TYPE_REQUEST_TOTAL_TIME, /* %{request-total-time}x */
63 ELEMENT_TYPE_PROCESS_TIME, /* %{process-time}x */
64 ELEMENT_TYPE_RESPONSE_TIME, /* %{response-total-time}x */
65 ELEMENT_TYPE_TOTAL_TIME, /* %{total-time}x */
66 ELEMENT_TYPE_ERROR, /* %{error}x */
67 ELEMENT_TYPE_PROTOCOL_SPECIFIC, /* %{protocol-specific...}x */
68 ELEMENT_TYPE_PROXY_IDLE_TIME, /* %{proxy.idle-time}x */
69 ELEMENT_TYPE_PROXY_CONNECT_TIME, /* %{proxy.connect-time}x */
70 ELEMENT_TYPE_PROXY_REQUEST_TIME, /* %{proxy.request-time}x */
71 ELEMENT_TYPE_PROXY_PROCESS_TIME, /* %{proxy.process-time}x */
72 ELEMENT_TYPE_PROXY_RESPONSE_TIME, /* %{proxy.response-time}x */
73 ELEMENT_TYPE_PROXY_TOTAL_TIME, /* %{proxy.total-time}x */
74 ELEMENT_TYPE_PROXY_REQUEST_BYTES, /* %{proxy.request-bytes}x */
75 ELEMENT_TYPE_PROXY_REQUEST_BYTES_HEADER, /* %{proxy.request-bytes-header}x */
76 ELEMENT_TYPE_PROXY_REQUEST_BYTES_BODY, /* %{proxy.request-bytes-body}x */
77 ELEMENT_TYPE_PROXY_RESPONSE_BYTES, /* %{proxy.response-bytes}x */
78 ELEMENT_TYPE_PROXY_RESPONSE_BYTES_HEADER, /* %{proxy.response-bytes-header}x */
79 ELEMENT_TYPE_PROXY_RESPONSE_BYTES_BODY, /* %{proxy.response-bytes-body}x */
80 ELEMENT_TYPE_PROXY_SSL_PROTOCOL_VERSION, /* ${proxy.ssl.protocol-version}x */
81 ELEMENT_TYPE_PROXY_SSL_SESSION_REUSED, /* ${proxy.ssl.session-reused}x */
82 ELEMENT_TYPE_PROXY_SSL_CIPHER, /* ${proxy.ssl.cipher}x */
83 ELEMENT_TYPE_PROXY_SSL_CIPHER_BITS, /* ${proxy.ssl.cipher_bits}x */
84 NUM_ELEMENT_TYPES
85 };
86
87 struct log_element_t {
88 unsigned type;
89 h2o_iovec_t suffix;
90 union {
91 const h2o_token_t *header_token;
92 h2o_iovec_t name;
93 size_t protocol_specific_callback_index;
94 } data;
95 unsigned magically_quoted_json : 1; /* whether to omit surrounding doublequotes when the output is null */
96 unsigned original_response : 1;
97 };
98
99 struct st_h2o_logconf_t {
100 H2O_VECTOR(struct log_element_t) elements;
101 int escape;
102 };
103
strdup_lowercased(const char * s,size_t len)104 static h2o_iovec_t strdup_lowercased(const char *s, size_t len)
105 {
106 h2o_iovec_t v = h2o_strdup(NULL, s, len);
107 h2o_strtolower(v.base, v.len);
108 return v;
109 }
110
determine_magicquote_nodes(h2o_logconf_t * logconf,char * errbuf)111 static int determine_magicquote_nodes(h2o_logconf_t *logconf, char *errbuf)
112 {
113 size_t element_index;
114 int quote_char = '\0'; /* the quote char being used if the state machine is within a string literal */
115 int just_in = 0; /* if we just went into the string literal */
116
117 for (element_index = 0; element_index < logconf->elements.size; ++element_index) {
118 h2o_iovec_t suffix = logconf->elements.entries[element_index].suffix;
119 logconf->elements.entries[element_index].magically_quoted_json = just_in && suffix.len != 0 && suffix.base[0] == quote_char;
120
121 just_in = 0;
122
123 size_t i;
124 for (i = 0; i < suffix.len; ++i) {
125 just_in = 0;
126 if (quote_char != '\0') {
127 if (quote_char == suffix.base[i]) {
128 /* out of quote? */
129 size_t j, num_bs = 0;
130 for (j = i; j != 0; ++num_bs)
131 if (suffix.base[--j] != '\\')
132 break;
133 if (num_bs % 2 == 0)
134 quote_char = '\0';
135 }
136 } else {
137 if (suffix.base[i] == '"' || suffix.base[i] == '\'') {
138 quote_char = suffix.base[i];
139 just_in = 1;
140 }
141 }
142 }
143 }
144
145 return 1;
146 }
147
h2o_logconf_compile(const char * fmt,int escape,char * errbuf)148 h2o_logconf_t *h2o_logconf_compile(const char *fmt, int escape, char *errbuf)
149 {
150 h2o_logconf_t *logconf = h2o_mem_alloc(sizeof(*logconf));
151 const char *pt = fmt;
152 size_t fmt_len = strlen(fmt);
153
154 *logconf = (h2o_logconf_t){{NULL}, escape};
155
156 #define LAST_ELEMENT() (logconf->elements.entries + logconf->elements.size - 1)
157 /* suffix buffer is always guaranteed to be larger than the fmt + (sizeof('\n') - 1) (so that they would be no buffer overruns) */
158 #define NEW_ELEMENT(ty) \
159 do { \
160 h2o_vector_reserve(NULL, &logconf->elements, logconf->elements.size + 1); \
161 logconf->elements.size++; \
162 *LAST_ELEMENT() = (struct log_element_t){0}; \
163 LAST_ELEMENT()->type = ty; \
164 LAST_ELEMENT()->suffix.base = h2o_mem_alloc(fmt_len + 1); \
165 } while (0)
166
167 while (*pt != '\0') {
168 if (memcmp(pt, "%%", 2) == 0) {
169 ++pt; /* emit % */
170 } else if (*pt == '%') {
171 ++pt;
172 /* handle < and > */
173 int log_original = 0;
174 for (;; ++pt) {
175 if (*pt == '<') {
176 log_original = 1;
177 } else if (*pt == '>') {
178 log_original = 0;
179 } else {
180 break;
181 }
182 }
183 /* handle {...}n */
184 if (*pt == '{') {
185 const h2o_token_t *token;
186 const char *quote_end = strchr(++pt, '}');
187 if (quote_end == NULL) {
188 sprintf(errbuf, "failed to compile log format: unterminated header name starting at: \"%16s\"", pt);
189 goto Error;
190 }
191 const char modifier = quote_end[1];
192 switch (modifier) {
193 case 'i':
194 case 'o': {
195 h2o_iovec_t name = strdup_lowercased(pt, quote_end - pt);
196 token = h2o_lookup_token(name.base, name.len);
197 if (token != NULL) {
198 free(name.base);
199 if (modifier == 'o' && token == H2O_TOKEN_SET_COOKIE) {
200 NEW_ELEMENT(ELEMENT_TYPE_OUT_HEADER_TOKEN_CONCATENATED);
201 LAST_ELEMENT()->data.header_token = token;
202 } else {
203 NEW_ELEMENT(modifier == 'i' ? ELEMENT_TYPE_IN_HEADER_TOKEN : ELEMENT_TYPE_OUT_HEADER_TOKEN);
204 LAST_ELEMENT()->data.header_token = token;
205 }
206 } else {
207 NEW_ELEMENT(modifier == 'i' ? ELEMENT_TYPE_IN_HEADER_STRING : ELEMENT_TYPE_OUT_HEADER_STRING);
208 LAST_ELEMENT()->data.name = name;
209 }
210 LAST_ELEMENT()->original_response = log_original;
211 } break;
212 case 'p':
213 if (h2o_memis(pt, quote_end - pt, H2O_STRLIT("local"))) {
214 NEW_ELEMENT(ELEMENT_TYPE_LOCAL_PORT);
215 } else if (h2o_memis(pt, quote_end - pt, H2O_STRLIT("remote"))) {
216 NEW_ELEMENT(ELEMENT_TYPE_REMOTE_PORT);
217 } else {
218 sprintf(errbuf, "failed to compile log format: unknown specifier for %%{...}p");
219 goto Error;
220 }
221 break;
222 case 'e': {
223 h2o_iovec_t name = h2o_strdup(NULL, pt, quote_end - pt);
224 NEW_ELEMENT(ELEMENT_TYPE_ENV_VAR);
225 LAST_ELEMENT()->data.name = name;
226 } break;
227 case 't':
228 if (h2o_memis(pt, quote_end - pt, H2O_STRLIT("sec"))) {
229 NEW_ELEMENT(ELEMENT_TYPE_TIMESTAMP_SEC_SINCE_EPOCH);
230 } else if (h2o_memis(pt, quote_end - pt, H2O_STRLIT("msec"))) {
231 NEW_ELEMENT(ELEMENT_TYPE_TIMESTAMP_MSEC_SINCE_EPOCH);
232 } else if (h2o_memis(pt, quote_end - pt, H2O_STRLIT("usec"))) {
233 NEW_ELEMENT(ELEMENT_TYPE_TIMESTAMP_USEC_SINCE_EPOCH);
234 } else if (h2o_memis(pt, quote_end - pt, H2O_STRLIT("msec_frac"))) {
235 NEW_ELEMENT(ELEMENT_TYPE_TIMESTAMP_MSEC_FRAC);
236 } else if (h2o_memis(pt, quote_end - pt, H2O_STRLIT("usec_frac"))) {
237 NEW_ELEMENT(ELEMENT_TYPE_TIMESTAMP_USEC_FRAC);
238 } else {
239 h2o_iovec_t name = h2o_strdup(NULL, pt, quote_end - pt);
240 NEW_ELEMENT(ELEMENT_TYPE_TIMESTAMP_STRFTIME);
241 LAST_ELEMENT()->data.name = name;
242 }
243 break;
244 case 'x':
245 #define MAP_EXT_TO_TYPE(name, id) \
246 if (h2o_lcstris(pt, quote_end - pt, H2O_STRLIT(name))) { \
247 NEW_ELEMENT(id); \
248 goto MAP_EXT_Found; \
249 }
250 #define MAP_EXT_TO_PROTO(name, cb) \
251 if (h2o_lcstris(pt, quote_end - pt, H2O_STRLIT(name))) { \
252 h2o_conn_callbacks_t dummy_; \
253 NEW_ELEMENT(ELEMENT_TYPE_PROTOCOL_SPECIFIC); \
254 LAST_ELEMENT()->data.protocol_specific_callback_index = &dummy_.log_.cb - dummy_.log_.callbacks; \
255 goto MAP_EXT_Found; \
256 }
257 MAP_EXT_TO_TYPE("connection-id", ELEMENT_TYPE_CONNECTION_ID);
258 MAP_EXT_TO_TYPE("connect-time", ELEMENT_TYPE_CONNECT_TIME);
259 MAP_EXT_TO_TYPE("request-total-time", ELEMENT_TYPE_REQUEST_TOTAL_TIME);
260 MAP_EXT_TO_TYPE("request-header-time", ELEMENT_TYPE_REQUEST_HEADER_TIME);
261 MAP_EXT_TO_TYPE("request-body-time", ELEMENT_TYPE_REQUEST_BODY_TIME);
262 MAP_EXT_TO_TYPE("process-time", ELEMENT_TYPE_PROCESS_TIME);
263 MAP_EXT_TO_TYPE("response-time", ELEMENT_TYPE_RESPONSE_TIME);
264 MAP_EXT_TO_TYPE("duration", ELEMENT_TYPE_TOTAL_TIME);
265 MAP_EXT_TO_TYPE("total-time", ELEMENT_TYPE_TOTAL_TIME);
266 MAP_EXT_TO_TYPE("error", ELEMENT_TYPE_ERROR);
267 MAP_EXT_TO_TYPE("proxy.idle-time", ELEMENT_TYPE_PROXY_IDLE_TIME);
268 MAP_EXT_TO_TYPE("proxy.connect-time", ELEMENT_TYPE_PROXY_CONNECT_TIME);
269 MAP_EXT_TO_TYPE("proxy.request-time", ELEMENT_TYPE_PROXY_REQUEST_TIME);
270 MAP_EXT_TO_TYPE("proxy.process-time", ELEMENT_TYPE_PROXY_PROCESS_TIME);
271 MAP_EXT_TO_TYPE("proxy.response-time", ELEMENT_TYPE_PROXY_RESPONSE_TIME);
272 MAP_EXT_TO_TYPE("proxy.total-time", ELEMENT_TYPE_PROXY_TOTAL_TIME);
273 MAP_EXT_TO_TYPE("proxy.request-bytes", ELEMENT_TYPE_PROXY_REQUEST_BYTES);
274 MAP_EXT_TO_TYPE("proxy.request-bytes-header", ELEMENT_TYPE_PROXY_REQUEST_BYTES_HEADER);
275 MAP_EXT_TO_TYPE("proxy.request-bytes-body", ELEMENT_TYPE_PROXY_REQUEST_BYTES_BODY);
276 MAP_EXT_TO_TYPE("proxy.response-bytes", ELEMENT_TYPE_PROXY_RESPONSE_BYTES);
277 MAP_EXT_TO_TYPE("proxy.response-bytes-header", ELEMENT_TYPE_PROXY_RESPONSE_BYTES_HEADER);
278 MAP_EXT_TO_TYPE("proxy.response-bytes-body", ELEMENT_TYPE_PROXY_RESPONSE_BYTES_BODY);
279 MAP_EXT_TO_TYPE("proxy.ssl.protocol-version", ELEMENT_TYPE_PROXY_SSL_PROTOCOL_VERSION);
280 MAP_EXT_TO_TYPE("proxy.ssl.session-reused", ELEMENT_TYPE_PROXY_SSL_SESSION_REUSED);
281 MAP_EXT_TO_TYPE("proxy.ssl.cipher", ELEMENT_TYPE_PROXY_SSL_CIPHER);
282 MAP_EXT_TO_TYPE("proxy.ssl.cipher-bits", ELEMENT_TYPE_PROXY_SSL_CIPHER_BITS);
283 MAP_EXT_TO_PROTO("http1.request-index", http1.request_index);
284 MAP_EXT_TO_PROTO("http2.stream-id", http2.stream_id);
285 MAP_EXT_TO_PROTO("http2.priority.received", http2.priority_received);
286 MAP_EXT_TO_PROTO("http2.priority.received.exclusive", http2.priority_received_exclusive);
287 MAP_EXT_TO_PROTO("http2.priority.received.parent", http2.priority_received_parent);
288 MAP_EXT_TO_PROTO("http2.priority.received.weight", http2.priority_received_weight);
289 MAP_EXT_TO_PROTO("http2.priority.actual", http2.priority_actual);
290 MAP_EXT_TO_PROTO("http2.priority.actual.parent", http2.priority_actual_parent);
291 MAP_EXT_TO_PROTO("http2.priority.actual.weight", http2.priority_actual_weight);
292 MAP_EXT_TO_PROTO("http3.stream-id", http3.stream_id);
293 MAP_EXT_TO_PROTO("http3.quic-stats", http3.quic_stats);
294 MAP_EXT_TO_PROTO("http3.quic-version", http3.quic_version);
295 MAP_EXT_TO_PROTO("cc.name", transport.cc_name);
296 MAP_EXT_TO_PROTO("delivery-rate", transport.delivery_rate);
297 MAP_EXT_TO_PROTO("ssl.protocol-version", ssl.protocol_version);
298 MAP_EXT_TO_PROTO("ssl.session-reused", ssl.session_reused);
299 MAP_EXT_TO_PROTO("ssl.cipher", ssl.cipher);
300 MAP_EXT_TO_PROTO("ssl.cipher-bits", ssl.cipher_bits);
301 MAP_EXT_TO_PROTO("ssl.session-id", ssl.session_id);
302 MAP_EXT_TO_PROTO("ssl.server-name", ssl.server_name);
303 MAP_EXT_TO_PROTO("ssl.negotiated-protocol", ssl.negotiated_protocol);
304 { /* not found */
305 h2o_iovec_t name = strdup_lowercased(pt, quote_end - pt);
306 NEW_ELEMENT(ELEMENT_TYPE_EXTENDED_VAR);
307 LAST_ELEMENT()->data.name = name;
308 }
309 MAP_EXT_Found:
310 #undef MAP_EXT_TO_TYPE
311 #undef MAP_EXT_TO_PROTO
312 break;
313 default:
314 sprintf(errbuf, "failed to compile log format: header name is not followed by either `i`, `o`, `x`, `e`");
315 goto Error;
316 }
317 pt = quote_end + 2;
318 continue;
319 } else {
320 unsigned type = NUM_ELEMENT_TYPES;
321 switch (*pt++) {
322 #define TYPE_MAP(ch, ty) \
323 case ch: \
324 type = ty; \
325 break
326 TYPE_MAP('A', ELEMENT_TYPE_LOCAL_ADDR);
327 TYPE_MAP('b', ELEMENT_TYPE_BYTES_SENT);
328 TYPE_MAP('H', ELEMENT_TYPE_PROTOCOL);
329 TYPE_MAP('h', ELEMENT_TYPE_REMOTE_ADDR);
330 TYPE_MAP('l', ELEMENT_TYPE_LOGNAME);
331 TYPE_MAP('m', ELEMENT_TYPE_METHOD);
332 TYPE_MAP('p', ELEMENT_TYPE_LOCAL_PORT);
333 TYPE_MAP('e', ELEMENT_TYPE_ENV_VAR);
334 TYPE_MAP('q', ELEMENT_TYPE_QUERY);
335 TYPE_MAP('r', ELEMENT_TYPE_REQUEST_LINE);
336 TYPE_MAP('s', ELEMENT_TYPE_STATUS);
337 TYPE_MAP('t', ELEMENT_TYPE_TIMESTAMP);
338 TYPE_MAP('U', ELEMENT_TYPE_URL_PATH);
339 TYPE_MAP('u', ELEMENT_TYPE_REMOTE_USER);
340 TYPE_MAP('V', ELEMENT_TYPE_AUTHORITY);
341 TYPE_MAP('v', ELEMENT_TYPE_HOSTCONF);
342 #undef TYPE_MAP
343 default:
344 sprintf(errbuf, "failed to compile log format: unknown escape sequence: %%%c", pt[-1]);
345 goto Error;
346 }
347 NEW_ELEMENT(type);
348 LAST_ELEMENT()->original_response = log_original;
349 continue;
350 }
351 }
352 /* emit current char */
353 if (logconf->elements.size == 0)
354 NEW_ELEMENT(ELEMENT_TYPE_EMPTY);
355 LAST_ELEMENT()->suffix.base[LAST_ELEMENT()->suffix.len++] = *pt++;
356 }
357
358 /* emit end-of-line */
359 if (logconf->elements.size == 0)
360 NEW_ELEMENT(ELEMENT_TYPE_EMPTY);
361 LAST_ELEMENT()->suffix.base[LAST_ELEMENT()->suffix.len++] = '\n';
362
363 #undef NEW_ELEMENT
364 #undef LAST_ELEMENT
365
366 if (escape == H2O_LOGCONF_ESCAPE_JSON) {
367 if (!determine_magicquote_nodes(logconf, errbuf))
368 goto Error;
369 }
370
371 return logconf;
372
373 Error:
374 h2o_logconf_dispose(logconf);
375 return NULL;
376 }
377
h2o_logconf_dispose(h2o_logconf_t * logconf)378 void h2o_logconf_dispose(h2o_logconf_t *logconf)
379 {
380 size_t i;
381
382 for (i = 0; i != logconf->elements.size; ++i) {
383 free(logconf->elements.entries[i].suffix.base);
384 switch (logconf->elements.entries[i].type) {
385 case ELEMENT_TYPE_EXTENDED_VAR:
386 case ELEMENT_TYPE_IN_HEADER_STRING:
387 case ELEMENT_TYPE_OUT_HEADER_STRING:
388 case ELEMENT_TYPE_TIMESTAMP_STRFTIME:
389 free(logconf->elements.entries[i].data.name.base);
390 break;
391 default:
392 break;
393 }
394 }
395 free(logconf->elements.entries);
396 free(logconf);
397 }
398
append_safe_string(char * pos,const char * src,size_t len)399 static inline char *append_safe_string(char *pos, const char *src, size_t len)
400 {
401 memcpy(pos, src, len);
402 return pos + len;
403 }
404
append_unsafe_string_apache(char * pos,const char * src,size_t len)405 static char *append_unsafe_string_apache(char *pos, const char *src, size_t len)
406 {
407 const char *src_end = src + len;
408
409 for (; src != src_end; ++src) {
410 if (' ' <= *src && *src < 0x7d && *src != '"') {
411 *pos++ = *src;
412 } else {
413 *pos++ = '\\';
414 *pos++ = 'x';
415 *pos++ = ("0123456789abcdef")[(*src >> 4) & 0xf];
416 *pos++ = ("0123456789abcdef")[*src & 0xf];
417 }
418 }
419
420 return pos;
421 }
422
append_unsafe_string_json(char * pos,const char * src,size_t len)423 static char *append_unsafe_string_json(char *pos, const char *src, size_t len)
424 {
425 const char *src_end = src + len;
426
427 for (; src != src_end; ++src) {
428 if (' ' <= *src && *src < 0x7e) {
429 if (*src == '"' || *src == '\\')
430 *pos++ = '\\';
431 *pos++ = *src;
432 } else {
433 *pos++ = '\\';
434 *pos++ = 'u';
435 *pos++ = '0';
436 *pos++ = '0';
437 *pos++ = ("0123456789abcdef")[(*src >> 4) & 0xf];
438 *pos++ = ("0123456789abcdef")[*src & 0xf];
439 }
440 }
441
442 return pos;
443 }
444
append_addr(char * pos,socklen_t (* cb)(h2o_conn_t * conn,struct sockaddr * sa),h2o_conn_t * conn,h2o_iovec_t nullexpr)445 static char *append_addr(char *pos, socklen_t (*cb)(h2o_conn_t *conn, struct sockaddr *sa), h2o_conn_t *conn, h2o_iovec_t nullexpr)
446 {
447 struct sockaddr_storage ss;
448 socklen_t sslen;
449
450 if ((sslen = cb(conn, (void *)&ss)) == 0)
451 goto Fail;
452 size_t l = h2o_socket_getnumerichost((void *)&ss, sslen, pos);
453 if (l == SIZE_MAX)
454 goto Fail;
455 pos += l;
456 return pos;
457
458 Fail:
459 memcpy(pos, nullexpr.base, nullexpr.len);
460 pos += nullexpr.len;
461 return pos;
462 }
463
append_port(char * pos,socklen_t (* cb)(h2o_conn_t * conn,struct sockaddr * sa),h2o_conn_t * conn,h2o_iovec_t nullexpr)464 static char *append_port(char *pos, socklen_t (*cb)(h2o_conn_t *conn, struct sockaddr *sa), h2o_conn_t *conn, h2o_iovec_t nullexpr)
465 {
466 struct sockaddr_storage ss;
467 socklen_t sslen;
468
469 if ((sslen = cb(conn, (void *)&ss)) == 0)
470 goto Fail;
471 int32_t port = h2o_socket_getport((void *)&ss);
472 if (port == -1)
473 goto Fail;
474 pos += sprintf(pos, "%" PRIu16, (uint16_t)port);
475 return pos;
476
477 Fail:
478 memcpy(pos, nullexpr.base, nullexpr.len);
479 pos += nullexpr.len;
480 return pos;
481 }
482
483 #define APPEND_SAFE_STRING_WITH_LEN(pos, s, len) \
484 do { \
485 if (s == NULL) \
486 goto EmitNull; \
487 RESERVE(len); \
488 pos = append_safe_string(pos, s, len); \
489 } while (0)
490 #define APPEND_SAFE_STRING(pos, s) APPEND_SAFE_STRING_WITH_LEN(pos, s, strlen(s))
491 #define APPEND_DURATION(pos, name) \
492 do { \
493 int64_t delta_usec; \
494 if (!h2o_time_compute_##name(req, &delta_usec)) \
495 goto EmitNull; \
496 int32_t delta_sec = (int32_t)(delta_usec / (1000 * 1000)); \
497 delta_usec -= ((int64_t)delta_sec * (1000 * 1000)); \
498 RESERVE(sizeof(H2O_INT32_LONGEST_STR ".999999") - 1); \
499 pos += sprintf(pos, "%" PRId32, delta_sec); \
500 if (delta_usec != 0) { \
501 int i; \
502 *pos++ = '.'; \
503 for (i = 5; i >= 0; --i) { \
504 pos[i] = '0' + delta_usec % 10; \
505 delta_usec /= 10; \
506 } \
507 pos += 6; \
508 } \
509 } while (0)
510
expand_line_buf(char * line,size_t * cur_size,size_t required,int should_realloc)511 static char *expand_line_buf(char *line, size_t *cur_size, size_t required, int should_realloc)
512 {
513 size_t new_size = *cur_size;
514
515 /* determine the new size */
516 do {
517 new_size *= 2;
518 } while (new_size < required);
519
520 /* reallocate */
521 if (!should_realloc) {
522 char *newpt = h2o_mem_alloc(new_size);
523 memcpy(newpt, line, *cur_size);
524 line = newpt;
525 } else {
526 line = h2o_mem_realloc(line, new_size);
527 }
528 *cur_size = new_size;
529
530 return line;
531 }
532
h2o_log_request(h2o_logconf_t * logconf,h2o_req_t * req,size_t * len,char * buf)533 char *h2o_log_request(h2o_logconf_t *logconf, h2o_req_t *req, size_t *len, char *buf)
534 {
535 char *line = buf, *pos = line, *line_end = line + *len;
536 h2o_iovec_t nullexpr;
537 char *(*append_unsafe_string)(char *pos, const char *src, size_t len);
538 size_t element_index, unsafe_factor;
539 struct tm localt = {0};
540 int should_realloc_on_expand = 0;
541
542 switch (logconf->escape) {
543 case H2O_LOGCONF_ESCAPE_APACHE:
544 nullexpr = h2o_iovec_init(H2O_STRLIT("-"));
545 append_unsafe_string = append_unsafe_string_apache;
546 unsafe_factor = 4;
547 break;
548 case H2O_LOGCONF_ESCAPE_JSON:
549 nullexpr = h2o_iovec_init(H2O_STRLIT("null"));
550 append_unsafe_string = append_unsafe_string_json;
551 unsafe_factor = 6;
552 break;
553 default:
554 h2o_fatal("unexpected escape mode");
555 break;
556 }
557
558 for (element_index = 0; element_index != logconf->elements.size; ++element_index) {
559 struct log_element_t *element = logconf->elements.entries + element_index;
560
561 /* reserve capacity + suffix.len */
562 #define RESERVE(capacity) \
563 do { \
564 if ((capacity) + element->suffix.len > line_end - pos) { \
565 size_t off = pos - line; \
566 size_t size = line_end - line; \
567 line = expand_line_buf(line, &size, off + (capacity) + element->suffix.len, should_realloc_on_expand); \
568 pos = line + off; \
569 line_end = line + size; \
570 should_realloc_on_expand = 1; \
571 } \
572 } while (0)
573
574 switch (element->type) {
575 case ELEMENT_TYPE_EMPTY:
576 RESERVE(0);
577 break;
578 case ELEMENT_TYPE_LOCAL_ADDR: /* %A */
579 RESERVE(NI_MAXHOST);
580 pos = append_addr(pos, req->conn->callbacks->get_sockname, req->conn, nullexpr);
581 break;
582 case ELEMENT_TYPE_BYTES_SENT: /* %b */
583 RESERVE(sizeof(H2O_UINT64_LONGEST_STR) - 1);
584 pos += sprintf(pos, "%" PRIu64, req->bytes_sent);
585 break;
586 case ELEMENT_TYPE_PROTOCOL: /* %H */
587 if (req->version == 0)
588 goto EmitNull;
589 RESERVE(sizeof("HTTP/1.1"));
590 pos += h2o_stringify_protocol_version(pos, req->version);
591 break;
592 case ELEMENT_TYPE_REMOTE_ADDR: /* %h */
593 RESERVE(NI_MAXHOST);
594 pos = append_addr(pos, req->conn->callbacks->get_peername, req->conn, nullexpr);
595 break;
596 case ELEMENT_TYPE_METHOD: /* %m */
597 if (req->input.method.len == 0)
598 goto EmitNull;
599 RESERVE(req->input.method.len * unsafe_factor);
600 pos = append_unsafe_string(pos, req->input.method.base, req->input.method.len);
601 break;
602 case ELEMENT_TYPE_LOCAL_PORT: /* %p */
603 RESERVE(sizeof(H2O_UINT16_LONGEST_STR) - 1);
604 pos = append_port(pos, req->conn->callbacks->get_sockname, req->conn, nullexpr);
605 break;
606 case ELEMENT_TYPE_REMOTE_PORT: /* %{remote}p */
607 RESERVE(sizeof(H2O_UINT16_LONGEST_STR) - 1);
608 pos = append_port(pos, req->conn->callbacks->get_peername, req->conn, nullexpr);
609 break;
610 case ELEMENT_TYPE_ENV_VAR: /* %{..}e */ {
611 h2o_iovec_t *env_var = h2o_req_getenv(req, element->data.name.base, element->data.name.len, 0);
612 if (env_var == NULL)
613 goto EmitNull;
614 RESERVE(env_var->len * unsafe_factor);
615 pos = append_safe_string(pos, env_var->base, env_var->len);
616 } break;
617 case ELEMENT_TYPE_QUERY: /* %q */
618 if (req->input.query_at != SIZE_MAX) {
619 size_t len = req->input.path.len - req->input.query_at;
620 RESERVE(len * unsafe_factor);
621 pos = append_unsafe_string(pos, req->input.path.base + req->input.query_at, len);
622 }
623 break;
624 case ELEMENT_TYPE_REQUEST_LINE: /* %r */
625 if (req->version == 0)
626 goto EmitNull;
627 RESERVE((req->input.method.len + req->input.path.len) * unsafe_factor + sizeof(" HTTP/1.1"));
628 pos = append_unsafe_string(pos, req->input.method.base, req->input.method.len);
629 *pos++ = ' ';
630 pos = append_unsafe_string(pos, req->input.path.base, req->input.path.len);
631 *pos++ = ' ';
632 pos += h2o_stringify_protocol_version(pos, req->version);
633 break;
634 case ELEMENT_TYPE_STATUS: /* %s */
635 if (req->res.status == 0)
636 goto EmitNull;
637 RESERVE(sizeof(H2O_INT32_LONGEST_STR) - 1);
638 pos += sprintf(pos, "%" PRId32, (int32_t)(element->original_response ? req->res.original.status : req->res.status));
639 break;
640 case ELEMENT_TYPE_TIMESTAMP: /* %t */
641 if (h2o_timeval_is_null(&req->processed_at.at))
642 goto EmitNull;
643 RESERVE(H2O_TIMESTR_LOG_LEN + 2);
644 *pos++ = '[';
645 pos = append_safe_string(pos, req->processed_at.str->log, H2O_TIMESTR_LOG_LEN);
646 *pos++ = ']';
647 break;
648 case ELEMENT_TYPE_TIMESTAMP_STRFTIME: /* %{...}t */
649 if (h2o_timeval_is_null(&req->processed_at.at))
650 goto EmitNull;
651 {
652 size_t bufsz, len;
653 if (localt.tm_year == 0)
654 localtime_r(&req->processed_at.at.tv_sec, &localt);
655 for (bufsz = 128;; bufsz *= 2) {
656 RESERVE(bufsz);
657 if ((len = strftime(pos, bufsz, element->data.name.base, &localt)) != 0)
658 break;
659 }
660 pos += len;
661 }
662 break;
663 case ELEMENT_TYPE_TIMESTAMP_SEC_SINCE_EPOCH: /* %{sec}t */
664 if (h2o_timeval_is_null(&req->processed_at.at))
665 goto EmitNull;
666 RESERVE(sizeof(H2O_UINT32_LONGEST_STR) - 1);
667 pos += sprintf(pos, "%" PRIu32, (uint32_t)req->processed_at.at.tv_sec);
668 break;
669 case ELEMENT_TYPE_TIMESTAMP_MSEC_SINCE_EPOCH: /* %{msec}t */
670 if (h2o_timeval_is_null(&req->processed_at.at))
671 goto EmitNull;
672 RESERVE(sizeof(H2O_UINT64_LONGEST_STR) - 1);
673 pos += sprintf(pos, "%" PRIu64,
674 (uint64_t)req->processed_at.at.tv_sec * 1000 + (uint64_t)req->processed_at.at.tv_usec / 1000);
675 break;
676 case ELEMENT_TYPE_TIMESTAMP_USEC_SINCE_EPOCH: /* %{usec}t */
677 if (h2o_timeval_is_null(&req->processed_at.at))
678 goto EmitNull;
679 RESERVE(sizeof(H2O_UINT64_LONGEST_STR) - 1);
680 pos +=
681 sprintf(pos, "%" PRIu64, (uint64_t)req->processed_at.at.tv_sec * 1000000 + (uint64_t)req->processed_at.at.tv_usec);
682 break;
683 case ELEMENT_TYPE_TIMESTAMP_MSEC_FRAC: /* %{msec_frac}t */
684 if (h2o_timeval_is_null(&req->processed_at.at))
685 goto EmitNull;
686 RESERVE(3);
687 pos += sprintf(pos, "%03u", (unsigned)(req->processed_at.at.tv_usec / 1000));
688 break;
689 case ELEMENT_TYPE_TIMESTAMP_USEC_FRAC: /* %{usec_frac}t */
690 if (h2o_timeval_is_null(&req->processed_at.at))
691 goto EmitNull;
692 RESERVE(6);
693 pos += sprintf(pos, "%06u", (unsigned)req->processed_at.at.tv_usec);
694 break;
695 case ELEMENT_TYPE_URL_PATH: /* %U */ {
696 if (req->input.path.len == 0)
697 goto EmitNull;
698 size_t path_len = req->input.query_at == SIZE_MAX ? req->input.path.len : req->input.query_at;
699 RESERVE(path_len * unsafe_factor);
700 pos = append_unsafe_string(pos, req->input.path.base, path_len);
701 } break;
702 case ELEMENT_TYPE_REMOTE_USER: /* %u */ {
703 h2o_iovec_t *remote_user = h2o_req_getenv(req, H2O_STRLIT("REMOTE_USER"), 0);
704 if (remote_user == NULL)
705 goto EmitNull;
706 RESERVE(remote_user->len * unsafe_factor);
707 pos = append_unsafe_string(pos, remote_user->base, remote_user->len);
708 } break;
709 case ELEMENT_TYPE_AUTHORITY: /* %V */
710 RESERVE(req->input.authority.len * unsafe_factor);
711 pos = append_unsafe_string(pos, req->input.authority.base, req->input.authority.len);
712 break;
713 case ELEMENT_TYPE_HOSTCONF: /* %v */
714 RESERVE(req->hostconf->authority.hostport.len * unsafe_factor);
715 pos = append_unsafe_string(pos, req->hostconf->authority.hostport.base, req->hostconf->authority.hostport.len);
716 break;
717
718 #define EMIT_HEADER(__headers, concat, findfunc, ...) \
719 do { \
720 h2o_headers_t *headers = (__headers); \
721 ssize_t index = -1; \
722 int found = 0; \
723 while ((index = (findfunc)(headers, __VA_ARGS__, index)) != -1) { \
724 if (found) { \
725 RESERVE(2); \
726 *pos++ = ','; \
727 *pos++ = ' '; \
728 } else { \
729 found = 1; \
730 } \
731 const h2o_header_t *header = headers->entries + index; \
732 RESERVE(header->value.len *unsafe_factor); \
733 pos = append_unsafe_string(pos, header->value.base, header->value.len); \
734 if (!concat) \
735 break; \
736 } \
737 if (!found) \
738 goto EmitNull; \
739 } while (0)
740
741 case ELEMENT_TYPE_IN_HEADER_TOKEN:
742 EMIT_HEADER(&req->headers, 0, h2o_find_header, element->data.header_token);
743 break;
744 case ELEMENT_TYPE_IN_HEADER_STRING:
745 EMIT_HEADER(&req->headers, 0, h2o_find_header_by_str, element->data.name.base, element->data.name.len);
746 break;
747 case ELEMENT_TYPE_OUT_HEADER_TOKEN:
748 EMIT_HEADER(element->original_response ? &req->res.original.headers : &req->res.headers, 0, h2o_find_header,
749 element->data.header_token);
750 break;
751 case ELEMENT_TYPE_OUT_HEADER_STRING:
752 EMIT_HEADER(element->original_response ? &req->res.original.headers : &req->res.headers, 0, h2o_find_header_by_str,
753 element->data.name.base, element->data.name.len);
754 break;
755 case ELEMENT_TYPE_OUT_HEADER_TOKEN_CONCATENATED:
756 EMIT_HEADER(element->original_response ? &req->res.original.headers : &req->res.headers, 1, h2o_find_header,
757 element->data.header_token);
758 break;
759
760 #undef EMIT_HEADER
761
762 case ELEMENT_TYPE_CONNECTION_ID:
763 RESERVE(sizeof(H2O_UINT64_LONGEST_STR) - 1);
764 pos += sprintf(pos, "%" PRIu64, req->conn->id);
765 break;
766
767 case ELEMENT_TYPE_CONNECT_TIME:
768 APPEND_DURATION(pos, connect_time);
769 break;
770
771 case ELEMENT_TYPE_REQUEST_HEADER_TIME:
772 APPEND_DURATION(pos, header_time);
773 break;
774
775 case ELEMENT_TYPE_REQUEST_BODY_TIME:
776 APPEND_DURATION(pos, body_time);
777 break;
778
779 case ELEMENT_TYPE_REQUEST_TOTAL_TIME:
780 APPEND_DURATION(pos, request_total_time);
781 break;
782
783 case ELEMENT_TYPE_PROCESS_TIME:
784 APPEND_DURATION(pos, process_time);
785 break;
786
787 case ELEMENT_TYPE_RESPONSE_TIME:
788 APPEND_DURATION(pos, response_time);
789 break;
790
791 case ELEMENT_TYPE_TOTAL_TIME:
792 APPEND_DURATION(pos, total_time);
793 break;
794
795 case ELEMENT_TYPE_ERROR:
796 if (req->error_logs != NULL)
797 pos = append_unsafe_string(pos, req->error_logs->bytes, req->error_logs->size);
798 break;
799
800 case ELEMENT_TYPE_PROXY_IDLE_TIME:
801 APPEND_DURATION(pos, proxy_idle_time);
802 break;
803
804 case ELEMENT_TYPE_PROXY_CONNECT_TIME:
805 APPEND_DURATION(pos, proxy_connect_time);
806 break;
807
808 case ELEMENT_TYPE_PROXY_REQUEST_TIME:
809 APPEND_DURATION(pos, proxy_request_time);
810 break;
811
812 case ELEMENT_TYPE_PROXY_PROCESS_TIME:
813 APPEND_DURATION(pos, proxy_process_time);
814 break;
815
816 case ELEMENT_TYPE_PROXY_RESPONSE_TIME:
817 APPEND_DURATION(pos, proxy_response_time);
818 break;
819
820 case ELEMENT_TYPE_PROXY_TOTAL_TIME:
821 APPEND_DURATION(pos, proxy_total_time);
822 break;
823
824 case ELEMENT_TYPE_PROXY_REQUEST_BYTES:
825 RESERVE(sizeof(H2O_UINT64_LONGEST_STR) - 1);
826 pos += sprintf(pos, "%" PRIu64, req->proxy_stats.bytes_written.total);
827 break;
828
829 case ELEMENT_TYPE_PROXY_REQUEST_BYTES_HEADER:
830 RESERVE(sizeof(H2O_UINT64_LONGEST_STR) - 1);
831 pos += sprintf(pos, "%" PRIu64, req->proxy_stats.bytes_written.header);
832 break;
833
834 case ELEMENT_TYPE_PROXY_REQUEST_BYTES_BODY:
835 RESERVE(sizeof(H2O_UINT64_LONGEST_STR) - 1);
836 pos += sprintf(pos, "%" PRIu64, req->proxy_stats.bytes_written.body);
837 break;
838
839 case ELEMENT_TYPE_PROXY_RESPONSE_BYTES:
840 RESERVE(sizeof(H2O_UINT64_LONGEST_STR) - 1);
841 pos += sprintf(pos, "%" PRIu64, req->proxy_stats.bytes_read.total);
842 break;
843
844 case ELEMENT_TYPE_PROXY_RESPONSE_BYTES_HEADER:
845 RESERVE(sizeof(H2O_UINT64_LONGEST_STR) - 1);
846 pos += sprintf(pos, "%" PRIu64, req->proxy_stats.bytes_read.header);
847 break;
848
849 case ELEMENT_TYPE_PROXY_RESPONSE_BYTES_BODY:
850 RESERVE(sizeof(H2O_UINT64_LONGEST_STR) - 1);
851 pos += sprintf(pos, "%" PRIu64, req->proxy_stats.bytes_read.body);
852 break;
853 case ELEMENT_TYPE_PROXY_SSL_SESSION_REUSED:
854 RESERVE(1);
855 *pos++ = (req->proxy_stats.conn.ssl.session_reused) ? '1' : '0';
856 break;
857 case ELEMENT_TYPE_PROXY_SSL_CIPHER_BITS:
858 if (req->proxy_stats.conn.ssl.cipher_bits == 0)
859 goto EmitNull;
860 RESERVE(sizeof(H2O_INT16_LONGEST_STR));
861 pos += sprintf(pos, "%" PRIu16, (uint16_t)req->proxy_stats.conn.ssl.cipher_bits);
862 break;
863 case ELEMENT_TYPE_PROXY_SSL_PROTOCOL_VERSION:
864 APPEND_SAFE_STRING(pos, req->proxy_stats.conn.ssl.protocol_version);
865 break;
866 case ELEMENT_TYPE_PROXY_SSL_CIPHER:
867 APPEND_SAFE_STRING(pos, req->proxy_stats.conn.ssl.cipher);
868 break;
869 case ELEMENT_TYPE_PROTOCOL_SPECIFIC: {
870 h2o_iovec_t (*cb)(h2o_req_t *) = req->conn->callbacks->log_.callbacks[element->data.protocol_specific_callback_index];
871 if (cb == NULL)
872 goto EmitNull;
873 h2o_iovec_t s = cb(req);
874 APPEND_SAFE_STRING_WITH_LEN(pos, s.base, s.len);
875 } break;
876
877 case ELEMENT_TYPE_LOGNAME: /* %l */
878 case ELEMENT_TYPE_EXTENDED_VAR: /* %{...}x */
879 EmitNull:
880 RESERVE(nullexpr.len);
881 /* special case that trims surrounding quotes */
882 if (element->magically_quoted_json) {
883 --pos;
884 pos = append_safe_string(pos, nullexpr.base, nullexpr.len);
885 pos = append_safe_string(pos, element->suffix.base + 1, element->suffix.len - 1);
886 continue;
887 }
888 pos = append_safe_string(pos, nullexpr.base, nullexpr.len);
889 break;
890
891 default:
892 assert(!"unknown type");
893 break;
894 }
895
896 #undef RESERVE
897
898 pos = append_safe_string(pos, element->suffix.base, element->suffix.len);
899 }
900
901 *len = pos - line;
902 return line;
903 }
904