Hi Davi
Davi Arnaut wrote:
> Below is the list of changes that have just been committed into a local
> 5.1 repository of davi. When davi does a push these changes will
> be propagated to the main repository and, within 24 hours after the
> push, to the public repository.
> For information on how to access the public repository
> see http://dev.mysql.com/doc/mysql/en/installing-source-tree.html
>
> ChangeSet@stripped, 2007-10-15 11:01:18-03:00, davi@stripped +8 -0
> Bug#21557 entries in the general query log truncated at 1000 characters.
>
> The general log write function (general_log_print) uses printf style
> arguments which need to be pre-processed, meaning that the all arguments
> are copied to a single buffer and the problem is that the buffer size is
> constant (1022 characters) but queries can be much larger then this.
>
> The solution is to introduce a new log write function that accepts a
> buffer and it's length as arguments. The function is to be used when
> a formatted output is not required, which is the case for almost all
> query write-to-log calls.
>
> mysql-test/r/log_tables.result@stripped, 2007-10-15 11:01:14-03:00, davi@stripped
> +207 -0
> Add test case result for Bug#21557
>
> mysql-test/t/log_tables.test@stripped, 2007-10-15 11:01:14-03:00, davi@stripped
> +111 -0
> Add test case for Bug#21557
>
> sql/log.cc@stripped, 2007-10-15 11:01:14-03:00, davi@stripped +34 -13
> Introduce the logger function general_log_write which is similar to
> general_log_print but accepts a single buffer and the buffer length.
> The function doesn't perform any formatting and sends the buffer
> directly to the underlying log handlers.
>
> sql/log.h@stripped, 2007-10-15 11:01:14-03:00, davi@stripped +2 -0
> Introduce the logger function general_log_write.
>
> sql/log_event.cc@stripped, 2007-10-15 11:01:14-03:00, davi@stripped +1 -1
> Pass the query buffer directly to the logger function, formatting
> is not required on this case.
>
> sql/mysql_priv.h@stripped, 2007-10-15 11:01:14-03:00, davi@stripped +3 -0
> Prototype for the logger function general_log_write.
>
> sql/sp_head.cc@stripped, 2007-10-15 11:01:14-03:00, davi@stripped +1 -1
> Pass the query buffer directly to the logger function, formatting
> is not required on this case.
>
> sql/sql_parse.cc@stripped, 2007-10-15 11:01:14-03:00, davi@stripped +3 -4
> Pass the buffer directly to the logger function when formatting
> is not required.
>
>
I totally agree with the general approach,
providing LOGGER::general_log_write(),
and using the original string directly when no formating is needed.
Not only this avoids the data truncation,
but this also helps performances by not having to make a copy of the string,
which the previous code used to do with silly "%s" printf formats ...
However, I have the following comments about the implementation:
1)
When calling general_log_print(), the following test seems to be performed twice,
once in print and once in write:
- if (*general_log_handler_list && (what_to_log & (1L << (uint)
command)))
- if (!*general_log_handler_list || !(what_to_log & (1L << (uint) command)))
2)
When calling general_log_print(), the my_vsnprintf is executed,
even if later general_log_write() decide that there is nothing to log,
due to:
if ((thd->options & OPTION_LOG_OFF)
#ifndef NO_EMBEDDED_ACCESS_CHECKS
&& (sctx->master_access & SUPER_ACL)
#endif
)
{
return 0; /* No logging */
}
So, please reorganize the LOGGER implementation to:
a) have a helper method to decide if something must be logged or not,
to avoid duplication
b) Have LOGGER::general_log_write()
- call this helper
- and then dispatch to the Log_event_handler's
c) Have LOGGER::general_log_print()
- call this helper
- perform the my_vsnprintf
- and then dispatch to the Log_event_handler's
This should address points 1) and 2)
Also, it should be noted that the fix is only partial:
COM_QUERY will log the entire query, without truncation,
while other places in the code, still calling the general_log_print() method,
will have a truncated output.
In particular, COM_PREPARE is still truncated (see sql_prepare.cc)
const char *format= "[%lu] %.*b";
general_log_print(thd, COM_STMT_PREPARE, format, id,
query_length, query);
The COM_PREPARE case should be also fixed and tested,
to avoid later bug reports for prepared statements,
similar in nature to the complaint of bug#21557
A proposed solution, for the remaining calls to general_log_print,
is to provide an extra parameter that indicate the maximun length of the formatted query
(assuming the caller can compute it or can compute an upper bound of it).
The implementation could try either a call to my_vsnprintf() using a stack buffer,
or fall back to a call with dynamically allocated memory only for "big" formatted strings.
With this proposal, every calls to general_log_print()
- will use a stack buffer of a fixed size in most cases (performances)
- will use dynamically allocated memory on rare cases, to avoid truncation
- will never print truncated data
- will still be easy to use from the caller point of view
- will still not perform any vsnprintf when logging is off
Thanks for looking into this.
Regards,
Marc.
