How can I determine current thread / request / execution context?

dev
1

Hi,
I’m trying to debug some funny stuff that sometimes happens in my app, so I’m trying to get a handle on exactly what code is run and when.
I have peppered log statements throughout my application.cfc hooks. Thing is, I’ve now realized that the log statements are interleaving between various concurrent requests running the same code in different contexts. I would like to be able to label my log statements with the current thread id. Is this possible?

I’m assuming that each incoming request is handled by an automatically created (or allocated) thread. Is that right? The docs regarding the threading model/syntax in lucee are pretty confusing to me, but it seems like in order to get any specific thread info, I would have to explicitly start up a new thread using cfthread. I don’t want to add to the confusion by creating any new threads, but I would like a way to identify the execution context at any particular point in the code.

Thanks!
-Partap

2

You can log the name of the current thread like so:

createObject( 'java', 'java.lang.Thread' ).currentThread().getName()

Your code may run in a different thread if you use the runAsync() method, the cfthread tag, or the parallel struct/array each member functions. There are also internal things can can use a thread such as certain JDBC drivers with timeout settings or the cfhttp tag, but you’d really need to show the specific code you’re referring to.

3

Thanks, I think this is what I’m looking for.

Is this an expensive operation? i.e., would it be ok to just include that createObject() code in my log function, or should I just call it once in onStartRequest and cache it in the Request object?

Right now I’m mostly using it to help me understand how the code is run, so I’ll probably include it in the logging function, but if it’s cheap enough, maybe I could leave it there for production?

4

Doesn’t the built in logging with Lucee already include the threadId for each log entry?

5

Is this an expensive operation?

Not necessarily. It depends on how often you’re calling it. java.lang.Thread comes from the JDK so it’s pretty fast to class load.

would it be ok to just include that createObject() code in my log function, or should I just call it once in onStartRequest and cache it in the Request object?

It’s important to note that you’re not actually creating an instance of the Thread class.
currentThread() is a static method on the class that just returns the reference to the current one. Therefore you can cache this part if you like:

application.ThreadClass = createObject( 'java', 'java.lang.Thread' );

And then just use it where you need it like so:

var thisThreadName = application.ThreadClass.currentThread().getName();

But the overhead is small enough it probably doesn’t really matter.

1 Like
6

I’m relatively new to CF so I don’t actually know what the “built in logging” with Lucee is…

The codebase I’m working with uses a custom tag:

<cf_tag_trace outputline="I agree, this is kind of awkward">

The tag adds some info and writes out to a file:

2020-11-06 11:52:43 [ 127.0.0.1 | /myscript.cfm | MY_SESSION_ID ] - I agree, this is kind of awkward

It’s kind of annoying to use, coming from node/javascript…
e.g. in cfscript I’m doing this:

cf_tag_trace(outputline="Just did something. mydata: #toString(myDataStruct)#");

But I’d rather be able to do something like this:

niceLogger.debug("Did something else. mydata:", myDataStruct);

I’ve inherited this legacy codebase and the last of the original developers left the company recently, so I’m free to do pretty much whatever now.

The more I read up on Lucee/cfscript, the more I’m finding that CF doesn’t have to be as painful to use as this code suggests (e.g. hundreds of files of code… all written in tag notation, dependent on global variables, etc) :stuck_out_tongue:

7

I assume that was a reference to the CFLog tag built into the CFML language

I’ll be honest, I don’t really use that as it’s very simplistic. I use LogBox, which is a fully-featured pluggable logging framework that can be used standalone and ships with ColdBox MVC that’s built simliar to Java’s Log4j. (I’m part of team ColdBox FWIW)

So with that I’ve got named logging categories, multiple appenders (file, console, E-mail, Sentry, etc), logging severity filters, and my logging code looks exactly like:

niceLogger.debug( "message", extraInfo );
1 Like
8

Thanks,
I installed logbox using CommandBox, but not having any luck so far…It seems that some of the documentation is inaccurate/outdated. Maybe you can help?

The refcard contains a sample /config/LogBox.cfc that doesn’t work. First, I needed to wrap it with component { } (maybe that was supposed to be obvious? still a noob…)
It also refers to class='logbox...AsyncRollingFileAppender', which doesn’t seem to exist. I replaced that with RollingFileAppender but still not getting any output in the /logs directory.

9

OK, I found another example that uses RollingFileAppender here: Appender - LogBox : Enterprise Logging & Messaging

I tweaked the filePath property and now I’m getting data in /logs/MyAsyncFile.log!
Nice!

10

Correct, that was simply left out of the refcard for brevity. All valid CFC files need the component block.

It also refers to class='logbox...AsyncRollingFileAppender'

Yes, the PDF refcards are from a few years ago (and a lot of work to keep up to date). We recently made it possible to make any appender async with a top-level async property and deprecated the specific async appender names.

I tweaked the filePath property and now I’m getting data in /logs/MyAsyncFile.log!

Glad you’ve got it working. The config has a lot of options since it’s so configurable, but once you have it up and running, it’s pretty straightforward to use. You’ll notice that a lot of the information on LogBox out there assumes you’re using it inside of ColdBox MVC just since that’s the most common approach, but it still does all the same stuff as a standalone library. It’s just a little more work to manually create it.