미들웨어 개발중 발생한 버그 해결 과정
29 September 2021
미들웨어 개발중 발생한 버그 해결 과정
개발을 하다보면 언제나 버그가 발생하기 마련입니다.
저희는 웹 Portal 로 부터 요청을 받아서 처리하는 API Gateway 를 구동하던중, 어느 순간부터 socket: too many open files 라는 에러가 발생하면서 데이터베이스의 요청도 제대로 수행되지 않고 API Gateway 가 동작 불능 상태에 빠지게 되는 현상이 발생하였습니다.
이 문제를 해결 하기 위해 문제 상황을 인지하고 문제의 원인을 찾아 해결하는 과정까지 설명하도록 하겠습니다.
먼저 too many open files 라는 에러가 어느때 발생하는지를 알아 보았습니다.
확인을 해보니 특정 모듈과의 통신이 몇번 이루어 지고 난 후와 장시간 Piccolo 를 구동할경우, MySQL 의 socket 을 Open 하는 과정에서 위 에러가 발생하는 것을 확인하였습니다.
Linux 에는 rLimit 이라고 하여 프로세스당 최대로 열 수 있는 파일의 최대 개수를 지정할 수 있습니다.
데이터베이스에 접근할때 socket: too many open files 라는 에러가 발생하였기 때문에 MySQL 의 파일 Open 개수 제한 관련 설정을 변경해 봅니다.
/etc/my.cnf 파일의 [mysqld] 에서 open_files_limit 항목의 값을 수정하여 지정할 수 있습니다.
[mysqld]
... 생략
open_files_limit=65535
... 생략
다음으로 Linux 머신 자체의 파일 Open 개수 제한을 늘려 주기 위해서 OS 의 설정 값을 변경해 줍니다.
해당 부분은 /etc/security/limits.conf 라는 설정 파일에서 설정 할 수 있습니다.
아래와 같이 추가하여 mysql 에서 설정한 값과 같은 값이 되도록 해주었습니다.
* - nofile 65535
적용을 완료한 후 API Gateway 의 동작을 지켜봅니다.
lsof 명령어를 사용하여 IPv4 로 Open 된 socket 들의 개수를 확인해 봅니다.
$ lsof -i 4 | grep api_gateway | wc -l
4081
4081 개로 상당히 많은 수의 socket 이 Open 되어있음을 확인 할 수 있습니다.
또한, 시간이 지남에 따라 값이 점점 증가함을 확인하였습니다.
따라서 임시 방편으로 API Gateway 가 동작하도록 할 수는 있지만 근본적인 원인 해결이 아니라는 것을 알 수 있습니다.
따라서 어느 시점에 socket Open 개수가 기하 급수적으로 증가하는지 확인해 봅니다.
확인해본 결과 저희가 웹 Portal 로 부터 GraphQL 로 요청을 하는 과정중 Subscription 으로 요청을 할 경우 기하 급수적으로 늘어남을 확인 하였습니다.
더 자세히 확인해본 결과 Subscription 과정중에 gRPC 로 연결을 요청 한후 연결이 종료되어도 socket 이 Close 되면서 사라지지 않고 Open 된 Socket 들이 엄청나게 쌓이는 것을 확인하였습니다.
socket Open 개수가 많아지면서 최대 파일 Open 개수에 다다르게 되어 API Gateway 가 비정상적으로 동작하고 MySQL 로 연결하는 socket 에도 문제가 발생함을 인지하였습니다.
문제가 발생하는 gRPC 관련 모듈을 종료하고 다시 IPv4 로 Open 된 socket 들의 개수를 확인해 봅니다.
$ lsof -i 4 | grep api_gateway | wc -l
3296
$ lsof -i 4 | grep api_gateway | wc -l
311
점점 줄어들더니 Open 된 socket 들의 개수가 확연하게 줄어든 것을 볼 수 있습니다.
관련된 부분의 소스를 확인해 봅니다.
// InitTuba : Initialize a gRPC connection to tuba module
func InitTuba(serverAddress string, serverPort int, conn *grpc.ClientConn) (pb.TubaClient, error) {
var err error
addr := serverAddress + ":" + strconv.Itoa(serverPort)
conn, err = grpc.Dial(addr, grpc.WithInsecure())
if err != nil {
return nil, err
}
tubaClient := pb.NewTubaClient(conn)
return tubaClient, nil
}
gRPC 연결 정보를 담을 conn 포인터 변수를 넘기면서 해당 변수에 연결 정보를 담이와서 InitTuba() 함수 밖에서 gRPC 연결을 종료하려고 하였습니다.
하지만 InitTuba() 함수가 끝나면 해당 변수의 값은 초기화가 된다는 사실을 인지하였습니다.
해당 부분을 다음과 같이 수정해 주었습니다.
// InitTuba : Initialize a gRPC connection to tuba module
func InitTuba(serverAddress string, serverPort int) (pb.TubaClient, *grpc.ClientConn, error) {
var err error
addr := serverAddress + ":" + strconv.Itoa(serverPort)
conn, err := grpc.Dial(addr, grpc.WithInsecure())
if err != nil {
return nil, nil, err
}
tubaClient := pb.NewTubaClient(conn)
return tubaClient, conn, nil
}
InitTuba() 함수가 끝날때 gRPC 연결 정보를 담을 conn 변수를 리턴해 주면 함수가 끝나도 함수를 사용하는 쪽에서는 연결 정보를 받아 올 수 있습니다.
수정후 InitTuba() 함수밖에서 gRPC 연결을 정상적으로 종료할 수 있었고 Open 된 파일 개수가 적정선에서 유지되는 것을 확인할 수 있었습니다.
$ lsof -i 4 | grep api_gateway | wc -l
35
여기까지 특정 모듈과 통신할때 too many open files 에러는 더이상 발생하지 않지만, 장시간 구동할 경우에 API Gateway 가 동작 불능 상태에 빠지게 되었습니다.
GraphQL 의 Subscription 동작을 다시 자세히 살펴보았습니다.
Subscription 으로 쿼리를 요청하게 되면 클라이언트는 API Gateway 에 Websocket 으로 연결하게 됩니다.
이때 클라이언트의 연결을 구분하는 Connection ID 와 클라이언트의 각 쿼리마다 부여되는 Operataion ID 로 각 Subscription 쿼리에 대한 동작을 구분합니다.
각 Operataion ID 가 Connection ID 에 종속되어 집니다.
Operataion ID 마다 Subscription 동작을 수행하는 쓰레드를 생성하여 돌아가다가 연결이 끊어질 경우 해당 함수를 빠져나와 더이상 동작하지 않도록 의도하도 개발을 하였습니다.
func graphqlCommonSubscription(conn graphqlws.Connection,
opID string,
data *graphqlws.StartMessagePayload) {
ctx := context.Background()
for true {
... 생략
if isOperationStopped(conn.ID(), opID) {
return
}
... 생략
}
}
클라이언트와의 연결이 성립된 상태에서 쿼리의 요청이 중단되면 isOperationStopped() 함수가 true 를 반환하며 Subscription 동작을 중단하도록 하였습니다.
하지만 여기서 문제가 발생합니다.
클라이언트와의 연결 자체가 끊어지면 Connection ID 정보는 사라지고 해당 Operataion ID 는 어떤 Connection ID 에 종속되어있는지 알 수가 없어 Subscription 동작이 멈추지 않고 계속 수행되는 상태에 빠지게 됩니다.
이상태가 계속된다면 API Gateway 에는 수많은 쓰레드가 생겨나면서 동작이 원활하게 되지 않을 수 있습니다.
클라이언트와의 연결이 중단되었는지 확인하는 코드를 추가해줍니다.
func graphqlCommonSubscription(conn graphqlws.Connection,
opID string,
data *graphqlws.StartMessagePayload) {
ctx := context.Background()
for true {
... 생략
// 추가된 부분
if isDisconnected(conn.ID()) {
return
}
if isOperationStopped(conn.ID(), opID) {
return
}
... 생략
}
}
위와 같이 수정하고 난후 클라이언트와의 연결이 종료되면 해당 Connection ID 에 종속되어 있던 모든 Operataion ID 로 생성된 쓰레드들이 정상적으로 종료되는 것을 확인 하였습니다.
언제나 개발을 하다보면 버그가 생기기 마련인데, 당황하지 않고 차근차근 문제의 원인을 파악하고 코드를 살펴보며 더욱더 훌륭한 인재로 거듭나시길 바랍니다!
긴글 읽어주셔서 감사합니다.