1509181 - GitHub pushes should be ordered by push time, not author time of the head commit

Status: VERIFIED FIXED

(Tree Management :: Treeherder: Data Ingestion, defect, P1)

Description

[Simon Sapin (:SimonSapin)]

Git commits contain two timestamps: the "author" one and the "committer" one. They are often the same, but some operations like amending or rebasing reset the former without resetting the latter.

Currently, when reading Pulse messages about GitHub pushes, Treeherder takes the author time of the head commit as the push time:

https://github.com/mozilla/treeherder/blob/2ab03506086961ac51d9732f1e5c45fd532f2eae/treeherder/etl/push_loader.py#L96-L97
> "push_timestamp": to_timestamp(head_commit["commit"]["author"]["date"]),

This time is then used for sorting pushes in the UI. It’s really easy to get in a situation where an earlier push incorrectly gets sorted first, because it contains a commit authored later. Multiple push of the same (amended) commit can get the same timestamp, I’m not sure how they’re sorted in that case.

Using the committer date/timestamp instead would be an improvement, but a marginal one. What we really want is when the push operation was made. Unfortunately, as far as I understand that information is not part of the GitHub web hook payload that Taskcluster-GitHub integration reads in order to write the Pulse messages that Treeherder reads.

It is however present in the List Repository Events API:

    https://developer.github.com/v3/activity/events/#list-repository-events

Treeherder could do the Python equivalent of:

  $ curl -s https://api.github.com/repos/servo/servo/events \
    | jq '.|map(select(
      .type=="PushEvent" and
      .payload.before=="2b410acbf989e648fda450979962e9dc57c1ee48" and
      .payload.head=="2d5c6d8863dc060db74ff2081b58d9206cec9f29" and
      .payload.ref=="refs/heads/auto"
    ))[0].created_at'
  "2018-11-21T19:09:43Z"

I can work on a patch, but first: does this sound like the right idea?

An alternative might be to use the current date when processing the Pulse message.

Comment 1

[Simon Sapin (:SimonSapin)]

> Git commits contain two timestamps: the "author" one and the "committer" one. They are often the same, but some operations like amending or rebasing reset the former without resetting the latter.

I swapped former and latter here, of course. Amending resets the committer time (and name).

Comment 2

[Cameron Dawson [:camd]]

N-i myself so I can take a look in just a bit.

Comment 3

[Cameron Dawson [:camd]]

Yeah, this sounds very reasonable.  The place where we fetch the github push data is here: https://github.com/mozilla/treeherder/blob/master/treeherder/etl/push_loader.py#L86

Sounds like you already knew that code location.  :)  Sounds like I just wasn't sure what the right "date" was at the time.

Comment 4

[GitHub Bugzilla PR Linker]

Attachment: Link to GitHub pull-request: https://github.com/mozilla/treeherder/pull/4320

Comment 5

[Johan Lorenzo [:jlorenzo]]

In bug 1533393, I enabled treeherder on a new GitHub repo[1]. I noticed the same problem as well.

For reference, this bug wasn't noticeable back in Firefox OS era[2] (which was one of the first supported git repository), because back then, GitHub didn't support "squash and merge" or "rebase and merge" operations.

[1] https://treeherder.mozilla.org/#/jobs?repo=reference-browser
[2] https://treeherder.mozilla.org/#/jobs?repo=gaia
[3] https://github.blog/2016-04-01-squash-your-commits/

Comment 6

[Tom Prince [:tomprince]]

Note that at least hg-git (which is what I use for git repos mostly), uses author time as committer time, so is going to break things either way (github PRs handle this poorly as well).

Comment 7

[Simon Sapin (:SimonSapin)]

The distinction between author time and committer time is not very relevant. Both can be different from the time of the push event, which is what yields the correct ordering.

I think merging v.s. rebasing or squashing is only relevant when doing so using GitHub’s web UI (as opposed to using the git push command), because in that case pushing to the target branch happens immediately after creating the merge commit.

Note that there is already a PR at https://github.com/mozilla/treeherder/pull/4320 that attempts to fix this, but it has a bug that still needs to be investigated. Anyone feel free to take over.

Comment 8

[Cameron Dawson [:camd]]

Getting these pushes to sort properly when they have identical datetimes is going to be tricky. Perhaps averaging the two times or something? We'd have to dig into that to find something that works. I just don't have any time to spare before the end of the quarter. I'd think we could hit this up in about 1 month.

Comment 9

[Simon Sapin (:SimonSapin)]

By averaging the two times, do you mean the head commit’s "author" and "committer" times? Why would averaging be useful? Neither of them timestamps is the time of push, which is what we actually want to sort by.

(It’s possible that two pushes occur within one second and so have the same timestamp, but that’s not what this bug is about. And: either at least one of them is a force-push so the “real” ordering is not that significant, or the second one needs to have fetched the first and and merged or rebased it, which given network and protocol overhead makes it unlikely that the whole thing will complete within one second.)

Again please see https://github.com/mozilla/treeherder/pull/4320 which already has a proposed fix (but might be buggy and needs some more testing).

Comment 11

[Dave Hunt [:davehunt] [he/him] ⌚BST]

This is affecting the performance results shown in Perfherder and on the health.graphics dashboards for Fenix. See bug 1555773 for more details. Do we have an update on the status of a fix?

Comment 12

[Simon Sapin (:SimonSapin)]

The status is that I have a pull request that tries to fix this, but it still needs work and I am not doing that at the moment. Anyone should feel free to pick it up again.

When it was deployed to the treeherder-prototype instance, some pushes were missing entirely. This might indicate a serious bug in the PR that still needs to be investigated.

Later I rebased (IIRC on top of an indentation style change in JSON files for test data) but broke something in the unit tests.

Comment 13

[Karl Thiessen [:kthiessen, he/him]]

Per comment 12, I'm de-assigning this so it shows up in my "Needs Owner" query for (re-)triage.

This is pretty much the first step for Treeherder in further Github integration (which is likely to be a 2019H2 goal, and will need its own meta-bug sooner rather than later.)

Comment 14

[Jordan Lund (:jlund)]

Joel confirmed they can tackle this in Q1

Comment 15

[Armen [:armenzg]]

Do any of you have any recent examples? (or old ones) Thanks!

Comment 16

[Simon Sapin (:SimonSapin)]

It’s easy to reproduce with git commit --amend and git push --force:

https://treeherder.mozilla.org/#/jobs?repo=servo-try currently shows https://treeherder.mozilla.org/#/jobs?repo=servo-try&revision=d3fc617de67fc19101ae624914e8dae92f7c8ef0 as the "latest" push, followed by https://treeherder.mozilla.org/#/jobs?repo=servo-try&revision=689c6596b8ba6068d2611e215a86fb0d72065533. But they were actually pushed in the reverse order. They have the same author date on their respective head commits, so I don’t know how ordering "ties" are broken.

Comment 17

[Armen [:armenzg]]

Attachment: Github pushes out of order

For the curious, you can see the pushes out of order in that screenshot.

Comment 18

[GitHub Bugzilla PR Linker]

Attachment: Link to GitHub pull-request: https://github.com/mozilla/treeherder/pull/6019

Comment 19

[Armen [:armenzg]]

Attachment: [screenshot] Production ingested pushes (inverted order) and localhost ingestion (correct order)

This shows that the code changes are ingesting the pushes correctly.

Comment 20

[Armen [:armenzg]]

Attachment: [screenshot] Fenix pushes in order

This is information I want to gather based on a chat between Simon and I.

Notice that the pushes shown in the first window and 2nd window are sorted in the same order. The code changes are working.

On the Github window, we notice that the 2nd commit says "2 days ago" while the 3rd one says "6 hours ago". This is because the 3rd commit was commited 6 hours ago, however, it got pushed to master at 09:02:13 while the 2nd one was commited 2 days ago but got pushed to master at 11:35:42.

If you load https://api.github.com/repos/mozilla-mobile/fenix/commits you will the push information there:

      "committer": {
        "name": "Jeff Boek",
        "email": "[e-mail]",
        "date": "2020-02-21T17:32:02Z" ---> 12:32:02 
      },
      "committer": {
        "name": "Sawyer Blatz",
        "email": "[e-mail]",
        "date": "2020-02-21T16:35:42Z" ---> 11:35:42
      },
      "committer": {
        "name": "GitHub",
        "email": "[e-mail]",
        "date": "2020-02-21T14:02:13Z" ---> 09:02:13
      },

This information is also found for individual commit information:
https://api.github.com/repos/mozilla-mobile/fenix/commits/0630e2482ff6a3d26015db7585ca3bb874c57ddd

Comment 21

[Armen [:armenzg]]

I'm surprised this bug did not get as much attention until now.

A push that landed today:
https://treeherder.mozilla.org/#/jobs?repo=fenix&revision=d918cfdf3841a17545053dca2e7480c648ab4f95
vs correct date/time:
https://treeherder-github-pushe-kb4y63.herokuapp.com/#/jobs?repo=fenix&revision=d918cfdf3841a17545053dca2e7480c648ab4f95

In any case, I'm going to ask for reviews.
If anyone is interested on testing the deployment you're welcome to. I'm satisfied with the results.

Comment 22

[Armen [:armenzg]]

I would like to deploy this tomorrow.

This means that all Treeherder Github pushes ingested from that point on will be properly sorted.
No push from the past will be corrected.

Does this need to be announced anywhere? Or are the people in this bug sufficient notification of a change on behaviour?

Comment 23

[Armen [:armenzg]]

In production.

Comment 24

[Armen [:armenzg]]

The Pulse ingestion is not handling well merge commits (I handled this well in the manual ingestion code). This started affecting the servo-try but it is not guaranteed it will stay like that. I reverted this.

The problem comes that it will ingest them as not having any associated revisions and the UI does not handle that.
From the API:

      {
            "id": 648555,
            "revision": "dae49435c2f3e18502c889a1f0b67194a797cb1a",
            "author": "[e-mail]",
            "revisions": [],
            "revision_count": 0,
            "push_timestamp": 1582575650,
            "repository_id": 99
        }

On stage I have removed the following pushes:

>>> Push.objects.filter(repository_id=99, revision="54015be6bf1a5c8195ec0842801455899cded111").delete()
(29, {'model.Commit': 0, 'model.TaskclusterMetadata': 4, 'model.JobDetail': 12, 'model.BugJobMap': 0, 'model.JobNote': 0, 'perf.PerformanceDatum': 0, 'model.JobLog': 4, 'model.TextLogStep': 4, 'model.Job': 4, 'model.Push': 1})
>>> Push.objects.filter(repository_id=99, revision="c9c5f8b9e545ae292d4ccb256758cb681a744612").delete()
(29, {'model.Commit': 0, 'model.TaskclusterMetadata': 4, 'model.JobDetail': 12, 'model.BugJobMap': 0, 'model.JobNote': 0, 'perf.PerformanceDatum': 0, 'model.JobLog': 4, 'model.TextLogStep': 4, 'model.Job': 4, 'model.Push': 1})
>>> Push.objects.filter(repository_id=99, revision="dae49435c2f3e18502c889a1f0b67194a797cb1a").delete()
(8, {'model.Commit': 0, 'model.TaskclusterMetadata': 1, 'model.JobDetail': 3, 'model.BugJobMap': 0, 'model.JobNote': 0, 'perf.PerformanceDatum': 0, 'model.JobLog': 1, 'model.TextLogStep': 1, 'model.Job': 1, 'model.Push': 1})

I've re-added them manually:

./manage.py ingest git-push -p servo-try -c 54015be6bf1a5c8195ec0842801455899cded111
./manage.py ingest git-push -p servo-try -c c9c5f8b9e545ae292d4ccb256758cb681a744612
./manage.py ingest git-push -p servo-try -c dae49435c2f3e18502c889a1f0b67194a797cb1a

On production I have removed the following pushes:

>>> Push.objects.filter(repository_id=99, revision="54015be6bf1a5c8195ec0842801455899cded111").delete()
(29, {'model.Commit': 0, 'model.TaskclusterMetadata': 4, 'model.JobDetail': 12, 'model.BugJobMap': 0, 'model.JobNote': 0, 'perf.PerformanceDatum': 0, 'model.JobLog': 4, 'model.TextLogStep': 4, 'model.Job': 4, 'model.Push': 1})

I could re-add the production push I removed but it will take some time to do so (on stage I was on a dyno with the old code).

Comment 25

[GitHub Bugzilla PR Linker]

Attachment: Link to GitHub pull-request: https://github.com/mozilla/treeherder/pull/6065

Comment 26

[Armen [:armenzg]]

The new PR is being able to ingest Github pushes:
https://treeherder-github-pushe-jg4o09.herokuapp.com/#/jobs?repo=servo-auto
https://treeherder-github-pushe-jg4o09.herokuapp.com/#/jobs?repo=servo-try
https://treeherder-github-pushe-jg4o09.herokuapp.com/#/jobs?repo=android-components

The PR is ready for review.

Fixing the manual ingestion code will follow up on a different PR.

Comment 27

[Armen [:armenzg]]

I have created a script that compares staging with the last 50 pushes for all Github projects I'm aware of. It also gives us links to the different instances for each differing push.

% ./misc/compare_pushes.py --projects android-components,fenix,reference-browser,servo-master,servo-auto,servo-try
Comparing android-components against production.
Comparing fenix against production.
Comparing reference-browser against production.
{"values_changed": {"root['push_timestamp']": {"new_value": 1582580346, "old_value": 1582581477}}}
https://treeherder.allizom.org/#/jobs?repo=reference-browser&revision=547a18b97534b237fa87bd22650f342836014c4e
https://treeherder.mozilla.org/#/jobs?repo=reference-browser&revision=547a18b97534b237fa87bd22650f342836014c4e
Comparing servo-master against production.
Comparing servo-auto against production.
Comparing servo-try against production.

Comment 28

[Armen [:armenzg]]

This is now deployed.
Please let me know if you notice any issues.

Comment 29

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Treeherder doesn't show the pushes in the commit order: Example: https://treeherder.mozilla.org/#/jobs?repo=fenix&group_state=expanded&resultStatus=testfailed%2Cbusted%2Cexception%2Cretry%2Cusercancel%2Crunnable&tochange=a4d93002a972125d34e0527ca5fa495265898999&fromchange=e2bfe8d0dba0374285a6e41eb69d6cd754cab8ae

The push in the center (7b170c4428d8016602aeef1750784a70684f56e5) is the fix for the debug failures of the top one (a4d93002a972125d34e0527ca5fa495265898999). And the one at the bottom (e2bfe8d0dba0374285a6e41eb69d6cd754cab8ae) got pushed between both according to Github.

Is Github also supposed to use the time when a commit got published on Github?

Comment 30

[Armen [:armenzg]]

Attachment: [screenshot] Fenix pushes out of order

This is just a screenshot of what Aryx is referring to. I will look into it.

Comment 31

[Armen [:armenzg]]

Attachment: PushEvent

[Commit 7b170c4](https://github.com/mozilla-mobile/fenix/commit/7b170c4428d8016602aeef1750784a70684f56e5) shows 10:44am EST (2020-03-04T15:44:29Z) as the time (what Treeherder shows) placing the push out of order.
If I load the associated [PR 8971](https://github.com/mozilla-mobile/fenix/pull/8971) I can see the time 12:40pm EST ("ekager merged 1 commit into mozilla-mobile:master from pocmo:intent-processor 21 hours ago") --> "2020-03-04T17:40:01Z".

This [pull API](https://api.github.com/repos/mozilla-mobile/fenix/pulls/8971) contains "updated_at": "2020-03-04T17:40:01Z".

I can correlate the commit to which PR it got merged in via the Sha or the title:
https://api.github.com/search/issues?q=7b170c4428d8016602aeef1750784a70684f56e5+repo:mozilla-mobile/fenix+type:pr
https://api.github.com/search/issues?q=Update%20IntentProcessor%20implementation%20to%20comply%20with%20new%20interface.+repo:mozilla-mobile/fenix+type:pr

Through both I can get to "2020-03-04T17:40:01Z"

This is similar to getting this information:
https://github.com/mozilla-mobile/fenix/branch_commits/7b170c4428d8016602aeef1750784a70684f56e5
except there's no REST API exposing it:
https://github.community/t5/GitHub-API-Development-and/How-to-get-all-branches-which-contain-a-commit-from-SHA-using/td-p/25006#


I've also attached a PushEvent related to it for documentation purposes.

Comment 32

[Armen [:armenzg]]

Attachment: PushEvent for 7b170c4428d8016602aeef1750784a70684f56e5 push

This is the actual PushEvent for master which contains the push time which is 1 second after the PR's merge time:

"created_at": "2020-03-04T17:40:02Z",

This might be the repository created_at field that comes via the Pulse message:
https://github.com/mozilla/treeherder/blob/master/tests/sample_data/pulse_consumer/github_push.json#L76

Comment 33

[Armen [:armenzg]]

Attachment: [screenshot] Fenix pushes (prod vs local vs Github)

I'm now looking at the commits API again.

I wonder if all we ever wanted from the beginning is the "commiter" date rather than "author" date:

"author": {
      "name": "Sebastian",
      "email": "[e-mail]",
      "date": "2020-03-04T15:44:29Z"
    },
    "committer": {
      "name": "Emily Kager",
      "email": "[e-mail]",
      "date": "2020-03-04T17:40:00Z"
    },

Sebastian authored the commits in the PR, however, Emily "merged/commited" the PR to master (which corresponds with the "push" time).

So far locally it works. It seems we have been having trouble with co-authored commits.

Comment 34

[Armen [:armenzg]]

Attachment: Link to GitHub pull-request: https://github.com/mozilla/treeherder/pull/6070

Comment 35

[Armen [:armenzg]]

I forgot to mention that the latest fix was deployed yesterday.

Comment 36

[Armen [:armenzg]]

Please let me know if anything does not work as expected.

The actual fix was to use the committer's date of the tipmost commit:

head_commit["commit"]["committer"]["date"]

instead of:

head_commit["commit"]["author"]["date"]

There's lots of information on the PR if anyone is curious.
Ingesting all pushes for a repo is as simple as ./manage.py ingest git-pushes -p <project_name>

Comment 37

[Simon Sapin (:SimonSapin)]

The committer dates of the respective head commits of two pushes are more likely than their author dates to be in the same order as the push dates (since git rebase overwrites committer dates by default) but they are still not the same as the push date. There can be any amount of time between making a commit and pushing it.

So while this is an improvement, it does not completely fix this bug. I don’t have a strong opinion on whether this is good enough.

Comment 38

[Tom Prince [:tomprince]]

I believe that if github squashes, or rebases, or creates a merge commit, the tip of the "push" should have a commit date that matches the push time. So I think the remaining issue is only if the pushes are made manually.