• yundream
  • 2017-06-24 16:16:16
  • 2017-06-21 13:05:24
  • 179814

Contents

웹 애플리케이션 서버에서의 로그 처리

웹 애플리케이션 서버는 웹 엑세스로그와 애플리케이션 로그다. 웹 엑세스 로그는 NginX와 Apache 웹 서버가 남기는 HTTP 접근 로그다. 이 로그는 접근 URL, 메서드(GET, POST, PUT, DELETE), HTTP Status Code, 접근 시간, 클라이언트 애플리케이션 정보등을 포함한다. Combined 로그 형식을 널리 사용한다.
127.0.0.1 - frank [10/Oct/2000:13:55:36 -0700] "GET /apache_pb.gif HTTP/1.0" 200 2326 "http://www.example.com/start.html" "Mozilla/4.08 [en] (Win98; I ;Nav)"

Gorilla 웹 툴킷에서의 Combined 로깅

Gorilla 웹 툴킷에서 제공하는 로깅핸들러 메서드를 이용했다.
package main

import (
    "fmt"
    "github.com/gorilla/handlers"
    "github.com/gorilla/mux"
    "net/http"
    "os"
    "strconv"
)

func hello(w http.ResponseWriter, r *http.Request) {
    fmt.Fprintf(w, "Hello world")
}

func main() {
    h := mux.NewRouter()
    h.HandleFunc("/hello", hello).Methods("GET")
    logFile, _ := os.OpenFile("/tmp/access.log", os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0644)
    http.Handle("/", handlers.CombinedLoggingHandler(logFile, h))
    http.ListenAndServe(":3000", nil)
}
curl로 테스트를 했다.
127.0.0.1 - - [21/Jun/2017:23:12:50 +0900] "GET /hello HTTP/1.1" 200 11 "" "curl/7.52.1"
127.0.0.1 - - [21/Jun/2017:23:13:06 +0900] "GET /mypage HTTP/1.1" 404 19 "" "curl/7.52.1"

Logrus

Combined 로깅은 HTTP 레벨의 로깅이다. HTTP Status code를 표현하는 것에 촛점이 맞춰져 있기 때문에, 문제가 발생 했을 때, 원인을 찾기가 쉽지 않다. 예컨데, 500 Internal server error나 발생했면, 뭔가 시스템상에서 중요한 에러가 발생한 것 같긴 하지만 어떤 에러인지(데이터베이스 문제인지, 파일 시스템 혹은 메모리 문제인지, 그냥 잘못된 코드인건지)를 확인 할 수 없다.

결국 애플리케이션 상태를 정확히 추적하기 위해서는 애플리케이션 레벨 로그를 남겨야 한다. Logrus 패키지를 이용해서 웹 애플리케이션에서 애플리케이션 레벨 로그를 남기는방법을 살펴보려 한다.

package main

import (
    log "github.com/sirupsen/logrus"
)

func main() {
    log.WithFields(log.Fields{
        "userId": "yundream",
    }).Error("User not found")
}
Error 레벨의 로그를 만들었다. 로그 정보로 userID 필드에 yundream 정보를 설정했다. 실행 결과는 아래와 같다.
ERRO[0000] User not found                                userId=yundream
간단한 로그지만 userId가 yundream인 유저를 찾지 못했다는 것을 알 수 있다.

로그를 JSON 형태로 만들어서 파일로 저장해 보자.
package main

import (
    log "github.com/sirupsen/logrus"
    "os"
)

func main() {
    log.SetFormatter(&log.JSONFormatter{})
    f, _ := os.OpenFile("/tmp/app.log", os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0644)
    log.SetOutput(f)
    log.WithFields(log.Fields{
        "userId": "yundream",
        "email":  "yundream@gmail.com",
    }).Info("User found")
}
아래와 같이 JSON 형태로 로그가 남는다.
{"email":"yundream@gmail.com","level":"info","msg":"User found","time":"2017-06-22T00:13:49+09:00","userId":"yundream"}

웹 애플리케이션에서 로그 남기기

웹 애플리케이션을 개발하려고 하면, HTTP 요청을 실행하기 위해서 공유해야 하는 많은 기능과 데이터들이 생기기 마련이다. 예컨데, 유저 세션을 확인하거나 세션에서 얻은 정보를 핸들러(요청 처리기)로 넘기고 인증을 하고 캐시 하는 등의 일들이다.

이러한 기능을 각 핸들러에서 처리하는 것은 매우 비효율적이다(동일한 코드가 많은 핸들러에서 중복된다고 생각해 보라). 그 보다는 핸들러를 호출하기 전에, 공통되는 기능을 먼저 수행하는게 효율적일 것이다. 핸들러 호출전에 독립적으로 작동하는 이런 코드를 미들웨어라고 한다. 로그는 모든 모든 핸들러에서 공통으로 사용하는 기능이다. 따라서 미들웨어에서 처리하면 효율적일 것이다.

REDIS를 이용해서 세션을 관리하는 웹 애플리케이션이 있다고 가정해보자. REDIS에는 SessionID와 UserID, Email, LoginTime 과 같은 정보를 저장하고 있다.

세션을 필요로 하는 각 핸들러에서 REDIS 값을 GET 할 수도 있지만 좋은 방법은 아니다. 미들웨어에서 일괄 처리하고, 처리한 값은 context로 넘길 수 있을 것이다. 이제 핸들러에서는 context 값을 이용해서 로깅을 할 수 있을 것이다.

package main

import (
    "context"
    "fmt"
    "github.com/fatih/structs"
    "github.com/gorilla/handlers"
    "github.com/gorilla/mux"
    log "github.com/sirupsen/logrus"
    "net/http"
    "os"
    "time"
)

type Handler struct {
    Router *mux.Router
}

func New() *Handler {
    h := &Handler{
        Router: mux.NewRouter(),
    }
    h.Router.HandleFunc("/hello", h.hello).Methods("GET")
    logFile, _ := os.OpenFile("/tmp/access.log", os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0644)
    http.Handle("/", handlers.CombinedLoggingHandler(logFile, h.MiddleWare(h.Router)))
    return h
}
func (h Handler) hello(w http.ResponseWriter, r *http.Request) {
    ctx := r.Context().Value("ctx")
    session := ctx.(Session)
    // 구조체를 맵으로 바꾼다.
    log.WithFields(structs.Map(session)).Info("Request hello")
    fmt.Fprintf(w, "Hello world ")
}

type Session struct {
    Sessionid   string
    IsLogin     bool
    UserID      string
    CreatedDate int64
}

func (h Handler) MiddleWare(next http.Handler) http.Handler {
    f, _ := os.OpenFile("/tmp/app.log", os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0644)
    log.SetOutput(f)
    Logger := log.New()
    Logger.Info("MiddleWare setting")
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        // 여기에서 REDIS 데이터를 읽는다. 읽었다고 치자.
        // Session 구조체를 설정 한 다음, context에 저장한다.
        s := Session{"123anbd1d", true, "yundream", time.Now().Unix()}
        ctx := context.WithValue(r.Context(), "ctx", s)
        next.ServeHTTP(w, r.WithContext(ctx))
    })
}

func main() {
    New()
    http.ListenAndServe(":3000", nil)
}
아래와 같이 로그를 확인 할 수 있다.
$ tail -f /tmp/app.log 
time="2017-06-24T23:58:36+09:00" level=info msg="Request hello" CreatedDate=1498316316 IsLogin=true Sessionid=123anbd1d UserID=yundream