From e6da08a987913b19c52f25bfbea55c6a5a92247f Mon Sep 17 00:00:00 2001
From: LittleSheep <littlesheep.code@hotmail.com>
Date: Wed, 13 Nov 2024 22:18:14 +0800
Subject: [PATCH] :loud_sound: Add more verbose logging on handling requests

---
 pkg/internal/provider/caller.go | 20 ++++++++++++++++++++
 pkg/internal/provider/mailer.go | 21 ++++++++++++++++++++-
 2 files changed, 40 insertions(+), 1 deletion(-)

diff --git a/pkg/internal/provider/caller.go b/pkg/internal/provider/caller.go
index 9b32061..f2603a9 100644
--- a/pkg/internal/provider/caller.go
+++ b/pkg/internal/provider/caller.go
@@ -3,6 +3,7 @@ package provider
 import (
 	"fmt"
 	"git.solsynth.dev/hypernet/pusher/pkg/pushkit"
+	"github.com/google/uuid"
 	"github.com/rs/zerolog/log"
 	"sync"
 	"time"
@@ -15,6 +16,14 @@ func AddProvider(in NotificationProvider) {
 }
 
 func PushNotification(in pushkit.NotificationPushRequest) error {
+	requestId := uuid.NewString()
+	log.Debug().
+		Str("tk", in.Token).
+		Str("provider", in.Provider).
+		Str("topic", in.Notification.Topic).
+		Str("request_id", requestId).
+		Msg("Pushing notification...")
+
 	prov, ok := notifyProviders[in.Provider]
 	if !ok {
 		return fmt.Errorf("provider not found")
@@ -26,18 +35,27 @@ func PushNotification(in pushkit.NotificationPushRequest) error {
 			Str("tk", in.Token).
 			Str("provider", prov.GetName()).
 			Dur("elapsed", time.Since(start)).
+			Str("request_id", requestId).
 			Msg("Push notification failed once")
 	} else {
 		log.Debug().
 			Str("tk", in.Token).
 			Str("provider", prov.GetName()).
 			Dur("elapsed", time.Since(start)).
+			Str("request_id", requestId).
 			Msg("Pushed one notification")
 	}
 	return err
 }
 
 func PushNotificationBatch(in pushkit.NotificationPushBatchRequest) {
+	requestId := uuid.NewString()
+	log.Debug().
+		Int("count", len(in.Tokens)).
+		Str("topic", in.Notification.Topic).
+		Str("request_id", requestId).
+		Msg("Pushing notification batch...")
+
 	var wg sync.WaitGroup
 	for idx, key := range in.Providers {
 		prov, ok := notifyProviders[key]
@@ -54,12 +72,14 @@ func PushNotificationBatch(in pushkit.NotificationPushBatchRequest) {
 					Str("tk", in.Tokens[idx]).
 					Str("provider", prov.GetName()).
 					Dur("elapsed", time.Since(start)).
+					Str("request_id", requestId).
 					Msg("Push notification failed once")
 			} else {
 				log.Debug().
 					Str("tk", in.Tokens[idx]).
 					Str("provider", prov.GetName()).
 					Dur("elapsed", time.Since(start)).
+					Str("request_id", requestId).
 					Msg("Pushed one notification")
 			}
 		}()
diff --git a/pkg/internal/provider/mailer.go b/pkg/internal/provider/mailer.go
index a06ac06..37a9524 100644
--- a/pkg/internal/provider/mailer.go
+++ b/pkg/internal/provider/mailer.go
@@ -4,13 +4,22 @@ import (
 	"crypto/tls"
 	"fmt"
 	"git.solsynth.dev/hypernet/pusher/pkg/pushkit"
+	"github.com/google/uuid"
 	"github.com/jordan-wright/email"
+	"github.com/rs/zerolog/log"
 	"github.com/spf13/viper"
 	"net/smtp"
 	"net/textproto"
 )
 
 func SendMail(target string, in pushkit.EmailData) error {
+	requestId := uuid.NewString()
+	log.Debug().
+		Str("request_id", requestId).
+		Str("to", target).
+		Str("subject", in.Subject).
+		Msg("Sending email...")
+
 	mail := &email.Email{
 		To:      []string{target},
 		From:    viper.GetString("mailer.name"),
@@ -23,7 +32,7 @@ func SendMail(target string, in pushkit.EmailData) error {
 	if in.HTML != nil {
 		mail.HTML = []byte(*in.HTML)
 	}
-	return mail.SendWithTLS(
+	err := mail.SendWithTLS(
 		fmt.Sprintf("%s:%d", viper.GetString("mailer.smtp_host"), viper.GetInt("mailer.smtp_port")),
 		smtp.PlainAuth(
 			"",
@@ -33,4 +42,14 @@ func SendMail(target string, in pushkit.EmailData) error {
 		),
 		&tls.Config{ServerName: viper.GetString("mailer.smtp_host")},
 	)
+
+	if err != nil {
+		log.Warn().
+			Str("request_id", requestId).
+			Str("to", target).
+			Str("subject", in.Subject).
+			Err(err).Msg("Failed to send email...")
+	}
+
+	return err
 }