diff --git a/logging/simple_logger.go b/logging/simple_logger.go index 1a9fd14a1..61f89b795 100644 --- a/logging/simple_logger.go +++ b/logging/simple_logger.go @@ -10,7 +10,7 @@ import ( type SimpleLogger struct { Source string History bytes.Buffer - Log *log.Logger + Logger *log.Logger KeepHistory bool Level LogLevel } @@ -27,7 +27,7 @@ const ( func NewSimpleLogger(source string, log *log.Logger, keepHistory bool, level LogLevel) *SimpleLogger { return &SimpleLogger{ Source: source, - Log: log, + Logger: log, Level: level, KeepHistory: keepHistory, } @@ -48,28 +48,28 @@ func ToLogLevel(levelStr string) LogLevel { } func (l *SimpleLogger) Debug(format string, a ...interface{}) { - l.log(Debug, format, a...) + l.Log(Debug, format, a...) } func (l *SimpleLogger) Info(format string, a ...interface{}) { - l.log(Info, format, a...) + l.Log(Info, format, a...) } func (l *SimpleLogger) Warn(format string, a ...interface{}) { - l.log(Warn, format, a...) + l.Log(Warn, format, a...) } func (l *SimpleLogger) Err(format string, a ...interface{}) { - l.log(Error, format, a...) + l.Log(Error, format, a...) } -func (l *SimpleLogger) log(level LogLevel, format string, a ...interface{}) { +func (l *SimpleLogger) Log(level LogLevel, format string, a ...interface{}) { levelStr := l.levelToString(level) msg := l.capitalizeFirstLetter(fmt.Sprintf(format, a...)) // only log this message if configured to log at this level if l.Level <= level { - l.Log.Printf("[%s] %s: %s\n", levelStr, l.Source, msg) + l.Logger.Printf("[%s] %s: %s\n", levelStr, l.Source, msg) } // keep history at all log levels diff --git a/prerun/pre_run_test.go b/prerun/pre_run_test.go index 2c0e748f9..1eac692b6 100644 --- a/prerun/pre_run_test.go +++ b/prerun/pre_run_test.go @@ -13,7 +13,7 @@ import ( var level logging.LogLevel = logging.Info var logger = &logging.SimpleLogger{ Source: "server", - Log: log.New(os.Stderr, "", log.LstdFlags), + Logger: log.New(os.Stderr, "", log.LstdFlags), Level: level, } diff --git a/server/command_handler.go b/server/command_handler.go index c2ac3a3f1..f134db805 100644 --- a/server/command_handler.go +++ b/server/command_handler.go @@ -72,7 +72,7 @@ type Command struct { func (c *CommandHandler) ExecuteCommand(ctx *CommandContext) { src := fmt.Sprintf("%s/pull/%d", ctx.BaseRepo.FullName, ctx.Pull.Num) // it's safe to reuse the underlying logger e.logger.Log - ctx.Log = logging.NewSimpleLogger(src, c.logger.Log, true, c.logger.Level) + ctx.Log = logging.NewSimpleLogger(src, c.logger.Logger, true, c.logger.Level) defer c.recover(ctx) // need to get additional data from the PR diff --git a/server/middleware.go b/server/middleware.go index e35d9d296..5bee845d2 100644 --- a/server/middleware.go +++ b/server/middleware.go @@ -5,21 +5,22 @@ import ( "github.com/hootsuite/atlantis/logging" "github.com/urfave/negroni" + "strings" ) -func NewNon200Logger(logger *logging.SimpleLogger) *FailedRequestLogger { - return &FailedRequestLogger{logger} +func NewRequestLogger(logger *logging.SimpleLogger) *RequestLogger { + return &RequestLogger{logger} } -// FailedRequestLogger logs the request when a response code >= 400 is sent -type FailedRequestLogger struct { +// RequestLogger logs requests and their response codes +type RequestLogger struct { logger *logging.SimpleLogger } -func (l *FailedRequestLogger) ServeHTTP(rw http.ResponseWriter, r *http.Request, next http.HandlerFunc) { +func (l *RequestLogger) ServeHTTP(rw http.ResponseWriter, r *http.Request, next http.HandlerFunc) { next(rw, r) res := rw.(negroni.ResponseWriter) - if res.Status() >= 400 { - l.logger.Info("%s %s - Response code %d", r.Method, r.URL.RequestURI(), res.Status()) + if !strings.HasPrefix(r.URL.RequestURI(), "/static") { + l.logger.Info("%d | %s %s", res.Status(), r.Method, r.URL.RequestURI()) } } diff --git a/server/server.go b/server/server.go index 6f5148a37..a0f7fff4f 100644 --- a/server/server.go +++ b/server/server.go @@ -197,7 +197,7 @@ func (s *Server) Start() error { PrintStack: false, StackAll: false, StackSize: 1024 * 8, - }, NewNon200Logger(s.logger)) + }, NewRequestLogger(s.logger)) n.UseHandler(s.router) s.logger.Info("Atlantis started - listening on port %v", s.port) return cli.NewExitError(http.ListenAndServe(fmt.Sprintf(":%d", s.port), n), 1) @@ -280,33 +280,30 @@ func (s *Server) lock(w http.ResponseWriter, r *http.Request) { func (s *Server) deleteLock(w http.ResponseWriter, r *http.Request) { id, ok := mux.Vars(r)["id"] - if !ok { - w.WriteHeader(http.StatusBadRequest) - fmt.Fprint(w, "no lock id in request") + if !ok || id == "" { + s.respond(w, logging.Warn, http.StatusBadRequest, "No id in request") + return } idUnencoded, err := url.PathUnescape(id) if err != nil { - w.WriteHeader(http.StatusBadRequest) - fmt.Fprint(w, "invalid lock id") + s.respond(w, logging.Warn, http.StatusBadRequest, "Invalid lock id: %s", err) + return } lock, err := s.lockingClient.Unlock(idUnencoded) if err != nil { - w.WriteHeader(http.StatusBadRequest) - fmt.Fprintf(w, "Failed to unlock: %s", err) + s.respond(w, logging.Error, http.StatusInternalServerError, "Failed to delete lock %s: %s", idUnencoded, err) return } if lock == nil { - w.WriteHeader(http.StatusBadRequest) - fmt.Fprint(w, "No lock at that key") + s.respond(w, logging.Warn, http.StatusBadRequest, "No lock found at id %s", idUnencoded) return } - fmt.Fprint(w, "Unlocked successfully") + s.respond(w, logging.Info, http.StatusOK, "Deleted lock id %s", idUnencoded) } // postEvents handles comment and pull request events from GitHub func (s *Server) postEvents(w http.ResponseWriter, r *http.Request) { githubReqID := "X-Github-Delivery=" + r.Header.Get("X-Github-Delivery") - var payload []byte // webhook requests can either be application/json or application/x-www-form-urlencoded @@ -314,10 +311,8 @@ func (s *Server) postEvents(w http.ResponseWriter, r *http.Request) { // GitHub stores the json payload as a form value payloadForm := r.PostFormValue("payload") if payloadForm == "" { - w.WriteHeader(http.StatusBadRequest) - fmt.Fprint(w, "request did not contain expected 'payload' form value") + s.respond(w, logging.Warn, http.StatusBadRequest, "request did not contain expected 'payload' form value") return - } payload = []byte(payloadForm) } else { @@ -326,8 +321,7 @@ func (s *Server) postEvents(w http.ResponseWriter, r *http.Request) { var err error payload, err = ioutil.ReadAll(r.Body) if err != nil { - w.WriteHeader(http.StatusBadRequest) - fmt.Fprintf(w, "could not read body: %s", err) + s.respond(w, logging.Warn, http.StatusBadRequest, "could not read body: %s", err) return } } @@ -339,47 +333,38 @@ func (s *Server) postEvents(w http.ResponseWriter, r *http.Request) { case *gh.PullRequestEvent: s.handlePullRequestEvent(w, event, githubReqID) default: - s.logger.Debug("Ignoring unsupported event %s", githubReqID) - fmt.Fprintln(w, "Ignoring") + s.respond(w, logging.Debug, http.StatusOK, "Ignoring unsupported event %s", githubReqID) } } // handlePullRequestEvent will delete any locks associated with the pull request func (s *Server) handlePullRequestEvent(w http.ResponseWriter, pullEvent *gh.PullRequestEvent, githubReqID string) { if pullEvent.GetAction() != "closed" { - s.logger.Debug("Ignoring pull request event since action was not closed %s", githubReqID) - fmt.Fprintln(w, "Ignoring") + s.respond(w, logging.Debug, http.StatusOK, "Ignoring pull request event since action was not closed %s", githubReqID) return } pull, _, err := s.eventParser.ExtractPullData(pullEvent.PullRequest) if err != nil { - s.logger.Err("parsing pull data: %s", err) - w.WriteHeader(http.StatusBadRequest) - fmt.Fprintf(w, "error parsing request: %s", err) + s.respond(w, logging.Error, http.StatusBadRequest, "Error parsing pull data: %s", err) return } repo, err := s.eventParser.ExtractRepoData(pullEvent.Repo) if err != nil { - s.logger.Err("parsing repo data: %s", err) - w.WriteHeader(http.StatusBadRequest) - fmt.Fprintf(w, "error parsing request: %s", err) + s.respond(w, logging.Error, http.StatusBadRequest, "Error parsing repo data: %s", err) return } - s.logger.Info("cleaning up locks and plans for repo %s and pull %d", repo.FullName, pull.Num) if err := s.pullClosedExecutor.CleanUpPull(repo, pull); err != nil { - s.logger.Err("cleaning pull request: %s", err) - w.WriteHeader(http.StatusInternalServerError) - fmt.Fprintf(w, "Error cleaning pull request: %s", err) + s.respond(w, logging.Error, http.StatusInternalServerError, "Error cleaning pull request: %s", err) return } + s.logger.Info("deleted locks and workspace for repo %s, pull %d", repo.FullName, pull.Num) fmt.Fprint(w, "Pull request cleaned successfully") } func (s *Server) handleCommentEvent(w http.ResponseWriter, event *gh.IssueCommentEvent, githubReqID string) { if event.GetAction() != "created" { - s.logger.Debug("Ignoring comment event since action was not created %s", githubReqID) - fmt.Fprintln(w, "Ignoring") + s.respond(w, logging.Debug, http.StatusOK, "Ignoring comment event since action was not created %s", githubReqID) return } @@ -387,18 +372,23 @@ func (s *Server) handleCommentEvent(w http.ResponseWriter, event *gh.IssueCommen ctx := &CommandContext{} command, err := s.eventParser.DetermineCommand(event) if err != nil { - s.logger.Debug("Ignoring request: %v %s", err, githubReqID) - fmt.Fprintln(w, "Ignoring") + s.respond(w, logging.Debug, http.StatusOK, "Ignoring: %s %s", err, githubReqID) return } ctx.Command = command if err = s.eventParser.ExtractCommentData(event, ctx); err != nil { - s.logger.Err("Failed parsing event: %v %s", err, githubReqID) - fmt.Fprintln(w, "Ignoring") + s.respond(w, logging.Error, http.StatusInternalServerError, "Failed parsing event: %v %s", err, githubReqID) return } // respond with success and then actually execute the command asynchronously fmt.Fprintln(w, "Processing...") go s.commandHandler.ExecuteCommand(ctx) } + +func (s *Server) respond(w http.ResponseWriter, lvl logging.LogLevel, code int, format string, args... interface{}) { + response := fmt.Sprintf(format, args...) + s.logger.Log(lvl, response) + w.WriteHeader(code) + fmt.Fprintln(w, response) +}