tomas/pocketbase
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

[#3918] added --dev flag, dev log printer and some minor log UI enhacements

Browse Source
This commit is contained in:
Gani Georgiev
2023-12-16 15:41:12 +02:00
parent bf5eba0384
commit 5c961f8537
43 changed files with 3771 additions and 3411 deletions
Download Patch File Download Diff File Expand all files Collapse all files
core/app.go
+3
View File
@@ -59,6 +59,9 @@ type App interface {
// (used for settings encryption).
EncryptionEnv() string
// IsDev returns whether the app is in dev mode.
IsDev() bool
// Settings returns the loaded app settings.
Settings() *settings.Settings
core/base.go
+45 -16
View File
@@ -47,6 +47,7 @@ type BaseApp struct {
// @todo consider introducing a mutex to allow safe concurrent config changes during runtime
// configurable parameters
isDev bool
dataDir string
encryptionEnv string
dataMaxOpenConns int
@@ -174,6 +175,7 @@ type BaseApp struct {
// BaseAppConfig defines a BaseApp configuration option
type BaseAppConfig struct {
IsDev bool
DataDir string
EncryptionEnv string
DataMaxOpenConns int // default to 500
@@ -188,6 +190,7 @@ type BaseAppConfig struct {
// To initialize the app, you need to call `app.Bootstrap()`.
func NewBaseApp(config BaseAppConfig) *BaseApp {
app := &BaseApp{
isDev: config.IsDev,
dataDir: config.DataDir,
encryptionEnv: config.EncryptionEnv,
dataMaxOpenConns: config.DataMaxOpenConns,
@@ -458,6 +461,13 @@ func (app *BaseApp) EncryptionEnv() string {
return app.encryptionEnv
}
// IsDev returns whether the app is in dev mode.
//
// When enabled logs, executed sql statements, etc. are printed to the stderr.
func (app *BaseApp) IsDev() bool {
return app.isDev
}
// Settings returns the loaded app settings.
func (app *BaseApp) Settings() *settings.Settings {
return app.settings
@@ -589,9 +599,11 @@ func (app *BaseApp) RefreshSettings() error {
return err
}
// reload handler level (if initialized)
if h, ok := app.Logger().Handler().(*logger.BatchHandler); ok {
h.SetLevel(slog.Level(app.settings.Logs.MinLevel))
// reload handler level (if initialized and not in dev mode)
if !app.IsDev() && app.Logger() != nil {
if h, ok := app.Logger().Handler().(*logger.BatchHandler); ok {
h.SetLevel(slog.Level(app.settings.Logs.MinLevel))
}
}
return nil
@@ -1054,15 +1066,16 @@ func (app *BaseApp) initDataDB() error {
nonconcurrentDB.DB().SetMaxIdleConns(1)
nonconcurrentDB.DB().SetConnMaxIdleTime(3 * time.Minute)
// @todo benchmark whether it will have an impact if always enabled as TRACE log
// nonconcurrentDB.QueryLogFunc = func(ctx context.Context, t time.Duration, sql string, rows *sql.Rows, err error) {
// color.HiBlack("[%.2fms] %v\n", float64(t.Milliseconds()), sql)
// }
// concurrentDB.QueryLogFunc = nonconcurrentDB.QueryLogFunc
// nonconcurrentDB.ExecLogFunc = func(ctx context.Context, t time.Duration, sql string, result sql.Result, err error) {
// color.HiBlack("[%.2fms] %v\n", float64(t.Milliseconds()), sql)
// }
// concurrentDB.ExecLogFunc = nonconcurrentDB.ExecLogFunc
if app.IsDev() {
nonconcurrentDB.QueryLogFunc = func(ctx context.Context, t time.Duration, sql string, rows *sql.Rows, err error) {
color.HiBlack("[%.2fms] %v\n", float64(t.Milliseconds()), sql)
}
nonconcurrentDB.ExecLogFunc = func(ctx context.Context, t time.Duration, sql string, result sql.Result, err error) {
color.HiBlack("[%.2fms] %v\n", float64(t.Milliseconds()), sql)
}
concurrentDB.QueryLogFunc = nonconcurrentDB.QueryLogFunc
concurrentDB.ExecLogFunc = nonconcurrentDB.ExecLogFunc
}
app.dao = app.createDaoWithHooks(concurrentDB, nonconcurrentDB)
@@ -1176,15 +1189,31 @@ func (app *BaseApp) initLogger() error {
ticker := time.NewTicker(duration)
done := make(chan bool)
level := slog.LevelInfo
if app.Settings() != nil {
level = slog.Level(app.Settings().Logs.MinLevel)
// Apply the min level only if it is not in develop
// to allow printing the logs to the console.
//
// DB logs are still filtered but the checks for the min level are done
// in the BatchOptions.BeforeAddFunc instead of the slog.Handler.Enabled() method.
var minLevel slog.Level
if app.IsDev() {
minLevel = -9999
} else if app.Settings() != nil {
minLevel = slog.Level(app.Settings().Logs.MinLevel)
}
handler := logger.NewBatchHandler(logger.BatchOptions{
Level: level,
Level: minLevel,
BatchSize: 200,
BeforeAddFunc: func(ctx context.Context, log *logger.Log) bool {
if app.IsDev() {
printLog(log)
// manually check the log level and skip if necessary
if log.Level < slog.Level(app.Settings().Logs.MinLevel) {
return false
}
}
ticker.Reset(duration)
return app.Settings().Logs.MaxDays > 0
core/base_test.go
+253 -46
View File
@@ -1,11 +1,17 @@
package core
import (
"fmt"
"log/slog"
"os"
"testing"
"time"
"github.com/pocketbase/pocketbase/daos"
"github.com/pocketbase/pocketbase/migrations"
"github.com/pocketbase/pocketbase/migrations/logs"
"github.com/pocketbase/pocketbase/models"
"github.com/pocketbase/pocketbase/tools/list"
"github.com/pocketbase/pocketbase/tools/logger"
"github.com/pocketbase/pocketbase/tools/mailer"
"github.com/pocketbase/pocketbase/tools/migrate"
@@ -18,6 +24,7 @@ func TestNewBaseApp(t *testing.T) {
app := NewBaseApp(BaseAppConfig{
DataDir: testDataDir,
EncryptionEnv: "test_env",
IsDev: true,
})
if app.dataDir != testDataDir {
@@ -28,6 +35,10 @@ func TestNewBaseApp(t *testing.T) {
t.Fatalf("expected encryptionEnv test_env, got %q", app.dataDir)
}
if !app.isDev {
t.Fatalf("expected isDev true, got %v", app.isDev)
}
if app.store == nil {
t.Fatal("expected store to be set, got nil")
}
@@ -132,6 +143,7 @@ func TestBaseAppGetters(t *testing.T) {
app := NewBaseApp(BaseAppConfig{
DataDir: testDataDir,
EncryptionEnv: "pb_test_env",
IsDev: true,
})
defer app.ResetBootstrapState()
@@ -163,6 +175,10 @@ func TestBaseAppGetters(t *testing.T) {
t.Fatalf("Expected app.EncryptionEnv %v, got %v", app.EncryptionEnv(), app.encryptionEnv)
}
if app.isDev != app.IsDev() {
t.Fatalf("Expected app.IsDev %v, got %v", app.IsDev(), app.isDev)
}
if app.settings != app.Settings() {
t.Fatalf("Expected app.Settings %v, got %v", app.Settings(), app.settings)
}
@@ -185,13 +201,11 @@ func TestBaseAppGetters(t *testing.T) {
}
func TestBaseAppNewMailClient(t *testing.T) {
const testDataDir = "./pb_base_app_test_data_dir/"
defer os.RemoveAll(testDataDir)
app := NewBaseApp(BaseAppConfig{
DataDir: testDataDir,
EncryptionEnv: "pb_test_env",
})
app, cleanup, err := initTestBaseApp()
if err != nil {
t.Fatal(err)
}
defer cleanup()
client1 := app.NewMailClient()
if val, ok := client1.(*mailer.Sendmail); !ok {
@@ -207,13 +221,11 @@ func TestBaseAppNewMailClient(t *testing.T) {
}
func TestBaseAppNewFilesystem(t *testing.T) {
const testDataDir = "./pb_base_app_test_data_dir/"
defer os.RemoveAll(testDataDir)
app := NewBaseApp(BaseAppConfig{
DataDir: testDataDir,
EncryptionEnv: "pb_test_env",
})
app, cleanup, err := initTestBaseApp()
if err != nil {
t.Fatal(err)
}
defer cleanup()
// local
local, localErr := app.NewFilesystem()
@@ -236,13 +248,11 @@ func TestBaseAppNewFilesystem(t *testing.T) {
}
func TestBaseAppNewBackupsFilesystem(t *testing.T) {
const testDataDir = "./pb_base_app_test_data_dir/"
defer os.RemoveAll(testDataDir)
app := NewBaseApp(BaseAppConfig{
DataDir: testDataDir,
EncryptionEnv: "pb_test_env",
})
app, cleanup, err := initTestBaseApp()
if err != nil {
t.Fatal(err)
}
defer cleanup()
// local
local, localErr := app.NewBackupsFilesystem()
@@ -265,31 +275,25 @@ func TestBaseAppNewBackupsFilesystem(t *testing.T) {
}
func TestBaseAppLoggerWrites(t *testing.T) {
testDataDir, err := os.MkdirTemp("", "logger_writes")
app, cleanup, err := initTestBaseApp()
if err != nil {
t.Fatal(err)
}
defer os.RemoveAll(testDataDir)
app := NewBaseApp(BaseAppConfig{
DataDir: testDataDir,
})
if err := app.Bootstrap(); err != nil {
t.Fatal(err)
}
// init logs migrations
runner, err := migrate.NewRunner(app.LogsDB(), logs.LogsMigrations)
if err != nil {
t.Fatalf("Logs runner error: %v", err)
}
if _, err := runner.Up(); err != nil {
t.Fatalf("Logs migration execution error: %v", err)
}
defer cleanup()
threshold := 200
totalLogs := func(app App, t *testing.T) int {
var total int
err := app.LogsDao().LogQuery().Select("count(*)").Row(&total)
if err != nil {
t.Fatalf("Failed to fetch total logs: %v", err)
}
return total
}
// disabled logs retention
{
app.Settings().Logs.MaxDays = 0
@@ -333,13 +337,216 @@ func TestBaseAppLoggerWrites(t *testing.T) {
}
}
func totalLogs(app App, t *testing.T) int {
var total int
err := app.LogsDao().LogQuery().Select("count(*)").Row(&total)
func TestBaseAppRefreshSettingsLoggerMinLevelEnabled(t *testing.T) {
app, cleanup, err := initTestBaseApp()
if err != nil {
t.Fatalf("Failed to fetch total logs: %v", err)
t.Fatal(err)
}
defer cleanup()
handler, ok := app.Logger().Handler().(*logger.BatchHandler)
if !ok {
t.Fatalf("Expected BatchHandler, got %v", app.Logger().Handler())
}
return total
scenarios := []struct {
name string
isDev bool
level int
// level->enabled map
expectations map[int]bool
}{
{
"dev mode",
true,
4,
map[int]bool{
3: true,
4: true,
5: true,
},
},
{
"nondev mode",
false,
4,
map[int]bool{
3: false,
4: true,
5: true,
},
},
}
for _, s := range scenarios {
t.Run(s.name, func(t *testing.T) {
app.isDev = s.isDev
app.Settings().Logs.MinLevel = s.level
if err := app.Dao().SaveSettings(app.Settings()); err != nil {
t.Fatalf("Failed to save settings: %v", err)
}
if err := app.RefreshSettings(); err != nil {
t.Fatalf("Failed to refresh app settings: %v", err)
}
for level, enabled := range s.expectations {
if v := handler.Enabled(nil, slog.Level(level)); v != enabled {
t.Fatalf("Expected level %d Enabled() to be %v, got %v", level, enabled, v)
}
}
})
}
}
func TestBaseAppLoggerLevelDevPrint(t *testing.T) {
app, cleanup, err := initTestBaseApp()
if err != nil {
t.Fatal(err)
}
defer cleanup()
testLogLevel := 4
app.Settings().Logs.MinLevel = testLogLevel
if err := app.Dao().SaveSettings(app.Settings()); err != nil {
t.Fatal(err)
}
scenarios := []struct {
name string
isDev bool
levels []int
printedLevels []int
persistedLevels []int
}{
{
"dev mode",
true,
[]int{testLogLevel - 1, testLogLevel, testLogLevel + 1},
[]int{testLogLevel - 1, testLogLevel, testLogLevel + 1},
[]int{testLogLevel, testLogLevel + 1},
},
{
"nondev mode",
false,
[]int{testLogLevel - 1, testLogLevel, testLogLevel + 1},
[]int{},
[]int{testLogLevel, testLogLevel + 1},
},
}
for _, s := range scenarios {
t.Run(s.name, func(t *testing.T) {
var printedLevels []int
var persistedLevels []int
app.isDev = s.isDev
// trigger slog handler min level refresh
if err := app.RefreshSettings(); err != nil {
t.Fatal(err)
}
// track printed logs
originalPrintLog := printLog
defer func() {
printLog = originalPrintLog
}()
printLog = func(log *logger.Log) {
printedLevels = append(printedLevels, int(log.Level))
}
// track persisted logs
app.LogsDao().AfterCreateFunc = func(eventDao *daos.Dao, m models.Model) error {
l, ok := m.(*models.Log)
if ok {
persistedLevels = append(persistedLevels, l.Level)
}
return nil
}
// write and persist logs
for _, l := range s.levels {
app.Logger().Log(nil, slog.Level(l), "test")
}
handler, ok := app.Logger().Handler().(*logger.BatchHandler)
if !ok {
t.Fatalf("Expected BatchHandler, got %v", app.Logger().Handler())
}
if err := handler.WriteAll(nil); err != nil {
t.Fatalf("Failed to write all logs: %v", err)
}
// check persisted log levels
if len(s.persistedLevels) != len(persistedLevels) {
t.Fatalf("Expected persisted levels \n%v\ngot\n%v", s.persistedLevels, persistedLevels)
}
for _, l := range persistedLevels {
if !list.ExistInSlice(l, s.persistedLevels) {
t.Fatalf("Missing expected persisted level %v in %v", l, persistedLevels)
}
}
// check printed log levels
if len(s.printedLevels) != len(printedLevels) {
t.Fatalf("Expected printed levels \n%v\ngot\n%v", s.printedLevels, printedLevels)
}
for _, l := range printedLevels {
if !list.ExistInSlice(l, s.printedLevels) {
t.Fatalf("Missing expected printed level %v in %v", l, printedLevels)
}
}
})
}
}
// -------------------------------------------------------------------
// note: make sure to call `defer cleanup()` when the app is no longer needed.
func initTestBaseApp() (app *BaseApp, cleanup func(), err error) {
testDataDir, err := os.MkdirTemp("", "test_base_app")
if err != nil {
return nil, nil, err
}
cleanup = func() {
os.RemoveAll(testDataDir)
}
app = NewBaseApp(BaseAppConfig{
DataDir: testDataDir,
})
initErr := func() error {
if err := app.Bootstrap(); err != nil {
return fmt.Errorf("bootstrap error: %w", err)
}
logsRunner, err := migrate.NewRunner(app.LogsDB(), logs.LogsMigrations)
if err != nil {
return fmt.Errorf("logsRunner error: %w", err)
}
if _, err := logsRunner.Up(); err != nil {
return fmt.Errorf("logsRunner migrations execution error: %w", err)
}
dataRunner, err := migrate.NewRunner(app.DB(), migrations.AppMigrations)
if err != nil {
return fmt.Errorf("logsRunner error: %w", err)
}
if _, err := dataRunner.Up(); err != nil {
return fmt.Errorf("dataRunner migrations execution error: %w", err)
}
return nil
}()
if initErr != nil {
cleanup()
return nil, nil, initErr
}
return app, cleanup, nil
}
core/log_printer.go
+67
View File
@@ -0,0 +1,67 @@
package core
import (
"fmt"
"log/slog"
"strings"
"github.com/fatih/color"
"github.com/pocketbase/pocketbase/tools/logger"
"github.com/pocketbase/pocketbase/tools/store"
"github.com/spf13/cast"
)
var cachedColors = store.New[*color.Color](nil)
// getColor returns [color.Color] object and cache it (if not already).
func getColor(attrs ...color.Attribute) (c *color.Color) {
cacheKey := fmt.Sprint(attrs)
if c = cachedColors.Get(cacheKey); c == nil {
c = color.New(attrs...)
cachedColors.Set(cacheKey, c)
}
return
}
// printLog prints the provided log to the stderr.
// (note: defined as variable to overwriting in the tests)
var printLog = func(log *logger.Log) {
var str strings.Builder
switch log.Level {
case slog.LevelDebug:
str.WriteString(getColor(color.Bold, color.FgHiBlack).Sprint("DEBUG "))
str.WriteString(getColor(color.FgHiBlack).Sprint(log.Message))
case slog.LevelInfo:
str.WriteString(getColor(color.Bold, color.FgWhite).Sprint("INFO "))
str.WriteString(getColor(color.FgWhite).Sprint(log.Message))
case slog.LevelWarn:
str.WriteString(getColor(color.Bold, color.FgYellow).Sprint("WARN "))
str.WriteString(getColor(color.FgYellow).Sprint(log.Message))
case slog.LevelError:
str.WriteString(getColor(color.Bold, color.FgRed).Sprint("ERROR "))
str.WriteString(getColor(color.FgRed).Sprint(log.Message))
default:
str.WriteString(getColor(color.Bold, color.FgCyan).Sprintf("[%d] ", log.Level))
str.WriteString(getColor(color.FgCyan).Sprint(log.Message))
}
str.WriteString("\n")
if v, ok := log.Data["type"]; ok && cast.ToString(v) == "request" {
padding := 0
keys := []string{"error", "details"}
for _, k := range keys {
if v := log.Data[k]; v != nil {
str.WriteString(getColor(color.FgHiRed).Sprintf("%s└─ %v", strings.Repeat(" ", padding), v))
str.WriteString("\n")
padding += 3
}
}
} else if len(log.Data) > 0 {
str.WriteString(getColor(color.FgHiBlack).Sprintf("└─ %v", log.Data))
str.WriteString("\n")
}
fmt.Printf(str.String())
}