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

fix: avoid truncating sessionaction logs #86

Merged
merged 1 commit into from
Nov 8, 2023
Merged

Conversation

ddneilson
Copy link
Contributor

What was the problem/requirement? (What/Why)

In the service we use a SessionAction's reported startedAt/endedAt time
to filter the cloudwatch logs stream for a Session so that we can display only the logs relevant to that particular SessionAction. There is an edge case that occationally shows up where the very last log line of a SessionAction will not show up in this filtered view. This is because the timestamp on that log line is after the endedAt time of the SessionAction; see below for a sample:

In the portal UI I only see the following in the sync attachments log:

2023/11/02 13:29:10-05:00 Syncing inputs using Job Attachments
2023/11/02 13:29:11-05:00 Downloaded 445.0 B / 445.0 B of 1 file (Transfer rate: 0.0 B/s)

The full log shows:

    2023-11-02T13:29:10.839-05:00    Syncing inputs using Job Attachments
    2023-11-02T13:29:11.042-05:00    Downloaded 445.0 B / 445.0 B of 1 file (Transfer rate: 0.0 B/s)
    2023-11-02T13:29:11.044-05:00    Summary Statistics for file downloads: Processed 1 file totaling 445.0 B. Skipped re-processing 0 files totaling 0.0 B. Total processing time of 0.05191 seconds at 8.57 KB/s.

The session action details are:

% aws deadline get-session-action --farm-id ...
{
    "sessionActionId": "sessionaction-d0f37f306f93484699ceda74bb6c15ef-0",
    "status": "SUCCEEDED",
    "startedAt": "2023-11-02T18:29:10.838000+00:00",
    "endedAt": "2023-11-02T18:29:11.043000+00:00",
    "progressPercent": 100.0,
    "sessionId": "session-d0f37f306f93484699ceda74bb6c15ef",
    "definition": {
        "syncInputJobAttachments": {}
    }
}

Notice that the timestamp on the line of logging that's excluded is 1 millisecond after the endedAt time of the SessionAction.

What was the solution? (How)

This comes down to a difference in rounding. We are rounding when converting a
timestamp in to the integer number of milliseconds after epoch-utc to report to CloudWatch. However, the Deadline Cloud service is truncating the startedAt/endedAt times to the number of milliseconds. Truncation and rounding produce different results half of the time (statistically speaking). So, this fix modifies the timestamp that we report to CloudWatch to truncate to the number of milliseconds rather than round.

What is the impact of this change?

Customers that view a SessionAction's logs through the portal UI will no longer have lines of logging missing from the view.

How was this change tested?

Just unit testing.

Was this change documented?

No

Is this a breaking change?

No

Summary:
 In the service we use a SessionAction's reported startedAt/endedAt time
to filter the cloudwatch logs stream for a Session so that we can
display only the logs relevant to that particular SessionAction. There
is an edge case that occationally shows up where the very last log line
of a SessionAction will not show up in this filtered view. This is
because the timestamp on that log line is *after* the endedAt time of
the SessionAction; see below for a sample:

In the portal UI I only see the following in the sync attachments log:

```
2023/11/02 13:29:10-05:00 Syncing inputs using Job Attachments
2023/11/02 13:29:11-05:00 Downloaded 445.0 B / 445.0 B of 1 file (Transfer rate: 0.0 B/s)
```

The full log shows:

```
    2023-11-02T13:29:10.839-05:00    Syncing inputs using Job Attachments
    2023-11-02T13:29:11.042-05:00    Downloaded 445.0 B / 445.0 B of 1 file (Transfer rate: 0.0 B/s)
    2023-11-02T13:29:11.044-05:00    Summary Statistics for file downloads: Processed 1 file totaling 445.0 B. Skipped re-processing 0 files totaling 0.0 B. Total processing time of 0.05191 seconds at 8.57 KB/s.
```

The session action details are:

```
% aws deadline get-session-action --farm-id ...
{
    "sessionActionId": "sessionaction-d0f37f306f93484699ceda74bb6c15ef-0",
    "status": "SUCCEEDED",
    "startedAt": "2023-11-02T18:29:10.838000+00:00",
    "endedAt": "2023-11-02T18:29:11.043000+00:00",
    "progressPercent": 100.0,
    "sessionId": "session-d0f37f306f93484699ceda74bb6c15ef",
    "definition": {
        "syncInputJobAttachments": {}
    }
}
```

Notice that the timestamp on the line of logging that's excluded is 1
millisecond after the endedAt time of the SessionAction.

Resolution:
 This comes down to a difference in rounding. We are rounding when converting a
timestamp in to the integer number of milliseconds after epoch-utc to report
to CloudWatch. However, the Deadline Cloud service is truncating the
startedAt/endedAt times to the number of milliseconds. Truncation and
rounding produce different results half of the time (statistically
speaking). So, this fix modifies the timestamp that we report to
CloudWatch to truncate to the number of milliseconds rather than round.

Signed-off-by: Daniel Neilson <53624638+ddneilson@users.noreply.github.com>
@ddneilson ddneilson merged commit 47dca3e into mainline Nov 8, 2023
9 checks passed
@ddneilson ddneilson deleted the ddneilson/13998 branch November 8, 2023 21:16
@jusiskin jusiskin added the bug Something isn't working label Nov 8, 2023
gmchale79 pushed a commit that referenced this pull request Feb 12, 2024
Summary:
 In the service we use a SessionAction's reported startedAt/endedAt time
to filter the cloudwatch logs stream for a Session so that we can
display only the logs relevant to that particular SessionAction. There
is an edge case that occationally shows up where the very last log line
of a SessionAction will not show up in this filtered view. This is
because the timestamp on that log line is *after* the endedAt time of
the SessionAction; see below for a sample:

In the portal UI I only see the following in the sync attachments log:

```
2023/11/02 13:29:10-05:00 Syncing inputs using Job Attachments
2023/11/02 13:29:11-05:00 Downloaded 445.0 B / 445.0 B of 1 file (Transfer rate: 0.0 B/s)
```

The full log shows:

```
    2023-11-02T13:29:10.839-05:00    Syncing inputs using Job Attachments
    2023-11-02T13:29:11.042-05:00    Downloaded 445.0 B / 445.0 B of 1 file (Transfer rate: 0.0 B/s)
    2023-11-02T13:29:11.044-05:00    Summary Statistics for file downloads: Processed 1 file totaling 445.0 B. Skipped re-processing 0 files totaling 0.0 B. Total processing time of 0.05191 seconds at 8.57 KB/s.
```

The session action details are:

```
% aws deadline get-session-action --farm-id ...
{
    "sessionActionId": "sessionaction-d0f37f306f93484699ceda74bb6c15ef-0",
    "status": "SUCCEEDED",
    "startedAt": "2023-11-02T18:29:10.838000+00:00",
    "endedAt": "2023-11-02T18:29:11.043000+00:00",
    "progressPercent": 100.0,
    "sessionId": "session-d0f37f306f93484699ceda74bb6c15ef",
    "definition": {
        "syncInputJobAttachments": {}
    }
}
```

Notice that the timestamp on the line of logging that's excluded is 1
millisecond after the endedAt time of the SessionAction.

Resolution:
 This comes down to a difference in rounding. We are rounding when converting a
timestamp in to the integer number of milliseconds after epoch-utc to report
to CloudWatch. However, the Deadline Cloud service is truncating the
startedAt/endedAt times to the number of milliseconds. Truncation and
rounding produce different results half of the time (statistically
speaking). So, this fix modifies the timestamp that we report to
CloudWatch to truncate to the number of milliseconds rather than round.

Signed-off-by: Daniel Neilson <53624638+ddneilson@users.noreply.github.com>
Signed-off-by: Graeme McHale <gmchale@amazon.com>
gmchale79 pushed a commit that referenced this pull request Mar 11, 2024
Summary:
 In the service we use a SessionAction's reported startedAt/endedAt time
to filter the cloudwatch logs stream for a Session so that we can
display only the logs relevant to that particular SessionAction. There
is an edge case that occationally shows up where the very last log line
of a SessionAction will not show up in this filtered view. This is
because the timestamp on that log line is *after* the endedAt time of
the SessionAction; see below for a sample:

In the portal UI I only see the following in the sync attachments log:

```
2023/11/02 13:29:10-05:00 Syncing inputs using Job Attachments
2023/11/02 13:29:11-05:00 Downloaded 445.0 B / 445.0 B of 1 file (Transfer rate: 0.0 B/s)
```

The full log shows:

```
    2023-11-02T13:29:10.839-05:00    Syncing inputs using Job Attachments
    2023-11-02T13:29:11.042-05:00    Downloaded 445.0 B / 445.0 B of 1 file (Transfer rate: 0.0 B/s)
    2023-11-02T13:29:11.044-05:00    Summary Statistics for file downloads: Processed 1 file totaling 445.0 B. Skipped re-processing 0 files totaling 0.0 B. Total processing time of 0.05191 seconds at 8.57 KB/s.
```

The session action details are:

```
% aws deadline get-session-action --farm-id ...
{
    "sessionActionId": "sessionaction-d0f37f306f93484699ceda74bb6c15ef-0",
    "status": "SUCCEEDED",
    "startedAt": "2023-11-02T18:29:10.838000+00:00",
    "endedAt": "2023-11-02T18:29:11.043000+00:00",
    "progressPercent": 100.0,
    "sessionId": "session-d0f37f306f93484699ceda74bb6c15ef",
    "definition": {
        "syncInputJobAttachments": {}
    }
}
```

Notice that the timestamp on the line of logging that's excluded is 1
millisecond after the endedAt time of the SessionAction.

Resolution:
 This comes down to a difference in rounding. We are rounding when converting a
timestamp in to the integer number of milliseconds after epoch-utc to report
to CloudWatch. However, the Deadline Cloud service is truncating the
startedAt/endedAt times to the number of milliseconds. Truncation and
rounding produce different results half of the time (statistically
speaking). So, this fix modifies the timestamp that we report to
CloudWatch to truncate to the number of milliseconds rather than round.

Signed-off-by: Daniel Neilson <53624638+ddneilson@users.noreply.github.com>
Signed-off-by: Graeme McHale <gmchale@amazon.com>
jusiskin pushed a commit to jusiskin/deadline-cloud-worker-agent that referenced this pull request Sep 4, 2024
…ws-deadline#86)

Updates the requirements on [pytest-cov](https://github.com/pytest-dev/pytest-cov) to permit the latest version.
- [Changelog](https://github.com/pytest-dev/pytest-cov/blob/master/CHANGELOG.rst)
- [Commits](pytest-dev/pytest-cov@v4.1.0...v5.0.0)

---
updated-dependencies:
- dependency-name: pytest-cov
  dependency-type: direct:production
...

Signed-off-by: dependabot[bot] <support@github.com>
Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants