Merge branch 'byte-based-logging'

Logging used to re-encode tokens for receive logging and double-encode
tokens for send logging. This had the flexibility to pretty-print the
XML. Furthermore it was trivial to prepend a prefix like `S: ` and `C: `
for server and client.

This merge moves away from logging based on re-encoding XML tokens.
Instead the received or sent bytes are multiplexed to a logger which
uses the log module of the standard library to log the XML code.

These advantages come with this merge:

- [TX] / [RX] instead of C: / S: as prefixes (direction instead of node)
- encoding issues can be debugged via the log
- everything is now logged via the log module and has timestamps

The only disadvantage is that the logged XML is not pretty-printed
anymore. This is choosen for the RX stream to not accidentally hide
encoding issues and show what is really on the wire. That argument is
true for TX aswell and consistency is appreciated anyway.

2 files changed, 34 insertions, 35 deletions

diff --git a/xmpp/encoder_decoder.go b/xmpp/encoder_decoder.go
index c340b09..b0ea77b 100644
--- a/xmpp/encoder_decoder.go
+++ b/xmpp/encoder_decoder.go
@@ -5,15 +5,12 @@ import (
 	"errors"
 	"io"
 	"log"
-	"os"
 )
 
 type encoderDecoder struct {
 	session    *session
-	ct         *xml.Encoder // client transport encoder
-	cl         *xml.Encoder // client log encoder
-	st         *xml.Decoder // server transport decoder
-	sl         *xml.Encoder // server log encoder
+	tx         *xml.Encoder
+	rx         *xml.Decoder
 	terminator chan bool
 }
 
@@ -22,16 +19,14 @@ func newEncoderDecoder(s *session) encoderDecoder {
 
 	ed.session = s
 
-	ed.ct = xml.NewEncoder(s.transport)
-	ed.ct.Indent("", "    ")
+	lw := logger{"[TX] "}
+	w := io.MultiWriter(s.transport, lw)
+	ed.tx = xml.NewEncoder(w)
+	ed.tx.Indent("", "")
 
-	ed.cl = xml.NewEncoder(os.Stdout)
-	ed.cl.Indent("C: ", "    ")
-
-	ed.st = xml.NewDecoder(s.transport)
-
-	ed.sl = xml.NewEncoder(os.Stdout)
-	ed.sl.Indent("S: ", "    ")
+	lr := logger{"[RX] "}
+	r := io.TeeReader(s.transport, lr)
+	ed.rx = xml.NewDecoder(r)
 
 	return ed
 }
@@ -44,20 +39,11 @@ func (ed *encoderDecoder) encodeToken(t xml.Token) error {
 		}
 	}()
 
-	err = ed.ct.EncodeToken(t)
-	if err != nil {
-		return err
-	}
-	err = ed.ct.Flush()
-	if err != nil {
-		return err
-	}
-
-	err = ed.cl.EncodeToken(t)
+	err = ed.tx.EncodeToken(t)
 	if err != nil {
 		return err
 	}
-	err = ed.cl.Flush()
+	err = ed.tx.Flush()
 	if err != nil {
 		return err
 	}
@@ -71,18 +57,16 @@ func (ed *encoderDecoder) run() {
 		case <-ed.terminator:
 			return
 		default:
-			t, err := ed.st.Token()
+			t, err := ed.rx.Token()
 			if t != nil && err == nil {
-				err = ed.sl.EncodeToken(t)
-				if err != nil {
-					log.Println("Could not encode to server stream log")
-				}
-				err = ed.sl.Flush()
-				if err != nil {
-					log.Println("Could not flush server stream log")
+				switch t.(type) {
+				case xml.ProcInst:
+				case xml.Directive:
+				case xml.Comment:
+				default:
+					c := xml.CopyToken(t)
+					ed.session.rx <- c
 				}
-				c := xml.CopyToken(t)
-				ed.session.rx <- c
 			}
 			if err != nil {
 				if errors.Is(err, io.EOF) {
diff --git a/xmpp/log.go b/xmpp/log.go
new file mode 100644
index 0000000..4ac0f88
--- /dev/null
+++ b/xmpp/log.go
@@ -0,0 +1,15 @@
+package xmpp
+
+import (
+	"log"
+)
+
+type logger struct {
+	prefix string
+}
+
+func (l logger) Write(p []byte) (n int, err error) {
+	log.Printf("%s%s", l.prefix, string(p))
+
+	return len(p), nil
+}