matrix-rust-sdk

public

Star0

Watch0

46 commits 4 branches 0 tags 0 releases16.6 MiB

use std::{
    collections::BTreeMap,
    fs,
    io::{self, BufRead, Write},
    ops::Sub,
    path,
    time::Duration,
};

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>[^"]+)"

                # Since https://github.com/matrix-org/matrix-rust-sdk/pull/6118,
                # we have `pos` and `timeout`. We must consider they are
                # optional.
                (
                    .*?
                    (\spos="(?<pos>[^"]+)")?
                    \stimeout=(?<timeout>\d+)
                )?
            \}

            # 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` 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 pos = captures.name("pos").map(|pos| pos.as_str());
            let timeout = captures.name("timeout").and_then(|timeout| {
                timeout.as_str().parse::<u64>().ok().map(Duration::from_millis)
            });
            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").and_then(|status| status.as_str().parse().ok());

            if let Some(smallest_start_at_inner) = smallest_start_at {
                if smallest_start_at_inner > date_time {
                    smallest_start_at = Some(date_time);
                }
            } else {
                smallest_start_at = Some(date_time);
            }

            if let Some(largest_end_at_inner) = largest_end_at {
                if largest_end_at_inner < date_time {
                    largest_end_at = Some(date_time);
                }
            } else {
                largest_end_at = Some(date_time);
            }

            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(),
                        pos: pos.map(ToOwned::to_owned),
                        timeout,
                        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 {
                        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()
        .flat_map(|(connection_id, spans)| {
            spans.iter().map(
                |(
                    request_id,
                    Span {
                        status,
                        method,
                        uri,
                        pos,
                        timeout,
                        request_size,
                        response_size,
                        start_at,
                        duration,
                        request_log_line,
                        response_log_line
                    },
                )| {
                    let uri = Url::parse(uri);
                    let duration = duration.num_milliseconds().unsigned_abs();
                    let timeout: Option<u64> = timeout.map(|timeout| timeout.as_millis().try_into().expect("Failed to cast a u128 to u64"));

                    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>{timeout_label}</td>
      <td>{request_size}</td>
      <td>{response_size}</td>
      <td><time datetime=\"{date_time}\">{time}</time></td>
      <td>
        <div class=\"span\" style=\"--start-at: {start_at}; --timeout: {timeout}; --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>
            <li>Sliding Sync <code>pos</code>: <span class=\"text-overflow\">{pos}</span></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(),
                        timeout_label = timeout
                            .map(|timeout| format!("{timeout}ms"))
                            .unwrap_or_else(|| "(unknown)".to_owned()),
                        timeout = timeout
                            .map(|timeout| {
                                // The response was received before hitting the timeout.
                                if duration < timeout {
                                    0
                                } else {
                                    timeout
                                }
                            })
                            .unwrap_or(0),
                        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()),
                        date_time = start_at.format("%+"),
                        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()),
                        pos = pos.clone().unwrap_or_else(|| "(unknown)".to_owned())
                    )
                },
            )
        })
        .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,
    pos: Option<String>,
    timeout: Option<Duration>,
    request_size: Option<String>,
    response_size: Option<String>,
    start_at: DateTime<FixedOffset>,
    duration: TimeDelta,
    request_log_line: usize,
    response_log_line: Option<usize>,
}

1	use std::{
2	collections::BTreeMap,
3	fs,
4	io::{self, BufRead, Write},
5	ops::Sub,
6	path,
7	time::Duration,
8	};
9
10	use chrono::{DateTime, FixedOffset, TimeDelta};
11	use indexmap::{IndexMap, map::Entry};
12	use regex::RegexBuilder;
13	use url::{Position as UrlPosition, Url};
14
15	use crate::Result;
16
17	const OUTPUT_TEMPLATE: &str = include_str!("sync.template.html");
18
19	pub(super) fn run(log_path: path::PathBuf, output_path: path::PathBuf) -> Result<()> {
20	let find_sync = RegexBuilder::new(
21	r#"
22	# Datetime of the log line.
23	(?<datetime>\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d+Z)
24
25	# Ensure it's about the `http_client` scope.
26	.*matrix_sdk::http_client
27
28	# Ensure it's about a sync.
29	.*>\ssync_once\{
30	conn_id="(?<connection_id>[^"]+)"
31
32	# Since https://github.com/matrix-org/matrix-rust-sdk/pull/6118,
33	# we have `pos` and `timeout`. We must consider they are
34	# optional.
35	(
36	.*?
37	(\spos="(?<pos>[^"]+)")?
38	\stimeout=(?<timeout>\d+)
39	)?
40	\}
41
42	# Let's capture some data about `send()`!
43	\s>\ssend\{
44	request_id="REQ-(?<request_id>\d+)"
45	\smethod=(?<method>\S+)
46	\suri="(?<uri>[^"]+)"
47	# If there is a `request_size`.
48	(.*\srequest_size="(?<request_size>[^"]+)")?
49	# If this is a response, there is a `status`.
50	(.*\sstatus=(?<status>\d+))?
51	# If there is a `response_size`.
52	(.*\sresponse_size="(?<response_size>[^"]+)")?
53	"#,
54	)
55	.ignore_whitespace(true)
56	.build()
57	.expect("Failed to build the `find_sync` regex");
58
59	let log_file = fs::File::open(&log_path)?;
60	let mut output_file = fs::File::create(&output_path)?;
61
62	let reader = io::BufReader::new(log_file);
63	let mut number_of_analysed_lines = 0;
64	let mut number_of_matched_lines = 0;
65	let mut smallest_start_at = None;
66	let mut largest_end_at = None;
67
68	let mut spans: BTreeMap<ConnectionId, IndexMap<RequestId, Span>> = BTreeMap::new();
69
70	for (line_nth, line) in reader.lines().enumerate().map(\|(nth, line)\| {
71	(
72	nth + 1,
73	line.unwrap_or_else(\|error\| {
74	panic!("Failed to read line #{nth}\n{error}");
75	}),
76	)
77	}) {
78	number_of_analysed_lines += 1;
79
80	if let Some(captures) = find_sync.captures(&line) {
81	number_of_matched_lines += 1;
82
83	let date_time = DateTime::parse_from_rfc3339(
84	captures.name("datetime").expect("Failed to capture `datetime`").as_str(),
85	)
86	.expect("Failed to parse `datetime`");
87	let connection_id =
88	captures.name("connection_id").expect("Failed to capture `connection_id`").as_str();
89	let pos = captures.name("pos").map(\|pos\| pos.as_str());
90	let timeout = captures.name("timeout").and_then(\|timeout\| {
91	timeout.as_str().parse::<u64>().ok().map(Duration::from_millis)
92	});
93	let request_id = captures
94	.name("request_id")
95	.expect("Failed to capture `request_id`")
96	.as_str()
97	.parse()
98	.expect("Failed to parse `request_id`");
99	let method = captures.name("method").expect("Failed to capture `method`").as_str();
100	let uri = captures.name("uri").expect("Failed to capture `uri`").as_str();
101	let request_size =
102	captures.name("request_size").map(\|request_size\| request_size.as_str());
103	let response_size =
104	captures.name("response_size").map(\|response_size\| response_size.as_str());
105	let status = captures.name("status").and_then(\|status\| status.as_str().parse().ok());
106
107	if let Some(smallest_start_at_inner) = smallest_start_at {
108	if smallest_start_at_inner > date_time {
109	smallest_start_at = Some(date_time);
110	}
111	} else {
112	smallest_start_at = Some(date_time);
113	}
114
115	if let Some(largest_end_at_inner) = largest_end_at {
116	if largest_end_at_inner < date_time {
117	largest_end_at = Some(date_time);
118	}
119	} else {
120	largest_end_at = Some(date_time);
121	}
122
123	let spans_for_connection_id = spans.entry(connection_id.to_owned()).or_default();
124
125	match spans_for_connection_id.entry(request_id) {
126	Entry::Vacant(entry) => {
127	entry.insert(Span {
128	status: None,
129	method: method.to_owned(),
130	uri: uri.to_owned(),
131	pos: pos.map(ToOwned::to_owned),
132	timeout,
133	request_size: request_size.map(ToOwned::to_owned),
134	response_size: response_size.map(ToOwned::to_owned),
135	start_at: date_time,
136	duration: TimeDelta::zero(),
137	request_log_line: line_nth,
138	response_log_line: None,
139	});
140	}
141	Entry::Occupied(mut entry) => {
142	let span = entry.get_mut();
143
144	if let Some(status) = status {
145	span.status = Some(status);
146	}
147
148	span.duration = date_time.sub(&span.start_at);
149
150	if let Some(request_size) = request_size {
151	span.request_size = Some(request_size.to_owned());
152	}
153
154	if let Some(response_size) = response_size {
155	span.response_size = Some(response_size.to_owned());
156	}
157
158	span.response_log_line = Some(line_nth);
159	}
160	}
161	}
162	}
163
164	let smallest_start_at =
165	smallest_start_at.map(\|date_time\| date_time.timestamp_millis()).unwrap_or_default();
166	let largest_end_at =
167	largest_end_at.map(\|date_time\| date_time.timestamp_millis()).unwrap_or_default();
168	let end_at = largest_end_at.saturating_sub(smallest_start_at).to_string();
169	let rows = spans
170	.iter()
171	.flat_map(\|(connection_id, spans)\| {
172	spans.iter().map(
173	\|(
174	request_id,
175	Span {
176	status,
177	method,
178	uri,
179	pos,
180	timeout,
181	request_size,
182	response_size,
183	start_at,
184	duration,
185	request_log_line,
186	response_log_line
187	},
188	)\| {
189	let uri = Url::parse(uri);
190	let duration = duration.num_milliseconds().unsigned_abs();
191	let timeout: Option<u64> = timeout.map(\|timeout\| timeout.as_millis().try_into().expect("Failed to cast a u128 to u64"));
192
193	format!(
194	" <tr id=\"{connection_id}-{request_id}\">
195	<td><code>{connection_id}</code></td>
196	<td><a href=\"#{connection_id}-{request_id}\" title=\"Permalink to this line\"><code>{request_id}</code></a></td>
197	<td data-status-family=\"{status_family}\"><span>{status}</span></td>
198	<td><code>{method}</code></td>
199	<td title=\"{domain}\">{domain}</td>
200	<td title=\"{path}\">{path}</td>
201	<td>{timeout_label}</td>
202	<td>{request_size}</td>
203	<td>{response_size}</td>
204	<td><time datetime=\"{date_time}\">{time}</time></td>
205	<td>
206	<div class=\"span\" style=\"--start-at: {start_at}; --timeout: {timeout}; --duration: {duration}\"><span>{duration_label}</span></div>
207	<details>
208	<summary><span class=\"hidden\">information</span></summary>
209	<ul>
210	<li>Request log line number: {request_log_line}</li>
211	<li>Response log line number: {response_log_line}</li>
212	<li>Sliding Sync <code>pos</code>: <span class=\"text-overflow\">{pos}</span></li>
213	</ul>
214	</details>
215	</td>
216	</tr>
217	",
218	connection_id = connection_id.clone(),
219	status = status
220	.map(\|status\| status.to_string())
221	.unwrap_or_else(\|\| "×".to_owned()),
222	status_family = status
223	.map(\|status\| (if status > 0 { status / 100 } else { 0 } ).to_string())
224	.unwrap_or_else(\|\| "cancelled".to_owned()),
225	domain = uri
226	.as_ref()
227	.map(\|uri\| uri[UrlPosition::BeforeHost..UrlPosition::BeforePath].to_owned())
228	.unwrap_or_default(),
229	path = uri
230	.as_ref()
231	.map(\|uri\| uri[UrlPosition::BeforePath..].to_owned())
232	.unwrap_or_default(),
233	timeout_label = timeout
234	.map(\|timeout\| format!("{timeout}ms"))
235	.unwrap_or_else(\|\| "(unknown)".to_owned()),
236	timeout = timeout
237	.map(\|timeout\| {
238	// The response was received before hitting the timeout.
239	if duration < timeout {
240	0
241	} else {
242	timeout
243	}
244	})
245	.unwrap_or(0),
246	request_size = request_size
247	.clone()
248	.map(\|request_size\| request_size.to_string())
249	.unwrap_or_else(\|\| "".to_owned()),
250	response_size = response_size
251	.clone()
252	.map(\|response_size\| response_size.to_string())
253	.unwrap_or_else(\|\| "".to_owned()),
254	date_time = start_at.format("%+"),
255	time = start_at.format("%H:%M:%S%.3f"),
256	start_at = start_at
257	.timestamp_millis()
258	.saturating_sub(smallest_start_at),
259	duration_label = if duration > 0 { format!("{duration}ms") } else { "<em>cancelled</em>".to_owned() },
260	response_log_line = response_log_line.map(\|line\| line.to_string()).unwrap_or_else(\|\| "(none)".to_owned()),
261	pos = pos.clone().unwrap_or_else(\|\| "(unknown)".to_owned())
262	)
263	},
264	)
265	})
266	.collect::<String>();
267
268	let output = OUTPUT_TEMPLATE
269	.replace("{log_file}", &log_path.to_string_lossy())
270	.replace("{end_at}", &end_at)
271	.replace("{rows}", &rows);
272
273	output_file.write_all(output.as_bytes()).expect("Failed to write the output");
274
275	println!(
276	"\nNumber of analysed log lines: {number_of_analysed_lines}\n\
277	Number of matched lines: {number_of_matched_lines}\n\
278	Output file: {output_path:?}\n\
279	Done!"
280	);
281
282	Ok(())
283	}
284
285	type ConnectionId = String;
286	type RequestId = u32;
287
288	#[derive(Debug)]
289	struct Span {
290	status: Option<u8>,
291	method: String,
292	uri: String,
293	pos: Option<String>,
294	timeout: Option<Duration>,
295	request_size: Option<String>,
296	response_size: Option<String>,
297	start_at: DateTime<FixedOffset>,
298	duration: TimeDelta,
299	request_log_line: usize,
300	response_log_line: Option<usize>,
301	}