Skip to content

Commit 650ff39

Browse files
sshaderConvex, Inc.
sshader
authored and
Convex, Inc.
committed
Log function execution on system errors (#24232)
We've decided we want to have entries in our function execution log even when functions fail due to system errors (i.e. errors that probably aren't the developer's fault). This adds this for actions (isolate, HTTP, and node). GitOrigin-RevId: f48493ef494531476537e1da60bba74db2eeb948
1 parent 0364e93 commit 650ff39

File tree

10 files changed

+657
-376
lines changed

10 files changed

+657
-376
lines changed

‎crates/application/src/application_function_runner/mod.rs‎

Lines changed: 133 additions & 84 deletions
Original file line numberDiff line numberDiff line change
@@ -92,6 +92,7 @@ use isolate::{
9292
ConcurrencyLimiter,
9393
FunctionOutcome,
9494
FunctionResult,
95+
HttpActionOutcome,
9596
HttpActionRequest,
9697
IsolateClient,
9798
IsolateConfig,
@@ -813,16 +814,15 @@ impl<RT: Runtime> ApplicationFunctionRunner<RT> {
813814
let (mut tx, mut outcome) = match result {
814815
Ok(r) => r,
815816
Err(e) => {
816-
self.log_udf_system_error(
817+
self.function_log.log_mutation_system_error(
818+
&e,
817819
udf_path,
818820
arguments,
819821
identity,
820822
start,
821823
caller,
822-
&e,
823824
context.clone(),
824-
)
825-
.await?;
825+
);
826826
return Err(e);
827827
},
828828
};
@@ -847,7 +847,6 @@ impl<RT: Runtime> ApplicationFunctionRunner<RT> {
847847
stats,
848848
execution_time,
849849
caller,
850-
false,
851850
usage_tracker,
852851
context.clone(),
853852
);
@@ -903,13 +902,11 @@ impl<RT: Runtime> ApplicationFunctionRunner<RT> {
903902
}
904903
outcome.result = Err(JsError::from_error_ref(&e));
905904

906-
self.function_log.log_mutation(
907-
outcome.clone(),
905+
self.function_log.log_mutation_occ_error(
906+
outcome,
908907
stats,
909908
execution_time,
910909
caller,
911-
true,
912-
usage_tracker,
913910
context.clone(),
914911
);
915912
log_occ_retries(backoff.failures() as usize);
@@ -923,7 +920,6 @@ impl<RT: Runtime> ApplicationFunctionRunner<RT> {
923920
stats,
924921
execution_time,
925922
caller,
926-
false,
927923
usage_tracker,
928924
context.clone(),
929925
);
@@ -1046,22 +1042,38 @@ impl<RT: Runtime> ApplicationFunctionRunner<RT> {
10461042
let context = ExecutionContext::new(request_id.clone(), &caller);
10471043
let name = name.canonicalize();
10481044
let usage_tracking = FunctionUsageTracker::new();
1049-
let completion = self
1045+
let start = self.runtime.monotonic_now();
1046+
let completion_result = self
10501047
.run_action_no_udf_log(
1051-
name,
1052-
arguments,
1048+
name.clone(),
1049+
arguments.clone(),
10531050
identity.clone(),
10541051
allowed_visibility,
1055-
caller,
1052+
caller.clone(),
10561053
usage_tracking.clone(),
1057-
context,
1054+
context.clone(),
10581055
)
1059-
.await?;
1056+
.await;
1057+
let completion = match completion_result {
1058+
Ok(c) => c,
1059+
Err(e) => {
1060+
self.function_log.log_action_system_error(
1061+
&e,
1062+
name,
1063+
arguments,
1064+
identity.into(),
1065+
start,
1066+
caller,
1067+
vec![].into(),
1068+
context,
1069+
);
1070+
anyhow::bail!(e)
1071+
},
1072+
};
10601073
let log_lines =
10611074
RedactedLogLines::from_log_lines(completion.log_lines().clone(), block_logging);
10621075
let result = completion.outcome.result.clone();
1063-
self.function_log
1064-
.log_action(completion, false, usage_tracking);
1076+
self.function_log.log_action(completion, usage_tracking);
10651077

10661078
let value = match result {
10671079
Ok(ref value) => value.unpack(),
@@ -1173,6 +1185,7 @@ impl<RT: Runtime> ApplicationFunctionRunner<RT> {
11731185
});
11741186
},
11751187
};
1188+
let udf_server_version = path_and_args.npm_version().clone();
11761189
// We should not be missing the module given we validated the path above
11771190
// which requires the module to exist.
11781191
let module_version = self
@@ -1182,8 +1195,9 @@ impl<RT: Runtime> ApplicationFunctionRunner<RT> {
11821195
.context("Missing a valid module_version")?;
11831196
let (log_line_sender, log_line_receiver) = mpsc::unbounded();
11841197

1198+
let inert_identity = tx.inert_identity();
11851199
let timer = function_total_timer(module_version.environment, UdfType::Action);
1186-
match module_version.environment {
1200+
let completion_result = match module_version.environment {
11871201
ModuleEnvironment::Isolate => {
11881202
// TODO: This is the only use case of clone. We should get rid of clone,
11891203
// when we deprecate that codepath.
@@ -1205,19 +1219,18 @@ impl<RT: Runtime> ApplicationFunctionRunner<RT> {
12051219
},
12061220
)
12071221
.await;
1208-
let outcome = outcome_result?;
12091222
let memory_in_mb: u64 = (*ISOLATE_MAX_USER_HEAP_SIZE / (1 << 20))
12101223
.try_into()
12111224
.unwrap();
12121225
timer.finish();
1213-
Ok(ActionCompletion {
1226+
outcome_result.map(|outcome| ActionCompletion {
12141227
outcome,
12151228
execution_time: start.elapsed(),
12161229
environment: ModuleEnvironment::Isolate,
12171230
memory_in_mb,
1218-
context,
1231+
context: context.clone(),
12191232
unix_timestamp,
1220-
caller,
1233+
caller: caller.clone(),
12211234
log_lines,
12221235
})
12231236
},
@@ -1309,33 +1322,63 @@ impl<RT: Runtime> ApplicationFunctionRunner<RT> {
13091322
},
13101323
)
13111324
.await;
1312-
let node_outcome = node_outcome_result?;
1313-
1314-
let outcome = ActionOutcome {
1315-
udf_path: name.clone(),
1325+
timer.finish();
1326+
node_outcome_result.map(|node_outcome| {
1327+
let outcome = ActionOutcome {
1328+
udf_path: name.clone(),
1329+
arguments: arguments.clone(),
1330+
identity: tx.inert_identity(),
1331+
unix_timestamp,
1332+
result: node_outcome.result.map(JsonPackedValue::pack),
1333+
syscall_trace: node_outcome.syscall_trace,
1334+
udf_server_version,
1335+
};
1336+
ActionCompletion {
1337+
outcome,
1338+
execution_time: start.elapsed(),
1339+
environment: ModuleEnvironment::Node,
1340+
memory_in_mb: node_outcome.memory_used_in_mb,
1341+
context: context.clone(),
1342+
unix_timestamp,
1343+
caller: caller.clone(),
1344+
log_lines,
1345+
}
1346+
})
1347+
},
1348+
ModuleEnvironment::Invalid => {
1349+
Err(anyhow::anyhow!("Attempting to run an invalid function"))
1350+
},
1351+
};
1352+
match completion_result {
1353+
Ok(c) => Ok(c),
1354+
Err(e) if e.is_deterministic_user_error() => {
1355+
let outcome = ActionOutcome::from_error(
1356+
JsError::from_error(e),
1357+
name,
13161358
arguments,
1317-
identity: tx.inert_identity(),
1318-
unix_timestamp,
1319-
result: node_outcome.result.map(JsonPackedValue::pack),
1320-
syscall_trace: node_outcome.syscall_trace,
1359+
inert_identity,
1360+
self.runtime.clone(),
13211361
udf_server_version,
1322-
};
1323-
timer.finish();
1324-
let memory_in_mb = node_outcome.memory_used_in_mb;
1362+
);
13251363
Ok(ActionCompletion {
13261364
outcome,
13271365
execution_time: start.elapsed(),
1328-
environment: ModuleEnvironment::Node,
1329-
memory_in_mb,
1366+
environment: module_version.environment,
1367+
memory_in_mb: match module_version.environment {
1368+
ModuleEnvironment::Isolate => (*ISOLATE_MAX_USER_HEAP_SIZE / (1 << 20))
1369+
.try_into()
1370+
.unwrap(),
1371+
// This isn't correct but we don't have a value to use here.
1372+
ModuleEnvironment::Node => 0,
1373+
ModuleEnvironment::Invalid => 0,
1374+
},
13301375
context,
13311376
unix_timestamp,
13321377
caller,
1333-
log_lines,
1378+
log_lines: vec![].into(),
13341379
})
13351380
},
1336-
ModuleEnvironment::Invalid => {
1337-
anyhow::bail!("Attempting to run an invalid function")
1338-
},
1381+
Err(e) => Err(e),
13391382
}
13401383
}
13411384

@@ -1379,7 +1422,9 @@ impl<RT: Runtime> ApplicationFunctionRunner<RT> {
13791422
let unix_timestamp = self.runtime.unix_timestamp();
13801423
let context = ExecutionContext::new(request_id, &caller);
13811424

1382-
let route = http_request.head.route_for_failure()?;
1425+
let route = http_request.head.route_for_failure();
1426+
let http_request_head = http_request.head.clone();
1427+
let inert_identity = InertIdentity::from(identity.clone());
13831428
let (log_line_sender, log_line_receiver) = mpsc::unbounded();
13841429
let outcome_future = self
13851430
.http_actions
@@ -1407,16 +1452,53 @@ impl<RT: Runtime> ApplicationFunctionRunner<RT> {
14071452
)
14081453
})
14091454
.await;
1410-
let outcome = outcome_result?;
1411-
self.function_log.log_http_action(
1412-
outcome.clone(),
1413-
log_lines,
1414-
start.elapsed(),
1415-
caller,
1416-
usage_tracker,
1417-
context,
1418-
);
1419-
Ok(outcome.result)
1455+
match outcome_result {
1456+
Ok(outcome) => {
1457+
let result = outcome.result.clone();
1458+
self.function_log.log_http_action(
1459+
outcome,
1460+
log_lines,
1461+
start.elapsed(),
1462+
caller,
1463+
usage_tracker,
1464+
context,
1465+
);
1466+
Ok(result)
1467+
},
1468+
Err(e) if e.is_deterministic_user_error() => {
1469+
let result = Err(JsError::from_error(e));
1470+
let outcome = HttpActionOutcome::new(
1471+
None,
1472+
http_request_head,
1473+
inert_identity,
1474+
unix_timestamp,
1475+
result.clone(),
1476+
None,
1477+
None,
1478+
);
1479+
self.function_log.log_http_action(
1480+
outcome.clone(),
1481+
log_lines,
1482+
start.elapsed(),
1483+
caller,
1484+
usage_tracker,
1485+
context,
1486+
);
1487+
Ok(result)
1488+
},
1489+
Err(e) => {
1490+
self.function_log.log_http_action_system_error(
1491+
&e,
1492+
http_request_head,
1493+
inert_identity,
1494+
start,
1495+
caller,
1496+
log_lines,
1497+
context,
1498+
);
1499+
Err(e)
1500+
},
1501+
}
14201502
}
14211503

14221504
#[minitrace::trace]
@@ -1750,39 +1832,6 @@ impl<RT: Runtime> ApplicationFunctionRunner<RT> {
17501832
Ok(Some(result))
17511833
}
17521834

1753-
pub async fn log_udf_system_error(
1754-
&self,
1755-
udf_path: CanonicalizedUdfPath,
1756-
arguments: ConvexArray,
1757-
identity: InertIdentity,
1758-
start: RT::Instant,
1759-
caller: FunctionCaller,
1760-
e: &anyhow::Error,
1761-
context: ExecutionContext,
1762-
) -> anyhow::Result<()> {
1763-
// TODO: We currently synthesize a `UdfOutcome` for
1764-
// an internal system error. If we decide we want to keep internal system errors
1765-
// in the UDF execution log, we may want to plumb through stuff like log lines.
1766-
let outcome = UdfOutcome::from_error(
1767-
JsError::from_error_ref(e),
1768-
udf_path,
1769-
arguments,
1770-
identity,
1771-
self.runtime.clone(),
1772-
None,
1773-
);
1774-
self.function_log.log_mutation(
1775-
outcome,
1776-
BTreeMap::new(),
1777-
start.elapsed(),
1778-
caller,
1779-
true,
1780-
FunctionUsageTracker::new(),
1781-
context,
1782-
);
1783-
Ok(())
1784-
}
1785-
17861835
#[minitrace::trace]
17871836
async fn write_mutation_status(
17881837
&self,

0 commit comments

Comments
 (0)