ssh 経由での hg clone が終了しない。

[ohira]

いつもお世話になっております。

おおひらです。

ssh 経由の接続でリモートのマシンにcloseを実行すると、ずっと実行中のままプロンプトに帰ってこない現象が発生しました。

特定のマシンへの接続の場合に発生しています、今回問題が発生した同じクライアントマシンから他のマシンにssh経由でclone 

した場合には発生していません。

このような現象を回避する方法はありますでしょうか？

デバッグオプションをつけて実行したログ

sp11% env LANG=C ssh release-dev env LANG=C hg

Mercurial Distributed SCM

basic commands:

 add           add the specified files on the next commit

 annotate      show changeset information by line for each file

 clone         make a copy of an existing repository

 commit        commit the specified files or all outstanding changes

 diff          diff repository (or selected files)

 export        dump the header and diffs for one or more changesets

 forget        forget the specified files on the next commit

 init          create a new repository in the given directory

 log           show revision history of entire repository or files

 merge         merge another revision into working directory

 pull          pull changes from the specified source

 push          push changes to the specified destination

 remove        remove the specified files on the next commit

 serve         start stand-alone webserver

 status        show changed files in the working directory

 summary       summarize working directory state

 update        update working directory (or switch revisions)

(use "hg help" for the full list of commands or "hg -v" for details)

sp11%

sp11%

sp11% hg init hoge                        

sp11% hg clone --debug hoge ssh://release-dev/hoge

running ssh release-dev 'hg init hoge'

running ssh release-dev 'hg -R hoge serve --stdio'

sending hello command

sending between command

remote: 345

remote: capabilities: lookup changegroupsubset branchmap pushkey known getbundle unbundlehash batch stream bundle2=HG20%0Achangegroup%3D01%2C02%0Adigests%3Dmd5%2Csha1%2Csha512%0Aerror%3Dabort%2Cunsupportedcontent%2Cpushraced%2Cpushkey%0Ahgtagsfnodes%0Alistkeys%0Apushkey%0Aremote-changegroup%3Dhttp%2Chttps unbundle=HG10GZ,HG10BZ,HG10UN httpheader=1024

remote: 1

query 1; heads

sending batch command

preparing listkeys for "phases"

sending listkeys command

received listkey for "phases": 15 bytes

checking for updated bookmarks

preparing listkeys for "bookmarks"

sending listkeys command

received listkey for "bookmarks": 0 bytes

差分はありません

preparing listkeys for "phases"

sending listkeys command

received listkey for "phases": 15 bytes

上の場所で止まってしまいます。

[Katsunori FUJIWARA]

藤原です。

2015-12-17 19:42 GMT+09:00 ohira <shin....@gmail.com>:

> ssh 経由の接続でリモートのマシンにcloseを実行すると、ずっと実行
> 中のままプロンプトに帰ってこない現象が発生しました。
>
> 特定のマシンへの接続の場合に発生しています、今回問題が発生した同
> じクライアントマシンから他のマシンにssh経由でclone した場合には
> 発生していません。

>
> このような現象を回避する方法はありますでしょうか？
>
> デバッグオプションをつけて実行したログ
>
> sp11% env LANG=C ssh release-dev env LANG=C hg
> Mercurial Distributed SCM

これまでおおひらさんから質問のあったケースでは、サーバ側で
mercurial-server 等を併用しているケースが多かったのですが、"ssh
release-dev env LANG=C hg" を直接実行できていることから、今回は
mercurial-server 等が間に噛んでいない、という認識でよいですか？

また、release-dev 側における以下の情報を「ssh 経由」で採取してもら
えますか？（ログインして対話的に実行すると、環境設定が変わる可能性
があるので ssh 経由でお願いします）

- "hg version" でのバージョン情報

- "hg config" による設定情報

> sp11% hg init hoge
> sp11% hg clone --debug hoge ssh://release-dev/hoge

以下の点を確認してもらえますか？

- "hg init ssh://release-dev/hoge" 単独実行は正常終了するか？

- 上記の init が成功する場合、その後の
"hg push ssh://release-dev/hoge" 単独実行は正常終了するか？

クライアント側でのコマンド実行時に --config ui.remotecmd="hg --debug"
指定を追加して、サーバ側のデバッグ出力も表示させてみてもらえますか？

> running ssh release-dev 'hg init hoge'
> running ssh release-dev 'hg -R hoge serve --stdio'
> sending hello command
> sending between command
> remote: 345
> remote: capabilities: lookup changegroupsubset branchmap pushkey known
> getbundle unbundlehash batch stream
> bundle2=HG20%0Achangegroup%3D01%2C02%0Adigests%3Dmd5%2Csha1%2Csha512%0Aerror%3Dabort%2Cunsupportedcontent%2Cpushraced%2Cpushkey%0Ahgtagsfnodes%0Alistkeys%0Apushkey%0Aremote-changegroup%3Dhttp%2Chttps
> unbundle=HG10GZ,HG10BZ,HG10UN httpheader=1024
> remote: 1
> query 1; heads
> sending batch command
> preparing listkeys for "phases"
> sending listkeys command
> received listkey for "phases": 15 bytes
> checking for updated bookmarks
> preparing listkeys for "bookmarks"
> sending listkeys command
> received listkey for "bookmarks": 0 bytes
> 差分はありません
> preparing listkeys for "phases"
> sending listkeys command
> received listkey for "phases": 15 bytes
>
> 上の場所で止まってしまいます。

その後は、通常だと単に終了するだけなんですよねぇ……

Mercurial の通信処理周りでの不具合を除いて、無理やり原因をひねり出
すとすれば、サーバ側でフック実行等の延長で処理が止まっている、とか
でしょうか。

- 何らかの排他解放待ちでデッドロックしている
- 何らかの確認／選択等の入力待ちでブロックしてしまっている

先述した release-dev での "hg config" 実行の出力に、不明な hooks
設定があれば、その辺が原因かも。

--
----------------------------------------------------------------------
FUJIWARA Katsunori(flying...@gmail.com)

[ohira]

おおひらです。

[mercurial-server 等が間に噛んでいない、という認識でよいですか？]

はい。そうですrelease-devにはmercurial-serverは入っていません。

通常のmercurialを使っています。

["hg version" でのバージョン情報]

sp11% ssh release-dev env LANG=C hg --version

Mercurial Distributed SCM (version 3.6.1)

(see https://mercurial-scm.org for more information)

Copyright (C) 2005-2015 Matt Mackall and others

This is free software; see the source for copying conditions. There is NO

warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.

["hg config" による設定情報]

sp11% ssh release-dev env LANG=C hg config   

extensions.hgext.convert=

merge-tools.kdiff3.args=--auto --L1 base --L2 local --L3 other $base $local $other -o $output

merge-tools.kdiff3.regkey=Software\KDiff3

merge-tools.kdiff3.regkeyalt=Software\Wow6432Node\KDiff3

merge-tools.kdiff3.regappend=\kdiff3.exe

merge-tools.kdiff3.fixeol=True

merge-tools.kdiff3.gui=True

merge-tools.kdiff3.diffargs=--L1 $plabel1 --L2 $clabel $parent $child

merge-tools.gvimdiff.args=--nofork -d -g -O $local $other $base

merge-tools.gvimdiff.regkey=Software\Vim\GVim

merge-tools.gvimdiff.regkeyalt=Software\Wow6432Node\Vim\GVim

merge-tools.gvimdiff.regname=path

merge-tools.gvimdiff.priority=-9

merge-tools.gvimdiff.diffargs=--nofork -d -g -O $parent $child

merge-tools.vimdiff.args=$local $other $base -c 'redraw | echomsg "hg merge conflict, type \":cq\" to abort vimdiff"'

merge-tools.vimdiff.check=changed

merge-tools.vimdiff.priority=-10

merge-tools.merge.check=conflicts

merge-tools.merge.priority=-100

merge-tools.gpyfm.gui=True

merge-tools.meld.gui=True

merge-tools.meld.args=--label='local' $local --label='merged' $base --label='other' $other -o $output

merge-tools.meld.check=changed

merge-tools.meld.diffargs=-a --label=$plabel1 $parent --label=$clabel $child

merge-tools.tkdiff.args=$local $other -a $base -o $output

merge-tools.tkdiff.gui=True

merge-tools.tkdiff.priority=-8

merge-tools.tkdiff.diffargs=-L $plabel1 $parent -L $clabel $child

merge-tools.xxdiff.args=--show-merged-pane --exit-with-merge-status --title1 local --title2 base --title3 other --merged-filename $output --merge $local $base $other

merge-tools.xxdiff.gui=True

merge-tools.xxdiff.priority=-8

merge-tools.xxdiff.diffargs=--title1 $plabel1 $parent --title2 $clabel $child

merge-tools.diffmerge.regkey=Software\SourceGear\SourceGear DiffMerge\

merge-tools.diffmerge.regkeyalt=Software\Wow6432Node\SourceGear\SourceGear DiffMerge\

merge-tools.diffmerge.regname=Location

merge-tools.diffmerge.priority=-7

merge-tools.diffmerge.args=-nosplash -merge -title1=local -title2=merged -title3=other $local $base $other -result=$output

merge-tools.diffmerge.check=changed

merge-tools.diffmerge.gui=True

merge-tools.diffmerge.diffargs=--nosplash --title1=$plabel1 --title2=$clabel $parent $child

merge-tools.p4merge.args=$base $local $other $output

merge-tools.p4merge.regkey=Software\Perforce\Environment

merge-tools.p4merge.regkeyalt=Software\Wow6432Node\Perforce\Environment

merge-tools.p4merge.regname=P4INSTROOT

merge-tools.p4merge.regappend=\p4merge.exe

merge-tools.p4merge.gui=True

merge-tools.p4merge.priority=-8

merge-tools.p4merge.diffargs=$parent $child

merge-tools.p4mergeosx.executable=/Applications/p4merge.app/Contents/MacOS/p4merge

merge-tools.p4mergeosx.args=$base $local $other $output

merge-tools.p4mergeosx.gui=True

merge-tools.p4mergeosx.priority=-8

merge-tools.p4mergeosx.diffargs=$parent $child

merge-tools.tortoisemerge.args=/base:$base /mine:$local /theirs:$other /merged:$output

merge-tools.tortoisemerge.regkey=Software\TortoiseSVN

merge-tools.tortoisemerge.regkeyalt=Software\Wow6432Node\TortoiseSVN

merge-tools.tortoisemerge.check=changed

merge-tools.tortoisemerge.gui=True

merge-tools.tortoisemerge.priority=-8

merge-tools.tortoisemerge.diffargs=/base:$parent /mine:$child /basename:$plabel1 /minename:$clabel

merge-tools.ecmerge.args=$base $local $other --mode=merge3 --title0=base --title1=local --title2=other --to=$output

merge-tools.ecmerge.regkey=Software\Elli\xc3\xa9 Computing\Merge

merge-tools.ecmerge.regkeyalt=Software\Wow6432Node\Elli\xc3\xa9 Computing\Merge

merge-tools.ecmerge.gui=True

merge-tools.ecmerge.diffargs=$parent $child --mode=diff2 --title1=$plabel1 --title2=$clabel

merge-tools.editmerge.args=$output

merge-tools.editmerge.check=changed

merge-tools.editmerge.premerge=keep

merge-tools.filemerge.executable=/Developer/Applications/Utilities/FileMerge.app/Contents/MacOS/FileMerge

merge-tools.filemerge.args=-left $other -right $local -ancestor $base -merge $output

merge-tools.filemerge.gui=True

merge-tools.filemergexcode.executable=/Applications/Xcode.app/Contents/Applications/FileMerge.app/Contents/MacOS/FileMerge

merge-tools.filemergexcode.args=-left $other -right $local -ancestor $base -merge $output

merge-tools.filemergexcode.gui=True

merge-tools.beyondcompare3.args=$local $other $base $output /ro /lefttitle=local /centertitle=base /righttitle=other /automerge /reviewconflicts /solo

merge-tools.beyondcompare3.regkey=Software\Scooter Software\Beyond Compare 3

merge-tools.beyondcompare3.regname=ExePath

merge-tools.beyondcompare3.gui=True

merge-tools.beyondcompare3.priority=-2

merge-tools.beyondcompare3.diffargs=/lro /lefttitle=$plabel1 /righttitle=$clabel /solo /expandall $parent $child

merge-tools.bcompare.args=$local $other $base -mergeoutput=$output -ro -lefttitle=parent1 -centertitle=base -righttitle=parent2 -outputtitle=merged -automerge -reviewconflicts -solo

merge-tools.bcompare.gui=True

merge-tools.bcompare.priority=-1

merge-tools.bcompare.diffargs=-lro -lefttitle=$plabel1 -righttitle=$clabel -solo -expandall $parent $child

merge-tools.bcomposx.executable=/Applications/Beyond Compare.app/Contents/MacOS/bcomp

merge-tools.bcomposx.args=$local $other $base -mergeoutput=$output -ro -lefttitle=parent1 -centertitle=base -righttitle=parent2 -outputtitle=merged -automerge -reviewconflicts -solo

merge-tools.bcomposx.gui=True

merge-tools.bcomposx.priority=-1

merge-tools.bcomposx.diffargs=-lro -lefttitle=$plabel1 -righttitle=$clabel -solo -expandall $parent $child

merge-tools.winmerge.args=/e /x /wl /ub /dl other /dr local $other $local $output

merge-tools.winmerge.regkey=Software\Thingamahoochie\WinMerge

merge-tools.winmerge.regkeyalt=Software\Wow6432Node\Thingamahoochie\WinMerge\

merge-tools.winmerge.regname=Executable

merge-tools.winmerge.check=changed

merge-tools.winmerge.gui=True

merge-tools.winmerge.priority=-10

merge-tools.winmerge.diffargs=/r /e /x /ub /wl /dl $plabel1 /dr $clabel $parent $child

merge-tools.araxis.regkey=SOFTWARE\Classes\TypeLib\{46799e0a-7bd1-4330-911c-9660bb964ea2}\7.0\HELPDIR

merge-tools.araxis.regappend=\ConsoleCompare.exe

merge-tools.araxis.priority=-2

merge-tools.araxis.args=/3 /a2 /wait /merge /title1:"Other" /title2:"Base" /title3:"Local :"$local $other $base $local $output

merge-tools.araxis.checkconflict=True

merge-tools.araxis.binary=True

merge-tools.araxis.gui=True

merge-tools.araxis.diffargs=/2 /wait /title1:$plabel1 /title2:$clabel $parent $child

merge-tools.diffuse.priority=-3

merge-tools.diffuse.args=$local $base $other

merge-tools.diffuse.gui=True

merge-tools.diffuse.diffargs=$parent $child

merge-tools.UltraCompare.regkey=Software\Microsoft\Windows\CurrentVersion\App Paths\UC.exe

merge-tools.UltraCompare.regkeyalt=Software\Wow6432Node\Microsoft\Windows\CurrentVersion\App Paths\UC.exe

merge-tools.UltraCompare.args=$base $local $other -title1 base -title3 other

merge-tools.UltraCompare.priority=-2

merge-tools.UltraCompare.gui=True

merge-tools.UltraCompare.binary=True

merge-tools.UltraCompare.check=conflicts,changed

merge-tools.UltraCompare.diffargs=$child $parent -title1 $clabel -title2 $plabel1

ui.username=(estore@release-dev)

sp11% 

["hg init ssh://release-dev/hoge" 単独実行は正常終了するか？]

正常終了せず。止まってしまいます。

sp11% hg init --debug ssh://release-dev/hoge

running ssh release-dev 'hg init hoge'

running ssh release-dev 'hg -R hoge serve --stdio'

sending hello command

sending between command

remote: 345

remote: capabilities: lookup changegroupsubset branchmap pushkey known getbundle unbundlehash batch stream bundle2=HG20%0Achangegroup%3D01%2C02%0Adigests%3Dmd5%2Csha1%2Csha512%0Aerror%3Dabort%2Cunsupportedcontent%2Cpushraced%2Cpushkey%0Ahgtagsfnodes%0Alistkeys%0Apushkey%0Aremote-changegroup%3Dhttp%2Chttps unbundle=HG10GZ,HG10BZ,HG10UN httpheader=1024

remote: 1

この上で止まってしまいます。プロンプトに戻ってきません。

[クライアント側でのコマンド実行時に --config ui.remotecmd="hg --debug" 

指定を追加して、サーバ側のデバッグ出力も表示させてみてもらえますか？]

sp11% hg --config ui.remotecmd="hg --debug" init ssh://release-dev/hoge

bash: hg --debug: command not found

中止: 指定リポジトリとの連携に失敗!

sp11%

2015年12月17日木曜日 20時49分00秒 UTC+9 FUJIWARA Katsunori:

[Katsunori FUJIWARA]

藤原です。

2015年12月18日 10:37 ohira <shin....@gmail.com>:

> [mercurial-server 等が間に噛んでいない、という認識でよいですか？]
> はい。そうですrelease-devにはmercurial-serverは入っていません。
> 通常のmercurialを使っています。

これで多少は作業が楽になりそうです（笑）

> ["hg version" でのバージョン情報]
> sp11% ssh release-dev env LANG=C hg --version
> Mercurial Distributed SCM (version 3.6.1)
> (see https://mercurial-scm.org for more information)
>
> Copyright (C) 2005-2015 Matt Mackall and others
> This is free software; see the source for copying conditions. There is NO
> warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.
>
>
> ["hg config" による設定情報]
> sp11% ssh release-dev env LANG=C hg config
> extensions.hgext.convert=

出力を見る限りでは、convert エクステンションの有効化以外は、マージ
ツール設定のみみたいですから、フック等の設定周りの問題ではなさそう
ですね。

> ["hg init ssh://release-dev/hoge" 単独実行は正常終了するか？]
> 正常終了せず。止まってしまいます。
>
> sp11% hg init --debug ssh://release-dev/hoge
> running ssh release-dev 'hg init hoge'
> running ssh release-dev 'hg -R hoge serve --stdio'
> sending hello command
> sending between command
> remote: 345
> remote: capabilities: lookup changegroupsubset branchmap pushkey known
> getbundle unbundlehash batch stream
> bundle2=HG20%0Achangegroup%3D01%2C02%0Adigests%3Dmd5%2Csha1%2Csha512%0Aerror%3Dabort%2Cunsupportedcontent%2Cpushraced%2Cpushkey%0Ahgtagsfnodes%0Alistkeys%0Apushkey%0Aremote-changegroup%3Dhttp%2Chttps
> unbundle=HG10GZ,HG10BZ,HG10UN httpheader=1024
> remote: 1
> この上で止まってしまいます。プロンプトに戻ってきません。

この感じだと、実質的なやりとりが無くても "hg serve --stdio" との連
携で詰まっている感じですね。

ssh での非対話コマンド実行自体は、特に問題なく出来ているみたいです
から、プロトコル上の問題か、I/O でのバッファリング周りの話かなぁ。

ちなみに、release-dev の環境はどのようなものでしょうか？

- uname -a

- python --version

head `which hg` 出力の一行目を見て、hg コマンド実行で実際に使
用される python インタプリンタを特定した上で確認してください。

もしも /usr/bin/env python 等の記述になっている場合は、環境設
定周りの影響を受けるので、以下のような感じで、ssh 経由で確認し
てください。

ssh release-dev /usr/bin/env python --version

> [クライアント側でのコマンド実行時に --config ui.remotecmd="hg --debug"
> 指定を追加して、サーバ側のデバッグ出力も表示させてみてもらえますか？]
>
> sp11% hg --config ui.remotecmd="hg --debug" init ssh://release-dev/hoge
> bash: hg --debug: command not found
> 中止: 指定リポジトリとの連携に失敗!
> sp11%

おっと、この形式だと 'hg --debug' が単一引数扱いされてしまいますね。
失礼しました。

以下の手順を実施して、(3)～(4) でのコマンド出力を採取してもらえま
すか？


1. release-dev に ssh ログインして直接 hg init hoge を実施

2. release-dev 側の hoge/.hg/hgrc に以下の設定を記述

[ui]
debug=true

3. クライアント側で --debug --traceback 付きで
hg push ssh://release-dev/hoge を実施

4. コマンドが終了せずに停止する筈なので、Ctrl-C で中断


ちなみに、サーバ側に hg の 3.5 とか 3.4 等の少し古い版があるならば、
クライアント側で --config ui.remotecmd="/path/to/3.5/hg" 等を指定
して、同様の問題が発生するかも確認してみてください。

--
----------------------------------------------------------------------
FUJIWARA Katsunori(flying...@gmail.com)

[ohira]

大平です。

回答ありがとうございます。

テスト実行したログです。

sp11% ssh release-dev uname -a                  

Linux release-dev 2.6.18-238.19.1.el5 #1 SMP Fri Jul 15 07:31:24 EDT 2011 x86_64 x86_64 x86_64 GNU/Linux

sp11% ssh release-dev which hg

/usr/local/bin/hg

sp11% ssh release-dev head /usr/local/bin/hg

#!/usr/local/bin/python

#

# mercurial - scalable distributed SCM

#

# Copyright 2005-2007 Matt Mackall <m...@selenic.com>

#

# This software may be used and distributed according to the terms of the

# GNU General Public License version 2 or any later version.

import os

sp11% ssh release-dev /usr/local/bin/python --version

Python 2.7.10

sp11% 

sp11% 

sp11% ssh release-dev hg init hoge                   

sp11% 

sp11% ssh release-dev ls -lsd hoge

4 drwxrwxr-x 3 estore estore 4096 12�� 18 14:12 hoge

sp11% ssh release-dev cat hoge/.hg/hgrc

[ui]

debug=true

sp11% hg push --debug --traceback ssh://release-dev/hoge

Traceback (most recent call last):

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 163, in _runcatch

    return _dispatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 880, in _dispatch

    % os.getcwd())

RepoError: '/usr/home/estore' 配下にはリポジトリがありません (.hg が見つかりません)

中止: '/usr/home/estore' 配下にはリポジトリがありません (.hg が見つかりません)!

sp11% hg clone ssh://hg@localhost/hoge 

複製先ディレクトリ: hoge

全リビジョンを取得中

リビジョンを追加中

マニフェストを追加中

ファイルの変更を追加中

88 個のリビジョン(32 の変更を 16 ファイルに適用)を追加 (+1個のヘッド)

ブランチ default へ更新中

ファイルの更新数 9、 マージ数 0、 削除数 0、 衝突未解消数 0

sp11% cd hoge

sp11% hg push --debug --traceback ssh://release-dev/hoge

ssh://release-dev/hoge への反映中

running ssh release-dev 'hg -R hoge serve --stdio'

sending hello command

sending between command

remote: could not import hgext.hgext.convert (No module named hgext.convert): trying hgext.convert

remote: 345

remote: capabilities: lookup changegroupsubset branchmap pushkey known getbundle unbundlehash batch stream bundle2=HG20%0Achangegroup%3D01%2C02%0Adigests%3Dmd5%2Csha1%2Csha512%0Aerror%3Dabort%2Cunsupportedcontent%2Cpushraced%2Cpushkey%0Ahgtagsfnodes%0Alistkeys%0Apushkey%0Aremote-changegroup%3Dhttp%2Chttps unbundle=HG10GZ,HG10BZ,HG10UN httpheader=1024

remote: 1

query 1; heads

sending batch command

変更点を探索中

taking quick initial sample

query 2; still undecided: 86, sample size is: 86

sending known command

2 total queries

preparing listkeys for "phases"

sending listkeys command

連携先: listing keys for "phases"

received listkey for "phases": 15 bytes

checking for updated bookmarks

preparing listkeys for "bookmarks"

sending listkeys command

連携先: listing keys for "bookmarks"

received listkey for "bookmarks": 0 bytes

88 個のリビジョンがあります

list of changesets:

3b9e5ab570b7995f42cc5ca1de8750971357979e

1b15f63c0478b28969f864312564ad1828a29da9

bf2e29e5044e67202cb648146369a47fcaf872d8

a69ee1695dd96f8779bca7ee1d2106c088ebcf60

d5f8fcc0fa3dc7ecccd2c760ce37fbb78e08c193

6c8249bffee437238d54c6b9f5c81f1bcb926339

0d8f36a22a2fc9379102301e6630373aa82cc5e4

aaaabda5b6e91a6827b330e6d82a87bdff8d3441

c4dc55170b16eb64792bae96f7d0f4f040979c54

49967659ea43aa33c881224d0702cd10187cbbae

60d706e859f2166974b1f57b8e6786c67f5c1961

795f190ee5b9c7ea633915d78d57af37c850f141

48294485b2ef7e934dd51e5eb2294b96364f2b92

861611545177fb3374a57ea63f75da857654c1ab

b0dd4876b1f309bb001977859a1a9592c7f557c0

fef5e639bf8c22d0eda27a919d4b425c2eef2c34

84a02ceac1b4ac607be56680bf4dbbdc7aea9a92

428dae0e0a38ee92bdc7746927f1e92f3be8f8f9

8e49d4bb8ef36ebfdb19d3e83535554363bb4706

77c4dde4074873aa6783cc15887a74db8ebbfda8

4ec1fd9fe5e650184de9a6de8c5d90e62e8fb2f6

f6df8d5893173a1a554b334e5189ad0b075f3875

33f16c4849021565d035a45a5223181043d95816

b828250b2a4b2d4d14b18f9554e413a876b97bd8

bd39072b26a5e58e1879e9f77236ee4f5409b932

889dfd83c7cdd2fef670f17adde32d0a64c52291

4940cda31b1295f9197a9ed5d8910d7514ebb802

bcf638c48c019ba4782e8cefdb95f7b2de0cbc45

4b81208df39e012fd192053c70910d97ed9e758d

4f86efdb9ac1d6e054d0d678f05dfbe9bdfe2aa4

d5b4138abc3831c3fd3cc6876c6eb3af9aec71d1

b319e76be91d1d6da7e656af527c1522c4adf5c1

9b56503455c02c91fc51d95eb9ed77b696448d79

ccf5c5f2a0c7b0886e7af651b7facb6737eaa6a1

bfa00dd7e22d6a91ca8f24995dd78f8e75afa38e

d138d4e19ab09397d5fc9f10250715a5aa174b15

365fc0637f4eb81e2ad653801860e63abb5c7685

38edbeb25bdd322a48ce8c712107b0cde60a003c

ed4ca2b93a94e3ad893ef75c2f5100e774d94cea

830c14fb71429517649329b8d67f34558c73b5c9

bf8ee1c56bbea951815eb218ea8b46866eef379e

e9b28f4fe23b165ffd22c34fc1e9e4ad5f2a1ef2

2c850d5fa714e42621969f01761d8493cdc5a3d0

5b90dba7687088522c9f1cc8b5d141ec095d44ea

dd6e0a14c118f7fbd7e5f55b3353650675f7c2fd

bc5935b2512f356919fce1fb47c86143c5c31cfa

1663c983c6bd6efc0b270fe20cead939eb711586

f442543b415ff11a32e1943093dc86f643ce57e6

8983b4b480ef762eea7d81edb93cc389c719381e

f6e9c0190b009ac0e7d33930ee7cccf9b7ad36ad

5fe2fb4a97365a97eead41e0d6cdfb00671e7a54

9dfb4bc39d550a823862498edd24fe3df63a9fe3

9a2e304c98c64163236b0308a182a0ad2c0de2d6

430b48277a0f5428035fdf922082c4f2322a1d22

cd0eb70ead50848aa14b791295e041b4b77afea7

8bd86b129955fed2cc26bc44983433eee0894a50

943b97295414644e8845b2a39977772b6cde33d5

fca03f0db623f9bed22fc0f5a5f617586d81daa0

cc07b0f44d28a612c29e6bc6d40cbe53c628ed8f

e774cf983e08f3169ccaefe202cff1b59d6b2c0d

f659857f250b83356390650f72794322d7a87c4f

5583b0bce2693ceefa909594ef1692e1176cb634

45f5d5ad684d09d5b36dd6731e4dedb03e696282

7c11396ecd72df2a8068165dba23857ef836363f

ac5cdb368b1705b1fd1d366bec5fa120f084424e

17e8f9470032842702288629ea049789ee888b9d

7104f68610ca4e87ff6fe50cc4e2328e9fad0927

40a0abd7eb4886b04549a679008c17bd0909f982

cca94a0d4716b7e6e67367f71e167086072661d1

5cf093744bf16e891930be08da40e2a3ef2828e5

bebbd7c5831bbf0fe5a727eac111b89e093827c3

72eecedbe7ccec97d3a3cf3cf57ecd70d7863383

e25e5570fe9d33784f88fc5cb61766ef89b46454

7300649e2d69080ecfea673ee8786978a19d4d8d

59a72bb0a2df6de9bfb035dbcc2373c75889cd31

98e57026c69280c660dabdb996f7cf8323b28306

a4fb9b0bb28c632406502a9bb07ea6a10d0627ef

eff1408401d1db61c786648ed7141c9f1e9038d9

5bba35ef1c1d4bf947b162c164461c7f70b98ae8

08468118b39af2eb425aabbde1fa7876a2d55f8b

f1e34f8f7cd84b9e896ab93697d3d79f0da644e4

666953a386c1288d9cf47d5cd39346c82c0b1057

84d0fb302cfe86373488f9b1d1d67e30097fe06e

a92f74015ad7071b2e5d8baa71e9008f0d43962e

87f90acdc031a8bdba11f80bb0ff6c1be6b2b377

ab353537d30b90d545842b7ebe5544cef59584c1

233cc0ec61959f21fc25bb5dd4931cd40c666f9f

783e247ffa9a1d91ccf3920088fcb8c2cb22761f

sending unbundle command

bundle2-output-bundle: "HG20", 5 parts total

bundle2-output-part: "replycaps" 155 bytes payload

bundle2-output-part: "check:heads" streamed payload

bundle2-output-part: "changegroup" (params: 1 mandatory) streamed payload

^CTraceback (most recent call last):

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 163, in _runcatch

    return _dispatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 895, in _dispatch

    cmdpats, cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 656, in runcommand

    ret = _runcommand(ui, options, cmd, d)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 1013, in _runcommand

    return checkargs()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 982, in checkargs

    return cmdfunc()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 892, in <lambda>

    d = lambda: util.checksignature(func)(ui, *args, **cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/util.py", line 792, in check

    return func(*args, **kwargs)

  File "/usr/local/lib/python2.7/site-packages/mercurial/commands.py", line 5286, in push

    bookmarks=opts.get('bookmark', ()))

  File "/usr/local/lib/python2.7/site-packages/mercurial/exchange.py", line 240, in push

    _pushbundle2(pushop)

  File "/usr/local/lib/python2.7/site-packages/mercurial/exchange.py", line 650, in _pushbundle2

    reply = pushop.remote.unbundle(stream, ['force'], 'push')

KeyboardInterrupt

中断されました!

Exception RuntimeError: 'generator ignored GeneratorExit' in <generator object getchunks at 0x29080194> ignored

bundle2-input-stream-interrupt: encoding exception 連携先: Killed by signal 2.

連携先: Killed by signal 2.

sp11% pwd

/home/estore/hoge

sp11% cd ..

sp11% rm -rf hoge

sp11% hg init hoge

sp11% cd hoge

sp11% hg push --debug --traceback ssh://release-dev/hoge

ssh://release-dev/hoge への反映中

running ssh release-dev 'hg -R hoge serve --stdio'

sending hello command

sending between command

remote: could not import hgext.hgext.convert (No module named hgext.convert): trying hgext.convert

remote: 345

remote: capabilities: lookup changegroupsubset branchmap pushkey known getbundle unbundlehash batch stream bundle2=HG20%0Achangegroup%3D01%2C02%0Adigests%3Dmd5%2Csha1%2Csha512%0Aerror%3Dabort%2Cunsupportedcontent%2Cpushraced%2Cpushkey%0Ahgtagsfnodes%0Alistkeys%0Apushkey%0Aremote-changegroup%3Dhttp%2Chttps unbundle=HG10GZ,HG10BZ,HG10UN httpheader=1024

remote: 1

query 1; heads

sending batch command

preparing listkeys for "phases"

sending listkeys command

連携先: listing keys for "phases"

received listkey for "phases": 15 bytes

checking for updated bookmarks

preparing listkeys for "bookmarks"

sending listkeys command

連携先: listing keys for "bookmarks"

received listkey for "bookmarks": 0 bytes

差分はありません

preparing listkeys for "phases"

sending listkeys command

連携先: listing keys for "phases"

received listkey for "phases": 15 bytes

^CException KeyboardInterrupt: KeyboardInterrupt() in <bound method sshpeer.cleanup of <mercurial.sshpeer.sshpeer object at 0x289314ac>> ignored

sp11%

sp11% ssh release-dev cd hoge; hg log 

sp11% ssh release-dev cd hoge; hg sum

親リビジョン: -1:000000000000 tip (空のリポジトリ)

ブランチ:     default

作業領域状態: (変更無し)

update 候補:  (現行親リビジョン)

sp11% ssh release-dev cd hoge; hg --debug --traceback sum

親リビジョン: -1:000000000000 tip (空のリポジトリ)

ブランチ:     default

作業領域状態: (変更無し)

update 候補:  (現行親リビジョン)

sp11%

sp11% ssh -vvv release-dev env LANG=C hg

OpenSSH_5.1p1 FreeBSD-20080901, OpenSSL 0.9.8e 23 Feb 2007

debug1: Reading configuration data /home/estore/.ssh/config

debug1: Applying options for release-dev

debug1: Reading configuration data /etc/ssh/ssh_config

debug2: ssh_connect: needpriv 0

debug1: Executing proxy command: exec nohup ssh co122 nc  release-dev.mxfw.net 22

debug1: permanently_drop_suid: 1032

debug1: identity file /home/estore/.ssh/identity type -1

debug3: Not a RSA1 key file /home/estore/.ssh/id_rsa.

debug2: key_type_from_name: unknown key type '-----BEGIN'

debug3: key_read: missing keytype

debug3: key_read: missing whitespace

debug3: key_read: missing whitespace

debug3: key_read: missing whitespace

debug3: key_read: missing whitespace

debug3: key_read: missing whitespace

debug3: key_read: missing whitespace

debug3: key_read: missing whitespace

debug3: key_read: missing whitespace

debug3: key_read: missing whitespace

debug3: key_read: missing whitespace

debug3: key_read: missing whitespace

debug3: key_read: missing whitespace

debug3: key_read: missing whitespace

debug3: key_read: missing whitespace

debug3: key_read: missing whitespace

debug3: key_read: missing whitespace

debug3: key_read: missing whitespace

debug3: key_read: missing whitespace

debug3: key_read: missing whitespace

debug3: key_read: missing whitespace

debug3: key_read: missing whitespace

debug3: key_read: missing whitespace

debug3: key_read: missing whitespace

debug3: key_read: missing whitespace

debug3: key_read: missing whitespace

debug2: key_type_from_name: unknown key type '-----END'

debug3: key_read: missing keytype

debug1: identity file /home/estore/.ssh/id_rsa type 1

debug1: identity file /home/estore/.ssh/id_dsa type -1

debug1: Remote protocol version 2.0, remote software version OpenSSH_4.3

debug1: match: OpenSSH_4.3 pat OpenSSH*

debug1: Enabling compatibility mode for protocol 2.0

debug1: Local version string SSH-2.0-OpenSSH_5.1p1 FreeBSD-20080901

debug2: fd 5 setting O_NONBLOCK

debug2: fd 4 setting O_NONBLOCK

debug1: SSH2_MSG_KEXINIT sent

debug1: SSH2_MSG_KEXINIT received

debug2: kex_parse_kexinit: diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1

debug2: kex_parse_kexinit: ssh-dss,ssh-rsa

debug2: kex_parse_kexinit: aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour128,arcfour256,arcfour,aes192-cbc,aes256-cbc,rijnda...@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr

debug2: kex_parse_kexinit: aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour128,arcfour256,arcfour,aes192-cbc,aes256-cbc,rijnda...@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr

debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,uma...@openssh.com,hmac-ripemd160,hmac-ri...@openssh.com,hmac-sha1-96,hmac-md5-96

debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,uma...@openssh.com,hmac-ripemd160,hmac-ri...@openssh.com,hmac-sha1-96,hmac-md5-96

debug2: kex_parse_kexinit: none,zl...@openssh.com,zlib

debug2: kex_parse_kexinit: none,zl...@openssh.com,zlib

debug2: kex_parse_kexinit: 

debug2: kex_parse_kexinit: 

debug2: kex_parse_kexinit: first_kex_follows 0 

debug2: kex_parse_kexinit: reserved 0 

debug2: kex_parse_kexinit: diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1

debug2: kex_parse_kexinit: ssh-rsa,ssh-dss

debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijnda...@lysator.liu.se

debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijnda...@lysator.liu.se

debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ri...@openssh.com,hmac-sha1-96,hmac-md5-96

debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ri...@openssh.com,hmac-sha1-96,hmac-md5-96

debug2: kex_parse_kexinit: none,zl...@openssh.com

debug2: kex_parse_kexinit: none,zl...@openssh.com

debug2: kex_parse_kexinit: 

debug2: kex_parse_kexinit: 

debug2: kex_parse_kexinit: first_kex_follows 0 

debug2: kex_parse_kexinit: reserved 0 

debug2: mac_setup: found hmac-md5

debug1: kex: server->client aes128-cbc hmac-md5 none

debug2: mac_setup: found hmac-md5

debug1: kex: client->server aes128-cbc hmac-md5 none

debug1: SSH2_MSG_KEX_DH_GEX_REQUEST(1024<1024<8192) sent

debug1: expecting SSH2_MSG_KEX_DH_GEX_GROUP

debug2: dh_gen_key: priv key bits set: 119/256

debug2: bits set: 486/1024

debug1: SSH2_MSG_KEX_DH_GEX_INIT sent

debug1: expecting SSH2_MSG_KEX_DH_GEX_REPLY

debug3: check_host_in_hostfile: filename /home/estore/.ssh/known_hosts

debug3: check_host_in_hostfile: match line 21

debug1: Host 'release-dev.mxfw.net' is known and matches the DSA host key.

debug1: Found key in /home/estore/.ssh/known_hosts:21

debug2: bits set: 519/1024

debug1: ssh_dss_verify: signature correct

debug2: kex_derive_keys

debug2: set_newkeys: mode 1

debug1: SSH2_MSG_NEWKEYS sent

debug1: expecting SSH2_MSG_NEWKEYS

debug2: set_newkeys: mode 0

debug1: SSH2_MSG_NEWKEYS received

debug1: SSH2_MSG_SERVICE_REQUEST sent

debug2: service_accept: ssh-userauth

debug1: SSH2_MSG_SERVICE_ACCEPT received

debug2: key: /home/estore/.ssh/identity (0x0)

debug2: key: /home/estore/.ssh/id_rsa (0x28435e30)

debug2: key: /home/estore/.ssh/id_dsa (0x0)

debug1: Authentications that can continue: publickey,gssapi-with-mic,password

debug3: start over, passed a different list publickey,gssapi-with-mic,password

debug3: preferred publickey,keyboard-interactive,password

debug3: authmethod_lookup publickey

debug3: remaining preferred: keyboard-interactive,password

debug3: authmethod_is_enabled publickey

debug1: Next authentication method: publickey

debug1: Trying private key: /home/estore/.ssh/identity

debug3: no such identity: /home/estore/.ssh/identity

debug1: Offering public key: /home/estore/.ssh/id_rsa

debug3: send_pubkey_test

debug2: we sent a publickey packet, wait for reply

debug1: Server accepts key: pkalg ssh-rsa blen 277

debug2: input_userauth_pk_ok: fp 68:52:01:a5:63:4d:14:53:a7:f5:3c:a9:da:56:c8:ee

debug3: sign_and_send_pubkey

debug1: read PEM private key done: type RSA

debug1: Authentication succeeded (publickey).

debug1: channel 0: new [client-session]

debug3: ssh_session2_open: channel_new: 0

debug2: channel 0: send open

debug1: Requesting no-more-...@openssh.com

debug1: Entering interactive session.

debug2: callback start

debug2: client_session2_setup: id 0

debug1: Sending command: env LANG=C hg

debug2: channel 0: request exec confirm 1

debug2: callback done

debug2: channel 0: open confirm rwindow 0 rmax 32768

debug2: channel 0: rcvd adjust 2097152

debug2: channel_input_confirm: type 99 id 0

debug2: exec request accepted on channel 0

Mercurial Distributed SCM

basic commands:

 add           add the specified files on the next commit

 annotate      show changeset information by line for each file

 clone         make a copy of an existing repository

 commit        commit the specified files or all outstanding changes

 diff          diff repository (or selected files)

 export        dump the header and diffs for one or more changesets

 forget        forget the specified files on the next commit

 init          create a new repository in the given directory

 log           show revision history of entire repository or files

 merge         merge another revision into working directory

 pull          pull changes from the specified source

 push          push changes to the specified destination

 remove        remove the specified files on the next commit

 serve         start stand-alone webserver

 status        show changed files in the working directory

 summary       summarize working directory state

 update        update working directory (or switch revisions)

(use "hg help" for the full list of commands or "hg -v" for details)

debug2: channel 0: rcvd eof

debug2: channel 0: output open -> drain

debug2: channel 0: obuf empty

debug2: channel 0: close_write

debug2: channel 0: output drain -> closed

debug1: client_input_channel_req: channel 0 rtype exit-status reply 0

debug2: channel 0: rcvd close

debug2: channel 0: close_read

debug2: channel 0: input open -> closed

debug3: channel 0: will not send data after close

debug2: channel 0: almost dead

debug2: channel 0: gc: notify user

debug2: channel 0: gc: user detached

debug2: channel 0: send close

debug2: channel 0: is dead

debug2: channel 0: garbage collecting

debug1: channel 0: free: client-session, nchannels 1

debug3: channel 0: status: The following connections are open:

  #0 client-session (t4 r0 i3/0 o3/0 fd -1/-1 cfd -1)

debug3: channel 0: close_fds r -1 w -1 e 7 c -1

Transferred: sent 2192, received 3224 bytes, in 0.3 seconds

Bytes per second: sent 7298.8, received 10735.1

debug1: Exit status 0

sp11%

2015年12月18日金曜日 12時12分34秒 UTC+9 FUJIWARA Katsunori:

[Katsunori FUJIWARA]

藤原です。

情報採取ありがとうございます。

以下に頂いた情報をまとめておきます。念のため、クライアント側の情報
も頂けますか？


サーバ側
--------- ----------------------
OS x86 Linux
(2.6.18-238.19.1.el5)

Python 2.7.10

Mercurial 3.6.1
--------- ----------------------

2015年12月18日 15:10 ohira <shin....@gmail.com>:

> テスト実行したログです。

(snip)

(snip)

bundle2 での連携過程でアレしているっぽい感じですね。

既知の障害で何か心当たりってあります？ ＞ 西原さん

お手数ですが、以下の手順を実施してもらえますか？

1. サーバ側に空リポジトリ foo を作成

foo/.hg/hgrc に以下の記述を追加:

[experimental]
bundle2-exp = false
bundle2-advertise = false

2. クライアント側に空リポジトリ foo を作成

foo/.hg/hgrc に以下の記述を追加:

[experimental]
bundle2-exp = false
bundle2-advertise = false

3. クライアント側の foo から ssh 経由で hg outgoing を実施

4. クライアント側の foo から ssh 経由で hg push を実施

5. クライアント側の foo から ssh 経由で hg incoming を実施

6. クライアント側の foo から ssh 経由で hg pull を実施

上記 3. ～ 6. の各実行はブロックするか？

ブロックするなら、--traceback 付き実行で ^C 中断して、スタッ
クトレースを採取

(Python の場合、kill -TERM か kill -INT で外から中断させた方
が良かったりしますかね？ > 識者)

7. 上記 3. ～ 6. の各実行がブロック「しなかった」場合は:

- サーバ側／クライアント側双方の hgrc の設定から、
experimental セクションの記述を除外

- サーバ側／クライアント側双方の hgrc の設定に、以下の記述を
追加:

[devel]
bundle2.debug = true

- 先述した 3. ～ 6. を再実行

その際に実行がブロックするなら、--traceback 付き実行で ^C
中断して、スタックトレースを採取

想定では、bundle2 使用を禁止した場合は、サックリ動いてくれると思う
（動いて欲しい）のですが……

--
----------------------------------------------------------------------
FUJIWARA Katsunori(flying...@gmail.com)

[ohira]

おおひらです。

テストの結果をお知らせいたします。

[クライアントマシンの情報]

sp11% uname -a                       

FreeBSD sp11.mxfw.net 7.2-STABLE FreeBSD 7.2-STABLE #0: Mon Aug 10 18:54:40 JST 2009     ro...@sp11.mxfw.net:/usr/obj/usr/src/sys/MYKERNEL  i386

sp11% hg --version                   

Mercurial - 分散構成管理ツール(バージョン 3.5.2)

(詳細は http://mercurial.selenic.com を参照)

Copyright (C) 2005-2015 Matt Mackall 他

本製品はフリーソフトウェアです。

頒布条件に関しては同梱されるライセンス条項をお読みください。

市場適合性や特定用途への可否を含め、 本製品は無保証です。

sp11% head `which hg`                

#!/usr/local/bin/python

#

# mercurial - scalable distributed SCM

#

# Copyright 2005-2007 Matt Mackall <m...@selenic.com>

#

# This software may be used and distributed according to the terms of the

# GNU General Public License version 2 or any later version.

import os

sp11% /usr/local/bin/python --version

Python 2.7.10

sp11% 

[テストの準備]

sp11% cd

sp11% ssh release-dev hg init foo

sp11% hg init foo

sp11% ssh release-dev cat foo/.hg/hgrc

[experimental] 

bundle2-exp = false 

bundle2-advertise = false

sp11% cat foo/.hg/hgrc 

[experimental] 

bundle2-exp = false 

bundle2-advertise = false

sp11%

[configの確認]

sp11% hg config

bundle.mainreporoot=/usr/home/estore/foo

experimental.bundle2-exp=false

experimental.bundle2-advertise=false

trusted.users=hg

trusted.groups=hg

ui.username=estore

sp11% ssh release-dev hg config

[テストsono1]

sp11% cd foo

sp11% hg outgoing ssh://release-dev/foo

ssh://release-dev/foo と比較中

差分はありません

^CException KeyboardInterrupt: KeyboardInterrupt() in <bound method sshpeer.cleanup of <mercurial.sshpeer.sshpeer object at 0x289314ac>> ignored

sp11% hg push ssh://release-dev/foo

ssh://release-dev/foo への反映中

差分はありません

^CException KeyboardInterrupt: KeyboardInterrupt() in <bound method sshpeer.cleanup of <mercurial.sshpeer.sshpeer object at 0x2893152c>> ignored

sp11% hg incoming ssh://release-dev/foo

ssh://release-dev/foo と比較中

差分はありません

^CException KeyboardInterrupt: KeyboardInterrupt() in <bound method sshpeer.cleanup of <mercurial.sshpeer.sshpeer object at 0x284c038c>> ignored

sp11% hg pull ssh://release-dev/foo

ssh://release-dev/foo から取り込み中

差分はありません

^CException KeyboardInterrupt: KeyboardInterrupt() in <bound method sshpeer.cleanup of <mercurial.sshpeer.sshpeer object at 0x289314ac>> ignored

sp11% 

[テストsono2]

sp11% cd foo

sp11% hg outgoing ssh://release-dev/foo --traceback

ssh://release-dev/foo と比較中

差分はありません

^CException KeyboardInterrupt: KeyboardInterrupt() in <bound method sshpeer.cleanup of <mercurial.sshpeer.sshpeer object at 0x2893256c>> ignored

sp11% hg push ssh://release-dev/foo --traceback

ssh://release-dev/foo への反映中

差分はありません

^CException KeyboardInterrupt: KeyboardInterrupt() in <bound method sshpeer.cleanup of <mercurial.sshpeer.sshpeer object at 0x289325ec>> ignored

sp11% hg incoming ssh://release-dev/foo --traceback

ssh://release-dev/foo と比較中

差分はありません

Exception mercurial.error.SignalInterrupt: SignalInterrupt() in <bound method sshpeer.cleanup of <mercurial.sshpeer.sshpeer object at 0x284c03ac>> ignored

sp11% hg pull ssh://release-dev/foo --traceback

ssh://release-dev/foo から取り込み中

差分はありません

Exception mercurial.error.SignalInterrupt: SignalInterrupt() in <bound method sshpeer.cleanup of <mercurial.sshpeer.sshpeer object at 0x2893256c>> ignored

sp11% 

上の2つは^Cで停止、下の2つはkillで停止しました。

2015年12月18日金曜日 17時19分37秒 UTC+9 FUJIWARA Katsunori:

[ohira]

sp11% ssh release-dev cd foo ; hg config

2015年12月18日金曜日 18時01分22秒 UTC+9 ohira:

[Katsunori FUJIWARA]

藤原です。

環境情報をまとめておきます。

サーバ側 クライアント側
--------- ---------------------- --------------
OS x86 Linux x86 FreeBSD
(2.6.18-238.19.1.el5) (7.2-STABLE)

Python 2.7.10 2.7.10

Mercurial 3.6.1 3.5.2
--------- ---------------------- --------------

2015-12-18 18:01 GMT+09:00 ohira <shin....@gmail.com>:

> テストの結果をお知らせいたします。

"テストsono1" が experimental での bundle2 無効化設定アリのケース
で、"テストsono2" が bundle2 無効化設定ナシのケース、という認識で
よろしいですか？

また、いずれのケース／いずれのコマンド実行でも、連携処理が途中で止
まっている、という認識でよろしいですか？

とりあえず「sshpeer.cleanup でのブロック」だと仮定した場合、怪しい
のは、サーバ側から close されるまで error 情報の読み込みでループし
ているあたりでしょうか。

https://selenic.com/repo/hg/file/3.5.2/mercurial/sshpeer.py#l207

def cleanup(self):
if self.pipeo is None:
return
self.pipeo.close()
self.pipei.close()
---------------- ここから ----------------
try:
# read the error descriptor until EOF
for l in self.pipee:
self.ui.status(_("remote: "), l)
except (IOError, ValueError):
pass
---------------- ここまで ----------------
self.pipee.close()

ただ、ssh 連携での pipe 周りは、最近も色々手が入っていたと記憶して
ますから、その辺の副作用の可能性もありますねぇ。

とりあえず、クライアント側の Mercurial を最新の 3.6.2 に上げてみて
もらえますか？


それでも駄目なら、クライアント側で、どこか適当な場所に修正確認用の
Mercurial をインストール (make PREFIX=/path/to/tmp install-bin 等
の実施) するなどした上で、インストール先ソースに以下の修正を試して
みてください。

(1) 上記の「ここから」～「ここまで」の範囲をコメントアウト

(2) self.pipeo.close() の直後に self.pipeo = None を追加
(※ pipe"i" を None にしないように注意)

修正の適用＆確認は、以下の様な手順でお願いします:

A. (1) + (2) でブロックしなくなることの確認

これでもブロックするなら、とりあえず cleanup() の冒頭で問答無
用に return するようにしてみてもらえますか？

B. 上記対処でブロックしなくなれば、(2) のみで再度確認

ここでブロックするなら、初回の cleanup() 呼び出しでブロックし
ていることになるので、サーバ側で pipee を閉じようとしていない
とかの問題なのかな？

C. (2) の対処のみでブロックしなくなるのなら、二度目以降の
cleanup() 呼び出しの際に、前回の pipee.close() 実行が上手く反
映されていない、というあたりが原因かな？



ちなみに、私の環境 (Linux/Python2.6.6/Mercurial 3.5 or 3.6.1) だ
と、--traceback 指定付きで実行すれば、^C 停止でスタックトレースが
表示されるのですが、そちらの環境では表示されないのですよね？

以前のメールに添付されていたものは、たまたま採取できたケースなので
しょうか？

あるいは、ブロックしているシステムコール等によって挙動が違うのか
なぁ？: 私の環境では報告のあった現象が再現しないので、とりあえず長
時間 sleep するフックを仕込んで ^C で止めていることから、入力待ち
の select(2) でのブロック。


--
----------------------------------------------------------------------
FUJIWARA Katsunori(flying...@gmail.com)

[ohira]

おおひらです。

回答ありがとうございます。

テストsono1 は3,4,5,6を実行しました。

結果止まってしまったので

--traceback付きで再度3,4,5,6を実行したものがテストsono2です。

来週mercurialを最新にして今回お知らせいただいたテストを実施してみます。

2015年12月18日金曜日 19時38分53秒 UTC+9 FUJIWARA Katsunori:

[Yuya Nishihara]

On Fri, 18 Dec 2015 19:38:52 +0900, Katsunori FUJIWARA wrote:
> サーバ側 クライアント側
> --------- ---------------------- --------------
> OS x86 Linux x86 FreeBSD
> (2.6.18-238.19.1.el5) (7.2-STABLE)
>
> Python 2.7.10 2.7.10
>
> Mercurial 3.6.1 3.5.2
> --------- ---------------------- --------------

クライアント側が FreeBSD なのが引っかかりますね。 Mercurial 3.4.x と 3.5.x
で差はありますか?

3.5 で追加された doublepipe は、パイプの書き込み側のファイルディスクリプタも
select() の readfds 引数に渡していたと思います。 POSIX の仕様では保証されて
ないと思いますし、 FreeBSD はパイプの両端のファイルディスクリプタがリソースを
共有しているか何かで、 select(readfds=[wfd], writefds=[wfd]) は上手く動かな
かったと思います。

https://selenic.com/repo/hg/file/tip/contrib/showstack.py

このエクステンションを入れると、 Ctrl+T (SIGINFO) でスタックトレースを表示
できます。

[ohira]

おはようございます。

おおひらです。

回答ありがとうございます。

ソースを修正して動作を確認しました。

とりあえず、クライアント側の Mercurial を最新の 3.6.2 に上げてみて 

もらえますか？ 

[クライアントのみインストールを行い、mercurialを3.6.2にあげてみましたが状況は変わりませんでした]

それでも駄目なら、クライアント側で、どこか適当な場所に修正確認用の 

Mercurial をインストール (make PREFIX=/path/to/tmp install-bin 等 

の実施) するなどした上で、インストール先ソースに以下の修正を試して 

みてください。 

  (1) 上記の「ここから」～「ここまで」の範囲をコメントアウト 

  (2) self.pipeo.close() の直後に self.pipeo = None を追加 

      (※ pipe"i" を None にしないように注意) 

修正の適用＆確認は、以下の様な手順でお願いします: 

  A. (1) + (2) でブロックしなくなることの確認 

  

[A の (1)+(2)でブロックしなくなることを確認しました]

     これでもブロックするなら、とりあえず cleanup() の冒頭で問答無 

     用に return するようにしてみてもらえますか？ 

  B. 上記対処でブロックしなくなれば、(2) のみで再度確認 

[再度　(2) のみで確認したところ、ブロックしました]

     ここでブロックするなら、初回の cleanup() 呼び出しでブロックし 

     ていることになるので、サーバ側で pipee を閉じようとしていない 

     とかの問題なのかな？ 

  C. (2) の対処のみでブロックしなくなるのなら、二度目以降の 

     cleanup() 呼び出しの際に、前回の pipee.close() 実行が上手く反 

     映されていない、というあたりが原因かな？ 

2015年12月18日金曜日 19時38分53秒 UTC+9 FUJIWARA Katsunori:

藤原です。

[ohira]

おはようございます。

おおひらです。

回答ありがとうございます。

sigshowエクステンションを追加して、再度テストを行いました。

sp11% pwd

/home/estore/foo

sp11% hg stat

sp11% hg push ssh://release-dev/foo

ssh://release-dev/foo への反映中

load: 0.08  cmd: python2.7 19998 [running] 0.12u 0.03s 0% 11184k

  File "/usr/local/lib/python2.7/site-packages/mercurial/util.py", line 792, in check

    return func(*args, **kwargs)

  File "/usr/local/lib/python2.7/site-packages/mercurial/commands.py", line 5259, in push

    other = hg.peer(repo, opts, dest)

  File "/usr/local/lib/python2.7/site-packages/mercurial/hg.py", line 146, in peer

    return _peerorrepo(rui, path, create).peer()

  File "/usr/local/lib/python2.7/site-packages/mercurial/hg.py", line 123, in _peerorrepo

    obj = _peerlookup(path).instance(ui, path, create)

  File "/usr/local/lib/python2.7/site-packages/mercurial/sshpeer.py", line 145, in __init__

    self._validaterepo(sshcmd, args, remotecmd)

  File "/usr/local/lib/python2.7/site-packages/mercurial/sshpeer.py", line 179, in _validaterepo

    l = r.readline()

  File "/usr/local/lib/python2.7/site-packages/mercurial/sshpeer.py", line 85, in readline

    return self._call('readline')

  File "/usr/local/lib/python2.7/site-packages/mercurial/sshpeer.py", line 95, in _call

    mainready, sideready = self._wait()

  File "/usr/local/lib/python2.7/site-packages/mercurial/sshpeer.py", line 72, in _wait

    act = util.poll(fds)

  File "/usr/local/lib/python2.7/site-packages/mercurial/posix.py", line 606, in poll

    res = select.select(fds, fds, fds)

----

** 非同梱のエクステンション sigshow に起因する例外が発生しました。

** 当該エクステンションのサポート対象 Mercurial の版: unknown

** エクステンション sigshow を無効化してから、再度同じ処理を実行してください。

** 問題が改善された場合、 障害の発生を エクステンションの作者 に報告してください。

** Python 2.7.10 (default, Sep  4 2015, 13:56:33) [GCC 4.2.1 20070719  [FreeBSD]]

Mercurial - 分散構成管理ツール (バージョン 3.5.2)

** Extensions loaded: sigshow

Traceback (most recent call last):

  File "/usr/local/bin/hg", line 43, in <module>

    mercurial.dispatch.run()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 30, in run

    sys.exit((dispatch(request(sys.argv[1:])) or 0) & 255)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 92, in dispatch

    ret = _runcatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 163, in _runcatch

    return _dispatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 895, in _dispatch

    cmdpats, cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 656, in runcommand

    ret = _runcommand(ui, options, cmd, d)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 1013, in _runcommand

    return checkargs()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 982, in checkargs

    return cmdfunc()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 892, in <lambda>

    d = lambda: util.checksignature(func)(ui, *args, **cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/util.py", line 792, in check

    return func(*args, **kwargs)

  File "/usr/local/lib/python2.7/site-packages/mercurial/commands.py", line 5259, in push

    other = hg.peer(repo, opts, dest)

  File "/usr/local/lib/python2.7/site-packages/mercurial/hg.py", line 146, in peer

    return _peerorrepo(rui, path, create).peer()

  File "/usr/local/lib/python2.7/site-packages/mercurial/hg.py", line 123, in _peerorrepo

    obj = _peerlookup(path).instance(ui, path, create)

  File "/usr/local/lib/python2.7/site-packages/mercurial/sshpeer.py", line 145, in __init__

    self._validaterepo(sshcmd, args, remotecmd)

  File "/usr/local/lib/python2.7/site-packages/mercurial/sshpeer.py", line 179, in _validaterepo

    l = r.readline()

  File "/usr/local/lib/python2.7/site-packages/mercurial/sshpeer.py", line 85, in readline

    return self._call('readline')

  File "/usr/local/lib/python2.7/site-packages/mercurial/sshpeer.py", line 95, in _call

    mainready, sideready = self._wait()

  File "/usr/local/lib/python2.7/site-packages/mercurial/sshpeer.py", line 72, in _wait

    act = util.poll(fds)

  File "/usr/local/lib/python2.7/site-packages/mercurial/posix.py", line 606, in poll

    res = select.select(fds, fds, fds)

select.error: (4, 'Interrupted system call')

^C

sp11% hg push ssh://release-dev/foo

ssh://release-dev/foo への反映中

差分はありません

load: 0.08  cmd: python2.7 33653 [running] 0.17u 0.01s 0% 12700k

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 30, in run

    sys.exit((dispatch(request(sys.argv[1:])) or 0) & 255)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 92, in dispatch

    ret = _runcatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 163, in _runcatch

    return _dispatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 895, in _dispatch

    cmdpats, cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 656, in runcommand

    ret = _runcommand(ui, options, cmd, d)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 1013, in _runcommand

    return checkargs()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 982, in checkargs

    return cmdfunc()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 892, in <lambda>

    d = lambda: util.checksignature(func)(ui, *args, **cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/util.py", line 792, in check

    return func(*args, **kwargs)

  File "/usr/local/lib/python2.7/site-packages/mercurial/sshpeer.py", line 214, in cleanup

    for l in self.pipee:

----

sp11%

2015年12月19日土曜日 17時11分32秒 UTC+9 Yuya Nishihara:

[ohira]

おおひらです。

ブロックしたときに^Tで停止すると下のような結果になることの方が多いです。

sp11% hg push ssh://release-dev/foo

ssh://release-dev/foo への反映中

差分はありません

load: 0.10  cmd: python2.7 93579 [running] 0.18u 0.01s 0% 12752k

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 54, in run

    sys.exit((dispatch(request(sys.argv[1:])) or 0) & 255)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 116, in dispatch

    ret = _runcatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 187, in _runcatch

    return _dispatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 920, in _dispatch

    cmdpats, cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 679, in runcommand

    ret = _runcommand(ui, options, cmd, d)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 1051, in _runcommand

    return checkargs()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 1011, in checkargs

    return cmdfunc()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 917, in <lambda>

    d = lambda: util.checksignature(func)(ui, *args, **cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/util.py", line 801, in check

    return func(*args, **kwargs)

  File "/usr/local/lib/python2.7/site-packages/mercurial/sshpeer.py", line 222, in cleanup

    for l in self.pipee:

----

sp11% 

2015年12月21日月曜日 11時44分28秒 UTC+9 ohira:

[ohira]

ちなみに、私の環境 (Linux/Python2.6.6/Mercurial 3.5 or 3.6.1) だ
と、--traceback 指定付きで実行すれば、^C 停止でスタックトレースが
表示されるのですが、そちらの環境では表示されないのですよね？

以前のメールに添付されていたものは、たまたま採取できたケースなので
しょうか？

以前のメールでは取れていることもありました、そのときは

hogeの内容が空ではなくて実際にpdfファイルとかが入っているものでした。

空のリポジトリでは、取れなかったと思います。 

[Katsunori FUJIWARA]

藤原です。

情報採取ありがとうございます。

2015-12-21 11:44 GMT+09:00 ohira <shin....@gmail.com>:

> sp11% pwd
> /home/estore/foo
> sp11% hg stat
> sp11% hg push ssh://release-dev/foo
> ssh://release-dev/foo への反映中
> load: 0.08 cmd: python2.7 19998 [running] 0.12u 0.03s 0% 11184k

(snip)

こちらのスタックトレースを見る限りでは、ssh 連携での差分検出処理の
途中で中断されているみたいなのですが、数十秒程度の確実なブロック状
態を経て中断したものでしょうか？

もう一つの中断例のような、「サーバ側での close 待ち」な cleanup()
でのブロックと違い、__init__() の延長での連携処理では「応答データ
の終端」形式が決まっているものなので、ここでブロックしている（or
する可能性がある）のだとすると、先のメールで修正効果を確認してもらっ
たような「pipee からの読み出し処理を省略」的な単純な対処ではカバー
できないことになります。

毎回ここでブロックしている、という症状なら、とりあえず「pipee から
の読み出し処理を省略」で対処できるんですけどねぇ。

ちなみに、上記の動作確認を行った環境は、以前のメールで動作確認を行っ
た際にお願いしたように、クライアント側・サーバ側共に空のリポジトリ
同士での連携ですよね？

> 2015年12月19日土曜日 17時11分32秒 UTC+9 Yuya Nishihara:
>>
>> On Fri, 18 Dec 2015 19:38:52 +0900, Katsunori FUJIWARA wrote:
>> > サーバ側 クライアント側
>> > --------- ---------------------- --------------
>> > OS x86 Linux x86 FreeBSD
>> > (2.6.18-238.19.1.el5) (7.2-STABLE)
>> >
>> > Python 2.7.10 2.7.10
>> >
>> > Mercurial 3.6.1 3.5.2
>> > --------- ---------------------- --------------
>>
>> クライアント側が FreeBSD なのが引っかかりますね。 Mercurial 3.4.x と 3.5.x
>> で差はありますか?
>>
>> 3.5 で追加された doublepipe は、パイプの書き込み側のファイルディスクリプタも
>> select() の readfds 引数に渡していたと思います。 POSIX の仕様では保証されて
>> ないと思いますし、 FreeBSD はパイプの両端のファイルディスクリプタがリソースを
>> 共有しているか何かで、 select(readfds=[wfd], writefds=[wfd]) は上手く動かな
>> かったと思います。

原因としてはこの辺が怪しい可能性が高そうですね。

で、それとは別に「他のホストとの ssh 連携時に問題が無いのは何故
か？」という疑問も出てくるんですよねぇ。

FreeBSD クライアントからの ssh 連携が、期待通りに機能「している」
サーバの環境情報も教えてもらえますか？

- OS
- Python
- Mercurial
- mercurial-server (利用している場合)

ちなみに、release-dev におけるｗ Mercurial のバージョンや
mercurial-server 利用の有無等を、上手く連携できているホストと揃え
た場合も、やはり release-dev との連携はブロックしますかね？

>> https://selenic.com/repo/hg/file/tip/contrib/showstack.py
>>
>> このエクステンションを入れると、 Ctrl+T (SIGINFO) でスタックトレースを表示
>> できます。

--
----------------------------------------------------------------------
FUJIWARA Katsunori(flying...@gmail.com)

[ohira]

おおひらです。

2015年12月21日月曜日 15時39分28秒 UTC+9 FUJIWARA Katsunori:

すいません。待ち時間が不十分だったかもしれません。 

fooでテストを行うように指示をいただいてからは、空のものでテストしています。

OS  Linux nfs-release 2.6.18-308.1.1.el5

Python 2.7.6

Mercurial - 分散構成管理ツール(バージョン 3.5.2)

mercurial-server テストでは使用していません。

[テストログ]

sp11% hg clone foo ssh://nfs-release/foo

差分はありません

sp11% ssh release-dev rm -rf foo

sp11% hg clone foo ssh://release-dev/foo

差分はありません

load: 0.05  cmd: python2.7 59577 [running] 0.14u 0.05s 0% 12584k

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 54, in run

    sys.exit((dispatch(request(sys.argv[1:])) or 0) & 255)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 116, in dispatch

    ret = _runcatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 187, in _runcatch

    return _dispatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 920, in _dispatch

    cmdpats, cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 679, in runcommand

    ret = _runcommand(ui, options, cmd, d)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 1051, in _runcommand

    return checkargs()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 1011, in checkargs

    return cmdfunc()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 917, in <lambda>

    d = lambda: util.checksignature(func)(ui, *args, **cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/util.py", line 801, in check

    return func(*args, **kwargs)

  File "/usr/local/lib/python2.7/site-packages/mercurial/sshpeer.py", line 222, in cleanup

    for l in self.pipee:

----

sp11% 

[環境確認ログ]

 [estore@nfs-release ~]$ uname -a

Linux nfs-release 2.6.18-308.1.1.el5 #1 SMP Wed Mar 7 04:16:51 EST 2012 x86_64 x86_64 x86_64 GNU/Linux

[estore@nfs-release ~]$ head `which hg`

#!/usr/local/bin/python

#

# mercurial - scalable distributed SCM

#

# Copyright 2005-2007 Matt Mackall <m...@selenic.com>

#

# This software may be used and distributed according to the terms of the

# GNU General Public License version 2 or any later version.

import os

[estore@nfs-release ~]$ /usr/local/bin/python --version

Python 2.7.6

[estore@nfs-release ~]$ hg --version

Mercurial - 分散構成管理ツール(バージョン 3.5.2)

(詳細は http://mercurial.selenic.com を参照)

Copyright (C) 2005-2015 Matt Mackall 他

本製品はフリーソフトウェアです。

頒布条件に関しては同梱されるライセンス条項をお読みください。

市場適合性や特定用途への可否を含め、 本製品は無保証です。

[estore@nfs-release ~]$ 

[Katsunori FUJIWARA]

藤原です。

2015年12月19日 17:09 Yuya Nishihara <yu...@tcha.org>:

> On Fri, 18 Dec 2015 19:38:52 +0900, Katsunori FUJIWARA wrote:
>> サーバ側 クライアント側
>> --------- ---------------------- --------------
>> OS x86 Linux x86 FreeBSD
>> (2.6.18-238.19.1.el5) (7.2-STABLE)
>>
>> Python 2.7.10 2.7.10
>>
>> Mercurial 3.6.1 3.5.2
>> --------- ---------------------- --------------
>
> クライアント側が FreeBSD なのが引っかかりますね。 Mercurial 3.4.x と 3.5.x
> で差はありますか?

このバージョン違いの確認は可能ですか？ > おおひらさん

> 3.5 で追加された doublepipe は、パイプの書き込み側のファイルディスクリプタも
> select() の readfds 引数に渡していたと思います。 POSIX の仕様では保証されて
> ないと思いますし、 FreeBSD はパイプの両端のファイルディスクリプタがリソースを
> 共有しているか何かで、 select(readfds=[wfd], writefds=[wfd]) は上手く動かな
> かったと思います。

以下のような感じの修正を考えてみましたが、どんなもんでしょうね？

https://bitbucket.org/snippets/foozy/58Ka9


なお、'cleanup()' でブロックしているケースの場合、読み出し用の
pipee への直接アクセスで、doublepipe を介さない処理なのですが、そ
れに先立つ doublepipe 経由のアクセス等が影響していたりするんですか
ね？

最近の devel-ml にも、Solaris 環境ではバッファリング等が絡むために
シーク位置が云々とかの話が流れていましたから、ファイル I/O 周りは
色々癖があるのかなぁ……

> https://selenic.com/repo/hg/file/tip/contrib/showstack.py
>
> このエクステンションを入れると、 Ctrl+T (SIGINFO) でスタックトレースを表示
> できます。

--
----------------------------------------------------------------------
FUJIWARA Katsunori(flying...@gmail.com)

[ohira]

おおひらです。

サーバのmercurialのバージョンを変更して試してみました。

3.5.2

3.4.2

どちらも今までと同じ動作でした。

これからクライアントを3.4.2にして試してみます。

[テストログ]

sp11% ssh release-dev rm -rf foo             

sp11% rm -rf foo

sp11% hg init foo

sp11% hg clone foo ssh://release-dev/foo

差分はありません

load: 0.10  cmd: python2.7 1886 [running] 0.17u 0.02s 0% 12748k

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 54, in run

    sys.exit((dispatch(request(sys.argv[1:])) or 0) & 255)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 116, in dispatch

    ret = _runcatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 187, in _runcatch

    return _dispatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 920, in _dispatch

    cmdpats, cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 679, in runcommand

    ret = _runcommand(ui, options, cmd, d)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 1051, in _runcommand

    return checkargs()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 1011, in checkargs

    return cmdfunc()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 917, in <lambda>

    d = lambda: util.checksignature(func)(ui, *args, **cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/util.py", line 801, in check

    return func(*args, **kwargs)

  File "/usr/local/lib/python2.7/site-packages/mercurial/sshpeer.py", line 222, in cleanup

    for l in self.pipee:

----

sp11% ssh release-dev hg --version

Mercurial - ʬ����������ġ���(�С������� 3.5.2)

(�ܺ٤� http://mercurial.selenic.com �򻲾�)

Copyright (C) 2005-2015 Matt Mackall ¾

����ʤϥե꡼���եȥ������Ǥ���

���۾����˴ؤ��Ƥ�Ʊ���������饤���󥹾��������ɤߤ��������

�Ծ�Ŭ������������Ӥؤβ��ݤ��ޤᡢ ����ʤ�̵�ݾڤǤ���

sp11% ssh release-dev env LANG=C hg --version

Mercurial Distributed SCM (version 3.4.2)

(see http://mercurial.selenic.com for more information)

Copyright (C) 2005-2015 Matt Mackall and others

This is free software; see the source for copying conditions. There is NO

warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.

sp11% rm -rf foo                             

sp11% ssh release-dev rm -rf foo             

sp11% hg init foo                            

sp11% hg clone foo ssh://release-dev/foo     

差分はありません

load: 0.05  cmd: python2.7 17582 [running] 0.16u 0.03s 0% 12752k

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 54, in run

    sys.exit((dispatch(request(sys.argv[1:])) or 0) & 255)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 116, in dispatch

    ret = _runcatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 187, in _runcatch

    return _dispatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 920, in _dispatch

    cmdpats, cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 679, in runcommand

    ret = _runcommand(ui, options, cmd, d)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 1051, in _runcommand

    return checkargs()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 1011, in checkargs

    return cmdfunc()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 917, in <lambda>

    d = lambda: util.checksignature(func)(ui, *args, **cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/util.py", line 801, in check

    return func(*args, **kwargs)

  File "/usr/local/lib/python2.7/site-packages/mercurial/sshpeer.py", line 222, in cleanup

    for l in self.pipee:

----

sp11% 

2015年12月21日月曜日 17時00分05秒 UTC+9 FUJIWARA Katsunori:

[ohira]

おおひらです。

クライアントのhgのバージョンを3.4.2 にしてみましたが

状況は変わりませんでした。

[テストログ]

sp11% hg --version

Mercurial - 分散構成管理ツール(バージョン 3.4.2)

(詳細は http://mercurial.selenic.com を参照)

Copyright (C) 2005-2015 Matt Mackall 他

本製品はフリーソフトウェアです。

頒布条件に関しては同梱されるライセンス条項をお読みください。

市場適合性や特定用途への可否を含め、 本製品は無保証です。

sp11% ssh release-dev env LANG=C hg --version

Mercurial Distributed SCM (version 3.4.2)

(see http://mercurial.selenic.com for more information)

Copyright (C) 2005-2015 Matt Mackall and others

This is free software; see the source for copying conditions. There is NO

warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.

sp11% rm -rf foo

sp11% ssh release-dev rm -rf foo

sp11% hg init foo

sp11% hg clone foo ssh://release-dev/foo

差分はありません

load: 0.14  cmd: python2.7 37771 [running] 0.14u 0.04s 0% 12428k

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 29, in run

    sys.exit((dispatch(request(sys.argv[1:])) or 0) & 255)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 91, in dispatch

    ret = _runcatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 160, in _runcatch

    return _dispatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 885, in _dispatch

    cmdpats, cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 646, in runcommand

    ret = _runcommand(ui, options, cmd, d)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 976, in _runcommand

    return checkargs()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 947, in checkargs

    return cmdfunc()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 882, in <lambda>

    d = lambda: util.checksignature(func)(ui, *args, **cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/util.py", line 716, in check

    return func(*args, **kwargs)

  File "/usr/local/lib/python2.7/site-packages/mercurial/sshpeer.py", line 127, in cleanup

    for l in self.pipee:

----

sp11%

2015年12月21日月曜日 17時25分56秒 UTC+9 ohira:

[ohira]

おおひらです。

その後ヴァージョンを変えて試してみました。

client 3.4.2, server 3.4.2 でも　NG

client 3.6.2, server 3.6.2 でも　NG

client 3.6.2+patch, server 3.6.2+patchでも　NG

でした。

2015年12月21日月曜日 17時33分01秒 UTC+9 ohira:

[Katsunori FUJIWARA]

藤原です。

各種情報採取ありがとうございます。

改めて障害が発生する状況をまとめてみました。


クライアント NG なサーバ OK なサーバ
--------- -------------- --------------------- --------------------
OS x86 FreeBSD x86-64bit Linux x86-64bit Linux
(7.2-STABLE) (2.6.18-238.19.1.el5) (2.6.18-308.1.1.el5)

Python 2.7.10 2.7.10 2.7.6

Mercurial 3.6.2(*1) 3.6.1(*2) 3.5.2
--------- -------------- --------------------- --------------------

(*1) 3.5.2, 3.4.2 でも変わらず ⇒ 3.5 で導入された doublepipe の影響は無さそう
(*2) 3.5.2, 3.4.2 でも変わらず

サーバ側は、NG サーバと OK サーバで、OS と Python の更新度合いがク
ロスした構成になっているんですね


Linux + Python 2.7.10 + Mercurial 3.4.x なクライアントと、NG サー
バとの連携を試すことで、原因の範囲をもう少し絞り込めるかもしれません。

● NG なら、OS 非依存な問題

- サーバ側 Python の問題
(2.7.6 ～ 2.7.10 での挙動の変化)

- クライアント側 Mercurial の問題
(Python 2.7.10 への対応が不十分)

● OK なら、OS 依存な問題

- サーバ側 Linux (or SSH 実装) の問題
(2.6.18-238.19.1.el5 ～ 2.6.18-308.1.1.el5 での挙動の変化)

- クライアント側 Python の問題
(ビルド OS による挙動の変化)

- クライアント側 Mercurial の問題
(BSD 固有挙動への対応が不十分)

NG サーバ = release-dev の上で、Mercurial 3.4.x 系を使って自分自身
への ssh 連携を実施するのが、一番手っ取り早いのかな？

その際に、localhost とか 127.0.0.1 とかのループバックアドレスを使
うと、カーネル内で通信レイヤの処理パスが変わる可能性があるので、
FreeBSD クライアントから接続する場合と同じ IP アドレスを使うように
してください (それでも最適化等で処理パスが変わる可能性がありますが)。

まぁ、「OK ＝ OS 依存な問題」になるんでしょうねぇ…… (^ ^;;;)


ちなみに、十分な時間経過後にブロックしていると判断した場合、強制中
断すると、常時 'sshpeer.cleanup()' の pipee 読み出しでブロックして
いる、という認識でよろしいでしょうか？それとも、メールで頂いた実行
ログのように、時々他のケースもあったりします？

「常時 'sshpeer.cleanup()' の pipee 読み出しでブロック」なら、当面
は例の「pipee 読み出し処理の省略」対処ですね。



2015年12月21日 17:33 ohira <shin....@gmail.com>:

> --
> from Mercurial 日本語コミュニティ <mercur...@googlegroups.com>
> ※ ヘルプ表示は http://groups.google.com/group/mercurial-ja?hl=ja
> ---
> このメールは Google グループのグループ「mercurial-ja」に登録しているユーザーに送られています。
> このグループから退会し、グループからのメールの配信を停止するには mercurial-ja...@googlegroups.com
> にメールを送信してください。
> その他のオプションについては https://groups.google.com/d/optout にアクセスしてください。



--
----------------------------------------------------------------------
FUJIWARA Katsunori(flying...@gmail.com)

[Yuya Nishihara]

On Mon, 21 Dec 2015 17:00:04 +0900, Katsunori FUJIWARA wrote:
> > 3.5 で追加された doublepipe は、パイプの書き込み側のファイルディスクリプタも
> > select() の readfds 引数に渡していたと思います。 POSIX の仕様では保証されて
> > ないと思いますし、 FreeBSD はパイプの両端のファイルディスクリプタがリソースを
> > 共有しているか何かで、 select(readfds=[wfd], writefds=[wfd]) は上手く動かな
> > かったと思います。
>
> 以下のような感じの修正を考えてみましたが、どんなもんでしょうね？
>
> https://bitbucket.org/snippets/foozy/58Ka9

修正はそんなだと思います。 read は bool か 'r'/'w' か、のようなバイク小屋議論
はあると思いますが。それから、 exceptfds は普段チェックしないですよね?

http://stackoverflow.com/a/15714756

> なお、'cleanup()' でブロックしているケースの場合、読み出し用の
> pipee への直接アクセスで、doublepipe を介さない処理なのですが、そ
> れに先立つ doublepipe 経由のアクセス等が影響していたりするんですか
> ね？

いや、全く関係ないと思います。単純に考えると、クライアント側の書き込み端を
閉じたのに、サーバー側が EOF を検出できなくて死んでないということですよね。

"ssh remotehost hg serve --stdio" を直接叩いて、 ^D で閉じた場合はちゃんと
終わりますか?

[ohira]

2015年12月21日月曜日 23時06分13秒 UTC+9 Yuya Nishihara:

> なお、'cleanup()' でブロックしているケースの場合、読み出し用の
> pipee への直接アクセスで、doublepipe を介さない処理なのですが、そ
> れに先立つ doublepipe 経由のアクセス等が影響していたりするんですか
> ね？

いや、全く関係ないと思います。単純に考えると、クライアント側の書き込み端を
閉じたのに、サーバー側が EOF を検出できなくて死んでないということですよね。

"ssh remotehost hg serve --stdio" を直接叩いて、 ^D で閉じた場合はちゃんと
終わりますか?

 直接叩いた場合にちゃんと終わるか再度確認しました。（先ほどは待ち時間が不足していましたすいません）

NGのサーバでも、OKのサーバでも何もキーを入れないで待っていれば終わりました。

[実行ログ]

sp11% 

sp11% ssh release-dev env LANG=C hg serve --stdio

abort: there is no Mercurial repository here (.hg not found)!

sp11% 

sp11% ssh nfs-release hg serve --stdio           

abort: there is no Mercurial repository here (.hg not found)!

sp11%                                            

sp11% ssh release-dev env LANG=C hg serve --stdio

abort: there is no Mercurial repository here (.hg not found)!

sp11% 

sp11% ssh nfs-release hg serve --stdio           

abort: there is no Mercurial repository here (.hg not found)!

sp11% 

sp11% ssh release-dev env LANG=C hg serve --stdio

abort: there is no Mercurial repository here (.hg not found)!

sp11% 

sp11% ssh nfs-release hg serve --stdio           

abort: there is no Mercurial repository here (.hg not found)!

sp11%

[Katsunori FUJIWARA]

藤原です。

2015年12月22日 11:07 ohira <shin....@gmail.com>:

"abort: there is no Mercurial repository here (.hg not found)!" が
発生する状況は、サーバ側が勝手に終了するケースですから、クライアン
トからの EOF を検出しているか否かは判定できません。

"ssh remotehost hg -R path/to/repo serve --stdio" のように、-R オ
プションで実在するリポジトリを指定した上で、クライアント側での ^D
入力による EOF 通知を検出するか確認してみてください。

--
----------------------------------------------------------------------
FUJIWARA Katsunori(flying...@gmail.com)

[ohira]

おおひらです。

-R で実在するリポジトリを指定して、OKのサーバとNGのサーバで動作を確認しました。

どちらのサーバでも^Dを入力することで終了しました。

[実行ログ]

sp11% 

sp11% 

sp11% ssh release-dev hg -R foo serve --stdio

sp11% 

sp11% ssh nfs-release hg -R foo serve --stdio

sp11% 

sp11% ssh release-dev hg -R foo serve --stdio

sp11% 

sp11% ssh nfs-release hg -R foo serve --stdio

sp11% 

sp11% ssh release-dev hg -R foo serve --stdio

sp11% 

sp11% ssh nfs-release hg -R foo serve --stdio

sp11% 

sp11% 

2015年12月22日火曜日 12時19分09秒 UTC+9 FUJIWARA Katsunori:

藤原です。

2015年12月22日 11:07 ohira <shin....@gmail.com>:

> 2015年12月21日月曜日 23時06分13秒 UTC+9 Yuya Nishihara:

[Katsunori FUJIWARA]

藤原です。

2015年12月22日 12:33 ohira <shin....@gmail.com>:
> おおひらです。
>
> -R で実在するリポジトリを指定して、OKのサーバとNGのサーバで動作
> を確認しました。
>
> どちらのサーバでも^Dを入力することで終了しました。

その感じだと、Python かそれよりも上の層での問題っぽいですね。

確認用の急造エクステンションを以下にアップロードしました。

https://bitbucket.org/snippets/foozy/58Ka9#file-baressh.py

上記のエクステンションを有効にした上で、以下のコマンドを順次実行し
てみてもらえますか？URL は実在するリポジトリを指定してください。

$ hg baressh --close-after none ssh://release-dev/foo
$ hg baressh --close-after hello ssh://release-dev/foo
$ hg baressh --close-after between ssh://release-dev/foo

どれかで実行がブロックするようなら、それ以降の実行は不要です。また、
ブロックする場合は、実行中断時のスタックトレースの採取もお願いしま
す。

もしも、上記のどれでもブロックしないようであれば、ブロックするよう
になるまで、以下の手順を実施してください。

1. --buffered 付きで一連のコマンドを実行
2. --buffered および --doublepipe 付きで一連のコマンドを実行

万が一ここまでの手順でブロックしないようだと……凄くタイミング or
手順依存な問題なのかも？（笑）

--
----------------------------------------------------------------------
FUJIWARA Katsunori(flying...@gmail.com)

[ohira]

おおひらです。

9種類のテストを行いましたが

どれも一瞬でプロンプトが返ってきて、ブロックしませんでした。

[テストログ]

sp11% hg baressh --close-after none ssh://release-dev/foo  

中止: デフォルトの連携先が設定されていません

("hg help config" の "path" セクションを参照してください)

sp11% hg baressh --close-after hello ssh://release-dev/foo  

中止: デフォルトの連携先が設定されていません

("hg help config" の "path" セクションを参照してください)

sp11% hg baressh --close-after between ssh://release-dev/foo

中止: デフォルトの連携先が設定されていません

("hg help config" の "path" セクションを参照してください)

sp11% hg baressh --close-after none ssh://nfs-release/foo --buffered

中止: デフォルトの連携先が設定されていません

("hg help config" の "path" セクションを参照してください)

sp11% hg baressh --close-after hello ssh://release-dev/foo --buffered

中止: デフォルトの連携先が設定されていません

("hg help config" の "path" セクションを参照してください)

sp11% hg baressh --close-after between ssh://release-dev/foo --buffered

中止: デフォルトの連携先が設定されていません

("hg help config" の "path" セクションを参照してください)

sp11% hg baressh --close-after none ssh://nfs-release/foo --buffered --doublepipe

中止: デフォルトの連携先が設定されていません

("hg help config" の "path" セクションを参照してください)

sp11% hg baressh --close-after hello ssh://release-dev/foo --buffered --doublepipe

中止: デフォルトの連携先が設定されていません

("hg help config" の "path" セクションを参照してください)

sp11% hg baressh --close-after between ssh://release-dev/foo --buffered --doublepipe

中止: デフォルトの連携先が設定されていません

("hg help config" の "path" セクションを参照してください)

sp11% 

2015年12月22日火曜日 15時55分59秒 UTC+9 FUJIWARA Katsunori:

[Katsunori FUJIWARA]

藤原です。

2015年12月22日 16:44 ohira <shin....@gmail.com>:

> おおひらです。
>
> 9種類のテストを行いましたが
> どれも一瞬でプロンプトが返ってきて、ブロックしませんでした。
>
> [テストログ]
> sp11% hg baressh --close-after none ssh://release-dev/foo
> 中止: デフォルトの連携先が設定されていません
> ("hg help config" の "path" セクションを参照してください)

済みません。

[paths] default 等の設定を使えるように配慮したコードが、Mercurial
バージョンの違いで上手く機能していないのだと思います。

便利にしようとおもって裏目に出てしまった…… orz

'def baressh()' 冒頭の以下の部分を丸々削除するか、あるいは参照先
URL から baressh.py の更新版を入手して再実施をお願いします。

path = ui.paths.getpath(sshurl, default='default')
if not path:
raise error.Abort(_('default repository not configured!'),
hint=_('see the "path" section in "hg help config"'))

sshurl = path.pushloc or path.loc


--
----------------------------------------------------------------------
FUJIWARA Katsunori(flying...@gmail.com)

[ohira]

おおひらです。

実行するとすぐにスタックトレースを表示してプロンプトに返ってきます。

どれもブロックはしませんでした。

[実行ログ]

sp11% hg baressh --close-after none ssh://release-dev/foo

running ssh release-dev 'hg -R foo serve --stdio'

** 非同梱のエクステンション sigshow に起因する例外が発生しました。

** 当該エクステンションのサポート対象 Mercurial の版: unknown

** エクステンション sigshow を無効化してから、再度同じ処理を実行してください。

** 問題が改善された場合、 障害の発生を エクステンションの作者 に報告してください。

** Python 2.7.10 (default, Sep  4 2015, 13:56:33) [GCC 4.2.1 20070719  [FreeBSD]]

Mercurial - 分散構成管理ツール (バージョン 3.4.2)

** Extensions loaded: sigshow, baressh

Traceback (most recent call last):

  File "/usr/local/bin/hg", line 43, in <module>

    mercurial.dispatch.run()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 29, in run

    sys.exit((dispatch(request(sys.argv[1:])) or 0) & 255)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 91, in dispatch

    ret = _runcatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 160, in _runcatch

    return _dispatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 885, in _dispatch

    cmdpats, cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 646, in runcommand

    ret = _runcommand(ui, options, cmd, d)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 976, in _runcommand

    return checkargs()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 947, in checkargs

    return cmdfunc()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 882, in <lambda>

    d = lambda: util.checksignature(func)(ui, *args, **cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/util.py", line 716, in check

    return func(*args, **kwargs)

  File "/home/estore/58Ka9/baressh.py", line 94, in baressh

    doublepipe=opts['doublepipe'])

  File "/home/estore/58Ka9/baressh.py", line 43, in __init__

    sub = util.popen4(cmd, bufsize=0)

TypeError: popen4() got an unexpected keyword argument 'bufsize'

Exception AttributeError: "'baresshpeer' object has no attribute 'pipeo'" in <bound method baresshpeer.cleanup of <hgext_baressh.baresshpeer object at 0x28c51f6c>> ignored

sp11% 

sp11% 

sp11% hg baressh --close-after hello ssh://release-dev/foo

running ssh release-dev 'hg -R foo serve --stdio'

** 非同梱のエクステンション sigshow に起因する例外が発生しました。

** 当該エクステンションのサポート対象 Mercurial の版: unknown

** エクステンション sigshow を無効化してから、再度同じ処理を実行してください。

** 問題が改善された場合、 障害の発生を エクステンションの作者 に報告してください。

** Python 2.7.10 (default, Sep  4 2015, 13:56:33) [GCC 4.2.1 20070719  [FreeBSD]]

Mercurial - 分散構成管理ツール (バージョン 3.4.2)

** Extensions loaded: sigshow, baressh

Traceback (most recent call last):

  File "/usr/local/bin/hg", line 43, in <module>

    mercurial.dispatch.run()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 29, in run

    sys.exit((dispatch(request(sys.argv[1:])) or 0) & 255)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 91, in dispatch

    ret = _runcatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 160, in _runcatch

    return _dispatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 885, in _dispatch

    cmdpats, cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 646, in runcommand

    ret = _runcommand(ui, options, cmd, d)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 976, in _runcommand

    return checkargs()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 947, in checkargs

    return cmdfunc()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 882, in <lambda>

    d = lambda: util.checksignature(func)(ui, *args, **cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/util.py", line 716, in check

    return func(*args, **kwargs)

  File "/home/estore/58Ka9/baressh.py", line 94, in baressh

    doublepipe=opts['doublepipe'])

  File "/home/estore/58Ka9/baressh.py", line 43, in __init__

    sub = util.popen4(cmd, bufsize=0)

TypeError: popen4() got an unexpected keyword argument 'bufsize'

Exception AttributeError: "'baresshpeer' object has no attribute 'pipeo'" in <bound method baresshpeer.cleanup of <hgext_baressh.baresshpeer object at 0x28c51f6c>> ignored

sp11% hg baressh --close-after between ssh://release-dev/foo

running ssh release-dev 'hg -R foo serve --stdio'

** 非同梱のエクステンション sigshow に起因する例外が発生しました。

** 当該エクステンションのサポート対象 Mercurial の版: unknown

** エクステンション sigshow を無効化してから、再度同じ処理を実行してください。

** 問題が改善された場合、 障害の発生を エクステンションの作者 に報告してください。

** Python 2.7.10 (default, Sep  4 2015, 13:56:33) [GCC 4.2.1 20070719  [FreeBSD]]

Mercurial - 分散構成管理ツール (バージョン 3.4.2)

** Extensions loaded: sigshow, baressh

Traceback (most recent call last):

  File "/usr/local/bin/hg", line 43, in <module>

    mercurial.dispatch.run()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 29, in run

    sys.exit((dispatch(request(sys.argv[1:])) or 0) & 255)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 91, in dispatch

    ret = _runcatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 160, in _runcatch

    return _dispatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 885, in _dispatch

    cmdpats, cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 646, in runcommand

    ret = _runcommand(ui, options, cmd, d)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 976, in _runcommand

    return checkargs()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 947, in checkargs

    return cmdfunc()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 882, in <lambda>

    d = lambda: util.checksignature(func)(ui, *args, **cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/util.py", line 716, in check

    return func(*args, **kwargs)

  File "/home/estore/58Ka9/baressh.py", line 94, in baressh

    doublepipe=opts['doublepipe'])

  File "/home/estore/58Ka9/baressh.py", line 43, in __init__

    sub = util.popen4(cmd, bufsize=0)

TypeError: popen4() got an unexpected keyword argument 'bufsize'

Exception AttributeError: "'baresshpeer' object has no attribute 'pipeo'" in <bound method baresshpeer.cleanup of <hgext_baressh.baresshpeer object at 0x28c51f6c>> ignored

sp11% hg baressh --close-after none ssh://nfs-release/foo --buffered

running ssh nfs-release 'hg -R foo serve --stdio'

** 非同梱のエクステンション sigshow に起因する例外が発生しました。

** 当該エクステンションのサポート対象 Mercurial の版: unknown

** エクステンション sigshow を無効化してから、再度同じ処理を実行してください。

** 問題が改善された場合、 障害の発生を エクステンションの作者 に報告してください。

** Python 2.7.10 (default, Sep  4 2015, 13:56:33) [GCC 4.2.1 20070719  [FreeBSD]]

Mercurial - 分散構成管理ツール (バージョン 3.4.2)

** Extensions loaded: sigshow, baressh

Traceback (most recent call last):

  File "/usr/local/bin/hg", line 43, in <module>

    mercurial.dispatch.run()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 29, in run

    sys.exit((dispatch(request(sys.argv[1:])) or 0) & 255)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 91, in dispatch

    ret = _runcatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 160, in _runcatch

    return _dispatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 885, in _dispatch

    cmdpats, cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 646, in runcommand

    ret = _runcommand(ui, options, cmd, d)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 976, in _runcommand

    return checkargs()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 947, in checkargs

    return cmdfunc()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 882, in <lambda>

    d = lambda: util.checksignature(func)(ui, *args, **cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/util.py", line 716, in check

    return func(*args, **kwargs)

  File "/home/estore/58Ka9/baressh.py", line 94, in baressh

    doublepipe=opts['doublepipe'])

  File "/home/estore/58Ka9/baressh.py", line 43, in __init__

    sub = util.popen4(cmd, bufsize=0)

TypeError: popen4() got an unexpected keyword argument 'bufsize'

Exception AttributeError: "'baresshpeer' object has no attribute 'pipeo'" in <bound method baresshpeer.cleanup of <hgext_baressh.baresshpeer object at 0x28c51f8c>> ignored

sp11% hg baressh --close-after hello ssh://release-dev/foo --buffered

running ssh release-dev 'hg -R foo serve --stdio'

** 非同梱のエクステンション sigshow に起因する例外が発生しました。

** 当該エクステンションのサポート対象 Mercurial の版: unknown

** エクステンション sigshow を無効化してから、再度同じ処理を実行してください。

** 問題が改善された場合、 障害の発生を エクステンションの作者 に報告してください。

** Python 2.7.10 (default, Sep  4 2015, 13:56:33) [GCC 4.2.1 20070719  [FreeBSD]]

Mercurial - 分散構成管理ツール (バージョン 3.4.2)

** Extensions loaded: sigshow, baressh

Traceback (most recent call last):

  File "/usr/local/bin/hg", line 43, in <module>

    mercurial.dispatch.run()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 29, in run

    sys.exit((dispatch(request(sys.argv[1:])) or 0) & 255)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 91, in dispatch

    ret = _runcatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 160, in _runcatch

    return _dispatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 885, in _dispatch

    cmdpats, cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 646, in runcommand

    ret = _runcommand(ui, options, cmd, d)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 976, in _runcommand

    return checkargs()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 947, in checkargs

    return cmdfunc()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 882, in <lambda>

    d = lambda: util.checksignature(func)(ui, *args, **cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/util.py", line 716, in check

    return func(*args, **kwargs)

  File "/home/estore/58Ka9/baressh.py", line 94, in baressh

    doublepipe=opts['doublepipe'])

  File "/home/estore/58Ka9/baressh.py", line 43, in __init__

    sub = util.popen4(cmd, bufsize=0)

TypeError: popen4() got an unexpected keyword argument 'bufsize'

Exception AttributeError: "'baresshpeer' object has no attribute 'pipeo'" in <bound method baresshpeer.cleanup of <hgext_baressh.baresshpeer object at 0x28c51f8c>> ignored

sp11% hg baressh --close-after between ssh://release-dev/foo --buffered

running ssh release-dev 'hg -R foo serve --stdio'

** 非同梱のエクステンション sigshow に起因する例外が発生しました。

** 当該エクステンションのサポート対象 Mercurial の版: unknown

** エクステンション sigshow を無効化してから、再度同じ処理を実行してください。

** 問題が改善された場合、 障害の発生を エクステンションの作者 に報告してください。

** Python 2.7.10 (default, Sep  4 2015, 13:56:33) [GCC 4.2.1 20070719  [FreeBSD]]

Mercurial - 分散構成管理ツール (バージョン 3.4.2)

** Extensions loaded: sigshow, baressh

Traceback (most recent call last):

  File "/usr/local/bin/hg", line 43, in <module>

    mercurial.dispatch.run()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 29, in run

    sys.exit((dispatch(request(sys.argv[1:])) or 0) & 255)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 91, in dispatch

    ret = _runcatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 160, in _runcatch

    return _dispatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 885, in _dispatch

    cmdpats, cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 646, in runcommand

    ret = _runcommand(ui, options, cmd, d)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 976, in _runcommand

    return checkargs()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 947, in checkargs

    return cmdfunc()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 882, in <lambda>

    d = lambda: util.checksignature(func)(ui, *args, **cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/util.py", line 716, in check

    return func(*args, **kwargs)

  File "/home/estore/58Ka9/baressh.py", line 94, in baressh

    doublepipe=opts['doublepipe'])

  File "/home/estore/58Ka9/baressh.py", line 43, in __init__

    sub = util.popen4(cmd, bufsize=0)

TypeError: popen4() got an unexpected keyword argument 'bufsize'

Exception AttributeError: "'baresshpeer' object has no attribute 'pipeo'" in <bound method baresshpeer.cleanup of <hgext_baressh.baresshpeer object at 0x28c51f8c>> ignored

sp11% hg baressh --close-after none ssh://nfs-release/foo --buffered --doublepipe

running ssh nfs-release 'hg -R foo serve --stdio'

** 非同梱のエクステンション sigshow に起因する例外が発生しました。

** 当該エクステンションのサポート対象 Mercurial の版: unknown

** エクステンション sigshow を無効化してから、再度同じ処理を実行してください。

** 問題が改善された場合、 障害の発生を エクステンションの作者 に報告してください。

** Python 2.7.10 (default, Sep  4 2015, 13:56:33) [GCC 4.2.1 20070719  [FreeBSD]]

Mercurial - 分散構成管理ツール (バージョン 3.4.2)

** Extensions loaded: sigshow, baressh

Traceback (most recent call last):

  File "/usr/local/bin/hg", line 43, in <module>

    mercurial.dispatch.run()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 29, in run

    sys.exit((dispatch(request(sys.argv[1:])) or 0) & 255)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 91, in dispatch

    ret = _runcatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 160, in _runcatch

    return _dispatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 885, in _dispatch

    cmdpats, cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 646, in runcommand

    ret = _runcommand(ui, options, cmd, d)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 976, in _runcommand

    return checkargs()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 947, in checkargs

    return cmdfunc()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 882, in <lambda>

    d = lambda: util.checksignature(func)(ui, *args, **cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/util.py", line 716, in check

    return func(*args, **kwargs)

  File "/home/estore/58Ka9/baressh.py", line 94, in baressh

    doublepipe=opts['doublepipe'])

  File "/home/estore/58Ka9/baressh.py", line 43, in __init__

    sub = util.popen4(cmd, bufsize=0)

TypeError: popen4() got an unexpected keyword argument 'bufsize'

Exception AttributeError: "'baresshpeer' object has no attribute 'pipeo'" in <bound method baresshpeer.cleanup of <hgext_baressh.baresshpeer object at 0x28c51f8c>> ignored

sp11% hg baressh --close-after hello ssh://release-dev/foo --buffered --doublepipe

running ssh release-dev 'hg -R foo serve --stdio'

** 非同梱のエクステンション sigshow に起因する例外が発生しました。

** 当該エクステンションのサポート対象 Mercurial の版: unknown

** エクステンション sigshow を無効化してから、再度同じ処理を実行してください。

** 問題が改善された場合、 障害の発生を エクステンションの作者 に報告してください。

** Python 2.7.10 (default, Sep  4 2015, 13:56:33) [GCC 4.2.1 20070719  [FreeBSD]]

Mercurial - 分散構成管理ツール (バージョン 3.4.2)

** Extensions loaded: sigshow, baressh

Traceback (most recent call last):

  File "/usr/local/bin/hg", line 43, in <module>

    mercurial.dispatch.run()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 29, in run

    sys.exit((dispatch(request(sys.argv[1:])) or 0) & 255)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 91, in dispatch

    ret = _runcatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 160, in _runcatch

    return _dispatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 885, in _dispatch

    cmdpats, cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 646, in runcommand

    ret = _runcommand(ui, options, cmd, d)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 976, in _runcommand

    return checkargs()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 947, in checkargs

    return cmdfunc()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 882, in <lambda>

    d = lambda: util.checksignature(func)(ui, *args, **cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/util.py", line 716, in check

    return func(*args, **kwargs)

  File "/home/estore/58Ka9/baressh.py", line 94, in baressh

    doublepipe=opts['doublepipe'])

  File "/home/estore/58Ka9/baressh.py", line 43, in __init__

    sub = util.popen4(cmd, bufsize=0)

TypeError: popen4() got an unexpected keyword argument 'bufsize'

Exception AttributeError: "'baresshpeer' object has no attribute 'pipeo'" in <bound method baresshpeer.cleanup of <hgext_baressh.baresshpeer object at 0x28c51f8c>> ignored

sp11% hg baressh --close-after between ssh://release-dev/foo --buffered --doublepipe

running ssh release-dev 'hg -R foo serve --stdio'

** 非同梱のエクステンション sigshow に起因する例外が発生しました。

** 当該エクステンションのサポート対象 Mercurial の版: unknown

** エクステンション sigshow を無効化してから、再度同じ処理を実行してください。

** 問題が改善された場合、 障害の発生を エクステンションの作者 に報告してください。

** Python 2.7.10 (default, Sep  4 2015, 13:56:33) [GCC 4.2.1 20070719  [FreeBSD]]

Mercurial - 分散構成管理ツール (バージョン 3.4.2)

** Extensions loaded: sigshow, baressh

Traceback (most recent call last):

  File "/usr/local/bin/hg", line 43, in <module>

    mercurial.dispatch.run()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 29, in run

    sys.exit((dispatch(request(sys.argv[1:])) or 0) & 255)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 91, in dispatch

    ret = _runcatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 160, in _runcatch

    return _dispatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 885, in _dispatch

    cmdpats, cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 646, in runcommand

    ret = _runcommand(ui, options, cmd, d)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 976, in _runcommand

    return checkargs()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 947, in checkargs

    return cmdfunc()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 882, in <lambda>

    d = lambda: util.checksignature(func)(ui, *args, **cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/util.py", line 716, in check

    return func(*args, **kwargs)

  File "/home/estore/58Ka9/baressh.py", line 94, in baressh

    doublepipe=opts['doublepipe'])

  File "/home/estore/58Ka9/baressh.py", line 43, in __init__

    sub = util.popen4(cmd, bufsize=0)

TypeError: popen4() got an unexpected keyword argument 'bufsize'

Exception AttributeError: "'baresshpeer' object has no attribute 'pipeo'" in <bound method baresshpeer.cleanup of <hgext_baressh.baresshpeer object at 0x28c51f8c>> ignored

sp11% 

2015年12月22日火曜日 17時00分20秒 UTC+9 FUJIWARA Katsunori:

[Katsunori FUJIWARA]

藤原です。

2015-12-22 17:11 GMT+09:00 ohira <shin....@gmail.com>:
> おおひらです。
>
> 実行するとすぐにスタックトレースを表示してプロンプトに返ってきます。
> どれもブロックはしませんでした。

あぁ、そこも 3.5 以降で拡張されていたか…… > util.popen4()

とりあえず 3.5.x 系か 3.6.x 系の Mercuiral で動かしてみてもらえま
すか？ 3.5.x 系や 3.6.x 系でもブロックする状況には変わりありません
でしたよね？

[ohira]

おおひらです。

クライアントマシンのhgのバージョンを3.6.2に変更しました。

再度テストを行ったところ　一つ目でブロックしました。

[実行ログ]

sp11% hg baressh --close-after none ssh://release-dev/foo

running ssh release-dev 'hg -R foo serve --stdio'

closing SSH channels ....

load: 0.91  cmd: python2.7 1424 [running] 0.11u 0.02s 0% 10676k

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 116, in dispatch

    ret = _runcatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 187, in _runcatch

    return _dispatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 920, in _dispatch

    cmdpats, cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 679, in runcommand

    ret = _runcommand(ui, options, cmd, d)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 1051, in _runcommand

    return checkargs()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 1011, in checkargs

    return cmdfunc()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 917, in <lambda>

    d = lambda: util.checksignature(func)(ui, *args, **cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/util.py", line 801, in check

    return func(*args, **kwargs)

  File "/home/estore/58Ka9/baressh.py", line 111, in baressh

    peer.cleanup()

  File "/usr/local/lib/python2.7/site-packages/mercurial/sshpeer.py", line 221, in cleanup

    for l in self.pipee:

----

sp11%

2015年12月22日火曜日 17時17分14秒 UTC+9 FUJIWARA Katsunori:

[ohira]

おおひらです。

サーバにlsofを入れて、クライアントがハングしている時のファイルファイルディスクリプタの状況を

みてみたら、hg push を実行でハングするときには、差分はありませんと表示された後に

開放されているようです。

今回のテストでもハングした状態でファイルディスクリプタは使われていないようです。

それに比べて^Dで止めるテストでは、ずっとファイルディスクリプタが使用中で

動作が違うようでした。

2015年12月22日火曜日 17時25分20秒 UTC+9 ohira:

[ohira]

おおひらです。

比較のため

問題があるクライアント、サーバーの組み合わせで

git で同じような処理を試してみました。

gitだとハングせずに処理ができるようです。

sp11% git clone ssh://release-dev/home/estore/bar

Cloning into 'bar'...

warning: You appear to have cloned an empty repository.

Checking connectivity... done.

sp11% cd bar

sp11% git status

On branch master

Initial commit

nothing to commit (create/copy files and use "git add" to track)

sp11% 

2015年12月22日火曜日 17時37分14秒 UTC+9 ohira:

[Katsunori FUJIWARA]

藤原です。

情報採取ありがとうございます。

2015年12月22日 18:54 ohira <shin....@gmail.com>:

> おおひらです。
>
> 比較のため
> 問題があるクライアント、サーバーの組み合わせで
> git で同じような処理を試してみました。
>
> gitだとハングせずに処理ができるようです。
>
> sp11% git clone ssh://release-dev/home/estore/bar
> Cloning into 'bar'...
> warning: You appear to have cloned an empty repository.
> Checking connectivity... done.
> sp11% cd bar
> sp11% git status
> On branch master
>
> Initial commit
>
> nothing to commit (create/copy files and use "git add" to track)
> sp11%

"hg serve --stdio" の直接実行や、git でのアクセスでブロックしない
ことから、サーバ側で EOF が検出できない問題が、Python のレイヤか、
あるいはそれよりも下のレイヤなのかを切り分けるのが良さそうですね。

検証用のプログラムをいくつか作成しましたので、以下の手順で確認をお
願いします。但し、後述する lsof 絡みの確認の方を先にお願いします。


1. クライアント側で baressh を有効化
(※ 古い版の Mercurial でも動作できるように修正済みです)

https://bitbucket.org/snippets/foozy/58Ka9#file-baressh.py

2. NG サーバ側で、以下の cfakeserve.c をコンパイルし、実行ファイ
ル cfakeserve を作成

https://bitbucket.org/snippets/foozy/58Ka9#file-cfakeserve.c

3. サーバ側コマンドに cfakeserve を明示して baressh を実行

$ hg baressh \
--close-after none \
--config ui.remotecmd=/path/to/cfakeserve \
ssh://release-dev/foo

4. 上記 3 の時点でブロックする場合、考えられるのは:

- Python の Subprocess モジュール経由で起動した場合に ssh の
挙動が異なる

fork/exec 絡みで git 等とは異なった挙動／設定になっていると
か？ (PIPE に対する ioctl、tty 絡み、signal 絡みあたり？)

もしも 3 でブロックしないようなら、以下の手順に進む

5. NG サーバ側で、以下の fakeserve.py を実行可能状態 (chmod
+x) にする

必要であれば、冒頭の #!/usr/bin/env python を #!/usr/local/bin/python
等に書き換える

https://bitbucket.org/snippets/foozy/58Ka9#file-fakeserve.py

6. サーバ側コマンドに fakeserve.py を明示して baressh を実行

$ hg baressh \
--close-after none \
--config ui.remotecmd=/path/to/fakeserve.py \
ssh://release-dev/foo

7. 上記 6 の時点でブロックする場合、考えられるのは:

- NG サーバ上の Python (2.7.10) の挙動が他と異なっている

Python 2.6.x 系が利用可能であれば、そちらでもブロックするか
確認してみてください。

もしも 6 でブロックしないようなら…… fakeserve.py って、hg
serve --stdio と実質同じことしかしてない筈なんですよねぇ (^ ^ ;;;)

後述する内容を書いていて思い付いたのですが、何らかの理由で
Python プロセスが終了処理でブロックしてしまっているのかも？

終了処理時に呼ばれるコールバックが無限待ちしているとか、資源
解放処理 (既存オブジェクトの __del__ 呼び出し等) の中でグルグ
ル回っているとか……


> 2015年12月22日火曜日 17時37分14秒 UTC+9 ohira:

>> サーバにlsofを入れて、クライアントがハングしている時のファイル
>> ファイルディスクリプタの状況をみてみたら、hg push を実行でハン
>> グするときには、差分はありませんと表示された後に開放されている
>> ようです。
>>
>> 今回のテストでもハングした状態でファイルディスクリプタは使われ
>> ていないようです。

これは:

- 事前の pgrep python 等で、別途稼働中の hg serve が無いことを確
認済み

- ハングしている時点での pgrep python 実行等により、稼働中の hg
serve の存在が確認可能

- lsof -p `pgrep python` 等で表示されるディスクリプタ一覧に、標
準入出力 (0, 1) やエラー出力 (2) が表示されない

例えば私の環境で、意図的に待ち状態にしたサーバ側プロセスに対す
る lsof 実行では、これらのファイルディスクリプタが有効な状態の
で、以下のような一覧が表示されます。

python 24561 fujiwara 0r FIFO 0,8 0t0 12295999 pipe
python 24561 fujiwara 1w FIFO 0,8 0t0 12296000 pipe
python 24561 fujiwara 2w FIFO 0,8 0t0 12296001 pipe


という認識であってますか？

ファイルディスクリプタは、プロセス毎の管理資源なので、PIPE におけ
る送り出し側プロセスで close (＝破棄) されても、受け取り側プロセス
のファイルディスクリプタは自動的には close されません。

ですから、「クライアントからの EOF 通知が届いてなくて、リクエスト
待ち状態」という障害原因の推測が正しければ、"hg serve" 実行中のプ
ロセスにおいて、ファイルディスクリプタが解放されている筈はありませ
ん。

しかし、" hg serve" プロセスにおいて明示的な close が実施されてい
ない標準入出力等が、「差分はありませんと表示された後に開放されてい
る」のだとしたら、Python プロセス終了処理の途中でブロックしている
可能性が出てきます。

もしも lsof での確認が、上記の想定と合致しているのであれば、ハング
している状態で、NG サーバ上の "hg serve" を実行している python プ
ロセスの CPU 使用率を確認してみてください。

CPU 使用率が高ければ、何らかの無限ループ状態でしょうし、そうでない
なら、何らかのイベント待ち（システムコール復帰待ち）状態になってい
るのだと思われます。


>> それに比べて^Dで止めるテストでは、ずっとファイルディスクリプタ
>> が使用中で動作が違うようでした。

「^Dで止めるテスト」の場合、^D 入力 ⇒ 即プロセス終了する筈ですか
ら、^D を入力する前の時点での lsof 確認、という認識で合っています
か？

そうであれば、この時点ではサーバ側は入力待ちで待機しているだけです
から、ファイルディスクリプタは当然解放されていないのは、想定通りの
挙動ですね。


--
----------------------------------------------------------------------
FUJIWARA Katsunori(flying...@gmail.com)

[ohira]

おおひらです。

サーバ側のプロセスの状況とファイルディスクリプタの状況をしらべてみました。

2015年12月24日木曜日 18時26分12秒 UTC+9 FUJIWARA Katsunori:

     後述する内容を書いていて思い付いたのですが、何らかの理由で
     Python プロセスが終了処理でブロックしてしまっているのかも？

     終了処理時に呼ばれるコールバックが無限待ちしているとか、資源
     解放処理 (既存オブジェクトの __del__ 呼び出し等) の中でグルグ
     ル回っているとか……

サーバー側は終了してしまっているようです。

直接の原因としてぐるぐるしているのはクライアントということになります。

プロトコル的にはどちらに原因があるのかわかりませんから根本的な

原因はサーバ側になるのかもしれませんが。

> 2015年12月22日火曜日 17時37分14秒 UTC+9 ohira:

>> サーバにlsofを入れて、クライアントがハングしている時のファイル
>> ファイルディスクリプタの状況をみてみたら、hg push を実行でハン
>> グするときには、差分はありませんと表示された後に開放されている
>> ようです。
>>
>> 今回のテストでもハングした状態でファイルディスクリプタは使われ
>> ていないようです。

これは:

  - 事前の pgrep python 等で、別途稼働中の hg serve が無いことを確
    認済み

  - ハングしている時点での pgrep python 実行等により、稼働中の hg
    serve の存在が確認可能

  - lsof -p `pgrep python` 等で表示されるディスクリプタ一覧に、標
    準入出力 (0, 1) やエラー出力 (2) が表示されない

途中では表示されますが、最終的には開放されて表示されなくなります。

開放された状態でクライアント側がハングしています。 

    例えば私の環境で、意図的に待ち状態にしたサーバ側プロセスに対す
    る lsof 実行では、これらのファイルディスクリプタが有効な状態の
    で、以下のような一覧が表示されます。

    python  24561 fujiwara    0r  FIFO    0,8      0t0 12295999 pipe
    python  24561 fujiwara    1w  FIFO    0,8      0t0 12296000 pipe
    python  24561 fujiwara    2w  FIFO    0,8      0t0 12296001 pipe


という認識であってますか？

サーバ側の途中経過で 0 1 2が使われています。

クライアントがハングした時点では、開放済みです。 

[estore@release-dev log]$ while true; do lsof -U; done

COMMAND  PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      3610 estore    0u  unix 0xffff810029646340      59157938 type=STREAM

hg      3610 estore    1w  unix 0xffff810029646340      59157938 type=STREAM

hg      3610 estore    2w  unix 0xffff8100296468c0      59157940 type=STREAM

COMMAND  PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      3610 estore    0u  unix 0xffff810029646340      59157938 type=STREAM

hg      3610 estore    1w  unix 0xffff810029646340      59157938 type=STREAM

hg      3610 estore    2w  unix 0xffff8100296468c0      59157940 type=STREAM

COMMAND  PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      3610 estore    0u  unix 0xffff810029646340      59157938 type=STREAM

hg      3610 estore    1w  unix 0xffff810029646340      59157938 type=STREAM

hg      3610 estore    2w  unix 0xffff8100296468c0      59157940 type=STREAM

COMMAND  PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      3610 estore    0u  unix 0xffff810029646340      59157938 type=STREAM

hg      3610 estore    1w  unix 0xffff810029646340      59157938 type=STREAM

hg      3610 estore    2w  unix 0xffff8100296468c0      59157940 type=STREAM

COMMAND  PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      3610 estore    0u  unix 0xffff810029646340      59157938 type=STREAM

hg      3610 estore    1w  unix 0xffff810029646340      59157938 type=STREAM

hg      3610 estore    2w  unix 0xffff8100296468c0      59157940 type=STREAM

クライアントハング時には表示なし。

ファイルディスクリプタは、プロセス毎の管理資源なので、PIPE におけ
る送り出し側プロセスで close (＝破棄) されても、受け取り側プロセス
のファイルディスクリプタは自動的には close されません。

ですから、「クライアントからの EOF 通知が届いてなくて、リクエスト
待ち状態」という障害原因の推測が正しければ、"hg serve" 実行中のプ
ロセスにおいて、ファイルディスクリプタが解放されている筈はありませ
ん。

しかし、" hg serve" プロセスにおいて明示的な close が実施されてい
ない標準入出力等が、「差分はありませんと表示された後に開放されてい
る」のだとしたら、Python プロセス終了処理の途中でブロックしている
可能性が出てきます。

クライアントがハングしている時点では、

サーバ側のプロセスは終了しています。 

もしも lsof での確認が、上記の想定と合致しているのであれば、ハング
している状態で、NG サーバ上の "hg serve" を実行している python プ
ロセスの CPU 使用率を確認してみてください。

CPUの使用はありませんでした。

プロセスは終了しているようなので、当然といえば当然なのですが。 

CPU 使用率が高ければ、何らかの無限ループ状態でしょうし、そうでない
なら、何らかのイベント待ち（システムコール復帰待ち）状態になってい
るのだと思われます。

クライアントハング時にサーバプロセスは終了していることがわかりました。 

 

サーバ側のプロセス 

 [estore@release-dev ~]$ while true; do ps -ef | fgrep hg |grep -v fgrep; done

estore    3610  3606 15 16:55 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore    3610  3606 15 16:55 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore    3610  3606 15 16:55 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore    3610  3606 15 16:55 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore    3610  3606 15 16:55 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore    3610  3606 15 16:55 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore    3610  3606 16 16:55 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

クライアントハング時には表示なし。

[ohira]

おおひらです。

新しいbaressh.pyを使用してテストを行いました。

baresshを指定して実行したところクライアントがハングして

クライアントがハングした時点ではサーバー側の実行が終わっているようです。

(プロセスも使用ファイルディスクリプタもなくなるので)

クライアントの実行結果

sp11% hg baressh \

--close-after none \

--config ui.remotecmd=58Ka/cfakeserve \

ssh://release-dev/foo

running ssh release-dev '58Ka/cfakeserve -R foo serve --stdio'

closing SSH channels ....

load: 0.07  cmd: python2.7 74580 [running] 0.14u 0.00s 0% 10648k

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 116, in dispatch

    ret = _runcatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 187, in _runcatch

    return _dispatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 920, in _dispatch

    cmdpats, cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 679, in runcommand

    ret = _runcommand(ui, options, cmd, d)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 1051, in _runcommand

    return checkargs()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 1011, in checkargs

    return cmdfunc()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 917, in <lambda>

    d = lambda: util.checksignature(func)(ui, *args, **cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/util.py", line 801, in check

    return func(*args, **kwargs)

  File "/home/estore/58Ka9/baressh.py", line 111, in baressh

    peer.cleanup()

  File "/usr/local/lib/python2.7/site-packages/mercurial/sshpeer.py", line 222, in cleanup

    self.ui.status(_("remote: "), l)

----

連携先: bash: 58Ka/cfakeserve: ���Τ褦�ʥե��������ǥ��쥯�ȥ��Ϥ����ޤ���

load: 0.06  cmd: python2.7 74580 [running] 0.14u 0.00s 0% 10868k

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 116, in dispatch

    ret = _runcatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 187, in _runcatch

    return _dispatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 920, in _dispatch

    cmdpats, cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 679, in runcommand

    ret = _runcommand(ui, options, cmd, d)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 1051, in _runcommand

    return checkargs()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 1011, in checkargs

    return cmdfunc()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 917, in <lambda>

    d = lambda: util.checksignature(func)(ui, *args, **cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/util.py", line 801, in check

    return func(*args, **kwargs)

  File "/home/estore/58Ka9/baressh.py", line 111, in baressh

    peer.cleanup()

  File "/usr/local/lib/python2.7/site-packages/mercurial/sshpeer.py", line 221, in cleanup

    for l in self.pipee:

----

sp11%

サーバの実行結果

サーバのプロセス

[estore@release-dev ~]$ while true; do ps -ef | fgrep cfakeserve |grep -v fgrep; done

estore   30554 30549  0 18:13 ?        00:00:00 bash -c 58Ka/cfakeserve -R foo serve --stdio

estore   30555 30554  0 18:13 ?        00:00:00 bash -c 58Ka/cfakeserve -R foo serve --stdio

estore   30556 30555  0 18:13 ?        00:00:00 bash -c 58Ka/cfakeserve -R foo serve --stdio

estore   30554 30549  0 18:13 ?        00:00:00 bash -c 58Ka/cfakeserve -R foo serve --stdio

estore   30554 30549  0 18:13 ?        00:00:00 bash -c 58Ka/cfakeserve -R foo serve --stdio

estore   30581 30554  0 18:13 ?        00:00:00 bash -c 58Ka/cfakeserve -R foo serve --stdio

estore   30582 30581  0 18:13 ?        00:00:00 bash -c 58Ka/cfakeserve -R foo serve --stdio

estore   30554 30549  0 18:13 ?        00:00:00 bash -c 58Ka/cfakeserve -R foo serve --stdio

estore   30587 30554  0 18:13 ?        00:00:00 bash -c 58Ka/cfakeserve -R foo serve --stdio

estore   30589 30587  0 18:13 ?        00:00:00 bash -c 58Ka/cfakeserve -R foo serve --stdio

estore   30554 30549  0 18:13 ?        00:00:00 bash -c 58Ka/cfakeserve -R foo serve --stdio

estore   30587 30554  0 18:13 ?        00:00:00 bash -c 58Ka/cfakeserve -R foo serve --stdio

estore   30554 30549  0 18:13 ?        00:00:00 bash -c 58Ka/cfakeserve -R foo serve --stdio

estore   30587 30554  0 18:13 ?        00:00:00 bash -c 58Ka/cfakeserve -R foo serve --stdio

estore   30554 30549  0 18:13 ?        00:00:00 bash -c 58Ka/cfakeserve -R foo serve --stdio

estore   30587 30554  0 18:13 ?        00:00:00 bash -c 58Ka/cfakeserve -R foo serve --stdio

[estore@release-dev ~]$

クライアントハング時にはプロセス無し

サーバのファイルディスクリプタ

[estore@release-dev log]$ while true; do lsof -U; done

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

bash    30554 estore    0u  unix 0xffff81000a28f200      73875728 type=STREAM

bash    30554 estore    1u  unix 0xffff81000a28f200      73875728 type=STREAM

bash    30554 estore    2u  unix 0xffff81000a28ec80      73875730 type=STREAM

bash    30555 estore    0u  unix 0xffff81000a28f200      73875728 type=STREAM

bash    30555 estore    2u  unix 0xffff81000a28ec80      73875730 type=STREAM

bash    30556 estore    0u  unix 0xffff81000a28f200      73875728 type=STREAM

bash    30556 estore    2u  unix 0xffff81000a28ec80      73875730 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

bash    30554 estore    0u  unix 0xffff81000a28f200      73875728 type=STREAM

bash    30554 estore   10u  unix 0xffff81000a28f200      73875728 type=STREAM

bash    30554 estore   11u  unix 0xffff81000a28ec80      73875730 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

bash    30554 estore    0u  unix 0xffff81000a28f200      73875728 type=STREAM

bash    30554 estore   10u  unix 0xffff81000a28f200      73875728 type=STREAM

bash    30554 estore   11u  unix 0xffff81000a28ec80      73875730 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

bash    30554 estore    0u  unix 0xffff81000a28f200      73875728 type=STREAM

bash    30554 estore   10u  unix 0xffff81000a28f200      73875728 type=STREAM

bash    30554 estore   11u  unix 0xffff81000a28ec80      73875730 type=STREAM

bash    30587 estore    0u  unix 0xffff81000a28f200      73875728 type=STREAM

bash    30587 estore   10u  unix 0xffff81000a28f200      73875728 type=STREAM

bash    30587 estore   11u  unix 0xffff81000a28ec80      73875730 type=STREAM

bash    30589 estore    0u  unix 0xffff81000a28f200      73875728 type=STREAM

bash    30589 estore   10u  unix 0xffff81000a28f200      73875728 type=STREAM

bash    30589 estore   11u  unix 0xffff81000a28ec80      73875730 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

bash    30554 estore    0u  unix 0xffff81000a28f200      73875728 type=STREAM

bash    30554 estore   10u  unix 0xffff81000a28f200      73875728 type=STREAM

bash    30554 estore   11u  unix 0xffff81000a28ec80      73875730 type=STREAM

bash    30587 estore    0u  unix 0xffff81000a28f200      73875728 type=STREAM

bash    30587 estore   10u  unix 0xffff81000a28f200      73875728 type=STREAM

bash    30587 estore   11u  unix 0xffff81000a28ec80      73875730 type=STREAM

bash    30589 estore    0u  unix 0xffff81000a28f200      73875728 type=STREAM

bash    30589 estore   10u  unix 0xffff81000a28f200      73875728 type=STREAM

bash    30589 estore   11u  unix 0xffff81000a28ec80      73875730 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

bash    30554 estore    0u  unix 0xffff81000a28f200      73875728 type=STREAM

bash    30554 estore   10u  unix 0xffff81000a28f200      73875728 type=STREAM

bash    30554 estore   11u  unix 0xffff81000a28ec80      73875730 type=STREAM

bash    30587 estore    0u  unix 0xffff81000a28f200      73875728 type=STREAM

bash    30587 estore   10u  unix 0xffff81000a28f200      73875728 type=STREAM

bash    30587 estore   11u  unix 0xffff81000a28ec80      73875730 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

bash    30554 estore    0u  unix 0xffff81000a28f200      73875728 type=STREAM

bash    30554 estore   10u  unix 0xffff81000a28f200      73875728 type=STREAM

bash    30554 estore   11u  unix 0xffff81000a28ec80      73875730 type=STREAM

bash    30587 estore    0u  unix 0xffff81000a28f200      73875728 type=STREAM

bash    30587 estore   10u  unix 0xffff81000a28f200      73875728 type=STREAM

bash    30587 estore   11u  unix 0xffff81000a28ec80      73875730 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

bash    30554 estore    0u  unix 0xffff81000a28f200      73875728 type=STREAM

bash    30554 estore   10u  unix 0xffff81000a28f200      73875728 type=STREAM

bash    30554 estore   11u  unix 0xffff81000a28ec80      73875730 type=STREAM

bash    30587 estore    0u  unix 0xffff81000a28f200      73875728 type=STREAM

bash    30587 estore   10u  unix 0xffff81000a28f200      73875728 type=STREAM

bash    30587 estore   11u  unix 0xffff81000a28ec80      73875730 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

bash    30554 estore    0u  unix 0xffff81000a28f200      73875728 type=STREAM

[estore@release-dev log]$

クライアントハング時には、サーバ側ファイルディスクリプタ開放済み

2015年12月24日木曜日 18時26分12秒 UTC+9 FUJIWARA Katsunori:

藤原です。

[Katsunori FUJIWARA]

藤原です。

情報採取ありがとうございます。


2015年12月30日 17:38 ohira <shin....@gmail.com>:

> おおひらです。
>
> サーバ側のプロセスの状況とファイルディスクリプタの状況をしらべてみました。
>
>
> 2015年12月24日木曜日 18時26分12秒 UTC+9 FUJIWARA Katsunori:

(snip)

クライアントホストから ssh 経由で非対話的にコマンドを実行した場合、
サーバ側で実行されるコマンドの標準入出力等は、サーバ側の sshd プロ
セスと PIPE で接続されます。

「もしかして Linux では、UNIX domain socket と PIPE の内部実装が統
合されている？」とも思いましたが、私の手元の Linux
2.6.32-5 (debian) では、ssh 経由でのサーバ側コマンド実行では、標準
入力には PIPE が使用されていました。

例えば、クライアント側で "ssh release-dev cat -n" を実行しつつ、入
力待ちになっている間に release-dev 側で cat プロセスの lsof を見た
場合、ディスクリプタの 0, 1, 2 は PIPE ですか？ UNIX domain
socket ですか？

hg コマンドが明示的に UNIX domain socket を使いそうな契機として思
いつくのは、chg 等を経由して command server を利用しているケースな
のですが、何か思い当たる節はありますか？ ＞ おおひらさん

https://bitbucket.org/yuja/chg
http://tcha.org/blog/2011/12/14/fast-hg-client/

とは言え、以前頂いたメールだと、ssh 経由で確認した hg ファイルの冒
頭は、通常の hg コマンドのそれなんですよねぇ。

sp11% ssh release-dev head /usr/local/bin/hg

#!/usr/local/bin/python
#
# mercurial - scalable distributed SCM
#
# Copyright 2005-2007 Matt Mackall <m...@selenic.com>
#
# This software may be used and distributed according to the terms of the
# GNU General Public License version 2 or any later version.

import os

sp11%

hg config 出力にも、特に怪しい alias 的なものは見受けられませんで
したし…… もしかして、リモート側のシェル (bash 等) が alias か何
かでやらかしているとか？

command server が絡むようなケースで何か思い当たる事はありますか？ ＞ 西原さん

>> CPU 使用率が高ければ、何らかの無限ループ状態でしょうし、そうでない
>> なら、何らかのイベント待ち（システムコール復帰待ち）状態になってい
>> るのだと思われます。
>
> クライアントハング時にサーバプロセスは終了していることがわかりました。
>
> サーバ側のプロセス
> [estore@release-dev ~]$ while true; do ps -ef | fgrep hg |grep -v fgrep;
> done
> estore 3610 3606 15 16:55 ? 00:00:00 /usr/local/bin/python
> /usr/local/bin/hg -R foo serve --stdio
> estore 3610 3606 15 16:55 ? 00:00:00 /usr/local/bin/python
> /usr/local/bin/hg -R foo serve --stdio
> estore 3610 3606 15 16:55 ? 00:00:00 /usr/local/bin/python
> /usr/local/bin/hg -R foo serve --stdio
> estore 3610 3606 15 16:55 ? 00:00:00 /usr/local/bin/python
> /usr/local/bin/hg -R foo serve --stdio
> estore 3610 3606 15 16:55 ? 00:00:00 /usr/local/bin/python
> /usr/local/bin/hg -R foo serve --stdio
> estore 3610 3606 15 16:55 ? 00:00:00 /usr/local/bin/python
> /usr/local/bin/hg -R foo serve --stdio
> estore 3610 3606 16 16:55 ? 00:00:00 /usr/local/bin/python
> /usr/local/bin/hg -R foo serve --stdio
> クライアントハング時には表示なし。

クライアントがハングした時点で、hg コマンドの親プロセス (上記のケー
スならプロセスID 3606) の実行状況は確認できますか？

もしも実行中であれば、そのプロセスを親プロセスとする他のプロセスは
ありますか？

また、サーバ側で pgrep sshd を実行した場合、以下のタイミングで出力
される PID 一覧に差分はありますか？

- クライアントからの要求前
- クライアントからの要求がハング中

差がある場合、その sshd プロセスがクライアントからの要求を橋渡しし
ているプロセスです。

上記の情報と、ps -ejH 出力等を元に、関連するプロセスの稼働状況を確
認してみてください。

もしも、pgrep sshd 出力に差がない場合は、サーバ側の sshd による処
理の終了を、クライアント側の ssh コマンドが検出できていないことに
なりますので、ssh レイヤのレベルで原因調査した方がよいかもしれません。

--
----------------------------------------------------------------------
FUJIWARA Katsunori(flying...@gmail.com)

[Yuya Nishihara]

On Wed, 30 Dec 2015 20:44:48 +0900, Katsunori FUJIWARA wrote:
> 2015年12月30日 17:38 ohira <shin....@gmail.com>:

> > サーバ側の途中経過で 0 1 2が使われています。
> > クライアントがハングした時点では、開放済みです。
> >
> > [estore@release-dev log]$ while true; do lsof -U; done
> > COMMAND PID USER FD TYPE DEVICE SIZE NODE NAME
> > hg 3610 estore 0u unix 0xffff810029646340 59157938 type=STREAM
> > hg 3610 estore 1w unix 0xffff810029646340 59157938 type=STREAM
> > hg 3610 estore 2w unix 0xffff8100296468c0 59157940 type=STREAM

無名ソケットくさいですね。サーバー側の sshd はいつのですか?
OpenSSH のログに、相当古いですが気になる修正がありました。

http://cvsweb.openbsd.org/cgi-bin/cvsweb/src/usr.bin/ssh/session.c#rev1.238

> hg コマンドが明示的に UNIX domain socket を使いそうな契機として思
> いつくのは、chg 等を経由して command server を利用しているケースな

chg の場合は、プロセス名が hg serve --cmdserver=chgunix になるはずです。

> command server が絡むようなケースで何か思い当たる事はありますか？ ＞ 西原さん

コマンドサーバーは関係ないですが、親プロセスが子プロセスを fork し、子プロセス
がデーモンを(double fork せずに)フォークし、そのデーモンが標準入出力を掴んで
いると、親プロセスが子プロセスの終了を検出できずに処理が詰まる事があります。
例えば、以下の関係で kdiff3 の終了を EOF で待っていると死ねません。

親プロセス: hg
子プロセス: kdiff3 (KDE 対応版)
デーモン: kded

今回の場合は、親(sshd)が子(hg)の終了を検出できていないのかもしれません。

[ohira]

おおひらです。

(対処療法で根本的な原因は不明のままですが)

nohupを使用していたのが原因のようです。

(古いバージョンのsshに限った話かもしれませんが)

ssh経由でmercurialを利用する場合にnohupを使わない方が良いようです。

>> command server が絡むようなケースで何か思い当たる事はありますか？ ＞ 西原さん 

> コマンドサーバーは関係ないですが、親プロセスが子プロセスを fork し、子プロセス 

> がデーモンを(double fork せずに)フォークし、そのデーモンが標準入出力を掴んで 

> いると、親プロセスが子プロセスの終了を検出できずに処理が詰まる事があります。 

> 例えば、以下の関係で kdiff3 の終了を EOF で待っていると死ねません。 

>  親プロセス: hg 

> 子プロセス: kdiff3 (KDE 対応版) 

> デーモン: kded 

> 今回の場合は、親(sshd)が子(hg)の終了を検出できていないのかもしれません。 

西原さんのご指摘をいただき、sshdの動作を確認しました。

ご指摘の通りにmercurialの親プロセスが終了していないことがわかりました。

今回の環境ではsshを起動するときにnohupを使用していました。

nohupの利用をやめることでmercurialのコマンドが終了しない現象が

解決しました。

opensshのバージョンは、かなり古く4.3.p2でした、4系統の最新と思われる

4.9.p1にアップしてテストしましたが、状況はかわりませんでした。

(どちらのバージョンも2008ごろのもののようです ）

sshdの動作状況を確認しやすくするためport22299で別のsshdをLISTENする

ようにして動作を確認しました。(daemontools経由で起動)

hgとgit以外でssh経由の動作をさせた場合どうなのだろうと思い

rsyncで確認してみたところ問題なく終了しました。

(svnやcvsでも大丈夫だと思いますが、問題が起きた環境では試していません)

sp11% rsync -a -e "ssh" aaa release-dev:aaa  

sp11%

[estore@release-dev ~]$ 

[estore@release-dev ~]$ while true; do ps -ef | fgrep rsync |grep -v fgrep; done

estore   29130 29129  0 13:11 ?        00:00:00 bash -c rsync --server -logDtpre.iLfx . aaa

estore   29137 29130  0 13:11 ?        00:00:00 bash -c rsync --server -logDtpre.iLfx . aaa

estore   29138 29137  0 13:11 ?        00:00:00 bash -c rsync --server -logDtpre.iLfx . aaa

estore   29130 29129  0 13:11 ?        00:00:00 bash -c rsync --server -logDtpre.iLfx . aaa

estore   29153 29130  0 13:11 ?        00:00:00 bash -c rsync --server -logDtpre.iLfx . aaa

estore   29130 29129  0 13:11 ?        00:00:00 [rsync]

estore   29130 29129  0 13:11 ?        00:00:00 rsync --server -logDtpre.iLfx . aaa

estore   29130 29129  0 13:11 ?        00:00:00 rsync --server -logDtpre.iLfx . aaa

estore   29130 29129  0 13:11 ?        00:00:00 rsync --server -logDtpre.iLfx . aaa

estore   29130 29129  0 13:11 ?        00:00:00 rsync --server -logDtpre.iLfx . aaa

estore   29130 29129  0 13:11 ?        00:00:00 rsync --server -logDtpre.iLfx . aaa

estore   29130 29129  0 13:11 ?        00:00:00 rsync --server -logDtpre.iLfx . aaa

estore   29130 29129  0 13:11 ?        00:00:00 rsync --server -logDtpre.iLfx . aaa

estore   29216 29130  0 13:11 ?        00:00:00 rsync --server -logDtpre.iLfx . aaa

estore   29130 29129  0 13:11 ?        00:00:00 rsync --server -logDtpre.iLfx . aaa

estore   29216 29130  0 13:11 ?        00:00:00 rsync --server -logDtpre.iLfx . aaa

estore   29130 29129  0 13:11 ?        00:00:00 rsync --server -logDtpre.iLfx . aaa

estore   29216 29130  0 13:11 ?        00:00:00 rsync --server -logDtpre.iLfx . aaa

estore   29130 29129  0 13:11 ?        00:00:00 rsync --server -logDtpre.iLfx . aaa

以下表示なし

以下mercurialでの動作確認、親プロセスの未終了の確認ログ

[クライアント]

sp11% cd foo

sp11% hg push ssh://release-dev/foo

ssh://release-dev/foo への反映中

差分はありません

load: 0.25  cmd: python2.7 92849 [running] 0.16u 0.03s 0% 12992k

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 54, in run

    sys.exit((dispatch(request(sys.argv[1:])) or 0) & 255)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 116, in dispatch

    ret = _runcatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 187, in _runcatch

    return _dispatch(req)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 920, in _dispatch

    cmdpats, cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 679, in runcommand

    ret = _runcommand(ui, options, cmd, d)

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 1051, in _runcommand

    return checkargs()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 1011, in checkargs

    return cmdfunc()

  File "/usr/local/lib/python2.7/site-packages/mercurial/dispatch.py", line 917, in <lambda>

    d = lambda: util.checksignature(func)(ui, *args, **cmdoptions)

  File "/usr/local/lib/python2.7/site-packages/mercurial/util.py", line 801, in check

    return func(*args, **kwargs)

  File "/usr/local/lib/python2.7/site-packages/mercurial/sshpeer.py", line 221, in cleanup

    for l in self.pipee:

----

sp11% 

sp11% 

[sshdのログ port22299]

[estore@release-dev ~]$ tail -F /service/ssh22299/log/main/current | tai64nlocal

2016-01-04 16:43:13.534932500 tcpserver: status: 0/200

2016-01-04 16:44:07.577328500 tcpserver: status: 1/200

2016-01-04 16:44:07.577344500 tcpserver: pid 12003 from 192.168.1.244

2016-01-04 16:44:07.577344500 tcpserver: ok 12003 0:172.16.10.10:22299 :192.168.1.244::65286

2016-01-04 16:44:08.082212500 Accepted publickey for estore from 192.168.1.244 port 65286 ssh2

[終了したmercurialの親プロセスをたどりました]

これは、クライアントがハングした後のもの

接続をOKしたプロセス12003が残っているようです。

[estore@release-dev ~]$ 

[estore@release-dev ~]$ ps -ef | fgrep 12003 | grep -v fgrep

root     12003  5557  0 16:44 ?        00:00:00 sshd: estore [priv]     

estore   12128 12003  0 16:44 ?        00:00:00 sshd: estore@notty      

[estore@release-dev ~]$ ps -ef | fgrep 12128 | grep -v fgrep

estore   12128 12003  0 16:44 ?        00:00:00 sshd: estore@notty      

[estore@release-dev ~]$ ps -ef | fgrep 5557 | grep -v fgrep

root      5557  5556  0 16:43 ?        00:00:00 tcpserver -vDHRl0 -x rules/data.cdb -U -c 200 0 22299 /usr/local/sbin/sshd -ei

root     12003  5557  0 16:44 ?        00:00:00 sshd: estore [priv]     

[estore@release-dev ~]$ ps -ef | fgrep 5556 | grep -v fgrep

root      5556  2308  0 16:43 ?        00:00:00 supervise ssh22299

root      5557  5556  0 16:43 ?        00:00:00 tcpserver -vDHRl0 -x rules/data.cdb -U -c 200 0 22299 /usr/local/sbin/sshd -ei

[estore@release-dev ~]$ ps -ef | fgrep 2308 | grep -v fgrep

root      2308  2273  0  2015 ?        00:00:23 svscan /service

root      5556  2308  0 16:43 ?        00:00:00 supervise ssh22299

root      9072  2308  0 14:24 ?        00:00:00 supervise log

root     23080  2089  0  2015 ?        00:00:00 sshd: estore [priv]

estore   23087 23080  0  2015 ?        00:00:00 sshd: estore@notty

[estore@release-dev ~]$ ps -ef | fgrep 2273 | grep -v fgrep

root      2273     1  0  2015 ?        00:00:00 /bin/sh /command/svscanboot

root      2308  2273  0  2015 ?        00:00:23 svscan /service

root      2310  2273  0  2015 ?        00:00:00 readproctitle service errors: ................................................................................................................................................................................................................................................................................................................................................................................................................

[estore@release-dev ~]$ 

動作中のプロセス

[estore@release-dev ~]$ while true; do ps -ef | fgrep hg |grep -v fgrep; done

estore   12138 12128  0 16:44 ?        00:00:00 bash -c hg -R foo serve --stdio

estore   12138 12128  0 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  0 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  5 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  2 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  3 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  3 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  3 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  3 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  3 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  2 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  3 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  3 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  3 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  3 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  3 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  4 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  4 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  4 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  3 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  3 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  3 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  3 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  3 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  3 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  3 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  3 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  3 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  3 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  3 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  3 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  3 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  3 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  3 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  3 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  3 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  3 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  3 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  3 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  3 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  3 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  3 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  3 16:44 ?        00:00:00 /usr/local/bin/python /usr/local/bin/hg -R foo serve --stdio

estore   12138 12128  3 16:44 ?        00:00:00 [hg]

この後表示なし

利用中のファイルディスクリプタ

[estore@release-dev ~]$ while true; do lsof -U; done

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

bash    12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

bash    12138 estore   10u  unix 0xffff81000fa50140      84199117 type=STREAM

bash    12138 estore   11u  unix 0xffff81000fa511c0      84199119 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    1w  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    2w  unix 0xffff81000fa511c0      84199119 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    1w  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    2w  unix 0xffff81000fa511c0      84199119 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    1w  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    2w  unix 0xffff81000fa511c0      84199119 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    1w  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    2w  unix 0xffff81000fa511c0      84199119 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    1w  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    2w  unix 0xffff81000fa511c0      84199119 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    1w  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    2w  unix 0xffff81000fa511c0      84199119 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    1w  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    2w  unix 0xffff81000fa511c0      84199119 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    1w  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    2w  unix 0xffff81000fa511c0      84199119 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    1w  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    2w  unix 0xffff81000fa511c0      84199119 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    1w  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    2w  unix 0xffff81000fa511c0      84199119 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    1w  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    2w  unix 0xffff81000fa511c0      84199119 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    1w  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    2w  unix 0xffff81000fa511c0      84199119 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    1w  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    2w  unix 0xffff81000fa511c0      84199119 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    1w  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    2w  unix 0xffff81000fa511c0      84199119 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    1w  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    2w  unix 0xffff81000fa511c0      84199119 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    1w  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    2w  unix 0xffff81000fa511c0      84199119 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    1w  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    2w  unix 0xffff81000fa511c0      84199119 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    1w  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    2w  unix 0xffff81000fa511c0      84199119 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    1w  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    2w  unix 0xffff81000fa511c0      84199119 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    1w  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    2w  unix 0xffff81000fa511c0      84199119 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    1w  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    2w  unix 0xffff81000fa511c0      84199119 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    1w  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    2w  unix 0xffff81000fa511c0      84199119 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    1w  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    2w  unix 0xffff81000fa511c0      84199119 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    1w  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    2w  unix 0xffff81000fa511c0      84199119 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    1w  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    2w  unix 0xffff81000fa511c0      84199119 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    1w  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    2w  unix 0xffff81000fa511c0      84199119 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    1w  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    2w  unix 0xffff81000fa511c0      84199119 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    1w  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    2w  unix 0xffff81000fa511c0      84199119 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    1w  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    2w  unix 0xffff81000fa511c0      84199119 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    1w  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    2w  unix 0xffff81000fa511c0      84199119 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    1w  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    2w  unix 0xffff81000fa511c0      84199119 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    1w  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    2w  unix 0xffff81000fa511c0      84199119 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    1w  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    2w  unix 0xffff81000fa511c0      84199119 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    1w  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    2w  unix 0xffff81000fa511c0      84199119 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    1w  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    2w  unix 0xffff81000fa511c0      84199119 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    1w  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    2w  unix 0xffff81000fa511c0      84199119 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    1w  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    2w  unix 0xffff81000fa511c0      84199119 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    1w  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    2w  unix 0xffff81000fa511c0      84199119 type=STREAM

COMMAND   PID   USER   FD   TYPE             DEVICE SIZE     NODE NAME

hg      12138 estore    0u  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    1w  unix 0xffff81000fa50140      84199117 type=STREAM

hg      12138 estore    2w  unix 0xffff81000fa511c0      84199119 type=STREAM

この後表示なし。

[以下のファイルを修正してnohupを利用しないように変更]

sp11% tail -5 ~/.ssh/config

host release-dev release-dev.mxfw.net

#        ProxyCommand nohup ssh co122 nc %h %p # NG

#        ProxyCommand nohup ssh co122 nc %h 22299 # NG

        ProxyCommand ssh co122 nc %h 22299 # OK

sp11% 

今回の環境ではこの変更(NG->OK)で問題が解決したようです。

nohupよりもscreenを使うべき

http://www.m-bsys.com/knowledge/linux-jobs

nohupの説明

http://www.codereading.com/nb/ignore-the-hangup-signal.html

nohupの詳細な説明

http://www.glamenv-septzen.net/view/854

nohupの簡単なマニュアル

https://linuxjm.osdn.jp/html/GNU_sh-utils/man1/nohup.1.html

gitでのnohupの利用例(使い方が違いますがnonupで高速化)

https://yakst.com/ja/posts/48

[ohira]

おおひらです。

ハングする前と後のpgrep sshの差を調べました。

[estore@release-dev ~]$ 

[estore@release-dev ~]$ diff a.txt.01 a.txt.06

39a40,41

> 11686

> 11739

[estore@release-dev ~]$ ps -ef | fgrep 11686 | grep -v fgrep

root     11686 28505  0 09:35 ?        00:00:00 sshd: estore [priv]     

estore   11739 11686  0 09:35 ?        00:00:00 sshd: estore@notty      

[estore@release-dev ~]$ ps -ef | fgrep 11739 | grep -v fgrep

estore   11739 11686  0 09:35 ?        00:00:00 sshd: estore@notty      

[estore@release-dev ~]$ ps -ef | fgrep 28505 | grep -v fgrep

root     11686 28505  0 09:35 ?        00:00:00 sshd: estore [priv]     

root     28505 28504  0 09:29 ?        00:00:00 tcpserver -vDHRl0 -x rules/data.cdb -U -c 200 0 22299 /usr/local/sbin/sshd -ei

[estore@release-dev ~]$ ps -ef | fgrep 28504 | grep -v fgrep

root     28504  2308  0 09:29 ?        00:00:00 supervise ssh22299

root     28505 28504  0 09:29 ?        00:00:00 tcpserver -vDHRl0 -x rules/data.cdb -U -c 200 0 22299 /usr/local/sbin/sshd -ei

[estore@release-dev ~]$ ps -ef | fgrep 2308 | grep -v fgrep

root      2308  2273  0  2015 ?        00:00:24 svscan /service

root      9072  2308  0 Jan04 ?        00:00:00 supervise log

root     23080  2089  0  2015 ?        00:00:00 sshd: estore [priv]

estore   23087 23080  0  2015 ?        00:00:00 sshd: estore@notty

root     28504  2308  0 09:29 ?        00:00:00 supervise ssh22299

[estore@release-dev ~]$ ps -ef | fgrep 2273 | grep -v fgrep

root      2273     1  0  2015 ?        00:00:00 /bin/sh /command/svscanboot

root      2308  2273  0  2015 ?        00:00:24 svscan /service

root      2310  2273  0  2015 ?        00:00:00 readproctitle service errors: ................................................................................................................................................................................................................................................................................................................................................................................................................

[estore@release-dev ~]$ 

2015年12月30日水曜日 20時44分50秒 UTC+9 FUJIWARA Katsunori:

[ohira]

おおひらです。

mercurialのサーバ側プロセス終了後も残っている親プロセスのpipeの利用状況を確認しました。

親子関係にあるプロセス11739とプロセス11686はパイプ77062521で通信している。

子プロセス側の11739がpipe84885686を使ってmercurialのサーバ側プロセスと

通信していたっぽいが、（サーバプロセスは終了済みだし）84885686を利用している他のプロセスは無いようです。

確認ログ

[estore@release-dev ~]$ 

[estore@release-dev ~]$ sudo lsof -p 11739 | fgrep FIFO

sshd    11739 estore    2w  FIFO                0,6      0t0 77062521 pipe

sshd    11739 estore    6r  FIFO                0,6      0t0 84885686 pipe

sshd    11739 estore    7w  FIFO                0,6      0t0 84885686 pipe

[estore@release-dev ~]$ sudo lsof -p 11686 | fgrep FIFO   

sshd    11686 root    2w  FIFO                0,6      0t0 77062521 pipe

[estore@release-dev ~]$ sudo lsof | fgrep 84885686

sshd      11739         estore    6r  FIFO                0,6      0t0   84885686 pipe

sshd      11739         estore    7w  FIFO                0,6      0t0   84885686 pipe

[estore@release-dev ~]$ 

2016年1月5日火曜日 10時13分40秒 UTC+9 ohira:

[ohira]

おおひらです。

サーバ側のmercurialの親プロセスが終了できないのが原因のようです。

nohupを使用しないか、

mercurialの親プロセスを kill -HUP することで

クライアント側のプロセスが終了します。

[sshクライアントの設定]

sp11% tail ~/.ssh/config

host hup

        hostname release-dev

        port 22299

        ProxyCommand       ssh co122 nc %h %p # OK

host nohup

        hostname release-dev

        port 22299

        ProxyCommand nohup ssh co122 nc %h %p # NG

sp11%

[クライアントのログ]

ssh://hup/foo の場合は、何もしなくても終了。(signal 1.の表示あり)

ssh://nohup/foo の場合は、ハングした時に残っているmercurialの親プロセスを kill -HUP することで終了。

sp11% cd foo

sp11% hg push ssh://hup/foo

ssh://hup/foo への反映中

差分はありません

連携先: Killed by signal 1.

sp11% 

sp11% 

sp11% hg push ssh://nohup/foo

ssh://nohup/foo への反映中

差分はありません

sp11% 

[サーバ側のsshdのログ]

2016-01-05 12:32:33.155708500 tcpserver: status: 0/200

<hupの場合>

2016-01-05 14:10:13.614511500 tcpserver: status: 1/200

2016-01-05 14:10:13.615305500 tcpserver: pid 22051 from 192.168.1.244

2016-01-05 14:10:13.615446500 tcpserver: ok 22051 0:172.16.10.10:22299 :192.168.1.244::37546

2016-01-05 14:10:13.873909500 Accepted publickey for estore from 192.168.1.244 port 37546 ssh2

2016-01-05 14:10:14.883089500 tcpserver: end 22051 status 0

2016-01-05 14:10:14.883091500 tcpserver: status: 0/200

<ここからnohupの場合>

2016-01-05 14:11:31.743359500 tcpserver: status: 1/200

2016-01-05 14:11:31.744152500 tcpserver: pid 22117 from 192.168.1.244

2016-01-05 14:11:31.744288500 tcpserver: ok 22117 0:172.16.10.10:22299 :192.168.1.244::29053

2016-01-05 14:11:32.291301500 Accepted publickey for estore from 192.168.1.244 port 29053 ssh2

<ここで、クライントがハングしている>

<子プロセスを　kill -HUP 22121 することで、プロセス22117が終了, クライアントも終了>

2016-01-05 14:14:13.273405500 tcpserver: end 22117 status 65280

2016-01-05 14:14:13.273408500 tcpserver: status: 0/200

[サーバ側の操作ログ]

<ssh://hup への接続の場合は、何もしなくてもプロセスが終了している>

[estore@release-dev ~]$ ps -ef | fgrep 22051 | grep -v fgrep

[estore@release-dev ~]$ 

[estore@release-dev ~]$

<ssh://nohup への接続の場合は、サーバ側にプロセスが残っている>

[estore@release-dev ~]$ ps -ef | fgrep 22117 | grep -v fgrep

root     22117 21688  0 14:11 ?        00:00:00 sshd: estore [priv]     

estore   22121 22117  0 14:11 ?        00:00:00 sshd: estore@notty      

[estore@release-dev ~]$ ps -ef | fgrep 22121 | grep -v fgrep

estore   22121 22117  0 14:11 ?        00:00:00 sshd: estore@notty      

[estore@release-dev ~]$ 

[estore@release-dev ~]$ sudo lsof -p 22117 | fgrep pipe

sshd    22117 root    2w  FIFO                0,6      0t0 77062521 pipe

[estore@release-dev ~]$ sudo lsof -p 22121 | fgrep pipe

sshd    22121 estore    2w  FIFO                0,6      0t0 77062521 pipe

sshd    22121 estore    6r  FIFO                0,6      0t0 90216829 pipe

sshd    22121 estore    7w  FIFO                0,6      0t0 90216829 pipe

[estore@release-dev ~]$

<ここで子プロセスにシグナル送信>

[estore@release-dev ~]$ kill -HUP 22121

[estore@release-dev ~]$ 

<クライアント側の処理が終了>

<サーバー側のmercurialプロセス終了後も残っていたプロセスの終了を確認>

[estore@release-dev ~]$ ps -ef | fgrep 22121 | grep -v fgrep

[estore@release-dev ~]$ ps -ef | fgrep 22117 | grep -v fgrep

[estore@release-dev ~]$ 

[estore@release-dev ~]$

2016年1月5日火曜日 11時12分58秒 UTC+9 ohira:

[Yuya Nishihara]

On Mon, 4 Jan 2016 02:12:45 -0800 (PST), ohira wrote:
> (対処療法で根本的な原因は不明のままですが)
> nohupを使用していたのが原因のようです。
>
> (古いバージョンのsshに限った話かもしれませんが)
> ssh経由でmercurialを利用する場合にnohupを使わない方が良いようです。

> [以下のファイルを修正してnohupを利用しないように変更]
>
> sp11% tail -5 ~/.ssh/config
>
> host release-dev release-dev.mxfw.net
> # ProxyCommand nohup ssh co122 nc %h %p # NG
> # ProxyCommand nohup ssh co122 nc %h 22299 # NG
> ProxyCommand ssh co122 nc %h 22299 # OK

ログとコードは確認していませんが、 Mercurial サーバー(%h)と通信している外側の
ssh プロセスと、中継ホスト(co122)と通信している内側の ssh プロセスとの間で、
不整合が起きているのではないでしょうか。

hg -> ssh -> nohup -> "ssh co122.."
\
---- SIGHUP --> x ??

hg に限らず、パイプの途中にプロセスの連携を阻害するようなコマンドを挟まない方が
いいと思います。