Recommanded Free YOUTUBE Lecture: <% selectedImage[1] %>

Contents

Middleware에 대해서

미들웨어(Middleware)는 소프트웨어 구성요소의 입력과 출력 사이에서 데이터를 처리하는 시스템이다. 따라서 개발자는 응용 프로그램의 목적에만 집중 할 수 있다.

웹 서버의 경우에는 데이터베이스 액세스, 보안, 인증, 로깅과 같은 작업을 처리하기 위해서 사용한다. 이들 기능은 모든 서비스에 공통적으로 사용되기 마련이다. 이런 작업들을 미들웨어에서 대신 처리해 주기 때문에, 개발자는 핵심 로직에만 신경쓰면 된다.

 Middleware

  1. HTTP Request가 서버로 전송된다.
  2. MUX가 요청을 특정 핸들러로 라우팅하고 디스패치한다.
  3. 미들웨어를 실행한다.
  4. 핸들러를 실행한다.

기본 원칙

미들웨어는 핸들러를 감싸는 구조로 실행되는 함수이므로 핸들러(http.Handler)를 파라미터로 전달하면 된다.
func exampleMiddleware(next http.Handler) http.Handler {
  return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
    // 여기에 미들웨어 로직을 코딩한다. 
    next.ServeHTTP(w, r)
  })
}

미들웨어는 핸들러와 동일하게 http.Handler를 리턴하기 때문에 아래와 같이 미들웨어 함수를 중첩하여 임의의 핸들러 체인을 만들 수 있다.
mux := http.NewServeMux()
mux.Handle("/", middlewareOne(middlewareTwo(finalHandler)))

기본 예제

package main

import (
	"log"
	"net/http"
)

func middlewareOne(next http.Handler) http.Handler {
	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		log.Println("Executing middlewareOne Pre")
		next.ServeHTTP(w, r)
		log.Println("Executing middlewareOne Post")
	})
}

func middlewareTwo(next http.Handler) http.Handler {
	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		log.Println("Executing middlewareTwo Pre")
		if r.URL.Path == "/foo" {
			return
		}

		next.ServeHTTP(w, r)
		log.Println("Executing middlewareTwo Post")
	})
}

func final(w http.ResponseWriter, r *http.Request) {
	log.Println("Executing finalHandler")
	w.Write([]byte("OK"))
}

func main() {
	mux := http.NewServeMux()

	finalHandler := http.HandlerFunc(final)
	mux.Handle("/", middlewareOne(middlewareTwo(finalHandler)))

	log.Println("Listening on :3000...")
	err := http.ListenAndServe(":3000", mux)
	log.Fatal(err)
}
미들웨어는 중첩 순서대로 실행되며, 역방향으로 복구된다. 위 코드를 실행해보자.
2021/04/20 17:00:26 Executing middlewareOne Pre
2021/04/20 17:00:26 Executing middlewareTwo Pre
2021/04/20 17:00:26 Executing finalHandler
2021/04/20 17:00:26 Executing middlewareTwo Post
2021/04/20 17:00:26 Executing middlewareOne Post
미들웨어는 핸들러가 실행전과 실행후에 코드를 넣을 수 있다.
  1. 실행전 : 인증, 권한, 올바른 요청인지 확인..
  2. 실행후 : 에러처리, 로깅
중첩된 미들웨어는 return을 통해서 전파를 중지하고 빠져나올 수 있다. http://localhost:3000/foo 로 테스트해보자.
2021/04/20 16:58:19 Executing middlewareOne Pre
2021/04/20 16:58:19 Executing middlewareTwo Pre
2021/04/20 16:58:19 Executing middlewareOne Post

실제 사용

좀 더 현실적인 프로그램을 만들어 보자. 이 프로그램은 특정 클라이언트 ID와 시크릿 키를 포함하고 있는지 그리고 Content-Type이 application/json으로 설정됐는지를 검사한다.
package main

import (
	"log"
	"net/http"
)

func enforceHeaderHandler(next http.Handler) http.Handler {
	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		clientID := r.Header.Get("Joinc-Client-ID")
		if clientID != "yundream" {
			http.Error(w, "Client not found", http.StatusForbidden)
			return
		}
		clientAccessID := r.Header.Get("Joinc-Client-Key")
		if clientAccessID != "mysecretkey" {
			http.Error(w, "Invalid Secret Key", http.StatusForbidden)
			return
		}
		contentType := r.Header.Get("Content-Type")
		if contentType != "application/json" {
			http.Error(w, "Invalid Secret Key", http.StatusForbidden)
			return
		}
		next.ServeHTTP(w,r)
	})
}

func final(w http.ResponseWriter, r *http.Request) {
	log.Println("Executing finalHandler")
	w.Write([]byte("OK"))
}

func main() {
	mux := http.NewServeMux()

	finalHandler := http.HandlerFunc(final)
	mux.Handle("/", enforceHeaderHandler(finalHandler))

	log.Println("Listening on :3000...")
	err := http.ListenAndServe(":3000", mux)
	log.Fatal(err)
}
테스트해 보자.
# curl -i localhost:3000
HTTP/1.1 403 Forbidden
Content-Type: text/plain; charset=utf-8
X-Content-Type-Options: nosniff
Date: Wed, 21 Apr 2021 08:34:10 GMT
Content-Length: 17

Client not found

# curl -i localhost:3000 -H "Joinc-Client-ID:yundream" -H "Joinc-Client-Key:mysecretkey" -H "Content-Type: application/json"
HTTP/1.1 200 OK
Date: Wed, 21 Apr 2021 08:54:15 GMT
Content-Length: 2
Content-Type: text/plain; charset=utf-8

OK

echo 프레임워크에서의 미들웨어

이렇게 기본 net/http 패키지만을 이용해서 미들웨어를 포함한 완전한 웹 애플리케이션 서버를 개발 할 수 있기는 하지만 많은 시간과 노력이 들어간다. 개발자들은 시간을 아끼기 위해서 3rd-party 패키지를 찾는다.

현재 가장 많은 star를 받은 프레임워크는 gin, beego, echo 이다. 이 중 echo를 선택했다. 이유는 내가 사용하는 프레임워크이기 때문이다.

간단한 echo 서버를 만들어보자.
package main

import (
	"net/http"

	"github.com/labstack/echo"
)

func main() {
	e := echo.New()
	e.GET("/ping", Ping)

	e.Logger.Fatal(e.Start(":1234"))
}

func Ping(c echo.Context) error {
	return c.JSON(http.StatusOK, Response{101, "pong"})
}

type Response struct {
	Code    int    `json:"code"`
	Message string `json:"string"`
}

테스트
curl -i localhost:1234/ping
HTTP/1.1 200 OK
Content-Type: application/json; charset=UTF-8
Date: Wed, 21 Apr 2021 15:53:31 GMT
Content-Length: 29

{"code":101,"string":"pong"}

이제 미들웨어를 만들어보자. 나는 로깅 미들웨어를 만들 것이다. 요구 사항은 아래와 같다.
  1. 요청 헤더
  2. 요청 처리에 걸린 시간
  3. 데이터 분석을 위해서 요청과 응답 데이터를 저장한다. 나중에 이들 데이터는 필터링 해야 할 것인데, 지금은 전부 기록한다.
  4. 기타 등등
요청 처리에 걸린시간을 측정하기 위해서는 미들웨어가 핸들러를 감싸는 구조여야 할 것이다. 아래와 같이 미들웨어를 개발했다. 원리를 설명하는게 목적이라서 코드가 깔끔하지는 않다.
package main

import (
	"encoding/json"
	"fmt"
	"net/http"
	"time"

	"github.com/labstack/echo"
)

func myLogMiddleware(next echo.HandlerFunc) echo.HandlerFunc {
	return func(c echo.Context) error {
		var err error
		t1 := time.Now()
		if err = next(c); err != nil {
			return err
		}
		diff := time.Now().Sub(t1)
		req := c.Request()
		res := c.Response()
		clog, _ := json.Marshal(c.Get("clog"))
		fmt.Println(
			t1.Format(time.RFC3339),
			diff,                                     // Latency
			c.RealIP(),                               // Request host IP
			req.Method,                               // Request Method
			req.Host,                                 // Request Host
			req.Header.Get(echo.HeaderContentLength), // Request Data Size
			res.Size,                                 // Response Data Size
			string(clog),
		)
		return err
	}
}

func main() {
	e := echo.New()
	e.Use(myLogMiddleware)
	e.GET("/ping", Ping)

	e.Logger.Fatal(e.Start(":1234"))
}

func Ping(c echo.Context) error {
	time.Sleep(time.Millisecond * 20)
	c.Set("clog", LogFilter{"INFO", 101, "pong", "yundream@gmail.com"})
	return c.JSON(http.StatusOK, Response{101, "pong"})
}

type Response struct {
	Code    int    `json:"code"`
	Message string `json:"string"`
}

type LogFilter struct {
	Level   string `json:"level"`
	Code    int    `json:"code"`
	Message string `json:"message"`
	UserID  string `json:"UserID"`
}

미들웨어 부분을 보자.
func myLogMiddleware(next echo.HandlerFunc) echo.HandlerFunc {
	return func(c echo.Context) error {
		var err error
		t1 := time.Now()
		if err = next(c); err != nil {
			return err
		}
		diff := time.Now().Sub(t1)
		req := c.Request()
		res := c.Response()
		clog, _ := json.Marshal(c.Get("clog"))
		fmt.Println(
			t1.Format(time.RFC3339),
			diff,                                     // Latency
			c.RealIP(),                               // Request host IP
			req.Method,                               // Request Method
			req.Host,                                 // Request Host
			req.Header.Get(echo.HeaderContentLength), // Request Data Size
			res.Size,                                 // Response Data Size
			string(clog),
		)
		return err
	}
}
time 패키지를 이용해서 처리시간(Latency)을 측정했다. next(echo.HandlerFunc)가 실행되기전에 time.Now() 로 현재 시간을 기록하다. 실행이 끝난 후 time.Now().Sub() 로 걸린 시간을 계산했다. 기타 echo.Context의 값을 이용해서, 로그 시스템이 남겨야 할 정보들을 추출 했다.

여기까지는 간단하다. 다음 요구사항인 "요청/응답 데이터의 기록"은 좀 생각해야 할 부분들이 있다.

모든 요청/응답을 남기는 것은 효율이 떨어지기 때문에, 각 핸들러에 대해서 로그 필터를 남겨야 할 것이다. 예를 들어서 단순 목록을 조회하는 요청이라면 굳이 응답을 로그로 남길 필요가 없을 것이다.

func Ping(c echo.Context) error {
	time.Sleep(time.Millisecond * 20)
	c.Set("clog", LogFilter{"INFO", 101, "pong", "yundream@gmail.com"})
	return c.JSON(http.StatusOK, Response{101, "pong"})
}
가장 쉬운 방법은 echo.Context에 로깅할 값들을 넘겨주는 것이다. 작동하는데 문제는 없을 것이다. 서버를 실행 한 후 테스트를 했다.
⇨ http server started on [::]:1234
20.282934ms 127.0.0.1 GET localhost:1234  29 {"level":"INFO","code":101,"message":"pong","UserID":"yundream@gmail.com"}
Latency를 테스트 하기 위해서 ping 핸들러에 time.Sleep(time.Millisecond * 20)을 줬는데, 잘 측정된 것 같다.

개선

아래와 같이 미들웨어를 개선하기로 했다.
  1. 미들웨어에서 로그를 남긴다.
  2. 로그는 request, response 데이터를 포함하여 비즈니스 정보를 로깅하고 향후 분석 할 수 있게 한다.
이렇게 하기 위해서는 각 핸들러 별로 로그필터를 작성해야 한다. 나는 로그 필터를 만들기로 했다.

사용자 데이터를 리턴하는 핸들러를 개발해야 한다면, 개발자는 Go struct를 이용해서 아래와 같이 데이터 모델을 만들 것이다.
type Users struct {
	UserID  string `json:"userid"`
	Email   string `json:"email"`
	Age     int    `json:"age"`
	Name    string `json:"name"`
	Address string `json:"address"`
	GoodsID string `json:"goodsid"`
}
이 중 UserID, Email, Age, GoodsID를 로그에 남기고 싶다. 일일이 하드코딩 하는 방법도 있지만 좋은 방법은 아니다. Go struct Tag 기능을 이용해서, 데이터 모델에 통합하는 방식을 사용하기로 했다.
type Users struct {
	UserID  string `json:"userid" logging:"true"`
	Email   string `json:"email" logging:"true"`
	Age     int    `json:"age" logging:"true"`
	Name    string `json:"name"`
	Address string `json:"address"`
	GoodsID string `json:"goodsid" looging:"goodsid"`
}

개념은 간단하다. reflect를 이용해서 Users 구조체의 변수의 Tag를 검사한다. "logging"이 태깅되어 있으면 로그로 남기기 위한 작업을 한다. 역시 reflect로 변수이름과 값을 읽어서 map[string]interface{}로 만들어서 리턴한다. Filter 코드를 분석해보자.
func (l *Users) Filter() *map[string]interface{} {
	t := reflect.ValueOf(l)
	e := t.Elem()
	m := make(map[string]interface{})
	for i := 0; i < e.NumField(); i++ {
		mValue := e.Field(i)
		mType := e.Type().Field(i)
		if _, ok := mType.Tag.Lookup("logging"); ok {
			m[mType.Name] = mValue.Interface()
		}
	}
	return &m
}
reflect는 런타임에서 구조체, 변수, 함수를 임의로 조작 할 수 있도록 돕는다. ValueOf() 메서드를 이용해서 런타임 데이터의 정보를 나타내는 값인 "Value"가 반환된다. 이 메서드를 이용해서 Users 구조체의 정보를 추출 할 수 있다.

Value.Elem() 메서드는 Value 인터페이스에 포함된 값 또는 Value 포인터가 가리키는 값을 가져올 수 있다. 이제 e.NumField() 메서드를 이용해서 User 구조체의 모든 변수들을 순환하면서 logging 태깅 된 변수(mType.Tag.Lookup("logging"))를 확인해서 map[string]interface{} 를 구성한다.

이렇게 만들어진 데이터는 JSON으로 변환해서 사용 할 수 있을 것이다. 위 코드를 실행해보자.
# go run main.go
&map[Age:0 Email:yundream@gmail.com UserID:10001]

이제 로깅 미들웨어를 만들어보자.
package main

import (
	"encoding/json"
	"fmt"
	"net/http"
	"reflect"
	"time"

	"github.com/labstack/echo"
)

func myLogMiddleware(next echo.HandlerFunc) echo.HandlerFunc {
	return func(c echo.Context) error {
		var err error
		var clog []byte
		t1 := time.Now()
		if err = next(c); err != nil {
			return err
		}
		diff := time.Now().Sub(t1)
		req := c.Request()
		res := c.Response()
		data := c.Get("filter")
		if data != nil {

			t := reflect.ValueOf(data)
			e := t.Elem()
			m := make(map[string]interface{})
			for i := 0; i < e.NumField(); i++ {
				mValue := e.Field(i)
				mType := e.Type().Field(i)
				if _, ok := mType.Tag.Lookup("logging"); ok {
					m[mType.Name] = mValue.Interface()
				}
			}
			clog, _ = json.Marshal(m)
		}
		fmt.Println(
			t1.Format(time.RFC3339),
			diff,                                     // Latency
			c.RealIP(),                               // Request host IP
			req.Method,                               // Request Method
			req.Host,                                 // Request Host
			req.Header.Get(echo.HeaderContentLength), // Request Data Size
			res.Size,                                 // Response Data Size
			string(clog),
		)
		return err
	}
}

func main() {
	e := echo.New()
	e.Use(myLogMiddleware)
	e.GET("/ping", Ping)

	e.Logger.Fatal(e.Start(":1234"))
}

func Ping(c echo.Context) error {
	time.Sleep(time.Millisecond * 20)
	u := Users{
		UserID:  "10a293d",
		Email:   "yundream@gmail.com",
		Age:     38,
		Name:    "yundream",
		Address: "seoul",
		GoodsID: "3849-14281",
	}
	u.Filter(c)
	return c.JSON(http.StatusOK, Response{101, "pong", u})
}

type Response struct {
	Code    int         `json:"code"`
	Message string      `json:"string"`
	User    interface{} `json:"user"`
}

type Users struct {
	UserID  string `json:"userid" logging:"true"`
	Email   string `json:"email" logging:"true"`
	Age     int    `json:"age" logging:"true"`
	Name    string `json:"name"`
	Address string `json:"address"`
	GoodsID string `json:"goodsid" looging:"goodsid"`
}

func (u *Users) Filter(c echo.Context) {
	c.Set("filter", u)
}
CURL로 요청을 보냈다.
# curl localhost:1234/ping
{"code":101,"string":"pong","user":{"userid":"10a293d","email":"yundream@gmail.com","age":38,"name":"yundream","address":"seoul","goodsid":"3849-14281"}}

서버측 로그다.
⇨ http server started on [::]:1234
2021-04-23T12:37:34+09:00 20.588978ms 127.0.0.1 GET localhost:1234  154 {"Age":38,"Email":"yundream@gmail.com","UserID":"10a293d"}
이제 미들웨어를 좀 예쁘게 수정하면, 로그 필터링이 작동하는 미들웨어를 만들 수 있을 것이다.