Page MenuHomePhabricator

Unexpected output from Pygments encountered
Closed, ResolvedPublic

Description

It seems syntaxhighlighting is completely failing at translatewiki.net

[4488cdacc1d9c363622ef67e] /wiki/LocalTime MWException from line 169 of /www/dev.translatewiki.net/docroot/w/extensions/SyntaxHighlight_GeSHi/SyntaxHighlight_GeSHi.class.php: Unexpected output from Pygments encountered

Backtrace:

#0 /www/dev.translatewiki.net/docroot/w/includes/parser/Parser.php(3853): SyntaxHighlight_GeSHi::parserHook(string, array, Parser, PPFrame_Hash)
#1 /www/dev.translatewiki.net/docroot/w/includes/parser/Preprocessor_Hash.php(1089): Parser->extensionSubstitution(array, PPFrame_Hash)
#2 /www/dev.translatewiki.net/docroot/w/includes/parser/Parser.php(2917): PPFrame_Hash->expand(PPNode_Hash_Tree, integer)
#3 /www/dev.translatewiki.net/docroot/w/includes/parser/Parser.php(1265): Parser->replaceVariables(string)
#4 /www/dev.translatewiki.net/docroot/w/includes/parser/Parser.php(441): Parser->internalParse(string)
#5 /www/dev.translatewiki.net/docroot/w/includes/content/WikitextContent.php(330): Parser->parse(string, Title, ParserOptions, boolean, boolean, integer)
#6 /www/dev.translatewiki.net/docroot/w/includes/content/AbstractContent.php(497): WikitextContent->fillParserOutput(Title, integer, ParserOptions, boolean, ParserOutput)
#7 /www/dev.translatewiki.net/docroot/w/includes/poolcounter/PoolWorkArticleView.php(140): AbstractContent->getParserOutput(Title, integer, ParserOptions)
#8 /www/dev.translatewiki.net/docroot/w/includes/poolcounter/PoolCounterWork.php(123): PoolWorkArticleView->doWork()
#9 /www/dev.translatewiki.net/docroot/w/includes/page/Article.php(651): PoolCounterWork->execute()
#10 /www/dev.translatewiki.net/docroot/w/includes/actions/ViewAction.php(71): Article->view()
#11 /www/dev.translatewiki.net/docroot/w/includes/MediaWiki.php(495): ViewAction->show()
#12 /www/dev.translatewiki.net/docroot/w/includes/MediaWiki.php(289): MediaWiki->performAction(Article, Title)
#13 /www/dev.translatewiki.net/docroot/w/includes/MediaWiki.php(851): MediaWiki->performRequest()
#14 /www/dev.translatewiki.net/docroot/w/includes/MediaWiki.php(512): MediaWiki->main()
#15 /www/dev.translatewiki.net/docroot/w/index.php(43): MediaWiki->run()
#16 {main}

Based on current debugging, what I am seeing is that the value from self::highlight returns some random (but consistent) 8192 bytes from somewhere middle.

Using HHVM 3.15.3.


See also:

Related Objects

View Standalone Graph
This task is connected to more than 200 other tasks. Only direct parents and subtasks are shown here. Use View Standalone Graph to show more of the graph.
StatusAssignedTask
OpenNone
ResolvedKrinkle

Event Timeline

Restricted Application added a subscriber: Aklapper. · View Herald TranscriptNov 24 2016, 7:40 AM

After I removed loading from cache, the result is now 4096 bytes long.

After downgrading symfony version, it seemed to work once, but then went back to 4096.

- Removing symfony/process (v3.1.7)
- Installing symfony/process (v3.0.8)

There are no test failures for symfony/process master version.

If I do:

			$callbackOutput = '';
			$process->run( function( $type, $bar ) use ( &$callbackOutput ) {
				$callbackOutput .= $bar;
			} );

			if ( !$process->isSuccessful() ) {
				$status->warning( 'syntaxhighlight-error-pygments-invocation-failure' );
				wfWarn( 'Failed to invoke Pygments: ' . $process->getErrorOutput() );
				$status->value = self::highlight( $code, null, $args )->getValue();
				return $status;
			}

			$output = $process->getOutput();
			var_dump( 'XKA', $output );
			var_dump( 'XKB', $callbackOutput );

$callbackOutput contains full output, while $output does not. This seems to be a bug either in HHVM or symfony/process.

I cannot reproduce from command line with this script:

<?php

require_once __DIR__ . '/vendor/autoload.php';

use Symfony\Component\Process\Process;

$process = new Process( "'/www/dev.translatewiki.net/docroot/w/extensions/SyntaxHighlight_GeSHi/pygments/pygmentize' '-l' 'yaml' '-f' 'html' '-O' 'cssclass=mw-highlight,encoding=utf-8'" );
$process->setInput( <<<INPUT
interval-past:
  SECONDS:
   - "if # is 1:          second ago"
   - "if INDEX(#) is 0: # second ago"
   - "if INDEX(#) is 1: # seconds ago"
  MINUTES:
   - "if # is 1:          minute ago"
   - "if INDEX(#) is 0: # minute ago"
   - "if INDEX(#) is 1: # minutes ago"
  HOURS:
   - "if # is 1:          hour ago"
   - "if INDEX(#) is 0: # hour ago"
   - "if INDEX(#) is 1: # hours ago"
  DAYS:
   - "if # is 1:          yesterday"
   - "if INDEX(#) is 0: # day ago"
   - "if INDEX(#) is 1: # days ago"
  WEEKS:
   - "if # is 1:          week ago"
   - "if INDEX(#) is 0: # week ago"
   - "if INDEX(#) is 1: # weeks ago"
  MONTHS:
   - "if # is 1:          month ago"
   - "if INDEX(#) is 0: # month ago"
   - "if INDEX(#) is 1: # months ago"
  YEARS:
   - "if # is 1:          year ago"
   - "if INDEX(#) is 0: # year ago"
   - "if INDEX(#) is 1: # years ago"
  DECADES:
   - "if # is 1:          decade ago"
   - "if INDEX(#) is 0: # decade ago"
   - "if INDEX(#) is 1: # decades ago"
  CENTURIES:
   - "if # is 1:          century ago"
   - "if INDEX(#) is 0: # century ago"
   - "if INDEX(#) is 1: # centuries ago"
  MILLENNIA:
   - "if # is 1:          millenium ago"
   - "if INDEX(#) is 0: # millenium ago"
   - "if INDEX(#) is 1: # millennia ago"

interval-future:
  DAYS:
   - "if # is 1: tomorrow"
   - "if INDEX(#) is 0: after # day"
   - "if INDEX(#) is 1: after # days"

duration:
  DAYS:
   - "if INDEX(#) is 0: # day"
   - "if INDEX(#) is 1: # days"
INPUT
);

$process->run();
var_dump( $process->getOutput() );

In fact, copying some code from Special:ExpandTemplates (where it fails) to a command line script, it does not fail.

The code in symfony-process is:

/**
 * Returns the current output of the process (STDOUT).
 *
 * @return string The process output
 *
 * @throws LogicException in case the output has been disabled
 * @throws LogicException In case the process is not started
 */
public function getOutput()
{
    $this->readPipesForOutput(__FUNCTION__);

    if (false === $ret = stream_get_contents($this->stdout, -1, 0)) {
        return '';
    }

    return $ret;
}

The issue happens in stream_get_contents($this->stdout, -1, 0) in server mode.

For reference, my HHVM configuration:

cat /etc/hhvm/php.ini /etc/hhvm/server.ini
; This file is managed by puppet

; php options
date.timezone = 'UTC'
include_path = '.:/usr/share/php'

hhvm.jit = 0 ; Overwritten in server configs
hhvm.perf_pid_map = false
hhvm.log.always_log_unhandled_exceptions = true
hhvm.enable_obj_destruct_call = true
hhvm.enable_zend_compat = true

hhvm.mysql.typed_results = false
hhvm.mysql.slow_query_threshold = 30000
hhvm.mysql.connect_timeout = 3000
hhvm.mysql.read_timeout = 300000




; php options

pid = /run/hhvm/hhvm.pid

display_errors = 0
memory_limit = 200M
max_execution_time = 10s
hhvm.log.file = /www/translatewiki.net/logs/error_php
error_log = /www/translatewiki.net/logs/error_php

; hhvm specific
hhvm.server.ip = 127.0.0.1
hhvm.server.file_socket = /run/hhvm/hhvm.sock
hhvm.server.type = fastcgi
hhvm.server.gzip_compression_level = 0
hhvm.server.graceful_shutdown_wait = 5
hhvm.server.stat_cache = 1
hhvm.admin_server.port = 9001

hhvm.repo.central.path = /run/hhvm/hhvm.hhbc

hhvm.jit = 1

After downgrading the error went away:
dpkg: warning: downgrading hhvm from 3.15.3~trusty to 3.12.7+dfsg-1+wmf1~trusty1

@greg It seems this could affect WMF sites as well if you are going to upgrade HHVM.

greg added a subscriber: Joe.Dec 5 2016, 6:57 PM

@greg It seems this could affect WMF sites as well if you are going to upgrade HHVM.

cc @Joe ^^

Umm, now the error has started to appear also in 3.12.7+dfsg-1+wmf1~trusty1 (I had to downgrade because 3.17.0 has a crashing bug). So the cause must be something else.

If I do:

			$callbackOutput = '';
			$process->run( function( $type, $bar ) use ( &$callbackOutput ) {
				$callbackOutput .= $bar;
			} );

$callbackOutput contains full output, while $output does not. This seems to be a bug either in HHVM or symfony/process.

Does $callbackOutput approach work reliably?
Maybe we should use it as a temporary workaround?

I would think that approach is reliable, but then again the issue is intermittent in the first place so I cannot be completely sure.

I applied this workaround on my wikis.
Will check if the issue reappears or not in the next few days.

Change 332992 had a related patch set uploaded (by Edward Chernenko):
Workaround for intermittent problems in Symfony/Process under HHVM.

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

edwardspec added a comment.EditedJan 19 2017, 1:22 PM

Tested for 5 days, no problems encountered so far.
Submitted a patch.

Change 332992 merged by jenkins-bot:
Workaround for intermittent problems in Symfony/Process under HHVM.

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

TheDJ added a subscriber: TheDJ.Jan 23 2017, 12:05 PM

Do we consider this fixed, with the report upstream and the workaround in place ?

Will it be backported to REL1_28?

Change 334246 had a related patch set uploaded (by Nemo bis):
Workaround for intermittent problems in Symfony/Process under HHVM.

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

Change 334247 had a related patch set uploaded (by Nemo bis):
Workaround for intermittent problems in Symfony/Process under HHVM.

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

Will it be backported to REL1_28?

It should be, and also LTS. Is the problem present in 1.23?

edwardspec added a comment.EditedJan 26 2017, 9:32 AM

Is the problem present in 1.23?

No, SyntaxHightlight for 1.23 doesn't use Symfony/Process.

Have we filed an upstream bug with symfony?

Change 334247 merged by jenkins-bot:
Workaround for intermittent problems in Symfony/Process under HHVM.

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

Change 334246 merged by jenkins-bot:
Workaround for intermittent problems in Symfony/Process under HHVM.

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

Nemo_bis triaged this task as High priority.Jan 29 2017, 11:10 AM
Nemo_bis updated the task description. (Show Details)

Have we filed an upstream bug with symfony?

I think not.

Have we filed an upstream bug with symfony?

Where would that https://gerrit.wikimedia.org/r/#/c/332992/ be proposed? Somewhere on http://trac.symfony-project.org/ ?
https://www.mediawiki.org/wiki/Upstream_projects lists only lists Pygments...

It is not clear whether the issue is in symfony or in HHVM. I have been assuming the latter.

Krinkle closed this task as Resolved.Apr 28 2017, 8:57 PM
Krinkle claimed this task.
Krinkle added a subscriber: Krinkle.

Upstream bug was reported with HHVM.
https://github.com/facebook/hhvm/issues/6921

Workaround applied in master and backported to 1.27 and 1.28.
https://gerrit.wikimedia.org/r/#/q/I21ef340eccca0741d7e86840f444272623675c46

Krinkle moved this task from Backlog to Accepted on the SyntaxHighlight board.Apr 28 2017, 9:02 PM