diff --git a/.gitignore b/.gitignore index dd481936..ed11982f 100644 --- a/.gitignore +++ b/.gitignore @@ -16,3 +16,9 @@ # Generated binaries, checksums /release_assets + +# Temporary or local content to ignore +/scratch + +# Ignore temporary log files +/*.log diff --git a/CHANGELOG.md b/CHANGELOG.md index 472e9f56..5eec687e 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -24,7 +24,62 @@ The following types of changes will be recorded in this file: ## [Unreleased] -- placeholder +### Added + +- Add support for Microsoft Teams notifications + - configurable retry, retry delay settings + - rate-limited submissions to help prevent unintentional abuse of remote API + - currently hard-coded, but will likely expose this as a flag in a future + release + +- Add monitoring/reporting of notification channels with pending items + +- Add monitoring/reporting of notification statistics + - total + - pending + - success + - failure + +- Capture `Ctrl+C` and attempt graceful shutdown + +- Plumbed `context` throughout majority of application for cancellation and + timeout functionality + - still learning proper use of this package, so likely many mistakes that + will need to be fixed in a future release + +- Logging + - add *many* more debug statements to help with troubleshooting + +### Changed + +- Dependencies + - Use `atc0005/go-teams-notify` package + - fork of original package with current features and some additional + changes not yet accepted upstream + - Use `atc0005/send2teams` package + - provides wrapper for upstream functionality with message retry, delay + functionality + - provides formatting helper functions + - provides additional webhook URL validation + - Drop indirect dependency + - Update `golang/gddo` + - Add commented entries to have Go use local copies of packages for fast + prototyping work + +### Fixed + +- GoDoc formatting + - remove forced line-wrap which resulted in unintentional code block + formatting of non-code content + +- Refactor logging, flag handling + - not user visible, so not recording as a "change" + +- Manually flush `http.ResponseWriter` to (massively) speed up response time + for client requests + +- Move template parsing to `main()` in an effort to speed up endpoint response + time for client requests ## [v0.3.3] - 2020-03-14 diff --git a/README.md b/README.md index 86a65fa0..7f42522e 100644 --- a/README.md +++ b/README.md @@ -24,6 +24,7 @@ Small utility to assist with building HTTP endpoints - [How to use it](#how-to-use-it) - [General](#general) - [Examples](#examples) + - [Local: Send client request details to Microsoft Teams](#local-send-client-request-details-to-microsoft-teams) - [Local: View headers submitted by `GET` request using your browser](#local-view-headers-submitted-by-get-request-using-your-browser) - [Local: Submit JSON payload using `curl`, receive unformatted response](#local-submit-json-payload-using-curl-receive-unformatted-response) - [Local: Submit JSON payload using `curl` to JSON-specific endpoint, get formatted response](#local-submit-json-payload-using-curl-to-json-specific-endpoint-get-formatted-response) @@ -64,9 +65,17 @@ in testing other tools that submit data via HTTP requests. endpoint - Optional, colorization and custom ident control for formatted JSON output +- Optional submission of client request details to a user-specified Microsoft + Teams channel (by providing a webhook URL) + - User configurable logging settings - levels, format and output (see command-line arguments table) +- Message delivery retry support with retry and retry delay values + configurable via flag + - currently used by Microsoft Teams notifications support, also intended for + use with future email notifications support + ### Future | Priority | Milestone | Description | @@ -166,16 +175,19 @@ Tested using: ### Command-line Arguments -| Option | Required | Default | Repeat | Possible | Description | -| ------------ | -------- | ----------- | ------ | ------------------------------------------ | ------------------------------------------------------------------------------------------------------------------ | -| `h`, `help` | No | `false` | No | `h`, `help` | Show Help text along with the list of supported flags. | -| `port` | No | `8000` | No | *valid whole numbers* | TCP port that this application should listen on for incoming HTTP requests. | -| `ipaddr` | No | `localhost` | No | *valid fqdn, local name or IP Address* | Local IP Address that this application should listen on for incoming HTTP requests. | -| `color` | No | `false` | No | `true`, `false` | Whether JSON output should be colorized. | -| `indent-lvl` | No | `2` | No | *1+; positive whole numbers* | Number of spaces to use when indenting colorized JSON output. Has no effect unless colorized JSON mode is enabled. | -| `log-lvl` | No | `info` | No | `fatal`, `error`, `warn`, `info`, `debug` | Log message priority filter. Log messages with a lower level are ignored. | -| `log-out` | No | `stdout` | No | `stdout`, `stderr` | Log messages are written to this output target. | -| `log-fmt` | No | `text` | No | `cli`, `json`, `logfmt`, `text`, `discard` | Use the specified `apex/log` package "handler" to output log messages in that handler's format. | +| Option | Required | Default | Repeat | Possible | Description | +| --------------- | -------- | -------------- | ------ | ------------------------------------------ | ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| `h`, `help` | No | `false` | No | `h`, `help` | Show Help text along with the list of supported flags. | +| `port` | No | `8000` | No | *valid whole numbers* | TCP port that this application should listen on for incoming HTTP requests. | +| `ipaddr` | No | `localhost` | No | *valid fqdn, local name or IP Address* | Local IP Address that this application should listen on for incoming HTTP requests. | +| `color` | No | `false` | No | `true`, `false` | Whether JSON output should be colorized. | +| `indent-lvl` | No | `2` | No | *1+; positive whole numbers* | Number of spaces to use when indenting colorized JSON output. Has no effect unless colorized JSON mode is enabled. | +| `log-lvl` | No | `info` | No | `fatal`, `error`, `warn`, `info`, `debug` | Log message priority filter. Log messages with a lower level are ignored. | +| `log-out` | No | `stdout` | No | `stdout`, `stderr` | Log messages are written to this output target. | +| `log-fmt` | No | `text` | No | `cli`, `json`, `logfmt`, `text`, `discard` | Use the specified `apex/log` package "handler" to output log messages in that handler's format. | +| `webhook-url` | No | *empty string* | No | *valid webhook URL* | The Webhook URL provided by a preconfigured Connector. If specified, this application will attempt to send client request details to the Microsoft Teams channel associated with the webhook URL. | +| `retries` | No | `2` | No | *positive whole number* | The number of attempts that this application will make to deliver messages before giving up. | +| `retries-delay` | No | `2` | No | *positive whole number* | The number of seconds that this application will wait before making another delivery attempt. | ### Worth noting @@ -194,6 +206,12 @@ Tested using: | `text` | human-friendly colored output | | `discard` | discards all logs | +- Microsoft Teams webhook URLs have one of two known prefixes. Both are valid + as of this writing, but new webhook URLs only appear to be generated using + the first prefix. + 1. + 1. + ## How to use it ### General @@ -214,6 +232,11 @@ Tested using: - skip this step if you plan to only submit HTTP requests from your own system to this application running *on* your system - e.g., `localhost:8000` +1. Run this application using your preferred settings by specifying the + appropriate command-line flag options. + - e.g., if you specify a valid Outlook/Microsoft Teams webhook URL, this + application will attempt to send client request details to the associated + Microsoft Teams channel. 1. Visit the index page for this application at the appropriate IP Address and the port you specified - e.g., `http://localhost:8000/` @@ -221,6 +244,16 @@ Tested using: ### Examples +#### Local: Send client request details to Microsoft Teams + +**TODO**: Update this to include real log output from using this option. + +```ShellSession +$ ./bounce.exe -webhook-url "https://outlook.office.com/webhook/a1269812-6d10-44b1-abc5-b84f93580ba0@9e7b80c7-d1eb-4b52-8582-76f921e416d9/IncomingWebhook/3fdd6767bae44ac58e5995547d66a4e4/f332c8d9-3397-4ac5-957b-b8e3fc465a8c" + +INSERT REAL OUTPUT HERE +``` + #### Local: View headers submitted by `GET` request using your browser ```ShellSession @@ -413,6 +446,28 @@ and with colorized JSON output enabled: - - - + - + - + - + - explains benefits of 1-deep buffered channels (asynchronous) vs + unbuffered (synchronous) + - Bakul Shah: *In general, synchronize only when you have to. Here the main thread + wants to know when the worker thread terminates but the worker thread + doesn't care when the main thread gets around to reading from "done". + Using a 1 deep buffer channel exactly captures this usage pattern. An + unbuffered channel would make the worker thread "rendezvous" with the + main thread, which is unnecessary.* + - + - + - + +- Contexts + - + - + - + - + - + - - Request body - @@ -422,6 +477,8 @@ and with colorized JSON output enabled: - HTTP Server - - + - + - - Logging - @@ -435,6 +492,9 @@ and with colorized JSON output enabled: - Splunk / JSON payload - [Splunk Enterprise (v8.0.1) > Alerting Manual > Use a webhook alert action](https://docs.splunk.com/Documentation/Splunk/8.0.1/Alert/Webhooks) +- Microsoft Teams + - + [screenshot-uncolored-json-output]: media/v0.2.0/bounce-json-uncolored-output-2020-03-04.png "Uncolored JSON output example screenshot" [screenshot-colored-json-output-v0.2.0]: media/v0.2.0/bounce-json-colorizer-output-2020-03-04.png "Colored JSON output example screenshot for v0.2.0 release" diff --git a/cmd/bounce/client-ip.go b/cmd/bounce/client-ip.go index 9570d7dd..52a126b7 100644 --- a/cmd/bounce/client-ip.go +++ b/cmd/bounce/client-ip.go @@ -18,8 +18,8 @@ import ( "github.com/apex/log" ) -// GetIP gets a requests IP address by reading off the forwarded-for -// header (for proxies) and falls back to use the remote address. +// GetIP gets a request's IP address by reading off the forwarded-for +// header (for proxies) and falls back to using the remote address. func GetIP(r *http.Request) string { forwarded := r.Header.Get("X-FORWARDED-FOR") log.WithFields(log.Fields{ diff --git a/cmd/bounce/handlers.go b/cmd/bounce/handlers.go index 445fa8eb..ed793879 100644 --- a/cmd/bounce/handlers.go +++ b/cmd/bounce/handlers.go @@ -9,6 +9,7 @@ package main import ( "bytes" + "context" "encoding/json" "errors" "fmt" @@ -40,15 +41,29 @@ const ( // TODO: Find a better location for this constant const MB int64 = 1048576 +// clientRequestDetails is used to bundle various client request details for +// processing by templates or notification functions. +type clientRequestDetails struct { + Datestamp string + EndpointPath string + HTTPMethod string + ClientIPAddress string + Headers http.Header + Body string + BodyError string + FormattedBody string + FormattedBodyError string + RequestError string + ContentTypeError string +} + // handleIndex receives our HTML template and our defined routes as a pointer. // Both are used to generate a dynamic index of the available routes or // "endpoints" for users to target with test payloads. A pointer is used because // by the time this handler is defined, the full set of routes has *not* been // defined. Using a pointer, we are able to access the complete collection // of defined routes when this handler is finally called. -func handleIndex(templateText string, rs *routes.Routes) http.HandlerFunc { - - tmpl := htmlTemplate.Must(htmlTemplate.New("indexPage").Parse(templateText)) +func handleIndex(tmpl *htmlTemplate.Template, rs *routes.Routes) http.HandlerFunc { return func(w http.ResponseWriter, r *http.Request) { @@ -65,7 +80,7 @@ func handleIndex(templateText string, rs *routes.Routes) http.HandlerFunc { "http_method": r.Method, }).Debug("non-GET request received on GET-only endpoint") errorMsg := fmt.Sprintf( - "\nSorry, this endpoint only accepts %s requests.\n"+ + "Sorry, this endpoint only accepts %s requests. "+ "Please see the README for examples and then try again.", http.MethodGet, ) @@ -91,6 +106,7 @@ func handleIndex(templateText string, rs *routes.Routes) http.HandlerFunc { err := tmpl.Execute(w, *rs) if err != nil { http.Error(w, err.Error(), http.StatusInternalServerError) + ctxLog.Error(err.Error()) } } @@ -98,48 +114,49 @@ func handleIndex(templateText string, rs *routes.Routes) http.HandlerFunc { } // echoHandler echos back the HTTP request received by -func echoHandler(templateText string, coloredJSON bool, coloredJSONIndent int) http.HandlerFunc { +func echoHandler(ctx context.Context, tmpl *textTemplate.Template, coloredJSON bool, coloredJSONIndent int, notifyWorkQueue chan<- clientRequestDetails) http.HandlerFunc { return func(w http.ResponseWriter, r *http.Request) { // For now, we generate plain text responses //w.Header().Set("Content-Type", "text/plain") - type echoHandlerResponse struct { - Datestamp string - EndpointPath string - HTTPMethod string - ClientIPAddress string - Headers http.Header - Body string - BodyError string - FormattedBody string - FormattedBodyError string - RequestError string - ContentTypeError string - } - - ourResponse := echoHandlerResponse{} + ourResponse := clientRequestDetails{} mw := io.MultiWriter(w, os.Stdout) - tmpl := textTemplate.Must(textTemplate.New("echoHandler").Parse(templateText)) - + // TODO: Consider moving this "up" so that it can receive values as + // arguments instead of relying on them to be defined in the local + // scope? writeTemplate := func() { err := tmpl.Execute(mw, ourResponse) if err != nil { http.Error(w, err.Error(), http.StatusInternalServerError) + log.Errorf("error occurred while trying to execute template: %v", err) // We force a a return here since it is unlikely that we should // execute any other code after failing to generate/write out our // template return } + + // Manually flush http.ResponseWriter + // https://blog.simon-frey.eu/manual-flush-golang-http-responsewriter/ + if f, ok := w.(http.Flusher); ok { + log.Debug("echoHandler: Manually flushing http.ResponseWriter") + f.Flush() + } else { + log.Warn("echoHandler: http.Flusher interface not available, cannot flush http.ResponseWriter") + log.Warn("echoHandler: Not flushing http.ResponseWriter may cause a noticeable delay between requests") + } + } - log.Debug("echoHandler endpoint hit") + log.Debug("echoHandler: echoHandler endpoint hit") - ourResponse.Datestamp = time.Now().Format((time.RFC3339)) + // Work around Teams choosing to ignore time.RFC3339 designation and + // display as localtime by explicitly converting to localtime + ourResponse.Datestamp = time.Now().Format("2006-01-02 15:04:05") ourResponse.EndpointPath = r.URL.Path ourResponse.HTTPMethod = r.Method ourResponse.ClientIPAddress = GetIP(r) @@ -154,8 +171,12 @@ func echoHandler(templateText string, coloredJSON bool, coloredJSONIndent int) h case http.MethodGet: - // Write out what we have. Nothing further to do for this endpoint + // Write out what we have. writeTemplate() + + // Send to Notification Manager for further processing + go func() { notifyWorkQueue <- ourResponse }() + return case http.MethodPost: @@ -168,7 +189,13 @@ func echoHandler(templateText string, coloredJSON bool, coloredJSONIndent int) h ourResponse.BodyError = errorMsg http.Error(w, errorMsg, http.StatusBadRequest) + log.Error(errorMsg) + writeTemplate() + + // Send to Notification Manager for further processing + go func() { notifyWorkQueue <- ourResponse }() + return } @@ -184,12 +211,23 @@ func echoHandler(templateText string, coloredJSON bool, coloredJSONIndent int) h // the template against it writeTemplate() + // Send to Notification Manager for further processing + go func() { notifyWorkQueue <- ourResponse }() + + return + default: errorMsg := fmt.Sprintf("ERROR: Unsupported method %q received; please try again using %s method", r.Method, http.MethodPost) ourResponse.RequestError = errorMsg http.Error(w, errorMsg, http.StatusMethodNotAllowed) + log.Error("echoHandler: " + errorMsg) + writeTemplate() + + // Send to Notification Manager for further processing + go func() { notifyWorkQueue <- ourResponse }() + return } @@ -200,14 +238,20 @@ func echoHandler(templateText string, coloredJSON bool, coloredJSONIndent int) h case http.MethodGet: // TODO: Collect this for use with our template errorMsg := fmt.Sprintf( - "Sorry, this endpoint only accepts JSON data via %s requests.\n"+ + "Sorry, this endpoint only accepts JSON data via %s requests. "+ "Please see the README for examples and then try again.", http.MethodPost, ) ourResponse.RequestError = errorMsg http.Error(w, http.StatusText(http.StatusMethodNotAllowed), http.StatusMethodNotAllowed) + log.Error("echoHandler: " + errorMsg) + writeTemplate() + + // Send to Notification Manager for further processing + go func() { notifyWorkQueue <- ourResponse }() + return case http.MethodPost: @@ -227,7 +271,13 @@ func echoHandler(templateText string, coloredJSON bool, coloredJSONIndent int) h ourResponse.BodyError = errorMsg http.Error(w, errorMsg, http.StatusBadRequest) + log.Error(errorMsg) + writeTemplate() + + // Send to Notification Manager for further processing + go func() { notifyWorkQueue <- ourResponse }() + return } ourResponse.Body = string(requestBody) @@ -246,15 +296,25 @@ func echoHandler(templateText string, coloredJSON bool, coloredJSONIndent int) h ourResponse.FormattedBodyError = fmt.Sprintf("%s: %s", errorPrefix, mr.msg) http.Error(w, mr.msg, mr.status) + writeTemplate() + + // Send to Notification Manager for further processing + go func() { notifyWorkQueue <- ourResponse }() + return } errorMsg := fmt.Sprintf("%s: %s", errorPrefix, err.Error()) ourResponse.FormattedBodyError = errorMsg - log.Error(errorMsg) http.Error(w, errorMsg, http.StatusInternalServerError) + log.Error("echoHandler: " + errorMsg) + writeTemplate() + + // Send to Notification Manager for further processing + go func() { notifyWorkQueue <- ourResponse }() + return } } @@ -294,20 +354,32 @@ func echoHandler(templateText string, coloredJSON bool, coloredJSONIndent int) h // the template against it writeTemplate() + // Send to Notification Manager for further processing + go func() { notifyWorkQueue <- ourResponse }() + default: errorMsg := fmt.Sprintf("ERROR: Unsupported method %q received; please try again using %s method", r.Method, http.MethodPost) ourResponse.RequestError = errorMsg http.Error(w, errorMsg, http.StatusMethodNotAllowed) + writeTemplate() + + // Send to Notification Manager for further processing + go func() { notifyWorkQueue <- ourResponse }() + return } default: // Template is not used for this code block, so no need to account for // the output in the template - log.Debugf("Rejecting request %q; not explicitly handled by a route.", r.URL.Path) + log.Debugf("echoHandler: Rejecting request %q; not explicitly handled by a route.", r.URL.Path) http.NotFound(w, r) + + // Send to Notification Manager for further processing + go func() { notifyWorkQueue <- ourResponse }() + return } diff --git a/cmd/bounce/main.go b/cmd/bounce/main.go index dd77e866..c5e8a692 100644 --- a/cmd/bounce/main.go +++ b/cmd/bounce/main.go @@ -8,21 +8,22 @@ package main import ( + "context" "errors" "flag" "fmt" + htmlTemplate "html/template" "net/http" "os" + "os/signal" + textTemplate "text/template" "github.com/atc0005/bounce/config" "github.com/atc0005/bounce/routes" + goteamsnotify "github.com/atc0005/go-teams-notify" + send2teams "github.com/atc0005/send2teams/teams" "github.com/apex/log" - "github.com/apex/log/handlers/cli" - "github.com/apex/log/handlers/discard" - "github.com/apex/log/handlers/json" - "github.com/apex/log/handlers/logfmt" - "github.com/apex/log/handlers/text" ) // for handler in cli discard es graylog json kinesis level logfmt memory @@ -34,6 +35,11 @@ import ( func main() { + // Toggle debug logging from library packages as needed to troubleshoot + // implementation work + goteamsnotify.DisableLogging() + send2teams.DisableLogging() + // This will use default logging settings (level filter, destination) // as the application hasn't "booted up" far enough to apply custom // choices yet. @@ -47,41 +53,79 @@ func main() { log.Fatalf("Failed to initialize application: %s", err) } - var logOutput *os.File - switch appConfig.LogOutput { - case config.LogOutputStderr: - logOutput = os.Stderr - case config.LogOutputStdout: - logOutput = os.Stdout - } + log.Debugf("AppConfig: %+v", appConfig) - switch appConfig.LogFormat { - case config.LogFormatCLI: - log.SetHandler(cli.New(logOutput)) - case config.LogFormatJSON: - log.SetHandler(json.New(logOutput)) - case config.LogFormatLogFmt: - log.SetHandler(logfmt.New(logOutput)) - case config.LogFormatText: - log.SetHandler(text.New(logOutput)) - case config.LogFormatDiscard: - log.SetHandler(discard.New()) - } + mux := http.NewServeMux() - switch appConfig.LogLevel { - case config.LogLevelFatal: - log.SetLevel(log.FatalLevel) - case config.LogLevelError: - log.SetLevel(log.ErrorLevel) - case config.LogLevelWarn: - log.SetLevel(log.WarnLevel) - case config.LogLevelInfo: - log.SetLevel(log.InfoLevel) - case config.LogLevelDebug: - log.SetLevel(log.DebugLevel) + // Apply "default" timeout settings provided by Simon Frey; override the + // default "wait forever" configuration. + // FIXME: Refine these settings to apply values more appropriate for a + // small-to-medium on-premise API (e.g., not over a public Internet link + // where clients are expected to be slow) + httpServer := &http.Server{ + ReadHeaderTimeout: config.HTTPServerReadHeaderTimeout, + ReadTimeout: config.HTTPServerReadTimeout, + WriteTimeout: config.HTTPServerWriteTimeout, + Handler: mux, + Addr: fmt.Sprintf("%s:%d", appConfig.LocalIPAddress, appConfig.LocalTCPPort), } - log.Debugf("AppConfig: %+v", appConfig) + // Create context that can be used to cancel background jobs. + ctx, cancel := context.WithCancel(context.Background()) + + // Defer cancel() to cover edge cases where it might not otherwise be + // called + // TODO: Is this defer needed if we cover the cases elsewhere? + defer cancel() + + // Use signal.Notify() to send a message on dedicated channel when when + // interrupt is received (e.g., Ctrl+C) so that we can cleanly shutdown + // the application. + // + // Q: Why are these channels buffered? + // A: In order to make them asynchronous. + // Per Bakul Shah (golang-nuts/QEORIGKZO24): In general, synchronize only + // when you have to. Here the main thread wants to know when the worker + // thread terminates but the worker thread doesn't care when the main + // thread gets around to reading from "done". Using a 1 deep buffer + // channel exactly captures this usage pattern. An unbuffered channel + // would make the worker thread "rendezvous" with the main thread, which + // is unnecessary. + // + // NOTE: Setting up a separate done channel for notify mgr and another + // for when the http server has been shutdown. + // done := make(chan struct{}, 1) + httpDone := make(chan struct{}, 1) + notifyDone := make(chan struct{}, 1) + quit := make(chan os.Signal, 1) + + signal.Notify(quit, os.Interrupt) + + // Where clientRequestDetails values will be sent for processing. We use a + // buffered channel in an effort to reduce the delay for client requests + // as much as possible. + notifyWorkQueue := make(chan clientRequestDetails, config.NotifyMgrQueueDepth) + + // Create "notifications manager" function as persistent goroutine to + // process incoming notification requests. + go StartNotifyMgr(ctx, appConfig, notifyWorkQueue, notifyDone) + + // Setup "listener" to cancel the parent context when Signal.Notify() + // indicates that SIGINT has been received + go shutdownListener(ctx, quit, cancel) + + // Setup "listener" to shutdown the running http server when + // the parent context has been cancelled + go gracefulShutdown(ctx, httpServer, config.HTTPServerShutdownTimeout, httpDone) + + // Pre-process bundled templates in string/text format to Templates that + // our handlers can execute. Based on brief testing, this seems to provide + // a significant performance boost at the cost of a little more startup + // time. + indexPageHandleTemplate := htmlTemplate.Must( + htmlTemplate.New("indexPage").Parse(handleIndexTemplateText)) + echoHandlerTemplate := textTemplate.Must( + textTemplate.New("echoHandler").Parse(handleEchoTemplateText)) // SETUP ROUTES // See handlers.go for handler definitions @@ -92,7 +136,7 @@ func main() { Description: "Main page, fallback for unspecified routes", Pattern: "/", AllowedMethods: []string{http.MethodGet}, - HandlerFunc: handleIndex(handleIndexTemplate, &ourRoutes), + HandlerFunc: handleIndex(indexPageHandleTemplate, &ourRoutes), }) ourRoutes.Add(routes.Route{ @@ -100,7 +144,13 @@ func main() { Description: "Prints received values as-is to stdout and returns them via HTTP response", Pattern: apiV1EchoEndpointPattern, AllowedMethods: []string{http.MethodGet, http.MethodPost}, - HandlerFunc: echoHandler(echoHandlerTemplate, appConfig.ColorizedJSON, appConfig.ColorizedJSONIndent), + HandlerFunc: echoHandler( + ctx, + echoHandlerTemplate, + appConfig.ColorizedJSON, + appConfig.ColorizedJSONIndent, + notifyWorkQueue, + ), }) ourRoutes.Add(routes.Route{ @@ -108,31 +158,47 @@ func main() { Description: "Prints formatted JSON response to stdout and via HTTP response", Pattern: apiV1EchoJSONEndpointPattern, AllowedMethods: []string{http.MethodPost}, - HandlerFunc: echoHandler(echoHandlerTemplate, appConfig.ColorizedJSON, appConfig.ColorizedJSONIndent), + HandlerFunc: echoHandler( + ctx, + echoHandlerTemplate, + appConfig.ColorizedJSON, + appConfig.ColorizedJSONIndent, + notifyWorkQueue, + ), }) - mux := http.NewServeMux() ourRoutes.RegisterWithServeMux(mux) - // Apply "default" timeout settings provided by Simon Frey; override the - // default "wait forever" configuration. - // FIXME: Refine these settings to apply values more appropriate for a - // small-to-medium on-premise API (e.g., not over a public Internet link - // where clients are expected to be slow) - httpServer := &http.Server{ - ReadHeaderTimeout: config.HTTPServerReadHeaderTimeout, - ReadTimeout: config.HTTPServerReadTimeout, - WriteTimeout: config.HTTPServerWriteTimeout, - Handler: mux, - Addr: fmt.Sprintf("%s:%d", appConfig.LocalIPAddress, appConfig.LocalTCPPort), - } + // listen on specified port and IP Address, block until app is terminated + log.Infof("%s is listening on %s port %d", + config.MyAppName, appConfig.LocalIPAddress, appConfig.LocalTCPPort) - // listen on specified port on ALL IP Addresses, block until app is terminated - log.Infof("Listening on %s port %d ", + log.Infof("Visit http://%s:%d in your web browser for details", appConfig.LocalIPAddress, appConfig.LocalTCPPort) // TODO: This can be handled in a cleaner fashion? if err := httpServer.ListenAndServe(); err != nil { - log.Fatal(err.Error()) + + // Calling Shutdown() will immediately return ErrServerClosed, but + // based on reading the docs it sounds like any errors from closing + // connections will instead overwrite this default error message with + // a real one, so receiving ErrServerClosed can be treated as a + // "successful shutdown" message of sorts, so ignore it and look for + // any other error message. + if !errors.Is(err, http.ErrServerClosed) { + log.Errorf("error occurred while running httpServer: %v", err) + os.Exit(1) + } } + + log.Debug("Waiting on gracefulShutdown completion signal") + <-httpDone + log.Debug("Received gracefulShutdown completion signal") + + log.Debug("Waiting on StartNotifyMgr completion signal") + <-notifyDone + log.Debug("Received StartNotifyMgr completion signal") + + log.Infof("%s successfully shutdown", config.MyAppName) + } diff --git a/cmd/bounce/message.go b/cmd/bounce/message.go new file mode 100644 index 00000000..37248b5b --- /dev/null +++ b/cmd/bounce/message.go @@ -0,0 +1,304 @@ +// Copyright 2020 Adam Chalkley +// +// https://github.com/atc0005/bounce +// +// Licensed under the MIT License. See LICENSE file in the project root for +// full license information. + +package main + +import ( + "context" + "fmt" + "runtime" + "time" + + "github.com/apex/log" + "github.com/atc0005/bounce/config" + + // use our fork for now until recent work can be submitted for inclusion + // in the upstream project + goteamsnotify "github.com/atc0005/go-teams-notify" + + send2teams "github.com/atc0005/send2teams/teams" +) + +func createMessage(clientRequest clientRequestDetails) goteamsnotify.MessageCard { + + log.Debugf("createMessage: clientRequestDetails received: %#v", clientRequest) + + const ClientRequestErrorsRecorded = "Errors recorded for client request" + const ClientRequestErrorsNotFound = "No errors recorded for client request" + + // FIXME: Pull this out as a separate helper function? + // FIXME: Rework and offer upstream? + addFactPair := func(msg *goteamsnotify.MessageCard, section *goteamsnotify.MessageCardSection, key string, values ...string) { + + if err := section.AddFactFromKeyValue( + key, + values..., + ); err != nil { + + // runtime.Caller(skip int) (pc uintptr, file string, line int, ok bool) + _, file, line, ok := runtime.Caller(0) + from := fmt.Sprintf("createMessage [file %s, line %d]:", file, line) + if !ok { + from = "createMessage:" + } + errMsg := fmt.Sprintf("%s error returned from attempt to add fact from key/value pair: %v", from, err) + log.Errorf("%s %s", from, errMsg) + msg.Text = msg.Text + "\n\n" + send2teams.TryToFormatAsCodeSnippet(errMsg) + } + } + + // build MessageCard for submission + msgCard := goteamsnotify.NewMessageCard() + msgCard.Title = "Notification from " + config.MyAppName + msgCard.Text = fmt.Sprintf( + "%s request received on %s endpoint", + send2teams.TryToFormatAsCodeSnippet(clientRequest.HTTPMethod), + send2teams.TryToFormatAsCodeSnippet(clientRequest.EndpointPath), + ) + + /* + Client Request Summary Section - General client request details + */ + + clientRequestSummarySection := goteamsnotify.NewMessageCardSection() + clientRequestSummarySection.Title = "## Client Request Summary" + clientRequestSummarySection.StartGroup = true + + addFactPair(&msgCard, clientRequestSummarySection, "Received at", clientRequest.Datestamp) + addFactPair(&msgCard, clientRequestSummarySection, "Endpoint path", clientRequest.EndpointPath) + addFactPair(&msgCard, clientRequestSummarySection, "HTTP Method", clientRequest.HTTPMethod) + addFactPair(&msgCard, clientRequestSummarySection, "Client IP Address", clientRequest.ClientIPAddress) + + if err := msgCard.AddSection(clientRequestSummarySection); err != nil { + errMsg := fmt.Sprintf("Error returned from attempt to add clientRequestSummarySection: %v", err) + log.Error("createMessage: " + errMsg) + msgCard.Text = msgCard.Text + "\n\n" + send2teams.TryToFormatAsCodeSnippet(errMsg) + } + + /* + Client Request Payload Section + */ + + clientPayloadSection := goteamsnotify.NewMessageCardSection() + clientPayloadSection.Title = "## Request body/payload" + clientPayloadSection.StartGroup = true + + switch { + case clientRequest.Body == "": + log.Debugf("createMessage: Body is NOT defined, cannot use it to generate code block") + clientPayloadSection.Text = send2teams.TryToFormatAsCodeSnippet("No request body was provided by client.") + case clientRequest.Body != "": + log.Debugf("createMessage: Body is defined, using it to generate code block") + clientPayloadSection.Text = send2teams.TryToFormatAsCodeBlock(clientRequest.Body) + } + + log.Debugf("createMessage: Body field contents: %v", clientRequest.Body) + + if err := msgCard.AddSection(clientPayloadSection); err != nil { + errMsg := fmt.Sprintf("Error returned from attempt to add clientPayloadSection: %v", err) + log.Error("createMessage: " + errMsg) + msgCard.Text = msgCard.Text + "\n\n" + send2teams.TryToFormatAsCodeSnippet(errMsg) + } + + /* + Client Request Errors Section + */ + + responseErrorsSection := goteamsnotify.NewMessageCardSection() + responseErrorsSection.Title = "## Client Request errors" + responseErrorsSection.StartGroup = true + + // Be optimistic to start with + responseErrorsSection.Text = ClientRequestErrorsNotFound + + if clientRequest.RequestError != "" { + responseErrorsSection.Text = "" + addFactPair(&msgCard, responseErrorsSection, "RequestError", + send2teams.ConvertEOLToBreak(clientRequest.RequestError)) + } + + if clientRequest.BodyError != "" { + responseErrorsSection.Text = ClientRequestErrorsRecorded + addFactPair(&msgCard, responseErrorsSection, "BodyError", + send2teams.ConvertEOLToBreak(clientRequest.BodyError)) + } + + if clientRequest.ContentTypeError != "" { + responseErrorsSection.Text = ClientRequestErrorsRecorded + addFactPair(&msgCard, responseErrorsSection, "ContentTypeError", + send2teams.ConvertEOLToBreak(clientRequest.ContentTypeError)) + } + + if clientRequest.FormattedBodyError != "" { + responseErrorsSection.Text = ClientRequestErrorsRecorded + addFactPair(&msgCard, responseErrorsSection, "FormattedBodyError", + send2teams.ConvertEOLToBreak(clientRequest.FormattedBodyError)) + } + + if err := msgCard.AddSection(responseErrorsSection); err != nil { + errMsg := fmt.Sprintf("Error returned from attempt to add responseErrorsSection: %v", err) + log.Error("createMessage: " + errMsg) + msgCard.Text = msgCard.Text + "\n\n" + send2teams.TryToFormatAsCodeSnippet(errMsg) + } + + /* + Client Request Headers Section + */ + + clientRequestHeadersSection := goteamsnotify.NewMessageCardSection() + clientRequestHeadersSection.StartGroup = true + clientRequestHeadersSection.Title = "## Client Request Headers" + + clientRequestHeadersSection.Text = fmt.Sprintf( + "%d client request headers provided", + len(clientRequest.Headers), + ) + + // process client request headers + + for header, values := range clientRequest.Headers { + for index, value := range values { + // update value with code snippet formatting, assign back using + // the available index value + values[index] = send2teams.TryToFormatAsCodeSnippet(value) + } + addFactPair(&msgCard, clientRequestHeadersSection, header, values...) + } + + if err := msgCard.AddSection(clientRequestHeadersSection); err != nil { + errMsg := fmt.Sprintf("Error returned from attempt to add clientRequestHeadersSection: %v", err) + log.Error("createMessage: " + errMsg) + msgCard.Text = msgCard.Text + "\n\n" + send2teams.TryToFormatAsCodeSnippet(errMsg) + } + + /* + Message Card Branding/Trailer Section + */ + + trailerSection := goteamsnotify.NewMessageCardSection() + trailerSection.StartGroup = true + trailerSection.Text = send2teams.ConvertEOLToBreak(config.MessageTrailer()) + if err := msgCard.AddSection(trailerSection); err != nil { + errMsg := fmt.Sprintf("Error returned from attempt to add trailerSection: %v", err) + log.Error("createMessage: " + errMsg) + msgCard.Text = msgCard.Text + "\n\n" + send2teams.TryToFormatAsCodeSnippet(errMsg) + } + + return msgCard +} + +// define function/wrapper for sending details to Microsoft Teams +func sendMessage( + ctx context.Context, + webhookURL string, + msgCard goteamsnotify.MessageCard, + schedule time.Time, + retries int, + retriesDelay int, +) NotifyResult { + + // Note: We already do validation elsewhere, and the library call does + // even more validation, but we can handle this obvious empty argument + // problem directly + if webhookURL == "" { + return NotifyResult{ + Err: fmt.Errorf("sendMessage: webhookURL not defined, skipping message submission to Microsoft Teams channel"), + Success: false, + } + } + + log.Debugf("sendMessage: Time now is %v", time.Now().Format("15:04:05")) + log.Debugf("sendMessage: Notification scheduled for: %v", schedule.Format("15:04:05")) + + // Set delay timer to meet received notification schedule. This helps + // ensure that we delay the appropriate amount of time before we make our + // first attempt at sending a message to Microsoft Teams. + notificationDelay := time.Until(schedule) + + notificationDelayTimer := time.NewTimer(notificationDelay) + defer notificationDelayTimer.Stop() + log.Debugf("sendMessage: notificationDelayTimer created at %v with duration %v", + time.Now().Format("15:04:05"), + notificationDelay, + ) + + log.Debug("sendMessage: Waiting for either context or notificationDelayTimer to expire before sending notification") + + select { + case <-ctx.Done(): + ctxErr := ctx.Err() + msg := NotifyResult{ + Val: fmt.Sprintf("sendMessage: Received Done signal at %v: %v, shutting down", + time.Now().Format("15:04:05"), + ctxErr.Error(), + ), + Success: false, + } + log.Debug(msg.Val) + return msg + + // Delay between message submission attempts; this will *always* + // delay, regardless of whether the attempt is the first one or not + case <-notificationDelayTimer.C: + + log.Debugf("sendMessage: Waited %v before notification attempt at %v", + notificationDelay, + time.Now().Format("15:04:05"), + ) + + ctxExpires, ctxExpired := ctx.Deadline() + if ctxExpired { + log.Debugf("sendMessage: WaitTimeout context expires at: %v", ctxExpires.Format("15:04:05")) + } + + // check to see if context has expired during our delay + if ctx.Err() != nil { + msg := NotifyResult{ + Val: fmt.Sprintf( + "sendMessage: context expired or cancelled at %v: %v, attempting to abort message submission", + time.Now().Format("15:04:05"), + ctx.Err().Error(), + ), + Success: false, + } + + log.Debug(msg.Val) + + return msg + } + + // Submit message card, retry submission if needed up to specified number + // of retry attempts. + if err := send2teams.SendMessage(ctx, webhookURL, msgCard, retries, retriesDelay); err != nil { + errMsg := NotifyResult{ + Err: fmt.Errorf( + "sendMessage: ERROR: Failed to submit message to Microsoft Teams at %v: %v", + time.Now().Format("15:04:05"), + err, + ), + Success: false, + } + log.Error(errMsg.Err.Error()) + return errMsg + } + + successMsg := NotifyResult{ + Val: fmt.Sprintf( + "sendMessage: Message successfully sent to Microsoft Teams at %v", + time.Now().Format("15:04:05"), + ), + Success: true, + } + + // Note success for potential troubleshooting + log.Debug(successMsg.Val) + + return successMsg + + } + +} diff --git a/cmd/bounce/notify.go b/cmd/bounce/notify.go new file mode 100644 index 00000000..df6dc2d4 --- /dev/null +++ b/cmd/bounce/notify.go @@ -0,0 +1,884 @@ +package main + +import ( + "context" + "fmt" + "runtime" + "time" + + "github.com/apex/log" + "github.com/atc0005/bounce/config" +) + +// NotifyResult wraps the results of notification operations to make it easier +// to inspect the status of various tasks so that we can take action on either +// error or success conditions +type NotifyResult struct { + + // Val is the non-error condition message to return from a notification + // operation + Val string + + // Err is the error condition message to return from a notification + // operation + Err error + + // Success indicates whether the notification attempt succeeded or if it + // failed for one reason or another (remote API, timeout, cancellation, + // etc) + Success bool +} + +// NotifyQueue represents a channel used to queue input data and responses +// between the main application, the notifications manager and "notifiers". +type NotifyQueue struct { + // The name of a queue. This is intended for display in log messages or + // other output to identify queues with pending items. + Name string + + // Channel is a channel used to transport input data and responses. + Channel interface{} + + // Count is the number of items currently in the queue + Count int + + // Capacity is the maximum number of items allowed in the queue + Capacity int +} + +// NotifyStats is a collection of stats for Teams and Email notifications +type NotifyStats struct { + + // These fields are collected directly + IncomingMsgReceived int + TeamsMsgSent int + TeamsMsgSuccess int + TeamsMsgFailure int + EmailMsgSent int + EmailMsgSuccess int + EmailMsgFailure int + + // These fields are calculated from collected field values + TeamsMsgPending int + EmailMsgPending int + + TotalPendingMsg int + TotalSuccessMsg int + TotalFailureMsg int +} + +// newNotifyScheduler takes a time.Duration value as a delay and returns a +// function that can be used to generate a new notification schedule. Each +// call to this function will produce a new schedule incremented by the +// time.Duration delay value. The intent is to provide an easy to use +// mechanism for delaying notifications to remote systems (e.g., in order to +// respect remote API limits). +func newNotifyScheduler(delay time.Duration) func() time.Time { + + log.Debugf("newNotifyScheduler: Initializing lastNotificationSchedule at %s", + time.Now().Format("15:04:05"), + ) + lastNotificationSchedule := time.Now() + + return func() time.Time { + + // if we haven't sent a message in a while we should make ensure + // that we do not return a "next schedule" that has already passed + if !lastNotificationSchedule.After(time.Now()) { + + expiredSchedule := lastNotificationSchedule.Add(delay) + + log.Debugf( + "Expired next schedule: [Now: %v, Last: %v, Next: %v]", + time.Now().Format("15:04:05.000"), + lastNotificationSchedule.Format("15.04:05.000"), + expiredSchedule.Format("15:04:05.000"), + ) + + replacementSchedule := time.Now().Add(delay) + + log.Debugf( + "Replace expired schedule (%v) by resetting the schedule to now (%v) + delay (%v): %v", + expiredSchedule.Format("15:04:05.000"), + time.Now().Format("15:04:05.000"), + delay, + replacementSchedule.Format("15:04:05"), + ) + + lastNotificationSchedule = replacementSchedule + + return replacementSchedule + } + + nextSchedule := lastNotificationSchedule.Add(delay) + + log.Debugf( + "Next schedule not expired: [Last: %v, Now: %v, Next: %v]", + lastNotificationSchedule.Format("15:04:05"), + time.Now().Format("15:04:05"), + nextSchedule.Format("15:04:05"), + ) + + lastNotificationSchedule = nextSchedule + + return nextSchedule + } +} + +// notifyStatsMonitor accepts a context, a delay and a channel for NotifyStats +// values in order to collect and emit summary information for notifications. +// This function is intended to be run as a goroutine. +func notifyStatsMonitor(ctx context.Context, delay time.Duration, statsQueue <-chan NotifyStats) { + + log.Debug("notifyStatsMonitor: Running") + + // this will be populated using values received on statsQueue + stats := NotifyStats{} + + for { + t := time.NewTimer(delay) + + // log.Debug("notifyQueueMonitor: Starting loop") + + // block until: + // - context cancellation + // - timer fires + select { + case <-ctx.Done(): + t.Stop() + log.Debugf( + "notifyStatsMonitor: Received Done signal: %v, shutting down ...", + ctx.Err().Error(), + ) + + return + + // emit stats summary here + case <-t.C: + + ctxLog := log.WithFields(log.Fields{ + "timestamp": time.Now().Format("15:04:05"), + "emit_stats": delay, + }) + + // ctxLog.Infof( + // "notifyStatsMonitor: "+ + // "Total: [%d received, %d pending, %d success, %d failure], "+ + // "Teams: [%d total, %d pending, %d success, %d failure], "+ + // "Email: [%d total, %d pending, %d success, %d failure]", + // stats.IncomingMsgReceived, + // stats.TotalPendingMsg, + // stats.TotalSuccessMsg, + // stats.TotalFailureMsg, + + // stats.TeamsMsgSent, + // stats.TeamsMsgPending, + // stats.TeamsMsgSuccess, + // stats.TeamsMsgFailure, + + // stats.EmailMsgSent, + // stats.EmailMsgPending, + // stats.EmailMsgSuccess, + // stats.EmailMsgFailure, + // ) + + ctxLog.Infof( + "notifyStatsMonitor: Total: "+ + "[%d received, %d pending, %d success, %d failure]", + stats.IncomingMsgReceived, + stats.TotalPendingMsg, + stats.TotalSuccessMsg, + stats.TotalFailureMsg, + ) + + ctxLog.Infof( + "notifyStatsMonitor: Teams: "+ + "[%d total, %d pending, %d success, %d failure]", + stats.TeamsMsgSent, + stats.TeamsMsgPending, + stats.TeamsMsgSuccess, + stats.TeamsMsgFailure, + ) + + ctxLog.Infof( + "notifyStatsMonitor: Email: "+ + "[%d total, %d pending, %d success, %d failure]", + stats.EmailMsgSent, + stats.EmailMsgPending, + stats.EmailMsgSuccess, + stats.EmailMsgFailure, + ) + + // received stats update; update our totals + case statsUpdate := <-statsQueue: + + stats.IncomingMsgReceived += statsUpdate.IncomingMsgReceived + + stats.TeamsMsgSent += statsUpdate.TeamsMsgSent + stats.TeamsMsgSuccess += statsUpdate.TeamsMsgSuccess + stats.TeamsMsgFailure += statsUpdate.TeamsMsgFailure + + stats.EmailMsgSent += statsUpdate.EmailMsgSent + stats.EmailMsgSuccess += statsUpdate.EmailMsgSuccess + stats.EmailMsgFailure += statsUpdate.EmailMsgFailure + + // calculate non-collected stats here + stats.TeamsMsgPending = stats.TeamsMsgSent - + (stats.TeamsMsgSuccess + stats.TeamsMsgFailure) + + stats.EmailMsgPending = stats.EmailMsgSent - + (stats.EmailMsgSuccess + stats.EmailMsgFailure) + + stats.TotalPendingMsg = stats.EmailMsgPending + stats.TeamsMsgPending + stats.TotalFailureMsg = stats.EmailMsgFailure + stats.TeamsMsgFailure + stats.TotalSuccessMsg = stats.EmailMsgSuccess + stats.TeamsMsgSuccess + + } + } +} + +// notifyQueueMonitor accepts a context, a delay and one or many NotifyQueue +// values to monitor for items yet to be processed. This function is intended +// to be run as a goroutine. +func notifyQueueMonitor(ctx context.Context, delay time.Duration, notifyQueues ...NotifyQueue) { + + if len(notifyQueues) == 0 { + log.Error("received empty list of notifyQueues to monitor, exiting") + return + } + + log.Debug("notifyQueueMonitor: Running") + + for { + + t := time.NewTimer(delay) + + // log.Debug("notifyQueueMonitor: Starting loop") + + // block until: + // - context cancellation + // - timer fires + select { + case <-ctx.Done(): + t.Stop() + log.Debugf( + "notifyQueueMonitor: Received Done signal: %v, shutting down ...", + ctx.Err().Error(), + ) + return + + case <-t.C: + + // log.Debug("notifyQueueMonitor: Timer fired") + + // NOTE: Not needed since the channel is already drained as a + // result of the case statement triggering and draining the + // channel + // t.Stop() + + // Attempt to receive message count updates, proceed without them + // if they're not available + + var itemsFound bool + //log.Debugf("Length of queues: %d", len(queues)) + for _, notifyQueue := range notifyQueues { + + switch queue := notifyQueue.Channel.(type) { + + // FIXME: Is there a generic way to match any channel type + // here in order to calculate the length? + case chan clientRequestDetails: + notifyQueue.Count = len(queue) + notifyQueue.Capacity = cap(queue) + + case <-chan clientRequestDetails: + notifyQueue.Count = len(queue) + notifyQueue.Capacity = cap(queue) + + case chan NotifyResult: + notifyQueue.Count = len(queue) + notifyQueue.Capacity = cap(queue) + + case chan NotifyStats: + notifyQueue.Count = len(queue) + notifyQueue.Capacity = cap(queue) + + default: + log.Warn("Default case triggered (this should not happen") + log.Warnf( + "Unhandled channel: [Name: %s, Type: %T]", + notifyQueue.Name, notifyQueue, + ) + + } + + // Show stats only for queues with content + if notifyQueue.Count > 0 { + itemsFound = true + + log.WithField("timestamp", time.Now().Format("15:04:05")).Debugf( + "notifyQueueMonitor: %d/%d items in %s, %d goroutines running", + notifyQueue.Count, + notifyQueue.Capacity, + notifyQueue.Name, + runtime.NumGoroutine(), + ) + continue + } + + } + + if !itemsFound { + log.WithField("timestamp", time.Now().Format("15:04:05")).Debugf( + "notifyQueueMonitor: 0 items queued, %d goroutines running", + runtime.NumGoroutine()) + } + } + } +} + +// teamsNotifier is a persistent goroutine used to receive incoming +// notification requests and spin off goroutines to create and send Microsoft +// Teams messages. +// TODO: Refactor per GH-37 +func teamsNotifier( + ctx context.Context, + webhookURL string, + sendTimeout time.Duration, + sendDelay time.Duration, + retries int, + retriesDelay int, + incoming <-chan clientRequestDetails, + notifyMgrResultQueue chan<- NotifyResult, + done chan<- struct{}, +) { + + log.Debug("teamsNotifier: Running") + + // used by goroutines called by this function to return results + ourResultQueue := make(chan NotifyResult) + + // Setup new scheduler that we can use to add an intentional delay between + // Microsoft Teams notification attempts + // https://docs.microsoft.com/en-us/microsoftteams/platform/webhooks-and-connectors/how-to/connectors-using + notifyScheduler := newNotifyScheduler(sendDelay) + + for { + + select { + + case <-ctx.Done(): + + ctxErr := ctx.Err() + result := NotifyResult{ + Val: fmt.Sprintf("teamsNotifier: Received Done signal: %v, shutting down", ctxErr.Error()), + } + log.Debug(result.Val) + + log.Debug("teamsNotifier: Sending back results") + notifyMgrResultQueue <- result + + log.Debug("teamsNotifier: Closing notifyMgrResultQueue channel to signal shutdown") + close(notifyMgrResultQueue) + + log.Debug("teamsNotifier: Closing done channel to signal shutdown") + close(done) + log.Debug("teamsNotifier: done channel closed, returning") + return + + case clientRequest := <-incoming: + + log.Debugf("teamsNotifier: Request received at %v: %#v", + time.Now(), clientRequest) + + log.Debug("Calculating next scheduled notification") + + nextScheduledNotification := notifyScheduler() + + log.Debugf("Now: %v, Next scheduled notification: %v", + time.Now().Format("15:04:05"), + nextScheduledNotification.Format("15:04:05"), + ) + + timeoutValue := config.GetTimeout( + sendTimeout, + nextScheduledNotification, + retries, + retriesDelay, + ) + + ctx, cancel := context.WithTimeout(ctx, timeoutValue) + defer cancel() + + log.Debugf("teamsNotifier: child context created with timeout duration %v", timeoutValue) + + // if there is a message waiting *and* ctx.Done() case statements + // are both valid, either path could be taken. If this one is + // taken, then the message send timeout will be the only thing + // forcing the attempt to loop back around and trigger the + // ctx.Done() path, but only if this one isn't taken again by the + // random case selection logic + log.Debug("teamsNotifier: Checking context to determine whether we should proceed") + + if ctx.Err() != nil { + result := NotifyResult{ + Success: false, + Val: "teamsNotifier: context has been cancelled, aborting notification attempt", + } + log.Debug(result.Val) + notifyMgrResultQueue <- result + + continue + } + + log.Debug("teamsNotifier: context not cancelled, proceeding with notification attempt") + + // launch task in separate goroutine, each with its own schedule + log.Debug("teamsNotifier: Launching message creation/submission in separate goroutine") + + go func( + ctx context.Context, + webhookURL string, + clientRequest clientRequestDetails, + schedule time.Time, + numRetries int, + retryDelay int, + resultQueue chan<- NotifyResult) { + + ourMessage := createMessage(clientRequest) + resultQueue <- sendMessage(ctx, webhookURL, ourMessage, schedule, numRetries, retryDelay) + + }(ctx, webhookURL, clientRequest, nextScheduledNotification, retries, retriesDelay, ourResultQueue) + + case result := <-ourResultQueue: + if result.Err != nil { + log.Errorf("teamsNotifier: Error received from ourResultQueue: %v", result.Err) + } else { + log.Debugf("teamsNotifier: OK: non-error status received on ourResultQueue: %v", result.Val) + } + + notifyMgrResultQueue <- result + + } + + } + +} + +// emailNotifier is a persistent goroutine used to receive incoming +// notification requests and spin off goroutines to create and send email +// messages. +// TODO: Refactor per GH-37 +func emailNotifier( + ctx context.Context, + sendTimeout time.Duration, + sendDelay time.Duration, + retries int, + retriesDelay int, + incoming <-chan clientRequestDetails, + notifyMgrResultQueue chan<- NotifyResult, + done chan<- struct{}, +) { + + log.Debug("emailNotifier: Running") + + // used by goroutines called by this function to return results + ourResultQueue := make(chan NotifyResult) + + // Setup new scheduler that we can use to add an intentional delay between + // email notification attempts + notifyScheduler := newNotifyScheduler(sendDelay) + + for { + + select { + + case <-ctx.Done(): + + ctxErr := ctx.Err() + result := NotifyResult{ + Val: fmt.Sprintf("emailNotifier: Received Done signal: %v, shutting down", ctxErr.Error()), + } + log.Debug(result.Val) + + log.Debug("emailNotifier: Sending back results") + notifyMgrResultQueue <- result + + log.Debug("emailNotifier: Closing notifyMgrResultQueue channel to signal shutdown") + close(notifyMgrResultQueue) + + log.Debug("emailNotifier: Closing done channel to signal shutdown") + close(done) + log.Debug("emailNotifier: done channel closed, returning") + return + + case clientRequest := <-incoming: + + log.Debugf("emailNotifier: Request received at %v: %#v", + time.Now(), clientRequest) + + log.Debug("Calculating next scheduled notification") + + nextScheduledNotification := notifyScheduler() + + log.Debugf("Now: %v, Next scheduled notification: %v", + time.Now().Format("15:04:05"), + nextScheduledNotification.Format("15:04:05"), + ) + + timeoutValue := config.GetTimeout( + sendTimeout, + nextScheduledNotification, + retries, + retriesDelay, + ) + + ctx, cancel := context.WithTimeout(ctx, timeoutValue) + defer cancel() + + log.Debugf("emailNotifier: child context created with timeout duration %v", timeoutValue) + + // if there is a message waiting *and* ctx.Done() case statements + // are both valid, either path could be taken. If this one is + // taken, then the message send timeout will be the only thing + // forcing the attempt to loop back around and trigger the + // ctx.Done() path, but only if this one isn't taken again by the + // random case selection logic + log.Debug("emailNotifier: Checking context to determine whether we should proceed") + + if ctx.Err() != nil { + result := NotifyResult{ + Success: false, + Val: "emailNotifier: context has been cancelled, aborting notification attempt", + } + log.Debug(result.Val) + notifyMgrResultQueue <- result + + continue + } + + log.Debug("emailNotifier: context not cancelled, proceeding with notification attempt") + + // launch task in separate goroutine, each with its own schedule + log.Debug("emailNotifier: Launching message creation/submission in separate goroutine") + + // launch task in a separate goroutine + // FIXME: Implement most of the same parameters here as with the + // goroutine in teamsNotifier, pass ctx for email function to use. + go func(resultQueue chan<- NotifyResult) { + result := NotifyResult{ + Err: fmt.Errorf("emailNotifier: Sending email is not currently supported"), + } + log.Error(result.Err.Error()) + resultQueue <- result + }(ourResultQueue) + + case result := <-ourResultQueue: + + if result.Err != nil { + log.Errorf("emailNotifier: Error received from ourResultQueue: %v", result.Err) + } else { + log.Debugf("emailNotifier: OK: non-error status received on ourResultQueue: %v", result.Val) + } + + notifyMgrResultQueue <- result + + } + } + +} + +// StartNotifyMgr receives clientRequestDetails values and sends notifications +// to any enabled service (e.g., Microsoft Teams). +func StartNotifyMgr(ctx context.Context, cfg *config.Config, notifyWorkQueue <-chan clientRequestDetails, done chan<- struct{}) { + + log.Debug("StartNotifyMgr: Running") + + // TODO: Refactor as part of GH-37 + // + // Create separate, buffered channels to hand-off clientRequestDetails + // values for processing for each service, e.g., one channel for Microsoft + // Teams outgoing notifications, another for email and so on. Buffered + // channels are used both to enable async tasks and to provide a means of + // monitoring the number of items queued for each channel; unbuffered + // channels have a queue depth (and thus length) of 0. + teamsNotifyWorkQueue := make(chan clientRequestDetails, config.NotifyMgrQueueDepth) + teamsNotifyResultQueue := make(chan NotifyResult, config.NotifyMgrQueueDepth) + teamsNotifyDone := make(chan struct{}) + + emailNotifyWorkQueue := make(chan clientRequestDetails, config.NotifyMgrQueueDepth) + emailNotifyResultQueue := make(chan NotifyResult, config.NotifyMgrQueueDepth) + emailNotifyDone := make(chan struct{}) + + notifyStatsQueue := make(chan NotifyStats, 1) + + if !cfg.NotifyTeams() && !cfg.NotifyEmail() { + log.Debug("StartNotifyMgr: Teams and email notifications not requested, not starting notifier goroutines") + // NOTE: Do not return/exit here. + // + // We cannot return/exit the function here because StartNotifyMgr HAS + // to run in order to keep the notifyWorkQueue from filling up and + // blocking other parts of this application that send messages to this + // channel. + } + + // If enabled, start persistent goroutine to process request details and + // submit messages to Microsoft Teams. + if cfg.NotifyTeams() { + log.Debug("StartNotifyMgr: Teams notifications enabled") + log.Debug("StartNotifyMgr: Starting up teamsNotifier") + go teamsNotifier( + ctx, + cfg.WebhookURL, + config.NotifyMgrTeamsTimeout, + config.NotifyMgrTeamsNotificationDelay, + cfg.Retries, + cfg.RetriesDelay, + teamsNotifyWorkQueue, + teamsNotifyResultQueue, + teamsNotifyDone, + ) + } + + // If enabled, start persistent goroutine to process request details and + // submit messages by email. + if cfg.NotifyEmail() { + log.Debug("StartNotifyMgr: Email notifications enabled") + log.Debug("StartNotifyMgr: Starting up emailNotifier") + go emailNotifier( + ctx, + config.NotifyMgrEmailTimeout, + config.NotifyMgrEmailNotificationDelay, + cfg.Retries, + cfg.RetriesDelay, + emailNotifyWorkQueue, + emailNotifyResultQueue, + emailNotifyDone, + ) + } + + // Monitor queues and report stats for each, even if the user has not + // opted to use notifications. This is done since we are tracking at least + // one queue (notifyStatsQueue) which is active even with notifiers + // disabled. + queuesToMonitor := []NotifyQueue{ + { + Name: "notifyWorkQueue", + Channel: notifyWorkQueue, + }, + { + Name: "emailNotifyWorkQueue", + Channel: emailNotifyWorkQueue, + }, + { + Name: "emailNotifyResultQueue", + Channel: emailNotifyResultQueue, + }, + { + Name: "teamsNotifyWorkQueue", + Channel: teamsNotifyWorkQueue, + }, + { + Name: "teamsNotifyResultQueue", + Channel: teamsNotifyResultQueue, + }, + { + Name: "notifyStatsQueue", + Channel: notifyStatsQueue, + }, + } + + // periodically print current queue items + go notifyQueueMonitor( + ctx, + config.NotifyQueueMonitorDelay, + queuesToMonitor..., + ) + + // collect and periodically emit summary of notification details + go notifyStatsMonitor( + ctx, + config.NotifyStatsMonitorDelay, + notifyStatsQueue, + ) + + for { + + select { + + // NOTE: This should ONLY ever be done when shutting down the entire + // application, as otherwise goroutines associated with client + // requests will likely hang, likely until client/server timeout + // settings are reached + case <-ctx.Done(): + ctxErr := ctx.Err() + log.Debugf("StartNotifyMgr: Received Done signal: %v, shutting down ...", ctxErr.Error()) + + evalResults := func(queueName string, result NotifyResult) { + if result.Err != nil { + log.Errorf("StartNotifyMgr: Error received from %s: %v", queueName, result.Err) + return + } + log.Debugf("StartNotifyMgr: OK: non-error status received on %s: %v", queueName, result.Val) + } + + // Process any waiting results before blocking and waiting + // on final completion response from notifier goroutines + if cfg.NotifyTeams() { + log.Debug("StartNotifyMgr: Teams notifications are enabled, shutting down teamsNotifier") + + log.Debug("StartNotifyMgr: Ranging over teamsNotifyResultQueue") + for result := range teamsNotifyResultQueue { + evalResults("teamsNotifyResultQueue", result) + } + + log.Debug("StartNotifyMgr: Waiting on teamsNotifyDone") + select { + case <-teamsNotifyDone: + log.Debug("StartNotifyMgr: Received from teamsNotifyDone") + case <-time.After(config.NotifyMgrServicesShutdownTimeout): + log.Debug("StartNotifyMgr: Timeout occurred while waiting for teamsNotifyDone") + log.Debug("StartNotifyMgr: Proceeding with shutdown") + } + + } + + if cfg.NotifyEmail() { + log.Debug("StartNotifyMgr: Email notifications are enabled, shutting down emailNotifier") + + log.Debug("StartNotifyMgr: Ranging over emailNotifyResultQueue") + for result := range emailNotifyResultQueue { + evalResults("emailNotifyResultQueue", result) + } + + log.Debug("StartNotifyMgr: Waiting on emailNotifyDone") + select { + case <-emailNotifyDone: + log.Debug("StartNotifyMgr: Received from emailNotifyDone") + case <-time.After(config.NotifyMgrServicesShutdownTimeout): + log.Debug("StartNotifyMgr: Timeout occurred while waiting for emailNotifyDone") + log.Debug("StartNotifyMgr: Proceeding with shutdown") + } + + } + + log.Debug("StartNotifyMgr: Closing done channel") + close(done) + + log.Debug("StartNotifyMgr: About to return") + return + + case clientRequest := <-notifyWorkQueue: + + log.Debug("StartNotifyMgr: Input received from notifyWorkQueue") + + go func() { + notifyStatsQueue <- NotifyStats{ + IncomingMsgReceived: 1, + } + }() + + // If we don't have *any* notifications enabled we will just + // discard the item we have pulled from the channel + if !cfg.NotifyEmail() && !cfg.NotifyTeams() { + log.Debug("StartNotifyMgr: Notifications are not currently enabled; ignoring notification request") + continue + } + + if cfg.NotifyTeams() { + log.Debug("StartNotifyMgr: Creating new goroutine to place clientRequest into teamsNotifyWorkQueue") + + // TODO: Perhaps record this *after* sending the clientRequest + // down the teamsNotifyWorkQueue channel? See other cases + // where we're using the same "record stat, then do it" + // approach. + + go func() { + notifyStatsQueue <- NotifyStats{ + TeamsMsgSent: 1, + } + }() + + go func() { + log.Debugf("StartNotifyMgr: Existing items in teamsNotifyWorkQueue: %d", len(teamsNotifyWorkQueue)) + log.Debug("StartNotifyMgr: Pending; placing clientRequest into teamsNotifyWorkQueue") + teamsNotifyWorkQueue <- clientRequest + log.Debug("StartNotifyMgr: Done; placed clientRequest into teamsNotifyWorkQueue") + log.Debugf("StartNotifyMgr: Items now in teamsNotifyWorkQueue: %d", len(teamsNotifyWorkQueue)) + }() + } + + if cfg.NotifyEmail() { + log.Debug("StartNotifyMgr: Creating new goroutine to place clientRequest in emailNotifyWorkQueue") + + go func() { + notifyStatsQueue <- NotifyStats{ + EmailMsgSent: 1, + } + }() + + go func() { + log.Debugf("StartNotifyMgr: Existing items in emailNotifyWorkQueue: %d", len(emailNotifyWorkQueue)) + log.Debug("StartNotifyMgr: Pending; placing clientRequest into emailNotifyWorkQueue") + emailNotifyWorkQueue <- clientRequest + log.Debug("StartNotifyMgr: Done; placed clientRequest into emailNotifyWorkQueue") + log.Debugf("StartNotifyMgr: Items now in emailNotifyWorkQueue: %d", len(emailNotifyWorkQueue)) + }() + } + + case result := <-teamsNotifyResultQueue: + + statsUpdate := NotifyStats{} + + // NOTE: Only consider explicit success, not a non-error condition + // because cancellations and timeouts are (currently) treated as + // non-error, but they're not successful notifications. + + if !result.Success { + if result.Err != nil { + log.Errorf("StartNotifyMgr: Error received from teamsNotifyResultQueue: %v", result.Err) + } + statsUpdate.TeamsMsgFailure = 1 + } + + if result.Success { + log.Debugf("StartNotifyMgr: OK: non-error status received on teamsNotifyResultQueue: %v", result.Val) + log.Infof("StartNotifyMgr: %v", result.Val) + statsUpdate.TeamsMsgSuccess = 1 + } + + //log.Debugf("statsUpdate: %#v", statsUpdate) + + go func() { + notifyStatsQueue <- statsUpdate + }() + + case result := <-emailNotifyResultQueue: + + statsUpdate := NotifyStats{} + + // NOTE: Only consider explicit success, not a non-error condition + // because cancellations and timeouts are (currently) treated as + // non-error, but they're not successful notifications. + + if !result.Success { + if result.Err != nil { + log.Errorf("StartNotifyMgr: Error received from emailNotifyResultQueue: %v", result.Err) + } + statsUpdate.EmailMsgFailure = 1 + } + + if result.Success { + log.Debugf("StartNotifyMgr: non-error status received on emailNotifyResultQueue: %v", result.Val) + log.Infof("StartNotifyMgr: %v", result.Val) + statsUpdate.EmailMsgSuccess = 1 + } + + go func() { + notifyStatsQueue <- statsUpdate + }() + + } + + } +} diff --git a/cmd/bounce/server.go b/cmd/bounce/server.go new file mode 100644 index 00000000..9ad14dac --- /dev/null +++ b/cmd/bounce/server.go @@ -0,0 +1,88 @@ +// Copyright 2020 Adam Chalkley +// +// https://github.com/atc0005/bounce +// +// Licensed under the MIT License. See LICENSE file in the project root for +// full license information. + +package main + +import ( + "context" + "net/http" + "os" + "time" + + "github.com/apex/log" + "github.com/atc0005/bounce/config" +) + +// shutdownListener listens for an os.Signal on the provided quit channel. +// When this signal is received, the provided parent context cancel() function +// is used to cancel all child contexts. This is intended to be run as a +// goroutine. +func shutdownListener(ctx context.Context, quit <-chan os.Signal, parentContextCancel context.CancelFunc) { + + // monitor for shutdown signal + osSignal := <-quit + + log.Debugf("shutdownListener: Received shutdown signal: %v", osSignal) + + // Attempt to trigger a cancellation of the parent context + log.Debug("shutdownListener: Cancelling context ...") + parentContextCancel() + log.Debug("shutdownListener: context canceled") + +} + +// gracefullShutdown listens for a context cancellation and then shuts down +// the running http server. Once the http server is shutdown, this function +// signals back that work is complete by closing the provided done channel. +// This function is intended to be run as a goroutine. +func gracefulShutdown(ctx context.Context, server *http.Server, timeout time.Duration, done chan<- struct{}) { + + log.Debug("gracefulShutdown: started; now waiting on <-ctx.Done()") + + // monitor for cancellation context + <-ctx.Done() + + log.Debugf("gracefulShutdown: context is done: %v", ctx.Err()) + log.Warnf("%s is shutting down, please wait ...", config.MyAppName) + + // Disable HTTP keep-alives to prevent connections from persisting + server.SetKeepAlivesEnabled(false) + + ctxShutdown, cancel := context.WithTimeout(ctx, timeout) + defer cancel() + + // From the docs: + // Shutdown returns the context's error, otherwise it returns any error + // returned from closing the Server's underlying Listener(s). + if err := server.Shutdown(ctxShutdown); err != nil { + log.Errorf("gracefulShutdown: could not gracefully shutdown the server: %v", err) + } + close(done) +} + +// TODO: Reevaluate later once I've had a chance to think over precompilation +// of templates and whether including that step here makes any logical sense +// func newHTTPServer(serveMux *http.ServeMux) *http.Server { + +// mux := http.NewServeMux() + +// // Apply "default" timeout settings provided by Simon Frey; override the +// // default "wait forever" configuration. +// // FIXME: Refine these settings to apply values more appropriate for a +// // small-to-medium on-premise API (e.g., not over a public Internet link +// // where clients are expected to be slow) +// httpServer := http.Server{ +// ReadHeaderTimeout: config.HTTPServerReadHeaderTimeout, +// ReadTimeout: config.HTTPServerReadTimeout, +// WriteTimeout: config.HTTPServerWriteTimeout, +// Handler: serveMux, +// Addr: fmt.Sprintf("%s:%d", appConfig.LocalIPAddress, appConfig.LocalTCPPort), +// } + +// return &httpServer + +// } diff --git a/cmd/bounce/templates.go b/cmd/bounce/templates.go index 58d0b2fc..ddb3f2b1 100644 --- a/cmd/bounce/templates.go +++ b/cmd/bounce/templates.go @@ -7,7 +7,7 @@ package main -const handleIndexTemplate string = ` +const handleIndexTemplateText string = ` @@ -119,7 +119,7 @@ const handleIndexTemplate string = ` ` -const echoHandlerTemplate string = ` +const handleEchoTemplateText string = ` Request received: {{if .Datestamp }}{{ .Datestamp }}{{end}} Endpoint path requested by client: {{if .EndpointPath }}{{ .EndpointPath }}{{end}} HTTP Method used by client: {{if .HTTPMethod }}{{ .HTTPMethod }}{{end}} diff --git a/config/config.go b/config/config.go index f7b06859..3faf7a90 100644 --- a/config/config.go +++ b/config/config.go @@ -16,6 +16,16 @@ import ( "time" "github.com/apex/log" + "github.com/apex/log/handlers/cli" + "github.com/apex/log/handlers/discard" + "github.com/apex/log/handlers/json" + "github.com/apex/log/handlers/logfmt" + "github.com/apex/log/handlers/text" + + // use our fork for now until recent work can be submitted for inclusion + // in the upstream project + goteamsnotify "github.com/atc0005/go-teams-notify" + send2teams "github.com/atc0005/send2teams/teams" ) // version is updated via Makefile builds by referencing the fully-qualified @@ -24,8 +34,24 @@ import ( // non-Makefile builds. var version string = "x.y.z" -const myAppName string = "bounce" -const myAppURL string = "https://github.com/atc0005/bounce" +// MyAppName is the public name of this application +const MyAppName string = "bounce" + +// MyAppURL is the location of the repo for this application +const MyAppURL string = "https://github.com/atc0005/bounce" + +const ( + portFlagHelp = "TCP port that this application should listen on for incoming HTTP requests." + localIPAddressFlagHelp = "Local IP Address that this application should listen on for incoming HTTP requests." + colorizedJSONFlagHelp = "Whether JSON output should be colorized." + colorizedJSONIndentFlagHelp = "Number of spaces to use when indenting colorized JSON output. Has no effect unless colorized JSON mode is enabled." + logLevelFlagHelp = "Log message priority filter. Log messages with a lower level are ignored." + logOutputFlagHelp = "Log messages are written to this output target" + logFormatFlagHelp = "Log messages are written in this format" + webhookURLFlagHelp = "The Webhook URL provided by a preconfigured Connector. If specified, this application will attempt to send client request details to the Microsoft Teams channel associated with the webhook URL." + retriesFlagHelp = "The number of attempts that this application will make to deliver messages before giving up." + retriesDelayFlagHelp = "The number of seconds that this application will wait before making another delivery attempt." +) // Default flag settings if not overridden by user input const ( @@ -36,6 +62,9 @@ const ( defaultLogLevel string = "info" defaultLogOutput string = "stdout" defaultLogFormat string = "text" + defaultWebhookURL string = "" + defaultRetries int = 2 + defaultRetriesDelay int = 2 ) // Timeout settings applied to our instance of http.Server @@ -45,6 +74,68 @@ const ( HTTPServerWriteTimeout time.Duration = 2 * time.Minute ) +// HTTPServerShutdownTimeout is used by the graceful shutdown process to +// control how long the shutdown process should wait before forcefully +// terminating. +const HTTPServerShutdownTimeout time.Duration = 30 * time.Second + +// NotifyMgrServicesShutdownTimeout is used by the NotifyMgr to determine how +// long it should wait for results from each notifier or notifier "service" +// before continuing on with the shutdown process. +const NotifyMgrServicesShutdownTimeout time.Duration = 2 * time.Second + +// Timing-related settings (delays, timeouts) used by our notification manager +// and child goroutines to concurrently process notification requests. +const ( + + // NotifyMgrTeamsTimeout is the timeout setting applied to each Microsoft + // Teams notification attempt. This value does NOT take into account the + // number of configured retries and retry delays. The final value timeout + // applied to each notification attempt should be based on those + // calculations. The GetTimeout method does just that. + NotifyMgrTeamsTimeout time.Duration = 10 * time.Second + + // NotifyMgrTeamsSendAttemptTimeout + + // NotifyMgrEmailTimeout is the timeout setting applied to each email + // notification attempt. This value does NOT take into account the number + // of configured retries and retry delays. The final value timeout applied + // to each notification attempt should be based on those calculations. The + // GetTimeout method does just that. + NotifyMgrEmailTimeout time.Duration = 30 * time.Second + + // NotifyStatsMonitorDelay limits notification stats logging to no more + // often than this duration. This limiter is to keep from logging the + // details so often that the information simply becomes noise. + NotifyStatsMonitorDelay time.Duration = 30 * time.Second + + // NotifyQueueMonitorDelay limits notification queue stats logging to no + // more often than this duration. This limiter is to keep from logging the + // details so often that the information simply becomes noise. + NotifyQueueMonitorDelay time.Duration = 15 * time.Second + + // NotifyMgrTeamsNotificationDelay is the delay between Microsoft Teams + // notification attempts. This delay is intended to help prevent + // unintentional abuse of remote services. + NotifyMgrTeamsNotificationDelay time.Duration = 5 * time.Second + + // NotifyMgrEmailNotificationDelay is the delay between email notification + // attempts. This delay is intended to help prevent unintentional abuse of + // remote services. + NotifyMgrEmailNotificationDelay time.Duration = 5 * time.Second +) + +// NotifyMgrQueueDepth is the number of items allowed into the queue/channel +// at one time. Senders with items for the notification "pipeline" that do not +// fit within the allocated space will block until space in the queue opens. +// Best practice for channels advocates that a smaller number is better than a +// larger one, so YMMV if this is set either too high or too low. +// +// Brief testing (as of this writing) shows that a depth as low as 1 works for +// our purposes, but results in a greater number of stalled goroutines waiting +// to place items into the queue. +const NotifyMgrQueueDepth int = 5 + // ReadHeaderTimeout: // TCP port ranges @@ -125,9 +216,20 @@ const ( LogOutputStderr string = "stderr" ) +// MessageTrailer generates a branded "footer" for use with notifications. +func MessageTrailer() string { + return fmt.Sprintf( + "Message generated by [%s](%s) (%s) at %s", + MyAppName, + MyAppURL, + version, + time.Now().Format(time.RFC3339), + ) +} + // Branding is responsible for emitting application name, version and origin -func Branding() { - fmt.Fprintf(flag.CommandLine.Output(), "\n%s %s\n%s\n\n", myAppName, version, myAppURL) +func Branding() string { + return fmt.Sprintf("\n%s %s\n%s\n\n", MyAppName, version, MyAppURL) } // Usage is a custom override for the default Help text provided by @@ -137,7 +239,7 @@ func Usage(flagSet *flag.FlagSet) func() { return func() { - Branding() + fmt.Fprint(flag.CommandLine.Output(), Branding()) fmt.Fprintf(flag.CommandLine.Output(), "Usage of \"%s\":\n", flagSet.Name(), @@ -151,6 +253,13 @@ func Usage(flagSet *flag.FlagSet) func() { // command-line flags type Config struct { + // Retries is the number of attempts that this application will make + // to deliver messages before giving up. + Retries int + + // RetriesDelay is the number of seconds to wait between retry attempts. + RetriesDelay int + // LocalTCPPort is the TCP port that this application should listen on for // incoming requests LocalTCPPort int @@ -181,11 +290,28 @@ type Config struct { // of the formats supported by the third-party leveled-logging package // used by this application. LogFormat string + + // WebhookURL is the full URL used to submit messages to the Teams channel + // This URL is in the form of https://outlook.office.com/webhook/xxx or + // https://outlook.office365.com/webhook/xxx. This URL is REQUIRED in + // order for this application to function and needs to be created in + // advance by adding/configuring a Webhook Connector in a Microsoft Teams + // channel that you wish to submit messages to using this application. + WebhookURL string } func (c *Config) String() string { return fmt.Sprintf( - "LocalTCPPort: %d, LocalIPAddress: %s, ColorizedJSON: %t, ColorizedJSONIndent: %d, LogLevel: %s, LogOutput: %s, LogFormat: %s", + "LocalTCPPort: %d, "+ + "LocalIPAddress: %s, "+ + "ColorizedJSON: %t, "+ + "ColorizedJSONIndent: %d, "+ + "LogLevel: %s, "+ + "LogOutput: %s, "+ + "LogFormat: %s, "+ + "WebhookURL: %s, "+ + "Retries: %d, "+ + "RetriesDelay: %d", c.LocalTCPPort, c.LocalIPAddress, c.ColorizedJSON, @@ -193,78 +319,84 @@ func (c *Config) String() string { c.LogLevel, c.LogOutput, c.LogFormat, + c.WebhookURL, + c.Retries, + c.RetriesDelay, ) } -// NewConfig is a factory function that produces a new Config object based -// on user provided flag values. -func NewConfig() (*Config, error) { +// NotifyTeams indicates whether or not notifications should be sent to a +// Microsoft Teams channel. +func (c Config) NotifyTeams() bool { - config := Config{} + // Assumption: config.validate() has already been called for the existing + // instance of the Config type and this method is now being called by + // later stages of the codebase to determine only whether an attempt + // should be made to send a message to Teams. - mainFlagSet := flag.NewFlagSet(os.Args[0], flag.ContinueOnError) + // For now, use the same logic that validate() uses to determine whether + // validation checks should be run: Is c.WebhookURL set to a non-empty + // string. + return c.WebhookURL != "" - mainFlagSet.IntVar( - &config.LocalTCPPort, - "port", - defaultLocalTCPPort, - "TCP port that this application should listen on for incoming HTTP requests.", - ) +} - mainFlagSet.StringVar( - &config.LocalIPAddress, - "ipaddr", - defaultLocalIP, - "Local IP Address that this application should listen on for incoming HTTP requests.", - ) +// NotifyEmail indicates whether or not notifications should be generated and +// sent via email to specified recipients. +func (c Config) NotifyEmail() bool { - mainFlagSet.BoolVar( - &config.ColorizedJSON, - "color", - defaultColorizedJSON, - "Whether JSON output should be colorized.", - ) + // TODO: Add support for email notifications. For now, this method is a + // placeholder to allow logic for future notification support to be + // written. + return false - mainFlagSet.IntVar( - &config.ColorizedJSONIndent, - "indent-lvl", - defaultColorizedJSONIntent, - "Number of spaces to use when indenting colorized JSON output. Has no effect unless colorized JSON mode is enabled.", - ) +} - mainFlagSet.StringVar( - &config.LogLevel, - "log-lvl", - defaultLogLevel, - "Log message priority filter. Log messages with a lower level are ignored.", - ) +// GetTimeout accepts the next scheduled notification, the number of +// message submission retries and the delay between each +// attempt and returns the timeout value for the entire message submission +// process, including the initial attempt and all retry attempts. +// +// This overall timeout value is computed using multiple values; (1) the base +// timeout value for a single message submission attempt, (2) the next +// scheduled notification (which was created using the configured delay we +// wish to force between message submission attempts), (3) the total number of +// retries allowed, (4) the delay between retry attempts +func GetTimeout(baseTimeout time.Duration, schedule time.Time, retries int, retriesDelay int) time.Duration { + + timeoutValue := (baseTimeout + time.Until(schedule)) + + (time.Duration(retriesDelay) * time.Duration(retries)) + + // Note: This seems to allow the app to make it all the way to and execute + // goteamsnotify mstClient.SendWithContext() once before the context + // timeout is triggered and shuts everything down + // timeoutValue := 6000 * time.Millisecond + + // ... to make it to + // "sendMessage: Waiting for either context or notificationDelayTimer" + // before the context expires (0 executions of SendWithContext()). + // timeoutValue := 5010 * time.Millisecond + + return timeoutValue +} - mainFlagSet.StringVar( - &config.LogOutput, - "log-out", - defaultLogOutput, - "Log messages are written to this output target", - ) +// NewConfig is a factory function that produces a new Config object based +// on user provided flag values. +func NewConfig() (*Config, error) { - mainFlagSet.StringVar( - &config.LogFormat, - "log-fmt", - defaultLogFormat, - "Log messages are written in this format", - ) + config := Config{} - mainFlagSet.Usage = Usage(mainFlagSet) - // FIXME: Is this needed for any reason since our mainFlagSet has already - // been parsed? - //flag.CommandLine = mainFlagSet - //flag.Parse() - if err := mainFlagSet.Parse(os.Args[1:]); err != nil { - return nil, err + if err := config.handleFlagsConfig(); err != nil { + return nil, fmt.Errorf("error encountered configuring flags: %w", err) } + // Apply initial logging settings based on any provided CLI flags + config.configureLogging() + // If no errors were encountered during parsing, proceed to validation of // configuration settings (both user-specified and defaults) if err := validate(config); err != nil { + flag.Usage() return nil, err } @@ -272,6 +404,46 @@ func NewConfig() (*Config, error) { } +// configureLogging is a wrapper function to enable setting requested logging +// settings. +func (c Config) configureLogging() { + + var logOutput *os.File + + switch c.LogOutput { + case LogOutputStderr: + logOutput = os.Stderr + case LogOutputStdout: + logOutput = os.Stdout + } + + switch c.LogFormat { + case LogFormatCLI: + log.SetHandler(cli.New(logOutput)) + case LogFormatJSON: + log.SetHandler(json.New(logOutput)) + case LogFormatLogFmt: + log.SetHandler(logfmt.New(logOutput)) + case LogFormatText: + log.SetHandler(text.New(logOutput)) + case LogFormatDiscard: + log.SetHandler(discard.New()) + } + + switch c.LogLevel { + case LogLevelFatal: + log.SetLevel(log.FatalLevel) + case LogLevelError: + log.SetLevel(log.ErrorLevel) + case LogLevelWarn: + log.SetLevel(log.WarnLevel) + case LogLevelInfo: + log.SetLevel(log.InfoLevel) + case LogLevelDebug: + log.SetLevel(log.DebugLevel) + } +} + // validate confirms that all config struct fields have reasonable values func validate(c Config) error { @@ -367,6 +539,21 @@ func validate(c Config) error { // LogFormat + // Not having a webhook URL is a valid choice. Perform validation if value + // is provided. + if c.WebhookURL != "" { + + // TODO: Do we really need both of these? + if ok, err := goteamsnotify.IsValidWebhookURL(c.WebhookURL); !ok { + return err + } + + if err := send2teams.ValidateWebhook(c.WebhookURL); err != nil { + return err + } + + } + // if we made it this far then we signal all is well return nil diff --git a/config/flags.go b/config/flags.go new file mode 100644 index 00000000..4ddba5d4 --- /dev/null +++ b/config/flags.go @@ -0,0 +1,47 @@ +// Copyright 2020 Adam Chalkley +// +// https://github.com/atc0005/bounce +// +// Licensed under the MIT License. See LICENSE file in the project root for +// full license information. + +package config + +import ( + "flag" + "os" +) + +// handleFlagsConfig wraps flag setup code into a bundle for potential ease of +// use and future testability +func (c *Config) handleFlagsConfig() error { + + mainFlagSet := flag.NewFlagSet(os.Args[0], flag.ContinueOnError) + + mainFlagSet.IntVar(&c.LocalTCPPort, "port", defaultLocalTCPPort, portFlagHelp) + mainFlagSet.StringVar(&c.LocalIPAddress, "ipaddr", defaultLocalIP, localIPAddressFlagHelp) + mainFlagSet.BoolVar(&c.ColorizedJSON, "color", defaultColorizedJSON, colorizedJSONFlagHelp) + mainFlagSet.IntVar(&c.ColorizedJSONIndent, "indent-lvl", defaultColorizedJSONIntent, colorizedJSONIndentFlagHelp) + mainFlagSet.StringVar(&c.LogLevel, "log-lvl", defaultLogLevel, logLevelFlagHelp) + mainFlagSet.StringVar(&c.LogOutput, "log-out", defaultLogOutput, logOutputFlagHelp) + mainFlagSet.StringVar(&c.LogFormat, "log-fmt", defaultLogFormat, logFormatFlagHelp) + mainFlagSet.StringVar(&c.WebhookURL, "webhook-url", defaultWebhookURL, webhookURLFlagHelp) + mainFlagSet.IntVar(&c.Retries, "retries", defaultRetries, retriesFlagHelp) + mainFlagSet.IntVar(&c.RetriesDelay, "retries-delay", defaultRetriesDelay, retriesDelayFlagHelp) + + mainFlagSet.Usage = Usage(mainFlagSet) + + // TODO: Safe to do this? + flag.Usage = Usage(mainFlagSet) + + // FIXME: Is this needed for any reason since our mainFlagSet has already + // been parsed? + //flag.CommandLine = mainFlagSet + //flag.Parse() + if err := mainFlagSet.Parse(os.Args[1:]); err != nil { + return err + } + + return nil + +} diff --git a/doc.go b/doc.go index ed66123a..d0605cb4 100644 --- a/doc.go +++ b/doc.go @@ -5,9 +5,9 @@ bounce is a small utility to assist with building HTTP endpoints PROJECT HOME -See our GitHub repo (https://github.com/atc0005/bounce) for the latest -code, to file an issue or submit improvements for review and potential -inclusion into the project. +See our GitHub repo (https://github.com/atc0005/bounce) for the latest code, +to file an issue or submit improvements for review and potential inclusion +into the project. PURPOSE @@ -21,11 +21,15 @@ FEATURES • minimal configuration +• Optional submission of client request details to a user-specified Microsoft Teams channel (by providing a webhook URL) + • index page automatically generated listing currently supported routes -• request body and associated metadata is echoed to stdout and back to client - as unformatted request body and automatic formatting of JSON payloads when - sent to the /api/v1/echo/json endpoint +• request body and associated metadata are echoed to stdout and back to client + +• echoed request details are provided as-is/unformatted when sent to the /api/v1/echo/json endpoint + +• JSON payloads to the /api/v1/echo/json endpoint are automatically formatted • Optional, colorization and custom ident control for formatted JSON output @@ -39,6 +43,7 @@ FEATURES • User configurable logging output (stdout or stderr) +• User configurable message submission retry and retry delay limits USAGE @@ -46,24 +51,30 @@ Help output is below. See the README for examples. $ ./bounce.exe -h - bounce x.y.z - https://github.com/atc0005/bounce - - Usage of "T:\github\bounce\bounce.exe": - -color - Whether JSON output should be colorized. - -indent-lvl int - Number of spaces to use when indenting colorized JSON output. Has no effect unless colorized JSON mode is enabled. (default 2) - -ipaddr string - Local IP Address that this application should listen on for incoming HTTP requests. (default "localhost") - -log-fmt string - Log messages are written in this format (default "text") - -log-lvl string - Log message priority filter. Log messages with a lower level are ignored. (default "info") - -log-out string - Log messages are written to this output target (default "stdout") - -port int - TCP port that this application should listen on for incoming HTTP requests. (default 8000) + bounce x.y.z + https://github.com/atc0005/bounce + + Usage of "T:\github\bounce\bounce.exe": + -color + Whether JSON output should be colorized. + -indent-lvl int + Number of spaces to use when indenting colorized JSON output. Has no effect unless colorized JSON mode is enabled. (default 2) + -ipaddr string + Local IP Address that this application should listen on for incoming HTTP requests. (default "localhost") + -log-fmt string + Log messages are written in this format (default "text") + -log-lvl string + Log message priority filter. Log messages with a lower level are ignored. (default "info") + -log-out string + Log messages are written to this output target (default "stdout") + -port int + TCP port that this application should listen on for incoming HTTP requests. (default 8000) + -retries int + The number of attempts that this application will make to deliver messages before giving up. (default 2) + -retries-delay int + The number of seconds that this application will wait before making another delivery attempt. (default 2) + -webhook-url string + The Webhook URL provided by a preconfigured Connector. If specified, this application will attempt to send client request details to the Microsoft Teams channel associated with the webhook URL. */ package main diff --git a/go.mod b/go.mod index 011b33dc..5b81927d 100644 --- a/go.mod +++ b/go.mod @@ -12,11 +12,33 @@ go 1.13 // $ go list -m -versions github.com/apex/log // github.com/apex/log v1.0.0 v1.1.0 v1.1.1 v1.1.2 +// Use local copy of library package (instead of fetching remote content) +// replace github.com/atc0005/go-teams-notify => ../go-teams-notify +// replace github.com/atc0005/send2teams => ../send2teams + +// +// require ( +// +// ... +// Note: Due to `replace` directive and `v0.0.0` here, we use the current +// state of this library package from the local system instead of fetching +// remote content +// github.com/atc0005/go-teams-notify v0.0.0 +// github.com/atc0005/send2teams v0.0.0 +// ... +//) + require ( github.com/TylerBrock/colorjson v0.0.0-20180527164720-95ec53f28296 github.com/apex/log v1.1.2 + + //gopkg.in/dasrick/go-teams-notify.v1 v1.2.0 + + // temporarily use our fork while developing changes for potential + // inclusion in the upstream project + github.com/atc0005/go-teams-notify v1.3.1-0.20200419155834-55cca556e726 + github.com/atc0005/send2teams v0.4.0 github.com/fatih/color v1.9.0 // indirect - github.com/golang/gddo v0.0.0-20200219175727-df439dd5819e + github.com/golang/gddo v0.0.0-20200324184333-3c2cc9a6329d github.com/hokaccha/go-prettyjson v0.0.0-20190818114111-108c894c2c0e // indirect - gopkg.in/yaml.v2 v2.2.4 // indirect ) diff --git a/go.sum b/go.sum index 4d3197c0..e159f74f 100644 --- a/go.sum +++ b/go.sum @@ -8,6 +8,10 @@ github.com/apex/logs v0.0.3/go.mod h1:XzxuLZ5myVHDy9SAmYpamKKRNApGj54PfYLcFrXqDw github.com/aphistic/golf v0.0.0-20180712155816-02c07f170c5a h1:2KLQMJ8msqoPHIPDufkxVcoTtcmE5+1sL9950m4R9Pk= github.com/aphistic/golf v0.0.0-20180712155816-02c07f170c5a/go.mod h1:3NqKYiepwy8kCu4PNA+aP7WUV72eXWJeP9/r3/K9aLE= github.com/aphistic/sweet v0.2.0/go.mod h1:fWDlIh/isSE9n6EPsRmC0det+whmX6dJid3stzu0Xys= +github.com/atc0005/go-teams-notify v1.3.1-0.20200419155834-55cca556e726 h1:pUJFxj7XRR6UxgWTvG4BCf1cVsn7nNqxdigBhMd1r/c= +github.com/atc0005/go-teams-notify v1.3.1-0.20200419155834-55cca556e726/go.mod h1:zUADEXrhalWyaQvxzYgHswljBWycIpX1UAFrggjcdi4= +github.com/atc0005/send2teams v0.4.0 h1:Nee4VqCRdZA2JdVNYnvxaBkyO/rzonknuV7U1CsU7xQ= +github.com/atc0005/send2teams v0.4.0/go.mod h1:uS4e7eZnRBhY/ia8crocFu3PM2Rl0VxHGA+r3Rb8eXo= github.com/aws/aws-sdk-go v1.20.6 h1:kmy4Gvdlyez1fV4kw5RYxZzWKVyuHZHgPWeU/YvRsV4= github.com/aws/aws-sdk-go v1.20.6/go.mod h1:KmX6BPdI08NWTb3/sm4ZGu5ShLoqVDhKgpiN924inxo= github.com/aybabtme/rgbterm v0.0.0-20170906152045-cc83f3b3ce59 h1:WWB576BN5zNSZc/M9d/10pqEx5VHNhaQ/yOVAkmj5Yo= @@ -25,8 +29,8 @@ github.com/garyburd/redigo v1.1.1-0.20170914051019-70e1b1943d4f/go.mod h1:NR3MbY github.com/go-logfmt/logfmt v0.4.0 h1:MP4Eh7ZCb31lleYCFuwm0oe4/YGak+5l1vA2NOE80nA= github.com/go-logfmt/logfmt v0.4.0/go.mod h1:3RMwSq7FuexP4Kalkev3ejPJsZTpXXBr9+V4qmtdjCk= github.com/go-stack/stack v1.6.0/go.mod h1:v0f6uXyyMGvRgIKkXu+yp6POWl0qKG85gN/melR3HDY= -github.com/golang/gddo v0.0.0-20200219175727-df439dd5819e h1:NsQfXZpFhWx7D7/Wo3dSB3/o3vGVhAB4dJmR3eXXpmM= -github.com/golang/gddo v0.0.0-20200219175727-df439dd5819e/go.mod h1:sam69Hju0uq+5uvLJUMDlsKlQ21Vrs1Kd/1YFPNYdOU= +github.com/golang/gddo v0.0.0-20200324184333-3c2cc9a6329d h1:ZJhGJay808i+klrJbox3i5NMVerJ3/tEhtOTeQpPwJQ= +github.com/golang/gddo v0.0.0-20200324184333-3c2cc9a6329d/go.mod h1:sam69Hju0uq+5uvLJUMDlsKlQ21Vrs1Kd/1YFPNYdOU= github.com/golang/lint v0.0.0-20170918230701-e5d664eb928e/go.mod h1:tluoj9z5200jBnyusfRPU2LqT6J+DAorxEvtC7LHB+E= github.com/golang/protobuf v1.2.0/go.mod h1:6lQm79b+lXiMfvg/cZm0SGofjICqVBUtrP5yJMmIC1U= github.com/golang/protobuf v1.3.1/go.mod h1:6lQm79b+lXiMfvg/cZm0SGofjICqVBUtrP5yJMmIC1U= @@ -90,6 +94,8 @@ github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+ github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI= github.com/stretchr/testify v1.4.0 h1:2E4SXV/wtOkTonXsotYi4li6zVWxYlZuYNCXe9XRJyk= github.com/stretchr/testify v1.4.0/go.mod h1:j7eGeouHqKxXV5pUuKE4zz7dFj8WfuZ+81PSLYec5m4= +github.com/stretchr/testify v1.5.1 h1:nOGnQDM7FYENwehXlg/kFVnos3rEvtKTjRvOWSzb6H4= +github.com/stretchr/testify v1.5.1/go.mod h1:5W2xD1RspED5o8YsWQXVCued0rvSQ+mT+I5cxcmMvtA= github.com/tj/assert v0.0.0-20171129193455-018094318fb0/go.mod h1:mZ9/Rh9oLWpLLDRpvE+3b7gP/C2YyLFYxNmcLnPTMe0= github.com/tj/go-elastic v0.0.0-20171221160941-36157cbbebc2 h1:eGaGNxrtoZf/mBURsnNQKDR7u50Klgcf2eFDQEnc8Bc= github.com/tj/go-elastic v0.0.0-20171221160941-36157cbbebc2/go.mod h1:WjeM0Oo1eNAjXGDx2yma7uG2XoyRZTq1uv3M/o7imD0= @@ -127,5 +133,5 @@ gopkg.in/fsnotify.v1 v1.4.7/go.mod h1:Tz8NjZHkW78fSQdbUxIjBTcgA1z1m8ZHf0WmKUhAMy gopkg.in/tomb.v1 v1.0.0-20141024135613-dd632973f1e7/go.mod h1:dt/ZhP58zS4L8KSrWDmTeBkI65Dw0HsyUHuEVlX15mw= gopkg.in/yaml.v2 v2.2.1/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI= gopkg.in/yaml.v2 v2.2.2/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI= -gopkg.in/yaml.v2 v2.2.4 h1:/eiJrUcujPVeJ3xlSWaiNi3uSVmDGBK1pDHUHAnao1I= -gopkg.in/yaml.v2 v2.2.4/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI= +gopkg.in/yaml.v2 v2.2.8 h1:obN1ZagJSUGI0Ek/LBmuj4SNLPfIny3KsKFopxRdj10= +gopkg.in/yaml.v2 v2.2.8/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI=