str_repeat(): Second argument has to be greater than or equal to 0

[ghost]

Steps to reproduce

1. Have a working 10.0.7
2. Follow manual upgrade guide to delete all files and folders expect /data and /config
3. Extract new 10.0.8 tar.bz2
4. Run ./occ upgrade
5. Have a look at owncloud.log

Expected behaviour

No message about str_repeate() should be shown in the owncloud.log

Actual behaviour

Many messages about str_repeate() are shown in the owncloud.log (26 times). The same messages where showing up in previous versions as well so this is nothing 10.0.8 specific.

Server configuration

Operating system: Debian 9

Web server: Nginx

Database: MariaDB

PHP version: 7.0.27

ownCloud version: 10.0.8

Updated from an older ownCloud or fresh install: Updated from 10.0.7

Where did you install ownCloud from: Manual install via tar.bz2 file

Signing status (ownCloud 9.0 and above): No issues found

The content of config/config.php:

<?php
$CONFIG = array (
  'instanceid' => '***',
  'passwordsalt' => '***',
  'datadirectory' => '/var/www/owncloud/data',
  'dbtype' => 'mysql',
  'version' => '10.0.8.5',
  'dbname' => '***',
  'dbhost' => '***',
  'dbtableprefix' => 'oc_',
  'dbuser' => '***',
  'dbpassword' => '***',
  'installed' => true,
  'logtimezone' => 'Europe/Berlin',
  'maintenance' => false,
  'mail_smtpmode' => 'php',
  'mail_domain' => '***',
  'overwriteprotocol' => 'https',
  'overwritewebroot' => '',
  'appcodechecker' => false,
  'trusted_domains' =>
  array (
    0 => '***',
  ),
  'secret' => '***',
  'enabledPreviewProviders' =>
  array (
    0 => 'OC\\Preview\\PNG',
    1 => 'OC\\Preview\\JPEG',
    2 => 'OC\\Preview\\GIF',
    3 => 'OC\\Preview\\BMP',
    4 => 'OC\\Preview\\XBitmap',
    5 => 'OC\\Preview\\MarkDown',
    6 => 'OC\\Preview\\MP3',
    7 => 'OC\\Preview\\TXT',
    8 => 'OC\\Preview\\Illustrator',
    9 => 'OC\\Preview\\Movie',
    10 => 'OC\\Preview\\MSOffice2003',
    11 => 'OC\\Preview\\MSOffice2007',
    10 => 'OC\\Preview\\MSOffice2003',
    11 => 'OC\\Preview\\MSOffice2007',
    12 => 'OC\\Preview\\MSOfficeDoc',
    13 => 'OC\\Preview\\OpenDocument',
    14 => 'OC\\Preview\\PDF',
    15 => 'OC\\Preview\\Photoshop',
    16 => 'OC\\Preview\\Postscript',
    17 => 'OC\\Preview\\StarOffice',
    18 => 'OC\\Preview\\SVG',
    19 => 'OC\\Preview\\TIFF',
    20 => 'OC\\Preview\\Font',
  ),
  'loglevel' => 2,
  'memcache.local' => '\\OC\\Memcache\\APCu',
  'filelocking.enabled' => true,
  'memcache.locking' => '\\OC\\Memcache\\Redis',
  'redis' =>
  array (
    'host' => '/var/run/redis/redis.sock',
    'port' => 0,
  ),
  'overwrite.cli.url' => '***',
  'htaccess.RewriteBase' => '/',
  'apps_paths' =>
  array (
    0 =>
    array (
      'path' => '/var/www/owncloud/apps',
      'url' => '/apps',
      'writable' => false,
    ),
    1 =>
    array (
      'path' => '/var/www/owncloud/apps2',
      'url' => '/apps2',
      'writable' => true,
    ),
  ),
);

List of activated apps:

Enabled:
  - activity: 2.3.6
  - audioplayer: 2.2.4
  - bookmarks: 0.10.2
  - calendar: 1.5.7
  - comments: 0.3.0
  - contacts: 1.5.4
  - dav: 0.3.2
  - federatedfilesharing: 0.3.1
  - federation: 0.1.0
  - files: 1.5.1
  - files_external: 0.7.1
  - files_pdfviewer: 0.8.2
  - files_reader: 1.2.3
  - files_sharing: 0.10.1
  - files_texteditor: 2.2.1
  - files_trashbin: 0.9.1
  - files_versions: 1.3.0
  - files_videoplayer: 0.9.8
  - firstrunwizard: 1.1
  - gallery: 16.0.2
  - market: 0.2.4
  - notifications: 0.3.3
  - piwik: 0.3.2
  - polls: 0.8.1
  - richdocuments: 2.0.5
  - systemtags: 0.3.0
  - tasks: 0.9.6
  - updatenotification: 0.2.1
Disabled:
  - configreport
  - encryption
  - external
  - provisioning_api
  - theme-example
  - user_external

Are you using external storage, if yes which one: No

Are you using encryption: No

Are you using an external user-backend, if yes which one: No

Logs

ownCloud log (data/owncloud.log)

Repeated 26 times:

{"reqId":"aNeLPpFNyZx0h4bxUkp7","level":3,"time":"2018-04-28T16:43:41+02:00","remoteAddr":"","user":"--","app":"PHP","method":"--","url":"--","message":"str_repeat(): Second argument has to be greater than or equal to 0 at \/var\/www\/owncloud\/lib\/composer\/symfony\/console\/Helper\/ProgressBar.php#512"}

[ghost]

I googled around and the only hint i have found about this message together with symfony was in sebastianbergmann/phpunit#1976 but that was more related to test runs not happening here during the update.

The fix there was done with: sebastianbergmann/environment@22aa49b

ownCloud related issues:

Seems there are a few closed issues discussing other problems but which contains the same message as well so this seems to be there since quite some time: #30120, #26297, #28763

Similar on central:

https://central.owncloud.org/t/custom-theme-deleted-after-uprade-10-0-6-10-0-7/12113/9

https://central.owncloud.org/t/update-10-0-3-3-to-10-0-6-stuck/11734

https://central.owncloud.org/t/http-error-500-after-upgrade-to-owncloud-9-1/2259/3

[sharidas]

Based on investigation its been found that the error related to str_repeat() gets triggered from -> https://github.com/symfony/symfony/blob/57a1dd1c57170f610c8396001c24f18c03f45f81/src/Symfony/Component/Console/Helper/ProgressBar.php#L428

[PVince81]

@sharidas reproducible ?

[sharidas]

It is reproducible.

[phil-davis]

I just noticed this also, ended up at Sebastian's PHP unit thread, which led me back here to ownCloud!
I think that somehow in core/command/Upgrade.php we are calling $progress->setProgress() in a way that the symfony progress bar code thinks leaves a negative amount of empty progress "space" bars.
The message in the log is:

{"reqId":"xsq72cPPZrwrkcAJTu9k","level":0,"time":"2018-07-05T11:31:52+00:00","remoteAddr":"","user":"--","app":"core","method":"--","url":"--","message":"starting upgrade from 10.0.8.5 to 10.0.9.3"}
{"reqId":"xsq72cPPZrwrkcAJTu9k","level":3,"time":"2018-07-05T11:31:52+00:00","remoteAddr":"","user":"--","app":"PHP","method":"--","url":"--","message":"str_repeat(): Second argument has to be greater than or equal to 0 at \/home\/phil\/git\/owncloud\/core\/lib\/composer\/symfony\/console\/Helper\/ProgressBar.php#512"}
{"reqId":"xsq72cPPZrwrkcAJTu9k","level":3,"time":"2018-07-05T11:31:52+00:00","remoteAddr":"","user":"--","app":"PHP","method":"--","url":"--","message":"str_repeat(): Second argument has to be greater than or equal to 0 at \/home\/phil\/git\/owncloud\/core\/lib\/composer\/symfony\/console\/Helper\/ProgressBar.php#512"}
...

[PVince81]

can we get a full stack ? maybe hack the symfony helper code, add an if statement there and throw an exception so we see the stack

[phil-davis]

It is in lib/private/Repair/DropOldTables.php not in the general repair step code.
The log entry is generated nearly 28 times (26 I think!), for almost all of the calls to:

$output->advance(1, "Drop old database table: $tableName");

comment that line out, and the log messages go away, and of course the progress bar starts at 0% and suddenly jumps to 100% after all the dropTable() checks.

[PVince81]

Great, thanks. That should be enough to debug.

[PVince81]

I'm able to reproduce this on stable10 by simply increasing the fourth digit in version.php then running occ upgrade.

After debugging a bit I still don't understand what is going on. The DropOldTables job initializes the progress bar with the correct max value then advances only as many times as the max value.

It could be a problem related to indentation of the messages. Maybe the progress bar code from Symfony isn't compatible with outputting timestamps ?

2018-08-27T12:54:27+00:00 Drop old database tables
2018-08-27T12:54:27+00:00 
                                                    2018-08-27T12:54:27+00:00  Done
 29/29 [============================] 100%2018-08-27T12:54:27+00:00

[PVince81]

The simplest fix would be to remove the progress bar for this job.

It seems that other jobs do not have a progress bar, or maybe they just don't have anything to repair so the bug isn't always visible.

[phil-davis]

Deleted code is debugged code :)