지난 두 달간 너무 빠빴다. 기존 레거시 cloud화 작업도 하면서, 다른 팀 레거시 문제점 분석까지 도와주면서 밤도 새고 잠도 제대로 못잤다.
이제 다시 오픈소스 좀 참여해보도록 하자...
문제 확인
standard log library로 만드신 logger가 file에만 데이터를 쓰고 있을 뿐, stdout에는 log가 출력되지 않아서, 일일히 pod에 들어가서 log file을 열어봐야 한다. 설마 의도한 건 아니겠지...
가령 REST API 요청을 보내보면 stdout에는 log가 나오는 것을 볼 수 있다.
[GIN] 2024/12/14 - 11:58:25 | 404 | 641ns | 116.121.222.205 | GET "/getModelInfo"
[GIN] 2024/12/14 - 11:58:25 | 200 | 2.66253ms | 116.121.222.205 | GET "/getModelInfo/qoe1"
[GIN] 2024/12/14 - 11:59:16 | 200 | 573.001µs | 116.121.222.205 | GET "/models"해당 log는 gin에서의 logger가 출력해주는 내용이지, custom logger가 출력해준 내용이 아니다. pod안에 들어가서 log file을 열어보자.
kubectl exec -it -n traininghost modelmgmtservice-7b8bf6c6b4-9q6zz -- cat ./mmes.log
INFO:2024/12/14 11:58:21 Connection string for DB host=tm-db-postgresql user=postgres password=9yR6Ptj3BN dbname=training_manager_database port=5432 sslmode=disable
INFO:2024/12/14 11:58:22 Creating single instance for S3Manager
INFO:2024/12/14 11:58:22 Starting api..
INFO:2024/12/14 11:58:25 Get model info by name API ...
ERROR:2024/12/14 11:58:25 Error, can't get fetch object..
INFO:2024/12/14 11:59:16 Get model info 정작 중요한 정보는 file에 감춰져 있다.
이 밖에도 log file rotation이 안되거나, 다양한 출력 log 형식 변경이 불가능, log level 기능 미지원 등이 있다.
logger를 개선하거나, 새로운 logging library를 추가하여 문제를 해결해보자.
해결 방법
첫 번째 방법은 standart library log를 가지고 만든 custom logger를 고쳐주는 방법이다.
import (
"log"
"os"
)
var infoLogger *log.Logger
var warnLogger *log.Logger
var errorLogger *log.Logger
func init() {
//TODO add current timestamp as file prefix to retain the old log file
logFile, fileErr := os.Create(os.Getenv("LOG_FILE_NAME"))
if fileErr != nil {
log.Fatal("Can not start MMES service,issue in creating log file")
}
flags := log.Ldate | log.Ltime
infoLogger = log.New(logFile, "INFO:", flags)
warnLogger = log.New(logFile, "WARN:", flags)
errorLogger = log.New(logFile, "ERROR:", flags)
INFO("Loggers loaded ..")
}예에전에 썻던 go logging 방법인 것 같다. 해결 방법은 생각보다 쉬운데, io.MultiWriter를 사용해서 log내용을 stdout에 출력해주도록 하는 것이다. io.writer 만세~
두 번째 방법은, custom logger를 버리고 slog, zap과 같은 logging library를 사용하는 방법이다. 필자의 경험으로 두 라이브러리를 비교하자면, 로그량이 적고 작은 app에 대해서는 slog를 사용하고, 로그량이 많고 큰 app에 대해서는 zap이 좋았다. 이는 zap 자체의 디자인이 다량의 log를 빠르게 쓰기 위해서 만들어졌기 때문이다.
modelmgmtservice는 로그 량이 적은 작은 app이므로 slog로 하도록 하자.
https://medium.com/@akhigbeeromo/using-the-slog-package-in-golang-e1f167a7c928
https://medium.com/@julianojj/exploring-the-advantages-of-slog-on-golang-an-overview-2cbee6fece07
https://blog.stackademic.com/all-you-need-to-know-about-logging-in-go-using-slog-281ed46f9b49
https://signoz.io/guides/golang-slog/#monitoring-logs-with-an-observability-tool
https://betterstack.com/community/guides/logging/logging-in-go/
https://www.gopherguides.com/articles/golang-slog-package
slog 정리 글이 아니므로, 아주 간단하게만 정리하자. 가장 기본적인 사용법은 default로 설정되어있는 slog 구현체를 사용하는 것이다.
func main() {
slog.Info("hello gophers")
slog.Warn("be warned!")
slog.Error("this is broken")
slog.Debug("show some debugging output")
}slog 구현체를 custom하고 싶다면, handler를 만들어서 io.Writer를 구현하고 있는 구조체에 대해 log를 쓰도록 하면 된다. 여기서 handler는 두 개로 정리할 수 있다.
JSONHandler: 출력을 json형식으로 해준다.TextHandler: 출력을 text형식으로 해준다. 이때key=value형식으로 출력 해줄 수 있다.
func main() {
logger := slog.New(slog.NewJSONHandler(os.Stdout, nil))
logger.Debug("Debug message")
logger.Info("Info message")
logger.Warn("Warning message")
logger.Error("Error message")
}option도 설정해줄 수 있다.
logHandlerOpt := slog.HandlerOptions{
Level: slog.LevelInfo,
AddSource: true,
}
stdoutLogHandler := slog.NewTextHandler(os.Stdout, &logHandlerOpt)log level을 설정해놓을 수 있고, AddSource를 설정하면 log를 호출하는 code가 어디인지 알려준다. source=/home/app/main.go:60 이렇게 나오는 것이다.
그런데, slog의 경우 log rotation 기능이 없다. 그래서 lumberjack을 사용하기로 했다.
fileRotationLogger := lumberjack.Logger{
Filename: filename,
MaxSize: 100, // 100MB
MaxBackups: 5,
MaxAge: 30,
Compress: true,
}file에 log를 쓰면 100MB가 될 때, 새로운 log 파일을 만드는 것이다. 백업 용으로 5개까지만 저장하며 최대 저장 기간은 30일이고, 압축을 실행한다는 것이다.
lumberjack으로 만든 logger의 가장 좋은 점은 io.Writer를 구현하였기 때문에 io.Writer가 있는 곳에 쓸 수 있다는 것이다. 따라서 slog의 handler에도 쓸 수 있다. 이 덕분에 file에 쓰는 log는 system이 분석하기 편한 json으로 만들고, stdout으로 쓰여지는 log는 stdout으로 쓰도록 handler를 따로 설정해줄 수 있다.
var (
Logger *slog.Logger
once sync.Once
)
func Load(logLevel string, filename string) {
once.Do(func() {
parsedLogLevel, err := parseLogLevel(logLevel)
fileRotationLogger := lumberjack.Logger{
Filename: filename,
MaxSize: 100, // 100MB
MaxBackups: 5,
MaxAge: 30,
Compress: true,
}
logHandlerOpt := slog.HandlerOptions{
Level: parsedLogLevel.convertLogLevelToSlogLogLevel(),
AddSource: true,
}
fileLogHandler := slog.NewJSONHandler(&fileRotationLogger, &logHandlerOpt)
stdoutLogHandler := slog.NewTextHandler(os.Stdout, &logHandlerOpt)
Logger = slog.New(slogmulti.Fanout(fileLogHandler, stdoutLogHandler)).With(slog.String("app", "mmes"))
if err != nil {
Logger.Error("error occurred: ", slog.Any("error", err))
}
})
}간단한 코드지만 json, text handler를 만들어서 각각 file, stdout에 하나의 log를 써주도록 할 수 있다. 또한, lumberjack 덕분에 log rotation 기능도 동작한다.
그런데, 한 가지 문제는 slog의 handler가 io.Writer를 구현하지 않았으므로 io.MultiWriter를 쓸 수가 없다. 따라서, file handler와 stdout handler를 하나의 slog.Logger로 만들기 위해서, 추가적인 모듈인 slogmulti가 필요하다.
slogmulti.Fanout으로 두 handler를 하나로 묶어서 하나의 handler로 묶어 준 다음, slog.Logger를 만들어준 것이다.
이제 만들어놓은 slog.Logger로 log를 만들어보도록 하자.
DSN := fmt.Sprintf(
"host=%s user=%s password=%s dbname=%s port=%s sslmode=disable ",
configManager.DB.PG_HOST,
configManager.DB.PG_USER,
configManager.DB.PG_PASSWORD,
configManager.DB.PG_DBNAME,
configManager.DB.PG_PORT,
)
logging.Logger.Info("Connection string for DB", slog.String("DSN", DSN))Logger.Info의 앞 부분은 string으로 msg를 적으면 되고, 뒷 부분은 하나의 추가 옵션인데, slog.String과 같은 방식으로 key=value를 넣을 수 있다. 결과는 아래에서 확인해보도록 하자.
결과
이제 log 결과를 확인해보도록 하자.
아래가 기존의 file log이다.
INFO:2024/12/14 12:41:40 Connection string for DB host=tm-db-postgresql user=postgres password=temporary dbname=training_manager_database port=5432 sslmode=disableslog를 도입한 결과이다.
{"time":"2024-12-14T15:57:38.122197173Z","level":"INFO","source":{"function":"main.main","file":"/home/app/main.go","line":60},"msg":"Connection string for DB","DSN":"host=tm-db-postgresql user=postgres password=temporary dbname=training_manager_database port=5432 sslmode=disable "}시스템이 파싱하기 딱 좋은 json 형식으로 데이터가 저장되는 것을 볼 수 있다.
추가적으로 기존에는 안나오던 stdout log 출력도 확인할 수 있다.
time=2024-12-14T15:57:38.122Z level=INFO source=/home/app/main.go:60 msg="Connection string for DB" DSN="host=tm-db-postgresql user=postgres password=temporary dbname=training_manager_database port=5432 sslmode=disable "읽기 편하게 key=value 형식의 text로 나오는 것을 알 수 있다.
slog를 도입한 덕분에 다음의 기대효과를 얻을 수 있다.
1. log 출력 format 변경(json, text)
2. file rotation 기능
3. stdout에 log 출력
4. log level에 따른 logging filter 기능
이제 리뷰를 받아보고, 고쳐야할 점들을 고쳐보도록 하자.
https://gerrit.o-ran-sc.org/r/c/aiml-fw/awmf/modelmgmtservice/+/13875
고려해야 할 점
그러나, 앞으로 고려해야할 부분들도 있다.
1. 어떻게 기존 로그들을 slog로 유연하게 바꿀 것인가?
2. 다른 개발자들이 볼 때 slog를 쉽게 사용할 수 있도록 어떻게 할 것인가?
3. logging 관련 interface를 만들어서 slog뿐만 아니라, 다른 logging library도 구현체만 전달하게 하는 방법이 더 좋지 않을까?
사실 언제나 3번이 가장 어려운 대목인 것 같다. go를 처음하시는 분들의 특징 중 하나는 뭐든 interface로 만들어서 다형성을 제공하려고 한다. 그러나, 생각보다 시니어 go개발자는 interface를 그렇게까지 많이 쓰진 않고, 오히려 구조체 그대로를 노출시킬 때가 많다.
왜냐면 모든 작업들을 interface로 만들어서 제공하다보면 interface가 너무 비대해지고, 사실상 특정 구조체가 아닌 이상 해당 interface를 구현할 구현체가 없을 수 있기 때문이다. 따라서 interface는 되도록 적은 메서드를 가지고도록 작아야한다. 그래서 나는 아래와 같은 database interface들을 별로 안좋아한다.
type DBMgr interface {
CreateBucket(bucketName string) (err error)
GetBucketObject(objectName string, bucketName string) BucketObject
DeleteBucket(client *s3.S3, objectName string, bucketName string)
DeleteBucketObject(client *s3.S3, objectName string, bucketName string) bool
UploadFile(dataBytes []byte, file_name string, bucketName string)
ListBucket(bucketObjPostfix string) ([]Bucket, error)
GetBucketItems(bucketName string)
}이렇게 점점 interface가 비대지고 복잡해지면 사실상, 특정 DB말고는 딱히 다른 DB가 해당 interface의 구현체로 쓸 수가 없다. 벌써 object storage인 것을 상정하고 만든 것이 보인다. 그렇다면 굳이 interface를 만들어서 복잡도를 높일 필요없이, object storage 구조체를 만들어 제공하면 된다. 물론, interface 덕분에 test는 좀 더 편하겠지만, mock을 사용하면 되므로 이것도 굳이 interface를 사용할 필요가 없다.
logger 역시도 마찬가지이다. logging library들이 제공하는 기능들이 전부 다르고, 다양한데, 이것을 하나의 interface로 제공하면, 분명 interface에 특정 logging library를 위한 method가 생기게 된다. 이러한 부분이 go code를 매우 안좋게 만드는 부분이다.
과연, logger를 interface화시켜서 다른 logging library도 사용할 수 있게 만드는 것이 의미가 있을까? 즉, interface를 통해 production, test 환경에서의 logging library를 바꾸어 쓰는 것이 의미가 있을까?
