Improved logging.

client.go

@@ -19,6 +19,9 @@ import (
 
 // A client connection
 type Client struct {
+	// Logging
+	*log.Logger
+	lf *clientLogForwarder
 
 	// Connection-related
 	tcpaddr *net.TCPAddr
@@ -114,7 +117,7 @@ func (client *Client) ShownName() string {
 
 // Something invalid happened on the wire.
 func (client *Client) Panic(reason string) {
-	log.Printf("Client panic: %s", reason)
+	client.Printf("panic: %v", reason)
 	client.Disconnect()
 }
 
@@ -248,7 +251,7 @@ func (c *Client) sendPermissionDeniedTypeUser(kind string, user *Client) {
 			kind: MessagePermissionDenied,
 		}
 	} else {
-		log.Panic("Unknown permission denied type.")
+		c.Panic("Unknown permission denied type.")
 	}
 }
 
@@ -339,10 +342,10 @@ func (client *Client) udpreceiver() {
 
 func (client *Client) sendUdp(msg *Message) {
 	if client.udp {
-		log.Printf("Sent UDP!")
+		client.Printf("Sent UDP!")
 		client.server.udpsend <- msg
 	} else {
-		log.Printf("Sent TCP!")
+		client.Printf("Sent TCP!")
 		msg.kind = MessageUDPTunnel
 		client.msgchan <- msg
 	}
@@ -417,10 +420,10 @@ func (client *Client) receiver() {
 			msg, err := client.readProtoMessage()
 			if err != nil {
 				if err == os.EOF {
-					log.Printf("Client disconnected.")
+					client.Printf("Disconnected.")
 					client.Disconnect()
 				} else {
-					log.Printf("Client error.")
+					client.Printf("Client error")
 				}
 				return
 			}
@@ -474,10 +477,10 @@ func (client *Client) receiver() {
 			msg, err := client.readProtoMessage()
 			if err != nil {
 				if err == os.EOF {
-					log.Printf("Client disconnected.")
+					client.Printf("Disconnected")
 					client.Disconnect()
 				} else {
-					log.Printf("Client error.")
+					client.Printf("Client error")
 				}
 				return
 			}
@@ -507,9 +510,9 @@ func (client *Client) receiver() {
 				client.OSVersion = *version.OsVersion
 			}
 
-			log.Printf("version = 0x%x", client.Version)
-			log.Printf("os = %s %s", client.OSName, client.OSVersion)
-			log.Printf("client = %s", client.ClientName)
+			client.Printf("version = 0x%x", client.Version)
+			client.Printf("os = %s %s", client.OSName, client.OSVersion)
+			client.Printf("client = %s", client.ClientName)
 
 			client.state = StateClientSentVersion
 		}

grumble.go

@@ -76,6 +76,7 @@ func main() {
 		return
 	}
 
+	log.SetPrefix("[G] ")
 	log.Printf("Grumble - Mumble server written in Go")
 
 	if len(*datadir) == 0 {

message.go

@@ -5,7 +5,6 @@
 package main
 
 import (
-	"log"
 	"mumbleproto"
 	"goprotobuf.googlecode.com/hg/proto"
 	"net"
@@ -85,14 +84,14 @@ func (server *Server) handleCryptSetup(client *Client, msg *Message) {
 	// No client nonce. This means the client
 	// is requesting that we re-sync our nonces.
 	if len(cs.ClientNonce) == 0 {
-		log.Printf("Requested crypt-nonce resync")
+		client.Printf("Requested crypt-nonce resync")
 		cs.ClientNonce = make([]byte, cryptstate.AESBlockSize)
 		if copy(cs.ClientNonce, client.crypt.EncryptIV[0:]) != cryptstate.AESBlockSize {
 			return
 		}
 		client.sendProtoMessage(MessageCryptSetup, cs)
 	} else {
-		log.Printf("Received client nonce")
+		client.Printf("Received client nonce")
 		if len(cs.ClientNonce) != cryptstate.AESBlockSize {
 			return
 		}
@@ -101,7 +100,7 @@ func (server *Server) handleCryptSetup(client *Client, msg *Message) {
 		if copy(client.crypt.DecryptIV[0:], cs.ClientNonce) != cryptstate.AESBlockSize {
 			return
 		}
-		log.Printf("Crypt re-sync successful")
+		client.Printf("Crypt re-sync successful")
 	}
 }
 
@@ -237,7 +236,7 @@ func (server *Server) handleChannelStateMessage(client *Client, msg *Message) {
 		if len(description) > 0 {
 			key, err = globalBlobstore.Put([]byte(description))
 			if err != nil {
-				log.Panicf("Blobstore error: %v", err.String())
+				server.Panicf("Blobstore error: %v", err.String())
 			}
 		}
 
@@ -416,7 +415,7 @@ func (server *Server) handleChannelStateMessage(client *Client, msg *Message) {
 		if chanstate.Description != nil {
 			key, err := globalBlobstore.Put([]byte(*chanstate.Description))
 			if err != nil {
-				log.Panicf("Blobstore error: %v", err.String())
+				server.Panicf("Blobstore error: %v", err.String())
 			}
 			channel.DescriptionBlob = key
 		}
@@ -487,12 +486,12 @@ func (server *Server) handleUserRemoveMessage(client *Client, msg *Message) {
 
 	if ban {
 		// fixme(mkrautz): Implement banning.
-		log.Printf("handleUserRemove: Banning is not yet implemented.")
+		server.Printf("handleUserRemove: Banning is not yet implemented.")
 	}
 
 	userremove.Actor = proto.Uint32(uint32(client.Session))
 	if err = server.broadcastProtoMessage(MessageUserRemove, userremove); err != nil {
-		log.Panic("Unable to broadcast UserRemove message")
+		server.Panicf("Unable to broadcast UserRemove message")
 		return
 	}
 
@@ -509,7 +508,7 @@ func (server *Server) handleUserStateMessage(client *Client, msg *Message) {
 
 	actor, ok := server.clients[client.Session]
 	if !ok {
-		log.Panic("Client not found in server's client map.")
+		server.Panic("Client not found in server's client map.")
 		return
 	}
 	target := actor
@@ -638,7 +637,7 @@ func (server *Server) handleUserStateMessage(client *Client, msg *Message) {
 	if userstate.Texture != nil && target.user != nil {
 		key, err := globalBlobstore.Put(userstate.Texture)
 		if err != nil {
-			log.Panicf("Blobstore error: %v", err.String())
+			server.Panicf("Blobstore error: %v", err.String())
 		}
 
 		if target.user.TextureBlob != key {
@@ -678,7 +677,7 @@ func (server *Server) handleUserStateMessage(client *Client, msg *Message) {
 	if userstate.Comment != nil && target.user != nil {
 		key, err := globalBlobstore.Put([]byte(*userstate.Comment))
 		if err != nil {
-			log.Panicf("Blobstore error: %v", err.String())
+			server.Panicf("Blobstore error: %v", err.String())
 		}
 
 		if target.user.CommentBlob != key {
@@ -770,7 +769,7 @@ func (server *Server) handleUserStateMessage(client *Client, msg *Message) {
 				return client.Version < 0x10202
 			})
 			if err != nil {
-				log.Panic("Unable to broadcast UserState")
+				server.Panic("Unable to broadcast UserState")
 			}
 			// Re-add it to the message, so that 1.2.2+ clients *do* get the new-style texture.
 			userstate.Texture = texture
@@ -780,7 +779,7 @@ func (server *Server) handleUserStateMessage(client *Client, msg *Message) {
 				return client.Version < 0x10202
 			})
 			if err != nil {
-				log.Panic("Unable to broadcast UserState")
+				server.Panic("Unable to broadcast UserState")
 			}
 		}
 
@@ -812,7 +811,7 @@ func (server *Server) handleUserStateMessage(client *Client, msg *Message) {
 			return client.Version >= 0x10203
 		})
 		if err != nil {
-			log.Panic("Unable to broadcast UserState")
+			server.Panic("Unable to broadcast UserState")
 		}
 	}
 }
@@ -1012,7 +1011,7 @@ func (server *Server) handleAclMessage(client *Client, msg *Message) {
 		for uid, _ := range users {
 			user, ok := server.Users[uint32(uid)]
 			if !ok {
-				log.Printf("Invalid user id in ACL")
+				client.Printf("Invalid user id in ACL")
 				continue
 			}
 			queryusers.Ids = append(queryusers.Ids, uint32(uid))
@@ -1110,7 +1109,7 @@ func (server *Server) handleUserStatsMessage(client *Client, msg *Message) {
 		client.Panic(err.String())
 	}
 
-	log.Printf("UserStats")
+	client.Printf("UserStats")
 }
 
 // Permission query
@@ -1150,7 +1149,7 @@ func (server *Server) handleRequestBlob(client *Client, msg *Message) {
 				if target.user.HasTexture() {
 					buf, err := globalBlobstore.Get(target.user.TextureBlob)
 					if err != nil {
-						log.Panicf("Blobstore error: %v", err.String())
+						server.Panicf("Blobstore error: %v", err.String())
 					}
 					userstate.Reset()
 					userstate.Session = proto.Uint32(uint32(target.Session))
@@ -1174,7 +1173,7 @@ func (server *Server) handleRequestBlob(client *Client, msg *Message) {
 				if target.user.HasComment() {
 					buf, err := globalBlobstore.Get(target.user.CommentBlob)
 					if err != nil {
-						log.Panicf("Blobstore error: %v", err.String())
+						server.Panicf("Blobstore error: %v", err.String())
 					}
 					userstate.Reset()
 					userstate.Session = proto.Uint32(uint32(target.Session))
@@ -1198,7 +1197,7 @@ func (server *Server) handleRequestBlob(client *Client, msg *Message) {
 					chanstate.Reset()
 					buf, err := globalBlobstore.Get(channel.DescriptionBlob)
 					if err != nil {
-						log.Panicf("Blobstore error: %v", err.String())
+						server.Panicf("Blobstore error: %v", err.String())
 					}
 					chanstate.ChannelId = proto.Uint32(uint32(channel.Id))
 					chanstate.Description = proto.String(string(buf))

register.go

@@ -11,7 +11,6 @@ import (
 	"encoding/hex"
 	"http"
 	"io/ioutil"
-	"log"
 	"net"
 	"os"
 	"strconv"
@@ -118,7 +117,7 @@ func (server *Server) RegisterPublicServer() {
 	buf := bytes.NewBuffer(nil)
 	t, err := template.Parse(registerTemplate, nil)
 	if err != nil {
-		log.Printf("register: unable to parse template: %v", err)
+		server.Printf("register: unable to parse template: %v", err)
 		return
 	}
 	err = t.Execute(buf, map[string]string{
@@ -133,7 +132,7 @@ func (server *Server) RegisterPublicServer() {
 		"channels": strconv.Itoa(len(server.Channels)),
 	})
 	if err != nil {
-		log.Printf("register: unable to execute template: %v", err)
+		server.Printf("register: unable to execute template: %v", err)
 		return
 	}
 
@@ -143,7 +142,7 @@ func (server *Server) RegisterPublicServer() {
 		// certificate chain, so we use our own wrapper instead.
 		hc, err := newTLSClientAuthConn(registerAddr, config)
 		if err != nil {
-			log.Printf("register: unable to create https client: %v", err)
+			server.Printf("register: unable to create https client: %v", err)
 			return
 		}
 		defer hc.Close()
@@ -164,13 +163,13 @@ func (server *Server) RegisterPublicServer() {
 
 		req.URL, err = http.ParseURL(registerUrl)
 		if err != nil {
-			log.Printf("register: error parsing url: %v", err)
+			server.Printf("register: error parsing url: %v", err)
 			return
 		}
 
 		r, err := hc.Do(&req)
 		if err != nil && err != http.ErrPersistEOF {
-			log.Printf("register: unable to post registration request: %v", err)
+			server.Printf("register: unable to post registration request: %v", err)
 			return
 		}
 
@@ -178,12 +177,12 @@ func (server *Server) RegisterPublicServer() {
 		if err == nil {
 			registerMsg := string(bodyBytes)
 			if r.StatusCode == 200 {
-				log.Printf("register: %v", registerMsg)
+				server.Printf("register: %v", registerMsg)
 			} else {
-				log.Printf("register: (status %v) %v", r.StatusCode, registerMsg)
+				server.Printf("register: (status %v) %v", r.StatusCode, registerMsg)
 			}
 		} else {
-			log.Printf("register: unable to read post response: %v", err)
+			server.Printf("register: unable to read post response: %v", err)
 			return
 		}
 	}()

server.go

@@ -19,6 +19,7 @@ import (
 	"goprotobuf.googlecode.com/hg/proto"
 	"mumbleproto"
 	"cryptstate"
+	"fmt"
 	"gob"
 	"hash"
 	"io"
@@ -96,6 +97,26 @@ type Server struct {
 
 	// ACL cache
 	aclcache ACLCache
+
+	// Logging
+	*log.Logger
+}
+
+type clientLogForwarder struct {
+	client *Client
+	logger *log.Logger
+}
+
+func (lf clientLogForwarder) Write(incoming []byte) (int, os.Error) {
+	buf := bytes.NewBuffer(nil)
+	if (lf.client.Session == 0) {
+		buf.WriteString("{?} ")
+	} else {
+		buf.WriteString(fmt.Sprintf("{%v} ", lf.client.Session))
+	}
+	buf.Write(incoming)
+	lf.logger.Output(3, buf.String())
+	return len(incoming), nil
 }
 
 type freezeRequest struct {
@@ -133,6 +154,8 @@ func NewServer(id int64, addr string, port int) (s *Server, err os.Error) {
 	s.root = s.NewChannel(0, "Root")
 	s.aclcache = NewACLCache()
 
+	s.Logger = log.New(os.Stdout, fmt.Sprintf("[%v] ", s.Id), log.Ldate|log.Ltime)
+
 	return
 }
 
@@ -140,7 +163,7 @@ func NewServer(id int64, addr string, port int) (s *Server, err os.Error) {
 func (server *Server) CheckSuperUserPassword(password string) bool {
 	superUser, exists := server.Users[0]
 	if !exists {
-		log.Panicf("Fatal error: No SuperUser for server %v", server.Id)
+		server.Panicf("Fatal error: No SuperUser for server %v", server.Id)
 	}
 
 	parts := strings.Split(superUser.Password, "$", -1)
@@ -186,6 +209,9 @@ func (server *Server) NewClient(conn net.Conn) (err os.Error) {
 		return
 	}
 
+	client.lf = &clientLogForwarder{client, server.Logger}
+	client.Logger = log.New(client.lf, "", 0)
+
 	client.tcpaddr = addr.(*net.TCPAddr)
 	client.server = server
 	client.conn = conn
@@ -241,7 +267,7 @@ func (server *Server) RemoveClient(client *Client, kicked bool) {
 			Session: proto.Uint32(client.Session),
 		})
 		if err != nil {
-			log.Panic("Unable to broadcast UserRemove message for disconnected client.")
+			server.Panic("Unable to broadcast UserRemove message for disconnected client.")
 		}
 	}
 }
@@ -274,7 +300,7 @@ func (server *Server) AddChannel(name string) (channel *Channel) {
 // Remove a channel from the server.
 func (server *Server) RemoveChanel(channel *Channel) {
 	if channel.Id == 0 {
-		log.Printf("Attempted to remove root channel.")
+		server.Printf("Attempted to remove root channel.")
 		return
 	}
 	server.Channels[channel.Id] = nil, false
@@ -331,7 +357,7 @@ func (server *Server) handler() {
 			server.handleIncomingMessage(client, msg)
 		// Voice broadcast
 		case vb := <-server.voicebroadcast:
-			log.Printf("VoiceBroadcast!")
+			server.Printf("VoiceBroadcast!")
 			if vb.target == 0 {
 				channel := vb.client.Channel
 				for _, client := range channel.clients {
@@ -352,7 +378,7 @@ func (server *Server) handler() {
 		case req := <-server.freezeRequest:
 			fs, err := server.Freeze()
 			if err != nil {
-				log.Panicf("Unable to freeze the server")
+				server.Panicf("Unable to freeze the server")
 			}
 			go server.handleFreezeRequest(req, &fs)
 
@@ -373,7 +399,7 @@ func (server *Server) handleFreezeRequest(freq *freezeRequest, fs *frozenServer)
 	zw, err := gzip.NewWriterLevel(pw, gzip.BestCompression)
 	if err != nil {
 		if err = pw.CloseWithError(err); err != nil {
-			log.Panicf("Unable to close PipeWriter: %v", err.String())
+			server.Panicf("Unable to close PipeWriter: %v", err.String())
 		}
 		return
 	}
@@ -382,12 +408,12 @@ func (server *Server) handleFreezeRequest(freq *freezeRequest, fs *frozenServer)
 	err = enc.Encode(fs)
 	if err != nil {
 		if err = pw.CloseWithError(err); err != nil {
-			log.Panicf("Unable to close PipeWriter: %v", err.String())
+			server.Panicf("Unable to close PipeWriter: %v", err.String())
 		}
 	}
 
 	if err = pw.CloseWithError(zw.Close()); err != nil {
-		log.Panicf("Unable to close PipeWriter: %v", err.String())
+		server.Panicf("Unable to close PipeWriter: %v", err.String())
 	}
 }
 
@@ -496,7 +522,7 @@ func (server *Server) handleAuthenticate(client *Client, msg *Message) {
 	// Add codecs
 	client.codecs = auth.CeltVersions
 	if len(client.codecs) == 0 {
-		log.Printf("Client %i connected without CELT codecs.", client.Session)
+		server.Printf("Client %i connected without CELT codecs.", client.Session)
 	}
 
 	client.state = StateClientAuthenticated
@@ -566,7 +592,7 @@ func (server *Server) finishAuthenticate(client *Client) {
 			} else {
 				buf, err := globalBlobstore.Get(client.user.TextureBlob)
 				if err != nil {
-					log.Panicf("Blobstore error: %v", err.String())
+					server.Panicf("Blobstore error: %v", err.String())
 				}
 				userstate.Texture = buf
 			}
@@ -579,7 +605,7 @@ func (server *Server) finishAuthenticate(client *Client) {
 			} else {
 				buf, err := globalBlobstore.Get(client.user.CommentBlob)
 				if err != nil {
-					log.Panicf("Blobstore error: %v", err.String())
+					server.Panicf("Blobstore error: %v", err.String())
 				}
 				userstate.Comment = proto.String(string(buf))
 			}
@@ -677,11 +703,11 @@ func (server *Server) updateCodecVersions() {
 		PreferAlpha: proto.Bool(server.PreferAlphaCodec),
 	})
 	if err != nil {
-		log.Printf("Unable to broadcast.")
+		server.Printf("Unable to broadcast.")
 		return
 	}
 
-	log.Printf("CELT codec switch %#x %#x (PreferAlpha %v)", uint32(server.AlphaCodec), uint32(server.BetaCodec), server.PreferAlphaCodec)
+	server.Printf("CELT codec switch %#x %#x (PreferAlpha %v)", uint32(server.AlphaCodec), uint32(server.BetaCodec), server.PreferAlphaCodec)
 	return
 }
 
@@ -714,7 +740,7 @@ func (server *Server) sendUserList(client *Client) {
 				} else {
 					buf, err := globalBlobstore.Get(connectedClient.user.TextureBlob)
 					if err != nil {
-						log.Panicf("Blobstore error: %v", err.String())
+						server.Panicf("Blobstore error: %v", err.String())
 					}
 					userstate.Texture = buf
 				}
@@ -727,7 +753,7 @@ func (server *Server) sendUserList(client *Client) {
 				} else {
 					buf, err := globalBlobstore.Get(connectedClient.user.CommentBlob)
 					if err != nil {
-						log.Panicf("Blobstore error: %v", err.String())
+						server.Panicf("Blobstore error: %v", err.String())
 					}
 					userstate.Comment = proto.String(string(buf))
 				}
@@ -778,7 +804,7 @@ func (server *Server) sendClientPermissions(client *Client, channel *Channel) {
 	server.HasPermission(client, channel, EnterPermission)
 
 	perm := server.aclcache.GetPermission(client, channel)
-	log.Printf("Permissions = 0x%x", perm)
+	server.Printf("Permissions = 0x%x", perm)
 
 	// fixme(mkrautz): Cache which permissions we've already sent.
 	client.sendProtoMessage(MessagePermissionQuery, &mumbleproto.PermissionQuery{
@@ -834,11 +860,11 @@ func (server *Server) handleIncomingMessage(client *Client, msg *Message) {
 	case MessageCryptSetup:
 		server.handleCryptSetup(msg.client, msg)
 	case MessageContextAction:
-		log.Printf("MessageContextAction from client")
+		server.Printf("MessageContextAction from client")
 	case MessageUserList:
 		server.handleUserList(msg.client, msg)
 	case MessageVoiceTarget:
-		log.Printf("MessageVoiceTarget from client")
+		server.Printf("MessageVoiceTarget from client")
 	case MessagePermissionQuery:
 		server.handlePermissionQuery(msg.client, msg)
 	case MessageUserStats:
@@ -889,7 +915,7 @@ func (server *Server) ListenUDP() {
 
 		udpaddr, ok := remote.(*net.UDPAddr)
 		if !ok {
-			log.Printf("No UDPAddr in read packet. Disabling UDP. (Windows?)")
+			server.Printf("No UDPAddr in read packet. Disabling UDP. (Windows?)")
 			return
 		}
 
@@ -929,7 +955,7 @@ func (server *Server) ListenUDP() {
 			if ok {
 				err = client.crypt.Decrypt(plain[0:], buf[0:nread])
 				if err != nil {
-					log.Panicf("Unable to decrypt incoming packet for client %v (host-port matched)", client)
+					server.Panicf("Unable to decrypt incoming packet for client %v (host-port matched)", client)
 				}
 				match = client
 			} else {
@@ -952,7 +978,7 @@ func (server *Server) ListenUDP() {
 
 			// No client found.
 			if match == nil {
-				log.Printf("Sender of UDP packet could not be determined. Packet dropped.")
+				server.Printf("Sender of UDP packet could not be determined. Packet dropped.")
 				continue
 			}
 
@@ -1001,7 +1027,7 @@ func (s *Server) FreezeServer() io.ReadCloser {
 	if !s.running {
 		fs, err := s.Freeze()
 		if err != nil {
-			log.Panicf("Unable to freeze the server")
+			s.Panicf("Unable to freeze the server")
 		}
 		fr := &freezeRequest{done: make(chan bool)}
 		go s.handleFreezeRequest(fr, &fs)
@@ -1106,7 +1132,7 @@ func (s *Server) ListenAndMurmur() {
 	// Create a new listening TLS socket.
 	cert, err := tls.LoadX509KeyPair(filepath.Join(*datadir, "cert"), filepath.Join(*datadir, "key"))
 	if err != nil {
-		log.Printf("Unable to load x509 key pair: %v", err)
+		s.Printf("Unable to load x509 key pair: %v", err)
 		return
 	}
 
@@ -1120,13 +1146,13 @@ func (s *Server) ListenAndMurmur() {
 		s.port,
 	})
 	if err != nil {
-		log.Printf("Cannot bind: %s\n", err)
+		s.Printf("Cannot bind: %s\n", err)
 		return
 	}
 
 	listener := tls.NewListener(tl, s.tlscfg)
 
-	log.Printf("Created new Murmur instance on port %v", s.port)
+	s.Printf("Created new Murmur instance on port %v", s.port)
 
 	// Update server registration if needed.
 	go func() {
@@ -1142,16 +1168,16 @@ func (s *Server) ListenAndMurmur() {
 		// New client connected
 		conn, err := listener.Accept()
 		if err != nil {
-			log.Printf("Unable to accept() new client.")
+			s.Printf("Unable to accept() new client.")
 		}
 
 		// Create a new client connection from our *tls.Conn
 		// which wraps net.TCPConn.
 		err = s.NewClient(conn)
 		if err != nil {
-			log.Printf("Unable to start new client")
+			s.Printf("Unable to start new client")
 		}
 
-		log.Printf("num clients = %v", len(s.clients))
+		s.Printf("num clients = %v", len(s.clients))
 	}
 }