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