strange bug with autoloader

[jeroenbourgois]

I noticed that e.g. the Crypt class wouldn't autoload anymore. More precise, the init function was not triggered.

I started looking around, and insidefuel/core/classes/autoloader.php I put a debug statement on line 348, inside the init_class function. This is my statement:

    system('echo ' . date('d/m/y G:H:i:s') . '" :: loading :: ' . $class . ' ' . static::$auto_initialize . '" >> /tmp/fueldebug');

And here is an excerpt of the output:

31/01/13 13:13:18:13 :: loading :: Fuel :: Fuel
31/01/13 13:13:18:13 :: loading :: FuelException :: Config
31/01/13 13:13:18:13 :: loading :: Config :: Config
31/01/13 13:13:18:13 :: loading :: Fuel\Core\Config_Interface :: Config_Php
31/01/13 13:13:18:13 :: loading :: Config_File :: Config_Php
31/01/13 13:13:18:13 :: loading :: Config_Php :: Config_Php
31/01/13 13:13:18:13 :: loading :: Finder :: Finder
31/01/13 13:13:18:13 :: loading :: Arr :: Arr
31/01/13 13:13:18:13 :: loading :: Profiler :: Profiler
31/01/13 13:13:18:13 :: loading :: Input :: Input
31/01/13 13:13:18:13 :: loading :: Security :: Security
31/01/13 13:13:18:13 :: loading :: Event :: Event
31/01/13 13:13:18:13 :: loading :: ConfigException :: ConfigException
31/01/13 13:13:18:13 :: loading :: Event_Instance :: Event_Instance
31/01/13 13:13:18:13 :: loading :: Package :: Package
31/01/13 13:13:18:13 :: loading :: Sentry :: Sentry
31/01/13 13:13:18:13 :: loading :: Log\Log :: Log\Log
31/01/13 13:13:18:13 :: loading :: Psr\Log\LoggerInterface :: Monolog\Logger
31/01/13 13:13:18:13 :: loading :: Monolog\Logger :: Monolog\Logger
31/01/13 13:13:18:13 :: loading :: Monolog\Handler\HandlerInterface :: Monolog\Handler\StreamHandler
31/01/13 13:13:18:13 :: loading :: Monolog\Handler\AbstractHandler :: Monolog\Handler\StreamHandler
31/01/13 13:13:18:13 :: loading :: Monolog\Handler\AbstractProcessingHandler :: Monolog\Handler\StreamHandler
31/01/13 13:13:18:13 :: loading :: Monolog\Handler\StreamHandler :: Monolog\Handler\StreamHandler
31/01/13 13:13:18:13 :: loading :: Monolog\Formatter\FormatterInterface :: Monolog\Formatter\LineFormatter
31/01/13 13:13:18:13 :: loading :: Monolog\Formatter\NormalizerFormatter :: Monolog\Formatter\LineFormatter
31/01/13 13:13:18:13 :: loading :: Monolog\Formatter\LineFormatter :: Monolog\Formatter\LineFormatter
31/01/13 13:13:18:13 :: loading :: Monolog\Handler\RavenHandler :: Monolog\Handler\RavenHandler
31/01/13 13:13:18:13 :: loading :: Module :: Module
31/01/13 13:13:18:13 :: loading :: Router :: Router
31/01/13 13:13:18:13 :: loading :: Route :: Route
31/01/13 13:13:18:13 :: loading :: Request :: Request
31/01/13 13:13:18:13 :: loading :: Fuel\Core\Uri :: Uri
31/01/13 13:13:18:13 :: loading :: Uri :: Uri
31/01/13 13:13:18:13 :: loading :: Inflector :: Inflector
31/01/13 13:13:18:13 :: loading :: Session :: Controller_Default
31/01/13 13:13:18:13 :: loading :: Session_Driver :: Controller_Default
31/01/13 13:13:18:13 :: loading :: Session_Cookie :: Controller_Default
31/01/13 13:13:18:13 :: loading :: Date :: Controller_Default
31/01/13 13:13:18:13 :: loading :: Cookie :: Controller_Default
31/01/13 13:13:18:13 :: loading :: Crypt :: Controller_Default

What I noticed is that suddenly the $auto_initialize variable contains Controller_Default for a couple of classes, and therefore those classes are not _init-ed. Is this by design? Because if it is, and I have a fairly stupid typo in my controller (for example I forget a closing bracket) then I get:

Fatal error: Call to a member function setKey() on a non-object in /Volumes/data/Users/jeroenb/Projects/engine/fuel/core/classes/crypt.php on line 125

Because the Crypt object hasn't been initialized. If I call Crypt::_init() in my bootstrap, I get a nice error telling me the line of my typo.

Moreso, I noticed a custom package of mine has the same problem, where it is loaded but not _init.

A found one solution, but I doubt it is a good one. Inside the Autoloader class, on line 291, I changed:

if (static::$auto_initialize == $class) {
    static::$auto_initialize = null;
}

to

// removed the if statement
static::$auto_initialize = null;

I hope you can help me and moreover that I can help you finding and fixing this bug :)

/cc @pierot, @rob-bar, @dupontjonathan, @jonathanpardon, @jeroendp

[pierot]

I noticed the same behaviour.

[jeroendp]

I've had the same behaviour in a project.

[WanWizard]

I'm clueless. There isn't such a thing in FuelPHP called Controller_Default. If this was a generic issue, I bet the forums would be flooded with reports about this?

[WanWizard]

I can't reproduce it. Creating a syntax error in a controller (in a working application on 1.6/develop) I just get the normal error screen.

[jeroenbourgois]

Ok thank you for the efforts so far. I will try again with the 1.6/develop branch and see what's different from the fuel version we are using. If the problem persists I will get back to you, untill then you can consider this as closed.

[WanWizard]

Think I know what goes wrong.

That code is there to capture recusive calls.Suppose you have :

D extends C extends B extends A

and you load class D. Then the autoloader will recursively have to load C, B and A too. Now if only A would have an _init(), and this check wasn't there, to would call _init() on loading D, C, B and A, four times instead of only once.

This code makes sure _init() is only called on the first class in the chain being loaded, in this example class D, because that is set in load(), L#231.

Now, in your case, "Controller_Default" is being loaded, which has the syntax error. This will cause a PHP error to occur, aborting the load() call. Leaving the static::$auto_initialize to be set.

The PHP error will be converted to an Exception, and FuelPHP will continue wrapping up, first by running the exception handler, then the shutdown handler. Which will call Session if you have that loaded, to close the session. This however will trigger more autoloader calls, which now go wrong because of the invalid state of the loader.

You can test this theory (as I can't reproduce it here) by making the $auto_initialize property in the Autoloader class public, and then in the Error class, in the error_handler(), add `\Autoloader::$auto_initialize = null; to reset the autoloader state.

[WanWizard]

I think I fixed it in https://github.com/fuel/core/commit/974281dde67345ca8d7cfa27bcf4aa55c984d48e. Can someone test this, as I have trouble reproducing these issues.

[jeroenbourgois]

This seems to work.

[WanWizard]

Cool, thanks for the feedback.

[andrewwheal]

I have had this issue crop up on the 1.7/develop branch (specifically, initially at a4f5933 and then also at 3c1816a)

It was caused by the use of the Log class at the top of the file to log a warning that the class was deprecated. The Log class did not have _init() run and thus errored on trying to use the static $monolog property which had not been set.

[WanWizard]

The Log class deprecated?

[andrewwheal]

No, a class in our code was deprecated, and the Log class was used at the top of this file to record the deprecation.

https://gist.github.com/SicoAnimal/425fab1004d812562fc9#file-field-php

[WanWizard]

Ok, I'll try to see if I can reproduce that.

[WanWizard]

If I add that to an existing controller, and force a parsing error, I get the error without problems.

syntax error, unexpected end of file, expecting function (T_FUNCTION)

The reason that code is in the autoloader btw, it because of recursive autoloading. Consider this:

class A
{
    public static function _init()
    {
    }
}

class B extends A
{
    public static function _init()
    {
        parent::_init();
    }
}

class C extends B
{
    public static function _init()
    {
        parent::_init();
    }
}

This will mean that as soon as the autoloader loads C, it will trigger an autoload of B, which will trigger an autoload of A. This all happens inside the autoloader.

Which that change you made, it means the autoloader will detect and call _init() for each of these three class loads, while it should only call C::_init(), the class you load in your code. This is what that piece of code does.

Now, if the autoloader aborts due to an error in the class loaded, that static was not reset, causing subsequent class loads from the error or exception handler to not trigger the call to _init(), which was terminal for the Log class.

This has been fixed by the initial response to this issue, by having the error and exception handler reset the autoloader before processing the error (see fuel/core/bootstrap.php, the call to \Autoloader::_reset();).

[andrewwheal]

I realise that the code in the autoloader is there to stop parent class recursion, and I know that changes were made to solve the issue when errors were involved.

In my particular issue there was no error being generated in my code. The problem with the autoloader not calling _init() on the Log class was because of where the Log class was being used and the fact that the Log class had not been previously loaded.

The sequence of events as I understand them is:

1. \Test1\Fieldset_Markup_Field is used in code
2. \Autoloader::$auto_initialize is set to \Test1\Fieldset_Markup_Field
3. The autoloader includes the file for the \Test1\Fieldset_Markup_Field class
4. The Log class is encountered for the first time and the autoloader kicks in
5. \Autoloader::$auto_initialize is already set so the autoloader just includes the log file and does not run Log::_init()
6. Log::warning() causes an error because the Log class has not been initialised

I fixed the problem in my code by moving my Log::warning() into the \Test1\Fieldset_Markup_Field_init() method, but I commented on this issue to make you aware that it was reproducable.

[WanWizard]

Ok, just wanted to point out the danger of removing that if.

I've managed to reproduce it by loading a class with a Log call in the app bootstrap, which is before Log is loaded by the request class.

[andrewwheal]

A detection between autoloading separate classes and parent classes might be possible with either Reflection or class_parents()

[WanWizard]

I'm pretty sure it can not be fixed, due to the fact that the SPL autoloader only registers the class loaded at the very end, which means that when loading a class triggers a secondary load, the first parent isn't marked loaded, so you can't use reflection or class_parents() to check if the secondary load was triggered because of an "extends".