From 287d0e5c7c3745211b0a0e9445c490de92987d06 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Dominik=20Schr=C3=B6ter?= Date: Mon, 13 Jan 2025 07:52:40 +0100 Subject: [PATCH] enhance logging --- app_llm.go | 23 ++++++++++++----------- main.go | 29 ++++++++++++++++++++--------- ocr.go | 25 ++++++++++++++++++------- 3 files changed, 50 insertions(+), 27 deletions(-) diff --git a/app_llm.go b/app_llm.go index 22883a5..4f0bb27 100644 --- a/app_llm.go +++ b/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]) } diff --git a/main.go b/main.go index 783fa7e..22af13f 100644 --- a/main.go +++ b/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 diff --git a/ocr.go b/ocr.go index b96d74a..6819a98 100644 --- a/ocr.go +++ b/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 }