Add structured logging to documentStore methods

To troubleshoot reported issues, we add more debugging outputs in
the logging. This includes detailed, structured logs in the Create
and FindID methods to provide better traceability and debuggability.

These changes help diagnose issues by providing detailed context in
the logs, which should improve the ability to identify and resolve
problems.

See also: #9

README.md

@@ -75,7 +75,10 @@ Example: `STORAGE_TYPE=sqlite DATA_SOURCE_NAME=/tmp/excalidb.sqlite`
 Start the server:
 
 ```bash
-./excalidraw-complete
+go run main.go
+
+STORAGE_TYPE=sqlite DATA_SOURCE_NAME=test.db go run main.go --loglevel debug
+STORAGE_TYPE=filesystem LOCAL_STORAGE_PATH=/tmp/excalidraw/ go run main.go --loglevel debug
 ```
 
 Excalidraw Complete is now running on your machine, ready to bring your collaborative whiteboard ideas to life.

go.mod

@@ -45,6 +45,7 @@ require (
 	github.com/quic-go/qtls-go1-20 v0.4.1 // indirect
 	github.com/quic-go/quic-go v0.40.1 // indirect
 	github.com/quic-go/webtransport-go v0.6.0 // indirect
+	github.com/sirupsen/logrus v1.9.3 // indirect
 	github.com/vmihailenco/msgpack/v5 v5.4.1 // indirect
 	github.com/vmihailenco/tagparser/v2 v2.0.0 // indirect
 	github.com/xo/terminfo v0.0.0-20210125001918-ca9a967f8778 // indirect

go.sum

@@ -84,8 +84,11 @@ github.com/quic-go/quic-go v0.40.1 h1:X3AGzUNFs0jVuO3esAGnTfvdgvL4fq655WaOi1snv1
 github.com/quic-go/quic-go v0.40.1/go.mod h1:PeN7kuVJ4xZbxSv/4OX6S1USOX8MJvydwpTx31vx60c=
 github.com/quic-go/webtransport-go v0.6.0 h1:CvNsKqc4W2HljHJnoT+rMmbRJybShZ0YPFDD3NxaZLY=
 github.com/quic-go/webtransport-go v0.6.0/go.mod h1:9KjU4AEBqEQidGHNDkZrb8CAa1abRaosM2yGOyiikEc=
+github.com/sirupsen/logrus v1.9.3 h1:dueUQJ1C2q9oE3F7wvmSGAaVtTmUizReu6fjN8uqzbQ=
+github.com/sirupsen/logrus v1.9.3/go.mod h1:naHLuLoDiP4jHNo9R0sCBMtWGeIprob74mVsIT4qYEQ=
 github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
 github.com/stretchr/testify v1.6.1/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg=
+github.com/stretchr/testify v1.7.0/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg=
 github.com/stretchr/testify v1.8.4 h1:CcVxjf3Q8PM0mHUKJCdn+eZZtm5yQwehR5yeSVQQcUk=
 github.com/stretchr/testify v1.8.4/go.mod h1:sz/lmYIOXD/1dqDmKjjqLyZ2RngseejIcXlSw2iwfAo=
 github.com/vmihailenco/msgpack/v5 v5.4.1 h1:cQriyiUvjTwOHg8QZaPihLWeRAAVoCpE00IUPn0Bjt8=
@@ -112,6 +115,7 @@ golang.org/x/mod v0.12.0 h1:rmsUpXtvNzj340zd98LZ4KntptpfRHwpFOHG188oHXc=
 golang.org/x/mod v0.12.0/go.mod h1:iBbtSCu2XBx23ZKBPSOrRkjjQPZFPuis4dIYUhu/chs=
 golang.org/x/net v0.17.0 h1:pVaXccu2ozPjCXewfr1S7xza/zcXTity9cCdXQYSjIM=
 golang.org/x/net v0.17.0/go.mod h1:NxSsAGuq816PNPmqtQdLE42eU2Fs7NoRIZrHJAlaCOE=
+golang.org/x/sys v0.0.0-20220715151400-c0bba94af5f8/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.15.0 h1:h48lPFYpsTvQJZF4EKyI4aLHaev3CxivZmv7yZig9pc=
 golang.org/x/sys v0.15.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA=
 golang.org/x/text v0.14.0 h1:ScX5w1eTa3QqT8oi6+ziP7dTV1S2+ALU0bI+0zXKWiQ=

main.go

@@ -7,6 +7,7 @@ import (
 	"excalidraw-complete/handlers/api/documents"
 	"excalidraw-complete/handlers/api/firebase"
 	"excalidraw-complete/stores"
+	"flag"
 	"fmt"
 	"io"
 	"io/fs"
@@ -16,6 +17,8 @@ import (
 	"strings"
 	"syscall"
 
+	"github.com/sirupsen/logrus"
+
 	"github.com/go-chi/chi/v5"
 	"github.com/go-chi/chi/v5/middleware"
 	"github.com/go-chi/cors"
@@ -239,6 +242,18 @@ func waitForShutdown(ioo *socketio.Server) {
 }
 
 func main() {
+	// Define a log level flag
+	logLevel := flag.String("loglevel", "info", "Set the logging level: debug, info, warn, error, fatal, panic")
+	flag.Parse()
+
+	// Set the log level
+	level, err := logrus.ParseLevel(*logLevel)
+	if err != nil {
+		fmt.Fprintf(os.Stderr, "Invalid log level: %v\n", err)
+		os.Exit(1)
+	}
+	logrus.SetLevel(level)
+
 	documentStore := stores.GetStore() // Make sure this is well-defined in your "stores" package
 	r := setupRouter(documentStore)
 	ioo := setupSocketIO()
@@ -251,8 +266,15 @@ func main() {
 	})
 	r.Mount("/", handleUI())
 
-	go http.ListenAndServe(":3002", r)
-	fmt.Println("listen on 3002")
+	addr := ":3002"
+	logrus.WithField("addr", addr).Info("starting server")
+	go func() {
+		if err := http.ListenAndServe(addr, r); err != nil {
+			logrus.WithField("event", "start server").Fatal(err)
+		}
+	}()
+
+	logrus.Debug("Server is running in the background")
 	waitForShutdown(ioo)
 
 }

stores/filesystem/documents.go

@@ -10,6 +10,7 @@ import (
 	"path/filepath"
 
 	"github.com/oklog/ulid/v2"
+	"github.com/sirupsen/logrus"
 )
 
 type documentStore struct {
@@ -26,12 +27,16 @@ func NewDocumentStore(basePath string) core.DocumentStore {
 
 func (s *documentStore) FindID(ctx context.Context, id string) (*core.Document, error) {
 	filePath := filepath.Join(s.basePath, id)
+	log := logrus.WithField("document_id", id)
 
+	log.WithField("file_path", filePath).Info("Retrieving document by ID")
 	data, err := os.ReadFile(filePath)
 	if err != nil {
 		if os.IsNotExist(err) {
+			log.WithField("error", "document not found").Warn("Document with specified ID not found")
 			return nil, fmt.Errorf("document with id %s not found", id)
 		}
+		log.WithField("error", err).Error("Failed to retrieve document")
 		return nil, err
 	}
 
@@ -39,16 +44,24 @@ func (s *documentStore) FindID(ctx context.Context, id string) (*core.Document,
 		Data: *bytes.NewBuffer(data),
 	}
 
+	log.Info("Document retrieved successfully")
 	return &document, nil
 }
 
 func (s *documentStore) Create(ctx context.Context, document *core.Document) (string, error) {
 	id := ulid.Make().String()
 	filePath := filepath.Join(s.basePath, id)
+	log := logrus.WithFields(logrus.Fields{
+		"document_id": id,
+		"file_path":   filePath,
+	})
+	log.Info("Creating new document")
 
 	if err := os.WriteFile(filePath, document.Data.Bytes(), 0644); err != nil {
+		log.WithField("error", err).Error("Failed to create document")
 		return "", err
 	}
 
+	log.Info("Document created successfully")
 	return id, nil
 }

stores/memory/documents.go

@@ -6,6 +6,7 @@ import (
 	"fmt"
 
 	"github.com/oklog/ulid/v2"
+	"github.com/sirupsen/logrus"
 )
 
 var savedDocuments = make(map[string]core.Document)
@@ -18,14 +19,23 @@ func NewDocumentStore() core.DocumentStore {
 }
 
 func (s *documentStore) FindID(ctx context.Context, id string) (*core.Document, error) {
+	log := logrus.WithField("document_id", id)
 	if val, ok := savedDocuments[id]; ok {
+		log.Info("Document retrieved successfully")
 		return &val, nil
 	}
+	log.WithField("error", "document not found").Warn("Document with specified ID not found")
 	return nil, fmt.Errorf("document with id %s not found", id)
 }
 
 func (s *documentStore) Create(ctx context.Context, document *core.Document) (string, error) {
 	id := ulid.Make().String()
 	savedDocuments[id] = *document
+	log := logrus.WithFields(logrus.Fields{
+		"document_id": id,
+		"data_length": len(document.Data.Bytes()),
+	})
+	log.Info("Document created successfully")
+
 	return id, nil
 }

stores/sqlite/documents.go

@@ -11,6 +11,7 @@ import (
 
 	_ "github.com/mattn/go-sqlite3"
 	"github.com/oklog/ulid/v2"
+	"github.com/sirupsen/logrus"
 )
 
 var savedDocuments = make(map[string]core.Document)
@@ -35,26 +36,38 @@ func NewDocumentStore(dataSourceName string) core.DocumentStore {
 }
 
 func (s *documentStore) FindID(ctx context.Context, id string) (*core.Document, error) {
+	log := logrus.WithField("document_id", id)
+	log.Debug("Retrieving document by ID")
 	var data []byte
 	err := s.db.QueryRowContext(ctx, "SELECT data FROM documents WHERE id = ?", id).Scan(&data)
 	if err != nil {
 		if err == sql.ErrNoRows {
+			log.WithField("error", "document not found").Warn("Document with specified ID not found")
 			return nil, fmt.Errorf("document with id %s not found", id)
 		}
+		log.WithField("error", err).Error("Failed to retrieve document")
 		return nil, err
 	}
 	document := core.Document{
 		Data: *bytes.NewBuffer(data),
 	}
+	log.Info("Document retrieved successfully")
 	return &document, nil
 }
 
 func (s *documentStore) Create(ctx context.Context, document *core.Document) (string, error) {
 	id := ulid.Make().String()
 	data := document.Data.Bytes()
+	log := logrus.WithFields(logrus.Fields{
+		"document_id": id,
+		"data_length": len(data),
+	})
+
 	_, err := s.db.ExecContext(ctx, "INSERT INTO documents (id, data) VALUES (?, ?)", id, data)
 	if err != nil {
+		log.WithField("error", err).Error("Failed to create document")
 		return "", err
 	}
+	log.Info("Document created successfully")
 	return id, nil
 }

stores/storage.go

@@ -7,24 +7,35 @@ import (
 	"excalidraw-complete/stores/memory"
 	"excalidraw-complete/stores/sqlite"
 	"os"
+
+	"github.com/sirupsen/logrus"
 )
 
 func GetStore() core.DocumentStore {
 	storageType := os.Getenv("STORAGE_TYPE")
 	var store core.DocumentStore
 
+	storageField := logrus.Fields{
+		"storageType": storageType,
+	}
+
 	switch storageType {
 	case "filesystem":
 		basePath := os.Getenv("LOCAL_STORAGE_PATH")
+		storageField["basePath"] = basePath
 		store = filesystem.NewDocumentStore(basePath)
 	case "sqlite":
 		dataSourceName := os.Getenv("DATA_SOURCE_NAME")
+		storageField["dataSourceName"] = dataSourceName
 		store = sqlite.NewDocumentStore(dataSourceName)
 	case "s3":
 		bucketName := os.Getenv("S3_BUCKET_NAME")
+		storageField["bucketName"] = bucketName
 		store = aws.NewDocumentStore(bucketName)
 	default:
 		store = memory.NewDocumentStore()
+		storageField["storageType"] = "in-memory"
 	}
+	logrus.WithFields(storageField).Info("Use storage")
 	return store
 }