Skip to content

Commit 7369776

Browse files
NicolappsConvex, Inc.
authored andcommitted
node-executor: Include logs in analyze error messages (#43582)
When `analyze` fails in isolate, we include the log messages: ``` ✖ Error fetching POST http://127.0.0.1:8000/api/deploy2/start_push 400 Bad Request: InvalidModules: Hit an error while pushing: Loading the pushed modules encountered the following error: Failed to analyze test.js: Uncaught Error: Uninformative error 'aaa' 'bbb' at <anonymous> (../convex/test.ts:4:37) ``` However, we’re not doing the same thing for Node modules: ``` ✖ Error fetching POST http://127.0.0.1:8000/api/deploy2/start_push 400 Bad Request: InvalidModules: Hit an error while pushing: Loading the pushed modules encountered the following error: Uncaught Failed to analyze test.js: Uninformative error at <anonymous> (../convex/test.ts:6:37) ``` This pull request changes the behavior of node-executor so that log messages are also included in the error message. This will be particularly helpful to debug issues with third-party packages that `console.error` + `process.exit` when an API key is missing. (The full support for `process.exit` is coming in #43563.) GitOrigin-RevId: c3121a1aba3082e9ce00091c36ff1a6533d1d5a7
1 parent 107f34a commit 7369776

File tree

1 file changed

+112
-9
lines changed

1 file changed

+112
-9
lines changed

crates/node_executor/src/executor.rs

Lines changed: 112 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -20,8 +20,10 @@ use common::{
2020
execution_context::ExecutionContext,
2121
knobs::NODE_ANALYZE_MAX_RETRIES,
2222
log_lines::{
23+
run_function_and_collect_log_lines,
2324
LogLine,
2425
LogLineStructured,
26+
LogLines,
2527
},
2628
runtime::Runtime,
2729
sha256::Sha256Digest,
@@ -38,6 +40,7 @@ use errors::{
3840
ErrorMetadataAnyhowExt,
3941
};
4042
use futures::{
43+
FutureExt,
4144
Stream,
4245
StreamExt,
4346
};
@@ -366,14 +369,23 @@ impl<RT: Runtime> Actions<RT> {
366369
result
367370
}
368371

369-
async fn invoke_analyze(&self, request: AnalyzeRequest) -> anyhow::Result<InvokeResponse> {
372+
async fn invoke_analyze(
373+
&self,
374+
request: AnalyzeRequest,
375+
) -> anyhow::Result<(InvokeResponse, LogLines)> {
370376
let mut backoff = Backoff::new(NODE_ANALYZE_INITIAL_BACKOFF, NODE_ANALYZE_MAX_BACKOFF);
371377
let mut retries = 0;
372378
loop {
373-
let (log_line_sender, _log_line_receiver) = mpsc::unbounded_channel();
379+
let (log_line_sender, log_line_receiver) = mpsc::unbounded_channel();
374380
let request = ExecutorRequest::Analyze(request.clone());
375-
match self.executor.invoke(request, log_line_sender).await {
376-
Ok(response) => return Ok(response),
381+
let (response, log_lines) = run_function_and_collect_log_lines(
382+
self.executor.invoke(request, log_line_sender).boxed(),
383+
log_line_receiver,
384+
|_| {},
385+
)
386+
.await;
387+
match response {
388+
Ok(response) => return Ok((response, log_lines)),
377389
Err(e) => {
378390
if retries >= *NODE_ANALYZE_MAX_RETRIES || e.is_deterministic_user_error() {
379391
return Err(e);
@@ -395,10 +407,13 @@ impl<RT: Runtime> Actions<RT> {
395407
) -> anyhow::Result<Result<BTreeMap<CanonicalizedModulePath, AnalyzedModule>, JsError>> {
396408
let timer = node_executor("analyze");
397409

398-
let InvokeResponse {
399-
response,
400-
aws_request_id,
401-
} = self.invoke_analyze(request).await?;
410+
let (
411+
InvokeResponse {
412+
response,
413+
aws_request_id,
414+
},
415+
log_lines,
416+
) = self.invoke_analyze(request).await?;
402417
let response: AnalyzeResponse = serde_json::from_value(response.clone()).map_err(|e| {
403418
anyhow::anyhow!(
404419
"Failed to deserialize analyze response: {}. Response: {}",
@@ -417,7 +432,7 @@ impl<RT: Runtime> Actions<RT> {
417432
AnalyzeResponse::Success { modules } => modules,
418433
AnalyzeResponse::Error { message, frames } => {
419434
let error = construct_js_error(message, "".to_string(), None, frames, source_maps)?;
420-
return Ok(Err(error));
435+
return Ok(Err(append_logs_to_error(error, log_lines)));
421436
},
422437
};
423438
let mut result = BTreeMap::new();
@@ -1007,3 +1022,91 @@ pub async fn handle_node_executor_stream(
10071022
.ok_or_else(|| anyhow::anyhow!("Received no result from node executor response"))?;
10081023
Ok(Ok(payload))
10091024
}
1025+
1026+
fn append_logs_to_error(mut error: JsError, log_lines: LogLines) -> JsError {
1027+
if log_lines.is_empty() {
1028+
return error;
1029+
}
1030+
1031+
let len = log_lines.len();
1032+
let logs_text = log_lines
1033+
.into_iter()
1034+
// Keep only the last 100 log entries
1035+
.skip(len.saturating_sub(100))
1036+
.flat_map(|l| l.to_pretty_strings())
1037+
.collect::<Vec<_>>()
1038+
.join("\n");
1039+
1040+
error.message = format!("{}\n\n{}", error.message, logs_text);
1041+
error
1042+
}
1043+
1044+
#[cfg(test)]
1045+
mod tests {
1046+
use common::{
1047+
errors::JsError,
1048+
log_lines::{
1049+
LogLevel,
1050+
LogLine,
1051+
LogLines,
1052+
},
1053+
runtime::UnixTimestamp,
1054+
};
1055+
1056+
use crate::executor::append_logs_to_error;
1057+
1058+
#[test]
1059+
fn test_append_logs_to_error() {
1060+
let error = JsError::from_message("Original error".to_string());
1061+
let log_lines = LogLines::from(vec![
1062+
LogLine::new_developer_log_line(
1063+
LogLevel::Info,
1064+
vec!["Log 1".to_string()],
1065+
UnixTimestamp::from_millis(1000),
1066+
),
1067+
LogLine::new_developer_log_line(
1068+
LogLevel::Error,
1069+
vec!["Log 2".to_string()],
1070+
UnixTimestamp::from_millis(1001),
1071+
),
1072+
]);
1073+
1074+
let error = append_logs_to_error(error, log_lines);
1075+
1076+
assert!(error.message.contains("Original error"));
1077+
assert!(error.message.contains("[INFO] Log 1"));
1078+
assert!(error.message.contains("[ERROR] Log 2"));
1079+
}
1080+
1081+
#[test]
1082+
fn test_append_logs_to_error_empty() {
1083+
let error = JsError::from_message("Original error".to_string());
1084+
let log_lines = LogLines::from(Vec::new());
1085+
1086+
let error = append_logs_to_error(error, log_lines);
1087+
1088+
assert_eq!(error.message, "Original error");
1089+
}
1090+
1091+
#[test]
1092+
fn test_append_logs_to_error_truncation() {
1093+
let error = JsError::from_message("Original error".to_string());
1094+
let mut logs = Vec::new();
1095+
for i in 0..110 {
1096+
logs.push(LogLine::new_developer_log_line(
1097+
LogLevel::Info,
1098+
vec![format!("Log {}", i)],
1099+
UnixTimestamp::from_millis(1000 + i as u64),
1100+
));
1101+
}
1102+
let log_lines = LogLines::from(logs);
1103+
1104+
let error = append_logs_to_error(error, log_lines);
1105+
1106+
assert!(error.message.contains("Original error"));
1107+
assert!(!error.message.contains("Log 0")); // Should be truncated
1108+
assert!(error.message.contains("Log 10")); // Should be present (last 100 start from index 10)
1109+
assert!(error.message.contains("Log 109")); // Last log should be
1110+
// present
1111+
}
1112+
}

0 commit comments

Comments
 (0)