-
Notifications
You must be signed in to change notification settings - Fork 19
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
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
ddneilson
force-pushed
the
ddneilson/13998
branch
from
November 8, 2023 21:01
16cd208
to
0a0c539
Compare
epmog
approved these changes
Nov 8, 2023
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
force-pushed
the
ddneilson/13998
branch
from
November 8, 2023 21:06
0a0c539
to
90053b0
Compare
gmchale79
approved these changes
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>
Closed
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
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
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:
The full log shows:
The session action details are:
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