puppetdb 4.3 on PG 9.4 fresh install fails to start with DB UTF8 encoding error

[s...@la-z-boy.com]

Hi everyone,

I'm trying to do my first ever install of PuppetDB.  I'm installing PuppetDB 4.3 from RPM with Postgres 9.4.  When I try to start PuppetDB I get the following errors (removed some of the non-important java debugging lines):

2017-02-16 14:19:54,539 INFO  [p.p.s.migrate] Applying database migration version 43

2017-02-16 14:19:54,570 ERROR [p.p.s.migrate] Caught SQLException during migration

java.sql.BatchUpdateException: Batch entry 1 CREATE AGGREGATE md5_agg (BYTEA)

    (

      sfunc = dual_md5,

      stype = bytea,

      initcond = '\x00'

    ) was aborted.  Call getNextException to see the cause.

2017-02-16 14:19:54,571 ERROR [p.p.s.migrate] Unravelled exception

org.postgresql.util.PSQLException: ERROR: invalid byte sequence for encoding "UTF8": 0x00

Any advice would be appreciated.  

[Wyatt Alt]

Hi,

This seems like a bug to me, but I can't reproduce it on postgres 9.4 + centos 7.3 and the combination of PDB 4.3 and postgres 9.4 is widely used/tested.

Can you give a bit more detail about your environment? I'd like to know your OS and version and the method you used to install postgres. It would also be good to see the output of

'\l+'

executed in psql, which will give you a table like this:
https://gist.github.com/wkalt/bbffafe68ec4018f7bcbc5b62961dc24

Thanks,
Wyatt

[s...@la-z-boy.com]

Hi Wyatt,

The environment is Oracle Linux 7.3.  Postgres 9.4 was installed from the PGDG repositories then tuned for memory usage.  I've pasted the content of the psql command to pastebin so it's easier to read:  http://pastebin.com/uveSYRWN.  

PuppetDB version:

puppetdb-4.3.0-1.el7.noarch

puppetdb-termini-4.3.0-1.el7.noarch

puppetdb-terminus-3-1.el7.noarch

Puppet server version:

puppetserver-2.7.2-1.el7.noarch

Thanks for your help.

[Rob Browning]

s...@la-z-boy.com writes:

> java.sql.BatchUpdateException: Batch entry 1 CREATE AGGREGATE md5_agg
> (BYTEA)
> (
> sfunc = dual_md5,
> stype = bytea,
> initcond = '\x00'
> ) was aborted. Call getNextException to see the cause.
>
> 2017-02-16 14:19:54,571 ERROR [p.p.s.migrate] Unravelled exception
> org.postgresql.util.PSQLException: ERROR: invalid byte sequence for
> encoding "UTF8": 0x00

Hmm, I don't yet have a good idea why you're having this trouble, but as
another bit of data, I just tested that function against postgres 9.4
via psql and it worked fine, then against 8.4, and I saw something very
similar:

$ psql -U rlb puppetdb
psql (8.4.21)
Type "help" for help.

puppetdb=# create aggregate md5_agg_foo (bytea) (sfunc = dual_md5, stype = bytea, initcond = '\x00');
WARNING: nonstandard use of escape in a string literal
LINE 1: ...bytea) (sfunc = dual_md5, stype = bytea, initcond = '\x00');
^
HINT: Use the escape string syntax for escapes, e.g., E'\r\n'.

ERROR: invalid byte sequence for encoding "UTF8": 0x00

HINT: This error can also happen if the byte sequence does not match the encoding expected by the server, which is controlled by "client_encoding".

But I believe puppetdb should be checking your database version before
we even get to that point via:

https://github.com/puppetlabs/puppetdb/blob/master/src/puppetlabs/puppetdb/scf/storage.clj#L1371

And indeed, when I try to run puppetdb against 8.4, I see this:

* PostgreSQL DB versions older than 9.4 are no longer supported. Please upgrade Postgres and restart PuppetDB.
*
********************
2017-02-17 16:23:09,000 ERROR [async-dispatch-2] [p.p.s.storage] ********************
*
* PostgreSQL DB versions older than 9.4 are no longer supported. Please upgrade Postgres and restart PuppetDB.
*
********************
2017-02-17 16:23:09,007 INFO [Thread-2] [p.t.internal] Shutting down due to JVM shutdown hook.
2017-02-17 16:23:09,011 INFO [Thread-2] [p.t.internal] Beginning shutdown sequence

So it does seem a bit unlikely that puppetdb is talking to a postgres
that's "too old". Out of curiosity, does everything look reasonable
when you run

ps aux | grep postgres

And if you take the PID for the main postgres process, something like:

rlb 19180 1.3 0.5 2305952 82340 pts/5 S+ 16:38 0:00 postgres -h localhost -D data

Then do you see the dir you expect for:

ls -l /proc/19180/cwd

?

Thanks
--
Rob Browning

[Russell Mull]

Hi, 

Just to be sure, I verified that PuppetDB works as expected in Oracle Linux 7.3. I posted my Vagrant setup here: https://gist.github.com/mullr/c09d87332edb5fb074c298620fd3df24

How does that compare to the way you installed PostgreSQL and PuppetDB? Do you think you can reproduce the issue in that context?

As my colleagues said, PuppetDB should complain if you're running against an older verison of PostgreSQL, so that doesn't really seem likely to be the problem. My best guess is that it's a database configuration issue that we haven't seen before. In any case, this is a very strange problem and we'd like to get to the bottom of it.  

- Russell 

[Ben West]

I encountered this very same problem installing puppetDB v4.4 from RPM on CentOS 7.2.1511, with postgres v9.4 installed via RPMs retrieved from yum.postgresql.org.

I tried following the instructions here for creating the puppetdb role and database in postgresql:
https://docs.puppet.com/puppetdb/4.4/configure.html#using-postgresql

Nevertheless, pointing the puppetdb service to this blank database and starting it up yielded this same (persistent) error in puppetdb.log, quoted below.

A resolution I found was to pg_restore a backup from another instance of puppetdb, and then restart puppetdb again.  That is, the problem appears to be limited to populating the postgres database on first startup.

2017-10-06 17:28:42,627 INFO  [p.p.s.migrate] Applying database migration version 28
2017-10-06 17:28:43,153 INFO  [p.p.s.migrate] Applying database migration version 29
2017-10-06 17:28:43,564 INFO  [p.p.s.migrate] Applying database migration version 30
2017-10-06 17:28:43,571 INFO  [p.p.s.migrate] Applying database migration version 31
2017-10-06 17:28:43,586 INFO  [p.p.s.migrate] Applying database migration version 32
2017-10-06 17:28:43,589 INFO  [p.p.s.migrate] Applying database migration version 33
2017-10-06 17:28:43,611 INFO  [p.p.s.migrate] Applying database migration version 34
2017-10-06 17:28:43,632 INFO  [p.p.s.migrate] Applying database migration version 35
2017-10-06 17:28:43,633 INFO  [p.p.s.migrate] Applying database migration version 36
2017-10-06 17:28:43,635 INFO  [p.p.s.migrate] Applying database migration version 37
2017-10-06 17:28:43,637 INFO  [p.p.s.migrate] Applying database migration version 38
2017-10-06 17:28:43,647 INFO  [p.p.s.migrate] Applying database migration version 39
2017-10-06 17:28:43,791 INFO  [p.p.s.migrate] Applying database migration version 40
2017-10-06 17:28:43,803 INFO  [p.p.s.migrate] Applying database migration version 41
2017-10-06 17:28:43,804 INFO  [p.p.s.migrate] Applying database migration version 42
2017-10-06 17:28:43,840 INFO  [p.p.s.migrate] Applying database migration version 43
2017-10-06 17:28:43,853 ERROR [p.p.s.migrate] Caught SQLException during migration

java.sql.BatchUpdateException: Batch entry 1 CREATE AGGREGATE md5_agg (BYTEA)
    (
      sfunc = dual_md5,
      stype = bytea,
      initcond = '\x00'
    ) was aborted.  Call getNextException to see the cause.

    at org.postgresql.jdbc.BatchResultHandler.handleError(BatchResultHandler.java:133)
    at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2004)
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:360)
    at org.postgresql.jdbc.PgStatement.executeBatch(PgStatement.java:1019)
    at com.zaxxer.hikari.pool.ProxyStatement.executeBatch(ProxyStatement.java:128)
    at com.zaxxer.hikari.pool.HikariProxyStatement.executeBatch(HikariProxyStatement.java)
    at clojure.java.jdbc$execute_batch.invokeStatic(jdbc.clj:439)
    at clojure.java.jdbc$execute_batch.invoke(jdbc.clj:432)
    at clojure.java.jdbc$db_do_commands$fn__21807.invoke(jdbc.clj:748)
    at clojure.java.jdbc$db_transaction_STAR_.invokeStatic(jdbc.clj:662)
    at clojure.java.jdbc$db_transaction_STAR_.invoke(jdbc.clj:598)
    at clojure.java.jdbc$db_transaction_STAR_.invokeStatic(jdbc.clj:611)
    at clojure.java.jdbc$db_transaction_STAR_.invoke(jdbc.clj:598)
    at clojure.java.jdbc$db_do_commands.invokeStatic(jdbc.clj:747)
    at clojure.java.jdbc$db_do_commands.invoke(jdbc.clj:732)
    at puppetlabs.puppetdb.jdbc$do_commands.invokeStatic(jdbc.clj:38)
    at puppetlabs.puppetdb.jdbc$do_commands.doInvoke(jdbc.clj:33)
    at clojure.lang.RestFn.invoke(RestFn.java:436)
    at puppetlabs.puppetdb.scf.migrate$add_indexes_for_reports_summary_query.invokeStatic(migrate.clj:900)
    at puppetlabs.puppetdb.scf.migrate$add_indexes_for_reports_summary_query.invoke(migrate.clj:898)
    at puppetlabs.puppetdb.scf.migrate$migrate_BANG_$fn__35954$fn__35963.invoke(migrate.clj:1400)
    at puppetlabs.puppetdb.scf.migrate$sql_or_die.invokeStatic(migrate.clj:1343)
    at puppetlabs.puppetdb.scf.migrate$sql_or_die.invoke(migrate.clj:1334)
    at puppetlabs.puppetdb.scf.migrate$migrate_BANG_$fn__35954.invoke(migrate.clj:1400)
    at clojure.java.jdbc$db_transaction_STAR_.invokeStatic(jdbc.clj:628)
    at clojure.java.jdbc$db_transaction_STAR_.invoke(jdbc.clj:598)
    at puppetlabs.puppetdb.scf.migrate$migrate_BANG_.invokeStatic(migrate.clj:1397)
    at puppetlabs.puppetdb.scf.migrate$migrate_BANG_.invoke(migrate.clj:1367)
    at puppetlabs.puppetdb.cli.services$initialize_schema.invokeStatic(services.clj:293)
    at puppetlabs.puppetdb.cli.services$initialize_schema.invoke(services.clj:284)
    at puppetlabs.puppetdb.cli.services$init_with_db$fn__36175.invoke(services.clj:316)
    at puppetlabs.puppetdb.cli.services$init_with_db.invokeStatic(services.clj:312)
    at puppetlabs.puppetdb.cli.services$init_with_db.invoke(services.clj:297)
    at puppetlabs.puppetdb.cli.services$start_puppetdb.invokeStatic(services.clj:343)
    at puppetlabs.puppetdb.cli.services$start_puppetdb.invoke(services.clj:323)
    at puppetlabs.puppetdb.cli.services$reify__36282$service_fnk__19218__auto___positional$reify__36291.start(services.clj:432)
    at puppetlabs.trapperkeeper.services$eval19020$fn__19034$G__19010__19037.invoke(services.clj:8)
    at puppetlabs.trapperkeeper.services$eval19020$fn__19034$G__19009__19041.invoke(services.clj:8)
    at puppetlabs.trapperkeeper.internal$eval19576$run_lifecycle_fn_BANG___19583$fn__19584.invoke(internal.clj:204)
    at puppetlabs.trapperkeeper.internal$eval19576$run_lifecycle_fn_BANG___19583.invoke(internal.clj:187)
    at puppetlabs.trapperkeeper.internal$eval19605$run_lifecycle_fns__19610$fn__19611.invoke(internal.clj:238)
    at puppetlabs.trapperkeeper.internal$eval19605$run_lifecycle_fns__19610.invoke(internal.clj:215)
    at puppetlabs.trapperkeeper.internal$eval20075$build_app_STAR___20084$fn$reify__20094.start(internal.clj:591)
    at puppetlabs.trapperkeeper.internal$eval20121$boot_services_for_app_STAR__STAR___20128$fn__20129$fn__20131.invoke(internal.clj:617)
    at puppetlabs.trapperkeeper.internal$eval20121$boot_services_for_app_STAR__STAR___20128$fn__20129.invoke(internal.clj:615)
    at puppetlabs.trapperkeeper.internal$eval20121$boot_services_for_app_STAR__STAR___20128.invoke(internal.clj:609)
    at clojure.core$partial$fn__4761.invoke(core.clj:2521)
    at puppetlabs.trapperkeeper.internal$eval19644$initialize_lifecycle_worker__19655$fn__19656$fn__19742$state_machine__14866__auto____19743$fn__19745.invoke(internal.clj:255)
    at puppetlabs.trapperkeeper.internal$eval19644$initialize_lifecycle_worker__19655$fn__19656$fn__19742$state_machine__14866__auto____19743.invoke(internal.clj:255)
    at clojure.core.async.impl.ioc_macros$run_state_machine.invokeStatic(ioc_macros.clj:1012)
    at clojure.core.async.impl.ioc_macros$run_state_machine.invoke(ioc_macros.clj:1011)
    at clojure.core.async.impl.ioc_macros$run_state_machine_wrapped.invokeStatic(ioc_macros.clj:1016)
    at clojure.core.async.impl.ioc_macros$run_state_machine_wrapped.invoke(ioc_macros.clj:1014)
    at clojure.core.async$ioc_alts_BANG_$fn__15034.invoke(async.clj:383)
    at clojure.core.async$do_alts$fn__14980$fn__14983.invoke(async.clj:252)
    at clojure.core.async.impl.channels.ManyToManyChannel$fn__9790$fn__9791.invoke(channels.clj:95)
    at clojure.lang.AFn.run(AFn.java:22)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
2017-10-06 17:28:43,854 ERROR [p.p.s.migrate] Unravelled exception

org.postgresql.util.PSQLException: ERROR: invalid byte sequence for encoding "UTF8": 0x00

    at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2284)
    at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2003)
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:360)
    at org.postgresql.jdbc.PgStatement.executeBatch(PgStatement.java:1019)
    at com.zaxxer.hikari.pool.ProxyStatement.executeBatch(ProxyStatement.java:128)
    at com.zaxxer.hikari.pool.HikariProxyStatement.executeBatch(HikariProxyStatement.java)
    at clojure.java.jdbc$execute_batch.invokeStatic(jdbc.clj:439)
    at clojure.java.jdbc$execute_batch.invoke(jdbc.clj:432)
    at clojure.java.jdbc$db_do_commands$fn__21807.invoke(jdbc.clj:748)
    at clojure.java.jdbc$db_transaction_STAR_.invokeStatic(jdbc.clj:662)
    at clojure.java.jdbc$db_transaction_STAR_.invoke(jdbc.clj:598)
    at clojure.java.jdbc$db_transaction_STAR_.invokeStatic(jdbc.clj:611)
    at clojure.java.jdbc$db_transaction_STAR_.invoke(jdbc.clj:598)
    at clojure.java.jdbc$db_do_commands.invokeStatic(jdbc.clj:747)
    at clojure.java.jdbc$db_do_commands.invoke(jdbc.clj:732)
    at puppetlabs.puppetdb.jdbc$do_commands.invokeStatic(jdbc.clj:38)
    at puppetlabs.puppetdb.jdbc$do_commands.doInvoke(jdbc.clj:33)
    at clojure.lang.RestFn.invoke(RestFn.java:436)
    at puppetlabs.puppetdb.scf.migrate$add_indexes_for_reports_summary_query.invokeStatic(migrate.clj:900)
    at puppetlabs.puppetdb.scf.migrate$add_indexes_for_reports_summary_query.invoke(migrate.clj:898)
    at puppetlabs.puppetdb.scf.migrate$migrate_BANG_$fn__35954$fn__35963.invoke(migrate.clj:1400)
    at puppetlabs.puppetdb.scf.migrate$sql_or_die.invokeStatic(migrate.clj:1343)
    at puppetlabs.puppetdb.scf.migrate$sql_or_die.invoke(migrate.clj:1334)
    at puppetlabs.puppetdb.scf.migrate$migrate_BANG_$fn__35954.invoke(migrate.clj:1400)
    at clojure.java.jdbc$db_transaction_STAR_.invokeStatic(jdbc.clj:628)
    at clojure.java.jdbc$db_transaction_STAR_.invoke(jdbc.clj:598)
    at puppetlabs.puppetdb.scf.migrate$migrate_BANG_.invokeStatic(migrate.clj:1397)
    at puppetlabs.puppetdb.scf.migrate$migrate_BANG_.invoke(migrate.clj:1367)
    at puppetlabs.puppetdb.cli.services$initialize_schema.invokeStatic(services.clj:293)
    at puppetlabs.puppetdb.cli.services$initialize_schema.invoke(services.clj:284)
    at puppetlabs.puppetdb.cli.services$init_with_db$fn__36175.invoke(services.clj:316)
    at puppetlabs.puppetdb.cli.services$init_with_db.invokeStatic(services.clj:312)
    at puppetlabs.puppetdb.cli.services$init_with_db.invoke(services.clj:297)
    at puppetlabs.puppetdb.cli.services$start_puppetdb.invokeStatic(services.clj:343)
    at puppetlabs.puppetdb.cli.services$start_puppetdb.invoke(services.clj:323)
    at puppetlabs.puppetdb.cli.services$reify__36282$service_fnk__19218__auto___positional$reify__36291.start(services.clj:432)
    at puppetlabs.trapperkeeper.services$eval19020$fn__19034$G__19010__19037.invoke(services.clj:8)
    at puppetlabs.trapperkeeper.services$eval19020$fn__19034$G__19009__19041.invoke(services.clj:8)
    at puppetlabs.trapperkeeper.internal$eval19576$run_lifecycle_fn_BANG___19583$fn__19584.invoke(internal.clj:204)
    at puppetlabs.trapperkeeper.internal$eval19576$run_lifecycle_fn_BANG___19583.invoke(internal.clj:187)
    at puppetlabs.trapperkeeper.internal$eval19605$run_lifecycle_fns__19610$fn__19611.invoke(internal.clj:238)
    at puppetlabs.trapperkeeper.internal$eval19605$run_lifecycle_fns__19610.invoke(internal.clj:215)
    at puppetlabs.trapperkeeper.internal$eval20075$build_app_STAR___20084$fn$reify__20094.start(internal.clj:591)
    at puppetlabs.trapperkeeper.internal$eval20121$boot_services_for_app_STAR__STAR___20128$fn__20129$fn__20131.invoke(internal.clj:617)
    at puppetlabs.trapperkeeper.internal$eval20121$boot_services_for_app_STAR__STAR___20128$fn__20129.invoke(internal.clj:615)
    at puppetlabs.trapperkeeper.internal$eval20121$boot_services_for_app_STAR__STAR___20128.invoke(internal.clj:609)
    at clojure.core$partial$fn__4761.invoke(core.clj:2521)
    at puppetlabs.trapperkeeper.internal$eval19644$initialize_lifecycle_worker__19655$fn__19656$fn__19742$state_machine__14866__auto____19743$fn__19745.invoke(internal.clj:255)
    at puppetlabs.trapperkeeper.internal$eval19644$initialize_lifecycle_worker__19655$fn__19656$fn__19742$state_machine__14866__auto____19743.invoke(internal.clj:255)
    at clojure.core.async.impl.ioc_macros$run_state_machine.invokeStatic(ioc_macros.clj:1012)
    at clojure.core.async.impl.ioc_macros$run_state_machine.invoke(ioc_macros.clj:1011)
    at clojure.core.async.impl.ioc_macros$run_state_machine_wrapped.invokeStatic(ioc_macros.clj:1016)
    at clojure.core.async.impl.ioc_macros$run_state_machine_wrapped.invoke(ioc_macros.clj:1014)
    at clojure.core.async$ioc_alts_BANG_$fn__15034.invoke(async.clj:383)
    at clojure.core.async$do_alts$fn__14980$fn__14983.invoke(async.clj:252)
    at clojure.core.async.impl.channels.ManyToManyChannel$fn__9790$fn__9791.invoke(channels.clj:95)
    at clojure.lang.AFn.run(AFn.java:22)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
2017-10-06 17:28:43,857 INFO  [p.t.internal] Shutting down due to JVM shutdown hook.
2017-10-06 17:28:43,859 INFO  [p.t.internal] Beginning shutdown sequence

From postgresql.log:

2017-10-06 17:34:44 UTC ERROR:  invalid byte sequence for encoding "UTF8": 0x00
2017-10-06 17:34:44 UTC STATEMENT:  CREATE AGGREGATE md5_agg (BYTEA)

        (
          sfunc = dual_md5,
          stype = bytea,
          initcond = '\x00'
        )