Replace log.Print with real logging in most packages

config/account.go

@@ -164,7 +164,7 @@ func (a *Account) ID() string {
 
 // EnsurePrivateKey generates a private key for the account in case it's missing
 func (a *Account) EnsurePrivateKey() (hasUpdate bool, e error) {
-	log.Printf("[%s] ensureConfigHasKey()\n", a.Account)
+	log.WithField("account", a.Account).Debug("EnsurePrivateKey()")
 
 	prevKeys := a.AllPrivateKeys()
 	newKeys, err := otr3.GenerateMissingKeys(prevKeys)

config/connection_policy.go

@@ -13,6 +13,7 @@ import (
 
 	"golang.org/x/net/proxy"
 
+	"github.com/coyim/coyim/coylog"
 	ournet "github.com/coyim/coyim/net"
 	"github.com/coyim/coyim/servers"
 	ourtls "github.com/coyim/coyim/tls"
@@ -37,6 +38,8 @@ type ConnectionPolicy struct {
 	DialerFactory interfaces.DialerFactory
 
 	torState ournet.TorState
+
+	Log coylog.Logger
 }
 
 func (p *ConnectionPolicy) initTorState() {
@@ -111,6 +114,7 @@ func (p *ConnectionPolicy) buildDialerFor(conf *Account, verifier ourtls.Verifie
 	}
 
 	dialer := p.DialerFactory(verifier, ourtls.Real)
+	dialer.SetLogger(p.Log)
 	dialer.SetJID(conf.Account)
 	dialer.SetProxy(proxy)
 	dialer.SetConfig(xmppConfig)

config/logger.go → coylog/logger.go

@@ -1,4 +1,4 @@
-package config
+package coylog
 
 import (
 	"context"

net/dns.go

@@ -33,7 +33,7 @@ func timingOutLookup(f func() (cname string, addrs []*net.SRV, err error), t tim
 
 	select {
 	case <-time.After(t):
-		log.Println("dns: lookup timed out")
+		log.Warn("dns: lookup timed out")
 		return "", nil, ErrTimeout
 	case <-result:
 		return

net/tor.go

@@ -94,20 +94,20 @@ func (*defaultTorManager) IsConnectionOverTor(d proxy.Dialer) bool {
 
 	resp, err := c.Get("https://check.torproject.org/api/ip")
 	if err != nil {
-		log.Printf("Got error when trying to check tor: %v", err)
+		log.WithError(err).Warn("Got error when trying to check tor")
 		return false
 	}
 
 	content, err := ioutil.ReadAll(resp.Body)
 	if err != nil {
-		log.Printf("Got error when trying to check tor: %v", err)
+		log.WithError(err).Warn("Got error when trying to check tor")
 		return false
 	}
 
 	v := CheckTorResult{}
 	err = json.Unmarshal(content, &v)
 	if err != nil {
-		log.Printf("Got error when trying to check tor: %v", err)
+		log.WithError(err).Warn("Got error when trying to check tor")
 		return false
 	}
 

otrclient/conversation_manager.go

@@ -4,7 +4,7 @@ import (
 	"fmt"
 	"sync"
 
-	"github.com/coyim/coyim/config"
+	"github.com/coyim/coyim/coylog"
 	"github.com/coyim/coyim/xmpp/jid"
 	"github.com/coyim/otr3"
 )
@@ -47,11 +47,11 @@ type conversationManager struct {
 	onCreateEH OnEventHandlerCreation
 
 	account string
-	log     config.Logger
+	log     coylog.Logger
 }
 
 // NewConversationManager returns a new ConversationManager
-func NewConversationManager(builder ConversationBuilder, sender Sender, account string, onCreateEH OnEventHandlerCreation, l config.Logger) ConversationManager {
+func NewConversationManager(builder ConversationBuilder, sender Sender, account string, onCreateEH OnEventHandlerCreation, l coylog.Logger) ConversationManager {
 	return &conversationManager{
 		conversations: make(map[string]*conversation),
 		builder:       builder,

otrclient/event_handler.go

@@ -5,7 +5,7 @@ import (
 
 	log "github.com/sirupsen/logrus"
 
-	"github.com/coyim/coyim/config"
+	"github.com/coyim/coyim/coylog"
 	"github.com/coyim/coyim/xmpp/jid"
 	"github.com/coyim/otr3"
 )
@@ -27,7 +27,7 @@ type EventHandler struct {
 	delayedMessageSent chan<- int
 	delays             map[int]bool
 	pendingDelays      int
-	log                config.Logger
+	log                coylog.Logger
 }
 
 // ConsumeDelayedState returns whether the given trace has been delayed or not, blanking out that status as a side effect

session/session.go

@@ -12,6 +12,7 @@ import (
 	log "github.com/sirupsen/logrus"
 
 	"github.com/coyim/coyim/config"
+	"github.com/coyim/coyim/coylog"
 	"github.com/coyim/coyim/i18n"
 	"github.com/coyim/coyim/otrclient"
 	"github.com/coyim/coyim/roster"
@@ -36,7 +37,7 @@ const (
 
 type session struct {
 	conn             xi.Conn
-	connectionLogger config.Logger
+	connectionLogger coylog.Logger
 	r                *roster.List
 
 	connStatus     connStatus
@@ -103,12 +104,14 @@ func parseFromConfig(cu *config.Account) []otr3.PrivateKey {
 
 	allKeys := cu.AllPrivateKeys()
 
-	log.Printf("Loading %d configured keys", len(allKeys))
+	acc := cu.Account
+	l := log.WithField("account", acc)
+	l.WithField("numKeys", len(allKeys)).Info("Loading configured keys")
 	for _, pp := range allKeys {
 		_, ok, parsedKey := otr3.ParsePrivateKey(pp)
 		if ok {
 			result = append(result, parsedKey)
-			log.Printf("Loaded key: %s", config.FormatFingerprint(parsedKey.PublicKey().Fingerprint()))
+			l.WithField("key", config.FormatFingerprint(parsedKey.PublicKey().Fingerprint())).Info("Loaded key")
 		}
 	}
 
@@ -178,7 +181,10 @@ func (s *session) ReloadKeys() {
 func (s *session) Send(peer jid.Any, msg string) error {
 	conn, ok := s.connection()
 	if ok {
-		log.Printf("<- to=%v {%v}\n", peer, msg)
+		s.connectionLogger.WithFields(log.Fields{
+			"to":      peer,
+			"sentMsg": msg,
+		}).Debug("Send()")
 		return conn.Send(peer.String(), msg)
 	}
 	return &access.OfflineError{Msg: i18n.Local("Couldn't send message since we are not connected")}
@@ -208,7 +214,7 @@ func retrieveMessageTime(stanza *data.ClientMessage) time.Time {
 }
 
 func (s *session) receivedClientMessage(stanza *data.ClientMessage) bool {
-	log.Printf("-> Stanza %#v\n", stanza)
+	s.connectionLogger.WithField("stanza", fmt.Sprintf("%#v", stanza)).Debug("receivedClientMessage()")
 
 	if len(stanza.Body) == 0 && len(stanza.Extensions) > 0 {
 		s.processExtensions(stanza)
@@ -637,7 +643,7 @@ func (s *session) watchTimeout() {
 		newTimeouts := make(map[data.Cookie]time.Time)
 		for cookie, expiry := range s.timeouts {
 			if now.After(expiry) {
-				log.Println("session: cookie", cookie, "has expired")
+				s.connectionLogger.WithField("cookie", cookie).Debug("session: cookie has expired")
 				s.conn.Cancel(cookie)
 			} else {
 				newTimeouts[cookie] = expiry
@@ -677,7 +683,7 @@ func (s *session) getVCard() {
 
 	vcardStanza, ok := <-vcardReply
 	if !ok {
-		log.Println("session: vcard request cancelled or timedout")
+		s.connectionLogger.Debug("session: vcard request cancelled or timed out")
 		return
 	}
 
@@ -719,7 +725,7 @@ func (s *session) requestRoster() bool {
 	rosterStanza, ok := <-rosterReply
 	if !ok {
 		//TODO: should we retry the request in such case?
-		log.Println("session: roster request cancelled or timedout")
+		s.connectionLogger.Debug("session: roster request cancelled or timed out")
 		return true
 	}
 
@@ -787,7 +793,7 @@ func (s *session) Connect(password string, verifier tls.Verifier) error {
 
 	conf := s.GetConfig()
 	policy := config.ConnectionPolicy{
-		// Logger:        s.connectionLogger,
+		Log:           s.connectionLogger,
 		XMPPLogger:    s.xmppLogger,
 		DialerFactory: s.dialerFactory,
 	}

session/session_log.go

@@ -15,11 +15,11 @@ func openLogFile(logFile string) io.Writer {
 		return nil
 	}
 
-	log.Println("Logging XMPP messages to:", logFile)
+	log.WithField("file", logFile).Debug("Logging XMPP messages to file")
 
 	rawLog, err := os.OpenFile(logFile, os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0600)
 	if err != nil {
-		log.Println("Failed to open log file.", err)
+		log.WithError(err).Warn("Failed to open log file.")
 		//return nil, errors.New("Failed to open raw log file: " + err.Error())
 		return nil
 	}

session/session_test.go

@@ -1005,9 +1005,10 @@ func (s *SessionSuite) Test_watchTimeouts_cancelsTimedoutRequestsAndForgetsAbout
 	}
 
 	sess := &session{
-		connStatus: CONNECTED,
-		timeouts:   timeouts,
-		conn:       xmpp.NewConn(nil, nil, ""),
+		connectionLogger: log.New(),
+		connStatus:       CONNECTED,
+		timeouts:         timeouts,
+		conn:             xmpp.NewConn(nil, nil, ""),
 	}
 
 	go func() {

xmpp/connection.go

@@ -21,6 +21,7 @@ import (
 	log "github.com/sirupsen/logrus"
 
 	"github.com/coyim/coyim/cache"
+	"github.com/coyim/coyim/coylog"
 	"github.com/coyim/coyim/xmpp/data"
 	"github.com/coyim/coyim/xmpp/interfaces"
 	"github.com/coyim/coyim/xmpp/jid"
@@ -59,6 +60,8 @@ type conn struct {
 	statusUpdates chan<- string
 
 	channelBinding []byte
+
+	log coylog.Logger
 }
 
 func (c *conn) Cache() cache.WithExpiry {
@@ -133,6 +136,8 @@ func (c *conn) Out() io.Writer {
 // NewConn creates a new connection
 //TODO: this is used only for testing. Remove when we have a Conn interface
 func NewConn(in *xml.Decoder, out io.WriteCloser, jid string) interfaces.Conn {
+	l := log.New()
+	l.SetOutput(ioutil.Discard)
 	conn := &conn{
 		in:     in,
 		out:    out,
@@ -144,6 +149,7 @@ func NewConn(in *xml.Decoder, out io.WriteCloser, jid string) interfaces.Conn {
 
 		rand: rand.Reader,
 		c:    cache.NewWithExpiry(),
+		log:  l,
 	}
 
 	conn.setClosed(true)
@@ -168,7 +174,7 @@ func (c *conn) Close() error {
 	}
 
 	// RFC 6120, Section 4.4 and 9.1.5
-	log.Println("xmpp: sending closing stream tag")
+	c.log.Info("xmpp: sending closing stream tag")
 
 	c.closedLock.Lock()
 	_, err := fmt.Fprint(c.out, "</stream:stream>")
@@ -194,14 +200,14 @@ func (c *conn) Close() error {
 	// channel...
 	case <-c.streamCloseReceived:
 	case <-time.After(30 * time.Second):
-		log.Println("xmpp: timed out waiting for closing stream")
+		c.log.Info("xmpp: timed out waiting for closing stream")
 	}
 
 	return c.closeTCP()
 }
 
 func (c *conn) receivedStreamClose() error {
-	log.Println("xmpp: received closing stream tag")
+	c.log.Info("xmpp: received closing stream tag")
 	return c.closeImmediately()
 }
 
@@ -222,7 +228,7 @@ func (c *conn) closeTCP() error {
 	//Close all pending requests at this moment. It will include pending pings
 	c.cancelInflights()
 
-	log.Println("xmpp: TCP closed")
+	c.log.Info("xmpp: TCP closed")
 	c.setClosed(true)
 	return c.rawOut.Close()
 }
@@ -249,7 +255,7 @@ func (c *conn) asyncReturnIQResponse(stanza data.Stanza) error {
 	c.inflightsMutex.Unlock()
 
 	if !ok {
-		log.Println("xmpp: received reply to unknown iq. id:", iq.ID)
+		c.log.WithField("iq", iq).Warn("xmpp: received reply to unknown iq")
 		return nil
 	}
 
@@ -285,7 +291,7 @@ func (c *conn) asyncReturnIQResponse(stanza data.Stanza) error {
 // the stanza for processing.
 func (c *conn) Next() (stanza data.Stanza, err error) {
 	for {
-		if stanza.Name, stanza.Value, err = next(c); err != nil {
+		if stanza.Name, stanza.Value, err = next(c, c.log); err != nil {
 			return
 		}
 
@@ -351,7 +357,7 @@ func (c *conn) ReadStanzas(stanzaChan chan<- data.Stanza) error {
 	for {
 		stanza, err := c.Next()
 		if err != nil {
-			log.Printf("xmpp: error receiving stanza. %s\n", err)
+			c.log.WithError(err).Warn("xmpp: error receiving stanza")
 			return err
 		}