Switch Watchdog to a PSR-3 logging framework

subscribe

Subscribing. The irony is hook_watchdog() is one of the best cases for our current hook system conceptually, but the late-bootstrap problem is legitimate.

Subscribing.

Disclaimer: I barely know Drupal, so maybe if I'm assuming things incorrectly please correct me :)

@catch, regarding the issues you mentioned:

- Let's start with the arg signature:

$type: For this, the way we have integrated Monolog in Symfony is by having multiple Logger instances, all configured with the same Handler instances. Loggers take a $channel arg in their constructor. This is added to each log record. It's a way to categorize things, and I guess it'd match your $type thing well. If you don't want to have multiple instances floating around (in Symfony it's done via the Dependency Injection Container which makes things easy, you just say you want an instance of the logger with a given channel name) then you could extend the Logger and add that $channel arg to addRecord, so it can be specified in every call rather than on the instance itself.

$message: That one's easy :)

$variables: I guess that's the equivalent of Monolog's $context, some handlers do something with it, some don't. It's just there if needed. In case you're not sure what this is, it's really meant as just being contextual information to accompany the message, and log some additional data that helps you debug issues. After reading again I see it's just vars for the message placeholders, that sounds ok to me as context info. The only thing you may want to do, if you combine message vars with additional context info (which you don't have now I assume), then maybe you'd want to remove the values that are used for the message from the context before displaying the context to the user. I don't know if that's feasible though, depends how you pass the info and how you format the message.

$severity: = $level

$link: You could put it in the context and then have a Processor registered which moves it in the $record['extra'] key if it's found in context. Or you could just again extend the Logger so that the $link automatically goes in the extra key.

- For capping, you could have a wrapper handler that does that, we should have one at some point anyway in Monolog, that would prevent from logging duplicate entries, because I want to avoid Email and other such handlers (something creating tickets for errors would come to mind) from repeatedly act on the same error. However it's a fairly difficult problem, because you can't only rely on the message, since it could contain variables and be different for every error that happens. I planned on relying on the stack trace to identify single path of failures, but I'm not yet sure this will work. Apparently you have moved the variables off the message, so this doesn't affect you I guess, and you can have a simple implementation of a capping handler.

I hope this helps a bit.

Subscribing.

That'd be an E_STRICT warning no?

Yes, unless you add it as a last optional argument of addRecord, then it'd be ok. Or you can also have another public method that matches your current signature more closely, but anyway if you can live with the multiple instances (honestly they're not too expensive, just a few pushHandler() calls to set them up) it doesn't matter.

Right, we'd basically be stuffing stuff into context then filtering it back out again. It's doable but could potentially get a bit wonky (i.e. it'd need to be $context['variables'] = array('@foo' => 'bar')) which detaches the variables from the message - i.e. right now the arguments match format_string() so there's a choice between keeping the watchdog() arguments the same and then switching them around before they're sent to the method, or having the arguments inconsistent with other places in Drupal that use the same mechanism.

What I was thinking about was more along the lines of:

addWarning('Hello @what', array('@what' => 'World', 'args' => $args));

Then when you want to display a message, you just need to loop over $context, and remove any key that starts with [%@!] from the contextual data since those are your message placeholders. This separation of context and message placeholders could be done in addRecord too I suppose. Or again, add a new public method to your own Logger class so that it can have more arguments, then you could have $message, $variables and $context.

Anyway, the bottom line I think is that the main benefit of using Monolog would be to re-use and share Handlers imo. The Logger class doesn't do much beyond addRecord(), and if needed you could even have your own implementation of that that doesn't even extend Monolog's, then you're free to define your own API.

I'd much rather #1594956: Merge watchdog and Symfony logger classes.

Ah, thanks for the clarification. Was thinking about the architecture behind this:

1. Introduce a Logger instance which is held in the drupal_container()
2. Calling watchdog() invokes the Logger object in the container (drupal_container()->get('watchdog')->addWarning(), etc)
3. We implement our own Handler classes, which acts on how we want logging to be done:
   • dblog implements DatabaseLogger
   • syslog is already suppored via SyslogHandler
4. The dblog and syslog modules register their handlers to the Logger object to the "watchdog" object within the Container
5. Remove hook_watchdog() as it's now handler-driven rather than hook-based

Yay watchdog logging system 2.0! It's easily extendible, and works well with all other Symfony components.

The sense I got from talking with Fabien at Symfony Live is that the answer to most things in Symfony is "you use a config file to register it in the DIC, the DIC is the first thing that loads, and nearly all of your problems go away". So we would do away with runtime registration and move to a config/rebuild registration (which we will have to do for the DIC for performance reasons), and then almost anything OO is available at any time, regardless of bootstrap phase.

So dblog.module would just need to use whatever mechanism we establish for registering things in the DIC, and the rest just works.

Edit: And yes, the watchdog() function needs to be temporary only and go away eventually. Otherwise we still have a hard dependency everywhere we call it, which means some other file that we have to manually insure is loaded before we run some other code, which is exactly what we want to eliminate.

It's a start.

After letting it sleep since Barcelona, here is the (admittedly ugly) initial version I demoed in Lyon and Barcelona. Working on it this week in Munich.

Or in just one patch on curreny head.

fgm, can you split this into multiple patches? One should JUST add Monolog via Composer, the other should depend on it and actually make use of it. That makes it easier to review. Thanks.

FGM, any movement here? I'd love to get Monolog in, but we only have another 2 months to get it in place.

Currently fulltime on client projects, but I've allocated half of my time in october and november to D8 core work, so this should restart moving next week.

OK, great! If you need help or input come by the WSCCI channel.

The attached patch simply adds Monolog using Composer.

As for the previous patch...

+++ b/core/lib/Drupal/Core/Watchdog/Logger.php
@@ -0,0 +1,28 @@
+    // A system logger always needs to be available for watchdog() and logging
+    // in Symfony code, even if this is the Null logger. This default can be
+    // overridden by watchdog.module configuration.
+    drupal_container()->register(WATCHDOG_CONTAINER_KEY, 'Drupal\\Core\\Watchdog\\Logger');

I feel weird about touching the Container from Drupal\Core\Watchdog\Logger. Do we even need this class? I was thinking something like the following...

1. We register a "watchdog" service in drupal_container() directly to a Monolog\Logger. Note that drupal_container() is already completely pluggable so we don't need to handle the mappings at all since that's what the container is there for.

     drupal_container()->register('watchdog', 'Monolog\Logger');
   

   This, of course, will become easier as #1706064: Compile the Injection Container to disk progresses.

2. Syslog module, Dblog module, etc, register their own Monolog\Handler to drupal_container()'s "watchdog".
   

   function dblog_init() {
     $handler = new Drupal\Dblog\DblogHandler();
     drupal_container()->get('watchdog')->pushHandler($handler);
   }
   

3. We turn watchdog() into a wrapper around interacting with drupal_container()->get('watchdog')->add*();

Re #21:

- I wouldn't even bother calling the service watchdog. It's monolog. Let's just call it that and be honest.

- We wouldn't use hook_init(). Rather, dblog and friends would add a compiler pass for the Container that adds the handler call to the monolog service.

- We need to check and see how Symfony handles bridging Monolog to the various LoggerInterface definitions different components define. They're all identical I think, so it shouldn't be more than adding a trivial wrapper class, but we should still verify it so that we can inject it nicely.

Otherwise, agreed.

Another question, should this become a meta issue so we can track the various tasks required?

• #1810664: Add Monolog Symfony-Bridge to Drupal

- I wouldn't even bother calling the service watchdog. It's monolog. Let's just call it that and be honest.

Agreed.

- We wouldn't use hook_init(). Rather, dblog and friends would add a compiler pass for the Container that adds the handler call to the monolog service.

Definitely want this to happen. Hopefully #1706064: Compile the Injection Container to disk gets in soon so we can head in that direction.

- We need to check and see how Symfony handles bridging Monolog to the various LoggerInterface definitions different components define. They're all identical I think, so it shouldn't be more than adding a trivial wrapper class, but we should still verify it so that we can inject it nicely.

Sent up a pull request for Monolog\LoggerInterface to allow such a thing. We're in no way blocked by this though.

Don't know is here is the right place but the dblog interface [dblog_overview()] should be dropped too and either wrap the watchdog table with an entity, either provide Views (as Views will be in core) with watchdog as base table.

The idea would be to replace the custom dblog UI with a View that can be extended and customized by sitebuilders. Turning the watchdog item into an entity would be the best approach as it open other doors.

claudiu: Agreed that could be done, but that's a separate issue from this. Also, cannot happen until Views is in core anyway.

I'm really confused as to why we're so focussed on moving to Monolog.

The only requirement I'm able to find in this issue is that we need to move logging out of hooks and into plugins, similar to cache.

We're potentially talking about a one-method interface. How hard could that be to throw together without bringing in another dependency?

@msonnabaum: this has indeed been discussed but regrettably not in writing. One of the problems which led to this had been from working on mostly biggish sites which need to have multiple types of logging, with per-channel specifics, like the ability to send one channel to one logging destination whatever the level, another to another destination, the ability to log at debug level for one channel while not logging below warning on others, ability to cut logging flow if no event above a given threshold happens to limit log volume ("fingers crossed" logging), ability to log to gelf or logstash for centralized logging.

Monolog is one of the existing tools which bring most if not all of this, and can be included as a new plugin.

Needs #1810664: Add Monolog Symfony-Bridge to Drupal ... Still needs lots of work, but it does register the Bundle and Handler for syslog and dblog.

1. Really not sure what to do with Actions Loop Test, as it's really just testing watchdog(), which doesn't really apply anymore. In this patch it just removes it
2. Also not quite sure what to do with entity_cache_test.module either, as it tests itself using variables in a watchdog log, which seems really wrong

msonnabaum made me think again and reconsider this choice: the arguments for Monolog, which most of us, myself included, have done, are good, and this is likely the best candidate (not sure I posted my review of logging solutions anywhere ?), HOWEVER....

Working on larger environments than ever, I noticed that even with the expanded facilities offered by Monolog, the mechanism provided was sufficient for the needs encountered, but the actual target drivers(handlers in Monolog parlance) are not necessarily sufficient. And conversely, if even such a large package does not cover all needs, need we really include it all, or focus on a new logging interface, and only bundle as more limited version of Monolog, including only the most basic (supporting) classes and not the whole shebang, up to very specific handlers or little use for most sites, like Gelf/Graylog, Logstash, and others ?

To align with the principle of keeping core lean, it would make sense to only include these components, while allowing for the clean addition of extra handlers or processors as needed, or maybe even swapping the core classes entirely as long as the interface remains the same.

What do you think or this ? Should I (re?)write my findings about the logging panorama before we continue down that track ?

@fgm: A quick word from my (maybe biased) side: if your goal is to keep core lean, I would say using an external lib is leaner than rewriting parts of it. As for bundling the whole shebang.. well most handlers are really small, that's why I took the approach of including most anything in monolog itself. That makes it a very good general purpose logging tool, and it's not like it takes much space (if that ever mattered in the 21st century;). I don't know if external code should count as bloating the core or not.

Updated patch...

1. Depends #1810664: Add Monolog Symfony-Bridge to Drupal. 1289536-with-monolog.patch combines both patches.
2. Still need to figure out what to do with entity_cache_test.module

To align with the principle of keeping core lean, it would make sense to only include these components, while allowing for the clean addition of extra handlers or processors as needed, or maybe even swapping the core classes entirely as long as the interface remains the same.

It's our internal code that needs to be slimmed down. Like Seldaek mentioned, depending on external code doesn't add bloat to Drupal Core. Bringing in third-party libraries just means we can work with a larger developer base to accomplish the goals that we aim to accomplish.

As for swapping core classes, that's made possible with the Dependency Injection Container. As long as the "logger" service inherits from Monolog/Logger, or the Handler you're adding inherits from AbstractHandler, you can switch definitions easily. In this patch, you can see that done with DblogBundle and DblogHandler. Since we're using Symfony's MonologBridge here, all Symfony logging is compatible with it too.

That's part of what I was trying to say: we should be able to swap not by swapping just an implementation with one of its descendants, but rather by anything exposing the same interface, whatever its inheritance.

Which would mean having core rely on implementation of one (or more) interfaces (typically the interface exposed by the existing o Monolog base and abstract classes), and providing a basic implementation, maybe just some NullLogger. Or alternatively bundle it as we have been planning to do until now, with the extra handlers I added (and more ?) but at least allow replacements based on interface contracts, not implementation.

fgm: Isn't that what we're doing? Just using Monolog to define those interfaces?

At some point you have to depend on *something*. :-)

Since I'm working on it in Gent, I've prepared a set of data model diagrams to introduce what Monolog actually is: http://blog.riff.org/2012_11_02_rethinking_watchdog_monolog_architecture

Next up, besides working on the patch, will be an explanation of the way all of this works together, and how to put it to good use in Drupal 8 (notably why this is better than our legacy implementation). That will probably be the basis for the change notice once the code gets in.

Rerolled on top of HEAD with a small change to handle invalid $level values and convert them in a more compact fashion.

At this point, installing fails with a DI exception: "The service definition "logger" does not exist." in ContainerBuilder->getDefinition().

Dalin mentions that the Monolog license could be a problem and needs to be vetted before we proceed.

Adding Legal tag for this reason.

@fgm: Why would it be a problem? It's MIT - which is the same as Symfony by the way.

@seldaek: Quoting Dalin (from his comment on my blog):

MIT license isn't actually a thing, there are several licenses that are incorrectly mislabelled as "The MIT license" unfortunately none of which are compatible with the GPL (and thus the code is not able to be included with Drupal core). The APL is compatible and so the code could be included. However a few other projects (notably jQuery) have created a dual license with the GPL so that they could be included with Drupal.

I /think/ the specific license text you use allows us to sublicense on GPL2+, but I'm no legal advisor, so someone else needs to check.

@fgm: Oh ok, just for the record though I use the text from http://spdx.org/licenses/MIT#licenseText - which is a pretty good source of the "official" MIT license text I believe. But anyway let me know if there is any problem.

The Monolog license is definitely the MIT License: http://opensource.org/licenses/MIT

The fact that people mislabel other licenses as MIT has no bearing on this. Also, I'd like to note that the Apache license (APL) is NOT compatible with GPL2 under any circumstances. We can relicense MIT as GPL, and as such, this does not need Legal review.

#24: #1836598: Convert dblog record[-s/-ing] to Entity API.

I think there'll be lively interest coming from here. :)

Possibly. However, log volume in most cases will not be a good match for the complexity of the entity code path with all its hooks invocations.

Left my comment in the issue linked in #43, but to clarify, this issue is about logging, not logging UIs. The UI can be implemented as a separate interface for logging backends that can support it.

For those not following that discussion in the FIG group, PSR-3 "LoggerInterface" to defined a standard for logging interfaces appears to be on a reasonably fast track towards adoption.

Here is the latest draft being reviewed: https://github.com/Seldaek/fig-standards/blob/logger-interface/proposed/...

While feature freeze is in just two days, I think it would be nice if we could still define at this point that D8 will be using the final version of this standard, when it is released.

Helpful points towards that end are the facts that the effort on this interface :

• is being spearheaded by Jordi Boggiano, the creator and maintainer of Monolog
• has incorporated a number of suggestions by Crell and myself to make it well suited to Drupal needs

With regard to this specific issue, it means we can still push the integration with Monolog as foreseeen, and switch to the standard implementation later on, for those sites wishing to replace Monolog with an other implementation.

As an opposite point, one should note that for Symfony 2.2, the trend seems to be towards directly specifying Monolog as /the/ Symfony 2 logger, instead of maintaining a compatibility interface: https://github.com/symfony/symfony/issues/5968 .

They have deadlines close to ours: 2.2 is AIUI frozen at the end of december.

@fgm Very nice, thanks for the link. I'd love to push Monolog forward as soon as possible. We'll most definitely need it if we want to keep up with the PSRs.

#1834594: Update dependencies (Symfony and Twig) follow up fixes for Composer

Any other libraries in mind ?

I would really rather prefers http://logging.apache.org/log4php/ than monolog. I don't like its architecture and I'd rather bank on the apache project which has a great documentation and user base.

I also really love the Logger Interface idea. There is nothing more pleasant than to switch from a Syslog Logger from dev to a NullLogger in prod without changing the code. fgm has made an interesting point in #33, this is IMO a good practice of using loggers. If monolog is being re-architectured with the PSR-3 Standard for Logger Interface in mind, then Monolog++;

unblocking given #1834594: Update dependencies (Symfony and Twig) follow up fixes for Composer was committed.

This looks to be a feature to me, not a task. However, it also looks to be sufficiently in-progress to qualify for feature freeze extension.

@Sylvain Lecoy: you might want to look at the comparison I did about Monolog vs other loggin solutions, especially log4php, in this series of blog posts about this issue http://blog.riff.org/tags/monolog

Of course thank you for the link I appreciate :)

The PHP-FIG group has recently approved PSR-3, a standard logging interface, which was developed with an eye toward Drupal-friendliness. Monolog has already adopted it, and Symfony's components now have as well as of earlier today.

cf:
https://github.com/php-fig/fig-standards/blob/master/accepted/PSR-3-logg...
https://github.com/symfony/symfony/pull/6628

I see two possible ways forward, and consider doing one or the other to be a critical for Drupal 8:

1) Adopt Monolog (which has features above and beyond PSR-3) and use that throughout Drupal.
2) Roll our own basic implementations of PSR-3 and use that for any of the new objects we have, particularly the Symfony ones (which right now we have no logging for at all).

PSR-3 was developed more for components than for full applications, but it can be used as a baseline for full applications. Monolog would likely be the more complete solution, but our own PSR-3 implementations would still offer sizeable benefits.

Psr\Log looks nice and sensible. Guess the first step would be to add that to core, as we'll need it either way.

Let's just put together a simple psr-3 based logging class to replace watchdog. Then we can switch it out later if needed and not impact any of the calling code.

I much prefer this approach because it separates the issues of a) replace watchdog with a classed object and b) evaluate monolog, which are very separate issues.

The attached patch adds the PSR-3 vendor library, and adds the most trivial wrapping class I could think of. Right now all it does is map from LoggerInterface to watchdog(), more or less. I figure this is a decent place to start as it gives us something to pass around, and as msonnabaum said once we have objects working with Psr\Log\LoggerInterface we can change out what goes on inside the logger object (or objects), including putting Monolog behind it, without changing the API.

I'd be fine if this went in as is, but I'm also happy to flesh it out and get rid of watchdog in the same patch. I can go either way.

+++ b/core/lib/Drupal/Core/WatchdogLogger.php
@@ -0,0 +1,83 @@
+      if (!in_array($key, array('exception', 'link'))) {

$context['link'] was just unset, so I don't think you need to check that here?

Otherwise looks good.
You (I suppose inadverdently) reverted a recent change to the composer file, and the Interface isn't actually added to the repository with this patch.

Ugh, damnit. Composer keeps trying to use git for dev downloads, which means I can't check them in. That's the second time it's goofed on me. I'll try to fix that tonight.

As for the revert, um, the rdf line was there when I pulled right before branching. Race condition? :-) What is it supposed to be? (The line in the patch there doesn't actually work since there is no 8.x release of that library, and the library's been renamed, but I didn't want to mess with it in this patch.)

msonnabaum: What would you consider the more fleshed out version that "gets rid of watchdog"? If we can get consensus on that quickly, let's do. If not, let's move forward with the minimalist approach here and we can do the fancier version in a follow-up and/or decide to replace it with Monolog.

Either way I consider the WatchdogLogger class to be an interim solution, which is fine.

Composer keeps trying to use git for dev downloads, which means I can't check them in.

Using "psr/log": "1.*@stable" will fix that. I may have some time today to help out here.

OK, let's try this again. With the library this time, and without b0rking easyrdf. Also fixes the tweak from #61.

I'd register the logger as 'logger' in Drupal's DI container, instead of 'logger.watchdog'. That name is more generic and will not cause any confusion if the actual implementation ever gets replaced by Monolog or anything else.

@msonnabaum, did you mean that calls to watchdog() should be replaced by drupal_container()->get('logger')->... as well, and deprecate or completely remove the watchdog() function? In case of removal, some more code needs to be copied over to the WatchdogLogger class.

@Cyberwolf I was talking about removing the watchdog function, but now that I think of it, maybe it should stay. Classes can have the logger injected, but it'd be pretty ugly for procedural calls to all be changed to drupal_container()->get('logger'). We have procedural wrappers for other services, so maybe it makes sense to not remove for now.

And I agree that this should just be registered as "logger". I also think the class should just be \Drupal\Logger. Watchdog doesn't really make sense here.

@msonnabaum, can you give me some examples of the procedural wrappers for other services? I took a quick look at http://api.drupal.org/api/drupal/core%21includes%21bootstrap.inc/functio... but that's quite a long list. At first sight most of those methods serve a certain distinct task requiring more logic than just 1 call on a service. IMHO leaving watchdog() like it is now in D8 would be a missed chance to fully embrace PSR-3 because module developers currently familiar with watchdog() will most likely keep on using it, postponing a possible BC break to D9 or later. Maybe that's a good thing for most people, "the short pain" is just my personal preference :)

I think the naming of the class is actually right, because the logger will still use hook_watchdog() for now if I understood well the barriers of the current approach for D8.

wtf, testbot? I rolled that right against HEAD...

The way PSR-3 is designed if we were to convert over to it entirely then each "type" or "channel" would become a separate service. Using the context array for it as I'm doing here is an ugly hack, which is just for temporary BC. What we'd really want to do is have a couple of different logging services, logger.system, logger.cron, logger.php, etc. That's fine, we'd just have to set it up. That's why I didn't go with just "logger". (As a side note that would allow us to log certain channels of error to the database, others to syslog, others to an SMS gateway, etc. Although at that point, I think we're getting into territory where Monolog would take less work.)

@Crell you must have uploaded the wrong patch at #65, it's the same as #58. and it still includes a submodule, that won't work...

Mostly, I think core will just configure a single logging service catching all channels, or possibly two (one to be used before DB is initialized, in-memory or in-cache, the other after it is, handled by the revamped dblog handler), and it will be up to contrib to expose additional instances and change the channel-to-service routing.

why would I remove this tag? didn't mean to do that.

fgm: That would be a feature regression from where we are now.

@crell: then I was not clear enough. The intent is not to reduce features, as you can guess. I'm just describing a possible minimal default configuration here. Obviously, the "contrib" term was improperly chosen, since syslog must obviously remain a core choice.

fgm: I think we're talking about different things. You're talking about the backend. I'm referring to the "channel", what watchdog() calls $type. The PSR-3 way to handle that is with separate objects for each channel, on the assumption that a given object will only be writing to one channel so you just set the channel on the object and call it a day.

Sigh, I was in the wrong directory, so uploaded the wrong patch file. Freshly rebased to account for the Routing patch moving things around in CoreBundle.

#78: 1289536-psr3-watchdog.patch queued for re-testing.

+++ b/core/lib/Drupal/Core/WatchdogLogger.php
@@ -0,0 +1,83 @@
+    array_walk($context, function(&$element, $key) {
+      if ($key != 'exception') {
+        $element = '@' . $element;
+      }
+    });

Doesn't this change the array values instead of the keys. I.e starting from $context['entity_type'] = 'node' I think this makes it $context['entity_type'] = '@node' instead of $context['@entity_type'] = 'node'.

It looks like WatchdogLogger isn't being used anywhere. Will be turning watchdog() into a wrapper around WatchdogLogger at some point? Move code from watchdog() over to the class itself? Let's make a follow up for that.

Doesn't this change the array values instead of the keys. I.e starting from $context['entity_type'] = 'node' I think this makes it $context['entity_type'] = '@node' instead of $context['@entity_type'] = 'node'.

I've hopefully addressed that in this patch.

Whitespace.

Rob: Where we go from here is still an open question. We could turn watchdog() into a wrapper for this object, keep this as a wrapper for watchdog(), replace both with broken-out logger objects for each "channel", or replace it wholesale with Monolog. I think all are on the table at the moment. However, this gets us something we can pass to objects that require the PSR LoggerInterface, which means that we can now start logging from Symfony objects. :-) And any Drupal objects that convert over to taking an injected LoggerInterface object can start logging now and don't need to change their API again.

I'd RTBC this, but since it's (mostly) my patch I shouldn't take advantage of the loophole of Rob fixing something. :-) We need to resync Symfony before we can start passing it into places.

+++ b/core/lib/Drupal/Core/WatchdogLogger.php
@@ -0,0 +1,85 @@
+      if ($key != 'exception') {

In case this gets a re-roll, it would be cool to add a comment here.

Marking RTBC anyway, because this is generally very clear and well documented.

We should add some tests for this, and also use it in a number of core functions (that are tested).

it actually blocks #1888734: Get rid of all 'bootstrap' hooks which is a critical task.

In that case, this should be a major priority task, right?

Once #1894002: Update vendor libraries and pin them to specific versions in composer.json is in, we can use this object for most of the Symfony objects that take a logger, since that update switches the Symfony classes to use the PSR-3 logger interface.

The psr/log library was just committed as part of #1894002: Update vendor libraries and pin them to specific versions in composer.json, since symfony/http-kernel had a dependency on it. This patch now explicitely pins prs/log to 1.0.0 in our composer.json. I'm using the latest version of composer, which seems to cause a bit of shuffling in composer.lock and installed.json. The "for_review" patch only shows the relevant bits for easier review without any noise from composer.

#90 looks good. Would be great to figure out how we can run composer update without so much noise in the composer.lock and installed.json files: if someone figures that out, please open a separate issue explaining what's needed.

Back to "needs work" for making this patch do something useful: whether that's tests per #87 or injecting the object to Symfony classes per #89 or both. Retitling accordingly.

Updated patch. This just injects the watchdog object into the services that could currently accept it. Let's see how badly it breaks. :-)

#92: 1289536-psr3-watchdog.patch queued for re-testing.

The latest patch seems to be missing the actual WatchdogLogger class.

It's not clear to me how this patch gets us any closer to removing hook_watchdog from the list of bootstrap hooks, which was originally a primary goal of this issue. Do we need to create a separate issue to focus on that now? This is in fact the only remaining bootstrap hook so it's all that stands in the way of removing the very concept of bootstrap hooks from D8.

Sigh. Git apply, you suck.

This doesn't remove hook_watchdog directly, but it moves any of the uses that would require it to be a bootstrap hook to using the object instead. That the logger object currently uses watchdog() internally is an implementation detail I expect we'll change in the next patch. (If someone feels comfortable coming up with a new approach for that now, I'm open to it.)

I wanted to work on that issue, though composer does someone really odd and fails with " Failed to clone http://github.com/symfony/Process.git via git, https and http protocols, aborting. ".
Fixed two small nitpicks, at least.

What's happening is composer thinks your local installation includes the git clones, but the .git folders aren't actually checked into Drupal. So you need to run rm -rf core/vendor/*/* prior to running composer update.

oh great, it still feels odd that this updates so much.

+++ b/core/lib/Drupal/Core/CoreBundle.phpundefined
@@ -326,7 +329,8 @@ protected function registerRouting(ContainerBuilder $container) {
+       -addArgument(new Reference('logger.watchdog'));

i guess thats why installation fails

Fixed it and tried locally, it installs succesfully..but composer generates too much noise..actual changes are 7KB
Hope this is helpful, since i am not exactly sure what should be done now? transfer watchdog() functionality in WatchdogLogger ?
And turn watchdog() to \Drupal::Watchdog maybe?

Looks pretty good to me, is there anything else we should stick into this patch?

+++ b/core/vendor/composer/autoload_classmap.phpundefined
@@ -3,350 +3,350 @@
-    'PHPUnit_Extensions_PhptTestCase' => $baseDir . '/vendor/phpunit/phpunit/PHPUnit/Extensions/PhptTestCase.php',
-    'PHPUnit_Extensions_PhptTestCase_Logger' => $baseDir . '/vendor/phpunit/phpunit/PHPUnit/Extensions/PhptTestCase/Logger.php',
-    'PHPUnit_Extensions_PhptTestSuite' => $baseDir . '/vendor/phpunit/phpunit/PHPUnit/Extensions/PhptTestSuite.php',
-    'PHPUnit_Extensions_RepeatedTest' => $baseDir . '/vendor/phpunit/phpunit/PHPUnit/Extensions/RepeatedTest.php',
-    'PHPUnit_Extensions_TestDecorator' => $baseDir . '/vendor/phpunit/phpunit/PHPUnit/Extensions/TestDecorator.php',
-    'PHPUnit_Extensions_TicketListener' => $baseDir . '/vendor/phpunit/phpunit/PHPUnit/Extensions/TicketListener.php',
-    'PHPUnit_Framework_Assert' => $baseDir . '/vendor/phpunit/phpunit/PHPUnit/Framework/Assert.php',
-    'PHPUnit_Framework_AssertionFailedError' => $baseDir . '/vendor/phpunit/phpunit/PHPUnit/Framework/AssertionFailedError.php',

The Composer additions are nothing to worry about. They're just follow ups from the composer.json move.

+++ b/core/lib/Drupal/Core/WatchdogLogger.phpundefined
@@ -0,0 +1,85 @@
+    }
+
+    watchdog($type, $message, $variables, $this->mapLevel($level), $link);

Do we have follow ups set up to move watchdog() over to use WatchdogLogger and the event subscriber?

well there is an issue with typehints
https://github.com/symfony-cmf/Routing/pull/53
Also i think some tests are needed, or replacing some of the current usage with the class, so we can say this is tested

postponed for #1977570: Update third-party vendors and fix composer.json we need to update routing

#103: 1289536-psr3-watchdog-103.patch queued for re-testing.

here is a reroll..but well, there are some updates again..easyrdf seems added quite some stufff..or dunno..this is a mess..
@RobLoach what did i mess?

or... you know.... psr logger is already there, so here is just the drupal thing

given, this is the last step for #1888734: Get rid of all 'bootstrap' hooks, i will move watchdog in this WatchdogLogger class and ... well, just quoting Crell from IRC:

ParisLiakos: Hm. In that case, it would probably be the same model as we use elsehwere: dblog and syslog both implement the PSR-3 log interface themselves, then the Watchdog logger also has an addLogger() method on it.

and then...well guess what..no more bootstrap hooks:)

One possible issue with that approach I just realized: watchdog() has the "type" concept (or more generically called "channel" in other loggers). PSR-3 does not, on the assumption that each "type" would be a DIFFERENT logger object you inject.

So, perhaps we then need to register a logger per type, same class but with a different literal in its constructor parameters in the DIC? That can still take all the same individual implementations (dblog, syslog, etc.), but would be responsible for shoe-horning the type into the context before passing it on (as we're doing in the class now). I'm not sure how big of a wrench that is.

I think the only drawback for module developers is that if they want their own "channel" they would need to copy ~3 lines of YAML to register it before injecting rather than just throwing new strings into watchdog() willy nilly. Which is arguably good, I suppose, as it helps reduce typo potential...

you know, fixing dblog and syslog was the easier part..now we have two nice tests that rely on hook_watchdog

• action_loop_test_watchdog
• entity_cache_test_watchdog

and they both rely on them with a unique way...that well, needs some research on how to migrate em correctly...anyways lets see what else fails beside those

w/e
at least hook_permissions is not going anywhere soon
this should be green

+++ b/core/includes/bootstrap.incundefined
@@ -1398,7 +1398,7 @@ function drupal_serve_page_from_cache(stdClass $cache) {
 function bootstrap_hooks() {
-  return array('watchdog');
+  return array();

i propose removing bootstrap_hooks() and friends in the parent META issue..or i should do it here?

+++ b/core/core.services.yml
@@ -96,6 +96,9 @@ services:
+  logger.watchdog:
+    class: Drupal\Core\WatchdogLogger
+    arguments: ['@request']

Is it redundant to call it logger.watchdog now, given that we're moving all the way over to this model? Shouldn't it be just logger or watchdog, but not both?

+++ b/core/includes/bootstrap.inc
@@ -1651,47 +1651,15 @@ function watchdog_exception($type, Exception $exception, $message = NULL, $varia
+  $context = array(
+    'type' => $type,
+    'variables' => $variables,
+    'link' => $link,

I think this is actually wrong. The way the PSR3 interface is defined, $context IS $variables. We just need to add type and link to it.

+++ b/core/lib/Drupal/Core/EventSubscriber/WatchdogRequestSubscriber.php
@@ -0,0 +1,62 @@
+  public function setWatchdogLoggerRequest(GetResponseEvent $event) {
+    if ($event->getRequestType() == HttpKernelInterface::MASTER_REQUEST) {
+      $this->watchdogLogger->setRequest($event->getRequest());
+    }
+  }

Actually, as of Symfony 2.3 the better way to do this is to call setRequest from the DIC configuration. That way the DIC can handle request scoping for us to set and reset the request when we go into subrequests.

If we just need this at the master level only, then... don't pass in the request object. Just pass in the data from the request object.

+++ b/core/lib/Drupal/Core/WatchdogLogger.php
@@ -0,0 +1,128 @@
+      'request_uri' => $base_root . request_uri(),

If we're passing in the request object, then request_ur() is totally not appropriate anymore. Neither is global $base_root.

As above, though, we should just be extracting the bits of the request we care about rather than keeping it around.

+++ b/core/lib/Drupal/Core/WatchdogLogger.php
@@ -0,0 +1,128 @@
+  public function addLogger(LoggerInterface $logger) {
+    $this->loggers[] = $logger;

We support a priority parameter everywhere else we're following this pattern. Let's do that here, too.

+++ b/core/modules/dblog/lib/Drupal/dblog/DbLogWatchdog.php
@@ -0,0 +1,61 @@
+    if (isset($context['variables']['backtrace'])) {
+      // Remove any backtraces since they may contain an unserializable variable.
+      unset($context['variables']['backtrace']);

unset() is safe to call on non-existent values, so you can skip the isset(). Same result either way.

+++ b/core/modules/syslog/lib/Drupal/syslog/SysLogWatchdog.php
@@ -0,0 +1,61 @@
+    global $base_url;

No need for this anymore, I'd think.

I don't think this addresses the DX question from #114, either. How do we want to handle that?

Actually, as of Symfony 2.3 the better way to do this is to call setRequest from the DIC configuration. That way the DIC can handle request scoping for us to set and reset the request when we go into subrequests.

Shouldnt we update to 2.3 first, then? also i am not sure i get what should i do

No need for this anymore, I'd think.

It is used 3 lines below:P

I don't think this addresses the DX question from #114, either. How do we want to handle that?

i dont think there is a DX problem? what is so bad with putting type inside context?

and the interdiff..i hope message_variables makes it clearier what is this about..variables was too general indeed

dont think there is a DX problem? what is so bad with putting type inside context?

i think the message variables could be more of DX problem than type

watchdog('rest', 'Deleted entity %type with ID %id.', array('%type' => $entity->entityType(), '%id' => $entity->id()));

using the injected service:

$this->logger->notice('Deleted entity %type with ID %id.', array('type'=>'rest', 'message_variables' =>array('%type' => $entity->entityType(), '%id' => $entity->id())));

Per the PSR-3 spec, Section 1.2:

The message MAY contain placeholders which implementors MAY replace with values from the context array.

Placeholder names MUST correspond to keys in the context array.

So using "message_variables" as a sub-key of the context array is not compatible with the specification.

For "channels", we discussed that at length in FIG and the general feeling was that PSR-3 was targeted at the stand-alone libraries, which only need one channel at a time, and thus "if you want multiple channels, make multiple objects." That was a deliberated design decision. (Drupal's watchdog() was discussed specifically as an existing implementation, and that was where we ended up.)

#121: 1289536-psr3-watchdog-121.patch queued for re-testing.

Re-roll.

Re @#124
I see. Then we have to resolve two things.not only $type.. but $link as well from the watchdog arguments:/

Having modules registering types doesnt sound really bad to me, since many modules use "domains"/"types" that are not their module name....examples? 'page not found' or 'access denied'

Anyway..how do we deal with $link?

link would be just another context key.

Perhaps we need to have a Watchdog object that is available to Drupal-specific code that has extra parameters, which it just collapses into context and passes on to the appropriate logger?

Or perhaps we should just do the simple original approach with the Watchdog class, pass that into the existing 3rd party libraries, and at least get that win while we figure it out?

i like the first approach better, the second one, still leave us stuck with the watchdog hook

So, i will make the Watchdog logger service not implementing the PSR logger interface (since its arguments will change), but it does holds an array of PSR loggers, and collapses parameters to the context array.
this way we have the same DX even when injecting it, and modules providing loggers are still PSR compatible loggers.

then we could phase out $link, (at least for me it doesnt make any sense and i never used it) and maybe after that move on with the $type proposal in #114

Given that we *do not* have any routing depending on $type only right now, I suggest we just move $type to 'type' in the context array. Just keep watchdog() parameters as they stand right now and merge $type into the $variables array.

To extend on #131 (and possibly contradict it): most mature logging frameworks have a separation between "the service that gives me a logging object" and "a logging object that I can use to log debug, notices, error, exceptions, etc.". Ideally, we would not try to mix those two functions, and PSR-3 is clearly only the second part of this.

Which means that ideally, I would like to see watchdog() implemented as:

function watchdog($type, $message, array $variables = NULL, $severity = WATCHDOG_NOTICE, $link = NULL) {
  Drupal::service('logging')->getLogger($type)->log($severity, $message, $context);
}

... or, if we want to make it simple and use the container as a service discovery mechanism, something like:

function watchdog($type, $message, array $variables = NULL, $severity = WATCHDOG_NOTICE, $link = NULL) {
  try {
    $logging = Drupal::service('logging.' . $type);
  }
  catch (\InvalidArgumentException $e) {
    $logging = Drupal::service('logging');
  }
  $logging->log($severity, $message, $context);
}

Something like #132 is my preference as well, and I think I suggested the latter option further up the thread (or maybe in IRC when talking with Paris). The caveat is that OO code should *not* be calling watchdog(), but getting an injected logger. In which case it will need to know (when it's wired into the DIC) which channel it wants, and thus which service (logger.page, logger.php, logger.block, etc.) should be injected. It also means that link becomes just another context value.

Mind you, I am entirely OK with that caveat. But it is a change from our current model to just use the PSR-3 interface directly like that.

@Crell: what you describe might be a reason to have "the service that gives me a logging object" as an actual service. This could be just a simple ContainerAware service with a single getLogger() method that implements the fallback I described in #132. As far as I know, the Symfony Container doesn't implement any form of fallback mechanism.

You're right, it does not. Why do we need one? The implication is "you're going to log to logger.bob? Make sure you have a logger.bob service. kthxbye." That's not necessarily a bad implication.

(Or we could just switch to Monolog like we were discussing 100 comments ago. *runs*)

After a lengthy irc discussion between Crell and msonnabaum, i picked most bits i could, and ended up with this. how does it look?

quick fix! and some tags:)

Also a note: I have not added channels for every module that needs one, so some tests might fail..i will do so in a few hours

+++ b/core/lib/Drupal/Core/Watchdog/WatchdogChannelFactory.php
@@ -0,0 +1,34 @@
+    try {
+      return $this->container->get('watchdog.channel.' . $channel);
+    }
+    catch (\InvalidArgumentException $e) {
+      return $this->container->get('watchdog.channel.default');

Can we use $this->container->has() here. Throwing at exception feels a little heavy, IMO.

Can we use $this->container->has() here. Throwing at exception feels a little heavy, IMO.

Agreed!

also added the getInfo method:/

some channel additions

This should be green and ready

+++ b/core/tests/Drupal/Tests/Core/Watchdog/WatchdogLoggerBaseTest.phpundefined
@@ -0,0 +1,76 @@
+        array('message' => 'User {username} created', 'context' => array('username' => 'rootatwc')),

This should be ParisLiakos :D

Totally a fan of both @rootatwc and @ParisLiakos, but I think it is more common to use things such as 'Dries' or 'Druplicon' in that case.

heh fun times!
i turned it to Dries since its shorter:P

Is monolog usage still on the roadmap or not? Because this whole watchdog + channels stuff is looking at lot like monolog, and uses the same PSR-3 interface anyway. I might be biased though :)

As the code wasn't written original by paris, it felt okay :)

@Seldaek
Next week is API freeze so it feels just impossible. With this change it seems to be that you could at least wrap monolog and use it for yourself.

Well strictly speaking you could swap in monolog and it wouldn't be an API change since it has the same PSR-3 interface. That said, if that is still a long term goal, and/or for the sake of forward compatibility and flexibility, I would advise you call the services logger/logger.channel instead of watchdog style names. It would be more generic and mean that changing the underlying implementation of the logger service to something else wouldn't make it feel strange. Watchdog probably sounds familiar to drupal folks, but it sounds more like an implementation specific thing to my external eye. Just my two cents anyway.

i am +1 renaming those services to logger.X than watchdog, but i heard yesterday on IRC that some people would have problem with that..we could do it in a followup just to not bikeshed this issue.

I'd be perfectly OK with logger.X, especially if it makes switching to Monolog (either after 1 July, via contrib, or in D9) a non-API-change. That's the whole idea behind standard interfaces. :-) I can also live with punting on that and getting this in, since even without Monolog considerations this issue still gets rid of our last bootstrap hook. Huzzah!

well, its the correct thing to do, lets make things easier for us:)

probably back to NR though

interdiff between #146 and #152

and here is a straight reroll, for the CoreBundle => CoreServiceProvider commit

#155: 1289536-psr3-watchdog-155.patch queued for re-testing.

one more test for this exception

FWIW, we have a nice candidate for a real use of PSR-3 in #2031199: drupal_set_message('whatever', 'error') should be integrated with logging.

And back.

reroll, conflicts in system.api.php

#161: 1289536-psr3-watchdog-161.patch queued for re-testing.

well, lets do the some optimizations, seems, i think simpler with a beer

Can we commit this so I can stop re-RTBCing interdiffs? :-)

strpos($key, '@') === 0 || strpos($key, '%') === 0 || strpos($key, '!') === 0

Why not:

$key[0] === '@' || $key[0] === '%' || $key[0] === '!'

Instead?

It is technically possible that a key would be just an empty string, and $key[0] would error out on that case.

!empty($key) && ($key[0] === '@' || $key[0] === '%' || $key[0] === '!')

There's chances that it will faster, empty() is a language construct while strpos() is a function. Direct access using an index on the string will be 3 times faster than parsing the full string to find the occurence (approximatively, depending on the string length of course) in all cases I think it will perform best. Notice that this is a very micro optimization, but the line is also smaller and more readable: it aims directly the first caracter and that's more explicit than doing strpos() calls.

they both look readable to me, and i believe the strpos one is easier to parse for a not so experienced PHP person..but well, i dont care that much tbh

This issue was RTBC and passing tests on July 1, the beginning of API freeze.

Not ready (I think) I played with the parseMessagePlaceholders() method, and this:
Test {with} two {encapsuled} strings
Becomes this:
Test @with} two {encapsuled strings
Because the preg_replace() function is greedy per default.

Two solutions:

• Use the ungreedy operator '/\{(.*)\}/U' for the regex
• Rewrite the regex as follows: '/\{([^}]*)\}/'

The first solution (ungreedy operator) seems faster at runtime.

Moreover I took the liberty testing the function and rewriting it a bit (see attached file) and make it between 15% and 25% faster depending on my test cases (which is probably not really reflecting reality): see first attached file.

I don't have a D8 environment here, I cannot provide a patch. Maybe I'll do it later. In all cases, the greedy regex must be fixed.

@pounard:
Can #171 (and #168, which I slightly prefer as well) possibly be a followup?
I mean, certainly this is a bug, but for this very moment an acceptable one to still get this committed. However, the patch in #164 contains all API changes and was RTBC before July 1.
Please move back #164 to RTBC, if you agree.
In the meantime, I worked your input from #171 into a followup patch, so it can be already tested.

You should probably use /\{(.*)\}/U as regex instead of /\{([^\}]*)\}/ it's both faster and more readable, aside I agree for followups.

I won't RTBC #164 without the preg fix.
Here is the exact replica of #164 just adding the 'U' regex modifier.

And here is the followup (stripped version removing a useless if() condition and replacing strpos() with index access on strings).

I mean, certainly this is a bug, but for this very moment an acceptable one to still get this committed.

there are no commitable bugs:P

@pounard thanks for the fix. since you added the fix for this can you also add a test case for the
Test {with} two {encapsuled} strings

And like i said i dont care if you replace the strpos with index access, it doesnt have to be a followup
Thanks

Oh okay. I did a manual patch edit, I don't a have a running D8 here, so it's gonna be difficult for me to write the test right now.

this should do it then:)

erm..and here it is without other random patches attached:/ sorry.. reposting the interdiff it is vs #164

Very nice, thanks.

there are no commitable bugs:P

We regularly commit 90% solutions with known regressions, as long as the regressions are immediately covered by a followup. But fine, let's roll in what we have.

this should do it then:)

Quite, but not yet...
Let's take a look at it one by one, so we don't lose oversight.

In #171, pounard proposed a number of improvements:

1.)
/\{(.*)\}/U instead of /\{([^\}]*)\}/ at least on my machine brings a minimal performance regression rather than a boost, but it's negligible and the regex is easier to read. So the ungreedy (first) variant is okay.

Now, strpos() is what's really slow, so...

2.)
replacing:
if (!empty($key) && ($key[0] === '@' || $key[0] === '%' || $key[0] === '!')) {
by:
if (strpos($key, '@') === 0 || strpos($key, '%') === 0 || strpos($key, '!') === 0) {
brings a 10-20% performance boost

3.)
and replacing:
if (!empty($key) && $key['0'] !== '@') {
by:
if (strpos($message, '@' . $key) !== FALSE) {
brings another 10-20% performance boost and is missing in #181.

4a.)
Finally, replacing:
if (($start = strpos($message, '{')) !== FALSE && strpos($message, '}') > $start) {
by:
if (($start = strpos($message, '{')) !== FALSE) {
brings a slight performance improvement, but leads to $has_ps3 erroneously being TRUE in some cases which might be the reason for the fails.

4b.)
So while at micro-optimizing, instead of 4a.) I'd propose to completely leave out the if clause, always run the preg_replace() on the string, and then compare the replaced string with the original one:
$has_ps3 = ($replaced !== $message);
This is significantly faster by another 10-20%. And surprisingly, it is still 10% faster, even if I add a bunch more messages to the test that contain no placeholders, so unnecessarily run through preg_replace().

Patch following.

@Pancho, i dont understand why you put it to needs work. i fixed the bug, lets *please* stop talk about performance micro-optimizations and get this in, like you proposed in #172, can we?

@Paris, then I don't understand why you said:

And like i said i dont care if you replace the strpos with index access, it doesnt have to be a followup

But okay, let the rest be a followup.

I'm sorry I didn't want to start a micro-optimisation flame war! I'm pro every improvement in this kind of algorithm, but if getting it commited is important to unblock other issues, please commit it, any further improvements, and Pancho's one are, can be in follow ups.

#181 is RTBC.

@Pancho, i see, i meant i didnt mind for the specific one, not that they could block this issue from being committed.
anyway, all cool, thanks

Yes, all cool, and no flame war in sight! :)
Definitely RTBC.

reroll

We discussed this a bit in IRC today.

The map method is mostly for BC. If we're fully switching to this model we can probably drop the old constants, although maybe not quite yet in this patch to keep rerolling easier.

A "debug" channel registered by system.module seems like a good addition.

We should be able to auto-add the setRequest() call to services in the compiler pass. That would reduce the boilerplate for setting up a new channel.

so, this adds the request in the compiler pass. its a lot better. also a 'debug' channel

watchdog('file') is used in core/incudes/file.inc, for example by file_unmanaged_copy(), so this needs to be defined somewhere more central than file module. If file module is disabled it'll fall back to system.

I am not sure whether this is something bad? falling back to "system" channel if file module is not enabled seems better to me, than having more logger services registered to system module.
But i can do either, it just requires some time, to go one by one service to see where it is called and if its module is available.

and a patch with the changes in the watchdog function:P

ok, so its only image and file that can be used when their modules are not enabled. i moved them to system module.
also added the missing channel for content_translation module

The interdiffs all look sane to me. Back up.

Retitling, to be kind to Alex. :-) (And because the old one was totally out of date.)

#196: 1289536-psr3-watchdog-196.patch queued for re-testing.

#196: 1289536-psr3-watchdog-196.patch queued for re-testing.

random test failures ftw -.-

Assigning to catch as he created the issue. I think we should profile the change since watchdog calls happen can happen alot on high traffic sites... for example during every user log in.