Pass the logger channel through as a prefix

[eileenmcnaughton]

Overview

This builds on the recently added PR #20079
and changes the default behaviour such that if a channel is used, without any other intervention,
it will result in a change to the file name to reflect the channel

Channels are a new feature so this won't affect existing sites but
I think adding the prefix is a thing that people using different channels might
reasonably expect as a helpful default. I kept it such that we ignore anything
beyond a narrow range of characters - we could throw an exception
rather than silently ignore if we prefer

Before

Instantiating a logger with a channel logs to the same file as everything else, if a service is not defined

After

Instantiating a logger with a channel logs to a file prefixed by the channel name , if a service is not defined.

If the service uses letters that are no alphanumeric or '-' or '_' it will be silently ignored for security

Technical Details

@totten I think this adds some incentive to start updating existing calls to have a channel as it will separate them out - there are some existing payment processors that already use a prefix (bypassing the Civi::log() )

Comments

[civibot]

(Standard links)

• If this is your first pull-request for CiviCRM, please browse CONTRIBUTING.md for information about the development and testing processes.
• If you are reviewing this pull-request, you may wish to consult the test sites and the Review Standards (long template, short template).

[eileenmcnaughton]

@totten what are your thoughts on this? If we do merge it I think it would be good to merge to the same release that introduced channels

[totten]

@eileenmcnaughton - OK, I'm personally happy with a policy of splitting channels into separate files by default.

From an r-tech POV, I suspect that some sysadmins/upgraders might prefer an option to keep the unified log (e.g. if they've already linked that into their log-aggregation system). Would be curious if we had some feedback from folks with sophisticated deployments (e.g. @MegaphoneJon @adixon @mlutfy).

Maybe a setting where you could opt-out/opt-in to split-files. Ex:

  // Default - Log every channel to separate file: "log_file_channels" == "/.*/"
  // Alternative - Don't log anything to a separate file: "log_file_channels" == "/^$/"
  // Alternative - Log two specific channels to separate files: "log_file_channels" == "/^(mail|ipn)$/

  if (preg_match(Civi::settings()->get('log_file_channels'), $channel)) {
    // Use separate file
  }
  else {
    // Use traditional file
  }

Implementation-wise, there should be a separate instance of the logger for each channel. To my eye, this looks like it'll re-use one instance, which could cause some crossed wires. Consider:

class Foo {
  private $log;
  public function __construct() { $this->log = Civi::log('foo'); }
  public function fooify() { $this->info("Hello from Foo"); }
}

class Bar {
  private $log;
  public function __construct() { $this->log = Civi::log('bar'); }
  public function barbecueTofu() { $this->info("Hello from Bar"); }
}

$foo = new Foo();
$bar = new Bar();
$foo->fooify();
$bar->barbecueTofu();
// If the two objects reference the same `$log`, then one or the other will route to the wrong place.

Assuming you're keen on the combination of DEFAULT_LOGGER and method_exists(...'setChannel') -- then one could get the desired result with clone, e.g.

if ($c->has($svc) {
  $log = $c->get($svc);
}
else {
  $log =  $c->get(self::DEFAULT_LOGGER);;
  if ($channel !== 'default' && method_exists($this->channels[$channel], 'setChannel') /* && settings encourage split files */) {
    $log = clone $log;
    $log->setChannel($channel);
  }
}
$this->channels[$channel] = $log;

(Also, small note - the old code there was using a default value of empty-string (''). The property protected $channel has a default of NULL. Dunno if that makes a difference here.)

[eileenmcnaughton]

It's worth noting that there are no existing configured channels so far - so default behaviour is no change - however there would be a change if we also defined channels

If this needs a setting to maintain then I don't think we should merge that change - it makes more sense to manage it all in an extension - which I'm making good progress on.

The main reason I thought it might be worth merging is the splitting out of log files give some incentive for people to think about what should get logged to which channels

Based on your feedback I'm inclined to close this but I'll leave it for a couple of days just to let people add any thoughts

[totten]

Proposed variant: #20163

[mattwire]

Is there a lab issue to discuss the preferred implementation of this. I'm very much in favour of the ability to split log files per channel etc. but I'm not sure about it being the default. Specifically my concern is:

1. Split log files can be much more difficult to debug because you have to do work to put them in cronological order:
   eg. an IPN call comes in which triggers some "ipn" channel messages and then creates a new contribution via repeatransaction which triggers the "Contribution X updated successfully" log message through the contribution BAO. Then you might get another ipn log message confirming that the ipn was processed successfully. You can no longer be sure of the order of the messages, especially when they are recorded with the same (seconds) timestamp.
2. You can miss log messages because you (or your client!) don't check the right "channel" log.

[eileenmcnaughton]

There is a gitlab issue.

I think I've gone off the idea of doing this in core since it's now do-able in an extension - so I don't think anything needs doing here now- but I will post a blog once we put the extension into production

[mattwire]

@eileenmcnaughton Which is the lab issue please?

[eileenmcnaughton]

@mattwire not sure - but search logging or whatever & you'l find it - or maybe search 'monolog' since it was from that issue I found Dave's monolog extension

[mlutfy]

https://lab.civicrm.org/community/feature-request/-/issues/12