001/*-
002 * #%L
003 * HAPI FHIR Subscription Server
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.jpa.subscription.util;
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.jpa.searchparam.matcher.InMemoryMatchResult;
026import ca.uhn.fhir.jpa.subscription.model.CanonicalSubscriptionChannelType;
027import ca.uhn.fhir.jpa.subscription.model.ResourceDeliveryMessage;
028import ca.uhn.fhir.jpa.subscription.model.ResourceModifiedMessage;
029import ca.uhn.fhir.util.StopWatch;
030import org.slf4j.Logger;
031import org.slf4j.LoggerFactory;
032import org.slf4j.event.Level;
033
034import java.util.Date;
035import java.util.EnumMap;
036import java.util.function.Function;
037
038/**
039 * This interceptor can be used for troubleshooting subscription processing. It provides very
040 * detailed logging about the subscription processing pipeline.
041 * <p>
042 * This interceptor logs each step in the processing pipeline with a
043 * different event code, using the event codes itemized in
044 * {@link EventCodeEnum}. By default these are each placed in a logger with
045 * a different name (e.g. <code>ca.uhn.fhir.jpa.subscription.util.SubscriptionDebugLogInterceptor.SUBS20</code>
046 * in order to facilitate fine-grained logging controls where some codes are omitted and
047 * some are not.
048 * </p>
049 * <p>
050 * A custom log factory can also be passed in, in which case the logging
051 * creation may use another strategy.
052 * </p>
053 *
054 * @see EventCodeEnum
055 * @since 3.7.0
056 */
057@Interceptor
058public class SubscriptionDebugLogInterceptor {
059
060        private static final String SUBSCRIPTION_DEBUG_LOG_INTERCEPTOR_PRECHECK =
061                        "SubscriptionDebugLogInterceptor_precheck";
062        private final Level myLevel;
063        private final EnumMap<EventCodeEnum, Logger> myLoggers;
064
065        /**
066         * Constructor that logs at INFO level to the logger <code>ca.uhn.fhir.jpa.subscription.util.SubscriptionDebugLogInterceptor</code>
067         */
068        public SubscriptionDebugLogInterceptor() {
069                this(defaultLogFactory(), Level.INFO);
070        }
071
072        /**
073         * Constructor using a specific logger
074         */
075        public SubscriptionDebugLogInterceptor(Function<EventCodeEnum, Logger> theLogFactory, Level theLevel) {
076                myLevel = theLevel;
077                myLoggers = new EnumMap<>(EventCodeEnum.class);
078                for (EventCodeEnum next : EventCodeEnum.values()) {
079                        myLoggers.put(next, theLogFactory.apply(next));
080                }
081        }
082
083        @Hook(Pointcut.SUBSCRIPTION_RESOURCE_MODIFIED)
084        public void step10_resourceModified(ResourceModifiedMessage theMessage) {
085                String value = Long.toString(System.currentTimeMillis());
086                theMessage.setAttribute(SUBSCRIPTION_DEBUG_LOG_INTERCEPTOR_PRECHECK, value);
087                String resourceId = theMessage.getPayloadId();
088                if (resourceId == null) {
089                        // Delete operations have no payload
090                        resourceId = theMessage.getId();
091                }
092                log(
093                                EventCodeEnum.SUBS1,
094                                "Resource {} is starting the processing pipeline (op={})",
095                                resourceId,
096                                theMessage.getOperationType());
097        }
098
099        /*
100         * These methods are numbered in the order that an individual
101         * resource would go through them, for clarity and ease of
102         * tracing when debugging and poring over logs.
103         *
104         * I don't know if this numbering scheme makes sense.. I'm incrementing
105         * by 10 for each step in the normal delivery pipeline, leaving lots of
106         * gaps to add things if we ever need them.
107         */
108
109        @Hook(Pointcut.SUBSCRIPTION_BEFORE_PERSISTED_RESOURCE_CHECKED)
110        public void step20_beforeChecked(ResourceModifiedMessage theMessage) {
111                log(
112                                EventCodeEnum.SUBS2,
113                                "Checking resource {} (op={}) for matching subscriptions",
114                                theMessage.getPayloadId(),
115                                theMessage.getOperationType());
116        }
117
118        @Hook(Pointcut.SUBSCRIPTION_RESOURCE_MATCHED)
119        public void step30_subscriptionMatched(ResourceDeliveryMessage theMessage, InMemoryMatchResult theResult) {
120                log(
121                                EventCodeEnum.SUBS3,
122                                "Resource {} matched by subscription {} (memory match={})",
123                                theMessage.getPayloadId(),
124                                theMessage.getSubscription().getIdElementString(),
125                                theResult.isInMemory());
126        }
127
128        @Hook(Pointcut.SUBSCRIPTION_RESOURCE_DID_NOT_MATCH_ANY_SUBSCRIPTIONS)
129        public void step35_subscriptionNotMatched(ResourceModifiedMessage theMessage) {
130                log(EventCodeEnum.SUBS4, "Resource {} did not match any subscriptions", theMessage.getPayloadId());
131        }
132
133        @Hook(Pointcut.SUBSCRIPTION_BEFORE_DELIVERY)
134        public void step40_beforeDelivery(ResourceDeliveryMessage theMessage) {
135                log(
136                                EventCodeEnum.SUBS5,
137                                "Delivering resource {} for subscription {} to channel of type {} to endpoint {}",
138                                theMessage.getPayloadId(),
139                                theMessage.getSubscription().getIdElementString(),
140                                theMessage.getSubscription().getChannelType(),
141                                theMessage.getSubscription().getEndpointUrl());
142        }
143
144        @Hook(Pointcut.SUBSCRIPTION_AFTER_DELIVERY_FAILED)
145        public void step45_deliveryFailed(ResourceDeliveryMessage theMessage, Exception theFailure) {
146                String payloadId = null;
147                String subscriptionId = null;
148                CanonicalSubscriptionChannelType channelType = null;
149                String failureString = null;
150                if (theMessage != null) {
151                        payloadId = theMessage.getPayloadId();
152                        if (theMessage.getSubscription() != null) {
153                                subscriptionId = theMessage.getSubscription().getIdElementString();
154                                channelType = theMessage.getSubscription().getChannelType();
155                        }
156                }
157                if (theFailure != null) {
158                        failureString = theFailure.toString();
159                }
160                log(
161                                EventCodeEnum.SUBS6,
162                                "Delivery of resource {} for subscription {} to channel of type {} - Failure: {}",
163                                payloadId,
164                                subscriptionId,
165                                channelType,
166                                failureString);
167        }
168
169        @Hook(Pointcut.SUBSCRIPTION_AFTER_DELIVERY)
170        public void step50_afterDelivery(ResourceDeliveryMessage theMessage) {
171                String processingTime = theMessage
172                                .getAttribute(SUBSCRIPTION_DEBUG_LOG_INTERCEPTOR_PRECHECK)
173                                .map(Long::parseLong)
174                                .map(Date::new)
175                                .map(start -> new StopWatch(start).toString())
176                                .orElse("(unknown)");
177
178                log(
179                                EventCodeEnum.SUBS7,
180                                "Finished delivery of resource {} for subscription {} to channel of type {} - Total processing time: {}",
181                                theMessage.getPayloadId(),
182                                theMessage.getSubscription().getIdElementString(),
183                                theMessage.getSubscription().getChannelType(),
184                                processingTime);
185        }
186
187        protected void log(EventCodeEnum theEventCode, String theMessage, Object... theArguments) {
188                Logger logger = myLoggers.get(theEventCode);
189                if (logger != null) {
190                        switch (myLevel) {
191                                case ERROR:
192                                        logger.error(theMessage, theArguments);
193                                        break;
194                                case WARN:
195                                        logger.warn(theMessage, theArguments);
196                                        break;
197                                case INFO:
198                                        logger.info(theMessage, theArguments);
199                                        break;
200                                case DEBUG:
201                                        logger.debug(theMessage, theArguments);
202                                        break;
203                                case TRACE:
204                                        logger.trace(theMessage, theArguments);
205                                        break;
206                        }
207                }
208        }
209
210        public enum EventCodeEnum {
211                /**
212                 * A new/updated resource has been submitted to the processing pipeline and is about
213                 * to be placed on the matchign queue.
214                 */
215                SUBS1,
216                /**
217                 * A resources has been dequeued from the matching queue and is about to be checked
218                 * for any matching subscriptions.
219                 */
220                SUBS2,
221                /**
222                 * The resource has matched a subscription (logged once for each matching subscription)
223                 * and is about to be queued for delivery.
224                 */
225                SUBS3,
226                /**
227                 * The resource did not match any subscriptions and processing is complete.
228                 */
229                SUBS4,
230                /**
231                 * The resource has been dequeued from the delivery queue and is about to be
232                 * delivered.
233                 */
234                SUBS5,
235                /**
236                 * Delivery failed
237                 */
238                SUBS6,
239                /**
240                 * Delivery is now complete and processing is finished.
241                 */
242                SUBS7
243        }
244
245        private static Function<EventCodeEnum, Logger> defaultLogFactory() {
246                return code -> LoggerFactory.getLogger(SubscriptionDebugLogInterceptor.class.getName() + "." + code.name());
247        }
248}