Problem/Motivation

  1. The Watchdog logging system is great as it allows modules to implement their own logging implementation to extend the way Drupal handles logging. Watchdog is getting rather dated, however, as more modern solutions of logging pop up.
  2. Many Symfony objects can receive an injected logger, but we cant inject watchdog(). This means that potential problems are not being logged

Proposed resolution

The PHP-FIG group has approved PSR-3, a standard logging interface, which was developed with an eye toward Drupal-friendliness.
https://github.com/php-fig/fig-standards/blob/master/accepted/PSR-3-logg...
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).
In order to adopt the PSR Logger, we must:

  1. Add a "logger.factory" service to the Dependency Injection Container.
  2. This factory produces logging channels (currently this is the $type parameter of watchdog())
  3. Each channel receives every logger registered in the container (eg, dblog(5), syslog(6) ). When the log() method is called on a channel, the channel calls the log() method on all the registered loggers.
  4. Make watchdog() post to the new logger factory service and deprecate it.
  5. Introduce a Dblog logger to dblog.module that logs to the database
  6. Add a SysLog logger to syslog.module, which uses PHP's syslog()

Remaining tasks

RTBC
Commit

User interface changes

No user interface changes.

API changes

  • watchdog($type, $message, $variables, $severity, $link) becomes deprecated in favor of \Drupal::logger($type)->log($severity, $message, $variables) or any of the helper methods of Psr\Log\LoggerTrait
    eg \Drupal::logger($type)->warning($message, $variables)
  • hook_warchdog() is gone. For a module to implement a logger, it has to register a service tagged as logger. eg
    services:
    
      logger.mylog:
        class: Drupal\mylog\Logger\MyLog
        tags:
          - { name: logger }

    This class must implement this \Psr\Log\LoggerInterface

Original report by catch

hook_watchdog() is a good candidate for moving out of the hook system into pluggable (and in this case stackable) classes - we want it to be available as early as possible, however currently it's not available until bootstrap modules are loaded - too late if you want to log in a cache backend or the lock system for any reason.

However hook_watchdog() is a small part of what our existing logging modules do. dblog has settings for expiring log items and an admin page for viewing/filtering log entries. Syslog has an admin screen, mongodb in contrib has an improved version of the dblog UI. So those would likely stay more or less the same - just the actual logging backend called from watchdog() would be different.

If we moved logging to OOP, I'd want to keep the same basic feature of being able to have more than one logger enabled at a time - it's handy to be able to log different messages to different storage etc.

In #1263478: Identify pieces of Drupal that could be replaced by Symfony code https://github.com/Seldaek/monolog was brought up.

I had a very quick glance at the Monolog code mainly to see if it supports more than one handler (which it does). That would be a showstopper if not, have not looked beyond this though yet.

Files: 
CommentFileSizeAuthor
#309 1289536.309.patch56.58 KBalexpott
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 71,772 pass(es). View
#309 289-309-interdiff.txt1.2 KBalexpott
#307 psr-logger.307.patch55.77 KBParisLiakos
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] Setup environment: Test cancelled by admin prior to completion. View
#295 interdiff-psr3-282-vs-289.txt17.56 KBParisLiakos
#289 interdiff-psr3.txt11.49 KBParisLiakos
#289 psr-logger.289.patch55.53 KBParisLiakos
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 71,584 pass(es). View
#287 interdiff-psr3.txt2.69 KBParisLiakos
#285 interdiff-psr3.txt24.34 KBParisLiakos
#285 psr-logger.285.patch61.13 KBParisLiakos
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] 70,699 pass(es), 131 fail(s), and 0 exception(s). View
#274 psr-logger.272.patch57.25 KBParisLiakos
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 66,835 pass(es). View
#270 psr-logger.interdiff.txt6.79 KBParisLiakos
#270 psr-logger.270.patch57.14 KBParisLiakos
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] 66,889 pass(es), 6 fail(s), and 1 exception(s). View
#269 psr-logger.interdiff.txt521 bytesParisLiakos
#269 psr-logger.269.patch57.25 KBParisLiakos
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 66,766 pass(es). View
#262 psr-logger.interdiff.txt1.68 KBParisLiakos
#260 psr-logger.interdiff.txt21.23 KBParisLiakos
#260 psr-logger.260.patch50.45 KBParisLiakos
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] 66,512 pass(es), 0 fail(s), and 2 exception(s). View
#258 psr-logger.258.patch40.99 KBParisLiakos
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] 66,425 pass(es), 3 fail(s), and 2 exception(s). View

Comments

lsmith77’s picture

subscribe

catch’s picture

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

watchdog($type, $message, $variables = array(), $severity = WATCHDOG_NOTICE, $link = NULL)

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

  public function addRecord($level, $message, array $context = array())

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.

Crell’s picture

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.

Seldaek’s picture

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.

msonnabaum’s picture

Subscribing.

catch’s picture

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

Seldaek’s picture

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.

RobLoach’s picture

catch’s picture

They're the same issue IMO, I've marked the other as duplicate since this is much older, and it has discussion of monolog which was being considered on the other issue without nearly as much discussion.

RobLoach’s picture

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.

catch’s picture

The dblog and syslog modules register their handlers to the Logger object to the "watchdog" object within the Container

How do they do that though?

Could we consider moving watchdog logger configuration to settings.php similar to database drivers and cache backends? That would absolutely kill the necessity for any module to be loaded before the logging handler can be used so they'd work a lot earlier than they do now.

Then you can configure the handlers there - don't think we need a UI for it since choice of logging tool is pretty advanced.

The actual module part of syslog and dblog modules then would just be an admin interface/reports screen which would be optional-ish.

Not sure we want to keep watchdog() forever, but yeah definitely that'd be great for temporary backwards compatibility.

Crell’s picture

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.

RobLoach’s picture

Status: Active » Needs work
FileSize
186.82 KB
FAILED: [[SimpleTest]]: [MySQL] Unable to apply patch 1289536.patch. Unable to apply patch. See the log in the details link for more information. View

It's a start.

fgm’s picture

FileSize
5.3 KB
FAILED: [[SimpleTest]]: [MySQL] Unable to apply patch 0002-Initial-version-ugly-but-works.patch. Unable to apply patch. See the log in the details link for more information. View
227.13 KB
FAILED: [[SimpleTest]]: [MySQL] Invalid patch format in 0001-First-draft-of-watchdog-rework-with-Symfony-watchdog.patch. View

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’s picture

FileSize
230.83 KB
FAILED: [[SimpleTest]]: [MySQL] Invalid patch format in 0001-Issue-1289536-Take-hook_watchdog-out-of-the-hook-sys.patch. View

Or in just one patch on curreny head.

Crell’s picture

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.

Crell’s picture

Title: Take hook_watchdog() out of the hook system into classes » Adopt Monolog for logging

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

fgm’s picture

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.

Crell’s picture

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

catch’s picture

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.

RobLoach’s picture

FileSize
231.62 KB
PASSED: [[SimpleTest]]: [MySQL] 42,174 pass(es). View

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*();
Crell’s picture

Status: Needs work » Needs review

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.

RobLoach’s picture

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

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

claudiu.cristea’s picture

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.

Crell’s picture

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

msonnabaum’s picture

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?

fgm’s picture

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

RobLoach’s picture

Status: Needs review » Needs work
FileSize
19.03 KB
FAILED: [[SimpleTest]]: [MySQL] Unable to apply patch monolog-needs-1810664.patch. Unable to apply patch. See the log in the details link for more information. View

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’s picture

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 ?

Seldaek’s picture

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

RobLoach’s picture

Component: base system » watchdog.module
Status: Needs work » Needs review
Issue tags: +watchdog, +Dependency Injection (DI)
FileSize
288.13 KB
FAILED: [[SimpleTest]]: [MySQL] Drupal installation failed. View
23.47 KB
FAILED: [[SimpleTest]]: [MySQL] Drupal installation failed. View

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.

Anonymous’s picture

Issue summary: View changes

Fixing typo.

fgm’s picture

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.

Crell’s picture

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

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

fgm’s picture

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.

fgm’s picture

FileSize
17.93 KB
FAILED: [[SimpleTest]]: [MySQL] Unable to apply patch 0002-Issue-1289536-Adopt-Monolog-for-logging-on-top-of-18.patch. Unable to apply patch. See the log in the details link for more information. View
279.03 KB
FAILED: [[SimpleTest]]: [MySQL] Unable to apply patch 0001-Issue-1810664-by-Rob-Loach-Add-Monolog-Symfony-Bridg.patch. Unable to apply patch. See the log in the details link for more information. View

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’s picture

Issue tags: +Legal

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

Adding Legal tag for this reason.

Seldaek’s picture

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

fgm’s picture

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

Seldaek’s picture

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

cweagans’s picture

Issue tags: -Legal

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.

mitchell’s picture

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

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

fgm’s picture

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.

msonnabaum’s picture

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’s picture

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.

RobLoach’s picture

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

RobLoach’s picture

Sylvain Lecoy’s picture

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

scor’s picture

Status: Postponed » Needs work
webchick’s picture

Category: task » feature

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.

catch’s picture

Title: Adopt Monolog for logging » Refactor hook_watchdog() so it's not a bootstrap hook
Category: feature » task

Monolog itself is a feature. But refactoring watchdog to not be a 'bootstrap hook' is veering close to a critical task unless #1331486: Move module_invoke_*() and friends to an Extensions class does it for us, and that's all the original issue wanted. Re-titling to make this more clear, and moving back to task.

fgm’s picture

@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

Sylvain Lecoy’s picture

Of course thank you for the link I appreciate :)

Crell’s picture

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.

sun’s picture

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

msonnabaum’s picture

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.

Crell’s picture

Title: Refactor hook_watchdog() so it's not a bootstrap hook » Add PSR-3 based watchdog logger object
Status: Needs work » Needs review
FileSize
15.24 KB
FAILED: [[SimpleTest]]: [MySQL] 50,832 pass(es), 1 fail(s), and 2 exception(s). View

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.

msonnabaum’s picture

Status: Needs work » Needs review

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.

tstoeckler’s picture

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

Crell’s picture

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

Crell’s picture

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.

RobLoach’s picture

Status: Needs review » Needs work

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.

Crell’s picture

Status: Needs work » Needs review
FileSize
15.24 KB
FAILED: [[SimpleTest]]: [MySQL] Unable to apply patch 1289536-psr3-watchdog_0.patch. Unable to apply patch. See the log in the details link for more information. View

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

Cyberwolf’s picture

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.

msonnabaum’s picture

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

Cyberwolf’s picture

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

catch’s picture

cache() and lock() are two wrappers still in there that are equivalent, low-level functionality. I'm not prepared to get rid of those wrappers until #1875086: Improve DX of drupal_container()->get() is resolved. watchdog() is slightly different in that it won't return a logger instance but regardless that's something we can look at in a separate issue.

Crell’s picture

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

scor’s picture

Issue tags: -watchdog

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

fgm’s picture

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.

scor’s picture

Issue tags: +watchdog

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

Crell’s picture

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

fgm’s picture

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

Crell’s picture

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.

Crell’s picture

Status: Needs work » Needs review
FileSize
29.37 KB
PASSED: [[SimpleTest]]: [MySQL] 50,637 pass(es). View

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.

Crell’s picture

Status: Needs work » Needs review
Issue tags: +watchdog, +Dependency Injection (DI)

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

tstoeckler’s picture

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

RobLoach’s picture

FileSize
29.45 KB
PASSED: [[SimpleTest]]: [MySQL] 50,661 pass(es). View

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.

RobLoach’s picture

FileSize
29.47 KB
PASSED: [[SimpleTest]]: [MySQL] 50,699 pass(es). View

Whitespace.

Crell’s picture

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.

tstoeckler’s picture

Status: Needs review » Reviewed & tested by the community
+++ 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.

Dries’s picture

Category: task » feature
Status: Reviewed & tested by the community » Needs work
Issue tags: +Needs tests

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

catch’s picture

Category: feature » task

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.

effulgentsia’s picture

Priority: Normal » Major

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?

Crell’s picture

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.

scor’s picture

Status: Needs work » Needs review
FileSize
22.8 KB
PASSED: [[SimpleTest]]: [MySQL] 49,162 pass(es). View
3.5 KB

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.

effulgentsia’s picture

Title: Add PSR-3 based watchdog logger object » Add test coverage and/or one real use of PSR-3 based watchdog logger object
Status: Needs review » Needs work

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

Crell’s picture

Status: Needs work » Needs review
FileSize
24.44 KB
FAILED: [[SimpleTest]]: [MySQL] Drupal installation failed. View

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

scor’s picture

Status: Needs work » Needs review

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

katbailey’s picture

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.

Crell’s picture

Status: Needs work » Needs review
FileSize
26.89 KB
FAILED: [[SimpleTest]]: [MySQL] Drupal installation failed. View

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

dawehner’s picture

FileSize
26.89 KB
FAILED: [[SimpleTest]]: [MySQL] Unable to apply patch 1289536-psr3-watchdog-99.patch. Unable to apply patch. See the log in the details link for more information. View

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.

effulgentsia’s picture

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.

dawehner’s picture

Status: Needs work » Needs review
FileSize
37.33 KB
FAILED: [[SimpleTest]]: [MySQL] Drupal installation failed. View

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

ParisLiakos’s picture

Status: Needs work » Needs review
FileSize
86.72 KB
FAILED: [[SimpleTest]]: [MySQL] Unable to apply patch 1289536-psr3-watchdog-103.patch. Unable to apply patch. See the log in the details link for more information. View
7.17 KB
+++ 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?

RobLoach’s picture

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?

ParisLiakos’s picture

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

ParisLiakos’s picture

Status: Needs work » Postponed

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

RobLoach’s picture

Status: Postponed » Needs review
RobLoach’s picture

ParisLiakos’s picture

Status: Needs work » Needs review
FileSize
1.16 MB
PASSED: [[SimpleTest]]: [MySQL] 55,813 pass(es). View

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?

ParisLiakos’s picture

FileSize
5.78 KB
PASSED: [[SimpleTest]]: [MySQL] 55,488 pass(es). View

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

ParisLiakos’s picture

Assigned: Unassigned » ParisLiakos
Status: Needs review » Needs work

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

Crell’s picture

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

ParisLiakos’s picture

Status: Needs work » Needs review
FileSize
21.68 KB
FAILED: [[SimpleTest]]: [MySQL] 55,414 pass(es), 4 fail(s), and 0 exception(s). View

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

ParisLiakos’s picture

Status: Needs work » Needs review
FileSize
26.58 KB
PASSED: [[SimpleTest]]: [MySQL] 55,361 pass(es). View

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

ParisLiakos’s picture

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

Crell’s picture

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

Crell’s picture

Status: Needs review » Needs work
ParisLiakos’s picture

Status: Needs work » Needs review
FileSize
27.77 KB
FAILED: [[SimpleTest]]: [MySQL] Unable to apply patch 1289536-psr3-watchdog-121.patch. Unable to apply patch. See the log in the details link for more information. View

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?

ParisLiakos’s picture

FileSize
10.14 KB

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

ParisLiakos’s picture

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())));
Crell’s picture

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

kerasai’s picture

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

socketwench’s picture

Status: Needs work » Needs review
FileSize
27.77 KB
None View

Re-roll.

ParisLiakos’s picture

Assigned: ParisLiakos » Unassigned
Status: Needs review » Needs work

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?

Crell’s picture

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?

ParisLiakos’s picture

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

Damien Tournoud’s picture

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.

Damien Tournoud’s picture

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);
}
Crell’s picture

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.

Damien Tournoud’s picture

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

Crell’s picture

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

ParisLiakos’s picture

Status: Needs work » Needs review
FileSize
35.9 KB
FAILED: [[SimpleTest]]: [MySQL] Failed to run tests: tests were executed, but no results were found. View

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

ParisLiakos’s picture

Issue tags: +phpunit, +PHPUnit Blocker
FileSize
693 bytes
35.9 KB
FAILED: [[SimpleTest]]: [MySQL] Failed to run tests: tests were executed, but no results were found. View

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

tstoeckler’s picture

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

ParisLiakos’s picture

Status: Needs work » Needs review
FileSize
1.49 KB
36.18 KB
FAILED: [[SimpleTest]]: [MySQL] 58,592 pass(es), 5 fail(s), and 2 exception(s). View

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

Agreed!

also added the getInfo method:/

ParisLiakos’s picture

Status: Needs work » Needs review
FileSize
7.76 KB
47.15 KB
FAILED: [[SimpleTest]]: [MySQL] 57,990 pass(es), 5 fail(s), and 2 exception(s). View

some channel additions

ParisLiakos’s picture

FileSize
1.21 KB
48.87 KB
PASSED: [[SimpleTest]]: [MySQL] 58,391 pass(es). View

This should be green and ready

jibran’s picture

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

tstoeckler’s picture

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.

ParisLiakos’s picture

FileSize
1.89 KB
48.85 KB
PASSED: [[SimpleTest]]: [MySQL] 58,445 pass(es). View

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

Seldaek’s picture

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

dawehner’s picture

Status: Needs review » Reviewed & tested by the community

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.

Seldaek’s picture

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.

ParisLiakos’s picture

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.

Crell’s picture

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!

ParisLiakos’s picture

FileSize
48.33 KB
PASSED: [[SimpleTest]]: [MySQL] 58,222 pass(es). View

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

ParisLiakos’s picture

Status: Reviewed & tested by the community » Needs review

probably back to NR though

ParisLiakos’s picture

FileSize
33.83 KB

interdiff between #146 and #152

ParisLiakos’s picture

FileSize
48.48 KB
PASSED: [[SimpleTest]]: [MySQL] 56,386 pass(es). View

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

ParisLiakos’s picture

Status: Needs work » Needs review
Issue tags: +phpunit, +Dependency Injection (DI), +PHPUnit Blocker

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

ParisLiakos’s picture

FileSize
48.75 KB
PASSED: [[SimpleTest]]: [MySQL] 56,617 pass(es). View
1.48 KB

one more test for this exception

fgm’s picture

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.

Crell’s picture

Status: Needs review » Reviewed & tested by the community

And back.

ParisLiakos’s picture

FileSize
48.74 KB
PASSED: [[SimpleTest]]: [MySQL] 56,791 pass(es). View

reroll, conflicts in system.api.php

ParisLiakos’s picture

Status: Needs work » Needs review
Issue tags: +phpunit, +Dependency Injection (DI), +PHPUnit Blocker

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

ParisLiakos’s picture

FileSize
940 bytes
48.66 KB
PASSED: [[SimpleTest]]: [MySQL] 56,618 pass(es). View

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

Crell’s picture

Status: Needs review » Reviewed & tested by the community

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

pounard’s picture

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

Why not:

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

Instead?

Seldaek’s picture

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

pounard’s picture

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

ParisLiakos’s picture

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

YesCT’s picture

Issue tags: +RTBC July 1

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

pounard’s picture

Status: Reviewed & tested by the community » Needs work
FileSize
1.25 KB
7.09 KB

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.

Pancho’s picture

Status: Needs work » Needs review
FileSize
2.3 KB
48.61 KB
FAILED: [[SimpleTest]]: [MySQL] 56,674 pass(es), 1 fail(s), and 12 exception(s). View

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

pounard’s picture

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

pounard’s picture

Status: Needs work » Needs review
FileSize
48.66 KB
PASSED: [[SimpleTest]]: [MySQL] 56,737 pass(es). View

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

pounard’s picture

FileSize
48.62 KB
FAILED: [[SimpleTest]]: [MySQL] 56,680 pass(es), 0 fail(s), and 4 exception(s). View

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

ParisLiakos’s picture

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

pounard’s picture

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.

ParisLiakos’s picture

Status: Needs work » Needs review
FileSize
2 KB
67.77 KB
FAILED: [[SimpleTest]]: [MySQL] Failed to run tests: PHP Fatal error encountered during run_tests.sh. See review log for details.. View

this should do it then:)

ParisLiakos’s picture

FileSize
2 KB
49 KB
PASSED: [[SimpleTest]]: [MySQL] 56,684 pass(es). View

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

pounard’s picture

Very nice, thanks.

Pancho’s picture

Status: Needs review » Needs work

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.

ParisLiakos’s picture

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

Pancho’s picture

Status: Needs work » Needs review

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

pounard’s picture

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.

pounard’s picture

Status: Needs review » Reviewed & tested by the community

#181 is RTBC.

ParisLiakos’s picture

@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

Pancho’s picture

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

ParisLiakos’s picture

FileSize
49.13 KB
PASSED: [[SimpleTest]]: [MySQL] 56,998 pass(es). View

reroll

catch’s picture

Status: Reviewed & tested by the community » Needs work
+++ b/core/lib/Drupal/Core/Logger/LoggerChannel.phpundefined
@@ -0,0 +1,147 @@
+    // @todo Retrieve from request once https://drupal.org/node/1890878 is in.

#1890878: Add modular authentication system, including Http Basic; deprecate global $user is in.

+++ b/core/lib/Drupal/Core/Logger/LoggerChannel.phpundefined
@@ -0,0 +1,147 @@
+  protected function mapLevel($level) {
+    if (empty($this->levelTranslation)) {
+      // Use PHP constants to keep this unit-testable.
+      $this->levelTranslation = array(
+        LogLevel::EMERGENCY => LOG_EMERG,
+        LogLevel::ALERT => LOG_ALERT,
+        LogLevel::CRITICAL => LOG_CRIT,
+        LogLevel::ERROR => LOG_ERR,
+        LogLevel::WARNING => LOG_WARNING,
+        LogLevel::NOTICE => LOG_NOTICE,
+        LogLevel::INFO => LOG_INFO,
+        LogLevel::DEBUG => LOG_DEBUG,
+      );

These mean the same thing, why map? Needs a better comment.

+++ b/core/lib/Drupal/Core/Logger/LoggerChannelFactory.phpundefined
@@ -0,0 +1,35 @@
+  /**
+   * Retrieves the registered logger for the requested channel.
+   *
+   * If the channel does not exist, the default "system" channel is being used.
+   *
+   * @return \Psr\Log\LoggerInterface
+   *   The registered logger for this channel.
+   */
+  public function getLogger($channel) {
+    $channel_service = 'logger.channel.' . str_replace(' ', '_', $channel);
+    if ($this->container->has($channel_service)) {
+      return $this->container->get($channel_service);
+    }
+    else {
+      return $this->container->get('logger.channel.default');
+    }

It's not great that each channel has to be a service. I brought this up in follow-up #2 or #3 of this issue and still don't like it much.

I've used one-off watchdog channels for debugging (particularly for 'only on staging' type bugs) and I'm sure plenty of other people have as well. If there's no way around one-off channels we might need to consider an 'debug' channel or similar that's permantently there or something. Also see below - at least one channel in the patch is defined in the wrong place, meaning it'll be missing if that module is disabled and fall back to system.

+++ b/core/modules/aggregator/aggregator.services.ymlundefined
@@ -13,3 +13,10 @@ services:
+  logger.channel.aggregator:
+    class: Drupal\Core\Logger\LoggerChannel
+    arguments: ['aggregator']
+    calls:
+      - [setRequest, ['@?request']]
+    tags:

Then this is a fair amount of boilerplate just to log to watchdog with your module name.

+++ b/core/modules/dblog/lib/Drupal/dblog/Logger/DbLog.phpundefined
@@ -0,0 +1,61 @@
+  /**
+   * {@inheritdoc}
+   */
+  public function log($level, $message, array $context = array()) {
+    // Remove any backtraces since they may contain an unserializable variable.
+    unset($context['backtrace']);
+

Looking at the way channel gets translated to type- why not use the default channel, but then pass the string down as whatever gets passed, wouldn't that solve the custom/one-off logging need? There doesn't seem to be a particular reason why the message type has to be so strictly tied to the channel.

+++ b/core/modules/dblog/lib/Drupal/dblog/Tests/DbLogTest.phpundefined
index 2ded051..e9f928a 100644
--- a/core/modules/file/file.services.yml

--- a/core/modules/file/file.services.yml
+++ b/core/modules/file/file.services.ymlundefined

+++ b/core/modules/file/file.services.ymlundefined
+++ b/core/modules/file/file.services.ymlundefined
@@ -2,3 +2,10 @@ services:

@@ -2,3 +2,10 @@ services:
   file.usage:
     class: Drupal\file\FileUsage\DatabaseFileUsageBackend
     arguments: ['@database']
+  logger.channel.file:
+    class: Drupal\Core\Logger\LoggerChannel
+    arguments: ['file']
+    calls:
+      - [setRequest, ['@?request']]
+    tags:

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 didn't check the others.

Crell’s picture

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.

ParisLiakos’s picture

Status: Needs work » Needs review
FileSize
16.33 KB
46.13 KB
FAILED: [[SimpleTest]]: [MySQL] Setup environment: Test cancelled by admin prior to completion. View

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.

ParisLiakos’s picture

FileSize
3.35 KB
48.32 KB
FAILED: [[SimpleTest]]: [MySQL] 56,660 pass(es), 1 fail(s), and 0 exception(s). View

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

ParisLiakos’s picture

Status: Needs work » Needs review
FileSize
2.35 KB
48.43 KB
PASSED: [[SimpleTest]]: [MySQL] 56,789 pass(es). View

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

Crell’s picture

Status: Needs review » Reviewed & tested by the community

The interdiffs all look sane to me. Back up.

Crell’s picture

Title: Add test coverage and/or one real use of PSR-3 based watchdog logger object » Switch Watchdog to a PSR-3 logging framework

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

Crell’s picture

ParisLiakos’s picture

Status: Needs work » Needs review
Issue tags: +phpunit, +Dependency Injection (DI), +PHPUnit Blocker, +RTBC July 1

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

ParisLiakos’s picture

Status: Needs review » Reviewed & tested by the community

random test failures ftw -.-

alexpott’s picture

Assigned: Unassigned » catch
Issue tags: +Needs profiling

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.

catch’s picture

Status: Reviewed & tested by the community » Needs work

Agreed on profiling. Gave this another review and it still doesn't look quite right to me.

Registering a service for each logging channel still feels like a lot of boilerplate to me. At a minimum there should be more examples in the code as to how the channels are useful - right now it just looks like a workaround for the limitations of the PSR-3 logging interface, which it mostly is.

Being able to route different channels to different loggers could be useful, but I can see that being more useful for severity than type. For example why would I want to route 'taxonomy' and 'rest test' to different loggers?.

Also several less serious issues, although the constants one is a regression:

+++ b/core/lib/Drupal/Core/Logger/LoggerBase.phpundefined
@@ -0,0 +1,60 @@
+      // Replace PS3 messages containing placeholders.

PS3? This appears multiple times across the patch, did anyone actually review the whole patch before it got to RTBC?

+++ b/core/lib/Drupal/Core/Logger/LoggerChannel.phpundefined
@@ -0,0 +1,159 @@
+  protected function mapLevel($level) {
+    if (empty($this->levelTranslation)) {
+      // Use PHP constants which are the same with watchdog's ones to keep this
+      // unit-testable.
+      $this->levelTranslation = array(
+        LogLevel::EMERGENCY => LOG_EMERG,
+        LogLevel::ALERT => LOG_ALERT,
+        LogLevel::CRITICAL => LOG_CRIT,
+        LogLevel::ERROR => LOG_ERR,
+        LogLevel::WARNING => LOG_WARNING,
+        LogLevel::NOTICE => LOG_NOTICE,
+        LogLevel::INFO => LOG_INFO,
+        LogLevel::DEBUG => LOG_DEBUG,
+      );

These should map to the WATCHDOG constants, not the PHP constants. The PHP constants are incorrect on Windows. This is well documented in bootstrap.inc


+services:
+  logger.channel.rest_test:
+    class: Drupal\Core\Logger\LoggerChannel
+    arguments: ['rest_test']
+    calls:
+      - [setRequest, ['@?request']]
+    tags:
+      - { name: logger_channel }

@@ -0,0 +1,6 @@
+services:
+  logger.channel.search:
+    class: Drupal\Core\Logger\LoggerChannel
+    arguments: ['search']
+    tags:
+      - { name: logger_channel }
diff --git a/core/modules/syslog/lib/Drupal/syslog/Logger/SysLog.php b/core/modules/syslog/lib/Drupal/syslog/Logger/SysLog.php

Why does one call setRequest and the other not?

Seldaek’s picture

catch: Regarding routing channels to different places, I know people use that in Sf2 to log specific things into different files, but the good thing with having one logger per channel and then similar handlers is that you can easily route some types of messages to one log where you just want the essential, but also keep those logs in the main log so if you look at the complete log you have still everything in one place. Moreover the instantiation of a logger really isn't much, and you shouldn't have a gazillion I guess, Sf2 only comes with a few channels (request, doctrine, app, probably a couple I forget but that's not so many). See more configuration details at http://symfony.com/doc/current/cookbook/logging/channels_handlers.html

catch’s picture

@Seldaek, I just checked a client site and they had 27 watchdog 'types' (now channels) in their active log. Most of this is because Drupal modules tend to give their own module name as type.

Seldaek’s picture

@catch: Does that mean 27 in a single request? Or overall across all the execution paths? Also can't this situation be improved by communicating new guidelines to module authors? If the main modules consolidate to a few "official" types I suppose having a longtail of fringe modules using custom types won't be as bad.

catch’s picture

Assigned: catch » Unassigned

@Seldaek that's 27 recently logged watchdog types, not one request, but also likely not all possible ones.

The current patch here doesn't do any consolidation, it moves all the existing types used in core over to channels. So that could potentially be improved, but it's not been discussed much yet.

Also unassigning me since I've reviewed the patch.

ParisLiakos’s picture

Status: Needs work » Needs review
FileSize
48.53 KB
FAILED: [[SimpleTest]]: [MySQL] 58,123 pass(es), 3 fail(s), and 0 exception(s). View

straight reroll

ParisLiakos’s picture

FileSize
3.91 KB
48.44 KB
FAILED: [[SimpleTest]]: [MySQL] 58,041 pass(es), 1 fail(s), and 0 exception(s). View

Fixes the non-important points in #209

ParisLiakos’s picture

So this patch here introduces 36 logger channels..I went through them and most make perfect sense to be a channel on their own

+++ b/core/modules/node/node.services.ymlundefined
@@ -7,3 +7,13 @@ services:
+  logger.channel.content:
+    class: Drupal\Core\Logger\LoggerChannel
+    arguments: ['content']
+    tags:
+      - { name: logger_channel }
+  logger.channel.node:
+    class: Drupal\Core\Logger\LoggerChannel
+    arguments: ['node']
+    tags:
+      - { name: logger_channel }

+++ b/core/modules/rest/rest.services.ymlundefined
@@ -20,3 +20,8 @@ services:
+      - { name: logger_channel }

Those could be consolidated to one, but i checked core and node is being used for content types CRUD, content for nodes CRUD, so it might make sense to keep those different.

+++ b/core/modules/content_translation/content_translation.services.ymlundefined
@@ -2,3 +2,8 @@ services:
+  logger.channel.content_translation:
+    class: Drupal\Core\Logger\LoggerChannel
+    arguments: ['content translation']
+    tags:
+      - { name: logger_channel }

+++ b/core/modules/language/language.services.ymlundefined
@@ -5,3 +5,8 @@ services:
+  logger.channel.language:
+    class: Drupal\Core\Logger\LoggerChannel
+    arguments: ['language']
+    tags:
+      - { name: logger_channel }

+++ b/core/modules/locale/locale.services.ymlundefined
@@ -16,3 +16,8 @@ services:
+  logger.channel.locale:
+    class: Drupal\Core\Logger\LoggerChannel
+    arguments: ['locale']
+    tags:
+      - { name: logger_channel }

Maybe consolidate those to a multilingual channel?

webchick’s picture

Issue tags: +Approved API change

Tagging as an approved API change, per catch.

ParisLiakos’s picture

Status: Needs work » Needs review
FileSize
47.41 KB
FAILED: [[SimpleTest]]: [MySQL] 58,099 pass(es), 0 fail(s), and 1 exception(s). View

So, rerolled and fixed failing test, hopefully this is green again

ParisLiakos’s picture

Status: Needs work » Needs review
FileSize
724 bytes
48.36 KB
PASSED: [[SimpleTest]]: [MySQL] 58,123 pass(es). View

so this is actually working, we found a bug in the FilterSettingsTest..and well who knows how much more..in my dblog i have all kind of messages from routing..
yay for wasting so much time on this 2 line fix

tim.plunkett’s picture

FileSize
948 bytes
48.52 KB
PASSED: [[SimpleTest]]: [MySQL] 58,082 pass(es). View

Actually, even that is overkill. All filters are added to a format always.

Crell’s picture

I think it's OK to do channel consolidation in a follow-up, given that this is an API changing issue and channel consolidation would rarely leave the container configuration. It's just a bunch of string replacements.

For logging different levels/channels differently, I talked to Paris in IRC and he explained how you could do that in this model. I don't recall exactly how at the moment, but he seemed confident that it could be done. I think that's something we will need to include in the change notice.

Paris, can you include brief instructions on that here just for confirmation? Once that's done and confirmed as acceptable I think this is commitable.

ParisLiakos’s picture

right now, you do something like this:

services:
  logger.mylogger:
    class: Drupal\mylogger\Logger\MyLogger
    tags:
      - { name: logger }
/**
 * Pings someone when a php error occurs.
 */
class MyLogger extends LoggerBase {

  /**
   * {@inheritdoc}
   */
  public function log($level, $message, array $context = array()) {
    if ($level == LogLevel::ERROR && isset($context['type']) && $context['type'] == 'php') {
       // Something is really wrong ping me!
    }
  }

}

its the same someone would do currently with the watchdog hook.
I was trying to find a way to swap compiler passes, but seems thats not currently possible. Mainly because the compiler pass, is where the loggers are being added to channels, and well if someone would only want his logger added to a specific channel and not all, he would swap out core's compiler pass with one of his own..
But since thats not possible, the above is the way to do it now.

Maybe we could add this configuration to the services.yml file, something like:

services:
  logger.mylogger:
    class: Drupal\mylogger\Logger\MyLogger
    tags:
      - { name: logger}
    channels: [php]

or whatever the syntax would be..but you get the point. if the logger does not specify channels, add it to all

Something else:
What about changing the $context['type'] to $context['channel'] since, well thats how we call the class and the property, and well monolog calls them that way

Crell’s picture

So

1) "Do it yourself" is consistent with hook_watchdog() now, so I'm OK with it.

2) Yeah, we may as well use the more common terminology, since we've half-reimplemented Monolog anyway. :-)

Let's update for that, then I'm OK RTBCing this.

ParisLiakos’s picture

FileSize
3.77 KB
50.49 KB
PASSED: [[SimpleTest]]: [MySQL] 58,203 pass(es). View

so here it is with type => channel
i didnt rename the dblog table field nor the syslog config yml, so i dont have to deal with upgrade path.
at least in core is consistent as channel now..any logger can translate to anything it wants

Crell’s picture

+++ b/core/modules/dblog/lib/Drupal/dblog/Tests/DbLogTest.php
@@ -417,7 +417,7 @@ protected function testDBLogAddAndClear() {
-      'type'        => 'custom',
+      'channel'     => 'system',

Was that a deliberate rename?

ParisLiakos’s picture

Issue tags: -Needs profiling

so here is some profiling.
Its the front page. what i did, triggered some php errors, so watchdog was called 7 times in the request

while we have 362 less functions calls, ram usage goes up (mainly because of the service container)

Overall Diff Summary

Number of Function Calls 84,904 84,542 -362 -0.4%
Incl. Wall Time (microsec) 518,584 499,131 -19,453 -3.8%
Incl. CPU (microsecs) 392,000 360,000 -32,000 -8.2%
Incl. MemUse (bytes) 17,149,576 17,234,376 84,800 0.5%
Incl. PeakMemUse (bytes) 17,275,104 17,359,480 84,376 0.5%
Crell’s picture

If I'm reading that right, the memory increase is statistically insignificant. The only significant change is CPU time, which goes down. So I'd say profiling gives this a +1. :-)

ParisLiakos’s picture

FileSize
363 bytes
50.14 KB
FAILED: [[SimpleTest]]: [MySQL] Unable to apply patch watchdog-1289536-224.patch. Unable to apply patch. See the log in the details link for more information. View

Was that a deliberate rename?

yes, there is no custom channel, and one is not needed by the test, so i am using system instead..

If I'm reading that right, the memory increase is statistically insignificant. The only significant change is CPU time, which goes down. So I'd say profiling gives this a +1. :-)

Well, i have learn that CPU flag is not reliable in xhprof, but i included it anyway..the big win here is all those 'function_exists' calls from the hook we get rid of.

now, disregard the previous patch, it has some junk in it:P

Crell’s picture

Status: Needs review » Reviewed & tested by the community

And back.

ParisLiakos’s picture

opened #2068111: Consolidate similar but same logging channels as a followup to take care of comments #207 to #211

webchick’s picture

Assigned: Unassigned » catch

I know catch was interested in this one.

Crell’s picture

catch already unassigned himself back in #208. :-)

msonnabaum’s picture

Those profiling results don't look quite right. I'd like to see a bit more info on what/how it was tested, and please attach the xhprof files.

ParisLiakos’s picture

FileSize
124.42 KB
124.27 KB

here are the files, they were still in my /tmp
like i said, triggered a php error, which was iirc in the arg() function (which apparently is called 7 times in the homepage) which in turn called watchdog() 7 times

msonnabaum’s picture

If you dig into the watchdog calls, you'll see this:

dblog_watchdog -> Drupal\Core\Database\Driver\mysql\Insert::execute - 7 calls, 121.7ms
Drupal\Core\Logger\LoggerChannel::log -> Drupal\Core\Database\Driver\mysql\Insert::execute - 7 calls, 3.2ms

Unless this patch magically makes inserts go faster, I'd say that's not exactly an accurate representation.

ParisLiakos’s picture

hmm, dunno, the only that changes there is that the database connection is injected, while before it uses the global call.

maybe disabling dblog while profiling, since database is not reliable between tests? but anyway, i think that function calls would be still less, cause one less logger is called with the patch, the hook still calls function_exists on all available modules before the patch

msonnabaum’s picture

My point is, profile it and look at the results until they make sense, then post the results with an explanation of why.

Also, you want to post the diff of just the watchdog call, not the entire request.

catch’s picture

Status: Reviewed & tested by the community » Needs review
ParisLiakos’s picture

Issue tags: +Needs profiling

lets add the tag back, i probably suck at this

ParisLiakos’s picture

Issue summary: View changes

afds

jibran’s picture

225: watchdog-1289536-224.patch queued for re-testing.

larowlan’s picture

Issue summary: View changes
Issue tags: +Needs reroll
larowlan’s picture

Status: Needs work » Needs review
Issue tags: -Needs reroll
FileSize
53.59 KB
FAILED: [[SimpleTest]]: [MySQL] Drupal installation failed. View

Just a re-roll

larowlan’s picture

hmm installs locally, testing login/logout locally

larowlan’s picture

Status: Needs work » Needs review
FileSize
428 bytes
53.38 KB
FAILED: [[SimpleTest]]: [MySQL] 59,603 pass(es), 368 fail(s), and 333 exception(s). View

whoops - stuffed the re-roll - standard install profile wouldn't work with this.

larowlan’s picture

Status: Needs work » Needs review
FileSize
575 bytes
53.38 KB
FAILED: [[SimpleTest]]: [MySQL] 59,886 pass(es), 20 fail(s), and 2 exception(s). View

thou shalt pay closer attention to brackets

ParisLiakos’s picture

Status: Needs work » Needs review
FileSize
49.75 KB
FAILED: [[SimpleTest]]: [MySQL] 63,614 pass(es), 3 fail(s), and 1 exception(s). View

reroll
#245 contained unrelated hunks from an image toolkit related issue

andypost’s picture

Look rtbc, just nitpicks

  1. +++ b/core/lib/Drupal/Core/Logger/LoggerChannelFactory.php
    @@ -0,0 +1,35 @@
    +    else {
    +      return $this->container->get('logger.channel.default');
    +    }
    

    else is not needed

  2. +++ b/core/modules/filter/lib/Drupal/filter/Tests/FilterSettingsTest.php
    @@ -34,13 +34,11 @@ public static function getInfo() {
    -    $filters = array_fill_keys(array_keys($filter_info), array());
    ...
    -      'filters' => $filters,
    

    Is this change needed?

ParisLiakos’s picture

Status: Needs work » Needs review
FileSize
50.36 KB
FAILED: [[SimpleTest]]: [MySQL] 63,686 pass(es), 1 fail(s), and 1 exception(s). View
4.42 KB

thanks for the review!

Is this change needed?

yes, see #216

This should fix some failures..i just need to figure out what to do with the request, i ll probably need an event subscriber

ParisLiakos’s picture

Status: Needs work » Needs review
FileSize
50.46 KB
PASSED: [[SimpleTest]]: [MySQL] 63,621 pass(es). View
2.37 KB

probably the best and simplest fix

ParisLiakos’s picture

FileSize
41.01 KB
PASSED: [[SimpleTest]]: [MySQL] 63,681 pass(es). View
16.36 KB

which brings me to this:

The request is synthetic and watchdog is called all over the place, which makes sense and we dont want to limit it just in the request scope.
Thus we need that extra layer..which since it is there, it can also allow us to not have to register channel names in services.yml
It also still allows for services to get injected loggers (like what is already be done with the default one already)

I believe is an approach that will allow this issue to move forward finally.
Modules dont need to register channels as services. Let me know if this is something that can work and i will add interface and tests.

dawehner’s picture

+++ b/core/lib/Drupal/Core/Logger/LoggerChannelFactory.php
@@ -0,0 +1,84 @@
+      // If the request is available, set it with the current user to the channel.
+      try {
+        $instance->setRequest($this->container->get('request'));

An alternative approach could be to register a setRequest call on factory service and pass that along to all instances.

ParisLiakos’s picture

would then have the same problem with the one LoggerChannels had in #250

ParisLiakos’s picture

FileSize
40.98 KB
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] Drupal installation failed. View

first a reroll

ParisLiakos’s picture

Status: Needs work » Needs review
FileSize
40.99 KB
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] 66,425 pass(es), 3 fail(s), and 2 exception(s). View

Eh, messed up a filename

 rename core/lib/Drupal/Core/DependencyInjection/Compiler/{RegisterLoggerPass.php => RegisterLoggersPass.php} (100%)
ParisLiakos’s picture

Status: Needs work » Needs review
FileSize
50.45 KB
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] 66,512 pass(es), 0 fail(s), and 2 exception(s). View
21.23 KB

-switched abstract BaseLogger to trait
-added interfaces
-added tests

ParisLiakos’s picture

Status: Needs work » Needs review
FileSize
1.68 KB
50.07 KB
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 66,577 pass(es). View

well ErrorHandlerTest and FormValuesTest rely on the error_log() call of Symfony\Component\HttpKernel\EventListener\ExceptionListener which only happens when it doesnt have a logger injected.
I removed it from core.services.yml, we can add it in another issue, or if someone wants to fix it here.

Crell’s picture

WOOHOO! Green!

  1. +++ b/core/includes/bootstrap.inc
    @@ -1179,54 +1179,11 @@ function watchdog_exception($type, Exception $exception, $message = NULL, $varia
    +  $variables = $variables ?: array();
    

    Why not just change the default in the method signature to array()?

  2. +++ b/core/lib/Drupal/Core/Logger/LogMessageParserTrait.php
    @@ -0,0 +1,62 @@
    +trait LogMessageParserTrait {
    

    Ooo... :-)

  3. +++ b/core/lib/Drupal/Core/Logger/LogMessageParserTrait.php
    @@ -0,0 +1,62 @@
    +    $has_ps3 = FALSE;
    

    $has_psr3. The r is missing.

  4. +++ b/core/lib/Drupal/Core/Logger/LoggerChannel.php
    @@ -0,0 +1,182 @@
    +      foreach ($group as $logger) {
    +        if (!$logger instanceof LoggerInterface) {
    +          throw new InvalidArgumentException('All loggers must implement \Psr\Log\LoggerInterface.');
    +        }
    +      }
    

    We don't generally check for this manually. PHP will break for us if someone screws that up.

  5. +++ b/core/lib/Drupal/Core/Logger/LoggerChannel.php
    @@ -0,0 +1,182 @@
    +      $this->levelTranslation = array(
    +        LogLevel::EMERGENCY => WATCHDOG_EMERGENCY,
    +        LogLevel::ALERT => WATCHDOG_ALERT,
    +        LogLevel::CRITICAL => WATCHDOG_CRITICAL,
    +        LogLevel::ERROR => WATCHDOG_ERROR,
    +        LogLevel::WARNING => WATCHDOG_WARNING,
    +        LogLevel::NOTICE => WATCHDOG_NOTICE,
    +        LogLevel::INFO => WATCHDOG_INFO,
    +        LogLevel::DEBUG => WATCHDOG_DEBUG,
    +      );
    

    It should be possible to assign this in the class definition directly on the property. It's all constants, so it should be fine. Not a huge deal though since it's a temporary method.

  6. +++ b/core/lib/Drupal/Core/Logger/LoggerChannelFactory.php
    @@ -0,0 +1,69 @@
    +  /**
    +   * {@inheritdoc}
    +   */
    +  public function get($channel) {
    

    What is this inheriting from? ContainerAware has no such method.

  7. +++ b/core/lib/Drupal/Core/Logger/LoggerChannelFactory.php
    @@ -0,0 +1,69 @@
    +      // If the request is available, set it with the current user to the channel.
    +      try {
    +        $instance->setRequest($this->container->get('request'));
    +        $instance->setCurrentUser($this->container->get('current_user'));
    +      }
    +      catch (RuntimeException $e) {
    +        // We are not in a request context.
    +      }
    

    Wouldn't this be easier if the request and user were set on this class? Then it could pass them on directly rather than using the container.

    If that doesn't work, the try-catch can be eliminated by using $container->get($service, ContainerInterface::NULL_ON_INVALID_REFERENCE);

  8. +++ b/core/modules/dblog/lib/Drupal/dblog/Logger/DbLog.php
    @@ -0,0 +1,68 @@
    +class DbLog implements LoggerInterface {
    +
    +  use LoggerTrait;
    +  use LogMessageParserTrait;
    

    Uber-pedant: No space before the use lines. :-)

  9. +++ b/core/modules/dblog/lib/Drupal/dblog/Logger/DbLog.php
    @@ -0,0 +1,68 @@
    +    // Convert PSR3-style messages to String::format() style, so they can be
    +    // translated too in runtime.
    +    $this->parseMessagePlaceholders($message, $context);
    

    Is the long-term plan to go a step farther and save the PSR-3 versions, and convert those at runtime? That seems sensible, but I agree that's probably too far to go right now.

  10. +++ b/core/modules/syslog/lib/Drupal/syslog/Logger/SysLog.php
    @@ -0,0 +1,69 @@
    +    $facility = $this->config->get('facility');
    +    if ($facility === '') {
    +      $facility = defined('LOG_LOCAL0') ? LOG_LOCAL0 : LOG_USER;
    +    }
    +    openlog($this->config->get('identity'), LOG_NDELAY, $facility);
    

    This seems like more than we should be doing in a constructor. Do we really want to open the log file unconditionally?

ParisLiakos’s picture

FileSize
16.09 KB
57.09 KB
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 66,558 pass(es). View

great review, thanks!

1. Well originally i didnt want to touch the function signature at all, but the Approved API change tag is our friend here :) Changed!
3. Fixed!
4. Yes you are probably right. Fixed
5. Fixed
6. UGH..i forget to add the implements of the interface there -.- Good catch :)
7. Yes thats what i originally tried #250 , but the problem here is that request is synthetic. So if you call watchdog() very early or late, you get a nice fat exception. And ContainerInterface::NULL_ON_INVALID_REFERENCE does not work for synthetic services. There is a solution for the request: You can use the request_proxy, but it then blows up with the current_user because it requires the request, which brings you back to the original problem.
So until #2180109: Change the current_user service to a proxy lands there is no other solution than this try/catch statement and ContainerAware
8. Fixed
9. DbLog: Yes, i will open a followup for dblog module, because besides that which i agree on, i would like to rename its table's fields to bring them inline with the new naming (especially channel vs type)
10. You are completely right, i have no idea what i was thinking when doing this:/

I also:
- improved some hackery i did for the unit tests, because FormBuilder is defining a watchdog constant too, which would bring failures when running phpunit tests, depending on which test runs first
- added a \Drupal::logger() method
- deprecated watchdog()

Crell’s picture

  1. +++ b/core/authorize.php
    @@ -148,7 +148,7 @@ function authorize_access_allowed() {
    +  watchdog('access denied', 'authorize.php', array(), WATCHDOG_WARNING);
    

    It may be easier to use [] in this case, since that's legal syntax now. :-)

  2. +++ b/core/modules/dblog/lib/Drupal/dblog/Logger/DbLog.php
    @@ -18,6 +18,7 @@
     
       use LoggerTrait;
    +
       use LogMessageParserTrait;
    

    Hm, I meant go the other way. In the traits I've used to date I've not had any blank lines here. We should probably develop a convention here, probably just adopt whatever everyone else is doing since we have no prior art.

ParisLiakos’s picture

FileSize
1.78 KB
57.25 KB
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 66,596 pass(es). View

ah i see...yes we have one trait in views and no blank line used there. eg see https://api.drupal.org/api/drupal/core%21modules%21views%21lib%21Drupal%...

so i will just use the same pattern there

also added a @param docs

Crell’s picture

+++ b/core/lib/Drupal.php
@@ -615,6 +615,10 @@ public static function formBuilder() {
+   * @param string $channel
+   *   The name of the channel. Can be any string, but the general practice is
+   *   to use the name of the module calling this.
+   *

I wouldn't call that general practice, or good practice. "Subsystem"? That may not always correspond to a module.

Remember, "module" is just a useful collection of related code. Aside from hook namespacing there's nothing else magical about them anymore.

ParisLiakos’s picture

FileSize
518 bytes
57.25 KB
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 66,702 pass(es). View

i copied it from the watchdog's docs, but yes subsystem suits D8 better

ParisLiakos’s picture

FileSize
57.25 KB
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 66,766 pass(es). View
521 bytes

fail

ParisLiakos’s picture

FileSize
57.14 KB
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] 66,889 pass(es), 6 fail(s), and 1 exception(s). View
6.79 KB

now that current user is a proxy (yay!) we can get rid of ContainerAware

ParisLiakos’s picture

Status: Needs work » Needs review
FileSize
57.25 KB

ah, yeah this will still not work very early cause current_user still has a setRequest call registered. which blows up when request is not there

just re-uploading #269 then

dawehner’s picture

+++ b/core/lib/Drupal/Core/Logger/LoggerChannel.php
@@ -0,0 +1,149 @@
+    $context['user'] = $this->currentUser;

This is potentially dangerous. It would be call getAccount() directly in order to NOT store in some authentication manager and all the other shit.

ParisLiakos’s picture

FileSize
57.25 KB
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 66,835 pass(es). View

Good idea, but that would be the logger's job to do and not the channel's.
dblog doesnt save the user object to the database anyway, just the uid

reuploading the patch

jibran’s picture

  1. +++ b/core/lib/Drupal/Core/Logger/LoggerChannel.php
    @@ -0,0 +1,157 @@
    +   * @var array
    
    +++ b/core/lib/Drupal/Core/Logger/LoggerChannelInterface.php
    @@ -0,0 +1,53 @@
    +   * @param array $loggers
    

    not array \Psr\LoggerInteface[]

  2. +++ b/core/tests/Drupal/Tests/Core/Logger/LogMessageParserTraitTest.php
    @@ -0,0 +1,95 @@
    +   * Test for LogMessageParserTrait::parseMessagePlaceholders()
    

    instead if test for it should be tests.

  3. +++ b/core/tests/Drupal/Tests/Core/Logger/LoggerChannelTest.php
    @@ -0,0 +1,155 @@
    +// @todo Remove once watchdog() is removed.
    

    Is there any issue for this. Maybe link it all places where we use @todo.

  4. +++ b/core/tests/Drupal/Tests/Core/Logger/LoggerChannelTest.php
    @@ -0,0 +1,155 @@
    +   * Test for LoggerChannel::log()
    ...
    +   * Test for LoggerChannel::addLoggers()
    

    Tests instead of test for.

pjezek’s picture

Profiled admin page as frontpage with an anonymous user to trigger around 200 watchdog entries ;)

=== psr-logger.272_0..psr-logger.272_0 compared (5336e1e6acd58..5336e2cad4ff5):

ct  : 29,626|29,812|186|0.6%
wt  : 158,494|156,809|-1,685|-1.1%
cpu : 150,756|149,521|-1,235|-0.8%
mu  : 12,222,376|12,349,848|127,472|1.0%
pmu : 12,297,704|12,424,968|127,264|1.0%
=== psr-logger.272_0..psr-logger.272_0 compared (5336e1e6acd58..5336e2f1a0d07):

ct  : 29,626|29,812|186|0.6%
wt  : 158,494|161,680|3,186|2.0%
cpu : 150,756|154,440|3,684|2.4%
mu  : 12,222,376|12,349,848|127,472|1.0%
pmu : 12,297,704|12,424,968|127,264|1.0%
pjezek’s picture

Issue tags: -Needs profiling
ParisLiakos’s picture

FileSize
57.36 KB
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] Unable to apply patch psr-logger.275.patch. Unable to apply patch. See the log in the details link for more information. View
3.61 KB

not array \Psr\LoggerInteface[]

Well it is an array of arrays keyed by priority. i think this only applies for one depth level arrays?

Is there any issue for this. Maybe link it all places where we use @todo.

no issue

Furthemore, i made the container to the factory optional..so one can use it, even before the container is setup with a fairly simple logger without dependencies

ParisLiakos’s picture

Status: Needs work » Needs review
FileSize
3.07 KB
54.82 KB
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] 69,723 pass(es), 4 fail(s), and 2 exception(s). View
ParisLiakos’s picture

Status: Needs work » Needs review
FileSize
55.45 KB
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 70,344 pass(es). View
2.89 KB

hmm some unrelated stuff got in from when i was experimenting with #273

ParisLiakos’s picture

Can i haz an RTBC? I really think this is ready now.

Retesting (it still applies oO)
282: psr-logger.282.patch queued for re-testing.

Crell’s picture

  1. +++ b/core/lib/Drupal/Core/Logger/LogMessageParserTrait.php
    @@ -0,0 +1,62 @@
    +trait LogMessageParserTrait {
    

    The way this is used makes me think it shouldn't be a trait but its own service object. In particular it's complex enough to bother testing (further down in the patch), which implies it is its own logic unit. Thus it should be a service object that gets injected into the 2-3 places where it's used. I'm pretty sure those are all straightforward places to pass an object, either from the container setup or from the factory object itself.

  2. +++ b/core/lib/Drupal/Core/Logger/LoggerChannelFactory.php
    @@ -0,0 +1,74 @@
    +        catch (RuntimeException $e) {
    

    This needs to be \RuntimeException since we're in a namespace.

Other than those fairly simple points, I think we're done here. Thanks, Paris!

ParisLiakos’s picture

FileSize
61.13 KB
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] 70,699 pass(es), 131 fail(s), and 0 exception(s). View
24.34 KB

The exception is actually Symfony\Component\DependencyInjection\Exception\RuntimeException ;)

Allright, i switched the message/placeholder parser to a service and added an interface for it.

But, most importantly, since this started taking quite some time i converted syslog and dblog to work with PSR log levels instead of the watchdog ones..that way i can stop worrying that we might ship with non-psr3 loggers...a followup is no longer a good idea.
Now loggers are are 100% PSR3

ParisLiakos’s picture

Status: Needs work » Needs review
FileSize
63.82 KB
2.69 KB
catch’s picture

We define our own constants for consistency with RFC 3164. It looks like https://github.com/php-fig/fig-standards/blob/master/accepted/PSR-3-logg... is not using the decimal levels but arbitrary strings instead, I couldn't find the arbitrary strings in the RFC.

Additionally, PSR-3 is not clear on whether the decimal levels in RFC 3164 can be used instead of the strings or not, only that the eight log levels should be used, and that it provides the interface as a helper.

Could we not override the interface instead of having each implementation do its own conversion?

ParisLiakos’s picture

FileSize
55.53 KB
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 71,584 pass(es). View
11.49 KB

You, are right. My bad :)

related issue https://github.com/php-fig/log/issues/8

I reverted the changes and adjusted the comments..we can always discuss this in a followup, but as long as our channels accept PSR3 levels, there should be no problem. Then our loggers (dblog, syslog) standardize on the decimal levels

catch’s picture

Hmm looks like that's won't fix, and also https://github.com/php-fig/log/pull/11 :(

Looks like we're fine to be PSR-3 compatible while also using the RFC (current) log levels, so yeah let's figure out in a follow-up (which might be the watchdog removal).

YesCT’s picture

Issue tags: +Needs followup
yched’s picture

Looks like the issue summary could use an update ? It advertizes the thread as "move to Monolog", which the patch doesn't seem to be doing at all ?

ParisLiakos’s picture

Issue summary: View changes
Issue tags: -Needs followup

Yes, issue summary is ancient. I updated it and also opened #2267545: Standardize to RFC 5424 log levels.

Crell’s picture

Paris, can you post an interdiff from #282 to #289, so we can see what changed without the jitter of the CONSTANT shuffling? It's a bit hard to verify what all changed with that.

ParisLiakos’s picture

@Crell: sure, you are right, sorry for the noise:)

Crell’s picture

Status: Needs review » Reviewed & tested by the community

I find it amusing that this issue has the "RTBC July 1" tag, which is LAST July, but whatever. It's back now. :-) Thanks, Paris!

catch’s picture

Status: Reviewed & tested by the community » Needs work

This looks fine now, and we have the other issue open for sorting out the constants.

However it's removing hook_watchdog() and there's no draft change notice, so should not have been RTBCed.

ParisLiakos’s picture

Status: Needs work » Needs review
Crell’s picture

Status: Needs review » Reviewed & tested by the community

That looks very complete. Thanks!

cosmicdreams’s picture

+1

catch’s picture

Status: Reviewed & tested by the community » Fixed

Thanks for the change notice. Committed/pushed to 8.x, thanks!

  • Commit ef250ba on 8.x by catch:
    Issue #1289536 by RobLoach, Crell, Pancho, pounard, socketwench, fgm,...

  • Commit 52a11d6 on 8.x by alexpott:
    Revert "Issue #1289536 by RobLoach, Crell, Pancho, pounard, socketwench...
alexpott’s picture

Assigned: catch » Unassigned
Status: Fixed » Needs work

I'm so sorry - but this has introduced a critical regression in Drupal installation so reverted.

Steps to reproduce

  1. Start with a clean Drupal
  2. Open an anonymous window
  3. Install Drupal all the way to part where you are logged in
  4. Wipe db, files and settings.php - prepare to reinstall
  5. In same anonymous window try to reinstall
  6. Crashes because of the watchdog call to log system module installation. This is because the currentUser service tries to access the old session and the users table does not exist yet - the user module is not installed :)

Fixes?

Sessions does because it is declared in system.install - but interestingly has foreign key to users.uid and a uid column - should it really exist before users??? The old watchdog used global $user and so was immune to this.

  • So one fix would be to move the users table to system.install
  • Another fix would be to move the currentUser service to the user module and then only use it if it exists
yched’s picture

So one fix would be to move the users table to system.install

Probably not an option with #2183231: Make ContentEntityDatabaseStorage generate static database schemas for content entities ?

tstoeckler’s picture

Right, with #2183231: Make ContentEntityDatabaseStorage generate static database schemas for content entities this would mean moving the User entity type to System module which would be pretty gross.

ParisLiakos’s picture

Status: Needs work » Needs review
Related issues: +#2272189: Uncouple session handling from user module
FileSize
55.77 KB
FAILED: [[SimpleTest]]: [PHP 5.4 MySQL] Setup environment: Test cancelled by admin prior to completion. View
1.6 KB

It might be gross but thats the truth. as long as session table has an uid column..Its definitely not the place to fix this though, so i opened #2272189: Uncouple session handling from user module and a fix here, so installation process still works if you have a cookie

alexpott’s picture

FileSize
1.53 KB
56.92 KB
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 71,692 pass(es). View

Let's use the service container to fix this for us - it's what it is for! - and lol xpost with @ParisLiakos

alexpott’s picture

FileSize
1.2 KB
56.58 KB
PASSED: [[SimpleTest]]: [PHP 5.4 MySQL] 71,772 pass(es). View

@tim.plunkett pointed out that the authentication manager would return the anonymous user session if there was no auth providers so...

The last submitted patch, 307: psr-logger.307.patch, failed testing.

tim.plunkett’s picture

Status: Needs review » Reviewed & tested by the community

+1 for #309, that's rather elegant.

Crell’s picture

I like #309 as well. It feels like what we should be doing anyway, and neatly solves this bug, too. :-)

tstoeckler’s picture

It seems weird to have user module expose classe in \Drupal\Core as services. Should we move those over to user.module as well?

damiankloip’s picture

That is what I was about to ask too :). It does seem a bit weird.

  • Commit e44d15a on 8.x by catch:
    Issue #1289536 by ParisLiakos, RobLoach, Crell, larowlan, fgm, pounard,...
catch’s picture

Status: Reviewed & tested by the community » Fixed

#309 looks good to me as well.

If sessions really gets decoupled from users in #2272189: Uncouple session handling from user module then we might not need to move the class, but yes for honesty/clarity's sake that makes sense.

Committed/pushed to 8.x, thanks!

Xano’s picture

This breaks WebTestbase::setUp() in my contrib tests. Is that supposed to happen? The exception I get is the following:

LogicException: Cannot change the ID of an active session in Symfony\Component\HttpFoundation\Session\Storage\Proxy\AbstractProxy->setId() (line 123 of /var/www/code/drupal/core/8test/core/vendor/symfony/http-foundation/Symfony/Component/HttpFoundation/Session/Storage/Proxy/AbstractProxy.php).

Symfony\Component\HttpFoundation\Session\Storage\Proxy\AbstractProxy->setId('KtAElvrTphr-bb_6fL-S8rMquhyezhii4IJhV2LGGI0')
Symfony\Component\HttpFoundation\Session\Storage\NativeSessionStorage->setId('KtAElvrTphr-bb_6fL-S8rMquhyezhii4IJhV2LGGI0')
Drupal\Core\Session\SessionManager->initialize()
Drupal\Core\Authentication\Provider\Cookie->authenticate(Object)
Drupal\Core\Authentication\AuthenticationManager->authenticate(Object)
Drupal\Core\Session\AccountProxy->getAccount()
Drupal\Core\Session\AccountProxy->id()
Drupal\payment\Entity\Payment::preCreate(Object, Array)
Drupal\Core\Entity\EntityStorageBase->create(Array)
Drupal\payment\Entity\Payment\PaymentStorage->create(Array)
entity_create('payment', Array)
Drupal\payment\Generate::createPayment(2)
Drupal\payment\Tests\Element\PaymentLineItemsDisplayUnitTest->testElement()
Drupal\simpletest\TestBase->run()
_simpletest_batch_operation(Array, '1', Array)
call_user_func_array('_simpletest_batch_operation', Array)
_batch_process()
_batch_do()
_batch_page(Object)
Drupal\system\Controller\BatchController->batchPage(Object)
call_user_func_array(Array, Array)
Symfony\Component\HttpKernel\HttpKernel->handleRaw(Object, 1)
Symfony\Component\HttpKernel\HttpKernel->handle(Object, 1, 1)
Drupal\Core\HttpKernel->handle(Object, 1, 1)
Drupal\Core\DrupalKernel->handle(Object)
drupal_handle_request()
Xano’s picture

For the record, this only happens when running the tests from the UI.

damiankloip’s picture

That happened for me with core tests, haven't tested with this fixed committed though.

Xano’s picture

A few corrections and additions to my previous post: this happens when testing using DUTB/KernelTestBase. When I add the following code to my setUp() method, the test runs fine:

    $anonymous = new AnonymousUserSession();
    \Drupal::currentUser()->setAccount($anonymous);

This feels like the system fails because there is no active session and we should either always have an active session, or not fail it there is none.

Status: Fixed » Closed (fixed)

Automatically closed - issue fixed for 2 weeks with no activity.

Gábor Hojtsy’s picture

I'm very puzzled by this change or more precisely the lack of thought could have went into considering the translation friendliness, if we even continue to care about that?

1. First of all, this new system had no potx issue opened to support text extraction (now I opened at #2285063: Support for Drupal 8 logger API).

2. Second, the change log mentions methods like notice() and error() which are not defined here, OTOH a log() method is defined which takes a level but that is not mentioned in the change notice.

3. This now supports two possible log string formats. Its unclear to me how that affects translations/translators. Will they get the PSR log format exposed to them? The transformed format? Should we do the same transformation on the potx side?

Answers to some of these questions would be required to even start implementing #2285063: Support for Drupal 8 logger API. Thanks!

hass’s picture

How does the upgrade path for watchdog_exception() looks like? It seems not documented.

Xano’s picture

Second, the change log mentions methods like notice() and error() which are not defined here, OTOH a log() method is defined which takes a level but that is not mentioned in the change notice.

The other methods are all available on \Psr\Log\LoggerInterface, just like log(). What is confusing to me is that we now seem to have two sets of levels, namely those of PSR-3 and the old Watchdog levels. The PSR-3 levels are not defined on the interface, which is terribly confusing, but on the somewhat unusable class \Psr\Log\LogLevel.

ParisLiakos’s picture

@Xano : #2267545: Standardize to RFC 5424 log levels
@hass: keep using watchdog_exception(). There is no change there. yet

Gábor Hojtsy’s picture

Still looking at how to make the string extraction work with the new structure, the log channel API made it impossible to detect the channel names and therefore pointless to try to later translate them. Your present for wanting to have an injectable logging API where channel and messages are separated. So #2287039: Decide if we still want to translate log channel names and make modifications accordingly.