Hello! I'm trying to upload data to Wikibase via OpenRefine. I've done this several times before with no problems, using the same schema. I've fixed issues and verified in the preview that the edits are correct. I'm using a Wikidata bot account (but I did try logging out and back in, and even logging out and logging in with my regular, non-bot account...same issue).
When I try to "Upload edits to Wikibase," OpenRefine pops up the progress message "Perform Wikibase edits," which remains at 0% complete. Within the OpenRefine command window, these are the messages that I get:
05:05:35.912 [ refine] POST /command/wikidata/perform-wikibase-edits (75727ms)
05:05:35.929 [..mWikibaseEditsOperation] Performing edits (16ms)
05:05:35.929 [..ting.EditBatchProcessor] Requesting documents (0ms)
05:05:36.214 [..baseapi.WbEditingAction] [maxlag] Waiting for wdqs1014: 7.4166666666667 seconds lagged. -- pausing for 1000 milliseconds. (285ms)
05:05:37.365 [..baseapi.WbEditingAction] [maxlag] Waiting for wdqs1014: 7.4166666666667 seconds lagged. -- pausing for 1500 milliseconds. (1150ms)
05:05:39.006 [..baseapi.WbEditingAction] [maxlag] Waiting for wdqs1014: 7.4166666666667 seconds lagged. -- pausing for 2250 milliseconds. (1640ms)
05:05:41.387 [..baseapi.WbEditingAction] [maxlag] Waiting for wdqs1014: 7.4166666666667 seconds lagged. -- pausing for 3375 milliseconds. (2381ms)
05:05:44.900 [..baseapi.WbEditingAction] [maxlag] Waiting for wdqs1014: 7.4166666666667 seconds lagged. -- pausing for 5062 milliseconds. (3512ms)
05:05:50.108 [..baseapi.WbEditingAction] [maxlag] Waiting for wdqs1014: 7.4166666666667 seconds lagged. -- pausing for 7593 milliseconds. (5207ms)
05:05:57.843 [..baseapi.WbEditingAction] [maxlag] Waiting for wdqs1014: 7.4166666666667 seconds lagged. -- pausing for 11389 milliseconds. (7735ms)
Etc. If I leave it sitting for hours, it will continue trying to upload, ultimately unsuccessfully. It is not a huge dataset...45 persons are being created, all new, each with multiple properties.
Does anyone have any idea what's going wrong? My colleagues are not experiencing this issue, despite following the same set of steps that I do when editing data (in fact, I wrote those steps and the JSON script they are using).
That's an oddly specific, and unchanging, lag time. I suspect you're getting some other kind of error which is masquerading as a maxlag error.
It looks like the default retry count is 14, after which it may log a more informative message, hopefully with the entire stack trace. The message should be something like:
Gave up after several retries. Last error was:
Can you check to see if the logs contain anything like that and if it contains any more useful information?
It's possible that this is something to do with their increasingly strict API rate limits, but it's hard to tell from the available information.
Tom
Thanks so much for your response. I've tried again this morning, and I'll post the log below. Some more info: I'm running the latest release (3.10.0) on Windows 11, using Firefox as the default browser. This morning I tried a new VPN, in case it logged me as geographically elsewhere in the US and tapped me into a different Wikidata node.
This time, the results were slightly different. Similar maxlag messages for a while, then it jumped to 42% complete and I got several "We are editing too fast" messages. Then it stalled again, stuck at 42%, resuming maxlag messages. I seem to get 12 of these, then they stop. This time, it DID eventually finish, taking about a total of 11 minutes to add 45 records. This is better than the time I let it run for 4 hours for 22 records. If it's just slow...that I can handle, but sometimes it seems to make no progress at all. I have not changed any of the default settings available when uploading to Wikibase. Perhaps the backend host machines are simply terribly overloaded...which might be why it keeps bouncing around from server to server (wdqs1018, then wdqs1018, wdqs1011, wdqs1014, etc.)?
Of course, the next upload I tried spun for about 30 minutes without ever proceeding past the 12 maxlag statements...and I canceled it.
I have not changed any of the default values for uploading edits to Wikidata, meaning maxlag is still set at 5.
11:50:25.289 [..mWikibaseEditsOperation] Performing edits (66ms)
11:50:25.293 [..ting.EditBatchProcessor] Requesting documents (4ms)
11:50:25.704 [..baseapi.WbEditingAction] [maxlag] Waiting for wdqs1018: 54.416666666667 seconds lagged. -- pausing for 1000 milliseconds. (411ms)
11:50:26.889 [..baseapi.WbEditingAction] [maxlag] Waiting for wdqs1018: 54.416666666667 seconds lagged. -- pausing for 1500 milliseconds. (1184ms)
11:50:28.612 [..baseapi.WbEditingAction] [maxlag] Waiting for wdqs1018: 54.416666666667 seconds lagged. -- pausing for 2250 milliseconds. (1722ms)
11:50:31.034 [..baseapi.WbEditingAction] [maxlag] Waiting for wdqs1018: 54.416666666667 seconds lagged. -- pausing for 3375 milliseconds. (2422ms)
11:50:34.567 [..baseapi.WbEditingAction] [maxlag] Waiting for wdqs1018: 54.416666666667 seconds lagged. -- pausing for 5062 milliseconds. (3532ms)
11:50:39.789 [..baseapi.WbEditingAction] [maxlag] Waiting for wdqs1018: 54.416666666667 seconds lagged. -- pausing for 7593 milliseconds. (5222ms)
11:50:47.530 [..baseapi.WbEditingAction] [maxlag] Waiting for wdqs1018: 54.416666666667 seconds lagged. -- pausing for 11389 milliseconds. (7741ms)
11:50:59.066 [..baseapi.WbEditingAction] [maxlag] Waiting for wdqs1018: 54.416666666667 seconds lagged. -- pausing for 17083 milliseconds. (11535ms)
11:51:16.297 [..baseapi.WbEditingAction] [maxlag] Waiting for wdqs1011: 125.53333333333 seconds lagged. -- pausing for 25624 milliseconds. (17230ms)
11:51:42.081 [..baseapi.WbEditingAction] [maxlag] Waiting for wdqs1011: 125.53333333333 seconds lagged. -- pausing for 38436 milliseconds. (25783ms)
11:52:20.725 [..baseapi.WbEditingAction] [maxlag] Waiting for wdqs1018: 55.883333333333 seconds lagged. -- pausing for 57654 milliseconds. (38644ms)
11:53:18.513 [..baseapi.WbEditingAction] [maxlag] Waiting for wdqs1014: 85.3 seconds lagged. -- pausing for 86481 milliseconds. (57787ms)
11:54:48.543 [..baseapi.WbEditingAction] We are editing too fast. Pausing for 5852 milliseconds. (90030ms)
11:54:57.760 [..baseapi.WbEditingAction] We are editing too fast. Pausing for 5637 milliseconds. (9216ms)
11:55:03.564 [..baseapi.WbEditingAction] [maxlag] Waiting for wdqs1015: 130.41666666667 seconds lagged. -- pausing for 1000 milliseconds. (5804ms)
11:55:04.731 [..baseapi.WbEditingAction] [maxlag] Waiting for wdqs1015: 130.41666666667 seconds lagged. -- pausing for 1500 milliseconds. (1167ms)
11:55:06.362 [..baseapi.WbEditingAction] [maxlag] Waiting for wdqs1015: 130.41666666667 seconds lagged. -- pausing for 2250 milliseconds. (1630ms)
11:55:08.774 [..baseapi.WbEditingAction] [maxlag] Waiting for wdqs1015: 130.41666666667 seconds lagged. -- pausing for 3375 milliseconds. (2411ms)
11:55:12.274 [..baseapi.WbEditingAction] [maxlag] Waiting for wdqs1015: 130.41666666667 seconds lagged. -- pausing for 5062 milliseconds. (3500ms)
11:55:17.482 [..baseapi.WbEditingAction] [maxlag] Waiting for wdqs1015: 130.41666666667 seconds lagged. -- pausing for 7593 milliseconds. (5207ms)
11:55:25.240 [..baseapi.WbEditingAction] [maxlag] Waiting for wdqs1015: 130.41666666667 seconds lagged. -- pausing for 11389 milliseconds. (7758ms)
11:55:36.823 [..baseapi.WbEditingAction] [maxlag] Waiting for wdqs1015: 130.41666666667 seconds lagged. -- pausing for 17083 milliseconds. (11582ms)
11:55:54.033 [..baseapi.WbEditingAction] [maxlag] Waiting for wdqs1015: 130.41666666667 seconds lagged. -- pausing for 25624 milliseconds. (17209ms)
11:56:19.819 [..baseapi.WbEditingAction] [maxlag] Waiting for wdqs1015: 125.68333333333 seconds lagged. -- pausing for 38436 milliseconds. (25786ms)
11:56:58.417 [..baseapi.WbEditingAction] [maxlag] Waiting for wdqs1015: 125.68333333333 seconds lagged. -- pausing for 57654 milliseconds. (38597ms)
11:57:56.229 [..baseapi.WbEditingAction] [maxlag] Waiting for wdqs1015: 123.7 seconds lagged. -- pausing for 86481 milliseconds. (57811ms)
11:59:22.855 [..baseapi.WbEditingAction] [maxlag] Waiting for wdqs1018: 56.45 seconds lagged. -- pausing for 129721 milliseconds. (86626ms)
12:01:36.334 [..baseapi.WbEditingAction] We are editing too fast. Pausing for 5886 milliseconds. (133479ms)
12:01:45.685 [..baseapi.WbEditingAction] We are editing too fast. Pausing for 5537 milliseconds. (9350ms)
12:01:54.053 [..mWikibaseEditsOperation] Storing editing results in: Wikibase editing results (8368ms)
Thanks for the additional detail. Those errors are coming from the Wikidata Toolkit, so we'd have to dig into that to figure out what triggers them. The "editing too fast" messages make a lot more sense to me than the "125 seconds lagged."
It's good news that it made progress and completed, albeit slowly, but it seems like we could improve observability and do a better job of documenting what errors map to what underlying conditions.
You might want to check with the operators of the Wikibase that you were using to see if there were any operational issues around the time you ran into problems. Was the Wikidata or a different Wikibase?
Tom