fidlcat: Guide

Launching fidlcat

For information about launching fidlcat: fidlcat.

{% dynamic if request.tld != “dev” %}

Notice

This file only renders correctly from fuchsia.dev. Please navigate to https://fuchsia.dev/fuchsia-src/development/monitoring/fidlcat/fidlcat_usage.md to see the examples correctly!

{% dynamic endif %}

Default display

The default display for fidlcat is:

  1. echo_client_cpp_synchronous 180768:180781 zx_channel_call(handle:handle: 14b21e1b, options:uint32: 0, deadline:time: ZX_TIME_INFINITE, rd_num_bytes:uint32: 65536, rd_num_handles:uint32: 64)
  2.   sent request fidl.examples.echo/Echo.EchoString = {
  3.     value: string = "hello synchronous world"
  4.   }
  5.   -> ZX_OK
  6.     received response fidl.examples.echo/Echo.EchoString = {
  7.       response: string = "hello synchronous world"
  8.     }

We have the following information:

  • echo_client_cpp_synchronous: the name of the application that has generated this display.

  • 180768: the process koid.

  • 180781: the thread koid.

  • zx_channel_call: the name of the intercepted/displayed system call.

  • all the basic input parameters of the system call (here handle and options).

    For each one, we have:

    • The name of the parameter in black.

    • The type of the parameter in green.

    • The value of the parameter (the color depends on the parameter type).

  • all the complex input parameters. Here we display a FIDL message. This is a request, which is sent by our application.

The display stops here. It will resume when the system call returns (sometimes it can be a very long time). For one thread, there will be no other display between the input arguments and the returned value. However, another thread display may be interleaved. When the system call returns, we display:

  • The returned value (-> ZX_OK)

  • The basic output parameters (there is no basic output parameters in this example).

  • The complex output parameters. Here we display a FIDL message. This is the response we received to the request we sent.

For zx_channel_read we can have this display:

  1. echo_client_rust 256109:256122 zx_channel_read(handle:handle: e4c7c57f, options:uint32: 0, num_bytes:uint32: 48, num_handles:uint32: 0)
  2.   -> ZX_OK
  3.     received response fidl.examples.echo/Echo.EchoString = {
  4.       response: string = "hello world!"
  5.     }

But, if there is an error, we can have:

  1. echo_client_rust 256109:256122 zx_channel_read(handle:handle: e4c7c57f, options:uint32: 0, num_bytes:uint32: 0, num_handles:uint32: 0)
  2.   -> ZX_ERR_SHOULD_WAIT

Or:

  1. echo_client_rust 256109:256122 zx_channel_read(handle:handle: e4c7c57f, options:uint32: 0, num_bytes:uint32: 0, num_handles:uint32: 0)
  2.   -> ZX_ERR_BUFFER_TOO_SMALL (actual_bytes:uint32: 48, actual_handles:uint32: 0)

In this last case, even if the system call fails, we have some valid output parameters. actual_bytes and actual_handles give the minimal values which should have been used to call zx_channel_read.

Modifying the display

By default, we only display the process information on the first line.

Eventually, we also display the process information before the returned value if a system call from another thread has been displayed between the call and the returned value:

  1. ledger.cmx 5859666:5861991 zx_channel_write(handle:handle: 035393df, options:uint32: 0)
  2.   sent request fuchsia.io/Directory.Open = {
  3.     flags: uint32 = 12582912
  4.     mode: uint32 = 0
  5.     path: string = "29/cache/cached_db"
  6.     object: handle = 03f3b46b
  7.   }
  8.  
  9. ledger.cmx 5859666:5859693 zx_channel_write(handle:handle: 035393df, options:uint32: 0)
  10.   sent request fuchsia.io/Directory.Open = {
  11.     flags: uint32 = 13107200
  12.     mode: uint32 = 0
  13.     path: string = "."
  14.     object: handle = 0053b5fb
  15.   }
  16.  
  17. ledger.cmx 5859666:5861991   -> ZX_OK
  18.  
  19. ledger.cmx 5859666:5859693   -> ZX_OK

Using the flag —with-process-info, we can display the process information on each line:

  1. echo_client_rust 305640:305653 zx_channel_write(handle:handle: 4446ec4b, options:uint32: 0)
  2. echo_client_rust 305640:305653   sent request fidl.examples.echo/Echo.EchoString = {
  3. echo_client_rust 305640:305653     value: string = "hello world!"
  4. echo_client_rust 305640:305653   }
  5. echo_client_rust 305640:305653   -> ZX_OK

This is very useful if we want to do a grep on the output (for example, to only select one thread).

Interpreting the display

Most of the time we want to link several messages to be able to understand what our program is doing.

In this example:

  1. ledger.cmx 5859666:5859693 zx_channel_create(options:uint32: 0)
  2.   -> ZX_OK (out0:handle: 0243b493, out1:handle: 0163b42b)
  3.  
  4. ledger.cmx 5859666:5859693 zx_channel_write(handle:handle: 035393df, options:uint32: 0)
  5.   sent request fuchsia.io/Directory.Open = {
  6.     flags: uint32 = 12582912
  7.     mode: uint32 = 0
  8.     path: string = "29"
  9.     object: handle = 0163b42b
  10.   }
  11.   -> ZX_OK
  12.  
  13. ledger.cmx 5859666:5859693 zx_channel_read(handle:handle: 0243b493, options:uint32: 1, num_bytes:uint32: 64, num_handles:uint32: 1)
  14.   -> ZX_OK
  15.     received response fuchsia.io/Node.OnOpen = {
  16.       s: int32 = -25
  17.       info: fuchsia.io/NodeInfo = null
  18.     }
  19.  
  20. ledger.cmx 5859666:5859693 zx_channel_read(handle:handle: 0243b493, options:uint32: 1, num_bytes:uint32: 64, num_handles:uint32: 1)
  21.   -> ZX_OK
  22.     received response fuchsia.io/Node.OnOpen = {
  23.       s: int32 = 0
  24.       info: fuchsia.io/NodeInfo = { directory: fuchsia.io/DirectoryObject = {} }
  25.     }
  26.  
  27. ledger.cmx 5859666:5859693 zx_channel_call(handle:handle: 0243b493, options:uint32: 0, deadline:time: ZX_TIME_INFINITE, rd_num_bytes:uint32: 24, rd_num_handles:uint32: 0)
  28.   sent request fuchsia.io/Node.Close = {}
  29.   -> ZX_OK
  30.     received response fuchsia.io/Node.Close = {
  31.       s: int32 = 0
  32.     }

We first create a channel. The two handles 0243b493 and 0163b42b are linked. That means that a write on one handle will result on a read on the other handle.

We use handle 0163b42b in the Directory.Open message. That means that the associated handle (0243b493) is the handle that controls the directory we just opened.

When we receive Node.OnOpen on 0243b493 we know that it’s a response to our Directory.Open. We also used the handle to call Node.Close.

Stack frames

By default, only the system calls are displayed. However, it’s sometime interesting to know where a system call has been called. Using the flag —stack we can display the stack frames for every system call.

By default (—stack=0), the stack frames are not displayed.

With —stack=1 only the call site (1 to 4 frames) is displayed:

  1. echo_client_cpp 5231515:5231528 at zircon/system/ulib/fidl/message.cc:62 fidl::Message::Read
  2. echo_client_cpp 5231515:5231528 zx_channel_read(handle:handle: a0575917, options:uint32: 0, num_bytes:uint32: 65536, num_handles:uint32: 64)
  3.   -> ZX_OK
  4.     received response fidl.examples.echo/Echo.EchoString = {
  5.       response: string = "hello world"
  6.     }

This option doesn’t add any overhead (except for the display).

With —stack=2 all the frames are displayed:

  1. echo_client_cpp 5234749:5234762 at zircon/third_party/ulib/musl/src/env/__libc_start_main.c:74 start_main
  2. echo_client_cpp 5234749:5234762 at garnet/examples/fidl/echo_client_cpp/echo_client.cc:40 main
  3. echo_client_cpp 5234749:5234762 at zircon/system/ulib/async-loop/loop_wrapper.cc:25 async::Loop::Run
  4. echo_client_cpp 5234749:5234762 at zircon/system/ulib/async-loop/loop.c:241 async_loop_run
  5. echo_client_cpp 5234749:5234762 at zircon/system/ulib/async-loop/loop.c:284 async_loop_run_once
  6. echo_client_cpp 5234749:5234762 at zircon/system/ulib/async-loop/loop.c:335 async_loop_dispatch_wait
  7. echo_client_cpp 5234749:5234762 at sdk/lib/fidl/cpp/internal/message_reader.cc:165 fidl::internal::MessageReader::CallHandler
  8. echo_client_cpp 5234749:5234762 at sdk/lib/fidl/cpp/internal/message_reader.cc:177 fidl::internal::MessageReader::OnHandleReady
  9. echo_client_cpp 5234749:5234762 at sdk/lib/fidl/cpp/internal/message_reader.cc:201 fidl::internal::MessageReader::ReadAndDispatchMessage
  10. echo_client_cpp 5234749:5234762 at zircon/system/ulib/fidl/message.cc:62 fidl::Message::Read
  11. echo_client_cpp 5234749:5234762 zx_channel_read(handle:handle: a95c4cdf, options:uint32: 0, num_bytes:uint32: 65536, num_handles:uint32: 64)
  12.   -> ZX_OK
  13.     received response fidl.examples.echo/Echo.EchoString = {
  14.       response: string = "hello world"
  15.     }

This option adds some overhead because we need to ask zxdb for the full stack for each system call (and fidlcat becomes even more verbose). You should use it only when you need to understand what part of your code called the system calls.

Exceptions

Sometimes, your program crashes. If it’s monitored by fidlcat you automatically have a stack where it crashed.

For example:

  1. echo_server_cpp.cmx 1707964:1707977 zx_channel_read(handle:handle: ca322b6f, options:uint32: 0, num_bytes:uint32: 65536, num_handles:uint32: 64)
  2.   -> ZX_OK
  3.     received request fidl.examples.echo/Echo.EchoString = {
  4.       value: string = "hello world"
  5.     }
  6.  
  7. echo_server_cpp.cmx 1707964:1707977 at zircon/third_party/ulib/musl/src/env/__libc_start_main.c:93 start_main
  8. echo_server_cpp.cmx 1707964:1707977 at garnet/examples/fidl/echo_server_cpp/echo_server.cc:15 main
  9. echo_server_cpp.cmx 1707964:1707977 at zircon/system/ulib/async-loop/loop_wrapper.cc:21 async::Loop::Run
  10. echo_server_cpp.cmx 1707964:1707977 at zircon/system/ulib/async-loop/loop.c:194 async_loop_run
  11. echo_server_cpp.cmx 1707964:1707977 at zircon/system/ulib/async-loop/loop.c:236 async_loop_run_once
  12. echo_server_cpp.cmx 1707964:1707977 at zircon/system/ulib/async-loop/loop.c:277 async_loop_dispatch_wait
  13. echo_server_cpp.cmx 1707964:1707977 at sdk/lib/fidl/cpp/internal/message_reader.cc:165 fidl::internal::MessageReader::CallHandler
  14. echo_server_cpp.cmx 1707964:1707977 at sdk/lib/fidl/cpp/internal/message_reader.cc:177 fidl::internal::MessageReader::OnHandleReady
  15. echo_server_cpp.cmx 1707964:1707977 at sdk/lib/fidl/cpp/internal/message_reader.cc:228 fidl::internal::MessageReader::ReadAndDispatchMessage
  16. echo_server_cpp.cmx 1707964:1707977 at sdk/lib/fidl/cpp/internal/stub_controller.cc:32 fidl::internal::StubController::OnMessage
  17. echo_server_cpp.cmx 1707964:1707977 at fidling/gen/garnet/examples/fidl/services/fidl/examples/echo/cpp/fidl.cc:152 fidl::examples::echo::Echo_Stub::Dispatch_
  18. echo_server_cpp.cmx 1707964:1707977 at garnet/examples/fidl/echo_server_cpp/echo_server_app.cc:22 echo::EchoServerApp::EchoString
  19. echo_server_cpp.cmx 1707964:1707977 thread stopped on exception

You have the stack frames for the exception even if you didn’t ask for the stack frames with the —stack options.

Syscalls

By default, fidlcat only displays the zx_channel syscalls.

You can display all the syscalls and choose which ones you want to display.

The —syscalls option let you define a regular expression that selects the syscalls to decode and display.

It can be passed multiple times.

To display all the syscalls, use: —syscalls=”.*“

The —exclude-syscalls flag lets you exclude some syscalls selected by —syscalls. It’s a regular expression that selects the syscalls to not decode and display.

It can be passed multiple times.

To be displayed, a syscall must satisfy the —syscalls pattern and not satisfy the —exclude-syscalls pattern.

To display all the syscalls but the zx_handle syscalls, use:

—syscalls “.*“ —exclude-syscalls “zxhandle.*“

Filtering messages

By default, fidlcat displays all the messages.

You can specify the messages you want to display using:

  • —messages allows you to specify one or more regular expressions the messages must satisfy to be displayed.

  • —exclude-messages allows you to specify one or more regular expressions the messages must not satisfy to be displayed.

If both options are used at the same time, to be displayed, a message must satisfy one of the regular expressions specified with —messages and not satisfy any regular expression specified with —exclude-messages.

Message filtering works on the method’s fully qualified name. For example, with:

  1. --messages=".*Open"

Methods like:

  1. fuchsia.io/Directory.Open
  2. fuchsia.io/Node.OnOpen

Will match.

Postponing the message display

By default, everything is displayed as soon as an application is monitored. You can differ the display using —trigger. With this option the display will start only if one message satisfying one of the regular expressions specified with —trigger is encountered.

This is really useful when you need to understand what’s going on after you received or emit a particular message.

Filter threads

When using the option --thread=<thread koid> only the events from the specified thread are displayed. The option can be used several times to display several threads.

High level summary

Sometime, you don’t need to display all the messages exchanged but only a high level view of the session. The options --with=summary and --with=summary=&lt;path&gt; generate a high level summary of the session.

With those options, fidlcat displays a list of all the monitored processes.

For each process, fidlcat displays a list of all the handles found for the process.

For each handle, fidlcat displays the information we have about the process. That includes the data fidlcat has been able to infer. It also display if the handle is a startup handle (inherited while the process has been created) or a handle created during the process life.

For channels, fidlcat tries to display the other end of the channel (even if the other end is own by another process).

For non startup handles, fidlcat displays how the handle was created:

  • by calling zx_channel_create, zx_port_create, zx_timer_create, …

  • by receiving a handle within a message.

Then fidlcat displays a list of all the messages sent and received (only for channels).

Finally fidlcat displays how the handle was closed:

  • by calling zx_handle_close or zx_handle_close_many.

  • by sending the handle to another process.

If fidlcat doesn’t display that a handle is closed, that probably means that the program forgot to close it.

In addition to --with=summary you can use --stack=2. In that case, the stack frame is displayed for each channel creation.

Continuous monitoring

By default, fidlcat ends when all the monitored processes are ended.

With the option --stay-alive, fidlcat doesn’t automatically end (which means a control-c to end it).

This is useful to monitor a service you want to restart. When launched, fidlcat will monitor the current version of the service. When the service is restarted, fidlcat stops monitoring the old process and then automatically monitors the new process. This way you can have all the messages exchanged when the service is restarted.

Top protocols

The options --with=top and --with=top=&lt;path&gt; generate a view that groups the output by process, protocol, and method. The groups are sorted by number of events, so groups with more associated events are listed earlier.

Group by thread

The options --with=group-by-thread and --with=group-by-thread=&lt;path&gt; generate a view that, for each thread, displays a short version of all the events.