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

@@ -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

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(`<?xml version="1.0" encoding="utf-8" standalone="yes"?><s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body>%s</s:Body></s:Envelope>`, 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 {

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)
+}

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.