wfShellExec errors end up in HHVM log
Closed, ResolvedPublicPRODUCTION ERROR
Actions

Assigned To

Authored By

	Tgr
	Feb 9 2017, 1:26 AM

Description

It seems some (all?) wfShellExec errors end up in the HHVM fatal log, which is quite useless as it contains neither a stack trace nor wiki/URL information. These errors should be reported by wfShellExec via Monolog.

One example is T157644: Shell error from "pdftotext" and "pdfinfo" commands (e.g. "Syntax Error: Invalid XRef entry"); IIRC this was discussed in the past in the context of T111441: SiteConfiguration::getConfig() does not work in Wikimedia production but I can't remember the details.

Related Objects
Search...

Status	Subtype	Assigned	Task
Declined	PRODUCTION ERROR	None	T157644 Shell error from "pdftotext" and "pdfinfo" commands (e.g. "Syntax Error: Invalid XRef entry")
Open		None	T157850 Interacting with Wikimedia logs should be a pleasant experience
Resolved	PRODUCTION ERROR	MaxSem	T157646 wfShellExec errors end up in HHVM log
Resolved	PRODUCTION ERROR	Seb35	T138036 proc line: 2959: warning: points must have either 4 or 2 values per line
Resolved	PRODUCTION ERROR	hashar	T158649 firejail for mediawiki converter leaks to stderr: "Reading profile /etc/firejail/mediawiki-converters.profile"
Resolved	PRODUCTION ERROR	Tgr	T145772 Error: Couldn't find trailer dictionary

Event Timeline

Tgr created this task.Feb 9 2017, 1:26 AM

Restricted Application added a subscriber: Aklapper. · View Herald TranscriptFeb 9 2017, 1:26 AM

Tgr added a parent task: T157644: Shell error from "pdftotext" and "pdfinfo" commands (e.g. "Syntax Error: Invalid XRef entry").Feb 9 2017, 1:27 AM

Tgr added a parent task: T157850: Interacting with Wikimedia logs should be a pleasant experience.Feb 11 2017, 1:39 AM

@hashar believes (and I have no reason to doubt) that this is the ultimate cause of all of the Syntax Error/Warning type messages in the logs, e.g.:

Syntax Warning: Could not parse ligature component \"127\" of \"_127\" in parseCharName
Syntax Error: Invalid XRef entry
Syntax Error (3714139): Bad 'Length' attribute in stream

There are considerable spikes of these errors frequently: https://logstash.wikimedia.org/goto/77b024392153d591645d6e0d48a7da61

I tend to look at all hhvm logstash messages while deploying so the spikes caused by this family of messages make it very difficult to see whether a deployment was successful or not. We actually hide a good deal of these errors in fatalmonitor (see https://logstash.wikimedia.org/app/kibana#/dashboard/Fatal-Monitor).

Individually blocking each message on the logstash dashboard is clearly a sisyphean task. If anyone can help to fix/mitigate the root cause it would be very much appreciated.

thcipriani mentioned this in T155527: MW-1.29.0-wmf.12 deployment blockers.Feb 15 2017, 4:56 PM

EasyTimeline is an example, it does something like: wfShellExec(timeline.pl), and anything sent to stderr ends up being replayed by hhvm and thus to fatal.log.

The fix would be to pass to wfShellExec [ 'duplicateStderr' => true ] then use structured logging so we get the full context in logstash.

I have some WIP toward that goal for EasyTimeline in https://gerrit.wikimedia.org/r/#/c/335238/ (poke T138036 )

hashar added a subtask: T138036: proc line: 2959: warning: points must have either 4 or 2 values per line.Feb 15 2017, 5:46 PM

The way wfShellExec handles this sucks. If we don't care about stderr, it should just be sent to devnull - there is no point in spamming the hhvm log with it as without any accompanying information it's almost certainly not going to be actionable. If we do care about it then we should not mix it into the normal output - we are using proc_open which supports multiple output streams.

The syntax is already a horrible mess so it would be best to get https://gerrit.wikimedia.org/r/#/c/319505/ merged first and build on that.

In T157646#3035414, @Tgr wrote:

If we don't care about stderr, it should just be sent to devnull - there is no point in spamming the hhvm log with it as without any accompanying information it's almost certainly not going to be actionable. If we do care about it then we should not mix it into the normal output - we are using proc_open which supports multiple output streams.

@MaxSem already has a patch for this (https://gerrit.wikimedia.org/r/#/c/325063/), cool!

hashar added a subtask: T158649: firejail for mediawiki converter leaks to stderr: "Reading profile /etc/firejail/mediawiki-converters.profile".Feb 21 2017, 2:52 PM

hashar mentioned this in T158649: firejail for mediawiki converter leaks to stderr: "Reading profile /etc/firejail/mediawiki-converters.profile".

hashar added a subtask: T145772: Error: Couldn't find trailer dictionary.Feb 23 2017, 4:05 PM

T138036 is a similar behavior coming from EasyTimeline. I have some low priority work in progress patch that would capture all output of wfShellExec AND adds structured logging so it shows up nicely in Logstash: https://gerrit.wikimedia.org/r/#/c/335238/

hashar closed subtask T158649: firejail for mediawiki converter leaks to stderr: "Reading profile /etc/firejail/mediawiki-converters.profile" as Resolved.Apr 25 2017, 2:05 PM

Tgr added a project: User-Tgr.May 2 2017, 12:14 PM

Tgr moved this task from Backlog to Pending on the User-Tgr board.May 2 2017, 1:21 PM

https://gerrit.wikimedia.org/r/#/c/325063/ is being deployed this week so error messages should be discarded from now, unless explicitly mixed into stdout with duplicateStderr. MediaWiki can still access the error output, although by default it doesn't (maybe we should change that). If all goes well, errors like these should disappear tomorrow.

And so they did. I think this and all the subtasks can be closed now.

Tgr mentioned this in T138036: proc line: 2959: warning: points must have either 4 or 2 values per line.Oct 26 2017, 7:03 PM

Tgr closed subtask T138036: proc line: 2959: warning: points must have either 4 or 2 values per line as Resolved.

Tgr closed subtask T145772: Error: Couldn't find trailer dictionary as Resolved.Oct 26 2017, 7:05 PM

Closing per above.
Note that https://gerrit.wikimedia.org/r/#/c/385946/ will re-add logging of stderr but it will use proper structured logging (instead of one log event per output line), a dedicated channel, include wiki/server/URL/caller method, and it can be manually suppressed where that makes sense.

Tgr mentioned this in T157644: Shell error from "pdftotext" and "pdfinfo" commands (e.g. "Syntax Error: Invalid XRef entry").Oct 26 2017, 7:10 PM

Tgr closed this task as Resolved.Oct 31 2017, 12:01 AM

Tgr claimed this task.

Tgr reassigned this task from Tgr to MaxSem.

Tgr moved this task from Pending to Done on the User-Tgr board.

thcipriani awarded a token.Oct 31 2017, 6:05 PM