Repository: newrelic/elixir_agent (elixir)

Issue:
[Bug/Request] Change or clearly communicate risks with default logging behaviour
First of all I just wanted to say thank you for creating and maintaining this package. In our testing so far it's worked beautifully and manual instrumentation APIs are very neat and handy!

Onto the bug/request!

**Describe the bug**
- Elixir 1.9 OTP 23
- Install new_relic_agent version 1.12.7
- Setup barebones config in `releases.exs`
```
config :new_relic_agent,
  app_name: System.get_env("NEW_RELIC_APP_NAME"),
  license_key: System.get_env("NEW_RELIC_API_KEY")
```
- Deploy and run application, integration works perfectly 👍 
- After a couple of weeks the application dies with an erlang/BEAM exception, something about being out of memory (sorry we didn't capture the original error)
- Upon investigating the server we found the log file (`/tmp/new_relic.log`) grows infinitely? big, or at least consumed all the remaining HDD space on the server (~ 10GB)
- Nothing in the README mentions that this might happen, and it wasn't immediately apparent in the hexdocs (although it's kinda implied behaviour in [the logger](https://hexdocs.pm/new_relic_agent/NewRelic.Config.html#logger/0))

I'm not 100% sure if this is intentional behaviour or if we've just stumbled upon some sort of logging bug?

If it is intentional, then in my opinion I think the default behaviour is risky as it has the potential to crash production systems. Personally I would prefer making the risks clear in the documentation somewhere, or even changing the default logging behaviour.

**Possible resolutions**
I fully understand some of these might be tricky as they could be a breaking change, and as I'm not familiar with the internals of new relic or the agent I could be proposing something that isn't feasible.

- Find and fix the logging bug (if that's what this is?)
- Update the README and/or hexdocs to make it clear that the default logging behaviour is risky in production
- Limit the size of the log file (rolling log?) and have a "reasonable" default size
- Change the default logging mechanism
- Add compile/run time warnings when logging configuration could result in large log files

I'm more than happy to get my hands dirty and submit a PR if there's a preferred way to tackle this.

Pull request:
Use Elixir Logger as the default agent logger
This PR sets the default Agent logging behavior to use the Elixir `Logger`, instead of the current behavior of writing directly to `tmp/new_relic.log`

This could be considered a breaking change. It doesn't change the agent's behavior, but obviously changes where logs go, which is something folks probably care about.

Closes #377 

Patch:
diff --git a/.github/workflows/elixir.yml b/.github/workflows/elixir.yml
index b8c996c..1ff868d 100644
--- a/.github/workflows/elixir.yml
+++ b/.github/workflows/elixir.yml
@@ -17,18 +17,16 @@ jobs:
     strategy:
       matrix:
         include:
-          - elixir: '1.15'
+          - elixir: '1.18'
+            otp: '27'
+          - elixir: '1.17'
+            otp: '27'
+          - elixir: '1.16'
             otp: '26'
           - elixir: '1.15'
-            otp: '25'
-          - elixir: '1.14'
             otp: '26'
-          - elixir: '1.13'
+          - elixir: '1.14'
             otp: '25'
-          - elixir: '1.12'
-            otp: '24'
-          - elixir: '1.11'
-            otp: '23'
 
     steps:
     - name: Checkout
@@ -84,14 +82,14 @@ jobs:
     strategy:
       matrix:
         include:
-          - elixir: '1.15'
+          - elixir: '1.18'
+            otp: '27'
+          - elixir: '1.17'
+            otp: '27'
+          - elixir: '1.16'
             otp: '26'
-          - elixir: '1.14'
+          - elixir: '1.15'
             otp: '26'
-          - elixir: '1.13'
-            otp: '25'
-          - elixir: '1.12'
-            otp: '24'
 
     defaults:
       run:
diff --git a/lib/new_relic/config.ex b/lib/new_relic/config.ex
index 1819619..a60e57a 100644
--- a/lib/new_relic/config.ex
+++ b/lib/new_relic/config.ex
@@ -40,11 +40,12 @@ defmodule NewRelic.Config do
   This controls how the Agent logs it's own behavior, and doesn't impact your
   applications own logging at all.
 
-  Defaults to the File `"tmp/new_relic.log"`.
+  Defaults to using `Logger`.
 
   Options:
+  - `"Logger"` Send Agent logs to Elixir's `Logger`
+  - `"tmp"` Write to `tmp/new_relic.log`
   - `"stdout"` Write directly to Standard Out
-  - `"Logger"` Send Agent logs to Elixir's Logger
   - `"file_name.log"` Write to a chosen file
 
   Agent logging can be configured in two ways:
@@ -96,6 +97,27 @@ defmodule NewRelic.Config do
   def labels,
     do: get(:labels)
 
+  @doc """
+  An optional list of paths that will be used to ignore Web Transactions.
+
+  Individual items can be Strings or Regexes.
+
+  Common use cases include:
+  * Ignore health checks: `"/health"`
+  * Ignore Phoenix longpoll http requests: `"/live/longpoll"`
+
+  Example:
+  ```
+  config :new_relic_agent,
+    ignore_paths: [
+      "/health",
+      ~r/longpoll/
+    ]
+  ```
+  """
+  def ignore_paths,
+    do: get(:ignore_paths)
+
   @doc """
   Some Agent features can be toggled via configuration.
 
@@ -115,6 +137,8 @@ defmodule NewRelic.Config do
 
   * `:plug_instrumentation_enabled` (default `true`)
     * Controls all Plug instrumentation
+  * `:distributed_tracing` (default `true`)
+    * Controls Distributed Tracking
   * `:ecto_instrumentation_enabled` (default `true`)
     * Controls all Ecto instrumentation
   * `:redix_instrumentation_enabled` (default `true`)
@@ -139,6 +163,10 @@ defmodule NewRelic.Config do
     get(:features, :db_query_collection)
   end
 
+  def feature?(:distributed_tracing) do
+    get(:features, :distributed_tracing)
+  end
+
   def feature?(:plug_instrumentation) do
     get(:features, :plug_instrumentation)
   end
diff --git a/lib/new_relic/distributed_trace.ex b/lib/new_relic/distributed_trace.ex
index a80f91a..8a2cb0b 100644
--- a/lib/new_relic/distributed_trace.ex
+++ b/lib/new_relic/distributed_trace.ex
@@ -9,9 +9,20 @@ defmodule NewRelic.DistributedTrace do
   alias NewRelic.Harvest.Collector.AgentRun
   alias NewRelic.Transaction
 
+  def start(type, headers \\ %{})
+
   def start(:http, headers) do
-    determine_context(:http, headers)
-    |> track_transaction(transport_type: "HTTP")
+    if NewRelic.Config.feature?(:distributed_tracing) do
+      determine_context(:http, headers)
+      |> track_transaction(transport_type: "HTTP")
+    end
+  end
+
+  def start(:other, _) do
+    if NewRelic.Config.feature?(:distributed_tracing) do
+      generate_new_context()
+      |> track_transaction(transport_type: "Other")
+    end
   end
 
   defp determine_context(:http, headers) do
diff --git a/lib/new_relic/harvest/harvest_cycle.ex b/lib/new_relic/harvest/harvest_cycle.ex
index d90a589..a27818d 100644
--- a/lib/new_relic/harvest/harvest_cycle.ex
+++ b/lib/new_relic/harvest/harvest_cycle.ex
@@ -140,7 +140,10 @@ defmodule NewRelic.Harvest.HarvestCycle do
 
   defp stop_harvest_cycle(timer), do: timer && Process.cancel_timer(timer)
 
-  defp trigger_harvest_cycle(%{lookup_module: lookup_module, harvest_cycle_key: harvest_cycle_key}) do
+  defp trigger_harvest_cycle(%{
+         lookup_module: lookup_module,
+         harvest_cycle_key: harvest_cycle_key
+       }) do
     harvest_cycle = lookup_module.lookup(harvest_cycle_key) || 60_000
     Process.send_after(self(), :harvest_cycle, harvest_cycle)
   end
diff --git a/lib/new_relic/init.ex b/lib/new_relic/init.ex
index 81882b8..6f1a618 100644
--- a/lib/new_relic/init.ex
+++ b/lib/new_relic/init.ex
@@ -39,6 +39,7 @@ defmodule NewRelic.Init do
       region_prefix: region_prefix,
       automatic_attributes: determine_automatic_attributes(),
       labels: determine_config(:labels) |> parse_labels(),
+      ignore_paths: determine_config(:ignore_paths, []),
       telemetry_hosts: telemetry_hosts,
       trace_mode: determine_trace_mode()
     })
@@ -71,6 +72,11 @@ defmodule NewRelic.Init do
             "NEW_RELIC_DB_QUERY_COLLECTION_ENABLED",
             :db_query_collection_enabled
           ),
+      distributed_tracing:
+        determine_feature(
+          "NEW_RELIC_DISTRIBUTED_TRACING_ENABLED",
+          :distributed_tracing_enabled
+        ),
       ecto_instrumentation:
         determine_feature(
           "NEW_RELIC_ECTO_INSTRUMENTATION_ENABLED",
diff --git a/lib/new_relic/logger.ex b/lib/new_relic/logger.ex
index dabd7b9..722369f 100644
--- a/lib/new_relic/logger.ex
+++ b/lib/new_relic/logger.ex
@@ -61,7 +61,8 @@ defmodule NewRelic.Logger do
 
   def initial_logger do
     case NewRelic.Config.logger() do
-      nil -> {:file, "tmp/new_relic.log"}
+      nil -> :logger
+      "file" -> {:file, "tmp/new_relic.log"}
       "stdout" -> :stdio
       "memory" -> :memory
       "Logger" -> :logger
diff --git a/lib/new_relic/other_transaction.ex b/lib/new_relic/other_transaction.ex
index c2a5534..9ab043c 100644
--- a/lib/new_relic/other_transaction.ex
+++ b/lib/new_relic/other_transaction.ex
@@ -3,9 +3,7 @@ defmodule NewRelic.OtherTransaction do
 
   def start_transaction(category, name) do
     NewRelic.Transaction.Reporter.start_transaction(:other)
-
-    NewRelic.DistributedTrace.generate_new_context()
-    |> NewRelic.DistributedTrace.track_transaction(transport_type: "Other")
+    NewRelic.DistributedTrace.start(:other)
 
     NewRelic.add_attributes(
       pid: inspect(self()),
diff --git a/lib/new_relic/sampler/process.ex b/lib/new_relic/sampler/process.ex
index 2d7a7a7..d9c7564 100644
--- a/lib/new_relic/sampler/process.ex
+++ b/lib/new_relic/sampler/process.ex
@@ -69,21 +69,26 @@ defmodule NewRelic.Sampler.Process do
     {current_sample, stats}
   end
 
-  @kb 1024
   def take_sample(pid) do
     # http://erlang.org/doc/man/erlang.html#process_info-2
     info = Process.info(pid, [:message_queue_len, :memory, :reductions, :registered_name])
 
     %{
       pid: inspect(pid),
-      memory_kb: info[:memory] / @kb,
+      memory_kb: kb(info[:memory]),
       message_queue_length: info[:message_queue_len],
       name: parse(:name, info[:registered_name]) || inspect(pid),
       reductions: info[:reductions]
     }
   end
 
-  defp delta(previous, current), do: %{reductions: current.reductions - previous.reductions}
+  @kb 1024
+  defp kb(nil), do: nil
+  defp kb(bytes), do: bytes / @kb
+
+  defp delta(%{reductions: nil}, _), do: nil
+  defp delta(_, %{reductions: nil}), do: nil
+  defp delta(%{reductions: prev}, %{reductions: curr}), do: %{reductions: curr - prev}
 
   defp parse(:name, []), do: nil
   defp parse(:name, name), do: inspect(name)
diff --git a/lib/new_relic/span/reporter.ex b/lib/new_relic/span/reporter.ex
index 5a59d08..83f0a37 100644
--- a/lib/new_relic/span/reporter.ex
+++ b/lib/new_relic/span/reporter.ex
@@ -2,7 +2,9 @@ defmodule NewRelic.Span.Reporter do
   @moduledoc false
 
   def report_span(span) do
-    case NewRelic.Config.feature(:infinite_tracing) do
+    case NewRelic.Config.feature?(:distributed_tracing) &&
+           NewRelic.Config.feature(:infinite_tracing) do
+      false -> :ignore
       :sampling -> NewRelic.Harvest.Collector.SpanEvent.Harvester.report_span(span)
       :infinite -> NewRelic.Harvest.TelemetrySdk.Spans.Harvester.report_span(span)
     end
diff --git a/lib/new_relic/telemetry/plug.ex b/lib/new_relic/telemetry/plug.ex
index 3d10288..dc66946 100644
--- a/lib/new_relic/telemetry/plug.ex
+++ b/lib/new_relic/telemetry/plug.ex
@@ -98,14 +98,15 @@ defmodule NewRelic.Telemetry.Plug do
       ) do
     measurements = Map.put_new(measurements, :system_time, System.system_time())
 
-    Transaction.Reporter.start_transaction(:web)
-    headers = get_headers(meta, server)
+    with :collect <- Transaction.Reporter.start_transaction(:web, path(meta, server)) do
+      headers = get_headers(meta, server)
 
-    if NewRelic.Config.enabled?(),
-      do: DistributedTrace.start(:http, headers)
+      if NewRelic.Config.enabled?(),
+        do: DistributedTrace.start(:http, headers)
 
-    add_start_attrs(meta, measurements, headers, server)
-    maybe_report_queueing(headers)
+      add_start_attrs(meta, measurements, headers, server)
+      maybe_report_queueing(headers)
+    end
   end
 
   def handle_event(
@@ -268,6 +269,10 @@ defmodule NewRelic.Telemetry.Plug do
     end
   end
 
+  defp path(%{req: %{path: path}}, :cowboy), do: path
+  defp path(%{conn: %{request_path: path}}, :bandit), do: path
+  defp path(_, _), do: "unknown"
+
   defp get_headers(%{conn: conn}, :bandit) do
     Map.new(conn.req_headers)
   end
diff --git a/lib/new_relic/transaction/reporter.ex b/lib/new_relic/transaction/reporter.ex
index 345cf05..98189b9 100644
--- a/lib/new_relic/transaction/reporter.ex
+++ b/lib/new_relic/transaction/reporter.ex
@@ -26,9 +26,15 @@ defmodule NewRelic.Transaction.Reporter do
     Transaction.Sidecar.add(custom_name: custom_name)
   end
 
-  def start_transaction(:web) do
-    Transaction.ErlangTrace.trace()
-    Transaction.Sidecar.track(:web)
+  def start_transaction(:web, path) do
+    if NewRelic.Util.path_match?(path, NewRelic.Config.ignore_paths()) do
+      ignore_transaction()
+      :ignore
+    else
+      Transaction.ErlangTrace.trace()
+      Transaction.Sidecar.track(:web)
+      :collect
+    end
   end
 
   def start_transaction(:other) do
diff --git a/lib/new_relic/transaction/sidecar.ex b/lib/new_relic/transaction/sidecar.ex
index 64d6f51..16f09c1 100644
--- a/lib/new_relic/transaction/sidecar.ex
+++ b/lib/new_relic/transaction/sidecar.ex
@@ -13,7 +13,7 @@ defmodule NewRelic.Transaction.Sidecar do
 
   def track(type) do
     # We use `GenServer.start` to avoid a bi-directional link
-    # and guarentee that we never crash the Transaction process
+    # and guarantee that we never crash the Transaction process
     # even in the case of an unexpected bug. Additionally, this
     # blocks the Transaction process the smallest amount possible
     {:ok, sidecar} = GenServer.start(__MODULE__, {self(), type})
diff --git a/lib/new_relic/util.ex b/lib/new_relic/util.ex
index a34a02a..138942c 100644
--- a/lib/new_relic/util.ex
+++ b/lib/new_relic/util.ex
@@ -78,7 +78,7 @@ defmodule NewRelic.Util do
       {key, value} when is_bitstring(value) ->
         case String.valid?(value) do
           true -> [{key, value}]
-          false -> [bad_value(key, value)]
+          false -> [{key, "[BINARY_VALUE]"}]
         end
 
       {key, value} when is_reference(value) when is_pid(value) when is_port(value) ->
@@ -179,6 +179,16 @@ defmodule NewRelic.Util do
     with {:ok, name} <- :inet.gethostname(), do: to_string(name)
   end
 
+  def path_match?(_path, []), do: false
+
+  def path_match?(path, path_set) do
+    Enum.any?(path_set, fn
+      string when is_binary(string) -> path == string
+      %Regex{} = regex -> path =~ regex
+      _ -> false
+    end)
+  end
+
   def uuid4() do
     "#{u(4)}-#{u(2)}-4a#{u(1)}-#{u(2)}-#{u(6)}"
   end


Test patch:
diff --git a/config/test.exs b/config/test.exs
index c76f6b0..64822d1 100644
--- a/config/test.exs
+++ b/config/test.exs
@@ -5,4 +5,5 @@ config :logger, level: :warning
 config :new_relic_agent,
   app_name: "ElixirAgentTest",
   automatic_attributes: [test_attribute: "test_value"],
-  log: "memory"
+  ignore_paths: ["/ignore/this", ~r(ignore/these/*.)],
+  log: "Logger"
diff --git a/test/distributed_trace_test.exs b/test/distributed_trace_test.exs
index 30c7c6d..dee4a95 100644
--- a/test/distributed_trace_test.exs
+++ b/test/distributed_trace_test.exs
@@ -15,8 +15,10 @@ defmodule DistributedTraceTest do
     plug(:dispatch)
 
     get "/" do
-      [{_, outbound_payload} | _] = NewRelic.distributed_trace_headers(:http)
-      send_resp(conn, 200, outbound_payload)
+      case NewRelic.distributed_trace_headers(:http) do
+        [{_, outbound_payload} | _] -> send_resp(conn, 200, outbound_payload)
+        [] -> send_resp(conn, 200, "nothin")
+      end
     end
 
     get "/w3c" do
@@ -66,6 +68,35 @@ defmodule DistributedTraceTest do
     :ok
   end
 
+  test "can disable Distributed Tracing" do
+    reset_config =
+      TestHelper.update(:nr_features,
+        distributed_tracing: false
+      )
+
+    TestHelper.restart_harvest_cycle(Collector.TransactionEvent.HarvestCycle)
+
+    TestHelper.request(
+      TestPlugApp,
+      conn(:get, "/")
+      |> put_req_header(@dt_header, generate_inbound_payload(:app))
+    )
+
+    [[_, attrs] | _] = TestHelper.gather_harvest(Collector.TransactionEvent.Harvester)
+
+    assert attrs[:name]
+    refute attrs[:error_reason]
+
+    refute attrs[:"parent.app"]
+    refute attrs[:parentId]
+    refute attrs[:parentSpanId]
+    refute attrs[:traceId]
+
+    TestHelper.pause_harvest_cycle(Collector.TransactionEvent.HarvestCycle)
+
+    reset_config.()
+  end
+
   test "Annotate Transaction event with DT attrs" do
     TestHelper.restart_harvest_cycle(Collector.TransactionEvent.HarvestCycle)
 
@@ -135,7 +166,7 @@ defmodule DistributedTraceTest do
     TestHelper.pause_harvest_cycle(Collector.Metric.HarvestCycle)
   end
 
-  test "propigate the context through connected Elixir processes" do
+  test "propagate the context through connected Elixir processes" do
     response =
       TestHelper.request(
         TestPlugApp,
diff --git a/test/transaction_test.exs b/test/transaction_test.exs
index e7effef..e62a0a5 100644
--- a/test/transaction_test.exs
+++ b/test/transaction_test.exs
@@ -169,6 +169,14 @@ defmodule TransactionTest do
       send_resp(conn, 200, "ignored")
     end
 
+    get "/ignore/this" do
+      send_resp(conn, 200, "ignore me!")
+    end
+
+    get "/ignore/these/too" do
+      send_resp(conn, 200, "ignore me!")
+    end
+
     get "/total_time" do
       Process.sleep(10)
 
@@ -207,7 +215,6 @@ defmodule TransactionTest do
            end)
   end
 
-  @bad "[BAD_VALUE]"
   test "Attribute coercion" do
     TestHelper.restart_harvest_cycle(Collector.TransactionEvent.HarvestCycle)
 
@@ -233,11 +240,13 @@ defmodule TransactionTest do
     assert {:ok, _} = Date.from_iso8601(event[:date])
     assert {:ok, _} = Time.from_iso8601(event[:time])
 
+    # Binary values
+    assert event[:binary] == "[BINARY_VALUE]"
+
     # Bad values
-    assert event[:binary] == @bad
-    assert event[:tuple] == @bad
-    assert event[:function] == @bad
-    assert event[:struct] == @bad
+    assert event[:tuple] == "[BAD_VALUE]"
+    assert event[:function] == "[BAD_VALUE]"
+    assert event[:struct] == "[BAD_VALUE]"
 
     # Don't report nil values
     refute Map.has_key?(event, :nilValue)
@@ -411,6 +420,17 @@ defmodule TransactionTest do
     assert events == []
   end
 
+  test "Allow a transaction to be ignored via configuration" do
+    TestHelper.restart_harvest_cycle(Collector.TransactionEvent.HarvestCycle)
+    Task.Supervisor.start_link(name: TestTaskSup)
+
+    assert %{status_code: 200} = TestHelper.request(TestPlugApp, conn(:get, "/ignore/this"))
+    assert %{status_code: 200} = TestHelper.request(TestPlugApp, conn(:get, "/ignore/these/too"))
+
+    events = TestHelper.gather_harvest(Collector.TransactionEvent.Harvester)
+    assert events == []
+  end
+
   test "Calculate total time" do
     TestHelper.restart_harvest_cycle(Collector.TransactionEvent.HarvestCycle)