Undefined index: i in … FileJournal.php

hubipe

Hello,
from time to time (it happened 3 times since web was launched 2 months ago), FileJournal got corrupted. I don't know how does it happend, but result is, that users got Error 500 page.

In log it starts like this:

[2014-11-05 10-23-03] PHP Notice: Undefined index: i in ...\libs\_vendors\nette\nette\Nette\Caching\Storages\FileJournal.php:616  @  http://...
[2014-11-05 10-23-03] PHP Notice: Undefined index: i in ...\libs\_vendors\nette\nette\Nette\Caching\Storages\FileJournal.php:728  @  http://...
[2014-11-05 10-23-10] PHP Notice: Undefined index: i in ...\libs\_vendors\nette\nette\Nette\Caching\Storages\FileJournal.php:797  @  http://...
[2014-11-05 10-23-10] PHP Notice: Undefined index: i in ...\libs\_vendors\nette\nette\Nette\Caching\Storages\FileJournal.php:728  @  http://...
[2014-11-05 10-23-16] PHP Notice: Undefined index: i in ...\libs\_vendors\nette\nette\Nette\Caching\Storages\FileJournal.php:797  @  http://...
[2014-11-05 10-23-16] PHP Notice: Undefined index: i in ...\libs\_vendors\nette\nette\Nette\Caching\Storages\FileJournal.php:728  @  http://...
[2014-11-05 10-23-42] PHP Notice: Undefined index: i in ...\libs\_vendors\nette\nette\Nette\Caching\Storages\FileJournal.php:797  @  http://...
[2014-11-05 10-23-42] PHP Notice: Undefined index: i in ...\libs\_vendors\nette\nette\Nette\Caching\Storages\FileJournal.php:728  @  http://...
[2014-11-05 10-24-31] PHP Notice: Undefined index: i in ...\libs\_vendors\nette\nette\Nette\Caching\Storages\FileJournal.php:797  @  http://...
[2014-11-05 10-24-31] PHP Notice: Undefined index: i in ...\libs\_vendors\nette\nette\Nette\Caching\Storages\FileJournal.php:728  @  http://...
[2014-11-05 10-25-07] PHP Notice: Undefined index: i in ...\libs\_vendors\nette\nette\Nette\Caching\Storages\FileJournal.php:797  @  http://...

then, always few logs after, it starts filling with FatalExceptions:

[2014-11-10 12-24-19] PHP Warning: Illegal offset type in isset or empty in ...\libs\_vendors\nette\nette\Nette\Caching\Storages\FileJournal.php:569  @  http://...
[2014-11-10 12-24-19] Fatal error: Unsupported operand types in ...\libs\_vendors\nette\nette\Nette\Caching\Storages\FileJournal.php:573  @  http://...

Some system info:

Apache/2.4.9 (Win32) OpenSSL/1.0.1g PHP/5.5.11
Windows Server 2012
FileSystem NTFS
Nette Framework 2.1.2 (revision released on 2014-03-17)

Does anybody else experienced the same problem? I'm not sure why is this happening in such a rare occassions (it's not public server, maybe when simultaneous write to cache is performed? Does NTFS supports File locking?)

xificurk

We ran into this on one of our projects. Since it was isolated occurrence, we did not investigate the underlying cause and simply deleted the cache.

Our system info is:
Ubuntu Linux
ext4 FS
PHP 5.3.10–1ubuntu3.15
Nette 2.1.4

cubic

I had similar problems last year. For some reason file btfj.dat wasn't saved complete. There was no obvious reason but memcached / redis solved the problem..

hubipe

If this occured only once, I'd be happy, but explain to your client, that Error 500 occured due to some error I can't handle and I don't know how it happened :)

Jan Tvrdík

I would blame this on Windows. You may try to enable FileJournal::$debug.

BTW: Probably a lot more interesting than your system info is how exactly do you use cache? What kind of dependencies do you use? Do you use priority? Do you use tags? etc.

Last edited by Jan Tvrdík (2014-11-11 09:55)

Michalek

Same problem on Nette 2.1, don't know why. Just sometimes.

This works, but I think it's not good solution :)

ErrorPresenter.php

	public function renderDefault($exception)
	{
	    if($exception instanceof Nette\InvalidStateException) {
	        $temp = $this->context->parameters['tempDir'];
	        unlink($temp . '/btfj.dat');
	    }
	}

Last edited by Michalek (2014-11-11 09:58)

Milo

@Michalek In your workaround… could you rename btfj file instead of removing? For example:

rename($temp . '/btfj.dat', $temp . '/btfj.dat' . microtime(TRUE));

And send me such malformed files? It is very hard to solve this issue and any feed back is very appreciated.

https://github.com/…ng/issues/11

Michalek

Ok, changed, we will see.

hubipe

Here are three corrupted btfj.dat I could restore from recycle bin (at least I thing they're corrupted):

http://filejournal.hubik.net/btfj1.dat
http://filejournal.hubik.net/btfj2.dat
http://filejournal.hubik.net/btfj3.dat

Last edited by hubipe (2014-11-12 00:37)

hubipe

@JanTvrdík I use only TAGS to be able to expire cache by those tags. (Plus EXPIRE, but that doesn't have anything to do with FileJournal.)

Milo

@hubipe Thank you! I reuploaded files (links in Github issue) so you can delete them if you wish.

If you can, could you replace your FileJournal.php by this one from Gist? It adds simple logging functionality into file btfj.dat.log in the same directory. It does not solve the issues, but it tries to log situations you mentioned in your first post. So, you should still get PHP notices, but Fatal Error should be suppressed.

Before sending a log, please, check the privacy content. It will contain variable dumps and stack traces.

hubipe

I uploaded your FileJournal, now I can only wait.

Milo

@hubipe Some catches in log file?

hubipe

None yet, it can take a while (even a month), until the error occures again. I'll keep you updated

hubipe

Ok – it happened again (I wasn't able to upload it sooner, sorry):

http://filejournal.hubik.net/btfj4.dat
http://filejournal.hubik.net/btfj4.dat.log

Milo

Thanks! I'll analyze it and report it to the FileJournal author.

If you want to prevent FileJournal buggy behaviour, you can use SQLiteStorage instead of FileStorage. It works with TAGS and PRIORITY too, but it is slower.