Code Coverage
 
Lines
Functions and Methods
Classes and Traits
Total
24.72% covered (danger)
24.72%
44 / 178
21.05% covered (danger)
21.05%
4 / 19
CRAP
0.00% covered (danger)
0.00%
0 / 1
API
24.72% covered (danger)
24.72%
44 / 178
21.05% covered (danger)
21.05%
4 / 19
3241.38
0.00% covered (danger)
0.00%
0 / 1
 __construct
100.00% covered (success)
100.00%
1 / 1
100.00% covered (success)
100.00%
1 / 1
1
 get_common_context
100.00% covered (success)
100.00%
1 / 1
100.00% covered (success)
100.00%
1 / 1
1
 set_common_context
0.00% covered (danger)
0.00%
0 / 1
0.00% covered (danger)
0.00%
0 / 1
2
 get_log_url
0.00% covered (danger)
0.00%
0 / 6
0.00% covered (danger)
0.00%
0 / 1
6
 get_log_files
0.00% covered (danger)
0.00%
0 / 17
0.00% covered (danger)
0.00%
0 / 1
182
 delete_log
0.00% covered (danger)
0.00%
0 / 14
0.00% covered (danger)
0.00%
0 / 1
6
 delete_all_logs
0.00% covered (danger)
0.00%
0 / 13
0.00% covered (danger)
0.00%
0 / 1
12
 delete_old_logs
0.00% covered (danger)
0.00%
0 / 8
0.00% covered (danger)
0.00%
0 / 1
20
 get_backtrace
82.61% covered (warning)
82.61%
19 / 23
0.00% covered (danger)
0.00%
0 / 1
22.10
 set_cached_backtrace
0.00% covered (danger)
0.00%
0 / 4
0.00% covered (danger)
0.00%
0 / 1
12
 get_cached_backtrace
0.00% covered (danger)
0.00%
0 / 5
0.00% covered (danger)
0.00%
0 / 1
6
 is_backtrace_contains_plugin
100.00% covered (success)
100.00%
7 / 7
100.00% covered (success)
100.00%
1 / 1
4
 is_file_from_plugin
0.00% covered (danger)
0.00%
0 / 1
0.00% covered (danger)
0.00%
0 / 1
6
 get_last_log_time_transient_name
100.00% covered (success)
100.00%
1 / 1
100.00% covered (success)
100.00%
1 / 1
1
 get_last_log_time
65.22% covered (warning)
65.22%
15 / 23
0.00% covered (danger)
0.00%
0 / 1
10.69
 get_last_logs_view_time
0.00% covered (danger)
0.00%
0 / 11
0.00% covered (danger)
0.00%
0 / 1
20
 set_last_logs_view_time
0.00% covered (danger)
0.00%
0 / 6
0.00% covered (danger)
0.00%
0 / 1
6
 parse_log
0.00% covered (danger)
0.00%
0 / 16
0.00% covered (danger)
0.00%
0 / 1
30
 log_lines_to_entry
0.00% covered (danger)
0.00%
0 / 20
0.00% covered (danger)
0.00%
0 / 1
72
1<?php
2/**
3 * The main functions of the logger.
4 *
5 * @package brianhenryie/bh-wp-logger
6 */
7
8namespace BrianHenryIE\WP_Logger\API;
9
10use BrianHenryIE\WC_Logger\WC_PSR_Logger;
11use BrianHenryIE\WP_Logger\Admin\Logs_List_Table;
12use BrianHenryIE\WP_Logger\Admin\Logs_Page;
13use BrianHenryIE\WP_Logger\API_Interface;
14use BrianHenryIE\WP_Logger\Logger_Settings_Interface;
15use BrianHenryIE\WP_Logger\Logger;
16use BrianHenryIE\WP_Logger\WooCommerce_Logger_Settings_Interface;
17use DateTime;
18use DateTimeImmutable;
19use DateTimeInterface;
20use DateTimeZone;
21use Exception;
22use Psr\Log\LoggerAwareTrait;
23use Psr\Log\LoggerInterface;
24use stdClass;
25use WP_Filesystem_Base;
26
27/**
28 * BH_WP_PSR_Logger extends this, then Logger extends that.
29 *
30 * @phpstan-type BackTraceFrameArray array{function: string, line?: int, file?: string, class?: class-string, type?: "->"|"::", args?: list<mixed>, object?: object}
31 * @phpstan-type BackTraceArray list<BackTraceFrameArray>
32 *
33 * @see BH_WP_PSR_Logger
34 * @see Logger
35 */
36class API implements API_Interface {
37
38    use LoggerAwareTrait;
39
40    // TODO: replace globals with `wp_cache_set()` etc.
41    const CACHE_GROUP_KEY = 'bh-wp-logger';
42
43    /**
44     *
45     * TODO: IS {@see getmypid()} reliable?
46     * TODO: Add current user id.
47     *
48     * @see https://stackoverflow.com/questions/10404979/get-unique-worker-thread-process-request-id-in-php
49     *
50     * @var array<string,mixed> Common data for context. "state"?
51     */
52    protected array $common_context = array();
53
54    /**
55     * Instantiate the API class with settings provided by the plugin.
56     *
57     * BH_WP_PSR_Logger needs and API instance and API needs a PSR logger instance if it is to log. LoggerAwareTrait
58     * allows setting the logger after instantiation.
59     *
60     * @param Logger_Settings_Interface $settings The settings provided by the plugin to instantiate the logger. Needed for the plugin slug to link correctly.
61     * @param LoggerInterface           $logger A PSR logger, presumably later a BH_WP_PSR_Logger.
62     */
63    public function __construct(
64        protected Logger_Settings_Interface $settings,
65        LoggerInterface $logger
66    ) {
67        $this->setLogger( $logger );
68    }
69
70    /**
71     * Array of data to add to every log entry.
72     * Resets on each new page-load (request).
73     *
74     * @return array<string, mixed>
75     */
76    public function get_common_context(): array {
77        return $this->common_context;
78    }
79
80    /**
81     * Set a value in the common context.
82     *
83     * @param string $key Descriptive key.
84     * @param mixed  $value Will be parsed to JSON later.
85     */
86    public function set_common_context( string $key, mixed $value ): void {
87        $this->common_context[ $key ] = $value;
88    }
89
90    /**
91     * Get the WordPress admin link to the log UI at a date.
92     *
93     * @param ?string $date A date string Y-m-d or null to get the most recent.
94     *
95     * @return string
96     */
97    public function get_log_url( ?string $date = null ): string {
98
99        $query_args = array(
100            'page' => $this->settings->get_plugin_slug() . '-logs',
101        );
102
103        if ( ! empty( $date ) ) {
104            $query_args['date'] = $date;
105        }
106
107        return admin_url( add_query_arg( $query_args, 'admin.php' ) );
108    }
109
110    /**
111     * Scan the logs files dir for the latest log file, or the log file matching the supplied date.
112     *
113     * TODO: Test the regex. It seems to be pulling in all files that match a date?
114     *
115     * @param ?string $date In 'Y-m-d' format. e.g. '2021-09-16'.
116     *
117     * @return array<string, string> Y-m-d index with path as the value.
118     */
119    public function get_log_files( ?string $date = null ): array {
120
121        // TODO: Replace WC_LOG_DIR check with the plugin_active check that is used overall.
122        if ( ( $this->settings instanceof WooCommerce_Logger_Settings_Interface ) && defined( 'WC_LOG_DIR' ) && is_string( constant( 'WC_LOG_DIR' ) ) ) {
123
124            /** @var string $log_files_dir */
125            $log_files_dir = constant( 'WC_LOG_DIR' );
126
127        } else {
128
129            $log_files_dir = wp_normalize_path( WP_CONTENT_DIR . '/uploads/logs/' );
130        }
131
132        $files      = scandir( $log_files_dir );
133        $logs_files = array();
134
135        if ( ! empty( $files ) ) {
136            foreach ( $files as $filename ) {
137                if ( ! in_array( $filename, array( '.', '..' ), true ) ) {
138
139                    if ( ! is_dir( $filename ) && strstr( $filename, '.log' ) ) {
140
141                        if ( 1 === preg_match( '/^' . $this->settings->get_plugin_slug() . '-(\d{4}-\d{2}-\d{2}).*/', $filename, $regex_matches ) ) {
142                            $logs_files[ "{$regex_matches[1]}" ] = $log_files_dir . $filename;
143
144                            if ( ! is_null( $date ) && $regex_matches[1] === $date ) {
145                                $path     = $log_files_dir . $filename;
146                                $realpath = realpath( $path );
147                                return array( $date => false === $realpath ? $path : $realpath );
148                            }
149                        }
150                    }
151                }
152            }
153        }
154
155        ksort( $logs_files );
156
157        return $logs_files;
158    }
159
160    /**
161     * Delete a specific date's log file.
162     *
163     * @param string $ymd_date The date formatted Y-m-d, e.g. 2021-09-27.
164     *
165     * @used-by Logs_Page
166     *
167     * @return array{success:bool, message?:string}
168     */
169    public function delete_log( string $ymd_date ): array {
170
171        $result = array();
172
173        $log_file_paths_by_date = $this->get_log_files();
174
175        if ( ! isset( $log_file_paths_by_date[ $ymd_date ] ) ) {
176            $result['success'] = false;
177            $message           = 'Log file not found for date: ' . $ymd_date;
178            $result['message'] = $message;
179            $this->logger->warning( $message );
180            return $result;
181        }
182
183        wp_delete_file( $log_file_paths_by_date[ $ymd_date ] );
184        $result['success'] = true;
185        $message           = 'Logfile deleted at ' . $log_file_paths_by_date[ $ymd_date ];
186        $result['message'] = $message;
187        $this->logger->info( $message, array( 'logfile' => $log_file_paths_by_date[ $ymd_date ] ) );
188
189        return $result;
190    }
191
192    /**
193     * Delete all logs for this plugin.
194     *
195     * @used-by Logs_Page
196     *
197     * @return array{success:bool, deleted_files:array<string>, failed_to_delete:array<string>}
198     */
199    public function delete_all_logs(): array {
200
201        $result = array();
202
203        $deleted_files    = array();
204        $failed_to_delete = array();
205
206        $log_file_paths_by_date = $this->get_log_files();
207
208        foreach ( $log_file_paths_by_date as $date => $log_filepath ) {
209            $deleted = wp_delete_file( $log_filepath );
210            if ( $deleted ) {
211                $deleted_files[ $date ] = $log_filepath;
212            } else {
213                $failed_to_delete[ $date ] = $log_filepath;
214            }
215        }
216
217        $result['deleted_files']    = $deleted_files;
218        $result['failed_to_delete'] = $failed_to_delete;
219        $result['success']          = empty( $failed_to_delete );
220
221        return $result;
222    }
223
224    /**
225     * Deletes log files older than MONTH_IN_SECONDS.
226     * Deletes empty log files.
227     *
228     * TODO: Do not use for WooCommerce_Logger_Interface, because WooCommerce handles deleting logs itself.
229     *
230     * @used-by Cron::delete_old_logs()
231     */
232    public function delete_old_logs(): void {
233
234        $existing_logs = $this->get_log_files();
235
236        foreach ( $existing_logs as $date => $log_filepath ) {
237
238            if ( strtotime( $date ) < time() - MONTH_IN_SECONDS ) {
239                $this->logger->debug( 'deleting old log file ' . $log_filepath );
240                wp_delete_file( $log_filepath );
241            } elseif ( 0 === filesize( $log_filepath ) ) {
242                $this->logger->debug( 'deleting empty log file ' . $log_filepath );
243                wp_delete_file( $log_filepath );
244            }
245        }
246
247        // TODO: delete the last visited option if it's older than the most recent logs.
248    }
249
250
251    /**
252     * Get the backtrace and skips:
253     * * function calls from inside this file
254     * * call_user_func_array()
255     * * function calls from other plugins using this same library (using filename).
256     *
257     * @param ?string $source_hash A unique identifier for the source of the log entry. Used to cache the backtrace. The backtrace will not be cached if this is absent.
258     * @param ?int    $steps The number of backtrace entries to return.
259     *
260     * @return BackTraceArray
261     */
262    public function get_backtrace( ?string $source_hash = null, ?int $steps = null ): array {
263
264        if ( ! empty( $source_hash ) ) {
265            $backtrace_cached = $this->get_cached_backtrace( $source_hash );
266
267            if ( is_array( $backtrace_cached ) ) {
268                return $backtrace_cached;
269            }
270        }
271
272        /**
273         * This is critical to the library.
274         *
275         * phpcs:disable WordPress.PHP.DevelopmentFunctions.error_log_debug_backtrace
276         *
277         * @var BackTraceArray $backtrace
278         */
279        $backtrace = debug_backtrace();
280
281        $ignore_starting_frame = function ( array $frame ): bool {
282            /** @var BackTraceFrameArray $frame */
283            switch ( true ) {
284                case isset( $frame['file'] ) && __FILE__ === $frame['file']:
285                case 'call_user_func_array' === $frame['function']:
286                case isset( $frame['file'] ) && basename( $frame['file'] ) === 'class-php-error-handler.php':
287                case isset( $frame['file'] ) && basename( $frame['file'] ) === 'class-functions.php':
288                case isset( $frame['file'] ) && false !== stripos( $frame['file'], 'bh-wp-logger/includes' ):
289                case isset( $frame['file'] ) && false !== stripos( $frame['file'], 'psr/log/Psr/Log/' ):
290                case isset( $frame['file'] ) && str_contains( $frame['file'], 'php-http/logger-plugin' ):
291                    return true;
292                default:
293                    return false;
294            }
295        };
296
297        foreach ( $backtrace as $index => $frame ) {
298            if ( $ignore_starting_frame( $frame ) ) {
299                unset( $backtrace[ $index ] );
300            } else {
301                break;
302            }
303        }
304        /** @var BackTraceArray $backtrace */
305
306        if ( ! is_null( $source_hash ) ) {
307            $this->set_cached_backtrace( $source_hash, $backtrace );
308        }
309
310        return $backtrace;
311    }
312
313    /**
314     * Save the backtrace to a global cache.
315     *
316     * @see PHP_Error_Handler::is_related_error()
317     *
318     * If other plugins are using bh-wp-logger, they can use this cache to avoid rerunning the backtrace.
319     *
320     * @see debug_backtrace()
321     *
322     * @param string               $source_hash A unique identifier for backtrace – `implode(func_get_args())` of the error handler is used.
323     * @param BackTraceArray&array $backtrace The PHP backtrace, presumably filtered to remove irrelevant frames.
324     */
325    protected function set_cached_backtrace( string $source_hash, array $backtrace ): void {
326        if ( ! isset( $GLOBALS['bh_wp_logger_cache'] ) || ! is_array( $GLOBALS['bh_wp_logger_cache'] ) ) {
327            $GLOBALS['bh_wp_logger_cache'] = array();
328        }
329        $source_hash                                   = sanitize_key( $source_hash );
330        $GLOBALS['bh_wp_logger_cache'][ $source_hash ] = $backtrace;
331    }
332
333    /**
334     * Check if the backtrace for this error already been run.
335     *
336     * @param string $source_hash A unique identifier for backtrace.
337     *
338     * @return ?BackTraceArray
339     */
340    protected function get_cached_backtrace( string $source_hash ): ?array {
341        $source_hash = sanitize_key( $source_hash );
342
343        if ( ! isset( $GLOBALS['bh_wp_logger_cache'] ) ) {
344            return null;
345        }
346
347        /** @var array<string, BackTraceArray> $bh_wp_logger_cache */
348        global $bh_wp_logger_cache;
349
350        return $bh_wp_logger_cache[ $source_hash ] ?? null;
351    }
352
353    /**
354     * Checks each file in the backtrace and if it contains WP_PLUGINS_DIR/plugin-slug then return true.
355     *
356     * @param ?string $source_hash A unique identifier for the source of the log entry.
357     */
358    public function is_backtrace_contains_plugin( ?string $source_hash = null ): bool {
359
360        $frames = $this->get_backtrace( $source_hash );
361
362        $is_file_from_plugin = false;
363
364        foreach ( $frames as $frame ) {
365
366            if ( isset( $frame['file'] ) && $this->is_file_from_plugin( $frame['file'] ) ) {
367                $is_file_from_plugin = true;
368                break;
369            }
370        }
371
372        return $is_file_from_plugin;
373    }
374
375    /**
376     * Given a filepath, tries to determine if this file is part of this plugin.
377     *
378     * TODO: Be consistent about meanings of plugin-slug and plugin basename.
379     * TODO: Remove code duplication with Plugins class.
380     *
381     * @see Plugins::get_plugin_data_from_slug()
382     *
383     * @param string $filepath Path to the file to be checked.
384     */
385    public function is_file_from_plugin( string $filepath ): bool {
386        return str_starts_with( plugin_basename( realpath( $filepath ) ?: $filepath ), $this->settings->get_plugin_slug() );
387    }
388
389    /**
390     * Get the name of the plugin-specific transient which indicates the last log message time.
391     *
392     * The value is used on plugins.php to show if new logs have been recorded.
393     * A transient is used to avoid re-calculating it from reading the log files from disk.
394     *
395     * @return string
396     */
397    public function get_last_log_time_transient_name(): string {
398        return $this->settings->get_plugin_slug() . '-last-log-time';
399    }
400
401    /**
402     * Used on plugins.php to highlight the logs link if there are new logs since they were last viewed.
403     *
404     * Saves the time in a 24-hour transient to avoid filesystem calls. The transient is deleted when the log is written to.
405     */
406    public function get_last_log_time(): ?DateTimeInterface {
407
408        // If a user can't access `plugins.php`, this method is moot.
409        if ( ! current_user_can( 'activate_plugins' ) ) {
410            return null;
411        }
412
413        $transient_name = $this->get_last_log_time_transient_name();
414
415        $transient_value = get_transient( $transient_name );
416
417        if ( is_string( $transient_value ) ) {
418            try {
419                return new DateTimeImmutable( $transient_value, new DateTimeZone( 'UTC' ) );
420            } catch ( Exception $_exception ) {
421                delete_transient( $transient_name );
422            }
423        }
424
425        $log_files = $this->get_log_files();
426
427        $reverse_chronological_log_files = array_reverse( $log_files );
428
429        if ( empty( $GLOBALS['wp_filesystem'] ) ) {
430            WP_Filesystem();
431        }
432
433        /** @var WP_Filesystem_Base $wp_filesystem */
434        global $wp_filesystem;
435
436        foreach ( $reverse_chronological_log_files as $last_log_file_path ) {
437
438            if ( ! $wp_filesystem->exists( $last_log_file_path ) ) {
439                continue;
440            }
441
442            $timestamp = $wp_filesystem->mtime( $last_log_file_path );
443
444            if ( ! is_numeric( $timestamp ) ) {
445                continue;
446            }
447
448            $datetime = new DateTimeImmutable( "@{$timestamp}" );
449
450            set_transient( $transient_name, $datetime->format( DateTimeInterface::ATOM ), DAY_IN_SECONDS );
451
452            // Log time will always be UTC.
453            return $datetime;
454        }
455
456        return null;
457    }
458
459    /**
460     * Used on plugins.php to highlight the logs link if there are new logs since they were last viewed.
461     *
462     * @return ?DateTimeInterface
463     */
464    public function get_last_logs_view_time(): ?DateTimeInterface {
465
466        $option_name                    = $this->settings->get_plugin_slug() . '-last-logs-view-time';
467        $last_log_view_time_atom_string = get_option( $option_name );
468
469        if ( ! is_string( $last_log_view_time_atom_string ) ) {
470            if ( ! empty( $last_log_view_time_atom_string ) ) {
471                delete_option( $option_name );
472            }
473            return null;
474        }
475
476        $last_log_view_time_datetime = DateTimeImmutable::createFromFormat( DateTimeInterface::ATOM, $last_log_view_time_atom_string, new DateTimeZone( 'UTC' ) );
477
478        if ( false === $last_log_view_time_datetime ) {
479            delete_option( $option_name );
480            return null;
481        }
482
483        return $last_log_view_time_datetime;
484    }
485
486    /**
487     * Record the last time the logs were viewed in order to determine if admin notices should or should not be displayed.
488     * i.e. "mark read".
489     *
490     * @used-by Logs_Page
491     *
492     * @param ?DateTimeInterface $date_time A time to set, defaults to "now".
493     *
494     * phpcs:disable Generic.CodeAnalysis.EmptyStatement.DetectedCatch
495     */
496    public function set_last_logs_view_time( ?DateTimeInterface $date_time = null ): void {
497        $option_name = $this->settings->get_plugin_slug() . '-last-logs-view-time';
498
499        try {
500            $date_time ??= new DateTimeImmutable( 'now', new DateTimeZone( 'UTC' ) );
501        } catch ( Exception $_exception ) { /** @phpstan-ignore catch.neverThrown */
502            /**
503             * This will never happen.
504             */
505            return;
506        }
507
508        $atom_time_string = $date_time->format( DateTimeInterface::ATOM );
509
510        update_option( $option_name, $atom_time_string );
511    }
512
513    /**
514     * Given the path to a log file, this returns an array of arrays – an array of log entries, each of which is an
515     * array containing the time, level, message and context.
516     *
517     * @used-by API::get_last_log_time()
518     * @used-by Logs_List_Table::get_data()
519     *
520     * @param string $filepath Path to the log file to read.
521     *
522     * @return array<array{time:string,datetime:DateTime|null,level:string,message:string,context:stdClass|null}>
523     */
524    public function parse_log( string $filepath ): array {
525
526        $file_lines = file( $filepath );
527
528        if ( false === $file_lines ) {
529            // Failed to read file.
530            return array();
531        }
532
533        $entries = array();
534
535        if ( $this->logger instanceof WC_PSR_Logger ) {
536            $pattern = '/^(?P<time>[^\s]*)\s(?P<level>\w*)\s(?P<message>.*?)\sCONTEXT:\s(?P<context>.*)/';
537        } else {
538            $pattern = '/(?P<time>\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}.{1}\d{2}:\d{2})\s(?P<level>\w*)\s(?P<message>.*)/im';
539        }
540
541        // TODO: This will fail if the first line does not parse.
542        foreach ( $file_lines as $input_line ) {
543            $output_array = array();
544            if ( 1 === preg_match( $pattern, $input_line, $output_array ) ) {
545                $entries[] = array(
546                    'line_one_parsed' => $output_array,
547                    'lines'           => array( $output_array['context'] ?? '' ),
548                );
549            } else {
550                $entries[ count( $entries ) - 1 ]['lines'][] = $input_line;
551            }
552        }
553
554        return array_map( array( $this, 'log_lines_to_entry' ), $entries );
555    }
556
557    /**
558     * Given the set of lines that constitutes a single log entry, this parses them into the array of time, level, message, context.
559     *
560     * @used-by API::parse_log()
561     *
562     * @param array{line_one_parsed:array{time:string,level:string,message:string}, lines:string[]} $input_lines A single log entries as a set of lines.
563     *
564     * @return array{time:string,datetime:DateTime|null,level:string,message:string,context:stdClass|null}
565     */
566    protected function log_lines_to_entry( array $input_lines ): array {
567
568        $entry = array();
569
570        $time_string = $input_lines['line_one_parsed']['time'];
571        $str_time    = strtotime( $time_string );
572        // E.g. "2020-10-23T17:39:36+00:00".
573        $datetime = DateTime::createFromFormat( 'U', "{$str_time}" ) ?: null;
574
575        $level = $input_lines['line_one_parsed']['level'];
576
577        $message = $input_lines['line_one_parsed']['message'];
578
579        // Assume all lines that do not begin with a date should be joined together as context object.
580        $context = json_decode( implode( PHP_EOL, $input_lines['lines'] ) );
581        if ( is_null( $context ) ) {
582            foreach ( $input_lines['lines'] as $input_line ) {
583                // This is a bug, but I'm not going to fix it until I see the problem exist.
584                // What happens if there is multiple lines that for some reason are valid JSON? Data will be lost in display.
585                $context = json_decode( $input_line );
586                if ( is_null( $context ) ) {
587                    $message .= $input_line;
588                }
589            }
590        }
591
592        if ( $context instanceof stdClass && isset( $context->source ) ) {
593            unset( $context->source );
594        }
595
596        $entry['time']     = $time_string;
597        $entry['datetime'] = $datetime;
598        $entry['level']    = $level;
599        $entry['message']  = $message;
600        $entry['context']  = $context instanceof stdClass ? $context : null;
601
602        return $entry;
603    }
604}