[
https://issues.apache.org/jira/browse/MESOS-3789?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14968182#comment-14968182
]
Anand Mazumdar commented on MESOS-3789:
---------------------------------------
[~vinodkone] I am marking this as dup in favor of
https://issues.apache.org/jira/browse/MESOS-3733
[~gyliu] was already looking at this.
> ContentType/SchedulerTest.Suppress/1 is flalky
> ----------------------------------------------
>
> Key: MESOS-3789
> URL: https://issues.apache.org/jira/browse/MESOS-3789
> Project: Mesos
> Issue Type: Bug
> Environment:
> https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose%20--enable-libevent%20--enable-ssl,OS=ubuntu:14.04,label_exp=docker%7C%7CHadoop/965/consoleFull
> Reporter: Vinod Kone
> Assignee: Guangya Liu
>
> Observed in ASF CI
> {code}
> [ RUN ] ContentType/SchedulerTest.Suppress/1
> Using temporary directory '/tmp/ContentType_SchedulerTest_Suppress_1_QtJ44w'
> I1021 19:17:43.142560 30920 leveldb.cpp:176] Opened db in 2.484217ms
> I1021 19:17:43.143709 30920 leveldb.cpp:183] Compacted db in 1.002737ms
> I1021 19:17:43.143831 30920 leveldb.cpp:198] Created db iterator in 25419ns
> I1021 19:17:43.143971 30920 leveldb.cpp:204] Seeked to beginning of db in
> 3107ns
> I1021 19:17:43.144098 30920 leveldb.cpp:273] Iterated through 0 keys in the
> db in 504ns
> I1021 19:17:43.144224 30920 replica.cpp:748] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I1021 19:17:43.145409 30948 recover.cpp:449] Starting replica recovery
> I1021 19:17:43.146062 30943 recover.cpp:475] Replica is in EMPTY status
> I1021 19:17:43.148715 30942 replica.cpp:644] Replica in EMPTY status received
> a broadcasted recover request from (10113)@172.17.3.153:57838
> I1021 19:17:43.149269 30943 recover.cpp:195] Received a recover response from
> a replica in EMPTY status
> I1021 19:17:43.149783 30942 recover.cpp:566] Updating replica status to
> STARTING
> I1021 19:17:43.150475 30945 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 562580ns
> I1021 19:17:43.150565 30945 replica.cpp:323] Persisted replica status to
> STARTING
> I1021 19:17:43.150841 30945 recover.cpp:475] Replica is in STARTING status
> I1021 19:17:43.152133 30945 replica.cpp:644] Replica in STARTING status
> received a broadcasted recover request from (10114)@172.17.3.153:57838
> I1021 19:17:43.152479 30945 recover.cpp:195] Received a recover response from
> a replica in STARTING status
> I1021 19:17:43.153056 30945 recover.cpp:566] Updating replica status to VOTING
> I1021 19:17:43.153539 30945 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 275156ns
> I1021 19:17:43.153623 30945 replica.cpp:323] Persisted replica status to
> VOTING
> I1021 19:17:43.153820 30943 recover.cpp:580] Successfully joined the Paxos
> group
> I1021 19:17:43.153996 30943 recover.cpp:464] Recover process terminated
> I1021 19:17:43.154260 30940 master.cpp:376] Master
> 242dc5ed-402d-4873-be6d-9bad1f3296f9 (79d8015cd9f0) started on
> 172.17.3.153:57838
> I1021 19:17:43.154288 30940 master.cpp:378] Flags at startup: --acls=""
> --allocation_interval="1secs" --allocator="HierarchicalDRF"
> --authenticate="false" --authenticate_slaves="true"
> --authenticators="crammd5" --authorizers="local"
> --credentials="/tmp/ContentType_SchedulerTest_Suppress_1_QtJ44w/credentials"
> --framework_sorter="drf" --help="false" --hostname_lookup="true"
> --initialize_driver_logging="true" --log_auto_initialize="true"
> --logbufsecs="0" --logging_level="INFO" --max_slave_ping_timeouts="5"
> --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_ping_timeout="15secs"
> --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false"
> --webui_dir="/mesos/mesos-0.26.0/_inst/share/mesos/webui"
> --work_dir="/tmp/ContentType_SchedulerTest_Suppress_1_QtJ44w/master"
> --zk_session_timeout="10secs"
> I1021 19:17:43.154597 30940 master.cpp:425] Master allowing unauthenticated
> frameworks to register
> I1021 19:17:43.154605 30940 master.cpp:428] Master only allowing
> authenticated slaves to register
> I1021 19:17:43.154611 30940 credentials.hpp:37] Loading credentials for
> authentication from
> '/tmp/ContentType_SchedulerTest_Suppress_1_QtJ44w/credentials'
> I1021 19:17:43.154871 30940 master.cpp:467] Using default 'crammd5'
> authenticator
> I1021 19:17:43.155226 30940 master.cpp:504] Authorization enabled
> I1021 19:17:43.155524 30947 whitelist_watcher.cpp:79] No whitelist given
> I1021 19:17:43.155642 30939 hierarchical.cpp:140] Initialized hierarchical
> allocator process
> I1021 19:17:43.157397 30952 master.cpp:1609] The newly elected leader is
> master@172.17.3.153:57838 with id 242dc5ed-402d-4873-be6d-9bad1f3296f9
> I1021 19:17:43.157438 30952 master.cpp:1622] Elected as the leading master!
> I1021 19:17:43.157455 30952 master.cpp:1382] Recovering from registrar
> I1021 19:17:43.157595 30943 registrar.cpp:309] Recovering registrar
> I1021 19:17:43.158347 30950 log.cpp:661] Attempting to start the writer
> I1021 19:17:43.159632 30949 replica.cpp:478] Replica received implicit
> promise request from (10115)@172.17.3.153:57838 with proposal 1
> I1021 19:17:43.160238 30949 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 565627ns
> I1021 19:17:43.160266 30949 replica.cpp:345] Persisted promised to 1
> I1021 19:17:43.160828 30952 coordinator.cpp:231] Coordinator attempting to
> fill missing positions
> I1021 19:17:43.161840 30941 replica.cpp:378] Replica received explicit
> promise request from (10116)@172.17.3.153:57838 for position 0 with proposal 2
> I1021 19:17:43.162844 30941 leveldb.cpp:343] Persisting action (8 bytes) to
> leveldb took 957986ns
> I1021 19:17:43.162972 30941 replica.cpp:683] Persisted action at 0
> I1021 19:17:43.164635 30944 replica.cpp:512] Replica received write request
> for position 0 from (10117)@172.17.3.153:57838
> I1021 19:17:43.164803 30944 leveldb.cpp:438] Reading position from leveldb
> took 51932ns
> I1021 19:17:43.165463 30944 leveldb.cpp:343] Persisting action (14 bytes) to
> leveldb took 510820ns
> I1021 19:17:43.165559 30944 replica.cpp:683] Persisted action at 0
> I1021 19:17:43.166410 30940 replica.cpp:662] Replica received learned notice
> for position 0 from @0.0.0.0:0
> I1021 19:17:43.166817 30940 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 373148ns
> I1021 19:17:43.166843 30940 replica.cpp:683] Persisted action at 0
> I1021 19:17:43.166864 30940 replica.cpp:668] Replica learned NOP action at
> position 0
> I1021 19:17:43.167780 30940 log.cpp:677] Writer started with ending position 0
> I1021 19:17:43.169354 30942 leveldb.cpp:438] Reading position from leveldb
> took 38722ns
> I1021 19:17:43.170537 30954 registrar.cpp:342] Successfully fetched the
> registry (0B) in 12.764928ms
> I1021 19:17:43.170884 30954 registrar.cpp:441] Applied 1 operations in
> 37094ns; attempting to update the 'registry'
> I1021 19:17:43.172201 30945 log.cpp:685] Attempting to append 176 bytes to
> the log
> I1021 19:17:43.172338 30950 coordinator.cpp:341] Coordinator attempting to
> write APPEND action at position 1
> I1021 19:17:43.173254 30954 replica.cpp:512] Replica received write request
> for position 1 from (10118)@172.17.3.153:57838
> I1021 19:17:43.173974 30954 leveldb.cpp:343] Persisting action (195 bytes) to
> leveldb took 483251ns
> I1021 19:17:43.174073 30954 replica.cpp:683] Persisted action at 1
> I1021 19:17:43.174882 30939 replica.cpp:662] Replica received learned notice
> for position 1 from @0.0.0.0:0
> I1021 19:17:43.175428 30939 leveldb.cpp:343] Persisting action (197 bytes) to
> leveldb took 513065ns
> I1021 19:17:43.175456 30939 replica.cpp:683] Persisted action at 1
> I1021 19:17:43.175478 30939 replica.cpp:668] Replica learned APPEND action at
> position 1
> I1021 19:17:43.176733 30947 registrar.cpp:486] Successfully updated the
> 'registry' in 5.61408ms
> I1021 19:17:43.176875 30947 registrar.cpp:372] Successfully recovered
> registrar
> I1021 19:17:43.176983 30948 log.cpp:704] Attempting to truncate the log to 1
> I1021 19:17:43.177096 30954 coordinator.cpp:341] Coordinator attempting to
> write TRUNCATE action at position 2
> I1021 19:17:43.177280 30947 master.cpp:1419] Recovered 0 slaves from the
> Registry (137B) ; allowing 10mins for slaves to re-register
> I1021 19:17:43.178356 30944 replica.cpp:512] Replica received write request
> for position 2 from (10119)@172.17.3.153:57838
> I1021 19:17:43.178867 30944 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 470190ns
> I1021 19:17:43.178894 30944 replica.cpp:683] Persisted action at 2
> I1021 19:17:43.179762 30944 replica.cpp:662] Replica received learned notice
> for position 2 from @0.0.0.0:0
> I1021 19:17:43.180310 30944 leveldb.cpp:343] Persisting action (18 bytes) to
> leveldb took 521320ns
> I1021 19:17:43.180368 30944 leveldb.cpp:401] Deleting ~1 keys from leveldb
> took 33175ns
> I1021 19:17:43.180387 30944 replica.cpp:683] Persisted action at 2
> I1021 19:17:43.180408 30944 replica.cpp:668] Replica learned TRUNCATE action
> at position 2
> I1021 19:17:43.190227 30920 containerizer.cpp:143] Using isolation:
> posix/cpu,posix/mem,filesystem/posix
> W1021 19:17:43.190665 30920 backend.cpp:50] Failed to create 'bind' backend:
> BindBackend requires root privileges
> I1021 19:17:43.195164 30943 slave.cpp:191] Slave started on
> 355)@172.17.3.153:57838
> I1021 19:17:43.195212 30943 slave.cpp:192] Flags at startup:
> --appc_store_dir="/tmp/mesos/store/appc" --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/ContentType_SchedulerTest_Suppress_1_MuNt5t/credential"
> --default_role="*" --disk_watch_interval="1mins" --docker="docker"
> --docker_kill_orphans="true"
> --docker_local_archives_dir="/tmp/mesos/images/docker"
> --docker_puller="local" --docker_remove_delay="6hrs"
> --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns"
> --docker_store_dir="/tmp/mesos/store/docker"
> --enforce_container_disk_quota="false"
> --executor_registration_timeout="1mins"
> --executor_shutdown_grace_period="5secs"
> --fetcher_cache_dir="/tmp/ContentType_SchedulerTest_Suppress_1_MuNt5t/fetch"
> --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks"
> --gc_disk_headroom="0.1" --hadoop_home="" --help="false"
> --hostname_lookup="true" --image_provisioner_backend="copy"
> --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem"
> --launcher_dir="/mesos/mesos-0.26.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_runtime_directory="/run/systemd/system" --version="false"
> --work_dir="/tmp/ContentType_SchedulerTest_Suppress_1_MuNt5t"
> I1021 19:17:43.195694 30943 credentials.hpp:85] Loading credential for
> authentication from
> '/tmp/ContentType_SchedulerTest_Suppress_1_MuNt5t/credential'
> I1021 19:17:43.195986 30943 slave.cpp:322] Slave using credential for:
> test-principal
> I1021 19:17:43.196172 30920 scheduler.cpp:156] Version: 0.26.0
> I1021 19:17:43.196632 30943 slave.cpp:392] Slave resources: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I1021 19:17:43.196708 30943 slave.cpp:400] Slave attributes: [ ]
> I1021 19:17:43.196720 30943 slave.cpp:405] Slave hostname: 79d8015cd9f0
> I1021 19:17:43.196727 30943 slave.cpp:410] Slave checkpoint: true
> I1021 19:17:43.198149 30945 state.cpp:54] Recovering state from
> '/tmp/ContentType_SchedulerTest_Suppress_1_MuNt5t/meta'
> I1021 19:17:43.198578 30945 status_update_manager.cpp:202] Recovering status
> update manager
> I1021 19:17:43.198750 30945 containerizer.cpp:385] Recovering containerizer
> I1021 19:17:43.199414 30951 scheduler.cpp:238] New master detected at
> master@172.17.3.153:57838
> I1021 19:17:43.200877 30947 scheduler.cpp:300] Sending SUBSCRIBE call to
> master@172.17.3.153:57838
> I1021 19:17:43.200989 30945 slave.cpp:4222] Finished recovery
> I1021 19:17:43.202597 30945 slave.cpp:4379] Querying resource estimator for
> oversubscribable resources
> I1021 19:17:43.203027 30941 slave.cpp:4393] Received oversubscribable
> resources from the resource estimator
> I1021 19:17:43.203382 30945 slave.cpp:726] New master detected at
> master@172.17.3.153:57838
> I1021 19:17:43.203701 30945 slave.cpp:789] Authenticating with master
> master@172.17.3.153:57838
> I1021 19:17:43.203830 30945 slave.cpp:794] Using default CRAM-MD5
> authenticatee
> I1021 19:17:43.203766 30947 process.cpp:3078] Handling HTTP event for process
> 'master' with path: '/master/api/v1/scheduler'
> I1021 19:17:43.203546 30951 status_update_manager.cpp:176] Pausing sending
> status updates
> I1021 19:17:43.204018 30945 slave.cpp:762] Detecting new master
> I1021 19:17:43.204095 30939 authenticatee.cpp:115] Creating new client SASL
> connection
> I1021 19:17:43.204100 30947 http.cpp:338] HTTP POST for
> /master/api/v1/scheduler from 172.17.3.153:46875
> I1021 19:17:43.204498 30947 master.cpp:1871] Received subscription request
> for HTTP framework 'default'
> I1021 19:17:43.204592 30947 master.cpp:1648] Authorizing framework principal
> 'test-principal' to receive offers for role '*'
> I1021 19:17:43.204988 30947 master.cpp:5144] Authenticating
> slave(355)@172.17.3.153:57838
> I1021 19:17:43.205153 30951 authenticator.cpp:407] Starting authentication
> session for crammd5_authenticatee(766)@172.17.3.153:57838
> I1021 19:17:43.208039 30946 authenticator.cpp:92] Creating new server SASL
> connection
> I1021 19:17:43.209027 30939 authenticatee.cpp:206] Received SASL
> authentication mechanisms: CRAM-MD5
> I1021 19:17:43.209064 30939 authenticatee.cpp:232] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I1021 19:17:43.214236 30946 authenticator.cpp:197] Received SASL
> authentication start
> I1021 19:17:43.214387 30946 authenticator.cpp:319] Authentication requires
> more steps
> I1021 19:17:43.214680 30946 authenticatee.cpp:252] Received SASL
> authentication step
> I1021 19:17:43.214803 30946 authenticator.cpp:225] Received SASL
> authentication step
> I1021 19:17:43.214943 30946 auxprop.cpp:102] Request to lookup properties for
> user: 'test-principal' realm: '79d8015cd9f0' server FQDN: '79d8015cd9f0'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I1021 19:17:43.215086 30946 auxprop.cpp:174] Looking up auxiliary property
> '*userPassword'
> I1021 19:17:43.215250 30946 auxprop.cpp:174] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I1021 19:17:43.215385 30946 auxprop.cpp:102] Request to lookup properties for
> user: 'test-principal' realm: '79d8015cd9f0' server FQDN: '79d8015cd9f0'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I1021 19:17:43.215488 30946 auxprop.cpp:124] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I1021 19:17:43.215611 30946 auxprop.cpp:124] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I1021 19:17:43.215739 30946 authenticator.cpp:311] Authentication success
> I1021 19:17:43.216043 30946 authenticator.cpp:425] Authentication session
> cleanup for crammd5_authenticatee(766)@172.17.3.153:57838
> I1021 19:17:43.216740 30947 master.cpp:1963] Subscribing framework 'default'
> with checkpointing disabled and capabilities [ ]
> I1021 19:17:43.216050 30953 authenticatee.cpp:292] Authentication success
> I1021 19:17:43.219017 30953 hierarchical.cpp:185] Added framework
> 242dc5ed-402d-4873-be6d-9bad1f3296f9-0000
> I1021 19:17:43.219091 30953 hierarchical.cpp:952] No resources available to
> allocate!
> I1021 19:17:43.219135 30953 hierarchical.cpp:1045] No inverse offers to send
> out!
> I1021 19:17:43.219159 30953 hierarchical.cpp:851] Performed allocation for 0
> slaves in 109115ns
> I1021 19:17:43.219187 30953 master.hpp:1436] Sending heartbeat to
> 242dc5ed-402d-4873-be6d-9bad1f3296f9-0000
> I1021 19:17:43.219491 30950 slave.cpp:857] Successfully authenticated with
> master master@172.17.3.153:57838
> I1021 19:17:43.220130 30950 slave.cpp:1251] Will retry registration in
> 10.860994ms if necessary
> I1021 19:17:43.223247 30950 scheduler.cpp:459] Enqueuing event SUBSCRIBED
> received from master@172.17.3.153:57838
> I1021 19:17:43.225275 30950 scheduler.cpp:459] Enqueuing event HEARTBEAT
> received from master@172.17.3.153:57838
> I1021 19:17:43.225968 30950 master_maintenance_tests.cpp:179] Ignoring
> HEARTBEAT event
> I1021 19:17:43.226428 30947 master.cpp:5174] Successfully authenticated
> principal 'test-principal' at slave(355)@172.17.3.153:57838
> I1021 19:17:43.226799 30947 master.cpp:3868] Registering slave at
> slave(355)@172.17.3.153:57838 (79d8015cd9f0) with id
> 242dc5ed-402d-4873-be6d-9bad1f3296f9-S0
> I1021 19:17:43.228605 30946 registrar.cpp:441] Applied 1 operations in
> 88549ns; attempting to update the 'registry'
> I1021 19:17:43.229575 30949 log.cpp:685] Attempting to append 345 bytes to
> the log
> I1021 19:17:43.229738 30948 coordinator.cpp:341] Coordinator attempting to
> write APPEND action at position 3
> I1021 19:17:43.232003 30948 replica.cpp:512] Replica received write request
> for position 3 from (10132)@172.17.3.153:57838
> I1021 19:17:43.232977 30948 leveldb.cpp:343] Persisting action (364 bytes) to
> leveldb took 923453ns
> I1021 19:17:43.233007 30948 replica.cpp:683] Persisted action at 3
> I1021 19:17:43.233093 30951 slave.cpp:1251] Will retry registration in
> 5.810029ms if necessary
> I1021 19:17:43.233362 30951 master.cpp:3856] Ignoring register slave message
> from slave(355)@172.17.3.153:57838 (79d8015cd9f0) as admission is already in
> progress
> I1021 19:17:43.234104 30943 replica.cpp:662] Replica received learned notice
> for position 3 from @0.0.0.0:0
> I1021 19:17:43.234513 30943 leveldb.cpp:343] Persisting action (366 bytes) to
> leveldb took 375576ns
> I1021 19:17:43.234537 30943 replica.cpp:683] Persisted action at 3
> I1021 19:17:43.234560 30943 replica.cpp:668] Replica learned APPEND action at
> position 3
> I1021 19:17:43.236737 30948 registrar.cpp:486] Successfully updated the
> 'registry' in 8.048128ms
> I1021 19:17:43.236984 30953 log.cpp:704] Attempting to truncate the log to 3
> I1021 19:17:43.237198 30953 coordinator.cpp:341] Coordinator attempting to
> write TRUNCATE action at position 4
> I1021 19:17:43.237706 30948 master.cpp:3936] Registered slave
> 242dc5ed-402d-4873-be6d-9bad1f3296f9-S0 at slave(355)@172.17.3.153:57838
> (79d8015cd9f0) with cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000]
> I1021 19:17:43.237839 30948 slave.cpp:3212] Received ping from
> slave-observer(341)@172.17.3.153:57838
> I1021 19:17:43.237998 30948 slave.cpp:901] Registered with master
> master@172.17.3.153:57838; given slave ID
> 242dc5ed-402d-4873-be6d-9bad1f3296f9-S0
> I1021 19:17:43.238001 30953 hierarchical.cpp:335] Added slave
> 242dc5ed-402d-4873-be6d-9bad1f3296f9-S0 (79d8015cd9f0) with cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
> I1021 19:17:43.238742 30953 hierarchical.cpp:1045] No inverse offers to send
> out!
> I1021 19:17:43.238787 30953 hierarchical.cpp:867] Performed allocation for
> slave 242dc5ed-402d-4873-be6d-9bad1f3296f9-S0 in 741106ns
> I1021 19:17:43.239154 30946 master.cpp:4973] Sending 1 offers to framework
> 242dc5ed-402d-4873-be6d-9bad1f3296f9-0000 (default)
> I1021 19:17:43.239403 30942 replica.cpp:512] Replica received write request
> for position 4 from (10133)@172.17.3.153:57838
> I1021 19:17:43.238023 30948 fetcher.cpp:79] Clearing fetcher cache
> I1021 19:17:43.239969 30942 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 522312ns
> I1021 19:17:43.240000 30942 replica.cpp:683] Persisted action at 4
> I1021 19:17:43.240113 30943 status_update_manager.cpp:183] Resuming sending
> status updates
> I1021 19:17:43.240196 30948 slave.cpp:924] Checkpointing SlaveInfo to
> '/tmp/ContentType_SchedulerTest_Suppress_1_MuNt5t/meta/slaves/242dc5ed-402d-4873-be6d-9bad1f3296f9-S0/slave.info'
> I1021 19:17:43.241015 30948 slave.cpp:960] Forwarding total oversubscribed
> resources
> I1021 19:17:43.241464 30943 replica.cpp:662] Replica received learned notice
> for position 4 from @0.0.0.0:0
> I1021 19:17:43.241564 30948 master.cpp:4278] Received update of slave
> 242dc5ed-402d-4873-be6d-9bad1f3296f9-S0 at slave(355)@172.17.3.153:57838
> (79d8015cd9f0) with total oversubscribed resources
> I1021 19:17:43.241904 30948 hierarchical.cpp:391] Slave
> 242dc5ed-402d-4873-be6d-9bad1f3296f9-S0 (79d8015cd9f0) updated with
> oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000])
> I1021 19:17:43.243401 30948 hierarchical.cpp:952] No resources available to
> allocate!
> I1021 19:17:43.243451 30948 hierarchical.cpp:1045] No inverse offers to send
> out!
> I1021 19:17:43.243479 30948 hierarchical.cpp:867] Performed allocation for
> slave 242dc5ed-402d-4873-be6d-9bad1f3296f9-S0 in 498910ns
> I1021 19:17:43.243829 30942 scheduler.cpp:459] Enqueuing event OFFERS
> received from master@172.17.3.153:57838
> I1021 19:17:43.244977 30943 leveldb.cpp:343] Persisting action (18 bytes) to
> leveldb took 3.480521ms
> I1021 19:17:43.245064 30943 leveldb.cpp:401] Deleting ~2 keys from leveldb
> took 52965ns
> I1021 19:17:43.245084 30943 replica.cpp:683] Persisted action at 4
> I1021 19:17:43.245111 30943 replica.cpp:668] Replica learned TRUNCATE action
> at position 4
> I1021 19:17:43.247225 30941 scheduler.cpp:300] Sending DECLINE call to
> master@172.17.3.153:57838
> I1021 19:17:43.249984 30954 process.cpp:3078] Handling HTTP event for process
> 'master' with path: '/master/api/v1/scheduler'
> I1021 19:17:43.250172 30954 http.cpp:338] HTTP POST for
> /master/api/v1/scheduler from 172.17.3.153:46876
> I1021 19:17:43.250521 30954 master.cpp:3306] Processing DECLINE call for
> offers: [ 242dc5ed-402d-4873-be6d-9bad1f3296f9-O0 ] for framework
> 242dc5ed-402d-4873-be6d-9bad1f3296f9-0000 (default)
> I1021 19:17:43.251798 30954 hierarchical.cpp:739] Recovered cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on slave
> 242dc5ed-402d-4873-be6d-9bad1f3296f9-S0 from framework
> 242dc5ed-402d-4873-be6d-9bad1f3296f9-0000
> I1021 19:17:43.251868 30954 hierarchical.cpp:776] Framework
> 242dc5ed-402d-4873-be6d-9bad1f3296f9-0000 filtered slave
> 242dc5ed-402d-4873-be6d-9bad1f3296f9-S0 for 1hrs
> I1021 19:17:43.254041 30939 scheduler.cpp:300] Sending SUPPRESS call to
> master@172.17.3.153:57838
> I1021 19:17:43.255121 30950 slave.cpp:4379] Querying resource estimator for
> oversubscribable resources
> I1021 19:17:43.255394 30950 slave.cpp:3248] No pings from master received
> within 75secs
> I1021 19:17:43.255556 30950 slave.cpp:4038] Current disk usage 7.11%. Max
> allowed age: 5.802229041383391days
> I1021 19:17:43.255671 30950 master.hpp:1436] Sending heartbeat to
> 242dc5ed-402d-4873-be6d-9bad1f3296f9-0000
> I1021 19:17:43.255695 30939 hierarchical.cpp:1045] No inverse offers to send
> out!
> I1021 19:17:43.255738 30939 hierarchical.cpp:851] Performed allocation for 1
> slaves in 956377ns
> I1021 19:17:43.256590 30954 master.cpp:4973] Sending 1 offers to framework
> 242dc5ed-402d-4873-be6d-9bad1f3296f9-0000 (default)
> I1021 19:17:43.257079 30950 slave.cpp:3212] Received ping from
> slave-observer(341)@172.17.3.153:57838
> I1021 19:17:43.257279 30950 slave.cpp:4393] Received oversubscribable
> resources from the resource estimator
> I1021 19:17:43.258214 30945 scheduler.cpp:459] Enqueuing event HEARTBEAT
> received from master@172.17.3.153:57838
> I1021 19:17:43.259373 30946 master_maintenance_tests.cpp:179] Ignoring
> HEARTBEAT event
> I1021 19:17:43.259476 30950 slave.cpp:715] Re-detecting master
> I1021 19:17:43.259500 30950 slave.cpp:762] Detecting new master
> I1021 19:17:43.259547 30946 status_update_manager.cpp:176] Pausing sending
> status updates
> I1021 19:17:43.260365 30954 process.cpp:3078] Handling HTTP event for process
> 'master' with path: '/master/api/v1/scheduler'
> I1021 19:17:43.260648 30950 slave.cpp:726] New master detected at
> master@172.17.3.153:57838
> I1021 19:17:43.260707 30950 slave.cpp:789] Authenticating with master
> master@172.17.3.153:57838
> I1021 19:17:43.260732 30950 slave.cpp:794] Using default CRAM-MD5
> authenticatee
> I1021 19:17:43.260923 30950 slave.cpp:762] Detecting new master
> I1021 19:17:43.261015 30954 http.cpp:338] HTTP POST for
> /master/api/v1/scheduler from 172.17.3.153:46877
> I1021 19:17:43.260979 30939 status_update_manager.cpp:176] Pausing sending
> status updates
> I1021 19:17:43.261217 30954 master.cpp:2638] Processing SUPPRESS call for
> framework 242dc5ed-402d-4873-be6d-9bad1f3296f9-0000 (default)
> I1021 19:17:43.261339 30950 hierarchical.cpp:811] Suppressed offers for
> framework 242dc5ed-402d-4873-be6d-9bad1f3296f9-0000
> I1021 19:17:43.261993 30951 authenticatee.cpp:115] Creating new client SASL
> connection
> I1021 19:17:43.262704 30954 master.cpp:5144] Authenticating
> slave(355)@172.17.3.153:57838
> I1021 19:17:43.263375 30942 authenticator.cpp:407] Starting authentication
> session for crammd5_authenticatee(767)@172.17.3.153:57838
> I1021 19:17:43.263804 30942 authenticator.cpp:92] Creating new server SASL
> connection
> I1021 19:17:43.264616 30954 scheduler.cpp:459] Enqueuing event OFFERS
> received from master@172.17.3.153:57838
> I1021 19:17:43.266490 30942 authenticatee.cpp:206] Received SASL
> authentication mechanisms: CRAM-MD5
> I1021 19:17:43.266536 30942 authenticatee.cpp:232] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I1021 19:17:43.266654 30941 authenticator.cpp:197] Received SASL
> authentication start
> I1021 19:17:43.266738 30941 authenticator.cpp:319] Authentication requires
> more steps
> I1021 19:17:43.266836 30941 authenticatee.cpp:252] Received SASL
> authentication step
> I1021 19:17:43.267122 30941 authenticator.cpp:225] Received SASL
> authentication step
> I1021 19:17:43.267158 30941 auxprop.cpp:102] Request to lookup properties for
> user: 'test-principal' realm: '79d8015cd9f0' server FQDN: '79d8015cd9f0'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I1021 19:17:43.267170 30941 auxprop.cpp:174] Looking up auxiliary property
> '*userPassword'
> I1021 19:17:43.267220 30941 auxprop.cpp:174] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I1021 19:17:43.267249 30941 auxprop.cpp:102] Request to lookup properties for
> user: 'test-principal' realm: '79d8015cd9f0' server FQDN: '79d8015cd9f0'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I1021 19:17:43.267261 30941 auxprop.cpp:124] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I1021 19:17:43.267268 30941 auxprop.cpp:124] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I1021 19:17:43.267287 30941 authenticator.cpp:311] Authentication success
> I1021 19:17:43.267400 30954 authenticatee.cpp:292] Authentication success
> I1021 19:17:43.267452 30945 master.cpp:5174] Successfully authenticated
> principal 'test-principal' at slave(355)@172.17.3.153:57838
> I1021 19:17:43.267523 30939 authenticator.cpp:425] Authentication session
> cleanup for crammd5_authenticatee(767)@172.17.3.153:57838
> I1021 19:17:43.267814 30954 slave.cpp:857] Successfully authenticated with
> master master@172.17.3.153:57838
> I1021 19:17:43.268054 30954 slave.cpp:1251] Will retry registration in
> 18.375612ms if necessary
> I1021 19:17:43.268355 30954 master.cpp:4028] Re-registering slave
> 242dc5ed-402d-4873-be6d-9bad1f3296f9-S0 at slave(355)@172.17.3.153:57838
> (79d8015cd9f0)
> I1021 19:17:43.268550 30954 master.cpp:4216] Sending updated checkpointed
> resources to slave 242dc5ed-402d-4873-be6d-9bad1f3296f9-S0 at
> slave(355)@172.17.3.153:57838 (79d8015cd9f0)
> I1021 19:17:43.268687 30954 slave.cpp:1001] Re-registered with master
> master@172.17.3.153:57838
> I1021 19:17:43.268806 30954 slave.cpp:1037] Forwarding total oversubscribed
> resources
> I1021 19:17:43.268983 30949 status_update_manager.cpp:183] Resuming sending
> status updates
> I1021 19:17:43.269088 30949 master.cpp:4278] Received update of slave
> 242dc5ed-402d-4873-be6d-9bad1f3296f9-S0 at slave(355)@172.17.3.153:57838
> (79d8015cd9f0) with total oversubscribed resources
> I1021 19:17:43.269444 30949 hierarchical.cpp:391] Slave
> 242dc5ed-402d-4873-be6d-9bad1f3296f9-S0 (79d8015cd9f0) updated with
> oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000])
> I1021 19:17:43.269820 30949 hierarchical.cpp:952] No resources available to
> allocate!
> I1021 19:17:43.269876 30949 hierarchical.cpp:1045] No inverse offers to send
> out!
> I1021 19:17:43.269903 30949 hierarchical.cpp:867] Performed allocation for
> slave 242dc5ed-402d-4873-be6d-9bad1f3296f9-S0 in 407598ns
> I1021 19:17:43.270341 30954 slave.cpp:2284] Updated checkpointed resources
> from to
> ../../src/tests/scheduler_tests.cpp:1028: Failure
> Value of: event.isPending()
> Actual: false
> Expected: true
> I1021 19:17:43.276475 30920 master.cpp:925] Master terminating
> I1021 19:17:43.276880 30949 hierarchical.cpp:364] Removed slave
> 242dc5ed-402d-4873-be6d-9bad1f3296f9-S0
> I1021 19:17:43.277751 30945 hierarchical.cpp:220] Removed framework
> 242dc5ed-402d-4873-be6d-9bad1f3296f9-0000
> I1021 19:17:43.277863 30941 slave.cpp:3258] master@172.17.3.153:57838 exited
> W1021 19:17:43.277899 30941 slave.cpp:3261] Master disconnected! Waiting for
> a new master to be elected
> I1021 19:17:43.303658 30920 slave.cpp:606] Slave terminating
> [ FAILED ] ContentType/SchedulerTest.Suppress/1, where GetParam() =
> application/json (172 ms)
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
