From 711760a5688b4f2044c6cd980b0a1365ec049864 Mon Sep 17 00:00:00 2001 From: Kichiyaki Date: Sat, 24 Oct 2020 08:17:52 +0200 Subject: [PATCH] log system improved --- cron/cron.go | 21 +++--- cron/{handler.go => worker.go} | 126 ++++++++++++++++++++++----------- discord/discord.go | 19 ++++- go.mod | 3 +- go.sum | 8 ++- main.go | 48 +++++++++---- 6 files changed, 156 insertions(+), 69 deletions(-) rename cron/{handler.go => worker.go} (64%) diff --git a/cron/cron.go b/cron/cron.go index 0b95e89..dcf7f9a 100644 --- a/cron/cron.go +++ b/cron/cron.go @@ -3,6 +3,7 @@ package cron import ( "time" + "github.com/sirupsen/logrus" "github.com/tribalwarshelp/golang-sdk/sdk" "github.com/tribalwarshelp/shared/mode" @@ -14,6 +15,8 @@ import ( "github.com/robfig/cron/v3" ) +var log = logrus.WithField("package", "cron") + type Config struct { ServerRepo server.Repository ObservationRepo observation.Repository @@ -24,7 +27,7 @@ type Config struct { } func Attach(c *cron.Cron, cfg Config) { - h := &handler{ + w := &worker{ lastEnnoblementAt: make(map[string]time.Time), serverRepo: cfg.ServerRepo, observationRepo: cfg.ObservationRepo, @@ -33,16 +36,16 @@ func Attach(c *cron.Cron, cfg Config) { api: cfg.API, status: cfg.Status, } - c.AddFunc("@every 1m", h.checkEnnoblements) - c.AddFunc("@every 30m", h.checkBotServers) - c.AddFunc("@every 2h10m", h.deleteClosedTribalWarsServers) - c.AddFunc("@every 2h", h.updateBotStatus) + c.AddFunc("@every 1m", w.checkEnnoblements) + c.AddFunc("@every 30m", w.checkBotServers) + c.AddFunc("@every 2h10m", w.deleteClosedTribalWarsServers) + c.AddFunc("@every 2h", w.updateBotStatus) go func() { - h.checkBotServers() - h.deleteClosedTribalWarsServers() - h.updateBotStatus() + w.checkBotServers() + w.deleteClosedTribalWarsServers() + w.updateBotStatus() if mode.Get() == mode.DevelopmentMode { - h.checkEnnoblements() + w.checkEnnoblements() } }() } diff --git a/cron/handler.go b/cron/worker.go similarity index 64% rename from cron/handler.go rename to cron/worker.go index 3a73c07..d8e4428 100644 --- a/cron/handler.go +++ b/cron/worker.go @@ -3,7 +3,6 @@ package cron import ( "context" "fmt" - "log" "time" "github.com/nicksnyder/go-i18n/v2/i18n" @@ -22,7 +21,7 @@ import ( "github.com/tribalwarshelp/golang-sdk/sdk" ) -type handler struct { +type worker struct { lastEnnoblementAt map[string]time.Time serverRepo server.Repository observationRepo observation.Repository @@ -32,7 +31,7 @@ type handler struct { status string } -func (h *handler) loadEnnoblements(servers []string) (map[string]ennoblements, error) { +func (w *worker) loadEnnoblements(servers []string) (map[string]ennoblements, error) { m := make(map[string]ennoblements) if len(servers) == 0 { @@ -62,12 +61,12 @@ func (h *handler) loadEnnoblements(servers []string) (map[string]ennoblements, e resp := make(map[string]ennoblements) - if err := h.api.Post(fmt.Sprintf(`query { %s }`, query), &resp); err != nil { + if err := w.api.Post(fmt.Sprintf(`query { %s }`, query), &resp); err != nil { return m, errors.Wrap(err, "loadEnnoblements") } for server, ennoblements := range resp { - lastEnnoblementAt, ok := h.lastEnnoblementAt[server] + lastEnnoblementAt, ok := w.lastEnnoblementAt[server] if !ok { lastEnnoblementAt = time.Now().Add(-1 * time.Minute) } @@ -81,13 +80,13 @@ func (h *handler) loadEnnoblements(servers []string) (map[string]ennoblements, e if lastEnnoblement != nil { lastEnnoblementAt = lastEnnoblement.EnnobledAt } - h.lastEnnoblementAt[server] = lastEnnoblementAt + w.lastEnnoblementAt[server] = lastEnnoblementAt } return m, nil } -func (h *handler) loadLangVersions(servers []string) ([]*shared_models.LangVersion, error) { +func (w *worker) loadLangVersions(servers []string) ([]*shared_models.LangVersion, error) { languageTags := []shared_models.LanguageTag{} cache := make(map[shared_models.LanguageTag]bool) for _, server := range servers { @@ -98,7 +97,7 @@ func (h *handler) loadLangVersions(servers []string) ([]*shared_models.LangVersi } } - langVersionList, err := h.api.LangVersions.Browse(&shared_models.LangVersionFilter{ + langVersionList, err := w.api.LangVersions.Browse(&shared_models.LangVersionFilter{ Tag: languageTags, }) if err != nil { @@ -108,32 +107,43 @@ func (h *handler) loadLangVersions(servers []string) ([]*shared_models.LangVersi return langVersionList.Items, nil } -func (h *handler) checkEnnoblements() { +func (w *worker) checkEnnoblements() { start := time.Now() + log. + Infoln("checkEnnoblements: called") - servers, err := h.observationRepo.FetchServers(context.Background()) + servers, err := w.observationRepo.FetchServers(context.Background()) if err != nil { - log.Print("checkEnnoblements error: " + err.Error()) + log.Errorln("checkEnnoblements:", err.Error()) return } - log.Print("checkEnnoblements: servers: ", servers) + log. + WithField("servers", servers). + Info("checkEnnoblements: Loaded servers") - groups, total, err := h.groupRepo.Fetch(context.Background(), nil) + groups, total, err := w.groupRepo.Fetch(context.Background(), nil) if err != nil { - log.Print("checkEnnoblements error: " + err.Error()) + log.Errorln("checkEnnoblements:", err.Error()) return } - log.Print("checkEnnoblements: number of loaded groups: ", total) + log. + WithField("numberOfGroups", total). + Info("checkEnnoblements: Loaded groups") - langVersions, err := h.loadLangVersions(servers) + langVersions, err := w.loadLangVersions(servers) if err != nil { - log.Print(err) + log.Errorln("checkEnnoblements:", err) return } - ennoblementsByServerKey, err := h.loadEnnoblements(servers) + log. + WithField("numberOfLangVersions", len(langVersions)). + Info("checkEnnoblements: Loaded lang versions") + + ennoblementsByServerKey, err := w.loadEnnoblements(servers) if err != nil { - log.Print(err) + log.Errorln("checkEnnoblements:", err) } + log.Info("checkEnnoblements: Loaded ennoblements") for _, group := range groups { if group.ConqueredVillagesChannelID == "" && group.LostVillagesChannelID == "" { @@ -191,7 +201,7 @@ func (h *handler) checkEnnoblements() { DefaultMessage: message.FallbackMsg(message.CronConqueredVillagesTitle, "Conquered villages"), }) - go h.discord.SendEmbed(group.ConqueredVillagesChannelID, + go w.discord.SendEmbed(group.ConqueredVillagesChannelID, discord. NewEmbed(). SetTitle(title). @@ -207,7 +217,7 @@ func (h *handler) checkEnnoblements() { DefaultMessage: message.FallbackMsg(message.CronLostVillagesTitle, "Lost villages"), }) - go h.discord.SendEmbed(group.LostVillagesChannelID, + go w.discord.SendEmbed(group.LostVillagesChannelID, discord. NewEmbed(). SetTitle(title). @@ -218,50 +228,69 @@ func (h *handler) checkEnnoblements() { } } - log.Printf("checkEnnoblements: finished in %s", time.Since(start).String()) + log. + WithField("executionTime", time.Since(start).String()). + Infoln("checkEnnoblements: finished executing") } -func (h *handler) checkBotServers() { - servers, total, err := h.serverRepo.Fetch(context.Background(), nil) +func (w *worker) checkBotServers() { + start := time.Now() + log.Info("checkBotServers: called") + + servers, total, err := w.serverRepo.Fetch(context.Background(), nil) if err != nil { - log.Print("checkBotServers error: " + err.Error()) + log.Error("checkBotServers: " + err.Error()) return } - log.Print("checkBotServers: total number of loaded discord servers: ", total) + log. + WithField("executionTime", time.Since(start)). + WithField("numberOfServers", total). + Info("checkBotServers: loaded servers") idsToDelete := []string{} for _, server := range servers { - if isGuildMember, _ := h.discord.IsGuildMember(server.ID); !isGuildMember { + if isGuildMember, _ := w.discord.IsGuildMember(server.ID); !isGuildMember { idsToDelete = append(idsToDelete, server.ID) } } if len(idsToDelete) > 0 { - deleted, err := h.serverRepo.Delete(context.Background(), &models.ServerFilter{ + deleted, err := w.serverRepo.Delete(context.Background(), &models.ServerFilter{ ID: idsToDelete, }) if err != nil { - log.Print("checkBotServers error: " + err.Error()) + log.Error("checkBotServers: " + err.Error()) } else { - log.Printf("checkBotServers: total number of deleted discord servers: %d", len(deleted)) + log. + WithField("numberOfDeletedServers", len(deleted)). + Info("checkBotServers: deleted servers") } } + + log. + WithField("executionTime", time.Since(start).String()). + Infoln("checkBotServers: finished executing") } -func (h *handler) deleteClosedTribalWarsServers() { - servers, err := h.observationRepo.FetchServers(context.Background()) +func (w *worker) deleteClosedTribalWarsServers() { + start := time.Now() + log.Info("deleteClosedTribalWarsServers: called") + + servers, err := w.observationRepo.FetchServers(context.Background()) if err != nil { - log.Print("deleteClosedTribalWarsServers: " + err.Error()) + log.Error("deleteClosedTribalWarsServers: " + err.Error()) return } - log.Print("deleteClosedTribalWarsServers: servers: ", servers) + log. + WithField("servers", servers). + Info("deleteClosedTribalWarsServers: loaded servers") - list, err := h.api.Servers.Browse(&shared_models.ServerFilter{ + list, err := w.api.Servers.Browse(&shared_models.ServerFilter{ Key: servers, Status: []shared_models.ServerStatus{shared_models.ServerStatusClosed}, }, nil) if err != nil { - log.Print("deleteClosedTribalWarsServers: " + err.Error()) + log.Errorln("deleteClosedTribalWarsServers: " + err.Error()) return } if list == nil || list.Items == nil { @@ -274,19 +303,32 @@ func (h *handler) deleteClosedTribalWarsServers() { } if len(keys) > 0 { - deleted, err := h.observationRepo.Delete(context.Background(), &models.ObservationFilter{ + deleted, err := w.observationRepo.Delete(context.Background(), &models.ObservationFilter{ Server: keys, }) if err != nil { - log.Print("deleteClosedTribalWarsServers error: " + err.Error()) + log.Errorln("deleteClosedTribalWarsServers: " + err.Error()) } else { - log.Printf("deleteClosedTribalWarsServers: total number of deleted observations: %d", len(deleted)) + log. + WithField("numberOfDeletedObservations", len(deleted)). + Infof("deleteClosedTribalWarsServers: deleted observations") } } + + log. + WithField("executionTime", time.Since(start).String()). + Infoln("deleteClosedTribalWarsServers: finished executing") } -func (h *handler) updateBotStatus() { - if err := h.discord.UpdateStatus(h.status); err != nil { - log.Print("updateBotStatus: " + err.Error()) +func (w *worker) updateBotStatus() { + start := time.Now() + log.Info("updateBotStatus: updating bot status...") + + if err := w.discord.UpdateStatus(w.status); err != nil { + log.Error("updateBotStatus: " + err.Error()) } + + log. + WithField("executionTime", time.Since(start).String()). + Infoln("updateBotStatus: bot status has been updated") } diff --git a/discord/discord.go b/discord/discord.go index 7b0d5e3..d7442af 100644 --- a/discord/discord.go +++ b/discord/discord.go @@ -5,6 +5,7 @@ import ( "fmt" "strings" + "github.com/sirupsen/logrus" "github.com/tribalwarshelp/dcbot/message" "github.com/tribalwarshelp/dcbot/group" @@ -16,6 +17,8 @@ import ( "github.com/bwmarrin/discordgo" ) +var log = logrus.WithField("package", "discord") + type handler struct { cmd Command requireAdmPermissions bool @@ -240,8 +243,7 @@ func (s *Session) handleNewMessage(_ *discordgo.Session, m *discordgo.MessageCre } splitted := strings.Split(m.Content, " ") - argsLength := len(splitted) - 1 - args := splitted[1 : argsLength+1] + args := splitted[1:] server := &models.Server{ ID: m.GuildID, Lang: message.GetDefaultLanguage().String(), @@ -256,7 +258,8 @@ func (s *Session) handleNewMessage(_ *discordgo.Session, m *discordgo.MessageCre localizer: message.NewLocalizer(server.Lang), } - h := s.handlers.find(Command(splitted[0])) + cmd := Command(splitted[0]) + h := s.handlers.find(cmd) if h != nil { if h.requireAdmPermissions { if m.GuildID == "" { @@ -267,6 +270,16 @@ func (s *Session) handleNewMessage(_ *discordgo.Session, m *discordgo.MessageCre return } } + log. + WithFields(logrus.Fields{ + "serverID": server.ID, + "lang": server.Lang, + "command": cmd, + "args": args, + "authorID": m.Author.ID, + "authorUsername": m.Author.Username, + }). + Info("handleNewMessage: Executing command") h.fn(ctx, m, args...) return } diff --git a/go.mod b/go.mod index edb41ba..9a8cc4d 100644 --- a/go.mod +++ b/go.mod @@ -10,10 +10,11 @@ require ( github.com/nicksnyder/go-i18n/v2 v2.1.1 github.com/pkg/errors v0.9.1 github.com/robfig/cron/v3 v3.0.1 + github.com/sirupsen/logrus v1.7.0 github.com/tribalwarshelp/golang-sdk v0.0.0-20200903125555-7b6975e64f6f github.com/tribalwarshelp/shared v0.0.0-20200824102353-ef15dea9c1a3 golang.org/x/crypto v0.0.0-20201016220609-9e8e0b390897 // indirect golang.org/x/net v0.0.0-20201016165138-7b1cca2348c0 // indirect - golang.org/x/sys v0.0.0-20201017003518-b09fb700fbb7 // indirect + golang.org/x/sys v0.0.0-20201022201747-fb209a7c41cd // indirect golang.org/x/text v0.3.3 ) diff --git a/go.sum b/go.sum index 56a183e..72c4f62 100644 --- a/go.sum +++ b/go.sum @@ -112,7 +112,10 @@ github.com/robfig/cron/v3 v3.0.1 h1:WdRxkvbJztn8LMz/QEvLN5sBU+xKpSqwwUO1Pjr4qDs= github.com/robfig/cron/v3 v3.0.1/go.mod h1:eQICP3HwyT7UooqI/z+Ov+PtYAWygg1TEWWzGIFLtro= github.com/segmentio/encoding v0.2.0 h1:lmwUV/WjSX7pL1pbK4MEQBH/M7K2NrgYymeSc1pV1W8= github.com/segmentio/encoding v0.2.0/go.mod h1:MJjRE6bMDocliO2FyFC2Dusp+uYdBfHWh5Bw7QyExto= +github.com/sirupsen/logrus v1.7.0 h1:ShrD1U9pZB12TX0cVy0DtePoCH97K8EtX+mg7ZARUtM= +github.com/sirupsen/logrus v1.7.0/go.mod h1:yWOB1SBYBC5VeMP7gHvWumXLIWorT60ONWic61uBYv0= github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME= +github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXfy6kDkUVs= github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI= github.com/stretchr/testify v1.5.1 h1:nOGnQDM7FYENwehXlg/kFVnos3rEvtKTjRvOWSzb6H4= github.com/stretchr/testify v1.5.1/go.mod h1:5W2xD1RspED5o8YsWQXVCued0rvSQ+mT+I5cxcmMvtA= @@ -198,6 +201,7 @@ golang.org/x/sys v0.0.0-20190904154756-749cb33beabd/go.mod h1:h1NjWce9XRLGQEsW7w golang.org/x/sys v0.0.0-20191001151750-bb3f8db39f24/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20191005200804-aed5e4c7ecf9/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20191010194322-b09406accb47/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= +golang.org/x/sys v0.0.0-20191026070338-33540a1f6037/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20191120155948-bd437916bb0e/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20200323222414-85ca7c5b95cd/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20200519105757-fe76b779f299/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= @@ -208,8 +212,8 @@ golang.org/x/sys v0.0.0-20200930185726-fdedc70b468f/go.mod h1:h1NjWce9XRLGQEsW7w golang.org/x/sys v0.0.0-20201009025420-dfb3f7c4e634/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20201015000850-e3ed0017c211 h1:9UQO31fZ+0aKQOFldThf7BKPMJTiBfWycGh/u3UoO88= golang.org/x/sys v0.0.0-20201015000850-e3ed0017c211/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= -golang.org/x/sys v0.0.0-20201017003518-b09fb700fbb7 h1:XtNJkfEjb4zR3q20BBBcYUykVOEMgZeIUOpBPfNYgxg= -golang.org/x/sys v0.0.0-20201017003518-b09fb700fbb7/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= +golang.org/x/sys v0.0.0-20201022201747-fb209a7c41cd h1:WgqgiQvkiZWz7XLhphjt2GI2GcGCTIZs9jqXMWmH+oc= +golang.org/x/sys v0.0.0-20201022201747-fb209a7c41cd/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/text v0.3.0 h1:g61tztE5qeGQ89tm6NTjjM9VPIm088od1l6aSorWRWg= golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ= golang.org/x/text v0.3.2 h1:tW2bmiBqwgJj/UpqtC8EpXEZVYOwU0yG4iWbprSVAcs= diff --git a/main.go b/main.go index a8ee5ea..3e78b69 100644 --- a/main.go +++ b/main.go @@ -8,6 +8,7 @@ import ( "strings" "syscall" + "github.com/sirupsen/logrus" "github.com/tribalwarshelp/dcbot/message" "github.com/tribalwarshelp/golang-sdk/sdk" @@ -38,26 +39,41 @@ func init() { if mode.Get() == mode.DevelopmentMode { godotenv.Load(".env.development") } + + customFormatter := new(logrus.TextFormatter) + customFormatter.TimestampFormat = "2006-01-02 15:04:05" + customFormatter.FullTimestamp = true + logrus.SetFormatter(customFormatter) } func main() { dir, err := os.Getwd() if err != nil { - log.Fatal(err) + logrus.Fatal(err) } - if err := message.LoadMessageFiles(path.Join(dir, "message", "translations")); err != nil { - log.Fatal(err) + dirWithMessages := path.Join(dir, "message", "translations") + if err := message.LoadMessageFiles(dirWithMessages); err != nil { + logrus.Fatal(err) } + logrus.WithField("dir", dirWithMessages). + WithField("languages", message.LanguageTags()). + Info("Loaded messages") - db := pg.Connect(&pg.Options{ + dbOptions := &pg.Options{ User: os.Getenv("DB_USER"), Password: os.Getenv("DB_PASSWORD"), Database: os.Getenv("DB_NAME"), Addr: os.Getenv("DB_HOST") + ":" + os.Getenv("DB_PORT"), - }) + } + dbFields := logrus.Fields{ + "user": dbOptions.User, + "database": dbOptions.Database, + "addr": dbOptions.Addr, + } + db := pg.Connect(dbOptions) defer func() { if err := db.Close(); err != nil { - log.Fatal(err) + logrus.WithFields(dbFields).Fatalln(err) } }() if strings.ToUpper(os.Getenv("LOG_DB_QUERIES")) == "TRUE" { @@ -65,19 +81,21 @@ func main() { Verbose: true, }) } + logrus.WithFields(dbFields).Info("Connected to the database") serverRepo, err := server_repository.NewPgRepo(db) if err != nil { - log.Fatal(err) + logrus.Fatal(err) } groupRepo, err := group_repository.NewPgRepo(db) if err != nil { - log.Fatal(err) + logrus.Fatal(err) } observationRepo, err := observation_repository.NewPgRepo(db) if err != nil { - log.Fatal(err) + logrus.Fatal(err) } + logrus.Info("Loaded all repositories") api := sdk.New(os.Getenv("API_URL")) @@ -91,9 +109,14 @@ func main() { API: api, }) if err != nil { - log.Fatal(err) + logrus.Fatal(err) } defer sess.Close() + logrus.WithFields(logrus.Fields{ + "api": os.Getenv("API_URL"), + "commandPrefix": commandPrefix, + "status": status, + }).Info("Initialized new Discord session") c := cron.New(cron.WithChain( cron.SkipIfStillRunning(cron.VerbosePrintfLogger(log.New(os.Stdout, "cron: ", log.LstdFlags))), @@ -108,12 +131,13 @@ func main() { }) c.Start() defer c.Stop() + logrus.Info("Started cron worker") - log.Print("Bot is waiting for your actions!") + logrus.Info("Bot is waiting for your actions!") channel := make(chan os.Signal, 1) signal.Notify(channel, os.Interrupt, os.Kill, syscall.SIGTERM, syscall.SIGINT) <-channel - log.Print("shutting down") + logrus.Info("shutting down") }