Admin vhost intermittent 500 error (FreeBSD)

R

raphidae

Well-Known Member
#1
#1
Hi,

I recently upgraded to 4.2.9 and just to 4.2.10, and since the upgrade to 4.2.9 the admin site has been erratic. Around 1 in 5 page requests results in a 500 error (it works again when refreshing the same page/resubmitting the form). The following is logged:
i
Code: 
2014-05-07 05:59:31.007 [INFO] [PHP5-somevhost.example.com] PID: 5402, add child process pid: 5496, procinfo: 0x840c8c0
2014-05-07 06:00:00.095 [INFO] [AdminPHP] PID: 5402, add child process pid: 5512, procinfo: 0x840cac0
2014-05-07 06:00:00.098 [INFO] [46.12.34.56:57516-0#_AdminVHost] PID: 5402, add child process pid: 5513, procinfo: 0x840cac0
2014-05-07 06:00:00.100 [INFO] [46.12.34.56:57516-0#_AdminVHost] PID: 5402, add child process pid: 5514, procinfo: 0x840cac0
2014-05-07 06:00:00.103 [INFO] [46.12.34.56:57516-0#_AdminVHost] PID: 5402, add child process pid: 5515, procinfo: 0x840cac0
2014-05-07 06:00:00.105 [INFO] [46.12.34.56:57516-0#_AdminVHost] PID: 5402, add child process pid: 5516, procinfo: 0x840cac0
2014-05-07 06:00:00.106 [INFO] [46.12.34.56:57516-0#_AdminVHost] abort request..., code: 4 
2014-05-07 06:00:00.106 [INFO] [46.12.34.56:57516-0#_AdminVHost] Abort request processing by PID:5516, kill: 1, begin time: 0, sent time: 1399435200, req processed: 0
2014-05-07 06:00:01.000 [INFO] [CLEANUP] Send signal: 30 to process: 5516
2014-05-07 06:00:03.615 [INFO] [46.12.34.56:57517-1#_AdminVHost] PID: 5402, add child process pid: 5596, procinfo: 0x840cac0
2014-05-07 06:00:35.999 [INFO] [CLEANUP] Send signal: 30 to process: 5496
2014-05-07 06:00:36.003 [INFO] Remove pid: 5496, exitcode: 160
2014-05-07 06:00:59.630 [INFO] [PHP5-someothervhost.example.net] PID: 5402, add child process pid: 6752, procinfo: 0x8465200
2014-05-07 06:02:54.421 [INFO] [46.12.34.56:57563-0#_AdminVHost] PID: 5402, add child process pid: 6848, procinfo: 0x840cac0
2014-05-07 06:02:54.424 [INFO] [46.12.34.56:57563-0#_AdminVHost] PID: 5402, add child process pid: 6849, procinfo: 0x840cac0
2014-05-07 06:02:54.426 [INFO] [46.12.34.56:57563-0#_AdminVHost] PID: 5402, add child process pid: 6851, procinfo: 0x840cac0
2014-05-07 06:02:54.429 [INFO] [46.12.34.56:57563-0#_AdminVHost] PID: 5402, add child process pid: 6852, procinfo: 0x840cac0
2014-05-07 06:02:54.429 [INFO] [46.12.34.56:57563-0#_AdminVHost] abort request..., code: 4 
2014-05-07 06:02:54.429 [INFO] [46.12.34.56:57563-0#_AdminVHost] Abort request processing by PID:6852, kill: 1, begin time: 0, sent time: 159, req processed: 0
2014-05-07 06:02:54.999 [INFO] [CLEANUP] Send signal: 30 to process: 6852
2014-05-07 06:03:03.207 [INFO] [46.12.34.56:57564-0#_AdminVHost] PID: 5402, add child process pid: 6865, procinfo: 0x840cac0
2014-05-07 06:03:05.999 [INFO] [CLEANUP] Send signal: 30 to process: 6752
2014-05-07 06:03:06.003 [INFO] Remove pid: 6752, exitcode: 160
somevhost.example.com:80, someothervhost.example.net:80 and AdminVHost:280 are different listeners, and afaik the PHP compiled for the vhosts is a different one from the PHP serving the admin site. The vhosts don't have an issue with PHP.

Please advise.
 
R

raphidae

Well-Known Member
#3
#3
Code: 
2014-05-07 22:16:25.580 [DEBUG] [217.1.2.3:280] HttpListener::handleEvents(), fd: 14, event: 1, revents: 1.
2014-05-07 22:16:25.580 [DEBUG] [217.1.2.3:280] New connection from 46.12.34.56:52361.
2014-05-07 22:16:25.580 [DEBUG] [46.12.34.56:52361-0] concurrent conn: 1
2014-05-07 22:16:25.580 [DEBUG] [217.1.2.3:280] 1 connections accepted!
2014-05-07 22:16:25.580 [DEBUG] [46.12.34.56:52361-0] HttpIOLink::handleEvents() events=1!
2014-05-07 22:16:25.580 [DEBUG] [46.12.34.56:52361-0] HttpConnection::onReadEx(), state: 0!
2014-05-07 22:16:25.580 [DEBUG] [46.12.34.56:52361-0] readToHeaderBuf(). 
2014-05-07 22:16:25.580 [DEBUG] [46.12.34.56:52361-0] Read from client: 621
2014-05-07 22:16:25.580 [DEBUG] [46.12.34.56:52361-0] read 621 bytes to header buffer
2014-05-07 22:16:25.580 [DEBUG] [46.12.34.56:52361-0] processHeader() return 0, header state: 3. 
2014-05-07 22:16:25.580 [DEBUG] [46.12.34.56:52361-0] readToHeaderBuf() return 0. 
2014-05-07 22:16:25.580 [NOTICE] [46.12.34.56:52361-0#_AdminVHost] Content len: 0, Request line: 'GET /config/confMgr.php?m=serv HTTP/1.1'
2014-05-07 22:16:25.580 [INFO] [46.12.34.56:52361-0#_AdminVHost] Cookie len: 127, template=classic_black; lng=en; LSWSWEBUI=xxx; lsws_uid=xxx; lsws_pass=xxx
2014-05-07 22:16:25.580 [DEBUG] [46.12.34.56:52361-0#_AdminVHost] Find context with URI: [/], location: [/usr/local/lsws/admin/html/]
2014-05-07 22:16:25.580 [DEBUG] [46.12.34.56:52361-0#_AdminVHost] Check Symbolic link for [/usr/local/lsws/admin/html/config/confMgr.php] is successful, access to target [/usr/local/lsws/admin/html.4.2.10/config/confMgr.php] is granted
2014-05-07 22:16:25.580 [DEBUG] [46.12.34.56:52361-0#_AdminVHost] Find handler [AdminPHP] for [.php]
2014-05-07 22:16:25.581 [DEBUG] [46.12.34.56:52361-0#_AdminVHost] processContextPath() return 0
2014-05-07 22:16:25.581 [DEBUG] [46.12.34.56:52361-0#_AdminVHost] run lsapi processor.
2014-05-07 22:16:25.581 [DEBUG] [UDS://tmp/lshttpd/admin_php.sock] create new connection succeed!
2014-05-07 22:16:25.581 [DEBUG] [UDS://tmp/lshttpd/admin_php.sock] request [46.12.34.56:52361-0#_AdminVHost:lsapi] is assigned with connection [0x8414000]!
2014-05-07 22:16:25.581 [DEBUG] [46.12.34.56:52361-0#_AdminVHost:lsapi] [ExtConn] reconnect()
2014-05-07 22:16:25.581 [INFO] Start listen socket [/tmp/lshttpd/admin_php.sock].
2014-05-07 22:16:25.583 [INFO] [AdminPHP] pid list size: 1 
2014-05-07 22:16:25.583 [INFO] [AdminPHP] PID: 50041, add child process pid: 50118, procinfo: 0x8406880
2014-05-07 22:16:25.583 [INFO] Pid: 50118 associated with [AdminPHP]
2014-05-07 22:16:25.583 [INFO] ProcInfo Pid: 50118, socket: /tmp/lshttpd/admin_php.sock 
2014-05-07 22:16:25.584 [INFO] Start listen socket [/tmp/lshttpd/admin_php.sock].
2014-05-07 22:16:25.586 [INFO] [AdminPHP] pid list size: 2 
2014-05-07 22:16:25.586 [INFO] [46.12.34.56:52361-0#_AdminVHost:lsapi] PID: 50041, add child process pid: 50119, procinfo: 0x8406880
2014-05-07 22:16:25.586 [DEBUG] [46.12.34.56:52361-0#_AdminVHost:lsapi] [ExtConn] reconnect()
2014-05-07 22:16:25.586 [INFO] Pid: 50119 associated with [AdminPHP]
2014-05-07 22:16:25.586 [INFO] ProcInfo Pid: 50119, socket: /tmp/lshttpd/admin_php.sock 
2014-05-07 22:16:25.586 [INFO] Start listen socket [/tmp/lshttpd/admin_php.sock].
2014-05-07 22:16:25.588 [INFO] [AdminPHP] pid list size: 3 
2014-05-07 22:16:25.589 [INFO] [46.12.34.56:52361-0#_AdminVHost:lsapi] PID: 50041, add child process pid: 50120, procinfo: 0x8406880
2014-05-07 22:16:25.589 [DEBUG] [46.12.34.56:52361-0#_AdminVHost:lsapi] [ExtConn] reconnect()
2014-05-07 22:16:25.589 [INFO] Pid: 50120 associated with [AdminPHP]
2014-05-07 22:16:25.589 [INFO] ProcInfo Pid: 50120, socket: /tmp/lshttpd/admin_php.sock 
2014-05-07 22:16:25.589 [INFO] Start listen socket [/tmp/lshttpd/admin_php.sock].
2014-05-07 22:16:25.591 [INFO] [AdminPHP] pid list size: 4 
2014-05-07 22:16:25.591 [INFO] [46.12.34.56:52361-0#_AdminVHost:lsapi] PID: 50041, add child process pid: 50121, procinfo: 0x8406880
2014-05-07 22:16:25.591 [DEBUG] [46.12.34.56:52361-0#_AdminVHost:lsapi] [ExtConn] reconnect()
2014-05-07 22:16:25.591 [INFO] Pid: 50121 associated with [AdminPHP]
2014-05-07 22:16:25.591 [INFO] ProcInfo Pid: 50121, socket: /tmp/lshttpd/admin_php.sock 
2014-05-07 22:16:25.591 [DEBUG] [46.12.34.56:52361-0#_AdminVHost:lsapi] HttpIOLink::continueWrite()...
2014-05-07 22:16:25.591 [DEBUG] [46.12.34.56:52361-0#_AdminVHost:lsapi] write resumed!
2014-05-07 22:16:25.591 [INFO] [AdminPHP] pid list size: 3, pid stop list size: 0
2014-05-07 22:16:25.594 [INFO] [AdminPHP] pid list size: 4 
2014-05-07 22:16:25.594 [INFO] [46.12.34.56:52361-0#_AdminVHost:lsapi] PID: 50041, add child process pid: 50122, procinfo: 0x8406880
2014-05-07 22:16:25.594 [DEBUG] [46.12.34.56:52361-0#_AdminVHost:lsapi] [ExtConn] connecting to [UDS://tmp/lshttpd/admin_php.sock]...
2014-05-07 22:16:25.594 [DEBUG] [46.12.34.56:52361-0#_AdminVHost:lsapi] ExtConn::onWrite()
2014-05-07 22:16:25.594 [DEBUG] [46.12.34.56:52361-0#_AdminVHost:lsapi] ExtConn::suspendWrite()
2014-05-07 22:16:25.594 [INFO] [AdminPHP] pid list size: 3, pid stop list size: 0
2014-05-07 22:16:25.594 [INFO] [AdminPHP] pid list size: 2, pid stop list size: 0
2014-05-07 22:16:25.594 [INFO] [AdminPHP] pid list size: 1, pid stop list size: 0
2014-05-07 22:16:25.594 [DEBUG] [46.12.34.56:52361-0#_AdminVHost:lsapi] processNewReq() return 0. 
2014-05-07 22:16:25.594 [DEBUG] [46.12.34.56:52361-0#_AdminVHost:lsapi] HttpIOLink::handleEvents() events=4!
2014-05-07 22:16:25.594 [DEBUG] [46.12.34.56:52361-0#_AdminVHost:lsapi] HttpIOLink::suspendWrite()...
2014-05-07 22:16:25.594 [DEBUG] [46.12.34.56:52361-0#_AdminVHost:lsapi] HttpConnection::sendHttpError(),code=500 Internal Server Error
2014-05-07 22:16:25.594 [DEBUG] [46.12.34.56:52361-0#_AdminVHost:lsapi] HttpConnection::flush()!
2014-05-07 22:16:25.594 [DEBUG] [46.12.34.56:52361-0#_AdminVHost:lsapi] Written to client: 1402
2014-05-07 22:16:25.594 [DEBUG] [46.12.34.56:52361-0#_AdminVHost:lsapi] HttpConnection::nextRequest()!
2014-05-07 22:16:25.594 [DEBUG] [46.12.34.56:52361-0#_AdminVHost:lsapi] HttpExtConnector::cleanUp() ...
2014-05-07 22:16:25.594 [INFO] [46.12.34.56:52361-0#_AdminVHost:lsapi] abort request..., code: 4 
2014-05-07 22:16:25.594 [INFO] [46.12.34.56:52361-0#_AdminVHost:lsapi] Abort request processing by PID:50122, kill: 1, begin time: 0, sent time: 1399493785, req processed: 0
2014-05-07 22:16:25.594 [INFO] [AdminPHP] killProcess: process changed UID, let parent kill it: 50122
2014-05-07 22:16:25.594 [DEBUG] [AdminPHP] kill pid 50122 associated with ProcInfo: 0x8406880
2014-05-07 22:16:25.594 [DEBUG] [46.12.34.56:52361-0#_AdminVHost:lsapi] ExtConn::continueWrite()
2014-05-07 22:16:25.594 [DEBUG] [46.12.34.56:52361-0#_AdminVHost:lsapi] release ExtProcessor!
2014-05-07 22:16:25.594 [DEBUG] [idle] [ExtConn] close()
2014-05-07 22:16:25.594 [DEBUG] [UDS://tmp/lshttpd/admin_php.sock] add recycled connection to connection pool!
2014-05-07 22:16:25.594 [DEBUG] [46.12.34.56:52361-0#_AdminVHost:lsapi] Non-KeepAlive, CLOSING!
2014-05-07 22:16:25.594 [DEBUG] [46.12.34.56:52361-0#_AdminVHost:lsapi] Shutting down out-bound socket ...
2014-05-07 22:16:25.594 [DEBUG] [46.12.34.56:52361-0#_AdminVHost:lsapi] Available Connections: 150, concurrent conn: 0
2014-05-07 22:16:25.600 [DEBUG] [46.12.34.56:52361-0#_AdminVHost:lsapi] HttpIOLink::handleEvents() events=17!
2014-05-07 22:16:25.600 [DEBUG] [46.12.34.56:52361-0#_AdminVHost:lsapi] Close socket ...
2014-05-07 22:16:26.000 [INFO] [CLEANUP] Send signal: 30 to process: 50122
2014-05-07 22:16:26.000 [INFO] Pid: 50122 associated with [AdminPHP]
2014-05-07 22:16:26.000 [INFO] ProcInfo Pid: -1, socket: /tmp/lshttpd/admin_php.sock 
2014-05-07 22:16:26.000 [INFO] [AdminPHP] pid list size: 0, pid stop list size: 0
Also, the admin vhost access log is no longer working. I shut down lsws, emptied the logs and started lsws again, and the access log (configured to be $SERVER_ROOT/logs/access.log) simply stays empty. This may or may not be related to the 500 errors. I haven't checked the log lately, so its possible this has been broken for longer. I also haven't kept the old log, so I can't check from when the last entry was.

Another thing I noticed are the different auto-generated error pages. Why do these even have a link to the litespeedtech website?

If the link needs a disclaimer to go with it on the error page itself and then links to a page with another disclaimer, the sensible choice seems to not link to the web server manufacturers website (which most likely means absolutely nothing to the person getting the error, which explains the need for two disclaimers) and simply omit it or replace it with something useful, like the Administrator Email set...

Is there an easy way to remove this link or do I have to create a whole set of custom error pages just to get rid of it? What's the rationale for including a link on completely unrelated error pages over simply something like "LiteSpeed WebServer Standard -- for issues with this site contact <Admin Email>"? Is it to get a better Google ranking for your site or something?

Thanks.
 
R

raphidae

Well-Known Member
#5
#5
mistwang said:
For the link you can turn it off with
http://www.litespeedtech.com/docs/webserver/config/general#hideSigInErrorPage

For admin PHP problem, it is because a FreeBSD security feature. If you set

the problem will be fixed.

We will turn off the PID checking for FreeBSD.
Click to expand...
Thanks. I should have RTFM instead of going on a rant about the link :) I do still feel that the link in the signature should be disabled by default.

That sysctl shouldn't prohibit listing PIDs under the same uid though. When and why are processes looking at PIDs for other users? Could you be more specific in what the problem is?

The workaround is impractical; it's a multiuser system. The users are not all that clever and will accidentally start commands with a password on the command line (among other things), exposing passwords, usernames and IP addresses to all local users. So not limiting the process table is not something I can do.

If you can describe the problem in more detail I may be able to find another workaround. BTW, if you turn off PID checking for FreeBSD, what's the drawback? Surely the check serves some purpose?

Thanks.
 
You must log in or register to reply here.
Top