Move tags "message" and "backtrace" in "rails.exceptions" series to values

[vassilevsky]

Hello 🙃

I was surprised to find such enormous series in my database 😲

rails.exceptions,application_name=FooBar,application_root=/projects/foo_bar/releases/20171124132703,backtrace=["[GEM_ROOT]/gems/shrine-2.6.1/lib/shrine.rb:369\ in\ `_enforce_io'"\,"[GEM_ROOT]/gems/shrine-2.6.1/lib/shrine.rb:300\ in\ `_store'"\,"[GEM_ROOT]/gems/shrine-2.6.1/lib/shrine.rb:234\ in\ `store'"\,"[GEM_ROOT]/gems/shrine-2.6.1/lib/shrine/plugins/hooks.rb:95\ in\ `block\ in\ store'"\,"[GEM_ROOT]/gems/shrine-2.6.1/lib/shrine/plugins/hooks.rb:101\ in\ `around_store'"\,"[GEM_ROOT]/gems/shrine-2.6.1/lib/shrine/plugins/hooks.rb:95\ in\ `store'"\,"[GEM_ROOT]/gems/shrine-2.6.1/lib/shrine/plugins/logging.rb:85\ in\ `block\ in\ store'"\,"[GEM_ROOT]/gems/shrine-2.6.1/lib/shrine/plugins/logging.rb:100\ in\ `block\ in\ log'"\,"[GEM_ROOT]/gems/shrine-2.6.1/lib/shrine/plugins/logging.rb:160\ in\ `benchmark'"\,"[GEM_ROOT]/gems/shrine-2.6.1/lib/shrine/plugins/logging.rb:100\ in\ `log'"\,"[GEM_ROOT]/gems/shrine-2.6.1/lib/shrine/plugins/logging.rb:85\ in\ `store'"\,"[GEM_ROOT]/gems/shrine-2.6.1/lib/shrine.rb:212\ in\ `upload'"\,"[GEM_ROOT]/gems/shrine-2.6.1/lib/shrine/plugins/hooks.rb:56\ in\ `block\ in\ upload'"\,"[GEM_ROOT]/gems/shrine-2.6.1/lib/shrine/plugins/hooks.rb:62\ in\ `around_upload'"\,"[GEM_ROOT]/gems/shrine-2.6.1/lib/shrine/plugins/hooks.rb:56\ in\ `upload'"\,"[GEM_ROOT]/gems/shrine-2.6.1/lib/shrine.rb:614\ in\ `cache!'"\,"[GEM_ROOT]/gems/shrine-2.6.1/lib/shrine.rb:505\ in\ `assign'"\,"[GEM_ROOT]/gems/shrine-2.6.1/lib/shrine.rb:407\ in\ `avatar\='"\,"[GEM_ROOT]/gems/activemodel-5.1.3/lib/active_model/attribute_assignment.rb:46\ in\ `public_send'"\,"[GEM_ROOT]/gems/activemodel-5.1.3/lib/active_model/attribute_assignment.rb:46\ in\ `_assign_attribute'"\,"[GEM_ROOT]/gems/activemodel-5.1.3/lib/active_model/attribute_assignment.rb:40\ in\ `block\ in\ _assign_attributes'"\,"[GEM_ROOT]/gems/activemodel-5.1.3/lib/active_model/attribute_assignment.rb:39\ in\ `each'"\,"[GEM_ROOT]/gems/activemodel-5.1.3/lib/active_model/attribute_assignment.rb:39\ in\ `_assign_attributes'"\,"[GEM_ROOT]/gems/activerecord-5.1.3/lib/active_record/attribute_assignment.rb:26\ in\ `_assign_attributes'"\,"[GEM_ROOT]/gems/activemodel-5.1.3/lib/active_model/attribute_assignment.rb:33\ in\ `assign_attributes'"\,"[GEM_ROOT]/gems/activerecord-5.1.3/lib/active_record/persistence.rb:297\ in\ `block\ in\ update!'"\,"[GEM_ROOT]/gems/activerecord-5.1.3/lib/active_record/transactions.rb:384\ in\ `block\ in\ with_transaction_returning_status'"\,"[GEM_ROOT]/gems/activerecord-5.1.3/lib/active_record/connection_adapters/abstract/database_statements.rb:235\ in\ `block\ in\ transaction'"\,"[GEM_ROOT]/gems/activerecord-5.1.3/lib/active_record/connection_adapters/abstract/transaction.rb:194\ in\ `block\ in\ within_new_transaction'"\,"/usr/local/rbenv/versions/2.4.2-p0/lib/ruby/2.4.0/monitor.rb:214\ in\ `mon_synchronize'"\,"[GEM_ROOT]/gems/activerecord-5.1.3/lib/active_record/connection_adapters/abstract/transaction.rb:191\ in\ `within_new_transaction'"\,"[GEM_ROOT]/gems/activerecord-5.1.3/lib/active_record/connection_adapters/abstract/database_statements.rb:235\ in\ `transaction'"\,"[GEM_ROOT]/gems/activerecord-5.1.3/lib/active_record/transactions.rb:210\ in\ `transaction'"\,"[GEM_ROOT]/gems/activerecord-5.1.3/lib/active_record/transactions.rb:381\ in\ `with_transaction_returning_status'"\,"[GEM_ROOT]/gems/activerecord-5.1.3/lib/active_record/persistence.rb:296\ in\ `update!'"\,"[APP_ROOT]/app/controllers/foo_controller.rb:30\ in\ `update'"\,"[GEM_ROOT]/gems/actionpack-5.1.3/lib/action_controller/metal/basic_implicit_render.rb:4\ in\ `send_action'"\,"[GEM_ROOT]/gems/actionpack-5.1.3/lib/abstract_controller/base.rb:186\ in\ `process_action'"\,"[GEM_ROOT]/gems/actionpack-5.1.3/lib/action_controller/metal/rendering.rb:30\ in\ `process_action'"\,"[GEM_ROOT]/gems/actionpack-5.1.3/lib/abstract_controller/callbacks.rb:20\ in\ `block\ in\ process_action'"\,"[GEM_ROOT]/gems/activesupport-5.1.3/lib/active_support/callbacks.rb:108\ in\ `block\ in\ run_callbacks'"\,"[GEM_ROOT]/gems/sentry-raven-2.7.1/lib/raven/integrations/rails/controller_transaction.rb:7\ in\ `block\ in\ included'"\,"[GEM_ROOT]/gems/activesupport-5.1.3/lib/active_support/callbacks.rb:117\ in\ `instance_exec'"\,"[GEM_ROOT]/gems/activesupport-5.1.3/lib/active_support/callbacks.rb:117\ in\ `block\ in\ run_callbacks'"\,"[GEM_ROOT]/gems/activesupport-5.1.3/lib/active_support/callbacks.rb:135\ in\ `run_callbacks'"\,"[GEM_ROOT]/gems/actionpack-5.1.3/lib/abstract_controller/callbacks.rb:19\ in\ `process_action'"\,"[GEM_ROOT]/gems/actionpack-5.1.3/lib/action_controller/metal/rescue.rb:20\ in\ `process_action'"\,"[GEM_ROOT]/gems/actionpack-5.1.3/lib/action_controller/metal/instrumentation.rb:32\ in\ `block\ in\ process_action'"\,"[GEM_ROOT]/gems/activesupport-5.1.3/lib/active_support/notifications.rb:166\ in\ `block\ in\ instrument'"\,"[GEM_ROOT]/gems/activesupport-5.1.3/lib/active_support/notifications/instrumenter.rb:21\ in\ `instrument'"\,"[GEM_ROOT]/gems/activesupport-5.1.3/lib/active_support/notifications.rb:166\ in\ `instrument'"\,"[GEM_ROOT]/gems/actionpack-5.1.3/lib/action_controller/metal/instrumentation.rb:30\ in\ `process_action'"\,"[GEM_ROOT]/gems/actionpack-5.1.3/lib/action_controller/metal/params_wrapper.rb:252\ in\ `process_action'"\,"[GEM_ROOT]/gems/activerecord-5.1.3/lib/active_record/railties/controller_runtime.rb:22\ in\ `process_action'"\,"[GEM_ROOT]/gems/actionpack-5.1.3/lib/abstract_controller/base.rb:124\ in\ `process'"\,"[GEM_ROOT]/gems/actionview-5.1.3/lib/action_view/rendering.rb:30\ in\ `process'"\,"[GEM_ROOT]/gems/actionpack-5.1.3/lib/action_controller/metal.rb:189\ in\ `dispatch'"\,"[GEM_ROOT]/gems/actionpack-5.1.3/lib/action_controller/metal.rb:253\ in\ `dispatch'"\,"[GEM_ROOT]/gems/actionpack-5.1.3/lib/action_dispatch/routing/route_set.rb:49\ in\ `dispatch'"\,"[GEM_ROOT]/gems/actionpack-5.1.3/lib/action_dispatch/routing/route_set.rb:31\ in\ `serve'"\,"[GEM_ROOT]/gems/actionpack-5.1.3/lib/action_dispatch/journey/router.rb:46\ in\ `block\ in\ serve'"\,"[GEM_ROOT]/gems/actionpack-5.1.3/lib/action_dispatch/journey/router.rb:33\ in\ `each'"\,"[GEM_ROOT]/gems/actionpack-5.1.3/lib/action_dispatch/journey/router.rb:33\ in\ `serve'"\,"[GEM_ROOT]/gems/actionpack-5.1.3/lib/action_dispatch/routing/route_set.rb:834\ in\ `call'"\,"[GEM_ROOT]/gems/cp-sparrow-0.0.16/lib/sparrow/response_middleware.rb:11\ in\ `call'"\,"[APP_ROOT]/middlewares/log_http_response_body_middleware.rb:7\ in\ `call'"\,"[GEM_ROOT]/gems/rack-2.0.3/lib/rack/etag.rb:25\ in\ `call'"\,"[GEM_ROOT]/gems/rack-2.0.3/lib/rack/conditional_get.rb:38\ in\ `call'"\,"[GEM_ROOT]/gems/rack-2.0.3/lib/rack/head.rb:12\ in\ `call'"\,"[GEM_ROOT]/gems/rack-2.0.3/lib/rack/session/abstract/id.rb:232\ in\ `context'"\,"[GEM_ROOT]/gems/rack-2.0.3/lib/rack/session/abstract/id.rb:226\ in\ `call'"\,"[GEM_ROOT]/gems/actionpack-5.1.3/lib/action_dispatch/middleware/cookies.rb:613\ in\ `call'"\,"[GEM_ROOT]/gems/actionpack-5.1.3/lib/action_dispatch/middleware/callbacks.rb:26\ in\ `block\ in\ call'"\,"[GEM_ROOT]/gems/activesupport-5.1.3/lib/active_support/callbacks.rb:97\ in\ `run_callbacks'"\,"[GEM_ROOT]/gems/actionpack-5.1.3/lib/action_dispatch/middleware/callbacks.rb:24\ in\ `call'"\,"[GEM_ROOT]/gems/actionpack-5.1.3/lib/action_dispatch/middleware/executor.rb:12\ in\ `call'"\,"[GEM_ROOT]/gems/actionpack-5.1.3/lib/action_dispatch/middleware/debug_exceptions.rb:59\ in\ `call'"\,"[GEM_ROOT]/gems/actionpack-5.1.3/lib/action_dispatch/middleware/show_exceptions.rb:31\ in\ `call'"\,"[APP_ROOT]/middlewares/request_data_log_middleware.rb:8\ in\ `call'"\,"[GEM_ROOT]/gems/cp-sparrow-0.0.16/lib/sparrow/middleware.rb:33\ in\ `call'"\,"[APP_ROOT]/lib/monkeypatches/sparrow/middleware_extension.rb:6\ in\ `call'"\,"[GEM_ROOT]/gems/service_revision-1.1.0/lib/service_revision/revision_rack_middleware.rb:11\ in\ `call'"\,"[GEM_ROOT]/gems/railties-5.1.3/lib/rails/rack/logger.rb:36\ in\ `call_app'"\,"[GEM_ROOT]/gems/railties-5.1.3/lib/rails/rack/logger.rb:24\ in\ `block\ in\ call'"\,"[GEM_ROOT]/gems/activesupport-5.1.3/lib/active_support/tagged_logging.rb:69\ in\ `block\ in\ tagged'"\,"[GEM_ROOT]/gems/activesupport-5.1.3/lib/active_support/tagged_logging.rb:26\ in\ `tagged'"\,"[GEM_ROOT]/gems/activesupport-5.1.3/lib/active_support/tagged_logging.rb:69\ in\ `tagged'"\,"[GEM_ROOT]/gems/railties-5.1.3/lib/rails/rack/logger.rb:24\ in\ `call'"\,"[GEM_ROOT]/gems/actionpack-5.1.3/lib/action_dispatch/middleware/remote_ip.rb:79\ in\ `call'"\,"[GEM_ROOT]/gems/unilog-1.2.3/lib/unilog/ext/action_dispatch/middleware/request_id.rb:9\ in\ `block\ in\ call'"\,"[GEM_ROOT]/gems/unilog-1.2.3/lib/unilog.rb:92\ in\ `within_context'"\,"[GEM_ROOT]/gems/unilog-1.2.3/lib/unilog/ext/action_dispatch/middleware/request_id.rb:8\ in\ `call'"\,"[GEM_ROOT]/gems/rack-2.0.3/lib/rack/method_override.rb:22\ in\ `call'"\,"[GEM_ROOT]/gems/rack-2.0.3/lib/rack/runtime.rb:22\ in\ `call'"\,"[GEM_ROOT]/gems/activesupport-5.1.3/lib/active_support/cache/strategy/local_cache_middleware.rb:27\ in\ `call'"\,"[GEM_ROOT]/gems/actionpack-5.1.3/lib/action_dispatch/middleware/executor.rb:12\ in\ `call'"\,"[GEM_ROOT]/gems/rack-2.0.3/lib/rack/sendfile.rb:111\ in\ `call'"\,"[GEM_ROOT]/gems/influxdb-rails-0.4.0/lib/influxdb/rails/rack.rb:14\ in\ `_call'"\,"[GEM_ROOT]/gems/influxdb-rails-0.4.0/lib/influxdb/rails/rack.rb:9\ in\ `call'"\,"[GEM_ROOT]/gems/sentry-raven-2.7.1/lib/raven/integrations/rack.rb:51\ in\ `call'"\,"[GEM_ROOT]/gems/railties-5.1.3/lib/rails/engine.rb:522\ in\ `call'"\,"[GEM_ROOT]/gems/rack-2.0.3/lib/rack/tempfile_reaper.rb:15\ in\ `call'"\,"[GEM_ROOT]/gems/rack-2.0.3/lib/rack/lint.rb:49\ in\ `_call'"\,"[GEM_ROOT]/gems/rack-2.0.3/lib/rack/lint.rb:37\ in\ `call'"\,"[GEM_ROOT]/gems/rack-2.0.3/lib/rack/show_exceptions.rb:23\ in\ `call'"\,"[GEM_ROOT]/gems/rack-2.0.3/lib/rack/common_logger.rb:33\ in\ `call'"\,"[GEM_ROOT]/gems/rack-2.0.3/lib/rack/chunked.rb:54\ in\ `call'"\,"[GEM_ROOT]/gems/rack-2.0.3/lib/rack/content_length.rb:15\ in\ `call'"\,"[GEM_ROOT]/gems/unicorn-5.3.0/lib/unicorn/http_server.rb:606\ in\ `process_client'"\,"[GEM_ROOT]/gems/unicorn-5.3.0/lib/unicorn/http_server.rb:702\ in\ `worker_loop'"\,"[GEM_ROOT]/gems/unicorn-5.3.0/lib/unicorn/http_server.rb:549\ in\ `spawn_missing_workers'"\,"[GEM_ROOT]/gems/unicorn-5.3.0/lib/unicorn/http_server.rb:142\ in\ `start'"\,"[GEM_ROOT]/gems/unicorn-5.3.0/bin/unicorn:126\ in\ `<top\ (required)>'"\,"[GEM_ROOT]/bin/unicorn:23\ in\ `load'"\,"[GEM_ROOT]/bin/unicorn:23\ in\ `<main>'"],class=Shrine::InvalidFile,custom_data={},filename=shrine.rb,framework=Rails,framework_version=5.1.3,language=Ruby,language_version=2.4.2-p198,message=0\ is\ not\ a\ valid\ IO\ object\ (it\ doesn't\ respond\ to\ #read\,\ #eof?\,\ #rewind\,\ #close),method=#,server=foobar.ru,status=open

I propose this move of long and highly variable data from tags to values.

What else can be done?

[dmke]

Hm, the original implementation really looks like a mistake. However, just moving the keys from the tag set to the value set will introduce unwanted fields:

$ influx
> insert test1,foo=bar baz=21i
> insert test1 foo="snafu",baz=42i
> select * from test1
name: test1
time                baz foo   foo_1
----                --- ---   -----
1513948026343760560 21        bar
1513948045110594133 42  snafu 

I suggest using different keys for ExceptionPresenter#values, maybe exception_message and exception_backtrace.

Since both scenarios (just moving vs. also renaming) will need a backward incompatible release, users can at least continue to use the same measurement when the keys don't stay message and backtrace (although, I'd strongly advise using a new measurement and migrating the old data...)

[dmke]

@toddboom As far as I can see, you've authored the code in question (some years ago :-)) Do you remember, why the message and backtrace ended up in the tag set?

[dmke]

Btw. I don't expect any response this year, this time is stressful enough :-)

🎅 🌟 🎁

[kkentzo]

Any progress on this? We have a branch in our forked version that extends @vassilevsky's branch by implementing the changes proposed by @dmke (basically renaming the exception field keys).

Would a new PR be the way to go?

[dmke]

Another PR is not necessary, I'll pull directly from your fork.

If I don't hear from @toddboom by next week, I'll just merge it in, if that's OK with you.

[vassilevsky]

Hi :) I'm fine by any solution. Not really wanting to show off here :)

[dmke]

I'm going to include these changes in an upcoming 1.0 release (ETA: on the weekend).

[toddboom]

@dmke hey, sorry for being radio silent on this for so long! i think your intuitions on this are correct. my guess is that the exception being encoded as a tag probably goes way, way back to a time when we were internally (possibly for Errplane, which was pre-InfluxDB) planning to use the exception as part of an indexing strategy. in hindsight, this was a terrible idea and i fully support making it a value instead. merge away!

[dmke]

Will do! :-)

[dmke]

Merged in eb465f2.