[infinispan-dev] More verbose logging

[Manik Surtani]

Guys,

I see this emitted by the CommandAwareRpcDispatcher:

2013-02-19 16:22:13,988 TRACE [CommandAwareRpcDispatcher] (OOB-1,ISPN,NodeB-11464) Attempting to execute command: StateResponseCommand{cache=___defaultcache, origin=NodeA-62578, topologyId=1, stateChunks=[StateChunk{segmentId=0, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=1, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=2, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=3, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=4, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=5, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=6, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=7, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=8, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=9, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=10, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=11, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=12, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=13, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=14, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=15, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=17, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=16, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=19, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=18, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=21, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=20, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=23, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=22, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=25, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=24, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=27, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=26, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=29, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=28, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=31, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=30, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=34, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=35, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=32, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=33, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=38, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=39, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=36, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=37, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=42, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=43, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=40, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=41, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=46, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=47, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=44, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=45, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=51, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=50, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=49, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=48, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=55, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=54, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=53, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=52, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=59, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=58, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=57, cacheEntries=[], isLastChunk=true}, StateChunk{segmentId=56, cacheEntries=[], isLastChunk=true}]} [sender=NodeA-62578]


Again, just 3 nodes, default segment size, but with TRACE level logging.  

a) This would explode to something huge if we have, say, a cluster of 100+ nodes with, say, 5000 segments.
b) Each StateChunk is listing all of its entries!  Again, here this is fine since the cache is empty; but a running system with a few hundred GB of data would make enabling TRACE logging akin to a DoS attack.

I agree that TRACE level logging on a running system is not recommended, and generally will slow things down a lot, but this has potential to bring a cluster down.  I imagine such information is only really useful in a lab or test environment when tracing edge-case consistency issues - so maybe we need a separate flag?  Perhaps a -Dinfinispan.logging.verbose=true, which would alter the output of StateResponseCommand.toString() accordingly?

- M

--
Manik Surtani
manik at jboss.org
twitter.com/maniksurtani

Platform Architect, JBoss Data Grid
http://red.ht/data-grid