Fix handling of logger calls in lib/private/Log.php

[phil-davis]

Description

Try to run a background job with verbose output.
Before this PR:

phil@phil-Inspiron-5468:~/git/owncloud/core$ git checkout master
Switched to branch 'master'
Your branch is up to date with 'origin/master'.
phil@phil-Inspiron-5468:~/git/owncloud/core$ php occ background:queue:execute --force -vvv 23
This command is for maintenance and support purposes. 
This will run the specified background job now. Regular scheduled runs of the job will
continue to happen at their scheduled times. 
If you still want to use this command please confirm the usage by entering: yes
yes
Found job: OCA\Files_Antivirus\Cron\Task with ID 23
Forcing run, resetting last run value to 0
Running job...
Finished in 0 seconds
phil@phil-Inspiron-5468:~/git/owncloud/core$ cat data/owncloud.log 
{"reqId":"HH4bi7VV9j1x0S8cKJkM","level":3,"time":"2023-06-20T07:56:37+00:00","remoteAddr":"","user":"--","app":"PHP","method":"--","url":"--","message":"call_user_func() expects parameter 1 to be a valid callback, class 'OC\\Log\\CommandLogger' does not have a method 'write' at \/home\/phil\/git\/owncloud\/core\/lib\/private\/Log.php#400"}
{"reqId":"HH4bi7VV9j1x0S8cKJkM","level":3,"time":"2023-06-20T07:56:37+00:00","remoteAddr":"","user":"--","app":"PHP","method":"--","url":"--","message":"call_user_func() expects parameter 1 to be a valid callback, class 'OC\\Log\\CommandLogger' does not have a method 'write' at \/home\/phil\/git\/owncloud\/core\/lib\/private\/Log.php#400"}
{"reqId":"HH4bi7VV9j1x0S8cKJkM","level":3,"time":"2023-06-20T07:56:37+00:00","remoteAddr":"","user":"--","app":"PHP","method":"--","url":"--","message":"call_user_func() expects parameter 1 to be a valid callback, class 'OC\\Log\\CommandLogger' does not have a method 'write' at \/home\/phil\/git\/owncloud\/core\/lib\/private\/Log.php#400"}

Errors are logged to owncloud.log and the verbose output is not displayed.

After this PR:

phil@phil-Inspiron-5468:~/git/owncloud/core$ git checkout log-with-CommandLogger
Switched to branch 'log-with-CommandLogger'
Your branch is up to date with 'origin/log-with-CommandLogger'.
phil@phil-Inspiron-5468:~/git/owncloud/core$ rm data/owncloud.log 
phil@phil-Inspiron-5468:~/git/owncloud/core$ php occ background:queue:execute --force -vvv 23
This command is for maintenance and support purposes. 
This will run the specified background job now. Regular scheduled runs of the job will
continue to happen at their scheduled times. 
If you still want to use this command please confirm the usage by entering: yes
yes
Found job: OCA\Files_Antivirus\Cron\Task with ID 23
Forcing run, resetting last run value to 0
Running job...
Running job with id 23 and class OCA\Files_Antivirus\Cron\Task. Last run 0 and interval 900
Started background job of class : OCA\Files_Antivirus\Cron\Task with arguments : 
Finished background job, the job took : 0 seconds, this job is an instance of class : OCA\Files_Antivirus\Cron\Task with arguments : 
Finished in 0 seconds
phil@phil-Inspiron-5468:~/git/owncloud/core$ cat data/owncloud.log 

The verbose output is displayed and no errors are written to owncloud.log

Some things pass a real OCP\ILogger class to the "old" lib/private/Log.php

OCP\ILogger does not have methods writeExtra or write, so it fails when trying to call write

This PR adds more logic so that it calls the log method if that exists.
This should be backward-compatible with whatever currently calls lib/private/Log.php and has writeExtra and write methods.

Related Issue

I noticed this because I was looking at owncloud/files_antivirus#378

How Has This Been Tested?

See fixed command output above.

Added an acceptance test for the background:queue:execute command (there was not one yet)

Types of changes

• Bug fix (non-breaking change which fixes an issue)
• New feature (non-breaking change which adds functionality)
• Database schema changes (next release will require increase of minor version instead of patch)
• Breaking change (fix or feature that would cause existing functionality to change)
• Technical debt
• Tests only (no source changes)

Checklist:

• Code changes
• Unit tests added
• Acceptance tests added
• Documentation ticket raised:
• Changelog item, see TEMPLATE

[phil-davis]

I don't see any unit tests for lib/private/Log.php
I am very happy to add a unit test case(s), so please point me to the unit tests if they do exist.

[jvillafanez]

Should we write a crash log if we can't write in the log file? Although it's a weird case that shouldn't happen, if it happens I don't think we'll notice.

[ownclouders]

💥 Acceptance tests pipeline cliBackground-maria10.2-php7.4 failed. The build has been cancelled.

https://drone.owncloud.com/owncloud/core/38632/109

[phil-davis]

Should we write a crash log if we can't write in the log file? Although it's a weird case that shouldn't happen, if it happens I don't think we'll notice.

if the logger object has no writeExtra, write or log method, then what can we do? We can't write to "the log" because we don't know how - the supposed "logger object" does not have any way that we are aware of to write to the log.

Do I just add and else that throws an exception, and "something" might handle it?

[jvillafanez]

We can try to throw an exception and see how it behaves. If the exception is unhandled, it should end up in the crash log (https://github.com/search?q=repo%3Aowncloud%2Fcore%20crashlog&type=code).
I'm not sure if it's a good idea, but hiding an error because we can't write in the log seems worse.

[phil-davis]

I added an else to:

throw new \Exception("No logger method available. Trying to log message '$formattedMessage'.");

If I adjust the code locally so that that happens, then I get this output:

$ php occ background:queue:execute --force --accept-warning -vvv 1
Found job: OCA\Files\BackgroundJob\ScanFiles with ID 1
Forcing run, resetting last run value to 0
Running job...

In Log.php line 403:
                                                                                                                                                       
  [Exception]                                                                                                                                          
  No logger method available. Trying to log message 'Running job with id 1 and class OCA\Files\BackgroundJob\ScanFiles. Last run 0 and interval 600'.  
                                                                                                                                                       

Exception trace:
  at /home/phil/git/owncloud/core/lib/private/Log.php:403
 OC\Log->log() at /home/phil/git/owncloud/core/lib/private/Log.php:259
 OC\Log->debug() at /home/phil/git/owncloud/core/lib/private/BackgroundJob/TimedJob.php:60
 OC\BackgroundJob\TimedJob->execute() at /home/phil/git/owncloud/core/core/Command/Background/Queue/Execute.php:107
 OC\Core\Command\Background\Queue\Execute->execute() at /home/phil/git/owncloud/core/lib/composer/symfony/console/Command/Command.php:298
 Symfony\Component\Console\Command\Command->run() at /home/phil/git/owncloud/core/lib/composer/symfony/console/Application.php:1040
 Symfony\Component\Console\Application->doRunCommand() at /home/phil/git/owncloud/core/lib/composer/symfony/console/Application.php:301
 Symfony\Component\Console\Application->doRun() at /home/phil/git/owncloud/core/lib/composer/symfony/console/Application.php:171
 Symfony\Component\Console\Application->run() at /home/phil/git/owncloud/core/lib/private/Console/Application.php:165
 OC\Console\Application->run() at /home/phil/git/owncloud/core/console.php:116
 require_once() at /home/phil/git/owncloud/core/occ:11

background:queue:execute [-f|--force] [--accept-warning] [--] <Job ID>

That works for occ commands - the exception details are displayed.
In other contexts, the output is going to go "somewhere". If it is a completely background job that has output directed to /dev/null then this will go in the bit-bucket. But if a job has some output file for stdout/stderr then this should appear there.

[sonarcloud]

Kudos, SonarCloud Quality Gate passed!   

0 Bugs
0 Vulnerabilities
0 Security Hotspots
1 Code Smell

25.0% Coverage
0.0% Duplication

[jnweiger]

Confirmed fixed in 10.13.0-rc.1