From f0e439de0df77b6ceee197d62f51b47455fe8a3a Mon Sep 17 00:00:00 2001 From: Dan Walters Date: Sun, 26 May 2019 13:51:22 -0500 Subject: [PATCH] dlna: improve logging and error handling Mostly trying to get logging to happen through rclone's log methods. Added request logging, and a trace parameter that will dump the entire request/response for debugging when dealing with poorly written clients. Also added a flag to specify the device's "Friendly Name" explicitly, and made an attempt at allowing mime types in addition to video. --- cmd/serve/dlna/cds.go | 26 ++++--- cmd/serve/dlna/dlna.go | 64 +++++++++------- cmd/serve/dlna/dlna_util.go | 103 ++++++++++++++++++++++++++ cmd/serve/dlna/dlnaflags/dlnaflags.go | 15 +++- 4 files changed, 171 insertions(+), 37 deletions(-) diff --git a/cmd/serve/dlna/cds.go b/cmd/serve/dlna/cds.go index c5e3865e3..56be89dfb 100644 --- a/cmd/serve/dlna/cds.go +++ b/cmd/serve/dlna/cds.go @@ -9,11 +9,13 @@ import ( "os" "path" "path/filepath" + "regexp" "sort" "github.com/anacrolix/dms/dlna" "github.com/anacrolix/dms/upnp" "github.com/anacrolix/dms/upnpav" + "github.com/ncw/rclone/fs" "github.com/ncw/rclone/vfs" "github.com/pkg/errors" ) @@ -27,6 +29,8 @@ func (cds *contentDirectoryService) updateIDString() string { return fmt.Sprintf("%d", uint32(os.Getpid())) } +var mediaMimeTypeRegexp = regexp.MustCompile("^(video|audio|image)/") + // Turns the given entry and DMS host into a UPnP object. A nil object is // returned if the entry is not of interest. func (cds *contentDirectoryService) cdsObjectToUpnpavObject(cdsObject object, fileInfo os.FileInfo, host string) (ret interface{}, err error) { @@ -47,8 +51,13 @@ func (cds *contentDirectoryService) cdsObjectToUpnpavObject(cdsObject object, fi return } - // Hardcode "videoItem" so that files show up in VLC. - obj.Class = "object.item.videoItem" + mimeType := fs.MimeTypeFromName(fileInfo.Name()) + mediaType := mediaMimeTypeRegexp.FindStringSubmatch(mimeType) + if mediaType == nil { + return + } + + obj.Class = "object.item." + mediaType[1] + "Item" obj.Title = fileInfo.Name() item := upnpav.Item{ @@ -65,8 +74,7 @@ func (cds *contentDirectoryService) cdsObjectToUpnpavObject(cdsObject object, fi "path": {cdsObject.Path}, }.Encode(), }).String(), - // Hardcode "video/x-matroska" so that files show up in VLC. - ProtocolInfo: fmt.Sprintf("http-get:*:video/x-matroska:%s", dlna.ContentFeatures{ + ProtocolInfo: fmt.Sprintf("http-get:*:%s:%s", mimeType, dlna.ContentFeatures{ SupportRange: true, }.String()), Bitrate: 0, @@ -106,14 +114,14 @@ func (cds *contentDirectoryService) readContainer(o object, host string) (ret [] } obj, err := cds.cdsObjectToUpnpavObject(child, de, host) if err != nil { - log.Printf("error with %s: %s", child.FilePath(), err) + fs.Errorf(cds, "error with %s: %s", child.FilePath(), err) continue } - if obj != nil { - ret = append(ret, obj) - } else { - log.Printf("bad %s", de) + if obj == nil { + fs.Debugf(cds, "unrecognized file type: %s", de) + continue } + ret = append(ret, obj) } return diff --git a/cmd/serve/dlna/dlna.go b/cmd/serve/dlna/dlna.go index cf95fa21c..ef8663a16 100644 --- a/cmd/serve/dlna/dlna.go +++ b/cmd/serve/dlna/dlna.go @@ -4,7 +4,6 @@ import ( "bytes" "encoding/xml" "fmt" - "log" "net" "net/http" "net/url" @@ -53,7 +52,7 @@ players might show files that they are not able to play back correctly. cmd.Run(false, false, command, func() error { s := newServer(f, &dlnaflags.Opt) if err := s.Serve(); err != nil { - log.Fatal(err) + return err } s.Wait() return nil @@ -93,23 +92,23 @@ type server struct { } func newServer(f fs.Fs, opt *dlnaflags.Options) *server { - hostName, err := os.Hostname() - if err != nil { - hostName = "" - } else { - hostName = " (" + hostName + ")" + friendlyName := opt.FriendlyName + if friendlyName == "" { + friendlyName = makeDefaultFriendlyName() } s := &server{ AnnounceInterval: 10 * time.Second, + FriendlyName: friendlyName, + RootDeviceUUID: makeDeviceUUID(friendlyName), Interfaces: listInterfaces(), - FriendlyName: "rclone" + hostName, httpListenAddr: opt.ListenAddr, f: f, vfs: vfs.New(f, &vfsflags.Opt), } + s.services = map[string]UPnPService{ "ContentDirectory": &contentDirectoryService{ server: s, @@ -118,17 +117,21 @@ func newServer(f fs.Fs, opt *dlnaflags.Options) *server { server: s, }, } - s.RootDeviceUUID = makeDeviceUUID(s.FriendlyName) // Setup the various http routes. r := http.NewServeMux() r.HandleFunc(resPath, s.resourceHandler) - r.HandleFunc(rootDescPath, s.rootDescHandler) - r.HandleFunc(serviceControlURL, s.serviceControlHandler) + if opt.LogTrace { + r.Handle(rootDescPath, traceLogging(http.HandlerFunc(s.rootDescHandler))) + r.Handle(serviceControlURL, traceLogging(http.HandlerFunc(s.serviceControlHandler))) + } else { + r.HandleFunc(rootDescPath, s.rootDescHandler) + r.HandleFunc(serviceControlURL, s.serviceControlHandler) + } r.Handle("/static/", http.StripPrefix("/static/", withHeader("Cache-Control", "public, max-age=86400", http.FileServer(data.Assets)))) - s.handler = withHeader("Server", serverField, r) + s.handler = logging(withHeader("Server", serverField, r)) return s } @@ -140,6 +143,11 @@ type UPnPService interface { Unsubscribe(sid string) error } +// Formats the server as a string (used for logging.) +func (s *server) String() string { + return fmt.Sprintf("DLNA server on %v", s.httpListenAddr) +} + // Returns rclone version number as the model number. func (s *server) ModelNumber() string { return fs.Version @@ -223,14 +231,18 @@ func (s *server) rootDescHandler(w http.ResponseWriter, r *http.Request) { buffer := new(bytes.Buffer) err := rootDescTmpl.Execute(buffer, s) if err != nil { - http.Error(w, err.Error(), http.StatusBadRequest) + serveError(s, w, "Failed to create root descriptor XML", err) return } w.Header().Set("content-type", `text/xml; charset="utf-8"`) w.Header().Set("cache-control", "private, max-age=60") w.Header().Set("content-length", strconv.FormatInt(int64(buffer.Len()), 10)) - buffer.WriteTo(w) + _, err = buffer.WriteTo(w) + if err != nil { + // Network error + fs.Debugf(s, "Error writing rootDesc: %v", err) + } } // Handle a service control HTTP request. @@ -238,30 +250,30 @@ func (s *server) serviceControlHandler(w http.ResponseWriter, r *http.Request) { soapActionString := r.Header.Get("SOAPACTION") soapAction, err := upnp.ParseActionHTTPHeader(soapActionString) if err != nil { - http.Error(w, err.Error(), http.StatusBadRequest) + serveError(s, w, "Could not parse SOAPACTION header", err) return } var env soap.Envelope if err := xml.NewDecoder(r.Body).Decode(&env); err != nil { - http.Error(w, err.Error(), http.StatusBadRequest) + serveError(s, w, "Could not parse SOAP request body", err) return } w.Header().Set("Content-Type", `text/xml; charset="utf-8"`) w.Header().Set("Ext", "") - w.Header().Set("server", serverField) soapRespXML, code := func() ([]byte, int) { respArgs, err := s.soapActionResponse(soapAction, env.Body.Action, r) if err != nil { + fs.Errorf(s, "Error invoking %v: %v", soapAction, err) upnpErr := upnp.ConvertError(err) - return mustMarshalXML(soap.NewFault("UPnPError", upnpErr)), 500 + return mustMarshalXML(soap.NewFault("UPnPError", upnpErr)), http.StatusInternalServerError } - return marshalSOAPResponse(soapAction, respArgs), 200 + return marshalSOAPResponse(soapAction, respArgs), http.StatusOK }() bodyStr := fmt.Sprintf(`%s`, soapRespXML) w.WriteHeader(code) if _, err := w.Write([]byte(bodyStr)); err != nil { - log.Print(err) + fs.Infof(s, "Error writing response: %v", err) } } @@ -280,7 +292,7 @@ func (s *server) resourceHandler(w http.ResponseWriter, r *http.Request) { remotePath := r.URL.Query().Get("path") node, err := s.vfs.Stat(remotePath) if err != nil { - http.Error(w, err.Error(), http.StatusInternalServerError) + http.NotFound(w, r) return } @@ -297,12 +309,12 @@ func (s *server) resourceHandler(w http.ResponseWriter, r *http.Request) { file := node.(*vfs.File) in, err := file.Open(os.O_RDONLY) if err != nil { - http.Error(w, err.Error(), http.StatusInternalServerError) + serveError(node, w, "Could not open resource", err) + return } defer fs.CheckClose(in, &err) http.ServeContent(w, r, remotePath, node.ModTime(), in) - return } // Serve runs the server - returns the error only if @@ -410,16 +422,16 @@ func (s *server) ssdpInterface(intf net.Interface) { // good. return } - log.Printf("Error creating ssdp server on %s: %s", intf.Name, err) + fs.Errorf(s, "Error creating ssdp server on %s: %s", intf.Name, err) return } defer ssdpServer.Close() - log.Println("Started SSDP on", intf.Name) + fs.Infof(s, "Started SSDP on %v", intf.Name) stopped := make(chan struct{}) go func() { defer close(stopped) if err := ssdpServer.Serve(); err != nil { - log.Printf("%q: %q\n", intf.Name, err) + fs.Errorf(s, "%q: %q\n", intf.Name, err) } }() select { diff --git a/cmd/serve/dlna/dlna_util.go b/cmd/serve/dlna/dlna_util.go index b9d905756..6952e3dcb 100644 --- a/cmd/serve/dlna/dlna_util.go +++ b/cmd/serve/dlna/dlna_util.go @@ -8,11 +8,26 @@ import ( "log" "net" "net/http" + "net/http/httptest" + "net/http/httputil" + "os" "github.com/anacrolix/dms/soap" "github.com/anacrolix/dms/upnp" + "github.com/ncw/rclone/fs" ) +// Return a default "friendly name" for the server. +func makeDefaultFriendlyName() string { + hostName, err := os.Hostname() + if err != nil { + hostName = "" + } else { + hostName = " (" + hostName + ")" + } + return "rclone" + hostName +} + func makeDeviceUUID(unique string) string { h := md5.New() if _, err := io.WriteString(h, unique); err != nil { @@ -71,6 +86,87 @@ func marshalSOAPResponse(sa upnp.SoapAction, args map[string]string) []byte { sa.Action, sa.ServiceURN.String(), mustMarshalXML(soapArgs))) } +type loggingResponseWriter struct { + http.ResponseWriter + request *http.Request + committed bool +} + +func (lrw *loggingResponseWriter) logRequest(code int, err interface{}) { + // Choose appropriate log level based on response status code. + var level fs.LogLevel + if code < 400 && err == nil { + level = fs.LogLevelInfo + } else { + level = fs.LogLevelError + } + + fs.LogPrintf(level, lrw.request.URL.Path, "%s %s %d %s %s", + lrw.request.RemoteAddr, lrw.request.Method, code, + lrw.request.Header.Get("SOAPACTION"), err) +} + +func (lrw *loggingResponseWriter) WriteHeader(code int) { + lrw.committed = true + lrw.logRequest(code, nil) + lrw.ResponseWriter.WriteHeader(code) +} + +// HTTP handler that logs requests and any errors or panics. +func logging(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + lrw := &loggingResponseWriter{ResponseWriter: w, request: r} + defer func() { + err := recover() + if err != nil { + if !lrw.committed { + lrw.logRequest(http.StatusInternalServerError, err) + http.Error(w, fmt.Sprint(err), http.StatusInternalServerError) + } else { + // Too late to send the error to client, but at least log it. + fs.Errorf(r.URL.Path, "Recovered panic: %v", err) + } + } + }() + next.ServeHTTP(lrw, r) + }) +} + +// HTTP handler that logs complete request and response bodies for debugging. +// Error recovery and general request logging are left to logging(). +func traceLogging(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + dump, err := httputil.DumpRequest(r, true) + if err != nil { + serveError(nil, w, "error dumping request", err) + return + } + fs.Debugf(nil, "%s", dump) + + recorder := httptest.NewRecorder() + next.ServeHTTP(recorder, r) + + dump, err = httputil.DumpResponse(recorder.Result(), true) + if err != nil { + // log the error but ignore it + fs.Errorf(nil, "error dumping response: %v", err) + } else { + fs.Debugf(nil, "%s", dump) + } + + // copy from recorder to the real response writer + for k, v := range recorder.Header() { + w.Header()[k] = v + } + w.WriteHeader(recorder.Code) + _, err = recorder.Body.WriteTo(w) + if err != nil { + // Network error + fs.Debugf(nil, "Error writing response: %v", err) + } + }) +} + // HTTP handler that sets headers. func withHeader(name string, value string, next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { @@ -78,3 +174,10 @@ func withHeader(name string, value string, next http.Handler) http.Handler { next.ServeHTTP(w, r) }) } + +// serveError returns an http.StatusInternalServerError and logs the error +func serveError(what interface{}, w http.ResponseWriter, text string, err error) { + fs.CountError(err) + fs.Errorf(what, "%s: %v", text, err) + http.Error(w, text+".", http.StatusInternalServerError) +} diff --git a/cmd/serve/dlna/dlnaflags/dlnaflags.go b/cmd/serve/dlna/dlnaflags/dlnaflags.go index ba820372e..dd8ce518c 100644 --- a/cmd/serve/dlna/dlnaflags/dlnaflags.go +++ b/cmd/serve/dlna/dlnaflags/dlnaflags.go @@ -14,16 +14,25 @@ Use --addr to specify which IP address and port the server should listen on, eg --addr 1.2.3.4:8000 or --addr :8080 to listen to all IPs. +Use --name to choose the friendly server name, which is by +default "rclone (hostname)". + +Use --log-trace in conjunction with -vv to enable additional debug +logging of all UPNP traffic. ` // Options is the type for DLNA serving options. type Options struct { - ListenAddr string + ListenAddr string + FriendlyName string + LogTrace bool } // DefaultOpt contains the defaults options for DLNA serving. var DefaultOpt = Options{ - ListenAddr: ":7879", + ListenAddr: ":7879", + FriendlyName: "", + LogTrace: false, } // Opt contains the options for DLNA serving. @@ -34,6 +43,8 @@ var ( func addFlagsPrefix(flagSet *pflag.FlagSet, prefix string, Opt *Options) { rc.AddOption("dlna", &Opt) flags.StringVarP(flagSet, &Opt.ListenAddr, prefix+"addr", "", Opt.ListenAddr, "ip:port or :port to bind the DLNA http server to.") + flags.StringVarP(flagSet, &Opt.FriendlyName, prefix+"name", "", Opt.FriendlyName, "name of DLNA server") + flags.BoolVarP(flagSet, &Opt.LogTrace, prefix+"log-trace", "", Opt.LogTrace, "enable trace logging of SOAP traffic") } // AddFlags add the command line flags for DLNA serving.