Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Stop logging all noisy stack trace when actual trace is empty and simply point where to configure trace #25222

Merged
merged 2 commits into from Jul 2, 2016

Conversation

@vipulnsward
Copy link
Member

@vipulnsward vipulnsward commented May 31, 2016

r? @dhh

First pass at: Stop logging all noisy stack trace when actual trace is empty and simply point where to configure trace.

Fixes #25219
See also #24434

@@ -146,14 +146,15 @@ def render(status, body, format)
[status, {'Content-Type' => "#{format}; charset=#{Response.default_charset}", 'Content-Length' => body.bytesize.to_s}, [body]]
end

EMPTY_BACKTRACE_MESSAGE = ["[Backtrace silenced by Rails. Tweak config/initializers/backtrace_silencer.rb if needed]"]
Copy link
Member

@dhh dhh Jun 1, 2016

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Let's get a little more specific: [Framework-specific backtrace silenced by Rails. Tweak config/initializers/backtrace_silencer.rb if needed].

Loading

@matthewd
Copy link
Member

@matthewd matthewd commented Jun 1, 2016

I don't understand how this is an improvement. If something has gone wrong in the framework code, the first thing anyone will need in order to diagnose it is the framework backtrace; this just seems likely to result in people turning off the silencer, then being worse off on normal application errors.

(This change is unrelated to @dhh's issue in #25219 -- that's about an error in the console, caused by a typo. This is about suppressing the backtrace when something goes wrong inside, say, Action Controller... or perhaps more likely, some third party gem's middleware.)

Loading

@dhh
Copy link
Member

@dhh dhh commented Jun 1, 2016

It's to address #24434 as well. We might have said "that's expected behavior", but I think that's a wrong expected behavior. We shouldn't be exposing the user to a framework trace when the exception is part of the public interface (rather than because Rails died unexpectedly inside itself).

Loading

@matthewd
Copy link
Member

@matthewd matthewd commented Jun 1, 2016

Yeah, agreed on the public-interface exception. But I'd hope we can do a better job of distinguishing them than simply assume any exception from inside the framework is capable of standing on its own, devoid of context.

Actually, are there exceptions other than RoutingError for which this is true? That particular exception is raised in this very middleware, so giving it special treatment isn't unreasonable... in fact, we already do.

Loading

@dhh
Copy link
Member

@dhh dhh commented Jun 1, 2016

Yeah, that's all fair. If we can close all the public-interface exceptions,
console/routing/whatever, then I'm happy to see that path play out as well.
Though I'll say it's been a very long time since I've seen a genuine
framework error bubble up through user code like this as well.

On Wed, Jun 1, 2016 at 2:25 PM, Matthew Draper notifications@github.com
wrote:

Yeah, agreed on the public-interface exception. But I'd hope we can do a
better job of distinguishing them than simply assume any exception from
inside the framework is capable of standing on its own, devoid of context.

Actually, are there exceptions other than RoutingError for which this is
true? That particular exception is raised in this very middleware, so
giving it special treatment isn't unreasonable... in fact, we already do
https://github.com/rails/rails/blob/5-0-stable/actionpack/lib/action_dispatch/middleware/debug_exceptions.rb#L124
.


You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
#25222 (comment), or mute
the thread
https://github.com/notifications/unsubscribe/AAAKtXLC35k2XRSeHTPhr28z_myibG_7ks5qHXo2gaJpZM4IqvJu
.

Loading

@vipulnsward
Copy link
Member Author

@vipulnsward vipulnsward commented Jun 1, 2016

Yes, as pointed out, I haven't addressed the console scenario. I am looking into it, and its a bit tricky than middlewares. IRB has its own cleanup https://github.com/ruby/ruby/blob/trunk/lib/irb/workspace.rb#L91-L110 . I am trying to see if we can hook into it cleanly.

Loading

@gsamokovarov
Copy link
Contributor

@gsamokovarov gsamokovarov commented Jun 1, 2016

I have something similar for web-console, when evaluating code in it: https://github.com/rails/web-console/blob/master/lib/web_console/evaluator.rb. You may try something similar providing an interface like Binding (e.g. #eval) and doing the cleanup there. E.g. wrap the TOPLEVEL_BINDING in this self-cleaning object and pass it straight to IRB when starting it.

Loading

@vipulnsward
Copy link
Member Author

@vipulnsward vipulnsward commented Jun 1, 2016

Sweet. Thanks, let me see.

Loading

@gsamokovarov
Copy link
Contributor

@gsamokovarov gsamokovarov commented Jun 1, 2016

Although, there seem to be type checks in the IRB code, so this approach may not be feasible. 😞 Anyway, just an idea. 😄

Loading

@vipulnsward
Copy link
Member Author

@vipulnsward vipulnsward commented Jun 7, 2016

@matthewd @dhh this takes care of the filtering/cleaning, and uses existing setup, config, etc. Do we want to go down this path for cleanup on console?

module IRB # :nodoc:
  class WorkSpace # :nodoc:
    alias :orig_filter_backtrace :filter_backtrace
    def filter_backtrace(bt)
      res = orig_filter_backtrace(bt)
      res = Rails.backtrace_cleaner.clean([res.to_s])[0]
      res
    end
  end
end

Loading

@@ -7,6 +7,12 @@ module Rails
class Console
include ConsoleHelper

module BacktraceCleaner
def filter_backtrace(bt)
(v = super) && Rails.backtrace_cleaner.filter([v]).first
Copy link
Contributor

@gsamokovarov gsamokovarov Jun 24, 2016

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

A small cosmetic nit: we can avoid reverencing the named argument, as we are not using it (may avoid Ruby warnings). We can also make the condition a bit more explicit.

def filter_backtrace(_)
  if v = super
    Rails.backtrace_cleaner.filter([v]).first
  end
end

Loading

@vipulnsward
Copy link
Member Author

@vipulnsward vipulnsward commented Jun 28, 2016

Updated.
@matthewd

  • This doesn't collide with pry/debug etc, they have a wrapper around for exception trapping and don't rely on our console.
  • I tried to add some test for this, but its a bit unusual since it goes to interactive mode. There are no related tests on https://github.com/ruby/ruby/tree/trunk/test/irb that could be used for reference.

I believe the plan of action is to get #25343 in first and then this.

Loading

@matthewd
Copy link
Member

@matthewd matthewd commented Jun 28, 2016

@vipulnsward this PR is changing two things that are only very loosely related; better to split it in two. (Particularly as I'm not yet sold on the non-irb change being the right approach. And it has nothing to do with the original issue description in #25219.)

We also still need the "and then" part of my proposed plan here.

Loading

@vipulnsward
Copy link
Member Author

@vipulnsward vipulnsward commented Jun 28, 2016

Cool, let me create a new PR for that change and discussion. I will restrict this one for IRB changes.

Loading

@@ -7,6 +7,14 @@ module Rails
class Console
include ConsoleHelper

module BacktraceCleaner
def filter_backtrace(bt)
if _res = super
Copy link
Member

@matthewd matthewd Jun 28, 2016

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why the underscore / abbr?

Loading

@vipulnsward
Copy link
Member Author

@vipulnsward vipulnsward commented Jun 29, 2016

Updated to just have the backtrace cleaner for IRB

Loading

@matthewd
Copy link
Member

@matthewd matthewd commented Jun 29, 2016

❤️

The "and then" I mentioned above is amending https://github.com/rails/rails/blob/master/railties/lib/rails/backtrace_cleaner.rb#L5 so it considers (irb) to be 'application code'. (Maybe we should just match on /^\(/. That'd be good for pry... do we know of anything else that uses a (foo)-style fake filename?)

Loading

Add handling of cleaning up backtrace from IRB console in case of errors
"from /Path/to/rails/railties/lib/rails/commands/commands_tasks.rb:49:in `run_command!'",
"from /Path/to/rails/railties/lib/rails/commands.rb:18:in `<top (required)>'",
"from bin/rails:4:in `require'",
"from bin/rails:4:in `<main>'" ]
Copy link
Member

@matthewd matthewd Jul 1, 2016

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That's a lot of array, given the following assertion is only checking that the first entry survives 😄

Loading

… irb as user/lib code

- Cleaned up backtrace cleaner test code and removed instaces variables
test "should consider traces from irb lines as User code" do
backtrace = [ "from (irb):1",
"from /Path/to/rails/railties/lib/rails/commands/console.rb:77:in `start'",
"from bin/rails:4:in `<main>'" ]
Copy link
Member Author

@vipulnsward vipulnsward Jul 1, 2016

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pushed a variant to just have three different kind of traces 😄

Loading

@matthewd matthewd merged commit edc5603 into rails:master Jul 2, 2016
@kaspth
Copy link
Member

@kaspth kaspth commented Jul 5, 2016

Loading

@vipulnsward vipulnsward deleted the 25219-fix-logs branch Oct 27, 2016
@lordofthedanse
Copy link

@lordofthedanse lordofthedanse commented Jul 27, 2017

@matthewd @dhh apologize for being so late to the party, but I don't think we're getting the the behavior intended re: app traces versus stack traces ...

@matthewd wrote

Actually, are there exceptions other than RoutingError for which this is true? That particular exception is raised in this very middleware, so giving it special treatment isn't unreasonable... in fact, we already do.

which points to

      trace_to_show = 'Application Trace'
      if traces[trace_to_show].empty? && wrapper.rescue_template != 'routing_error'
        trace_to_show = 'Full Trace'
      end

But, I'm pretty sure that means I shouldn't be getting this:

15:11:11 web.1       | ActionController::RoutingError (No route matches [GET] "/uploads/store/user_avatars/f09944d311.jpg"):
15:11:11 web.1       |   
15:11:11 web.1       | actionpack (5.1.2) lib/action_dispatch/middleware/debug_exceptions.rb:63:in `call'
15:11:11 web.1       | actionpack (5.1.2) lib/action_dispatch/middleware/show_exceptions.rb:31:in `call'
15:11:11 web.1       | railties (5.1.2) lib/rails/rack/logger.rb:36:in `call_app'
15:11:11 web.1       | railties (5.1.2) lib/rails/rack/logger.rb:24:in `block in call'
15:11:11 web.1       | activesupport (5.1.2) lib/active_support/tagged_logging.rb:69:in `block in tagged'
15:11:11 web.1       | activesupport (5.1.2) lib/active_support/tagged_logging.rb:26:in `tagged'
15:11:11 web.1       | activesupport (5.1.2) lib/active_support/tagged_logging.rb:69:in `tagged'

Loading

@matthewd
Copy link
Member

@matthewd matthewd commented Aug 2, 2017

Yeah, it looks like that change (#24434) fell off the radar: this line needs an extra condition to make it more like the one you quoted. The above is used to decide whether/which trace to show in the HTML response, but the decision for the log is made separately.

Loading

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked issues

Successfully merging this pull request may close these issues.

None yet

6 participants