001/* 002 * Licensed to the Apache Software Foundation (ASF) under one or more 003 * contributor license agreements. See the NOTICE file distributed with 004 * this work for additional information regarding copyright ownership. 005 * The ASF licenses this file to You under the Apache License, Version 2.0 006 * (the "License"); you may not use this file except in compliance with 007 * the License. You may obtain a copy of the License at 008 * 009 * http://www.apache.org/licenses/LICENSE-2.0 010 * 011 * Unless required by applicable law or agreed to in writing, software 012 * distributed under the License is distributed on an "AS IS" BASIS, 013 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 014 * See the License for the specific language governing permissions and 015 * limitations under the License. 016 */ 017package org.apache.juneau.rest.server.logging; 018 019import static org.apache.juneau.commons.utils.Shorts.*; 020 021import java.util.logging.*; 022 023import org.apache.juneau.commons.logging.LogRecordContext; 024import org.apache.juneau.commons.logging.RichLogger; 025import org.apache.juneau.http.header.NoTrace; 026import org.apache.juneau.rest.server.*; 027 028import jakarta.servlet.http.*; 029 030/** 031 * The request-completion half of the JUL-level-driven REST debug pipeline. 032 * 033 * <p> 034 * The request-start half is handled by {@code RestContext}/{@code RestOpContext}, which install bounded body-caching 035 * wrappers only when the resolved logger is loggable at {@link Level#FINEST FINEST}. This class re-derives the cumulative 036 * tier from the resolved logger, renders a single cumulative message through the resolved {@link RestDebugFormatter}, 037 * and emits exactly one {@link LogRecord}: 038 * <ul> 039 * <li>tier {@code INFO} — {@code formatBasic} only. 040 * <li>tier {@code FINE} — {@code +formatHeaders}. 041 * <li>tier {@code FINEST} — {@code +formatBody} (from the cached bytes). 042 * <li>coarser than {@code INFO} ({@code WARNING}, {@code SEVERE}, {@code OFF}) — nothing is emitted. 043 * </ul> 044 * The emitted record level is always {@link Level#INFO}; the resolved tier controls message detail only. 045 * 046 * @since 10.0.0 047 */ 048public class RestDebugPipeline { 049 050 /** Contains any diagnostic-formatting failure on the completion path (mirrors {@code RestSession.finish()}). */ 051 private static final RichLogger LOG = RichLogger.getLogger(RestDebugPipeline.class); 052 053 private RestDebugPipeline() {} 054 055 /** 056 * Emits one debug record for the completed call on the synchronous request thread, if the resolved logger's 057 * effective level warrants it. 058 * 059 * <p> 060 * This is the synchronous entry point: it resolves the logger/formatter/detail-tier <i>now</i> (the operation is 061 * already resolved by finish time) and renders/emits immediately. The emitted record is always stamped at 062 * {@link Level#INFO}; the resolved tier controls only which sections are rendered into the message body. 063 * 064 * @param session The completed REST session. Must not be <jk>null</jk>. 065 */ 066 public static void emit(RestSession session) { 067 emit(session, snapshot(session)); 068 } 069 070 /** 071 * Resolves the logger/formatter/detail-tier snapshot for the given session and stashes it on the session for 072 * later completion-path emission. 073 * 074 * <p> 075 * Called on the request thread at the async-dispatch handoff, before any completion callback is registered, so the 076 * immutable snapshot is safely published to the completion thread. Stashes <jk>null</jk> when access logging is off 077 * (no allocation), keeping {@link #emitOnCompletion(RestSession)} a no-op in that case. 078 * 079 * @param session The REST session being handed off to async dispatch. Must not be <jk>null</jk>. 080 */ 081 public static void captureAsyncSnapshot(RestSession session) { 082 session.stashDebugSnapshot(snapshot(session)); 083 } 084 085 /** 086 * Emits one debug record for a completed asynchronous call on the response-completion thread. 087 * 088 * <p> 089 * Reads the snapshot published on the request thread (via {@link #captureAsyncSnapshot(RestSession)}), sets 090 * finish-time attributes (such as {@code ExecTime}) immediately before rendering, and renders from the final 091 * request/response state now that the async body and headers have been written. No-ops when no snapshot was 092 * stashed (access logging off). Any diagnostic-formatting failure is contained so it cannot disrupt request 093 * cleanup or async-context completion. 094 * 095 * @param session The completed REST session. Can be <jk>null</jk> (no-op). 096 */ 097 public static void emitOnCompletion(RestSession session) { 098 if (session == null) 099 return; 100 // Contain diagnostic formatting/emission on the completion thread exactly as RestSession.finish() does on the 101 // request thread: log only a fixed token — never the message, body, or a second formatter pass — so a 102 // scrubber throwing new RuntimeException(body) cannot re-leak the secret the placeholder just refused. 103 try { 104 session.setFinishTimeAttributes(); 105 emit(session, (RestDebugSnapshot) session.getDebugSnapshot()); 106 } catch (Throwable t) { // NOSONAR - deliberate containment of any diagnostic failure at request completion. 107 LOG.log(Level.WARNING, "debug formatter failed"); 108 } 109 } 110 111 /** 112 * Resolves the logger/formatter/detail-tier for the given session. 113 * 114 * <p> 115 * Resolves the operation logger when an operation was created, else the resource logger. Returns <jk>null</jk> when 116 * access logging is off (no logger, the logger is coarser than {@code INFO}, or no level finer than the root default was configured for it), in which case nothing is emitted. 117 * 118 * @param session The REST session. Must not be <jk>null</jk>. 119 * @return The resolved snapshot, or <jk>null</jk> if access logging is off. 120 */ 121 static RestDebugSnapshot snapshot(RestSession session) { 122 var opSession = session.getOpSessionOrNull(); 123 var logger = opSession != null ? opSession.getContext().getLogger() : session.getContext().getLogger(); 124 if (logger == null) 125 return null; 126 127 var tier = resolveTier(logger); 128 if (tier == null) 129 return null; 130 131 // Capture the request thread's LogContext snapshot here (on the request thread, before any async handoff), so an 132 // async completion record can re-establish the structured requestId even though the completion thread's live 133 // LogContext is empty. Empty singleton when no context is active — no allocation. 134 return new RestDebugSnapshot(logger, resolveFormatter(session), tier, RichLogger.context().snapshot()); 135 } 136 137 /** 138 * Emits one debug record from the supplied resolution snapshot, reading the final request/response state at call 139 * time. 140 * 141 * <p> 142 * No-ops on a <jk>null</jk> snapshot. The emitted record is always stamped at {@link Level#INFO}; the snapshot's 143 * detail tier controls only how much of the message is rendered. 144 * 145 * @param session The completed REST session. Must not be <jk>null</jk>. 146 * @param snapshot The resolution snapshot, or <jk>null</jk> (no-op). 147 */ 148 static void emit(RestSession session, RestDebugSnapshot snapshot) { 149 if (snapshot == null) 150 return; 151 152 var opSession = session.getOpSessionOrNull(); 153 var msg = render(session, opSession, snapshot); 154 155 var logRecord = new LogRecord(Level.INFO, msg); 156 logRecord.setLoggerName(snapshot.logger().getName()); 157 var thrown = session.getException(); 158 if (thrown != null && ! isNoTrace(session.getRequest())) 159 logRecord.setThrown(thrown); 160 // Pre-seed the record's correlation context from the request-thread snapshot BEFORE log(). Because log()'s own 161 // attach (RichLogger) is attachIfAbsent and the completion thread's live LogContext is empty, the pre-seeded 162 // map wins — this is what carries requestId across the async hop. No-op / empty short-circuit 163 // inside attachIfAbsent when the map is empty (the common synchronous case). 164 LogRecordContext.attachIfAbsent(logRecord, snapshot.context()); 165 snapshot.logger().log(logRecord); 166 } 167 168 /** 169 * Returns <jk>true</jk> if the caller asked for the stack trace to be left off the log record, either with a 170 * <c>No-Trace: true</c> request header or by setting the <js>"NoTrace"</js> request attribute 171 * (see {@link RestRequest#setNoTrace()}). 172 */ 173 private static boolean isNoTrace(HttpServletRequest req) { 174 var attr = req.getAttribute("NoTrace"); 175 return b(or(attr, req.getHeader(NoTrace.NAME))); 176 } 177 178 private static String render(RestSession session, RestOpSession opSession, RestDebugSnapshot snapshot) { 179 var formatter = snapshot.formatter(); 180 181 // No operation resolved (404/no-op path): only the basic status line is renderable — there is no 182 // RestRequest/RestResponse to drive the formatter tiers through. The sanitized, length-capped instance 183 // statusLine (not a static-only path) renders it. 184 if (opSession == null) 185 return formatter.statusLine(session.getRequest(), session.getResponse()); 186 187 var level = snapshot.tier(); 188 var req = opSession.getRequest(); 189 var res = opSession.getResponse(); 190 191 var sb = new StringBuilder(formatter.formatBasic(req, res)); 192 if (level.intValue() <= Level.FINE.intValue()) 193 sb.append(formatter.formatHeaders(req, res)); 194 if (level.intValue() <= Level.FINEST.intValue()) 195 sb.append(formatter.formatBody(req, res)); 196 return sb.toString(); 197 } 198 199 private static RestDebugFormatter resolveFormatter(RestSession session) { 200 var f = session.getContext().getRestDebugFormatter(); 201 return f != null ? f : new BasicRestDebugFormatter(); 202 } 203 204 /** 205 * Maps the resolved logger's effective level to the cumulative debug tier. 206 * 207 * @param logger The resolved logger. 208 * @return {@code FINEST}/{@code FINE}/{@code INFO}, or <jk>null</jk> if the logger is coarser than {@code INFO} or sits at the stock 209 * root-inherited {@code INFO} (nothing configured for the resource). 210 */ 211 static Level resolveTier(Logger logger) { 212 if (logger.isLoggable(Level.FINEST)) 213 return Level.FINEST; 214 if (logger.isLoggable(Level.FINE)) 215 return Level.FINE; 216 if (logger.isLoggable(Level.INFO) && isInfoConfigured(logger)) 217 return Level.INFO; 218 return null; 219 } 220 221 /** 222 * Returns <jk>true</jk> if an {@code INFO}-or-finer level was set explicitly on the logger or one of its ancestors 223 * below the root logger. 224 * 225 * <p> 226 * Stock JUL leaves the root logger at {@code INFO}, so every logger is "loggable at INFO" by default. That default 227 * must not turn on the per-request status line; only a level configured for the resource (or an enclosing logger 228 * namespace) does. 229 */ 230 private static boolean isInfoConfigured(Logger logger) { 231 // A RichLogger is a wrapper outside the JUL hierarchy; its delegate is the logger that has parents. 232 for (var l = logger instanceof RichLogger r ? r.getDelegate() : logger; l != null && l.getParent() != null; l = l.getParent()) { 233 var level = l.getLevel(); 234 if (level != null) 235 return level.intValue() <= Level.INFO.intValue(); 236 } 237 return false; 238 } 239}