[PDB-3058] Report not being stored in PuppetDB due to Unicode Error Created: 2016/09/20  Updated: 2019/01/15  Resolved: 2019/01/15

Status: Closed
Project: PuppetDB
Component/s: PuppetDB
Affects Version/s: PDB 4.1.0
Fix Version/s: PDB 4.2.3.2, PDB 4.4.2, PDB 5.1.0

Type: Bug Priority: Critical
Reporter: Nicolas Corrarello Assignee: Russell Mull
Resolution: Done Votes: 0
Labels: docs_reviewed, maintenance
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Centos 7.2 Master
Windows Server 2012 R2 Agent
Puppet Enterprise 2016.2 using control repository on https://github.com/ncorrare/puppetcont2016-control.


Attachments: Text File puppetdb.log    
Issue Links:
Blocks
Relates
relates to PDB-3648 PuppetDB having issues with escape ch... Closed
Template:
Team: Data Platform
Story Points: 3
Sprint: FF 2016-10-19, FF 2016-11-02, PuppetDB 2017-04-19, Data Platform 2017-09-06
Release Notes: Bug Fix
Release Notes Summary: PuppetDB now filters null bytes in Resource Events fields; this fixes a problem when dealing with certain entries in the Windows registry which contain the value '\0' by default.

 Description   

Not sure if this is actually a PuppetDB bug but I thought I'd raise visibility into it.
Running a Master on Centos 7.2 / Windows Server 2012 R2 Agent.
Upon finishing a puppet run configuring a server with the role::ecommerceweb, report isn't stored.

PuppetDB log reports as follows:
2016-09-20 10:39:27,766 ERROR [command-proc-53] [p.p.mq-listener] [bc073d6d-dde3-42b9-a090-f9dfe01dcb24] [store report] Retrying after attempt 10 for server2012r2a.pdx.puppet.vm, due to: org.postgresql.util.PSQLException: ERROR: unsupported Unicode escape sequence
Detail: \u0000 cannot be converted to text.
Where: JSON data, line 1: ...ts/init.pp","line":48,"level":"notice","message":...
org.postgresql.util.PSQLException: ERROR: unsupported Unicode escape sequence
Detail: \u0000 cannot be converted to text.
Where: JSON data, line 1: ...ts/init.pp","line":48,"level":"notice","message":...

(Full log of puppetdb foreground --debug attached).

I'm pretty sure a module is breaking it, although I can't pinpoint which one.
I can replicate the issue, and assist with the troubleshooting if required.



 Comments   
Comment by Wyatt Alt [ 2016/09/20 ]

Nicolas Corrarello Thanks for reporting this. I thought we had fixed it in 4.2.0 but I just looked and it seems like not. We'll get on it as soon as we can.

For what it's worth, the issue is that postgres's jsonb type can't handle null bytes, and you seem to be ending up with one in your report logs somehow. If you want to find the source of it, you should be able to look under /opt/puppetlabs/server/data/puppetdb/mq for a directory called "discarded". This will have a subdirectory of failed store report commands, and you can grep through that for your error and locate the null byte from there.

Comment by Wyatt Alt [ 2016/10/20 ]

@reid yeah that's correct. It's fixed in one manifestation of the issue (insertion of a null byte into jsonb) but not another (insertion into text). Trivial to reproduce with

Facter.add("mynilfact") do
  setcode do
    {"foo" => "\u0000"}
  end
end

I've got a fix in progress but since it's a maintenance issue progress has been a bit slow. If you're troubleshooting it with a customer the usual cause is binary file content FWIW.

Comment by Wyatt Alt [ 2016/10/20 ]

Nicolas Corrarello Russell Mull I had a minute to try this out. I'm unable to reproduce the issue with that file and the manifest

file {"/home/wyatt/Desktop/test.bin":
  source => "file:///home/wyatt/Desktop/default(1).bgi",
  ensure => file,
}

on linux running against postgres 9.5. We can revisit next week with Nico's environment to see if we can pull the problem message out of the DLO. Let me know if the manifest has an obvious issue.

Comment by Susan McNerney [ 2016/11/02 ]

probably will not move in 11/15 sprint due to release obligations for PDB.

Comment by Jacky Leung [ 2017/01/17 ]

I have a similar issue but it seem i get this when attempt to query it not storing it. so i think the data is already exist inside the database.

puppetdb          | 172.18.0.5 - - [18/Jan/2017:07:04:13 +0000] "GET /metrics/v1/mbeans/puppetlabs.puppetdb.population:name=num-nodes HTTP/1.1" 200 19 "https://puppetboard.fishpond.co.nz/" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:50.0) Gecko/20100101 Firefox/50.0"
puppetexplorer    | 172.18.0.1 - [18/Jan/2017:07:04:13 +0000] "GET /metrics/v1/mbeans/puppetlabs.puppetdb.population:name=num-nodes HTTP/1.0" 200 19
puppetdb          | 172.18.0.5 - - [18/Jan/2017:07:04:13 +0000] "GET /metrics/v1/mbeans/puppetlabs.puppetdb.population:name=num-resources HTTP/1.1" 200 21 "https://puppetboard.fishpond.co.nz/" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:50.0) Gecko/20100101 Firefox/50.0"
puppetexplorer    | 172.18.0.1 - [18/Jan/2017:07:04:13 +0000] "GET /metrics/v1/mbeans/puppetlabs.puppetdb.population:name=num-resources HTTP/1.0" 200 21
puppetexplorer    | 172.18.0.1 - [18/Jan/2017:07:04:13 +0000] "GET /metrics/v1/mbeans/puppetlabs.puppetdb.population:name=avg-resources-per-node HTTP/1.0" 200 33
puppetdb          | 172.18.0.5 - - [18/Jan/2017:07:04:13 +0000] "GET /metrics/v1/mbeans/puppetlabs.puppetdb.population:name=avg-resources-per-node HTTP/1.1" 200 33 "https://puppetboard.fishpond.co.nz/" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:50.0) Gecko/20100101 Firefox/50.0"
puppetexplorer    | 172.18.0.1 - [18/Jan/2017:07:04:13 +0000] "GET /metrics/v1/mbeans/puppetlabs.puppetdb.population:name=pct-resource-dupes HTTP/1.0" 200 34
puppetdb          | 172.18.0.5 - - [18/Jan/2017:07:04:13 +0000] "GET /metrics/v1/mbeans/puppetlabs.puppetdb.population:name=pct-resource-dupes HTTP/1.1" 200 34 "https://puppetboard.fishpond.co.nz/" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:50.0) Gecko/20100101 Firefox/50.0"
puppetdb          | 172.18.0.5 - - [18/Jan/2017:07:04:13 +0000] "GET /pdb/meta/v1/version HTTP/1.1" 200 25 "https://puppetboard.fishpond.co.nz/" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:50.0) Gecko/20100101 Firefox/50.0"
puppetexplorer    | 172.18.0.1 - [18/Jan/2017:07:04:13 +0000] "GET /pdb/meta/v1/version HTTP/1.0" 200 49
puppetdb          | 172.18.0.5 - - [18/Jan/2017:07:04:13 +0000] "GET /pdb/query/v4/nodes?include_total=true&limit=50&offset=0&order_by=%5B%7B%22field%22:%22certname%22,%22order%22:%22asc%22%7D%5D&query=%5B%22~%22,%22certname%22,%22staging%22%5D HTTP/1.1" 200 1055 "https://puppetboard.fishpond.co.nz/" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:50.0) Gecko/20100101 Firefox/50.0"
puppetexplorer    | 172.18.0.1 - [18/Jan/2017:07:04:13 +0000] "GET /pdb/query/v4/nodes?include_total=true&limit=50&offset=0&order_by=%5B%7B%22field%22:%22certname%22,%22order%22:%22asc%22%7D%5D&query=%5B%22~%22,%22certname%22,%22staging%22%5D HTTP/1.0" 200 380
puppetdb          | 172.18.0.5 - - [18/Jan/2017:07:04:13 +0000] "GET /pdb/query/v4/reports?include_total=true&limit=1&order_by=%5B%7B%22field%22:%22receive_time%22,%22order%22:%22desc%22%7D%5D&query=%5B%22%3D%22,%22certname%22,%22staging-1.srv.fish%22%5D HTTP/1.1" 500 0 "https://puppetboard.fishpond.co.nz/" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:50.0) Gecko/20100101 Firefox/50.0"
puppetdb          | 2017-01-18 07:04:13,561 WARN  [o.e.j.s.HttpChannel] /pdb/query/v4/reports?include_total=true&limit=1&order_by=%5B%7B%22field%22:%22receive_time%22,%22order%22:%22desc%22%7D%5D&query=%5B%22%3D%22,%22certname%22,%22staging-1.srv.fish%22%5D
puppetdb          | javax.servlet.ServletException: org.postgresql.util.PSQLException: ERROR: unsupported Unicode escape sequence
puppetdb          |   Detail: \u0000 cannot be converted to text.
puppetdb          |   Where: JSON data, line 1: ...
puppetdb          | 	at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:130) ~[puppetdb.jar:na]
puppetdb          | 	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97) ~[puppetdb.jar:na]
puppetdb          | 	at org.eclipse.jetty.server.handler.RequestLogHandler.handle(RequestLogHandler.java:95) ~[puppetdb.jar:na]
puppetdb          | 	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97) ~[puppetdb.jar:na]
puppetdb          | 	at org.eclipse.jetty.server.handler.StatisticsHandler.handle(StatisticsHandler.java:159) ~[puppetdb.jar:na]
puppetdb          | 	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97) ~[puppetdb.jar:na]
puppetdb          | 	at org.eclipse.jetty.server.Server.handle(Server.java:497) ~[puppetdb.jar:na]
puppetexplorer    | 172.18.0.1 - [18/Jan/2017:07:04:13 +0000] "GET /pdb/query/v4/reports?include_total=true&limit=1&order_by=%5B%7B%22field%22:%22receive_time%22,%22order%22:%22desc%22%7D%5D&query=%5B%22%3D%22,%22certname%22,%22staging-1.srv.fish%22%5D HTTP/1.0" 500 343
puppetdb          | 	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:310) ~[puppetdb.jar:na]
puppetdb          | 	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:257) [puppetdb.jar:na]
puppetdb          | 	at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:540) [puppetdb.jar:na]
puppetdb          | 	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635) [puppetdb.jar:na]
puppetdb          | 	at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555) [puppetdb.jar:na]
puppetdb          | 	at java.lang.Thread.run(Thread.java:745) [na:1.8.0_91]
puppetdb          | Caused by: org.postgresql.util.PSQLException: ERROR: unsupported Unicode escape sequence
puppetdb          |   Detail: \u0000 cannot be converted to text.
puppetdb          |   Where: JSON data, line 1: ...
puppetdb          | 	at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2284) ~[puppetdb.jar:na]
puppetdb          | 	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2003) ~[puppetdb.jar:na]
puppetdb          | 	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:200) ~[puppetdb.jar:na]
puppetdb          | 	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:424) ~[puppetdb.jar:na]
puppetdb          | 	at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:161) ~[puppetdb.jar:na]
puppetdb          | 	at org.postgresql.jdbc.PgPreparedStatement.executeQuery(PgPreparedStatement.java:114) ~[puppetdb.jar:na]
puppetdb          | 	at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeQuery(ProxyPreparedStatement.java:52) ~[puppetdb.jar:na]
puppetdb          | 	at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeQuery(HikariProxyPreparedStatement.java) ~[puppetdb.jar:na]
puppetdb          | 	at sun.reflect.GeneratedMethodAccessor13.invoke(Unknown Source) ~[na:na]
puppetdb          | 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_91]
puppetdb          | 	at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_91]
puppetdb          | 	at clojure.lang.Reflector.invokeMatchingMethod(Reflector.java:93) ~[puppetdb.jar:na]
puppetdb          | 	at clojure.lang.Reflector.invokeNoArgInstanceMember(Reflector.java:313) ~[puppetdb.jar:na]
puppetdb          | 	at puppetlabs.puppetdb.jdbc$with_query_results_cursor$fn__21936.invoke(jdbc.clj:342) ~[na:na]
puppetdb          | 	at clojure.java.jdbc$db_transaction_STAR_.invokeStatic(jdbc.clj:620) ~[na:na]
puppetdb          | 	at clojure.java.jdbc$db_transaction_STAR_.doInvoke(jdbc.clj:568) ~[na:na]
puppetdb          | 	at clojure.lang.RestFn.invoke(RestFn.java:425) ~[puppetdb.jar:na]
puppetdb          | 	at puppetlabs.puppetdb.jdbc$with_query_results_cursor.invokeStatic(jdbc.clj:337) ~[na:na]
puppetdb          | 	at puppetlabs.puppetdb.jdbc$with_query_results_cursor.invoke(jdbc.clj:326) ~[na:na]
puppetdb          | 	at puppetlabs.puppetdb.query_eng$eval27676$produce_streaming_body__27681$fn__27682$fn__27685$fn__27687$fn__27688.invoke(query_eng.clj:189) ~[na:na]
puppetdb          | 	at puppetlabs.puppetdb.jdbc$with_transacted_connection_fn$fn__21915$fn__21916.invoke(jdbc.clj:306) ~[na:na]
puppetdb          | 	at clojure.java.jdbc$db_transaction_STAR_.invokeStatic(jdbc.clj:595) ~[na:na]
puppetdb          | 	at clojure.java.jdbc$db_transaction_STAR_.doInvoke(jdbc.clj:568) ~[na:na]
puppetdb          | 	at clojure.lang.RestFn.invoke(RestFn.java:464) ~[puppetdb.jar:na]
puppetdb          | 	at puppetlabs.puppetdb.jdbc$with_transacted_connection_fn$fn__21915.invoke(jdbc.clj:305) ~[na:na]
puppetdb          | 	at puppetlabs.puppetdb.jdbc$eval21889$retry_sql_STAR___21894$fn__21895$fn__21896.invoke(jdbc.clj:283) ~[na:na]
puppetdb          | 	at puppetlabs.puppetdb.jdbc$eval21889$retry_sql_STAR___21894$fn__21895.invoke(jdbc.clj:282) ~[na:na]
puppetdb          | 	at puppetlabs.puppetdb.jdbc$eval21889$retry_sql_STAR___21894.invoke(jdbc.clj:273) ~[na:na]
puppetdb          | 	at puppetlabs.puppetdb.jdbc$with_transacted_connection_fn.invokeStatic(jdbc.clj:303) ~[na:na]
puppetdb          | 	at puppetlabs.puppetdb.jdbc$with_transacted_connection_fn.invoke(jdbc.clj:298) ~[na:na]
puppetdb          | 	at puppetlabs.puppetdb.query_eng$eval27676$produce_streaming_body__27681$fn__27682$fn__27685$fn__27687.invoke(query_eng.clj:188) ~[na:na]
puppetdb          | 	at ring.util.io$piped_input_stream$fn__6781.invoke(io.clj:28) ~[na:na]
puppetdb          | 	at clojure.core$binding_conveyor_fn$fn__4676.invoke(core.clj:1938) ~[puppetdb.jar:na]
puppetdb          | 	at clojure.lang.AFn.call(AFn.java:18) ~[puppetdb.jar:na]
puppetdb          | 	at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[na:1.8.0_91]
puppetdb          | 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) ~[na:1.8.0_91]
puppetdb          | 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) ~[na:1.8.0_91]
puppetdb          | 	... 1 common frames omitted
puppetdb          | 172.18.0.5 - - [18/Jan/2017:07:04:13 +0000] "GET /pdb/query/v4/reports?include_total=true&limit=1&order_by=%5B%7B%22field%22:%22receive_time%22,%22order%22:%22desc%22%7D%5D&query=%5B%22%3D%22,%22certname%22,%22staging.srv.fish%22%5D HTTP/1.1" 500 0 "https://puppetboard.fishpond.co.nz/" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:50.0) Gecko/20100101 Firefox/50.0"
puppetdb          | 2017-01-18 07:04:13,574 WARN  [o.e.j.s.HttpChannel] /pdb/query/v4/reports?include_total=true&limit=1&order_by=%5B%7B%22field%22:%22receive_time%22,%22order%22:%22desc%22%7D%5D&query=%5B%22%3D%22,%22certname%22,%22staging.srv.fish%22%5D
puppetdb          | javax.servlet.ServletException: org.postgresql.util.PSQLException: ERROR: unsupported Unicode escape sequence
puppetdb          |   Detail: \u0000 cannot be converted to text.
puppetdb          |   Where: JSON data, line 1: ...
puppetdb          | 	at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:130) ~[puppetdb.jar:na]
puppetdb          | 	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97) ~[puppetdb.jar:na]
puppetdb          | 	at org.eclipse.jetty.server.handler.RequestLogHandler.handle(RequestLogHandler.java:95) ~[puppetdb.jar:na]
puppetdb          | 	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97) ~[puppetdb.jar:na]
puppetdb          | 	at org.eclipse.jetty.server.handler.StatisticsHandler.handle(StatisticsHandler.java:159) ~[puppetdb.jar:na]
puppetdb          | 	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97) ~[puppetdb.jar:na]
puppetdb          | 	at org.eclipse.jetty.server.Server.handle(Server.java:497) ~[puppetdb.jar:na]
puppetdb          | 	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:310) ~[puppetdb.jar:na]
puppetdb          | 	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:257) [puppetdb.jar:na]
puppetdb          | 	at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:540) [puppetdb.jar:na]
puppetdb          | 	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635) [puppetdb.jar:na]
puppetdb          | 	at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555) [puppetdb.jar:na]
puppetdb          | 	at java.lang.Thread.run(Thread.java:745) [na:1.8.0_91]
puppetdb          | Caused by: org.postgresql.util.PSQLException: ERROR: unsupported Unicode escape sequence
puppetdb          |   Detail: \u0000 cannot be converted to text.
puppetdb          |   Where: JSON data, line 1: ...
puppetdb          | 	at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2284) ~[puppetdb.jar:na]
puppetdb          | 	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2003) ~[puppetdb.jar:na]
puppetdb          | 	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:200) ~[puppetdb.jar:na]
puppetdb          | 	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:424) ~[puppetdb.jar:na]
puppetdb          | 	at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:161) ~[puppetdb.jar:na]
puppetdb          | 	at org.postgresql.jdbc.PgPreparedStatement.executeQuery(PgPreparedStatement.java:114) ~[puppetdb.jar:na]
puppetdb          | 	at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeQuery(ProxyPreparedStatement.java:52) ~[puppetdb.jar:na]
puppetdb          | 	at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeQuery(HikariProxyPreparedStatement.java) ~[puppetdb.jar:na]
puppetdb          | 	at sun.reflect.GeneratedMethodAccessor13.invoke(Unknown Source) ~[na:na]
puppetdb          | 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_91]
puppetdb          | 	at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_91]
puppetdb          | 	at clojure.lang.Reflector.invokeMatchingMethod(Reflector.java:93) ~[puppetdb.jar:na]
puppetdb          | 	at clojure.lang.Reflector.invokeNoArgInstanceMember(Reflector.java:313) ~[puppetdb.jar:na]
puppetdb          | 	at puppetlabs.puppetdb.jdbc$with_query_results_cursor$fn__21936.invoke(jdbc.clj:342) ~[na:na]
puppetdb          | 	at clojure.java.jdbc$db_transaction_STAR_.invokeStatic(jdbc.clj:620) ~[na:na]
puppetdb          | 	at clojure.java.jdbc$db_transaction_STAR_.doInvoke(jdbc.clj:568) ~[na:na]
puppetdb          | 	at clojure.lang.RestFn.invoke(RestFn.java:425) ~[puppetdb.jar:na]
puppetexplorer    | 172.18.0.1 - [18/Jan/2017:07:04:13 +0000] "GET /pdb/query/v4/reports?include_total=true&limit=1&order_by=%5B%7B%22field%22:%22receive_time%22,%22order%22:%22desc%22%7D%5D&query=%5B%22%3D%22,%22certname%22,%22staging.srv.fish%22%5D HTTP/1.0" 500 343
puppetdb          | 	at puppetlabs.puppetdb.jdbc$with_query_results_cursor.invokeStatic(jdbc.clj:337) ~[na:na]
puppetdb          | 	at puppetlabs.puppetdb.jdbc$with_query_results_cursor.invoke(jdbc.clj:326) ~[na:na]
puppetdb          | 	at puppetlabs.puppetdb.query_eng$eval27676$produce_streaming_body__27681$fn__27682$fn__27685$fn__27687$fn__27688.invoke(query_eng.clj:189) ~[na:na]
puppetdb          | 	at puppetlabs.puppetdb.jdbc$with_transacted_connection_fn$fn__21915$fn__21916.invoke(jdbc.clj:306) ~[na:na]
puppetdb          | 	at clojure.java.jdbc$db_transaction_STAR_.invokeStatic(jdbc.clj:595) ~[na:na]
puppetdb          | 	at clojure.java.jdbc$db_transaction_STAR_.doInvoke(jdbc.clj:568) ~[na:na]
puppetdb          | 	at clojure.lang.RestFn.invoke(RestFn.java:464) ~[puppetdb.jar:na]
puppetdb          | 	at puppetlabs.puppetdb.jdbc$with_transacted_connection_fn$fn__21915.invoke(jdbc.clj:305) ~[na:na]
puppetdb          | 	at puppetlabs.puppetdb.jdbc$eval21889$retry_sql_STAR___21894$fn__21895$fn__21896.invoke(jdbc.clj:283) ~[na:na]
puppetdb          | 	at puppetlabs.puppetdb.jdbc$eval21889$retry_sql_STAR___21894$fn__21895.invoke(jdbc.clj:282) ~[na:na]
puppetdb          | 	at puppetlabs.puppetdb.jdbc$eval21889$retry_sql_STAR___21894.invoke(jdbc.clj:273) ~[na:na]
puppetdb          | 	at puppetlabs.puppetdb.jdbc$with_transacted_connection_fn.invokeStatic(jdbc.clj:303) ~[na:na]
puppetdb          | 	at puppetlabs.puppetdb.jdbc$with_transacted_connection_fn.invoke(jdbc.clj:298) ~[na:na]
puppetdb          | 	at puppetlabs.puppetdb.query_eng$eval27676$produce_streaming_body__27681$fn__27682$fn__27685$fn__27687.invoke(query_eng.clj:188) ~[na:na]
puppetdb          | 	at ring.util.io$piped_input_stream$fn__6781.invoke(io.clj:28) ~[na:na]
puppetdb          | 	at clojure.core$binding_conveyor_fn$fn__4676.invoke(core.clj:1938) ~[puppetdb.jar:na]
puppetdb          | 	at clojure.lang.AFn.call(AFn.java:18) ~[puppetdb.jar:na]
puppetdb          | 	at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[na:1.8.0_91]
puppetdb          | 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) ~[na:1.8.0_91]
puppetdb          | 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) ~[na:1.8.0_91]
puppetdb          | 	... 1 common frames omitted
puppetdb          | 2017-01-18 07:04:13,621 WARN  [p.p.q.engine] The event-counts entity is experimental and may be altered or removed in the future.
puppetdb          | 172.18.0.5 - - [18/Jan/2017:07:04:13 +0000] "GET /pdb/query/v4/event-counts?order_by=%5B%7B%22field%22:%22certname%22,%22order%22:%22asc%22%7D%5D&query=%5B%22and%22,%5B%22%3D%22,%22certname%22,%22staging-1.srv.fish%22%5D,%5B%22%3D%22,%22latest_report%3F%22,true%5D%5D&summarize_by=certname HTTP/1.1" 200 117 "https://puppetboard.fishpond.co.nz/" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:50.0) Gecko/20100101 Firefox/50.0"
puppetexplorer    | 172.18.0.1 - [18/Jan/2017:07:04:13 +0000] "GET /pdb/query/v4/event-counts?order_by=%5B%7B%22field%22:%22certname%22,%22order%22:%22asc%22%7D%5D&query=%5B%22and%22,%5B%22%3D%22,%22certname%22,%22staging-1.srv.fish%22%5D,%5B%22%3D%22,%22latest_report%3F%22,true%5D%5D&summarize_by=certname HTTP/1.0" 200 117
puppetdb          | 2017-01-18 07:04:13,630 WARN  [p.p.q.engine] The event-counts entity is experimental and may be altered or removed in the future.
puppetdb          | 172.18.0.5 - - [18/Jan/2017:07:04:13 +0000] "GET /pdb/query/v4/event-counts?order_by=%5B%7B%22field%22:%22certname%22,%22order%22:%22asc%22%7D%5D&query=%5B%22and%22,%5B%22%3D%22,%22certname%22,%22staging.srv.fish%22%5D,%5B%22%3D%22,%22latest_report%3F%22,true%5D%5D&summarize_by=certname HTTP/1.1" 200 116 "https://puppetboard.fishpond.co.nz/" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:50.0) Gecko/20100101 Firefox/50.0"
puppetexplorer    | 172.18.0.1 - [18/Jan/2017:07:04:13 +0000] "GET /pdb/query/v4/event-counts?order_by=%5B%7B%22field%22:%22certname%22,%22order%22:%22asc%22%7D%5D&query=%5B%22and%22,%5B%22%3D%22,%22certname%22,%22staging.srv.fish%22%5D,%5B%22%3D%22,%22latest_report%3F%22,true%5D%5D&summarize_by=certname HTTP/1.0" 200 115

Comment by Jacky Leung [ 2017/01/17 ]

Puppetdb version is 4.2.0

Comment by Wyatt Alt [ 2017/01/18 ]

Jacky Leung thanks for the note – that's really annoying. I can see how it might happen if the null byte were in an event, possibly in a message or resource type/title-- those are serialized to JSON on the way out of the database, but stored as text inside.

I've been slowly picking away at this – planning to do some more work on it today. I think the solution is ultimately going to be to strip the null bytes out on the way in. I'm not sure there's a good way to fix cases where the data is already there short of manual updates to the database. If this is causing you problems I might be able to help with that.

Comment by Jacky Leung [ 2017/01/18 ]

Wyatt Alt I am recently starting to migrate from puppet 3.8 to puppet 4.8, the code side seem to be compatible and puppetdb/postgresql both seem to be upgraded without errors. but it seem the existing data is causing problem. I am not sure will new data cause problem and i just truncated my whole puppetdb and start from scratch.

so far after the truncate i don't seem to have any more errors, but this mean i also need to re-run puppet on all servers to regenerate all exported resources and all historical puppet reports.

Comment by Jacky Leung [ 2017/01/18 ]

Wyatt Alt actually forget what i say in last comment. it is still happening in new flash data

Comment by Wyatt Alt [ 2017/01/19 ]

Jacky Leung I spent some time trying to reproduce your issue this morning but haven't been able to yet. Can you verify that the two queries here return counts of zero?

psql -d puppetdb -c 'select count(*) from reports where metrics_json is not null'
psql -d puppetdb -c 'select count(*) from reports where logs_json is not null'

If either of those return nonzero counts, it means the database wasn't actually cleared on the move to 4.2.0.

I think the PR linked in this ticket should fix the problem, though I can't say how quickly it'll be released.

To get around this you'll need to figure out where the null byte is coming from. You might be able to enable the yaml store for reports (https://docs.puppet.com/puppet/latest/configuration.html#reports), and then once your nodes have checked in, grep through the directory for the word "binary". This will indicate where you've got binary data in the report.

When I stick a null byte in one of my reports, I get data that looks like this:

https://gist.github.com/wkalt/db5aa9b9d16a5ca4e9f3f873b8b4886d

You may be able to grep for that base64 encoded string directly and get lucky, though I could imagine that depending on the representation.

Once you find the null byte, it should be pretty easy to backtrack it to a manifest.

Comment by Jacky Leung [ 2017/01/19 ]

hm.. they both return zero

puppetdb=> select count(*) from reports where metrics_json is not null
puppetdb-> ;
 count 
-------
     0
(1 row)
 
puppetdb=> select count(*) from reports where logs_json is not null;
 count 
-------
     0
(1 row)

Comment by Jacky Leung [ 2017/01/19 ]

the stored reports don't have the binary data

Comment by Wyatt Alt [ 2017/01/19 ]

Jacky Leung Okay, thanks for confirming that. I'll pick this up again tomorrow (I'm US pacific) and get back to you with some more targeted queries.

Comment by Wyatt Alt [ 2017/01/23 ]

Jacky Leung considering this a bit, the easiest way to find the null byte might be to create a text dump of the database using pg_dump, and then use grep on it.

Comment by Jacky Leung [ 2017/01/23 ]

no binary data from dump. there are "binary" but it is part of the text content of a file so i don't think that is related

Comment by Wyatt Alt [ 2017/01/27 ]

Jacky Leung I saw the comment you left – no immediate timeline on the fix, but next release I'd assume. If you're getting the error in the ticket description now, does the PuppetDB log contain the name of the node with the null byte like it does in the description? If so, it shouldn't be too hard to track down the source of it (the report is cached on your master probably).

Since the "fix" is just to replace those bytes with empty strings on ingestion (likely corrupting whatever binary data was there) it's probably worth understanding where it's coming from anyway so you know nothing important is getting lost.

Comment by Jacky Leung [ 2017/01/29 ]

hm... about the "nothing import is getting lost".... the problem is that it also refuse record exported resource. which mean all code/module related to exported resources is not operational

Comment by Wyatt Alt [ 2017/01/29 ]

Jacky Leung right – sorry if it wasn't clear but my implication there was that important things may be being lost.

If I were you I would try and tie the null byte to a specific node and figure out why it's there/how to get rid of it. The usual cause is binary file content in a manifest. If you're getting log messages like the one in the ticket description (e.g "Retrying after attempt xxx") then you should be able to find the failing command in your dead letter office and inspect it for a null byte. The dead letter office should be in

/var/lib/puppetdb/mq/discarded

assuming you're on the open source defaults.

edit: sorry – I feel like I'm still being unclear. You're currently having issues because you have a null byte in a report, which is preventing reports from getting stored. Even given the fix, these null bytes will just be replaced with empty strings, which means you won't be able to get them back out of the database. My only point was that independent of the PuppetDB fix, it's probably worth figuring out where the null bytes are coming from and how to get rid of them, since they will not be doing you any good after they're replaced.

Comment by Charlie Sharpsteen [ 2017/03/02 ]

Started poking around in the discarded directory for another ticket where this came up. It appears that whatever process dumps out the discarded command is scrubbing null bytes, so we'll need to figure out another way of tracking these down.

Comment by Charlie Sharpsteen [ 2017/03/02 ]

Turns out that the nulls are present in discarded commands, they just show up as the unicode escape sequence \u0000 rather than literal null values.

Comment by Jacky Leung [ 2017/03/02 ]

Wyatt Alt hi thanks. i have no discarded catalog or report but i have lot for discarded facts. it seem i have some encoded data in ec2_user_data and the facter picked it up.

is there any way to disable certain facters on the machine? as ec2_user_data only being used when server launch, it never need by puppet itself.

i think this issue start happening to us may related to puppet4 deprecated stringify_facts. beside that facts i don't see any binary data anywhere and being discarded

Comment by Charlie Sharpsteen [ 2017/03/03 ]

Also looks like this can happen when setting registry values on windows, as the default value for some is a null byte.

For example the legal notice that can be set on Windows:

# The default value on 2012R2 is a null byte so this resource will produce a failing report.
registry_value { 'HKLM\Software\Microsoft\Windows\CurrentVersion\Policies\System\legalnoticetext':
  ensure => present,
  data => "test string",
  type => 'string',
}
 
# Using a unicode escape to re-set the default value will succeed, but also produces a failing report.
registry_value { 'HKLM\Software\Microsoft\Windows\CurrentVersion\Policies\System\legalnoticetext':
  ensure => present,
  data => "\u0000",
  type => 'string',
}

Comment by Jacky Leung [ 2017/03/13 ]

I found another area that caused the issue.

The offending SQL is:

SELECT reports.receive_time AS receive_time,
       reports.corrective_change AS corrective_change,
       reports.code_id AS code_id,
       reports.noop AS noop,
       reports.certname AS certname,
       reports.puppet_version AS puppet_version,
       encode(reports.hash::bytea, 'hex') AS hash,
       reports.cached_catalog_status AS cached_catalog_status,
       reports.transaction_uuid::text AS transaction_uuid,
       reports.configuration_version AS configuration_version,
       report_statuses.status AS status,
       producers.name AS producer,
       reports.catalog_uuid::text AS catalog_uuid,
 
  (SELECT row_to_json(t)
   FROM
     (SELECT coalesce(logs, CAST(logs_json AS jsonb)) AS DATA,
             format('/pdb/query/v4/reports/%s/logs', encode(hash::bytea, 'hex')) AS href) t) AS logs,
       reports.noop_pending AS noop_pending,
       reports.end_time AS end_time,
       environments.environment AS environment,
       reports.start_time AS start_time,
 
  (SELECT row_to_json(event_data)
   FROM
     (SELECT json_agg(row_to_json(t)) AS DATA,
             format('/pdb/query/v4/reports/%s/events', encode(hash::bytea, 'hex')) AS href
      FROM
        (SELECT re.status,
                re.timestamp,
                re.resource_type,
                re.resource_title,
                re.property,
                re.corrective_change,
                CAST(re.new_value AS jsonb),
                CAST(re.old_value AS jsonb),
                re.message,
                re.file,
                re.line,
                re.containment_path,
                re.containing_class
         FROM resource_events re
         WHERE reports.id = re.report_id) t) event_data) AS resource_events,
 
  (SELECT row_to_json(t)
   FROM
     (SELECT coalesce(metrics, CAST(metrics_json AS jsonb)) AS DATA,
             format('/pdb/query/v4/reports/%s/metrics', encode(hash::bytea, 'hex')) AS href) t) AS metrics,
       reports.producer_timestamp AS producer_timestamp,
       reports.report_format AS report_format
FROM reports
LEFT JOIN environments ON environments.id = reports.environment_id
LEFT JOIN producers ON producers.id = reports.producer_id
LEFT JOIN report_statuses ON reports.status_id = report_statuses.id
WHERE ((environments.environment = '$1')
       AND (reports.certname = '$2'))
ORDER BY reports.start_time DESC
LIMIT 10

the main offending section

SELECT re.status,
                re.timestamp,
                re.resource_type,
                re.resource_title,
                re.property,
                re.corrective_change,
                CAST(re.new_value AS jsonb),
                CAST(re.old_value AS jsonb),
                re.message,
                re.file,
                re.line,
                re.containment_path,
                re.containing_class
FROM resource_events re
WHERE reports.id = re.report_id

It seem the new_value contains binary data

        containing_class         |                new_value                
----------------------------------+-----------------------------------------
 Logstashforwarder::Config        | "\u0000## GENERATED BY PUPPET ##\u0000"

Comment by Jacky Leung [ 2017/03/13 ]

After i run this SQL it fixed my problems

puppetdb=# UPDATE resource_events 
puppetdb-# SET 
puppetdb-#     new_value = replace(new_value, '\u0000', ''),
puppetdb-#     old_value = replace(old_value, '\u0000', '');
UPDATE 652444

Comment by Susan McNerney [ 2017/03/21 ]

Approved for PDB 4.3.2.1 / PE 2016.4.4 by davis leads.

Comment by Isaac Eldridge [ 2017/03/30 ]

please use the docs tab to indicate if this needs a release note or not

Comment by Susan McNerney [ 2017/04/13 ]

We've pushed 4.2.3.2 release out to 18th to give best chance of this releasing.

Comment by Isaac Eldridge [ 2017/04/18 ]

Which PE versions will is this fixed in? 2016.4.4 and Glisan?

Comment by Russell Mull [ 2017/04/18 ]

Isaac Eldridge the fixversion field is accurate

Comment by Andreas Lambrecht [ 2017/08/24 ]

I've experience the same issue on PE2017.2.1 today, with a profile which includes the following:

registry_value

{ 'HKEY_LOCAL_MACHINE\Software\Microsoft\Windows\CurrentVersion\Policies\System\LegalNoticeText': type => string, data => 'This Legal Notice Text is Managed By Puppet', }

registry_value

{ KEY_LOCAL_MACHINE\Software\Microsoft\Windows\CurrentVersion\Policies\System\LegalNoticeCaption': type => string, data => 'This Legal Notice Caption is Managed By Puppet', }

According to "Fixed version" this should be fixed in PE2017.2.2+. However I have updated my PE2017.2.1 -> PE2017.2.3 and still have the same issue.

Generated at Sat Feb 22 06:06:19 PST 2020 using JIRA 7.7.1#77002-sha1:e75ca93d5574d9409c0630b81c894d9065296414.