Missing routing logs from "cf logs app-name"


Simon Johansson <simon@...>
 

Howdie! Not really a dev related question, but since there is no cf-user list I'm trying my luck here. :)

Im looking into an issue where we don't get enough RTR logs from cf logs / firehose-to-syslog
I'm using cf-env[1] as the test app, and Im hitting app.domain.com/kehehehe.
For each request the app itself logs the the path requested and the gorouters logs the same information but a bit more verbose.

$ cf logs cf-env-test
...
2015-08-11T11:43:41.24+0200 [RTR/0] OUT cf-env-test.domain.com - [11/08/2015:09:43:41 +0000] "GET /kehehehe HTTP/1.1" 404 0 18 "-" "curl/7.43.0" 10.230.15.4:59728 x_forwarded_for:"10.230.15.4" vcap_request_id:4a186d9e-046a-47bc-74d0-f0c3a8cb1257 response_time:0.008503156 app_id:7f1944a2-2197-43b5-9334-0be7c8b9b40e
2015-08-11T11:43:41.31+0200 [App/0] ERR 10.230.15.8 - - [11/Aug/2015 09:43:41] "GET /kehehehe HTTP/1.1" 404 18 0.0006

I shoot off 1000 requests and would expect to see 1000 of each log type. But only the App logs are correct.

$ grep "App/" /tmp/cf-logs | wc -l # /tmp/cf-logs comes from cf logs cf-env-test > /tmp/cf-logs
1000
$ grep "RTR/" /tmp/cf-logs | wc -l
145

Looking at the gorouters
nsaadmin(a)a99a5339-4308-43db-b3a4-59442169861d:~$ grep "GET /kehehehe" /var/vcap/sys/log/gorouter/access.log | wc -l
484
nsaadmin(a)1d8ef2c2-2ec1-417d-8882-0234de251c60:~$ grep "GET /kehehehe" /var/vcap/sys/log/gorouter/access.log | wc -l
516
So the gorouter process definitely logs the right amount of requests to disk.

In metron_agent.stdout.log on the gorouters there are a lot of lines like

{"timestamp":1439286941.958369255,"process_id":25749,"source":"metron","log_level":"warn","message":"no matching HTTP start message found for {low:6001753075995010215 high:3404432699330643838 1}","data":null,"file":"/var/vcap/data/compile/metron_agent/loggregator/src/metron/messageaggregator/message_aggregator.go","line":97,"method":"metron/messageaggregator.(*MessageAggregator).handleHTTPStop"}
{"timestamp":1439286941.959420443,"process_id":25749,"source":"metron","log_level":"warn","message":"no matching HTTP start message found for {low:8668459744461365080 high:13197025281073682796 2}","data":null,"file":"/var/vcap/data/compile/metron_agent/loggregator/src/metron/messageaggregator/message_aggregator.go","line":97,"method":"metron/messageaggregator.(*MessageAggregator).handleHTTPStop"}
{"timestamp":1439286941.964927912,"process_id":25749,"source":"metron","log_level":"warn","message":"no matching HTTP start message found for {low:13205430422726438703 high:7208042014820494920 1}","data":null,"file":"/var/vcap/data/compile/metron_agent/loggregator/src/metron/messageaggregator/message_aggregator.go","line":97,"method":"metron/messageaggregator.(*MessageAggregator).handleHTTPStop"}

Has anyone seen this before?

[1] https://github.com/cloudfoundry-community/cf-env

Join cf-dev@lists.cloudfoundry.org to automatically receive all group messages.