Problem with PuppetDB and OpenSSL

[Jonathan Gazeley]

Hi chaps,

I run all my Puppetised servers on CentOS 6.4. Overnight there were a
load of updates for CentOS including an update to openssl-1.0.1e-15.el6.
Since installing the updates, PuppetDB is no longer working and seems to
be having troubles with SSL.

All my puppet nodes show:

Error: Could not retrieve catalog from remote server: Error 400 on
SERVER: Failed to submit 'replace facts' command for
radius-dev.nomadic-core.bris.ac.uk to PuppetDB at
puppetdb.resnet.bris.ac.uk:8081: Connection refused - connect(2)

The PuppetDB server shows:

2013-11-27 12:09:58,347 WARN [qtp1710594959-45] [io.nio]
javax.net.ssl.SSLException: Inbound closed before receiving peer's
close_notify: possible truncation attack?

Has anyone else had this problem? Any tips? I recreated the PuppetDB
certs but this didn't help.

Thanks,
Jonathan

[Ken Barber]

This all sounds pretty serious, but something isn't quite right here
with the information you have provided. This error:

> puppetdb.resnet.bris.ac.uk:8081: Connection refused - connect(2)

Its very rare that a bug in a running piece of code/framework whatever
will cause a connection refused (destination port unreachable) message
on its own, its usually because the port and IP you are connecting to
is wrong and your client never got to connect to your application.
Thus its the kernel that returns the error, not the application.

So generally, this doesn't marry up in my mind with this error message:

> 2013-11-27 12:09:58,347 WARN [qtp1710594959-45] [io.nio]
> javax.net.ssl.SSLException: Inbound closed before receiving peer's
> close_notify: possible truncation attack?

This implies you _did_ connect. In short I almost believe these are
somehow unrelated, or we're mixing errors here. The SSL error is most
definitely concerning, but doesn't make sense with the connection
refused message. A connection refused usually happens long before the
client gets to the serving application, if you see what I mean :-).

Can you test the port with 'telnet puppetdb.resnet.bris.ac.uk 8081'
from the puppet master and confirm the connection refused manually?
Also - can you make sure these errors truly to correlate? Try to
reproduce both at the same time if you can. Also make sure no other
traffic is going to the PuppetDB web server at the same time.

The details for how the master connects to the PuppetDB instance is in
/etc/puppet/puppetdb.conf, double check these are correct and that the
hostname resolves to what you think it does. Also check you don't have
any firewalling enabled, its rare but firewalls can throw destination
port unreachable also.

Now the SSL error is valid and concerning to me on a separate level. I
have a whole bunch of questions though:

* What _exact_ version of the JDK is PuppetDB using? The output of
'jinfo <pid>' (pid of the jvm process for puppetdb) would be helpful
here, and the exact package revision from Centos.
* What exact version of PuppetDB are you running?
* Are you sure it was just openssl that was upgraded? Not java as
well? Double check your yum.log or whatever.
* Have you tried downgrading the recently upgraded packages to see if
it solves it? If it was an upgrade that caused it, a downgrade and
restart of PuppetDB should solve it in theory. I'd be interested if
this works, and what packages you downgraded to.
* Can you show the full stack trace from the PuppetDB log, if there is
more to it.

ken.

[Darin Perusich]

If your runnning jdk 6u26 or older you're probably hitting these bugs.
I had this same error with the OpenDJ LDAP server a few years back and
upgrading the JDK fixed it.

http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6932403
http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=7025227

[Jonathan Gazeley]

On 27/11/13 14:55, Ken Barber wrote:
> This all sounds pretty serious, but something isn't quite right here
> with the information you have provided. This error:
>
>> >puppetdb.resnet.bris.ac.uk:8081: Connection refused - connect(2)
> Its very rare that a bug in a running piece of code/framework whatever
> will cause a connection refused (destination port unreachable) message
> on its own, its usually because the port and IP you are connecting to
> is wrong and your client never got to connect to your application.
> Thus its the kernel that returns the error, not the application.

Sorry, my mistake. This is the message I am getting - the above message
was the result of some of my tinkering.

Error: Could not retrieve catalog from remote server: Error 400 on
SERVER: Failed to submit 'replace facts' command for
radius-dev.nomadic-core.bris.ac.uk to PuppetDB at

puppetdb.resnet.bris.ac.uk:8081: SSL_connect returned=1 errno=0
state=SSLv3 read server key exchange B: EC lib
Warning: Not using cache on failed catalog
Error: Could not retrieve catalog; skipping run

[Jonathan Gazeley]

Oops, I was a bit premature firing off my previous response. Here are
the responses to your questions - and thanks very much for your help.
Sorry for the massive email...

On 27/11/13 14:55, Ken Barber wrote:

> * What_exact_ version of the JDK is PuppetDB using? The output of

> 'jinfo <pid>' (pid of the jvm process for puppetdb) would be helpful
> here, and the exact package revision from Centos.

[jg4461@puppetdb log]$ yum list installed java*
Installed Packages
java-1.6.0-openjdk.x86_64 1:1.6.0.0-1.66.1.13.0.el6 @cr
java-1.6.0-openjdk-devel.x86_64

[jg4461@puppetdb log]$ sudo jinfo 12199
Attaching to process ID 12199, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 23.25-b01
Java System Properties:

org.apache.kahadb.util.LockFile.lock./var/lib/puppetdb/mq/localhost/KahaDB/lock
= Wed Nov 27 13:24:14 GMT 2013
java.runtime.name = OpenJDK Runtime Environment
java.vm.version = 23.25-b01
sun.boot.library.path =
/usr/lib/jvm/java-1.6.0-openjdk-1.6.0.0.x86_64/jre/lib/amd64
java.vendor.url = http://java.sun.com/
java.vm.vendor = Sun Microsystems Inc.
path.separator = :
file.encoding.pkg = sun.io
java.vm.name = OpenJDK 64-Bit Server VM
sun.os.patch.level = unknown
user.country = GB
sun.java.launcher = SUN_STANDARD
user.dir = /
java.vm.specification.name = Java Virtual Machine Specification
java.runtime.version = 1.6.0_28-b28
java.awt.graphicsenv = sun.awt.X11GraphicsEnvironment
os.arch = amd64
java.endorsed.dirs =
/usr/lib/jvm/java-1.6.0-openjdk-1.6.0.0.x86_64/jre/lib/endorsed
java.io.tmpdir = /tmp
line.separator =

java.vm.specification.vendor = Sun Microsystems Inc.
os.name = Linux
sun.jnu.encoding = ISO-8859-1
java.library.path =
/usr/lib/jvm/java-1.6.0-openjdk-1.6.0.0.x86_64/jre/lib/amd64/server:/usr/lib/jvm/java-1.6.0-openjdk-1.6.0.0.x86_64/jre/lib/amd64:/usr/lib/jvm/java-1.6.0-openjdk-1.6.0.0.x86_64/jre/../lib/amd64:/usr/java/packages/lib/amd64:/usr/lib64:/lib64:/lib:/usr/lib
java.specification.name = Java Platform API Specification
java.class.version = 50.0
sun.management.compiler = HotSpot 64-Bit Tiered Compilers
os.version = 2.6.32-431.el6.x86_64
user.home = /usr/share/puppetdb
user.timezone = Europe/London
java.awt.printerjob = sun.print.PSPrinterJob
file.encoding = ISO-8859-1
java.specification.version = 1.6
user.name = puppetdb
java.class.path = /usr/share/puppetdb/puppetdb.jar
java.vm.specification.version = 1.0
sun.arch.data.model = 64
sun.java.command = /usr/share/puppetdb/puppetdb.jar services -c
/etc/puppetdb/conf.d
java.home = /usr/lib/jvm/java-1.6.0-openjdk-1.6.0.0.x86_64/jre
user.language = en
java.specification.vendor = Sun Microsystems Inc.
org.apache.kahadb.util.LockFile.lock./var/lib/puppetdb/mq/localhost/scheduler/lock
= Wed Nov 27 13:24:14 GMT 2013
java.vm.info = mixed mode
java.version = 1.6.0_28
java.ext.dirs =
/usr/lib/jvm/java-1.6.0-openjdk-1.6.0.0.x86_64/jre/lib/ext:/usr/java/packages/lib/ext
sun.boot.class.path =
/usr/lib/jvm/java-1.6.0-openjdk-1.6.0.0.x86_64/jre/lib/resources.jar:/usr/lib/jvm/java-1.6.0-openjdk-1.6.0.0.x86_64/jre/lib/rt.jar:/usr/lib/jvm/java-1.6.0-openjdk-1.6.0.0.x86_64/jre/lib/sunrsasign.jar:/usr/lib/jvm/java-1.6.0-openjdk-1.6.0.0.x86_64/jre/lib/jsse.jar:/usr/lib/jvm/java-1.6.0-openjdk-1.6.0.0.x86_64/jre/lib/jce.jar:/usr/lib/jvm/java-1.6.0-openjdk-1.6.0.0.x86_64/jre/lib/charsets.jar:/usr/lib/jvm/java-1.6.0-openjdk-1.6.0.0.x86_64/jre/lib/jfr.jar:/usr/lib/jvm/java-1.6.0-openjdk-1.6.0.0.x86_64/jre/lib/netx.jar:/usr/lib/jvm/java-1.6.0-openjdk-1.6.0.0.x86_64/jre/lib/plugin.jar:/usr/lib/jvm/java-1.6.0-openjdk-1.6.0.0.x86_64/jre/lib/rhino.jar:/usr/lib/jvm/java-1.6.0-openjdk-1.6.0.0.x86_64/jre/classes
java.vendor = Sun Microsystems Inc.
file.separator = /
java.vendor.url.bug = http://java.sun.com/cgi-bin/bugreport.cgi
sun.io.unicode.encoding = UnicodeLittle
sun.cpu.endian = little
sun.cpu.isalist =

VM Flags:

-XX:OnOutOfMemoryError=kill -9 %p -Xmx192m
-XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath=/var/log/puppetdb/puppetdb-oom.hprof

> * What exact version of PuppetDB are you running?

puppetdb-1.5.2-1.el6, from puppetlabs-products

> * Are you sure it was just openssl that was upgraded? Not java as
> well? Double check your yum.log or whatever.

Hmm. Java was indeed updated. I'm not suyre which version we were
running before - whatever was latest in the 1.6.0 series from CentOS 6
(including CR)

Nov 27 10:18:22 Updated: 1:java-1.6.0-openjdk-1.6.0.0-1.66.1.13.0.el6.x86_64

> * Have you tried downgrading the recently upgraded packages to see if
> it solves it? If it was an upgrade that caused it, a downgrade and
> restart of PuppetDB should solve it in theory. I'd be interested if
> this works, and what packages you downgraded to.

I tried downgrading openssl which was not possible, because half the OS
is pinned to the new version. I just noted that java-1.7.0 is available
and I will try upgrading to that next, if you think that is a wise move.

> * Can you show the full stack trace from the PuppetDB log, if there is
> more to it.

2013-11-27 13:02:24,921 DEBUG [main] [puppetlabs.utils] Debug logging enabled
2013-11-27 13:02:25,251 DEBUG [main] [puppetlabs.ssl] Loaded PEM
object of type 'class
org.bouncycastle.jcajce.provider.asymmetric.x509.X509CertificateObject'
from '/etc/puppetdb/ssl/ca.pem'
2013-11-27 13:02:25,276 DEBUG [main] [puppetlabs.ssl] Loaded PEM
object of type 'class java.security.KeyPair' from
'/etc/puppetdb/ssl/private.pem'
2013-11-27 13:02:25,278 DEBUG [main] [puppetlabs.ssl] Loaded PEM
object of type 'class
org.bouncycastle.jcajce.provider.asymmetric.x509.X509CertificateObject'
from '/etc/puppetdb/ssl/public.pem'
2013-11-27 13:02:25,376 INFO [main] [cli.services] PuppetDB version 1.5.2
2013-11-27 13:02:25,377 DEBUG [main] [bonecp.BoneCPDataSource] JDBC
URL = jdbc:postgresql://pg-p11.isys.bris.ac.uk:5432/resnet_puppet,
Username = resnet_puppet, partitions = 1, max (per partition) = 50,
min (per partition) = 1, helper threads = 3, idle max age = 60 min,
idle test period = 45 min
2013-11-27 13:02:25,473 DEBUG [main] [bonecp.PreparedStatementHandle]
SELECT version FROM schema_migrations ORDER BY version
2013-11-27 13:02:25,507 DEBUG [main] [bonecp.PreparedStatementHandle]
SELECT version FROM schema_migrations ORDER BY version
2013-11-27 13:02:25,521 INFO [main] [cli.services] Starting broker
2013-11-27 13:02:25,832 DEBUG [main] [index.BTreeIndex] loading
2013-11-27 13:02:25,837 DEBUG [main] [index.BTreeIndex] loading
2013-11-27 13:02:25,837 DEBUG [main] [index.BTreeIndex] loading
2013-11-27 13:02:25,837 DEBUG [main] [index.BTreeIndex] loading
2013-11-27 13:02:25,838 DEBUG [main] [index.BTreeIndex] loading
2013-11-27 13:02:25,838 DEBUG [main] [index.BTreeIndex] loading
2013-11-27 13:02:26,397 DEBUG [main] [index.BTreeIndex] loading
2013-11-27 13:02:26,397 DEBUG [main] [index.BTreeIndex] loading
2013-11-27 13:02:26,400 DEBUG [main] [index.BTreeIndex] loading
2013-11-27 13:02:26,488 WARN [main] [broker.BrokerService] Store
limit is 100000 mb, whilst the data directory:
/var/lib/puppetdb/mq/localhost/KahaDB only has 4495 mb of usable space
2013-11-27 13:02:26,488 ERROR [main] [broker.BrokerService] Temporary
Store limit is 50000 mb, whilst the temporary data directory:
/var/lib/puppetdb/mq/localhost/tmp_storage only has 4495 mb of usable
space
2013-11-27 13:02:26,488 INFO [main] [cli.services] Starting 2 command
processor threads
2013-11-27 13:02:26,690 INFO [main] [cli.services] Starting query server
2013-11-27 13:02:26,729 DEBUG [clojure-agent-send-off-pool-3]
[component.Container] Container
org.eclipse.jetty.server.Server@44045db0 +
SelectChann...@puppetdb.resnet.bris.ac.uk:8080 as connector
2013-11-27 13:02:26,741 INFO [pool-2-thread-1] [cli.services]
Starting database garbage collection
2013-11-27 13:02:26,773 DEBUG [pool-2-thread-1]
[bonecp.StatementHandle] DELETE FROM catalogs WHERE NOT EXISTS (SELECT
* FROM certname_catalogs cc WHERE cc.catalog=catalogs.hash)
2013-11-27 13:02:26,785 DEBUG [clojure-agent-send-off-pool-3]
[component.Container] Container
org.eclipse.jetty.server.Server@44045db0 +
SslSelectCha...@puppetdb.resnet.bris.ac.uk:8081 as connector
2013-11-27 13:02:26,786 DEBUG [clojure-agent-send-off-pool-3]
[component.Container] Container
org.eclipse.jetty.server.Server@44045db0 +
ring.adapter.jetty.proxy$org.eclipse.jetty.server.handler.AbstractHandler$0@65d8c3bc
as handler
2013-11-27 13:02:26,787 DEBUG [clojure-agent-send-off-pool-3]
[component.Container] Container
org.eclipse.jetty.server.Server@44045db0 + qtp815329945{8<=0<=0/50,-1}
as threadpool
2013-11-27 13:02:26,787 DEBUG [clojure-agent-send-off-pool-3]
[component.AbstractLifeCycle] starting
org.eclipse.jetty.server.Server@44045db0
2013-11-27 13:02:26,787 INFO [clojure-agent-send-off-pool-3]
[server.Server] jetty-7.x.y-SNAPSHOT
2013-11-27 13:02:26,799 DEBUG [clojure-agent-send-off-pool-1]
[listener.DefaultMessageListenerContainer] Established shared JMS
Connection
2013-11-27 13:02:26,799 DEBUG [clojure-agent-send-off-pool-0]
[listener.DefaultMessageListenerContainer] Established shared JMS
Connection
2013-11-27 13:02:26,811 DEBUG [pool-2-thread-1]
[bonecp.StatementHandle] DELETE FROM resource_params WHERE NOT EXISTS
(SELECT * FROM catalog_resources cr WHERE
cr.resource=resource_params.resource)
2013-11-27 13:02:26,836 DEBUG [clojure-agent-send-off-pool-3]
[component.AbstractLifeCycle] starting
ring.adapter.jetty.proxy$org.eclipse.jetty.server.handler.AbstractHandler$0@65d8c3bc
2013-11-27 13:02:26,836 DEBUG [clojure-agent-send-off-pool-3]
[handler.AbstractHandler] starting
ring.adapter.jetty.proxy$org.eclipse.jetty.server.handler.AbstractHandler$0@65d8c3bc
2013-11-27 13:02:26,836 DEBUG [clojure-agent-send-off-pool-3]
[component.AbstractLifeCycle] STARTED
ring.adapter.jetty.proxy$org.eclipse.jetty.server.handler.AbstractHandler$0@65d8c3bc
2013-11-27 13:02:26,836 DEBUG [clojure-agent-send-off-pool-3]
[handler.AbstractHandler] starting
org.eclipse.jetty.server.Server@44045db0
2013-11-27 13:02:26,836 DEBUG [clojure-agent-send-off-pool-3]
[component.AbstractLifeCycle] starting qtp815329945{8<=0<=0/50,-1}
2013-11-27 13:02:26,856 DEBUG [clojure-agent-send-off-pool-3]
[component.AbstractLifeCycle] STARTED qtp815329945{8<=6<=8/50,0}
2013-11-27 13:02:26,856 DEBUG [clojure-agent-send-off-pool-3]
[component.AbstractLifeCycle] starting
SelectChann...@puppetdb.resnet.bris.ac.uk:8080
2013-11-27 13:02:26,866 DEBUG [clojure-agent-send-off-pool-3]
[component.AbstractLifeCycle] starting null/null
2013-11-27 13:02:26,871 DEBUG [clojure-agent-send-off-pool-3]
[component.AbstractLifeCycle] STARTED PooledBuffers
[0/1024@6144,0/1024@16384,0/1024@-]/PooledBuffers
[0/1024@6144,0/1024@32768,0/1024@-]
2013-11-27 13:02:26,871 DEBUG [clojure-agent-send-off-pool-3]
[component.AbstractLifeCycle] starting
org.eclipse.jetty.server.nio.SelectChannelConnector$ConnectorSelectorManager@762e0806
2013-11-27 13:02:26,885 DEBUG [qtp815329945-41 Selector0] [io.nio]
Starting Thread[qtp815329945-41 Selector0,5,main] on
org.eclipse.jetty.io.nio.SelectorManager$1@3f730eb1
2013-11-27 13:02:26,885 DEBUG [clojure-agent-send-off-pool-3]
[component.AbstractLifeCycle] STARTED
org.eclipse.jetty.server.nio.SelectChannelConnector$ConnectorSelectorManager@762e0806
2013-11-27 13:02:26,890 INFO [clojure-agent-send-off-pool-3]
[server.AbstractConnector] Started
SelectChann...@puppetdb.resnet.bris.ac.uk:8080
2013-11-27 13:02:26,890 DEBUG [clojure-agent-send-off-pool-3]
[component.AbstractLifeCycle] STARTED
SelectChann...@puppetdb.resnet.bris.ac.uk:8080
2013-11-27 13:02:26,890 DEBUG [clojure-agent-send-off-pool-3]
[component.AbstractLifeCycle] starting
SslSelectCha...@puppetdb.resnet.bris.ac.uk:8081
2013-11-27 13:02:26,895 DEBUG [clojure-agent-send-off-pool-3]
[component.AbstractLifeCycle] starting
SslContextFactory@d1763cc(null,null)
2013-11-27 13:02:26,912 DEBUG [clojure-agent-send-off-pool-2]
[conn.SingleClientConnManager] Get connection for route
{}->http://updates.puppetlabs.com
2013-11-27 13:02:26,946 DEBUG [clojure-agent-send-off-pool-2]
[conn.DefaultClientConnectionOperator] Connecting to
updates.puppetlabs.com:80
2013-11-27 13:02:27,019 INFO [clojure-agent-send-off-pool-3]
[ssl.SslContextFactory] Enabled Protocols [SSLv2Hello, SSLv3, TLSv1]
of [SSLv2Hello, SSLv3, TLSv1]
2013-11-27 13:02:27,020 DEBUG [clojure-agent-send-off-pool-3]
[ssl.SslContextFactory] Enabled Ciphers [SSL_RSA_WITH_RC4_128_MD5,
SSL_RSA_WITH_RC4_128_SHA, TLS_RSA_WITH_AES_128_CBC_SHA,
TLS_RSA_WITH_AES_256_CBC_SHA, TLS_ECDH_ECDSA_WITH_RC4_128_SHA,
TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA,
TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA, TLS_ECDH_RSA_WITH_RC4_128_SHA,
TLS_ECDH_RSA_WITH_AES_128_CBC_SHA, TLS_ECDH_RSA_WITH_AES_256_CBC_SHA,
TLS_ECDHE_ECDSA_WITH_RC4_128_SHA,
TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA,
TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA, TLS_ECDHE_RSA_WITH_RC4_128_SHA,
TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA,
TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA, TLS_DHE_RSA_WITH_AES_128_CBC_SHA,
TLS_DHE_RSA_WITH_AES_256_CBC_SHA, TLS_DHE_DSS_WITH_AES_128_CBC_SHA,
TLS_DHE_DSS_WITH_AES_256_CBC_SHA, SSL_RSA_WITH_3DES_EDE_CBC_SHA,
TLS_ECDH_ECDSA_WITH_3DES_EDE_CBC_SHA,
TLS_ECDH_RSA_WITH_3DES_EDE_CBC_SHA,
TLS_ECDHE_ECDSA_WITH_3DES_EDE_CBC_SHA,
TLS_ECDHE_RSA_WITH_3DES_EDE_CBC_SHA,
SSL_DHE_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_DSS_WITH_3DES_EDE_CBC_SHA,
SSL_RSA_WITH_DES_CBC_SHA, SSL_DHE_RSA_WITH_DES_CBC_SHA,
SSL_DHE_DSS_WITH_DES_CBC_SHA, SSL_RSA_EXPORT_WITH_RC4_40_MD5,
SSL_RSA_EXPORT_WITH_DES40_CBC_SHA,
SSL_DHE_RSA_EXPORT_WITH_DES40_CBC_SHA,
SSL_DHE_DSS_EXPORT_WITH_DES40_CBC_SHA,
TLS_EMPTY_RENEGOTIATION_INFO_SCSV] of [SSL_RSA_WITH_RC4_128_MD5,
SSL_RSA_WITH_RC4_128_SHA, TLS_RSA_WITH_AES_128_CBC_SHA,
TLS_RSA_WITH_AES_256_CBC_SHA, TLS_ECDH_ECDSA_WITH_RC4_128_SHA,
TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA,
TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA, TLS_ECDH_RSA_WITH_RC4_128_SHA,
TLS_ECDH_RSA_WITH_AES_128_CBC_SHA, TLS_ECDH_RSA_WITH_AES_256_CBC_SHA,
TLS_ECDHE_ECDSA_WITH_RC4_128_SHA,
TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA,
TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA, TLS_ECDHE_RSA_WITH_RC4_128_SHA,
TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA,
TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA, TLS_DHE_RSA_WITH_AES_128_CBC_SHA,
TLS_DHE_RSA_WITH_AES_256_CBC_SHA, TLS_DHE_DSS_WITH_AES_128_CBC_SHA,
TLS_DHE_DSS_WITH_AES_256_CBC_SHA, SSL_RSA_WITH_3DES_EDE_CBC_SHA,
TLS_ECDH_ECDSA_WITH_3DES_EDE_CBC_SHA,
TLS_ECDH_RSA_WITH_3DES_EDE_CBC_SHA,
TLS_ECDHE_ECDSA_WITH_3DES_EDE_CBC_SHA,
TLS_ECDHE_RSA_WITH_3DES_EDE_CBC_SHA,
SSL_DHE_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_DSS_WITH_3DES_EDE_CBC_SHA,
SSL_RSA_WITH_DES_CBC_SHA, SSL_DHE_RSA_WITH_DES_CBC_SHA,
SSL_DHE_DSS_WITH_DES_CBC_SHA, SSL_RSA_EXPORT_WITH_RC4_40_MD5,
SSL_RSA_EXPORT_WITH_DES40_CBC_SHA,
SSL_DHE_RSA_EXPORT_WITH_DES40_CBC_SHA,
SSL_DHE_DSS_EXPORT_WITH_DES40_CBC_SHA,
TLS_EMPTY_RENEGOTIATION_INFO_SCSV, SSL_RSA_WITH_NULL_MD5,
SSL_RSA_WITH_NULL_SHA, TLS_ECDH_ECDSA_WITH_NULL_SHA,
TLS_ECDH_RSA_WITH_NULL_SHA, TLS_ECDHE_ECDSA_WITH_NULL_SHA,
TLS_ECDHE_RSA_WITH_NULL_SHA, SSL_DH_anon_WITH_RC4_128_MD5,
TLS_DH_anon_WITH_AES_128_CBC_SHA, TLS_DH_anon_WITH_AES_256_CBC_SHA,
SSL_DH_anon_WITH_3DES_EDE_CBC_SHA, SSL_DH_anon_WITH_DES_CBC_SHA,
TLS_ECDH_anon_WITH_RC4_128_SHA, TLS_ECDH_anon_WITH_AES_128_CBC_SHA,
TLS_ECDH_anon_WITH_AES_256_CBC_SHA,
TLS_ECDH_anon_WITH_3DES_EDE_CBC_SHA,
SSL_DH_anon_EXPORT_WITH_RC4_40_MD5,
SSL_DH_anon_EXPORT_WITH_DES40_CBC_SHA, TLS_ECDH_anon_WITH_NULL_SHA,
TLS_KRB5_WITH_RC4_128_SHA, TLS_KRB5_WITH_RC4_128_MD5,
TLS_KRB5_WITH_3DES_EDE_CBC_SHA, TLS_KRB5_WITH_3DES_EDE_CBC_MD5,
TLS_KRB5_WITH_DES_CBC_SHA, TLS_KRB5_WITH_DES_CBC_MD5,
TLS_KRB5_EXPORT_WITH_RC4_40_SHA, TLS_KRB5_EXPORT_WITH_RC4_40_MD5,
TLS_KRB5_EXPORT_WITH_DES_CBC_40_SHA,
TLS_KRB5_EXPORT_WITH_DES_CBC_40_MD5]
2013-11-27 13:02:27,020 DEBUG [clojure-agent-send-off-pool-3]
[component.AbstractLifeCycle] STARTED
SslContextFactory@d1763cc(null,null)
2013-11-27 13:02:27,022 DEBUG [clojure-agent-send-off-pool-3]
[component.AbstractLifeCycle] starting null/null
2013-11-27 13:02:27,022 DEBUG [clojure-agent-send-off-pool-3]
[component.AbstractLifeCycle] STARTED PooledBuffers
[0/1024@16660,0/1024@16660,0/1024@-]/PooledBuffers
[0/1024@6144,0/1024@32768,0/1024@-]
2013-11-27 13:02:27,022 DEBUG [clojure-agent-send-off-pool-3]
[component.AbstractLifeCycle] starting
org.eclipse.jetty.server.nio.SelectChannelConnector$ConnectorSelectorManager@4b4a1467
2013-11-27 13:02:27,025 DEBUG [qtp815329945-43 Selector0] [io.nio]
Starting Thread[qtp815329945-43 Selector0,5,main] on
org.eclipse.jetty.io.nio.SelectorManager$1@6c819cce
2013-11-27 13:02:27,026 DEBUG [clojure-agent-send-off-pool-3]
[component.AbstractLifeCycle] STARTED
org.eclipse.jetty.server.nio.SelectChannelConnector$ConnectorSelectorManager@4b4a1467
2013-11-27 13:02:27,026 INFO [clojure-agent-send-off-pool-3]
[server.AbstractConnector] Started
SslSelectCha...@puppetdb.resnet.bris.ac.uk:8081
2013-11-27 13:02:27,026 DEBUG [clojure-agent-send-off-pool-3]
[component.AbstractLifeCycle] STARTED
SslSelectCha...@puppetdb.resnet.bris.ac.uk:8081
2013-11-27 13:02:27,027 DEBUG [clojure-agent-send-off-pool-3]
[component.AbstractLifeCycle] STARTED
org.eclipse.jetty.server.Server@44045db0
2013-11-27 13:02:27,058 DEBUG [clojure-agent-send-off-pool-2]
[protocol.RequestAddCookies] CookieSpec selected: compatibility
2013-11-27 13:02:27,063 DEBUG [clojure-agent-send-off-pool-2]
[protocol.RequestAuthCache] Auth cache not set in the context
2013-11-27 13:02:27,063 DEBUG [clojure-agent-send-off-pool-2]
[protocol.RequestTargetAuthentication] Target auth state: UNCHALLENGED
2013-11-27 13:02:27,064 DEBUG [clojure-agent-send-off-pool-2]
[protocol.RequestProxyAuthentication] Proxy auth state: UNCHALLENGED
2013-11-27 13:02:27,064 DEBUG [clojure-agent-send-off-pool-2]
[client.DefaultHttpClient] Attempt 1 to execute request
2013-11-27 13:02:27,064 DEBUG [clojure-agent-send-off-pool-2]
[conn.DefaultClientConnection] Sending request: GET
/check-for-updates?product=puppetdb&version=1.5.2&database-name=PostgreSQL&database-version=9.1
HTTP/1.1
2013-11-27 13:02:27,064 DEBUG [clojure-agent-send-off-pool-2]
[http.wire] >> "GET
/check-for-updates?product=puppetdb&version=1.5.2&database-name=PostgreSQL&database-version=9.1
HTTP/1.1[\r][\n]"
2013-11-27 13:02:27,065 DEBUG [clojure-agent-send-off-pool-2]
[http.wire] >> "Connection: close[\r][\n]"
2013-11-27 13:02:27,066 DEBUG [clojure-agent-send-off-pool-2]
[http.wire] >> "accept-encoding: gzip, deflate[\r][\n]"
2013-11-27 13:02:27,066 DEBUG [clojure-agent-send-off-pool-2]
[http.wire] >> "accept: application/json[\r][\n]"
2013-11-27 13:02:27,066 DEBUG [clojure-agent-send-off-pool-2]
[http.wire] >> "Content-Length: 0[\r][\n]"
2013-11-27 13:02:27,066 DEBUG [clojure-agent-send-off-pool-2]
[http.wire] >> "Host: updates.puppetlabs.com[\r][\n]"
2013-11-27 13:02:27,066 DEBUG [clojure-agent-send-off-pool-2]
[http.wire] >> "User-Agent: Apache-HttpClient/4.2.1 (java
1.5)[\r][\n]"
2013-11-27 13:02:27,066 DEBUG [clojure-agent-send-off-pool-2]
[http.wire] >> "[\r][\n]"
2013-11-27 13:02:27,066 DEBUG [clojure-agent-send-off-pool-2]
[http.headers] >> GET
/check-for-updates?product=puppetdb&version=1.5.2&database-name=PostgreSQL&database-version=9.1
HTTP/1.1
2013-11-27 13:02:27,066 DEBUG [clojure-agent-send-off-pool-2]
[http.headers] >> Connection: close
2013-11-27 13:02:27,066 DEBUG [clojure-agent-send-off-pool-2]
[http.headers] >> accept-encoding: gzip, deflate
2013-11-27 13:02:27,066 DEBUG [clojure-agent-send-off-pool-2]
[http.headers] >> accept: application/json
2013-11-27 13:02:27,066 DEBUG [clojure-agent-send-off-pool-2]
[http.headers] >> Content-Length: 0
2013-11-27 13:02:27,067 DEBUG [clojure-agent-send-off-pool-2]
[http.headers] >> Host: updates.puppetlabs.com
2013-11-27 13:02:27,067 DEBUG [clojure-agent-send-off-pool-2]
[http.headers] >> User-Agent: Apache-HttpClient/4.2.1 (java 1.5)
2013-11-27 13:02:27,103 INFO [pool-2-thread-1] [cli.services]
Finished database garbage collection
2013-11-27 13:02:27,106 INFO [pool-2-thread-1] [cli.services]
Starting sweep of stale reports (threshold: 14 days)
2013-11-27 13:02:27,109 DEBUG [pool-2-thread-1]
[bonecp.StatementHandle] DELETE FROM reports WHERE end_time <
2013-11-13 13:02:27.107
2013-11-27 13:02:27,113 INFO [pool-2-thread-1] [cli.services]
Finished sweep of stale reports (threshold: 14 days)
2013-11-27 13:02:27,163 DEBUG [clojure-agent-send-off-pool-2]
[http.wire] << "HTTP/1.1 200 OK[\r][\n]"
2013-11-27 13:02:27,164 DEBUG [clojure-agent-send-off-pool-2]
[http.wire] << "Server: nginx/1.2.4[\r][\n]"
2013-11-27 13:02:27,164 DEBUG [clojure-agent-send-off-pool-2]
[http.wire] << "Date: Wed, 27 Nov 2013 13:02:27 GMT[\r][\n]"
2013-11-27 13:02:27,164 DEBUG [clojure-agent-send-off-pool-2]
[http.wire] << "Content-Length: 101[\r][\n]"
2013-11-27 13:02:27,164 DEBUG [clojure-agent-send-off-pool-2]
[http.wire] << "Connection: close[\r][\n]"
2013-11-27 13:02:27,164 DEBUG [clojure-agent-send-off-pool-2]
[http.wire] << "[\r][\n]"
2013-11-27 13:02:27,165 DEBUG [clojure-agent-send-off-pool-2]
[conn.DefaultClientConnection] Receiving response: HTTP/1.1 200 OK
2013-11-27 13:02:27,165 DEBUG [clojure-agent-send-off-pool-2]
[http.headers] << HTTP/1.1 200 OK
2013-11-27 13:02:27,165 DEBUG [clojure-agent-send-off-pool-2]
[http.headers] << Server: nginx/1.2.4
2013-11-27 13:02:27,165 DEBUG [clojure-agent-send-off-pool-2]
[http.headers] << Date: Wed, 27 Nov 2013 13:02:27 GMT
2013-11-27 13:02:27,165 DEBUG [clojure-agent-send-off-pool-2]
[http.headers] << Content-Length: 101
2013-11-27 13:02:27,165 DEBUG [clojure-agent-send-off-pool-2]
[http.headers] << Connection: close
2013-11-27 13:02:27,171 DEBUG [clojure-agent-send-off-pool-2]
[http.wire] << "{"newer":false,"link":"http://docs.puppetlabs.com/puppetdb/1.5/release_notes.html","version":"1.5.2"}"
2013-11-27 13:02:27,171 DEBUG [clojure-agent-send-off-pool-2]
[conn.SingleClientConnManager] Releasing connection
org.apache.http.impl.conn.SingleClientConnManager$ConnAdapter@105ef941
2013-11-27 13:02:27,171 DEBUG [clojure-agent-send-off-pool-2]
[conn.SingleClientConnManager] Released connection open but not
reusable.
2013-11-27 13:02:27,172 DEBUG [clojure-agent-send-off-pool-2]
[conn.DefaultClientConnection] Connection
0.0.0.0:35345<->50.116.41.135:80 shut down
2013-11-27 13:02:31,246 DEBUG [qtp815329945-43 Selector0] [io.nio]
created SCEP@59364878{l(/172.16.67.40:47119)<->r(/172.16.67.25:8081),d=false,open=true,ishut=false,oshut=false,rb=false,wb=false,w=true,i=0}-{SslConnection@7acfec09
SSL NOT_HANDSHAKING i/o/u=-1/-1/-1 ishut=false oshut=false
{AsyncHttpConnection@208a2053,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-14,l=0,c=0},r=0}}
2013-11-27 13:02:31,250 DEBUG [qtp815329945-45] [nio.ssl] [Session-1,
SSL_NULL_WITH_NULL_NULL] SslConnection@7acfec09 SSL NOT_HANDSHAKING
i/o/u=307/0/0 ishut=false oshut=false
{AsyncHttpConnection@208a2053,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-14,l=0,c=0},r=0}
NOT_HANDSHAKING filled=307/307 flushed=0/0
2013-11-27 13:02:31,255 DEBUG [qtp815329945-45] [nio.ssl] [Session-1,
SSL_NULL_WITH_NULL_NULL] unwrap OK NEED_TASK consumed=307 produced=0
2013-11-27 13:02:31,256 DEBUG [qtp815329945-45] [nio.ssl] [Session-1,
SSL_NULL_WITH_NULL_NULL] SslConnection@7acfec09 SSL NEED_TASK
i/o/u=0/0/0 ishut=false oshut=false
{AsyncHttpConnection@208a2053,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-14,l=0,c=0},r=0}
NEED_TASK filled=0/0 flushed=0/0
2013-11-27 13:02:31,280 DEBUG [qtp815329945-43 Selector0] [io.nio]
created SCEP@7238621d{l(/172.16.67.40:47120)<->r(/172.16.67.25:8081),d=false,open=true,ishut=false,oshut=false,rb=false,wb=false,w=true,i=0}-{SslConnection@53b19880
SSL NOT_HANDSHAKING i/o/u=-1/-1/-1 ishut=false oshut=false
{AsyncHttpConnection@6b664f03,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-14,l=0,c=0},r=0}}
2013-11-27 13:02:31,281 DEBUG [qtp815329945-46] [nio.ssl] [Session-1,
SSL_NULL_WITH_NULL_NULL] SslConnection@53b19880 SSL NOT_HANDSHAKING
i/o/u=307/0/0 ishut=false oshut=false
{AsyncHttpConnection@6b664f03,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-14,l=0,c=0},r=0}
NOT_HANDSHAKING filled=307/307 flushed=0/0
2013-11-27 13:02:31,282 DEBUG [qtp815329945-46] [nio.ssl] [Session-1,
SSL_NULL_WITH_NULL_NULL] unwrap OK NEED_TASK consumed=307 produced=0
2013-11-27 13:02:31,282 DEBUG [qtp815329945-46] [nio.ssl] [Session-1,
SSL_NULL_WITH_NULL_NULL] SslConnection@53b19880 SSL NEED_TASK
i/o/u=0/0/0 ishut=false oshut=false
{AsyncHttpConnection@6b664f03,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-14,l=0,c=0},r=0}
NEED_TASK filled=0/0 flushed=0/0
2013-11-27 13:02:31,846 DEBUG [qtp815329945-45] [nio.ssl] [Session-1,
SSL_NULL_WITH_NULL_NULL] SslConnection@7acfec09 SSL NEED_WRAP
i/o/u=0/0/0 ishut=false oshut=false
{AsyncHttpConnection@208a2053,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-14,l=0,c=0},r=0}
NEED_WRAP filled=0/0 flushed=0/0
2013-11-27 13:02:31,846 DEBUG [qtp815329945-45] [nio.ssl] [Session-1,
SSL_NULL_WITH_NULL_NULL] wrap OK NEED_UNWRAP consumed=0 produced=2227
2013-11-27 13:02:31,847 DEBUG [qtp815329945-45] [nio.ssl] [Session-1,
SSL_NULL_WITH_NULL_NULL] SslConnection@7acfec09 SSL NEED_UNWRAP
i/o/u=0/0/0 ishut=false oshut=false
{AsyncHttpConnection@208a2053,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-14,l=0,c=0},r=0}
NEED_UNWRAP filled=0/0 flushed=2227/0
2013-11-27 13:02:31,847 DEBUG [qtp815329945-45] [nio.ssl] [Session-1,
SSL_NULL_WITH_NULL_NULL] SslConnection@7acfec09 SSL NEED_UNWRAP
i/o/u=0/0/0 ishut=false oshut=false
{AsyncHttpConnection@208a2053,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-14,l=0,c=0},r=0}
NEED_UNWRAP filled=0/0 flushed=0/0
2013-11-27 13:02:31,847 DEBUG [qtp815329945-45] [http.HttpParser] filled 0/0
2013-11-27 13:02:31,848 DEBUG [qtp815329945-45] [nio.ssl] [Session-1,
SSL_NULL_WITH_NULL_NULL] SslConnection@7acfec09 SSL NEED_UNWRAP
i/o/u=0/0/0 ishut=false oshut=false
{AsyncHttpConnection@208a2053,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-14,l=0,c=0},r=0}
NEED_UNWRAP filled=0/0 flushed=0/0
2013-11-27 13:02:31,848 DEBUG [qtp815329945-45] [nio.ssl] [Session-1,
SSL_NULL_WITH_NULL_NULL] SslConnection@7acfec09 SSL NEED_UNWRAP
i/o/u=0/0/0 ishut=false oshut=false
{AsyncHttpConnection@208a2053,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-14,l=0,c=0},r=0}
NEED_UNWRAP filled=0/0 flushed=0/0
2013-11-27 13:02:31,848 DEBUG [qtp815329945-45] [http.HttpParser] filled 0/0
2013-11-27 13:02:31,848 DEBUG [qtp815329945-46] [nio.ssl] [Session-1,
SSL_NULL_WITH_NULL_NULL] SslConnection@53b19880 SSL NEED_WRAP
i/o/u=0/0/0 ishut=false oshut=false
{AsyncHttpConnection@6b664f03,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-14,l=0,c=0},r=0}
NEED_WRAP filled=0/0 flushed=0/0
2013-11-27 13:02:31,852 DEBUG [qtp815329945-46] [nio.ssl] [Session-1,
SSL_NULL_WITH_NULL_NULL] wrap OK NEED_UNWRAP consumed=0 produced=2227
2013-11-27 13:02:31,852 DEBUG [qtp815329945-45] [nio.ssl] [Session-1,
SSL_NULL_WITH_NULL_NULL] SslConnection@7acfec09 SSL NEED_UNWRAP
i/o/u=0/0/0 ishut=false oshut=false
{AsyncHttpConnection@208a2053,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-14,l=0,c=0},r=0}
NEED_UNWRAP filled=0/0 flushed=0/0
2013-11-27 13:02:31,852 DEBUG [qtp815329945-46] [nio.ssl] [Session-1,
SSL_NULL_WITH_NULL_NULL] SslConnection@53b19880 SSL NEED_UNWRAP
i/o/u=0/0/0 ishut=false oshut=false
{AsyncHttpConnection@6b664f03,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-14,l=0,c=0},r=0}
NEED_UNWRAP filled=0/0 flushed=2227/0
2013-11-27 13:02:31,852 DEBUG [qtp815329945-45] [nio.ssl] [Session-1,
SSL_NULL_WITH_NULL_NULL] handle SslConnection@7acfec09 SSL NEED_UNWRAP
i/o/u=0/0/0 ishut=false oshut=false
{AsyncHttpConnection@208a2053,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-14,l=0,c=0},r=0}
progress=false
2013-11-27 13:02:31,853 DEBUG [qtp815329945-46] [nio.ssl] [Session-1,
SSL_NULL_WITH_NULL_NULL] SslConnection@53b19880 SSL NEED_UNWRAP
i/o/u=0/0/0 ishut=false oshut=false
{AsyncHttpConnection@6b664f03,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-14,l=0,c=0},r=0}
NEED_UNWRAP filled=0/0 flushed=0/0
2013-11-27 13:02:31,853 DEBUG [qtp815329945-46] [http.HttpParser] filled 0/0
2013-11-27 13:02:31,854 DEBUG [qtp815329945-46] [nio.ssl] [Session-1,
SSL_NULL_WITH_NULL_NULL] SslConnection@53b19880 SSL NEED_UNWRAP
i/o/u=0/0/0 ishut=false oshut=false
{AsyncHttpConnection@6b664f03,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-14,l=0,c=0},r=0}
NEED_UNWRAP filled=0/0 flushed=0/0
2013-11-27 13:02:31,854 DEBUG [qtp815329945-48] [nio.ChannelEndPoint]
ishut SCEP@59364878{l(/172.16.67.40:47119)<->r(/172.16.67.25:8081),d=true,open=true,ishut=false,oshut=false,rb=false,wb=false,w=true,i=1r}-{SslConnection@7acfec09
SSL NEED_UNWRAP i/o/u=0/0/0 ishut=false oshut=false
{AsyncHttpConnection@208a2053,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-14,l=0,c=0},r=0}}
2013-11-27 13:02:31,855 DEBUG [qtp815329945-48] [nio.ssl] [Session-1,
SSL_NULL_WITH_NULL_NULL] SslConnection@7acfec09 SSL NEED_UNWRAP
i/o/u=0/0/0 ishut=false oshut=false
{AsyncHttpConnection@208a2053,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-14,l=0,c=0},r=0}
NEED_UNWRAP filled=-1/0 flushed=0/0
2013-11-27 13:02:31,856 DEBUG [qtp815329945-48] [nio.ChannelEndPoint]
ishut SCEP@59364878{l(/172.16.67.40:47119)<->r(/172.16.67.25:8081),d=true,open=true,ishut=true,oshut=false,rb=false,wb=false,w=true,i=1r}-{SslConnection@7acfec09
SSL NEED_UNWRAP i/o/u=0/0/0 ishut=false oshut=false
{AsyncHttpConnection@208a2053,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-14,l=0,c=0},r=0}}
2013-11-27 13:02:31,856 DEBUG [qtp815329945-48] [nio.ssl] [Session-1,
SSL_NULL_WITH_NULL_NULL] ssl endp.close
2013-11-27 13:02:31,856 DEBUG [qtp815329945-48] [nio.ChannelEndPoint]
close SCEP@59364878{l(/172.16.67.40:47119)<->r(/172.16.67.25:8081),d=true,open=true,ishut=true,oshut=false,rb=false,wb=false,w=true,i=1r}-{SslConnection@7acfec09
SSL NEED_WRAP i/o/u=-1/-1/-1 ishut=true oshut=false
{AsyncHttpConnection@208a2053,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-14,l=0,c=0},r=0}}
2013-11-27 13:02:31,857 WARN [qtp815329945-48] [io.nio]

javax.net.ssl.SSLException: Inbound closed before receiving peer's
close_notify: possible truncation attack?

2013-11-27 13:02:31,857 DEBUG [qtp815329945-48] [nio.ChannelEndPoint]
close SCEP@59364878{l(/172.16.67.40:47119)<->r(/172.16.67.25:8081),d=true,open=false,ishut=true,oshut=true,rb=false,wb=false,w=true,i=1!}-{SslConnection@7acfec09
SSL NEED_WRAP i/o/u=-1/-1/-1 ishut=true oshut=false
{AsyncHttpConnection@208a2053,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=7,l=0,c=0},r=0}}
2013-11-27 13:02:31,855 DEBUG [qtp815329945-46] [nio.ChannelEndPoint]
ishut SCEP@7238621d{l(/172.16.67.40:47120)<->r(/172.16.67.25:8081),d=true,open=true,ishut=false,oshut=false,rb=false,wb=false,w=true,i=0r}-{SslConnection@53b19880
SSL NEED_UNWRAP i/o/u=0/0/0 ishut=false oshut=false
{AsyncHttpConnection@6b664f03,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-14,l=0,c=0},r=0}}
2013-11-27 13:02:31,858 DEBUG [qtp815329945-46] [nio.ssl] [Session-1,
SSL_NULL_WITH_NULL_NULL] SslConnection@53b19880 SSL NEED_UNWRAP
i/o/u=0/0/0 ishut=false oshut=false
{AsyncHttpConnection@6b664f03,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-14,l=0,c=0},r=0}
NEED_UNWRAP filled=-1/0 flushed=0/0
2013-11-27 13:02:31,859 DEBUG [qtp815329945-46] [nio.ChannelEndPoint]
ishut SCEP@7238621d{l(/172.16.67.40:47120)<->r(/172.16.67.25:8081),d=true,open=true,ishut=true,oshut=false,rb=false,wb=false,w=true,i=0r}-{SslConnection@53b19880
SSL NEED_UNWRAP i/o/u=0/0/0 ishut=false oshut=false
{AsyncHttpConnection@6b664f03,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-14,l=0,c=0},r=0}}
2013-11-27 13:02:31,859 DEBUG [qtp815329945-46] [http.HttpParser]

javax.net.ssl.SSLException: Inbound closed before receiving peer's
close_notify: possible truncation attack?

at sun.security.ssl.Alerts.getSSLException(Alerts.java:208)
at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1446)
at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1414)
at sun.security.ssl.SSLEngineImpl.closeInbound(SSLEngineImpl.java:1353)
at org.eclipse.jetty.io.nio.SslConnection.process(SslConnection.java:401)
at org.eclipse.jetty.io.nio.SslConnection.access$900(SslConnection.java:43)
at org.eclipse.jetty.io.nio.SslConnection$SslEndPoint.fill(SslConnection.java:658)
at org.eclipse.jetty.http.HttpParser.fill(HttpParser.java:1038)
at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:276)
at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:230)
at org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:76)
at org.eclipse.jetty.io.nio.SslConnection.handle(SslConnection.java:191)
at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:609)
at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:45)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:599)
at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:534)
at java.lang.Thread.run(Thread.java:701)
2013-11-27 13:02:31,861 DEBUG [qtp815329945-46] [http.HttpParser]
HttpParser{s=-14,l=0,c=0}
org.eclipse.jetty.io.EofException
at org.eclipse.jetty.http.HttpParser.fill(HttpParser.java:1044)
at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:276)
at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:230)
at org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:76)
at org.eclipse.jetty.io.nio.SslConnection.handle(SslConnection.java:191)
at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:609)
at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:45)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:599)
at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:534)
at java.lang.Thread.run(Thread.java:701)
Caused by: javax.net.ssl.SSLException: Inbound closed before receiving

peer's close_notify: possible truncation attack?

at sun.security.ssl.Alerts.getSSLException(Alerts.java:208)
at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1446)
at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1414)
at sun.security.ssl.SSLEngineImpl.closeInbound(SSLEngineImpl.java:1353)
at org.eclipse.jetty.io.nio.SslConnection.process(SslConnection.java:401)
at org.eclipse.jetty.io.nio.SslConnection.access$900(SslConnection.java:43)
at org.eclipse.jetty.io.nio.SslConnection$SslEndPoint.fill(SslConnection.java:658)
at org.eclipse.jetty.http.HttpParser.fill(HttpParser.java:1038)
... 9 more
2013-11-27 13:02:31,862 DEBUG [qtp815329945-46] [nio.ssl] [Session-1,
SSL_NULL_WITH_NULL_NULL] ssl endp.close
2013-11-27 13:02:31,862 DEBUG [qtp815329945-46] [nio.ChannelEndPoint]
close SCEP@7238621d{l(/172.16.67.40:47120)<->r(/172.16.67.25:8081),d=true,open=true,ishut=true,oshut=false,rb=false,wb=false,w=true,i=0r}-{SslConnection@53b19880
SSL NEED_WRAP i/o/u=-1/-1/-1 ishut=true oshut=false
{AsyncHttpConnection@6b664f03,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=0,l=0,c=0},r=0}}
2013-11-27 13:02:31,863 DEBUG [qtp815329945-46] [io.nio] EOF
org.eclipse.jetty.io.EofException
at org.eclipse.jetty.http.HttpParser.fill(HttpParser.java:1044)
at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:276)
at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:230)
at org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:76)
at org.eclipse.jetty.io.nio.SslConnection.handle(SslConnection.java:191)
at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:609)
at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:45)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:599)
at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:534)
at java.lang.Thread.run(Thread.java:701)
Caused by: javax.net.ssl.SSLException: Inbound closed before receiving

peer's close_notify: possible truncation attack?

at sun.security.ssl.Alerts.getSSLException(Alerts.java:208)
at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1446)
at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1414)
at sun.security.ssl.SSLEngineImpl.closeInbound(SSLEngineImpl.java:1353)
at org.eclipse.jetty.io.nio.SslConnection.process(SslConnection.java:401)
at org.eclipse.jetty.io.nio.SslConnection.access$900(SslConnection.java:43)
at org.eclipse.jetty.io.nio.SslConnection$SslEndPoint.fill(SslConnection.java:658)
at org.eclipse.jetty.http.HttpParser.fill(HttpParser.java:1038)
... 9 more
2013-11-27 13:02:31,859 DEBUG [qtp815329945-43 Selector0] [io.nio]
destroyEndPoint
SCEP@59364878{l(null)<->r(/172.16.67.25:8081),d=false,open=false,ishut=true,oshut=true,rb=false,wb=false,w=true,i=1!}-{SslConnection@7acfec09
SSL NEED_WRAP i/o/u=-1/-1/-1 ishut=true oshut=false
{AsyncHttpConnection@208a2053,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=7,l=0,c=0},r=0}}
2013-11-27 13:02:31,864 DEBUG [qtp815329945-46] [nio.ChannelEndPoint]
close SCEP@7238621d{l(/172.16.67.40:47120)<->r(/172.16.67.25:8081),d=true,open=false,ishut=true,oshut=true,rb=false,wb=false,w=true,i=0!}-{SslConnection@53b19880
SSL NEED_WRAP i/o/u=-1/-1/-1 ishut=true oshut=false
{AsyncHttpConnection@6b664f03,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=0,l=0,c=0},r=0}}
2013-11-27 13:02:31,865 DEBUG [qtp815329945-43 Selector0] [io.nio]
destroyEndPoint
SCEP@7238621d{l(null)<->r(/172.16.67.25:8081),d=true,open=false,ishut=true,oshut=true,rb=false,wb=false,w=true,i=0!}-{SslConnection@53b19880
SSL NEED_WRAP i/o/u=-1/-1/-1 ishut=true oshut=false
{AsyncHttpConnection@6b664f03,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=0,l=0,c=0},r=0}}
^C
Session terminated, killing shell...2013-11-27 13:02:34,492 INFO
[Thread-4] [cli.services] Shutdown request received; puppetdb exiting.
...killed.


Thanks,
Jonathan

[Jonathan Gazeley]

Hmm, well I removed java-1.6.0-openjdk and installed java-1.7.0-openjdk.
Reinstalled puppetdb, which pulled java-1.6.0-openjdk back in again, so
the two javas were installed simultaneously. Restarted puppetdb and
puppetmaster and everything works again.... I have no idea what was wrong.

[Deepak Giridharagopal]

On Nov 27, 2013, at 9:11 AM, Jonathan Gazeley <Jonathan...@bristol.ac.uk> wrote:

> Hmm, well I removed java-1.6.0-openjdk and installed java-1.7.0-openjdk. Reinstalled puppetdb, which pulled java-1.6.0-openjdk back in again, so the two javas were installed simultaneously. Restarted puppetdb and puppetmaster and everything works again.... I have no idea what was wrong.

Hmm, pulling in an older version jdk despite the presence of a newer one smells like a bug to me...can you file one against PuppetDB?

We're touching that code right now, as we're actually in the process of deprecating use of JDK 1.6 with PuppetDB. So the upgrade situation you describe is something we should try and test.

--
Deepak Giridharagopal / Puppet Labs

[Matthias Saou]

FWIW, I just did a "yum update" on a RHEL 6 puppet master, which got
all updates from RHEL 6.5, and I started seeing failed puppet runs with
the exact same symptoms.

This is initially with puppet 3.3.2 and puppetdb 1.4.0.

Restarting the services didn't help. Rebooting the server to make sure
all new system libs were used didn't help either.
Updating to puppetdb 1.5.2 and running /usr/sbin/puppetdb-ssl-setup -f
didn't help (still the exact same message).

But this fixed it :

yum install java-1.7.0-openjdk.x86_64
service puppetdb restart

Previously, I had only java-1.6.0-openjdk installed, and it had been
updated. I'm guessing the update broke something related to SSL. After
installing 1.7.0, alternatives automatically updated all java related
paths to make 1.7.0 the default, and puppetdb seems to work fine with
it.

So if you're running PuppetDB on RHEL (or any clone), then make sure
you have the right version of Java available for it.

Matthias

--
Matthias Saou ██ ██
██ ██
Web: http://matthias.saou.eu/ ██████████████
Mail/XMPP: matt...@saou.eu ████ ██████ ████
██████████████████████
GPG: 4096R/E755CC63 ██ ██████████████ ██
8D91 7E2E F048 9C9C 46AF ██ ██ ██ ██
21A9 7A51 7B82 E755 CC63 ████ ████

[Ken Barber]

Okay, so this problem seems prolific now. Would you mind raising a
redmine ticket on this?

http://projects.puppetlabs.com/projects/puppetdb

> --
> You received this message because you are subscribed to the Google Groups "Puppet Users" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to puppet-users...@googlegroups.com.
> To view this discussion on the web visit https://groups.google.com/d/msgid/puppet-users/20131128165900.4b11f270%40r2d2.marmotte.net.
> For more options, visit https://groups.google.com/groups/opt_out.

[Ken Barber]

So this seems to be a regression in openssl-1.0.1e-15.el6.x86_64. The
reason why this works for JDK 7, is because we've had issues with the
ECC based ciphers in the past, and had to pin JDK 7 to non-ECC
ciphers.

However we had the anticipation that this might be something that
would come back, so we provided a configuration option to override
this. Alas, the solution without downgrading openssl or upgrading to
JDK 7 is to add the following line to your jetty.ini:

cipher-suites =
TLS_RSA_WITH_AES_256_CBC_SHA256,TLS_RSA_WITH_AES_256_CBC_SHA,TLS_RSA_WITH_AES_128_CBC_SHA256,TLS_RSA_WITH_AES_128_CBC_SHA,SSL_RSA_WITH_RC4_128_SHA,SSL_RSA_WITH_3DES_EDE_CBC_SHA,SSL_RSA_WITH_RC4_128_MD5

... and then restart your puppetdb instance.

We're looking into a permanent solution now. Of course, upgrade to JDK
7 is a good idea regardless, so I would recommend that first. In the
very near future we are looking to deprecate JDK 6 anyway, so better
to move now rather then later.

ken.

[Ken Barber]

For what its worth the bug in openssl-1.0.1e-15 has been fixed in
upstream by openssl-1.0.1e-16:
http://rhn.redhat.com/errata/RHBA-2013-1751.html