Lua Bad request exception after successful Delete

Google Groups archive
1

Orthanc 1.0

Plugins:
Dicomweb 0.2
Postgresql 2.0
Webviewer 2.1

I adapted the example server side OnStableStudy Lua script for modifying instances with a subsequent call to Delete to remove the original instances.

Everything appears to work, but I am seeing error messages in the log file indicating exceptions. Based on the time stamps, it appears that shortly after issuing the Delete call, the PluginInstanceManager receives an exception from a REST GET for the deleted instance:

I0712 20:13:46.966733 DeleteInstanceCommand.cpp:46] Deleting instance 152f0971-9d26650e-64e759d2-7161b3bf-68719ab1
I0712 20:13:46.978604 OrthancPlugins.cpp:941] Plugin making REST GET call on URI /instances/152f0971-9d26650e-64e759d2-7161b3bf-68719ab1 (built-in API)
E0712 20:13:46.986424 PluginsManager.cpp:194] Exception while invoking plugin service 3001: Bad request

I have used both the Delete function and the direct RestApiDelete call (with and without builtin set to true/false) with the same result.

Again, everything appears to be working. I just can’t track down where this particular error might be occurring in the Lua script. I specifically check the ModifiedFrom and AnonymizedFrom fields in OnStableStudy to prevent the reprocessing of already modified/anonymized data.

For debugging purposes, I have the stability time set at 60 seconds. The OnStableStudy script I set up first anonymizes data and then performs a series of modifications. I am testing with a small study (1 series, 5 images). The log file indicates that the anonymization, modification, deletion and subsequent exception errors all occur within seconds, well inside the 60 second window that triggers another OnStableStudy on the newly anonymized study.

John.

2

Hello,

Please could you post a sample script for us to reproduce your issue?

Regards,
Sébastien-

3

In the code below:

  • instances - array of Orthanc instance ids returned by RestApiPost call to anonymized studyid, ‘/studies/anonstudyid/instances’
  • instanceIDNew - array of Orthanc instance ids returned by calling /modify on the above instances
  • ShiftDateTimePatAgeOfInstances - function where the modify command is called, shifting specific DICOM date fields in time
  • I have commented out the actual deletion of original (anoymized) instances and the sending of their modified instances. I added print statements to show in the logs what is happening.

Portion of Lua script:

– Second pass anonymization creates files modified by shiftEpoch
– Deletes First pass anonymized files following shiftEpoch modification
instanceIDNew = ShiftDateTimePatAgeOfInstances(instances, shiftEpoch)

– Delete the original instance
local i, instanceTable, instanceID
for i, instanceTable in pairs(instances) do
instanceID = (instanceTable[‘ID’])
–RestApiDelete(‘/instances/’ … instanceID, false)
print(‘Deleting’)
print(instanceID)
–Delete(instanceID)
end – loop over instances

– Send to receiving modality
for i, instanceID in pairs(instanceIDNew) do
print(‘Sending’)
print(instanceID)
–SendToModality(instanceID, ‘UUHSC’)
end

In the following log, we first see the association from the incoming STORESCU. The images are stored (New instance stored) and one of the plugins immediately generates a REST GET on the newly stored instances. I suspect the “New instance stored” comes before the REST GET, but is mixed up due to the asynchronous nature of the various processes running here. These Orthanc instance ID are of the original non-anonymized DICOM.

I0715 17:52:55.498789 CommandDispatcher.cpp:491] Association Received from AET STORESCU on IP 192.168.58.1
I0715 17:52:55.521824 CommandDispatcher.cpp:689] Association Acknowledged (Max Send PDV: 16372)
I0715 17:52:55.601931 OrthancPlugins.cpp:941] Plugin making REST GET call on URI /instances/88577920-33f6c36c-dc61d0f8-209fa805-c6259143 (built-in API)
I0715 17:52:55.602404 ServerContext.cpp:260] New instance stored
I0715 17:52:55.662608 OrthancPlugins.cpp:941] Plugin making REST GET call on URI /instances/af831381-f569142a-bf2aaafb-fe7e1072-4bac9f83 (built-in API)
I0715 17:52:55.662896 ServerContext.cpp:260] New instance stored
I0715 17:52:55.708158 OrthancPlugins.cpp:941] Plugin making REST GET call on URI /instances/6d45cf05-751786f6-f5a03751-3f46b4ae-087feaab (built-in API)
I0715 17:52:55.708458 ServerContext.cpp:260] New instance stored
I0715 17:52:55.788229 OrthancPlugins.cpp:941] Plugin making REST GET call on URI /instances/721237a8-7dc59aba-6492a38e-2351a8db-504faa01 (built-in API)
I0715 17:52:55.789032 ServerContext.cpp:260] New instance stored
I0715 17:52:55.849334 OrthancPlugins.cpp:941] Plugin making REST GET call on URI /instances/e040eaec-8f8cd447-dc043018-dfac2ae2-5c8a2897 (built-in API)
I0715 17:52:55.849634 ServerContext.cpp:260] New instance stored

Now, after the stable study delay, the anonymization occurs. We see reports of the original nonanonymized id being anonymized. We see “New instance stored”, but this time, we don’t see any accompanying REST GET calls on those new instances. I suspect that the REST GET are generated but don’t execute until later - AFTER I’ve deleted the anonymized images.

I0715 17:53:56.683592 OrthancRestAnonymizeModify.cpp:256] Modifying instance e040eaec-8f8cd447-dc043018-dfac2ae2-5c8a2897
I0715 17:53:56.735793 ServerContext.cpp:260] New instance stored
I0715 17:53:56.736314 OrthancRestAnonymizeModify.cpp:256] Modifying instance 721237a8-7dc59aba-6492a38e-2351a8db-504faa01
I0715 17:53:56.778566 ServerContext.cpp:260] New instance stored
I0715 17:53:56.779200 OrthancRestAnonymizeModify.cpp:256] Modifying instance 6d45cf05-751786f6-f5a03751-3f46b4ae-087feaab
I0715 17:53:56.822661 ServerContext.cpp:260] New instance stored
I0715 17:53:56.822985 OrthancRestAnonymizeModify.cpp:256] Modifying instance af831381-f569142a-bf2aaafb-fe7e1072-4bac9f83
I0715 17:53:56.859656 ServerContext.cpp:260] New instance stored
I0715 17:53:56.860105 OrthancRestAnonymizeModify.cpp:256] Modifying instance 88577920-33f6c36c-dc61d0f8-209fa805-c6259143
I0715 17:53:56.900561 ServerContext.cpp:260] New instance stored

Finally, we hit the modification step where the anonymized images are modified, generated a 3rd set of images that are then stored. We are inside the ShiftDateTime… function. Again, we see reports of “New instance stored”, but the associated REST GET are not yet generated.

I0715 17:53:56.986177 OrthancRestApi.cpp:90] Receiving a DICOM file of 141034 bytes through HTTP
I0715 17:53:57.031419 ServerContext.cpp:260] New instance stored
I0715 17:53:57.042179 OrthancRestApi.cpp:90] Receiving a DICOM file of 141034 bytes through HTTP
I0715 17:53:57.072254 ServerContext.cpp:260] New instance stored
I0715 17:53:57.082064 OrthancRestApi.cpp:90] Receiving a DICOM file of 141032 bytes through HTTP
I0715 17:53:57.114611 ServerContext.cpp:260] New instance stored
I0715 17:53:57.124787 OrthancRestApi.cpp:90] Receiving a DICOM file of 141036 bytes through HTTP
I0715 17:53:57.157123 ServerContext.cpp:260] New instance stored
I0715 17:53:57.167757 OrthancRestApi.cpp:90] Receiving a DICOM file of 141040 bytes through HTTP
I0715 17:53:57.199460 ServerContext.cpp:260] New instance stored

Finally, in the script, we have exited the ShiftDateTime function and now hit the delete/send portions. At this point, no actual deletion occurs. I’m simply printing to the log, so I can see what’s happening.

W0715 17:53:57.199899 LuaContext.cpp:103] Lua says: Deleting
W0715 17:53:57.200535 LuaContext.cpp:103] Lua says: c6e2ee13-bb6736ea-1764b791-d53c768b-8b4112c9
W0715 17:53:57.201080 LuaContext.cpp:103] Lua says: Deleting
W0715 17:53:57.201293 LuaContext.cpp:103] Lua says: 2c849668-31de535a-ef5910e5-0886c8cf-90f982c1
W0715 17:53:57.201443 LuaContext.cpp:103] Lua says: Deleting
W0715 17:53:57.201589 LuaContext.cpp:103] Lua says: bae6f9f1-bc1d3728-488b0dd0-c6fe7f56-f1dc108f
W0715 17:53:57.201734 LuaContext.cpp:103] Lua says: Deleting
W0715 17:53:57.201869 LuaContext.cpp:103] Lua says: 4f88f980-f894d6fe-b7a86988-59d95d69-6aa170ac
W0715 17:53:57.202021 LuaContext.cpp:103] Lua says: Deleting
W0715 17:53:57.202152 LuaContext.cpp:103] Lua says: 4b5e8a88-a0d13258-2e3904a4-856cfd0f-a5cddd49
W0715 17:53:57.202283 LuaContext.cpp:103] Lua says: Sending
W0715 17:53:57.202414 LuaContext.cpp:103] Lua says: 8ae7a558-c54932ce-62d7b6e4-7d25f4be-b53b8089
W0715 17:53:57.202545 LuaContext.cpp:103] Lua says: Sending
W0715 17:53:57.202675 LuaContext.cpp:103] Lua says: 22baee01-f809da7e-21542323-3f85b560-2a497248
W0715 17:53:57.202805 LuaContext.cpp:103] Lua says: Sending
W0715 17:53:57.202939 LuaContext.cpp:103] Lua says: 9c18fe13-8a9f5a9f-1f1beaca-579267df-797b11dc
W0715 17:53:57.203070 LuaContext.cpp:103] Lua says: Sending
W0715 17:53:57.203200 LuaContext.cpp:103] Lua says: db987909-1e322adf-fa5764d4-984611f6-88cb137b
W0715 17:53:57.203335 LuaContext.cpp:103] Lua says: Sending
W0715 17:53:57.203465 LuaContext.cpp:103] Lua says: 3dd0fcab-6e402e84-20c4a958-55ba7591-ae5b9d30

Now, for the finale, a bunch of REST GETS occur. These are on all the newly created instances: the 2nd set of images, anonymized from the first; and the 3rd set of images, modified from the 2nd.

I0715 17:53:57.207938 OrthancPlugins.cpp:941] Plugin making REST GET call on URI /instances/c6e2ee13-bb6736ea-1764b791-d53c768b-8b4112c9 (built-in API)
I0715 17:53:57.210918 OrthancPlugins.cpp:941] Plugin making REST GET call on URI /instances/2c849668-31de535a-ef5910e5-0886c8cf-90f982c1 (built-in API)
I0715 17:53:57.213867 OrthancPlugins.cpp:941] Plugin making REST GET call on URI /instances/bae6f9f1-bc1d3728-488b0dd0-c6fe7f56-f1dc108f (built-in API)
I0715 17:53:57.216765 OrthancPlugins.cpp:941] Plugin making REST GET call on URI /instances/4f88f980-f894d6fe-b7a86988-59d95d69-6aa170ac (built-in API)
I0715 17:53:57.219703 OrthancPlugins.cpp:941] Plugin making REST GET call on URI /instances/4b5e8a88-a0d13258-2e3904a4-856cfd0f-a5cddd49 (built-in API)
I0715 17:53:57.222475 OrthancPlugins.cpp:941] Plugin making REST GET call on URI /instances/8ae7a558-c54932ce-62d7b6e4-7d25f4be-b53b8089 (built-in API)
I0715 17:53:57.224774 OrthancPlugins.cpp:941] Plugin making REST GET call on URI /instances/22baee01-f809da7e-21542323-3f85b560-2a497248 (built-in API)
I0715 17:53:57.226539 OrthancPlugins.cpp:941] Plugin making REST GET call on URI /instances/9c18fe13-8a9f5a9f-1f1beaca-579267df-797b11dc (built-in API)
I0715 17:53:57.228312 OrthancPlugins.cpp:941] Plugin making REST GET call on URI /instances/db987909-1e322adf-fa5764d4-984611f6-88cb137b (built-in API)
I0715 17:53:57.230202 OrthancPlugins.cpp:941] Plugin making REST GET call on URI /instances/3dd0fcab-6e402e84-20c4a958-55ba7591-ae5b9d30 (built-in API)

I think that what is happening is that these REST GET are being queued up during anonymization and modifification calls. For some reason, they do not execute until some time later. You can see from the time stamps that the deletions occur before these REST GET calls. I think that’s why I’m seeing the REST GET exceptions. If these REST GET are being generated by the anonymization/modify routine, they should probably be flushed upon exit from those routines, rather than some time later.

John.