1 /* Copyright (c) 2000, 2021, Oracle and/or its affiliates.
2
3 This program is free software; you can redistribute it and/or modify
4 it under the terms of the GNU General Public License, version 2.0,
5 as published by the Free Software Foundation.
6
7 This program is also distributed with certain software (including
8 but not limited to OpenSSL) that is licensed under separate terms,
9 as designated in a particular file or component or in included license
10 documentation. The authors of MySQL hereby grant you an additional
11 permission to link the program and your derivative works with the
12 separately licensed software that they have included with MySQL.
13
14 This program is distributed in the hope that it will be useful,
15 but WITHOUT ANY WARRANTY; without even the implied warranty of
16 MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
17 GNU General Public License, version 2.0, for more details.
18
19 You should have received a copy of the GNU General Public License
20 along with this program; if not, write to the Free Software
21 Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA */
22
23
24 /**
25 @file
26
27 @brief
28 logging of commands
29
30 @todo
31 Abort logging when we get an error in reading or writing log files
32 */
33
34 #include "log.h"
35
36 #include "sql_audit.h" // mysql_audit_general_log
37 #include "sql_base.h" // close_log_table
38 #include "sql_class.h" // THD
39 #include "sql_parse.h" // sql_command_flags
40 #include "sql_time.h" // calc_time_from_sec
41 #include "table.h" // TABLE_FIELD_TYPE
42
43 #include "pfs_file_provider.h"
44 #include "mysql/psi/mysql_file.h"
45
46 #include <string>
47 #include <sstream>
48 #ifdef _WIN32
49 #include <message.h>
50 #else
51 #include <syslog.h>
52 #endif
53
54 using std::min;
55 using std::max;
56
57 #ifndef _WIN32
58 static int log_syslog_facility= 0;
59 #endif
60 static char *log_syslog_ident = NULL;
61 static bool log_syslog_enabled = false;
62
63
64 /* 26 for regular timestamp, plus 7 (".123456") when using micro-seconds */
65 static const int iso8601_size= 33;
66
67 enum enum_slow_query_log_table_field
68 {
69 SQLT_FIELD_START_TIME = 0,
70 SQLT_FIELD_USER_HOST,
71 SQLT_FIELD_QUERY_TIME,
72 SQLT_FIELD_LOCK_TIME,
73 SQLT_FIELD_ROWS_SENT,
74 SQLT_FIELD_ROWS_EXAMINED,
75 SQLT_FIELD_DATABASE,
76 SQLT_FIELD_LAST_INSERT_ID,
77 SQLT_FIELD_INSERT_ID,
78 SQLT_FIELD_SERVER_ID,
79 SQLT_FIELD_SQL_TEXT,
80 SQLT_FIELD_THREAD_ID,
81 SQLT_FIELD_COUNT
82 };
83
84 static const TABLE_FIELD_TYPE slow_query_log_table_fields[SQLT_FIELD_COUNT] =
85 {
86 {
87 { C_STRING_WITH_LEN("start_time") },
88 { C_STRING_WITH_LEN("timestamp(6)") },
89 { NULL, 0 }
90 },
91 {
92 { C_STRING_WITH_LEN("user_host") },
93 { C_STRING_WITH_LEN("mediumtext") },
94 { C_STRING_WITH_LEN("utf8") }
95 },
96 {
97 { C_STRING_WITH_LEN("query_time") },
98 { C_STRING_WITH_LEN("time(6)") },
99 { NULL, 0 }
100 },
101 {
102 { C_STRING_WITH_LEN("lock_time") },
103 { C_STRING_WITH_LEN("time(6)") },
104 { NULL, 0 }
105 },
106 {
107 { C_STRING_WITH_LEN("rows_sent") },
108 { C_STRING_WITH_LEN("int(11)") },
109 { NULL, 0 }
110 },
111 {
112 { C_STRING_WITH_LEN("rows_examined") },
113 { C_STRING_WITH_LEN("int(11)") },
114 { NULL, 0 }
115 },
116 {
117 { C_STRING_WITH_LEN("db") },
118 { C_STRING_WITH_LEN("varchar(512)") },
119 { C_STRING_WITH_LEN("utf8") }
120 },
121 {
122 { C_STRING_WITH_LEN("last_insert_id") },
123 { C_STRING_WITH_LEN("int(11)") },
124 { NULL, 0 }
125 },
126 {
127 { C_STRING_WITH_LEN("insert_id") },
128 { C_STRING_WITH_LEN("int(11)") },
129 { NULL, 0 }
130 },
131 {
132 { C_STRING_WITH_LEN("server_id") },
133 { C_STRING_WITH_LEN("int(10) unsigned") },
134 { NULL, 0 }
135 },
136 {
137 { C_STRING_WITH_LEN("sql_text") },
138 { C_STRING_WITH_LEN("mediumblob") },
139 { NULL, 0 }
140 },
141 {
142 { C_STRING_WITH_LEN("thread_id") },
143 { C_STRING_WITH_LEN("bigint(21) unsigned") },
144 { NULL, 0 }
145 }
146 };
147
148 static const TABLE_FIELD_DEF
149 slow_query_log_table_def= {SQLT_FIELD_COUNT, slow_query_log_table_fields};
150
151
152 enum enum_general_log_table_field
153 {
154 GLT_FIELD_EVENT_TIME = 0,
155 GLT_FIELD_USER_HOST,
156 GLT_FIELD_THREAD_ID,
157 GLT_FIELD_SERVER_ID,
158 GLT_FIELD_COMMAND_TYPE,
159 GLT_FIELD_ARGUMENT,
160 GLT_FIELD_COUNT
161 };
162
163 static const TABLE_FIELD_TYPE general_log_table_fields[GLT_FIELD_COUNT] =
164 {
165 {
166 { C_STRING_WITH_LEN("event_time") },
167 { C_STRING_WITH_LEN("timestamp(6)") },
168 { NULL, 0 }
169 },
170 {
171 { C_STRING_WITH_LEN("user_host") },
172 { C_STRING_WITH_LEN("mediumtext") },
173 { C_STRING_WITH_LEN("utf8") }
174 },
175 {
176 { C_STRING_WITH_LEN("thread_id") },
177 { C_STRING_WITH_LEN("bigint(21) unsigned") },
178 { NULL, 0 }
179 },
180 {
181 { C_STRING_WITH_LEN("server_id") },
182 { C_STRING_WITH_LEN("int(10) unsigned") },
183 { NULL, 0 }
184 },
185 {
186 { C_STRING_WITH_LEN("command_type") },
187 { C_STRING_WITH_LEN("varchar(64)") },
188 { C_STRING_WITH_LEN("utf8") }
189 },
190 {
191 { C_STRING_WITH_LEN("argument") },
192 { C_STRING_WITH_LEN("mediumblob") },
193 { NULL, 0 }
194 }
195 };
196
197 static const TABLE_FIELD_DEF
198 general_log_table_def= {GLT_FIELD_COUNT, general_log_table_fields};
199
200
201 class Query_log_table_intact : public Table_check_intact
202 {
203 protected:
report_error(uint,const char * fmt,...)204 void report_error(uint, const char *fmt, ...)
205 {
206 va_list args;
207 va_start(args, fmt);
208 error_log_print(ERROR_LEVEL, fmt, args);
209 va_end(args);
210 }
211 };
212
213 /** In case of an error, a message is printed to the error log. */
214 static Query_log_table_intact log_table_intact;
215
216
217 /**
218 Silence all errors and warnings reported when performing a write
219 to a log table.
220 Errors and warnings are not reported to the client or SQL exception
221 handlers, so that the presence of logging does not interfere and affect
222 the logic of an application.
223 */
224
225 class Silence_log_table_errors : public Internal_error_handler
226 {
227 char m_message[MYSQL_ERRMSG_SIZE];
228 public:
Silence_log_table_errors()229 Silence_log_table_errors() { m_message[0]= '\0'; }
230
handle_condition(THD * thd,uint sql_errno,const char * sql_state,Sql_condition::enum_severity_level * level,const char * msg)231 virtual bool handle_condition(THD *thd,
232 uint sql_errno,
233 const char* sql_state,
234 Sql_condition::enum_severity_level *level,
235 const char* msg)
236 {
237 strmake(m_message, msg, sizeof(m_message)-1);
238 return true;
239 }
240
message() const241 const char *message() const { return m_message; }
242 };
243
244
245 #ifndef _WIN32
246
247 /**
248 On being handed a syslog facility name tries to look it up.
249 If successful, fills in a struct with the facility ID and
250 the facility's canonical name.
251
252 @param f [in] Name of the faciltiy we're trying to look up.
253 Lookup is case-insensitive; leading "log_" is ignored.
254 @param rsf [out] A buffer in which to return the ID and canonical name.
255
256 @return
257 false No errors; buffer contains valid result
258 true Something went wrong, no valid result set returned
259 */
log_syslog_find_facility(char * f,SYSLOG_FACILITY * rsf)260 bool log_syslog_find_facility(char *f, SYSLOG_FACILITY *rsf)
261 {
262 if (!f || !*f || !rsf)
263 return true;
264
265 if (strncasecmp(f, "log_", 4) == 0)
266 f+= 4;
267
268 for(int i= 0; syslog_facility[i].name != NULL; i++)
269 if (!strcasecmp(f, syslog_facility[i].name))
270 {
271 rsf->id= syslog_facility[i].id;
272 rsf->name= syslog_facility[i].name;
273 return false;
274 }
275
276 return true;
277 }
278
279 #endif
280
281
282 /**
283 Close POSIX syslog / Windows EventLog.
284 */
log_syslog_close()285 static void log_syslog_close()
286 {
287 if (log_syslog_enabled)
288 {
289 log_syslog_enabled= false;
290 my_closelog();
291 }
292 }
293
294
295 /**
296 Update syslog / Windows EventLog characteristics (on/off,
297 identify-as, log-PIDs, facility, ...) from global variables.
298
299 @return
300 false No errors; all characteristics updated.
301 true Unable to update characteristics.
302 */
log_syslog_update_settings()303 bool log_syslog_update_settings()
304 {
305 const char *prefix;
306
307 if (!opt_log_syslog_enable && log_syslog_enabled)
308 {
309 log_syslog_close();
310 return false;
311 }
312
313 #ifndef _WIN32
314 {
315 /*
316 make facility
317 */
318
319 SYSLOG_FACILITY rsf = { LOG_DAEMON, "daemon" };
320
321 assert(opt_log_syslog_facility != NULL);
322
323 if (log_syslog_find_facility(opt_log_syslog_facility, &rsf))
324 {
325 log_syslog_find_facility((char *) "daemon", &rsf);
326 sql_print_warning("failed to set syslog facility to \"%s\", "
327 "setting to \"%s\" (%d) instead.",
328 opt_log_syslog_facility, rsf.name, rsf.id);
329 rsf.name= NULL;
330 }
331 log_syslog_facility= rsf.id;
332
333 // If NaN, set to the canonical form (cut "log_", fix case)
334 if ((rsf.name != NULL) && (strcmp(opt_log_syslog_facility, rsf.name) != 0))
335 strcpy(opt_log_syslog_facility, rsf.name);
336 }
337
338 /*
339 Logs historically have subtly different names, to meet each platform's
340 conventions -- "mysqld" on unix (via mysqld_safe), and "MySQL" for the
341 Win NT EventLog.
342 */
343 prefix= "mysqld";
344 #else
345 prefix= "MySQL";
346 #endif
347
348 // tag must not contain directory separators
349 if ((opt_log_syslog_tag != NULL) &&
350 (strchr(opt_log_syslog_tag, FN_LIBCHAR) != NULL))
351 return true;
352
353 if (opt_log_syslog_enable)
354 {
355 /*
356 make ident
357 */
358 char *ident= NULL;
359
360 if ((opt_log_syslog_tag == NULL) ||
361 (*opt_log_syslog_tag == '\0'))
362 ident= my_strdup(PSI_NOT_INSTRUMENTED, prefix, MYF(0));
363 else
364 {
365 size_t l= 6 + 1 + 1 + strlen(opt_log_syslog_tag);
366
367 ident= (char *) my_malloc(PSI_NOT_INSTRUMENTED, l, MYF(0));
368 if (ident)
369 my_snprintf(ident, l, "%s-%s", prefix, opt_log_syslog_tag);
370 }
371
372 // if we succeeded in making an ident, replace the old one
373 if (ident)
374 {
375 char *i= log_syslog_ident;
376 log_syslog_ident= ident;
377 if (i)
378 my_free(i);
379 }
380 else
381 return true;
382
383 log_syslog_close();
384
385 int ret;
386
387 ret= my_openlog(log_syslog_ident,
388 #ifndef _WIN32
389 opt_log_syslog_include_pid ? MY_SYSLOG_PIDS : 0,
390 log_syslog_facility
391 #else
392 0, 0
393 #endif
394 );
395
396 if (ret == -1)
397 return true;
398
399 log_syslog_enabled= true;
400
401 if (ret == -2)
402 {
403 my_syslog(system_charset_info, ERROR_LEVEL, "could not update log settings!");
404 return true;
405 }
406 }
407
408 return false;
409 }
410
411
412 /**
413 Stop using syslog / EventLog. Call as late as possible.
414 */
log_syslog_exit(void)415 void log_syslog_exit(void)
416 {
417 log_syslog_close();
418
419 if (log_syslog_ident != NULL)
420 {
421 my_free(log_syslog_ident);
422 log_syslog_ident= NULL;
423 }
424 }
425
426
427 /**
428 Start using syslog / EventLog.
429
430 @return
431 true could not open syslog / EventLog with the requested characteristics
432 false no issues encountered
433 */
log_syslog_init(void)434 bool log_syslog_init(void)
435 {
436 if (log_syslog_update_settings())
437 {
438 #ifdef _WIN32
439 const char *l = "Windows EventLog";
440 #else
441 const char *l = "syslog";
442 #endif
443 sql_print_error("Cannot open %s; check privileges, or start server with --log_syslog=0", l);
444 return true;
445 }
446 return false;
447 }
448
449
ull2timeval(ulonglong utime,struct timeval * tv)450 static void ull2timeval(ulonglong utime, struct timeval *tv)
451 {
452 assert(tv != NULL);
453 assert(utime > 0); /* should hold true in this context */
454 tv->tv_sec= static_cast<long>(utime / 1000000);
455 tv->tv_usec=utime % 1000000;
456 }
457
458
459 /**
460 Make and return an ISO 8601 / RFC 3339 compliant timestamp.
461 Heeds log_timestamps.
462
463 @param buf A buffer of at least 26 bytes to store the timestamp in
464 (19 + tzinfo tail + \0)
465 @param seconds Seconds since the epoch, or 0 for "now"
466
467 @return length of timestamp (excluding \0)
468 */
469
make_iso8601_timestamp(char * buf,ulonglong utime=0)470 static int make_iso8601_timestamp(char *buf, ulonglong utime= 0)
471 {
472 struct tm my_tm;
473 char tzinfo[7]="Z"; // max 6 chars plus \0
474 size_t len;
475 time_t seconds;
476
477 if (utime == 0)
478 utime= my_micro_time();
479
480 seconds= utime / 1000000;
481 utime = utime % 1000000;
482
483 if (opt_log_timestamps == 0)
484 gmtime_r(&seconds, &my_tm);
485 else
486 {
487 localtime_r(&seconds, &my_tm);
488
489 #ifdef __FreeBSD__
490 /*
491 The field tm_gmtoff is the offset (in seconds) of the time represented
492 from UTC, with positive values indicating east of the Prime Meridian.
493 */
494 long tim= -my_tm.tm_gmtoff;
495 #elif _WIN32
496 long tim = _timezone;
497 #else
498 long tim= timezone; // seconds West of UTC.
499 #endif
500 char dir= '-';
501
502 if (tim < 0)
503 {
504 dir= '+';
505 tim= -tim;
506 }
507 my_snprintf(tzinfo, sizeof(tzinfo), "%c%02d:%02d",
508 dir, (int) (tim / (60 * 60)), (int) ((tim / 60) % 60));
509 }
510
511 len= my_snprintf(buf, iso8601_size, "%04d-%02d-%02dT%02d:%02d:%02d.%06lu%s",
512 my_tm.tm_year + 1900,
513 my_tm.tm_mon + 1,
514 my_tm.tm_mday,
515 my_tm.tm_hour,
516 my_tm.tm_min,
517 my_tm.tm_sec,
518 (unsigned long) utime,
519 tzinfo);
520
521 return min<int>(len, iso8601_size - 1);
522 }
523
524
is_valid_log_name(const char * name,size_t len)525 bool is_valid_log_name(const char *name, size_t len)
526 {
527 if (len > 3)
528 {
529 const char *tail= name + len - 4;
530 if (my_strcasecmp(system_charset_info, tail, ".ini") == 0 ||
531 my_strcasecmp(system_charset_info, tail, ".cnf") == 0)
532 {
533 return false;
534 }
535 }
536 return true;
537 }
538
539
540 /**
541 Get the real log file name, and possibly reopen file.
542
543 The implementation is platform dependent due to differences in how this is
544 supported:
545
546 On Windows, we get the actual path based on the file descriptor. This path is
547 copied into the supplied buffer. The 'file' parameter is returned without
548 re-opening.
549
550 On other platforms, we use realpath() to get the path with symbolic links
551 expanded. Then, we close the file, and reopen the real path using the
552 O_NOFOLLOW flag. This will reject folowing symbolic links.
553
554 @param file File descriptor.
555 @param log_file_key Key for P_S instrumentation.
556 @param open_flags Flags to use for opening the file.
557 @param opened_file_name Name of the open fd.
558 @param [out] real_file_name Buffer for actual name of the fd.
559
560 @retval file descriptor to open file with 'real_file_name', or '-1'
561 in case of errors.
562 */
563
mysql_file_real_name_reopen(File file,PSI_file_key log_file_key,int open_flags,const char * opened_file_name,char * real_file_name)564 static File mysql_file_real_name_reopen(File file,
565 #ifdef HAVE_PSI_INTERFACE
566 PSI_file_key log_file_key,
567 #endif
568 int open_flags,
569 const char *opened_file_name,
570 char *real_file_name)
571 {
572 assert(file);
573 assert(opened_file_name);
574 assert(real_file_name);
575
576 #ifdef _WIN32
577 /* On Windows, O_NOFOLLOW is not supported. Verify real path from fd. */
578 DWORD real_length= GetFinalPathNameByHandle(my_get_osfhandle(file),
579 real_file_name,
580 FN_REFLEN,
581 FILE_NAME_OPENED);
582
583 /* May ret 0 if e.g. on a ramdisk. Ignore - return open file and name. */
584 if (real_length == 0)
585 {
586 strcpy(real_file_name, opened_file_name);
587 return file;
588 }
589
590 if (real_length > FN_REFLEN)
591 {
592 mysql_file_close(file, MYF(0));
593 return -1;
594 }
595
596 return file;
597 #else
598 /* On *nix, get realpath, open realpath with O_NOFOLLOW. */
599 if (realpath(opened_file_name, real_file_name) == NULL)
600 {
601 (void) mysql_file_close(file, MYF(0));
602 return -1;
603 }
604
605 if (mysql_file_close(file, MYF(0)))
606 return -1;
607
608 /* Make sure the real path is not too long. */
609 if (strlen(real_file_name) > FN_REFLEN)
610 return -1;
611
612 return mysql_file_open(log_file_key, real_file_name,
613 open_flags | O_NOFOLLOW,
614 MYF(MY_WME));
615 #endif //_WIN32
616 }
617
618
open()619 bool File_query_log::open()
620 {
621 File file= -1;
622 my_off_t pos= 0;
623 const char *log_name= NULL;
624 char buff[FN_REFLEN];
625 MY_STAT f_stat;
626 DBUG_ENTER("File_query_log::open");
627
628 if (m_log_type == QUERY_LOG_SLOW)
629 log_name= opt_slow_logname;
630 else if (m_log_type == QUERY_LOG_GENERAL)
631 log_name= opt_general_logname;
632 else
633 assert(false);
634 assert(log_name && log_name[0]);
635
636 write_error= false;
637
638 if (!(name= my_strdup(key_memory_File_query_log_name, log_name, MYF(MY_WME))))
639 {
640 name= const_cast<char *>(log_name); // for the error message
641 goto err;
642 }
643
644 fn_format(log_file_name, name, mysql_data_home, "", 4);
645
646 /* File is regular writable file */
647 if (my_stat(log_file_name, &f_stat, MYF(0)) && !MY_S_ISREG(f_stat.st_mode))
648 goto err;
649
650 db[0]= 0;
651
652 /* First, open the file to make sure it exists. */
653 if ((file= mysql_file_open(m_log_file_key,
654 log_file_name,
655 O_CREAT | O_BINARY | O_WRONLY | O_APPEND,
656 MYF(MY_WME))) < 0)
657 goto err;
658
659 #ifdef _WIN32
660 char real_log_file_name[FN_REFLEN];
661 #else
662 /* File name must have room for PATH_MAX. Checked against F_REFLEN later. */
663 char real_log_file_name[PATH_MAX];
664 #endif // _Win32
665
666 /* Reopen and get real path. */
667 if ((file= mysql_file_real_name_reopen(file,
668 #ifdef HAVE_PSI_INTERFACE
669 m_log_file_key,
670 #endif
671 O_CREAT | O_BINARY | O_WRONLY | O_APPEND,
672 log_file_name, real_log_file_name)) < 0)
673 goto err;
674
675 if (!is_valid_log_name(real_log_file_name, strlen(real_log_file_name)))
676 {
677 sql_print_error("Invalid log file name after expanding symlinks: '%s'",
678 real_log_file_name);
679 goto err;
680 }
681
682 if ((pos= mysql_file_tell(file, MYF(MY_WME))) == MY_FILEPOS_ERROR)
683 {
684 if (my_errno() == ESPIPE)
685 pos= 0;
686 else
687 goto err;
688 }
689
690 if (init_io_cache(&log_file, file, IO_SIZE, WRITE_CACHE, pos, 0,
691 MYF(MY_WME | MY_NABP)))
692 goto err;
693
694 {
695 char *end;
696 size_t len=my_snprintf(buff, sizeof(buff), "%s, Version: %s (%s). "
697 #ifdef EMBEDDED_LIBRARY
698 "embedded library\n",
699 my_progname, server_version, MYSQL_COMPILATION_COMMENT
700 #elif _WIN32
701 "started with:\nTCP Port: %d, Named Pipe: %s\n",
702 my_progname, server_version, MYSQL_COMPILATION_COMMENT,
703 mysqld_port, mysqld_unix_port
704 #else
705 "started with:\nTcp port: %d Unix socket: %s\n",
706 my_progname, server_version, MYSQL_COMPILATION_COMMENT,
707 mysqld_port, mysqld_unix_port
708 #endif
709 );
710 end= my_stpncpy(buff + len, "Time Id Command Argument\n",
711 sizeof(buff) - len);
712 if (my_b_write(&log_file, (uchar*) buff, (uint) (end-buff)) ||
713 flush_io_cache(&log_file))
714 goto err;
715 }
716
717 log_open= true;
718 DBUG_RETURN(false);
719
720 err:
721 char log_open_file_error_message[96]= "";
722 if (strcmp(opt_slow_logname, name) == 0)
723 {
724 strcpy(log_open_file_error_message, "either restart the query logging "
725 "by using \"SET GLOBAL SLOW_QUERY_LOG=ON\" or");
726 }
727 else if (strcmp(opt_general_logname, name) == 0)
728 {
729 strcpy(log_open_file_error_message, "either restart the query logging "
730 "by using \"SET GLOBAL GENERAL_LOG=ON\" or");
731 }
732
733 char errbuf[MYSYS_STRERROR_SIZE];
734 sql_print_error("Could not use %s for logging (error %d - %s). "
735 "Turning logging off for the server process. "
736 "To turn it on again: fix the cause, "
737 "then %s restart the MySQL server.", name, errno,
738 my_strerror(errbuf, sizeof(errbuf), errno),
739 log_open_file_error_message);
740 if (file >= 0)
741 mysql_file_close(file, MYF(0));
742 end_io_cache(&log_file);
743 my_free(name);
744 name= NULL;
745 log_open= false;
746 DBUG_RETURN(true);
747 }
748
749
close()750 void File_query_log::close()
751 {
752 DBUG_ENTER("File_query_log::close");
753 if (!is_open())
754 DBUG_VOID_RETURN;
755
756 end_io_cache(&log_file);
757
758 if (mysql_file_sync(log_file.file, MYF(MY_WME)))
759 check_and_print_write_error();
760
761 if (mysql_file_close(log_file.file, MYF(MY_WME)))
762 check_and_print_write_error();
763
764 log_open= false;
765 my_free(name);
766 name= NULL;
767 DBUG_VOID_RETURN;
768 }
769
770
check_and_print_write_error()771 void File_query_log::check_and_print_write_error()
772 {
773 if (!write_error)
774 {
775 char errbuf[MYSYS_STRERROR_SIZE];
776 write_error= true;
777 sql_print_error(ER_DEFAULT(ER_ERROR_ON_WRITE), name, errno,
778 my_strerror(errbuf, sizeof(errbuf), errno));
779 }
780 }
781
782
write_general(ulonglong event_utime,const char * user_host,size_t user_host_len,my_thread_id thread_id,const char * command_type,size_t command_type_len,const char * sql_text,size_t sql_text_len)783 bool File_query_log::write_general(ulonglong event_utime,
784 const char *user_host,
785 size_t user_host_len,
786 my_thread_id thread_id,
787 const char *command_type,
788 size_t command_type_len,
789 const char *sql_text,
790 size_t sql_text_len)
791 {
792 char buff[32];
793 size_t length= 0;
794
795 mysql_mutex_lock(&LOCK_log);
796 assert(is_open());
797
798 /* Note that my_b_write() assumes it knows the length for this */
799 char local_time_buff[iso8601_size];
800 int time_buff_len= make_iso8601_timestamp(local_time_buff, event_utime);
801
802 if (my_b_write(&log_file, (uchar*) local_time_buff, time_buff_len))
803 goto err;
804
805 if (my_b_write(&log_file, (uchar*) "\t", 1))
806 goto err;
807
808 length= my_snprintf(buff, 32, "%5u ", thread_id);
809
810 if (my_b_write(&log_file, (uchar*) buff, length))
811 goto err;
812
813 if (my_b_write(&log_file, (uchar*) command_type, command_type_len))
814 goto err;
815
816 if (my_b_write(&log_file, (uchar*) "\t", 1))
817 goto err;
818
819 /* sql_text */
820 if (my_b_write(&log_file, (uchar*) sql_text, sql_text_len))
821 goto err;
822
823 if (my_b_write(&log_file, (uchar*) "\n", 1) ||
824 flush_io_cache(&log_file))
825 goto err;
826
827 mysql_mutex_unlock(&LOCK_log);
828 return false;
829
830 err:
831 check_and_print_write_error();
832 mysql_mutex_unlock(&LOCK_log);
833 return true;
834 }
835
836
write_slow(THD * thd,ulonglong current_utime,ulonglong query_start_arg,const char * user_host,size_t user_host_len,ulonglong query_utime,ulonglong lock_utime,bool is_command,const char * sql_text,size_t sql_text_len)837 bool File_query_log::write_slow(THD *thd, ulonglong current_utime,
838 ulonglong query_start_arg,
839 const char *user_host,
840 size_t user_host_len, ulonglong query_utime,
841 ulonglong lock_utime, bool is_command,
842 const char *sql_text, size_t sql_text_len)
843 {
844 char buff[80], *end;
845 char query_time_buff[22+7], lock_time_buff[22+7];
846 size_t buff_len;
847 end= buff;
848
849 mysql_mutex_lock(&LOCK_log);
850 assert(is_open());
851
852 if (!(specialflag & SPECIAL_SHORT_LOG_FORMAT))
853 {
854 char my_timestamp[iso8601_size];
855
856 make_iso8601_timestamp(my_timestamp, current_utime);
857
858 buff_len= my_snprintf(buff, sizeof buff,
859 "# Time: %s\n", my_timestamp);
860
861 /* Note that my_b_write() assumes it knows the length for this */
862 if (my_b_write(&log_file, (uchar*) buff, buff_len))
863 goto err;
864
865 buff_len= my_snprintf(buff, 32, "%5u", thd->thread_id());
866 if (my_b_printf(&log_file, "# User@Host: %s Id: %s\n", user_host, buff)
867 == (uint) -1)
868 goto err;
869 }
870
871 /* For slow query log */
872 sprintf(query_time_buff, "%.6f", ulonglong2double(query_utime)/1000000.0);
873 sprintf(lock_time_buff, "%.6f", ulonglong2double(lock_utime)/1000000.0);
874 if (my_b_printf(&log_file,
875 "# Query_time: %s Lock_time: %s"
876 " Rows_sent: %lu Rows_examined: %lu\n",
877 query_time_buff, lock_time_buff,
878 (ulong) thd->get_sent_row_count(),
879 (ulong) thd->get_examined_row_count()) == (uint) -1)
880 goto err;
881 if (thd->db().str && strcmp(thd->db().str, db))
882 { // Database changed
883 if (my_b_printf(&log_file,"use %s;\n",thd->db().str) == (uint) -1)
884 goto err;
885 my_stpcpy(db,thd->db().str);
886 }
887 if (thd->stmt_depends_on_first_successful_insert_id_in_prev_stmt)
888 {
889 end=my_stpcpy(end, ",last_insert_id=");
890 end=longlong10_to_str((longlong)
891 thd->first_successful_insert_id_in_prev_stmt_for_binlog,
892 end, -10);
893 }
894 // Save value if we do an insert.
895 if (thd->auto_inc_intervals_in_cur_stmt_for_binlog.nb_elements() > 0)
896 {
897 if (!(specialflag & SPECIAL_SHORT_LOG_FORMAT))
898 {
899 end=my_stpcpy(end,",insert_id=");
900 end=longlong10_to_str((longlong)
901 thd->auto_inc_intervals_in_cur_stmt_for_binlog.minimum(),
902 end, -10);
903 }
904 }
905
906 /*
907 This info used to show up randomly, depending on whether the query
908 checked the query start time or not. now we always write current
909 timestamp to the slow log
910 */
911 end= my_stpcpy(end, ",timestamp=");
912 end= int10_to_str((long) (current_utime / 1000000), end, 10);
913
914 if (end != buff)
915 {
916 *end++=';';
917 *end='\n';
918 if (my_b_write(&log_file, (uchar*) "SET ", 4) ||
919 my_b_write(&log_file, (uchar*) buff + 1, (uint) (end-buff)))
920 goto err;
921 }
922 if (is_command)
923 {
924 end= strxmov(buff, "# administrator command: ", NullS);
925 buff_len= (ulong) (end - buff);
926 DBUG_EXECUTE_IF("simulate_slow_log_write_error",
927 {DBUG_SET("+d,simulate_file_write_error");});
928 if (my_b_write(&log_file, (uchar*) buff, buff_len))
929 goto err;
930 }
931 if (my_b_write(&log_file, (uchar*) sql_text, sql_text_len) ||
932 my_b_write(&log_file, (uchar*) ";\n",2) ||
933 flush_io_cache(&log_file))
934 goto err;
935
936 mysql_mutex_unlock(&LOCK_log);
937 return false;
938
939 err:
940 check_and_print_write_error();
941 mysql_mutex_unlock(&LOCK_log);
942 return true;
943 }
944
945
log_general(THD * thd,ulonglong event_utime,const char * user_host,size_t user_host_len,my_thread_id thread_id,const char * command_type,size_t command_type_len,const char * sql_text,size_t sql_text_len,const CHARSET_INFO * client_cs)946 bool Log_to_csv_event_handler::log_general(THD *thd, ulonglong event_utime,
947 const char *user_host,
948 size_t user_host_len,
949 my_thread_id thread_id,
950 const char *command_type,
951 size_t command_type_len,
952 const char *sql_text,
953 size_t sql_text_len,
954 const CHARSET_INFO *client_cs)
955 {
956 TABLE *table= NULL;
957 bool result= true;
958 bool need_close= false;
959 bool need_rnd_end= false;
960 uint field_index;
961 struct timeval tv;
962
963 /*
964 CSV uses TIME_to_timestamp() internally if table needs to be repaired
965 which will set thd->time_zone_used
966 */
967 bool save_time_zone_used= thd->time_zone_used;
968
969 ulonglong save_thd_options= thd->variables.option_bits;
970 thd->variables.option_bits&= ~OPTION_BIN_LOG;
971
972 TABLE_LIST table_list;
973 table_list.init_one_table(MYSQL_SCHEMA_NAME.str, MYSQL_SCHEMA_NAME.length,
974 GENERAL_LOG_NAME.str, GENERAL_LOG_NAME.length,
975 GENERAL_LOG_NAME.str,
976 TL_WRITE_CONCURRENT_INSERT);
977
978 /*
979 1) open_log_table generates an error if the
980 table can not be opened or is corrupted.
981 2) "INSERT INTO general_log" can generate warning sometimes.
982
983 Suppress these warnings and errors, they can't be dealt with
984 properly anyway.
985
986 QQ: this problem needs to be studied in more detail.
987 Comment this 2 lines and run "cast.test" to see what's happening.
988 */
989 Silence_log_table_errors error_handler;
990 thd->push_internal_handler(&error_handler);
991
992 Open_tables_backup open_tables_backup;
993 if (!(table= open_log_table(thd, &table_list, &open_tables_backup)))
994 goto err;
995
996 need_close= true;
997
998 if (log_table_intact.check(table_list.table, &general_log_table_def))
999 goto err;
1000
1001 if (table->file->extra(HA_EXTRA_MARK_AS_LOG_TABLE) ||
1002 table->file->ha_rnd_init(0))
1003 goto err;
1004
1005 need_rnd_end= true;
1006
1007 /* Honor next number columns if present */
1008 table->next_number_field= table->found_next_number_field;
1009
1010 /*
1011 NOTE: we do not call restore_record() here, as all fields are
1012 filled by the Logger (=> no need to load default ones).
1013 */
1014
1015 /*
1016 We do not set a value for table->field[0], as it will use
1017 default value (which is CURRENT_TIMESTAMP).
1018 */
1019
1020 assert(table->field[GLT_FIELD_EVENT_TIME]->type() == MYSQL_TYPE_TIMESTAMP);
1021 ull2timeval(event_utime, &tv);
1022 table->field[GLT_FIELD_EVENT_TIME]->store_timestamp(&tv);
1023
1024 /* do a write */
1025 if (table->field[GLT_FIELD_USER_HOST]->store(user_host, user_host_len,
1026 client_cs) ||
1027 table->field[GLT_FIELD_THREAD_ID]->store((longlong) thread_id, true) ||
1028 table->field[GLT_FIELD_SERVER_ID]->store((longlong) server_id, true) ||
1029 table->field[GLT_FIELD_COMMAND_TYPE]->store(command_type,
1030 command_type_len, client_cs))
1031 goto err;
1032
1033 /*
1034 A positive return value in store() means truncation.
1035 Still logging a message in the log in this case.
1036 */
1037 if (table->field[GLT_FIELD_ARGUMENT]->store(sql_text, sql_text_len,
1038 client_cs) < 0)
1039 goto err;
1040
1041 /* mark all fields as not null */
1042 table->field[GLT_FIELD_USER_HOST]->set_notnull();
1043 table->field[GLT_FIELD_THREAD_ID]->set_notnull();
1044 table->field[GLT_FIELD_SERVER_ID]->set_notnull();
1045 table->field[GLT_FIELD_COMMAND_TYPE]->set_notnull();
1046 table->field[GLT_FIELD_ARGUMENT]->set_notnull();
1047
1048 /* Set any extra columns to their default values */
1049 for (field_index= GLT_FIELD_COUNT ;
1050 field_index < table->s->fields ;
1051 field_index++)
1052 {
1053 table->field[field_index]->set_default();
1054 }
1055
1056 /* log table entries are not replicated */
1057 if (table->file->ha_write_row(table->record[0]))
1058 goto err;
1059
1060 result= false;
1061
1062 err:
1063 thd->pop_internal_handler();
1064
1065 if (result && !thd->killed)
1066 sql_print_error("Failed to write to mysql.general_log: %s",
1067 error_handler.message());
1068
1069 if (need_rnd_end)
1070 {
1071 table->file->ha_rnd_end();
1072 table->file->ha_release_auto_increment();
1073 }
1074
1075 if (need_close)
1076 close_log_table(thd, &open_tables_backup);
1077
1078 thd->variables.option_bits= save_thd_options;
1079 thd->time_zone_used= save_time_zone_used;
1080 return result;
1081 }
1082
1083
log_slow(THD * thd,ulonglong current_utime,ulonglong query_start_arg,const char * user_host,size_t user_host_len,ulonglong query_utime,ulonglong lock_utime,bool is_command,const char * sql_text,size_t sql_text_len)1084 bool Log_to_csv_event_handler::log_slow(THD *thd, ulonglong current_utime,
1085 ulonglong query_start_arg,
1086 const char *user_host,
1087 size_t user_host_len,
1088 ulonglong query_utime,
1089 ulonglong lock_utime, bool is_command,
1090 const char *sql_text,
1091 size_t sql_text_len)
1092 {
1093 TABLE *table= NULL;
1094 bool result= true;
1095 bool need_close= false;
1096 bool need_rnd_end= false;
1097 const CHARSET_INFO *client_cs= thd->variables.character_set_client;
1098 struct timeval tv;
1099
1100 DBUG_ENTER("Log_to_csv_event_handler::log_slow");
1101
1102 /*
1103 CSV uses TIME_to_timestamp() internally if table needs to be repaired
1104 which will set thd->time_zone_used
1105 */
1106 bool save_time_zone_used= thd->time_zone_used;
1107
1108 TABLE_LIST table_list;
1109 table_list.init_one_table(MYSQL_SCHEMA_NAME.str, MYSQL_SCHEMA_NAME.length,
1110 SLOW_LOG_NAME.str, SLOW_LOG_NAME.length,
1111 SLOW_LOG_NAME.str,
1112 TL_WRITE_CONCURRENT_INSERT);
1113
1114 Silence_log_table_errors error_handler;
1115 thd->push_internal_handler(& error_handler);
1116
1117 Open_tables_backup open_tables_backup;
1118 if (!(table= open_log_table(thd, &table_list, &open_tables_backup)))
1119 goto err;
1120
1121 need_close= true;
1122
1123 if (log_table_intact.check(table_list.table, &slow_query_log_table_def))
1124 goto err;
1125
1126 if (table->file->extra(HA_EXTRA_MARK_AS_LOG_TABLE) ||
1127 table->file->ha_rnd_init(0))
1128 goto err;
1129
1130 need_rnd_end= true;
1131
1132 /* Honor next number columns if present */
1133 table->next_number_field= table->found_next_number_field;
1134
1135 restore_record(table, s->default_values); // Get empty record
1136
1137 /* store the time and user values */
1138 assert(table->field[SQLT_FIELD_START_TIME]->type() == MYSQL_TYPE_TIMESTAMP);
1139 ull2timeval(current_utime, &tv);
1140 table->field[SQLT_FIELD_START_TIME]->store_timestamp(&tv);
1141
1142 if (table->field[SQLT_FIELD_USER_HOST]->store(user_host, user_host_len,
1143 client_cs))
1144 goto err;
1145
1146 if (query_start_arg)
1147 {
1148 /*
1149 A TIME field can not hold the full longlong range; query_time or
1150 lock_time may be truncated without warning here, if greater than
1151 839 hours (~35 days)
1152 */
1153 MYSQL_TIME t;
1154 t.neg= 0;
1155
1156 /* fill in query_time field */
1157 calc_time_from_sec(&t,
1158 static_cast<long>(min((longlong)(query_utime / 1000000),
1159 (longlong)TIME_MAX_VALUE_SECONDS)),
1160 query_utime % 1000000);
1161 if (table->field[SQLT_FIELD_QUERY_TIME]->store_time(&t))
1162 goto err;
1163 /* lock_time */
1164 calc_time_from_sec(&t,
1165 static_cast<long>(min((longlong)(lock_utime / 1000000),
1166 (longlong)TIME_MAX_VALUE_SECONDS)),
1167 lock_utime % 1000000);
1168 if (table->field[SQLT_FIELD_LOCK_TIME]->store_time(&t))
1169 goto err;
1170 /* rows_sent */
1171 if (table->field[SQLT_FIELD_ROWS_SENT]->store((longlong) thd->get_sent_row_count(), true))
1172 goto err;
1173 /* rows_examined */
1174 if (table->field[SQLT_FIELD_ROWS_EXAMINED]->store((longlong) thd->get_examined_row_count(), true))
1175 goto err;
1176 }
1177 else
1178 {
1179 table->field[SQLT_FIELD_QUERY_TIME]->set_null();
1180 table->field[SQLT_FIELD_LOCK_TIME]->set_null();
1181 table->field[SQLT_FIELD_ROWS_SENT]->set_null();
1182 table->field[SQLT_FIELD_ROWS_EXAMINED]->set_null();
1183 }
1184 /* fill database field */
1185 if (thd->db().str)
1186 {
1187 if (table->field[SQLT_FIELD_DATABASE]->store(thd->db().str,
1188 thd->db().length,
1189 client_cs))
1190 goto err;
1191 table->field[SQLT_FIELD_DATABASE]->set_notnull();
1192 }
1193
1194 if (thd->stmt_depends_on_first_successful_insert_id_in_prev_stmt)
1195 {
1196 if (table->
1197 field[SQLT_FIELD_LAST_INSERT_ID]->store((longlong)
1198 thd->first_successful_insert_id_in_prev_stmt_for_binlog,
1199 true))
1200 goto err;
1201 table->field[SQLT_FIELD_LAST_INSERT_ID]->set_notnull();
1202 }
1203
1204 /*
1205 Set value if we do an insert on autoincrement column. Note that for
1206 some engines (those for which get_auto_increment() does not leave a
1207 table lock until the statement ends), this is just the first value and
1208 the next ones used may not be contiguous to it.
1209 */
1210 if (thd->auto_inc_intervals_in_cur_stmt_for_binlog.nb_elements() > 0)
1211 {
1212 if (table->
1213 field[SQLT_FIELD_INSERT_ID]->store((longlong)
1214 thd->auto_inc_intervals_in_cur_stmt_for_binlog.minimum(), true))
1215 goto err;
1216 table->field[SQLT_FIELD_INSERT_ID]->set_notnull();
1217 }
1218
1219 if (table->field[SQLT_FIELD_SERVER_ID]->store((longlong) server_id, true))
1220 goto err;
1221 table->field[SQLT_FIELD_SERVER_ID]->set_notnull();
1222
1223 /*
1224 Column sql_text.
1225 A positive return value in store() means truncation.
1226 Still logging a message in the log in this case.
1227 */
1228 if (table->field[SQLT_FIELD_SQL_TEXT]->store(sql_text, sql_text_len,
1229 client_cs) < 0)
1230 goto err;
1231
1232 if (table->field[SQLT_FIELD_THREAD_ID]->store((longlong) thd->thread_id(),
1233 true))
1234 goto err;
1235
1236 /* log table entries are not replicated */
1237 if (table->file->ha_write_row(table->record[0]))
1238 goto err;
1239
1240 result= false;
1241
1242 err:
1243 thd->pop_internal_handler();
1244
1245 if (result && !thd->killed)
1246 sql_print_error("Failed to write to mysql.slow_log: %s",
1247 error_handler.message());
1248
1249 if (need_rnd_end)
1250 {
1251 table->file->ha_rnd_end();
1252 table->file->ha_release_auto_increment();
1253 }
1254
1255 if (need_close)
1256 close_log_table(thd, &open_tables_backup);
1257
1258 thd->time_zone_used= save_time_zone_used;
1259 DBUG_RETURN(result);
1260 }
1261
1262
activate_log(THD * thd,enum_log_table_type log_table_type)1263 bool Log_to_csv_event_handler::activate_log(THD *thd,
1264 enum_log_table_type log_table_type)
1265 {
1266 TABLE_LIST table_list;
1267
1268 DBUG_ENTER("Log_to_csv_event_handler::activate_log");
1269
1270 switch (log_table_type)
1271 {
1272 case QUERY_LOG_GENERAL:
1273 table_list.init_one_table(MYSQL_SCHEMA_NAME.str, MYSQL_SCHEMA_NAME.length,
1274 GENERAL_LOG_NAME.str, GENERAL_LOG_NAME.length,
1275 GENERAL_LOG_NAME.str, TL_WRITE_CONCURRENT_INSERT);
1276 break;
1277 case QUERY_LOG_SLOW:
1278 table_list.init_one_table(MYSQL_SCHEMA_NAME.str, MYSQL_SCHEMA_NAME.length,
1279 SLOW_LOG_NAME.str, SLOW_LOG_NAME.length,
1280 SLOW_LOG_NAME.str, TL_WRITE_CONCURRENT_INSERT);
1281 break;
1282 default:
1283 assert(false);
1284 }
1285
1286 Open_tables_backup open_tables_backup;
1287 if (open_log_table(thd, &table_list, &open_tables_backup) != NULL)
1288 {
1289 close_log_table(thd, &open_tables_backup);
1290 DBUG_RETURN(false);
1291 }
1292 DBUG_RETURN(true);
1293 }
1294
1295
log_slow(THD * thd,ulonglong current_utime,ulonglong query_start_arg,const char * user_host,size_t user_host_len,ulonglong query_utime,ulonglong lock_utime,bool is_command,const char * sql_text,size_t sql_text_len)1296 bool Log_to_file_event_handler::log_slow(THD *thd, ulonglong current_utime,
1297 ulonglong query_start_arg,
1298 const char *user_host,
1299 size_t user_host_len,
1300 ulonglong query_utime,
1301 ulonglong lock_utime,
1302 bool is_command,
1303 const char *sql_text,
1304 size_t sql_text_len)
1305 {
1306 if (!mysql_slow_log.is_open())
1307 return false;
1308
1309 Silence_log_table_errors error_handler;
1310 thd->push_internal_handler(&error_handler);
1311 bool retval= mysql_slow_log.write_slow(thd, current_utime, query_start_arg,
1312 user_host, user_host_len,
1313 query_utime, lock_utime, is_command,
1314 sql_text, sql_text_len);
1315 thd->pop_internal_handler();
1316 return retval;
1317 }
1318
1319
log_general(THD * thd,ulonglong event_utime,const char * user_host,size_t user_host_len,my_thread_id thread_id,const char * command_type,size_t command_type_len,const char * sql_text,size_t sql_text_len,const CHARSET_INFO * client_cs)1320 bool Log_to_file_event_handler::log_general(THD *thd, ulonglong event_utime,
1321 const char *user_host,
1322 size_t user_host_len,
1323 my_thread_id thread_id,
1324 const char *command_type,
1325 size_t command_type_len,
1326 const char *sql_text,
1327 size_t sql_text_len,
1328 const CHARSET_INFO *client_cs)
1329 {
1330 if (!mysql_general_log.is_open())
1331 return false;
1332
1333 Silence_log_table_errors error_handler;
1334 thd->push_internal_handler(&error_handler);
1335 bool retval= mysql_general_log.write_general(event_utime, user_host,
1336 user_host_len, thread_id,
1337 command_type, command_type_len,
1338 sql_text, sql_text_len);
1339 thd->pop_internal_handler();
1340 return retval;
1341 }
1342
1343
cleanup()1344 void Query_logger::cleanup()
1345 {
1346 mysql_rwlock_destroy(&LOCK_logger);
1347
1348 assert(file_log_handler);
1349 file_log_handler->cleanup();
1350 delete file_log_handler;
1351 file_log_handler= NULL;
1352 }
1353
1354
slow_log_write(THD * thd,const char * query,size_t query_length)1355 bool Query_logger::slow_log_write(THD *thd, const char *query,
1356 size_t query_length)
1357 {
1358 assert(thd->enable_slow_log && opt_slow_log);
1359
1360 if (!(*slow_log_handler_list))
1361 return false;
1362
1363 /* do not log slow queries from replication threads */
1364 if (thd->slave_thread && !opt_log_slow_slave_statements)
1365 return false;
1366
1367 mysql_rwlock_rdlock(&LOCK_logger);
1368
1369 /* fill in user_host value: the format is "%s[%s] @ %s [%s]" */
1370 char user_host_buff[MAX_USER_HOST_SIZE + 1];
1371 Security_context *sctx= thd->security_context();
1372 LEX_CSTRING sctx_user= sctx->user();
1373 LEX_CSTRING sctx_host= sctx->host();
1374 LEX_CSTRING sctx_ip= sctx->ip();
1375 size_t user_host_len= (strxnmov(user_host_buff, MAX_USER_HOST_SIZE,
1376 sctx->priv_user().str, "[",
1377 sctx_user.length ? sctx_user.str : "", "] @ ",
1378 sctx_host.length ? sctx_host.str : "", " [",
1379 sctx_ip.length ? sctx_ip.str : "", "]",
1380 NullS) - user_host_buff);
1381 ulonglong current_utime= thd->current_utime();
1382 ulonglong query_utime, lock_utime;
1383 if (thd->start_utime)
1384 {
1385 query_utime= (current_utime - thd->start_utime);
1386 lock_utime= (thd->utime_after_lock - thd->start_utime);
1387 }
1388 else
1389 {
1390 query_utime= 0;
1391 lock_utime= 0;
1392 }
1393
1394 bool is_command= false;
1395 if (!query)
1396 {
1397 is_command= true;
1398 query= command_name[thd->get_command()].str;
1399 query_length= command_name[thd->get_command()].length;
1400 }
1401
1402 bool error= false;
1403 for (Log_event_handler **current_handler= slow_log_handler_list;
1404 *current_handler ;)
1405 {
1406 error|= (*current_handler++)->log_slow(thd, current_utime,
1407 (thd->start_time.tv_sec * 1000000) +
1408 thd->start_time.tv_usec,
1409 user_host_buff, user_host_len,
1410 query_utime, lock_utime, is_command,
1411 query, query_length);
1412 }
1413
1414 mysql_rwlock_unlock(&LOCK_logger);
1415
1416 return error;
1417 }
1418
1419
1420 /**
1421 Check if a given command should be logged to the general log.
1422
1423 @param thd Thread handle
1424 @param command SQL command
1425
1426 @return true if command should be logged, false otherwise.
1427 */
log_command(THD * thd,enum_server_command command)1428 static bool log_command(THD *thd, enum_server_command command)
1429 {
1430 if (what_to_log & (1L << (uint) command))
1431 {
1432 if ((thd->variables.option_bits & OPTION_LOG_OFF)
1433 #ifndef NO_EMBEDDED_ACCESS_CHECKS
1434 && (thd->security_context()->check_access(SUPER_ACL))
1435 #endif
1436 )
1437 {
1438 /* No logging */
1439 return false;
1440 }
1441 return true;
1442 }
1443 return false;
1444 }
1445
1446
general_log_write(THD * thd,enum_server_command command,const char * query,size_t query_length)1447 bool Query_logger::general_log_write(THD *thd, enum_server_command command,
1448 const char *query, size_t query_length)
1449 {
1450 #ifndef EMBEDDED_LIBRARY
1451 /* Send a general log message to the audit API. */
1452 mysql_audit_general_log(thd, command_name[(uint) command].str,
1453 command_name[(uint) command].length);
1454 #endif
1455
1456 /*
1457 Do we want to log this kind of command?
1458 Is general log enabled?
1459 Any active handlers?
1460 */
1461 if (!log_command(thd, command) ||
1462 !opt_general_log ||
1463 !(*general_log_handler_list))
1464 return false;
1465
1466 mysql_rwlock_rdlock(&LOCK_logger);
1467
1468 char user_host_buff[MAX_USER_HOST_SIZE + 1];
1469 size_t user_host_len= make_user_name(thd->security_context(), user_host_buff);
1470 ulonglong current_utime= thd->current_utime();
1471
1472 bool error= false;
1473 for (Log_event_handler **current_handler= general_log_handler_list;
1474 *current_handler; )
1475 {
1476 error|= (*current_handler++)->log_general(thd, current_utime, user_host_buff,
1477 user_host_len, thd->thread_id(),
1478 command_name[(uint) command].str,
1479 command_name[(uint) command].length,
1480 query, query_length,
1481 thd->variables.character_set_client);
1482 }
1483 mysql_rwlock_unlock(&LOCK_logger);
1484
1485 return error;
1486 }
1487
1488
general_log_print(THD * thd,enum_server_command command,const char * format,...)1489 bool Query_logger::general_log_print(THD *thd, enum_server_command command,
1490 const char *format, ...)
1491 {
1492 /*
1493 Do we want to log this kind of command?
1494 Is general log enabled?
1495 Any active handlers?
1496 */
1497 if (!log_command(thd, command) ||
1498 !opt_general_log ||
1499 !(*general_log_handler_list))
1500 {
1501 #ifndef EMBEDDED_LIBRARY
1502 /* Send a general log message to the audit API. */
1503 mysql_audit_general_log(thd, command_name[(uint) command].str,
1504 command_name[(uint) command].length);
1505 #endif
1506 return false;
1507 }
1508
1509 size_t message_buff_len= 0;
1510 char message_buff[MAX_LOG_BUFFER_SIZE];
1511
1512 /* prepare message */
1513 if (format)
1514 {
1515 va_list args;
1516 va_start(args, format);
1517 message_buff_len= my_vsnprintf(message_buff, sizeof(message_buff),
1518 format, args);
1519 va_end(args);
1520 }
1521 else
1522 message_buff[0]= '\0';
1523
1524 return general_log_write(thd, command, message_buff, message_buff_len);
1525 }
1526
1527
init_query_log(enum_log_table_type log_type,ulonglong log_printer)1528 void Query_logger::init_query_log(enum_log_table_type log_type,
1529 ulonglong log_printer)
1530 {
1531 if (log_type == QUERY_LOG_SLOW)
1532 {
1533 if (log_printer & LOG_NONE)
1534 {
1535 slow_log_handler_list[0]= NULL;
1536 return;
1537 }
1538
1539 switch (log_printer) {
1540 case LOG_FILE:
1541 slow_log_handler_list[0]= file_log_handler;
1542 slow_log_handler_list[1]= NULL;
1543 break;
1544 case LOG_TABLE:
1545 slow_log_handler_list[0]= &table_log_handler;
1546 slow_log_handler_list[1]= NULL;
1547 break;
1548 case LOG_TABLE|LOG_FILE:
1549 slow_log_handler_list[0]= file_log_handler;
1550 slow_log_handler_list[1]= &table_log_handler;
1551 slow_log_handler_list[2]= NULL;
1552 break;
1553 }
1554 }
1555 else if (log_type == QUERY_LOG_GENERAL)
1556 {
1557 if (log_printer & LOG_NONE)
1558 {
1559 general_log_handler_list[0]= NULL;
1560 return;
1561 }
1562
1563 switch (log_printer) {
1564 case LOG_FILE:
1565 general_log_handler_list[0]= file_log_handler;
1566 general_log_handler_list[1]= NULL;
1567 break;
1568 case LOG_TABLE:
1569 general_log_handler_list[0]= &table_log_handler;
1570 general_log_handler_list[1]= NULL;
1571 break;
1572 case LOG_TABLE|LOG_FILE:
1573 general_log_handler_list[0]= file_log_handler;
1574 general_log_handler_list[1]= &table_log_handler;
1575 general_log_handler_list[2]= NULL;
1576 break;
1577 }
1578 }
1579 else
1580 assert(false);
1581 }
1582
1583
set_handlers(ulonglong log_printer)1584 void Query_logger::set_handlers(ulonglong log_printer)
1585 {
1586 mysql_rwlock_wrlock(&LOCK_logger);
1587
1588 init_query_log(QUERY_LOG_SLOW, log_printer);
1589 init_query_log(QUERY_LOG_GENERAL, log_printer);
1590
1591 mysql_rwlock_unlock(&LOCK_logger);
1592 }
1593
1594
activate_log_handler(THD * thd,enum_log_table_type log_type)1595 bool Query_logger::activate_log_handler(THD* thd, enum_log_table_type log_type)
1596 {
1597 bool res= false;
1598 mysql_rwlock_wrlock(&LOCK_logger);
1599 if (table_log_handler.activate_log(thd, log_type) ||
1600 file_log_handler->get_query_log(log_type)->open())
1601 res= true;
1602 else
1603 init_query_log(log_type, log_output_options);
1604 mysql_rwlock_unlock(&LOCK_logger);
1605 return res;
1606 }
1607
1608
deactivate_log_handler(enum_log_table_type log_type)1609 void Query_logger::deactivate_log_handler(enum_log_table_type log_type)
1610 {
1611 mysql_rwlock_wrlock(&LOCK_logger);
1612 file_log_handler->get_query_log(log_type)->close();
1613 // table_list_handler has no state, nothing to close
1614 mysql_rwlock_unlock(&LOCK_logger);
1615 }
1616
1617
reopen_log_file(enum_log_table_type log_type)1618 bool Query_logger::reopen_log_file(enum_log_table_type log_type)
1619 {
1620 mysql_rwlock_wrlock(&LOCK_logger);
1621 file_log_handler->get_query_log(log_type)->close();
1622 bool res= file_log_handler->get_query_log(log_type)->open();
1623 mysql_rwlock_unlock(&LOCK_logger);
1624 return res;
1625 }
1626
1627
1628 enum_log_table_type
check_if_log_table(TABLE_LIST * table_list,bool check_if_opened) const1629 Query_logger::check_if_log_table(TABLE_LIST *table_list,
1630 bool check_if_opened) const
1631 {
1632 if (table_list->db_length == MYSQL_SCHEMA_NAME.length &&
1633 !my_strcasecmp(system_charset_info,
1634 table_list->db, MYSQL_SCHEMA_NAME.str))
1635 {
1636 if (table_list->table_name_length == GENERAL_LOG_NAME.length &&
1637 !my_strcasecmp(system_charset_info,
1638 table_list->table_name, GENERAL_LOG_NAME.str))
1639 {
1640 if (!check_if_opened || is_log_table_enabled(QUERY_LOG_GENERAL))
1641 return QUERY_LOG_GENERAL;
1642 return QUERY_LOG_NONE;
1643 }
1644
1645 if (table_list->table_name_length == SLOW_LOG_NAME.length &&
1646 !my_strcasecmp(system_charset_info,
1647 table_list->table_name, SLOW_LOG_NAME.str))
1648 {
1649 if (!check_if_opened || is_log_table_enabled(QUERY_LOG_SLOW))
1650 return QUERY_LOG_SLOW;
1651 return QUERY_LOG_NONE;
1652 }
1653 }
1654 return QUERY_LOG_NONE;
1655 }
1656
1657
1658 Query_logger query_logger;
1659
1660
make_query_log_name(char * buff,enum_log_table_type log_type)1661 char *make_query_log_name(char *buff, enum_log_table_type log_type)
1662 {
1663 const char* log_ext= "";
1664 if (log_type == QUERY_LOG_GENERAL)
1665 log_ext= ".log";
1666 else if (log_type == QUERY_LOG_SLOW)
1667 log_ext= "-slow.log";
1668 else
1669 assert(false);
1670
1671 strmake(buff, default_logfile_name, FN_REFLEN-5);
1672 return fn_format(buff, buff, mysql_real_data_home, log_ext,
1673 MYF(MY_UNPACK_FILENAME|MY_REPLACE_EXT));
1674 }
1675
1676
log_slow_applicable(THD * thd)1677 bool log_slow_applicable(THD *thd)
1678 {
1679 DBUG_ENTER("log_slow_applicable");
1680
1681 /*
1682 The following should never be true with our current code base,
1683 but better to keep this here so we don't accidently try to log a
1684 statement in a trigger or stored function
1685 */
1686 if (unlikely(thd->in_sub_stmt))
1687 DBUG_RETURN(false); // Don't set time for sub stmt
1688
1689 /*
1690 Do not log administrative statements unless the appropriate option is
1691 set.
1692 */
1693 if (thd->enable_slow_log && opt_slow_log)
1694 {
1695 bool warn_no_index= ((thd->server_status &
1696 (SERVER_QUERY_NO_INDEX_USED |
1697 SERVER_QUERY_NO_GOOD_INDEX_USED)) &&
1698 opt_log_queries_not_using_indexes &&
1699 !(sql_command_flags[thd->lex->sql_command] &
1700 CF_STATUS_COMMAND));
1701 bool log_this_query= ((thd->server_status & SERVER_QUERY_WAS_SLOW) ||
1702 warn_no_index) &&
1703 (thd->get_examined_row_count() >=
1704 thd->variables.min_examined_row_limit);
1705 bool suppress_logging= log_throttle_qni.log(thd, warn_no_index);
1706
1707 if (!suppress_logging && log_this_query)
1708 DBUG_RETURN(true);
1709 }
1710 DBUG_RETURN(false);
1711 }
1712
1713
log_slow_do(THD * thd)1714 void log_slow_do(THD *thd)
1715 {
1716 THD_STAGE_INFO(thd, stage_logging_slow_query);
1717 thd->status_var.long_query_count++;
1718
1719 if (thd->rewritten_query().length())
1720 query_logger.slow_log_write(thd,
1721 thd->rewritten_query().ptr(),
1722 thd->rewritten_query().length());
1723 else
1724 query_logger.slow_log_write(thd, thd->query().str, thd->query().length);
1725 }
1726
1727
log_slow_statement(THD * thd)1728 void log_slow_statement(THD *thd)
1729 {
1730 if (log_slow_applicable(thd))
1731 log_slow_do(thd);
1732 }
1733
1734
1735 #ifdef MYSQL_SERVER
new_window(ulonglong now)1736 void Log_throttle::new_window(ulonglong now)
1737 {
1738 count= 0;
1739 window_end= now + window_size;
1740 }
1741
1742
new_window(ulonglong now)1743 void Slow_log_throttle::new_window(ulonglong now)
1744 {
1745 Log_throttle::new_window(now);
1746 total_exec_time= 0;
1747 total_lock_time= 0;
1748 }
1749
1750
Slow_log_throttle(ulong * threshold,mysql_mutex_t * lock,ulong window_usecs,bool (* logger)(THD *,const char *,size_t),const char * msg)1751 Slow_log_throttle::Slow_log_throttle(ulong *threshold, mysql_mutex_t *lock,
1752 ulong window_usecs,
1753 bool (*logger)(THD *, const char *, size_t),
1754 const char *msg)
1755 : Log_throttle(window_usecs, msg), total_exec_time(0), total_lock_time(0),
1756 rate(threshold), log_summary(logger), LOCK_log_throttle(lock)
1757 { }
1758
1759
prepare_summary(ulong rate)1760 ulong Log_throttle::prepare_summary(ulong rate)
1761 {
1762 ulong ret= 0;
1763 /*
1764 Previous throttling window is over or rate changed.
1765 Return the number of lines we throttled.
1766 */
1767 if (count > rate)
1768 {
1769 ret= count - rate;
1770 count= 0; // prevent writing it again.
1771 }
1772
1773 return ret;
1774 }
1775
1776
print_summary(THD * thd,ulong suppressed,ulonglong print_lock_time,ulonglong print_exec_time)1777 void Slow_log_throttle::print_summary(THD *thd, ulong suppressed,
1778 ulonglong print_lock_time,
1779 ulonglong print_exec_time)
1780 {
1781 /*
1782 We synthesize these values so the totals in the log will be
1783 correct (just in case somebody analyses them), even if the
1784 start/stop times won't be (as they're an aggregate which will
1785 usually mostly lie within [ window_end - window_size ; window_end ]
1786 */
1787 ulonglong save_start_utime= thd->start_utime;
1788 ulonglong save_utime_after_lock= thd->utime_after_lock;
1789 Security_context *save_sctx= thd->security_context();
1790
1791 char buf[128];
1792
1793 my_snprintf(buf, sizeof(buf), summary_template, suppressed);
1794
1795 mysql_mutex_lock(&thd->LOCK_thd_data);
1796 thd->start_utime= thd->current_utime() - print_exec_time;
1797 thd->utime_after_lock= thd->start_utime + print_lock_time;
1798 thd->set_security_context(&aggregate_sctx);
1799 mysql_mutex_unlock(&thd->LOCK_thd_data);
1800
1801 (*log_summary)(thd, buf, strlen(buf));
1802
1803 mysql_mutex_lock(&thd->LOCK_thd_data);
1804 thd->set_security_context(save_sctx);
1805 thd->start_utime = save_start_utime;
1806 thd->utime_after_lock= save_utime_after_lock;
1807 mysql_mutex_unlock(&thd->LOCK_thd_data);
1808 }
1809
1810
flush(THD * thd)1811 bool Slow_log_throttle::flush(THD *thd)
1812 {
1813 // Write summary if we throttled.
1814 mysql_mutex_lock(LOCK_log_throttle);
1815 ulonglong print_lock_time= total_lock_time;
1816 ulonglong print_exec_time= total_exec_time;
1817 ulong suppressed_count= prepare_summary(*rate);
1818 mysql_mutex_unlock(LOCK_log_throttle);
1819 if (suppressed_count > 0)
1820 {
1821 print_summary(thd, suppressed_count, print_lock_time, print_exec_time);
1822 return true;
1823 }
1824 return false;
1825 }
1826
1827
log(THD * thd,bool eligible)1828 bool Slow_log_throttle::log(THD *thd, bool eligible)
1829 {
1830 bool suppress_current= false;
1831
1832 /*
1833 If throttling is enabled, we might have to write a summary even if
1834 the current query is not of the type we handle.
1835 */
1836 if (*rate > 0)
1837 {
1838 mysql_mutex_lock(LOCK_log_throttle);
1839
1840 ulong suppressed_count= 0;
1841 ulonglong print_lock_time= total_lock_time;
1842 ulonglong print_exec_time= total_exec_time;
1843 ulonglong end_utime_of_query= thd->current_utime();
1844
1845 /*
1846 If the window has expired, we'll try to write a summary line.
1847 The subroutine will know whether we actually need to.
1848 */
1849 if (!in_window(end_utime_of_query))
1850 {
1851 suppressed_count= prepare_summary(*rate);
1852 // start new window only if this is the statement type we handle
1853 if (eligible)
1854 new_window(end_utime_of_query);
1855 }
1856 if (eligible && inc_log_count(*rate))
1857 {
1858 /*
1859 Current query's logging should be suppressed.
1860 Add its execution time and lock time to totals for the current window.
1861 */
1862 total_exec_time += (end_utime_of_query - thd->start_utime);
1863 total_lock_time += (thd->utime_after_lock - thd->start_utime);
1864 suppress_current= true;
1865 }
1866
1867 mysql_mutex_unlock(LOCK_log_throttle);
1868
1869 /*
1870 print_summary() is deferred until after we release the locks to
1871 avoid congestion. All variables we hand in are local to the caller,
1872 so things would even be safe if print_summary() hadn't finished by the
1873 time the next one comes around (60s later at the earliest for now).
1874 The current design will produce correct data, but does not guarantee
1875 order (there is a theoretical race condition here where the above
1876 new_window()/unlock() may enable a different thread to print a warning
1877 for the new window before the current thread gets to print_summary().
1878 If the requirements ever change, add a print_lock to the object that
1879 is held during print_summary(), AND that is briefly locked before
1880 returning from this function if(eligible && !suppress_current).
1881 This should ensure correct ordering of summaries with regard to any
1882 follow-up summaries as well as to any (non-suppressed) warnings (of
1883 the type we handle) from the next window.
1884 */
1885 if (suppressed_count > 0)
1886 print_summary(thd, suppressed_count, print_lock_time, print_exec_time);
1887 }
1888
1889 return suppress_current;
1890 }
1891
1892
log()1893 bool Error_log_throttle::log()
1894 {
1895 ulonglong end_utime_of_query= my_micro_time();
1896 DBUG_EXECUTE_IF("simulate_error_throttle_expiry",
1897 end_utime_of_query+=Log_throttle::LOG_THROTTLE_WINDOW_SIZE;);
1898
1899 /*
1900 If the window has expired, we'll try to write a summary line.
1901 The subroutine will know whether we actually need to.
1902 */
1903 if (!in_window(end_utime_of_query))
1904 {
1905 ulong suppressed_count= prepare_summary(1);
1906
1907 new_window(end_utime_of_query);
1908
1909 if (suppressed_count > 0)
1910 print_summary(suppressed_count);
1911 }
1912
1913 /*
1914 If this is a first error in the current window then do not suppress it.
1915 */
1916 return inc_log_count(1);
1917 }
1918
1919
flush()1920 bool Error_log_throttle::flush()
1921 {
1922 // Write summary if we throttled.
1923 ulong suppressed_count= prepare_summary(1);
1924 if (suppressed_count > 0)
1925 {
1926 print_summary(suppressed_count);
1927 return true;
1928 }
1929 return false;
1930 }
1931
1932
slow_log_write(THD * thd,const char * query,size_t query_length)1933 static bool slow_log_write(THD *thd, const char *query, size_t query_length)
1934 {
1935 return opt_slow_log && query_logger.slow_log_write(thd, query, query_length);
1936 }
1937
1938
1939 Slow_log_throttle log_throttle_qni(&opt_log_throttle_queries_not_using_indexes,
1940 &LOCK_log_throttle_qni,
1941 Log_throttle::LOG_THROTTLE_WINDOW_SIZE,
1942 slow_log_write,
1943 "throttle: %10lu 'index "
1944 "not used' warning(s) suppressed.");
1945 #endif // MYSQL_SERVER
1946
1947 ////////////////////////////////////////////////////////////
1948 //
1949 // Error Log
1950 //
1951 ////////////////////////////////////////////////////////////
1952
1953 static bool error_log_initialized= false;
1954 // This mutex prevents fprintf from different threads from being interleaved.
1955 // It also prevents reopen while we are in the process of logging.
1956 static mysql_mutex_t LOCK_error_log;
1957 // This variable is different from log_error_dest.
1958 // E.g. log_error_dest is "stderr" if we are not logging to file.
1959 static const char *error_log_file= NULL;
1960 static bool error_log_buffering= true;
1961 static std::string *buffered_messages= NULL;
1962
1963
flush_error_log_messages()1964 void flush_error_log_messages()
1965 {
1966 if (buffered_messages && !buffered_messages->empty())
1967 {
1968 fprintf(stderr, "%s", buffered_messages->c_str());
1969 fflush(stderr);
1970 delete buffered_messages;
1971 buffered_messages= NULL;
1972 }
1973 error_log_buffering= false;
1974 }
1975
1976
init_error_log()1977 void init_error_log()
1978 {
1979 assert(!error_log_initialized);
1980 mysql_mutex_init(key_LOCK_error_log, &LOCK_error_log, MY_MUTEX_INIT_FAST);
1981 error_log_initialized= true;
1982 }
1983
1984
open_error_log(const char * filename,bool get_lock)1985 bool open_error_log(const char *filename, bool get_lock)
1986 {
1987 assert(filename);
1988 int retries= 2, errors= 0;
1989
1990 do
1991 {
1992 errors= 0;
1993 if (!my_freopen(filename, "a", stderr))
1994 errors++;
1995 #ifndef EMBEDDED_LIBRARY
1996 if (!my_freopen(filename, "a", stdout))
1997 errors++;
1998 #endif
1999 }
2000 while (retries-- && errors);
2001
2002 if (errors)
2003 {
2004 char errbuf[MYSYS_STRERROR_SIZE];
2005 if (get_lock)
2006 mysql_mutex_unlock(&LOCK_error_log);
2007 sql_print_error(ER_DEFAULT(ER_CANT_OPEN_ERROR_LOG), filename,
2008 ": ", my_strerror(errbuf, sizeof(errbuf), errno));
2009 flush_error_log_messages();
2010 if (get_lock)
2011 mysql_mutex_lock(&LOCK_error_log);
2012 return true;
2013 }
2014
2015 /* The error stream must be unbuffered. */
2016 setbuf(stderr, NULL);
2017
2018 error_log_file= filename; // Remember name for later reopen
2019
2020 // Write any messages buffered while we were figuring out the filename
2021 flush_error_log_messages();
2022 return false;
2023 }
2024
2025
destroy_error_log()2026 void destroy_error_log()
2027 {
2028 // We should have flushed before this...
2029 assert(!error_log_buffering);
2030 // ... but play it safe on release builds
2031 flush_error_log_messages();
2032 if (error_log_initialized)
2033 {
2034 error_log_initialized= false;
2035 error_log_file= NULL;
2036 mysql_mutex_destroy(&LOCK_error_log);
2037 }
2038 }
2039
2040
reopen_error_log()2041 bool reopen_error_log()
2042 {
2043 if (!error_log_file)
2044 return false;
2045 mysql_mutex_lock(&LOCK_error_log);
2046 bool result= open_error_log(error_log_file, true);
2047 mysql_mutex_unlock(&LOCK_error_log);
2048 if (result)
2049 my_error(ER_CANT_OPEN_ERROR_LOG, MYF(0), error_log_file, ".", "");
2050 return result;
2051 }
2052
2053
2054 #ifndef EMBEDDED_LIBRARY
print_buffer_to_file(enum loglevel level,const char * buffer,size_t length)2055 static void print_buffer_to_file(enum loglevel level, const char *buffer,
2056 size_t length)
2057 {
2058 DBUG_ENTER("print_buffer_to_file");
2059 DBUG_PRINT("enter",("buffer: %s", buffer));
2060
2061 char my_timestamp[iso8601_size];
2062
2063 my_thread_id thread_id= 0;
2064
2065 /*
2066 If the thread system is up and running and we're in a connection,
2067 add the connection ID to the log-line, otherwise 0.
2068 */
2069 if (THR_THD_initialized && (current_thd != NULL))
2070 thread_id= current_thd->thread_id();
2071
2072 make_iso8601_timestamp(my_timestamp);
2073
2074 /*
2075 This must work even if the mutex has not been initialized yet.
2076 At that point we should still be single threaded so that it is
2077 safe to write without mutex.
2078 */
2079 if (error_log_initialized)
2080 mysql_mutex_lock(&LOCK_error_log);
2081
2082 if (error_log_buffering)
2083 {
2084 // Logfile not open yet, buffer messages for now.
2085 if (buffered_messages == NULL)
2086 buffered_messages= new (std::nothrow) std::string();
2087 std::ostringstream s;
2088 s << my_timestamp << " " << thread_id;
2089 if (level == ERROR_LEVEL)
2090 s << " [ERROR] ";
2091 else if (level == WARNING_LEVEL)
2092 s << " [Warning] ";
2093 else
2094 s << " [Note] ";
2095 s << buffer << std::endl;
2096 buffered_messages->append(s.str());
2097 }
2098 else
2099 {
2100 fprintf(stderr, "%s %u [%s] %.*s\n",
2101 my_timestamp,
2102 thread_id,
2103 (level == ERROR_LEVEL ? "ERROR" : level == WARNING_LEVEL ?
2104 "Warning" : "Note"),
2105 (int) length, buffer);
2106
2107 fflush(stderr);
2108 }
2109
2110 if (error_log_initialized)
2111 mysql_mutex_unlock(&LOCK_error_log);
2112 DBUG_VOID_RETURN;
2113 }
2114
2115
error_log_print(enum loglevel level,const char * format,va_list args)2116 void error_log_print(enum loglevel level, const char *format, va_list args)
2117 {
2118 char buff[MAX_LOG_BUFFER_SIZE];
2119 size_t length;
2120 DBUG_ENTER("error_log_print");
2121
2122 if (static_cast<ulong>(level) < log_error_verbosity)
2123 {
2124 length= my_vsnprintf(buff, sizeof(buff), format, args);
2125 print_buffer_to_file(level, buff, length);
2126
2127 if (log_syslog_enabled
2128 #ifdef _WIN32
2129 && !abort_loop // Don't write to the eventlog during shutdown.
2130 #endif
2131 )
2132 {
2133 my_syslog(system_charset_info, level, buff);
2134 }
2135 }
2136
2137 DBUG_VOID_RETURN;
2138 }
2139 #endif /* EMBEDDED_LIBRARY */
2140
2141
sql_print_error(const char * format,...)2142 void sql_print_error(const char *format, ...)
2143 {
2144 va_list args;
2145 DBUG_ENTER("sql_print_error");
2146
2147 va_start(args, format);
2148 error_log_print(ERROR_LEVEL, format, args);
2149 va_end(args);
2150
2151 DBUG_VOID_RETURN;
2152 }
2153
2154
sql_print_warning(const char * format,...)2155 void sql_print_warning(const char *format, ...)
2156 {
2157 va_list args;
2158 DBUG_ENTER("sql_print_warning");
2159
2160 va_start(args, format);
2161 error_log_print(WARNING_LEVEL, format, args);
2162 va_end(args);
2163
2164 DBUG_VOID_RETURN;
2165 }
2166
2167
sql_print_information(const char * format,...)2168 void sql_print_information(const char *format, ...)
2169 {
2170 va_list args;
2171 DBUG_ENTER("sql_print_information");
2172
2173 va_start(args, format);
2174 error_log_print(INFORMATION_LEVEL, format, args);
2175 va_end(args);
2176
2177 DBUG_VOID_RETURN;
2178 }
2179
2180
2181 extern "C"
my_plugin_log_message(MYSQL_PLUGIN * plugin_ptr,plugin_log_level level,const char * format,...)2182 int my_plugin_log_message(MYSQL_PLUGIN *plugin_ptr, plugin_log_level level,
2183 const char *format, ...)
2184 {
2185 char format2[MAX_LOG_BUFFER_SIZE];
2186 loglevel lvl;
2187 struct st_plugin_int *plugin = static_cast<st_plugin_int *> (*plugin_ptr);
2188 va_list args;
2189
2190 assert(level >= MY_ERROR_LEVEL || level <= MY_INFORMATION_LEVEL);
2191
2192 switch (level)
2193 {
2194 case MY_ERROR_LEVEL: lvl= ERROR_LEVEL; break;
2195 case MY_WARNING_LEVEL: lvl= WARNING_LEVEL; break;
2196 case MY_INFORMATION_LEVEL: lvl= INFORMATION_LEVEL; break;
2197 default: return 1;
2198 }
2199
2200 va_start(args, format);
2201 my_snprintf(format2, sizeof (format2) - 1, "Plugin %.*s reported: '%s'",
2202 (int) plugin->name.length, plugin->name.str, format);
2203 error_log_print(lvl, format2, args);
2204 va_end(args);
2205 return 0;
2206 }
2207