Jira (PDB-1880) org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "reports_pkey"

54 views

Skip to first unread message

James Glenn (JIRA)

unread,

Aug 6, 2015, 3:13:07 PM8/6/15

to puppe...@googlegroups.com

James Glenn created an issue

PuppetDB /

PDB-1880

org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "reports_pkey"

Issue Type:	Bug
Affects Versions:	PDB 2.3.6
Assignee:	Unassigned
Created:	2015/08/06 12:12 PM
Environment:	CentOS 7.1.1503 puppet-3.8.1-1.el7.noarch puppetlabs-release-7-11.noarch puppetdb-2.3.6-1.el7.noarch puppet-server-3.8.1-1.el7.noarch puppetdb-terminus-2.3.6-1.el7.noarch postgresql-server-9.2.13-1.el7_1.x86_64 postgresql-contrib-9.2.13-1.el7_1.x86_64 postgresql-9.2.13-1.el7_1.x86_64 postgresql-libs-9.2.13-1.el7_1.x86_64
Priority:	Minor
Reporter:	James Glenn

{{2015-08-06 14:05:37,551 INFO [o.e.j.u.log] Logging initialized @38444ms
2015-08-06 14:05:40,472 INFO [p.t.s.w.jetty9-service] Initializing web server(s).
2015-08-06 14:05:40,485 INFO [p.t.s.w.jetty9-service] Starting web server(s).
2015-08-06 14:05:40,734 INFO [p.t.s.w.jetty9-core] Starting web server.
2015-08-06 14:05:40,739 INFO [o.e.j.s.Server] jetty-9.2.z-SNAPSHOT
2015-08-06 14:05:40,822 INFO [o.e.j.s.ServerConnector] Started ServerConnector@64127516

{HTTP/1.1} {localhost:8080}

2015-08-06 14:05:40,938 INFO [o.e.j.s.ServerConnector] Started ServerConnector@2c46492b

{SSL-HTTP/1.1} {0.0.0.0:8081}

2015-08-06 14:05:40,938 INFO [o.e.j.s.Server] Started @41836ms
2015-08-06 14:05:40,942 WARN [c.p.p.config] The configuration item `url-prefix` in the [global] section is deprecated. It will be removed in the future.
2015-08-06 14:05:41,033 INFO [c.p.p.c.services] PuppetDB version 2.3.6
2015-08-06 14:05:41,184 WARN [c.p.p.s.storage] PostgreSQL DB versions 8.4 - 9.3 are deprecated and won't be supported in the future.
2015-08-06 14:05:41,288 INFO [c.p.p.s.migrate] There are no pending migrations
2015-08-06 14:05:41,290 WARN [c.p.p.s.migrate] Unable to install optimal indexing

We are unable to create optimal indexes for your database.
For maximum index performance, we recommend using PostgreSQL 9.3 or
greater.

2015-08-06 14:05:41,302 INFO [c.p.p.c.services] Starting broker
2015-08-06 14:05:42,324 INFO [o.a.a.s.k.MessageDatabase] KahaDB is version 4
2015-08-06 14:05:42,391 INFO [o.a.a.s.k.MessageDatabase] Recovering from the journal ...
2015-08-06 14:05:42,392 INFO [o.a.a.s.k.MessageDatabase] Recovery replayed 1 operations from the journal in 0.053 seconds.
2015-08-06 14:05:43,021 WARN [o.a.a.b.BrokerService] Store limit is 100000 mb, whilst the data directory: /var/lib/puppetdb/mq/localhost/KahaDB only has 7791 mb of usable space
2015-08-06 14:05:43,022 ERROR [o.a.a.b.BrokerService] Temporary Store limit is 50000 mb, whilst the temporary data directory: /var/lib/puppetdb/mq/localhost/tmp_storage only has 7791 mb of usable space
2015-08-06 14:05:43,023 INFO [c.p.p.c.services] Starting 2 command processor threads
2015-08-06 14:05:43,072 INFO [c.p.p.c.services] Starting query server
2015-08-06 14:05:43,117 WARN [o.e.j.s.h.ContextHandler] Empty contextPath
2015-08-06 14:05:43,166 INFO [o.e.j.s.h.ContextHandler] Started o.e.j.s.h.ContextHandler@195edb4a

{/,null,AVAILABLE}

2015-08-06 14:05:43,214 INFO [c.p.p.c.services] Starting sweep of stale nodes (threshold: 15 days)
2015-08-06 14:05:43,341 INFO [c.p.p.c.services] Finished sweep of stale nodes (threshold: 15 days)
2015-08-06 14:05:43,344 INFO [c.p.p.c.services] Starting purge deactivated nodes (threshold: 30 days)
2015-08-06 14:05:43,449 INFO [c.p.p.c.services] Finished purge deactivated nodes (threshold: 30 days)
2015-08-06 14:05:43,451 INFO [c.p.p.c.services] Starting sweep of stale reports (threshold: 14 days)
2015-08-06 14:05:43,624 INFO [c.p.p.c.services] Finished sweep of stale reports (threshold: 14 days)
2015-08-06 14:05:43,626 INFO [c.p.p.c.services] Starting database garbage collection
2015-08-06 14:05:43,762 INFO [c.p.p.c.services] Newer version 3.0.2 is available! Visit https://docs.puppetlabs.com/puppetdb/3.0/release_notes.html for details.
2015-08-06 14:05:43,807 INFO [c.p.p.c.services] Finished database garbage collection
2015-08-06 14:05:58,640 WARN [c.p.p.h.event-counts] The event-counts endpoint is experimental and may be altered or removed in the future.
2015-08-06 14:06:09,894 INFO [c.p.p.command] [fd6b2738-b606-496c-96f9-ff2a4062a366] [replace facts] dldggraem01.vml.lan
2015-08-06 14:06:14,513 ERROR [c.p.p.command] [5cc540f0-8589-4478-863a-3f41da7791ec] [store report] Retrying after attempt 8, due to: org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "reports_pkey"
Detail: Key (hash)=(6cb10ac4b4be82870db2a709a346fb4a132325cb) already exists.
org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "reports_pkey"
Detail: Key (hash)=(6cb10ac4b4be82870db2a709a346fb4a132325cb) already exists.
at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2157) ~[puppetdb.jar:na]
at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1886) ~[puppetdb.jar:na]
at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:255) ~[puppetdb.jar:na]
at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:555) ~[puppetdb.jar:na]
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:417) ~[puppetdb.jar:na]
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeUpdate(AbstractJdbc2Statement.java:363) ~[puppetdb.jar:na]
at com.jolbox.bonecp.PreparedStatementHandle.executeUpdate(PreparedStatementHandle.java:203) ~[puppetdb.jar:na]
at clojure.java.jdbc.internal$do_prepared_return_keys_STAR_$fn__5838.invoke(internal.clj:337) ~[na:na]
at clojure.java.jdbc.internal$transaction_STAR_.invoke(internal.clj:223) ~[na:na]
at clojure.java.jdbc.internal$do_prepared_return_keys_STAR_.invoke(internal.clj:337) ~[na:na]
at clojure.lang.AFn.applyToHelper(AFn.java:156) ~[puppetdb.jar:na]
at clojure.lang.AFn.applyTo(AFn.java:144) ~[puppetdb.jar:na]
at clojure.core$apply.invoke(core.clj:626) ~[puppetdb.jar:na]
at clojure.java.jdbc$insert_values.doInvoke(jdbc.clj:263) ~[na:na]
at clojure.lang.RestFn.invoke(RestFn.java:442) ~[puppetdb.jar:na]
at clojure.java.jdbc$insert_records$ins_v__5906.invoke(jdbc.clj:278) ~[na:na]
at clojure.core$map$fn__4245.invoke(core.clj:2559) ~[puppetdb.jar:na]
at clojure.lang.LazySeq.sval(LazySeq.java:40) ~[puppetdb.jar:na]
at clojure.lang.LazySeq.seq(LazySeq.java:49) ~[puppetdb.jar:na]
at clojure.lang.RT.seq(RT.java:484) ~[puppetdb.jar:na]
at clojure.core$seq.invoke(core.clj:133) ~[puppetdb.jar:na]
at clojure.core$dorun.invoke(core.clj:2855) ~[puppetdb.jar:na]
at clojure.core$doall.invoke(core.clj:2871) ~[puppetdb.jar:na]
at clojure.java.jdbc$insert_records.doInvoke(jdbc.clj:279) ~[na:na]
at clojure.lang.RestFn.invoke(RestFn.java:423) ~[puppetdb.jar:na]
at clojure.java.jdbc$insert_record.invoke(jdbc.clj:286) ~[na:na]
at com.puppetlabs.puppetdb.scf.storage$add_report_BANG_STAR$fn_9641$fn_9645.invoke(storage.clj:1104) ~[na:na]
at clojure.java.jdbc.internal$transaction_STAR_.invoke(internal.clj:223) ~[na:na]
at com.puppetlabs.puppetdb.scf.storage$add_report_BANG_STAR$fn__9641.invoke(storage.clj:1094) ~[na:na]
at com.puppetlabs.puppetdb.scf.storage.proxy$java.lang.Object$Callable$7da976d4.call(Unknown Source) ~[na:na]
at com.yammer.metrics.core.Timer.time(Timer.java:91) ~[puppetdb.jar:na]
at com.puppetlabs.puppetdb.scf.storage$add_report_BANG_STAR.invoke(storage.clj:1088) ~[na:na]
at com.puppetlabs.puppetdb.scf.storage$eval9812$add_report_BANG__9813$fn_9814.invoke(storage.clj:1221) ~[na:na]
at com.puppetlabs.puppetdb.scf.storage$eval9812$add_report_BANG___9813.invoke(storage.clj:1217) ~[na:na]
at com.puppetlabs.puppetdb.command$store_report_STAR_$fn__13416.invoke(command.clj:413) ~[na:na]
at com.puppetlabs.jdbc$with_transacted_connection_fn$fn_6256$fn6257$fn_6258.invoke(jdbc.clj:290) ~[na:na]
at clojure.java.jdbc.internal$transaction_STAR_.invoke(internal.clj:204) ~[na:na]
at com.puppetlabs.jdbc$with_transacted_connection_fn$fn_6256$fn_6257.invoke(jdbc.clj:290) ~[na:na]
at clojure.java.jdbc.internal$with_connection_STAR_.invoke(internal.clj:186) ~[na:na]
at com.puppetlabs.jdbc$with_transacted_connection_fn$fn__6256.invoke(jdbc.clj:287) ~[na:na]
at com.puppetlabs.jdbc$eval6234$retry_sql_STAR__6235$fn6236$fn_6237.invoke(jdbc.clj:259) ~[na:na]
at com.puppetlabs.jdbc$eval6234$retry_sql_STAR__6235$fn_6236.invoke(jdbc.clj:258) ~[na:na]
at com.puppetlabs.jdbc$eval6234$retry_sql_STAR___6235.invoke(jdbc.clj:250) ~[na:na]
at com.puppetlabs.jdbc$with_transacted_connection_fn.invoke(jdbc.clj:286) ~[na:na]
at com.puppetlabs.puppetdb.command$store_report_STAR_.invoke(command.clj:411) ~[na:na]
at com.puppetlabs.puppetdb.command$eval13444$fn__13447.invoke(command.clj:434) ~[na:na]
at clojure.lang.MultiFn.invoke(MultiFn.java:231) ~[puppetdb.jar:na]
at com.puppetlabs.puppetdb.command$produce_message_handler$fn__13528.invoke(command.clj:647) ~[na:na]
at com.puppetlabs.puppetdb.command$wrap_with_discard$fn_13477$fn_13481.invoke(command.clj:554) ~[na:na]
at com.puppetlabs.puppetdb.command.proxy$java.lang.Object$Callable$7da976d4.call(Unknown Source) ~[na:na]
at com.yammer.metrics.core.Timer.time(Timer.java:91) ~[puppetdb.jar:na]
at com.puppetlabs.puppetdb.command$wrap_with_discard$fn__13477.invoke(command.clj:553) ~[na:na]
at com.puppetlabs.puppetdb.command$wrap_with_exception_handling$fn_13462$fn_13463.invoke(command.clj:507) ~[na:na]
at com.puppetlabs.puppetdb.command.proxy$java.lang.Object$Callable$7da976d4.call(Unknown Source) ~[na:na]
at com.yammer.metrics.core.Timer.time(Timer.java:91) ~[puppetdb.jar:na]
at com.puppetlabs.puppetdb.command$wrap_with_exception_handling$fn__13462.invoke(command.clj:506) ~[na:na]
at com.puppetlabs.puppetdb.command$wrap_with_command_parser$fn__13472.invoke(command.clj:529) [na:na]
at com.puppetlabs.puppetdb.command$wrap_with_meter$fn__13452.invoke(command.clj:467) [na:na]
at com.puppetlabs.puppetdb.command$wrap_with_thread_name$fn__13486.invoke(command.clj:569) [na:na]
at com.puppetlabs.mq$create_message_listener$reify__10371.onMessage(mq.clj:277) [na:na]
at org.springframework.jms.listener.AbstractMessageListenerContainer.doInvokeListener(AbstractMessageListenerContainer.java:560) [puppetdb.jar:na]
at org.springframework.jms.listener.AbstractMessageListenerContainer.invokeListener(AbstractMessageListenerContainer.java:498) [puppetdb.jar:na]
at org.springframework.jms.listener.AbstractMessageListenerContainer.doExecuteListener(AbstractMessageListenerContainer.java:467) [puppetdb.jar:na]
at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.doReceiveAndExecute(AbstractPollingMessageListenerContainer.java:325) [puppetdb.jar:na]
at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute(AbstractPollingMessageListenerContainer.java:263) [puppetdb.jar:na]
at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.invokeListener(DefaultMessageListenerContainer.java:1058) [puppetdb.jar:na]
at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.executeOngoingLoop(DefaultMessageListenerContainer.java:1050) [puppetdb.jar:na]
at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:947) [puppetdb.jar:na]
at java.lang.Thread.run(Thread.java:745) [na:1.7.0_85]
}}

Add Comment

This message was sent by Atlassian JIRA (v6.4.5#64020-sha1:78acd6c)

James Glenn (JIRA)

unread,

Aug 6, 2015, 3:13:09 PM8/6/15

to puppe...@googlegroups.com

James Glenn commented on

PDB-1880

Re: org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "reports_pkey"

Please let me know if anyone needs more info.

Add Comment

Wyatt Alt (JIRA)

unread,

Aug 6, 2015, 4:03:05 PM8/6/15

to puppe...@googlegroups.com

Wyatt Alt commented on

PDB-1880

Re: org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "reports_pkey"

James Glenn That's interesting. Probably apparent from the message, but it indicates that a report that you've successfully stored in PDB ended up back in the queue somehow. Just to get the ball rolling, can you confirm the following?

does your setup contain a single PuppetDB instance or multiple? Same question for Puppet masters.
have you recently used the import tool (or other bulk loading tool) to get data into PuppetDB?
is this an isolated occurrence or do you have similar conflicts for other reports?

could you curl the PDB reports endpoint to get the report in question, and report if anything looks odd about it (if you're willing to share it that would be optimal. This ticket is public but you can send it to me wy...@puppetlabs.com to share privately.) You can get the report with

curl -X GET http://localhost:8080/v4/reports -d 'query=["=","hash","6cb10ac4b4be82870db2a709a346fb4a132325cb"]'

ditto for the events associated with the report:

curl -X GET http://localhost:8080/v4/events -d 'query=["=","report","6cb10ac4b4be82870db2a709a346fb4a132325cb"]'

I'm interested in whether either of these calls return objects with null or empty fields.

would you mind sharing your full puppetdb.log file with me at the email address above? I'd like to see the full history of command retries and see if I can correlate it with anything else in the log.

Wyatt

Add Comment

James Glenn (JIRA)

unread,

Aug 6, 2015, 4:48:04 PM8/6/15

to puppe...@googlegroups.com

James Glenn commented on

PDB-1880

Re: org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "reports_pkey"

> does your setup contain a single PuppetDB instance or multiple? Same question for Puppet masters.

Single puppetdb server and single puppet master server.

> have you recently used the import tool (or other bulk loading tool) to get data into PuppetDB?

No.

> is this an isolated occurrence or do you have similar conflicts for other reports?

Seems to be limited to Key (hash)=(6cb10ac4b4be82870db2a709a346fb4a132325cb)

[root@plvmlinfra01 ~]# curl -X GET http://localhost:8080/v4/reports -d 'query=["=","hash","6cb10ac4b4be82870db2a709a346fb4a132325cb"]'

[ {

  "hash" : "6cb10ac4b4be82870db2a709a346fb4a132325cb",

  "puppet-version" : "3.8.1",

  "receive-time" : "2015-08-06T05:08:55.507Z",

  "report-format" : 4,

  "start-time" : "2015-08-06T04:34:51.035Z",

  "end-time" : "2015-08-06T04:35:06.526Z",

  "transaction-uuid" : "359c31b5-3a90-46b7-8bcc-23a3ead185cf",

  "status" : "unchanged",

  "environment" : "production",

  "configuration-version" : "1438832846",

  "certname" : "dwccruises01.vml.lan"

} ][root@plvmlinfra01 ~]# curl -X GET http://localhost:8080/v4/events -d 'query=["=","report","6cb10ac4b4be82870db2a709a346fb4a132325cb"]'

[ ][root@plvmlinfra01 ~]#

puppetdb.log will be in the mail shortly.

Add Comment

Wyatt Alt (JIRA)

unread,

Aug 6, 2015, 6:20:04 PM8/6/15

to puppe...@googlegroups.com

Wyatt Alt commented on

PDB-1880

Re: org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "reports_pkey"

James Glenn Thanks for the log. I see a 1hr gap in command processing starting at 2015-08-04 18:31:55,089 and ending at 2015-08-04 18:37:35,904 (with a GC happening right in the middle). The first logged failure occurs at 2015-08-04 19:07:35,139, which is 64 seconds after command processing resumes.

None of your other GC's look like that. Do you have any idea why PDB wouldn't have been processing commands during that time period?

Add Comment

James Glenn (JIRA)

unread,

Aug 7, 2015, 1:59:06 AM8/7/15

to puppe...@googlegroups.com

James Glenn commented on

PDB-1880

Re: org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "reports_pkey"

No clue. Nothing about the environment should cause that.

puppetdb configs:

[global]

# Store mq/db data in a custom directory

vardir = /var/lib/puppetdb

# Use an external logback config file

logging-config = /etc/puppetdb/logback.xml

[command-processing]

# How many command-processing threads to use, defaults to (CPUs / 2)

# threads = 4

# Maximum amount of disk space (in MB) to allow for ActiveMQ persistent message storage

# store-usage = 102400

# Maximum amount of disk space (in MB) to allow for ActiveMQ temporary message storage

# temp-usage = 51200

[database]

# For the embedded DB: org.hsqldb.jdbcDriver

# For PostgreSQL: org.postgresql.Driver

# Defaults to embedded DB

classname = org.postgresql.Driver

# For the embedded DB: hsqldb

# For PostgreSQL: postgresql

# Defaults to embedded DB

subprotocol = postgresql

# For the embedded DB: file:/path/to/database;hsqldb.tx=mvcc;sql.syntax_pgs=true

# For PostgreSQL: //host:port/databaseName

# Defaults to embedded DB located in <vardir>/db

# subname = file:/var/lib/puppetdb/db/db;hsqldb.tx=mvcc;sql.syntax_pgs=true

subname = //127.0.0.1:5432/puppetdb

# Connect as a specific user

username = puppetdb

# Use a specific password

password = <redacted>

# How often (in minutes) to compact the database

gc-interval = 60

# Number of seconds before any SQL query is considered 'slow'; offending

# queries will not be interrupted, but will be logged at the WARN log level.

log-slow-statements = 10

node-ttl = 15d

node-purge-ttl = 30d

[jetty]

# IP address or hostname to listen for clear-text HTTP. To avoid resolution

# issues, IP addresses are recommended over hostnames.

# Default is `localhost`.

# host = <host>

# Port to listen on for clear-text HTTP.

port = 8080

# The following are SSL specific settings. They can be configured

# automatically with the tool `puppetdb ssl-setup`, which is normally

# ran during package installation.

# IP address to listen on for HTTPS connections. Hostnames can also be used

# but are not recommended to avoid DNS resolution issues. To listen on all

# interfaces, use `0.0.0.0`.

ssl-host = 0.0.0.0

# The port to listen on for HTTPS connections

ssl-port = 8081

# Private key path

ssl-key = /etc/puppetdb/ssl/private.pem

# Public certificate path

ssl-cert = /etc/puppetdb/ssl/public.pem

# Certificate authority path

ssl-ca-cert = /etc/puppetdb/ssl/ca.pem

[repl]

# Set to true to enable the remote REPL

enabled = false

# Either nrepl or swank or telnet

type = nrepl

# What port the REPL should listen on

port = 8082

Add Comment

Wyatt Alt (JIRA)

unread,

Aug 10, 2015, 12:49:06 PM8/10/15

to puppe...@googlegroups.com

Wyatt Alt commented on

PDB-1880

Re: org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "reports_pkey"

James Glenn Strange. Without much else to go on I'm suspecting some kind of unspecific AMQ hiccup. It's not something I can reproduce locally. The issue shouldn't cause problems if it's just a one-time thing, and we've already made significant changes to our AMQ setup in the 3.x series, so there's a chance it's been fixed. Would you mind just keeping an eye out for a repeat occurrence, and in the meantime we'll sit on this?

Wyatt