extends debug messages with duration of handling

output/all/internal.go

@@ -2,6 +2,7 @@ package all
 
 import (
 	"github.com/bdlm/log"
+	"time"
 
 	"dev.sum7.eu/genofire/logmania/bot"
 	"dev.sum7.eu/genofire/logmania/database"
@@ -69,7 +70,19 @@ func (out *Output) sender() {
 }
 
 func (out *Output) Send(e *log.Entry, to *database.Notify) bool {
+	before := time.Now()
+
+	logger := log.WithFields(e.Data)
+	logger = logger.WithField("msg", e.Message)
+
+	logger.Debugf("starting forward message")
+
 	out.channelNotify <- e
+
+	after := time.Now()
+	delta := after.Sub(before)
+	logger.WithField("ms", float64(delta)/float64(time.Millisecond)).Debugf("end forward message")
+
 	return true
 }
 

output/xmpp/recv.go

@@ -1,21 +1,30 @@
 package xmpp
 
 import (
+	"time"
+
 	"github.com/bdlm/log"
 	"gosrc.io/xmpp"
 )
 
 func (out *Output) recvMessage(s xmpp.Sender, p xmpp.Packet) {
+	before := time.Now()
+
 	msg, ok := p.(xmpp.Message)
 	if !ok {
 		log.Errorf("blame gosrc.io/xmpp for routing: %s", p)
 		return
 	}
+	log.WithFields(map[string]interface{}{
+		"sender":  msg.From,
+		"request": msg.Body,
+	}).Debug("handling bot message")
 	from, err := xmpp.NewJid(msg.From)
 	if err != nil {
 		log.Errorf("blame gosrc.io/xmpp for jid encoding: %s", msg.From)
 		return
 	}
+
 	fromBare := from.Bare()
 	fromLogmania := ""
 	if msg.Type == xmpp.MessageTypeGroupchat {
@@ -30,6 +39,16 @@ func (out *Output) recvMessage(s xmpp.Sender, p xmpp.Packet) {
 	}
 	reply := xmpp.Message{Attrs: xmpp.Attrs{To: fromBare, Type: msg.Type}, Body: answer}
 	s.Send(reply)
+
+	after := time.Now()
+	delta := after.Sub(before)
+
+	log.WithFields(map[string]interface{}{
+		"sender":  fromLogmania,
+		"request": msg.Body,
+		"answer":  answer,
+		"ms":      float64(delta) / float64(time.Millisecond),
+	}).Debug("handled xmpp bot message")
 }
 
 func (out *Output) recvPresence(s xmpp.Sender, p xmpp.Packet) {