Rethinking collective.usernamelogger: user id vs login name

Hi folks,

I am trying to rethink a use case of collective.usernamelogger -- logging the internal user id gathered from the __ac cookie is fast and unobtrusive, but may not be as useful and logging the login name (which is unfortunately not available from cookie). This is especially true if using UUID as user ids.

Some questions for the community:

  • Is there a reasonable way to approach obtaining the login name during the course of the session, such that it can be set as an instance attribute on a ZServer.http_server.http_request object?
    • Maybe in a post-traversal hook? How would one access the http_request (medusa) object from such a context?
  • My use case is email-based login, grepping the Z2.log for user activity by email address. Is this worth making changes for, in the general case? Do others want this ability?
  • I assume that this would be an opt-in behavior (e.g. environment variable) if I was to put such functionality together.

Thoughts?

Cc: @lukasgraf @kroman0 @vincentfretin

I wouldn't mind this change an an optional feature, though I probably won't be needing collective.usernamelogger for much longer.

We're currently moving towards shipping our logs to an ELK stack (Elasticsearch, Kibana, Logstash) using Filebeat to ship them off.

As part of that transition we'll also be implementing our own structured logging, instead of parsing Z2.log. The structured access log will be a simple file with lines of JSON, one for each request. That allows for not justing logging the information that's already in Z2.log or other Apache combined log style logs, but other interesting information, such as request timings. In terms of implementation it's going to be similar to what collective.stats is doing - hook into Publisher using the ZPublisher.interfaces.IPubStart etc. events, and write a custom log instead.

That way I simply don't have to bother with the ZServer/Medusa parts of the request or logging.

I use the following ZPublisher.interfaces.IPubEnd subscriber to gather additional logging information to enhance Z2 logging.

## Verbessertes Z2-Logging
def subscriber_enhance_z2_logging(event):
  try:
    request = event.request
    mrequest = getattr(request.response.stdout, "_request", None)
    if mrequest is None: return
    mrequest.client_addr = request.getClientAddr()
    user = request.get("AUTHENTICATED_USER")
    mrequest.user = user is not None and user.getId() or "Anonymous"
  except Exception:
    logger.exception("`subscriber_enhance_z2_logging` failed: Z2 log entry will be wrong")

mrequest above becomes the self of ZServer.medusa.http_server.http_server.z2_log which I override to make use of the newly provided client_addr and user (if available).

Thanks, Dieter. I presume that this is the means to obtain the medusa http_request object in your subscriber? That is exactly what I was looking for.

Sean