X Tutup
Skip to content

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

Merged
phil-davis merged 3 commits intomasterfrom
log-with-CommandLogger
Jun 20, 2023
Merged

Fix handling of logger calls in lib/private/Log.php#40844
phil-davis merged 3 commits intomasterfrom
log-with-CommandLogger

Conversation

@phil-davis
Copy link
Contributor

@phil-davis phil-davis commented Jun 20, 2023 •
edited
Loading

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 phil-davis self-assigned this Jun 20, 2023
@phil-davis phil-davis force-pushed the log-with-CommandLogger branch from dea6860 to 40ae632 Compare June 20, 2023 08:10
@owncloud owncloud deleted a comment from update-docs bot Jun 20, 2023
@phil-davis phil-davis marked this pull request as ready for review June 20, 2023 08:10
@phil-davis
Copy link
Contributor Author

phil-davis commented Jun 20, 2023

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
Copy link
Member

jvillafanez commented Jun 20, 2023

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
Copy link
Contributor

ownclouders commented Jun 20, 2023 •
edited
Loading

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

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

@phil-davis
Copy link
Contributor Author

phil-davis commented Jun 20, 2023

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?

@phil-davis phil-davis force-pushed the log-with-CommandLogger branch from eb05455 to dc9ac6f Compare June 20, 2023 09:59
@jvillafanez
Copy link
Member

jvillafanez commented Jun 20, 2023

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 phil-davis force-pushed the log-with-CommandLogger branch from dc9ac6f to 5965fd9 Compare June 20, 2023 10:36
@phil-davis
Copy link
Contributor Author

phil-davis commented Jun 20, 2023 •
edited
Loading

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.

@sonarqubecloud
Copy link

sonarqubecloud bot commented Jun 20, 2023

Kudos, SonarCloud Quality Gate passed!    Quality Gate passed

Bug A 0 Bugs
Vulnerability A 0 Vulnerabilities
Security Hotspot A 0 Security Hotspots
Code Smell C 1 Code Smell

25.0% 25.0% Coverage
0.0% 0.0% Duplication

@phil-davis phil-davis merged commit d493fc0 into master Jun 20, 2023
@delete-merged-branch delete-merged-branch bot deleted the log-with-CommandLogger branch June 20, 2023 12:08
@jnweiger
Copy link
Contributor

jnweiger commented Aug 17, 2023

Confirmed fixed in 10.13.0-rc.1

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

@jvillafanez jvillafanez jvillafanez approved these changes

@DeepDiver1975 DeepDiver1975 Awaiting requested review from DeepDiver1975

Assignees

@phil-davis phil-davis

Labels

None yet

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

4 participants

@phil-davis @jvillafanez @ownclouders @jnweiger
X Tutup