Duplicate Logfile Entries

[kixe]

During module development I've recognized a strange behaviour. Logfile entries in errors.txt and messages.txt are always created twice. This happened on different servers in different environments with different modules.

I tested it with this small module:

<?php
class Debug extends WireData implements Module {

    public function init() {
	$this->message(microtime(),Notice::logOnly); // same with $this->error()
    }
}

/*log file entries:
 * 2014-11-07 05:52:14    admin    [...]/admin/module/    0.43575100 1415335934
 * 2014-11-07 05:52:14    admin    [...]/admin/module/    0.43575100 1415335934
*/

whereas only a simple entry is generated when I provoke an error an catch it to log with exception handling.

<?php
class Debug extends WireData implements Module {

	public function init() {
		try {
			foo($bar);
		} catch(Exception $e) {
			$this->error($e->getMessage(), Notice::log); 
		}
	}
}

/*log file entry:
 * 2014-11-07 12:45:19  admin  [...]/admin/module/    Error:  Call to undefined function foo() (line 16 of [...]/site/modules/Debug.module)
 */

Happened this before anywhere? Any Experiences with that? Any Ideas? Couldn't find out the reason for that!

[Soma]

Nope. Obviously your class is inited two times. How do you trigger that example?

[kixe]

I triggered it by installing and uninstalling.
This way of log writing (outside a try catch handler) is very rare in core. I found it here:

FieldtypeComments.module -> after creating a field of type Comments.
ProcessPageSort.module -> after a page has been moved or after sort settings has been changed under tab 'children'.

Could you please try out this and tell me if you get duplicated entries in messages.txt? Thanks.

[Soma]

On Install is that a midule is inited or triggered twice. Not sure about details but recognized this long time ago.

But otherwise usually not unless theres some thing happening like rendering multiple thing in one request. It can happen.

[kixe]

.... It can happen.

Yes, its not the biggest problem I have. But there should be a way to solve this.

ProcessLogin.module (v101) gives an error notice if an index.php file from an older pw-version is found in the root directory.

I played with this one too. I got 6 entries in errors.txt with the same message by one click.

Two is ok, but six is too much for the best CMS in the world, isn't it?

[horst]

@kixe: interesting!

If you like, maybe just for testing you can make Notices::add (in wire/core/notices.php) hookable by preceding three underscores: ___add(

And then there should be stored the last error / warning / message into class vars and if a comparision of a new arrived notice against that previous stored ones matches, one could simply drop them. Or something along that lines.

If you work out a solution to make it better in the regard of double / multiple notices, you can post it to Ryan at Github.