CVL error response enhancements and panic recovery (#68)

1) If a REST request fails due to cvl error, all non-zero values from
CVLErrorInfo object will be encoded in the "error-info" field of
response data (RFC8040 section 7.1). The "error-info" value will be a
josn object with one field "cvl-error", whose value will be an object
containing data from CVLErrorInfo.

"error-info": {
    "cvl-error": {
        "error-code":   <CVLErrorInfo.Code>,
        "description":  <CVLErrorInfo.CVLErrDetails>,
        "message":      <CVLErrorInfo.Msg>,
        "table-name":   <CVLErrorInfo.TableName>,
        "table-keys":   <CVLErrorInfo.Keys>,
        "field-name":   <CVLErrorInfo.Field>,
        "field-value":  <CVLErrorInfo.Value>,
    }
}
ErrAppTag and ConstraintErrMsg are not included here since they will
be encoded in "error-app-tag" and "error-message" fields of the error
object.

The "error-info" may include other error details in future. Clients
should check for the presence of "cvl-error" field to identify CVL
error.

2) REST server recovers panicking request handlers to return an error
status 500 (internal server error) to the clients. Writes an error log
with "runtime error" prefix, which can be used to redirect such
messages to the device console (requires rsyslog config enhancements).
Previously, the panics would have abruptly closed client connection
without proper logs or messages.

3) Changed REST server to log all client data validation and translib
errors as warnings. They need not be errors in client app's context.
Errors returned by system APIs continue to get logged as error message.
This helps better monitoring and filtering of log messages.

go.sum

@@ -24,6 +24,7 @@ github.com/go-playground/universal-translator v0.17.0 h1:icxd5fm+REJzpZx7ZfpaD87
 github.com/go-playground/universal-translator v0.17.0/go.mod h1:UkSxE5sNxxRwHyU+Scu5vgOQjsIJAF8j9muTVoKLVtA=
 github.com/go-redis/redis v6.15.6+incompatible h1:H9evprGPLI8+ci7fxQx6WNZHJSb7be8FqJQRhdQZ5Sg=
 github.com/go-redis/redis v6.15.6+incompatible/go.mod h1:NAIEuMOZ/fxfXJIrKDQDz8wamY7mA7PouImQ2Jvg6kA=
+github.com/go-redis/redis/v7 v7.0.0-beta.3.0.20190824101152-d19aba07b476 h1:WNSiFp8Ww4ZP7XUzW56zDYv5roKQ4VfsdHCLoh8oDj4=
 github.com/go-redis/redis/v7 v7.0.0-beta.3.0.20190824101152-d19aba07b476/go.mod h1:xhhSbUMTsleRPur+Vgx9sUHtyN33bdjxY+9/0n9Ig8s=
 github.com/golang/glog v0.0.0-20160126235308-23def4e6c14b h1:VKtxabqXZkF25pY9ekfRL6a582T4P37/31XEstQ5p58=
 github.com/golang/glog v0.0.0-20160126235308-23def4e6c14b/go.mod h1:SBH7ygxi8pfUlaOkMMuAQtPIUF8ecWP5IEl/CR7VP2Q=
@@ -73,6 +74,8 @@ github.com/openconfig/ygot v0.6.1-0.20190723223108-724a6b18a922/go.mod h1:o30svN
 github.com/openconfig/ygot v0.7.1 h1:kqDRYQpowXTr7EhGwr2BBDKJzqs+H8aFYjffYQ8lBsw=
 github.com/openconfig/ygot v0.7.1/go.mod h1:5MwNX6DMP1QMf2eQjW+aJN/KNslVqRJtbfSL3SO6Urk=
 github.com/pborman/getopt v0.0.0-20190409184431-ee0cd42419d3/go.mod h1:85jBQOZwpVEaDAr341tbn15RS4fCAsIst0qp7i8ex1o=
+github.com/philopon/go-toposort v0.0.0-20170620085441-9be86dbd762f h1:WyCn68lTiytVSkk7W1K9nBiSGTSRlUOdyTnSjwrIlok=
+github.com/philopon/go-toposort v0.0.0-20170620085441-9be86dbd762f/go.mod h1:/iRjX3DdSK956SzsUdV55J+wIsQ+2IBWmBrB4RvZfk4=
 github.com/pkg/profile v1.4.0 h1:uCmaf4vVbWAOZz36k1hrQD7ijGRzLwaME8Am/7a4jZI=
 github.com/pkg/profile v1.4.0/go.mod h1:NWz/XGvpEW1FyYQ7fCx4dqYBLlfTcE+A9FLAkNKqjFE=
 github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=

rest/server/error.go

@@ -65,6 +65,17 @@ const (
 	errtagMalformedMessage      errtag = "malformed-message"
 )
 
+// cvlErrorData holds error-info data for cvl errors.
+type cvlErrorData struct {
+	Code  int      `json:"error-code,omitempty"`
+	Descr string   `json:"description,omitempty"`
+	Msg   string   `json:"message,omitempty"`
+	Table string   `json:"table-name,omitempty"`
+	Keys  []string `json:"key-values,omitempty"`
+	Field string   `json:"field-name,omitempty"`
+	Value string   `json:"field-value,omitempty"`
+}
+
 // httpErrorType is an error structure for indicating HTTP protocol
 // errors. Includes HTTP status code and user displayable message.
 type httpErrorType struct {
@@ -158,6 +169,18 @@ func toErrorEntry(err error, r *http.Request) (status int, errInfo errorEntry) {
 		errInfo.Message = e.CVLErrorInfo.ConstraintErrMsg
 		errInfo.AppTag = e.CVLErrorInfo.ErrAppTag
 
+		errInfo.ErrInfo = map[string]interface{}{
+			"cvl-error": cvlErrorData{
+				Code:  e.Code,
+				Descr: e.CVLErrorInfo.CVLErrDetails,
+				Msg:   e.CVLErrorInfo.Msg,
+				Table: e.CVLErrorInfo.TableName,
+				Keys:  e.CVLErrorInfo.Keys,
+				Field: e.CVLErrorInfo.Field,
+				Value: e.CVLErrorInfo.Value,
+			},
+		}
+
 		switch cvl.CVLRetCode(e.Code) {
 		case cvl.CVL_SEMANTIC_KEY_ALREADY_EXIST, cvl.CVL_SEMANTIC_KEY_DUPLICATE:
 			status = http.StatusConflict

rest/server/handler.go

@@ -67,7 +67,7 @@ func Process(w http.ResponseWriter, r *http.Request) {
 
 	status, data, err = invokeTranslib(&args, rc)
 	if err != nil {
-		glog.Errorf("[%s] Translib error %T - %v", reqID, err, err)
+		glog.Warningf("[%s] Translib error %T - %v", reqID, err, err)
 		status, data, rtype = prepareErrorResponse(err, r)
 		goto write_resp
 	}
@@ -81,7 +81,7 @@ func Process(w http.ResponseWriter, r *http.Request) {
 
 	rtype, err = resolveResponseContentType(data, r, rc)
 	if err != nil {
-		glog.Errorf("[%s] Failed to resolve response content-type, err=%v", rc.ID, err)
+		glog.Warningf("[%s] Failed to resolve response content-type, err=%v", rc.ID, err)
 		status, data, rtype = prepareErrorResponse(err, r)
 		goto write_resp
 	}
@@ -141,15 +141,15 @@ func getRequestBody(r *http.Request, rc *RequestContext) (*MediaType, []byte, er
 
 	ct, err := parseMediaType(ctype)
 	if err != nil {
-		glog.Errorf("[%s] Bad content-type '%s'; err=%v",
+		glog.Warningf("[%s] Bad content-type '%s'; err=%v",
 			rc.ID, r.Header.Get("Content-Type"), err)
 		return nil, nil, httpBadRequest("Bad content-type")
 	}
 
 	// Check if content type is one of the acceptable types specified
 	// in "consumes" section in OpenAPI spec.
 	if !rc.Consumes.Contains(ct.Type) {
-		glog.Errorf("[%s] Content-type '%s' not supported. Valid types %v", rc.ID, ct.Type, rc.Consumes)
+		glog.Warningf("[%s] Content-type '%s' not supported. Valid types %v", rc.ID, ct.Type, rc.Consumes)
 		return nil, nil, httpError(http.StatusUnsupportedMediaType, "Unsupported content-type")
 	}
 

rest/server/handler_test.go

@@ -559,6 +559,15 @@ func verifyParseVersion(t *testing.T, r *http.Request, expSuccess bool, expVer t
 	}
 }
 
+func TestPanic(t *testing.T) {
+	s := newEmptyRouter()
+	s.addRoute("panic", "GET", "/panic",
+		func(w http.ResponseWriter, r *http.Request) { panic("testing 123") })
+	w := httptest.NewRecorder()
+	s.ServeHTTP(w, prepareRequest(t, "GET", "/panic", ""))
+	verifyResponse(t, w, 500)
+}
+
 func TestProcessGET(t *testing.T) {
 	w := httptest.NewRecorder()
 	Process(w, prepareRequest(t, "GET", "/api-tests:sample", ""))

rest/server/pamAuth.go

@@ -95,7 +95,7 @@ func PAMAuthenAndAuthor(r *http.Request, rc *RequestContext) error {
 
 	username, passwd, authOK := r.BasicAuth()
 	if authOK == false {
-		glog.Errorf("[%s] User info not present", rc.ID)
+		glog.Warningf("[%s] User info not present", rc.ID)
 		return httpError(http.StatusUnauthorized, "")
 	}
 
@@ -131,7 +131,7 @@ func PAMAuthenAndAuthor(r *http.Request, rc *RequestContext) error {
 
 	//Allow SET request only if user belong to admin group
 	if isWriteOperation(r) && IsAdminGroup(username) == false {
-		glog.Errorf("[%s] Not an admin; cannot allow %s", rc.ID, r.Method)
+		glog.Warningf("[%s] Not an admin; cannot allow %s", rc.ID, r.Method)
 		return httpError(http.StatusForbidden, "Not an admin user")
 	}
 

rest/server/req_validate.go

@@ -53,7 +53,7 @@ func validateRequestJSON(jsn []byte, rc *RequestContext) ([]byte, error) {
 
 	err = json.Unmarshal(jsn, v)
 	if err != nil {
-		glog.Errorf("[%s] json decoding error; %v", rc.ID, err)
+		glog.Warningf("[%s] json decoding error; %v", rc.ID, err)
 		return nil, httpBadRequest("Invalid json")
 	}
 
@@ -75,7 +75,7 @@ func validateRequestJSON(jsn []byte, rc *RequestContext) ([]byte, error) {
 			err = validate.Struct(v)
 		}
 		if err != nil {
-			glog.Errorf("[%s] validation failed: %v", rc.ID, err)
+			glog.Warningf("[%s] validation failed: %v", rc.ID, err)
 			return nil, httpBadRequest("Content not as per schema")
 		}
 	} else {
@@ -86,7 +86,7 @@ func validateRequestJSON(jsn []byte, rc *RequestContext) ([]byte, error) {
 	// extra fields if any..
 	newBody, err := json.Marshal(v)
 	if err != nil {
-		glog.Errorf("[%s] Failed to marshall; %v", rc.ID, err)
+		glog.Warningf("[%s] Failed to marshall; %v", rc.ID, err)
 		return nil, httpServerError("Internal error")
 	}
 

rest/server/router.go

@@ -24,6 +24,7 @@ import (
 	"net/http"
 	"path"
 	"regexp"
+	"runtime"
 	"strings"
 	"time"
 
@@ -61,6 +62,7 @@ type RouterConfig struct {
 // ServeHTTP resolves and invokes the handler for http request r.
 // RESTCONF paths are served from the routeTree; rest from mux router.
 func (router *Router) ServeHTTP(w http.ResponseWriter, r *http.Request) {
+	defer doRecover(w, r)
 	path := cleanPath(r.URL.EscapedPath())
 	r = setContextValue(r, routerObjContextKey, router)
 
@@ -116,6 +118,20 @@ func isServeFromTree(path string) bool {
 	return strings.HasPrefix(path, "/restconf/")
 }
 
+// doRecover recovers from panics, logs Error messages
+// Runtime error is a special keyword used by rsyslogD rules to display message on console
+func doRecover(w http.ResponseWriter, r *http.Request) {
+	if err := recover(); err != nil && err != http.ErrAbortHandler {
+		buf := make([]byte, 64<<10)
+		buf = buf[:runtime.Stack(buf, false)]
+		glog.Errorf("Runtime error: panic serving REST request \"%s %s\", Client addr: %s",
+			r.Method, r.URL.Path, r.RemoteAddr)
+		glog.Errorf("Panic data: %v\n%s", err, buf)
+		retErr := httpError(http.StatusInternalServerError, "unexpected error in server")
+		writeErrorResponse(w, r, retErr)
+	}
+}
+
 // routeMatchInfo holds the matched route information in
 // request context.
 type routeMatchInfo struct {