Persistent Error 500

General support regarding TimeTrex, such as
configuring policies/taxes or processing payroll.
Post Reply
Two8nine
Posts: 16
Joined: Wed Aug 30, 2017 5:10 am

Persistent Error 500

Post by Two8nine » Fri Jan 19, 2018 1:56 pm

Hi, system has been issue free for us for a long time, but abruptly over the past couple days we've been getting constant "Error 500/Connection Lost" popups.

The issue started immediately following windows updates, though that could well be coincidental, as I've no evidence to connect them. The issue seems to happen at random, and once it starts it grows worse quickly. (To start closing the popup resumes normal function, after a while all you get is a solid grey screen.)

Rebooting the pc it's installed on is a temporary fix, but always less than a day before it starts up again.

The same could be said for a re-install, which completes ok, but the issue is always back after a few hours.

I've had a look at the log file titled 'timetrex' but don't know what to look for, so any thoughts or suggestions are appreciated.

Version: 11.1.2 (Was 11.1.0 when issue first occurred.)
Install OS: Windows 10 Profressional
Install Type: exe all in one installer.
Actions before issue occurs: Any (Occurs regardless of whether the system is 'in use' or not)
Additional Details: System is accessed over a local network by about 60 users, mix of Windows 10 and Windows 7, browsers may be Chrome, Firefox, or IE, issue occurs for all users, but not always at the same time.
Attachments
error500.png
error500.png (178.24 KiB) Viewed 2873 times

shanec
Posts: 390
Joined: Thu Apr 25, 2013 8:22 am

Re: Persistent Error 500

Post by shanec » Fri Jan 19, 2018 4:24 pm


Two8nine
Posts: 16
Joined: Wed Aug 30, 2017 5:10 am

Re: Persistent Error 500

Post by Two8nine » Tue Jan 23, 2018 7:49 am

Ok I've made the log file changes.

The issue has since re-occured, and I've includedthe portions flagged with 'error'. I can post the entire log file if preferred as well.

1. This occurs twice, though neither timestamp matches the point the issue occured (Observed at 8AM on Jan 23, was working at 6:45 AM)

DEBUG [L0251] [00062ms]: [Function](): Session ID: 9150c175b153d0de940ad56d172ab50a2b2c7d30 Source IP: 192.168.10.71
DEBUG [L0941] [00062ms]: Authentication::Check(): Session ID: 9150c175b153d0de940ad56d172ab50a2b2c7d30 IP Address: 192.168.10.71 URL: /api/json/api.php?Class=APIMisc&Method=getRawData&v=2&user_id=5632133e-106c-b7ef-54c6-000000000478&StationID=fae57de
DEBUG [L0941] [00062ms]: Authentication::Check(): 63e7554eb450a45fcc1805936&MessageID=3f3c2274-88df-2da1-1369-f94eb7b27258 Touch Updated Date: 1
DEBUG [L0255] [00064ms]: [Function](): SessionID set but user not authenticated!
DEBUG [L0429] [00064ms]: TTi18n::setLocale(): Set Master Locale To: en-CA
DEBUG [L0546] [00064ms]: TTi18n::chooseBestLocale(): Using Locale: en-CA
DEBUG [L0050] [00064ms]: unauthenticatedInvokeService(): Handling UNAUTHENTICATED JSON Call To API Factory: APIMisc Method: getRawData Message ID: 3f3c2274-88df-2da1-1369-f94eb7b27258
DEBUG [L0075] [00064ms]: unauthenticatedInvokeService(): Class: APIMisc does not exist! (unauth)
DEBUG [L0474] [00064ms] Array: APIFactory::returnHandler(): returnHandler v2 ERROR: 0
array(2) {
["api_retval"]=>
bool(false)
["api_details"]=>
array(7) {
["code"]=>
string(7) "SESSION"
["description"]=>
string(49) "Class APIMisc does not exist, or unauthenticat
ed."
["record_details"]=>
array(3) {
["total"]=>
int(0)
["valid"]=>
int(0)
["invalid"]=>
int(0)
}
["user_generic_status_batch_id"]=>
bool(false)

["request"]=>
bool(false)
["pager"]=>
bool(false)
["details"]=>
bool(false)
}
}

2. This occurs repeatedly, though doesn't coincide with any observed issues:

DEBUG [L0638] [00079ms]: APIAuthentication::getCompanyName(): Primary Company ID: 1
DEBUG [L0643] [00079ms]: APIAuthentication::getCompanyName(): ERROR: Primary Company does not exist!

3. This most closely matches the point the isue occured:

DEBUG [L0402] [00001ms]: [Function](): URI: /api/json/api.php?Class=APIUserGroup&Method=getUserGroup&v=2&StationID=6ac14c7dde397627b394f98924f6decd&MessageID=c90ff971-00e7-dc06-d297-6c7a0c15a47d IP Address: 192.168.10.101
DEBUG [L0404] [00001ms]: [Function](): USER-AGENT: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/63.0.3239.132 Safari/537.36
DEBUG [L0405] [00001ms]: [Function](): Version: 11.1.2 (PHP: v7.0.17) Edition: 10 Production: 1 Server: 192.168.10.72 OS: WIN Database: Type: postgres8 Name: timetrex Config: C:\TimeTrex\timetrex\includes\..\timetrex.ini.php Demo Mode: 0
DEBUG [L0192] [00141ms]: TTDate::setTimeZone(): Setting TimeZone: GMT
DEBUG [L0197] [00141ms]: [Function](): Handling JSON Call To API Factory: APIUserGroup Method: getUserGroup Message ID: c90ff971-00e7-dc06-d297-6c7a0c15a47d
DEBUG [L0240] [00141ms] Array: [Function](): Arguments: (Size: 63)
array(3) {
[0]=>
string(0) ""
[1]=>
bool(false)
[2]=>
bool(false)
}


DEBUG [L0251] [00142ms]: [Function](): Session ID: 5fe1e5a6f1229589227c9a6a4c64799c5ad298bb Source IP: 192.168.10.101
DEBUG [L0941] [00142ms]: Authentication::Check(): Session ID: 5fe1e5a6f1229589227c9a6a4c64799c5ad298bb IP Address: 192.168.10.101 URL: /api/json/api.php?Class=APIUserGroup&Method=getUserGroup&v=2&StationID=6ac14c7dde397627b394f98924f6decd&MessageID=c
DEBUG [L0941] [00142ms]: Authentication::Check(): 90ff971-00e7-dc06-d297-6c7a0c15a47d Touch Updated Date: 1
DEBUG [L0192] [00146ms]: TTDate::setTimeZone(): Setting TimeZone: CST6CDT
DEBUG [L0246] [00146ms]: TTDate::setDateFormat(): Setting Default Date Format: Y-m-d
DEBUG [L0264] [00146ms]: TTDate::setTimeFormat(): Setting Default Time Format: g:i A
DEBUG [L0282] [00146ms]: TTDate::setTimeUnitFormat(): Setting Default Time Unit Format: 10
DEBUG [L0095] [00147ms]: authenticatedInvokeService(): Locale Cookie: en-CA
DEBUG [L0103] [00147ms]: authenticatedInvokeService(): User Preference Language matches cookie!
DEBUG [L0429] [00148ms]: TTi18n::setLocale(): Set Master Locale To: en-CA
DEBUG [L0118] [00148ms]: authenticatedInvokeService(): Current User: admin (User ID: 5632133e-106c-b7ef-54c6-000000000002) Company: Midwest Teleservices International (Company ID: 5632133e-106c-b7ef-54c6-000000000002)
DEBUG [L0228] [00160ms] Array: APIFactory::initializeFilterAndPager(): ERROR: Input data is not an array:
string(0) ""


DEBUG [L0137] [00184ms]: APIUserGroup::getUserGroup(): Record Count: 1
DEBUG [L0049] [00193ms]: TTTree::FormatArray(): Formatting Array...
DEBUG [L0269] [00194ms]: [Function](): Server Response Time: 0.19327592849731

4 -- Lastly, there are multiple cases of this message, which are timestamped at a future time? (Log pulled at 8AM)


---------------[ 23-Jan-2018 13:41:02 +0000 [1516714860.9519] (PID: 11424) ]---------------
DEBUG [L0402] [00002ms]: [Function](): URI: /api/json/api.php?Class=APIAuthentication&Method=Login&v=2&StationID=bcaa0fcab1b21a22755491a3170565da&MessageID=f3f987ed-a433-9a0c-ee80-14c92e4d7057 IP Address: ::1
DEBUG [L0404] [00002ms]: [Function](): USER-AGENT: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/63.0.3239.132 Safari/537.36
DEBUG [L0405] [00002ms]: [Function](): Version: 11.1.2 (PHP: v7.0.17) Edition: 10 Production: 1 Server: ::1 OS: WIN Database: Type: postgres8 Name: timetrex Config: C:\TimeTrex\timetrex\includes\..\timetrex.ini.php Demo Mode: 0
DEBUG [L0192] [00081ms]: TTDate::setTimeZone(): Setting TimeZone: GMT
DEBUG [L0197] [00082ms]: [Function](): Handling JSON Call To API Factory: APIAuthentication Method: Login Message ID: f3f987ed-a433-9a0c-ee80-14c92e4d7057
DEBUG [L0238] [00082ms] Array: [Function](): *Censored* Arguments: (Size: 63)
string(5) "admin"


DEBUG [L0262] [00083ms]: [Function](): No SessionID or calling non-authenticated function...
DEBUG [L0429] [00084ms]: TTi18n::setLocale(): Set Master Locale To: en-CA
DEBUG [L0546] [00084ms]: TTi18n::chooseBestLocale(): Using Locale: en-CA
DEBUG [L0050] [00084ms]: unauthenticatedInvokeService(): Handling UNAUTHENTICATED JSON Call To API Factory: APIAuthentication Method: Login Message ID: f3f987ed-a433-9a0c-ee80-14c92e4d7057
DEBUG [L0176] [00084ms]: APIAuthentication::Login(): User Name: admin Password Length: 12 Type: USER_NAME
DEBUG [L0761] [00084ms]: Authentication::Login(): Login Type: user_name
DEBUG [L1055] [00092ms]: Authentication::checkCompanyStatus(): Company Status: 10
DEBUG [L0790] [00093ms]: UserFactory::checkPassword(): LDAP authentication is not enabled...
DEBUG [L0883] [00093ms]: Authentication::Login(): Login Failed! Attempt: 2
DEBUG [L0790] [01103ms]: UserFactory::checkPassword(): LDAP authentication is not enabled...
DEBUG [L1173] [01103ms]: Validator::Error(): Validation Error: Label: user_name Value: "0" Msg: User Name or Password is incorrect
DEBUG [L0474] [01103ms] Array: APIFactory::returnHandler(): returnHandler v2 ERROR: 0
array(2) {
["api_retval"]=>
bool(false)
["api_details"]=>
array(7) {
["code"]=>
string(10) "VALIDATION"
["description"]=>
string(12) "INVALID DATA"
["record_details"]=>

array(3) {
["total"]=>
int(1)
["valid"]=>
int(0)
["invalid"]=>
int(1)
}
["user_generic_status_batch_id"]=>
bool(false)
["request"]=>
bool(false
)
["pager"]=>
bool(false)
["details"]=>
array(1) {
[0]=>
array(1) {
["user_name"]=>
array(1) {
[0]=>
string(34) "User Name or Password i
s incorrect"
}
}
}
}
}


DEBUG [L0126] [01104ms]: ProgressBar::start(): start: 'f3f987ed-a433-9a0c-ee80-14c92e4d7057' Iterations: 9999 Update Iterations: 9999 Key: f3f987ed-a433-9a0c-ee80-14c92e4d7057(1516714862.0551) Message: INVALID DATA
DEBUG [L0269] [01108ms]: [Function](): Server Response Time: 1.1078279018402
---------------[ 23-Jan-2018 13:41:02 +0000 [1516714862.0597] (PID: 11424) ]---------------

shaunw
Posts: 7483
Joined: Tue Sep 19, 2006 2:22 pm

Re: Persistent Error 500

Post by shaunw » Tue Jan 23, 2018 10:27 am

To fix this error:

Code: Select all

ERROR: Primary Company does not exist!
You need to edit your timetrex.ini.php and change the "primary_company_id" line to:

Code: Select all

primary_company_id = 5632133e-106c-b7ef-54c6-000000000002
The reason you may be seeing timestamps in the future is likely simply due to a timezone difference, which you can of course set in your timetrex.ini.php file as well.

Two8nine
Posts: 16
Joined: Wed Aug 30, 2017 5:10 am

Re: Persistent Error 500

Post by Two8nine » Fri Jan 26, 2018 7:32 am

Thanks for the response.

I changed the company ID, and all seemed well for a couple days.

The error came back this morning, and I checked the log file and see the company id is right back to '1' (Confirmed in the timetrex.ini file.)

At a loss as to why it keeps changing -- any thoughts?

shaunw
Posts: 7483
Joined: Tue Sep 19, 2006 2:22 pm

Re: Persistent Error 500

Post by shaunw » Fri Jan 26, 2018 8:43 am

We would need to see your entire log file for the days between when you made the change to your .ini and now.

Two8nine
Posts: 16
Joined: Wed Aug 30, 2017 5:10 am

Re: Persistent Error 500

Post by Two8nine » Wed Jan 31, 2018 7:52 am

Just to be contentious the problem abruptly went away for a few days, but has returned this morning at around 8AM. I've attached the full log for the day if that helps.

Lots of this:

DEBUG [L0474] [00064ms] Array: APIFactory::returnHandler(): returnHandler v2 ERROR: 0
array(2) {
["api_retval"]=>
bool(false)
["api_details"]=>
array(7) {
["code"]=>
string(7) "SESSION"
["description"]=>
string(49) "Class APIMisc does not exist, or unauthenticat
ed."
["record_details"]=>
array(3) {
["total"]=>
int(0)
["valid"]=>
int(0)
["invalid"]=>
int(0)
}
["user_generic_status_batch_id"]=>
bool(false)

["request"]=>
bool(false)
["pager"]=>
bool(false)
["details"]=>
bool(false)
}
}
Attachments
timetrex.log
(14.03 MiB) Downloaded 58 times

shaunw
Posts: 7483
Joined: Tue Sep 19, 2006 2:22 pm

Re: Persistent Error 500

Post by shaunw » Wed Jan 31, 2018 4:38 pm

This error in the logs:

Code: Select all

Class APIMisc does not exist, or unauthenticated.
Seems to be related to someone trying to import data after their session has timed out. Which seems a little strange to me.

I'm also still seeing the original error message as of January 31st, so it hasn't been corrected either:

Code: Select all

ERROR: Primary Company does not exist!
None of these errors should actually be causing an internal server error though. For that I think you will need to check your Apache/PHP error logs for more information.

Two8nine
Posts: 16
Joined: Wed Aug 30, 2017 5:10 am

Re: Persistent Error 500

Post by Two8nine » Wed Jan 31, 2018 7:49 pm

Much appreciated.

Not sure how much it matters, but both apache and php are installed within the timetrex dir. (Installed via all in one exe.) I've edited the php.ini file within timetrex to log errors to the same directory timetrex does, but (so far) no errors have been logged.

Apache on the other hand has loads. Particularly this: AH00558: httpd.exe: Could not reliably determine the server's fully qualified domain name, using fe80::fc3a:dac9:1051:9e58. Set the 'ServerName' directive globally to suppress

Is that part of my issue?

I've attached the full apache log if it helps.
Attachments
error.log
(5.08 MiB) Downloaded 57 times

shaunw
Posts: 7483
Joined: Tue Sep 19, 2006 2:22 pm

Re: Persistent Error 500

Post by shaunw » Thu Feb 01, 2018 9:30 am

I see many errors like this in your Apache log:

Code: Select all

[Wed Jan 31 14:09:50.327319 2018] [fcgid:warn] [pid 3228:tid 2620] (OS 109)The pipe has been ended.  : [client 192.168.10.48:50142] mod_fcgid: get overlap result error, referer: http://192.168.10.72:8085/interface/html5/
[Wed Jan 31 14:09:50.327319 2018] [core:error] [pid 3228:tid 2620] [client 192.168.10.48:50142] End of script output before headers: api.php, referer: http://192.168.10.72:8085/interface/html5/
[Wed Jan 31 14:09:50.327319 2018] [fcgid:warn] [pid 3228:tid 2808] (OS 109)The pipe has been ended.  : [client 192.168.10.48:50134] mod_fcgid: get overlap result error, referer: http://192.168.10.72:8085/interface/html5/
[Wed Jan 31 14:09:50.327319 2018] [core:error] [pid 3228:tid 2808] [client 192.168.10.48:50134] End of script output before headers: api.php, referer: http://192.168.10.72:8085/interface/html5/
[Wed Jan 31 14:09:50.358572 2018] [fcgid:warn] [pid 3228:tid 2656] (OS 109)The pipe has been ended.  : [client 192.168.10.48:50136] mod_fcgid: get overlap result error, referer: http://192.168.10.72:8085/interface/html5/
[Wed Jan 31 14:09:50.358572 2018] [core:error] [pid 3228:tid 2656] [client 192.168.10.48:50136] End of script output before headers: api.php, referer: http://192.168.10.72:8085/interface/html5/
[Wed Jan 31 14:10:07.425475 2018] [fcgid:warn] [pid 3228:tid 2544] (OS 109)The pipe has been ended.  : [client 192.168.10.44:50069] mod_fcgid: get overlap result error, referer: http://192.168.10.72:8085/interface/html5/
If you check your Windows event viewer, do you see any Apache/PHP crash/error events?

My best guess is that Apache or PHP is crashing, which is causing the internal server error.

Two8nine
Posts: 16
Joined: Wed Aug 30, 2017 5:10 am

Re: Persistent Error 500

Post by Two8nine » Wed Feb 07, 2018 11:45 am

There are indeed.

Crashes are accompanied by this error in event viewer:

Faulting application name: php-win.exe, version: 7.0.17.0, time stamp: 0x58c8834f
Faulting module name: ntdll.dll, version: 10.0.16299.192, time stamp: 0x16e7ff7f
Exception code: 0xc0000409
Fault offset: 0x00089d10
Faulting process id: 0x58c
Faulting application start time: 0x01d39f20a0f12f00
Faulting application path: C:\TimeTrex\php\php-win.exe
Faulting module path: C:\WINDOWS\SYSTEM32\ntdll.dll
Report Id: dba48812-3287-4fb0-a1ce-359daa3e7fea
Faulting package full name:
Faulting package-relative application ID:

There are multiple 'process id's that fail, but the rest of the fault message is the same.

shaunw
Posts: 7483
Joined: Tue Sep 19, 2006 2:22 pm

Re: Persistent Error 500

Post by shaunw » Wed Feb 07, 2018 12:38 pm

There is definitely some instability with your system or a combination of the installed software libraries then, as PHP should never be crashing like that. Is your windows installation 32bit or 64bit?

Unfortunately trying to narrow down such crashes can be extremely difficult, here a few things I would try first though:

1. Make sure you have installed all windows updates.

2. If you have a virus scanner installed, try disabling it for a while to see if that helps at all.

3. Try disabling "opcache" in your php.ini file. It will greatly slow things down, but if the crashing stops it at least helps narrow down the culprit.

Two8nine
Posts: 16
Joined: Wed Aug 30, 2017 5:10 am

Re: Persistent Error 500

Post by Two8nine » Wed Feb 07, 2018 12:50 pm

Much appreciated.

PC is windows 10 64 bit.

All updates are installed, however, this issue started immediately following a major windows update -- so while I have my doubts the update itself is responsible. (Since no one else is reporting the issue) But it may well be that the root of the issue is there.

I had temporarily disabled the anitvirus, but unfortunately the issue kept happening.

I'll make the php changes and see what happens.

brianoneal
Posts: 15
Joined: Fri Apr 13, 2018 9:01 am

Re: Persistent Error 500

Post by brianoneal » Thu May 31, 2018 1:46 pm

We had the same problem for many days. We run a script that deletes old tmp files in our Windows\temp folder daily at midnight. I noticed the cache file: ZendOPcache.MemoryBase@SYSTEM@65b2f8f07d5af2583a329bf4132cf6a9 was being deleted along with the temp files and we'd have the ERROR 500. Havent seen the ERROR 500 since changing our script to exclude deleting this file.

mikeb
Posts: 545
Joined: Thu Jul 27, 2006 11:58 am

Re: Persistent Error 500

Post by mikeb » Fri Nov 23, 2018 12:26 pm

Can you try installing both of the following Microsoft Visual C++ Redistributable packages to see if that makes any difference:

https://aka.ms/vs/15/release/VC_redist.x86.exe
https://aka.ms/vs/15/release/VC_redist.x64.exe
TimeTrex Community Edition is developed and supported by volunteers.
Help motivate us to continue by showing your appreciation!

Post Reply