navinpeiris/logster

Easily parsable single line, plain text and JSON logger for Plug and Phoenix applications

logster's Issues

JSON Formatter

I'm looking at logging to a service like Loggly, which does best with a JSON formatted log.

I love the work you've done, and wonder if you'd be open to a PR allowing different formatters.

I'm thinking it would be best to accumulate the data in a KW list, then format that KW list, either as JSON or as a set of key=val pairs.

Of course, if you don't want a JSON library as a dep of this library (which I totally understand), the PR would just allow for another package to come along and format the log line.

How to remove Phoenix default logging

The logster README shows how to log new messages with logster, but it doesn't show how to remove the Phoenix generated log statements. To me, the README implies that you can remove logging by removing a plug Plug.Logger line, but that line doesn't exist in a new Phoenix generated app.

I found this Phoenix issue that details how to remove the Phoenix generated log statements, phoenixframework/phoenix#3483 (comment)

I used this technique in my project to keep Phoenix from generating redundant messages with logster. Added the following lines to m Application.ex file in my Phoenix project.

    # Disable Phoenix logging, using Logster instead
    :ok = :telemetry.detach({Phoenix.Logger, [:phoenix, :endpoint, :start]})
    :ok = :telemetry.detach({Phoenix.Logger, [:phoenix, :endpoint, :stop]})

Not sure if you want to update the README or not, but I thought I'd mention it in case it saves someone else some time.

Logster raises for params with %

Got some errors today because something added params with '%', like /?v=%85

A quick test verified that

 test "should not fail" do
    {_conn, message} = conn(:get, "/?v=%85") |> call
    assert is_binary(message)
 end

=>

  1) test should not fail (Logster.Plugs.LoggerTest)
     test/logster/plugs/logger_test.exs:157
     ** (Poison.EncodeError) unable to encode value: <<133>>
     stacktrace:
       lib/poison/encoder.ex:154: Poison.Encoder.BitString.chunk_size/3
       lib/poison/encoder.ex:122: Poison.Encoder.BitString.escape/2
       lib/poison/encoder.ex:84: Poison.Encoder.BitString.encode/2
       lib/poison/encoder.ex:213: anonymous fn/4 in Poison.Encoder.Map.encode/3
       lib/poison/encoder.ex:214: Poison.Encoder.Map."-encode/3-lists^foldl/2-0-"/3
       lib/poison/encoder.ex:214: Poison.Encoder.Map.encode/3
       lib/poison.ex:41: Poison.encode!/2
       (logster) lib/logster/string_formatter.ex:10: Logster.StringFormatter.format_field/1
       (elixir) lib/enum.ex:1184: Enum."-map/2-lists^map/1-0-"/2
       (elixir) lib/enum.ex:1184: Enum."-map/2-lists^map/1-0-"/2
       (logster) lib/logster/string_formatter.ex:5: Logster.StringFormatter.format/1
       (logger) lib/logger.ex:611: Logger.truncate/2
       (logger) lib/logger.ex:486: Logger.bare_log/3
       (logster) lib/logster/plugs/logger.ex:36: anonymous fn/3 in Logster.Plugs.Logger.call/2
       (elixir) lib/enum.ex:1623: Enum."-reduce/3-lists^foldl/2-0-"/3
       lib/plug/conn.ex:904: Plug.Conn.run_before_send/2
       lib/plug/conn.ex:355: Plug.Conn.send_resp/1
       test/logster/plugs/logger_test.exs:8: Logster.Plugs.LoggerTest.MyPlug.plug_builder_call/2
       test/logster/plugs/logger_test.exs:90: anonymous fn/1 in Logster.Plugs.LoggerTest.capture_log/1
       (ex_unit) lib/ex_unit/capture_io.ex:146: ExUnit.CaptureIO.do_capture_io/2

Metadata Duplication

Logster copies the Logger.metadata into its log message.
However, the standard for logging metadata through a backend is to configure that backend's metadata option, specifying which keys should be printed.
This means that with a correctly configured backend, like

config :logger, :console,
  format: "[$level] $levelpad $message $metadata",
  metadata: [:request_id, :trace_id, :span_id]

logs will be produced that have request_id, trace_id, and span_id logged twice: once in the message itself via Logster, and then again via the backend.

Example

[info]   state=set duration=... status=200 
params={...} path=... method=GET format=json-api controller=... action=show
span_id=1691184670686183571 trace_id=2439927720751528365 request_id=FZX--3x64qa8bTUAAFfx
request_id=FZX--3x64qa8bTUAAFfx trace_id=2439927720751528365 span_id=1691184670686183571 

I think the easiest fix for this would be to revert the work in #6 and update the readme or changelog with a small guide on how to configure a backend to include metadata (removing the responsibility from Logster)

Exception for Plug.Upload

This exception occurs when I try to upload something

Server: localhost:4000 (http)
Request: POST /admin/uploads
** (exit) an exception was raised:
    ** (Protocol.UndefinedError) protocol Enumerable not implemented for %Plug.Upload{content_type: "image/png", filename: "Bildschirmfoto 2016-04-06 um 10.14.12.png", path: "/tmp/plug-1459/multipart-930459-149247-1"}
        (elixir) lib/enum.ex:1: Enumerable.impl_for!/1
        (elixir) lib/enum.ex:116: Enumerable.reduce/3
        (elixir) lib/enum.ex:1477: Enum.reduce/3
        (elixir) lib/enum.ex:1025: Enum.into/4
        (logster) lib/logster/plugs/logger.ex:68: anonymous fn/1 in Logster.Plugs.Logger.filter_params/1
        (elixir) lib/enum.ex:1019: anonymous fn/4 in Enum.into/3
        (stdlib) lists.erl:1262: :lists.foldl/3
        (elixir) lib/enum.ex:1025: Enum.into/4

Replacing Phoenix Live View logging

I recently set up Logster (v2.0.0-rc1) to replace Phoenix logs, and it's working well. However, Phoenix Live View is still sending multi-line logs.

Example (I haven't made many changes from the phoenix app, and this is just loading /):

[info] state=sent method=GET path=/ controller=MyAppWeb.PageController action=home params={} status=200 duration=1.744
[info] action=connect state=ok socket=Phoenix.LiveView.Socket duration=0.012 transport=websocket serializer=Phoenix.Socket.V2.JSONSerializer params={"_csrf_token":"REDACTED","vsn":"2.0.0"}
[debug] MOUNT Phoenix.LiveDashboard.PageLive
  Parameters: %{"page" => "home"}
  Session: %{"_csrf_token" => "REDACTED", "allow_destructive_actions" => false, "csp_nonces" => %{script: nil, style: nil, img: nil}, "pages" => [home: {Phoenix.LiveDashboard.HomePage, %{env_keys: nil, home_app: {"Dashboard", :phoenix_live_dashboard}}}, os_mon: {Phoenix.LiveDashboard.OSMonPage, %{}}, memory_allocators: {Phoenix.LiveDashboard.MemoryAllocatorsPage, %{}}, metrics: {Phoenix.LiveDashboard.MetricsPage, %{metrics: {MyAppWeb.Telemetry, :metrics}, metrics_history: nil}}, request_logger: {Phoenix.LiveDashboard.RequestLoggerPage, %{request_logger: {"request_logger", "request_logger"}, cookie_domain: nil}}, applications: {Phoenix.LiveDashboard.ApplicationsPage, %{}}, processes: {Phoenix.LiveDashboard.ProcessesPage, %{}}, ports: {Phoenix.LiveDashboard.PortsPage, %{}}, sockets: {Phoenix.LiveDashboard.SocketsPage, %{}}, ets: {Phoenix.LiveDashboard.EtsPage, %{}}, ecto_stats: {Phoenix.LiveDashboard.EctoStatsPage, %{repos: :auto_discover, ecto_options: [ecto_psql_extras_options: [], ecto_mysql_extras_options: [], ecto_sqlite3_extras_options: []]}}], "requirements" => [application: :os_mon]}
[debug] Replied in 20ms
[debug] HANDLE PARAMS in Phoenix.LiveDashboard.PageLive
  Parameters: %{"page" => "home"}
[debug] Replied in 76µs
[debug] HANDLE EVENT "select_refresh" in Phoenix.LiveDashboard.PageLive
  Parameters: %{"_target" => ["refresh"], "refresh" => "15"}
[debug] Replied in 73µs

I see that Logster.attach_phoenix_logger() works by listening to Phoenix telemetry, and Live View also sends telemetry.

Perhaps Logster.attach_phoenix_logger() should also listen to live view events, or there should be another Logster.attach_phoenix_live_view_logger() function.

config :phoenix_live_view, logger: false works to quiet the default Live View logging. For now I'll just do that because they're just debug messages.

Consider using monotonic time

Thanks so much for taking the time and building this! You made my log-tailing day :)

Would you consider switching from :os.timestamp to :erlang.monotonic_time? See elixir-plug/plug#373 for the equivalent change in Plug.