From e37be3a12a7fce506f0d3f63fb2b9203cc48307a Mon Sep 17 00:00:00 2001 From: Kyle Isom Date: Fri, 17 Jul 2015 15:11:21 -0700 Subject: [PATCH 1/2] Consistent and more thorough logging. This PR makes log entries consistent in their format, and ensures that all the core functions are logged. --- core/core.go | 177 +++++++++++++++++++++++++++++++++++---------------- 1 file changed, 121 insertions(+), 56 deletions(-) diff --git a/core/core.go b/core/core.go index 61063f5..d8bdb34 100644 --- a/core/core.go +++ b/core/core.go @@ -166,7 +166,17 @@ func validateName(name, password string) error { } // Init reads the records from disk from a given path -func Init(path string) (err error) { +func Init(path string) error { + var err error + + defer func() { + if err != nil { + log.Printf("init failed: %v", err) + } else { + log.Printf("init success: path=%s", path) + } + }() + if records, err = passvault.InitFrom(path); err != nil { err = fmt.Errorf("Failed to load password vault %s: %s", path, err) } @@ -174,27 +184,37 @@ func Init(path string) (err error) { cache = keycache.Cache{UserKeys: make(map[string]keycache.ActiveUser)} crypt = cryptor.New(&records, &cache) - return + return err } // Create processes a create request. func Create(jsonIn []byte) ([]byte, error) { var s CreateRequest - if err := json.Unmarshal(jsonIn, &s); err != nil { + var err error + + defer func() { + if err != nil { + log.Printf("create failed: user=%s %v", s.Name, err) + } else { + log.Printf("create success: user=%s", s.Name) + } + }() + + if err = json.Unmarshal(jsonIn, &s); err != nil { return jsonStatusError(err) } if records.NumRecords() != 0 { - return jsonStatusError(errors.New("Vault is already created")) - } - - // Validate the Name and Password as valid - if err := validateName(s.Name, s.Password); err != nil { + err = errors.New("Vault is already created") return jsonStatusError(err) } - if _, err := records.AddNewRecord(s.Name, s.Password, true, passvault.DefaultRecordType); err != nil { - log.Printf("Error adding record for %s: %s\n", s.Name, err) + // Validate the Name and Password as valid + if err = validateName(s.Name, s.Password); err != nil { + return jsonStatusError(err) + } + + if _, err = records.AddNewRecord(s.Name, s.Password, true, passvault.DefaultRecordType); err != nil { return jsonStatusError(err) } @@ -204,18 +224,27 @@ func Create(jsonIn []byte) ([]byte, error) { // Summary processes a summary request. func Summary(jsonIn []byte) ([]byte, error) { var s SummaryRequest + var err error cache.Refresh() + defer func() { + if err != nil { + log.Printf("summary failed: user=%s %v", s.Name, err) + } else { + log.Printf("summary success: user=%s", s.Name) + } + }() + if err := json.Unmarshal(jsonIn, &s); err != nil { return jsonStatusError(err) } if records.NumRecords() == 0 { - return jsonStatusError(errors.New("Vault is not created yet")) + err = errors.New("vault has not been created") + return jsonStatusError(err) } if err := validateUser(s.Name, s.Password, false); err != nil { - log.Printf("failed to validate %s in summary request: %s", s.Name, err) return jsonStatusError(err) } @@ -225,16 +254,27 @@ func Summary(jsonIn []byte) ([]byte, error) { // Delegate processes a delegation request. func Delegate(jsonIn []byte) ([]byte, error) { var s DelegateRequest - if err := json.Unmarshal(jsonIn, &s); err != nil { + var err error + + defer func() { + if err != nil { + log.Printf("delegate failed: user=%s %v", s.Name, err) + } else { + log.Printf("delegate success: user=%s uses=%d time=%s users=%v labels=%v", s.Name, s.Uses, s.Time, s.Users, s.Labels) + } + }() + + if err = json.Unmarshal(jsonIn, &s); err != nil { return jsonStatusError(err) } if records.NumRecords() == 0 { - return jsonStatusError(errors.New("Vault is not created yet")) + errors.New("Vault is not created yet") + return jsonStatusError(err) } // Validate the Name and Password as valid - if err := validateName(s.Name, s.Password); err != nil { + if err = validateName(s.Name, s.Password); err != nil { return jsonStatusError(err) } @@ -243,20 +283,17 @@ func Delegate(jsonIn []byte) ([]byte, error) { pr, found := records.GetRecord(s.Name) if found { - if err := pr.ValidatePassword(s.Password); err != nil { + if err = pr.ValidatePassword(s.Password); err != nil { return jsonStatusError(err) } } else { - var err error if pr, err = records.AddNewRecord(s.Name, s.Password, false, passvault.DefaultRecordType); err != nil { - log.Printf("Error adding record for %s: %s\n", s.Name, err) return jsonStatusError(err) } } // add signed-in record to active set - if err := cache.AddKeyFromRecord(pr, s.Name, s.Password, s.Users, s.Labels, s.Uses, s.Time); err != nil { - log.Printf("Error adding key to cache for %s: %s\n", s.Name, err) + if err = cache.AddKeyFromRecord(pr, s.Name, s.Password, s.Users, s.Labels, s.Uses, s.Time); err != nil { return jsonStatusError(err) } @@ -265,18 +302,29 @@ func Delegate(jsonIn []byte) ([]byte, error) { // Password processes a password change request. func Password(jsonIn []byte) ([]byte, error) { + var err error var s PasswordRequest - if err := json.Unmarshal(jsonIn, &s); err != nil { + + defer func() { + if err != nil { + log.Printf("password failed: user=%s %v", s.Name, err) + } else { + log.Printf("password success: user=%s", s.Name) + } + }() + + if err = json.Unmarshal(jsonIn, &s); err != nil { return jsonStatusError(err) } if records.NumRecords() == 0 { - return jsonStatusError(errors.New("Vault is not created yet")) + err = errors.New("Vault is not created yet") + return jsonStatusError(err) } // add signed-in record to active set - if err := records.ChangePassword(s.Name, s.Password, s.NewPassword); err != nil { - log.Println("Error changing password:", err) + err = records.ChangePassword(s.Name, s.Password, s.NewPassword) + if err != nil { return jsonStatusError(err) } @@ -286,20 +334,21 @@ func Password(jsonIn []byte) ([]byte, error) { // Encrypt processes an encrypt request. func Encrypt(jsonIn []byte) ([]byte, error) { var s EncryptRequest - - err := json.Unmarshal(jsonIn, &s) - if err != nil { - return jsonStatusError(err) - } + var err error defer func() { if err != nil { - log.Printf("encrypt: request for encryption from %s failed: %v", s.Name, err) + log.Printf("encrypt failed: user=%s size=%d %v", s.Name, len(s.Data), err) } else { - log.Printf("encrypt: successful encryption for %s", s.Name) + log.Printf("encrypt success: user=%s size=%d", s.Name, len(s.Data)) } }() + err = json.Unmarshal(jsonIn, &s) + if err != nil { + return jsonStatusError(err) + } + if err = validateUser(s.Name, s.Password, false); err != nil { return jsonStatusError(err) } @@ -313,28 +362,28 @@ func Encrypt(jsonIn []byte) ([]byte, error) { resp, err := crypt.Encrypt(s.Data, s.Labels, access) if err != nil { return jsonStatusError(err) - } else { - return jsonResponse(resp) } + return jsonResponse(resp) } // Decrypt processes a decrypt request. func Decrypt(jsonIn []byte) ([]byte, error) { var s DecryptRequest - err := json.Unmarshal(jsonIn, &s) - if err != nil { - log.Printf("decrypt: failed to unmarshal input: %v", err) - return jsonStatusError(err) - } + var err error defer func() { if err != nil { - log.Printf("decrypt: request for decryption from %s failed: %v", s.Name, err) + log.Printf("decrypt failed: user=%s %v", s.Name, err) } else { - log.Printf("decrypt: successful decryption for %s", s.Name) + log.Printf("decrypt success: user=%s", s.Name) } }() + err = json.Unmarshal(jsonIn, &s) + if err != nil { + return jsonStatusError(err) + } + err = validateUser(s.Name, s.Password, false) if err != nil { return jsonStatusError(err) @@ -362,20 +411,21 @@ func Decrypt(jsonIn []byte) ([]byte, error) { // Modify processes a modify request. func Modify(jsonIn []byte) ([]byte, error) { var s ModifyRequest - - err := json.Unmarshal(jsonIn, &s) - if err != nil { - return jsonStatusError(err) - } + var err error defer func() { if err != nil { - log.Printf("modify: attempt to modify %s by %s fail: %v", s.ToModify, s.Name, err) + log.Printf("modify failed: user=%s target=%s command=%s %v", s.Name, s.ToModify, s.Command, err) } else { - log.Printf("modify: attempt to modify %s by %s succeeded", s.ToModify, s.Name) + log.Printf("modify success: user=%s target=%s command=%s", s.Name, s.ToModify, s.Command) } }() + err = json.Unmarshal(jsonIn, &s) + if err != nil { + return jsonStatusError(err) + } + if err = validateUser(s.Name, s.Password, true); err != nil { return jsonStatusError(err) } @@ -412,15 +462,23 @@ func Modify(jsonIn []byte) ([]byte, error) { // Owners processes a owners request. func Owners(jsonIn []byte) ([]byte, error) { var s OwnersRequest - err := json.Unmarshal(jsonIn, &s) + var err error + + defer func() { + if err != nil { + log.Printf("owners failed: size=%d %v", len(s.Data), err) + } else { + log.Printf("owners success: size=%d", len(s.Data)) + } + }() + + err = json.Unmarshal(jsonIn, &s) if err != nil { - log.Println("Error unmarshaling input:", err) return jsonStatusError(err) } names, err := crypt.GetOwners(s.Data) if err != nil { - log.Println("Error listing owners:", err) return jsonStatusError(err) } @@ -429,22 +487,29 @@ func Owners(jsonIn []byte) ([]byte, error) { // Export returns a backed up vault. func Export(jsonIn []byte) ([]byte, error) { - var req ExportRequest - err := json.Unmarshal(jsonIn, &req) + var s ExportRequest + var err error + + defer func() { + if err != nil { + log.Printf("export failed: user=%s %v", s.Name, err) + } else { + log.Printf("export success: user=%s", s.Name) + } + }() + + err = json.Unmarshal(jsonIn, &s) if err != nil { - log.Println("Error unmarshaling input:", err) return jsonStatusError(err) } - err = validateUser(req.Name, req.Password, true) + err = validateUser(s.Name, s.Password, true) if err != nil { - log.Println("Unauthorized attempt to export disk records") return jsonStatusError(err) } out, err := json.Marshal(records) if err != nil { - log.Println("Error exporting vault:", err) return jsonStatusError(err) } From e0e6b260a0ff6e044b5176cb965f37853b579391 Mon Sep 17 00:00:00 2001 From: Kyle Isom Date: Fri, 17 Jul 2015 15:34:08 -0700 Subject: [PATCH 2/2] Note the component that a log entry originates from. Instead of just 'init', use 'core.init' for core commands. Likewise, in the HTTP server, note log entries originate from the server. --- core/core.go | 42 +++++++++++++++++++++--------------------- redoctober.go | 6 +++--- 2 files changed, 24 insertions(+), 24 deletions(-) diff --git a/core/core.go b/core/core.go index d8bdb34..21d32f0 100644 --- a/core/core.go +++ b/core/core.go @@ -171,14 +171,14 @@ func Init(path string) error { defer func() { if err != nil { - log.Printf("init failed: %v", err) + log.Printf("core.init failed: %v", err) } else { - log.Printf("init success: path=%s", path) + log.Printf("core.init success: path=%s", path) } }() if records, err = passvault.InitFrom(path); err != nil { - err = fmt.Errorf("Failed to load password vault %s: %s", path, err) + err = fmt.Errorf("failed to load password vault %s: %s", path, err) } cache = keycache.Cache{UserKeys: make(map[string]keycache.ActiveUser)} @@ -194,9 +194,9 @@ func Create(jsonIn []byte) ([]byte, error) { defer func() { if err != nil { - log.Printf("create failed: user=%s %v", s.Name, err) + log.Printf("core.create failed: user=%s %v", s.Name, err) } else { - log.Printf("create success: user=%s", s.Name) + log.Printf("core.create success: user=%s", s.Name) } }() @@ -229,9 +229,9 @@ func Summary(jsonIn []byte) ([]byte, error) { defer func() { if err != nil { - log.Printf("summary failed: user=%s %v", s.Name, err) + log.Printf("core.summary failed: user=%s %v", s.Name, err) } else { - log.Printf("summary success: user=%s", s.Name) + log.Printf("core.summary success: user=%s", s.Name) } }() @@ -258,9 +258,9 @@ func Delegate(jsonIn []byte) ([]byte, error) { defer func() { if err != nil { - log.Printf("delegate failed: user=%s %v", s.Name, err) + log.Printf("core.delegate failed: user=%s %v", s.Name, err) } else { - log.Printf("delegate success: user=%s uses=%d time=%s users=%v labels=%v", s.Name, s.Uses, s.Time, s.Users, s.Labels) + log.Printf("core.delegate success: user=%s uses=%d time=%s users=%v labels=%v", s.Name, s.Uses, s.Time, s.Users, s.Labels) } }() @@ -307,9 +307,9 @@ func Password(jsonIn []byte) ([]byte, error) { defer func() { if err != nil { - log.Printf("password failed: user=%s %v", s.Name, err) + log.Printf("core.password failed: user=%s %v", s.Name, err) } else { - log.Printf("password success: user=%s", s.Name) + log.Printf("core.password success: user=%s", s.Name) } }() @@ -338,9 +338,9 @@ func Encrypt(jsonIn []byte) ([]byte, error) { defer func() { if err != nil { - log.Printf("encrypt failed: user=%s size=%d %v", s.Name, len(s.Data), err) + log.Printf("core.encrypt failed: user=%s size=%d %v", s.Name, len(s.Data), err) } else { - log.Printf("encrypt success: user=%s size=%d", s.Name, len(s.Data)) + log.Printf("core.encrypt success: user=%s size=%d", s.Name, len(s.Data)) } }() @@ -373,9 +373,9 @@ func Decrypt(jsonIn []byte) ([]byte, error) { defer func() { if err != nil { - log.Printf("decrypt failed: user=%s %v", s.Name, err) + log.Printf("core.decrypt failed: user=%s %v", s.Name, err) } else { - log.Printf("decrypt success: user=%s", s.Name) + log.Printf("core.decrypt success: user=%s", s.Name) } }() @@ -415,9 +415,9 @@ func Modify(jsonIn []byte) ([]byte, error) { defer func() { if err != nil { - log.Printf("modify failed: user=%s target=%s command=%s %v", s.Name, s.ToModify, s.Command, err) + log.Printf("core.modify failed: user=%s target=%s command=%s %v", s.Name, s.ToModify, s.Command, err) } else { - log.Printf("modify success: user=%s target=%s command=%s", s.Name, s.ToModify, s.Command) + log.Printf("core.modify success: user=%s target=%s command=%s", s.Name, s.ToModify, s.Command) } }() @@ -466,9 +466,9 @@ func Owners(jsonIn []byte) ([]byte, error) { defer func() { if err != nil { - log.Printf("owners failed: size=%d %v", len(s.Data), err) + log.Printf("core.owners failed: size=%d %v", len(s.Data), err) } else { - log.Printf("owners success: size=%d", len(s.Data)) + log.Printf("core.owners success: size=%d", len(s.Data)) } }() @@ -492,9 +492,9 @@ func Export(jsonIn []byte) ([]byte, error) { defer func() { if err != nil { - log.Printf("export failed: user=%s %v", s.Name, err) + log.Printf("core.export failed: user=%s %v", s.Name, err) } else { - log.Printf("export success: user=%s", s.Name) + log.Printf("core.export success: user=%s", s.Name) } }() diff --git a/redoctober.go b/redoctober.go index f333c28..defb717 100644 --- a/redoctober.go +++ b/redoctober.go @@ -134,7 +134,7 @@ func NewServer(process chan<- userRequest, staticPath, addr, certPath, keyPath, // copy this so reference does not get overwritten requestType := current mux.HandleFunc(requestType, func(w http.ResponseWriter, r *http.Request) { - log.Printf("request to %s from %s", requestType, r.RemoteAddr) + log.Printf("http.server: endpoint=%s remote=%s", requestType, r.RemoteAddr) queueRequest(process, requestType, w, r) }) } @@ -226,10 +226,10 @@ func main() { if err == nil { req.resp <- r } else { - log.Printf("Error handling %s: %s\n", req.rt, err) + log.Printf("http.main failed: %s: %s", req.rt, err) } } else { - log.Printf("Unknown user request received: %s\n", req.rt) + log.Printf("http.main: request=%s function is not supported", req.rt) } // Note that if an error occurs no message is sent down