1

I am creating a receiver for webhooks in Go, this is my first application in Go.

I have tested the application locally and it works over there. But now I have deployed it on my Ubuntu server in a Docker container behind an NGINX proxy (the proxy is outside of Docker). The pingHandler works, and the gitlabHandler can send the 403 message. But if the token is valid I will always see a 502 message and the NGINX log tells me:

*1115 upstream prematurely closed connection while reading response header from upstream, client: X.X.X.X, server: myserver.home.example, request: "POST /webhookreceiver/gitlab HTTP/1.1", upstream: "http://127.0.0.1:7080/gitlab", host: "myserver.home.example"

Also when I send an invalid JSON payload it will still give the same error message, so if I understand the error correctly my Go application closes the connection somewhere before line 72-76. I am guessing something is wrong with line 65?

For most other people having this issue it can be solved by increasing the timeout because their requests are too large, but in my case I am testing with a JSON message of only a few bytes.

main.go

package main

import (
    "bytes"
    "encoding/json"
    "fmt"
    "io/ioutil"
    "log"
    "net/http"
    "os"
    "strings"
    "time"
)

type ServerConfig struct {
    Https       bool   `json:"https"`
    Cert        string `json:"cert"`
    Key         string `json:"key"`
    Gitlabtoken string `json:"gitlab_token"`
}

type SplunkConfig struct {
    Token    string
    Url      string
    Metadata map[string]string
}

type SplunkEvent struct {
    Host       string                 `json:"host"`
    Sourcetype string                 `json:"sourcetype"`
    Index      string                 `json:"index"`
    Source     string                 `json:"source"`
    Event      map[string]interface{} `json:"event"`
}

var splunk_config SplunkConfig
var server_config ServerConfig

type middleware func(next http.HandlerFunc) http.HandlerFunc

func withLogging(next http.HandlerFunc) http.HandlerFunc {
    return func(w http.ResponseWriter, r *http.Request) {
        log.Printf("IP %s", r.RemoteAddr)
        next.ServeHTTP(w, r)
    }
}

func chainMiddleware(mw ...middleware) middleware {
    return func(final http.HandlerFunc) http.HandlerFunc {
        return func(w http.ResponseWriter, r *http.Request) {
            last := final
            for i := len(mw) - 1; i >= 0; i-- {
                last = mw[i](last)
            }
            last(w, r)
        }
    }
}

func gitlabHandler(w http.ResponseWriter, req *http.Request) {
    // Check if GitLab token is present and correct
    gitlab_header := req.Header.Get("X-Gitlab-Token")
    if gitlab_header == server_config.Gitlabtoken {
        // Create SplunkEvent to send to Splunk
        body, err := ioutil.ReadAll(req.Body)
        if err != nil {
            log.Println(err)
            w.WriteHeader(http.StatusInternalServerError)
            w.Write([]byte("500 - Error reading body"))
            return
        }
        var event map[string]interface{}
        err = json.Unmarshal(body, &event)
        if err != nil {
            log.Println(err)
            w.WriteHeader(http.StatusBadRequest)
            w.Write([]byte("400 - Request cannot be parsed"))
            return
        }
        se := SplunkEvent{
            Host:       splunk_config.Metadata["host"],
            Sourcetype: splunk_config.Metadata["sourcetype"],
            Index:      splunk_config.Metadata["index"],
            Source:     "gitlab",
            Event:      event}
        j, err := json.Marshal(se)
        if err != nil {
            log.Println(err)
            w.WriteHeader(http.StatusInternalServerError)
            w.Write([]byte("500 - Error creating forwarding call"))
            return
        }
        // Send SplunkEvent to Splunk
        b := bytes.NewBuffer(j)
        client := &http.Client{
            Timeout: time.Second * 30,
        }
        req, err := http.NewRequest("POST", splunk_config.Url, b)
        if err != nil {
            log.Println(err)
            w.WriteHeader(http.StatusInternalServerError)
            w.Write([]byte("500 - Error creating request"))
            return
        }
        req.Header.Add("Authorization", "Splunk "+splunk_config.Token)
        resp, err := client.Do(req)
        if err != nil {
            log.Println(err)
            w.WriteHeader(http.StatusInternalServerError)
            w.Write([]byte("500 - Error sending request"))
            return
        }
        // Check response
        bod, err := ioutil.ReadAll(resp.Body)
        if strings.Contains(string(bod), "Success") {
            log.Println("Received and succesfully processed request")
            w.WriteHeader(http.StatusOK)
            w.Write([]byte("200 - OK"))
            return
        } else {
            log.Println(string(bod))
            w.WriteHeader(http.StatusInternalServerError)
            w.Write([]byte("500 - Error sending to Splunk"))
            return
        }
        defer resp.Body.Close()
    } else {
        log.Println("Incorrect Gitlab token")
        w.WriteHeader(http.StatusForbidden)
        w.Write([]byte("403 - Forbidden"))
        return
    }
}

func pingHandler(w http.ResponseWriter, r *http.Request) {
    log.Println("Received ping call")
    fmt.Fprint(w, "{\"check\": \"online\"}")
}

func main() {
    // Setup logging
    file, err := os.OpenFile("webhookreceiver.log", os.O_CREATE|os.O_APPEND, 0644)
    if err != nil {
        log.Fatal("Error opening log file: " + err.Error())
    }
    defer file.Close()
    log.SetOutput(file)
    // Load Splunk config
    data, err := ioutil.ReadFile("configs/splunk.json")
    if err != nil {
        log.Fatal("Error reading splunk_config.json: " + err.Error())
    }
    err = json.Unmarshal(data, &splunk_config)
    if err != nil {
        log.Fatal("Error on unmarshal of Splunk config: " + err.Error())
    }
    // Load server config
    data, err = ioutil.ReadFile("configs/server.json")
    if err != nil {
        log.Fatal("Error reading server_config.json: " + err.Error())
    }
    err = json.Unmarshal(data, &server_config)
    if err != nil {
        log.Fatal("Error on unmarshal of Server config: " + err.Error())
    }
    // Start server
    log.Println("Starting server")
    mw := chainMiddleware(withLogging)
    http.Handle("/gitlab", mw(gitlabHandler))
    http.HandleFunc("/ping", mw(pingHandler))
    if server_config.Https {
        log.Fatal(http.ListenAndServeTLS(":7443", server_config.Cert, server_config.Key, nil))
    } else {
        log.Fatal(http.ListenAndServe(":7080", nil))
    }
}

Relevant bit of NGINX config

server {
  listen 443 ssl;
  listen [::]:443 ssl;
  ssl_certificate /blabla/fullchain.pem;
  ssl_certificate_key /blabla/privkey.pem;
  client_max_body_size 3M;
  add_header Strict-Transport-Security "max-age=31536000" always;
  location /webhookreceiver/ {
    proxy_pass http://127.0.0.1:7080/;
    proxy_set_header X-Real-IP $remote_addr;
    proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
  }
}

Also the logging of my Go application is working locally but not inside of my Docker container, the log file is being created but it stays empty. So at this point I don't have any messages from there, unless someone knows why that is ;-)

Bob
  • 614
  • 1
  • 7
  • 19
  • Have you tried without timeout? Like maybe using the [default client](https://golang.org/pkg/net/http/#DefaultClient)? – mkopriva Jan 06 '19 at 20:56
  • 2
    You are not exiting the request handler when an error occurs, leading to multiple WriteHeader calls and possibly even nil-pointer dereferences (panics), which would explain the behavior you describe. That should be visible in the logs. Move the deferred `resp.Body.Close` call up before inserting return calls, so it always executes if there is a response. – Peter Jan 06 '19 at 21:00
  • @Peter that makes sense, unfortunately after making those changes the NGINX error remains, and the other logs remain empty... – Bob Jan 06 '19 at 21:12
  • How are you checking the logs. You're aware that you redirect them to a file within the container? Do you not even see the "Starting server" and "IP ..." lines? – Peter Jan 06 '19 at 21:20
  • Yes, I am looking at the file inside of the container which apparently is succesfully created by the application, but indeed, even those lines do not show up. Even though they do show up locally. – Bob Jan 06 '19 at 21:23
  • Check this answer https://stackoverflow.com/a/24830777/1370029. It was helpful in my case. Also check for errors in the SELinux logs : `sudo cat /var/log/audit/audit.log | grep nginx | grep denied` – Aliaksei Maniuk Jan 13 '22 at 03:09

1 Answers1

0

Have you tried looking at the Docker logs instead of the log file that isn't working? First get the container ID:

docker container ls

Then get the log:

docker logs 14eb7d0a2332

The nginx error means that your Golang application accepted the connection, but closed the connection without returning a response. This indicates that your webhook is returning without writing a response.

It looks like your gitlabHandler does not return a response when the request succeeds, the last thing that you do is read the upstream response:

    bod, err := ioutil.ReadAll(resp.Body)
    if strings.Contains(string(bod), "Success") {
        log.Println("Received and succesfully processed request")
    } else {
        log.Println(string(bod))
    }
    defer resp.Body.Close()

You need to write to the ResponseWriter here.

Aaron
  • 29
  • 1
  • The Docker log is empty. I have added lines to always write a response (see the update of my post), thanks that is at least one thing I missed :-) Unfortunately the error is still occurring. I did expect that because the error also occurs when I send invalid JSON and then the gitlabHandler should return before reaching that last bit. – Bob Jan 06 '19 at 20:46
  • 2
    If WriteHeader is not called by the handler, the http package calls `WriteHeader(200)` automatically. – Peter Jan 06 '19 at 21:09