Logging OvalBuilder constraint violations omits field names

[cwbriones]

The log says "message": "net.sf.oval.constraint.NotNull.violated" without indicating which field violated the constraint. This must be happening somewhere in the logging serialization stack because ConstraintsViolatedException normally includes the context in the error message.

The expected message is something like

net.sf.oval.ConstraintViolation: com.arpnetworking.metrics.portal.scheduling.JobRef$Builder._execRepository cannot be null

and indeed, if you catch a violation exception from a test this is what is logged.

Full log:

{
  "time": "2020-04-30T02:54:12.572Z",
  "name": "log",
  "level": "crit",
  "data": {
    "message": "error processing request",
    "request": {
      "_id": "24791273",
      "_class": "play.mvc.Http$RequestImpl"
    },
    "method": "PUT",
    "path": "/v1/reports"
  },
  "exception": {
    "type": "net.sf.oval.exception.ConstraintsViolatedException",
    "message": "net.sf.oval.constraint.NotNull.violated",
    "backtrace": [
      "at com.arpnetworking.commons.builder.OvalBuilder.build(OvalBuilder.java:180)",
      "at controllers.ReportController.kickJobExecutor(ReportController.java:264)",
      "at controllers.ReportController.addOrUpdate(ReportController.java:134)",
      "at portal.Routes$$anonfun$routes$1$$anonfun$applyOrElse$17$$anonfun$apply$17.apply(Routes.scala:707)",
      "at portal.Routes$$anonfun$routes$1$$anonfun$applyOrElse$17$$anonfun$apply$17.apply(Routes.scala:707)",
      "at play.core.routing.HandlerInvokerFactory$$anon$3.resultCall(HandlerInvoker.scala:142)",
      "at play.core.routing.HandlerInvokerFactory$$anon$3.resultCall(HandlerInvoker.scala:141)",
      "at play.core.routing.HandlerInvokerFactory$JavaActionInvokerFactory$$anon$8$$anon$2$$anon$1.invocation(HandlerInvoker.scala:115)",
      "at play.core.j.JavaAction$$anon$1.call(JavaAction.scala:111)",
      "at com.arpnetworking.play.metrics.MetricsActionWrapper.call(MetricsActionWrapper.java:60)",
      "at play.core.j.JavaAction$$anonfun$9.apply(JavaAction.scala:170)",
      "at play.core.j.JavaAction$$anonfun$9.apply(JavaAction.scala:170)",
      "at scala.concurrent.impl.Future$PromiseCompletingRunnable.liftedTree1$1(Future.scala:24)",
      "at scala.concurrent.impl.Future$PromiseCompletingRunnable.run(Future.scala:24)",
      "at play.core.j.HttpExecutionContext$$anon$2.run(HttpExecutionContext.scala:64)",
      "at play.api.libs.streams.Execution$trampoline$.execute(Execution.scala:71)",
      "at play.core.j.HttpExecutionContext.execute(HttpExecutionContext.scala:56)",
      "at scala.concurrent.impl.Future$.apply(Future.scala:31)",
      "at scala.concurrent.Future$.apply(Future.scala:494)",
      "at play.core.j.JavaAction.apply(JavaAction.scala:170)",
      "at play.api.mvc.Action$$anonfun$apply$2.apply(Action.scala:97)",
      "at play.api.mvc.Action$$anonfun$apply$2.apply(Action.scala:90)",
      "at scala.concurrent.Future$$anonfun$flatMap$1.apply(Future.scala:253)",
      "at scala.concurrent.Future$$anonfun$flatMap$1.apply(Future.scala:251)",
      "at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:36)",
      "at akka.dispatch.BatchingExecutor$AbstractBatch.processBatch(BatchingExecutor.scala:55)",
      "at akka.dispatch.BatchingExecutor$BlockableBatch$$anonfun$run$1.apply$mcV$sp(BatchingExecutor.scala:91)",
      "at akka.dispatch.BatchingExecutor$BlockableBatch$$anonfun$run$1.apply(BatchingExecutor.scala:91)",
      "at akka.dispatch.BatchingExecutor$BlockableBatch$$anonfun$run$1.apply(BatchingExecutor.scala:91)",
      "at scala.concurrent.BlockContext$.withBlockContext(BlockContext.scala:72)",
      "at akka.dispatch.BatchingExecutor$BlockableBatch.run(BatchingExecutor.scala:90)",
      "at akka.dispatch.TaskInvocation.run(AbstractDispatcher.scala:40)",
      "at akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinTask.exec(ForkJoinExecutorConfigurator.scala:44)",
      "at akka.dispatch.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)",
      "at akka.dispatch.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339)",
      "at akka.dispatch.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)",
      "at akka.dispatch.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)"
    ],
    "data": {
      "_id": "7d89ddf5",
      "_class": "net.sf.oval.exception.ConstraintsViolatedException"
    }
  },
  "context": {
    "host": "ab0e9daca236",
    "processId": "1",
    "threadId": "mportal-akka.actor.default-dispatcher-17",
    "logger": "g.ErrorHandler"
  },
  "id": "a9d7bb3f-dd35-4c42-8fa8-68d0145ac095",
  "version": "0"
}

[vjkoskela]

Is this a production log? Test log? There are two different log modes, json and text. Depending on the objects they may produce very different output.

[cwbriones]

This is a log from a local instance running during integration tests, although I have seen similar logs during unit tests as well.