Skip to content

Commit

Permalink
Merge branch 'assertions' into develop
Browse files Browse the repository at this point in the history
  • Loading branch information
johnbillion committed Nov 10, 2023
2 parents bdb9dab + 7f5c98c commit d40485e
Show file tree
Hide file tree
Showing 7 changed files with 216 additions and 80 deletions.
80 changes: 12 additions & 68 deletions README.md
Original file line number Diff line number Diff line change
Expand Up @@ -98,11 +98,7 @@ Currently this includes PHP errors and some overview information such as memory

The response from an authenticated WordPress REST API request will contain various debugging information in its headers, as long as the authenticated user has permission to view Query Monitor's output.

Currently this includes PHP errors and overview information.

To see more detailed information about a REST API request you need to perform [an enveloped request](https://developer.wordpress.org/rest-api/using-the-rest-api/global-parameters/#_envelope) which means appending `?_envelope` to the requested URL. In this case, Query Monitor will include debugging data in a `qm` property in the response. Currently this includes database queries (including information about duplicates and errors), HTTP API requests, and transient updates. More information may be added in a future version.

By using the combination of the HTTP headers and the `qm` property in the response to an enveloped request you'll get good insight into the aspects of a request which have the greatest impact on performance.
[Read more about debugging REST API requests with Query Monitor](https://querymonitor.com/wordpress-debugging/rest-api-requests/).

### Admin Screen

Expand All @@ -118,64 +114,30 @@ By using the combination of the HTTP headers and the `qm` property in the respon

### Logging

Debugging messages can be sent to the Logs panel in Query Monitor using actions. This works as a good replacement for `var_dump()`:
Debugging messages can be sent to the Logs panel using actions. This works as a good replacement for `var_dump()`:

```php
do_action( 'qm/debug', 'This happened!' );
```

The logger is PSR-3 compatible, so you can use any of the following actions which correspond to PSR-3 log levels:

* `qm/emergency`
* `qm/alert`
* `qm/critical`
* `qm/error`
* `qm/warning`
* `qm/notice`
* `qm/info`
* `qm/debug`
* `qm/info`
* `qm/notice`
* `qm/warning`
* `qm/error`
* `qm/critical`
* `qm/alert`
* `qm/emergency`

A log level of `warning` or higher will trigger a notification in Query Monitor's admin toolbar.

Contextual interpolation can be used via the curly brace syntax:

```php
do_action( 'qm/warning', 'Unexpected value of {foo} encountered', [
'foo' => $foo,
] );
```

A `WP_Error`, `Exception`, or `Throwable` object can be passed directly into the logger:

```php
if ( is_wp_error( $response ) ) {
do_action( 'qm/error', $response );
}
```

```php
try {
// your code
} catch ( Exception $e ) {
do_action( 'qm/error', $e );
}
```

A non-scalar value can be passed to the logger and its value will be formatted and output in the same panel.

```php
do_action( 'qm/debug', get_queried_object() );
```

Finally, the static logging methods on the `QM` class can be used instead of calling `do_action()`.

```php
QM::error( 'Everything is broken' );
```
[Read more about profiling and logging in Query Monitor](https://querymonitor.com/wordpress-debugging/profiling-and-logging/).

### Profiling

Basic performance profiling can be displayed in the Timings panel in Query Monitor using actions in your code:
Basic performance profiling can be displayed in the Timings panel using actions in your code:

```php
// Start the 'foo' timer:
Expand All @@ -188,25 +150,7 @@ my_potentially_slow_function();
do_action( 'qm/stop', 'foo' );
```

The time taken and approximate memory usage used between the `qm/start` and `qm/stop` actions for the given function name will be recorded and shown in the Timings panel. Timers can be nested, although be aware that this reduces the accuracy of the memory usage calculations.

Timers can also make use of laps with the `qm/lap` action:

```php
// Start the 'bar' timer:
do_action( 'qm/start', 'bar' );

// Iterate over some data:
foreach ( range( 1, 10 ) as $i ) {
my_potentially_slow_function( $i );
do_action( 'qm/lap', 'bar' );
}

// Stop the 'bar' timer:
do_action( 'qm/stop', 'bar' );
```

Note that the times and memory usage displayed in the Timings panel should be treated as approximations, because they are recorded at the PHP level and can be skewed by your environment and by other code. If you require highly accurate timings, you'll need to use a low level profiling tool such as XHProf. See the [Related Tools](#related-tools) section for more information.
[Read more about profiling and logging in Query Monitor](https://querymonitor.com/wordpress-debugging/profiling-and-logging/).

### Everything Else

Expand Down
19 changes: 19 additions & 0 deletions classes/QM.php
Original file line number Diff line number Diff line change
Expand Up @@ -143,6 +143,25 @@ public static function debug( $message, array $context = array() ) {
do_action( 'qm/debug', $message, $context );
}

/**
* @param mixed $assertion
* @param string $message
* @param ?mixed $value
* @return void
*/
public static function assert( $assertion, string $message = '', $value = null ) {
/**
* Fires when an assertion is performed.
*
* @since x.y.z
*
* @param mixed $assertion The assertion result, ideally something that evaluates to true.
* @param string $message The assertion message. May be an empty string.
* @param mixed $value Optional. A value to show along with the message when the assertion fails.
*/
do_action( 'qm/assert', $assertion, $message, $value );
}

/**
* @param string $level
* @param string $message
Expand Down
64 changes: 60 additions & 4 deletions collectors/logger.php
Original file line number Diff line number Diff line change
Expand Up @@ -42,6 +42,7 @@ public function set_up() {
add_action( "qm/{$level}", array( $this, $level ), 10, 2 );
}

add_action( 'qm/assert', array( $this, 'assert' ), 10, 3 );
add_action( 'qm/log', array( $this, 'log' ), 10, 3 );
}

Expand Down Expand Up @@ -138,6 +139,49 @@ public function debug( $message, array $context = array() ) {
$this->store( self::DEBUG, $message, $context );
}

/**
* @param mixed $assertion
* @param string $message
* @param ?mixed $value
* @return void
*/
public function assert( $assertion, string $message = '', $value = null ) {
$prefix = null;

if ( $assertion ) {
$level = self::DEBUG;

if ( $message ) {
$message = sprintf(
/* translators: %s: Assertion message */
__( 'Assertion passed: %s', 'query-monitor' ),
$message
);
} else {
$message = __( 'Assertion passed', 'query-monitor' );
}
} else {
$level = self::ERROR;

if ( $message ) {
$message = sprintf(
/* translators: %s: Assertion message */
__( 'Assertion failed: %s', 'query-monitor' ),
$message
);
} else {
$message = __( 'Assertion failed', 'query-monitor' );
}

if ( $value !== null ) {
$prefix = $message;
$message = $value;
}
}

$this->store( $level, $message, array(), $prefix );
}

/**
* @param string $level
* @param mixed $message
Expand All @@ -158,11 +202,12 @@ public function log( $level, $message, array $context = array() ) {
* @param string $level
* @param mixed $message
* @param array<string, mixed> $context
* @param ?string $prefix
* @phpstan-param self::* $level
* @phpstan-param LogMessage $message
* @return void
*/
protected function store( $level, $message, array $context = array() ) {
protected function store( $level, $message, array $context = array(), string $prefix = null ) {
$trace = new QM_Backtrace( array(
'ignore_hook' => array(
current_filter() => true,
Expand Down Expand Up @@ -201,7 +246,7 @@ protected function store( $level, $message, array $context = array() ) {

$this->data->counts[ $level ]++;
$this->data->logs[] = array(
'message' => self::interpolate( $message, $context ),
'message' => self::interpolate( $message, $context, $prefix ),
'filtered_trace' => $trace->get_filtered_trace(),
'component' => $trace->get_component(),
'level' => $level,
Expand All @@ -211,9 +256,10 @@ protected function store( $level, $message, array $context = array() ) {
/**
* @param string $message
* @param array<string, mixed> $context
* @param ?string $prefix
* @return string
*/
protected static function interpolate( $message, array $context = array() ) {
protected static function interpolate( $message, array $context = array(), string $prefix = null ) {
// build a replacement array with braces around the context keys
$replace = array();

Expand All @@ -223,11 +269,21 @@ protected static function interpolate( $message, array $context = array() ) {
$replace[ "{{$key}}" ] = ( $val ? 'true' : 'false' );
} elseif ( is_scalar( $val ) ) {
$replace[ "{{$key}}" ] = $val;
} elseif ( is_object( $val ) ) {
$replace[ "{{$key}}" ] = sprintf( '[%s]', get_class( $val ) );
} else {
$replace[ "{{$key}}" ] = sprintf( '[%s]', gettype( $val ) );
}
}

// interpolate replacement values into the message and return
return strtr( $message, $replace );
$message = strtr( $message, $replace );

if ( $prefix !== null ) {
$message = $prefix . "\n" . $message;
}

return $message;
}

/**
Expand Down
16 changes: 16 additions & 0 deletions docs/_config.yml
Original file line number Diff line number Diff line change
Expand Up @@ -26,6 +26,22 @@ nav_external_links:
- title: Privacy statement
url: /privacy/
hide_icon: true
callouts_level:
callouts:
highlight:
color: yellow
important:
title: Important
color: blue
new:
title: New
color: green
note:
title: Note
color: purple
warning:
title: Warning
color: red

plugins:
- jekyll-redirect-from
Binary file added docs/assets/assertions.png
Loading
Sorry, something went wrong. Reload?
Sorry, we cannot display this file.
Sorry, this file is invalid so it cannot be displayed.
91 changes: 91 additions & 0 deletions docs/wordpress-debugging/assertions.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,91 @@
---
title: Assertions
parent: WordPress debugging
---

# Performing assertions in Query Monitor

{: .new }
This feature is new in Query Monitor 3.15

Query Monitor allows developers to perform assertions which will log an error in the Logs panel in Query Monitor when they fail. This is a convenience wrapper around the logging feature which allows you to get alerted to problems without performing conditional logic.

Here's what assertions look like in the Logs panel:

[![Query Monitor's Logging Panel](../../assets/assertions.png)](../../assets/assertions.png)

Let's take a look at how to use this feature and what it's useful for.

## Basic usage

```php
do_action( 'qm/assert', $value === 5 );
do_action( 'qm/assert', $value === 5, 'Value is 5' );
do_action( 'qm/assert', $value === 5, 'Value is 5', $value );
```

The `qm/assert` action accepts an assertion value as its first parameter which you'll usually provide in the form of an expression. This should be a boolean `true` or `false` value, although technically anything truthy or falsey is accepted.

If the assertion fails then Query Monitor will show an error in the Logs panel, which in turn causes a red warning to appear in the admin toolbar so you get notified about the failure. If the assertion passes then a debug level message will be shown in the Logs panel, which helps you confirm that your assertion is being executed.

The second parameter is an optional short description of the assertion. If provided, this will be shown along with the assertion failure or pass message.

The third parameter is an optional value of any type that will get output below the error message if the assertion fails. This is useful for debugging an unexpected value.

{: .warning }
Be careful not to log very large values such as an array of post objects or the raw response from an HTTP request. If you really need to debug the value of something large, use a tool such as [step debugging in Xdebug](https://xdebug.org/docs/step_debug) or [debugging in Ray](https://myray.app/).

## More examples

You can use this assertion feature to ensure your code is behaving as expected, for example to assert how many database queries are being performed or not performed:

```php
foreach ( $posts as $post ) {
$before = $wpdb->num_queries;
$this->process_post( $post );
$after = $wpdb->num_queries;

// Assert that no database queries are performed as we process each post:
do_action( 'qm/assert', $after === $before );
}
```

Preconditions can be used to assert a certain state before performing logic based on expectations:

```php
do_action( 'qm/assert', is_array( $data ), 'Data is an array', $data );
do_action( 'qm/assert', array_key_exists( 'foo', $data ), 'Data contains foo', $data );
```

Postconditions can be used to assert that a particular outcome occured:

```php
do_action( 'qm/assert', did_action( 'my-action' ) );
```

The static assertion method on the `QM` class can be used instead of calling `do_action()`:

```php
QM::assert( $value === 5 );
QM::assert( $value === 5, 'Value is 5' );
QM::assert( $value === 5, 'Value is 5', $value );
```

## Differences from `assert()`

This feature differs from the native `assert()` function in PHP because they serve different purposes.

* The `assert()` function in PHP will terminate execution of the script if the assertions fails, this is not true for assertions in Query Monitor. Think of this like a soft assertion that raises an error instead. Code should behave as expected regardless of whether the assertion passes.
* Query Monitor logs passed assertions too. This is useful for verifying that your assertion is being executed.
* Assertions in Query Monitor will always be performed and logged as necessary. The `assert()` function in PHP will only perform the assertion if assertions are enabled in the `php.ini` configuration.
* Assertions in Query Monitor can be passed an optional value to output for debugging purposes, which is not possible with `assert()`.

## Notes on usage

Assertions are primarily a development tool to identify bugs or sub-optimal behaviour in your code. This is distinct from error handling or data validation, which assertions are not intended for.

Just as with the `assert()` function in PHP, your code must handle the situation where your assertion fails because in a production environment the code will continue to execute past the assertion.

## Profiling and logging

[Read more about the profiling and logging functionality in Query Monitor](./profiling-and-logging/).
Loading

0 comments on commit d40485e

Please sign in to comment.