[PDB-1362] puppetdb crashes after upgrade Created: 2015/03/31  Updated: 2015/05/06  Resolved: 2015/04/01

Status: Closed
Project: PuppetDB
Component/s: None
Affects Version/s: PDB 2.3.0, PDB 2.3.1
Fix Version/s: PDB 2.3.2

Type: Bug Priority: Major
Reporter: Pete Brown Assignee: Unassigned
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Template:
Story Points: 1
Sprint: PuppetDB 2015-04-08
QA Contact: Kurt Wall

 Description   

Hi Gang,

I just upgraded to PuppetDB 2.3.1 from 2.3.0 in my development environment and PuppetDB crashed on restart.

If you need more information let me know.

The resulting log messages.
2015-04-01 08:44:51,294 INFO [o.e.j.u.log] Logging initialized @24441ms
2015-04-01 08:44:52,110 INFO [p.t.s.w.jetty9-core] Removing buggy security provider SunPKCS11-NSS version 1.7
2015-04-01 08:44:52,636 INFO [p.t.s.w.jetty9-service] Initializing web server(s).
2015-04-01 08:44:52,642 INFO [p.t.s.w.jetty9-service] Starting web server(s).
2015-04-01 08:44:52,818 INFO [p.t.s.w.jetty9-core] Starting web server.
2015-04-01 08:44:52,822 INFO [o.e.j.s.Server] jetty-9.2.z-SNAPSHOT
2015-04-01 08:44:52,874 INFO [o.e.j.s.ServerConnector] Started ServerConnector@66ace155

{HTTP/1.1}{localhost:8080}
2015-04-01 08:44:53,150 INFO [o.e.j.s.ServerConnector] Started ServerConnector@7f17e429{SSL-HTTP/1.1}{0.0.0.0:8081}
2015-04-01 08:44:53,151 INFO [o.e.j.s.Server] Started @26300ms
2015-04-01 08:44:53,228 INFO [c.p.p.c.services] PuppetDB version 2.3.1
2015-04-01 08:44:53,362 INFO [c.p.p.s.migrate] Applying database migration version 28
2015-04-01 08:44:53,396 ERROR [c.p.p.s.migrate] Caught SQLException during migration
java.sql.BatchUpdateException: Batch entry 5 DELETE FROM fact_paths t1
WHERE t1.id <> (SELECT MIN(t2.id) FROM fact_paths t2
WHERE t1.path = t2.path) was aborted. Call getNextException to see the cause.
at org.postgresql.jdbc2.AbstractJdbc2Statement$BatchResultHandler.handleError(AbstractJdbc2Statement.java:2746) ~[puppetdb.jar:na]
at org.postgresql.core.v3.QueryExecutorImpl$1.handleError(QueryExecutorImpl.java:457) ~[puppetdb.jar:na]
at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1887) ~[puppetdb.jar:na]
at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:405) ~[puppetdb.jar:na]
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeBatch(AbstractJdbc2Statement.java:2893) ~[puppetdb.jar:na]
at com.jolbox.bonecp.StatementHandle.executeBatch(StatementHandle.java:469) ~[puppetdb.jar:na]
at clojure.java.jdbc$do_commands$fn__7301.invoke(jdbc.clj:188) ~[na:na]
at clojure.java.jdbc.internal$transaction_STAR_.invoke(internal.clj:223) [na:na]
at clojure.java.jdbc$do_commands.doInvoke(jdbc.clj:187) ~[na:na]
at clojure.lang.RestFn.invoke(RestFn.java:3894) [puppetdb.jar:na]
at com.puppetlabs.puppetdb.scf.migrate$lift_fact_paths_into_facts.invoke(migrate.clj:968) ~[na:na]
at com.puppetlabs.puppetdb.scf.migrate$migrate_BANG_$fn_20902$fn_20915.invoke(migrate.clj:1063) ~[na:na]
at com.puppetlabs.puppetdb.scf.migrate$migrate_BANG_$fn__20902.invoke(migrate.clj:1062) [na:na]
at clojure.java.jdbc.internal$transaction_STAR_.invoke(internal.clj:204) [na:na]
at com.puppetlabs.puppetdb.scf.migrate$migrate_BANG_.invoke(migrate.clj:1059) [na:na]
at com.puppetlabs.puppetdb.cli.services$start_puppetdb$fn__21109.invoke(services.clj:292) [na:na]
at clojure.java.jdbc.internal$with_connection_STAR_.invoke(internal.clj:186) [na:na]
at com.puppetlabs.puppetdb.cli.services$start_puppetdb.invoke(services.clj:290) [na:na]
at com.puppetlabs.puppetdb.cli.services$reify_21157$service_fnk18232auto_positional$reify_21168.start(services.clj:366) [na:na]
at puppetlabs.trapperkeeper.services$eval18068$fn_18082$G18058_18085.invoke(services.clj:10) [na:na]
at puppetlabs.trapperkeeper.services$eval18068$fn_18082$G18057_18089.invoke(services.clj:10) [na:na]
at puppetlabs.trapperkeeper.internal$run_lifecycle_fn_BANG_.invoke(internal.clj:154) [na:na]
at puppetlabs.trapperkeeper.internal$run_lifecycle_fns.invoke(internal.clj:182) [na:na]
at puppetlabs.trapperkeeper.internal$build_app_STAR_$reify__18905.start(internal.clj:449) [na:na]
at puppetlabs.trapperkeeper.internal$boot_services_STAR_$fn__18917.invoke(internal.clj:473) [na:na]
at puppetlabs.trapperkeeper.internal$boot_services_STAR_.invoke(internal.clj:471) [na:na]
at puppetlabs.trapperkeeper.core$boot_with_cli_data.invoke(core.clj:113) [na:na]
at puppetlabs.trapperkeeper.core$run.invoke(core.clj:144) [na:na]
at puppetlabs.trapperkeeper.core$main.doInvoke(core.clj:159) [na:na]
at clojure.lang.RestFn.applyTo(RestFn.java:137) [puppetdb.jar:na]
at clojure.core$apply.invoke(core.clj:624) [puppetdb.jar:na]
at com.puppetlabs.puppetdb.cli.services$_main.doInvoke(services.clj:373) [na:na]
at clojure.lang.RestFn.invoke(RestFn.java:421) [puppetdb.jar:na]
at clojure.lang.Var.invoke(Var.java:383) [puppetdb.jar:na]
at clojure.lang.AFn.applyToHelper(AFn.java:156) [puppetdb.jar:na]
at clojure.lang.Var.applyTo(Var.java:700) [puppetdb.jar:na]
at clojure.core$apply.invoke(core.clj:624) [puppetdb.jar:na]
at com.puppetlabs.puppetdb.core$run_command.invoke(core.clj:87) [na:na]
at com.puppetlabs.puppetdb.core$_main.doInvoke(core.clj:95) [na:na]
at clojure.lang.RestFn.invoke(RestFn.java:436) [puppetdb.jar:na]
at clojure.lang.Var.invoke(Var.java:388) [puppetdb.jar:na]
at clojure.lang.AFn.applyToHelper(AFn.java:160) [puppetdb.jar:na]
at clojure.lang.Var.applyTo(Var.java:700) [puppetdb.jar:na]
at clojure.core$apply.invoke(core.clj:624) [puppetdb.jar:na]
at clojure.main$main_opt.invoke(main.clj:315) [puppetdb.jar:na]
at clojure.main$main.doInvoke(main.clj:420) [puppetdb.jar:na]
at clojure.lang.RestFn.invoke(RestFn.java:482) [puppetdb.jar:na]
at clojure.lang.Var.invoke(Var.java:401) [puppetdb.jar:na]
at clojure.lang.AFn.applyToHelper(AFn.java:171) [puppetdb.jar:na]
at clojure.lang.Var.applyTo(Var.java:700) [puppetdb.jar:na]
at clojure.main.main(main.java:37) [puppetdb.jar:na]
2015-04-01 08:44:53,398 ERROR [c.p.p.s.migrate] Unravelled exception
org.postgresql.util.PSQLException: ERROR: update or delete on table "fact_paths" violates foreign key constraint "fact_values_path_id_fk" on table "fact_values"
Detail: Key (id)=(452) is still referenced from table "fact_values".
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:405) ~[puppetdb.jar:na]
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeBatch(AbstractJdbc2Statement.java:2893) ~[puppetdb.jar:na]
at com.jolbox.bonecp.StatementHandle.executeBatch(StatementHandle.java:469) ~[puppetdb.jar:na]
at clojure.java.jdbc$do_commands$fn__7301.invoke(jdbc.clj:188) ~[na:na]
at clojure.java.jdbc.internal$transaction_STAR_.invoke(internal.clj:223) [na:na]
at clojure.java.jdbc$do_commands.doInvoke(jdbc.clj:187) ~[na:na]
at clojure.lang.RestFn.invoke(RestFn.java:3894) [puppetdb.jar:na]
at com.puppetlabs.puppetdb.scf.migrate$lift_fact_paths_into_facts.invoke(migrate.clj:968) ~[na:na]
at com.puppetlabs.puppetdb.scf.migrate$migrate_BANG_$fn_20902$fn_20915.invoke(migrate.clj:1063) ~[na:na]
at com.puppetlabs.puppetdb.scf.migrate$migrate_BANG_$fn__20902.invoke(migrate.clj:1062) [na:na]
at clojure.java.jdbc.internal$transaction_STAR_.invoke(internal.clj:204) [na:na]
at com.puppetlabs.puppetdb.scf.migrate$migrate_BANG_.invoke(migrate.clj:1059) [na:na]
at com.puppetlabs.puppetdb.cli.services$start_puppetdb$fn__21109.invoke(services.clj:292) [na:na]
at clojure.java.jdbc.internal$with_connection_STAR_.invoke(internal.clj:186) [na:na]
at com.puppetlabs.puppetdb.cli.services$start_puppetdb.invoke(services.clj:290) [na:na]
at com.puppetlabs.puppetdb.cli.services$reify_21157$service_fnk18232auto_positional$reify_21168.start(services.clj:366) [na:na]
at puppetlabs.trapperkeeper.services$eval18068$fn_18082$G18058_18085.invoke(services.clj:10) [na:na]
at puppetlabs.trapperkeeper.services$eval18068$fn_18082$G18057_18089.invoke(services.clj:10) [na:na]
at puppetlabs.trapperkeeper.internal$run_lifecycle_fn_BANG_.invoke(internal.clj:154) [na:na]
at puppetlabs.trapperkeeper.internal$run_lifecycle_fns.invoke(internal.clj:182) [na:na]
at puppetlabs.trapperkeeper.internal$build_app_STAR_$reify__18905.start(internal.clj:449) [na:na]
at puppetlabs.trapperkeeper.internal$boot_services_STAR_$fn__18917.invoke(internal.clj:473) [na:na]
at puppetlabs.trapperkeeper.internal$boot_services_STAR_.invoke(internal.clj:471) [na:na]
at puppetlabs.trapperkeeper.core$boot_with_cli_data.invoke(core.clj:113) [na:na]
at puppetlabs.trapperkeeper.core$run.invoke(core.clj:144) [na:na]
at puppetlabs.trapperkeeper.core$main.doInvoke(core.clj:159) [na:na]
at clojure.lang.RestFn.applyTo(RestFn.java:137) [puppetdb.jar:na]
at clojure.core$apply.invoke(core.clj:624) [puppetdb.jar:na]
at com.puppetlabs.puppetdb.cli.services$_main.doInvoke(services.clj:373) [na:na]
at clojure.lang.RestFn.invoke(RestFn.java:421) [puppetdb.jar:na]
at clojure.lang.Var.invoke(Var.java:383) [puppetdb.jar:na]
at clojure.lang.AFn.applyToHelper(AFn.java:156) [puppetdb.jar:na]
at clojure.lang.Var.applyTo(Var.java:700) [puppetdb.jar:na]
at clojure.core$apply.invoke(core.clj:624) [puppetdb.jar:na]
at com.puppetlabs.puppetdb.core$run_command.invoke(core.clj:87) [na:na]
at com.puppetlabs.puppetdb.core$_main.doInvoke(core.clj:95) [na:na]
at clojure.lang.RestFn.invoke(RestFn.java:436) [puppetdb.jar:na]
at clojure.lang.Var.invoke(Var.java:388) [puppetdb.jar:na]
at clojure.lang.AFn.applyToHelper(AFn.java:160) [puppetdb.jar:na]
at clojure.lang.Var.applyTo(Var.java:700) [puppetdb.jar:na]
at clojure.core$apply.invoke(core.clj:624) [puppetdb.jar:na]
at clojure.main$main_opt.invoke(main.clj:315) [puppetdb.jar:na]
at clojure.main$main.doInvoke(main.clj:420) [puppetdb.jar:na]
at clojure.lang.RestFn.invoke(RestFn.java:482) [puppetdb.jar:na]
at clojure.lang.Var.invoke(Var.java:401) [puppetdb.jar:na]
at clojure.lang.AFn.applyToHelper(AFn.java:171) [puppetdb.jar:na]
at clojure.lang.Var.applyTo(Var.java:700) [puppetdb.jar:na]
at clojure.main.main(main.java:37) [puppetdb.jar:na]
2015-04-01 08:44:53,403 INFO [p.t.internal] Shutting down due to JVM shutdown hook.
2015-04-01 08:44:53,404 INFO [p.t.internal] Beginning shutdown sequence
2015-04-01 08:44:53,406 INFO [c.p.p.c.services] Shutdown request received; puppetdb exiting.
2015-04-01 08:44:53,406 INFO [p.t.s.w.jetty9-service] Shutting down web server(s).
2015-04-01 08:44:53,407 INFO [p.t.s.w.jetty9-core] Shutting down web server.
2015-04-01 08:44:53,414 INFO [o.e.j.s.ServerConnector] Stopped ServerConnector@66ace155{HTTP/1.1} {localhost:8080}

2015-04-01 08:44:53,420 INFO [o.e.j.s.ServerConnector] Stopped ServerConnector@7f17e429

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

2015-04-01 08:44:53,422 INFO [p.t.s.w.jetty9-core] Web server shutdown
2015-04-01 08:44:53,423 INFO [p.t.internal] Finished shutdown sequence


QA Risk Analysis

Probability Low
Severity Med (puppetdb crash
Risk Level Low
Test Level Unit


 Comments   
Comment by Wyatt Alt [ 2015/03/31 ]

Pete Brown can you tell us what the operating system is and how many nodes you have? Also is there anything in your postgres logs that you can correlate to the crash?

Wyatt

Comment by Wyatt Alt [ 2015/03/31 ]

Pete Brown my guess is that running the following two queries on a 2.3.0 database will permit the upgrade:

delete from fact_values where id not in (select distinct fact_value_id from facts);
delete from fact_paths where id not in (select path_id from fact_values);

if you're up for trying it we'd be interested to know if it does the trick. Otherwise thanks for reporting this issue – we're on it and will keep you posted.

Comment by Pete Brown [ 2015/03/31 ]

Hi Wyatt.

Damn. Sorry I forgot to add that.

Operating system is Ubuntu 14.04, PostgresSQL version is 9.3.
I manage my Dev environment with the same code as my live server and I just noticed postgresql-contrib wasn't installed and pg_trgm isn't setup on the puppetdb database.
I added that and added the extension to the puppetdb database but upgrade still doesn't work.

I shall try your suggested fix and let you know how it goes.

PostgreSQL logs have this in it which seems pretty relevant.
2015-04-01 08:44:53 AEST ERROR: update or delete on table "fact_paths" violates foreign key constraint "fact_values_path_id_fk" on table "fact_values"
2015-04-01 08:44:53 AEST DETAIL: Key (id)=(452) is still referenced from table "fact_values".
2015-04-01 08:44:53 AEST STATEMENT: DELETE FROM fact_paths t1
WHERE t1.id <> (SELECT MIN(t2.id) FROM fact_paths t2
WHERE t1.path = t2.path)

Comment by Pete Brown [ 2015/03/31 ]

On a side note I was able to downgrade to 2.3.0 and it works again.

I ran these two queries
delete from fact_values where id not in (select distinct fact_value_id from facts);
delete from fact_paths where id not in (select path_id from fact_values);
and started up puppetdb but it's still not starting

These are the errors I got in the logs this time

2015-04-01 09:35:21,808 INFO [c.p.p.c.services] PuppetDB version 2.3.1
2015-04-01 09:35:21,956 INFO [c.p.p.s.migrate] Applying database migration version 28
2015-04-01 09:35:21,988 ERROR [c.p.p.s.migrate] Caught SQLException during migration
java.sql.BatchUpdateException: Batch entry 5 DELETE FROM fact_paths t1
WHERE t1.id <> (SELECT MIN(t2.id) FROM fact_paths t2
WHERE t1.path = t2.path) was aborted. Call getNextException to see the cause.
at org.postgresql.jdbc2.AbstractJdbc2Statement$BatchResultHandler.handleError(AbstractJdbc2Statement.java:2746) ~[puppetdb.jar:na]
at org.postgresql.core.v3.QueryExecutorImpl$1.handleError(QueryExecutorImpl.java:457) ~[puppetdb.jar:na]
at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1887) ~[puppetdb.jar:na]
at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:405) ~[puppetdb.jar:na]
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeBatch(AbstractJdbc2Statement.java:2893) ~[puppetdb.jar:na]
at com.jolbox.bonecp.StatementHandle.executeBatch(StatementHandle.java:469) ~[puppetdb.jar:na]
at clojure.java.jdbc$do_commands$fn__7301.invoke(jdbc.clj:188) ~[na:na]
at clojure.java.jdbc.internal$transaction_STAR_.invoke(internal.clj:223) [na:na]
at clojure.java.jdbc$do_commands.doInvoke(jdbc.clj:187) ~[na:na]
at clojure.lang.RestFn.invoke(RestFn.java:3894) [puppetdb.jar:na]
at com.puppetlabs.puppetdb.scf.migrate$lift_fact_paths_into_facts.invoke(migrate.clj:968) ~[na:na]
at com.puppetlabs.puppetdb.scf.migrate$migrate_BANG_$fn_20902$fn_20915.invoke(migrate.clj:1063) ~[na:na]
at com.puppetlabs.puppetdb.scf.migrate$migrate_BANG_$fn__20902.invoke(migrate.clj:1062) [na:na]
at clojure.java.jdbc.internal$transaction_STAR_.invoke(internal.clj:204) [na:na]
at com.puppetlabs.puppetdb.scf.migrate$migrate_BANG_.invoke(migrate.clj:1059) [na:na]
at com.puppetlabs.puppetdb.cli.services$start_puppetdb$fn__21109.invoke(services.clj:292) [na:na]
at clojure.java.jdbc.internal$with_connection_STAR_.invoke(internal.clj:186) [na:na]
at com.puppetlabs.puppetdb.cli.services$start_puppetdb.invoke(services.clj:290) [na:na]
at com.puppetlabs.puppetdb.cli.services$reify_21157$service_fnk18232auto_positional$reify_21168.start(services.clj:366) [na:na]
at puppetlabs.trapperkeeper.services$eval18068$fn_18082$G18058_18085.invoke(services.clj:10) [na:na]
at puppetlabs.trapperkeeper.services$eval18068$fn_18082$G18057_18089.invoke(services.clj:10) [na:na]
at puppetlabs.trapperkeeper.internal$run_lifecycle_fn_BANG_.invoke(internal.clj:154) [na:na]
at puppetlabs.trapperkeeper.internal$run_lifecycle_fns.invoke(internal.clj:182) [na:na]
at puppetlabs.trapperkeeper.internal$build_app_STAR_$reify__18905.start(internal.clj:449) [na:na]
at puppetlabs.trapperkeeper.internal$boot_services_STAR_$fn__18917.invoke(internal.clj:473) [na:na]
at puppetlabs.trapperkeeper.internal$boot_services_STAR_.invoke(internal.clj:471) [na:na]
at puppetlabs.trapperkeeper.core$boot_with_cli_data.invoke(core.clj:113) [na:na]
at puppetlabs.trapperkeeper.core$run.invoke(core.clj:144) [na:na]
at puppetlabs.trapperkeeper.core$main.doInvoke(core.clj:159) [na:na]
at clojure.lang.RestFn.applyTo(RestFn.java:137) [puppetdb.jar:na]
at clojure.core$apply.invoke(core.clj:624) [puppetdb.jar:na]
at com.puppetlabs.puppetdb.cli.services$_main.doInvoke(services.clj:373) [na:na]
at clojure.lang.RestFn.invoke(RestFn.java:421) [puppetdb.jar:na]
at clojure.lang.Var.invoke(Var.java:383) [puppetdb.jar:na]
at clojure.lang.AFn.applyToHelper(AFn.java:156) [puppetdb.jar:na]
at clojure.lang.Var.applyTo(Var.java:700) [puppetdb.jar:na]
at clojure.core$apply.invoke(core.clj:624) [puppetdb.jar:na]
at com.puppetlabs.puppetdb.core$run_command.invoke(core.clj:87) [na:na]
at com.puppetlabs.puppetdb.core$_main.doInvoke(core.clj:95) [na:na]
at clojure.lang.RestFn.invoke(RestFn.java:436) [puppetdb.jar:na]
at clojure.lang.Var.invoke(Var.java:388) [puppetdb.jar:na]
at clojure.lang.AFn.applyToHelper(AFn.java:160) [puppetdb.jar:na]
at clojure.lang.Var.applyTo(Var.java:700) [puppetdb.jar:na]
at clojure.core$apply.invoke(core.clj:624) [puppetdb.jar:na]
at clojure.main$main_opt.invoke(main.clj:315) [puppetdb.jar:na]
at clojure.main$main.doInvoke(main.clj:420) [puppetdb.jar:na]
at clojure.lang.RestFn.invoke(RestFn.java:482) [puppetdb.jar:na]
at clojure.lang.Var.invoke(Var.java:401) [puppetdb.jar:na]
at clojure.lang.AFn.applyToHelper(AFn.java:171) [puppetdb.jar:na]
at clojure.lang.Var.applyTo(Var.java:700) [puppetdb.jar:na]
at clojure.main.main(main.java:37) [puppetdb.jar:na]
2015-04-01 09:35:21,990 ERROR [c.p.p.s.migrate] Unravelled exception
org.postgresql.util.PSQLException: ERROR: update or delete on table "fact_paths" violates foreign key constraint "fact_values_path_id_fk" on table "fact_values"
Detail: Key (id)=(452) is still referenced from table "fact_values".
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:405) ~[puppetdb.jar:na]
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeBatch(AbstractJdbc2Statement.java:2893) ~[puppetdb.jar:na]
at com.jolbox.bonecp.StatementHandle.executeBatch(StatementHandle.java:469) ~[puppetdb.jar:na]
at clojure.java.jdbc$do_commands$fn__7301.invoke(jdbc.clj:188) ~[na:na]
at clojure.java.jdbc.internal$transaction_STAR_.invoke(internal.clj:223) [na:na]
at clojure.java.jdbc$do_commands.doInvoke(jdbc.clj:187) ~[na:na]
at clojure.lang.RestFn.invoke(RestFn.java:3894) [puppetdb.jar:na]
at com.puppetlabs.puppetdb.scf.migrate$lift_fact_paths_into_facts.invoke(migrate.clj:968) ~[na:na]
at com.puppetlabs.puppetdb.scf.migrate$migrate_BANG_$fn_20902$fn_20915.invoke(migrate.clj:1063) ~[na:na]
at com.puppetlabs.puppetdb.scf.migrate$migrate_BANG_$fn__20902.invoke(migrate.clj:1062) [na:na]
at clojure.java.jdbc.internal$transaction_STAR_.invoke(internal.clj:204) [na:na]
at com.puppetlabs.puppetdb.scf.migrate$migrate_BANG_.invoke(migrate.clj:1059) [na:na]
at com.puppetlabs.puppetdb.cli.services$start_puppetdb$fn__21109.invoke(services.clj:292) [na:na]
at clojure.java.jdbc.internal$with_connection_STAR_.invoke(internal.clj:186) [na:na]
at com.puppetlabs.puppetdb.cli.services$start_puppetdb.invoke(services.clj:290) [na:na]
at com.puppetlabs.puppetdb.cli.services$reify_21157$service_fnk18232auto_positional$reify_21168.start(services.clj:366) [na:na]
at puppetlabs.trapperkeeper.services$eval18068$fn_18082$G18058_18085.invoke(services.clj:10) [na:na]
at puppetlabs.trapperkeeper.services$eval18068$fn_18082$G18057_18089.invoke(services.clj:10) [na:na]
at puppetlabs.trapperkeeper.internal$run_lifecycle_fn_BANG_.invoke(internal.clj:154) [na:na]
at puppetlabs.trapperkeeper.internal$run_lifecycle_fns.invoke(internal.clj:182) [na:na]
at puppetlabs.trapperkeeper.internal$build_app_STAR_$reify__18905.start(internal.clj:449) [na:na]
at puppetlabs.trapperkeeper.internal$boot_services_STAR_$fn__18917.invoke(internal.clj:473) [na:na]
at puppetlabs.trapperkeeper.internal$boot_services_STAR_.invoke(internal.clj:471) [na:na]
at puppetlabs.trapperkeeper.core$boot_with_cli_data.invoke(core.clj:113) [na:na]
at puppetlabs.trapperkeeper.core$run.invoke(core.clj:144) [na:na]
at puppetlabs.trapperkeeper.core$main.doInvoke(core.clj:159) [na:na]
at clojure.lang.RestFn.applyTo(RestFn.java:137) [puppetdb.jar:na]
at clojure.core$apply.invoke(core.clj:624) [puppetdb.jar:na]
at com.puppetlabs.puppetdb.cli.services$_main.doInvoke(services.clj:373) [na:na]
at clojure.lang.RestFn.invoke(RestFn.java:421) [puppetdb.jar:na]
at clojure.lang.Var.invoke(Var.java:383) [puppetdb.jar:na]
at clojure.lang.AFn.applyToHelper(AFn.java:156) [puppetdb.jar:na]
at clojure.lang.Var.applyTo(Var.java:700) [puppetdb.jar:na]
at clojure.core$apply.invoke(core.clj:624) [puppetdb.jar:na]
at com.puppetlabs.puppetdb.core$run_command.invoke(core.clj:87) [na:na]
at com.puppetlabs.puppetdb.core$_main.doInvoke(core.clj:95) [na:na]
at clojure.lang.RestFn.invoke(RestFn.java:436) [puppetdb.jar:na]
at clojure.lang.Var.invoke(Var.java:388) [puppetdb.jar:na]
at clojure.lang.AFn.applyToHelper(AFn.java:160) [puppetdb.jar:na]
at clojure.lang.Var.applyTo(Var.java:700) [puppetdb.jar:na]
at clojure.core$apply.invoke(core.clj:624) [puppetdb.jar:na]
at clojure.main$main_opt.invoke(main.clj:315) [puppetdb.jar:na]
at clojure.main$main.doInvoke(main.clj:420) [puppetdb.jar:na]
at clojure.lang.RestFn.invoke(RestFn.java:482) [puppetdb.jar:na]
at clojure.lang.Var.invoke(Var.java:401) [puppetdb.jar:na]
at clojure.lang.AFn.applyToHelper(AFn.java:171) [puppetdb.jar:na]
at clojure.lang.Var.applyTo(Var.java:700) [puppetdb.jar:na]
at clojure.main.main(main.java:37) [puppetdb.jar:na]
2015-04-01 09:35:21,991 INFO [p.t.internal] Shutting down due to JVM shutdown hook.
2015-04-01 09:35:21,995 INFO [p.t.internal] Beginning shutdown sequence
2015-04-01 09:35:21,997 INFO [c.p.p.c.services] Shutdown request received; puppetdb exiting.
2015-04-01 09:35:21,998 INFO [p.t.s.w.jetty9-service] Shutting down web server(s).
2015-04-01 09:35:21,999 INFO [p.t.s.w.jetty9-core] Shutting down web server.
2015-04-01 09:35:22,006 INFO [o.e.j.s.ServerConnector] Stopped ServerConnector@e5cd780

{HTTP/1.1} {localhost:8080}

2015-04-01 09:35:22,016 INFO [o.e.j.s.ServerConnector] Stopped ServerConnector@6a2cc795

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

2015-04-01 09:35:22,017 INFO [p.t.s.w.jetty9-core] Web server shutdown
2015-04-01 09:35:22,018 INFO [p.t.internal] Finished shutdown sequence

Comment by Wyatt Alt [ 2015/03/31 ]

Well, thanks for ruling that out anyway. Would you mind giving the outputs of the following queries?

select 1 from facts where fact_value_id=452 limit 1;

select * from fact_values where id=452,

select * from fact_paths where id in (select path_id from fact_values where id=452);

Thanks for the help.
Wyatt

Comment by Pete Brown [ 2015/03/31 ]

Here you go.
Should they all be empty?

puppetdb=# select 1 from facts where fact_value_id=452 limit 1;
?column?
----------
(0 rows)

puppetdb=# select * from fact_values where id=452;
id | path_id | value_type_id | value_hash | value_integer | value_float | value_string | value_boolean | value_json
---------------------------------------------------------------------------------------------
(0 rows)

puppetdb=# select * from fact_paths where id in (select path_id from fact_values where id=452);
id | value_type_id | depth | name | path
------------------------------
(0 rows)

Comment by Wyatt Alt [ 2015/03/31 ]

@Pete Brown I just used that id because it's the one in the stack trace. It looks like it's no longer applicable though.

We've managed to replicate your error message by having two facts on different hosts with the same name but different types.

Could you check if that's your case using this query?

select path,count(1) from fact_paths group by path having count(1) > 1;

Comment by Pete Brown [ 2015/03/31 ]

Looks like pip_version is culprit

puppetdb=# select path,count(1) from fact_paths group by path having count(1) > 1;
path | count
------------+------
pip_version | 2
(1 row)

Comment by Wyatt Alt [ 2015/03/31 ]

Pete Brown yep, I think that's the issue. We've got a fix up for review here: https://github.com/puppetlabs/puppetdb/pull/1332, and we'll get it out in a new release in the next day or two. Thanks again for the quick report and debugging assistance.

Wyatt

Comment by Pete Brown [ 2015/03/31 ]

Awesome! Thanks Wyatt Alt!
Happy to help.

I am going to guess this won't affect new installs?

Comment by Wyatt Alt [ 2015/03/31 ]

Pete Brown Yeah, new installs should be fine.

My guess is the main risk is when migrating folks have a mix of facter versions across their infrastructure, or a mix of module versions where the module generates custom facts. Old versions of facter stringified all fact values, whereas new ones use more varied types. The same is true of modules, since only strings used to be supported.

So for instance if you have puppetlabs-python from a year ago somewhere, in addition to one installed yesterday in another place, you could easily hit this issue with the pip_version fact.

Comment by Pete Brown [ 2015/03/31 ]

I use Vagrant for my development environment and I tend to destroy and rebuild it pretty regularly, sometimes every day.
I also manage versions of facter with puppet so everything gets upgraded not long after new versions get rolled out.

I do have two "environments" with stankevich-python installed (for puppetboard) but they are not used in separate environments and they are at the same version.

Does that help?

Comment by Wyatt Alt [ 2015/03/31 ]

Alternatively, a module may be assigning null values on some nodes for facts that don't apply. I'd expect that to cause the same.

Comment by Wyatt Alt [ 2015/03/31 ]

Pete Brown sorry, didn't see your comment before I posted mine. What does the query

select * from fact_paths where path='pip_version';

return?

Comment by Wyatt Alt [ 2015/03/31 ]

the type ids can be correlated with the types in the output of

select * from value_types;

Comment by Pete Brown [ 2015/03/31 ]

Dammit.

I just destroyed and rebuilt my dev puppet server and used the new version of puppetdb.

I can try and build it with the old version and see how it goes and let you know what I find.

Comment by Wyatt Alt [ 2015/03/31 ]

Pete Brown If it weren't too much trouble that would certainly help confirm.

Comment by Pete Brown [ 2015/03/31 ]

Just booting it up now.

I ran those queries on my live puppet master and it seems like it doesn't have any duplicates.
Can I assume from that it would be safe to upgrade it to latest PuppetDB?

Comment by Wyatt Alt [ 2015/03/31 ]

The output of
curl -X GET http://localhost:8080/v4/facts/pip_version

would also show the different types if you manage to replicate the problem on your dev environment.

As for your live puppet master (production I assume) attempting an upgrade will be safe since the migrations take place within a transaction, and assuming I understand the problem, the fact that

 select path,count(1) from fact_paths group by path having count(1) > 1;

returns nothing means the migration should succeed.

Comment by Pete Brown [ 2015/03/31 ]

I booted up my puppetmaster and it didn't have a duplicate fact for pip_version
I was running a couple of other nodes last time so I have booted up a test dhcp server and it added the extra pip_version fact.

While I have it running is there anything else you would like me to check?

Results from the queries.
puppetdb=# select * from fact_paths where path='pip_version';
id | value_type_id | depth | name | path
---------------------------------------------
98 | 0 | 0 | pip_version | pip_version
180 | 3 | 0 | pip_version | pip_version
(2 rows)

puppetdb=# select * from value_types;
id | type
---+--------
0 | string
1 | integer
2 | float
3 | boolean
4 | null
5 | json
(6 rows)

Comment by Pete Brown [ 2015/03/31 ]

Sorry missed you last comment.
Here is the curl request

root@puppet:~# curl -X GET http://localhost:8080/v4/facts/pip_version
[

{ "value" : "1.5.4", "name" : "pip_version", "environment" : "development", "certname" : "puppet.pivit.net.au" }

,

{ "value" : false, "name" : "pip_version", "environment" : "development", "certname" : "dhcp.pivit.net.au" }
Comment by Pete Brown [ 2015/03/31 ]

Just letting you know I upgraded PuppetDB on my live server and it worked without a hitch.

It seems to have been suffering from the memory bloat that 2.3.1 fixed.
Thanks for that.

Comment by Wyatt Alt [ 2015/04/01 ]

Pete Brown Thanks for the helpful updates. I think this confirms the issue conclusively in your case. I'm glad to hear the upgrade went well.

Comment by Wyatt Alt [ 2015/04/01 ]

Pete Brown we have addressed this issue in today's 2.3.2 release.

Generated at Mon Sep 23 12:34:22 PDT 2019 using JIRA 7.7.1#77002-sha1:e75ca93d5574d9409c0630b81c894d9065296414.