[Pkg-puppet-devel] Bug#994843: puppetdb: Frequent command submissions failures with jetty 9.4.16-0+deb10u1

[Kienan Stewart]

Package: puppetdb
Version: 6.2.0-3
Severity: important
X-Debbugs-Cc: kienan at koumbit.org

Dear Maintainer,

I'm not sure whether this bug applies more to puppetdb or libjetty9-java, but I will start the report here.

After libjetty9-java upgraded from 9.4.15-1 to 9.4.16-0+deb10u1 frequent puppet agent run errors started happening, with a vague error:

Error: Could not retrieve catalog from remote server: Error 500 on SERVER: Server Error: Failed to execute '/pdb/cmd/v1?checksum=9c18923b33f99552a5e49974ae5ff05be74fb672&version=9&certname=xxx.example.com&command=replace_catalog&producer-timestamp=2021-09-20T20:13:16.121Z' on at least 1 of the following 'server_urls': https://puppet:8081

The error didn't happen regularly for all nodes, but seemed to affect nodes with larger catalogs more frequently.

While testing, I enabled to the debug logging in the puppetdb logback.xml. During the runs that failed, I found a backtrace with the error:

2021-09-20T18:33:07.796-04:00 DEBUG [o.e.j.i.WriteFlusher] ignored: WriteFlusher at 23e9cdf8{IDLE}->null
javax.net.ssl.SSLHandshakeException: Encrypted buffer max length exceeded

A more complete version is towards the end of this report. There is a jetty release that covered a possibly related issue: https://github.com/eclipse/jetty.project/issues/6121

Verifying against our monitoring history, which contains information on the puppet run failures, I noticed that the date corresponded with when the jetty version changed. By downgrading, I was able to confirm that it fixed the situation. As I said at the beginning I'm not sure if the fault here is in puppetdb, or in libjetty9-java.

Please let me know if you need more information.

Debian release: buster
# apt policy
Package files:
 100 /var/lib/dpkg/status
     release a=now
 500 http://deb.debian.org/debian buster/contrib amd64 Packages
     release v=10.10,o=Debian,a=oldstable,n=buster,l=Debian,c=contrib,b=amd64
     origin deb.debian.org
 500 http://deb.debian.org/debian buster/main amd64 Packages
     release v=10.10,o=Debian,a=oldstable,n=buster,l=Debian,c=main,b=amd64
     origin deb.debian.org
 500 http://deb.debian.org/debian buster-updates/main amd64 Packages
     release o=Debian,a=oldstable-updates,n=buster-updates,l=Debian,c=main,b=amd64
     origin deb.debian.org
 500 http://security.debian.org/debian-security buster/updates/main amd64 Packages
     release v=10,o=Debian,a=oldstable,n=buster,l=Debian-Security,c=main,b=amd64
     origin security.debian.org


2021-09-20T18:33:07.796-04:00 DEBUG [o.e.j.i.WriteFlusher] ignored: WriteFlusher at 23e9cdf8{IDLE}->null
javax.net.ssl.SSLHandshakeException: Encrypted buffer max length exceeded
        at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.fill(SslConnection.java:613)
        at org.eclipse.jetty.server.HttpConnection.fillRequestBuffer(HttpConnection.java:340)
        at org.eclipse.jetty.server.HttpConnection.fillAndParseForContent(HttpConnection.java:313)
        at org.eclipse.jetty.server.HttpInputOverHTTP.produceContent(HttpInputOverHTTP.java:33)
        at org.eclipse.jetty.server.HttpInput.nextContent(HttpInput.java:369)
        at org.eclipse.jetty.server.HttpInput.read(HttpInput.java:301)
        at java.base/java.io.InputStream.transferTo(InputStream.java:704)
        at java.base/java.nio.file.Files.copy(Files.java:3078)
        at puppetlabs.stockpile.queue$write_stream.invokeStatic(queue.clj:102)
        at puppetlabs.stockpile.queue$write_stream.invoke(queue.clj:100)
        at puppetlabs.stockpile.queue$store$fn__6587.invoke(queue.clj:282)
        at puppetlabs.stockpile.queue$store.invokeStatic(queue.clj:281)
        at puppetlabs.stockpile.queue$store.invoke(queue.clj:228)
        at puppetlabs.puppetdb.queue$eval21400$store_in_stockpile__21405$fn__21406.invoke(queue.clj:288)
        at puppetlabs.puppetdb.queue$eval21400$store_in_stockpile__21405.invoke(queue.clj:283)
        at puppetlabs.puppetdb.queue$eval21432$store_command__21437$fn__21438.invoke(queue.clj:321)
        at puppetlabs.puppetdb.queue$eval21432$store_command__21437.invoke(queue.clj:317)
        at puppetlabs.puppetdb.command$eval37528$do_enqueue_command__37533$fn__37537$fn__37539.invoke(command.clj:253)
        at puppetlabs.puppetdb.command.proxy$java.lang.Object$Callable$7da976d4.call(Unknown Source)
        at com.codahale.metrics.Timer.time(Timer.java:101)
        at puppetlabs.puppetdb.command$eval37528$do_enqueue_command__37533$fn__37537.invoke(command.clj:252)
        at puppetlabs.puppetdb.command$eval37528$do_enqueue_command__37533.invoke(command.clj:244)
        at puppetlabs.puppetdb.command$reify__37765$service_fnk__23931__auto___positional$reify__37775.enqueue_command(command.clj:728)
        at puppetlabs.puppetdb.command$eval37650$fn__37651$G__37638__37667.invoke(command.clj:420)
        at puppetlabs.puppetdb.command$eval37650$fn__37651$G__37637__37684.invoke(command.clj:420)
        at clojure.lang.AFn.applyToHelper(AFn.java:195)
        at clojure.lang.AFn.applyTo(AFn.java:144)
        at clojure.core$apply.invokeStatic(core.clj:673)
        at clojure.core$partial$fn__5824.doInvoke(core.clj:2622)
        at clojure.lang.RestFn.invoke(RestFn.java:573)
        at puppetlabs.puppetdb.http.command$enqueue_command_handler$fn__48413$do_submit__48417.invoke(command.clj:225)
        at puppetlabs.puppetdb.http.command$enqueue_command_handler$fn__48413.invoke(command.clj:239)
        at compojure.response$eval1557$fn__1558.invoke(response.clj:47)
        at compojure.response$eval1479$fn__1480$G__1470__1487.invoke(response.clj:7)
        at puppetlabs.puppetdb.http.command$routes$fn__48426.invoke(command.clj:252)
        at bidi.ring$eval37244$fn__37245.invoke(ring.cljc:25)
        at bidi.ring$eval37223$fn__37224$G__37214__37233.invoke(ring.cljc:16)
        at puppetlabs.puppetdb.middleware$eval37961$make_pdb_handler__37970$fn__37973$fn__37975.invoke(middleware.clj:336)
        at puppetlabs.puppetdb.http.command$validate_command_version$fn__48312.invoke(command.clj:51)
        at puppetlabs.puppetdb.http.command$wrap_with_request_normalization$fn__48407.invoke(command.clj:173)
        at puppetlabs.puppetdb.http.command$add_received_param$fn__48423.invoke(command.clj:248)
        at puppetlabs.puppetdb.middleware$validate_query_params$fn__37878.invoke(middleware.clj:171)
        at puppetlabs.puppetdb.middleware$verify_accepts_content_type$fn__37860.invoke(middleware.clj:114)
        at puppetlabs.puppetdb.middleware$verify_content_type$fn__37872.invoke(middleware.clj:144)
        at puppetlabs.puppetdb.middleware$verify_content_encoding$fn__37865.invoke(middleware.clj:128)
        at puppetlabs.puppetdb.middleware$fail_when_payload_too_large$fn__37910.invoke(middleware.clj:289)
        at puppetlabs.puppetdb.middleware$wrap_with_metrics$fn__37888$fn__37897.invoke(middleware.clj:239)
        at puppetlabs.puppetdb.utils.metrics$multitime_BANG__STAR_$fn__36085$fn__36086$fn__36087.invoke(metrics.clj:14)
        at puppetlabs.puppetdb.utils.metrics.proxy$java.lang.Object$Callable$7da976d4.call(Unknown Source)
        at com.codahale.metrics.Timer.time(Timer.java:101)