2016-08-19 12:21:48 +08:00
|
|
|
# Change Notes
|
|
|
|
|
|
|
|
## Summary
|
|
|
|
|
|
|
|
This document describes the DarwinLog logging feature.
|
|
|
|
|
|
|
|
## StructuredDataDarwinLog feature
|
|
|
|
|
2016-12-13 13:54:17 +08:00
|
|
|
The DarwinLog feature supports logging `os_log`*() and `NSLog`() messages
|
2016-08-19 12:21:48 +08:00
|
|
|
to the command-line lldb console, as well as making those messages
|
|
|
|
available to LLDB clients via the event system. Starting with fall
|
|
|
|
2016 OSes, Apple platforms introduce a new fire-hose, stream-style
|
|
|
|
logging system where the bulk of the log processing happens on the log
|
|
|
|
consumer side. This reduces logging impact on the system when there
|
|
|
|
are no consumers, making it cheaper to include logging at all times.
|
|
|
|
However, it also increases the work needed on the consumer end when
|
|
|
|
log messages are desired.
|
|
|
|
|
|
|
|
The debugserver binary has been modified to support collection of
|
2016-12-13 13:54:17 +08:00
|
|
|
`os_log`*()/`NSLog`() messages, selection of which messages appear in the
|
2016-08-19 12:21:48 +08:00
|
|
|
stream, and fine-grained filtering of what gets passed on to the LLDB
|
2016-12-13 13:54:17 +08:00
|
|
|
client. DarwinLog also tracks the activity chain (i.e. `os_activity`()
|
2016-08-19 12:21:48 +08:00
|
|
|
hierarchy) in effect at the time the log messages were issued. The
|
|
|
|
user is able to configure a number of aspects related to the
|
|
|
|
formatting of the log message header fields.
|
|
|
|
|
|
|
|
The DarwinLog support is written in a way which should support the
|
|
|
|
lldb client side on non-Apple clients talking to an Apple device or
|
|
|
|
macOS system; hence, the plugin support is built into all LLDB
|
|
|
|
clients, not just those built on an Apple platform.
|
|
|
|
|
|
|
|
StructuredDataDarwinLog implements the 'DarwinLog' feature type, and
|
2016-12-13 13:54:17 +08:00
|
|
|
the plugin name for it shows up as `darwin-log`.
|
2016-08-19 12:21:48 +08:00
|
|
|
|
|
|
|
The user interface to the darwin-log support is via the following:
|
|
|
|
|
2016-12-13 13:54:17 +08:00
|
|
|
* `plugin structured-data darwin-log enable` command
|
2016-08-19 12:21:48 +08:00
|
|
|
|
|
|
|
This is the main entry point for enabling the command. It can be
|
|
|
|
set before launching a process or while the process is running.
|
|
|
|
If the user wants to squelch seeing info-level or debug-level
|
|
|
|
messages, which is the default behavior, then the enable command
|
|
|
|
must be made prior to launching the process; otherwise, the
|
|
|
|
info-level and debug-level messages will always show up. Also,
|
|
|
|
there is a similar "echo os_log()/NSLog() messages to target
|
|
|
|
process stderr" mechanism which is properly disabled when enabling
|
|
|
|
the DarwinLog support prior to launch. This cannot be squelched
|
|
|
|
if enabling DarwinLog after launch.
|
|
|
|
|
|
|
|
See the help for this command. There are a number of options
|
|
|
|
to shrink or expand the number of messages that are processed
|
|
|
|
on the remote side and sent over to the client, and other
|
|
|
|
options to control the formatting of messages displayed.
|
|
|
|
|
|
|
|
This command is sticky. Once enabled, it will stay enabled for
|
|
|
|
future process launches.
|
|
|
|
|
2016-12-13 13:54:17 +08:00
|
|
|
* `plugin structured-data darwin-log disable` command
|
2016-08-19 12:21:48 +08:00
|
|
|
|
|
|
|
Executing this command disables os_log() capture in the currently
|
|
|
|
running process and signals LLDB to stop attempting to launch
|
|
|
|
new processes with DarwinLog support enabled.
|
|
|
|
|
2016-12-13 13:54:17 +08:00
|
|
|
* `settings set
|
|
|
|
plugin.structured-data.darwin-log.enable-on-startup true`
|
2016-08-19 12:21:48 +08:00
|
|
|
|
|
|
|
and
|
|
|
|
|
2016-12-13 13:54:17 +08:00
|
|
|
`settings set
|
|
|
|
plugin.structured-data.darwin-log.auto-enable-options -- `{options}
|
2016-08-19 12:21:48 +08:00
|
|
|
|
2016-12-13 13:54:17 +08:00
|
|
|
When `enable-on-startup` is set to `true`, then LLDB will automatically
|
2016-08-19 12:21:48 +08:00
|
|
|
enable DarwinLog on startup of relevant processes. It will use the
|
|
|
|
content provided in the auto-enable-options settings as the
|
|
|
|
options to pass to the enable command.
|
|
|
|
|
2016-12-13 13:54:17 +08:00
|
|
|
Note the `--` required after auto-enable-command. That is necessary
|
|
|
|
for raw commands like settings set. The `--` will not become part
|
2016-08-19 12:21:48 +08:00
|
|
|
of the options for the enable command.
|
|
|
|
|
|
|
|
### Message flow and related performance considerations
|
|
|
|
|
2016-12-13 13:54:17 +08:00
|
|
|
`os_log`()-style collection is not free. The more data that must be
|
2016-08-19 12:21:48 +08:00
|
|
|
processed, the slower it will be. There are several knobs available
|
|
|
|
to the developer to limit how much data goes through the pipe, and how
|
|
|
|
much data ultimately goes over the wire to the LLDB client. The
|
|
|
|
user's goal should be to ensure he or she only collects as many log
|
|
|
|
messages are needed, but no more.
|
|
|
|
|
|
|
|
The flow of data looks like the following:
|
|
|
|
|
|
|
|
1. Data comes into debugserver from the low-level OS facility that
|
|
|
|
receives log messages. The data that comes through this pipe can
|
2016-12-13 13:54:17 +08:00
|
|
|
be limited or expanded by the `--debug`, `--info` and
|
|
|
|
`--all-processes` options of the `plugin structured-data darwin-log
|
|
|
|
enable` command options. Exclude as many categories as possible
|
2016-08-19 12:21:48 +08:00
|
|
|
here (also the default). The knobs here are very coarse - for
|
2016-12-13 13:54:17 +08:00
|
|
|
example, whether to include `os_log_info()`-level or
|
|
|
|
`os_log_debug()`-level info, or to include callstacks in the log
|
2016-08-19 12:21:48 +08:00
|
|
|
message event data.
|
|
|
|
|
|
|
|
2. The debugserver process filters the messages that arrive through a
|
|
|
|
message log filter that may be fully customized by the user. It
|
|
|
|
works similar to a rules-based packet filter: a set of rules are
|
|
|
|
matched against the log message, each rule tried in sequential
|
|
|
|
order. The first rule that matches then either accepts or rejects
|
|
|
|
the message. If the log message does not match any rule, then the
|
|
|
|
message gets the no-match (i.e. fall-through) action. The no-match
|
|
|
|
action defaults to accepting but may be set to reject.
|
|
|
|
|
2016-12-13 13:54:17 +08:00
|
|
|
Filters can be added via the enable command's '`--filter`
|
2016-08-19 12:21:48 +08:00
|
|
|
{filter-spec}' option. Filters are added in order, and multiple
|
2016-12-13 13:54:17 +08:00
|
|
|
`--filter` entries can be provided to the enable command.
|
2016-08-19 12:21:48 +08:00
|
|
|
|
|
|
|
Filters take the following form:
|
2016-12-13 13:54:17 +08:00
|
|
|
```
|
2016-08-19 12:21:48 +08:00
|
|
|
{action} {attribute} {op}
|
|
|
|
|
|
|
|
{action} :=
|
|
|
|
accept |
|
|
|
|
reject
|
|
|
|
|
|
|
|
{attribute} :=
|
|
|
|
category | // The log message category
|
2016-12-13 13:54:17 +08:00
|
|
|
subsystem | // The log message subsystem
|
2016-08-19 12:21:48 +08:00
|
|
|
activity | // The child-most activity in force
|
|
|
|
// at the time the message was logged.
|
|
|
|
activity-chain | // The complete activity chain, specified
|
|
|
|
// as {parent-activity}:{child-activity}:
|
|
|
|
// {grandchild-activity}
|
|
|
|
message | // The fully expanded message contents.
|
|
|
|
// Note this one is expensive because it
|
|
|
|
// requires expanding the message. Avoid
|
|
|
|
// this if possible, or add it further
|
|
|
|
// down the filter chain.
|
|
|
|
|
|
|
|
{op} :=
|
|
|
|
match {exact-match-text} |
|
|
|
|
regex {search-regex} // uses C++ std::regex
|
|
|
|
// ECMAScript variant.
|
2016-12-13 13:54:17 +08:00
|
|
|
```
|
|
|
|
e.g.
|
|
|
|
`--filter "accept subsystem match com.example.mycompany.myproduct"`
|
|
|
|
`--filter "accept subsystem regex com.example.+"`
|
|
|
|
`--filter "reject category regex spammy-system-[[:digit:]]+"`
|
2016-08-19 12:21:48 +08:00
|
|
|
|
|
|
|
3. Messages that are accepted by the log message filter get sent to
|
|
|
|
the lldb client, where they are mapped to the
|
|
|
|
StructuredDataDarwinLog plugin. By default, command-line lldb will
|
|
|
|
issue a Process-level event containing the log message content, and
|
|
|
|
will request the plugin to print the message if the plugin is
|
|
|
|
enabled to do so.
|
|
|
|
|
|
|
|
### Log message display
|
|
|
|
|
|
|
|
Several settings control aspects of displaying log messages in
|
2016-12-13 13:54:17 +08:00
|
|
|
command-line LLDB. See the `enable` command's help for a description
|
2016-08-19 12:21:48 +08:00
|
|
|
of these.
|
|
|
|
|
|
|
|
|