improve logging (#1507)

* add store log file (use 3rd party lib lfshook)

* add --force-color flag to change formatter of logs

* fix /runtime-logs missing logs

* fix app logs

* fix test fail

* fix since query on logs

* update skywire@utilities

* fix name on skywire.log

* change logfile lib, add max size 1mb

* change customdmsghttppath to dmsghttp_server_path

---------

Co-authored-by: Moses Narrow <36607567+0pcom@users.noreply.github.com>

go.mod

@@ -48,6 +48,7 @@ require (
 	github.com/james-barrow/golang-ipc v0.0.0-20210227130457-95e7cc81f5e2
 	github.com/jaypipes/ghw v0.10.0
 	github.com/lib/pq v1.10.7
+	github.com/orandin/lumberjackrus v1.0.1
 	github.com/pterm/pterm v0.12.49
 	github.com/skycoin/dmsg v1.3.0-rc1.0.20230224131835-1c194ef9791e
 	github.com/skycoin/skywire-utilities v0.0.0-20230315234948-7c62dc34c53a
@@ -102,6 +103,7 @@ require (
 	golang.org/x/crypto v0.1.0 // indirect
 	golang.org/x/mod v0.6.0-dev.0.20220419223038-86c51ed26bb4 // indirect
 	golang.org/x/text v0.7.0 // indirect
+	gopkg.in/natefinch/lumberjack.v2 v2.2.1 // indirect
 	gopkg.in/yaml.v2 v2.4.0 // indirect
 	gopkg.in/yaml.v3 v3.0.1 // indirect
 	howett.net/plist v1.0.0 // indirect

go.sum

@@ -458,6 +458,8 @@ github.com/onsi/gomega v1.10.1/go.mod h1:iN09h71vgCQne3DLsj+A5owkum+a2tYe+TOCB1y
 github.com/onsi/gomega v1.17.0/go.mod h1:HnhC7FXeEQY45zxNK3PPoIUhzk/80Xly9PcubAlGdZY=
 github.com/onsi/gomega v1.18.1/go.mod h1:0q+aL8jAiMXy9hbwj2mr5GziHiwhAIQpFmmtT5hitRs=
 github.com/openzipkin/zipkin-go v0.1.1/go.mod h1:NtoC/o8u3JlF1lSlyPNswIbeQH9bJTmOf0Erfk+hxe8=
+github.com/orandin/lumberjackrus v1.0.1 h1:7ysDQ0MHD79zIFN9/EiDHjUcgopNi5ehtxFDy8rUkWo=
+github.com/orandin/lumberjackrus v1.0.1/go.mod h1:xYLt6H8W93pKnQgUQaxsApS0Eb4BwHLOkxk5DVzf5H0=
 github.com/pascaldekloe/goe v0.0.0-20180627143212-57f6aae5913c/go.mod h1:lzWF7FIEvWOWxwDKqyGYQf6ZUaNfKdP144TG7ZOy1lc=
 github.com/pascaldekloe/goe v0.1.0/go.mod h1:lzWF7FIEvWOWxwDKqyGYQf6ZUaNfKdP144TG7ZOy1lc=
 github.com/pelletier/go-toml v1.9.4/go.mod h1:u1nR/EPcESfeI/szUZKdtJ0xRNbUoANCkoOuaOx1Y+c=
@@ -1121,6 +1123,8 @@ gopkg.in/errgo.v2 v2.1.0/go.mod h1:hNsd1EY+bozCKY1Ytp96fpM3vjJbqLJn88ws8XvfDNI=
 gopkg.in/fsnotify.v1 v1.4.7/go.mod h1:Tz8NjZHkW78fSQdbUxIjBTcgA1z1m8ZHf0WmKUhAMys=
 gopkg.in/inf.v0 v0.9.1/go.mod h1:cWUDdTG/fYaXco+Dcufb5Vnc6Gp2YChqWtbxRZE0mXw=
 gopkg.in/ini.v1 v1.66.2/go.mod h1:pNLf8WUiyNEtQjuu5G5vTm06TEv9tsIgeAvK8hOrP4k=
+gopkg.in/natefinch/lumberjack.v2 v2.2.1 h1:bBRl1b0OH9s/DuPhuXpNl+VtCaJXFZ5/uEFST95x9zc=
+gopkg.in/natefinch/lumberjack.v2 v2.2.1/go.mod h1:YD8tP3GAjkrDg1eZH7EGmyESg/lsYskCTPBJVb9jqSc=
 gopkg.in/tomb.v1 v1.0.0-20141024135613-dd632973f1e7/go.mod h1:dt/ZhP58zS4L8KSrWDmTeBkI65Dw0HsyUHuEVlX15mw=
 gopkg.in/yaml.v1 v1.0.0-20140924161607-9f9df34309c0/go.mod h1:WDnlLJ4WF5VGsH/HVa3CI79GS0ol3YnhVnKP89i0kNg=
 gopkg.in/yaml.v2 v2.2.1/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI=

pkg/app/appcommon/log_store.go

@@ -215,8 +215,7 @@ func (l *bBoltLogStore) Fire(entry *log.Entry) error {
 	}()
 
 	// time in RFC3339Nano is between the bytes 1 and 36. This will change if other time layout is in use
-	t := p[1 : 1+len(timeLayout)]
-
+	t := strings.Split(strings.Split(strings.Split(p, " ")[0], "]")[0], "[")[2]
 	err = db.Update(func(tx *bbolt.Tx) error {
 		b := tx.Bucket(l.bucket)
 		return b.Put([]byte(t), []byte(str))

pkg/app/appcommon/proc_config.go

@@ -70,16 +70,17 @@ type ProcID uint16
 
 // ProcConfig defines configuration parameters for `Proc`.
 type ProcConfig struct {
-	AppName     string        `json:"app_name"`
-	AppSrvAddr  string        `json:"app_server_addr"`
-	ProcKey     ProcKey       `json:"proc_key"`
-	ProcArgs    []string      `json:"proc_args"`
-	ProcEnvs    []string      `json:"proc_envs"` // Additional env variables. Will be overwritten if they conflict with skywire-app specific envs.
-	ProcWorkDir string        `json:"proc_work_dir"`
-	VisorPK     cipher.PubKey `json:"visor_pk"`
-	RoutingPort routing.Port  `json:"routing_port"`
-	BinaryLoc   string        `json:"binary_loc"`
-	LogDBLoc    string        `json:"log_db_loc"`
+	AppName      string        `json:"app_name"`
+	AppSrvAddr   string        `json:"app_server_addr"`
+	ProcKey      ProcKey       `json:"proc_key"`
+	ProcArgs     []string      `json:"proc_args"`
+	ProcEnvs     []string      `json:"proc_envs"` // Additional env variables. Will be overwritten if they conflict with skywire-app specific envs.
+	ProcWorkDir  string        `json:"proc_work_dir"`
+	VisorPK      cipher.PubKey `json:"visor_pk"`
+	RoutingPort  routing.Port  `json:"routing_port"`
+	BinaryLoc    string        `json:"binary_loc"`
+	LogDBLoc     string        `json:"log_db_loc"`
+	LogStorePath string        `json:"log_store_path"`
 }
 
 // ProcConfigFromEnv obtains a ProcConfig from the associated env variable, returning an error if any.

pkg/app/appserver/proc.go

@@ -16,6 +16,7 @@ import (
 	"time"
 
 	ipc "github.com/james-barrow/golang-ipc"
+	"github.com/orandin/lumberjackrus"
 	"github.com/sirupsen/logrus"
 
 	"github.com/skycoin/skywire-utilities/pkg/logging"
@@ -80,7 +81,7 @@ type Proc struct {
 
 // NewProc constructs `Proc`.
 func NewProc(mLog *logging.MasterLogger, conf appcommon.ProcConfig, disc appdisc.Updater, m ProcManager,
-	appName string) *Proc {
+	appName, logStorePath string) *Proc {
 	if mLog == nil {
 		mLog = logging.NewMasterLogger()
 	}
@@ -96,8 +97,14 @@ func NewProc(mLog *logging.MasterLogger, conf appcommon.ProcConfig, disc appdisc
 	var appLogDB appcommon.LogStore
 	var appLog *logging.MasterLogger
 	var stderr io.ReadCloser
+	procLogger := mLog
 	if conf.LogDBLoc != "" {
 		appLog, appLogDB = appcommon.NewProcLogger(conf, mLog)
+		procLogger = appLog
+		if logStorePath != "" {
+			storeLog(appLog, logStorePath)
+		}
+
 		cmd.Stdout = appLog.WithField("_module", moduleName).WithField("func", "(STDOUT)").WriterLevel(logrus.DebugLevel)
 
 		// we read the Stderr pipe in order to filter some false positive app errors
@@ -109,7 +116,7 @@ func NewProc(mLog *logging.MasterLogger, conf appcommon.ProcConfig, disc appdisc
 	p := &Proc{
 		disc:      disc,
 		conf:      conf,
-		log:       mLog.PackageLogger(moduleName),
+		log:       procLogger.PackageLogger(moduleName),
 		logDB:     appLogDB,
 		cmd:       cmd,
 		connCh:    make(chan struct{}, 1),
@@ -468,3 +475,73 @@ func (p *Proc) ConnectionsSummary() []ConnectionSummary {
 
 	return summaries
 }
+
+func storeLog(log *logging.MasterLogger, localPath string) {
+	hook, _ := lumberjackrus.NewHook( //nolint
+		&lumberjackrus.LogFile{
+			Filename:   localPath + "/log/skywire.log",
+			MaxSize:    1,
+			MaxBackups: 1,
+			MaxAge:     1,
+			Compress:   false,
+			LocalTime:  false,
+		},
+		logrus.TraceLevel,
+		&logging.TextFormatter{
+			DisableColors:   true,
+			FullTimestamp:   true,
+			ForceFormatting: true,
+		},
+		&lumberjackrus.LogFileOpts{
+			logrus.InfoLevel: &lumberjackrus.LogFile{
+				Filename:   localPath + "/log/skywire.log",
+				MaxSize:    1,
+				MaxBackups: 1,
+				MaxAge:     1,
+				Compress:   false,
+				LocalTime:  false,
+			},
+			logrus.WarnLevel: &lumberjackrus.LogFile{
+				Filename:   localPath + "/log/skywire.log",
+				MaxSize:    1,
+				MaxBackups: 1,
+				MaxAge:     1,
+				Compress:   false,
+				LocalTime:  false,
+			},
+			logrus.TraceLevel: &lumberjackrus.LogFile{
+				Filename:   localPath + "/log/skywire.log",
+				MaxSize:    1,
+				MaxBackups: 1,
+				MaxAge:     1,
+				Compress:   false,
+				LocalTime:  false,
+			},
+			logrus.ErrorLevel: &lumberjackrus.LogFile{
+				Filename:   localPath + "/log/skywire.log",
+				MaxSize:    1,
+				MaxBackups: 1,
+				MaxAge:     1,
+				Compress:   false,
+				LocalTime:  false,
+			},
+			logrus.DebugLevel: &lumberjackrus.LogFile{
+				Filename:   localPath + "/log/skywire.log",
+				MaxSize:    1,
+				MaxBackups: 1,
+				MaxAge:     1,
+				Compress:   false,
+				LocalTime:  false,
+			},
+			logrus.FatalLevel: &lumberjackrus.LogFile{
+				Filename:   localPath + "/log/skywire.log",
+				MaxSize:    1,
+				MaxBackups: 1,
+				MaxAge:     1,
+				Compress:   false,
+				LocalTime:  false,
+			},
+		},
+	)
+	log.Hooks.Add(hook)
+}

pkg/app/appserver/proc_manager.go

@@ -73,10 +73,12 @@ type procManager struct {
 
 	mx   sync.RWMutex
 	done chan struct{}
+
+	logStorePath string
 }
 
 // NewProcManager constructs `ProcManager`.
-func NewProcManager(mLog *logging.MasterLogger, discF *appdisc.Factory, eb *appevent.Broadcaster, addr string) (ProcManager, error) {
+func NewProcManager(mLog *logging.MasterLogger, discF *appdisc.Factory, eb *appevent.Broadcaster, addr, logStorePath string) (ProcManager, error) {
 	if mLog == nil {
 		mLog = logging.NewMasterLogger()
 	}
@@ -93,16 +95,17 @@ func NewProcManager(mLog *logging.MasterLogger, discF *appdisc.Factory, eb *appe
 	}
 
 	procM := &procManager{
-		mLog:       mLog,
-		log:        mLog.PackageLogger("proc_manager"),
-		lis:        lis,
-		conns:      make(map[string]net.Conn),
-		discF:      discF,
-		procs:      make(map[string]*Proc),
-		procsByKey: make(map[appcommon.ProcKey]*Proc),
-		errors:     make(map[string]string),
-		eb:         eb,
-		done:       make(chan struct{}),
+		mLog:         mLog,
+		log:          mLog.PackageLogger("proc_manager"),
+		lis:          lis,
+		conns:        make(map[string]net.Conn),
+		discF:        discF,
+		procs:        make(map[string]*Proc),
+		procsByKey:   make(map[appcommon.ProcKey]*Proc),
+		errors:       make(map[string]string),
+		eb:           eb,
+		done:         make(chan struct{}),
+		logStorePath: logStorePath,
 	}
 
 	procM.connsWG.Add(1)
@@ -207,7 +210,7 @@ func (m *procManager) Start(conf appcommon.ProcConfig) (appcommon.ProcID, error)
 			Debug("No app discovery associated with app.")
 	}
 
-	proc := NewProc(m.mLog, conf, disc, m, conf.AppName)
+	proc := NewProc(nil, conf, disc, m, conf.AppName, m.logStorePath)
 	m.procs[conf.AppName] = proc
 	m.procsByKey[conf.ProcKey] = proc
 
@@ -253,7 +256,7 @@ func (m *procManager) Register(conf appcommon.ProcConfig) (appcommon.ProcKey, er
 			Debug("No app discovery associated with app.")
 	}
 
-	proc := NewProc(m.mLog, conf, disc, m, conf.AppName)
+	proc := NewProc(nil, conf, disc, m, conf.AppName, m.logStorePath)
 	m.procs[conf.AppName] = proc
 	m.procsByKey[conf.ProcKey] = proc
 	go func() {

pkg/app/appserver/proc_manager_test.go

@@ -12,7 +12,7 @@ import (
 )
 
 func TestProcManager_ProcByName(t *testing.T) {
-	mI, err := NewProcManager(nil, nil, nil, ":0")
+	mI, err := NewProcManager(nil, nil, nil, ":0", "")
 	require.NoError(t, err)
 
 	m, ok := mI.(*procManager)
@@ -32,7 +32,7 @@ func TestProcManager_ProcByName(t *testing.T) {
 }
 
 func TestProcManager_Range(t *testing.T) {
-	mI, err := NewProcManager(nil, nil, nil, ":0")
+	mI, err := NewProcManager(nil, nil, nil, ":0", "")
 	require.NoError(t, err)
 
 	m, ok := mI.(*procManager)
@@ -61,7 +61,7 @@ func TestProcManager_Range(t *testing.T) {
 }
 
 func TestProcManager_Pop(t *testing.T) {
-	mI, err := NewProcManager(nil, nil, nil, ":0")
+	mI, err := NewProcManager(nil, nil, nil, ":0", "")
 	require.NoError(t, err)
 
 	m, ok := mI.(*procManager)
@@ -84,7 +84,7 @@ func TestProcManager_Pop(t *testing.T) {
 }
 
 func TestProcManager_SetDetailedStatus(t *testing.T) {
-	mI, err := NewProcManager(nil, nil, nil, ":0")
+	mI, err := NewProcManager(nil, nil, nil, ":0", "")
 	require.NoError(t, err)
 
 	m, ok := mI.(*procManager)
@@ -109,7 +109,7 @@ func TestProcManager_SetDetailedStatus(t *testing.T) {
 }
 
 func TestProcManager_DetailedStatus(t *testing.T) {
-	mI, err := NewProcManager(nil, nil, nil, ":0")
+	mI, err := NewProcManager(nil, nil, nil, ":0", "")
 	require.NoError(t, err)
 
 	m, ok := mI.(*procManager)
@@ -132,7 +132,7 @@ func TestProcManager_DetailedStatus(t *testing.T) {
 }
 
 func TestProcManager_RegisterAndDeregister(t *testing.T) {
-	mI, err := NewProcManager(nil, nil, nil, ":0")
+	mI, err := NewProcManager(nil, nil, nil, ":0", "")
 	require.NoError(t, err)
 
 	m, ok := mI.(*procManager)

pkg/visor/cmd.go

@@ -55,6 +55,8 @@ var (
 	visorBuildInfo *buildinfo.Info
 	dmsgServer     string
 	rawSurvey      bool
+	isStoreLog     bool
+	isForceColor   bool
 )
 
 func init() {
@@ -130,8 +132,11 @@ func init() {
 	hiddenflags = append(hiddenflags, "completion")
 	RootCmd.Flags().BoolVar(&rawSurvey, "raw-survey", false, "survey will generate and store decrypted if pass this flag")
 	hiddenflags = append(hiddenflags, "raw-survey")
+	RootCmd.Flags().BoolVarP(&isStoreLog, "store-log", "l", false, "store all logs to file")
+	hiddenflags = append(hiddenflags, "store-log")
+	RootCmd.Flags().BoolVar(&isForceColor, "force-color", false, "set force coler true in loggers")
+	hiddenflags = append(hiddenflags, "force-color")
 	RootCmd.Flags().BoolVar(&all, "all", false, "show all flags")
-
 	for _, j := range hiddenflags {
 		RootCmd.Flags().MarkHidden(j) //nolint
 	}

pkg/visor/init.go

@@ -388,7 +388,7 @@ func initDmsgHTTPLogServer(ctx context.Context, v *Visor, log *logging.Logger) e
 		printLog = true
 	}
 
-	lsAPI := logserver.New(logger, v.conf.Transport.LogStore.Location, v.conf.LocalPath, v.conf.CustomDmsgHTTPPath, printLog)
+	lsAPI := logserver.New(logger, v.conf.Transport.LogStore.Location, v.conf.LocalPath, v.conf.DmsgHTTPServerPath, printLog)
 
 	lis, err := dmsgC.Listen(visorconfig.DmsgHTTPPort)
 	if err != nil {
@@ -1007,7 +1007,7 @@ func initLauncher(ctx context.Context, v *Visor, log *logging.Logger) error {
 	conf := v.conf.Launcher
 
 	// Prepare proc manager.
-	procM, err := appserver.NewProcManager(v.MasterLogger(), &v.serviceDisc, v.ebc, conf.ServerAddr)
+	procM, err := appserver.NewProcManager(v.MasterLogger(), &v.serviceDisc, v.ebc, conf.ServerAddr, v.conf.LocalPath)
 	if err != nil {
 		err := fmt.Errorf("failed to start proc_manager: %w", err)
 		return err