Wfexec logging tweaks, add debug wf step kind

automation/service/workflow.go

@@ -521,6 +521,8 @@ func (svc *workflow) workflowStepDefConv(g *wfexec.Graph, s *types.WorkflowStep,
 		switch s.Kind {
 		case types.WorkflowStepKindVisual:
 			return nil, nil
+		case types.WorkflowStepKindDebug:
+			return svc.convDebugStep(s)
 
 		case types.WorkflowStepKindExpressions:
 			return svc.convExpressionStep(s)
@@ -659,6 +661,15 @@ func (svc *workflow) convExpressionStep(s *types.WorkflowStep) (wfexec.Step, err
 	return types.ExpressionsStep(s.Arguments...), nil
 }
 
+// internal debug step that can log entire
+func (svc *workflow) convDebugStep(s *types.WorkflowStep) (wfexec.Step, error) {
+	if err := svc.parseExpressions(s.Arguments...); err != nil {
+		return nil, err
+	}
+
+	return types.DebugStep(svc.log), nil
+}
+
 func (svc *workflow) convFunctionStep(g *wfexec.Graph, s *types.WorkflowStep, out []*types.WorkflowPath) (wfexec.Step, error) {
 	if s.Ref == "" {
 		return nil, errors.Internal("function reference missing")
@@ -798,6 +809,9 @@ func validateSteps(ss ...*types.WorkflowStep) error {
 		switch s.Kind {
 		case types.WorkflowStepKindErrHandler:
 
+		case types.WorkflowStepKindDebug:
+			checks = append(checks, noResults)
+
 		case types.WorkflowStepKindVisual:
 			checks = append(checks, noArgs, noResults)
 

automation/types/debug.go

@@ -0,0 +1,53 @@
+package types
+
+import (
+	"context"
+	"github.com/cortezaproject/corteza-server/pkg/expr"
+	"github.com/cortezaproject/corteza-server/pkg/wfexec"
+	"go.uber.org/zap"
+)
+
+type (
+	debugStep struct {
+		identifiableStep
+		log *zap.Logger
+	}
+)
+
+// DebugStep creates a step that logs entire contents of the scope
+func DebugStep(log *zap.Logger) *debugStep {
+	return &debugStep{
+		log: log,
+	}
+}
+
+// Executes debug step
+func (s *debugStep) Exec(ctx context.Context, r *wfexec.ExecRequest) (wfexec.ExecResponse, error) {
+	var (
+		fields = make([]zap.Field, 0)
+
+		// We want to be sure to actually get the logger that will print out debug info
+		// so we need to use logger directly from workflow and not the one we (could)
+		// get from context by wfexec.
+		log = s.log.With(
+			zap.Uint64("sessionID", r.SessionID),
+			zap.Uint64("stateID", r.StateID),
+			zap.Uint64("stepID", s.ID()),
+		)
+	)
+
+	if r.Scope == nil {
+		fields = append(fields, zap.Int("scopeKeyCount", 0))
+	} else {
+		fields = append(fields, zap.Int("scopeKeyCount", r.Scope.Len()))
+		_ = r.Scope.Each(func(k string, v expr.TypedValue) error {
+			fields = append(fields, zap.Any(k, v.Get()))
+			fields = append(fields, zap.Any(k+"Type", v.Type()))
+			return nil
+		})
+	}
+
+	log.Debug("debug", fields...)
+
+	return &expr.Vars{}, nil
+}

automation/types/workflow.go

@@ -124,6 +124,7 @@ const (
 	WorkflowStepKindPrompt      WorkflowStepKind = "prompt"        // ref = <client function>
 	WorkflowStepKindErrHandler  WorkflowStepKind = "error-handler" // no ref
 	WorkflowStepKindVisual      WorkflowStepKind = "visual"        // ref = <*>
+	WorkflowStepKindDebug       WorkflowStepKind = "debug"         // ref = <*>
 	//WorkflowStepKindSubprocess  WorkflowStepKind = "subprocess"
 	//WorkflowStepKindEvent       WorkflowStepKind = "event" // ref = ??
 )

pkg/wfexec/session.go

@@ -155,7 +155,7 @@ func NewSession(ctx context.Context, g *Graph, oo ...sessionOpt) *Session {
 
 	s.log = s.log.
 		WithOptions(zap.AddStacktrace(zap.ErrorLevel)).
-		With(zap.Uint64("sessionId", s.id))
+		With(zap.Uint64("sessionID", s.id))
 
 	go s.worker(ctx)
 
@@ -317,7 +317,7 @@ func (s *Session) worker(ctx context.Context) {
 				break
 			}
 
-			s.log.Debug("pulled state from queue", zap.Uint64("stateId", st.stateId))
+			s.log.Debug("pulled state from queue", zap.Uint64("stateID", st.stateId))
 			if st.step == nil {
 				s.log.Debug("done, stopping and setting results")
 				defer s.mux.Unlock()
@@ -340,7 +340,7 @@ func (s *Session) worker(ctx context.Context) {
 				<-s.execLock
 
 				status := s.Status()
-				s.log.Debug("executed", zap.Uint64("stateId", st.stateId), zap.Int("status", status))
+				s.log.Debug("executed", zap.Uint64("stateID", st.stateId), zap.Int("status", status))
 				// after exec lock is released call event handler with (new) session status
 				s.eventHandler(status, st, s)
 			}()
@@ -385,7 +385,7 @@ func (s *Session) queueScheduledSuspended() {
 		}
 
 		delete(s.suspended, id)
-		s.log.Debug("resuming suspended state", zap.Uint64("stateId", sus.state.stateId))
+		s.log.Debug("resuming suspended state", zap.Uint64("stateID", sus.state.stateId))
 		s.qState <- sus.state
 	}
 }
@@ -399,11 +399,11 @@ func (s *Session) exec(ctx context.Context, st *State) {
 
 		currLoop = st.loopCurr()
 
-		log = s.log.With(zap.Uint64("stateId", st.stateId))
+		log = s.log.With(zap.Uint64("stateID", st.stateId))
 	)
 
 	if st.step != nil {
-		log = log.With(zap.Uint64("step", st.step.ID()))
+		log = log.With(zap.Uint64("stepID", st.step.ID()))
 	}
 
 	// @todo enable this when not in debug mode