« back to all changes in this revision
Viewing changes to drizzled/log.cc
- browse files at revision 458
- compare with another revision
- download diff
- download tarball
- view history from revision 458
- Committer: Monty Taylor
- Date: 2008-10-04 03:14:52 UTC
- mfrom: (438.1.5 drizzle)
- Revision ID: monty@inaugust.com-20081004031452-v1evilfl3nvmztgl
Merged from trunk.
added
removed
drizzled/log.cc
213
213
return 0;
214
214
}
215
215
216
/* log event handlers */
217
218
bool Log_to_file_event_handler::
219
log_error(enum loglevel level, const char *format,
220
va_list args)
221
{
222
return vprint_msg_to_log(level, format, args);
223
}
224
225
void Log_to_file_event_handler::init_pthread_objects()
226
{
227
mysql_log.init_pthread_objects();
228
mysql_slow_log.init_pthread_objects();
229
}
230
231
232
/** Wrapper around DRIZZLE_LOG::write() for slow log. */
233
234
bool Log_to_file_event_handler::
235
log_slow(THD *thd, time_t current_time, time_t query_start_arg,
236
const char *user_host, uint user_host_len,
237
uint64_t query_utime, uint64_t lock_utime, bool is_command,
238
const char *sql_text, uint sql_text_len)
239
{
240
return mysql_slow_log.write(thd, current_time, query_start_arg,
241
user_host, user_host_len,
242
query_utime, lock_utime, is_command,
243
sql_text, sql_text_len);
244
}
245
246
247
/**
248
Wrapper around DRIZZLE_LOG::write() for general log. We need it since we
249
want all log event handlers to have the same signature.
250
*/
251
252
bool Log_to_file_event_handler::
253
log_general(THD *thd __attribute__((unused)),
254
time_t event_time, const char *user_host,
255
uint user_host_len, int thread_id,
256
const char *command_type, uint command_type_len,
257
const char *sql_text, uint sql_text_len,
258
const CHARSET_INFO * const client_cs __attribute__((unused)))
259
{
260
return mysql_log.write(event_time, user_host, user_host_len,
261
thread_id, command_type, command_type_len,
262
sql_text, sql_text_len);
263
}
264
265
266
bool Log_to_file_event_handler::init()
267
{
268
if (!is_initialized)
269
{
270
if (opt_slow_log)
271
mysql_slow_log.open_slow_log(sys_var_slow_log_path.value);
272
273
if (opt_log)
274
mysql_log.open_query_log(sys_var_general_log_path.value);
275
276
is_initialized= true;
277
}
278
279
return false;
280
}
281
282
283
void Log_to_file_event_handler::cleanup()
284
{
285
mysql_log.cleanup();
286
mysql_slow_log.cleanup();
287
}
288
289
void Log_to_file_event_handler::flush()
290
{
291
/* reopen log files */
292
if (opt_log)
293
mysql_log.reopen_file();
294
if (opt_slow_log)
295
mysql_slow_log.reopen_file();
296
}
297
298
216
/*
299
217
Log error with all enabled log event handlers
300
218
329
247
{
330
248
assert(inited == 1);
331
249
rwlock_destroy(&LOCK_logger);
332
if (file_log_handler)
333
file_log_handler->cleanup();
334
250
}
335
251
336
252
337
253
void LOGGER::cleanup_end()
338
254
{
339
255
assert(inited == 1);
340
if (file_log_handler)
341
delete file_log_handler;
342
256
}
343
257
344
258
351
265
assert(inited == 0);
352
266
inited= 1;
353
267
354
/*
355
Here we create file log handler. We don't do it for the table log handler
356
here as it cannot be created so early. The reason is THD initialization,
357
which depends on the system variables (parsed later).
358
*/
359
if (!file_log_handler)
360
file_log_handler= new Log_to_file_event_handler;
361
362
268
/* by default we use traditional error log */
363
269
init_error_log(LOG_FILE);
364
270
365
file_log_handler->init_pthread_objects();
366
271
my_rwlock_init(&LOCK_logger, NULL);
367
272
}
368
273
377
282
*/
378
283
logger.lock_exclusive();
379
284
380
/* reopen log files */
381
file_log_handler->flush();
382
383
285
/* end of log flush */
384
286
logger.unlock();
385
287
return rc;
386
288
}
387
289
388
389
/*
390
Log slow query with all enabled log event handlers
391
392
SYNOPSIS
393
slow_log_print()
394
395
thd THD of the query being logged
396
query The query being logged
397
query_length The length of the query string
398
current_utime Current time in microseconds (from undefined start)
399
400
RETURN
401
FALSE OK
402
TRUE error occured
403
*/
404
405
bool LOGGER::slow_log_print(THD *thd, const char *query, uint query_length,
406
uint64_t current_utime)
407
408
{
409
bool error= false;
410
Log_event_handler **current_handler;
411
bool is_command= false;
412
char user_host_buff[MAX_USER_HOST_SIZE];
413
Security_context *sctx= thd->security_ctx;
414
uint user_host_len= 0;
415
uint64_t query_utime, lock_utime;
416
417
/*
418
Print the message to the buffer if we have slow log enabled
419
*/
420
421
if (*slow_log_handler_list)
422
{
423
time_t current_time;
424
425
/* do not log slow queries from replication threads */
426
if (thd->slave_thread && !opt_log_slow_slave_statements)
427
return 0;
428
429
lock_shared();
430
if (!opt_slow_log)
431
{
432
unlock();
433
return 0;
434
}
435
436
/* fill in user_host value: the format is "%s[%s] @ %s [%s]" */
437
user_host_len= (strxnmov(user_host_buff, MAX_USER_HOST_SIZE,
438
sctx->user, "[", sctx->user, "] @ ",
439
sctx->ip, " [",
440
sctx->ip, "]", NullS) -
441
user_host_buff);
442
443
current_time= my_time_possible_from_micro(current_utime);
444
if (thd->start_utime)
445
{
446
query_utime= (current_utime - thd->start_utime);
447
lock_utime= (thd->utime_after_lock - thd->start_utime);
448
}
449
else
450
{
451
query_utime= lock_utime= 0;
452
}
453
454
if (!query)
455
{
456
is_command= true;
457
query= command_name[thd->command].str;
458
query_length= command_name[thd->command].length;
459
}
460
461
for (current_handler= slow_log_handler_list; *current_handler ;)
462
error= (*current_handler++)->log_slow(thd, current_time, thd->start_time,
463
user_host_buff, user_host_len,
464
query_utime, lock_utime, is_command,
465
query, query_length) || error;
466
467
unlock();
468
}
469
return error;
470
}
471
472
bool LOGGER::general_log_write(THD *thd, enum enum_server_command command,
473
const char *query, uint query_length)
474
{
475
bool error= false;
476
Log_event_handler **current_handler= general_log_handler_list;
477
char user_host_buff[MAX_USER_HOST_SIZE];
478
Security_context *sctx= thd->security_ctx;
479
ulong id;
480
uint user_host_len= 0;
481
time_t current_time;
482
483
if (thd)
484
id= thd->thread_id; /* Normal thread */
485
else
486
id= 0; /* Log from connect handler */
487
488
lock_shared();
489
if (!opt_log)
490
{
491
unlock();
492
return 0;
493
}
494
user_host_len= strxnmov(user_host_buff, MAX_USER_HOST_SIZE,
495
sctx->user, "[",
496
sctx->user, "] @ ",
497
sctx->ip, " [",
498
sctx->ip, "]", NullS) -
499
user_host_buff;
500
501
current_time= my_time(0);
502
503
while (*current_handler)
504
error|= (*current_handler++)->
505
log_general(thd, current_time, user_host_buff,
506
user_host_len, id,
507
command_name[(uint) command].str,
508
command_name[(uint) command].length,
509
query, query_length,
510
thd->variables.character_set_client) || error;
511
unlock();
512
513
return error;
514
}
515
516
bool LOGGER::general_log_print(THD *thd, enum enum_server_command command,
517
const char *format, va_list args)
518
{
519
uint message_buff_len= 0;
520
char message_buff[MAX_LOG_BUFFER_SIZE];
521
522
/* prepare message */
523
if (format)
524
message_buff_len= vsnprintf(message_buff, sizeof(message_buff),
525
format, args);
526
else
527
message_buff[0]= '\0';
528
529
return general_log_write(thd, command, message_buff, message_buff_len);
530
}
531
532
290
void LOGGER::init_error_log(uint error_log_printer)
533
291
{
534
292
if (error_log_printer & LOG_NONE)
537
295
return;
538
296
}
539
297
540
switch (error_log_printer) {
541
case LOG_FILE:
542
error_log_handler_list[0]= file_log_handler;
543
error_log_handler_list[1]= 0;
544
break;
545
}
546
}
547
548
void LOGGER::init_slow_log(uint slow_log_printer)
549
{
550
if (slow_log_printer & LOG_NONE)
551
{
552
slow_log_handler_list[0]= 0;
553
return;
554
}
555
556
slow_log_handler_list[0]= file_log_handler;
557
slow_log_handler_list[1]= 0;
558
}
559
560
void LOGGER::init_general_log(uint general_log_printer)
561
{
562
if (general_log_printer & LOG_NONE)
563
{
564
general_log_handler_list[0]= 0;
565
return;
566
}
567
568
general_log_handler_list[0]= file_log_handler;
569
general_log_handler_list[1]= 0;
570
}
571
572
573
bool LOGGER::activate_log_handler(THD* thd __attribute__((unused)),
574
uint log_type)
575
{
576
DRIZZLE_QUERY_LOG *file_log;
577
bool res= false;
578
lock_exclusive();
579
switch (log_type) {
580
case QUERY_LOG_SLOW:
581
if (!opt_slow_log)
582
{
583
file_log= file_log_handler->get_mysql_slow_log();
584
585
file_log->open_slow_log(sys_var_slow_log_path.value);
586
init_slow_log(log_output_options);
587
opt_slow_log= true;
588
}
589
break;
590
case QUERY_LOG_GENERAL:
591
if (!opt_log)
592
{
593
file_log= file_log_handler->get_mysql_log();
594
595
file_log->open_query_log(sys_var_general_log_path.value);
596
init_general_log(log_output_options);
597
opt_log= true;
598
}
599
break;
600
default:
601
assert(0);
602
}
603
unlock();
604
return res;
605
}
606
607
608
void LOGGER::deactivate_log_handler(THD *thd __attribute__((unused)),
609
uint log_type)
610
{
611
bool *tmp_opt= 0;
612
DRIZZLE_LOG *file_log;
613
614
switch (log_type) {
615
case QUERY_LOG_SLOW:
616
tmp_opt= &opt_slow_log;
617
file_log= file_log_handler->get_mysql_slow_log();
618
break;
619
case QUERY_LOG_GENERAL:
620
tmp_opt= &opt_log;
621
file_log= file_log_handler->get_mysql_log();
622
break;
623
default:
624
assert(0); // Impossible
625
}
626
627
if (!(*tmp_opt))
628
return;
629
630
lock_exclusive();
631
file_log->close(0);
632
*tmp_opt= false;
633
unlock();
634
}
635
636
int LOGGER::set_handlers(uint error_log_printer,
637
uint slow_log_printer,
638
uint general_log_printer)
298
}
299
300
int LOGGER::set_handlers(uint error_log_printer)
639
301
{
640
302
/* error log table is not supported yet */
641
303
lock_exclusive();
642
304
643
305
init_error_log(error_log_printer);
644
init_slow_log(slow_log_printer);
645
init_general_log(general_log_printer);
646
647
306
unlock();
648
307
649
308
return 0;
1356
1015
}
1357
1016
1358
1017
1359
/*
1360
Reopen the log file
1361
1362
SYNOPSIS
1363
reopen_file()
1364
1365
DESCRIPTION
1366
Reopen the log file. The method is used during FLUSH LOGS
1367
and locks LOCK_log mutex
1368
*/
1369
1370
1371
void DRIZZLE_QUERY_LOG::reopen_file()
1372
{
1373
char *save_name;
1374
1375
if (!is_open())
1376
{
1377
return;
1378
}
1379
1380
pthread_mutex_lock(&LOCK_log);
1381
1382
save_name= name;
1383
name= 0; // Don't free name
1384
close(LOG_CLOSE_TO_BE_OPENED);
1385
1386
/*
1387
Note that at this point, log_state != LOG_CLOSED (important for is_open()).
1388
*/
1389
1390
open(save_name, log_type, 0, io_cache_type);
1391
my_free(save_name, MYF(0));
1392
1393
pthread_mutex_unlock(&LOCK_log);
1394
1395
return;
1396
}
1397
1398
1399
/*
1400
Write a command to traditional general log file
1401
1402
SYNOPSIS
1403
write()
1404
1405
event_time command start timestamp
1406
user_host the pointer to the string with user@host info
1407
user_host_len length of the user_host string. this is computed once
1408
and passed to all general log event handlers
1409
thread_id Id of the thread, issued a query
1410
command_type the type of the command being logged
1411
command_type_len the length of the string above
1412
sql_text the very text of the query being executed
1413
sql_text_len the length of sql_text string
1414
1415
DESCRIPTION
1416
1417
Log given command to to normal (not rotable) log file
1418
1419
RETURN
1420
FASE - OK
1421
TRUE - error occured
1422
*/
1423
1424
bool DRIZZLE_QUERY_LOG::write(time_t event_time,
1425
const char *user_host __attribute__((unused)),
1426
uint user_host_len __attribute__((unused)),
1427
int thread_id,
1428
const char *command_type, uint command_type_len,
1429
const char *sql_text, uint sql_text_len)
1430
{
1431
char buff[32];
1432
uint length= 0;
1433
char local_time_buff[MAX_TIME_SIZE];
1434
struct tm start;
1435
uint time_buff_len= 0;
1436
1437
(void) pthread_mutex_lock(&LOCK_log);
1438
1439
/* Test if someone closed between the is_open test and lock */
1440
if (is_open())
1441
{
1442
/* Note that my_b_write() assumes it knows the length for this */
1443
if (event_time != last_time)
1444
{
1445
last_time= event_time;
1446
1447
localtime_r(&event_time, &start);
1448
1449
time_buff_len= snprintf(local_time_buff, MAX_TIME_SIZE,
1450
"%02d%02d%02d %2d:%02d:%02d",
1451
start.tm_year % 100, start.tm_mon + 1,
1452
start.tm_mday, start.tm_hour,
1453
start.tm_min, start.tm_sec);
1454
1455
if (my_b_write(&log_file, (uchar*) local_time_buff, time_buff_len))
1456
goto err;
1457
}
1458
else
1459
if (my_b_write(&log_file, (uchar*) "\t\t" ,2) < 0)
1460
goto err;
1461
1462
/* command_type, thread_id */
1463
length= snprintf(buff, 32, "%5ld ", (long) thread_id);
1464
1465
if (my_b_write(&log_file, (uchar*) buff, length))
1466
goto err;
1467
1468
if (my_b_write(&log_file, (uchar*) command_type, command_type_len))
1469
goto err;
1470
1471
if (my_b_write(&log_file, (uchar*) "\t", 1))
1472
goto err;
1473
1474
/* sql_text */
1475
if (my_b_write(&log_file, (uchar*) sql_text, sql_text_len))
1476
goto err;
1477
1478
if (my_b_write(&log_file, (uchar*) "\n", 1) ||
1479
flush_io_cache(&log_file))
1480
goto err;
1481
}
1482
1483
(void) pthread_mutex_unlock(&LOCK_log);
1484
return false;
1485
err:
1486
1487
if (!write_error)
1488
{
1489
write_error= 1;
1490
sql_print_error(ER(ER_ERROR_ON_WRITE), name, errno);
1491
}
1492
(void) pthread_mutex_unlock(&LOCK_log);
1493
return true;
1494
}
1495
1496
1497
/*
1498
Log a query to the traditional slow log file
1499
1500
SYNOPSIS
1501
write()
1502
1503
thd THD of the query
1504
current_time current timestamp
1505
query_start_arg command start timestamp
1506
user_host the pointer to the string with user@host info
1507
user_host_len length of the user_host string. this is computed once
1508
and passed to all general log event handlers
1509
query_utime Amount of time the query took to execute (in microseconds)
1510
lock_utime Amount of time the query was locked (in microseconds)
1511
is_command The flag, which determines, whether the sql_text is a
1512
query or an administrator command.
1513
sql_text the very text of the query or administrator command
1514
processed
1515
sql_text_len the length of sql_text string
1516
1517
DESCRIPTION
1518
1519
Log a query to the slow log file.
1520
1521
RETURN
1522
FALSE - OK
1523
TRUE - error occured
1524
*/
1525
1526
bool DRIZZLE_QUERY_LOG::write(THD *thd, time_t current_time,
1527
time_t query_start_arg __attribute__((unused)),
1528
const char *user_host,
1529
uint user_host_len, uint64_t query_utime,
1530
uint64_t lock_utime, bool is_command,
1531
const char *sql_text, uint sql_text_len)
1532
{
1533
bool error= 0;
1534
1535
(void) pthread_mutex_lock(&LOCK_log);
1536
1537
if (!is_open())
1538
{
1539
(void) pthread_mutex_unlock(&LOCK_log);
1540
return(0);
1541
}
1542
1543
if (is_open())
1544
{ // Safety agains reopen
1545
int tmp_errno= 0;
1546
char buff[80], *end;
1547
char query_time_buff[22+7], lock_time_buff[22+7];
1548
uint buff_len;
1549
end= buff;
1550
1551
{
1552
if (current_time != last_time)
1553
{
1554
last_time= current_time;
1555
struct tm start;
1556
localtime_r(¤t_time, &start);
1557
1558
buff_len= snprintf(buff, sizeof buff,
1559
"# Time: %02d%02d%02d %2d:%02d:%02d\n",
1560
start.tm_year % 100, start.tm_mon + 1,
1561
start.tm_mday, start.tm_hour,
1562
start.tm_min, start.tm_sec);
1563
1564
/* Note that my_b_write() assumes it knows the length for this */
1565
if (my_b_write(&log_file, (uchar*) buff, buff_len))
1566
tmp_errno= errno;
1567
}
1568
const uchar uh[]= "# User@Host: ";
1569
if (my_b_write(&log_file, uh, sizeof(uh) - 1))
1570
tmp_errno= errno;
1571
if (my_b_write(&log_file, (uchar*) user_host, user_host_len))
1572
tmp_errno= errno;
1573
if (my_b_write(&log_file, (uchar*) "\n", 1))
1574
tmp_errno= errno;
1575
}
1576
/* For slow query log */
1577
sprintf(query_time_buff, "%.6f", uint64_t2double(query_utime)/1000000.0);
1578
sprintf(lock_time_buff, "%.6f", uint64_t2double(lock_utime)/1000000.0);
1579
if (my_b_printf(&log_file,
1580
"# Query_time: %s Lock_time: %s"
1581
" Rows_sent: %lu Rows_examined: %lu\n",
1582
query_time_buff, lock_time_buff,
1583
(ulong) thd->sent_row_count,
1584
(ulong) thd->examined_row_count) == (uint) -1)
1585
tmp_errno= errno;
1586
if (thd->db && strcmp(thd->db, db))
1587
{ // Database changed
1588
if (my_b_printf(&log_file,"use %s;\n",thd->db) == (uint) -1)
1589
tmp_errno= errno;
1590
my_stpcpy(db,thd->db);
1591
}
1592
if (thd->stmt_depends_on_first_successful_insert_id_in_prev_stmt)
1593
{
1594
end=my_stpcpy(end, ",last_insert_id=");
1595
end=int64_t10_to_str((int64_t)
1596
thd->first_successful_insert_id_in_prev_stmt_for_binlog,
1597
end, -10);
1598
}
1599
// Save value if we do an insert.
1600
if (thd->auto_inc_intervals_in_cur_stmt_for_binlog.nb_elements() > 0)
1601
{
1602
{
1603
end=my_stpcpy(end,",insert_id=");
1604
end=int64_t10_to_str((int64_t)
1605
thd->auto_inc_intervals_in_cur_stmt_for_binlog.minimum(),
1606
end, -10);
1607
}
1608
}
1609
1610
/*
1611
This info used to show up randomly, depending on whether the query
1612
checked the query start time or not. now we always write current
1613
timestamp to the slow log
1614
*/
1615
end= my_stpcpy(end, ",timestamp=");
1616
end= int10_to_str((long) current_time, end, 10);
1617
1618
if (end != buff)
1619
{
1620
*end++=';';
1621
*end='\n';
1622
if (my_b_write(&log_file, (uchar*) "SET ", 4) ||
1623
my_b_write(&log_file, (uchar*) buff + 1, (uint) (end-buff)))
1624
tmp_errno= errno;
1625
}
1626
if (is_command)
1627
{
1628
end= strxmov(buff, "# administrator command: ", NullS);
1629
buff_len= (ulong) (end - buff);
1630
my_b_write(&log_file, (uchar*) buff, buff_len);
1631
}
1632
if (my_b_write(&log_file, (uchar*) sql_text, sql_text_len) ||
1633
my_b_write(&log_file, (uchar*) ";\n",2) ||
1634
flush_io_cache(&log_file))
1635
tmp_errno= errno;
1636
if (tmp_errno)
1637
{
1638
error= 1;
1639
if (! write_error)
1640
{
1641
write_error= 1;
1642
sql_print_error(ER(ER_ERROR_ON_WRITE), name, error);
1643
}
1644
}
1645
}
1646
(void) pthread_mutex_unlock(&LOCK_log);
1647
return(error);
1648
}
1649
1650
1651
1018
/**
1652
1019
@todo
1653
1020
The following should be using fn_format(); We just need to
3285
2652
return logger.error_log_print(level, format, args);
3286
2653
}
3287
2654
3288
3289
bool slow_log_print(THD *thd, const char *query, uint query_length,
3290
uint64_t current_utime)
3291
{
3292
return logger.slow_log_print(thd, query, query_length, current_utime);
3293
}
3294
3295
3296
bool LOGGER::log_command(THD *thd, enum enum_server_command command)
3297
{
3298
/*
3299
Log command if we have at least one log event handler enabled and want
3300
to log this king of commands
3301
*/
3302
if (*general_log_handler_list && (what_to_log & (1L << (uint) command)))
3303
{
3304
if (thd->options & OPTION_LOG_OFF)
3305
{
3306
/* No logging */
3307
return false;
3308
}
3309
3310
return true;
3311
}
3312
3313
return false;
3314
}
3315
3316
3317
bool general_log_print(THD *thd, enum enum_server_command command,
3318
const char *format, ...)
3319
{
3320
va_list args;
3321
uint error= 0;
3322
3323
/* Print the message to the buffer if we want to log this king of commands */
3324
if (! logger.log_command(thd, command))
3325
return false;
3326
3327
va_start(args, format);
3328
error= logger.general_log_print(thd, command, format, args);
3329
va_end(args);
3330
3331
return error;
3332
}
3333
3334
bool general_log_write(THD *thd, enum enum_server_command command,
3335
const char *query, uint query_length)
3336
{
3337
/* Write the message to the log if we want to log this king of commands */
3338
if (logger.log_command(thd, command))
3339
return logger.general_log_write(thd, command, query, query_length);
3340
3341
return false;
3342
}
3343
3344
2655
void DRIZZLE_BIN_LOG::rotate_and_purge(uint flags)
3345
2656
{
3346
2657
if (!(flags & RP_LOCK_LOG_IS_ALREADY_LOCKED))
Loggerhead is a web-based interface for Breezy
Version: 2.0.1