Hi Jeremy, you're running with TRACE logging turned on which can be very verbose, I'd suggest you run with INFO level in normal circumstances.
Patrick On Thu, Jul 7, 2011 at 10:40 AM, Jeremy Stribling <[email protected]> wrote: > Has anyone ever seen Zookeeper explode with a flood of "outstanding > proposal" messages? I'm running 3.3.3* with three nodes (under fairly > stressful client load), and all of the sudden one of the nodes' logs starts > filling up with these messages: > > 2011-07-06 18:37:51,161 628684 [ProcessThread:-1] TRACE > org.apache.zookeeper.server.PrepRequestProcessor - > :Psessionid:0x5d310234eaf10002 type:delete cxid:0x4e15574f > zxid:0xfffffffffffffffe txntype:unknown > reqpath:/zkrsm/cpt-0000000000000009-000000000000afc8/0000000000000009_record0000003293 > 2011-07-06 18:37:51,162 628685 [ProcessThread:-1] DEBUG > org.apache.zookeeper.server.quorum.CommitProcessor - Processing request:: > sessionid:0x5d310234eaf10002 type:delete cxid:0x4e15574f zxid:0x40000121c > txntype:2 reqpath:n/a > 2011-07-06 18:37:51,162 628685 [SyncThread:177] TRACE > org.apache.zookeeper.server.quorum.Leader - Ack zxid: 0x4000011fb > 2011-07-06 18:37:51,162 628685 [SyncThread:177] TRACE > org.apache.zookeeper.server.quorum.Leader - outstanding proposal: > 0x400001204 > 2011-07-06 18:37:51,162 628685 [SyncThread:177] TRACE > org.apache.zookeeper.server.quorum.Leader - outstanding proposal: > 0x40000120d > 2011-07-06 18:37:51,162 628685 [SyncThread:177] TRACE > org.apache.zookeeper.server.quorum.Leader - outstanding proposal: > 0x400001207 > 2011-07-06 18:37:51,162 628685 [SyncThread:177] TRACE > org.apache.zookeeper.server.quorum.Leader - outstanding proposal: > 0x400001215 > 2011-07-06 18:37:51,162 628685 [SyncThread:177] TRACE > org.apache.zookeeper.server.quorum.Leader - outstanding proposal: > 0x4000011fe > 2011-07-06 18:37:51,162 628685 [SyncThread:177] TRACE > org.apache.zookeeper.server.quorum.Leader - outstanding proposal: > 0x400001208 > 2011-07-06 18:37:51,162 628685 [SyncThread:177] TRACE > org.apache.zookeeper.server.quorum.Leader - outstanding proposal: > 0x400001214 > 2011-07-06 18:37:51,162 628685 [SyncThread:177] TRACE > org.apache.zookeeper.server.quorum.Leader - outstanding proposal: > 0x400001219 > 2011-07-06 18:37:51,162 628685 [SyncThread:177] TRACE > org.apache.zookeeper.server.quorum.Leader - outstanding proposal: > 0x400001206 > 2011-07-06 18:37:51,162 628685 [SyncThread:177] TRACE > org.apache.zookeeper.server.quorum.Leader - outstanding proposal: > 0x400001201 > 2011-07-06 18:37:51,162 628685 [SyncThread:177] TRACE > org.apache.zookeeper.server.quorum.Leader - outstanding proposal: > 0x400001213 > 2011-07-06 18:37:51,162 628685 [SyncThread:177] TRACE > org.apache.zookeeper.server.quorum.Leader - outstanding proposal: > 0x4000011ff > 2011-07-06 18:37:51,162 628685 [SyncThread:177] TRACE > org.apache.zookeeper.server.quorum.Leader - outstanding proposal: > 0x40000121a > 2011-07-06 18:37:51,162 628685 [SyncThread:177] TRACE > org.apache.zookeeper.server.quorum.Leader - outstanding proposal: > 0x400001200 > 2011-07-06 18:37:51,162 628685 [SyncThread:177] TRACE > org.apache.zookeeper.server.quorum.Leader - outstanding proposal: > 0x40000121b > 2011-07-06 18:37:51,162 628685 [SyncThread:177] TRACE > org.apache.zookeeper.server.quorum.Leader - outstanding proposal: > 0x400001209 > 2011-07-06 18:37:51,162 628685 [SyncThread:177] TRACE > org.apache.zookeeper.server.quorum.Leader - outstanding proposal: > 0x400001212 > 2011-07-06 18:37:51,162 628685 [SyncThread:177] TRACE > org.apache.zookeeper.server.quorum.Leader - outstanding proposal: > 0x4000011fc > 2011-07-06 18:37:51,162 628685 [SyncThread:177] TRACE > org.apache.zookeeper.server.quorum.Leader - outstanding proposal: > 0x400001211 > 2011-07-06 18:37:51,162 628685 [SyncThread:177] TRACE > org.apache.zookeeper.server.quorum.Leader - outstanding proposal: > 0x400001203 > 2011-07-06 18:37:51,162 628685 [SyncThread:177] TRACE > org.apache.zookeeper.server.quorum.Leader - outstanding proposal: > 0x40000120a > 2011-07-06 18:37:51,162 628685 [SyncThread:177] TRACE > org.apache.zookeeper.server.quorum.Leader - outstanding proposal: > 0x4000011fd > 2011-07-06 18:37:51,162 628685 [SyncThread:177] TRACE > org.apache.zookeeper.server.quorum.Leader - outstanding proposal: > 0x400001210 > 2011-07-06 18:37:51,162 628685 [SyncThread:177] TRACE > org.apache.zookeeper.server.quorum.Leader - outstanding proposal: > 0x400001218 > 2011-07-06 18:37:51,162 628685 [SyncThread:177] TRACE > org.apache.zookeeper.server.quorum.Leader - outstanding proposal: > 0x400001202 > 2011-07-06 18:37:51,162 628685 [SyncThread:177] TRACE > org.apache.zookeeper.server.quorum.Leader - outstanding proposal: > 0x40000120b > 2011-07-06 18:37:51,162 628685 [SyncThread:177] TRACE > org.apache.zookeeper.server.quorum.Leader - outstanding proposal: > 0x400001216 > 2011-07-06 18:37:51,162 628685 [SyncThread:177] TRACE > org.apache.zookeeper.server.quorum.Leader - outstanding proposal: > 0x40000120f > 2011-07-06 18:37:51,162 628685 [SyncThread:177] TRACE > org.apache.zookeeper.server.quorum.Leader - outstanding proposal: > 0x400001217 > 2011-07-06 18:37:51,162 628685 [SyncThread:177] TRACE > org.apache.zookeeper.server.quorum.Leader - outstanding proposal: > 0x40000120c > > It goes on like that for hundreds of megabytes over a few minutes, until we > killed the test. As far as I can tell, there were no node churn events that > sparked this. > > I can provide the full set of logs and/or file a JIRA, but I thought I'd do > a quick check first to see if this sparked anyone's memory. > > Thanks, > > Jeremy > > * I have applied a few patches on top of 3.3.3, namely a homegrown, > temporary patch for ZOOKEEPER-1046 and one for ZOOKEEPER-1060. > >
