Add test coverage and/or one real use of PSR-3 based watchdog logger object

Looked through Monolog a bit more. The stacking is nice, it comes with several logging back ends (including syslog), generally looks pretty solid.

There's a couple of things that look tricky to me though:

http://api.drupal.org/api/drupal/includes--bootstrap.inc/function/watchdog

https://github.com/Seldaek/monolog/blob/master/src/Monolog/Logger.php#L160

Since Drupal 6, we've separated $message from $variables, for use with t() (or now format_string() would also work for something like syslog()).

This allows for a couple of features:

- messages can be translated on output into whichever language the current user is viewing the logs. See http://api.drupal.org/api/drupal/modules--dblog--dblog.admin.inc/functio...

- http://drupal.org/project/mongodb adds a capped collection per message - meaning that it'll log 1,000 each of the same message with different variables - that stops one particularly frequent log message evicting others which might be more important.

- I'm not sure if there's a module for it, but with dblog it's easy to run a query to find the top PHP errors etc checking type = 'php' then a count on variables and group by.

Apart from stuffing variables into $context which would be a hack, I don't see a way to do that with the API from Monolog.

There's also no 'type' variable which dblog and mongodb_log let you filter on, but we could arguably stuff that into context so less of an issue.

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.

$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.

This sounds similar yeah. Creating more logger instances doesn't sound too bad - should not be too many different loggers required during the same request except possibly background stuff.

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.

That'd be an E_STRICT warning no?

$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.

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.

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.

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.

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.

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.

Converting watchdog to a class is necessary to remove the concept of bootstrap hooks, so this issue might be exempt from feature freeze if we can't have sane bootstrap code without it. That shouldn't stop people from trying to get it done asap though.

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.

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.

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?

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

@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.

The last submitted patch, 1289536-with-monolog.patch, failed testing.

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

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

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().

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

@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.

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

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

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.

@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.

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++;

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

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.

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 last submitted patch, 1289536-psr3-watchdog.patch, failed testing.

$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.

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.

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

The last submitted patch, 1289536-psr3-watchdog.patch, failed testing.

@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.)

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.

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

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.

The last submitted patch, 1289536-psr3-watchdog.patch, failed testing.

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'.

Whitespace.

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.

I don't see this as a feature, it actually blocks #1888734: Get rid of all 'bootstrap' hooks which is a critical task.

Basic test coverage for the conversion prior to watchdog should be added here agreed.

The most obvious place to use this would be with the existing Symfony code that wants a logger but doesn't actually get one at the moment, but do we need to update Symfony to be able to do that?

I don't think there's much consensus on where to go after this patch - i.e. converting dblog and syslog to the new interface vs. adopting Monolog. I'd lean towards just converting dblog/syslog at the moment, Monolog can be added extremely easily via contrib.

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.

#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.

The last submitted patch, 1289536-psr3-watchdog.patch, failed testing.

The last submitted patch, 1289536-psr3-watchdog.patch, failed testing.

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.

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

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?

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?

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:)

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

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?

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.

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.

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.

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

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

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?

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