Error log at login/consent cancelation

[sawadashota]

Describe the bug

Currently, logs error when user cancels login/consent.
I think this is not error because it's not unexpected.

Reproducing the bug

Steps to reproduce the behavior:

1. Start Authorization Code Flow
2. Cancel login or consent as user action
3. Error logs appear

Server logs

This is public hydra server logs after cancel login.
In production, of course, debug log at line 3 is not appeared.

{"level":"info","method":"GET","msg":"started handling request","remote":"192.168.0.1","request":"/oauth2/auth?client_id=test-client\u0026code_challenge=_yPeZyFMd0eHOCA0TM33fJim0gfSm14ntygeePGla7s\u0026code_challenge_method=S256\u0026login_verifier=d6383f4d691047beaac7c10ab39f50e8\u0026nonce=m7lPX3Df-SJ5ngrh9xZocWaWrpmegmwOpWps\u0026prompt=\u0026redirect_uri=https%3A%2F%2F127.0.0.1%3A3030%2Fcallback\u0026response_type=code\u0026scope=openid+profile+email\u0026state=R1hS4yv7IbY0xTqvOifqlg%3D%3D","time":"2020-06-17T00:31:16Z"}
{"description":"user canceled login","error":"canceled","level":"error","msg":"An error occurred","time":"2020-06-17T00:31:16Z"}
{"level":"debug","msg":"Stack trace: \ngit.luolix.top/ory/hydra/consent.(*DefaultStrategy).verifyAuthentication\n\t/go/src/github.com/ory/hydra/consent/strategy_default.go:345\ngit.luolix.top/ory/hydra/consent.(*DefaultStrategy).HandleOAuth2AuthorizationRequest\n\t/go/src/github.com/ory/hydra/consent/strategy_default.go:970\ngit.luolix.top/ory/hydra/oauth2.(*Handler).AuthHandler\n\t/go/src/github.com/ory/hydra/oauth2/handler.go:624\ngit.luolix.top/julienschmidt/httprouter.(*Router).ServeHTTP\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v1.2.0/router.go:334\ngit.luolix.top/urfave/negroni.Wrap.func1\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:46\ngit.luolix.top/urfave/negroni.HandlerFunc.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:29\ngit.luolix.top/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2012\ngit.luolix.top/ory/hydra/x.RejectInsecureRequests.func1\n\t/go/src/github.com/ory/hydra/x/tls_termination.go:83\ngit.luolix.top/urfave/negroni.HandlerFunc.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:29\ngit.luolix.top/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngit.luolix.top/ory/x/metricsx.(*Service).ServeHTTP\n\t/go/pkg/mod/github.com/ory/x@v0.0.111/metricsx/middleware.go:261\ngit.luolix.top/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngit.luolix.top/ory/hydra/metrics/prometheus.(*MetricsManager).ServeHTTP\n\t/go/src/github.com/ory/hydra/metrics/prometheus/middleware.go:26\ngit.luolix.top/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngit.luolix.top/ory/x/reqlog.(*Middleware).ServeHTTP\n\t/go/pkg/mod/github.com/ory/x@v0.0.111/reqlog/middleware.go:140\ngit.luolix.top/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngit.luolix.top/urfave/negroni.(*Negroni).ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:96\nnet/http.serverHandler.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2807\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1895\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1373","time":"2020-06-17T00:31:16Z"}
{"level":"info","measure#hydra/public: https://127.0.0.1:8080/.latency":6309900,"method":"GET","msg":"completed handling request","remote":"192.168.0.1","request":"/oauth2/auth?client_id=test-client\u0026code_challenge=_yPeZyFMd0eHOCA0TM33fJim0gfSm14ntygeePGla7s\u0026code_challenge_method=S256\u0026login_verifier=d6383f4d691047beaac7c10ab39f50e8\u0026nonce=m7lPX3Df-SJ5ngrh9xZocWaWrpmegmwOpWps\u0026prompt=\u0026redirect_uri=https%3A%2F%2F127.0.0.1%3A3030%2Fcallback\u0026response_type=code\u0026scope=openid+profile+email\u0026state=R1hS4yv7IbY0xTqvOifqlg%3D%3D","status":302,"text_status":"Found","time":"2020-06-17T00:31:16Z","took":6309900}

Expected behavior

Don't log error because this is user's intentional action.

Environment

• Version: v1.4.9
• Environment: Docker

Additional context

Related source codes are here.

Handler

hydra/oauth2/handler.go

Lines 630 to 638 in 4bfbddb

	session, err := h.r.ConsentStrategy().HandleOAuth2AuthorizationRequest(w, r, authorizeRequest)
	if errors.Cause(err) == consent.ErrAbortOAuth2Request {
	// do nothing
	return
	} else if err != nil {
	x.LogError(r, err, h.r.Logger())
	h.writeAuthorizeError(w, r, authorizeRequest, err)
	return
	}

Login cancel

hydra/consent/strategy_default.go

Lines 343 to 346 in 8967b9c

	if session.HasError() {
	session.Error.SetDefaults(loginRequestDeniedErrorName)
	return nil, errors.WithStack(session.Error.toRFCError())
	}

Consent cancel

hydra/consent/strategy_default.go

Lines 582 to 585 in 8967b9c

	if session.HasError() {
	session.Error.SetDefaults(consentRequestDeniedErrorName)
	return nil, errors.WithStack(session.Error.toRFCError())
	}