Iris: [QUESTION]can logger write to multiple files asynchronously and rotate based on size or time?

Created on 20 Aug 2020  ·  57Comments  ·  Source: kataras/iris

I need to write different level to different file
for example：
INFO & WARN level write toinfo.log
ERRO level write to error.log
In addition, I need to save the access log including request params and response data to access.log

If the log files become more and more large, I expect that logger can automatically rotate the log files based on size or time

Does logger support the requirements above and write file asynchronously？

question implemented idea
Source
picture tuhao1020

All 57 comments

Personally, I would use https://linux.die.net/man/8/logrotate for this purpose, it is a standard *nix tool included in even microkernels since the dawn of Linux time. That being said, if you're not on Linux the story is different. -- That and it only answers a portion of your question.

Also, logrotate generally requires that the application be able to re-open log files with a HUP signal, or similar action.

An example of such configuration would be:

$ cat /etc/logrotate.d/myapp
/wherever/your/app/something.log {
    size 1m
    copytruncate
    create 660 yourname yourname
    rotate 4
    compress
    missingok
}

You can find more information about this tool here

AlbinoGeek picture AlbinoGeek on 21 Aug 2020

@AlbinoGeek my server may run on windows, so I want to find a cross platform solution, but also thank you!

tuhao1020 picture tuhao1020 on 21 Aug 2020

@tuhao1020 You may be interested in LogRotateWin or Powershell Methods

AlbinoGeek picture AlbinoGeek on 21 Aug 2020

Hello @tuhao1020 have you seen https://github.com/kataras/golog/tree/master/_examples/rotation? Maybe you can use something like that, if that's not the case I think we can add a feature there per-level io.Writer so you can add different files, although you can already do that by customizing the output (app.Logger().Handle the Log by yourself and change the writers based on the level), there is an example of that here: https://github.com/kataras/golog/blob/master/_examples/customize-output/main.go.

@AlbinoGeek check the messages in https://chat.iris-go.com I sent you two documentation PDF files of the two latest features in master branch that may be useful for your application.

kataras picture kataras on 21 Aug 2020

@kataras I'll try the examples, but if possible, I recommend supporting built-in multiple log file output per level.

Is there built-in support for access log?

tuhao1020 picture tuhao1020 on 21 Aug 2020

By access log you mean request logger @tuhao1020 ?

but if possible, I recommend supporting built-in multiple log file output per level.

It's easy to do it by yourself, less than 12 code of lines but maybe I should add an example of that too.

kataras picture kataras on 21 Aug 2020

@kataras yes, I want to record all the request in access.log file including request parameters and returned json data

tuhao1020 picture tuhao1020 on 21 Aug 2020

@tuhao1020 and returned json data you mean the response body sent to those clients or the request data they send?

So you want:

  • different files for each log level on the Application-level logs
  • an access.log file for the request logs (the requests are logged through the app.Logger().Info, so it uses the application logger, you can customize each log variable by https://github.com/kataras/iris/blob/e41e861c4c0d9be9dd4c88f7e06c2732b52ba60d/middleware/logger/config.go#L83-L86, however we can also add a Logger field there for the case you need to use a customized golog.Logger instance)
  • that access.log should contain response body too, golog supports WithFields that are available to its Handlers (see my previous post).

I have one question, what's the format of the access.log file? Can you give me an example of a logged requested so I can design it?

About the rotation, @AlbinoGeek is right, rotation is out of scope of this library and there are better builtin tools exist for years to do that, see his answer and also navigate to the link I gave you above.

Thanks

kataras picture kataras on 21 Aug 2020

access.log is just a simple text file, user can customize the log fields, every record is written in one line.
my access.log looks like this(timestamp|latency|endpoint|querystring|statusCode|response|):

2020/08/22 04:03:35|6ms|/uses||200|[{"id":10,"name":"Tim", "age":22},{"id":11,"name":"Alice", "age":23}]|
2020/08/22 04:03:47|4ms|/uses|id=10|200|[{"name":"Tim", "age":22}]|
2020/08/22 04:04:04|2ms|/invalidroute|id=10|404||
tuhao1020 picture tuhao1020 on 21 Aug 2020

@tuhao1020 That's easy, we don't need to add a feature for that, you can already do that and there are two examples available. However I am writing one just for you :) NOTE: you want |response| OR the REQUEST data the client send to the server?

EDIT: I added both, here you are: https://github.com/kataras/iris/blob/master/_examples/logging/request-logger/request-logger-access-log-file/main.go

access.log sample:

```text
2020-08-22 00:44:20|993.3µs|POST|/read_body||200|{"id":10,"name":"Tim","age":22}|{"message":"OK"}|
2020-08-22 00:44:30|0s|POST|/read_body||400||error(invalid character 'a' looking for beginning of object key string)||
2020-08-22 03:02:41|1ms|GET|/|a=1 b=2|200||

Hello index

|
2020-08-22 03:15:29|968.8µs|GET|/public|file=public|404|||
2020-08-22 03:03:42|0s|GET|/user/kataras|username=kataras|200||Hello, kataras!|
2020-08-22 03:05:40|0s|GET|/user/kataras|username=kataras a_query_parameter=name|200||Hello, kataras!|
````

Also check a new answer I got for you on a previous issue of yours at: https://github.com/kataras/iris/issues/1596#issuecomment-675687668

kataras picture kataras on 21 Aug 2020

Ahh yeah, this looks very similar to the Apache HTTPd or Microsoft IIS7+ access_log mod at this point, I see the motivation now.

AlbinoGeek picture AlbinoGeek on 22 Aug 2020

Yeah I though Apache too when I first saw it :D. Preparing an example to push ~which will contain url parameters and path parameters too~, maybe we can add a different middleware for that sole prupose? so users can wrap it on their own rotation lib?

kataras picture kataras on 22 Aug 2020

@kataras Thanks! That's exactly what I want.
@AlbinoGeek Thank you too!

Do you agree that the above samples are a little complicated for beginners? :)
Log is the infrastructure of software system, for application devolopers(like me), they prefer the out of the box feature for rapid development.
I expect Iris to provide a simpler and more powerful log system. :)

tuhao1020 picture tuhao1020 on 22 Aug 2020

Hello @tuhao1020, you are welcome! About the coplicated or not... yes for beginner I would assume that is not an easy task to do, hoever the API is there and you can do whatever you want with Iris if you know what to do.

So, you are on the idea to push that on its own middleware or add an option to the existing request logger one or keep it in the same package but initialize it with logger.NewAccessLog("file")?

kataras picture kataras on 22 Aug 2020

@kataras yes, I would prefer the logger apis like below:

logger.SetLevelOutput("warn", "./log", "info.log")   // level <= warn will log to ./log/APPNAME-20200822112358.info.log
logger.SetLevelOutput("erro", "./log", "error.log")  // level == erro will log to ./log/APPNAME-20200822112358.error.log

// log file rotate setting
logger.EnableRotate(rotation.WithMaxAge(24 * time.Hour).WithMaxSize(100 * 1024 * 1024))

// set output type such as text, json..., this setting will valid for all log levels
logger.SetOutputType(logger.JSON)

// access log is not enabled by default
logger.EnableAccessLog("./log", "access.log")

// supply some pre-defined field patterns
// for example: %time bind to request timestamp with format 2006/01/02 15:04:05, %header.referer bind to ctx.GetHeader("referer")
logger.SetAccessLogFields("%time", "%latency", "%statusCode", "%header.referer")

// valid for text output only, ignored this setting for json output
logger.SetAccessLogFieldsSeperator("|")
tuhao1020 picture tuhao1020 on 22 Aug 2020

@tuhao1020 My only concern is:

https://en.wikipedia.org/wiki/Separation_of_concerns

That being said, a different accessLogger package seems like a great candidate for some of this functionality.

As per your requests for SetLevelOutput, EnableRotate and SetOutputType those would be canidates for golog (the logging package also written by @kataras, that iris happens to use for its logging. For more information on what you can customize about golog, consider checking out its page:

https://github.com/kataras/golog

Of note, SetHandler already appears to let you change the format to JSON, and there is a concept of "multiple logging outputs", but I do not know if you can filter these outputs (for example, as you ask, to show one log level per file.)

AlbinoGeek picture AlbinoGeek on 23 Aug 2020

@AlbinoGeek I agree with the separation of concerns. I just expect that the log libaray which iris depends on has those feature s that I mentioned.

In the spring(spring boot) ecosystem, it provides a very powerful and easy-to-use log component, I hope you can think about it and bring it to Iris. @kataras

tuhao1020 picture tuhao1020 on 24 Aug 2020

Hello @tuhao1020, @AlbinoGeek

All the features discussed can already implemented with the current golog exported functionality, even to write a file per log level (use the handler inside a struct which prints based on the golog.Level, e.g. map[golog.Level]io.Writer, it's easy see next post comment).

// set output type such as text, json..., this setting will valid for all log levels
logger.SetOutputType(logger.JSON)

EDIT: see the next comment on this post issue, the answer has been updated, a new Formatter introduced, one level higher than the Handler below.

Example Code:

import "github.com/kataras/golog"

func jsonOutput(l *golog.Log) bool {
    enc := json.NewEncoder(l.Logger.GetLevelOutput(l.Level.String()))
    enc.SetIndent("", "    ")
    err := enc.Encode(l)
    return err == nil
}

// [...Register it] 
app.Logger().Handle(jsonOutput)

I also agree with separation of concerns, that's why I think we can implement something in a totally new package. However, the implementation of different file per level, rotation and e.t.c cannot be implemented just for the request logger, the request logger has a single level (info) so I think @tuhao1020 asked that for the whole application's logger, this feature is easy to design, as said before, manually but we can add helper functions inside the golog package itself (same for the JSON output and e.t.c.)

// supply some pre-defined field patterns
// for example: %time bind to request timestamp with format 2006/01/02 15:04:05, %header.referer bind to ctx.GetHeader("referer")
logger.SetAccessLogFields("%time", "%latency", "%statusCode", "%header.referer")

I don't like this, what that means?:

  • is it format ? no
  • what would be their title names if JSON output selected?
  • it binds? meaning that the | characters will not be visible on not-set fields?
  • what %header.referer means and why not configuration fields like: Referer bool or HeaderKeys []string{"Referer", ...}?

// access log is not enabled by default
logger.EnableAccessLog("./log", "access.log")

This cannot be lived inside the app.Logger() because it is only useful for http/request logging, the golog package is a general purpose leveled logger. Instead, it should be registered like the current request logger, e.g accesslog.New(...).

// log file rotate setting
logger.EnableRotate(rotation.WithMaxAge(24 * time.Hour).WithMaxSize(100 * 1024 * 1024))

About log rotation, I am not an expert on that field, I can learn fast, I can design APIs to be as developer-friendly as possible but...I still believe that there are software out there (especially in unix world) that are tested for years and developers are already familiar with those. However, if @tuhao1020 insists that such a feature should live inside Iris ecosystem, I can give it a try, this will live in the golog package though, which can be developed and tested Iris-independently (app.Logger().EnableRotation(...).

kataras picture kataras on 6 Sep 2020

@AlbinoGeek @tuhao1020

A new accesslog middleware is available. Example. It does what the example above was plus some options, it is a work in progress as we have to add more features.

Also, the latest Iris commit depends on the golog v0.1.5 which contains the following new methods:

  • Logger.RegisterFormatter(Formatter) to register a custom Formatter.
  • Logger.SetFormat(formatter string, opts ...interface{}) to set the default formatter for all log levels.
  • Logger.SetLevelFormat(levelName string, formatter string, opts ...interface{}) to change the output format for the given "levelName".
  • Logger.SetLevelOutput(levelName string, w io.Writer) to customize the writer per level.
  • Logger.GetLevelOutput(levelName string) io.Writer to get the leveled output or the default one.

Formatter Example Code:

app := iris.New()
app.Logger().SetFormat("json", "     ")
app.Logger().SetLevelFormat("error", "json", "  ")
// [...]

Level Output Example Code:

app := iris.New()
logger := app.Logger()

// output error level to os.Stderr, the rest remains the same (os.Stdout by default):
// (use `io.MultiWriter` wrapper to set more than one writer to a single level).
logger.SetLevelOutput("error", os.Stderr)
// output info level to "info.log" file:
infoFile, err := os.OpenFile("info.log", os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0666)
if err != nil {
    panic(err)
}
defer infoFile.Close()
logger.SetLevelOutput("info", infoFile)


logger.Error("An errormessage") // outputs to the os.Stderr

logger.Info("An info message")
// info.log contains:
// [INFO] 2020/09/06 12:01 An info message
kataras picture kataras on 6 Sep 2020

@kataras Great! Thanks! 👍

tuhao1020 picture tuhao1020 on 7 Sep 2020

@tuhao1020 you are welcome. The only thing missing it's the rotation but we don't have to implement it, we already have an example of using rotation with logs:

import (
  rotatelogs "github.com/lestrrat-go/file-rotatelogs"

  "github.com/kataras/iris/v12"
  "github.com/kataras/iris/v12/middleware/accesslog"
)

// [...]

pathToAccessLog := "./access_log.%Y%m%d%H%M"
w, err := rotatelogs.New(
    pathToAccessLog,
    rotatelogs.WithMaxAge(24*time.Hour),
    rotatelogs.WithRotationTime(time.Hour))

// For application logger:
// app.Logger().SetOutput(w)
// For access log middleware:
ac := accesslog.New(w) // override (after Handler): ac.SetOutput(io.Writer)
// ac.AddOuput(os.Stdout) add a second output. 
// ^ The io.MultiWriter(w, os.Stdout) could be used instead.

app.UseRouter(ac.Handler)
kataras picture kataras on 7 Sep 2020

@kataras Thanks for your example. I'am trying the lestrrat-go/file-rotatelogs too. This library doesn't supply a WithMaxSize option，I have created a PR, but nobody reviewed and merged :(

tuhao1020 picture tuhao1020 on 7 Sep 2020

I see @tuhao1020, until then, I've added more features to the accesslog. It has its own SetFormatter now as its new Log instance contains request-specific log information. I also added an Async bool field which can be turned on if you want the logging to happen after the request-response lifecycle is done - which makes registering the middleware with almost zero cost to the overall user experience/performance. The accesslog has two formatters, the (tab) writer (default) (as you proposed in your first example, the current implementation) and the JSON one. Also, keep in touch because I am working on a new Fields map[string]interface{} field which will give you the chance to set custom data (e.g a specific header or all the headers) to the log.

kataras picture kataras on 7 Sep 2020

The new features looks very nice, I'm a bit busy recently, and I'll try these new features later at the end of the month, if there is any question or issue I'll give you a feedback. Thanks for your excellent work！

tuhao1020 picture tuhao1020 on 7 Sep 2020

This library doesn't supply a WithMaxSize option，I have created a PR, but nobody reviewed and merged :(

You don't have to wait. Why not fork it and use it to your own projects? The accesslog.New and *AccessLog.SetOutput (and Iris logger) can accept any io.Writer.

The new features looks very nice, I'm a bit busy recently, and I'll try these new features later at the end of the month, if there is any question or issue I'll give you a feedback. Thanks for your excellent work！

Yes no worries, take your time and if you need anything just talk to me in chat. I thank you for the initial idea! I am always trying to do my best for our users.

kataras picture kataras on 7 Sep 2020

OK @tuhao1020 @AlbinoGeek with the latest commit I think we are in a good state with the new accesslog middleware.

You can now customize the entire log: add custom request fields, change the order of fields, set custom separators and e.t.c. using the accesslog.Template formatter. Which accepts a simple Text string for the text/template to be parsed or a custom loaded Tmpl *template.Template .

Example setting custom Fields:

ac.AddField(func(ctx iris.Context) (string, interface{}) {
  v := ctx.RemoteAddr()
  if v == "" {
    return "", nil
  }
  // the log entry name and its value.
  return "IP", v
})

Example using the Template Formatter:

ac.SetFormatter(&accesslog.Template{
  Text: "{{.Now.Format .TimeFormat}}|{{.Latency}}|{{.Method}}|{{.Path}}|{{.RequestValuesLine}}|{{.Code}}|{{.BytesReceivedLine}}|{{.BytesSentLine}}|{{.Request}}|{{.Response}}|\n",
})

The Log structure, which can be printed with json or text/template and more:

type Log struct {
  // The AccessLog instance this Log was created of.
  Logger *AccessLog `json:"-" yaml:"-" toml:"-"`

  // The time the log is created.
  Now time.Time `json:"-" yaml:"-" toml:"-"`
  // TimeFormat selected to print the Time as string,
  // useful on Template Formatter.
  TimeFormat string `json:"-" yaml:"-" toml:"-"`
  // Timestamp the Now's unix timestamp (seconds).
  Timestamp int64 `json:"timestamp"`

  // Request-Response latency.
  Latency time.Duration `json:"latency"`
  // Init request's Method and Path.
  Method string `json:"method"`
  Path   string `json:"path"`
  // The response status code.
  Code int `json:"code"`
  // Sorted URL Query arguments.
  Query []memstore.StringEntry `json:"query"`
  // Dynamic path parameters.
  PathParams []memstore.Entry `json:"params"`
  // Fields any data information useful to represent this Log.
  Fields []memstore.Entry `json:"fields,omitempty"`

  //  The actual number of bytes received and sent on the network (headers + body).
  BytesReceived int `json:"bytes_received"`
  BytesSent     int `json:"bytes_sent"`

  // The Request and Response raw bodies.
  // If they are escaped (e.g. JSON),
  // A third-party software can read it through:
  // data, _ := strconv.Unquote(log.Request)
  // err := json.Unmarshal([]byte(data), &customStruct)
  Request  string `json:"request"`
  Response string `json:"response"`

  // A copy of the Request's Context when Async is true (safe to use concurrently),
  // otherwise it's the current Context (not safe for concurrent access).
  Ctx *context.Context `json:"-" yaml:"-" toml:"-"`
}

// RequestValuesLine returns a string line which
// combines the path parameters, query and custom fields.
func (l *Log) RequestValuesLine() string {
    return parseRequestValues(l.Code, l.Ctx.Params(), l.Ctx.URLParamsSorted(), l.Fields)
}

// BytesReceivedLine returns the formatted bytes received length.
func (l *Log) BytesReceivedLine() string {
  return formatBytes(l.BytesReceived)
}

// BytesSentLine returns the formatted bytes sent length.
func (l *Log) BytesSentLine() string {
  return formatBytes(l.BytesSent)
}

Also, the field AccessLog.LockWriter is introduced, to manually lock unprotected writer outputs. The middleware will try to decide if the underline io.Writer's needs a locker or not (os.File, bytes.Buffer requires lock) However, in our example, the logrorate 3rd-party package is already protected with mutex, so this field defaults to false,

kataras picture kataras on 7 Sep 2020

OK, more things added here. Log total amount of bytes received/sent (headers+body) and you have now the ability to set custom log fields through handlers, example: https://github.com/kataras/iris/blob/fb7627256a3e7f691ec5a638cc878b6488367071/_examples/logging/request-logger/accesslog/main.go#L158-L169
Accesslog sample file:

2020-09-08 13:34:42|0s|POST|/read_body||200|324 B|217 B|{"name":"John","email":"[email protected]"}|{"data":{"email":"[email protected]","name":"John"},"message":"OK"}|
2020-09-08 13:40:28|0s|POST|/read_body||400||85 B|error(invalid character '\r' in string literal)||
2020-09-08 13:41:05|1.0024ms|GET|/|a=1 b=2|200|767 B|251 B||<h1>Hello index</h1>|
2020-09-08 13:41:26|0s|GET|/public||404|765 B|83 B|||
2020-09-08 13:41:36|0s|GET|/user/kataras|username=kataras|200|771 B|91 B||Hello, kataras!|
2020-09-08 13:41:47|0s|GET|/user/kataras|username=kataras a_query_parameter=name|200|774 B|91 B||Hello, kataras!|
2020-09-08 20:37:33|0s|GET|/admin|auth=admin:admin|200|608 B|164 B||<h2>Username: admin</h2><h3>Password: admin</h3>|
2020-09-09 07:56:00|738.1µs|GET|/session|session_id=23fe763f-c9d5-4d65-9e1a-2cc8d23d1aa3 session_test_key=session_test_value|200|818 B|302 B||OK|
2020-09-09 08:36:47|2.0095505s|GET|/fields|job_latency=2s|200|544 B|130 B||OK|

You see now.... I am really into this, you ask for x and i do x10 :D

kataras picture kataras on 9 Sep 2020

More on this with https://github.com/kataras/iris/commit/b77227a0f965e031507701901eb0b375a6483386

Log broker:
https://github.com/kataras/iris/blob/b77227a0f965e031507701901eb0b375a6483386/_examples/logging/request-logger/accesslog-broker/main.go#L17-L20

https://github.com/kataras/iris/blob/b77227a0f965e031507701901eb0b375a6483386/_examples/logging/request-logger/accesslog-broker/main.go#L57-L73

Ability to skip logging per route inside the handler: https://github.com/kataras/iris/blob/b77227a0f965e031507701901eb0b375a6483386/_examples/logging/request-logger/accesslog-broker/main.go#L55

kataras picture kataras on 9 Sep 2020

@kataras I'll take some time to try these new features recently.
My first question is: accesslog doesn't record the request which has a staus code of 404 or panic in the Hanlder

log, _ := rotatelogs.New("./%Y%m%d%H.access.log", rotatelogs.WithRotationTime(time.Hour))
ac := accesslog.New(log)
app := iris.New()
app.Use(ac.Handler)

app.Get("/panic", func(ctx iris.Context) {
    panic("oops")
})

app.Get("/hello", func(ctx iris.Context) {
    ctx.Text("hello")
})

app.Run(iris.Addr(":8080"))

if request for /hello1, it will respond with a Not Found page, but there's no record in access.log
if request for /panic, it will respond with a Internal Server Error page, but there's no record too

tuhao1020 picture tuhao1020 on 10 Sep 2020

Yes because you register it with Use, if you see the examples and the documentation, Use only runs on matched method routes, where .UseRouter runs everywhere under a particular party and its children. @tuhao1020. Please take a look at the _examples/logging/request-logger/accesslog and accesslog-broker examples.

kataras picture kataras on 10 Sep 2020

OK. I use UseRouter instead, but request for /panic still has no record in log file

tuhao1020 picture tuhao1020 on 10 Sep 2020

You mean their bodies are not recorded or the the whole line is missing? ( if only body is missing, i am aware of it, as the accesslog is registered first but calls ctx.Next and then continue its job, and on erorr handlers the handler index is reset-ed to 0, If you register it with UseError it will record their bodies too but I am working on fixing this for accesslog)

kataras picture kataras on 10 Sep 2020

the whole line is missing when panic occurs @kataras

tuhao1020 picture tuhao1020 on 10 Sep 2020

I see @tuhao1020. I am working on that.

kataras picture kataras on 10 Sep 2020

@tuhao1020 finally it's done. The recover middleware and accesslog can "communicate" now. Also both the panic cause and the error bodies are written to the log too, register the accesslog middleware like the examples, using the app.UseRouter. And if you want panic recover logs too register the recover middleware after the accesslog one. A new AccessLog.KeepMultiLineError bool was introduced as well.
Example at:

https://github.com/kataras/iris/blob/ae67987f5581a02ccb5d53c2f5f9a6e51d7ec841/_examples/logging/request-logger/accesslog-broker/main.go#L26-L27

https://github.com/kataras/iris/blob/ae67987f5581a02ccb5d53c2f5f9a6e51d7ec841/_examples/logging/request-logger/accesslog-broker/main.go#L80-L82

As a bonus we have introduced the "private errors". There are errors that you can pass to ctx.SetErr, they will be accessible through ctx.GetErr but they will NOT be printed to the client on default error handlers when custom body is missing. (iris.ErrPrivate interface, e.g type myerror struct { iris.ErrPrivate ...other fields here} and iris.IsErrPrivate(err))

kataras picture kataras on 10 Sep 2020

@kataras 👍
besides AccessLog.KeepMultiLineError, Maybe it is necessary to provide a simple error information such as AccessLog.KeepSimpleError that only keep one statck trace runtime.Caller(2)

log sample:

  • AccessLog.KeepMultiLineError = false // when this set to true, ignore AccessLog.KeepSimpleError
  • AccessLog.KeepSimpleError = false //default value is false
Thu, 10 Sep 2020 23:12:33 GMT|1.273359ms|GET|/panic||500||116 B|error(hello /usr/local/Cellar/go/1.15.1/libexec/src/runtime/panic.go:969 /Users/tuhao/GoProjects/iris-log/main.go:21 /Users/tuhao/.go/pkg/mod/github.com/kataras/iris/[email protected]/context/context.go:477 /Users/tuhao/.go/pkg/mod/github.com/kataras/iris/[email protected]/core/router/handler.go:441 /Users/tuhao/.go/pkg/mod/github.com/kataras/iris/[email protected]/core/router/router.go:110 /Users/tuhao/.go/pkg/mod/github.com/kataras/iris/[email protected]/context/context.go:612 /Users/tuhao/.go/pkg/mod/github.com/kataras/iris/[email protected]/middleware/recover/recover.go:54 /Users/tuhao/.go/pkg/mod/github.com/kataras/iris/[email protected]/context/context.go:612 /Users/tuhao/.go/pkg/mod/github.com/kataras/iris/[email protected]/middleware/accesslog/accesslog.go:377 /Users/tuhao/.go/pkg/mod/github.com/kataras/iris/[email protected]/context/context.go:477 /Users/tuhao/.go/pkg/mod/github.com/kataras/iris/[email protected]/core/router/router.go:158 /Users/tuhao/.go/pkg/mod/github.com/kataras/iris/[email protected]/core/router/router.go:322 /usr/local/Cellar/go/1.15.1/libexec/src/net/http/server.go:2843 /usr/local/Cellar/go/1.15.1/libexec/src/net/http/server.go:1925 /usr/local/Cellar/go/1.15.1/libexec/src/runtime/asm_amd64.s:1374 )|Internal Server Error|
  • AccessLog.KeepSimpleError = true // valid when AccessLog.KeepMultiLineError is false
Thu, 10 Sep 2020 22:40:39 GMT|225.491µs|GET|/panic||500||116 B|error(oops /Users/tuhao/GoProjects/iris-accesslog/main.go:21 )|Internal Server Error|
tuhao1020 picture tuhao1020 on 10 Sep 2020

@kataras yes, no need to modify the stack trace to keep only one record in the recover middleware, just find a way to filter out the starting point of panic in accesslog middleware would be ok. But I'm not sure runtime.Caller(2) is always what I want.

There're another two ideas for my current usage scenarios：

  1. add a RemoteHost string field to accesslog.Log, accesslog can record ip by default.
  1. add a CustomFields map[string]interface{} field to accesslog.Log
    for some reason, I have to add some custom fields, but I expect these custom fields can be logged separated by | like the built-in fileds such as {{.Latency}}|{{.Method}}. for example, I add a key-value {"client": "svcmgr"} to Log.CustomFields, then I can set the template pattern like this: {{index .CustomFields "client"}}
tuhao1020 picture tuhao1020 on 10 Sep 2020

@kataras 👍
besides AccessLog.KeepMultiLineError, Maybe it is necessary to provide a simple error information such as AccessLog.KeepSimpleError that only keep one statck trace runtime.Caller(2)

log sample:

  • AccessLog.KeepMultiLineError = false // when this set to true, ignore AccessLog.KeepSimpleError
  • AccessLog.KeepSimpleError = false //default value is false
Thu, 10 Sep 2020 23:12:33 GMT|1.273359ms|GET|/panic||500||116 B|error(hello /usr/local/Cellar/go/1.15.1/libexec/src/runtime/panic.go:969 /Users/tuhao/GoProjects/iris-log/main.go:21 /Users/tuhao/.go/pkg/mod/github.com/kataras/iris/[email protected]/context/context.go:477 /Users/tuhao/.go/pkg/mod/github.com/kataras/iris/[email protected]/core/router/handler.go:441 /Users/tuhao/.go/pkg/mod/github.com/kataras/iris/[email protected]/core/router/router.go:110 /Users/tuhao/.go/pkg/mod/github.com/kataras/iris/[email protected]/context/context.go:612 /Users/tuhao/.go/pkg/mod/github.com/kataras/iris/[email protected]/middleware/recover/recover.go:54 /Users/tuhao/.go/pkg/mod/github.com/kataras/iris/[email protected]/context/context.go:612 /Users/tuhao/.go/pkg/mod/github.com/kataras/iris/[email protected]/middleware/accesslog/accesslog.go:377 /Users/tuhao/.go/pkg/mod/github.com/kataras/iris/[email protected]/context/context.go:477 /Users/tuhao/.go/pkg/mod/github.com/kataras/iris/[email protected]/core/router/router.go:158 /Users/tuhao/.go/pkg/mod/github.com/kataras/iris/[email protected]/core/router/router.go:322 /usr/local/Cellar/go/1.15.1/libexec/src/net/http/server.go:2843 /usr/local/Cellar/go/1.15.1/libexec/src/net/http/server.go:1925 /usr/local/Cellar/go/1.15.1/libexec/src/runtime/asm_amd64.s:1374 )|Internal Server Error|
  • AccessLog.KeepSimpleError = true // valid when AccessLog.KeepMultiLineError is false
Thu, 10 Sep 2020 22:40:39 GMT|225.491µs|GET|/panic||500||116 B|error(oops /Users/tuhao/GoProjects/iris-accesslog/main.go:21 )|Internal Server Error|

I've just pushed a commit, giving 3 levels on access log:

https://github.com/kataras/iris/blob/2bb04823b03f1aba0bb357d957ee047a17efce57/middleware/accesslog/accesslog.go#L163-L169

LogHandler, LogCallers and LogStack for the AccessLog.PanicLog field.

  • LogHandler: log the error + file:line of the handler was recovered from
  • LogCallers: log the error + the functions callers (if KeepMultilineError is false then as a single line)
  • LogStack: log the error + the full debug stack (if KeepMultilineError is false then as a single line)

Usage:

https://github.com/kataras/iris/blob/2bb04823b03f1aba0bb357d957ee047a17efce57/_examples/logging/request-logger/accesslog-broker/main.go#L20-L28

Also the recover middleware stores all these info in a "private" error of ErrPanicRecovery (not sent to the client but you are able to ctx.GetErr it after a recovery).

kataras picture kataras on 10 Sep 2020

@kataras yes, no need to modify the stack trace to keep only one record in the recover middleware, just find a way to filter out the starting point of panic in accesslog middleware would be ok. But I'm not sure runtime.Caller(2) is always what I want.

There're another two ideas for my current usage scenarios：

  1. add a RemoteHost string field to accesslog.Log, accesslog can record ip by default.
  2. add a CustomFields map[string]interface{} field to accesslog.Log
    for some reason, I have to add some custom fields, but I expect these custom fields can be logged separated by | like the built-in fileds such as {{.Latency}}|{{.Method}}. for example, I add a key-value {"client": "svcmgr"} to Log.CustomFields, then I can set the template pattern like this: {{index .CustomFields "client"}}

So, that CustomFields map has nothing to do with the current AddFields and accesslog.GetFields(ctx).Set thing. Is it a static set of key values that should be stored no matter what? I dont think this is necessary because you can already loop through or get the by key from within a template of custom fields. A Log instance is created if formatter or broker were not nil, and this is binded to the template! It has a Log.Fields slice field, each of its entry has Key and Value. You can loop (or select by key with the latest commit):

Same when you want to add new fields e..g now you asked about IP which is good and we have it on the "old" request logger, but, you can customize the log as you want: 

// 1. Register a field.
ac.AddFields(func(ctx iris.Context, fields *accesslog.Fields) {
  fields.Set("IP", ctx.RemoteAddr())
})

// 2. Use Template formatter's `Text` value
// to customize the look & feel of a log.
// You could also use its `Tmpl` field to
// set a *template.Template instance.
ac.SetFormatter(&accesslog.Template{
  Text: `{{.Now.Format .TimeFormat}} {{.Path}} {{.Code}} {{.Fields.Get "IP" }}
`,
})

The .Fields is an iris memstore.Store like request parameters or ctx.Values() so they have all the methods you already used to work with, e.g. Get, Set, GetIntDefault and e.t.c. (a new one of Exists(key string) bool was added to help you with template statements too).

result (Local ip)

2020-09-10 21:38:13 / 200 ::1

Example: https://github.com/kataras/iris/tree/master/_examples/logging/request-logger/accesslog-template

@tuhao1020, So, now that you are aware of these things, you still want an extra field of static key-values (static because value is interface{}) of CustomFields?

kataras picture kataras on 10 Sep 2020

I run the accesslog-template example and got an error:
[ERRO] 2020/09/11 02:46 accesslog: template: :1:57: executing "" at <.Fields.Get>: can't evaluate field Get in type []memstore.Entry

ac.AddFields(func(ctx iris.Context, fields *accesslog.Fields) {
    fields.Set("IP", ctx.RemoteAddr())
    fields.Set("Client", "svcmgr")
})

If I add {{.Fields.Get "IP"}}, I will get the above error, if I remove the template, log will be IP=::1 Client=svcmgr, what I expect is ::1|svcmgr

tuhao1020 picture tuhao1020 on 10 Sep 2020

@tuhao1020 I think you forgot to go get -u github.com/kataras/iris/v12@master - the field was initially declared as []memstore.Entry but it's the same as memstore.Store (it's still a slice of memstore.Entry + plus helper methods)

kataras picture kataras on 10 Sep 2020 
go: golang.org/x/text upgrade => v0.3.3
go: golang.org/x/net upgrade => v0.0.0-20200904194848-62affa334b73
go: google.golang.org/protobuf upgrade => v1.25.0
go: github.com/modern-go/concurrent upgrade => v0.0.0-20180306012644-bacd9c7ef1dd
go: google.golang.org/appengine upgrade => v1.6.6
go: golang.org/x/sys upgrade => v0.0.0-20200909081042-eff7692f9009
go: github.com/golang/protobuf upgrade => v1.4.2
go: golang.org/x/crypto upgrade => v0.0.0-20200820211705-5c72a883971a
go: gopkg.in/ini.v1 upgrade => v1.61.0
go: github.com/modern-go/reflect2 upgrade => v1.0.1
go: github.com/klauspost/compress upgrade => v1.11.0
go: gopkg.in/yaml.v3 upgrade => v3.0.0-20200615113413-eeeca48fe776
go: github.com/tdewolff/minify/v2 upgrade => v2.9.4
go: github.com/tdewolff/parse/v2 upgrade => v2.5.2

error still exists

tuhao1020 picture tuhao1020 on 10 Sep 2020

@tuhao1020 you show other upgraded packages except Iris, so I cannot verify the above log ^ Here is a complete log:

PS C:\Users\kataras\Desktop\testirismaster> go get -u github.com/kataras/iris/v12@master
go: downloading github.com/kataras/iris/v12 v12.1.9-0.20200910180334-2bb04823b03f
go: github.com/kataras/iris/v12 master => v12.1.9-0.20200910180334-2bb04823b03f
go: google.golang.org/appengine upgrade => v1.6.6
go: github.com/klauspost/compress upgrade => v1.11.0
go: github.com/modern-go/reflect2 upgrade => v1.0.1
go: golang.org/x/net upgrade => v0.0.0-20200904194848-62affa334b73
go: golang.org/x/text upgrade => v0.3.3
go: golang.org/x/sys upgrade => v0.0.0-20200909081042-eff7692f9009
go: github.com/golang/protobuf upgrade => v1.4.2
go: github.com/modern-go/concurrent upgrade => v0.0.0-20180306012644-bacd9c7ef1dd
go: google.golang.org/protobuf upgrade => v1.25.0
go: golang.org/x/crypto upgrade => v0.0.0-20200820211705-5c72a883971a
go: gopkg.in/yaml.v3 upgrade => v3.0.0-20200615113413-eeeca48fe776
go: github.com/tdewolff/minify/v2 upgrade => v2.9.4
go: github.com/tdewolff/parse/v2 upgrade => v2.5.2
go: gopkg.in/ini.v1 upgrade => v1.61.0

Can you copy-paste the example and run it? I am sure you are not using the latest commit because the error message you get says []memstore.Entry but the field is memstore.Store...maybe try with GOPROXY=goproxy.cn,direct? Your go.mod file should contain that exact line:

github.com/kataras/iris/v12 v12.1.9-0.20200910180334-2bb04823b03f
kataras picture kataras on 10 Sep 2020

go.mod

go 1.15

require (
    github.com/Joker/hpp v1.0.0 // indirect
    github.com/fastly/go-utils v0.0.0-20180712184237-d95a45783239 // indirect
    github.com/jehiah/go-strftime v0.0.0-20171201141054-1d33003b3869 // indirect
    github.com/jonboulle/clockwork v0.2.1 // indirect
    github.com/k0kubun/colorstring v0.0.0-20150214042306-9440f1994b88 // indirect
    github.com/kataras/iris/v12 v12.1.9-0.20200910180334-2bb04823b03f
    github.com/klauspost/compress v1.11.0 // indirect
    github.com/lestrrat-go/file-rotatelogs v2.4.0+incompatible
    github.com/lestrrat-go/strftime v1.0.3 // indirect
    github.com/mattn/go-colorable v0.1.7 // indirect
    github.com/modern-go/concurrent v0.0.0-20180306012644-bacd9c7ef1dd // indirect
    github.com/modern-go/reflect2 v1.0.1 // indirect
    github.com/onsi/ginkgo v1.14.1 // indirect
    github.com/onsi/gomega v1.10.2 // indirect
    github.com/smartystreets/goconvey v1.6.4 // indirect
    github.com/tdewolff/minify/v2 v2.9.4 // indirect
    github.com/tebeka/strftime v0.1.5 // indirect
    github.com/yudai/pp v2.0.1+incompatible // indirect
    golang.org/x/net v0.0.0-20200904194848-62affa334b73 // indirect
    golang.org/x/sys v0.0.0-20200909081042-eff7692f9009 // indirect
    google.golang.org/appengine v1.6.6 // indirect
    gopkg.in/ini.v1 v1.61.0 // indirect
)

package version seems ok, but my local code is not the same as github, maybe it is because of the GFW

tuhao1020 picture tuhao1020 on 10 Sep 2020

@kataras I retried some times and now I pull down the new code, ac.AddFields and {{.Fields.Get "xxx"}} exactly meet my needs 😄

tuhao1020 picture tuhao1020 on 10 Sep 2020

@tuhao1020 That's great !! 👍 👍

I have one more for you, you can also bind template.FuncMap inside your log template format. Here's how:

    // 1. Register a field.
    ac.AddFields(func(ctx iris.Context, fields *accesslog.Fields) {
        fields.Set("IP", ctx.RemoteAddr())
    })

    // 2. Parse your log line template.
    // Note that you can use a pre-made template too.
    //
    // 2.1 The log line format:
    text := `{{.Now.Format .TimeFormat}} {{.Path}} {{.Code}} {{.Fields.Get "IP" }}
` /* 2020-09-10 21:38:13 / 200 ::1 */
    //
    // 2.2 Parse the template, optionally using custom Template Functions.
    tmpl := template.Must(template.New("").
        Funcs(template.FuncMap{
            // Custom functions you may want to use inside "text",
            // e.g. prefixFields .Fields "my_prefix"
            // to get a slice of fields starts with "my_prefix"
            // and later, in the template, loop through them and render its values.
            // "key": func(input) string { return ... }
        }).
        Parse(text))
    //
    // 3. Use Template formatter's `Text` value
    // or the `Tmpl` field to customize the look & feel of a log.
    ac.SetFormatter(&accesslog.Template{
        Tmpl: tmpl,
    })
    // 4. Register the middleware. That's all.
    app.UseRouter(ac.Handler)
kataras picture kataras on 10 Sep 2020

l'm going to encode some fields to base64 tomorrow 😄

tuhao1020 picture tuhao1020 on 10 Sep 2020
😄1

Sure, why not? 💡 I'm going to sleep as I was working with Iris for the past ~19 hours...Please check all the above comments for accesslog features and test test test try to break things please 💯

kataras picture kataras on 10 Sep 2020
👍1

@kataras
PanicLog 🆗
AddFields & Custom Template 🆗
Custom FuncMap 🆗
LogBroker 🆗

above features tested and I found no problems. 🎉 🎉 🎉 🎉 🎉

Log.Timestamp is the Now's unix timestamp in seconds. I think it might be better to use milliseconds

tuhao1020 picture tuhao1020 on 11 Sep 2020

Thanks 🎉 Yes it's in seconds to be compatible with other systems. You can change it on a custom formatter (a formatter accepts a *Log so it can also modify its fields) but if you want my opinion I prefer nanoseconds instead, it's more acquirate. However, Timestamp is useful for JSON format, otherwise if you use the Template one or a custom, you have access to the Now time.Time field so you can format it as you want at the template itself. However, I will default it to millis (Now.UnixNano() / 1000000) as you proposed though.

Thanks for your tests, I believe that we have now the most advanced, featured and still simple to use builtin request logger compared to other frameworks. Thanks to you and your initial idea, pushed me to add more and more and I really like this discussion we have here.

kataras picture kataras on 11 Sep 2020

Thanks for your hard work!
I think the builtin request logger is powerful and flexible enough, it's time to close this long discussion.
I'm new to Iris and I learned a lot from you these days. Thank you again！
Expect version 12.2.0 😄

tuhao1020 picture tuhao1020 on 11 Sep 2020
🚀1

That's awesome @tuhao1020. Please feel free to tag my name and comment more ideas in the future!

kataras picture kataras on 11 Sep 2020

Sure! :D

tuhao1020 picture tuhao1020 on 11 Sep 2020

Actually I am thinking of putting IP in the builtin fields as you proposed and also make a function that can read the log file and print search/groupped based on regex search, e.g. accesslog.Search(io.Reader, *regexp.Regexp) []accesslog.Log) so you can find the requests made by a specific client mapped by its IP or request id (that's useful, e.g. show a page to your client of its requests through the entire website session based on time ranges for example). What do you think? Or maybe let it to 3rd-parties and custom editor's find tooling?

kataras picture kataras on 11 Sep 2020

I think putting IP in the builtin fields should be welcomed by users, curerntly I don't have the requirement to find the ip and its matched requests. Normally, there're 3rd-party solutions to do this, such as Logstash/Filebeat/Elasticsearch... So I don't think it is necessary to provide this function.

tuhao1020 picture tuhao1020 on 11 Sep 2020

OK @tuhao1020 the new format (put the code in front, the ip after the method:path):

{{.Now.Format .TimeFormat}}|{{.Latency}}|{{.Code}}|{{.Method}}|{{.Path}}|{{.IP}}|{{.RequestValuesLine}}|{{.BytesReceivedLine}}|{{.BytesSentLine}}|{{.Request}}|{{.Response}}|\n

Also, the iris.Default now uses this middleware instead of the old one, logs the requests on ./access.log file, prints information about its attached middlewares too.

kataras picture kataras on 11 Sep 2020

Update: &accesslog.CSV{...} format was added.

kataras picture kataras on 12 Sep 2020
Was this page helpful?
0 / 5 - 0 ratings

Related issues

Dexus picture Dexus  ·  4Comments
shenkaige picture shenkaige  ·  5Comments
caimingyi484 picture caimingyi484  ·  4Comments
AlbinoGeek picture AlbinoGeek  ·  4Comments
fangli picture fangli  ·  3Comments