Litespeed generated 500 errors on POST

[IanD]

Hi,

We've been using Litespeed for many years without any problems but a couple of days started getting some 500 errors come up that we can't reproduce.

Using LS 6.0.8 but also happened in 6.0.5.

Debug log:

2021-09-11 16:01:23.738460 [DEBUG] [29960] [T0] [XXX.XXX.XXX.XXX:13498#ServerV2] use Porxy IP header: cf-connecting-ip: XXX.XXX.XXX.XXX
2021-09-11 16:01:23.738488 [DEBUG] [29960] [T0] [XXX.XXX.XXX.XXX:13498#ServerV2] update REMOTE_ADDR based on cf-connecting-ip header to XXX.XXX.XXX.XXX, access: 1, local: 0
2021-09-11 16:01:23.738492 [DEBUG] [29960] [T0] [XXX.XXX.XXX.XXX] increase connection count to 1.
2021-09-11 16:01:23.738496 [DEBUG] [29960] [T0] [XXX.XXX.XXX.XXX:13498#ServerV2>XXX.XXX.XXX.XXX] [RECAPITCHA] Disabled at server level, skip recaptcha.
2021-09-11 16:01:23.738499 [DEBUG] [29960] [T0] [XXX.XXX.XXX.XXX:13498#ServerV2>XXX.XXX.XXX.XXX] matchedVhost(): HSPS_NEW_REQ -> HSPS_HKPT_HTTP_BEGIN
2021-09-11 16:01:23.738502 [DEBUG] [29960] [T0] [XXX.XXX.XXX.XXX:13498#ServerV2>XXX.XXX.XXX.XXX] runEventHkpt(): HSPS_HKPT_HTTP_BEGIN -> HSPS_HKPT_RCVD_REQ_HEADER
2021-09-11 16:01:23.738505 [DEBUG] [29960] [T0] [XXX.XXX.XXX.XXX:13498#ServerV2>XXX.XXX.XXX.XXX] runEventHkpt(): HSPS_HKPT_RCVD_REQ_HEADER -> HSPS_TRY_FINISH_REQ_BODY
2021-09-11 16:01:23.738518 [DEBUG] [29960] [T0] [XXX.XXX.XXX.XXX:13498#ServerV2>XXX.XXX.XXX.XXX] Read Request Body!
2021-09-11 16:01:23.738530 [DEBUG] [29960] [T0] [XXX.XXX.XXX.XXX:13498#ServerV2>XXX.XXX.XXX.XXX] processNewReqBody(): HSPS_TRY_FINISH_REQ_BODY -> HSPS_PROCESS_NEW_URI
2021-09-11 16:01:23.738533 [DEBUG] [29960] [T0] [XXX.XXX.XXX.XXX:13498#ServerV2>XXX.XXX.XXX.XXX] smProcessReq(): HSPS_PROCESS_NEW_URI -> HSPS_HTTP_ERROR
2021-09-11 16:01:23.738536 [DEBUG] [29960] [T0] [XXX.XXX.XXX.XXX:13498#ServerV2>XXX.XXX.XXX.XXX] HttpSession::sendHttpError(),code=500 Internal Server Error
2021-09-11 16:01:23.738546 [DEBUG] [29960] [T0] [XXX.XXX.XXX.XXX:13498#ServerV2>XXX.XXX.XXX.XXX] sendRespHeaders()
2021-09-11 16:01:23.738550 [DEBUG] [29960] [T0] [XXX.XXX.XXX.XXX:13498#ServerV2>XXX.XXX.XXX.XXX] HIO_FLAG_ALTSVC_SENT: 0, user-agent-type: 2, vhost QUIC: 1
2021-09-11 16:01:23.738554 [DEBUG] [29960] [T0] [XXX.XXX.XXX.XXX:13498#ServerV2>XXX.XXX.XXX.XXX] vhostmap->altsvc: 0x173e2f8, len: 0
2021-09-11 16:01:23.738585 [DEBUG] [29960] [T0] [XXX.XXX.XXX.XXX:13498#ServerV2>XXX.XXX.XXX.XXX] writeRespBody() sent: 712
2021-09-11 16:01:23.738601 [DEBUG] [29960] [T0] [XXX.XXX.XXX.XXX:13498#ServerV2>XXX.XXX.XXX.XXX] endResponse( 2 )
2021-09-11 16:01:23.738605 [DEBUG] [29960] [T0] [XXX.XXX.XXX.XXX:13498#ServerV2>XXX.XXX.XXX.XXX] endResponseInternal()
2021-09-11 16:01:23.738607 [DEBUG] [29960] [T0] [XXX.XXX.XXX.XXX:13498#ServerV2>XXX.XXX.XXX.XXX] mark COMPLETE.
2021-09-11 16:01:23.738610 [DEBUG] [29960] [T0] [XXX.XXX.XXX.XXX:13498#ServerV2>XXX.XXX.XXX.XXX] HttpSession::nextRequest()!
2021-09-11 16:01:23.738613 [DEBUG] [29960] [T0] [XXX.XXX.XXX.XXX:13498#ServerV2>XXX.XXX.XXX.XXX] [MODSEC] skipped LOG_PHASE: SubReq: 0, engine off: 0, runtime: (nil), need phase: 0
2021-09-11 16:01:23.738616 [DEBUG] [29960] [T0] [XXX.XXX.XXX.XXX:13498#ServerV2>XXX.XXX.XXX.XXX] Non-KeepAlive, CLOSING!
2021-09-11 16:01:23.738618 [DEBUG] [29960] [T0] [XXX.XXX.XXX.XXX:13498#ServerV2>XXX.XXX.XXX.XXX] HttpSession::closeSession(0).
2021-09-11 16:01:23.738621 [DEBUG] [29960] [T0] [XXX.XXX.XXX.XXX:13498#ServerV2>XXX.XXX.XXX.XXX] Log access, vhost: 0x1785300, cancelled: 0.
2021-09-11 16:01:23.738623 [DEBUG] [29960] [T0] [XXX.XXX.XXX.XXX:13498#ServerV2>XXX.XXX.XXX.XXX] Log access to 0x1782bc0->[/usr/local/lsws/logs/access.log].
2021-09-11 16:01:23.738629 [DEBUG] [29960] [T0] [XXX.XXX.XXX.XXX:13498#ServerV2>XXX.XXX.XXX.XXX] Log buffer size: 105.
2021-09-11 16:01:23.738636 [DEBUG] [29960] [T0] [XXX.XXX.XXX.XXX:13498#ServerV2>XXX.XXX.XXX.XXX] HttpSession::releaseResources() discard=1!
2021-09-11 16:01:23.738638 [DEBUG] [29960] [T0] [XXX.XXX.XXX.XXX] reduce connection count to 0.
2021-09-11 16:01:23.738679 [DEBUG] [29960] [T0] [XXX.XXX.XXX.XXX:13498#ServerV2>XXX.XXX.XXX.XXX] HttpSession::recycle(), state: HSPS_HTTP_ERROR

This server is processing around 1k/requests per second and it's a very tiny % that are affected but is causing our monitor alarms to go off and then the same thing is happening on each of our 3 different web servers so doesn't appear to be machine specific (CentOS 7.9.2009)

It appears to be a problem with the Request Body but how can we debug further?

Many thanks for any guidance.

Kind Regards,

Ian

 

[mistwang]

Log does not give reason for 500 status code, but based on the analysis, the cause is failed to read request body.
The log is not complete, so it is hard to say what exactly happened at socket level.
If it is HTTPS, it should have more low level SSL related log.

 

[IanD]

Thanks for the reply. No it's not HTTPS unfortunately.

I did tweak the debug settings for maximum, here is the output:

error.log.2021_09_12.02:2021-09-12 11:13:53.997484 [DEBUG] [26061] [T0] [XXX.XXX.XXX.XXX:43388] Headers: POST /callback/635c2f643c425960356b08dc25cb0ff8 HTTP/1.1
error.log.2021_09_12.02:2021-09-12 11:13:53.997489 [DEBUG] [26061] [T0] [XXX.XXX.XXX.XXX:43388#ServerV2] userProxyHeader: 2, trust IP: 1
error.log.2021_09_12.02:2021-09-12 11:13:53.997492 [DEBUG] [26061] [T0] [XXX.XXX.XXX.XXX:43388#ServerV2] use Porxy IP header: cf-connecting-ip: XXX.XXX.XXX.XXX
error.log.2021_09_12.02:2021-09-12 11:13:53.997570 [DEBUG] [26061] [T0] [XXX.XXX.XXX.XXX:43388#ServerV2] update REMOTE_ADDR based on cf-connecting-ip header to XXX.XXX.XXX.XXX, access: 1, local: 0
error.log.2021_09_12.02:2021-09-12 11:13:53.997581 [DEBUG] [26061] [T0] [XXX.XXX.XXX.XXX:43388#ServerV2>XXX.XXX.XXX.XXX] [RECAPITCHA] Disabled at server level, skip recaptcha.
error.log.2021_09_12.02:2021-09-12 11:13:53.997585 [DEBUG] [26061] [T0] [XXX.XXX.XXX.XXX:43388#ServerV2>XXX.XXX.XXX.XXX] matchedVhost(): HSPS_NEW_REQ -> HSPS_HKPT_HTTP_BEGIN
error.log.2021_09_12.02:2021-09-12 11:13:53.997589 [DEBUG] [26061] [T0] [XXX.XXX.XXX.XXX:43388#ServerV2>XXX.XXX.XXX.XXX] runEventHkpt(): HSPS_HKPT_HTTP_BEGIN -> HSPS_HKPT_RCVD_REQ_HEADER
error.log.2021_09_12.02:2021-09-12 11:13:53.997593 [DEBUG] [26061] [T0] [XXX.XXX.XXX.XXX:43388#ServerV2>XXX.XXX.XXX.XXX] runEventHkpt(): HSPS_HKPT_RCVD_REQ_HEADER -> HSPS_TRY_FINISH_REQ_BODY
error.log.2021_09_12.02:2021-09-12 11:13:53.997609 [DEBUG] [26061] [T0] [XXX.XXX.XXX.XXX:43388#ServerV2>XXX.XXX.XXX.XXX] Read Request Body!
error.log.2021_09_12.02:2021-09-12 11:13:53.997617 [DEBUG] [26061] [T0] [XXX.XXX.XXX.XXX:43388] End of stream detected, CLOSING!
error.log.2021_09_12.02:2021-09-12 11:13:53.997620 [DEBUG] [26061] [T0] [XXX.XXX.XXX.XXX:43388] Read from client: -1
error.log.2021_09_12.02:2021-09-12 11:13:53.997622 [DEBUG] [26061] [T0] [XXX.XXX.XXX.XXX:43388#ServerV2>XXX.XXX.XXX.XXX] processNewReqBody(): HSPS_TRY_FINISH_REQ_BODY -> HSPS_PROCESS_NEW_URI
error.log.2021_09_12.02:2021-09-12 11:13:53.997625 [DEBUG] [26061] [T0] [XXX.XXX.XXX.XXX:43388#ServerV2>XXX.XXX.XXX.XXX] smProcessReq(): HSPS_PROCESS_NEW_URI -> HSPS_HTTP_ERROR
error.log.2021_09_12.02:2021-09-12 11:13:53.997627 [DEBUG] [26061] [T0] [XXX.XXX.XXX.XXX:43388#ServerV2>XXX.XXX.XXX.XXX] HttpSession::sendHttpError(),code=500 Internal Server Error
error.log.2021_09_12.02:2021-09-12 11:13:53.997638 [DEBUG] [26061] [T0] [XXX.XXX.XXX.XXX:43388#ServerV2>XXX.XXX.XXX.XXX] sendRespHeaders()
error.log.2021_09_12.02:2021-09-12 11:13:53.997641 [DEBUG] [26061] [T0] [XXX.XXX.XXX.XXX:43388#ServerV2>XXX.XXX.XXX.XXX] HIO_FLAG_ALTSVC_SENT: 0, user-agent-type: 1, vhost QUIC: 1
error.log.2021_09_12.02:2021-09-12 11:13:53.997643 [DEBUG] [26061] [T0] [XXX.XXX.XXX.XXX:43388#ServerV2>XXX.XXX.XXX.XXX] vhostmap->altsvc: 0x189cf38, len: 0
error.log.2021_09_12.02:2021-09-12 11:13:53.997647 [DEBUG] [26061] [T0] [XXX.XXX.XXX.XXX:43388#ServerV2>XXX.XXX.XXX.XXX] Resp headers, total: 8, removed: 1, unique:7, has hole: 0, buffer size: 223
error.log.2021_09_12.02:2021-09-12 11:13:53.997649 [DEBUG] [26061] [T0] [XXX.XXX.XXX.XXX:43388#ServerV2>XXX.XXX.XXX.XXX]     cache-control: private, no-cache, no-store, must-revalidate, max-age=0
error.log.2021_09_12.02:2021-09-12 11:13:53.997651 [DEBUG] [26061] [T0] [XXX.XXX.XXX.XXX:43388#ServerV2>XXX.XXX.XXX.XXX]     pragma: no-cache
error.log.2021_09_12.02:2021-09-12 11:13:53.997653 [DEBUG] [26061] [T0] [XXX.XXX.XXX.XXX:43388#ServerV2>XXX.XXX.XXX.XXX]     content-type: text/html
error.log.2021_09_12.02:2021-09-12 11:13:53.997655 [DEBUG] [26061] [T0] [XXX.XXX.XXX.XXX:43388#ServerV2>XXX.XXX.XXX.XXX]     content-length: 712
error.log.2021_09_12.02:2021-09-12 11:13:53.997657 [DEBUG] [26061] [T0] [XXX.XXX.XXX.XXX:43388#ServerV2>XXX.XXX.XXX.XXX]     date: Sun, 12 Sep 2021 11:13:53 GMT
error.log.2021_09_12.02:2021-09-12 11:13:53.997659 [DEBUG] [26061] [T0] [XXX.XXX.XXX.XXX:43388#ServerV2>XXX.XXX.XXX.XXX]     server: LiteSpeed
error.log.2021_09_12.02:2021-09-12 11:13:53.997661 [DEBUG] [26061] [T0] [XXX.XXX.XXX.XXX:43388#ServerV2>XXX.XXX.XXX.XXX]     x-turbo-charged-by: LiteSpeed
error.log.2021_09_12.02:2021-09-12 11:13:53.997676 [DEBUG] [26061] [T0] [XXX.XXX.XXX.XXX:43388] NtwkIOLink written: 992
error.log.2021_09_12.02:2021-09-12 11:13:53.997679 [DEBUG] [26061] [T0] [XXX.XXX.XXX.XXX:43388#ServerV2>XXX.XXX.XXX.XXX] writeRespBody() sent: 712
error.log.2021_09_12.02:2021-09-12 11:13:53.997681 [DEBUG] [26061] [T0] [XXX.XXX.XXX.XXX:43388#ServerV2>XXX.XXX.XXX.XXX] endResponse( 2 )
error.log.2021_09_12.02:2021-09-12 11:13:53.997683 [DEBUG] [26061] [T0] [XXX.XXX.XXX.XXX:43388#ServerV2>XXX.XXX.XXX.XXX] endResponseInternal()
error.log.2021_09_12.02:2021-09-12 11:13:53.997686 [DEBUG] [26061] [T0] [XXX.XXX.XXX.XXX:43388#ServerV2>XXX.XXX.XXX.XXX] mark COMPLETE.
error.log.2021_09_12.02:2021-09-12 11:13:53.997691 [DEBUG] [26061] [T0] [XXX.XXX.XXX.XXX:43388#ServerV2>XXX.XXX.XXX.XXX] HttpSession::nextRequest()!
error.log.2021_09_12.02:2021-09-12 11:13:53.997695 [DEBUG] [26061] [T0] [XXX.XXX.XXX.XXX:43388#ServerV2>XXX.XXX.XXX.XXX] [MODSEC] skipped LOG_PHASE: SubReq: 0, engine off: 0, runtime: (nil), need phase: 0
error.log.2021_09_12.02:2021-09-12 11:13:53.997698 [DEBUG] [26061] [T0] [XXX.XXX.XXX.XXX:43388#ServerV2>XXX.XXX.XXX.XXX] Non-KeepAlive, CLOSING!
error.log.2021_09_12.02:2021-09-12 11:13:53.997702 [DEBUG] [26061] [T0] [XXX.XXX.XXX.XXX:43388#ServerV2>XXX.XXX.XXX.XXX] HttpSession::closeSession(0).

Could something be cutting off the body request before it's finished sending?

We've looked at the useragents and it's happening with all different browsers.

Have you seen anything like this CloudFlare? We do use them as our CDN.

What's strange is that if this has always been happening, it only started producing 500 errors on Litespeed a couple of days ago but Litespeed wasn't upgraded at the time, nothing was changed there.

 

[mistwang]

There should be request headers logged without

[IP:port]

prefix, should post that part as well to get full info about the request.
I wonder if "Content-Length" header is set or not.
The log shows the client does not send any request body, market the connection half closed.
```
2021-09-12 11:13:53.997617 [DEBUG] [26061] [T0] [XXX.XXX.XXX.XXX:43388] End of stream detected, CLOSING!
2021-09-12 11:13:53.997620 [DEBUG] [26061] [T0] [XXX.XXX.XXX.XXX:43388] Read from client: -1
```
It is more likely a change on cloudflare side.

 

[IanD]

"There should be request headers logged without "

In the same debug file?

If I can't search the log on IP, I'm not sure I would be able to locate the entries due to the volume of requests logged.

 

[mistwang]

Can location the log entries in log file with grep, then check the log file directly with an editor to find it.

 

[IanD]

Just seen a new version available of LS and in the release log:

BUGFIX Address POST requests randomly hanging

is that related to this thread?