Source code

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