Source code

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