Allow reducing the priority of concurrent requests

Zackster · August 2, 2022, 5:07pm

@micstriit has been working on a new feature which will help to make uncoordinated DDOS attacks less effective against Lucee, by amongst other things reducing the thread priority

It’s been added to the 5.3.9.151-SNAPSHOT and 5.3.10.39-SNAPSHOTs

More details in the ticket [LDEV-4123] - Lucee

Phillyun · August 3, 2022, 11:53am

Interesting… two things here:

I’m most curious about the comment about it doing this priority reduction

Same way Lucee reduces prio of threads running more than 10 seconds.

Regarding thread deprioritization of an active long-running thread, am I inferring correctly that a long running database transaction thread with a mutually exclusive lock would become a liability (blocker) for other higher priority (normal) threads that want to read committed data and MUST wait?

More info on how that works may answer my question better (or tests related to that feature where I can add my DB related scenarios)

In the code I see opc.getHttpServletRequest().getRemoteAddr().
Can someone remind me how this is handled when being served via proxy (or load balancer)?
I think this effectively reduces the concurrent request count for processing at normal priority, no?

micstriit · August 4, 2022, 1:21pm

First of all the feature that Lucee/Railo reduces the priority always existed, that was never added because already Railo 1.0 had it.
This feature of course is limited to code executed within the JVM, of course when you do a db query, the DB server does not care about this setting.

We did of course consider different ways to identify a client, cookies of course is not a solution because with a DOS attack you mostly not get a cookie back. We are of course open for suggestion to improve this. Have in mind that this setting never blocks a client, it only slows them down.

Phillyun · August 4, 2022, 3:45pm

I appreciate the reply; I’m not at all saying this is bad behavior per se …

This question was a sub-par caffeine level contrived (fake) scenario where a known longer-running task (like a nightly task / update) may unintentionally block other requests longer due to the reduced priority scenario.

Even databases will pause thread execution of a query to process other query requests if concurrency is possible - so it’s not a bad thing for Lucee to do a similar thing.

In the end: Knowing there’s this 10 sec window specifically makes me want to re-think some of our external resource fetches where we already have a limited resource that specifically relies on FIFO (first request in, first request out) processing.

I appreciate having the better understanding of what’s actually happening behind the scenes (and if I can specify a request-priority level outside of an un-joined thread) for future improvements.

Zackster · August 4, 2022, 3:56pm

We’re going to add some logging around both these behaviours too

Update @micstriit just added some

mjclemente · May 31, 2023, 4:30pm

Just upgrades to lucee-light@5.3.10+120, with Java 11.0.19_7.

I’m seeing the logging for this:

downgrade priority of the a request at path: /app/path.cfm.  Open locks at this time [a73a1076-c1fa-4cea-8b15342ba3f25a6f, c35ff6b0-39d1-41d9-8d592a90f0271b75].;java.lang.Throwable;java.lang.Throwable

It’s then followed by a full stack trace every time:

at lucee.loader.servlet.CFMLServlet.service(CFMLServlet.java:51)
at lucee.loader.engine.CFMLEngineWrapper.serviceCFML(CFMLEngineWrapper.java:97)
at lucee.runtime.engine.CFMLEngineImpl.serviceCFML(CFMLEngineImpl.java:1162)
at lucee.runtime.engine.CFMLEngineImpl._service(CFMLEngineImpl.java:1216)
at lucee.runtime.engine.Request.exe(Request.java:45)
at lucee.runtime.PageContextImpl.executeCFML(PageContextImpl.java:2449)
at lucee.runtime.PageContextImpl._execute(PageContextImpl.java:2478)
at lucee.runtime.PageContextImpl.execute(PageContextImpl.java:2493)
at lucee.runtime.listener.ModernAppListener.onRequest(ModernAppListener.java:107)
at lucee.runtime.listener.ModernAppListener._onRequest(ModernAppListener.java:219)
at lucee.runtime.PageContextImpl._doInclude(PageContextImpl.java:948)
at lucee.runtime.PageContextImpl._doInclude(PageContextImpl.java:1056)
at path$cf$70.call(/path.cfm:39)
at lucee.runtime.functions.system.Sleep.call(Sleep.java:31)
at java.base@11.0.19/java.lang.Thread.sleep(Native Method)

Is this expected? Kinda flooding the logs.

Zackster · May 31, 2023, 4:38pm

nah it’s not, what’s the code doing?

Zackster · May 31, 2023, 5:49pm

actually it is expected, when you bump the log level up to INFO, ERROR is the default

github.com

lucee/Lucee/blob/5.3/core/src/main/java/lucee/runtime/CFMLFactoryImpl.java#L374


      
          									+ getActiveThreads() + " active cfthreads " + getPath(pc) + "." + MonitorState.getBlockedThreads(pc) + RequestTimeoutException.locks(pc),
          									ExceptionUtil.toThrowable(pc.getThread().getStackTrace()));
          						}
          					}
          				}
          				// after 10 seconds downgrade priority of the thread
          				else if (pc.getStartTime() + 10000 < System.currentTimeMillis() && pc.getThread().getPriority() != Thread.MIN_PRIORITY) {
          					Log log = ThreadLocalPageContext.getLog(pc, "requesttimeout");
          					if (log != null) {
          						PageContext root = pc.getRootPageContext();
          						log.log(Log.LEVEL_INFO, "controller", "downgrade priority of the a " + (root != null && root != pc ? "thread" : "request") + " at " + getPath(pc) + ". "
          								+ MonitorState.getBlockedThreads(pc) + RequestTimeoutException.locks(pc), ExceptionUtil.toThrowable(pc.getThread().getStackTrace()));
          					}
          					try {
          						pc.getThread().setPriority(Thread.MIN_PRIORITY);
          					}
          					catch (Throwable t) {
          						ExceptionUtil.rethrowIfNecessary(t);
          					}
          				}
          			}

the idea being that it’s better that Lucee expresses (i.e. logs) what it has always done (since forever) with long running threads, which is downgrading the priority of any request running longer than 10s

mjclemente · May 31, 2023, 8:36pm

Interesting! Thanks for tracking that down.

Looks like when I set my requesttimeout log to WARN those logs are omitted - appreciate that!