[
https://issues.apache.org/jira/browse/MESOS-5548?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Benjamin Bannier updated MESOS-5548:
------------------------------------
Labels: flaky (was: )
> FaultToleranceTest.UpdateFrameworkInfoOnSchedulerFailover is flaky
> ------------------------------------------------------------------
>
> Key: MESOS-5548
> URL: https://issues.apache.org/jira/browse/MESOS-5548
> Project: Mesos
> Issue Type: Bug
> Components: flaky, test
> Environment:
> https://builds.apache.org/job/Mesos/2223/BUILDTOOL=autotools,COMPILER=gcc,CONFIGURATION=--verbose%20--enable-libevent%20--enable-ssl,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1,OS=centos:7,label_exp=(docker%7C%7CHadoop)&&(!ubuntu-us1)/consoleFull
> Reporter: Vinod Kone
> Labels: flaky
>
> Observed this on ASF CI, where this test runs forever
> {code}
> [ RUN ] FaultToleranceTest.UpdateFrameworkInfoOnSchedulerFailover
> I0606 17:09:02.953631 29338 cluster.cpp:155] Creating default 'local'
> authorizer
> I0606 17:09:02.957620 29338 leveldb.cpp:174] Opened db in 3.247876ms
> I0606 17:09:02.958684 29338 leveldb.cpp:181] Compacted db in 1.023058ms
> I0606 17:09:02.958762 29338 leveldb.cpp:196] Created db iterator in 17962ns
> I0606 17:09:02.958794 29338 leveldb.cpp:202] Seeked to beginning of db in
> 2453ns
> I0606 17:09:02.958820 29338 leveldb.cpp:271] Iterated through 0 keys in the
> db in 465ns
> I0606 17:09:02.958880 29338 replica.cpp:779] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0606 17:09:02.959601 29362 recover.cpp:448] Starting replica recovery
> I0606 17:09:02.959996 29362 recover.cpp:474] Replica is in EMPTY status
> I0606 17:09:02.961241 29357 replica.cpp:673] Replica in EMPTY status received
> a broadcasted recover request from (1793)@172.17.0.2:39784
> I0606 17:09:02.961608 29369 recover.cpp:194] Received a recover response from
> a replica in EMPTY status
> I0606 17:09:02.962347 29357 recover.cpp:565] Updating replica status to
> STARTING
> I0606 17:09:02.963209 29371 leveldb.cpp:304] Persisting metadata (8 bytes) to
> leveldb took 706012ns
> I0606 17:09:02.963240 29371 replica.cpp:320] Persisted replica status to
> STARTING
> I0606 17:09:02.963435 29370 recover.cpp:474] Replica is in STARTING status
> I0606 17:09:02.963881 29360 master.cpp:382] Master
> 7d25f96c-ab51-4074-b613-df1b15675b81 (1ead8e6f9ec5) started on
> 172.17.0.2:39784
> I0606 17:09:02.963907 29360 master.cpp:384] Flags at startup: --acls=""
> --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins"
> --allocation_interval="1secs" --allocator="HierarchicalDRF"
> --authenticate_agents="true" --authenticate_frameworks="true"
> --authenticate_http="true" --authenticate_http_frameworks="true"
> --authenticators="crammd5" --authorizers="local"
> --credentials="/tmp/TzbJnN/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_agent_ping_timeouts="5" --max_completed_frameworks="50"
> --max_completed_tasks_per_framework="1000" --quiet="false"
> --recovery_agent_removal_limit="100%" --registry="replicated_log"
> --registry_fetch_timeout="1mins" --registry_store_timeout="100secs"
> --registry_strict="true" --root_submissions="true" --user_sorter="drf"
> --version="false" --webui_dir="/mesos/mesos-1.0.0/_inst/share/mesos/webui"
> --work_dir="/tmp/TzbJnN/master" --zk_session_timeout="10secs"
> I0606 17:09:02.964334 29360 master.cpp:433] Master only allowing
> authenticated frameworks to register
> I0606 17:09:02.964355 29360 master.cpp:439] Master only allowing
> authenticated agents to register
> I0606 17:09:02.964366 29360 master.cpp:445] Master only allowing
> authenticated HTTP frameworks to register
> I0606 17:09:02.964376 29360 credentials.hpp:37] Loading credentials for
> authentication from '/tmp/TzbJnN/credentials'
> I0606 17:09:02.964445 29372 replica.cpp:673] Replica in STARTING status
> received a broadcasted recover request from (1794)@172.17.0.2:39784
> I0606 17:09:02.964728 29360 master.cpp:489] Using default 'crammd5'
> authenticator
> I0606 17:09:02.964891 29360 master.cpp:560] Using default 'basic' HTTP
> authenticator
> I0606 17:09:02.964926 29361 recover.cpp:194] Received a recover response from
> a replica in STARTING status
> I0606 17:09:02.965065 29360 master.cpp:640] Using default 'basic' HTTP
> framework authenticator
> I0606 17:09:02.965330 29360 master.cpp:687] Authorization enabled
> I0606 17:09:02.965418 29362 recover.cpp:565] Updating replica status to VOTING
> I0606 17:09:02.965591 29359 hierarchical.cpp:142] Initialized hierarchical
> allocator process
> I0606 17:09:02.965672 29367 whitelist_watcher.cpp:77] No whitelist given
> I0606 17:09:02.966047 29365 leveldb.cpp:304] Persisting metadata (8 bytes) to
> leveldb took 366626ns
> I0606 17:09:02.966080 29365 replica.cpp:320] Persisted replica status to
> VOTING
> I0606 17:09:02.966222 29368 recover.cpp:579] Successfully joined the Paxos
> group
> I0606 17:09:02.966526 29368 recover.cpp:463] Recover process terminated
> I0606 17:09:02.968436 29366 master.cpp:1951] The newly elected leader is
> [email protected]:39784 with id 7d25f96c-ab51-4074-b613-df1b15675b81
> I0606 17:09:02.968492 29366 master.cpp:1964] Elected as the leading master!
> I0606 17:09:02.968526 29366 master.cpp:1651] Recovering from registrar
> I0606 17:09:02.968731 29371 registrar.cpp:332] Recovering registrar
> I0606 17:09:02.969341 29359 log.cpp:524] Attempting to start the writer
> I0606 17:09:02.970733 29368 replica.cpp:493] Replica received implicit
> promise request from (1797)@172.17.0.2:39784 with proposal 1
> I0606 17:09:02.971122 29368 leveldb.cpp:304] Persisting metadata (8 bytes) to
> leveldb took 346218ns
> I0606 17:09:02.971153 29368 replica.cpp:342] Persisted promised to 1
> I0606 17:09:02.972035 29363 coordinator.cpp:238] Coordinator attempting to
> fill missing positions
> I0606 17:09:02.973377 29368 replica.cpp:388] Replica received explicit
> promise request from (1798)@172.17.0.2:39784 for position 0 with proposal 2
> I0606 17:09:02.973850 29368 leveldb.cpp:341] Persisting action (8 bytes) to
> leveldb took 419380ns
> I0606 17:09:02.973884 29368 replica.cpp:712] Persisted action at 0
> I0606 17:09:02.975050 29364 replica.cpp:537] Replica received write request
> for position 0 from (1799)@172.17.0.2:39784
> I0606 17:09:02.975131 29364 leveldb.cpp:436] Reading position from leveldb
> took 36667ns
> I0606 17:09:02.975550 29364 leveldb.cpp:341] Persisting action (14 bytes) to
> leveldb took 366348ns
> I0606 17:09:02.975582 29364 replica.cpp:712] Persisted action at 0
> I0606 17:09:02.976235 29360 replica.cpp:691] Replica received learned notice
> for position 0 from @0.0.0.0:0
> I0606 17:09:02.976652 29360 leveldb.cpp:341] Persisting action (16 bytes) to
> leveldb took 376620ns
> I0606 17:09:02.976683 29360 replica.cpp:712] Persisted action at 0
> I0606 17:09:02.976724 29360 replica.cpp:697] Replica learned NOP action at
> position 0
> I0606 17:09:02.977457 29362 log.cpp:540] Writer started with ending position 0
> I0606 17:09:02.978617 29364 leveldb.cpp:436] Reading position from leveldb
> took 35230ns
> I0606 17:09:02.979652 29367 registrar.cpp:365] Successfully fetched the
> registry (0B) in 10.86208ms
> I0606 17:09:02.979790 29367 registrar.cpp:464] Applied 1 operations in
> 22882ns; attempting to update the 'registry'
> I0606 17:09:02.980599 29363 log.cpp:548] Attempting to append 168 bytes to
> the log
> I0606 17:09:02.980787 29366 coordinator.cpp:348] Coordinator attempting to
> write APPEND action at position 1
> I0606 17:09:02.981648 29363 replica.cpp:537] Replica received write request
> for position 1 from (1800)@172.17.0.2:39784
> I0606 17:09:02.982123 29363 leveldb.cpp:341] Persisting action (187 bytes) to
> leveldb took 429124ns
> I0606 17:09:02.982154 29363 replica.cpp:712] Persisted action at 1
> I0606 17:09:02.983042 29366 replica.cpp:691] Replica received learned notice
> for position 1 from @0.0.0.0:0
> I0606 17:09:02.983487 29366 leveldb.cpp:341] Persisting action (189 bytes) to
> leveldb took 407945ns
> I0606 17:09:02.983518 29366 replica.cpp:712] Persisted action at 1
> I0606 17:09:02.983541 29366 replica.cpp:697] Replica learned APPEND action at
> position 1
> I0606 17:09:02.984771 29368 registrar.cpp:509] Successfully updated the
> 'registry' in 4.911872ms
> I0606 17:09:02.984946 29368 registrar.cpp:395] Successfully recovered
> registrar
> I0606 17:09:02.985101 29362 log.cpp:567] Attempting to truncate the log to 1
> I0606 17:09:02.985332 29366 coordinator.cpp:348] Coordinator attempting to
> write TRUNCATE action at position 2
> I0606 17:09:02.985574 29362 hierarchical.cpp:169] Skipping recovery of
> hierarchical allocator: nothing to recover
> I0606 17:09:02.985570 29357 master.cpp:1759] Recovered 0 agents from the
> Registry (129B) ; allowing 10mins for agents to re-register
> I0606 17:09:02.986429 29367 replica.cpp:537] Replica received write request
> for position 2 from (1801)@172.17.0.2:39784
> I0606 17:09:02.986819 29367 leveldb.cpp:341] Persisting action (16 bytes) to
> leveldb took 345811ns
> I0606 17:09:02.986852 29367 replica.cpp:712] Persisted action at 2
> I0606 17:09:02.987632 29369 replica.cpp:691] Replica received learned notice
> for position 2 from @0.0.0.0:0
> I0606 17:09:02.988188 29369 leveldb.cpp:341] Persisting action (18 bytes) to
> leveldb took 512643ns
> I0606 17:09:02.988260 29369 leveldb.cpp:399] Deleting ~1 keys from leveldb
> took 38736ns
> I0606 17:09:02.988298 29369 replica.cpp:712] Persisted action at 2
> I0606 17:09:02.988327 29369 replica.cpp:697] Replica learned TRUNCATE action
> at position 2
> I0606 17:09:03.000023 29338 containerizer.cpp:198] Using isolation:
> posix/cpu,posix/mem,filesystem/posix,network/cni
> W0606 17:09:03.000926 29338 backend.cpp:66] Failed to create 'bind' backend:
> BindBackend requires root privileges
> I0606 17:09:03.002598 29338 cluster.cpp:432] Creating default 'local'
> authorizer
> I0606 17:09:03.004048 29360 slave.cpp:203] Agent started on
> 41)@172.17.0.2:39784
> I0606 17:09:03.004072 29360 slave.cpp:204] Flags at startup: --acls=""
> --appc_simple_discovery_uri_prefix="http://";
> --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="true"
> --authenticatee="crammd5" --authorizer="local"
> --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/FaultToleranceTest_UpdateFrameworkInfoOnSchedulerFailover_fcOHgu/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"
> --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume"
> --enforce_container_disk_quota="false"
> --executor_registration_timeout="1mins"
> --executor_shutdown_grace_period="5secs"
> --fetcher_cache_dir="/tmp/FaultToleranceTest_UpdateFrameworkInfoOnSchedulerFailover_fcOHgu/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/FaultToleranceTest_UpdateFrameworkInfoOnSchedulerFailover_fcOHgu/http_credentials"
> --image_provisioner_backend="copy" --initialize_driver_logging="true"
> --isolation="posix/cpu,posix/mem"
> --launcher_dir="/mesos/mesos-1.0.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/FaultToleranceTest_UpdateFrameworkInfoOnSchedulerFailover_fcOHgu"
> I0606 17:09:03.004683 29360 credentials.hpp:86] Loading credential for
> authentication from
> '/tmp/FaultToleranceTest_UpdateFrameworkInfoOnSchedulerFailover_fcOHgu/credential'
> I0606 17:09:03.004874 29360 slave.cpp:341] Agent using credential for:
> test-principal
> I0606 17:09:03.004922 29360 credentials.hpp:37] Loading credentials for
> authentication from
> '/tmp/FaultToleranceTest_UpdateFrameworkInfoOnSchedulerFailover_fcOHgu/http_credentials'
> I0606 17:09:03.005223 29360 slave.cpp:393] Using default 'basic' HTTP
> authenticator
> I0606 17:09:03.005403 29338 sched.cpp:224] Version: 1.0.0
> I0606 17:09:03.005568 29360 resources.cpp:572] Parsing resources as JSON
> failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
> Trying semicolon-delimited string format instead
> I0606 17:09:03.005972 29360 slave.cpp:592] Agent resources: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0606 17:09:03.006027 29360 slave.cpp:600] Agent attributes: [ ]
> I0606 17:09:03.006038 29360 slave.cpp:605] Agent hostname: 1ead8e6f9ec5
> I0606 17:09:03.006053 29369 sched.cpp:328] New master detected at
> [email protected]:39784
> I0606 17:09:03.006173 29369 sched.cpp:384] Authenticating with master
> [email protected]:39784
> I0606 17:09:03.006197 29369 sched.cpp:391] Using default CRAM-MD5
> authenticatee
> I0606 17:09:03.006466 29359 authenticatee.cpp:121] Creating new client SASL
> connection
> I0606 17:09:03.006822 29370 master.cpp:5925] Authenticating
> [email protected]:39784
> I0606 17:09:03.006969 29364 authenticator.cpp:414] Starting authentication
> session for crammd5_authenticatee(125)@172.17.0.2:39784
> I0606 17:09:03.007194 29369 state.cpp:57] Recovering state from
> '/tmp/FaultToleranceTest_UpdateFrameworkInfoOnSchedulerFailover_fcOHgu/meta'
> I0606 17:09:03.007253 29359 authenticator.cpp:98] Creating new server SASL
> connection
> I0606 17:09:03.007606 29364 authenticatee.cpp:213] Received SASL
> authentication mechanisms: CRAM-MD5
> I0606 17:09:03.007643 29366 status_update_manager.cpp:200] Recovering status
> update manager
> I0606 17:09:03.007649 29364 authenticatee.cpp:239] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0606 17:09:03.007835 29363 authenticator.cpp:204] Received SASL
> authentication start
> I0606 17:09:03.007853 29360 containerizer.cpp:486] Recovering containerizer
> I0606 17:09:03.007918 29363 authenticator.cpp:326] Authentication requires
> more steps
> I0606 17:09:03.008039 29367 authenticatee.cpp:259] Received SASL
> authentication step
> I0606 17:09:03.008167 29363 authenticator.cpp:232] Received SASL
> authentication step
> I0606 17:09:03.008211 29363 auxprop.cpp:107] Request to lookup properties for
> user: 'test-principal' realm: '1ead8e6f9ec5' server FQDN: '1ead8e6f9ec5'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0606 17:09:03.008232 29363 auxprop.cpp:179] Looking up auxiliary property
> '*userPassword'
> I0606 17:09:03.008280 29363 auxprop.cpp:179] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0606 17:09:03.008319 29363 auxprop.cpp:107] Request to lookup properties for
> user: 'test-principal' realm: '1ead8e6f9ec5' server FQDN: '1ead8e6f9ec5'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0606 17:09:03.008342 29363 auxprop.cpp:129] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0606 17:09:03.008358 29363 auxprop.cpp:129] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0606 17:09:03.008388 29363 authenticator.cpp:318] Authentication success
> I0606 17:09:03.008494 29370 authenticatee.cpp:299] Authentication success
> I0606 17:09:03.008725 29360 master.cpp:5955] Successfully authenticated
> principal 'test-principal' at
> [email protected]:39784
> I0606 17:09:03.008774 29361 authenticator.cpp:432] Authentication session
> cleanup for crammd5_authenticatee(125)@172.17.0.2:39784
> I0606 17:09:03.009054 29368 sched.cpp:474] Successfully authenticated with
> master [email protected]:39784
> I0606 17:09:03.009078 29368 sched.cpp:785] Sending SUBSCRIBE call to
> [email protected]:39784
> I0606 17:09:03.009256 29368 sched.cpp:818] Will retry registration in
> 905.999953ms if necessary
> I0606 17:09:03.009430 29371 master.cpp:2521] Received SUBSCRIBE call for
> framework 'Framework 1' at
> [email protected]:39784
> I0606 17:09:03.009510 29371 master.cpp:1990] Authorizing framework principal
> 'test-principal' to receive offers for role '*'
> I0606 17:09:03.009595 29362 provisioner.cpp:253] Provisioner recovery complete
> I0606 17:09:03.009912 29372 slave.cpp:4827] Finished recovery
> I0606 17:09:03.010077 29370 master.cpp:2597] Subscribing framework Framework
> 1 with checkpointing disabled and capabilities [ ]
> I0606 17:09:03.010352 29372 slave.cpp:4999] Querying resource estimator for
> oversubscribable resources
> I0606 17:09:03.010742 29369 hierarchical.cpp:264] Added framework
> 7d25f96c-ab51-4074-b613-df1b15675b81-0000
> I0606 17:09:03.010783 29364 sched.cpp:712] Framework registered with
> 7d25f96c-ab51-4074-b613-df1b15675b81-0000
> I0606 17:09:03.010810 29369 hierarchical.cpp:1488] No allocations performed
> I0606 17:09:03.010843 29369 hierarchical.cpp:1583] No inverse offers to send
> out!
> I0606 17:09:03.010877 29364 sched.cpp:726] Scheduler::registered took 65429ns
> I0606 17:09:03.010897 29369 hierarchical.cpp:1139] Performed allocation for 0
> agents in 128801ns
> I0606 17:09:03.010937 29372 slave.cpp:962] New master detected at
> [email protected]:39784
> I0606 17:09:03.010946 29364 status_update_manager.cpp:174] Pausing sending
> status updates
> I0606 17:09:03.010967 29372 slave.cpp:1024] Authenticating with master
> [email protected]:39784
> I0606 17:09:03.011085 29372 slave.cpp:1033] Using default CRAM-MD5
> authenticatee
> I0606 17:09:03.011230 29372 slave.cpp:997] Detecting new master
> I0606 17:09:03.011281 29358 authenticatee.cpp:121] Creating new client SASL
> connection
> I0606 17:09:03.011375 29372 slave.cpp:5013] Received oversubscribable
> resources from the resource estimator
> I0606 17:09:03.011526 29357 master.cpp:5925] Authenticating
> slave(41)@172.17.0.2:39784
> I0606 17:09:03.011629 29371 authenticator.cpp:414] Starting authentication
> session for crammd5_authenticatee(126)@172.17.0.2:39784
> I0606 17:09:03.011870 29364 authenticator.cpp:98] Creating new server SASL
> connection
> I0606 17:09:03.012056 29369 authenticatee.cpp:213] Received SASL
> authentication mechanisms: CRAM-MD5
> I0606 17:09:03.012080 29369 authenticatee.cpp:239] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0606 17:09:03.012192 29368 authenticator.cpp:204] Received SASL
> authentication start
> I0606 17:09:03.012259 29368 authenticator.cpp:326] Authentication requires
> more steps
> I0606 17:09:03.012300 29338 sched.cpp:224] Version: 1.0.0
> I0606 17:09:03.012362 29362 authenticatee.cpp:259] Received SASL
> authentication step
> I0606 17:09:03.012496 29363 authenticator.cpp:232] Received SASL
> authentication step
> I0606 17:09:03.012531 29363 auxprop.cpp:107] Request to lookup properties for
> user: 'test-principal' realm: '1ead8e6f9ec5' server FQDN: '1ead8e6f9ec5'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0606 17:09:03.012543 29363 auxprop.cpp:179] Looking up auxiliary property
> '*userPassword'
> I0606 17:09:03.012576 29363 auxprop.cpp:179] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0606 17:09:03.012614 29363 auxprop.cpp:107] Request to lookup properties for
> user: 'test-principal' realm: '1ead8e6f9ec5' server FQDN: '1ead8e6f9ec5'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0606 17:09:03.012626 29363 auxprop.cpp:129] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0606 17:09:03.012632 29363 auxprop.cpp:129] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0606 17:09:03.012645 29363 authenticator.cpp:318] Authentication success
> I0606 17:09:03.012899 29361 authenticator.cpp:432] Authentication session
> cleanup for crammd5_authenticatee(126)@172.17.0.2:39784
> I0606 17:09:03.012929 29360 master.cpp:5955] Successfully authenticated
> principal 'test-principal' at slave(41)@172.17.0.2:39784
> I0606 17:09:03.013170 29368 authenticatee.cpp:299] Authentication success
> I0606 17:09:03.013368 29368 sched.cpp:328] New master detected at
> [email protected]:39784
> I0606 17:09:03.013453 29368 sched.cpp:384] Authenticating with master
> [email protected]:39784
> I0606 17:09:03.013473 29368 sched.cpp:391] Using default CRAM-MD5
> authenticatee
> I0606 17:09:03.013674 29358 authenticatee.cpp:121] Creating new client SASL
> connection
> I0606 17:09:03.013984 29364 master.cpp:5925] Authenticating
> [email protected]:39784
> I0606 17:09:03.014000 29357 slave.cpp:1098] Successfully authenticated with
> master [email protected]:39784
> I0606 17:09:03.014120 29359 authenticator.cpp:414] Starting authentication
> session for crammd5_authenticatee(127)@172.17.0.2:39784
> I0606 17:09:03.014191 29357 slave.cpp:1501] Will retry registration in
> 7.250151ms if necessary
> I0606 17:09:03.014392 29367 authenticator.cpp:98] Creating new server SASL
> connection
> I0606 17:09:03.014456 29366 master.cpp:4635] Registering agent at
> slave(41)@172.17.0.2:39784 (1ead8e6f9ec5) with id
> 7d25f96c-ab51-4074-b613-df1b15675b81-S0
> I0606 17:09:03.014631 29372 authenticatee.cpp:213] Received SASL
> authentication mechanisms: CRAM-MD5
> I0606 17:09:03.014669 29372 authenticatee.cpp:239] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0606 17:09:03.014936 29371 authenticator.cpp:204] Received SASL
> authentication start
> I0606 17:09:03.015007 29371 authenticator.cpp:326] Authentication requires
> more steps
> I0606 17:09:03.015121 29369 registrar.cpp:464] Applied 1 operations in
> 80047ns; attempting to update the 'registry'
> I0606 17:09:03.015172 29372 authenticatee.cpp:259] Received SASL
> authentication step
> I0606 17:09:03.015329 29372 authenticator.cpp:232] Received SASL
> authentication step
> I0606 17:09:03.015367 29372 auxprop.cpp:107] Request to lookup properties for
> user: 'test-principal' realm: '1ead8e6f9ec5' server FQDN: '1ead8e6f9ec5'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0606 17:09:03.015379 29372 auxprop.cpp:179] Looking up auxiliary property
> '*userPassword'
> I0606 17:09:03.015405 29372 auxprop.cpp:179] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0606 17:09:03.015427 29372 auxprop.cpp:107] Request to lookup properties for
> user: 'test-principal' realm: '1ead8e6f9ec5' server FQDN: '1ead8e6f9ec5'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0606 17:09:03.015439 29372 auxprop.cpp:129] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0606 17:09:03.015446 29372 auxprop.cpp:129] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0606 17:09:03.015463 29372 authenticator.cpp:318] Authentication success
> I0606 17:09:03.015569 29370 authenticatee.cpp:299] Authentication success
> I0606 17:09:03.015602 29366 master.cpp:5955] Successfully authenticated
> principal 'test-principal' at
> [email protected]:39784
> I0606 17:09:03.015635 29372 authenticator.cpp:432] Authentication session
> cleanup for crammd5_authenticatee(127)@172.17.0.2:39784
> I0606 17:09:03.016139 29370 sched.cpp:474] Successfully authenticated with
> master [email protected]:39784
> I0606 17:09:03.016167 29370 sched.cpp:785] Sending SUBSCRIBE call to
> [email protected]:39784
> I0606 17:09:03.016304 29364 log.cpp:548] Attempting to append 337 bytes to
> the log
> I0606 17:09:03.016314 29370 sched.cpp:818] Will retry registration in
> 1.18637508secs if necessary
> I0606 17:09:03.016474 29370 coordinator.cpp:348] Coordinator attempting to
> write APPEND action at position 3
> I0606 17:09:03.016614 29359 master.cpp:2521] Received SUBSCRIBE call for
> framework 'Framework 2' at
> [email protected]:39784
> I0606 17:09:03.016782 29359 master.cpp:1990] Authorizing framework principal
> 'test-principal' to receive offers for role '*'
> I0606 17:09:03.017385 29358 master.cpp:2597] Subscribing framework Framework
> 2 with checkpointing disabled and capabilities [ REVOCABLE_RESOURCES ]
> I0606 17:09:03.017515 29358 master.cpp:2661] Updating info for framework
> 7d25f96c-ab51-4074-b613-df1b15675b81-0000
> I0606 17:09:03.017648 29361 replica.cpp:537] Replica received write request
> for position 3 from (1817)@172.17.0.2:39784
> I0606 17:09:03.017693 29358 master.cpp:2674] Framework
> 7d25f96c-ab51-4074-b613-df1b15675b81-0000 (Framework 2) at
> [email protected]:39784 failed over
> I0606 17:09:03.017875 29365 sched.cpp:1136] Got error 'Framework failed over'
> I0606 17:09:03.017997 29365 sched.cpp:1983] Asked to abort the driver
> I0606 17:09:03.018044 29357 sched.cpp:712] Framework registered with
> 7d25f96c-ab51-4074-b613-df1b15675b81-0000
> I0606 17:09:03.018101 29365 sched.cpp:1147] Scheduler::error took 49642ns
> I0606 17:09:03.018149 29357 sched.cpp:726] Scheduler::registered took 77613ns
> I0606 17:09:03.018177 29365 sched.cpp:1182] Aborting framework
> '7d25f96c-ab51-4074-b613-df1b15675b81-0000'
> I0606 17:09:03.017907 29361 leveldb.cpp:341] Persisting action (356 bytes) to
> leveldb took 212588ns
> I0606 17:09:03.018410 29361 replica.cpp:712] Persisted action at 3
> W0606 17:09:03.018651 29366 master.cpp:2808] Ignoring deactivate framework
> message for framework 7d25f96c-ab51-4074-b613-df1b15675b81-0000 (Framework 2)
> at [email protected]:39784 because it
> is not expected from
> [email protected]:39784
> I0606 17:09:03.019297 29366 replica.cpp:691] Replica received learned notice
> for position 3 from @0.0.0.0:0
> I0606 17:09:03.019763 29366 leveldb.cpp:341] Persisting action (358 bytes) to
> leveldb took 428994ns
> I0606 17:09:03.019795 29366 replica.cpp:712] Persisted action at 3
> I0606 17:09:03.019819 29366 replica.cpp:697] Replica learned APPEND action at
> position 3
> I0606 17:09:03.020942 29364 process.cpp:3254] Handling HTTP event for process
> 'master' with path: '/master/state'
> I0606 17:09:03.021627 29361 registrar.cpp:509] Successfully updated the
> 'registry' in 6.425856ms
> I0606 17:09:03.021914 29371 log.cpp:567] Attempting to truncate the log to 3
> I0606 17:09:03.022142 29370 coordinator.cpp:348] Coordinator attempting to
> write TRUNCATE action at position 4
> I0606 17:09:03.022351 29362 slave.cpp:1501] Will retry registration in
> 2.888229ms if necessary
> I0606 17:09:03.022819 29363 slave.cpp:3737] Received ping from
> slave-observer(40)@172.17.0.2:39784
> I0606 17:09:03.022935 29360 master.cpp:4703] Registered agent
> 7d25f96c-ab51-4074-b613-df1b15675b81-S0 at slave(41)@172.17.0.2:39784
> (1ead8e6f9ec5) with cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000]
> I0606 17:09:03.023005 29363 slave.cpp:1142] Registered with master
> [email protected]:39784; given agent ID
> 7d25f96c-ab51-4074-b613-df1b15675b81-S0
> I0606 17:09:03.023035 29363 fetcher.cpp:86] Clearing fetcher cache
> I0606 17:09:03.023097 29360 http.cpp:483] HTTP GET for /master/state from
> 172.17.0.2:47179
> I0606 17:09:03.023205 29366 status_update_manager.cpp:181] Resuming sending
> status updates
> I0606 17:09:03.023236 29365 hierarchical.cpp:473] Added agent
> 7d25f96c-ab51-4074-b613-df1b15675b81-S0 (1ead8e6f9ec5) with cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
> I0606 17:09:03.023524 29363 slave.cpp:1165] Checkpointing SlaveInfo to
> '/tmp/FaultToleranceTest_UpdateFrameworkInfoOnSchedulerFailover_fcOHgu/meta/slaves/7d25f96c-ab51-4074-b613-df1b15675b81-S0/slave.info'
> I0606 17:09:03.023816 29372 replica.cpp:537] Replica received write request
> for position 4 from (1820)@172.17.0.2:39784
> I0606 17:09:03.023905 29360 master.cpp:4605] Agent
> 7d25f96c-ab51-4074-b613-df1b15675b81-S0 at slave(41)@172.17.0.2:39784
> (1ead8e6f9ec5) already registered, resending acknowledgement
> I0606 17:09:03.024102 29363 slave.cpp:1202] Forwarding total oversubscribed
> resources
> W0606 17:09:03.024260 29363 slave.cpp:1188] Already registered with master
> [email protected]:39784
> I0606 17:09:03.024292 29363 slave.cpp:1202] Forwarding total oversubscribed
> resources
> I0606 17:09:03.024327 29372 leveldb.cpp:341] Persisting action (16 bytes) to
> leveldb took 456116ns
> I0606 17:09:03.024356 29372 replica.cpp:712] Persisted action at 4
> I0606 17:09:03.024351 29359 master.cpp:5048] Received update of agent
> 7d25f96c-ab51-4074-b613-df1b15675b81-S0 at slave(41)@172.17.0.2:39784
> (1ead8e6f9ec5) with total oversubscribed resources
> I0606 17:09:03.024433 29365 hierarchical.cpp:1583] No inverse offers to send
> out!
> I0606 17:09:03.024502 29365 hierarchical.cpp:1162] Performed allocation for
> agent 7d25f96c-ab51-4074-b613-df1b15675b81-S0 in 1.205716ms
> I0606 17:09:03.025060 29359 master.cpp:5048] Received update of agent
> 7d25f96c-ab51-4074-b613-df1b15675b81-S0 at slave(41)@172.17.0.2:39784
> (1ead8e6f9ec5) with total oversubscribed resources
> [libprotobuf FATAL
> ../3rdparty/protobuf-2.6.1/src/google/protobuf/repeated_field.h:886] CHECK
> failed: (index) < (size()):
> I0606 17:09:03.025326 29365 hierarchical.cpp:531] Agent
> 7d25f96c-ab51-4074-b613-df1b15675b81-S0 (1ead8e6f9ec5) updated with
> oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000])
> I0606 17:09:03.025398 29367 replica.cpp:691] Replica received learned notice
> for position 4 from @0.0.0.0:0
> I0606 17:09:03.025485 29365 hierarchical.cpp:1488] No allocations performed
> I0606 17:09:03.025543 29365 hierarchical.cpp:1583] No inverse offers to send
> out!
> I0606 17:09:03.025624 29365 hierarchical.cpp:1162] Performed allocation for
> agent 7d25f96c-ab51-4074-b613-df1b15675b81-S0 in 236277ns
> I0606 17:09:03.025830 29367 leveldb.cpp:341] Persisting action (18 bytes) to
> leveldb took 390640ns
> libprocess: (1821)@I0606 17:09:03.025889 29359 master.cpp:5754] Sending 1
> offers to framework 7d25f96c-ab51-4074-b613-df1b15675b81-0000 (Framework 2)
> at [email protected]:39784
> 172.17.0.2:39784 terminating due to CHECK failed: (index) < (size()):
> I0606 17:09:03.025944 29367 leveldb.cpp:399] Deleting ~2 keys from leveldb
> took 67826ns
> I0606 17:09:03.025980 29367 replica.cpp:712] Persisted action at 4
> I0606 17:09:03.026021 29367 replica.cpp:697] Replica learned TRUNCATE action
> at position 4
> I0606 17:09:03.026072 29365 hierarchical.cpp:531] Agent
> 7d25f96c-ab51-4074-b613-df1b15675b81-S0 (1ead8e6f9ec5) updated with
> oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000])
> I0606 17:09:03.026221 29365 hierarchical.cpp:1488] No allocations performed
> I0606 17:09:03.026264 29365 hierarchical.cpp:1583] No inverse offers to send
> out!
> I0606 17:09:03.026319 29365 hierarchical.cpp:1162] Performed allocation for
> agent 7d25f96c-ab51-4074-b613-df1b15675b81-S0 in 196386ns
> I0606 17:09:03.026330 29362 sched.cpp:882] Scheduler::resourceOffers took
> 29474ns
> I0606 17:09:03.966789 29370 hierarchical.cpp:1488] No allocations performed
> I0606 17:09:03.966842 29370 hierarchical.cpp:1583] No inverse offers to send
> out!
> I0606 17:09:03.966917 29370 hierarchical.cpp:1139] Performed allocation for 1
> agents in 306394ns
> I0606 17:09:04.930238 31721 exec.cpp:98] Committing suicide by killing the
> process group
> I0606 17:09:04.930488 31742 exec.cpp:98] Committing suicide by killing the
> process group
> I0606 17:09:04.932122 31715 exec.cpp:98] Committing suicide by killing the
> process group
> I0606 17:09:04.967631 29368 hierarchical.cpp:1488] No allocations performed
> I0606 17:09:04.967682 29368 hierarchical.cpp:1583] No inverse offers to send
> out!
> I0606 17:09:04.967756 29368 hierarchical.cpp:1139] Performed allocation for 1
> agents in 243827ns
> I0606 17:09:05.969039 29367 hierarchical.cpp:1488] No allocations performed
> I0606 17:09:05.969097 29367 hierarchical.cpp:1583] No inverse offers to send
> out!
> I0606 17:09:05.969184 29367 hierarchical.cpp:1139] Performed allocation for 1
> agents in 260260ns
> I0606 17:09:06.970069 29370 hierarchical.cpp:1488] No allocations performed
> I0606 17:09:06.970116 29370 hierarchical.cpp:1583] No inverse offers to send
> out!
> I0606 17:09:06.970175 29370 hierarchical.cpp:1139] Performed allocation for 1
> agents in 208444ns
> I0606 17:09:07.970765 29359 hierarchical.cpp:1488] No allocations performed
> I0606 17:09:07.970818 29359 hierarchical.cpp:1583] No inverse offers to send
> out!
> I0606 17:09:07.970890 29359 hierarchical.cpp:1139] Performed allocation for 1
> agents in 258423ns
> I0606 17:09:08.007097 29370 sched.cpp:486] Ignoring authentication timeout
> because the driver is not running!
> I0606 17:09:08.972277 29370 hierarchical.cpp:1488] No allocations performed
> I0606 17:09:08.972326 29370 hierarchical.cpp:1583] No inverse offers to send
> out!
> I0606 17:09:08.972383 29370 hierarchical.cpp:1139] Performed allocation for 1
> agents in 206527ns
> I0606 17:09:09.973254 29372 hierarchical.cpp:1488] No allocations performed
> I0606 17:09:09.973302 29372 hierarchical.cpp:1583] No inverse offers to send
> out!
> I0606 17:09:09.973361 29372 hierarchical.cpp:1139] Performed allocation for 1
> agents in 212278ns
> I0606 17:09:10.974567 29371 hierarchical.cpp:1488] No allocations performed
> I0606 17:09:10.974620 29371 hierarchical.cpp:1583] No inverse offers to send
> out!
> I0606 17:09:10.974841 29371 hierarchical.cpp:1139] Performed allocation for 1
> agents in 253821ns
> I0606 17:09:11.975347 29368 hierarchical.cpp:1488] No allocations performed
> I0606 17:09:11.975396 29368 hierarchical.cpp:1583] No inverse offers to send
> out!
> I0606 17:09:11.975455 29368 hierarchical.cpp:1139] Performed allocation for 1
> agents in 208010ns
> I0606 17:09:12.976863 29362 hierarchical.cpp:1488] No allocations performed
> I0606 17:09:12.976918 29362 hierarchical.cpp:1583] No inverse offers to send
> out!
> I0606 17:09:12.976991 29362 hierarchical.cpp:1139] Performed allocation for 1
> agents in 353721ns
> I0606 17:09:13.978327 29370 hierarchical.cpp:1488] No allocations performed
> I0606 17:09:13.978474 29370 hierarchical.cpp:1583] No inverse offers to send
> out!
> I0606 17:09:13.978638 29370 hierarchical.cpp:1139] Performed allocation for 1
> agents in 1.035881ms
> I0606 17:09:14.979547 29365 hierarchical.cpp:1488] No allocations performed
> I0606 17:09:14.979603 29365 hierarchical.cpp:1583] No inverse offers to send
> out!
> I0606 17:09:14.979676 29365 hierarchical.cpp:1139] Performed allocation for 1
> agents in 268215ns
> I0606 17:09:15.980909 29362 hierarchical.cpp:1488] No allocations performed
> I0606 17:09:15.980957 29362 hierarchical.cpp:1583] No inverse offers to send
> out!
> I0606 17:09:15.981017 29362 hierarchical.cpp:1139] Performed allocation for 1
> agents in 229419ns
> I0606 17:09:16.982249 29357 hierarchical.cpp:1488] No allocations performed
> I0606 17:09:16.982297 29357 hierarchical.cpp:1583] No inverse offers to send
> out!
> I0606 17:09:16.982357 29357 hierarchical.cpp:1139] Performed allocation for 1
> agents in 226096ns
> I0606 17:09:17.983276 29365 hierarchical.cpp:1488] No allocations performed
> I0606 17:09:17.983322 29365 hierarchical.cpp:1583] No inverse offers to send
> out!
> I0606 17:09:17.983379 29365 hierarchical.cpp:1139] Performed allocation for 1
> agents in 204849ns
> I0606 17:09:18.012662 29370 slave.cpp:4999] Querying resource estimator for
> oversubscribable resources
> I0606 17:09:18.013126 29360 slave.cpp:5013] Received oversubscribable
> resources from the resource estimator
> I0606 17:09:18.024147 29366 slave.cpp:3737] Received ping from
> slave-observer(40)@172.17.0.2:39784
> I0606 17:09:18.984776 29367 hierarchical.cpp:1488] No allocations performed
> I0606 17:09:18.984824 29367 hierarchical.cpp:1583] No inverse offers to send
> out!
> I0606 17:09:18.984884 29367 hierarchical.cpp:1139] Performed allocation for 1
> agents in 264252ns
> I0606 17:09:19.986194 29365 hierarchical.cpp:1488] No allocations performed
> I0606 17:09:19.986248 29365 hierarchical.cpp:1583] No inverse offers to send
> out!
> I0606 17:09:19.986309 29365 hierarchical.cpp:1139] Performed allocation for 1
> agents in 216298ns
> I0606 17:09:20.987082 29366 hierarchical.cpp:1488] No allocations performed
> I0606 17:09:20.987128 29366 hierarchical.cpp:1583] No inverse offers to send
> out!
> I0606 17:09:20.987186 29366 hierarchical.cpp:1139] Performed allocation for 1
> agents in 204558ns
> I0606 17:09:21.988206 29358 hierarchical.cpp:1488] No allocations performed
> I0606 17:09:21.988255 29358 hierarchical.cpp:1583] No inverse offers to send
> out!
> I0606 17:09:21.988314 29358 hierarchical.cpp:1139] Performed allocation for 1
> agents in 224919ns
> I0606 17:09:22.989120 29360 hierarchical.cpp:1488] No allocations performed
> I0606 17:09:22.989166 29360 hierarchical.cpp:1583] No inverse offers to send
> out!
> I0606 17:09:22.989225 29360 hierarchical.cpp:1139] Performed allocation for 1
> agents in 212465ns
> I0606 17:09:23.990144 29368 hierarchical.cpp:1488] No allocations performed
> I0606 17:09:23.990216 29368 hierarchical.cpp:1583] No inverse offers to send
> out!
> I0606 17:09:23.990299 29368 hierarchical.cpp:1139] Performed allocation for 1
> agents in 389041ns
> I0606 17:09:24.991322 29357 hierarchical.cpp:1488] No allocations performed
> I0606 17:09:24.991394 29357 hierarchical.cpp:1583] No inverse offers to send
> out!
> I0606 17:09:24.991478 29357 hierarchical.cpp:1139] Performed allocation for 1
> agents in 369972ns
> I0606 17:09:25.992058 29361 hierarchical.cpp:1488] No allocations performed
> I0606 17:09:25.992105 29361 hierarchical.cpp:1583] No inverse offers to send
> out!
> I0606 17:09:25.992166 29361 hierarchical.cpp:1139] Performed allocation for 1
> agents in 231349ns
> I0606 17:09:26.993691 29366 hierarchical.cpp:1488] No allocations performed
> I0606 17:09:26.993775 29366 hierarchical.cpp:1583] No inverse offers to send
> out!
> I0606 17:09:26.993860 29366 hierarchical.cpp:1139] Performed allocation for 1
> agents in 421170ns
> I0606 17:09:27.994453 29369 hierarchical.cpp:1488] No allocations performed
> I0606 17:09:27.994501 29369 hierarchical.cpp:1583] No inverse offers to send
> out!
> I0606 17:09:27.994562 29369 hierarchical.cpp:1139] Performed allocation for 1
> agents in 253922ns
> I0606 17:09:28.995723 29372 hierarchical.cpp:1488] No allocations performed
> I0606 17:09:28.995813 29372 hierarchical.cpp:1583] No inverse offers to send
> out!
> I0606 17:09:28.996001 29372 hierarchical.cpp:1139] Performed allocation for 1
> agents in 757147ns
> I0606 17:09:29.996526 29365 hierarchical.cpp:1488] No allocations performed
> I0606 17:09:29.996578 29365 hierarchical.cpp:1583] No inverse offers to send
> out!
> I0606 17:09:29.996644 29365 hierarchical.cpp:1139] Performed allocation for 1
> agents in 272727ns
> I0606 17:09:30.997154 29368 hierarchical.cpp:1488] No allocations performed
> I0606 17:09:30.997208 29368 hierarchical.cpp:1583] No inverse offers to send
> out!
> I0606 17:09:30.997273 29368 hierarchical.cpp:1139] Performed allocation for 1
> agents in 260618ns
> I0606 17:09:31.997973 29358 hierarchical.cpp:1488] No allocations performed
> I0606 17:09:31.998029 29358 hierarchical.cpp:1583] No inverse offers to send
> out!
> I0606 17:09:31.998103 29358 hierarchical.cpp:1139] Performed allocation for 1
> agents in 471132ns
> I0606 17:09:32.999361 29360 hierarchical.cpp:1488] No allocations performed
> I0606 17:09:32.999409 29360 hierarchical.cpp:1583] No inverse offers to send
> out!
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
