adding new filterable logging system

This commit is contained in:
Dan Ballard 2018-11-30 13:04:38 -08:00
parent fa720940d8
commit 2815e29704
11 changed files with 296 additions and 113 deletions

View File

@ -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)

View File

@ -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])
}

View File

@ -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)
}

View File

@ -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)

View File

@ -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

View File

@ -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
}

View File

@ -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)
}()

View File

@ -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
}

View File

@ -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])

187
log/log.go Normal file
View File

@ -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...)
}

View File

@ -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)