Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Correctly handle the timezone in batch job logs #4604

Merged
merged 2 commits into from Nov 20, 2021
Merged

Correctly handle the timezone in batch job logs #4604

merged 2 commits into from Nov 20, 2021

Conversation

yan12125
Copy link
Contributor

At least with Podman, log timestamps contain timezone information
(ex: 2021-11-20T13:45:15+08:00). As a result, timestamps parsed with
ignoretz=True may be several hours later (ex: 8 hours) than the actual
time, causing logs to be rejected.

The issue can be reproduced by running tests on a UTC+8 machine:

$ DOCKER_HOST=unix:///run/user/1000/podman/podman.sock pytest -v tests/test_batch/test_batch_jobs.py -k test_submit_job --capture=no
============================================================================ test session starts =============================================================================
platform linux -- Python 3.9.7, pytest-6.2.5, py-1.10.0, pluggy-0.13.1 -- /usr/bin/python
cachedir: .pytest_cache
rootdir: /home/yen/tmp/moto, configfile: setup.cfg
plugins: anyio-3.3.4
collected 10 items / 8 deselected / 2 selected

tests/test_batch/test_batch_jobs.py::test_submit_job_by_name PASSED
tests/test_batch/test_batch_jobs.py::test_submit_job FAILED

================================================================================== FAILURES ==================================================================================
______________________________________________________________________________ test_submit_job _______________________________________________________________________________

self = <sure.AssertionBuilder object at 0x7fe8f1da7ee0>, args = (['hello'],), kw = {}

    @wraps(func)
    def wrapper(self, *args, **kw):
        try:
>           value = func(self, *args, **kw)

/usr/lib/python3.9/site-packages/sure/__init__.py:408:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <sure.AssertionBuilder object at 0x7fe8f1da7ee0>, what = ['hello'], epsilon = None

    @assertionmethod
    def equal(self, what, epsilon=None):
        """compares given object ``X``  with an expected ``Y`` object.

        It primarily assures that the compared objects are absolute equal ``==``.

        :param what: the expected value
        :param epsilon: a delta to leverage upper-bound floating point permissiveness
        """

        try:
            comparison = DeepComparison(self.obj, what, epsilon).compare()
            error = False
        except AssertionError as e:
            error = e
            comparison = None

        if isinstance(comparison, DeepExplanation):
            error = comparison.get_assertion(self.obj, what)

        if self.negative:
            if error:
                return True

            msg = "%s should differ from %s, but is the same thing"
            raise AssertionError(msg % (safe_repr(self.obj), safe_repr(what)))

        else:
            if not error:
                return True
>           raise error
E           AssertionError: given
E           X = []
E               and
E           Y = ['hello']
E           Y has 1 items whereas X has only 0

/usr/lib/python3.9/site-packages/sure/__init__.py:729: AssertionError

During handling of the above exception, another exception occurred:

    @mock_logs
    @mock_ec2
    @mock_ecs
    @mock_iam
    @mock_batch
    @pytest.mark.network
    def test_submit_job():
        ec2_client, iam_client, _, logs_client, batch_client = _get_clients()
        _, _, _, iam_arn = _setup(ec2_client, iam_client)
        start_time_milliseconds = time.time() * 1000

        job_def_name = str(uuid4())[0:6]
        commands = ["echo", "hello"]
        job_def_arn, queue_arn = prepare_job(batch_client, commands, iam_arn, job_def_name)

        resp = batch_client.submit_job(
            jobName=str(uuid4())[0:6], jobQueue=queue_arn, jobDefinition=job_def_arn
        )
        job_id = resp["jobId"]

        # Test that describe_jobs() returns 'createdAt'
        # github.com/spulec/moto/issues/4364
        resp = batch_client.describe_jobs(jobs=[job_id])
        created_at = resp["jobs"][0]["createdAt"]
        created_at.should.be.greater_than(start_time_milliseconds)

        _wait_for_job_status(batch_client, job_id, "SUCCEEDED")

        resp = logs_client.describe_log_streams(
            logGroupName="/aws/batch/job", logStreamNamePrefix=job_def_name
        )
        resp["logStreams"].should.have.length_of(1)
        ls_name = resp["logStreams"][0]["logStreamName"]

        resp = logs_client.get_log_events(
            logGroupName="/aws/batch/job", logStreamName=ls_name
        )
>       [event["message"] for event in resp["events"]].should.equal(["hello"])

tests/test_batch/test_batch_jobs.py:126:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <sure.AssertionBuilder object at 0x7fe8f1da7ee0>, args = (['hello'],), kw = {}

    @wraps(func)
    def wrapper(self, *args, **kw):
        try:
            value = func(self, *args, **kw)
        except AssertionError as e:
>           raise AssertionError(e)
E           AssertionError: given
E           X = []
E               and
E           Y = ['hello']
E           Y has 1 items whereas X has only 0

/usr/lib/python3.9/site-packages/sure/__init__.py:410: AssertionError
============================================================================== warnings summary ==============================================================================
../../../../usr/lib/python3.9/site-packages/boto/plugin.py:40
  /usr/lib/python3.9/site-packages/boto/plugin.py:40: DeprecationWarning: the imp module is deprecated in favour of importlib; see the module's documentation for alternative uses
    import imp

-- Docs: https://docs.pytest.org/en/stable/warnings.html
========================================================================== short test summary info ===========================================================================
FAILED tests/test_batch/test_batch_jobs.py::test_submit_job - AssertionError: given
============================================================ 1 failed, 1 passed, 8 deselected, 1 warning in 4.10s ============================================================

Chih-Hsuan Yen added 2 commits November 20, 2021 13:46
At least with Podman, log timestamps contain timezone information
(ex: 2021-11-20T13:45:15+08:00). As a result, timestamps parsed with
ignoretz=True may be several hours later (ex: 8 hours) than the actual
time, causing logs to be rejected.

The issue can be reproduced by running tests on a UTC+8 machine:

$ DOCKER_HOST=unix:///run/user/1000/podman/podman.sock pytest -v tests/test_batch/test_batch_jobs.py -k test_submit_job --capture=no
============================================================================ test session starts =============================================================================
platform linux -- Python 3.9.7, pytest-6.2.5, py-1.10.0, pluggy-0.13.1 -- /usr/bin/python
cachedir: .pytest_cache
rootdir: /home/yen/tmp/moto, configfile: setup.cfg
plugins: anyio-3.3.4
collected 10 items / 8 deselected / 2 selected

tests/test_batch/test_batch_jobs.py::test_submit_job_by_name PASSED
tests/test_batch/test_batch_jobs.py::test_submit_job FAILED

================================================================================== FAILURES ==================================================================================
______________________________________________________________________________ test_submit_job _______________________________________________________________________________

self = <sure.AssertionBuilder object at 0x7fe8f1da7ee0>, args = (['hello'],), kw = {}

    @wraps(func)
    def wrapper(self, *args, **kw):
        try:
>           value = func(self, *args, **kw)

/usr/lib/python3.9/site-packages/sure/__init__.py:408:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <sure.AssertionBuilder object at 0x7fe8f1da7ee0>, what = ['hello'], epsilon = None

    @assertionmethod
    def equal(self, what, epsilon=None):
        """compares given object ``X``  with an expected ``Y`` object.

        It primarily assures that the compared objects are absolute equal ``==``.

        :param what: the expected value
        :param epsilon: a delta to leverage upper-bound floating point permissiveness
        """

        try:
            comparison = DeepComparison(self.obj, what, epsilon).compare()
            error = False
        except AssertionError as e:
            error = e
            comparison = None

        if isinstance(comparison, DeepExplanation):
            error = comparison.get_assertion(self.obj, what)

        if self.negative:
            if error:
                return True

            msg = "%s should differ from %s, but is the same thing"
            raise AssertionError(msg % (safe_repr(self.obj), safe_repr(what)))

        else:
            if not error:
                return True
>           raise error
E           AssertionError: given
E           X = []
E               and
E           Y = ['hello']
E           Y has 1 items whereas X has only 0

/usr/lib/python3.9/site-packages/sure/__init__.py:729: AssertionError

During handling of the above exception, another exception occurred:

    @mock_logs
    @mock_ec2
    @mock_ecs
    @mock_iam
    @mock_batch
    @pytest.mark.network
    def test_submit_job():
        ec2_client, iam_client, _, logs_client, batch_client = _get_clients()
        _, _, _, iam_arn = _setup(ec2_client, iam_client)
        start_time_milliseconds = time.time() * 1000

        job_def_name = str(uuid4())[0:6]
        commands = ["echo", "hello"]
        job_def_arn, queue_arn = prepare_job(batch_client, commands, iam_arn, job_def_name)

        resp = batch_client.submit_job(
            jobName=str(uuid4())[0:6], jobQueue=queue_arn, jobDefinition=job_def_arn
        )
        job_id = resp["jobId"]

        # Test that describe_jobs() returns 'createdAt'
        # github.com//issues/4364
        resp = batch_client.describe_jobs(jobs=[job_id])
        created_at = resp["jobs"][0]["createdAt"]
        created_at.should.be.greater_than(start_time_milliseconds)

        _wait_for_job_status(batch_client, job_id, "SUCCEEDED")

        resp = logs_client.describe_log_streams(
            logGroupName="/aws/batch/job", logStreamNamePrefix=job_def_name
        )
        resp["logStreams"].should.have.length_of(1)
        ls_name = resp["logStreams"][0]["logStreamName"]

        resp = logs_client.get_log_events(
            logGroupName="/aws/batch/job", logStreamName=ls_name
        )
>       [event["message"] for event in resp["events"]].should.equal(["hello"])

tests/test_batch/test_batch_jobs.py:126:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <sure.AssertionBuilder object at 0x7fe8f1da7ee0>, args = (['hello'],), kw = {}

    @wraps(func)
    def wrapper(self, *args, **kw):
        try:
            value = func(self, *args, **kw)
        except AssertionError as e:
>           raise AssertionError(e)
E           AssertionError: given
E           X = []
E               and
E           Y = ['hello']
E           Y has 1 items whereas X has only 0

/usr/lib/python3.9/site-packages/sure/__init__.py:410: AssertionError
============================================================================== warnings summary ==============================================================================
../../../../usr/lib/python3.9/site-packages/boto/plugin.py:40
  /usr/lib/python3.9/site-packages/boto/plugin.py:40: DeprecationWarning: the imp module is deprecated in favour of importlib; see the module's documentation for alternative uses
    import imp

-- Docs: https://docs.pytest.org/en/stable/warnings.html
========================================================================== short test summary info ===========================================================================
FAILED tests/test_batch/test_batch_jobs.py::test_submit_job - AssertionError: given
============================================================ 1 failed, 1 passed, 8 deselected, 1 warning in 4.10s ============================================================
Copy link
Collaborator

@bblommers bblommers left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM! Thanks for the fix @yan12125

@bblommers bblommers merged commit c7a9dc3 into getmoto:master Nov 20, 2021
@bblommers bblommers added this to the 2.2.16 milestone Nov 20, 2021
@yan12125 yan12125 deleted the fix-batch-logs branch November 20, 2021 10:52
@github-actions
Copy link
Contributor

This is now part of moto >= 2.2.16.dev21

archlinux-github pushed a commit to archlinux/svntogit-community that referenced this pull request Nov 20, 2021
…4604

git-svn-id: file:///srv/repos/svn-community/svn@1052847 9fca08f4-af9d-4005-b8df-a31f2cc04f65
archlinux-github pushed a commit to archlinux/svntogit-community that referenced this pull request Nov 20, 2021
…4604

git-svn-id: file:///srv/repos/svn-community/svn@1052847 9fca08f4-af9d-4005-b8df-a31f2cc04f65
sahilshah6196 pushed a commit to EBSCOIS/moto that referenced this pull request Dec 20, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

2 participants