r82021 MediaWiki - Code Review archive

Repository:MediaWiki
Revision:< r82020‎ | r82021 | r82022 >
Date:18:09, 12 February 2011
Author:catrope
Status:ok (Comments)
Tags:
Comment:
wmerrors: Enable UDP support (already supported by Platonides's existing TCP support, just had to whitelist "udp://") and buffer output in wmerrors_write_trace() so we write out the entire backtrace at once instead of doing it a few bytes (or even one byte) at a time. The latter is really bad for UDP
Modified paths:
  • /trunk/php/wmerrors/php_wmerrors.h (modified) (history)
  • /trunk/php/wmerrors/wmerrors.c (modified) (history)

Diff [purge]

Index: trunk/php/wmerrors/wmerrors.c
——@@ -62,6 +62,7 @@
6363 wmerrors_globals->message_file = NULL;
6464 wmerrors_globals->logging_file = NULL;
6565 wmerrors_globals->log_level = 0;
 66+ wmerrors_globals->log_buffer.c = NULL;
6667 }
6768
6869 PHP_MINIT_FUNCTION(wmerrors)
——@@ -160,7 +161,7 @@
161162 int err; char *errstr = NULL;
162163 struct timeval tv;
163164
164 - if ( strncmp( stream_name, "tcp://", 6 ) ) {
 165+ if ( strncmp( stream_name, "tcp://", 6 ) && strncmp( stream_name, "udp://", 6 ) ) {
165166 /* Is it a wrapper? */
166167 stream = php_stream_open_wrapper(stream_name, "ab", ENFORCE_SAFE_MODE | REPORT_ERRORS, NULL);
167168 } else {
——@@ -179,16 +180,18 @@
180181 }
181182
182183 /* Callback for zend_print_zval_r_ex()
183 - * Gets the file to write from the module global logfile_stream.
 184+ * Writes to the global buffer
184185 */
185186 static int wmerrors_write_trace(const char *str, uint str_length) {
186187 TSRMLS_FETCH();
187 - return php_stream_write(WMERRORS_G(logfile_stream), str, str_length);
 188+ smart_str_appendl(&WMERRORS_G(log_buffer), str, str_length);
 189+ return str_length;
188190 }
189191
190192 static void wmerrors_log_error(int type, const char *error_filename, const uint error_lineno, const char *format, va_list args TSRMLS_DC) {
191193 char *tmp1; zval *trace; char *error_time_str;
192194 int tmp1_len; va_list my_args;
 195+ php_stream *logfile_stream;
193196
194197 if ( !WMERRORS_G(enabled) || !WMERRORS_G(log_level) ) {
195198 /* Redundant with the caller */
——@@ -201,8 +204,8 @@
202205 }
203206
204207 /* Try opening the logging file */
205 - WMERRORS_G(logfile_stream) = open_logging_file( WMERRORS_G(logging_file) );
206 - if ( !WMERRORS_G(logfile_stream) ) {
 208+ logfile_stream = open_logging_file( WMERRORS_G(logging_file) );
 209+ if ( !logfile_stream ) {
207210 return;
208211 }
209212
——@@ -213,7 +216,7 @@
214217
215218 /* Log the error (log_level >= 1) */
216219 error_time_str = php_format_date("d-M-Y H:i:s", 11, time(NULL), 0 TSRMLS_CC);
217 - php_stream_printf(WMERRORS_G(logfile_stream) TSRMLS_CC, "[%s UTC] %s: %.*s at %s on line %u%s", error_time_str, error_type_to_string(type), tmp1_len, tmp1, error_filename, error_lineno, PHP_EOL);
 220+ php_stream_printf(logfile_stream TSRMLS_CC, "[%s UTC] %s: %.*s at %s on line %u%s", error_time_str, error_type_to_string(type), tmp1_len, tmp1, error_filename, error_lineno, PHP_EOL);
218221 efree(error_time_str);
219222 efree(tmp1);
220223
——@@ -223,9 +226,10 @@
224227 zend_fetch_debug_backtrace(trace, 0, 0 TSRMLS_CC);
225228 zend_print_zval_r_ex(wmerrors_write_trace, trace, 4 TSRMLS_CC);
226229 FREE_ZVAL(trace);
 230+ php_stream_write(logfile_stream, WMERRORS_G(log_buffer).c, WMERRORS_G(log_buffer).len TSRMLS_CC);
227231 }
228232
229 - php_stream_close( WMERRORS_G(logfile_stream) );
 233+ php_stream_close( logfile_stream );
230234 }
231235
232236 static void wmerrors_show_message(int type, const char *error_filename, const uint error_lineno, const char *format, va_list args TSRMLS_DC)
Index: trunk/php/wmerrors/php_wmerrors.h
——@@ -15,6 +15,8 @@
1616 #include "TSRM.h"
1717 #endif
1818
 19+#include "ext/standard/php_smart_str_public.h"
 20+
1921 PHP_MINIT_FUNCTION(wmerrors);
2022 PHP_MSHUTDOWN_FUNCTION(wmerrors);
2123 PHP_RINIT_FUNCTION(wmerrors);
——@@ -27,7 +29,7 @@
2830 int recursion_guard;
2931 int enabled;
3032 long int log_level;
31 - php_stream *logfile_stream;
 33+ smart_str log_buffer;
3234 ZEND_END_MODULE_GLOBALS(wmerrors)
3335
3436

Follow-up revisions

RevisionCommit summaryAuthorDate
r82035Follow up r82021. The buffer is to be initialised every request.platonides21:35, 12 February 2011
r82045Follow up r82021. Free the string after using it. This would not just be a te...platonides00:04, 13 February 2011

Comments

#Comment by Platonides (talk | contribs)   21:31, 12 February 2011

Good method. Now it logs much more. However, I see the udp message truncated. It sends 791/2519 lines.

I also think if we should manually split the message. Seems silly sending in several udp datagramas, which are then fragmented again at IP level.

#Comment by Platonides (talk | contribs)   00:22, 13 February 2011

It looked a "simple bug" when I saw php_stream_write saying it sent the whole 132334 bytes, but exactly 65536 sent in that second call. No way. There 3953147/4215291

Still, stracing it, it seems to send everything. Maybe the problem is at capturing the traffic. :s

#Comment by Catrope (talk | contribs)   11:30, 13 February 2011

I wrote a function for optionally generating a concise backtrace formatted as "foo.php:123 bar.php:456 baz.php:789" and prepending that to the error_filename parameter to old_error_cb(), triggered by wmerrors.concise_backtrace_in_error_log. See r82046 and r82052. I guess we could put in another option for logging this concise backtrace instead of the whole thing to the UDP stream.

#Comment by Tim Starling (talk | contribs)   10:21, 15 February 2011

You have to use send() rather some high-level stream function. We had this problem with UDP logs in MediaWiki: messages bigger than 8KB will be split up into several send() calls, and then the individual packets will be reordered as they traverse the network, corrupting the messages. See r59193, the solution will be basically the same.

#Comment by Platonides (talk | contribs)   23:28, 15 February 2011

The network can do anything it wants with datagrams, but as I was sniffing on the machine output, I didn't expect such issues. I have narrowed the problem to some fragments not being captured (or just dropped by the kernel?). So not php or the extension fault.

Status & tagging log