Message in Fabrik log not relevant ?

[lcollong]

Hi,

I have several Fabrik's cron tasks. The fabrik_log table contains several of these :

2,DateTime::__construct(): Failed to parse time string (SOMETHING) at position 0 (S): The timezone could not be found in the database,/home/xxxxxxx/www/libraries/fabrik/fabrik/Helpers/Worker.php,1989

I thought it was one of my scripts. But the line 1989 belong to a function "isDate" which try to check if a string is a valid date one.

It seems that users are doing interactive list search and, sometimes, while the cron script is running in background at the same time. Thus triggering the error message which, apparantly, has nothing to see with my scripts.
However I'm wondering why the search stuff is trying to check if "SOMETHING" is a valid date. I guess users are using the global list search feature which try to verify if the search string is a valid date to compare to some dateTime columns ? But the selected fields on which search should check against do not include any dateTime elt....

I've added a trace instruction in the catch part of the isDate function and here is what I catch :

APCHEA !! --> #0 /home/xxxxxx/www/libraries/fabrik/fabrik/Helpers/Worker.php(1989): DateTime->__construct('SOMETHING') #1 /home/xxxxxx/www/plugins/fabrik_element/date/date.php(1147): Fabrik\Helpers\Worker::isDate('SOMETHING') #2 /home/xxxxxxx/www/components/com_fabrik/models/listfilter.php(632): PlgFabrik_ElementDate->includeInSearchAll(false, 'SOMETHING') #3 /home/xxxxxxxxx/www/components/com_fabrik/models/listfilter.php(365): FabrikFEModelListfilter->insertSearchAllIntoFilters(Array, 'SOMETHING') #4 /home/xxxxxxx/www/components/com_fabrik/models/listfilter.php(177): FabrikFEModelListfilter->getSearchAllFilters(Array) #5 /home/xxxxxxxx/www/components/com_fabrik/models/list.php(825): FabrikFEModelListfilter->getFilters() #6 /home/xxxxxxxx/www/components/com_fabrik/controllers/list.php(160): FabrikFEModelList->getRequestData() #7 /home/xxxxxxx/www/libraries/src/MVC/Controller/BaseController.php(710): FabrikControllerList->filter() #8 /home/xxxxxxxx/www/components/com_fabrik/fabrik.php(181): Joomla\CMS\MVC\Controller\BaseController->execute('filter') #9 /home/xxxxxxxx/www/libraries/src/Component/ComponentHelper.php(381): require_once('/home/xxxxxx...') #10 /home/xxxxxxx/www/libraries/src/Component/ComponentHelper.php(356): Joomla\CMS\Component\ComponentHelper::executeComponent('/home/xxxxxxx...') #11 /home/xxxxxxx/www/libraries/src/Application/SiteApplication.php(194): Joomla\CMS\Component\ComponentHelper::renderComponent('com_fabrik') #12 /home/xxxxxxxx/www/libraries/src/Application/SiteApplication.php(233): Joomla\CMS\Application\SiteApplication->dispatch() #13 /home/xxxxxxx/www/libraries/src/Application/CMSApplication.php(267): Joomla\CMS\Application\SiteApplication->doExecute() #14 /home/xxxxxxx/www/index.php(49): Joomla\CMS\Application\CMSApplication->execute() #15 {main}

So questions are : why do we check "isDate" ? Shouldn't we purge the message queue somewhere to avoid to catch the unwanted message in the cron task ?

 

[cheesegrits]

Out of interest, can you tell me what the "SOMETHING" is? Typically you'd only get that specific error if DateTime() thinks it's a date shaped value, with a symbolic (rather than numeric) time zone appended ...

$dt = new DateTime('01/18/2016 00:00 AM America/New_York');

... and you don't have the MySQL timezone tables installed (which aren't installed by default, which is a gigantic pain in the ass for date handling).

The reason we have to run the isDate() on anything we want to treat as a date that we aren't 100% sure will be a valid date string is because the PHP DateTime class will throw an error if you try and create a date from a non-date string. And there are lots of places in the code where we accept dates that may not be dates, either by design - we accept "non dates" as dates in things like filters, like "tomorrow" or "next month", which are MySQL "dates", which we pass through to the query rather than converting to a date - or by accident, where someone puts a malformed date in a query string, etc.

And if we don't test, any non-dates will blow up. So we run dates through our isDate(), which does ...

        try
        {
            $dt = new DateTime($d);
        } catch (Exception $e)
        {
            return false;
        }

... so if the DateTime() class creation blows up, the theory is we catch the exception and return false, so the code calling isDate() knows it's not a date.

HOWEVER ... depending on the exact version of PHP, and the exact error DateTime finds, it sometimes just does a straight up fatal error, instead of throwing a catchable exception. It's a perennial problem with the DateTime class, which is gradually improving, but not quite there yet.In other words, where you are seeing that error is the code designed to make sure you DON'T see that error ... but for reasons I don't understand, that try/catch isn't catching the exception.

What version of PHP do you run?

As for purging error message queues ... we do try, but it's just not possible to do in all circumstances. PHP *really* wants to tell you about errors.

-- hugh

 

[lcollong]

The "SOMETHING" is just the string I am looking for in the list's search all field (as per the screenshot). Apparently he's checking for date whatever you enter in the search area.
I've modified the isDate function this way :

        try
        {
            $dt = new DateTime($d);
        } catch (Exception $e)
        {
            echo "APCHEA !!  --> " . $e->getTraceAsString();
            return false;
        }

        return true;

what ever I search for in the table, I got the "echo" message which seems to mean he's always doing a isDate check. The only way to not display the trace message is actually to search for.... a date ! (ie 2017-12-06).

We are running PHP version 7.1.9

I understand the reason why testing for date and the clever way to do it. Thanks for the explanations.
I was just wondering why I got this message in the cron log spending a "bit of time" trying to find out what were wrong with my scripts....
Now, I know I can forget these messages !

 

[cheesegrits]

What error logging level do you use?

I just noticed that it isn't saying "Uncaught exception" in your log, which means our function is doing what it is supposed to do, but the error thrown by Datetime(), which we catch, is still being logged. I think the only way to stop that would be to reduce your error logging in PHP.

-- hugh

 

[lcollong]

already set to "none" (screenshot)....
I think I'll have to live with it

 

[cheesegrits]

Hmm, yeah, I guess it's not really PHP logging it ... it's when we check for errors in eval'ed code in the cron plugin ... I'll see if we can do a better job of clearing out errors before the code is eval'ed.

-- hugh