o19s / quepid

Improve your Elasticsearch, OpenSearch, Solr, Vectara, Algolia and Custom Search search quality.
http://www.quepid.com
Apache License 2.0
280 stars 100 forks source link

DB password can be printed to logs in production environment #601

Closed schicks closed 1 year ago

schicks commented 1 year ago

Describe the bug If the database connection URI does not parse as a URI, an error is thrown containing the whole content of the connection string. This can include a password.

To Reproduce Steps to reproduce the behavior:

  1. set DATABASE_URL=mysql2://user:my_weird^password@mysql:3306/quepid
  2. look at the logs

Expected behavior The same error would be thrown but would reference the DATABASE_URL by name rather than showing the value

epugh commented 1 year ago

Thanks @schicks for this... All of this is part of Rails... Do you have any pointers to how to prevent this? I'm actually a bit surprised sicne there is a lot of "sensistive content being hidden" stuff available in Rails...

schicks commented 1 year ago

Honestly I don't know a whole lot about rails. My best guess would be to change the database config so that the prod case looks more like the general case. if rails is trying to hide sensitive content, having the password split out into its own supplied field seems like a good way to communicate that this field should be hidden, which might be hard to identify when the db connection string is given all as one variable.

Another, simpler approach would be to change the log level to be configurable via an environment variable, so that we could just suppress all warning logs in production to avoid the issue.

olivierlacan commented 1 year ago

Edit: misunderstood the issue, see later comment.

Try to add :database_url (it uses a regex match) to Rails.application.config.filter_parameters in https://github.com/o19s/quepid/blob/34d6e45a929dc8626b3aeeb8743de5c1c6d2dc8b/config/initializers/filter_parameter_logging.rb#L6

I can't remember for sure if the Rails logger abides by filter_parameters but it really should even outside request/response cycle calls to the logger.

Should be fairly easy to test.

epugh commented 1 year ago

I am a bit surpirsed this isn't a default convention in Rails! Patch to rails ? ;-)

olivierlacan commented 1 year ago

I am a bit surpirsed this isn't a default convention in Rails! Patch to rails ? ;-)

I'm pretty sure the common database drivers out there filter DATABASE_PASSWORD and DATABASE_URL env vars from logs since it's a common way to configure Rails apps, notably on Heroku.

So I'm not sure why the leak occurred here but I haven't looked very deeply in the configuration yet.

olivierlacan commented 1 year ago

Just realized we're talking about the value of ENV["DATABASE_URL"] here, not the key DATABASE_URL which would get you nowhere. So generally, I'd say it's an extremely bad idea to ever log out DATABASE_URL itself and probably why Rails doesn't default to it.

If you want to log database connection details at best I would try to retrieve whichever DB_HOST (not sure why the prefix is different but that's what you have in config/database.yml) is configured, not the DATABASE_URL.

Otherwise, I'd recommend retrieving the host from the application configuration interface instead perhaps.

You can retrieve that from Rails.configuration.database_configuration at runtime but it is a Ruby object:

{"default"=>{"adapter"=>"mysql2", "encoding"=>"utf8mb4", "pool"=>5},
 "development"=>
  {"adapter"=>"mysql2",
   "encoding"=>"utf8mb4",
   "pool"=>5,
   "database"=>"development_db_name",
   "host"=>"localhost",
   "username"=>"olivierlacan",
   "password"=>nil},
 "test"=>
  {"adapter"=>"mysql2",
   "encoding"=>"utf8mb4",
   "pool"=>5,
   "host"=>"localhost",
   "database"=>"test_db_name"},
 "production"=>
  {"adapter"=>"mysql2", "encoding"=>"utf8mb4", "pool"=>5, "url" => "mysql2://user:my_weird^password@mysql:3306/quepid"}}

So I'm not sure what is logging out the full DATABASE_URL, could be the mysql2 gem somehow, but if this is something quepid is specifically logging out somewhere, you could do something like:

if Rails.env.production?
  logger.info("Failed to connect to database")
elsif
  logger.info("Failed to connect to database: #{Rails.configuration.database_configuration[Rails.env]}")
end 

It would only print out the environment-relevant database config in other environments than production, which would prevent the issue @schicks is having here.

olivierlacan commented 1 year ago

@epugh Sadly, I don't think this issue is fixable by quepid.

As you suggested this seems like something Rails should handle actually. It probably should rescue this URI exception from Ruby to avoid accidental credential leakage.

Might be something to run by Rails folks, I'll open an issue there to see what they think.

Reproduction

I reproduced the issue in development with the following:

# config/database.yml

# ...
development:
  <<: *default
  database: <%= ENV["DB_NAME"] %>_development
  url: <%= ENV["DATABASE_URL"] %>
# .env

# ... 
# DB_HOST=mysql
# DB_USERNAME=root
# DB_PASSWORD=password
# DB_NAME=quepid

DATABASE_URL=mysql2://user:my_weird^password@mysql:3306/quepid

Then started development server (after following the excellent README setup instructions):

$ bin/docker server

Log output

Exception

! Unable to load application: URI::InvalidURIError: bad URI(is not URI?): mysql2://user:my_weird^password@mysql:3306/quepid
  bundler: failed to load command: puma (/usr/local/bundle/bin/puma)
  /usr/local/lib/ruby/3.2.0/uri/rfc2396_parser.rb:176:in `split': bad URI(is not URI?): mysql2://user:my_weird^password@mysql:3306/quepid (URI::InvalidURIError)
    from /usr/local/lib/ruby/3.2.0/uri/rfc2396_parser.rb:210:in `parse'
    from /usr/local/bundle/gems/activerecord-6.1.7.2/lib/active_record/database_configurations/connection_url_resolver.rb:26:in `initialize'

Since Rails defers to Ruby's URI class to parse this DATABASE_URL value, Rails or more specifically ActiveRecord would need to rescue the specific URI::InvalidURIError here to avoid leakage and sanitize output before re-raising the exception.

That might not be something Rails maintainers are willing to take on but if @schicks's DATABASE_URL was actually a valid URL, then... folks we might have a Ruby bug on our hands. Although since the exception is coming straight out of Ruby 3.2.0's URI class RFC2369 parser I would be very surprised.

Full Ruby Stacktrace ``` 00:17:05 web.1 | started with pid 7 00:17:06 web.1 | [7] Puma starting in cluster mode... 00:17:06 web.1 | [7] * Puma version: 6.0.2 (ruby 3.2.0-p0) ("Sunflower") 00:17:06 web.1 | [7] * Min threads: 5 00:17:06 web.1 | [7] * Max threads: 5 00:17:06 web.1 | [7] * Environment: development 00:17:06 web.1 | [7] * Master PID: 7 00:17:06 web.1 | [7] * Workers: 2 00:17:06 web.1 | [7] * Restarts: (✔) hot (✖) phased 00:17:06 web.1 | [7] * Preloading application 00:17:08 web.1 | [7] ! Unable to load application: URI::InvalidURIError: bad URI(is not URI?): mysql2://user:my_weird^password@mysql:3306/quepid 00:17:08 web.1 | bundler: failed to load command: puma (/usr/local/bundle/bin/puma) 00:17:08 web.1 | /usr/local/lib/ruby/3.2.0/uri/rfc2396_parser.rb:176:in `split': bad URI(is not URI?): mysql2://user:my_weird^password@mysql:3306/quepid (URI::InvalidURIError) 00:17:08 web.1 | from /usr/local/lib/ruby/3.2.0/uri/rfc2396_parser.rb:210:in `parse' 00:17:08 web.1 | from /usr/local/bundle/gems/activerecord-6.1.7.2/lib/active_record/database_configurations/connection_url_resolver.rb:26:in `initialize' 00:17:08 web.1 | from /usr/local/bundle/gems/activerecord-6.1.7.2/lib/active_record/database_configurations/url_config.rb:48:in `new' 00:17:08 web.1 | from /usr/local/bundle/gems/activerecord-6.1.7.2/lib/active_record/database_configurations/url_config.rb:48:in `build_url_hash' 00:17:08 web.1 | from /usr/local/bundle/gems/activerecord-6.1.7.2/lib/active_record/database_configurations/url_config.rb:38:in `initialize' 00:17:08 web.1 | from /usr/local/bundle/gems/activerecord-6.1.7.2/lib/active_record/database_configurations.rb:263:in `new' 00:17:08 web.1 | from /usr/local/bundle/gems/activerecord-6.1.7.2/lib/active_record/database_configurations.rb:263:in `environment_url_config' 00:17:08 web.1 | from /usr/local/bundle/gems/activerecord-6.1.7.2/lib/active_record/database_configurations.rb:178:in `build_configs' 00:17:08 web.1 | from /usr/local/bundle/gems/activerecord-6.1.7.2/lib/active_record/database_configurations.rb:20:in `initialize' 00:17:08 web.1 | from /usr/local/bundle/gems/activerecord-6.1.7.2/lib/active_record/core.rb:64:in `new' 00:17:08 web.1 | from /usr/local/bundle/gems/activerecord-6.1.7.2/lib/active_record/core.rb:64:in `configurations=' 00:17:08 web.1 | from /usr/local/bundle/gems/activerecord-6.1.7.2/lib/active_record/core.rb:66:in `block in ' 00:17:08 web.1 | from /usr/local/bundle/gems/activesupport-6.1.7.2/lib/active_support/concern.rb:136:in `class_eval' 00:17:08 web.1 | from /usr/local/bundle/gems/activesupport-6.1.7.2/lib/active_support/concern.rb:136:in `append_features' 00:17:08 web.1 | from /usr/local/bundle/gems/activerecord-6.1.7.2/lib/active_record/base.rb:282:in `include' 00:17:08 web.1 | from /usr/local/bundle/gems/activerecord-6.1.7.2/lib/active_record/base.rb:282:in `' 00:17:08 web.1 | from /usr/local/bundle/gems/activerecord-6.1.7.2/lib/active_record/base.rb:265:in `' 00:17:08 web.1 | from /usr/local/bundle/gems/activerecord-6.1.7.2/lib/active_record/base.rb:15:in `
' 00:17:08 web.1 | from /usr/local/bundle/gems/bootsnap-1.15.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:32:in `require' 00:17:08 web.1 | from /usr/local/bundle/gems/bootsnap-1.15.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:32:in `require' 00:17:08 web.1 | from /usr/local/bundle/gems/zeitwerk-2.6.6/lib/zeitwerk/kernel.rb:38:in `require' 00:17:08 web.1 | from /usr/local/bundle/gems/bullet-7.0.7/lib/bullet/active_record61.rb:16:in `enable' 00:17:08 web.1 | from /usr/local/bundle/gems/bullet-7.0.7/lib/bullet.rb:68:in `enable=' 00:17:08 web.1 | from /srv/app/config/environments/development.rb:77:in `block (2 levels) in
' 00:17:08 web.1 | from /usr/local/bundle/gems/activesupport-6.1.7.2/lib/active_support/lazy_load_hooks.rb:68:in `block in execute_hook' 00:17:08 web.1 | from /usr/local/bundle/gems/activesupport-6.1.7.2/lib/active_support/lazy_load_hooks.rb:61:in `with_execution_control' 00:17:08 web.1 | from /usr/local/bundle/gems/activesupport-6.1.7.2/lib/active_support/lazy_load_hooks.rb:66:in `execute_hook' 00:17:08 web.1 | from /usr/local/bundle/gems/activesupport-6.1.7.2/lib/active_support/lazy_load_hooks.rb:52:in `block in run_load_hooks' 00:17:08 web.1 | from /usr/local/bundle/gems/activesupport-6.1.7.2/lib/active_support/lazy_load_hooks.rb:51:in `each' 00:17:08 web.1 | from /usr/local/bundle/gems/activesupport-6.1.7.2/lib/active_support/lazy_load_hooks.rb:51:in `run_load_hooks' 00:17:08 web.1 | from /usr/local/bundle/gems/railties-6.1.7.2/lib/rails/application/finisher.rb:140:in `block in ' 00:17:08 web.1 | from /usr/local/bundle/gems/railties-6.1.7.2/lib/rails/initializable.rb:32:in `instance_exec' 00:17:08 web.1 | from /usr/local/bundle/gems/railties-6.1.7.2/lib/rails/initializable.rb:32:in `run' 00:17:08 web.1 | from /usr/local/bundle/gems/railties-6.1.7.2/lib/rails/initializable.rb:61:in `block in run_initializers' 00:17:08 web.1 | from /usr/local/lib/ruby/3.2.0/tsort.rb:228:in `block in tsort_each' 00:17:08 web.1 | from /usr/local/lib/ruby/3.2.0/tsort.rb:350:in `block (2 levels) in each_strongly_connected_component' 00:17:08 web.1 | from /usr/local/lib/ruby/3.2.0/tsort.rb:431:in `each_strongly_connected_component_from' 00:17:08 web.1 | from /usr/local/lib/ruby/3.2.0/tsort.rb:349:in `block in each_strongly_connected_component' 00:17:08 web.1 | from /usr/local/lib/ruby/3.2.0/tsort.rb:347:in `each' 00:17:08 web.1 | from /usr/local/lib/ruby/3.2.0/tsort.rb:347:in `call' 00:17:08 web.1 | from /usr/local/lib/ruby/3.2.0/tsort.rb:347:in `each_strongly_connected_component' 00:17:08 web.1 | from /usr/local/lib/ruby/3.2.0/tsort.rb:226:in `tsort_each' 00:17:08 web.1 | from /usr/local/lib/ruby/3.2.0/tsort.rb:205:in `tsort_each' 00:17:08 web.1 | from /usr/local/bundle/gems/railties-6.1.7.2/lib/rails/initializable.rb:60:in `run_initializers' 00:17:08 web.1 | from /usr/local/bundle/gems/railties-6.1.7.2/lib/rails/application.rb:391:in `initialize!' 00:17:08 web.1 | from /srv/app/config/environment.rb:7:in `' 00:17:08 web.1 | from config.ru:5:in `require_relative' 00:17:08 web.1 | from config.ru:5:in `block in
' 00:17:08 web.1 | from /usr/local/bundle/gems/rack-2.2.6.2/lib/rack/builder.rb:116:in `eval' 00:17:08 web.1 | from /usr/local/bundle/gems/rack-2.2.6.2/lib/rack/builder.rb:116:in `new_from_string' 00:17:08 web.1 | from /usr/local/bundle/gems/rack-2.2.6.2/lib/rack/builder.rb:105:in `load_file' 00:17:08 web.1 | from /usr/local/bundle/gems/rack-2.2.6.2/lib/rack/builder.rb:66:in `parse_file' 00:17:08 web.1 | from /usr/local/bundle/gems/puma-6.0.2/lib/puma/configuration.rb:364:in `load_rackup' 00:17:08 web.1 | from /usr/local/bundle/gems/puma-6.0.2/lib/puma/configuration.rb:286:in `app' 00:17:08 web.1 | from /usr/local/bundle/gems/puma-6.0.2/lib/puma/runner.rb:158:in `load_and_bind' 00:17:08 web.1 | from /usr/local/bundle/gems/puma-6.0.2/lib/puma/cluster.rb:359:in `run' 00:17:08 web.1 | from /usr/local/bundle/gems/puma-6.0.2/lib/puma/launcher.rb:186:in `run' 00:17:08 web.1 | from /usr/local/bundle/gems/puma-6.0.2/lib/puma/cli.rb:75:in `run' 00:17:08 web.1 | from /usr/local/bundle/gems/puma-6.0.2/bin/puma:10:in `' 00:17:08 web.1 | from /usr/local/bundle/bin/puma:25:in `load' 00:17:08 web.1 | from /usr/local/bundle/bin/puma:25:in `' 00:17:08 web.1 | from /usr/local/bundle/gems/bundler-2.3.18/lib/bundler/cli/exec.rb:58:in `load' 00:17:08 web.1 | from /usr/local/bundle/gems/bundler-2.3.18/lib/bundler/cli/exec.rb:58:in `kernel_load' 00:17:08 web.1 | from /usr/local/bundle/gems/bundler-2.3.18/lib/bundler/cli/exec.rb:23:in `run' 00:17:08 web.1 | from /usr/local/bundle/gems/bundler-2.3.18/lib/bundler/cli.rb:483:in `exec' 00:17:08 web.1 | from /usr/local/bundle/gems/bundler-2.3.18/lib/bundler/vendor/thor/lib/thor/command.rb:27:in `run' 00:17:08 web.1 | from /usr/local/bundle/gems/bundler-2.3.18/lib/bundler/vendor/thor/lib/thor/invocation.rb:127:in `invoke_command' 00:17:08 web.1 | from /usr/local/bundle/gems/bundler-2.3.18/lib/bundler/vendor/thor/lib/thor.rb:392:in `dispatch' 00:17:08 web.1 | from /usr/local/bundle/gems/bundler-2.3.18/lib/bundler/cli.rb:31:in `dispatch' 00:17:08 web.1 | from /usr/local/bundle/gems/bundler-2.3.18/lib/bundler/vendor/thor/lib/thor/base.rb:485:in `start' 00:17:08 web.1 | from /usr/local/bundle/gems/bundler-2.3.18/lib/bundler/cli.rb:25:in `start' 00:17:08 web.1 | from /usr/local/bundle/gems/bundler-2.3.18/exe/bundle:48:in `block in ' 00:17:08 web.1 | from /usr/local/bundle/gems/bundler-2.3.18/lib/bundler/friendly_errors.rb:120:in `with_friendly_errors' 00:17:08 web.1 | from /usr/local/bundle/gems/bundler-2.3.18/exe/bundle:36:in `' 00:17:08 web.1 | from /usr/local/bundle/bin/bundle:25:in `load' 00:17:08 web.1 | from /usr/local/bundle/bin/bundle:25:in `
' 00:17:09 web.1 | exited with code 1 00:17:09 system | sending SIGTERM to all processes ```
rbwrightjr91 commented 1 year ago

That might not be something Rails maintainers are willing to take on but if @schicks's DATABASE_URL was actually a valid URL, then... folks we might have a Ruby bug on our hands.

@olivierlacan Our password does have characters that, when passed directly, result in an invalid URI (notably the ^ character). In other areas of our codebase, we get around this by URI Encoding the password and I'm sure we could do that here as well. However, we still thought it prudent to bring up the issue as it seems totally reasonable that someone would not think to URI Encode the password while configuring this for the first time.

olivierlacan commented 1 year ago

@rbwrightjr91 Yeah, I created a repro repo to suggest this might be a good idea to do within ActiveRecord. In the meantime URI encoding the whole URL or just the password should work.

I'll see what Rails folks think, but from quick research it's a fairly common issue with DB URLs across languages/frameworks.

olivierlacan commented 1 year ago

As a circumvention of this issue, quepid could allow the log level to be set via an environment variable which is a default that was just added to the upcoming Rails 7.1 (not yet released):

# in config/environments/production.rb

config.log_level = ENV.fetch("RAILS_LOG_LEVEL") { "info" }

https://github.com/rails/rails/blob/main/railties/lib/rails/generators/rails/app/templates/config/environments/production.rb.tt#L73-L73

This would allow anyone running quepid via a Docker image to pass RAILS_LOG_LEVEL=warn in order to silence higher log levels like info.

The available log levels are: :debug, :info, :warn, :error, :fatal, and :unknown, corresponding to the log level numbers from 0 up to 5, respectively. To change the default log level, use https://guides.rubyonrails.org/debugging_rails_applications.html#log-levels

schicks commented 1 year ago

So having now tried that change, it does not seem to fix the problem. As far as we can tell this is because the problematic log message is an error thrown from active record in some context that does not respect the rails log level even when it is configured.

olivierlacan commented 1 year ago

That makes a lot of sense, any error monitoring would leak this stuff as well. This makes me think opening a Rails issue to see if ActiveRecord can rescue these exceptions more cleanly is the best solution.

schicks commented 1 year ago

In that context, I think it's pretty clear this is not really a Quepid issue so I'm going to go ahead and close this thread.

epugh commented 1 year ago

Thank you @schicks and @olivierlacan for working through this issue! Seeing you'all workign through this made me feel like we're finally building out a qommunity that mutual supports each other!

I do want to get us to Rails 7 soon, for many reasons, one of which is that security fixes will come to us.