#2 application runtime problem

[Marie-Francoise Incardona]

With a pluin that executes a simple ALTime(10), an ALApplication seems to stop before the end (run time found at 1.2 instead of more that 10 sec) of the sleep... the strange thing is that with option that slow the system (--DEBUG, jython instead of python), the runtime is well calculated:

Here is an example of Error case:
--------------------------------

[ 2007/11/26 14:22:02 ] Resource::Loaded = /scisoft/users/incardon/.EDTestApplication-v0.1/EDTestApplication-v0.1.res
[ 2007/11/26 14:22:03 ] /mntdirect/_scisoft/users/incardon/WorkSpace-321-redhat40-i686-v20/edna/prototype/tmp-olof/PluginIndexingMOSFLM/modules/EDTestApplication.py --verbose --test
[ 2007/11/26 14:22:03 ] EDTestApplication-v0.1::Starting
[ 2007/11/26 14:22:03 ] Resource::Loaded = /scisoft/users/incardon/.EDTestApplication-v0.1/EDTestApplication-v0.1.res
[ 2007/11/26 14:22:03 ] Last Run: [ 2007/11/26 14:21:47 ]
[ 2007/11/26 14:22:03 ] Total Actions: 2
[ 2007/11/26 14:22:03 ] Running Actions: 0
[ 2007/11/26 14:22:03 ] Stopped Actions: 2
[ 2007/11/26 14:22:03 ] [objALCommandLine] - Run Time [s]: 0.00304102897644
[ 2007/11/26 14:22:03 ] [objALCommandLineInterface] - Run Time [s]: 0.00227808952332
[ 2007/11/26 14:22:03 ] Starting command line
[ 2007/11/26 14:22:03 ] Total Actions: 3
[ 2007/11/26 14:22:03 ] Running Actions: 1
[ 2007/11/26 14:22:03 ] Stopped Actions: 2
[ 2007/11/26 14:22:03 ] Starting EDPluginTest
[ 2007/11/26 14:22:03 ] ***Waiting for 10 sec....***
[ 2007/11/26 14:22:04 ] Resource::Saved = /scisoft/users/incardon/.EDTestApplication-v0.1/EDTestApplication-v0.1.res
[ 2007/11/26 14:22:04 ] ########################################### [ Actions Log tree ]
[ 2007/11/26 14:22:04 ] ################################################################
[ 2007/11/26 14:22:04 ] [ Action log Tree: ALCommandLine-0200-3629-4303-4255-0040-3201]
[ 2007/11/26 14:22:04 ] ==>[ 2007/11/26 14:22:03 ] [DEBUG]: [Thread] Starting instance: <ALCommandLine(Thread-4, initial)>
[ 2007/11/26 14:22:04 ] ==>[ 2007/11/26 14:22:03 ] [DEBUG]: [Thread] parameter: None
[ 2007/11/26 14:22:04 ] ==>[ 2007/11/26 14:22:03 ] [DEBUG]: Execution: ALAction.preProcess()
[ 2007/11/26 14:22:04 ] ==>[ 2007/11/26 14:22:03 ] [DEBUG]: Execution: ALAction.postProcess()
[ 2007/11/26 14:22:04 ] ################################################################
[ 2007/11/26 14:22:04 ] [ Action log Tree: ALCommandLineInterface-0200-8347-8328-8139-0002-1094]
[ 2007/11/26 14:22:04 ] ==>[ 2007/11/26 14:22:03 ] [DEBUG]: [Thread] Starting instance: <ALCommandLineInterface(Thread-8, initial)>
[ 2007/11/26 14:22:04 ] ==>[ 2007/11/26 14:22:03 ] [DEBUG]: [Thread] parameter: None
[ 2007/11/26 14:22:04 ] ==>[ 2007/11/26 14:22:03 ] [DEBUG]: Execution: ALAction.preProcess()
[ 2007/11/26 14:22:04 ] ==>[ 2007/11/26 14:22:03 ] [DEBUG]: Execution: ALAction.postProcess()
[ 2007/11/26 14:22:04 ] ################################################################
[ 2007/11/26 14:22:04 ] [ Action log Tree: EDPluginCommandLine-0200-3518-3109-2238-0020-0430]
[ 2007/11/26 14:22:04 ] ==>[ 2007/11/26 14:22:03 ] [DEBUG]: [Thread] Starting instance: <EDPluginCommandLine(Thread-9, initial)>
[ 2007/11/26 14:22:04 ] ==>[ 2007/11/26 14:22:03 ] [DEBUG]: [Thread] parameter: <ALApplication.ALApplication object at 0xb3c3a94c>
[ 2007/11/26 14:22:04 ] ==>[ 2007/11/26 14:22:03 ] [DEBUG]: Thread::STOPPED under control: objEDPluginCommandLine EDPluginCommandLine-0200-3518-3109-2238-0020-0430
[ 2007/11/26 14:22:04 ] ==>[ 2007/11/26 14:22:03 ] [DEBUG]: Action::STOPPED under control: objEDPluginCommandLine EDPluginCommandLine-0200-3518-3109-2238-0020-0430
[ 2007/11/26 14:22:04 ] ################################################################
[ 2007/11/26 14:22:04 ] [ Action log Tree: ALCommandLine-0200-1331-9599-0175-0021-7240]
[ 2007/11/26 14:22:04 ] ==>[ 2007/11/26 14:22:03 ] [DEBUG]: [Thread] Starting instance: <ALCommandLine(Thread-10, initial)>
[ 2007/11/26 14:22:04 ] ==>[ 2007/11/26 14:22:03 ] [DEBUG]: [Thread] parameter: None
[ 2007/11/26 14:22:04 ] ==>[ 2007/11/26 14:22:03 ] [DEBUG]: Execution: ALAction.preProcess()
[ 2007/11/26 14:22:04 ] ==>[ 2007/11/26 14:22:03 ] [DEBUG]: Execution: ALAction.postProcess()
[ 2007/11/26 14:22:04 ] ################################################################
[ 2007/11/26 14:22:04 ] [ Action log Tree: EDPluginTest-0200-3664-9010-5526-0011-7849]
[ 2007/11/26 14:22:04 ] ==>[ 2007/11/26 14:22:03 ] [DEBUG]: [Thread] Starting instance: <EDPluginTest(Thread-11, initial)>
[ 2007/11/26 14:22:04 ] ==>[ 2007/11/26 14:22:03 ] [DEBUG]: [Thread] parameter: --test
[ 2007/11/26 14:22:04 ] ==>[ 2007/11/26 14:22:03 ] Starting EDPluginTest
[ 2007/11/26 14:22:04 ] ==>[ 2007/11/26 14:22:03 ] ***Waiting for 10 sec....***
[ 2007/11/26 14:22:04 ] ################################################################
[ 2007/11/26 14:22:04 ] [ Action log Tree: ALActionProcess-0200-4728-8436-4373-0065-9077]
[ 2007/11/26 14:22:04 ] ==>[ 2007/11/26 14:22:03 ] [DEBUG]: [Thread] Starting instance: <ALActionProcess(Thread-13, initial)>
[ 2007/11/26 14:22:04 ] ==>[ 2007/11/26 14:22:03 ] [DEBUG]: [Thread] parameter: None
[ 2007/11/26 14:22:04 ] ==>[ 2007/11/26 14:22:03 ] [DEBUG]: Execution: ALActionProcess.preProcess()
[ 2007/11/26 14:22:04 ] ==>[ 2007/11/26 14:22:03 ] [DEBUG]: Execution: ALAction.preProcess()
[ 2007/11/26 14:22:04 ] ==>[ 2007/11/26 14:22:03 ] [DEBUG]: Execution: ALActionProcess.process()
[ 2007/11/26 14:22:04 ] EDTestApplication-v0.1::Closing
[ 2007/11/26 14:22:04 ] EDTestApplication-v0.1::Runtime: 1.62360310555 [s]
[ 2007/11/26 14:22:13 ] ***10 sec done!***
[ 2007/11/26 14:22:13 ] Finished EDPluginTest

--> Application RunTime: 1.62360310555 [s] instead of more that 10

Example where it works: with --DEBUG:
------------------------------------

[ 2007/11/26 14:09:34 ] ==>[ 2007/11/26 14:09:22 ] [DEBUG]: [Thread] Starting instance: <ALCommandLine(Thread-7, initial)>
[ 2007/11/26 14:09:34 ] ==>[ 2007/11/26 14:09:22 ] [DEBUG]: [Thread] parameter: None
[ 2007/11/26 14:09:34 ] ==>[ 2007/11/26 14:09:22 ] [DEBUG]: Execution: ALAction.preProcess()
[ 2007/11/26 14:09:34 ] ==>[ 2007/11/26 14:09:22 ] [DEBUG]: Execution: ALAction.postProcess()
[ 2007/11/26 14:09:34 ] ################################################################
[ 2007/11/26 14:09:34 ] [ Action log Tree: EDPluginTest-0200-9760-8114-4546-0025-9432]
[ 2007/11/26 14:09:34 ] ==>[ 2007/11/26 14:09:22 ] [DEBUG]: [Thread] Starting instance: <EDPluginTest(Thread-8, initial)>
[ 2007/11/26 14:09:34 ] ==>[ 2007/11/26 14:09:22 ] [DEBUG]: [Thread] parameter: --test
[ 2007/11/26 14:09:34 ] ################################################################
[ 2007/11/26 14:09:34 ] [ Action log Tree: ALActionProcess-0200-9873-5047-1453-0046-0550]
[ 2007/11/26 14:09:34 ] ==>[ 2007/11/26 14:09:22 ] [DEBUG]: [Thread] Starting instance: <ALActionProcess(Thread-10, initial)>
[ 2007/11/26 14:09:34 ] ==>[ 2007/11/26 14:09:22 ] [DEBUG]: [Thread] parameter: None
[ 2007/11/26 14:09:34 ] ==>[ 2007/11/26 14:09:22 ] [DEBUG]: Execution: ALActionProcess.preProcess()
[ 2007/11/26 14:09:34 ] ==>[ 2007/11/26 14:09:22 ] [DEBUG]: Execution: ALAction.preProcess()
[ 2007/11/26 14:09:34 ] ==>[ 2007/11/26 14:09:22 ] [DEBUG]: Execution: ALActionProcess.process()
[ 2007/11/26 14:09:34 ] ==>[ 2007/11/26 14:09:23 ] [DEBUG]: Execution: ALActionProcess.postProcess()
[ 2007/11/26 14:09:34 ] ==>[ 2007/11/26 14:09:23 ] [DEBUG]: Execution: ALAction.postProcess()
[ 2007/11/26 14:09:34 ] EDTestApplication-v0.1::Closing
[ 2007/11/26 14:09:34 ] EDTestApplication-v0.1::Runtime: 12.1353909969 [s]