CodeIgniter\Debug\Exceptions::exceptionHandler() - Add File and Line to message

[sclubricants]

PHP Version

8.0

CodeIgniter4 Version

4.1.8

CodeIgniter4 Installation Method

Composer (using codeigniter4/appstarter)

Which operating systems have you tested for this bug?

Windows

Which server did you use?

apache

Database

No response

What happened?

Sort of a bug, sort of a feature request.

In some cases Exception trace doesn't include any useful information.

In CodeIgniter\Debug\Exceptions::exceptionHandler() the log_message() function is called as follows:

            log_message('critical', $exception->getMessage() . "\n{trace}", [
                'trace' => $exception->getTraceAsString(),
            ]);

It would be helpful to include the file and line in the message.

Steps to Reproduce

Create a controller method and put the following lines:

set_time_limit(2);
sleep(5);

Expected Output

The log file produces:

CRITICAL - 2022-02-10 14:28:06 --> Maximum execution time of 2 seconds exceeded
#0 [internal function]: CodeIgniter\Debug\Exceptions->shutdownHandler()
#1 {main}

This isn't helpful to know where the timeout is occurring.

Anything else?

By changing the CodeIgniter\Debug\Exceptions::exceptionHandler() log_message() function to include file and line:

            log_message('critical', $exception->getMessage().' called in '.$this->cleanPath($exception->getFile()).' line '.$exception->getLine() . "\n{trace}", [
                'trace' => $exception->getTraceAsString(),
            ]);

We now get useful information to where the problem is.

CRITICAL - 2022-02-10 14:29:05 --> Maximum execution time of 2 seconds exceeded called in APPPATH\Controllers\Admin\Test.php line 14
#0 [internal function]: CodeIgniter\Debug\Exceptions->shutdownHandler()
#1 {main}

Perhaps there is a better way to do this.. maybe even a configurable option to turn this on?

[kenjis]

We use GitHub issues to track BUGS and to track approved DEVELOPMENT work packages. We use our forum to provide SUPPORT and to discuss FEATURE REQUESTS.

If you raise an issue here that pertains to support or a feature request, it will be closed! If you are not sure if you have found a bug, raise a thread on the forum first - someone else may have encountered the same thing.
https://github.com/codeigniter4/CodeIgniter4#repository-management

[sclubricants]

Well I kind of see this as a bug. The problem seems to be more in the method shutdownHandler(). Here the last error is fetched and a new instance of an exception is created and handed off to the exception handler. Therefore there is no trace except to shutdownHandler().

It seems unintended to have "shutdownHandler() threw an error (I know where but I'm not going to tell you)" in the logs. Its pointless.

[kenjis]

@lonnieezell Is this a bug?

[paulbalandan]

I think this is for consistency's sake. At least in browser and CLI, we show file/line:

diff --git a/app/Controllers/Home.php b/app/Controllers/Home.php
index 7f867e95f..8a6bb869e 100644
--- a/app/Controllers/Home.php
+++ b/app/Controllers/Home.php
@@ -2,10 +2,13 @@

 namespace App\Controllers;

+set_time_limit(2);
+
 class Home extends BaseController
 {
     public function index()
     {
+        sleep(5);
         return view('welcome_message');
     }
 }

diff --git a/system/Commands/ListCommands.php b/system/Commands/ListCommands.php
index 0c808322a..b7d0fcecd 100644
--- a/system/Commands/ListCommands.php
+++ b/system/Commands/ListCommands.php
@@ -11,6 +11,8 @@

 namespace CodeIgniter\Commands;

+set_time_limit(2);
+
 use CodeIgniter\CLI\BaseCommand;
 use CodeIgniter\CLI\CLI;

@@ -72,6 +74,8 @@ class ListCommands extends BaseCommand
      */
     public function run(array $params)
     {
+        sleep(5);
+
         $commands = $this->commands->getCommands();
         ksort($commands);

[ErrorException]

Maximum execution time of 2 seconds exceeded

at SYSTEMPATH\Commands\ListCommands.php:79

Backtrace:
  1    [internal function]
       CodeIgniter\Debug\Exceptions()->shutdownHandler()

[sclubricants]

I added another bug related to this here: #5679

This issue is fixed below by using @header().

Here is what would be awesome if we could get here:

CodeIgniter\Debug\Exceptions::exceptionHandler():

    public function exceptionHandler(Throwable $exception)
    {
        [$statusCode, $exitCode] = $this->determineCodes($exception);

        if ($this->config->log === true && ! in_array($statusCode, $this->config->ignoreCodes, true)) {
            log_message('critical', $exception->getMessage()." at {messagefile} ({messageline})\n{trace}", [
                'messagefile' => $this->cleanPath(str_replace(array('/', '\\'), DIRECTORY_SEPARATOR, $exception->getFile())),
                'messageline' => $exception->getLine(),
                'trace' => $this->getExceptionTraceAsString($exception),
            ]);
        }

        if (! is_cli()) {
            $this->response->setStatusCode($statusCode);
            @header(sprintf('HTTP/%s %s %s', $this->request->getProtocolVersion(), $this->response->getStatusCode(), $this->response->getReasonPhrase()), true, $statusCode);

            if (strpos($this->request->getHeaderLine('accept'), 'text/html') === false) {
                $this->respond(ENVIRONMENT === 'development' ? $this->collectVars($exception, $statusCode) : '', $statusCode)->send();

                exit($exitCode);
            }
        }

        $this->render($exception, $statusCode);

        exit($exitCode);
    }

I added the method getExceptionTraceAsString(). This doesn't truncate the error message making it more useful.

    /**
     * a better trace that doesn't truncate text/html
     * adapted from https://stackoverflow.com/questions/1949345/how-can-i-get-the-full-string-of-php-s-gettraceasstring
     * and includes calls to $this->cleanPath() to clean up paths
     */
	private function getExceptionTraceAsString($exception) {
		$rtn = "";
		$count = 0;
		foreach ($exception->getTrace() as $frame) {

			$args = "";
			if (isset($frame['args'])) {
				$args = array();
				foreach ($frame['args'] as $arg) {
					if (is_string($arg)) {
						$args[] = "'" . $this->cleanPath($arg) . "'";
					} elseif (is_array($arg)) {
						$args[] = "Array";
					} elseif (is_null($arg)) {
						$args[] = 'NULL';
					} elseif (is_bool($arg)) {
						$args[] = ($arg) ? "true" : "false";
					} elseif (is_object($arg)) {
						$args[] = get_class($arg);
					} elseif (is_resource($arg)) {
						$args[] = get_resource_type($arg);
					} else {
						$args[] = $arg;
					}
				}
				$args = join(", ", $args);
			}
			$current_file = "[internal function]";
			if(isset($frame['file']))
			{
				$current_file = $frame['file'];
			}
			$current_line = "";
			if(isset($frame['line']))
			{
				$current_line = $frame['line'];
			}
			$rtn .= sprintf( "#%s %s(%s): %s(%s)\n",
				$count,
				$this->cleanPath($current_file),
				$current_line,
				$frame['function'],
				$args );
			$count++;
		}
		return $rtn;
	}

[kenjis]

This issue is fixed below by using @header().

We should not use @. It does not fix anything. It only hides it.

[kenjis]

@paulbalandan I can't reproduce your samples. No errors and these run normally.
I looked for the reason, I remembered

The set_time_limit() function and the configuration directive max_execution_time only affect the execution time of the script itself. Any time spent on activity that happens outside the execution of the script such as system calls using system(), stream operations, database queries, etc. is not included when determining the maximum time that the script has been running. This is not true on Windows where the measured time is real.
https://www.php.net/manual/en/function.set-time-limit.php#refsect1-function.set-time-limit-notes

[paulbalandan]

Yes, I've run the code in Windows.

[kenjis]

@sclubricants Can you check #5684 solves your problem?

[sclubricants]

@sclubricants Can you check #5684 solves your problem?

Yes, it looks good.

@paulbalandan
Only thing you could do but is not a big issue is add:

					case is_string($value):
						return clean_path($value);

after "case is_resource($value):" in renderBacktrace(). (line 469) This would pretty up the logs a bit more.

Instead of:

CRITICAL - 2022-02-14 14:34:25 --> Cannot modify header information - headers already sent
in APPPATH\Controllers\Admin\Test.php on line 16.
 1 [internal function]: CodeIgniter\Debug\Exceptions->errorHandler(2, 'Cannot modify header information - headers already sent', 'C:\\xampp\\portal\\app\\Controllers\\Admin\\Test.php', 16)
...

You get:

CRITICAL - 2022-02-14 14:34:34 --> Cannot modify header information - headers already sent
in APPPATH\Controllers\Admin\Test.php on line 16.
 1 [internal function]: CodeIgniter\Debug\Exceptions->errorHandler(2, Cannot modify header information - headers already sent, APPPATH\Controllers\Admin\Test.php, 16)