From 0fb3114a42bd448c109993dbbd1c57bc3783531d Mon Sep 17 00:00:00 2001 From: isengrims <104489572+isengrims@users.noreply.github.com> Date: Mon, 14 Aug 2023 17:50:31 +0400 Subject: [PATCH] [TH2-5026] Improve logging. (#54) --- README.md | 5 +- gradle.properties | 2 +- .../java/com/exactpro/th2/FixHandler.java | 86 +++++++++++-------- 3 files changed, 57 insertions(+), 36 deletions(-) diff --git a/README.md b/README.md index 530b50c..2b98919 100644 --- a/README.md +++ b/README.md @@ -1,4 +1,4 @@ -# th2-conn-dirty-fix (0.3.0) +# th2-conn-dirty-fix (0.3.1) This microservice allows sending and receiving messages via FIX protocol @@ -325,6 +325,9 @@ spec: ``` # Changelog +### 0.3.1 +* Improve logging: log session group and session alias for each log message. + ## 0.3.0 * Ability to recover messages from cradle. diff --git a/gradle.properties b/gradle.properties index bf2b61a..3a9a318 100644 --- a/gradle.properties +++ b/gradle.properties @@ -1,2 +1,2 @@ -release_version=0.3.0 +release_version=0.3.1 jackson_version=2.11.2 diff --git a/src/main/java/com/exactpro/th2/FixHandler.java b/src/main/java/com/exactpro/th2/FixHandler.java index e5a075f..4c4853b 100644 --- a/src/main/java/com/exactpro/th2/FixHandler.java +++ b/src/main/java/com/exactpro/th2/FixHandler.java @@ -233,7 +233,7 @@ public void onStart() { channel = context.createChannel(address, settings.getSecurity(), Map.of(), true, settings.getReconnectDelay() * 1000L, Integer.MAX_VALUE); if(settings.isLoadSequencesFromCradle()) { SequenceHolder sequences = messageLoader.loadInitialSequences(channel.getSessionAlias()); - LOGGER.info("Loaded sequences are: client - {}, server - {}", sequences.getClientSeq(), sequences.getServerSeq()); + info("Loaded sequences are: client - %d, server - %d", sequences.getClientSeq(), sequences.getServerSeq()); msgSeqNum.set(sequences.getClientSeq()); serverMsgSeqNum.set(sequences.getServerSeq()); } @@ -256,11 +256,11 @@ public CompletableFuture send(@NotNull RawMessage rawMessage) { } while (channel.isOpen() && !enabled.get()) { - if (LOGGER.isWarnEnabled()) LOGGER.warn("Session is not yet logged in: {}", channel.getSessionAlias()); + warn("Session is not yet logged in"); try { Thread.sleep(1000); } catch (InterruptedException e) { - LOGGER.error("Error while sleeping."); + error("Error while sleeping.", null); } } @@ -325,14 +325,14 @@ public Map onIncoming(@NotNull IChannel channel, @NotNull ByteBu FixField msgSeqNumValue = findField(message, MSG_SEQ_NUM_TAG); if (msgSeqNumValue == null) { metadata.put(REJECT_REASON, "No msgSeqNum Field"); - if (LOGGER.isErrorEnabled()) LOGGER.error("Invalid message. No MsgSeqNum in message: {}", message.toString(US_ASCII)); + if(LOGGER.isErrorEnabled()) error("Invalid message. No MsgSeqNum in message: %s", null, message.toString(US_ASCII)); return metadata; } FixField msgType = findField(message, MSG_TYPE_TAG); if (msgType == null) { metadata.put(REJECT_REASON, "No msgType Field"); - if (LOGGER.isErrorEnabled()) LOGGER.error("Invalid message. No MsgType in message: {}", message.toString(US_ASCII)); + if(LOGGER.isErrorEnabled()) error("Invalid message. No MsgType in message: %s", null, message.toString(US_ASCII)); return metadata; } @@ -355,7 +355,7 @@ public Map onIncoming(@NotNull IChannel channel, @NotNull ByteBu sendLogout(); reconnectRequestTimer = executorService.schedule(this::sendLogon, settings.getReconnectDelay(), TimeUnit.SECONDS); metadata.put(REJECT_REASON, "SeqNum is less than expected."); - if (LOGGER.isErrorEnabled()) LOGGER.error("Invalid message. SeqNum is less than expected {}: {}", serverMsgSeqNum.get(), message.toString(US_ASCII)); + error("Invalid message. SeqNum is less than expected %d: %s", null, serverMsgSeqNum.get(), message.toString(US_ASCII)); return metadata; } @@ -368,18 +368,18 @@ public Map onIncoming(@NotNull IChannel channel, @NotNull ByteBu switch (msgTypeValue) { case MSG_TYPE_HEARTBEAT: - if (LOGGER.isInfoEnabled()) LOGGER.info("Heartbeat received - {}", message.toString(US_ASCII)); + if(LOGGER.isInfoEnabled()) info("Heartbeat received - %s", message.toString(US_ASCII)); checkHeartbeat(message); break; case MSG_TYPE_LOGON: - if (LOGGER.isInfoEnabled()) LOGGER.info("Logon received - {}", message.toString(US_ASCII)); + if(LOGGER.isInfoEnabled()) info("Logon received - %s", message.toString(US_ASCII)); boolean connectionSuccessful = checkLogon(message); if (connectionSuccessful) { if(settings.useNextExpectedSeqNum()) { FixField nextExpectedSeqField = findField(message, NEXT_EXPECTED_SEQ_NUMBER_TAG); if(nextExpectedSeqField == null) { metadata.put(REJECT_REASON, "No NextExpectedSeqNum field"); - if (LOGGER.isErrorEnabled()) LOGGER.error("Invalid message. No NextExpectedSeqNum in message: {}", message.toString(US_ASCII)); + if(LOGGER.isErrorEnabled()) error("Invalid message. No NextExpectedSeqNum in message: %s", null, message.toString(US_ASCII)); return metadata; } @@ -413,15 +413,13 @@ public Map onIncoming(@NotNull IChannel channel, @NotNull ByteBu reconnectRequestTimer = executorService.schedule(this::sendLogon, settings.getReconnectDelay(), TimeUnit.SECONDS); } break; - case MSG_TYPE_LOGOUT: //extract logout reason - handleLogout(message); - break; + //extract logout reason case MSG_TYPE_RESEND_REQUEST: - if (LOGGER.isInfoEnabled()) LOGGER.info("Resend request received - {}", message.toString(US_ASCII)); + if(LOGGER.isInfoEnabled()) info("Resend request received - %s", message.toString(US_ASCII)); handleResendRequest(message); break; case MSG_TYPE_SEQUENCE_RESET: //gap fill - if (LOGGER.isInfoEnabled()) LOGGER.info("Sequence reset received - {}", message.toString(US_ASCII)); + if(LOGGER.isInfoEnabled()) info("Sequence reset received - %s", message.toString(US_ASCII)); resetSequence(message); break; } @@ -434,7 +432,7 @@ public Map onIncoming(@NotNull IChannel channel, @NotNull ByteBu } private void handleLogout(@NotNull ByteBuf message) { - if (LOGGER.isInfoEnabled()) LOGGER.info("Logout received - {}", message.toString(US_ASCII)); + if(LOGGER.isInfoEnabled()) info("Logout received - %s", message.toString(US_ASCII)); FixField sessionStatus = findField(message, SESSION_STATUS_TAG); boolean isSequenceChanged = false; if(sessionStatus != null) { @@ -442,7 +440,7 @@ private void handleLogout(@NotNull ByteBuf message) { if(statusCode != SUCCESSFUL_LOGOUT_CODE) { FixField text = findField(message, TEXT_TAG); if (text != null) { - LOGGER.warn("Received Logout has text (58) tag: {}", text.getValue()); + warn("Received Logout has text (58) tag: %s", text.getValue()); String wrongClientSequence = StringUtils.substringBetween(text.getValue(), "expecting ", " but received"); if (wrongClientSequence != null) { msgSeqNum.set(Integer.parseInt(wrongClientSequence) - 1); @@ -477,7 +475,7 @@ private void resetSequence(ByteBuf message) { serverMsgSeqNum.set(Integer.parseInt(requireNonNull(seqNumValue.getValue())) - 1); } } else { - LOGGER.trace("Failed to reset servers MsgSeqNum. No such tag in message: {}", message.toString(US_ASCII)); + if(LOGGER.isWarnEnabled()) warn("Failed to reset servers MsgSeqNum. No such tag in message: %s", message.toString(US_ASCII)); } } @@ -542,7 +540,7 @@ private void recovery(int beginSeqNo, int endSeqNo) { } int endSeq = endSeqNo; - LOGGER.info("Loading messages from {} to {}", beginSeqNo, endSeqNo); + info("Loading messages from %d to %d", beginSeqNo, endSeqNo); if(settings.isLoadMissedMessagesFromCradle()) { Function1 processMessage = (buf) -> { FixField seqNum = findField(buf, MSG_SEQ_NUM_TAG); @@ -606,7 +604,7 @@ private void recovery(int beginSeqNo, int endSeqNo) { resetHeartbeatTask(); } catch (Exception e) { - LOGGER.error("Error while loading messages for recovery", e); + error("Error while loading messages for recovery", e); String seqReset = createSequenceReset(Math.max(beginSeqNo, lastProcessedSequence.get() + 1), msgSeqNum.get() + 1).toString(); channel.send( @@ -663,9 +661,7 @@ private boolean checkLogon(ByteBuf message) { public void onOutgoing(@NotNull IChannel channel, @NotNull ByteBuf message, @NotNull Map metadata) { onOutgoingUpdateTag(message, metadata); - if (LOGGER.isDebugEnabled()) { - LOGGER.debug("Outgoing message: {}", message.toString(US_ASCII)); - } + if(LOGGER.isDebugEnabled()) debug("Outgoing message: %s", message.toString(US_ASCII)); } public void onOutgoingUpdateTag(@NotNull ByteBuf message, @NotNull Map metadata) { @@ -688,9 +684,7 @@ public void onOutgoingUpdateTag(@NotNull ByteBuf message, @NotNull Map> future) { future.get().cancel(false); } + + private void info(String message, Object... args) { + if(LOGGER.isInfoEnabled()) { + LOGGER.info("{} - {}: {}", channel.getSessionGroup(), channel.getSessionAlias(), String.format(message, args)); + } + } + + private void error(String message, Throwable throwable, Object... args) { + if(LOGGER.isErrorEnabled()) { + LOGGER.error("{} - {}: {}", channel.getSessionGroup(), channel.getSessionAlias(), String.format(message, args), throwable); + } + } + + private void warn(String message, Object... args) { + if(LOGGER.isWarnEnabled()) { + LOGGER.warn("{} - {}: {}", channel.getSessionGroup(), channel.getSessionAlias(), String.format(message, args)); + } + } + + private void debug(String message, Object... args) { + if(LOGGER.isDebugEnabled()) { + LOGGER.debug("{} - {}: {}", channel.getSessionGroup(), channel.getSessionAlias(), String.format(message, args)); + } + } } \ No newline at end of file