Merge pull request #3577 from ActiveState/DX-3136

Handle more panics

cmd/state-svc/internal/messages/messages.go

@@ -4,6 +4,7 @@ import (
 	"encoding/json"
 	"fmt"
 	"os"
+	"runtime/debug"
 	"sync"
 	"time"
 
@@ -15,6 +16,7 @@ import (
 	"github.com/ActiveState/cli/internal/httputil"
 	"github.com/ActiveState/cli/internal/logging"
 	"github.com/ActiveState/cli/internal/poller"
+	"github.com/ActiveState/cli/internal/runbits/panics"
 	"github.com/ActiveState/cli/internal/strutils"
 	auth "github.com/ActiveState/cli/pkg/platform/authentication"
 	"github.com/ActiveState/cli/pkg/sysinfo"
@@ -43,6 +45,9 @@ func New(cfg *config.Instance, auth *auth.Auth) (*Messages, error) {
 	}
 
 	poll := poller.New(1*time.Hour, func() (interface{}, error) {
+		defer func() {
+			panics.LogAndPanic(recover(), debug.Stack())
+		}()
 		resp, err := fetch()
 		return resp, err
 	})
@@ -74,7 +79,11 @@ func (m *Messages) Check(command string, flags []string) ([]*graph.MessageInfo,
 	if cacheValue == nil {
 		return []*graph.MessageInfo{}, nil
 	}
-	allMessages := cacheValue.([]*graph.MessageInfo)
+
+	allMessages, ok := cacheValue.([]*graph.MessageInfo)
+	if !ok {
+		return nil, errs.New("cacheValue has unexpected type: %T", cacheValue)
+	}
 
 	conditionParams := *m.baseParams // copy
 	conditionParams.UserEmail = m.auth.Email()
@@ -110,7 +119,11 @@ func check(params *ConditionParams, messages []*graph.MessageInfo, lastReportMap
 		logging.Debug("Checking message %s", message.ID)
 		// Ensure we don't show the same message too often
 		if lastReport, ok := lastReportMap[message.ID]; ok {
-			lastReportTime, err := time.Parse(time.RFC3339, lastReport.(string))
+			lr, ok := lastReport.(string)
+			if !ok {
+				return nil, errs.New("Could not get last reported time for message %s as it's not a string: %T", message.ID, lastReport)
+			}
+			lastReportTime, err := time.Parse(time.RFC3339, lr)
 			if err != nil {
 				return nil, errs.New("Could not parse last reported time for message %s as it's not a valid RFC3339 value: %v", message.ID, lastReport)
 			}

cmd/state-svc/internal/resolver/resolver.go

@@ -24,9 +24,9 @@ import (
 	"github.com/ActiveState/cli/internal/graph"
 	"github.com/ActiveState/cli/internal/logging"
 	configMediator "github.com/ActiveState/cli/internal/mediators/config"
-	"github.com/ActiveState/cli/internal/multilog"
 	"github.com/ActiveState/cli/internal/poller"
 	"github.com/ActiveState/cli/internal/rtutils/ptr"
+	"github.com/ActiveState/cli/internal/runbits/panics"
 	"github.com/ActiveState/cli/internal/updater"
 	"github.com/ActiveState/cli/pkg/platform/authentication"
 	"github.com/ActiveState/cli/pkg/projectfile"
@@ -57,6 +57,9 @@ func New(cfg *config.Instance, an *sync.Client, auth *authentication.Auth) (*Res
 
 	upchecker := updater.NewDefaultChecker(cfg, an)
 	pollUpdate := poller.New(1*time.Hour, func() (interface{}, error) {
+		defer func() {
+			panics.LogAndPanic(recover(), debug.Stack())
+		}()
 		logging.Debug("Poller checking for update info")
 		return upchecker.CheckFor(constants.ChannelName, "")
 	})
@@ -71,6 +74,9 @@ func New(cfg *config.Instance, an *sync.Client, auth *authentication.Auth) (*Res
 	}
 
 	pollAuth := poller.New(time.Duration(int64(time.Millisecond)*pollRate), func() (interface{}, error) {
+		defer func() {
+			panics.LogAndPanic(recover(), debug.Stack())
+		}()
 		if auth.SyncRequired() {
 			return nil, auth.Sync()
 		}
@@ -110,7 +116,7 @@ func (r *Resolver) Query() genserver.QueryResolver { return r }
 func (r *Resolver) Mutation() genserver.MutationResolver { return r }
 
 func (r *Resolver) Version(ctx context.Context) (*graph.Version, error) {
-	defer func() { handlePanics(recover(), debug.Stack()) }()
+	defer func() { panics.LogAndPanic(recover(), debug.Stack()) }()
 
 	r.an.EventWithLabel(anaConsts.CatStateSvc, "endpoint", "Version")
 	logging.Debug("Version resolver")
@@ -126,7 +132,7 @@ func (r *Resolver) Version(ctx context.Context) (*graph.Version, error) {
 }
 
 func (r *Resolver) AvailableUpdate(ctx context.Context, desiredChannel, desiredVersion string) (*graph.AvailableUpdate, error) {
-	defer func() { handlePanics(recover(), debug.Stack()) }()
+	defer func() { panics.LogAndPanic(recover(), debug.Stack()) }()
 
 	if desiredChannel == "" {
 		desiredChannel = constants.ChannelName
@@ -174,7 +180,7 @@ func (r *Resolver) AvailableUpdate(ctx context.Context, desiredChannel, desiredV
 }
 
 func (r *Resolver) Projects(ctx context.Context) ([]*graph.Project, error) {
-	defer func() { handlePanics(recover(), debug.Stack()) }()
+	defer func() { panics.LogAndPanic(recover(), debug.Stack()) }()
 
 	r.an.EventWithLabel(anaConsts.CatStateSvc, "endpoint", "Projects")
 	logging.Debug("Projects resolver")
@@ -194,7 +200,7 @@ func (r *Resolver) Projects(ctx context.Context) ([]*graph.Project, error) {
 }
 
 func (r *Resolver) AnalyticsEvent(_ context.Context, category, action, source string, _label *string, dimensionsJson string) (*graph.AnalyticsEventResponse, error) {
-	defer func() { handlePanics(recover(), debug.Stack()) }()
+	defer func() { panics.LogAndPanic(recover(), debug.Stack()) }()
 
 	logging.Debug("Analytics event resolver: %s - %s: %s (%s)", category, action, ptr.From(_label, "NIL"), source)
 
@@ -228,7 +234,7 @@ func (r *Resolver) AnalyticsEvent(_ context.Context, category, action, source st
 }
 
 func (r *Resolver) ReportRuntimeUsage(_ context.Context, pid int, exec, source string, dimensionsJSON string) (*graph.ReportRuntimeUsageResponse, error) {
-	defer func() { handlePanics(recover(), debug.Stack()) }()
+	defer func() { panics.LogAndPanic(recover(), debug.Stack()) }()
 
 	logging.Debug("Runtime usage resolver: %d - %s", pid, exec)
 	var dims *dimensions.Values
@@ -242,26 +248,26 @@ func (r *Resolver) ReportRuntimeUsage(_ context.Context, pid int, exec, source s
 }
 
 func (r *Resolver) CheckMessages(ctx context.Context, command string, flags []string) ([]*graph.MessageInfo, error) {
-	defer func() { handlePanics(recover(), debug.Stack()) }()
+	defer func() { panics.LogAndPanic(recover(), debug.Stack()) }()
 	logging.Debug("Check messages resolver")
 	return r.messages.Check(command, flags)
 }
 
 func (r *Resolver) ConfigChanged(ctx context.Context, key string) (*graph.ConfigChangedResponse, error) {
-	defer func() { handlePanics(recover(), debug.Stack()) }()
+	defer func() { panics.LogAndPanic(recover(), debug.Stack()) }()
 
 	go configMediator.NotifyListeners(key)
 	return &graph.ConfigChangedResponse{Received: true}, nil
 }
 
 func (r *Resolver) FetchLogTail(ctx context.Context) (string, error) {
-	defer func() { handlePanics(recover(), debug.Stack()) }()
+	defer func() { panics.LogAndPanic(recover(), debug.Stack()) }()
 
 	return logging.ReadTail(), nil
 }
 
 func (r *Resolver) GetProcessesInUse(ctx context.Context, execDir string) ([]*graph.ProcessInfo, error) {
-	defer func() { handlePanics(recover(), debug.Stack()) }()
+	defer func() { panics.LogAndPanic(recover(), debug.Stack()) }()
 
 	inUse := r.rtwatch.GetProcessesInUse(execDir)
 	processes := make([]*graph.ProcessInfo, 0, len(inUse))
@@ -272,7 +278,7 @@ func (r *Resolver) GetProcessesInUse(ctx context.Context, execDir string) ([]*gr
 }
 
 func (r *Resolver) GetJwt(ctx context.Context) (*graph.Jwt, error) {
-	defer func() { handlePanics(recover(), debug.Stack()) }()
+	defer func() { panics.LogAndPanic(recover(), debug.Stack()) }()
 
 	if err := r.auth.MaybeRenew(); err != nil {
 		return nil, errs.Wrap(err, "Could not renew auth token")
@@ -308,7 +314,7 @@ func (r *Resolver) GetJwt(ctx context.Context) (*graph.Jwt, error) {
 }
 
 func (r *Resolver) HashGlobs(ctx context.Context, wd string, globs []string) (*graph.GlobResult, error) {
-	defer func() { handlePanics(recover(), debug.Stack()) }()
+	defer func() { panics.LogAndPanic(recover(), debug.Stack()) }()
 
 	hash, files, err := r.fileHasher.HashFiles(wd, globs)
 	if err != nil {
@@ -341,11 +347,3 @@ func (r *Resolver) SetCache(ctx context.Context, key string, value string, expir
 	r.globalCache.Set(key, value, time.Duration(expiry)*time.Second)
 	return &graphqltypes.Void{}, nil
 }
-
-func handlePanics(recovered interface{}, stack []byte) {
-	if recovered != nil {
-		multilog.Error("Panic: %v", recovered)
-		logging.Debug("Stack: %s", string(stack))
-		panic(recovered) // We're only logging the panic, not interrupting it
-	}
-}

internal/runbits/panics/panics.go

@@ -34,3 +34,12 @@ func LogPanics(recovered interface{}, stack []byte) bool {
 	}
 	return false
 }
+
+// LogAndPanic produces actionable output for panic events (that shouldn't happen) and panics
+func LogAndPanic(recovered interface{}, stack []byte) {
+	if recovered != nil {
+		multilog.Error("Panic: %v", recovered)
+		logging.Debug("Stack: %s", string(stack))
+		panic(recovered) // We're only logging the panic, not interrupting it
+	}
+}