From 33eb18e687f5d3d9c18a273f8dd84e03d44f4969 Mon Sep 17 00:00:00 2001 From: Hugo Thunnissen Date: Tue, 4 Feb 2020 15:17:58 +0100 Subject: [PATCH] Refactor code to log to file in stead of stdout --- botcommands/whapp-bridge.go | 3 --- core/bridge_context.go | 22 +++++++++++++++++-- core/deltachat.go | 44 +++++++++++++++++++++++++------------ core/whapp.go | 2 ++ go.mod | 2 +- go.sum | 2 ++ whappdc/chat_worker.go | 10 ++++++--- whappdc/message_tracker.go | 14 ++++++++---- whappdc/message_worker.go | 8 +++++-- whappdc/whapp_context.go | 9 ++++---- whappdc/whapp_handler.go | 11 ++++------ 11 files changed, 87 insertions(+), 40 deletions(-) diff --git a/botcommands/whapp-bridge.go b/botcommands/whapp-bridge.go index 2f419be..9a5ca36 100644 --- a/botcommands/whapp-bridge.go +++ b/botcommands/whapp-bridge.go @@ -2,7 +2,6 @@ package botcommands import ( "fmt" - "log" "github.com/Rhymen/go-whatsapp" "github.com/hugot/go-deltachat/deltachat" @@ -26,7 +25,6 @@ func (b *WhappBridge) Accepts(c *deltachat.Chat, m *deltachat.Message) bool { if err != nil { // The database is failing, very much an edge case. - log.Println(err) b.bridgeCtx.SendLog(err.Error()) return false @@ -43,7 +41,6 @@ func (b *WhappBridge) Execute( JID, err := b.bridgeCtx.DB.GetWhappJIDForDCID(chat.GetID()) if err != nil { - log.Println(err) b.bridgeCtx.SendLog( fmt.Sprintf( "Database error in Whapp bridge: %s", diff --git a/core/bridge_context.go b/core/bridge_context.go index 7434f4d..db81e83 100644 --- a/core/bridge_context.go +++ b/core/bridge_context.go @@ -1,7 +1,9 @@ package core import ( + "fmt" "log" + "os" "github.com/Rhymen/go-whatsapp" "github.com/hugot/go-deltachat/deltabot" @@ -16,6 +18,7 @@ type BridgeContext struct { DB *Database DCUserID uint32 DCUserChatID uint32 + logger deltachat.Logger } func NewBridgeContext(config *Config) *BridgeContext { @@ -39,6 +42,16 @@ func (b *BridgeContext) Init( return err } + logFile, err := os.OpenFile( + b.Config.App.DataFolder+"/whapp-deltachat.log", + os.O_WRONLY|os.O_CREATE|os.O_APPEND, + 0644, + ) + + b.logger = log.New(logFile, "", log.LstdFlags) + + fmt.Printf("Logs will be written to %s\n", logFile.Name()) + dcClient, err := BootstrapDcClientFromConfig(*b.Config, b) b.SendLog("Whapp-Deltachat started.") @@ -48,7 +61,7 @@ func (b *BridgeContext) Init( } for i := 0; i < 10; i++ { - log.Println("Attempting whapp login") + b.SendLog(fmt.Sprintf("Attempting whapp login (attempt %d)", i+1)) err = CreateAndLoginWhappConnection(b.Config.App.DataFolder, b) if err == nil { @@ -62,7 +75,7 @@ func (b *BridgeContext) Init( b.WhappConn.AddHandler(whappHandler) - bot := &deltabot.Bot{} + bot := deltabot.NewBot(b.logger) for _, command := range botCommands { bot.AddCommand(command) @@ -87,6 +100,11 @@ func (b *BridgeContext) Close() error { return err } +func (b *BridgeContext) Logger() deltachat.Logger { + return b.logger +} + func (b *BridgeContext) SendLog(logString string) { + b.logger.Println(logString) b.DCContext.SendTextMessage(b.DCUserChatID, logString) } diff --git a/core/deltachat.go b/core/deltachat.go index c5e8d1f..7aeb722 100644 --- a/core/deltachat.go +++ b/core/deltachat.go @@ -4,21 +4,24 @@ import ( "encoding/binary" "errors" "fmt" - "log" "os" "github.com/hugot/go-deltachat/deltachat" "github.com/mdp/qrterminal" ) -func DcClientFromConfig(databasePath string, config map[string]string) *deltachat.Client { - client := &deltachat.Client{} +func DcClientFromConfig( + databasePath string, + logger deltachat.Logger, + config map[string]string, +) *deltachat.Client { + client := deltachat.NewClient(logger) // Handler for info logs from libdeltachat client.On(deltachat.DC_EVENT_INFO, func(c *deltachat.Context, e *deltachat.Event) { info, _ := e.Data2.String() - log.Println(*info) + logger.Println(*info) }) client.Open(databasePath) @@ -45,11 +48,15 @@ func DcClientFromConfig(databasePath string, config map[string]string) *deltacha // Note: this manipulates the BridgeContext. func BootstrapDcClientFromConfig(config Config, ctx *BridgeContext) (*deltachat.Client, error) { - dcClient := DcClientFromConfig(config.App.DataFolder+"/deltachat.db", config.Deltachat) + dcClient := DcClientFromConfig( + config.App.DataFolder+"/deltachat.db", + ctx.Logger(), + config.Deltachat, + ) DCCtx := dcClient.Context() - log.Println("Waiting for deltachat client to be configured") + ctx.Logger().Println("Waiting for deltachat client to be configured") for !DCCtx.IsConfigured() { } @@ -74,7 +81,7 @@ func BootstrapDcClientFromConfig(config Config, ctx *BridgeContext) (*deltachat. // The verified group chat that is used as 1:1 between whappDC and the user is // created here if verified groups are enabled. if userChatIDRaw == nil { - userChatID, err = AddUserAsVerifiedContact(dcUserID, dcClient) + userChatID, err = AddUserAsVerifiedContact(dcUserID, dcClient, ctx.Logger()) if err != nil { return nil, err } @@ -99,7 +106,11 @@ func BootstrapDcClientFromConfig(config Config, ctx *BridgeContext) (*deltachat. // Add a user as verified contact to the deltachat context. This is necessary to be able // to create verified groups. -func AddUserAsVerifiedContact(dcUserID uint32, client *deltachat.Client) (uint32, error) { +func AddUserAsVerifiedContact( + dcUserID uint32, + client *deltachat.Client, + logger deltachat.Logger, +) (uint32, error) { confirmChan := make(chan bool) client.On( @@ -108,7 +119,7 @@ func AddUserAsVerifiedContact(dcUserID uint32, client *deltachat.Client) (uint32 contactIDInt, err := e.Data1.Int() if err != nil { - log.Println(err) + logger.Println(err) // Something weird is going on here, deltachat is not passing expected // values. Make the join process fail. @@ -119,7 +130,7 @@ func AddUserAsVerifiedContact(dcUserID uint32, client *deltachat.Client) (uint32 contactID := uint32(*contactIDInt) if contactID != dcUserID { - log.Println( + logger.Println( fmt.Sprintf( "Unexpected contact ID encountered for securejoin progress: %v", contactID, @@ -132,7 +143,7 @@ func AddUserAsVerifiedContact(dcUserID uint32, client *deltachat.Client) (uint32 progress, err := e.Data2.Int() if err != nil { - log.Println(err) + logger.Println(err) confirmChan <- false return @@ -149,7 +160,7 @@ func AddUserAsVerifiedContact(dcUserID uint32, client *deltachat.Client) (uint32 chatID := ctx.CreateGroupChat(true, "Whapp-DC ***status***") - log.Println("Scan this qr code with your DC client") + fmt.Println("Scan this qr code with your DC client:") qrterminal.Generate( ctx.GetSecurejoinQR(chatID), qrterminal.L, @@ -159,10 +170,15 @@ func AddUserAsVerifiedContact(dcUserID uint32, client *deltachat.Client) (uint32 success := <-confirmChan if !success { - return chatID, errors.New("Contact Verification process failed") + errorString := "Contact Verification process failed" + fmt.Fprintln(os.Stderr, errorString) + + return chatID, errors.New(errorString) } - log.Println("Securejoin verification completed") + successString := "Securejoin verification completed" + fmt.Println(successString) + logger.Println(successString) return chatID, nil } diff --git a/core/whapp.go b/core/whapp.go index 37cb6fe..acfde23 100644 --- a/core/whapp.go +++ b/core/whapp.go @@ -81,12 +81,14 @@ func WhappQrLogin( tmpFile, err := ioutil.TempFile(storageDir+"/tmp", "XXXXXXX-qr") if err != nil { + ctx.SendLog("Failed to create temporarary file: " + err.Error()) log.Fatal(err) } err = qrcode.WriteFile(qrCode, qrcode.Medium, 256, tmpFile.Name()) if err != nil { + ctx.SendLog("Failed to save qrcode file: " + err.Error()) log.Fatal(err) } diff --git a/go.mod b/go.mod index 4c0806e..5ca3bc1 100644 --- a/go.mod +++ b/go.mod @@ -6,7 +6,7 @@ require ( github.com/Rhymen/go-whatsapp v0.1.0 github.com/golang/protobuf v1.3.2 // indirect github.com/gorilla/websocket v1.4.1 // indirect - github.com/hugot/go-deltachat v0.0.0-20200129012921-ed391e8c375b + github.com/hugot/go-deltachat v0.0.0-20200204072655-35fe0f4df433 github.com/kr/pretty v0.2.0 // indirect github.com/mdp/qrterminal v1.0.1 github.com/pkg/errors v0.9.1 // indirect diff --git a/go.sum b/go.sum index 93690c1..27ce7c7 100644 --- a/go.sum +++ b/go.sum @@ -19,6 +19,8 @@ github.com/hugot/go-deltachat v0.0.0-20200115103405-94f97902030f h1:mfCED+euCowU github.com/hugot/go-deltachat v0.0.0-20200115103405-94f97902030f/go.mod h1:QFRDi9Rx2oT6xcrUhar6xBPHCwvuGabDxFhTqaZUfNI= github.com/hugot/go-deltachat v0.0.0-20200129012921-ed391e8c375b h1:D57KR1i6DP2smSv00kojlJJHuftZ2Oedy8SrhpECUOY= github.com/hugot/go-deltachat v0.0.0-20200129012921-ed391e8c375b/go.mod h1:QFRDi9Rx2oT6xcrUhar6xBPHCwvuGabDxFhTqaZUfNI= +github.com/hugot/go-deltachat v0.0.0-20200204072655-35fe0f4df433 h1:babXKcICVYwSgeGKXpJpN8rtFU6o6M7ot2fhSawdIuE= +github.com/hugot/go-deltachat v0.0.0-20200204072655-35fe0f4df433/go.mod h1:QFRDi9Rx2oT6xcrUhar6xBPHCwvuGabDxFhTqaZUfNI= github.com/kr/pretty v0.2.0 h1:s5hAObm+yFO5uHYt5dYjxi2rXrsnmRpJx4OYvIWUaQs= github.com/kr/pretty v0.2.0/go.mod h1:ipq/a2n7PKx3OHsz4KJII5eveXtPO4qwEXGdVfWzfnI= github.com/kr/pty v1.1.1/go.mod h1:pFQYn66WHrOpPYNljwOMqo10TkYh1fy3cYio2l3bCsQ= diff --git a/whappdc/chat_worker.go b/whappdc/chat_worker.go index b1f009b..7da27e5 100644 --- a/whappdc/chat_worker.go +++ b/whappdc/chat_worker.go @@ -1,19 +1,23 @@ package whappdc -import "log" +import ( + "github.com/hugot/go-deltachat/deltachat" +) // ChatWorker receives structs of type MessageHandler and executes them sequentially. By // executing the handlers sequentially we try to make sure that the messages are sent // through deltachat in the right order. type ChatWorker struct { + logger deltachat.Logger incomingHandlers chan MessageHandler quit chan bool } -func NewChatWorker() *ChatWorker { +func NewChatWorker(logger deltachat.Logger) *ChatWorker { return &ChatWorker{ incomingHandlers: make(chan MessageHandler, 3), quit: make(chan bool), + logger: logger, } } @@ -35,7 +39,7 @@ func (w *ChatWorker) Start() { err := handler.Action() if err != nil { - log.Println(err) + w.logger.Println(err) } } } diff --git a/whappdc/message_tracker.go b/whappdc/message_tracker.go index 2dd85bc..a149ff4 100644 --- a/whappdc/message_tracker.go +++ b/whappdc/message_tracker.go @@ -1,16 +1,21 @@ package whappdc import ( - "log" "sync" "time" + "github.com/hugot/go-deltachat/deltachat" "github.com/hugot/whapp-deltachat/core" ) -func NewMessageTracker(DB *core.Database, flushInterval time.Duration) *MessageTracker { +func NewMessageTracker( + DB *core.Database, + flushInterval time.Duration, + logger deltachat.Logger, +) *MessageTracker { tracker := &MessageTracker{ - DB: DB, + DB: DB, + logger: logger, } tracker.FlushWithInterval(flushInterval) @@ -24,6 +29,7 @@ func NewMessageTracker(DB *core.Database, flushInterval time.Duration) *MessageT // up to date answer. type MessageTracker struct { DB *core.Database + logger deltachat.Logger delivered [80]*string deliveredMutex sync.RWMutex deliveredIdx int @@ -75,7 +81,7 @@ func (t *MessageTracker) FlushWithInterval(interval time.Duration) { err := t.Flush() if err != nil { - log.Println(err) + t.logger.Println(err) } } }() diff --git a/whappdc/message_worker.go b/whappdc/message_worker.go index 2774f67..7eafe07 100644 --- a/whappdc/message_worker.go +++ b/whappdc/message_worker.go @@ -1,5 +1,7 @@ package whappdc +import "github.com/hugot/go-deltachat/deltachat" + // MessageWorker receives structs of type MessageHandler and distributes them across chat // workers. Each whatsapp chat should have its own worker. If a message is encountered for // a chat that has no worker yet, it is created. @@ -7,13 +9,15 @@ type MessageWorker struct { incomingHandlers chan MessageHandler chatWorkers map[string]*ChatWorker quit chan bool + logger deltachat.Logger } -func NewMessageWorker() *MessageWorker { +func NewMessageWorker(logger deltachat.Logger) *MessageWorker { return &MessageWorker{ incomingHandlers: make(chan MessageHandler), chatWorkers: make(map[string]*ChatWorker), quit: make(chan bool), + logger: logger, } } @@ -39,7 +43,7 @@ func (w *MessageWorker) Start() { worker, ok := w.chatWorkers[handler.Jid] if !ok { - worker = NewChatWorker() + worker = NewChatWorker(w.logger) worker.Start() w.chatWorkers[handler.Jid] = worker diff --git a/whappdc/whapp_context.go b/whappdc/whapp_context.go index ea69c54..7aa07cd 100644 --- a/whappdc/whapp_context.go +++ b/whappdc/whapp_context.go @@ -1,7 +1,6 @@ package whappdc import ( - "log" "time" "github.com/Rhymen/go-whatsapp" @@ -13,7 +12,11 @@ func NewWhappContext( bridgeCtx *core.BridgeContext, msgTrackerFlushInterval time.Duration, ) *WhappContext { - messageTracker := NewMessageTracker(bridgeCtx.DB, msgTrackerFlushInterval) + messageTracker := NewMessageTracker( + bridgeCtx.DB, + msgTrackerFlushInterval, + bridgeCtx.Logger(), + ) return &WhappContext{ BridgeCtx: bridgeCtx, @@ -65,7 +68,6 @@ func (w *WhappContext) MessageWasSent(ID string) bool { sent, err := w.MessageTracker.WasSent(ID) if err != nil { - log.Println(err) w.BridgeCtx.SendLog(err.Error()) } @@ -98,7 +100,6 @@ func (w *WhappContext) markSentIf404Download(ID *string, err error) { err := w.MessageTracker.MarkSent(ID) if err != nil { - log.Println(err) w.BridgeCtx.SendLog(err.Error()) } } diff --git a/whappdc/whapp_handler.go b/whappdc/whapp_handler.go index d2afe8f..7030b2f 100644 --- a/whappdc/whapp_handler.go +++ b/whappdc/whapp_handler.go @@ -2,7 +2,6 @@ package whappdc import ( "fmt" - "log" "time" "github.com/Rhymen/go-whatsapp" @@ -21,7 +20,7 @@ func NewWhappHandler( ) *WhappHandler { return &WhappHandler{ WhappCtx: NewWhappContext(bridgeCtx, msgTrackerFlushInterval), - MessageWorker: NewMessageWorker(), + MessageWorker: NewMessageWorker(bridgeCtx.Logger()), } } @@ -43,18 +42,16 @@ func (h *WhappHandler) HandleError(err error) { ) if err != nil { - logString := "Failed to restore whatsapp connection: " + err.Error() - log.Println(logString) - h.WhappCtx.BridgeCtx.SendLog(logString) + h.WhappCtx.BridgeCtx.SendLog("Failed to restore whatsapp connection: " + err.Error()) } return } - log.Println(fmt.Sprintf("Whatsapp Error of type: %T", err)) + h.WhappCtx.BridgeCtx.Logger().Println(fmt.Sprintf("Whatsapp Error of type: %T", err)) logString := "Whatsapp Error: " + err.Error() - log.Println(logString) + h.WhappCtx.BridgeCtx.Logger().Println(logString) // Invalid ws data seems to be pretty common, let's not bore the user with that.xg if err.Error() != "error processing data: "+whatsapp.ErrInvalidWsData.Error() {