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

oldnomad commented 2 years ago

⚠️ 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

ColonelSanderson commented 2 years ago

Having the same issue after upgrading to NC24

dhorstmann commented 2 years ago

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

Shnoulle commented 1 year ago

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

k-popov commented 1 year ago

Upgraded from 24.0.1 to 24.0.5 and noticed this issue too.

k-popov commented 1 year ago

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>

znerol commented 1 year ago

Filed #34256.

ChristophWurst commented 1 year ago

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

szaimen commented 1 year ago

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+

oldnomad commented 1 year ago

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.

Nerothos commented 1 year ago

25.0.3 doesn't fix it either.

ChristophWurst commented 1 year ago

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

kesselb commented 1 year ago

Fixed for everyone?

k-popov commented 1 year ago

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

nextcloud / server