Sehr langsame discobot-Zertifikatgenerierung auf unserem Server

[mentalstring (Paulo)]

Wir haben unsere neuen Mitglieder dazu gedrängt, das Discobot-Tutorial durchzuführen, und einige stoßen dabei auf ein Problem, das wir bereits in einer früheren (Staging-)Discourse-Instanz erlebt haben: Das Zertifikat im letzten Beitrag benötigt sehr lange, um generiert zu werden und tatsächlich angezeigt zu werden, ohne dass eine Lade- oder Generierungsanzeige vorhanden ist. Mit „sehr lange

[Falco]

Diese Route ist tatsächlich langsam, da sie neu ist.

Anstatt sie zu beschleunigen, könnten wir die Nachricht vielleicht so ändern, dass dem Benutzer mitgeteilt wird, dass Discobot etwas vorbereitet und dies eine Minute dauern wird?

[mentalstring (Paulo)]

Mir war nicht bewusst, dass es als langsam bekannt ist – wenn nichts anderes, könnte zumindest ein Update im Beitrag, das dies klarstellt, helfen. Dennoch erwarte ich, dass einige Leute aufgeben, wenn die Wartezeit zu lang ist.

Ich muss sagen, dass 10 bis 20 Sekunden zum Generieren ungewöhnlich lang erscheinen, um ein bereits existierendes SVG (vermutlich?) mit etwas Text auszufüllen? Soweit ich das überblicke, scheint dies nicht CPU-bedingt zu sein. Was ist hier der Flaschenhals?

[codinghorror (Jeff Atwood)]

Ich habe überlegt, den Text hier so anzupassen, dass ein Satz wie „Bitte warten, ich generiere etwas Cooles für dich!

[Falco]

Ich glaube, er spricht über die Generierung des Zertifikatsbildes, nicht über den Beitrag.

[mentalstring (Paulo)]

Ich spreche tatsächlich von der Generierung des Zertifikats — nicht von der Antwortpost, die es einbettet (die ist schnell). Das ist das Problem, das einige unserer Mitglieder betrifft:

@codinghorror

Also… zieht dein Server einfach… nur… oder was?

Nein, eine t3a.medium ist eine Instanz mittlerer Leistungsklasse, und die Auslastung ist nicht hoch.

Wie gesagt, scheint dies nicht CPU-bedingt zu sein, denn während ich auf eine Anfrage wie /discobot/certificate.svg?date=Oct+28+2020&user_id=123 warte, ist die CPU nicht stärker ausgelastet als zu anderen Zeiten (was ohnehin nicht sehr belastet ist).

Das Problem scheint mit einem Netzwerk-Request zusammenzuhängen, der ein Timeout verursacht:

@mentalstring

In den /logs sehe ich eine Warnung, von der ich nicht weiß, ob sie damit zusammenhängt:

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'

Das Avatar-Bild auf dem Zertifikat scheint ein data:image/png;base64-Blob zu sein. Soweit ich sehe, wird versucht, ein Avatar herunterzuladen, das ein Timeout verursacht? Vielleicht ist das der Grund für die Verlangsamung?

Zum Kontext: Dies findet in einem Forum mit SSO statt, und Avatare sind HTTPS-URLs, die auf S3 gespeichert sind. Ich habe versucht, einige dieser Avatare innerhalb des Docker-Containers abzurufen, und das funktioniert nahezu sofort — keine Firewall-Probleme usw. Alles andere im Forum läuft schnell, außer bei der Generierung des Zertifikats, was sehr lange dauert.

Gerne würde ich weiter nach dem Fehler suchen, wenn ich Hinweise darauf bekomme, was ich überprüfen soll.

[codinghorror (Jeff Atwood)]

@Falco

über die Generierung des Zertifikatsbildes

@mentalstring

Ich spreche tatsächlich über die Generierung des Zertifikats

Das Bild erschien bei mir auf try.discourse.org mehr oder weniger sofort. Mir fiel keine spürbare Verzögerung von mehr als vielleicht einer halben Sekunde auf, falls überhaupt? Probier es selbst aus, wenn du mir nicht glaubst!

Also komme ich zurück zu dem, was ich ursprünglich gesagt habe: Warum ist das auf deinem Server so langsam, aber auf try.discourse.org so schnell?

[mentalstring (Paulo)]

Warum wohl… Genau darum bitte ich um Unterstützung.

Ich verstehe, dass dies ein “es funktioniert auf meinem Rechner”-Szenario ist, das mit Docker eigentlich gar nicht auftreten sollte, aber nun ja, hier sind wir und es scheint, als wäre ich nicht der einzige.

Jegliche Hinweise, wie ich das Problem auf meiner Seite debuggen kann, wären sehr willkommen.

[mentalstring (Paulo)]

Ich habe mir das etwas genauer angesehen, und das Problem scheint darin zu bestehen, dass der discourse-narrative-bot blockiert, wenn er das Avatar des Benutzers lädt, um es auf dem Zertifikat einzufügen. Hier:

plugins/discourse-narrative-bot/plugin.rb

Dieses Forum nutzt SSO, und die Avatare sind Amazon-S3-URLs – diese sind schnell und werden von Amazon nicht gedrosselt. Dennoch ruft diese Funktion eine Avatar-URL im folgenden Format ab:

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

Könnten die Timeout-Fehler, die die Zertifikatsgenerierung verlangsamen, darauf zurückzuführen sein, dass irgendwie die Ratenbegrenzung von Discourse ausgelöst wird? Entweder dadurch, dass die Avatare zu schnell von der Discourse-Instanz selbst angefordert werden, oder weil versucht wird, bei Amazon S3 zu schnell zuzugreifen, wenn mehrere Benutzer gleichzeitig das Bot-Tutorial durchlaufen?

[Falco]

Interessant. Wir haben dort ein Base64-Bild inline eingebettet. Ich frage mich, warum wir nicht einfach auf die externe Ressource im image-SVG-Tag verweisen

Ich habe die Historie des Plugins bis zu dem Punkt durchsucht, an dem wir dies erstmals hinzugefügt haben:

FEATURE: Replace ASCII certificate.

Und es sieht so aus, als hätten wir Avatare immer als inline eingebettete Base64-Bilder verwendet.

EDIT: Nach einiger Recherche: Wir verwenden Base64, weil das Zertifikat über ein img-HTML-Tag geladen wird. Um günstigere Avatare zu erhalten, müssten wir auf ein object-Tag umsteigen, das in unserer CSP standardmäßig blockiert ist. Oder wir betten das gesamte SVG direkt in den Beitrag ein. Ich schätze, ein iframe ist unsere beste Option.

Ich habe FIX: Make discobot certificate gen faster/non blocking by xfalcox · Pull Request #11344 · discourse/discourse · GitHub für Kommentare von @tgxworld erstellt.

[mentalstring (Paulo)]

Ich habe angenommen, dass das SVG, das das in Base64 kodierte Avatar-Bild enthält, aus demselben Grund verwendet wurde, aus dem das Logo so gehandelt hat: damit das Zertifikat ein Momentaufnahme sein kann – vielleicht vom Preisträger gespeichert, ohne externe Abhängigkeiten, sodass es später immer noch exakt gleich dargestellt wird.

Der Iframe-Ansatz verhindert, dass es leicht in einem Beitrag geteilt und damit geprahlt werden kann. Ich weiß nicht, wie verbreitet dies auf anderen Foren ist, aber ich habe gesehen, wie einige unserer Benutzer dies tun, indem sie einfach die URL des Bildes kopieren.

@Falco

Um günstigere Avatare zu erhalten, müssten wir auf ein object-Tag umsteigen, das in unserer CSP standardmäßig blockiert ist.

Wenn man sich für eine Verlinkung zu etwas Externem entscheidet, würde es hier nicht funktionieren, <image> zu verwenden und so die Notwendigkeit zu vermeiden, allowed_iframes zu ändern?

[Falco]

@mentalstring

Wenn man auf etwas Externes verlinkt, würde es dann nicht funktionieren, <image> zu verwenden und so die Notwendigkeit zu umgehen, allowed_iframes zu ändern?

Genau das macht der oben genannte PR, wenn man ihn liest

Aber wenn du das SVG wie heute mit dem HTML-img-Tag lädst, werden externe Bilder, die in den SVG-image-Tags enthalten sind, nicht geladen. Dafür muss es entweder mit object oder iframe geladen werden.

[mentalstring (Paulo)]

Offensichtlich weiß ich nicht genug über SVG. Der Iframe-Ansatz verhindert, dass das Zertifikat zitiert/kopiert wird, aber dennoch freue ich mich, dass dies irgendwie angegangen wird, da dies unser Problem löst und auch das fehlende Logo auf dem Zertifikat behebt.

[Falco]

@mentalstring Ich habe den neuen Code zur Zertifikatsgenerierung gerade zusammengeführt. Es sollte jetzt viel schneller sein.

[mentalstring (Paulo)]

Toll, dass das hier gemergt wird.

Wir nutzen stable und habe aktuell keine gute Möglichkeit, das zu testen. Wenn fetch_avatar jedoch nicht mehr verwendet wird, erwarte ich, dass unsere Net::ReadTimeout-Fehler damit verschwinden. Ich markiere das hier als gelöst und öffne den Fall erneut, falls ich beim Update doch wieder auf dasselbe Problem stoße. Danke!