[bugreport mercurial-2.6.2] "hg pull --debug" aborted: "... /mercurial/phases.py", line 363, in analyzeremotephases node = bin(nhex) TypeError: Odd-length string

Sun Jul 14 21:55:40 CDT 2013

( V="hg-stable"  && cd "$V"  && date '+%n%F %a %T' >> "../${V}.pull.log"  && hg pull --debug  |& tee -a "../${V}.pull.log" )
----------------------------------------------------------------------------------------------------------------------------
2013-07-14 So 07:16:12
using http://www.selenic.com/repo/hg-stable
proxying through http://wwwoffle:9080
sending capabilities command
pulling from http://www.selenic.com/repo/hg-stable
preparing listkeys for "bookmarks"
sending listkeys command
query 1; heads
sending batch command
searching for changes
all local heads known remotely
sending getbundle command
adding changesets
changesets: 1 chunks
add changeset 87bb53367633
changesets: 2 chunks
add changeset 73066ba46ec5
changesets: 3 chunks
add changeset da16d21cf4ed
changesets: 4 chunks
add changeset b500a663a2c7
changesets: 5 chunks
add changeset 6f3428c528b4
changesets: 6 chunks
add changeset 66da6e9feacd
changesets: 7 chunks
add changeset 9778c77f05d6
changesets: 8 chunks
add changeset ec17ddecdf64
changesets: 9 chunks
add changeset e71667a085f5
changesets: 10 chunks
add changeset 0af993732f66
changesets: 11 chunks
add changeset 05dd39b92f2b
changesets: 12 chunks
add changeset d61ac200fb13
changesets: 13 chunks
add changeset e9fdde7c388a
changesets: 14 chunks
add changeset 3cfe5b65b5d4
changesets: 15 chunks
add changeset 863d4838066a
changesets: 16 chunks
add changeset 379682165248
changesets: 17 chunks
add changeset bbf2e4b9730a
changesets: 18 chunks
add changeset 62388510fd10
changesets: 19 chunks
add changeset a199ca58d608
changesets: 20 chunks
add changeset 18d7b2c2e313
changesets: 21 chunks
add changeset 4f937815f4c5
changesets: 22 chunks
add changeset 60a4a4035a18
changesets: 23 chunks
add changeset e731da3ee766
changesets: 24 chunks
add changeset e701c07814f1
changesets: 25 chunks
add changeset 71d8ef8ebeca
changesets: 26 chunks
add changeset 2a98f59fc5a9
changesets: 27 chunks
add changeset 66d17ad097d8
changesets: 28 chunks
add changeset d106352f6321
changesets: 29 chunks
add changeset 12563db1d122
changesets: 30 chunks
add changeset 5470f6bf6b21
changesets: 31 chunks
add changeset f9c3e42536a1
changesets: 32 chunks
add changeset 545930c51297
changesets: 33 chunks
add changeset a27711aecfae
changesets: 34 chunks
add changeset fa14231087b8
changesets: 35 chunks
add changeset f5a77221ef17
changesets: 36 chunks
add changeset 6db25c342658
changesets: 37 chunks
add changeset 0931b01a0125
changesets: 38 chunks
add changeset a142b0c06c93
changesets: 39 chunks
add changeset a4ea2d4e03e7
changesets: 40 chunks
add changeset 5f8c10df3b7f
changesets: 41 chunks
add changeset 77daf3ab691a
changesets: 42 chunks
add changeset 216eb60d12a1
changesets: 43 chunks
add changeset c45b324cd2b5
changesets: 44 chunks
add changeset f84aa729057f
changesets: 45 chunks
add changeset c30e8f895919
changesets: 46 chunks
add changeset 009794acc6e3
changesets: 47 chunks
add changeset 0101aaf6ff52
changesets: 48 chunks
add changeset fbdac607bff3
adding manifests
manifests: 1/48 chunks (2.08%)
manifests: 2/48 chunks (4.17%)
manifests: 3/48 chunks (6.25%)
manifests: 4/48 chunks (8.33%)
manifests: 5/48 chunks (10.42%)
manifests: 6/48 chunks (12.50%)
manifests: 7/48 chunks (14.58%)
manifests: 8/48 chunks (16.67%)
manifests: 9/48 chunks (18.75%)
manifests: 10/48 chunks (20.83%)
manifests: 11/48 chunks (22.92%)
manifests: 12/48 chunks (25.00%)
manifests: 13/48 chunks (27.08%)
manifests: 14/48 chunks (29.17%)
manifests: 15/48 chunks (31.25%)
manifests: 16/48 chunks (33.33%)
manifests: 17/48 chunks (35.42%)
manifests: 18/48 chunks (37.50%)
manifests: 19/48 chunks (39.58%)
manifests: 20/48 chunks (41.67%)
manifests: 21/48 chunks (43.75%)
manifests: 22/48 chunks (45.83%)
manifests: 23/48 chunks (47.92%)
manifests: 24/48 chunks (50.00%)
manifests: 25/48 chunks (52.08%)
manifests: 26/48 chunks (54.17%)
manifests: 27/48 chunks (56.25%)
manifests: 28/48 chunks (58.33%)
manifests: 29/48 chunks (60.42%)
manifests: 30/48 chunks (62.50%)
manifests: 31/48 chunks (64.58%)
manifests: 32/48 chunks (66.67%)
manifests: 33/48 chunks (68.75%)
manifests: 34/48 chunks (70.83%)
manifests: 35/48 chunks (72.92%)
manifests: 36/48 chunks (75.00%)
manifests: 37/48 chunks (77.08%)
manifests: 38/48 chunks (79.17%)
manifests: 39/48 chunks (81.25%)
manifests: 40/48 chunks (83.33%)
manifests: 41/48 chunks (85.42%)
manifests: 42/48 chunks (87.50%)
manifests: 43/48 chunks (89.58%)
manifests: 44/48 chunks (91.67%)
manifests: 45/48 chunks (93.75%)
manifests: 46/48 chunks (95.83%)
manifests: 47/48 chunks (97.92%)
manifests: 48/48 chunks (100.00%)
adding file changes
adding .hgsigs revisions
files: 1/23 chunks (4.35%)
adding .hgtags revisions
files: 2/23 chunks (8.70%)
adding doc/hgrc.5.txt revisions
files: 3/23 chunks (13.04%)
adding hgext/histedit.py revisions
files: 4/23 chunks (17.39%)
adding i18n/da.po revisions
files: 5/23 chunks (21.74%)
adding i18n/de.po revisions
files: 6/23 chunks (26.09%)
adding i18n/el.po revisions
files: 7/23 chunks (30.43%)
adding i18n/fr.po revisions
files: 8/23 chunks (34.78%)
adding i18n/it.po revisions
files: 9/23 chunks (39.13%)
adding i18n/ja.po revisions
files: 10/23 chunks (43.48%)
adding i18n/pt_BR.po revisions
files: 11/23 chunks (47.83%)
adding i18n/ru.po revisions
files: 12/23 chunks (52.17%)
adding i18n/sv.po revisions
files: 13/23 chunks (56.52%)
adding i18n/zh_CN.po revisions
files: 14/23 chunks (60.87%)
adding mercurial/commands.py revisions
files: 15/23 chunks (65.22%)
adding mercurial/help/extensions.txt revisions
files: 16/23 chunks (69.57%)
adding mercurial/help/phases.txt revisions
files: 17/23 chunks (73.91%)
adding mercurial/hg.py revisions
files: 18/23 chunks (78.26%)
adding mercurial/pathencode.c revisions
files: 19/23 chunks (82.61%)
adding tests/test-branches.t revisions
files: 20/23 chunks (86.96%)
adding tests/test-commit-amend.t revisions
files: 21/23 chunks (91.30%)
adding tests/test-graft.t revisions
files: 22/23 chunks (95.65%)
adding tests/test-pathencode.py revisions
files: 23/23 chunks (100.00%)
added 48 changesets with 49 changes to 23 files
preparing listkeys for "phases"
sending listkeys command
transaction abort!
rollback completed
updating the branch cache
** unknown exception encountered, please report by visiting
** http://mercurial.selenic.com/wiki/BugTracker
** Python 2.7.1 (r271:86832, Sep 17 2011, 07:44:39) [GCC 4.5.3]
** Mercurial Distributed SCM (version 2.6.2+2-04eb7d7e115b+20130603)
** Extensions loaded: color, extdiff, pager, convert, rebase, transplant, graphlog, mq, gpg
Traceback (most recent call last):
  File "/usr/bin/hg-2.7", line 38, in <module>
    mercurial.dispatch.run()
  File "/usr/lib64/python2.7/site-packages/mercurial/dispatch.py", line 28, in run
    sys.exit((dispatch(request(sys.argv[1:])) or 0) & 255)
  File "/usr/lib64/python2.7/site-packages/mercurial/dispatch.py", line 69, in dispatch
    ret = _runcatch(req)
  File "/usr/lib64/python2.7/site-packages/mercurial/dispatch.py", line 97, in _runcatch
    return _dispatch(req)
  File "/usr/lib64/python2.7/site-packages/mercurial/dispatch.py", line 778, in _dispatch
    cmdpats, cmdoptions)
  File "/usr/lib64/python2.7/site-packages/mercurial/dispatch.py", line 549, in runcommand
    ret = _runcommand(ui, options, cmd, d)
  File "/usr/lib64/python2.7/site-packages/mercurial/extensions.py", line 188, in wrap
    return wrapper(origfn, *args, **kwargs)
  File "/usr/lib64/python2.7/site-packages/hgext/color.py", line 405, in colorcmd
    return orig(ui_, opts, cmd, cmdfunc)
  File "/usr/lib64/python2.7/site-packages/mercurial/dispatch.py", line 869, in _runcommand
    return checkargs()
  File "/usr/lib64/python2.7/site-packages/mercurial/dispatch.py", line 840, in checkargs
    return cmdfunc()
  File "/usr/lib64/python2.7/site-packages/mercurial/dispatch.py", line 775, in <lambda>
    d = lambda: util.checksignature(func)(ui, *args, **cmdoptions)
  File "/usr/lib64/python2.7/site-packages/mercurial/util.py", line 506, in check
    return func(*args, **kwargs)
  File "/usr/lib64/python2.7/site-packages/mercurial/extensions.py", line 143, in wrap
    util.checksignature(origfn), *args, **kwargs)
  File "/usr/lib64/python2.7/site-packages/mercurial/util.py", line 506, in check
    return func(*args, **kwargs)
  File "/usr/lib64/python2.7/site-packages/hgext/mq.py", line 3528, in mqcommand
    return orig(ui, repo, *args, **kwargs)
  File "/usr/lib64/python2.7/site-packages/mercurial/util.py", line 506, in check
    return func(*args, **kwargs)
  File "/usr/lib64/python2.7/site-packages/mercurial/extensions.py", line 143, in wrap
    util.checksignature(origfn), *args, **kwargs)
  File "/usr/lib64/python2.7/site-packages/mercurial/util.py", line 506, in check
    return func(*args, **kwargs)
  File "/usr/lib64/python2.7/site-packages/hgext/rebase.py", line 780, in pullrebase
    orig(ui, repo, *args, **opts)
  File "/usr/lib64/python2.7/site-packages/mercurial/util.py", line 506, in check
    return func(*args, **kwargs)
  File "/usr/lib64/python2.7/site-packages/mercurial/commands.py", line 4552, in pull
    modheads = repo.pull(other, heads=revs, force=opts.get('force'))
  File "/usr/lib64/python2.7/site-packages/mercurial/localrepo.py", line 1713, in pull
    remotephases)
  File "/usr/lib64/python2.7/site-packages/mercurial/phases.py", line 363, in analyzeremotephases
    node = bin(nhex)
TypeError: Odd-length string

Related proxy server log snippet
--------------------------------
2013-07-14T07:16:13+02:00 mobil wwwoffles[15918]: URL='http://www.selenic.com/repo/hg-stable?cmd=capabilities'.
2013-07-14T07:16:14+02:00 mobil wwwoffles[15918]: Cache Access Status='Modified on Server'.
2013-07-14T07:16:14+02:00 mobil wwwoffles[15918]: Server bytes; 318 Read, 404 Written.
2013-07-14T07:16:14+02:00 mobil wwwoffles[15918]: Client bytes; 189 Read, 361 Written.
2013-07-14T07:16:14+02:00 mobil wwwoffled[13535]: Child wwwoffles exited with status 0 (pid=15918).
2013-07-14T07:16:14+02:00 mobil wwwoffled[13535]: HTTP Proxy connection from host mobil.systemanalysen.net (127.0.0.1).
2013-07-14T07:16:14+02:00 mobil wwwoffled[13535]: Forked wwwoffles -real (pid=15919).
2013-07-14T07:16:14+02:00 mobil wwwoffles[15919]: URL='http://www.selenic.com/repo/hg-stable?cmd=listkeys'.
2013-07-14T07:16:14+02:00 mobil wwwoffles[15919]: Cache Access Status='Modified on Server'.
2013-07-14T07:16:14+02:00 mobil wwwoffles[15919]: Server bytes; 229 Read, 449 Written.
2013-07-14T07:16:14+02:00 mobil wwwoffles[15919]: Client bytes; 234 Read, 273 Written.
2013-07-14T07:16:14+02:00 mobil wwwoffled[13535]: Child wwwoffles exited with status 0 (pid=15919).
2013-07-14T07:16:14+02:00 mobil wwwoffled[13535]: HTTP Proxy connection from host mobil.systemanalysen.net (127.0.0.1).
2013-07-14T07:16:14+02:00 mobil wwwoffled[13535]: Forked wwwoffles -real (pid=15920).
2013-07-14T07:16:14+02:00 mobil wwwoffles[15920]: URL='http://www.selenic.com/repo/hg-stable?cmd=batch'.
2013-07-14T07:16:15+02:00 mobil wwwoffles[15920]: Cache Access Status='Modified on Server'.
2013-07-14T07:16:15+02:00 mobil wwwoffles[15920]: Server bytes; 230 Read, 495 Written.
2013-07-14T07:16:15+02:00 mobil wwwoffles[15920]: Client bytes; 280 Read, 274 Written.
2013-07-14T07:16:15+02:00 mobil wwwoffled[13535]: Child wwwoffles exited with status 0 (pid=15920).
2013-07-14T07:16:15+02:00 mobil wwwoffled[13535]: HTTP Proxy connection from host mobil.systemanalysen.net (127.0.0.1).
2013-07-14T07:16:15+02:00 mobil wwwoffled[13535]: Forked wwwoffles -real (pid=15921).
2013-07-14T07:16:15+02:00 mobil wwwoffles[15921]: URL='http://www.selenic.com/repo/hg-stable?cmd=getbundle'.
2013-07-14T07:16:17+02:00 mobil wwwoffles[15921]: Server has used 'Transfer-Encoding: chunked'.
2013-07-14T07:16:17+02:00 mobil wwwoffles[15921]: Cache Access Status='Modified on Server'.
2013-07-14T07:16:17+02:00 mobil wwwoffles[15921]: Server bytes; 20936 Read, 525 Written.
2013-07-14T07:16:17+02:00 mobil wwwoffles[15921]: Client bytes; 310 Read, 21053 Written.
2013-07-14T07:16:17+02:00 mobil wwwoffled[13535]: Child wwwoffles exited with status 0 (pid=15921).
2013-07-14T07:16:17+02:00 mobil wwwoffled[13535]: HTTP Proxy connection from host mobil.systemanalysen.net (127.0.0.1).
2013-07-14T07:16:17+02:00 mobil wwwoffled[13535]: Forked wwwoffles -real (pid=15922).
2013-07-14T07:16:17+02:00 mobil wwwoffles[15922]: URL='http://www.selenic.com/repo/hg-stable?cmd=listkeys'.
2013-07-14T07:16:17+02:00 mobil wwwoffles[15922]: Cache Access Status='Cached Page Used'.
2013-07-14T07:16:17+02:00 mobil wwwoffles[15922]: Client bytes; 231 Read, 273 Written.
2013-07-14T07:16:17+02:00 mobil wwwoffled[13535]: Child wwwoffles exited with status 0 (pid=15922).

Caching the second request for "… ?cmd=listkeys" so far never caused a problem.

On request for '... ?cmd=listkeys', proxy server replied following http
headers and content (for readability quoted-printable encoded):
/usr/bin/wwwoffle-read -c /etc/wwwoffle/wwwoffle.conf 'http://www.selenic.com/repo/hg-stable?cmd=listkeys'  | recode data..qp
-----------------------------------------------------------------------------------------------------------------------------
HTTP/1.0 200 Script output follows=0D
Date: Sun, 14 Jul 2013 05:16:16 GMT=0D
Server: Apache/2.2.16 (Debian)=0D
Content-Type: application/mercurial-0.1=0D
Connection: close=0D
Proxy-Connection: close=0D
=0D
@       762208a3edabc483936fff7ef4c8e02b25a8fba0=

locale
------
LANG=de_DE.utf8
LC_CTYPE=de_DE.utf8
LC_NUMERIC=de_DE.utf8
LC_TIME=de_DE.utf8
LC_COLLATE=C
LC_MONETARY=de_DE.utf8
LC_MESSAGES=de_DE.utf8
LC_PAPER=de_DE.utf8
LC_NAME=de_DE.utf8
LC_ADDRESS=de_DE.utf8
LC_TELEPHONE=de_DE.utf8
LC_MEASUREMENT=de_DE.utf8
LC_IDENTIFICATION=de_DE.utf8
LC_ALL=

My patches applied to files listed below apparently don't matter;  I could
reproduce the bug with an unpatched hg build, repository restored from backup,
and proxy server set to offline mode (= use always cached data, never request
from parent server).
mercurial/cmdutil.py
mercurial/localrepo.py
mercurial/readable_repository.py
mercurial/scmutil.py
mercurial/commands.py
mercurial/minirst.py
tests/test-minirst.py.out
contrib/bash_completion

My none-default “site.py” (in def setencoding(): encoding = "utf-8")
apparently does not matter;  I could reproduce the bug after reverting to
default “site.py” (encoding = "ascii").

-- 
Regards
Roland Eggner
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 198 bytes
Desc: not available
URL: <http://selenic.com/pipermail/mercurial-devel/attachments/20130715/44e899e4/attachment.pgp>