On Sat, Mar 8, 2025 at 9:26 PM Sergei Golubchik <serg@mariadb.org> wrote:

Hi, Alexey,

See few comments below.

But the main question, could you have used FILE or IO_CACHE instead of a
custom implementation?

On Mar 08, Alexey Botchkov wrote:
> revision-id: b7dbe187b1a (mariadb-11.8.1-8-gb7dbe187b1a)
> parent(s): 6f1161aa34c
> author: Alexey Botchkov
> committer: Alexey Botchkov
> timestamp: 2025-03-02 16:27:23 +0400
> message:
>
> MDEV-34680 Asynchronous and Buffered Logging for Audit Plugin.
>
> Buffering added to the file logger.
> Two buffers are created so writing to the file doesn't
> block other threads from logging.
> Operations isolated with two mutexes.

> diff --git a/include/mysql/service_logger.h b/include/mysql/service_logger.h
> index 35c2eb1e3a9..adce7bc9038 100644
> --- a/include/mysql/service_logger.h
> +++ b/include/mysql/service_logger.h
> @@ -64,41 +64,44 @@ extern struct logger_service_st {
> void (*logger_init_mutexes)();
> LOGGER_HANDLE* (*open)(const char *path,
> unsigned long long size_limit,
> - unsigned int rotations);
> + unsigned int rotations, size_t buffer_size);

incompatible API change. MUST change the major service version.

> int (*close)(LOGGER_HANDLE *log);
> int (*vprintf)(LOGGER_HANDLE *log, const char *fmt, va_list argptr)
> ATTRIBUTE_FORMAT_FPTR(printf, 2, 0);
> int (*printf)(LOGGER_HANDLE *log, const char *fmt, ...)
> ATTRIBUTE_FORMAT_FPTR(printf, 2, 3);
> - int (*write)(LOGGER_HANDLE *log, const char *buffer, size_t size);
> + int (*write)(LOGGER_HANDLE *log, const void *data, size_t size);
> int (*rotate)(LOGGER_HANDLE *log);
> + int (*sync)(LOGGER_HANDLE *log);
> } *logger_service;
>
> #ifdef MYSQL_DYNAMIC_PLUGIN
>
> #define logger_init_mutexes logger_service->logger_init_mutexes
> -#define logger_open(path, size_limit, rotations) \
> - (logger_service->open(path, size_limit, rotations))
> +#define logger_open(path, size_limit, rotations, buffer_size) \
> + (logger_service->open(path, size_limit, rotations, buffer_size))
> #define logger_close(log) (logger_service->close(log))
> #define logger_rotate(log) (logger_service->rotate(log))
> +#define logger_rsync(log) (logger_service->sync(log))
> #define logger_vprintf(log, fmt, argptr) (logger_service->\
> vprintf(log, fmt, argptr))
> #define logger_printf (*logger_service->printf)
> -#define logger_write(log, buffer, size) \
> - (logger_service->write(log, buffer, size))
> +#define logger_write(log, data, size) \
> + (logger_service->write(log, data, size))
> #else
>
> void logger_init_mutexes();
> LOGGER_HANDLE *logger_open(const char *path,
> unsigned long long size_limit,
> - unsigned int rotations);
> + unsigned int rotations, size_t buffer_size);
> int logger_close(LOGGER_HANDLE *log);
> int logger_vprintf(LOGGER_HANDLE *log, const char *fmt, va_list argptr)
> ATTRIBUTE_FORMAT(printf, 2, 0);
> int logger_printf(LOGGER_HANDLE *log, const char *fmt, ...)
> ATTRIBUTE_FORMAT(printf, 2, 3);
> - int logger_write(LOGGER_HANDLE *log, const char *buffer, size_t size);
> + int logger_write(LOGGER_HANDLE *log, const void *data, size_t size);
> int logger_rotate(LOGGER_HANDLE *log);
> + int logger_sync(LOGGER_HANDLE *log);
> #endif
>
>
> diff --git a/mysys/file_logger.c b/mysys/file_logger.c
> index a753c049f68..5464e43eddf 100644
> --- a/mysys/file_logger.c
> +++ b/mysys/file_logger.c
> @@ -145,85 +230,108 @@ static int do_rotate(LOGGER_HANDLE *log)
> namebuf[log->path_len]= 0;
> result= my_rename(namebuf, logname(log, log->path, 1), MYF(0));
> log->file= my_open(namebuf, LOG_FLAGS, MYF(0));
> + log->in_file= 0;
> exit:
> errno= my_errno;
> return log->file < 0 || result;
> }
>
>
> -/*
> - Return 1 if we should rotate the log
> -*/
> -
> -my_bool logger_time_to_rotate(LOGGER_HANDLE *log)
> -{
> - my_off_t filesize;
> - if (log->rotations > 0 &&
> - (filesize= my_tell(log->file, MYF(0))) != (my_off_t) -1 &&
> - ((ulonglong) filesize >= log->size_limit))
> - return 1;
> - return 0;
> -}
> -
> -
> int logger_vprintf(LOGGER_HANDLE *log, const char* fmt, va_list ap)
> {
> - int result;
> char cvtbuf[1024];
> size_t n_bytes;
>
> - flogger_mutex_lock(&log->lock);
> - if (logger_time_to_rotate(log) && do_rotate(log))
> - {
> - result= -1;
> - errno= my_errno;
> - goto exit; /* Log rotation needed but failed */
> - }
> -
> n_bytes= my_vsnprintf(cvtbuf, sizeof(cvtbuf), fmt, ap);
> if (n_bytes >= sizeof(cvtbuf))
> n_bytes= sizeof(cvtbuf) - 1;
>
> - result= (int)my_write(log->file, (uchar *) cvtbuf, n_bytes, MYF(0));
> -
> -exit:
> - flogger_mutex_unlock(&log->lock);
> - return result;
> + return logger_write(log, cvtbuf, n_bytes);
> }
>
>
> -static int logger_write_r(LOGGER_HANDLE *log, my_bool allow_rotations,
> - const char *buffer, size_t size)
> +int logger_write(LOGGER_HANDLE *log, const void *data, size_t size)
> {
> int result;
> + size_t in_buffer;
> +
> + mysql_mutex_lock(&log->lock);
>
> - flogger_mutex_lock(&log->lock);
> - if (allow_rotations && logger_time_to_rotate(log) && do_rotate(log))
> + if (log->buffer_left >= size)
> + {
> + memcpy(log->buffer_pos, data, size);
> + log->buffer_pos+= size;
> + log->buffer_left-= size;
> + mysql_mutex_unlock(&log->lock);
> + return size;
> + }
> +
> + mysql_mutex_lock(&log->lock_buffer);
> +
> + in_buffer= log->buffer_pos - log->buffer;
> +
> + { /* swap buffers. */
> + uchar *tmp_buf= log->buffer;
> + log->buffer= log->idle_buffer;
> + log->idle_buffer= tmp_buf;
> + }
> +
> + set_buffer_pos_and_left(log);
> +
> + /* Now other threads can write to the new buffer. */
> + mysql_mutex_unlock(&log->lock);
> +
> + if ((in_buffer &&
> + my_write(log->file, log->idle_buffer, in_buffer, MYF(0)) != in_buffer)||
> + my_write(log->file, (uchar *) data, size, MYF(0)) != size)
> {
> result= -1;
> errno= my_errno;
> - goto exit; /* Log rotation needed but failed */
> + goto exit_buf;
> }
> + else
> + result= 0;
>
> - result= (int)my_write(log->file, (uchar *) buffer, size, MYF(0));
> + log->in_file+= in_buffer + size;
> + if (log->rotations > 0 && log->in_file >= log->size_limit)
> + {
> + if (do_rotate(log))
> + {
> + result= -1;
> + errno= my_errno;
> + goto exit_buf; /* Log rotation needed but failed */
> + }
> + }
>
> -exit:
> - flogger_mutex_unlock(&log->lock);
> +exit_buf:
> + mysql_mutex_unlock(&log->lock_buffer);
> return result;
> }
>
>
> -int logger_write(LOGGER_HANDLE *log, const char *buffer, size_t size)
> -{
> - return logger_write_r(log, TRUE, buffer, size);
> -}
> -
> int logger_rotate(LOGGER_HANDLE *log)
> {
> int result;
> - flogger_mutex_lock(&log->lock);
> - result= do_rotate(log);
> - flogger_mutex_unlock(&log->lock);
> + mysql_mutex_lock(&log->lock);
> + mysql_mutex_lock(&log->lock_buffer);
> + result= flush_buffer(log) || do_rotate(log);

I'd though you can switch buffers here too and flush/rotate
only under the lock_buffer mutex

> + mysql_mutex_unlock(&log->lock_buffer);
> + mysql_mutex_unlock(&log->lock);
> + return result;
> +}
> +
> +
> +int logger_sync(LOGGER_HANDLE *log)

Why did you introduce an explicit sync API?

> +{
> + int result;
> + mysql_mutex_lock(&log->lock);
> + mysql_mutex_lock(&log->lock_buffer);
> + if ((result= flush_buffer(log)))
> + {
> + result= fsync(log->file);
> + }
> + mysql_mutex_unlock(&log->lock_buffer);
> + mysql_mutex_unlock(&log->lock);
> return result;
> }
>
> diff --git a/plugin/server_audit/server_audit.c b/plugin/server_audit/server_audit.c
> index 5fc0e3373f3..e51df7ab6b5 100644
> --- a/plugin/server_audit/server_audit.c
> +++ b/plugin/server_audit/server_audit.c
> @@ -1393,26 +1401,15 @@ static void change_connection(struct connection_info *cn,
> static int write_log(const char *message, size_t len, int take_lock)
> {
> int result= 0;
> +
> if (take_lock)
> - {
> - /* Start by taking a read lock */
> mysql_prlock_rdlock(&lock_operations);
> - }
>
> if (output_type == OUTPUT_FILE)
> {
> if (logfile)
> {
> - my_bool allow_rotate= !take_lock; /* Allow rotate if caller write lock */
> - if (take_lock && logger_time_to_rotate(logfile))
> - {
> - /* We have to rotate the log, change above read lock to write lock */
> - mysql_prlock_unlock(&lock_operations);
> - mysql_prlock_wrlock(&lock_operations);
> - allow_rotate= 1;
> - }
> - if (!(is_active= (logger_write_r(logfile, allow_rotate, message, len) ==
> - (int) len)))
> + if (!(is_active= (logger_write(logfile, message, len) == (int) len)))

nice, rotation is indeed the logger's headache, not the caller's

> {
> ++log_write_failures;
> result= 1;
> @@ -2899,6 +2906,36 @@ static void update_file_rotations(MYSQL_THD thd __attribute__((unused)),
> }
>
>
> +static void update_file_buffer_size(MYSQL_THD thd __attribute__((unused)),
> + struct st_mysql_sys_var *var __attribute__((unused)),
> + void *var_ptr __attribute__((unused)), const void *save)
> +{
> + file_buffer_size= *(unsigned int *) save;
> +
> + error_header();
> + fprintf(stderr, "Log file buffer size was changed to '%d'.\n", file_buffer_size);
> +
> + if (!logging || output_type != OUTPUT_FILE)
> + return;
> +
> + ADD_ATOMIC(internal_stop_logging, 1);
> + if (!maria_55_started || !debug_server_started)
> + mysql_prlock_wrlock(&lock_operations);
> +
> + stop_logging();
> + if (start_logging())

this could be an API call in the logger. Like "reinit(new params)"
and it'll close, change params, open - all under a log mutex, which doesn't
need to be destroyed and reinitialized.

> + {
> + error_header();
> + fprintf(stderr, "Logging was disabled..\n");
> + CLIENT_ERROR(1, "Logging was disabled.", MYF(ME_WARNING));
> + }
> +
> + if (!maria_55_started || !debug_server_started)
> + mysql_prlock_unlock(&lock_operations);
> + ADD_ATOMIC(internal_stop_logging, -1);
> +}
> +
> +
> static void update_file_rotate_size(MYSQL_THD thd __attribute__((unused)),
> struct st_mysql_sys_var *var __attribute__((unused)),
> void *var_ptr __attribute__((unused)), const void *save)

Regards,
Sergei
Chief Architect, MariaDB Server
and security@mariadb.org