Novo erro `503` sobre o `database.js`

[filipedeschamps]

@aprendendofelipe olha que interessante, depois do deploy de hoje (que não tem nada a ver com o erro), a reconstrução do cache dos estáticos estourou o limite de conexões. Imagino que foi por conta da alteração da tolerância:

https://github.com/filipedeschamps/tabnews.com.br/blob/2140677b91ce45280355fef2d25f2ad4c0411815/infra/database.js#L81

Exemplo de request:

/_next/data/qB4Sh0A7dKVrKyO0cHOAP/pt-br/Ezequias/tabnews-discord-bot-teste-13-testando-markdown.json?username=Ezequias&slug=tabnews-discord-bot-teste-13-testando-markdown

{
   "level":50,
   "time":1662918874297,
   "environment":"preview",
   "payload":{
      "name":"ServiceError",
      "message":"remaining connection slots are reserved for non-replication superuser connections",
      "action":"Verifique se o serviço está disponível.",
      "status_code":503,
      "error_id":"e198ad5e-c870-4113-805f-f07bbb3eddc0",
      "context":{
         "query":"\n      WITH user_found AS (\n        SELECT\n          *\n        FROM\n          users\n        WHERE\n          LOWER(username) = LOWER($1)\n        LIMIT\n          1\n      )\n      SELECT\n        user_found.*,\n        get_current_balance('user:tabcoin', user_found.id) as tabcoins,\n        get_current_balance('user:tabcash', user_found.id) as tabcash\n      FROM\n        user_found\n      ;"
      },
      "error_location_code":"INFRA:DATABASE:QUERY",
      "database_error_code":"53300"
   }
}

---

Nesse parece que não deu tempo das retentativas (dado a distância entre lambdas e banco)

/_next/data/qB4Sh0A7dKVrKyO0cHOAP/pt-br/filipedeschamps/testando-o-novo-metodo-findrootcontent-que-vai-poder-trazer-muito-mais-contexto.json?username=filipedeschamps&slug=testando-o-novo-metodo-findrootcontent-que-vai-poder-trazer-muito-mais-contexto

{
   "level":50,
   "time":1662918873580,
   "environment":"preview",
   "payload":{
      "name":"ServiceError",
      "message":"sorry, too many clients already",
      "action":"Verifique se o serviço está disponível.",
      "status_code":503,
      "error_id":"01238d2f-333c-4d63-9ff6-807172519f1b",
      "context":{
         "query":"\n      WITH user_found AS (\n        SELECT\n          *\n        FROM\n          users\n        WHERE\n          LOWER(username) = LOWER($1)\n        LIMIT\n          1\n      )\n      SELECT\n        user_found.*,\n        get_current_balance('user:tabcoin', user_found.id) as tabcoins,\n        get_current_balance('user:tabcash', user_found.id) as tabcash\n      FROM\n        user_found\n      ;"
      },
      "error_location_code":"INFRA:DATABASE:QUERY",
      "database_error_code":"53300"
   }
}

Conclusão

Talvez reduzir um pouco o maxConnectionsTolerance e aumentar um pouco as retentativas? Digo talvez, pois Produção não reclamou de nada.

[aprendendofelipe]

Já sabemos que sempre que ocorre um deploy:

1. Não é aproveitada nenhuma conexão já aberta com o banco, pois são criadas novas lambdas sem descartar as que já existiam.
2. Dezenas de lambdas são criadas simultaneamente para gerar os estáticos de cada conteúdo listado em ContentList, além das páginas de cada diferente autor desses conteúdos. Isso pode passar de 60 novas conexões.

Então vamos especular sobre a situação que deve ter ocorrido para pensar em como solucionar.

Situação que gerou o erro

Imagino que foi algo assim:

1. Antes do deploy, por qualquer motivo, já haviam muitas conexões abertas, mas em número menor do que o limiar de 90%. 90% parece mesmo ser muito, talvez os 70% de antes funcionem melhor, ou até menos.
2. Após o deploy, para gerar as páginas estáticas, o número de tentativas de abertura de novas conexões ultrapassou não somente os 90%, mas chegou ao limite do banco.
3. As primeiras lambdas que conseguiram se conectar encerraram suas conexões logo após suas primeiras consultas (que obtém o id do autor) por causa do tooManyConnections.
4. Então essas lambdas entraram no processo de retry para tentar fazer a segunda consulta (que obtém os dados do conteúdo). Esse ponto precisa de ajuste, pois seria melhor a página ser gerada com uma única consulta ao banco, ou no mínimo garantir que essas duas consultas ocorram com o mesmo client, como já é feito nas transações.
5. Enquanto isso as demais lambdas ficaram tentando se conectar de acordo com a configuração de retry e só conseguiram utilizar as conexões encerradas pelas primeiras lambdas desse novo deploy. Somente as conexões que já estavam livres antes do deploy são revezadas. Dependendo de quantas conexões estão sendo revezadas, e pelo maior tempo gasto em cada geração por necessitar estabelecer conexão duas vezes, nem todas lambdas conseguirão se conectar dentro dos tempos configurados e por isso temos esses erros. Aumentar o número de tentativas pode diminuir os erros, mas desde que não cause ainda mais lentidão no banco, que será sentida provavelmente pelo erro de timeout de conexão.
6. Já as lambdas do deploy antigo nem tomaram conhecimento e continuaram monopolizando as conexões com o banco, pois se não estavam fazendo consultas, não executaram o checkForTooManyConnections. Aqui talvez o idle_session_timeout seja útil.

Dúvidas

As dúvidas que ainda tenho que sanar antes de propor solução melhor são:

1. Em que momento o servidor PostgreSQL encerra a conexão iniciada por uma lambda que foi congelada antes que pudesse liberar a conexão que ela estava utilizando? Informação útil, entre outras coisas, para lidar com as conexões abertas por deploys antigos.
2. Ao utilizar getStaticPaths são utilizadas diferentes lambdas (e diferentes conexões com o banco) para cada página que será gerada durante o deploy ou as páginas são geradas por uma única instância?
3. Numa situação de alta demanda para o banco, quanto tempo dura a consulta para gerar uma página estática? Informação útil para determinar o timeout do retry.
4. Como podemos identificar se estamos enfrentando uma situação esporádica de alta demanda ou se estamos sob algum ataque?
5. Enquanto não estamos diferenciando as duas situações acima (alta demanda ou ataque), pensando na experiência do usuário, qual é o tempo ideal para retornar um erro que indique que o sistema está passando por alguma instabilidade? Ou seja, quanto tempo ficar reenviando tentativas de conexões com o banco para atender uma solicitação antes de retornar um erro? É boa ideia usar todo o limite de 60s das lambdas?

Proposta provisória

Se as especulações estiverem corretas, e nenhum outro tipo de erro foi gerado, o que deve ter causado o problema foi que o número de conexões existentes antes do deploy somado aos que foram gerados pelo deploy acabaram passando do limite do banco. Sendo assim, o que podemos fazer por enquanto é diminuir o maxConnectionsTolerance para limitar as conexões preexistentes.

E caso queira aumentar o número de tentativas de conexão com o banco antes de gerar um erro, temos que trabalhar nos valores do retry. Sem mexer nos demais parâmetros, dá pra deixar o retries até 12 que ainda assim não vamos extrapolar os 60s de limite da lambda, mesmo se o banco não estiver respondendo. E a partir da 6ª tentativa os intervalos serão de 5 segundos entre cada tentativa de conexão que o banco recusar.

Resumindo

Totalmente de acordo com o que você sugeriu: maxConnectionsTolerance = 0.6 ou 0.7. retries: 12 ou qualquer coisa entre 5 e 12.

[filipedeschamps]

Recebendo novos erros e o banco está no talo:

Não tem nada nas estatísticas ou logs que justifiquem esse load. Se desse para saber qual lambda está consumindo a conexão seria muito show.

[filipedeschamps]

Incluindo alguns erros doidos:

MissingStaticPage [Error]: Failed to load static file for page: /pt-br/500 ENOENT: no such file or directory, open '/var/task/.next/server/pages/pt-br/500.html'
    at /var/task/node_modules/next/dist/server/require.js:55:19
    at async Promise.all (index 2)
    at async Object.loadComponents (/var/task/node_modules/next/dist/server/load-components.js:53:49)
    at async NextNodeServer.findPageComponents (/var/task/node_modules/next/dist/server/next-server.js:451:36)
    at async NextNodeServer.renderErrorToResponse (/var/task/node_modules/next/dist/server/base-server.js:1250:26)
    at async NextNodeServer.renderToResponse (/var/task/node_modules/next/dist/server/base-server.js:1188:30)
    at async NextNodeServer.pipe (/var/task/node_modules/next/dist/server/base-server.js:634:25)
    at async Object.fn (/var/task/node_modules/next/dist/server/base-server.js:501:21)
    at async Router.execute (/var/task/node_modules/next/dist/server/router.js:222:36)
    at async NextNodeServer.run (/var/task/node_modules/next/dist/server/base-server.js:612:29)

[aprendendofelipe]

Recebendo novos erros e o banco está no talo:

Acabamos não fazendo o que comentamos acima

[filipedeschamps]

Meu maior palpite é que algum bot (ou pessoa) possa ter passado por várias paginações antigas e disparado requests de todos os links, apesar de ao avaliar somente o que foi acessado de /_next não revelar nenhum outlier. Vou continuar monitorando aqui e fazer merge do #751 🤝

[aprendendofelipe]

Meu maior palpite é que algum bot (ou pessoa) possa ter passado por várias paginações antigas e disparado requests de todos os links

Provavelmente foi isso, pois parece que foi algo momentâneo, né? E não deve ter relação com o novo algoritmo de ranqueamento, pois só tem 2 ou 3 páginas utilizando ele. Na geração das páginas de recentes só mudou a questão do count.

Essa configuração do #751 deve diminuir a chance disso se repetir.

[filipedeschamps]

Tá no talo de novo e analisando qual a última query feita pelas conexões que estão idle, a maioria se agrupa entre estas três:

Query 1

      WITH RECURSIVE children AS (
        SELECT
            id,
            owner_id,
            parent_id,
            slug,
            title,
            body,
            status,
            source_url,
            created_at,
            updated_at,
            published_at,
            deleted_at
        FROM
          contents
        WHERE
          contents.id = $1 AND
          contents.status = 'published'
        UNION ALL
          SELECT
            contents.id,
            contents.owner_id,
            contents.parent_id,
            contents.slug,
            contents.title,
            contents.body,
            contents.status,
            contents.source_url,
            contents.created_at,
            contents.updated_at,
            contents.published_at,
            contents.deleted_at
          FROM
            contents
          INNER JOIN
            children ON contents.parent_id = children.id
          WHERE
            contents.status = 'published'

      )
      SELECT
        children.id,
        children.owner_id,
        children.parent_id,
        children.slug,
        children.title,
        children.body,
        children.status,
        children.source_url,
        children.created_at,
        children.updated_at,
        children.published_at,
        children.deleted_at,
        users.username as owner_username,
        get_current_balance('content:tabcoin', children.id) as tabcoins
      FROM
        children
      INNER JOIN
        users ON children.owner_id = users.id
      ORDER BY
        children.published_at ASC;
      ;

Query 2

      WITH user_found AS (
        SELECT
          *
        FROM
          users
        WHERE
          LOWER(username) = LOWER($1)
        LIMIT
          1
      )
      SELECT
        user_found.*,
        get_current_balance('user:tabcoin', user_found.id) as tabcoins,
        get_current_balance('user:tabcash', user_found.id) as tabcash
      FROM
        user_found
      ;

Query 3

SELECT numbackends as opened_connections FROM pg_stat_database where datname = $1

---

Por exemplo, agora está com 45 conexões abertas, sendo nas top 3 queries, 17 são da Query 1, 11 da Query 3 e 8 da Query 2.

[aprendendofelipe]

Por exemplo, agora está com 45 conexões abertas, sendo nas top 3 queries, 17 são da Query 1, 11 da Query 3 e 8 da Query 2.

Nenhuma dessas queries foi alterada. Na verdade você está vendo as queries mais utilizadas, não necessariamente as que estão causando algum problema. Se é que o problema é alguma query específica.

Está aparecendo alguma vez a query de ranqueamento? Ela está sendo chamada a todo momento por causa do revalidateOnMount chamando a api/contents, então é para aparecer.

Ou tem alguém fazendo algum acesso diferente do normal, ou a nova query está deixando o banco mais lento, pois comparando ontem e hoje nos mesmos horários, dá pra ver no console da Vercel que aumentou o tempo de execução das lambdas.

Mas não deu mais erro após o deploy do #751, né?

[aprendendofelipe]

Será que tem muita gente acessando pra ver o saldo dos outros? 🙈

https://www.tabnews.com.br/GabrielSozinho/pitch-tabstats-um-site-para-ver-informacoes-de-usuarios-do-tabnews

[filipedeschamps]

estão causando algum problema. Se é que o problema é alguma query específica.

Isso, das conexões que estão ainda abertas, essa foi a última query rodada naquela conexão. É o mais próximo que conseguir chegar de tentar entender quem está com essas conexões abertas. Seria muito massa conseguir ver quais lambdas estão ativas e congeladas 😍

Está aparecendo alguma vez a query de ranqueamento? Ela está sendo chamada a todo momento por causa do revalidateOnMount chamando a api/contents, então é para aparecer.

Ela aparece sim, mas não ficou em nenhum momento no top das mais usadas. Tem algum acesso acontecendo por dentro das páginas mesmo, eu especulo.

Ou tem alguém fazendo algum acesso diferente do normal, ou a nova query está deixando o banco mais lento, pois comparando ontem e hoje nos mesmos horários, dá pra ver no console da Vercel que aumentou o tempo de execução das lambdas.

Pelo que estou entendo dos gráficos, a nova query não está deixando o banco mais lento, olha a análise do P25, P50 e P75 dos últimos 2 dias:

E a média:

Passando um pente fino, a média saiu de ~750ms para ~900ms o que é absurdamente ótimo considerando o que a query nova faz 🤝

Mas não deu mais erro após o deploy do #751, né?

Não deu, tudo 100% 🤝

[filipedeschamps]

Será que tem muita gente acessando pra ver o saldo dos outros? 🙈

https://www.tabnews.com.br/GabrielSozinho/pitch-tabstats-um-site-para-ver-informacoes-de-usuarios-do-tabnews

😂 eu especulei isso! @gabrielsozinho você poderia compartilhar a quantidade de acessos ao seu site (se você tiver) para vermos se teve algum volume que case com a quantidade de conexões abertas aqui?

[gabrielsozinho]

Será que tem muita gente acessando pra ver o saldo dos outros? 🙈 https://www.tabnews.com.br/GabrielSozinho/pitch-tabstats-um-site-para-ver-informacoes-de-usuarios-do-tabnews

😂 eu especulei isso! @gabrielsozinho você poderia compartilhar a quantidade de acessos ao seu site (se você tiver) para vermos se teve algum volume que case com a quantidade de conexões abertas aqui?

Opa, desculpa não responder antes! Eu não tenho acesso a esses dados, não adicionei nenhum contador de acessos e só contas premium conseguem esses dados na Netlify. Se ainda for do interesse, eu posso tirar o site do ar ou adicionar um contador.

[gabrielsozinho]

Pra deixar registrado, 5 dias depois do comentário que eu fiz aqui em cima, eu implementei um contador de acessos. A página é acessada em média de 6 à 11 vezes por dia. Mas também, vale ressaltar que eu não divulguei o site em nenhum lugar depois disso, sendo assim, o número na época em que eu publiquei no TabNews era bem maior.

Acho que esses acessos ou vieram de pessoas que conheceram o TabStats pelo TabNews, ou vieram pelo meu portfólio. (Que eu não sei como, conseguiu 104 acessos desde que eu implementei o contador, sendo que eu apenas adicionei o link no meu GitHub e em um comentário do TabNews).

[aprendendofelipe]

Vou fechar essa issue já que aparentemente o problema não se repetiu, até porque fizemos diversas otimizações após esse período. 🤝