Apparently never ending "Indexing call sites..."

[akimd]

Hi Justin,

Background

Brakeman version: 5.2.1
Rails version: 6.1.4.1
Ruby version: 2.7.2

Link to Rails application code: Sorry, I don't own the code, cannot do that. Besides I don't know what specific file would be responsible.

Hanging or Slowness

Please run Brakeman with --debug to see which file may be causing the issue.

I did that, and actually I'd like to know if there's a way for Brakeman to be even more verbose and to describe what it's doing in this "Indexing" phase. I have not stopped it, maybe it is still making progress, I do not know, and don't know how I could know.

It displayed this "Indexing" message four hours ago.

Cheers!

[akimd]

It's now been running for 20 hours.

[presidentbeef]

Hi @akimd - if Brakeman runs for more than ten minutes, there is probably something wrong.

No, there is no out-of-the-box way to get visibility into what's happening during the call indexing phase.

Is this a large codebase? Is Brakeman running in a memory-constrained environment?

[akimd]

Justin,

If you have a suggested diff to make it more verbose, I can do that.
Yes, the code base is quite large. wc -l on app/models say 462872 for instance.

But now that I ran ps on it, I can see that its state is "(interruptible) Sleeping".

It it run this way:

bundle exec brakeman --no-exit-on-warn --no-exit-on-error --output test/brakeman.json --parser-timeout 30 --skip-files app/views/user_login_attempts/_query_builder_filters_list.html.erb,...,app/views/specialties/_query_builder_filters_list.html.erb,app/views/search_bookmarks/_query_builder_filters_list.html.erb --safe-methods strip_tags -d -n

And ps aux says

USER     PID %CPU %MEM        VSZ       RSS TTY  STAT START   TIME COMMAND
xxx   968078  2.8  4.8 10.563.924 6.354.424 ?    S    Mar30  40:58 /gems/bin/brakeman --no-exit-on-warn --no-exit-on-error --output test/brakeman.json --parser-timeout 30 --skip-files app/views/user_login_attempts/_query_builder_filters_list.html.erb,...

Any idea what it might be waiting for?

[presidentbeef]

Honestly still think it's a memory issue.

I'll get back to you with a diff. If it's really stuck at call indexing, the debug flag isn't going to be helpful and in fact could be making the issue worse.

[presidentbeef]

@akimd

I'd try adding logging to lib/brakeman/tracker.rb to show progress during call indexing:

diff --git a/lib/brakeman/tracker.rb b/lib/brakeman/tracker.rb
index b6894f8b8..2b3c60c5d 100644
--- a/lib/brakeman/tracker.rb
+++ b/lib/brakeman/tracker.rb
@@ -253,21 +253,27 @@ class Brakeman::Tracker
     finder = Brakeman::FindAllCalls.new self
 
     self.each_method do |definition, set_name, method_name, file|
+      Brakeman.notify "[Call Index] #{file} #{set_name} #{method_name}"
       finder.process_source definition, :class => set_name, :method => method_name, :file => file
     end
 
     self.each_class do |definition, set_name, file|
+      Brakeman.notify "[Call Index] #{file} #{set_name}"
       finder.process_source definition, :class => set_name, :file => file
     end
 
     self.each_template do |_name, template|
+      Brakeman.notify "[Call Index] #{template.file}"
       finder.process_source template.src, :template => template, :file => template.file
     end
 
     self.initializers.each do |file_name, src|
+      Brakeman.notify "[Call Index] #{file_name}"
       finder.process_all_source src, :file => file_name
     end
 
+    Brakeman.notify "Creating call index..."
+
     @call_index = Brakeman::CallIndex.new finder.calls
   end

I'd also skip the -d flag.

I also recommend using a beefy machine with lots of free memory. Unfortunately Brakeman uses a lot of memory, especially for large applications.

You can also try the --faster and --skip-vendor flags to see if either or both of those help.

[akimd]

Hi Justin,
Thanks for the patch!
Now brakeman is stuck in a different state, but it seems to still be consuming some CPU:

USER         PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
XXXXXXXX 1069204 33.8  5.2 10419236 6926412 ?    D    14:11  35:47 /gems/bin/brakeman --no-exit-on-warn --no-exit-on-error --output test/brakeman.json --parser-timeout 30 --skip-files app/views/user_login_attempts/_query_builder_filters_list.html.erb,[...]

The man page says "D uninterruptible sleep (usually IO)".

The logs:

bundle exec brakeman --no-exit-on-warn --no-exit-on-error --output test/brakeman.json --parser-timeout 30 --skip-files app/views/user_login_attempts/_query_builder_filters_list.html.erb,[...] --safe-methods strip_tags
[...]
W, WARN -- : [Call Index] /app/app/views/app_archive_options/_result_list.html.erb
W, WARN -- : [Call Index] /app/app/views/app_archive_options/_select_active_show.html.erb
W, WARN -- : [Call Index] /app/app/views/app_archive_options/async_ongoing.html.erb
W, WARN -- : [Call Index] /app/app/views/app_archive_options/dev_menu.html.erb

There's nothing specific about this last file.

$ ls -l app/views/app_archive_options/dev_menu.html.erb
-rw-r--r-- 1 xxx xxx 64532 Feb 28 09:40 app/views/app_archive_options/dev_menu.html.erb

As a matter of fact it grokked other versions of it for other types of resources. I'll send that file to you privately.

I will also --skip it to see if that's exactly this file, or other would jam it the same way.

Wrt RAM, here's what I get on this machine (well, this image)

$ free
              total        used        free      shared  buff/cache   available
Mem:      131883128    69530292     5046332     8608256    57306504    53174536
Swap:     270532600    16853832   253678768

Cheers!

[akimd]

I'll send that file to you privately.

Couldn't find a way to do that :)

[akimd]

Hey, actually it still moves! It appeared to be stuck for a long while on [Call Index] /app/app/views/app_archive_options/dev_menu.html.erb, but it's gone further.

W, WARN -- : Creating call index...
W, WARN -- : Running checks in parallel...
[...]
W, WARN -- :  - CheckWithoutProtection
W, WARN -- :  - CheckXMLDoS
W, WARN -- :  - CheckYAMLParsing

and now it is back in Sl, i.e., state S but multithreaded (I had not passed -n this time).

USER         PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
xxxxxxxx 1069204 28.4  5.5 10790712 7299152 ?    Sl   14:11  39:28 /gems/bin/brakeman [...]

[akimd]

It eventually ended.

It started at 2022-04-01 14:11:46 and finished at 2022-04-01 17:53:05, in parallel.

I'll see if I can add timestamps to my logs to see what steps were really long.

[presidentbeef]

That's the longest successful run I've ever heard of.

Unless there is a really obvious root cause that you can easily reproduce with sample code, it's probably going to be hard to improve the situation without access to the source code of the Rails app.

[akimd]

Justin,
Yes, I understand all this. Is there a way for brakeman to spit statistics that could help me get an idea of what part of the app was so expensive to process? Or maybe just metrics.

[presidentbeef]

@akimd Not as-is, but adding logging for different stages is pretty easy. I can send you a diff, if you want.

Typically, though, there is some pathological case that causes an explosion of nodes in Brakeman. Figuring out where that's happening can be challenging... especially if an app takes hours to process.

Question... is it only the call indexing part that is slow? Or is it everything?

This is giving me flashbacks to 2012 😄