From cb273019846fac5e18d4b8f5422e9a44cff2d14c Mon Sep 17 00:00:00 2001 From: Alexander Tesfamichael Date: Tue, 10 Oct 2023 11:45:20 +0200 Subject: [PATCH] feat(inclusion_monitor): rewrite query and parse Rewrites how we query and parse the result from Loki. This version is more reliable and can expect only a single log line result. --- src/phoenix/inclusion_monitor/loki_client.rs | 78 ++--- .../test_data/payload_logs_7496729.json | 276 ++---------------- 2 files changed, 70 insertions(+), 284 deletions(-) diff --git a/src/phoenix/inclusion_monitor/loki_client.rs b/src/phoenix/inclusion_monitor/loki_client.rs index 6ad4bc1..648d740 100644 --- a/src/phoenix/inclusion_monitor/loki_client.rs +++ b/src/phoenix/inclusion_monitor/loki_client.rs @@ -13,50 +13,46 @@ pub struct PayloadLogStats { pub request_download_duration_ms: i64, } -fn date_time_from_timestamp( - request_finished_log: &serde_json::Value, - key: &str, -) -> anyhow::Result> { - request_finished_log[key] - .as_str() +fn extract_date_time(json_map: &serde_json::Value, key: &str) -> anyhow::Result> { + json_map + .get(key) + .and_then(|timestamp| timestamp.as_str()) .and_then(|timestamp| timestamp.parse::().ok()) .and_then(|timestamp| Utc.timestamp_millis_opt(timestamp).single()) - .with_context(|| format!("failed to parse {key} as timestamp from payload log")) + .with_context(|| { + format!( + "failed to parse {} as timestamp from payload published log", + key + ) + }) } +/// Takes the payload logs response and extracts the first log line. We rely on the query being +/// crafted in such a way that the oldest matching result is the one we're looking for. fn parse_log_response(text: &str) -> anyhow::Result> { let request_finished_log: serde_json::Value = { - let log_data: serde_json::Value = serde_json::from_str(text) + let log_response_json: serde_json::Value = serde_json::from_str(text) .context("failed to parse payload log request body as JSON")?; - // This is the array of parsed log lines and their raw values. - let results = log_data["data"]["result"] - .as_array() - .context("expected at least one log line in payload logs response")?; - - let log_data = results - .iter() - .find(|result| { - let stream = &result["stream"]; - let msg = stream["msg"].as_str().unwrap_or(""); - msg.contains("request finished") - }) - .map(|result| &result["stream"]) - .cloned(); - - match log_data { - Some(log_data) => log_data, - // If there are no logs, we stop here. - None => return Ok(None), - } + // See the tests for an example of the data. + log_response_json + // The rest is response metadata + .get("data") + // These are the lines, the rest is metadata about the lines + .and_then(|data| data.get("result")) + .and_then(|result| result.as_array()) + .and_then(|lines| lines.iter().next()) + // Each of these lines is expected to contain parsed JSON values in the `stream` field and + // raw values in the `values` field. + .and_then(|line| line.get("stream")) + .context("failed to get stream from payload published log") + .cloned()? }; - let received_at = date_time_from_timestamp(&request_finished_log, "timestampRequestStart")?; - let decoded_at = date_time_from_timestamp(&request_finished_log, "timestampAfterDecode")?; - let pre_publish_at = - date_time_from_timestamp(&request_finished_log, "timestampBeforePublishing")?; - let post_publish_at = - date_time_from_timestamp(&request_finished_log, "timestampAfterPublishing")?; + let received_at = extract_date_time(&request_finished_log, "timestampRequestStart")?; + let decoded_at = extract_date_time(&request_finished_log, "timestampAfterDecode")?; + let pre_publish_at = extract_date_time(&request_finished_log, "timestampBeforePublishing")?; + let post_publish_at = extract_date_time(&request_finished_log, "timestampAfterPublishing")?; let decoded_at_slot_age_ms = request_finished_log["msIntoSlot"] .as_str() .and_then(|s| s.parse::().ok()) @@ -98,12 +94,20 @@ impl LokiClient { } pub async fn payload_logs(&self, slot: &i32) -> anyhow::Result> { - let query = format!(r#"{{app="proposer-api"}} |= `"slot":{slot}` | json"#); + let query = format!( + r#"{{app="proposer-api"}} |= `"slot":{slot}` |= "block published through beacon node" | json"# + ); let since = "24h"; let url = format!("{}/loki/api/v1/query_range", self.server_url); - let url_with_params = - Url::parse_with_params(&url, &[("query", query.as_str()), ("since", since)])?; + let url_with_params = Url::parse_with_params( + &url, + &[ + ("direction", "forward"), + ("query", query.as_str()), + ("since", since), + ], + )?; let response = self.client.get(url_with_params).send().await?; let body = response.text().await?; diff --git a/src/phoenix/inclusion_monitor/test_data/payload_logs_7496729.json b/src/phoenix/inclusion_monitor/test_data/payload_logs_7496729.json index 2eb7b54..461ba68 100644 --- a/src/phoenix/inclusion_monitor/test_data/payload_logs_7496729.json +++ b/src/phoenix/inclusion_monitor/test_data/payload_logs_7496729.json @@ -3,48 +3,6 @@ "data": { "resultType": "streams", "result": [ - { - "stream": { - "app": "proposer-api", - "blockHash": "0x73bec1f6e7571247af2037120680a8a7e57fdbfc1d27202d619638141f0e0096", - "container": "proposer-api", - "contentLength": "81587", - "feeRecipient": "0x4675c7e5baafbffbca748158becba61ef3b0a263", - "filename": "/var/log/pods/default_proposer-api-cf64dbf6-wmz9h_5805ffc1-3abf-4e10-9468-1120c8add007/proposer-api/0.log", - "headSlot": "7496728", - "headSlotEpochPos": "25", - "idArg": "", - "job": "default/proposer-api", - "level": "info", - "level_extracted": "info", - "method": "getPayload", - "mevBoostV": "v1.6", - "msIntoSlot": "3625", - "msg": "getPayload request received", - "namespace": "default", - "node_name": "kate", - "pod": "proposer-api-cf64dbf6-wmz9h", - "proposerIndex": "138873", - "proposerPubkey": "0x8f94956dde1ba8d8a800163e0c654553a5e05eabebed8d443ffc5f52a77ffffc5ec69a14e406b4982371ddc96c007488", - "service": "relay/api", - "slot": "7496729", - "slotEpochPos": "26", - "slotStartSec": "1696784771", - "stream": "stdout", - "time": "2023-10-08T17:06:14.62824969Z", - "timestampAfterDecode": "1696784774625", - "timestampAfterSignatureVerify": "1696784774628", - "timestampRequestStart": "1696784773892", - "ua": "mev-boost/v1.6 Lighthouse/v4.3.0-dfcb336", - "version": "" - }, - "values": [ - [ - "1696784774628249690", - "{\"blockHash\":\"0x73bec1f6e7571247af2037120680a8a7e57fdbfc1d27202d619638141f0e0096\",\"contentLength\":81587,\"feeRecipient\":\"0x4675c7e5baafbffbca748158becba61ef3b0a263\",\"headSlot\":7496728,\"headSlotEpochPos\":25,\"idArg\":\"\",\"level\":\"info\",\"method\":\"getPayload\",\"mevBoostV\":\"v1.6\",\"msIntoSlot\":3625,\"msg\":\"getPayload request received\",\"proposerIndex\":138873,\"proposerPubkey\":\"0x8f94956dde1ba8d8a800163e0c654553a5e05eabebed8d443ffc5f52a77ffffc5ec69a14e406b4982371ddc96c007488\",\"service\":\"relay/api\",\"slot\":7496729,\"slotEpochPos\":26,\"slotStartSec\":1696784771,\"time\":\"2023-10-08T17:06:14.62824969Z\",\"timestampAfterDecode\":1696784774625,\"timestampAfterSignatureVerify\":1696784774628,\"timestampRequestStart\":1696784773892,\"ua\":\"mev-boost/v1.6 Lighthouse/v4.3.0-dfcb336\",\"version\":\"\"}" - ] - ] - }, { "stream": { "app": "proposer-api", @@ -91,209 +49,33 @@ "{\"blockHash\":\"0x73bec1f6e7571247af2037120680a8a7e57fdbfc1d27202d619638141f0e0096\",\"contentLength\":81587,\"feeRecipient\":\"0x4675c7e5baafbffbca748158becba61ef3b0a263\",\"headSlot\":7496728,\"headSlotEpochPos\":25,\"idArg\":\"\",\"level\":\"info\",\"method\":\"getPayload\",\"mevBoostV\":\"v1.6\",\"msIntoSlot\":3625,\"msNeededForPublishing\":647,\"msg\":\"block published through beacon node\",\"proposerIndex\":138873,\"proposerPubkey\":\"0x8f94956dde1ba8d8a800163e0c654553a5e05eabebed8d443ffc5f52a77ffffc5ec69a14e406b4982371ddc96c007488\",\"service\":\"relay/api\",\"slot\":7496729,\"slotEpochPos\":26,\"slotStartSec\":1696784771,\"time\":\"2023-10-08T17:06:15.285183899Z\",\"timestampAfterAlreadyDeliveredCheck\":1696784774635,\"timestampAfterDecode\":1696784774625,\"timestampAfterLoadResponse\":1696784774634,\"timestampAfterPublishing\":1696784775285,\"timestampAfterSignatureVerify\":1696784774628,\"timestampBeforePublishing\":1696784774638,\"timestampRequestStart\":1696784773892,\"ua\":\"mev-boost/v1.6 Lighthouse/v4.3.0-dfcb336\",\"version\":\"\"}" ] ] - }, - { - "stream": { - "app": "proposer-api", - "blockHash": "0x73bec1f6e7571247af2037120680a8a7e57fdbfc1d27202d619638141f0e0096", - "blockNumber": "18307137", - "container": "proposer-api", - "contentLength": "81587", - "feeRecipient": "0x4675c7e5baafbffbca748158becba61ef3b0a263", - "filename": "/var/log/pods/default_proposer-api-cf64dbf6-wmz9h_5805ffc1-3abf-4e10-9468-1120c8add007/proposer-api/0.log", - "headSlot": "7496728", - "headSlotEpochPos": "25", - "idArg": "", - "job": "default/proposer-api", - "level": "info", - "level_extracted": "info", - "method": "getPayload", - "mevBoostV": "v1.6", - "msIntoSlot": "3625", - "msg": "request finished", - "namespace": "default", - "node_name": "kate", - "numTx": "196", - "pod": "proposer-api-cf64dbf6-wmz9h", - "proposerIndex": "138873", - "proposerPubkey": "0x8f94956dde1ba8d8a800163e0c654553a5e05eabebed8d443ffc5f52a77ffffc5ec69a14e406b4982371ddc96c007488", - "requestDurationMs": "2425", - "service": "relay/api", - "slot": "7496729", - "slotEpochPos": "26", - "slotStartSec": "1696784771", - "stream": "stdout", - "time": "2023-10-08T17:06:16.318189593Z", - "timestampAfterAlreadyDeliveredCheck": "1696784774635", - "timestampAfterDecode": "1696784774625", - "timestampAfterLoadResponse": "1696784774634", - "timestampAfterPublishing": "1696784775285", - "timestampAfterSignatureVerify": "1696784774628", - "timestampBeforePublishing": "1696784774638", - "timestampRequestFin": "1696784776318", - "timestampRequestStart": "1696784773892", - "ua": "mev-boost/v1.6 Lighthouse/v4.3.0-dfcb336", - "version": "" - }, - "values": [ - [ - "1696784776318189593", - "{\"blockHash\":\"0x73bec1f6e7571247af2037120680a8a7e57fdbfc1d27202d619638141f0e0096\",\"blockNumber\":18307137,\"contentLength\":81587,\"feeRecipient\":\"0x4675c7e5baafbffbca748158becba61ef3b0a263\",\"headSlot\":7496728,\"headSlotEpochPos\":25,\"idArg\":\"\",\"level\":\"info\",\"method\":\"getPayload\",\"mevBoostV\":\"v1.6\",\"msIntoSlot\":3625,\"msg\":\"request finished\",\"numTx\":196,\"proposerIndex\":138873,\"proposerPubkey\":\"0x8f94956dde1ba8d8a800163e0c654553a5e05eabebed8d443ffc5f52a77ffffc5ec69a14e406b4982371ddc96c007488\",\"requestDurationMs\":2425,\"service\":\"relay/api\",\"slot\":7496729,\"slotEpochPos\":26,\"slotStartSec\":1696784771,\"time\":\"2023-10-08T17:06:16.318189593Z\",\"timestampAfterAlreadyDeliveredCheck\":1696784774635,\"timestampAfterDecode\":1696784774625,\"timestampAfterLoadResponse\":1696784774634,\"timestampAfterPublishing\":1696784775285,\"timestampAfterSignatureVerify\":1696784774628,\"timestampBeforePublishing\":1696784774638,\"timestampRequestFin\":1696784776318,\"timestampRequestStart\":1696784773892,\"ua\":\"mev-boost/v1.6 Lighthouse/v4.3.0-dfcb336\",\"version\":\"\"}" - ] - ] - }, - { - "stream": { - "app": "proposer-api", - "blockHash": "0x73bec1f6e7571247af2037120680a8a7e57fdbfc1d27202d619638141f0e0096", - "blockNumber": "18307137", - "container": "proposer-api", - "contentLength": "81587", - "feeRecipient": "0x4675c7e5baafbffbca748158becba61ef3b0a263", - "filename": "/var/log/pods/default_proposer-api-cf64dbf6-wmz9h_5805ffc1-3abf-4e10-9468-1120c8add007/proposer-api/0.log", - "headSlot": "7496728", - "headSlotEpochPos": "25", - "idArg": "", - "job": "default/proposer-api", - "level": "info", - "level_extracted": "info", - "method": "getPayload", - "mevBoostV": "v1.6", - "msIntoSlot": "3625", - "msg": "no demotion in getPayload, successful block proposal", - "namespace": "default", - "node_name": "kate", - "numTx": "196", - "pod": "proposer-api-cf64dbf6-wmz9h", - "proposerIndex": "138873", - "proposerPubkey": "0x8f94956dde1ba8d8a800163e0c654553a5e05eabebed8d443ffc5f52a77ffffc5ec69a14e406b4982371ddc96c007488", - "service": "relay/api", - "slot": "7496729", - "slotEpochPos": "26", - "slotStartSec": "1696784771", - "stream": "stdout", - "time": "2023-10-08T17:06:16.321953648Z", - "timestampAfterAlreadyDeliveredCheck": "1696784774635", - "timestampAfterDecode": "1696784774625", - "timestampAfterLoadResponse": "1696784774634", - "timestampAfterPublishing": "1696784775285", - "timestampAfterSignatureVerify": "1696784774628", - "timestampBeforePublishing": "1696784774638", - "timestampRequestStart": "1696784773892", - "ua": "mev-boost/v1.6 Lighthouse/v4.3.0-dfcb336", - "version": "" - }, - "values": [ - [ - "1696784776321953648", - "{\"blockHash\":\"0x73bec1f6e7571247af2037120680a8a7e57fdbfc1d27202d619638141f0e0096\",\"blockNumber\":18307137,\"contentLength\":81587,\"feeRecipient\":\"0x4675c7e5baafbffbca748158becba61ef3b0a263\",\"headSlot\":7496728,\"headSlotEpochPos\":25,\"idArg\":\"\",\"level\":\"info\",\"method\":\"getPayload\",\"mevBoostV\":\"v1.6\",\"msIntoSlot\":3625,\"msg\":\"no demotion in getPayload, successful block proposal\",\"numTx\":196,\"proposerIndex\":138873,\"proposerPubkey\":\"0x8f94956dde1ba8d8a800163e0c654553a5e05eabebed8d443ffc5f52a77ffffc5ec69a14e406b4982371ddc96c007488\",\"service\":\"relay/api\",\"slot\":7496729,\"slotEpochPos\":26,\"slotStartSec\":1696784771,\"time\":\"2023-10-08T17:06:16.321953648Z\",\"timestampAfterAlreadyDeliveredCheck\":1696784774635,\"timestampAfterDecode\":1696784774625,\"timestampAfterLoadResponse\":1696784774634,\"timestampAfterPublishing\":1696784775285,\"timestampAfterSignatureVerify\":1696784774628,\"timestampBeforePublishing\":1696784774638,\"timestampRequestStart\":1696784773892,\"ua\":\"mev-boost/v1.6 Lighthouse/v4.3.0-dfcb336\",\"version\":\"\"}" - ] - ] - }, - { - "stream": { - "app": "proposer-api", - "blockHash": "0x73bec1f6e7571247af2037120680a8a7e57fdbfc1d27202d619638141f0e0096", - "blockNumber": "18307137", - "container": "proposer-api", - "contentLength": "81587", - "feeRecipient": "0x4675c7e5baafbffbca748158becba61ef3b0a263", - "filename": "/var/log/pods/default_proposer-api-cf64dbf6-wmz9h_5805ffc1-3abf-4e10-9468-1120c8add007/proposer-api/0.log", - "headSlot": "7496728", - "headSlotEpochPos": "25", - "idArg": "", - "job": "default/proposer-api", - "level": "info", - "level_extracted": "info", - "method": "getPayload", - "metric_stream": "execution-payload-delivered", - "mevBoostV": "v1.6", - "msIntoSlot": "3625", - "msg": "execution payload delivered", - "namespace": "default", - "node_name": "kate", - "numTx": "196", - "pod": "proposer-api-cf64dbf6-wmz9h", - "proposerIndex": "138873", - "proposerPubkey": "0x8f94956dde1ba8d8a800163e0c654553a5e05eabebed8d443ffc5f52a77ffffc5ec69a14e406b4982371ddc96c007488", - "service": "relay/api", - "slot": "7496729", - "slotEpochPos": "26", - "slotStartSec": "1696784771", - "stream": "stdout", - "time": "2023-10-08T17:06:16.310283235Z", - "timestampAfterAlreadyDeliveredCheck": "1696784774635", - "timestampAfterDecode": "1696784774625", - "timestampAfterLoadResponse": "1696784774634", - "timestampAfterPublishing": "1696784775285", - "timestampAfterSignatureVerify": "1696784774628", - "timestampBeforePublishing": "1696784774638", - "timestampRequestStart": "1696784773892", - "ua": "mev-boost/v1.6 Lighthouse/v4.3.0-dfcb336", - "version": "" - }, - "values": [ - [ - "1696784776310283235", - "{\"blockHash\":\"0x73bec1f6e7571247af2037120680a8a7e57fdbfc1d27202d619638141f0e0096\",\"blockNumber\":18307137,\"contentLength\":81587,\"feeRecipient\":\"0x4675c7e5baafbffbca748158becba61ef3b0a263\",\"headSlot\":7496728,\"headSlotEpochPos\":25,\"idArg\":\"\",\"level\":\"info\",\"method\":\"getPayload\",\"mevBoostV\":\"v1.6\",\"msIntoSlot\":3625,\"msg\":\"execution payload delivered\",\"numTx\":196,\"proposerIndex\":138873,\"proposerPubkey\":\"0x8f94956dde1ba8d8a800163e0c654553a5e05eabebed8d443ffc5f52a77ffffc5ec69a14e406b4982371ddc96c007488\",\"service\":\"relay/api\",\"slot\":7496729,\"slotEpochPos\":26,\"slotStartSec\":1696784771,\"time\":\"2023-10-08T17:06:16.310283235Z\",\"timestampAfterAlreadyDeliveredCheck\":1696784774635,\"timestampAfterDecode\":1696784774625,\"timestampAfterLoadResponse\":1696784774634,\"timestampAfterPublishing\":1696784775285,\"timestampAfterSignatureVerify\":1696784774628,\"timestampBeforePublishing\":1696784774638,\"timestampRequestStart\":1696784773892,\"ua\":\"mev-boost/v1.6 Lighthouse/v4.3.0-dfcb336\",\"version\":\"\"}" - ] - ] - }, - { - "stream": { - "app": "proposer-api", - "beacon": "http://10.0.0.1:3500", - "blockHash": "0x73bec1f6e7571247af2037120680a8a7e57fdbfc1d27202d619638141f0e0096", - "component": "beaconClient", - "container": "proposer-api", - "filename": "/var/log/pods/default_proposer-api-cf64dbf6-wmz9h_5805ffc1-3abf-4e10-9468-1120c8add007/proposer-api/0.log", - "job": "default/proposer-api", - "level": "info", - "level_extracted": "info", - "msg": "published block", - "namespace": "default", - "node_name": "kate", - "pod": "proposer-api-cf64dbf6-wmz9h", - "service": "relay/api", - "slot": "7496729", - "statusCode": "200", - "stream": "stdout", - "time": "2023-10-08T17:06:15.285144063Z", - "version": "" - }, - "values": [ - [ - "1696784775285144063", - "{\"beacon\":\"http://10.0.0.1:3500\",\"blockHash\":\"0x73bec1f6e7571247af2037120680a8a7e57fdbfc1d27202d619638141f0e0096\",\"component\":\"beaconClient\",\"level\":\"info\",\"msg\":\"published block\",\"service\":\"relay/api\",\"slot\":7496729,\"statusCode\":200,\"time\":\"2023-10-08T17:06:15.285144063Z\",\"version\":\"\"}" - ] - ] } ], "stats": { "summary": { - "bytesProcessedPerSecond": 230885010, - "linesProcessedPerSecond": 785906, - "totalBytesProcessed": 67432281, - "totalLinesProcessed": 229532, - "execTime": 0.29206, - "queueTime": 0.000567, + "bytesProcessedPerSecond": 339288704, + "linesProcessedPerSecond": 1162829, + "totalBytesProcessed": 127584551, + "totalLinesProcessed": 437265, + "execTime": 0.376035, + "queueTime": 0.000848, "subqueries": 0, - "totalEntriesReturned": 6, - "splits": 97, - "shards": 3 + "totalEntriesReturned": 1, + "splits": 193, + "shards": 4 }, "querier": { "store": { - "totalChunksRef": 48, - "totalChunksDownloaded": 48, - "chunksDownloadTime": 67631518, + "totalChunksRef": 95, + "totalChunksDownloaded": 95, + "chunksDownloadTime": 506314604, "chunk": { "headChunkBytes": 0, "headChunkLines": 0, - "decompressedBytes": 67432281, - "decompressedLines": 229532, - "compressedBytes": 5421475, - "totalDuplicates": 2 + "decompressedBytes": 127584551, + "decompressedLines": 437265, + "compressedBytes": 10312251, + "totalDuplicates": 0 } } }, @@ -318,13 +100,13 @@ }, "cache": { "chunk": { - "entriesFound": 44, - "entriesRequested": 48, - "entriesStored": 4, - "bytesReceived": 16970760, - "bytesSent": 244499, - "requests": 3, - "downloadTime": 28564786 + "entriesFound": 46, + "entriesRequested": 95, + "entriesStored": 49, + "bytesReceived": 1053238, + "bytesSent": 36044743, + "requests": 5, + "downloadTime": 5628161 }, "index": { "entriesFound": 0, @@ -336,13 +118,13 @@ "downloadTime": 0 }, "result": { - "entriesFound": 94, - "entriesRequested": 95, - "entriesStored": 0, - "bytesReceived": 9218, + "entriesFound": 189, + "entriesRequested": 191, + "entriesStored": 1, + "bytesReceived": 26655, "bytesSent": 0, - "requests": 95, - "downloadTime": 101725232 + "requests": 192, + "downloadTime": 271432420 } } }