Geração de certificado discobot muito lenta em nosso servidor

Suporte
1

Temos incentivado nossos novos membros a passar pelo tutorial do discobot, e vários deles estão enfrentando um problema que já havíamos experimentado em uma instância anterior do Discourse (ambiente de staging): o certificado no último post demora muito para ser gerado e aparecer de fato, sem nenhuma indicação de que está sendo carregado ou gerado. Por ‘muito tempo’, entendo um período de 10 a 20 segundos — o suficiente para alguém desistir.

Tentei no meta e parece ser instantâneo aqui.

Notei que o certificado pode ser gerado sob demanda usando a URL /discobot/certificate.svg?date=Oct+28+2020&user_id=123, então fiz alguns testes. No início, foi instantâneo. Mas assim que usei IDs de usuários que não fizeram o tutorial recentemente, precisei esperar o período de 10 a 20 segundos (é rápido assim que gerado pela primeira vez, então presumo que haja algum cache). Também obtive alguns erros 500 durante o período de espera, que presumo serem algum tipo de timeout, pois funcionou na próxima atualização.

Nos /logs, estou vendo um aviso que não sei se está relacionado:

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'

Entendo que o certificado é gerado localmente, sem nenhuma solicitação de rede externa?

A máquina é uma t3a.medium (4 GB de memória) e o fórum não está particularmente ocupado (~0,4 de carga, ainda há muita memória livre). Durante a espera pela geração do certificado, a CPU não parece ter mudado em nada, então isso não parece ser o gargalo.

Não somos os únicos enfrentando isso (não tenho certeza se isso está relacionado), mas não vejo nada lá que possa ajudar.

Não tenho certeza se estou no caminho certo, mas se eu atualizar a URL do certificado algumas vezes, eventualmente recebo um erro dizendo para diminuir a velocidade. Existe algum mecanismo de limitação de URL que possa estar interferindo aqui se muitas pessoas estiverem gerando certificados no mesmo caminho de URL? Possivelmente não, mas estou sem ideias do por que isso está acontecendo. Qualquer dica é bem-vinda.

3

Essa rota é de fato lenta, pois é nova.

Além de tentar torná-la mais rápida, talvez possamos alterar o texto da mensagem para informar ao usuário que o Discobot está preparando algo e que isso levará um minuto?

5

Eu não sabia que era conhecido por ser lento — se não for nada mais, acho que uma atualização no post para deixar isso claro pode ajudar, mas ainda espero que algumas pessoas desistam se a espera for longa.

Devo dizer que 10 a 20 segundos para gerar parecem um tempo excessivamente longo para produzir um SVG pré-existente (assumo?) preenchido com algum texto? Pelo que consigo ver, isso não parece ser limitado pela CPU. Qual é o gargalo aqui?

6

Estava pensando em editar o texto aqui para incluir uma frase como “por favor, aguarde, estou gerando algo legal para você!” na etapa anterior… mas no try.discourse.org a geração do certificado é MUITO rápida:

image
image1540×881 107 KB

Timestamp da última etapa do discobot: 2 de nov., 18:46 1604371566089
Timestamp da etapa de geração do certificado do discobot: 2 de nov., 18:46 1604371567470

Não sei exatamente quais são as unidades dos timestamps subjacentes, mas isso representa uma diferença de 1381.

Respondi o mais rápido possível no mesmo tópico e obtive estes timestamps, claramente com menos de alguns segundos de diferença:

1604373488630
1604373492182

Isso é uma diferença de 3552… e eu literalmente publiquei o mais rápido que pude, usando colagem e atalhos de teclado!

Então… seu servidor simplesmente… é ruim… ou algo assim?

7

Acredito que ele esteja falando sobre a geração da imagem do certificado, não sobre o post.

8

Estou, de fato, falando da geração do certificado — e não da resposta que o incorpora (que é rápida). É isso que este problema está causando para alguns dos nossos membros:

image
image556×333 3.72 KB

Não, uma instância t3a.medium é de faixa intermediária e a carga não é alta.

Como disse, isso não parece ser limitado por CPU, pois enquanto aguardo o término de uma solicitação, por exemplo, /discobot/certificate.svg?date=Oct+28+2020&user_id=123, a CPU não está mais ocupada do que em qualquer outro momento (o que não é muito ocupado).

O problema parece estar relacionado a um tempo limite em uma solicitação de rede:

O avatar no certificado parece ser um blob data:image/png;base64. Pelo que consigo ver, há uma tentativa de baixar um avatar que está atingindo o tempo limite? Talvez seja isso que esteja deixando as coisas lentas aqui?

Para contexto, isso ocorre em um fórum com SSO e os avatares são URLs HTTPS armazenados no S3. Tentei buscar alguns desses avatares de dentro do contêiner Docker e funciona, sendo quase instantâneo — sem problemas de firewall, etc. Tudo mais no fórum funciona rápido, exceto ao gerar o certificado, o que leva muito tempo.

Fico feliz em tentar depurar isso mais a fundo se receber orientações sobre o que verificar.

9

A imagem apareceu mais ou menos instantaneamente para mim no try.discourse.org… Não percebi um atraso significativo de mais de talvez meio segundo, se é que houve algum? Teste você mesmo se não acredita em mim!

Então, volto ao que disse originalmente: por que isso é tão lento no seu servidor, mas tão rápido no try.discourse.org?

11

Por que, na verdade… É sobre isso que estou tentando obter suporte.

Entendo que isso seja um cenário do tipo “funciona na minha máquina” que nem deveria existir com Docker, mas, infelizmente, aqui estamos e parece que não sou o único.

Qualquer dica sobre como depurar isso do meu lado seria apreciada.

12

Passei algum tempo investigando isso e o problema parece ser que o discourse-narrative-bot fica bloqueado ao buscar o avatar do usuário para incluir no certificado. Veja aqui:

Este fórum utiliza SSO e os avatares são URLs do Amazon S3 — que são rápidas e não têm limite de taxa imposto pela Amazon. Dito isso, essa função está buscando uma URL de avatar no seguinte formato:

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

Será que os erros de timeout que estão atrasando a geração do certificado são causados por atingir o limite de taxa do Discourse de alguma forma? Seja por solicitar os avatares muito rapidamente da própria instância do Discourse ou, ao tentar acessar o Amazon S3 com muita frequência quando vários usuários estão fazendo o tutorial do bot?

13

Interessante. Injetamos uma imagem em base64 ali. Me pergunto por que não simplesmente linkamos para o recurso externo na tag image do SVG :thinking:

Eu mergulhei na história do plugin até onde adicionamos isso pela primeira vez:

E parece que sempre usamos avatares em base64 injetados.

EDIT: Após algumas pesquisas, injetamos com base64 porque o certificado é carregado via uma tag HTML img. Para obter avatares mais baratos, teríamos que migrar para uma tag object, que é bloqueada por padrão no nosso CSP. Ou injetar o SVG inteiro no conteúdo da postagem. Acho que um iframe é nossa melhor opção.

Tenho FIX: Make discobot certificate gen faster/non blocking by xfalcox · Pull Request #11344 · discourse/discourse · GitHub para os comentários do @tgxworld.

14

Eu assumi que o SVG incorporando o avatar em base64 era pelo mesmo motivo que o logo “estava fazendo” isso: para que o certificado pudesse ser um instantâneo no tempo — talvez salvo pelo premiado, sem dependências externas, para que ainda fosse renderizado exatamente da mesma forma mais tarde.

A abordagem com iframe impede que seja facilmente compartilhado e exibido com orgulho em uma postagem. Não sei o quão comum isso é em outros fóruns, mas já vi alguns dos nossos usuários fazendo isso apenas copiando a URL da imagem.

Se for usar links para algo externo, não funcionaria usar <image> aqui e evitar a necessidade de alterar allowed_iframes?

15

É exatamente isso que o PR acima faz, se você o ler :grimacing:

Mas se você carregar o SVG com a tag HTML img, como fazemos hoje, as imagens externas contidas nas tags image do SVG não serão carregadas. Para que isso funcione, é necessário carregá-las usando object ou iframe.

16

Claramente, não sei o suficiente sobre SVG. A abordagem com iframe impede que o certificado seja citado/copiado, mas, mesmo assim, fico feliz que isso esteja sendo resolvido de alguma forma, pois isso corrigirá nosso problema e também o logotipo ausente no certificado. :+1:

17

@mentalstring Acabei de mesclar o novo código de geração de certificados. Deve ser muito mais rápido agora.

18

Ótimo ver isso sendo mesclado. :+1:

Estamos na versão stable e no momento não tenho uma boa maneira de testar isso. Mas, se fetch_avatar não for mais utilizado, espero que nossos erros Net::ReadTimeout desapareçam com essa alteração. Marcando como resolvido e reabrirei se, por algum motivo, eu encontrar o mesmo problema novamente quando atualizarmos. Obrigado!