Migrate Logging: Redux #1461
Migrate Logging: Redux #1461
Conversation
ryanrath
added
maintenance / code quality
ryanrath
force-pushed
the
migrate_logging_again
branch
from
959c94b
to
a3f5d7b
Compare
ryanrath
force-pushed
the
migrate_logging_again
branch
from
81e5f56
to
185adcb
Compare
|
Issugest that you implement a new MonoLog formatter class that outputs the log records in the identical way that they used to be. This would include the strtolower(level_name). A cursory glance at the monolog source code suggests that you could also handle the array to string encoding in the formatter class too. For an example of the strtolower see e.g. https://github.com/Seldaek/monolog/blob/9776fa1d548716490a7d49ffbb608e5c2dda589b/src/Monolog/Formatter/FluentdFormatter.php see also the JsonFormatter for example code about how you would handle the array to string conversion: https://github.com/Seldaek/monolog/blob/9776fa1d548716490a7d49ffbb608e5c2dda589b/src/Monolog/Formatter/JsonFormatter.php |
|
So the database output uses a json encoding: So you are going to have to come up with a way of making it use the json encoding with the DB handler and the CCRLine-style encoding with the Console handler. One option could be to always serialize to json in the CCR::Logger::extractMessage() function and then have the CCRLineFormatter do a speculative json_decode() and then run the |
ryanrath
force-pushed
the
migrate_logging_again
branch
from
ce28199
to
1bb08c9
Compare
ryanrath
force-pushed
the
migrate_logging_again
branch
from
1bb08c9
to
c2c8c4e
Compare
There was a problem hiding this comment.
The output format for the database logging is still incorrect:
The incorrect contents look like this:
[2020-12-03 18:25:46] xdmod-import-csv.NOTICE: {"message":"xdmod-import-csv start","process_start_time":"2020-12-03 18:25:46"} [] []
whereas you'll want it to only output the json bits
classes/CCR/CCRDBHandler.php
Outdated
| ':id' => $this->getNextId(), | ||
| ':ident' => $record['channel'], | ||
| ':priority' => $record['level'], | ||
| ':message' => $record['formatted'] |
There was a problem hiding this comment.
Do not output record['formatted'] as the message.
There was a problem hiding this comment.
you probably want record['message'] but I have not verified this in the actual code
There was a problem hiding this comment.
Great catch, thanks! Yeah, I believe this was left over from moving the formatting around to different places within the code. I tested locally by spinning up a local docker w/ an upgrade. Ran xdmod-ingestor to generate some log messages and confirmed that they were not displayed correctly in the interface. Updated the field to message and repeated the docker upgrade test and confirmed that the log messages were correctly displayed.
One thing I did note is that testing the upgrade path did not generate any log records, which in turn meant that when I clicked on the Log Data tab all that was displayed was a blank Tab Panel, as opposed to displaying the log interface, just without data, or an informational message indicating that things were working, just that there was no data to display.
There was a problem hiding this comment.
Also, I've updated CCRDBHandlerTest so that it:
- Is constructing it's logger the same way that the rest of the code does.
- Actually inspects the format of the generated log records to make sure that we don't run into this again.
classes/CCR/Log.php
Outdated
| 'type' => $e['type'], | ||
| )); | ||
| $logger->crit( | ||
| sprintf( |
There was a problem hiding this comment.
Is this sprintf correct here? Don't you want to send an array in so that it can be json_encoded properly?
There was a problem hiding this comment.
I can change it back, this was added pre being able to handle arrays as messages.
This error cropped up in our Shippable builds: `PHP Fatal error: Class 'Monolog\Logger' not found in /root/src/github.com/ubccr/xdmod/classes/CCR/Log.php on line 150`. This occured because Monolog didn't make it into the `composer.lock` file in the previous commits.
|
The output is still changed from the old code: new: |
|
@jpwhite4 re: #1461 (comment) Do we want to exclude the information about what script / logger is generating the log message? It's not a hard change, but it strikes me that this might be useful information to have. @jpwhite4 Ok, just to double check, did #1461 (comment) address your previous concern about the output from unhandled exceptions? |
|
The file and console log format output is incorrect. Also the datestamp is also wrong: new code: the two problems are (1) the new code puts the string 'datawarehouse.query' into the output. and (2) the hours, minutss and seconds in the timestamp are wrong. |
This pull request should not change the log output format. If you want to change the log output format then do it in a different pull request. If you do want to change the log output format then you will have to do a risk analysis to check whether you will break some other processes / components. One example of breakage is anything that currently parses the log output |
|
Your problem is in: const TIME_FORMAT = 'Y-m-d h:m:s';lowercase h is hours in 12 hour format and lower case m is months. |
Per code review by @jpwhite, the date/time format was using `m` for both months and minutes which obviously was not correct and the `%channel%` portion of the line format was removed so that our current log output matches our previous log output.
|
@jpwhite4 Thanks for this catch: #1461 (comment) The latest commit: 21871c6 contains the changes to resolve those format discrepancies. |
|
The output from the test.php is still different: current build: |
configuration/linker.php
Outdated
| // Set the exception's headers (if any). | ||
| foreach ($exceptionOutput['headers'] as $headerKey => $headerValue) { | ||
| header("$headerKey: $headerValue"); | ||
| if ($exceptionOutput['isServerContext']) { |
There was a problem hiding this comment.
Please explain why this code changed.
There was a problem hiding this comment.
I implemented this change to address this comment: #1461 (comment)
Specifically it was so that this line was not displayed:
2020-12-22 09:12:23 file [error] {"message":"Message: This message should be written to \/usr\/share\/xdmod\/logs\/exception.log"}
{"success":false,"count":0,"total":0,"totalCount":0,"results":[],"data":[],"message":"This message should be written to \/usr\/share\/xdmod\/logs\/exception.log","code":0}
configuration/linker.php
Outdated
| $logConf = array( | ||
| 'mode' => 0644, | ||
| 'file' => $logfile, | ||
| 'consoleLogLevel' => CCR\Log::INFO |
There was a problem hiding this comment.
The old code created a file logger here. But this change seems to create a file logger and a console logger and set the console logger to log at info. I don't think this is the correct thing to do since it will likely break the frontend.
There was a problem hiding this comment.
Also this code is sending emails too. Which the old code did not.
There was a problem hiding this comment.
Yup, per our earlier convo I updated the logger config here: 29de561
These changes were not necessary as it was really the `$logger` specified in `handle_uncaught_exception` that was in error. Specifically it was that the original instantiation was a direct call to `\Log::factory` and not `Log::factory`. The difference being that `\Log::factory` is the PEAR Log factory and not `\CCR\Log::factory`.
- This logger was incorrectly refactored to utilize `\CCR\Log::factory` as opposed to `\CCR\Log::singleton`. - This logger needed to be configured as a `file` logger only.
This logger was originally instantiated utilizing PEAR Log's factory method:
```php
$logger = \Log::factory('console', '', 'test', \CCR\Log::DEBUG);
```
This equates to a console logger w/ a log level of DEBUG and an ident of 'test'.
To ensure that we create a logger with the same functionality the way in which
it is configured needed to be changed. Instead of `\CCR\Log::factory` we use
`\CCR\Log::singleton` as that more closely mimics the way PEAR Log functions. We
also needed to explicitely add explicit entries for mail, db and file with false
values so that the resultant logger is only a console logger. The loggers ident
was also changed to `test`.
This was probably removed due to it never actually being instantiated. But since it's most likely used for debugging than it should have been left in place.
|
Please can you squash and merge when you merge since there are lots of commits. |
|
@jpwhite4 Absolutely, thanks! |
* Updating Pear \ CCR Log to Monolog These changes update: - \Log => Monolog\Logger|Psr\Log\LoggerInterface where appropriate - PEAR_LOG_* => CCR\Log::* ( which correspond to Monolog\Logger::* ) - CCR\Log has been updated to provide Monolog Loggers w/ different types of Handlers based on the requested configuration as it did before. And add: - CCRDBHandler: Monolog does not come with a way to write to a MySQL db natively, so this new class utilizes CCR's DB class to provide that functionality. - CCR\Logger: Pear Log supported passing an array as the message but unfortunately Monolog does not. This class has been added as a shim layer between Monolog & our code so that any array / class that is passed as a message will be json_encode and then passed to the underlying Monolog library to be handled as normal. This is accomplished by being the Monolog\Logger implementation returned by the CCR\Log::factory function. * Style checker fixes & reverting PHP7.2 return type declarations - Changes to appease the style check gods - Reverted code meant for PHP 7.2 to it's less typed 5.4 form. - Removed the xd*Log classes as they are no longer used. - Removed references to and `use` statements of the PEAR Log class. - Revervted changes in xdmod.spec.in to what's required in Centos7 - Reverted changes in the templates/apache.conf file to what's required for Centos7 - Quoted the expected output to account for json_encode in post_ingest_test.sh * Fixing Log Level Name Differences * I r gud at reading code * Update our LoggerInterface implementation to format messages This change updates our log messages to be the same as when we utilized PEAR Log. * Removing previously trace log statements * Removing debug code These changes were added during the debugging process. * Reverted this test back to the format expected pre-Monolog * Reverting log line format To ensure we keep follow-on problems from updating the Logging framework to a minimum these changes introduce a new class the `CCRLineFormater` which lower cases the level_name. The other changes are to support this change. * Just fixing some fat fingered changes * This was meant for the centos8 branch * Actually reverting the expected values for these tests. * strpos tests don't need characeters escaped * asdkfj * Updates per code review from @jpwhite4 We needed to make sure that logs handled by CCRDBHandler were inserted as json, while handled as text elsewhere in the logging infrastructure. These changes provided by @jpwhite4 provdide that functionality. * Appeasing the style gods * Resetting the pesky security.php * Additional Logging Changes These changes were missed previously and are being included now. * Documentation Logging related changes We no longer utilize \Log ( PEAR Log ) so this has been updated to represent that. * Adding a bare bones test for our CCRDBHandler * Removing what were once trace calls These log calls were previously `trace` calls, which we decided to remove previously. Seeing as how I missed them they are being removed now. * Minor Cleanup from reviewing Github changes - StateManager.php: Want to standardize on using CCR\Log as opposed to Monolog\Logger so that if we need to swap out Logging Frameworks in the future it will be easier. i.e. we're utilizing CCR\Log is a Facade - Other changes are just removing unused `use` statements. * Fixing the formatting of DB Log records The log viewing portion of our internal dashboard requires log records to be formatted in a very specific way. We needed to insert the raw message vs the message after it's been modified by the logging framework. This bug was caught by @jpwhite4 during code review. * Ensuring we test the contents of the log table We ran into a problem where the records inserted into `log_table` were not correctly formatted. This had the nock-on effect of making the log viewer tab in the internal dashboard display useless as it could not parse the malformed records. I've modified this test so that the logger is retrieved in the same way as loggers in the rest of the app and also added tests to ensure that the records generated by said logger are in the format we expect. * Appeasing the style gods * Fixing console line format These changes fix the formatting of log messages observed when logging to the console. The format had changed to resemble: - 2020-12-04 02:12:47 xdmod-import-csv [notice] 2020-12-04 02:12:47 xdmod-import-csv [notice] xdmod-import-csv start (process_start_time: 2020-12-04 02:30:47) as oppossed to: - 2020-12-04 02:12:47 xdmod-import-csv [notice] xdmod-import-csv start (process_start_time: 2020-12-04 02:30:47) * Migrating from Monolog Log Levels to the levels in rfc5424 Changes made per code review by @jpwhite4. These new levels bring the numeric identifier for each log level in line with https://tools.ietf.org/html/rfc5424 * Adding more context to convertLevel function name Updated this functions name to `convertToCCRLevel` so that it's more apparent what the function is meant to be doing. i.e. converting from `$monologLevel` => CCR's level. CCR's level being the log levels defined in \CCR\Log. * Adding a new log level conversion function We previously added a conversion function for going between monolog's log levels & ccr's levels so this function just provides for going the other way. These changes were needed after noticing a marked increase in logging in the Shippable build. After having a think about things it became obvious that we were providing PSR ( 0-7 ) Log levels to Monolog. As all of PSR's levels are less than Monolog's DEBUG level ( 100 ), we were always logging at the debug level. By adding this new conversion function & utilizing it in conjunction w/ the Log Handlers provided by CCR\Log we can ensure that the default log level is provided correctly to these handlers. The addition of the `if` statement to `CCR\Logger::log` is for the same reason as the changes in CCR\Log. It allows the providing of PSR log levels to function correctly. Specifically this was found while testing the logging in `linker.php` which directly calls `$logger->log( ... );` as opposed to say `$logger->error( ... );`. And while we tend to use the named log functions in XDMoD, there are a number of instances of using `log` in XDMoD's modules. * Comments explaining `if` statement in Logger::log Just adding a comment to explain why this `if` statement is present. Which is to enable code to do the following: ```php $logger = \CCR\Log::factory('id', $loggerConfig); $logger->log(\CCR\Log::INFO, "This is an informational message"); ``` Previously, Monolog would interpret all of the \CCR\Log log levels as `DEBUG` due to them all being less then (numerically) Monolog\Logger::DEBUG. \CCR\Log log levels range from 0-7 where as Monolog's log levels range from 100-600. * Simplifying and adding docs for log level conv functions - Refactored the log level conversion functions to utilize a newly added `$logLevels` array that maps \CCR\Log levels to their equivalent \Monolog\Logger log levels. This reduces duplicated code between the two conversion functions as well as makes it easier to manage supported log levels in the future. - Added documentation for the two log level conversion functions. * Reverting the expected value to what it was previously This value should have been changed back previously but the test didn't end up failing due to being a >= test. * Simplified CCRDBHandler::getNextId Went with a generic try-catch on the off chance that something untoward happens as opposed to checking return values. Also, since we aren't checking return values I removed the comment about not checking the return value for the DELETE statement since we're not checking the rest of them. * Pre-flipping log levels instead of flipping the log levels everytime the convertToCCRLevel function is called. Just pre-flipping them per @jpwrhite4 code review. * Changes per code review by @jpwhite4 These changes came about after investigating what effect the new Logging framework would have on globally uncaught exceptions. @jpwhite4 noticed that the log output generated by the new framework did not match what was previously generated. These differences were: - The message was originally output as json - This was resolved by changing the log calls from `$logger->log( <level>, <message>);` to `$logger->level(array(`message' => <message>));` - There was additional json formatted information output at the very end of the log output. - This was fixed by restructuring the `global_uncaught_exception_handler` function so that it only `echo $exceptionOutput['content']` when executed in a server context. - The last `info` log message has newlines embedded in it to ease reading. Monolog was replacing these with empty spaces. - This was fixed by implementing our own `replaceNewLines` function in our custom line formatter `CCRLineFormater` w/ code from Monolog's Line Formatter that ensures that linebreaks in the log message are preserved. * Reverting log configuration This configuration change was not necessary to get the new Logging framework working within XDMoD. * Resolving problem w/ Monolog in depdencies This error cropped up in our Shippable builds: `PHP Fatal error: Class 'Monolog\Logger' not found in /root/src/github.com/ubccr/xdmod/classes/CCR/Log.php on line 150`. This occured because Monolog didn't make it into the `composer.lock` file in the previous commits. * Appeasing the style gods * Fixing line / time format Per code review by @jpwhite, the date/time format was using `m` for both months and minutes which obviously was not correct and the `%channel%` portion of the line format was removed so that our current log output matches our previous log output. * Updating time format * Reverting changes to global_uncaught_exception_handler These changes were not necessary as it was really the `$logger` specified in `handle_uncaught_exception` that was in error. Specifically it was that the original instantiation was a direct call to `\Log::factory` and not `Log::factory`. The difference being that `\Log::factory` is the PEAR Log factory and not `\CCR\Log::factory`. * Updating logger instantiation / configurtation - This logger was incorrectly refactored to utilize `\CCR\Log::factory` as opposed to `\CCR\Log::singleton`. - This logger needed to be configured as a `file` logger only. * Reconfiguring logger for HostListParserTest This logger was originally instantiated utilizing PEAR Log's factory method: ```php $logger = \Log::factory('console', '', 'test', \CCR\Log::DEBUG); ``` This equates to a console logger w/ a log level of DEBUG and an ident of 'test'. To ensure that we create a logger with the same functionality the way in which it is configured needed to be changed. Instead of `\CCR\Log::factory` we use `\CCR\Log::singleton` as that more closely mimics the way PEAR Log functions. We also needed to explicitely add explicit entries for mail, db and file with false values so that the resultant logger is only a console logger. The loggers ident was also changed to `test`. * Re-adding self::$logger to BaseETLTest This was probably removed due to it never actually being instantiated. But since it's most likely used for debugging than it should have been left in place. Co-authored-by: Ryan Rathsam <[email protected]> Co-authored-by: Joe White <[email protected]>
XDMoD has had the pre-requisite PR ( ubccr/xdmod#1461 ) merged so these environment variables can be reverted.
* Pear Log -> Monolog migration Replacing PEAR Log w/ PSR\Log && Monolog * Logging Documentation Changes * Reverting environment variables XDMoD has had the pre-requisite PR ( ubccr/xdmod#1461 ) merged so these environment variables can be reverted. * Updating doctype for logger Since we're no longer using Pear Log this should have been changed in a previous commit. * Code Changes per @jpwhite4 * 100% more isset conditionals
Description
This PR swaps all Pear Log usage w/ Monolog.
CCR\Loggingclass that takes the place ofCCR\Logand utilizes Monolog.tracelevel for now, but this can be re-added if we create a fork of Monolog as we did w/ Log.\CCR\Loggerthat is utilized inCCR\Log::factoryand\CCR\Log::singleton. This class provides a shim layer between our code that provides arrays as log messages & Monolog that will json_encode these messages before passing them on to the default Monolog handlers.Motivation and Context
This PR came about from looking at what would be required to update XDMoD to support integrating Symfony Flex which requires PHP7. After speaking with Jeff about his students work towards the Centos8 / PHP7 goal he pointed me to https://docs.google.com/document/d/1fIr5ZzTrYdfO3aWP_sNouC-iojNfePqn3axMapJVsu4 which documents some of the currently known blockers for migrating XDMoD to Centos8 / PHP7. I started experimenting w/ a local docker image based on Jeff's students work and noticed that Pear Log required MDB2 which is not compatible w/ PHP7. After a brief conversation he had mentioned that we should probably replace our Logging prior to moving to PHP7, which got me thinking about how hard it would be to actually do. Turns out that it wasn't hard at all, just tedious. After this PR is merged I have a branch ready to go w/ the basics of centos8 support for XDMoD.
Tests performed
All automated tests for OpenXDMoD fresh install & upgrade
Checklist: