Adar Dembo created KUDU-2361:
--------------------------------
Summary: MasterTest.TestDumpStacksOnRpcQueueOverflow fails in TSAN
mode with stress
Key: KUDU-2361
URL: https://issues.apache.org/jira/browse/KUDU-2361
Project: Kudu
Issue Type: Bug
Components: test
Affects Versions: 1.7.0
Reporter: Adar Dembo
I noticed this in a full test run in TSAN mode on Ubuntu 16, and was able to
repro by passing --stress_cpu_threads=8 (I have 8 cores on my machine) locally.
Test output:
{noformat}
Note: Google Test filter = *TestDumpStacksOnRpcQueueOverflow*
[==========] Running 1 test from 1 test case.
[----------] Global test environment set-up.
[----------] 1 test from MasterTest
[ RUN ] MasterTest.TestDumpStacksOnRpcQueueOverflow
I0320 12:28:58.121057 439 system_ntp.cc:143] NTP initialized. Skew: 500ppm
Current error: 73757us
I0320 12:28:58.121695 439 fs_manager.cc:260] Metadata directory not provided
I0320 12:28:58.121868 439 fs_manager.cc:266] Using write-ahead log directory
(fs_wal_dir) as metadata directory
I0320 12:28:58.122126 439 server_base.cc:434] Could not load existing FS
layout: Not found:
/tmp/kudutest-1000/master-test.MasterTest.TestDumpStacksOnRpcQueueOverflow.1521574137899614-439/Master/instance:
No such file or directory (error 2)
I0320 12:28:58.122280 439 server_base.cc:435] Attempting to create new FS
layout instead
I0320 12:28:58.139992 439 fs_manager.cc:595] Generated new instance metadata
in path
/tmp/kudutest-1000/master-test.MasterTest.TestDumpStacksOnRpcQueueOverflow.1521574137899614-439/Master/instance:
uuid: "55f12dd184874ef1906983634a1dda96"
format_stamp: "Formatted at 2018-03-20 19:28:58 on adar-ThinkPad-T540p"
I0320 12:28:58.167023 439 fs_manager.cc:495] Time spent creating directory
manager: real 0.026s user 0.012s sys 0.012s
I0320 12:28:58.168340 439 env_posix.cc:1624] Raising this process' open files
per process limit from 1024 to 1048576
I0320 12:28:58.168772 439 file_cache.cc:470] Constructed file cache lbm with
capacity 419430
I0320 12:28:58.204406 439 fs_manager.cc:417] Time spent opening block
manager: real 0.019s user 0.000s sys 0.008s
I0320 12:28:58.204677 439 fs_manager.cc:428] Opened local filesystem:
/tmp/kudutest-1000/master-test.MasterTest.TestDumpStacksOnRpcQueueOverflow.1521574137899614-439/Master
uuid: "55f12dd184874ef1906983634a1dda96"
format_stamp: "Formatted at 2018-03-20 19:28:58 on adar-ThinkPad-T540p"
I0320 12:28:58.205045 439 fs_report.cc:347] Block manager report
--------------------
1 data directories:
/tmp/kudutest-1000/master-test.MasterTest.TestDumpStacksOnRpcQueueOverflow.1521574137899614-439/Master/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
W0320 12:28:59.004899 439 thread.cc:559] rpc reactor (reactor) Time spent
creating pthread: real 0.687s user 0.000s sys 0.008s
W0320 12:28:59.005123 439 thread.cc:526] rpc reactor (reactor) Time spent
starting thread: real 0.687s user 0.000s sys 0.008s
I0320 12:28:59.151173 439 env_posix.cc:1629] Not raising this process'
running threads per effective uid limit of 63233; it is already as high as it
can go
I0320 12:28:59.174991 467 process_memory.cc:182] Process hard memory limit is
12.441025 GB
I0320 12:28:59.175251 467 process_memory.cc:184] Process soft memory limit is
9.952820 GB
I0320 12:28:59.175415 467 process_memory.cc:187] Process memory pressure
threshold is 7.464615 GB
I0320 12:28:59.831009 439 rpc_server.cc:201] RPC server started. Bound to:
127.0.0.1:44269
I0320 12:28:59.947118 439 webserver.cc:173] Starting webserver on 127.0.0.1:0
I0320 12:28:59.947260 439 webserver.cc:184] Document root disabled
I0320 12:28:59.970778 439 webserver.cc:311] Webserver started. Bound to:
http://127.0.0.1:35093/
I0320 12:28:59.984550 513 data_dirs.cc:931] Could only allocate 1 dirs of
requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs
full, 0 dirs failed
I0320 12:29:00.052474 513 tablet_bootstrap.cc:436] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96: Bootstrap
starting.
I0320 12:29:00.055348 513 tablet_bootstrap.cc:581] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96: No blocks
or log segments found. Creating new log.
I0320 12:29:00.056701 513 log.cc:520] T 00000000000000000000000000000000 P
55f12dd184874ef1906983634a1dda96: Log is configured to *not* fsync() on all
Append() calls
I0320 12:29:00.074784 513 tablet_bootstrap.cc:436] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96: No
bootstrap required, opened a new log
I0320 12:29:00.111340 513 raft_consensus.cc:304] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96 [term 0
FOLLOWER]: Replica starting. Triggering 0 pending transactions. Active config:
opid_index: -1 OBSOLETE_local: true peers { permanent_uuid:
"55f12dd184874ef1906983634a1dda96" member_type: VOTER }
I0320 12:29:00.111927 513 raft_consensus.cc:330] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96 [term 0
FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a
prompt election more likely
I0320 12:29:00.112182 513 raft_consensus.cc:605] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96 [term 0
FOLLOWER]: Becoming Follower/Learner. State: Replica:
55f12dd184874ef1906983634a1dda96, State: Initialized, Role: FOLLOWER
I0320 12:29:00.113060 513 consensus_queue.cc:226] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96
[NON_LEADER]: Queue going to NON_LEADER mode. State: All replicated index: 0,
Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last
appended by leader: 0, Current term: 0, Majority size: -1, State: 0, Mode:
NON_LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers {
permanent_uuid: "55f12dd184874ef1906983634a1dda96" member_type: VOTER }
I0320 12:29:00.113554 513 raft_consensus.cc:344] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96 [term 0
FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I0320 12:29:00.113808 513 raft_consensus.cc:436] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96 [term 0
FOLLOWER]: Starting leader election (initial election of a single-replica
configuration)
I0320 12:29:00.114053 513 raft_consensus.cc:2700] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96: Snoozing
failure detection for 2.020s (starting election)
I0320 12:29:00.114297 513 raft_consensus.cc:2752] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96 [term 0
FOLLOWER]: Advancing to term 1
I0320 12:29:00.118088 513 raft_consensus.cc:458] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96 [term 1
FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local:
true peers { permanent_uuid: "55f12dd184874ef1906983634a1dda96" member_type:
VOTER }
I0320 12:29:00.118873 513 leader_election.cc:258] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96
[CANDIDATE]: Term 1 election: Election decided. Result: candidate won.
I0320 12:29:00.143113 515 raft_consensus.cc:2700] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96: Snoozing
failure detection for 1.623s (election complete)
I0320 12:29:00.143416 515 raft_consensus.cc:2507] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96 [term 1
FOLLOWER]: Leader election won for term 1
I0320 12:29:00.174619 515 raft_consensus.cc:572] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96 [term 1
LEADER]: Becoming Leader. State: Replica: 55f12dd184874ef1906983634a1dda96,
State: Running, Role: LEADER
I0320 12:29:00.175150 515 consensus_queue.cc:203] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96 [LEADER]:
Queue going to LEADER mode. State: All replicated index: 0, Majority replicated
index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0,
Current term: 1, Majority size: 1, State: 0, Mode: LEADER, active raft config:
opid_index: -1 OBSOLETE_local: true peers { permanent_uuid:
"55f12dd184874ef1906983634a1dda96" member_type: VOTER }
I0320 12:29:00.195482 517 sys_catalog.cc:335] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96
[sys.catalog]: SysCatalogTable state changed. Reason: New leader
55f12dd184874ef1906983634a1dda96. Latest consensus state: current_term: 1
leader_uuid: "55f12dd184874ef1906983634a1dda96" committed_config { opid_index:
-1 OBSOLETE_local: true peers { permanent_uuid:
"55f12dd184874ef1906983634a1dda96" member_type: VOTER } }
I0320 12:29:00.195924 517 sys_catalog.cc:338] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96
[sys.catalog]: This master's current role is: LEADER
I0320 12:29:00.195751 513 sys_catalog.cc:335] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96
[sys.catalog]: SysCatalogTable state changed. Reason: Started TabletReplica.
Latest consensus state: current_term: 1 leader_uuid:
"55f12dd184874ef1906983634a1dda96" committed_config { opid_index: -1
OBSOLETE_local: true peers { permanent_uuid: "55f12dd184874ef1906983634a1dda96"
member_type: VOTER } }
I0320 12:29:00.195516 516 sys_catalog.cc:335] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96
[sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started.
Latest consensus state: current_term: 1 leader_uuid:
"55f12dd184874ef1906983634a1dda96" committed_config { opid_index: -1
OBSOLETE_local: true peers { permanent_uuid: "55f12dd184874ef1906983634a1dda96"
member_type: VOTER } }
I0320 12:29:00.196521 516 sys_catalog.cc:338] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96
[sys.catalog]: This master's current role is: LEADER
I0320 12:29:00.196115 513 sys_catalog.cc:338] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96
[sys.catalog]: This master's current role is: LEADER
I0320 12:29:00.203620 513 sys_catalog.cc:422] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96
[sys.catalog]: configured and running, proceeding with master startup.
W0320 12:29:00.267588 522 catalog_manager.cc:1018] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96: acquiring
CA information for follower catalog manager: Not found: root CA entry not found
W0320 12:29:00.267813 522 catalog_manager.cc:560] Not found: root CA entry
not found: failed to prepare follower catalog manager, will retry
I0320 12:29:00.268275 521 catalog_manager.cc:972] Loading table and tablet
metadata into memory...
I0320 12:29:00.270922 521 catalog_manager.cc:983] Initializing Kudu internal
certificate authority...
W0320 12:29:00.426303 467 tablet.cc:1679] T 00000000000000000000000000000000
P 55f12dd184874ef1906983634a1dda96: Can't schedule compaction. Clean time has
not been advanced past its initial value.
I0320 12:29:00.515857 521 catalog_manager.cc:870] Generated new certificate
authority record
I0320 12:29:00.518018 521 catalog_manager.cc:992] Loading token signing
keys...
I0320 12:29:00.546751 521 catalog_manager.cc:3871] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96: Generated
new TSK 0
I0320 12:29:00.827468 439 master.cc:225] [email protected]:44269 shutting
down...
I0320 12:29:01.020676 439 raft_consensus.cc:2012] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96 [term 1
LEADER]: Raft consensus shutting down.
I0320 12:29:01.021024 439 raft_consensus.cc:2039] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96 [term 1
FOLLOWER]: Raft consensus is shut down!
I0320 12:29:01.021750 439 tablet_replica.cc:262] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96: stopping
tablet replica
I0320 12:29:01.021996 439 maintenance_manager.cc:235] P
55f12dd184874ef1906983634a1dda96: Unregistered op
CompactRowSetsOp(00000000000000000000000000000000)
I0320 12:29:01.022163 439 maintenance_manager.cc:235] P
55f12dd184874ef1906983634a1dda96: Unregistered op
MinorDeltaCompactionOp(00000000000000000000000000000000)
I0320 12:29:01.022305 439 maintenance_manager.cc:235] P
55f12dd184874ef1906983634a1dda96: Unregistered op
MajorDeltaCompactionOp(00000000000000000000000000000000)
I0320 12:29:01.022439 439 maintenance_manager.cc:235] P
55f12dd184874ef1906983634a1dda96: Unregistered op
UndoDeltaBlockGCOp(00000000000000000000000000000000)
I0320 12:29:01.022673 439 maintenance_manager.cc:235] P
55f12dd184874ef1906983634a1dda96: Unregistered op
FlushMRSOp(00000000000000000000000000000000)
I0320 12:29:01.022807 439 maintenance_manager.cc:235] P
55f12dd184874ef1906983634a1dda96: Unregistered op
FlushDeltaMemStoresOp(00000000000000000000000000000000)
I0320 12:29:01.022928 439 maintenance_manager.cc:235] P
55f12dd184874ef1906983634a1dda96: Unregistered op
LogGCOp(00000000000000000000000000000000)
I0320 12:29:01.134024 439 master.cc:236] [email protected]:44269 shutdown
complete.
I0320 12:29:01.171110 439 system_ntp.cc:143] NTP initialized. Skew: 500ppm
Current error: 75257us
I0320 12:29:01.171545 439 fs_manager.cc:260] Metadata directory not provided
I0320 12:29:01.171741 439 fs_manager.cc:263] Using existing metadata
directory in first data directory
I0320 12:29:01.179345 439 fs_manager.cc:397] Time spent opening directory
manager: real 0.007s user 0.000s sys 0.008s
I0320 12:29:01.180353 439 file_cache.cc:470] Constructed file cache lbm with
capacity 419430
I0320 12:29:01.203125 439 fs_manager.cc:417] Time spent opening block
manager: real 0.015s user 0.000s sys 0.000s
I0320 12:29:01.203403 439 fs_manager.cc:428] Opened local filesystem:
/tmp/kudutest-1000/master-test.MasterTest.TestDumpStacksOnRpcQueueOverflow.1521574137899614-439/Master
uuid: "55f12dd184874ef1906983634a1dda96"
format_stamp: "Formatted at 2018-03-20 19:28:58 on adar-ThinkPad-T540p"
I0320 12:29:01.203735 439 fs_report.cc:347] Block manager report
--------------------
1 data directories:
/tmp/kudutest-1000/master-test.MasterTest.TestDumpStacksOnRpcQueueOverflow.1521574137899614-439/Master/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
I0320 12:29:01.518903 439 rpc_server.cc:201] RPC server started. Bound to:
127.0.0.1:44269
I0320 12:29:01.519835 439 webserver.cc:173] Starting webserver on
127.0.0.1:35093
I0320 12:29:01.519968 439 webserver.cc:184] Document root disabled
I0320 12:29:01.535214 439 webserver.cc:311] Webserver started. Bound to:
http://127.0.0.1:35093/
I0320 12:29:01.567597 549 tablet_bootstrap.cc:436] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96: Bootstrap
starting.
I0320 12:29:01.611582 549 tablet_bootstrap.cc:436] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96: Bootstrap
replayed 1/1 log segments. Stats: ops{read=4 overwritten=0 applied=4 ignored=1}
inserts{seen=2 ignored=0} mutations{seen=0 ignored=0} orphaned_commits=0.
Pending: 0 replicates
I0320 12:29:01.612310 549 tablet_bootstrap.cc:436] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96: Bootstrap
complete.
I0320 12:29:01.613600 549 raft_consensus.cc:304] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96 [term 1
FOLLOWER]: Replica starting. Triggering 0 pending transactions. Active config:
opid_index: -1 OBSOLETE_local: true peers { permanent_uuid:
"55f12dd184874ef1906983634a1dda96" member_type: VOTER }
I0320 12:29:01.613976 549 raft_consensus.cc:605] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96 [term 1
FOLLOWER]: Becoming Follower/Learner. State: Replica:
55f12dd184874ef1906983634a1dda96, State: Initialized, Role: FOLLOWER
I0320 12:29:01.614390 549 consensus_queue.cc:226] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96
[NON_LEADER]: Queue going to NON_LEADER mode. State: All replicated index: 0,
Majority replicated index: 0, Committed index: 4, Last appended: 1.4, Last
appended by leader: 4, Current term: 0, Majority size: -1, State: 0, Mode:
NON_LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers {
permanent_uuid: "55f12dd184874ef1906983634a1dda96" member_type: VOTER }
I0320 12:29:01.614800 549 raft_consensus.cc:344] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96 [term 1
FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I0320 12:29:01.614998 549 raft_consensus.cc:436] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96 [term 1
FOLLOWER]: Starting leader election (initial election of a single-replica
configuration)
I0320 12:29:01.619002 549 raft_consensus.cc:2700] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96: Snoozing
failure detection for 1.502s (starting election)
I0320 12:29:01.619308 549 raft_consensus.cc:2752] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96 [term 1
FOLLOWER]: Advancing to term 2
I0320 12:29:01.625046 549 raft_consensus.cc:458] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96 [term 2
FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local:
true peers { permanent_uuid: "55f12dd184874ef1906983634a1dda96" member_type:
VOTER }
I0320 12:29:01.629127 549 leader_election.cc:258] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96
[CANDIDATE]: Term 2 election: Election decided. Result: candidate won.
I0320 12:29:01.637392 551 raft_consensus.cc:2700] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96: Snoozing
failure detection for 1.879s (election complete)
I0320 12:29:01.637658 551 raft_consensus.cc:2507] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96 [term 2
FOLLOWER]: Leader election won for term 2
I0320 12:29:01.657527 551 raft_consensus.cc:572] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96 [term 2
LEADER]: Becoming Leader. State: Replica: 55f12dd184874ef1906983634a1dda96,
State: Running, Role: LEADER
I0320 12:29:01.657930 551 consensus_queue.cc:203] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96 [LEADER]:
Queue going to LEADER mode. State: All replicated index: 0, Majority replicated
index: 4, Committed index: 4, Last appended: 1.4, Last appended by leader: 4,
Current term: 2, Majority size: 1, State: 0, Mode: LEADER, active raft config:
opid_index: -1 OBSOLETE_local: true peers { permanent_uuid:
"55f12dd184874ef1906983634a1dda96" member_type: VOTER }
I0320 12:29:01.672679 553 sys_catalog.cc:335] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96
[sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started.
Latest consensus state: current_term: 2 leader_uuid:
"55f12dd184874ef1906983634a1dda96" committed_config { opid_index: -1
OBSOLETE_local: true peers { permanent_uuid: "55f12dd184874ef1906983634a1dda96"
member_type: VOTER } }
I0320 12:29:01.672747 549 sys_catalog.cc:335] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96
[sys.catalog]: SysCatalogTable state changed. Reason: Started TabletReplica.
Latest consensus state: current_term: 2 leader_uuid:
"55f12dd184874ef1906983634a1dda96" committed_config { opid_index: -1
OBSOLETE_local: true peers { permanent_uuid: "55f12dd184874ef1906983634a1dda96"
member_type: VOTER } }
I0320 12:29:01.673079 553 sys_catalog.cc:338] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96
[sys.catalog]: This master's current role is: LEADER
I0320 12:29:01.673100 549 sys_catalog.cc:338] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96
[sys.catalog]: This master's current role is: LEADER
I0320 12:29:01.678683 555 sys_catalog.cc:335] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96
[sys.catalog]: SysCatalogTable state changed. Reason: New leader
55f12dd184874ef1906983634a1dda96. Latest consensus state: current_term: 2
leader_uuid: "55f12dd184874ef1906983634a1dda96" committed_config { opid_index:
-1 OBSOLETE_local: true peers { permanent_uuid:
"55f12dd184874ef1906983634a1dda96" member_type: VOTER } }
I0320 12:29:01.681085 555 sys_catalog.cc:338] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96
[sys.catalog]: This master's current role is: LEADER
I0320 12:29:01.681375 549 sys_catalog.cc:422] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96
[sys.catalog]: configured and running, proceeding with master startup.
I0320 12:29:01.716922 558 catalog_manager.cc:502] Waiting for catalog manager
background task thread to start: Service unavailable: Catalog manager is not
initialized. State: 1
I0320 12:29:01.726768 559 catalog_manager.cc:972] Loading table and tablet
metadata into memory...
I0320 12:29:01.729962 559 catalog_manager.cc:983] Initializing Kudu internal
certificate authority...
I0320 12:29:01.734299 559 catalog_manager.cc:992] Loading token signing
keys...
I0320 12:29:01.738445 559 catalog_manager.cc:3882] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96: Loaded
TSK: 0
W0320 12:29:01.879313 533 service_pool.cc:130] GetTableLocations request on
kudu.master.MasterService from 127.0.0.1:35832 dropped due to backpressure. The
service queue is full; it has 1 items.
I0320 12:29:01.879936 533 service_pool.cc:133] GetTableLocations request on
kudu.master.MasterService from 127.0.0.1:35832 dropped due to backpressure. The
service queue is full; it has 1 items. Contents of service queue:
Call kudu.master.MasterService.GetTableLocations from 127.0.0.1:35832 (request
call id 2)
I0320 12:29:01.897538 533 service_pool.cc:133] GetTableLocations request on
kudu.master.MasterService from 127.0.0.1:35832 dropped due to backpressure. The
service queue is full; it has 1 items. Contents of service queue:
Call kudu.master.MasterService.GetTableLocations from 127.0.0.1:35832 (request
call id 2)
I0320 12:29:01.898228 533 service_pool.cc:133] GetTableLocations request on
kudu.master.MasterService from 127.0.0.1:35832 dropped due to backpressure. The
service queue is full; it has 1 items. Contents of service queue:
Call kudu.master.MasterService.GetTableLocations from 127.0.0.1:35832 (request
call id 2)
I0320 12:29:01.899801 533 service_pool.cc:133] GetTableLocations request on
kudu.master.MasterService from 127.0.0.1:35832 dropped due to backpressure. The
service queue is full; it has 1 items. Contents of service queue:
Call kudu.master.MasterService.GetTableLocations from 127.0.0.1:35832 (request
call id 2)
I0320 12:29:01.900344 533 service_pool.cc:133] GetTableLocations request on
kudu.master.MasterService from 127.0.0.1:35832 dropped due to backpressure. The
service queue is full; it has 1 items. Contents of service queue:
Call kudu.master.MasterService.GetTableLocations from 127.0.0.1:35832 (request
call id 2)
I0320 12:29:01.901034 533 service_pool.cc:133] GetTableLocations request on
kudu.master.MasterService from 127.0.0.1:35832 dropped due to backpressure. The
service queue is full; it has 1 items. Contents of service queue:
Call kudu.master.MasterService.GetTableLocations from 127.0.0.1:35832 (request
call id 2)
I0320 12:29:01.901525 533 service_pool.cc:133] GetTableLocations request on
kudu.master.MasterService from 127.0.0.1:35832 dropped due to backpressure. The
service queue is full; it has 1 items. Contents of service queue:
Call kudu.master.MasterService.GetTableLocations from 127.0.0.1:35832 (request
call id 2)
I0320 12:29:01.902161 533 service_pool.cc:133] GetTableLocations request on
kudu.master.MasterService from 127.0.0.1:35832 dropped due to backpressure. The
service queue is full; it has 1 items. Contents of service queue:
Call kudu.master.MasterService.GetTableLocations from 127.0.0.1:35832 (request
call id 2)
I0320 12:29:01.903232 533 service_pool.cc:133] GetTableLocations request on
kudu.master.MasterService from 127.0.0.1:35832 dropped due to backpressure. The
service queue is full; it has 1 items. Contents of service queue:
Call kudu.master.MasterService.GetTableLocations from 127.0.0.1:35832 (request
call id 2)
I0320 12:29:01.904125 533 service_pool.cc:133] GetTableLocations request on
kudu.master.MasterService from 127.0.0.1:35832 dropped due to backpressure. The
service queue is full; it has 1 items. Contents of service queue:
Call kudu.master.MasterService.GetTableLocations from 127.0.0.1:35832 (request
call id 2)
I0320 12:29:01.904739 533 service_pool.cc:133] GetTableLocations request on
kudu.master.MasterService from 127.0.0.1:35832 dropped due to backpressure. The
service queue is full; it has 1 items. Contents of service queue:
Call kudu.master.MasterService.GetTableLocations from 127.0.0.1:35832 (request
call id 2)
I0320 12:29:01.906430 533 service_pool.cc:133] GetTableLocations request on
kudu.master.MasterService from 127.0.0.1:35832 dropped due to backpressure. The
service queue is full; it has 1 items. Contents of service queue:
Call kudu.master.MasterService.GetTableLocations from 127.0.0.1:35832 (request
call id 2)
I0320 12:29:01.907002 533 service_pool.cc:133] GetTableLocations request on
kudu.master.MasterService from 127.0.0.1:35832 dropped due to backpressure. The
service queue is full; it has 1 items. Contents of service queue:
Call kudu.master.MasterService.GetTableLocations from 127.0.0.1:35832 (request
call id 2)
I0320 12:29:01.907941 533 service_pool.cc:133] GetTableLocations request on
kudu.master.MasterService from 127.0.0.1:35832 dropped due to backpressure. The
service queue is full; it has 1 items. Contents of service queue:
Call kudu.master.MasterService.GetTableLocations from 127.0.0.1:35832 (request
call id 2)
I0320 12:29:01.908489 533 service_pool.cc:133] GetTableLocations request on
kudu.master.MasterService from 127.0.0.1:35832 dropped due to backpressure. The
service queue is full; it has 1 items. Contents of service queue:
Call kudu.master.MasterService.GetTableLocations from 127.0.0.1:35832 (request
call id 2)
I0320 12:29:01.909440 533 service_pool.cc:133] GetTableLocations request on
kudu.master.MasterService from 127.0.0.1:35832 dropped due to backpressure. The
service queue is full; it has 1 items. Contents of service queue:
Call kudu.master.MasterService.GetTableLocations from 127.0.0.1:35832 (request
call id 2)
I0320 12:29:01.909982 533 service_pool.cc:133] GetTableLocations request on
kudu.master.MasterService from 127.0.0.1:35832 dropped due to backpressure. The
service queue is full; it has 1 items. Contents of service queue:
Call kudu.master.MasterService.GetTableLocations from 127.0.0.1:35832 (request
call id 2)
I0320 12:29:01.923619 533 service_pool.cc:133] GetTableLocations request on
kudu.master.MasterService from 127.0.0.1:35832 dropped due to backpressure. The
service queue is full; it has 1 items. Contents of service queue:
Call kudu.master.MasterService.GetTableLocations from 127.0.0.1:35832 (request
call id 2)
W0320 12:29:02.895246 537 debug-util.cc:396] Leaking SignalData structure
0x7b080007a100 after lost signal to thread 442
W0320 12:29:02.895696 537 debug-util.cc:396] Leaking SignalData structure
0x7b0800067f00 after lost signal to thread 546
I0320 12:29:02.895265 542 rpcz_store.cc:265] Call
kudu.master.MasterService.GetTableLocations from 127.0.0.1:35832 (request call
id 1) took 1017ms. Request Metrics: {}
I0320 12:29:03.911542 542 rpcz_store.cc:265] Call
kudu.master.MasterService.GetTableLocations from 127.0.0.1:35832 (request call
id 2) took 2033ms. Request Metrics: {}
../../src/kudu/master/master-test.cc:843: Failure
Expected: dump_count
Which is: 0
To be equal to: 1
I0320 12:29:03.913710 439 master.cc:225] [email protected]:44269 shutting
down...
I0320 12:29:03.916647 439 raft_consensus.cc:2012] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96 [term 2
LEADER]: Raft consensus shutting down.
I0320 12:29:03.916927 439 raft_consensus.cc:2039] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96 [term 2
FOLLOWER]: Raft consensus is shut down!
I0320 12:29:03.917110 439 tablet_replica.cc:262] T
00000000000000000000000000000000 P 55f12dd184874ef1906983634a1dda96: stopping
tablet replica
I0320 12:29:03.917285 439 maintenance_manager.cc:235] P
55f12dd184874ef1906983634a1dda96: Unregistered op
CompactRowSetsOp(00000000000000000000000000000000)
I0320 12:29:03.917426 439 maintenance_manager.cc:235] P
55f12dd184874ef1906983634a1dda96: Unregistered op
MinorDeltaCompactionOp(00000000000000000000000000000000)
I0320 12:29:03.917557 439 maintenance_manager.cc:235] P
55f12dd184874ef1906983634a1dda96: Unregistered op
MajorDeltaCompactionOp(00000000000000000000000000000000)
I0320 12:29:03.917688 439 maintenance_manager.cc:235] P
55f12dd184874ef1906983634a1dda96: Unregistered op
UndoDeltaBlockGCOp(00000000000000000000000000000000)
I0320 12:29:03.917836 439 maintenance_manager.cc:235] P
55f12dd184874ef1906983634a1dda96: Unregistered op
FlushMRSOp(00000000000000000000000000000000)
I0320 12:29:03.917964 439 maintenance_manager.cc:235] P
55f12dd184874ef1906983634a1dda96: Unregistered op
FlushDeltaMemStoresOp(00000000000000000000000000000000)
I0320 12:29:03.918082 439 maintenance_manager.cc:235] P
55f12dd184874ef1906983634a1dda96: Unregistered op
LogGCOp(00000000000000000000000000000000)
I0320 12:29:04.307595 439 master.cc:236] [email protected]:44269 shutdown
complete.
I0320 12:29:04.320631 439 test_util.cc:119]
-----------------------------------------------
I0320 12:29:04.320791 439 test_util.cc:120] Had fatal failures, leaving test
files at
/tmp/kudutest-1000/master-test.MasterTest.TestDumpStacksOnRpcQueueOverflow.1521574137899614-439
[ FAILED ] MasterTest.TestDumpStacksOnRpcQueueOverflow (6288 ms)
[----------] 1 test from MasterTest (6288 ms total)
[----------] Global test environment tear-down
[==========] 1 test from 1 test case ran. (6289 ms total)
[ PASSED ] 0 tests.
[ FAILED ] 1 test, listed below:
[ FAILED ] MasterTest.TestDumpStacksOnRpcQueueOverflow
1 FAILED TEST
{noformat}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
