Line data Source code
1 : /*
2 : * Copyright (c) 2015-21 David Lamparter, for NetDEF, Inc.
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 : /* when you work on this code, please install a fuzzer (e.g. AFL) and run
18 : * tests/lib/fuzz_zlog.c
19 : *
20 : * The most likely type of bug in this code is an off-by-one error in the
21 : * buffer management pieces, and this isn't easily covered by an unit test
22 : * or topotests. Fuzzing is the best tool here, but the CI can't do that
23 : * since it's quite resource intensive.
24 : */
25 :
26 : #include "zebra.h"
27 :
28 : #include "zlog_5424.h"
29 :
30 : #include <sys/un.h>
31 : #include <syslog.h>
32 :
33 : #include "memory.h"
34 : #include "frrcu.h"
35 : #include "printfrr.h"
36 : #include "typerb.h"
37 : #include "frr_pthread.h"
38 : #include "command.h"
39 : #include "monotime.h"
40 : #include "thread.h"
41 :
42 : #include "lib/version.h"
43 : #include "lib/lib_errors.h"
44 :
45 36 : DEFINE_MTYPE_STATIC(LOG, LOG_5424, "extended log target");
46 36 : DEFINE_MTYPE_STATIC(LOG, LOG_5424_ROTATE, "extended log rotate helper");
47 :
48 : /* the actual log target data structure
49 : *
50 : * remember this is RCU'd by the core zlog functions. Changing anything
51 : * works by allocating a new struct, filling it, adding it, and removing the
52 : * old one.
53 : */
54 : struct zlt_5424 {
55 : struct zlog_target zt;
56 :
57 : atomic_uint_fast32_t fd;
58 :
59 : enum zlog_5424_format fmt;
60 : uint32_t ts_flags;
61 : int facility;
62 :
63 : /* the various extra pieces to add... */
64 : bool kw_version : 1;
65 : bool kw_location : 1;
66 : bool kw_uid : 1;
67 : bool kw_ec : 1;
68 : bool kw_args : 1;
69 :
70 : /* some formats may or may not include the trailing \n */
71 : bool use_nl : 1;
72 :
73 : /* for DGRAM & SEQPACKET sockets, send 1 log message per packet, since
74 : * the socket preserves packet boundaries. On Linux, this uses
75 : * sendmmsg() for efficiency, on other systems we need a syscall each.
76 : */
77 : bool packets : 1;
78 :
79 : /* for DGRAM, in order to not have to reconnect, we need to use
80 : * sendto()/sendmsg() with the destination given; otherwise we'll get
81 : * ENOTCONN. (We do a connect(), which serves to verify the type of
82 : * socket, but if the receiver goes away, the kernel disconnects the
83 : * socket so writev() no longer works since the destination is now
84 : * unspecified.)
85 : */
86 : struct sockaddr_storage sa;
87 : socklen_t sa_len;
88 :
89 : /* these are both getting set, but current_err is cleared on success,
90 : * so we know whether the error is current or past.
91 : */
92 : int last_err, current_err;
93 : atomic_size_t lost_msgs;
94 : struct timeval last_err_ts;
95 :
96 : struct rcu_head_close head_close;
97 : };
98 :
99 : static int zlog_5424_open(struct zlog_cfg_5424 *zcf, int sock_type);
100 :
101 : /* rough header length estimate
102 : * ============================
103 : *
104 : * ^ = might grow
105 : *
106 : * 49^ longest filename (pceplib/test/pcep_utils_double_linked_list_test.h)
107 : * 5^ highest line number (48530, bgpd/bgp_nb_config.c)
108 : * 65^ longest function name
109 : * (lib_prefix_list_entry_ipv6_prefix_length_greater_or_equal_destroy)
110 : * 11 unique id ("XXXXX-XXXXX")
111 : * 10 EC ("4294967295" or "0xffffffff")
112 : * 35 ISO8601 TS at full length ("YYYY-MM-DD HH:MM:SS.NNNNNNNNN+ZZ:ZZ")
113 : * ---
114 : * 175
115 : *
116 : * rarely used (hopefully...):
117 : * 26^ FRR_VERSION ("10.10.10-dev-gffffffffffff")
118 : * ---
119 : * 201
120 : *
121 : * x16 highest number of format parameters currently
122 : * 40 estimate for hostname + 2*daemon + pid
123 : *
124 : * specific format overhead:
125 : *
126 : * RFC3164 - shorter than the others
127 : * RFC5424 - 175 + "<999>1 "=7 + 52 (location@50145) + 40 (host/...)
128 : * rarely: + 65 + 26 (for [origin])
129 : * args: 16 * (8 + per-arg (20?)) = ~448
130 : *
131 : * so without "args@", origin or (future) keywords, around 256 seems OK
132 : * with args@ and/or origin and/or keywords, 512 seems more reasonable
133 : *
134 : * but - note the code allocates this amount multiplied by the number of
135 : * messages in the incoming batch (minimum 3), this means short messages and
136 : * long messages smooth each other out.
137 : *
138 : * Since the code handles space-exceeded by grabbing a bunch of stack memory,
139 : * a reasonable middle ground estimate is desirable here, so ...
140 : * *drumroll*
141 : * let's go with 128 + args?128. (remember the minimum 3 multiplier)
142 : *
143 : * low_space is the point where we don't try to fit another message in & just
144 : * submit what we have to the kernel.
145 : *
146 : * The zlog code only buffers debug & informational messages, so in production
147 : * usage most of the calls will be writing out only 1 message. This makes
148 : * the min *3 multiplier quite useful.
149 : */
150 :
151 0 : static inline size_t zlog_5424_bufsz(struct zlt_5424 *zte, size_t nmsgs,
152 : size_t *low_space)
153 : {
154 0 : size_t ret = 128;
155 :
156 0 : if (zte->kw_args)
157 0 : ret += 128;
158 0 : *low_space = ret;
159 0 : return ret * MAX(nmsgs, 3);
160 : }
161 :
162 : struct state {
163 : struct fbuf *fbuf;
164 : struct iovec *iov;
165 : };
166 :
167 : /* stack-based keyword support is likely to bump this to 3 or 4 */
168 : #define IOV_PER_MSG 2
169 : _Static_assert(IOV_MAX >= IOV_PER_MSG,
170 : "this code won't work with IOV_MAX < IOV_PER_MSG");
171 :
172 : /* the following functions are quite similar, but trying to merge them just
173 : * makes a big mess. check the others when touching one.
174 : *
175 : * timestamp keywords hostname
176 : * RFC5424 ISO8601 yes yes
177 : * RFC3164 RFC3164 no yes
178 : * local RFC3164 no no
179 : * journald ISO8601(unused) yes (unused)
180 : */
181 :
182 0 : static size_t zlog_5424_one(struct zlt_5424 *zte, struct zlog_msg *msg,
183 : struct state *state)
184 : {
185 0 : size_t textlen;
186 0 : struct fbuf *fbuf = state->fbuf;
187 0 : char *orig_pos = fbuf->pos;
188 0 : size_t need = 0;
189 0 : int prio = zlog_msg_prio(msg);
190 0 : intmax_t pid, tid;
191 :
192 0 : zlog_msg_pid(msg, &pid, &tid);
193 :
194 0 : need += bprintfrr(fbuf, "<%d>1 ", prio | zte->facility);
195 0 : need += zlog_msg_ts(msg, fbuf, zte->ts_flags);
196 0 : need += bprintfrr(fbuf, " %s %s %jd %.*s ", cmd_hostname_get() ?: "-",
197 0 : zlog_progname, pid, (int)(zlog_prefixsz - 2),
198 : zlog_prefix);
199 :
200 0 : if (zte->kw_version)
201 0 : need += bprintfrr(
202 : fbuf,
203 : "[origin enterpriseId=\"50145\" software=\"FRRouting\" swVersion=\"%s\"]",
204 : FRR_VERSION);
205 :
206 0 : const struct xref_logmsg *xref;
207 0 : struct xrefdata *xrefdata;
208 :
209 0 : need += bprintfrr(fbuf, "[location@50145 tid=\"%jd\"", tid);
210 0 : if (zlog_instance > 0)
211 0 : need += bprintfrr(fbuf, " instance=\"%d\"", zlog_instance);
212 :
213 0 : xref = zlog_msg_xref(msg);
214 0 : xrefdata = xref ? xref->xref.xrefdata : NULL;
215 0 : if (xrefdata) {
216 0 : if (zte->kw_uid)
217 0 : need += bprintfrr(fbuf, " id=\"%s\"", xrefdata->uid);
218 0 : if (zte->kw_ec && prio <= LOG_WARNING)
219 0 : need += bprintfrr(fbuf, " ec=\"%u\"", xref->ec);
220 0 : if (zte->kw_location)
221 0 : need += bprintfrr(
222 : fbuf, " file=\"%s\" line=\"%d\" func=\"%s\"",
223 0 : xref->xref.file, xref->xref.line,
224 0 : xref->xref.func);
225 : }
226 0 : need += bputch(fbuf, ']');
227 :
228 0 : size_t hdrlen, n_argpos;
229 0 : const struct fmt_outpos *argpos;
230 0 : const char *text;
231 :
232 0 : text = zlog_msg_text(msg, &textlen);
233 0 : zlog_msg_args(msg, &hdrlen, &n_argpos, &argpos);
234 :
235 0 : if (zte->kw_args && n_argpos) {
236 0 : need += bputs(fbuf, "[args@50145");
237 :
238 0 : for (size_t i = 0; i < n_argpos; i++) {
239 0 : int len = argpos[i].off_end - argpos[i].off_start;
240 :
241 0 : need += bprintfrr(fbuf, " arg%zu=%*pSQsq", i + 1, len,
242 0 : text + argpos[i].off_start);
243 : }
244 :
245 0 : need += bputch(fbuf, ']');
246 : }
247 :
248 0 : need += bputch(fbuf, ' ');
249 :
250 0 : if (orig_pos + need > fbuf->buf + fbuf->len) {
251 : /* not enough space in the buffer for headers. the loop in
252 : * zlog_5424() will flush other messages that are already in
253 : * the buffer, grab a bigger buffer if needed, and try again.
254 : */
255 0 : fbuf->pos = orig_pos;
256 0 : return need;
257 : }
258 :
259 : /* NB: zlog_5424 below assumes we use max. IOV_PER_MSG iovs here */
260 0 : state->iov->iov_base = orig_pos;
261 0 : state->iov->iov_len = fbuf->pos - orig_pos;
262 0 : state->iov++;
263 :
264 0 : state->iov->iov_base = (char *)text + hdrlen;
265 0 : state->iov->iov_len = textlen - hdrlen + zte->use_nl;
266 0 : state->iov++;
267 0 : return 0;
268 : }
269 :
270 0 : static size_t zlog_3164_one(struct zlt_5424 *zte, struct zlog_msg *msg,
271 : struct state *state)
272 : {
273 0 : size_t textlen;
274 0 : struct fbuf *fbuf = state->fbuf;
275 0 : char *orig_pos = fbuf->pos;
276 0 : size_t need = 0;
277 0 : int prio = zlog_msg_prio(msg);
278 0 : intmax_t pid, tid;
279 :
280 0 : zlog_msg_pid(msg, &pid, &tid);
281 :
282 0 : need += bprintfrr(fbuf, "<%d>", prio | zte->facility);
283 0 : need += zlog_msg_ts_3164(msg, fbuf, zte->ts_flags);
284 0 : if (zte->fmt != ZLOG_FMT_LOCAL) {
285 0 : need += bputch(fbuf, ' ');
286 0 : need += bputs(fbuf, cmd_hostname_get() ?: "-");
287 : }
288 0 : need += bprintfrr(fbuf, " %s[%jd]: ", zlog_progname, pid);
289 :
290 0 : if (orig_pos + need > fbuf->buf + fbuf->len) {
291 : /* not enough space in the buffer for headers. loop in
292 : * zlog_5424() will flush other messages that are already in
293 : * the buffer, grab a bigger buffer if needed, and try again.
294 : */
295 0 : fbuf->pos = orig_pos;
296 0 : return need;
297 : }
298 :
299 : /* NB: zlog_5424 below assumes we use max. IOV_PER_MSG iovs here */
300 0 : state->iov->iov_base = orig_pos;
301 0 : state->iov->iov_len = fbuf->pos - orig_pos;
302 0 : state->iov++;
303 :
304 0 : state->iov->iov_base = (char *)zlog_msg_text(msg, &textlen);
305 0 : state->iov->iov_len = textlen + zte->use_nl;
306 0 : state->iov++;
307 0 : return 0;
308 : }
309 :
310 0 : static size_t zlog_journald_one(struct zlt_5424 *zte, struct zlog_msg *msg,
311 : struct state *state)
312 : {
313 0 : size_t textlen;
314 0 : struct fbuf *fbuf = state->fbuf;
315 0 : char *orig_pos = fbuf->pos;
316 0 : size_t need = 0;
317 0 : int prio = zlog_msg_prio(msg);
318 0 : intmax_t pid, tid;
319 :
320 0 : zlog_msg_pid(msg, &pid, &tid);
321 :
322 0 : need += bprintfrr(fbuf,
323 : "PRIORITY=%d\n"
324 : "SYSLOG_FACILITY=%d\n"
325 : "TID=%jd\n"
326 : "FRR_DAEMON=%s\n"
327 : "SYSLOG_TIMESTAMP=",
328 : prio, zte->facility, tid, zlog_progname);
329 0 : need += zlog_msg_ts(msg, fbuf, zte->ts_flags);
330 0 : need += bputch(fbuf, '\n');
331 0 : if (zlog_instance > 0)
332 0 : need += bprintfrr(fbuf, "FRR_INSTANCE=%d\n", zlog_instance);
333 :
334 0 : const struct xref_logmsg *xref;
335 0 : struct xrefdata *xrefdata;
336 :
337 0 : xref = zlog_msg_xref(msg);
338 0 : xrefdata = xref ? xref->xref.xrefdata : NULL;
339 0 : if (xrefdata) {
340 0 : if (zte->kw_uid && xrefdata->uid[0])
341 0 : need += bprintfrr(fbuf, "FRR_ID=%s\n", xrefdata->uid);
342 0 : if (zte->kw_ec && prio <= LOG_WARNING)
343 0 : need += bprintfrr(fbuf, "FRR_EC=%d\n", xref->ec);
344 0 : if (zte->kw_location)
345 0 : need += bprintfrr(fbuf,
346 : "CODE_FILE=%s\n"
347 : "CODE_LINE=%d\n"
348 : "CODE_FUNC=%s\n",
349 0 : xref->xref.file, xref->xref.line,
350 0 : xref->xref.func);
351 : }
352 :
353 0 : size_t hdrlen, n_argpos;
354 0 : const struct fmt_outpos *argpos;
355 0 : const char *text;
356 :
357 0 : text = zlog_msg_text(msg, &textlen);
358 0 : zlog_msg_args(msg, &hdrlen, &n_argpos, &argpos);
359 :
360 0 : if (zte->kw_args && n_argpos) {
361 0 : for (size_t i = 0; i < n_argpos; i++) {
362 0 : int len = argpos[i].off_end - argpos[i].off_start;
363 :
364 : /* rather than escape the value, we could use
365 : * journald's binary encoding, but that seems a bit
366 : * excessive/unnecessary. 99% of things we print here
367 : * will just output 1:1 with %pSE.
368 : */
369 0 : need += bprintfrr(fbuf, "FRR_ARG%zu=%*pSE\n", i + 1,
370 0 : len, text + argpos[i].off_start);
371 : }
372 : }
373 :
374 0 : need += bputs(fbuf, "MESSAGE=");
375 :
376 0 : if (orig_pos + need > fbuf->buf + fbuf->len) {
377 : /* not enough space in the buffer for headers. loop in
378 : * zlog_5424() will flush other messages that are already in
379 : * the buffer, grab a bigger buffer if needed, and try again.
380 : */
381 0 : fbuf->pos = orig_pos;
382 0 : return need;
383 : }
384 :
385 : /* NB: zlog_5424 below assumes we use max. IOV_PER_MSG iovs here */
386 0 : state->iov->iov_base = orig_pos;
387 0 : state->iov->iov_len = fbuf->pos - orig_pos;
388 0 : state->iov++;
389 :
390 0 : state->iov->iov_base = (char *)text + hdrlen;
391 0 : state->iov->iov_len = textlen - hdrlen + 1;
392 0 : state->iov++;
393 0 : return 0;
394 : }
395 :
396 0 : static size_t zlog_one(struct zlt_5424 *zte, struct zlog_msg *msg,
397 : struct state *state)
398 : {
399 0 : switch (zte->fmt) {
400 0 : case ZLOG_FMT_5424:
401 0 : return zlog_5424_one(zte, msg, state);
402 0 : case ZLOG_FMT_3164:
403 : case ZLOG_FMT_LOCAL:
404 0 : return zlog_3164_one(zte, msg, state);
405 0 : case ZLOG_FMT_JOURNALD:
406 0 : return zlog_journald_one(zte, msg, state);
407 : }
408 : return 0;
409 : }
410 :
411 0 : static void zlog_5424_err(struct zlt_5424 *zte, size_t count)
412 : {
413 0 : if (!count) {
414 0 : zte->current_err = 0;
415 0 : return;
416 : }
417 :
418 : /* only the counter is atomic because otherwise it'd be meaningless */
419 0 : atomic_fetch_add_explicit(&zte->lost_msgs, count, memory_order_relaxed);
420 :
421 : /* these are non-atomic and can provide wrong results when read, but
422 : * since they're only for debugging / display, that's OK.
423 : */
424 0 : zte->current_err = zte->last_err = errno;
425 0 : monotime(&zte->last_err_ts);
426 : }
427 :
428 0 : static void zlog_5424(struct zlog_target *zt, struct zlog_msg *msgs[],
429 : size_t nmsgs)
430 0 : {
431 0 : size_t i;
432 0 : struct zlt_5424 *zte = container_of(zt, struct zlt_5424, zt);
433 0 : int fd, ret;
434 0 : size_t niov = MIN(IOV_PER_MSG * nmsgs, IOV_MAX);
435 0 : struct iovec iov[niov], *iov_last = iov + niov;
436 0 : struct mmsghdr mmsg[zte->packets ? nmsgs : 1], *mpos = mmsg;
437 0 : size_t count = 0;
438 :
439 : /* refer to size estimate at top of file */
440 0 : size_t low_space;
441 0 : char hdr_buf[zlog_5424_bufsz(zte, nmsgs, &low_space)];
442 0 : struct fbuf hdr_pos = {
443 : .buf = hdr_buf,
444 : .pos = hdr_buf,
445 : .len = sizeof(hdr_buf),
446 : };
447 0 : struct state state = {
448 : .fbuf = &hdr_pos,
449 : .iov = iov,
450 : };
451 :
452 0 : fd = atomic_load_explicit(&zte->fd, memory_order_relaxed);
453 :
454 0 : memset(mmsg, 0, sizeof(mmsg));
455 0 : if (zte->sa_len) {
456 0 : for (i = 0; i < array_size(mmsg); i++) {
457 0 : mmsg[i].msg_hdr.msg_name = (struct sockaddr *)&zte->sa;
458 0 : mmsg[i].msg_hdr.msg_namelen = zte->sa_len;
459 : }
460 : }
461 0 : mmsg[0].msg_hdr.msg_iov = iov;
462 :
463 0 : for (i = 0; i < nmsgs; i++) {
464 0 : int prio = zlog_msg_prio(msgs[i]);
465 0 : size_t need = 0;
466 :
467 0 : if (prio <= zte->zt.prio_min) {
468 0 : if (zte->packets)
469 0 : mpos->msg_hdr.msg_iov = state.iov;
470 :
471 0 : need = zlog_one(zte, msgs[i], &state);
472 :
473 0 : if (zte->packets) {
474 0 : mpos->msg_hdr.msg_iovlen =
475 0 : state.iov - mpos->msg_hdr.msg_iov;
476 0 : mpos++;
477 : }
478 0 : count++;
479 : }
480 :
481 : /* clang-format off */
482 0 : if ((need
483 0 : || (size_t)(hdr_pos.buf + hdr_pos.len - hdr_pos.pos)
484 : < low_space
485 0 : || i + 1 == nmsgs
486 0 : || state.iov + IOV_PER_MSG > iov_last)
487 0 : && state.iov > iov) {
488 : /* clang-format on */
489 :
490 0 : if (zte->packets) {
491 : struct mmsghdr *sendpos;
492 :
493 0 : for (sendpos = mmsg; sendpos < mpos;) {
494 0 : ret = sendmmsg(fd, sendpos,
495 0 : mpos - sendpos, 0);
496 0 : if (ret <= 0)
497 : break;
498 0 : sendpos += ret;
499 : }
500 0 : zlog_5424_err(zte, mpos - sendpos);
501 0 : mpos = mmsg;
502 : } else {
503 0 : if (!zte->sa_len)
504 0 : ret = writev(fd, iov, state.iov - iov);
505 : else {
506 0 : mpos->msg_hdr.msg_iovlen =
507 0 : state.iov - iov;
508 0 : ret = sendmsg(fd, &mpos->msg_hdr, 0);
509 : }
510 :
511 0 : if (ret < 0)
512 0 : zlog_5424_err(zte, count);
513 : else
514 0 : zlog_5424_err(zte, 0);
515 : }
516 :
517 0 : count = 0;
518 0 : hdr_pos.pos = hdr_buf;
519 0 : state.iov = iov;
520 : }
521 :
522 : /* if need == 0, we just put a message (or nothing) in the
523 : * buffer and are continuing for more to batch in a single
524 : * writev()
525 : */
526 0 : if (need == 0)
527 0 : continue;
528 :
529 0 : if (need && need <= sizeof(hdr_buf)) {
530 : /* don't need to allocate, just try this msg
531 : * again without other msgs already using up
532 : * buffer space
533 : */
534 0 : i--;
535 0 : continue;
536 : }
537 :
538 : /* need > sizeof(hdr_buf), need to grab some memory. Taking
539 : * it off the stack is fine here.
540 : */
541 0 : char buf2[need];
542 0 : struct fbuf fbuf2 = {
543 : .buf = buf2,
544 : .pos = buf2,
545 : .len = sizeof(buf2),
546 : };
547 :
548 0 : state.fbuf = &fbuf2;
549 0 : need = zlog_one(zte, msgs[i], &state);
550 0 : assert(need == 0);
551 :
552 0 : if (!zte->sa_len)
553 0 : ret = writev(fd, iov, state.iov - iov);
554 : else {
555 0 : mpos->msg_hdr.msg_iovlen = state.iov - iov;
556 0 : ret = sendmsg(fd, &mpos->msg_hdr, 0);
557 : }
558 :
559 0 : if (ret < 0)
560 0 : zlog_5424_err(zte, 1);
561 : else
562 0 : zlog_5424_err(zte, 0);
563 :
564 0 : count = 0;
565 0 : state.fbuf = &hdr_pos;
566 0 : state.iov = iov;
567 0 : mpos = mmsg;
568 : }
569 :
570 0 : assert(state.iov == iov);
571 0 : }
572 :
573 : /* strftime(), gmtime_r() and localtime_r() aren't AS-Safe (they access locale
574 : * data), but we need an AS-Safe timestamp below :(
575 : */
576 0 : static void gmtime_assafe(time_t ts, struct tm *res)
577 : {
578 0 : res->tm_sec = ts % 60;
579 0 : ts /= 60;
580 0 : res->tm_min = ts % 60;
581 0 : ts /= 60;
582 0 : res->tm_hour = ts % 24;
583 0 : ts /= 24;
584 :
585 0 : ts -= 11017; /* start on 2020-03-01, 11017 days since 1970-01-01 */
586 :
587 : /* 1461 days = 3 regular years + 1 leap year
588 : * this works until 2100, which isn't a leap year
589 : *
590 : * struct tm.tm_year starts at 1900.
591 : */
592 0 : res->tm_year = 2000 - 1900 + 4 * (ts / 1461);
593 0 : ts = ts % 1461;
594 :
595 0 : if (ts == 1460) {
596 0 : res->tm_year += 4;
597 0 : res->tm_mon = 1;
598 0 : res->tm_mday = 29;
599 0 : return;
600 : }
601 0 : res->tm_year += ts / 365;
602 0 : ts %= 365;
603 :
604 : /* note we're starting in march like the romans did... */
605 0 : if (ts >= 306) /* Jan 1 of next year */
606 0 : res->tm_year++;
607 :
608 0 : static time_t months[13] = {
609 : 0, 31, 61, 92, 122, 153, 184, 214, 245, 275, 306, 337, 365,
610 : };
611 0 : const size_t month_max = array_size(months) - 1;
612 :
613 0 : for (size_t i = 0; i < month_max; i++) {
614 0 : if (ts < months[i + 1]) {
615 0 : res->tm_mon = ((i + 2) % 12);
616 0 : res->tm_mday = 1 + ts - months[i];
617 0 : break;
618 : }
619 : }
620 : }
621 :
622 : /* one of the greatest advantages of this logging target: unlike syslog(),
623 : * which is not AS-Safe, we can send crashlogs to syslog here.
624 : */
625 0 : static void zlog_5424_sigsafe(struct zlog_target *zt, const char *text,
626 : size_t len)
627 : {
628 0 : static const char *const months_3164[12] = {
629 : "Jan", "Feb", "Mar", "Apr", "May", "Jun",
630 : "Jul", "Aug", "Sep", "Oct", "Nov", "Dec",
631 : };
632 :
633 0 : struct zlt_5424 *zte = container_of(zt, struct zlt_5424, zt);
634 0 : struct iovec iov[3], *iovp = iov;
635 0 : char buf[256];
636 0 : struct fbuf fbuf = {
637 : .buf = buf,
638 : .pos = buf,
639 : .len = sizeof(buf),
640 : };
641 0 : int fd;
642 0 : intmax_t pid = (intmax_t)getpid();
643 0 : struct tm tm;
644 :
645 0 : switch (zte->fmt) {
646 0 : case ZLOG_FMT_5424:
647 0 : gmtime_assafe(time(NULL), &tm);
648 0 : bprintfrr(
649 : &fbuf,
650 : "<%d>1 %04u-%02u-%02uT%02u:%02u:%02uZ - %s %jd %.*s ",
651 0 : zte->facility | LOG_CRIT, tm.tm_year + 1900,
652 0 : tm.tm_mon + 1, tm.tm_mday, tm.tm_hour, tm.tm_min,
653 0 : tm.tm_sec, zlog_progname, pid, (int)(zlog_prefixsz - 2),
654 : zlog_prefix);
655 0 : break;
656 :
657 0 : case ZLOG_FMT_3164:
658 : case ZLOG_FMT_LOCAL:
659 : /* this will unfortuantely be wrong by the timezone offset
660 : * if the user selected non-UTC. But not much we can do
661 : * about that...
662 : */
663 0 : gmtime_assafe(time(NULL), &tm);
664 0 : bprintfrr(&fbuf, "<%d>%3s %2u %02u:%02u:%02u %s%s[%jd]: ",
665 0 : zte->facility | LOG_CRIT, months_3164[tm.tm_mon],
666 : tm.tm_mday, tm.tm_hour, tm.tm_min, tm.tm_sec,
667 0 : (zte->fmt == ZLOG_FMT_LOCAL) ? "" : "- ",
668 : zlog_progname, pid);
669 0 : break;
670 :
671 0 : case ZLOG_FMT_JOURNALD:
672 0 : bprintfrr(&fbuf,
673 : "PRIORITY=%d\n"
674 : "SYSLOG_FACILITY=%d\n"
675 : "FRR_DAEMON=%s\n"
676 : "MESSAGE=",
677 : LOG_CRIT, zte->facility, zlog_progname);
678 0 : break;
679 : }
680 :
681 0 : iovp->iov_base = fbuf.buf;
682 0 : iovp->iov_len = fbuf.pos - fbuf.buf;
683 0 : iovp++;
684 :
685 0 : iovp->iov_base = (char *)text;
686 0 : iovp->iov_len = len;
687 0 : iovp++;
688 :
689 0 : if (zte->use_nl) {
690 0 : iovp->iov_base = (char *)"\n";
691 0 : iovp->iov_len = 1;
692 0 : iovp++;
693 : }
694 :
695 0 : fd = atomic_load_explicit(&zte->fd, memory_order_relaxed);
696 :
697 0 : if (!zte->sa_len)
698 0 : writev(fd, iov, iovp - iov);
699 : else {
700 0 : struct msghdr mh = {};
701 :
702 0 : mh.msg_name = (struct sockaddr *)&zte->sa;
703 0 : mh.msg_namelen = zte->sa_len;
704 0 : mh.msg_iov = iov;
705 0 : mh.msg_iovlen = iovp - iov;
706 0 : sendmsg(fd, &mh, 0);
707 : }
708 0 : }
709 :
710 : /* housekeeping & configuration */
711 :
712 0 : void zlog_5424_init(struct zlog_cfg_5424 *zcf)
713 : {
714 0 : pthread_mutex_init(&zcf->cfg_mtx, NULL);
715 0 : }
716 :
717 0 : static void zlog_5424_target_free(struct zlt_5424 *zlt)
718 : {
719 0 : if (!zlt)
720 : return;
721 :
722 0 : rcu_close(&zlt->head_close, zlt->fd);
723 0 : rcu_free(MTYPE_LOG_5424, zlt, zt.rcu_head);
724 : }
725 :
726 0 : void zlog_5424_fini(struct zlog_cfg_5424 *zcf, bool keepopen)
727 : {
728 0 : if (keepopen)
729 0 : zcf->active = NULL;
730 :
731 0 : if (zcf->active) {
732 0 : struct zlt_5424 *ztf;
733 0 : struct zlog_target *zt;
734 :
735 0 : zt = zlog_target_replace(&zcf->active->zt, NULL);
736 0 : ztf = container_of(zt, struct zlt_5424, zt);
737 0 : zlog_5424_target_free(ztf);
738 : }
739 0 : pthread_mutex_destroy(&zcf->cfg_mtx);
740 0 : }
741 :
742 0 : static void zlog_5424_cycle(struct zlog_cfg_5424 *zcf, int fd)
743 : {
744 0 : struct zlog_target *old;
745 0 : struct zlt_5424 *zlt = NULL, *oldt;
746 :
747 0 : if (fd >= 0) {
748 0 : struct zlog_target *zt;
749 :
750 : /* all of this is swapped in by zlog_target_replace() below,
751 : * the old target is RCU-freed afterwards.
752 : */
753 0 : zt = zlog_target_clone(MTYPE_LOG_5424, &zcf->active->zt,
754 : sizeof(*zlt));
755 0 : zlt = container_of(zt, struct zlt_5424, zt);
756 :
757 0 : zlt->fd = fd;
758 0 : zlt->kw_version = zcf->kw_version;
759 0 : zlt->kw_location = zcf->kw_location;
760 0 : zlt->kw_uid = zcf->kw_uid;
761 0 : zlt->kw_ec = zcf->kw_ec;
762 0 : zlt->kw_args = zcf->kw_args;
763 0 : zlt->use_nl = true;
764 0 : zlt->facility = zcf->facility;
765 :
766 : /* DGRAM & SEQPACKET = 1 log message per packet */
767 0 : zlt->packets = (zcf->sock_type == SOCK_DGRAM) ||
768 : (zcf->sock_type == SOCK_SEQPACKET);
769 0 : zlt->sa = zcf->sa;
770 0 : zlt->sa_len = zcf->sa_len;
771 0 : zlt->fmt = zcf->fmt;
772 0 : zlt->zt.prio_min = zcf->prio_min;
773 0 : zlt->zt.logfn = zlog_5424;
774 0 : zlt->zt.logfn_sigsafe = zlog_5424_sigsafe;
775 :
776 0 : switch (zcf->fmt) {
777 0 : case ZLOG_FMT_5424:
778 : case ZLOG_FMT_JOURNALD:
779 0 : zlt->ts_flags = zcf->ts_flags;
780 0 : zlt->ts_flags &= ZLOG_TS_PREC | ZLOG_TS_UTC;
781 0 : zlt->ts_flags |= ZLOG_TS_ISO8601;
782 0 : break;
783 0 : case ZLOG_FMT_3164:
784 : case ZLOG_FMT_LOCAL:
785 0 : zlt->ts_flags = zcf->ts_flags & ZLOG_TS_UTC;
786 0 : if (zlt->packets)
787 0 : zlt->use_nl = false;
788 : break;
789 : }
790 : }
791 :
792 0 : old = zcf->active ? &zcf->active->zt : NULL;
793 0 : old = zlog_target_replace(old, &zlt->zt);
794 0 : zcf->active = zlt;
795 :
796 : /* oldt->fd == fd happens for zlog_5424_apply_meta() */
797 0 : oldt = container_of(old, struct zlt_5424, zt);
798 0 : if (oldt && oldt->fd != (unsigned int)fd)
799 0 : rcu_close(&oldt->head_close, oldt->fd);
800 0 : rcu_free(MTYPE_LOG_5424, oldt, zt.rcu_head);
801 0 : }
802 :
803 0 : static void zlog_5424_reconnect(struct thread *t)
804 : {
805 0 : struct zlog_cfg_5424 *zcf = THREAD_ARG(t);
806 0 : int fd = THREAD_FD(t);
807 0 : char dummy[256];
808 0 : ssize_t ret;
809 :
810 0 : if (zcf->active) {
811 0 : ret = read(fd, dummy, sizeof(dummy));
812 0 : if (ret > 0) {
813 : /* logger is sending us something?!?! */
814 0 : thread_add_read(t->master, zlog_5424_reconnect, zcf, fd,
815 : &zcf->t_reconnect);
816 0 : return;
817 : }
818 :
819 0 : if (ret == 0)
820 0 : zlog_warn("logging socket %pSE closed by peer",
821 : zcf->filename);
822 : else
823 0 : zlog_warn("logging socket %pSE error: %m",
824 : zcf->filename);
825 : }
826 :
827 : /* do NOT close() anything here; other threads may still be writing
828 : * and their messages need to be lost rather than end up on a random
829 : * other fd that got reassigned the same number, like a BGP session!
830 : */
831 0 : fd = zlog_5424_open(zcf, -1);
832 :
833 0 : frr_with_mutex (&zcf->cfg_mtx) {
834 0 : zlog_5424_cycle(zcf, fd);
835 : }
836 : }
837 :
838 0 : static int zlog_5424_unix(struct sockaddr_un *suna, int sock_type)
839 : {
840 0 : int fd;
841 0 : int size = 1 * 1024 * 1024, prev_size;
842 0 : socklen_t opt_size;
843 0 : int save_errno;
844 :
845 0 : fd = socket(AF_UNIX, sock_type, 0);
846 0 : if (fd < 0)
847 : return -1;
848 :
849 0 : if (connect(fd, (struct sockaddr *)suna, sizeof(*suna))) {
850 : /* zlog_5424_open() will print the error for connect() */
851 0 : save_errno = errno;
852 0 : close(fd);
853 0 : errno = save_errno;
854 0 : return -1;
855 : }
856 :
857 0 : opt_size = sizeof(prev_size);
858 0 : if (getsockopt(fd, SOL_SOCKET, SO_SNDBUF, &prev_size, &opt_size))
859 : return fd;
860 :
861 : /* setsockopt_so_sendbuf() logs on error; we don't really care that
862 : * much here. Also, never shrink the buffer below the initial size.
863 : */
864 0 : while (size > prev_size &&
865 0 : setsockopt(fd, SOL_SOCKET, SO_SNDBUF, &size, sizeof(size)) == -1)
866 0 : size /= 2;
867 :
868 : return fd;
869 : }
870 :
871 0 : static int zlog_5424_open(struct zlog_cfg_5424 *zcf, int sock_type)
872 : {
873 0 : int fd = -1;
874 0 : int flags = 0;
875 0 : int err;
876 0 : socklen_t optlen;
877 0 : bool do_chown = false;
878 0 : bool need_reconnect = false;
879 0 : static const int unix_types[] = {
880 : SOCK_STREAM,
881 : SOCK_SEQPACKET,
882 : SOCK_DGRAM,
883 : };
884 0 : struct sockaddr_un sa;
885 :
886 0 : zcf->sock_type = -1;
887 0 : zcf->sa_len = 0;
888 :
889 0 : switch (zcf->dst) {
890 : case ZLOG_5424_DST_NONE:
891 : break;
892 :
893 0 : case ZLOG_5424_DST_FD:
894 0 : fd = dup(zcf->fd);
895 :
896 0 : optlen = sizeof(sock_type);
897 0 : if (!getsockopt(fd, SOL_SOCKET, SO_TYPE, &sock_type, &optlen)) {
898 0 : zcf->sock_type = sock_type;
899 0 : need_reconnect = (zcf->sock_type != SOCK_DGRAM);
900 : }
901 : break;
902 :
903 0 : case ZLOG_5424_DST_FIFO:
904 0 : if (!zcf->filename)
905 : break;
906 :
907 0 : if (!zcf->file_nocreate) {
908 0 : frr_with_privs (lib_privs) {
909 0 : mode_t prevmask;
910 :
911 0 : prevmask = umask(0777 ^ zcf->file_mode);
912 0 : err = mkfifo(zcf->filename, 0666);
913 0 : umask(prevmask);
914 : }
915 0 : if (err == 0)
916 : do_chown = true;
917 0 : else if (errno != EEXIST)
918 : break;
919 : }
920 :
921 : flags = O_NONBLOCK;
922 : /* fallthru */
923 :
924 0 : case ZLOG_5424_DST_FILE:
925 0 : if (!zcf->filename)
926 : break;
927 :
928 0 : frr_with_privs (lib_privs) {
929 0 : fd = open(zcf->filename, flags | O_WRONLY | O_APPEND |
930 : O_CLOEXEC | O_NOCTTY);
931 : }
932 0 : if (fd >= 0)
933 : break;
934 0 : if (zcf->file_nocreate || flags) {
935 0 : flog_err_sys(EC_LIB_SYSTEM_CALL,
936 : "could not open log file %pSE: %m",
937 : zcf->filename);
938 0 : break;
939 : }
940 :
941 0 : frr_with_privs (lib_privs) {
942 0 : mode_t prevmask;
943 :
944 0 : prevmask = umask(0777 ^ zcf->file_mode);
945 0 : fd = open(zcf->filename,
946 : O_WRONLY | O_APPEND | O_CLOEXEC | O_NOCTTY |
947 : O_CREAT | O_EXCL,
948 : zcf->file_mode);
949 0 : umask(prevmask);
950 : }
951 0 : if (fd >= 0) {
952 : do_chown = true;
953 : break;
954 : }
955 :
956 0 : frr_with_privs (lib_privs) {
957 0 : fd = open(zcf->filename,
958 : O_WRONLY | O_APPEND | O_CLOEXEC | O_NOCTTY);
959 : }
960 0 : if (fd >= 0)
961 : break;
962 :
963 0 : flog_err_sys(EC_LIB_SYSTEM_CALL,
964 : "could not open or create log file %pSE: %m",
965 : zcf->filename);
966 0 : break;
967 :
968 0 : case ZLOG_5424_DST_UNIX:
969 0 : if (!zcf->filename)
970 : break;
971 :
972 0 : memset(&sa, 0, sizeof(sa));
973 0 : sa.sun_family = AF_UNIX;
974 0 : strlcpy(sa.sun_path, zcf->filename, sizeof(sa.sun_path));
975 :
976 : /* check if ZLOG_5424_DST_FD needs a touch when changing
977 : * something here. the user can pass in a pre-opened unix
978 : * socket through a fd at startup.
979 : */
980 0 : frr_with_privs (lib_privs) {
981 0 : if (sock_type != -1)
982 0 : fd = zlog_5424_unix(&sa, sock_type);
983 : else {
984 0 : for (size_t i = 0; i < array_size(unix_types);
985 0 : i++) {
986 0 : fd = zlog_5424_unix(&sa, unix_types[i]);
987 0 : if (fd != -1) {
988 0 : zcf->sock_type = unix_types[i];
989 0 : break;
990 : }
991 : }
992 : }
993 : }
994 0 : if (fd == -1) {
995 0 : zcf->sock_type = -1;
996 :
997 0 : flog_err_sys(
998 : EC_LIB_SYSTEM_CALL,
999 : "could not connect to log unix path %pSE: %m",
1000 : zcf->filename);
1001 0 : need_reconnect = true;
1002 : } else {
1003 : /* datagram sockets are connectionless, restarting
1004 : * the receiver may lose some packets but will resume
1005 : * working afterwards without any action from us.
1006 : */
1007 0 : need_reconnect = (zcf->sock_type != SOCK_DGRAM);
1008 : }
1009 : break;
1010 : }
1011 :
1012 : /* viable on both DST_FD and DST_UNIX path */
1013 0 : if (zcf->sock_type == SOCK_DGRAM) {
1014 0 : zcf->sa_len = sizeof(zcf->sa);
1015 0 : if (getpeername(fd, (struct sockaddr *)&zcf->sa,
1016 : &zcf->sa_len)) {
1017 0 : flog_err_sys(
1018 : EC_LIB_SYSTEM_CALL,
1019 : "could not get remote address for log socket. logging may break if log receiver restarts.");
1020 0 : zcf->sa_len = 0;
1021 : }
1022 : }
1023 :
1024 0 : if (do_chown) {
1025 0 : uid_t uid = zcf->file_uid;
1026 0 : gid_t gid = zcf->file_gid;
1027 :
1028 0 : if (uid != (uid_t)-1 || gid != (gid_t)-1) {
1029 0 : frr_with_privs (lib_privs) {
1030 0 : err = fchown(fd, uid, gid);
1031 : }
1032 0 : if (err)
1033 0 : flog_err_sys(
1034 : EC_LIB_SYSTEM_CALL,
1035 : "failed to chown() log file %pSE: %m",
1036 : zcf->filename);
1037 : }
1038 : }
1039 :
1040 0 : if (need_reconnect) {
1041 0 : assert(zcf->master);
1042 :
1043 0 : if (fd != -1) {
1044 0 : thread_add_read(zcf->master, zlog_5424_reconnect, zcf,
1045 : fd, &zcf->t_reconnect);
1046 0 : zcf->reconn_backoff_cur = zcf->reconn_backoff;
1047 :
1048 : } else {
1049 0 : thread_add_timer_msec(zcf->master, zlog_5424_reconnect,
1050 : zcf, zcf->reconn_backoff_cur,
1051 : &zcf->t_reconnect);
1052 :
1053 0 : zcf->reconn_backoff_cur += zcf->reconn_backoff_cur / 2;
1054 0 : if (zcf->reconn_backoff_cur > zcf->reconn_backoff_max)
1055 0 : zcf->reconn_backoff_cur =
1056 : zcf->reconn_backoff_max;
1057 : }
1058 : }
1059 :
1060 0 : return fd;
1061 : }
1062 :
1063 0 : bool zlog_5424_apply_dst(struct zlog_cfg_5424 *zcf)
1064 : {
1065 0 : int fd = -1;
1066 :
1067 0 : thread_cancel(&zcf->t_reconnect);
1068 :
1069 0 : if (zcf->prio_min != ZLOG_DISABLED)
1070 0 : fd = zlog_5424_open(zcf, -1);
1071 :
1072 0 : frr_with_mutex (&zcf->cfg_mtx) {
1073 0 : zlog_5424_cycle(zcf, fd);
1074 : }
1075 0 : return fd != -1;
1076 : }
1077 :
1078 :
1079 0 : bool zlog_5424_apply_meta(struct zlog_cfg_5424 *zcf)
1080 : {
1081 0 : frr_with_mutex (&zcf->cfg_mtx) {
1082 0 : if (zcf->active)
1083 0 : zlog_5424_cycle(zcf, zcf->active->fd);
1084 : }
1085 :
1086 0 : return true;
1087 : }
1088 :
1089 0 : void zlog_5424_state(struct zlog_cfg_5424 *zcf, size_t *lost_msgs,
1090 : int *last_errno, bool *stale_errno, struct timeval *err_ts)
1091 : {
1092 0 : if (lost_msgs)
1093 0 : *lost_msgs =
1094 0 : zcf->active
1095 0 : ? atomic_load_explicit(&zcf->active->lost_msgs,
1096 : memory_order_relaxed)
1097 0 : : 0;
1098 0 : if (last_errno)
1099 0 : *last_errno = zcf->active ? zcf->active->last_err : 0;
1100 0 : if (stale_errno)
1101 0 : *stale_errno = zcf->active ? !zcf->active->current_err : 0;
1102 0 : if (err_ts && zcf->active)
1103 0 : *err_ts = zcf->active->last_err_ts;
1104 0 : }
1105 :
1106 : struct rcu_close_rotate {
1107 : struct rcu_head_close head_close;
1108 : struct rcu_head head_self;
1109 : };
1110 :
1111 0 : bool zlog_5424_rotate(struct zlog_cfg_5424 *zcf)
1112 : {
1113 0 : struct rcu_close_rotate *rcr;
1114 0 : int fd;
1115 :
1116 0 : frr_with_mutex (&zcf->cfg_mtx) {
1117 0 : if (!zcf->active)
1118 : return true;
1119 :
1120 0 : thread_cancel(&zcf->t_reconnect);
1121 :
1122 : /* need to retain the socket type because it also influences
1123 : * other fields (packets) and we can't atomically swap these
1124 : * out. But we really want the atomic swap so we neither lose
1125 : * nor duplicate log messages, particularly for file targets.
1126 : *
1127 : * (zlog_5424_apply_dst / zlog_target_replace will cause
1128 : * duplicate log messages if another thread logs something
1129 : * while we're right in the middle of swapping out the log
1130 : * target)
1131 : */
1132 0 : fd = zlog_5424_open(zcf, zcf->sock_type);
1133 0 : if (fd < 0)
1134 : return false;
1135 :
1136 0 : fd = atomic_exchange_explicit(&zcf->active->fd,
1137 : (uint_fast32_t)fd,
1138 : memory_order_relaxed);
1139 : }
1140 :
1141 0 : rcr = XCALLOC(MTYPE_LOG_5424_ROTATE, sizeof(*rcr));
1142 0 : rcu_close(&rcr->head_close, fd);
1143 0 : rcu_free(MTYPE_LOG_5424_ROTATE, rcr, head_self);
1144 :
1145 0 : return true;
1146 : }
|
