|
| 1 | +// Copyright (c) 2023 - Restate Software, Inc., Restate GmbH |
| 2 | +// |
| 3 | +// This file is part of the Restate Java SDK, |
| 4 | +// which is released under the MIT license. |
| 5 | +// |
| 6 | +// You can find a copy of the license in file LICENSE in the root |
| 7 | +// directory of this repository or package, or at |
| 8 | +// https://github.com/restatedev/sdk-java/blob/main/LICENSE |
| 9 | +package dev.restate.sdk.core.statemachine.ffm; |
| 10 | + |
| 11 | +import java.lang.foreign.Arena; |
| 12 | +import java.lang.foreign.FunctionDescriptor; |
| 13 | +import java.lang.foreign.Linker; |
| 14 | +import java.lang.foreign.MemorySegment; |
| 15 | +import java.lang.foreign.ValueLayout; |
| 16 | +import java.lang.invoke.MethodHandle; |
| 17 | +import java.lang.invoke.MethodHandles; |
| 18 | +import java.lang.invoke.MethodType; |
| 19 | +import java.nio.charset.StandardCharsets; |
| 20 | +import java.util.Locale; |
| 21 | +import org.apache.logging.log4j.Level; |
| 22 | +import org.apache.logging.log4j.LogManager; |
| 23 | +import org.apache.logging.log4j.Logger; |
| 24 | +import org.apache.logging.log4j.spi.StandardLevel; |
| 25 | + |
| 26 | +/** |
| 27 | + * Bridges the native {@code restate-sdk-shared-core} tracing output into Log4j2. |
| 28 | + * |
| 29 | + * <p>At startup the FFM state machine installs a {@code tracing} subscriber in the native core (see |
| 30 | + * {@code init} in {@code rust/src/lib.rs}) parameterized with: |
| 31 | + * |
| 32 | + * <ul> |
| 33 | + * <li>a <b>max level</b> ({@link #abiLevel()}) derived from this class's Log4j2 logger, so the |
| 34 | + * core filters disabled events on its side — critically, its {@code #[instrument(level = |
| 35 | + * "trace")]} spans short-circuit before doing any work when trace is off; |
| 36 | + * <li>a <b>log callback</b> ({@link #callbackStub()}): an FFM upcall stub the core invokes for |
| 37 | + * every event that passes the filter. |
| 38 | + * </ul> |
| 39 | + * |
| 40 | + * <p>The callback is invoked synchronously on the same thread that made the downcall into the core, |
| 41 | + * so a native log line naturally inherits that thread's logging context (the {@code |
| 42 | + * restateInvocationId} / {@code restateInvocationTarget} MDC set by the endpoint handler) — a |
| 43 | + * Log4j2 pattern using {@code %X{restateInvocationId}} works unchanged. |
| 44 | + * |
| 45 | + * <p><b>Copy semantics.</b> The core hands the callback a borrowed {@code (ptr, len)} view over a |
| 46 | + * buffer that is valid only for the duration of the call. We therefore eagerly copy the bytes into |
| 47 | + * a JVM-heap {@code String} <b>during the call</b>: an async Log4j2 appender that retains the |
| 48 | + * message then holds a self-contained Java object, never a view over native memory that has since |
| 49 | + * been reused or freed. |
| 50 | + */ |
| 51 | +final class NativeLogging { |
| 52 | + |
| 53 | + private NativeLogging() {} |
| 54 | + |
| 55 | + /** Dedicated logger all native (shared-core) events are routed through. */ |
| 56 | + static final String LOGGER_NAME = "dev.restate.sdk.core.StateMachine"; |
| 57 | + |
| 58 | + private static final Logger LOG = LogManager.getLogger(LOGGER_NAME); |
| 59 | + |
| 60 | + /** |
| 61 | + * Optional override for the native max level, bypassing the Log4j2-derived value. Accepts {@code |
| 62 | + * TRACE|DEBUG|INFO|WARN|ERROR}. |
| 63 | + */ |
| 64 | + private static final String LEVEL_OVERRIDE_PROPERTY = |
| 65 | + "dev.restate.sdk.core.statemachine.ffm.FfmStateMachine.loglevel"; |
| 66 | + |
| 67 | + // ABI ordinal -> Log4j2 level. Mirrors AbiLogLevel in rust/src/lib.rs. |
| 68 | + private static final Level[] LEVELS = { |
| 69 | + Level.TRACE, Level.DEBUG, Level.INFO, Level.WARN, Level.ERROR |
| 70 | + }; |
| 71 | + |
| 72 | + private static final FunctionDescriptor CALLBACK_DESC = |
| 73 | + FunctionDescriptor.ofVoid(ValueLayout.JAVA_INT, ValueLayout.ADDRESS, ValueLayout.JAVA_LONG); |
| 74 | + |
| 75 | + /** |
| 76 | + * Upcall entry point invoked by the native core for each tracing event. Must never throw across |
| 77 | + * the FFI boundary, so everything is wrapped in a catch-all. |
| 78 | + * |
| 79 | + * @param level the {@link #LEVELS} ordinal |
| 80 | + * @param msgPtr native pointer to UTF-8 bytes, valid only for this call |
| 81 | + * @param msgLen length in bytes of the message at {@code msgPtr} |
| 82 | + */ |
| 83 | + static void log(int level, MemorySegment msgPtr, long msgLen) { |
| 84 | + try { |
| 85 | + Level l = level >= 0 && level < LEVELS.length ? LEVELS[level] : Level.INFO; |
| 86 | + // The native side already filtered by max level; this guards against per-logger config that |
| 87 | + // is stricter than the max, and avoids the decode when the event would be dropped anyway. |
| 88 | + if (!LOG.isEnabled(l)) { |
| 89 | + return; |
| 90 | + } |
| 91 | + // Eagerly copy the native bytes into a JVM-heap String *now*, before returning. This is the |
| 92 | + // single copy that makes the whole scheme safe: the native buffer is valid only for this |
| 93 | + // call, so an async Log4j2 appender that retains the message must be handed a self-contained |
| 94 | + // Java object, never a view over native memory. |
| 95 | + byte[] bytes = msgPtr.reinterpret(msgLen).toArray(ValueLayout.JAVA_BYTE); |
| 96 | + LOG.log(l, new String(bytes, StandardCharsets.UTF_8)); |
| 97 | + } catch (Throwable ignored) { |
| 98 | + // Swallow: an exception unwinding into the native caller across `extern "C"` is UB. |
| 99 | + } |
| 100 | + } |
| 101 | + |
| 102 | + /** |
| 103 | + * Builds the upcall stub for {@link #log}. Uses {@link Arena#global()} (never freed): the native |
| 104 | + * core keeps only the raw function pointer, which the GC cannot see, so the stub must outlive the |
| 105 | + * process — an {@link Arena#ofAuto()} stub would be reclaimed as soon as the returned segment |
| 106 | + * becomes unreachable (right after {@code init} returns), and the next event would call freed |
| 107 | + * code. |
| 108 | + */ |
| 109 | + static MemorySegment callbackStub() { |
| 110 | + try { |
| 111 | + MethodHandle handle = |
| 112 | + MethodHandles.lookup() |
| 113 | + .findStatic( |
| 114 | + NativeLogging.class, |
| 115 | + "log", |
| 116 | + MethodType.methodType(void.class, int.class, MemorySegment.class, long.class)); |
| 117 | + return Linker.nativeLinker().upcallStub(handle, CALLBACK_DESC, Arena.global()); |
| 118 | + } catch (NoSuchMethodException | IllegalAccessException e) { |
| 119 | + throw new ExceptionInInitializerError(e); |
| 120 | + } |
| 121 | + } |
| 122 | + |
| 123 | + /** |
| 124 | + * The max native tracing level as an {@code AbiLogLevel} ordinal (0 trace .. 4 error), taken from |
| 125 | + * the {@link #LEVEL_OVERRIDE_PROPERTY} system property when set, otherwise from the effective |
| 126 | + * Log4j2 level of {@link #LOGGER_NAME}. Passed to native {@code init} so the core does not even |
| 127 | + * produce events below it. |
| 128 | + */ |
| 129 | + static int abiLevel() { |
| 130 | + String override = System.getProperty(LEVEL_OVERRIDE_PROPERTY); |
| 131 | + if (override != null) { |
| 132 | + return switch (override.trim().toUpperCase(Locale.ROOT)) { |
| 133 | + case "TRACE" -> 0; |
| 134 | + case "DEBUG" -> 1; |
| 135 | + case "WARN" -> 3; |
| 136 | + case "ERROR" -> 4; |
| 137 | + default -> 2; |
| 138 | + }; |
| 139 | + } |
| 140 | + return abiLevel(LOG.getLevel()); |
| 141 | + } |
| 142 | + |
| 143 | + private static int abiLevel(Level level) { |
| 144 | + if (level == null) { |
| 145 | + return 2; // INFO |
| 146 | + } |
| 147 | + // Log4j2 intLevel decreases with severity (TRACE=600 .. ERROR=200); a logger set to level L |
| 148 | + // permits L and everything more severe. Map that to the coarser native max level. |
| 149 | + int i = level.intLevel(); |
| 150 | + if (i >= StandardLevel.TRACE.intLevel()) { |
| 151 | + return 0; |
| 152 | + } else if (i >= StandardLevel.DEBUG.intLevel()) { |
| 153 | + return 1; |
| 154 | + } else if (i >= StandardLevel.INFO.intLevel()) { |
| 155 | + return 2; |
| 156 | + } else if (i >= StandardLevel.WARN.intLevel()) { |
| 157 | + return 3; |
| 158 | + } |
| 159 | + return 4; |
| 160 | + } |
| 161 | +} |
0 commit comments