Log configurations access date formatter is ignored

[gaborbernat]

https://github.com/emmett-framework/granian/pull/298/files#diff-0dbdb5a01ed2fc4299930a6f88b2e6f595d2ea9266bfb7db163cc80ba0686205 adds access dateFmt, however this is not used anywhere and instead time has a hard-coded value here https://github.com/emmett-framework/granian/blob/e0133b8f47e82f5c30f458752bd8a74eb88cdd12/granian/log.py#L85. This is confusing 😊 One can work around this by redefining the fmt of that logger, but I think the fmt there should respect the value inside dateFmt.

    log_config = deepcopy(LOGGING_CONFIG)
    log_config["loggers"][""] = {"handlers": ["console"], "level": "DEBUG" if IS_LOCAL else "INFO"}
    log_level = LogLevels.debug if IS_LOCAL else LogLevels.info
    formatters = log_config["formatters"]
    log_fmt = f"%(asctime)s.%(msecs)03d{time.strftime("%z")} %(process)s %(levelname)s %(name)s %(message)s"
    formatters["access"]["datefmt"] = log_config["formatters"]["generic"]["datefmt"] = "%Y-%m-%d %H:%M:%S"
    formatters["generic"]["fmt"] = formatters["access"]["fmt"] = log_fmt
    access_fmt = '%(addr)s - "%(method)s %(path)s %(protocol)s" %(status)d %(dt_ms).3f'

[gi0baro]

Those are 2 different things:

• dateFmt can be used to customise the format of the logging timestamp (which is the time at which the log message was produced)
• the time atom is the time at which the request actually arrived, not when it was logged

Given this, there's no easy way to customise the atoms rendering; in fact you can't customise any of the existing atoms, just use or don't use them.

[gaborbernat]

My suggestion here is that rdt.strftime should use the value from formatters["access"]["datefmt"] rather than roll its own.

[gi0baro]

My suggestion here is that rdt.strftime should use the value from formatters["access"]["datefmt"] rather than roll its own.

I'm not completely sold on that idea. AFAIK neither Gunicorn or Hypercorn allow this.

[gaborbernat]

I'm not sure this is an acceptable solution from my side. This essentially means that I need to use one formatting type for dates in all the accessing logs and another one for everything else. Is this really the best we can do?

[gi0baro]

I'm not sure this is an acceptable solution from my side. This essentially means that I need to use one formatting type for dates in all the accessing logs and another one for everything else. Is this really the best we can do?

I assumed this was stale given the absence of recent activity, reopened this.

The idea to have a single atom behaving differently from all the others still doesn't sound right to me. Can you please provide examples of other servers supporting this? At least it might be a starting point to look at their implementation.

I'd also say having different atoms for request time is probably a better implementation in my mind (eg: having time_epoch, time_dt, time_dtz...).

[gaborbernat]

I do not have good compression to other frameworks and honestly I don't really care what other frameworks do. I am more like providing some feedback on trying to use this framework and what issues I ran into it. I am not saying that my proposed solution is the best path ahead. However, there should be a clean and well-documented way to achieve the same type of log message for both my application and its access log rather than the two of them differing.

The issue did not become stale just because I did not comment on it. I did not comment on it because I have nothing more to add to it and the outstanding issue never been addressed.

For me a minimally acceptable solution would like at the very least documenting what my suggested work around was. However, I am not 100% sure that work around is a good enough solution, but it's something that anyone using this framework can easily be cut out by. So worth documenting it.