
001/*- 002 * #%L 003 * HAPI FHIR Subscription Server 004 * %% 005 * Copyright (C) 2014 - 2023 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 loges 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 = "SubscriptionDebugLogInterceptor_precheck"; 061 private final Level myLevel; 062 private final EnumMap<EventCodeEnum, Logger> myLoggers; 063 064 /** 065 * Constructor that logs at INFO level to the logger <code>ca.uhn.fhir.jpa.subscription.util.SubscriptionDebugLogInterceptor</code> 066 */ 067 public SubscriptionDebugLogInterceptor() { 068 this(defaultLogFactory(), Level.INFO); 069 } 070 071 /** 072 * Constructor using a specific logger 073 */ 074 public SubscriptionDebugLogInterceptor(Function<EventCodeEnum, Logger> theLogFactory, Level theLevel) { 075 myLevel = theLevel; 076 myLoggers = new EnumMap<>(EventCodeEnum.class); 077 for (EventCodeEnum next : EventCodeEnum.values()) { 078 myLoggers.put(next, theLogFactory.apply(next)); 079 } 080 } 081 082 @Hook(Pointcut.SUBSCRIPTION_RESOURCE_MODIFIED) 083 public void step10_resourceModified(ResourceModifiedMessage theMessage) { 084 String value = Long.toString(System.currentTimeMillis()); 085 theMessage.setAttribute(SUBSCRIPTION_DEBUG_LOG_INTERCEPTOR_PRECHECK, value); 086 String resourceId = theMessage.getPayloadId(); 087 if (resourceId == null) { 088 // Delete operations have no payload 089 resourceId = theMessage.getId(); 090 } 091 log(EventCodeEnum.SUBS1, "Resource {} was submitted to the processing pipeline (op={})", resourceId, theMessage.getOperationType()); 092 } 093 094 /* 095 * These methods are numbered in the order that an individual 096 * resource would go through them, for clarity and ease of 097 * tracing when debugging and poring over logs. 098 * 099 * I don't know if this numbering scheme makes sense.. I'm incrementing 100 * by 10 for each step in the normal delivery pipeline, leaving lots of 101 * gaps to add things if we ever need them. 102 */ 103 104 @Hook(Pointcut.SUBSCRIPTION_BEFORE_PERSISTED_RESOURCE_CHECKED) 105 public void step20_beforeChecked(ResourceModifiedMessage theMessage) { 106 log(EventCodeEnum.SUBS2, "Checking resource {} (op={}) for matching subscriptions", theMessage.getPayloadId(), theMessage.getOperationType()); 107 } 108 109 @Hook(Pointcut.SUBSCRIPTION_RESOURCE_MATCHED) 110 public void step30_subscriptionMatched(ResourceDeliveryMessage theMessage, InMemoryMatchResult theResult) { 111 log(EventCodeEnum.SUBS3, "Resource {} matched by subscription {} (memory match={})", theMessage.getPayloadId(), theMessage.getSubscription().getIdElementString(), theResult.isInMemory()); 112 } 113 114 @Hook(Pointcut.SUBSCRIPTION_RESOURCE_DID_NOT_MATCH_ANY_SUBSCRIPTIONS) 115 public void step35_subscriptionNotMatched(ResourceModifiedMessage theMessage) { 116 log(EventCodeEnum.SUBS4, "Resource {} did not match any subscriptions", theMessage.getPayloadId()); 117 } 118 119 @Hook(Pointcut.SUBSCRIPTION_BEFORE_DELIVERY) 120 public void step40_beforeDelivery(ResourceDeliveryMessage theMessage) { 121 log(EventCodeEnum.SUBS5, "Delivering resource {} for subscription {} to channel of type {} to endpoint {}", theMessage.getPayloadId(), theMessage.getSubscription().getIdElementString(), theMessage.getSubscription().getChannelType(), theMessage.getSubscription().getEndpointUrl()); 122 } 123 124 @Hook(Pointcut.SUBSCRIPTION_AFTER_DELIVERY_FAILED) 125 public void step45_deliveryFailed(ResourceDeliveryMessage theMessage, Exception theFailure) { 126 String payloadId = null; 127 String subscriptionId = null; 128 CanonicalSubscriptionChannelType channelType = null; 129 String failureString = null; 130 if (theMessage != null) { 131 payloadId = theMessage.getPayloadId(); 132 if (theMessage.getSubscription() != null) { 133 subscriptionId = theMessage.getSubscription().getIdElementString(); 134 channelType = theMessage.getSubscription().getChannelType(); 135 } 136 } 137 if (theFailure != null) { 138 failureString = theFailure.toString(); 139 } 140 log(EventCodeEnum.SUBS6, "Delivery of resource {} for subscription {} to channel of type {} - Failure: {}", payloadId, subscriptionId, channelType, failureString); 141 } 142 143 @Hook(Pointcut.SUBSCRIPTION_AFTER_DELIVERY) 144 public void step50_afterDelivery(ResourceDeliveryMessage theMessage) { 145 String processingTime = theMessage 146 .getAttribute(SUBSCRIPTION_DEBUG_LOG_INTERCEPTOR_PRECHECK) 147 .map(Long::parseLong) 148 .map(Date::new) 149 .map(start -> new StopWatch(start).toString()) 150 .orElse("(unknown)"); 151 152 log(EventCodeEnum.SUBS7, "Finished delivery of resource {} for subscription {} to channel of type {} - Total processing time: {}", theMessage.getPayloadId(), theMessage.getSubscription().getIdElementString(), theMessage.getSubscription().getChannelType(), processingTime); 153 } 154 155 protected void log(EventCodeEnum theEventCode, String theMessage, Object... theArguments) { 156 Logger logger = myLoggers.get(theEventCode); 157 if (logger != null) { 158 switch (myLevel) { 159 case ERROR: 160 logger.error(theMessage, theArguments); 161 break; 162 case WARN: 163 logger.warn(theMessage, theArguments); 164 break; 165 case INFO: 166 logger.info(theMessage, theArguments); 167 break; 168 case DEBUG: 169 logger.debug(theMessage, theArguments); 170 break; 171 case TRACE: 172 logger.trace(theMessage, theArguments); 173 break; 174 } 175 } 176 } 177 178 public enum EventCodeEnum { 179 /** 180 * A new/updated resource has been submitted to the processing pipeline and is about 181 * to be placed on the matchign queue. 182 */ 183 SUBS1, 184 /** 185 * A resources has been dequeued from the matching queue and is about to be checked 186 * for any matching subscriptions. 187 */ 188 SUBS2, 189 /** 190 * The resource has matched a subscription (logged once for each matching subscription) 191 * and is about to be queued for delivery. 192 */ 193 SUBS3, 194 /** 195 * The resource did not match any subscriptions and processing is complete. 196 */ 197 SUBS4, 198 /** 199 * The resource has been dequeued from the delivery queue and is about to be 200 * delivered. 201 */ 202 SUBS5, 203 /** 204 * Delivery failed 205 */ 206 SUBS6, 207 /** 208 * Delivery is now complete and processing is finished. 209 */ 210 SUBS7 211 } 212 213 214 private static Function<EventCodeEnum, Logger> defaultLogFactory() { 215 return code -> LoggerFactory.getLogger(SubscriptionDebugLogInterceptor.class.getName() + "." + code.name()); 216 } 217 218}