Introduce logging

Author: aNNiMON

build.gradle

@@ -19,6 +19,10 @@ dependencies {
     implementation 'com.github.kilianB:JImageHash:3.0.0'
     implementation 'com.h2database:h2:1.4.200'
 
+    implementation 'org.apache.logging.log4j:log4j-core:2.13.3'
+    implementation 'com.fasterxml.jackson.dataformat:jackson-dataformat-yaml:2.11.3'
+    implementation "com.fasterxml.jackson.module:jackson-module-kotlin:2.11.3"
+
     testCompile 'junit:junit:4.12'
 }
 

log4j2.yaml

@@ -0,0 +1,17 @@
+Configuration:
+    name: SimilarImagesBot
+  
+    Appenders:
+      Console:
+        - name: Console
+          target: SYSTEM_OUT
+          PatternLayout:
+            Pattern: "%d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"
+  
+    Loggers:
+      Root:
+        level: debug
+        AppenderRef:
+          - ref: Console
+            level: debug
+  

src/main/java/com/annimon/similarimagesbot/BaseBotHandler.java

@@ -15,9 +15,13 @@
 import com.pengrad.telegrambot.model.PhotoSize;
 import com.pengrad.telegrambot.model.Update;
 import com.pengrad.telegrambot.request.GetUpdates;
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
 
 public abstract class BaseBotHandler {
 
+    protected static final Logger LOGGER = LogManager.getLogger(BaseBotHandler.class);
+
     private final Comparator<PhotoSize> photoSizeComparator = Comparator
             .comparingInt(ps -> ps.width() * ps.height());
 
@@ -33,23 +37,26 @@ public BaseBotHandler(String botToken) {
 
     public void run() {
         int oldLastUpdateId = readLastUpdateId();
+        LOGGER.debug("Start updates listener from {}", oldLastUpdateId);
         bot.setUpdatesListener(updates -> {
             final var filteredUpdates = updates.stream()
                     .filter(u -> u.updateId() > oldLastUpdateId)
                     .collect(Collectors.toList());
             handleUpdates(filteredUpdates);
-            int newLastUpdateId = getLastUpdateIdFromUpdatesList(updates, oldLastUpdateId);
-            writeLastUpdateId(newLastUpdateId + 1);
+            int nextLastUpdateId = geNextUpdateId(updates, oldLastUpdateId);
+            writeNextUpdateId(nextLastUpdateId);
             return UpdatesListener.CONFIRMED_UPDATES_ALL;
         });
     }
 
     public void runOnce() {
         int oldLastUpdateId = readLastUpdateId();
+        LOGGER.debug("Get updates from {}", oldLastUpdateId);
         final var updates = bot.execute(new GetUpdates().offset(oldLastUpdateId)).updates();
+        LOGGER.debug("Handle {} updates", updates.size());
         handleUpdates(updates);
-        int newLastUpdateId = getLastUpdateIdFromUpdatesList(updates, oldLastUpdateId);
-        writeLastUpdateId(newLastUpdateId + 1);
+        int newLastUpdateId = geNextUpdateId(updates, oldLastUpdateId);
+        writeNextUpdateId(newLastUpdateId);
     }
 
     protected abstract void handleUpdates(List<Update> updates);
@@ -74,23 +81,33 @@ protected PhotoSize getBiggestPhoto(PhotoSize[] photoSizes) {
                 .orElse(photoSizes[0]);
     }
 
-    private int getLastUpdateIdFromUpdatesList(List<Update> updates, int previousUpdateId) {
-        return updates.stream()
+    private int geNextUpdateId(List<Update> updates, int previousUpdateId) {
+        final int lastUpdateId = updates.stream()
             .mapToInt(Update::updateId)
             .max()
             .orElse(previousUpdateId);
+        final int nextUpdateId; 
+        if (lastUpdateId != previousUpdateId) {
+            nextUpdateId = lastUpdateId + 1;
+        } else {
+            nextUpdateId = lastUpdateId;
+        }
+        return nextUpdateId;
     }
 
     private int readLastUpdateId() {
         try {
             return Integer.parseInt(Files.readString(uniqueIdPath));
         } catch (IOException ioe) {
+            LOGGER.error("readLastUpdateId", ioe);
             return 0;
         }
     }
 
-    private void writeLastUpdateId(int updateId) {
+    private void writeNextUpdateId(int updateId) {
         try {
             Files.writeString(uniqueIdPath, Integer.toString(updateId));
-        } catch (IOException ignore) {}
+        } catch (IOException ioe) {
+            LOGGER.error("writeLastUpdateId", ioe);
+        }
     }}

src/main/java/com/annimon/similarimagesbot/BotHandler.java

@@ -72,11 +72,12 @@ private Optional<Post> processDelCommand(Matcher m) {
         }
         final var channelId = Long.parseLong("-100" + m.group(1));
         final var messageId = Integer.parseInt(m.group(2));
+        LOGGER.debug("Delete message {} in {}", messageId, channelId);
         bot.execute(new DeleteMessage(channelId, messageId));
         try {
             indexer.deleteImage(channelId, messageId);
         } catch (SQLException ex) {
-            System.err.println("Cannot delete image in db");
+            LOGGER.error("Cannot delete image in db", ex);
         }
         return Optional.of(new Post(channelId, messageId));
     }
@@ -88,6 +89,7 @@ private Optional<Post> processCompareCommand(Matcher m) {
         final var channelId = Long.parseLong("-100" + m.group(1));
         final var messageA = Integer.parseInt(m.group(2));
         final var messageB = Integer.parseInt(m.group(3));
+        LOGGER.debug("Compare messages {} and {} in {}", messageA, messageB, channelId);
 
         // Forward and get photo to compare
         var sentA = bot.execute(new ForwardMessage(adminId, channelId, messageA));
@@ -127,7 +129,7 @@ private void processUpdates(List<Update> updates, Set<Post> ignoredPosts) {
                     similarImagesInfos.add(info);
                 }
             } catch (IOException | SQLException e) {
-                System.err.format("Error while processing photo in %s%n", linkToMessage(post));
+                LOGGER.error("Error while processing photo in {}", linkToMessage(post));
             }
         }
         if (!similarImagesInfos.isEmpty()) {

src/main/java/com/annimon/similarimagesbot/Main.java

@@ -1,20 +1,24 @@
 package com.annimon.similarimagesbot;
 
 import java.util.Optional;
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
 
 public class Main {
 
+    private static final Logger LOGGER = LogManager.getLogger(Main.class);
+
     public static void main(String[] args) {
         final String botToken = stringProp("BOT_TOKEN")
                 .orElseThrow(() -> new IllegalArgumentException("BOT_TOKEN is required"));
         final ImageIndexer indexer = new ImageIndexer();
         final var handler = new BotHandler(botToken, indexer);
         handler.setAdminId(longProp("ADMIN_ID").orElse(0L));
         if (isOnceMode() || (args.length == 1 && args[0].equalsIgnoreCase("once"))) {
-            System.out.println("Started in once mode");
+            LOGGER.info("Started in once mode");
             handler.runOnce();
         } else {
-            System.out.println("Started in listen mode");
+            LOGGER.info("Started in listen mode");
             handler.run();
         }
     }