feat: Better error reporting for sinks

interpreter/func_provider.go

@@ -494,12 +494,24 @@ Run executes this function.
 */
 func (rf *sinkerror) Run(instanceID string, vs parser.Scope, is map[string]interface{}, args []interface{}) (interface{}, error) {
 	var msg string
+	var detail interface{}
 
 	if len(args) > 0 {
-		msg = fmt.Sprint(args...)
+		msg = fmt.Sprint(args[0])
+		if len(args) > 1 {
+			detail = args[1]
+		}
+	}
+
+	erp := is["erp"].(*ECALRuntimeProvider)
+	node := is["astnode"].(*parser.ASTNode)
+
+	return nil, &SinkRuntimeError{
+		erp.NewRuntimeError(util.ErrSink, msg, node).(*util.RuntimeError),
+		nil,
+		detail,
 	}
 
-	return nil, &sinkError{msg}
 }
 
 /*
@@ -627,7 +639,16 @@ func (rf *addeventandwait) Run(instanceID string, vs parser.Scope, is map[string
 
 				errors := map[interface{}]interface{}{}
 				for k, v := range e.ErrorMap {
-					errors[k] = v.Error()
+					se := v.(*SinkRuntimeError)
+
+					// Note: The variable scope of the sink (se.environment)
+					// was also captured - for now it is not exposed to the
+					// language environment
+
+					errors[k] = map[interface{}]interface{}{
+						"message": se.Error(),
+						"detail":  se.detail,
+					}
 				}
 
 				item := map[interface{}]interface{}{

interpreter/provider.go

@@ -12,6 +12,7 @@
 // Event function: event
 // Context supporting final
 // Event handling
+// Inline escaping in strings "bla {1+1} bla"
 
 package interpreter
 

interpreter/rt_identifier.go

@@ -14,6 +14,7 @@ import (
 	"fmt"
 	"strings"
 
+	"devt.de/krotik/common/stringutil"
 	"devt.de/krotik/ecal/parser"
 	"devt.de/krotik/ecal/scope"
 	"devt.de/krotik/ecal/stdlib"
@@ -125,7 +126,8 @@ resolveFunction execute function calls and return the result.
 func (rt *identifierRuntime) resolveFunction(astring string, vs parser.Scope, is map[string]interface{},
 	node *parser.ASTNode, result interface{}, err error) (interface{}, error) {
 
-	is["erp"] = rt.erp // All functions have access to the ECAL Runtime Provider
+	is["erp"] = rt.erp      // All functions have access to the ECAL Runtime Provider
+	is["astnode"] = rt.node // ... and the AST node
 
 	for _, funccall := range node.Children {
 
@@ -169,19 +171,34 @@ func (rt *identifierRuntime) resolveFunction(astring string, vs parser.Scope, is
 
 				if err == nil {
 
-					if astring == "log" {
-						rt.erp.Logger.LogInfo(args...)
-					} else if astring == "error" {
-						rt.erp.Logger.LogError(args...)
-					} else if astring == "debug" {
-						rt.erp.Logger.LogDebug(args...)
+					if astring == "log" || astring == "error" || astring == "debug" {
+
+						// Convert non-string structures
+
+						for i, a := range args {
+							if _, ok := args[i].(string); !ok {
+								args[i] = stringutil.ConvertToPrettyString(a)
+							}
+						}
+
+						if astring == "log" {
+							rt.erp.Logger.LogInfo(args...)
+						} else if astring == "error" {
+							rt.erp.Logger.LogError(args...)
+						} else if astring == "debug" {
+							rt.erp.Logger.LogDebug(args...)
+						}
+
 					} else {
 
 						// Execute the function and
 
 						result, err = funcObj.Run(rt.instanceID, vs, is, args)
 
-						if _, ok := err.(*util.RuntimeError); err != nil && !ok {
+						_, ok1 := err.(*util.RuntimeError)
+						_, ok2 := err.(*SinkRuntimeError)
+
+						if err != nil && !ok1 && !ok2 {
 
 							// Convert into a proper runtime error if necessary
 

interpreter/rt_sink.go

@@ -200,11 +200,20 @@ func (rt *sinkRuntime) Eval(vs parser.Scope, is map[string]interface{}) (interfa
 				if err == nil {
 					scope.SetParentOfScope(sinkVS, vs)
 
-					_, err = statements.Runtime.Eval(sinkVS, sinkIs)
+					if _, err = statements.Runtime.Eval(sinkVS, sinkIs); err != nil {
 
-					if err != nil {
-						if _, ok := err.(*sinkError); !ok {
-							err = fmt.Errorf("%v\nEnvironment:\n%v", err.Error(), sinkVS.String())
+						if sre, ok := err.(*SinkRuntimeError); ok {
+							sre.environment = sinkVS
+
+						} else {
+
+							// Provide additional information for unexpected errors
+
+							err = &SinkRuntimeError{
+								err.(*util.RuntimeError),
+								sinkVS,
+								nil,
+							}
 						}
 					}
 				}
@@ -222,17 +231,12 @@ func (rt *sinkRuntime) Eval(vs parser.Scope, is map[string]interface{}) (interfa
 }
 
 /*
-sinkError is a special error which indicates that a sink has failed.
-*/
-type sinkError struct {
-	msg string
-}
-
-/*
-Eval evaluate this runtime component.
+SinkRuntimeError is a sink specific error with additional environment information.
 */
-func (se *sinkError) Error() string {
-	return se.msg
+type SinkRuntimeError struct {
+	*util.RuntimeError
+	environment parser.Scope
+	detail      interface{}
 }
 
 // Sink child nodes

interpreter/rt_sink_test.go

@@ -84,13 +84,15 @@ GlobalScope {
 		return
 	}
 
+	// Test case 1 - Multiple rules, scope match, priorities and waiting for finish (no errors)
+
 	_, err = UnitTestEval(
 		`
 sink rule1
     kindmatch [ "web.page.index" ],
 	scopematch [ "request.read" ],
 	{
-        log("rule1 > Handling request: ", event.kind)
+        log("rule1 - Handling request: ", event.kind)
         addEvent("Rule1Event1", "not_existing", event.state)
         addEvent("Rule1Event2", "web.log", event.state)
 	}
@@ -99,13 +101,16 @@ sink rule2
     kindmatch [ "web.page.*" ],
     priority 1,  # Ensure this rule is always executed after rule1
 	{
-        log("rule2 > Tracking user:", event.state.user)
+        log("rule2 - Tracking user:", event.state.user)
+        if event.state.user == "bar" {
+            sinkError("User bar was here", [123])
+        }
 	}
 
 sink rule3
     kindmatch [ "web.log" ],
 	{
-        log("rule3 > Logging user:", event.state.user)
+        log("rule3 - Logging user:", event.state.user)
 	}
 
 res := addEventAndWait("request", "web.page.index", {
@@ -113,7 +118,56 @@ res := addEventAndWait("request", "web.page.index", {
 }, {
 	"request.read" : true
 })
-log("ErrorResult:", res, len(res) == 0)
+
+log("ErrorResult:", res, " ", len(res) == 0)
+
+res := addEventAndWait("request", "web.page.index", {
+	"user" : "bar"
+}, {
+	"request.read" : false
+})
+log("ErrorResult:", res[0].errors, " ", res == null)
+`, vs)
+
+	if err != nil {
+		t.Error(err)
+		return
+	}
+
+	if testlogger.String() != `
+rule1 - Handling request: web.page.index
+rule2 - Tracking user:foo
+rule3 - Logging user:foo
+ErrorResult:null true
+rule2 - Tracking user:bar
+ErrorResult:{
+  "rule2": {
+    "detail": [
+      123
+    ],
+    "message": "ECAL error in ECALTestRuntime: Error in sink (User bar was here) (Line:17 Pos:13)"
+  }
+} false`[1:] {
+		t.Error("Unexpected result:", testlogger.String())
+		return
+	}
+
+	// Test case 2 - unexpected error
+
+	_, err = UnitTestEval(
+		`
+sink rule1
+    kindmatch [ "test" ],
+    {
+        log("rule1 - ", event.kind)
+        noexitingfunctioncall()
+    }
+
+err := addEventAndWait("someevent", "test", {})
+
+if err != null {
+    error(err[0].errors)
+}
 `, vs)
 
 	if err != nil {
@@ -122,10 +176,13 @@ log("ErrorResult:", res, len(res) == 0)
 	}
 
 	if testlogger.String() != `
-rule1 > Handling request: web.page.index
-rule2 > Tracking user:foo
-rule3 > Logging user:foo
-ErrorResult:[] true`[1:] {
+rule1 - test
+error: {
+  "rule1": {
+    "detail": null,
+    "message": "ECAL error in ECALTestRuntime: Unknown construct (Unknown function: noexitingfunctioncall) (Line:6 Pos:9)"
+  }
+}`[1:] {
 		t.Error("Unexpected result:", testlogger.String())
 		return
 	}

util/error.go

@@ -46,6 +46,7 @@ var (
 	ErrNotAList         = errors.New("Operand is not a list")
 	ErrNotAMap          = errors.New("Operand is not a map")
 	ErrNotAListOrMap    = errors.New("Operand is not a list nor a map")
+	ErrSink             = errors.New("Error in sink")
 
 	// ErrReturn is not an error. It is used to return when executing a function
 	ErrReturn = errors.New("*** return ***")