Page MenuHomePhabricator
Paste P47993

T324913 debugging notes
ActivePublic

Authored by Chlod on May 9 2023, 12:13 PM.
Referenced Files
F36989762: T324913 debugging notes.md
May 9 2023, 12:13 PM
Subscribers
None
# T324913
* Debugging session.
* Setup started 9 May 2023, 18:07:40 (UTC +08:00)
* Debugging started 9 May 2023, 18:25:52.99 (UTC +08:00)
* User:Chlod
## Environment
* Windows 11 22H2 22621.1635
* Apache Server (httpd) 2.4.46
* PHP 8.0.2 ( ZTS Visual C++ 2019 x64 )
* 8.0.2 (apache2handler)
* MediaWiki 1.41.0-alpha (f98e5b9) on `mwdev.chlod.local`
* MySQL 8.0.23
* PageTriage (2079fa4; origin/master)
* Firefox 113.0b9 (64-bit)
### Sanitized data
* `mwdev\` -> `mwdev\`
## Setup
```
[a4dd9fed720d44dd54bf7ebc] /index.php?title=Main_Page Error: Call to undefined method Wikimedia\Rdbms\LBFactorySimple::getPrimaryDatabase()
Backtrace:
from mwdev\extensions\PageTriage\ServiceWiring.php(9)
#0 mwdev\core\vendor\wikimedia\services\src\ServiceContainer.php(447): Wikimedia\Services\ServiceContainer::{closure}()
#1 mwdev\core\vendor\wikimedia\services\src\ServiceContainer.php(411): Wikimedia\Services\ServiceContainer->createService()
#2 mwdev\core\includes\MediaWikiServices.php(302): Wikimedia\Services\ServiceContainer->getService()
#3 mwdev\core\vendor\wikimedia\services\src\ServiceContainer.php(419): MediaWiki\MediaWikiServices->getService()
#4 mwdev\core\vendor\wikimedia\object-factory\src\ObjectFactory.php(211): Wikimedia\Services\ServiceContainer->get()
#5 mwdev\core\vendor\wikimedia\object-factory\src\ObjectFactory.php(152): Wikimedia\ObjectFactory\ObjectFactory::getObjectFromSpec()
#6 mwdev\core\includes\HookContainer\HookContainer.php(473): Wikimedia\ObjectFactory\ObjectFactory->createObject()
#7 mwdev\core\includes\HookContainer\HookContainer.php(156): MediaWiki\HookContainer\HookContainer->getHandlers()
#8 mwdev\core\includes\HookContainer\HookRunner.php(851): MediaWiki\HookContainer\HookContainer->run()
#9 mwdev\core\includes\page\Article.php(1131): MediaWiki\HookContainer\HookRunner->onArticleViewFooter()
#10 mwdev\core\includes\page\Article.php(543): Article->showViewFooter()
#11 mwdev\core\includes\actions\ViewAction.php(78): Article->view()
#12 mwdev\core\includes\MediaWiki.php(542): ViewAction->show()
#13 mwdev\core\includes\MediaWiki.php(322): MediaWiki->performAction()
#14 mwdev\core\includes\MediaWiki.php(904): MediaWiki->performRequest()
#15 mwdev\core\includes\MediaWiki.php(562): MediaWiki->main()
#16 mwdev\core\index.php(50): MediaWiki->run()
#17 mwdev\core\index.php(46): wfIndexMain()
#18 {main}
```
Must be a bad core installation.
```
$ install-new.sh
```
MediaWiki 1.41.0-alpha (f98e5b9) installed.
## Pre-debug analysis
Let's take a look at the details:
```
The JavaScript console says Exception in module-execute in module ext.pageTriage.views.toolbar: TypeError: mw.pageTriage.Article is not a constructor.
```
This seems to be the main issue. TypeError implies that at the moment mw.pageTriage.Article is being instantiated, it does not exist. This means the issue is probably with how PageTriage loads.
* `I wonder if taking the code in modules/ext.pageTriage.util/models/ext.pageTriage.article.js (or all scripts in that dir for that matter) out of $(...) changes anything` (Nardog)
* This is definitely possible, but this shorthand (for `$( document ).ready(...)`) should execute code sequentially (in the order of registration). If this were the issue, then article would not exist at the time of execution either way.
* `ext.pageTriage.toolbarStartup references mw.pageTriage. That gets defined in ext.pageTriage.init. So dependencies also fine there ✔️`
* No issues with dependencies. I'm assuming these also work in the proper order. So it's something else?
* `are there any server side logs we can check to debug this further`
* This is a client-side issue, so server logs are unlikely to help.
It seems at the point of the error, Article is not being declared. There's a way to check every piece of code that runs prior to the instantiation of Article, and that's with the profiler on and debug=1. We'll try that first.
### Activity 1. Probing
Purely probing the code to see what runs and at which sequence. JavaScript is single-threaded, and I'm sure PageTriage isn't running anything that would otherwise work in a worker context (which would trigger "multi-threading"), so we can assume that the sequence of calls in the profiler would be correct.
```
GET https://mwdev.chlod.local/index.php?title=Special:NewPages
```
Nothings showing, but no console errors either. ~~Am I missing rights?~~ Not missing rights per ListGroup Rights.
Checking where this is being run...
Oh, I'm dumb. I'm supposed to visit a page *listed* there.
```
GET https://mwdev.chlod.local/index.php?title=Random25
```
Working fine after 5 refreshes. Dialing network speed down to "Good 2G".
```
GET https://mwdev.chlod.local/index.php?title=Random25
Network-Speed: Good 2G (Firefox)
```
Still not showing. I guess it's worth doing the profiling now to see if Article is even being used at all.
```
GET https://mwdev.chlod.local/index.php?title=Random25&debug=yes
```
* profiler data: https://share.firefox.dev/42B2HeZ
Nothing popped up in the console. There's a stacktrace reported on enwiki. Let's investigate that and see if we find anything glaring.
```
TypeError: mw.pageTriage.Article is not a constructor
at ext.pageTriage.views.toolbar/ToolbarView.js (load.php?lang=en&modules=ext.pageTriage.views.toolbar&skin=vector&version=xmdtm:1)
at runScript (load.php?lang=en&modules=startup&only=scripts&raw=1&skin=vector:11)
at Array.<anonymous> (load.php?lang=en&modules=startup&only=scripts&raw=1&skin=vector:12)
at flushCssBuffer (load.php?lang=en&modules=startup&only=scripts&raw=1&skin=vector:4)
```
Article seems to be instantiated at the root level, so this should run as soon as the file is loaded. The profiler indicates that the render function is the only part running here (and it's only ever called if `article.fetch` had called back).
AH, but of course, if the Article constructor call is in the root level, and the Article class declaration is stuck in a `$(...)` call, then the toolbar instantiates the `Article` class at load time whereas the `Article` class is defined at execution time.
I'm unable to properly reproduce this, so we'll have to simulate the error. This, of course, causes a "straw-man"-like situation where we try to patch an artifically-introduced bug. But in this case, I'm slightly confident that this might work.
## Activity 2: Coercing reproduction
```diff
diff --git a/modules/ext.pageTriage.util/models/ext.pageTriage.article.js b/modules/ext.pageTriage.util/models/ext.pageTriage.article.js
index 8849fef5..d736d705 100644
--- a/modules/ext.pageTriage.util/models/ext.pageTriage.article.js
+++ b/modules/ext.pageTriage.util/models/ext.pageTriage.article.js
@@ -1,7 +1,15 @@
// Article represents the metadata for a single article.
// ArticleList is a collection of articles for use in the list view
-$( function () {
+function testDelay( func ) {
+ return ( ...args ) => {
+ setTimeout( () => {
+ func.call( this, args );
+ }, 5000 );
+ };
+}
+
+$( testDelay( function () {
mw.pageTriage.Article = Backbone.Model.extend( {
defaults: {
title: 'Empty Article',
@@ -455,4 +463,4 @@ $( function () {
} );
-} );
+} ) );
```
This simulates a 5000ms delay between actual declaration from load time.
```
GET https://mwdev.chlod.local/index.php?title=Random25&debug=yes
```
**REPLICATION SUCCESS.** Now trying this without `debug=yes`.
```
GET https://mwdev.chlod.local/index.php?title=Random25
```
**REPLICATION SUCCESS.** So this is a likely race condition.
The race condition occurs when toolbar.js has loaded but the article.js has not been called by `document.ready` yet. It would make sense that this is intermittent; toolbar is always loaded asynchronously (there's no entries for it in extension.json that would indicate a synchronous load along with other modules).
Now as to why this is happening, I'm still unsure. This shouldn't happen if all paths that lead to the toolbar loading are under a `$(...)` call as well. I'll check if this is the case in other files.
* `mw.loader.using`:
* toolbarStartup: ✅ `$(...)`
* `require()`
* No calls found...
Looks like the prior assumption that `$(...)` loads things synchronously is incorrect. Perhaps this isn't the case for the English Wikipedia?
Re-reading the ticket, it seems Nardog already found this out some time ago.
Perhaps toolbarStartup is being called before article.js in terms of sequencing? This means the module is loaded in the wrong sequence.
```
ext.pageTriage.toolbarStartup references mw.pageTriage. That gets defined in ext.pageTriage.init. So dependencies also fine there ✔️
```
Though this may be true, it doesn't seem like `ext.pageTriage.toolbarStartup` requires `ext.pageTriage.util`. So in terms of loading, if `ext.pageTriage.util` isn't earlier in the ResourceLoader load sequence, then it's possible that the toolbarStartup's `$(...)` call is perfored *earlier* than `article.js`'.
**LocalSettings.php**
```
$wgDebugLogFile = "debug.log";
```
Earlier diff undone.
It seems ResourceLoader doesn't log anything. We'll instead break as soon as `toolbarStartup.js` loads and check the call stack.
```diff
diff --git a/modules/ext.pageTriage.toolbarStartup/ext.pageTriage.toolbarStartup.js b/modules/ext.pageTriage.toolbarStartup/ext.pageTriage.toolbarStartup.js
index 4270dd67..9fb6c589 100644
--- a/modules/ext.pageTriage.toolbarStartup/ext.pageTriage.toolbarStartup.js
+++ b/modules/ext.pageTriage.toolbarStartup/ext.pageTriage.toolbarStartup.js
@@ -1,3 +1,4 @@
+debugger;
$( function () {
const ns = mw.config.get( 'wgNamespaceNumber' );
```
Using the debugger statement above, I'm dumping the registry's load states.
```
> registry["ext.pageTriage.util"].state
"registered"
```
`article.js` is merely registered at the point that `toolbarStartup.js` is executed. Since the `$(...)` here immediately executes afterwards, and `article.js` is not yet `"loaded"`, then we can confirm that `toolbarStartup` is run before `article.js` is loaded (and therefore, the `$(...)` calls are run in the wrong order).
Why this doesn't happen all the time is still beyond me. Perhaps a ResourceLoader expert knows more.
## Actvity 3: Propspective fix attempt
Patch applied with previous (for debugging).
```
diff --git a/extension.json b/extension.json
index 169872e8..7c7375d6 100644
--- a/extension.json
+++ b/extension.json
@@ -730,7 +730,8 @@
"ext.pageTriage.toolbarStartup/ext.pageTriage.toolbarStartup.js"
],
"dependencies": [
- "ext.pageTriage.init"
+ "ext.pageTriage.init",
+ "ext.pageTriage.util"
]
},
"ext.pageTriage.article": {
```
```
> registry["ext.pageTriage.util"]
"ready"
```
Bingo bongo. Now we're 100% sure that the `article.js`' `$(...)` call fires before `toolbarStartup.js`' `$(...)` call.
This patch will be a shot in the dark, but it has a good chance of fixing the issue based on the story told above. We'll see if the issues persist after some time, and mark the ticket as closed if it hasn't reappeared in a month or so.
## Activity 4: Revelation
This dawned on me as I was writing the commit message. The race condition occurs because `mw.loader.using` is asynchronous. `Article` isn't required by `toolbarStartup`, it's required by `views.toolbar`. If, at the time `views.toolbar` is loaded, `Article` hasn't finished executing, *then* the issue appears.
So I guess this isn't that much of a shot in the dark after all. I'll include this reasoning in the commit message.
Also just had the thought: *but if `views.toolbar` depends on `util`, why is there still a race condition?
This is due to the call sequence found in the `$(...)` files. So basically, this can happen:
* Page load
* `toolbarStartup` is loaded
* `$(...)` to load `views.toolbar` is registered
* `state` becomes `ready`
* `util` is loaded
* `$(...)` to declare Article is registered
* `state` becomes `ready`
* Document becomes ready
* `views.toolbar` is being loaded
* ResourceLoader sees that `util` is ready. It won't include it in the request for `views.toolbar`.
* In reality, `util` is ready but Article is yet to be declared later in this chain of events.
* `toolbar` loads! **RACE CONDITION HIT.**
* This can hit a race condition because cached responses have a 0ms response time. Subsequent JavaScript code will run immediately after the module has loaded. Since JS is single-threaded, we probably didn't yield to the event loop (which is usually done to make way for other JS to run while network requests are being performed).
* `$(...)` to declare Article is executed
## Activity 5: Patch
```diff
diff --git a/extension.json b/extension.json
index 169872e8..7c7375d6 100644
--- a/extension.json
+++ b/extension.json
@@ -730,7 +730,8 @@
"ext.pageTriage.toolbarStartup/ext.pageTriage.toolbarStartup.js"
],
"dependencies": [
- "ext.pageTriage.init"
+ "ext.pageTriage.init",
+ "ext.pageTriage.util"
]
},
"ext.pageTriage.article": {
```
Add .util as dependency of .toolbarStartup
This adds `ext.pageTriage.util` as an explicit dependency of
`ext.pageTriage.toolbarStartup`. This ensures that upon client-side load,
the `$(...)` call inside of `ext.pageTriage.util/.../ext.pageTriage.article.js`
is executed before the `$(...)` call inside of
`ext.pageTriage.toolbarStartup.js`. This is due to the way ResourceLoader
loads dependencies, which is otherwise sequential unless it comes across an
unloaded dependency. Since `mw.loader.using` is asynchronous, it's possible
that `ext.pageTriage.views.toolbar` loads prior to `ext.pageTriage.util`
being able to register `mw.pageTriage.Article`, if the request for
`ext.pageTriage.views.toolbar` is cached.
Bug: T324913