improved debugging

Author: Guy Bedford

integration-tests/js-compute/fixtures/module-mode/src/http-cache.js

@@ -2,10 +2,19 @@
 import { strictEqual, assertRejects } from './assertions.js';
 import { routes } from './routes.js';
 import { CacheOverride } from 'fastly:cache-override';
+import { Backend } from 'fastly:backend';
 
 // generate a unique URL everytime so that we never work on a populated cache
 const getTestUrl = () =>
-  `https://httpbin.org/anything?${Math.random().toString().slice(2)}`;
+  `https://httpbin.org/anything/${Math.random().toString().slice(2)}`;
+
+let _httpBinBackend;
+const httpBinBackend = () =>
+  _httpBinBackend ||
+  (_httpBinBackend = new Backend({
+    name: `httpbin-${Math.random().toString().slice(2)}`,
+    target: 'httpbin.org',
+  }));
 
 // Test suite: Error handling
 {
@@ -16,6 +25,7 @@ const getTestUrl = () =>
     await assertRejects(
       () =>
         fetch(url, {
+          backend: httpBinBackend(),
           cacheOverride: new CacheOverride({
             afterSend(res) {
               res.status = 'invalid'; // Should throw type error

integration-tests/js-compute/fixtures/module-mode/src/index.js

@@ -42,11 +42,14 @@ async function app(event) {
         return (res = new Response(
           `The routeHandler for ${path} threw a [${error.constructor?.name ?? error.name}] error: ${error.message || error}` +
             '\n' +
-            error.stack,
+            error.stack +
+            (fastly.debugMessages
+              ? '\n[DEBUG BUILD MESSAGES]:\n\n  - ' +
+                fastly.debugMessages.join('\n  - ')
+              : ''),
           { status: 500 },
         ));
       } catch (errRes) {
-        console.error('err2', errRes);
         res = errRes;
       }
     }

integration-tests/js-compute/test.js

@@ -40,6 +40,7 @@ const moduleMode = args.includes('--module-mode');
 const aot = args.includes('--aot');
 const debugBuild = args.includes('--debug-build');
 const filter = args.filter((arg) => !arg.startsWith('--'));
+const bail = args.includes('--bail');
 
 async function $(...args) {
   return await retry(10, () => zx(...args));
@@ -120,7 +121,7 @@ if (!local) {
   if (existsSync(setupPath)) {
     core.startGroup('Extra set-up steps for the service');
     await zx`node ${setupPath} ${serviceName}`;
-    await sleep(60);
+    await sleep(20);
     core.endGroup();
   }
 } else {
@@ -262,31 +263,35 @@ for (const chunk of chunks(Object.entries(tests), 100)) {
           }
         } else {
           if (test.environments.includes('compute')) {
-            // TODO: this just hides flakes, so we should remove this and fix the flakes.
-            return retry(10, expBackoff('60s', '10s'), async () => {
-              let path = test.downstream_request.pathname;
-              let url = `${domain}${path}`;
-              try {
-                const response = await request(url, {
-                  method: test.downstream_request.method || 'GET',
-                  headers: test.downstream_request.headers || undefined,
-                  body: test.downstream_request.body || undefined,
-                });
-                const bodyChunks = await getBodyChunks(response);
-                await compareDownstreamResponse(
-                  test.downstream_response,
-                  response,
-                  bodyChunks,
-                );
-                return {
-                  title,
-                  test,
-                  skipped: false,
-                };
-              } catch (error) {
-                throw new Error(`${title} ${error.message}`);
-              }
-            });
+            // TODO: this just hides flakes, so we should remove retry and fix the flakes.
+            return (bail ? (_, __, fn) => fn() : retry)(
+              10,
+              expBackoff('60s', '10s'),
+              async () => {
+                let path = test.downstream_request.pathname;
+                let url = `${domain}${path}`;
+                try {
+                  const response = await request(url, {
+                    method: test.downstream_request.method || 'GET',
+                    headers: test.downstream_request.headers || undefined,
+                    body: test.downstream_request.body || undefined,
+                  });
+                  const bodyChunks = await getBodyChunks(response);
+                  await compareDownstreamResponse(
+                    test.downstream_response,
+                    response,
+                    bodyChunks,
+                  );
+                  return {
+                    title,
+                    test,
+                    skipped: false,
+                  };
+                } catch (error) {
+                  throw new Error(`${title} ${error.message}`);
+                }
+              },
+            );
           } else {
             return {
               title,

runtime/fastly/builtins/fastly.cpp

@@ -39,6 +39,7 @@ bool debug_logging_enabled() { return DEBUG_LOGGING_ENABLED; }
 
 namespace fastly::fastly {
 
+JS::PersistentRooted<JSObject *> debugMessages;
 JS::PersistentRooted<JSObject *> Fastly::env;
 JS::PersistentRooted<JSObject *> Fastly::baseURL;
 JS::PersistentRooted<JSString *> Fastly::defaultBackend;
@@ -431,6 +432,19 @@ 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;
 
@@ -584,6 +598,15 @@ bool install(api::Engine *engine) {
     return false;
   }
 
+  // debugMessages for debug-only builds
+#ifdef DEBUG
+  debugMessages.init(engine->cx(), JS::NewArrayObject(engine->cx(), 0));
+  RootedValue debug_messages_val(engine->cx(), JS::ObjectValue(*debugMessages));
+  if (!JS_SetProperty(engine->cx(), fastly, "debugMessages", debug_messages_val)) {
+    return false;
+  }
+#endif
+
   return true;
 }
 

runtime/fastly/builtins/fastly.h

@@ -61,6 +61,14 @@ class Fastly : public builtins::BuiltinNoConstructor<Fastly> {
 JS::Result<std::tuple<JS::UniqueChars, size_t>> convertBodyInit(JSContext *cx,
                                                                 JS::HandleValue bodyInit);
 
+/**
+ * Debug only logging system, adding messages to `fastly.debugMessages`
+ *
+ * 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
 
 #endif

runtime/fastly/builtins/fetch/fetch.cpp

@@ -618,6 +618,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");
     return fetch_send_body<false>(cx, request, args.rval());
   }
 
@@ -640,6 +641,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");
     return fetch_send_body<true>(cx, request, args.rval());
   }
 
@@ -664,6 +666,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");
     if (host_api::error_is_limit_exceeded(*err)) {
       JS_ReportErrorASCII(cx, "HTTP caching limit exceeded");
     } else {
@@ -680,6 +683,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");
     HANDLE_ERROR(cx, *err);
     JSObject *promise = PromiseRejectedWithPendingError(cx);
     if (!promise) {
@@ -689,10 +693,12 @@ 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));
 
   // 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");
     HANDLE_ERROR(cx, *err);
     JSObject *promise = PromiseRejectedWithPendingError(cx);
     if (!promise) {
@@ -704,6 +710,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");
     auto cached_response = maybe_response.value();
 
     if (cache_state.must_insert_or_update()) {
@@ -751,12 +758,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");
     // 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);
     if (!fetch_send_body_with_cache_hooks(cx, request, cache_entry, &stream_back_promise)) {
       cache_entry.close();

runtime/fastly/handler.cpp

@@ -46,9 +46,9 @@ void handle_incoming(host_api::Request req) {
   }
 
   if (ENGINE->debug_logging_enabled()) {
-    fastly::fetch_event::dispatch_fetch_event(fetch_event, &total_compute);
+    fetch_event::dispatch_fetch_event(fetch_event, &total_compute);
   } else {
-    fastly::fetch_event::dispatch_fetch_event(fetch_event);
+    fetch_event::dispatch_fetch_event(fetch_event);
   }
 
   // Loop until no more resolved promises or backend requests are pending.

runtime/fastly/host-api/host_api.cpp

@@ -17,20 +17,26 @@ using fastly::FastlyAPIError;
 #ifdef DEBUG
 
 static void log_hostcall(const char *func_name, ...) {
+  std::stringstream ss;
+  ss << "HOSTCALL: " << func_name << "(";
+
   va_list args;
   va_start(args, func_name);
-  fprintf(stderr, "HOSTCALL: %s(", func_name);
 
   const auto *arg = va_arg(args, const std::string_view *);
   if (arg) {
-    fprintf(stderr, "\"%.*s\"", (int)arg->size(), arg->data());
+    ss << std::string_view(arg->data(), arg->size());
     while ((arg = va_arg(args, const std::string_view *))) {
-      fprintf(stderr, ", \"%.*s\"", (int)arg->size(), arg->data());
+      ss << ", " << std::string_view(arg->data(), arg->size());
     }
   }
-  fprintf(stderr, ")\n");
+  ss << ")";
+
   va_end(args);
-  fflush(stderr);
+
+  // 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());
 }
 
 #define TRACE_CALL() log_hostcall(__func__);
@@ -1378,7 +1384,7 @@ Result<HostString> HttpReq::get_method() const {
 }
 
 Result<Void> HttpReq::set_uri(std::string_view str) {
-  TRACE_CALL()
+  TRACE_CALL_ARGS(std::string_view(std::to_string(this->handle)), str)
   Result<Void> res;
 
   fastly::fastly_host_error err;
@@ -1930,7 +1936,7 @@ from_fastly_cache_write_options(const fastly::fastly_http_cache_write_options &f
 
 // HttpReq cache-related method implementations
 Result<bool> HttpReq::is_cacheable() const {
-  TRACE_CALL()
+  TRACE_CALL_ARGS(std::string_view(std::to_string(this->handle)))
   uint32_t is_cacheable_out;
   auto res = fastly::http_cache_is_request_cacheable(this->handle, &is_cacheable_out);
   if (res != 0) {
@@ -1985,8 +1991,8 @@ 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()
-  uint32_t handle_out __attribute__((aligned(4)));
+  TRACE_CALL_ARGS(std::string_view(std::to_string(req.handle)))
+  alignas(4) uint32_t handle_out;
   fastly::fastly_http_cache_lookup_options opts{};
   uint32_t opts_mask = 0;
 
@@ -2207,15 +2213,18 @@ HttpCacheEntry::get_found_response(bool transform_for_client) const {
 }
 
 Result<CacheState> HttpCacheEntry::get_state() const {
-  TRACE_CALL()
-  alignas(4) uint8_t state_out;
-  auto res = fastly::http_cache_get_state(this->handle, &state_out);
+  TRACE_CALL_ARGS(std::string_view(std::to_string(this->handle)))
+  Result<CacheState> res;
 
-  if (res != 0) {
-    return Result<CacheState>::err(host_api::APIError(res));
+  fastly::fastly_host_error err;
+  alignas(4) uint8_t state;
+  if (!convert_result(fastly::http_cache_get_state(this->handle, &state), &err)) {
+    res.emplace_err(err);
+  } else {
+    res.emplace(CacheState{state});
   }
 
-  return Result<CacheState>::ok(CacheState(state_out));
+  return res;
 }
 
 Result<uint64_t> HttpCacheEntry::get_length() const {

runtime/fastly/host-api/host_api_fastly.h

@@ -24,6 +24,10 @@ struct JSErrorFormatString;
 
 namespace fastly {
 
+namespace fastly {
+void push_debug_message(std::string_view msg);
+}
+
 const JSErrorFormatString *FastlyGetErrorMessage(void *userRef, unsigned errorNumber);
 
 enum FastlyAPIError {