Play Java logs errors before calling the Global.onError method

[Donja Crta]

Hello all,

We are using Play 2.14 for java.
We are doing some error handling with our own exceptions which we than catch in the onError method and return responses based on that. That saves us a lot of repetitive code like:

if(userForm.hasErrors()) {
    return badRequest(form.render(userForm));
} else {
    User user = userForm.get();
    return ok("Got user " + user);
}

We just have a generic method that accepts a form, and if a form is not good we throw an BadRequest exception which inherits from UsefulException.
We then return 400 with a message.

The problem is that the framework logs the excpetion in log before it gives us the control. So the exception is logged and then method onError is called. We don't know what to do about it. The logs just get poluted by exceptions that we throw.
Is this a bug or a feature?
Why would you log an exception before giving it to the code that is supposed to handle it. It makes no sense to me.

Is there any way to prevent this behavior?

Kind regards
M.

[James Roper]

Exceptions are not meant to be used in Play for flow control.

--
You received this message because you are subscribed to the Google Groups "play-framework" group.
To unsubscribe from this group and stop receiving emails from it, send an email to play-framewor...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.

--

James Roper
Software Engineer

Typesafe – Build reactive apps!
Twitter: @jroper

[Donja Crta]

Thanks for your reply. But i think you focused on the wrong part of the topic.

The real question is why is the framework logging exceptions before calling the method that is supposed to handle them?

Shouldn't it be better if we could decide for ourselves whether we want to log it or not?

Could somebody explain the reasoning about the decision to always log exceptions?

Thanks in advance.

[Peter Empen]

It seems also to me that your approach is no good practice. The framework has to handle exceptions if you don't do it YOURSELF BEFORE sending your response. Afaics, onError has the single purpose to render a response in case an EXCEPTION HAS OCCURED, in other words it's not meant to be an exception handler. Maybe the name of this function is not best selected but you sure get it.

You could also replace if-else in you controllers anytime by a function of your own thus achieving what you aim: DRY, right? Alternative for formal parameters would then be: (form), (form, play.libs.F.Callback)...

Also, throwing exceptions for non-error handling is genrally a bad idea because a) it's expensive in terms of JVM execution time and b) it increases side effects in your program making it less maintainable.

Peter

[virtualeyes]

Agreed, but there's another side effect: bloated log.

I have a try catch block in my Global.scala to validate an inbound 8 digit URI date param (that passes the basic routes validation) and convert to a Joda DateTime.

Would be nice to log a concise message to the logs on date conversion error, but as it stands I get megs and megs of useless stacktraces (users try all sorts of date manipulations to bypass current season login requirement).

Might not be a Play issue, but this has been the out of the box experience without setting up a custom logging solution.

[Guillaume Bort]

Yes the onError callback should be only called for UNEXPECTED cases. Managed exceptions should be handled at the controller layer. 

If something really unexpected happen in your application, Play logs the exception and call onError only to inform you that's something unexpected happened and get the HTTP response that should be served to the client (typically a 500, something bad happened message). 

--

You received this message because you are subscribed to the Google Groups "play-framework" group.
To unsubscribe from this group and stop receiving emails from it, send an email to play-framewor...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.

--

Guillaume Bort, @guillaumebort – http://guillaume.bort.fr

[Donja Crta]

Ok I consider my question answered. You think it is a feature that a user cannot log his own exceptions. I find that very strange. I bet most of java people coming from known frameworks will find that strange too.

I think if you really think of getting java people on board, than you should look at what java framework do at this day for developers, and do better, or the same NOT worse for everyday tasks like validating and such.

In the state this is right now in some areas today it looks like a step back.

Good luck.

Ciao

[Peter Empen]

Sorry but I'm convinced that there is a serious misunderstanding here:

The default logger implementation in the Play Framework is LogBack so you may configure LogBack according to your needs as you can in any other Java app. You may also configure LogBack not to log your specific exception.

Each framework has to decide at what point it captures unhandled exceptions. This is a pure design decision having nothing to do with languages. Your problem is that the place you insist to handle your exception is not properly selected in terms of the framework design.

Btw., I'm a Play for Java user at my company and so far no Java people have this kind of issue.

Peter

[Donja Crta]

Nobody is saying anything about languages. I am saying that java frameworks have a way of handling the exceptions in one place in the code. Exceptions are not meant there to be blow control tool too but excpetion handlers are still useful. If you look at Spring MVC there is one, jax-rs has one, etc. etc.
Spring MVC for instance lets you write something like this:

public Something myMethod(@RequestParam(required=true, name="bla") String bla, @PathParam String bla2)...

And that required=true is enough to save you one call of calling myForm.hasErrors() to check if there are required parameters that are not there.

The code that is actually logging the exception is in Application.scala

catch {
    case NonFatal(e) => try {
      Logger.error(
        """
        |
        |! %sInternal server error, for (%s) [%s] ->
        |""".stripMargin.format(e match {
          case p: PlayException => "@" + p.id + " - "
          case _ => ""
        }, request.method, request.uri),
        e
      )
      global.onError(request, e)
    } catch {
      case NonFatal(e) => DefaultGlobal.onError(request, e)
    }

Logger.error is called first and then global.onError
So the log that is being generated starts with 
"Internal server error, for" if somebody can tell me how to make this logger shut up i will be more than greatful.

Regards,
M.

[Donja Crta]

And i have found a solution. Here it goes:

    @Override
    public Action onRequest(Http.Request request, Method method) {
            return new Action.Simple() {

                @Override
                public Result call(Context ctx) throws Throwable {
                    try {
                        return delegate.call(ctx);
                    } catch (final Throwable e) {
                        //do error handling code here
                    }
                }

            };
    }
Its not pretty but it work.
Maybe somebody else finds this useful.

Ciao.
M.

[Guillaume Bort]

On Thu, Oct 3, 2013 at 11:17 PM, Donja Crta <crta...@gmail.com> wrote:

Its not pretty but it work.

Actually it's exactly the way it is intended to be used: Action composition is the way to compose logic in Play framework, and it's just functional composition 

(you can read more about the way we thought about Web functional programming for Play 2 in the Sadek's blog post at http://engineering.linkedin.com/play/play-framework-democratizing-functional-programming-modern-web-programmers)

I know it's not pretty because Java is not a functional language and we have to defined anonymous classes everywhere to handle this functional composition. But it should be syntactically simpler soon with the Java 8 lambda.  

[virtualeyes]

Peter, thanks for the clue, so we can catch a custom exception:
try { foo } catch {case e: MyLogBloatingException => ... }

and in a custom LogBack config ignore it?

Guess it's time to dive into LogBack docs, single application.log is not easily parsed when it's filled with junk...

On Thursday, October 3, 2013 8:40:57 AM UTC+2, Peter Empen wrote:

[Eric Mason]

That's all fine and good, but, at least in Java, there are legitimate reasons for using the Global Settings to handle errors without having Play do it's own error logging. Being able to decide what kind of error should actually be logged as an error and what type of error would be acceptable as a warning is pretty useful when you're using an error monitoring service that reads from your logs and sends out alerts when errors are encountered (least you be unnecessarily spammed and miss the critical errors). Yes, ideally, this would be handled at a lower level, but for a number of reasons that isn't always desirable (i.e. maintainability concerns, java syntactic clutter, etc.).

The project I'm currently working on wraps errors generated by our API under a common category of exception and we would like to handle these errors and demonstrate an appropriate json-output from a common location (i.e the Global Settings). Errors can be potentially be encountered in our API Authentication Actions/our Controllers, or our services called upon by our Controllers. Unfortunately, this has resulted in an flood of errors to our alerting system despite the fact we're able to handle them just fine, which is completely unacceptable.

This only leaves us with one undesirable choice for handling theses errors without messing up our logs:

Handling/rendering the output for these errors in all of our actions/controllers/async result mappings/plus the global settings (for anything we miss) (a pretty poor approach for maintainability and separation of concerns)

The alternative discussed here "creating an Action to wrap and handle errors" falls apart if your controller uses async results, because the local context coming out of the async result won't be the same as the one going in. So any errors thrown in the async result gets bubbled back up to the Global Settings rather to the action that wrapped the original request. 

It makes sense to me that you should be able to handle the logging for errors that are caught by this handler however you like if you have chosen to override the method. I really don't see why this:

catch {
    case NonFatal(e) => try {
      Logger.error(
        """
        |
        |! %sInternal server error, for (%s) [%s] ->
        |""".stripMargin.format(e match {
          case p: PlayException => "@" + p.id + " - "
          case _ => ""
        }, request.method, request.uri),
        e
      )
      global.onError(request, e)
    } catch {
      case NonFatal(e) => DefaultGlobal.onError(request, e)
    }

can't be something like this:

catch {
    case NonFatal(e) => try {

      global.onError(request, e)
    } catch {

      Logger.error( "Unhandled Internal Server Error" ... )

      case NonFatal(e) => DefaultGlobal.onError(request, e)
    }

Or better yet leave it to the DefaultGlobal.onError to do the error logging. Then at least you would only have error logging for "Unhandled Errors" rather than the "Handled Unexpected Errors" that are being logged now.

[Gösen Jojjasson]

I also think it's a bug (or at least a very non-flexible and unwanted feature) in Play to log the error (in a very specific format) before calling onError().

Just move the logging statement to the standard implementation of onError().

Users liking the logging don't have to do anything, it will by default be as the Play developers designed. But if another user want to change the logging they can override the onError().

Simple as that.

Best regards,

Gösta

[James Roper]

This has already been fixed on master:

https://github.com/playframework/playframework/commit/6d9311703f695574d005fffc72caa210aa8a1c16#diff-abe8627ccfb12f318fb2dc017144dde0R177

For more options, visit https://groups.google.com/d/optout.

[Gösta Jonasson]

That's great James, thanks a lot!

I'm not sure I understand your branch strategy/release process. When/in which version will this be released? 

In 2.4.0? And will that be released somewhere in the beginning of 2015?

Best regards,

Gösta

--
You received this message because you are subscribed to a topic in the Google Groups "play-framework" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/play-framework/YSASFRpATTQ/unsubscribe.
To unsubscribe from this group and all its topics, send an email to play-framewor...@googlegroups.com.

[James Roper]

On Wed, Oct 22, 2014 at 7:29 PM, Gösta Jonasson <gos...@gmail.com> wrote:

That's great James, thanks a lot!

I'm not sure I understand your branch strategy/release process. When/in which version will this be released? 

Anything in master will be in the next stable release - which is 2.4.

 

In 2.4.0? And will that be released somewhere in the beginning of 2015?

Hopefully, but we can't promise anything.

[Don Bellenger]

Actually, the solution of overriding the GlobalSettings.OnRequest method has issues. Because actions are executed at the local level first, controller level second, and lastly on the global level, you won't be able to catch exceptions that happen in annotated actions. This becomes a really big issue if your actions do things that are significant, like authenticating with other services.

https://groups.google.com/forum/#!topic/play-framework/AY4NuQziYyM

don