How to analyse System Logs?

[Emediate]

We finally updated to PHP8 and latest Invision this week after delays with app/plugin updates.

We have a repeating error showing up in the System Logs, and despite wanting to get to the bottom of it, it also made curious on how Support and other knowledgable Invision admins decipher what's going on from System Logs. Can anyone give me some basic guidance on what to make of this, and what to look for when looking at System Logs please?

Quote

The log entry was triggered by a guest (Guests)

Quote

Error: Failed opening required '/home/stereoglobal/public_html/forums/datastore/widget_activeUsers_uyk4g99lq_37a49db4f1b3f9f667205f1c460f38c0.462e267699.php' (include_path='.:/opt/cpanel/ea-php80/root/usr/share/pear') (0)
#0 /home/stereoglobal/public_html/forums/system/Data/Store/FileSystem.php(178): IPS\Data\Store\_FileSystem->get('widget_activeUs...')
#1 /home/stereoglobal/public_html/forums/system/Data/AbstractData.php(126): IPS\Data\Store\_FileSystem->exists('widget_activeUs...')
#2 /home/stereoglobal/public_html/forums/system/Data/Store.php(303): IPS\Data\_AbstractData->__isset('widget_activeUs...')
#3 /home/stereoglobal/public_html/forums/system/Widget/Widget.php(904): IPS\Data\_Store->__isset('widget_activeUs...')
#4 /home/stereoglobal/public_html/forums/system/Theme/Theme.php(885) : eval()'d code(18944): IPS\_Widget->__toString()
#5 /home/stereoglobal/public_html/forums/system/Theme/SandboxedTemplate.php(61): IPS\Theme\class_core_front_global->widgetContainer('footer', 'horizontal')
#6 /home/stereoglobal/public_html/forums/system/Theme/Theme.php(885) : eval()'d code(6835): IPS\Theme\_SandboxedTemplate->__call('widgetContainer', Array)
#7 /home/stereoglobal/public_html/forums/system/Theme/SandboxedTemplate.php(61): IPS\Theme\class_core_front_global->globalTemplate('taming treble -...', '\n\n\n<div class="...', Array)
#8 /home/stereoglobal/public_html/forums/system/Dispatcher/Dispatcher.php(173): IPS\Theme\_SandboxedTemplate->__call('globalTemplate', Array)
#9 /home/stereoglobal/public_html/forums/system/Dispatcher/Standard.php(113): IPS\_Dispatcher->finish()
#10 /home/stereoglobal/public_html/forums/system/Dispatcher/Front.php(558): IPS\Dispatcher\_Standard->finish()
#11 /home/stereoglobal/public_html/forums/system/Dispatcher/Dispatcher.php(155): IPS\Dispatcher\_Front->finish()
#12 /home/stereoglobal/public_html/forums/index.php(13): IPS\_Dispatcher->run()
#13 {main}

Backtrace

Quote

#0 /home/stereoglobal/public_html/forums/init.php(1029): IPS\_Log::log('Error: Failed o...', 'uncaught_except...')
#1 /home/stereoglobal/public_html/forums/system/Widget/Widget.php(939): IPS\IPS::exceptionHandler(Object(Error))
#2 /home/stereoglobal/public_html/forums/system/Theme/Theme.php(885) : eval()'d code(18944): IPS\_Widget->__toString()
#3 /home/stereoglobal/public_html/forums/system/Theme/SandboxedTemplate.php(61): IPS\Theme\class_core_front_global->widgetContainer('footer', 'horizontal')
#4 /home/stereoglobal/public_html/forums/system/Theme/Theme.php(885) : eval()'d code(6835): IPS\Theme\_SandboxedTemplate->__call('widgetContainer', Array)
#5 /home/stereoglobal/public_html/forums/system/Theme/SandboxedTemplate.php(61): IPS\Theme\class_core_front_global->globalTemplate('taming treble -...', '\n\n\n<div class="...', Array)
#6 /home/stereoglobal/public_html/forums/system/Dispatcher/Dispatcher.php(173): IPS\Theme\_SandboxedTemplate->__call('globalTemplate', Array)
#7 /home/stereoglobal/public_html/forums/system/Dispatcher/Standard.php(113): IPS\_Dispatcher->finish()
#8 /home/stereoglobal/public_html/forums/system/Dispatcher/Front.php(558): IPS\Dispatcher\_Standard->finish()
#9 /home/stereoglobal/public_html/forums/system/Dispatcher/Dispatcher.php(155): IPS\Dispatcher\_Front->finish()
#10 /home/stereoglobal/public_html/forums/index.php(13): IPS\_Dispatcher->run()
#11 {main}

Thanks in advance!

[Marc Stridgen]

Go to Support in the admin CP and click to clear cache. That will empty the datastore folder, so if there are issues in there, it should stop happening. It does look to be an issue with a specific file in there

[Emediate]

Thanks Marc. I still would love a little guidance on deciphering System Logs though.

I'm in the middle of moving storage to Amazon S3. Safe to clear cache while that process is happening?

[Marc Stridgen]

13 minutes ago, Emediate said:

Thanks Marc. I still would love a little guidance on deciphering System Logs though.

Im not sure what guideance you are looking for there. This is PHP code. There isnt really any way for me to teach you how to decipher them, other than to say you should always try to disable 3rd party items to resolve the issue, and should always clear the cache to see if that resolves the issue. Other than that, its actually knowing how to read code. 

15 minutes ago, Emediate said:

I'm in the middle of moving storage to Amazon S3. Safe to clear cache while that process is happening?

Yes you can clear cache

[Randy Calvert]

What you’re looking at in the output was the order of execution. Basically a list of steps that were performed before an error occurred. The most recent events are on top. 

In this case the “error failed to open required” says the script was trying to load a cached theme file (specifically for the active user widget) but that it was not found. 

As theme files can be generated on demand by clearing the system cache, a new set of theme files are generated. 

Generally these types of errors are good for helping point you in a general direction. If you see references to things outside of the core IPB software such as hooks or 3rd party applications, you can discover if they’re interfering etc. Or in this case that it was a simple theme issue. 

[Emediate]

That's great, thanks @Randy Calvert - appreciate it.

How does the Backtrace come into it?

[Emediate]

53 minutes ago, Marc Stridgen said:

Go to Support in the admin CP and click to clear cache. That will empty the datastore folder, so if there are issues in there, it should stop happening. It does look to be an issue with a specific file in there

Did this, but the same error returns again.

[Marc Stridgen]

18 minutes ago, Emediate said:

That's great, thanks @Randy Calvert - appreciate it.

How does the Backtrace come into it?

Backtrace is tracing back through the code to what was executed before it

12 minutes ago, Emediate said:

Did this, but the same error returns again.

This being the case, it looks like PHP8 is having issues with opening items in that folder. Check permissions on that. For example it may be its running suPHP where before it wasnt. Only your host can confirm this.

[Emediate]

Thanks Marc. Points me in the right direction.

[Emediate]

15 hours ago, Marc Stridgen said:

This being the case, it looks like PHP8 is having issues with opening items in that folder. Check permissions on that. For example it may be its running suPHP where before it wasnt. Only your host can confirm this.

Spoke to hosts about this.

Quote

We do run suPHP on your server but all PHP versions use it so the software has the same access as it did on the previous PHP version.

I can see that files have been written to the datastore folder as recent as 3 minutes ago so the software definitely can write to the datastore folder.

I can't think of any reason why that error would be generated if that file did exist. I did have a quick look for that exact file and it doesn't exist but I'm not sure if that's because the software deleted it.

Clearing cache doesn't solve it, and the errors are anywhere between every 15 and 60 mins.

[Marc Stridgen]

I would wait to see what your host comes back with first of all.

[Emediate]

That was what the hosts came back with. 

[Marc Stridgen]

31 minutes ago, Emediate said:

That was what the hosts came back with. 

Ah sorry, my confusion. While I understand what they are saying there, something is causing issues with permissions there unfortunately. The only thing that has indeed changed is the PHP version on the hosting. Check if its 777 on that folder. If it is, try setting it to 644 and empty the folder. See if that works for you

[Emediate]

Did that. But getting this now:

Have changed permissions back to 777. Hasn't made the above go away though. 
Any advice?

[Emediate]

Seems to have cleared itself up now. Thanks again.

[Marc Stridgen]

Excellent. Glad to hear that 🙂 

[Emediate]

The original problem is back again. It stopped for around 12 hours after clearing the datastore, but is now recording the same error 1-2 times an hour. Any other suggestions?

[Jim M]

Is it still a "Error: Failed opening required" message that you're seeing?

If so, this sounds like a permissions or corrupted/faulty file issue potentially. Especially if clearing the datastore for a period of time is clearing the issue then an action on your server presents itself and the error triggers again. This could be an issue with your storage device, reading/writing to that storage device, permissions, etc...

While not really a long-term solution, you can temporarily switch your datastore to be stored in the database to see if this helps resolve this issue. If it does, it would be something you need to talk with your hosting provider about.

To switch your datastore to database, go to ACP -> System -> Advanced Configuration -> Data storage.

[Emediate]

Could it be related at all to moving data storage (for attachments) to Amazon S3? That's been processing for 2.5 days (~80% complete). 

1 hour ago, Jim M said:

Is it still a "Error: Failed opening required" message that you're seeing?

 

Yes:

Quote

Error: Failed opening required '/home/stereoglobal/public_html/forums/datastore/widget_activeUsers_uyk4g99lq_de661042d0179da51cc434f8e544d565.462e267699.php' (include_path='.:/opt/cpanel/ea-php80/root/usr/share/pear') (0)

 

[Jim M]

5 minutes ago, Emediate said:

Could it be related at all to moving data storage (for attachments) to Amazon S3? That's been processing for 2.5 days (~80% complete). 

Yes:

 

No that wouldn’t be related as this is with the datastore. Unless it’s over powering your server to the point where it’s having trouble reading/writing. Ultimately, something we can’t answer. 

[Emediate]

Thanks, @Jim M - it doesn't seem to be causing any performance issues that I can tell. I'll let this process complete, clear the logs, cache and the datastore again, and then reassess. Thanks for your input 🙂

[Emediate]

On 12/17/2022 at 7:02 AM, Jim M said:

Is it still a "Error: Failed opening required" message that you're seeing?

If so, this sounds like a permissions or corrupted/faulty file issue potentially. Especially if clearing the datastore for a period of time is clearing the issue then an action on your server presents itself and the error triggers again. This could be an issue with your storage device, reading/writing to that storage device, permissions, etc...

While not really a long-term solution, you can temporarily switch your datastore to be stored in the database to see if this helps resolve this issue. If it does, it would be something you need to talk with your hosting provider about.

To switch your datastore to database, go to ACP -> System -> Advanced Configuration -> Data storage.

Before I investigate switching the datastore to the database, coming back to the original issue, which still exists ...

1. We have cleared the cache
2. We have emptied the datastore and reset the permissions
3. The exact same file "failed opening ..." comes back instantly.

Reluctant to consider it a permissions error or some other problem on our end given the system is writing all other files and filling up the datastore quickly again with no other issues.

It's this one particular file it's not happy about, and I can confirm this file does not exist on the server.

Any other advice?

[Randy Calvert]

There could be a bunch of things but all not associated with the software. (Disk fragmentation, i/o limitations if using a vps, inode issues, etc.)

I would just suggest not writing to disk if it’s problematic for you.  

[Emediate]

Why would the above apply to just one file of many in the datastore, and not affect any others?

Are you suggesting using the database rather than the datastore directory? What are the pros/cons of this? We've never written to the database.

[Randy Calvert]

It could be when the files are written, it could be where on the hard drive the files are written, it could be based on other I/O limits if using a VPS… 

Basically IPS is trying to write a file and it fails. That’s a system issue with SOMETHING either in your system config or hardware. You can troubleshoot it yourself if you like but as it’s not a software issue, there is not a lot that can be done from here. 

The majority of people are fine using the DB as a datastore.  It adds a little extra DB load but nothing significant. I’ve used it for years without issue. (I used it originally because I was load balancing requests between servers and did not want to deal with the datastore across multiple machines.)