Hi Konstantin,
Konstantin Osipov wrote:
> * 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.
The bug reporter (which is a costumer) is complaining that COM_REFRESH
is logged but doesn't show what was being refreshed.
>> +
>> 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.
OK.
>> @@ -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.
OK.
>> 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.
OK.
>> 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.
OK.
>> +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!
Oops, left over from the debug phase, not intended to be here.
>
> 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);
>
OK.
>
> Or rather. Add the test case to 5.1 only. Use logging-to-tables
> feature and write the test case in SQL.
OK.
[..]
>
> 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
This one (COM_REFRESH) I think it's worthwhile since it's close to
useless if it doesn't log the arguments because it can be so many
different things.
> - please rewrite the test in SQL.
> - I would like to take a look at the patch before you push.
OK.
Regards,
--
Davi Arnaut, Software Engineer
MySQL Inc, www.mysql.com
Are you MySQL certified? www.mysql.com/certification
