File: log_sink_buffer.cc

package info (click to toggle)
mysql-8.0 8.0.45-1
  • links: PTS, VCS
  • area: main
  • in suites: sid
  • size: 1,273,048 kB
  • sloc: cpp: 4,685,434; ansic: 412,712; pascal: 108,396; java: 83,641; perl: 30,221; cs: 27,067; sql: 26,594; python: 21,816; sh: 17,285; yacc: 17,169; php: 11,522; xml: 7,388; javascript: 7,083; makefile: 1,793; lex: 1,075; awk: 670; asm: 520; objc: 183; ruby: 97; lisp: 86
file content (473 lines) | stat: -rw-r--r-- 19,280 bytes parent folder | download
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
414
415
416
417
418
419
420
421
422
423
424
425
426
427
428
429
430
431
432
433
434
435
436
437
438
439
440
441
442
443
444
445
446
447
448
449
450
451
452
453
454
455
456
457
458
459
460
461
462
463
464
465
466
467
468
469
470
471
472
473
/* Copyright (c) 2020, 2025, Oracle and/or its affiliates.

This program is free software; you can redistribute it and/or modify
it under the terms of the GNU General Public License, version 2.0,
as published by the Free Software Foundation.

This program is designed to work with certain software (including
but not limited to OpenSSL) that is licensed under separate terms,
as designated in a particular file or component or in included license
documentation.  The authors of MySQL hereby grant you an additional
permission to link the program and your derivative works with the
separately licensed software that they have either included with
the program or referenced in the documentation.

This program is distributed in the hope that it will be useful,
but WITHOUT ANY WARRANTY; without even the implied warranty of
MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
GNU General Public License, version 2.0, for more details.

You should have received a copy of the GNU General Public License
along with this program; if not, write to the Free Software
Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301  USA */

/**
  @file log_sink_buffer.cc

  This file contains

  a) the log-sink that buffers errors logged during start-up so they
  can be flushed once all configured log-components have become available;

  b) the functions for querying and setting the phase the server is in
  with regard to logging (buffering, normal operation, and so forth);

  c) the functions for flushing the buffered information (to force writing
  out this information in cases of early shutdowns and so on).
*/

#include "log_sink_buffer.h"
#include <mysql/components/services/log_shared.h>  // data types
#include "log_builtins_filter_imp.h"
#include "log_sink_trad.h"
#include "my_systime.h"  // my_micro_time()
#include "mysql/psi/mysql_mutex.h"
#include "sql/log.h"
#include "sql/psi_memory_key.h"  // key_memory_log_error_stack
#include "sql/server_component/log_builtins_internal.h"

/**
  Make sure only one instance of the buffered "writer" runs at a time.

  In normal operation, the log-event will be created dynamically, then
  it will be fed through the pipeline, and then it will be released.
  Since the event is allocated in the caller, we can be sure it won't
  go away wholesale during processing, and since the event is local to
  the caller, no other thread will tangle with it. It is therefore safe
  in those cases not to wrap a lock around the event.
  (The log-pipeline will still grab a shared lock, THR_LOCK_log_stack,
  to protect the pipeline (not the event) and the log-services cache from
  being changed while the pipeline is being applied.
  Likewise, log-services may protect their resources (file-writers will
  usually take a lock to serialize their writes; the built-in filter will
  take a lock on its rule-set as that is shared between concurrent
  threads running the filter, and so on).
  None of these are intended to protect the event itself though.

  In buffered mode on the other hand, we copy each log-event (the
  original of which, see above, is owned by the caller and local
  to the thread, and therefore safe without locking) to a global
  buffer / backlog. As this backlog can be added to by all threads,
  it must be protected by a lock (once we have fully initialized
  the subsystem with log_builtins_init() and support multi-threaded
  mode anyway, as indicated by log_builtins_started being non-zero,
  see below). This is that lock.
*/
mysql_mutex_t THR_LOCK_log_buffered;

/// Pointer to the first element in the list of buffered log messages
static log_line_buffer *log_line_buffer_start = nullptr;
/// Where to write the pointer to the newly-created tail-element of the list
static log_line_buffer **log_line_buffer_tail = &log_line_buffer_start;

/**
  Timestamp of the last event we put into the error-log buffer
  during buffered mode (while starting up). New items must
  receive a LOG_ITEM_LOG_BUFFERED timestamp greater than this.
*/
static ulonglong log_sink_buffer_latest_buffered = 0;

/**
  Duplicate a log-event. This is a deep copy where the items (key/value pairs)
  have their own allocated memory separate from that in the source item.

  @param   dst    log_line that will hold the copy
  @param   src    log_line we copy from

  @retval  false  on success
  @retval  true   if out of memory
*/
static bool log_line_duplicate(log_line *dst, log_line *src) {
  int c;

  assert((dst != nullptr) && (src != nullptr));

  *dst = *src;

  for (c = 0; c < src->count; c++) {
    dst->item[c].alloc = LOG_ITEM_FREE_NONE;

    if ((dst->item[c].key =
             my_strndup(key_memory_log_error_loaded_services, src->item[c].key,
                        strlen(src->item[c].key), MYF(0))) != nullptr) {
      // We just allocated a key, remember to free it later:
      dst->item[c].alloc = LOG_ITEM_FREE_KEY;

      // If the value is a string, duplicate it, and remember to free it later!
      if (log_item_string_class(src->item[c].item_class) &&
          (src->item[c].data.data_string.str != nullptr)) {
        if ((dst->item[c].data.data_string.str = my_strndup(
                 key_memory_log_error_loaded_services,
                 src->item[c].data.data_string.str,
                 src->item[c].data.data_string.length, MYF(0))) != nullptr)
          dst->item[c].alloc |= LOG_ITEM_FREE_VALUE;
        else
          goto fail; /* purecov: inspected */
      }
    } else
      goto fail; /* purecov: inspected */
  }

  return false;

fail:                           /* purecov: begin inspected */
  dst->count = c + 1;           // consider only the items we actually processed
  log_line_item_free_all(dst);  // free those items
  return true;                  // flag failure
  /* purecov: end */
}

/**
  services: log sinks: buffered logging

  During start-up, we buffer log-info until a) we have basic info for
  the built-in logger (what file to log to, verbosity, and so on), and
  b) advanced info (any logging components to load, any configuration
  for them, etc.).

  As a failsafe, if start-up takes very, very long, and a time-out is
  reached before reaching b) and we actually have something worth
  reporting (e.g. errors, as opposed to info), we try to keep the user
  informed by using the basic logger configured in a), while going on
  buffering all info and flushing it to any advanced loggers when b)
  is reached.

  1) This function checks and, if needed, updates the time-out, and calls
     the flush functions as needed. It is internal to the logger and should
     not be called from elsewhere.

  2) Function will save log-event (if given) for later filtering and output.

  3) Function acquires/releases THR_LOCK_log_buffered if initialized.

  @param           instance             instance handle
                                        Not currently used in this writer;
                                        if this changes later, keep in mind
                                        that nullptr will be passed if this
                                        is called before the structured
                                        logger's locks are initialized, so
                                        that must remain a valid argument!
  @param           ll                   The log line to write,
                                        or nullptr to not add a new logline,
                                        but to just check whether the time-out
                                        has been reached and if so, flush
                                        as needed.

  @retval          -1                   can not add event to buffer (OOM?)
  @retval          >0                   number of added fields
*/
int log_sink_buffer(void *instance [[maybe_unused]], log_line *ll) {
  log_line_buffer *llb = nullptr;  ///< log-line buffer
  ulonglong now = 0;
  int count = 0;

  /*
    If we were actually given an event, add it to the buffer.
  */
  if (ll != nullptr) {
    if ((llb = (log_line_buffer *)my_malloc(key_memory_log_error_stack,
                                            sizeof(log_line_buffer), MYF(0))) ==
        nullptr)
      return -1; /* purecov: inspected */

    llb->next = nullptr;

    /*
      Don't let the submitter free the keys/values; we'll do it later when
      the buffer is flushed and then de-allocated!
      (No lock needed for copy as the target-event is still private to this
      function, and the source-event is alloc'd in the caller so will be
      there at least until we return.)
    */
    log_line_duplicate(&llb->ll, ll);
  }

  /*
    Insert the new last event into the buffer
    (a singly linked list of events).
  */
  if (log_builtins_started()) mysql_mutex_lock(&THR_LOCK_log_buffered);

  now = my_micro_time();

  if (ll != nullptr) {
    /*
      Prevent two events from receiving the exact same timestamp on
      systems with low resolution clocks.
    */
    if (now > log_sink_buffer_latest_buffered)
      log_sink_buffer_latest_buffered = now;
    else
      log_sink_buffer_latest_buffered++;

    /*
      Save the current time so we can regenerate the textual timestamp
      later when we have the command-line options telling us what format
      it should be in (e.g. UTC or system time).
    */
    if (!log_line_full(&llb->ll)) {
      log_line_item_set(&llb->ll, LOG_ITEM_LOG_BUFFERED)->data_integer =
          log_sink_buffer_latest_buffered;
    }

    *log_line_buffer_tail = llb;
    log_line_buffer_tail = &(llb->next);

    /*
      Save the element-count now as the time-out flush below may release
      the underlying log line buffer, llb, making that info inaccessible.
    */
    count = llb->ll.count;
  }

  if (log_builtins_started()) mysql_mutex_unlock(&THR_LOCK_log_buffered);

  return count;
}

/*
  Release all buffered log-events (discard_error_log_messages()),
  optionally after running them through the error log stack first
  (flush_error_log_messages()). Safe to call repeatedly (though
  subsequent calls will only output anything if further events
  occurred after the previous flush).
*/
void log_sink_buffer_flush(enum log_sink_buffer_flush_mode mode) {
  log_line_buffer *llp, *local_head, *local_tail = nullptr;

  /*
    "steal" public list of buffered log events

    The general mechanism is that we move the buffered events from
    the global list to one local to this function, iterate over
    it, and then put it back. If anything was added to the global
    list we emptied while were working, we append the new items
    from the global list to the end of the "stolen" list, and then
    make that union the new global list. The grand idea here is
    that this way, we only have to acquire a lock very briefly
    (while updating the global list's head and tail, once for
    "stealing" it, once for giving it back), rather than holding
    a lock the entire time, or locking each event individually,
    while still remaining safe if one caller starts a
    flush-with-print, and then another runs a flush-to-delete
    that might catch up and cause trouble if we neither held
    a lock nor stole the list.
  */

  /*
    If the lock hasn't been init'd yet, don't get it.
  */
  if (log_builtins_started()) mysql_mutex_lock(&THR_LOCK_log_buffered);

  local_head = log_line_buffer_start;             // save list head
  log_line_buffer_start = nullptr;                // empty public list
  log_line_buffer_tail = &log_line_buffer_start;  // adjust tail of public list

  if (log_builtins_started()) mysql_mutex_unlock(&THR_LOCK_log_buffered);

  // get head element from list of buffered log events
  llp = local_head;

  while (llp != nullptr) {
    /*
      Forward the buffered lines to log-writers
      (other than the buffered writer), unless
      we're in "discard" mode, in which case,
      we'll just throw the information away.
    */
    if (mode != LOG_BUFFER_DISCARD_ONLY) {
      // Fetch integer timestamp of when we buffered the event.
      ulonglong now = 0;
      int index_buff = log_line_index_by_type(&llp->ll, LOG_ITEM_LOG_BUFFERED);

      if (index_buff >= 0) now = llp->ll.item[index_buff].data.data_integer;

      // We failed to set a timestamp earlier (OOM?). Use current time!
      if (now == 0) now = my_micro_time(); /* purecov: inspected */

      DBUG_EXECUTE_IF("log_error_normalize", { now = 0; });

      // Regenerate timestamp with the correct options.
      char local_time_buff[iso8601_size];
      make_iso8601_timestamp(local_time_buff, now,
                             iso8601_sysvar_logtimestamps);
      char *date = my_strndup(key_memory_log_error_stack, local_time_buff,
                              strlen(local_time_buff) + 1, MYF(0));

      if (date != nullptr) {
        int index_time =
            log_line_index_by_type(&llp->ll, LOG_ITEM_LOG_TIMESTAMP);

        if (index_time >= 0) {
          // release old timestamp value
          if (llp->ll.item[index_time].alloc & LOG_ITEM_FREE_VALUE) {
            my_free(const_cast<char *>(
                llp->ll.item[index_time].data.data_string.str));
          }
          // set new timestamp value
          llp->ll.item[index_time].data.data_string.str = date;
          llp->ll.item[index_time].data.data_string.length = strlen(date);
          llp->ll.item[index_time].alloc |= LOG_ITEM_FREE_VALUE;
        } else if (!log_line_full(&llp->ll)) { /* purecov: begin inspected */
          // set all new timestamp key/value pair; we didn't previously have one
          // This shouldn't happen unless we run out of space during submit()!
          log_item_data *d =
              log_line_item_set(&llp->ll, LOG_ITEM_LOG_TIMESTAMP);
          if (d != nullptr) {
            d->data_string.str = date;
            d->data_string.length = strlen(d->data_string.str);
            llp->ll.item[llp->ll.count - 1].alloc |= LOG_ITEM_FREE_VALUE;
          } else
            my_free(date);  // couldn't create key/value pair for timestamp
        } else
          my_free(date);  // log_line is full
      }                   /* purecov: end */

      /*
        If no log-service is configured (because log_builtins_init()
        hasn't run and initialized the log-pipeline), or if the
        log-service is the buffered writer (which is only available
        internally and used during start-up), it's still early in the
        start-up sequence, so we may not have all configured external
        log-components yet. Therefore, and since this is a fallback
        only, we ignore the configuration and use the built-in services
        that we know are available, on the grounds that when something
        goes wrong, information with undesired formatting is still
        better than not knowing about the issue at all.
      */
      if ((log_error_stage_get() != LOG_ERROR_STAGE_COMPONENTS) &&
          (log_error_stage_get() != LOG_ERROR_STAGE_COMPONENTS_AND_PFS)) {
        /*
          This is a fallback used when the user's log_error_services
          has not been made active yet (and loadable logging-components
          have not been loaded yet).

          In fallback modes, we run with default settings and
          services.
        */

        // LOG_BUFFER_PROCESS_AND_DISCARD

        /*
          This is a fallback used primarily when start-up is aborted.

          If we get here, flush_error_log_messages() was called
          before logging came out of buffered mode. (If it was
          called after buffered modes completes, we should land
          in the following branch instead.)

          We're asked to print all log-info so far using basic
          logging, and to then throw it away (rather than keep
          it around for proper logging). This usually implies
          that we're shutting down because some unrecoverable
          situation has arisen during start-up, so a) the user
          needs to know about it even if full logging (as
          configured) is not available yet, and b) we'll shut
          down before we'll ever get full logging, so keeping
          the info around is pointless.
        */

        if (log_filter_builtin_rules != nullptr)
          log_builtins_filter_run(log_filter_builtin_rules, &llp->ll);

        log_sink_trad(nullptr, &llp->ll);
      } else {  // no longer buffering
        /*
          If we get here, logging has left the buffered phase, and
          we can write out the log-events using the configuration
          requested by the user, as it should be!
        */
        log_line_submit(&llp->ll);  // frees keys + values (but not llp itself)
        goto kv_freed;              // skip freeing of keys + values
      }
    }

    log_line_item_free_all(&local_head->ll);  // free key/value pairs
  kv_freed:
    local_head = local_head->next;  // delist event
    my_free(llp);                   // free buffered event
    llp = local_head;
  }  // while (any_more_buffered_events_to_process)

  if (log_builtins_started()) mysql_mutex_lock(&THR_LOCK_log_buffered);

  /*
    At this point, if (local_head == nullptr), we either didn't have
    a list to begin with, or we just emptied the local version.
    Since we also emptied the global version at the top, whatever's
    in there now (still empty, or new events attached while we were
    processing) is now authoritative, and no change is needed here.

    If local_head is non-NULL, we started with a non-empty local list
    and mode was KEEP. In that case, we merge the local list back into
    the global one:
  */

  if (local_head != nullptr) {
    /*
      Since local_head was non-NULL, we started with a non-empty
      (local) list. Therefore, local_tail should point at the last
      element in that list (as it is only allowed to be NULL if
      the list is empty).
    */
    assert(local_tail != nullptr);

    /*
      Append global list to end of local list. If global list is still
      empty, the global tail pointer points at the global anchor, so
      we set the global tail pointer to the next-pointer in last stolen
      item. If global list was non-empty, the tail pointer already
      points at the correct element's next-pointer (the correct element
      being the last one in the global list, as we'll append the
      global list to the end of the local list).
    */
    if ((local_tail->next = log_line_buffer_start) == nullptr)
      log_line_buffer_tail = &local_tail->next;

    /*
      Return the stolen list, with any log-events that happened while
      we were processing appended to its end.
    */
    log_line_buffer_start = local_head;
  }

  if (log_builtins_started()) mysql_mutex_unlock(&THR_LOCK_log_buffered);
}

/**
  Prepend a list of log-events to the already buffered events.

  @param[in]  head  Head of the list to prepend to the main list
  @param[out] tail  Pointer to the `next` pointer in last element to prepend
*/
void log_sink_buffer_prepend_list(log_line_buffer *head,
                                  log_line_buffer **tail) {
  if ((head == nullptr) || (tail == nullptr)) return;

  mysql_mutex_lock(&THR_LOCK_log_buffered);

  *tail = log_line_buffer_start;
  log_line_buffer_start = head;

  mysql_mutex_unlock(&THR_LOCK_log_buffered);
}