Manual instrumentation insertion does not work when HTTP streaming is used about newrelic-ruby-agent

[jasonrclark]

Hey @vojtad thanks for the report. We definitely haven't done much around streaming to this point, so it's possible something wrong there.

It would help out if you could let me know what version of Rails and the newrelic_rpm gem you're using. Also, if you've got a log/newrelic_agent.log, I'm curious if you see any errors listed in it.

Thanks!

[vojtad]

Hey @jasonrclark, I am using Rails 4.0.5 and newrelic_rpm 3.8.1.221. I am also running my application on Heroku, so I do not know how to get log/newrelic_agent.log you have requested. However, here is output relevant to NewRelic from heroku logs at least but I do not see any errors there.

2014-06-10T16:30:21.204516+00:00 app[web.1]: ** [NewRelic][06/10/14 16:30:21 +0000 76c13aaa-1827-44a3-81a4-b6cfe22e70c9 (2)] INFO : Unable to send metric_data data, will try again later. Error:
2014-06-10T16:30:21.204577+00:00 app[web.1]: ** [NewRelic][06/10/14 16:30:21 +0000 76c13aaa-1827-44a3-81a4-b6cfe22e70c9 (2)] INFO : RuntimeError: Server Error (IOException): java.util.concurrent.TimeoutException: Idle timeout expired: 2500/2500 ms
2014-06-10T16:30:23.755510+00:00 app[web.1]: ** [NewRelic][06/10/14 16:30:23 +0000 76c13aaa-1827-44a3-81a4-b6cfe22e70c9 (9)] INFO : Starting Agent shutdown
2014-06-10T16:30:23.752088+00:00 app[web.1]: ** [NewRelic][06/10/14 16:30:23 +0000 76c13aaa-1827-44a3-81a4-b6cfe22e70c9 (27)] INFO : Starting Agent shutdown
2014-06-10T16:30:23.761340+00:00 app[web.1]: ** [NewRelic][06/10/14 16:30:23 +0000 76c13aaa-1827-44a3-81a4-b6cfe22e70c9 (18)] INFO : Starting Agent shutdown
2014-06-10T16:30:24.557929+00:00 app[web.1]: ** [NewRelic][06/10/14 16:30:24 +0000 76c13aaa-1827-44a3-81a4-b6cfe22e70c9 (2)] INFO : Starting Agent shutdown
2014-06-10T16:30:26.209966+00:00 app[web.1]: ** [NewRelic][06/10/14 16:30:26 +0000 76c13aaa-1827-44a3-81a4-b6cfe22e70c9 (2)] INFO : Error during check_for_and_handle_agent_commands, will retry later:
2014-06-10T16:30:26.209979+00:00 app[web.1]: ** [NewRelic][06/10/14 16:30:26 +0000 76c13aaa-1827-44a3-81a4-b6cfe22e70c9 (2)] INFO : NewRelic::Agent::ServerConnectionException: Recoverable error connecting to collector-127.newrelic.com:443: end of file reached
2014-06-10T16:30:28.323405+00:00 app[web.2]: ** [NewRelic][06/10/14 16:30:28 +0000 a37fd7a4-18ae-44b2-be40-1727a52a5e8d (17)] INFO : Starting Agent shutdown
2014-06-10T16:30:28.324234+00:00 app[web.2]: ** [NewRelic][06/10/14 16:30:28 +0000 a37fd7a4-18ae-44b2-be40-1727a52a5e8d (25)] INFO : Starting Agent shutdown
2014-06-10T16:30:28.384104+00:00 app[web.2]: ** [NewRelic][06/10/14 16:30:28 +0000 a37fd7a4-18ae-44b2-be40-1727a52a5e8d (9)] INFO : Starting Agent shutdown
2014-06-10T16:30:29.676872+00:00 app[web.2]: ** [NewRelic][06/10/14 16:30:29 +0000 a37fd7a4-18ae-44b2-be40-1727a52a5e8d (2)] INFO : Starting Agent shutdown
2014-06-10T16:30:34.756069+00:00 app[web.2]: ** [NewRelic][06/10/14 16:30:34 +0000 74b367b7-5c10-4a9c-8e61-a003614d74c2 (2)] INFO : Starting the New Relic agent in "production" environment.
2014-06-10T16:30:34.756082+00:00 app[web.2]: ** [NewRelic][06/10/14 16:30:34 +0000 74b367b7-5c10-4a9c-8e61-a003614d74c2 (2)] INFO : To prevent agent startup add a NEWRELIC_AGENT_ENABLED=false environment variable or modify the "production" section of your newrelic.yml.
2014-06-10T16:30:34.756114+00:00 app[web.2]: ** [NewRelic][06/10/14 16:30:34 +0000 74b367b7-5c10-4a9c-8e61-a003614d74c2 (2)] INFO : Reading configuration from config/newrelic.yml
2014-06-10T16:30:34.756885+00:00 app[web.2]: ** [NewRelic][06/10/14 16:30:34 +0000 74b367b7-5c10-4a9c-8e61-a003614d74c2 (2)] INFO : Environment: production
2014-06-10T16:30:34.756919+00:00 app[web.2]: ** [NewRelic][06/10/14 16:30:34 +0000 74b367b7-5c10-4a9c-8e61-a003614d74c2 (2)] INFO : Dispatcher: puma
2014-06-10T16:30:34.756962+00:00 app[web.2]: ** [NewRelic][06/10/14 16:30:34 +0000 74b367b7-5c10-4a9c-8e61-a003614d74c2 (2)] INFO : Application: SlidesLive
2014-06-10T16:30:34.821819+00:00 app[web.2]: ** [NewRelic][06/10/14 16:30:34 +0000 74b367b7-5c10-4a9c-8e61-a003614d74c2 (2)] INFO : delayed_job not available: No DJ worker present
2014-06-10T16:30:34.851043+00:00 app[web.2]: ** [NewRelic][06/10/14 16:30:34 +0000 74b367b7-5c10-4a9c-8e61-a003614d74c2 (2)] INFO : Installing Dalli Memcache instrumentation
2014-06-10T16:30:34.851082+00:00 app[web.2]: ** [NewRelic][06/10/14 16:30:34 +0000 74b367b7-5c10-4a9c-8e61-a003614d74c2 (2)] INFO : Installing Net instrumentation
2014-06-10T16:30:34.919579+00:00 app[web.2]: ** [NewRelic][06/10/14 16:30:34 +0000 74b367b7-5c10-4a9c-8e61-a003614d74c2 (2)] INFO : Installing deferred Rack instrumentation
2014-06-10T16:30:34.921511+00:00 app[web.2]: ** [NewRelic][06/10/14 16:30:34 +0000 74b367b7-5c10-4a9c-8e61-a003614d74c2 (2)] INFO : Installing ActiveRecord 4 instrumentation
2014-06-10T16:30:34.850025+00:00 app[web.2]: ** [NewRelic][06/10/14 16:30:34 +0000 74b367b7-5c10-4a9c-8e61-a003614d74c2 (2)] INFO : Installing DelayedJob instrumentation [part 1/2]
2014-06-10T16:30:34.920585+00:00 app[web.2]: ** [NewRelic][06/10/14 16:30:34 +0000 74b367b7-5c10-4a9c-8e61-a003614d74c2 (2)] INFO : Installing middleware-based Excon instrumentation
2014-06-10T16:30:34.921648+00:00 app[web.2]: ** [NewRelic][06/10/14 16:30:34 +0000 74b367b7-5c10-4a9c-8e61-a003614d74c2 (2)] INFO : Installing Rails 4 view instrumentation
2014-06-10T16:30:34.921716+00:00 app[web.2]: ** [NewRelic][06/10/14 16:30:34 +0000 74b367b7-5c10-4a9c-8e61-a003614d74c2 (2)] INFO : Installing Rails 4 Controller instrumentation
2014-06-10T16:30:34.921886+00:00 app[web.2]: ** [NewRelic][06/10/14 16:30:34 +0000 74b367b7-5c10-4a9c-8e61-a003614d74c2 (2)] INFO : Installing Rails4 Error instrumentation
2014-06-10T16:30:34.921948+00:00 app[web.2]: ** [NewRelic][06/10/14 16:30:34 +0000 74b367b7-5c10-4a9c-8e61-a003614d74c2 (2)] INFO : Finished instrumentation
2014-06-10T16:30:35.523433+00:00 app[web.2]: ** [NewRelic][06/10/14 16:30:35 +0000 74b367b7-5c10-4a9c-8e61-a003614d74c2 (2)] INFO : Reporting to: https://rpm.newrelic.com/accounts/687214/applications/3129769
2014-06-10T16:30:36.360099+00:00 app[web.2]: ** [NewRelic][06/10/14 16:30:36 +0000 74b367b7-5c10-4a9c-8e61-a003614d74c2 (2)] INFO : Doing deferred dependency-detection before Rack startup
2014-06-10T16:30:36.491723+00:00 app[web.1]: ** [NewRelic][06/10/14 16:30:36 +0000 50dc2335-c9da-490d-8f84-13b18c805590 (2)] INFO : Starting the New Relic agent in "production" environment.
2014-06-10T16:30:36.491737+00:00 app[web.1]: ** [NewRelic][06/10/14 16:30:36 +0000 50dc2335-c9da-490d-8f84-13b18c805590 (2)] INFO : To prevent agent startup add a NEWRELIC_AGENT_ENABLED=false environment variable or modify the "production" section of your newrelic.yml.
2014-06-10T16:30:36.491739+00:00 app[web.1]: ** [NewRelic][06/10/14 16:30:36 +0000 50dc2335-c9da-490d-8f84-13b18c805590 (2)] INFO : Reading configuration from config/newrelic.yml
2014-06-10T16:30:36.492602+00:00 app[web.1]: ** [NewRelic][06/10/14 16:30:36 +0000 50dc2335-c9da-490d-8f84-13b18c805590 (2)] INFO : Environment: production
2014-06-10T16:30:36.492637+00:00 app[web.1]: ** [NewRelic][06/10/14 16:30:36 +0000 50dc2335-c9da-490d-8f84-13b18c805590 (2)] INFO : Dispatcher: puma
2014-06-10T16:30:36.492681+00:00 app[web.1]: ** [NewRelic][06/10/14 16:30:36 +0000 50dc2335-c9da-490d-8f84-13b18c805590 (2)] INFO : Application: SlidesLive
2014-06-10T16:30:36.510320+00:00 app[web.1]: ** [NewRelic][06/10/14 16:30:36 +0000 50dc2335-c9da-490d-8f84-13b18c805590 (2)] INFO : delayed_job not available: No DJ worker present
2014-06-10T16:30:36.891230+00:00 app[web.1]: ** [NewRelic][06/10/14 16:30:36 +0000 50dc2335-c9da-490d-8f84-13b18c805590 (2)] INFO : Installing Dalli Memcache instrumentation
2014-06-10T16:30:37.044192+00:00 app[web.1]: ** [NewRelic][06/10/14 16:30:37 +0000 50dc2335-c9da-490d-8f84-13b18c805590 (2)] INFO : Installing deferred Rack instrumentation
2014-06-10T16:30:37.045155+00:00 app[web.1]: ** [NewRelic][06/10/14 16:30:37 +0000 50dc2335-c9da-490d-8f84-13b18c805590 (2)] INFO : Installing DelayedJob instrumentation [part 1/2]
2014-06-10T16:30:37.047261+00:00 app[web.1]: ** [NewRelic][06/10/14 16:30:37 +0000 50dc2335-c9da-490d-8f84-13b18c805590 (2)] INFO : Installing Rails4 Error instrumentation
2014-06-10T16:30:37.049779+00:00 app[web.1]: ** [NewRelic][06/10/14 16:30:37 +0000 50dc2335-c9da-490d-8f84-13b18c805590 (2)] INFO : Installing Rails 4 Controller instrumentation
2014-06-10T16:30:36.895020+00:00 app[web.1]: ** [NewRelic][06/10/14 16:30:36 +0000 50dc2335-c9da-490d-8f84-13b18c805590 (2)] INFO : Installing middleware-based Excon instrumentation
2014-06-10T16:30:37.044765+00:00 app[web.1]: ** [NewRelic][06/10/14 16:30:37 +0000 50dc2335-c9da-490d-8f84-13b18c805590 (2)] INFO : Installing ActiveRecord 4 instrumentation
2014-06-10T16:30:37.045593+00:00 app[web.1]: ** [NewRelic][06/10/14 16:30:37 +0000 50dc2335-c9da-490d-8f84-13b18c805590 (2)] INFO : Installing Net instrumentation
2014-06-10T16:30:37.049558+00:00 app[web.1]: ** [NewRelic][06/10/14 16:30:37 +0000 50dc2335-c9da-490d-8f84-13b18c805590 (2)] INFO : Installing Rails 4 view instrumentation
2014-06-10T16:30:37.052408+00:00 app[web.1]: ** [NewRelic][06/10/14 16:30:37 +0000 50dc2335-c9da-490d-8f84-13b18c805590 (2)] INFO : Finished instrumentation
2014-06-10T16:30:37.704433+00:00 app[web.1]: ** [NewRelic][06/10/14 16:30:37 +0000 50dc2335-c9da-490d-8f84-13b18c805590 (2)] INFO : Reporting to: https://rpm.newrelic.com/accounts/687214/applications/3129769
2014-06-10T16:30:38.172209+00:00 app[web.2]: ** [NewRelic][06/10/14 16:30:38 +0000 74b367b7-5c10-4a9c-8e61-a003614d74c2 (27)] WARN : Ignoring addition of cpu because it is already registered.
2014-06-10T16:30:38.172316+00:00 app[web.2]: ** [NewRelic][06/10/14 16:30:38 +0000 74b367b7-5c10-4a9c-8e61-a003614d74c2 (27)] WARN : Ignoring addition of memory because it is already registered.
2014-06-10T16:30:38.172620+00:00 app[web.2]: ** [NewRelic][06/10/14 16:30:38 +0000 74b367b7-5c10-4a9c-8e61-a003614d74c2 (27)] INFO : delayed_job not available: No DJ worker present
2014-06-10T16:30:38.172723+00:00 app[web.2]: ** [NewRelic][06/10/14 16:30:38 +0000 74b367b7-5c10-4a9c-8e61-a003614d74c2 (27)] WARN : Ignoring addition of vm because it is already registered.
2014-06-10T16:30:38.796890+00:00 app[web.2]: ** [NewRelic][06/10/14 16:30:38 +0000 74b367b7-5c10-4a9c-8e61-a003614d74c2 (27)] INFO : Reporting to: https://rpm.newrelic.com/accounts/687214/applications/3129769
2014-06-10T16:30:39.432893+00:00 app[web.1]: ** [NewRelic][06/10/14 16:30:39 +0000 50dc2335-c9da-490d-8f84-13b18c805590 (2)] INFO : Doing deferred dependency-detection before Rack startup
2014-06-10T16:30:44.927188+00:00 app[web.2]: ** [NewRelic][06/10/14 16:30:44 +0000 74b367b7-5c10-4a9c-8e61-a003614d74c2 (18)] WARN : Ignoring addition of vm because it is already registered.
2014-06-10T16:30:44.926780+00:00 app[web.2]: ** [NewRelic][06/10/14 16:30:44 +0000 74b367b7-5c10-4a9c-8e61-a003614d74c2 (18)] WARN : Ignoring addition of cpu because it is already registered.
2014-06-10T16:30:44.926881+00:00 app[web.2]: ** [NewRelic][06/10/14 16:30:44 +0000 74b367b7-5c10-4a9c-8e61-a003614d74c2 (18)] WARN : Ignoring addition of memory because it is already registered.
2014-06-10T16:30:44.927120+00:00 app[web.2]: ** [NewRelic][06/10/14 16:30:44 +0000 74b367b7-5c10-4a9c-8e61-a003614d74c2 (18)] INFO : delayed_job not available: No DJ worker present
2014-06-10T16:30:45.544121+00:00 app[web.2]: ** [NewRelic][06/10/14 16:30:45 +0000 74b367b7-5c10-4a9c-8e61-a003614d74c2 (18)] INFO : Reporting to: https://rpm.newrelic.com/accounts/687214/applications/3129769
2014-06-10T16:30:57.129340+00:00 app[web.1]: ** [NewRelic][06/10/14 16:30:57 +0000 50dc2335-c9da-490d-8f84-13b18c805590 (9)] WARN : Ignoring addition of memory because it is already registered.
2014-06-10T16:30:57.131936+00:00 app[web.1]: ** [NewRelic][06/10/14 16:30:57 +0000 50dc2335-c9da-490d-8f84-13b18c805590 (9)] WARN : Ignoring addition of vm because it is already registered.
2014-06-10T16:30:57.119401+00:00 app[web.1]: ** [NewRelic][06/10/14 16:30:57 +0000 50dc2335-c9da-490d-8f84-13b18c805590 (9)] WARN : Ignoring addition of cpu because it is already registered.
2014-06-10T16:30:57.130476+00:00 app[web.1]: ** [NewRelic][06/10/14 16:30:57 +0000 50dc2335-c9da-490d-8f84-13b18c805590 (9)] INFO : delayed_job not available: No DJ worker present
2014-06-10T16:30:58.210430+00:00 app[web.1]: ** [NewRelic][06/10/14 16:30:58 +0000 50dc2335-c9da-490d-8f84-13b18c805590 (9)] INFO : Reporting to: https://rpm.newrelic.com/accounts/687214/applications/3129769
2014-06-10T16:31:06.935028+00:00 app[web.1]: ** [NewRelic][06/10/14 16:31:06 +0000 50dc2335-c9da-490d-8f84-13b18c805590 (22)] WARN : Ignoring addition of cpu because it is already registered.
2014-06-10T16:31:06.935642+00:00 app[web.1]: ** [NewRelic][06/10/14 16:31:06 +0000 50dc2335-c9da-490d-8f84-13b18c805590 (22)] INFO : delayed_job not available: No DJ worker present
2014-06-10T16:31:06.935728+00:00 app[web.1]: ** [NewRelic][06/10/14 16:31:06 +0000 50dc2335-c9da-490d-8f84-13b18c805590 (22)] WARN : Ignoring addition of vm because it is already registered.
2014-06-10T16:31:06.935315+00:00 app[web.1]: ** [NewRelic][06/10/14 16:31:06 +0000 50dc2335-c9da-490d-8f84-13b18c805590 (22)] WARN : Ignoring addition of memory because it is already registered.
2014-06-10T16:31:07.893437+00:00 app[web.1]: ** [NewRelic][06/10/14 16:31:07 +0000 50dc2335-c9da-490d-8f84-13b18c805590 (22)] INFO : Reporting to: https://rpm.newrelic.com/accounts/687214/applications/3129769

[jasonrclark]

Thanks for the info! That's actually exactly the log output we're looking for. I notice that's only for a minute or so. Did a streaming render get called during that timeframe, or is that just the recent logging?

[vojtad]

Yep it got called. I did heroku restart to get the log from loading the intrumentations and then i loaded streamed page to make sure it gets called.

[jasonrclark]

Thanks for the help @vojtad! I've successfully duplicated this and gotten an item onto the team backlog about it. I don't think it's likely this will make it into the upcoming release given timing, but we will respond back here when a fix is available.

Thanks again for the report!

[vojtad]

Cool, thanks @jasonrclark! Just let me know when the fix is available, I will definitely test it.

[guigs]

I'm also very interested in using RUM with HTTP streaming, since we are going to use streaming to make page header load as soon as possible. We will love to compare RUM metrics before and after the change. Please, let me know when it is supported or if there is any workaround to get it working. Thanks.

[justinfoote]

We are closing this issue due to age. If this issue is still a problem, please open a new issue, reach out on the New Relic Explorers Hub or contact Support.

Thank you!