CakePHP notices pre-fixed with 'Debug: '; go into debug.log

Question

I've just discovered that my application is logging Notices in debug.log instead of error.log. All notices seem to be prefixed with "Debug: ", e.g.:

2014-07-25 14:10:50 Debug: Notice (8):

Debug is set to 0 in core.php. I'm using a custom error handler, configured in core.php:

Configure::write('Error', array(
    'handler' => 'MyErrorHandler::handleError',
    'level' => E_ALL & ~E_DEPRECATED & ~E_STRICT,
    'trace' => true,
    'api' => false
));

I have this in bootstrap.php:

App::uses('MyErrorHandler', 'Lib');

App::uses('CakeLog', 'Log');
CakeLog::config('debug', array(
    'engine' => 'FileLog',
    'types' => array('info', 'debug'),
    'file' => 'debug',
));
CakeLog::config('error', array(
    'engine' => 'FileLog',
    'types' => array('warning', 'error', 'critical', 'alert', 'emergency', 'notice'),
    'file' => 'error',
));

If I move 'debug' from the debug config to the error config, debug messages go to error.log, but then so does the output from Debugger:log().

The issue seems to be that the notices are being prefixed with "Debug". Any ideas?

Update See answer from @ndm Here is the code I used in my custom mapErrorCode function to help resolve this:

case E_NOTICE:
case E_USER_NOTICE:
    $error = 'Notice';
    $levels = array_flip(CakeLog::levels());
    $log = ( isset($levels['notice']) ? $levels['notice'] : LOG_NOTICE );

Answer 1

The problem

As mentioned in my comment, this behavior is caused by LOG_DEBUG and LOG_NOTICE holding the same value (6) on Windows systems, some people in the PHP team thought it might be funny to handle the OS differences (Windows doesn't have that many levels) exposed at user level, instead of translating the values internally.

https://bugs.php.net/bug.php?id=18090

Internally CakeLog uses an error type (string) to error level (int) map, which is being flipped to create a map to retrieve the type by level, and so you'll end up with a map that looks like

array(
    (int) 1 => 'critical',
    (int) 4 => 'error',
    (int) 5 => 'warning',
    (int) 6 => 'debug'
)

which will cause LOG_DEBUG, LOG_NOTICE and LOG_INFO levels to be treated as debug types, as they are all holding the value 6.

A possible workaround

Working around this problem should be possible, but it might have some caveats. You could override the levels in CakeLog using CakeLog::levels() so that the types have individual levels:

CakeLog::levels(array(
    'emergency', 'alert', 'critical', 'error',
    'warning', 'notice', 'info', 'debug'
),
false);

would result in a map like

array(
    (int) 0 => 'emergency',
    (int) 1 => 'alert',
    (int) 2 => 'critical',
    (int) 3 => 'error',
    (int) 4 => 'warning',
    (int) 5 => 'notice',
    (int) 6 => 'info',
    (int) 7 => 'debug'
)

Finally you'd need to use a custom error handler which maps the error codes to the proper levels, see ErrorHandler::mapErrorCode(), by default notices are mapped to LOG_NOTICE (6), which you'd want to be 5 instead.

The problem with that might be

While this might work for PHP errors (like for example notices about undefined variables and the like) that are flowing through the error handler, and custom calls to CakeLog::write() where you are explicitly passing the appropriate level, you may run into problems where the core or a plugin calls CakeLog::write() and passes hard-coded LOG_* constants, which would most likely cause the types to be written into the wrong log again.

However as far as I can tell the only place where such calls to CakeLog::write() appear in the core (yet), is in the error handler, so overriding this might do it for now.