CI logging: Two rounds of CI logs for each page load?

[eluser]Nick Jennings[/eluser]
Hi All,

I'm currently debugging a CI app that I did not develop. Some strange behavior lead me to have a look at the CI logs, and I noticed that for each "reaload" of a page, I was getting seemingly two run-throughs of logs (two groups of info both ending in their own "Total execution time" statistic).

I thought this was specific to the application, so I tested it on my test install of CI, and low-and-behold I got the same results. It seems any errors I get, I get twice in the logs.

Here is an example of what showed up in the logs after a single page reload on my local CI app:

Code:

DEBUG - 2010-06-02 14:32:45 --> Config Class Initialized
DEBUG - 2010-06-02 14:32:45 --> Hooks Class Initialized
DEBUG - 2010-06-02 14:32:45 --> URI Class Initialized
DEBUG - 2010-06-02 14:32:45 --> No URI present. Default controller set.
DEBUG - 2010-06-02 14:32:45 --> Router Class Initialized
DEBUG - 2010-06-02 14:32:45 --> Output Class Initialized
DEBUG - 2010-06-02 14:32:45 --> Input Class Initialized
DEBUG - 2010-06-02 14:32:45 --> Global POST and COOKIE data sanitized
DEBUG - 2010-06-02 14:32:45 --> Language Class Initialized
DEBUG - 2010-06-02 14:32:45 --> Loader Class Initialized
DEBUG - 2010-06-02 14:32:45 --> Helper loaded: url_helper
DEBUG - 2010-06-02 14:32:45 --> Database Driver Class Initialized
DEBUG - 2010-06-02 14:32:45 --> Session Class Initialized
DEBUG - 2010-06-02 14:32:45 --> Helper loaded: string_helper
DEBUG - 2010-06-02 14:32:45 --> Session routines successfully run
DEBUG - 2010-06-02 14:32:45 --> Controller Class Initialized
DEBUG - 2010-06-02 14:32:45 --> Model Class Initialized
DEBUG - 2010-06-02 14:32:45 --> File loaded: application/views/content_shows.php
DEBUG - 2010-06-02 14:32:45 --> File loaded: application/views/content_photos.php
DEBUG - 2010-06-02 14:32:45 --> File loaded: application/views/content_videos.php
DEBUG - 2010-06-02 14:32:45 --> File loaded: application/views/content_store.php
DEBUG - 2010-06-02 14:32:45 --> File loaded: application/views/frontend_template.php
DEBUG - 2010-06-02 14:32:45 --> Final output sent to browser
DEBUG - 2010-06-02 14:32:45 --> Total execution time: 0.1454
DEBUG - 2010-06-02 14:32:45 --> Config Class Initialized
DEBUG - 2010-06-02 14:32:45 --> Hooks Class Initialized
DEBUG - 2010-06-02 14:32:45 --> URI Class Initialized
DEBUG - 2010-06-02 14:32:45 --> Router Class Initialized
DEBUG - 2010-06-02 14:32:45 --> Output Class Initialized
DEBUG - 2010-06-02 14:32:45 --> Input Class Initialized
DEBUG - 2010-06-02 14:32:45 --> Global POST and COOKIE data sanitized
DEBUG - 2010-06-02 14:32:45 --> Language Class Initialized
DEBUG - 2010-06-02 14:32:45 --> Loader Class Initialized
DEBUG - 2010-06-02 14:32:45 --> Helper loaded: url_helper
DEBUG - 2010-06-02 14:32:45 --> Database Driver Class Initialized
DEBUG - 2010-06-02 14:32:46 --> Session Class Initialized
DEBUG - 2010-06-02 14:32:46 --> Helper loaded: string_helper
DEBUG - 2010-06-02 14:32:46 --> Session routines successfully run
DEBUG - 2010-06-02 14:32:46 --> Controller Class Initialized
DEBUG - 2010-06-02 14:32:46 --> Model Class Initialized
DEBUG - 2010-06-02 14:32:46 --> Final output sent to browser
DEBUG - 2010-06-02 14:32:46 --> Total execution time: 0.2698

Is this normal? If so could someone explain to me whats going on here so I can better understand and debug my applications?

Thanks,
Nick

[eluser]n0xie[/eluser]
This usually happens when you try to load a file that isn't there. Remember that all the requests go through index.php so if a 404 occurs it still goes through the index.php. You see that it are 2 different requests:

Code:

DEBUG - 2010-06-02 14:32:45 --> URI Class Initialized
DEBUG - 2010-06-02 14:32:45 --> No URI present. Default controller set.
DEBUG - 2010-06-02 14:32:45 --> Router Class Initialized

Code:

DEBUG - 2010-06-02 14:32:45 --> URI Class Initialized
DEBUG - 2010-06-02 14:32:45 --> Router Class Initialized

[eluser]Nick Jennings[/eluser]
Hi n0xie,

Thanks for the reply. That makes sense, I wasn't thinking about calls back to other CI functions from within the view. (in this case, to display a thumbnail from a db record).

Thanks again!
-nick

[eluser]Nick Jennings[/eluser]
Quick secondary question, isn't there a way to logs which controllers and controller methods are called on a request? This debug output is all very general and not very informative.

[eluser]WanWizard[/eluser]
Hook into the pre_controller hook, and add

Code:

log_message('debug', 'routing to '.$this->router->fetch_class().'::'.$this->router->fetch_method().'()');

or do this in the constructor of your MY_Controller.

[eluser]Nick Jennings[/eluser]
Thanks!