Page MenuHomePhabricator

Add support for dynamic placeholder replacement in logger.
Open, Needs TriagePublic

Description

Problem statement

When creating logs, in some places we want to include the request IP - here are some examples:

We solve this by:

  • sometimes we have easy access to $request variable and we just use it by $request->getIP() or $this->getRequest()->getIP().
  • sometimes we just call RequestContext::getMain()->getRequest() to get the global WebRequest
  • sometimes we pass the IP directly to the class, and in case something is wrong we use that $reqIP to add to the log context
  • sometimes we fetch Request from things that Request does not belong to, like User object.

In general - having the possibility to include the IP (and maybe any other based on the current request) is something common. In other places, it's usually handled by solutions like Monolog WebProcessor that includes the Client IP with every single log. We don't want the IP in every single log - but when we want it - things get difficult.

Proposal

Implement a placeholder Processor and inject it into our Monolog logger.
This would allow us to define placeholders in the $context array without having to specify the value. Then, when a message gets processed, the PlaceHolder processor iterates over the context array and replaces all placeholders.

Code example:

	$this->logger->info(
		"An example log message",
		[ 'client_ip' => PlaceholderProcessor::CLIENT_IP ]
	);

This way we would get the possibility to log request-related information without having to inject those over the way, simplify the code a bit, and also it would help with the removal of the User::getRequest() method, which is also often used to retrieve the client IP.

Kudos to @daniel for the initial proposal for this idea.

Event Timeline

Change 982893 had a related patch set uploaded (by Pmiazga; author: Pmiazga):

[mediawiki/core@master] POC: logger: Introduce the PlaceholderProcessor

https://gerrit.wikimedia.org/r/982893

I don't think it would solve any problems (you can just replace User::getRequest() with RequestContext::getMain()->getRequest()), but it would introduce new ones:

  • We have an abstract logging framework that's not tied to Monolog, much less to specific Monolog processors, and implementations of it can't be reasonably expected to understand special values like this. We should probably just drop that framework and standardize Monolog, but it's a big task.
  • The request context can change (e.g. via RequestContext::importScopedSession() which is used by the job queue and some other things) so you'd have to be very sure that the processors are applied immediately and not after a delay (because you are using OverflowHandler or something like that), by which point the scoped import might have been cleaned up.

I don't think it would solve any problems (you can just replace User::getRequest() with RequestContext::getMain()->getRequest()), but it would introduce new ones:

The problem this is intended to solve is the issue of accessing the request via global state. If we use a placeholder, the code that controlls construction of the logger can inject the necessary context information.

  • We have an abstract logging framework that's not tied to Monolog, much less to specific Monolog processors, and implementations of it can't be reasonably expected to understand special values like this. We should probably just drop that framework and standardize Monolog, but it's a big task.

I was thinking this would function as a wrapper around whatever logger we'd want to use.

  • The request context can change (e.g. via RequestContext::importScopedSession() which is used by the job queue and some other things) so you'd have to be very sure that the processors are applied immediately and not after a delay (because you are using OverflowHandler or something like that), by which point the scoped import might have been cleaned up.

This was actually the intended use case: We should not manipulate global state when executing jobs. We just eventually get to a situation where we supply the correct context (Request, Authority, etc) as to whatever classes are needed by the job. Basically, the Job object would know a RequestContext, and would have a getLogger( $name ) method that would automatically wrap the logger with one that has the appropriate context information.

Of course, this is a fairly big shift - conecptially, we are making it so that getting a logger requires a context, where so far, it didn't.

The problem this is intended to solve is the issue of accessing the request via global state.

But it doesn't actually solve that, you just hide it. You can't inject the request during setup, because the request can change when you import the context for a job. You can create a service that keeps track of scoped contexts, in which case you still have global state, encapsulated inside a service which is accessed via singleton pattern (LoggerFactory), while RequestContext is... a service encapsulating global state, accessed via singleton pattern.

I was thinking this would function as a wrapper around whatever logger we'd want to use.

What LoggerFactory returns is entirely controlled by the logger SPI, you cannot wrap it. I guess we could change how LoggerFactory works, but it seems like a lot of effort for a cosmetic improvement.

This was actually the intended use case: We should not manipulate global state when executing jobs. We just eventually get to a situation where we supply the correct context (Request, Authority, etc) as to whatever classes are needed by the job. Basically, the Job object would know a RequestContext, and would have a getLogger( $name ) method that would automatically wrap the logger with one that has the appropriate context information.

That would mean having to inject a RequestContext or wrapped Logger or something like that into every method that has a chance of being called from a job. That goes completely against separation of concerns - a business logic class should not know whether it's used in a job or a web request, and we should not have to refactor every single call chain that leads to a log entry being created somewhere every time we want to move some processing to a job for performance reasons.

Logging and the request context are cross-cutting concerns that are relevant to basically everything everywhere. It's fine to manage cross-cutting concerns via global state; the alternative is constantly having to track down and update call chains whenever someone decides a method should do something fairly trivial that it didn't do before, like logging. If we wanted to rewrite MediaWiki as a multi-threaded application, we'd have to get rid of global state completely, which would be a ton of work, but would then have compelling benefits. Without such benefits, I don't think it's worth doing. There is a lot of global state that has been causing problems, and was/is worth getting rid of, some of it is in RequestContext (the language should really be passed explicitly to everything that needs it, for example). I don't think the IP is one of those.

The client IP address is an inherent part of the HTTP request. MediaWiki uses PHP as a CGI runtime, where each request gets its own thread or process. As such, there are not multiple competing "correct" values. This believe this is why we can use global state to access the "correct" value in automatic logging code, such as in the proposed patch.

The question this raises, if it's already safe to do that, what stability or code quality problem we solve, if we accessing the same RequestContext::getMain method either way? The assumption made, is that this method is always both safe and correct.

I would question that. In CLI context, there is no meaningful "web request" data. We could return a fake 127.0.0.1 value, and that'd be reasonable as a placeholder for something that has no explicit demand from a piece of code (i.e. to add default log context to all messages, where you don't explicitly ask for it).

When a piece of code is explicitly fetching the IP, that suggests it is making some assumptions about it being in a web request. If true, then it should already have easy access to RequestContext, as indeed one would for any other request-bound information such as getTitle, getActionName, getUser, etc. This is generally available in:

  • entry points,
  • route handler classes (Action, SpecialPage, ApiModule, Rest subclasses),
  • a method that takes RequestContext as parameter.
  • any class that is only constructed by one of the above.

In any other code (i.e. the majority of service classes, value classes, and low-level code) we would not have a RequestContext, and thus not have a single always-present always-correct value for "title", "action", or "IP"; and thus should not fetch it globally. It would either need to be optional, or passed, or accessed via a "only for debugging" static helper, where we safely provide a generic fake answer, on the assumption that the caller will not use it for business logic.

That "something" exists today and is RequestContext::getRequest, where we construct a FauxRequest if running on the CLI, with a fake IP of 127.0.0.1.

Is there something about accessing the IP that is harder than accessing the current page name or current user name? Or something about the IP that makes us not want to pass data in?

Sometimes CI is hard or incompatible with the way something works today. But that suggests there's a differnet code smell that requires a closer look at the specific class in question to fine a path forward. If there is, it likely has other benefits that can justify the work instead.