Spark Frameworkでstop()を呼ぶとInterruptedExceptionが発生して固まる

状況

Spark FrameworkというSinatraっぽい軽量サーバを使ってGroovyでWebAPIのサーバを書いてます。

sparkjava.com

サーバを停止する処理を呼ぶと停止処理中に固まってしまうという現象が起きてました。

実装

サーバを停止する方法は公式ドキュメントにある通り簡単なものです。

Stopping the Server

By calling the stop() method the server is stopped and all routes are cleared.

stop();

以下のようにAPIとして呼べるようにしてあります。

get "/stop", { req, res -> stop() }

が、以下のようなエラーが出てしまいます。

[Thread-1] INFO org.eclipse.jetty.util.log - Logging initialized @975ms
[Thread-1] INFO spark.webserver.JettySparkServer - == Spark has ignited ...
[Thread-1] INFO spark.webserver.JettySparkServer - >> Listening on 0.0.0.0:8010
[Thread-1] INFO org.eclipse.jetty.server.Server - jetty-9.3.2.v20150730
[Thread-1] INFO org.eclipse.jetty.server.ServerConnector - Started ServerConnector@3ab422de{HTTP/1.1,[http/1.1]}{0.0.0.0:8010}
[Thread-1] INFO org.eclipse.jetty.server.Server - Started @1089ms
[qtp1972788076-17] INFO spark.webserver.MatcherFilter - The requested route [/] has not been mapped in Spark
[qtp1972788076-20] INFO spark.webserver.JettySparkServer - >>> Spark shutting down ...
[qtp1972788076-20] INFO org.eclipse.jetty.server.ServerConnector - Stopped ServerConnector@3ab422de{HTTP/1.1,[http/1.1]}{0.0.0.0:8010}
[qtp1972788076-20] ERROR spark.webserver.JettySparkServer - stop failed
java.lang.InterruptedException
        at java.lang.Object.wait(Native Method)
        at java.lang.Thread.join(Thread.java:1253)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.doStop(QueuedThreadPool.java:161)
        at org.eclipse.jetty.util.component.AbstractLifeCycle.stop(AbstractLifeCycle.java:89)
        at org.eclipse.jetty.util.component.ContainerLifeCycle.stop(ContainerLifeCycle.java:143)
        at org.eclipse.jetty.util.component.ContainerLifeCycle.doStop(ContainerLifeCycle.java:161)
        at org.eclipse.jetty.server.handler.AbstractHandler.doStop(AbstractHandler.java:73)
        at org.eclipse.jetty.server.Server.doStop(Server.java:476)
        at org.eclipse.jetty.util.component.AbstractLifeCycle.stop(AbstractLifeCycle.java:89)
        at spark.webserver.JettySparkServer.stop(JettySparkServer.java:148)
        at spark.SparkInstance.stop(SparkInstance.java:317)
        at spark.Spark.stop(Spark.java:987)
        at spark.Spark$stop$0.callStatic(Unknown Source)
        at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCallStatic(CallSiteArray.java:56)
        at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callStatic(AbstractCallSite.java:194)
        at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callStatic(AbstractCallSite.java:198)
        at FooWebapiService$_main_closure5.doCall(fooWebapi.groovy:47)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:497)
        at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:93)
        at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:325)
        at org.codehaus.groovy.runtime.metaclass.ClosureMetaClass.invokeMethod(ClosureMetaClass.java:294)
        at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1019)
        at groovy.lang.Closure.call(Closure.java:426)
        at org.codehaus.groovy.runtime.ConvertedClosure.invokeCustom(ConvertedClosure.java:53)
        at org.codehaus.groovy.runtime.ConversionHandler.invoke(ConversionHandler.java:105)
        at com.sun.proxy.$Proxy5.handle(Unknown Source)
        at spark.RouteImpl$1.handle(RouteImpl.java:58)
        at spark.webserver.MatcherFilter.doFilter(MatcherFilter.java:162)
        at spark.webserver.JettyHandler.doHandle(JettyHandler.java:61)
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:189)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:119)
        at org.eclipse.jetty.server.Server.handle(Server.java:517)
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:302)
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:242)
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:245)
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:95)
        at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:75)
        at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceAndRun(ExecuteProduceConsume.java:213)
        at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:147)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:654)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:572)
        at java.lang.Thread.run(Thread.java:745)

修正

調べるとGitHubにIssueがありました

github.com

どうやら停止するときは別スレッドにしておくと良いらしい。なるほどー。
さっそく修正してみる。

// 別ThreadにしないとInterruptedExceptionが発生してしまう
get "/stop", { req, res -> Thread.start {stop()} }

直ったー。(^_^)v

[Thread-1] INFO org.eclipse.jetty.util.log - Logging initialized @899ms
[Thread-1] INFO spark.webserver.JettySparkServer - == Spark has ignited ...
[Thread-1] INFO spark.webserver.JettySparkServer - >> Listening on 0.0.0.0:8010
[Thread-1] INFO org.eclipse.jetty.server.Server - jetty-9.3.2.v20150730
[Thread-1] INFO org.eclipse.jetty.server.ServerConnector - Started ServerConnector@6591cb3b{HTTP/1.1,[http/1.1]}{0.0.0.0:8010}
[Thread-1] INFO org.eclipse.jetty.server.Server - Started @1015ms
[Thread-11] INFO spark.webserver.JettySparkServer - >>> Spark shutting down ...
[Thread-11] INFO org.eclipse.jetty.server.ServerConnector - Stopped ServerConnector@6591cb3b{HTTP/1.1,[http/1.1]}{0.0.0.0:8010}
[Thread-11] INFO spark.webserver.JettySparkServer - done

Windowsでsedを使って環境変数を利用した置換をする

nginxの設定ファイルを起動時に環境変数の値を使って書き換えたい

nginxのerror_logとaccess_logを1箇所で管理しているログディレクトリのパスで書き換えたいけど手動ではやりたくないです。
nginxの引数で-g "error_log xxx;"とかできるけどaccess_logは出来ないのでテンプレートの設定ファイルを用意してsedで書き換えることにしました。

sed for Windows

gnuwin32.sourceforge.net

書き換え

  • ファイルパスの置換 nginxのerror_log等はパスの区切りをバックスラッシュではなくスラッシュ(/)で記述しますが、環境変数はバックスラッシュ(\)なので置換します。
    ※この時、\/に置換しておかないと後処理のsed/がエスケープされなくてエラーになってしまう!

sed的には以下のように書けばよいのですが、

> echo %LOG_HOME%
C:\logs
> echo %LOG_HOME% | sed "s/\\/\\\//g"
C:/logs

バッチファイルの中で使うには変数に代入とか簡単にできないので以下のようにします。

> FOR /F "usebackq" %x IN (`echo %LOG_HOME% ^| sed -e "s/\\/\\\//g"`) DO SET LOG_HOME_NGINX=%x
> echo %LOG_HOME_NGINX
C:/logs

最終的にバッチファイルに記述するときは%x%%xに書き換えてください。

sedの中でパイプを使いたい時にハット(^|)が付いていますがこれがないと以下のようなエラーになります。

| の使い方が誤っています。

わからんて・・・。
ちなみにsedへのパスが通ってない時にも同じエラーになりました。(ますますわからん・・・

  • sedの中で環境変数を展開する sedで、テンプレートに書いてある環境変数のようなキーワードを環境変数で置換するには以下のようにします。
    テンプレートには、error_log %LOG_HOME%/nginx/error.logと定義してあります。
> sed "s/\%%LOG_HOME\%%/%LOG_HOME_NGINX%/" conf\nginx.conf

置換するキーワードはエスケープして、実際の環境変数はエスケープしません。
Windowsならではですが、%を使うために\%%としている所に注意。sed的には\でエスケープだがWindows的には%%と市内と行けないのでダブルで指定している。

  • テンプレートをコピーしてsedで書き換える一連の流れは以下のようになります。
set APP_HOME=%~dp0
copy /Y %APP_HOME%conf\nginx.template %APP_HOME%conf\nginx.conf
FOR /F "usebackq" %%x IN (`echo %LOG_HOME% ^| sed "s/\\/\//"`) DO SET LOG_HOME_NGINX=%%x
sed -i -e "s/\%LOG_HOME\%/%LOG_HOME_NGINX%/" %APP_HOME%conf\nginx.conf
%APP_HOME%nginx.exe -p %APP_HOME% -c %APP_HOME%conf\nginx.conf

Linuxbash使ってとかだと簡単なことが結構つまづいたので記録に残しておきます。

AsciiDocで文字色を変えたがasciidoctor-pdfで作成したPDFに反映しない

AsciiDocで文字色を変える

HTMLへ変換する場合、文字に色つけるときは[red]#あああ#みたいにすると出来ます。 ところが、asciidoctor-pdfでPDFを作ると期待通り色がつきません。

原因

asciidoctor-pdf でspanが来た時に色を付ける処理が[red]#text#が生成するspanと一致していないのが原因っぽいです。

この辺のソースでspanのstyleを読んでいるのでそういうことなんでしょう。

github.com

対応

現状のasciidoctor-pdfが期待する通りのspanを作ってやれば取り敢えず色変わりました。

pass:[<span style="color:#ff0000">あああ</span>]

まー、修正してプルリクだす元気もないので取り敢えず今回はこれで回避。

JenkinsでSubModuleの更新に失敗する

経緯

複数のリポジトリから参照されるスタイル設定情報をSubModule化しました。
ローカルでは問題なかったのですが、Jenkinsでエラーが発生するようになります。

対応

Jenkinsのジョブのソースコード管理>GitからAdvanced sub-modules behavioursを追加します。
Recursively update submodulesをチェックするとサブモジュールも更新されるらしい。
が、それでもエラーが出ます・・・

00:00:12.424  > git remote # timeout=10
00:00:12.426  > git submodule init # timeout=10
00:00:12.445  > git submodule sync # timeout=10
00:00:12.464  > git config --get remote.origin.url # timeout=10
00:00:12.469  > git submodule update --init --recursive
00:00:12.543 FATAL: Command "git submodule update --init --recursive" returned status code 1:
00:00:12.543 stdout: 
00:00:12.543 stderr: Cloning into 'submodule_lib'...
00:00:12.543 fatal: Authentication failed for 'http://git.example.com/scm/projects/submodule_lib.git/'
00:00:12.543 Clone of 'http://git.example.com/scm/projects/submodule_lib.git' into submodule path 'submodule_lib' failed
00:00:12.543 
00:00:12.543 hudson.plugins.git.GitException: Command "git submodule update --init --recursive" returned status code 1:
00:00:12.543 stdout: 
00:00:12.543 stderr: Cloning into 'submodule_lib'...
00:00:12.543 fatal: Authentication failed for 'http://git.example.com/scm/projects/submodule_lib.git/'
00:00:12.543 Clone of 'http://git.example.com/scm/projects/submodule_lib.git' into submodule path 'submodule_lib' failed
00:00:12.543 
00:00:12.543     at org.jenkinsci.plugins.gitclient.CliGitAPIImpl.launchCommandIn(CliGitAPIImpl.java:1719)
00:00:12.543     at org.jenkinsci.plugins.gitclient.CliGitAPIImpl.access$500(CliGitAPIImpl.java:63)
00:00:12.543     at org.jenkinsci.plugins.gitclient.CliGitAPIImpl$7.execute(CliGitAPIImpl.java:967)
00:00:12.543     at org.jenkinsci.plugins.gitclient.RemoteGitImpl$CommandInvocationHandler$1.call(RemoteGitImpl.java:152)
00:00:12.543     at org.jenkinsci.plugins.gitclient.RemoteGitImpl$CommandInvocationHandler$1.call(RemoteGitImpl.java:145)
00:00:12.543     at hudson.remoting.UserRequest.perform(UserRequest.java:152)
00:00:12.543     at hudson.remoting.UserRequest.perform(UserRequest.java:50)
00:00:12.543     at hudson.remoting.Request$2.run(Request.java:332)
00:00:12.543     at hudson.remoting.InterceptingExecutorService$1.call(InterceptingExecutorService.java:68)
00:00:12.543     at java.util.concurrent.FutureTask.run(FutureTask.java:262)
00:00:12.543     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
00:00:12.543     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
00:00:12.543     at java.lang.Thread.run(Thread.java:745)
00:00:12.543     at ......remote call to ci-slave-linux1(Native Method)
00:00:12.543     at hudson.remoting.Channel.attachCallSiteStackTrace(Channel.java:1416)
00:00:12.543     at hudson.remoting.UserResponse.retrieve(UserRequest.java:252)
00:00:12.543     at hudson.remoting.Channel.call(Channel.java:781)
00:00:12.543     at org.jenkinsci.plugins.gitclient.RemoteGitImpl$CommandInvocationHandler.execute(RemoteGitImpl.java:145)
00:00:12.543     at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
00:00:12.543     at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
00:00:12.543     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
00:00:12.543     at java.lang.reflect.Method.invoke(Method.java:606)
00:00:12.543     at org.jenkinsci.plugins.gitclient.RemoteGitImpl$CommandInvocationHandler.invoke(RemoteGitImpl.java:131)
00:00:12.543     at com.sun.proxy.$Proxy83.execute(Unknown Source)
00:00:12.543     at hudson.plugins.git.extensions.impl.SubmoduleOption.onCheckoutCompleted(SubmoduleOption.java:90)
00:00:12.543     at hudson.plugins.git.GitSCM.checkout(GitSCM.java:1134)
00:00:12.543     at hudson.scm.SCM.checkout(SCM.java:485)
00:00:12.543     at hudson.model.AbstractProject.checkout(AbstractProject.java:1269)
00:00:12.543     at hudson.model.AbstractBuild$AbstractBuildExecution.defaultCheckout(AbstractBuild.java:607)
00:00:12.543     at jenkins.scm.SCMCheckoutStrategy.checkout(SCMCheckoutStrategy.java:86)
00:00:12.543     at hudson.model.AbstractBuild$AbstractBuildExecution.run(AbstractBuild.java:529)
00:00:12.543     at hudson.model.Run.execute(Run.java:1738)
00:00:12.544     at hudson.model.FreeStyleBuild.run(FreeStyleBuild.java:43)
00:00:12.544     at hudson.model.ResourceController.execute(ResourceController.java:98)
00:00:12.544     at hudson.model.Executor.run(Executor.java:410)

ぐぐるとこんなのが・・・

[JENKINS-20941] Stored git credentials not used when submodule is updated - Jenkins JIRA

つい数日前に直したのでexperimental pluginsからGit Pluginの3.0.0-beta2を入れるとUse credentials from default remote of parent repositoryというのが出るのでそれをチェックすると。なんか良さそうだけど入れたくないなぁ。

というわけで、Disable submodules processingにチェックしてサブモジュールを更新しないようにし、手動で設定ファイルを置いとくことにしました。
Git Pluginが正式リリースされたらもとに戻すということで。

SourceTreeでサブツリーを作るとき

  • いきなり失敗したので、φ(..)メモメモ

SourceTreeでSubTreeを作成

サブツリーの追加/リンクを押すと、ソースパス/URLブランチ/コミットローカルパスを入れる画面が出ますが、わざわざ空のディレクトリ作ってローカルパスを指定したのが失敗でした。

サブツリー情報とリンク

既にフォルダが存在するパスが指定されています。
指定されたリモート情報と既存のフォルダにリンクを作成しますか?
(注意, リンクを作成してもリポジトリは変更されません)

キャンセル  / リンクを作成する

このようなメッセージが出てキャンセルをしたら駄目だし、リンクを作成するとしても意図した階層でプル出来ません。

何の事はない、あらかじめディレクトリを作成するとか余計なことをせずに、存在しないディレクトリをローカルパスに指定すれば良いだけでした。_| ̄|○

結局使わなかった・・・

SubTreeはいろいろと出来ることが多くて良いとは思うのですが、リモートからCloneしたら自動的にリンクが出来るわけじゃないのでメンバーの習熟度やリンク部分は基本あまり変更しない想定なので結局SubModuleを使うことにしました。

C#でファイルバージョンは自動的なリビジョンを入れ、製品バージョンを手動で振る

  • デフォルトではAssemblyVersionとAssemblyFileVersionがあるのですが、なぜか両方あると*が効きませんよね。
    • AssemblyFileVersionを指定しなければ自動的なリビジョンが振られます。
// すべての値を指定するか、下のように '*' を使ってビルドおよびリビジョン番号を 
// 既定値にすることができます:
[assembly: AssemblyVersion("1.0.*")]
//[assembly: AssemblyFileVersion("1.0.0.0")]
  • ただし、これだとファイルのプロパティから確認するときに製品バージョンにも同じ値が入ってしまいます。
    • やはり製品バージョンは手動で値を振りたい。
    • 製品バージョンはAssemblyInformationalVersionを使うと振れます。
  • 最終形
// すべての値を指定するか、下のように '*' を使ってビルドおよびリビジョン番号を 
// 既定値にすることができます:
[assembly: AssemblyVersion("1.0.*")]
//[assembly: AssemblyFileVersion("1.0.0.0")]
[assembly: AssemblyInformationalVersion("0.9.1.0")]

これでファイルバージョンはどんどん変わっていくけど製品バージョンは手動で変えたい時だけ変えることが出来ます。やったね!

GradleでやってるようにGitのコミットIDを入れられたらもっといいんだけどね。(まあ今日はここまでにしておこう)

Jettyのstderrout.logとrequest.logのパスを環境変数で指定する

Jettyのログを相対パスで指定していたのですが、異なるドライブレターに出したいというご要望です

共通

  • Windowsサーバです。
  • ドライブレターは環境変数環境変数で指定したものをプロパティとして起動時の引数で渡している想定です。
  • jetty.homeとjetty.baseは分離しています。
  • jettyは以下のように起動します。
set JETTY_HOME=C:\foo\runtime\jetty
set LOGDIR=C:\bar\logs\hogehoge

java -Djetty.home=%JETTY_HOME% -jar start.jar --exec -DLOGDIR=%LOGDIR%
  • ログディレクトリの指定を絶対パスにして各サービスのあちこちに埋め込むと導入時や開発時に書き換えが必要な場合にミスしやすいので、できれば使いたくありません。

stderrout.log

  • プロパティとして渡しているLOGDIRが効かないのでstart.iniの中で相対パスで指定していました。
--module=logging
jetty.logs=logs/hogehoge
  • 例えば出力先をD:\logsに変えたいとした時に相対パスではダメです。
    • jetty.homeetc\jetty-logging.xml${jetty.base}\etcにコピーして<Property name="jetty.logs" default="./logs"/>の所をLOGDIRに書き換えれば出来そうです。(start.iniのjetty.logsは消しておきます)
<Configure id="logging" class="org.eclipse.jetty.util.log.Log">

    <New id="ServerLog" class="java.io.PrintStream">
      <Arg>
        <New class="org.eclipse.jetty.util.RolloverFileOutputStream">
          <Arg><Property name="jetty.logs" default="./logs"/>/yyyy_mm_dd.stderrout.log</Arg><Arg><Property name="LOGDIR" />/yyyy_mm_dd.stderrout.log</Arg>

request.log

  • こちらもプロパティとして渡しているLOGDIRが効かないのでstart.iniの中で相対パスで指定していました。(指定の仕方は微妙に違います)
--module=requestlog
requestlog.filename=logs/hogehoge/yyyy_mm_dd.request.log
  • stderrout.logとは微妙に指定の仕方が違います。
    • jetty.homeetc\jetty-requestlog.xml${jetty.base}\etcにコピーして<Property name="jetty.base" default="." /><Property name="requestlog.filename" default="/logs/yyyy_mm_dd.request.log"/></Set>の所をLOGDIRに書き換えれば出来そうです。(start.iniのrequestlog.filenameは消しておきます)
<Configure id="Server" class="org.eclipse.jetty.server.Server">

  <!-- =========================================================== -->
  <!-- Configure Request Log -->
  <!-- =========================================================== -->
  <Ref refid="Handlers">
    <Call name="addHandler">
      <Arg>
        <New id="RequestLog" class="org.eclipse.jetty.server.handler.RequestLogHandler">
          <Set name="requestLog">
            <New id="RequestLogImpl" class="org.eclipse.jetty.server.AsyncNCSARequestLog">
            <Set name="filename"><Property name="jetty.base" default="." /><Property name="requestlog.filename" default="/logs/yyyy_mm_dd.request.log"/></Set><Set name="filename"><Property name="LOGDIR" /><Property name="requestlog.filename" default="/yyyy_mm_dd.request.log"/></Set>

これで出たと思う。