OOM in a Gin API Gateway: Caching Every Response Body

Posted on Edited on Views: Word count in article: 2.4k Reading time ≈ 2 mins.
A postmortem of an OOM caused by caching every response body in a Gin API gateway: why memory ballooned in minutes, and a safer implementation.

Reuse existing libraries; don’t reinvent the wheel :sob: :sob: :sob: :sob: :sob: :sob:

Symptom: gateway memory spikes in minutes

We built an API gateway on top of Gin. After deploying it, we found that memory would surge in a short time and then the process would be OOM-killed. The memory trend looked like this:

Memory monitoring with English time-range controls

Zooming in on one occurrence:

Memory usage during the Gin response-body OOM investigation

In the second chart you can see how fast memory grows: nearly 2 GB in a minute and a half.

For problems where memory spikes this fast, it’s hard to catch the state in time with pprof — unless you write a script that samples pprof on a timer.

Root cause: every request cached the response body

Another pass over the code turned up the cause:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
package server

import (
	"bytes"
	"fmt"

	"github.com/gin-gonic/gin"
	jsoniter "github.com/json-iterator/go"
)

var json = jsoniter.ConfigCompatibleWithStandardLibrary

type BodyDumpResponseWriter struct {
	gin.ResponseWriter
	body *bytes.Buffer
}

func (w *BodyDumpResponseWriter) Write(b []byte) (int, error) {
	w.body.Write(b) // note this line
	return w.ResponseWriter.Write(b)
}

func ReadResponseBody(ctx *gin.Context) {
	rbw := &BodyDumpResponseWriter{body: &bytes.Buffer{}, ResponseWriter: ctx.Writer}
	ctx.Writer = rbw

	ctx.Next()

	rawResp := rbw.body.String()
	if len(rawResp) == 0 {
		AbnormalPrint(ctx, "resp-empty", rawResp)
		return
	}
	ctx.Set(ctx_raw_response_body, rawResp)

	// serialize the Body and put it in the ctx
	// the response Body is read so it can be written to the audit log
}

// AbnormalPrint logs diagnostic info on abnormal conditions
func AbnormalPrint(ctx *gin.Context, typ string, rawResp string) {
// actual code omitted
}

At a glance, isn’t this the standard way to capture the response body in Gin? After all, this is exactly how it is written on GitHub and Stack Overflow:
https://github.com/gin-gonic/gin/issues/1363
https://stackoverflow.com/questions/38501325/how-to-log-response-body-in-gin

So where is the problem?

Look at the code again: the logic keeps a complete copy of every response body in memory. For requests with large response bodies, that alone causes memory to spike — a log download, for example.

Fix: skip caching by request type

Once the cause was clear, the fix was simple: skip file-download requests based on the response headers, and skip SSE and WebSocket requests based on the request headers — streaming responses are of little value in the audit log, and they also break JSON serialization.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
package server

import (
	"bytes"
	"fmt"
	"net/http"
	"strings"

	"github.com/gin-gonic/gin"
	jsoniter "github.com/json-iterator/go"
)

var json = jsoniter.ConfigCompatibleWithStandardLibrary

type BodyDumpResponseWriter struct {
	gin.ResponseWriter
	body *bytes.Buffer
}

func (w *BodyDumpResponseWriter) Write(b []byte) (int, error) {
	// file-download requests: no longer cache the response
	if !isFileDownLoad(w.Header()) {
		w.body.Write(b)
	}
	return w.ResponseWriter.Write(b)
}

func isNoNeedToReadResponse(req *http.Request) bool {
	if isSSE(req) || isWebsocket(req) {
		return true
	}
	return false
}

func isSSE(req *http.Request) bool {
	contentType := req.Header.Get("Accept")
	if contentType == "" {
		contentType = req.Header.Get("accept")
	}
	contentType = strings.ToLower(contentType)
	// sse
	if !strings.Contains(contentType, "text/event-stream") {
		return false
	}
	return true
}

// https://developer.mozilla.org/zh-CN/docs/Web/HTTP/Basics_of_HTTP/MIME_types
// https://developer.mozilla.org/en-US/docs/Web/HTTP/Headers/Content-Disposition
func isFileDownLoad(responseHeader http.Header) bool {
	contentType := strings.ToLower(responseHeader.Get("Content-Type"))
	if strings.Contains(contentType, "application/octet-stream") {
		return true
	}
	contentDisposition := responseHeader.Get("Content-Disposition")
	if contentDisposition != "" {
		return true
	}
	return false
}

func isWebsocket(req *http.Request) bool {
	conntype := strings.ToLower(req.Header.Get("Connection"))
	upgrade := strings.ToLower(req.Header.Get("Upgrade"))
	if conntype == "upgrade" && upgrade == "websocket" {
		return true
	}
	return false
}

func ReadResponseBody(ctx *gin.Context) {

	if isNoNeedToReadResponse(ctx.Request) {
		return
	}

	rbw := &BodyDumpResponseWriter{body: &bytes.Buffer{}, ResponseWriter: ctx.Writer}
	ctx.Writer = rbw

	ctx.Next()

	contentType := ctx.Writer.Header().Get("content-type")
	if !strings.Contains(contentType, "application/json") {
		return
	}

	rawResp := rbw.body.String()
	if len(rawResp) == 0 {
		AbnormalPrint(ctx, "resp-empty", rawResp)
		return
	}
	ctx.Set(ctx_raw_response_body, rawResp)

	// serialize the Body and put it in the ctx
	// the response Body is read so it can be written to the audit log
}

// AbnormalPrint logs diagnostic info on abnormal conditions
func AbnormalPrint(ctx *gin.Context, typ string, rawResp string) {
// actual code omitted
}

Postmortem: when you copy code, mind your own use case

The real point of this post is not how the problem was fixed, but this:

  • When you copy code, pay attention to whether it fits your context.
  • Reuse existing libraries instead of rolling your own.

While hand-writing the API gateway, we also ran into the following:

  • The first version of the network handling was hand-written too, which meant it handled the various Content-Types badly;
  • Because we had to parse the body, and didn’t have the capacity to support every compression scheme, compression had to be forcibly disabled at the gateway;
  • Hand-written network handling produces strange problems
    • For example: we ship a browser-based terminal that connects to a K8S cluster over WebSocket. Suppose the service behind that connection is service A (browser <—-> gateway <—-> service A <—-> K8S cluster). Later, some requests going through the gateway would hit service A directly — skipping the gateway’s API router entirely and reusing the WebSocket connection — even when those APIs did not belong to service A.

A sketch of the first hand-written version of the request handling:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
func proxyHttp(ctx context.Context, proxy_req *http.Request, domain string) {
	// origin request
	req := ctx.Request()

	response, err := HttpClient.Do(proxy_req)
	if err != nil {
		// log the error
		return
	}

	defer response.Body.Close()

	//copy response header
	if response != nil && response.Header != nil {
		for k, values := range response.Header {
			for _, value := range values {
				ctx.ResponseWriter().Header().Set(k, value)
			}
		}
	}
	// status code
	ctx.StatusCode(response.StatusCode)
	buf := make([]byte, 1024)

	for {
		len, err := response.Body.Read(buf)
		if err != nil && err != io.EOF {
			// log the error
			break
		}
		if len == 0 {
			break
		}

		ctx.ResponseWriter().Write(buf[:len])
		ctx.ResponseWriter().Flush()
		continue

	}
	ctx.Next()
}

func proxyWebSocket(ctx context.Context, request *http.Request, target string) {
	var logger = ctx.Application().Logger()
	responseWriter := http.ResponseWriter(ctx.ResponseWriter())

	conn, err := net.Dial("tcp", target)
	if err != nil {
		// log the error
		return
	}
	hijacker, ok := responseWriter.(http.Hijacker)
	if !ok {
		http.Error(responseWriter, "Not a hijacker?", 500)
		return
	}

	nc, _, err := hijacker.Hijack()
	if err != nil {
		// log the error
		return
	}
	defer nc.Close()
	defer conn.Close()

	err = request.Write(conn)
	if err != nil {
		// log the error
		return
	}

	errc := make(chan error, 2)
	cp := func(dst io.Writer, src io.Reader) {
		_, err := io.Copy(dst, src)
		errc <- err
	}
	go cp(conn, nc)
	go cp(nc, conn)

	// wait over
	<-errc

	ctx.Application().Logger().Infof("websocket proxy to %s over", target)
}

We eventually switched to the standard library’s httputil.ReverseProxy for connection handling, and the problem went away.

This article is the English edition of a post originally published in Chinese.