From 1cf7c2b7c7a27cfd0c535a137bea6fc1c78ff3e0 Mon Sep 17 00:00:00 2001 From: Sarah Jamie Lewis Date: Tue, 27 Jun 2017 12:24:04 -0700 Subject: [PATCH] Adding a Trace log to Connection and removing all other logging directives --- channels/hiddenserviceauthchannel.go | 3 +- connection/autoconnectionhandler.go | 3 -- connection/connection.go | 54 ++++++++++++++++++++----- connection/connection_test.go | 1 + connection/outboundconnectionhandler.go | 3 -- ricochet.go | 4 -- utils/error.go | 13 +----- 7 files changed, 46 insertions(+), 35 deletions(-) diff --git a/channels/hiddenserviceauthchannel.go b/channels/hiddenserviceauthchannel.go index e62f7d3..a614d63 100644 --- a/channels/hiddenserviceauthchannel.go +++ b/channels/hiddenserviceauthchannel.go @@ -13,7 +13,6 @@ import ( "github.com/s-rah/go-ricochet/wire/auth" "github.com/s-rah/go-ricochet/wire/control" "io" - "log" ) // HiddenServiceAuthChannel wraps implementation of im.ricochet.auth.hidden-service" @@ -255,7 +254,7 @@ func (ah *HiddenServiceAuthChannel) GenChallenge(clientHostname string, serverHo key := make([]byte, 32) copy(key[0:16], ah.clientCookie[:]) copy(key[16:], ah.serverCookie[:]) - log.Printf("CHALLENGE: %s %s %v", clientHostname, serverHostname, key) + value := []byte(clientHostname + serverHostname) mac := hmac.New(sha256.New, key) mac.Write(value) diff --git a/connection/autoconnectionhandler.go b/connection/autoconnectionhandler.go index 11a5ba6..42a8a9e 100644 --- a/connection/autoconnectionhandler.go +++ b/connection/autoconnectionhandler.go @@ -4,7 +4,6 @@ import ( "crypto/rsa" "github.com/s-rah/go-ricochet/channels" "github.com/s-rah/go-ricochet/utils" - "log" ) // AutoConnectionHandler implements the ConnectionHandler interface on behalf of @@ -59,7 +58,6 @@ func (ach *AutoConnectionHandler) WaitForAuthenticationEvent() channels.AuthChan // ClientAuthResult ... func (ach *AutoConnectionHandler) ClientAuthResult(accepted bool, isKnownContact bool) { - log.Printf("Got auth result %v %v", accepted, isKnownContact) ach.authResultChannel <- channels.AuthChannelResult{Accepted: accepted, IsKnownContact: isKnownContact} } @@ -89,7 +87,6 @@ func (ach *AutoConnectionHandler) OnOpenChannelRequest(ctype string) (channels.H handler, ok := ach.handlerMap[ctype] if ok { h := handler() - log.Printf("Got Channel Handler") return h, nil } return nil, utils.UnknownChannelTypeError diff --git a/connection/connection.go b/connection/connection.go index 398c063..6d05373 100644 --- a/connection/connection.go +++ b/connection/connection.go @@ -9,6 +9,7 @@ import ( "io" "log" "time" + "fmt" ) // Connection encapsulates the state required to maintain a connection to @@ -29,6 +30,7 @@ type Connection struct { unlockResponseChannel chan bool messageBuilder utils.MessageBuilder + trace bool Conn io.ReadWriteCloser IsInbound bool @@ -74,6 +76,10 @@ func NewOutboundConnection(conn io.ReadWriteCloser, remoteHostname string) *Conn return rc } +func (rc *Connection) TraceLog(enabled bool) { + rc.trace = enabled +} + // start func (rc *Connection) start() { for { @@ -91,11 +97,11 @@ func (rc *Connection) start() { // use Do() func (rc *Connection) Do(do func() error) error { // Force process to soft-break so we can lock - log.Printf("UnLocking Processloop") + rc.traceLog("request unlocking of process loop for do()") rc.unlockChannel <- true - log.Printf("Unlocked Processloop") + rc.traceLog("process loop is unlocked for do()") ret := do() - log.Printf("Giving up lock Processloop") + rc.traceLog("giving up lock process loop after do() ") rc.unlockResponseChannel <- true return ret } @@ -105,10 +111,12 @@ func (rc *Connection) Do(do func() error) error { // are not met on the local side (a nill error return does not mean the // channel was opened successfully) func (rc *Connection) RequestOpenChannel(ctype string, handler Handler) error { + rc.traceLog(fmt.Sprintf("requesting open channel of type %s", ctype)) return rc.Do(func() error { chandler, err := handler.OnOpenChannelRequest(ctype) if err != nil { + rc.traceLog(fmt.Sprintf("failed to reqeust open channel of type %v", err)) return err } @@ -124,6 +132,7 @@ func (rc *Connection) RequestOpenChannel(ctype string, handler Handler) error { channel, err := rc.channelManager.OpenChannelRequest(chandler) if err != nil { + rc.traceLog(fmt.Sprintf("failed to reqeust open channel of type %v", err)) return err } @@ -139,8 +148,10 @@ func (rc *Connection) RequestOpenChannel(ctype string, handler Handler) error { } response, err := chandler.OpenOutbound(channel) if err == nil { + rc.traceLog(fmt.Sprintf("requested open channel of type %s", ctype)) rc.SendRicochetPacket(rc.Conn, 0, response) } else { + rc.traceLog(fmt.Sprintf("failed to reqeust open channel of type %v", err)) rc.channelManager.RemoveChannel(channel.ID) } return nil @@ -157,7 +168,7 @@ func (rc *Connection) RequestOpenChannel(ctype string, handler Handler) error { // Process blocks until the connection is closed or until Break() is called. // If the connection is closed, a non-nil error is returned. func (rc *Connection) Process(handler Handler) error { - log.Printf("Entering Processloop") + rc.traceLog("entering process loop") handler.OnReady(rc) breaked := false for !breaked { @@ -169,7 +180,7 @@ func (rc *Connection) Process(handler Handler) error { <-rc.unlockResponseChannel continue case <-rc.breakChannel: - log.Printf("Process has Ended as Expected!!!") + rc.traceLog("process has ended after break") breaked = true continue case packet = <-rc.packetChannel: @@ -179,13 +190,13 @@ func (rc *Connection) Process(handler Handler) error { handler.OnClosed(err) return err case <-tick: - log.Printf("timeout") + rc.traceLog("peer timed out") return errors.New("peer timed out") } - log.Printf("Received Packet on Channel %d", packet.Channel) - + if packet.Channel == 0 { + rc.traceLog(fmt.Sprintf("received control packet on channel %d", packet.Channel)) res := new(Protocol_Data_Control.Packet) err := proto.Unmarshal(packet.Data[:], res) if err == nil { @@ -196,9 +207,11 @@ func (rc *Connection) Process(handler Handler) error { channel, found := rc.channelManager.GetChannel(packet.Channel) if found { if len(packet.Data) == 0 { + rc.traceLog(fmt.Sprintf("removing channel %d", packet.Channel)) rc.channelManager.RemoveChannel(packet.Channel) (*channel.Handler).Closed(errors.New("channel closed by peer")) } else { + rc.traceLog(fmt.Sprintf("received packet on %v channel %d", (*channel.Handler).Type(), packet.Channel)) // Send The Ricochet Packet to the Handler (*channel.Handler).Packet(packet.Data[:]) } @@ -206,6 +219,7 @@ func (rc *Connection) Process(handler Handler) error { // When a non-zero packet is received for an unknown // channel, the recipient responds by closing // that channel. + rc.traceLog(fmt.Sprintf("received packet on unknown channel %d. closing.", packet.Channel)) if len(packet.Data) != 0 { rc.SendRicochetPacket(rc.Conn, packet.Channel, []byte{}) } @@ -234,12 +248,15 @@ func (rc *Connection) controlPacket(handler Handler, res *Protocol_Data_Control. // Check that we have the authentication already if chandler.RequiresAuthentication() != "none" { + rc.traceLog(fmt.Sprintf("channel %v requires authorization of type %v", chandler.Type(), chandler.RequiresAuthentication())) // Enforce Authentication Check. _, authed := rc.Authentication[chandler.RequiresAuthentication()] if !authed { rc.SendRicochetPacket(rc.Conn, 0, []byte{}) + rc.traceLog(fmt.Sprintf("do not have required authorization to open channel type %v", chandler.Type())) return } + rc.traceLog("succeeded authorization check") } channel, err := rc.channelManager.OpenChannelRequestFromPeer(opm.GetChannelIdentifier(), chandler) @@ -259,15 +276,17 @@ func (rc *Connection) controlPacket(handler Handler, res *Protocol_Data_Control. response, err := chandler.OpenInbound(channel, opm) if err == nil && channel.Pending == false { - log.Printf("Opening Channel %v on %v", channel.Type, channel.ID) + rc.traceLog(fmt.Sprintf("opening channel %v on %v", channel.Type, channel.ID)) rc.SendRicochetPacket(rc.Conn, 0, response) } else { + rc.traceLog(fmt.Sprintf("removing channel %v", channel.ID)) rc.channelManager.RemoveChannel(channel.ID) rc.SendRicochetPacket(rc.Conn, 0, []byte{}) } } else { // Send Error Packet response := rc.messageBuilder.RejectOpenChannel(opm.GetChannelIdentifier(), "GenericError") + rc.traceLog(fmt.Sprintf("sending reject open channel for %v", opm.GetChannelIdentifier())) rc.SendRicochetPacket(rc.Conn, 0, response) } @@ -278,12 +297,15 @@ func (rc *Connection) controlPacket(handler Handler, res *Protocol_Data_Control. channel, found := rc.channelManager.GetChannel(id) if !found { + rc.traceLog(fmt.Sprintf("channel result recived for unknown channel: %v", channel.Type, id)) return } if cr.GetOpened() { + rc.traceLog(fmt.Sprintf("channel of type %v opened on %v", channel.Type, id)) (*channel.Handler).OpenOutboundResult(nil, cr) } else { + rc.traceLog(fmt.Sprintf("channel of type %v rejected on %v", channel.Type, id)) (*channel.Handler).OpenOutboundResult(errors.New(""), cr) } @@ -291,25 +313,35 @@ func (rc *Connection) controlPacket(handler Handler, res *Protocol_Data_Control. // XXX Though not currently part of the protocol // We should likely put these calls behind // authentication. + rc.traceLog("received keep alive packet") if res.GetKeepAlive().GetResponseRequested() { messageBuilder := new(utils.MessageBuilder) raw := messageBuilder.KeepAlive(true) + rc.traceLog("sending keep alive response") rc.SendRicochetPacket(rc.Conn, 0, raw) } } else if res.GetEnableFeatures() != nil { - // TODO Respond with an Empty List + rc.traceLog("received features enabled packet") messageBuilder := new(utils.MessageBuilder) raw := messageBuilder.FeaturesEnabled([]string{}) + rc.traceLog("sending featured enabled empty response") rc.SendRicochetPacket(rc.Conn, 0, raw) } else if res.GetFeaturesEnabled() != nil { // TODO We should never send out an enabled features // request. + rc.traceLog("sending unsolicited features enabled response") } } +func (rc *Connection) traceLog(message string) { + if rc.trace { + log.Printf(message) + } +} + // Break causes Process() to return, but does not close the underlying connection func (rc *Connection) Break() { - log.Printf("breaking...") + rc.traceLog("breaking out of process loop") rc.breakChannel <- true <-rc.breakResultChannel // Wait for Process to End } diff --git a/connection/connection_test.go b/connection/connection_test.go index 9b979fd..61b9356 100644 --- a/connection/connection_test.go +++ b/connection/connection_test.go @@ -21,6 +21,7 @@ func TestProcessAuthAsServer(t *testing.T) { cconn, _ := net.Dial("tcp", ln.Addr().String()) orc := NewOutboundConnection(cconn, "kwke2hntvyfqm7dr") + orc.TraceLog(true) privateKey, _ := utils.LoadPrivateKeyFromFile("../testing/private_key") known, err := HandleOutboundConnection(orc).ProcessAuthAsClient(privateKey) diff --git a/connection/outboundconnectionhandler.go b/connection/outboundconnectionhandler.go index 3e1fb38..e6998c2 100644 --- a/connection/outboundconnectionhandler.go +++ b/connection/outboundconnectionhandler.go @@ -6,7 +6,6 @@ import ( "github.com/s-rah/go-ricochet/channels" "github.com/s-rah/go-ricochet/utils" "github.com/s-rah/go-ricochet/policies" - "log" ) // OutboundConnectionHandler is a convieniance wrapper for handling outbound @@ -48,9 +47,7 @@ func (och *OutboundConnectionHandler) ProcessAuthAsClient(privateKey *rsa.Privat if err != nil { return } - log.Printf("waiting for auth result") result = ach.WaitForAuthenticationEvent() - log.Printf("received auth result") och.connection.Break() }() diff --git a/ricochet.go b/ricochet.go index 257127c..36c80bd 100644 --- a/ricochet.go +++ b/ricochet.go @@ -5,7 +5,6 @@ import ( "github.com/s-rah/go-ricochet/connection" "io" "net" - "log" ) // Open establishes a protocol session on an established net.Conn, and returns a new // OpenConnection instance representing this connection. On error, the connection @@ -14,20 +13,17 @@ import ( // handling protocol messages. func Open(remoteHostname string) (*connection.Connection, error) { networkResolver := utils.NetworkResolver{} - log.Printf("Connecting...") conn, remoteHostname, err := networkResolver.Resolve(remoteHostname) if err != nil { return nil, err } - log.Printf("Connected...negotiating version") rc, err := negotiateVersion(conn, remoteHostname) if err != nil { conn.Close() return nil, err } - log.Printf("Connected...negotiated version") return rc, nil } diff --git a/utils/error.go b/utils/error.go index beaba0f..bd2f869 100644 --- a/utils/error.go +++ b/utils/error.go @@ -2,7 +2,6 @@ package utils import ( "fmt" - "log" ) // Error captures various common ricochet errors @@ -26,19 +25,9 @@ const ( ClientFailedToAuthenticateError = Error("ClientFailedToAuthenticateError") - PrivateKeyNotSetError = Error("PrivateKeyNotSetError") + PrivateKeyNotSetError = Error("ClientFailedToAuthenticateError") ) -// RecoverFromError doesn't really recover from anything....see comment below -func RecoverFromError() { - if r := recover(); r != nil { - // This should only really happen if there is a failure de/serializing. If - // this does happen then we currently error. In the future we might be - // able to make this nicer. - log.Fatalf("Recovered from panic() - this really shouldn't happen. Reason: %v", r) - } -} - // CheckError is a helper function for panicing on errors which we need to handle // but should be very rare e.g. failures deserializing a protobuf object that // should only happen if there was a bug in the underlying library.