Add Logging for plist parse errors

[4e554c4c]

This is useful to debug errors that occur because of bad plists sent by
clients. Usually in this case, one receives a not-very-useful error such
as HTTP status 400 (Bad Request): <opaque error>.

Test Plan

1. Patch mdmb so that it sends bad checkins

diff --git a/internal/device/mdm.go b/internal/device/mdm.go
index 33a4c50..cda3d69 100644
--- a/internal/device/mdm.go
+++ b/internal/device/mdm.go
@@ -185,10 +185,7 @@ func (c *MDMClient) connect(client *http.Client, connReq interface{}) error {
                return errors.New("device not enrolled")
        }

-       plistBytes, err := plist.Marshal(connReq)
-       if err != nil {
-               return err
-       }
+       plistBytes := []byte("aoeuaoeuaoeu")

2. Run

$ mdmb -uuids $uuid devices-connect

3. Observe more verbose NanoMDM log:

2022/07/21 15:52:43 level=info handler=checkin-command msg=command report results err=HTTP status 400 (Bad Request): decoding command results: parse error: EOF: raw body: aoeuaoeuaoeu

[jessepeterson]

Nice! I'd also like to see some error checking such that the body is logged as its own individual column. Something along these lines:

diff --git a/http/mdm/mdm.go b/http/mdm/mdm.go
index 0325280..ae4f493 100644
--- a/http/mdm/mdm.go
+++ b/http/mdm/mdm.go
@@ -2,6 +2,7 @@ package mdm
 
 import (
        "errors"
+       "fmt"
        "net/http"
        "strings"
 
@@ -37,12 +38,20 @@ func CheckinHandler(svc service.Checkin, logger log.Logger) http.HandlerFunc {
                }
                respBytes, err := service.CheckinRequest(svc, mdmReqFromHTTPReq(r), bodyBytes)
                if err != nil {
-                       logger.Info("msg", "check-in request", "err", err)
+                       logs := []interface{}{"msg", "check-in request"}
                        httpStatus := http.StatusInternalServerError
                        var statusErr *service.HTTPStatusError
                        if errors.As(err, &statusErr) {
                                httpStatus = statusErr.Status
+                               err = statusErr.Err
+                               var parseErr *mdm.ParseError
+                               if errors.As(statusErr.Err, &parseErr) {
+                                       err = fmt.Errorf("parse: %w", parseErr.Err)
+                                       logs = append(logs, "body", parseErr.Body)
+                               }
                        }
+                       logs = append(logs, "http_status", httpStatus, "err", err)
+                       logger.Info(logs...)
                        http.Error(w, http.StatusText(httpStatus), httpStatus)
                }
                w.Write(respBytes)

(And same for command endpoint)

However perhaps this is future thing — it's.. complicated to do the right set of logging by clobbering multiple errors into a single log line and potentially losing some context along the way. I think the above patch would look something like this with your example log line:

2022/07/21 15:52:43 level=info handler=checkin-command msg=command report results body=aoeuaoeuaoeu http_status=400 err=parse: EOF

But in any case there's at least a couple small requested changes. :)

[4e554c4c]

new log line:

2022/07/25 11:26:09 level=info handler=checkin-command trace_id=222d85887f605374 msg=command report results err=HTTP status 400 (Bad Request): decoding command results: parse error: EOF: raw content: aoeuaoeuaoeu http_status=400 content=aoeuaoeuaoeu

[jessepeterson]

lgtm! thanks for the changes. :)