Adding a Trace log to Connection and removing all other logging directives

This commit is contained in:
Sarah Jamie Lewis 2017-06-27 12:24:04 -07:00
parent f4ed1c244b
commit 1cf7c2b7c7
7 changed files with 46 additions and 35 deletions

View File

@ -13,7 +13,6 @@ import (
"github.com/s-rah/go-ricochet/wire/auth" "github.com/s-rah/go-ricochet/wire/auth"
"github.com/s-rah/go-ricochet/wire/control" "github.com/s-rah/go-ricochet/wire/control"
"io" "io"
"log"
) )
// HiddenServiceAuthChannel wraps implementation of im.ricochet.auth.hidden-service" // HiddenServiceAuthChannel wraps implementation of im.ricochet.auth.hidden-service"
@ -255,7 +254,7 @@ func (ah *HiddenServiceAuthChannel) GenChallenge(clientHostname string, serverHo
key := make([]byte, 32) key := make([]byte, 32)
copy(key[0:16], ah.clientCookie[:]) copy(key[0:16], ah.clientCookie[:])
copy(key[16:], ah.serverCookie[:]) copy(key[16:], ah.serverCookie[:])
log.Printf("CHALLENGE: %s %s %v", clientHostname, serverHostname, key)
value := []byte(clientHostname + serverHostname) value := []byte(clientHostname + serverHostname)
mac := hmac.New(sha256.New, key) mac := hmac.New(sha256.New, key)
mac.Write(value) mac.Write(value)

View File

@ -4,7 +4,6 @@ import (
"crypto/rsa" "crypto/rsa"
"github.com/s-rah/go-ricochet/channels" "github.com/s-rah/go-ricochet/channels"
"github.com/s-rah/go-ricochet/utils" "github.com/s-rah/go-ricochet/utils"
"log"
) )
// AutoConnectionHandler implements the ConnectionHandler interface on behalf of // AutoConnectionHandler implements the ConnectionHandler interface on behalf of
@ -59,7 +58,6 @@ func (ach *AutoConnectionHandler) WaitForAuthenticationEvent() channels.AuthChan
// ClientAuthResult ... // ClientAuthResult ...
func (ach *AutoConnectionHandler) ClientAuthResult(accepted bool, isKnownContact bool) { 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} 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] handler, ok := ach.handlerMap[ctype]
if ok { if ok {
h := handler() h := handler()
log.Printf("Got Channel Handler")
return h, nil return h, nil
} }
return nil, utils.UnknownChannelTypeError return nil, utils.UnknownChannelTypeError

View File

@ -9,6 +9,7 @@ import (
"io" "io"
"log" "log"
"time" "time"
"fmt"
) )
// Connection encapsulates the state required to maintain a connection to // Connection encapsulates the state required to maintain a connection to
@ -29,6 +30,7 @@ type Connection struct {
unlockResponseChannel chan bool unlockResponseChannel chan bool
messageBuilder utils.MessageBuilder messageBuilder utils.MessageBuilder
trace bool
Conn io.ReadWriteCloser Conn io.ReadWriteCloser
IsInbound bool IsInbound bool
@ -74,6 +76,10 @@ func NewOutboundConnection(conn io.ReadWriteCloser, remoteHostname string) *Conn
return rc return rc
} }
func (rc *Connection) TraceLog(enabled bool) {
rc.trace = enabled
}
// start // start
func (rc *Connection) start() { func (rc *Connection) start() {
for { for {
@ -91,11 +97,11 @@ func (rc *Connection) start() {
// use Do() // use Do()
func (rc *Connection) Do(do func() error) error { func (rc *Connection) Do(do func() error) error {
// Force process to soft-break so we can lock // 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 rc.unlockChannel <- true
log.Printf("Unlocked Processloop") rc.traceLog("process loop is unlocked for do()")
ret := do() ret := do()
log.Printf("Giving up lock Processloop") rc.traceLog("giving up lock process loop after do() ")
rc.unlockResponseChannel <- true rc.unlockResponseChannel <- true
return ret 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 // are not met on the local side (a nill error return does not mean the
// channel was opened successfully) // channel was opened successfully)
func (rc *Connection) RequestOpenChannel(ctype string, handler Handler) error { 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 { return rc.Do(func() error {
chandler, err := handler.OnOpenChannelRequest(ctype) chandler, err := handler.OnOpenChannelRequest(ctype)
if err != nil { if err != nil {
rc.traceLog(fmt.Sprintf("failed to reqeust open channel of type %v", err))
return err return err
} }
@ -124,6 +132,7 @@ func (rc *Connection) RequestOpenChannel(ctype string, handler Handler) error {
channel, err := rc.channelManager.OpenChannelRequest(chandler) channel, err := rc.channelManager.OpenChannelRequest(chandler)
if err != nil { if err != nil {
rc.traceLog(fmt.Sprintf("failed to reqeust open channel of type %v", err))
return err return err
} }
@ -139,8 +148,10 @@ func (rc *Connection) RequestOpenChannel(ctype string, handler Handler) error {
} }
response, err := chandler.OpenOutbound(channel) response, err := chandler.OpenOutbound(channel)
if err == nil { if err == nil {
rc.traceLog(fmt.Sprintf("requested open channel of type %s", ctype))
rc.SendRicochetPacket(rc.Conn, 0, response) rc.SendRicochetPacket(rc.Conn, 0, response)
} else { } else {
rc.traceLog(fmt.Sprintf("failed to reqeust open channel of type %v", err))
rc.channelManager.RemoveChannel(channel.ID) rc.channelManager.RemoveChannel(channel.ID)
} }
return nil 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. // Process blocks until the connection is closed or until Break() is called.
// If the connection is closed, a non-nil error is returned. // If the connection is closed, a non-nil error is returned.
func (rc *Connection) Process(handler Handler) error { func (rc *Connection) Process(handler Handler) error {
log.Printf("Entering Processloop") rc.traceLog("entering process loop")
handler.OnReady(rc) handler.OnReady(rc)
breaked := false breaked := false
for !breaked { for !breaked {
@ -169,7 +180,7 @@ func (rc *Connection) Process(handler Handler) error {
<-rc.unlockResponseChannel <-rc.unlockResponseChannel
continue continue
case <-rc.breakChannel: case <-rc.breakChannel:
log.Printf("Process has Ended as Expected!!!") rc.traceLog("process has ended after break")
breaked = true breaked = true
continue continue
case packet = <-rc.packetChannel: case packet = <-rc.packetChannel:
@ -179,13 +190,13 @@ func (rc *Connection) Process(handler Handler) error {
handler.OnClosed(err) handler.OnClosed(err)
return err return err
case <-tick: case <-tick:
log.Printf("timeout") rc.traceLog("peer timed out")
return errors.New("peer timed out") return errors.New("peer timed out")
} }
log.Printf("Received Packet on Channel %d", packet.Channel)
if packet.Channel == 0 { if packet.Channel == 0 {
rc.traceLog(fmt.Sprintf("received control packet on channel %d", packet.Channel))
res := new(Protocol_Data_Control.Packet) res := new(Protocol_Data_Control.Packet)
err := proto.Unmarshal(packet.Data[:], res) err := proto.Unmarshal(packet.Data[:], res)
if err == nil { if err == nil {
@ -196,9 +207,11 @@ func (rc *Connection) Process(handler Handler) error {
channel, found := rc.channelManager.GetChannel(packet.Channel) channel, found := rc.channelManager.GetChannel(packet.Channel)
if found { if found {
if len(packet.Data) == 0 { if len(packet.Data) == 0 {
rc.traceLog(fmt.Sprintf("removing channel %d", packet.Channel))
rc.channelManager.RemoveChannel(packet.Channel) rc.channelManager.RemoveChannel(packet.Channel)
(*channel.Handler).Closed(errors.New("channel closed by peer")) (*channel.Handler).Closed(errors.New("channel closed by peer"))
} else { } else {
rc.traceLog(fmt.Sprintf("received packet on %v channel %d", (*channel.Handler).Type(), packet.Channel))
// Send The Ricochet Packet to the Handler // Send The Ricochet Packet to the Handler
(*channel.Handler).Packet(packet.Data[:]) (*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 // When a non-zero packet is received for an unknown
// channel, the recipient responds by closing // channel, the recipient responds by closing
// that channel. // that channel.
rc.traceLog(fmt.Sprintf("received packet on unknown channel %d. closing.", packet.Channel))
if len(packet.Data) != 0 { if len(packet.Data) != 0 {
rc.SendRicochetPacket(rc.Conn, packet.Channel, []byte{}) 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 // Check that we have the authentication already
if chandler.RequiresAuthentication() != "none" { if chandler.RequiresAuthentication() != "none" {
rc.traceLog(fmt.Sprintf("channel %v requires authorization of type %v", chandler.Type(), chandler.RequiresAuthentication()))
// Enforce Authentication Check. // Enforce Authentication Check.
_, authed := rc.Authentication[chandler.RequiresAuthentication()] _, authed := rc.Authentication[chandler.RequiresAuthentication()]
if !authed { if !authed {
rc.SendRicochetPacket(rc.Conn, 0, []byte{}) rc.SendRicochetPacket(rc.Conn, 0, []byte{})
rc.traceLog(fmt.Sprintf("do not have required authorization to open channel type %v", chandler.Type()))
return return
} }
rc.traceLog("succeeded authorization check")
} }
channel, err := rc.channelManager.OpenChannelRequestFromPeer(opm.GetChannelIdentifier(), chandler) 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) response, err := chandler.OpenInbound(channel, opm)
if err == nil && channel.Pending == false { 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) rc.SendRicochetPacket(rc.Conn, 0, response)
} else { } else {
rc.traceLog(fmt.Sprintf("removing channel %v", channel.ID))
rc.channelManager.RemoveChannel(channel.ID) rc.channelManager.RemoveChannel(channel.ID)
rc.SendRicochetPacket(rc.Conn, 0, []byte{}) rc.SendRicochetPacket(rc.Conn, 0, []byte{})
} }
} else { } else {
// Send Error Packet // Send Error Packet
response := rc.messageBuilder.RejectOpenChannel(opm.GetChannelIdentifier(), "GenericError") 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) 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) channel, found := rc.channelManager.GetChannel(id)
if !found { if !found {
rc.traceLog(fmt.Sprintf("channel result recived for unknown channel: %v", channel.Type, id))
return return
} }
if cr.GetOpened() { if cr.GetOpened() {
rc.traceLog(fmt.Sprintf("channel of type %v opened on %v", channel.Type, id))
(*channel.Handler).OpenOutboundResult(nil, cr) (*channel.Handler).OpenOutboundResult(nil, cr)
} else { } else {
rc.traceLog(fmt.Sprintf("channel of type %v rejected on %v", channel.Type, id))
(*channel.Handler).OpenOutboundResult(errors.New(""), cr) (*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 // XXX Though not currently part of the protocol
// We should likely put these calls behind // We should likely put these calls behind
// authentication. // authentication.
rc.traceLog("received keep alive packet")
if res.GetKeepAlive().GetResponseRequested() { if res.GetKeepAlive().GetResponseRequested() {
messageBuilder := new(utils.MessageBuilder) messageBuilder := new(utils.MessageBuilder)
raw := messageBuilder.KeepAlive(true) raw := messageBuilder.KeepAlive(true)
rc.traceLog("sending keep alive response")
rc.SendRicochetPacket(rc.Conn, 0, raw) rc.SendRicochetPacket(rc.Conn, 0, raw)
} }
} else if res.GetEnableFeatures() != nil { } else if res.GetEnableFeatures() != nil {
// TODO Respond with an Empty List rc.traceLog("received features enabled packet")
messageBuilder := new(utils.MessageBuilder) messageBuilder := new(utils.MessageBuilder)
raw := messageBuilder.FeaturesEnabled([]string{}) raw := messageBuilder.FeaturesEnabled([]string{})
rc.traceLog("sending featured enabled empty response")
rc.SendRicochetPacket(rc.Conn, 0, raw) rc.SendRicochetPacket(rc.Conn, 0, raw)
} else if res.GetFeaturesEnabled() != nil { } else if res.GetFeaturesEnabled() != nil {
// TODO We should never send out an enabled features // TODO We should never send out an enabled features
// request. // 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 // Break causes Process() to return, but does not close the underlying connection
func (rc *Connection) Break() { func (rc *Connection) Break() {
log.Printf("breaking...") rc.traceLog("breaking out of process loop")
rc.breakChannel <- true rc.breakChannel <- true
<-rc.breakResultChannel // Wait for Process to End <-rc.breakResultChannel // Wait for Process to End
} }

View File

@ -21,6 +21,7 @@ func TestProcessAuthAsServer(t *testing.T) {
cconn, _ := net.Dial("tcp", ln.Addr().String()) cconn, _ := net.Dial("tcp", ln.Addr().String())
orc := NewOutboundConnection(cconn, "kwke2hntvyfqm7dr") orc := NewOutboundConnection(cconn, "kwke2hntvyfqm7dr")
orc.TraceLog(true)
privateKey, _ := utils.LoadPrivateKeyFromFile("../testing/private_key") privateKey, _ := utils.LoadPrivateKeyFromFile("../testing/private_key")
known, err := HandleOutboundConnection(orc).ProcessAuthAsClient(privateKey) known, err := HandleOutboundConnection(orc).ProcessAuthAsClient(privateKey)

View File

@ -6,7 +6,6 @@ import (
"github.com/s-rah/go-ricochet/channels" "github.com/s-rah/go-ricochet/channels"
"github.com/s-rah/go-ricochet/utils" "github.com/s-rah/go-ricochet/utils"
"github.com/s-rah/go-ricochet/policies" "github.com/s-rah/go-ricochet/policies"
"log"
) )
// OutboundConnectionHandler is a convieniance wrapper for handling outbound // OutboundConnectionHandler is a convieniance wrapper for handling outbound
@ -48,9 +47,7 @@ func (och *OutboundConnectionHandler) ProcessAuthAsClient(privateKey *rsa.Privat
if err != nil { if err != nil {
return return
} }
log.Printf("waiting for auth result")
result = ach.WaitForAuthenticationEvent() result = ach.WaitForAuthenticationEvent()
log.Printf("received auth result")
och.connection.Break() och.connection.Break()
}() }()

View File

@ -5,7 +5,6 @@ import (
"github.com/s-rah/go-ricochet/connection" "github.com/s-rah/go-ricochet/connection"
"io" "io"
"net" "net"
"log"
) )
// Open establishes a protocol session on an established net.Conn, and returns a new // Open establishes a protocol session on an established net.Conn, and returns a new
// OpenConnection instance representing this connection. On error, the connection // OpenConnection instance representing this connection. On error, the connection
@ -14,20 +13,17 @@ import (
// handling protocol messages. // handling protocol messages.
func Open(remoteHostname string) (*connection.Connection, error) { func Open(remoteHostname string) (*connection.Connection, error) {
networkResolver := utils.NetworkResolver{} networkResolver := utils.NetworkResolver{}
log.Printf("Connecting...")
conn, remoteHostname, err := networkResolver.Resolve(remoteHostname) conn, remoteHostname, err := networkResolver.Resolve(remoteHostname)
if err != nil { if err != nil {
return nil, err return nil, err
} }
log.Printf("Connected...negotiating version")
rc, err := negotiateVersion(conn, remoteHostname) rc, err := negotiateVersion(conn, remoteHostname)
if err != nil { if err != nil {
conn.Close() conn.Close()
return nil, err return nil, err
} }
log.Printf("Connected...negotiated version")
return rc, nil return rc, nil
} }

View File

@ -2,7 +2,6 @@ package utils
import ( import (
"fmt" "fmt"
"log"
) )
// Error captures various common ricochet errors // Error captures various common ricochet errors
@ -26,19 +25,9 @@ const (
ClientFailedToAuthenticateError = Error("ClientFailedToAuthenticateError") 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 // 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 // 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. // should only happen if there was a bug in the underlying library.