progress

integration-tests/js-compute/test.js

@@ -121,7 +121,7 @@ if (!local) {
   if (existsSync(setupPath)) {
     core.startGroup('Extra set-up steps for the service');
     await zx`node ${setupPath} ${serviceName}`;
-    await sleep(20);
+    await sleep(15);
     core.endGroup();
   }
 } else {

runtime/fastly/builtins/fastly.cpp

@@ -432,19 +432,6 @@ const JSPropertySpec Fastly::properties[] = {
     JS_PSG("sdkVersion", version_get, JSPROP_ENUMERATE),
     JS_PS_END};
 
-void push_debug_message(std::string_view msg) {
-#ifdef DEBUG
-  JS::RootedString str(
-      ENGINE->cx(), JS_NewStringCopyUTF8N(ENGINE->cx(), JS::UTF8Chars(msg.data(), msg.length())));
-  bool res;
-  uint32_t len;
-  res = JS::GetArrayLength(ENGINE->cx(), debugMessages, &len);
-  MOZ_ASSERT(res);
-  res = JS_SetElement(ENGINE->cx(), debugMessages, len, str);
-  MOZ_ASSERT(res);
-#endif
-}
-
 bool install(api::Engine *engine) {
   ENGINE = engine;
 
@@ -662,3 +649,16 @@ JS::Result<std::tuple<JS::UniqueChars, size_t>> convertBodyInit(JSContext *cx,
 }
 
 } // namespace fastly::fastly
+
+void fastly_push_debug_message(std::string_view msg) {
+#ifdef DEBUG
+  JS::RootedString str(
+      ENGINE->cx(), JS_NewStringCopyUTF8N(ENGINE->cx(), JS::UTF8Chars(msg.data(), msg.length())));
+  bool res;
+  uint32_t len;
+  res = JS::GetArrayLength(ENGINE->cx(), fastly::fastly::debugMessages, &len);
+  MOZ_ASSERT(res);
+  res = JS_SetElement(ENGINE->cx(), fastly::fastly::debugMessages, len, str);
+  MOZ_ASSERT(res);
+#endif
+}

runtime/fastly/builtins/fastly.h

@@ -67,8 +67,9 @@ JS::Result<std::tuple<JS::UniqueChars, size_t>> convertBodyInit(JSContext *cx,
  * This is useful for debugging compute, allowing messages to be inlined into the response in test
  * case debugging, where other logging systems may introduce greater latency than this.
  */
-void push_debug_message(std::string_view msg);
 
 } // namespace fastly::fastly
 
+void fastly_push_debug_message(std::string_view msg);
+
 #endif

runtime/fastly/builtins/fetch/fetch.cpp

@@ -416,6 +416,7 @@ bool fetch_send_body_with_cache_hooks(JSContext *cx, HandleObject request,
 
 bool background_revalidation_then_handler(JSContext *cx, JS::HandleObject request,
                                           JS::HandleValue response, JS::CallArgs args) {
+  DEBUG_LOG("background_revalidation_then_handler")
   auto cache_entry = RequestOrResponse::cache_entry(request).value();
   JSObject *response_obj = &response.toObject();
   MOZ_ASSERT(cache_entry.handle == RequestOrResponse::cache_entry(response_obj).value().handle);
@@ -474,6 +475,7 @@ bool background_revalidation_then_handler(JSContext *cx, JS::HandleObject reques
 
 bool background_revalidation_catch_handler(JSContext *cx, JS::HandleObject request,
                                            JS::HandleValue promise_val, JS::CallArgs args) {
+  DEBUG_LOG("background_revalidation_catch_handler")
   // we follow the Rust implementation calling "close" instead of "transaction_abandon" here
   // this could be reconsidered in future if alternative semantics are required
   auto cache_entry = RequestOrResponse::cache_entry(request).value();
@@ -484,6 +486,7 @@ bool background_revalidation_catch_handler(JSContext *cx, JS::HandleObject reque
 
 bool stream_back_then_handler(JSContext *cx, JS::HandleObject request, JS::HandleValue response,
                               JS::CallArgs args) {
+  DEBUG_LOG("stream_back_then_handler")
   auto cache_entry = RequestOrResponse::cache_entry(request).value();
   RootedObject response_obj(cx, &response.toObject());
   MOZ_ASSERT(cache_entry.handle == RequestOrResponse::cache_entry(response_obj).value().handle);
@@ -575,11 +578,14 @@ bool stream_back_then_handler(JSContext *cx, JS::HandleObject request, JS::Handl
 
 bool stream_back_catch_handler(JSContext *cx, JS::HandleObject request, JS::HandleValue promise_val,
                                JS::CallArgs args) {
+  DEBUG_LOG("stream_back_catch_handler")
   // we follow the Rust implementation calling "close" instead of "transaction_abandon" here
   // this could be reconsidered in future if alternative semantics are required
   auto cache_entry = RequestOrResponse::cache_entry(request).value();
   cache_entry.close();
-  return true;
+  // "rethrow" the streaming error
+  JS_SetPendingException(cx, args.get(0), JS::ExceptionStackBehavior::DoNotCapture);
+  return false;
 }
 
 // TODO: throw in all Request methods/getters that rely on host calls once a
@@ -618,7 +624,7 @@ bool fetch(JSContext *cx, unsigned argc, Value *vp) {
     return false;
   }
   if (!should_use_guest_caching_out) {
-    fastly::push_debug_message("Using traditional fetch without cache API");
+    DEBUG_LOG("Using traditional fetch without cache API")
     return fetch_send_body<false>(cx, request, args.rval());
   }
 
@@ -641,7 +647,7 @@ bool fetch(JSContext *cx, unsigned argc, Value *vp) {
 
   // If not cacheable, fallback to non-caching path
   if (!is_cacheable) {
-    fastly::push_debug_message("Request not cacheable, using non-caching fetch");
+    DEBUG_LOG("Request not cacheable, using non-caching fetch")
     return fetch_send_body<true>(cx, request, args.rval());
   }
 
@@ -666,7 +672,7 @@ bool fetch(JSContext *cx, unsigned argc, Value *vp) {
   auto transaction_res =
       host_api::HttpCacheEntry::transaction_lookup(request_handle, override_key_span);
   if (auto *err = transaction_res.to_err()) {
-    fastly::push_debug_message("Transaction lookup error");
+    DEBUG_LOG("Transaction lookup error")
     if (host_api::error_is_limit_exceeded(*err)) {
       JS_ReportErrorASCII(cx, "HTTP caching limit exceeded");
     } else {
@@ -683,7 +689,7 @@ bool fetch(JSContext *cx, unsigned argc, Value *vp) {
 
   auto state_res = cache_entry.get_state();
   if (auto *err = state_res.to_err()) {
-    fastly::push_debug_message("Cache state error");
+    DEBUG_LOG("Cache state error")
     HANDLE_ERROR(cx, *err);
     JSObject *promise = PromiseRejectedWithPendingError(cx);
     if (!promise) {
@@ -693,12 +699,13 @@ bool fetch(JSContext *cx, unsigned argc, Value *vp) {
     return true;
   }
   auto cache_state = state_res.unwrap();
-  fastly::push_debug_message(std::to_string(cache_state.state));
+  std::string state_str = std::to_string(cache_state.state);
+  DEBUG_LOG(state_str)
 
   // Check for usable cached response
   auto found_res = cache_entry.get_found_response(true);
   if (auto *err = found_res.to_err()) {
-    fastly::push_debug_message("Usable cache response error");
+    DEBUG_LOG("Usable cache response error")
     HANDLE_ERROR(cx, *err);
     JSObject *promise = PromiseRejectedWithPendingError(cx);
     if (!promise) {
@@ -710,7 +717,7 @@ bool fetch(JSContext *cx, unsigned argc, Value *vp) {
 
   auto maybe_response = found_res.unwrap();
   if (maybe_response.has_value()) {
-    fastly::push_debug_message("Have usable response");
+    DEBUG_LOG("Have usable response")
     auto cached_response = maybe_response.value();
 
     if (cache_state.must_insert_or_update()) {
@@ -758,16 +765,15 @@ bool fetch(JSContext *cx, unsigned argc, Value *vp) {
 
   // No valid cached response, need to make backend request
   if (!cache_state.must_insert_or_update()) {
-    fastly::push_debug_message("No usable response, and don't need to insert or update -> pass");
+    DEBUG_LOG("No usable response, and don't need to insert or update -> pass")
     // transaction entry is done
     cache_entry.close();
     // request collapsing has been disabled: pass the original request to the origin without
     // updating the cache and without caching
     return fetch_send_body<true>(cx, request, args.rval());
   } else {
-    fastly::push_debug_message(
-        "No usable response, and must insert or update, running origin fetch hooks");
-    JS::RootedValue stream_back_promise(cx);
+    DEBUG_LOG("No usable response, and must insert or update, running origin fetch hooks")
+    JS::RootedValue stream_back_promise(cx, JS::ObjectValue(*JS::NewPromiseObject(cx, nullptr)));
     if (!fetch_send_body_with_cache_hooks(cx, request, cache_entry, &stream_back_promise)) {
       cache_entry.close();
       return false;

runtime/fastly/builtins/fetch/request-response.cpp

@@ -333,6 +333,7 @@ bool Response::add_fastly_cache_headers(JSContext *cx, JS::HandleObject self,
 
 bool after_send_then(JSContext *cx, JS::HandleObject response, JS::HandleValue request,
                      JS::CallArgs args) {
+  DEBUG_LOG("After afterSend")
   JS::RootedObject request_obj(cx, &request.toObject());
   JS::RootedObject response_promise(
       cx, &JS::GetReservedSlot(request_obj, static_cast<uint32_t>(Request::Slots::ResponsePromise))
@@ -356,6 +357,7 @@ bool after_send_then(JSContext *cx, JS::HandleObject response, JS::HandleValue r
     // set_cacheable / set_uncacheable
     if (cache_val.isBoolean()) {
       if (cache_val.toBoolean()) {
+        DEBUG_LOG("After send cache true return")
         if (static_cast<host_api::HttpStorageAction>(
                 JS::GetReservedSlot(response, static_cast<uint32_t>(Response::Slots::StorageAction))
                     .toInt32()) != host_api::HttpStorageAction::Update) {
@@ -364,6 +366,7 @@ bool after_send_then(JSContext *cx, JS::HandleObject response, JS::HandleValue r
               JS::Int32Value(static_cast<uint32_t>(host_api::HttpStorageAction::Insert)));
         }
       } else {
+        DEBUG_LOG("After send cache false return")
         JS::SetReservedSlot(
             response, static_cast<uint32_t>(Response::Slots::StorageAction),
             JS::Int32Value(static_cast<uint32_t>(host_api::HttpStorageAction::DoNotStore)));
@@ -378,6 +381,7 @@ bool after_send_then(JSContext *cx, JS::HandleObject response, JS::HandleValue r
                                  "return, 'uncacheable' is the only permitted string value");
         return RejectPromiseWithPendingError(cx, response_promise);
       }
+      DEBUG_LOG("After send uncacheable return")
       JS::SetReservedSlot(
           response, static_cast<uint32_t>(Response::Slots::StorageAction),
           JS::Int32Value(static_cast<uint32_t>(host_api::HttpStorageAction::RecordUncacheable)));
@@ -392,6 +396,7 @@ bool after_send_then(JSContext *cx, JS::HandleObject response, JS::HandleValue r
       return RejectPromiseWithPendingError(cx, response_promise);
     }
     if (!body_transform_val.isNullOrUndefined()) {
+      DEBUG_LOG("After send body transform")
       if (!body_transform_val.isObject() || !JS_ObjectIsFunction(&body_transform_val.toObject())) {
         JS_ReportErrorLatin1(cx, "Unexpected value for 'bodyTransform' property on afterSend "
                                  "return, must be a function");
@@ -432,6 +437,7 @@ bool after_send_then(JSContext *cx, JS::HandleObject response, JS::HandleValue r
   // TODO: actually run body transform
 
   JS::RootedValue response_val(cx, JS::ObjectValue(*response));
+  DEBUG_LOG("HTTP cache lifecycle complete")
   JS::ResolvePromise(cx, response_promise, response_val);
   return true;
 }
@@ -465,6 +471,7 @@ bool RequestOrResponse::process_pending_request(JSContext *cx,
       RequestOrResponse::cache_entry(request);
 
   if (!maybe_cache_entry) {
+    DEBUG_LOG("Non HTTP cache request, returning")
     JS::RootedObject response(cx, Response::create(cx, request, res));
     JS::RootedValue response_val(cx, JS::ObjectValue(*response));
     return JS::ResolvePromise(cx, promise, response_val);
@@ -486,6 +493,7 @@ bool RequestOrResponse::process_pending_request(JSContext *cx,
   res.resp = suggested_resp;
 
   // create the candidate response
+  DEBUG_LOG("Creating candidate response")
   JS::RootedObject response(cx, Response::create(cx, request, res));
   // JS::RootedValue response_val(cx, JS::ObjectValue(*response));
 
@@ -500,6 +508,7 @@ bool RequestOrResponse::process_pending_request(JSContext *cx,
   }
   if (result.isBoolean() && result.toBoolean() == true &&
       suggested_storage_action != host_api::HttpStorageAction::DoNotStore) {
+    DEBUG_LOG("Set cookie opt-out")
     suggested_storage_action = host_api::HttpStorageAction::RecordUncacheable;
   }
 
@@ -517,6 +526,7 @@ bool RequestOrResponse::process_pending_request(JSContext *cx,
               .toObjectOrNull());
   RootedObject after_send(cx);
   if (cache_override) {
+    DEBUG_LOG("Reading cache override from request")
     after_send.set(CacheOverride::afterSend(cache_override));
 
     // convert the CacheOverride provided to the request into HttpCacheWriteOptions overrides
@@ -587,19 +597,23 @@ bool RequestOrResponse::process_pending_request(JSContext *cx,
     if (!override_pci.isUndefined()) {
       override_cache_options->sensitive_data = override_pci.toBoolean();
     }
+  } else {
+    DEBUG_LOG("No cache override on request, using suggested only")
   }
 
   JS::SetReservedSlot(response, static_cast<uint32_t>(Response::Slots::OverrideCacheWriteOptions),
                       JS::PrivateValue(override_cache_options));
 
   JS::RootedObject after_send_promise(cx);
   if (after_send) {
+    DEBUG_LOG("Calling after send")
     JS::RootedValue ret_val(cx);
     JS::RootedValueArray<1> args(cx);
     args[0].set(JS::ObjectValue(*response));
 
     // now call after_send with the candidate_request, allowing any async work
     if (!JS::Call(cx, JS::NullHandleValue, after_send, args, &ret_val)) {
+      DEBUG_LOG("After send call failure")
       return RejectPromiseWithPendingError(cx, promise);
     }
     after_send_promise = JS::RootedObject(cx, JS::CallOriginalPromiseResolve(cx, ret_val));

runtime/fastly/host-api/host_api.cpp

@@ -15,7 +15,6 @@ using api::FastlyResult;
 using fastly::FastlyAPIError;
 
 #ifdef DEBUG
-
 static void log_hostcall(const char *func_name, ...) {
   std::stringstream ss;
   ss << "HOSTCALL: " << func_name << "(";
@@ -34,13 +33,13 @@ static void log_hostcall(const char *func_name, ...) {
 
   va_end(args);
 
-  // fprintf(stderr, "%s\n", ss.str().c_str());
+  fprintf(stderr, "%s\n", ss.str().c_str());
   // Useful for debugging compute to output logs directly to error responses
-  fastly::fastly::push_debug_message(ss.str());
+  fastly_push_debug_message(ss.str());
 }
-
 #define TRACE_CALL() log_hostcall(__func__);
 #define TRACE_CALL_ARGS(...) log_hostcall(__func__, __VA_ARGS__, nullptr);
+#define TSV(s) std::string_view(s)
 #else
 #define TRACE_CALL()
 #define TRACE_CALL_ARGS(...)
@@ -885,7 +884,7 @@ FastlyKVError make_fastly_kv_error(fastly::fastly_kv_error kv_error,
 } // namespace
 
 Result<HttpBody> HttpBody::make() {
-  TRACE_CALL()
+  TRACE_CALL_ARGS(TSV("body"))
   Result<HttpBody> res;
 
   HttpBody::Handle handle;
@@ -1115,7 +1114,7 @@ TlsVersion TlsVersion::version_1_2() { return TlsVersion{fastly::TLS::VERSION_1_
 TlsVersion TlsVersion::version_1_3() { return TlsVersion{fastly::TLS::VERSION_1_3}; }
 
 Result<HttpReq> HttpReq::make() {
-  TRACE_CALL()
+  TRACE_CALL_ARGS(TSV("http_req"))
   Result<HttpReq> res;
 
   HttpReq::Handle handle;
@@ -1992,19 +1991,20 @@ Result<HttpCacheEntry> HttpCacheEntry::lookup(const HttpReq &req, std::span<uint
 Result<HttpCacheEntry> HttpCacheEntry::transaction_lookup(const HttpReq &req,
                                                           std::span<uint8_t> override_key) {
   TRACE_CALL_ARGS(std::string_view(std::to_string(req.handle)))
-  alignas(4) uint32_t handle_out;
+  uint32_t handle_out;
   fastly::fastly_http_cache_lookup_options opts{};
   uint32_t opts_mask = 0;
 
+  MOZ_ASSERT(override_key.empty());
   if (!override_key.empty()) {
     MOZ_ASSERT(override_key.size() == 32);
     opts.override_key = reinterpret_cast<const char *>(override_key.data());
     opts.override_key_len = override_key.size();
     opts_mask |= FASTLY_HTTP_CACHE_LOOKUP_OPTIONS_MASK_OVERRIDE_KEY;
   }
 
-  auto res = fastly::http_cache_lookup(req.handle, opts_mask,
-                                       override_key.empty() ? nullptr : &opts, &handle_out);
+  auto res = fastly::http_cache_transaction_lookup(
+      req.handle, opts_mask, override_key.empty() ? nullptr : &opts, &handle_out);
   if (res != 0) {
     return Result<HttpCacheEntry>::err(host_api::APIError(res));
   }
@@ -2177,7 +2177,7 @@ HttpCacheEntry::get_suggested_cache_options(const HttpResp &resp) const {
 Result<std::tuple<HttpStorageAction, HttpResp>>
 HttpCacheEntry::prepare_response_for_storage(HttpResp resp) const {
   TRACE_CALL()
-  HttpStorageAction storage_action_out;
+  alignas(4) HttpStorageAction storage_action_out;
   uint32_t updated_resp_handle_out;
 
   auto res = fastly::http_cache_prepare_response_for_storage(

runtime/fastly/host-api/host_api_fastly.h

@@ -22,11 +22,23 @@
 
 struct JSErrorFormatString;
 
-namespace fastly {
+void fastly_push_debug_message(std::string_view msg);
+
+// Debug mode debugging logging that logs both into an error response post-data
+// via fastly.debugMessages, as well as to stderr for flexible debugging.
+#ifdef DEBUG
+#define DEBUG_LOG(msg)                                                                             \
+  {                                                                                                \
+    std::string_view view(msg);                                                                    \
+    fprintf(stderr, "%.*s\n", static_cast<int>(view.size()), view.data());                         \
+    fflush(stderr);                                                                                \
+    fastly_push_debug_message(msg);                                                                \
+  }
+#else
+#define DEBUG_LOG(msg)
+#endif
 
 namespace fastly {
-void push_debug_message(std::string_view msg);
-}
 
 const JSErrorFormatString *FastlyGetErrorMessage(void *userRef, unsigned errorNumber);