Add logging to better troubleshoot issues

Signed-off-by: Igor Shishkin <me@teran.ru>

deduplicator.lrdevplugin/FindDuplicates.lua

@@ -6,6 +6,14 @@ local LrPathUtils = import 'LrPathUtils'
 local LrProgressScope = import 'LrProgressScope'
 local LrSystemInfo = import 'LrSystemInfo'
 local LrTasks = import 'LrTasks'
+local LrLogger = import 'LrLogger'
+local LrSystemInfo = import 'LrSystemInfo'
+
+local logger = LrLogger('Deduplicator')
+logger:enable('logfile')
+
+logger:trace('FindDuplicates.lua invoked')
+logger:infof('summaryString: %s', LrSystemInfo.summaryString())
 
 local json = require "JSON"
 json.strictTypes = true
@@ -39,6 +47,7 @@ end
 Deduplicator = {}
 
 function IndexPhoto(photo)
+  logger:trace('IndexPhoto() invoked')
   local command
   local quotedCommand
 
@@ -52,13 +61,18 @@ function IndexPhoto(photo)
   end
 
   if photo:checkPhotoAvailability() then
-    if LrTasks.execute( quotedCommand ) ~= 0 then
-      LrDialogs.message( "Subcommand execution error", "Error while executing imgsum")
+    logger:debugf('Preparing to run command %s', quotedCommand)
+    if LrTasks.execute(quotedCommand) ~= 0 then
+      logger:errorf("Error while executing imgsum")
+      LrDialogs.message("Subcommand execution error", "Error while executing imgsum")
     end
+  else
+    logger:warnf('checkPhotoAvailability check is not passed for %s', imagePath)
   end
 end
 
 function FindDuplicates()
+  logger:trace('FindDuplicates() invoked')
   local command
   local quotedCommand
 
@@ -70,27 +84,36 @@ function FindDuplicates()
      quotedCommand = command
   end
 
+  logger:debugf('Preparing to run command %s', quotedCommand)
   local f = assert(io.popen(quotedCommand, 'r'))
   local s = assert(f:read('*a'))
   f:close()
+  logger:debugf('imgsum -find-duplicates output: %s', s)
 
   if s ~= "" then
     local imgsum_output = json:decode(s)
 
     if imgsum_output["duplicates"] ~= nil then
-      catalog:withWriteAccessDo("Create collection", function()
+      catalog:withWriteAccessDo("Add photos to duplicates collection", function()
         for _, photo in pairs(imgsum_output["duplicates"]) do
           for _, file in pairs(photo) do
+            logger:infof('Preparing query to Lightroom about %s', file)
             p = catalog:findPhotoByPath(file)
+            logger:infof('Preparing to add photo id=%s to collection id=%s', p.localIdentifier, collection.localIdentifier)
             collection:addPhotos({p})
           end
         end
       end)
+    else
+      logger:warn('JSON output from imgsum contains null at duplicates array')
     end
+  else
+    logger:warn('Empty output from imgsum')
   end
 end
 
 function Deduplicator.FindDuplicates()
+  logger:trace('Deduplicator.FindDuplicates() invoked')
   local catPhotos = catalog:getMultipleSelectedOrAllPhotos()
   local titles = {}
   local indexerProgress = LrProgressScope({
@@ -102,19 +125,23 @@ function Deduplicator.FindDuplicates()
 
   for i, photo in ipairs(catPhotos) do
     if indexerProgress:isCanceled() then
+      logger:info('Indexing process cancelled')
       break;
     end
 
     local fileName = photo:getFormattedMetadata("fileName")
+    logger:debugf('Processing file %s', fileName)
 
     indexerProgress:setPortionComplete(i, #catPhotos)
     indexerProgress:setCaption("Processing " .. fileName)
 
     IndexPhoto(photo)
   end
 
+  logger:info('Setting indexing process to done state')
   indexerProgress:done()
 
+  logger:info('Starting database search process')
   FindDuplicates()
 end