Hello has anyone experienced issues with logs not properly g

Question

Hello has anyone experienced issues with logs not properly getting routed to AWS logs drivers via stdout for runs launched via the `EcsRunLauncher` and in a seemingly nondeterministic way We re experiencing a problem where logs that would normally get sent to stdout and captured by our observability tooling in our other ECS based services are not properly captured when running in a Dagster launched task even though they are successfully captured by the Dagster logging handler Strangely the issue seems to be related to the length of execution of individual ops when an op is artificially lengthened by use of `time sleep` logs tend to be captured at a higher rate More details in thread point down thread

Matt Millican · Answer

Here is an example of a job that exhibits this behavior when launched in ECS ```import logging from time import sleep from typing import Generator from dagster import DynamicOut DynamicOutput fs io manager job in process executor op logger = logging getLogger our logger op out=DynamicOut def num helloworlds num steps int gt Generator DynamicOutput None None for i in range num steps yield DynamicOutput None mapping key=str i op def log and sleep result None num rounds per step int sleep len float gt None for i in range num rounds per step for level in logging DEBUG <http logging INFO|logging INFO> logging WARNING logging ERROR logging CRITICAL logger log level f hello world i sleep sleep len job resource defs= io manager fs io manager executor def=in process executor tags= ecs cpu 2048 ecs memory 4096 def helloworld num steps int num rounds per step int sleep len float gt None helloworld output = num helloworlds num steps helloworld output map lambda dynamicout log and sleep dynamicout num rounds per step sleep len ```

Matt Millican · Answer

Here is our in house Python logging configuration which would typically route all logs from `our logger` to the `stdout` of the container for collection by AWS logs drivers This is passed to `logging dictConfig` when a process is launched ```INFRA LOGGING CONFIG = version 1 disable existing loggers False formatters json pythonjsonlogger jsonlogger JsonFormatter format asctime asctime s created created f filename filename s funcName funcName s levelname levelname s levelno levelno s lineno lineno d message message s module module s msec msecs d name name s pathname pathname s process process d processName processName s relativeCreated relativeCreated d thread thread d threadName threadName s exc info exc info s datefmt Y m d H M S handlers stdout class logging StreamHandler stream <ext sys stdout> formatter json loggers dagster level DEBUG handlers stdout dagit level DEBUG handlers stdout level INFO handlers stdout ```

prha · Answer

Do you have a compute log manager configured If you are grabbing logs using a sidecar you may want to bypass the dagster controlled log capture by configuring the `NoOpComputeLogManager` <https docs dagster io dagster cloud deployment agents customizing configuration disabling compute logs>

prha · Answer

By default I think there s some subprocess that routes output both to stdout and to a file but it can hit some timing issues depending on the OS particulars of the run process

Matt Millican · Answer

for completeness here s the part of our Dagster config that controls run launches and logging ``` run launcher module dagster aws ecs class EcsRunLauncher config include sidecars true task definition lt our task definition ARN gt container name staging workflows runs python logs managed python loggers our logger```

Matt Millican · Answer

And the behavior we observed was that logs would semi nondeterministically get collected and routed to other sources via stdout which is the typical path for ECS log routing but would get picked up much more reliably when we launched a run with a large `sleep len` seemingly giving the steps more time to flush logs to stdout before finishing

Matt Millican · Answer

Thanks for the suggestion < prha> we can take a look at this as a start

prha · Answer

Yeah I d bet that switching the compute log config would help with the reliability On unix systems I think there s a child process that invokes `tee` and on windows it s some polling interval that should flush

prha · Answer

Would have to dig in deeper into what s going on in your case but bypassing the compute log capture will at least not muck with the file handles in the OS

Bianca Rosa · Answer

So reviving Matt s thread here I m picking up from where he left we are using `NoOpComputeLogManager` and while it does help it doesn t help with all of it ```compute logs module dagster core storage noop compute log manager class NoOpComputeLogManager``` for this op I expected to see up to 49 helloworlds sent to datadog and for some reason we are getting up to 28 they all share the same timestamp on datadog `Sep 12 12 42 41 370` and were likely on the same batch dagsterlogger 29 on dagster starts at `12 42 41 347` and we lose all logs until `12 42 41 932` we do have the logs for hook skipped and the final execution logs on datadog ```2022 09 12 15 42 42 +0000 dagster DEBUG helloworld job c4dee54d e328 449c aed3 969e394138c2 hello world HOOK SKIPPED Skipped the execution of hook store exit code It did not meet its triggering condition during the execution of hello world 2022 09 12 15 42 42 +0000 dagster DEBUG helloworld job c4dee54d e328 449c aed3 969e394138c2 1 ENGINE EVENT Finished steps in process pid 1 in 1 82s 2022 09 12 15 42 42 +0000 dagster DEBUG helloworld job c4dee54d e328 449c aed3 969e394138c2 1 RUN SUCCESS Finished execution of run for helloworld job ``` and they are actually dated as `Sep 12 12 42 42 089` roughly a second after the last log was sent on the job they also come from the same container so any assumption that the error might be on the log forwarder is losing strength the SIGTERM to the aws for fluent bit was sent afterwards too ``` 2022 09 12 15 42 43 engine caught signal SIGTERM 2022 09 12 15 42 43 info input pausing forward 2```

prha · Answer

It s strange that the logger is losing batches in the middle because you re getting the run termination event logs and that everything is happening on the same container Do you get the same behavior with cloudwatch This isn t something I ve seen before

Bianca Rosa · Answer

from what we ve tested before yes we lose the logs on cloudwatch too it looks like the `stdout` handler is not handling those logs well while the `dagster` handler is dealing with them properly

Bianca Rosa · Answer

One question < prha> is it possible that even using `NoOpComputeLogManager` but still using `fs io manager` we can hitting the timing issues you mentioned in this thread

prha · Answer

< Bianca Rosa> I don t think so The `fs io manager` is responsible for reading inputs writing outputs to disk The compute log manager is more about routing stdout stderr to disk and potentially uploading it somewhere like S3 With the noop compute log manager we don t touch stdout stderr at all so the datadog sidecar you have set up should work as intended If you re still running into issues I wonder if there s some debugging you could do with your AWS rep in terms of the container lifecycle I saw this issue in SO that doesn t sound like is what you re seeing but maybe there s some similar flushing issue that you re hitting

Bianca Rosa · Answer

I didn t think that was the case because we had container s dependencies properly set and we don t have this in any of our other apps so I spent the day hooking our app into datadog locally and I was able to reproduce it in a local containerized environment

Bianca Rosa · Answer

I m losing roughly 10 logs on stdout nearby the end of the execution of the hello world job and those logs get sent to the Dagster UI

Bianca Rosa · Answer

Oh wait one last thing to check enable `NoOpComputeLogManager` locally

Bianca Rosa · Answer

Ha With `NoOpComputeLogManager` in fact the behavior doesnt continue locally grimacing

Bianca Rosa · Answer

Update here for you < prha> indeed `NoOpComputeLogManager` was the way to go I wonder if there is a way to make it explicit default if you use ECS on the docs code Our issue was so much harder due to the fact that workflows user code was not picking up the config changes and we went into a rabbit hole that was hard to get out of because we needed to update all the three images with it but our Dockerfile was not copying the right config into `dagster yaml` for the workflows user code container Anyways things were quite hard to debug but eventually we got there