Telemetry / :ets in remote docker

Questions / Help
, , ,
1

Hi everyone,

I’m trying to make telemetry work for the last couple of days, but without any luck. My setup runs in a docker container on a remote machine. The issue started when I wanted to receive [:phoenix, :router_dispatch, :stop] telemetry event. I attach to events with :telemetry.attach_many, all the usual stuff. I see every event, besides [:phoenix, :router_dispatch, :stop]. I tried a lot of things, and got the project to a state where I restart the container, make 1 request and I see my event. But for all later requests it doesn’t come anymore.

Then to check the theory if maybe it’s something wrong with my project, I created a new clean project and ran it in a) remote docker 2) docker on mac 3) mac without docker. On docker on mac and pure mac it works flawlessly, every event is received.

On remote docker - nope. I receive everything but [:phoenix, :router_dispatch, :stop]. @chrismccord in Slack recommended to add some debugging statements to Phoenix Router before the telemetry events get sent. I did that and now I am even more puzzled.

router.ex — sales_tool_telemetry 2020-05-15 08-31-55
router.ex — sales_tool_telemetry 2020-05-15 08-31-551838×962 175 KB

As you see from the log, “BEFORE ETS” gets logged, but not the content from :ets, and nothing after that. If I comment out the :ets.tab2list line, then “BEFORE STOP” gets logged.

Is it something with :ets? What is going on? And why is it happening only in remote docker?

1 Like
2

Another theory - my remote docker machine is slow and can’t handle so many IO.inspects and some just get dropped? Can anyone dispute it?

I was logging the telemetry events in my app also with IO.inspect

3

I think I’m on to something here. I removed all the IO.inspect calls, and just using Logger.info to output the name of the event without the long metadata.

sales_tool_telemetry_1                         | [info] [:phoenix, :router_dispatch, :start]
sales_tool_telemetry_1                         | [info] Sent 200 in 2ms
sales_tool_telemetry_1                         | [info] [:phoenix, :router_dispatch, :stop]

Getting consistent output.

But, wtf?

4

Is it possible that inspecting a big complex object messes with docker’s ability to figure out which lines are logging lines?