Line data Source code
1 : // Copyright (C) 2018 The Android Open Source Project
2 : //
3 : // Licensed under the Apache License, Version 2.0 (the "License");
4 : // you may not use this file except in compliance with the License.
5 : // You may obtain a copy of the License at
6 : //
7 : // http://www.apache.org/licenses/LICENSE-2.0
8 : //
9 : // Unless required by applicable law or agreed to in writing, software
10 : // distributed under the License is distributed on an "AS IS" BASIS,
11 : // WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
12 : // See the License for the specific language governing permissions and
13 : // limitations under the License.
14 :
15 : package com.google.gerrit.server.logging;
16 :
17 : import static java.util.Objects.requireNonNull;
18 :
19 : import com.google.common.base.Stopwatch;
20 : import com.google.common.base.Strings;
21 : import com.google.common.collect.HashBasedTable;
22 : import com.google.common.collect.ImmutableList;
23 : import com.google.common.collect.ImmutableMap;
24 : import com.google.common.collect.Table;
25 : import com.google.common.flogger.FluentLogger;
26 : import com.google.gerrit.common.Nullable;
27 : import com.google.gerrit.server.cancellation.RequestStateContext;
28 : import java.util.Optional;
29 : import java.util.concurrent.TimeUnit;
30 : import java.util.function.Consumer;
31 :
32 : /**
33 : * TraceContext that allows to set logging tags and enforce logging.
34 : *
35 : * <p>The logging tags are attached to all log entries that are triggered while the trace context is
36 : * open. If force logging is enabled all logs that are triggered while the trace context is open are
37 : * written to the log file regardless of the configured log level.
38 : *
39 : * <pre>
40 : * try (TraceContext traceContext = TraceContext.open()
41 : * .addTag("tag-name", "tag-value")
42 : * .forceLogging()) {
43 : * // This gets logged as: A log [CONTEXT forced=true tag-name="tag-value" ]
44 : * // Since force logging is enabled this gets logged independently of the configured log
45 : * // level.
46 : * logger.atFinest().log("A log");
47 : *
48 : * // do stuff
49 : * }
50 : * </pre>
51 : *
52 : * <p>The logging tags and the force logging flag are stored in the {@link LoggingContext}. {@link
53 : * LoggingContextAwareExecutorService}, {@link LoggingContextAwareScheduledExecutorService} and the
54 : * executor in {@link com.google.gerrit.server.git.WorkQueue} ensure that the logging context is
55 : * automatically copied to background threads.
56 : *
57 : * <p>On close of the trace context newly set tags are unset. Force logging is disabled on close if
58 : * it got enabled while the trace context was open.
59 : *
60 : * <p>Trace contexts can be nested:
61 : *
62 : * <pre>
63 : * // Initially there are no tags
64 : * logger.atSevere().log("log without tag");
65 : *
66 : * // a tag can be set by opening a trace context
67 : * try (TraceContext ctx = TraceContext.open().addTag("tag1", "value1")) {
68 : * logger.atSevere().log("log with tag1=value1");
69 : *
70 : * // while a trace context is open further tags can be added.
71 : * ctx.addTag("tag2", "value2")
72 : * logger.atSevere().log("log with tag1=value1 and tag2=value2");
73 : *
74 : * // also by opening another trace context a another tag can be added
75 : * try (TraceContext ctx2 = TraceContext.open().addTag("tag3", "value3")) {
76 : * logger.atSevere().log("log with tag1=value1, tag2=value2 and tag3=value3");
77 : *
78 : * // it's possible to have the same tag name with multiple values
79 : * ctx2.addTag("tag3", "value3a")
80 : * logger.atSevere().log("log with tag1=value1, tag2=value2, tag3=value3 and tag3=value3a");
81 : *
82 : * // adding a tag with the same name and value as an existing tag has no effect
83 : * try (TraceContext ctx3 = TraceContext.open().addTag("tag3", "value3a")) {
84 : * logger.atSevere().log("log with tag1=value1, tag2=value2, tag3=value3 and tag3=value3a");
85 : * }
86 : *
87 : * // closing ctx3 didn't remove tag3=value3a since it was already set before opening ctx3
88 : * logger.atSevere().log("log with tag1=value1, tag2=value2, tag3=value3 and tag3=value3a");
89 : * }
90 : *
91 : * // closing ctx2 removed tag3=value3 and tag3-value3a
92 : * logger.atSevere().log("with tag1=value1 and tag2=value2");
93 : * }
94 : *
95 : * // closing ctx1 removed tag1=value1 and tag2=value2
96 : * logger.atSevere().log("log without tag");
97 : * </pre>
98 : */
99 : public class TraceContext implements AutoCloseable {
100 : private static final String PLUGIN_TAG = "PLUGIN";
101 :
102 : public static TraceContext open() {
103 151 : return new TraceContext();
104 : }
105 :
106 : /**
107 : * Opens a new trace context for request tracing.
108 : *
109 : * <ul>
110 : * <li>sets a tag with a trace ID
111 : * <li>enables force logging
112 : * </ul>
113 : *
114 : * <p>if no trace ID is provided a new trace ID is only generated if request tracing was not
115 : * started yet. If request tracing was already started the given {@code traceIdConsumer} is
116 : * invoked with the existing trace ID and no new logging tag is set.
117 : *
118 : * <p>No-op if {@code trace} is {@code false}.
119 : *
120 : * @param trace whether tracing should be started
121 : * @param traceId trace ID that should be used for tracing, if {@code null} a trace ID is
122 : * generated
123 : * @param traceIdConsumer consumer for the trace ID, should be used to return the generated trace
124 : * ID to the client, not invoked if {@code trace} is {@code false}
125 : * @return the trace context
126 : */
127 : public static TraceContext newTrace(
128 : boolean trace, @Nullable String traceId, TraceIdConsumer traceIdConsumer) {
129 106 : if (!trace) {
130 : // Create an empty trace context.
131 106 : return open();
132 : }
133 :
134 7 : if (!Strings.isNullOrEmpty(traceId)) {
135 7 : traceIdConsumer.accept(RequestId.Type.TRACE_ID.name(), traceId);
136 7 : return open().addTag(RequestId.Type.TRACE_ID, traceId).forceLogging();
137 : }
138 :
139 : Optional<String> existingTraceId =
140 3 : LoggingContext.getInstance().getTagsAsMap().get(RequestId.Type.TRACE_ID.name()).stream()
141 3 : .findAny();
142 3 : if (existingTraceId.isPresent()) {
143 : // request tracing was already started, no need to generate a new trace ID
144 1 : traceIdConsumer.accept(RequestId.Type.TRACE_ID.name(), existingTraceId.get());
145 1 : return open();
146 : }
147 :
148 3 : RequestId newTraceId = new RequestId();
149 3 : traceIdConsumer.accept(RequestId.Type.TRACE_ID.name(), newTraceId.toString());
150 3 : return open().addTag(RequestId.Type.TRACE_ID, newTraceId).forceLogging();
151 : }
152 :
153 : @FunctionalInterface
154 : public interface TraceIdConsumer {
155 : void accept(String tagName, String traceId);
156 : }
157 :
158 : /**
159 : * Opens a new timer that logs the time for an operation if request tracing is enabled.
160 : *
161 : * @param operation the name of operation the is being performed
162 : * @return the trace timer
163 : */
164 : public static TraceTimer newTimer(String operation) {
165 148 : return new TraceTimer(requireNonNull(operation, "operation is required"));
166 : }
167 :
168 : /**
169 : * Opens a new timer that logs the time for an operation if request tracing is enabled.
170 : *
171 : * @param operation the name of operation the is being performed
172 : * @param metadata metadata
173 : * @return the trace timer
174 : */
175 : public static TraceTimer newTimer(String operation, Metadata metadata) {
176 154 : return new TraceTimer(
177 154 : requireNonNull(operation, "operation is required"),
178 154 : requireNonNull(metadata, "metadata is required"));
179 : }
180 :
181 : public static class TraceTimer implements AutoCloseable {
182 154 : private static final FluentLogger logger = FluentLogger.forEnclosingClass();
183 :
184 : private final Consumer<Long> doneLogFn;
185 : private final Stopwatch stopwatch;
186 :
187 : private TraceTimer(String operation) {
188 148 : this(
189 148 : () -> logger.atFine().log("Starting timer for %s", operation),
190 : elapsedMs -> {
191 148 : LoggingContext.getInstance()
192 148 : .addPerformanceLogRecord(() -> PerformanceLogRecord.create(operation, elapsedMs));
193 148 : logger.atFine().log("%s done (%d ms)", operation, elapsedMs);
194 148 : });
195 148 : }
196 :
197 : private TraceTimer(String operation, Metadata metadata) {
198 154 : this(
199 : () ->
200 154 : logger.atFine().log(
201 154 : "Starting timer for %s (%s)", operation, metadata.toStringForLoggingLazy()),
202 : elapsedMs -> {
203 154 : LoggingContext.getInstance()
204 154 : .addPerformanceLogRecord(
205 3 : () -> PerformanceLogRecord.create(operation, elapsedMs, metadata));
206 154 : logger.atFine().log(
207 154 : "%s (%s) done (%d ms)", operation, metadata.toStringForLoggingLazy(), elapsedMs);
208 154 : });
209 154 : }
210 :
211 154 : private TraceTimer(Runnable startLogFn, Consumer<Long> doneLogFn) {
212 154 : RequestStateContext.abortIfCancelled();
213 154 : startLogFn.run();
214 154 : this.doneLogFn = doneLogFn;
215 154 : this.stopwatch = Stopwatch.createStarted();
216 154 : }
217 :
218 : @Override
219 : public void close() {
220 154 : stopwatch.stop();
221 154 : doneLogFn.accept(stopwatch.elapsed(TimeUnit.MILLISECONDS));
222 154 : RequestStateContext.abortIfCancelled();
223 154 : }
224 : }
225 :
226 : // Table<TAG_NAME, TAG_VALUE, REMOVE_ON_CLOSE>
227 151 : private final Table<String, String, Boolean> tags = HashBasedTable.create();
228 :
229 : private final boolean oldAclLogging;
230 : private final ImmutableList<String> oldAclLogRecords;
231 :
232 : private boolean stopForceLoggingOnClose;
233 : private boolean stopAclLoggingOnClose;
234 :
235 151 : private TraceContext() {
236 : // Just in case remember the old state and reset ACL log entries.
237 151 : this.oldAclLogging = LoggingContext.getInstance().isAclLogging();
238 151 : this.oldAclLogRecords = LoggingContext.getInstance().getAclLogRecords();
239 151 : }
240 :
241 : public TraceContext addTag(RequestId.Type requestId, Object tagValue) {
242 103 : return addTag(requireNonNull(requestId, "request ID is required").name(), tagValue);
243 : }
244 :
245 : public TraceContext addTag(String tagName, Object tagValue) {
246 151 : String name = requireNonNull(tagName, "tag name is required");
247 151 : String value = requireNonNull(tagValue, "tag value is required").toString();
248 151 : tags.put(name, value, LoggingContext.getInstance().addTag(name, value));
249 151 : return this;
250 : }
251 :
252 : public ImmutableMap<String, String> getTags() {
253 96 : ImmutableMap.Builder<String, String> tagMap = ImmutableMap.builder();
254 96 : tags.cellSet().forEach(c -> tagMap.put(c.getRowKey(), c.getColumnKey()));
255 96 : return tagMap.build();
256 : }
257 :
258 : public TraceContext addPluginTag(String pluginName) {
259 151 : return addTag(PLUGIN_TAG, pluginName);
260 : }
261 :
262 : public TraceContext forceLogging() {
263 7 : if (stopForceLoggingOnClose) {
264 1 : return this;
265 : }
266 :
267 7 : stopForceLoggingOnClose = !LoggingContext.getInstance().forceLogging(true);
268 7 : return this;
269 : }
270 :
271 : public static boolean isTracing() {
272 28 : return LoggingContext.getInstance().isLoggingForced();
273 : }
274 :
275 : public static Optional<String> getTraceId() {
276 2 : return LoggingContext.getInstance().getTagsAsMap().get(RequestId.Type.TRACE_ID.name()).stream()
277 2 : .findFirst();
278 : }
279 :
280 : public static Optional<String> getPluginTag() {
281 0 : return getTag(PLUGIN_TAG);
282 : }
283 :
284 : public static Optional<String> getTag(String tagName) {
285 0 : return LoggingContext.getInstance().getTagsAsMap().get(tagName).stream().findFirst();
286 : }
287 :
288 : public TraceContext enableAclLogging() {
289 1 : if (stopAclLoggingOnClose) {
290 0 : return this;
291 : }
292 :
293 1 : stopAclLoggingOnClose = !LoggingContext.getInstance().aclLogging(true);
294 1 : return this;
295 : }
296 :
297 : public static ImmutableList<String> getAclLogRecords() {
298 1 : return LoggingContext.getInstance().getAclLogRecords();
299 : }
300 :
301 : @Override
302 : public void close() {
303 151 : for (Table.Cell<String, String, Boolean> cell : tags.cellSet()) {
304 151 : if (cell.getValue()) {
305 151 : LoggingContext.getInstance().removeTag(cell.getRowKey(), cell.getColumnKey());
306 : }
307 151 : }
308 151 : if (stopForceLoggingOnClose) {
309 7 : LoggingContext.getInstance().forceLogging(false);
310 : }
311 :
312 151 : if (stopAclLoggingOnClose) {
313 1 : LoggingContext.getInstance().aclLogging(oldAclLogging);
314 1 : LoggingContext.getInstance().setAclLogRecords(oldAclLogRecords);
315 : }
316 151 : }
317 : }
|
