서버에서 discobot 인증서 생성이 매우 느립니다

지원
1

새로운 멤버들에게 discobot 튜토리얼을 완료하도록 독려해 왔는데, 상당수가 이전(스테이징) Discourse 인스턴스에서 이미 경험했던 문제를 겪고 있습니다. 바로 마지막 게시글의 인증서가 생성되고 실제로 표시되기까지 긴 시간이 소요되며, 로딩 또는 생성 중이라는 어떠한 표시도 없다는 점입니다. 여기서 긴 시간이란 10~20초를 의미하며, 이는 누군가 포기하기에 충분한 시간입니다. meta에서 테스트해 보니 여기서는 즉각적으로 표시됩니다.

인증서는 /discobot/certificate.svg?date=Oct+28+2020&user_id=123 URL을 사용하여 온디맨드(on-demand)로 생성될 수 있음을 발견했고, 이에 몇 가지 테스트를 수행했습니다. 처음에는 즉각적으로 생성되었습니다. 그러나 최근에 튜토리얼을 완료하지 않은 사용자 ID를 사용하자마자 10~20초의 대기 시간이 발생했습니다(처음 생성된 후에는 빠르므로 어딘가에 캐시가 있는 것으로 추정됩니다). 또한 대기 기간 동안 몇 가지 500 에러가 발생했는데, 이는 다음 새로고침 시 정상 작동했으므로某种 종류의 타임아웃으로 추정됩니다.

/logs에서 관련이 있는지 알 수 없는 경고 메시지를 확인했습니다:

Failed to process hijacked response correctly : Net::ReadTimeout

traceback 
/usr/local/lib/ruby/2.6.0/net/protocol.rb:217:in `rbuf_fill'

/usr/local/lib/ruby/2.6.0/net/protocol.rb:191:in `readuntil'

/usr/local/lib/ruby/2.6.0/net/protocol.rb:201:in `readline'

/usr/local/lib/ruby/2.6.0/net/http/response.rb:40:in `read_status_line'

/usr/local/lib/ruby/2.6.0/net/http/response.rb:29:in `read_new'

/usr/local/lib/ruby/2.6.0/net/http.rb:1509:in `block in transport_request'

/usr/local/lib/ruby/2.6.0/net/http.rb:1506:in `catch'

/usr/local/lib/ruby/2.6.0/net/http.rb:1506:in `transport_request'

/usr/local/lib/ruby/2.6.0/net/http.rb:1479:in `request'

rack-mini-profiler-2.0.2/lib/patches/net_patches.rb:9:in `block in request_with_mini_profiler'

rack-mini-profiler-2.0.2/lib/mini_profiler/profiling_methods.rb:39:in `step'

rack-mini-profiler-2.0.2/lib/patches/net_patches.rb:8:in `request_with_mini_profiler'

/var/www/discourse/lib/final_destination.rb:370:in `block in safe_get'

/var/www/discourse/lib/final_destination.rb:414:in `block in safe_session'

/usr/local/lib/ruby/2.6.0/net/http.rb:920:in `start'

/usr/local/lib/ruby/2.6.0/net/http.rb:605:in `start'

/var/www/discourse/lib/final_destination.rb:411:in `safe_session'

/var/www/discourse/lib/final_destination.rb:362:in `safe_get'

/var/www/discourse/lib/final_destination.rb:131:in `get'

/var/www/discourse/lib/final_destination.rb:152:in `get'

/var/www/discourse/lib/file_helper.rb:55:in `download'

/var/www/discourse/plugins/discourse-narrative-bot/plugin.rb:113:in `fetch_avatar'

/var/www/discourse/plugins/discourse-narrative-bot/plugin.rb:98:in `block in generate'

/var/www/discourse/lib/hijack.rb:56:in `instance_eval'

/var/www/discourse/lib/hijack.rb:56:in `block in hijack'

/var/www/discourse/lib/scheduler/defer.rb:94:in `block in do_work'

rails_multisite-2.3.0/lib/rails_multisite/connection_management.rb:68:in `with_connection'

/var/www/discourse/lib/scheduler/defer.rb:89:in `do_work'

/var/www/discourse/lib/scheduler/defer.rb:79:in `block (2 levels) in start_thread'

인증서는 외부 네트워크 요청 없이 로컬에서 생성되는 것으로 이해하고 있습니다.

서버는 t3a.medium(메모리 4GB)이며 포럼은 특별히 바쁘지 않습니다(로드 평균 약 0.4, 여전히 충분한 여유 메모리 존재). 인증서 생성을 기다리는 동안 CPU 사용률이 전혀 변하지 않았으므로, 이것이 병목 현상의 원인으로 보이지 않습니다.

이 문제를 겪는 곳은 우리만 아닙니다(여기 참고, 이것이 관련 있는지는 확실하지 않음), 하지만 거기서 도움이 될 만한 내용을 찾지 못했습니다.

확신은 없는데, 인증서 URL을 몇 번 새로고침하면 결국 속도를 줄이라는 오류 메시지가 표시됩니다. 많은 사람이 동일한 URL 경로에서 인증서를 생성할 때 간섭을 일으킬 수 있는 URL 스로틀링(요청 제한) 메커니즘이 있는 걸까요? 아마 아닐 수도 있지만, 왜 이런 일이 발생하는지 막막합니다. 어떤 힌트든 환영합니다.

3

그 경로는 실제로 느립니다. 이미 알고 있듯이요.

더 빠르게 만드는 것을 시도하는 것 외에도, 메시지에 디스코봇이 무언가를 준비 중이며 약 1분 정도 걸릴 것이라는 내용을 추가하는 것은 어떨까요?

5

느리다는 사실을 알지 못했습니다. 다른 이유라도, 기다리는 시간이 길면 일부 사용자는 포기할 것 같습니다. 하지만 게시글에 해당 사실을 명확히 하는 업데이트를 하면 도움이 될 것 같긴 합니다.

기존의 SVG 파일(추측컨대)에 텍스트를 채우는 데 10초에서 20초가 걸린다는 것은 상당히 길어 보입니다. 제가 보기에는 CPU 부하가 병목인 것 같지는 않은데, 여기서는 무엇이 병목이 되는 것일까요?

6

여기서 카피를 수정해서 이전 단계에 "잠시만 기다려 주세요, 멋진 무언가를 생성 중입니다!"라는 문장을 포함하는 걸 고민하고 있었는데, try.discourse.org에서는 인증서 생성이 매우 빠르거든요:

image
image1540×881 107 KB

discobot 마지막 단계 타임스탬프: 11월 2일, 오후 6:46 1604371566089
discobot 인증서 생성 단계 타임스탬프: 11월 2일, 오후 6:46 1604371567470

기저 타임스탬프의 단위를 정확히 알지는 못하지만, 그 차이는 **1381**입니다.

같은 주제에서 최대한 빨리 답글을 달았는데, 이 타임스탬프들이 나왔습니다. 몇 초 차이도 안 나는데도 말이에요:

1604373488630
1604373492182

그 차이는 **3552**인데, 저는 정말 키보드 단축키를 이용해 붙여넣기하는 속도로 최대한 빨리 게시했습니다!

그러니까.. 서버가 그냥.. 느려터졌나요.. 아니면 뭔가 다른 이유가 있나요?

7

그가 말하는 것은 게시물이 아니라 인증서 이미지의 생성 과정이라고 생각합니다.

8

실제로 제가 이야기하고 있는 것은 인증서 생성 과정이지, 그것을 임베드하는 답글(이것은 빠릅니다)이 아닙니다. 이 문제가 우리 멤버 중 일부에게 미치는 영향은 다음과 같습니다:

image
image556×333 3.72 KB

아니요, t3a.medium는 중간급 인스턴스이며 부하도 높지 않습니다.

말씀드렸듯이, 예를 들어 /discobot/certificate.svg?date=Oct+28+2020&user_id=123 요청이 완료될 때까지 기다리는 동안 CPU 사용량이 평소보다 더 높지 않기 때문에(평소에도 매우 바쁘지 않음) CPU 병목인 것 같지는 않습니다.

이 문제는 네트워크 요청 타임아웃과 관련이 있는 것으로 보입니다:

인증서의 아바타는 data:image/png;base64 블롭인 것 같습니다. 제가 볼 때, 타임아웃이 발생하는 아바타 다운로드 시도가 있는 것 같습니다. 이것이 여기서 처리를 늦추는 원인이 아닐까요?

참고로, 이 포럼은 SSO를 사용 중이며 아바타는 S3에 저장된 https URL입니다. 도커 컨테이너 내에서 일부 아바타를 가져오는 것을 시도해 보았는데 작동하며 거의 즉시 완료됩니다 — 방화벽 문제 등은 없습니다. 인증서 생성 시에는 오랜 시간이 걸리지만, 포럼의 모든 다른 기능은 빠르게 작동합니다.

확인해야 할 사항에 대한 힌트를 주신다면 더 깊이 디버깅을 시도해 보겠습니다.

9

try.discourse.org에서 이미지는 거의 즉시 표시되었습니다. 만약 0.5초 이상의 지연이 있었다면 그 정도도 체감되지 않았을 겁니다. 믿기지 않으시면 직접 한번 시도해 보세요!

그래서 처음 말한 내용으로 돌아가겠습니다: 왜 여러분의 서버에서는 이렇게 느리면서 try.discourse.org에서는 이렇게 빠른가요?

11

정말 그렇군요… 제가 지원을 요청하는 이유가 바로 그 때문입니다.

이것이 '내 컴퓨터에서는 작동한다’는 전형적인 상황이라는 점은 이해합니다. Docker를 사용한다면 이런 상황이 발생해서는 안 되는데, 어쨌든 현재 이런 상태이고, 저만 이런 문제를 겪고 있는 것은 아닌 것 같습니다(유일한 사례가 아닙니다).

제 환경에서 이를 디버깅하는 방법에 대한 조언이 있다면 감사하겠습니다.

12

이 문제를 조사해 본 결과, discourse-narrative-bot이 인증서에 포함할 사용자의 아바타를 가져오는 과정에서 블로킹이 발생하는 것 같습니다. 관련 코드는 여기 있습니다:

이 포럼은 SSO를 사용하며 아바타는 Amazon S3 URL을 사용합니다. Amazon의 S3는 빠르고 속도 제한이 없습니다. 그러나 해당 함수는 다음과 같은 형태의 아바타 URL을 가져오고 있습니다:

https://forum.tld/user_avatar/forum.tld/username/240/18705_2.png

인증서 생성을 늦추고 있는 타임아웃 오류는 Discourse의 속도 제한과 관련이 있을까요? Discourse 인스턴스 _자체_에서 아바타를 너무 빠르게 요청하거나, 여러 사용자가 봇 튜토리얼을 수행하는 동안 Amazon S3에 너무 빠르게 접근하려고 해서 그런 것일까요?

13

흥미롭네요. 여기 base64 이미지를 인라인으로 넣고 있네요. image svg 태그에서 외부 리소스에 링크를 걸지 않은 이유가 궁금하네요 :thinking:

이 플러그인의 히스토리를 처음 이 기능이 추가된 곳까지 파고들어 봤는데:

아무래도 처음부터 base64 인라인 아바타를 사용해 온 것 같습니다.

수정: 조사해 보니 인증서가 img HTML 태그를 통해 로드되기 때문에 base64로 인라인 처리하고 있었습니다. 더 가벼운 아바타를 사용하려면 CSP에서 기본적으로 차단되어 있는 object 태그로 전환하거나, SVG 전체를 게시글 콘텐츠에 인라인으로 넣어야 합니다. 아마 iframe이 최선의 방법이 될 것 같습니다.

@tgxworld의 코멘트를 위해 FIX: Make discobot certificate gen faster/non blocking - Pull Request #11344 - discourse/discourse - GitHub 를 준비해 두었습니다.

14

base64 인코딩된 아바타를 SVG에 임베드한 것이 로고를 “그렇게 처리한” 이유와 동일한 목적, 즉 인증서가 특정 시점의 스냅샷 역할을 하도록 하기 위함이라고 가정했습니다. 수상자가 외부 의존성 없이 인증서를 저장해 두면 나중에에도 동일한 방식으로 렌더링되도록 하려는 것이죠.

iframe 방식은 게시물에서 인증서를 쉽게 공유하거나 자랑하기 어렵게 만듭니다. 다른 포럼에서는 얼마나 흔한지 모르겠지만, 우리 사용자 중 일부는 이미지의 URL을 그대로 복사해서 공유하는 것을 본 적이 있습니다.

외부 리소스에 링크를 사용하는 방향으로 간다면, <image> 태그를 사용하면 여기서 작동하고 allowed_iframes를 변경할 필요가 없게 되지 않을까요?

15

위 PR을 읽어보시면 그것이 바로 해당 PR이 하는 일입니다 :grimacing:

하지만 우리가 현재처럼 HTML img 태그로 SVG를 로드하는 경우, SVG 내부의 image 태그에 포함된 외부 이미지는 로드되지 않습니다. 이를 동작시키려면 반드시 object 또는 iframe을 사용해서 로드해야 합니다.

16

분명히 내가 SVG에 대해 충분히 모르는 것 같습니다. iframe 방식은 인증서에 서명/복사가 되는 것을 방지하지만, 어쨌든 이 문제가 어떻게든 해결되고 있다는 점은 다행입니다. 이렇게 하면 우리의 문제와 인증서 위의 누락된 로고 문제도 함께 해결될 테니까요. :+1:

17

@mentalstring 새로운 인증서 생성 코드를 병합했습니다. 이제 훨씬 더 빠를 거예요.

18

이 PR이 병합되는 걸 보니 기쁩니다. :+1:

저희는 stable 버전을 사용 중이며, 현재 이 기능을 테스트할 좋은 방법이 없습니다. 하지만 fetch_avatar가 더 이상 사용되지 않는다면, 이 변경 사항으로 인해 저희의 Net::ReadTimeout 오류가 사라질 것으로 기대합니다. 이 이슈를 해결로 표시하고, 업데이트 후 같은 문제가 다시 발생하면 다시 열겠습니다. 감사합니다!