WIP: Add hook execution logging
#782 implements hooks execution logging in scans.
This PR introduces a more general solution to printing logs when executing hooks - it is not restricted to scans and work with any macro.
It is still WIP - for the moment works only with hooks added with Hookable.appendHook()
and not the ones with the Hookable.hooks
property setter. If you like this more general idea, I could also implement it for the property setter.
Here is how it looks like:
Door_zreszela_1 [28]: defgh "mv mot02 0" pre-acq
Defining general hook
mv mot02 0
Door_zreszela_1 [29]: debug on
debug mode is now on
Door_zreszela_1 [30]: ascan mot01 0 1 1 0.1
[START] runMacro Macro 'ascan(mot01, 0.0, 1.0, 1, 0.1) -> 39594a5e-67c9-11eb-b709-4ce17347e857'
Operation will be saved in /tmp/scan3.h5 (Spec from SPEC_FileRecorder)
Scan #21 started at Fri Feb 5 16:45:51 2021. It will take at least 0:00:00.765685
#Pt No mot01 ct01 ct02 ct03 ct04 zerod01 dt
Start hook: mv([['mot02', '0']]) at hook place pre-acq
Executing macro: mv
[START] runMacro Macro 'mv([['mot02', '0.0']]) -> None'
Starting mot02 movement to 0.0
[ END ] runMacro Macro 'mv([['mot02', '0.0']]) -> None'
End hook: mv([['mot02', '0']]) at hook place pre-acq
0 0 0.1 0.2 0.3 0.4 101.172 0.313357
Start hook: mv([['mot02', '0']]) at hook place pre-acq
Executing macro: mv
[START] runMacro Macro 'mv([['mot02', '0.0']]) -> None'
Starting mot02 movement to 0.0
[ END ] runMacro Macro 'mv([['mot02', '0.0']]) -> None'
End hook: mv([['mot02', '0']]) at hook place pre-acq
1 1 0.1 0.2 0.3 0.4 100.659 0.791111
Operation saved in /tmp/scan3.h5 (Spec)
Scan #21 ended at Fri Feb 5 16:45:52 2021, taking 0:00:00.972370. Dead time 79.4% (motion dead time 63.6%)
[ END ] runMacro Macro 'ascan(mot01, 0.0, 1.0, 1, 0.1) -> 39594a5e-67c9-11eb-b709-4ce17347e857'
Job ended (stopped=False, aborted=False)
It should also already work for the simple callable hooks (not macros).
@AntoineDupre, @13bscsaamjad could you check if this also solves your need?