src/libdlogutil/logretrieve.c

   1 /*  MIT License
   2  *
   3  * Copyright (c) 2019-2020 Samsung Electronics Co., Ltd
   4  *
   5  * Permission is hereby granted, free of charge, to any person obtaining a copy
   6  * of this software and associated documentation files (the "Software"), to deal
   7  * in the Software without restriction, including without limitation the rights
   8  * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
   9  * copies of the Software, and to permit persons to whom the Software is furnished
  10  * to do so, subject to the following conditions:
  11  *
  12  * The above copyright notice and this permission notice shall be included in all
  13  * copies or substantial portions of the Software.
  14  *
  15  * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
  16  * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
  17  * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
  18  * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
  19  * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
  20  * OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN
  21  * THE SOFTWARE. */
  22
  23 // DLog
  24 #include <dlogutil-internal.h>
  25 #include <queued_entry_timestamp.h>
  26
  27 #include "fdi_pipe.h"
  28 #include "fdi_logger.h"
  29 #include "fdi_zero_copy.h"
  30 #include "logretrieve.h"
  31
  32 // C
  33 #include <assert.h>
  34 #include <limits.h>
  35
  36 static const struct fd_ops *get_ops_by_buffer(size_t buf_id, int enabled_buffers, backend_t backend, bool is_compressed_memory)
  37 {
  38         if (!bit_test(enabled_buffers, buf_id))
  39                 return NULL;
  40
  41         /* These are implemented by the pipe daemon,
  42          * regardless of the nominal backend. */
  43         if (is_compressed_memory
  44         || buf_id == LOG_ID_KMSG
  45         || buf_id == LOG_ID_SYSLOG)
  46                 return &ops_pipe;
  47
  48         switch (backend) {
  49         case BACKEND_PIPE          : return &ops_pipe;
  50         case BACKEND_ANDROID_LOGGER: return &ops_logger;
  51         case BACKEND_ZERO_COPY     : return &ops_zero_copy;
  52         default                    : return NULL;
  53         }
  54 }
  55
  56 static size_t get_required_fdi_capacity(const struct fd_ops *ops_by_buffer[static LOG_ID_MAX])
  57 {
  58         size_t ret = 1; // NULL terminator
  59         for (size_t i = 0; i < LOG_ID_MAX; ++i)
  60                 if (ops_by_buffer[i])
  61                         ++ ret;
  62         return ret;
  63 }
  64
  65 int create_initial_fdis(struct fd_info ***fdis, int enabled_buffers, backend_t backend, bool is_compressed_memory, const struct log_config *conf, log_id_t aliased[LOG_ID_MAX])
  66 {
  67         assert(fdis);
  68         assert(conf);
  69         assert(backend != BACKEND_NONE);
  70         assert(backend != BACKEND_NULL);
  71
  72         const struct fd_ops *ops_by_buffer[LOG_ID_MAX];
  73         for (size_t i = 0; i < NELEMS(ops_by_buffer); ++i)
  74                 ops_by_buffer[i] = get_ops_by_buffer(i, enabled_buffers, backend, is_compressed_memory);
  75
  76         int fdi_cnt = 0;
  77         __attribute__((cleanup(fdi_array_free))) struct fd_info **fdi_ptrs = calloc(get_required_fdi_capacity(ops_by_buffer), sizeof *fdi_ptrs);
  78         if (!fdi_ptrs)
  79                 return TIZEN_ERROR_OUT_OF_MEMORY;
  80
  81         __attribute__ ((cleanup(list_clear_free_contents))) list_head used_paths = NULL;
  82
  83         for (int i = 0; i < LOG_ID_MAX; ++i) {
  84                 const struct fd_ops *const ops = ops_by_buffer[i];
  85                 if (!ops)
  86                         continue;
  87
  88                 struct fd_info *const fdi = fdi_create(ops, i);
  89                 if (!fdi)
  90                         return -ENOMEM;
  91
  92                 int r = fdi->ops->create(fdi, conf, i, &used_paths, &aliased[i]);
  93                 if (r == 0)
  94                         aliased[i] = i;
  95                 if (r < 0) {
  96                         // TODO: Inform about that again somewhere else (except if r == -EALREADY and aliased[i] != INVALID)
  97                         fdi_free(fdi);
  98                         continue;
  99                 }
 100                 fdi_ptrs[fdi_cnt++] = fdi;
 101         }
 102
 103         if (fdi_cnt == 0)
 104                 return -EINVAL; // TODO: This has literally nothing to do with EINVAL
 105
 106         *fdis = fdi_ptrs;
 107         fdi_ptrs = NULL;
 108
 109         return fdi_cnt;
 110 }
 111
 112 struct fd_info *find_earliest_log(struct fd_info **data_fds, int fd_count, dlogutil_sorting_order_e sort_by)
 113 {
 114         assert(data_fds);
 115
 116         struct fd_info *best_fdi = NULL;
 117         struct timespec best_ts = {};
 118
 119         for (int i = 0; i < fd_count; ++i) {
 120                 struct fd_info *const fdi = data_fds[i];
 121                 if (!fdi || !fdi->ops->has_log(fdi))
 122                         continue;
 123
 124                 const dlogutil_entry_s *const le = fdi->ops->peek_entry(fdi);
 125                 struct timespec current_ts;
 126                 if (dlogutil_entry_get_timestamp(le, sort_by, &current_ts) != TIZEN_ERROR_NONE)
 127                         return fdi; // the timestampless log is always the best choice to flush ASAP
 128
 129                 if (best_fdi && ((current_ts.tv_sec > best_ts.tv_sec) || (current_ts.tv_sec == best_ts.tv_sec && current_ts.tv_nsec > best_ts.tv_nsec)))
 130                         continue;
 131
 132                 best_ts = current_ts;
 133                 best_fdi = fdi;
 134         }
 135
 136         return best_fdi;
 137 }
 138
 139 int put_logs_into_vector(struct fd_info **data_fds, int fd_count, struct sort_vector *logs, struct log_filter *filter, bool limited_dump, bool *at_least_one_buffer_drained, bool *all_buffers_empty, dlogutil_entry_s **entry_out)
 140 {
 141         assert(data_fds);
 142         assert(logs);
 143         assert(filter);
 144         assert(entry_out);
 145         assert(!*entry_out);
 146
 147         struct fd_info *best_fdi;
 148         do {
 149                 best_fdi = find_earliest_log(data_fds, fd_count, logs->sort_by);
 150                 if (!best_fdi) {
 151                         *all_buffers_empty = true;
 152                         *at_least_one_buffer_drained = true;
 153                         return TIZEN_ERROR_NONE;
 154                 }
 155
 156                 int r = fdi_push_log(best_fdi, logs, limited_dump, entry_out, filter);
 157                 if (r)
 158                         return r;
 159                 if (*entry_out) {
 160                         if (!limited_dump) {
 161                                 if (!best_fdi->ops->has_log(best_fdi))
 162                                         *at_least_one_buffer_drained = true;
 163                                 return TIZEN_ERROR_NONE;
 164                         }
 165
 166                         free(*entry_out);
 167                         *entry_out = NULL;
 168                 }
 169         } while (best_fdi->ops->has_log(best_fdi)); // if a buffer got drained, break to give them all a chance to refill
 170
 171         *at_least_one_buffer_drained = true;
 172         return TIZEN_ERROR_NONE;
 173 }
 174
 175 static int state_prepare_single_print(dlogutil_state_s *state, int nfds, char *compress)
 176 {
 177         assert(state);
 178         assert(state->mode != DLOGUTIL_MODE_NONPRINTING);
 179
 180         int r = state->data_fds[nfds]->ops->prepare_print(state->data_fds[nfds], state->dump_size, state->mode == DLOGUTIL_MODE_MONITOR, state->filter_object, compress);
 181         if (r < 0)
 182                 return TIZEN_ERROR_IO_ERROR;
 183         if (r > 0) {
 184                 // everything went fine, but we're not printing this one
 185                 fdi_free(state->data_fds[nfds]);
 186                 state->data_fds[nfds] = NULL;
 187                 return TIZEN_ERROR_NONE;
 188         }
 189
 190         int fd = state->data_fds[nfds]->fd;
 191         r = fd_set_flags(fd, O_NONBLOCK);
 192         if (r < 0)
 193                 return TIZEN_ERROR_IO_ERROR;
 194         struct epoll_event ev = {
 195                 .data.ptr = state->data_fds[nfds],
 196                 .events = EPOLLIN,
 197         };
 198         state->enabled[nfds] = true;
 199
 200         if (!state->data_fds[nfds]->ops->poll_timeout) {
 201                 epoll_ctl(state->epollfd, EPOLL_CTL_ADD, fd, &ev);
 202                 ++ state->epoll_cnt;
 203         } else {
 204                 ++ state->non_epoll_cnt;
 205         }
 206
 207         return TIZEN_ERROR_NONE;
 208 }
 209
 210 static int state_prepare_prints(dlogutil_state_s *state, char *compress)
 211 {
 212         assert(state);
 213         assert(state->mode != DLOGUTIL_MODE_NONPRINTING);
 214
 215         state->enabled = calloc(state->fd_count, sizeof *state->enabled);
 216         if (!state->enabled)
 217                 return TIZEN_ERROR_OUT_OF_MEMORY;
 218
 219         for (int nfds = 0; nfds < state->fd_count; ++nfds) {
 220                 int r = state_prepare_single_print(state, nfds, compress);
 221                 if (r != TIZEN_ERROR_NONE)
 222                         return r;
 223         }
 224
 225         return TIZEN_ERROR_NONE;
 226 }
 227
 228 int dlogutil_state_init(dlogutil_state_s *state, struct fd_info ***data_fds_ptr, int fd_count, dlogutil_config_s *config, bool sorting_needed, dlogutil_sorting_order_e real_sort_by, const struct log_config *conf, log_id_t aliased[LOG_ID_MAX])
 229 {
 230         assert(data_fds_ptr);
 231         struct fd_info **data_fds = *data_fds_ptr;
 232         assert(data_fds);
 233         assert(conf);
 234         assert(aliased);
 235
 236         // TODO: optimize mode == DLOGUTIL_MODE_NONPRINTING case
 237         state->epollfd = -1;
 238         state->epoll_cnt = 0;
 239         state->non_epoll_cnt = 0;
 240         state->enabled = NULL;
 241         state->filter_object = NULL;
 242         state->evs = NULL;
 243         state->fd_count = fd_count;
 244         state->data_fds = data_fds;
 245         state->mode = config->mode;
 246         state->need_epoll = true;
 247         state->flush_target = LONG_MAX;
 248         state->dump_size = (config->mode == DLOGUTIL_MODE_DUMP) ? config->dump_size : 0;
 249         *data_fds_ptr = NULL;
 250
 251         for (int i = 0; i < LOG_ID_MAX; ++i)
 252                 state->aliased[i] = aliased[i];
 253
 254         sort_vector_init(&state->logs);
 255
 256         state->epollfd = epoll_create1(0);
 257         if (state->epollfd < 0)
 258                 return TIZEN_ERROR_IO_ERROR;
 259
 260         state->filter_object = log_filter_from_filter(&config->filter);
 261         if (!state->filter_object)
 262                 return TIZEN_ERROR_OUT_OF_MEMORY;
 263         if (log_filter_need_apply_default(state->filter_object) && log_filter_set_filterspec(state->filter_object, "*:D"))
 264                 return TIZEN_ERROR_OUT_OF_MEMORY;
 265
 266         sort_vector_apply_config(&state->logs, conf);
 267         state->logs.size = sorting_needed ? config->logs_size : 0;
 268         state->logs.sort_by = real_sort_by;
 269         clock_gettime(get_proper_clock(real_sort_by), &state->logs.start);
 270
 271         if (config->mode == DLOGUTIL_MODE_DUMP && state->dump_size != DLOGUTIL_MAX_DUMP_SIZE)
 272                 state->logs.size = state->dump_size + 1;
 273
 274         if (!sort_vector_finalize(&state->logs))
 275                 return TIZEN_ERROR_OUT_OF_MEMORY;
 276
 277         if (state->mode != DLOGUTIL_MODE_NONPRINTING) {
 278                 int r = state_prepare_prints(state, config->compress);
 279                 if (r != TIZEN_ERROR_NONE)
 280                         return r;
 281         }
 282
 283         if (state->epoll_cnt) {
 284                 state->evs = calloc(state->epoll_cnt, sizeof *state->evs);
 285                 if (!state->evs)
 286                         return TIZEN_ERROR_OUT_OF_MEMORY;
 287         }
 288
 289         return TIZEN_ERROR_NONE;
 290 }
 291
 292 static bool flush_single_log(dlogutil_state_s *state, dlogutil_entry_s **out)
 293 {
 294         assert(!*out);
 295
 296         if (state->flush_target >= LONG_MAX
 297         ||  sort_vector_empty(&state->logs))
 298                 return false;
 299
 300         dlogutil_entry_s *const e = sort_vector_back(&state->logs);
 301         struct timespec log_ts;
 302         if (!dlogutil_entry_get_timestamp(e, state->logs.sort_by, &log_ts)
 303         && log_ts.tv_sec * 1000 + log_ts.tv_nsec / 1000000 > state->flush_target)
 304                 return false;
 305
 306         *out = sort_vector_pop_ret(&state->logs);
 307         return true;
 308 }
 309
 310 static bool handle_flush(dlogutil_state_s *state, dlogutil_entry_s **out)
 311 {
 312         assert(!*out);
 313
 314         bool const r = flush_single_log(state, out);
 315         if (!r)
 316                 state->flush_target = LONG_MAX;
 317         return r;
 318 }
 319
 320 static void remove_drained_buffers(dlogutil_state_s *state)
 321 {
 322         assert(state->enabled);
 323
 324         /* Instead of removing buffers when .read returns 0, we do it
 325          * in a separate loop, using their .eof "method". This is because
 326          * removing buffers that way would fail if EOF would be triggered
 327          * somewhere else and the buffer would never be .read again. */
 328
 329         for (int i = 0; i < state->fd_count; ++i) {
 330                 if (!state->enabled[i])
 331                         continue;
 332
 333                 const struct fd_info *const fdi = state->data_fds[i];
 334                 if (!fdi->ops->eof(fdi))
 335                         continue;
 336
 337                 state->enabled[i] = false;
 338
 339                 if (!fdi->ops->poll_timeout) {
 340                         epoll_ctl(state->epollfd, EPOLL_CTL_DEL, fdi->fd, NULL);
 341                         -- state->epoll_cnt;
 342                 } else {
 343                         -- state->non_epoll_cnt;
 344                 }
 345         }
 346 }
 347
 348 static int refill_fdi_buffers_regular(dlogutil_state_s *state, int timeout)
 349 {
 350         if (!state->epoll_cnt)
 351                 return 0;
 352
 353         int const nfds = epoll_wait(state->epollfd, state->evs, state->epoll_cnt, timeout);
 354         if (nfds < 0)
 355                 return -errno;
 356
 357         for (int i = 0; i < nfds; ++i) {
 358                 struct fd_info *const fdi = state->evs[i].data.ptr;
 359                 int const rd = fdi->ops->read(fdi);
 360                 if (rd < 0 && rd != -EAGAIN)
 361                         return rd;
 362         }
 363
 364         return 0;
 365 }
 366
 367 static int how_long_would_we_have_to_wait(dlogutil_state_s *state)
 368 {
 369         /* Pick the smallest timeout. We're using epoll timeout
 370          * convention where -1 means infinite. This is mostly
 371          * for future-proofing since the only client using this
 372          * is the zero-copy backend which only has 1 FDI anyway. */
 373
 374         int ret = -1;
 375         for (int i = 0; i < state->fd_count; ++i) {
 376                 if (!state->enabled[i])
 377                         continue;
 378
 379                 const struct fd_info *const fdi = state->data_fds[i];
 380                 if (fdi->ops->eof(fdi))
 381                         continue;
 382
 383                 const int timeout = fdi->ops->poll_timeout(fdi);
 384                 if (timeout != -1 && (timeout < ret || ret == -1))
 385                         ret = timeout;
 386         }
 387         return ret;
 388 }
 389
 390 static int refill_fdi_buffers_special(dlogutil_state_s *state, int timeout)
 391 {
 392         if (!state->non_epoll_cnt)
 393                 return 0;
 394
 395         /* Figure out how long we would have to wait. Sleep until then, or at least
 396          * as long as we are allowed to (can't always pull off an all-nighter). */
 397         int needed_timeout = how_long_would_we_have_to_wait(state);
 398         if (needed_timeout > timeout && timeout != -1) {
 399                 usleep(timeout * USEC_PER_MSEC);
 400                 return 0;
 401         }
 402
 403         // FIXME: can the sleep be interrupted via signals etc?
 404         // also FIXME: can `needed_timeout` be -1 at this point?
 405
 406         usleep(needed_timeout * USEC_PER_MSEC);
 407         for (int i = 0; i < state->fd_count; ++i) {
 408                 if (!state->enabled[i])
 409                         continue;
 410
 411                 struct fd_info *const fdi = state->data_fds[i];
 412                 if (fdi->ops->eof(fdi))
 413                         continue;
 414
 415                 int const rd = fdi->ops->read(fdi);
 416                 if (rd < 0 && rd != -EAGAIN)
 417                         return rd;
 418         }
 419
 420         return 0;
 421 }
 422
 423 static int refill_fdi_buffers(dlogutil_state_s *state, int timeout)
 424 {
 425         int r;
 426
 427         /* Both of the two modes below perform a timeout-limited
 428          * sleep; they can't both do it at the same time or we
 429          * would exceed the timeout. Fortunately they don't live
 430          * together, so we can assume only one of the two will run. */
 431         assert(state->non_epoll_cnt == 0 || state->epoll_cnt == 0);
 432
 433         /* Regular file descriptors are handled via a collective epoll
 434          * to minimize the number of performed syscalls. */
 435         r = refill_fdi_buffers_regular(state, timeout);
 436         if (r)
 437                 return r;
 438
 439         /* Special needs file descriptors have their own
 440          * means of figuring out if they're ready to refill. */
 441         r = refill_fdi_buffers_special(state, timeout);
 442         if (r)
 443                 return r;
 444
 445         return 0;
 446 }
 447
 448 static void set_flush_target(dlogutil_state_s *state, bool all_buffers_empty, long last_log_age)
 449 {
 450         /* For the dumping modes, don't flush since that just removes the
 451          * ability to sort flushed and incoming logs against each other. */
 452         if (state->mode == DLOGUTIL_MODE_DUMP)
 453                 return;
 454
 455         /* The oldest log can be so fresh as to be from the future
 456          * (i.e. has a negative age). This can happen when somebody
 457          * changes the realtime clock backwards. In that case let
 458          * such logs be force-flushed immediately since the realtime
 459          * timestamp has lost its meaning and the monotonic timestamp
 460          * might not be present. Otherwise the log would wait until
 461          * the clock reaches its old value again. */
 462         if (last_log_age < 0) {
 463                 state->flush_target = -1;
 464                 return;
 465         }
 466
 467         /* If all buffers got drained, we make the assumption that any logs
 468          * yet to come would sort later than the ones we already have, so
 469          * we can reasonably flush in that case.
 470          *
 471          * Otherwise, wait until the first burst of logs gets processed
 472          * before flushing anything based on the timeout. Approximately all
 473          * logs from the initial burst are old enough to be flushable right
 474          * when they appear, but we want to wait a bit (through the second
 475          * condition, which ends when the initial burst is processed fully)
 476          * to make extra sure they're sorted correctly against each other. */
 477         if (!all_buffers_empty && (!state->logs.old_logs_dumped || last_log_age < state->logs.timeout))
 478                 return;
 479
 480         struct timespec reference_ts;
 481         clock_gettime(get_proper_clock(state->logs.sort_by), &reference_ts);
 482         state->flush_target = reference_ts.tv_sec * 1000 + reference_ts.tv_nsec / 1000000 - state->logs.timeout;
 483 }
 484
 485 static int get_timeout(dlogutil_state_s *state, int timeout, long last_log_age)
 486 {
 487         if (sort_vector_empty(&state->logs))
 488                 return timeout;
 489
 490         int max_timeout = state->logs.timeout - last_log_age;
 491         if (max_timeout < 0)
 492                 return 0;
 493         else
 494                 return timeout == -1 || timeout > max_timeout ? max_timeout : timeout;
 495 }
 496
 497 /**
 498  * @brief Handle input
 499  * @details The main loop reading log data
 500  * @param[in] data_fds An array of FDs to read data from
 501  * @param[in] fd_count Size of the above array
 502  * @param[in] logs The log sorting vector
 503  * @param[in] l_file File output metadata
 504  * @return int 0 if successful, a negative value on error, callback's return value if it isn't 0
 505  */
 506 int do_print_once(dlogutil_state_s *state, int timeout, dlogutil_entry_s **out)
 507 {
 508         assert(!*out);
 509
 510         struct timespec now = { .tv_nsec = -1 };
 511         int end_at = -1;
 512         if (timeout != -1) {
 513                 clock_gettime(CLOCK_MONOTONIC, &now);
 514                 end_at = now.tv_sec * 1000 + now.tv_nsec / 1000000 + timeout;
 515         }
 516
 517         const bool is_limited_dumping = state->mode == DLOGUTIL_MODE_DUMP
 518                 && state->dump_size != DLOGUTIL_MAX_DUMP_SIZE;
 519
 520         while (state->epoll_cnt > 0 || state->non_epoll_cnt > 0) {
 521                 /* Note: sort_vector_time_span assumes that either now.tv_nsec == -1,
 522                  * or now is the current CLOCK_MONOTONIC timestamp. If you change the clock,
 523                  * make sure to change that function! */
 524                 const long last_log_age = sort_vector_time_span(&state->logs, now);
 525                 timeout = get_timeout(state, timeout, last_log_age);
 526
 527                 if (state->need_epoll) {
 528                         int r = refill_fdi_buffers(state, timeout);
 529                         if (r < 0)
 530                                 return TIZEN_ERROR_IO_ERROR;
 531                         state->need_epoll = false;
 532                 }
 533
 534                 if (handle_flush(state, out))
 535                         return TIZEN_ERROR_NONE;
 536
 537                 bool all_buffers_empty = false;
 538                 int r = put_logs_into_vector(state->data_fds, state->fd_count, &state->logs, state->filter_object, is_limited_dumping, &state->need_epoll, &all_buffers_empty, out);
 539
 540                 /* Putting logs into the vector can cause extra reads,
 541                  * which means a buffer might have gotten drained here
 542                  * and not at the regular refill stage. */
 543                 remove_drained_buffers(state);
 544
 545                 if (r < 0)
 546                         return r;
 547
 548                 set_flush_target(state, all_buffers_empty, last_log_age);
 549
 550                 if (*out)
 551                         return TIZEN_ERROR_NONE;
 552                 else if (end_at != -1) {
 553                         clock_gettime(CLOCK_MONOTONIC, &now);
 554                         if (end_at <= now.tv_sec * 1000 + now.tv_nsec / 1000000)
 555                                 return TIZEN_ERROR_TIMED_OUT;
 556                 } else
 557                         assert(now.tv_nsec == -1); // Could be now.tv_nsec = 1, but this is slightly faster
 558         }
 559
 560         int r;
 561         bool all_buffers_empty;
 562         do {
 563                 all_buffers_empty = false;
 564                 r = put_logs_into_vector(state->data_fds, state->fd_count, &state->logs, state->filter_object, is_limited_dumping, &state->need_epoll, &all_buffers_empty, out);
 565         } while (r == 0 && !all_buffers_empty && !*out);
 566         if (r < 0)
 567                 return r;
 568         if (*out)
 569                 return TIZEN_ERROR_NONE;
 570
 571         if (is_limited_dumping)
 572                 while (sort_vector_used_size(&state->logs) > state->dump_size)
 573                         sort_vector_pop(&state->logs);
 574
 575         if (!sort_vector_empty(&state->logs)) {
 576                 *out = sort_vector_pop_ret(&state->logs);
 577                 return TIZEN_ERROR_NONE;
 578         }
 579
 580         return TIZEN_ERROR_NO_DATA;
 581 }
 582