Page MenuHomePhabricator
Create Task
Maniphest T214193

PHP Notice: Unable to unserialize in AbuseFilter.php
Closed, ResolvedPublicPRODUCTION ERROR
Actions

Description

Error

Request ID: AWhh9wR0zpjgITg63PIw
Request URL: here (contains cyrillic letters, pretty long to write here)

message
PHP Notice: Unable to unserialize: [Here is a serialized AbuseFilterVariableHolder object]. Unexpected end of buffer during unserialization.
trace
#0 /srv/mediawiki/php-1.33.0-wmf.13/extensions/AbuseFilter/includes/AbuseFilter.php(1525): MWExceptionHandler::handleError(integer, string, string, integer, array, array)
#1 /srv/mediawiki/php-1.33.0-wmf.13/extensions/AbuseFilter/includes/Views/AbuseFilterViewExamine.php(172): AbuseFilter::loadVarDump(string)
#2 /srv/mediawiki/php-1.33.0-wmf.13/extensions/AbuseFilter/includes/Views/AbuseFilterViewExamine.php(27): AbuseFilterViewExamine->showExaminerForLogEntry(string)
#3 /srv/mediawiki/php-1.33.0-wmf.13/extensions/AbuseFilter/includes/special/SpecialAbuseFilter.php(122): AbuseFilterViewExamine->show()
#4 /srv/mediawiki/php-1.33.0-wmf.13/includes/specialpage/SpecialPage.php(569): SpecialAbuseFilter->execute(string)
#5 /srv/mediawiki/php-1.33.0-wmf.13/includes/specialpage/SpecialPageFactory.php(558): SpecialPage->run(string)
#6 /srv/mediawiki/php-1.33.0-wmf.13/includes/MediaWiki.php(288): MediaWiki\Special\SpecialPageFactory->executePath(Title, RequestContext)
#7 /srv/mediawiki/php-1.33.0-wmf.13/includes/MediaWiki.php(862): MediaWiki->performRequest()
#8 /srv/mediawiki/php-1.33.0-wmf.13/includes/MediaWiki.php(517): MediaWiki->main()
#9 /srv/mediawiki/php-1.33.0-wmf.13/index.php(42): MediaWiki->run()
#10 /srv/mediawiki/w/index.php(3): include(string)
#11 {main}

Impact

Presumably low, seen twice in the last 7 days.

Notes

Probably due to something bad happened in the past. Should be handled within T213006.

Details

Related Changes in Gerrit:
SubjectRepoBranchLines +/-
Add a maintenance script to clean afl_var_dumpmediawiki/extensions/AbuseFiltermaster+1 K -1
Customize query in gerrit

Related Objects
Search...

Event Timeline

Daimona created this task.Jan 18 2019, 6:17 PM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptJan 18 2019, 6:17 PM
Daimona added a project: User-Daimona.Jan 18 2019, 6:17 PM
Daimona moved this task from Backlog to Next on the User-Daimona board.
Daimona mentioned this in T213006: Create a script to update afl_var_dump, drop back-compat code.
Daimona updated the task description. (Show Details)Jan 18 2019, 6:23 PM
Daimona mentioned this in T214196: BadMethodCallException: Call to a member function dumpAllVars() on a non-object (boolean).Jan 18 2019, 6:41 PM
• Krinkle moved this task from Untriaged to Jan 2019 / 1.33.wmf13–14 on the Wikimedia-production-error board.Jan 22 2019, 3:05 AM
Daimona added a comment.Jan 22 2019, 1:42 PM

OK, so I think I understood this. First of, this is the link with the broken log entry. Using quarry for abuse_filter_log.afl_id === 101, you can get the whole row. Since it was inserted in 2009, the var dump is inside afl_var_dump instead of the text table/external storage. Reading it, you can see that the serialized string is truncated, and thus unserialization obviously fails. My guess is that this happened because the string was too long for an SQL blob [1], thus being truncated upon insertion. In fact, strlen returns 65361 of length, whereas BLOB is capped at 65535. I guess the delta has some explanation unrelated to this bug (maybe I didn't count bytes properly). The only thing I'm not sure of is the presence of the special character U+FFFD at the end of the serialized string. But again, I guess this is unrelated to the bug, and probably added e.g. by quarry or upon DB insertion.

As anticipated in the task description, this can and should be handled within the script for T213006. Since having a truncated serialized string is a pretty common problem, there are several PHP scripts around the web to recover partial data. I'll try to see if we can use any of them, or write one myself, and will add it to the script.

[1]: Curiously, the afl_var_dump was changed from BLOB to LONGBLOB in rEABFa7bc94cc80487f0b3063fa5ff19b6e6ff7917ddd, just a couple of days before this bug happened.

Daimona moved this task from Jan 2019 / 1.33.wmf13–14 to Older on the Wikimedia-production-error board.Jan 22 2019, 2:41 PM
gerritbot subscribed.Jan 22 2019, 6:22 PM

Change 482499 had a related patch set uploaded (by Daimona Eaytoy; owner: Daimona Eaytoy):
[mediawiki/extensions/AbuseFilter@master] [WIP] Add a maintenance script to clean afl_var_dump

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

gerritbot added a project: Patch-For-Review.Jan 22 2019, 6:22 PM
Daimona claimed this task.Jan 22 2019, 6:22 PM
• Alroilim closed this task as Declined.Feb 2 2019, 7:19 PM
• Alroilim removed Daimona as the assignee of this task.
• Alroilim triaged this task as Lowest priority.
• Alroilim set Due Date to Feb 1 2019, 9:00 PM.
• Alroilim removed projects: Patch-For-Review, User-Daimona, AbuseFilter, Wikimedia-production-error.
• Alroilim updated the task description. (Show Details)
• Alroilim removed subscribers: gerritbot, Daimona, Aklapper.
Restricted Application changed the subtype of this task from "Task" to "Deadline". · View Herald TranscriptFeb 2 2019, 7:19 PM
Gopavasanth reopened this task as Open.Feb 2 2019, 7:42 PM
Gopavasanth assigned this task to Daimona.
Huji added projects: Patch-For-Review, User-Daimona, AbuseFilter, Wikimedia-production-error.Feb 2 2019, 7:54 PM
Huji updated the task description. (Show Details)
Huji updated the task description. (Show Details)
Huji added subscribers: Aklapper, gerritbot.
Huji raised the priority of this task from Lowest to Needs Triage.Feb 2 2019, 7:56 PM
Huji removed Due Date which was set to Feb 1 2019, 9:00 PM.
Restricted Application changed the subtype of this task from "Deadline" to "Task". · View Herald TranscriptFeb 2 2019, 7:56 PM
Daimona moved this task from Next to Under review on the User-Daimona board.Feb 11 2019, 5:52 PM
gerritbot added a comment.Mar 24 2019, 12:49 PM

Change 482499 had a related patch set uploaded (by Daimona Eaytoy; owner: Daimona Eaytoy):
[mediawiki/extensions/AbuseFilter@master] [WIP] Add a maintenance script to clean afl_var_dump

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

• mmodell changed the subtype of this task from "Task" to "Production Error".Aug 28 2019, 11:07 PM
Daimona added a parent task: T213006: Create a script to update afl_var_dump, drop back-compat code.Sep 23 2019, 2:31 PM
• Krinkle removed a project: Patch-For-Review.Nov 8 2019, 5:55 AM
gerritbot added a comment.Mar 3 2020, 1:20 AM

Change 482499 merged by jenkins-bot:
[mediawiki/extensions/AbuseFilter@master] Add a maintenance script to clean afl_var_dump

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

• Krinkle subscribed.Apr 29 2020, 7:22 PM

I'm seeing various of these in Logstash. Looks like it might be the same error has this task but maybe the error message evolved a bit?

 PHP Notice: unserialize(): Error at offset 693 of 65535 bytes

#0 [internal function]: MWExceptionHandler::handleError(integer, string, string, integer, array)
#1 /srv/mediawiki/php-1.35.0-wmf.27/extensions/AbuseFilter/includes/AbuseFilter.php(745): unserialize(string)
#2 /srv/mediawiki/php-1.35.0-wmf.27/extensions/AbuseFilter/includes/Views/AbuseFilterViewExamine.php(198): AbuseFilter::loadVarDump(string)
#3 /srv/mediawiki/php-1.35.0-wmf.27/extensions/AbuseFilter/includes/Views/AbuseFilterViewExamine.php(46): AbuseFilterViewExamine->showExaminerForLogEntry(string)
#4 /srv/mediawiki/php-1.35.0-wmf.27/extensions/AbuseFilter/includes/special/SpecialAbuseFilter.php(139): AbuseFilterViewExamine->show()
#5 /srv/mediawiki/php-1.35.0-wmf.27/includes/specialpage/SpecialPage.php(575): SpecialAbuseFilter->execute(string)
#6 /srv/mediawiki/php-1.35.0-wmf.27/includes/specialpage/SpecialPageFactory.php(618): SpecialPage->run(string)
#7 /srv/mediawiki/php-1.35.0-wmf.27/includes/MediaWiki.php(299): MediaWiki\SpecialPage\SpecialPageFactory->executePath(Title, RequestContext)
#8 /srv/mediawiki/php-1.35.0-wmf.27/includes/MediaWiki.php(973): MediaWiki->performRequest()
#9 /srv/mediawiki/php-1.35.0-wmf.27/includes/MediaWiki.php(535): MediaWiki->main()
#10 /srv/mediawiki/php-1.35.0-wmf.27/index.php(47): MediaWiki->run()
#11 /srv/mediawiki/w/index.php(3): require(string)
#12 {main}
Daimona added a comment.Apr 30 2020, 5:32 PM
In T214193#6094959, @Krinkle wrote:

I'm seeing various of these in Logstash. Looks like it might be the same error has this task but maybe the error message evolved a bit?

Yes, apparently PHP7 has a different error format. The URL in the task description now gives:

PHP Notice: unserialize(): Error at offset 51349 of 65535 bytes

#0 [internal function]: MWExceptionHandler::handleError(integer, string, string, integer, array)
#1 /srv/mediawiki/php-1.35.0-wmf.30/extensions/AbuseFilter/includes/AbuseFilter.php(745): unserialize(string)
#2 /srv/mediawiki/php-1.35.0-wmf.30/extensions/AbuseFilter/includes/Views/AbuseFilterViewExamine.php(198): AbuseFilter::loadVarDump(string)
#3 /srv/mediawiki/php-1.35.0-wmf.30/extensions/AbuseFilter/includes/Views/AbuseFilterViewExamine.php(46): AbuseFilterViewExamine->showExaminerForLogEntry(string)
#4 /srv/mediawiki/php-1.35.0-wmf.30/extensions/AbuseFilter/includes/special/SpecialAbuseFilter.php(139): AbuseFilterViewExamine->show()
#5 /srv/mediawiki/php-1.35.0-wmf.30/includes/specialpage/SpecialPage.php(576): SpecialAbuseFilter->execute(string)
#6 /srv/mediawiki/php-1.35.0-wmf.30/includes/specialpage/SpecialPageFactory.php(618): SpecialPage->run(string)
#7 /srv/mediawiki/php-1.35.0-wmf.30/includes/MediaWiki.php(299): MediaWiki\SpecialPage\SpecialPageFactory->executePath(Title, RequestContext)
#8 /srv/mediawiki/php-1.35.0-wmf.30/includes/MediaWiki.php(973): MediaWiki->performRequest()
#9 /srv/mediawiki/php-1.35.0-wmf.30/includes/MediaWiki.php(535): MediaWiki->main()
#10 /srv/mediawiki/php-1.35.0-wmf.30/index.php(47): MediaWiki->run()
#11 /srv/mediawiki/w/index.php(3): require(string)
#12 {main}

which is (almost) the same as yours.

Daimona removed a parent task: T213006: Create a script to update afl_var_dump, drop back-compat code.Nov 18 2020, 10:21 PM
Daimona added a subtask: T246539: Dry-run, then actually run updateVarDumps.
Urbanecm closed subtask T246539: Dry-run, then actually run updateVarDumps as Resolved.Dec 8 2020, 5:12 PM
Daimona closed this task as Resolved.Dec 8 2020, 5:14 PM
Content licensed under Creative Commons Attribution-ShareAlike (CC BY-SA) 4.0 unless otherwise noted; code licensed under GNU General Public License (GPL) 2.0 or later and other open source licenses. By using this site, you agree to the Terms of Use, Privacy Policy, and Code of Conduct. · Wikimedia Foundation · Privacy Policy · Code of Conduct · Terms of Use · Disclaimer · CC-BY-SA · GPL · Credits