[PDB-2267] puppetdb-access.log does not log access requests to a hostname/IP it is not listening to Created: 2015/12/21  Updated: 2016/01/19  Resolved: 2016/01/06

Status: Closed
Project: PuppetDB
Component/s: None
Affects Version/s: PDB 3.2.2
Fix Version/s: PDB 3.2.3

Type: Bug Priority: Normal
Reporter: Rob Nelson Assignee: Unassigned
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Centos 7.2


Template:
Story Points: 1
Sprint: PuppetDB 2016-01-13

 Description   

When attempting to access puppetdb, the puppetdb-access.log only logs requests that it accepts and does not log attempts that it is not configured to accept. I have a server with IP address 10.0.0.134 and hostname testbox.nelson.va. Here is the jetty.ini configuration:

[jetty]
# IP address or hostname to listen for clear-text HTTP. To avoid resolution
# issues, IP addresses are recommended over hostnames.
# Default is `localhost`.
# host = <host>
host = localhost
 
# Port to listen on for clear-text HTTP.
port = 8080
 
# The following are SSL specific settings. They can be configured
# automatically with the tool `puppetdb ssl-setup`, which is normally
# ran during package installation.
 
# IP address to listen on for HTTPS connections. Hostnames can also be used
# but are not recommended to avoid DNS resolution issues. To listen on all
# interfaces, use `0.0.0.0`.
ssl-host = 0.0.0.0
 
# The port to listen on for HTTPS connections
ssl-port = 8081
 
# Private key path
ssl-key = /etc/puppetlabs/puppetdb/ssl/private.pem
 
# Public certificate path
ssl-cert = /etc/puppetlabs/puppetdb/ssl/public.pem
 
# Certificate authority path
ssl-ca-cert = /etc/puppetlabs/puppetdb/ssl/ca.pem
 
# Access logging configuration path. To turn off access logging
# comment out the line with `access-log-config=...`
access-log-config = /etc/puppetlabs/puppetdb/request-logging.xml

When I make the request from the node to localhost as curl http://localhost:8080/pdb/query/v4/nodes/testbox.nelson.va/facts -k -H "Accept: application/json", I see this in the log:

[root@testbox puppetdb]# tail -f puppetdb-access.log
127.0.0.1 - - [21/Dec/2015:15:44:15 +0000] "GET /pdb/query/v4/nodes/testbox.nelson.va/facts HTTP/1.1" 200 25414 "-" "curl/7.29.0"

When I make a request to the hostname testbox or it's IP 10.0.0.134 via curl http://10.0.0.134:8080/pdb/query/v4/nodes/testbox.nelson.va/facts -k -H "Accept: application/json", nothing shows up in the log. However, I do see the packets being processed and rejected:

[root@testbox puppetdb]# tcpdump -nni eno16780032 port 8080
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on eno16780032, link-type EN10MB (Ethernet), capture size 65535 bytes
15:36:54.742290 IP 10.0.0.201.50350 > 10.0.0.134.8080: Flags [S], seq 82872684, win 8192, options [mss 1460,nop,wscale 8,nop,nop,sackOK], length 0
15:36:54.742334 IP 10.0.0.134.8080 > 10.0.0.201.50350: Flags [R.], seq 0, ack 82872685, win 0, length 0
15:36:54.992636 IP 10.0.0.201.50351 > 10.0.0.134.8080: Flags [S], seq 2435678504, win 8192, options [mss 1460,nop,wscale 8,nop,nop,sackOK], length 0
15:36:54.992679 IP 10.0.0.134.8080 > 10.0.0.201.50351: Flags [R.], seq 0, ack 2435678505, win 0, length 0
15:36:55.242185 IP 10.0.0.201.50350 > 10.0.0.134.8080: Flags [S], seq 82872684, win 8192, options [mss 1460,nop,wscale 8,nop,nop,sackOK], length 0
15:36:55.242218 IP 10.0.0.134.8080 > 10.0.0.201.50350: Flags [R.], seq 0, ack 1, win 0, length 0
15:36:55.492292 IP 10.0.0.201.50351 > 10.0.0.134.8080: Flags [S], seq 2435678504, win 8192, options [mss 1460,nop,wscale 8,nop,nop,sackOK], length 0
15:36:55.492332 IP 10.0.0.134.8080 > 10.0.0.201.50351: Flags [R.], seq 0, ack 1, win 0, length 0
15:36:55.742088 IP 10.0.0.201.50350 > 10.0.0.134.8080: Flags [S], seq 82872684, win 8192, options [mss 1460,nop,nop,sackOK], length 0
15:36:55.742140 IP 10.0.0.134.8080 > 10.0.0.201.50350: Flags [R.], seq 0, ack 1, win 0, length 0
15:36:55.992320 IP 10.0.0.201.50351 > 10.0.0.134.8080: Flags [S], seq 2435678504, win 8192, options [mss 1460,nop,nop,sackOK], length 0
15:36:55.992360 IP 10.0.0.134.8080 > 10.0.0.201.50351: Flags [R.], seq 0, ack 1, win 0, length 0
15:36:55.993755 IP 10.0.0.201.50352 > 10.0.0.134.8080: Flags [S], seq 2631119819, win 8192, options [mss 1460,nop,wscale 8,nop,nop,sackOK], length 0
15:36:55.993788 IP 10.0.0.134.8080 > 10.0.0.201.50352: Flags [R.], seq 0, ack 2631119820, win 0, length 0
15:36:56.491254 IP 10.0.0.201.50352 > 10.0.0.134.8080: Flags [S], seq 2631119819, win 8192, options [mss 1460,nop,wscale 8,nop,nop,sackOK], length 0
15:36:56.491297 IP 10.0.0.134.8080 > 10.0.0.201.50352: Flags [R.], seq 0, ack 1, win 0, length 0
15:36:56.991329 IP 10.0.0.201.50352 > 10.0.0.134.8080: Flags [S], seq 2631119819, win 8192, options [mss 1460,nop,nop,sackOK], length 0
15:36:56.991383 IP 10.0.0.134.8080 > 10.0.0.201.50352: Flags [R.], seq 0, ack 1, win 0, length 0

While this is properly being rejected by puppetdb, there is absolutely no log of these attempts or the reason why they are failing.



 Comments   
Comment by Rob Nelson [ 2015/12/21 ]

Further testing shows similar logging issues with curls against the right URL but invalid certificate options. Here is a working query and tcpdump:

# curl https://10.0.0.134:8081/pdb/query/v4/nodes/testbox.nelson.va/facts -k --cacert /etc/puppetlabs/puppet/ssl/certs/ca.pem --cert /etc/puppetlabs/puppet/ssl/certs/testbox.nelson.va.pem --key /etc/puppetlabs/puppet/ssl/private_keys/testbox.nelson.va.pem
<lots of JSON output>
 
# tcpdump -nni lo port 8081
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on lo, link-type EN10MB (Ethernet), capture size 65535 bytes
16:16:34.901740 IP 10.0.0.134.45961 > 10.0.0.134.8081: Flags [S], seq 659415533, win 43690, options [mss 65495,sackOK,TS val 92807965 ecr 0,nop,wscale 7], length 0
12:12:57.372566 IP 10.0.0.134.8081 > 10.0.0.134.45961: Flags [S.], seq 2605542896, ack 659415534, win 43690, options [mss 65495,sackOK,TS val 92807965 ecr 92807965,nop,wscale 7], length 0
16:16:34.901766 IP 10.0.0.134.45961 > 10.0.0.134.8081: Flags [.], ack 1, win 342, options [nop,nop,TS val 92807965 ecr 92807965], length 0
16:16:34.962334 IP 10.0.0.134.45961 > 10.0.0.134.8081: Flags [P.], seq 1:154, ack 1, win 342, options [nop,nop,TS val 92808025 ecr 92807965], length 153
16:16:34.962356 IP 10.0.0.134.8081 > 10.0.0.134.45961: Flags [.], ack 154, win 350, options [nop,nop,TS val 92808025 ecr 92808025], length 0
16:16:34.963757 IP 10.0.0.134.8081 > 10.0.0.134.45961: Flags [P.], seq 1:1619, ack 154, win 350, options [nop,nop,TS val 92808027 ecr 92808025], length 1618
16:16:34.963765 IP 10.0.0.134.45961 > 10.0.0.134.8081: Flags [.], ack 1619, win 1365, options [nop,nop,TS val 92808027 ecr 92808027], length 0
16:16:34.979799 IP 10.0.0.134.45961 > 10.0.0.134.8081: Flags [P.], seq 154:2721, ack 1619, win 1365, options [nop,nop,TS val 92808043 ecr 92808027], length 2567
16:16:34.979997 IP 10.0.0.134.8081 > 10.0.0.134.45961: Flags [.], ack 2721, win 1373, options [nop,nop,TS val 92808043 ecr 92808043], length 0
16:16:35.034319 IP 10.0.0.134.8081 > 10.0.0.134.45961: Flags [P.], seq 1619:1625, ack 2721, win 1373, options [nop,nop,TS val 92808097 ecr 92808043], length 6
16:16:35.034364 IP 10.0.0.134.8081 > 10.0.0.134.45961: Flags [P.], seq 1625:1694, ack 2721, win 1373, options [nop,nop,TS val 92808097 ecr 92808043], length 69
16:16:35.034767 IP 10.0.0.134.45961 > 10.0.0.134.8081: Flags [.], ack 1694, win 1365, options [nop,nop,TS val 92808098 ecr 92808097], length 0
16:16:35.034907 IP 10.0.0.134.45961 > 10.0.0.134.8081: Flags [P.], seq 2721:2886, ack 1694, win 1365, options [nop,nop,TS val 92808098 ecr 92808097], length 165
16:16:35.058612 IP 10.0.0.134.8081 > 10.0.0.134.45961: Flags [P.], seq 1694:18131, ack 2886, win 1413, options [nop,nop,TS val 92808122 ecr 92808098], length 16437
16:16:35.058862 IP 10.0.0.134.8081 > 10.0.0.134.45961: Flags [P.], seq 18131:27368, ack 2886, win 1413, options [nop,nop,TS val 92808122 ecr 92808098], length 9237
16:16:35.058869 IP 10.0.0.134.45961 > 10.0.0.134.8081: Flags [.], ack 27368, win 3411, options [nop,nop,TS val 92808122 ecr 92808122], length 0
16:16:35.060217 IP 10.0.0.134.45961 > 10.0.0.134.8081: Flags [P.], seq 2886:2939, ack 27368, win 3411, options [nop,nop,TS val 92808123 ecr 92808122], length 53
16:16:35.060232 IP 10.0.0.134.45961 > 10.0.0.134.8081: Flags [F.], seq 2939, ack 27368, win 3411, options [nop,nop,TS val 92808123 ecr 92808122], length 0
16:16:35.061584 IP 10.0.0.134.8081 > 10.0.0.134.45961: Flags [F.], seq 27368, ack 2940, win 1413, options [nop,nop,TS val 92808125 ecr 92808123], length 0
16:16:35.061592 IP 10.0.0.134.45961 > 10.0.0.134.8081: Flags [.], ack 27369, win 3411, options [nop,nop,TS val 92808125 ecr 92808125], length 0
 
# tail -f puppetdb-access.log
10.0.0.134 - - [21/Dec/2015:16:20:17 +0000] "GET /pdb/query/v4/nodes/testbox.nelson.va/facts HTTP/1.1" 200 25414 "-" "curl/7.29.0"

By comparison, here is what happens when the cert options are left off. Obviously this fails as it should, but it does open a socket and is not logged.

# curl https://10.0.0.134:8081/pdb/query/v4/nodes/testbox.nelson.va/facts -k
curl: (35) NSS: client certificate not found (nickname not specified)
 
# tcpdump -nni lo port 8081
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on lo, link-type EN10MB (Ethernet), capture size 65535 bytes
16:21:21.630685 IP 10.0.0.134.45970 > 10.0.0.134.8081: Flags [S], seq 1085702087, win 43690, options [mss 65495,sackOK,TS val 93094694 ecr 0,nop,wscale 7], length 0
18:17:49.337034 IP 10.0.0.134.8081 > 10.0.0.134.45970: Flags [S.], seq 3570655584, ack 1085702088, win 43690, options [mss 65495,sackOK,TS val 93094694 ecr 93094694,nop,wscale 7], length 0
16:21:21.630714 IP 10.0.0.134.45970 > 10.0.0.134.8081: Flags [.], ack 1, win 342, options [nop,nop,TS val 93094694 ecr 93094694], length 0
16:21:21.698859 IP 10.0.0.134.45970 > 10.0.0.134.8081: Flags [P.], seq 1:154, ack 1, win 342, options [nop,nop,TS val 93094762 ecr 93094694], length 153
16:21:21.698878 IP 10.0.0.134.8081 > 10.0.0.134.45970: Flags [.], ack 154, win 350, options [nop,nop,TS val 93094762 ecr 93094762], length 0
16:21:21.700959 IP 10.0.0.134.8081 > 10.0.0.134.45970: Flags [P.], seq 1:1619, ack 154, win 350, options [nop,nop,TS val 93094764 ecr 93094762], length 1618
16:21:21.700968 IP 10.0.0.134.45970 > 10.0.0.134.8081: Flags [.], ack 1619, win 1365, options [nop,nop,TS val 93094764 ecr 93094764], length 0
16:21:21.702722 IP 10.0.0.134.45970 > 10.0.0.134.8081: Flags [P.], seq 154:759, ack 1619, win 1365, options [nop,nop,TS val 93094766 ecr 93094764], length 605
16:21:21.703996 IP 10.0.0.134.8081 > 10.0.0.134.45970: Flags [F.], seq 1619, ack 759, win 360, options [nop,nop,TS val 93094767 ecr 93094766], length 0
16:21:21.704050 IP 10.0.0.134.45970 > 10.0.0.134.8081: Flags [F.], seq 759, ack 1620, win 1365, options [nop,nop,TS val 93094767 ecr 93094767], length 0
16:21:21.704059 IP 10.0.0.134.8081 > 10.0.0.134.45970: Flags [.], ack 760, win 360, options [nop,nop,TS val 93094767 ecr 93094767], length 0
 
# tail -f puppetdb-access.log
<no new statements>

Comment by Ken Barber [ 2016/01/04 ]

This really describes 2 issues I think.

So in regards to your first problem in the description Rob, your curl against localhost should log, because its listening on localhost. But host = localhost won't necessarily accept connections on your 10.0.0.134 address, the tcpdump you've sent doesn't prove the server is listening on this port, it seems to me like the packets are being rejected by the OS, not accepted. Anyway, if you've set host = localhost, it should only listen on the hostname that resolves to (and by the way, you should really set this to an IP address not a hostname fwiw). You can prove this with a netstat -anp | grep java, to see where its listening to. So I'm not convinced the first problem curling localhost v 10.0.0.134 on clear text is valid ... it just looks like we don't listen, so therefore no - we don't log. Perhaps I'm wrong, provide more info if you think so. Also btw, if you look at your first tcpdump, the R responses from 10.0.0.134 indicate a reset - not a successful TCP handshake, which is needed (as well as the HTTP request) for us to log I guess .

Now as far as the second problem and SSL, I don't think its that surprising that a failed SSL negotiation won't log. If an SSL negotiation failed, no actually HTTP request was sent. As we know, SSL is a wrapper around HTTP really, so SSL negotiation has to succeed first ... if SSL fails, what can we log? That is, we never see the GET request, the URL, nor the hostname or query params if SSL fails, so its not at all surprising an access log wasn't dropped. I'm pretty sure we can't just 'fix this', its endemic to the protocol ... I mean, what would we log exactly anyway? Be mindful, the access log HTTP requests only, to me, it just didn't get this far up the network stack to do this. Instead, SSL negotiation errors usually get logged as debug or errors in the main log, not in the access log - I think you'll find Apache is the same here when you're using client SSL authentication.

Comment by Rob Nelson [ 2016/01/04 ]

Ken, I really should have caught the first issue (rejected by OS, not application), whoops!

On the second, I guess the question is, where are the debug/error logs for puppetdb? If someone tries to connect and has issues or is malicious and it results in a flood on port 8081, would I currently be able to see this in any log? I haven't found that so far.

Comment by Ken Barber [ 2016/01/04 ]

So this stuff doesn't log by default, seems Jetty logs this at a debug level. One way to solve this, would be to modify your logback.xml to log the correct class & DEBUG level to file.

So `puppetdb foreground --debug` gives you the flood gates btw, and if you do a curl with a -k, you get an exception: https://gist.github.com/kbarber/ca45d596bbdb4d8b1d70

So what you want here, is to modify logback.xml to raise that up just for anything in `org.eclipse.jetty.server.HttpConnection`, this rule applies to anything interesting in that debug log btw, so you can adapt these instructions for other logging namespaces etc.

Anyway, your logback.xml should be modified kind of like this:

<configuration scan="true">
... snip ...
<logger name="org.eclipse.jetty.server.HttpConnection" level="debug"/>
... snip ...
</configuration>

Its going to drop other noise, I have no idea how much though on average . For me its about 3-4 lines per connection, but at least you'll see the exceptions.

I think jetty by default doesn't show these at say info or error, because for most cases, a public website certainly doesn't care all that much about the dozens and dozens of SSL attempts they get per second - they'd simply get inundated with bad messages just due to automated scripts from bots and such.

Comment by Rob Nelson [ 2016/01/05 ]

Seems like a sane default to suppress and it's nice to know how to elevate on demand, when a connection appears to be failing or you think you're flooded. I'll see about a documentation PR so this is captured somewhere other than JIRA.

Comment by Rob Nelson [ 2016/01/05 ]

Some scribbles at https://github.com/rnelson0/puppetdb/blob/PDB-2267/logging/documentation/trouble_session_logging.markdown. Let me know what tweaks you'd like to see before I submit the PR. Thanks!

Comment by Ken Barber [ 2016/01/06 ]

I think that doc looks reasonable, although I'll probably comment some more on the details once you raise a PR. You'll need to update the navigation to add this new doc: https://github.com/puppetlabs/puppetdb/blob/stable/documentation/_puppetdb_nav.html as well.

I suggest doing it on stable also, so it gets published straight away.

Comment by Rob Nelson [ 2016/01/06 ]

Documentation update

Generated at Sun Aug 25 05:22:57 PDT 2019 using JIRA 7.7.1#77002-sha1:e75ca93d5574d9409c0630b81c894d9065296414.