In-Portal Issue Tracker - In-Portal CMS
Viewing Issue Advanced Details
ID: Category: Type: Reproducibility: Date Submitted: Last Update:
1003 [In-Portal CMS] Database feature request N/A 2011-02-14 13:20 2012-10-04 10:30
Reporter: alex Platform:  
Assigned To: alex OS:  
Priority: minor OS Version:  
Status: resolved Product Version: 5.1.2-B1  
Product Build: Resolution: fixed  
 
ETA: none Fixed in Version: 5.2.1-B1  
Reference: https://groups.google.com/d/topic/in-portal-dev/-YLc3RLkEtc/discussion
Change Log Message: Added powerful Event Logging engine
Estimate Points: 3
Summary: 0001003: Logging engine
Description: In-Portal has very powerful logging system when debug mode is on, but if developer won't look at errors reported there in time (e.g. before he closes the page with debugger), then most probably he won't get same error next time.

Also In-Portal has nice "Silent Log" feature, when all errors got written to file, but it is turned off by default and that log (since it's a text file) can't be easily analysed.

So this is good error reporting code, but it's results are not being recorded for future analysis and what's is recorded is not enough to properly pinpoint problematic place in code after error already happened and there is no more place to retrieve data from.


To solve above mentioned issues I'm proposing to create kLogger class (and associated SystemLog table), that would:
* handle sql error processing
* handle php error/notice/warning processing
* handle exception processing
* handle user-defined messages

What should be recorded along with each event being logged:
* $_SERVER['HTTP_HOST'] - address of page's webserver (useful in multi-user development environment)
* $_SERVER['REMOTE_ADDR'] - ip address of page visitor
* current user id (guest or not)
* SessionData/UserSession table - session data
* SessionID - session id (when available)
* $_GET, $_POST, $_COOKIE - user input on page, where event happened
* $_SERVER['REQUEST_URI'] - url that was used to access the page
* $this->Application->isAdmi - is user an admin or not
* complete trace to the php method, that raised that event
[TODO] * occurrences count: today/yesterday/last week/last month
[TODO] * last occurrence on - date/time when event was raised


Automatic system log cleanup:
* none
* automatic (weekly)
* automatic (monthly)

In Admin Console there will be a new section under "Summary & Logs" called "System Log" with list of all logged events, that happened.
Steps To Reproduce:
Additional Information: === Info moved from 0000268 ===
1. create kLogger class, that would:
- handle sql error processing
- handle php error processing
- handle exception processing
- ability to handle user defined events
- put data to silent log, when not in debug mode
- also record $_SERVER['HTTP_HOST'] to store host, where problem was found in multi-user development environment
- also record current user id (guest or not) and it's session data
- optionally use database to store all errors, that are happening
- report errors to in-portal website for analysis
Relationships
parent of 0001376resolved  (5.2.1)alex Single place for random code generation 
parent of 0001379active  (5.3.0) Submitting system logs to Intechnic servers 
parent of 0001395resolved  (5.2.1)alex Too aggressive line ending normalization in plain text e-mails 
parent of 0001440resolved  (5.2.1)alex Hide "System Log" section for "Simple" preset 
related to 0000268active  (5.2.1) Code Cleanup in 5.2.x branch 
related to 0001381resolved  (5.2.1)alex Adding more info to item validation error message 
related to 0001383resolved  (5.2.1)alex Incorrect setting page saving detection 
related to 0001393resolved  (5.2.1)alex Random "Requested ID for prefix <prefix> not passed" notices 
related to 0001394resolved  (5.2.1)alex Multiple notices discovered while developing System Log 
Not all the children of this issue are yet resolved or closed.
Attached Files: patch system_log_feature_core.patch (124,059) 2012-10-02 12:09
http://tracker.in-portal.org/file_download.php?file_id=1812&type=bug
patch fatal_error_with_disabled_syslog_fix.patch (479) 2012-10-04 10:29
http://tracker.in-portal.org/file_download.php?file_id=1813&type=bug
Issue History
Date Modified Username Field Change
2013-01-08 08:07 alex Relationship added parent of 0001440
2012-10-16 08:58 alex Changeset attached 5.3.x r15579
2012-10-16 08:55 alex Changeset attached 5.3.x r15578
2012-10-04 10:30 alex Changeset attached 5.2.x r15553
2012-10-04 10:30 alex Note Added: 0005202
2012-10-04 10:29 alex File Added: fatal_error_with_disabled_syslog_fix.patch
2012-10-02 12:13 alex Note Added: 0005201
2012-10-02 12:13 alex Status reviewed and tested => resolved
2012-10-02 12:13 alex Fixed in Version => 5.2.1-B1
2012-10-02 12:13 alex Resolution open => fixed
2012-10-02 12:13 alex Assigned To !COMMUNITY => alex
2012-10-02 12:13 alex Changeset attached 5.2.x r15552
2012-10-02 12:12 alex Note Added: 0005200
2012-10-02 12:12 alex Status needs testing => reviewed and tested
2012-10-02 12:11 alex Time Estimate Removed 8 =>
2012-10-02 12:11 alex Assigned To => !COMMUNITY
2012-10-02 12:11 alex Developer => alex
2012-10-02 12:11 alex Status active => needs testing
2012-10-02 12:09 alex File Added: system_log_feature_core.patch
2012-10-02 12:08 alex Note Added: 0005199
2012-10-02 11:07 alex Note Added: 0005198
2012-10-02 10:13 alex Description Updated bug_revision_view_page.php?rev_id=1050#r1050
2012-09-14 11:12 alex Relationship replaced parent of 0001395
2012-09-14 11:12 alex Relationship added related to 0001395
2012-09-14 10:40 alex Relationship added related to 0001394
2012-09-14 08:10 alex Relationship added related to 0001393
2012-08-20 12:20 alex Relationship added related to 0001383
2012-08-20 10:23 alex Relationship added related to 0001381
2012-08-20 08:40 alex Note Added: 0005145
2012-08-20 08:39 alex Relationship added parent of 0001379
2012-08-20 08:38 alex Summary Remote Logging and Reporting => Logging engine
2012-08-20 08:38 alex Description Updated bug_revision_view_page.php?rev_id=1036#r1036
2012-08-20 08:38 alex Additional Information Updated bug_revision_view_page.php?rev_id=1037#r1037
2012-08-20 08:30 alex Target Version Icebox => 5.2.1
2012-08-17 10:10 alex Relationship added parent of 0001376
2011-12-23 11:34 Dmitry Additional Information Updated bug_revision_view_page.php?rev_id=935#r935
2011-12-23 10:57 alex Relationship added related to 0000268
2011-12-18 15:25 Dmitry Target Version 5.2.0 => Icebox
2011-10-22 05:39 alex Estimate Points => 3
2011-09-26 04:50 alex Time Estimate Added 8
2011-09-23 20:59 Dmitry Priority normal => minor
2011-09-23 20:59 Dmitry Target Version Icebox => 5.2.0
2011-02-14 13:28 Dmitry Change Log Message Adds powerful event logging engine => Added powerful Event Logging engine
2011-02-14 13:28 Dmitry Description Updated bug_revision_view_page.php?rev_id=681#r681
2011-02-14 13:28 Dmitry Additional Information Updated bug_revision_view_page.php?rev_id=683#r683
2011-02-14 13:20 alex New Issue
2011-02-14 13:20 alex Reference => https://groups.google.com/d/topic/in-portal-dev/-YLc3RLkEtc/discussion
2011-02-14 13:20 alex Change Log Message => Adds powerful event logging engine

Notes
(0005145)
alex   
2012-08-20 08:40   
All remote logging functionality has been moved to 0001379 task.
(0005198)
alex   
2012-10-02 11:07   
What was actually done:
=======================
1. methods log/logDelete was added to kApplication class to allow developer to put/delete user-defined message into "System Log"
2. fatal errors, that cause "white screen" effect (e.g. parse error, out of memory) are handled
3. added e-mail event, that sends selected user-defined messages from System Log to e-mail, specified in configuration
4. System Log can work in 3 modes: always enabled (system errors/exception and user-defined message), only user-defined messages, always disabled
5. level of logging (decision to allow message to be written into System Log) can be controlled via configuration
6. following info can be stored with each logged message:
- unique id
- log level - emergency/alert/critical/error/warning/notice/info/debug
- type - php/database/other
- code - for errors it's error code (e.g. MySQL error code)
- message - text of logged message (for errors it's error text)
- timestamp - when message was logged
- event name - even, which caused this message to be logged (directly or indirectly), e.g. "p:OnCreate"
- ip address - ip address of website visitor
- hostname - domain where In-Portal is installed (useful to know if site domain feature is used)
- interface - front/admin/cron front/cron admin/api
- request source - web/cli
- request uri
- request data - complete set of GET/POST/COOKIE variables at moment of message logging
- logged-in username
- session key
- session data
- complete trace (with function arguments) to place where message was sent (useful for error messages)
- file and line inside that file, where message was sent (for errors indicates place where error happened)
- process id - allows easily to identify set of message during single In-Portal run
- amount of used memory at time of message sending (not at the end of script) - allows to see memory eating progress
- custom data - any data, that can be stored in database and contains extra info about the message


What was done additionally:
===========================
1. all php error/exception and sql error handling code was moved away from kApplication class into new kLogger class
2. added kDBConnection::connectionOpened and kDBLoadBalancer::connectionOpened methods for checking current database connection state
3. removed SILENT_LOG functionality, since "System Log" already does silent logging and much more
4. functionality for throwing messages, longer then "log_errors_max_len" setting from php.ini was improved (to look at "log_errors_max_len" setting value) and moved from Debugger to kLogger class and because of that debugger now is dependant on kLogger class presence
5. Debugger now can handle fatal errors, that caused "white screen" effect (e.g. parse error, out of memory)
6. removed E_STRICT errors, displayed inside AJAX responses (PHP 5.4+ only)
7. debugger setting DBG_IGNORE_STRICT_ERRORS removed, since in In-Portal 5.2.0+ we mixed all major strict errors
8. debugger now can handle all existing error types including E_CORE_* errors
9. debugger now doesn't use special kApplication methods to register it's own error/exception handlers when user together with kApplication class
10. method "__toString" added to kBase class allowing to get string representation of every kBase class descended (used during backtrace printing in System Log)
11. fixed notice caused by session printing inside debugger right after session creation (e.g. user successful login)
(0005199)
alex   
2012-10-02 12:08   
Found issues when upgrading from 5.1.0 to 5.2.0 after module selection step (if system log was enabled):
1. lots of errors about missing SystemLog table are displayed right on the screen.
2. running scheduled tasks during upgrade results in strange errors, when RunSchedule field having integer value is treated as interval.

Possible solution could lay in a way to do real class (which does what we don't want it to do during install/upgrade) replace with it's descendant class with all problematic methods overwritten with stubs.

This would be better, then doing IS_INSTALL constant check on every corner.
(0005200)
alex   
2012-10-02 12:12   
Tested install/upgrade. Install caused no errors. Some errors during upgrade when user enabled system log during upgrade. Will fix them later.
(0005201)
alex   
2012-10-02 12:13   
Fix committed to 5.2.x branch. Commit Message:

Fixes 0001003: Logging engine
(0005202)
alex   
2012-10-04 10:30   
Patch "fatal_error_with_disabled_syslog_fix.patch" fixes fatal error, that was always happening when system log is disabled and attempt is made to catch last error happened on a page.