Reporting 'normal' events is spammy, don't do it #334

Merged
merged 1 commit into from Jun 13, 2013

Conversation

Projects
None yet
4 participants
Contributor

slfritchie commented Jun 7, 2013

Avoid log spamminess like this:

14:42:43.877 [info] 1141798154164767904846628775559596109106197299200 riak_kv_vnode ignored handle_info {'DOWN',#Ref<0.0.1.47104>,process,<0.9841.1>,normal} - vnode unregistering
14:42:47.720 [info] 1324485858831130769622089379649131486563188867072 riak_kv_vnode ignored handle_info {'DOWN',#Ref<0.0.1.42852>,process,<0.9416.1>,normal} - vnode unregistering
14:42:48.050 [info] 502391187832497878132516661246222288006726811648 riak_kv_vnode ignored handle_info {'DOWN',#Ref<0.0.1.49271>,process,<0.10111.1>,normal} - vnode unregistering
14:43:14.399 [info] 936274486415109681974235595958868809467081785344 riak_kv_vnode ignored handle_info {'DOWN',#Ref<0.0.1.52833>,process,<0.10501.1>,normal} - vnode unregistering
14:43:27.347 [info] 685078892498860742907977265335757665463718379520 riak_kv_vnode ignored handle_info {'DOWN',#Ref<0.0.1.49219>,process,<0.10092.1>,normal} - vnode unregistering
14:43:57.701 [info] 1027618338748291114361965898003636498195577569280 riak_kv_vnode ignored handle_info {'DOWN',#Ref<0.0.1.52781>,process,<0.10482.1>,normal} - vnode unregistering

slfritchie was assigned Jun 7, 2013

Contributor

jonmeredith commented on 77bab30 Jun 7, 2013

Are you sure this isn't hiding some other problem? Why are 'DOWN' messages being delivered in the first place?

Contributor

slfritchie replied Jun 7, 2013

Example: after handoff, the vnode shuts down. It exits with normal. That's wonderful, things are working as they're supposed to, but don't spam about it. The new clause is pattern matching on exactly the normal case and no other.

Contributor

slfritchie replied Jun 7, 2013

See also: the PR comment in #334

Contributor

slfritchie commented Jun 10, 2013

Ping ... the freeze is quickly approaching ...

Contributor

slfritchie commented Jun 12, 2013

I'm a leavin' in a jet plane tomorrow ... ping.

Contributor

jrwest commented Jun 13, 2013

believe I tracked down the source of these messages: the monitor riak_kv_vnode sets on its aae trees -- so ignoring these is in fact harmless. Turning aae off w/o this fix will get rid of the messages. With this fix + aae on the messages are also gone. +1.

slfritchie merged commit 28f1a04 into master Jun 13, 2013

1 check failed

default The Travis CI build failed
Details

@beerriot beerriot pushed a commit that referenced this pull request Jun 19, 2013

Bryan Fink only silently drop DOWN-normal messages in deleted modstate
This is a restriction of the modification made in PR #334.

Dropping all {'DOWN',_,process,_,normal} messages on the floor instead
of passing them to vnode handle_info functions causes riak_pipe vnodes
to missing messages that it uses to cleanup workers for pipes that
shutdown unexpectedly.

This commit restricts the DOWN-normal message dropping to the case
that the vnode's modstate is {deleted, _}. PR #334 suggests the original
modification was made only to quiet the log spam generated by the
following clause, which also only operates in modstate-deleted.

Before this commit, the riak_test pipe_verify_exceptions would fail
during its verify_middle_fitting_normal test, because workers would be
left running after the fitting exited 'normal'. After this commit,
workers are once again terminated correctly, so the test passes again.
55a753a

evanmcc was assigned Jul 2, 2013

seancribbs deleted the slf-no-log-spam-on-normal-shutdown branch Apr 1, 2015

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment