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:

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