From f548d67748d067d351fdc42d4aa26b640c164bf3 Mon Sep 17 00:00:00 2001 From: Sachin Holla <51310506+sachinholla@users.noreply.github.com> Date: Wed, 4 Nov 2020 00:12:27 +0530 Subject: [PATCH] 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": , "description": , "message": , "table-name": , "table-keys": , "field-name": , "field-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 | 3 +++ rest/server/error.go | 23 +++++++++++++++++++++++ rest/server/handler.go | 8 ++++---- rest/server/handler_test.go | 9 +++++++++ rest/server/pamAuth.go | 4 ++-- rest/server/req_validate.go | 6 +++--- rest/server/router.go | 16 ++++++++++++++++ 7 files changed, 60 insertions(+), 9 deletions(-) diff --git a/go.sum b/go.sum index 9cd8b44a45..72fe87a944 100644 --- a/go.sum +++ b/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= diff --git a/rest/server/error.go b/rest/server/error.go index 0c5072abd3..dccecde0e2 100644 --- a/rest/server/error.go +++ b/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 diff --git a/rest/server/handler.go b/rest/server/handler.go index b94ac04c23..d318cbdacc 100644 --- a/rest/server/handler.go +++ b/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,7 +141,7 @@ 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") } @@ -149,7 +149,7 @@ func getRequestBody(r *http.Request, rc *RequestContext) (*MediaType, []byte, er // 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") } diff --git a/rest/server/handler_test.go b/rest/server/handler_test.go index 7bec94a12e..c29c150cbb 100644 --- a/rest/server/handler_test.go +++ b/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", "")) diff --git a/rest/server/pamAuth.go b/rest/server/pamAuth.go index d2554d83ae..0a35877dcf 100644 --- a/rest/server/pamAuth.go +++ b/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") } diff --git a/rest/server/req_validate.go b/rest/server/req_validate.go index 4571d8a100..5ab9feac8c 100644 --- a/rest/server/req_validate.go +++ b/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") } diff --git a/rest/server/router.go b/rest/server/router.go index 77263e2b9a..b4c44363b9 100644 --- a/rest/server/router.go +++ b/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 {