Logging/Debugging

Weston’s printf

Logging in weston takes place through weston_log() function, which calls a log handler (log_handler) that has to be installed before actually calling weston_log(). In weston, the log handler makes use of the logging framework which is (mostly) comprised of Log scopes (produces of data) and Subscribers.

Logging context

Management of the logging framework in weston happens under the weston_log_context object and is entirely separated from the main compositor instance (weston_compositor). The compositor instance can be brought up much more later, but in the same time logging can take place much earlier without the need of a compositor instance.

Instantiation of the weston_log_context object takes place using weston_log_ctx_create() and clean-up/destroy with weston_log_ctx_destroy() or weston_log_ctx_compositor_destroy().

Log scopes

A scope represents a source for a data stream (i.e., a producer). You’ll require one as a way to generate data. Creating a log scope is done using weston_log_ctx_add_log_scope() or weston_compositor_add_log_scope(). You can customize the scope behaviour and you’ll require at least a name and a description for the scope.

Note

A scope name identifies that scope. Scope retrieval from the weston_log_context is done using the scope name. The name is important for the subscription part, detailed bit later.

Log scopes are managed explicitly, and destroying the scope is done using weston_log_scope_destroy().

Available scopes in weston

Weston has a few scopes worth mentioning:

log - a debug scope for generic logging, upon which weston_log() re-routes its data.
proto - debug scope that displays the protocol communication. It is similar to WAYLAND_DEBUG=server environmental variable but has the ability to distinguish multiple clients.
scene-graph - an one-shot debug scope which describes the current scene graph comprising of layers (containers of views), views (which represent a window), their surfaces, sub-surfaces, buffer type and format, both in DRM_FOURCC type and human-friendly form.
drm-backend - Weston uses DRM (Direct Rendering Manager) as one of its backends and this debug scope display information related to that: details the transitions of a view as it takes before being assigned to a hardware plane or to a renderer, current assignments of views, the compositing mode Weston is using for rendering the scene-graph, describes the current hardware plane properties like CRTC_ID, FB_ID, FORMAT when doing a commit or a page-flip. It incorporates the scene-graph scope as well.
xwm-wm-x11 - a scope for the X11 window manager in Weston for supporting Xwayland, printing some X11 protocol actions.
content-protection-debug - scope for debugging HDCP issues.
timeline - see more at Timeline points

Note

Besides ‘log’ scope, which is a generic scope, intended for usage through weston_log(), all the others scopes listed above could suffer various modifications and might not represent a current list on which one should rely upon.

Subscribers

Besides creating a creating a scope, a subscriber (weston_log_subscriber) object needs to be created. The subscriber object is an opaque object (private) and allows customization of the back-end side of libweston. The subscriber object can define its own methods. Users wanting to define a new data stream should extend this weston_log_subscriber.

For example libweston make uses of several type of subscribers, specific to the data streams they will be generating:

a ‘logger’ type created by weston_log_subscriber_create_log()
a ‘flight-recoder’ type created by weston_log_subscriber_destroy_flight_rec()
for the ‘weston-debug’ protocol, which is private/hidden created whenever a client connects

Like log scopes, the subscribers are also manged explicitly and both of the subscriber types above have their destroy counter-parts. weston-debug protocol is a bit special in this regard as the destroying part is handled implicitly using wayland protocol specifics.

Once the subscriber has been created there needs to be a subscription process in which we establish a relationship between the subscriber and the scope.

To create a subscription we use weston_log_subscribe() which uses the subscriber created previously and the scope name. If the scope was not created at the time, the subscription will be (at least for a time) a pending subscription. Once the scope is created the pending subscription is destroyed, not before creating a new subscription to accommodate the initial/original one.

Note

The subscription process is (an) internal API and is managed implicitly.

When a scope is being destroyed the subscriptions for this scope will be destroyed as well.

Logger

weston uses a logger type of a subscriber for logging everything in the code (through the help of weston_log()). The subscriber method (weston_log_subscriber_create_log()) takes an FILE * as an argument in case the std stdout file-descriptor is not where the data should be sent to.

Additionally, specifying which scopes to subscribe to can be done using --logger-scopes command line option. As log scopes are already created in the code, this merely subscribes to them. Default, the ‘log’ scope is being subscribr to the logger subscriber.

Flight recorder

The flight recorder acts like a black box found in airplanes: it accumulates data until the user wants to display its contents. The backed up storage is a simple ring-buffer of a compiled-time fixed size value, and the memory is forcibly-mapped such that we make sure the kernel allocated storage for it.

The user can use the debug keybinding KEY_D (shift+mod+space-d) to force the contents to be printed on stdout file-descriptor. The user has first to specify which log scope to subscribe to.

Specifying which scopes to subscribe for the flight-recorder can be done using --flight-rec-scopes. By default, the ‘log’ scope and ‘drm-backend’ are the scopes subscribed to.

weston-debug protocol

Weston-debug protocol is only present in the weston compositor (i.e., a weston specific compositor). It make uses of the the logging framework presented above, with the exception that the subscription happens automatically rather than manually with weston_log_subscribe() in case of the other two types of subscribers. Also the subscriber is created once the client has connected and requested data from a log scope. This means that each time a client connects a new subscriber will be created. For each stream subscribed a subscription will be created. Enabling the debug-protocol happens using the --debug command line.

Timeline points

A special log scope is the ‘timeline’ scope which, together with wesgr tool, helps diagnose latency issues. Timeline points write to this ‘timeline’ scope in different parts of the compositor, including the GL renderer.

As with all other scopes this scope is available over the debug protocol, or by using the others Subscribers. By far the easiest way to get data out of this scope would be to use the debug protocol. Then use wesgr to process the data which will transform it into a SVG that can be rendered by any web browser.

The following illustrates how to use it:

./weston-debug timeline > log.json
./wesgr -i log.json -o log.svg

Inserting timeline points

Timline points can be inserted using TL_POINT macro. The macro will take the weston_compositor instance, followed by the name of the timeline point. What follows next is a variable number of arguments, which must end with the macro TLP_END.

Debug protocol API

void weston_compositor_enable_debug_protocol(struct weston_compositor *compositor)

Enable weston-debug protocol extension.

This enables the weston_debug_v1 Wayland protocol extension which any client can use to get debug messages from the compositor.

WARNING: This feature should not be used in production. If a client provides a file descriptor that blocks writes, it will block the whole compositor indefinitely.

There is no control on which client is allowed to subscribe to debug messages. Any and all clients are allowed.

The debug extension is disabled by default, and once enabled, cannot be disabled again.

Parameters: compositor – The libweston compositor where to enable.

bool weston_compositor_is_debug_protocol_enabled(struct weston_compositor *wc)

Determine if the debug protocol has been enabled.

Parameters: wc – The libweston compositor to verify if debug protocol has been enabled

Weston Log API

typedef int (*log_func_t)(const char *fmt, va_list ap)

static log_func_t log_handler = default_log_handler : Needs to be set, defaults to default_log_handler.

static log_func_t log_continue_handler = default_log_handler : Needs to be set, defaults to default_log_handler.

static int default_log_handler(const char *fmt, va_list ap)

Sentinel log message handler.

This function is used as the default handler for log messages. It exists only to issue a noisy reminder to the user that a real handler must be installed prior to issuing logging calls. The process is immediately aborted after the reminder is printed.

Parameters

fmt – The format string. Ignored.
ap – The variadic argument list. Ignored.

void weston_log_set_handler(log_func_t log, log_func_t cont)

Install the log handler.

The given functions will be called to output text as passed to the weston_log and weston_log_continue functions.

Parameters

log – The log function. This function will be called when weston_log is called, and should begin a new line, with user defined line headers, if any.
cont – The continue log function. This function will be called when weston_log_continue is called, and should append its output to the current line, without any header or other content in between.

int weston_vlog(const char *fmt, va_list ap): weston_vlog calls log_handler

int weston_log(const char *fmt, ...)

printf() equivalent in weston compositor.

Note

Needs log_handler to be set-up!

void weston_log_paced(struct weston_log_pacer *pacer, unsigned int max_burst, unsigned int reset_ms, const char *fmt, ...)

weston logger with throttling

Throttled logger that will suppress a message after a fixed number of prints, and optionally reset the counter reset_ms miliseconds after the first message in a burst.

On the first new message printed with this pacer after the timeout expires, a count of suppressed messages will also be printed.

Note that the “initialized” member of struct weston_log_pacer must be set to 0 before first call.

Parameters

pacer – The pacer instance
max_burst – Number of messages to allow before throttling - must not be zero.
reset_ms – Duration from burst start before the count is reset, or zero to never reset.
fmt – The format string

int weston_vlog_continue(const char *fmt, va_list argp): weston_vlog_continue calls log_continue_handler

int weston_log_continue(const char *fmt, ...): weston_log_continue

Logging API

void weston_timeline_refresh_subscription_objects(struct weston_compositor *wc, void *object)

Sets (on) the timeline subscription object refresh status.

This function ‘notifies’ timeline to print the object ID. The timeline code will reset it back, so there’s no need for users to do anything about it.

Can be used from outside libweston.

Parameters

wc – a weston_compositor instance
object – the underlying object

void weston_timeline_point(struct weston_log_scope *timeline_scope, const char *name, ...)

Disseminates the message to all subscriptions of the scope timeline_scope.

The TL_POINT() is a wrapper over this function, but it uses the weston_compositor instance to pass the timeline scope.

Parameters

timeline_scope – the timeline scope
name – the name of the timeline point. Interpretable by the tool reading the output (wesgr).

struct weston_log_context *weston_log_ctx_create(void)

Creates weston_log_context structure.

weston_log_context is a singleton for each weston_compositor.

Returns: NULL in case of failure, or a weston_log_context object in case of success

void weston_log_ctx_destroy(struct weston_log_context *log_ctx)

Destroy weston_log_context structure.

Parameters: log_ctx – The log context to destroy.

void weston_log_subscription_complete(struct weston_log_subscription *sub): Close the stream’s complete callback if one was installed/created.

void weston_log_subscription_printf(struct weston_log_subscription *sub, const char *fmt, ...)

Write a formatted string for a subscription.

Writes to formatted string to the stream that created the subscription.

Parameters

sub – The subscription to write for; may be NULL, in which case nothing will be written.
fmt – Printf-style format string and arguments.

void weston_log_subscriber_destroy(struct weston_log_subscriber *subscriber)

Destroy a file type or a flight-rec type subscriber.

They are created, respectively, with weston_log_subscriber_create_log() and weston_log_subscriber_create_flight_rec()

Parameters: subscriber – the weston_log_subscriber object to destroy

void weston_log_subscribe(struct weston_log_context *log_ctx, struct weston_log_subscriber *subscriber, const char *scope_name)

Subscribe to a scope.

Creates a subscription which is used to subscribe the subscriber to the scope scope_name.

If scope_name has already been created (using weston_log_ctx_add_log_scope or weston_compositor_add_log_scope) the subscription will take place immediately, otherwise we store the subscription into a pending list. See also weston_log_ctx_add_log_scope() and weston_compositor_add_log_scope()

Parameters

log_ctx – the log context, used for accessing pending list
subscriber – the subscriber, which has to be created before
scope_name – the scope name. In case the scope is not created we temporarily store the subscription in the pending list.

TLP_END: Should be used as the last argument when using TL_POINT macro.

TL_POINT(ec, ...)

This macro is used to add timeline points.

Use TLP_END when done for the vargs.

Parameters

ec – weston_compositor instance

struct weston_log_scope

weston-log message scope

This is used for scoping logging/debugging messages. Clients can subscribe to only the scopes they are interested in. A scope is identified by its name (also referred to as debug stream name).

Public Types

typedef void (*weston_log_scope_cb)(struct weston_log_subscription *sub, void *user_data)

weston_log_scope callback

Parameters

sub – The subscription.
user_data – The user_data argument given to weston_log_ctx_add_log_scope() or weston_compositor_add_log_scope().

Public Functions

struct weston_log_scope *weston_log_ctx_add_log_scope(struct weston_log_context *log_ctx, const char *name, const char *description, weston_log_scope_cb new_subscription, weston_log_scope_cb destroy_subscription, void *user_data)

Register a new stream name, creating a log scope.

This function is used to create a log scope. All debug message printing happens for a scope, which allows clients to subscribe to the kind of debug messages they want by name. For the weston-debug protocol, subscription for the scope will happen automatically but for other types of streams, weston_log_subscribe() should be called as to create a subscription and tie it to the scope created by this function.

name must be unique in the weston_compositor instance. name and description must both be provided. In case of the weston-debug protocol, the description is printed when a client asks for a list of supported log scopes.

new_subscription, if not NULL, is called when a client subscribes to the log scope creating a debug stream. This is for log scopes that need to print messages as a response to a client appearing, e.g. printing a list of windows on demand or a static preamble. The argument user_data is passed in to the callback and is otherwise unused.

For one-shot debug streams, new_subscription should finally call weston_log_subscription_complete() to close the stream and tell the client the printing is complete. Otherwise the client expects more data to be written. The complete callback in weston_log_subscriber should be installed to trigger it and it is set-up automatically for the weston-debug protocol.

As subscription can take place before creating the scope, any pending subscriptions to scope added by weston_log_subscribe(), will be checked against the scope being created and if found will be added to the scope’s subscription list.

The log scope must be destroyed using weston_log_scope_destroy() before destroying the weston_compositor.

See: weston_log_scope_cb, weston_log_subscribe

Parameters

log_ctx – The weston_log_context where to add.
name – The debug stream/scope name; must not be NULL.
description – The log scope description for humans; must not be NULL.
new_subscription – Optional callback when a client subscribes to this scope.
destroy_subscription – Optional callback when a client destroys the subscription.
user_data – Optional user data pointer for the callback.

Returns

A valid pointer on success, NULL on failure.

void weston_log_scope_destroy(struct weston_log_scope *scope)

Destroy a log scope.

Destroys the log scope, calling each stream’s destroy callback if one was installed/created.

Parameters: scope – The log scope to destroy; may be NULL.

bool weston_log_scope_is_enabled(struct weston_log_scope *scope)

Are there any active subscriptions to the scope?

As printing some debugging messages may be relatively expensive, one can use this function to determine if there is a need to gather the debugging information at all. If this function returns false, all printing for this scope is dropped, so gathering the information is pointless.

The return value of this function should not be stored, as new clients may subscribe to the debug scope later.

If the given scope is NULL, this function will always return false, making it safe to use in teardown or destroy code, provided the scope is initialized to NULL before creation and set to NULL after destruction.

Parameters: scope – The log scope to check; may be NULL.
Returns: True if any streams are open for this scope, false otherwise.

void weston_log_scope_complete(struct weston_log_scope *scope)

Close the log scope.

Complete the log scope, calling each stream’s complete callback if one was installed/created. This can be useful to signal the reading end that the data has been transmitted and should no longer expect that written over the stream. Particularly useful for the weston-debug protocol.

See: weston_log_ctx_add_log_scope, weston_compositor_add_log_scope, weston_log_scope_destroy

Parameters: scope – The log scope to complete; may be NULL.

void weston_log_scope_write(struct weston_log_scope *scope, const char *data, size_t len)

Write log data for a scope.

Writes the given data to all subscribed clients’ streams.

Parameters

scope – The debug scope to write for; may be NULL, in which case nothing will be written.
data – [in] Pointer to the data to write.
len – Number of bytes to write.

int weston_log_scope_vprintf(struct weston_log_scope *scope, const char *fmt, va_list ap)

Write a formatted string for a scope (varargs)

Writes to formatted string to all subscribed clients’ streams.

The behavioral details for each stream are the same as for weston_debug_stream_write().

Parameters

scope – The log scope to write for; may be NULL, in which case nothing will be written.
fmt – Printf-style format string.
ap – Formatting arguments.

int weston_log_scope_printf(struct weston_log_scope *scope, const char *fmt, ...)

Write a formatted string for a scope.

Writes to formatted string to all subscribed clients’ streams.

The behavioral details for each stream are the same as for weston_debug_stream_write().

Parameters

scope – The log scope to write for; may be NULL, in which case nothing will be written.
fmt – Printf-style format string and arguments.

char *weston_log_scope_timestamp(struct weston_log_scope *scope, char *buf, size_t len)

Write debug scope name and current time into string.

Reads the current local wall-clock time and formats it into a string. and append the debug scope name to it, if a scope is available. The string is NUL-terminated, even if truncated.

Parameters

scope – [in] debug scope; may be NULL
buf – [out] Buffer to store the string.
len – Available size in the buffer in bytes.

Returns

buf

Public Members

char *name

char *desc

weston_log_scope_cb new_subscription

weston_log_scope_cb destroy_subscription

void *user_data

struct wl_list compositor_link

struct wl_list subscription_list: weston_log_subscription::source_link

Internal logging API

Note

The following is mean to be internal API and aren’t exposed in libweston!

void weston_timeline_create_subscription(struct weston_log_subscription *sub, void *user_data)

Create a timeline subscription and hang it off the subscription.

Called when the subscription is created.

void weston_timeline_destroy_subscription(struct weston_log_subscription *sub, void *user_data)

Destroy the timeline subscription and all timeline subscription objects associated with it.

Called when (before) the subscription is destroyed.

struct weston_log_scope *weston_log_get_scope(struct weston_log_context *log_ctx, const char *name)

Look-up the scope from the scope list stored in the log context, by matching against the name.

Parameters

log_ctx –
name – the scope name, see weston_log_ctx_add_log_scope() and weston_compositor_add_log_scope()

Returns

NULL if none found, or a pointer to a weston_log_scope

void weston_log_run_cb_new_subscription(struct weston_log_subscription *sub)

Wrapper to invoke the weston_log_scope_cb.

Allows to call the cb new_subscription of a log scope.

void weston_debug_protocol_advertise_scopes(struct weston_log_context *log_ctx, struct wl_resource *res)

Advertise the log scope name and the log scope description.

This is only used by the weston-debug protocol!

static void weston_log_ctx_disable_debug_protocol(struct weston_log_context *log_ctx)

Disable debug-protocol.

Parameters: log_ctx – The log context where the debug-protocol is linked

struct timeline_emit_context

Timeline itself is not a subscriber but a scope (a producer of data), and it re-routes the data it produces to all the subscriptions (and implicitly to the subscribers) using a subscription iteration to go through all of them.

Public API:

weston_timeline_refresh_subscription_objects() - allows outside parts of libweston notify/signal timeline code about the fact that underlying object has suffered some modifications and needs to re-emit the object ID.
weston_log_timeline_point() - which will disseminate data to all subscriptions

Do note that only weston_timeline_refresh_subscription_objects() is exported in libweston.

Destruction of the objects assigned to each underlying objects happens in two places: one in the logging framework callback of the log scope (‘destroy_subscription’), and secondly, when the object itself gets destroyed.

timeline_emit_context - For each subscription this object will be created to store a buffer when the object itself will be written and a subscription, which will be used to force the object ID if there is a need to do so (the underlying object has been refreshed, or better said has suffered some modification). Data written to a subscription will be flushed before the data written to the FILE *.

See: weston_timeline_point

param cur: a FILE *
param subscription: a pointer to an already created subscription

Public Members

FILE *cur

struct weston_log_subscription *subscription

struct weston_timeline_subscription

#include <timeline.h>

Timeline subscription created for each subscription.

Created automatically by weston_log_scope::new_subscription and destroyed by weston_log_scope::destroy_subscription.

Public Members

unsigned int next_id

struct wl_list objects: weston_timeline_subscription_object::subscription_link

struct weston_timeline_subscription_object

#include <timeline.h>

Created when object is first seen for a particular timeline subscription Destroyed when the subscription got destroyed or object was destroyed.

Public Members

void *object: points to the object

unsigned int id

bool force_refresh

struct wl_list subscription_link: weston_timeline_subscription::objects

struct wl_listener destroy_listener

struct weston_log_subscriber

#include <weston-log-internal.h>

Subscriber allows each type of stream to customize or to provide its own methods to manipulate the underlying storage.

It follows also an object-oriented approach, contains the ops callbacks and a list of subcriptions of type weston_log_subscription. Each subscription created will be both added to this subscription list and that of the weston_log_scope.

A kind of stream can inherit the subscriber class and provide its own callbacks:

struct weston_log_data_stream {
        struct weston_log_subscriber base;
        struct weston_data_stream opaque;
};

Passing the base class will require container retrieval type of methods to be allowed to reach the opaque type (i.e., container_of()).

Public Members

void (*write)(struct weston_log_subscriber *sub, const char *data, size_t len)

write the data pointed by

Parameters: data –

void (*destroy)(struct weston_log_subscriber *sub): For destroying the subscriber.

void (*destroy_subscription)(struct weston_log_subscriber *sub): For the type of streams that required additional destroy operation for destroying the stream.

void (*complete)(struct weston_log_subscriber *sub): For the type of streams that can inform the ‘consumer’ part that write operation has been terminated/finished and should close the stream.

struct wl_list subscription_list: weston_log_subscription::owner_link

struct weston_log_context

Main weston-log context.

One per weston_compositor. Stores list of scopes created and a list pending subscriptions.

A pending subscription is a subscription to a scope which hasn’t been created. When the scope is finally created the pending subscription will be removed from the pending subscription list, but not before was added in the scope’s subscription list and that of the subscriber list.

Pending subscriptions only make sense for other types of streams, other than those created by weston-debug protocol. In the case of the weston-debug protocol, the subscription processes is done automatically whenever a client connects and subscribes to a scope which was previously advertised by the compositor.

Public Members

struct wl_global *global

struct wl_listener compositor_destroy_listener

struct wl_list scope_list: weston_log_scope::compositor_link

struct wl_list pending_subscription_list: weston_log_subscription::source_link

struct weston_log_subscription

Ties a subscriber to a scope.

A subscription is created each time we’d want to subscribe to a scope. From the stream type we can retrieve the subscriber and from the subscriber we reach each of the streams callbacks. See also weston_log_subscriber object.

When a subscription has been created we store it in the scope’s subscription list and in the subscriber’s subscription list. The subscription might be a pending subscription until the scope for which there’s was a subscribe has been created. The scope creation will take of looking through the pending subscription list.

A subscription can reached from a subscriber subscription list by using the streams base class.

Public Functions

void weston_log_subscription_create(struct weston_log_subscriber *owner, struct weston_log_scope *scope)

Creates a new subscription using the subscriber by owner.

The subscription created is added to the owner subscription list. Destroying the subscription using weston_log_subscription_destroy() will remove the link from the subscription list and free storage alloc’ed.

Note that this adds the subscription to the scope’s subscription list hence the scope required argument.

See: weston_log_subscription_destroy, weston_log_subscription_remove, weston_log_subscription_add

Parameters

owner – the subscriber owner, must be created before creating a subscription
scope – the scope in order to add the subscription to the scope’s subscription list

void weston_log_subscription_destroy(struct weston_log_subscription *sub)

Destroys the subscription.

Removes the subscription from the scopes subscription list and from subscriber’s subscription list. It destroys the subscription afterwads.

void weston_log_subscription_add(struct weston_log_scope *scope, struct weston_log_subscription *sub)

Adds the subscription sub to the subscription list of the scope.

This should used when the scope has been created, and the subscription sub has be created before calling this function.

Parameters

scope – the scope
sub – the subscription, it must be created before, see weston_log_subscription_create()

void weston_log_subscription_remove(struct weston_log_subscription *sub): Removes the subscription from the scope’s subscription list.

Public Members

struct weston_log_subscriber *owner

struct wl_list owner_link: weston_log_subscriber::subscription_list

char *scope_name

struct weston_log_scope *source

struct wl_list source_link: weston_log_scope::subscription_list or weston_log_context::pending_subscription_list

void *data

Public Static Functions

static void weston_log_subscription_create_pending(struct weston_log_subscriber *owner, const char *scope_name, struct weston_log_context *log_ctx)

Create a pending subscription and add it the list of pending subscriptions.

Parameters

owner – a subscriber represented by weston_log_subscriber object
scope_name – the name of the scope (which we don’t have in the list of scopes)
log_ctx – the logging context used to add the pending subscription

static void weston_log_subscription_destroy_pending(struct weston_log_subscription *sub)

Destroys the pending subscription created previously with weston_log_subscription_create_pending()

Parameters: sub – the weston_log_subscription object to remove from the list of subscriptions and to destroy the subscription

static void weston_log_subscription_write(struct weston_log_subscription *sub, const char *data, size_t len): Write to the stream’s subscription.

static void weston_log_subscription_vprintf(struct weston_log_subscription *sub, const char *fmt, va_list ap): Write a formatted string to the stream’s subscription.