server icon indicating copy to clipboard operation
server copied to clipboard

Published 20 hours ago • verified publisher icon nextcloud

[Bug]: Error reporting with 'errorlog' is broken in 24.0.3

Open oldnomad opened this issue 3 years ago • 11 comments

⚠️ This issue respects the following points: ⚠️

  • [X] This is a bug, not a question or a configuration/webserver/proxy issue.
  • [X] This issue is not already reported on Github (I've searched it).
  • [X] Nextcloud Server is up to date. See Maintenance and Release Schedule for supported versions.
  • [X] Nextcloud Server is running on 64bit capable CPU, PHP and OS.
  • [X] I agree to follow Nextcloud's Code of Conduct.

Bug description

Recently, after I've upgraded from 23.0.x to 24.0.3, errors from the cron jobs started coming as "Array to string conversion at /srv/www/html/lib/private/Log/Errorlog.php#46" instead. For example, I get following:

[owncloud][PHP][3] {"Exception":"Error","Message":"Array to string conversion at /srv/www/html/lib/private/Log/Errorlog.php#46","Code":0,"Trace":[{"file":"/srv/www/html/lib/private/Log/Errorlog.php","line":46,"function":"onError","class":"OC\\Log\\ErrorHandler","type":"::"},{"file":"/srv/www/html/lib/private/Log.php","line":375,"function":"write","class":"OC\\Log\\Errorlog","type":"->"},{"file":"/srv/www/html/lib/private/Log.php","line":215,"function":"writeLog","class":"OC\\Log","type":"->"},{"file":"/srv/www/html/lib/private/Log.php","line":158,"function":"log","class":"OC\\Log","type":"->"},{"file":"/srv/www/html/lib/private/Log/PsrLoggerAdapter.php","line":165,"function":"warning","class":"OC\\Log","type":"->"},{"file":"/srv/www/html/lib/private/AppFramework/ScopedPsrLogger.php","line":101,"function":"warning","class":"OC\\Log\\PsrLoggerAdapter","type":"->"},{"file":"/srv/www/html/apps/news/vendor/debril/feed-io/src/FeedIo/Reader.php","line":129,"function":"warning","class":"OC\\AppFramework\\ScopedPsrLogger","type":"->"},{"file":"/srv/www/html/apps/news/vendor/debril/feed-io/src/FeedIo/FeedIo.php","line":316,"function":"read","class":"FeedIo\\Reader","type":"->"},{"file":"/srv/www/html/apps/news/lib/Fetcher/FeedFetcher.php","line":124,"function":"read","class":"FeedIo\\FeedIo","type":"->"},{"file":"/srv/www/html/apps/news/lib/Service/FeedServiceV2.php","line":265,"function":"fetch","class":"OCA\\News\\Fetcher\\FeedFetcher","type":"->"},{"file":"/srv/www/html/apps/news/lib/Service/FeedServiceV2.php","line":342,"function":"fetch","class":"OCA\\News\\Service\\FeedServiceV2","type":"->"},{"file":"/srv/www/html/apps/news/lib/Service/UpdaterService.php","line":55,"function":"fetchAll","class":"OCA\\News\\Service\\FeedServiceV2","type":"->"},{"file":"/srv/www/html/apps/news/lib/Cron/UpdaterJob.php","line":71,"function":"update","class":"OCA\\News\\Service\\UpdaterService","type":"->","args":["*** sensitive parameters replaced ***"]},{"file":"/srv/www/html/lib/private/BackgroundJob/Job.php","line":54,"function":"run","class":"OCA\\News\\Cron\\UpdaterJob","type":"->"},{"file":"/srv/www/html/lib/private/BackgroundJob/TimedJob.php","line":60,"function":"execute","class":"OC\\BackgroundJob\\Job","type":"->"},{"file":"/srv/www/html/cron.php","line":151,"function":"execute","class":"OC\\BackgroundJob\\TimedJob","type":"->"}],"File":"/srv/www/html/lib/private/Log/ErrorHandler.php","Line":92,"CustomMessage":"--"}
[owncloud][news][2] Array

instead of expected:

[owncloud][news][2] https://www.omniglot.com/bloggle/?feed=rss2 read error : Server error: `GET https://www.omniglot.com/bloggle/?feed=rss2` resulted in a `520 status code 520` response:
<html><body>Origin Error</body></html><!-- [github.com/ezoic/sol/origcontent.(*OrigContent).loadContentInternal:654] cou (truncated...)

or something like that.

As far as I can see, the problem is that errorlog logger (OC\Log\Errorlog), unlike other loggers, is not ready for the message in write(...) method being an array. All other loggers extend LogDetails and do the proper thing, but not Errorlog. I think that some behavior changed in 08035833cf25c203fba4ba52dbd692df8fba09fb, but it's likely that the problem existed earlier too.

Steps to reproduce

1.Set log_type in the configuration to errorlog. 2.Perform an action that produces an error message. 3.Observe that "Array to string conversion" notice is reported, and that the error message is "Array" instead of the expected text.

Expected behavior

Expected error message should be logged.

Installation method

Manual installation

Operating system

Debian/Ubuntu

PHP engine version

PHP 7.4

Web server

Apache (supported)

Database engine version

MySQL

Is this bug present after an update or on a fresh install?

Updated to a major version (ex. 22.2.3 to 23.0.1)

Are you using the Nextcloud Server Encryption module?

Encryption is Disabled

What user-backends are you using?

  • [ ] Default user-backend (database)
  • [ ] LDAP/ Active Directory
  • [ ] SSO - SAML
  • [X] Other

Configuration report

{
    "system": {
        "instanceid": "***REMOVED SENSITIVE VALUE***",
        "passwordsalt": "***REMOVED SENSITIVE VALUE***",
        "secret": "***REMOVED SENSITIVE VALUE***",
        "trusted_domains": [
            "cloud.kojaev.name"
        ],
        "datadirectory": "***REMOVED SENSITIVE VALUE***",
        "dbtype": "mysql",
        "version": "24.0.3.2",
        "overwrite.cli.url": "https:\/\/cloud.kojaev.name",
        "dbname": "***REMOVED SENSITIVE VALUE***",
        "dbhost": "***REMOVED SENSITIVE VALUE***",
        "dbport": "",
        "dbtableprefix": "oc_",
        "mysql.utf8mb4": true,
        "dbuser": "***REMOVED SENSITIVE VALUE***",
        "dbpassword": "***REMOVED SENSITIVE VALUE***",
        "installed": true,
        "default_phone_region": "RU",
        "log_type": "errorlog",
        "memcache.local": "\\OC\\Memcache\\APCu",
        "maintenance": false,
        "theme": "",
        "loglevel": 2,
        "ldapProviderFactory": "OCA\\User_LDAP\\LDAPProviderFactory",
        "app_install_overwrite": [
            "user_pwauth"
        ],
        "encryption.legacy_format_support": false,
        "encryption.key_storage_migrated": false
    }
}

List of activated Apps

Enabled:
  - accessibility: 1.10.0
  - activity: 2.16.0
  - admin_audit: 1.14.0
  - announcementcenter: 6.3.1
  - audioplayer: 3.3.0
  - bookmarks: 10.5.1
  - bruteforcesettings: 2.4.0
  - calendar: 3.4.2
  - checksum: 1.1.4
  - circles: 24.0.0
  - cloud_federation_api: 1.7.0
  - cms_pico: 1.0.19
  - comments: 1.14.0
  - contacts: 4.2.0
  - contactsinteraction: 1.5.0
  - dashboard: 7.4.0
  - dav: 1.22.0
  - external: 4.0.0
  - extract: 1.3.5
  - federatedfilesharing: 1.14.0
  - federation: 1.14.0
  - files: 1.19.0
  - files_external: 1.16.1
  - files_markdown: 2.3.6
  - files_pdfviewer: 2.5.0
  - files_rightclick: 1.3.0
  - files_sharing: 1.16.2
  - files_trashbin: 1.14.0
  - files_versions: 1.17.0
  - files_videoplayer: 1.13.0
  - firstrunwizard: 2.13.0
  - gpoddersync: 3.4.0
  - groupfolders: 12.0.1
  - keeweb: 0.6.9
  - logreader: 2.9.0
  - lookup_server_connector: 1.12.0
  - mail: 1.13.6
  - maps: 0.2.0
  - metadata: 0.16.0
  - news: 18.1.0
  - nextcloud_announcements: 1.13.0
  - notes: 4.4.0
  - notifications: 2.12.0
  - oauth2: 1.12.0
  - password_policy: 1.14.0
  - photos: 1.6.0
  - privacy: 1.8.0
  - provisioning_api: 1.14.0
  - recommendations: 1.3.0
  - richdocuments: 6.1.1
  - richdocumentscode: 22.5.401
  - serverinfo: 1.14.0
  - settings: 1.6.0
  - sharebymail: 1.14.0
  - socialsharing_diaspora: 2.5.0
  - socialsharing_email: 2.5.0
  - socialsharing_facebook: 2.5.0
  - socialsharing_telegram: 2.5.0
  - socialsharing_twitter: 2.5.0
  - support: 1.7.0
  - survey_client: 1.12.0
  - systemtags: 1.14.0
  - tasks: 0.14.4
  - text: 3.5.1
  - theming: 1.15.0
  - twofactor_backupcodes: 1.13.0
  - twofactor_email: 2.5.0
  - twofactor_gateway: 0.20.0
  - twofactor_nextcloud_notification: 3.4.0
  - twofactor_totp: 6.4.0
  - twofactor_webauthn: 0.3.1
  - updatenotification: 1.14.0
  - user_ldap: 1.14.1
  - user_pwauth: 2.7.2
  - user_status: 1.4.0
  - viewer: 1.8.0
  - weather_status: 1.4.0
  - workflowengine: 2.6.0
Disabled:
  - backup: 1.0.6
  - encryption: 2.8.1
  - integration_google: 1.0.6
  - ocdownloader: 1.8.0
  - ocsms: 2.2.0
  - social
  - twofactor_admin: 3.2.0
  - user_external: 3.0.0

Nextcloud Signing status

No errors have been found.

Nextcloud Logs

No response

Additional info

No response

oldnomad avatar Jul 22 '22 00:07 oldnomad

Having the same issue after upgrading to NC24

ColonelSanderson avatar Aug 02 '22 13:08 ColonelSanderson

Same here: NC 24.0.3. running on K8s Cluster (official nextcloud-fpm docker image), php 8 Furthermore the apps files and deck arent accessible anymore after setting loglevel in combination with logtype=errorlog

dhorstmann avatar Aug 12 '22 10:08 dhorstmann

Updating from 23.0.x to 24.0.4 via console

have this error and some array on console.

me@belar:~$ php -d apc.enable=1 -d apc.enable_cli=1 /basedirectory/www/updater/updater.phar 
Nextcloud Updater - version: v20.0.0beta4-11-g68fa0d4

Current version is 23.0.8.

Update to Nextcloud 24.0.4 available. (channel: "stable")
Following file will be downloaded automatically: https://download.nextcloud.com/server/releases/nextcloud-24.0.4.zip
Open changelog ↗

Steps that will be executed:
[ ] Check for expected files
[ ] Check for write permissions
[ ] Create backup
[ ] Downloading
[ ] Verify integrity
[ ] Extracting
[ ] Enable maintenance mode
[ ] Replace entry points
[ ] Delete old files
[ ] Move new files in place
[ ] Done

Start update? [y/N] y

Info: Pressing Ctrl-C will finish the currently running step and then stops the updater.

[✔] Check for expected files
[✔] Check for write permissions
[✔] Create backup
[✔] Downloading
[✔] Verify integrity
[✔] Extracting
[✔] Enable maintenance mode
[✔] Replace entry points
[✔] Delete old files
[✔] Move new files in place
[✔] Done

Update of code successful.

Should the "occ upgrade" command be executed? [Y/n] y
Nextcloud or one of the apps require upgrade - only a limited number of commands are available
You may use your browser or the occ upgrade command to do the upgrade
Setting log level to debug
[owncloud][PHP][3] {"Exception":"Error","Message":"Array to string conversion at /basedirectory/www/lib/private/Log/Errorlog.php#46","Code":0,"Trace":[{"file":"/basedirectory/www/lib/private/Log/Errorlog.php","line":46,"function":"onError","class":"OC\\Log\\ErrorHandler","type":"::"},{"file":"/basedirectory/www/lib/private/Log.php","line":375,"function":"write","class":"OC\\Log\\Errorlog","type":"->"},{"file":"/basedirectory/www/lib/private/Log.php","line":215,"function":"writeLog","class":"OC\\Log","type":"->"},{"file":"/basedirectory/www/lib/private/Log.php","line":193,"function":"log","class":"OC\\Log","type":"->"},{"file":"/basedirectory/www/lib/private/Log/PsrLoggerAdapter.php","line":233,"function":"debug","class":"OC\\Log","type":"->"},{"file":"/basedirectory/www/lib/private/Updater.php","line":129,"function":"debug","class":"OC\\Log\\PsrLoggerAdapter","type":"->"},{"file":"/basedirectory/www/core/Command/Upgrade.php","line":235,"function":"upgrade","class":"OC\\Updater","type":"->"},{"file":"/basedirectory/www/3rdparty/symfony/console/Command/Command.php","line":255,"function":"execute","class":"OC\\Core\\Command\\Upgrade","type":"->"},{"file":"/basedirectory/www/3rdparty/symfony/console/Application.php","line":1009,"function":"run","class":"Symfony\\Component\\Console\\Command\\Command","type":"->"},{"file":"/basedirectory/www/3rdparty/symfony/console/Application.php","line":273,"function":"doRunCommand","class":"Symfony\\Component\\Console\\Application","type":"->"},{"file":"/basedirectory/www/3rdparty/symfony/console/Application.php","line":149,"function":"doRun","class":"Symfony\\Component\\Console\\Application","type":"->"},{"file":"/basedirectory/www/lib/private/Console/Application.php","line":211,"function":"run","class":"Symfony\\Component\\Console\\Application","type":"->"},{"file":"/basedirectory/www/console.php","line":100,"function":"run","class":"OC\\Console\\Application","type":"->"},{"file":"/basedirectory/www/occ","line":11,"args":["/basedirectory/www/console.php"],"function":"require_once"}],"File":"/basedirectory/www/lib/private/Log/ErrorHandler.php","Line":92,"CustomMessage":"--"}
[owncloud][core][0] Array

[…]

[owncloud][PHP][3] {"Exception":"Error","Message":"Array to string conversion at /basedirectory/www/lib/private/Log/Errorlog.php#46","Code":0,"Trace":[{"file":"/basedirectory/www/lib/private/Log/Errorlog.php","line":46,"function":"onError","class":"OC\\Log\\ErrorHandler","type":"::"},{"file":"/basedirectory/www/lib/private/Log.php","line":375,"function":"write","class":"OC\\Log\\Errorlog","type":"->"},{"file":"/basedirectory/www/lib/private/Log.php","line":215,"function":"writeLog","class":"OC\\Log","type":"->"},{"file":"/basedirectory/www/lib/private/Log.php","line":182,"function":"log","class":"OC\\Log","type":"->"},{"file":"/basedirectory/www/lib/private/Log/PsrLoggerAdapter.php","line":211,"function":"info","class":"OC\\Log","type":"->"},{"file":"/basedirectory/www/lib/private/Updater.php","line":572,"function":"info","class":"OC\\Log\\PsrLoggerAdapter","type":"->"},{"function":"OC\\{closure}","class":"OC\\Updater","type":"->","args":["*** sensitive parameters replaced ***"]},{"file":"/basedirectory/www/lib/private/Hooks/EmitterTrait.php","line":106,"function":"call_user_func_array"},{"file":"/basedirectory/www/lib/private/Updater.php","line":157,"function":"emit","class":"OC\\Hooks\\BasicEmitter","type":"->"},{"file":"/basedirectory/www/core/Command/Upgrade.php","line":235,"function":"upgrade","class":"OC\\Updater","type":"->"},{"file":"/basedirectory/www/3rdparty/symfony/console/Command/Command.php","line":255,"function":"execute","class":"OC\\Core\\Command\\Upgrade","type":"->"},{"file":"/basedirectory/www/3rdparty/symfony/console/Application.php","line":1009,"function":"run","class":"Symfony\\Component\\Console\\Command\\Command","type":"->"},{"file":"/basedirectory/www/3rdparty/symfony/console/Application.php","line":273,"function":"doRunCommand","class":"Symfony\\Component\\Console\\Application","type":"->"},{"file":"/basedirectory/www/3rdparty/symfony/console/Application.php","line":149,"function":"doRun","class":"Symfony\\Component\\Console\\Application","type":"->"},{"file":"/basedirectory/www/lib/private/Console/Application.php","line":211,"function":"run","class":"Symfony\\Component\\Console\\Application","type":"->"},{"file":"/basedirectory/www/console.php","line":100,"function":"run","class":"OC\\Console\\Application","type":"->"},{"file":"/basedirectory/www/occ","line":11,"args":["/basedirectory/www/console.php"],"function":"require_once"}],"File":"/basedirectory/www/lib/private/Log/ErrorHandler.php","Line":92,"CustomMessage":"--"}
[owncloud][updater][1] Array

After update log to file : access seems OK

Shnoulle avatar Aug 31 '22 15:08 Shnoulle

Upgraded from 24.0.1 to 24.0.5 and noticed this issue too.

k-popov avatar Sep 09 '22 16:09 k-popov

I don't know how to implement a proper patch for this issue but here is a workaround to at least get logs text: Update https://github.com/nextcloud/server/blob/bc142f41ad643905ae48b8ea909ccb28752a4f00/lib/private/Log/Errorlog.php#L46 with:

error_log('[' . $this->tag . ']['.$app.']['.$level.'] '. implode(',', $message));

With this workaround the line in log looks like NOTICE: PHP message: [owncloud][<app_name>][0] <app_name>,<message>

k-popov avatar Sep 12 '22 11:09 k-popov

Filed #34256.

znerol avatar Sep 26 '22 12:09 znerol

I believe I just fixed the same bug: https://github.com/nextcloud/server/pull/35614

ChristophWurst avatar Dec 05 '22 18:12 ChristophWurst

Hi, please update to 24.0.9 or better 25.0.3 and report back if it fixes the issue. Thank you!

My goal is to add a label like e.g. 25-feedback to this ticket of an up-to-date major Nextcloud version where the bug could be reproduced. However this is not going to work without your help. So thanks for all your effort!

If you don't manage to reproduce the issue in time and the issue gets closed but you can reproduce the issue afterwards, feel free to create a new bug report with up-to-date information by following this link: https://github.com/nextcloud/server/issues/new?assignees=&labels=bug%2C0.+Needs+triage&template=BUG_REPORT.yml&title=%5BBug%5D%3A+

szaimen avatar Jan 23 '23 14:01 szaimen

Version 24.0.9 doesn't fix this. Backport pull request to stable24 (https://github.com/nextcloud/server/pull/35824) is still open, Psalm failure (seems to be erroneous to me). Backport to stable25 (https://github.com/nextcloud/server/pull/35821) is also open.

oldnomad avatar Jan 23 '23 16:01 oldnomad

25.0.3 doesn't fix it either.

Nerothos avatar Jan 25 '23 17:01 Nerothos

That is not too surprising. https://github.com/nextcloud/server/pull/35821 will come with 25.0.4 at the earliest.

ChristophWurst avatar Jan 25 '23 18:01 ChristophWurst

Fixed for everyone?

kesselb avatar Aug 14 '23 14:08 kesselb

Fixed in 25.0.8 or earlier. At least I could remove the above workaround when upgraded to 25.0.8.

k-popov avatar Aug 16 '23 13:08 k-popov