akairosame’s blog

備忘録やメモ

Play Framework 2.5のルーティングで詰まったので動作を調べた

サブプロジェクトを使ったときに上手くパスが設定されないようになってしまって解決まで時間が掛かったので、調べたことの記録。ちなみに調べた結果コンテキストパスでも上手く設定されないケースがありそうでした。

調査した環境

Play Framework 2.5.10

原因と対応

Play Frameworkを2.3から2.5にバージョンアップした際、アプリケーションの初期化中にメインモジュールからのパスではなくサブプロジェクトでのパスが直接指定されてしまう部分が出てきてしまいました。例えば、mainモジュールがsubモジュールに依存していたとして、subモジュールのindexメソッドへのリバースルーティングをmainモジュールで行った際、2.3なら「/sub/index」が取れていたのに「/index」が取れてしまうようになった、といった感じです。


コード例があった方がわかりやすいと思うので、サンプル作りました。GitHub - re-d-shark/routes-test

次のようなコントローラーを用意して、サブプロジェクトのパスを取ってみます。

callには、次のようなモジュールからDIされるCallクラスのインスタンスが入ります。

ここでは、GuiceのModuleでサブプロジェクトのコントローラーのメソッドのCallクラスを直にDIさせているだけですね。アプリケーションの初期化処理部分で色々やってた部分を簡略化しているので、あまり意味のない感じに見えるかもしれませんが…。

ルーティングはmain、subそれぞれ次のような感じ。

さて、subIndexを叩くと何が返ってくるでしょうか。同じメソッドを参照しているのだからDirectとInjectedで指す値は同じ値になって欲しいですね。答えは…

f:id:akairosame:20170218203007p:plain

えぇ…。

調べたところ、2.4以降からPlay Frameworkが内部でGuiceを使うようになって動的にアプリケーションの設定をするようになったところが原因だったようです。Play Frameworkの初期化処理は2.3ではGlobalSettings.beforeStartで書いていたのですが、2.4以降ではGlobalSettingsは使われなくなりGuiceのModuleとしてDIする時に色々するようになりました。と認識しています。(GlobalSettings - 2.4.x)そのときにどのようにルーティングを決定しているのか見てみましょう。

Play Framework の起動とルーティング

Play Frameworkのアプリケーションがどのように立ち上がるのかを簡単に追いかけながらソースを見ていきました。ここからはそのときソースリーディングした流れを追跡していきます。だらだらソースを読むだけなので、後ろで要点をまとめてます。

エントリポイントは本番環境(ProdServerStartのmain)と開発環境(sbt runする)で違うようですが、最終的にplay.api.Applicationトレイトの実装クラスを作成し、それを元に動作するようです。デバッガで追っかけたりはして無いですが大体次のような箇所で指定しているようです。

本番環境:play.core.server.ProdServerStart。(余談ですがplay.core.server.NettyServer使うと今はdeprecatedって出るんですね…。変えなきゃ…。)

開発環境:play.sbt.PlaySettings。この辺りはよく理解していませんが、sbtでrunタスクを実行したらplay.sbt.run.PlayRunの中でなんやかんやしてplay.runsupport.Reloader経由でplay.core.server.DevServerStart#mainDevが実行されるようです。

ともかくどっちでも最終的にplay.api.Play.start(application)と指定しているわけです。ここで、applicationはApplicationクラスのインスタンスですが、GuiceApplicationLoaderによりBuiltinModuleで指定されたDefaultApplicationが生成されています。ややこしいことをしていればGuice以外のApplicationLoaderを使うこともできるようですが、ややこしいのでパスしました。

Play#startで何をやっているか見てみると…

  def start(app: Application) {

    // First stop previous app if exists
    stop(_currentApp)

    _currentApp = app

    Threads.withContextClassLoader(app.classloader) {
      // Call before start now
      app.global.beforeStart(app)

      // Ensure routes are eagerly loaded, so that the reverse routers are
      // correctly initialised before plugins are started.
      app.routes

      // If the global plugin is loaded, then send it a start now.
      app.global.onStart(app)
    }

となっていますが、app.routesでroutesを呼び出してますね。Applicationクラスのroutesは…

  @deprecated("Either use HttpRequestHandler, or have the router injected", "2.4.0")
  def routes: Router = {
    // Use a cached value because the injector might be slow
    if (cachedRoutes != null) cachedRoutes else {
      cachedRoutes = injector.instanceOf[Router]
      cachedRoutes
    }
  }

と定義されています。deprecatedが怖いですが、Play Frameworkが内部でGuiceを使うようになり、ルーティングはGuiceのinjectorからインスタンスを生成して取得しているようですね。ではこのRouterですが、先程のBuiltinModuleを見るとRoutesProviderから提供されているようです。

このRoutesProviderですが、次のように定義されています。

@Singleton
class RoutesProvider @Inject() (injector: Injector, environment: Environment, configuration: Configuration, httpConfig: HttpConfiguration) extends Provider[Router] {
  lazy val get = {
    val prefix = httpConfig.context

    val router = Router.load(environment, configuration)
      .fold[Router](Router.empty)(injector.instanceOf(_))
    router.withPrefix(prefix)
  }
}

設定からコンテキストパスを取得して、Router.loadでRouterクラスのインスタンスを取得、コンテキストパスをwithPrefixに与えて返ってきたRouterクラスを返すという動作ですね。そして、そのRouter#loadは…

  def load(env: Environment, configuration: Configuration): Option[Class[_ <: Router]] = {
    val className = PlayConfig(configuration).getDeprecated[Option[String]]("play.http.router", "application.router")

    try {
      Some(Reflect.getClass[Router](className.getOrElse("router.Routes"), env.classLoader))
    } catch {
      case e: ClassNotFoundException =>
        // Only throw an exception if a router was explicitly configured, but not found.
        // Otherwise, it just means this application has no router, and that's ok.
        className.map { routerName =>
          throw configuration.reportError("application.router", "Router not found: " + routerName)
        }
    }
}

と定義されています。ここでようやくEnvironmentとConfigurationからRouterクラスを生成しているのが分かりました。環境と設定クラスは追いかけませんが、routesファイル名の設定があればその名前から、なければ"router.Routes"をRouterクラスのインスタンスとしてリフレクションで生成しています。大分近づいてきた感じがありますね。

では、routesファイルからコンパイルされ作られたmainプロジェクトのrouter.Routesクラス定義を見てみます。

class Routes(
  override val errorHandler: play.api.http.HttpErrorHandler, 
  // @LINE:1
  MainController_0: javax.inject.Provider[main.controllers.MainController],
  // @LINE:3
  sub_Routes_0: sub.Routes,
  val prefix: String
) extends GeneratedRouter {

   @javax.inject.Inject()
   def this(errorHandler: play.api.http.HttpErrorHandler,
    // @LINE:1
    MainController_0: javax.inject.Provider[main.controllers.MainController],
    // @LINE:3
    sub_Routes_0: sub.Routes
  ) = this(errorHandler, MainController_0, sub_Routes_0, "/")

コンストラクタにInjectアノテーションが付いており、エラーハンドラとmainプロジェクトのコントローラー、subプロジェクトのRoutesクラスがGuiceによってDIされ、prefixは"/"となるようですね。

そして、サブモジュールのRoutesクラスは…

class Routes(
  override val errorHandler: play.api.http.HttpErrorHandler, 
  // @LINE:1
  SubController_0: javax.inject.Provider[sub.controllers.SubController],
  val prefix: String
) extends GeneratedRouter {

   @javax.inject.Inject()
   def this(errorHandler: play.api.http.HttpErrorHandler,
    // @LINE:1
    SubController_0: javax.inject.Provider[sub.controllers.SubController]
  ) = this(errorHandler, SubController_0, "/")

でした。mainプロジェクトと同じような定義ですね。今のところ、どちらもprefixが"/"となっていますが…。とりあえず続きを見てみます。RoutesProviderでrouter.withPrefix(prefix)としてmainのRouterクラスのwithPrefixが呼ばれています。これは

  def withPrefix(prefix: String): Routes = {
    router.RoutesPrefix.setPrefix(prefix)
    new Routes(errorHandler, MainController_0, sub_Routes_0, prefix)
  }

と定義されており、router.RoutesPrefix.setPrefixでは…

package router {
  object RoutesPrefix {
    private var _prefix: String = "/"
    def setPrefix(p: String): Unit = {
      _prefix = p
    }
    def prefix: String = _prefix
    val byNamePrefix: Function0[String] = { () => prefix }
  }
}

オブジェクトにmutableな変数"_prefix"を定義しており、設定値のprefixを代入していました!そして設定後にnew Routesでクラスを作り直しているのでprefixの値が置き換わったmainプロジェクトのRoutesクラスを返しましたね。

subプロジェクトのprefixはどうやって設定しているのかというと、mainのRoutesクラスのメンバ変数に、次の定義がありました。

  // @LINE:3
  private[this] val prefixed_sub_Routes_0_1 = Include(sub_Routes_0.withPrefix(this.prefix + (if (this.prefix.endsWith("/")) "" else "/") + "sub"))

ここでmainプロジェクトのRoutesクラスを作り直した際に、subプロジェクトのRoutes#withPrefixでmainプロジェクトのprefix+"sub"のprefixが設定されました。はぇ~…よくできてる…。さて、これでどのタイミングでサブプロジェクトのルーティングが決まるのか分かりましたね。アプリケーションの生成後に動的に決定していたと。つまるところ、これが設定されていないタイミングでRoutesクラスを呼んじゃダメということですね。…この動作だと、コンテキストパスを設定する場合にも影響が出ますね…。


では、問題になっていたModuleによる初期化処理はどのタイミングで実行されるか、言い換えると、GuiceApplicationLoaderがModuleをどのタイミングで読み込むかです。が、これはまあ、アプリケーションの作成前ですね。長くなったので細かく追いませんが、GuiceApplicationLoader#loadがApplicationインスタンスを作成するためにGuiceApplicationBuilderを作成し、GuiceApplicationBuilder#injectorでModuleを読み込んでいく、という動作です。

なので、初期化処理時にプレフィックスが設定されている必要があればRoutesをDIするようなクラスかプロバイダを作って、それ経由でバインディングすると良いですね。Moduleクラスを以下のように書き換えました。

package main

import javax.inject.Inject

import com.google.inject.{AbstractModule, Provides}
import play.api.mvc.Call
import play.api.routing.Router

class Module extends AbstractModule {
  def configure() = {}

  @Provides
  @Inject
  def callProvider(routes: Router): Call = sub.controllers.routes.SubController.index
}

では見てみましょう。

f:id:akairosame:20170218235312p:plain

無事、プレフィックスが設定されたパスが取得できました。

まとめ

Play Framework 2.5.10では、Guice Moduleの読み込み→各種Play Frameworkの設定→アプリケーションの起動の順番で動作するようで、Moduleの読み込みの段階ではサブプロジェクトのRoutesクラスのパスやコンテキストパスが設定されない状態になってしまうようです。それらを使うような処理を書く際にはRouterクラスをDIしておきましょう。

感想

調べたときはGuiceを使いながら上手いことルーティングを動的に処理している!と感動しましたが、まとめている内にやっぱり紛らわしいなと思いました。最初に設定されていれば…。とはいえ、そうするとPlayの設定前に色々操作したい場合に不都合があるでしょうし、どこを直せば良いのかが分からなかったのとIssueにも上がってなさそうだったので、使い方が悪かったという感じがします。ソースを見れば回避方法は分かりましたし。しかし、ソースの中を追っかけていけるのは障害があったときになんとかなると安心しますし勉強になりますね。OSSのありがたみ…。

後、はてなブログに慣れていないせいでこの記事作成中に3回内容が吹っ飛びました。辛かった…。

sbtからPlay Frameworkをインストールしようとして失敗した

とりあえずPlayが入ればいいやと次のようにしたんですが、依存性の解決に失敗しました。

/* project/plugins.sbt */
resolvers += "Typesafe repository" at "https://repo.typesafe.com/typesafe/maven-releases/"

addSbtPlugin("com.typesafe.play" % "sbt-plugin" % "2.5.10")

/* project/build.properties */
sbt.version = 0.13.12

/* build.sbt */
scalaVersion := "2.11.8"

lazy val main = (project in file("main")).enablePlugins(PlayScala)
[error] (main/*:update) sbt.ResolveException: unresolved dependency: com.typesafe.play#play-server_2.10;2.5.10: not found
[error] unresolved dependency: com.typesafe.play#play-netty-server_2.10;2.5.10: not found
[error] unresolved dependency: com.typesafe.play#play-logback_2.10;2.5.10: not found
[error] unresolved dependency: com.typesafe.play#play-test_2.10;2.5.10: not found
[error] unresolved dependency: com.typesafe.play#play-omnidoc_2.10;2.5.10: not found
[error] (main/*:ssExtractDependencies) sbt.ResolveException: unresolved dependency: com.typesafe.play#play-server_2.10;2.5.10: not found
[error] unresolved dependency: com.typesafe.play#play-netty-server_2.10;2.5.10: not found
[error] unresolved dependency: com.typesafe.play#play-logback_2.10;2.5.10: not found
[error] unresolved dependency: com.typesafe.play#play-test_2.10;2.5.10: not found
[error] unresolved dependency: com.typesafe.play#play-omnidoc_2.10;2.5.10: not found

えぇ…、Scalaのバージョン2.10のライブラリ取ってこようとしてますね…。Scalaのバージョンは2.11指定してるのにーと思ったのですが、中でバージョン何見てるんだとsbt scalaVersionしてみると、

> sbt scalaVersion
[info] main/*:scalaVersion
[info]  2.10.6
[info] playroute25/*:scalaVersion // <- sbtプロジェクトのフォルダ名
[info]  2.11.8

ああそういう…。sbtの中でルートディレクトリのプロジェクトって絶対作られるんですね…。プロジェクト名ってフォルダ名が付くのか…。sbtのドキュメント見返すとちゃんと書いてありました。sbt Reference Manual — マルチプロジェクト・ビルド

バージョンはsettingsに指定すれば良いということですね。

/* builds.sbt */
lazy val main = (project in file("main"))
  .enablePlugins(PlayScala)
  .settings(scalaVersion := "2.11.8")

これでOKでした。

sbt+Specs2でコンソール出力を設定する方法

テストケースが増えていくとSpecs2でテストをした際にログが肥大して見辛かったり、失敗したテスト箇所の情報が今ひとつ足りなかったのでコンソールへ出力する内容を設定する方法を調べました。

環境

Specs2 3.6.6
sbt 0.13.12

設定方法

Specs2側でコンソール出力する内容の設定を持っているので、それをテスト時に指定すれば良いようです。
Arguments reference

org.specs2.reporter.Notifier などのクラスを実装すれば好きなように出力を弄れるようですね。今回はそこまで必要なかったので簡単な設定で変更できる部分のみ試しました。

例えば、失敗したテストだけ詳細を出力するようにして(xonly)、失敗した際にはスタックトレースを出力するようにする(failtrace)と、
build.sbtを以下のようにすると設定できました。

lazy val root = (project in file(".")).
  settings(
    name := "root",
    scalaVersion := "2.11.8",
    libraryDependencies += "org.specs2" %% "specs2-core" % "3.6.6" % "test",
    scalacOptions in Test ++= Seq("-Yrangepos"),
    // Specs2設定
    testOptions in Test += Tests.Argument(sbt.TestFrameworks.Specs2, "xonly", "true", "failtrace", "true")
  )
テストしてみる

簡単なテストケースを用意してテストしてみました。

import org.specs2.mutable.Specification

class PassSpec extends Specification {
  "Pass" should {
    "test" in {
      true must beTrue
    }
  }
}

class TargetSpec extends Specification {
  object Target {
    def test(b: Boolean) = b must beTrue
  }

  "Target#test" should {
    "true" in {
      Target.test(true)
    }
    "false" in {
      Target.test(false)
    }
  }
}

PassSpecはテストに通過するクラス、TargetSpecはテストに失敗するクラスです。スタックトレースがどんな感じで出るか見るためオブジェクトにMatcherを置きました。

これで設定によって出力がどのように変わったか見てみました。

設定前

[info] Loading project definition from C:\xxx\project
[info] Set current project to root (in build file:/C:/xxx/)
[info] PassSpec
[info]
[info] Pass should
[info]   + test
[info]
[info]
[info] Total for specification PassSpec
[info] Finished in 30 ms
[info] 1 example, 0 failure, 0 error
[info]
[info] TargetSpec
[info]
[info] Target#test should
[info]   + true
[error]   x false
[error]    the value is false (TargetSpec.scala:13)
[info]
[info]
[info]
[info] Total for specification TargetSpec
[info] Finished in 30 ms
[info] 2 examples, 1 failure, 0 error
[info]
[error] Failed: Total 3, Failed 1, Errors 0, Passed 2
[error] Failed tests:
[error]         TargetSpec
[error] (test:test) sbt.TestsFailedException: Tests unsuccessful
[error] Total time: 2 s, completed 2017/01/09 22:27:47


設定後

[info] Loading project definition from C:\xxx\project
[info] Set current project to root (in build file:/C:/xxx/)
[info] PassSpec
[error]   x false
[error]    the value is false (TargetSpec.scala:13)
[error] TargetSpec$Target$.test(TargetSpec.scala:13)
[error] TargetSpec$$anonfun$2$$anonfun$apply$5.apply(TargetSpec.scala:21)
[error] TargetSpec$$anonfun$2$$anonfun$apply$5.apply(TargetSpec.scala:21)
[info] TargetSpec
[error] Failed: Total 3, Failed 1, Errors 0, Passed 2
[error] Failed tests:
[error]         TargetSpec
[error] (test:test) sbt.TestsFailedException: Tests unsuccessful
[error] Total time: 2 s, completed 2017/01/09 22:24:47

すっきりして良いですね。通過したテストでログを圧迫しなくなりそうです。スタックトレースも出ているので、とりあえずこれでテスト中に何らかのエラーが起こった時にも追跡しやすくなるんじゃないかなと思います。