Adding DateTime to php warnings & errors on log files

[ozgurhangisi]

Please answer these questions before submitting your issue. Thanks!

1. What did you do? If possible, provide a recipe for reproducing the error.

Log file doesn't have datetime info for PHP Error and warnings. But It has datetime info for Swoole errors/notices. So It's not possible to analyze the log file if something goes wrong. Is it possible to add DateTime info for the PHP errors.

You can see the sample error log file below :

PHP Warning: PDOStatement::execute(): MySQL server has gone away in /var/www/pdo.class.php on line 44 PHP Warning: PDOStatement::execute(): Error reading result set's header in /var/www/pdo.class.php on line 44 [2018-09-02 03:18:45 *3086.0] NOTICE swFactoryProcess_finish (ERROR 1004): send 398 byte failed, because connection[fd=30127] is closed.

2. What did you expect to see?

I need to see Datetime info on the log file. If something is wrong I can not analyze the log file. Because if there are many errors in the log file I cannot see if X error is related with the previous error or it's independent case from the others etc...

3. What did you see instead?

I can not see DateTime info in the log file for php errors.

4. What version of Swoole are you using (php --ri swoole)?

4.1.1

5. What is your machine environment used (including version of kernel & php & gcc) ?

php 7.2.9

6. If you are using ssl, what is your openssl version?

No

[twose]

You must catch it and reconnect or server maybe killed by error or exception, if you catch it, you can output date by yourself.

[ozgurhangisi]

Thanks for your comment. Actually What Im trying to say is not about mysql connection errors. I can already handle these errors. When php error happens (it can be anything, not only mysql errors) there is no datetime on the log. So I have thousands of requests in a second. If there is a network error in the night I get many errors on the log file. So in the morning I even cannot see when these errors appeared. If you say that you can catch errors and add extra exception to the log file with datetime that is ok for me. But in this case log file doesnt help people to debug errors by default and everybody has to add extra error log to the log file to see when its happened. If you dont have any plan to add datetime info for php errors I can close the ticket.

Thanks for your effort.

[twose]

emmm, you misunderstand, we should code as these:

// here is in onRequest event callback
try{
  // your code here
  if (cache){
    throw new \ExitException(); // i want to exit
  }
 // slow query...
 // balabala
} catch (\ExitException $e){
  // as php exit
} catch (\Exception $e) {
  // the other exceptions...you can error log here
} finally {
   if (!$end) {
       $response->end(); // must be ended
   }
   // then you can call some functions here (as `register_shutdown_function `)
}

[twose]

every framework works like this.

[ozgurhangisi]

Thanks for the info. I think I should add more info to explain what Im trying to say. If any php error, notice or warning happens in the code, It adds error or notice info to the swoole log file. By default, php errors doesnt have datetime info in the swoole log file. So I can use try catch blocks and throw some custom exceptions with datetime info but wouldn’t it be easier if swoole add datetime info to the swoole log file by default ? (By the way swoole already have datetime info for swoole specific errors but not for native php errors. ) If you say you can throw custom exception with datetime info that is ok but I think in this way default log file will be useless without datetime.

[ghost]

Everything done automatically costs extra ressources. Thats the con of pro & con for this question. You have datetime already in the following swoole log entry - so whats the real pro of a logfile with one, hundreds or thousands of extra added timestamps? You will mostly never have a real usecase, just the one that you know: there are errors (often), so i have to rescue them with try and catch.

Have you a real usecase for hundreds of such timestamps @ozgurhangisi ? I did not know one at moment.

[ozgurhangisi]

Hi,

If you have thousands of requests in your server probably you'll get many notice, warning, etc.. in the log file. Sometimes we see many errors and warnings in the log file and swoole server stops working. When I look at the log file (It's about a few GB size) it's not possible to say that when this error happened. If I see the time I could look at the requests in my Load Balancer's log to see that what kind of requests caused the error. But now It's not possible to say what kind of requests caused swoole server stop working. I can not analyze the log file. So I can use try catch blocks and add extra datetime info to the log but I think it would be more easy for us if swoole adds datetime to the log file by default. That is the real case for us. Now we try to convert our system from nginx-php-fpm to swoole. Our system is quite big and connected to many systems but debugging is not easy for us and it takes too much time.

So If it needs extra resources you can close this ticket. It's just the case that I noticed when I try to convert our system to swoole and I wanted to share this problem with you.

BTW Many thanks for creating amazing swoole. Great Job guys !!!

[ghost]

@ozgurhangisi thats just my opinion :) maybe, the swoole team has a different view :)

In my experience, thousands of timestands in logs doesn't really help, because every IO simply need correct error-handling, so the error itself must be catched when it happens.

[ghost]

@ozgurhangisi while building my backend i am ending now with following error-logs, like:

swoole.log php.log fileHandler.log DB.log

swoole.log is all from swoole, php.log is done by PHP, fileHandler.log is the one i use to control filesystem errors and DB.log is my controlling about all of DB work. The rest is system logs

So, all my logs have Date/Time. Where do you personally miss it? :)

[fakharak]

I found this: // logging 'log_level' => 1, 'log_file' => '/data/swoole.log', 'log_rotation' => SWOOLE_LOG_ROTATION_DAILY | SW_LOG_ROTATION_SINGLE, 'log_date_format' => 'Y-m-d H:i:s', 'log_date_with_microseconds' => false, 'request_slowlog_file' => fasle, in $server->set( ) .... on the url: https://www.swoole.co.uk/docs/modules/swoole-server/configuration

That an probably be of help in regard to date-time with logs ?

Probably, frameworks built on top of Swoole mighthave implemented something like "monolog". See Mezzio. https://docs.mezzio.dev/mezzio-swoole/v2/logging/

Probably this can also be helpful in try-catch logic: https://www.php.net/manual/en/swoole-server.getlasterror.php

By the way, i reached o this thread while searching for the purpose / meaning of "log_rotation" configuration option. So if you can provide that information that it will be a great time saving help. Thanks in anticipation.