Feature/runtime logs

cmd/skywire-visor/commands/root.go

@@ -2,10 +2,8 @@ package commands
 
 import (
 	"context"
-	"embed"
 	"fmt"
 	"io"
-	"io/fs"
 	"io/ioutil"
 	"net/http"
 	_ "net/http/pprof" // nolint:gosec // https://golang.org/doc/diagnostics.html#profiling
@@ -15,6 +13,9 @@ import (
 	"syscall"
 	"time"
 
+	"embed"
+	"io/fs"
+
 	"github.com/pkg/profile"
 	"github.com/skycoin/dmsg/buildinfo"
 	"github.com/skycoin/dmsg/cmdutil"

go.sum

@@ -275,6 +275,7 @@ golang.org/x/crypto v0.0.0-20201208171446-5f87f3452ae9 h1:sYNJzB4J8toYPQTM6pAkcm
 golang.org/x/crypto v0.0.0-20201208171446-5f87f3452ae9/go.mod h1:jdWPYTVW3xRLrWPugEBEK3UY2ZEsg3UU495nc5E+M+I=
 golang.org/x/lint v0.0.0-20181026193005-c67002cb31c3/go.mod h1:UVdnD1Gm6xHRNCYTkRU2/jEulfH38KcIWyp/GAMgvoE=
 golang.org/x/lint v0.0.0-20190313153728-d0100b6bd8b3/go.mod h1:6SW0HCj/g11FgYtHlgUYUwCkIfeOF89ocIRzGO/8vkc=
+golang.org/x/mod v0.2.0 h1:KU7oHjnv3XNWfa5COkzUifxZmxp1TyI7ImMXqFxLwvQ=
 golang.org/x/mod v0.2.0/go.mod h1:s0Qsj1ACt9ePp/hMypM3fl4fZqREWJwdYDEqhRiZZUA=
 golang.org/x/mod v0.3.0/go.mod h1:s0Qsj1ACt9ePp/hMypM3fl4fZqREWJwdYDEqhRiZZUA=
 golang.org/x/mod v0.4.2 h1:Gz96sIWK3OalVv/I/qNygP42zyoKp3xptRVCWRFEBvo=
@@ -327,7 +328,6 @@ golang.org/x/text v0.3.2/go.mod h1:bEr9sfX3Q8Zfm5fL9x+3itogRgK3+ptLWKqgva+5dAk=
 golang.org/x/text v0.3.3 h1:cokOdA+Jmi5PJGXLlLllQSgYigAEfHXJAERHVMaCc2k=
 golang.org/x/text v0.3.3/go.mod h1:5Zoc/QRtKVWzQhOtBMvqHzDpF6irO9z98xDceosuGiQ=
 golang.org/x/time v0.0.0-20190308202827-9d24e82272b4/go.mod h1:tRJNPiyCQ0inRvYxbN9jk5I+vvW/OXSQhTDSoE431IQ=
-golang.org/x/time v0.0.0-20191024005414-555d28b269f0 h1:/5xXl8Y5W96D+TtHSlonuFqGHIWVuyCkGJLwGh9JJFs=
 golang.org/x/time v0.0.0-20191024005414-555d28b269f0/go.mod h1:tRJNPiyCQ0inRvYxbN9jk5I+vvW/OXSQhTDSoE431IQ=
 golang.org/x/tools v0.0.0-20180221164845-07fd8470d635/go.mod h1:n7NCudcB/nEzxVGmLbDWY5pfWTLqBcC2KZ6jyYvM4mQ=
 golang.org/x/tools v0.0.0-20180917221912-90fa682c2a6e/go.mod h1:n7NCudcB/nEzxVGmLbDWY5pfWTLqBcC2KZ6jyYvM4mQ=
@@ -354,12 +354,10 @@ google.golang.org/protobuf v0.0.0-20200221191635-4d8936d0db64/go.mod h1:kwYJMbMJ
 google.golang.org/protobuf v0.0.0-20200228230310-ab0ca4ff8a60/go.mod h1:cfTl7dwQJ+fmap5saPgwCLgHXTUD7jkjRqWcaiX5VyM=
 google.golang.org/protobuf v1.20.1-0.20200309200217-e05f789c0967/go.mod h1:A+miEFZTKqfCUM6K7xSMQL9OKL/b6hQv+e19PK+JZNE=
 google.golang.org/protobuf v1.21.0/go.mod h1:47Nbq4nVaFHyn7ilMalzfO3qCViNmqZ2kzikPIcrTAo=
-google.golang.org/protobuf v1.23.0 h1:4MY060fB1DLGMB/7MBTLnwQUY6+F09GEiz6SsrNqyzM=
 google.golang.org/protobuf v1.23.0/go.mod h1:EGpADcykh3NcUnDUJcl1+ZksZNG86OlYog2l/sGQquU=
 gopkg.in/alecthomas/kingpin.v2 v2.2.6/go.mod h1:FMv+mEhP44yOT+4EoQTLFTRgOQ1FBLkstjWtayDeSgw=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
 gopkg.in/check.v1 v1.0.0-20180628173108-788fd7840127/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
-gopkg.in/check.v1 v1.0.0-20190902080502-41f04d3bba15 h1:YR8cESwS4TdDjEe65xsg0ogRM/Nc3DYOhEAlW+xobZo=
 gopkg.in/check.v1 v1.0.0-20190902080502-41f04d3bba15/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
 gopkg.in/fsnotify.v1 v1.4.7/go.mod h1:Tz8NjZHkW78fSQdbUxIjBTcgA1z1m8ZHf0WmKUhAMys=
 gopkg.in/ini.v1 v1.51.0/go.mod h1:pNLf8WUiyNEtQjuu5G5vTm06TEv9tsIgeAvK8hOrP4k=

pkg/visor/api.go

@@ -69,6 +69,7 @@ type API interface {
 	UpdateWithStatus(config updater.UpdateConfig) <-chan StatusMessage
 	UpdateAvailable(channel updater.Channel) (*updater.Version, error)
 	UpdateStatus() (string, error)
+	RuntimeLogs() (string, error)
 }
 
 // HealthCheckable resource returns its health status as an integer
@@ -723,3 +724,8 @@ func (v *Visor) UpdateAvailable(channel updater.Channel) (*updater.Version, erro
 func (v *Visor) UpdateStatus() (string, error) {
 	return v.updater.Status(), nil
 }
+
+// RuntimeLogs returns visor runtime logs
+func (v *Visor) RuntimeLogs() (string, error) {
+	return v.logstore.GetLogStr()
+}

pkg/visor/hypervisor.go

@@ -257,6 +257,7 @@ func (hv *Hypervisor) makeMux() chi.Router {
 				r.Get("/visors/{pk}/update/ws/running", hv.isVisorWSUpdateRunning())
 				r.Get("/visors/{pk}/update/available", hv.visorUpdateAvailable())
 				r.Get("/visors/{pk}/update/available/{channel}", hv.visorUpdateAvailable())
+				r.Get("/visors/{pk}/runtime-logs", hv.getRuntimeLogs())
 			})
 		})
 
@@ -1304,6 +1305,22 @@ func (hv *Hypervisor) visorUpdateAvailable() http.HandlerFunc {
 	})
 }
 
+func (hv *Hypervisor) getRuntimeLogs() http.HandlerFunc {
+	return hv.withCtx(hv.visorCtx, func(w http.ResponseWriter, r *http.Request, ctx *httpCtx) {
+		logs, err := ctx.API.RuntimeLogs()
+		if err != nil {
+			httputil.WriteJSON(w, r, http.StatusInternalServerError, err)
+			return
+		}
+		w.Header().Set("Content-Type", "application/json")
+		w.WriteHeader(http.StatusOK)
+		_, err = w.Write([]byte(logs))
+		if err != nil {
+			hv.visor.log.Errorf("Cannot write response: %s", err)
+		}
+	})
+}
+
 /*
 	<<< Helper functions >>>
 */

pkg/visor/hypervisorconfig/config.go

@@ -3,13 +3,14 @@ package hypervisorconfig
 import (
 	"encoding/hex"
 	"encoding/json"
-	"io/fs"
 	"log"
 	"net/http"
 	"os"
 	"path/filepath"
 	"time"
 
+	"io/fs"
+
 	"github.com/skycoin/dmsg/cipher"
 
 	"github.com/skycoin/skywire/pkg/skyenv"

pkg/visor/logstore/logstore.go

@@ -0,0 +1,94 @@
+package logstore
+
+import (
+	"strings"
+
+	"github.com/sirupsen/logrus"
+)
+
+// LogRealLineKey is a key in the log enry that denote real log line number
+// in the total log (not limited by capacity of runtime log store)
+const LogRealLineKey = "real_line"
+
+// Store is in-memory log store that returns all logs as a single string
+type Store interface {
+	// get logs returns stored logs and the number of log entries overwritten
+	// due to insufficient capacity.
+	// returned number n means that n log entries have been dropped and the oldest
+	// log entry is (n+1)th
+	GetLogs() ([]*logrus.Entry, int64)
+	// get logs as a single string
+	GetLogStr() (string, error)
+}
+
+// MakeStore returns a new store that will hold up to max entries,
+// overwriting the oldest entry when over the capacity
+// returned hook should be registered in logrus master logger to
+// store log entries
+func MakeStore(max int) (Store, logrus.Hook) {
+	entries := make([]*logrus.Entry, max)
+	formatter := &logrus.JSONFormatter{}
+	store := &store{cap: int64(max), entries: entries, formatter: formatter}
+	return store, store
+}
+
+type store struct {
+	// max number of entries to hold simultaneously
+	cap int64
+	// number of the next entry to come (also number of entries processed since the beginning)
+	entryNum  int64
+	entries   []*logrus.Entry
+	formatter logrus.Formatter
+}
+
+// GetLogs returns most resent log lines (up to cap log lines is stored)
+func (s *store) GetLogs() ([]*logrus.Entry, int64) {
+	if s.entryNum < s.cap {
+		return s.collectLogs(0, s.entryNum), 0
+	}
+	idx := s.entryNum % s.cap
+	logs := s.collectLogs(idx, s.cap)
+	logs = append(logs, s.collectLogs(0, idx)...)
+	return logs, s.entryNum - s.cap
+}
+
+// collect log lines into a single string, starting at from (inclusive)
+// and ending at to (not inclusive)
+func (s *store) collectLogs(from, to int64) []*logrus.Entry {
+	logs := make([]*logrus.Entry, 0)
+	for i := from; i < to; i++ {
+		logs = append(logs, s.entries[i])
+	}
+	return logs
+}
+
+// GetLogStr returns logs as a single string
+// log entries are formatted with store formatter and concatenated together
+func (s *store) GetLogStr() (string, error) {
+	logs, _ := s.GetLogs()
+	var sb strings.Builder
+	for _, entry := range logs {
+		bs, err := s.formatter.Format(entry)
+		if err != nil {
+			return "", err
+		}
+		sb.WriteString(string(bs))
+	}
+	return sb.String(), nil
+}
+
+// Levels implements logrus.Hook interface. It denotes log levels
+// that we are interested in
+func (s *store) Levels() []logrus.Level {
+	return logrus.AllLevels
+}
+
+// Fire implements logrus.Hook interface to process new log entry
+// that we simply store
+func (s *store) Fire(entry *logrus.Entry) error {
+	idx := s.entryNum % s.cap
+	e := entry.WithField(LogRealLineKey, s.entryNum)
+	s.entries[idx] = e
+	s.entryNum++
+	return nil
+}

pkg/visor/rpc.go

@@ -538,3 +538,9 @@ func (r *RPC) UpdateStatus(_ *struct{}, status *string) (err error) {
 	*status, err = r.visor.UpdateStatus()
 	return
 }
+
+// RuntimeLogs returns visor runtime logs
+func (r *RPC) RuntimeLogs(_ *struct{}, logs *string) (err error) {
+	*logs, err = r.visor.RuntimeLogs()
+	return
+}

pkg/visor/rpc_client.go

@@ -331,6 +331,13 @@ func (rc *rpcClient) Update(config updater.UpdateConfig) (bool, error) {
 	return updated, err
 }
 
+// Update calls Update.
+func (rc *rpcClient) RuntimeLogs() (string, error) {
+	var logs string
+	err := rc.Call("RuntimeLogs", &struct{}{}, &logs)
+	return logs, err
+}
+
 // StatusMessage defines a status of visor update.
 type StatusMessage struct {
 	Text    string
@@ -911,3 +918,8 @@ func (mc *mockRPCClient) UpdateAvailable(_ updater.Channel) (*updater.Version, e
 func (mc *mockRPCClient) UpdateStatus() (string, error) {
 	return "", nil
 }
+
+// UpdateStatus implements API.
+func (mc *mockRPCClient) RuntimeLogs() (string, error) {
+	return "", nil
+}

pkg/visor/visor.go

@@ -26,6 +26,7 @@ import (
 	"github.com/skycoin/skywire/pkg/snet/arclient"
 	"github.com/skycoin/skywire/pkg/transport"
 	"github.com/skycoin/skywire/pkg/util/updater"
+	"github.com/skycoin/skywire/pkg/visor/logstore"
 	"github.com/skycoin/skywire/pkg/visor/visorconfig"
 )
 
@@ -40,6 +41,7 @@ const (
 	// moduleShutdownTimeout is the timeout given to a module to shutdown cleanly.
 	// Otherwise the shutdown logic will continue and report a timeout error.
 	moduleShutdownTimeout = time.Second * 2
+	runtimeLogMaxEntries  = 300
 )
 
 // Visor provides messaging runtime for Apps by setting up all
@@ -48,8 +50,9 @@ type Visor struct {
 	reportCh   chan vReport
 	closeStack []closeElem
 
-	conf *visorconfig.V1
-	log  *logging.Logger
+	conf     *visorconfig.V1
+	log      *logging.Logger
+	logstore logstore.Store
 
 	startedAt     time.Time
 	restartCtx    *restart.Context
@@ -117,6 +120,13 @@ func (v *Visor) MasterLogger() *logging.MasterLogger {
 	return v.conf.MasterLogger()
 }
 
+func (v *Visor) setupRuntimeLogStore() {
+	// todo: add config to change the capacity of in-memory log store
+	store, hook := logstore.MakeStore(runtimeLogMaxEntries)
+	v.MasterLogger().AddHook(hook)
+	v.logstore = store
+}
+
 // NewVisor constructs new Visor.
 func NewVisor(conf *visorconfig.V1, restartCtx *restart.Context) (v *Visor, ok bool) {
 	ok = true
@@ -134,6 +144,7 @@ func NewVisor(conf *visorconfig.V1, restartCtx *restart.Context) (v *Visor, ok b
 		v.conf.MasterLogger().SetLevel(logLvl)
 		logging.SetLevel(logLvl)
 	}
+	v.setupRuntimeLogStore()
 
 	log := v.MasterLogger().PackageLogger("visor:startup")
 	log.WithField("public_key", conf.PK).