enhance logging

app_llm.go

@@ -11,6 +11,7 @@ import (
 
 	_ "image/jpeg"
 
+	"github.com/sirupsen/logrus"
 	"github.com/tmc/langchaingo/llms"
 )
 
@@ -69,7 +70,7 @@ func (app *App) getSuggestedTags(ctx context.Context, content string, suggestedT
 	return filteredTags, nil
 }
 
-func (app *App) doOCRViaLLM(ctx context.Context, jpegBytes []byte) (string, error) {
+func (app *App) doOCRViaLLM(ctx context.Context, jpegBytes []byte, logger *logrus.Entry) (string, error) {
 
 	templateMutex.RLock()
 	defer templateMutex.RUnlock()
@@ -91,13 +92,13 @@ func (app *App) doOCRViaLLM(ctx context.Context, jpegBytes []byte) (string, erro
 		return "", fmt.Errorf("error decoding image: %v", err)
 	}
 	bounds := img.Bounds()
-	log.Debugf("Image dimensions: %dx%d", bounds.Dx(), bounds.Dy())
+	logger.Debugf("Image dimensions: %dx%d", bounds.Dx(), bounds.Dy())
 
 	// If not OpenAI then use binary part for image, otherwise, use the ImageURL part with encoding from https://platform.openai.com/docs/guides/vision
 	var parts []llms.ContentPart
 	if strings.ToLower(visionLlmProvider) != "openai" {
 		// Log image size in kilobytes
-		log.Debugf("Image size: %d KB", len(jpegBytes)/1024)
+		logger.Debugf("Image size: %d KB", len(jpegBytes)/1024)
 		parts = []llms.ContentPart{
 			llms.BinaryPart("image/jpeg", jpegBytes),
 			llms.TextPart(prompt),
@@ -105,7 +106,7 @@ func (app *App) doOCRViaLLM(ctx context.Context, jpegBytes []byte) (string, erro
 	} else {
 		base64Image := base64.StdEncoding.EncodeToString(jpegBytes)
 		// Log image size in kilobytes
-		log.Debugf("Image size: %d KB", len(base64Image)/1024)
+		logger.Debugf("Image size: %d KB", len(base64Image)/1024)
 		parts = []llms.ContentPart{
 			llms.ImageURLPart(fmt.Sprintf("data:image/jpeg;base64,%s", base64Image)),
 			llms.TextPart(prompt),
@@ -166,7 +167,7 @@ func (app *App) getSuggestedTitle(ctx context.Context, content string) (string,
 }
 
 // generateDocumentSuggestions generates suggestions for a set of documents
-func (app *App) generateDocumentSuggestions(ctx context.Context, suggestionRequest GenerateSuggestionsRequest) ([]DocumentSuggestion, error) {
+func (app *App) generateDocumentSuggestions(ctx context.Context, suggestionRequest GenerateSuggestionsRequest, logger *logrus.Entry) ([]DocumentSuggestion, error) {
 	// Fetch all available tags from paperless-ngx
 	availableTagsMap, err := app.Client.GetAllTags(ctx)
 	if err != nil {
@@ -194,7 +195,7 @@ func (app *App) generateDocumentSuggestions(ctx context.Context, suggestionReque
 		go func(doc Document) {
 			defer wg.Done()
 			documentID := doc.ID
-			log.Printf("Processing Document ID %d...", documentID)
+			logger.Printf("Processing Document ID %d...", documentID)
 
 			content := doc.Content
 			if len(content) > 5000 {
@@ -210,7 +211,7 @@ func (app *App) generateDocumentSuggestions(ctx context.Context, suggestionReque
 					mu.Lock()
 					errorsList = append(errorsList, fmt.Errorf("Document %d: %v", documentID, err))
 					mu.Unlock()
-					log.Errorf("Error processing document %d: %v", documentID, err)
+					logger.Errorf("Error processing document %d: %v", documentID, err)
 					return
 				}
 			}
@@ -221,7 +222,7 @@ func (app *App) generateDocumentSuggestions(ctx context.Context, suggestionReque
 					mu.Lock()
 					errorsList = append(errorsList, fmt.Errorf("Document %d: %v", documentID, err))
 					mu.Unlock()
-					log.Errorf("Error generating tags for document %d: %v", documentID, err)
+					logger.Errorf("Error generating tags for document %d: %v", documentID, err)
 					return
 				}
 			}
@@ -233,7 +234,7 @@ func (app *App) generateDocumentSuggestions(ctx context.Context, suggestionReque
 			}
 			// Titles
 			if suggestionRequest.GenerateTitles {
-				log.Printf("Suggested title for document %d: %s", documentID, suggestedTitle)
+				logger.Printf("Suggested title for document %d: %s", documentID, suggestedTitle)
 				suggestion.SuggestedTitle = suggestedTitle
 			} else {
 				suggestion.SuggestedTitle = doc.Title
@@ -241,14 +242,14 @@ func (app *App) generateDocumentSuggestions(ctx context.Context, suggestionReque
 
 			// Tags
 			if suggestionRequest.GenerateTags {
-				log.Printf("Suggested tags for document %d: %v", documentID, suggestedTags)
+				logger.Printf("Suggested tags for document %d: %v", documentID, suggestedTags)
 				suggestion.SuggestedTags = suggestedTags
 			} else {
 				suggestion.SuggestedTags = removeTagFromList(doc.Tags, manualTag)
 			}
 			documentSuggestions = append(documentSuggestions, suggestion)
 			mu.Unlock()
-			log.Printf("Document %d processed successfully.", documentID)
+			logger.Printf("Document %d processed successfully.", documentID)
 		}(documents[i])
 	}
 

main.go

@@ -326,6 +326,11 @@ func validateOrDefaultEnvVars() {
 	}
 }
 
+// documentLogger creates a logger with document context
+func documentLogger(documentID int) *logrus.Entry {
+	return log.WithField("document_id", documentID)
+}
+
 // processAutoTagDocuments handles the background auto-tagging of documents
 func (app *App) processAutoTagDocuments() (int, error) {
 	ctx := context.Background()
@@ -343,6 +348,8 @@ func (app *App) processAutoTagDocuments() (int, error) {
 	log.Debugf("Found at least %d remaining documents with tag %s", len(documents), autoTag)
 
 	documents = documents[:1] // Process only one document at a time
+	docLogger := documentLogger(documents[0].ID)
+	docLogger.Info("Processing document for auto-tagging")
 
 	suggestionRequest := GenerateSuggestionsRequest{
 		Documents:      documents,
@@ -350,16 +357,17 @@ func (app *App) processAutoTagDocuments() (int, error) {
 		GenerateTags:   strings.ToLower(autoGenerateTags) != "false",
 	}
 
-	suggestions, err := app.generateDocumentSuggestions(ctx, suggestionRequest)
+	suggestions, err := app.generateDocumentSuggestions(ctx, suggestionRequest, docLogger)
 	if err != nil {
-		return 0, fmt.Errorf("error generating suggestions: %w", err)
+		return 0, fmt.Errorf("error generating suggestions for document %d: %w", documents[0].ID, err)
 	}
 
-	err = app.Client.UpdateDocuments(ctx, suggestions, app.Database, false)
+	err = app.Client.UpdateDocuments(ctx, suggestions, app.Database, docLogger)
 	if err != nil {
-		return 0, fmt.Errorf("error updating documents: %w", err)
+		return 0, fmt.Errorf("error updating document %d: %w", documents[0].ID, err)
 	}
 
+	docLogger.Info("Successfully processed document")
 	return len(documents), nil
 }
 
@@ -380,12 +388,14 @@ func (app *App) processAutoOcrTagDocuments() (int, error) {
 	log.Debugf("Found at least %d remaining documents with tag %s", len(documents), autoOcrTag)
 
 	documents = documents[:1] // Process only one document at a time
+	docLogger := documentLogger(documents[0].ID)
+	docLogger.Info("Processing document for OCR")
 
 	ocrContent, err := app.ProcessDocumentOCR(ctx, documents[0].ID)
 	if err != nil {
-		return 0, fmt.Errorf("error processing document OCR: %w", err)
+		return 0, fmt.Errorf("error processing OCR for document %d: %w", documents[0].ID, err)
 	}
-	log.Debugf("OCR content for document %d: %s", documents[0].ID, ocrContent)
+	docLogger.Debug("OCR processing completed")
 
 	err = app.Client.UpdateDocuments(ctx, []DocumentSuggestion{
 		{
@@ -393,12 +403,13 @@ func (app *App) processAutoOcrTagDocuments() (int, error) {
 			OriginalDocument: documents[0],
 			SuggestedContent: ocrContent,
 		},
-	}, app.Database, false)
+	}, app.Database, docLogger)
 	if err != nil {
-		return 0, fmt.Errorf("error updating documents: %w", err)
+		return 0, fmt.Errorf("error updating document %d after OCR: %w", documents[0].ID, err)
 	}
 
-	return 1, nil // Processed one document
+	docLogger.Info("Successfully processed document OCR")
+	return 1, nil
 }
 
 // removeTagFromList removes a specific tag from a list of tags

ocr.go

@@ -9,31 +9,42 @@ import (
 
 // ProcessDocumentOCR processes a document through OCR and returns the combined text
 func (app *App) ProcessDocumentOCR(ctx context.Context, documentID int) (string, error) {
+	docLogger := documentLogger(documentID)
+	docLogger.Info("Starting OCR processing")
+
 	imagePaths, err := app.Client.DownloadDocumentAsImages(ctx, documentID, limitOcrPages)
 	defer func() {
 		for _, imagePath := range imagePaths {
-			os.Remove(imagePath)
+			if err := os.Remove(imagePath); err != nil {
+				docLogger.WithError(err).WithField("image_path", imagePath).Warn("Failed to remove temporary image file")
+			}
 		}
 	}()
 	if err != nil {
-		return "", fmt.Errorf("error downloading document images: %w", err)
+		return "", fmt.Errorf("error downloading document images for document %d: %w", documentID, err)
 	}
 
+	docLogger.WithField("page_count", len(imagePaths)).Debug("Downloaded document images")
+
 	var ocrTexts []string
-	for _, imagePath := range imagePaths {
+	for i, imagePath := range imagePaths {
+		pageLogger := docLogger.WithField("page", i+1)
+		pageLogger.Debug("Processing page")
+
 		imageContent, err := os.ReadFile(imagePath)
 		if err != nil {
-			return "", fmt.Errorf("error reading image file: %w", err)
+			return "", fmt.Errorf("error reading image file for document %d, page %d: %w", documentID, i+1, err)
 		}
 
-		ocrText, err := app.doOCRViaLLM(ctx, imageContent)
+		ocrText, err := app.doOCRViaLLM(ctx, imageContent, pageLogger)
 		if err != nil {
-			return "", fmt.Errorf("error performing OCR: %w", err)
+			return "", fmt.Errorf("error performing OCR for document %d, page %d: %w", documentID, i+1, err)
 		}
-		log.Debugf("OCR text: %s", ocrText)
+		pageLogger.Debug("OCR completed for page")
 
 		ocrTexts = append(ocrTexts, ocrText)
 	}
 
+	docLogger.Info("OCR processing completed successfully")
 	return strings.Join(ocrTexts, "\n\n"), nil
 }