Mercurial の Subversion 連携における問題の調査〜その２

※ 修正が取り込まれた 2.2. 版以降であれば、言語設定に起因する変換失敗は発生しません。それ以前の版を利用する場合は、"LC_ALL=en_US.utf-8; export LC_ALL" 等により、言語設定を無効にしてください。

なお、convert エクステンションでは、内部処理が全て UTF-8 で実施されるため、HGENCODING やロケール設定で cp932 を指定しても、ファイル名の cp932 化はできません。

前回に引き続き、ロケール設定で日本語が選択されている場合の Mercurial と Subversion の連携における問題を調査。

@r_rudi 氏に情報採取をお願いしたところ、早速採取データの第一報が。

(snip)
parsing revision 74 (11 changes)
[DBG] subversion:_fetch_revisions: .... date=[2011-01-24T11:16:01.128240Z]
parsing revision 71 (1 changes)
[DBG] subversion:_fetch_revisions: .... date=[2010-12-28T18:55:16.391270Z]

(snip)

走査中: 133 リビジョン
走査中: 134 リビジョン
走査中: 135 リビジョン
並べ替え中...
変換中...
134 hoge修正
変換元: svn:b4adc337-05bd-4085-a230-a13bcdbbdefc/hogerepo/trunk@74
変換中: 0/135 リビジョン (0.00%)
パスの走査中: hoge/file 0/11 (0.00%)

(snip)

run hg sink post-conversion action
中断: 不正な日付: '\xe6\x9c\x88 1\xe6\x9c\x88 24 11:16:01 2011 +0000'

あれ？てっきり svn ⇒ hg でのコミット内容受け渡し ("_fetch_revisions()") でアレしているのだと思ってログ採取コードを仕掛けたのだが、どうやらその部分では問題が無い模様。

『不正な日付: 〜』での中断は、mercurial/util.py の parsedate() しか有り得ないので、convert 実装からの呼び出しを確認してみたのだが、他には『日付ソート』指定時の処理ぐらいしか無い。

今回は単純変換の筈だから、このコードは多分無関係。

そうなると、『変換中...』や『パスの走査中:』表示から考えるに、変換処理の中でも、かなり後段になってからの処理失敗っぽい。
『run hg sink post-conversion action』が表示されているということは:

処理完了時のクリーンアップで失敗
処理失敗により、急遽クリーンアップが実施

のどちらかだけど、事後処理系の after() 定義を漁って見ても、ロックの解放とかの基本的な処理しかしていないので、多分後者の状況かなぁ。

こうなると問題箇所の特定は結構面倒な話に…… orz

てっきり『svn ⇒ hg でのコミット内容受け渡し』と思っていたので失念してたけど、折角だから --traceback 付きでの情報採取をお願いすればよかった、と慌てて @r_rudi 氏にお願い tweet しつつ、こちらも手をこまねいているだけではアレなので、確認範囲を convert エクステンション以外に広げて mercurial/util.py の parsedate() 呼び出しを確認。

…… 呼び出し箇所が案外少ない！これはラッキー！

むむむ！ changelog とか memctx とか、履歴記録系の処理でも呼び出している！しかも memctx の生成は、convert() ⇒ copy() ⇒ putcommit() の延長で実施されているので、処理中断位置との辻褄も合いそうだ。

putcommit() で memctx に渡す日時情報は、各所で mercurial/util.py の datestr() した文字列なので、日時情報 ⇒ datestr() ⇒ parsedate() ⇒ 日時情報が、ロケール設定の影響で正しく機能してないのかなぁ、などというあたりまでアタリを付けて、とりあえず就寝。

日があけて、@r_rudi 氏から --traceback 付きの採取データを入手。

           :
           :
  File "hgext/convert/__init__.py", line 269, in convert
    return convcmd.convert(ui, src, dest, revmapfile, **opts)
  File "hgext/convert/convcmd.py", line 469, in convert
    c.convert(sortmode)
  File "hgext/convert/convcmd.py", line 385, in convert
    self.copy(c)
  File "hgext/convert/convcmd.py", line 353, in copy
    source, self.map)
  File "hgext/convert/hg.py", line 170, in putcommit
    getfilectx, commit.author, commit.date, extra)
  File "mercurial/context.py", line 1090, in __init__
    self._date = date and util.parsedate(date) or util.makedate()
  File "mercurial/util.py", line 1023, in parsedate
    raise Abort(_('invalid date: %r') % date)
Abort: 不正な日付: '\xe6\x9c\x88 1\xe6\x9c\x88 24 11:16:01 2011 +0000'

やはり putcommit() ⇒ memctx ルートだったか。しかも @r_rudi 氏がデバッグプリントを色々仕掛けておいてくれたお陰で、『svn ⇒ hg』ルートの正常性の裏付け補強や、成功／失敗ケースの日付形式情報の詳細が入手できた。

で、早速ロケール設定と日時文字列化／解析処理の挙動を確認……またもや再現しねぇ……orz

とりあえず、Python の動作確認用に、以下のプログラム (datetest.py) を作ってみたのだが:

import locale
import time

jalocale = 'ja_JP.utf-8'
# Windows 環境の場合は 'jpn' (文字コードは cp932 に自動設定)

locale.setlocale(locale.LC_ALL, jalocale)

date = time.gmtime(float(1295867761))
format = '%a %b %d %H:%M:%S %Y'

datestr = time.strftime(format, date)
print datestr

struct_time = time.strptime(datestr, format)
print struct_time

僕の環境だと、ロケールに応じた文字列も普通に解析できている。

$ python datetest.py
月 1月 24 11:16:01 2011
time.struct_time(tm_year=2011, tm_mon=1, tm_mday=24,
                 tm_hour=11, tm_min=16, tm_sec=1, tm_wday=0,
                 tm_yday=24, tm_isdst=-1)

上記の例は cygwin 上の Python 2.6.7 で実行したのだが、そういえば @r_rudi 氏の環境は(スタックダンプのライブラリパス表示を見るに) 2.7 環境だったよなぁ、と思い出し、とりあえず手元にある 2.7 処理系ということで、Windows ネイティブ版の 2.7.2 で動作確認してみた。

$ python datetest.py
月 1 24 11:16:01 2011
time.struct_time(tm_year=2011, tm_mon=1, tm_mday=24,
                 tm_hour=11, tm_min=16, tm_sec=1, tm_wday=0,
                  tm_yday=24, tm_isdst=-1)

こっちも上手く行くなぁ………………あれ？ 2.6.7 版は『月 1月 24』なのに、2.7.2 版は『月 1 24』で、"month of year" の『月』表示が抜けているぞ？

@r_rudi 氏からの情報によると、問題の発生している環境は python 2.7.x 上なのに、日時情報文字列は『月 1月 24 11:16:01 2011』！これが原因じゃねぇ？

試しに 2.7.2 版で上記文字列を解析させてみると………やっぱり上手く行かない！

っつーことは:

python 2.6.7 〜 2.7.2 の間で、strftime()/strptime() の相互連携に失敗する時期があった
python の strftime()/strptime() 系が単なる libc のラッパーなら、@r_rudi 氏の環境の libc が、たまたま strftime()/strptime()　の相互連携に失敗する版だった

のどちらかというあたりが原因じゃなかろうか？という結論に。

問題の根っこは Python ないし libc 層にあるのだけれど、memctx に渡すための文字列は単なる中間形式なので、『ロケール依存にならない形式で文字列化』することで回避できる筈。

ということで、とりあえず以下の様な修正パッチを作成:

diff -r e3c7ca15cde2 hgext/convert/subversion.py
--- a/hgext/convert/subversion.py	Mon Apr 23 00:38:22 2012 +0900
+++ b/hgext/convert/subversion.py	Wed Apr 25 18:56:36 2012 +0900
@@ -808,7 +808,7 @@
                 branch = None
 
             cset = commit(author=author,
-                          date=util.datestr(date),
+                          date=util.datestr(date, '%Y-%m-%d %H:%M:%S %1%2'),
                           desc=log,
                           parents=parents,
                           branch=branch,

お手数ですが以下の作業をお願いします＞ @r_rudi 氏

上記パッチ適用時の ja_JP ロケールでの変換実施
python のバージョン確認
libc (glibc ? libc6 ?) のバージョンの確認
datetest.py (strftime()/strptime() 相互連携テスト) の動作確認

＃バージョン情報類は、本家へのバグ報告の際に環境情報として添付する予定です

この修正で問題なければ、2.2 版のリリースに何とか間に合いそうで一安心。

先述した datetest.py は、問題環境で正常終了してしまったらしく、そうなると mercurial/util.py での前処理に問題があることに……orz

しょうがないので、mercurial/util.py の機能に関しても動作確認できるようにプログラムを改造。

import sys
import locale
import time

dateval = int(sys.argv[1])
locale.setlocale(locale.LC_ALL, sys.argv[2])
sys.path.insert(0, sys.argv[3])

from mercurial import util

format = '%a %b %d %H:%M:%S %Y'
date = time.gmtime(float(dateval))
print 'date=%s' % (str(date))
datestr = time.strftime(format, date)
print 'strftime()=%s' % (datestr)
struct_time = time.strptime(datestr, format)
print 'strptime()=%s' % (str(struct_time))

date = (dateval, 0)
print 'date=%s' % (str(date))
datestr = util.datestr(date)
print 'datestr()=%s' % (datestr)
parseddate = util.parsedate(datestr)
print 'parsedate()=%s' % (str(parseddate))

UTC値やロケール、パスを埋め込むと色々面倒なので、これらは引数で指定出着るようにした。起動形式は:

$ python datetest.py UTC値 ロケール値 Mercurialのライブラリパス

例えば以下のような感じ(適当に行折り返しを加えてます):

$ python datetest.py 1295867761 ja_JP.cp932 \
         ~/hg/2.1.2/lib/python2.6/site-packages
date=time.struct_time(tm_year=2011, tm_mon=1, tm_mday=24,
         tm_hour=11, tm_min=16, tm_sec=1,
         tm_wday=0, tm_yday=24, tm_isdst=0)
strftime()=月 1月 24 11:16:01 2011
strptime()=time.struct_time(tm_year=2011, tm_mon=1, tm_mday=24,
         tm_hour=11, tm_min=16, tm_sec=1,
         tm_wday=0, tm_yday=24, tm_isdst=-1)
date=(1295867761, 0)
datestr()=月 1月 24 11:16:01 2011 +0000
parsedate()=(1295867761, 0)
$

Windows 環境で実行する場合、ロケール設定を "jpn" にする以外にも、ライブラリのパス設定が少々面倒かもしれないので注意。

手当たり次第に確認してみたところ、やや！仮想環境に入れた debian では再現した！

Cygwin 環境の python 2.6.7 で発生しないのに、ubuntu 上の python 2.7.2+ (libc は 2.13-20)や debian 上の python 2.6.6 (libc は 2.11.2-10)で発生するのは、やっぱり libc のバージョン依存っぽいけど、strftime()/strptime() 連携が正常動作している点を考えると、Mercurial 側の処理に、ロケール依存な部分があるんだろうなぁ。

彷徨えるフジワラ

年がら年中さまよってます

Mercurial の Subversion 連携における問題の調査〜その２