diff --git a/application/application.go b/application/application.go index 859f358..96181c2 100644 --- a/application/application.go +++ b/application/application.go @@ -6,7 +6,7 @@ import ( "git.openprivacy.ca/openprivacy/libricochet-go/connection" "git.openprivacy.ca/openprivacy/libricochet-go/connectivity" "git.openprivacy.ca/openprivacy/libricochet-go/identity" - "log" + "git.openprivacy.ca/openprivacy/libricochet-go/log" "net" "sync" ) @@ -42,7 +42,7 @@ func (ra *RicochetApplication) Init(acn connectivity.ACN, name string, v3identit func (ra *RicochetApplication) handleConnection(conn net.Conn) { rc, err := goricochet.NegotiateVersionInbound(conn) if err != nil { - log.Printf("There was an error") + log.Errorln("There was an error") conn.Close() return } @@ -52,12 +52,11 @@ func (ra *RicochetApplication) handleConnection(conn net.Conn) { err = ich.ProcessAuthAsV3Server(ra.v3identity, ra.contactManager.LookupContactV3) if err != nil { - log.Printf("There was an error authenticating the connection: %v", err) + log.Errorf("There was an error authenticating the connection: %v", err) conn.Close() return } - rc.TraceLog(true) rai := ra.aif.GetApplicationInstance(rc) ra.lock.Lock() ra.instances = append(ra.instances, rai) @@ -82,12 +81,11 @@ func (ra *RicochetApplication) HandleApplicationInstance(rai *ApplicationInstanc ra.lock.Unlock() } -// Open a connection to another Ricochet peer at onionAddress. If they are unknown to use, use requestMessage (otherwise can be blank) +// Open a connection to another Ricochet peer at onionAddress. Infof they are unknown to use, use requestMessage (otherwise can be blank) func (ra *RicochetApplication) Open(onionAddress string, requestMessage string) (*ApplicationInstance, error) { rc, err := goricochet.Open(ra.acn, onionAddress) - rc.TraceLog(true) if err != nil { - log.Printf("Error in application.Open(): %v\n", err) + log.Errorf("Error in application.Open(): %v\n", err) return nil, err } @@ -96,7 +94,7 @@ func (ra *RicochetApplication) Open(onionAddress string, requestMessage string) known, err := och.ProcessAuthAsV3Client(ra.v3identity) if err != nil { - log.Printf("There was an error authenticating the connection: %v", err) + log.Errorf("There was an error authenticating the connection: %v", err) return nil, err } rai := ra.aif.GetApplicationInstance(rc) @@ -113,7 +111,7 @@ func (ra *RicochetApplication) Open(onionAddress string, requestMessage string) return err }) if err != nil { - log.Printf("could not contact %s", err) + log.Errorf("could not contact %s", err) } } ra.HandleApplicationInstance(rai) diff --git a/application/examples/echobot/main.go b/application/examples/echobot/main.go index dbbd600..017fea6 100644 --- a/application/examples/echobot/main.go +++ b/application/examples/echobot/main.go @@ -7,11 +7,12 @@ import ( "git.openprivacy.ca/openprivacy/libricochet-go/channels" "git.openprivacy.ca/openprivacy/libricochet-go/connection" "git.openprivacy.ca/openprivacy/libricochet-go/identity" - "log" + "git.openprivacy.ca/openprivacy/libricochet-go/log" "time" "git.openprivacy.ca/openprivacy/libricochet-go/connectivity" "golang.org/x/crypto/ed25519" + "os" ) type EchoBotInstance struct { @@ -26,7 +27,7 @@ func (ebi *EchoBotInstance) Init(rai *application.ApplicationInstance, ra *appli // We always want bidirectional chat channels func (ebi *EchoBotInstance) OpenInbound() { - log.Println("OpenInbound() ChatChannel handler called...") + log.Degubln("OpenInbound() ChatChannel handler called...") outboutChatChannel := ebi.rai.Connection.Channel("im.ricochet.chat", channels.Outbound) if outboutChatChannel == nil { ebi.rai.Connection.Do(func() error { @@ -40,7 +41,7 @@ func (ebi *EchoBotInstance) OpenInbound() { } func (ebi *EchoBotInstance) ChatMessage(messageID uint32, when time.Time, message string) bool { - log.Printf("message from %v - %v", ebi.rai.RemoteHostname, message) + log.Infof("message from %v - %v", ebi.rai.RemoteHostname, message) ebi.SendChatMessage(ebi.rai, ebi.rai.RemoteHostname+" "+message) return true } @@ -66,20 +67,24 @@ func main() { //////////// // SERVER // //////////// + log.SetLevel(log.LevelInfo) + log.AddEverythingFromPattern("connectivity") echobot := new(application.RicochetApplication) cpubk, cprivk, err := ed25519.GenerateKey(rand.Reader) acn, err := connectivity.StartTor(".", "") if err != nil { - log.Panicf("Unable to start Tor: %v", err) + log.Errorf("Unable to start Tor: %v", err) + os.Exit(1) } defer acn.Close() listenService, err := acn.Listen(cprivk, application.RicochetPort) if err != nil { - log.Fatalf("error setting up onion service: %v", err) + log.Errorf("error setting up onion service: %v", err) + os.Exit(1) } af := application.ApplicationInstanceFactory{} @@ -95,10 +100,10 @@ func main() { }) echobot.Init(acn, "echobot", identity.InitializeV3("echobot", &cprivk, &cpubk), af, new(application.AcceptAllContactManager)) - log.Printf("echobot listening on %s", listenService.AddressFull()) + log.Infof("echobot listening on %v", listenService.AddressFull()) go echobot.Run(listenService) - log.Printf("counting to five ...") + log.Infoln("counting to five ...") time.Sleep(time.Second * 5) //////////// @@ -121,18 +126,20 @@ func NewAliceBot(acn connectivity.ACN, onion string) alicebot { var err error alice.pub, alice.priv, err = ed25519.GenerateKey(rand.Reader) if err != nil { - log.Fatalf("[alice] error generating key: %v", err) + log.Errorf("[alice] error generating key: %v", err) + os.Exit(1) } rc, err := goricochet.Open(acn, onion) if err != nil { - log.Fatalf("[alice] error connecting to echobot: %v", err) + log.Errorf("[alice] error connecting to echobot: %v", err) + os.Exit(1) } - rc.TraceLog(false) _, err = connection.HandleOutboundConnection(rc).ProcessAuthAsV3Client(identity.InitializeV3("alice", &alice.priv, &alice.pub)) if err != nil { - log.Fatalf("[alice] failed to authenticate connection: %v", err) + log.Errorf("[alice] failed to authenticate connection: %v", err) + os.Exit(1) } alice.rc = rc @@ -148,14 +155,15 @@ func NewAliceBot(acn connectivity.ACN, onion string) alicebot { go alice.rc.Process(&ach) - log.Printf("[alice] requesting channel...") + log.Infof("[alice] requesting channel...") alice.rc.Do(func() error { chatchannel := channels.ChatChannel{} chatchannel.Handler = &alice _, err := alice.rc.RequestOpenChannel("im.ricochet.chat", &chatchannel) if err != nil { - log.Fatalf("failed requestopenchannel: %v", err) + log.Errorf("failed requestopenchannel: %v", err) + os.Exit(1) } return nil }) @@ -172,33 +180,35 @@ type alicebot struct { } func (this *alicebot) SendMessage(message string) { - log.Printf("[alice] sending...") + log.Infof("[alice] sending...") this.rc.Do(func() error { channel := this.rc.Channel("im.ricochet.chat", channels.Outbound) if channel != nil { peerchannel, ok := channel.Handler.(*channels.ChatChannel) if ok { - log.Printf("[alice] sending '%s' to echobot", message) + log.Infof("[alice] sending '%s' to echobot", message) this.messages[peerchannel.SendMessage(message)] = message } else { - log.Fatalf("couldn't cast channel:") + log.Errorf("couldn't cast channel:") + os.Exit(1) } } else { - log.Fatalf("couldn't create channel") + log.Errorf("couldn't create channel") + os.Exit(1) } return nil }) } func (this *alicebot) OpenInbound() { - log.Printf("[alice] inbound connection established") + log.Infof("[alice] inbound connection established") } func (this *alicebot) ChatMessage(messageID uint32, when time.Time, message string) bool { - log.Printf("[alice] got message from echobot: %s", message) + log.Infof("[alice] got message from echobot: %s", message) return true } func (this *alicebot) ChatMessageAck(messageID uint32, accepted bool) { - log.Printf("[alice] message \"%s\" ack'd", this.messages[messageID]) + log.Infof("[alice] message \"%s\" ack'd", this.messages[messageID]) } diff --git a/application/examples/v3/main.go b/application/examples/v3/main.go index 88d47a2..d9faf1e 100644 --- a/application/examples/v3/main.go +++ b/application/examples/v3/main.go @@ -4,19 +4,22 @@ import ( "crypto/rand" "encoding/base32" "git.openprivacy.ca/openprivacy/libricochet-go/application" + "git.openprivacy.ca/openprivacy/libricochet-go/log" "git.openprivacy.ca/openprivacy/libricochet-go/utils" "golang.org/x/crypto/ed25519" - "log" "strings" "git.openprivacy.ca/openprivacy/libricochet-go/connectivity" + "os" ) // An example of how to setup a v3 onion service in go func main() { + log.SetLevel(log.LevelInfo) tm, err := connectivity.StartTor(".", "") if err != nil { - log.Panicf("Unable to start Tor: %v", err) + log.Errorf("Unable to start Tor: %v", err) + os.Exit(1) } defer tm.Close() @@ -24,8 +27,8 @@ func main() { onion, err := tm.Listen(cprivk, application.RicochetPort) utils.CheckError(err) defer onion.Close() - log.Printf("Got Listener %v", onion.AddressFull()) + log.Infof("Got Listener %v", onion.AddressFull()) decodedPub, err := base32.StdEncoding.DecodeString(strings.ToUpper(onion.AddressIdentity())) - log.Printf("Decoded Public Key: %x %v", decodedPub[:32], err) - log.Printf("ed25519 Public Key: %x", cpubk) + log.Infof("Decoded Public Key: %x %v", decodedPub[:32], err) + log.Infof("ed25519 Public Key: %x", cpubk) } diff --git a/channels/v3/inbound/3dhauthchannel.go b/channels/v3/inbound/3dhauthchannel.go index 49e0bc8..3ccbd0a 100644 --- a/channels/v3/inbound/3dhauthchannel.go +++ b/channels/v3/inbound/3dhauthchannel.go @@ -5,6 +5,7 @@ import ( "errors" "git.openprivacy.ca/openprivacy/libricochet-go/channels" "git.openprivacy.ca/openprivacy/libricochet-go/identity" + "git.openprivacy.ca/openprivacy/libricochet-go/log" "git.openprivacy.ca/openprivacy/libricochet-go/utils" "git.openprivacy.ca/openprivacy/libricochet-go/wire/auth/3edh" "git.openprivacy.ca/openprivacy/libricochet-go/wire/control" @@ -13,7 +14,6 @@ import ( "golang.org/x/crypto/nacl/secretbox" "golang.org/x/crypto/pbkdf2" "golang.org/x/crypto/sha3" - "log" ) // Server3DHAuthChannel wraps implementation of im.ricochet.auth.hidden-service" @@ -62,7 +62,7 @@ func (ah *Server3DHAuthChannel) Closed(err error) { } // OpenInbound is the first method called for an inbound channel request. -// If an error is returned, the channel is rejected. If a RawMessage is +// Infof an error is returned, the channel is rejected. Infof a RawMessage is // returned, it will be sent as the ChannelResult message. // Remote -> [Open Authentication Channel] -> Local func (ah *Server3DHAuthChannel) OpenInbound(channel *channels.Channel, oc *Protocol_Data_Control.OpenChannel) ([]byte, error) { @@ -76,7 +76,7 @@ func (ah *Server3DHAuthChannel) OpenInbound(channel *channels.Channel, oc *Proto ah.clientEphmeralPublicKey = ed25519.PublicKey(clientEphmeralPublicKeyBytes[:]) clientHostname := utils.GetTorV3Hostname(clientPubKeyBytes) - log.Printf("Received inbound auth 3DH request from %v", clientHostname) + log.Debugf("Received inbound auth 3DH request from %v", clientHostname) // Generate Ephemeral Keys pubkey, privkey, _ := ed25519.GenerateKey(rand.Reader) @@ -93,7 +93,7 @@ func (ah *Server3DHAuthChannel) OpenInbound(channel *channels.Channel, oc *Proto } // OpenOutbound is the first method called for an outbound channel request. -// If an error is returned, the channel is not opened. If a RawMessage is +// Infof an error is returned, the channel is not opened. Infof a RawMessage is // returned, it will be sent as the OpenChannel message. // Local -> [Open Authentication Channel] -> Remote func (ah *Server3DHAuthChannel) OpenOutbound(channel *channels.Channel) ([]byte, error) { @@ -101,7 +101,7 @@ func (ah *Server3DHAuthChannel) OpenOutbound(channel *channels.Channel) ([]byte, } // OpenOutboundResult is called when a response is received for an -// outbound OpenChannel request. If `err` is non-nil, the channel was +// outbound OpenChannel request. Infof `err` is non-nil, the channel was // rejected and Closed will be called immediately afterwards. `raw` // contains the raw protocol message including any extension data. // Input: Remote -> [ChannelResult] -> {Client} @@ -152,7 +152,7 @@ func (ah *Server3DHAuthChannel) Packet(data []byte) { if ok && string(decrypted) == "Hello World" { allowed, known := ah.ServerAuthValid(utils.GetTorV3Hostname(ah.clientPubKey), ah.clientPubKey) ah.channel.DelegateAuthorization() - log.Printf("3DH Session Decrypted OK. Authenticating Connection!") + log.Debugf("3DH Session Decrypted OK. Authenticating Connection!") messageBuilder := new(utils.MessageBuilder) result := messageBuilder.AuthResult3DH(allowed, known) ah.channel.SendMessage(result) diff --git a/channels/v3/outbound/3dhauthchannel.go b/channels/v3/outbound/3dhauthchannel.go index 93c3388..b0bc661 100644 --- a/channels/v3/outbound/3dhauthchannel.go +++ b/channels/v3/outbound/3dhauthchannel.go @@ -5,6 +5,7 @@ import ( "errors" "git.openprivacy.ca/openprivacy/libricochet-go/channels" "git.openprivacy.ca/openprivacy/libricochet-go/identity" + "git.openprivacy.ca/openprivacy/libricochet-go/log" "git.openprivacy.ca/openprivacy/libricochet-go/utils" "git.openprivacy.ca/openprivacy/libricochet-go/wire/auth/3edh" "git.openprivacy.ca/openprivacy/libricochet-go/wire/control" @@ -14,7 +15,6 @@ import ( "golang.org/x/crypto/pbkdf2" "golang.org/x/crypto/sha3" "io" - "log" ) // Client3DHAuthChannel wraps implementation of im.ricochet.auth.hidden-service" @@ -60,7 +60,7 @@ func (ah *Client3DHAuthChannel) Closed(err error) { } // OpenInbound is the first method called for an inbound channel request. -// If an error is returned, the channel is rejected. If a RawMessage is +// Infof an error is returned, the channel is rejected. Infof a RawMessage is // returned, it will be sent as the ChannelResult message. // Remote -> [Open Authentication Channel] -> Local func (ah *Client3DHAuthChannel) OpenInbound(channel *channels.Channel, oc *Protocol_Data_Control.OpenChannel) ([]byte, error) { @@ -68,13 +68,13 @@ func (ah *Client3DHAuthChannel) OpenInbound(channel *channels.Channel, oc *Proto } // OpenOutbound is the first method called for an outbound channel request. -// If an error is returned, the channel is not opened. If a RawMessage is +// Infof an error is returned, the channel is not opened. Infof a RawMessage is // returned, it will be sent as the OpenChannel message. // Local -> [Open Authentication Channel] -> Remote func (ah *Client3DHAuthChannel) OpenOutbound(channel *channels.Channel) ([]byte, error) { ah.channel = channel - log.Printf("Opening an outbound connection to %v", ah.ServerHostname) + log.Debugf("Opening an outbound connection to %v", ah.ServerHostname) // Generate Ephemeral Keys pubkey, privkey, _ := ed25519.GenerateKey(rand.Reader) @@ -92,7 +92,7 @@ func (ah *Client3DHAuthChannel) OpenOutbound(channel *channels.Channel) ([]byte, } // OpenOutboundResult is called when a response is received for an -// outbound OpenChannel request. If `err` is non-nil, the channel was +// outbound OpenChannel request. Infof `err` is non-nil, the channel was // rejected and Closed will be called immediately afterwards. `raw` // contains the raw protocol message including any extension data. // Input: Remote -> [ChannelResult] -> {Client} @@ -113,7 +113,7 @@ func (ah *Client3DHAuthChannel) OpenOutboundResult(err error, crm *Protocol_Data serverEphmeralPublicKeyBytes := serverEphemeralPublicKey.([]byte) ah.serverEphemeralPublicKey = ed25519.PublicKey(serverEphmeralPublicKeyBytes[:]) - log.Printf("Public Keys Exchanged. Deriving Encryption Keys and Sending Encrypted Test Message") + log.Debugf("Public Keys Exchanged. Deriving Encryption Keys and Sending Encrypted Test Message") // Server Ephemeral <-> Client Identity secret1 := utils.EDH(ah.clientEphemeralPrivateKey, ah.serverPubKey) @@ -159,7 +159,7 @@ func (ah *Client3DHAuthChannel) Packet(data []byte) { if res.GetResult() != nil { ah.ClientAuthResult(res.GetResult().GetAccepted(), res.GetResult().GetIsKnownContact()) if res.GetResult().GetAccepted() { - log.Printf("3DH Session Accepted OK. Authenticated! Connection!") + log.Debugf("3DH Session Accepted OK. Authenticated! Connection!") ah.channel.DelegateAuthorization() } return diff --git a/connection/connection.go b/connection/connection.go index 4b0f747..ed3b9e7 100644 --- a/connection/connection.go +++ b/connection/connection.go @@ -4,11 +4,11 @@ import ( "context" "fmt" "git.openprivacy.ca/openprivacy/libricochet-go/channels" + "git.openprivacy.ca/openprivacy/libricochet-go/log" "git.openprivacy.ca/openprivacy/libricochet-go/utils" "git.openprivacy.ca/openprivacy/libricochet-go/wire/control" "github.com/golang/protobuf/proto" "io" - "log" "sync" ) @@ -31,7 +31,6 @@ type Connection struct { unlockResponseChannel chan bool messageBuilder utils.MessageBuilder - trace bool closed bool closing bool @@ -88,13 +87,6 @@ func NewOutboundConnection(conn io.ReadWriteCloser, remoteHostname string) *Conn return rc } -// TraceLog turns on debug logging, you shouldn't need to do this but if for some -// reason ricochet isn't working, you can use this to see at what point in the -// protcol trace ricochet is failing. -func (rc *Connection) TraceLog(enabled bool) { - rc.trace = enabled -} - // start func (rc *Connection) start() { for { @@ -146,11 +138,11 @@ func (rc *Connection) Do(do func() error) error { } // Force process to soft-break so we can lock - rc.traceLog("request unlocking of process loop for do()") + log.Degubln("request unlocking of process loop for do()") rc.unlockChannel <- true - rc.traceLog("process loop is unlocked for do()") + log.Degubln("process loop is unlocked for do()") defer func() { - rc.traceLog("giving up lock process loop after do() ") + log.Degubln("giving up lock process loop after do() ") rc.unlockResponseChannel <- true }() @@ -177,18 +169,18 @@ func (rc *Connection) DoContext(ctx context.Context, do func(context.Context) er } // Force process to soft-break so we can lock - rc.traceLog("request unlocking of process loop for do()") + log.Degubln("request unlocking of process loop for do()") select { case rc.unlockChannel <- true: break case <-ctx.Done(): - rc.traceLog("giving up on unlocking process loop for do() because context cancelled") + log.Degubln("giving up on unlocking process loop for do() because context cancelled") return ctx.Err() } - rc.traceLog("process loop is unlocked for do()") + log.Degubln("process loop is unlocked for do()") defer func() { - rc.traceLog("giving up lock process loop after do() ") + log.Degubln("giving up lock process loop after do() ") rc.unlockResponseChannel <- true }() @@ -203,7 +195,7 @@ func (rc *Connection) DoContext(ctx context.Context, do func(context.Context) er // are not met on the local side (a nil error return does not mean the // channel was opened successfully, because channels open asynchronously). func (rc *Connection) RequestOpenChannel(ctype string, handler channels.Handler) (*channels.Channel, error) { - rc.traceLog(fmt.Sprintf("requesting open channel of type %s", ctype)) + log.Degubln(fmt.Sprintf("requesting open channel of type %s", ctype)) channel, err := rc.buildChannel(handler, rc.channelManager.OpenChannelRequest) if err == nil { response, err := handler.OpenOutbound(channel) @@ -217,7 +209,7 @@ func (rc *Connection) handleChannelOpening(channel *channels.Channel, response [ rc.SendRicochetPacket(rc.Conn, 0, response) return channel, nil } - rc.traceLog(fmt.Sprintf("failed to request open channel: %v", err)) + log.Degubln(fmt.Sprintf("failed to request open channel: %v", err)) rc.channelManager.RemoveChannel(channel.ID) return nil, err } @@ -271,12 +263,12 @@ func (rc *Connection) processUserCallback(cb func()) { // including connection close. // // Process blocks until the connection is closed or until Break() is called. -// If the connection is closed, a non-nil error is returned. +// Infof the connection is closed, a non-nil error is returned. func (rc *Connection) Process(handler Handler) error { if rc.closed { return utils.ConnectionClosedError } - rc.traceLog("entering process loop") + log.Degubln("entering process loop") rc.processUserCallback(func() { handler.OnReady(rc) }) // There are exactly two ways out of this loop: a signal on breakChannel @@ -296,7 +288,7 @@ func (rc *Connection) Process(handler Handler) error { <-rc.unlockResponseChannel continue case <-rc.breakChannel: - rc.traceLog("process has ended after break") + log.Degubln("process has ended after break") rc.breakResultChannel <- nil return nil case packet = <-rc.packetChannel: @@ -341,7 +333,7 @@ func (rc *Connection) Process(handler Handler) error { } if packet.Channel == 0 { - rc.traceLog(fmt.Sprintf("received control packet on channel %d", packet.Channel)) + log.Degubln(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 { @@ -354,11 +346,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)) + log.Degubln(fmt.Sprintf("removing channel %d", packet.Channel)) rc.channelManager.RemoveChannel(packet.Channel) rc.processUserCallback(func() { channel.Handler.Closed(utils.ChannelClosedByPeerError) }) } else { - rc.traceLog(fmt.Sprintf("received packet on %v channel %d", channel.Handler.Type(), packet.Channel)) + log.Degubln(fmt.Sprintf("received packet on %v channel %d", channel.Handler.Type(), packet.Channel)) // Send The Ricochet Packet to the Handler rc.processUserCallback(func() { channel.Handler.Packet(packet.Data[:]) }) } @@ -366,7 +358,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)) + log.Degubln(fmt.Sprintf("received packet on unknown channel %d. closing.", packet.Channel)) if len(packet.Data) != 0 { rc.SendRicochetPacket(rc.Conn, packet.Channel, []byte{}) } @@ -403,7 +395,7 @@ func (rc *Connection) controlPacket(handler Handler, res *Protocol_Data_Control. } // Send Error Packet response := rc.messageBuilder.RejectOpenChannel(opm.GetChannelIdentifier(), errorText) - rc.traceLog(fmt.Sprintf("sending reject open channel for %v: %v", opm.GetChannelIdentifier(), errorText)) + log.Degubln(fmt.Sprintf("sending reject open channel for %v: %v", opm.GetChannelIdentifier(), errorText)) rc.SendRicochetPacket(rc.Conn, 0, response) } else if res.GetChannelResult() != nil { @@ -412,20 +404,20 @@ 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") + log.Degubln("received keep alive packet") respond, data := rc.ctrlChannel.ProcessKeepAlive(res.GetKeepAlive()) if respond { - rc.traceLog("sending keep alive response") + log.Degubln("sending keep alive response") rc.SendRicochetPacket(rc.Conn, 0, data) } } else if res.GetEnableFeatures() != nil { - rc.traceLog("received enable features packet") + log.Degubln("received enable features packet") data := rc.ctrlChannel.ProcessEnableFeatures(handler, res.GetEnableFeatures()) - rc.traceLog(fmt.Sprintf("sending featured enabled: %v", data)) + log.Degubln(fmt.Sprintf("sending featured enabled: %v", data)) rc.SendRicochetPacket(rc.Conn, 0, data) } else if res.GetFeaturesEnabled() != nil { rc.SupportChannels = res.GetFeaturesEnabled().GetFeature() - rc.traceLog(fmt.Sprintf("connection supports: %v", rc.SupportChannels)) + log.Degubln(fmt.Sprintf("connection supports: %v", rc.SupportChannels)) } } @@ -437,14 +429,6 @@ func (rc *Connection) EnableFeatures(features []string) { rc.SendRicochetPacket(rc.Conn, 0, raw) } -// traceLog is an internal function which only logs messages -// if the connection is configured to log. -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 returns an error if it would not be valid to call Process() again for // the connection now. Currently, the only such error is ConnectionClosedError. @@ -455,10 +439,10 @@ func (rc *Connection) Break() error { rc.processBlockMutex.Lock() defer rc.processBlockMutex.Unlock() if rc.closed { - rc.traceLog("ignoring break because connection is already closed") + log.Degubln("ignoring break because connection is already closed") return utils.ConnectionClosedError } - rc.traceLog("breaking out of process loop") + log.Degubln("breaking out of process loop") rc.breakChannel <- true return <-rc.breakResultChannel // Wait for Process to End } diff --git a/connection/connection_test.go b/connection/connection_test.go index fa9ba05..7045c18 100644 --- a/connection/connection_test.go +++ b/connection/connection_test.go @@ -29,7 +29,6 @@ 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(identity.Initialize("", privateKey)) @@ -65,7 +64,6 @@ func TestProcessAuthAs3DHServer(t *testing.T) { hostname := utils.GetTorV3Hostname(pub) orc := NewOutboundConnection(cconn, hostname) - orc.TraceLog(true) known, err := HandleOutboundConnection(orc).ProcessAuthAsV3Client(identity.InitializeV3("", &cpriv, &cpub)) if err != nil { @@ -100,7 +98,6 @@ func TestProcessAuthAsV3ServerFail(t *testing.T) { // Setting the RemoteHostname to the client pub key approximates a server sending the wrong public key. hostname := utils.GetTorV3Hostname(cpub) orc := NewOutboundConnection(cconn, hostname) - orc.TraceLog(true) HandleOutboundConnection(orc).ProcessAuthAsV3Client(identity.InitializeV3("", &cpriv, &cpub)) }() @@ -129,7 +126,6 @@ func TestProcessAuthAsV3ClientFail(t *testing.T) { hostname := utils.GetTorV3Hostname(pub) orc := NewOutboundConnection(cconn, hostname) - orc.TraceLog(true) HandleOutboundConnection(orc).ProcessAuthAsV3Client(identity.InitializeV3("", &cpriv, &cpub)) }() @@ -173,7 +169,7 @@ func TestProcessAuthTimeout(t *testing.T) { go func() { net.Dial("tcp", ln.Addr().String()) - time.Sleep(16 * time.Second) + time.Sleep(17 * time.Second) }() diff --git a/connection/control_channel.go b/connection/control_channel.go index aaeae34..25f80dc 100644 --- a/connection/control_channel.go +++ b/connection/control_channel.go @@ -2,6 +2,8 @@ package connection import ( "errors" + "fmt" + "git.openprivacy.ca/openprivacy/libricochet-go/log" "git.openprivacy.ca/openprivacy/libricochet-go/utils" "git.openprivacy.ca/openprivacy/libricochet-go/wire/control" ) @@ -27,11 +29,11 @@ func (ctrl *ControlChannel) ProcessChannelResult(cr *Protocol_Data_Control.Chann } if cr.GetOpened() { - //rc.traceLog(fmt.Sprintf("channel of type %v opened on %v", channel.Type, id)) + log.Degubln(fmt.Sprintf("channel of type %v opened on %v", channel.Type, id)) channel.Handler.OpenOutboundResult(nil, cr) return true, nil } - //rc.traceLog(fmt.Sprintf("channel of type %v rejected on %v", channel.Type, id)) + log.Degubln(fmt.Sprintf("channel of type %v rejected on %v", channel.Type, id)) channel.Handler.OpenOutboundResult(errors.New(cr.GetCommonError().String()), cr) return false, nil } diff --git a/connectivity/torProvider.go b/connectivity/torProvider.go index db037a4..dd8973d 100644 --- a/connectivity/torProvider.go +++ b/connectivity/torProvider.go @@ -2,10 +2,10 @@ package connectivity import ( "errors" + "git.openprivacy.ca/openprivacy/libricochet-go/log" "git.openprivacy.ca/openprivacy/libricochet-go/utils" "github.com/cretz/bine/control" "github.com/cretz/bine/tor" - "log" "net" "net/textproto" "os" @@ -155,17 +155,17 @@ func StartTor(appDirectory string, bundledTorPath string) (ACN, error) { tp := &torProvider{appDirectory: appDirectory, bundeledTorPath: bundledTorPath, childListeners: make(map[string]*onionListenService), breakChan: make(chan bool)} // attempt connect to system tor - log.Printf("dialing system tor control port\n") + log.Debugf("dialing system tor control port\n") controlport, err := dialControlPort(9051) if err == nil { // TODO: configurable auth err := controlport.Authenticate("") if err == nil { - log.Printf("connected to control port") + log.Degubln("connected to control port") pinfo, err := controlport.ProtocolInfo() if err == nil && minTorVersionReqs(pinfo.TorVersion) { - log.Println("OK version " + pinfo.TorVersion) + log.Degubln("OK version " + pinfo.TorVersion) tp.t = createFromExisting(controlport, dataDir) go tp.monitorRestart() return tp, nil @@ -182,15 +182,15 @@ func StartTor(appDirectory string, bundledTorPath string) (ACN, error) { go tp.monitorRestart() return tp, nil } - log.Printf("Error connecting to self-run system tor: %v\n", err) + log.Debugf("Error connecting to self-run system tor: %v\n", err) } // try running bundledTor if bundledTorPath != "" && checkCmdlineTorVersion(bundledTorPath) { - log.Println("using bundled tor '" + bundledTorPath + "'") + log.Degubln("using bundled tor '" + bundledTorPath + "'") t, err := tor.Start(nil, &tor.StartConf{DataDir: dataDir, ExePath: bundledTorPath, DebugWriter: nil}) if err != nil { - log.Printf("Error running bundled tor: %v\n", err) + log.Debugf("Error running bundled tor: %v\n", err) } tp.t = t if err == nil { @@ -270,7 +270,7 @@ func checkCmdlineTorVersion(torCmd string) bool { out, err := cmd.CombinedOutput() re := regexp.MustCompile("[0-1]\\.[0-9]\\.[0-9]\\.[0-9]") sysTorVersion := re.Find(out) - log.Println("cmdline tor version: " + string(sysTorVersion)) + log.Infoln("tor version: " + string(sysTorVersion)) return err == nil && minTorVersionReqs(string(sysTorVersion)) } @@ -278,7 +278,7 @@ func checkCmdlineTorVersion(torCmd string) bool { // min requirment 0.3.5.x func minTorVersionReqs(torversion string) bool { torversions := strings.Split(torversion, ".") //eg: 0.3.4.8 or 0.3.5.1-alpha - log.Printf("torversions: %v", torversions) + log.Debugf("torversions: %v", torversions) tva, _ := strconv.Atoi(torversions[0]) tvb, _ := strconv.Atoi(torversions[1]) tvc, _ := strconv.Atoi(torversions[2]) diff --git a/log/log.go b/log/log.go new file mode 100644 index 0000000..0d818df --- /dev/null +++ b/log/log.go @@ -0,0 +1,187 @@ +package log + +import ( + "fmt" + golog "log" + "os" + "runtime" + "strings" +) + +// Level indicates the level a log should be classified at +type Level int + +// The possible levels a log can have +const ( + LevelDebug Level = iota + 1 + LevelInfo + LevelWarn + LevelError +) + +var levelString = map[Level]string{LevelDebug: "[DBUG]", LevelInfo: "[INFO]", LevelWarn: "[WARN]", LevelError: "[ERR ]"} + +// Logger is a go Logger wrapper that adds log levels and pattern filtering +// It allows high level 'log level' filtering broadly +// It allows allows two addition levels of filtering: +// everythingFrom which allows inclusion of packages/patterns along with general logging +// nothingExcept which allows focusing on just listed areas +type Logger struct { + logger *golog.Logger + level Level + nothingExceptPatterns []string + everythingFromPatterns []string +} + +// New returns a new Logger with a filter set to the supplied level +func New(level Level) *Logger { + return &Logger{logger: golog.New(os.Stderr, "", golog.Ldate|golog.Ltime), level: level, everythingFromPatterns: make([]string, 0), nothingExceptPatterns: make([]string, 0)} +} + +var std = New(LevelWarn) + +// filter +func (l *Logger) filter(level Level) bool { + + _, file, _, ok := runtime.Caller(3) + if !ok { + file = "???" + } + + for _, pattern := range l.everythingFromPatterns { + if strings.Contains(file, pattern) { + return true + } + } + + for _, pattern := range l.nothingExceptPatterns { + if strings.Contains(file, pattern) { + return true + } + } + + if len(l.nothingExceptPatterns) > 0 { + return false + } + + return l.aboveLevel(level) +} + +func (l *Logger) aboveLevel(level Level) bool { + return level >= l.level +} + +// SetLevel adjusts the output filter by logging level +func (l *Logger) SetLevel(level Level) { + l.level = level +} + +// AddNothingExceptFilter enables strong filtering showing logs only for things on the approved list, adding this pattern to the list +func (l *Logger) AddNothingExceptFilter(pattern string) { + l.nothingExceptPatterns = append(l.nothingExceptPatterns, pattern) +} + +// AddEverythingFromPattern adds a pattern to skip log level filtering, guaranteeing all logs matching hte pattern are seen +func (l *Logger) AddEverythingFromPattern(pattern string) { + l.everythingFromPatterns = append(l.everythingFromPatterns, pattern) +} + +func (l *Logger) header(level Level) string { + _, file, _, ok := runtime.Caller(3) + if !ok { + file = "???" + } else { + short := file + count := 0 + for i := len(file) - 1; i > 0; i-- { + if file[i] == '/' { + short = file[i+1:] + count++ + if count == 2 { + break + } + } + } + file = short + } + return file + " " + levelString[level] + " " +} + +// Printf outputs the format and variables, assuming it passes the filter levels +func (l *Logger) Printf(level Level, format string, v ...interface{}) { + if l.filter(level) { + l.logger.Output(3, l.header(level)+fmt.Sprintf(format, v...)) + } +} + +// Println outputs the variables assuming the filter levels are passed +func (l *Logger) Println(level Level, v ...interface{}) { + if l.filter(level) { + l.logger.Output(3, l.header(level)+fmt.Sprintln(v...)) + } +} + +// SetLevel changes the filtering level of the system logger +func SetLevel(level Level) { + std.SetLevel(level) +} + +// AddNothingExceptFilter enables strong filtering showing logs only for things on the approved list, adding this pattern to the list +func AddNothingExceptFilter(pattern string) { + std.AddNothingExceptFilter(pattern) +} + +// AddEverythingFromPattern adds a pattern to skip log level filtering, guaranteeing all logs matching hte pattern are seen +func AddEverythingFromPattern(pattern string) { + std.AddEverythingFromPattern(pattern) +} + +// Printf outputs the format with variables assuming it passes the filter level +func Printf(level Level, format string, v ...interface{}) { + std.Printf(level, format, v...) +} + +// Println outputs the varibles assuming they pass the filter level +func Println(level Level, v ...interface{}) { + std.Println(level, v...) +} + +// Debugf outputs the format and variables at the Debug level +func Debugf(format string, v ...interface{}) { + std.Printf(LevelDebug, format, v...) +} + +// Infof outputs the format and variables at the Info level +func Infof(format string, v ...interface{}) { + std.Printf(LevelInfo, format, v...) +} + +// Warnf outputs the format and variables at the Warning level +func Warnf(format string, v ...interface{}) { + std.Printf(LevelWarn, format, v...) +} + +// Errorf outputs the format and variables at the Error level +func Errorf(format string, v ...interface{}) { + std.Printf(LevelError, format, v...) +} + +// Degubln outputs the variables at the Debug level +func Degubln(v ...interface{}) { + std.Println(LevelDebug, v...) +} + +// Infoln outputs the variables at the Info level +func Infoln(v ...interface{}) { + std.Println(LevelInfo, v...) +} + +// Warnln outputs the variables at the Warn level +func Warnln(v ...interface{}) { + std.Println(LevelWarn, v...) +} + +// Errorln outputs the variables at the Error level +func Errorln(v ...interface{}) { + std.Println(LevelError, v...) +} diff --git a/testing/integration_test.go b/testing/integration_test.go index d676cbd..9e8830d 100644 --- a/testing/integration_test.go +++ b/testing/integration_test.go @@ -6,8 +6,9 @@ import ( "git.openprivacy.ca/openprivacy/libricochet-go/channels" "git.openprivacy.ca/openprivacy/libricochet-go/connectivity" "git.openprivacy.ca/openprivacy/libricochet-go/identity" + "git.openprivacy.ca/openprivacy/libricochet-go/log" "git.openprivacy.ca/openprivacy/libricochet-go/utils" - "log" + "os" "runtime" "strconv" "sync" @@ -53,7 +54,7 @@ type ChatEchoBot struct { // We always want bidirectional chat channels func (bot *ChatEchoBot) OpenInbound() { - log.Println("OpenInbound() ChatChannel handler called...") + log.Infoln("OpenInbound() ChatChannel handler called...") outboutChatChannel := bot.rai.Connection.Channel("im.ricochet.chat", channels.Outbound) if outboutChatChannel == nil { bot.rai.Connection.Do(func() error { @@ -67,7 +68,7 @@ func (bot *ChatEchoBot) OpenInbound() { } func (bot *ChatEchoBot) ChatMessage(messageID uint32, when time.Time, message string) bool { - log.Printf("ChatMessage(from: %v, %v", bot.rai.RemoteHostname, message) + log.Infof("ChatMessage(from: %v, %v", bot.rai.RemoteHostname, message) bot.Messages.Add(bot.rai.RemoteHostname, bot.onion, message) SendMessage(bot.rai, strconv.Itoa(bot.n)+" witty response") bot.n += 1 @@ -75,19 +76,19 @@ func (bot *ChatEchoBot) ChatMessage(messageID uint32, when time.Time, message st } func SendMessage(rai *application.ApplicationInstance, message string) { - log.Printf("SendMessage(to: %v, %v)\n", rai.RemoteHostname, message) + log.Infof("SendMessage(to: %v, %v)\n", rai.RemoteHostname, message) rai.Connection.Do(func() error { - log.Printf("Finding Chat Channel") + log.Infof("Finding Chat Channel") channel := rai.Connection.Channel("im.ricochet.chat", channels.Outbound) if channel != nil { - log.Printf("Found Chat Channel") + log.Infof("Found Chat Channel") chatchannel, ok := channel.Handler.(*channels.ChatChannel) if ok { chatchannel.SendMessage(message) } } else { - log.Printf("Could not find chat channel") + log.Infof("Could not find chat channel") } return nil }) @@ -98,6 +99,7 @@ func (bot *ChatEchoBot) ChatMessageAck(messageID uint32, accepted bool) { } func TestApplicationIntegration(t *testing.T) { + log.SetLevel(log.LevelInfo) startGoRoutines := runtime.NumGoroutine() acn, err := connectivity.StartTor(".", "") @@ -179,7 +181,7 @@ func TestApplicationIntegration(t *testing.T) { alicei.Connection.Do(func() error { handler, err := alicei.OnOpenChannelRequest("im.ricochet.chat") if err != nil { - log.Printf("Could not get chat handler!\n") + log.Infof("Could not get chat handler!\n") return err } _, err = alicei.Connection.RequestOpenChannel("im.ricochet.chat", handler) @@ -191,7 +193,8 @@ func TestApplicationIntegration(t *testing.T) { SendMessage(alicei, "Hello Bob!") if err != nil { - log.Fatal("Error dialing from Alice to Bob: ", err) + log.Errorf("Error dialing from Alice to Bob: ", err) + os.Exit(1) } time.Sleep(10 * time.Second)