realtime_block: log timings on exception in outermost block #255

cben · 2017-08-07T12:23:59Z

When realtime_block is aborted with exception, the timings are still there in the hash, so a higher level may log them.
Unless that is this was the outermost block, in which case they're lost.
This PR logs them in such case.

Example:

[----] E, [2017-08-07T15:04:08.145415 #14296:2aaca3b530cc] ERROR -- : MIQ(ManageIQ::Providers::Openshift::ContainerManager::Refresher#refresh) EMS: [scale-ocp-36-c03], id: [3] Refresh failed
[----] E, [2017-08-07T15:04:08.145736 #14296:2aaca3b530cc] ERROR -- : [KubeException]: Timed out connecting to server  Method:[block in method_missing]
[----] E, [2017-08-07T15:04:08.145855 #14296:2aaca3b530cc] ERROR -- : /home/bpaskinc/myenv/rbenv/versions/2.3.4/lib/ruby/gems/2.3.0/gems/kubeclient-2.4.0/lib/kubeclient/common.rb:117:in `rescue in handle_exception'
...
bin/rails:4:in `<main>'
[----] E, [2017-08-07T15:04:08.145951 #14296:2aaca3b530cc] ERROR -- : MIQ(ManageIQ::Providers::Openshift::ContainerManager::Refresher#refresh) EMS: [scale-ocp-36-c03], id: [3] Unable to perform refresh for the following targets:
[----] E, [2017-08-07T15:04:08.146105 #14296:2aaca3b530cc] ERROR -- : MIQ(ManageIQ::Providers::Openshift::ContainerManager::Refresher#refresh)  --- ManageIQ::Providers::Openshift::ContainerManager [scale-ocp-36-c03] id [3]
[----] I, [2017-08-07T15:04:08.236129 #14296:2aaca3b530cc]  INFO -- : MIQ(ManageIQ::Providers::Openshift::ContainerManager::Refresher#refresh) Refreshing all targets...Complete
[----] I, [2017-08-07T15:04:08.236201 #14296:2aaca3b530cc]  INFO -- : Exception in realtime_block :ems_total_refresh - Timings: {:collect_inventory_for_targets=>60.113999128341675, :ems_refresh=>60.11402702331543, :ems_total_refresh=>60.208136320114136}

This is not water-tight against Timeout.timeout.
Timeout inside the block logged:
```
Benchmark.realtime_block(:sleep) { Timeout.timeout(3) { sleep(10) } }
```
but outside it didn't:
```
Timeout.timeout(3) { Benchmark.realtime_block(:sleep) { sleep(10) } }
```
(See also Benchmark.realtime_block's ensure can be interrupted by a MiqQueue TimeoutError manageiq#9642 for more Timeout woes)

cben · 2017-08-08T12:17:49Z

@moolitayer asked if this needs an issue / BZ.
Don't think so, "good logging" is not a well defined feature we promise users :-)
It's when other issues happen and we debug from logs that this might help...

https://bugzilla.redhat.com/show_bug.cgi?id=1440950 is one example of "normal" exception where this could have improved logs.
https://bugzilla.redhat.com/show_bug.cgi?id=1428570 is one example of Timeout killing the thread, where PR probably won't help.

cben · 2017-08-08T12:55:49Z

@jrafanie @Fryguy @agrare please review.

moolitayer · 2017-08-08T13:32:55Z

@cben sorry my comment was not clear, I don't think we need a general logging issue. (see ManageIQ/manageiq-providers-kubernetes#82 (comment))

jrafanie · 2017-08-08T14:25:09Z

lib/gems/pending/util/extensions/miq-benchmark.rb

@@ -29,6 +29,10 @@ def self.realtime_block(key, &block)
    begin
      ret = realtime_store(hash, key, &block)
      return ret, hash
+    rescue
+      # Don't let timings be lost on exception when there is nobody else to pick them up.
+      $log.info("Exception in realtime_block #{key.inspect} - Timings: #{hash.inspect}") if outermost


There are no other log lines in this file. It probably shouldn't expect $log to be defined and instead be initialized with a logger... But, for a surgical change, maybe add if $log && outermost

The Benchmark extension is meant to be non-miq-specific. In fact, it's on the list to be moved to more_core_extensions. Imagine it's in more_core, how would this change work?

I'm clueless about how all the $log, _log thingies come to be (storks?), please advise...

The OOP answer is not use Benchmark class methods but an object intialized with a logger. meh — much hassle, and pushes similar problem onto the users that would want a global instance...

realtime_block could take a logger option, but again too much hassle to pass it everywhere, especially for an edge case.

could have some accessor Benchmark.realtime_block_logger = ... to be initialized once in apps that have logging. (need advice where to set in MIQ?)

just default to logging to stderr, might be good enough for a rare edge case?

I also wanted to propose a convenience realtime_log_once function that logs timing IFF it's the outermost, and only returns the result, so callers don't need to discard result, _ = ....
Same considerations, except it's standard flow, not an edge case.

@cben I agree.

Creating an instance that you pass a logger seems like a hassle.

Using a class accessor on Benchmark to set a logger might work but then the caller knows about benchmark... I guess. It might work? See here where we create the loggers and setup the external loggers.

stderr should work too. Try that first and see if the workers log it. I think that's the simplest approach. We should be keeping stderr.

app/models/miq_worker.rb: pid = Kernel.spawn(self.class.build_command_line(guid), [:out, :err] => [Rails.root.join("log", "evm.log"), "a"]) lib/tasks/evm_application.rb: pid = Kernel.spawn(env_options, command_line, :pgroup => true, [:out, :err] => [Rails.root.join("log/evm.log"), "a"])

The only other thing I can think of is a top-level accessor that has the "last" value's run... Something like a last_realtime_block_result. Downside is you would have this thing hanging around forever, but it isn't very big.

Try that first and see if the workers log it.

Again, you have to put on your non-manageiq hat, because that's where the class is going. This makes no sense if some random project uses it.

It makes perfect sense for a library to write to stderr on errors if they don't provide a facility for specifying a logger.

Done, hardcoded Logger.new($stderr), PTAL. If anyone wants more configuration, do a followup PR :)

Added tests, which made me fix rescue to catch any Exception.
Sneaked in a timecop version bump, to be able to do fractional travel for a simpler-matching regexp. Being a dev gemspec dependency, I believe it's safe to bump without affecting other repos (eg. my manageiq dir with override_gem to this gems-pending is still getting timecop 0.7.3, no conflict).

jrafanie · 2017-08-08T14:25:34Z

Tangentially related: #139

miq-bot · 2017-09-11T20:28:22Z

This pull request is not mergeable. Please rebase and repush.

Specifically want to pick up Timecop.travel(float) fix travisjeffery/timecop#178

Not necessary in inner blocks as timing still gets stored in hash and if caught will be returned from some outer block. When outermost block crashes, the whole hash is about to be discarded.

miq-bot · 2017-09-27T10:23:14Z

Checked commits cben/manageiq-gems-pending@a299923~...b207c1f with ruby 2.2.6, rubocop 0.47.1, and haml-lint 0.20.0
2 files checked, 2 offenses detected

lib/gems/pending/util/extensions/miq-benchmark.rb

⚠️ - Line 37, Col 9 - Lint/RescueException - Avoid rescuing the Exception class. Perhaps you meant to rescue StandardError?

spec/util/extensions/miq-benchmark_spec.rb

⚠️ - Line 92, Col 9 - Lint/RescueException - Avoid rescuing the Exception class. Perhaps you meant to rescue StandardError?

chessbyte · 2017-10-24T21:44:25Z

@jrafanie @Fryguy @agrare please review.

jrafanie

LGTM, I don't think the timecop upgrade should cause problems with manageiq, but we'll find out soon enough.

cben mentioned this pull request Aug 7, 2017

Refresher: Split collection from parsing methods ManageIQ/manageiq-providers-kubernetes#82

Merged

jrafanie reviewed Aug 8, 2017

View reviewed changes

miq-bot added the unmergeable label Sep 11, 2017

Bump timecop to latest

a299923

Specifically want to pick up Timecop.travel(float) fix travisjeffery/timecop#178

cben force-pushed the realtime-log branch from 8243cd7 to 0fc0ab1 Compare September 27, 2017 10:07

miq-bot removed the unmergeable label Sep 27, 2017

realtime_block: log timings to stderr on exception in outermost block

b207c1f

Not necessary in inner blocks as timing still gets stored in hash and if caught will be returned from some outer block. When outermost block crashes, the whole hash is about to be discarded.

cben force-pushed the realtime-log branch from 0fc0ab1 to b207c1f Compare September 27, 2017 10:18

chessbyte requested a review from agrare October 18, 2017 15:51

chessbyte assigned Fryguy Oct 18, 2017

chessbyte added the enhancement label Oct 18, 2017

jrafanie approved these changes Oct 25, 2017

View reviewed changes

jrafanie merged commit 0df3823 into ManageIQ:master Oct 25, 2017

jrafanie added this to the Sprint 72 Ending Oct 30, 2017 milestone Oct 25, 2017

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

realtime_block: log timings on exception in outermost block #255

realtime_block: log timings on exception in outermost block #255

cben commented Aug 7, 2017 •

edited

Loading

cben commented Aug 8, 2017

cben commented Aug 8, 2017

moolitayer commented Aug 8, 2017

jrafanie Aug 8, 2017

Fryguy Aug 11, 2017

cben Aug 15, 2017

jrafanie Aug 15, 2017

Fryguy Aug 24, 2017

Fryguy Aug 24, 2017

jrafanie Aug 31, 2017

cben Sep 27, 2017

jrafanie commented Aug 8, 2017

miq-bot commented Sep 11, 2017

miq-bot commented Sep 27, 2017

chessbyte commented Oct 24, 2017

jrafanie left a comment

realtime_block: log timings on exception in outermost block #255

realtime_block: log timings on exception in outermost block #255

Conversation

cben commented Aug 7, 2017 • edited Loading

cben commented Aug 8, 2017

cben commented Aug 8, 2017

moolitayer commented Aug 8, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jrafanie commented Aug 8, 2017

miq-bot commented Sep 11, 2017

miq-bot commented Sep 27, 2017

chessbyte commented Oct 24, 2017

jrafanie left a comment

Choose a reason for hiding this comment

cben commented Aug 7, 2017 •

edited

Loading