Tested on 0.9 and 0.11 with ruby 2.4.4.
Let's say we have:
class A
extend LightService::Organizer
def self.call(id)
with(id: id).around_each(LogDuration).reduce(steps)
end
def self.steps
[
A,
reduce_if(->(ctx) { !ctx.failure? }, [
B,
C,
D,
E,
F
]),
reduce_if(->(ctx) { ctx.debug_mode == true && !ctx.failure? }, [
G
])
]
end
end
LogDuration is the same as in the readme.
Expectation: around_each logs every execution time of each action from A to G.
Reality: around_each logs execution time of action A, F and G, and is wrong for F's execution time:
it "merges" execution times of B + C + D + E + F and advertise it as F's execution time. It then display F execution's time normally a second time.
Some trace:
I, [2018-05-30T17:40:39.472703 #17990] INFO -- : [LightService] - executing < G >
I, [2018-05-30T17:40:39.472797 #17990] INFO -- : [LightService] - expects: :start_time
I, [2018-05-30T17:40:39.472841 #17990] INFO -- : [LightService] - keys in context: :start_time, :debug_mode
I, [2018-05-30T17:40:39.972753 #17990] INFO -- : [LightService] - executing < F >
I, [2018-05-30T17:40:39.972851 #17990] INFO -- : [LightService] - expects: [...]
I, [2018-05-30T17:40:39.972948 #17990] INFO -- : {:action=>F, :duration=>2.418829613001435}
I, [2018-05-30T17:40:39.973028 #17990] INFO -- : [LightService] - executing <#<Proc:0x0000000006eb4528@/home/pak/attract/roar/.bundle/ruby/2.4.0/gems/light-service-0.11.0/lib/light-service/organizer/reduce_if.rb:7 (lambda)>>
I, [2018-05-30T17:40:39.973076 #17990] INFO -- : [LightService] - keys in context: [...]
I, [2018-05-30T17:40:39.973143 #17990] INFO -- : {:action=>F, :duration=>2.3894001060398296e-05}
I, [2018-05-30T17:40:39.973207 #17990] INFO -- : [LightService] - executing <#<Proc:0x0000000006eacf08@/home/pak/attract/roar/.bundle/ruby/2.4.0/gems/light-service-0.11.0/lib/light-service/organizer/reduce_if.rb:7 (lambda)>>
79 was coded and merged before #91 and #132 so I guess it's an unintended behavior ?
Yeah, logging has not been brought up to speed with all the Orchestrator logic. I have not confirmed it yet, but it's high likely this is correct. Thanks for reporting it!
Tested on 0.9 and 0.11 with ruby 2.4.4. Let's say we have:
LogDuration
is the same as in the readme. Expectation:around_each
logs every execution time of each action from A to G. Reality:around_each
logs execution time of action A, F and G, and is wrong for F's execution time:it "merges" execution times of B + C + D + E + F and advertise it as F's execution time. It then display F execution's time normally a second time.
Some trace:
79 was coded and merged before #91 and #132 so I guess it's an unintended behavior ?