Merge lp:~sergei.glushchenko/percona-server/5.5-ps-bug1363370 into lp:percona-server/5.5

Proposed by Sergei Glushchenko on 2014-09-01
Status: Merged
Approved by: Laurynas Biveinis on 2014-09-26
Approved revision: 692
Merged at revision: 701
Proposed branch: lp:~sergei.glushchenko/percona-server/5.5-ps-bug1363370
Merge into: lp:percona-server/5.5
Diff against target: 235 lines (+78/-26)
8 files modified
mysql-test/r/audit_log_rotate.result (+1/-0)
mysql-test/t/audit_log_rotate-master.opt (+8/-0)
mysql-test/t/audit_log_rotate.test (+29/-0)
plugin/audit_log/audit_file.c (+10/-6)
plugin/audit_log/buffer.c (+7/-8)
plugin/audit_log/buffer.h (+3/-1)
plugin/audit_log/file_logger.c (+14/-10)
plugin/audit_log/logger.h (+6/-1)
To merge this branch: bzr merge lp:~sergei.glushchenko/percona-server/5.5-ps-bug1363370
Reviewer Review Type Date Requested Status
Laurynas Biveinis (community) 2014-09-01 Approve on 2014-09-26
Review via email: mp+232842@code.launchpad.net

Description of the change

Bug 1363370: Audit plugin rotates file in middle of audit

Audit record can be split between two files when logging is done to
file with ASYNCHRONOUS strategy and log rotation turned on.

The cause is that logging is done via ring buffer and log record in
the buffer can be wrapped at the end of the buffer. Incomplete
record will be written into log file. If file is exceeded the size
limit, it will be rotated splitting the record into two files.

Fix is to let the log write function to know that record is
incomplete so it will skip log rotation.

http://jenkins.percona.com/view/PS%205.5/job/percona-server-5.5-param/1042/

To post a comment you must log in.

fprintf(stderr, "debug foo") left in

review: Needs Fixing

    - The testcase needs to count that the actual audit files present >= 2, or
      it will pass the same if the log rotate does not happen at all.

review: Needs Fixing

Hi Laurynas,

Added condition for files count into the test case
http://jenkins.percona.com/view/PS%205.5/job/percona-server-5.5-param/1052/

review: Approve

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1=== added file 'mysql-test/r/audit_log_rotate.result'
2--- mysql-test/r/audit_log_rotate.result 1970-01-01 00:00:00 +0000
3+++ mysql-test/r/audit_log_rotate.result 2014-09-26 08:34:49 +0000
4@@ -0,0 +1,1 @@
5+success
6
7=== added file 'mysql-test/t/audit_log_rotate-master.opt'
8--- mysql-test/t/audit_log_rotate-master.opt 1970-01-01 00:00:00 +0000
9+++ mysql-test/t/audit_log_rotate-master.opt 2014-09-26 08:34:49 +0000
10@@ -0,0 +1,8 @@
11+$AUDIT_LOG_OPT
12+$AUDIT_LOG_LOAD
13+--audit_log_file=test_audit.log
14+--audit_log_format=JSON
15+--audit_log_strategy=ASYNCHRONOUS
16+--audit_log_rotate_on_size=4096
17+--audit_log_buffer_size=5000
18+--audit_log_rotations=10
19
20=== added file 'mysql-test/t/audit_log_rotate.test'
21--- mysql-test/t/audit_log_rotate.test 1970-01-01 00:00:00 +0000
22+++ mysql-test/t/audit_log_rotate.test 2014-09-26 08:34:49 +0000
23@@ -0,0 +1,29 @@
24+--source include/not_embedded.inc
25+
26+let $MYSQLD_DATADIR= `select @@datadir`;
27+let MYSQLD_DATADIR= $MYSQLD_DATADIR;
28+
29+--disable_result_log
30+--disable_query_log
31+--source include/audit_log_events.inc
32+--source include/audit_log_events.inc
33+--source include/audit_log_events.inc
34+--source include/audit_log_events.inc
35+--enable_query_log
36+--enable_result_log
37+
38+perl;
39+ eval "use JSON qw(decode_json); 1" or exit 0;
40+ my @files = glob ($ENV{'MYSQLD_DATADIR'} . "/test_audit.log.*");
41+ foreach (@files) {
42+ open my $file, $_ or die "Could not open log: $!";
43+ while (my $line = <$file>) {
44+ decode_json($line);
45+ }
46+ close $file;
47+ }
48+ die "Rotation doesn't wrok!" unless scalar(@files) > 1
49+EOF
50+--remove_files_wildcard $MYSQLD_DATADIR test_audit.log*
51+
52+--echo success
53
54=== modified file 'plugin/audit_log/audit_file.c'
55--- plugin/audit_log/audit_file.c 2014-07-30 19:36:26 +0000
56+++ plugin/audit_log/audit_file.c 2014-09-26 08:34:49 +0000
57@@ -39,7 +39,8 @@
58 int audit_handler_file_close(audit_handler_t *handler);
59 static
60 int audit_handler_file_write_nobuf(LOGGER_HANDLE *logger,
61- const char *buf, size_t len);
62+ const char *buf, size_t len,
63+ log_record_state_t state);
64 static
65 int audit_handler_file_write_buf(audit_log_buffer_t *buffer,
66 const char *buf, size_t len);
67@@ -48,14 +49,15 @@
68 audit_handler_option_t opt, void *val);
69
70 static
71-int write_callback(void *data, const char *buf, size_t len)
72+int write_callback(void *data, const char *buf, size_t len,
73+ log_record_state_t state)
74 {
75 audit_handler_t *handler= (audit_handler_t *) data;
76 audit_handler_file_data_t *hdata= (audit_handler_file_data_t*) handler->data;
77
78 DBUG_ASSERT(hdata->struct_size == sizeof(audit_handler_file_data_t));
79
80- return audit_handler_file_write_nobuf(hdata->logger, buf, len);
81+ return audit_handler_file_write_nobuf(hdata->logger, buf, len, state);
82 }
83
84
85@@ -106,9 +108,10 @@
86
87 static
88 int audit_handler_file_write_nobuf(LOGGER_HANDLE *logger,
89- const char *buf, size_t len)
90+ const char *buf, size_t len,
91+ log_record_state_t state)
92 {
93- return logger_write(logger, buf, len);
94+ return logger_write(logger, buf, len, state);
95 }
96
97 static
98@@ -135,7 +138,8 @@
99 else
100 {
101 DBUG_ASSERT(data->logger);
102- res= audit_handler_file_write_nobuf(data->logger, buf, len);
103+ res= audit_handler_file_write_nobuf(data->logger, buf, len,
104+ LOG_RECORD_COMPLETE);
105
106 if (data->sync_on_write)
107 {
108
109=== modified file 'plugin/audit_log/buffer.c'
110--- plugin/audit_log/buffer.c 2014-04-21 12:07:45 +0000
111+++ plugin/audit_log/buffer.c 2014-09-26 08:34:49 +0000
112@@ -73,26 +73,25 @@
113 mysql_mutex_unlock(&log->mutex);
114 log->write_func(log->write_func_data,
115 log->buf + log->flush_pos,
116- log->size - log->flush_pos);
117+ log->size - log->flush_pos,
118+ LOG_RECORD_INCOMPLETE);
119 mysql_mutex_lock(&log->mutex);
120 log->flush_pos= 0;
121 log->write_pos%= log->size;
122- DBUG_ASSERT(log->write_pos >= log->flush_pos);
123- mysql_cond_broadcast(&log->flushed_cond);
124- mysql_mutex_unlock(&log->mutex);
125 }
126 else
127 {
128 size_t flushlen= log->write_pos - log->flush_pos;
129 mysql_mutex_unlock(&log->mutex);
130 log->write_func(log->write_func_data,
131- log->buf + log->flush_pos, flushlen);
132+ log->buf + log->flush_pos, flushlen,
133+ LOG_RECORD_COMPLETE);
134 mysql_mutex_lock(&log->mutex);
135 log->flush_pos+= flushlen;
136- DBUG_ASSERT(log->write_pos >= log->flush_pos);
137- mysql_cond_broadcast(&log->flushed_cond);
138- mysql_mutex_unlock(&log->mutex);
139 }
140+ DBUG_ASSERT(log->write_pos >= log->flush_pos);
141+ mysql_cond_broadcast(&log->flushed_cond);
142+ mysql_mutex_unlock(&log->mutex);
143 }
144
145
146
147=== modified file 'plugin/audit_log/buffer.h'
148--- plugin/audit_log/buffer.h 2014-07-30 19:36:26 +0000
149+++ plugin/audit_log/buffer.h 2014-09-26 08:34:49 +0000
150@@ -19,6 +19,7 @@
151 #define AUDIT_LOG_BUFFER_INCLUDED
152
153 #include <string.h> // for size_t
154+#include "logger.h"
155
156 #ifdef __cplusplus
157 extern "C" {
158@@ -26,7 +27,8 @@
159
160 typedef struct audit_log_buffer audit_log_buffer_t;
161
162-typedef int (*audit_log_write_func)(void *data, const char *buf, size_t len);
163+typedef int (*audit_log_write_func)(void *data, const char *buf, size_t len,
164+ log_record_state_t state);
165
166 audit_log_buffer_t *audit_log_buffer_init(size_t size, int drop_if_full,
167 audit_log_write_func write_func, void *data);
168
169=== modified file 'plugin/audit_log/file_logger.c'
170--- plugin/audit_log/file_logger.c 2014-05-23 16:14:27 +0000
171+++ plugin/audit_log/file_logger.c 2014-09-26 08:34:49 +0000
172@@ -279,24 +279,28 @@
173 }
174
175
176-int logger_write(LOGGER_HANDLE *log, const char *buffer, size_t size)
177+int logger_write(LOGGER_HANDLE *log, const char *buffer, size_t size,
178+ log_record_state_t state)
179 {
180 int result;
181 my_off_t filesize;
182
183 flogger_mutex_lock(log);
184- if (log->rotations > 0)
185- if ((filesize= my_tell(log->file, MYF(0))) == (my_off_t) -1 ||
186- ((unsigned long long)filesize >= log->size_limit &&
187- do_rotate(log)))
188- {
189- result= -1;
190- errno= my_errno;
191- goto exit; /* Log rotation needed but failed */
192- }
193
194 result= my_write(log->file, (uchar *) buffer, size, MYF(0));
195
196+ if (state == LOG_RECORD_COMPLETE && log->rotations > 0)
197+ {
198+ if ((filesize= my_tell(log->file, MYF(0))) == (my_off_t) -1 ||
199+ ((unsigned long long)filesize >= log->size_limit &&
200+ do_rotate(log)))
201+ {
202+ result= -1;
203+ errno= my_errno;
204+ goto exit; /* Log rotation needed but failed */
205+ }
206+ }
207+
208 exit:
209 flogger_mutex_unlock(log);
210 return result;
211
212=== modified file 'plugin/audit_log/logger.h'
213--- plugin/audit_log/logger.h 2014-07-30 19:36:26 +0000
214+++ plugin/audit_log/logger.h 2014-09-26 08:34:49 +0000
215@@ -62,6 +62,10 @@
216 typedef struct logger_handle_st LOGGER_HANDLE;
217 typedef size_t (*logger_prolog_func_t)(MY_STAT *, char *buf, size_t buflen);
218 typedef size_t (*logger_epilog_func_t)(char *buf, size_t buflen);
219+typedef enum {
220+ LOG_RECORD_COMPLETE,
221+ LOG_RECORD_INCOMPLETE
222+} log_record_state_t;
223
224 void logger_init_mutexes();
225 LOGGER_HANDLE *logger_open(const char *path,
226@@ -72,7 +76,8 @@
227 int logger_close(LOGGER_HANDLE *log, logger_epilog_func_t footer);
228 int logger_vprintf(LOGGER_HANDLE *log, const char *fmt, va_list argptr);
229 int logger_printf(LOGGER_HANDLE *log, const char *fmt, ...);
230-int logger_write(LOGGER_HANDLE *log, const char *buffer, size_t size);
231+int logger_write(LOGGER_HANDLE *log, const char *buffer, size_t size,
232+ log_record_state_t state);
233 int logger_rotate(LOGGER_HANDLE *log);
234 int logger_sync(LOGGER_HANDLE *log);
235 int logger_reopen(LOGGER_HANDLE *log, logger_prolog_func_t header,

Subscribers

People subscribed via source and target branches