* Davi Arnaut <davi@stripped> [07/12/21 14:02]:
> ChangeSet@stripped, 2007-12-21 08:49:53-02:00, davi@stripped +5 -0
> Bug#28386 the general log is incomplete
Hi Davi,
Please see below.
> +static void log_refresh_cmd(THD *thd, ulong options)
> +{
> + char buff[512];
> + String str(buff,(uint32) sizeof(buff), system_charset_info);
> + static struct {
> + ulong option;
> + const char *str;
> + } const refresh_opt[]= {
> + { REFRESH_GRANT, "PRIVILEGES, " },
> + { REFRESH_LOG, "LOGS, " },
> + { REFRESH_TABLES, "TABLES, " },
> + { REFRESH_HOSTS, "HOSTS, " },
> + { REFRESH_STATUS, "STATUS, " },
> + { REFRESH_THREADS, "THREADS, " },
> + { REFRESH_SLAVE, "SLAVE, " },
> + { REFRESH_MASTER, "MASTER, " },
> + { REFRESH_READ_LOCK, "TABLES WITH READ LOCK, " },
> + { REFRESH_QUERY_CACHE, "QUERY CACHE, " },
> + { REFRESH_QUERY_CACHE_FREE, "QUERY CACHE FREE, " },
> + { REFRESH_DES_KEY_FILE, "DES_KEY_FILE, " },
> + { REFRESH_USER_RESOURCES, "USER_RESOURCES, " }
> + };
> +
> + str.length(0);
> +
> + for (uint i= 0; i < array_elements(refresh_opt); i++)
> + {
> + if (refresh_opt[i].option & options)
> + str.append(refresh_opt[i].str);
> + }
> +
> + if (str.is_empty())
> + mysql_log.write(thd, thd->command, NullS);
> + else
> + mysql_log.write(thd, thd->command, "%.*s",
> + str.length() - 2, str.c_ptr_quick());
> +}
I'm not sure this change can be classified as a bug fix. It is not
very extensible (no compile-time check that one doesn't forget to
add an option name when a new REFRESH option is added).
I would exclude this change from the patch.
> +
> void thd_init_client_charset(THD *thd, uint cs_number)
> {
> /*
> @@ -2079,7 +2117,7 @@ bool dispatch_command(enum enum_server_c
> ulong options= (ulong) (uchar) packet[0];
> if (check_global_access(thd,RELOAD_ACL))
> break;
> - mysql_log.write(thd,command,NullS);
> + log_refresh_cmd(thd, options);
> if (!reload_acl_and_cache(thd, options, (TABLE_LIST*) 0, ¬_used))
> send_ok(thd);
> break;
> @@ -2159,6 +2197,7 @@ bool dispatch_command(enum enum_server_c
> }
> case COM_PING:
> statistic_increment(thd->status_var.com_other, &LOCK_status);
> + mysql_log.write(thd, command, NullS);
I believe not logging COM_PING in the general log is intentional.
COM_PING may be generated by a heartbeat service.
Since we don't provide a way to fine-tune what gets into the
general log, people may complain when this is added.
E.g. when we changed behaviour of --log-slow-admin-statements
many screamed loudly.
I think this should not be part of the patch.
> @@ -2458,6 +2458,11 @@ void mysql_stmt_reset(THD *thd, char *pa
>
> stmt->state= Query_arena::PREPARED;
>
> + /* Don't print if inside a stored procedure. */
> + if (thd->spcont == NULL)
> + mysql_log.write(thd, thd->command, "[%lu] %.*s", stmt->id,
> + stmt->name.length, stmt->name.str);
> +
OK, but mysql_stmt_reset can never be called from a stored
procedure. Thus no need to check for thd->spcont. You could add a
comment instead.
> send_ok(thd);
>
> DBUG_VOID_RETURN;
> @@ -2543,6 +2548,8 @@ void mysql_stmt_get_longdata(THD *thd, c
> uint param_number;
> Prepared_statement *stmt;
> Item_param *param;
> + char *extra_data;
> + ulong extra_length;
> #ifndef EMBEDDED_LIBRARY
> char *packet_end= packet + packet_length - 1;
> #endif
> @@ -2582,15 +2589,29 @@ void mysql_stmt_get_longdata(THD *thd, c
> param= stmt->param_array[param_number];
>
> #ifndef EMBEDDED_LIBRARY
> - if (param->set_longdata(packet, (ulong) (packet_end - packet)))
> + extra_data= packet;
> + extra_length= (ulong) (packet_end - packet);
> #else
> - if (param->set_longdata(thd->extra_data, thd->extra_length))
> + extra_data= thd->extra_data;
> + extra_length= thd->extra_length;
> #endif
> +
> + if (param->set_longdata(extra_data, extra_length))
> {
> stmt->state= Query_arena::ERROR;
> stmt->last_errno= ER_OUTOFMEMORY;
> sprintf(stmt->last_error, ER(ER_OUTOFMEMORY), 0);
> }
> +
> + /* Don't print if inside a stored procedure. */
> + if (thd->spcont == NULL)
> + {
> + const char fmt[]= "[%lu] %.*s %.*b";
> + mysql_log.write(thd, thd->command, fmt, stmt->id,
> + stmt->name.length, stmt->name.str,
> + extra_length, extra_data);
> + }
OK, but please do not log the argument. It can be
binary, to start with.
Once again, this code is never executed in a stored procedure.
> DBUG_VOID_RETURN;
> }
>
> @@ -3064,6 +3085,12 @@ bool Prepared_statement::deallocate()
> my_error(ER_PS_NO_RECURSION, MYF(0));
> return TRUE;
> }
> +
> + /* Don't print if inside a stored procedure. */
> + if (thd->spcont == NULL)
> + mysql_log.write(thd, thd->command, "[%lu] %.*s", id,
> + name.length, name.str);
OK. This code is never executed in a stored procedure.
> +static FILE *open_master_log(void)
> +{
> + FILE *log_file;
> + char *master_log_filename;
> +
> + master_log_filename = (char *) malloc(strlen(opt_vardir) +
> strlen("/log/master.log") + 1);
> + strcpy(master_log_filename, opt_vardir);
> + strcat(master_log_filename, "/log/master.log");
> + printf("Opening '%s'\n", master_log_filename);
> + log_file= my_fopen(master_log_filename, (int) (O_RDONLY | O_BINARY),
> MYF(MY_WME));
> + free(master_log_filename);
> +
> + return log_file;
> +}
> +
> /*
> Bug#17667: An attacker has the opportunity to bypass query logging.
>
> @@ -15067,7 +15082,6 @@ static void test_bug17667()
>
> struct buffer_and_length *statement_cursor;
> FILE *log_file;
> - char *master_log_filename;
>
> myheader("test_bug17667");
>
> @@ -15109,12 +15123,7 @@ static void test_bug17667()
> rc= mysql_query(mysql, "flush logs");
> myquery(rc);
>
> - master_log_filename = (char *) malloc(strlen(opt_vardir) +
> strlen("/log/master.log") + 1);
> - strcpy(master_log_filename, opt_vardir);
> - strcat(master_log_filename, "/log/master.log");
> - printf("Opening '%s'\n", master_log_filename);
> - log_file= my_fopen(master_log_filename, (int) (O_RDONLY | O_BINARY),
> MYF(MY_WME));
> - free(master_log_filename);
> + log_file= open_master_log();
>
> if (log_file != NULL) {
>
> @@ -16152,6 +16161,89 @@ static void test_bug31669()
> DBUG_VOID_RETURN;
> }
>
> +static void test_bug28386()
> +{
> + int rc;
> + uint i;
> + MYSQL_STMT *stmt;
> + FILE *log_file;
> + char buffer[MAX_TEST_QUERY_LENGTH*2], *line;
> + struct {
> + const char *str;
> + size_t len;
> + int found;
> + } tokens[] = {
> + { "Close stmt", 0, 0 },
> + { "Reset stmt", 0, 0 },
> + { "Long Data", 0, 0 },
> + { "Ping", 0, 0 },
> + { "Refresh", 0, 0 },
> + { "PRIVILEGES, STATUS", 0, 0 }
> + };
> + DBUG_ENTER("test_bug28386");
> + myheader("test_bug28386");
> +
> + sleep(30);
Ouch!
Why don't you use the approach from the other test:
/* Make sure the server has written the logs to disk before
* reading it */
rc= mysql_query(mysql, "flush logs");
myquery(rc);
?
Or rather. Add the test case to 5.1 only. Use logging-to-tables
feature and write the test case in SQL.
> +
> + for (i= 0; i < array_elements(tokens); i++)
> + tokens[i].len= strlen(tokens[i].str);
> +
> + stmt= mysql_simple_prepare(mysql, "SELECT 1");
> + check_stmt(stmt);
> +
> + rc= mysql_stmt_execute(stmt);
> + check_execute(stmt, rc);
> +
> + rc= my_process_stmt_result(stmt);
> + DIE_UNLESS(rc == 1);
> +
> + rc= mysql_stmt_reset(stmt);
> + check_execute(stmt, rc);
> +
> + rc= mysql_stmt_close(stmt);
> + DIE_UNLESS(!rc);
> +
> + rc= mysql_ping(mysql);
> + DIE_UNLESS(!rc);
> +
> + mysql_refresh(mysql, REFRESH_GRANT);
> + mysql_refresh(mysql, REFRESH_STATUS | REFRESH_GRANT);
> +
> + log_file= open_master_log();
> +
> + if (log_file == NULL)
> + {
> + fprintf(stderr, "Could not find the log file, VARDIR/log/master.log, so "
> + "test_bug28386 is \ninconclusive. Run test from the "
> + "mysql-test/mysql-test-run* program \nto set up the correct "
> + "environment for this test.\n\n");
> + DBUG_VOID_RETURN;
> + }
> +
> + while ((line= fgets(buffer, MAX_TEST_QUERY_LENGTH*2, log_file)))
> + {
> + for (i= 0; i < array_elements(tokens); i++)
> + {
> + if (my_memmem(line, MAX_TEST_QUERY_LENGTH*2, tokens[i].str,
> + tokens[i].len))
> + tokens[i].found= 1;
> + }
> + }
> +
> + for (i= 0; i < array_elements(tokens); i++)
> + DIE_UNLESS(tokens[i].found == 1);
> +
> + my_fclose(log_file, MYF(0));
> +
> + DBUG_VOID_RETURN;
> +}
> +
To sum up:
- OK to push the approved parts. Not approved parts in my view
more close in nature to a feature request, and they need
to be thought through before getting in. I recommend that you
open a separate bug report for them (feature request).
Not approved:
- logging arguments of LONGDATA
- logging COM_PING
- logging arguments of COM_REFRESH
- please rewrite the test in SQL.
- I would like to take a look at the patch before you push.
--
-- Konstantin Osipov Software Developer, Moscow, Russia
-- MySQL AB, www.mysql.com The best DATABASE COMPANY in the GALAXY
