Отсутствие строк журнала при записи в cloudwatch из контейнеров ECS Docker

Question

(Docker-контейнер в AWS-ECS завершает работу до того, как все журналы печатаются в журналах CloudWatch). Почему некоторые потоки из группы журналов CloudWatch являются неполными (т. Е. Контейнер Fargate Docker успешно завершается, но журналы перестают обновляться внезапно)?Видя это периодически, почти во всех группах журналов, однако, не на каждом потоке / задании журнала.Я использую версию 1.3.0

---

Описание:
A Dockerfile запускает сценарии node.js или Python с помощью команды CMD.

Это не серверы / долго выполняющиеся процессы, и мой вариант использования требует, чтобы контейнеры закрывались после завершения задачи.

Пример Dockerfile:

FROM node:6
WORKDIR /path/to/app/
COPY package*.json ./
RUN npm install
COPY . .
CMD [ "node", "run-this-script.js" ]

Все журналы правильно печатаются в stdout / stderr моего терминала, когда эта команда запускается на терминале локально с docker run.
Чтобы запускать их как Задачи ECS на Fargate, драйвер журнала для него устанавливается как awslogs из шаблона CloudFormation.

...
LogConfiguration:
   LogDriver: 'awslogs'
     Options:
        awslogs-group: !Sub '/ecs/ecs-tasks-${TaskName}'
        awslogs-region: !Ref AWS::Region
        awslogs-stream-prefix: ecs
...

Видя, что иногда вывод логов cloduwatch является неполным, я запустил тестыи проверил все ограничения от CW Logs Limits и уверен, что проблема не в этом.
Первоначально я думал, что это проблема с асинхронным выходом узла j перед сбросом console.log() или тем, что процесс завершается слишком рано, но такая же проблема возникает и при использовании другого языка - что заставляет меня верить в этоэто не проблема с кодом, а именно с cloudwatch специально.
Индуцирование задержек в коде путем добавления таймера отключения не сработало для меня .

Вполне возможно, что, поскольку контейнер Docker завершает работу сразу после завершения задачи, журналы не получают достаточно времени для записи в CWLogs, но должен быть способ гарантировать, что этого не произойдет?

примеры журналов: неполный поток:

{ "message": "configs to run", "data": {"dailyConfigs":"filename.json"]}}
running for filename

завершенный поток журнала:

{ "message": "configs to run", "data": {"dailyConfigs":"filename.json"]}}
running for filename

stdout: entered query_script
... <more log lines>
stderr:
real 0m23.394s
user 0m0.008s
sys 0m0.004s
(node:1) DeprecationWarning: PG.end is deprecated - please see the upgrade guide at https://node-postgres.com/guides/upgrading

Answer 1

Только что связался со службой поддержки AWS по этому вопросу, и вот их ответ:

...

На основании этого случая я вижу, что это происходит для контейнеров в FargateЗадача, которая быстро завершается после вывода в stdout / stderr.Похоже, это связано с тем, как работает драйвер awslogs и как Docker в Fargate взаимодействует с конечной точкой CW.

Глядя на наши внутренние билеты на то же самое, я вижу, что наша сервисная команда все еще работает над постоянным решением этой сообщенной ошибки.К сожалению, нет общего ресурса ETA, когда будет установлено исправление.Тем не менее, я воспользовался этой возможностью, чтобы добавить этот случай во внутренний тикет, чтобы проинформировать команду о подобном и попытаться ускорить процесс

Тем временем этого можно избежать, продлив срок действия выходаКонтейнер путем добавления задержки (~> 10 секунд) между выходом журнала приложения и выходом из процесса (выходом из контейнера).

...

Обновление : связались с AWS около 1 августа 2019 года, говорят, что эта проблема была исправлена.

Answer 2

Я тоже это заметил.Это должно быть ошибка ECS?

Мой обходной путь (Python 3.7):

import atexit
from time import sleep

atexit.register(finalizer)

def finalizer():
    logger.info("All tasks have finished. Exiting.")
    # Workaround:
    # Fargate will exit and final batch of CloudWatch logs will be lost
    sleep(10)

Answer 3

У меня была такая же проблема с очисткой журналов до CloudWatch.

После ответа Асавоя я переключился с формы exec на форму оболочки ENTRYPOINT и добавил 10-секундный сон в конце.

До:

ENTRYPOINT ["java","-jar","/app.jar"]

После:

ENTRYPOINT java -jar /app.jar; sleep 10

Answer 4

ОБНОВЛЕНИЕ: теперь это выглядит как фиксированный , поэтому нет необходимости применять обходной путь, описанный ниже

---

Я видел то же самоеповедение при использовании контейнеров ECS Fargate для запуска сценариев Python - и это вызвало то же разочарование!

Я думаю, это связано с тем, что агент журналов CloudWatch публикует события журнала в пакетном режиме:

Как пакетируются события журнала?

Пакет заполняется и публикуется при выполнении любого из следующих условий:

1. Время buffer_durationпрошло с момента добавления первого события журнала.

2. Меньше чем batch_size событий журнала накоплено, но добавление нового события журнала превышает batch_size.

3. Количество событий журнала достигло batch_count.

4. События журнала из пакета не занимают более 24 часов, но при добавлении нового события журналапревышает ограничение в 24 часа.

(Ссылка:https://docs.aws.amazon.com/AmazonCloudWatch/latest/logs/AgentReference.html)

Таким образом, возможное объяснение состоит в том, что события журнала буферизуются агентом, но еще не опубликованы, когда задача ECS остановлена.(И если так, то это похоже на проблему ECS - любые инженеры AWS ECS, желающие высказать свое мнение по этому вопросу ...?)

Кажется, нет прямого способа обеспечить публикацию журналов., но он предполагает, что можно подождать не менее buffer_duration секунд (по умолчанию 5 секунд), и любые предыдущие журналы должны быть опубликованы.

После небольшого тестирования, которое я опишу ниже, вотОбходной путь, на котором я приземлился.Сценарий оболочки run_then_wait.sh переносит команду для запуска сценария Python, чтобы добавить спящий режим после завершения сценария.

Dockerfile

FROM python:3.7-alpine
ADD run_then_wait.sh .
ADD main.py .

# The original command
# ENTRYPOINT ["python", "main.py"]

# To run the original command and then wait
ENTRYPOINT ["sh", "run_then_wait.sh", "python", "main.py"]

run_then_wait.sh

#!/bin/sh
set -e

# Wait 10 seconds on exit: twice the `buffer_duration` default of 5 seconds
trap 'echo "Waiting for logs to flush to CloudWatch Logs..."; sleep 10' EXIT

# Run the given command
"$@"

main.py

import logging
import time

logging.basicConfig(level=logging.INFO)
logger = logging.getLogger()

if __name__ == "__main__":
    # After testing some random values, had most luck to induce the
    # issue by sleeping 9 seconds here; would occur ~30% of the time
    time.sleep(9)
    logger.info("Hello world")

Надеемся, что подход может быть адаптирован к вашей ситуации.Вы также можете реализовать спящий режим внутри своего скрипта, но может быть сложнее убедиться, что он происходит независимо от того, как он завершается.

Трудно доказать, что предложенное объяснение является точным, поэтому я использовал приведенный выше код для проверкибыл ли обходной путь эффективным.Тест был исходной командой против run_then_wait.sh, по 30 прогонов каждый.В результате проблема наблюдалась в 30% случаев по сравнению с 0% времени соответственно.Надеюсь, что это так же эффективно для вас!