Code Coverage |
||||||||||
Lines |
Functions and Methods |
Classes and Traits |
||||||||
Total | |
13.21% |
21 / 159 |
|
7.69% |
1 / 13 |
CRAP | |
0.00% |
0 / 1 |
LegacyLogger | |
13.21% |
21 / 159 |
|
7.69% |
1 / 13 |
4808.72 | |
0.00% |
0 / 1 |
__construct | |
0.00% |
0 / 14 |
|
0.00% |
0 / 1 |
156 | |||
setMinimumForTest | |
0.00% |
0 / 5 |
|
0.00% |
0 / 1 |
6 | |||
log | |
0.00% |
0 / 23 |
|
0.00% |
0 / 1 |
156 | |||
shouldEmit | |
78.95% |
15 / 19 |
|
0.00% |
0 / 1 |
10.93 | |||
format | |
0.00% |
0 / 19 |
|
0.00% |
0 / 1 |
110 | |||
formatAsWfDebug | |
0.00% |
0 / 6 |
|
0.00% |
0 / 1 |
12 | |||
formatAsWfLogDBError | |
0.00% |
0 / 9 |
|
0.00% |
0 / 1 |
6 | |||
formatAsWfDebugLog | |
0.00% |
0 / 5 |
|
0.00% |
0 / 1 |
2 | |||
interpolate | |
100.00% |
6 / 6 |
|
100.00% |
1 / 1 |
3 | |||
flatten | |
0.00% |
0 / 28 |
|
0.00% |
0 / 1 |
272 | |||
destination | |
0.00% |
0 / 13 |
|
0.00% |
0 / 1 |
42 | |||
emit | |
0.00% |
0 / 10 |
|
0.00% |
0 / 1 |
42 | |||
maybeLogToStderr | |
0.00% |
0 / 2 |
|
0.00% |
0 / 1 |
6 |
1 | <?php |
2 | /** |
3 | * This program is free software; you can redistribute it and/or modify |
4 | * it under the terms of the GNU General Public License as published by |
5 | * the Free Software Foundation; either version 2 of the License, or |
6 | * (at your option) any later version. |
7 | * |
8 | * This program is distributed in the hope that it will be useful, |
9 | * but WITHOUT ANY WARRANTY; without even the implied warranty of |
10 | * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the |
11 | * GNU General Public License for more details. |
12 | * |
13 | * You should have received a copy of the GNU General Public License along |
14 | * with this program; if not, write to the Free Software Foundation, Inc., |
15 | * 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA. |
16 | * http://www.gnu.org/copyleft/gpl.html |
17 | * |
18 | * @file |
19 | */ |
20 | |
21 | namespace MediaWiki\Logger; |
22 | |
23 | use DateTimeZone; |
24 | use Error; |
25 | use LogicException; |
26 | use MediaWiki\Debug\MWDebug; |
27 | use MediaWiki\WikiMap\WikiMap; |
28 | use MWExceptionHandler; |
29 | use Psr\Log\AbstractLogger; |
30 | use Psr\Log\LogLevel; |
31 | use Throwable; |
32 | use UDPTransport; |
33 | use Wikimedia\AtEase\AtEase; |
34 | |
35 | /** |
36 | * PSR-3 logger that mimics the historic implementation of MediaWiki's former |
37 | * wfErrorLog logging implementation. |
38 | * |
39 | * This logger is configured by the following global configuration variables: |
40 | * - `$wgDebugLogFile` |
41 | * - `$wgDebugLogGroups` |
42 | * - `$wgDBerrorLog` |
43 | * - `$wgDBerrorLogTZ` |
44 | * |
45 | * See docs/Configuration.md for detailed explanations of these settings. |
46 | * |
47 | * @see \MediaWiki\Logger\LoggerFactory |
48 | * @since 1.25 |
49 | * @ingroup Debug |
50 | * @copyright © 2014 Wikimedia Foundation and contributors |
51 | */ |
52 | class LegacyLogger extends AbstractLogger { |
53 | |
54 | /** |
55 | * @var string |
56 | */ |
57 | protected $channel; |
58 | |
59 | private const LEVEL_DEBUG = 100; |
60 | private const LEVEL_INFO = 200; |
61 | private const LEVEL_NOTICE = 250; |
62 | private const LEVEL_WARNING = 300; |
63 | private const LEVEL_ERROR = 400; |
64 | private const LEVEL_CRITICAL = 500; |
65 | private const LEVEL_ALERT = 550; |
66 | private const LEVEL_EMERGENCY = 600; |
67 | private const LEVEL_INFINITY = 999; |
68 | |
69 | /** |
70 | * Convert \Psr\Log\LogLevel constants into int for sensible comparisons |
71 | * These are the same values that Monolog uses |
72 | * |
73 | * @var array |
74 | */ |
75 | protected static $levelMapping = [ |
76 | LogLevel::DEBUG => self::LEVEL_DEBUG, |
77 | LogLevel::INFO => self::LEVEL_INFO, |
78 | LogLevel::NOTICE => self::LEVEL_NOTICE, |
79 | LogLevel::WARNING => self::LEVEL_WARNING, |
80 | LogLevel::ERROR => self::LEVEL_ERROR, |
81 | LogLevel::CRITICAL => self::LEVEL_CRITICAL, |
82 | LogLevel::ALERT => self::LEVEL_ALERT, |
83 | LogLevel::EMERGENCY => self::LEVEL_EMERGENCY, |
84 | ]; |
85 | |
86 | /** |
87 | * Minimum level. This is just to allow faster discard of debugging |
88 | * messages. Not all messages meeting the level will be logged. |
89 | * |
90 | * @var int |
91 | */ |
92 | private $minimumLevel; |
93 | |
94 | /** |
95 | * Whether the channel is a DB channel |
96 | * |
97 | * @var bool |
98 | */ |
99 | private $isDB; |
100 | |
101 | /** |
102 | * @param string $channel |
103 | */ |
104 | public function __construct( $channel ) { |
105 | global $wgDebugLogFile, $wgDBerrorLog, $wgDebugLogGroups, $wgDebugToolbar, $wgDebugRawPage, $wgShowDebug; |
106 | |
107 | $this->channel = $channel; |
108 | $this->isDB = ( $channel === 'rdbms' ); |
109 | |
110 | // Calculate minimum level, duplicating some of the logic from log() and shouldEmit() |
111 | if ( !$wgDebugRawPage && wfIsDebugRawPage() ) { |
112 | $this->minimumLevel = self::LEVEL_WARNING; |
113 | } elseif ( $wgDebugLogFile != '' || $wgShowDebug || $wgDebugToolbar ) { |
114 | // Log all messages if there is a debug log file or debug toolbar |
115 | $this->minimumLevel = self::LEVEL_DEBUG; |
116 | } elseif ( isset( $wgDebugLogGroups[$channel] ) ) { |
117 | $logConfig = $wgDebugLogGroups[$channel]; |
118 | // Log messages if the config is set, according to the configured level |
119 | if ( is_array( $logConfig ) && isset( $logConfig['level'] ) ) { |
120 | $this->minimumLevel = self::$levelMapping[$logConfig['level']]; |
121 | } else { |
122 | $this->minimumLevel = self::LEVEL_DEBUG; |
123 | } |
124 | } else { |
125 | // No other case hit: discard all messages |
126 | $this->minimumLevel = self::LEVEL_INFINITY; |
127 | } |
128 | |
129 | if ( $this->isDB && $wgDBerrorLog && $this->minimumLevel > self::LEVEL_ERROR ) { |
130 | // Log DB errors if there is a DB error log |
131 | $this->minimumLevel = self::LEVEL_ERROR; |
132 | } |
133 | } |
134 | |
135 | /** |
136 | * Change an existing Logger singleton to act like NullLogger. |
137 | * |
138 | * @internal For use by MediaWikiIntegrationTestCase::setNullLogger |
139 | * @param null|int $level |
140 | * @return int |
141 | */ |
142 | public function setMinimumForTest( ?int $level ) { |
143 | if ( !defined( 'MW_PHPUNIT_TEST' ) ) { |
144 | throw new LogicException( 'Not allowed outside tests' ); |
145 | } |
146 | // Set LEVEL_INFINITY if given null, or restore the original level. |
147 | $original = $this->minimumLevel; |
148 | $this->minimumLevel = $level ?? self::LEVEL_INFINITY; |
149 | return $original; |
150 | } |
151 | |
152 | /** |
153 | * Logs with an arbitrary level. |
154 | * |
155 | * @param string|int $level |
156 | * @param string $message |
157 | * @param array $context |
158 | */ |
159 | public function log( $level, $message, array $context = [] ) { |
160 | if ( is_string( $level ) ) { |
161 | $level = self::$levelMapping[$level]; |
162 | } |
163 | if ( $level < $this->minimumLevel ) { |
164 | return; |
165 | } |
166 | |
167 | if ( $this->isDB |
168 | && $level === self::LEVEL_DEBUG |
169 | && isset( $context['sql'] ) |
170 | ) { |
171 | // Also give the query information to the MWDebug tools |
172 | MWDebug::query( |
173 | $context['sql'], |
174 | $context['method'], |
175 | $context['runtime_ms'] / 1000, |
176 | $context['db_server'] |
177 | ); |
178 | } |
179 | |
180 | // If this is a DB-related error, and the site has $wgDBerrorLog |
181 | // configured, rewrite the channel as wfLogDBError instead. |
182 | // Likewise, if the site does not use $wgDBerrorLog, it should |
183 | // configurable like any other channel via $wgDebugLogGroups |
184 | // or $wgMWLoggerDefaultSpi. |
185 | global $wgDBerrorLog; |
186 | if ( $this->isDB && $level >= self::LEVEL_ERROR && $wgDBerrorLog ) { |
187 | // Format and write DB errors to the legacy locations |
188 | $effectiveChannel = 'wfLogDBError'; |
189 | } else { |
190 | $effectiveChannel = $this->channel; |
191 | } |
192 | |
193 | if ( self::shouldEmit( $effectiveChannel, $message, $level, $context ) ) { |
194 | $text = self::format( $effectiveChannel, $message, $context ); |
195 | $destination = self::destination( $effectiveChannel, $message, $context ); |
196 | $this->maybeLogToStderr( $text ); |
197 | self::emit( $text, $destination ); |
198 | } |
199 | if ( !isset( $context['private'] ) || !$context['private'] ) { |
200 | // Add to debug toolbar if not marked as "private" |
201 | MWDebug::debugMsg( $message, [ 'channel' => $this->channel ] + $context ); |
202 | } |
203 | } |
204 | |
205 | /** |
206 | * Determine if the given message should be emitted or not. |
207 | * |
208 | * @param string $channel |
209 | * @param string $message |
210 | * @param string|int $level \Psr\Log\LogEvent constant or Monolog level int |
211 | * @param array $context |
212 | * @return bool True if message should be sent to disk/network, false |
213 | * otherwise |
214 | */ |
215 | public static function shouldEmit( $channel, $message, $level, $context ) { |
216 | global $wgDebugLogFile, $wgDBerrorLog, $wgDebugLogGroups; |
217 | |
218 | if ( is_string( $level ) ) { |
219 | $level = self::$levelMapping[$level]; |
220 | } |
221 | |
222 | if ( $channel === 'wfLogDBError' ) { |
223 | // wfLogDBError messages are emitted if a database log location is |
224 | // specified. |
225 | $shouldEmit = (bool)$wgDBerrorLog; |
226 | |
227 | } elseif ( $channel === 'wfDebug' ) { |
228 | // wfDebug messages are emitted if a catch all logging file has |
229 | // been specified. Checked explicitly so that 'private' flagged |
230 | // messages are not discarded by unset $wgDebugLogGroups channel |
231 | // handling below. |
232 | $shouldEmit = $wgDebugLogFile != ''; |
233 | |
234 | } elseif ( isset( $wgDebugLogGroups[$channel] ) ) { |
235 | $logConfig = $wgDebugLogGroups[$channel]; |
236 | |
237 | if ( is_array( $logConfig ) ) { |
238 | $shouldEmit = true; |
239 | if ( isset( $logConfig['sample'] ) ) { |
240 | // Emit randomly with a 1 in 'sample' chance for each message. |
241 | $shouldEmit = mt_rand( 1, $logConfig['sample'] ) === 1; |
242 | } |
243 | |
244 | if ( isset( $logConfig['level'] ) ) { |
245 | $shouldEmit = $level >= self::$levelMapping[$logConfig['level']]; |
246 | } |
247 | } else { |
248 | // Emit unless the config value is explicitly false. |
249 | $shouldEmit = $logConfig !== false; |
250 | } |
251 | |
252 | } elseif ( isset( $context['private'] ) && $context['private'] ) { |
253 | // Don't emit if the message didn't match previous checks based on |
254 | // the channel and the event is marked as private. This check |
255 | // discards messages sent via wfDebugLog() with dest == 'private' |
256 | // and no explicit wgDebugLogGroups configuration. |
257 | $shouldEmit = false; |
258 | } else { |
259 | // Default return value is the same as the historic wfDebug |
260 | // method: emit if $wgDebugLogFile has been set. |
261 | $shouldEmit = $wgDebugLogFile != ''; |
262 | } |
263 | |
264 | return $shouldEmit; |
265 | } |
266 | |
267 | /** |
268 | * Format a message. |
269 | * |
270 | * Messages to the 'wfDebug' and 'wfLogDBError' channels receive special formatting to mimic the |
271 | * historic output of the functions of the same name. All other channel values are formatted |
272 | * based on the historic output of the `wfDebugLog()` global function. |
273 | * |
274 | * @param string $channel |
275 | * @param string $message |
276 | * @param array $context |
277 | * @return string |
278 | */ |
279 | public static function format( $channel, $message, $context ) { |
280 | global $wgDebugLogGroups, $wgLogExceptionBacktrace; |
281 | |
282 | if ( $channel === 'wfDebug' ) { |
283 | $text = self::formatAsWfDebug( $channel, $message, $context ); |
284 | |
285 | } elseif ( $channel === 'wfLogDBError' ) { |
286 | $text = self::formatAsWfLogDBError( $channel, $message, $context ); |
287 | |
288 | } elseif ( !isset( $wgDebugLogGroups[$channel] ) ) { |
289 | $text = self::formatAsWfDebug( |
290 | $channel, "[{$channel}] {$message}", $context ); |
291 | |
292 | } else { |
293 | // Default formatting is wfDebugLog's historic style |
294 | $text = self::formatAsWfDebugLog( $channel, $message, $context ); |
295 | } |
296 | |
297 | // Append stacktrace of throwable if available |
298 | if ( $wgLogExceptionBacktrace && isset( $context['exception'] ) ) { |
299 | $e = $context['exception']; |
300 | $backtrace = false; |
301 | |
302 | if ( $e instanceof Throwable ) { |
303 | $backtrace = MWExceptionHandler::getRedactedTrace( $e ); |
304 | |
305 | } elseif ( is_array( $e ) && isset( $e['trace'] ) ) { |
306 | // Throwable has already been unpacked as structured data |
307 | $backtrace = $e['trace']; |
308 | } |
309 | |
310 | if ( $backtrace ) { |
311 | $text .= MWExceptionHandler::prettyPrintTrace( $backtrace ) . |
312 | "\n"; |
313 | } |
314 | } |
315 | |
316 | return self::interpolate( $text, $context ); |
317 | } |
318 | |
319 | /** |
320 | * Format a message as `wfDebug()` would have formatted it. |
321 | * |
322 | * @param string $channel |
323 | * @param string $message |
324 | * @param array $context |
325 | * @return string |
326 | */ |
327 | protected static function formatAsWfDebug( $channel, $message, $context ) { |
328 | $text = preg_replace( '![\x00-\x08\x0b\x0c\x0e-\x1f]!', ' ', $message ); |
329 | if ( isset( $context['seconds_elapsed'] ) ) { |
330 | // Prepend elapsed request time and real memory usage with two |
331 | // trailing spaces. |
332 | $text = "{$context['seconds_elapsed']} {$context['memory_used']} {$text}"; |
333 | } |
334 | if ( isset( $context['prefix'] ) ) { |
335 | $text = "{$context['prefix']}{$text}"; |
336 | } |
337 | return "{$text}\n"; |
338 | } |
339 | |
340 | /** |
341 | * Format a message as `wfLogDBError()` would have formatted it. |
342 | * |
343 | * @param string $channel |
344 | * @param string $message |
345 | * @param array $context |
346 | * @return string |
347 | */ |
348 | protected static function formatAsWfLogDBError( $channel, $message, $context ) { |
349 | global $wgDBerrorLogTZ; |
350 | static $cachedTimezone = null; |
351 | |
352 | if ( !$cachedTimezone ) { |
353 | $cachedTimezone = new DateTimeZone( $wgDBerrorLogTZ ); |
354 | } |
355 | |
356 | $d = date_create( 'now', $cachedTimezone ); |
357 | $date = $d->format( 'D M j G:i:s T Y' ); |
358 | |
359 | $host = wfHostname(); |
360 | $wiki = WikiMap::getCurrentWikiId(); |
361 | |
362 | $text = "{$date}\t{$host}\t{$wiki}\t{$message}\n"; |
363 | return $text; |
364 | } |
365 | |
366 | /** |
367 | * Format a message as `wfDebugLog() would have formatted it. |
368 | * |
369 | * @param string $channel |
370 | * @param string $message |
371 | * @param array $context |
372 | * @return string |
373 | */ |
374 | protected static function formatAsWfDebugLog( $channel, $message, $context ) { |
375 | $time = wfTimestamp( TS_DB ); |
376 | $wiki = WikiMap::getCurrentWikiId(); |
377 | $host = wfHostname(); |
378 | $text = "{$time} {$host} {$wiki}: {$message}\n"; |
379 | return $text; |
380 | } |
381 | |
382 | /** |
383 | * Interpolate placeholders in logging message. |
384 | * |
385 | * @param string $message |
386 | * @param array $context |
387 | * @return string Interpolated message |
388 | */ |
389 | public static function interpolate( $message, array $context ) { |
390 | if ( str_contains( $message, '{' ) ) { |
391 | $replace = []; |
392 | foreach ( $context as $key => $val ) { |
393 | $replace['{' . $key . '}'] = self::flatten( $val ); |
394 | } |
395 | $message = strtr( $message, $replace ); |
396 | } |
397 | return $message; |
398 | } |
399 | |
400 | /** |
401 | * Convert a logging context element to a string suitable for |
402 | * interpolation. |
403 | * |
404 | * @param mixed $item |
405 | * @return string |
406 | */ |
407 | protected static function flatten( $item ) { |
408 | if ( $item === null ) { |
409 | return '[Null]'; |
410 | } |
411 | |
412 | if ( is_bool( $item ) ) { |
413 | return $item ? 'true' : 'false'; |
414 | } |
415 | |
416 | if ( is_float( $item ) ) { |
417 | if ( is_infinite( $item ) ) { |
418 | return ( $item > 0 ? '' : '-' ) . 'INF'; |
419 | } |
420 | if ( is_nan( $item ) ) { |
421 | return 'NaN'; |
422 | } |
423 | return (string)$item; |
424 | } |
425 | |
426 | if ( is_scalar( $item ) ) { |
427 | return (string)$item; |
428 | } |
429 | |
430 | if ( is_array( $item ) ) { |
431 | return '[Array(' . count( $item ) . ')]'; |
432 | } |
433 | |
434 | if ( $item instanceof \DateTime ) { |
435 | return $item->format( 'c' ); |
436 | } |
437 | |
438 | if ( $item instanceof Throwable ) { |
439 | $which = $item instanceof Error ? 'Error' : 'Exception'; |
440 | return '[' . $which . ' ' . get_class( $item ) . '( ' . |
441 | $item->getFile() . ':' . $item->getLine() . ') ' . |
442 | $item->getMessage() . ']'; |
443 | } |
444 | |
445 | if ( is_object( $item ) ) { |
446 | if ( method_exists( $item, '__toString' ) ) { |
447 | return (string)$item; |
448 | } |
449 | |
450 | return '[Object ' . get_class( $item ) . ']'; |
451 | } |
452 | |
453 | // phpcs:ignore MediaWiki.Usage.ForbiddenFunctions.is_resource |
454 | if ( is_resource( $item ) ) { |
455 | return '[Resource ' . get_resource_type( $item ) . ']'; |
456 | } |
457 | |
458 | return '[Unknown ' . get_debug_type( $item ) . ']'; |
459 | } |
460 | |
461 | /** |
462 | * Select the appropriate log output destination for the given log event. |
463 | * |
464 | * If the event context contains 'destination' |
465 | * |
466 | * @param string $channel |
467 | * @param string $message |
468 | * @param array $context |
469 | * @return string |
470 | */ |
471 | protected static function destination( $channel, $message, $context ) { |
472 | global $wgDebugLogFile, $wgDBerrorLog, $wgDebugLogGroups; |
473 | |
474 | // Default destination is the debug log file as historically used by |
475 | // the wfDebug function. |
476 | $destination = $wgDebugLogFile; |
477 | |
478 | if ( isset( $context['destination'] ) ) { |
479 | // Use destination explicitly provided in context |
480 | $destination = $context['destination']; |
481 | |
482 | } elseif ( $channel === 'wfDebug' ) { |
483 | $destination = $wgDebugLogFile; |
484 | |
485 | } elseif ( $channel === 'wfLogDBError' ) { |
486 | $destination = $wgDBerrorLog; |
487 | |
488 | } elseif ( isset( $wgDebugLogGroups[$channel] ) ) { |
489 | $logConfig = $wgDebugLogGroups[$channel]; |
490 | |
491 | if ( is_array( $logConfig ) ) { |
492 | $destination = $logConfig['destination']; |
493 | } else { |
494 | $destination = strval( $logConfig ); |
495 | } |
496 | } |
497 | |
498 | return $destination; |
499 | } |
500 | |
501 | /** |
502 | * Log to a file without getting "file size exceeded" signals. |
503 | * |
504 | * Can also log to UDP with the syntax udp://host:port/prefix. This will send |
505 | * lines to the specified port, prefixed by the specified prefix and a space. |
506 | * |
507 | * @param string $text |
508 | * @param string $file Filename |
509 | */ |
510 | public static function emit( $text, $file ) { |
511 | if ( str_starts_with( $file, 'udp:' ) ) { |
512 | $transport = UDPTransport::newFromString( $file ); |
513 | $transport->emit( $text ); |
514 | } else { |
515 | AtEase::suppressWarnings(); |
516 | $exists = file_exists( $file ); |
517 | $size = $exists ? filesize( $file ) : false; |
518 | if ( !$exists || |
519 | ( $size !== false && $size + strlen( $text ) < 0x7fffffff ) |
520 | ) { |
521 | file_put_contents( $file, $text, FILE_APPEND ); |
522 | } |
523 | AtEase::restoreWarnings(); |
524 | } |
525 | } |
526 | |
527 | /** |
528 | * If MW_LOG_STDERR is set (used currently in `composer serve`) then also |
529 | * emit to stderr using error_log(). |
530 | * |
531 | * @param string $text |
532 | * @return void |
533 | */ |
534 | private function maybeLogToStderr( string $text ): void { |
535 | if ( getenv( 'MW_LOG_STDERR' ) ) { |
536 | error_log( trim( $text ) ); |
537 | } |
538 | } |
539 | |
540 | } |