Source code

001/*
002 * #%L
003 * HAPI FHIR - Server Framework
004 * %%
005 * Copyright (C) 2014 - 2025 Smile CDR, Inc.
006 * %%
007 * Licensed under the Apache License, Version 2.0 (the "License");
008 * you may not use this file except in compliance with the License.
009 * You may obtain a copy of the License at
010 *
011 *      http://www.apache.org/licenses/LICENSE-2.0
012 *
013 * Unless required by applicable law or agreed to in writing, software
014 * distributed under the License is distributed on an "AS IS" BASIS,
015 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
016 * See the License for the specific language governing permissions and
017 * limitations under the License.
018 * #L%
019 */
020package ca.uhn.fhir.rest.server.interceptor;
021
022import ca.uhn.fhir.interceptor.api.Hook;
023import ca.uhn.fhir.interceptor.api.Interceptor;
024import ca.uhn.fhir.interceptor.api.Pointcut;
025import ca.uhn.fhir.model.primitive.IdDt;
026import ca.uhn.fhir.rest.api.Constants;
027import ca.uhn.fhir.rest.api.EncodingEnum;
028import ca.uhn.fhir.rest.api.server.RequestDetails;
029import ca.uhn.fhir.rest.server.RestfulServer;
030import ca.uhn.fhir.rest.server.RestfulServerUtils;
031import ca.uhn.fhir.rest.server.RestfulServerUtils.ResponseEncoding;
032import ca.uhn.fhir.rest.server.exceptions.BaseServerResponseException;
033import ca.uhn.fhir.rest.server.servlet.ServletRequestDetails;
034import ca.uhn.fhir.util.UrlUtil;
035import jakarta.servlet.ServletException;
036import jakarta.servlet.http.HttpServletRequest;
037import jakarta.servlet.http.HttpServletResponse;
038import org.apache.commons.lang3.StringUtils;
039import org.apache.commons.lang3.Validate;
040import org.apache.commons.text.StringSubstitutor;
041import org.apache.commons.text.lookup.StringLookup;
042import org.slf4j.Logger;
043import org.slf4j.LoggerFactory;
044
045import java.io.IOException;
046import java.util.Date;
047import java.util.Map.Entry;
048
049import static org.apache.commons.lang3.StringUtils.isNotBlank;
050
051/**
052 * Server interceptor which logs each request using a defined format
053 * <p>
054 * The following substitution variables are supported:
055 * </p>
056 * <table summary="Substitution variables supported by this class">
057 * <tr>
058 * <td>${id}</td>
059 * <td>The resource ID associated with this request (or "" if none)</td>
060 * </tr>
061 * <tr>
062 * <td>${idOrResourceName}</td>
063 * <td>The resource ID associated with this request, or the resource name if the request applies to a type but not an
064 * instance, or "" otherwise</td>
065 * </tr>
066 * <tr>
067 * <td>${operationName}</td>
068 * <td>If the request is an extended operation (e.g. "$validate") this value will be the operation name, or ""
069 * otherwise</td>
070 * </tr>
071 * <tr>
072 * <td>${requestId}</td>
073 * <td>The request ID assigned to this request (either automatically, or via the <code>X-Request-ID</code> header in the request)</td>
074 * </tr>
075 * <tr>
076 * <td>${operationType}</td>
077 * <td>A code indicating the operation type for this request, e.g. "read", "history-instance",
078 * "extended-operation-instance", etc.)</td>
079 * </tr>
080 * <tr>
081 * <td>${remoteAddr}</td>
082 * <td>The originating IP of the request</td>
083 * </tr>
084 * <tr>
085 * <td>${requestHeader.XXXX}</td>
086 * <td>The value of the HTTP request header named XXXX. For example, a substitution variable named
087 * "${requestHeader.x-forwarded-for} will yield the value of the first header named "x-forwarded-for
088 * ", or "" if none.</td>
089 * </tr>
090 * <tr>
091 * <td>${requestParameters}</td>
092 * <td>The HTTP request parameters (or "")</td>
093 * </tr>
094 * <tr>
095 * <td>${responseEncodingNoDefault}</td>
096 * <td>The encoding format requested by the client via the _format parameter or the Accept header. Value will be "json"
097 * or "xml", or "" if the client did not explicitly request a format</td>
098 * </tr>
099 * <tr>
100 * <td>${servletPath}</td>
101 * <td>The part of thre requesting URL that corresponds to the particular Servlet being called (see
102 * {@link HttpServletRequest#getServletPath()})</td>
103 * </tr>
104 * <tr>
105 * <td>${requestBodyFhir}</td>
106 * <td>The complete body of the request if the request has a FHIR content-type (this can be quite large!). Will emit an
107 * empty string if the content type is not a FHIR content type</td>
108 * </tr>
109 * <tr>
110 * <td>${requestUrl}</td>
111 * <td>The complete URL of the request</td>
112 * </tr>
113 * <tr>
114 * <td>${requestVerb}</td>
115 * <td>The HTTP verb of the request</td>
116 * </tr>
117 * <tr>
118 * <td>${responseId}</td>
119 * <td>For operations which write a resource (create/update/patch), provides the ID of that resource as supplied in the <code>Location</code> header.</td>
120 * </tr>
121 * <tr>
122 * <td>${exceptionMessage}</td>
123 * <td>Applies only to an error message: The message from {@link Exception#getMessage()}</td>
124 * </tr>
125 * <tr>
126 * <td>${processingTimeMillis}</td>
127 * <td>The number of milliseconds spen processing this request</td>
128 * </tr>
129 * </table>
130 */
131@Interceptor
132public class LoggingInterceptor {
133
134        private static final Logger ourLog = LoggerFactory.getLogger(LoggingInterceptor.class);
135
136        private String myErrorMessageFormat = "ERROR - ${operationType} - ${idOrResourceName}";
137        private boolean myLogExceptions = true;
138        private Logger myLogger = ourLog;
139        private String myMessageFormat = "${operationType} - ${idOrResourceName}";
140
141        /**
142         * Constructor for server logging interceptor
143         */
144        public LoggingInterceptor() {
145                super();
146        }
147
148        /**
149         * Get the log message format to be used when logging exceptions
150         */
151        public String getErrorMessageFormat() {
152                return myErrorMessageFormat;
153        }
154
155        @Hook(Pointcut.SERVER_HANDLE_EXCEPTION)
156        public boolean handleException(
157                        RequestDetails theRequestDetails,
158                        BaseServerResponseException theException,
159                        HttpServletRequest theServletRequest,
160                        HttpServletResponse theServletResponse)
161                        throws ServletException, IOException {
162                if (myLogExceptions) {
163                        // Perform any string substitutions from the message format
164                        StringLookup lookup = new MyLookup(theServletRequest, theServletResponse, theException, theRequestDetails);
165                        StringSubstitutor subs = new StringSubstitutor(lookup, "${", "}", '\\');
166
167                        // Actually log the line
168                        String line = subs.replace(myErrorMessageFormat);
169                        myLogger.info(line);
170                }
171                return true;
172        }
173
174        @Hook(Pointcut.SERVER_PROCESSING_COMPLETED_NORMALLY)
175        public void processingCompletedNormally(ServletRequestDetails theRequestDetails) {
176                // Perform any string substitutions from the message format
177                StringLookup lookup = new MyLookup(
178                                theRequestDetails.getServletRequest(), theRequestDetails.getServletResponse(), theRequestDetails);
179                StringSubstitutor subs = new StringSubstitutor(lookup, "${", "}", '\\');
180
181                // Actually log the line
182                String line = subs.replace(myMessageFormat);
183                myLogger.info(line);
184        }
185
186        /**
187         * Should exceptions be logged by this logger
188         */
189        public boolean isLogExceptions() {
190                return myLogExceptions;
191        }
192
193        /**
194         * Set the log message format to be used when logging exceptions
195         */
196        public void setErrorMessageFormat(String theErrorMessageFormat) {
197                Validate.notBlank(theErrorMessageFormat, "Message format can not be null/empty");
198                myErrorMessageFormat = theErrorMessageFormat;
199        }
200
201        /**
202         * Should exceptions be logged by this logger
203         */
204        public void setLogExceptions(boolean theLogExceptions) {
205                myLogExceptions = theLogExceptions;
206        }
207
208        public void setLogger(Logger theLogger) {
209                Validate.notNull(theLogger, "Logger can not be null");
210                myLogger = theLogger;
211        }
212
213        public void setLoggerName(String theLoggerName) {
214                Validate.notBlank(theLoggerName, "Logger name can not be null/empty");
215                myLogger = LoggerFactory.getLogger(theLoggerName);
216        }
217
218        /**
219         * Sets the message format itself. See the {@link LoggingInterceptor class documentation} for information on the
220         * format
221         */
222        public void setMessageFormat(String theMessageFormat) {
223                Validate.notBlank(theMessageFormat, "Message format can not be null/empty");
224                myMessageFormat = theMessageFormat;
225        }
226
227        private static final class MyLookup implements StringLookup {
228                private final Throwable myException;
229                private final HttpServletRequest myRequest;
230                private final RequestDetails myRequestDetails;
231                private final HttpServletResponse myResponse;
232
233                private MyLookup(
234                                HttpServletRequest theRequest, HttpServletResponse theResponse, RequestDetails theRequestDetails) {
235                        myRequest = theRequest;
236                        myResponse = theResponse;
237                        myRequestDetails = theRequestDetails;
238                        myException = null;
239                }
240
241                MyLookup(
242                                HttpServletRequest theServletRequest,
243                                HttpServletResponse theResponse,
244                                BaseServerResponseException theException,
245                                RequestDetails theRequestDetails) {
246                        myException = theException;
247                        myRequestDetails = theRequestDetails;
248                        myRequest = theServletRequest;
249                        myResponse = theResponse;
250                }
251
252                @Override
253                public String lookup(String theKey) {
254
255                        /*
256                         * TODO: this method could be made more efficient through some sort of lookup map
257                         */
258
259                        switch (theKey) {
260                                case "operationType":
261                                        if (myRequestDetails.getRestOperationType() != null) {
262                                                return myRequestDetails.getRestOperationType().getCode();
263                                        }
264                                        return "";
265                                case "operationName":
266                                        if (myRequestDetails.getRestOperationType() != null) {
267                                                //noinspection EnumSwitchStatementWhichMissesCases
268                                                switch (myRequestDetails.getRestOperationType()) {
269                                                        case EXTENDED_OPERATION_INSTANCE:
270                                                        case EXTENDED_OPERATION_SERVER:
271                                                        case EXTENDED_OPERATION_TYPE:
272                                                                return myRequestDetails.getOperation();
273                                                        default:
274                                                                return "";
275                                                }
276                                        }
277                                        return "";
278                                case "id":
279                                        if (myRequestDetails.getId() != null) {
280                                                return myRequestDetails.getId().getValue();
281                                        }
282                                        return "";
283                                case "servletPath":
284                                        return StringUtils.defaultString(myRequest.getServletPath());
285                                case "idOrResourceName":
286                                        if (myRequestDetails.getId() != null) {
287                                                return myRequestDetails.getId().getValue();
288                                        }
289                                        if (myRequestDetails.getResourceName() != null) {
290                                                return myRequestDetails.getResourceName();
291                                        }
292                                        return "";
293                                case "requestParameters":
294                                        StringBuilder b = new StringBuilder();
295                                        for (Entry<String, String[]> next :
296                                                        myRequestDetails.getParameters().entrySet()) {
297                                                for (String nextValue : next.getValue()) {
298                                                        if (b.length() == 0) {
299                                                                b.append('?');
300                                                        } else {
301                                                                b.append('&');
302                                                        }
303                                                        b.append(UrlUtil.escapeUrlParam(next.getKey()));
304                                                        b.append('=');
305                                                        b.append(UrlUtil.escapeUrlParam(nextValue));
306                                                }
307                                        }
308                                        return b.toString();
309                                case "remoteAddr":
310                                        return StringUtils.defaultString(myRequest.getRemoteAddr());
311                                case "responseEncodingNoDefault": {
312                                        ResponseEncoding encoding = RestfulServerUtils.determineResponseEncodingNoDefault(
313                                                        myRequestDetails, myRequestDetails.getServer().getDefaultResponseEncoding());
314                                        if (encoding != null) {
315                                                return encoding.getEncoding().name();
316                                        }
317                                        return "";
318                                }
319                                case "exceptionMessage":
320                                        return myException != null ? myException.getMessage() : null;
321                                case "requestUrl":
322                                        return myRequest.getRequestURL().toString();
323                                case "requestVerb":
324                                        return myRequest.getMethod();
325                                case "requestBodyFhir": {
326                                        String contentType = myRequest.getContentType();
327                                        if (isNotBlank(contentType)) {
328                                                int colonIndex = contentType.indexOf(';');
329                                                if (colonIndex != -1) {
330                                                        contentType = contentType.substring(0, colonIndex);
331                                                }
332                                                contentType = contentType.trim();
333
334                                                EncodingEnum encoding = EncodingEnum.forContentType(contentType);
335                                                if (encoding != null) {
336                                                        byte[] requestContents = myRequestDetails.loadRequestContents();
337                                                        return new String(requestContents, Constants.CHARSET_UTF8);
338                                                }
339                                        }
340                                        return "";
341                                }
342                                case "processingTimeMillis":
343                                        Date startTime = (Date) myRequest.getAttribute(RestfulServer.REQUEST_START_TIME);
344                                        if (startTime != null) {
345                                                long time = System.currentTimeMillis() - startTime.getTime();
346                                                return Long.toString(time);
347                                        }
348                                        break;
349                                case "requestId":
350                                        return myRequestDetails.getRequestId();
351                                case "responseId":
352                                        String locationHeader = myResponse.getHeader(Constants.HEADER_LOCATION);
353                                        if (isNotBlank(locationHeader)) {
354                                                return new IdDt(locationHeader).toUnqualified().getValue();
355                                        }
356                                        return "";
357                                default:
358                                        if (theKey.startsWith("requestHeader.")) {
359                                                String val = myRequest.getHeader(theKey.substring("requestHeader.".length()));
360                                                return StringUtils.defaultString(val);
361                                        }
362                        }
363
364                        return "!VAL!";
365                }
366        }
367}