Does not display error log on AppEngine

[k2wanko]

Description

Does not display error log in Terminal and AppEngine console.
The solution is to replace to google.golang.org/appengine/log

Expected behaviour

google.golang.org/appengine/log

Actual behaviour

github.com/labstack/gommon/log

log:

{"time":"2016-08-20T03:23:35+09:00","level":"ERROR","prefix":"echo","file":"echo.go","line":"230","message":"BadRequest"}

Steps to reproduce

$ go run helloworld.go // this work.
$ goapp serve // dose not work.

Working code to debug

package main

import (
    "net/http"

    "github.com/labstack/echo"
    "github.com/labstack/echo/engine/standard"
    "github.com/labstack/gommon/log"
)

func init() {
    e := echo.New()
    e.SetLogLevel(log.ERROR)
    e.GET("/", func(c echo.Context) error {
        return echo.NewHTTPError(400, "BadRequest")
    })
    s := standard.New("")
    s.SetHandler(e)
    http.Handle("/", s)
}

func main() {
    http.ListenAndServe(":8080", nil)
}

application: helloworld
version: 1
runtime: go
api_version: go1

handlers:
- url: /.*
  script: _go_app

Version/commit

go version go1.6.2 (appengine-1.9.40) darwin/amd64

[vishr]

@k2wanko gommon/log just write to os.Stdout for appengine? How about standard log does that work?

[k2wanko]

@vishr Write to os.Stdout is not output in goapp serve.

$ goapp serve
INFO     2016-08-19 19:09:29,460 devappserver2.py:769] Skipping SDK update check.
INFO     2016-08-19 19:09:29,516 api_server.py:205] Starting API server at: http://localhost:58892
INFO     2016-08-19 19:09:29,521 dispatcher.py:197] Starting module "default" running at: http://localhost:8080
INFO     2016-08-19 19:09:29,524 admin_server.py:116] Starting admin server at: http://localhost:8000
/usr/local/Cellar/app-engine-go-64/1.9.40/share/app-engine-go-64/google/appengine/tools/devappserver2/mtime_file_watcher.py:115: UserWarning: There are too many files in your application for changes in all of them to be monitored. You may have to restart the development server to see some changes to your files.
  'There are too many files in your application for '
INFO     2016-08-19 19:09:45,643 module.py:788] default: "GET / HTTP/1.1" 400 10

[vishr]

Can you set output?

[k2wanko]

Can output if use google.golang.org/appengine/log

package main

import (
    "net/http"

    "google.golang.org/appengine"
    aelog "google.golang.org/appengine/log"

    "github.com/labstack/echo"
    "github.com/labstack/echo/engine/standard"
    "github.com/labstack/gommon/log"
)

func init() {
    e := echo.New()
    e.SetLogLevel(log.ERROR)
    e.GET("/", func(c echo.Context) error {
        ctx := appengine.NewContext(c.Request().(*standard.Request).Request)
        err := echo.NewHTTPError(400, "BadRequest")
        aelog.Errorf(ctx, "IndexError: %v", err)
        return err
    })
    s := standard.New("")
    s.SetHandler(e)
    http.Handle("/", s)
}

func main() {
    http.ListenAndServe(":8080", nil)
}

log:

$ goapp serve
INFO     2016-08-19 19:26:30,900 devappserver2.py:769] Skipping SDK update check.
INFO     2016-08-19 19:26:30,954 api_server.py:205] Starting API server at: http://localhost:60610
INFO     2016-08-19 19:26:30,960 dispatcher.py:197] Starting module "default" running at: http://localhost:8080
INFO     2016-08-19 19:26:30,965 admin_server.py:116] Starting admin server at: http://localhost:8000
/usr/local/Cellar/app-engine-go-64/1.9.40/share/app-engine-go-64/google/appengine/tools/devappserver2/mtime_file_watcher.py:115: UserWarning: There are too many files in your application for changes in all of them to be monitored. You may have to restart the development server to see some changes to your files.
  'There are too many files in your application for '
2016/08/19 19:26:36 ERROR: IndexError: BadRequest
INFO     2016-08-19 19:26:36,660 module.py:788] default: "GET / HTTP/1.1" 400 10

[dinoboff]

Would disabling logging and using a custom HTTPErrorHandler works?

The issue is the Echo Logger interface is not compatible with app engine logger (which require a golang 1.6 Context). Echo need to either let a middleware set a Logger for each request or change the Logger interface methods to have a Echo Context parameter.

[dinoboff]

To log the http error in app engine:

package hello

import (
    "net/http"

    "github.com/labstack/echo"
    "google.golang.org/appengine"
    "google.golang.org/appengine/log"
)

func init() {
    e := echo.New()

    e.HTTPErrorHandler = GaeHTTPErrorHandler
    e.GET("/", func(c echo.Context) error {
        return echo.NewHTTPError(400, "BadRequest")
    })

    http.Handle("/", e)
}

// GaeHTTPErrorHandler decorates default error handler by logging HTTP error using appengine/log.
func GaeHTTPErrorHandler(err error, c echo.Context) {
    ctx := appengine.NewContext(c.Request())
    log.Errorf(ctx, "HTTP error: %s", err)

    c.Echo().DefaultHTTPErrorHandler(err, c)
}

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.