Conflict in same thread

Laurent · January 7, 2022, 9:18am

Hello,

our server shares about 100 Lucee applications on the same context.
since few days, the exception.log grows with huge quantity of lines of that kind :

“ERROR”,“ajp-nio-127.0.0.1-8009-exec-2”,“01/07/2022”,“09:37:16”,“file”,“Conflict in same thread: on [/var/www/sites_lucee/publiccms/vendredi.txt]”

The line above (written TWICE in log file) result of a single test with a script to write a file “vendredi.txt” (fileopen… filewrite… fileclose).
But for some applications, the line is present 6 TIMES for the same operation (for exemple creating a RSS file). And it’s ALWAYS about writing files.

Since yesterday a have restarted Lucee, but no change.
Another “symptom” (linked ?) : our scheduled daily tasks don’t start anymore ! (but their manual execution is ok)

OS: Linux (4.15.0-159-generic) 64bit
Java Version: 11.0.7 (AdoptOpenJDK) 64bit
Tomcat Version: Apache Tomcat/9.0.35
Lucee Version: Lucee 5.3.8.189

Laurent · January 7, 2022, 9:46am

For the scheduled tasks, it seems ok, thank’s to :
https://luceeserver.atlassian.net/browse/LDEV-3685
(i changed all start dates to 01/01)

Zackster · January 7, 2022, 10:00am

you get that error with just a single run of a test script? while the 100 apps are running too or not?

are the 100 apps all writing to the same file?

https://luceeserver.atlassian.net/browse/LDEV-3495

Laurent · January 7, 2022, 10:22am

First, a made a little mistake : theses lines are found in application.log
And yes, it was a single run,
and each application writes its own files

Below, another example (6 times the same file, why 6 ???) :

“ERROR”,“ajp-nio-127.0.0.1-8009-exec-11”,“01/07/2022”,“10:28:23”,“file”,“Conflict in same thread: on [/home/web/sites_lucee/cms2/uimm/espaces/corporate/fr/sitemap.xml]”

Terry_Whitney · January 7, 2022, 11:42am

Its a race condition. Some part of your application that is writing or reading the file is trying to do it faster than the rest of your stack (usually hardware related) can close and complete the request.

There is the function sleep which only works in cfscript (Grrr) or better solution is cftrace, in which you can then force your application to DO SOMETHING based upon the state of a log, or in conjunction with cflog.

Laurent · January 7, 2022, 1:25pm

More tests with my file “vendredi.txt”:
The script is timed with 1000 ms between each instruction:

open file (write mode)
fileWriteLine x 10 loop
close file

In the file, i retreive:

Voici un contenu 1 écrit à 2:19:24 PM
Voici un contenu 2 écrit à 2:19:25 PM
Voici un contenu 3 écrit à 2:19:26 PM
Voici un contenu 4 écrit à 2:19:27 PM
Voici un contenu 5 écrit à 2:19:28 PM
Voici un contenu 6 écrit à 2:19:29 PM
Voici un contenu 7 écrit à 2:19:30 PM
Voici un contenu 8 écrit à 2:19:31 PM
Voici un contenu 9 écrit à 2:19:32 PM
Voici un contenu 10 écrit à 2:19:33 PM

After, i read in application.log:

“ERROR”,“ajp-nio-127.0.0.1-8009-exec-30”,“01/07/2022”,“14:19:34”,“file”,“Conflict in same thread: on [/var/www/sites_lucee/publiccms/vendredi.txt]”
“ERROR”,“ajp-nio-127.0.0.1-8009-exec-30”,“01/07/2022”,“14:19:34”,“file”,“Conflict in same thread: on [/var/www/sites_lucee/publiccms/vendredi.txt]”

Some facts about these tests:

The file “vendredi.txt” is always perfectly generated
Only the writing instruction produces errors
No difference with/without sleep between operations
1 or 2 or…10 fileWriteLine produce the same 2 lines in application.log
==> in fact, the error is written only when the closing operation occurs.

carehart · January 7, 2022, 1:51pm

Laurent, have you considered using cflock around this write operation? This might be an opportune use of it, perhaps in particular a NAME lock of type=“exclusive”. While normally its value is more for multiple requests causing such a race condition, perhaps you have the code implemented in a way that’s happening in just one thread.

Also Terry, about the sleep function, here’s good news: you can actually use it in tags, not just script. Functions like that, which return no result, can simply be used in a cfset without any assignment for example (in both Lucee and ACF). This would sleep 5 seconds:
<cfset sleep(5000)>

Terry_Whitney · January 7, 2022, 2:21pm

@carehart as always, you are a fountain of knowledge.

It would be great if you wrote another book on CF. Its been far too long since anything like a WAK has been seen.

Laurent · January 7, 2022, 2:55pm

I wrapped my script in a lock.
And this is my wonderful script…

lock name="testRep" type="exclusive" {
               f = getDirectoryFromPath(getBaseTemplatePath()) & 'vendredi4.txt';
                fic = fileOpen(f, "write");
                for (cpt=1; cpt lte 10; cpt++) {
                    sleep(500);
                    filewriteline(fic, "Voici un contenu #cpt# écrit à #timeformat(now(), 'medium')#");
                }
                sleep(500);
                fic.close();
            }

But the result is the same in application.log :

“ERROR”,“ajp-nio-127.0.0.1-8009-exec-8”,“01/07/2022”,“15:52:00”,“file”,“Conflict in same thread: on [/var/www/sites_lucee/publiccms/vendredi4.txt]”
“ERROR”,“ajp-nio-127.0.0.1-8009-exec-8”,“01/07/2022”,“15:52:00”,“file”,“Conflict in same thread: on [/var/www/sites_lucee/publiccms/vendredi4.txt]”

Zackster · January 7, 2022, 7:09pm

maybe consider using a database instead, they handle this concurrency stuff much better?

Terry_Whitney · January 7, 2022, 8:53pm

You are only waiting 5 milliseconds.
Try adding a zero

 sleep(5000);

additionally I would suggst, if you are going the file route, to maybe check to see is the file locked for writing, before you write to the file plus you should try to use cflog

carehart · January 7, 2022, 9:47pm

Thanks, Terry. There are many founts here, yourself included. But thanks for the kind regards. Books are a hell of a lot of work, and the market for them is thin (well, I’d think one on any cf topic would be).

But I have been seriously contemplating going the YouTube video route. Just lots of choices with that, too, leading to analysis paralysis. Still, I note potential topics literally every day, whether from my consulting engagements or from things I offer (or indeed learn) on forums like this and others.

We’re spoiled for choice, in that regard. Yet few folks can watch ALL the possible places, so knowledge comes and goes, without uniform distribution, which is a shame. But I hope to help however I might, and I appreciate all who do.

carehart · January 7, 2022, 9:56pm

So Laurent, you’re 100% sure this code is the cause? Is it everytime you run it? If so, what if you comment out the writeline, just as a test.

Also, you probably don’t need the sleeps, within a lock. No other request could run the code in this lock while it was running.

Fwiw, note that it IS possible for something ELSE (including other cfml) to be accessing that file. The lock doesn’t lock that resource. It’s just a “gentleman’s agreement” where the cfml engine won’t let other code run if that code is in a lock of the same name, while that same-named is held in an exclusive lock by any other request (or cfthread).

Or at least that’s how cf locks are supposed to work. You may want to slip a cflog/write log into that lock to see if you find anything unexpected happening.

Laurent · January 8, 2022, 7:17pm

So, i simplified my code.
First, just for open/close file:

lock name="testRepMini" type="exclusive" {
                f = getDirectoryFromPath(getBaseTemplatePath()) & 'thisFileNeverExisted.txt';
                fic = fileOpen(f, "write");
                sleep(1000);
                fic.close();
            }

=> Nothing happens (no file created, no errors in appication.log)

Then, adding a filewriteline before close:


lock name="testRepMini" type="exclusive" {
                f = getDirectoryFromPath(getBaseTemplatePath()) & 'thisFileNeverExisted.txt';
                fic = fileOpen(f, "write");
                filewriteline(fic,'abcdef');
                sleep(1000);
                fic.close();
            }

=> Again, two lines error in logs, added at the same time of the call of close:

“ERROR”,“ajp-nio-127.0.0.1-8009-exec-9”,“01/08/2022”,“20:03:46”,“file”,“Conflict in same thread: on [/var/www/sites_lucee/publiccms/thisFileNeverExisted.txt]”
“ERROR”,“ajp-nio-127.0.0.1-8009-exec-9”,“01/08/2022”,“20:03:46”,“file”,“Conflict in same thread: on [/var/www/sites_lucee/publiccms/thisFileNeverExisted.txt]”

At the end, the txt file is generated as expected.
Perhaps i should just ignore these logs !!!

carehart · January 8, 2022, 8:41pm

Interesting that one write gets you two errors. But only one line is indeed written to the file, right? If so, I’d still argue there could be value in adding a cflog/writelog along with the write, to confirm that indeed only one such log line is written, even if two errors and one line in the file written to. There sure seems inconsistentcy.

But sure, ignoring the errors (or wrapping the line in a try/catch–to ignore this specific error onjy) is indeed another way to go on all this.

Laurent · January 9, 2022, 8:32am

No,
whatever the number of lines added in the file, the file is correctly written.
And these damn two lines of log “appear” when the close is performed.

carehart · January 9, 2022, 3:30pm

Lauren, you say “no” like you feel I am misunderstanding you. To be clear, it was you who said the error occurs when you add the writeln (“Nothing happens (no file created, no errors in appication.log) Then, adding a filewriteline before close:”)

And you’re also stressing how the error happens on the close. OK. I don’t quite see how you know that, but so be it. That may or may not be crucial.

And you confirm that “whatever the number of lines added in the file, the file is correctly written.” Again, OK, but then I said specifically that “If so, I’d still argue there could be value in adding a cflog/writelog along with the write, to confirm that indeed only one such log line is written, even if two errors and one line in the file written to. There sure seems inconsistentcy.”

Would you please add that logging just to make sure there’s only one log line of this sort written for your one call to this set of code? This is indeed focused on understanding the error you got, and especially when you have added the lock.

I appreciate the problem is very frustrating for you. I really am simply trying to help.

Julian_Halliwell · January 9, 2022, 4:32pm

I think the problem is you are trying to use a “member” function fic.close() on the open file object, when that doesn’t seem to be supported. That’s resulting in a close() call on the underlying java object - which works in terms of writing/closing the file, but it’s not what Lucee is expecting and seems to cause these internal errors to be logged.

Try using the supported CFML function to close the file:

FileClose( fic );

Laurent · January 10, 2022, 8:25am

FILECLOSE !

The errors desappear with fileclose(f) instead of f.close
But why did i used the object notation ? I never used it for file handling !

It doesn’t give me the cause of all other errors (the real cases, without “.close” found anywhere), but this test is resolved and give me a lead…

Many thanks to all

Laurent · January 31, 2022, 4:38pm

Hello everybody,

i finally found origin of all “Conflict…” logged:

I use my own class “text file” with a property (type any) for the handle of the opened file.
Using this property as parameter in the fileclose generate de logs.
And the problem desappear if i use instead the full path of the file (as a string) !

Is a handle a so “special” variable, or is it a bug ?