webhook.go

package main

import (
	"encoding/json"
	"fmt"
	"io"
	"log"
	"net"
	"net/http"
	"os"
	"os/exec"
	"path/filepath"
	"strings"
	"time"

	"github.com/soulteary/webhook/internal/flags"
	"github.com/soulteary/webhook/internal/hook"
	"github.com/soulteary/webhook/internal/link"
	"github.com/soulteary/webhook/internal/middleware"
	"github.com/soulteary/webhook/internal/monitor"
	"github.com/soulteary/webhook/internal/pidfile"
	"github.com/soulteary/webhook/internal/platform"
	"github.com/soulteary/webhook/internal/rules"
	"github.com/soulteary/webhook/internal/version"

	chimiddleware "github.com/go-chi/chi/v5/middleware"
	"github.com/gorilla/mux"
	fsnotify "gopkg.in/fsnotify.v1"
)

var (
	watcher *fsnotify.Watcher
	signals chan os.Signal
	pidFile *pidfile.PIDFile
)

type flushWriter struct {
	f http.Flusher
	w io.Writer
}

func (fw *flushWriter) Write(p []byte) (n int, err error) {
	n, err = fw.w.Write(p)
	if fw.f != nil {
		fw.f.Flush()
	}
	return
}

func main() {
	appFlags := flags.Parse()

	if appFlags.ShowVersion {
		fmt.Println("webhook version " + version.Version)
		os.Exit(0)
	}

	if (appFlags.SetUID != 0 || appFlags.SetGID != 0) && (appFlags.SetUID == 0 || appFlags.SetGID == 0) {
		fmt.Println("error: setuid and setgid options must be used together")
		os.Exit(1)
	}

	if appFlags.Debug || appFlags.LogPath != "" {
		appFlags.Verbose = true
	}

	if len(rules.HooksFiles) == 0 {
		rules.HooksFiles = append(rules.HooksFiles, "hooks.json")
	}

	// logQueue is a queue for log messages encountered during startup. We need
	// to queue the messages so that we can handle any privilege dropping and
	// log file opening prior to writing our first log message.
	var logQueue []string

	addr := fmt.Sprintf("%s:%d", appFlags.Host, appFlags.Port)

	// Open listener early so we can drop privileges.
	ln, err := net.Listen("tcp", addr)
	if err != nil {
		logQueue = append(logQueue, fmt.Sprintf("error listening on port: %s", err))
		// we'll bail out below
	}

	if appFlags.SetUID != 0 {
		err := platform.DropPrivileges(appFlags.SetUID, appFlags.SetGID)
		if err != nil {
			logQueue = append(logQueue, fmt.Sprintf("error dropping privileges: %s", err))
			// we'll bail out below
		}
	}

	if appFlags.LogPath != "" {
		file, err := os.OpenFile(appFlags.LogPath, os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0600)
		if err != nil {
			logQueue = append(logQueue, fmt.Sprintf("error opening log file %q: %v", appFlags.LogPath, err))
			// we'll bail out below
		} else {
			log.SetOutput(file)
		}
	}

	log.SetPrefix("[webhook] ")
	log.SetFlags(log.Ldate | log.Ltime)

	if len(logQueue) != 0 {
		for i := range logQueue {
			log.Println(logQueue[i])
		}

		os.Exit(1)
	}

	if !appFlags.Verbose {
		log.SetOutput(io.Discard)
	}

	// Create pidfile
	if appFlags.PidPath != "" {
		var err error

		pidFile, err = pidfile.New(appFlags.PidPath)
		if err != nil {
			log.Fatalf("Error creating pidfile: %v", err)
		}

		defer func() {
			// NOTE(moorereason): my testing shows that this doesn't work with
			// ^C, so we also do a Remove in the signal handler elsewhere.
			if nerr := pidFile.Remove(); nerr != nil {
				log.Print(nerr)
			}
		}()
	}

	log.Println("version " + version.Version + " starting")

	// set os signal watcher
	if appFlags.AsTemplate {
		platform.SetupSignals(signals, rules.ReloadAllHooksAsTemplate, pidFile)
	} else {
		platform.SetupSignals(signals, rules.ReloadAllHooksNotAsTemplate, pidFile)
	}

	// load and parse hooks
	for _, hooksFilePath := range rules.HooksFiles {
		log.Printf("attempting to load hooks from %s\n", hooksFilePath)

		newHooks := hook.Hooks{}

		err := newHooks.LoadFromFile(hooksFilePath, appFlags.AsTemplate)
		if err != nil {
			log.Printf("couldn't load hooks from file! %+v\n", err)
		} else {
			log.Printf("found %d hook(s) in file\n", len(newHooks))

			for _, hook := range newHooks {
				if rules.MatchLoadedHook(hook.ID) != nil {
					log.Fatalf("error: hook with the id %s has already been loaded!\nplease check your hooks file for duplicate hooks ids!\n", hook.ID)
				}
				log.Printf("\tloaded: %s\n", hook.ID)
			}

			rules.LoadedHooksFromFiles[hooksFilePath] = newHooks
		}
	}

	newHooksFiles := rules.HooksFiles[:0]
	for _, filePath := range rules.HooksFiles {
		if _, ok := rules.LoadedHooksFromFiles[filePath]; ok {
			newHooksFiles = append(newHooksFiles, filePath)
		}
	}

	rules.HooksFiles = newHooksFiles

	if !appFlags.Verbose && !appFlags.NoPanic && rules.LenLoadedHooks() == 0 {
		log.SetOutput(os.Stdout)
		log.Fatalln("couldn't load any hooks from file!\naborting webhook execution since the -verbose flag is set to false.\nIf, for some reason, you want webhook to start without the hooks, either use -verbose flag, or -nopanic")
	}

	if appFlags.HotReload {
		var err error

		watcher, err = fsnotify.NewWatcher()
		if err != nil {
			log.Fatal("error creating file watcher instance\n", err)
		}
		defer watcher.Close()

		for _, hooksFilePath := range rules.HooksFiles {
			// set up file watcher
			log.Printf("setting up file watcher for %s\n", hooksFilePath)

			err = watcher.Add(hooksFilePath)
			if err != nil {
				log.Print("error adding hooks file to the watcher\n", err)
				return
			}
		}

		go monitor.WatchForFileChange(watcher, appFlags.AsTemplate, appFlags.Verbose, appFlags.NoPanic, rules.ReloadHooks, rules.RemoveHooks)
	}

	r := mux.NewRouter()

	r.Use(middleware.RequestID(
		middleware.UseXRequestIDHeaderOption(appFlags.UseXRequestID),
		middleware.XRequestIDLimitOption(appFlags.XRequestIDLimit),
	))
	r.Use(middleware.NewLogger())
	r.Use(chimiddleware.Recoverer)

	if appFlags.Debug {
		r.Use(middleware.Dumper(log.Writer()))
	}

	// Clean up input
	appFlags.HttpMethods = strings.ToUpper(strings.ReplaceAll(appFlags.HttpMethods, " ", ""))

	hooksURL := link.MakeRoutePattern(&appFlags.HooksURLPrefix)

	r.HandleFunc("/", func(w http.ResponseWriter, req *http.Request) {
		for _, responseHeader := range appFlags.ResponseHeaders {
			w.Header().Set(responseHeader.Name, responseHeader.Value)
		}

		fmt.Fprint(w, "OK")
	})

	hookHandler := createHookHandler(appFlags)
	r.HandleFunc(hooksURL, hookHandler)

	// Create common HTTP server settings
	svr := &http.Server{
		Addr:              addr,
		Handler:           r,
		ReadHeaderTimeout: 5 * time.Second,
		ReadTimeout:       5 * time.Second,
	}

	// Serve HTTP
	log.Printf("serving hooks on http://%s%s", addr, link.MakeHumanPattern(&appFlags.HooksURLPrefix))
	log.Print(svr.Serve(ln))
}

func createHookHandler(appFlags flags.AppFlags) func(w http.ResponseWriter, r *http.Request) {
	return func(w http.ResponseWriter, r *http.Request) {
		req := &hook.Request{
			ID:         middleware.GetReqID(r.Context()),
			RawRequest: r,
		}

		log.Printf("[%s] incoming HTTP %s request from %s\n", req.ID, r.Method, r.RemoteAddr)

		// TODO: rename this to avoid confusion with Request.ID
		id := mux.Vars(r)["id"]

		matchedHook := rules.MatchLoadedHook(id)
		if matchedHook == nil {
			w.WriteHeader(http.StatusNotFound)
			fmt.Fprint(w, "Hook not found.")
			return
		}

		// Check for allowed methods
		var allowedMethod bool

		switch {
		case len(matchedHook.HTTPMethods) != 0:
			for i := range matchedHook.HTTPMethods {
				// TODO(moorereason): refactor config loading and reloading to
				// sanitize these methods once at load time.
				if r.Method == strings.ToUpper(strings.TrimSpace(matchedHook.HTTPMethods[i])) {
					allowedMethod = true
					break
				}
			}
		case appFlags.HttpMethods != "":
			for _, v := range strings.Split(appFlags.HttpMethods, ",") {
				if r.Method == v {
					allowedMethod = true
					break
				}
			}
		default:
			allowedMethod = true
		}

		if !allowedMethod {
			w.WriteHeader(http.StatusMethodNotAllowed)
			log.Printf("[%s] HTTP %s method not allowed for hook %q", req.ID, r.Method, id)

			return
		}

		log.Printf("[%s] %s got matched\n", req.ID, id)

		for _, responseHeader := range appFlags.ResponseHeaders {
			w.Header().Set(responseHeader.Name, responseHeader.Value)
		}

		var err error

		// set contentType to IncomingPayloadContentType or header value
		req.ContentType = r.Header.Get("Content-Type")
		if len(matchedHook.IncomingPayloadContentType) != 0 {
			req.ContentType = matchedHook.IncomingPayloadContentType
		}

		isMultipart := strings.HasPrefix(req.ContentType, "multipart/form-data;")

		if !isMultipart {
			req.Body, err = io.ReadAll(r.Body)
			if err != nil {
				log.Printf("[%s] error reading the request body: %+v\n", req.ID, err)
			}
		}

		req.ParseHeaders(r.Header)
		req.ParseQuery(r.URL.Query())

		switch {
		case strings.Contains(req.ContentType, "json"):
			err = req.ParseJSONPayload()
			if err != nil {
				log.Printf("[%s] %s", req.ID, err)
			}

		case strings.Contains(req.ContentType, "x-www-form-urlencoded"):
			err = req.ParseFormPayload()
			if err != nil {
				log.Printf("[%s] %s", req.ID, err)
			}

		case strings.Contains(req.ContentType, "xml"):
			err = req.ParseXMLPayload()
			if err != nil {
				log.Printf("[%s] %s", req.ID, err)
			}

		case isMultipart:
			err = r.ParseMultipartForm(appFlags.MaxMultipartMem)
			if err != nil {
				msg := fmt.Sprintf("[%s] error parsing multipart form: %+v\n", req.ID, err)
				log.Println(msg)
				w.WriteHeader(http.StatusInternalServerError)
				fmt.Fprint(w, "Error occurred while parsing multipart form.")
				return
			}

			for k, v := range r.MultipartForm.Value {
				log.Printf("[%s] found multipart form value %q", req.ID, k)

				if req.Payload == nil {
					req.Payload = make(map[string]interface{})
				}

				// TODO(moorereason): support duplicate, named values
				req.Payload[k] = v[0]
			}

			for k, v := range r.MultipartForm.File {
				// Force parsing as JSON regardless of Content-Type.
				var parseAsJSON bool
				for _, j := range matchedHook.JSONStringParameters {
					if j.Source == "payload" && j.Name == k {
						parseAsJSON = true
						break
					}
				}

				// TODO(moorereason): we need to support multiple parts
				// with the same name instead of just processing the first
				// one. Will need #215 resolved first.

				// MIME encoding can contain duplicate headers, so check them
				// all.
				if !parseAsJSON && len(v[0].Header["Content-Type"]) > 0 {
					for _, j := range v[0].Header["Content-Type"] {
						if j == "application/json" {
							parseAsJSON = true
							break
						}
					}
				}

				if parseAsJSON {
					log.Printf("[%s] parsing multipart form file %q as JSON\n", req.ID, k)

					f, err := v[0].Open()
					if err != nil {
						msg := fmt.Sprintf("[%s] error parsing multipart form file: %+v\n", req.ID, err)
						log.Println(msg)
						w.WriteHeader(http.StatusInternalServerError)
						fmt.Fprint(w, "Error occurred while parsing multipart form file.")
						return
					}

					decoder := json.NewDecoder(f)
					decoder.UseNumber()

					var part map[string]interface{}
					err = decoder.Decode(&part)
					if err != nil {
						log.Printf("[%s] error parsing JSON payload file: %+v\n", req.ID, err)
					}

					if req.Payload == nil {
						req.Payload = make(map[string]interface{})
					}
					req.Payload[k] = part
				}
			}

		default:
			log.Printf("[%s] error parsing body payload due to unsupported content type header: %s\n", req.ID, req.ContentType)
		}

		// handle hook
		errors := matchedHook.ParseJSONParameters(req)
		for _, err := range errors {
			log.Printf("[%s] error parsing JSON parameters: %s\n", req.ID, err)
		}

		var ok bool

		if matchedHook.TriggerRule == nil {
			ok = true
		} else {
			// Save signature soft failures option in request for evaluators
			req.AllowSignatureErrors = matchedHook.TriggerSignatureSoftFailures

			ok, err = matchedHook.TriggerRule.Evaluate(req)
			if err != nil {
				if !hook.IsParameterNodeError(err) {
					msg := fmt.Sprintf("[%s] error evaluating hook: %s", req.ID, err)
					log.Println(msg)
					w.WriteHeader(http.StatusInternalServerError)
					fmt.Fprint(w, "Error occurred while evaluating hook rules.")
					return
				}

				log.Printf("[%s] %v", req.ID, err)
			}
		}

		if ok {
			log.Printf("[%s] %s hook triggered successfully\n", req.ID, matchedHook.ID)

			for _, responseHeader := range matchedHook.ResponseHeaders {
				w.Header().Set(responseHeader.Name, responseHeader.Value)
			}

			if matchedHook.StreamCommandOutput {
				_, err := handleHook(matchedHook, req, w)
				if err != nil {
					fmt.Fprint(w, "Error occurred while executing the hook's stream command. Please check your logs for more details.")
				}
			} else if matchedHook.CaptureCommandOutput {
				response, err := handleHook(matchedHook, req, nil)

				if err != nil {
					w.WriteHeader(http.StatusInternalServerError)
					if matchedHook.CaptureCommandOutputOnError {
						fmt.Fprint(w, response)
					} else {
						w.Header().Set("Content-Type", "text/plain; charset=utf-8")
						fmt.Fprint(w, "Error occurred while executing the hook's command. Please check your logs for more details.")
					}
				} else {
					// Check if a success return code is configured for the hook
					if matchedHook.SuccessHttpResponseCode != 0 {
						writeHttpResponseCode(w, req.ID, matchedHook.ID, matchedHook.SuccessHttpResponseCode)
					}
					fmt.Fprint(w, response)
				}
			} else {
				go handleHook(matchedHook, req, nil)

				// Check if a success return code is configured for the hook
				if matchedHook.SuccessHttpResponseCode != 0 {
					writeHttpResponseCode(w, req.ID, matchedHook.ID, matchedHook.SuccessHttpResponseCode)
				}

				fmt.Fprint(w, matchedHook.ResponseMessage)
			}
			return
		}

		// Check if a return code is configured for the hook
		if matchedHook.TriggerRuleMismatchHttpResponseCode != 0 {
			writeHttpResponseCode(w, req.ID, matchedHook.ID, matchedHook.TriggerRuleMismatchHttpResponseCode)
		}

		// if none of the hooks got triggered
		log.Printf("[%s] %s got matched, but didn't get triggered because the trigger rules were not satisfied\n", req.ID, matchedHook.ID)

		fmt.Fprint(w, "Hook rules were not satisfied.")
	}
}

func handleHook(h *hook.Hook, r *hook.Request, w http.ResponseWriter) (string, error) {
	var errors []error

	// check the command exists
	var lookpath string
	if filepath.IsAbs(h.ExecuteCommand) || h.CommandWorkingDirectory == "" {
		lookpath = h.ExecuteCommand
	} else {
		lookpath = filepath.Join(h.CommandWorkingDirectory, h.ExecuteCommand)
	}

	cmdPath, err := exec.LookPath(lookpath)
	if err != nil {
		log.Printf("[%s] error in %s", r.ID, err)

		// check if parameters specified in execute-command by mistake
		if strings.IndexByte(h.ExecuteCommand, ' ') != -1 {
			s := strings.Fields(h.ExecuteCommand)[0]
			log.Printf("[%s] use 'pass-arguments-to-command' to specify args for '%s'", r.ID, s)
		}

		return "", err
	}

	cmd := exec.Command(cmdPath)
	cmd.Dir = h.CommandWorkingDirectory

	cmd.Args, errors = h.ExtractCommandArguments(r)
	for _, err := range errors {
		log.Printf("[%s] error extracting command arguments: %s\n", r.ID, err)
	}

	var envs []string
	envs, errors = h.ExtractCommandArgumentsForEnv(r)

	for _, err := range errors {
		log.Printf("[%s] error extracting command arguments for environment: %s\n", r.ID, err)
	}

	files, errors := h.ExtractCommandArgumentsForFile(r)

	for _, err := range errors {
		log.Printf("[%s] error extracting command arguments for file: %s\n", r.ID, err)
	}

	for i := range files {
		tmpfile, err := os.CreateTemp(h.CommandWorkingDirectory, files[i].EnvName)
		if err != nil {
			log.Printf("[%s] error creating temp file [%s]", r.ID, err)
			continue
		}
		log.Printf("[%s] writing env %s file %s", r.ID, files[i].EnvName, tmpfile.Name())
		if _, err := tmpfile.Write(files[i].Data); err != nil {
			log.Printf("[%s] error writing file %s [%s]", r.ID, tmpfile.Name(), err)
			continue
		}
		if err := tmpfile.Close(); err != nil {
			log.Printf("[%s] error closing file %s [%s]", r.ID, tmpfile.Name(), err)
			continue
		}

		files[i].File = tmpfile
		envs = append(envs, files[i].EnvName+"="+tmpfile.Name())
	}

	cmd.Env = append(os.Environ(), envs...)

	log.Printf("[%s] executing %s (%s) with arguments %q and environment %s using %s as cwd\n", r.ID, h.ExecuteCommand, cmd.Path, cmd.Args, envs, cmd.Dir)

	var out []byte
	if w != nil {
		log.Printf("[%s] command output will be streamed to response", r.ID)

		// Implementation from https://play.golang.org/p/PpbPyXbtEs
		// as described in https://stackoverflow.com/questions/19292113/not-buffered-http-responsewritter-in-golang
		fw := flushWriter{w: w}
		if f, ok := w.(http.Flusher); ok {
			fw.f = f
		}
		cmd.Stderr = &fw
		cmd.Stdout = &fw

		if err := cmd.Run(); err != nil {
			log.Printf("[%s] error occurred: %+v\n", r.ID, err)
		}
	} else {
		out, err = cmd.CombinedOutput()

		log.Printf("[%s] command output: %s\n", r.ID, out)

		if err != nil {
			log.Printf("[%s] error occurred: %+v\n", r.ID, err)
		}
	}

	for i := range files {
		if files[i].File != nil {
			log.Printf("[%s] removing file %s\n", r.ID, files[i].File.Name())
			err := os.Remove(files[i].File.Name())
			if err != nil {
				log.Printf("[%s] error removing file %s [%s]", r.ID, files[i].File.Name(), err)
			}
		}
	}

	log.Printf("[%s] finished handling %s\n", r.ID, h.ID)

	return string(out), err
}

func writeHttpResponseCode(w http.ResponseWriter, rid, hookId string, responseCode int) {
	// Check if the given return code is supported by the http package
	// by testing if there is a StatusText for this code.
	if len(http.StatusText(responseCode)) > 0 {
		w.WriteHeader(responseCode)
	} else {
		log.Printf("[%s] %s got matched, but the configured return code %d is unknown - defaulting to 200\n", rid, hookId, responseCode)
	}
}