akka-http 没有堆栈跟踪或错误详细信息
akka-http no stack trace or details on error
我得到的结构基本上可以概括为:
- 外部用户向 akka-http 服务器发出休息请求
- akka-http 使用 asynchttpclient
向(某些)数据源发出请求(查询?)
- akka-http 转换来自 asynchttpclient 的结果并将其返回给用户
有时我从 akka 收到一个错误,它几乎没有告诉我任何信息。这个错误发生在 asynchttpclient returns 我得到一些结果之后。 (事实上我现在可以在日志上打印结果,它们是从 json 等解析的。但是 akka 已经出错了)
即使在调试日志记录级别,我也没有从 akka 或堆栈跟踪中收到可破译的错误消息。
我收到的唯一消息是:
2017-03-24 17:22:55 INFO CompanyRepository:111 - search company with name:"somecompanyname"
2017-03-24 17:22:55 INFO CompanyRepository:73 - [QUERY TIME]: 527ms
[ERROR] [03/24/2017 17:22:55.951] [company-api-system-akka.actor.default-dispatcher-3] [akka.actor.ActorSystemImpl(company-api-system)] Error during processing of request: 'requirement failed'. Completing with 500 Internal Server Error response.
这条错误消息是我唯一得到的。我配置的相关部分:
akka {
loglevel = "DEBUG"
# edit -- tested with sl4jlogger with no change
#loggers = ["akka.event.slf4j.Slf4jLogger"]
#logging-filter = "akka.event.slf4j.Slf4jLoggingFilter"
parsing {
max-content-length = 800m
max-chunk-size = 100m
}
server {
server-header = akka-http/${akka.http.version}
idle-timeout = 120 s
request-timeout = 120 s
bind-timeout = 10s
max-connections = 1024
pipelining-limit = 32
verbose-error-messages = on
}
client {
user-agent-header = akka-http/${akka.http.version}
}
host-connection-pool {
max-connections = 4
}
}
akka.http.routing {
verbose-error-messages = on
}
任何人都知道我是否可以让 akka 吐出更多关于 what/where 错误发生的细节?
编辑:我意识到我在较小的结果集上没有得到同样的错误。 <- 忽略
编辑 2:
- 添加了 akka.loglevel = DEBUG,吐出更多噪音,但仍未详细说明实际错误。
- 快速将 asynchttpclient 转换为 akka 以排除 AHC
我已经对我的查询进行了包装以对其进行计时,并在其中添加了一些日志记录以试图查明错误发生的确切时间。
def queryTimer[ R <: Future[ Any ] ]( block: => R ): R = {
val t0 = System.currentTimeMillis()
val result = block
result.onComplete { maybeResult =>
val t1 = System.currentTimeMillis()
logger.info( "[QUERY TIME]: " + ( t1 - t0 ) + "ms" )
maybeResult match {
case Success(some) =>
logger.info( "successful feature:")
logger.info( FormattedString.prettyPrint(some))
case Failure(someFailure) =>
logger.info( "failed feature:")
logger.debug( FormattedString.prettyPrint(someFailure))
}
}
result
}
结果日志:
2017-03-28 13:19:10 INFO CompanyRepository:111 - search company with name:"some company"
[DEBUG] [03/28/2017 13:19:10.497] [company-api-system-akka.actor.default-dispatcher-2] [EventStream(akka://xca-api-actor-system)] logger log1-Logging$DefaultLogger started
[DEBUG] [03/28/2017 13:19:10.497] [company-api-system-akka.actor.default-dispatcher-2] [EventStream(akka://xca-api-actor-system)] Default Loggers started
[DEBUG] [03/28/2017 13:19:10.613] [company-api-system-akka.actor.default-dispatcher-2] [AkkaSSLConfig(akka://xca-api-actor-system)] Initializing AkkaSSLConfig extension...
[DEBUG] [03/28/2017 13:19:10.613] [company-api-system-akka.actor.default-dispatcher-2] [AkkaSSLConfig(akka://xca-api-actor-system)] buildHostnameVerifier: created hostname verifier: com.typesafe.sslconfig.ssl.DefaultHostnameVerifier@779e2339
[DEBUG] [03/28/2017 13:19:10.633] [xca-api-actor-system-akka.actor.default-dispatcher-3] [akka://xca-api-actor-system/user/pool-master/PoolInterfaceActor-0] (Re-)starting host connection pool to localhost:27474
[DEBUG] [03/28/2017 13:19:10.727] [xca-api-actor-system-akka.actor.default-dispatcher-3] [akka://xca-api-actor-system/system/IO-TCP/selectors/$a/0] Resolving localhost before connecting
[DEBUG] [03/28/2017 13:19:10.740] [xca-api-actor-system-akka.actor.default-dispatcher-4] [akka://xca-api-actor-system/system/IO-DNS] Resolution request for localhost from Actor[akka://xca-api-actor-system/system/IO-TCP/selectors/$a/0#-815754478]
[DEBUG] [03/28/2017 13:19:10.749] [xca-api-actor-system-akka.actor.default-dispatcher-4] [akka://xca-api-actor-system/system/IO-TCP/selectors/$a/0] Attempting connection to [localhost/127.0.0.1:27474]
[DEBUG] [03/28/2017 13:19:10.751] [xca-api-actor-system-akka.actor.default-dispatcher-4] [akka://xca-api-actor-system/system/IO-TCP/selectors/$a/0] Connection established to [localhost:27474]
2017-03-28 13:19:10 INFO CompanyRepository:73 - [QUERY TIME]: 376ms
2017-03-28 13:19:10 INFO CompanyRepository:77 - successful feature:
[ERROR] [03/28/2017 13:19:10.896] [company-api-system-akka.actor.default-dispatcher-7] [akka.actor.ActorSystemImpl(company-api-system)] Error during processing of request: 'requirement failed'. Completing with 500 Internal Server Error response.
2017-03-28 13:19:10 INFO CompanyRepository:78 - SearchResult(List(
( prettyprint output here!!! lots and lots of legit result, json parsed succcesfully into a bunch of case classes)
如您所见,我的日志记录格式与 akkas 不同,错误来自 akka 并提供详细信息,而一切看起来都正常。
编辑 3:在两次调用之间用 sleep
记录
带睡眠的新查询定时器功能
def queryTimer[ R <: Future[ Any ] ]( block: => R ): R = {
val t0 = System.currentTimeMillis()
val result = block
result.onComplete { maybeResult =>
val t1 = System.currentTimeMillis()
logger.info( "[QUERY TIME]: " + ( t1 - t0 ) + "ms" )
maybeResult match {
case Success(some) =>
Thread.sleep(500)
logger.info( "successful feature:")
Thread.sleep(500)
logger.info( FormattedString.prettyPrint(some))
Thread.sleep(500)
logger.info("we are there!")
case Failure(someFailure) =>
logger.info( "failed feature:")
logger.debug( FormattedString.prettyPrint(someFailure))
}
}
result
}
睡眠日志
[DEBUG] [03/30/2017 11:11:58.629] [xca-api-actor-system-akka.actor.default-dispatcher-7] [akka://xca-api-actor-system/system/IO-TCP/selectors/$a/0] Attempting connection to [localhost/127.0.0.1:27474]
[DEBUG] [03/30/2017 11:11:58.631] [xca-api-actor-system-akka.actor.default-dispatcher-7] [akka://xca-api-actor-system/system/IO-TCP/selectors/$a/0] Connection established to [localhost:27474]
11:11:59.442 [pool-2-thread-1] DEBUG o.a.netty.channel.DefaultChannelPool - Closed 0 connections out of 0 in 0 ms
11:11:59.496 [pool-1-thread-1] DEBUG o.a.netty.channel.DefaultChannelPool - Closed 0 connections out of 0 in 0 ms
11:12:00.250 [ForkJoinPool-2-worker-15] INFO c.s.s.r.neo4j.CompanyRepository - [QUERY TIME]: 1880ms
[ERROR] [03/30/2017 11:12:00.265] [company-api-system-akka.actor.default-dispatcher-3] [akka.actor.ActorSystemImpl(company-api-system)] Error during processing of request: 'requirement failed'. Completing with 500 Internal Server Error response.
11:12:00.543 [pool-2-thread-1] DEBUG o.a.netty.channel.DefaultChannelPool - Closed 0 connections out of 0 in 0 ms
11:12:00.597 [pool-1-thread-1] DEBUG o.a.netty.channel.DefaultChannelPool - Closed 0 connections out of 0 in 0 ms
11:12:00.752 [ForkJoinPool-2-worker-15] INFO c.s.s.r.neo4j.CompanyRepository - successful feature:
11:12:01.645 [pool-2-thread-1] DEBUG o.a.netty.channel.DefaultChannelPool - Closed 0 connections out of 0 in 0 ms
11:12:01.697 [pool-1-thread-1] DEBUG o.a.netty.channel.DefaultChannelPool - Closed 0 connections out of 0 in 0 ms
11:12:01.750 [ForkJoinPool-2-worker-15] INFO c.s.s.r.neo4j.CompanyRepository - SearchResult(List( "lots of legit result here"
11:12:02.281 [ForkJoinPool-2-worker-15] INFO c.s.s.r.neo4j.CompanyRepository - we are there!
编辑4和解决方案!
显然默认异常处理程序不打印堆栈跟踪!用一个非常基本的包罗万象覆盖异常处理程序:
implicit def myExceptionHandler: ExceptionHandler =
ExceptionHandler {
case e: Exception => {
logger.info("---------------- exception log start")
logger.error(e.getMessage, e)
logger.error("cause" , e.getCause)
logger.error("cause" , e.getStackTraceString )
logger.info( FormattedString.prettyPrint(e))
logger.info("---------------- exception log end")
Directives.complete("server made a boo boo")
}
}
导致堆栈跟踪使我感到困惑!
11:42:04.634 [company-api-system-akka.actor.default-dispatcher-2] INFO c.stepweb.scarifgate.CompanyApiApp$ - ---------------- exception log start
11:42:04.640 [company-api-system-akka.actor.default-dispatcher-2] ERROR c.stepweb.scarifgate.CompanyApiApp$ - requirement failed
java.lang.IllegalArgumentException: requirement failed
at scala.Predef$.require(Predef.scala:212) ~[scala-library-2.11.8.jar:na]
at spray.json.BasicFormats$StringJsonFormat$.write(BasicFormats.scala:121) ~[spray-json_2.11-1.3.2.jar:na]
at spray.json.BasicFormats$StringJsonFormat$.write(BasicFormats.scala:119) ~[spray-json_2.11-1.3.2.jar:na]
at spray.json.ProductFormats$class.productElement2Field(ProductFormats.scala:46) ~[spray-json_2.11-1.3.2.jar:na]
at com.stepweb.scarifgate.services.CompanyService.productElement2Field(CompanyService.scala:14) ~[classes/:na]
at spray.json.ProductFormatsInstances$$anon.write(ProductFormatsInstances.scala:73) ~[spray-json_2.11-1.3.2.jar:na]
at spray.json.ProductFormatsInstances$$anon.write(ProductFormatsInstances.scala:68) ~[spray-json_2.11-1.3.2.jar:na]
at spray.json.PimpedAny.toJson(package.scala:39) ~[spray-json_2.11-1.3.2.jar:na]
at spray.json.CollectionFormats$$anon$$anonfun$write.apply(CollectionFormats.scala:26) ~[spray-json_2.11-1.3.2.jar:na]
at spray.json.CollectionFormats$$anon$$anonfun$write.apply(CollectionFormats.scala:26) ~[spray-json_2.11-1.3.2.jar:na]
at scala.collection.immutable.List.map(List.scala:273) ~[scala-library-2.11.8.jar:na]
at spray.json.CollectionFormats$$anon.write(CollectionFormats.scala:26) ~[spray-json_2.11-1.3.2.jar:na]
at spray.json.CollectionFormats$$anon.write(CollectionFormats.scala:25) ~[spray-json_2.11-1.3.2.jar:na]
at spray.json.ProductFormats$class.productElement2Field(ProductFormats.scala:46) ~[spray-json_2.11-1.3.2.jar:na]
at com.stepweb.scarifgate.services.CompanyService.productElement2Field(CompanyService.scala:14) ~[classes/:na]
at spray.json.ProductFormatsInstances$$anon.write(ProductFormatsInstances.scala:30) ~[spray-json_2.11-1.3.2.jar:na]
at spray.json.ProductFormatsInstances$$anon.write(ProductFormatsInstances.scala:26) ~[spray-json_2.11-1.3.2.jar:na]
at akka.http.scaladsl.marshallers.sprayjson.SprayJsonSupport$$anonfun$sprayJsonMarshaller.apply(SprayJsonSupport.scala:62) ~[akka-http-spray-json_2.11-10.0.0.jar:10.0.0]
at akka.http.scaladsl.marshallers.sprayjson.SprayJsonSupport$$anonfun$sprayJsonMarshaller.apply(SprayJsonSupport.scala:62) ~[akka-http-spray-json_2.11-10.0.0.jar:10.0.0]
at akka.http.scaladsl.marshalling.Marshaller$$anonfun$compose$$anonfun$apply.apply(Marshaller.scala:73) ~[akka-http_2.11-10.0.0.jar:10.0.0]
at akka.http.scaladsl.marshalling.Marshaller$$anonfun$compose$$anonfun$apply.apply(Marshaller.scala:73) ~[akka-http_2.11-10.0.0.jar:10.0.0]
at akka.http.scaladsl.marshalling.Marshaller$$anon.apply(Marshaller.scala:92) ~[akka-http_2.11-10.0.0.jar:10.0.0]
at akka.http.scaladsl.marshalling.GenericMarshallers$$anonfun$optionMarshaller$$anonfun$apply.apply(GenericMarshallers.scala:19) ~[akka-http_2.11-10.0.0.jar:10.0.0]
at akka.http.scaladsl.marshalling.GenericMarshallers$$anonfun$optionMarshaller$$anonfun$apply.apply(GenericMarshallers.scala:18) ~[akka-http_2.11-10.0.0.jar:10.0.0]
at akka.http.scaladsl.marshalling.Marshaller$$anon.apply(Marshaller.scala:92) ~[akka-http_2.11-10.0.0.jar:10.0.0]
at akka.http.scaladsl.marshalling.PredefinedToResponseMarshallers$$anonfun$fromStatusCodeAndHeadersAndValue$$anonfun$apply.apply(PredefinedToResponseMarshallers.scala:58) ~[akka-http_2.11-10.0.0.jar:10.0.0]
at akka.http.scaladsl.marshalling.PredefinedToResponseMarshallers$$anonfun$fromStatusCodeAndHeadersAndValue$$anonfun$apply.apply(PredefinedToResponseMarshallers.scala:57) ~[akka-http_2.11-10.0.0.jar:10.0.0]
at akka.http.scaladsl.marshalling.Marshaller$$anon.apply(Marshaller.scala:92) ~[akka-http_2.11-10.0.0.jar:10.0.0]
at akka.http.scaladsl.marshalling.Marshaller$$anonfun$compose$$anonfun$apply.apply(Marshaller.scala:73) ~[akka-http_2.11-10.0.0.jar:10.0.0]
at akka.http.scaladsl.marshalling.Marshaller$$anonfun$compose$$anonfun$apply.apply(Marshaller.scala:73) ~[akka-http_2.11-10.0.0.jar:10.0.0]
at akka.http.scaladsl.marshalling.Marshaller$$anon.apply(Marshaller.scala:92) ~[akka-http_2.11-10.0.0.jar:10.0.0]
at akka.http.scaladsl.marshalling.ToResponseMarshallable$$anonfun$$anonfun$apply.apply(ToResponseMarshallable.scala:29) ~[akka-http_2.11-10.0.0.jar:10.0.0]
at akka.http.scaladsl.marshalling.ToResponseMarshallable$$anonfun$$anonfun$apply.apply(ToResponseMarshallable.scala:29) ~[akka-http_2.11-10.0.0.jar:10.0.0]
at akka.http.scaladsl.marshalling.Marshaller$$anon.apply(Marshaller.scala:92) ~[akka-http_2.11-10.0.0.jar:10.0.0]
at akka.http.scaladsl.marshalling.GenericMarshallers$$anonfun$futureMarshaller$$anonfun$apply$$anonfun$apply.apply(GenericMarshallers.scala:33) ~[akka-http_2.11-10.0.0.jar:10.0.0]
at akka.http.scaladsl.marshalling.GenericMarshallers$$anonfun$futureMarshaller$$anonfun$apply$$anonfun$apply.apply(GenericMarshallers.scala:33) ~[akka-http_2.11-10.0.0.jar:10.0.0]
at akka.http.scaladsl.util.FastFuture$.akka$http$scaladsl$util$FastFuture$$strictTransform(FastFuture.scala:41) ~[akka-http-core_2.11-10.0.0.jar:10.0.0]
at akka.http.scaladsl.util.FastFuture$$anonfun$transformWith$extension1.apply(FastFuture.scala:51) [akka-http-core_2.11-10.0.0.jar:10.0.0]
at akka.http.scaladsl.util.FastFuture$$anonfun$transformWith$extension1.apply(FastFuture.scala:50) [akka-http-core_2.11-10.0.0.jar:10.0.0]
at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:32) [scala-library-2.11.8.jar:na]
at akka.dispatch.BatchingExecutor$AbstractBatch.processBatch(BatchingExecutor.scala:55) [akka-actor_2.11-2.4.16.jar:na]
at akka.dispatch.BatchingExecutor$BlockableBatch$$anonfun$run.apply$mcV$sp(BatchingExecutor.scala:91) [akka-actor_2.11-2.4.16.jar:na]
at akka.dispatch.BatchingExecutor$BlockableBatch$$anonfun$run.apply(BatchingExecutor.scala:91) [akka-actor_2.11-2.4.16.jar:na]
at akka.dispatch.BatchingExecutor$BlockableBatch$$anonfun$run.apply(BatchingExecutor.scala:91) [akka-actor_2.11-2.4.16.jar:na]
at scala.concurrent.BlockContext$.withBlockContext(BlockContext.scala:72) [scala-library-2.11.8.jar:na]
at akka.dispatch.BatchingExecutor$BlockableBatch.run(BatchingExecutor.scala:90) [akka-actor_2.11-2.4.16.jar:na]
at akka.dispatch.TaskInvocation.run(AbstractDispatcher.scala:39) [akka-actor_2.11-2.4.16.jar:na]
at akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinTask.exec(AbstractDispatcher.scala:415) [akka-actor_2.11-2.4.16.jar:na]
at scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260) [scala-library-2.11.8.jar:na]
at scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339) [scala-library-2.11.8.jar:na]
at scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979) [scala-library-2.11.8.jar:na]
at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107) [scala-library-2.11.8.jar:na]
11:42:04.640 [company-api-system-akka.actor.default-dispatcher-2] ERROR c.stepweb.scarifgate.CompanyApiApp$ - cause
11:42:04.641 [company-api-system-akka.actor.default-dispatcher-2] ERROR c.stepweb.scarifgate.CompanyApiApp$ - cause
11:42:04.644 [company-api-system-akka.actor.default-dispatcher-2] INFO c.stepweb.scarifgate.CompanyApiApp$ - java.lang.IllegalArgumentException: requirement failed
11:42:04.644 [company-api-system-akka.actor.default-dispatcher-2] INFO c.stepweb.scarifgate.CompanyApiApp$ - ---------------- exception log end
所以...异常是在spray.json.BasicFormats
这里造成的
implicit object StringJsonFormat extends JsonFormat[String] {
def write(x: String) = {
require(x ne null) // <-----------------------------------
JsString(x)
}
def read(value: JsValue) = value match {
case JsString(x) => x
case x => deserializationError("Expected String as JsString, but got " + x)
}
}
这意味着这数千行响应中的一个字符串为空。特别感谢在没有消息的情况下使用 "require" 的懒惰。调试哪个字符串为空将是一场噩梦,但我仍然认为 akka 应该以更好的方式失败。
也尝试设置记录器 - 从您的配置来看,它们似乎没有设置。类似于:
akka {
loggers = ["akka.event.slf4j.Slf4jLogger"]
loglevel = "DEBUG"
logging-filter = "akka.event.slf4j.Slf4jLoggingFilter"
}
此外,考虑使用 akka-slf4j along with their recommended logging backend logback。
这应该会让 akka 吐出更多细节。
akka-http no stack trace or details on error
好吧,默认的 akka-http ExceptionHandler
不打印堆栈跟踪,只打印错误消息或其 class 名称(如果消息为空),但您可以提供将打印的自定义异常处理程序你想要的任何东西(即你的例子中的堆栈跟踪)。
GitHub ExceptionHandlerExamplesSpec.spec
提供了一些如何制作自定义异常处理程序的示例
在您的案例中,最简单的方法似乎是定义您自己的自定义隐式异常处理程序
import akka.http.scaladsl.model._
import akka.http.scaladsl.server._
import StatusCodes._
import Directives._
implicit def myExceptionHandler: ExceptionHandler =
ExceptionHandler {
case NonFatal(e) =>
logger.error(s"Exception $e at\n${e.getStackTraceString}")
complete(HttpResponse(InternalServerError, entity = "Internal Server Error"))
}
}
我得到的结构基本上可以概括为:
- 外部用户向 akka-http 服务器发出休息请求
- akka-http 使用 asynchttpclient 向(某些)数据源发出请求(查询?)
- akka-http 转换来自 asynchttpclient 的结果并将其返回给用户
有时我从 akka 收到一个错误,它几乎没有告诉我任何信息。这个错误发生在 asynchttpclient returns 我得到一些结果之后。 (事实上我现在可以在日志上打印结果,它们是从 json 等解析的。但是 akka 已经出错了)
即使在调试日志记录级别,我也没有从 akka 或堆栈跟踪中收到可破译的错误消息。
我收到的唯一消息是:
2017-03-24 17:22:55 INFO CompanyRepository:111 - search company with name:"somecompanyname"
2017-03-24 17:22:55 INFO CompanyRepository:73 - [QUERY TIME]: 527ms
[ERROR] [03/24/2017 17:22:55.951] [company-api-system-akka.actor.default-dispatcher-3] [akka.actor.ActorSystemImpl(company-api-system)] Error during processing of request: 'requirement failed'. Completing with 500 Internal Server Error response.
这条错误消息是我唯一得到的。我配置的相关部分:
akka {
loglevel = "DEBUG"
# edit -- tested with sl4jlogger with no change
#loggers = ["akka.event.slf4j.Slf4jLogger"]
#logging-filter = "akka.event.slf4j.Slf4jLoggingFilter"
parsing {
max-content-length = 800m
max-chunk-size = 100m
}
server {
server-header = akka-http/${akka.http.version}
idle-timeout = 120 s
request-timeout = 120 s
bind-timeout = 10s
max-connections = 1024
pipelining-limit = 32
verbose-error-messages = on
}
client {
user-agent-header = akka-http/${akka.http.version}
}
host-connection-pool {
max-connections = 4
}
}
akka.http.routing {
verbose-error-messages = on
}
任何人都知道我是否可以让 akka 吐出更多关于 what/where 错误发生的细节?
编辑:我意识到我在较小的结果集上没有得到同样的错误。 <- 忽略
编辑 2:
- 添加了 akka.loglevel = DEBUG,吐出更多噪音,但仍未详细说明实际错误。
- 快速将 asynchttpclient 转换为 akka 以排除 AHC
我已经对我的查询进行了包装以对其进行计时,并在其中添加了一些日志记录以试图查明错误发生的确切时间。
def queryTimer[ R <: Future[ Any ] ]( block: => R ): R = { val t0 = System.currentTimeMillis() val result = block result.onComplete { maybeResult => val t1 = System.currentTimeMillis() logger.info( "[QUERY TIME]: " + ( t1 - t0 ) + "ms" ) maybeResult match { case Success(some) => logger.info( "successful feature:") logger.info( FormattedString.prettyPrint(some)) case Failure(someFailure) => logger.info( "failed feature:") logger.debug( FormattedString.prettyPrint(someFailure)) } } result }
结果日志:
2017-03-28 13:19:10 INFO CompanyRepository:111 - search company with name:"some company" [DEBUG] [03/28/2017 13:19:10.497] [company-api-system-akka.actor.default-dispatcher-2] [EventStream(akka://xca-api-actor-system)] logger log1-Logging$DefaultLogger started [DEBUG] [03/28/2017 13:19:10.497] [company-api-system-akka.actor.default-dispatcher-2] [EventStream(akka://xca-api-actor-system)] Default Loggers started [DEBUG] [03/28/2017 13:19:10.613] [company-api-system-akka.actor.default-dispatcher-2] [AkkaSSLConfig(akka://xca-api-actor-system)] Initializing AkkaSSLConfig extension... [DEBUG] [03/28/2017 13:19:10.613] [company-api-system-akka.actor.default-dispatcher-2] [AkkaSSLConfig(akka://xca-api-actor-system)] buildHostnameVerifier: created hostname verifier: com.typesafe.sslconfig.ssl.DefaultHostnameVerifier@779e2339 [DEBUG] [03/28/2017 13:19:10.633] [xca-api-actor-system-akka.actor.default-dispatcher-3] [akka://xca-api-actor-system/user/pool-master/PoolInterfaceActor-0] (Re-)starting host connection pool to localhost:27474 [DEBUG] [03/28/2017 13:19:10.727] [xca-api-actor-system-akka.actor.default-dispatcher-3] [akka://xca-api-actor-system/system/IO-TCP/selectors/$a/0] Resolving localhost before connecting [DEBUG] [03/28/2017 13:19:10.740] [xca-api-actor-system-akka.actor.default-dispatcher-4] [akka://xca-api-actor-system/system/IO-DNS] Resolution request for localhost from Actor[akka://xca-api-actor-system/system/IO-TCP/selectors/$a/0#-815754478] [DEBUG] [03/28/2017 13:19:10.749] [xca-api-actor-system-akka.actor.default-dispatcher-4] [akka://xca-api-actor-system/system/IO-TCP/selectors/$a/0] Attempting connection to [localhost/127.0.0.1:27474] [DEBUG] [03/28/2017 13:19:10.751] [xca-api-actor-system-akka.actor.default-dispatcher-4] [akka://xca-api-actor-system/system/IO-TCP/selectors/$a/0] Connection established to [localhost:27474] 2017-03-28 13:19:10 INFO CompanyRepository:73 - [QUERY TIME]: 376ms 2017-03-28 13:19:10 INFO CompanyRepository:77 - successful feature: [ERROR] [03/28/2017 13:19:10.896] [company-api-system-akka.actor.default-dispatcher-7] [akka.actor.ActorSystemImpl(company-api-system)] Error during processing of request: 'requirement failed'. Completing with 500 Internal Server Error response. 2017-03-28 13:19:10 INFO CompanyRepository:78 - SearchResult(List( ( prettyprint output here!!! lots and lots of legit result, json parsed succcesfully into a bunch of case classes)
如您所见,我的日志记录格式与 akkas 不同,错误来自 akka 并提供详细信息,而一切看起来都正常。
编辑 3:在两次调用之间用 sleep
记录
带睡眠的新查询定时器功能
def queryTimer[ R <: Future[ Any ] ]( block: => R ): R = { val t0 = System.currentTimeMillis() val result = block result.onComplete { maybeResult => val t1 = System.currentTimeMillis() logger.info( "[QUERY TIME]: " + ( t1 - t0 ) + "ms" ) maybeResult match { case Success(some) => Thread.sleep(500) logger.info( "successful feature:") Thread.sleep(500) logger.info( FormattedString.prettyPrint(some)) Thread.sleep(500) logger.info("we are there!") case Failure(someFailure) => logger.info( "failed feature:") logger.debug( FormattedString.prettyPrint(someFailure)) } } result }
睡眠日志
[DEBUG] [03/30/2017 11:11:58.629] [xca-api-actor-system-akka.actor.default-dispatcher-7] [akka://xca-api-actor-system/system/IO-TCP/selectors/$a/0] Attempting connection to [localhost/127.0.0.1:27474] [DEBUG] [03/30/2017 11:11:58.631] [xca-api-actor-system-akka.actor.default-dispatcher-7] [akka://xca-api-actor-system/system/IO-TCP/selectors/$a/0] Connection established to [localhost:27474] 11:11:59.442 [pool-2-thread-1] DEBUG o.a.netty.channel.DefaultChannelPool - Closed 0 connections out of 0 in 0 ms 11:11:59.496 [pool-1-thread-1] DEBUG o.a.netty.channel.DefaultChannelPool - Closed 0 connections out of 0 in 0 ms 11:12:00.250 [ForkJoinPool-2-worker-15] INFO c.s.s.r.neo4j.CompanyRepository - [QUERY TIME]: 1880ms [ERROR] [03/30/2017 11:12:00.265] [company-api-system-akka.actor.default-dispatcher-3] [akka.actor.ActorSystemImpl(company-api-system)] Error during processing of request: 'requirement failed'. Completing with 500 Internal Server Error response. 11:12:00.543 [pool-2-thread-1] DEBUG o.a.netty.channel.DefaultChannelPool - Closed 0 connections out of 0 in 0 ms 11:12:00.597 [pool-1-thread-1] DEBUG o.a.netty.channel.DefaultChannelPool - Closed 0 connections out of 0 in 0 ms 11:12:00.752 [ForkJoinPool-2-worker-15] INFO c.s.s.r.neo4j.CompanyRepository - successful feature: 11:12:01.645 [pool-2-thread-1] DEBUG o.a.netty.channel.DefaultChannelPool - Closed 0 connections out of 0 in 0 ms 11:12:01.697 [pool-1-thread-1] DEBUG o.a.netty.channel.DefaultChannelPool - Closed 0 connections out of 0 in 0 ms 11:12:01.750 [ForkJoinPool-2-worker-15] INFO c.s.s.r.neo4j.CompanyRepository - SearchResult(List( "lots of legit result here" 11:12:02.281 [ForkJoinPool-2-worker-15] INFO c.s.s.r.neo4j.CompanyRepository - we are there!
编辑4和解决方案!
显然默认异常处理程序不打印堆栈跟踪!用一个非常基本的包罗万象覆盖异常处理程序:
implicit def myExceptionHandler: ExceptionHandler = ExceptionHandler { case e: Exception => { logger.info("---------------- exception log start") logger.error(e.getMessage, e) logger.error("cause" , e.getCause) logger.error("cause" , e.getStackTraceString ) logger.info( FormattedString.prettyPrint(e)) logger.info("---------------- exception log end") Directives.complete("server made a boo boo") } }
导致堆栈跟踪使我感到困惑!
11:42:04.634 [company-api-system-akka.actor.default-dispatcher-2] INFO c.stepweb.scarifgate.CompanyApiApp$ - ---------------- exception log start 11:42:04.640 [company-api-system-akka.actor.default-dispatcher-2] ERROR c.stepweb.scarifgate.CompanyApiApp$ - requirement failed java.lang.IllegalArgumentException: requirement failed at scala.Predef$.require(Predef.scala:212) ~[scala-library-2.11.8.jar:na] at spray.json.BasicFormats$StringJsonFormat$.write(BasicFormats.scala:121) ~[spray-json_2.11-1.3.2.jar:na] at spray.json.BasicFormats$StringJsonFormat$.write(BasicFormats.scala:119) ~[spray-json_2.11-1.3.2.jar:na] at spray.json.ProductFormats$class.productElement2Field(ProductFormats.scala:46) ~[spray-json_2.11-1.3.2.jar:na] at com.stepweb.scarifgate.services.CompanyService.productElement2Field(CompanyService.scala:14) ~[classes/:na] at spray.json.ProductFormatsInstances$$anon.write(ProductFormatsInstances.scala:73) ~[spray-json_2.11-1.3.2.jar:na] at spray.json.ProductFormatsInstances$$anon.write(ProductFormatsInstances.scala:68) ~[spray-json_2.11-1.3.2.jar:na] at spray.json.PimpedAny.toJson(package.scala:39) ~[spray-json_2.11-1.3.2.jar:na] at spray.json.CollectionFormats$$anon$$anonfun$write.apply(CollectionFormats.scala:26) ~[spray-json_2.11-1.3.2.jar:na] at spray.json.CollectionFormats$$anon$$anonfun$write.apply(CollectionFormats.scala:26) ~[spray-json_2.11-1.3.2.jar:na] at scala.collection.immutable.List.map(List.scala:273) ~[scala-library-2.11.8.jar:na] at spray.json.CollectionFormats$$anon.write(CollectionFormats.scala:26) ~[spray-json_2.11-1.3.2.jar:na] at spray.json.CollectionFormats$$anon.write(CollectionFormats.scala:25) ~[spray-json_2.11-1.3.2.jar:na] at spray.json.ProductFormats$class.productElement2Field(ProductFormats.scala:46) ~[spray-json_2.11-1.3.2.jar:na] at com.stepweb.scarifgate.services.CompanyService.productElement2Field(CompanyService.scala:14) ~[classes/:na] at spray.json.ProductFormatsInstances$$anon.write(ProductFormatsInstances.scala:30) ~[spray-json_2.11-1.3.2.jar:na] at spray.json.ProductFormatsInstances$$anon.write(ProductFormatsInstances.scala:26) ~[spray-json_2.11-1.3.2.jar:na] at akka.http.scaladsl.marshallers.sprayjson.SprayJsonSupport$$anonfun$sprayJsonMarshaller.apply(SprayJsonSupport.scala:62) ~[akka-http-spray-json_2.11-10.0.0.jar:10.0.0] at akka.http.scaladsl.marshallers.sprayjson.SprayJsonSupport$$anonfun$sprayJsonMarshaller.apply(SprayJsonSupport.scala:62) ~[akka-http-spray-json_2.11-10.0.0.jar:10.0.0] at akka.http.scaladsl.marshalling.Marshaller$$anonfun$compose$$anonfun$apply.apply(Marshaller.scala:73) ~[akka-http_2.11-10.0.0.jar:10.0.0] at akka.http.scaladsl.marshalling.Marshaller$$anonfun$compose$$anonfun$apply.apply(Marshaller.scala:73) ~[akka-http_2.11-10.0.0.jar:10.0.0] at akka.http.scaladsl.marshalling.Marshaller$$anon.apply(Marshaller.scala:92) ~[akka-http_2.11-10.0.0.jar:10.0.0] at akka.http.scaladsl.marshalling.GenericMarshallers$$anonfun$optionMarshaller$$anonfun$apply.apply(GenericMarshallers.scala:19) ~[akka-http_2.11-10.0.0.jar:10.0.0] at akka.http.scaladsl.marshalling.GenericMarshallers$$anonfun$optionMarshaller$$anonfun$apply.apply(GenericMarshallers.scala:18) ~[akka-http_2.11-10.0.0.jar:10.0.0] at akka.http.scaladsl.marshalling.Marshaller$$anon.apply(Marshaller.scala:92) ~[akka-http_2.11-10.0.0.jar:10.0.0] at akka.http.scaladsl.marshalling.PredefinedToResponseMarshallers$$anonfun$fromStatusCodeAndHeadersAndValue$$anonfun$apply.apply(PredefinedToResponseMarshallers.scala:58) ~[akka-http_2.11-10.0.0.jar:10.0.0] at akka.http.scaladsl.marshalling.PredefinedToResponseMarshallers$$anonfun$fromStatusCodeAndHeadersAndValue$$anonfun$apply.apply(PredefinedToResponseMarshallers.scala:57) ~[akka-http_2.11-10.0.0.jar:10.0.0] at akka.http.scaladsl.marshalling.Marshaller$$anon.apply(Marshaller.scala:92) ~[akka-http_2.11-10.0.0.jar:10.0.0] at akka.http.scaladsl.marshalling.Marshaller$$anonfun$compose$$anonfun$apply.apply(Marshaller.scala:73) ~[akka-http_2.11-10.0.0.jar:10.0.0] at akka.http.scaladsl.marshalling.Marshaller$$anonfun$compose$$anonfun$apply.apply(Marshaller.scala:73) ~[akka-http_2.11-10.0.0.jar:10.0.0] at akka.http.scaladsl.marshalling.Marshaller$$anon.apply(Marshaller.scala:92) ~[akka-http_2.11-10.0.0.jar:10.0.0] at akka.http.scaladsl.marshalling.ToResponseMarshallable$$anonfun$$anonfun$apply.apply(ToResponseMarshallable.scala:29) ~[akka-http_2.11-10.0.0.jar:10.0.0] at akka.http.scaladsl.marshalling.ToResponseMarshallable$$anonfun$$anonfun$apply.apply(ToResponseMarshallable.scala:29) ~[akka-http_2.11-10.0.0.jar:10.0.0] at akka.http.scaladsl.marshalling.Marshaller$$anon.apply(Marshaller.scala:92) ~[akka-http_2.11-10.0.0.jar:10.0.0] at akka.http.scaladsl.marshalling.GenericMarshallers$$anonfun$futureMarshaller$$anonfun$apply$$anonfun$apply.apply(GenericMarshallers.scala:33) ~[akka-http_2.11-10.0.0.jar:10.0.0] at akka.http.scaladsl.marshalling.GenericMarshallers$$anonfun$futureMarshaller$$anonfun$apply$$anonfun$apply.apply(GenericMarshallers.scala:33) ~[akka-http_2.11-10.0.0.jar:10.0.0] at akka.http.scaladsl.util.FastFuture$.akka$http$scaladsl$util$FastFuture$$strictTransform(FastFuture.scala:41) ~[akka-http-core_2.11-10.0.0.jar:10.0.0] at akka.http.scaladsl.util.FastFuture$$anonfun$transformWith$extension1.apply(FastFuture.scala:51) [akka-http-core_2.11-10.0.0.jar:10.0.0] at akka.http.scaladsl.util.FastFuture$$anonfun$transformWith$extension1.apply(FastFuture.scala:50) [akka-http-core_2.11-10.0.0.jar:10.0.0] at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:32) [scala-library-2.11.8.jar:na] at akka.dispatch.BatchingExecutor$AbstractBatch.processBatch(BatchingExecutor.scala:55) [akka-actor_2.11-2.4.16.jar:na] at akka.dispatch.BatchingExecutor$BlockableBatch$$anonfun$run.apply$mcV$sp(BatchingExecutor.scala:91) [akka-actor_2.11-2.4.16.jar:na] at akka.dispatch.BatchingExecutor$BlockableBatch$$anonfun$run.apply(BatchingExecutor.scala:91) [akka-actor_2.11-2.4.16.jar:na] at akka.dispatch.BatchingExecutor$BlockableBatch$$anonfun$run.apply(BatchingExecutor.scala:91) [akka-actor_2.11-2.4.16.jar:na] at scala.concurrent.BlockContext$.withBlockContext(BlockContext.scala:72) [scala-library-2.11.8.jar:na] at akka.dispatch.BatchingExecutor$BlockableBatch.run(BatchingExecutor.scala:90) [akka-actor_2.11-2.4.16.jar:na] at akka.dispatch.TaskInvocation.run(AbstractDispatcher.scala:39) [akka-actor_2.11-2.4.16.jar:na] at akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinTask.exec(AbstractDispatcher.scala:415) [akka-actor_2.11-2.4.16.jar:na] at scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260) [scala-library-2.11.8.jar:na] at scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339) [scala-library-2.11.8.jar:na] at scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979) [scala-library-2.11.8.jar:na] at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107) [scala-library-2.11.8.jar:na] 11:42:04.640 [company-api-system-akka.actor.default-dispatcher-2] ERROR c.stepweb.scarifgate.CompanyApiApp$ - cause 11:42:04.641 [company-api-system-akka.actor.default-dispatcher-2] ERROR c.stepweb.scarifgate.CompanyApiApp$ - cause 11:42:04.644 [company-api-system-akka.actor.default-dispatcher-2] INFO c.stepweb.scarifgate.CompanyApiApp$ - java.lang.IllegalArgumentException: requirement failed 11:42:04.644 [company-api-system-akka.actor.default-dispatcher-2] INFO c.stepweb.scarifgate.CompanyApiApp$ - ---------------- exception log end
所以...异常是在spray.json.BasicFormats
这里造成的implicit object StringJsonFormat extends JsonFormat[String] { def write(x: String) = { require(x ne null) // <----------------------------------- JsString(x) } def read(value: JsValue) = value match { case JsString(x) => x case x => deserializationError("Expected String as JsString, but got " + x) } }
这意味着这数千行响应中的一个字符串为空。特别感谢在没有消息的情况下使用 "require" 的懒惰。调试哪个字符串为空将是一场噩梦,但我仍然认为 akka 应该以更好的方式失败。
也尝试设置记录器 - 从您的配置来看,它们似乎没有设置。类似于:
akka {
loggers = ["akka.event.slf4j.Slf4jLogger"]
loglevel = "DEBUG"
logging-filter = "akka.event.slf4j.Slf4jLoggingFilter"
}
此外,考虑使用 akka-slf4j along with their recommended logging backend logback。
这应该会让 akka 吐出更多细节。
akka-http no stack trace or details on error
好吧,默认的 akka-http ExceptionHandler
不打印堆栈跟踪,只打印错误消息或其 class 名称(如果消息为空),但您可以提供将打印的自定义异常处理程序你想要的任何东西(即你的例子中的堆栈跟踪)。
GitHub ExceptionHandlerExamplesSpec.spec
提供了一些如何制作自定义异常处理程序的示例在您的案例中,最简单的方法似乎是定义您自己的自定义隐式异常处理程序
import akka.http.scaladsl.model._
import akka.http.scaladsl.server._
import StatusCodes._
import Directives._
implicit def myExceptionHandler: ExceptionHandler =
ExceptionHandler {
case NonFatal(e) =>
logger.error(s"Exception $e at\n${e.getStackTraceString}")
complete(HttpResponse(InternalServerError, entity = "Internal Server Error"))
}
}