문제 배경:
9월 1일 17:12경, 구축 담당자로부터 일부 장비가 정상적으로 업그레이드되지 않고 콘솔에서 내려보낸 명령을 받지 못하는 등의 문제가 있다는 불만을 접수했다. 동료가 control 프로젝트(이하 control)의 로그를 확인한 결과, control이 장비에서 보고한 섀도 정보를 받지 못해 명령을 내려보내지 않은 것으로 드러났다. control 프로젝트는 장비와 직접 연동하며, 장비가 보고한 정보에 따라 업그레이드, 로그 보고 등을 포함한 명령과 설정 정보를 장비에 내려보낸다. IoT 도입 전에는 control이 하트비트 보고에 의존하여 장비의 현재 정보를 가져왔고, IoT 도입 후에는 장비 섀도 정보에 의존한다
기기의 현재 정보를 가져옵니다. control은 기기의 섀도 정보를 구독하지만, 섀도 정보는 섀도 서비스(약칭 IoT)가 전달하며, 기기가 보고하는 섀도 정보를 직접 수신하지는 않습니다. 구체적인 전달 과정은 아래 두 그림을 참고하세요:
애플리케이션(control)이 장치 상태를 가져온다

애플리케이션(control)이 기기에 명령을 전송한다

control이 섀도 메시지를 받지 못한다는 사실을 알고 바로 rabbitmq 콘솔에서 메시지가 있는지 확인했습니다. 확인할 사항은 두 가지였습니다:1.장치가 메시지를 보고했는지 2.rabbitmq가 정상인지, 아래 그림 1、그림 2은 당시 캡처한 rabbitmq 콘솔 이미지 두 장이며, 다음에서그림1장치가 메시지를 보고하고 있다는 점은 분명히 확인할 수 있지만, 많은 메시지가 unacked(이미 소비자에게 전달되었지만 소비자가 아직 ack를 보내지 않았다는 뜻입니다. 이론적으로는 잠시 기다리면 정상적으로)의 것이며,구체적으로 어느 큐에 unacked 메시지가 쌓여 있는지는 다음을 참조하세요그림 2,“spacebridgeiot-shadow”는 바로 장치가 보고하는 섀도 정보를 수신하는 데 쓰는 것으로, 메시지가 모두 큐에 쌓였으니 control로 전달되지 않은 것도 이해할 만했다. 한동안 관찰하니 unacked 수가 0이 되었지만, total의 총수는 크게 달라지지 않았다. 마치 unacked 메시지가 다시 메시지 큐로 돌아가 전달을 기다리는 것처럼 보였다. 역시 몇 분 뒤 다시 대량의 unacked 메시지가 나타났고, 또 몇 분이 지나자 이 unacked 메시지들이 다시 큐로 돌아갔다. control 쪽은 여전히 메시지를 받지 못했다. 이때 IoT 쪽 로그를 확인해 보니 뜻밖에도 섀도 메시지가 들어오지 않고 있었다. rabbitmq 콘솔에서 “spacebridgeiot-shadow”이 큐에는 놀랍게도 소비자가 없어졌다,예를 들면그림3와 같다. 이때 rabbitmq의 로그를 확인하니 실제로 오류 정보가 있었으며, 예를 들면그림4에 보이듯이, rabbitmq가 능동적으로 연결을 종료했습니다.
그림 1:rabbitmq 개요도

그림 2:rabbitmq 큐 통계 그래프

그림 3:spacebridgeiot-shadow 개요

그림 4:rabbitmq 오류 메시지

임시 해결책:
당시 이미 많은 불만이 접수된 상태여서, “쌓인 메시지를 삭제하는” 다소 과격한 해결책을 택했다. 삭제하자 과연 정상으로 돌아왔다(비고:운영 환경의 문제는 최대한 빨리 해결해야 한다. 로그를 분석하고 차근차근 해결할 시간적 여유가 없으므로, 반드시 신속해야 한다)。

비운영 환경에서 문제 재현하기:
1.10.200.41.166 환경의 rabbitmq 큐 “mirrorTestQueue”에 대량의 메시지(최소 수만 건 규모)를 쌓는다
2.mirrorTestQueue의 소비자를 중지하고, 메시지가 충분히 쌓인 뒤 다시 시작한다
3.메시지 적체가 완료되면,소비자를 다시 시작합니다
예상대로 몇 초 만에 수천 개의 메시지가 소비자에게 전달되었고, 몇 분간 지속된 뒤 rabbitmq가 소비자와의 연결을 능동적으로 종료했다. 이때 콘솔에서는 해당 큐의 소비자가 보이지 않았다. 소비자에 자동 복구를 설정했으므로 잠시 후 다시 자동으로 연결되며,
하지만 곧 다시 연결이 끊겼고, 우리가 운영 환경에서 겪은 문제와 거의 같았다. 도대체 무엇이 이 문제를 일으킨 것일까? 솔직히 당시에는 별다른 실마리가 없었고, 인터넷을 한 바퀴 뒤져 봐도 딱히 만족스러운 답을 찾지 못했다(당시에는 문제의 본질을 파악하지 못했고, 검색 키워드도 너무 포괄적이었다),이후
우리는 TCP 계층에 문제가 생긴 것일 수 있다고 추측하여, 패킷을 캡처해서 단서를 찾을 수 있는지 보기로 했다. 역시 운 좋게 단서를 찾았다. 긴말할 것 없이 바로 그림을 보자.


13:06:25.643428 이전까지 rabbitmq는 계속 소비자에게 메시지를 푸시하고 있었습니다. 그러다 13:06:25.643428 시점부터 소비자의 tcp 윈도가 가득 차기 시작했고, 약 30초 동안 지속된 뒤 rabbitmq가 능동적으로 연결을 끊었습니다(rst 패킷을 보냈습니다). 이후 소비자가 다시 연결했지만 윈도는 또다시 가득 찼고, 다시 약 30초 동안 지속된 뒤 연결이 끊겼습니다.


꽤 규칙적인 것 같다. 매번 30s 동안 지속되는 것으로 보아 설정 가능한 매개변수인 듯하다. 대략 정리하면 “tcp full window로 인해 서버가 능동적으로 rst를 보내 연결을 끊으며, 이 현상에는 규칙성도 있다”는 것이다
이번에는 검색어를 바꿔서 찾아냈다 답,rabbitmq에는 다음과 같은 매개변수가 있다 tcp_listen_options.send_timeout 는 쓰기 타임아웃을 제어하는 매개변수로, 쓰기 타임아웃이 발생하면 TCP의 RST(https://github.com/rabbitmq/rabbitmq-java-client/issues/341),수정해서 효과가 어떤지 살펴보자:
1. 쓰기 제한 시간을 10s로 변경
tcp_listen_options.send_timeout = 10000
2.패킷을 캡처하여 작동하는지 확인합니다


윈도우가 가득 찬 시점부터 연결이 닫힐 때까지 약 10s가 걸렸다.
현상 되짚어 보기:
rabbitmq 소비자 측에 prefetch를 설정하지 않아 rabbitmq가 한 번에 너무 많은 메시지를 전달했고, 그 결과 소비자의 tcp 윈도가 가득 차면서 rabbitmq의 tcp_listen_options.send_timeout이 발생했습니다. 이 쓰기 타임아웃이 임계값에 도달하면 rabbitmq가 소비자와의 tcp 연결을 끊습니다.
최종 해결책:
앞서 메시지를 삭제한 것은 어쩔 수 없는 방안이었다. 문제는 해결했지만 너무 과격했으니, 이를 다룰 깔끔한 방안을 찾아야 한다. 소비자에게 푸시하는 메시지가 너무 많아 TCP 윈도가 꽉 찬 것이므로, 수신 속도를 조절하면 된다. rabbitmq에 연결할 때 너무 많이 보내지 말라고 알려 주면 되는 것이다.(뒤에 나오는 이 글은 다음에서 발췌했다https://blog.csdn.net/james_searcher/article/details/70308565)rabbitmq에는 prefetch라는 속성이 있으며, prefetch는 단일 소비자가 소비할 수 있는 미확인 메시지(unacked messages)의 최대 개수를 뜻합니다. 어떻게 이해하면 될까요?mq는 각 consumer에 버퍼를 설정하며, 그 크기가 바로 prefetch입니다. 메시지를 하나 받을 때마다 MQ는 메시지를 버퍼에 넣은 다음 클라이언트로 전달합니다. ack 메시지를 받으면(consumer가 baseack 명령을 보냄), mq는 버퍼에서 한 자리를 비운 뒤 새 메시지를 추가합니다. 하지만 이때 버퍼가 가득 차 있으면 MQ는 차단 상태에 들어갑니다. 더 구체적으로 설명하면, prefetch 값을 10으로 설정하고 consumer가 두 개 있다고 가정해 보겠습니다. 즉 각 consumer는 매번 queue에서 메시지 10개를 미리 가져와 로컬에 캐시하고 소비를 기다립니다. 동시에 해당 channel의 unacked 수는 20이 됩니다. Rabbit의 전달 순서는 먼저 consumer1에 message 10개를 모두 전달한 다음, consumer2에 message 10개를 전달하는 방식입니다. 이때 새 message를 전달해야 한다면, 먼저 channel의 unacked 수가 20인지 확인합니다. 그렇다면 메시지를 consumer에 전달하지 않고, message는 계속 queue에 머뭅니다. 이후 어느 한 consumer가 메시지 하나에 ack를 보내면 unacked는 19가 됩니다. 그러면 Rabbit은 어느 consumer의 unacked가 10보다 적은지 확인하여 해당 consumer에 전달합니다.
코드로 구체적으로 표현하면

이 값을 어떻게 산정해야 할까? rabbitmq 공식 문서에 잘 설명된 글이 있으니 자세히 다루지는 않겠다. 우리 시스템에서는 현재 20으로 설정해 두었다.
https://www.rabbitmq.com/blog/2012/05/11/some-queuing-theory-throughput-latency-and-bandwidth/
맺음말:
우리는 아직 rabbitmq 사용의 초보 단계에 있으므로, 사용하기 전에 반드시 rabbitmq의 API를 충분히 살펴보고 자주 쓰는 API의 사용법을 익히며, 로컬 환경에서 실험을 많이 해 보아야 한다.