| 1 |
<?php |
| 2 |
/** |
| 3 |
* Client error logging. |
| 4 |
* |
| 5 |
* Owns the debug log file that the "Enable Logs" setting writes to: where it |
| 6 |
* lives, what may be written to it, and how large it is allowed to get. Nothing |
| 7 |
* else in the plugin should open that file. |
| 8 |
* |
| 9 |
* The log records form-submission failures reported by the visitor's browser — |
| 10 |
* the HTTP status and duration of the submit request, and the error behind a |
| 11 |
* failure — so a site owner can reproduce a bug and hand the file to support |
| 12 |
* instead of being talked through DevTools. |
| 13 |
* |
| 14 |
* @package SureForms |
| 15 |
* @since 2.12.6 |
| 16 |
*/ |
| 17 |
|
| 18 |
namespace SRFM\Inc; |
| 19 |
|
| 20 |
if ( ! defined( 'ABSPATH' ) ) { |
| 21 |
exit; |
| 22 |
} |
| 23 |
|
| 24 |
/** |
| 25 |
* Client_Logger |
| 26 |
* |
| 27 |
* Design notes that are load-bearing: |
| 28 |
* |
| 29 |
* - Every method fails silently. The uploads directory is not writable on |
| 30 |
* hardened or read-only-deploy hosts, and a logger that warns or fatals on a |
| 31 |
* visitor-facing request is worse than one that records nothing. |
| 32 |
* - The file name is unguessable and never disclosed. `.htaccess` does nothing |
| 33 |
* on nginx, so the name is the real protection; the download handler derives |
| 34 |
* the path itself and takes no filename parameter. |
| 35 |
* - Over the size cap the log stops accepting writes rather than trimming or |
| 36 |
* rotating. Someone reproducing a bug must not have the tail of their repro |
| 37 |
* evicted by newer noise from an unrelated visitor. |
| 38 |
* |
| 39 |
* @since 2.12.6 |
| 40 |
*/ |
| 41 |
class Client_Logger { |
| 42 |
/** |
| 43 |
* Option holding the random component of the log file name. |
| 44 |
* |
| 45 |
* @since 2.12.6 |
| 46 |
*/ |
| 47 |
public const FILENAME_OPTION = 'srfm_client_log_file'; |
| 48 |
|
| 49 |
/** |
| 50 |
* Consecutive faults before the site owner is told something is wrong. |
| 51 |
* |
| 52 |
* One. A fault is already filtered down to what a visitor cannot fix by trying |
| 53 |
* again -- the request never reached PHP, the response was not JSON, the server |
| 54 |
* errored, an email could not be sent -- so waiting for a run of them means |
| 55 |
* staying quiet through the first several lost submissions. |
| 56 |
* |
| 57 |
* @since 2.12.6 |
| 58 |
*/ |
| 59 |
public const FAULT_THRESHOLD = 1; |
| 60 |
|
| 61 |
/** |
| 62 |
* Maximum size of the log file in bytes. |
| 63 |
* |
| 64 |
* @since 2.12.6 |
| 65 |
*/ |
| 66 |
public const MAX_FILE_SIZE = 1048576; |
| 67 |
|
| 68 |
/** |
| 69 |
* Longest free-text value stored on a single entry, in characters. |
| 70 |
* |
| 71 |
* @since 2.12.6 |
| 72 |
*/ |
| 73 |
public const MAX_TEXT_LENGTH = 500; |
| 74 |
|
| 75 |
/** |
| 76 |
* Longest single field key stored on an entry, in characters. |
| 77 |
* |
| 78 |
* @since 2.12.6 |
| 79 |
*/ |
| 80 |
public const MAX_KEY_LENGTH = 100; |
| 81 |
|
| 82 |
/** |
| 83 |
* Option holding per-category failure state, keyed by category. |
| 84 |
* |
| 85 |
* Shape: [ category => [ 'count' => int, 'form_id' => int, 'form_title' => string, |
| 86 |
* 'at' => int, 'acked' => int, 'acked_at' => int ] ]. |
| 87 |
* |
| 88 |
* Kept per category because the three read completely differently to a site |
| 89 |
* owner: submissions failing means visitors cannot reach you, a notification |
| 90 |
* failing means you are not hearing about entries that did save, and an |
| 91 |
* integration failing means a third party is not receiving them. Collapsing |
| 92 |
* them into one warning would describe none of those accurately. |
| 93 |
* |
| 94 |
* @since 2.12.6 |
| 95 |
*/ |
| 96 |
public const FAILURES_OPTION = 'srfm_client_log_failures'; |
| 97 |
|
| 98 |
/** |
| 99 |
* Categories a failure can belong to. |
| 100 |
* |
| 101 |
* @since 2.12.6 |
| 102 |
*/ |
| 103 |
public const CATEGORIES = [ 'submission', 'notification', 'integration' ]; |
| 104 |
|
| 105 |
/** |
| 106 |
* Memoised get_tail() results for this request, keyed by character budget. |
| 107 |
* |
| 108 |
* A class property rather than a static inside the method so append() and |
| 109 |
* clear() can invalidate it: a request that writes to the log and then reads a |
| 110 |
* tail must not be handed the tail from before the write. |
| 111 |
* |
| 112 |
* @var array<string,array{text:string,shown:int,total:int}> |
| 113 |
* @since 2.12.7 |
| 114 |
*/ |
| 115 |
private static $tail_memo = []; |
| 116 |
|
| 117 |
/** |
| 118 |
* Whether client error logging is currently switched on. |
| 119 |
* |
| 120 |
* On by default, including on installs whose stored settings predate the |
| 121 |
* option. The point of the log is that the evidence already exists when a |
| 122 |
* support ticket arrives -- a default of off would mean asking the reporter to |
| 123 |
* enable it and reproduce, which is the round trip this feature removes. |
| 124 |
* |
| 125 |
* Costs nothing on a healthy site: only failures are ever written, so a site |
| 126 |
* whose forms work never creates the file at all. |
| 127 |
* |
| 128 |
* This is the one authority. The frontend also carries a flag, but that flag is |
| 129 |
* baked into cached HTML and can be a full cache TTL out of date, so every |
| 130 |
* write path re-checks here. |
| 131 |
* |
| 132 |
* @since 2.12.6 |
| 133 |
* @return bool |
| 134 |
*/ |
| 135 |
public static function is_enabled() { |
| 136 |
$general = get_option( 'srfm_general_settings_options', [] ); |
| 137 |
|
| 138 |
if ( ! is_array( $general ) || ! isset( $general['srfm_enable_logs'] ) ) { |
| 139 |
return true; |
| 140 |
} |
| 141 |
|
| 142 |
return (bool) $general['srfm_enable_logs']; |
| 143 |
} |
| 144 |
|
| 145 |
/** |
| 146 |
* Whether an entry means the site is broken, rather than the visitor. |
| 147 |
* |
| 148 |
* This distinction is the whole basis of the failure notice. Most of what the |
| 149 |
* log records is routine: a mistyped email, an expired captcha, a declined |
| 150 |
* card, a submission the server rejected by naming the field to fix. Those are |
| 151 |
* the form working correctly, and counting them would tell healthy sites to |
| 152 |
* contact support -- on every install, because logging is on by default. |
| 153 |
* |
| 154 |
* A fault is what a visitor cannot resolve by trying again correctly: the |
| 155 |
* request never reached PHP, the response was not JSON, the server returned an |
| 156 |
* error status, or a notification email could not be sent. |
| 157 |
* |
| 158 |
* @param array<string,mixed> $entry Entry as returned by sanitize_entry(). |
| 159 |
* @since 2.12.6 |
| 160 |
* @return bool |
| 161 |
*/ |
| 162 |
public static function is_fault( array $entry ) { |
| 163 |
$type = $entry['type'] ?? ''; |
| 164 |
|
| 165 |
// Allowlist, so an unrecognised or new category is not a fault by default. |
| 166 |
// 'blocked' is deliberately absent: it is the label the browser puts on a |
| 167 |
// stop the visitor can clear themselves. |
| 168 |
if ( in_array( $type, [ 'error', 'response', 'message' ], true ) ) { |
| 169 |
return true; |
| 170 |
} |
| 171 |
|
| 172 |
// 'after_submission' runs after the entry is already saved, so it is only a |
| 173 |
// fault when the server said so. A browser-side failure there -- an aborted |
| 174 |
// fetch as the page unloads, which is what a redirect confirmation does and |
| 175 |
// what `keepalive` exists to survive -- tells us nothing about whether the |
| 176 |
// work ran: the endpoint is guarded by is_after_submission_process_triggered |
| 177 |
// and usually has. Safari spells that abort "TypeError: Load failed", and |
| 178 |
// alarming on it reported healthy sites as broken. |
| 179 |
if ( ! in_array( $type, [ 'network', 'after_submission' ], true ) ) { |
| 180 |
return false; |
| 181 |
} |
| 182 |
|
| 183 |
$status = isset( $entry['status'] ) ? Helper::get_integer_value( $entry['status'] ) : 0; |
| 184 |
|
| 185 |
// 403 is the submit token being refused, which on a cached site means the |
| 186 |
// page is serving a token the server will not accept. |
| 187 |
return $status >= 500 || 403 === $status; |
| 188 |
} |
| 189 |
|
| 190 |
/** |
| 191 |
* Record a failure against a category and the form it happened on. |
| 192 |
* |
| 193 |
* The form is carried because "a form is failing" is not actionable on a site |
| 194 |
* with twenty of them -- the first thing anyone asks is which one. |
| 195 |
* |
| 196 |
* @param string $category One of self::CATEGORIES. |
| 197 |
* @param int $form_id Form the failure happened on. |
| 198 |
* @param string $form_title Form title, resolved by the caller. |
| 199 |
* @since 2.12.6 |
| 200 |
* @return void |
| 201 |
*/ |
| 202 |
public static function record_failure( $category, $form_id = 0, $form_title = '' ) { |
| 203 |
// Logging off means nothing is recorded, not merely nothing displayed. |
| 204 |
// |
| 205 |
// The display side was already gated -- get_action_items() skips the |
| 206 |
// first-party items and has_action_item_warnings() returns false -- but the |
| 207 |
// counter kept being written, from the two call sites in form-submit.php |
| 208 |
// that sit beside an append() the enabled check does stop. So a site with |
| 209 |
// logging switched off still accumulated failure state, and switching |
| 210 |
// logging on surfaced every fault recorded while it was off, behind a View |
| 211 |
// details report whose debug log is empty because nothing was written. |
| 212 |
// |
| 213 |
// Gated here rather than at the call sites, for the reason append() states: |
| 214 |
// the guard belongs on the function that writes, not on today's callers. |
| 215 |
// clear_category() and the acknowledge helpers are deliberately left |
| 216 |
// ungated -- they only remove state, and must keep working so nothing is |
| 217 |
// stranded by the toggle. |
| 218 |
if ( ! self::is_enabled() ) { |
| 219 |
return; |
| 220 |
} |
| 221 |
|
| 222 |
if ( ! in_array( $category, self::CATEGORIES, true ) ) { |
| 223 |
return; |
| 224 |
} |
| 225 |
|
| 226 |
$failures = self::get_failures(); |
| 227 |
$existing = $failures[ $category ] ?? []; |
| 228 |
|
| 229 |
$failures[ $category ] = [ |
| 230 |
'count' => Helper::get_integer_value( $existing['count'] ?? 0 ) + 1, |
| 231 |
'form_id' => absint( $form_id ), |
| 232 |
'form_title' => mb_substr( sanitize_text_field( $form_title ), 0, 100 ), |
| 233 |
'at' => time(), |
| 234 |
// Preserved: a report already made still stands until this new count |
| 235 |
// overtakes it, which is what get_open_failures() compares. |
| 236 |
'acked' => Helper::get_integer_value( $existing['acked'] ?? 0 ), |
| 237 |
// Carried forward too. This array is rebuilt from a fixed set of keys, so |
| 238 |
// anything not named here is dropped -- and "when did I last report |
| 239 |
// this" quietly disappearing on the next failure is exactly the kind of |
| 240 |
// loss nobody notices until support asks. |
| 241 |
'acked_at' => Helper::get_integer_value( $existing['acked_at'] ?? 0 ), |
| 242 |
]; |
| 243 |
|
| 244 |
update_option( self::FAILURES_OPTION, $failures, false ); |
| 245 |
} |
| 246 |
|
| 247 |
/** |
| 248 |
* All recorded failure state. |
| 249 |
* |
| 250 |
* @since 2.12.6 |
| 251 |
* @return array<string,array<string,mixed>> |
| 252 |
*/ |
| 253 |
public static function get_failures() { |
| 254 |
return Helper::get_array_value( get_option( self::FAILURES_OPTION, [] ) ); |
| 255 |
} |
| 256 |
|
| 257 |
/** |
| 258 |
* Categories with failures the site owner has not already reported. |
| 259 |
* |
| 260 |
* @since 2.12.6 |
| 261 |
* @return array<string,array<string,mixed>> |
| 262 |
*/ |
| 263 |
public static function get_open_failures() { |
| 264 |
$open = []; |
| 265 |
|
| 266 |
foreach ( self::get_failures() as $category => $failure ) { |
| 267 |
if ( ! in_array( $category, self::CATEGORIES, true ) ) { |
| 268 |
continue; |
| 269 |
} |
| 270 |
|
| 271 |
$count = Helper::get_integer_value( $failure['count'] ?? 0 ); |
| 272 |
|
| 273 |
// Compared on the count, not the clock: both are written to the second, |
| 274 |
// so a failure landing in the same second as the report would look |
| 275 |
// not-newer and be hidden. |
| 276 |
if ( $count > 0 && $count > Helper::get_integer_value( $failure['acked'] ?? 0 ) ) { |
| 277 |
$open[ $category ] = $failure; |
| 278 |
} |
| 279 |
} |
| 280 |
|
| 281 |
return $open; |
| 282 |
} |
| 283 |
|
| 284 |
/** |
| 285 |
* Mark one category as reported. |
| 286 |
* |
| 287 |
* @param string $category One of self::CATEGORIES. |
| 288 |
* @since 2.12.6 |
| 289 |
* @return void |
| 290 |
*/ |
| 291 |
public static function acknowledge_category( $category ) { |
| 292 |
$failures = self::get_failures(); |
| 293 |
|
| 294 |
if ( ! isset( $failures[ $category ] ) ) { |
| 295 |
return; |
| 296 |
} |
| 297 |
|
| 298 |
$failures[ $category ]['acked'] = Helper::get_integer_value( $failures[ $category ]['count'] ?? 0 ); |
| 299 |
|
| 300 |
// Recorded for the report -- "you told us at 14:12" is worth having when |
| 301 |
// support reads the ticket -- but deliberately not what decides whether the |
| 302 |
// notice comes back. The count does that. |
| 303 |
// |
| 304 |
// A timestamp cannot: it is written to the second, so a failure recorded in |
| 305 |
// the same second as the acknowledgement compares equal and gets swallowed. |
| 306 |
// That is the one moment it matters most, because a fault arriving as |
| 307 |
// someone reports the last one is a fault still happening. |
| 308 |
$failures[ $category ]['acked_at'] = time(); |
| 309 |
|
| 310 |
update_option( self::FAILURES_OPTION, $failures, false ); |
| 311 |
} |
| 312 |
|
| 313 |
/** |
| 314 |
* Forget one category's failures entirely. |
| 315 |
* |
| 316 |
* @param string $category One of self::CATEGORIES. |
| 317 |
* @since 2.12.6 |
| 318 |
* @return void |
| 319 |
*/ |
| 320 |
public static function clear_category( $category ) { |
| 321 |
$failures = self::get_failures(); |
| 322 |
|
| 323 |
if ( ! isset( $failures[ $category ] ) ) { |
| 324 |
return; |
| 325 |
} |
| 326 |
|
| 327 |
unset( $failures[ $category ] ); |
| 328 |
|
| 329 |
update_option( self::FAILURES_OPTION, $failures, false ); |
| 330 |
} |
| 331 |
|
| 332 |
/** |
| 333 |
* How many submission faults have been recorded. |
| 334 |
* |
| 335 |
* @since 2.12.6 |
| 336 |
* @return int |
| 337 |
*/ |
| 338 |
public static function get_fault_streak() { |
| 339 |
$failures = self::get_failures(); |
| 340 |
|
| 341 |
return Helper::get_integer_value( $failures['submission']['count'] ?? 0 ); |
| 342 |
} |
| 343 |
|
| 344 |
/** |
| 345 |
* Whether submissions are failing and it has not already been reported. |
| 346 |
* |
| 347 |
* @since 2.12.6 |
| 348 |
* @return bool |
| 349 |
*/ |
| 350 |
public static function has_persistent_failures() { |
| 351 |
return self::get_fault_streak() >= self::FAULT_THRESHOLD |
| 352 |
&& isset( self::get_open_failures()['submission'] ); |
| 353 |
} |
| 354 |
|
| 355 |
/** |
| 356 |
* The recorded acknowledgement for submission failures, if there is one. |
| 357 |
* |
| 358 |
* @since 2.12.6 |
| 359 |
* @return array<string,mixed> Empty when nothing has been acknowledged. |
| 360 |
*/ |
| 361 |
public static function get_acknowledgement() { |
| 362 |
$failures = self::get_failures(); |
| 363 |
$acked = Helper::get_integer_value( $failures['submission']['acked'] ?? 0 ); |
| 364 |
|
| 365 |
if ( $acked < 1 ) { |
| 366 |
return []; |
| 367 |
} |
| 368 |
|
| 369 |
return [ |
| 370 |
// The last fault time, not the acknowledgement time. Kept under this |
| 371 |
// key because callers already read it as "when the thing happened". |
| 372 |
'at' => Helper::get_integer_value( $failures['submission']['at'] ?? 0 ), |
| 373 |
// When the owner reported it. Separate, because the two answer |
| 374 |
// different questions and are usually seconds apart on a fresh fault |
| 375 |
// and days apart on an old one. |
| 376 |
'acked_at' => Helper::get_integer_value( $failures['submission']['acked_at'] ?? 0 ), |
| 377 |
'streak' => $acked, |
| 378 |
]; |
| 379 |
} |
| 380 |
|
| 381 |
/** |
| 382 |
* When the most recent submission fault happened. |
| 383 |
* |
| 384 |
* @since 2.12.6 |
| 385 |
* @return int Unix timestamp, or 0 when nothing has failed. |
| 386 |
*/ |
| 387 |
public static function get_last_fault_time() { |
| 388 |
$failures = self::get_failures(); |
| 389 |
|
| 390 |
return Helper::get_integer_value( $failures['submission']['at'] ?? 0 ); |
| 391 |
} |
| 392 |
|
| 393 |
/** |
| 394 |
* Record that the site owner has reported the current submission failures. |
| 395 |
* |
| 396 |
* @since 2.12.6 |
| 397 |
* @return void |
| 398 |
*/ |
| 399 |
public static function acknowledge_failures() { |
| 400 |
self::acknowledge_category( 'submission' ); |
| 401 |
} |
| 402 |
|
| 403 |
/** |
| 404 |
* Forget the submission failures after one gets through. |
| 405 |
* |
| 406 |
* Hooked - srfm_form_submit, which fires only on the success path. |
| 407 |
* |
| 408 |
* Only the submission category is cleared. A submission getting through says |
| 409 |
* nothing about whether its notification email sent or its integrations ran. |
| 410 |
* Notification clears on its own path, in Form_Submit::send_email(), once every |
| 411 |
* recipient for a submission has sent. Integration has no success signal to |
| 412 |
* clear on yet -- the failures are recorded by pro through |
| 413 |
* Form_Submit::log_integration_failure() and there is no matching |
| 414 |
* "it worked" call -- so that category still clears only when the owner |
| 415 |
* reports it. |
| 416 |
* |
| 417 |
* @since 2.12.6 |
| 418 |
* @return void |
| 419 |
*/ |
| 420 |
public static function reset_fault_streak() { |
| 421 |
self::clear_category( 'submission' ); |
| 422 |
} |
| 423 |
|
| 424 |
/** |
| 425 |
* Absolute path to the log file, creating its directory if needed. |
| 426 |
* |
| 427 |
* @param bool $create Whether to create the directory when it is absent. |
| 428 |
* @since 2.12.6 |
| 429 |
* @return string Absolute path, or '' when the location is unusable. |
| 430 |
*/ |
| 431 |
public static function get_log_path( $create = true ) { |
| 432 |
$uploads = wp_upload_dir(); |
| 433 |
|
| 434 |
if ( ! empty( $uploads['error'] ) || empty( $uploads['basedir'] ) ) { |
| 435 |
return ''; |
| 436 |
} |
| 437 |
|
| 438 |
$dir = trailingslashit( $uploads['basedir'] ) . 'sureforms/logs/'; |
| 439 |
|
| 440 |
if ( ! is_dir( $dir ) ) { |
| 441 |
if ( ! $create || ! wp_mkdir_p( $dir ) ) { |
| 442 |
return ''; |
| 443 |
} |
| 444 |
|
| 445 |
self::protect_directory( $dir ); |
| 446 |
} |
| 447 |
|
| 448 |
return $dir . 'srfm-debug-' . self::get_filename_hash() . '.log'; |
| 449 |
} |
| 450 |
|
| 451 |
/** |
| 452 |
* Append one validated entry to the log. |
| 453 |
* |
| 454 |
* @param array<string,mixed> $entry Entry as returned by sanitize_entry(). |
| 455 |
* @since 2.12.6 |
| 456 |
* @return bool True when the line was written. |
| 457 |
*/ |
| 458 |
public static function append( array $entry ) { |
| 459 |
// Any write invalidates a memoised tail, whether or not this one lands. |
| 460 |
self::$tail_memo = []; |
| 461 |
|
| 462 |
// Checked here as well as at the route, so the guard sits on the function |
| 463 |
// that writes rather than only on today's single caller. Without it any |
| 464 |
// future caller writes to disk on a site that never switched logging on. |
| 465 |
if ( ! self::is_enabled() ) { |
| 466 |
return false; |
| 467 |
} |
| 468 |
|
| 469 |
if ( empty( $entry ) ) { |
| 470 |
return false; |
| 471 |
} |
| 472 |
|
| 473 |
// Counted before the file is touched. A full log or an unwritable uploads |
| 474 |
// directory must not stop the site owner being told the form is failing -- |
| 475 |
// on a badly broken site those are exactly the conditions that occur. |
| 476 |
// A notification or integration failure records its own category at the call |
| 477 |
// site; everything else reaching here is the submission itself. |
| 478 |
$type = Helper::get_string_value( $entry['type'] ?? '' ); |
| 479 |
|
| 480 |
if ( self::is_fault( $entry ) && 'message' !== $type ) { |
| 481 |
// The after-submission step runs on an entry that is already saved and |
| 482 |
// fires srfm_after_submission_process, which is where integrations and |
| 483 |
// webhooks hook in. Calling that a submission failure told the site owner |
| 484 |
// "their entries were not saved" about entries that were -- the wrong |
| 485 |
// message on the one notice that cannot be dismissed. The category is |
| 486 |
// derived here rather than taken from the entry: the client names what |
| 487 |
// happened, the server decides what it means. |
| 488 |
self::record_failure( |
| 489 |
'after_submission' === $type ? 'integration' : 'submission', |
| 490 |
Helper::get_integer_value( $entry['form_id'] ?? 0 ), |
| 491 |
Helper::get_string_value( $entry['form_title'] ?? '' ) |
| 492 |
); |
| 493 |
} |
| 494 |
|
| 495 |
$path = self::get_log_path(); |
| 496 |
|
| 497 |
if ( '' === $path ) { |
| 498 |
return false; |
| 499 |
} |
| 500 |
|
| 501 |
// Cap and stop. Deliberately not a trim or a rotate: the person who |
| 502 |
// reproduced the bug is the one whose lines would be discarded. |
| 503 |
if ( self::is_full() ) { |
| 504 |
return false; |
| 505 |
} |
| 506 |
|
| 507 |
$entry['time'] = gmdate( 'Y-m-d H:i:s' ); |
| 508 |
|
| 509 |
$line = wp_json_encode( $entry ); |
| 510 |
|
| 511 |
if ( ! is_string( $line ) ) { |
| 512 |
return false; |
| 513 |
} |
| 514 |
|
| 515 |
// phpcs:ignore WordPress.WP.AlternativeFunctions.file_system_read_file_put_contents -- WP_Filesystem can prompt for credentials and is not initialised on a public REST request; this mirrors the raw-handle pattern already used in inc/entries.php. LOCK_EX is insurance for NFS/Windows -- appends of this size are already atomic on POSIX. |
| 516 |
return false !== file_put_contents( $path, $line . "\n", FILE_APPEND | LOCK_EX ); |
| 517 |
} |
| 518 |
|
| 519 |
/** |
| 520 |
* The most recent whole log lines, up to a character budget. |
| 521 |
* |
| 522 |
* An excerpt for reading and pasting. The budget is the caller's: the details |
| 523 |
* dialog shows it on screen and copies it to a clipboard, neither of which has |
| 524 |
* a length limit worth designing around, while an excerpt embedded anywhere |
| 525 |
* length-bound needs a smaller one. Newest entries are the ones that describe |
| 526 |
* the failure being reported, so the tail is the useful end and the oldest are |
| 527 |
* what a smaller budget drops. |
| 528 |
* |
| 529 |
* Whole lines only -- half a JSON object helps nobody. |
| 530 |
* |
| 531 |
* @param int $max_chars Character budget for the returned text. |
| 532 |
* @since 2.12.6 |
| 533 |
* @return array{text:string,shown:int,total:int} |
| 534 |
*/ |
| 535 |
public static function get_tail( $max_chars = 1200 ) { |
| 536 |
// Memoised per request and per budget. get_action_items() asks once per |
| 537 |
// open failure category and runs twice per admin request -- building the |
| 538 |
// localisation payload and again in the classic renderer -- so a site with |
| 539 |
// three open failures was reading a file capped at 1 MB six times to render |
| 540 |
// one page. |
| 541 |
$max_chars = (int) $max_chars; |
| 542 |
|
| 543 |
// Keyed by blog as well as budget: get_log_path() hashes the blog id into |
| 544 |
// the filename, so after a switch_to_blog() the same budget is a different |
| 545 |
// file. Unreachable today; nothing switches blogs on this path. |
| 546 |
// |
| 547 |
// Its own variable, not $max_chars reused -- that key is a string, and the |
| 548 |
// byte-budget comparison below coerces "1:1200" to 1, which silently |
| 549 |
// reduces every excerpt to a single line. |
| 550 |
$memo_key = get_current_blog_id() . ':' . $max_chars; |
| 551 |
|
| 552 |
if ( isset( self::$tail_memo[ $memo_key ] ) ) { |
| 553 |
return self::$tail_memo[ $memo_key ]; |
| 554 |
} |
| 555 |
|
| 556 |
$empty = [ |
| 557 |
'text' => '', |
| 558 |
'shown' => 0, |
| 559 |
'total' => 0, |
| 560 |
]; |
| 561 |
|
| 562 |
$path = self::get_log_path( false ); |
| 563 |
|
| 564 |
if ( '' === $path || ! file_exists( $path ) ) { |
| 565 |
self::$tail_memo[ $memo_key ] = $empty; |
| 566 |
|
| 567 |
return $empty; |
| 568 |
} |
| 569 |
|
| 570 |
// phpcs:ignore WordPress.WP.AlternativeFunctions.file_system_operations_file, WordPress.WP.AlternativeFunctions.file_system_read_file -- Reading a file this class owns; WP_Filesystem would prompt for credentials and is unavailable here. |
| 571 |
$lines = file( $path, FILE_IGNORE_NEW_LINES | FILE_SKIP_EMPTY_LINES ); |
| 572 |
|
| 573 |
if ( ! is_array( $lines ) || empty( $lines ) ) { |
| 574 |
self::$tail_memo[ $memo_key ] = $empty; |
| 575 |
|
| 576 |
return $empty; |
| 577 |
} |
| 578 |
|
| 579 |
$total = count( $lines ); |
| 580 |
$kept = []; |
| 581 |
$used = 0; |
| 582 |
|
| 583 |
foreach ( array_reverse( $lines ) as $line ) { |
| 584 |
$length = strlen( $line ) + 1; |
| 585 |
|
| 586 |
// Always keep one line, even if it alone exceeds the budget: an empty |
| 587 |
// excerpt is worse than a long one. |
| 588 |
if ( $used + $length > $max_chars && ! empty( $kept ) ) { |
| 589 |
break; |
| 590 |
} |
| 591 |
|
| 592 |
array_unshift( $kept, $line ); |
| 593 |
$used += $length; |
| 594 |
} |
| 595 |
|
| 596 |
self::$tail_memo[ $memo_key ] = [ |
| 597 |
'text' => implode( "\n", $kept ), |
| 598 |
'shown' => count( $kept ), |
| 599 |
'total' => $total, |
| 600 |
]; |
| 601 |
|
| 602 |
return self::$tail_memo[ $memo_key ]; |
| 603 |
} |
| 604 |
|
| 605 |
/** |
| 606 |
* Whether the log has reached its size cap. |
| 607 |
* |
| 608 |
* @since 2.12.6 |
| 609 |
* @return bool |
| 610 |
*/ |
| 611 |
public static function is_full() { |
| 612 |
return self::get_file_size() >= self::MAX_FILE_SIZE; |
| 613 |
} |
| 614 |
|
| 615 |
/** |
| 616 |
* Current size of the log file in bytes. |
| 617 |
* |
| 618 |
* @since 2.12.6 |
| 619 |
* @return int |
| 620 |
*/ |
| 621 |
public static function get_file_size() { |
| 622 |
$path = self::get_log_path( false ); |
| 623 |
|
| 624 |
if ( '' === $path || ! file_exists( $path ) ) { |
| 625 |
return 0; |
| 626 |
} |
| 627 |
|
| 628 |
$size = filesize( $path ); |
| 629 |
|
| 630 |
return is_int( $size ) ? $size : 0; |
| 631 |
} |
| 632 |
|
| 633 |
/** |
| 634 |
* Delete the log file. |
| 635 |
* |
| 636 |
* @since 2.12.6 |
| 637 |
* @return bool |
| 638 |
*/ |
| 639 |
public static function clear() { |
| 640 |
self::$tail_memo = []; |
| 641 |
|
| 642 |
$path = self::get_log_path( false ); |
| 643 |
|
| 644 |
if ( '' === $path || ! file_exists( $path ) ) { |
| 645 |
return true; |
| 646 |
} |
| 647 |
|
| 648 |
return wp_delete_file_from_directory( $path, dirname( $path ) ); |
| 649 |
} |
| 650 |
|
| 651 |
/** |
| 652 |
* Reduce a caller-supplied payload to the fixed shape the log accepts. |
| 653 |
* |
| 654 |
* The endpoint never appends caller text directly. Redaction governs values; |
| 655 |
* this governs shape. Without it, "we redact the field values" would still |
| 656 |
* leave an anonymous caller writing arbitrary content into a file an |
| 657 |
* administrator later opens. |
| 658 |
* |
| 659 |
* @param array<string,mixed> $raw Decoded request payload. |
| 660 |
* @since 2.12.6 |
| 661 |
* @return array<string,mixed> Empty when nothing usable survived. |
| 662 |
*/ |
| 663 |
public static function sanitize_entry( array $raw ) { |
| 664 |
$allowed_types = [ 'network', 'response', 'error', 'message', 'blocked', 'after_submission' ]; |
| 665 |
$type = isset( $raw['type'] ) ? sanitize_key( Helper::get_string_value( $raw['type'] ) ) : ''; |
| 666 |
|
| 667 |
if ( ! in_array( $type, $allowed_types, true ) ) { |
| 668 |
return []; |
| 669 |
} |
| 670 |
|
| 671 |
$entry = [ |
| 672 |
'type' => $type, |
| 673 |
'form_id' => isset( $raw['form_id'] ) ? absint( Helper::get_integer_value( $raw['form_id'] ) ) : 0, |
| 674 |
]; |
| 675 |
|
| 676 |
foreach ( [ 'message', 'source', 'body', 'form_title' ] as $key ) { |
| 677 |
if ( ! isset( $raw[ $key ] ) ) { |
| 678 |
continue; |
| 679 |
} |
| 680 |
|
| 681 |
$text = self::scrub_text( Helper::get_string_value( $raw[ $key ] ) ); |
| 682 |
|
| 683 |
if ( '' !== $text ) { |
| 684 |
$entry[ $key ] = $text; |
| 685 |
} |
| 686 |
} |
| 687 |
|
| 688 |
foreach ( [ 'status', 'duration_ms', 'line' ] as $key ) { |
| 689 |
if ( isset( $raw[ $key ] ) ) { |
| 690 |
$entry[ $key ] = absint( Helper::get_integer_value( $raw[ $key ] ) ); |
| 691 |
} |
| 692 |
} |
| 693 |
|
| 694 |
if ( isset( $raw['field_keys'] ) && is_array( $raw['field_keys'] ) ) { |
| 695 |
$keys = []; |
| 696 |
|
| 697 |
// Both the count and each key's length. Capping only the count left one |
| 698 |
// request able to write ~1MB of field keys and fill the log in a single |
| 699 |
// call -- and because the log stops rather than evicting, that silently |
| 700 |
// disabled the feature until an admin cleared it. A real key is |
| 701 |
// `srfm-input-lbl-<base64>`, far inside this bound. |
| 702 |
foreach ( array_slice( $raw['field_keys'], 0, 100 ) as $field_key ) { |
| 703 |
// Through scrub_text() like every other free-text value. A key is |
| 704 |
// supposed to be `srfm-input-lbl-<base64>`, but the array arrives |
| 705 |
// from the browser and nothing server-side guarantees that, so a |
| 706 |
// caller is free to put an address or a token in one. |
| 707 |
// |
| 708 |
// wp_check_invalid_utf8() is kept because scrub_text() is not a |
| 709 |
// drop-in for sanitize_text_field(): invalid UTF-8 reaching |
| 710 |
// wp_json_encode() in append() makes it return false and drop the |
| 711 |
// whole line -- after record_failure() has already incremented the |
| 712 |
// counter, leaving a banner with no log line behind it. |
| 713 |
$keys[] = mb_substr( |
| 714 |
self::scrub_text( wp_check_invalid_utf8( Helper::get_string_value( $field_key ) ) ), |
| 715 |
0, |
| 716 |
self::MAX_KEY_LENGTH |
| 717 |
); |
| 718 |
} |
| 719 |
|
| 720 |
$entry['field_keys'] = $keys; |
| 721 |
} |
| 722 |
|
| 723 |
// A type alone says nothing. Require at least one substantive value. |
| 724 |
$has_detail = isset( $entry['message'] ) || isset( $entry['body'] ) || isset( $entry['status'] ); |
| 725 |
|
| 726 |
return $has_detail ? $entry : []; |
| 727 |
} |
| 728 |
|
| 729 |
/** |
| 730 |
* Strip identifying detail out of free text and clamp its length. |
| 731 |
* |
| 732 |
* Redacting submitted field values is not sufficient on its own: error text |
| 733 |
* interpolates user input constantly ("Invalid email: someone@example.com"), |
| 734 |
* and a page URL routinely carries an address or a reset key in its query |
| 735 |
* string. Whitespace is collapsed as a log-injection guard, matching |
| 736 |
* inc/ai-form-builder/ai-helper.php. |
| 737 |
* |
| 738 |
* Removes, in order: JSON slash-escaping, so the rules below can see URLs at |
| 739 |
* all; credentials in a URL's userinfo; query strings and fragments; a foreign |
| 740 |
* URL's path past its first segment, keeping same-origin paths intact because |
| 741 |
* those are stack frames and the path is the diagnosis; the value following a |
| 742 |
* name that identifies a credential; email addresses; and long digit runs. |
| 743 |
* |
| 744 |
* A single-segment foreign path is truncated whole rather than kept, which is |
| 745 |
* the safe direction. |
| 746 |
* |
| 747 |
* What it cannot remove is a name, a street address or a free-text message |
| 748 |
* body -- those have no shape to match, so the log excerpt this produces |
| 749 |
* should still be treated as personal data. |
| 750 |
* |
| 751 |
* @param string $text Raw text. |
| 752 |
* @since 2.12.6 |
| 753 |
* @return string |
| 754 |
*/ |
| 755 |
public static function scrub_text( $text ) { |
| 756 |
if ( '' === $text ) { |
| 757 |
return ''; |
| 758 |
} |
| 759 |
|
| 760 |
// Clamped before the rules run, not after. Without it every pattern below |
| 761 |
// is applied to whatever the caller sent, however long that is. |
| 762 |
$text = mb_substr( $text, 0, self::MAX_TEXT_LENGTH * 4 ); |
| 763 |
|
| 764 |
// A WP REST error body arrives slash-escaped -- wp_json_encode() escapes |
| 765 |
// "/" and WP_REST_Server::serve_request() does not pass |
| 766 |
// JSON_UNESCAPED_SLASHES -- and two of the four body sinks log the raw |
| 767 |
// response text rather than the decoded object. Without this every URL |
| 768 |
// rule below misses every URL in the largest sink, including the webhook |
| 769 |
// tokens they exist for. |
| 770 |
$text = str_replace( '\\/', '/', $text ); |
| 771 |
|
| 772 |
// Credentials in the userinfo position, before the host rules see them. |
| 773 |
$text = (string) preg_replace( '#(https?://)[^\s/@]+@#i', '$1[credentials]@', $text ); |
| 774 |
|
| 775 |
// Drop query strings and fragments wholesale rather than allowlisting |
| 776 |
// parameters. A token after # is just as sensitive as one after ?. |
| 777 |
$text = (string) preg_replace( '#(https?://[^\s?\#]+)[?\#][^\s"\'<>,;)\]}]*#i', '$1', $text ); |
| 778 |
|
| 779 |
$site_host = Helper::get_string_value( wp_parse_url( home_url(), PHP_URL_HOST ) ); |
| 780 |
|
| 781 |
// Keep the origin and the first path segment of a foreign URL, drop the |
| 782 |
// rest: a webhook credential sits in the path as often as in the query, |
| 783 |
// and Slack and Discord both put theirs there. |
| 784 |
// |
| 785 |
// Same-origin URLs are exempt. `source` is a stack frame, not a page |
| 786 |
// address -- assets/js/unminified/form-submit.js takes |
| 787 |
// error.stack.split( "\n" )[1] -- so truncating our own paths deletes the |
| 788 |
// filename, the line and column, and which plugin threw, which is the |
| 789 |
// whole diagnosis. A third-party credential is never same-origin. |
| 790 |
// |
| 791 |
// The port is stripped before comparing. The pattern captures the whole |
| 792 |
// authority, so a site served on a non-default port produced frames reading |
| 793 |
// `example.test:8443`, while $site_host is PHP_URL_HOST and never carries a |
| 794 |
// port -- every own frame failed the check and was truncated to /[path], |
| 795 |
// which is the case this exemption exists for. Same host, different port is |
| 796 |
// treated as ours: on a WordPress install that is the same site behind a dev |
| 797 |
// server or a proxy, and the alternative is deleting the diagnosis. |
| 798 |
$text = (string) preg_replace_callback( |
| 799 |
'#(https?://)([^\s/]+)((?:/[^\s/]*)?)/[^\s"\'<>,;)\]}]+#i', |
| 800 |
static function ( $matches ) use ( $site_host ) { |
| 801 |
// Trailing :digits only, so an IPv6 literal keeps its brackets and |
| 802 |
// its own colons -- [::1]:8080 becomes [::1], which is the form |
| 803 |
// wp_parse_url() returns for one. |
| 804 |
$host = (string) preg_replace( '/:\d+$/', '', $matches[2] ); |
| 805 |
|
| 806 |
if ( '' !== $site_host && 0 === strcasecmp( $host, $site_host ) ) { |
| 807 |
return $matches[0]; |
| 808 |
} |
| 809 |
|
| 810 |
return $matches[1] . $matches[2] . $matches[3] . '/[path]'; |
| 811 |
}, |
| 812 |
$text |
| 813 |
); |
| 814 |
|
| 815 |
// Credentials named in the text itself. The name is matched as a whole |
| 816 |
// identifier, so a keyword with a prefix or suffix is still caught -- |
| 817 |
// AWS_SECRET_ACCESS_KEY, stripe_secret_key, X-Hub-Signature. And a |
| 818 |
// separator is required, so ordinary prose survives: "Invalid token |
| 819 |
// provided" and "password protected" are the most common things support |
| 820 |
// reads out of this log, and an earlier version redacted both. `bearer` |
| 821 |
// and `basic` are the exception, because those carry the value after a |
| 822 |
// space with no separator at all. |
| 823 |
$text = (string) preg_replace( |
| 824 |
'/(\b[\w.-]*(?:api[_-]?key|key|secret|token|password|passwd|pwd|auth|credential|signature)[\w.-]*["\']?\s*[:=]\s*["\']?|\b(?:bearer|basic)\s+)[^\s"\',;&]{8,}/i', |
| 825 |
'$1[redacted]', |
| 826 |
$text |
| 827 |
); |
| 828 |
|
| 829 |
// Email addresses. |
| 830 |
$text = (string) preg_replace( '/[\w.+-]+@[\w-]+\.[\w.-]+/', '[email]', $text ); |
| 831 |
|
| 832 |
// Long digit runs: card numbers, phone numbers, ids. Separators are matched |
| 833 |
// too, because a real phone number is written 555-123-4567 or (555) 123-4567 |
| 834 |
// and a contiguous-digits rule never sees it. |
| 835 |
$text = (string) preg_replace( '/\+?\d[\d\s().-]{5,}\d/', '[number]', $text ); |
| 836 |
|
| 837 |
$text = (string) preg_replace( '/\s+/', ' ', $text ); |
| 838 |
|
| 839 |
return mb_substr( trim( wp_strip_all_tags( $text ) ), 0, self::MAX_TEXT_LENGTH ); |
| 840 |
} |
| 841 |
|
| 842 |
/** |
| 843 |
* Random component of the log file name, generated once and reused. |
| 844 |
* |
| 845 |
* The blog id is part of the input because wp_salt() is network-wide: a |
| 846 |
* salt-only hash would be identical on every site of a multisite network, and |
| 847 |
* older subdirectory installs can share one uploads directory. |
| 848 |
* |
| 849 |
* @since 2.12.6 |
| 850 |
* @return string |
| 851 |
*/ |
| 852 |
private static function get_filename_hash() { |
| 853 |
$hash = get_option( self::FILENAME_OPTION, '' ); |
| 854 |
|
| 855 |
if ( is_string( $hash ) && 32 === strlen( $hash ) && ctype_xdigit( $hash ) ) { |
| 856 |
return $hash; |
| 857 |
} |
| 858 |
|
| 859 |
$hash = hash_hmac( 'md5', 'srfm-client-log|' . get_current_blog_id(), wp_salt( 'auth' ) ); |
| 860 |
|
| 861 |
update_option( self::FILENAME_OPTION, $hash, false ); |
| 862 |
|
| 863 |
return $hash; |
| 864 |
} |
| 865 |
|
| 866 |
/** |
| 867 |
* Write the directory guards, best effort. |
| 868 |
* |
| 869 |
* An index.html rather than index.php: the nginx failure mode is `autoindex on` |
| 870 |
* producing a listing, and an index.html suppresses that. .htaccess covers |
| 871 |
* Apache and is inert on nginx, which is why the unguessable file name — not |
| 872 |
* these files — is what actually protects the log. |
| 873 |
* |
| 874 |
* @param string $dir Directory to guard. |
| 875 |
* @since 2.12.6 |
| 876 |
* @return void |
| 877 |
*/ |
| 878 |
private static function protect_directory( $dir ) { |
| 879 |
$guards = [ |
| 880 |
'.htaccess' => "# Apache 2.4\n<IfModule mod_authz_core.c>\nRequire all denied\n</IfModule>\n# Apache 2.2\n<IfModule !mod_authz_core.c>\nOrder deny,allow\nDeny from all\n</IfModule>\n", |
| 881 |
'index.html' => '', |
| 882 |
]; |
| 883 |
|
| 884 |
foreach ( $guards as $name => $contents ) { |
| 885 |
if ( file_exists( $dir . $name ) ) { |
| 886 |
continue; |
| 887 |
} |
| 888 |
|
| 889 |
// phpcs:ignore WordPress.WP.AlternativeFunctions.file_system_read_file_put_contents -- Best-effort directory guard written at creation time; WP_Filesystem may prompt for credentials and is unavailable on the public request that first creates this directory. |
| 890 |
file_put_contents( $dir . $name, $contents ); |
| 891 |
} |
| 892 |
} |
| 893 |
} |
| 894 |
|