[
https://issues.apache.org/jira/browse/MESOS-2857?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Bernd Mathiske updated MESOS-2857:
----------------------------------
Shepherd: Bernd Mathiske
> FetcherCacheTest.LocalCachedExtract is flaky.
> ---------------------------------------------
>
> Key: MESOS-2857
> URL: https://issues.apache.org/jira/browse/MESOS-2857
> Project: Mesos
> Issue Type: Bug
> Components: fetcher, test
> Reporter: Benjamin Mahler
> Assignee: Benjamin Bannier
> Labels: flaky-test, mesosphere
>
> From jenkins:
> {noformat}
> [ RUN ] FetcherCacheTest.LocalCachedExtract
> Using temporary directory '/tmp/FetcherCacheTest_LocalCachedExtract_Cwdcdj'
> I0610 20:04:48.591573 24561 leveldb.cpp:176] Opened db in 3.512525ms
> I0610 20:04:48.592456 24561 leveldb.cpp:183] Compacted db in 828630ns
> I0610 20:04:48.592512 24561 leveldb.cpp:198] Created db iterator in 32992ns
> I0610 20:04:48.592531 24561 leveldb.cpp:204] Seeked to beginning of db in
> 8967ns
> I0610 20:04:48.592545 24561 leveldb.cpp:273] Iterated through 0 keys in the
> db in 7762ns
> I0610 20:04:48.592604 24561 replica.cpp:744] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0610 20:04:48.593438 24587 recover.cpp:449] Starting replica recovery
> I0610 20:04:48.593698 24587 recover.cpp:475] Replica is in EMPTY status
> I0610 20:04:48.595641 24580 replica.cpp:641] Replica in EMPTY status received
> a broadcasted recover request
> I0610 20:04:48.596086 24590 recover.cpp:195] Received a recover response from
> a replica in EMPTY status
> I0610 20:04:48.596607 24590 recover.cpp:566] Updating replica status to
> STARTING
> I0610 20:04:48.597507 24590 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 717888ns
> I0610 20:04:48.597535 24590 replica.cpp:323] Persisted replica status to
> STARTING
> I0610 20:04:48.597697 24590 recover.cpp:475] Replica is in STARTING status
> I0610 20:04:48.599165 24584 replica.cpp:641] Replica in STARTING status
> received a broadcasted recover request
> I0610 20:04:48.599434 24584 recover.cpp:195] Received a recover response from
> a replica in STARTING status
> I0610 20:04:48.599915 24590 recover.cpp:566] Updating replica status to VOTING
> I0610 20:04:48.600545 24590 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 432335ns
> I0610 20:04:48.600574 24590 replica.cpp:323] Persisted replica status to
> VOTING
> I0610 20:04:48.600659 24590 recover.cpp:580] Successfully joined the Paxos
> group
> I0610 20:04:48.600797 24590 recover.cpp:464] Recover process terminated
> I0610 20:04:48.602905 24594 master.cpp:363] Master
> 20150610-200448-3875541420-32907-24561 (dbade881e927) started on
> 172.17.0.231:32907
> I0610 20:04:48.602957 24594 master.cpp:365] Flags at startup: --acls=""
> --allocation_interval="1secs" --allocator="HierarchicalDRF"
> --authenticate="true" --authenticate_slaves="true" --authenticators="crammd5"
> --credentials="/tmp/FetcherCacheTest_LocalCachedExtract_Cwdcdj/credentials"
> --framework_sorter="drf" --help="false" --initialize_driver_logging="true"
> --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO"
> --quiet="false" --recovery_slave_removal_limit="100%"
> --registry="replicated_log" --registry_fetch_timeout="1mins"
> --registry_store_timeout="25secs" --registry_strict="true"
> --root_submissions="true" --slave_reregister_timeout="10mins"
> --user_sorter="drf" --version="false"
> --webui_dir="/mesos/mesos-0.23.0/_inst/share/mesos/webui"
> --work_dir="/tmp/FetcherCacheTest_LocalCachedExtract_Cwdcdj/master"
> --zk_session_timeout="10secs"
> I0610 20:04:48.603374 24594 master.cpp:410] Master only allowing
> authenticated frameworks to register
> I0610 20:04:48.603392 24594 master.cpp:415] Master only allowing
> authenticated slaves to register
> I0610 20:04:48.603404 24594 credentials.hpp:37] Loading credentials for
> authentication from
> '/tmp/FetcherCacheTest_LocalCachedExtract_Cwdcdj/credentials'
> I0610 20:04:48.603751 24594 master.cpp:454] Using default 'crammd5'
> authenticator
> I0610 20:04:48.604928 24594 master.cpp:491] Authorization enabled
> I0610 20:04:48.606034 24593 hierarchical.hpp:309] Initialized hierarchical
> allocator process
> I0610 20:04:48.606106 24593 whitelist_watcher.cpp:79] No whitelist given
> I0610 20:04:48.607430 24594 master.cpp:1476] The newly elected leader is
> master@172.17.0.231:32907 with id 20150610-200448-3875541420-32907-24561
> I0610 20:04:48.607466 24594 master.cpp:1489] Elected as the leading master!
> I0610 20:04:48.607481 24594 master.cpp:1259] Recovering from registrar
> I0610 20:04:48.607712 24594 registrar.cpp:313] Recovering registrar
> I0610 20:04:48.608543 24588 log.cpp:661] Attempting to start the writer
> I0610 20:04:48.610231 24588 replica.cpp:477] Replica received implicit
> promise request with proposal 1
> I0610 20:04:48.611335 24588 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 1.086439ms
> I0610 20:04:48.611382 24588 replica.cpp:345] Persisted promised to 1
> I0610 20:04:48.612303 24588 coordinator.cpp:230] Coordinator attemping to
> fill missing position
> I0610 20:04:48.613883 24593 replica.cpp:378] Replica received explicit
> promise request for position 0 with proposal 2
> I0610 20:04:48.619205 24593 leveldb.cpp:343] Persisting action (8 bytes) to
> leveldb took 5.228235ms
> I0610 20:04:48.619257 24593 replica.cpp:679] Persisted action at 0
> I0610 20:04:48.621919 24593 replica.cpp:511] Replica received write request
> for position 0
> I0610 20:04:48.621987 24593 leveldb.cpp:438] Reading position from leveldb
> took 49394ns
> I0610 20:04:48.622689 24593 leveldb.cpp:343] Persisting action (14 bytes) to
> leveldb took 668412ns
> I0610 20:04:48.622716 24593 replica.cpp:679] Persisted action at 0
> I0610 20:04:48.623507 24584 replica.cpp:658] Replica received learned notice
> for position 0
> I0610 20:04:48.624155 24584 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 612283ns
> I0610 20:04:48.624186 24584 replica.cpp:679] Persisted action at 0
> I0610 20:04:48.624215 24584 replica.cpp:664] Replica learned NOP action at
> position 0
> I0610 20:04:48.625144 24593 log.cpp:677] Writer started with ending position 0
> I0610 20:04:48.626724 24589 leveldb.cpp:438] Reading position from leveldb
> took 72013ns
> I0610 20:04:48.629276 24591 registrar.cpp:346] Successfully fetched the
> registry (0B) in 21.520128ms
> I0610 20:04:48.629663 24591 registrar.cpp:445] Applied 1 operations in
> 129587ns; attempting to update the 'registry'
> I0610 20:04:48.632237 24579 log.cpp:685] Attempting to append 131 bytes to
> the log
> I0610 20:04:48.632624 24579 coordinator.cpp:340] Coordinator attempting to
> write APPEND action at position 1
> I0610 20:04:48.633739 24579 replica.cpp:511] Replica received write request
> for position 1
> I0610 20:04:48.634351 24579 leveldb.cpp:343] Persisting action (150 bytes) to
> leveldb took 583937ns
> I0610 20:04:48.634382 24579 replica.cpp:679] Persisted action at 1
> I0610 20:04:48.635073 24583 replica.cpp:658] Replica received learned notice
> for position 1
> I0610 20:04:48.635442 24583 leveldb.cpp:343] Persisting action (152 bytes) to
> leveldb took 357122ns
> I0610 20:04:48.635469 24583 replica.cpp:679] Persisted action at 1
> I0610 20:04:48.635494 24583 replica.cpp:664] Replica learned APPEND action at
> position 1
> I0610 20:04:48.636337 24583 registrar.cpp:490] Successfully updated the
> 'registry' in 6.534144ms
> I0610 20:04:48.636725 24594 log.cpp:704] Attempting to truncate the log to 1
> I0610 20:04:48.636858 24583 registrar.cpp:376] Successfully recovered
> registrar
> I0610 20:04:48.637073 24594 coordinator.cpp:340] Coordinator attempting to
> write TRUNCATE action at position 2
> I0610 20:04:48.637789 24594 master.cpp:1286] Recovered 0 slaves from the
> Registry (95B) ; allowing 10mins for slaves to re-register
> I0610 20:04:48.638630 24583 replica.cpp:511] Replica received write request
> for position 2
> I0610 20:04:48.639127 24583 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 396272ns
> I0610 20:04:48.639153 24583 replica.cpp:679] Persisted action at 2
> I0610 20:04:48.639804 24583 replica.cpp:658] Replica received learned notice
> for position 2
> I0610 20:04:48.640965 24583 leveldb.cpp:343] Persisting action (18 bytes) to
> leveldb took 1.147322ms
> I0610 20:04:48.641054 24583 leveldb.cpp:401] Deleting ~1 keys from leveldb
> took 72395ns
> I0610 20:04:48.641197 24583 replica.cpp:679] Persisted action at 2
> I0610 20:04:48.641345 24583 replica.cpp:664] Replica learned TRUNCATE action
> at position 2
> I0610 20:04:48.652274 24561 containerizer.cpp:111] Using isolation:
> posix/cpu,posix/mem
> I0610 20:04:48.658994 24590 slave.cpp:188] Slave started on
> 42)@172.17.0.231:32907
> I0610 20:04:48.659049 24590 slave.cpp:189] Flags at startup:
> --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/FetcherCacheTest_LocalCachedExtract_LCHuuM/credential"
> --default_role="*" --disk_watch_interval="1mins" --docker="docker"
> --docker_kill_orphans="true" --docker_remove_delay="6hrs"
> --docker_sandbox_directory="/mnt/mesos/sandbox"
> --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns"
> --enforce_container_disk_quota="false"
> --executor_registration_timeout="1mins"
> --executor_shutdown_grace_period="5secs"
> --fetcher_cache_dir="/tmp/FetcherCacheTest_LocalCachedExtract_LCHuuM/fetch"
> --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks"
> --gc_disk_headroom="0.1" --hadoop_home="" --help="false"
> --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem"
> --launcher_dir="/mesos/mesos-0.23.0/_build/src" --logbufsecs="0"
> --logging_level="INFO" --oversubscribed_resources_interval="15secs"
> --perf_duration="10secs" --perf_interval="1mins" --quiet="false"
> --recover="reconnect" --recovery_timeout="15mins"
> --registration_backoff_factor="10ms" --resource_monitoring_interval="1secs"
> --resources="cpus(*):1000; mem(*):1000" --revocable_cpu_low_priority="true"
> --strict="true" --switch_user="true" --version="false"
> --work_dir="/tmp/FetcherCacheTest_LocalCachedExtract_LCHuuM"
> I0610 20:04:48.659570 24590 credentials.hpp:85] Loading credential for
> authentication from
> '/tmp/FetcherCacheTest_LocalCachedExtract_LCHuuM/credential'
> I0610 20:04:48.659803 24590 slave.cpp:319] Slave using credential for:
> test-principal
> I0610 20:04:48.660441 24590 slave.cpp:352] Slave resources: cpus(*):1000;
> mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0610 20:04:48.660555 24590 slave.cpp:382] Slave hostname: dbade881e927
> I0610 20:04:48.660578 24590 slave.cpp:387] Slave checkpoint: true
> I0610 20:04:48.661550 24588 state.cpp:35] Recovering state from
> '/tmp/FetcherCacheTest_LocalCachedExtract_LCHuuM/meta'
> I0610 20:04:48.661913 24590 status_update_manager.cpp:201] Recovering status
> update manager
> I0610 20:04:48.662253 24590 containerizer.cpp:312] Recovering containerizer
> I0610 20:04:48.663207 24581 slave.cpp:3950] Finished recovery
> I0610 20:04:48.663761 24581 slave.cpp:4104] Querying resource estimator for
> oversubscribable resources
> I0610 20:04:48.664077 24581 slave.cpp:678] New master detected at
> master@172.17.0.231:32907
> I0610 20:04:48.664088 24586 status_update_manager.cpp:175] Pausing sending
> status updates
> I0610 20:04:48.664245 24581 slave.cpp:741] Authenticating with master
> master@172.17.0.231:32907
> I0610 20:04:48.664388 24581 slave.cpp:746] Using default CRAM-MD5
> authenticatee
> I0610 20:04:48.664611 24581 slave.cpp:714] Detecting new master
> I0610 20:04:48.664647 24594 authenticatee.hpp:139] Creating new client SASL
> connection
> I0610 20:04:48.664813 24581 slave.cpp:4125] Received oversubscribable
> resources from the resource estimator
> I0610 20:04:48.665060 24581 slave.cpp:4129] No master detected. Re-querying
> resource estimator after 15secs
> I0610 20:04:48.665096 24594 master.cpp:4181] Authenticating
> slave(42)@172.17.0.231:32907
> I0610 20:04:48.665247 24581 authenticator.cpp:406] Starting authentication
> session for crammd5_authenticatee(130)@172.17.0.231:32907
> I0610 20:04:48.665657 24581 authenticator.cpp:92] Creating new server SASL
> connection
> I0610 20:04:48.666013 24581 authenticatee.hpp:230] Received SASL
> authentication mechanisms: CRAM-MD5
> I0610 20:04:48.666159 24581 authenticatee.hpp:256] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0610 20:04:48.666443 24592 authenticator.cpp:197] Received SASL
> authentication start
> I0610 20:04:48.666591 24592 authenticator.cpp:319] Authentication requires
> more steps
> I0610 20:04:48.666779 24592 authenticatee.hpp:276] Received SASL
> authentication step
> I0610 20:04:48.667007 24585 authenticator.cpp:225] Received SASL
> authentication step
> I0610 20:04:48.667043 24585 auxprop.cpp:101] Request to lookup properties for
> user: 'test-principal' realm: 'dbade881e927' server FQDN: 'dbade881e927'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0610 20:04:48.667058 24585 auxprop.cpp:173] Looking up auxiliary property
> '*userPassword'
> I0610 20:04:48.667110 24585 auxprop.cpp:173] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0610 20:04:48.667142 24585 auxprop.cpp:101] Request to lookup properties for
> user: 'test-principal' realm: 'dbade881e927' server FQDN: 'dbade881e927'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0610 20:04:48.667155 24585 auxprop.cpp:123] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0610 20:04:48.667163 24585 auxprop.cpp:123] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0610 20:04:48.667181 24585 authenticator.cpp:311] Authentication success
> I0610 20:04:48.667331 24585 authenticatee.hpp:316] Authentication success
> I0610 20:04:48.667414 24585 master.cpp:4211] Successfully authenticated
> principal 'test-principal' at slave(42)@172.17.0.231:32907
> I0610 20:04:48.667505 24585 authenticator.cpp:424] Authentication session
> cleanup for crammd5_authenticatee(130)@172.17.0.231:32907
> I0610 20:04:48.667809 24585 slave.cpp:812] Successfully authenticated with
> master master@172.17.0.231:32907
> I0610 20:04:48.667982 24585 slave.cpp:1146] Will retry registration in
> 7.257154ms if necessary
> I0610 20:04:48.668226 24585 master.cpp:3157] Registering slave at
> slave(42)@172.17.0.231:32907 (dbade881e927) with id
> 20150610-200448-3875541420-32907-24561-S0
> I0610 20:04:48.668737 24585 registrar.cpp:445] Applied 1 operations in
> 90255ns; attempting to update the 'registry'
> I0610 20:04:48.672297 24585 log.cpp:685] Attempting to append 305 bytes to
> the log
> I0610 20:04:48.672541 24585 coordinator.cpp:340] Coordinator attempting to
> write APPEND action at position 3
> I0610 20:04:48.673528 24593 replica.cpp:511] Replica received write request
> for position 3
> I0610 20:04:48.674321 24593 leveldb.cpp:343] Persisting action (324 bytes) to
> leveldb took 766804ns
> I0610 20:04:48.674355 24593 replica.cpp:679] Persisted action at 3
> I0610 20:04:48.675138 24587 replica.cpp:658] Replica received learned notice
> for position 3
> I0610 20:04:48.675866 24587 leveldb.cpp:343] Persisting action (326 bytes) to
> leveldb took 714643ns
> I0610 20:04:48.675897 24587 replica.cpp:679] Persisted action at 3
> I0610 20:04:48.675922 24587 replica.cpp:664] Replica learned APPEND action at
> position 3
> I0610 20:04:48.677471 24587 registrar.cpp:490] Successfully updated the
> 'registry' in 8.656128ms
> I0610 20:04:48.677759 24587 log.cpp:704] Attempting to truncate the log to 3
> I0610 20:04:48.678423 24593 coordinator.cpp:340] Coordinator attempting to
> write TRUNCATE action at position 4
> I0610 20:04:48.678621 24587 master.cpp:3214] Registered slave
> 20150610-200448-3875541420-32907-24561-S0 at slave(42)@172.17.0.231:32907
> (dbade881e927) with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06;
> ports(*):[31000-32000]
> I0610 20:04:48.678959 24593 hierarchical.hpp:496] Added slave
> 20150610-200448-3875541420-32907-24561-S0 (dbade881e927) with cpus(*):1000;
> mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] (and cpus(*):1000;
> mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] available)
> I0610 20:04:48.679157 24593 hierarchical.hpp:933] No resources available to
> allocate!
> I0610 20:04:48.679183 24593 hierarchical.hpp:852] Performed allocation for
> slave 20150610-200448-3875541420-32907-24561-S0 in 175519ns
> I0610 20:04:48.679805 24593 replica.cpp:511] Replica received write request
> for position 4
> I0610 20:04:48.684160 24587 slave.cpp:846] Registered with master
> master@172.17.0.231:32907; given slave ID
> 20150610-200448-3875541420-32907-24561-S0
> I0610 20:04:48.684229 24587 fetcher.cpp:77] Clearing fetcher cache
> I0610 20:04:48.684666 24587 slave.cpp:869] Checkpointing SlaveInfo to
> '/tmp/FetcherCacheTest_LocalCachedExtract_LCHuuM/meta/slaves/20150610-200448-3875541420-32907-24561-S0/slave.info'
> I0610 20:04:48.687366 24587 slave.cpp:2895] Received ping from
> slave-observer(42)@172.17.0.231:32907
> I0610 20:04:48.687453 24584 status_update_manager.cpp:182] Resuming sending
> status updates
> I0610 20:04:48.690901 24593 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 3.385583ms
> I0610 20:04:48.690975 24593 replica.cpp:679] Persisted action at 4
> I0610 20:04:48.692137 24593 replica.cpp:658] Replica received learned notice
> for position 4
> I0610 20:04:48.692603 24593 leveldb.cpp:343] Persisting action (18 bytes) to
> leveldb took 449838ns
> I0610 20:04:48.692674 24593 leveldb.cpp:401] Deleting ~2 keys from leveldb
> took 52471ns
> I0610 20:04:48.692699 24593 replica.cpp:679] Persisted action at 4
> I0610 20:04:48.692726 24593 replica.cpp:664] Replica learned TRUNCATE action
> at position 4
> I0610 20:04:48.693544 24561 sched.cpp:157] Version: 0.23.0
> I0610 20:04:48.695550 24590 sched.cpp:254] New master detected at
> master@172.17.0.231:32907
> I0610 20:04:48.697090 24590 sched.cpp:310] Authenticating with master
> master@172.17.0.231:32907
> I0610 20:04:48.697136 24590 sched.cpp:317] Using default CRAM-MD5
> authenticatee
> I0610 20:04:48.697511 24586 authenticatee.hpp:139] Creating new client SASL
> connection
> I0610 20:04:48.697937 24586 master.cpp:4181] Authenticating
> scheduler-51f5c1b5-bb50-4118-bde8-4dcdfd69205d@172.17.0.231:32907
> I0610 20:04:48.698185 24584 authenticator.cpp:406] Starting authentication
> session for crammd5_authenticatee(131)@172.17.0.231:32907
> I0610 20:04:48.698575 24584 authenticator.cpp:92] Creating new server SASL
> connection
> I0610 20:04:48.698807 24584 authenticatee.hpp:230] Received SASL
> authentication mechanisms: CRAM-MD5
> I0610 20:04:48.699898 24584 authenticatee.hpp:256] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0610 20:04:48.700040 24584 authenticator.cpp:197] Received SASL
> authentication start
> I0610 20:04:48.700119 24584 authenticator.cpp:319] Authentication requires
> more steps
> I0610 20:04:48.700193 24584 authenticatee.hpp:276] Received SASL
> authentication step
> I0610 20:04:48.700287 24584 authenticator.cpp:225] Received SASL
> authentication step
> I0610 20:04:48.700320 24584 auxprop.cpp:101] Request to lookup properties for
> user: 'test-principal' realm: 'dbade881e927' server FQDN: 'dbade881e927'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0610 20:04:48.700333 24584 auxprop.cpp:173] Looking up auxiliary property
> '*userPassword'
> I0610 20:04:48.700392 24584 auxprop.cpp:173] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0610 20:04:48.700425 24584 auxprop.cpp:101] Request to lookup properties for
> user: 'test-principal' realm: 'dbade881e927' server FQDN: 'dbade881e927'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0610 20:04:48.700439 24584 auxprop.cpp:123] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0610 20:04:48.700448 24584 auxprop.cpp:123] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0610 20:04:48.700467 24584 authenticator.cpp:311] Authentication success
> I0610 20:04:48.700640 24584 authenticatee.hpp:316] Authentication success
> I0610 20:04:48.700742 24584 authenticator.cpp:424] Authentication session
> cleanup for crammd5_authenticatee(131)@172.17.0.231:32907
> I0610 20:04:48.701282 24590 sched.cpp:398] Successfully authenticated with
> master master@172.17.0.231:32907
> I0610 20:04:48.701315 24590 sched.cpp:521] Sending registration request to
> master@172.17.0.231:32907
> I0610 20:04:48.701386 24590 sched.cpp:554] Will retry registration in
> 1.128089605secs if necessary
> I0610 20:04:48.701676 24586 master.cpp:4211] Successfully authenticated
> principal 'test-principal' at
> scheduler-51f5c1b5-bb50-4118-bde8-4dcdfd69205d@172.17.0.231:32907
> I0610 20:04:48.702863 24586 master.cpp:1716] Received registration request
> for framework 'default' at
> scheduler-51f5c1b5-bb50-4118-bde8-4dcdfd69205d@172.17.0.231:32907
> W0610 20:04:48.702924 24586 master.cpp:1539] Framework at
> scheduler-51f5c1b5-bb50-4118-bde8-4dcdfd69205d@172.17.0.231:32907
> (authenticated as 'test-principal') does not specify principal in its
> FrameworkInfo
> I0610 20:04:48.702957 24586 master.cpp:1555] Authorizing framework principal
> '' to receive offers for role '*'
> I0610 20:04:48.703580 24586 master.cpp:1783] Registering framework
> 20150610-200448-3875541420-32907-24561-0000 (default) at
> scheduler-51f5c1b5-bb50-4118-bde8-4dcdfd69205d@172.17.0.231:32907 with
> checkpointing enabled and capabilities [ ]
> I0610 20:04:48.705044 24590 hierarchical.hpp:354] Added framework
> 20150610-200448-3875541420-32907-24561-0000
> I0610 20:04:48.705657 24590 hierarchical.hpp:834] Performed allocation for 1
> slaves in 583520ns
> I0610 20:04:48.707613 24586 master.cpp:4100] Sending 1 offers to framework
> 20150610-200448-3875541420-32907-24561-0000 (default) at
> scheduler-51f5c1b5-bb50-4118-bde8-4dcdfd69205d@172.17.0.231:32907
> I0610 20:04:48.709035 24590 sched.cpp:448] Framework registered with
> 20150610-200448-3875541420-32907-24561-0000
> I0610 20:04:48.709113 24590 sched.cpp:462] Scheduler::registered took 33214ns
> GMOCK WARNING:
> Uninteresting mock function call - returning directly.
> Function call: resourceOffers(0x3bd7fb0, @0x7fe5bb7af898 { 128-byte
> object <90-8D 30-CD E5-7F 00-00 00-00 00-00 00-00 00-00 30-E8 00-80 E5-7F
> 00-00 D0-E8 00-80 E5-7F 00-00 70-E9 00-80 E5-7F 00-00 10-EA 00-80 E5-7F 00-00
> F0-58 00-80 E5-7F 00-00 04-00 00-00 04-00 00-00 04-00 00-00 65-45 76-65 00-00
> 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 E5-7F 00-00 00-00 00-00
> 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 0F-00
> 00-00> })
> Stack trace:
> I0610 20:04:48.709631 24590 sched.cpp:611] Scheduler::resourceOffers took
> 189034ns
> I0610 20:04:49.607378 24589 hierarchical.hpp:933] No resources available to
> allocate!
> I0610 20:04:49.607435 24589 hierarchical.hpp:834] Performed allocation for 1
> slaves in 474600ns
> I0610 20:04:50.608489 24582 hierarchical.hpp:933] No resources available to
> allocate!
> I0610 20:04:50.608551 24582 hierarchical.hpp:834] Performed allocation for 1
> slaves in 517133ns
> I0610 20:04:51.609849 24589 hierarchical.hpp:933] No resources available to
> allocate!
> I0610 20:04:51.609908 24589 hierarchical.hpp:834] Performed allocation for 1
> slaves in 440523ns
> I0610 20:04:52.611188 24584 hierarchical.hpp:933] No resources available to
> allocate!
> I0610 20:04:52.611250 24584 hierarchical.hpp:834] Performed allocation for 1
> slaves in 471882ns
> I0610 20:04:53.612911 24581 hierarchical.hpp:933] No resources available to
> allocate!
> I0610 20:04:53.612962 24581 hierarchical.hpp:834] Performed allocation for 1
> slaves in 411941ns
> I0610 20:04:54.614280 24582 hierarchical.hpp:933] No resources available to
> allocate!
> I0610 20:04:54.614336 24582 hierarchical.hpp:834] Performed allocation for 1
> slaves in 448103ns
> I0610 20:04:55.615985 24583 hierarchical.hpp:933] No resources available to
> allocate!
> I0610 20:04:55.616046 24583 hierarchical.hpp:834] Performed allocation for 1
> slaves in 494677ns
> I0610 20:04:56.616896 24580 hierarchical.hpp:933] No resources available to
> allocate!
> I0610 20:04:56.616952 24580 hierarchical.hpp:834] Performed allocation for 1
> slaves in 461555ns
> I0610 20:04:57.618814 24587 hierarchical.hpp:933] No resources available to
> allocate!
> I0610 20:04:57.618885 24587 hierarchical.hpp:834] Performed allocation for 1
> slaves in 491478ns
> I0610 20:04:58.620564 24589 hierarchical.hpp:933] No resources available to
> allocate!
> I0610 20:04:58.620621 24589 hierarchical.hpp:834] Performed allocation for 1
> slaves in 434384ns
> I0610 20:04:59.621649 24584 hierarchical.hpp:933] No resources available to
> allocate!
> I0610 20:04:59.621706 24584 hierarchical.hpp:834] Performed allocation for 1
> slaves in 453279ns
> I0610 20:05:00.623241 24593 hierarchical.hpp:933] No resources available to
> allocate!
> I0610 20:05:00.623299 24593 hierarchical.hpp:834] Performed allocation for 1
> slaves in 423551ns
> I0610 20:05:01.624984 24590 hierarchical.hpp:933] No resources available to
> allocate!
> I0610 20:05:01.625041 24590 hierarchical.hpp:834] Performed allocation for 1
> slaves in 458545ns
> I0610 20:05:02.626266 24591 hierarchical.hpp:933] No resources available to
> allocate!
> I0610 20:05:02.626327 24591 hierarchical.hpp:834] Performed allocation for 1
> slaves in 490068ns
> I0610 20:05:03.627702 24593 hierarchical.hpp:933] No resources available to
> allocate!
> I0610 20:05:03.627766 24593 hierarchical.hpp:834] Performed allocation for 1
> slaves in 473279ns
> I0610 20:05:03.666060 24581 slave.cpp:4104] Querying resource estimator for
> oversubscribable resources
> I0610 20:05:03.666353 24581 slave.cpp:4125] Received oversubscribable
> resources from the resource estimator
> I0610 20:05:03.680258 24588 slave.cpp:2895] Received ping from
> slave-observer(42)@172.17.0.231:32907
> F0610 20:05:03.725155 24561 fetcher_cache_tests.cpp:354] CHECK_READY(offers):
> is PENDING Failed to wait for resource offers
> *** Check failure stack trace: ***
> @ 0x7fe5cc5a2a0d google::LogMessage::Fail()
> @ 0x7fe5cc5a1dee google::LogMessage::SendToLog()
> @ 0x7fe5cc5a26cd google::LogMessage::Flush()
> @ 0x7fe5cc5a5b38 google::LogMessageFatal::~LogMessageFatal()
> @ 0x8947c7 _CheckFatal::~_CheckFatal()
> @ 0xadf458
> mesos::internal::tests::FetcherCacheTest::launchTask()
> @ 0xae5ea4
> mesos::internal::tests::FetcherCacheTest_LocalCachedExtract_Test::TestBody()
> @ 0x128fb83
> testing::internal::HandleSehExceptionsInMethodIfSupported<>()
> @ 0x127a7e7
> testing::internal::HandleExceptionsInMethodIfSupported<>()
> @ 0x1261c45 testing::Test::Run()
> @ 0x126287b testing::TestInfo::Run()
> @ 0x1262ec7 testing::TestCase::Run()
> @ 0x126854a testing::internal::UnitTestImpl::RunAllTests()
> @ 0x128c163
> testing::internal::HandleSehExceptionsInMethodIfSupported<>()
> @ 0x127c817
> testing::internal::HandleExceptionsInMethodIfSupported<>()
> @ 0x1268247 testing::UnitTest::Run()
> @ 0xca398e main
> @ 0x7fe5c8436ec5 (unknown)
> @ 0x749e8c (unknown)
> {noformat}
> [~bernd-mesos] not sure if there's a ticket capturing this already, sorry if
> this is a duplicate.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
