feat(xtask): Introduce xtask log sync to visualise logs about sync.

This patch introduces a new family of commands: `xtask log`. The goal
is to manipulate logs, to extract the right amount of data we need to
solve specific problems. The first member of this family is `sync` to
visualise logs about the sync process. It presents the sync requests and
responses in a table, with a "timeline" _à la_ network profiler graph.
The code is rather simple, on purpose. The generated HTML reports are
lightweight, and fully standalone: no JavaScript, pure HTML and CSS, no
external resources. These reports can be shared or archived super
easily.

Features:

- requests/responses are grouped by connection ID
- permalink to specific request ID
- status have colours
- time is displayed in a human form
- duration is calculated from the log timestamps
- view syncs in a "tree-like" flavor, a "time graph", super quick to
  spot long requests
- each line can be "opened" to see details, so far only log line numbers
  to get more context manually
This commit is contained in:
Ivan Enderlin
2026-01-29 12:06:07 +01:00
parent 87ce49e14f
commit 43e1932691
6 changed files with 658 additions and 0 deletions
Generated
+3
View File
@@ -7444,12 +7444,15 @@ name = "xtask"
version = "0.1.0"
dependencies = [
"camino",
"chrono",
"clap",
"fs_extra",
"indexmap",
"regex",
"serde",
"serde_json",
"uniffi_bindgen",
"url",
"xshell",
]
+3
View File
@@ -14,10 +14,13 @@ test = false
[dependencies]
camino = "1.0.8"
chrono.workspace = true
clap = { version = "4.0.18", features = ["derive"] }
fs_extra = "1"
indexmap.workspace = true
regex = "1"
serde = { workspace = true, features = ["derive"] }
serde_json.workspace = true
uniffi_bindgen.workspace = true
url.workspace = true
xshell = "0.2.2"
+39
View File
@@ -0,0 +1,39 @@
use std::path::PathBuf;
use clap::{Args, Subcommand};
mod sync;
use crate::{Result, sh, workspace};
#[derive(Args)]
pub struct LogArgs {
#[clap(subcommand)]
cmd: LogCommand,
}
#[derive(Subcommand)]
enum LogCommand {
/// Visualise the sync requests and responses.
Sync {
#[clap(long)]
log_file: PathBuf,
#[clap(long)]
html_output_file: PathBuf,
},
}
impl LogArgs {
pub fn run(self) -> Result<()> {
let sh = sh();
let _p = sh.push_dir(workspace::root_path()?);
match self.cmd {
LogCommand::Sync { log_file, html_output_file } => {
sync::run(log_file, html_output_file)?
}
}
Ok(())
}
}
+264
View File
@@ -0,0 +1,264 @@
use std::{
collections::BTreeMap,
fs,
io::{self, BufRead, Write},
ops::Sub,
path,
};
use chrono::{DateTime, FixedOffset, TimeDelta};
use indexmap::{IndexMap, map::Entry};
use regex::RegexBuilder;
use url::{Position as UrlPosition, Url};
use crate::Result;
const OUTPUT_TEMPLATE: &str = include_str!("sync.template.html");
pub(super) fn run(log_path: path::PathBuf, output_path: path::PathBuf) -> Result<()> {
let find_sync = RegexBuilder::new(
r#"
# Datetime of the log line.
(?<datetime>\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d+Z)
# Ensure it's about the `http_client` scope.
.*matrix_sdk::http_client
# Ensure it's about a sync.
.*>\ssync_once\{conn_id="(?<connection_id>[^"]+)"\}
# Let's capture some data about `send()`!
\s>\ssend\{
request_id="REQ-(?<request_id>\d+)"
\smethod=(?<method>\S+)
\suri="(?<uri>[^"]+)"
# If there is a `request_size`.
(.*\srequest_size="(?<request_size>[^"]+)")?
# If this is a response, there is a `status`.
(.*\sstatus=(?<status>\d+))?
# If there is a `response_size`.
(.*\sresponse_size="(?<response_size>[^"]+)")?
"#,
)
.ignore_whitespace(true)
.build()
.expect("Failed to build the `find_sync_start regex`");
let log_file = fs::File::open(&log_path)?;
let mut output_file = fs::File::create(&output_path)?;
let reader = io::BufReader::new(log_file);
let mut number_of_analysed_lines = 0;
let mut number_of_matched_lines = 0;
let mut smallest_start_at = None;
let mut largest_end_at = None;
let mut spans: BTreeMap<ConnectionId, IndexMap<RequestId, Span>> = BTreeMap::new();
for (line_nth, line) in reader.lines().enumerate().map(|(nth, line)| {
(
nth + 1,
line.unwrap_or_else(|error| {
panic!("Failed to read line #{nth}\n{error}");
}),
)
}) {
number_of_analysed_lines += 1;
if let Some(captures) = find_sync.captures(&line) {
number_of_matched_lines += 1;
let date_time = DateTime::parse_from_rfc3339(
captures.name("datetime").expect("Failed to capture `datetime`").as_str(),
)
.expect("Failed to parse `datetime`");
let connection_id =
captures.name("connection_id").expect("Failed to capture `connection_id`").as_str();
let request_id = captures
.name("request_id")
.expect("Failed to capture `request_id`")
.as_str()
.parse()
.expect("Failed to parse `request_id`");
let method = captures.name("method").expect("Failed to capture `method`").as_str();
let uri = captures.name("uri").expect("Failed to capture `uri`").as_str();
let request_size =
captures.name("request_size").map(|request_size| request_size.as_str());
let response_size =
captures.name("response_size").map(|response_size| response_size.as_str());
let status = captures.name("status").map(|status| status.as_str());
if let Some(smallest_start_at_inner) = smallest_start_at {
if smallest_start_at_inner > date_time {
smallest_start_at = Some(date_time.clone());
}
} else {
smallest_start_at = Some(date_time.clone());
}
if let Some(largest_end_at_inner) = largest_end_at {
if largest_end_at_inner < date_time {
largest_end_at = Some(date_time.clone());
}
} else {
largest_end_at = Some(date_time.clone());
}
let spans_for_connection_id = spans.entry(connection_id.to_owned()).or_default();
match spans_for_connection_id.entry(request_id) {
Entry::Vacant(entry) => {
entry.insert(Span {
status: None,
method: method.to_owned(),
uri: uri.to_owned(),
request_size: request_size.map(ToOwned::to_owned),
response_size: response_size.map(ToOwned::to_owned),
start_at: date_time,
duration: TimeDelta::zero(),
request_log_line: line_nth,
response_log_line: None,
});
}
Entry::Occupied(mut entry) => {
let span = entry.get_mut();
if let Some(status) = status {
if let Ok(status) = status.parse() {
span.status = Some(status);
}
}
span.duration = date_time.sub(&span.start_at);
if let Some(request_size) = request_size {
span.request_size = Some(request_size.to_owned());
}
if let Some(response_size) = response_size {
span.response_size = Some(response_size.to_owned());
}
span.response_log_line = Some(line_nth);
}
}
}
}
let smallest_start_at =
smallest_start_at.map(|date_time| date_time.timestamp_millis()).unwrap_or_default();
let largest_end_at =
largest_end_at.map(|date_time| date_time.timestamp_millis()).unwrap_or_default();
let end_at = largest_end_at.saturating_sub(smallest_start_at).to_string();
let rows = spans
.iter()
.map(|(connection_id, spans)| {
spans.iter().map(
|(
request_id,
Span {
status,
method,
uri,
request_size,
response_size,
start_at,
duration,
request_log_line,
response_log_line
},
)| {
let uri = Url::parse(uri);
let duration = duration.num_milliseconds();
format!(
" <tr id=\"{connection_id}-{request_id}\">
<td><code>{connection_id}</code></td>
<td><a href=\"#{connection_id}-{request_id}\" title=\"Permalink to this line\"><code>{request_id}</code></a></td>
<td data-status-family=\"{status_family}\"><span>{status}</span></td>
<td><code>{method}</code></td>
<td title=\"{domain}\">{domain}</td>
<td title=\"{path}\">{path}</td>
<td>{request_size}</td>
<td>{response_size}</td>
<td>{time}</td>
<td>
<div class=\"span\" style=\"--start-at: {start_at}; --duration: {duration}\"><span>{duration_label}</span></div>
<details>
<summary><span class=\"hidden\">information</span></summary>
<ul>
<li>Request log line number: {request_log_line}</li>
<li>Response log line number: {response_log_line}</li>
</ul>
</details>
</td>
</tr>
",
connection_id = connection_id.clone(),
status = status
.map(|status| status.to_string())
.unwrap_or_else(|| "×".to_owned()),
status_family = status
.map(|status| (if status > 0 { status / 100 } else { 0 } ).to_string())
.unwrap_or_else(|| "cancelled".to_owned()),
domain = uri
.as_ref()
.map(|uri| uri[UrlPosition::BeforeHost..UrlPosition::BeforePath].to_owned())
.unwrap_or_default(),
path = uri
.as_ref()
.map(|uri| uri[UrlPosition::BeforePath..].to_owned())
.unwrap_or_default(),
request_size = request_size
.clone()
.map(|request_size| request_size.to_string())
.unwrap_or_else(|| "".to_owned()),
response_size = response_size
.clone()
.map(|response_size| response_size.to_string())
.unwrap_or_else(|| "".to_owned()),
time = start_at.format("%H:%M:%S%.3f"),
start_at = start_at
.timestamp_millis()
.saturating_sub(smallest_start_at),
duration_label = if duration > 0 { format!("{duration}ms") } else { "<em>cancelled</em>".to_owned() },
response_log_line = response_log_line.map(|line| line.to_string()).unwrap_or_else(|| "(none)".to_owned()),
)
},
)
})
.flatten()
.collect::<String>();
let output = OUTPUT_TEMPLATE
.replace("{log_file}", &log_path.to_string_lossy())
.replace("{end_at}", &end_at)
.replace("{rows}", &rows);
output_file.write_all(output.as_bytes()).expect("Failed to write the output");
println!(
"\nNumber of analysed log lines: {number_of_analysed_lines}\n\
Number of matched lines: {number_of_matched_lines}\n\
Output file: {output_path:?}\n\
Done!"
);
Ok(())
}
type ConnectionId = String;
type RequestId = u32;
#[derive(Debug)]
struct Span {
status: Option<u8>,
method: String,
uri: String,
request_size: Option<String>,
response_size: Option<String>,
start_at: DateTime<FixedOffset>,
duration: TimeDelta,
request_log_line: usize,
response_log_line: Option<usize>,
}
+345
View File
@@ -0,0 +1,345 @@
<!doctype html>
<html lang="en">
<head>
<meta http-equiv="content-type" content="text/html; charset=utf-8">
<meta http-equiv="content-security-policy" content="default-src 'self'; script-src 'unsafe-inline'; style-src 'unsafe-inline'; img-src data:">
<meta name="viewport" content="width=device-width, minimum-scale=1">
<style>
/* Reset */
*, *::before, *::after {
box-sizing: border-box;
}
* { margin: 0 }
input, button, textarea, select {
font: inherit;
color: currentColor;
}
:root {
--space-very-small: .25rem;
--space-small: .5rem;
--space: 1rem;
--space-large: 2rem;
--space-very-large: 4rem;
--border-radius: 3px;
--color-accent: oklch(59.1% .236 10.25);
--color-text: oklch(.84 0 0);
--color-canvas: oklch(0.258 0.007 285.867);
--color-canvas-lighter: oklch(0.303 0.007 285.966);
--color-canvas-lighter-2: oklch(0.343 0.009 285.935);
--color-canvas-lighter-3: oklch(0.6 0 0);
--color-green: oklch(0.524 0.164 145.0);
--color-red : oklch(0.503 0.172 25.0);
--color-orange: oklch(0.793 0.171 70.670);
--color-yellow: oklch(0.968 0.211 109.769);
}
.content-grid {
--padding-inline: 1rem;
--content-max-width: 70ch;
--breakout-max-width: 85ch;
--breakout-size: calc((var(--breakout-max-width) - var(--content-max-width)) / 2);
display: grid;
grid-template-columns:
[full-width-start]
minmax(var(--padding-inline), 1fr)
[breakout-start]
minmax(0, var(--breakout-size))
[content-start]
min(
100% - (var(--padding-inline) * 2),
var(--content-max-width)
)
[content-end]
minmax(0, var(--breakout-size))
[breakout-end]
minmax(var(--padding-inline), 1fr)
[full-width-end];
> * {
grid-column: content;
}
> .breakout {
grid-column: breakout;
}
> .full-width {
grid-column: full-width;
}
}
html {
scroll-padding-top: var(--space-very-large);
}
body {
font-size: .95rem;
/* Thanks modernfontstacks.com */
font-family: Inter, Roboto, 'Helvetica Neue', 'Arial Nova', 'Nimbus Sans', Arial, sans-serif;
font-weight: normal;
font-variant-numeric: proportional-nums slashed-zero;
color: var(--color-text);
background: var(--color-canvas);
scroll-behaviour: smooth;
}
header {
text-align: center;
text-wrap: balanced;
margin-block: var(--space) var(--space-large);
}
ul {
margin: 0;
padding: 0;
list-style-position: inside;
list-style-type: " ";
}
main > table {
width: 100%;
min-width: 1400px;
border-spacing: 0;
th, td {
white-space: nowrap;
padding: .15rem var(--space-small);
}
thead {
position: sticky;
top: 0;
z-index: 100;
background: oklch(from var(--color-canvas) l c h / .8);
backdrop-filter: blur(5px);
tr {
font-weight: bold;
height: 3em;
}
}
tbody > tr {
position: relative;
&:nth-child(even) {
background: var(--color-canvas-lighter);
}
&:hover {
z-index: 2;
outline: 1px var(--color-canvas-lighter-3) dashed;
outline-offset: var(--space-very-small);
border-radius: var(--border-radius);
}
&:target {
z-index: 2;
outline: 3px var(--color-yellow) solid;
outline-offset: .1rem;
border-radius: var(--border-radius);
}
/* request ID */
> :nth-child(2) {
text-align: end;
a {
color: inherit;
}
}
/* status */
> :nth-child(3) {
&[data-status-family] {
--_background: var(--color-red);
> span {
width: 3em;
display: inline-block;
text-align: center;
border-radius: var(--border-radius);
padding-inline: var(--space-very-small);
background-color: var(--_background, transparent);
}
}
&[data-status-family="cancelled"] {
color: var(--color-canvas);
font-weight: bold;
--_background: var(--color-orange);
}
&[data-status-family="2"] { --_background: var(--color-green) }
}
/* domain and path */
> :nth-child(5) { --_column-width: 15ch; --_dir: ltr }
> :nth-child(6) { --_column-width: 20ch; --_dir: rtl }
> :nth-child(5),
> :nth-child(6) {
direction: var(--_dir);
text-overflow: ellipsis;
max-width: var(--_column-width);
overflow: hidden;
}
/* request size and response size */
> :nth-child(7),
> :nth-child(8) {
text-align: end;
}
/* time */
> :nth-child(9) {
font-size: small;
font-variant-numeric: slashed-zero tabular-nums;
}
> :last-child {
--_end-at: var(--end-at, 100);
width: 100%;
--_grid-step: 15%;
--_grid-width: 2px;
background: linear-gradient(
90deg,
var(--color-canvas-lighter-2) var(--_grid-width),
transparent var(--_grid-width)
);
background-size: var(--_grid-step);
position: relative;
.span {
--_start-at: var(--start-at, 0);
--_duration: var(--duration);
--_background: var(--color-accent);
--_end-gutter: 10ch; /* spaces for the labels */
display: block;
position: absolute;
top: .15rem;
left: calc((var(--_start-at) * (100% - var(--_end-gutter))) / var(--_end-at));
width: max(1px, calc((var(--_duration) * (100% - var(--_end-gutter))) / var(--_end-at)));
height: 1.2rem;
background: var(--_background);
border-radius: var(--border-radius);
tr:has(> td[data-status-family="cancelled"]) & {
width: 3px;
--_background: var(--color-orange);
}
> span {
position: absolute;
font-size: .855em;
top: .1em;
left: calc(100% + var(--space-very-small));
}
}
details {
text-align: end;
summary {
pointer: cursor;
height: 1em;
width: 100%;
list-style: none;
&::marker,
&::-webkit-details-marker {
content: none; /* all browsers */
display: none; /* WebKit */
}
&::after {
position: absolute;
top: 0;
right: var(--space-small);
content: '+';
font-weight: bold;
}
}
&[open] {
margin-bottom: var(--space-small);
summary {
margin-bottom: var(--space-small);
&::after {
content: '' !important;
}
}
}
summary ~ * {
text-align: start;
font-size: small;
}
}
}
}
}
code {
/* Thanks modernfontstacks.com */
font-family: ui-monospace, 'Cascadia Code', 'Source Code Pro', Menlo, Consolas, 'DejaVu Sans Mono', monospace;
font-weight: normal;
font-size: .9em;
}
.hidden {
display: none;
}
</style>
<title>Network viewer</title>
</head>
<body class="content-grid">
<header>
<h1>Analyse of <code>{log_file}</code></h1>
</header>
<main class="full-width">
<table>
<thead>
<tr>
<th scope="col"><abbr title="Connection">Conn.</abbr> ID</th>
<th scope="col"><abbr title="Request">Req.</abbr> ID</th>
<th scope="col">Status</th>
<th scope="col"><abbr title="Method">Meth.</abbr></th>
<th scope="col">Domain</th>
<th scope="col">Path</th>
<th scope="col"><abbr title="Request">Req.</abbr> size</th>
<th scope="col"><abbr title="Response">Resp.</abbr> size</th>
<th scope="col">Time</th>
<th scope="col">Timeline</th>
</tr>
</thead>
<tbody style="--end-at: {end_at}">
{rows}
</tbody>
</table>
</main>
</body>
</html>
+4
View File
@@ -3,6 +3,7 @@
mod ci;
mod fixup;
mod kotlin;
mod log;
mod release;
mod swift;
mod workspace;
@@ -13,6 +14,7 @@ use ci::CiArgs;
use clap::{Parser, Subcommand};
use fixup::FixupArgs;
use kotlin::KotlinArgs;
use log::LogArgs;
use release::ReleaseArgs;
use swift::SwiftArgs;
use xshell::{Shell, cmd};
@@ -43,6 +45,7 @@ enum Command {
Release(ReleaseArgs),
Swift(SwiftArgs),
Kotlin(KotlinArgs),
Log(LogArgs),
}
fn main() -> Result<()> {
@@ -53,6 +56,7 @@ fn main() -> Result<()> {
Command::Swift(cfg) => cfg.run(),
Command::Kotlin(cfg) => cfg.run(),
Command::Release(cfg) => cfg.run(),
Command::Log(cfg) => cfg.run(),
}
}