diff --git a/src/workerd/jsg/BUILD.bazel b/src/workerd/jsg/BUILD.bazel index 20264bde7b5..24b3a6c51fa 100644 --- a/src/workerd/jsg/BUILD.bazel +++ b/src/workerd/jsg/BUILD.bazel @@ -68,11 +68,13 @@ wd_cc_library( ":observer", ":url", "//src/workerd/util", + "//src/workerd/util:autogate", "//src/workerd/util:sentry", "//src/workerd/util:thread-scopes", "//src/workerd/util:uuid", "@capnp-cpp//src/kj", "@simdutf", + "@ssl", "@workerd-v8//:v8", ], ) @@ -176,6 +178,7 @@ wd_cc_library( src = f, deps = [ ":jsg", + "//src/workerd/util:autogate", ], ) for f in glob( ["*-test.c++"], diff --git a/src/workerd/jsg/util-test.c++ b/src/workerd/jsg/util-test.c++ index 5eb957eed98..289d9cf2f41 100644 --- a/src/workerd/jsg/util-test.c++ +++ b/src/workerd/jsg/util-test.c++ @@ -6,6 +6,8 @@ #include "jsg-test.h" #include "jsg.h" +#include + namespace workerd::jsg::test { namespace { @@ -112,12 +114,21 @@ struct ThrowContext: public ContextGlobalObject { }; JSG_DECLARE_ISOLATE_TYPE(ThrowIsolate, ThrowContext); -KJ_TEST("throw internal error") { +KJ_TEST("throw internal error without internal-error-id autogate") { + setPredictableModeForTest(); + util::Autogate::initAutogateNamesForTest({}); // without internal-error-id autogate + KJ_DEFER(util::Autogate::deinitAutogate()); + Evaluator e(v8System); { KJ_EXPECT_LOG(ERROR, "thrown from throwException"); e.expectEval("throwException()", "throws", "Error: internal error"); } + { + // We also expect the logged internal error to contain the error id. + KJ_EXPECT_LOG(ERROR, "wdErrId = 0123456789abcdefghijklmn"); + e.expectEval("throwException()", "throws", "Error: internal error"); + } { KJ_EXPECT_LOG(ERROR, "thrown from getThrowing"); @@ -135,6 +146,43 @@ KJ_TEST("throw internal error") { } } +KJ_TEST("throw internal error with internal-error-id autogate") { + setPredictableModeForTest(); + util::Autogate::initAutogateNamesForTest({"internal-error-id"_kj}); + KJ_DEFER(util::Autogate::deinitAutogate()); + + Evaluator e(v8System); + { + KJ_EXPECT_LOG(ERROR, "thrown from throwException"); + e.expectEval("throwException()", "throws", + "Error: internal error; reference = 0123456789abcdefghijklmn"); + } + { + // We also expect the logged internal error to contain the error id. + KJ_EXPECT_LOG(ERROR, "wdErrId = 0123456789abcdefghijklmn"); + e.expectEval("throwException()", "throws", + "Error: internal error; reference = 0123456789abcdefghijklmn"); + } + + { + KJ_EXPECT_LOG(ERROR, "thrown from getThrowing"); + e.expectEval( + "throwing", "throws", "Error: internal error; reference = 0123456789abcdefghijklmn"); + } + + { + KJ_EXPECT_LOG(ERROR, "thrown from setThrowing"); + e.expectEval( + "throwing = 123", "throws", "Error: internal error; reference = 0123456789abcdefghijklmn"); + } + + { + KJ_EXPECT_LOG(ERROR, "thrown from returnFunctionThatThrows"); + e.expectEval("returnFunctionThatThrows(123)(321)", "throws", + "Error: internal error; reference = 0123456789abcdefghijklmn"); + } +} + // ======================================================================================== struct TunneledContext: public ContextGlobalObject { @@ -261,7 +309,11 @@ struct TunneledContext: public ContextGlobalObject { }; JSG_DECLARE_ISOLATE_TYPE(TunneledIsolate, TunneledContext); -KJ_TEST("throw tunneled exception") { +KJ_TEST("throw tunneled exception without internal-error-id autogate") { + setPredictableModeForTest(); + util::Autogate::initAutogateNamesForTest({}); // without internal-error-id autogate + KJ_DEFER(util::Autogate::deinitAutogate()); + Evaluator e(v8System); e.expectEval( "throwTunneledTypeError()", "throws", "TypeError: thrown from throwTunneledTypeError"); @@ -279,6 +331,12 @@ KJ_TEST("throw tunneled exception") { e.expectEval( "throwTunneledInternalOperationError()", "throws", "OperationError: internal error"); } + { + // We also expect the logged internal error to contain the error id. + KJ_EXPECT_LOG(ERROR, "wdErrId = 0123456789abcdefghijklmn"); + e.expectEval( + "throwTunneledInternalOperationError()", "throws", "OperationError: internal error"); + } { KJ_EXPECT_LOG(ERROR, " jsg.TypeError"); e.expectEval("throwBadTunneledError()", "throws", "Error: internal error"); @@ -313,6 +371,72 @@ KJ_TEST("throw tunneled exception") { } } +KJ_TEST("throw tunneled exception with internal-error-id autogate") { + setPredictableModeForTest(); + util::Autogate::initAutogateNamesForTest({"internal-error-id"_kj}); + KJ_DEFER(util::Autogate::deinitAutogate()); + + Evaluator e(v8System); + e.expectEval( + "throwTunneledTypeError()", "throws", "TypeError: thrown from throwTunneledTypeError"); + e.expectEval("throwTunneledTypeErrorLateColon()", "throws", "TypeError"); + e.expectEval("throwTunneledTypeErrorWithExpectation()", "throws", + "TypeError: thrown from throwTunneledTypeErrorWithExpectation"); + e.expectEval("throwTunneledOperationError()", "throws", + "OperationError: thrown from throwTunneledOperationError"); + e.expectEval("throwTunneledOperationErrorWithoutMessage()", "throws", "OperationError"); + e.expectEval("throwTunneledOperationErrorLateColon()", "throws", "OperationError"); + e.expectEval("throwTunneledOperationErrorWithExpectation()", "throws", + "OperationError: thrown from throwTunneledOperationErrorWithExpectation"); + { + KJ_EXPECT_LOG(ERROR, "thrown from throwTunneledInternalOperationError"); + e.expectEval("throwTunneledInternalOperationError()", "throws", + "OperationError: internal error; reference = 0123456789abcdefghijklmn"); + } + { + // We also expect the logged internal error to contain the error id. + KJ_EXPECT_LOG(ERROR, "wdErrId = 0123456789abcdefghijklmn"); + e.expectEval("throwTunneledInternalOperationError()", "throws", + "OperationError: internal error; reference = 0123456789abcdefghijklmn"); + } + { + KJ_EXPECT_LOG(ERROR, " jsg.TypeError"); + e.expectEval("throwBadTunneledError()", "throws", + "Error: internal error; reference = 0123456789abcdefghijklmn"); + } + { + KJ_EXPECT_LOG(ERROR, "expected s.startsWith(\";\"); jsg.TypeError"); + e.expectEval("throwBadTunneledErrorWithExpectation()", "throws", + "Error: internal error; reference = 0123456789abcdefghijklmn"); + } + e.expectEval("throwTunneledMacroTypeError()", "throws", + "TypeError: thrown from throwTunneledMacroTypeError"); + e.expectEval("throwTunneledMacroTypeErrorWithExpectation()", "throws", + "TypeError: thrown from throwTunneledMacroTypeErrorWithExpectation"); + e.expectEval("throwTunneledMacroOperationError()", "throws", + "OperationError: thrown from throwTunneledMacroOperationError"); + e.expectEval("throwTunneledMacroOperationErrorWithExpectation()", "throws", + "OperationError: thrown from throwTunneledMacroOperationErrorWithExpectation"); + e.expectEval("throwTunneledCompileError()", "throws", + "CompileError: thrown from throwTunneledCompileError"); + e.expectEval( + "throwTunneledLinkError()", "throws", "CompileError: thrown from throwTunneledLinkError"); + e.expectEval("throwTunneledRuntimeError()", "throws", + "CompileError: thrown from throwTunneledRuntimeError"); + e.expectEval( + "throwTunneledDOMException()", "throws", "Some error: thrown from throwTunneledDOMException"); + { + KJ_EXPECT_LOG(ERROR, " thrown from throwTunneledInvalidDOMException"); + e.expectEval("throwTunneledInvalidDOMException()", "throws", + "Error: internal error; reference = 0123456789abcdefghijklmn"); + } + { + KJ_EXPECT_LOG(ERROR, " thrown from throwTunneledGarbledDOMException"); + e.expectEval("throwTunneledGarbledDOMException()", "throws", + "Error: internal error; reference = 0123456789abcdefghijklmn"); + } +} + KJ_TEST("runTunnelingExceptions") { Evaluator e(v8System); e.expectEval("throwRetunneledTypeError()", "throws", "TypeError: Dummy error message."); diff --git a/src/workerd/jsg/util.c++ b/src/workerd/jsg/util.c++ index bacd861f348..40a2085aebb 100644 --- a/src/workerd/jsg/util.c++ +++ b/src/workerd/jsg/util.c++ @@ -6,6 +6,8 @@ #include "ser.h" #include "setup.h" +#include + #include #include @@ -15,6 +17,7 @@ #include #endif +#include #include namespace workerd::jsg { @@ -90,9 +93,52 @@ kj::String typeName(const std::type_info& type) { return kj::mv(result); } +namespace { + +// For internal errors, we generate an ID to include when rendering user-facing "internal error" +// exceptions and writing internal exception logs, to make it easier to search for logs +// corresponding to "internal error" exceptions reported by users. +// +// We'll use an ID of 24 base-32 encoded characters, just because its relatively simple to +// generate from random bytes. This should give us a value with 120 bits of uniqueness, which is +// about as good as a UUID. +// +// (We're not using base-64 encoding to avoid issues with case insensitive search, as well as +// ensuring that the id is easy to select and copy via double-clicking.) +using InternalErrorId = kj::FixedArray; + +constexpr char BASE32_DIGITS[] = "0123456789abcdefghijklmnopqrstuv"; + +InternalErrorId makeInternalErrorId() { + InternalErrorId id; + if (isPredictableModeForTest()) { + // In testing mode, use content that generates a "0123456789abcdefghijklm" ID: + for (auto i: kj::indices(id)) { + id[i] = i; + } + } else { + KJ_ASSERT(RAND_bytes(id.asPtr().asBytes().begin(), id.size()) == 1); + } + for (auto i: kj::indices(id)) { + id[i] = BASE32_DIGITS[static_cast(id[i]) % 32]; + } + return id; +} + +kj::String renderInternalError(InternalErrorId& internalErrorId) { + if (util::Autogate::isEnabled(util::AutogateKey::INTERNAL_ERROR_ID)) { + return kj::str("internal error; reference = ", internalErrorId); + } else { + return kj::str("internal error"); + } +} + +} // namespace + v8::Local makeInternalError(v8::Isolate* isolate, kj::StringPtr internalMessage) { - KJ_LOG(ERROR, internalMessage); - return v8::Exception::Error(v8StrIntern(isolate, "internal error")); + auto wdErrId = makeInternalErrorId(); + KJ_LOG(ERROR, internalMessage, wdErrId); + return v8::Exception::Error(v8Str(isolate, renderInternalError(wdErrId))); } namespace { @@ -143,6 +189,8 @@ struct DecodedException { bool isInternal; bool isFromRemote; bool isDurableObjectReset; + // TODO(cleanup): Maybe<> is redundant with isInternal flag field? + kj::Maybe internalErrorId; }; DecodedException decodeTunneledException( @@ -167,15 +215,17 @@ DecodedException decodeTunneledException( // TODO(someday): Support arbitrary user-defined error types, not just Error? auto tunneledInfo = tunneledErrorType(internalMessage); + DecodedException result; auto errorType = tunneledInfo.message; - auto appMessage = [&](kj::StringPtr errorString) -> kj::StringPtr { + auto appMessage = [&](kj::StringPtr errorString) -> kj::ConstString { if (tunneledInfo.isInternal) { - return "internal error"_kj; + result.internalErrorId = makeInternalErrorId(); + return kj::ConstString(renderInternalError(KJ_ASSERT_NONNULL(result.internalErrorId))); } else { - return trimErrorMessage(errorString); + // .attach() to convert StringPtr to ConstString: + return trimErrorMessage(errorString).attach(); } }; - DecodedException result; result.isInternal = tunneledInfo.isInternal; result.isFromRemote = tunneledInfo.isFromRemote; result.isDurableObjectReset = tunneledInfo.isDurableObjectReset; @@ -213,7 +263,9 @@ DecodedException decodeTunneledException( } } // unrecognized exception type - result.handle = v8::Exception::Error(v8StrIntern(isolate, "internal error")); + result.internalErrorId = makeInternalErrorId(); + result.handle = v8::Exception::Error( + v8Str(isolate, renderInternalError(KJ_ASSERT_NONNULL(result.internalErrorId)))); result.isInternal = true; } while (false); #undef HANDLE_V8_ERROR @@ -240,6 +292,7 @@ DecodedException decodeTunneledException( kj::StringPtr extractTunneledExceptionDescription(kj::StringPtr message) { auto tunneledError = tunneledErrorType(message); if (tunneledError.isInternal) { + // TODO(soon): Include an internal error ID in message, and also return the id. return "Error: internal error"; } else { return tunneledError.message; @@ -271,7 +324,11 @@ v8::Local makeInternalError(v8::Isolate* isolate, kj::Exception&& exc // DISCONNECTED exceptions as these are unlikely to represent bugs worth tracking. if (exception.getType() != kj::Exception::Type::DISCONNECTED && !isDoNotLogException(exception.getDescription())) { - LOG_EXCEPTION("jsgInternalError", exception); + // LOG_EXCEPTION("jsgInternalError", ...), but with internal error ID: + auto& e = exception; + constexpr auto sentryErrorContext = "jsgInternalError"; + auto& wdErrId = KJ_ASSERT_NONNULL(tunneledException.internalErrorId); + KJ_LOG(ERROR, e, sentryErrorContext, wdErrId); } else { KJ_LOG(INFO, exception); // Run with --verbose to see exception logs. } diff --git a/src/workerd/util/autogate.c++ b/src/workerd/util/autogate.c++ index 49e0bf03ab0..567d3fcc107 100644 --- a/src/workerd/util/autogate.c++ +++ b/src/workerd/util/autogate.c++ @@ -21,6 +21,8 @@ kj::StringPtr KJ_STRINGIFY(AutogateKey key) { return "streaming-tail-workers"_kj; case AutogateKey::PYTHON_FETCH_INDIVIDUAL_PACKAGES: return "python-fetch-individual-packages"; + case AutogateKey::INTERNAL_ERROR_ID: + return "internal-error-id"; case AutogateKey::NumOfKeys: KJ_FAIL_ASSERT("NumOfKeys should not be used in getName"); } diff --git a/src/workerd/util/autogate.h b/src/workerd/util/autogate.h index 859d8ea9e87..de7caed5ec8 100644 --- a/src/workerd/util/autogate.h +++ b/src/workerd/util/autogate.h @@ -18,6 +18,8 @@ enum class AutogateKey { // Fetches Python packages as individual bundles from GCS instead of using a single big bundle // embedded in the binary PYTHON_FETCH_INDIVIDUAL_PACKAGES, + // Adds a "reference" ID to "internal error" exception messages + INTERNAL_ERROR_ID, NumOfKeys // Reserved for iteration. };