Jira (PDB-5549) PuppetDB 7.11.1: /pdb/admin/v1/archive returns 257 bytes

[Sebastian Döring]

Sebastian Döring created an issue

PuppetDB / PDB-5549 PuppetDB 7.11.1: /pdb/admin/v1/archive returns 257 bytes Issue Type: Bug Affects Versions: PDB 7.11.0 Assignee: Unassigned Components: PuppetDB \ API Created: 2022/10/11 2:03 AM Priority: Normal Reporter: Sebastian Döring On our puppetdb instance with around ~3000 nodes the puppetdb export stopped working. The behaviour occurs with both the puppetdb cli gem (puppet db export <file>) and when accessing the api directly: root@issopuppet7dbmwbsproda01:~# curl -X GET http://localhost:8080/pdb/admin/v1/archive -o puppetdb-export.tgz   % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current                                  Dload  Upload   Total   Spent    Left  Speed 100   258  100   258    0     0   2015      0 --:--:-- --:--:-- --:--:--  2015 (the curl returns almost immediately with the empty file) root@issopuppet7dbmwbsproda01:~# tar tf puppetdb-export.tgz puppetdb-bak/export-metadata.json root@issopuppet7dbmwbsproda01:~# cat puppetdb-bak/export-metadata.json { "timestamp" : "2022-10-11T07:58:58.397Z", "command_versions" : { "replace_catalog" : 9, "store_report" : 8, "replace_facts" : 5, "configure_expiration" : 1, "replace_catalog_inputs" : 1 } This used to work previously and I'm unsure what changed (last successful export: ~550 MB). Curiously the log shows no errors. For debugging I've enabled "log-queries = true" from a puppetdb instance and removed all other traffic. The puppetdb.log shows: 2022-10-10T14:50:50.546+02:00 INFO [p.p.export] Export triggered for PuppetDB 2022-10-10T14:50:50.548+02:00 INFO [p.p.query-eng] PDBQuery:d5f2ff70-9e66-40b3-8e4f-87bca27228b4:{"ast":["from","nodes-with-fact-expiration"],"origin":null} 2022-10-10T14:50:50.562+02:00 INFO [p.p.query-eng] PDBQuery:d5f2ff70-9e66-40b3-8e4f-87bca27228b4:{"origin":null,"params":[],"sql":"WITH inactive_nodes AS (SELECT certname FROM certnames WHERE (deactivated IS NOT NULL AND deactivated > '2022-04-13T12:50:50.560Z') OR (expired IS NOT NULL and expired > '2022-04-13T12:50:50.560Z')), not_active_nodes AS (SELECT certname FROM certnames WHERE (deactivated IS NOT NULL OR expired IS NOT NULL)) SELECT reports.corrective_change AS \"latest_report_corrective_change\", certnames.deactivated AS \"deactivated\", certnames.expired AS \"expired\", reports_environment.environment AS \"report_environment\", certnames.certname AS \"certname\", coalesce(certname_fact_expiration.expire, true) AS \"expires_facts\", fs.timestamp AS \"facts_timestamp\", facts_environment.environment AS \"facts_environment\", reports.cached_catalog_status AS \"cached_catalog_status\", report_statuses.status AS \"latest_report_status\", encode(reports.hash::bytea, 'hex') AS \"latest_report_hash\", catalogs.timestamp AS \"catalog_timestamp\", reports.noop_pending AS \"latest_report_noop_pending\", reports.end_time AS \"report_timestamp\", reports.noop AS \"latest_report_noop\", certname_fact_expiration.updated AS \"expires_facts_updated\", catalog_environment.environment AS \"catalog_environment\", reports.job_id AS \"latest_report_job_id\" FROM certnames LEFT JOIN catalogs ON catalogs.certname = certnames.certname LEFT JOIN factsets fs ON certnames.certname = fs.certname LEFT JOIN reports ON (certnames.certname = reports.certname AND certnames.latest_report_id = reports.id) LEFT JOIN environments catalog_environment ON catalog_environment.id = catalogs.environment_id LEFT JOIN report_statuses ON reports.status_id = report_statuses.id LEFT JOIN environments facts_environment ON facts_environment.id = fs.environment_id LEFT JOIN environments reports_environment ON reports_environment.id = reports.environment_id LEFT JOIN certname_fact_expiration ON certnames.id = certname_fact_expiration.certid"} 2022-10-10T14:56:38.178+02:00 INFO [p.t.internal] Shutting down due to JVM shutdown hook. There's no further queries and no "INFO [p.p.export] Finished exporting PuppetDB" output (as I see usually on my puppetdb test instance, where it's still working). What can we do to further diagnose this problem? Add Comment

This message was sent by Atlassian Jira (v8.20.11#820011-sha1:0629dd8)

[Sebastian Döring]

Sebastian Döring commented on PDB-5549

Re: PuppetDB 7.11.1: /pdb/admin/v1/archive returns 257 bytes I enabled <root level="debug"> in /etc/puppetlabs/puppetdb/logback.xml, but my untrained eyes don't notice anything suspicious or obviously wrong:     2022-10-11T15:57:20.799+02:00 INFO [p.p.export] Export triggered for PuppetDB 2022-10-11T15:57:20.801+02:00 DEBUG [o.e.j.s.HttpOutput] write(array HeapByteBuffer@238840f2[p=0,l=10,c=1024,r=10]={<<<\x1f\x8b\x08\x00\x00\x00\x00\x00\x00\xFf>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00}) 2022-10-11T15:57:20.801+02:00 DEBUG [o.e.j.s.HttpOutput] write(array) s=OPEN,api=BLOCKING,sc=false,e=null aggregated !flush HeapByteBuffer@397d38c0[p=0,l=10,c=32768, r=10]={<<<\x1f\x8b\x08\x00\x00\x00\x00\x00\x00\xFf>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00} 2022-10-11T15:57:20.819+02:00 INFO [p.p.query-eng] PDBQuery:935142ef-95d8-44d2-abf3-92266305ccec:{"ast":["from","nodes-with-fact-expiration"],"origin":null} 2022-10-11T15:57:20.856+02:00 DEBUG [p.p.q.engine] Attempting to drop unused joins from query 2022-10-11T15:57:20.864+02:00 INFO [p.p.query-eng] PDBQuery:935142ef-95d8-44d2-abf3-92266305ccec:{"origin":null,"params":[],"sql":"WITH inactive_nodes AS (SELECT certname FROM certnames WHERE (deactivated IS NOT NULL AND deactivated > '2022-04-14T13:57:20.859Z') OR (expired IS NOT NULL and expired > '2022-04-14T13:57:20.859Z')), not_active_nodes AS (SELECT certname FROM certnames WHERE (deactivated IS NOT NULL OR expired IS NOT NULL)) SELECT reports.corrective_change AS \"latest_report_corrective_change\", certnames.deactivated AS \"deactivated\", certnames.expired AS \"expired\", reports_environment.environment AS \"report_environment\", certnames.certname AS \"certname\", coalesce(certname_fact_expiration.expire, true) AS \"expires_facts\", fs.timestamp AS \"facts_timestamp\", facts_environment.environment AS \"facts_environment\", reports.cached_catalog_status AS \"cached_catalog_status\", report_statuses.status AS \"latest_report_status\", encode(reports.hash::bytea, 'hex') AS \"latest_report_hash\", catalogs.timestamp AS \"catalog_timestamp\", reports.noop_pending AS \"latest_report_noop_pending\", reports.end_time AS \"report_timestamp\", reports.noop AS \"latest_report_noop\", certname_fact_expiration.updated AS \"expires_facts_updated\", catalog_environment.environment AS \"catalog_environment\", reports.job_id AS \"latest_report_job_id\" FROM certnames LEFT JOIN catalogs ON catalogs.certname = certnames.certname LEFT JOIN factsets fs ON certnames.certname = fs.certname LEFT JOIN reports ON (certnames.certname = reports.certname AND certnames.latest_report_id = reports.id) LEFT JOIN environments catalog_environment ON catalog_environment.id = catalogs.environment_id LEFT JOIN report_statuses ON reports.status_id = report_statuses.id LEFT JOIN environments facts_environment ON facts_environment.id = fs. environment_id LEFT JOIN environments reports_environment ON reports_environment.id = reports.environment_id LEFT JOIN certname_fact_expiration ON certnames.id = certname_fact_expiration.certid"} 2022-10-11T15:57:21.124+02:00 DEBUG [o.e.j.s.HttpOutput] write(array HeapByteBuffer@56613b[p=0,l=246,c=1024,r=246]={<<<\xEd\x92\xCfn\xC3 \x0c\xC6s\xEeS\xA0\x9c\x93\xCe\x86\xF4_\x9e\xA3\xA7]"Jh...\x90\x12. \x8b\xCb_\x0fvfff\xE6\x9f\xF3\x0e{\xC7\xF1\xE5\x00\x08\x00\x00>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00}) 2022-10-11T15:57:21.124+02:00 DEBUG [o.e.j.s.HttpOutput] write(array) s=OPEN,api=BLOCKING,sc=false,e=null aggregated !flush HeapByteBuffer@397d38c0[p=0,l=256,c=32768,r=256]={<<<\x1f\x8b\x08\x00\x00\x00\x00\x00\x00\xFf\xEd\x92\xCfn\xC3 \x0c\xC6s\xEeS\xA0\x9c\x93\xCe...\x90\x12.\x8b\xCb_\x0fvfff\xE6\x9f\xF3\x0e{\xC7\xF1\xE5\x00\x08\x00\x00>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00} 2022-10-11T15:57:21.124+02:00 DEBUG [o.e.j.s.HttpOutput] close() s=CLOSING,api=BLOCKED,sc=false,e=null c=HeapByteBuffer@397d38c0[p=0,l=256,c=32768,r=256]={<<<\x1f\x8b\x08\x00\x00\x00\x00\x00\x00\xFf\xEd\x92\xCfn\xC3 \x0c\xC6s\xEeS\xA0\x9c\x93\xCe...\x90\x12.\x8b\xCb_\x0fvfff\xE6\x9f\xF3\x0e{\xC7\xF1\xE5\x00\x08\x00\x00>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00} b=Blocker@30aa340e{null} 2022-10-11T15:57:21.125+02:00 DEBUG [o.e.j.s.h.g.GzipHandler] GzipHandler@fb7f360{STARTED,min=32,inflate=-1} excluded not gzip accept Request(GET //localhost:8080/pdb/admin/v1/archive)@70e9ece0 2022-10-11T15:57:21.125+02:00 DEBUG [o.e.j.s.h.g.GzipHttpOutputInterceptor] org.eclipse.jetty.server.handler.gzip.GzipHttpOutputInterceptor@71f18929 exclude no deflater 2022-10-11T15:57:21.125+02:00 DEBUG [o.e.j.s.HttpChannel] sendResponse info=null content=HeapByteBuffer@397d38c0[p=0,l=256,c=32768,r=256]={<<<\x1f\x8b\x08\x00\x00\x00\x00\x00\x00\xFf\xEd\x92\xCfn\xC3 \x0c\xC6s\xEeS\xA0\x9c\x93\xCe... \x90\x12.\x8b\xCb_\x0fvfff\xE6\x9f\xF3\x0e{\xC7\xF1\xE5\x00\x08\x00\x00>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00} complete=true committing=true callback=Blocker@30aa340e{null} 2022-10-11T15:57:21.125+02:00 DEBUG [o.e.j.s.HttpChannel] COMMIT for /pdb/admin/v1/archive on HttpChannelOverHttp@77c5b5ae{s=HttpChannelState@23896806{s=HANDLING rs=BLOCKING os=COMMITTED is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=HANDLING,uri=//localhost:8080/pdb/admin/v1/archive,age=347} 200 null HTTP/1.1 Date: Tue, 11 Oct 2022 13:57:20 GMT^M Content-Type: application/octet-stream; charset=utf-8^M Content-Disposition: attachment; filename=puppetdb-export-2022-10-11T13:57:20.797Z.tgz^M Vary: Accept-Encoding, User-Agent^M ^M   2022-10-11T15:57:21.127+02:00 DEBUG [o.e.j.s.HttpConnection] generate: NEED_HEADER for SendCallback@625a7411[PROCESSING][i=HTTP/1.1{s=200,h=4,cl=-1},cb=org.eclipse.jetty.server.HttpChannel$SendCallback@7fd053ca] (null,[p=0,l=256,c=32768, r=256],true)@START 2022-10-11T15:57:21.127+02:00 DEBUG [o.e.j.h.HttpGenerator] generateHeaders HTTP/1.1{s=200,h=4,cl=-1} last=true content=HeapByteBuffer@397d38c0[p=0,l=256,c=32768,r=256]={<<<\x1f\x8b\x08\x00\x00\x00\x00\x00\x00\xFf\xEd\x92\xCfn\xC3 \x0c\xC6s\xEeS\xA0\x9c\x93\xCe...\x90\x12.\x8b\xCb_\x0fvfff\xE6\x9f\xF3\x0e{\xC7\xF1\xE5\x00\x08\x00\x00>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00} 2022-10-11T15:57:21.127+02:00 DEBUG [o.e.j.h.HttpGenerator] Date: Tue, 11 Oct 2022 13:57:20 GMT^M Content-Type: application/octet-stream; charset=utf-8^M Content-Disposition: attachment; filename=puppetdb-export-2022-10-11T13:57:20.797Z.tgz^M Vary: Accept-Encoding, User-Agent^M ^M   2022-10-11T15:57:21.128+02:00 DEBUG [o.e.j.h.HttpGenerator] CONTENT_LENGTH 2022-10-11T15:57:21.128+02:00 DEBUG [o.e.j.s.HttpConnection] generate: FLUSH for SendCallback@625a7411[PROCESSING][i=HTTP/1.1{s=200,h=4,cl=-1},cb=org.eclipse.jetty.server.HttpChannel$SendCallback@7fd053ca] ([p=0,l=255,c=8192,r=255],[p=0, l=256,c=32768,r=256],true)@COMPLETING 2022-10-11T15:57:21.128+02:00 DEBUG [o.e.j.i.WriteFlusher] write: WriteFlusher@211973dc{IDLE}->null [HeapByteBuffer@4ddc7fb6[p=0,l=255,c=8192,r=255]={<<<HTTP/1.1 200 OK\r\nDate: Tu...Content-Length: 256\r\n\r\n>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00},HeapByteBuffer@397d38c0[p=0,l=256,c=32768,r=256]={<<<\x1f\x8b\x08\x00\x00\x00\x00\x00\x00\xFf\xEd\x92\xCfn\xC3 \x0c\xC6s\xEeS\xA0\x9c\x93\xCe...\x90\x12. \x8b\xCb_\x0fvfff\xE6\x9f\xF3\x0e{\xC7\xF1\xE5\x00\x08\x00\x00>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00}] 2022-10-11T15:57:21.128+02:00 DEBUG [o.e.j.i.WriteFlusher] update WriteFlusher@211973dc{WRITING}->null:IDLE-->WRITING 2022-10-11T15:57:21.129+02:00 DEBUG [o.e.j.i.ChannelEndPoint] flushed 511 SocketChannelEndPoint@7e77087{l=/0:0:0:0:0:0:0:1:8080,r=/0:0:0:0:0:0:0:1:59484,OPEN,fill=-,flush=W,to=357/30000}{io=0/0,kio=0,kro=1}->HttpConnection@ 1d912c8e[p=HttpParser{s=CONTENT,0 of -1},g=HttpGenerator@6846698f{s=COMPLETING}]=>HttpChannelOverHttp@77c5b5ae{s=HttpChannelState@23896806{s=HANDLING rs=BLOCKING os=COMMITTED is=IDLE awp=false se=false i=true al=0},r=1,c=false/false, a=HANDLING,uri=//localhost:8080/pdb/admin/v1/archive,age=351} 2022-10-11T15:57:21.129+02:00 DEBUG [o.e.j.i.WriteFlusher] Flushed=true written=511 remaining=0 WriteFlusher@211973dc{WRITING}->null 2022-10-11T15:57:21.129+02:00 DEBUG [o.e.j.i.WriteFlusher] update WriteFlusher@211973dc{IDLE}->null:WRITING-->IDLE 2022-10-11T15:57:21.129+02:00 DEBUG [o.e.j.s.HttpConnection] generate: DONE for SendCallback@625a7411[PROCESSING][i=HTTP/1.1{s=200,h=4,cl=-1},cb=org.eclipse.jetty.server.HttpChannel$SendCallback@7fd053ca] ([p=255,l=255,c=8192,r=0],[p=256, l=256,c=32768,r=0],true)@END 2022-10-11T15:57:21.129+02:00 DEBUG [o.e.j.s.HttpOutput] onWriteComplete(true,null) s=CLOSING,api=BLOCKED,sc=false,e=null->s=CLOSED,api=BLOCKING,sc=false,e=null c=null cb=null w=false 2022-10-11T15:57:21.130+02:00 DEBUG [o.e.j.s.Server] handled=true async=false committed=true on HttpChannelOverHttp@77c5b5ae{s=HttpChannelState@23896806{s=HANDLING rs=BLOCKING os=COMPLETED is=IDLE awp=false se=false i=true al=0},r=1, c=false/true,a=HANDLING,uri=//localhost:8080/pdb/admin/v1/archive,age=352} 2022-10-11T15:57:21.130+02:00 DEBUG [o.e.j.s.HttpChannelState] unhandle HttpChannelState@23896806{s=HANDLING rs=BLOCKING os=COMPLETED is=IDLE awp=false se=false i=true al=0} 2022-10-11T15:57:21.130+02:00 DEBUG [o.e.j.s.HttpChannelState] nextAction(false) COMPLETE HttpChannelState@23896806{s=HANDLING rs=COMPLETING os=COMPLETED is=IDLE awp=false se=false i=false al=0} 2022-10-11T15:57:21.130+02:00 DEBUG [o.e.j.s.HttpChannel] action COMPLETE HttpChannelOverHttp@77c5b5ae{s=HttpChannelState@23896806{s=HANDLING rs=COMPLETING os=COMPLETED is=IDLE awp=false se=false i=false al=0},r=1,c=false/true,a=HANDLING, uri=//localhost:8080/pdb/admin/v1/archive,age=352} 2022-10-11T15:57:21.131+02:00 DEBUG [o.e.j.s.HttpOutput] complete(org.eclipse.jetty.util.Callback$3@1aed94ed) s=CLOSED,api=BLOCKING,sc=false,e=null s=true e=null, c=null 2022-10-11T15:57:21.131+02:00 DEBUG [o.e.j.s.HttpChannelState] completed HttpChannelState@23896806{s=HANDLING rs=COMPLETING os=COMPLETED is=IDLE awp=false se=false i=false al=0} 2022-10-11T15:57:21.131+02:00 DEBUG [o.e.j.s.HttpChannelState] unhandle HttpChannelState@23896806{s=HANDLING rs=COMPLETED os=COMPLETED is=IDLE awp=false se=false i=false al=0} 2022-10-11T15:57:21.131+02:00 DEBUG [o.e.j.s.HttpChannelState] nextAction(false) TERMINATED HttpChannelState@23896806{s=IDLE rs=COMPLETED os=COMPLETED is=IDLE awp=false se=false i=false al=0} 2022-10-11T15:57:21.131+02:00 DEBUG [o.e.j.s.HttpChannel] action TERMINATED HttpChannelOverHttp@77c5b5ae{s=HttpChannelState@23896806{s=IDLE rs=COMPLETED os=COMPLETED is=IDLE awp=false se=false i=false al=0},r=1,c=true/true,a=IDLE,uri=// localhost:8080/pdb/admin/v1/archive,age=353} 2022-10-11T15:57:21.131+02:00 DEBUG [o.e.j.s.HttpChannel] onCompleted for /pdb/admin/v1/archive written=256

Add Comment

[Andreas Paul (Jira)]

Andreas Paul commented on PDB-5549

Re: PuppetDB 7.11.1: /pdb/admin/v1/archive returns 257 bytes

I can confirm this also happens with 7.10.1

Add Comment

[Sebastian Döring]

Sebastian Döring commented on PDB-5549

Re: PuppetDB 7.11.1: /pdb/admin/v1/archive returns 257 bytes

Problem still occurs with 7.12.1-1bullseye

Add Comment

[Sebastian Döring]

Sebastian Döring commented on PDB-5549

Re: PuppetDB 7.11.1: /pdb/admin/v1/archive returns 257 bytes

Problem is still observed in 7.13.0-1bullseye

Add Comment

This message was sent by Atlassian Jira (v8.20.21#820021-sha1:38274c8)