Is there a way to make log messages more readable?

Phoenix Forum Questions / Help
,
1

One of the things I struggle with the most is reading complex log messages, which Elixir spits out on the terminal as “walls of text”. Here is an example MatchError output:

15) test delete deletes the invoice (MyAppWeb.InvoiceControllerTest)
     test/myapp_web/controllers/invoices/invoice_controller_test.exs:403
     ** (MatchError) no match of right hand side value: {:error, :invoice_history, #Ecto.Changeset<action: :insert, changes: %{event_description: "Invoice issued.", event_type: "Issued", invoice_id: 1019}, errors: [details: {"is invalid", [type: :string, validation: :cast]}], data: #MyApp.Invoices.InvoiceHistory<>, valid?: false>, %{customer_snapshot: %MyApp.Snapshots.CustomerSnapshot{__meta__: #Ecto.Schema.Metadata<:loaded, "tenant_6030dc37_e0d2_4ff1_91dd_38d37a028682", "customer_snapshots">, company: nil, customer: #Ecto.Association.NotLoaded<association :customer is not loaded>, customer_id: 1022, email: "13373d4e-bed8-4dd9-a5c1-f2fe91b5d6dd", estimate: #Ecto.Association.NotLoaded<association :estimate is not loaded>, estimate_id: nil, first_name: "some first_name", id: 22, inserted_at: #DateTime<2019-06-26 21:40:22.172000Z>, invoice: #Ecto.Association.NotLoaded<association :invoice is not loaded>, invoice_id: 1019, labels: #Ecto.Association.NotLoaded<association :labels is not loaded>, last_name: "some last_name", parent_entity_deleted_at: nil, parent_entity_deleted_by: nil, phone: 42, physical_address: "some address", updated_at: #DateTime<2019-06-26 21:40:22.172000Z>}, invoice: %MyApp.Invoices.Invoice{customer_snapshot: #Ecto.Association.NotLoaded<association :customer_snapshot is not loaded>, discount_percentage: 0.0, amount_paid: 0.0, due_date: ~D[2010-04-17], organization: #Ecto.Association.NotLoaded<association :organization is not loaded>, tax_rate: 0.0, inserted_at: #DateTime<2019-06-26 21:40:22.172000Z>, action_items: #Ecto.Association.NotLoaded<association :action_items is not loaded>, is_archived: false, allow_partial_payments: false, payment_term_snapshot: #Ecto.Association.NotLoaded<association :payment_term_snapshot is not loaded>, archived_by: nil, invoice_histories: #Ecto.Association.NotLoaded<association :invoice_histories is not loaded>, estimate_id: nil, notes: nil, tax_amount: 0.0, bank_payments_enabled: false, discount_type: "none", uuid: "2efb61a3-858d-450f-96bc-89a51041110c", organization_id: 1, id: 1019, visibility_level: 3, stripe_charge_id: nil, discount_amount: 0.0, user_snapshot: #Ecto.Association.NotLoaded<association :user_snapshot is not loaded>, project_id: nil, po_number: "some po_number", invoice_date: #DateTime<2019-06-26 21:40:22.169000Z>, payments: #Ecto.Association.NotLoaded<association :payments is not loaded>, project: #Ecto.Association.NotLoaded<association :project is not loaded>, cc_payments_enabled: false, status: "some status", invoice_description: nil, updated_at: #DateTime<2019-06-26 21:40:22.172000Z>, subtotal: 0.0, estimate: #Ecto.Association.NotLoaded<association :estimate is not loaded>, invoice_lines: #Ecto.Association.NotLoaded<association :invoice_lines is not loaded>, __meta__: #Ecto.Schema.Metadata<:loaded, "tenant_6030dc37_e0d2_4ff1_91dd_38d37a028682", "invoices_invoices">, total: #Decimal<120.5>, archive_date: nil}, invoice_blank_line: %MyApp.Invoices.InvoiceLine{__meta__: #Ecto.Schema.Metadata<:loaded, "tenant_6030dc37_e0d2_4ff1_91dd_38d37a028682", "invoices_invoice_lines">, data: #Ecto.Association.NotLoaded<association :data is not loaded>, id: 20, inserted_at: #DateTime<2019-06-26 21:40:22.172000Z>, invoice: #Ecto.Association.NotLoaded<association :invoice is not loaded>, invoice_id: 1019, updated_at: #DateTime<2019-06-26 21:40:22.172000Z>}, invoice_public: %MyApp.Invoices.Public.Invoice{__meta__: #Ecto.Schema.Metadata<:loaded, "invoices">, id: 23, inserted_at: #DateTime<2019-06-26 21:40:22.172000Z>, tenant: "6030dc37_e0d2_4ff1_91dd_38d37a028682", updated_at: #DateTime<2019-06-26 21:40:22.172000Z>, uuid: "2efb61a3-858d-450f-96bc-89a51041110c"}, line_data: "", payment_term_snapshot: %MyApp.Snapshots.PaymentTermSnapshot{__meta__: #Ecto.Schema.Metadata<:loaded, "tenant_6030dc37_e0d2_4ff1_91dd_38d37a028682", "payment_term_snapshots">, days: nil, description: "Test Description", id: 20, inserted_at: #DateTime<2019-06-26 21:40:22.172000Z>, invoice: #Ecto.Association.NotLoaded<association :invoice is not loaded>, invoice_id: 1019, name: "Test Payment Term", parent_entity_deleted_at: nil, parent_entity_deleted_by: nil, payment_term: #Ecto.Association.NotLoaded<association :payment_term is not loaded>, payment_term_id: 24, updated_at: #DateTime<2019-06-26 21:40:22.172000Z>}, user_snapshot: %MyApp.Snapshots.UserSnapshot{__meta__: #Ecto.Schema.Metadata<:loaded, "tenant_6030dc37_e0d2_4ff1_91dd_38d37a028682", "user_snapshots">, avatar_url: nil, email: "test@test.com", estimate: #Ecto.Association.NotLoaded<association :estimate is not loaded>, estimate_document: #Ecto.Association.NotLoaded<association :estimate_document is not loaded>, estimate_document_id: nil, estimate_id: nil, first_name: "test", id: 22, inserted_at: #DateTime<2019-06-26 21:40:22.172000Z>, invoice: #Ecto.Association.NotLoaded<association :invoice is not loaded>, invoice_id: 1019, job_title: nil, last_name: "user", organization: #Ecto.Association.NotLoaded<association :organization is not loaded>, organization_id: 1, parent_entity_deleted_at: nil, parent_entity_deleted_by: nil, phone: nil, updated_at: #DateTime<2019-06-26 21:40:22.172000Z>, user: #Ecto.Association.NotLoaded<association :user is not loaded>, user_id: 1000}}}
     code: {:ok, %{invoice: invoice}} = Invoices.create_invoice_from_scratch(user.organization.slug, user.id, create_attrs)
     stacktrace:
       test/myapp_web/controllers/invoices/invoice_controller_test.exs:410: (test)

When I get errors like this, I always shake my head in frustration because trying to figure out what the issue is can take several minutes of carefully reading through each line of text. Lately I’ve been just copy-pasting them into a text editor and doing Ctrl-F for certain keywords like “required” or “valid: false” in the hopes that it will highlight the part of the wall-of-text that has the issue. But that’s just for when the error contains a Changeset. It’s also not a scalable approach.

Is there a way to have the error message “pretty-printed” so that it is easier to read? Specifically, for maps and structs I’d like them to use new lines and indentations, such as when you use IO.inspect on an Ecto Changeset:

#Ecto.Changeset<
  action: :insert,
  changes: %{},
  errors: [
    name: {"can't be blank", [validation: :required]},
    tax_rate: {"can't be blank", [validation: :required]}
  ],
  data: #MyApp.Organizations.Tax<>,
  valid?: false
>

Color-coding of syntax would be awesome too, just like how it is color-coded above.

For what it’s worth, I’m on Windows, my terminal client is Cmder and my editor is Visual Studio Code.

2

If MatchError happens in test, then you can use assert pattern = func() to make result more readable. If this happens somewhere within your application, then you need to fix your code to accept invalid matches and handle them gracefully.

1 Like