Skip to content

Commit eac0eec

Browse files
committed
docs: rails debug guide - add detail on verbose logs [ci-skip]
Why this PR? * The docs make reference to enabling verbose queries, but do not explicitly state how this can be done. * We have also reviewed other parts of the guide, and have tidied it up.
1 parent af9ecc7 commit eac0eec

File tree

2 files changed

+40
-42
lines changed

2 files changed

+40
-42
lines changed

guides/source/7_1_release_notes.md

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -866,7 +866,7 @@ Please refer to the [Changelog][active-job] for detailed changes.
866866

867867
* Add `after_discard` method to `ActiveJob::Base` to run a callback when a job is about to be discarded.
868868

869-
* Add support for logging background job enqueue callers.
869+
* Add support for logging background job enqueue callers via `config.active_job.verbose_enqueue_logs`.
870870

871871
Action Text
872872
----------

guides/source/debugging_rails_applications.md

Lines changed: 39 additions & 41 deletions
Original file line numberDiff line numberDiff line change
@@ -107,22 +107,14 @@ It can also be useful to save information to log files at runtime. Rails maintai
107107

108108
### What is the Logger?
109109

110-
Rails makes use of the `ActiveSupport::Logger` class to write log information. Other loggers, such as `Log4r`, may also be substituted.
111-
112-
You can specify an alternative logger in `config/application.rb` or any other environment file, for example:
110+
Rails makes use of the `ActiveSupport::Logger` class to write log information. Other loggers, such as `Log4r`, may be substituted:
113111

114112
```ruby
113+
# config/environments/production.rb
115114
config.logger = Logger.new(STDOUT)
116115
config.logger = Log4r::Logger.new("Application Log")
117116
```
118117

119-
Or in the `Initializer` section, add _any_ of the following
120-
121-
```ruby
122-
Rails.logger = Logger.new(STDOUT)
123-
Rails.logger = Log4r::Logger.new("Application Log")
124-
```
125-
126118
TIP: By default, each log is created under `Rails.root/log/` and the log file is named after the environment in which the application is running.
127119

128120
### Log Levels
@@ -134,11 +126,11 @@ method.
134126

135127
The available log levels are: `:debug`, `:info`, `:warn`, `:error`, `:fatal`,
136128
and `:unknown`, corresponding to the log level numbers from 0 up to 5,
137-
respectively. To change the default log level, use
129+
respectively. To change the default log level:
138130

139131
```ruby
140-
config.log_level = :warn # In any environment initializer, or
141-
Rails.logger.level = 0 # at any time
132+
# config/environments/production.rb
133+
config.log_level = :warn
142134
```
143135

144136
This is useful when you want to log under development or staging without flooding your production log with unnecessary information.
@@ -217,7 +209,7 @@ irb(main):001:0> Article.pamplemousse
217209
=> #<Comment id: 2, author: "1", body: "Well, actually...", article_id: 1, created_at: "2018-10-19 00:56:10", updated_at: "2018-10-19 00:56:10">
218210
```
219211

220-
After running `ActiveRecord.verbose_query_logs = true` in the `bin/rails console` session to enable verbose query logs and running the method again, it becomes obvious what single line of code is generating all these discrete database calls:
212+
After enabling `verbose_query_logs` we can see additional information for each query:
221213

222214
```irb
223215
irb(main):003:0> Article.pamplemousse
@@ -232,23 +224,31 @@ irb(main):003:0> Article.pamplemousse
232224
=> #<Comment id: 2, author: "1", body: "Well, actually...", article_id: 1, created_at: "2018-10-19 00:56:10", updated_at: "2018-10-19 00:56:10">
233225
```
234226

235-
Below each database statement you can see arrows pointing to the specific source filename (and line number) of the method that resulted in a database call. This can help you identify and address performance problems caused by N+1 queries: single database queries that generates multiple additional queries.
227+
Below each database statement you can see arrows pointing to the specific source filename (and line number) of the method that resulted in a database call e.g. `↳ app/models/article.rb:5`.
228+
229+
This can help you identify and address performance problems caused by N+1 queries: i.e. single database queries that generate multiple additional queries.
236230

237-
Verbose query logs are enabled by default in the development environment logs after Rails 5.2.
231+
Verbose query logs are [enabled by default](configuring.html#config-active-record-verbose-query-logs) in the development environment logs.
238232

239233
WARNING: We recommend against using this setting in production environments. It relies on Ruby's `Kernel#caller` method which tends to allocate a lot of memory in order to generate stacktraces of method calls. Use query log tags (see below) instead.
240234

241235
### Verbose Enqueue Logs
242236

243237
Similar to the "Verbose Query Logs" above, allows to print source locations of methods that enqueue background jobs.
244238

245-
It is enabled by default in development. To enable in other environments, add in `application.rb` or any environment initializer:
239+
Verbose enqueue logs are [enabled by default](/7_1_release_notes.html#active-job-notable-changes) in the development environment logs.
246240

247-
```rb
241+
```ruby
242+
# config/environments/development.rb
248243
config.active_job.verbose_enqueue_logs = true
249244
```
250245

251-
As verbose query logs, it is not recommended for use in production environments.
246+
```irb
247+
# bin/rails console
248+
ActiveJob.verbose_enqueue_logs = true
249+
```
250+
251+
WARNING: We recommend against using this setting in production environments.
252252

253253
SQL Query Comments
254254
------------------
@@ -258,9 +258,7 @@ trace troublesome queries back to the area of the application that generated the
258258
logging slow queries (e.g. [MySQL](https://dev.mysql.com/doc/refman/en/slow-query-log.html), [PostgreSQL](https://www.postgresql.org/docs/current/runtime-config-logging.html#GUC-LOG-MIN-DURATION-STATEMENT)),
259259
viewing currently running queries, or for end-to-end tracing tools.
260260

261-
To enable, add in `application.rb` or any environment initializer:
262-
263-
```rb
261+
```ruby
264262
config.active_record.query_log_tags_enabled = true
265263
```
266264

@@ -349,7 +347,7 @@ By default, a debugging session will start after the `debug` library is required
349347

350348
To enter the debugging session, you can use `binding.break` and its aliases: `binding.b` and `debugger`. The following examples will use `debugger`:
351349

352-
```rb
350+
```ruby
353351
class PostsController < ApplicationController
354352
before_action :set_post, only: %i[ show edit update destroy ]
355353
@@ -364,7 +362,7 @@ end
364362

365363
Once your app evaluates the debugging statement, it'll enter the debugging session:
366364

367-
```rb
365+
```ruby
368366
Processing by PostsController#index as HTML
369367
[2, 11] in ~/projects/rails-guide-example/app/controllers/posts_controller.rb
370368
2| before_action :set_post, only: %i[ show edit update destroy ]
@@ -389,7 +387,7 @@ You can exit the debugging session at any time and continue your application exe
389387

390388
After entering the debugging session, you can type in Ruby code as if you are in a Rails console or IRB.
391389

392-
```rb
390+
```ruby
393391
(rdbg) @posts # ruby
394392
[]
395393
(rdbg) self
@@ -399,7 +397,7 @@ After entering the debugging session, you can type in Ruby code as if you are in
399397

400398
You can also use the `p` or `pp` command to evaluate Ruby expressions, which is useful when a variable name conflicts with a debugger command.
401399

402-
```rb
400+
```ruby
403401
(rdbg) p headers # command
404402
=> {"X-Frame-Options"=>"SAMEORIGIN", "X-XSS-Protection"=>"1; mode=block", "X-Content-Type-Options"=>"nosniff", "X-Download-Options"=>"noopen", "X-Permitted-Cross-Domain-Policies"=>"none", "Referrer-Policy"=>"strict-origin-when-cross-origin"}
405403
(rdbg) pp headers # command
@@ -422,7 +420,7 @@ Besides direct evaluation, the debugger also helps you collect a rich amount of
422420

423421
`info` provides an overview of the values of local and instance variables that are visible from the current frame.
424422

425-
```rb
423+
```ruby
426424
(rdbg) info # command
427425
%self = #<PostsController:0x0000000000af78>
428426
@_action_has_layout = true
@@ -442,7 +440,7 @@ Besides direct evaluation, the debugger also helps you collect a rich amount of
442440

443441
When used without any options, `backtrace` lists all the frames on the stack:
444442

445-
```rb
443+
```ruby
446444
=>#0 PostsController#index at ~/projects/rails-guide-example/app/controllers/posts_controller.rb:7
447445
#1 ActionController::BasicImplicitRender#send_action(method="index", args=[]) at ~/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/actionpack-2.0.alpha/lib/action_controller/metal/basic_implicit_render.rb:6
448446
#2 AbstractController::Base#process_action(method_name="index", args=[]) at ~/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/actionpack-8.1.0.alpha/lib/abstract_controller/base.rb:214
@@ -482,7 +480,7 @@ It is also possible to use these options together: `backtrace [num] /pattern/`.
482480
- Class variables
483481
- Methods & their sources
484482

485-
```rb
483+
```ruby
486484
ActiveSupport::Configurable#methods: config
487485
AbstractController::Base#methods:
488486
action_methods action_name action_name= available_action? controller_path inspect
@@ -531,7 +529,7 @@ And to remove them, you can use:
531529

532530
**Set a breakpoint on a specified line number - e.g. `b 28`**
533531

534-
```rb
532+
```ruby
535533
[20, 29] in ~/projects/rails-guide-example/app/controllers/posts_controller.rb
536534
20| end
537535
21|
@@ -550,7 +548,7 @@ And to remove them, you can use:
550548
#0 BP - Line /Users/st0012/projects/rails-guide-example/app/controllers/posts_controller.rb:28 (line)
551549
```
552550

553-
```rb
551+
```ruby
554552
(rdbg) c # continue command
555553
[23, 32] in ~/projects/rails-guide-example/app/controllers/posts_controller.rb
556554
23| def create
@@ -572,7 +570,7 @@ Stop by #0 BP - Line /Users/st0012/projects/rails-guide-example/app/controller
572570

573571
Set a breakpoint on a given method call - e.g. `b @post.save`.
574572

575-
```rb
573+
```ruby
576574
[20, 29] in ~/projects/rails-guide-example/app/controllers/posts_controller.rb
577575
20| end
578576
21|
@@ -592,7 +590,7 @@ Set a breakpoint on a given method call - e.g. `b @post.save`.
592590

593591
```
594592

595-
```rb
593+
```ruby
596594
(rdbg) c # continue command
597595
[39, 48] in ~/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-7.0.0.alpha2/lib/active_record/suppressor.rb
598596
39| SuppressorRegistry.suppressed[name] = previous_state
@@ -616,7 +614,7 @@ Stop by #0 BP - Method @post.save at /Users/st0012/.rbenv/versions/3.0.1/lib/r
616614
617615
Stop when an exception is raised - e.g. `catch ActiveRecord::RecordInvalid`.
618616
619-
```rb
617+
```ruby
620618
[20, 29] in ~/projects/rails-guide-example/app/controllers/posts_controller.rb
621619
20| end
622620
21|
@@ -635,7 +633,7 @@ Stop when an exception is raised - e.g. `catch ActiveRecord::RecordInvalid`.
635633
#1 BP - Catch "ActiveRecord::RecordInvalid"
636634
```
637635
638-
```rb
636+
```ruby
639637
(rdbg) c # continue command
640638
[75, 84] in ~/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-7.0.0.alpha2/lib/active_record/validations.rb
641639
75| def default_validation_context
@@ -659,7 +657,7 @@ Stop by #1 BP - Catch "ActiveRecord::RecordInvalid"
659657

660658
Stop when the instance variable is changed - e.g. `watch @_response_body`.
661659

662-
```rb
660+
```ruby
663661
[20, 29] in ~/projects/rails-guide-example/app/controllers/posts_controller.rb
664662
20| end
665663
21|
@@ -678,7 +676,7 @@ Stop when the instance variable is changed - e.g. `watch @_response_body`.
678676
#0 BP - Watch #<PostsController:0x00007fce69ca5320> @_response_body =
679677
```
680678

681-
```rb
679+
```ruby
682680
(rdbg) c # continue command
683681
[173, 182] in ~/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/actionpack-7.0.0.alpha2/lib/action_controller/metal.rb
684682
173| body = [body] unless body.nil? || body.respond_to?(:each)
@@ -714,7 +712,7 @@ In addition to different types of breakpoints, you can also specify options to a
714712

715713
Please also note that the first 3 options: `do:`, `pre:` and `if:` are also available for the debug statements we mentioned earlier. For example:
716714

717-
```rb
715+
```ruby
718716
[2, 11] in ~/projects/rails-guide-example/app/controllers/posts_controller.rb
719717
2| before_action :set_post, only: %i[ show edit update destroy ]
720718
3|
@@ -748,7 +746,7 @@ Please also note that the first 3 options: `do:`, `pre:` and `if:` are also avai
748746

749747
With those options, you can script your debugging workflow in one line like:
750748

751-
```rb
749+
```ruby
752750
def create
753751
debugger(do: "catch ActiveRecord::RecordInvalid do: bt 10")
754752
# ...
@@ -757,7 +755,7 @@ end
757755

758756
And then the debugger will run the scripted command and insert the catch breakpoint
759757

760-
```rb
758+
```ruby
761759
(rdbg:binding.break) catch ActiveRecord::RecordInvalid do: bt 10
762760
#0 BP - Catch "ActiveRecord::RecordInvalid"
763761
[75, 84] in ~/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-7.0.0.alpha2/lib/active_record/validations.rb
@@ -778,7 +776,7 @@ And then the debugger will run the scripted command and insert the catch breakpo
778776

779777
Once the catch breakpoint is triggered, it'll print the stack frames
780778

781-
```rb
779+
```ruby
782780
Stop by #0 BP - Catch "ActiveRecord::RecordInvalid"
783781

784782
(rdbg:catch) bt 10

0 commit comments

Comments
 (0)