Logging configuration dumps everything to STDOUT for test environment

[partydrone]

The current logging configuration dumps everything—including SQL statements—to STDOUT, and test output is no longer that nice, clean string of dots.

What's the best way to configure the test environment to log to a file in log/test.log again, or clean up test output?

[nickjj]

Hi,

Sorry for the delayed response.

Do you happen to have an example project set up that I can clone to test it against?

[partydrone]

Sorry for taking so long to get back to you. I just started a new project here.

On further investigation, it looks like the issue is tied to ENV["LOG_LEVEL"] in my .env file, so when running rails test, everything is dumped to STDOUT using the "debug" log level.

For example, with a new app, running rails test (actually, it's more like docker-compose app rails test), I get the following output:

   (1.4ms)  SELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC
   (1.6ms)  SELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC
   (0.6ms)  SELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC
   (281.3ms)  DROP DATABASE IF EXISTS "one_up_test"
   (1074.4ms)  CREATE DATABASE "one_up_test" ENCODING = 'utf8'
  SQL (2.0ms)  CREATE EXTENSION IF NOT EXISTS "plpgsql"
   (33.6ms)  CREATE TABLE "schema_migrations" ("version" character varying NOT NULL PRIMARY KEY)
   (1.9ms)  SELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC
   (2.0ms)  INSERT INTO "schema_migrations" (version) VALUES (0)
   (12.4ms)  CREATE TABLE "ar_internal_metadata" ("key" character varying NOT NULL PRIMARY KEY, "value" character varying, "created_at" timestamp NOT NULL, "updated_at" timestamp NOT NULL)
  ActiveRecord::InternalMetadata Load (2.0ms)  SELECT  "ar_internal_metadata".* FROM "ar_internal_metadata" WHERE "ar_internal_metadata"."key" = $1 LIMIT $2  [["key", "environment"], ["LIMIT", 1]]
   (0.3ms)  BEGIN
  SQL (3.6ms)  INSERT INTO "ar_internal_metadata" ("key", "value", "created_at", "updated_at") VALUES ($1, $2, $3, $4) RETURNING "key"  [["key", "environment"], ["value", "test"], ["created_at", "2017-07-23 17:38:47.691261"], ["updated_at", "2017-07-23 17:38:47.691261"]]
   (0.4ms)  COMMIT
  ActiveRecord::InternalMetadata Load (0.7ms)  SELECT  "ar_internal_metadata".* FROM "ar_internal_metadata" WHERE "ar_internal_metadata"."key" = $1 LIMIT $2  [["key", "environment"], ["LIMIT", 1]]
   (0.2ms)  BEGIN
   (0.2ms)  COMMIT
   (1.6ms)  SELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC

# Running tests with run options --seed 20590:

   (0.3ms)  BEGIN
---------------------------------------------
PagesController: test_0001_gets the home page
---------------------------------------------
[www] [d1ee5849-4473-4dce-baf2-f9ad17219d2a] Started GET "/" for 127.0.0.1 at 2017-07-23 17:38:48 +0000
[www] [d1ee5849-4473-4dce-baf2-f9ad17219d2a] Processing by PagesController#home as HTML
[www] [d1ee5849-4473-4dce-baf2-f9ad17219d2a]   Rendering pages/home.html.erb within layouts/application
[www] [d1ee5849-4473-4dce-baf2-f9ad17219d2a]   Rendered pages/home.html.erb within layouts/application (5.7ms)
[www] [d1ee5849-4473-4dce-baf2-f9ad17219d2a] Completed 200 OK in 220ms (Views: 206.8ms | ActiveRecord: 0.0ms)
   (0.3ms)  ROLLBACK
.

Finished tests in 0.539536s, 1.8534 tests/s, 1.8534 assertions/s.

1 tests, 1 assertions, 0 failures, 0 errors, 0 skips

After changing the log level in .env to warn and running the command again, I get:

# Running tests with run options --seed 6716:

.

Finished tests in 0.423461s, 2.3615 tests/s, 2.3615 assertions/s.

1 tests, 1 assertions, 0 failures, 0 errors, 0 skips

So it looks like setting the log level in config/environments/test.rb to something less verbose resolves the issue:

# config/environments/test/rb
Rails.application.configure do
  # …
  config.log_level = :warn
end

I did find it interesting that you put a lot of configuration in config/application.rb rather than in separate files in config/initializers as the comments suggest. I wonder why that is. Does the configuration not work as expected if you do it that way?

[nickjj]

@partydrone, a lot of the configuration is in config/application.rb because that allows them to be applied to all environments without having to duplicate them in each individual environment config.

In your case, putting a separate config option in test.rb overrides what's in application.rb and is considered a reasonable and standard way to fix the issue.

I'm going to keep this issue open because your proposed fix is what will make its way into the next update. Thanks for that!

[nickjj]

I just fixed this locally and am preparing a Rails 5.2 release soon.

Closing this as it's been addressed.