Aki Sasaki (not active) Reporter
	Description • 7 years ago

+++ This bug was initially created as a clone of Bug #1330837 +++

We upgraded from Mercurial 3.7.3 to 3.9.1 in Sep/Oct 2016 (bug 1298976) but the tools tests still use 3.7.3. See tox.ini in the base of tools for where we specify 3.7.3.  We then upgraded to 4.1.2 on TC but not buildbot in April 2017.

We'll have to fix this:

23) ERROR: testApplyAndPushRebaseFails (mozilla_buildtools.test.test_util_hg.TestHg)

   Traceback (most recent call last):
    lib/python/mozilla_buildtools/test/test_util_hg.py line 660 in testApplyAndPushRebaseFails
      lambda r, a: c(r, a, self.repodir), max_attempts=3)
    lib/python/util/hg.py line 564 in apply_and_push
      raise HgUtilError("Failed to push")
   HgUtilError: Failed to push
   -------------------- >> begin captured logging << --------------------
   util.commands: INFO: command: START
   util.commands: INFO: command: /Users/nthomas/source/hgmo/build/tools/lib/python/mozilla_buildtools/test/init_hgrepo.sh /var/folders/gr/f_63bw8j6jx1kbs37gfsvhf00000gn/T/tmplsLVK5/repo
   util.commands: INFO: command: cwd: /private/var/folders/gr/f_63bw8j6jx1kbs37gfsvhf00000gn/T/tmplsLVK5
   util.commands: INFO: command: output:
   util.commands: INFO: command: END (1.00s elapsed)

   util.commands: INFO: command: START
   util.commands: INFO: command: hg log -R /var/folders/gr/f_63bw8j6jx1kbs37gfsvhf00000gn/T/tmplsLVK5/repo --template {node|short}

   util.commands: INFO: command: cwd: /private/var/folders/gr/f_63bw8j6jx1kbs37gfsvhf00000gn/T/tmplsLVK5
   util.commands: DEBUG: Process returned 0
   util.commands: INFO: command: END (0.25s elapsed)

   util.commands: INFO: command: output:
   util.commands: INFO: d9647854da5c
   708108b19859
   f9129973d36c
   f99e43af0df3

   redo: DEBUG: attempt 1/2
   util.commands: INFO: command: START
   util.commands: INFO: command: hg clone --traceback /var/folders/gr/f_63bw8j6jx1kbs37gfsvhf00000gn/T/tmplsLVK5/repo /var/folders/gr/f_63bw8j6jx1kbs37gfsvhf00000gn/T/tmplsLVK5/wc
   util.commands: INFO: command: cwd: /private/var/folders/gr/f_63bw8j6jx1kbs37gfsvhf00000gn/T/tmplsLVK5
   util.commands: INFO: command: env: {'HGPLAIN': '1'}
   util.commands: DEBUG: Process returned 0
   util.commands: INFO: command: END (0.12s elapsed)

   util.commands: INFO: command: output:
   util.commands: INFO: updating to branch default
   2 files updated, 0 files merged, 0 files removed, 0 files unresolved

   util.commands: INFO: command: START
   util.commands: INFO: command: hg branch
   util.commands: INFO: command: cwd: /var/folders/gr/f_63bw8j6jx1kbs37gfsvhf00000gn/T/tmplsLVK5/wc
   util.commands: INFO: command: env: {'HGPLAIN': '1'}
   util.commands: DEBUG: Process returned 0
   util.commands: INFO: command: END (0.09s elapsed)

   util.commands: INFO: command: output:
   util.commands: INFO: default

   util.commands: INFO: command: START
   util.commands: INFO: command: hg update -C
   util.commands: INFO: command: cwd: /var/folders/gr/f_63bw8j6jx1kbs37gfsvhf00000gn/T/tmplsLVK5/wc
   util.commands: INFO: command: output:
   util.commands: INFO: command: END (0.12s elapsed)

   util.commands: INFO: command: START
   util.commands: INFO: command: hg parent --template {node|short}
   util.commands: INFO: command: cwd: /var/folders/gr/f_63bw8j6jx1kbs37gfsvhf00000gn/T/tmplsLVK5/wc
   util.commands: INFO: command: env: {'HGPLAIN': '1'}
   util.commands: DEBUG: Process returned 0
   util.commands: INFO: command: END (0.10s elapsed)

   util.commands: INFO: command: output:
   util.commands: INFO: d9647854da5c
   util.commands: INFO: command: START
   util.commands: INFO: command: hg branch
   util.commands: INFO: command: cwd: /var/folders/gr/f_63bw8j6jx1kbs37gfsvhf00000gn/T/tmplsLVK5/wc
   util.commands: INFO: command: env: {'HGPLAIN': '1'}
   util.commands: DEBUG: Process returned 0
   util.commands: INFO: command: END (0.09s elapsed)

   util.commands: INFO: command: output:
   util.commands: INFO: default

   util.commands: INFO: command: START
   util.commands: INFO: command: hg tag -f TEST
   util.commands: INFO: command: cwd: /var/folders/gr/f_63bw8j6jx1kbs37gfsvhf00000gn/T/tmplsLVK5/wc
   util.commands: INFO: command: output:
   util.commands: INFO: command: END (0.14s elapsed)

   util.commands: INFO: command: START
   util.commands: INFO: command: hg tag -f CONFLICTING_TAG
   util.commands: INFO: command: cwd: /var/folders/gr/f_63bw8j6jx1kbs37gfsvhf00000gn/T/tmplsLVK5/repo
   util.commands: INFO: command: output:
   util.commands: INFO: command: END (0.14s elapsed)

   util.commands: INFO: command: START
   util.commands: INFO: command: hg -q out --template "{node} {branches}
   " /var/folders/gr/f_63bw8j6jx1kbs37gfsvhf00000gn/T/tmplsLVK5/repo
   util.commands: INFO: command: cwd: /var/folders/gr/f_63bw8j6jx1kbs37gfsvhf00000gn/T/tmplsLVK5/wc
   util.commands: INFO: command: env: {'HGPLAIN': '1'}
   util.commands: DEBUG: Process returned 0
   util.commands: INFO: command: END (0.10s elapsed)

   util.commands: INFO: command: output:
   util.commands: INFO: e3d64a40f316ba041c7ed41e09d0b5da4813704e

   util.commands: INFO: command: START
   util.commands: INFO: command: hg push --traceback --new-branch /var/folders/gr/f_63bw8j6jx1kbs37gfsvhf00000gn/T/tmplsLVK5/repo
   util.commands: INFO: command: cwd: /var/folders/gr/f_63bw8j6jx1kbs37gfsvhf00000gn/T/tmplsLVK5/wc
   util.commands: INFO: command: output:
   util.commands: INFO: command: ERROR
   Traceback (most recent call last):
     File "/Users/nthomas/source/hgmo/build/tools/lib/python/util/commands.py", line 52, in run_cmd
       return subprocess.check_call(cmd, **kwargs)
     File "/usr/local/Cellar/python/2.7.11/Frameworks/Python.framework/Versions/2.7/lib/python2.7/subprocess.py", line 540, in check_call
       raise CalledProcessError(retcode, cmd)
   CalledProcessError: Command '['hg', 'push', '--traceback', '--new-branch', '/var/folders/gr/f_63bw8j6jx1kbs37gfsvhf00000gn/T/tmplsLVK5/repo']' returned non-zero exit status 255
   util.commands: INFO: command: END (0.13s elapsed)

   util.hg: DEBUG: Hit error when trying to push: Command '['hg', 'push', '--traceback', '--new-branch', '/var/folders/gr/f_63bw8j6jx1kbs37gfsvhf00000gn/T/tmplsLVK5/repo']' returned non-zero exit status 255

	Alin Selagea [:aselagea]
	Comment 1 • 7 years ago

I took Callek's suggestion and forked the Github version of the tools repo, enabled travis for it and then updated the environment configs so that it uses hg 4.1.2. When I pushed my changes, I noticed the same error as mentioned above.

util.hg: DEBUG: Hit error when trying to push: Command '['hg', 'push', '--traceback', '--new-branch', '/dev/shm/tmp6H4JZi/repo']' returned non-zero exit status 255

That seems to be coming from here:
https://hg.mozilla.org/build/tools/file/tip/lib/python/util/hg.py#l558

I've tried some hacks, but my mercurial knowledge is not enough to find a fix too easily and I'd prefer not spending so much time on this one.

@Callek: do you have any suggestions/pointers here?

	Justin Wood (:Callek)
	Comment 2 • 7 years ago

Firstly, sadly, dxr doesn't match so I just wasted 15-20 minutes trying to figure out why the code looked this way (https://dxr.mozilla.org/build-central/source/tools/lib/python/mozilla_buildtools/test/test_util_hg.py#515)

I'm still looking but :gps may know something offhand.

This is also broken in Hg 3.9 I'm told.

	Justin Wood (:Callek)
	Comment 3 • 7 years ago

So looking at it, I see us get to:

https://dxr.mozilla.org/build-central/source/tools/lib/python/util/hg.py#558

And then ... nothing...

I'm not sure why that is, I'd expect us to pull and attempt a rebase, but no further output to indicate as much. (based on c#0)

Looking deeper I see a full log at https://travis-ci.org/AlinSelagea/build-tools/builds/224312988

Where the real error we're hitting seems to be:

util.commands: INFO: command: ERROR
  Traceback (most recent call last):
    File "/home/travis/build/AlinSelagea/build-tools/lib/python/util/commands.py", line 52, in run_cmd
      return subprocess.check_call(cmd, **kwargs)
    File "/opt/python/2.7.9/lib/python2.7/subprocess.py", line 540, in check_call
      raise CalledProcessError(retcode, cmd)
  CalledProcessError: Command '['hg', '--config', 'ui.merge=internal:merge', 'rebase']' returned non-zero exit status 1
  util.commands: INFO: command: END (0.11s elapsed)
  util.hg: DEBUG: Failed to rebase: Command '['hg', '--config', 'ui.merge=internal:merge', 'rebase']' returned non-zero exit status 1

	Gregory Szorc [:gps]
	Comment 4 • 7 years ago

`hg rebase` without specifying -s/-b and -d is dangerous. Recent versions of Mercurial changed behavior to not allow some ambiguous intents to be performed automatically. My guess is that is what this test is running into.

The underlying code is buggy: at least the -d argument should be specified when invoking `hg rebase`.

	Alin Selagea [:aselagea]
	Comment 5 • 7 years ago

Attaching the full log for the failure.

I don't think the problem is related to the rebase step. As I see it, it's *expected* that the first 2 push attempts will fail since we have a conflicting tag being added to the latest commit in the remote repo. That will result in a merge conflict.

e.g:
hg --config ui.merge=internal:merge rebase
rebasing 5:fd53373f06db "Added tag TEST for changeset 801a3ce489d0"
merging .hgtags
warning: conflicts while merging .hgtags! (edit, then use 'hg resolve --mark')
unresolved conflicts (see hg resolve, then hg rebase --continue)

But that tag is not added for the third attempt. [1]

The problem I'm seeing here is that when we do a "hg -q out <remote repo>" to see what changes are present in the working repo but missing in the remote one, we always get the same commit revision: e3d64a40f316ba041c7ed41e09d0b5da4813704e

Even though we do a "hg --config extensions.mq= strip --no-backup e3d64a40f316ba041c7ed41e09d0b5da4813704e" twice in the current repo, the commit shown when we run "hg -q out" each time is the same.

Moreover, when Nick filed bug 1330837 to update these tests to hg 3.9.1 four months ago, he noticed the same failure and interestingly, the revision is the same in his case too. [2]

Could we hit some sort of caching issue? 

[1] https://dxr.mozilla.org/build-central/source/tools/lib/python/mozilla_buildtools/test/test_util_hg.py#657-658
[2] https://bugzilla.mozilla.org/show_bug.cgi?id=1330837#c0

	Alin Selagea [:aselagea]
	Comment 6 • 7 years ago

@gps: I wonder if you had a chance to take a look at this.

	Gregory Szorc [:gps]
	Comment 7 • 7 years ago

It isn't obvious from the logs what is going on. I'd need to step through it locally most likely. But I'm pretty busy and don't have many cycles right now. So needinfo me if you absolutely need me to take a look at this.

	Alin Selagea [:aselagea]
	Comment 8 • 6 years ago

Just as an fyi, it seems the same error occurs when testing with hg 4.3.1 and 4.4.1.

	Firefox Bug Husbandry Bot
	Comment 9 • 6 years ago

Bulk change of QA Contact to :jlund, per https://bugzilla.mozilla.org/show_bug.cgi?id=1428483

	Danut Labici [:dlabici] Assignee
	Comment 10 • 6 years ago

Hello I'm looking at this bug and I wonder how I can test this locally, on which repo does it happen?
Are we locked to hg4.1? I see on 4.2 and 4.3 received some rebase changes that might actually fix this, without needing any code/logic changes.

	Aki Sasaki (not active) Reporter
	Comment 11 • 6 years ago

The repo is https://hg.mozilla.org/build/tools , which gets synced to https://github.com/mozilla/build-tools .