[
https://issues.apache.org/jira/browse/MESOS-2331?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15244596#comment-15244596
]
haosdent commented on MESOS-2331:
---------------------------------
Raw this again
{code}
[ RUN ] MasterSlaveReconciliationTest.ReconcileRace
I0417 08:09:37.011265 31901 cluster.cpp:149] Creating default 'local' authorizer
I0417 08:09:37.086580 31901 leveldb.cpp:174] Opened db in 74.882317ms
I0417 08:09:37.103621 31901 leveldb.cpp:181] Compacted db in 16.92606ms
I0417 08:09:37.103744 31901 leveldb.cpp:196] Created db iterator in 32846ns
I0417 08:09:37.103762 31901 leveldb.cpp:202] Seeked to beginning of db in 3615ns
I0417 08:09:37.103775 31901 leveldb.cpp:271] Iterated through 0 keys in the db
in 250ns
I0417 08:09:37.103832 31901 replica.cpp:779] Replica recovered with log
positions 0 -> 0 with 1 holes and 0 unlearned
I0417 08:09:37.104671 31931 recover.cpp:447] Starting replica recovery
I0417 08:09:37.105304 31931 recover.cpp:473] Replica is in EMPTY status
I0417 08:09:37.106678 31934 replica.cpp:673] Replica in EMPTY status received a
broadcasted recover request from (6118)@172.17.0.1:35480
I0417 08:09:37.107188 31929 recover.cpp:193] Received a recover response from a
replica in EMPTY status
I0417 08:09:37.108885 31934 recover.cpp:564] Updating replica status to STARTING
I0417 08:09:37.111217 31922 master.cpp:382] Master
07f7917f-63d1-40d4-b983-4f0eb5c18f3d (95302125b116) started on 172.17.0.1:35480
I0417 08:09:37.111249 31922 master.cpp:384] Flags at startup: --acls=""
--allocation_interval="1secs" --allocator="HierarchicalDRF"
--authenticate="true" --authenticate_http="true"
--authenticate_http_frameworks="true" --authenticate_slaves="true"
--authenticators="crammd5" --authorizers="local"
--credentials="/tmp/Wdw9Iq/credentials" --framework_sorter="drf" --help="false"
--hostname_lookup="true" --http_authenticators="basic"
--http_framework_authenticators="basic" --initialize_driver_logging="true"
--log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO"
--max_completed_frameworks="50" --max_completed_tasks_per_framework="1000"
--max_slave_ping_timeouts="5" --quiet="false"
--recovery_slave_removal_limit="100%" --registry="replicated_log"
--registry_fetch_timeout="1mins" --registry_store_timeout="100secs"
--registry_strict="true" --root_submissions="true"
--slave_ping_timeout="15secs" --slave_reregister_timeout="10mins"
--user_sorter="drf" --version="false"
--webui_dir="/mesos/mesos-0.29.0/_inst/share/mesos/webui"
--work_dir="/tmp/Wdw9Iq/master" --zk_session_timeout="10secs"
I0417 08:09:37.111726 31922 master.cpp:433] Master only allowing authenticated
frameworks to register
I0417 08:09:37.111738 31922 master.cpp:439] Master only allowing authenticated
agents to register
I0417 08:09:37.111747 31922 master.cpp:445] Master only allowing authenticated
HTTP frameworks to register
I0417 08:09:37.111755 31922 credentials.hpp:37] Loading credentials for
authentication from '/tmp/Wdw9Iq/credentials'
I0417 08:09:37.112149 31922 master.cpp:489] Using default 'crammd5'
authenticator
I0417 08:09:37.112300 31922 master.cpp:560] Using default 'basic' HTTP
authenticator
I0417 08:09:37.112460 31922 master.cpp:640] Using default 'basic' HTTP
framework authenticator
I0417 08:09:37.112573 31922 master.cpp:687] Authorization enabled
I0417 08:09:37.112798 31931 hierarchical.cpp:142] Initialized hierarchical
allocator process
I0417 08:09:37.112861 31931 whitelist_watcher.cpp:77] No whitelist given
I0417 08:09:37.122642 31921 master.cpp:1932] The newly elected leader is
master@172.17.0.1:35480 with id 07f7917f-63d1-40d4-b983-4f0eb5c18f3d
I0417 08:09:37.122709 31921 master.cpp:1945] Elected as the leading master!
I0417 08:09:37.122732 31921 master.cpp:1632] Recovering from registrar
I0417 08:09:37.123011 31921 registrar.cpp:331] Recovering registrar
I0417 08:09:37.137696 31929 leveldb.cpp:304] Persisting metadata (8 bytes) to
leveldb took 28.65638ms
I0417 08:09:37.137791 31929 replica.cpp:320] Persisted replica status to
STARTING
I0417 08:09:37.138139 31921 recover.cpp:473] Replica is in STARTING status
I0417 08:09:37.139683 31929 replica.cpp:673] Replica in STARTING status
received a broadcasted recover request from (6121)@172.17.0.1:35480
I0417 08:09:37.139957 31935 recover.cpp:193] Received a recover response from a
replica in STARTING status
I0417 08:09:37.140836 31928 recover.cpp:564] Updating replica status to VOTING
I0417 08:09:37.161991 31928 leveldb.cpp:304] Persisting metadata (8 bytes) to
leveldb took 20.949493ms
I0417 08:09:37.162083 31928 replica.cpp:320] Persisted replica status to VOTING
I0417 08:09:37.162320 31935 recover.cpp:578] Successfully joined the Paxos group
I0417 08:09:37.162582 31935 recover.cpp:462] Recover process terminated
I0417 08:09:37.163247 31923 log.cpp:659] Attempting to start the writer
I0417 08:09:37.165011 31923 replica.cpp:493] Replica received implicit promise
request from (6122)@172.17.0.1:35480 with proposal 1
I0417 08:09:37.187156 31923 leveldb.cpp:304] Persisting metadata (8 bytes) to
leveldb took 22.073665ms
I0417 08:09:37.187252 31923 replica.cpp:342] Persisted promised to 1
I0417 08:09:37.188690 31923 coordinator.cpp:238] Coordinator attempting to fill
missing positions
I0417 08:09:37.190460 31923 replica.cpp:388] Replica received explicit promise
request from (6123)@172.17.0.1:35480 for position 0 with proposal 2
I0417 08:09:37.217609 31923 leveldb.cpp:341] Persisting action (8 bytes) to
leveldb took 27.059356ms
I0417 08:09:37.217706 31923 replica.cpp:712] Persisted action at 0
I0417 08:09:37.233053 31928 replica.cpp:537] Replica received write request for
position 0 from (6124)@172.17.0.1:35480
I0417 08:09:37.233181 31928 leveldb.cpp:436] Reading position from leveldb took
52988ns
I0417 08:09:37.267741 31928 leveldb.cpp:341] Persisting action (14 bytes) to
leveldb took 34.488485ms
I0417 08:09:37.267840 31928 replica.cpp:712] Persisted action at 0
I0417 08:09:37.268751 31933 replica.cpp:691] Replica received learned notice
for position 0 from @0.0.0.0:0
I0417 08:09:37.301877 31933 leveldb.cpp:341] Persisting action (16 bytes) to
leveldb took 33.066524ms
I0417 08:09:37.301971 31933 replica.cpp:712] Persisted action at 0
I0417 08:09:37.302008 31933 replica.cpp:697] Replica learned NOP action at
position 0
I0417 08:09:37.302850 31933 log.cpp:675] Writer started with ending position 0
I0417 08:09:37.304150 31924 leveldb.cpp:436] Reading position from leveldb took
60933ns
I0417 08:09:37.305534 31924 registrar.cpp:364] Successfully fetched the
registry (0B) in 182.47424ms
I0417 08:09:37.305845 31924 registrar.cpp:463] Applied 1 operations in 42916ns;
attempting to update the 'registry'
I0417 08:09:37.307245 31924 log.cpp:683] Attempting to append 170 bytes to the
log
I0417 08:09:37.307497 31924 coordinator.cpp:348] Coordinator attempting to
write APPEND action at position 1
I0417 08:09:37.308697 31922 replica.cpp:537] Replica received write request for
position 1 from (6125)@172.17.0.1:35480
I0417 08:09:37.343696 31922 leveldb.cpp:341] Persisting action (189 bytes) to
leveldb took 34.928438ms
I0417 08:09:37.343794 31922 replica.cpp:712] Persisted action at 1
I0417 08:09:37.344900 31922 replica.cpp:691] Replica received learned notice
for position 1 from @0.0.0.0:0
I0417 08:09:37.377158 31922 leveldb.cpp:341] Persisting action (191 bytes) to
leveldb took 32.20258ms
I0417 08:09:37.377257 31922 replica.cpp:712] Persisted action at 1
I0417 08:09:37.377295 31922 replica.cpp:697] Replica learned APPEND action at
position 1
I0417 08:09:37.378758 31935 registrar.cpp:508] Successfully updated the
'registry' in 72.839936ms
I0417 08:09:37.378903 31935 registrar.cpp:394] Successfully recovered registrar
I0417 08:09:37.378979 31922 log.cpp:702] Attempting to truncate the log to 1
I0417 08:09:37.379176 31935 coordinator.cpp:348] Coordinator attempting to
write TRUNCATE action at position 2
I0417 08:09:37.379410 31922 master.cpp:1740] Recovered 0 agents from the
Registry (131B) ; allowing 10mins for agents to re-register
I0417 08:09:37.379652 31921 hierarchical.cpp:169] Skipping recovery of
hierarchical allocator: nothing to recover
I0417 08:09:37.380750 31932 replica.cpp:537] Replica received write request for
position 2 from (6126)@172.17.0.1:35480
I0417 08:09:37.410661 31932 leveldb.cpp:341] Persisting action (16 bytes) to
leveldb took 29.840664ms
I0417 08:09:37.410758 31932 replica.cpp:712] Persisted action at 2
I0417 08:09:37.421082 31928 replica.cpp:691] Replica received learned notice
for position 2 from @0.0.0.0:0
I0417 08:09:37.452471 31928 leveldb.cpp:341] Persisting action (18 bytes) to
leveldb took 31.041585ms
I0417 08:09:37.452654 31928 leveldb.cpp:399] Deleting ~1 keys from leveldb took
91188ns
I0417 08:09:37.452682 31928 replica.cpp:712] Persisted action at 2
I0417 08:09:37.452718 31928 replica.cpp:697] Replica learned TRUNCATE action at
position 2
I0417 08:09:37.467718 31928 slave.cpp:201] Agent started on
141)@172.17.0.1:35480
I0417 08:09:37.467764 31928 slave.cpp:202] Flags at startup:
--appc_simple_discovery_uri_prefix="http://";
--appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="true"
--authenticatee="crammd5" --cgroups_cpu_enable_pids_and_tids_count="false"
--cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup"
--cgroups_limit_swap="false" --cgroups_root="mesos"
--container_disk_watch_interval="15secs" --containerizers="mesos"
--credential="/tmp/MasterSlaveReconciliationTest_ReconcileRace_5dHzkH/credential"
--default_role="*" --disk_watch_interval="1mins" --docker="docker"
--docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io";
--docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock"
--docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker"
--enforce_container_disk_quota="false" --executor_registration_timeout="1mins"
--executor_shutdown_grace_period="5secs"
--fetcher_cache_dir="/tmp/MasterSlaveReconciliationTest_ReconcileRace_5dHzkH/fetch"
--fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks"
--gc_disk_headroom="0.1" --hadoop_home="" --help="true"
--hostname_lookup="true" --http_authenticators="basic"
--http_command_executor="false"
--http_credentials="/tmp/MasterSlaveReconciliationTest_ReconcileRace_5dHzkH/http_credentials"
--image_provisioner_backend="copy" --initialize_driver_logging="true"
--isolation="posix/cpu,posix/mem"
--launcher_dir="/mesos/mesos-0.29.0/_build/src" --logbufsecs="0"
--logging_level="INFO" --oversubscribed_resources_interval="15secs"
--perf_duration="10secs" --perf_interval="1mins"
--qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect"
--recovery_timeout="15mins" --registration_backoff_factor="10ms"
--resources="cpus:2;mem:1024;disk:1024;ports:[31000-32000]"
--revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox"
--strict="true" --switch_user="true" --systemd_enable_support="true"
--systemd_runtime_directory="/run/systemd/system" --version="false"
--work_dir="/tmp/MasterSlaveReconciliationTest_ReconcileRace_5dHzkH"
I0417 08:09:37.468230 31928 credentials.hpp:86] Loading credential for
authentication from
'/tmp/MasterSlaveReconciliationTest_ReconcileRace_5dHzkH/credential'
I0417 08:09:37.468507 31928 slave.cpp:339] Agent using credential for:
test-principal
I0417 08:09:37.468535 31928 credentials.hpp:37] Loading credentials for
authentication from
'/tmp/MasterSlaveReconciliationTest_ReconcileRace_5dHzkH/http_credentials'
I0417 08:09:37.468834 31928 slave.cpp:391] Using default 'basic' HTTP
authenticator
I0417 08:09:37.469089 31928 resources.cpp:572] Parsing resources as JSON
failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
Trying semicolon-delimited string format instead
I0417 08:09:37.470298 31928 slave.cpp:590] Agent resources: cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0417 08:09:37.470379 31928 slave.cpp:598] Agent attributes: [ ]
I0417 08:09:37.470393 31928 slave.cpp:603] Agent hostname: 95302125b116
I0417 08:09:37.472777 31931 state.cpp:57] Recovering state from
'/tmp/MasterSlaveReconciliationTest_ReconcileRace_5dHzkH/meta'
I0417 08:09:37.473295 31931 status_update_manager.cpp:200] Recovering status
update manager
I0417 08:09:37.473757 31931 slave.cpp:4800] Finished recovery
I0417 08:09:37.474364 31931 slave.cpp:4972] Querying resource estimator for
oversubscribable resources
I0417 08:09:37.474916 31931 slave.cpp:945] New master detected at
master@172.17.0.1:35480
I0417 08:09:37.475071 31926 status_update_manager.cpp:174] Pausing sending
status updates
I0417 08:09:37.475244 31931 slave.cpp:1008] Authenticating with master
master@172.17.0.1:35480
I0417 08:09:37.475267 31931 slave.cpp:1013] Using default CRAM-MD5 authenticatee
I0417 08:09:37.475435 31931 slave.cpp:981] Detecting new master
I0417 08:09:37.475540 31927 authenticatee.cpp:121] Creating new client SASL
connection
I0417 08:09:37.475546 31931 slave.cpp:4986] Received oversubscribable resources
from the resource estimator
I0417 08:09:37.475848 31931 master.cpp:5801] Authenticating
slave(141)@172.17.0.1:35480
I0417 08:09:37.476028 31931 authenticator.cpp:413] Starting authentication
session for crammd5_authenticatee(337)@172.17.0.1:35480
I0417 08:09:37.476503 31931 authenticator.cpp:98] Creating new server SASL
connection
I0417 08:09:37.476897 31933 authenticatee.cpp:212] Received SASL authentication
mechanisms: CRAM-MD5
I0417 08:09:37.476930 31933 authenticatee.cpp:238] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0417 08:09:37.477042 31934 authenticator.cpp:203] Received SASL authentication
start
I0417 08:09:37.477123 31934 authenticator.cpp:325] Authentication requires more
steps
I0417 08:09:37.477226 31934 authenticatee.cpp:258] Received SASL authentication
step
I0417 08:09:37.477355 31934 authenticator.cpp:231] Received SASL authentication
step
I0417 08:09:37.477391 31934 auxprop.cpp:107] Request to lookup properties for
user: 'test-principal' realm: '95302125b116' server FQDN: '95302125b116'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I0417 08:09:37.477407 31934 auxprop.cpp:179] Looking up auxiliary property
'*userPassword'
I0417 08:09:37.477465 31934 auxprop.cpp:179] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0417 08:09:37.477511 31934 auxprop.cpp:107] Request to lookup properties for
user: 'test-principal' realm: '95302125b116' server FQDN: '95302125b116'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I0417 08:09:37.477530 31934 auxprop.cpp:129] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0417 08:09:37.477540 31934 auxprop.cpp:129] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0417 08:09:37.477560 31934 authenticator.cpp:317] Authentication success
I0417 08:09:37.478315 31934 authenticatee.cpp:298] Authentication success
I0417 08:09:37.478456 31934 master.cpp:5831] Successfully authenticated
principal 'test-principal' at slave(141)@172.17.0.1:35480
I0417 08:09:37.478579 31934 authenticator.cpp:431] Authentication session
cleanup for crammd5_authenticatee(337)@172.17.0.1:35480
I0417 08:09:37.479070 31934 slave.cpp:1078] Successfully authenticated with
master master@172.17.0.1:35480
I0417 08:09:37.479257 31934 slave.cpp:1474] Will retry registration in
15.623679ms if necessary
I0417 08:09:37.479826 31934 master.cpp:4512] Registering agent at
slave(141)@172.17.0.1:35480 (95302125b116) with id
07f7917f-63d1-40d4-b983-4f0eb5c18f3d-S0
I0417 08:09:37.480527 31934 registrar.cpp:463] Applied 1 operations in
100340ns; attempting to update the 'registry'
I0417 08:09:37.482246 31934 log.cpp:683] Attempting to append 339 bytes to the
log
I0417 08:09:37.482530 31934 coordinator.cpp:348] Coordinator attempting to
write APPEND action at position 3
I0417 08:09:37.484277 31925 replica.cpp:537] Replica received write request for
position 3 from (6132)@172.17.0.1:35480
I0417 08:09:37.496318 31926 slave.cpp:1474] Will retry registration in
22.656945ms if necessary
I0417 08:09:37.496881 31929 master.cpp:4500] Ignoring register agent message
from slave(141)@172.17.0.1:35480 (95302125b116) as admission is already in
progress
I0417 08:09:37.511219 31925 leveldb.cpp:341] Persisting action (358 bytes) to
leveldb took 26.862484ms
I0417 08:09:37.511314 31925 replica.cpp:712] Persisted action at 3
I0417 08:09:37.512845 31925 replica.cpp:691] Replica received learned notice
for position 3 from @0.0.0.0:0
I0417 08:09:37.520174 31929 slave.cpp:1474] Will retry registration in
30.767012ms if necessary
I0417 08:09:37.520510 31929 master.cpp:4500] Ignoring register agent message
from slave(141)@172.17.0.1:35480 (95302125b116) as admission is already in
progress
I0417 08:09:37.544715 31925 leveldb.cpp:341] Persisting action (360 bytes) to
leveldb took 31.823486ms
I0417 08:09:37.544800 31925 replica.cpp:712] Persisted action at 3
I0417 08:09:37.544836 31925 replica.cpp:697] Replica learned APPEND action at
position 3
I0417 08:09:37.547479 31925 registrar.cpp:508] Successfully updated the
'registry' in 66.857728ms
I0417 08:09:37.547834 31925 log.cpp:702] Attempting to truncate the log to 3
I0417 08:09:37.548766 31935 coordinator.cpp:348] Coordinator attempting to
write TRUNCATE action at position 4
I0417 08:09:37.549940 31935 replica.cpp:537] Replica received write request for
position 4 from (6133)@172.17.0.1:35480
I0417 08:09:37.550437 31930 slave.cpp:3681] Received ping from
slave-observer(141)@172.17.0.1:35480
I0417 08:09:37.551272 31926 hierarchical.cpp:473] Added agent
07f7917f-63d1-40d4-b983-4f0eb5c18f3d-S0 (95302125b116) with cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
I0417 08:09:37.551576 31926 hierarchical.cpp:1488] No resources available to
allocate!
I0417 08:09:37.552067 31926 hierarchical.cpp:1162] Performed allocation for
agent 07f7917f-63d1-40d4-b983-4f0eb5c18f3d-S0 in 660830ns
I0417 08:09:37.551933 31929 slave.cpp:1474] Will retry registration in
151.64771ms if necessary
I0417 08:09:37.552996 31926 slave.cpp:1122] Registered with master
master@172.17.0.1:35480; given agent ID 07f7917f-63d1-40d4-b983-4f0eb5c18f3d-S0
I0417 08:09:37.553086 31926 fetcher.cpp:81] Clearing fetcher cache
I0417 08:09:37.553536 31926 slave.cpp:1145] Checkpointing SlaveInfo to
'/tmp/MasterSlaveReconciliationTest_ReconcileRace_5dHzkH/meta/slaves/07f7917f-63d1-40d4-b983-4f0eb5c18f3d-S0/slave.info'
I0417 08:09:37.553630 31929 status_update_manager.cpp:181] Resuming sending
status updates
I0417 08:09:37.554303 31926 slave.cpp:1182] Forwarding total oversubscribed
resources
I0417 08:09:37.554316 31901 sched.cpp:224] Version: 0.29.0
I0417 08:09:37.555250 31926 slave.cpp:945] New master detected at
master@172.17.0.1:35480
I0417 08:09:37.555346 31924 status_update_manager.cpp:174] Pausing sending
status updates
I0417 08:09:37.555438 31926 slave.cpp:1008] Authenticating with master
master@172.17.0.1:35480
I0417 08:09:37.555462 31926 slave.cpp:1013] Using default CRAM-MD5 authenticatee
I0417 08:09:37.555672 31926 slave.cpp:981] Detecting new master
I0417 08:09:37.555693 31932 authenticatee.cpp:121] Creating new client SASL
connection
I0417 08:09:37.555902 31922 sched.cpp:328] New master detected at
master@172.17.0.1:35480
I0417 08:09:37.555970 31922 sched.cpp:384] Authenticating with master
master@172.17.0.1:35480
I0417 08:09:37.555991 31922 sched.cpp:391] Using default CRAM-MD5 authenticatee
I0417 08:09:37.556249 31922 authenticatee.cpp:121] Creating new client SASL
connection
I0417 08:09:37.556551 31925 master.cpp:4580] Registered agent
07f7917f-63d1-40d4-b983-4f0eb5c18f3d-S0 at slave(141)@172.17.0.1:35480
(95302125b116) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0417 08:09:37.557147 31925 master.cpp:4482] Agent
07f7917f-63d1-40d4-b983-4f0eb5c18f3d-S0 at slave(141)@172.17.0.1:35480
(95302125b116) already registered, resending acknowledgement
I0417 08:09:37.557377 31925 master.cpp:4924] Received update of agent
07f7917f-63d1-40d4-b983-4f0eb5c18f3d-S0 at slave(141)@172.17.0.1:35480
(95302125b116) with total oversubscribed resources
I0417 08:09:37.557840 31925 master.cpp:5801] Authenticating
slave(141)@172.17.0.1:35480
I0417 08:09:37.558323 31924 hierarchical.cpp:531] Agent
07f7917f-63d1-40d4-b983-4f0eb5c18f3d-S0 (95302125b116) updated with
oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000], allocated: )
I0417 08:09:37.558761 31924 hierarchical.cpp:1488] No resources available to
allocate!
I0417 08:09:37.558898 31924 hierarchical.cpp:1162] Performed allocation for
agent 07f7917f-63d1-40d4-b983-4f0eb5c18f3d-S0 in 300116ns
I0417 08:09:37.557502 31922 slave.cpp:1122] Registered with master
master@172.17.0.1:35480; given agent ID 07f7917f-63d1-40d4-b983-4f0eb5c18f3d-S0
I0417 08:09:37.559084 31922 fetcher.cpp:81] Clearing fetcher cache
I0417 08:09:37.559470 31925 master.cpp:5801] Authenticating
scheduler-031e6ecc-8893-40de-9680-fe9dd368eb4d@172.17.0.1:35480
I0417 08:09:37.559553 31924 authenticator.cpp:413] Starting authentication
session for crammd5_authenticatee(338)@172.17.0.1:35480
I0417 08:09:37.560792 31934 authenticator.cpp:98] Creating new server SASL
connection
I0417 08:09:37.561223 31934 authenticatee.cpp:212] Received SASL authentication
mechanisms: CRAM-MD5
I0417 08:09:37.561372 31934 authenticatee.cpp:238] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0417 08:09:37.561549 31934 authenticator.cpp:203] Received SASL authentication
start
I0417 08:09:37.561646 31934 authenticator.cpp:325] Authentication requires more
steps
I0417 08:09:37.561738 31934 authenticatee.cpp:258] Received SASL authentication
step
I0417 08:09:37.561836 31934 authenticator.cpp:231] Received SASL authentication
step
I0417 08:09:37.561908 31934 auxprop.cpp:107] Request to lookup properties for
user: 'test-principal' realm: '95302125b116' server FQDN: '95302125b116'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I0417 08:09:37.561929 31934 auxprop.cpp:179] Looking up auxiliary property
'*userPassword'
I0417 08:09:37.562000 31934 auxprop.cpp:179] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0417 08:09:37.562026 31934 auxprop.cpp:107] Request to lookup properties for
user: 'test-principal' realm: '95302125b116' server FQDN: '95302125b116'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I0417 08:09:37.562037 31934 auxprop.cpp:129] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0417 08:09:37.562047 31934 auxprop.cpp:129] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0417 08:09:37.562063 31934 authenticator.cpp:317] Authentication success
I0417 08:09:37.562207 31934 authenticatee.cpp:298] Authentication success
I0417 08:09:37.559978 31929 status_update_manager.cpp:181] Resuming sending
status updates
I0417 08:09:37.562481 31924 authenticator.cpp:413] Starting authentication
session for crammd5_authenticatee(339)@172.17.0.1:35480
I0417 08:09:37.562568 31934 master.cpp:5831] Successfully authenticated
principal 'test-principal' at slave(141)@172.17.0.1:35480
I0417 08:09:37.563238 31924 authenticator.cpp:431] Authentication session
cleanup for crammd5_authenticatee(338)@172.17.0.1:35480
I0417 08:09:37.563580 31929 authenticator.cpp:98] Creating new server SASL
connection
I0417 08:09:37.563839 31929 authenticatee.cpp:212] Received SASL authentication
mechanisms: CRAM-MD5
I0417 08:09:37.563873 31929 authenticatee.cpp:238] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0417 08:09:37.563949 31929 authenticator.cpp:203] Received SASL authentication
start
I0417 08:09:37.563999 31929 authenticator.cpp:325] Authentication requires more
steps
I0417 08:09:37.564077 31929 authenticatee.cpp:258] Received SASL authentication
step
I0417 08:09:37.564167 31929 authenticator.cpp:231] Received SASL authentication
step
I0417 08:09:37.564196 31929 auxprop.cpp:107] Request to lookup properties for
user: 'test-principal' realm: '95302125b116' server FQDN: '95302125b116'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I0417 08:09:37.564208 31929 auxprop.cpp:179] Looking up auxiliary property
'*userPassword'
I0417 08:09:37.564240 31929 auxprop.cpp:179] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0417 08:09:37.564275 31929 auxprop.cpp:107] Request to lookup properties for
user: 'test-principal' realm: '95302125b116' server FQDN: '95302125b116'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I0417 08:09:37.564291 31929 auxprop.cpp:129] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0417 08:09:37.564299 31929 auxprop.cpp:129] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0417 08:09:37.564316 31929 authenticator.cpp:317] Authentication success
I0417 08:09:37.564453 31929 authenticatee.cpp:298] Authentication success
I0417 08:09:37.564550 31929 master.cpp:5831] Successfully authenticated
principal 'test-principal' at
scheduler-031e6ecc-8893-40de-9680-fe9dd368eb4d@172.17.0.1:35480
I0417 08:09:37.564759 31923 authenticator.cpp:431] Authentication session
cleanup for crammd5_authenticatee(339)@172.17.0.1:35480
I0417 08:09:37.565045 31923 sched.cpp:474] Successfully authenticated with
master master@172.17.0.1:35480
I0417 08:09:37.565073 31923 sched.cpp:779] Sending SUBSCRIBE call to
master@172.17.0.1:35480
I0417 08:09:37.565170 31923 sched.cpp:812] Will retry registration in
38.454316ms if necessary
I0417 08:09:37.565574 31929 master.cpp:2463] Received SUBSCRIBE call for
framework 'default' at
scheduler-031e6ecc-8893-40de-9680-fe9dd368eb4d@172.17.0.1:35480
I0417 08:09:37.565656 31929 master.cpp:1971] Authorizing framework principal
'test-principal' to receive offers for role '*'
I0417 08:09:37.565956 31929 master.cpp:2539] Subscribing framework default with
checkpointing disabled and capabilities [ ]
I0417 08:09:37.566779 31933 sched.cpp:706] Framework registered with
07f7917f-63d1-40d4-b983-4f0eb5c18f3d-0000
I0417 08:09:37.566839 31933 sched.cpp:720] Scheduler::registered took 26993ns
I0417 08:09:37.559933 31922 slave.cpp:1145] Checkpointing SlaveInfo to
'/tmp/MasterSlaveReconciliationTest_ReconcileRace_5dHzkH/meta/slaves/07f7917f-63d1-40d4-b983-4f0eb5c18f3d-S0/slave.info'
I0417 08:09:37.567049 31929 hierarchical.cpp:264] Added framework
07f7917f-63d1-40d4-b983-4f0eb5c18f3d-0000
I0417 08:09:37.568264 31929 hierarchical.cpp:1583] No inverse offers to send
out!
I0417 08:09:37.568366 31929 hierarchical.cpp:1139] Performed allocation for 1
agents in 1.285506ms
I0417 08:09:37.568692 31921 master.cpp:5630] Sending 1 offers to framework
07f7917f-63d1-40d4-b983-4f0eb5c18f3d-0000 (default) at
scheduler-031e6ecc-8893-40de-9680-fe9dd368eb4d@172.17.0.1:35480
I0417 08:09:37.569186 31921 sched.cpp:876] Scheduler::resourceOffers took
112943ns
I0417 08:09:37.578850 31922 slave.cpp:1182] Forwarding total oversubscribed
resources
I0417 08:09:37.579274 31922 slave.cpp:1078] Successfully authenticated with
master master@172.17.0.1:35480
I0417 08:09:37.579457 31922 master.cpp:4924] Received update of agent
07f7917f-63d1-40d4-b983-4f0eb5c18f3d-S0 at slave(141)@172.17.0.1:35480
(95302125b116) with total oversubscribed resources
I0417 08:09:37.580134 31922 hierarchical.cpp:531] Agent
07f7917f-63d1-40d4-b983-4f0eb5c18f3d-S0 (95302125b116) updated with
oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000])
I0417 08:09:37.580379 31922 hierarchical.cpp:1488] No resources available to
allocate!
I0417 08:09:37.580432 31922 hierarchical.cpp:1583] No inverse offers to send
out!
I0417 08:09:37.580509 31922 hierarchical.cpp:1162] Performed allocation for
agent 07f7917f-63d1-40d4-b983-4f0eb5c18f3d-S0 in 307063ns
I0417 08:09:37.588114 31935 leveldb.cpp:341] Persisting action (16 bytes) to
leveldb took 38.050698ms
I0417 08:09:37.588212 31935 replica.cpp:712] Persisted action at 4
I0417 08:09:37.589210 31933 replica.cpp:691] Replica received learned notice
for position 4 from @0.0.0.0:0
I0417 08:09:37.613415 31933 leveldb.cpp:341] Persisting action (18 bytes) to
leveldb took 24.142675ms
I0417 08:09:37.613595 31933 leveldb.cpp:399] Deleting ~2 keys from leveldb took
87156ns
I0417 08:09:37.613634 31933 replica.cpp:712] Persisted action at 4
I0417 08:09:37.613673 31933 replica.cpp:697] Replica learned TRUNCATE action at
position 4
I0417 08:09:38.114523 31933 hierarchical.cpp:1488] No resources available to
allocate!
I0417 08:09:38.114627 31933 hierarchical.cpp:1583] No inverse offers to send
out!
I0417 08:09:38.114720 31933 hierarchical.cpp:1139] Performed allocation for 1
agents in 480560ns
I0417 08:09:39.115829 31933 hierarchical.cpp:1488] No resources available to
allocate!
I0417 08:09:39.115911 31933 hierarchical.cpp:1583] No inverse offers to send
out!
I0417 08:09:39.115995 31933 hierarchical.cpp:1139] Performed allocation for 1
agents in 430596ns
I0417 08:09:40.116791 31924 hierarchical.cpp:1488] No resources available to
allocate!
I0417 08:09:40.116873 31924 hierarchical.cpp:1583] No inverse offers to send
out!
I0417 08:09:40.116955 31924 hierarchical.cpp:1139] Performed allocation for 1
agents in 447134ns
I0417 08:09:41.118541 31930 hierarchical.cpp:1488] No resources available to
allocate!
I0417 08:09:41.118638 31930 hierarchical.cpp:1583] No inverse offers to send
out!
I0417 08:09:41.118724 31930 hierarchical.cpp:1139] Performed allocation for 1
agents in 436517ns
I0417 08:09:42.120342 31925 hierarchical.cpp:1488] No resources available to
allocate!
I0417 08:09:42.120429 31925 hierarchical.cpp:1583] No inverse offers to send
out!
I0417 08:09:42.120513 31925 hierarchical.cpp:1139] Performed allocation for 1
agents in 442687ns
I0417 08:09:43.122072 31934 hierarchical.cpp:1488] No resources available to
allocate!
I0417 08:09:43.122159 31934 hierarchical.cpp:1583] No inverse offers to send
out!
I0417 08:09:43.122244 31934 hierarchical.cpp:1139] Performed allocation for 1
agents in 434630ns
I0417 08:09:44.123519 31920 hierarchical.cpp:1488] No resources available to
allocate!
I0417 08:09:44.123623 31920 hierarchical.cpp:1583] No inverse offers to send
out!
I0417 08:09:44.123718 31920 hierarchical.cpp:1139] Performed allocation for 1
agents in 474577ns
I0417 08:09:45.125074 31924 hierarchical.cpp:1488] No resources available to
allocate!
I0417 08:09:45.125164 31924 hierarchical.cpp:1583] No inverse offers to send
out!
I0417 08:09:45.125249 31924 hierarchical.cpp:1139] Performed allocation for 1
agents in 443224ns
I0417 08:09:46.126581 31934 hierarchical.cpp:1488] No resources available to
allocate!
I0417 08:09:46.126675 31934 hierarchical.cpp:1583] No inverse offers to send
out!
I0417 08:09:46.126759 31934 hierarchical.cpp:1139] Performed allocation for 1
agents in 429628ns
I0417 08:09:47.127806 31920 hierarchical.cpp:1488] No resources available to
allocate!
I0417 08:09:47.127892 31920 hierarchical.cpp:1583] No inverse offers to send
out!
I0417 08:09:47.127976 31920 hierarchical.cpp:1139] Performed allocation for 1
agents in 439045ns
I0417 08:09:48.128811 31928 hierarchical.cpp:1488] No resources available to
allocate!
I0417 08:09:48.128896 31928 hierarchical.cpp:1583] No inverse offers to send
out!
I0417 08:09:48.128983 31928 hierarchical.cpp:1139] Performed allocation for 1
agents in 444979ns
I0417 08:09:49.129803 31930 hierarchical.cpp:1488] No resources available to
allocate!
I0417 08:09:49.129889 31930 hierarchical.cpp:1583] No inverse offers to send
out!
I0417 08:09:49.129972 31930 hierarchical.cpp:1139] Performed allocation for 1
agents in 434594ns
I0417 08:09:50.131384 31927 hierarchical.cpp:1488] No resources available to
allocate!
I0417 08:09:50.131472 31927 hierarchical.cpp:1583] No inverse offers to send
out!
I0417 08:09:50.131559 31927 hierarchical.cpp:1139] Performed allocation for 1
agents in 441996ns
I0417 08:09:51.132650 31925 hierarchical.cpp:1488] No resources available to
allocate!
I0417 08:09:51.132735 31925 hierarchical.cpp:1583] No inverse offers to send
out!
I0417 08:09:51.132819 31925 hierarchical.cpp:1139] Performed allocation for 1
agents in 436612ns
I0417 08:09:52.133709 31932 hierarchical.cpp:1488] No resources available to
allocate!
I0417 08:09:52.133798 31932 hierarchical.cpp:1583] No inverse offers to send
out!
I0417 08:09:52.133889 31932 hierarchical.cpp:1139] Performed allocation for 1
agents in 470131ns
I0417 08:09:52.476372 31928 slave.cpp:4972] Querying resource estimator for
oversubscribable resources
I0417 08:09:52.476711 31928 slave.cpp:4986] Received oversubscribable resources
from the resource estimator
I0417 08:09:52.551301 31933 slave.cpp:3681] Received ping from
slave-observer(141)@172.17.0.1:35480
../../src/tests/master_slave_reconciliation_tests.cpp:310: Failure
Failed to wait 15secs for reregisterSlaveMessage
I0417 08:09:52.584074 31935 master.cpp:1375] Framework
07f7917f-63d1-40d4-b983-4f0eb5c18f3d-0000 (default) at
scheduler-031e6ecc-8893-40de-9680-fe9dd368eb4d@172.17.0.1:35480 disconnected
I0417 08:09:52.584152 31935 master.cpp:2764] Disconnecting framework
07f7917f-63d1-40d4-b983-4f0eb5c18f3d-0000 (default) at
scheduler-031e6ecc-8893-40de-9680-fe9dd368eb4d@172.17.0.1:35480
I0417 08:09:52.584188 31935 master.cpp:2788] Deactivating framework
07f7917f-63d1-40d4-b983-4f0eb5c18f3d-0000 (default) at
scheduler-031e6ecc-8893-40de-9680-fe9dd368eb4d@172.17.0.1:35480
I0417 08:09:52.584708 31932 hierarchical.cpp:375] Deactivated framework
07f7917f-63d1-40d4-b983-4f0eb5c18f3d-0000
I0417 08:09:52.585319 31932 hierarchical.cpp:891] Recovered cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on agent
07f7917f-63d1-40d4-b983-4f0eb5c18f3d-S0 from framework
07f7917f-63d1-40d4-b983-4f0eb5c18f3d-0000
W0417 08:09:52.585718 31935 master.hpp:1828] Master attempted to send message
to disconnected framework 07f7917f-63d1-40d4-b983-4f0eb5c18f3d-0000 (default)
at scheduler-031e6ecc-8893-40de-9680-fe9dd368eb4d@172.17.0.1:35480
I0417 08:09:52.585855 31935 master.cpp:1399] Giving framework
07f7917f-63d1-40d4-b983-4f0eb5c18f3d-0000 (default) at
scheduler-031e6ecc-8893-40de-9680-fe9dd368eb4d@172.17.0.1:35480 0ns to failover
I0417 08:09:52.600791 31925 master.cpp:5482] Framework failover timeout,
removing framework 07f7917f-63d1-40d4-b983-4f0eb5c18f3d-0000 (default) at
scheduler-031e6ecc-8893-40de-9680-fe9dd368eb4d@172.17.0.1:35480
I0417 08:09:52.600867 31925 master.cpp:6210] Removing framework
07f7917f-63d1-40d4-b983-4f0eb5c18f3d-0000 (default) at
scheduler-031e6ecc-8893-40de-9680-fe9dd368eb4d@172.17.0.1:35480
I0417 08:09:52.601167 31901 slave.cpp:817] Agent terminating
I0417 08:09:52.606468 31935 master.cpp:1336] Agent
07f7917f-63d1-40d4-b983-4f0eb5c18f3d-S0 at slave(141)@172.17.0.1:35480
(95302125b116) disconnected
I0417 08:09:52.607295 31935 master.cpp:2823] Disconnecting agent
07f7917f-63d1-40d4-b983-4f0eb5c18f3d-S0 at slave(141)@172.17.0.1:35480
(95302125b116)
I0417 08:09:52.608685 31935 master.cpp:2842] Deactivating agent
07f7917f-63d1-40d4-b983-4f0eb5c18f3d-S0 at slave(141)@172.17.0.1:35480
(95302125b116)
I0417 08:09:52.609040 31925 hierarchical.cpp:326] Removed framework
07f7917f-63d1-40d4-b983-4f0eb5c18f3d-0000
I0417 08:09:52.609145 31925 hierarchical.cpp:560] Agent
07f7917f-63d1-40d4-b983-4f0eb5c18f3d-S0 deactivated
I0417 08:09:52.626760 31901 master.cpp:1189] Master terminating
I0417 08:09:52.627313 31933 hierarchical.cpp:505] Removed agent
07f7917f-63d1-40d4-b983-4f0eb5c18f3d-S0
../../3rdparty/libprocess/include/process/gmock.hpp:446: Failure
Actual function call count doesn't match EXPECT_CALL(filter->mock,
filter(testing::A<const MessageEvent&>()))...
Expected args: message matcher (8-byte object <08-75 04-68 A4-2B 00-00>, 1,
1)
Expected: to be called once
Actual: never called - unsatisfied and active
[ FAILED ] MasterSlaveReconciliationTest.ReconcileRace (16016 ms)
{code}
> MasterSlaveReconciliationTest.ReconcileRace is flaky
> ----------------------------------------------------
>
> Key: MESOS-2331
> URL: https://issues.apache.org/jira/browse/MESOS-2331
> Project: Mesos
> Issue Type: Bug
> Components: test
> Affects Versions: 0.22.0
> Reporter: Yan Xu
> Assignee: Qian Zhang
> Labels: flaky
>
> {noformat:title=}
> [ RUN ] MasterSlaveReconciliationTest.ReconcileRace
> Using temporary directory
> '/tmp/MasterSlaveReconciliationTest_ReconcileRace_NE9nhV'
> I0206 19:09:44.196542 32362 leveldb.cpp:175] Opened db in 38.230192ms
> I0206 19:09:44.206826 32362 leveldb.cpp:182] Compacted db in 9.988493ms
> I0206 19:09:44.207164 32362 leveldb.cpp:197] Created db iterator in 29979ns
> I0206 19:09:44.207641 32362 leveldb.cpp:203] Seeked to beginning of db in
> 4478ns
> I0206 19:09:44.207929 32362 leveldb.cpp:272] Iterated through 0 keys in the
> db in 737ns
> I0206 19:09:44.208222 32362 replica.cpp:743] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0206 19:09:44.209132 32384 recover.cpp:448] Starting replica recovery
> I0206 19:09:44.209524 32384 recover.cpp:474] Replica is in EMPTY status
> I0206 19:09:44.211094 32384 replica.cpp:640] Replica in EMPTY status received
> a broadcasted recover request
> I0206 19:09:44.211385 32384 recover.cpp:194] Received a recover response from
> a replica in EMPTY status
> I0206 19:09:44.211902 32384 recover.cpp:565] Updating replica status to
> STARTING
> I0206 19:09:44.236177 32381 master.cpp:344] Master
> 20150206-190944-16842879-36452-32362 (lucid) started on 127.0.1.1:36452
> I0206 19:09:44.236291 32381 master.cpp:390] Master only allowing
> authenticated frameworks to register
> I0206 19:09:44.236305 32381 master.cpp:395] Master only allowing
> authenticated slaves to register
> I0206 19:09:44.236327 32381 credentials.hpp:35] Loading credentials for
> authentication from
> '/tmp/MasterSlaveReconciliationTest_ReconcileRace_NE9nhV/credentials'
> I0206 19:09:44.236601 32381 master.cpp:439] Authorization enabled
> I0206 19:09:44.238539 32381 hierarchical_allocator_process.hpp:284]
> Initialized hierarchical allocator process
> I0206 19:09:44.238662 32381 whitelist_watcher.cpp:64] No whitelist given
> I0206 19:09:44.239364 32381 master.cpp:1350] The newly elected leader is
> master@127.0.1.1:36452 with id 20150206-190944-16842879-36452-32362
> I0206 19:09:44.239392 32381 master.cpp:1363] Elected as the leading master!
> I0206 19:09:44.239413 32381 master.cpp:1181] Recovering from registrar
> I0206 19:09:44.239645 32381 registrar.cpp:312] Recovering registrar
> I0206 19:09:44.241142 32384 leveldb.cpp:305] Persisting metadata (8 bytes) to
> leveldb took 29.029117ms
> I0206 19:09:44.241189 32384 replica.cpp:322] Persisted replica status to
> STARTING
> I0206 19:09:44.241478 32384 recover.cpp:474] Replica is in STARTING status
> I0206 19:09:44.243075 32384 replica.cpp:640] Replica in STARTING status
> received a broadcasted recover request
> I0206 19:09:44.243398 32384 recover.cpp:194] Received a recover response from
> a replica in STARTING status
> I0206 19:09:44.243964 32384 recover.cpp:565] Updating replica status to VOTING
> I0206 19:09:44.255692 32384 leveldb.cpp:305] Persisting metadata (8 bytes) to
> leveldb took 11.502759ms
> I0206 19:09:44.255765 32384 replica.cpp:322] Persisted replica status to
> VOTING
> I0206 19:09:44.256009 32384 recover.cpp:579] Successfully joined the Paxos
> group
> I0206 19:09:44.256253 32384 recover.cpp:463] Recover process terminated
> I0206 19:09:44.257669 32384 log.cpp:659] Attempting to start the writer
> I0206 19:09:44.259944 32377 replica.cpp:476] Replica received implicit
> promise request with proposal 1
> I0206 19:09:44.268805 32377 leveldb.cpp:305] Persisting metadata (8 bytes) to
> leveldb took 8.45858ms
> I0206 19:09:44.269067 32377 replica.cpp:344] Persisted promised to 1
> I0206 19:09:44.277974 32383 coordinator.cpp:229] Coordinator attemping to
> fill missing position
> I0206 19:09:44.279767 32383 replica.cpp:377] Replica received explicit
> promise request for position 0 with proposal 2
> I0206 19:09:44.288940 32383 leveldb.cpp:342] Persisting action (8 bytes) to
> leveldb took 9.128603ms
> I0206 19:09:44.289294 32383 replica.cpp:678] Persisted action at 0
> I0206 19:09:44.296417 32377 replica.cpp:510] Replica received write request
> for position 0
> I0206 19:09:44.296944 32377 leveldb.cpp:437] Reading position from leveldb
> took 48457ns
> I0206 19:09:44.305337 32377 leveldb.cpp:342] Persisting action (14 bytes) to
> leveldb took 8.141689ms
> I0206 19:09:44.305662 32377 replica.cpp:678] Persisted action at 0
> I0206 19:09:44.318168 32378 replica.cpp:657] Replica received learned notice
> for position 0
> I0206 19:09:44.326036 32378 leveldb.cpp:342] Persisting action (16 bytes) to
> leveldb took 6.910907ms
> I0206 19:09:44.326654 32378 replica.cpp:678] Persisted action at 0
> I0206 19:09:44.326942 32378 replica.cpp:663] Replica learned NOP action at
> position 0
> I0206 19:09:44.338552 32377 log.cpp:675] Writer started with ending position 0
> I0206 19:09:44.340262 32377 leveldb.cpp:437] Reading position from leveldb
> took 58420ns
> I0206 19:09:44.342963 32377 registrar.cpp:345] Successfully fetched the
> registry (0B) in 103.275776ms
> I0206 19:09:44.343070 32377 registrar.cpp:444] Applied 1 operations in
> 26702ns; attempting to update the 'registry'
> I0206 19:09:44.345824 32377 log.cpp:683] Attempting to append 118 bytes to
> the log
> I0206 19:09:44.346019 32377 coordinator.cpp:339] Coordinator attempting to
> write APPEND action at position 1
> I0206 19:09:44.347017 32382 replica.cpp:510] Replica received write request
> for position 1
> I0206 19:09:44.354070 32382 leveldb.cpp:342] Persisting action (135 bytes) to
> leveldb took 7.011319ms
> I0206 19:09:44.354118 32382 replica.cpp:678] Persisted action at 1
> I0206 19:09:44.355094 32382 replica.cpp:657] Replica received learned notice
> for position 1
> I0206 19:09:44.358392 32382 leveldb.cpp:342] Persisting action (137 bytes) to
> leveldb took 3.267785ms
> I0206 19:09:44.358621 32382 replica.cpp:678] Persisted action at 1
> I0206 19:09:44.358949 32382 replica.cpp:663] Replica learned APPEND action at
> position 1
> I0206 19:09:44.367099 32382 registrar.cpp:489] Successfully updated the
> 'registry' in 23.9488ms
> I0206 19:09:44.367259 32382 registrar.cpp:375] Successfully recovered
> registrar
> I0206 19:09:44.367698 32382 master.cpp:1208] Recovered 0 slaves from the
> Registry (82B) ; allowing 10mins for slaves to re-register
> I0206 19:09:44.367790 32382 log.cpp:702] Attempting to truncate the log to 1
> I0206 19:09:44.368067 32382 coordinator.cpp:339] Coordinator attempting to
> write TRUNCATE action at position 2
> I0206 19:09:44.369544 32381 replica.cpp:510] Replica received write request
> for position 2
> I0206 19:09:44.378540 32381 leveldb.cpp:342] Persisting action (16 bytes) to
> leveldb took 8.940568ms
> I0206 19:09:44.378811 32381 replica.cpp:678] Persisted action at 2
> I0206 19:09:44.387471 32377 replica.cpp:657] Replica received learned notice
> for position 2
> I0206 19:09:44.394693 32377 leveldb.cpp:342] Persisting action (18 bytes) to
> leveldb took 6.892787ms
> I0206 19:09:44.394815 32377 leveldb.cpp:400] Deleting ~1 keys from leveldb
> took 57353ns
> I0206 19:09:44.394840 32377 replica.cpp:678] Persisted action at 2
> I0206 19:09:44.394875 32377 replica.cpp:663] Replica learned TRUNCATE action
> at position 2
> I0206 19:09:44.423720 32380 slave.cpp:172] Slave started on
> 14)@127.0.1.1:36452
> I0206 19:09:44.426247 32380 credentials.hpp:83] Loading credential for
> authentication from
> '/tmp/MasterSlaveReconciliationTest_ReconcileRace_nT15cx/credential'
> I0206 19:09:44.426745 32380 slave.cpp:281] Slave using credential for:
> test-principal
> I0206 19:09:44.427234 32380 slave.cpp:299] Slave resources: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0206 19:09:44.427616 32380 slave.cpp:328] Slave hostname: lucid
> I0206 19:09:44.427829 32380 slave.cpp:329] Slave checkpoint: false
> W0206 19:09:44.428047 32380 slave.cpp:331] Disabling checkpointing is
> deprecated and the --checkpoint flag will be removed in a future release.
> Please avoid using this flag
> I0206 19:09:44.429821 32379 state.cpp:32] Recovering state from
> '/tmp/MasterSlaveReconciliationTest_ReconcileRace_nT15cx/meta'
> I0206 19:09:44.438045 32380 status_update_manager.cpp:196] Recovering status
> update manager
> I0206 19:09:44.438377 32380 slave.cpp:3526] Finished recovery
> I0206 19:09:44.439144 32380 slave.cpp:620] New master detected at
> master@127.0.1.1:36452
> I0206 19:09:44.439275 32380 slave.cpp:683] Authenticating with master
> master@127.0.1.1:36452
> I0206 19:09:44.439297 32380 slave.cpp:688] Using default CRAM-MD5
> authenticatee
> I0206 19:09:44.439472 32380 slave.cpp:656] Detecting new master
> I0206 19:09:44.439589 32380 status_update_manager.cpp:170] Pausing sending
> status updates
> I0206 19:09:44.439757 32380 authenticatee.hpp:137] Creating new client SASL
> connection
> I0206 19:09:44.440255 32380 master.cpp:3786] Authenticating
> slave(14)@127.0.1.1:36452
> I0206 19:09:44.440287 32380 master.cpp:3797] Using default CRAM-MD5
> authenticator
> I0206 19:09:44.440712 32380 authenticator.hpp:169] Creating new server SASL
> connection
> I0206 19:09:44.441010 32380 authenticatee.hpp:228] Received SASL
> authentication mechanisms: CRAM-MD5
> I0206 19:09:44.441036 32380 authenticatee.hpp:254] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0206 19:09:44.441136 32380 authenticator.hpp:275] Received SASL
> authentication start
> I0206 19:09:44.441216 32380 authenticator.hpp:397] Authentication requires
> more steps
> I0206 19:09:44.441303 32380 authenticatee.hpp:274] Received SASL
> authentication step
> I0206 19:09:44.441395 32380 authenticator.hpp:303] Received SASL
> authentication step
> I0206 19:09:44.441431 32380 auxprop.cpp:98] Request to lookup properties for
> user: 'test-principal' realm: 'lucid' server FQDN: 'lucid'
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0206 19:09:44.441442 32380 auxprop.cpp:170] Looking up auxiliary property
> '*userPassword'
> I0206 19:09:44.441493 32380 auxprop.cpp:170] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0206 19:09:44.441526 32380 auxprop.cpp:98] Request to lookup properties for
> user: 'test-principal' realm: 'lucid' server FQDN: 'lucid'
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0206 19:09:44.441540 32380 auxprop.cpp:120] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0206 19:09:44.441546 32380 auxprop.cpp:120] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0206 19:09:44.441561 32380 authenticator.hpp:389] Authentication success
> I0206 19:09:44.441668 32380 authenticatee.hpp:314] Authentication success
> I0206 19:09:44.441756 32380 master.cpp:3844] Successfully authenticated
> principal 'test-principal' at slave(14)@127.0.1.1:36452
> I0206 19:09:44.442070 32380 slave.cpp:754] Successfully authenticated with
> master master@127.0.1.1:36452
> I0206 19:09:44.442211 32380 slave.cpp:1082] Will retry registration in
> 19.488037ms if necessary
> I0206 19:09:44.442474 32380 master.cpp:2911] Registering slave at
> slave(14)@127.0.1.1:36452 (lucid) with id
> 20150206-190944-16842879-36452-32362-S0
> I0206 19:09:44.442922 32380 registrar.cpp:444] Applied 1 operations in
> 72989ns; attempting to update the 'registry'
> I0206 19:09:44.445914 32380 log.cpp:683] Attempting to append 283 bytes to
> the log
> I0206 19:09:44.446125 32380 coordinator.cpp:339] Coordinator attempting to
> write APPEND action at position 3
> I0206 19:09:44.448060 32384 replica.cpp:510] Replica received write request
> for position 3
> I0206 19:09:44.450963 32384 leveldb.cpp:342] Persisting action (302 bytes) to
> leveldb took 2.859704ms
> I0206 19:09:44.451252 32384 replica.cpp:678] Persisted action at 3
> I0206 19:09:44.452453 32382 replica.cpp:657] Replica received learned notice
> for position 3
> I0206 19:09:44.463752 32382 leveldb.cpp:342] Persisting action (304 bytes) to
> leveldb took 11.254934ms
> I0206 19:09:44.463817 32382 replica.cpp:678] Persisted action at 3
> I0206 19:09:44.463848 32382 replica.cpp:663] Replica learned APPEND action at
> position 3
> I0206 19:09:44.465450 32382 registrar.cpp:489] Successfully updated the
> 'registry' in 22.45888ms
> I0206 19:09:44.465725 32382 log.cpp:702] Attempting to truncate the log to 3
> I0206 19:09:44.466614 32379 coordinator.cpp:339] Coordinator attempting to
> write TRUNCATE action at position 4
> I0206 19:09:44.466958 32379 slave.cpp:1082] Will retry registration in
> 34.738916ms if necessary
> I0206 19:09:44.467807 32379 replica.cpp:510] Replica received write request
> for position 4
> I0206 19:09:44.469007 32381 slave.cpp:2595] Received ping from
> slave-observer(14)@127.0.1.1:36452
> I0206 19:09:44.469740 32377 hierarchical_allocator_process.hpp:450] Added
> slave 20150206-190944-16842879-36452-32362-S0 (lucid) with cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
> I0206 19:09:44.469871 32377 hierarchical_allocator_process.hpp:828] No
> resources available to allocate!
> I0206 19:09:44.469892 32377 hierarchical_allocator_process.hpp:753] Performed
> allocation for slave 20150206-190944-16842879-36452-32362-S0 in 107661ns
> I0206 19:09:44.470643 32378 slave.cpp:788] Registered with master
> master@127.0.1.1:36452; given slave ID 20150206-190944-16842879-36452-32362-S0
> I0206 19:09:44.473881 32383 status_update_manager.cpp:177] Resuming sending
> status updates
> I0206 19:09:44.476253 32379 leveldb.cpp:342] Persisting action (16 bytes) to
> leveldb took 8.4136ms
> I0206 19:09:44.476297 32379 replica.cpp:678] Persisted action at 4
> I0206 19:09:44.488441 32382 master.cpp:2968] Registered slave
> 20150206-190944-16842879-36452-32362-S0 at slave(14)@127.0.1.1:36452 (lucid)
> with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0206 19:09:44.489220 32382 master.cpp:2887] Slave
> 20150206-190944-16842879-36452-32362-S0 at slave(14)@127.0.1.1:36452 (lucid)
> already registered, resending acknowledgement
> I0206 19:09:44.490684 32379 replica.cpp:657] Replica received learned notice
> for position 4
> I0206 19:09:44.491462 32362 sched.cpp:149] Version: 0.22.0
> I0206 19:09:44.494812 32378 slave.cpp:620] New master detected at
> master@127.0.1.1:36452
> I0206 19:09:44.494870 32378 slave.cpp:683] Authenticating with master
> master@127.0.1.1:36452
> I0206 19:09:44.494889 32378 slave.cpp:688] Using default CRAM-MD5
> authenticatee
> I0206 19:09:44.495014 32378 slave.cpp:656] Detecting new master
> I0206 19:09:44.495160 32378 sched.cpp:246] New master detected at
> master@127.0.1.1:36452
> I0206 19:09:44.495232 32378 sched.cpp:302] Authenticating with master
> master@127.0.1.1:36452
> I0206 19:09:44.495252 32378 sched.cpp:309] Using default CRAM-MD5
> authenticatee
> I0206 19:09:44.495458 32378 status_update_manager.cpp:170] Pausing sending
> status updates
> I0206 19:09:44.495589 32378 authenticatee.hpp:137] Creating new client SASL
> connection
> I0206 19:09:44.495846 32378 authenticatee.hpp:137] Creating new client SASL
> connection
> I0206 19:09:44.498770 32382 master.cpp:3786] Authenticating
> slave(14)@127.0.1.1:36452
> I0206 19:09:44.498812 32382 master.cpp:3797] Using default CRAM-MD5
> authenticator
> I0206 19:09:44.499124 32382 master.cpp:3786] Authenticating
> scheduler-167ce2f8-8268-41f7-9c72-a4e29dc3316c@127.0.1.1:36452
> I0206 19:09:44.499151 32382 master.cpp:3797] Using default CRAM-MD5
> authenticator
> I0206 19:09:44.499363 32382 slave.cpp:788] Registered with master
> master@127.0.1.1:36452; given slave ID 20150206-190944-16842879-36452-32362-S0
> I0206 19:09:44.499675 32382 authenticator.hpp:169] Creating new server SASL
> connection
> I0206 19:09:44.499925 32382 authenticator.hpp:169] Creating new server SASL
> connection
> I0206 19:09:44.500035 32382 status_update_manager.cpp:177] Resuming sending
> status updates
> I0206 19:09:44.500330 32382 authenticatee.hpp:228] Received SASL
> authentication mechanisms: CRAM-MD5
> I0206 19:09:44.500356 32382 authenticatee.hpp:254] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0206 19:09:44.500501 32382 authenticatee.hpp:228] Received SASL
> authentication mechanisms: CRAM-MD5
> I0206 19:09:44.500526 32382 authenticatee.hpp:254] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0206 19:09:44.500691 32382 authenticator.hpp:275] Received SASL
> authentication start
> I0206 19:09:44.500758 32382 authenticator.hpp:397] Authentication requires
> more steps
> I0206 19:09:44.500836 32382 authenticator.hpp:275] Received SASL
> authentication start
> I0206 19:09:44.500874 32382 authenticator.hpp:397] Authentication requires
> more steps
> I0206 19:09:44.500943 32382 authenticatee.hpp:274] Received SASL
> authentication step
> I0206 19:09:44.501026 32382 authenticatee.hpp:274] Received SASL
> authentication step
> I0206 19:09:44.501104 32382 authenticator.hpp:303] Received SASL
> authentication step
> I0206 19:09:44.501130 32382 auxprop.cpp:98] Request to lookup properties for
> user: 'test-principal' realm: 'lucid' server FQDN: 'lucid'
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0206 19:09:44.501142 32382 auxprop.cpp:170] Looking up auxiliary property
> '*userPassword'
> I0206 19:09:44.501188 32382 auxprop.cpp:170] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0206 19:09:44.501212 32382 auxprop.cpp:98] Request to lookup properties for
> user: 'test-principal' realm: 'lucid' server FQDN: 'lucid'
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0206 19:09:44.501224 32382 auxprop.cpp:120] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0206 19:09:44.501230 32382 auxprop.cpp:120] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0206 19:09:44.501245 32382 authenticator.hpp:389] Authentication success
> I0206 19:09:44.501368 32382 authenticator.hpp:303] Received SASL
> authentication step
> I0206 19:09:44.501394 32382 auxprop.cpp:98] Request to lookup properties for
> user: 'test-principal' realm: 'lucid' server FQDN: 'lucid'
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0206 19:09:44.501405 32382 auxprop.cpp:170] Looking up auxiliary property
> '*userPassword'
> I0206 19:09:44.501435 32382 auxprop.cpp:170] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0206 19:09:44.501458 32382 auxprop.cpp:98] Request to lookup properties for
> user: 'test-principal' realm: 'lucid' server FQDN: 'lucid'
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0206 19:09:44.501469 32382 auxprop.cpp:120] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0206 19:09:44.501477 32382 auxprop.cpp:120] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0206 19:09:44.501489 32382 authenticator.hpp:389] Authentication success
> I0206 19:09:44.501582 32382 authenticatee.hpp:314] Authentication success
> I0206 19:09:44.501672 32382 master.cpp:3844] Successfully authenticated
> principal 'test-principal' at slave(14)@127.0.1.1:36452
> I0206 19:09:44.501898 32382 master.cpp:3844] Successfully authenticated
> principal 'test-principal' at
> scheduler-167ce2f8-8268-41f7-9c72-a4e29dc3316c@127.0.1.1:36452
> I0206 19:09:44.502104 32382 authenticatee.hpp:314] Authentication success
> I0206 19:09:44.502272 32382 slave.cpp:754] Successfully authenticated with
> master master@127.0.1.1:36452
> I0206 19:09:44.502421 32382 sched.cpp:390] Successfully authenticated with
> master master@127.0.1.1:36452
> I0206 19:09:44.502447 32382 sched.cpp:513] Sending registration request to
> master@127.0.1.1:36452
> I0206 19:09:44.502512 32382 sched.cpp:546] Will retry registration in
> 1.990458655secs if necessary
> I0206 19:09:44.502679 32382 master.cpp:1568] Received registration request
> for framework 'default' at
> scheduler-167ce2f8-8268-41f7-9c72-a4e29dc3316c@127.0.1.1:36452
> I0206 19:09:44.502760 32382 master.cpp:1429] Authorizing framework principal
> 'test-principal' to receive offers for role '*'
> I0206 19:09:44.503207 32379 leveldb.cpp:342] Persisting action (18 bytes) to
> leveldb took 12.488335ms
> I0206 19:09:44.503340 32379 leveldb.cpp:400] Deleting ~2 keys from leveldb
> took 95587ns
> I0206 19:09:44.503365 32379 replica.cpp:678] Persisted action at 4
> I0206 19:09:44.503394 32379 replica.cpp:663] Replica learned TRUNCATE action
> at position 4
> I0206 19:09:44.504719 32382 master.cpp:1632] Registering framework
> 20150206-190944-16842879-36452-32362-0000 (default) at
> scheduler-167ce2f8-8268-41f7-9c72-a4e29dc3316c@127.0.1.1:36452
> I0206 19:09:44.505327 32380 hierarchical_allocator_process.hpp:318] Added
> framework 20150206-190944-16842879-36452-32362-0000
> I0206 19:09:44.505712 32380 hierarchical_allocator_process.hpp:735] Performed
> allocation for 1 slaves in 353338ns
> I0206 19:09:44.517038 32382 master.cpp:3728] Sending 1 offers to framework
> 20150206-190944-16842879-36452-32362-0000 (default) at
> scheduler-167ce2f8-8268-41f7-9c72-a4e29dc3316c@127.0.1.1:36452
> I0206 19:09:44.517523 32382 sched.cpp:440] Framework registered with
> 20150206-190944-16842879-36452-32362-0000
> I0206 19:09:44.517575 32382 sched.cpp:454] Scheduler::registered took 26978ns
> I0206 19:09:44.517899 32382 sched.cpp:603] Scheduler::resourceOffers took
> 48926ns
> I0206 19:09:45.246789 32381 hierarchical_allocator_process.hpp:828] No
> resources available to allocate!
> I0206 19:09:45.246841 32381 hierarchical_allocator_process.hpp:735] Performed
> allocation for 1 slaves in 239355ns
> I0206 19:09:46.257019 32383 hierarchical_allocator_process.hpp:828] No
> resources available to allocate!
> I0206 19:09:46.257325 32383 hierarchical_allocator_process.hpp:735] Performed
> allocation for 1 slaves in 642985ns
> I0206 19:09:47.259109 32382 hierarchical_allocator_process.hpp:828] No
> resources available to allocate!
> I0206 19:09:47.259160 32382 hierarchical_allocator_process.hpp:735] Performed
> allocation for 1 slaves in 247172ns
> I0206 19:09:48.267207 32378 hierarchical_allocator_process.hpp:828] No
> resources available to allocate!
> I0206 19:09:48.267590 32378 hierarchical_allocator_process.hpp:735] Performed
> allocation for 1 slaves in 737879ns
> I0206 19:09:49.276871 32379 hierarchical_allocator_process.hpp:828] No
> resources available to allocate!
> I0206 19:09:49.276924 32379 hierarchical_allocator_process.hpp:735] Performed
> allocation for 1 slaves in 243974ns
> I0206 19:09:50.287142 32382 hierarchical_allocator_process.hpp:828] No
> resources available to allocate!
> I0206 19:09:50.287504 32382 hierarchical_allocator_process.hpp:735] Performed
> allocation for 1 slaves in 784304ns
> I0206 19:09:51.296839 32379 hierarchical_allocator_process.hpp:828] No
> resources available to allocate!
> I0206 19:09:51.296893 32379 hierarchical_allocator_process.hpp:735] Performed
> allocation for 1 slaves in 244814ns
> I0206 19:09:52.297719 32378 hierarchical_allocator_process.hpp:828] No
> resources available to allocate!
> I0206 19:09:52.299626 32378 hierarchical_allocator_process.hpp:735] Performed
> allocation for 1 slaves in 2.277105ms
> I0206 19:09:53.306870 32384 hierarchical_allocator_process.hpp:828] No
> resources available to allocate!
> I0206 19:09:53.306924 32384 hierarchical_allocator_process.hpp:735] Performed
> allocation for 1 slaves in 262416ns
> I0206 19:09:54.317059 32382 hierarchical_allocator_process.hpp:828] No
> resources available to allocate!
> I0206 19:09:54.320051 32382 hierarchical_allocator_process.hpp:735] Performed
> allocation for 1 slaves in 3.270301ms
> I0206 19:09:55.326977 32379 hierarchical_allocator_process.hpp:828] No
> resources available to allocate!
> I0206 19:09:55.330344 32379 hierarchical_allocator_process.hpp:735] Performed
> allocation for 1 slaves in 3.569401ms
> I0206 19:09:56.339260 32381 hierarchical_allocator_process.hpp:828] No
> resources available to allocate!
> I0206 19:09:56.343905 32381 hierarchical_allocator_process.hpp:735] Performed
> allocation for 1 slaves in 5.144928ms
> I0206 19:09:57.346943 32377 hierarchical_allocator_process.hpp:828] No
> resources available to allocate!
> I0206 19:09:57.347012 32377 hierarchical_allocator_process.hpp:735] Performed
> allocation for 1 slaves in 326655ns
> I0206 19:09:58.348335 32380 hierarchical_allocator_process.hpp:828] No
> resources available to allocate!
> I0206 19:09:58.351338 32380 hierarchical_allocator_process.hpp:735] Performed
> allocation for 1 slaves in 3.622285ms
> I0206 19:09:59.356886 32383 hierarchical_allocator_process.hpp:828] No
> resources available to allocate!
> I0206 19:09:59.356941 32383 hierarchical_allocator_process.hpp:735] Performed
> allocation for 1 slaves in 271092ns
> I0206 19:09:59.477521 32381 slave.cpp:2595] Received ping from
> slave-observer(14)@127.0.1.1:36452
> tests/master_slave_reconciliation_tests.cpp:283: Failure
> Failed to wait 15secs for reregisterSlaveMessage
> I0206 19:09:59.510076 32377 master.cpp:872] Framework
> 20150206-190944-16842879-36452-32362-0000 (default) at
> scheduler-167ce2f8-8268-41f7-9c72-a4e29dc3316c@127.0.1.1:36452 disconnected
> I0206 19:09:59.510154 32377 master.cpp:1937] Disconnecting framework
> 20150206-190944-16842879-36452-32362-0000 (default) at
> scheduler-167ce2f8-8268-41f7-9c72-a4e29dc3316c@127.0.1.1:36452
> I0206 19:09:59.510216 32377 master.cpp:1953] Deactivating framework
> 20150206-190944-16842879-36452-32362-0000 (default) at
> scheduler-167ce2f8-8268-41f7-9c72-a4e29dc3316c@127.0.1.1:36452
> I0206 19:09:59.511065 32377 master.cpp:894] Giving framework
> 20150206-190944-16842879-36452-32362-0000 (default) at
> scheduler-167ce2f8-8268-41f7-9c72-a4e29dc3316c@127.0.1.1:36452 0ns to failover
> I0206 19:09:59.512804 32383 hierarchical_allocator_process.hpp:397]
> Deactivated framework 20150206-190944-16842879-36452-32362-0000
> I0206 19:09:59.512990 32383 hierarchical_allocator_process.hpp:642] Recovered
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total
> allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on
> slave 20150206-190944-16842879-36452-32362-S0 from framework
> 20150206-190944-16842879-36452-32362-0000
> I0206 19:09:59.513653 32382 slave.cpp:609] Re-detecting master
> I0206 19:09:59.513687 32382 slave.cpp:656] Detecting new master
> *** Aborted at 1423278599 (unix time) try "date -d @1423278599" if you are
> using GNU date ***
> I0206 19:09:59.514680 32380 status_update_manager.cpp:170] Pausing sending
> status updates
> I0206 19:09:59.516027 32379 master.cpp:781] Master terminating
> PC: @ 0x2b2b91358b79 mesos::slave::Slave::detected()
> *** SIGSEGV (@0x10) received by PID 32362 (TID 0x2b2b98dad700) from PID 16;
> stack trace: ***
> @ 0x2b2b9b6ff3b4 os::Linux::chained_handler()
> @ 0x2b2b9b70459a JVM_handle_linux_signal
> @ 0x2b2b8f0a98f0 (unknown)
> @ 0x2b2b91358b79 mesos::slave::Slave::detected()
> @ 0x2b2b913d31b4 std::tr1::_Mem_fn<>::operator()()
> @ 0x2b2b913cd54f
> _ZNSt3tr15_BindIFNS_7_Mem_fnIMN5mesos5slave5SlaveEFvRKN7process6FutureI6OptionINS2_10MasterInfoEEEEEEENS_12_PlaceholderILi1EEESA_EE6__callIIRPS4_EILi0ELi1EEEENS_9result_ofIFSF_NSN_IFNS_3_MuISH_Lb0ELb1EEESH_NS_5tupleIIDpT_EEEEE4typeENSN_IFNSO_ISA_Lb0ELb0EEESA_ST_EE4typeEEE4typeERKST_NS_12_Index_tupleIIXspT0_EEEE
> @ 0x2b2b913c3216 std::tr1::_Bind<>::operator()<>()
> @ 0x2b2b913b6a7e std::tr1::_Function_handler<>::_M_invoke()
> @ 0x7f6b9a std::tr1::function<>::operator()()
> @ 0x7e765c process::internal::vdispatcher<>()
> @ 0x80e823
> _ZNSt3tr15_BindIFPFvPN7process11ProcessBaseENS_10shared_ptrINS_8functionIFvPN5mesos5slave5SlaveEEEEEEENS_12_PlaceholderILi1EEESC_EE6__callIIRS3_EILi0ELi1EEEENS_9result_ofIFSE_NSL_IFNS_3_MuISG_Lb0ELb1EEESG_NS_5tupleIIDpT_EEEEE4typeENSL_IFNSM_ISC_Lb0ELb0EEESC_SR_EE4typeEEE4typeERKSR_NS_12_Index_tupleIIXspT0_EEEE
> @ 0x803b6c std::tr1::_Bind<>::operator()<>()
> @ 0x7f6c86 std::tr1::_Function_handler<>::_M_invoke()
> @ 0x2b2b91a25714 std::tr1::function<>::operator()()
> @ 0x2b2b91a0ae4f process::ProcessBase::visit()
> @ 0x2b2b91a0f3a0 process::DispatchEvent::visit()
> @ 0x8a56f2 process::ProcessBase::serve()
> @ 0x2b2b91a06fc2 process::ProcessManager::resume()
> @ 0x2b2b919fabfc process::schedule()
> @ 0x2b2b8f0a09ca start_thread
> @ 0x2b2b94ab745d (unknown)
> make[3]: *** [check-local] Segmentation fault
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
