accesslog.c (7814B)
1 /*
2 * Copyright (c) 2013-2022 Joris Vink <joris@coders.se>
3 *
4 * Permission to use, copy, modify, and distribute this software for any
5 * purpose with or without fee is hereby granted, provided that the above
6 * copyright notice and this permission notice appear in all copies.
7 *
8 * THE SOFTWARE IS PROVIDED "AS IS" AND THE AUTHOR DISCLAIMS ALL WARRANTIES
9 * WITH REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF
10 * MERCHANTABILITY AND FITNESS. IN NO EVENT SHALL THE AUTHOR BE LIABLE FOR
11 * ANY SPECIAL, DIRECT, INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES
12 * WHATSOEVER RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN
13 * ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF
14 * OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE.
15 */
16
17 #include <sys/types.h>
18 #include <sys/socket.h>
19
20 #include <time.h>
21 #include <inttypes.h>
22 #include <signal.h>
23
24 #include "kore.h"
25 #include "http.h"
26
27 /*
28 * The worker will write accesslogs to its worker data structure which is
29 * held in shared memory.
30 *
31 * Each accesslog is prefixed with the internal domain ID (2 bytes) and
32 * the length of the log entry (2 bytes) (packed in kore_alog_header).
33 *
34 * The parent will every 10ms fetch the produced accesslogs from the workers
35 * and copy them to its own log buffer. Once this log buffer becomes full
36 * or 1 second has passed the parent will parse the logs and append them
37 * to the correct domain logbuffer which is eventually flushed to disk.
38 */
39
40 #define LOGBUF_SIZE (KORE_ACCESSLOG_BUFLEN * worker_count)
41 #define DOMAIN_LOGBUF_LEN (1024 * 1024)
42 #define LOG_ENTRY_MINSIZE_GUESS 90
43
44 static void accesslog_lock(struct kore_worker *);
45 static void accesslog_unlock(struct kore_worker *);
46 static void accesslog_flush_cb(struct kore_domain *);
47 static void accesslog_flush(struct kore_domain *, u_int64_t, int);
48
49 static u_int64_t time_cache = 0;
50 static char tbuf[128] = { '\0' };
51
52 static struct kore_buf *logbuf = NULL;
53
54 void
55 kore_accesslog_worker_init(void)
56 {
57 kore_domain_closelogs();
58 }
59
60 void
61 kore_accesslog(struct http_request *req)
62 {
63 struct timespec ts;
64 struct tm *tm;
65 u_int64_t now;
66 struct kore_alog_header *hdr;
67 size_t avail;
68 time_t curtime;
69 int len, attempts;
70 char addr[INET6_ADDRSTRLEN], *cn_value;
71 const char *ptr, *method, *http_version, *cn, *referer;
72
73 switch (req->method) {
74 case HTTP_METHOD_GET:
75 method = "GET";
76 break;
77 case HTTP_METHOD_POST:
78 method = "POST";
79 break;
80 case HTTP_METHOD_PUT:
81 method = "PUT";
82 break;
83 case HTTP_METHOD_DELETE:
84 method = "DELETE";
85 break;
86 case HTTP_METHOD_HEAD:
87 method = "HEAD";
88 break;
89 case HTTP_METHOD_PATCH:
90 method = "PATCH";
91 break;
92 default:
93 method = "UNKNOWN";
94 break;
95 }
96
97 if (req->flags & HTTP_VERSION_1_0)
98 http_version = "HTTP/1.0";
99 else
100 http_version = "HTTP/1.1";
101
102 if (req->referer != NULL)
103 referer = req->referer;
104 else
105 referer = "-";
106
107 if (req->agent == NULL)
108 req->agent = "-";
109
110 cn = "-";
111 cn_value = NULL;
112
113 if (req->owner->tls_cert != NULL) {
114 if (kore_x509_subject_name(req->owner, &cn_value,
115 KORE_X509_COMMON_NAME_ONLY))
116 cn = cn_value;
117 }
118
119 switch (req->owner->family) {
120 case AF_INET:
121 ptr = inet_ntop(req->owner->family,
122 &(req->owner->addr.ipv4.sin_addr), addr, sizeof(addr));
123 break;
124 case AF_INET6:
125 ptr = inet_ntop(req->owner->family,
126 &(req->owner->addr.ipv6.sin6_addr), addr, sizeof(addr));
127 break;
128 case AF_UNIX:
129 ptr = NULL;
130 break;
131 default:
132 fatal("unknown family %d", req->owner->family);
133 }
134
135 if (ptr == NULL) {
136 addr[0] = '-';
137 addr[1] = '\0';
138 }
139
140 now = kore_time_ms();
141 if ((now - time_cache) >= 1000) {
142 time(&curtime);
143 tm = localtime(&curtime);
144 (void)strftime(tbuf, sizeof(tbuf), "%d/%b/%Y:%H:%M:%S %z", tm);
145 time_cache = now;
146 }
147
148 attempts = 0;
149 ts.tv_sec = 0;
150 ts.tv_nsec = 1000000;
151
152 for (;;) {
153 if (attempts++ > 1000) {
154 if (getppid() == 1) {
155 if (kill(worker->pid, SIGQUIT) == -1)
156 fatal("failed to shutdown");
157 return;
158 }
159
160 attempts = 0;
161 }
162
163 accesslog_lock(worker);
164
165 avail = KORE_ACCESSLOG_BUFLEN - worker->lb.offset;
166 if (avail < sizeof(*hdr) + LOG_ENTRY_MINSIZE_GUESS) {
167 accesslog_unlock(worker);
168 nanosleep(&ts, NULL);
169 continue;
170 }
171
172 hdr = (struct kore_alog_header *)
173 (worker->lb.buf + worker->lb.offset);
174 worker->lb.offset += sizeof(*hdr);
175
176 len = snprintf(worker->lb.buf + worker->lb.offset, avail,
177 "%s - %s [%s] \"%s %s %s\" %d %" PRIu64" \"%s\" \"%s\"\n",
178 addr, cn, tbuf, method, req->path, http_version,
179 req->status, req->content_length, referer, req->agent);
180 if (len == -1)
181 fatal("failed to create log entry");
182
183 if ((size_t)len >= avail) {
184 worker->lb.offset -= sizeof(*hdr);
185 accesslog_unlock(worker);
186 nanosleep(&ts, NULL);
187 continue;
188 }
189
190 if ((size_t)len > USHRT_MAX) {
191 kore_log(LOG_WARNING,
192 "log entry length exceeds limit (%d)", len);
193 worker->lb.offset -= sizeof(*hdr);
194 break;
195 }
196
197 hdr->loglen = len;
198 hdr->domain = req->rt->dom->id;
199
200 worker->lb.offset += (size_t)len;
201 break;
202 }
203
204 kore_free(cn_value);
205 accesslog_unlock(worker);
206 }
207
208 void
209 kore_accesslog_gather(void *arg, u_int64_t now, int force)
210 {
211 int id;
212 struct kore_worker *kw;
213 struct kore_alog_header *hdr;
214 struct kore_domain *dom;
215 size_t off, remain;
216
217 if (logbuf == NULL)
218 logbuf = kore_buf_alloc(LOGBUF_SIZE);
219
220 for (id = KORE_WORKER_BASE; id < worker_count; id++) {
221 kw = kore_worker_data(id);
222
223 accesslog_lock(kw);
224
225 if (force || kw->lb.offset >= KORE_ACCESSLOG_SYNC) {
226 kore_buf_append(logbuf, kw->lb.buf, kw->lb.offset);
227 kw->lb.offset = 0;
228 }
229
230 accesslog_unlock(kw);
231 }
232
233 if (force || logbuf->offset >= LOGBUF_SIZE) {
234 off = 0;
235 remain = logbuf->offset;
236
237 while (remain > 0) {
238 if (remain < sizeof(*hdr)) {
239 kore_log(LOG_ERR,
240 "invalid log buffer: (%zu remain)", remain);
241 break;
242 }
243
244 hdr = (struct kore_alog_header *)(logbuf->data + off);
245 off += sizeof(*hdr);
246 remain -= sizeof(*hdr);
247
248 if (hdr->loglen > remain) {
249 kore_log(LOG_ERR,
250 "invalid log header: %u (%zu remain)",
251 hdr->loglen, remain);
252 break;
253 }
254
255 if ((dom = kore_domain_byid(hdr->domain)) == NULL)
256 fatal("unknown domain id %u", hdr->domain);
257
258 if (dom->logbuf == NULL)
259 dom->logbuf = kore_buf_alloc(DOMAIN_LOGBUF_LEN);
260
261 kore_buf_append(dom->logbuf, &logbuf->data[off],
262 hdr->loglen);
263
264 off += hdr->loglen;
265 remain -= hdr->loglen;
266
267 accesslog_flush(dom, now, force);
268 }
269
270 kore_buf_reset(logbuf);
271 }
272
273 if (force)
274 kore_domain_callback(accesslog_flush_cb);
275 }
276
277 void
278 kore_accesslog_run(void *arg, u_int64_t now)
279 {
280 static int ticks = 0;
281
282 kore_accesslog_gather(arg, now, ticks++ % 100 ? 0 : 1);
283 }
284
285 static void
286 accesslog_flush_cb(struct kore_domain *dom)
287 {
288 accesslog_flush(dom, 0, 1);
289 }
290
291 static void
292 accesslog_flush(struct kore_domain *dom, u_int64_t now, int force)
293 {
294 ssize_t written;
295
296 if (force && dom->logbuf == NULL)
297 return;
298
299 if (force || dom->logbuf->offset >= DOMAIN_LOGBUF_LEN) {
300 written = write(dom->accesslog, dom->logbuf->data,
301 dom->logbuf->offset);
302 if (written == -1) {
303 if (errno == EINTR)
304 return;
305 if (dom->logwarn == 0 ||
306 errno != dom->logerr) {
307 kore_log(LOG_NOTICE,
308 "error writing log for %s (%s)",
309 dom->domain, errno_s);
310 dom->logwarn = now;
311 dom->logerr = errno;
312 }
313 kore_buf_reset(dom->logbuf);
314 return;
315 }
316
317 if ((size_t)written != dom->logbuf->offset) {
318 kore_log(LOG_ERR, "partial accesslog write for %s",
319 dom->domain);
320 }
321
322 kore_buf_reset(dom->logbuf);
323 }
324 }
325
326 static void
327 accesslog_lock(struct kore_worker *kw)
328 {
329 for (;;) {
330 if (__sync_bool_compare_and_swap(&kw->lb.lock, 0, 1))
331 break;
332 }
333 }
334
335 static void
336 accesslog_unlock(struct kore_worker *kw)
337 {
338 if (!__sync_bool_compare_and_swap(&kw->lb.lock, 1, 0))
339 fatal("accesslog_unlock: failed to release");
340 }