Skip to content

Add more information to the error message log #236

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
glower wants to merge 2 commits into
base: master
Choose a base branch
from
Open

Add more information to the error message log #236

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
369693b
Add more information to the error message in the internal logs and fo…
Jun 13, 2019
592ef7e
Added some missing tests
Jun 13, 2019
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
6 changes: 6 additions & 0 deletions datastore/mock_database.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -154,6 +154,9 @@ func (mdb *MockDB) SyncAccount(account Account) error {
// FindModel mocks the database response for finding a model
func (mdb *MockDB) FindModel(brandID, modelName, apiKey string) (Model, error) {
model := Model{ID: 1, BrandID: "system", Name: "alder", KeypairID: 1, AuthorityID: "system", KeyID: "UytTqTvREVhx0tSfYC6KkFHmLWllIIZbQ3NsEG7OARrWuaXSRJyey0vjIQkTEvMO", KeyActive: true, SealedKey: ""}
if modelName == "lost" {
model = Model{ID: 999, BrandID: "system", Name: "lost", KeypairID: 1, AuthorityID: "system", KeyID: "UytTqTvREVhx0tSfYC6KkFHmLWllIIZbQ3NsEG7OARrWuaXSRJyey0vjIQkTEvMO", KeyActive: true, SealedKey: ""}
}
if modelName == "ash" {
model = Model{ID: 2, BrandID: "system", Name: "ash", KeypairID: 1, AuthorityID: "system", KeyID: "UytTqTvREVhx0tSfYC6KkFHmLWllIIZbQ3NsEG7OARrWuaXSRJyey0vjIQkTEvMO", KeyActive: true, SealedKey: ""}
}
Expand Down Expand Up @@ -725,6 +728,9 @@ func (mdb *MockDB) UpdateModelAssert(m ModelAssertion) error {

// GetModelAssert mock for updating model assertion record
func (mdb *MockDB) GetModelAssert(modelID int) (ModelAssertion, error) {
if modelID == 999 {
return ModelAssertion{}, errors.New("Cannot find the model assertion record")
}
if modelID == 2 {
return ModelAssertion{
ID: 1,
Expand Down
3 changes: 1 addition & 2 deletions service/assertion/actions.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -46,8 +46,7 @@ func modelAssertionHandler(w http.ResponseWriter, apiKey string, request ModelAs
// Validate the model by checking that it exists on the database
model, err := datastore.Environ.DB.FindModel(request.BrandID, request.Name, apiKey)
if err != nil {
log.Message("MODEL", response.ErrorInvalidModel.Code, response.ErrorInvalidModel.Message)
return response.ErrorInvalidModel
return response.ErrorInvalidModel("MODEL", request.Name, request.BrandID, apiKey)
}

assertions := []asserts.Assertion{}
Expand Down
4 changes: 2 additions & 2 deletions service/assertion/actions_user.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -52,8 +52,8 @@ func systemUserAssertionAction(w http.ResponseWriter, authUser datastore.User, a
model, err := datastore.Environ.DB.GetAllowedModel(user.ModelID, datastore.User{})
if err != nil {
log.Println(err)
svlog.Message("USER", response.ErrorInvalidModelID.Code, response.ErrorInvalidModelID.Message)
response.FormatStandardResponse(false, response.ErrorInvalidModelID.Code, "", response.ErrorInvalidModelID.Message, w)
resp := response.ErrorInvalidModelID("USER", user.ModelID)
response.FormatErrorResponse(resp, w)
return
}

Expand Down
10 changes: 10 additions & 0 deletions service/assertion/handlers_api_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -83,6 +83,7 @@ func (s *AssertionSuite) TestAssertionHandler(c *check.C) {
{invalidModel(), 400, response.JSONHeader, "ValidAPIKey"},
{unauthBrand(), 400, response.JSONHeader, "ValidAPIKey"},
{unknownBrand(), 400, response.JSONHeader, "ValidAPIKey"},
{unknownModel(), 400, response.JSONHeader, "ValidAPIKey"},
}

for _, t := range tests {
Expand Down Expand Up @@ -146,6 +147,15 @@ func unknownBrand() []byte {
return d
}

func unknownModel() []byte {
a := assertion.ModelAssertionRequest{
BrandID: "system",
Name: "lost",
}
d, _ := json.Marshal(a)
return d
}

func classicModel() []byte {
a := assertion.ModelAssertionRequest{
BrandID: "system",
Expand Down
16 changes: 16 additions & 0 deletions service/assertion/handlers_user_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -46,6 +46,7 @@ func (s *AssertionSuite) TestSystemUserAssertionHandler(c *check.C) {
{generateSystemUserRequestInactiveModel(), 400, false},
{generateSystemUserRequestInvalidAssertion(), 400, false},
{generateSystemUserRequestInvalidSince(), 200, true},
{generateSystemUserRequestEmptyCredentials(), 400, false},
}

for _, test := range tests {
Expand Down Expand Up @@ -103,3 +104,18 @@ func generateSystemUserRequestInvalidAssertion() string {

return string(req)
}

func generateSystemUserRequestEmptyCredentials() string {
request := assertion.SystemUserRequest{
Email: "test@example.com",
Name: "John Doe",
Username: "jdoe",
Password: "",
ModelID: 1,
Since: "2017-03-24T12:34:00Z",
SSHKeys: []string{},
}
req, _ := json.Marshal(request)

return string(req)
}
3 changes: 1 addition & 2 deletions service/pivot/handlers_pivot.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -205,8 +205,7 @@ func findModelPivot(brand, modelName, serial, apiKey string) (datastore.Substore
// Validate the model by checking that it exists on the database
model, err := datastore.Environ.DB.FindModel(brand, modelName, apiKey)
if err != nil {
svlog.Message("PIVOT", "invalid-model", "Cannot find model with the matching brand and model")
return datastore.Substore{}, response.ErrorInvalidModel
return datastore.Substore{}, response.ErrorInvalidModel("PIVOT", modelName, brand, apiKey)
}

// Check for a sub-store model for the pivot
Expand Down
33 changes: 29 additions & 4 deletions service/response/errors.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -20,7 +20,12 @@

package response

import "net/http"
import (
"fmt"
"net/http"

svlog "github.com/CanonicalLtd/serial-vault/service/log"
)

// ErrorResponse is a generic JSON error response structure from an API method
type ErrorResponse struct {
Expand All @@ -44,9 +49,6 @@ var (
ErrorInvalidType = ErrorResponse{false, "invalid-type", "", "The assertion type must be 'serial'", http.StatusBadRequest}
ErrorInvalidSecondType = ErrorResponse{false, "invalid-second-type", "", "The 2nd assertion type must be 'model'", http.StatusBadRequest}
ErrorInvalidNonce = ErrorResponse{false, "invalid-nonce", "", "Nonce is invalid or expired", http.StatusBadRequest}
ErrorInvalidModel = ErrorResponse{false, "invalid-model", "", "Cannot find model with the matching brand and model", http.StatusBadRequest}
ErrorInvalidModelID = ErrorResponse{false, "invalid-model", "", "Cannot find model with the selected ID", http.StatusBadRequest}
ErrorInvalidModelSubstore = ErrorResponse{false, "invalid-model", "", "Cannot find a matching model or sub-store model", http.StatusBadRequest}
ErrorInvalidSubstore = ErrorResponse{false, "invalid-substore", "", "Cannot find sub-store mapping for the model", http.StatusBadRequest}
ErrorInactiveModel = ErrorResponse{false, "invalid-model", "", "The model is linked with an inactive signing-key", http.StatusBadRequest}
ErrorInvalidAccount = ErrorResponse{false, "invalid-account", "", "The account cannot be found", http.StatusBadRequest}
Expand All @@ -66,3 +68,26 @@ var (
ErrorSignAssertion = ErrorResponse{false, "signing-assertion", "", "Error signing the assertion", http.StatusBadRequest}
ErrorGenerateNonce = ErrorResponse{false, "generate-nonce", "", "Error generating a nonce. Please try again later", http.StatusBadRequest}
)

// ErrorInvalidModel returns error message about wrong model
func ErrorInvalidModel(from, modelName, brand, apiKey string) ErrorResponse {
msg := fmt.Sprintf("Cannot find model %s with the matching brand %s and apiKey %s", modelName, brand, apiKey)
svlog.Message(from, "invalid-model", msg)
return ErrorResponse{false, "invalid-model", "", msg, http.StatusBadRequest}
}

// ErrorInvalidModelID returns InvalidModelID error message
func ErrorInvalidModelID(from string, ModelID int) ErrorResponse {
msg := fmt.Sprintf("Cannot find model with the selected ID %d", ModelID)
svlog.Message(from, "invalid-model", msg)

return ErrorResponse{false, "invalid-model", "", msg, http.StatusBadRequest}
}

// ErrorInvalidModelSubstore returns invalid model substore error
func ErrorInvalidModelSubstore(from, brandID, modelName, apiKey, serialNumer string) ErrorResponse {
msg := fmt.Sprintf("Cannot find a matching model or sub-store model %s with the matching brand %s apiKey %s and serialNumer %s",
modelName, brandID, apiKey, serialNumer)
svlog.Message(from, "invalid-model", msg)
return ErrorResponse{false, "invalid-model", "", msg, http.StatusBadRequest}
}
15 changes: 14 additions & 1 deletion service/response/response.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -48,7 +48,20 @@ func FormatStandardResponse(success bool, errorCode, errorSubcode, message strin

// Encode the response as JSON
if err := json.NewEncoder(w).Encode(response); err != nil {
log.Printf("Error forming the boolean response (%v)\n. %v", response, err)
log.Printf("Error forming the standard response (%v)\n. %v", response, err)
return err
}
return nil
}

// FormatErrorResponse returns a JSON response from an API method, indicating failure.
func FormatErrorResponse(response ErrorResponse, w http.ResponseWriter) error {
w.Header().Set("Content-Type", "application/json; charset=UTF-8")
w.WriteHeader(response.StatusCode)

// Encode the response as JSON
if err := json.NewEncoder(w).Encode(response); err != nil {
log.Printf("Error forming the error response (%v)\n. %v", response, err)
return err
}
return nil
Expand Down
8 changes: 4 additions & 4 deletions service/sign/handlers_sign.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -346,7 +346,8 @@ func findModel(brandID, modelName, serialNumer, apiKey string) (datastore.Model,
// Validate the model by checking that it exists on the database
model, err := datastore.Environ.DB.FindModel(brandID, modelName, apiKey)
if err != nil {

@pedronis pedronis Jun 14, 2019

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

because of the try FindModel and then otherwise on failure eagerly try GetSubstoreModel it seems - as it was already - this will always produce slightly odd error messages/responses, this isn't new but if the goal is making for more understandable errors for the brand user this might need a larger rethink

@glower glower Jun 14, 2019

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

OK, I will drop this PR and only put more info inside of the internal log. We can have a separate conversation about error responses.

@pedronis pedronis Jun 14, 2019 •
edited
Loading

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I would ask @cprov whether the change here is already enough of an improvement, he was the one having trouble debugging, before dropping them. For more clarity the issue here is how apiKey is checked implicitly in one case but not the other, I don't know the detail of the data model and other usages enough but in principle it would be better if the apiKey check was explicit/distinguishable unless we think leaking whether a model really exists or not is deemed a problem.

@glower glower Jun 14, 2019

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, I agree on that, but in this case, I just wanted to improve logging, not touching any business logic at all.

svlog.Message("SIGN", response.ErrorInvalidModel.Code, response.ErrorInvalidModel.Message)
msg := fmt.Sprintf("Cannot find model %s with the matching brand %s and apiKey %s", modelName, brandID, apiKey)
svlog.Message("SIGN", "invalid-model", msg)
} else {
// Found the model, so return it
return model, response.ErrorResponse{Success: true}
Expand All @@ -357,12 +358,11 @@ func findModel(brandID, modelName, serialNumer, apiKey string) (datastore.Model,
substore, err := datastore.Environ.DB.GetSubstoreModel(brandID, modelName, serialNumer)
if err != nil {
log.Println(err)
svlog.Message("CHECK", response.ErrorInvalidModelSubstore.Code, response.ErrorInvalidModelSubstore.Message)
return model, response.ErrorInvalidModelSubstore
return model, response.ErrorInvalidModelSubstore("CHECK", brandID, modelName, apiKey, serialNumer)
}

if substore.FromModel.APIKey != apiKey {
return substore.FromModel, response.ErrorInvalidModelSubstore
return substore.FromModel, response.ErrorInvalidModelSubstore("CHECK", brandID, modelName, apiKey, serialNumer)
}

return substore.FromModel, response.ErrorResponse{Success: true}
Expand Down