"; /** * Database handler: only rows this far below the newest row are searched. */ const DB_WINDOW = 20000; /** * Handler class names (compared as strings, case-insensitive). */ const FILE_HANDLERS = array( 'Automattic\\WooCommerce\\Internal\\Admin\\Logging\\LogHandlerFileV2', 'WC_Log_Handler_File' ); const DB_HANDLER = 'WC_Log_Handler_DB'; /** * Bytes read from the end of each file (filter `apwc_webhook_health_log_bytes`, 16 KB–1 MB). * * @since 1.0.0 * @return int */ public static function log_bytes(): int { /** * Filter how much of each webhook delivery log file Webhook health reads, from the end. * Clamped to 16 KB–1 MB; at most 3 files are read. * * @since 1.0.0 * @param int $bytes Bytes (default 256 KB). */ $bytes = (int) apply_filters( 'apwc_webhook_health_log_bytes', 256 * KB_IN_BYTES ); return max( 16 * KB_IN_BYTES, min( MB_IN_BYTES, $bytes ) ); } /** * Default number of deliveries shown (filter `apwc_webhook_health_deliveries_limit`, 1–200). * * @since 1.0.0 * @return int */ public static function default_limit(): int { /** * Filter how many recent webhook deliveries Webhook health shows. Clamped to 1–200. * * @since 1.0.0 * @param int $limit Deliveries (default 50). */ $limit = (int) apply_filters( 'apwc_webhook_health_deliveries_limit', 50 ); return max( 1, min( 200, $limit ) ); } /** * The recent deliveries, newest first. * * @since 1.0.0 * @param int $limit Most rows (1–200). * @return array{state: string, handler: string, rows: array>, unparsed: int, threshold: string, last: array>} * last: the newest row per webhook ID among every row read (not only the rows returned). * state: ok, off (logging off), threshold (Info not logged), other (another handler), * unreadable (log folder), unavailable (WooCommerce too old). */ public static function read( int $limit ): array { $limit = max( 1, min( 200, $limit ) ); $out = array( 'state' => 'ok', 'handler' => '', 'rows' => array(), 'unparsed' => 0, 'threshold' => '', 'last' => array(), ); try { $enabled = LoggingUtil::logging_is_enabled(); $threshold = strtolower( LoggingUtil::get_level_threshold() ); $handler = ltrim( LoggingUtil::get_default_handler(), '\\' ); } catch ( \Throwable $e ) { $out['state'] = 'unavailable'; return $out; } if ( ! $enabled ) { $out['state'] = 'off'; return $out; } if ( self::threshold_hides_info( $threshold ) ) { $out['state'] = 'threshold'; $out['threshold'] = $threshold; return $out; } $out['handler'] = $handler; $files = self::is_handler( $handler, self::FILE_HANDLERS ); if ( $files ) { // While WooCommerce logs bodies, repeats are rejected anyway: no need to scan the files. $parsed = self::from_files( self::log_directory(), ! self::bodies_logged() ); } elseif ( self::is_handler( $handler, array( self::DB_HANDLER ) ) ) { $parsed = self::from_database( $limit ); } else { $out['state'] = 'other'; return $out; } if ( null === $parsed ) { $out['state'] = 'unreadable'; return $out; } $checked = self::screen( $parsed['rows'], $files, time(), $parsed['bodies'] ); $rows = $checked['rows']; // Newest first; entries with the same second keep their log order (later = newer). $order = array_keys( $rows ); array_multisort( array_column( $rows, 'time' ), SORT_DESC, $order, SORT_DESC, $rows ); foreach ( $rows as $row ) { if ( ! isset( $out['last'][ $row['webhook_id'] ] ) ) { $out['last'][ $row['webhook_id'] ] = $row; // From every row read, not only the rows shown. } } $out['rows'] = array_slice( $rows, 0, $limit ); $out['unparsed'] = $parsed['unparsed'] + $checked['rejected']; return $out; } /** * Drop rows that can't be genuine deliveries, counting them as rejected: * - dated more than 60 s in the future; * - file handlers only: a Delivery ID that isn't the one WooCommerce builds * (`WC_Webhook::get_new_delivery_id()`: `wp_hash( $webhook_id . $time )`, with $time taken * when the delivery started, so between the entry time minus its duration (and 2 s) and the * entry time); * - file handlers only, while bodies may be in the log (below): a Delivery ID already read * (the first one read wins). * Otherwise repeated Delivery IDs are kept: the ID only changes once a second, so deliveries of * one webhook that start in the same second (one queue batch) share it, and each is real. * * Threat model: the only text a webhook receiver writes into a file log that can hold a line * break is its response body, which WooCommerce logs raw only under WP_DEBUG (otherwise both * bodies are LogParser::BODY_PLACEHOLDER). Bare CRs in header values are inert because lines * split on LF only (see LogParser). A logged body can hold text shaped like whole entries. * Without the site's salt it can't make a new valid Delivery ID, but it can reuse any ID it * ever received (X-WC-Webhook-Delivery-ID header), dated up to about 302 s after it (the * window genuine() allows). On multisite the sites share the log folder and the salt, so an ID * received for one site's webhook also verifies for the same-numbered webhook on another site. * * So repeats are rejected whenever bodies may be in the log: a file read may hold one * anywhere, not just in its tail ($bodies_in_log: from_files() scans each whole file with * may_hold_bodies(); one over SCAN_MAX counts), a row read has a logged request body * (`raw_body`), or WooCommerce logs bodies right now (bodies_logged()). A forged entry sits * inside the response body of a real entry, in the same file, after that entry's first line. * When WooCommerce writes deliveries as print_r() dumps (wc_print_r()'s first choice), that * entry's request Body line also comes first and isn't the placeholder, so the scan finds it * even when the entry starts outside the tail. When wc_print_r() falls back to var_export(), * json_encode() or serialize(), there's no such line (and var_export() and serialize() keep a * body's line breaks), so the scan also counts any entry line whose message isn't exactly * "Array". Either line is written by WooCommerce before the body, so a receiver can't remove * it. The database handler keeps one message per row, so a body can't add rows there: * repeats are always kept. * * Limits of "first one read wins": a forged entry still shows once with an ID whose real entry * isn't among the rows read (outside the read window), and the same applies when the real * entry is logged later: with concurrent deliveries of one webhook under WP_DEBUG, a forged * row read first replaces the real result, which is then dropped as the repeat. * * @since 1.0.0 * @param array> $rows Parsed rows, oldest first. * @param bool $verify_hash Check Delivery IDs (file handlers). * @param int $now Current Unix time. * @param bool $bodies_in_log A file read may hold a logged body (from_files()). * @return array{rows: array>, rejected: int} rejected: rows dropped. */ public static function screen( array $rows, bool $verify_hash, int $now, bool $bodies_in_log = false ): array { $unique = $verify_hash && ( $bodies_in_log || self::bodies_logged() || self::any_raw_body( $rows ) ); $out = array(); $seen = array(); foreach ( $rows as $row ) { $time = (int) $row['time']; $id = (string) $row['delivery_id']; if ( $time > $now + 60 || ( $verify_hash && ! self::genuine( $row ) ) ) { continue; } if ( $unique && '' !== $id ) { if ( isset( $seen[ $id ] ) ) { continue; } $seen[ $id ] = true; } $out[] = $row; } return array( 'rows' => $out, 'rejected' => count( $rows ) - count( $out ), ); } /** * Whether WooCommerce logs webhook bodies right now: `WC_Webhook::log_delivery()` logs them raw * while WP_DEBUG is on. Checked the same way (Jetpack's Constants, which tests can override). * * @since 1.0.0 * @return bool */ public static function bodies_logged(): bool { if ( class_exists( Constants::class ) ) { return (bool) Constants::is_true( 'WP_DEBUG' ); } return defined( 'WP_DEBUG' ) && WP_DEBUG; } /** * Whether any row was logged with its bodies. A row without the flag counts as logged. * * @since 1.0.0 * @param array> $rows Parsed rows. * @return bool */ private static function any_raw_body( array $rows ): bool { foreach ( $rows as $row ) { if ( ! isset( $row['raw_body'] ) || false !== $row['raw_body'] ) { return true; } } return false; } /** * Whether a row's Delivery ID is the one WooCommerce built for that webhook around that time. * * @since 1.0.0 * @param array $row Parsed row (webhook_id, delivery_id, duration, time). * @return bool */ public static function genuine( array $row ): bool { $id = (string) $row['delivery_id']; $time = (int) $row['time']; if ( '' === $id || $time <= 0 ) { return false; } $took = null === $row['duration'] ? 0 : (int) ceil( min( 300.0, (float) $row['duration'] ) ); for ( $t = $time; $t >= $time - $took - 2; $t-- ) { if ( hash_equals( wp_hash( (int) $row['webhook_id'] . $t ), $id ) ) { return true; } } return false; } /** * Whether WooCommerce's level threshold drops Info entries (deliveries are logged as Info). * * @since 1.0.0 * @param string $threshold Threshold level, or 'none'. * @return bool */ public static function threshold_hides_info( string $threshold ): bool { if ( '' === $threshold || 'none' === $threshold || ! class_exists( 'WC_Log_Levels' ) || ! \WC_Log_Levels::is_valid_level( $threshold ) ) { return false; } return \WC_Log_Levels::get_level_severity( 'info' ) < \WC_Log_Levels::get_level_severity( $threshold ); } /** * Whether a handler class name is one of these (by name only). * * @since 1.0.0 * @param string $handler Class name. * @param string[] $names Names. * @return bool */ private static function is_handler( string $handler, array $names ): bool { foreach ( $names as $name ) { if ( 0 === strcasecmp( $handler, $name ) ) { return true; } } return false; } /** * WooCommerce's log folder (never created here), or ''. * * @since 1.0.0 * @return string */ public static function log_directory(): string { try { return LoggingUtil::get_log_directory( false ); } catch ( \Throwable $e ) { return defined( 'WC_LOG_DIR' ) ? (string) WC_LOG_DIR : ''; } } /** * The newest delivery log files inside a folder: real paths, newest first, at most MAX_FILES. * * @since 1.0.0 * @param string $dir Folder. * @return string[]|null Null when the folder can't be read. */ public static function files( string $dir ): ?array { $real = '' === $dir ? false : realpath( $dir ); if ( false === $real || ! is_dir( $real ) || ! is_readable( $real ) ) { return null; } $names = scandir( $real ); // Not glob(): the folder path could contain pattern characters. if ( false === $names ) { return null; } $files = array(); $base = rtrim( $real, '/\\' ) . DIRECTORY_SEPARATOR; foreach ( $names as $name ) { if ( ! str_starts_with( $name, self::SOURCE ) || ! str_ends_with( $name, '.log' ) ) { continue; } $path = realpath( $base . $name ); // The real path (links resolved) must still be a file directly inside the log folder. if ( false === $path || ! str_starts_with( $path, $base ) || false !== strpbrk( substr( $path, strlen( $base ) ), '/\\' ) || ! is_file( $path ) || ! is_readable( $path ) ) { continue; } $files[ $path ] = (int) filemtime( $path ); } arsort( $files ); return array_slice( array_keys( $files ), 0, self::MAX_FILES ); } /** * Parse the newest delivery files. * * @since 1.0.0 * @param string $dir Log folder. * @param bool $scan Scan each whole file for logged bodies (may_hold_bodies()). * @return array{rows: array>, unparsed: int, bodies: bool}|null * Null when the folder can't be read. bodies: a file read may hold a logged body, or * is too large to scan. */ private static function from_files( string $dir, bool $scan ): ?array { $files = self::files( $dir ); if ( null === $files ) { return null; } $rows = array(); $unparsed = 0; $bodies = false; $bytes = self::log_bytes(); foreach ( array_reverse( $files ) as $file ) { // Oldest first, so later rows are newer. $read = self::read_file( $file, $bytes, $scan && ! $bodies ); // One finding is enough. $bodies = $bodies || $read['bodies']; if ( '' === $read['text'] ) { continue; } $parsed = LogParser::parse_file_text( $read['text'] ); $rows = array_merge( $rows, $parsed['rows'] ); $unparsed += $parsed['unparsed']; } return array( 'rows' => $rows, 'unparsed' => $unparsed, 'bodies' => $bodies, ); } /** * Read one log file through one handle, from one snapshot (its size when opened, so text * appended meanwhile is neither scanned nor read): its last bytes and, when asked, whether * the whole file may hold a logged body (may_hold_bodies(); a file over SCAN_MAX counts). * A file rotated or deleted since files() listed it is skipped quietly (no warning, which * would break the REST answer while errors are displayed). * * @since 1.0.0 * @param string $file Real path (checked by files()). * @param int $bytes Most bytes read from the end. * @param bool $scan Scan the whole file (may_hold_bodies()). * @return array{text: string, bodies: bool} */ private static function read_file( string $file, int $bytes, bool $scan ): array { // phpcs:disable WordPress.WP.AlternativeFunctions.file_system_operations_fopen, WordPress.WP.AlternativeFunctions.file_system_operations_fread, WordPress.WP.AlternativeFunctions.file_system_operations_fclose -- bounded reads (fseek) of a local log file; WP_Filesystem can only read whole files. // phpcs:ignore WordPress.PHP.NoSilencedErrors.Discouraged -- the file can still be rotated away between the check and the open; the failure is handled (skipped). $handle = is_readable( $file ) ? @fopen( $file, 'rb' ) : false; if ( false === $handle ) { return array( 'text' => '', 'bodies' => false, ); } $stat = fstat( $handle ); $size = is_array( $stat ) ? (int) $stat['size'] : 0; $bodies = $scan && ( $size > self::SCAN_MAX || self::may_hold_bodies( $handle, $size ) ); $text = ''; if ( $size > 0 && 0 === fseek( $handle, max( 0, $size - $bytes ) ) ) { $part = fread( $handle, min( $size, $bytes ) ); $text = is_string( $part ) ? $part : ''; } fclose( $handle ); // phpcs:enable return array( 'text' => $text, 'bodies' => $bodies, ); } /** * Whether the first $size bytes of an open log file may hold a webhook body WooCommerce * logged (text a receiver wrote, which can contain lines shaped like log entries). Either is * enough: * - a delivery-level request Body line (LF, exactly 12 spaces, "[Body] => ") whose value isn't * LogParser::BODY_PLACEHOLDER followed by the line end: a print_r() dump logged under * WP_DEBUG; * - an entry line (LogParser::ENTRY_START at the start of the file or after an LF) whose * message isn't exactly "Array" (a trailing CR allowed): not a print_r() dump. wc_print_r() * falls back to var_export(), json_encode() or serialize() when print_r() is unavailable or * `woocommerce_print_r_alternatives` reorders them; var_export() and serialize() keep a * body's line breaks, and such an entry has no Body line to check. * WooCommerce writes both lines before the body, so a receiver can't remove them: either rule * can only make a read stricter. Read in parts of $chunk bytes; each part keeps the last * bytes of the one before (enough for a whole Body line or entry start), so a line split * between parts is still judged whole. Fail-safe: a short read, or a Body line cut off by the * end of the file, counts. * * @since 1.0.0 * @param resource $handle File handle (read from the start). * @param int $size Bytes to scan (the snapshot size). * @param int $chunk Bytes read at a time. * @return bool */ public static function may_hold_bodies( $handle, int $size, int $chunk = self::SCAN_CHUNK ): bool { $keep = strlen( self::BODY_LINE ) + strlen( LogParser::BODY_PLACEHOLDER ) + 2; // A whole Body line, with "\r\n". $chunk = max( 1, $chunk ); if ( $size <= 0 ) { return false; } if ( ! rewind( $handle ) ) { return true; } $carry = ''; $first = true; // $buf starts at the start of the file. $done = 0; while ( $done < $size ) { // phpcs:ignore WordPress.WP.AlternativeFunctions.file_system_operations_fread -- bounded part of a local log file. $part = fread( $handle, min( $chunk, $size - $done ) ); if ( ! is_string( $part ) || '' === $part ) { return true; // Couldn't read it all. } $done += strlen( $part ); $buf = $carry . $part; $last = $done >= $size; if ( self::body_line_logged( $buf, $last, $keep ) || self::other_entry_line( $buf, $last, $keep, $first ) ) { return true; } $len = strlen( $buf ); $first = $first && $len <= $keep; // Still at the file's start only while all of it is kept. $carry = $len > $keep ? substr( $buf, -$keep ) : $buf; } return false; } /** * In a scan part: a delivery-level request Body line whose value isn't the placeholder. A line * the part cuts off is left to the next part (the last $keep bytes are kept), unless the part * ends the file. * * @since 1.0.0 * @param string $buf Part, after the bytes kept from the one before. * @param bool $last The part ends the file. * @param int $keep Bytes kept for the next part. * @return bool */ private static function body_line_logged( string $buf, bool $last, int $keep ): bool { $len = strlen( $buf ); $quiet = LogParser::BODY_PLACEHOLDER; $after = strlen( self::BODY_LINE ) + strlen( $quiet ); // Where the line end must follow. $at = strpos( $buf, self::BODY_LINE ); while ( false !== $at ) { if ( ! $last && $len - $at < $keep ) { return false; // This line and any after it: judged with the next part. } $end = substr( $buf, $at + $after, 2 ); if ( $len - $at < $after || 0 !== substr_compare( $buf, $quiet, $at + strlen( self::BODY_LINE ), strlen( $quiet ) ) || ( "\r\n" !== $end && ! str_starts_with( $end, "\n" ) ) ) { return true; } $at = strpos( $buf, self::BODY_LINE, $at + 1 ); } return false; } /** * In a scan part: an entry line whose message isn't exactly "Array" (a trailing CR allowed). * Lines start after an LF, or at the part's start when that's the file's start. A line the * part cuts off is left to the next part: LogParser::ENTRY_START is at most 43 bytes (time and * a level of up to 16 letters), so with the 7 bytes judged after it, the kept bytes always hold * the line's start and the LF before it (the check below counts the line should that change). * A longer level isn't an entry line for the parser either. * * @since 1.0.0 * @param string $buf Part, after the bytes kept from the one before. * @param bool $last The part ends the file. * @param int $keep Bytes kept for the next part. * @param bool $first The part starts at the file's start. * @return bool */ private static function other_entry_line( string $buf, bool $last, int $keep, bool $first ): bool { $len = strlen( $buf ); $starts = array(); // Line start => message start. $found = $first ? preg_match( '/\A' . LogParser::ENTRY_START . '/', $buf, $m ) : 0; $lines = preg_match_all( '/\n' . LogParser::ENTRY_START . '/', $buf, $all, PREG_OFFSET_CAPTURE ); if ( false === $found || false === $lines ) { return true; // The pattern failed (PCRE limits): count it. } if ( $found ) { $starts[0] = strlen( $m[0] ); } foreach ( $all[0] as $match ) { $starts[ (int) $match[1] + 1 ] = (int) $match[1] + strlen( (string) $match[0] ); } $kept_from = $len - min( $len, $keep ); // Where the bytes kept for the next part begin. foreach ( $starts as $start => $message ) { $text = substr( $buf, $message, 7 ); if ( str_starts_with( $text, "Array\n" ) || "Array\r\n" === $text ) { continue; // A print_r() dump. } if ( $last && ( 'Array' === $text || "Array\r" === $text ) ) { continue; // The file ends on it. } if ( ! $last && strlen( $text ) < 7 ) { // Cut off by the part: judged again with the next part if it keeps the line's start. if ( 0 === $start ? 0 === $kept_from : $start - 1 >= $kept_from ) { continue; } } return true; } return false; } /** * Newest delivery rows from WooCommerce's database log. * * @since 1.0.0 * @param int $limit Most rows. * @return array{rows: array>, unparsed: int, bodies: bool}|null * bodies: always false (one message per row: a body can't add rows). */ private static function from_database( int $limit ): ?array { global $wpdb; $table = $wpdb->prefix . 'woocommerce_log'; $suppress = $wpdb->suppress_errors( true ); // phpcs:disable WordPress.DB.DirectDatabaseQuery.DirectQuery, WordPress.DB.DirectDatabaseQuery.NoCaching -- WooCommerce's own log table; read on demand from the tool tab. $max = (int) $wpdb->get_var( $wpdb->prepare( 'SELECT MAX(log_id) FROM %i', $table ) ); $list = $max > 0 ? $wpdb->get_results( $wpdb->prepare( 'SELECT log_id, timestamp, message FROM %i WHERE log_id > %d AND source = %s ORDER BY log_id DESC LIMIT %d', $table, max( 0, $max - self::DB_WINDOW ), self::SOURCE, $limit ) ) : array(); // phpcs:enable $failed = '' !== $wpdb->last_error; $wpdb->suppress_errors( $suppress ); if ( $failed || ! is_array( $list ) ) { return null; } $rows = array(); $unparsed = 0; foreach ( array_reverse( $list ) as $entry ) { // Oldest first, like the files. $row = LogParser::parse_message( (string) $entry->message ); if ( null === $row ) { ++$unparsed; continue; } $time = strtotime( (string) $entry->timestamp . ' UTC' ); // WooCommerce stores it in UTC. $row['time'] = false === $time ? 0 : $time; $rows[] = $row; } return array( 'rows' => $rows, 'unparsed' => $unparsed, 'bodies' => false, ); } /** * The delivery queue (Action Scheduler jobs WooCommerce uses for webhook deliveries): pending * and failed counts and how late the oldest pending one is. Null when Action Scheduler isn't there. * * @since 1.0.0 * @return array{pending: int, failed: int, oldest_late: int}|null oldest_late in seconds (0 = on time). */ public static function queue(): ?array { if ( ! class_exists( '\ActionScheduler' ) || ! \ActionScheduler::is_initialized() || ! function_exists( 'as_get_scheduled_actions' ) ) { return null; } $store = \ActionScheduler::store(); $hook = 'woocommerce_deliver_webhook_async'; try { $pending = (int) $store->query_actions( array( 'hook' => $hook, 'status' => \ActionScheduler_Store::STATUS_PENDING, ), 'count' ); $failed = (int) $store->query_actions( array( 'hook' => $hook, 'status' => \ActionScheduler_Store::STATUS_FAILED, ), 'count' ); $late = 0; if ( $pending > 0 ) { $oldest = as_get_scheduled_actions( array( 'hook' => $hook, 'status' => \ActionScheduler_Store::STATUS_PENDING, 'orderby' => 'date', 'order' => 'ASC', 'per_page' => 1, ), 'ids' ); if ( $oldest ) { $date = $store->get_date( (int) reset( $oldest ) ); $late = max( 0, time() - (int) $date->getTimestamp() ); } } } catch ( \Throwable $e ) { return null; } return array( 'pending' => $pending, 'failed' => $failed, 'oldest_late' => $late, ); } }