fix #873 : stats logs moved to independent stats file

essentials/log/esl/default.go

@@ -15,10 +15,15 @@ import (
 var (
 	currentDefault Tee = newDefault()
 	currentConsole     = newConsole(ConsoleDefaultLevel())
+	currentStats       = newEmpty()
 	capture            = newEmpty()
 	loggerName     atomic.Int64
 )
 
+func SetStats(l Logger) {
+	currentStats = l
+}
+
 func Default() Logger {
 	return currentDefault
 }
@@ -31,6 +36,10 @@ func Capture() Logger {
 	return capture
 }
 
+func Stats() Logger {
+	return currentStats
+}
+
 func newEmpty() Logger {
 	return New(ConsoleDefaultLevel(), FlavorConsole, ioutil.Discard)
 }

essentials/log/esl_container/container.go

@@ -22,28 +22,36 @@ type Logger interface {
 	Close()
 }
 
-func NewTransient(consoleLevel esl.Level) (t, c, s Logger) {
+func NewTransient(consoleLevel esl.Level) (t, c, s, stats Logger) {
 	t = newTransient(consoleLevel, esl.FlavorConsole)
 	c = newTransient(esl.LevelQuiet, esl.FlavorFileCapture)
 	s = newTransient(esl.LevelQuiet, esl.FlavorConsole)
+	stats = newTransient(esl.LevelQuiet, esl.FlavorConsole)
 	return
 }
 
-func NewAll(basePath string, budget app_budget.Budget, consoleLevel esl.Level) (t, c, s Logger, err error) {
+func NewAll(basePath string, budget app_budget.Budget, consoleLevel esl.Level) (t, c, s, stats Logger, err error) {
 	t, err = NewToolbox(basePath, budget, consoleLevel)
 	if err != nil {
-		return nil, nil, nil, err
+		return nil, nil, nil, nil, err
 	}
 	c, err = NewCapture(basePath, budget)
 	if err != nil {
 		t.Close()
-		return nil, nil, nil, err
+		return nil, nil, nil, nil, err
 	}
 	s, err = LogSummary(basePath)
 	if err != nil {
 		t.Close()
 		c.Close()
-		return nil, nil, nil, err
+		return nil, nil, nil, nil, err
+	}
+	stats, err = LogStats(basePath, budget)
+	if err != nil {
+		t.Close()
+		c.Close()
+		s.Close()
+		return nil, nil, nil, nil, err
 	}
 	return
 }
@@ -60,6 +68,10 @@ func LogSummary(basePath string) (c Logger, err error) {
 	return New(basePath, app_definitions.LogSummary, app_budget.BudgetUnlimited, esl.LevelDebug, esl.LevelInfo, esl.FlavorFileStandard, false, false)
 }
 
+func LogStats(basePath string, budget app_budget.Budget) (c Logger, err error) {
+	return New(basePath, app_definitions.LogStats, budget, esl.LevelDebug, esl.LevelInfo, esl.FlavorFileStandard, false, false)
+}
+
 func New(basePath, name string, budget app_budget.Budget, fileLevel, consoleLevel esl.Level, flavor esl.Flavor, teeConsole, compress bool) (c Logger, err error) {
 	w := esl_rotate.NewWriter(basePath, name)
 

essentials/network/nw_congestion/congestion.go

@@ -139,7 +139,7 @@ func (z *ccImpl) key(hash, endpoint string) string {
 
 func (z *ccImpl) Start(hash, endpoint string) {
 	goRoutineId := es_goroutine.GetGoRoutineName()
-	l := esl.Default().With(esl.String("goroutine", goRoutineId),
+	l := esl.Stats().With(esl.String("goroutine", goRoutineId),
 		esl.String("hash", hash), esl.String("endpoint", endpoint))
 
 	z.monitorOnce.Do(func() {
@@ -206,7 +206,7 @@ func (z *ccImpl) Start(hash, endpoint string) {
 
 func (z *ccImpl) EndSuccess(hash, endpoint string) {
 	goRoutineId := es_goroutine.GetGoRoutineName()
-	l := esl.Default().With(esl.String("goroutine", goRoutineId),
+	l := esl.Stats().With(esl.String("goroutine", goRoutineId),
 		esl.String("hash", hash), esl.String("endpoint", endpoint))
 	l.Debug("Process finished: success")
 	key := z.key(hash, endpoint)
@@ -226,7 +226,7 @@ func (z *ccImpl) EndSuccess(hash, endpoint string) {
 
 func (z *ccImpl) EndTransportError(hash, endpoint string) {
 	goRoutineId := es_goroutine.GetGoRoutineName()
-	l := esl.Default().With(esl.String("goroutine", goRoutineId),
+	l := esl.Stats().With(esl.String("goroutine", goRoutineId),
 		esl.String("hash", hash), esl.String("endpoint", endpoint))
 
 	l.Debug("Transport error; do not change window")
@@ -246,7 +246,7 @@ func (z *ccImpl) isSignificantWait(reset time.Time) bool {
 func (z *ccImpl) EndRateLimit(hash, endpoint string, reset time.Time) {
 	isSignificant := z.isSignificantWait(reset)
 
-	l := esl.Default().With(esl.String("goroutine", es_goroutine.GetGoRoutineName()),
+	l := esl.Stats().With(esl.String("goroutine", es_goroutine.GetGoRoutineName()),
 		esl.String("hash", hash),
 		esl.String("endpoint", endpoint),
 		esl.Bool("significant", isSignificant),
@@ -295,7 +295,7 @@ func (z *ccImpl) EndRateLimit(hash, endpoint string, reset time.Time) {
 
 func (z *ccImpl) monitor() {
 	ticker := time.NewTicker(getReportInterval())
-	l := esl.Default().With(esl.String("goroutine", es_goroutine.GetGoRoutineName()))
+	l := esl.Stats().With(esl.String("goroutine", es_goroutine.GetGoRoutineName()))
 	l.Debug("Monitor start")
 
 	for {
@@ -328,7 +328,7 @@ func (z *ccImpl) monitor() {
 }
 
 func (z *ccImpl) noLockCanIncreaseWindow(key string) bool {
-	l := esl.Default().With(esl.String("goroutine", es_goroutine.GetGoRoutineName()),
+	l := esl.Stats().With(esl.String("goroutine", es_goroutine.GetGoRoutineName()),
 		esl.String("key", key))
 
 	monitorTime := time.Now().Add(-monitorDuration)
@@ -367,7 +367,7 @@ func (z *ccImpl) noLockCanIncreaseWindow(key string) bool {
 
 func (z *ccImpl) noLockCalcConcurrency(key string, includeSelf bool) (concurrency, waiters int) {
 	goRoutineId := es_goroutine.GetGoRoutineName()
-	l := esl.Default().With(esl.String("goroutine", goRoutineId),
+	l := esl.Stats().With(esl.String("goroutine", goRoutineId),
 		esl.String("key", key))
 
 	concurrency = 0
@@ -398,7 +398,7 @@ func (z *ccImpl) noLockCalcConcurrency(key string, includeSelf bool) (concurrenc
 
 func (z *ccImpl) noLockRelease(key string) {
 	goRoutineId := es_goroutine.GetGoRoutineName()
-	l := esl.Default().With(esl.String("goroutine", goRoutineId),
+	l := esl.Stats().With(esl.String("goroutine", goRoutineId),
 		esl.String("key", key))
 
 	delete(z.runners, goRoutineId)
@@ -407,7 +407,7 @@ func (z *ccImpl) noLockRelease(key string) {
 }
 
 func (z *ccImpl) noLockNotifyWaiters(key string) {
-	l := esl.Default().With(esl.String("goroutine", es_goroutine.GetGoRoutineName()),
+	l := esl.Stats().With(esl.String("goroutine", es_goroutine.GetGoRoutineName()),
 		esl.String("key", key))
 
 	window := z.window[key]

infra/control/app_definitions/constants.go

@@ -123,6 +123,7 @@ const (
 	LogToolbox = "toolbox"
 	LogCapture = "capture"
 	LogSummary = "summary"
+	LogStats   = "stats"
 
 	// Log names
 	LogNameStart  = "recipe.log"

infra/control/app_job_impl/launcher.go

@@ -97,8 +97,11 @@ func (z launchImpl) prepAuthDatabase(fe app_feature.Feature) (repo api_auth.Repo
 func (z launchImpl) Up() (ctl app_control.Control, err error) {
 	lg := z.wb.Logger().Logger()
 	sm := z.wb.Summary().Logger()
+	st := z.wb.Stats().Logger()
 	fe := app_feature_impl.NewFeature(z.com, z.wb.Workspace(), z.rcp.IsTransient())
 
+	esl.SetStats(st)
+
 	seq, er := app_queue.NewSequence(lg, fe, z.ui, z.wb)
 	ar, err := z.prepAuthDatabase(fe)
 	if err != nil {
@@ -120,7 +123,7 @@ func (z launchImpl) Up() (ctl app_control.Control, err error) {
 	}
 
 	// Launch monitor
-	es_memory.LaunchReporting(lg)
+	es_memory.LaunchReporting(st)
 
 	sm.Debug("Up completed",
 		esl.String("name", app_definitions.Name),

infra/control/app_license/license.go

@@ -516,6 +516,10 @@ func loadLicenseFile(key, path string) (ld *LicenseData, err error) {
 
 func ParseLicense(data []byte, license string) (ld *LicenseData, err error) {
 	l := esl.Default()
+	if license == "" || len(data) == 0 {
+		l.Debug("License is empty")
+		return nil, ErrorUnknownLicenseType
+	}
 	keySalt := app_definitions.BuildInfo.LicenseSalt + license
 	p1, err := sc_obfuscate.Deobfuscate(l, []byte(keySalt), data)
 	if err != nil {

infra/control/app_workspace/bundle.go

@@ -24,6 +24,9 @@ type Bundle interface {
 	// Summary logger
 	Summary() esl_container.Logger
 
+	// Stats logger
+	Stats() esl_container.Logger
+
 	// Storage budget
 	Budget() app_budget.Budget
 
@@ -43,11 +46,11 @@ func ForkBundleWithLevel(wb Bundle, name string, consoleLevel esl.Level) (bundle
 	if err != nil {
 		return nil, err
 	}
-	l, c, s, err := esl_container.NewAll(nws.Log(), wb.Budget(), consoleLevel)
+	l, c, s, st, err := esl_container.NewAll(nws.Log(), wb.Budget(), consoleLevel)
 	if err != nil {
 		return nil, err
 	}
-	return newBundleInternal(nws, wb.Budget(), c, l, s, consoleLevel, wb.IsTransient()), nil
+	return newBundleInternal(nws, wb.Budget(), c, l, s, st, consoleLevel, wb.IsTransient()), nil
 }
 
 func WithFork(wb Bundle, name string, f func(fwb Bundle) error) error {
@@ -67,25 +70,26 @@ func NewBundle(home string, budget app_budget.Budget, consoleLevel esl.Level, tr
 		return nil, err
 	}
 
-	var l, c, s esl_container.Logger
+	var l, c, s, st esl_container.Logger
 	if skipLogging {
-		l, c, s = esl_container.NewTransient(consoleLevel)
+		l, c, s, st = esl_container.NewTransient(consoleLevel)
 	} else {
-		l, c, s, err = esl_container.NewAll(ws.Log(), budget, consoleLevel)
+		l, c, s, st, err = esl_container.NewAll(ws.Log(), budget, consoleLevel)
 		if err != nil {
 			return nil, err
 		}
 	}
-	return newBundleInternal(ws, budget, c, l, s, consoleLevel, transient), nil
+	return newBundleInternal(ws, budget, c, l, s, st, consoleLevel, transient), nil
 }
 
-func newBundleInternal(ws Workspace, budget app_budget.Budget, capture, logger, summary esl_container.Logger, consoleLevel esl.Level, transient bool) Bundle {
+func newBundleInternal(ws Workspace, budget app_budget.Budget, capture, logger, summary, stats esl_container.Logger, consoleLevel esl.Level, transient bool) Bundle {
 	return &bdlImpl{
 		budget:    budget,
 		conLv:     consoleLevel,
 		capture:   capture,
 		logger:    logger,
 		summary:   summary,
+		stats:     stats,
 		ws:        ws,
 		transient: transient,
 	}
@@ -97,10 +101,15 @@ type bdlImpl struct {
 	capture   esl_container.Logger
 	logger    esl_container.Logger
 	summary   esl_container.Logger
+	stats     esl_container.Logger
 	ws        Workspace
 	transient bool
 }
 
+func (z bdlImpl) Stats() esl_container.Logger {
+	return z.stats
+}
+
 func (z bdlImpl) IsTransient() bool {
 	return z.transient
 }

infra/report/rp_writer_impl/json.go

@@ -17,6 +17,11 @@ import (
 	"sync"
 )
 
+var (
+	filterQueryLogEnabledExposed = false
+	filterQueryLogErrorExposed   = false
+)
+
 func NewJsonWriter(name string, ctl app_control.Control, toStdout bool) rp_writer.Writer {
 	return &jsonWriter{
 		name:     name,
@@ -105,10 +110,16 @@ func (z *jsonWriter) Row(r interface{}) {
 	var filterQuery *gojq.Query
 	var err error
 	if enabled {
-		l.Debug("Filter enabled", esl.String("filter", filter))
+		if !filterQueryLogEnabledExposed {
+			l.Debug("Filter enabled", esl.String("filter", filter))
+			filterQueryLogEnabledExposed = true
+		}
 		filterQuery, err = gojq.Parse(filter)
 		if err != nil {
-			l.Debug("Unable to parse filter query", esl.Error(err))
+			if !filterQueryLogErrorExposed {
+				l.Debug("Unable to parse filter query", esl.Error(err))
+				filterQueryLogErrorExposed = true
+			}
 			filterQuery = nil // ignore filter
 		}
 	}