PSR-3 compliance

[enov]

This is a work-in-progress for PSR-3 compliance.

[enov]

Hmm, this is not based on 3.4/develop. It seems to me that I have created a branch starting from the wrong revision.

[enov]

Or maybe I did not pull before starting.

[enov]

@acoulton, could you kindly review this? Also, kindly guide me what types of tests I need to write to make this complete?

[cyrrill]

This is freking great, I'm very glad to see Kohana move closer to full PSR :) 👍

[acoulton]

@enov this is looking great. A couple of thoughts:

• Do we need a Logger and Kohana_Logger interface? What benefit is there to someone being able to transparently extend the interface?
• Might it be worth introducing a class (perhaps with ArrayAccess for compatibility) for the log message itself, rather than the simple array that Log::log pushes onto the _messages array? Would allow better typehinting for that property and also for writer methods etc.

In terms of testing, things I'd consider covering (I've not reviewed what if anything is covered by existing tests):

Kohana_Core::init

• Creates default log instance if not set
• Does not change log instance if already assigned to a dummy \Psr\Log\LoggerInterface

Kohana_Exception::log

• Behaviour when Kohana::$log is not assigned (fails silently?)
• Logs the exception
• Writes logs if a Logger
• Does not fail (eg from attempting to call write) if the Kohana::$log is a non-kohana LoggerInterface

Kohana_Log

• I'd cover the inherited AbstractLogger methods for completeness, eg with a self-shunt extension class that captures calls to log and verifies that the level-specific methods call it as expected.
• That add calls log with expected argument structures
• How ::log handles the various types of levels (string, int, undefined)
• That ::log casts message to string
• That ::log interpolates context to message
• The various message properties are set in the messages array as expected
• That ::log writes if write_on_add is set - again could do this with a self-shunt

Kohana_Log_Syslog

• That it calls syslog with expected arguments, eg using a self-shunt
• Level conversion
• Exception logging

And if Kohana_Log_Writer::format_message doesn't already have coverage then I guess also tests for that.

[enov]

Do we need a Logger and Kohana_Logger interface

No we don't, interfaces should not be transparently extended like implementations, IMHO.

Might it be worth introducing a class for the log message itself

My initial intention was to be psr-3 compliant with the least change possible in the code base. I thought can further enhance the code in later versions. What do you say?

[acoulton]

Do we need a Logger and Kohana_Logger interface

No we don't, interfaces should not be transparently extended like implementations, IMHO.

Agreed - but you have both in this PR. My preference would be to drop Logger and update the type checks throughout to Kohana_Logger since that keeps it clearer where that has come from (eg makes obvious it's not a PSR3 interface).

Might it be worth introducing a class for the log message itself

My initial intention was to be psr-3 compliant with the least change possible in the code base. I thought can further enhance the code in later versions. What do you say?

Fair point, yes this pull should be limited to what's strictly necessary for PSR3.

[enov]

My preference would be to drop Logger and update the type checks throughout to Kohana_Logger

Agreed. I will create an issue for this later, targeting all other interfaces that follow this pattern.

[arteymix]

@enov do you think PSR-7 http-message should be implemented as well?

[enov]

@arteymix that's still under discussion. Plus, it would require us to be PSR-1/2 coding style, because unlike this PSR-3, it has long camelCased method names.

There is also a draft RFC about HTTP interface, that might go into PHP 7:
https://wiki.php.net/rfc/http-interface

[arteymix]

That's what I feared when I looked into the specification. PSR 1/2 is hardly thinkable at thins point.

It's a good thing though that we get more compliance with PSR, so I second you on that PR.

[enov]

@acoulton, I am struggling with writing the first test:

Kohana_Core::init

• Creates default log instance if not set

The problem is that PHPUnit boostraps Kohana the standard way, which calls Kohana::init().

So, since Kohana::init() is already called and log is set, in order for me to have an unset log, I have to unset it within the test. Now, while that seems to be easy, calling Kohana::init() again is not, because the protected flag Kohana::$_init that checks if it is initialized. That would lead us to call Kohana::deinit() within the test, which sets that flag to FALSE, but would remove also the registration of the standard Kohana autoloader, which makes other tests to fatal.

It seems to me I am hunting some kind of chicken and egg problem. I found the following 2 sub-par solutions:

Solution 1: Replay parts of bootstrap within the test

To be able to deinit() and then reinit(), I need to replay, in between these calls, parts of bootstrap required for tests to continue. I think this is sub-par solution because changing the bootstrap later on, would require us to revisit these tests and fix them.

Kindly find here-under the code for this solution:

    /**
     * Tests Kohana::init() for default log file creation
     */
    public function test_init_creates_default_log_instance_if_not_set()
    {
        // de-initialize Kohana, should set Kohana::$log to NULL
        Kohana::deinit();

        // re-register autoloader as de-initialization removes that
        spl_autoload_register(array('Kohana', 'auto_load'));

        // test if Kohana::$log is NULL at this point
        $this->assertNull(Kohana::$log);

        // re-initialize Kohana
        Kohana::init();

        // test if a default log instance is created
        $this->assertInstanceOf('Log', Kohana::$log);

        /**
         * At this point we need to replay some part from bootstrap
         * so that other tests may continue normally
         */

        // Attach the file write to logging. Multiple writers are supported.
        Kohana::$log->attach(new Log_File(APPPATH . 'logs'));

        //Attach a file reader to config. Multiple readers are supported.
        Kohana::$config->attach(new Config_File);
    }

Solution 2: a TestableCore that extends Core with a public set_init_flag

This solution relies on the fact that we can run init() again if the flag $_init is set to FALSE, which help us avoid to deinit() Kohana. I do think this solution is also sub-par, because it re-registers the exception handler, error handler and shutdown handler with PHP runtime again.

Please see the code for this solution here:

    /**
     * Tests Kohana::init() for default log file creation
     */
    public function test_init_creates_default_log_instance_if_not_set()
    {
        // set $log to NULL, as it inherited the instance from the parent class
        Kohana_CoreTest_TestableCore::$log = NULL;

        // test if it is NULL (do we need this?)
        $this->assertNull(Kohana_CoreTest_TestableCore::$log);

        // set the flag Kohana::$_init to FALSE to be able to run init() again
        Kohana_CoreTest_TestableCore::set_init_flag(FALSE);

        // initialize Kohana again
        Kohana_CoreTest_TestableCore::init();

        // assert
        $this->assertInstanceOf('Log', Kohana_CoreTest_TestableCore::$log);
    }

Code for Kohana_CoreTest_TestableCore:

class Kohana_CoreTest_TestableCore extends Kohana_Core {

    /**
     * Sets the init flag to force initialization/deinitialization
     * @param bool $flag
     */
    public static function set_init_flag($flag)
    {
        static::$_init = $flag;
    }

}

Thanks.

[acoulton]

@enov yes, that's all fairly horrid isn't it :)

Not sure what to suggest, as you say the main issue is that init does so much and replaying all of that in the unit test is bound to cause problems.

I suppose you could split all the separate actions in init into protected methods, then stub a class that makes all of them no-op - for example:

class Kohana_Core {
  public static function init() {
    if (Kohana::$_init)
    {
      // Do not allow execution twice
      return;
    }

    // Kohana is now initialized
    Kohana::$_init = TRUE;
    static::init_profile();
    static::init_errors();
    static::init_shutdown();
    static::init_windows();
    static::init_cache();
    // etc
    static::init_log();
    static::init_config();
  }
}

class LogInitKohana_CoreStub extends Kohana_Core {
  public static function init()
  {
    self::$_init = FALSE;
  }

  public static function init_profile() {}
  public static function init_errors() {}
  public static function init_cache() {}
  // etc for everything except init_log
}

That's not very nice either because of the need to be sure every init_ method was extended with an empty stub over time.

Another option would be to break the init method up into a stack of initialisers (classes or callables of some kind) - then you could just test the LogInitialiser. That would be cleaner and give more scope for extension in future and by end-users, but is obviously a chunky refactoring and may have performance, BC and other considerations.

Maybe for now the only sensible thing in the current architecture is to assume that PHPUnit didn't itself assign anything to Kohana::$log and so if it has a value it must have been assigned by init - in other words just test the result. It might be better than trying to sort out the whole init method as part of this feature.

[enov]

assume that PHPUnit didn't itself assign anything to Kohana::$log and so if it has a value it must have been assigned by init - in other words just test the result.

If we can get away with that for the first test, we can not for the second test you suggested 😄

Kohana_Core::init

• Does not change log instance if already assigned to a dummy \Psr\Log\LoggerInterface

[acoulton]

@enov indeed. I think maybe we have to accept that's almost impossible to test without introducing a lot of changes that aren't directly relevant to this PR. The only other thing I thought of was shelling out to a script in a separate PHP process but that would be pretty unpleasant too. Maybe for now these are things that just have to be verified by eye/knowing they work in end-user apps.

[enov]

I added tests comparing messages resulting from the generic log() method, as well as the 8 specialized level methods.

Tests are currently failing. This is because Kohana_Log adds trace information to the message. And since there is an additional method call when one of the level methods are used, we are having different trace entries in those messages when we compare them to the message generated by the generic log() method.

PSR-3 specifies that:

A ninth method, log, accepts a log level as first argument. Calling this method with one of the log level constants MUST have the same result as calling the level-specific method.

I think we either need to normalize the trace entries, by carefully re-engineering the result of the call to debug_backtrace, or to forget about the trace entry, as it is ignored by the abstract Log_Writer.

For the record, the file, line, class, and function entries are also giving different results. Sometimes they are NULL. I am not sure why. I also did some tests without array_slice, and results seemed to be slightly better (no NULLs, but again different results). I am even unsure why that array_slice is there, to begin with!

Any insight and guidance is greatly appreciated.

[enov]

Alright, played with fire and removed trace, class, and function keys from log message.

Please review.

cc @acoulton, @lenton, @rjd22, @shadowhand

[enov]

Do not merge yet.

[enov]

@acoulton could you please review this? Specifically this commit: 32247e5

[enov]

@acoulton I know you might be busy, but I just need your confirmation in case we can get rid of trace, class, and function from log message (as we are not using them in the default log writer).

Those are still available in case of an exception. I'll write more tests to prove the case.

[acoulton]

@enov so sorry, I've been flat out. I've just had a quick look over this and it's looking good.

I think it's fine to drop trace, class and function from ordinary log messages - as you say they're not written by any of our own writers and anyway that feels like something where the end-user should pass them as part of the context if they want them. Apart from unexpected exceptions (which are handled separately) usually you know the trace of application-specific logs.

[enov]

Thanks for the review @acoulton .

[rjd22]

@enov I also reviewed it and it looks good. I'm just wondering if we should still do our own logging. Wouldn't it be better to move to monolog? What do you think @acoulton

Anyway all in good time. For now 👍

[enov]

Thanks for the review @rjd22.

[rjd22]

@enov any updates on this?

[acoulton]

@enov this all looks good to me now. I'm not sure about the issue with travis/composer, the build output for 304678d looks normal to me?

[enov]

Thanks for reviewing again, @acoulton. Yeah, it built normally after I restarted it, most probably Travis/HHVM issue.

[acoulton]

@enov 🍻 🍰 🎈 🎆 and general 🎉

Thanks very much for this!

[enov]

Wow 😳 ... merged!

Thank you @acoulton and thank you all who participated: @cyrrill, @arteymix @Yahasana and @rjd22!

[rjd22]

@enov Thanks a log for the hard work!!

[enov]

@enov Thanks a log for the hard work!!

Haha! Good one, @rjd22, thanks!