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} &mdash; {@code formatBasic} only.
040 *    <li>tier {@code FINE} &mdash; {@code +formatHeaders}.
041 *    <li>tier {@code FINEST} &mdash; {@code +formatBody} (from the cached bytes).
042 *    <li>coarser than {@code INFO} ({@code WARNING}, {@code SEVERE}, {@code OFF}) &mdash; 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}