diff --git a/client.go b/client.go index fa33575..6fe5786 100644 --- a/client.go +++ b/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 } diff --git a/grumble.go b/grumble.go index 77f0719..476d816 100644 --- a/grumble.go +++ b/grumble.go @@ -76,6 +76,7 @@ func main() { return } + log.SetPrefix("[G] ") log.Printf("Grumble - Mumble server written in Go") if len(*datadir) == 0 { diff --git a/message.go b/message.go index 7b69037..01e3789 100644 --- a/message.go +++ b/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)) diff --git a/register.go b/register.go index 0f3ec50..d7e303b 100644 --- a/register.go +++ b/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 } }() diff --git a/server.go b/server.go index 8e25bc8..ef5b6ee 100644 --- a/server.go +++ b/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)) } }