Simon not sure is related but don,t if you don't consume enough quickly the
message, the buffer will be exhausted.

Did you try to increase the buffer size ?


On Wed, Aug 12, 2015 at 5:47 AM, Simon Johansson <simon(a)simonjohansson.com>
wrote:

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