Bug 4801 - While merging, the "was merge successful?" prompts no longer appear in cmd.exe
Summary: While merging, the "was merge successful?" prompts no longer appear in cmd.exe
Status: RESOLVED FIXED
Alias: None
Product: Mercurial
Classification: Unclassified
Component: Mercurial (show other bugs)
Version: 3.6.2
Hardware: PC Windows
: urgent bug
Assignee: Bugzilla
URL: regression
Keywords: regression
Depends on:
Blocks:
 
Reported: 2015-08-28 12:35 UTC by Deanna Earley
Modified: 2016-05-19 00:00 UTC (History)
7 users (show)

See Also:
Python Version: ---


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Deanna Earley 2015-08-28 12:35 UTC
When performing a merge, and not changing the local version, mercurial normally prompts with "was merge successful (yn)?".
In hg 3.5+5 (in thg 3.5), the prompt is no longer visible, but it still waits for an answer.

P:\iCatcher\Console\Development>hg merge 6.1
merging .hgtags
merging Changelog.txt
merging Console/Console.res

 y
merging Console/Console.vbp

 y
merging Console/Feeds/Settings/Settings.cls
merging Node/Node.vbp

 y
merging Version.cs

 y
merging VidCap/VidCap.vbp

 y
10 files updated, 8 files merged, 0 files removed, 0 files unresolved
(branch merge, don't forget to commit)

P:\iCatcher\Console\Development>

If I disable the progress bar, then the prompts appear as normal:

P:\iCatcher\Console\Development>hg merge 6.1
merging .hgtags
merging Changelog.txt
merging Console/Console.res
 output file Console/Console.res appears unchanged
was merge successful (yn)? y
merging Console/Console.vbp
 output file Console/Console.vbp appears unchanged
was merge successful (yn)? y
merging Console/Feeds/Settings/Settings.cls
merging Node/Node.vbp
 output file Node/Node.vbp appears unchanged
was merge successful (yn)? y
merging Version.cs
 output file Version.cs appears unchanged
was merge successful (yn)? y
merging VidCap/VidCap.vbp
 output file VidCap/VidCap.vbp appears unchanged
was merge successful (yn)? y
10 files updated, 8 files merged, 0 files removed, 0 files unresolved
(branch merge, don't forget to commit)

P:\iCatcher\Console\Development>

This is running hg 3.5+5, thg 3.5 on Windows 7, in the normal command prompt.
Comment 1 Matt Mackall 2015-09-09 17:52 UTC
Adding a couple people who might know what's going on. Any chance you could bisect it?
Comment 2 Matt Harbison 2015-09-14 17:20 UTC
I can't recall ever seeing this prompt, but ran into what is probably the same thing.

$ hg merge --tool :local -r 76 -f
remote changed .hglf/[..]/iScsiConfig.jar which local deleted
use (c)hanged version or leave (d)eleted? d
largefile Components/[..]/ATTOiSCSI has a merge conflict
ancestor was e8262f35d750a16eb169dca34df6fb60d668a246
keep (l)ocal db2ae6ec770211151bc881340d24b18b5541b83d or
take (o)ther f14cb5470c91f96f2e28a042ef7c981669e0c557? l








getting changed largefiles
0 largefiles updated, 0 removed
2 files updated, 13 files merged, 0 files removed, 0 files unresolved
(branch merge, don't forget to commit)

There are two prompts in that whitespace.  In the working revisions where the prompts were present, what I guess are color codes printed out with the prompt instead of actual color (e.g. ←[0;33mkeep).  I did this in MinGW.

Interesting to note, when I bisected, the first revision it tested was 2ddfac2f163e, which also ate the keep local/take other prompt shown above.  Everything else bad showed that first one.


Bisected back to here after several tries:

The first bad revision is:
changeset:   24186:a78888d98606
user:        Gregory Szorc <gregory.szorc@gmail.com>
date:        Tue Feb 03 16:24:32 2015 -0800
summary:     color: be more conservative about setting ANSI mode on Windows (BC)
Comment 3 Pierre-Yves David 2015-09-14 17:51 UTC
This behavior is tight to the 'check' merge tools options.

See hg help config.merge-tools

(just throwing context in the pit here)
Comment 4 Gregory Szorc 2015-09-24 00:33 UTC
changeset:   32896:1818d4dca75c
user:        Matt Harbison <matt_harbison@yahoo.com>
date:        Tue Mar 31 14:27:45 2015 -0400
summary:     color: fix crash in cmd.exe

Is also related.

Strangely, the reporter is presumably using cmd.exe (the "normal command prompt" from comment #0). I would think that a78888d98606 without 1818d4dca75c would crash in cmd.exe per 1818d4dca75c's commit message?

Old behavior:

                w32effects    no w32effects
TERM set          ansi            ansi
TERM unset        win32           win32


New behavior:

                w32effects           no w32effects
TERM set           ansi if 'XTERM'       ansi
TERM unset         win32                 ansi


no w32effects + no TERM from the old behavior gets converted into no color from the code below:

  if realmode == 'win32':
        _terminfo_params = {}
        if not w32effects:
            modewarn()
            return None

So I guess the problem is we're attempting to use "ansi" from cmd.exe where we weren't attempting any color before in the case where w32effects isn't available?
Comment 5 Pierre-Yves David 2015-09-24 01:42 UTC
Adding regression and "urgent" as the title contains "no longer".
Comment 6 Deanna Earley 2015-09-24 07:46 UTC
To confirm, yes it is a Windows 7 cmd.exe.
Comment 7 Deanna Earley 2015-09-24 07:49 UTC
I'm also in the IRC channel as Anoia if anyone wants me to test anything.
Comment 8 Matt Harbison 2015-09-24 12:05 UTC
I can't explain it, but the problem is intermittent.  I'm unfamiliar with the underlying APIs, so I'm just throwing darts.

I applied this patch to send the text and escape sequences to a file, and reran the merge in comment #2 several times.  The first couple of times, all lines showed up properly.  The last time, I was missing the prompts as in comment #2, but a diff of the files generated says they are binary equal.  Since I commented out the console manipulation, I'm baffled.  FWIW, I also have progress enabled.

diff --git a/hgext/color.py b/hgext/color.py
--- a/hgext/color.py
+++ b/hgext/color.py
@@ -672,6 +676,10 @@ else:
         if not text.startswith('\033['):
             text = '\033[m' + text

+        fp = util.posixfile('e:/Projects/hg/raw_with_color.txt', mode='a')
+
+        fp.write('printing %s' % text)
+
         # Look for ANSI-like codes embedded in text
         m = re.match(ansire, text)

@@ -679,10 +687,15 @@ else:
             while m:
                 for sattr in m.group(1).split(';'):
                     if sattr:
+                        fp.write('set attr to %s\n' % sattr)
                         attr = mapcolor(int(sattr), attr)
-                _kernel32.SetConsoleTextAttribute(stdout, attr)
+                    else:
+                        fp.write('no color to set now\n')
+                #_kernel32.SetConsoleTextAttribute(stdout, attr)
+                fp.write('output: %s\n' % m.group(2))
                 orig(m.group(2), **opts)
                 m = re.match(ansire, m.group(3))
         finally:
             # Explicitly reset original attributes
-            _kernel32.SetConsoleTextAttribute(stdout, origattr)
+            #_kernel32.SetConsoleTextAttribute(stdout, origattr)
+            fp.close()
Comment 9 Pierre-Yves David 2015-09-24 12:39 UTC
progress is into core and on by default. Not sure how this is relevant.
Comment 10 Matt Harbison 2015-09-24 12:59 UTC
(In reply to Pierre-Yves David from comment #9)

True.  Some of the early tinkering I did, where I printed the debugging to screen instead of the file, left progress artifacts.  It worked consistently (say 10+ consecutive times) like that, though obviously the display wasn't pretty.  It seemed like a long shot, but I wasn't sure if resetting to the beginning of the line and printing over the progress bar instead of new line was the difference.
Comment 11 Bugzilla 2015-10-18 16:24 UTC
Bug marked urgent for 24 days, bumping
Comment 12 Bugzilla 2015-10-29 00:00 UTC
Bug marked urgent for 10 days, bumping
Comment 13 Bugzilla 2015-11-17 00:00 UTC
Bug marked urgent for 10 days, bumping
Comment 14 Bugzilla 2015-11-28 00:00 UTC
Bug marked urgent for 11 days, bumping
Comment 15 Bugzilla 2015-12-09 00:00 UTC
Bug marked urgent for 11 days, bumping
Comment 16 Deanna Earley 2015-12-16 07:58 UTC
FYI, I've just tried again doing (what I thought was) the same operation with 3.6.2 with mixed results:

P:\iCatcher\Console\Development>hg merge 2354
merging .hgtags
merging Changelog.txt
merging Console/Console.res
merging Console/Console.vbp
merging Console/Feeds/Settings/Settings.cls
merging Node/Node.vbp
merging Version.cs
merging VidCap/VidCap.vbp
 output file Changelog.txt appears unchanged
was merge successful (yn)? n
merging Changelog.txt failed!

 y

 y

 n
merging Node/Node.vbp failed!

 y

 y
10 files updated, 6 files merged, 0 files removed, 2 files unresolved
use 'hg resolve' to retry unresolved file merges or 'hg update -C .' to abandon

P:\iCatcher\Console\Development>

The first prompt was colourised, and I noticed a visible progress bar on the following merges. Also note that some of the "merging..." lines are missing.

I don't have any enabled [color] or [progress] sections in my local or global hgrc.
Comment 17 Matt Mackall 2015-12-16 12:16 UTC
Woo, looks like we have a lead.

Progress is now enabled by default. You can turn it off with --config progress.disable=true.

hg debugextensions might tell us something interesting.
Comment 18 Deanna Earley 2015-12-16 12:21 UTC
Sorry, I thought I'd already confirmed that disabling progress allowed the prompts to appear as normal!
Comment 19 Matt Mackall 2015-12-16 12:27 UTC
Indeed you had. Adding the progress baron.
Comment 20 Bugzilla 2015-12-27 00:00 UTC
Bug marked urgent for 10 days, bumping
Comment 21 Bugzilla 2016-01-07 00:00 UTC
Bug marked urgent for 10 days, bumping
Comment 22 Bugzilla 2016-01-18 11:28 UTC
Bug marked urgent for 11 days, bumping
Comment 23 Augie Fackler 2016-01-27 10:32 UTC
So, I've been seeing merge prompts. Is this only a problem for cmd.exe users?

(Trying to figure out what I need to debug, I guess.)
Comment 24 Augie Fackler 2016-01-28 09:59 UTC
I believe this has to do with cmd.exe not being a full terminal emulator. It looks like NT-derived Windows (which I believe includes all XP and later versions?) don't have ansi.sys available anymore, which means we're sort of out of luck. Maybe https://github.com/adoxa/ansicon will help?
Comment 25 Deanna Earley 2016-01-28 10:53 UTC
I'm just about to try ansicon, but in the mean time, this script breaks ~10% of the time:

rmdir /s /q .hg
hg init

echo 1 > xfile.txt
hg add xfile.txt
hg commit -m commit1

echo 2 > xfile.txt
hg commit -m commit2

hg update 0
echo 3 > xfile.txt
hg commit -m commit3

hg merge 1

It requires progress enabled and the color extension loaded.
Comment 26 Bugzilla 2016-02-08 00:00 UTC
Bug marked urgent for 10 days, bumping
Comment 27 Matt Harbison 2016-02-12 22:14 UTC
Not sure if this is useful info, but I had it happen to me today in plain cmd.exe with the username prompt on an https pull.  The username and password prompts showed fine minutes before with clone.  Disabling color on the pull command line let the user/pw prompts show.  Progress was still enabled.
Comment 28 Augie Fackler 2016-02-13 21:09 UTC
Does anyone have a good reference for what cmd.exe actually supports?

I'm thinking for now we probably need to not do progress by default if we can detect cmd.exe.
Comment 29 Matt Harbison 2016-02-15 12:57 UTC
I ran into a library that purports to support ANSI escape codes in cmd.exe while looking into this.  It's maybe more complex than we want to bring in (and I can't tell if it helps progress, or what happens with I/O redirection), but the nice thing is it looks like it doesn't require a separate library or different console app.  For whatever reason, there are calls to FillConsoleOutputXxx() and SetConsoleCursorXxx() that I don't see in color.py (or anything resembling this ANSI escape code handling in progress.py)

https://github.com/mattn/ansicolor-w32.c
Comment 30 Gregory Szorc 2016-02-15 13:28 UTC
Windows cmd.exe ANSI support, see https://pypi.python.org/pypi/colorama. https://github.com/tartley/colorama/blob/master/colorama/win32.py is where the win32 code is.
Comment 31 Pierre-Yves David 2016-02-23 07:27 UTC
(half clueless comment)

So do we know what is causing this? color, progress? If this is progress, should we disable it by defaut on windows until this is solved?
Comment 32 Augie Fackler 2016-02-23 09:12 UTC
It appears to be using both color and progress. I've reached out to some people at Microsoft, but I'm not overly optimistic given how old cmd.exe is. Turning off progress for cmd.exe is probably the least awful thing for now (note that it appears to only be a bug for cmd, which is extra weird to me.)
Comment 33 Matt Harbison 2016-02-23 09:56 UTC
Not sure if this is a useful data point, but I see weird progress output 100% of the time when doing the initial clone, then update to tip of one of our large repos with subrepos.  It's the same output with color disabled, using 3.7.1.  Note the progress bar that didn't get erased.

I wonder if this seemingly lost '\r' can also happen to color codes?  I wasn't able to recreate the missing prompt issue with Deanna's script, so I couldn't change the background in cmd.exe to see if it is printing black text on a black background, or if the output is totally missing.

E:\Projects\C_Projects>hg clone https://vcs.attotech.com/scm/hg/ssg/pcidrv pcidrv_160223
requesting all changes
adding changesets
adding manifests
adding file changes
added 14884 changesets with 23736 changes to 2043 files (+6 heads)
updating to branch default
4 files updated, 0 files merged, 0 files removed, 0 files unresolved

E:\Projects\C_Projects>cd pcidrv_160223

E:\Projects\C_Projects\pcidrv_160223>hg up tip
updating [============================================================================================>] 2028/2028 01sre
al URL is https://vcs.attotech.com:443/scm/hg/ssg/include
cloning subrepo include from https://vcs.attotech.com/scm/hg/ssg/pcidrv/include
requesting all changes
adding changesets
adding manifests
adding file changes
added 914 changesets with 1050 changes to 102 files
real URL is https://vcs.attotech.com:443/scm/hg/ssg/lib/cli
cloning subrepo lib\cli from https://vcs.attotech.com/scm/hg/ssg/pcidrv/lib/cli
requesting all changes
adding changesets
adding manifests
adding file changes
added 299 changesets with 560 changes to 80 files
real URL is https://vcs.attotech.com:443/scm/hg/ssg/lib/storfilt
cloning subrepo lib\storfilt from https://vcs.attotech.com/scm/hg/ssg/pcidrv/lib/storfilt
requesting all changes
adding changesets
adding manifests
adding file changes
added 9 changesets with 39 changes to 25 files
2028 files updated, 0 files merged, 0 files removed, 0 files unresolved
Comment 34 Matt Mackall 2016-02-23 12:54 UTC
Theory: there's a very long history of buggy behavior with line feeds and lower-rightmost character cell in DOS-land. The long progress bar is tickling this weirdness... but only when we're at the bottom of the screen. Making the progress bar a couple columns narrower might make it go away.
Comment 35 Matt Harbison 2016-02-23 13:30 UTC
(In reply to Matt Mackall from comment #34)

I tried reducing progress.width() by 10.  The progress bar is shorter, but same behavior.  It's happening near the top of the window, with a 120x9999 buffer, so it was a long shot.

The other interesting thing I noticed is (with or without the width change), there is a '_' cursor blinking away at the end of the line as the problem bar is being drawn.  Once it writes the following "real URL..." line, the cursor disappears, and it doesn't appear as the bars without a problem are drawn.
Comment 36 timeless 2016-03-01 17:31 UTC
(In reply to Deanna Earley from comment #25)

ok, these steps plus the following:

[merge-tools]
foo.executable = true
foo.check = prompt
foo.priority = 1

[extensions]
color =

[progress]
delay = 0

(where true is something findable, i'm using a .bat file and an absolute path)
Comment 37 Pierre-Yves David 2016-03-09 17:10 UTC
piece of IRC about this issue:

19:09 < timeless> i think that we were able to avoid the problem by switching from the chained file object to the raw one
19:09 < timeless> i can't remember what mpm was planning to do to make a real fix
19:10 < mpm> I didn't have a plan. But I do feel like we have narrowed the debugging scope quite a bit.
Comment 38 Bugzilla 2016-03-20 00:00 UTC
Bug marked urgent for 10 days, bumping
Comment 39 Pierre-Yves David 2016-03-29 15:24 UTC
It seems like no progress have been made on this issue in the past 2 weeks. I'll probably take the Augie "disable progress on windows" hammer patch unless a fixes pops up by the time 3.7.4 is due (pretty much 48h from now)

https://www.mercurial-scm.org/pipermail/mercurial-devel/2016-March/080486.html
Comment 40 Matt Mackall 2016-03-29 15:36 UTC
I don't think I'll cut another release on the first. The next release will probably be 3.8 on May 1.
Comment 41 Bugzilla 2016-04-09 00:00 UTC
Bug marked urgent for 10 days, bumping
Comment 42 Bugzilla 2016-04-20 00:00 UTC
Bug marked urgent for 10 days, bumping
Comment 43 Matt Harbison 2016-04-28 11:58 UTC
(In reply to Pierre-Yves David from comment #37)

> 19:09 < timeless> i think that we were able to avoid the problem by switching
> from the chained file object to the raw one

Any details on what this means, or if there is a consistent way to reproduce this?
Comment 44 timeless 2016-04-28 20:34 UTC
printing to stdout is done via some wrapped file object.
if I printed via the underlying stdout object, things worked....

Basically, something along the chain was interfering, although I didn't manage to figure out the details...
Comment 45 Matt Harbison 2016-04-28 23:21 UTC
(In reply to timeless from comment #44)

I assume this is back to color then, since progress writes to sys.stderr?

Were you able to come up with a reproducible test?  I haven't hit one failure with the test addendum listed in #36 in about 20 minutes or so of trying.
Comment 46 Matt Mackall 2016-04-29 11:52 UTC
Progress is definitely involved. delay=0 seemed to be key to reproducing the problem. It's possible that presence/absence of a readline library might matter as well.
Comment 47 Augie Fackler 2016-05-06 12:58 UTC
Given we've had this regression known for more than six months (and now three releases), any chance we should reconsider my (admittedly sledgehammer-ugly) patch?
Comment 48 Pierre-Yves David 2016-05-06 13:01 UTC
+1 on the sledgehammer patch until we get a proper fixes out, the regression is pretty bad and it is unclear when we'll be able to land a proper fix.
Comment 49 Matt Mackall 2016-05-06 18:33 UTC
Ok, I've reproduced the bug under Wine and diagnosed it.

The win32 color mode is implemented by first generating ANSI color sequences and then parsing the result. Each fragment is used to set console attributes and then call the stock ui.write().

The stock ui.write clears the progress bar.

Because the prompt is colorized, the color extension adds ANSI codes and then parses it into TWO fragments (the second one empty!), and thus does clear/write/clear/write. The second clear erases the prompt from the first write.

The progress clear code is only conditional on whether the progress bar is enabled, not on whether one is currently active, or even if we just cleared it.
This would also screw up any case where two different colors are shown on the same line!

Making progress clearing a little smarter makes the problem go away.

I've got a patch for progress in the works so setting to (extra-appropriate) IN_PROGRESS.
Comment 50 Matt Mackall 2016-05-06 18:43 UTC
Please give this a spin:

diff -r 77de985d7c91 mercurial/progress.py
--- a/mercurial/progress.py	Thu May 05 16:29:31 2016 +0200
+++ b/mercurial/progress.py	Fri May 06 17:42:26 2016 -0500
@@ -163,7 +163,7 @@
         sys.stderr.flush()
 
     def clear(self):
-        if not shouldprint(self.ui):
+        if not self.printed or not self.lastprint or not shouldprint(self.ui):
             return
         sys.stderr.write('\r%s\r' % (' ' * self.width()))
         if self.printed:


I had best results triggering the issue with progress.delay and progress.changedelay set to -1.
Comment 51 Deanna Earley 2016-05-07 19:45 UTC
If there's a (64-bit) binary, I'm happy to test on the original machine.
I will lose access to it next Friday though.
Comment 52 Matt Harbison 2016-05-07 20:19 UTC
(In reply to Deanna Earley from comment #51)

Your best bet is probably to install Python and msys, and run from source.  It's been awhile since I setup a Windows system, but I think all you have to do is go to the source directory root in an msys shell, and type "make local".  'Hg version' will confirm you are running the local build.
Comment 53 Matt Mackall 2016-05-09 12:21 UTC
FYI, I was able to get a hackable copy of Windows hg thusly:

- install 64-bit Wine on my Linux machine
- wine start cmd to get a cmd window
- install Python 2.7.11 (64-bit)
- adjust path to include c:\Python27 and c:\Python27\scripts
- pip install mercurial  (this grabs hg 3.8.1 with precompiled bits)
- source is now in c:\python27\lib\site-packages\mercurial
Comment 54 HG Bot 2016-05-11 17:15 UTC
Fixed by https://selenic.com/repo/hg/rev/222b8170d69e
Matt Mackall <mpm@selenic.com>
progress: stop excessive clearing (issue4801)

The progress bar was being cleared on every write(), regardless of
whether it was currently displayed. This could foul up the display of
any writes that didn't include a linebreak.

In particular, the win32 mode of the color extension was turning
single prompt string writes into two writes, and the resulting
clear/write/clear/write pattern was making the prompt invisible.

We fix this by insisting that we have shown a progress bar and haven't
just cleared it (setting lastprint to 0).

Conveniently, the test suite already had instances of duplicate
clears.. that are now cleared up.

(please test the fix)
Comment 55 Bugzilla 2016-05-19 00:00 UTC
Bug was set to TESTING for 7 days, resolving