editSessionID is duplicated in Edit:Schema for Wikitext
Closed, ResolvedPublic40 Estimated Story Points
Actions

Assigned To

Authored By

	Halfak
	Apr 13 2015, 5:38 PM

Description

It seems that the editingSessionId field is regularly duplicated in wikitext edit sessions, but not VE sessions.

     > SELECT
    ->   event_editor,
    ->   COUNT(*) AS sessions,
    ->   SUM(revisions > 1) AS cross_revision,
    ->   SUM(pages > 1) AS cross_page,
    ->   SUM(users > 1) AS cross_user
    -> FROM (
    ->   SELECT
    ->     event_editingSessionId,
    ->     event_editor,
    ->     COUNT(DISTINCT `event_page.revid`) AS revisions,
    ->     COUNT(DISTINCT `event_page.id`) AS pages,
    ->     COUNT(DISTINCT `event_user.id`) AS users
    ->   FROM Edit_11448630
    ->   WHERE
    ->     timestamp BETWEEN "20150401" AND "20150402" AND
    ->     event_action = "saveSuccess"
    ->   GROUP BY 1
    -> ) AS session_counts
    -> GROUP BY 1;
+--------------+----------+----------------+------------+------------+
| event_editor | sessions | cross_revision | cross_page | cross_user |
+--------------+----------+----------------+------------+------------+
| visualeditor |    13416 |              0 |          0 |          0 |
| wikitext     |   309795 |            627 |          3 |          0 |
+--------------+----------+----------------+------------+------------+
2 rows in set (49.02 sec)

I did some more digging. See my notes here: https://meta.wikimedia.org/wiki/Research_talk:VisualEditor%27s_effect_on_newly_registered_editors/Work_log/2015-04-13

TL;DR: 100% of dupe sessions have only one "init" event.

Details

Subject	Repo	Branch	Lines +/-
Follow-up cc5ca3a2f6: now that we sample client-side, send all editingStatsIds to the client	mediawiki/extensions/WikiEditor	wmf/1.26wmf4	+0 -4
Follow-up cc5ca3a2f6: now that we sample client-side, send all editingStatsIds to the client	mediawiki/extensions/WikiEditor	wmf/1.26wmf3	+0 -4
Follow-up cc5ca3a2f6: now that we sample client-side, send all editingStatsIds to the client	mediawiki/extensions/WikiEditor	master	+0 -4
Perform 25% sampling on the client side as well	mediawiki/extensions/WikiEditor	wmf/1.26wmf3	+7 -0
Perform 25% sampling on the client side as well	mediawiki/extensions/WikiEditor	master	+7 -0
Regenerate editingStatsId on unload	mediawiki/extensions/WikiEditor	wmf/1.26wmf1	+16 -5
Regenerate editingStatsId on unload	mediawiki/extensions/WikiEditor	wmf/1.26wmf2	+16 -5
Regenerate editingStatsId on unload	mediawiki/extensions/WikiEditor	master	+15 -4

Customize query in gerrit

Related Objects

Mentioned In: rEWEDda3dec37649e: Follow-up cc5ca3a2f6: now that we sample client-side, send all…
rEWED622447881ae5: Follow-up cc5ca3a2f6: now that we sample client-side, send all…
rMEXT0275abef9145: Updated mediawiki/extensions Project: mediawiki/extensions/WikiEditor…
rEWEDbfae89b9e0bb: Follow-up cc5ca3a2f6: now that we sample client-side, send all…
rEWEDf29688cbd6e2: Perform 25% sampling on the client side as well
rEWEDcc5ca3a2f6d7: Perform 25% sampling on the client side as well
rMEXT774f1e72be8f: Updated mediawiki/extensions Project: mediawiki/extensions/WikiEditor…
rEWEDba7b148b228c: Regenerate editingStatsId on unload
rEWED1c6652452c8d: Regenerate editingStatsId on unload
rEWED418baf1efa85: Regenerate editingStatsId on unload
rMEXT6ab67bcd23b8: Updated mediawiki/extensions Project: mediawiki/extensions/WikiEditor…
Mentioned Here: rEWEDcc5ca3a2f6d7: Perform 25% sampling on the client side as well

Event Timeline

Halfak created this task.Apr 13 2015, 5:38 PM

Halfak raised the priority of this task from to Needs Triage.

Halfak updated the task description. (Show Details)

Halfak added a project: VisualEditor.

Halfak subscribed.

Restricted Application added a subscriber: Aklapper. · View Herald TranscriptApr 13 2015, 5:38 PM

Krenair edited projects, added WikiEditor (2010); removed VisualEditor.Apr 13 2015, 8:04 PM

Krenair set Security to None.

I just ran some tests and I was able to reproduce this issue on enwiki.

Steps to reproduce:

Go to wikitext editor
Make changes and click save
Click the back button in your browser so that you are back in the wikitext editor
Make more changes and save again

> SELECT timestamp, event_editingSessionId, event_action, `event_page.revid`, `event_page.title` FROM Edit_11448630 WHERE timestamp BETWEEN "20150413221400" AND "20150413222400" and `event_user.id` = 6396742 order by timestamp desc limit 10;
+----------------+----------------------------------+--------------+------------------+------------------------+
| timestamp      | event_editingSessionId           | event_action | event_page.revid | event_page.title       |
+----------------+----------------------------------+--------------+------------------+------------------------+
| 20150413222032 | b92dae61ab756f83aab8c27f0f30efc8 | saveAttempt  |        656342002 | User:EpochFail/sandbox |
| 20150413222032 | b92dae61ab756f83aab8c27f0f30efc8 | saveSuccess  |        656342037 | User:EpochFail/sandbox |
| 20150413222017 | b92dae61ab756f83aab8c27f0f30efc8 | ready        |                0 | User:EpochFail/sandbox |
| 20150413222014 | b92dae61ab756f83aab8c27f0f30efc8 | saveAttempt  |        656341356 | User:EpochFail/sandbox |
| 20150413222014 | b92dae61ab756f83aab8c27f0f30efc8 | saveSuccess  |        656342002 | User:EpochFail/sandbox |
| 20150413221731 | b92dae61ab756f83aab8c27f0f30efc8 | ready        |                0 | User:EpochFail/sandbox |
| 20150413221729 | b92dae61ab756f83aab8c27f0f30efc8 | abort        |                0 | User:EpochFail/sandbox |
| 20150413221720 | b92dae61ab756f83aab8c27f0f30efc8 | ready        |                0 | User:EpochFail/sandbox |
| 20150413221715 | b92dae61ab756f83aab8c27f0f30efc8 | saveSuccess  |        656341356 | User:EpochFail/sandbox |
| 20150413221715 | b92dae61ab756f83aab8c27f0f30efc8 | saveAttempt  |        656340241 | User:EpochFail/sandbox |
+----------------+----------------------------------+--------------+------------------+------------------------+

Jdforrester-WMF assigned this task to Krenair.Apr 15 2015, 12:07 AM

Jdforrester-WMF triaged this task as High priority.

Jdforrester-WMF added a project: VisualEditor 2014/15 Q4 blockers.

Jdforrester-WMF added a subscriber: Catrope.

In T95919#1205423, @Halfak wrote:

I just ran some tests and I was able to reproduce this issue on enwiki.

Steps to reproduce:

Go to wikitext editor

Make changes and click save

Click the back button in your browser so that you are back in the wikitext editor

Make more changes and save again

I'm guessing this probably only works in Firefox?

Sorry. Good question. I am using Google Chrome 41.0.2272.118 (64-bit) on Ubuntu 14.04.

Hmm so even Chrome retains hidden form field data on back? That actually surprises me a bit. I was expecting this to be a Firefox issue because they have a bfcache that avoids reloading the page altogether.

• Rdicerb subscribed.Apr 15 2015, 12:53 AM

When I tried this yesterday in Chrome, I would get a new session when I went back.

Though it seems to be retaining the session now. I wonder what's different.

• Elitre subscribed.Apr 15 2015, 10:27 AM

I have no idea how we can work around this.

Maybe you could check if the current version of the page matches the parentRevId field and update the sessionId if it doesn't.

Urgh. Then we'd have to query the API to check the latest revision ID for the page, every time you open the edit page?

Maybe you could store the sessionId some other way[1] and destroy it upon loading the completed edit screen. I'm worried that speculating at you wildly isn't too productive. Maybe you could run the problem past someone else on the VE team?

Logging in Wikitext needs to be roughly equivalent to VE's logging capabilities or we simply won't be able to compare how users use the two interfaces quantitatively.

e.g. cookie or localstore.

I have a feeling we're going to run into issues with multiple tabs...

Actually, when I press back, I seem to get my old cookies as well.

... In some circumstances and not others, I think. It might depend on some part of my code that checks whether the request was POST or not.

Jdforrester-WMF raised the priority of this task from High to Unbreak Now!.Apr 17 2015, 8:13 PM

Jdforrester-WMF assigned this task to Catrope.Apr 17 2015, 9:58 PM

GOIII subscribed.Apr 18 2015, 11:45 PM

Change 205189 had a related patch set uploaded (by Jforrester):
Regenerate editingStatsId on pageshow

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

gerritbot added a project: Patch-For-Review.Apr 20 2015, 1:38 AM

Change 205189 had a related patch set uploaded (by Catrope):
Regenerate editingStatsId on unload

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

Change 205189 merged by jenkins-bot:
Regenerate editingStatsId on unload

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

Diffusion mentioned this in rMEXT6ab67bcd23b8: Updated mediawiki/extensions Project: mediawiki/extensions/WikiEditor….Apr 21 2015, 1:06 AM

Change 205484 had a related patch set uploaded (by Catrope):
Regenerate editingStatsId on unload

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

Change 205485 had a related patch set uploaded (by Catrope):
Regenerate editingStatsId on unload

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

Catrope mentioned this in rEWED418baf1efa85: Regenerate editingStatsId on unload.Apr 21 2015, 1:07 AM

Change 205485 merged by jenkins-bot:
Regenerate editingStatsId on unload

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

Catrope mentioned this in rEWED1c6652452c8d: Regenerate editingStatsId on unload.Apr 21 2015, 1:08 AM

Change 205484 merged by jenkins-bot:
Regenerate editingStatsId on unload

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

Catrope mentioned this in rEWEDba7b148b228c: Regenerate editingStatsId on unload.Apr 21 2015, 1:09 AM

This should now be resolved (or, at least, much lower than the 0.2% of sessions it was before). @Halfak, can you confirm?

Jdforrester-WMF edited a custom field.Apr 21 2015, 11:00 PM

Jdforrester-WMF moved this task from Nominated to Done on the VisualEditor 2014/15 Q4 blockers board.

@Jdforrester-WMF, sure. When should I expect to see new data rolling in?

When I apply the "steps to reproduce" above, I get weird sessions with short sessionIds that only have "ready" events rather than the expected new, full session. The usual sessionId I see is 32 characters long, but these short sessionIds are only 16 chars long. When I look in the HTML, I see that the editingStatsId is set to this 16 chat string after I hit the back button to return to the edit pane. See my query below of my edits to my sandbox today that demonstrate the issue below:

> SELECT timestamp, event_editingSessionId, event_action, `event_page.revid` FROM Edit_11448630 WHERE timestamp > "20150423" AND `event_page.title` = "User:EpochFail/sandbox";
+----------------+----------------------------------+--------------+------------------+
| timestamp      | event_editingSessionId           | event_action | event_page.revid |
+----------------+----------------------------------+--------------+------------------+
| 20150424010652 | 05e0dd06a67ec60600fd44db34a8f2e1 | init         |        658922398 |
| 20150424010653 | 05e0dd06a67ec60600fd44db34a8f2e1 | ready        |                0 |
| 20150424010812 | 05e0dd06a67ec60600fd44db34a8f2e1 | saveSuccess  |        658923332 |
| 20150424010812 | 05e0dd06a67ec60600fd44db34a8f2e1 | saveAttempt  |        658922398 |
| 20150424010817 | e6f1d8a8d9716f2c                 | ready        |                0 |
| 20150424010843 | 6bf47b47ef047a05                 | ready        |                0 |
| 20150424010907 | 2b776d8238d0da69                 | ready        |                0 |
+----------------+----------------------------------+--------------+------------------+
7 rows in set (9.03 sec)

I think that those "ready" events with the short sessionId should have corresponding "saveAttempt" and "saveSuccess" events.

So I'm re-opening this task because it seems that new problems have been introduced.

Yeah, the new session IDs created when you hit the back button are shorter because we use mw.user.generateRandomSessionId() on the client (there is not necessarily a request going back to the server in this case). I don't think we're sampling these properly before ready/abort, but I think the server might be filtering them for saveSuccess/saveAttempt.

We might be able to create an "init" event when this happens, but I don't remember the exact issues involved with that. @Catrope?

@Jdforrester-WMF, @Catrope & @Krenair. Any progress here?

In T95919#1234009, @Krenair wrote:

Yeah, the new session IDs created when you hit the back button are shorter because we use mw.user.generateRandomSessionId() on the client (there is not necessarily a request going back to the server in this case). I don't think we're sampling these properly before ready/abort, but I think the server might be filtering them for saveSuccess/saveAttempt.

We might be able to create an "init" event when this happens, but I don't remember the exact issues involved with that. @Catrope?

We could send an "init" event when the user presses back, but the timing would be a lie (since it would be emitted at the same time as ready). If that's OK with you, it shouldn't be too hard to implement (despite Chrome's best attempts to make it difficult).

Alternatively, is the data useful to you without these init events? The sessions with shorter IDs and a ready event should be real sessions, with saveAttempt/Success where relevant and even abort events.

Also, https://gerrit.wikimedia.org/r/#/c/205194/ fixes the "revid is 0 for ready events" issue, but I haven't been able to get anyone to review it yet.

In T95919#1242184, @Halfak wrote:

@Jdforrester-WMF, @Catrope & @Krenair. Any progress here?

What do you want changed, exactly (and why)? We're using the Analytics-mandated session ID generators, which for some reason unknown to us have different UID lengths (16 and 32). Nothing in VE, WE or EL cares about the lengths of the strings, right?

I get weird sessions with short sessionIds that only have "ready" events rather than the expected new, full session.

In my opinion, this is a substantial regression. I'd rather get all of the events with overlapping sessionIds than not get most of the events. All of the sessions that I show in my query above should have a saveSuccess event. The last 3 only have "ready".

As @Krenair noted:

I don't think we're sampling these properly before ready/abort,

It seems that only the "ready" event is making through some filter.

In T95919#1242777, @Halfak wrote:

I get weird sessions with short sessionIds that only have "ready" events rather than the expected new, full session.

In my opinion, this is a substantial regression. I'd rather get all of the events with overlapping sessionIds than not get most of the events. All of the sessions that I show in my query above should have a saveSuccess event. The last 3 only have "ready".

As @Krenair noted:

I don't think we're sampling these properly before ready/abort,

It seems that only the "ready" event is making through some filter.

Understood, thanks for the clarification. @Catrope is fixing.

Change 207290 had a related patch set uploaded (by Catrope):
Perform 25% sampling on the client side as well

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

Change 207290 merged by jenkins-bot:
Perform 25% sampling on the client side as well

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

Catrope mentioned this in rMEXT774f1e72be8f: Updated mediawiki/extensions Project: mediawiki/extensions/WikiEditor….Apr 28 2015, 10:03 PM

Catrope mentioned this in rEWEDcc5ca3a2f6d7: Perform 25% sampling on the client side as well.Apr 28 2015, 10:07 PM

nshahquinn-wmf subscribed.Apr 29 2015, 4:55 PM

Change 207529 had a related patch set uploaded (by Jforrester):
Perform 25% sampling on the client side as well

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

This issue (not sampling for clients) is now fixed in wmf4 and will be SWATed to wmf3 this afternoon.

Is there anything else to do here?

Change 207529 merged by jenkins-bot:
Perform 25% sampling on the client side as well

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

Jdforrester-WMF mentioned this in rEWEDf29688cbd6e2: Perform 25% sampling on the client side as well.Apr 29 2015, 7:14 PM

@Jdforrester-WMF what are you referring to re. sampling?

Is there anything else to do here?

I suppose that this still remains to be tested.

• ggellerman subscribed.Apr 29 2015, 8:55 PM

Again, I have tried to test this fix and I'm struggling to get a single WikiText event logged.

I have saved 27 edits to https://en.wikipedia.org/wiki/User:EpochFail/sandbox since 04/30. I have not seen a single, relevant saveSuccess event for these saves despite the relevant Event Logging tables being up to date. I am getting a few events however.

> SELECT timestamp, event_editingSessionId, event_action, `event_page.revid` FROM Edit_11448630 WHERE timestamp > "20150430000000" AND `event_page.title` = "User:EpochFail/sandbox";
+----------------+----------------------------------+--------------+------------------+
| timestamp      | event_editingSessionId           | event_action | event_page.revid |
+----------------+----------------------------------+--------------+------------------+
| 20150430223840 | 1b1db3b6fb5e7ddb58e1981e4f54b709 | init         |        659729529 |
| 20150501143759 | 0cfdb819302900211a444ebdc95b306b | init         |        660247699 |
| 20150501143801 | 0cfdb819302900211a444ebdc95b306b | ready        |                0 |
| 20150501144124 | 0cfdb819302900211a444ebdc95b306b | abort        |                0 |
+----------------+----------------------------------+--------------+------------------+
4 rows in set (33.74 sec)

If I were to run a simple chi^2 test to see if the sampling rate were set at 25%, the p-value at which I'd reject that hypothesis is 0.018!

So, I still thing something is wrong and I suspect that it is related to my pattern of [edit]->[back]->[edit]->[back]->...

Change 208299 had a related patch set uploaded (by Catrope):
Follow-up cc5ca3a2f6: now that we sample client-side, send all editingStatsIds to the client

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

Working with @Catrope, we found the source of the issue. It seems that a new session ID is not generated for edits after [back] if the originating edit didn't have an ID. This explains why I was seeing almost no events when going through the pattern described in my 'steps to reproduce'.

Change 208299 merged by jenkins-bot:
Follow-up cc5ca3a2f6: now that we sample client-side, send all editingStatsIds to the client

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

Catrope mentioned this in rEWEDbfae89b9e0bb: Follow-up cc5ca3a2f6: now that we sample client-side, send all….May 1 2015, 11:13 PM

Catrope mentioned this in rMEXT0275abef9145: Updated mediawiki/extensions Project: mediawiki/extensions/WikiEditor….

Change 208324 had a related patch set uploaded (by Catrope):
Follow-up cc5ca3a2f6: now that we sample client-side, send all editingStatsIds to the client

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

Change 208325 had a related patch set uploaded (by Catrope):
Follow-up cc5ca3a2f6: now that we sample client-side, send all editingStatsIds to the client

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

Change 208325 merged by jenkins-bot:
Follow-up cc5ca3a2f6: now that we sample client-side, send all editingStatsIds to the client

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

Change 208324 merged by jenkins-bot:
Follow-up cc5ca3a2f6: now that we sample client-side, send all editingStatsIds to the client

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

Catrope mentioned this in rEWEDda3dec37649e: Follow-up cc5ca3a2f6: now that we sample client-side, send all….May 2 2015, 2:02 AM

Catrope mentioned this in rEWED622447881ae5: Follow-up cc5ca3a2f6: now that we sample client-side, send all….

In T95919#1253800, @gerritbot wrote:

Change 208299 merged by jenkins-bot:
Follow-up cc5ca3a2f6: now that we sample client-side, send all editingStatsIds to the client

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

This is deployed now.

Jdforrester-WMF edited a custom field.May 5 2015, 3:55 PM

Hey folks,

I ran the usual set of tests against this again and while I'm *finally* seeing sessions logged when I hit the back button, I'm seeing a surprisingly large set of issues with how these sessions are logged. See my worklog here: https://meta.wikimedia.org/wiki/Research_talk:VisualEditor%27s_effect_on_newly_registered_editors/Work_log/2015-05-06

First let me define a couple of terms.

Regular session: This is a session that started with a click on "edit".
Back session: This is a session that started after a regular session was completed by clicking [back] in the browser to reload the wikitext editor

Now a summary of the issues I observed in my testing.

Sometimes regular sessions do not have a "saveSuccess" or "saveAttempt" when they ought to. These sessions also lack an "abort".
Back sessions never have an "init" or "ready" event.
Sometimes back sessions don't have a "saveAttempt" even when they *do* have a "saveSuccess" event.

I did some more testing here using a new user account and I was unable to reproduce these issues. (See the same worklog linked in the last comment). However, when I looked at how often these strange sessions are happening in practice, I found some alarming things.

 > SELECT LENGTH(event_editingSessionId), COUNT(*), SUM(attempts > 0) AS attempts, SUM(successes > 0) AS success, SUM(inits = 0) AS no_init, SUM(readies = 0) AS no_ready, SUM(successes > 0 AND attempts = 0) AS success_no_attempt, SUM(attempts > 0 AND readies = 0) AS attempt_no_ready  FROM (SELECT event_editingSessionId, SUM(event_action = "init") AS inits, SUM(event_action = "ready") AS readies, SUM(event_action = "abort") as aborts, SUM(event_action = "saveAttempt") as attempts, SUM(event_action = "saveSuccess") AS successes FROM Edit_11448630 WHERE timestamp > "20150506" AND event_editor = "wikitext" GROUP BY 1) AS sessions GROUP BY 1;
 +--------------------------------+----------+----------+---------+---------+----------+--------------------+------------------+
 | LENGTH(event_editingSessionId) | COUNT(*) | attempts | success | no_init | no_ready | success_no_attempt | attempt_no_ready |
 +--------------------------------+----------+----------+---------+---------+----------+--------------------+------------------+
 |                             16 |    10811 |      818 |     726 |   10811 |     1158 |                 36 |              124 |
 |                             32 |   674965 |    59240 |   52610 |   69919 |   373061 |               3119 |            17774 |
 |                             33 |        2 |        0 |       0 |       2 |        0 |                  0 |                0 |
 +--------------------------------+----------+----------+---------+---------+----------+--------------------+------------------+
3 rows in set (52.34 sec)

So, 124/818=15% back sessions (identifiable by their 16 char ids) have a save attempt, but no ready. For regular sessions, 17774/59240=30% of sessions have an attempt, but no ready. That's a potentially concerningly high proportion. These *might* be able to be explained by no-js users, but it seems like 30% is too high of a number.

We're also seeing a high percentage of sessions with a saveSuccess, but no saveAttempt 3119/52619=6% and a high proportion of regular sessions with no init 69969/674965=10%.

• ggellerman added a subscriber: • JAufrecht.May 6 2015, 11:38 PM

Just in case this wasn't clear, I think that we can consider this task resolved. I would like someone to talk to about the percentage of edit sessions that are lacking a "ready" event, but that will turn into a new task if it is an issue at all.

@Halfak, sounds good! I will close this task now.

nshahquinn-wmf closed this task as Resolved.May 14 2015, 1:03 AM

Jdforrester-WMF removed a project: Patch-For-Review.Jun 3 2015, 5:47 PM

GOIII moved this task from Backlog to Closed on the WikiEditor (2010) board.Apr 3 2016, 9:09 AM

editSessionID is duplicated in Edit:Schema for WikitextClosed, ResolvedPublic40 Estimated Story PointsActions

Description

Details

Related Objects

Event Timeline

editSessionID is duplicated in Edit:Schema for Wikitext
Closed, ResolvedPublic40 Estimated Story Points
Actions