loading...

Tweaking Logger Outputs on the Fly

noelworden profile image Noel Worden ・4 min read

This Week I Learned (15 Part Series)

1) Beginning of a Blog Series 2) Accessing localhost within a Docker Image 3 ... 13 3) Identifying and Removing Hidden Characters 4) Getting Granular with Git Diff 5) Tweaking Logger Outputs on the Fly 6) Keeping Your Hands on the Keyboard: A Few Bash and Git Shortcuts 7) Breaking Down Elixir's `with` Expression 8) How To Write A Custom Elixir Schema Validation 9) The Handful of Commands I Use When Interactive Rebasing with Vim 10) Got 5 Minutes to Spare? Why Not Set up a Custom Commit Message Template? 11) Improving Your Commit Message with the 50/72 Rule 12) Synchronously Looping Over Two Collections in Elixir 13) How to Utilize Enum.any?, with a Refactoring Twist! 14) A Rabbit Hole of Decimal Formatting 15) More Custom Validation Work: Manipulating a Keyword List To and From a Map

The best thing I learned this week isn't exactly a mind bender, but it saves some clicks, and is worth writing about. I learned that you can pipe in custom logger output options right into an execution script.

I've been working on an Elixir/Phoenix project, and since the release of the production environment we have had to take steps to ensure data insertions are executable across multiple databases. The basic components are a CSV containing the data, a file containing the insertion functions, and a script to execute the process, which looks like this:

docker-compose exec web elixir -S mix run -e 'Finance.Manipulations.TestDataManipulation.run()'       

The logger output wasn't much of a concern, until we started running these scripts on our staging database and we needed to be absolute sure the data was inserting as expected. The process of inserting data to staging was:

  • Dry run the script locally
  • Save the logger output to a file
  • Dry run the script on staging
  • Save that logger output to a file
  • Diff the two files

While test running this the first time I realized that our local dev environment was printing out a much more detailed log than staging, which created an issue when attempting to diff the two files.

The local logging:

[debug] QUERY OK db=4.8ms queue=40.1ms idle=0.0ms
begin []
[debug] QUERY OK source="agents" db=2.9ms
SELECT a0."id", a0."name" FROM "agents" AS a0 WHERE (a0."legacy_id" = $1) [115]
[debug] QUERY OK source="form_as" db=8.1ms
SELECT s0."id", s0."vendors", s0."revenue_share", s0."legacy_id", s0."inserted_at", s0."updated_at" FROM "form_as" AS s0 WHERE (((s0."vendors" = 'the_vendor') AND (s0."legacy_id" = $1)) AND (s0."revenue_share" = $2)) [16, #Decimal<0.3>]
[debug] QUERY OK db=11.5ms
INSERT INTO "agents" ("legacy_id","name","inserted_at","updated_at") VALUES ($1,$2,$3,$4) RETURNING "id" [115, "PERSON ONE", ~U[2020-04-18 00:58:13Z], ~U[2020-04-18 00:58:13Z]]
[debug] QUERY OK db=6.5ms
INSERT INTO "form_as" ("legacy_id","revenue_share","vendors","inserted_at","updated_at") VALUES ($1,$2,$3,$4,$5) RETURNING "id" [16, #Decimal<0.3>, "the_vendor", ~U[2020-04-18 00:58:13Z], ~U[2020-04-18 00:58:13Z]]
[debug] QUERY OK db=7.0ms
INSERT INTO "merchant_accounts" ("agent_id","mid","form_a_id","vendors","inserted_at","updated_at") VALUES ($1,$2,$3,$4,$5,$6) RETURNING "id" [1, "899001426531", 1, "the_vendor", ~U[2020-04-18 00:58:13Z], ~U[2020-04-18 00:58:13Z]]
[info] Inserted data for %{name: "PERSON ONE", a_la_row_id: "115"}: %{agent: 1, merchant_account: 1, form_a: 1}
[debug] QUERY OK source="agents" db=0.4ms decode=0.1ms
SELECT a0."id", a0."name", a0."phone_number", a0."legacy_id", a0."inserted_at", a0."updated_at" FROM "agents" AS a0 WHERE (a0."legacy_id" = $1) [123]
[debug] QUERY OK source="form_as" db=0.3ms
SELECT s0."id", s0."vendors", s0."revenue_share", s0."legacy_id", s0."inserted_at", s0."updated_at" FROM "form_as" AS s0 WHERE (((s0."vendors" = 'the_vendor') AND (s0."legacy_id" = $1)) AND (s0."revenue_share" = $2)) [250, #Decimal<0.25>]
[debug] QUERY OK db=0.4ms
INSERT INTO "agents" ("legacy_id","name","inserted_at","updated_at") VALUES ($1,$2,$3,$4) RETURNING "id" [123, "ASPS", ~U[2020-04-18 00:58:13Z], ~U[2020-04-18 00:58:13Z]]
[debug] QUERY OK db=0.5ms
INSERT INTO "form_as" ("legacy_id","revenue_share","vendors","inserted_at","updated_at") VALUES ($1,$2,$3,$4,$5) RETURNING "id" [250, #Decimal<0.25>, "the_vendor", ~U[2020-04-18 00:58:13Z], ~U[2020-04-18 00:58:13Z]]
[debug] QUERY OK db=3.3ms
INSERT INTO "merchant_accounts" ("agent_id","mid","form_a_id","vendors","inserted_at","updated_at") VALUES ($1,$2,$3,$4,$5,$6) RETURNING "id" [2, "816553010306215", 2, "the_vendor", ~U[2020-04-18 00:58:13Z], ~U[2020-04-18 00:58:13Z]]
[info] Inserted data for %{name: "PERSON TWI", a_la_row_id: "123"}: %{agent: 1, merchant_account: 1, form_a: 1}

And the logging from staging:

[info] Inserted data for %{name: "PERSON ONE", legacy_id: "115"}
[info] Inserted data for %{name: "PERSON TWO", legacy_id: "123"}
[info] Inserted data for %{name: "PERSON THREE", legacy_id: "73"}
[info] Inserted data for %{name: "PERSON FOUR", legacy_id: "17"}
[info] Inserted data for %{name: "PERSON FIVE", legacy_id: "117"}
[info] Inserted data for %{name: "PERSON SIX", legacy_id: "84"}
[info] Inserted data for %{name: "PERSON SEVEN", legacy_id: "34"}
[info] Inserted data for %{name: "PERSON EIGHT", legacy_id: "69"}
[info] Inserted data for %{name: "PERSON NINE", legacy_id: "16"}
[info] Inserted data for %{name: "PERSON TEN", legacy_id: "114"}
[info] Inserted data for %{name: "PERSON ELEVEN", legacy_id: "78"}
[info] Inserted data for %{name: "PERSON TWELVE", legacy_id: "134"}
[info] Inserted data for %{name: "PERSON THIRTEEN", legacy_id: "113"}
[info] Inserted data for %{name: "PERSON FOURTEEN", legacy_id: "152"}
[info] Inserted data for %{name: "PERSON FIFTEEN", legacy_id: "138"}

The long way to manually sync the local logging output is go to the config > dev.exs file, and modify this line:

config :logger, :console, format: "[$level] $message\n"

To match the logging output of staging:

config :logger, level: :info

When finished running those scripts the changes would need to be reverted.

Its not a terrible workflow, but piping Logger.configure(level: :info); directly into the execution script is far more efficient:

docker-compose exec web elixir -S mix run -e 'Logger.configure(level: :info); Finance.Manipulations.TestDataManipulation.run()'       

With this simple addition to the script the logging detail levels match, and theres no need to temporary alter the config files.


This post is part of an ongoing This Week I Learned series. I welcome any critique, feedback, or suggestions in the comments.

This Week I Learned (15 Part Series)

1) Beginning of a Blog Series 2) Accessing localhost within a Docker Image 3 ... 13 3) Identifying and Removing Hidden Characters 4) Getting Granular with Git Diff 5) Tweaking Logger Outputs on the Fly 6) Keeping Your Hands on the Keyboard: A Few Bash and Git Shortcuts 7) Breaking Down Elixir's `with` Expression 8) How To Write A Custom Elixir Schema Validation 9) The Handful of Commands I Use When Interactive Rebasing with Vim 10) Got 5 Minutes to Spare? Why Not Set up a Custom Commit Message Template? 11) Improving Your Commit Message with the 50/72 Rule 12) Synchronously Looping Over Two Collections in Elixir 13) How to Utilize Enum.any?, with a Refactoring Twist! 14) A Rabbit Hole of Decimal Formatting 15) More Custom Validation Work: Manipulating a Keyword List To and From a Map

Posted on Jun 1 by:

noelworden profile

Noel Worden

@noelworden

Software Engineer in Boulder, CO - Writing code and getting strategically lost in the mountains

Discussion

markdown guide