You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Zhitao Li (JIRA)" <ji...@apache.org> on 2016/07/08 18:49:11 UTC
[jira] [Created] (MESOS-5812) MasterAPITest.Subscribe is flaky
Zhitao Li created MESOS-5812:
--------------------------------
Summary: MasterAPITest.Subscribe is flaky
Key: MESOS-5812
URL: https://issues.apache.org/jira/browse/MESOS-5812
Project: Mesos
Issue Type: Bug
Components: tests
Environment: mac os X
centos 7
Reporter: Zhitao Li
This test seems to be flaky, although on Mac OS X and CentOS 7 the error a bit different.
On Mac OS X:
{noformat}
[==========] Running 2 tests from 1 test case.
[----------] Global test environment set-up.
[----------] 2 tests from ContentType/MasterAPITest
[ RUN ] ContentType/MasterAPITest.Subscribe/0
I0708 11:43:18.712148 1927435008 cluster.cpp:155] Creating default 'local' authorizer
I0708 11:43:18.715232 1927435008 leveldb.cpp:174] Opened db in 2825us
I0708 11:43:18.715919 1927435008 leveldb.cpp:181] Compacted db in 623us
I0708 11:43:18.715968 1927435008 leveldb.cpp:196] Created db iterator in 16us
I0708 11:43:18.715994 1927435008 leveldb.cpp:202] Seeked to beginning of db in 13us
I0708 11:43:18.716038 1927435008 leveldb.cpp:271] Iterated through 0 keys in the db in 16us
I0708 11:43:18.716107 1927435008 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0708 11:43:18.716706 351518720 recover.cpp:451] Starting replica recovery
I0708 11:43:18.716948 351518720 recover.cpp:477] Replica is in EMPTY status
I0708 11:43:18.719182 349372416 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (3836)@127.0.0.1:50325
I0708 11:43:18.719526 349908992 master.cpp:382] Master 538a2836-92eb-4eae-85bb-4fb1a1e3b830 (localhost) started on 127.0.0.1:50325
I0708 11:43:18.719614 348299264 recover.cpp:197] Received a recover response from a replica in EMPTY status
I0708 11:43:18.719593 349908992 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="/private/tmp/phLdfh/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="/usr/local/share/mesos/webui" --work_dir="/private/tmp/phLdfh/master" --zk_session_timeout="10secs"
W0708 11:43:18.720010 349908992 master.cpp:387]
**************************************************
Master bound to loopback interface! Cannot communicate with remote schedulers or agents. You might want to set '--ip' flag to a routable IP address.
**************************************************
I0708 11:43:18.720057 349908992 master.cpp:434] Master only allowing authenticated frameworks to register
I0708 11:43:18.720069 349908992 master.cpp:448] Master only allowing authenticated agents to register
I0708 11:43:18.720079 349908992 master.cpp:461] Master only allowing authenticated HTTP frameworks to register
I0708 11:43:18.720089 349908992 credentials.hpp:37] Loading credentials for authentication from '/private/tmp/phLdfh/credentials'
I0708 11:43:18.720237 350982144 recover.cpp:568] Updating replica status to STARTING
I0708 11:43:18.720361 349908992 master.cpp:506] Using default 'crammd5' authenticator
I0708 11:43:18.720690 351518720 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 296us
I0708 11:43:18.720743 351518720 replica.cpp:320] Persisted replica status to STARTING
I0708 11:43:18.720746 349908992 master.cpp:578] Using default 'basic' HTTP authenticator
I0708 11:43:18.720927 349908992 master.cpp:658] Using default 'basic' HTTP framework authenticator
I0708 11:43:18.720979 350982144 recover.cpp:477] Replica is in STARTING status
I0708 11:43:18.721082 349908992 master.cpp:705] Authorization enabled
I0708 11:43:18.722473 349372416 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (3839)@127.0.0.1:50325
I0708 11:43:18.722820 349372416 recover.cpp:197] Received a recover response from a replica in STARTING status
I0708 11:43:18.723244 352055296 recover.cpp:568] Updating replica status to VOTING
I0708 11:43:18.723666 352055296 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 243us
I0708 11:43:18.723706 349372416 master.cpp:1973] The newly elected leader is master@127.0.0.1:50325 with id 538a2836-92eb-4eae-85bb-4fb1a1e3b830
I0708 11:43:18.723716 352055296 replica.cpp:320] Persisted replica status to VOTING
I0708 11:43:18.723742 349372416 master.cpp:1986] Elected as the leading master!
I0708 11:43:18.723798 349372416 master.cpp:1673] Recovering from registrar
I0708 11:43:18.723839 352055296 recover.cpp:582] Successfully joined the Paxos group
I0708 11:43:18.723889 348299264 registrar.cpp:332] Recovering registrar
I0708 11:43:18.724098 352055296 recover.cpp:466] Recover process terminated
I0708 11:43:18.724416 349372416 log.cpp:553] Attempting to start the writer
I0708 11:43:18.726004 351518720 replica.cpp:493] Replica received implicit promise request from (3840)@127.0.0.1:50325 with proposal 1
I0708 11:43:18.727088 351518720 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 835us
I0708 11:43:18.727145 351518720 replica.cpp:342] Persisted promised to 1
I0708 11:43:18.727679 350445568 coordinator.cpp:238] Coordinator attempting to fill missing positions
I0708 11:43:18.728906 350445568 replica.cpp:388] Replica received explicit promise request from (3841)@127.0.0.1:50325 for position 0 with proposal 2
I0708 11:43:18.729410 350445568 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 410us
I0708 11:43:18.729449 350445568 replica.cpp:712] Persisted action at 0
I0708 11:43:18.730459 349908992 replica.cpp:537] Replica received write request for position 0 from (3842)@127.0.0.1:50325
I0708 11:43:18.730510 349908992 leveldb.cpp:436] Reading position from leveldb took 28us
I0708 11:43:18.730722 349908992 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 194us
I0708 11:43:18.730756 349908992 replica.cpp:712] Persisted action at 0
I0708 11:43:18.731245 350445568 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
I0708 11:43:18.731382 350445568 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 123us
I0708 11:43:18.731415 350445568 replica.cpp:712] Persisted action at 0
I0708 11:43:18.731432 350445568 replica.cpp:697] Replica learned NOP action at position 0
I0708 11:43:18.731961 350982144 log.cpp:569] Writer started with ending position 0
I0708 11:43:18.732535 348299264 leveldb.cpp:436] Reading position from leveldb took 32us
I0708 11:43:18.732974 351518720 registrar.cpp:365] Successfully fetched the registry (0B) in 9.058048ms
I0708 11:43:18.733052 351518720 registrar.cpp:464] Applied 1 operations in 18us; attempting to update the 'registry'
I0708 11:43:18.733386 350445568 log.cpp:577] Attempting to append 159 bytes to the log
I0708 11:43:18.733485 349372416 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
I0708 11:43:18.733944 348835840 replica.cpp:537] Replica received write request for position 1 from (3843)@127.0.0.1:50325
I0708 11:43:18.734143 348835840 leveldb.cpp:341] Persisting action (178 bytes) to leveldb took 178us
I0708 11:43:18.734171 348835840 replica.cpp:712] Persisted action at 1
I0708 11:43:18.734509 349908992 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
I0708 11:43:18.736917 349908992 leveldb.cpp:341] Persisting action (180 bytes) to leveldb took 2406us
I0708 11:43:18.736989 349908992 replica.cpp:712] Persisted action at 1
I0708 11:43:18.737013 349908992 replica.cpp:697] Replica learned APPEND action at position 1
I0708 11:43:18.737725 348835840 registrar.cpp:509] Successfully updated the 'registry' in 4.623872ms
I0708 11:43:18.737812 348835840 registrar.cpp:395] Successfully recovered registrar
I0708 11:43:18.737905 348299264 log.cpp:596] Attempting to truncate the log to 1
I0708 11:43:18.738055 349908992 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
I0708 11:43:18.738200 352055296 master.cpp:1781] Recovered 0 agents from the Registry (121B) ; allowing 10mins for agents to re-register
I0708 11:43:18.738800 350982144 replica.cpp:537] Replica received write request for position 2 from (3844)@127.0.0.1:50325
I0708 11:43:18.739012 350982144 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 188us
I0708 11:43:18.739039 350982144 replica.cpp:712] Persisted action at 2
I0708 11:43:18.739459 351518720 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
I0708 11:43:18.739600 351518720 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 124us
I0708 11:43:18.739645 351518720 leveldb.cpp:399] Deleting ~1 keys from leveldb took 24us
I0708 11:43:18.739667 351518720 replica.cpp:712] Persisted action at 2
I0708 11:43:18.739686 351518720 replica.cpp:697] Replica learned TRUNCATE action at position 2
I0708 11:43:18.754873 1927435008 cluster.cpp:432] Creating default 'local' authorizer
I0708 11:43:18.756405 349372416 slave.cpp:205] Agent started on 121)@127.0.0.1:50325
I0708 11:43:18.756476 349372416 slave.cpp:206] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="true" --authenticatee="crammd5" --authentication_backoff_factor="1secs" --authorizer="local" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/var/folders/ny/tcvyblqj43s2gdh2_895v9nw0000gp/T/ContentType_MasterAPITest_Subscribe_0_1rRAL2/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="/var/folders/ny/tcvyblqj43s2gdh2_895v9nw0000gp/T/ContentType_MasterAPITest_Subscribe_0_1rRAL2/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_command_executor="false" --http_credentials="/var/folders/ny/tcvyblqj43s2gdh2_895v9nw0000gp/T/ContentType_MasterAPITest_Subscribe_0_1rRAL2/http_credentials" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/Users/zhitao/Uber/sync/zhitao-mesos1.dev.uber.com/home/uber/mesos/build/src" --logbufsecs="0" --logging_level="INFO" --oversubscribed_resources_interval="15secs" --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --version="false" --work_dir="/var/folders/ny/tcvyblqj43s2gdh2_895v9nw0000gp/T/ContentType_MasterAPITest_Subscribe_0_1rRAL2"
W0708 11:43:18.756916 349372416 slave.cpp:209]
**************************************************
Agent bound to loopback interface! Cannot communicate with remote master(s). You might want to set '--ip' flag to a routable IP address.
**************************************************
I0708 11:43:18.756934 349372416 credentials.hpp:86] Loading credential for authentication from '/var/folders/ny/tcvyblqj43s2gdh2_895v9nw0000gp/T/ContentType_MasterAPITest_Subscribe_0_1rRAL2/credential'
W0708 11:43:18.757009 1927435008 scheduler.cpp:157]
**************************************************
Scheduler driver bound to loopback interface! Cannot communicate with remote master(s). You might want to set 'LIBPROCESS_IP' environment variable to use a routable IP address.
**************************************************
I0708 11:43:18.757031 1927435008 scheduler.cpp:172] Version: 1.0.0
I0708 11:43:18.757195 349372416 slave.cpp:343] Agent using credential for: test-principal
I0708 11:43:18.757236 349372416 credentials.hpp:37] Loading credentials for authentication from '/var/folders/ny/tcvyblqj43s2gdh2_895v9nw0000gp/T/ContentType_MasterAPITest_Subscribe_0_1rRAL2/http_credentials'
I0708 11:43:18.757520 349372416 slave.cpp:395] Using default 'basic' HTTP authenticator
I0708 11:43:18.758111 348835840 scheduler.cpp:461] New master detected at master@127.0.0.1:50325
I0708 11:43:18.758543 349372416 slave.cpp:594] Agent resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0708 11:43:18.758613 349372416 slave.cpp:602] Agent attributes: [ ]
I0708 11:43:18.758627 349372416 slave.cpp:607] Agent hostname: localhost
I0708 11:43:18.759907 349372416 state.cpp:57] Recovering state from '/var/folders/ny/tcvyblqj43s2gdh2_895v9nw0000gp/T/ContentType_MasterAPITest_Subscribe_0_1rRAL2/meta'
I0708 11:43:18.760282 348299264 status_update_manager.cpp:200] Recovering status update manager
I0708 11:43:18.760668 350982144 slave.cpp:4856] Finished recovery
I0708 11:43:18.761791 348299264 slave.cpp:969] New master detected at master@127.0.0.1:50325
I0708 11:43:18.761795 349372416 status_update_manager.cpp:174] Pausing sending status updates
I0708 11:43:18.761838 348299264 slave.cpp:1028] Authenticating with master master@127.0.0.1:50325
I0708 11:43:18.761929 348299264 slave.cpp:1039] Using default CRAM-MD5 authenticatee
I0708 11:43:18.762065 348299264 slave.cpp:1001] Detecting new master
I0708 11:43:18.762116 349372416 authenticatee.cpp:121] Creating new client SASL connection
I0708 11:43:18.765058 349908992 http.cpp:381] HTTP POST for /master/api/v1/scheduler from 127.0.0.1:50932
I0708 11:43:18.765244 349908992 master.cpp:2272] Received subscription request for HTTP framework 'default'
I0708 11:43:18.765297 349908992 master.cpp:2012] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0708 11:43:18.765609 349908992 master.cpp:6006] Authenticating slave(121)@127.0.0.1:50325
I0708 11:43:18.765882 349908992 master.cpp:2370] Subscribing framework 'default' with checkpointing disabled and capabilities [ ]
I0708 11:43:18.766084 350445568 authenticator.cpp:98] Creating new server SASL connection
I0708 11:43:18.766309 350982144 hierarchical.cpp:271] Added framework 538a2836-92eb-4eae-85bb-4fb1a1e3b830-0000
I0708 11:43:18.769973 349372416 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0708 11:43:18.770043 349372416 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0708 11:43:18.770113 349372416 authenticator.cpp:204] Received SASL authentication start
I0708 11:43:18.770170 349372416 authenticator.cpp:326] Authentication requires more steps
I0708 11:43:18.770299 348299264 authenticatee.cpp:259] Received SASL authentication step
I0708 11:43:18.770464 348835840 authenticator.cpp:232] Received SASL authentication step
I0708 11:43:18.770514 348835840 authenticator.cpp:318] Authentication success
I0708 11:43:18.770613 352055296 authenticatee.cpp:299] Authentication success
I0708 11:43:18.770731 351518720 master.cpp:6036] Successfully authenticated principal 'test-principal' at slave(121)@127.0.0.1:50325
I0708 11:43:18.771021 348299264 slave.cpp:1123] Successfully authenticated with master master@127.0.0.1:50325
I0708 11:43:18.771534 350982144 master.cpp:4676] Registering agent at slave(121)@127.0.0.1:50325 (localhost) with id 538a2836-92eb-4eae-85bb-4fb1a1e3b830-S0
I0708 11:43:18.772023 348299264 registrar.cpp:464] Applied 1 operations in 59us; attempting to update the 'registry'
I0708 11:43:18.772625 350445568 log.cpp:577] Attempting to append 326 bytes to the log
I0708 11:43:18.772734 350982144 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3
I0708 11:43:18.773486 349372416 replica.cpp:537] Replica received write request for position 3 from (3854)@127.0.0.1:50325
I0708 11:43:18.773833 349372416 leveldb.cpp:341] Persisting action (345 bytes) to leveldb took 284us
I0708 11:43:18.773892 349372416 replica.cpp:712] Persisted action at 3
I0708 11:43:18.775391 349908992 replica.cpp:691] Replica received learned notice for position 3 from @0.0.0.0:0
I0708 11:43:18.776201 349908992 leveldb.cpp:341] Persisting action (347 bytes) to leveldb took 686us
I0708 11:43:18.776294 349908992 replica.cpp:712] Persisted action at 3
I0708 11:43:18.776326 349908992 replica.cpp:697] Replica learned APPEND action at position 3
I0708 11:43:18.779428 349372416 registrar.cpp:509] Successfully updated the 'registry' in 7.348992ms
I0708 11:43:18.779650 349372416 log.cpp:596] Attempting to truncate the log to 3
I0708 11:43:18.779717 349908992 master.cpp:4664] Ignoring register agent message from slave(121)@127.0.0.1:50325 (localhost) as admission is already in progress
I0708 11:43:18.779790 349372416 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4
I0708 11:43:18.780421 349908992 master.cpp:4745] Registered agent 538a2836-92eb-4eae-85bb-4fb1a1e3b830-S0 at slave(121)@127.0.0.1:50325 (localhost) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0708 11:43:18.780499 349372416 hierarchical.cpp:478] Added agent 538a2836-92eb-4eae-85bb-4fb1a1e3b830-S0 (localhost) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
I0708 11:43:18.780627 352055296 slave.cpp:1169] Registered with master master@127.0.0.1:50325; given agent ID 538a2836-92eb-4eae-85bb-4fb1a1e3b830-S0
I0708 11:43:18.780930 350445568 status_update_manager.cpp:181] Resuming sending status updates
I0708 11:43:18.781231 349908992 master.cpp:5835] Sending 1 offers to framework 538a2836-92eb-4eae-85bb-4fb1a1e3b830-0000 (default)
I0708 11:43:18.781726 352055296 slave.cpp:1229] Forwarding total oversubscribed resources
I0708 11:43:18.782104 350445568 replica.cpp:537] Replica received write request for position 4 from (3855)@127.0.0.1:50325
I0708 11:43:18.782253 348299264 master.cpp:5128] Received update of agent 538a2836-92eb-4eae-85bb-4fb1a1e3b830-S0 at slave(121)@127.0.0.1:50325 (localhost) with total oversubscribed resources
I0708 11:43:18.782299 350445568 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 167us
I0708 11:43:18.782332 350445568 replica.cpp:712] Persisted action at 4
I0708 11:43:18.782510 349908992 hierarchical.cpp:542] Agent 538a2836-92eb-4eae-85bb-4fb1a1e3b830-S0 (localhost) updated with oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000])
I0708 11:43:18.783447 348299264 replica.cpp:691] Replica received learned notice for position 4 from @0.0.0.0:0
I0708 11:43:18.783646 348299264 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 181us
I0708 11:43:18.783694 348299264 leveldb.cpp:399] Deleting ~2 keys from leveldb took 26us
I0708 11:43:18.783732 348299264 replica.cpp:712] Persisted action at 4
I0708 11:43:18.783749 348299264 replica.cpp:697] Replica learned TRUNCATE action at position 4
../../src/tests/api_tests.cpp:1464: Failure
(response).failure(): Disconnected
../../src/tests/api_tests.cpp:1465: Failure
(response).failure(): Disconnected
F0708 11:43:18.787530 1927435008 future.hpp:1107] Check failed: !isFailed() Future::get() but state == FAILED: Disconnected
*** Check failure stack trace: ***
@ 0x10e35adba google::LogMessage::Fail()
@ 0x10e359d47 google::LogMessage::SendToLog()
@ 0x10e35aa6a google::LogMessage::Flush()
@ 0x10e3618d8 google::LogMessageFatal::~LogMessageFatal()
@ 0x10e35b1f5 google::LogMessageFatal::~LogMessageFatal()
@ 0x106abf884 process::Future<>::get()
@ 0x106a76cea mesos::internal::tests::MasterAPITest_Subscribe_Test::TestBody()
@ 0x108465633 testing::internal::HandleSehExceptionsInMethodIfSupported<>()
@ 0x10844bf97 testing::internal::HandleExceptionsInMethodIfSupported<>()
@ 0x10840c485 testing::Test::Run()
@ 0x10840d9cb testing::TestInfo::Run()
@ 0x10840e667 testing::TestCase::Run()
@ 0x10841ce43 testing::internal::UnitTestImpl::RunAllTests()
@ 0x108468603 testing::internal::HandleSehExceptionsInMethodIfSupported<>()
@ 0x10844e3d7 testing::internal::HandleExceptionsInMethodIfSupported<>()
@ 0x10841ca40 testing::UnitTest::Run()
@ 0x107688731 RUN_ALL_TESTS()
@ 0x1076841df main
@ 0x7fff8dbc45c9 start
^C
zhitao@zhitao-C02NF090G3QT:~/Uber/sync/zhitao-mesos1.dev.uber.com/home/uber/mesos test_1.0.0-rc2
$ less /tmp/test.output
zhitao@zhitao-C02NF090G3QT:~/Uber/sync/zhitao-mesos1.dev.uber.com/home/uber/mesos test_1.0.0-rc2
$ less /tmp/test.output
I0708 11:43:03.572598 1927435008 master.cpp:1218] Master terminating
I0708 11:43:03.572844 352055296 hierarchical.cpp:510] Removed agent e055d60c-05ff-487e-82da-d0a43e52605c-S0
[ FAILED ] ContentType/MasterAPITest.Subscribe/0, where GetParam() = application/x-protobuf (15105 ms)
{noformat}
On CentOS 7
{noformat}
[ RUN ] ContentType/MasterAPITest.Subscribe/0
I0708 15:42:16.042171 29138 cluster.cpp:155] Creating default 'local' authorizer
I0708 15:42:16.154358 29138 leveldb.cpp:174] Opened db in 111.818825ms
I0708 15:42:16.197175 29138 leveldb.cpp:181] Compacted db in 42.714984ms
I0708 15:42:16.197293 29138 leveldb.cpp:196] Created db iterator in 32582ns
I0708 15:42:16.197324 29138 leveldb.cpp:202] Seeked to beginning of db in 4050ns
I0708 15:42:16.197343 29138 leveldb.cpp:271] Iterated through 0 keys in the db in 538ns
I0708 15:42:16.197417 29138 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0708 15:42:16.198655 29157 recover.cpp:451] Starting replica recovery
I0708 15:42:16.199364 29161 recover.cpp:477] Replica is in EMPTY status
I0708 15:42:16.200865 29161 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (16431)@172.17.0.3:34502
I0708 15:42:16.201282 29158 recover.cpp:197] Received a recover response from a replica in EMPTY status
I0708 15:42:16.203222 29160 recover.cpp:568] Updating replica status to STARTING
I0708 15:42:16.204633 29158 master.cpp:382] Master 2aea5b7f-ec9f-4fda-8f34-877d8adf064f (0382d073a49a) started on 172.17.0.3:34502
I0708 15:42:16.204675 29158 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/Lu916I/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.1.0/_inst/share/mesos/webui" --work_dir="/tmp/Lu916I/master" --zk_session_timeout="10secs"
I0708 15:42:16.205265 29158 master.cpp:434] Master only allowing authenticated frameworks to register
I0708 15:42:16.205283 29158 master.cpp:448] Master only allowing authenticated agents to register
I0708 15:42:16.205294 29158 master.cpp:461] Master only allowing authenticated HTTP frameworks to register
I0708 15:42:16.205307 29158 credentials.hpp:37] Loading credentials for authentication from '/tmp/Lu916I/credentials'
I0708 15:42:16.205705 29158 master.cpp:506] Using default 'crammd5' authenticator
I0708 15:42:16.205940 29158 master.cpp:578] Using default 'basic' HTTP authenticator
I0708 15:42:16.206192 29158 master.cpp:658] Using default 'basic' HTTP framework authenticator
I0708 15:42:16.206374 29158 master.cpp:705] Authorization enabled
I0708 15:42:16.206866 29172 hierarchical.cpp:151] Initialized hierarchical allocator process
I0708 15:42:16.207018 29172 whitelist_watcher.cpp:77] No whitelist given
I0708 15:42:16.210026 29165 master.cpp:1973] The newly elected leader is master@172.17.0.3:34502 with id 2aea5b7f-ec9f-4fda-8f34-877d8adf064f
I0708 15:42:16.210187 29165 master.cpp:1986] Elected as the leading master!
I0708 15:42:16.210330 29165 master.cpp:1673] Recovering from registrar
I0708 15:42:16.210577 29171 registrar.cpp:332] Recovering registrar
I0708 15:42:16.239378 29160 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 35.540287ms
I0708 15:42:16.239485 29160 replica.cpp:320] Persisted replica status to STARTING
I0708 15:42:16.239938 29161 recover.cpp:477] Replica is in STARTING status
I0708 15:42:16.242017 29165 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (16434)@172.17.0.3:34502
I0708 15:42:16.242527 29167 recover.cpp:197] Received a recover response from a replica in STARTING status
I0708 15:42:16.243140 29167 recover.cpp:568] Updating replica status to VOTING
I0708 15:42:16.281746 29167 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 38.318978ms
I0708 15:42:16.281828 29167 replica.cpp:320] Persisted replica status to VOTING
I0708 15:42:16.282094 29170 recover.cpp:582] Successfully joined the Paxos group
I0708 15:42:16.282440 29170 recover.cpp:466] Recover process terminated
I0708 15:42:16.283365 29170 log.cpp:553] Attempting to start the writer
I0708 15:42:16.285605 29167 replica.cpp:493] Replica received implicit promise request from (16435)@172.17.0.3:34502 with proposal 1
I0708 15:42:16.315435 29167 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 29.761608ms
I0708 15:42:16.315528 29167 replica.cpp:342] Persisted promised to 1
I0708 15:42:16.317147 29159 coordinator.cpp:238] Coordinator attempting to fill missing positions
I0708 15:42:16.318914 29160 replica.cpp:388] Replica received explicit promise request from (16436)@172.17.0.3:34502 for position 0 with proposal 2
I0708 15:42:16.348886 29160 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 29.896283ms
I0708 15:42:16.349161 29160 replica.cpp:712] Persisted action at 0
I0708 15:42:16.350939 29170 replica.cpp:537] Replica received write request for position 0 from (16437)@172.17.0.3:34502
I0708 15:42:16.351029 29170 leveldb.cpp:436] Reading position from leveldb took 42967ns
I0708 15:42:16.382378 29170 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 31.28917ms
I0708 15:42:16.382464 29170 replica.cpp:712] Persisted action at 0
I0708 15:42:16.383646 29169 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
I0708 15:42:16.415894 29169 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 32.189511ms
I0708 15:42:16.416015 29169 replica.cpp:712] Persisted action at 0
I0708 15:42:16.416056 29169 replica.cpp:697] Replica learned NOP action at position 0
I0708 15:42:16.417312 29168 log.cpp:569] Writer started with ending position 0
I0708 15:42:16.418628 29167 leveldb.cpp:436] Reading position from leveldb took 56748ns
I0708 15:42:16.420019 29165 registrar.cpp:365] Successfully fetched the registry (0B) in 209.31712ms
I0708 15:42:16.420155 29165 registrar.cpp:464] Applied 1 operations in 30566ns; attempting to update the 'registry'
I0708 15:42:16.420994 29172 log.cpp:577] Attempting to append 168 bytes to the log
I0708 15:42:16.421149 29157 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
I0708 15:42:16.422169 29162 replica.cpp:537] Replica received write request for position 1 from (16438)@172.17.0.3:34502
I0708 15:42:16.457743 29162 leveldb.cpp:341] Persisting action (187 bytes) to leveldb took 35.505294ms
I0708 15:42:16.457844 29162 replica.cpp:712] Persisted action at 1
I0708 15:42:16.459228 29172 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
I0708 15:42:16.495947 29172 leveldb.cpp:341] Persisting action (189 bytes) to leveldb took 36.653391ms
I0708 15:42:16.496048 29172 replica.cpp:712] Persisted action at 1
I0708 15:42:16.496091 29172 replica.cpp:697] Replica learned APPEND action at position 1
I0708 15:42:16.497947 29172 registrar.cpp:509] Successfully updated the 'registry' in 77.703936ms
I0708 15:42:16.498132 29172 registrar.cpp:395] Successfully recovered registrar
I0708 15:42:16.498169 29171 log.cpp:596] Attempting to truncate the log to 1
I0708 15:42:16.498294 29162 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
I0708 15:42:16.498668 29171 master.cpp:1781] Recovered 0 agents from the Registry (129B) ; allowing 10mins for agents to re-register
I0708 15:42:16.498919 29162 hierarchical.cpp:178] Skipping recovery of hierarchical allocator: nothing to recover
I0708 15:42:16.499577 29171 replica.cpp:537] Replica received write request for position 2 from (16439)@172.17.0.3:34502
I0708 15:42:16.521065 29171 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 21.423468ms
I0708 15:42:16.521160 29171 replica.cpp:712] Persisted action at 2
I0708 15:42:16.522766 29171 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
I0708 15:42:16.546223 29171 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 23.402601ms
I0708 15:42:16.546380 29171 leveldb.cpp:399] Deleting ~1 keys from leveldb took 70830ns
I0708 15:42:16.546411 29171 replica.cpp:712] Persisted action at 2
I0708 15:42:16.546445 29171 replica.cpp:697] Replica learned TRUNCATE action at position 2
I0708 15:42:16.560467 29138 cluster.cpp:432] Creating default 'local' authorizer
I0708 15:42:16.565003 29162 slave.cpp:205] Agent started on 449)@172.17.0.3:34502
I0708 15:42:16.565520 29138 scheduler.cpp:172] Version: 1.1.0
I0708 15:42:16.565150 29162 slave.cpp:206] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="true" --authenticatee="crammd5" --authentication_backoff_factor="1secs" --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/ContentType_MasterAPITest_Subscribe_0_be660M/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/ContentType_MasterAPITest_Subscribe_0_be660M/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/ContentType_MasterAPITest_Subscribe_0_be660M/http_credentials" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-1.1.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;gpus:0;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/ContentType_MasterAPITest_Subscribe_0_be660M"
I0708 15:42:16.566128 29162 credentials.hpp:86] Loading credential for authentication from '/tmp/ContentType_MasterAPITest_Subscribe_0_be660M/credential'
I0708 15:42:16.566423 29162 slave.cpp:343] Agent using credential for: test-principal
I0708 15:42:16.566520 29171 scheduler.cpp:461] New master detected at master@172.17.0.3:34502
I0708 15:42:16.566543 29162 credentials.hpp:37] Loading credentials for authentication from '/tmp/ContentType_MasterAPITest_Subscribe_0_be660M/http_credentials'
I0708 15:42:16.566557 29171 scheduler.cpp:470] Waiting for 0ns before initiating a re-(connection) attempt with the master
I0708 15:42:16.566838 29162 slave.cpp:395] Using default 'basic' HTTP authenticator
I0708 15:42:16.568023 29162 resources.cpp:572] Parsing resources as JSON failed: cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]
Trying semicolon-delimited string format instead
I0708 15:42:16.568527 29162 resources.cpp:572] Parsing resources as JSON failed: cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]
Trying semicolon-delimited string format instead
I0708 15:42:16.569443 29162 slave.cpp:594] Agent resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0708 15:42:16.569535 29162 slave.cpp:602] Agent attributes: [ ]
I0708 15:42:16.569552 29162 slave.cpp:607] Agent hostname: 0382d073a49a
I0708 15:42:16.571897 29165 state.cpp:57] Recovering state from '/tmp/ContentType_MasterAPITest_Subscribe_0_be660M/meta'
I0708 15:42:16.572376 29165 status_update_manager.cpp:200] Recovering status update manager
I0708 15:42:16.572638 29165 slave.cpp:4856] Finished recovery
I0708 15:42:16.573194 29165 slave.cpp:5028] Querying resource estimator for oversubscribable resources
I0708 15:42:16.574082 29165 slave.cpp:969] New master detected at master@172.17.0.3:34502
I0708 15:42:16.574111 29165 slave.cpp:1028] Authenticating with master master@172.17.0.3:34502
I0708 15:42:16.574174 29165 slave.cpp:1039] Using default CRAM-MD5 authenticatee
I0708 15:42:16.574213 29162 status_update_manager.cpp:174] Pausing sending status updates
I0708 15:42:16.574323 29165 slave.cpp:1001] Detecting new master
I0708 15:42:16.574525 29165 authenticatee.cpp:121] Creating new client SASL connection
I0708 15:42:16.574851 29160 slave.cpp:5042] Received oversubscribable resources from the resource estimator
I0708 15:42:16.575621 29164 scheduler.cpp:349] Connected with the master at http://172.17.0.3:34502/master/api/v1/scheduler
I0708 15:42:16.577546 29164 scheduler.cpp:231] Sending SUBSCRIBE call to http://172.17.0.3:34502/master/api/v1/scheduler
I0708 15:42:16.579020 29168 master.cpp:6006] Authenticating slave(449)@172.17.0.3:34502
I0708 15:42:16.579133 29165 authenticator.cpp:414] Starting authentication session for crammd5_authenticatee(926)@172.17.0.3:34502
I0708 15:42:16.579236 29168 process.cpp:3322] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I0708 15:42:16.579448 29157 authenticator.cpp:98] Creating new server SASL connection
I0708 15:42:16.579684 29165 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0708 15:42:16.579722 29165 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0708 15:42:16.579831 29165 authenticator.cpp:204] Received SASL authentication start
I0708 15:42:16.579910 29165 authenticator.cpp:326] Authentication requires more steps
I0708 15:42:16.580013 29165 authenticatee.cpp:259] Received SASL authentication step
I0708 15:42:16.580111 29165 authenticator.cpp:232] Received SASL authentication step
I0708 15:42:16.580143 29165 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '0382d073a49a' server FQDN: '0382d073a49a' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0708 15:42:16.580157 29165 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0708 15:42:16.580196 29165 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0708 15:42:16.580227 29165 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '0382d073a49a' server FQDN: '0382d073a49a' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0708 15:42:16.580240 29165 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0708 15:42:16.580251 29165 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0708 15:42:16.580271 29165 authenticator.cpp:318] Authentication success
I0708 15:42:16.580420 29165 authenticatee.cpp:299] Authentication success
I0708 15:42:16.580525 29165 authenticator.cpp:432] Authentication session cleanup for crammd5_authenticatee(926)@172.17.0.3:34502
I0708 15:42:16.580840 29165 slave.cpp:1123] Successfully authenticated with master master@172.17.0.3:34502
I0708 15:42:16.581131 29165 slave.cpp:1529] Will retry registration in 814473ns if necessary
I0708 15:42:16.581560 29168 master.cpp:6036] Successfully authenticated principal 'test-principal' at slave(449)@172.17.0.3:34502
I0708 15:42:16.581795 29168 master.cpp:4676] Registering agent at slave(449)@172.17.0.3:34502 (0382d073a49a) with id 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-S0
I0708 15:42:16.583050 29162 registrar.cpp:464] Applied 1 operations in 131284ns; attempting to update the 'registry'
I0708 15:42:16.584233 29170 slave.cpp:1529] Will retry registration in 27.411836ms if necessary
I0708 15:42:16.584384 29158 master.cpp:4664] Ignoring register agent message from slave(449)@172.17.0.3:34502 (0382d073a49a) as admission is already in progress
I0708 15:42:16.585019 29168 log.cpp:577] Attempting to append 337 bytes to the log
I0708 15:42:16.585113 29162 http.cpp:381] HTTP POST for /master/api/v1/scheduler from 172.17.0.3:33142
I0708 15:42:16.585156 29159 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3
I0708 15:42:16.585417 29162 master.cpp:2272] Received subscription request for HTTP framework 'default'
I0708 15:42:16.585486 29162 master.cpp:2012] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0708 15:42:16.586509 29159 replica.cpp:537] Replica received write request for position 3 from (16448)@172.17.0.3:34502
I0708 15:42:16.587302 29168 master.cpp:2370] Subscribing framework 'default' with checkpointing disabled and capabilities [ ]
I0708 15:42:16.588059 29170 master.hpp:2010] Sending heartbeat to 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000
I0708 15:42:16.588745 29168 hierarchical.cpp:271] Added framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000
I0708 15:42:16.588819 29168 hierarchical.cpp:1537] No allocations performed
I0708 15:42:16.588851 29168 hierarchical.cpp:1632] No inverse offers to send out!
I0708 15:42:16.588910 29168 hierarchical.cpp:1172] Performed allocation for 0 agents in 138375ns
I0708 15:42:16.593391 29162 scheduler.cpp:662] Enqueuing event SUBSCRIBED received from http://172.17.0.3:34502/master/api/v1/scheduler
I0708 15:42:16.594115 29162 scheduler.cpp:662] Enqueuing event HEARTBEAT received from http://172.17.0.3:34502/master/api/v1/scheduler
I0708 15:42:16.612622 29162 slave.cpp:1529] Will retry registration in 35.186867ms if necessary
I0708 15:42:16.613113 29169 master.cpp:4664] Ignoring register agent message from slave(449)@172.17.0.3:34502 (0382d073a49a) as admission is already in progress
I0708 15:42:16.621047 29159 leveldb.cpp:341] Persisting action (356 bytes) to leveldb took 34.409256ms
I0708 15:42:16.621134 29159 replica.cpp:712] Persisted action at 3
I0708 15:42:16.622661 29159 replica.cpp:691] Replica received learned notice for position 3 from @0.0.0.0:0
I0708 15:42:16.646806 29159 leveldb.cpp:341] Persisting action (358 bytes) to leveldb took 24.085822ms
I0708 15:42:16.646906 29159 replica.cpp:712] Persisted action at 3
I0708 15:42:16.646986 29159 replica.cpp:697] Replica learned APPEND action at position 3
I0708 15:42:16.649273 29157 registrar.cpp:509] Successfully updated the 'registry' in 66.121984ms
I0708 15:42:16.649538 29167 slave.cpp:1529] Will retry registration in 111.475397ms if necessary
I0708 15:42:16.649603 29158 log.cpp:596] Attempting to truncate the log to 3
I0708 15:42:16.649811 29157 master.cpp:4664] Ignoring register agent message from slave(449)@172.17.0.3:34502 (0382d073a49a) as admission is already in progress
I0708 15:42:16.650069 29160 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4
I0708 15:42:16.650713 29160 slave.cpp:3760] Received ping from slave-observer(404)@172.17.0.3:34502
I0708 15:42:16.650879 29160 slave.cpp:1169] Registered with master master@172.17.0.3:34502; given agent ID 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-S0
I0708 15:42:16.651007 29160 fetcher.cpp:86] Clearing fetcher cache
I0708 15:42:16.651065 29158 hierarchical.cpp:478] Added agent 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-S0 (0382d073a49a) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
I0708 15:42:16.651480 29160 slave.cpp:1192] Checkpointing SlaveInfo to '/tmp/ContentType_MasterAPITest_Subscribe_0_be660M/meta/slaves/2aea5b7f-ec9f-4fda-8f34-877d8adf064f-S0/slave.info'
I0708 15:42:16.651499 29166 status_update_manager.cpp:181] Resuming sending status updates
I0708 15:42:16.650825 29157 master.cpp:4745] Registered agent 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-S0 at slave(449)@172.17.0.3:34502 (0382d073a49a) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0708 15:42:16.651847 29158 hierarchical.cpp:1632] No inverse offers to send out!
I0708 15:42:16.652433 29158 hierarchical.cpp:1195] Performed allocation for agent 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-S0 in 1.317746ms
I0708 15:42:16.651897 29172 replica.cpp:537] Replica received write request for position 4 from (16450)@172.17.0.3:34502
I0708 15:42:16.653264 29157 master.cpp:5835] Sending 1 offers to framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000 (default)
I0708 15:42:16.654682 29160 slave.cpp:1229] Forwarding total oversubscribed resources
I0708 15:42:16.656188 29165 master.cpp:5128] Received update of agent 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-S0 at slave(449)@172.17.0.3:34502 (0382d073a49a) with total oversubscribed resources
I0708 15:42:16.656200 29164 scheduler.cpp:662] Enqueuing event OFFERS received from http://172.17.0.3:34502/master/api/v1/scheduler
I0708 15:42:16.656708 29159 hierarchical.cpp:542] Agent 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-S0 (0382d073a49a) updated with oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000])
I0708 15:42:16.657385 29159 hierarchical.cpp:1537] No allocations performed
I0708 15:42:16.657438 29159 hierarchical.cpp:1632] No inverse offers to send out!
I0708 15:42:16.657519 29159 hierarchical.cpp:1195] Performed allocation for agent 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-S0 in 516462ns
I0708 15:42:16.660909 29163 process.cpp:3322] Handling HTTP event for process 'master' with path: '/master/api/v1'
I0708 15:42:16.661958 29163 http.cpp:381] HTTP POST for /master/api/v1 from 172.17.0.3:33143
I0708 15:42:16.662125 29163 http.cpp:484] Processing call SUBSCRIBE
I0708 15:42:16.663280 29164 master.cpp:7599] Added subscriber: 726edf8d-ad3d-4d08-9243-de3dc2df5f4a to the list of active subscribers
I0708 15:42:16.671409 29161 scheduler.cpp:231] Sending ACCEPT call to http://172.17.0.3:34502/master/api/v1/scheduler
I0708 15:42:16.672615 29165 process.cpp:3322] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I0708 15:42:16.676375 29169 http.cpp:381] HTTP POST for /master/api/v1/scheduler from 172.17.0.3:33141
I0708 15:42:16.677199 29169 master.cpp:3468] Processing ACCEPT call for offers: [ 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-O0 ] on agent 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-S0 at slave(449)@172.17.0.3:34502 (0382d073a49a) for framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000 (default)
I0708 15:42:16.677291 29169 master.cpp:3106] Authorizing framework principal 'test-principal' to launch task d8bd1ba3-055a-4420-820c-8e85fdde7c08
W0708 15:42:16.679435 29169 validation.cpp:650] Executor default for task d8bd1ba3-055a-4420-820c-8e85fdde7c08 uses less CPUs (None) than the minimum required (0.01). Please update your executor, as this will be mandatory in future releases.
W0708 15:42:16.679492 29169 validation.cpp:662] Executor default for task d8bd1ba3-055a-4420-820c-8e85fdde7c08 uses less memory (None) than the minimum required (32MB). Please update your executor, as this will be mandatory in future releases.
I0708 15:42:16.680003 29169 master.cpp:7573] Notifying all active subscribers about TASK_ADDED event
I0708 15:42:16.680454 29172 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 27.707387ms
I0708 15:42:16.680685 29172 replica.cpp:712] Persisted action at 4
I0708 15:42:16.681685 29168 replica.cpp:691] Replica received learned notice for position 4 from @0.0.0.0:0
I0708 15:42:16.680449 29169 master.cpp:7565] Adding task d8bd1ba3-055a-4420-820c-8e85fdde7c08 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on agent 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-S0 (0382d073a49a)
I0708 15:42:16.682688 29169 master.cpp:3957] Launching task d8bd1ba3-055a-4420-820c-8e85fdde7c08 of framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000 (default) with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on agent 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-S0 at slave(449)@172.17.0.3:34502 (0382d073a49a)
I0708 15:42:16.683289 29171 slave.cpp:1569] Got assigned task d8bd1ba3-055a-4420-820c-8e85fdde7c08 for framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000
I0708 15:42:16.683903 29171 slave.cpp:1688] Launching task d8bd1ba3-055a-4420-820c-8e85fdde7c08 for framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000
I0708 15:42:16.684563 29171 paths.cpp:528] Trying to chown '/tmp/ContentType_MasterAPITest_Subscribe_0_be660M/slaves/2aea5b7f-ec9f-4fda-8f34-877d8adf064f-S0/frameworks/2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000/executors/default/runs/d8931456-e1d5-4875-9fb2-cf66e66d7fa3' to user 'mesos'
I0708 15:42:16.699834 29171 slave.cpp:5748] Launching executor default of framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000 with resources in work directory '/tmp/ContentType_MasterAPITest_Subscribe_0_be660M/slaves/2aea5b7f-ec9f-4fda-8f34-877d8adf064f-S0/frameworks/2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000/executors/default/runs/d8931456-e1d5-4875-9fb2-cf66e66d7fa3'
I0708 15:42:16.702018 29171 executor.cpp:188] Version: 1.1.0
I0708 15:42:16.702541 29171 slave.cpp:1914] Queuing task 'd8bd1ba3-055a-4420-820c-8e85fdde7c08' for executor 'default' of framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000
I0708 15:42:16.702777 29171 slave.cpp:922] Successfully attached file '/tmp/ContentType_MasterAPITest_Subscribe_0_be660M/slaves/2aea5b7f-ec9f-4fda-8f34-877d8adf064f-S0/frameworks/2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000/executors/default/runs/d8931456-e1d5-4875-9fb2-cf66e66d7fa3'
I0708 15:42:16.704201 29169 executor.cpp:389] Connected with the agent
I0708 15:42:16.704911 29159 executor.cpp:290] Sending SUBSCRIBE call to http://172.17.0.3:34502/slave(449)/api/v1/executor
I0708 15:42:16.706003 29170 process.cpp:3322] Handling HTTP event for process 'slave(449)' with path: '/slave(449)/api/v1/executor'
I0708 15:42:16.706897 29157 http.cpp:270] HTTP POST for /slave(449)/api/v1/executor from 172.17.0.3:33144
I0708 15:42:16.707108 29157 slave.cpp:2735] Received Subscribe request for HTTP executor 'default' of framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000
I0708 15:42:16.707819 29168 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 26.083403ms
I0708 15:42:16.707986 29168 leveldb.cpp:399] Deleting ~2 keys from leveldb took 117548ns
I0708 15:42:16.708031 29168 replica.cpp:712] Persisted action at 4
I0708 15:42:16.708076 29168 replica.cpp:697] Replica learned TRUNCATE action at position 4
I0708 15:42:16.708082 29157 slave.cpp:2079] Sending queued task 'd8bd1ba3-055a-4420-820c-8e85fdde7c08' to executor 'default' of framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000 (via HTTP)
I0708 15:42:16.710268 29163 executor.cpp:707] Enqueuing event SUBSCRIBED received from http://172.17.0.3:34502/slave(449)/api/v1/executor
I0708 15:42:16.712131 29169 executor.cpp:707] Enqueuing event LAUNCH received from http://172.17.0.3:34502/slave(449)/api/v1/executor
I0708 15:42:16.713174 29172 executor.cpp:290] Sending UPDATE call to http://172.17.0.3:34502/slave(449)/api/v1/executor
I0708 15:42:16.713984 29170 process.cpp:3322] Handling HTTP event for process 'slave(449)' with path: '/slave(449)/api/v1/executor'
I0708 15:42:16.714614 29170 http.cpp:270] HTTP POST for /slave(449)/api/v1/executor from 172.17.0.3:33145
I0708 15:42:16.714753 29170 slave.cpp:3285] Handling status update TASK_RUNNING (UUID: a93b73fb-5289-4aec-80e9-1cad44bec619) for task d8bd1ba3-055a-4420-820c-8e85fdde7c08 of framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000
I0708 15:42:16.715451 29172 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: a93b73fb-5289-4aec-80e9-1cad44bec619) for task d8bd1ba3-055a-4420-820c-8e85fdde7c08 of framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000
I0708 15:42:16.715498 29172 status_update_manager.cpp:497] Creating StatusUpdate stream for task d8bd1ba3-055a-4420-820c-8e85fdde7c08 of framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000
I0708 15:42:16.715996 29172 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: a93b73fb-5289-4aec-80e9-1cad44bec619) for task d8bd1ba3-055a-4420-820c-8e85fdde7c08 of framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000 to the agent
I0708 15:42:16.716584 29172 slave.cpp:3678] Forwarding the update TASK_RUNNING (UUID: a93b73fb-5289-4aec-80e9-1cad44bec619) for task d8bd1ba3-055a-4420-820c-8e85fdde7c08 of framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000 to master@172.17.0.3:34502
I0708 15:42:16.716956 29172 slave.cpp:3572] Status update manager successfully handled status update TASK_RUNNING (UUID: a93b73fb-5289-4aec-80e9-1cad44bec619) for task d8bd1ba3-055a-4420-820c-8e85fdde7c08 of framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000
I0708 15:42:16.717159 29171 master.cpp:5273] Status update TASK_RUNNING (UUID: a93b73fb-5289-4aec-80e9-1cad44bec619) for task d8bd1ba3-055a-4420-820c-8e85fdde7c08 of framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000 from agent 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-S0 at slave(449)@172.17.0.3:34502 (0382d073a49a)
I0708 15:42:16.717265 29171 master.cpp:5321] Forwarding status update TASK_RUNNING (UUID: a93b73fb-5289-4aec-80e9-1cad44bec619) for task d8bd1ba3-055a-4420-820c-8e85fdde7c08 of framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000
I0708 15:42:16.718080 29168 executor.cpp:707] Enqueuing event ACKNOWLEDGED received from http://172.17.0.3:34502/slave(449)/api/v1/executor
I0708 15:42:16.718299 29171 master.cpp:7573] Notifying all active subscribers about TASK_UPDATED event
I0708 15:42:16.719683 29171 master.cpp:6959] Updating the state of task d8bd1ba3-055a-4420-820c-8e85fdde7c08 of framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
I0708 15:42:16.720386 29171 scheduler.cpp:662] Enqueuing event UPDATE received from http://172.17.0.3:34502/master/api/v1/scheduler
I0708 15:42:16.726471 29164 hierarchical.cpp:1537] No allocations performed
W0708 15:42:16.726742 29163 status_update_manager.cpp:475] Resending status update TASK_RUNNING (UUID: a93b73fb-5289-4aec-80e9-1cad44bec619) for task d8bd1ba3-055a-4420-820c-8e85fdde7c08 of framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000
I0708 15:42:16.726840 29163 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: a93b73fb-5289-4aec-80e9-1cad44bec619) for task d8bd1ba3-055a-4420-820c-8e85fdde7c08 of framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000 to the agent
I0708 15:42:16.727401 29163 slave.cpp:3678] Forwarding the update TASK_RUNNING (UUID: a93b73fb-5289-4aec-80e9-1cad44bec619) for task d8bd1ba3-055a-4420-820c-8e85fdde7c08 of framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000 to master@172.17.0.3:34502
I0708 15:42:16.727880 29163 master.cpp:5273] Status update TASK_RUNNING (UUID: a93b73fb-5289-4aec-80e9-1cad44bec619) for task d8bd1ba3-055a-4420-820c-8e85fdde7c08 of framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000 from agent 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-S0 at slave(449)@172.17.0.3:34502 (0382d073a49a)
I0708 15:42:16.728035 29163 master.cpp:5321] Forwarding status update TASK_RUNNING (UUID: a93b73fb-5289-4aec-80e9-1cad44bec619) for task d8bd1ba3-055a-4420-820c-8e85fdde7c08 of framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000
I0708 15:42:16.728570 29163 master.cpp:6959] Updating the state of task d8bd1ba3-055a-4420-820c-8e85fdde7c08 of framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
I0708 15:42:16.728003 29164 hierarchical.cpp:1632] No inverse offers to send out!
I0708 15:42:16.730080 29164 hierarchical.cpp:1172] Performed allocation for 1 agents in 3.858387ms
I0708 15:42:16.751055 29160 master.cpp:1410] Framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000 (default) disconnected
I0708 15:42:16.751116 29160 master.cpp:2851] Disconnecting framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000 (default)
I0708 15:42:16.751149 29160 master.cpp:2875] Deactivating framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000 (default)
I0708 15:42:16.751242 29160 master.cpp:1423] Giving framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000 (default) 0ns to failover
I0708 15:42:16.751602 29160 hierarchical.cpp:382] Deactivated framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000
I0708 15:42:16.755091 29157 master.cpp:5687] Framework failover timeout, removing framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000 (default)
I0708 15:42:16.755164 29157 master.cpp:6422] Removing framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000 (default)
I0708 15:42:16.755425 29157 master.cpp:7573] Notifying all active subscribers about TASK_UPDATED event
I0708 15:42:16.755795 29157 master.cpp:6959] Updating the state of task d8bd1ba3-055a-4420-820c-8e85fdde7c08 of framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000 (latest state: TASK_KILLED, status update state: TASK_KILLED)
I0708 15:42:16.756032 29166 slave.cpp:2292] Asked to shut down framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000 by master@172.17.0.3:34502
I0708 15:42:16.756093 29166 slave.cpp:2317] Shutting down framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000
I0708 15:42:16.756172 29166 slave.cpp:4481] Shutting down executor 'default' of framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000 (via HTTP)
I0708 15:42:16.757699 29157 master.cpp:7025] Removing task d8bd1ba3-055a-4420-820c-8e85fdde7c08 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000 on agent 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-S0 at slave(449)@172.17.0.3:34502 (0382d073a49a)
I0708 15:42:16.758779 29161 hierarchical.cpp:924] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on agent 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-S0 from framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000
I0708 15:42:16.759784 29161 executor.cpp:707] Enqueuing event SHUTDOWN received from http://172.17.0.3:34502/slave(449)/api/v1/executor
I0708 15:42:16.761289 29157 master.cpp:7054] Removing executor 'default' with resources of framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000 on agent 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-S0 at slave(449)@172.17.0.3:34502 (0382d073a49a)
I0708 15:42:16.763124 29157 hierarchical.cpp:333] Removed framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000
I0708 15:42:16.777029 29163 slave.cpp:4163] Executor 'default' of framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000 exited with status 0
I0708 15:42:16.777218 29163 slave.cpp:4267] Cleaning up executor 'default' of framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000 (via HTTP)
I0708 15:42:16.777710 29163 slave.cpp:4355] Cleaning up framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000
I0708 15:42:16.778026 29163 gc.cpp:55] Scheduling '/tmp/ContentType_MasterAPITest_Subscribe_0_be660M/slaves/2aea5b7f-ec9f-4fda-8f34-877d8adf064f-S0/frameworks/2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000/executors/default/runs/d8931456-e1d5-4875-9fb2-cf66e66d7fa3' for gc 6.99999163714074days in the future
W0708 15:42:16.778028 29167 master.cpp:5369] Ignoring unknown exited executor 'default' of framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000 on agent 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-S0 at slave(449)@172.17.0.3:34502 (0382d073a49a)
I0708 15:42:16.778195 29157 status_update_manager.cpp:282] Closing status update streams for framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000
I0708 15:42:16.778239 29163 gc.cpp:55] Scheduling '/tmp/ContentType_MasterAPITest_Subscribe_0_be660M/slaves/2aea5b7f-ec9f-4fda-8f34-877d8adf064f-S0/frameworks/2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000/executors/default' for gc 6.99999163714074days in the future
I0708 15:42:16.778257 29157 status_update_manager.cpp:528] Cleaning up status update stream for task d8bd1ba3-055a-4420-820c-8e85fdde7c08 of framework 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000
I0708 15:42:16.778327 29163 gc.cpp:55] Scheduling '/tmp/ContentType_MasterAPITest_Subscribe_0_be660M/slaves/2aea5b7f-ec9f-4fda-8f34-877d8adf064f-S0/frameworks/2aea5b7f-ec9f-4fda-8f34-877d8adf064f-0000' for gc 6.99999163714074days in the future
I0708 15:42:16.797328 29138 slave.cpp:841] Agent terminating
I0708 15:42:16.799114 29165 master.cpp:1371] Agent 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-S0 at slave(449)@172.17.0.3:34502 (0382d073a49a) disconnected
I0708 15:42:16.800149 29165 master.cpp:2910] Disconnecting agent 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-S0 at slave(449)@172.17.0.3:34502 (0382d073a49a)
I0708 15:42:16.800727 29165 master.cpp:2929] Deactivating agent 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-S0 at slave(449)@172.17.0.3:34502 (0382d073a49a)
I0708 15:42:16.801389 29165 hierarchical.cpp:571] Agent 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-S0 deactivated
../../src/tests/api_tests.cpp:1496: Failure
Actual function call count doesn't match EXPECT_CALL(*scheduler, update(_, _))...
Expected: to be called twice
Actual: called once - unsatisfied and active
I0708 15:42:16.806820 29138 master.cpp:1218] Master terminating
I0708 15:42:16.807718 29160 hierarchical.cpp:510] Removed agent 2aea5b7f-ec9f-4fda-8f34-877d8adf064f-S0
[ FAILED ] ContentType/MasterAPITest.Subscribe/0, where GetParam() = application/x-protobuf (780 ms)
{noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)