@Dreamy_Jazz - I quickly checked this code and I found that this is caused by this line

https://github.com/wikimedia/mediawiki-extensions-CheckUser/blame/54abedf7c2e4e2a6157c48e13a95c612732c61c5/src/Hooks.php#L262

'cule_timestamp' => $dbw->timestamp( $logEntry->getTimestamp() ),

My understanding is that $dbw always exists, therefore it's the $logEntry that has to be null. The $logEntry comes from the $id - method argument.

       [...]
	 * @param ?RecentChange $rc If triggered by a RecentChange, then this is the associated
	 *  RecentChange object. Null if not triggered by a RecentChange.
         */
	private static function insertIntoCuLogEventTable(
		int $id,
		string $method,
		UserIdentity $user,
		?RecentChange $rc = null
	) {
		$services = MediaWikiServices::getInstance();
		$dbw = $services->getDBLoadBalancer()->getConnection( DB_PRIMARY );

		/** @var DatabaseLogEntry $logEntry Should not be null as a valid ID must be provided */
		$logEntry = DatabaseLogEntry::newFromId( $id, $dbw );
                [...]

This change was introduced in https://gerrit.wikimedia.org/r/c/mediawiki/extensions/CheckUser/+/876322/23/src/Hooks.php#258 (https://phabricator.wikimedia.org/T324907) which you're the author - therefore I'd like to consult the next steps with you.

The $rc is present when the log is associated with RecentChange. and the $id comes from $rc->getAttribute( 'rc_logid' ). Because this error is executed via maintenance script - I'm wondering - do we have a valid RecentChange in this scenario? There is a comment that says that DatabaseLogEntry should not be null, but it looks like it is we're getting NULLs - and I'm wondering what to do in such a situation.
We use DB_PRIMARY, therefore I cross out race conditions/replication lag. Therefore I see two options, $id is incorrect/missing in some scenarios, or the LogEntry for the given $id just do not exist.

The only thing that currently comes to my mind is to log the $id and then check in DB what's happening. Do you have any suggestions on how can we proceed?

Thanks for taking a look at this.

In T343983#9106719, @pmiazga wrote:

The $rc is present when the log is associated with RecentChange. and the $id comes from $rc->getAttribute( 'rc_logid' ). Because this error is executed via maintenance script - I'm wondering - do we have a valid RecentChange in this scenario? There is a comment that says that DatabaseLogEntry should not be null, but it looks like it is we're getting NULLs - and I'm wondering what to do in such a situation.
We use DB_PRIMARY, therefore I cross out race conditions/replication lag. Therefore I see two options, $id is incorrect/missing in some scenarios, or the LogEntry for the given $id just do not exist.

The only thing that currently comes to my mind is to log the $id and then check in DB what's happening. Do you have any suggestions on how can we proceed?

When first looking at this problem, I was unsure why this was occurring.

The value in rc_logid in this case must both:

1. Be an integer - https://github.com/wikimedia/mediawiki-extensions-CheckUser/blame/54abedf7c2e4e2a6157c48e13a95c612732c61c5/src/Hooks.php#L230 ensures only integers are passed and would cause an exception earlier than this point if the parameter was not an integer
2. Not be zero - https://github.com/wikimedia/mediawiki-extensions-CheckUser/blame/54abedf7c2e4e2a6157c48e13a95c612732c61c5/src/Hooks.php#L109 means a different method (Hooks::insertIntoCuPrivateEventTable) is called if the value is 0.

This means that the RecentChange entry has a log ID as a non-zero integer value. This would therefore suggest to me that the log ID is not valid for some reason. I can see no reason as to why this would be the case on inspection of the code in CentralAuth just now. It may make sense to log this and wait until the next run of this maintenance script.

Change 951171 had a related patch set uploaded (by Pmiazga; author: Pmiazga):

[mediawiki/extensions/CheckUser@master] Add the debug for T343983

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

The logstash entry (if you have access) shows that this was encountered by the attempts to fix two "stuck" global renames on enwiki and amwiki (one rename per wiki). In trying to find a log entry, I encountered a different problem I have filed as T344632. Notwithstanding the other problem I found, I was unable to find the log entry under the target username on the wikis mentioned.

Change 951171 merged by jenkins-bot:

[mediawiki/extensions/CheckUser@master] Add the debug for T343983

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

Mentioned in SAL (#wikimedia-operations) [2023-09-01T16:19:01Z] <pmiazga> T343983 Ran mwscript extensions/CentralAuth/maintenance/fixStuckGlobalRename.php --wiki=amwiki --logwiki=metawiki Jean-Mahmood User92259453

I cannot reproduce it anymore nor I don't see any similar logs. This error happened twice on on 2023-08-10 after each command:

09:07 urbanecm: mwscript extensions/CentralAuth/maintenance/fixStuckGlobalRename.php --wiki=amwiki --logwiki=metawiki 'Jean-Mahmood' 'User92259453'
09:08 urbanecm: mwscript extensions/CentralAuth/maintenance/fixStuckGlobalRename.php --wiki=enwiki --logwiki=metawiki 'Mittzy' 'Mittzy (usurped)'

I re-run the first script and it failed with

User92259453 does not have a rename in progress on this wiki.

I skipped the second user. I checked the logs and I don't see anything related to this ticket, or to user renames in general.

I do not have access to /wiki/Special:RenameUser on (amwiki|enwiki) therefore I cannot validate this more.

@Dreamy_Jazz do you have any way to validate if this is still happening? We can keep this open and keep an eye, to verify if this happens again.

At a wild guess, snapshot isolation might be hiding the new row? The insert and the select are in different implicit transactions, but probably in the same actual transaction.

In T343983#9137239, @pmiazga wrote:

@Dreamy_Jazz do you have any way to validate if this is still happening? We can keep this open and keep an eye, to verify if this happens again.

Unfortunately I do not have a way to validate this is still happening.

I found another log statement exactly from the same line. The previous error comes from fixStuckGlobalRename but the one I found comes from SpamBlacklist: https://logstash.wikimedia.org/app/dashboards#/view/c7013c90-a487-11ec-be91-b3435f0c0c49?_g=h@53fc073&_a=h@8974712 and was triggered on EditPage.

In case this error gets removed from our logstash:

Error

• service.version: 1.41.0-wmf.24
• trace.id: 4982a2b9-32c0-44c9-b282-b3c2af78b979
• Find trace.id in Logstash

[{reqId}] {exception_url}   Error: Call to a member function getTimestamp() on null

from /srv/mediawiki/php-1.41.0-wmf.24/extensions/CheckUser/src/Hooks.php(270)
#0 /srv/mediawiki/php-1.41.0-wmf.24/extensions/CheckUser/src/Hooks.php(140): MediaWiki\CheckUser\Hooks::insertIntoCuLogEventTable(integer, string, User, RecentChange)
#1 /srv/mediawiki/php-1.41.0-wmf.24/extensions/SpamBlacklist/includes/SpamBlacklist.php(259): MediaWiki\CheckUser\Hooks::updateCheckUserData(RecentChange)
#2 /srv/mediawiki/php-1.41.0-wmf.24/extensions/SpamBlacklist/includes/SpamBlacklist.php(152): MediaWiki\Extension\SpamBlacklist\SpamBlacklist->logFilterHit(User, MediaWiki\Title\Title, string)
#3 /srv/mediawiki/php-1.41.0-wmf.24/extensions/SpamBlacklist/includes/Hooks.php(135): MediaWiki\Extension\SpamBlacklist\SpamBlacklist->filter(string, MediaWiki\Title\Title, User)
#4 /srv/mediawiki/php-1.41.0-wmf.24/includes/HookContainer/HookContainer.php(161): MediaWiki\Extension\SpamBlacklist\Hooks->onEditFilterMergedContent(DerivativeContext, WikitextContent, MediaWiki\Status\Status, string, User, boolean)
#5 /srv/mediawiki/php-1.41.0-wmf.24/includes/HookContainer/HookRunner.php(1473): MediaWiki\HookContainer\HookContainer->run(string, array)
#6 /srv/mediawiki/php-1.41.0-wmf.24/includes/editpage/Constraint/EditFilterMergedContentHookConstraint.php(106): MediaWiki\HookContainer\HookRunner->onEditFilterMergedContent(DerivativeContext, WikitextContent, MediaWiki\Status\Status, string, User, boolean)
#7 /srv/mediawiki/php-1.41.0-wmf.24/includes/editpage/Constraint/EditConstraintRunner.php(88): MediaWiki\EditPage\Constraint\EditFilterMergedContentHookConstraint->checkConstraint()
#8 /srv/mediawiki/php-1.41.0-wmf.24/includes/editpage/EditPage.php(2431): MediaWiki\EditPage\Constraint\EditConstraintRunner->checkConstraints()
#9 /srv/mediawiki/php-1.41.0-wmf.24/includes/editpage/EditPage.php(1824): MediaWiki\EditPage\EditPage->internalAttemptSave(NULL, boolean, boolean)
#10 /srv/mediawiki/php-1.41.0-wmf.24/includes/editpage/EditPage.php(734): MediaWiki\EditPage\EditPage->attemptSave(NULL)
#11 /srv/mediawiki/php-1.41.0-wmf.24/includes/actions/EditAction.php(66): MediaWiki\EditPage\EditPage->edit()
#12 /srv/mediawiki/php-1.41.0-wmf.24/includes/actions/SubmitAction.php(38): EditAction->show()
#13 /srv/mediawiki/php-1.41.0-wmf.24/includes/MediaWiki.php(571): SubmitAction->show()
#14 /srv/mediawiki/php-1.41.0-wmf.24/includes/MediaWiki.php(350): MediaWiki->performAction(Article, MediaWiki\Title\Title)
#15 /srv/mediawiki/php-1.41.0-wmf.24/includes/MediaWiki.php(942): MediaWiki->performRequest()
#16 /srv/mediawiki/php-1.41.0-wmf.24/includes/MediaWiki.php(591): MediaWiki->main()
#17 /srv/mediawiki/php-1.41.0-wmf.24/index.php(50): MediaWiki->run()
#18 /srv/mediawiki/php-1.41.0-wmf.24/index.php(46): wfIndexMain()
#19 /srv/mediawiki/w/index.php(3): require(string)
#20 {main}

I'm going to revisit this and see what could cause it. @Krinkle @Tgr do you have any ideas what could be wrong here?
Also I wonder why I cannot find the log statement I added (https://github.com/wikimedia/mediawiki-extensions-CheckUser/blob/60e70669030c39a4a1dd672f008f23cc7116aa3c/src/Hooks.php#L245)
When I search in logstash T343983 I get no results. Any ideas how can I improve the log?

@pmiazga I was able to find it (I think) at https://logstash.wikimedia.org/app/dashboards#/doc/logstash-*/logstash-deploy-1-7.0.0-1-2023.09.04?id=xfyrX4oBi6TOjMqmYTZz

Interestingly there seems to no log ID with that ID, but there is one for the ID before and the ID after. The ID logged was 32655553 but it seems actual ID used for the log that CheckUser was trying to store was 32655552 (https://nl.wikipedia.org/w/index.php?title=Speciaal:Logboeken&logid=32655552) because that log ID is associated with the SpamBlacklist hit.

https://nl.wikipedia.org/w/index.php?title=Speciaal:Logboeken&logid=32655553 shows nothing and then https://nl.wikipedia.org/w/index.php?title=Speciaal:Logboeken&logid=32655554 shows an unrelated event.

There could be a private log event with that ID, but given that the failure is because no log was associated with the log ID I'm tempted to say there is no log with that ID in the DB.

In T343983#9161191, @Dreamy_Jazz wrote:

@pmiazga I was able to find it (I think) at https://logstash.wikimedia.org/app/dashboards#/doc/logstash-*/logstash-deploy-1-7.0.0-1-2023.09.04?id=xfyrX4oBi6TOjMqmYTZz

Yup, this is it. Ok, I don't know why but search was giving me no results, probably I messed up something when searching. Thanks!. I'll dig into this.

In T343983#9161195, @Dreamy_Jazz wrote:

Interestingly there seems to no log ID with that ID, but there is one for the ID before and the ID after.

Good catch! So, probably a DB rollback (maybe due to some unrelated error), and then the row ID is passed to a deferred or similar callback that runs outside the transaction?

There could be a private log event with that ID

There is no event with that ID.

So after investigating the code - We have a RecentChange entry, that contains information about the change in our system. RecentChange has an attribute rc_logid -> which is the log entry associated with given change. It can be 0 -> no log entry set, or a integer -> then it's a foreign_key to logging table.

When a RecentChange is created the logId is set to 0 by default.
rc_logid is set only, when RecentChange::newLogEntry() is called (https://gerrit.wikimedia.org/r/plugins/gitiles/mediawiki/core/+/refs/heads/master/includes/changes/RecentChange.php#905). This call has the $newId which should point to valid $logId.

The newLogEntry can be called or from :

1. RecentChange::notifyLog() -> this comes from LogPage::saveContent() when LogPage::updateRecentChanges is set to true
2. LogPage::saveContent() -> when LogPage::updateRecentChanges is false and sendToUDP is true
3. ManualLogEntry::publish() -> which is called by ton of things (26 usages).

Point 2 - informs only via UDP, doesn't save the RC, therefore it shouldn't be the culprit.
Point 1 -> Code is straightforward,

		$dbw->insert( 'logging', $data, __METHOD__ );
		$newId = $dbw->insertId();

		# And update recentchanges
		if ( $this->updateRecentChanges ) {
			$titleObj = SpecialPage::getTitleFor( 'Log', $this->type );
			RecentChange::notifyLog(
				$now, $titleObj, $this->performer, $this->getRcComment(), '',
				$this->type, $this->action, $this->target, $this->comment,
				$this->params, $newId, $this->getRcCommentIRC()
			);

And the RecentChange::notifyLog() (https://gerrit.wikimedia.org/r/plugins/gitiles/mediawiki/core/+/refs/heads/master/includes/changes/RecentChange.php#866) creates the Entry and calls save() immediately.
Save on RecentChange is performed on DB_PRIMARY LogPage::saveContent also uses DB_PRIMARY, therefore they should go in the same transaction (if there is one).

Therefore I assume the point 2 is also not a culprit.

This brings us to point 3 -> ManualLogEntry::publish() that gets the rc_logid via $newId argument. ( https://gerrit.wikimedia.org/r/plugins/gitiles/mediawiki/core/+/refs/heads/master/includes/logging/ManualLogEntry.php#405 ). The RecentChange::save() happens in deferred update, therefore if any of those 26 places that call ManualLogEntry::publish() happens in a transaction -> this could be the case.

I see four possible solutions here:

a) good but lengthy. We go through all 26 places where ManualLogEntry::publish() is called. Check which can end up with rollback -> then understand the cause of rollback and or fix it, or refactor code to support such event.

b) short, most likely should be fine - we need the LogEntry to get the timestamp. If we cannot get the timestamp, use wfTimestampNow() instead as we do in insertIntoCuPrivateEventTable. My understanding is that everything happens within a single request, therefore the timestamp might be milliseconds up to a couple of seconds off.

c) short but risky - when $RC doesn't have the valid $logId - or just don't log it, skip adding the row to cu_private_event and continue as if nothing happened. It may have some impact on CheckUser due to incomplete data (missing a row) in the cu_log_event. This is the current case, as when we get the exception mentioned in the ticket - row insertion fails.

d) leave it as it is, as it's impacting less than 0.1% of requests (1 entry in the last 30 days).

I don't the CheckUser extension that well, therefore it would be great to get a recommendation from someone who knows this extension better - as maybe the solution b) is good enough.
@Dreamy_Jazz do you have any recommendations here?

@pmiazga, thanks for the ping and your work on this. My thoughts on these solutions (as the listed individual maintainer of this extension):

a) Could work, but this wouldn't solve the issue long-term (as new places could use the method in a way that fails).

b) This will not work as when displaying rows from cu_log_event, as a SQL join is made to the logging table using the log ID provided. If this is invalid (i.e. no associated log_id in the logging table), then the row in cu_log_event would never be displayed because it uses an (inner) join.

c) A clarification question regarding this. Do you mean skip adding the row to cu_log_event? If there is a non-zero log ID the current behaviour is to try and insert into cu_log_event and the cu_private_event table is not touched.

d) This could be possible, but it would be good to find a solution that doesn't add exceptions to logstash even if it is rare.

I would propose an alternative:

e) In Hooks::updateCheckUserData, which is called when a RecentChanges entry is published, check both that the log ID is not zero and also that a row exists in the logging table for that log ID. If either of these fail, then add the data to cu_private_event that stores a copy of the data from the RecentChanges object (which means no SQL join to the logging table).

In c) I meant to skip adding this row entirely, and not add anything other. Yes, sorry, I messed up when copying/pasting. I didn't know is it safe to insert data to other table in such case as I don't know the big picture of what CheckUser is doing.

Let me rephrase the proposal - Instead of what we have right now - that calls self::insertIntoCuPrivateEventTable only when rc_logid == 0

			if ( $rc->getAttribute( 'rc_logid' ) == 0 ) {
				// [ ... ]
				self::insertIntoCuPrivateEventTable(
					$rcRow,
					__METHOD__,
					$rc->getPerformerIdentity(),
					$rc
				);
			} else {
				self::insertIntoCuLogEventTable(
					$rc->getAttribute( 'rc_logid' ),
					__METHOD__,
					$rc->getPerformerIdentity(),
					$rc
				);
			}

we want something along those lines:

                         $logEntry = fetchLogEntry( $rc->getAttribute('rc_logid') )

			if ( $logEntry === null ) {
				// [ ... ]
				self::insertIntoCuPrivateEventTable(
					$rcRow,
					__METHOD__,
					$rc->getPerformerIdentity(),
					$rc
				);
			} else {
				self::insertIntoCuLogEventTable(
					$rc->getAttribute( 'rc_logid' ),
					__METHOD__,
					$rc->getPerformerIdentity(),
					$rc
				);
			}

Am I right?

Change 957788 had a related patch set uploaded (by Pmiazga; author: Pmiazga):

[mediawiki/extensions/CheckUser@master] DNM: Store event in cu_private_even when related log entry cannot be found

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

I pushed the proposed change marked as DNM - @Dreamy_Jazz please let me know if this is what we're looking for. I haven't tested it yet, other than just running tests locally.

That is what I was looking for in my proposal. Thanks for creating the patch.

The downsides with this are:

1. Any suppression and/or revision deletion applied to the log entry under the correct ID will not be seen on the log event in CheckUser if stored in cu_private_event.
2. When the log entry appears in the results list, there will be no link to the log in Special:Log

Downside 2 is not a major issue, especially as this would occur very rarely.

Downside 1 could present more of an issue, but these tables were added to solve T326865 so the problem is still being reduced from all log entries to just a couple that end up in cu_private_event because of this issue. Furthermore, CheckUser still has no way to reliably find the "correct" log ID for the entry in these cases so to avoid this the code in other places would need to be fixed to ensure the logging ID exists before the RecentChanges entry is sent out.

In summary, in my opinion merging that patch you've created should solve this in a way that is acceptable.

Change 957788 merged by jenkins-bot:

[mediawiki/extensions/CheckUser@master] Store event in cu_private_event when related log entry cannot be found

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

Change 959210 had a related patch set uploaded (by Dreamy Jazz; author: Dreamy Jazz):

[mediawiki/extensions/CheckUser@master] Use cu_private_event on invalid log ID in populateCheckUserTable.php

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

I've created a follow-up change that makes the same change to the populateCheckUserTable.php maintenance script. This is not run on WMF wikis as it is run on the first run of update.php after the CheckUser extension is installed. Therefore, this is less of a priority, but otherwise should be addressed.

This follow-up is needed so that this issue, which may occur on third-party wikis, will not occur when running the populateCheckUserTable.php maintenance script. If this isn't implemented, then the issue will not cause a exception but will cause rows to be not displayed where the rc_logid was not a valid ID in the logging table.

Change 959210 merged by jenkins-bot:

[mediawiki/extensions/CheckUser@master] Use cu_private_event on invalid log ID in populateCheckUserTable.php

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

Suggested QA steps (for the maintenance script patch):

1. Choose one of:
   1. Create a fresh wiki,
   2. Use a wiki that has never had CheckUser installed, or
   3. Run the following SQL commands (these will wipe the CheckUser tables):

TRUNCATE TABLE cu_changes;
TRUNCATE TABLE cu_log_event;
TRUNCATE TABLE cu_private_event;

2. Move a page
3. Log into the database with a user that has write permissions
4. Run the following SQL and record the output

SELECT MAX(log_id) FROM logging;

5. Go into the database and run the following SQL where <id> is the log ID created by the move and <new id> is the ID from the SQL select query plus 1.

UPDATE recentchanges SET rc_logid = <new id> WHERE rc_logid = <id>;

6. Install CheckUser
7. Run php maintenance/run.php update.php

Verification step 1: Verify update.php runs without any errors
Verification step 2: Run the following SQL and verify that the result is 0, replacing <new id> with the same ID used as <new id> in the second query:

SELECT COUNT(*) FROM cu_log_event WHERE cule_log_id = <new id>;

Verification step 3: Verify that the output of the following SQL is move:

SELECT cupe_log_type FROM cu_private_event ORDER BY cupe_timestamp DESC LIMIT 1;

Testing the other patch through QA is much more difficult and as it is covered by tests, I propose that QA is not performed on that.

I think I found a way to reproduce the bug by setting this database trigger:

CREATE TRIGGER stop_insert BEFORE INSERT ON recentchanges FOR EACH ROW DELETE FROM logging WHERE log_id = new.rc_logid;

Every time a row is inserted into the recentchanges table, the associated row in the logging table is deleted. It might be a bit unrealistic, but it seems to reliably reproduce the bug in the parent commit.

With the above trigger, I performed a variety of actions and checked that they were inserted into the cu_private_event table (unless they were actions like edits).

I also temporarily disabled CheckUser, performed the same actions, then ran populateCheckUserTable.php maintenance script to see that the rows were also added to cu_private_event.

In case of regression, I repeated the same tests without the database trigger, to see the rows being added to cu_log_event as they normally should be.

Test environment: local docker (mysql) CheckUser 2.5 (e815596) 14:18, 9 October 2023.