Page MenuHomePhabricator

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

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.

Event Timeline

Halfak created this task.Apr 13 2015, 5:38 PM
Halfak updated the task description. (Show Details)
Halfak raised the priority of this task from to Needs Triage.
Halfak added a project: VisualEditor.
Halfak added a subscriber: Halfak.
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptApr 13 2015, 5:38 PM
Krenair edited projects, added WikiEditor; 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:

  1. Go to wikitext editor
  2. Make changes and click save
  3. Click the back button in your browser so that you are back in the wikitext editor
  4. 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 triaged this task as High priority.Apr 15 2015, 12:07 AM
Jdforrester-WMF assigned this task to Krenair.
Jdforrester-WMF added a subscriber: Catrope.

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

Steps to reproduce:

  1. Go to wikitext editor
  2. Make changes and click save
  3. Click the back button in your browser so that you are back in the wikitext editor
  4. 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.

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 added a subscriber: Elitre.Apr 15 2015, 10:27 AM
Krenair removed Krenair as the assignee of this task.Apr 15 2015, 8:36 PM
Krenair added a subscriber: Krenair.

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.

  1. 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
GOIII added a subscriber: GOIII.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

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

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

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

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

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

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

Jdforrester-WMF closed this task as Resolved.Apr 21 2015, 11:00 PM
Jdforrester-WMF added a subscriber: Jdforrester-WMF.

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 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?

Halfak reopened this task as Open.EditedApr 24 2015, 1:36 AM

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?

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.

@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.

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

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 what are you referring to re. sampling?

Is there anything else to do here?

I suppose that this still remains to be tested.

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

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

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
Halfak added a comment.May 6 2015, 5:15 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.

  1. Sometimes regular sessions do not have a "saveSuccess" or "saveAttempt" when they ought to. These sessions also lack an "abort".
  2. Back sessions never have an "init" or "ready" event.
  3. 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%.

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.

Neil_P._Quinn_WMF closed this task as Resolved.May 14 2015, 1:03 AM
GOIII moved this task from Backlog to Closed on the WikiEditor board.Apr 3 2016, 9:09 AM