リポジトリの更新タスクが複数回実行されてしまう。

[Carol]

Carolです。

利用環境は

linuxでredmine 1.4.3をです。

バージョン管理システムとの連携をhttp://Redmineサーバ名/sys/fetch_changesets?key=APIキー　を使用して行っています。

Subversionだけを連携している時は長くても１～２分程度で終わっていたのですが、CVSとの連携を設定したところ、連携に数時間かかるように

なってしまいました。

やむなく夜中から１回走るように設定したのですが、連携自体は行われているのにタスクの状態を見ると同じ処理が複数回実行されるようになってしまいました。

（朝の１０時とかになっても同じ連携処理が数タスク同時に実行されています）

詳しく調べてみると、どうも15分おきに処理が呼び出されているようです。

CVSの連携自体が遅いのはしょうがないとしても、この何回も呼び出されるのは何とかしたいと思いいろいろ調査しているのですが、情報が見つからずに困っています。

現状だと昼間に実行するとCVSの接続とredmineサーバのタスクを食いつぶして使い物にならなくなってしまいます。

どなたか情報をお持ちの方はいらっしゃらないでしょうか。

#CVSをやめるのが一番なんでしょうが...

[Carol]

morika-t様
ご返答ありがとうございます。

On Thursday, December 6, 2012 8:45:51 PM UTC+9, morika-t wrote:

今回の事象で参考になる情報かわかりませんが

以前複数のプロジェクトでそれぞれにgitを利用していて

似たような状況になった事があった際には

key=APIキーの後にプロジェクトidを入れると該当のPJに紐づいたリポジトリのみ更新され

多少動作が軽くなった事がありました。

参考ページ

http://d.hatena.ne.jp/yogit/20110802/1312252899

似たような状況になったことがあるということはやはり処理に長時間かかるとリトライしてしまうような仕組みが入っているということなのでしょうね。

個々のプロジェクト毎にわけるのは検討したのですが、プロジェクト数が結構多いのであきらめてました。

一度バラバラに更新するように設定して様子を見てみます。

引き続きリトライ？されてしまう件についてご存知の方がいらっしゃいましたら情報お待ちしております。

[nobu_toyofuku]

  豊福です。

全然見当もついていないのですが。

2012年12月5日 18:29 Carol <carol...@gmail.com>:

バージョン管理システムとの連携をhttp://Redmineサーバ名/sys/fetch_changesets?key=APIキー　を使用して行っています。

  ...

やむなく夜中から１回走るように設定したのですが、

 

これは cron で実行しているのですか。

詳しく調べてみると、どうも15分おきに処理が呼び出されているようです。

コードをいじれる環境でしたら取りあえず
app/controllers/sys_controller.rb の

  def fetch_changesets
と
lib/redmine/scm/adapters/abstract_adapter.rb の

  def self.shellout
でメソッドの出入りのときにログを時刻付きで出してみてはどうでしょう。

shellout の方は元々
  if logger && logger.debug?
    logger.debug "Shelling out: #{strip_credential(cmd)}"
  end
というのが入ってますね。

---

[Carol]

 豊福さんご返答ありがとうございます。

2012年12月18日火曜日 21時06分13秒 UTC+9 nobu_toyofuku:

  豊福です。

全然見当もついていないのですが。

  ... 

やむなく夜中から１回走るように設定したのですが、

 

これは cron で実行しているのですか。

cronで呼び出すようにしています。

 

詳しく調べてみると、どうも15分おきに処理が呼び出されているようです。

production.logを見ると約15分毎に呼び出しが行われていました。

こんな感じです。(IPアドレスとkeyは細工しています）

 Processing SysController#fetch_changesets (for 172.*.*.* at 2012-12-19 00:00:01) [GET]

  Parameters: {"key"=>"*********"}

Processing SysController#fetch_changesets (for 172.*.*.* at 2012-12-19 00:15:02) [GET]

  Parameters: {"key"=>"*********"}

Processing SysController#fetch_changesets (for 172.*.*.* at 2012-12-19 00:30:04) [GET]

  Parameters: {"key"=>"*********"}

処理が終了したときは以下の様なログが書か、呼ばれた回数分書かれていました。

Completed in 4424382ms (View: 2, DB: 20340) | 200 OK [http://172.*.*.*/sys/fetch_changesets?key=**************]

この呼び出しを行っているのが以下の部分ということなんですね。

rubyはあまり読めないのですが、ここにリトライの処理が無いか調べてみます。

[nobu_toyofuku]

  豊福です。一部訂正です。

2012年12月19日 15:52 nobu_toyofuku <nobu.t...@gmail.com>:

そう言えば、

wget http://.../sys/fetch_changesets?...
と書いた shell スクリプトをコンソールからを起動してみたら
実際の処理は終っているのにリターンキーを打つまでスクリプト
が終了しませんでした。（コンソールから直接 wget ... とやった
場合はすぐ終了しました。）

このリターンキー待ちの話はタイムアウトとは関係ありませんでした。

--timeout=60 --tries=20 をつけて cron で実行してみましたがリトライは
しませんでした。
---

[Carol]

Carolです。

すみません15:52？の投稿が見当たらない様です。

朝、途中のタスクを強制終了しても更新されていますので、動作としては処理に失敗してリトライしているというより

複数回並行して処理が実行されている感じです。

単に処理時間が15分以上かかるので勝手にタイムアウトとみなされてしまっているのかもしれませんが。

ログから見るとリポジトリの更新処理は75分～4時間程度かかっているようです。

（CVS*3の更新がssh経由なのもあって非常に重い）

2012年12月19日水曜日 17時58分07秒 UTC+9 nobu_toyofuku:

[Carol]

Carolです。

ご返答いただいた内容が気になったのwgetのオプションを調べてみました。

デフォルトでタイムアウトが900秒、リトライが20回とのことで、発生している現象とぴったり一致しました。
そこでapacheのaccess_logを見たところ15分おきにアクセスが行われていることが確認できました。

なので-t 1を付けて今晩実行してみます。

2012年12月19日水曜日 18時32分17秒 UTC+9 Carol:

Carolです。

すみません15:52？の投稿が見当たらない様です。

朝、途中のタスクを強制終了しても更新されていますので、動作としては処理に失敗してリトライしているというより

複数回並行して処理が実行されている感じです。

単に処理時間が15分以上かかるので勝手にタイムアウトとみなされてしまっているのかもしれませんが。

ログから見るとリポジトリの更新処理は75分～4時間程度かかっているようです。

（CVS*3の更新がssh経由なのもあって非常に重い）

[nobu_toyofuku]

  豊福です。

このメールを出すのは昨日からあわせて７回目。
６回目まで Gmail画面から返信してダメだったので今回は Google group画面から返信してみます。

2012年12月20日 14:31 Carol <carol...@gmail.com>:

デフォルトでタイムアウトが900秒、リトライが20回とのことで、発生している現象とぴったり一致しました。

下記が昨日書いた内容です。

======================

  豊福です。

2012年12月19日 10:23 Carol <carol...@gmail.com>:

これは cron で実行しているのですか。

cronで呼び出すようにしています。

 

詳しく調べてみると、どうも15分おきに処理が呼び出されているようです。

cron で使っているのは wget でしょうか。

wget でこういうのを見つけました。
「wgetを使って、

あるURLにアクセスしてバッチ処理を起動することがある。そのとき、バッチ処理自体が長時間かかるなどが原因で、wgetが15分おきに再アクセスを20回繰り返してしまう可能性がある。」
http://www.softel.co.jp/blogs/tech/archives/1402
解決方法も書いてあります。

そう言えば、
wget http://.../sys/fetch_changesets?...
と書いた shell スクリプトを

コンソールからを起動してみたら

実際の処理は終っているのにリターンキーを打つまでスクリプト
が終了しませんでした。（コンソールから直接 wget ... とやった
場合はすぐ終了しました。）

これが原因ではないですかね。
---

[Carol]

Carolです。

昨日cronの設定を変更したところ今朝ログを確認したら１回しか実行されていませんでした。

処理自体も40分ぐらいで終了していました。

これで昼間でも実行できそうです。

まさかwgetの方だとは気付きませんでした。

ありがとうございます。

2012年12月20日木曜日 17時18分57秒 UTC+9 nobu_toyofuku:

[nobu_toyofuku]

  豊福です。

昨日は２通メーリングリストへ、２通直接 Carolさんへ送信したつもりなのですが
届かなかったようです。なぜ？？？

2012年12月20日 14:31 Carol <carol...@gmail.com>:

デフォルトでタイムアウトが900秒、リトライが20回とのことで、発生している現象とぴったり一致しました。

下記が昨日書いた内容です。

======================

  豊福です。

2012年12月19日 10:23 Carol <carol...@gmail.com>:

これは cron で実行しているのですか。

cronで呼び出すようにしています。

 

詳しく調べてみると、どうも15分おきに処理が呼び出されているようです。

cron で使っているのは wget でしょうか。

wget でこういうのを見つけました。
「wgetを使って、

あるURLにアクセスしてバッチ処理を起動することがある。そのとき、バッチ処理自体が長時間かかるなどが原因で、wgetが15分おきに再アクセスを20回繰り返してしまう可能性がある。」
http://www.softel.co.jp/blogs/tech/archives/1402
解決方法も書いてあります。

そう言えば、
wget http://.../sys/fetch_changesets?...
と書いた shell スクリプトを

コンソールからを起動してみたら

実際の処理は終っているのにリターンキーを打つまでスクリプト
が終了しませんでした。（コンソールから直接 wget ... とやった
場合はすぐ終了しました。）

これが原因ではないですかね。
---

[Toshi MARUYAMA]

まるやまです。

Carol さんは書きました (2012年12月19日 18:32):
> 朝、途中のタスクを強制終了しても更新されていますので、動作としては処理に
> 失敗してリトライしているというより
> 複数回並行して処理が実行されている感じです。

結論から言うと、「CVSはやめておいた方が良い」です。
お勧めとしては、「Mercurialにコンバートした方が良い」です。
http://mercurial.selenic.com/wiki/ConvertExtension#Converting_from_CVS
Gitは、「複数回並行して処理」が、やや難があります。

理由は以下の通りです。
SubversionとMercurialは連番のリビジョン番号があります。
changesetsテーブルのrevisionカラムにsvn/hgのリビジョン番号が入ります。
次回の取り込みでは、DBに保存されているリビジョン番号＋１のものから
順番に取り込まれます。

revisionカラムはユニーク制約があるので、svn/hgの場合、
同時に実行されても後からのものは制約違反になるので、
後のものの保存が失敗するだけです。

CVSについては、リビジョン番号に相当するものがないので、
Redmine側で擬似的に作成しています。
おそらく、この処理が失敗しているものと思います。
http://www.redmine.org/projects/redmine/repository/entry/tags/2.2.0/app/models/repository/cvs.rb#L134

今見たらトランザクションの範囲が大きいので、全く保存されていないと思われます。
svn/hgの場合は、１リビジョン毎にトランザクションがかかっているので、
全く保存されないということはありません。
http://www.redmine.org/projects/redmine/repository/entry/tags/2.2.0/app/models/repository/mercurial.rb#L142

Gitの場合、リビジョン番号に相当するものがないので、
かなり複雑なことをしています。
Redmine1.4で実装が変わったので、
「複数回並行して処理」に対してはsvn/hgに対しては弱いです。

長くなったのでここまでです。

[Carol]

Carolです。

2012年12月20日木曜日 15時33分52秒 UTC+9 nobu_toyofuku:

  豊福です。

昨日は２通メーリングリストへ、２通直接 Carolさんへ送信したつもりなのですが
届かなかったようです。なぜ？？？

 ごめんなさいgmailの方はたまにしか見ないアドレスなので、気付いていませんでした。

[Carol]

Carolです。

CVSが良くないことは重々承知していて現在SVNへの移行計画はあるのですが、未だに更新が結構ある＆履歴が多いのでなかなか移行できないでいます。

個人的には使いにくいので早くなんとかしたいんですけど。

とりあえず処理が１回だけで時間も40分程度で終わるようになったのでタイミングをみて移行したいと思います。

ありがとうございました。

2012年12月19日水曜日 19時22分50秒 UTC+9 Toshi MARUYAMA:

[Toshi MARUYAMA]

まるやまです。

Carol さんは書きました (2012年12月21日 17:00):
> Carolです。
>
> CVSが良くないことは重々承知していて現在SVNへの移行計画はあるのですが、未
> だに更新が結構ある＆履歴が多いのでなかなか移行できないでいます。
> 個人的には使いにくいので早くなんとかしたいんですけど。

他のSCM(VCS)に移行を勧めているのではありません。
Redmineと連携をするのが目的であるのであれば、
CVSはやめておいた方が良い、ということです。

中央リポジトリとしてCVSを今まで通り運用しつつ、
MercurialのコンバートをミラーにしてRedmineと連携させてみてはどうか？
ということです。

Mercurialのコンバートには以下の機能があります。
・まずCVSからMercurialに全リビジョンコンバートする
・その時、コンバートしたリビジョンを記録する
・その記録から、CVSで増えたリビジョンだけを追加でコンバートする

Redmine本体には、Git(github)とMercurial(Bitbucket)にミラーがありますが、
それと同じ運用になります。

自分はCVSからSubversionへの移行を行ったことがないので、
CVSからSubversionへのミラーで同様のことが出来るかどうかは分かりません。
Gitへの移行も行ったことがないので分かりません。

以上です。

> とりあえず処理が１回だけで時間も40分程度で終わるようになったのでタイミン
> グをみて移行したいと思います。

> <http://www.redmine.org/projects/redmine/repository/entry/tags/2.2.0/app/models/repository/cvs.rb#L134>
>
>
> 今見たらトランザクションの範囲が大きいので、全く保存されていないと思