Skip to content

Commit e955cb2

Browse files
YukiInuYukiInu
authored
Merge pull request #178 from cinovo/feature/messageListenerLogImprovements
Overhaul logging for DaemonMessageListener
2 parents 282ddfc + 79f88c9 commit e955cb2

File tree

8 files changed

+189
-31
lines changed

8 files changed

+189
-31
lines changed

‎CHANGELOG.md‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -22,6 +22,7 @@
2222
* Bugfix: Fixing problem with retry messages in Interconnect
2323
* Bugfix: Better error handling in CloudconductorPropertyProvider
2424
* Fixed vulnerabilities: CVE-2024-13009(Jetty), CVE-2025-23184(Apache CXF), CVE-2024-57699 (Json-smart),CVE-2025-27533 (ActiveMQ)
25+
* Logging improvement and extension options for DaemonMessageListener
2526

2627
# 1.37
2728
* Major bug in interconnect core: DaemonScanner causes IllegalArgumentException due to wrong path of TimeoutException

‎interconnect/core/src/main/java/de/taimos/dvalin/interconnect/core/config/InterconnectConfig.java‎

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -5,6 +5,7 @@
55
import de.taimos.dvalin.interconnect.core.daemon.IDaemonMessageHandlerFactory;
66
import de.taimos.dvalin.interconnect.core.daemon.IDaemonMessageSender;
77
import de.taimos.dvalin.interconnect.core.daemon.handler.DefaultMessageHandlerFactory;
8+
import de.taimos.dvalin.interconnect.core.daemon.handler.MessageHandlerType;
89
import de.taimos.dvalin.interconnect.core.daemon.jms.DaemonMessageListener;
910
import de.taimos.dvalin.jms.DvalinConnectionFactory;
1011
import de.taimos.dvalin.jms.IDestinationService;
@@ -49,7 +50,7 @@ public IDaemonMessageHandlerFactory createDaemonMessageHandlerFactory(Applicatio
4950
ICryptoService cryptoService, //
5051
IDaemonMessageSender messageSender, //
5152
@Value("${interconnect.requesthandler.mode:}") String requestHandlerMode) {
52-
return new DefaultMessageHandlerFactory(applicationContext, messageSender, cryptoService, requestHandlerMode);
53+
return new DefaultMessageHandlerFactory(applicationContext, messageSender, cryptoService, MessageHandlerType.from(requestHandlerMode));
5354
}
5455

5556
/**
@@ -72,8 +73,7 @@ public DefaultMessageListenerContainer jmsListenerContainer(@Qualifier("DvalinCo
7273
*/
7374
@Bean(name = "defaultDaemonRequestDestination")
7475
public Destination getDefaultDaemonRequestDestination(IDestinationService destinationService) {
75-
return destinationService.createDestination(JmsTarget.QUEUE,
76-
this.serviceName + ".request");
76+
return destinationService.createDestination(JmsTarget.QUEUE, this.serviceName + ".request");
7777
}
7878

7979
/**

‎interconnect/core/src/main/java/de/taimos/dvalin/interconnect/core/daemon/handler/ADaemonMessageHandler.java‎

Lines changed: 69 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -30,8 +30,8 @@
3030
import de.taimos.dvalin.interconnect.core.daemon.model.InterconnectResponseContext;
3131
import de.taimos.dvalin.interconnect.core.daemon.util.DaemonMethodRegistry;
3232
import de.taimos.dvalin.interconnect.core.daemon.util.DaemonMethodRegistry.RegistryEntry;
33+
import de.taimos.dvalin.interconnect.core.exceptions.MessageCryptoException;
3334
import de.taimos.dvalin.interconnect.model.InterconnectObject;
34-
import de.taimos.dvalin.interconnect.model.ivo.IPageable;
3535
import de.taimos.dvalin.interconnect.model.ivo.IVO;
3636
import de.taimos.dvalin.interconnect.model.ivo.daemon.DaemonErrorIVO;
3737
import de.taimos.dvalin.interconnect.model.ivo.daemon.PingIVO;
@@ -41,15 +41,18 @@
4141
import de.taimos.dvalin.interconnect.model.service.DaemonScanner.DaemonMethod;
4242
import de.taimos.dvalin.interconnect.model.service.IDaemonHandler;
4343
import de.taimos.dvalin.jms.crypto.ICryptoService;
44-
import de.taimos.dvalin.interconnect.core.exceptions.MessageCryptoException;
44+
import org.joda.time.DateTime;
4545
import org.slf4j.Logger;
4646

4747
import javax.jms.JMSException;
4848
import javax.jms.Message;
4949
import javax.jms.TextMessage;
5050
import java.lang.reflect.InvocationTargetException;
51+
import java.util.ArrayList;
5152
import java.util.Collection;
53+
import java.util.List;
5254
import java.util.UUID;
55+
import java.util.function.Function;
5356

5457

5558
/**
@@ -66,12 +69,16 @@ public abstract class ADaemonMessageHandler implements IDaemonMessageHandler {
6669

6770
private final boolean throwExceptionOnTimeout;
6871

72+
protected final List<Function<InterconnectObject, String>> additionalLogAppender = new ArrayList<>();
73+
6974

70-
protected ADaemonMessageHandler(final Collection<Class<? extends IDaemonHandler>> aHandlerClazzes, IDaemonMessageSender messageSender, ICryptoService cryptoService, final boolean aThrowExceptionOnTimeout) {
75+
protected ADaemonMessageHandler(final Collection<Class<? extends IDaemonHandler>> aHandlerClazzes, IDaemonMessageSender messageSender, ICryptoService cryptoService,
76+
final boolean aThrowExceptionOnTimeout) {
7177
this.registry = new DaemonMethodRegistry(aHandlerClazzes);
7278
this.throwExceptionOnTimeout = aThrowExceptionOnTimeout;
7379
this.cryptoService = cryptoService;
7480
this.messageSender = messageSender;
81+
this.additionalLogAppender.add(DefaultMessageLogAppender::pageAppender);
7582
}
7683

7784

@@ -119,6 +126,7 @@ public final void onMessage(final Message message) throws Exception {
119126

120127
if (context.getReceivedContext().getIcoClass().equals(PingIVO.class)) {
121128
this.handlePing(context);
129+
this.logInvoke(context, message);
122130
return;
123131
}
124132

@@ -131,7 +139,7 @@ public final void onMessage(final Message message) throws Exception {
131139
final DaemonMethod method = ADaemonMessageHandler.getDaemonMethod(registryEntry, context);
132140
context.setCreateResponseMethod(method);
133141

134-
this.logInvoke(context);
142+
this.logInvoke(context, message);
135143

136144
if (method.getType() == DaemonScanner.Type.voit) {
137145
this.handleWithoutReply(handler, context);
@@ -157,9 +165,11 @@ private void handleWithReply(IDaemonHandler handler, InterconnectResponseContext
157165
this.reply(context);
158166
} catch (final DaemonError e) {
159167
if (e.getNumber().get() < 0) {
160-
this.getLogger().error("DaemonError for " + context.getCreateResponseMethod().getMethod().getName() + "(" + context.getReceivedContext().getIcoClass().getSimpleName() + ")" + " with " + de.taimos.dvalin.interconnect.model.InterconnectContext.getContext(), e);
168+
this.getLogger().error("DaemonError for {}({}) with {}", context.getCreateResponseMethod().getMethod().getName(), context.getReceivedContext().getIcoClass()
169+
.getSimpleName(), de.taimos.dvalin.interconnect.model.InterconnectContext.getContext(), e);
161170
} else {
162-
this.getLogger().debug("DaemonError for " + context.getCreateResponseMethod().getMethod().getName() + "(" + context.getReceivedContext().getIcoClass().getSimpleName() + ")" + " with " + de.taimos.dvalin.interconnect.model.InterconnectContext.getContext(), e);
171+
this.getLogger().debug("DaemonError for {}({}) with {}", context.getCreateResponseMethod().getMethod().getName(), context.getReceivedContext().getIcoClass()
172+
.getSimpleName(), de.taimos.dvalin.interconnect.model.InterconnectContext.getContext(), e);
163173
}
164174
this.sendErrorResponse(e, context);
165175
}
@@ -189,15 +199,17 @@ private void updateThreadContext(InterconnectResponseContext context) throws Exc
189199
private static DaemonMethod getDaemonMethod(RegistryEntry registryEntry, InterconnectResponseContext context) throws Exception {
190200
final DaemonMethod method = registryEntry.getMethod();
191201
if (method.isSecure() != context.getReceivedContext().isSecure()) {
192-
throw new Exception("Insecure call (is " + context.getReceivedContext().isSecure() + " should be " + method.isSecure() + ") for " + context.getReceivedContext().getIcoClass().getSimpleName() + " from " + context.getReceivedMessage().getJMSReplyTo());
202+
throw new Exception("Insecure call (is " + context.getReceivedContext().isSecure() + " should be " + method.isSecure() + ") for " + context.getReceivedContext()
203+
.getIcoClass().getSimpleName() + " from " + context.getReceivedMessage().getJMSReplyTo());
193204
}
194205
return method;
195206
}
196207

197208
private RegistryEntry getRegistryEntry(InterconnectResponseContext context) throws Exception {
198209
final RegistryEntry registryEntry = this.registry.get(context.getReceivedContext().getIcoClass());
199210
if (registryEntry == null) {
200-
throw new Exception("No registered method found for " + context.getReceivedContext().getIcoClass().getSimpleName() + " from " + context.getReceivedMessage().getJMSReplyTo());
211+
throw new Exception("No registered method found for " + context.getReceivedContext().getIcoClass().getSimpleName() + " from " + context.getReceivedMessage()
212+
.getJMSReplyTo());
201213
}
202214
return registryEntry;
203215
}
@@ -225,18 +237,54 @@ private HandlingDurationType duration(InterconnectResponseContext context) throw
225237
return handlingDuration.getHandlingDurationType();
226238
}
227239

228-
private void logInvoke(InterconnectResponseContext context) {
240+
private void logInvoke(InterconnectResponseContext context, Message message) {
241+
if (!this.getLogger().isInfoEnabled() && !this.getLogger().isWarnEnabled()) {
242+
return;
243+
}
244+
long inflightDuration = this.getInflightDuration(message);
245+
if (inflightDuration > 5000 && this.getLogger().isWarnEnabled()) {
246+
final String sbInvokeLog = this.createLogMessageForInvoke(context, inflightDuration);
247+
this.getLogger().warn(sbInvokeLog);
248+
return;
249+
}
229250
if (this.getLogger().isInfoEnabled()) {
230-
final StringBuilder sbInvokeLog = new StringBuilder() //
231-
.append("Invoke ") //
232-
.append(context.getCreateResponseMethod().getMethod().getName()) //
233-
.append("(").append(context.getReceivedContext().getIcoClass().getSimpleName()).append(")");
234-
if (context.getReceivedContext().getRequestIco() instanceof IPageable) {
235-
sbInvokeLog //
236-
.append(" at Page ").append(((IPageable) context.getReceivedContext().getRequestIco()).getOffset()).append(";").append(((IPageable) context.getReceivedContext().getRequestIco()).getLimit());
251+
final String sbInvokeLog = this.createLogMessageForInvoke(context, inflightDuration);
252+
this.getLogger().info(sbInvokeLog);
253+
}
254+
}
255+
256+
private String createLogMessageForInvoke(InterconnectResponseContext context, long inflightDuration) {
257+
final StringBuilder sbInvokeLog = new StringBuilder() //
258+
.append("Invoked: ") //
259+
.append(context.getReceivedContext().getIcoClass().getSimpleName());
260+
if (inflightDuration > 0) {
261+
sbInvokeLog.append(" | inflight: ").append(inflightDuration).append(" ms");
262+
}
263+
for (Function<InterconnectObject, String> appender : this.additionalLogAppender) {
264+
String logAppend = appender.apply(context.getReceivedContext().getRequestIco());
265+
if (logAppend != null && !logAppend.trim().isEmpty()) {
266+
sbInvokeLog.append(" | ").append(logAppend.trim());
237267
}
238-
sbInvokeLog.append(" with ").append(de.taimos.dvalin.interconnect.model.InterconnectContext.getContext());
239-
this.getLogger().info(sbInvokeLog.toString());
268+
}
269+
return sbInvokeLog.toString();
270+
}
271+
272+
private long getInflightDuration(Message message) {
273+
if (message == null) {
274+
return 0;
275+
}
276+
try {
277+
long expireTime = message.getJMSExpiration();
278+
if (expireTime <= 0) {
279+
return 0;
280+
}
281+
long sendTime = message.getJMSTimestamp();
282+
if (sendTime <= 0) {
283+
return 0;
284+
}
285+
return DateTime.now().getMillis() - sendTime;
286+
} catch (JMSException e) {
287+
return 0;
240288
}
241289
}
242290

@@ -302,7 +350,8 @@ private InterconnectObject handleRequest(final IDaemonHandler handler, final Dae
302350
throw new IdemponentRetryException(targetException);
303351
}
304352

305-
this.getLogger().error("Exception in non-idempotent " + method.getMethod().getName() + "(" + ico.getClass().getSimpleName() + ")" + " with " + de.taimos.dvalin.interconnect.model.InterconnectContext.getContext(), e);
353+
this.getLogger().error("Exception in non-idempotent {}({}) with {}", method.getMethod().getName(), ico.getClass()
354+
.getSimpleName(), de.taimos.dvalin.interconnect.model.InterconnectContext.getContext(), e);
306355
throw new DaemonError(FrameworkErrors.FRAMEWORK_ERROR, targetException);
307356
} catch (final Exception e) {
308357
throw new RuntimeException(e);
@@ -331,4 +380,5 @@ private void handleWithoutReply(final IDaemonHandler handler, InterconnectRespon
331380
}
332381
}
333382

383+
334384
}

‎interconnect/core/src/main/java/de/taimos/dvalin/interconnect/core/daemon/handler/DefaultMessageHandlerFactory.java‎

Lines changed: 45 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -4,15 +4,20 @@
44
import de.taimos.dvalin.interconnect.core.daemon.IDaemonMessageHandlerFactory;
55
import de.taimos.dvalin.interconnect.core.daemon.IDaemonMessageSender;
66
import de.taimos.dvalin.interconnect.core.daemon.RequestHandler;
7+
import de.taimos.dvalin.interconnect.model.InterconnectObject;
78
import de.taimos.dvalin.interconnect.model.service.ADaemonHandler;
89
import de.taimos.dvalin.interconnect.model.service.IDaemonHandler;
910
import de.taimos.dvalin.jms.crypto.ICryptoService;
1011
import org.slf4j.Logger;
1112
import org.springframework.beans.factory.config.AutowireCapableBeanFactory;
1213
import org.springframework.context.ApplicationContext;
1314

15+
import java.util.ArrayList;
1416
import java.util.HashSet;
17+
import java.util.List;
18+
import java.util.Objects;
1519
import java.util.Set;
20+
import java.util.function.Function;
1621

1722
/**
1823
* Copyright 2024 Cinovo AG<br>
@@ -24,33 +29,66 @@ public class DefaultMessageHandlerFactory implements IDaemonMessageHandlerFactor
2429
private final ApplicationContext applicationContext;
2530
private final IDaemonMessageSender messageSender;
2631
private final ICryptoService cryptoService;
27-
private final String requestHandlerMode;
32+
private final MessageHandlerType requestHandlerMode;
33+
private final List<Function<InterconnectObject, String>> additionalLogAppender = new ArrayList<>();
34+
private Logger loggerOverride;
2835

2936
/**
3037
* @param applicationContext spring application context
3138
* @param messageSender to use for the message handler
3239
* @param cryptoService for encryption and decryption of messages
3340
* @param requestHandlerMode mode of the request handler: "multi" has special handling
41+
* @deprecated use the constructor with the enum mode for requestHandler mode.
3442
*/
43+
@Deprecated
3544
public DefaultMessageHandlerFactory(ApplicationContext applicationContext, IDaemonMessageSender messageSender, ICryptoService cryptoService, String requestHandlerMode) {
45+
this.applicationContext = applicationContext;
46+
this.messageSender = messageSender;
47+
this.cryptoService = cryptoService;
48+
this.requestHandlerMode = MessageHandlerType.from(requestHandlerMode);
49+
}
50+
51+
/**
52+
* @param applicationContext spring application context
53+
* @param messageSender to use for the message handler
54+
* @param cryptoService for encryption and decryption of messages
55+
* @param requestHandlerMode mode of the request handler
56+
*/
57+
public DefaultMessageHandlerFactory(ApplicationContext applicationContext, IDaemonMessageSender messageSender, ICryptoService cryptoService,
58+
MessageHandlerType requestHandlerMode) {
3659
this.applicationContext = applicationContext;
3760
this.messageSender = messageSender;
3861
this.cryptoService = cryptoService;
3962
this.requestHandlerMode = requestHandlerMode;
4063
}
4164

65+
/**
66+
* @param logger the logger to use, instead of the default one
67+
*/
68+
@SuppressWarnings("unused")
69+
public void defaultLoggerOverride(Logger logger) {
70+
this.loggerOverride = logger;
71+
}
72+
73+
/**
74+
* @param appender the appender to add to this message handler
75+
*/
76+
@SuppressWarnings("unused")
77+
public void addAdditionalLogAppender(Function<InterconnectObject, String> appender) {
78+
this.additionalLogAppender.add(appender);
79+
}
80+
4281
public IDaemonMessageHandler create(Logger logger) {
4382
AutowireCapableBeanFactory beanFactory = this.applicationContext.getAutowireCapableBeanFactory();
44-
if ("multi".equals(this.requestHandlerMode)) {
45-
return this.createMultiDaemonMessageHandler(logger, beanFactory);
83+
if (Objects.requireNonNull(this.requestHandlerMode) == MessageHandlerType.MULTI) {
84+
return this.createMultiDaemonMessageHandler(this.loggerOverride == null ? logger : this.loggerOverride, beanFactory);
4685
}
47-
return this.createSingleDaemonMessageHandler(logger, beanFactory);
86+
return this.createSingleDaemonMessageHandler(this.loggerOverride == null ? logger : this.loggerOverride, beanFactory);
4887
}
4988

5089
private SingleDaemonMessageHandler createSingleDaemonMessageHandler(Logger logger, AutowireCapableBeanFactory beanFactory) {
5190
final ADaemonHandler rh = (ADaemonHandler) beanFactory.getBean("requestHandler");
52-
return new SingleDaemonMessageHandler(logger, rh.getClass(), this.cryptoService, this.messageSender,
53-
beanFactory);
91+
return new SingleDaemonMessageHandler(logger, rh.getClass(), this.cryptoService, this.messageSender, beanFactory, this.additionalLogAppender);
5492
}
5593

5694
private MultiDaemonMessageHandler createMultiDaemonMessageHandler(Logger logger, AutowireCapableBeanFactory beanFactory) {
@@ -60,6 +98,6 @@ private MultiDaemonMessageHandler createMultiDaemonMessageHandler(Logger logger,
6098
handlers.add(((IDaemonHandler) o).getClass());
6199
}
62100
}
63-
return new MultiDaemonMessageHandler(logger, handlers, this.cryptoService, this.messageSender, beanFactory);
101+
return new MultiDaemonMessageHandler(logger, handlers, this.cryptoService, this.messageSender, beanFactory, this.additionalLogAppender);
64102
}
65103
}

‎interconnect/core/src/main/java/de/taimos/dvalin/interconnect/core/daemon/handler/DefaultMessageLogAppender.java‎

Lines changed: 38 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,38 @@
1+
package de.taimos.dvalin.interconnect.core.daemon.handler;
2+
3+
import de.taimos.dvalin.interconnect.model.InterconnectObject;
4+
import de.taimos.dvalin.interconnect.model.ivo.IPageable;
5+
6+
/**
7+
* Copyright 2025 Cinovo AG<br>
8+
* <br>
9+
*
10+
* @author Philipp Sigloch
11+
*/
12+
public interface DefaultMessageLogAppender {
13+
/**
14+
* @param ivo the ivo
15+
* @return the string to append to log
16+
*/
17+
static String pageAppender(InterconnectObject ivo) {
18+
if (ivo instanceof IPageable) {
19+
return "at Page " + DefaultMessageLogAppender.asBoundString(((IPageable) ivo).getOffset()) + ";" + DefaultMessageLogAppender.asBoundString(((IPageable) ivo).getLimit());
20+
}
21+
return null;
22+
}
23+
24+
/**
25+
* @param value the integer value
26+
* @return each as string: "0" if <= 0; "MAX" if Integer.MAX; value otherwise
27+
*/
28+
static String asBoundString(Integer value) {
29+
if ((value == null || (value < 0))) {
30+
return "0";
31+
}
32+
if ((value >= Integer.MAX_VALUE)) {
33+
return "MAX";
34+
}
35+
return String.valueOf(value);
36+
}
37+
38+
}

‎interconnect/core/src/main/java/de/taimos/dvalin/interconnect/core/daemon/handler/MessageHandlerType.java‎

Lines changed: 19 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,19 @@
1+
package de.taimos.dvalin.interconnect.core.daemon.handler;
2+
3+
/**
4+
* Copyright 2025 Cinovo AG<br>
5+
* <br>
6+
*
7+
* @author Philipp Sigloch
8+
*/
9+
public enum MessageHandlerType {
10+
SINGLE, MULTI;
11+
12+
/**
13+
* @param input the string input
14+
* @return the type, defaults to single
15+
*/
16+
public static MessageHandlerType from(String input) {
17+
return ("multi".equals(input)) ? MessageHandlerType.MULTI : MessageHandlerType.SINGLE;
18+
}
19+
}

0 commit comments

Comments
 (0)