[
https://issues.apache.org/jira/browse/MESOS-2857?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15063883#comment-15063883
]
Benjamin Bannier commented on MESOS-2857:
-----------------------------------------
[[email protected]], we still cannot reproduce what you reported above, and
since the code triggering this is in effect sequential, it still seems likely
to be triggered by something independent of our code.
Could you please try to reproduce this on the affected machine with verbose
libprocess logging, or otherwise close this ticket?
> 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
> [email protected]: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
> [email protected]: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
> [email protected]: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 [email protected]: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
> [email protected]: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
> [email protected]:32907
> I0610 20:04:48.697090 24590 sched.cpp:310] Authenticating with master
> [email protected]: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
> [email protected]: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 [email protected]:32907
> I0610 20:04:48.701315 24590 sched.cpp:521] Sending registration request to
> [email protected]: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
> [email protected]:32907
> I0610 20:04:48.702863 24586 master.cpp:1716] Received registration request
> for framework 'default' at
> [email protected]:32907
> W0610 20:04:48.702924 24586 master.cpp:1539] Framework at
> [email protected]: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
> [email protected]: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
> [email protected]: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)
