Change 579682 had a related patch set uploaded (by Reedy; owner: Reedy):
[mediawiki/core@master] Cleanup and simplify LogStashFormatter

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

In T242751#5969137, @gerritbot wrote:

Change 579682 had a related patch set uploaded (by Reedy; owner: Reedy):
[mediawiki/core@master] Cleanup and simplify LogStashFormatter

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

Which strips out the special casing... And can be squashed into the patch above if this actually makes sense now

In T242751#5969133, @Reedy wrote:

I'm not 100% clear if we need to do anything about these context keys anymore (ie no prefixing/renaming neeed?), as they're not moved into the top level, as per the comment that is there now...

That would imply that either data from the processors doesn't make it into logstash, or the way process data and log context is merged has changed and our conflict detection code doesn't work anymore, or that we'll end up with some different structure in Logstash (processor data in a sub-array or something like that) which will break the indexing. Either of those would be bad.

In T242751#5969175, @Tgr wrote:

In T242751#5969133, @Reedy wrote:

I'm not 100% clear if we need to do anything about these context keys anymore (ie no prefixing/renaming neeed?), as they're not moved into the top level, as per the comment that is there now...

That would imply that either data from the processors doesn't make it into logstash, or the way process data and log context is merged has changed and our conflict detection code doesn't work anymore, or that we'll end up with some different structure in Logstash (processor data in a sub-array or something like that) which will break the indexing. Either of those would be bad.

From what I can tell, it’s a change of format that seems to be completely intentional. Whether that’s considered a bug they will fix it whether we need to adjust them ourselves now...

As per https://github.com/Seldaek/monolog/commit/a21b037a00c6480c5af7106d0a08edde564b2265 - "Change LogstashFormatter to have extra/context keys instead of prefixes for the keys", it does look completely intentional

https://github.com/Seldaek/monolog/pull/1057

It doesn't really make sense to let half of the key be configurable and the other half hardcoded.

Previously, the prefixes made sense because it wasn't a nested array so each key was dynamic.

And of course, it's a change made a good 2.5 years ago now at this point. And 2.0.0 has been stable since August 2019...

Also tagging 1.35... As 1.35 is going to be an LTS, it seems beneficial to get the newer version of monolog into it as we're going to be supporting it for a few years, so, and having the same major version as in master would be helpful (and if becomes necessary/sensible, a good time to make breaking format changes)

The other option is to bring in code from the old version of the parent class in monolog, and carry on things as we are.

Though this feels like we're bringing a maintenance burden onto ourselves, and therefore Technical-Debt we're carrying forward.

I do agree it's basically a breaking change from upstream, while they dropped the V0 format, they then broke the V1 format subtley

Let's try a version of that ontop of the core patch and see how things look...

Change 579761 had a related patch set uploaded (by Reedy; owner: Reedy):
[mediawiki/core@master] Import LogstashFormatter::formatV1 from monolog/monolog 1.25.3

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

Old output of LogstashFormatterTest::testV1WithPrefix

array(2) {
  'extra' =>
  array(1) {
    'url' =>
    int(1)
  }
  'context' =>
  array(1) {
    'url' =>
    int(2)
  }
}
/var/www/wiki/mediawiki/core/tests/phpunit/unit/includes/debug/logger/monolog/LogstashFormatterTest.php:53:
array(6) {
  '@timestamp' =>
  string(25) "2020-03-14T19:03:26+00:00"
  '@version' =>
  int(1)
  'host' =>
  string(6) "system"
  'type' =>
  string(3) "app"
  'url' =>
  int(1)
  'ctx_url' =>
  int(2)
}

Change 579761 abandoned by Reedy:
Import LogstashFormatter::formatV1 from monolog/monolog 1.25.3

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

Ok, so tests now passing (with minimal changes to them), importing the old format output...

Ready to be reviewed now :)

So what happens now if a processor adds an url field and the log context also has an url field? Before, there would have been a conflict (one would silently override the other) which we detected with some custom code that prefixed the context field with c_. (We never used the prefix option of the upstream class, which would have prefixed all context data, whether or not there's any conflict.)

Seems like now all of the context will end up in a sub-array? That would break all existing dashboards and require a manual reset of the indexes...

Nevermind, I see that's addressed (hypothetically) in T247675.

In T242751#5971449, @Tgr wrote:

So what happens now if a processor adds an url field and the log context also has an url field? Before, there would have been a conflict (one would silently override the other) which we detected with some custom code that prefixed the context field with c_. (We never used the prefix option of the upstream class, which would have prefixed all context data, whether or not there's any conflict.)

Seems like now all of the context will end up in a sub-array? That would break all existing dashboards and require a manual reset of the indexes...

Yes, I read that in your original comment and took note. T247675: Stop overriding LogstashFormatter format filed to clean that up longer term. In the meantime, to unblock the upgrade, I tried a different tact, not using the LogstashFormatter format function that was provided in monolog 2.0.2:

In T242751#5969677, @Reedy wrote:

The other option is to bring in code from the old version of the parent class in monolog, and carry on things as we are.

Though this feels like we're bringing a maintenance burden onto ourselves, and therefore Technical-Debt we're carrying forward.

I do agree it's basically a breaking change from upstream, while they dropped the V0 format, they then broke the V1 format subtley

Let's try a version of that ontop of the core patch and see how things look...

The format stays the same, as evident by minimal changes to the tests in https://gerrit.wikimedia.org/r/#/c/mediawiki/core/+/579668/30/tests/phpunit/unit/includes/debug/logger/monolog/LogstashFormatterTest.php

Then if we look at https://gerrit.wikimedia.org/r/#/c/mediawiki/core/+/579668/30/includes/debug/logger/monolog/LogstashFormatter.php we still do our own prefixing, as we strip out the context from the $record passed to the format function

The parent format function in the new version returns things as a json string, not an array now - https://gerrit.wikimedia.org/r/#/c/mediawiki/vendor/+/579666/3/monolog/monolog/src/Monolog/Formatter/LogstashFormatter.php

I can't remember if I tried something like swapping the current (in the gerrit chnage)

	public function format( array $record ): string {
		if ( $this->contextKey !== '' ) {
			return $this->toJson( $this->formatV1( $record ) ) . "\n";
		}

		$context = !empty( $record['context'] ) ? $record['context'] : [];
		$record['context'] = [];

		$formatted = $this->formatV1( $record );

		return $this->toJson( $this->fixKeyConflicts( $formatted, $context ) ) . "\n";
	}

to

	public function format( array $record ): string {
		if ( $this->contextKey !== '' ) {
			return parent::format( $record );
		}

		$context = !empty( $record['context'] ) ? $record['context'] : [];
		$record['context'] = [];

		$fixedConflicts = $this->fixKeyConflicts( $formatted, $context );

		return parent::format( $fixedConflicts );
	}

I feel like I did, and it caused issues. But can try it again in a patch ontop to see what's what

Change 579902 had a related patch set uploaded (by Reedy; owner: Reedy):
[mediawiki/core@master] Test something else

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

Change 579902 abandoned by Reedy:
Test something else

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

Change 580096 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[operations/mediawiki-config@master] [WIP] logging: Remove useMicrosecondTimestamps(false) calls

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

For what it's worth, I'm supportive of moving the message's own local context keys into a sub array. The vast majority of these are never used in Kibana dashboards and only viewed when expanding rows. At which point separating the infra/platform level keys from the local message seems quite valuable indeed. Right now they are scattered across alphabetically which actually makes them somewhat difficult to find, and also makes it non-obvious to a developer not familiar with the code where they come from.

It would in theory also allow us to decide to e.g. not index these in the Logstash/Elastic mapping by default (T234564, J178). And instead only whitelist a handful optimised indexing/filtering (e.g. context.exception.* comes to mind as one that we'd likely want to index). We could even make is that indexing equates implicitly renaming to a top-level key. Which has the bonus of not requiring dashboard updates.

In any event, even if we don't change what we index and just move them over, it'll at worst be a couple dashboard updates which is a one-time transition I'm sure we'll survive.

Late entry in the breaking changes category: https://github.com/Seldaek/monolog/issues/1446#issuecomment-626967375

A fix we made upstream for T118057: Monolog throws RuntimeException on JSON encoding failure will behave differently in 2.0.3 (unreleased) unless we make some changes in MediaWiki\Logger\Monolog\LogstashFormatter. Specifically non-UTF8 encoded strings in log events will end up with a lot of � replacement characters unless we explicitly remove JSON_INVALID_UTF8_SUBSTITUTE from the default NormalizerFormatter JSON encoding options in our grandchild class. See the diff to fix tests upstream to better understand how this may affect what ends up in the ELK stack.

Untagging 1.35, as this isn't going out in 1.35

We're on 1.25.3; 1.23.5 is now out... https://github.com/Seldaek/monolog/compare/1.25.3...1.25.5

"monolog/monolog": "~1.25.3", takes care of this in REL1_35. Probably worth a bump in vendor for wmf prod, but that's different

Change 621953 had a related patch set uploaded (by Reedy; owner: Reedy):
[mediawiki/vendor@master] Updating monolog/monolog (2.0.2 => 2.1.1)

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

Tagging Platform Engineering as working out a way forward here seems under their purview

In T242751#6530639, @AMooney wrote:

@Reedy, what are the open issues?

So, we've got a stack of issues here.

First off, we're still on monolog 1.x in MediaWiki. I think it can be considered the legacy release (no active developement, just bug fixes). I've filed https://github.com/Seldaek/monolog/issues/1506 upstream to get the question answered as to how long we should expect 1.x to be supported.

Upgrading to 2.x results in a change in logging format, see T247675: Stop overriding LogstashFormatter format (I've also just tagged Platform there too).

To minimise the amount of changes, in my MW core patch at https://gerrit.wikimedia.org/r/c/579668, I've basically put changes in to revert that change in the logging format. This is fine in the short term, but it adds further Technical-Debt

So we need to decide if we want to change the formatting. And if/when we want to revert this tech debt in WMF production, it's going to require some changes to Wikimedia-Logstash. Nothing impossible, but it is work. Potentially changing/updating indexes etc. Some dashboards to potentially poke too. See T242751#6068340

I would suggest after we've merged the bumps to monolog 2.0.2 into MW core and confirmed things are stable (no other regressions/changes), we probably want to have some sort of MW config flag, allowing us to change between the 1.x and 2.x formats. Which makes rolling out the logging format changes to Logstash easier, as we're not having it happening with the train rolling forward, which makes it more difficult to manage. We can then switch it on both branches at the same time for example etc

This is obviously a breaking change, and would need Documentation as such. And deciding how long this config flag sticks around in MW core... Do we get rid of it in the same cycle, or keep it around to allow people to migrate too over a couple of releases? Do people need that?

Then we also have:

In T242751#6127010, @bd808 wrote:

Late entry in the breaking changes category: https://github.com/Seldaek/monolog/issues/1446#issuecomment-626967375

A fix we made upstream for T118057: Monolog throws RuntimeException on JSON encoding failure will behave differently in 2.0.3 (unreleased) unless we make some changes in MediaWiki\Logger\Monolog\LogstashFormatter. Specifically non-UTF8 encoded strings in log events will end up with a lot of � replacement characters unless we explicitly remove JSON_INVALID_UTF8_SUBSTITUTE from the default NormalizerFormatter JSON encoding options in our grandchild class. See the diff to fix tests upstream to better understand how this may affect what ends up in the ELK stack.

Looks like this went into 2.1.0/2.1.1.

This shouldn't be as much work, but should be done too to bring things upto date.

Change 579666 merged by jenkins-bot:
[mediawiki/vendor@master] Updating monolog/monolog (1.25.5 => 2.0.2)

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

Change 579668 merged by jenkins-bot:
[mediawiki/core@master] Updating monolog/monolog (1.25.3 => 2.0.2)

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

Once this goes out we can probaly land:

https://gerrit.wikimedia.org/r/c/operations/mediawiki-config/+/580096

which removes the then-redundant workaround for T116550.

Needs an update to the vendor repo. The patch is probably stale by now. Can be done in clinic duty.

With https://gerrit.wikimedia.org/r/c/mediawiki/core/+/579668 , the messages formatted for logstash now have the monolog level as an integer when we already have the level name:

Seems that got borrowed from the upstream code. It is probably not an issue on its own beside adding a field to every single log messages.

Looking at https://gerrit.wikimedia.org/r/c/mediawiki/core/+/579668/34/includes/debug/logger/monolog/LogstashFormatter.php#b11 , I am not sure why we copy paste the code from the upstream \Monolog\Formatter\LogstashFormatter::format() method. But I guess there is a good reason?

In T242751#6663016, @hashar wrote:

With https://gerrit.wikimedia.org/r/c/mediawiki/core/+/579668 , the messages formatted for logstash now have the monolog level as an integer when we already have the level name:

monolog_level	300
level	WARNING

Seems that got borrowed from the upstream code. It is probably not an issue on its own beside adding a field to every single log messages.

Looking at https://gerrit.wikimedia.org/r/c/mediawiki/core/+/579668/34/includes/debug/logger/monolog/LogstashFormatter.php#b11 , I am not sure why we copy paste the code from the upstream \Monolog\Formatter\LogstashFormatter::format() method. But I guess there is a good reason?

See T247675: Stop overriding LogstashFormatter format

In T242751#5969175, @Tgr wrote:

In T242751#5969133, @Reedy wrote:

I'm not 100% clear if we need to do anything about these context keys anymore (ie no prefixing/renaming neeed?), as they're not moved into the top level, as per the comment that is there now...

That would imply that either data from the processors doesn't make it into logstash, or the way process data and log context is merged has changed and our conflict detection code doesn't work anymore, or that we'll end up with some different structure in Logstash (processor data in a sub-array or something like that) which will break the indexing. Either of those would be bad.

I didn't want to cause a change of logstash format at the same time as an upgrade, because it would have changed the format of the log entries, and possible need some work with index changes etc. And being able to differentiate between breakages from a format change and the general monolog upgrade... seemed beneficial :)

Longer term plan is to stop that, but it's not just a MediaWiki change, so would need more work/coordination

If there's things that have sneaked in like that, that we don't need/want/whatever else, we can just remove them again

Change 644834 had a related patch set uploaded (by Reedy; owner: Reedy):
[mediawiki/core@master] Updating monolog/monolog (2.0.2 => 2.1.1)

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

In T242751#6662685, @daniel wrote:

Needs an update to the vendor repo. The patch is probably stale by now. Can be done in clinic duty.

That's the easy part ;)

T247675: Stop overriding LogstashFormatter format needs working on at some point.

It does look like the 1.25.3 => 2.0.2 change worked without major issues, so potentially the 2.0.2 => 2.1.1 change can happen soon. Noting the version constraint changes will potentially cause problems in other repos, as seen with the bump to 2.x in T268207: mediawiki/core composer error: "The requested package monolog/monolog ^1.22 exists as monolog/monolog[2.0.2] but these are rejected by your constraint.", and as such, depending on the semver used, need further changes

And T196906: Sensible default parameters for Monolog logging probably wants reverting out too...

Another one from Parsoid T269386

Change 621953 merged by jenkins-bot:
[mediawiki/vendor@master] Updating monolog/monolog (2.0.2 => 2.1.1)

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

Change 644834 merged by jenkins-bot:
[mediawiki/core@master] Updating monolog/monolog (2.0.2 => 2.1.1)

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

Change 655621 had a related patch set uploaded (by Reedy; owner: Reedy):
[mediawiki/vendor@master] Updating monolog/monolog (2.1.1 => 2.2.0)

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

Change 655622 had a related patch set uploaded (by Reedy; owner: Reedy):
[mediawiki/core@master] Updating monolog/monolog (2.1.1 => 2.2.0)

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

Change 655626 had a related patch set uploaded (by Reedy; owner: Reedy):
[mediawiki/core@master] Updating monolog/monolog (2.1.1 => 2.2.0)

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

Change 655622 abandoned by Reedy:
[mediawiki/core@master] Updating monolog/monolog (2.1.1 => 2.2.0)

Reason:

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

Change 655621 abandoned by Reedy:
[mediawiki/vendor@master] Updating monolog/monolog (2.1.1 => 2.2.0)

Reason:
Sigh, change-id fails

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

Change 655712 had a related patch set uploaded (by Reedy; owner: Reedy):
[mediawiki/vendor@master] Updating monolog/monolog (2.1.1 => 2.2.0)

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

Change 655712 merged by jenkins-bot:
[mediawiki/vendor@master] Updating monolog/monolog (2.1.1 => 2.2.0)

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

Change 655626 merged by jenkins-bot:
[mediawiki/core@master] Updating monolog/monolog (2.1.1 => 2.2.0)

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

Change 664701 had a related patch set uploaded (by Reedy; owner: Reedy):
[mediawiki/core@REL1_35] Updating monolog/monolog (1.25.3 => 2.0.2)

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

Change 664703 had a related patch set uploaded (by Reedy; owner: Reedy):
[mediawiki/core@REL1_35] Updating monolog/monolog (2.0.2 => 2.1.1)

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

Change 664704 had a related patch set uploaded (by Reedy; owner: Reedy):
[mediawiki/core@REL1_35] Updating monolog/monolog (2.1.1 => 2.2.0)

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

Change 664701 merged by jenkins-bot:
[mediawiki/core@REL1_35] Updating monolog/monolog (1.25.3 => 2.0.2)

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

Change 664703 merged by jenkins-bot:
[mediawiki/core@REL1_35] Updating monolog/monolog (2.0.2 => 2.1.1)

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

Change 664704 merged by jenkins-bot:
[mediawiki/core@REL1_35] Updating monolog/monolog (2.1.1 => 2.2.0)

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

Change 677052 had a related patch set uploaded (by Seb35; author: Seb35):

[mediawiki/core@master] Fix the test MonologSpiTest::testDefaultChannel

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

Change 677052 merged by jenkins-bot:

[mediawiki/core@master] Fix the test MonologSpiTest::testDefaultChannel

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

Change 677405 had a related patch set uploaded (by Reedy; author: Seb35):

[mediawiki/core@REL1_35] Fix the test MonologSpiTest::testDefaultChannel

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

Change 677405 merged by jenkins-bot:

[mediawiki/core@REL1_35] Fix the test MonologSpiTest::testDefaultChannel

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

Change 580096 abandoned by Krinkle:

[operations/mediawiki-config@master] logging: Remove useMicrosecondTimestamps(false) calls

Reason:

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

Change 580096 restored by Krinkle:

[operations/mediawiki-config@master] logging: Remove useMicrosecondTimestamps(false) calls

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