Keep ReviewRequest timestamps in sync with Reviews and DiffSets
Review Request #8800 — Created March 7, 2017 and submitted
When publishing a
Review
, we let theReviewRequest
compute its own
last updated time, which ends up being mere milliseconds after
Review.timestamp
, which makes it always appear that the review request
is always the last updated object returned by
ReviewRequest.get_last_activity()
. The same is true forDiffSet
s
during publishing of review requests -- their timestamp is always
behind.We now force the timestamp of
ReviewRequest
to be in sync with
Review.timestamp
when publishing a review andDiffSet.timestamp
when
publishing a review request that contains a new diff. With in-sync
timestamps,ReviewRequest.get_last_activity()
now returns the correct
models.Co-authored-by: Anni Cao anni@sfu.ca.
Ran unit tests.
Built the docs and went through them.
Manually verified the following before applying the patch
(via./reviewboard/manage.py shell
):
ReviewRequest.get_last_activity()
returns the review request
after a review is published.ReviewRequest.get_last_activity()
returns the review request
after a revision with a diffset is published.
After applying the patch this is no longer the case.
Description | From | Last Updated |
---|---|---|
You should also add a unit test to ensure that saving a review results in the proper timestamps on the … |
chipx86 | |
This change is going to appear to fix the bug most of the time, but it will only appear that … |
chipx86 | |
Prior to this change, it was possible to call draft.publish() and have it kinda sorta do the right thing. It … |
chipx86 | |
Can you detail what manual testing you did to verify bug 3445? |
david | |
Why is the scmtools fixture needed, out of curiosity? |
mike_conley | |
Instead of converting all of these to a string and then comparing strings, how about just squashing out the microseconds … |
david | |
In the changes above, you are setting timestamp = diffset_timestamp and timestamp = review_timestamp but you never end up setting … |
szhang | |
There should be one of these per update type/result, rather than one big test. That way, if one part of … |
chipx86 | |
I'm a little confused. I wrote the following but later noticed that you have unit tests written and you said … |
szhang | |
I think your test could use a better name here. Perhaps something more specific like test_sync_of_review_timestamp_and_review_request_last_updated? |
szhang | |
Why are you checking this twice? |
szhang | |
You might want to put this into its own unit test. |
szhang | |
F401 'django.utils.six' imported but unused |
reviewbot | |
F401 'reviewboard.diffviewer.differ.DiffCompatVersion' imported but unused |
reviewbot | |
F401 'django.utils.six' imported but unused |
reviewbot | |
F821 undefined name 'timezone' |
reviewbot | |
Blank line before comment blocks. |
chipx86 | |
So I think what I'd like to see actually is a change to ModificationTimestampField that prevents overriding custom values. It … |
chipx86 | |
Needs to be the full module path. |
chipx86 | |
This sentence seems off. |
chipx86 | |
This may not link correctly now. |
chipx86 | |
Needs to be the full module path. |
chipx86 | |
This can be grouped together. |
chipx86 | |
Group together. |
chipx86 | |
Group together. |
chipx86 | |
This seeems... unrelated |
david | |
Needs a period. |
david | |
Do we still want to do this? Does the modification timestamp work fix this? If not, the comment above needs … |
chipx86 | |
This should be undone. The order was right before. |
chipx86 | |
, optional |
chipx86 |
-
Tool: Pyflakes Processed Files: reviewboard/reviews/tests/test_review_request.py reviewboard/reviews/models/review_request.py Tool: PEP8 Style Checker Processed Files: reviewboard/reviews/tests/test_review_request.py reviewboard/reviews/models/review_request.py
-
For a bit of background,
ReviewRequest.get_last_activity()
is actually used inreview_details()
inreviewboard/reviews/views.py
. So, I am trying to understand the reasoning behind the changes.Some more detail about the changes would be appreciated in the description. Why are the changes required?
Correct me if I am wrong--are this changes required because the comparison of timestamps (eg. on line 505 and 517 of the original file) is not working? Thus, you're using string comparisons instead?
-
In the changes above, you are setting
timestamp = diffset_timestamp
and
timestamp = review_timestamp
but you never end up setting
server_timestamp
, which should hold the timestamp of the latest activity of the review request.Right now,
server_timestamp
will always be set toself.last_updated
regardless of whether there is a new diffset or review newer thanself.last_updated
.
- Description:
-
~ When calling ReviewRequest.get_last_activity() always return the ReviewRequest itself.
~ When calling ReviewRequest.get_last_activity() always return the ReviewRequest itself. The bug is caused due to timestamp discrepancy between ReviewRequest.last_updated and review.timestamp. There is a minor difference in millisecond between these two timestamp although they are logically supposed to be same. I use strftime() to trim the millisecond part of both timestamps to remove the discrepancy.
After change, ReviewRequest.get_last_activity() returns the last update activity for a review request.
-
-
Instead of converting all of these to a string and then comparing strings, how about just squashing out the microseconds part of the datetimes?
timestamp = server_timestamp.replace(microsecond=0) ... diffset_timestamp = diffset.timestamp.replace(microsecond=0) if diffset_timestamp >= timestamp: ...
This should be faster and more conceptually correct than comparing string representations.
-
Tool: Pyflakes Processed Files: reviewboard/reviews/tests/test_review_request.py reviewboard/reviews/models/review_request.py Tool: PEP8 Style Checker Processed Files: reviewboard/reviews/tests/test_review_request.py reviewboard/reviews/models/review_request.py
- Description:
-
~ When calling ReviewRequest.get_last_activity() always return the ReviewRequest itself. The bug is caused due to timestamp discrepancy between ReviewRequest.last_updated and review.timestamp. There is a minor difference in millisecond between these two timestamp although they are logically supposed to be same. I use strftime() to trim the millisecond part of both timestamps to remove the discrepancy.
~ When calling ReviewRequest.get_last_activity() always return the ReviewRequest itself. The bug is caused due to timestamp discrepancy between ReviewRequest.last_updated and review.timestamp. There is a minor difference in millisecond between these two timestamp although they are logically supposed to be same. I use replace(microsecond=0) to trim the microsecond part of both timestamps to remove the discrepancy.
After change, ReviewRequest.get_last_activity() returns the last update activity for a review request.
- Description:
-
~ When calling ReviewRequest.get_last_activity() always return the ReviewRequest itself. The bug is caused due to timestamp discrepancy between ReviewRequest.last_updated and review.timestamp. There is a minor difference in millisecond between these two timestamp although they are logically supposed to be same. I use replace(microsecond=0) to trim the microsecond part of both timestamps to remove the discrepancy.
~ ReviewRequest.get_last_activity() always returns the ReviewRequest itself. The bug is caused by timestamp discrepancy between ReviewRequest.last_updated and review.timestamp. There is a minor difference in millisecond between these two timestamps although they are logically supposed to be same. I use replace(microsecond=0) to trim the microsecond part of the timestamps to remove the discrepancy.
After change, ReviewRequest.get_last_activity() returns the last update activity for a review request.
-
-
You should also add a unit test to ensure that saving a review results in the proper timestamps on the review request.
-
This change is going to appear to fix the bug most of the time, but it will only appear that way. In practice, it's still broken.
What this change is doing is compensating for the case where
review.timestamp
's microsecond is, say, 100000, andreview_request.last_updated
is, say, 100001, and is a result of the review being saved. We're knocking the microseconds down to 0 so the review wins (and it wins because the review request's timestamp is the fallback, in the event that any other is newer or equal).I say it only appears to fix it because there are still two cases where things will go wrong (one that is just a manifestation of the current bug, and another that is introduced by this change).
1) If
review.timestamp
is 999999 (or thereabouts) andreview_request.last_updated
is 1, the review request will still win. It's the same problem as before, but the difference isn't contained within a microsecond range of 0-999999. It overlapped into the next second. We'd have to then chase this into the seconds, knocking those to 0, but I think you'll agree that opens the door easily to false positives.
2) It's possible that the review request is newer than the review. If the review was posted at microsecond=1, and the review request was updated by another user at microsecond=999999, the review request should win! This is the same problem as the seconds issue I describe above, but in a smaller window of time (but on a busy server, this isn't unlikely).This change is what we call a "bandaid." It's trying to address the symptom of the problem without solving the core issue. If you get cut by sharp splinter of wood every time you open a drawer, a bandaid might keep blood from a cut on your finger from dripping, but it doesn't do anything to prevent that splinter from cutting you or someone else next time. Ideally, it's best to solve that core problem so the bandaid isn't ever necessary.
What's really happening with this bug is that, at some point, we publish a review with a timestamp of "now," and then when we save the review request, we allow it to re-calculate what "now" is. What we probably should be doing is forcing the two to be in sync.
Here's where this is happening, in
Review.publish
:# Update the last_updated timestamp and the last review activity # timestamp on the review request. self.review_request.last_review_activity_timestamp = self.timestamp self.review_request.save( update_fields=['last_review_activity_timestamp', 'last_updated'])
last_updated
is a special field that, left to its own devices, will update itself to "now" on save. You can see this code indjblets/db/fields.py
(ModificationTimestampField
). What needs to happen is we need to actually setlast_updated
the same way we're settinglast_review_activity_timestamp
, so the two are in sync, and bypassModificationTimestampField
's special settings of this.The good news is, it's really easy to bypass the special "pre-save" logic that
ModificationTimestampField
is doing that's causing it to set the latest timestamp. We can usesave_base(raw=True, ...)
instead ofsave(...)
.Model.save()
does some special stuff to prepare a model for saving, andReviewRequest.save()
does some other special stuff. In this case, though, none of that special stuff matters, at all. We're only changing two timestamps, and this is safe and reliable and simple. So you can do:self.review_request.last_updated = self.timestamp self.review_request.save( raw=True, update_fields=[...])
With that, you shouldn't need any of the bandaids to adjust microseconds, and it should be reliable every time (unless of course some signal handler intercepts the save and makes other modifications, but we can't do anything about that really).
Give that a try and adjust the unit tests, and see if you can make the problem go away.
-
There should be one of these per update type/result, rather than one big test. That way, if one part of all this regresses later, it'll help in diagnosing things.
You're also going to want to manually insert timestamps for the review and review request in these tests. (The
create_*
methods you use here, which live inreviewboard/testing/testcase.py
, will need to be updated to optionally takelast_updated
values). Unit tests that test timestamps without explicitly defining them often lead to their own time precision bugs.
-
Tool: Pyflakes Processed Files: reviewboard/reviews/tests/test_review.py reviewboard/reviews/tests/test_review_request.py reviewboard/reviews/models/review.py reviewboard/reviews/models/review_request_draft.py reviewboard/reviews/models/review_request.py Tool: PEP8 Style Checker Processed Files: reviewboard/reviews/tests/test_review.py reviewboard/reviews/tests/test_review_request.py reviewboard/reviews/models/review.py reviewboard/reviews/models/review_request_draft.py reviewboard/reviews/models/review_request.py
- Description:
-
~ ReviewRequest.get_last_activity() always returns the ReviewRequest itself. The bug is caused by timestamp discrepancy between ReviewRequest.last_updated and review.timestamp. There is a minor difference in millisecond between these two timestamps although they are logically supposed to be same. I use replace(microsecond=0) to trim the microsecond part of the timestamps to remove the discrepancy.
~ ReviewRequest.get_last_activity() always returns the ReviewRequest itself. The bug is caused by timestamp discrepancy between ReviewRequest.last_updated and review.timestamp. There is a minor difference in millisecond between these two timestamps although they are logically supposed to be same. What's really happening is that, when we publish/save an update with a timestamp of "now," and then when we save the review request, we allow it to re-calculate what "now" is. The fix should be forcing the two to be in sync.
After change, ReviewRequest.get_last_activity() returns the last update activity for a review request.
-
-
I'm a little confused. I wrote the following but later noticed that you have unit tests written and you said that they passed. Is this because
last_updated
is updated somewhere else?"In the docstring, you should be returning 'the last object updated, along with the timestamp of that object'.
On this line, you are returning
server_timestamp
and it is still assigned toself.last_updated
." -
I think your test could use a better name here. Perhaps something more specific like
test_sync_of_review_timestamp_and_review_request_last_updated
? -
-
- Change Summary:
-
Cleanups to Anni's patch.
- Summary:
-
Fix ReviewRequest.get_last_activity() to return the last update activity for a review requestKeep ReviewRequest timestamps in sync with Reviews and DiffSets
- Description:
-
~ ReviewRequest.get_last_activity() always returns the ReviewRequest itself. The bug is caused by timestamp discrepancy between ReviewRequest.last_updated and review.timestamp. There is a minor difference in millisecond between these two timestamps although they are logically supposed to be same. What's really happening is that, when we publish/save an update with a timestamp of "now," and then when we save the review request, we allow it to re-calculate what "now" is. The fix should be forcing the two to be in sync.
~ After change, ReviewRequest.get_last_activity() returns the last update activity for a review request. ~ When publishing a
Review
, we let theReviewRequest
compute its own~ last updated time, which ends up being mere milliseconds after + Review.timestamp
, which makes it always appear that the review request+ is always the last updated object returned by + ReviewRequest.get_last_activity()
. The same is true forDiffSet
s+ during publishing of review requests -- their timestamp is always + behind. + + We now force the timestamp of
ReviewRequest
to be in sync with+ Review.timestamp
when publishing a review andDiffSet.timestamp
when+ publishing a review request that contains a new diff. With in-sync + timestamps, ReviewRequest.get_last_activity()
now returns the correct+ models. + + Additionally, while I was updating
ReviewRequestDraft.publish
, I+ removed the send_notification
parameter that was unused except by+ ReviewRequest.publish
. Now onlyReviewRequest
will emit the+ review_request_published
singal.+ + The majority of this change was contributed by Anni Cao anni@sfu.ca.
- Testing Done:
-
~ Unit tests for following update type have been added and passed in ReviewRequestTests:
~ Ran unit tests.
- - Reviews - - Diffsets - - ChangeDescription - Commit:
-
2b7aac36d92e86980a0f71b0b1e26178bddfb4c19ea37fb4e466bb924178744bbfcc756c1194427d
- Change Summary:
-
flake8
- Commit:
-
9ea37fb4e466bb924178744bbfcc756c1194427dca44a255a218795f6ba5917406fd2d267c71404a
- Commit:
-
ca44a255a218795f6ba5917406fd2d267c71404a3a7630df0e57597b0326a310df1fe3edf9dfd786
Checks run (2 succeeded)
-
-
Prior to this change, it was possible to call
draft.publish()
and have it kinda sorta do the right thing. It wasn't consistent, though, and posed a problem. Looking through the test suite, we have places where we're publishing the draft, and not the review request. If we're going to change any semantics and function arguments in this change, I'd like to address this once and for all.I think what we should do is rename the existing
publish()
on drafts to something likeapply_changes()
. We may then want adraft.publish()
that in turn callsreview_request.publish()
and returns the change description (matching the existing return type for the method).This would help clarify what the publishing logic on the draft does, and help avoid problems if code (including existing extension code out in the wild) calls the wrong publish method.
-
-
So I think what I'd like to see actually is a change to
ModificationTimestampField
that prevents overriding custom values. It would entail tracking the loaded value and seeing if a new, explicit value was set. If so, it wouldn't override.This would also let us avoid calling
save()
and thensave_base()
, reducing the number of database writes and avoiding incorrect state if something looks up the row in-between these writes. -
-
-
-
-
-
-
- Description:
-
When publishing a
Review
, we let theReviewRequest
compute its ownlast updated time, which ends up being mere milliseconds after Review.timestamp
, which makes it always appear that the review requestis always the last updated object returned by ReviewRequest.get_last_activity()
. The same is true forDiffSet
sduring publishing of review requests -- their timestamp is always behind. We now force the timestamp of
ReviewRequest
to be in sync withReview.timestamp
when publishing a review andDiffSet.timestamp
whenpublishing a review request that contains a new diff. With in-sync timestamps, ReviewRequest.get_last_activity()
now returns the correctmodels. - Additionally, while I was updating
ReviewRequestDraft.publish
, I- removed the send_notification
parameter that was unused except by- ReviewRequest.publish
. Now onlyReviewRequest
will emit the- review_request_published
singal.- The majority of this change was contributed by Anni Cao anni@sfu.ca.
- Testing Done:
-
Ran unit tests.
+ + Built the docs and went through them.
- Depends On:
-
- Commit:
3a7630df0e57597b0326a310df1fe3edf9dfd786a2ebba1c90fec9cf3f840dbf9b5f5cb10af083ef- Diff:
Revision 8 (+143 -20)
Checks run (2 succeeded)
flake8 passed.JSHint passed.
- Testing Done:
-
Ran unit tests.
Built the docs and went through them.
+ + Manually verified the following before applying the patch
+ (via ./reviewboard/manage.py shell
):+ + ReviewRequest.get_last_activity()
returns the review request
after a review is published.
+ ReviewRequest.get_last_activity()
returns the review request
after a revision with a diffset is published.
+ + After applying the patch this is no longer the case.
- Commit:
-
a2ebba1c90fec9cf3f840dbf9b5f5cb10af083ef98bbedf0088c3b8e52e3bd9fd8c0a31435651db4
Checks run (2 succeeded)
- Change Summary:
-
Rebase on 3.0, addressed feedback
- Branch:
-
release-2.5.xrelease-3.0.x
- Commit:
-
98bbedf0088c3b8e52e3bd9fd8c0a31435651db4e6c24fce82b2a75131d404a9efef2e46808a5d42
Checks run (2 succeeded)
- Change Summary:
-
Addressed Christian's feedback.
- Commit:
-
e6c24fce82b2a75131d404a9efef2e46808a5d42fa23ae9c3b6fadeae1735312c000e36b94b8388d
Checks run (2 succeeded)
- Description:
-
When publishing a
Review
, we let theReviewRequest
compute its ownlast updated time, which ends up being mere milliseconds after Review.timestamp
, which makes it always appear that the review requestis always the last updated object returned by ReviewRequest.get_last_activity()
. The same is true forDiffSet
sduring publishing of review requests -- their timestamp is always behind. We now force the timestamp of
ReviewRequest
to be in sync withReview.timestamp
when publishing a review andDiffSet.timestamp
whenpublishing a review request that contains a new diff. With in-sync timestamps, ReviewRequest.get_last_activity()
now returns the correctmodels. ~ The majority of this change was contributed by Anni Cao anni@sfu.ca.
~ Co-authored-by: Anni Cao anni@sfu.ca.