Anonymization of large study via Lua hangs server

Google Groups archive
1

Hi all,

I am trying to anonymize a large DBT study (2.3GB). This works from the web interface, and takes about 90 seconds. If I try to do the same via Lua, the server hangs after processing a few instances and has to be forcefully killed.

Here is the Lua script:

local studyId = ‘b6ce44a0-3bffd551-890875d7-99d82d01-0285c8f3’;
local m = RestApiPost(‘/studies/’ … studyId … ‘/anonymize’, ‘{}’);

If I run Orthanc with tracing enabled, it processes a couple series and then hangs like this:

…

T0916 17:06:31.859287 Statement.cpp:144] SQLite::Statement::Step SELECT value FROM Metadata WHERE id=? AND type=?
T0916 17:06:31.859355 ServerIndex.cpp:181] Change related to resource e7c5cd19-0abae43d-e2362037-f2f7645f-432cfccc of type Series: NewChildInstance
T0916 17:06:31.859479 ServerIndex.cpp:181] Change related to resource 55d6823a-ceef0751-faba07a6-de39903e-a641bbe9 of type Study: NewChildInstance
T0916 17:06:31.859562 ServerIndex.cpp:181] Change related to resource 76464509-d9021142-a190d004-11ce65bc-e394cd90 of type Patient: NewChildInstance
T0916 17:06:31.859639 Statement.cpp:135] SQLite::Statement::Run COMMIT
I0916 17:06:31.859897 ServerContext.cpp:260] New instance stored
I0916 17:06:31.860112 OrthancRestAnonymizeModify.cpp:256] Modifying instance 35ecd98e-e228ff97-40654a14-49ff9ca6-004c3e05
T0916 17:06:31.860165 MemoryCache.cpp:56] Dropping the oldest cache page
T0916 17:06:31.862265 Statement.cpp:144] SQLite::Statement::Step SELECT internalId, resourceType FROM Resources WHERE publicId=?
T0916 17:06:31.862342 Statement.cpp:144] SQLite::Statement::Step SELECT uuid, uncompressedSize, compressionType, compressedSize, uncompressedMD5, compressedMD5 FROM AttachedFiles WHERE id=? AND fileType=?
T0916 17:06:37.884792 Connection.cpp:388] SQLite::Connection::FlushToDisk
T0916 17:06:41.899395 Statement.cpp:144] SQLite::Statement::Step SELECT * FROM Resources WHERE internalId=?
T0916 17:06:41.899482 Statement.cpp:135] SQLite::Statement::Run INSERT INTO Changes VALUES(NULL, ?, ?, ?, ?)
T0916 17:06:41.902623 ServerIndex.cpp:181] Change related to resource 76eb4836-9348e68e-2532950a-28e55df8-642098e0 of type Series: StableSeries
T0916 17:06:41.910321 Statement.cpp:144] SQLite::Statement::Step SELECT internalId, resourceType FROM Resources WHERE publicId=?
T0916 17:06:41.910394 Statement.cpp:144] SQLite::Statement::Step SELECT parentId FROM Resources WHERE internalId=?
T0916 17:06:41.910423 Statement.cpp:144] SQLite::Statement::Step SELECT publicId FROM Resources WHERE internalId=?
T0916 17:06:41.916028 Statement.cpp:144] SQLite::Statement::Step SELECT a.publicId FROM Resources AS a, Resources AS b WHERE a.parentId = b.internalId AND b.internalId = ?
T0916 17:06:41.916134 Statement.cpp:144] SQLite::Statement::Step SELECT a.publicId FROM Resources AS a, Resources AS b WHERE a.parentId = b.internalId AND b.internalId = ?
T0916 17:06:41.916175 Statement.cpp:144] SQLite::Statement::Step SELECT value FROM Metadata WHERE id=? AND type=?
T0916 17:06:41.916221 Statement.cpp:144] SQLite::Statement::Step SELECT value FROM Metadata WHERE id=? AND type=?
T0916 17:06:41.916250 Statement.cpp:144] SQLite::Statement::Step SELECT * FROM MainDicomTags WHERE id=?
T0916 17:06:41.933628 Statement.cpp:144] SQLite::Statement::Step SELECT * FROM MainDicomTags WHERE id=?
T0916 17:06:41.933783 Statement.cpp:144] SQLite::Statement::Step SELECT * FROM MainDicomTags WHERE id=?
T0916 17:06:41.933803 Statement.cpp:144] SQLite::Statement::Step SELECT * FROM MainDicomTags WHERE id=?
T0916 17:06:41.933819 Statement.cpp:144] SQLite::Statement::Step SELECT * FROM MainDicomTags WHERE id=?
T0916 17:06:41.933835 Statement.cpp:144] SQLite::Statement::Step SELECT * FROM MainDicomTags WHERE id=?
T0916 17:06:41.933850 Statement.cpp:144] SQLite::Statement::Step SELECT * FROM MainDicomTags WHERE id=?
T0916 17:06:41.933865 Statement.cpp:144] SQLite::Statement::Step SELECT * FROM MainDicomTags WHERE id=?
T0916 17:06:41.933881 Statement.cpp:144] SQLite::Statement::Step SELECT * FROM MainDicomTags WHERE id=?
T0916 17:06:41.933897 Statement.cpp:144] SQLite::Statement::Step SELECT * FROM MainDicomTags WHERE id=?
T0916 17:06:41.933921 Statement.cpp:144] SQLite::Statement::Step SELECT * FROM MainDicomTags WHERE id=?
T0916 17:06:41.933937 Statement.cpp:144] SQLite::Statement::Step SELECT * FROM MainDicomTags WHERE id=?
T0916 17:06:41.933953 Statement.cpp:144] SQLite::Statement::Step SELECT * FROM MainDicomTags WHERE id=?
T0916 17:06:41.934020 Statement.cpp:144] SQLite::Statement::Step SELECT value FROM Metadata WHERE id=? AND type=?
T0916 17:06:41.934048 Statement.cpp:144] SQLite::Statement::Step SELECT value FROM Metadata WHERE id=? AND type=?
T0916 17:06:41.934070 Statement.cpp:144] SQLite::Statement::Step SELECT value FROM Metadata WHERE id=? AND type=?
T0916 17:06:41.934096 Statement.cpp:144] SQLite::Statement::Step SELECT internalId, resourceType FROM Resources WHERE publicId=?
T0916 17:06:41.934121 Statement.cpp:144] SQLite::Statement::Step SELECT type FROM Metadata WHERE id=?
T0916 17:06:41.934149 Statement.cpp:144] SQLite::Statement::Step SELECT type FROM Metadata WHERE id=?
T0916 17:06:41.934167 Statement.cpp:144] SQLite::Statement::Step SELECT value FROM Metadata WHERE id=? AND type=?
T0916 17:06:44.668547 MemoryCache.cpp:67] Registering new data in a cache page
T0916 17:06:47.161700 Statement.cpp:144] SQLite::Statement::Step SELECT * FROM Resources WHERE internalId=?
T0916 17:06:47.484001 Statement.cpp:135] SQLite::Statement::Run INSERT INTO Changes VALUES(NULL, ?, ?, ?, ?)
T0916 17:06:47.529574 ServerIndex.cpp:181] Change related to resource e55923f9-05e99fd3-d1b60952-de90a92e-883490d6 of type Series: StableSeries
T0916 17:06:47.529655 Statement.cpp:144] SQLite::Statement::Step SELECT * FROM Resources WHERE internalId=?
T0916 17:06:47.557290 Statement.cpp:135] SQLite::Statement::Run INSERT INTO Changes VALUES(NULL, ?, ?, ?, ?)
T0916 17:06:47.557354 ServerIndex.cpp:181] Change related to resource b6ce44a0-3bffd551-890875d7-99d82d01-0285c8f3 of type Study: StableStudy
T0916 17:06:47.557385 Statement.cpp:144] SQLite::Statement::Step SELECT * FROM Resources WHERE internalId=?
T0916 17:06:47.557411 Statement.cpp:135] SQLite::Statement::Run INSERT INTO Changes VALUES(NULL, ?, ?, ?, ?)
T0916 17:06:47.557448 ServerIndex.cpp:181] Change related to resource 8b52dcff-6748a61a-53e679f0-74a4cb4e-a18cd16e of type Patient: StablePatient
T0916 17:06:47.899854 Connection.cpp:388] SQLite::Connection::FlushToDisk
T0916 17:06:58.133017 Connection.cpp:388] SQLite::Connection::FlushToDisk
T0916 17:07:08.134026 Connection.cpp:388] SQLite::Connection::FlushToDisk
T0916 17:07:18.134957 Connection.cpp:388] SQLite::Connection::FlushToDisk
T0916 17:07:18.560369 Statement.cpp:144] SQLite::Statement::Step SELECT * FROM Resources WHERE internalId=?
T0916 17:07:18.560502 Statement.cpp:135] SQLite::Statement::Run INSERT INTO Changes VALUES(NULL, ?, ?, ?, ?)
T0916 17:07:18.563843 ServerIndex.cpp:181] Change related to resource 19d2ede9-7ff16402-f9c1321d-94e27ef5-677fa0b4 of type Series: StableSeries
T0916 17:07:28.135811 Connection.cpp:388] SQLite::Connection::FlushToDisk
T0916 17:07:29.564930 Statement.cpp:144] SQLite::Statement::Step SELECT * FROM Resources WHERE internalId=?
T0916 17:07:29.565053 Statement.cpp:135] SQLite::Statement::Run INSERT INTO Changes VALUES(NULL, ?, ?, ?, ?)
T0916 17:07:29.567076 ServerIndex.cpp:181] Change related to resource de6a39f0-ddc28b60-0b8b96e6-e4d77821-ed5b1003 of type Series: StableSeries
T0916 17:07:31.567359 Statement.cpp:144] SQLite::Statement::Step SELECT * FROM Resources WHERE internalId=?
T0916 17:07:31.567444 Statement.cpp:135] SQLite::Statement::Run INSERT INTO Changes VALUES(NULL, ?, ?, ?, ?)
T0916 17:07:31.567502 ServerIndex.cpp:181] Change related to resource 48476df3-c4e70fdb-cf9523a3-335e8679-1b155fa8 of type Series: StableSeries
T0916 17:07:32.567689 Statement.cpp:144] SQLite::Statement::Step SELECT * FROM Resources WHERE internalId=?
T0916 17:07:32.567827 Statement.cpp:135] SQLite::Statement::Run INSERT INTO Changes VALUES(NULL, ?, ?, ?, ?)
T0916 17:07:32.567894 ServerIndex.cpp:181] Change related to resource e9a419fb-cc0f7c7a-89a75a3d-cc302bd6-571f6559 of type Series: StableSeries
T0916 17:07:32.572372 Statement.cpp:144] SQLite::Statement::Step SELECT * FROM Resources WHERE internalId=?
T0916 17:07:32.572405 Statement.cpp:135] SQLite::Statement::Run INSERT INTO Changes VALUES(NULL, ?, ?, ?, ?)
T0916 17:07:32.572470 ServerIndex.cpp:181] Change related to resource e7c5cd19-0abae43d-e2362037-f2f7645f-432cfccc of type Series: StableSeries
T0916 17:07:32.572499 Statement.cpp:144] SQLite::Statement::Step SELECT * FROM Resources WHERE internalId=?
T0916 17:07:32.572527 Statement.cpp:135] SQLite::Statement::Run INSERT INTO Changes VALUES(NULL, ?, ?, ?, ?)
T0916 17:07:32.572563 ServerIndex.cpp:181] Change related to resource 55d6823a-ceef0751-faba07a6-de39903e-a641bbe9 of type Study: StableStudy
T0916 17:07:32.572587 Statement.cpp:144] SQLite::Statement::Step SELECT * FROM Resources WHERE internalId=?
T0916 17:07:32.572611 Statement.cpp:135] SQLite::Statement::Run INSERT INTO Changes VALUES(NULL, ?, ?, ?, ?)
T0916 17:07:32.572647 ServerIndex.cpp:181] Change related to resource 76464509-d9021142-a190d004-11ce65bc-e394cd90 of type Patient: StablePatient
T0916 17:07:38.140383 Connection.cpp:388] SQLite::Connection::FlushToDisk
T0916 17:07:48.147045 Connection.cpp:388] SQLite::Connection::FlushToDisk
T0916 17:07:58.147893 Connection.cpp:388] SQLite::Connection::FlushToDisk
T0916 17:08:08.148765 Connection.cpp:388] SQLite::Connection::FlushToDisk

The last line repeats forever, server hangs and has to be kill -9’d.

Any ideas what might be going wrong? I am using 1.1.0 on Linux.

2

Dear Joe,

I confirm the deadlock, thanks for reporting it!

I have introduced a bug in our issue tracker, which contains a temporary workaround:
https://bitbucket.org/sjodogne/orthanc/issues/25/deadlock-with-lua-scripts

HTH,
Sébastien-

3

Thanks, that workaround works for now. I hope you plan to add concurrency at some point, during the 90 seconds it takes to anonymize these studies the entire server is unreachable, and any studies being sent from our PACS during that time fail due to timeout.

4

I have just added a note about concurrency inside the bug tracker. I cannot tell you when this will be implemented, as I currently work on other higher-priority features.

Please also note that if the built-in Lua scripting engine is insufficient for your usage, you can always create an external script that uses the REST API. Indeed, the REST API does not suffer from the shortcomings of Lua you report.

5

Sebastien,

I’m wondering if I’m running into the same problem here. I already have my StableAge set high to be consistent with our institution’s typical PACS policy - at 10 minutes or 600 seconds.

On occasion, my Lua scripts for anonymizing incoming studies simply hang in the middle of processing - for example, when running a RestApiPost to anonymize a study. I am working with the PostGre plugin rather than the native sqlite for meta data storage and my images are stored to disk (EnableStorage=false).

As a general question, is this problem likely to occur whenever the StableAge is less than the anticipated amount of time it takes to anonymize an entire study?

I tried running Orthanc in verbose mode at one point, but I don’t recall seeing the types of sqlite (or corresponding postgres) error messages that Joe saw.

Thanks for your help,
John.

6

I tried setting my StableAge very large at around 1 hour. For this particular Orthanc, this is not a big problem since I don’t need the DICOM anonymized immediately.

At that high StableAge, I have not encountered any deadlocks in my Lua anonymization script. So, it seems I was encountering the same problem.

John.