TortoiseHgでupdateが失敗したように見える

[flied onion]

こんにちは。

何度か発生していた、updateすると リビジョン nullにupdateしたように見えるという事象についてです。

原因はまるでつかめていないのですが、少し情報を集めてみましたので投稿させてもらいます。

とりあえずどういう事象か、説明しにくいのでキャプチャしてみました。

この投稿に添付している2ファイルを同じディレクトリにおいてhtmlファイルを起動すればswfが再生されると思います。

（swf単体でもブラウザで実行できますがサイズが崩れて多少汚いです。あいかわらずキャプチャスキルがありません ＾＾；）

この動画は、問題の事象が発生している状態から開始して何回か連続でアップデートし、また問題の事象に遭遇したところまでを動画にしています。

ほっておくとリピート再生されて気付かないうちに先頭に戻ってますので注意してください（笑）

要するにグラフで作業領域のリビジョンが -1+ で始まり、また -1+になったらおしまいです。

どちらも、「リビジョン 282にアップデートしたのに、 -1+ と表示されている」という状態にあります。

予想も含みますが少し整理します。

• HEADにアップデートするときに起こる模様（HEAD以外では記憶にない）
• 私愛用のTimestampModは関係ない（外しても起きました）
• 実際にはアップデートされている
  * 別途取り出しておいた同じリビジョンのファイルとWinMergeでぶつけても差分がなかった
  * thgを開き直しても目的のリビジョンに正常に更新された状態で更新される
• 事象発生時点から別のリビジョンにアップデートするとまれに「編集済みファイルがある」という警告が出る
  * 添付した動画の一回目のアップデートで出ている警告
  * 編集してない
  * 警告をCancelしてもう一度アップデートすると通過する
  
• 一度発生すると割と再現できるかもしれない
  * 同じ手順でアップデートすると再び起こるようになることも
  * 起きたままpullやcommitやpushしてないリポジトリだと、thg開き直しても起きるかもしれない
  * pullなどでできなくなる
  

編集していないのに「編集したファイルが出る」という警告が出ることから単純に作業領域の状態がとれず -1になっているんでしょうか。

mercurial部分は正しく機能しているようですので、描画中のエラーがスルーされてるとかでしょうか。

# どこでも起こるならいざ知らず、同じ手順でアップデートすると再び起こるとかHEADでよく起こるというのは引っかかてますが

[flied onion]

この動画をとるより前にちょいちょい検証してた時にとれた画面とその時のコマンドログです。

これは開いてすぐ起きたので、このコマンドログは thgが起動してから事象が発生するまでのすべてのログということになります。

[flied onion]

連投ですいません、

西原さんにTwitterで教わった THGDEBUGを設定しての画面（THG_DEBUG_TRUE_0315.png）と、ログ（THGDEBUG_TRUE.txt）、

あとその状態からさらにthgを開くとどう見えるのか（THG_DEBUG_TRUE_0315_moreThg.png）です。

尚これは rev273にアップデートしようとして起きてます。

以上になります。

thg開き直せば直りますしリポジトリや作業領域になにか起きているわけでもないようですので深刻な問題ではなさそうですが

何かの参考になれば幸いです。

[Yuya Nishihara]

西原です。

詳細なログをありがとうございます。とても参考になります。

On Tue, 26 Mar 2013 08:23:38 -0700 (PDT), flied onion wrote:
> - HEADにアップデートするときに起こる模様（HEAD以外では記憶にない）
> - 私愛用のTimestampModは関係ない（外しても起きました）
> - 実際にはアップデートされている
> * 別途取り出しておいた同じリビジョンのファイルとWinMergeでぶつけても差分がなかった
> * thgを開き直しても目的のリビジョンに正常に更新された状態で更新される
> - 事象発生時点から別のリビジョンにアップデートするとまれに「編集済みファイルがある」という警告が出る

> * 添付した動画の一回目のアップデートで出ている警告
> * 編集してない
> * 警告をCancelしてもう一度アップデートすると通過する

> - 一度発生すると割と再現できるかもしれない

> * 同じ手順でアップデートすると再び起こるようになることも
> * 起きたままpullやcommitやpushしてないリポジトリだと、thg開き直しても起きるかもしれない
> * pullなどでできなくなる

根本原因は分かりませんが、 TortoiseHg がリポジトリを読みなおす時に dirstate ファイルが
見えていない *1 のかもしれません。
ちょっと整理できていないので、細かい話は後日します。

この拡張を入れると問題が起きづらくなったりしますか?
試しにリポジトリの変更検知後 100msec 余裕を入れてみました。

https://bitbucket.org/yuja/hgext-workarounds/src/e18d09e9b68f/hgext/thgrepodamper.py

*1: Windows では atomic rename できないので、一瞬 unlink されるはず。しかし、それにしては
再現性ありすぎ。

[flied onion]

返信遅くなりすみません。

拡張ありがとうございます、簡単に試してみました。

拡張を設定した状態では起きませんでした（50回くらいupdateしてみました）。

そして拡張を外してみると再発したので効果があったと言えそうです（拡張つけてためしたのと同じ手順でやっている最中に割と早い段階で再発しました）。

ただし今回の問題とは関係ないですが拡張を付けた状態で

ファイル＞設定

を開こうとすると以下のエラーがでてthgが落ちてしまいましたので報告しておきます。

{{{

#!python

** Mercurial version (2.2.3).  TortoiseHg version (2.4.2)

** Command: --nofork workbench

** CWD: C:\hgExt\TimestampMod

** Encoding: cp932

** Extensions loaded: win32mbcs, rebase, TimestampMod, convert, fetch, mq, thgrepodamper

** Python version: 2.7.3 (default, Apr 10 2012, 23:31:26) [MSC v.1500 32 bit (Intel)]

** Windows version: sys.getwindowsversion(major=5, minor=1, build=2600, platform=2, service_pack='Service Pack 3')

** Processor architecture: x86

** Qt-4.8.0 PyQt-4.9.1

Traceback (most recent call last):

  File "tortoisehg\hgqt\workbench.pyo", line 1115, in editSettings

  File "tortoisehg\hgqt\settings.pyo", line 1051, in __init__

  File "mercurial\extensions.pyo", line 184, in wrap

  File "C:\hgExt\thgrepodamper\thgrepodamper.py", line 27, in repository

  File "C:\hgExt\thgrepodamper\thgrepodamper.py", line 18, in injectdamper

TypeError: disconnect() failed between 'directoryChanged' and 'onDirChange'

}}}

[Yuya Nishihara]

西原です。こんばんは。

On Sun, 31 Mar 2013 07:56:16 -0700 (PDT), flied onion wrote:
> 拡張ありがとうございます、簡単に試してみました。
> 拡張を設定した状態では起きませんでした（50回くらいupdateしてみました）。
> そして拡張を外してみると再発したので効果があったと言えそうです（拡張つけてためしたのと同じ手順でやっている最中に割と早い段階で再発しました）。

テストありがとうございます。
やっぱり何かあるんですね。再現環境を作って真面目に追わないといけないかも。

ちなみに、 increment/decrementBusyCount の行をコメントアウトした場合は
どうでしょう?

# disable pollStatus() by busy count, which may have side effect
- repo.incrementBusyCount = lambda: None
- repo.decrementBusyCount = repo.thginvalidate
+ #repo.incrementBusyCount = lambda: None
+ #repo.decrementBusyCount = repo.thginvalidate
return repo

もしこれで問題が出なければ、「コマンド実行中はリポジトリのロック解除を検知しない」という
修正で片付きます。分かりやすくていいです。

> ただし今回の問題とは関係ないですが拡張を付けた状態で
> ファイル＞設定
> を開こうとすると以下のエラーがでてthgが落ちてしまいましたので報告しておきます。

お、論理が逆でした。寝ぼけてました。
https://bitbucket.org/yuja/hgext-workarounds/commits/c98a02be6dcc

> #!python
> ** Mercurial version (2.2.3). TortoiseHg version (2.4.2)

それと、最新バージョン 2.7.1 でも問題は起きますか?

[flied onion]

こんばんは

拡張の修正ありがとうございます。

修正の確認や increment/decrementBusyCount のコメントアウトはまだ試していませんが、

ひとまず複数のthgのバージョンでためしてみました。

結果から言うと今検証しているリポジトリではthgが2.4.2、2.4.0の時に起こりました（試した中では）。

2.5.0、2.6.0、2.6.2、2.7.1では起きませんでした（発生頻度が低くて発生にいたらなかっただけかもしれません）。

2.4より古いものでは試していません。

2.5以降入れた後に再び2.4.0をインストールしても発生しました。

事象自体は仕事場の環境では thg 2.6.0で起きてはいます（2.6.2も起きてたかな）。

自宅はSSDで仕事場は普通のHDD＋ウィルス対策ソフトも重めのやつですのでスペックの差もあるかもしれません。

（ちなみに2.6.0で起きたのは全く別のリポジトリです。）

しかし、なかなか再現環境が構築できないのが厄介ですね。

decrementBusyCount コメントアウトの方は後日2.4.2で試してみようと思います。

[flied onion]

こんばんは。

コメントアウトした状態だと発生しますね。

thg起動したままコメントアウトしても発生してしまいましたし、

thg落としてコメントアウト状態変えてもやはりコメントアウトした状態だと発生してしまいました。

バージョンは thg 2.4.2です。

[Yuya Nishihara]

どうも、助かりました。結果から推測すると、可能性は

- increment/decrementBusyCount がバグっているか、
- lock ファイルが unlink された時点でデータの書き込みが終わっていない (なぜ?)

のどちらかだと思います。
2 つ目の理由だと厄介ですね...

[Kaz Sasa]

全く同じ状況かどうか判断つきませんが、Samba共有フォルダー上でMQを使用していて、パッチの更新を実行したときに、nullにアップデートされたようになるという現象に出くわしましたので情報を出しておきます。

作業ファイルを破棄して、元のリビジョンにアップデートしたところ、奇妙なことにMQの適用済みパッチがすべてqfinishしたかのように見えていて、qpop不可能というところで調べてみたところ、以下のような状態になっていました。

1. hg qapplied ではパッチがリストされる
   
2. .hg/patches/status にも適用済みパッチが残っている
3. hg log では適用済みパッチのうち最後の (更新した) ものだけ表示されない

MQでは適用済みとなっているリビジョンがリビジョンヒストリーにないので、パッチキューの状態を誤認識しているのだろうと辺りを付けて、強行策で.hg/patches/statusから最後のパッチを削除したところ、今回はどうにか元に戻りました。

バージョンはTortoiseHg 2.7.2で、Windows 7 64-bitです。

[Kaz Sasa]

少し考えてみたんですが、作業ファイルのリビジョンが履歴上で存在しなくなってしまったので、nullにアップデートしたように見えてしまったのかもしれませんね。次に発生したら検証してみます。

2013年5月19日日曜日 19時18分10秒 UTC+9 Kaz Sasa:

[Yuya Nishihara]

On Sun, 19 May 2013 03:18:10 -0700 (PDT), Kaz Sasa wrote:
> 全く同じ状況かどうか判断つきませんが、Samba共有フォルダー上でMQを使用していて、パッチの更新を実行したときに、nullにアップデートされたようになるという現象に出くわしましたので情報を出しておきます。
>
> 作業ファイルを破棄して、元のリビジョンにアップデートしたところ、奇妙なことにMQの適用済みパッチがすべてqfinishしたかのように見えていて、qpop不可能というところで調べてみたところ、以下のような状態になっていました。
>

> 1. hg qapplied ではパッチがリストされる
> 2. .hg/patches/status にも適用済みパッチが残っている
> 3. hg log では適用済みパッチのうち最後の (更新した) ものだけ表示されない
>
> MQでは適用済みとなっているリビジョンがリビジョンヒストリーにないので、パッチキューの状態を誤認識しているのだろうと辺りを付けて、強行策で.hg/patches/statusから最後のパッチを削除したところ、今回はどうにか元に戻りました。

ちょっと理由は分かりませんが、 qrefresh が予期しないエラーでコケたのではないかと思います。

共有フォルダだとファイルロックの問題(The process cannot access the file because it
is being used by another process)が起きやすいような気がします。

[Kaz Sasa]

確かに共有フォルダーだと問題が起きやすいですね。NetBeans IDEのC/C++リモート開発機能を使うには共有フォルダーが最も無難なので仕方なく使っています。

2013年5月21日火曜日 0時15分49秒 UTC+9 Yuya Nishihara: