feat(dingo): introduce injection tracing

Readme.md

@@ -426,16 +426,16 @@ type (
 )
 
 func (t *TplInterceptor) Render(context web.Context, name string, data interface{}) io.Reader {
-	log.Println("Before Rendering", name)
+	slog.Info("Before Rendering", name)
 	start := time.Now()
 	r := t.Engine.Render(context, name, data)
-	log.Println("After Rendering", time.Since(start))
+	slog.Info("After Rendering", time.Since(start))
 	return r
 }
 
 func (f *FunctionInterceptor) Name() string {
 	funcname := f.Function.Name()
-	log.Println("Function", funcname, "used")
+	slog.Info("Function", funcname, "used")
 	return funcname
 }
 ```
@@ -479,3 +479,7 @@ https://gocover.io/github.com/i-love-flamingo/dingo
 
 Dingo has a wrapper for `func(*Injector)` called `ModuleFunc`. It is possible to wrap a function with the `ModuleFunc` to become a `Module`.
 This is similar to the `http` Packages `HandlerFunc` mechanism and allows to save code and easier set up small projects.
+
+## Troubleshooting
+1. To trace possible circular injections Dingo has function `EnableCircularTracing()`, which also switches slog to DEBUG level. This makes execution very heavy in terms of memory, so should be used only for debug purposes.
+2. To trace possible injection issues, like when Dingo tries to inject dependency into unexported field and fails, and user does not know where this happens, Dingo has `EnableInjectionTracing()`, which is also sets slog level to DEBUG. 

dingo.go

@@ -3,7 +3,7 @@ package dingo
 import (
 	"errors"
 	"fmt"
-	"log"
+	"log/slog"
 	"reflect"
 	"strings"
 )
@@ -15,14 +15,24 @@ const (
 	DEFAULT
 )
 
-var ErrInvalidInjectReceiver = errors.New("usage of 'Inject' method with struct receiver is not allowed")
-var traceCircular []circularTraceEntry
-var errPointersToInterface = errors.New(" Do not use pointers to interface.")
+var (
+	ErrInvalidInjectReceiver = errors.New("usage of 'Inject' method with struct receiver is not allowed")
+	errPointersToInterface   = errors.New(" Do not use pointers to interface.")
+
+	traceCircular    []circularTraceEntry
+	injectionTracing = false
+)
 
 // EnableCircularTracing activates dingo's trace feature to find circular dependencies
 // this is super expensive (memory wise), so it should only be used for debugging purposes
 func EnableCircularTracing() {
 	traceCircular = make([]circularTraceEntry, 0)
+	_ = slog.SetLogLoggerLevel(slog.LevelDebug)
+}
+
+func EnableInjectionTracing() {
+	injectionTracing = true
+	_ = slog.SetLogLoggerLevel(slog.LevelDebug)
 }
 
 type (
@@ -372,9 +382,11 @@ func (injector *Injector) createInstanceOfAnnotatedType(t reflect.Type, annotati
 		for _, ct := range circularTrace {
 			if ct.typ == t && ct.annotation == annotation {
 				for _, ct := range circularTrace {
-					log.Println(ct.typ.PkgPath() + "#" + ct.typ.Name() + ": " + ct.annotation)
+					slog.Debug(fmt.Sprintf("%s#%s: %s", ct.typ.PkgPath(), ct.typ.Name(), ct.annotation))
 				}
-				log.Println(t.PkgPath() + "#" + t.Name() + ": " + annotation)
+
+				slog.Debug(fmt.Sprintf("%s#%s: %s", t.PkgPath(), t.Name(), annotation))
+
 				panic("detected circular dependency")
 			}
 		}
@@ -386,6 +398,14 @@ func (injector *Injector) createInstanceOfAnnotatedType(t reflect.Type, annotati
 		return n, injector.requestInjection(n.Interface(), subCircularTrace)
 	}
 
+	if injectionTracing {
+		if t.PkgPath() == "" || t.Name() == "" {
+			slog.Debug(fmt.Sprintf("INJECTING: %s", t.String()))
+		} else {
+			slog.Debug(fmt.Sprintf("INJECTING: %s#%s \"%s\"", t.PkgPath(), t.Name(), annotation))
+		}
+	}
+
 	n := reflect.New(t)
 	return n, injector.requestInjection(n.Interface(), nil)
 }
@@ -742,11 +762,20 @@ func (injector *Injector) requestInjection(object interface{}, circularTrace []c
 						}
 					}
 					if field.Kind() != reflect.Ptr && field.Kind() != reflect.Interface && instance.Kind() == reflect.Ptr {
+						if injectionTracing {
+							slog.Debug(fmt.Sprintf("SETTING FIELD: %s of type \"%s\"", currentFieldName, ctype.Field(fieldIndex).Type.String()))
+						}
+
 						field.Set(instance.Elem())
 					} else {
 						if field.Kind() == reflect.Ptr && field.Type().Kind() == reflect.Ptr && field.Type().Elem().Kind() == reflect.Interface {
 							return wrapErr(fmt.Errorf("field %#v is pointer to interface. %w", currentFieldName, errPointersToInterface))
 						}
+
+						if injectionTracing {
+							slog.Debug(fmt.Sprintf("SETTING FIELD: %s of type \"%s\"", currentFieldName, ctype.Field(fieldIndex).Type.String()))
+						}
+
 						field.Set(instance)
 					}
 				}

example/main.go

@@ -2,6 +2,7 @@ package main
 
 import (
 	"log"
+	"log/slog"
 
 	"flamingo.me/dingo"
 	"flamingo.me/dingo/example/application"
@@ -16,7 +17,7 @@ var _ application.TransactionLog = new(stdloggerTransactionLog)
 
 // Log a message with the configure prefix
 func (s *stdloggerTransactionLog) Log(id, message string) {
-	log.Println(s.prefix, id, message)
+	slog.Info(s.prefix, id, message)
 }
 
 type defaultModule struct{}

miniexample/main.go

@@ -2,6 +2,7 @@ package main
 
 import (
 	"log"
+	"log/slog"
 
 	"flamingo.me/dingo"
 	"flamingo.me/dingo/miniexample/logger"
@@ -11,7 +12,7 @@ type stdLogger struct{}
 
 // Log logs a message
 func (s *stdLogger) Log(message string) {
-	log.Println(message)
+	slog.Info(message)
 }
 
 type loggerModule struct{}