Skip to content

Commit

Permalink
enhance: various logging and docs fixes (#183)
Browse files Browse the repository at this point in the history
  • Loading branch information
@wass3r
wass3r committed Jul 20, 2021
1 parent 0c4e051 commit 3b7a296
Show file tree
Hide file tree
Showing 23 changed files with 251 additions and 221 deletions.
9 changes: 8 additions & 1 deletion .env.example
View file
Original file line number Diff line number Diff line change
@@ -1,2 +1,9 @@
SLACK_TOKEN=
SLACK_SIGNING_SECRET=
SLACK_APP_TOKEN=
SLACK_SIGNING_SECRET=
SLACK_EVENTS_CALLBACK_PATH=

DISCORD_TOKEN=
DISCORD_SERVER_ID=

TELEGRAM_TOKEN=
2 changes: 1 addition & 1 deletion README.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -86,4 +86,4 @@ Inspired by [Hexbot.io](https://github.com/mmcquillan/hex)

## Contributors

* [List of contributors](/target/flottbot/graphs/contributors)
* [List of contributors](https://github.com/target/flottbot/graphs/contributors)
53 changes: 33 additions & 20 deletions core/configure.go
View file
Original file line number Diff line number Diff line change
@@ -1,6 +1,7 @@
package core

import (
"io"
"os"
"strings"

Expand All @@ -16,24 +17,36 @@ var defaultSlackListenerPort = "3000"
// Configure searches the config directory for the bot.yml to create a Bot object.
// The Bot object will be passed around to make accessible system-specific information.
func Configure(bot *models.Bot) {
log.Info().Msg("Configuring bot...")
log.Info().Msg("configuring bot...")

initLogger(bot)

validateRemoteSetup(bot)

configureChatApplication(bot)

bot.Log.Info().Msgf("Configured bot '%s'!", bot.Name)
bot.Log.Info().Msgf("configured bot '%s'!", bot.Name)
}

// initLogger sets log configuration for the bot
func initLogger(b *models.Bot) {
b.Log = zerolog.New(os.Stdout).Level(zerolog.ErrorLevel)
var out io.Writer
var level zerolog.Level

// defaults
out = os.Stdout
level = zerolog.InfoLevel

// for CLI, use zerolog's ConsoleWriter
if b.CLI {
out = zerolog.ConsoleWriter{Out: os.Stderr}
}

if b.Debug {
b.Log = zerolog.New(os.Stdout).Level(zerolog.DebugLevel)
level = zerolog.DebugLevel
}

b.Log = zerolog.New(out).With().Timestamp().Logger().Level(level)
}

// configureChatApplication configures a user's specified chat application
Expand All @@ -57,7 +70,7 @@ func configureChatApplication(bot *models.Bot) {
// Discord bot token
token, err := utils.Substitute(bot.DiscordToken, emptyMap)
if err != nil {
bot.Log.Error().Msgf("could not set discord_token: %s", err.Error())
bot.Log.Error().Msgf("could not set 'discord_token': %s", err.Error())
bot.RunChat = false
}

Expand All @@ -67,14 +80,14 @@ func configureChatApplication(bot *models.Bot) {
// See https://support.discordapp.com/hc/en-us/articles/206346498-Where-can-I-find-my-User-Server-Message-ID-
serverID, err := utils.Substitute(bot.DiscordServerID, emptyMap)
if err != nil {
bot.Log.Error().Msgf("could not set discord_server_id: %s", err.Error())
bot.Log.Error().Msgf("could not set 'discord_server_id': %s", err.Error())
bot.RunChat = false
}

bot.DiscordServerID = serverID

if !isSet(token, serverID) {
bot.Log.Error().Msg("bot is not configured correctly for discord - check that discord_token and discord_server_id are set")
bot.Log.Error().Msg("bot is not configured correctly for discord - check that 'discord_token' and 'discord_server_id' are set")
bot.RunChat = false
}

Expand All @@ -84,12 +97,12 @@ func configureChatApplication(bot *models.Bot) {
case "telegram":
token, err := utils.Substitute(bot.TelegramToken, emptyMap)
if err != nil {
bot.Log.Error().Msgf("could not set telegram_token: %s", err.Error())
bot.Log.Error().Msgf("could not set 'telegram_token': %s", err.Error())
bot.RunChat = false
}

if !isSet(token) {
bot.Log.Error().Msg("bot is not configured correctly for telegram - check that telegram_token is set")
bot.Log.Error().Msg("bot is not configured correctly for telegram - check that 'telegram_token' is set")
bot.RunChat = false
}

Expand All @@ -110,52 +123,52 @@ func configureSlackBot(bot *models.Bot) {
// slack_token
token, err := utils.Substitute(bot.SlackToken, emptyMap)
if err != nil {
bot.Log.Error().Msgf("could not set slack_token: %s", err.Error())
bot.Log.Error().Msgf("could not set 'slack_token': %s", err.Error())
}

bot.SlackToken = token

// slack_app_token
appToken, err := utils.Substitute(bot.SlackAppToken, emptyMap)
if err != nil {
bot.Log.Warn().Msgf("could not set slack_app_token: %s", err.Error())
bot.Log.Warn().Msgf("could not set 'slack_app_token': %s", err.Error())
}

bot.SlackAppToken = appToken

// slack_signing_secret
signingSecret, err := utils.Substitute(bot.SlackSigningSecret, emptyMap)
if err != nil {
bot.Log.Warn().Msgf("could not set slack_signing_secret: %s", err.Error())
bot.Log.Warn().Msgf("could not set 'slack_signing_secret': %s", err.Error())
}

bot.SlackSigningSecret = signingSecret

// slack_events_callback_path
eCallbackPath, err := utils.Substitute(bot.SlackEventsCallbackPath, emptyMap)
if err != nil {
bot.Log.Warn().Msgf("could not set slack_events_callback_path: %s", err.Error())
bot.Log.Warn().Msgf("could not set 'slack_events_callback_path': %s", err.Error())
}

bot.SlackEventsCallbackPath = eCallbackPath

// slack_interactions_callback_path
iCallbackPath, err := utils.Substitute(bot.SlackInteractionsCallbackPath, emptyMap)
if err != nil {
bot.Log.Warn().Msgf("could not set slack_interactions_callback_path: %s", err.Error())
bot.Log.Warn().Msgf("could not set 'slack_interactions_callback_path': %s", err.Error())
}

bot.SlackInteractionsCallbackPath = iCallbackPath

// slack_listener_port
lPort, err := utils.Substitute(bot.SlackListenerPort, emptyMap)
if err != nil {
bot.Log.Warn().Msgf("could not set slack_listener_port: %s", err.Error())
bot.Log.Warn().Msgf("could not set 'slack_listener_port': %s", err.Error())
}

// set slack http listener port from config file or default
if !isSet(lPort) {
bot.Log.Warn().Msgf("slack_listener_port not set: %s", lPort)
bot.Log.Warn().Msgf("'slack_listener_port' not set: %s", lPort)
bot.Log.Info().Str("defaultSlackListenerPort", defaultSlackListenerPort).Msg("using default slack listener port.")
lPort = defaultSlackListenerPort
}
Expand All @@ -169,7 +182,7 @@ func configureSlackBot(bot *models.Bot) {
isSocketMode := isSet(token, appToken)
isEventsAPI := isSet(token, signingSecret, eCallbackPath)
if !isSocketMode && !isEventsAPI {
bot.Log.Error().Msg("bot is not configured correctly for slack - check that either slack_token and slack_app_token OR slack_token, slack_signing_secret, and slack_events_callback_path are set")
bot.Log.Error().Msg("must have either 'slack_token', 'slack_app_token' or 'slack_token', 'slack_signing_secret', and 'slack_events_callback_path' set")
bot.RunChat = false
}
}
Expand All @@ -184,18 +197,18 @@ func validateRemoteSetup(bot *models.Bot) {
}

if !bot.CLI && bot.ChatApplication == "" {
bot.Log.Fatal().Msgf("No chat_application specified and cli mode is not enabled. Exiting...")
bot.Log.Error().Msgf("no 'chat_application' specified and cli mode is not enabled. exiting...")
}

if bot.Scheduler {
bot.RunScheduler = true
if bot.CLI && bot.ChatApplication == "" {
bot.Log.Warn().Msg("Scheduler does not support scheduled outputs to CLI mode")
bot.Log.Warn().Msg("scheduler does not support scheduled outputs to cli mode")
bot.RunScheduler = false
}

if bot.ChatApplication == "" {
bot.Log.Warn().Msg("Scheduler did not find any configured chat applications. Scheduler is closing")
bot.Log.Warn().Msg("scheduler did not find any configured chat applications - scheduler is closing")
bot.RunScheduler = false
}
}
Expand Down
11 changes: 3 additions & 8 deletions core/configure_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -12,25 +12,20 @@ func TestInitLogger(t *testing.T) {
bot *models.Bot
}

testBot := new(models.Bot)

// Test setting the error and debug level flags
levelTests := []struct {
name string
args args
want string
}{
{"error level set", args{testBot}, "error"},
{"debug level set", args{testBot}, "debug"},
{"error level set", args{bot: &models.Bot{}}, "info"},
{"debug level set", args{bot: &models.Bot{Debug: true}}, "debug"},
}
for _, tt := range levelTests {
if tt.want == "debug" {
testBot.Debug = true
}
t.Run(tt.name, func(t *testing.T) {
initLogger(tt.args.bot)
if tt.want != tt.args.bot.Log.GetLevel().String() {
t.Errorf("initLogger() wanted level set at %s, but got %s", tt.want, tt.args.bot.Log.GetLevel().String())
t.Errorf("initLogger() wanted level set at '%s', but got '%s'", tt.want, tt.args.bot.Log.GetLevel().String())
}
})
}
Expand Down
47 changes: 22 additions & 25 deletions core/matcher.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -75,15 +75,15 @@ func handleChatServiceRule(outputMsgs chan<- models.Message, message models.Mess
if rule.Respond != "" || rule.Hear != "" {
// You can only use 'respond' OR 'hear'
if rule.Respond != "" && rule.Hear != "" {
bot.Log.Debug().Msgf("Rule '%s' has both 'hear' and 'match' or 'respond' defined. Please choose one or the other", rule.Name)
bot.Log.Debug().Msgf("rule '%s' has both 'hear' and 'match' or 'respond' defined. please choose one or the other", rule.Name)
}
// Args are not implemented for 'hear'
if rule.Hear != "" && len(rule.Args) > 0 {
bot.Log.Debug().Msgf("Rule '%s' has both 'args' and 'hear' set. To use 'args', use 'respond' instead of 'hear'", rule.Name)
bot.Log.Debug().Msgf("rule '%s' has both 'args' and 'hear' set. to use 'args', use 'respond' instead of 'hear'", rule.Name)
}

if hit && message.ThreadTimestamp != "" && rule.IgnoreThreads {
bot.Log.Debug().Msg("Response suppressed due to 'ignore_threads' being set")
bot.Log.Debug().Msg("response suppressed due to 'ignore_threads' being set")
return true, true
}

Expand All @@ -93,7 +93,7 @@ func handleChatServiceRule(outputMsgs chan<- models.Message, message models.Mess
}

if hit {
bot.Log.Debug().Msgf("Found rule match '%s' for input '%s'", rule.Name, message.Input)
bot.Log.Info().Msgf("found rule match '%s' for input '%s'", rule.Name, message.Input)
// Don't go through more rules if rule is matched
match, stopSearch = true, true
// Publish metric to prometheus - metricname will be combination of bot name and rule name
Expand Down Expand Up @@ -136,7 +136,7 @@ func handleNoMatch(outputMsgs chan<- models.Message, message models.Message, hit
if message.Type == models.MsgTypeDirect || message.BotMentioned {
// Do not send help message if DisableNoMatchHelp is true
if !bot.DisableNoMatchHelp {
bot.Log.Debug().Msg("Bot was addressed, but no rule matched. Showing help")
bot.Log.Info().Msg("bot was addressed, but no rule matched - showing help")
// Publish metric as none
Prommetric(bot.Name+"-None", bot)
// Set custom_help_text if it is set in bot.yml
Expand Down Expand Up @@ -167,8 +167,9 @@ func isValidHitChatRule(message *models.Message, rule models.Rule, processedInpu
if !canRunRule {
message.Output = fmt.Sprintf("You are not allowed to run the '%s' rule.", rule.Name)
// forcing direct message
message.DirectMessageOnly = true
// message.DirectMessageOnly = true
message.Type = models.MsgTypeDirect
message.IsEphemeral = true
return false
}
// If this wasn't a 'hear' rule, handle the args
Expand All @@ -189,29 +190,25 @@ func isValidHitChatRule(message *models.Message, rule models.Rule, processedInpu
}
if varArgs > 1 {
// error, can ony have 1
msg := fmt.Sprintf("You cannot specify more than 1 variable argument")
message.Output = msg
message.Output = "you cannot specify more than 1 variable argument"
return false
}
if len(rule.Args) > 0 && strings.HasSuffix(rule.Args[len(rule.Args)-1], "+") {
if optionalArgs > 0 {
// error, cannot combine optional and varargs
msg := fmt.Sprintf("You cannot combine optional arguments with variable arguments")
message.Output = msg
message.Output = "you cannot combine optional arguments with variable arguments"
return false
}
} else if varArgs == 1 {
// error, vararg but not in last position
msg := fmt.Sprintf("You must specify the variable argument in the last argument position")
message.Output = msg
message.Output = "you must specify the variable argument in the last argument position"
return false
}
// ensure we only require args that don't end with '?'
requiredArgs = len(rule.Args) - optionalArgs
// Are we expecting a number of args but don't have as many as the rule defines? Send a helpful message
if len(rule.Args) > 0 && requiredArgs > len(args) {
msg := fmt.Sprintf("You might be missing an argument or two. This is what I'm looking for\n```%s```", rule.HelpText)
message.Output = msg
message.Output = fmt.Sprintf("you might be missing an argument or two - this is what i'm looking for\n```%s```", rule.HelpText)
return false
}
// Go through the supplied args and make them available as variables
Expand Down Expand Up @@ -250,15 +247,15 @@ func doRuleActions(message models.Message, outputMsgs chan<- models.Message, rul
switch strings.ToLower(action.Type) {
// HTTP actions.
case "get", "post", "put":
bot.Log.Debug().Msgf("Executing action '%s'...", action.Name)
bot.Log.Debug().Msgf("executing action '%s'...", action.Name)
err = handleHTTP(action, &message, bot)
// Exec (script) actions
case "exec":
bot.Log.Debug().Msgf("Executing action '%s'...", action.Name)
bot.Log.Debug().Msgf("executing action '%s'...", action.Name)
err = handleExec(action, &message, bot)
// Normal message/log actions
case "message", "log":
bot.Log.Debug().Msgf("Executing action '%s'...", action.Name)
bot.Log.Debug().Msgf("executing action '%s'...", action.Name)
// Log actions cannot direct message users by default
directive := rule.DirectMessageOnly
if action.Type == "log" {
Expand All @@ -269,7 +266,7 @@ func doRuleActions(message models.Message, outputMsgs chan<- models.Message, rul
err = handleMessage(action, outputMsgs, &copy, directive, rule.StartMessageThread, hitRule, bot)
// Fallback to error if action type is invalid
default:
bot.Log.Error().Msgf("The rule '%s' of type %s is not a supported action", action.Name, action.Type)
bot.Log.Error().Msgf("the rule '%s' of type '%s' is not a supported action", action.Name, action.Type)
}

// Handle reaction update
Expand Down Expand Up @@ -332,7 +329,7 @@ func craftResponse(rule models.Rule, msg models.Message, bot *models.Bot) (strin

// Simple warning that we will ignore 'output_to_rooms' when 'direct_message_only' is set
if rule.DirectMessageOnly && len(rule.OutputToRooms) > 0 {
bot.Log.Debug().Msgf("The rule '%s' has 'direct_message_only' set, 'output_to_rooms' will be ignored", rule.Name)
bot.Log.Debug().Msgf("the rule '%s' has 'direct_message_only' set, 'output_to_rooms' will be ignored", rule.Name)
}

// Use FormatOutput as source for output and find variables and replace content the variable exists
Expand Down Expand Up @@ -384,19 +381,19 @@ func handleHTTP(action models.Action, msg *models.Message, bot *models.Bot) erro
return fmt.Errorf("no URL was supplied for the '%s' action named: %s", action.Type, action.Name)
}

resp, err := handlers.HTTPReq(action, msg)
resp, err := handlers.HTTPReq(action, msg, bot)
if err != nil {
msg.Error = fmt.Sprintf("Error in request made by action '%s'. See bot admin for more information", action.Name)
msg.Error = fmt.Sprintf("error in request made by action '%s' - see bot admin for more information", action.Name)
return err
}

// Just a friendly debugger warning on failed requests
if resp.Status >= 400 {
bot.Log.Debug().Msgf("Error in request made by action '%s'. %s returned %d with response: `%s`", action.Name, action.URL, resp.Status, resp.Raw)
bot.Log.Debug().Msgf("error in request made by action '%s' - '%s' returned '%d' with response: %s", action.Name, action.URL, resp.Status, resp.Raw)
}

// Always store raw response
bot.Log.Debug().Msgf("Successfully executed action '%s'", action.Name)
bot.Log.Debug().Msgf("successfully executed action '%s'", action.Name)
// Set explicit variables to make raw response output, http status code accessible in rules
msg.Vars["_raw_http_output"] = resp.Raw
msg.Vars["_raw_http_status"] = strconv.Itoa(resp.Status)
Expand Down Expand Up @@ -454,7 +451,7 @@ func handleMessage(action models.Action, outputMsgs chan<- models.Message, msg *
msg.Output = output
// Send to desired room(s)
if direct && len(action.LimitToRooms) > 0 { // direct=true and limit_to_rooms is specified
bot.Log.Debug().Msgf("You have specified to send only direct messages. The 'limit_to_rooms' field on the '%s' action will be ignored", action.Name)
bot.Log.Debug().Msgf("'direct_message_only' is set - 'limit_to_rooms' field on the '%s' action will be ignored", action.Name)
} else if !direct && len(action.LimitToRooms) > 0 { // direct=false and limit_to_rooms is specified
msg.OutputToRooms = utils.GetRoomIDs(action.LimitToRooms, bot)

Expand Down Expand Up @@ -497,7 +494,7 @@ func updateReaction(action models.Action, rule *models.Rule, vars map[string]str

t, err = template.New("update_reaction").Funcs(sprig.FuncMap()).Parse(action.Reaction)
if err != nil {
bot.Log.Error().Msgf("Failed to update Reaction %s", rule.Reaction)
bot.Log.Error().Msgf("failed to update reaction '%s'", rule.Reaction)
return
}
buf := new(bytes.Buffer)
Expand Down

0 comments on commit 3b7a296

Please sign in to comment.