Temporary files leak RESTserver / Windows7

[dizzzz]

What is the problem

While testing #1766 I found a lot of old existSRVxxxxxxxxxxxx.tmp files inside the newly defined tmp directory. These are written by org.exist.http.RESTServer#doPut

What did you expect

The nr of tmp files should not increase.

Describe how to reproduce or add a test

Use HTTP PUT to push XML documents (larger than 64k) to the eXist-db REST interface,

To verify: it might be a windows specific issue. Note #1702

Context information

Please always add the following information

• eXist-db version + Git Revision hash e.g. eXist-db 4,0
• Java version: Java8u161
• Operating system: Windows 7
• 64 bit
• start database via YAJSW

[alebastrov]

We have that issue unfixed in our 2.2 (+ our modifications) version. They are left in cases we could not recognize. At least they count on finalizers as far as I know, that's why it needs to be changed (finalizers are not supposed to be used as normal data flow)
It does not depend on windows platform, we have the same on linux one
P.S. size of files also does not matter.

[dizzzz]

by design, for eXist-db version 3+, for existSRVxxxxxxxxxxxx.tmp the size should matter as under a certain limit (40k?64k? the document is entirely bufferend in memory, hence no document is written to disk....

what are the exact filename patterns you see?

[jking527467]

Was there every anything done in regards to this? In my current system it seems every XML document being stored in eXist is creating a temporary file that's never cleaned up causing for 100's of GB's worth of data building up and tanking the heap space eventually.

[dizzzz]

I think that recent work of @reinhapa fixed this issue: #2621

[jking527467]

Awesome, this isn't in any released version right? I'd have to move forward with the develop-4.x.x branch?

[jking527467]

Actually, looks like it made it into https://github.com/eXist-db/exist/releases/tag/eXist-4.7.0

[jking527467]

I've upgraded to eXist 4.7.0 and I still see an issue. Basically a *.tmp file gets created for each XML Resource I create using the XML RPC endpoint and the *.tmp files never go away. When are these supposed to go away during the normal lifecycle?

[adamretter]

@jking527467 I assume you are operating on Windows? If so this issue might shed some light for you - #1863

[jking527467]

@adamretter - I don't see any errors in retrieval of the temp files in the logs, I just see a file get created each time a post happens : [29/May/2019:19:29:43 +0000] "POST /exist/xmlrpc HTTP/1.1" 200 159

I am operating on Windows and my code exists in a WAR file deployed inside Wildfly. The eXist DB is installed on a separate server and I'm posting to the xmlrpc endpoint. I see logging statements with items being removed in the eXist logs. The *.tmp files are being created on the server where my application is deployed in Wildfly.

[qtp566760932-62] INFO (NativeBroker.java [removeXMLResource]:2553) - Removing document TSS-L0642513-1 (1624) ...

[reinhapa]

The #2621 is currently for read operations for remote resources only. Due same issues while heavy writing lots of small files to a remote resource, I'm looking into using the same mechanism of buffering data within memory up to 4 MB also for write operations right know. (But both seems not be related to you're issue)

[adamretter]

@jking527467 Sure, so when you send data via XML-RPC to eXist-db, it needs to be cached somewhere before it is ingested. The temp files are used to do this.

We have historically had problems with deleting temp files on WIndows. This can be due to 1 of 3 reasons:

1. MemoryMapped file and NIO are mixed on the same temp file. This results in a bug within the JVM on Windows that is outside our control. This bug stops us from being able to close the file, and therefore we cannot delete it. We can work around this though, by not mixing the two types of IO on the same file.

2. Some Windows process (e.g. Virus Scanner etc) is reading the temp files, which stops us from being able to delete them when we are finished with them.

3. We are leaking file handles for the temp files. This would be a bug in our code...

Regards (1) and (3) I spent quite some time auditing and fixing such cases in the past. That is not to say we don't have an issue or a regression... Have you seen this issue with recent eXist-db versions prior to 4.7.0?

[jking527467]

@adamretter - I'd assume that for 1 and 2 I'd see errors somewhere that shows that these files cannot be deleted. I cannot locate those such errors.

We upgraded from a very old version of eXist (1.4.2) to 4.3.1 as part of a response to a security audit that required us to upgrade Java versions, add a username and password, etc. The same issue was happening in 4.3.1 which prompted me to upgrade to 4.7.0 where I still see it happening.

This did not happen in 1.4.2 though I'm sure the entire cache mechanism was overhauled.

[adamretter]

@jking527467 how are your temp files named?

[jking527467]

I just started the application and it created a folder named :
exist-db-temp-file-manager-5210439493760754392

The files are named :
exist-db-temp-18072172457871596.tmp

There is one file for each resource that I'm trying to save and each time I save a resource I get a new file.

[reinhapa]

@adamretter @jking527467 I can take a look into it. Just to be shure: your eXist-db version is 4.7.0 right?

[jking527467]

Yes, I saw the same behavior in 4.3.1 as well. I've made different configurations of the java.io.tmpdir and always see the same behavior. I also tried using different InputStreamCache classes but I don't seem to think that's helping.

[jking527467]

FYI the reason I found the file situation was through YourKit and a growing number of java.lang.ref.Finalizer objects.

[adamretter]

@jking527467 So the next step is to find which part of the codebase is creating the files (via the TemporaryFileManager), from there we can determine if we are closing the files correctly and/or if some external process is interfering with them.

[reinhapa]

@jking527467 @adamretter I did some local rework on the TemporaryFileManager in order to no longer relay on the in the meantime deprecated finalize() method for removing files in one shutdown hook thread.

I seems that there is at least a correct call to clean up the temporary file being called after the upload. It is maybe possible, that the stream is still open upon calling the cleanup method for the temp file... I will check that Monday on a Windows instance...

[jking527467]

@reinhapa Did you submit a PR for this? I'm interested in trying it out.

I also discovered that this does not happen on our instance that has not yet been upgraded. The instance has eXist 4.3.1 deployed but the software interacting with eXist is using the 1.4.1 eXist core library and xmldb 1.4.1 api. That instance also does not use a username and password to communicate with the eXist database. On that instance I can't even find temp files that have been created.

[reinhapa]

@jking527467 I created a bugfix branch on my exist repo for it and need to test it now on my Windows VM,,,

[jking527467]

Awesome, thanks. Just curious if you were able to reproduce the issue I'm seeing?

[reinhapa]

@jking527467 On my windows 8.1 VM there where no problems. File was created and deleted immediately after processing...

You can enable debug logging for the TemporaryFileManager by adding the following lines to you're log4j2.xml

 <Logger name="org.exist.util.io.TemporaryFileManager" additivity="false" level="debug">
        <AppenderRef ref="exist.core"/>
</Logger>

[jking527467]

So in the 4.7.0 baseline you cannot reproduce what I'm seeing? Unfortunately we're on Windows Server 2008 R2 so I don't know if that makes a difference.

[reinhapa]

@jking527467 just added a new update to properly delete old temp folders too. Also further tests did not reveal any problems on Windows. I would like that you test the current version and send me the exist.log containing the TemporaryFileManager entries that may show up...

[jking527467]

I will test with 4.7.0 with the logging changes and follow up with you.

[jking527467]

@reinhapa I wanted to follow up with you because I found a setup where I am not experiencing the issue.

Our instance has eXist 4.3.1 deployed and the software interacting with eXist is using the 2.2 eXist core library and xmldb 1.4.1 api. Files are being created and immediately deleted using this setup. I have not had time to incrementally upgrade the eXist core library to determine where it stops working, but I thought this may give you some more insight on what to look for.

[reinhapa]

@jking527467 I'm looking forward to hear from your results.

[adamretter]

@dizzzz @jking527467 Can we get an update for @reinhapa's work please?

[dizzzz]

I did a bulk upload with HTTP/PUT (as originally in my report), and monitored files like "exist-db-temp-8021125833792001398.tmp" (macOS).

commands for XML and non XML documents: :

for i in `seq 1 10000`; do curl http://localhost:8080/exist/rest/db/tmp/aaa$i.txt --upload-file conf.txt; echo $i;  done ;

and

for i in `seq 1 10000`; do curl http://localhost:8080/exist/rest/db/tmp/bbb$i.xml --upload-file conf.xml; echo $i;  done ;

Run in parallel; all temp files are removed as expected. For me, the issue is not present anymore.

Configuration:

• macOS
• 4.8.0-SNAPSHOT / 4XX branch
• Java 1.8.0_212

I do not have a windows7 box around; Maybe I can find a windows10 box.

Please note that @jking527467 's report is about running the WAR file inside WILDFLY which I have never tested.

[dizzzz]

when reading the thread I see something a bit annoying: my original issue was reported on the PUT method, not with an XMLRPC interface. Mixing up things makes a thread not readable :-(

in addition, running 1.4.1 client JARS with a 4.3 server: please don't. Why would you do this?

[duncdrum]

any news @jking527467

[dizzzz]

Two months later... let’s close it in a week or so.

[jking527467]

Sorry for the delay. I ended up changing jobs. The problem I faced was entirely with the XMLRPC interface. I'm aware that I should not be running the old client dependencies with the new server dependency. I noticed that the last individual that performed an eXist upgrade for us didn't update the client dependencies and we were not having the issue on that instance that we were having with the 4.3 server and 4.3 client. I rolled back to try and get more insight. Essentially what I ended up doing was rolling back to and older version of eXist on both the client and server side where the issue was not happening. It is definitely happening in 4.3. I rolled back and then upgraded incrementally until the issue represented itself. I know it was introduced in 2.x but don't know the minor version that introduced it. I'll see if I can dig back through my files to determine what version it's on or reach out to my old company to find out for you.

…

On Tue, Aug 27, 2019 at 2:25 AM Dannes Wessels ***@***.***> wrote: Two months later... let’s close it in a week or so. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#1767?email_source=notifications&email_token=ABM6KN236PU2LSZ2CIYXSSDQGTCG3A5CNFSM4EU3IDNKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD5GUJZQ#issuecomment-525157606>, or mute the thread <https://github.com/notifications/unsubscribe-auth/ABM6KN6GKS6F5U6ZNKL3Z6LQGTCG3ANCNFSM4EU3IDNA> .

[dizzzz]

Thnx for your reply. I suspect that the changes should fix the issue. I think that it is essential to have server and client side the same versions of the code; that is what we test , other combinations... not :/

[jking527467]

I absolutely agree with you. I'm just confirming what I was able to get working. Which was 2.x client and server which resolved the XMLRPC temporary file leak issue.

…

On Wed, Aug 28, 2019 at 3:50 PM Dannes Wessels ***@***.***> wrote: Thnx for your reply. I suspect that the changes should fix the issue. I think that it is essential to have server and client side the same versions of the code; that is what we test , other combinations... not :/ — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#1767?email_source=notifications&email_token=ABM6KN7ZVNKINAZQT7OQDPTQG3JG5A5CNFSM4EU3IDNKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD5MITDY#issuecomment-525896079>, or mute the thread <https://github.com/notifications/unsubscribe-auth/ABM6KN6QX2AVGQHUDMMNMODQG3JG5ANCNFSM4EU3IDNA> .