[MESOS-5812] MasterAPITest.Subscribe is flaky - ASF JIRA

XML

Word

Printable

JSON

Details

Type: Bug
Status: Resolved
Priority: Major
Resolution: Fixed
Affects Version/s: None
Fix Version/s: 1.1.0
Component/s: test
Labels:
None
Environment:

mac os X
centos 7

Epic Link:
Operator API v1
Sprint:
Mesosphere Sprint 39
Story Points:
3

Description

This test seems to be flaky, although on Mac OS X and CentOS 7 the error a bit different.

On Mac OS X:

[ RUN      ] ContentType/MasterAPITest.Subscribe/0
I0708 11:42:48.474665 1927435008 cluster.cpp:155] Creating default 'local' authorizer
I0708 11:42:48.480677 1927435008 leveldb.cpp:174] Opened db in 5727us
I0708 11:42:48.481494 1927435008 leveldb.cpp:181] Compacted db in 722us
I0708 11:42:48.481541 1927435008 leveldb.cpp:196] Created db iterator in 19us
I0708 11:42:48.481572 1927435008 leveldb.cpp:202] Seeked to beginning of db in 9us
I0708 11:42:48.481587 1927435008 leveldb.cpp:271] Iterated through 0 keys in the db in 7us
I0708 11:42:48.481617 1927435008 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0708 11:42:48.482030 350982144 recover.cpp:451] Starting replica recovery
I0708 11:42:48.482203 350982144 recover.cpp:477] Replica is in EMPTY status
I0708 11:42:48.484107 348299264 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (3780)@127.0.0.1:50325
I0708 11:42:48.484318 350982144 recover.cpp:197] Received a recover response from a replica in EMPTY status
I0708 11:42:48.484750 348835840 master.cpp:382] Master e055d60c-05ff-487e-82da-d0a43e52605c (localhost) started on 127.0.0.1:50325
I0708 11:42:48.484850 349908992 recover.cpp:568] Updating replica status to STARTING
I0708 11:42:48.484788 348835840 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/Sn2Kf4/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/Sn2Kf4/master" --zk_session_timeout="10secs"
W0708 11:42:48.485263 348835840 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:42:48.485291 348835840 master.cpp:434] Master only allowing authenticated frameworks to register
I0708 11:42:48.485314 348835840 master.cpp:448] Master only allowing authenticated agents to register
I0708 11:42:48.485335 348835840 master.cpp:461] Master only allowing authenticated HTTP frameworks to register
I0708 11:42:48.485347 348835840 credentials.hpp:37] Loading credentials for authentication from '/private/tmp/Sn2Kf4/credentials'
I0708 11:42:48.485373 349372416 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 397us
I0708 11:42:48.485414 349372416 replica.cpp:320] Persisted replica status to STARTING
I0708 11:42:48.485608 350982144 recover.cpp:477] Replica is in STARTING status
I0708 11:42:48.485749 348835840 master.cpp:506] Using default 'crammd5' authenticator
I0708 11:42:48.485852 348835840 master.cpp:578] Using default 'basic' HTTP authenticator
I0708 11:42:48.486018 348835840 master.cpp:658] Using default 'basic' HTTP framework authenticator
I0708 11:42:48.486140 348835840 master.cpp:705] Authorization enabled
I0708 11:42:48.486486 350982144 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (3783)@127.0.0.1:50325
I0708 11:42:48.486758 352055296 recover.cpp:197] Received a recover response from a replica in STARTING status
I0708 11:42:48.487176 350982144 recover.cpp:568] Updating replica status to VOTING
I0708 11:42:48.487576 352055296 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 300us
I0708 11:42:48.487658 352055296 replica.cpp:320] Persisted replica status to VOTING
I0708 11:42:48.487736 350982144 recover.cpp:582] Successfully joined the Paxos group
I0708 11:42:48.487951 350982144 recover.cpp:466] Recover process terminated
I0708 11:42:48.489441 348835840 master.cpp:1973] The newly elected leader is master@127.0.0.1:50325 with id e055d60c-05ff-487e-82da-d0a43e52605c
I0708 11:42:48.489518 348835840 master.cpp:1986] Elected as the leading master!
I0708 11:42:48.489545 348835840 master.cpp:1673] Recovering from registrar
I0708 11:42:48.489637 350982144 registrar.cpp:332] Recovering registrar
I0708 11:42:48.490120 351518720 log.cpp:553] Attempting to start the writer
I0708 11:42:48.491161 350445568 replica.cpp:493] Replica received implicit promise request from (3784)@127.0.0.1:50325 with proposal 1
I0708 11:42:48.491461 350445568 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 252us
I0708 11:42:48.491528 350445568 replica.cpp:342] Persisted promised to 1
I0708 11:42:48.492337 348299264 coordinator.cpp:238] Coordinator attempting to fill missing positions
I0708 11:42:48.493482 349372416 replica.cpp:388] Replica received explicit promise request from (3785)@127.0.0.1:50325 for position 0 with proposal 2
I0708 11:42:48.493854 349372416 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 283us
I0708 11:42:48.493904 349372416 replica.cpp:712] Persisted action at 0
I0708 11:42:48.495302 348299264 replica.cpp:537] Replica received write request for position 0 from (3786)@127.0.0.1:50325
I0708 11:42:48.495455 348299264 leveldb.cpp:436] Reading position from leveldb took 45us
I0708 11:42:48.495761 348299264 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 261us
I0708 11:42:48.495803 348299264 replica.cpp:712] Persisted action at 0
I0708 11:42:48.496484 350445568 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
I0708 11:42:48.496795 350445568 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 255us
I0708 11:42:48.496857 350445568 replica.cpp:712] Persisted action at 0
I0708 11:42:48.496896 350445568 replica.cpp:697] Replica learned NOP action at position 0
I0708 11:42:48.497445 350982144 log.cpp:569] Writer started with ending position 0
I0708 11:42:48.498523 350982144 leveldb.cpp:436] Reading position from leveldb took 80us
I0708 11:42:48.499307 349908992 registrar.cpp:365] Successfully fetched the registry (0B) in 9.63712ms
I0708 11:42:48.499464 349908992 registrar.cpp:464] Applied 1 operations in 36us; attempting to update the 'registry'
I0708 11:42:48.499953 351518720 log.cpp:577] Attempting to append 159 bytes to the log
I0708 11:42:48.500088 350982144 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
I0708 11:42:48.500880 348299264 replica.cpp:537] Replica received write request for position 1 from (3787)@127.0.0.1:50325
I0708 11:42:48.501186 348299264 leveldb.cpp:341] Persisting action (178 bytes) to leveldb took 259us
I0708 11:42:48.501231 348299264 replica.cpp:712] Persisted action at 1
I0708 11:42:48.501786 351518720 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
I0708 11:42:48.502118 351518720 leveldb.cpp:341] Persisting action (180 bytes) to leveldb took 311us
I0708 11:42:48.502260 351518720 replica.cpp:712] Persisted action at 1
I0708 11:42:48.502305 351518720 replica.cpp:697] Replica learned APPEND action at position 1
I0708 11:42:48.503475 349908992 registrar.cpp:509] Successfully updated the 'registry' in 3.944192ms
I0708 11:42:48.503909 349908992 registrar.cpp:395] Successfully recovered registrar
I0708 11:42:48.504003 350982144 log.cpp:596] Attempting to truncate the log to 1
I0708 11:42:48.504250 349372416 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
I0708 11:42:48.504546 350445568 master.cpp:1781] Recovered 0 agents from the Registry (121B) ; allowing 10mins for agents to re-register
I0708 11:42:48.506022 352055296 replica.cpp:537] Replica received write request for position 2 from (3788)@127.0.0.1:50325
I0708 11:42:48.506479 352055296 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 320us
I0708 11:42:48.506513 352055296 replica.cpp:712] Persisted action at 2
I0708 11:42:48.506978 351518720 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
I0708 11:42:48.507155 351518720 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 169us
I0708 11:42:48.507237 351518720 leveldb.cpp:399] Deleting ~1 keys from leveldb took 37us
I0708 11:42:48.507264 351518720 replica.cpp:712] Persisted action at 2
I0708 11:42:48.507285 351518720 replica.cpp:697] Replica learned TRUNCATE action at position 2
I0708 11:42:48.521363 1927435008 cluster.cpp:432] Creating default 'local' authorizer
I0708 11:42:48.522498 350982144 slave.cpp:205] Agent started on 119)@127.0.0.1:50325
I0708 11:42:48.522538 350982144 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_VaPndX/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_VaPndX/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_VaPndX/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_VaPndX"
W0708 11:42:48.522903 350982144 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:42:48.522922 350982144 credentials.hpp:86] Loading credential for authentication from '/var/folders/ny/tcvyblqj43s2gdh2_895v9nw0000gp/T/ContentType_MasterAPITest_Subscribe_0_VaPndX/credential'
W0708 11:42:48.522965 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:42:48.522992 1927435008 scheduler.cpp:172] Version: 1.0.0
I0708 11:42:48.523066 350982144 slave.cpp:343] Agent using credential for: test-principal
I0708 11:42:48.523092 350982144 credentials.hpp:37] Loading credentials for authentication from '/var/folders/ny/tcvyblqj43s2gdh2_895v9nw0000gp/T/ContentType_MasterAPITest_Subscribe_0_VaPndX/http_credentials'
I0708 11:42:48.523334 350982144 slave.cpp:395] Using default 'basic' HTTP authenticator
I0708 11:42:48.523973 352055296 scheduler.cpp:461] New master detected at master@127.0.0.1:50325
I0708 11:42:48.524050 350982144 slave.cpp:594] Agent resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0708 11:42:48.524196 350982144 slave.cpp:602] Agent attributes: [  ]
I0708 11:42:48.524224 350982144 slave.cpp:607] Agent hostname: localhost
I0708 11:42:48.525522 350445568 state.cpp:57] Recovering state from '/var/folders/ny/tcvyblqj43s2gdh2_895v9nw0000gp/T/ContentType_MasterAPITest_Subscribe_0_VaPndX/meta'
I0708 11:42:48.525853 350445568 status_update_manager.cpp:200] Recovering status update manager
I0708 11:42:48.526165 350445568 slave.cpp:4856] Finished recovery
I0708 11:42:48.527223 349372416 status_update_manager.cpp:174] Pausing sending status updates
I0708 11:42:48.527231 352055296 slave.cpp:969] New master detected at master@127.0.0.1:50325
I0708 11:42:48.527276 352055296 slave.cpp:1028] Authenticating with master master@127.0.0.1:50325
I0708 11:42:48.527328 352055296 slave.cpp:1039] Using default CRAM-MD5 authenticatee
I0708 11:42:48.527561 352055296 slave.cpp:1001] Detecting new master
I0708 11:42:48.527582 348299264 authenticatee.cpp:121] Creating new client SASL connection
I0708 11:42:48.528666 349908992 master.cpp:6006] Authenticating slave(119)@127.0.0.1:50325
I0708 11:42:48.528880 352055296 authenticator.cpp:98] Creating new server SASL connection
I0708 11:42:48.529089 350445568 http.cpp:381] HTTP POST for /master/api/v1/scheduler from 127.0.0.1:50918
I0708 11:42:48.529233 350445568 master.cpp:2272] Received subscription request for HTTP framework 'default'
I0708 11:42:48.529261 350445568 master.cpp:2012] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0708 11:42:48.529323 352055296 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0708 11:42:48.529357 352055296 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0708 11:42:48.529417 352055296 authenticator.cpp:204] Received SASL authentication start
I0708 11:42:48.529503 352055296 authenticator.cpp:326] Authentication requires more steps
I0708 11:42:48.529561 352055296 master.cpp:2370] Subscribing framework 'default' with checkpointing disabled and capabilities [  ]
I0708 11:42:48.529721 349908992 authenticatee.cpp:259] Received SASL authentication step
I0708 11:42:48.530005 348835840 authenticator.cpp:232] Received SASL authentication step
I0708 11:42:48.530241 348835840 authenticator.cpp:318] Authentication success
I0708 11:42:48.530254 350445568 hierarchical.cpp:271] Added framework e055d60c-05ff-487e-82da-d0a43e52605c-0000
I0708 11:42:48.530900 349908992 authenticatee.cpp:299] Authentication success
I0708 11:42:48.531186 350982144 master.cpp:6036] Successfully authenticated principal 'test-principal' at slave(119)@127.0.0.1:50325
I0708 11:42:48.531657 348299264 slave.cpp:1123] Successfully authenticated with master master@127.0.0.1:50325
I0708 11:42:48.531935 349372416 master.cpp:4676] Registering agent at slave(119)@127.0.0.1:50325 (localhost) with id e055d60c-05ff-487e-82da-d0a43e52605c-S0
I0708 11:42:48.532304 349908992 registrar.cpp:464] Applied 1 operations in 55us; attempting to update the 'registry'
I0708 11:42:48.532908 348835840 log.cpp:577] Attempting to append 326 bytes to the log
I0708 11:42:48.533015 352055296 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3
I0708 11:42:48.533641 349372416 replica.cpp:537] Replica received write request for position 3 from (3798)@127.0.0.1:50325
I0708 11:42:48.533867 349372416 leveldb.cpp:341] Persisting action (345 bytes) to leveldb took 186us
I0708 11:42:48.533917 349372416 replica.cpp:712] Persisted action at 3
I0708 11:42:48.537066 349908992 replica.cpp:691] Replica received learned notice for position 3 from @0.0.0.0:0
I0708 11:42:48.538169 349908992 leveldb.cpp:341] Persisting action (347 bytes) to leveldb took 914us
I0708 11:42:48.538226 349908992 replica.cpp:712] Persisted action at 3
I0708 11:42:48.538255 349908992 replica.cpp:697] Replica learned APPEND action at position 3
I0708 11:42:48.539247 352055296 registrar.cpp:509] Successfully updated the 'registry' in 6.895104ms
I0708 11:42:48.539302 348299264 log.cpp:596] Attempting to truncate the log to 3
I0708 11:42:48.539393 348299264 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4
I0708 11:42:48.539798 348835840 master.cpp:4745] Registered agent e055d60c-05ff-487e-82da-d0a43e52605c-S0 at slave(119)@127.0.0.1:50325 (localhost) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0708 11:42:48.539881 348299264 hierarchical.cpp:478] Added agent e055d60c-05ff-487e-82da-d0a43e52605c-S0 (localhost) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
I0708 11:42:48.539901 349908992 slave.cpp:1169] Registered with master master@127.0.0.1:50325; given agent ID e055d60c-05ff-487e-82da-d0a43e52605c-S0
I0708 11:42:48.540287 350445568 status_update_manager.cpp:181] Resuming sending status updates
I0708 11:42:48.540501 351518720 replica.cpp:537] Replica received write request for position 4 from (3799)@127.0.0.1:50325
I0708 11:42:48.540583 352055296 master.cpp:5835] Sending 1 offers to framework e055d60c-05ff-487e-82da-d0a43e52605c-0000 (default)
I0708 11:42:48.540798 351518720 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 247us
I0708 11:42:48.540868 351518720 replica.cpp:712] Persisted action at 4
I0708 11:42:48.540895 349908992 slave.cpp:1229] Forwarding total oversubscribed resources 
I0708 11:42:48.541035 352055296 master.cpp:5128] Received update of agent e055d60c-05ff-487e-82da-d0a43e52605c-S0 at slave(119)@127.0.0.1:50325 (localhost) with total oversubscribed resources 
I0708 11:42:48.541291 349908992 hierarchical.cpp:542] Agent e055d60c-05ff-487e-82da-d0a43e52605c-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:42:48.541630 350982144 replica.cpp:691] Replica received learned notice for position 4 from @0.0.0.0:0
I0708 11:42:48.541911 350982144 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 189us
I0708 11:42:48.541965 350982144 leveldb.cpp:399] Deleting ~2 keys from leveldb took 28us
I0708 11:42:48.541987 350982144 replica.cpp:712] Persisted action at 4
I0708 11:42:48.542006 350982144 replica.cpp:697] Replica learned TRUNCATE action at position 4
I0708 11:42:48.544836 352055296 http.cpp:381] HTTP POST for /master/api/v1 from 127.0.0.1:50920
I0708 11:42:48.544884 352055296 http.cpp:484] Processing call SUBSCRIBE
I0708 11:42:48.545382 352055296 master.cpp:7599] Added subscriber: a85e7341-ac15-4f18-9021-1a2efa326442 to the list of active subscribers
I0708 11:42:48.550048 348835840 http.cpp:381] HTTP POST for /master/api/v1/scheduler from 127.0.0.1:50919
I0708 11:42:48.550339 348835840 master.cpp:3468] Processing ACCEPT call for offers: [ e055d60c-05ff-487e-82da-d0a43e52605c-O0 ] on agent e055d60c-05ff-487e-82da-d0a43e52605c-S0 at slave(119)@127.0.0.1:50325 (localhost) for framework e055d60c-05ff-487e-82da-d0a43e52605c-0000 (default)
I0708 11:42:48.550390 348835840 master.cpp:3106] Authorizing framework principal 'test-principal' to launch task d94e54c0-8c89-43bd-be2f-adeb8cf70cb1
W0708 11:42:48.551434 348835840 validation.cpp:650] Executor default for task d94e54c0-8c89-43bd-be2f-adeb8cf70cb1 uses less CPUs (None) than the minimum required (0.01). Please update your executor, as this will be mandatory in future releases.
W0708 11:42:48.551477 348835840 validation.cpp:662] Executor default for task d94e54c0-8c89-43bd-be2f-adeb8cf70cb1 uses less memory (None) than the minimum required (32MB). Please update your executor, as this will be mandatory in future releases.
I0708 11:42:48.551803 348835840 master.cpp:7565] Adding task d94e54c0-8c89-43bd-be2f-adeb8cf70cb1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on agent e055d60c-05ff-487e-82da-d0a43e52605c-S0 (localhost)
I0708 11:42:48.551949 348835840 master.cpp:3957] Launching task d94e54c0-8c89-43bd-be2f-adeb8cf70cb1 of framework e055d60c-05ff-487e-82da-d0a43e52605c-0000 (default) with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on agent e055d60c-05ff-487e-82da-d0a43e52605c-S0 at slave(119)@127.0.0.1:50325 (localhost)
I0708 11:42:48.552151 352055296 slave.cpp:1569] Got assigned task d94e54c0-8c89-43bd-be2f-adeb8cf70cb1 for framework e055d60c-05ff-487e-82da-d0a43e52605c-0000
I0708 11:42:48.552592 352055296 slave.cpp:1688] Launching task d94e54c0-8c89-43bd-be2f-adeb8cf70cb1 for framework e055d60c-05ff-487e-82da-d0a43e52605c-0000
I0708 11:42:48.553282 352055296 paths.cpp:528] Trying to chown '/var/folders/ny/tcvyblqj43s2gdh2_895v9nw0000gp/T/ContentType_MasterAPITest_Subscribe_0_VaPndX/slaves/e055d60c-05ff-487e-82da-d0a43e52605c-S0/frameworks/e055d60c-05ff-487e-82da-d0a43e52605c-0000/executors/default/runs/62add906-b60f-43ec-ab06-0514a798de26' to user 'zhitao'
I0708 11:42:48.566201 352055296 slave.cpp:5748] Launching executor default of framework e055d60c-05ff-487e-82da-d0a43e52605c-0000 with resources  in work directory '/var/folders/ny/tcvyblqj43s2gdh2_895v9nw0000gp/T/ContentType_MasterAPITest_Subscribe_0_VaPndX/slaves/e055d60c-05ff-487e-82da-d0a43e52605c-S0/frameworks/e055d60c-05ff-487e-82da-d0a43e52605c-0000/executors/default/runs/62add906-b60f-43ec-ab06-0514a798de26'
I0708 11:42:48.567876 352055296 executor.cpp:188] Version: 1.0.0
I0708 11:42:48.568428 352055296 slave.cpp:1914] Queuing task 'd94e54c0-8c89-43bd-be2f-adeb8cf70cb1' for executor 'default' of framework e055d60c-05ff-487e-82da-d0a43e52605c-0000
E0708 11:42:48.571115 352591872 process.cpp:2104] Failed to shutdown socket with fd 254: Socket is not connected
W0708 11:42:48.570768 352055296 executor.cpp:739] Dropping SUBSCRIBE: Executor is in state DISCONNECTED

GMOCK WARNING:
Uninteresting mock function call - returning directly.
    Function call: disconnected(0x7fad21fcebf0)
Stack trace:
../../src/tests/api_tests.cpp:1537: Failure
Failed to wait 15secs for event
E0708 11:43:03.556205 352591872 process.cpp:2104] Failed to shutdown socket with fd 235: Socket is not connected
E0708 11:43:03.556584 352591872 process.cpp:2104] Failed to shutdown socket with fd 223: Socket is not connected
I0708 11:43:03.557134 349908992 master.cpp:1410] Framework e055d60c-05ff-487e-82da-d0a43e52605c-0000 (default) disconnected
I0708 11:43:03.557176 349908992 master.cpp:2851] Disconnecting framework e055d60c-05ff-487e-82da-d0a43e52605c-0000 (default)
I0708 11:43:03.557209 349908992 master.cpp:2875] Deactivating framework e055d60c-05ff-487e-82da-d0a43e52605c-0000 (default)
I0708 11:43:03.557415 349908992 master.cpp:1423] Giving framework e055d60c-05ff-487e-82da-d0a43e52605c-0000 (default) 0ns to failover
I0708 11:43:03.557456 348835840 hierarchical.cpp:382] Deactivated framework e055d60c-05ff-487e-82da-d0a43e52605c-0000
I0708 11:43:03.557878 350445568 master.cpp:5687] Framework failover timeout, removing framework e055d60c-05ff-487e-82da-d0a43e52605c-0000 (default)
I0708 11:43:03.557945 350445568 master.cpp:6422] Removing framework e055d60c-05ff-487e-82da-d0a43e52605c-0000 (default)
I0708 11:43:03.558076 352055296 slave.cpp:2292] Asked to shut down framework e055d60c-05ff-487e-82da-d0a43e52605c-0000 by master@127.0.0.1:50325
I0708 11:43:03.558106 352055296 slave.cpp:2317] Shutting down framework e055d60c-05ff-487e-82da-d0a43e52605c-0000
I0708 11:43:03.558131 352055296 slave.cpp:4481] Shutting down executor 'default' of framework e055d60c-05ff-487e-82da-d0a43e52605c-0000
W0708 11:43:03.558147 352055296 slave.hpp:768] Unable to send event to executor 'default' of framework e055d60c-05ff-487e-82da-d0a43e52605c-0000: unknown connection type
I0708 11:43:03.558188 350445568 master.cpp:6959] Updating the state of task d94e54c0-8c89-43bd-be2f-adeb8cf70cb1 of framework e055d60c-05ff-487e-82da-d0a43e52605c-0000 (latest state: TASK_KILLED, status update state: TASK_KILLED)
I0708 11:43:03.558507 350445568 master.cpp:7025] Removing task d94e54c0-8c89-43bd-be2f-adeb8cf70cb1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework e055d60c-05ff-487e-82da-d0a43e52605c-0000 on agent e055d60c-05ff-487e-82da-d0a43e52605c-S0 at slave(119)@127.0.0.1:50325 (localhost)
I0708 11:43:03.558709 350445568 master.cpp:7054] Removing executor 'default' with resources  of framework e055d60c-05ff-487e-82da-d0a43e52605c-0000 on agent e055d60c-05ff-487e-82da-d0a43e52605c-S0 at slave(119)@127.0.0.1:50325 (localhost)
I0708 11:43:03.559051 349372416 hierarchical.cpp:333] Removed framework e055d60c-05ff-487e-82da-d0a43e52605c-0000
I0708 11:43:03.567955 350982144 slave.cpp:4163] Executor 'default' of framework e055d60c-05ff-487e-82da-d0a43e52605c-0000 exited with status 0
I0708 11:43:03.568176 350982144 slave.cpp:4267] Cleaning up executor 'default' of framework e055d60c-05ff-487e-82da-d0a43e52605c-0000
W0708 11:43:03.568258 348299264 master.cpp:5369] Ignoring unknown exited executor 'default' of framework e055d60c-05ff-487e-82da-d0a43e52605c-0000 on agent e055d60c-05ff-487e-82da-d0a43e52605c-S0 at slave(119)@127.0.0.1:50325 (localhost)
I0708 11:43:03.568584 348299264 gc.cpp:55] Scheduling '/var/folders/ny/tcvyblqj43s2gdh2_895v9nw0000gp/T/ContentType_MasterAPITest_Subscribe_0_VaPndX/slaves/e055d60c-05ff-487e-82da-d0a43e52605c-S0/frameworks/e055d60c-05ff-487e-82da-d0a43e52605c-0000/executors/default/runs/62add906-b60f-43ec-ab06-0514a798de26' for gc 6.99999342143407days in the future
I0708 11:43:03.568864 350982144 slave.cpp:4355] Cleaning up framework e055d60c-05ff-487e-82da-d0a43e52605c-0000
I0708 11:43:03.568879 352055296 gc.cpp:55] Scheduling '/var/folders/ny/tcvyblqj43s2gdh2_895v9nw0000gp/T/ContentType_MasterAPITest_Subscribe_0_VaPndX/slaves/e055d60c-05ff-487e-82da-d0a43e52605c-S0/frameworks/e055d60c-05ff-487e-82da-d0a43e52605c-0000/executors/default' for gc 6.99999341739556days in the future
I0708 11:43:03.569056 350445568 status_update_manager.cpp:282] Closing status update streams for framework e055d60c-05ff-487e-82da-d0a43e52605c-0000
I0708 11:43:03.569247 350982144 slave.cpp:841] Agent terminating
I0708 11:43:03.569239 348835840 gc.cpp:55] Scheduling '/var/folders/ny/tcvyblqj43s2gdh2_895v9nw0000gp/T/ContentType_MasterAPITest_Subscribe_0_VaPndX/slaves/e055d60c-05ff-487e-82da-d0a43e52605c-S0/frameworks/e055d60c-05ff-487e-82da-d0a43e52605c-0000' for gc 6.99999341315852days in the future
I0708 11:43:03.569524 350982144 master.cpp:1371] Agent e055d60c-05ff-487e-82da-d0a43e52605c-S0 at slave(119)@127.0.0.1:50325 (localhost) disconnected
I0708 11:43:03.569577 350982144 master.cpp:2910] Disconnecting agent e055d60c-05ff-487e-82da-d0a43e52605c-S0 at slave(119)@127.0.0.1:50325 (localhost)
I0708 11:43:03.569767 350982144 master.cpp:2929] Deactivating agent e055d60c-05ff-487e-82da-d0a43e52605c-S0 at slave(119)@127.0.0.1:50325 (localhost)
I0708 11:43:03.570020 349372416 hierarchical.cpp:571] Agent e055d60c-05ff-487e-82da-d0a43e52605c-S0 deactivated
../../src/tests/api_tests.cpp:1509: Failure
Actual function call count doesn't match EXPECT_CALL(*executor, acknowledged(_, _))...
         Expected: to be called once
           Actual: never called - unsatisfied and active
../../src/tests/api_tests.cpp:1505: Failure
Actual function call count doesn't match EXPECT_CALL(*executor, launch(_, _))...
         Expected: to be called once
           Actual: never called - unsatisfied and active
../../src/tests/api_tests.cpp:1503: Failure
Actual function call count doesn't match EXPECT_CALL(*executor, subscribed(_, _))...
         Expected: to be called once
           Actual: never called - unsatisfied and active
../../src/tests/api_tests.cpp:1496: Failure
Actual function call count doesn't match EXPECT_CALL(*scheduler, update(_, _))...
         Expected: to be called twice
           Actual: never called - unsatisfied and active
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)

On CentOS 7

[ 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)

Attachments

Activity

People

Assignee:: Anand Mazumdar

Reporter:: Zhitao Li

Shepherd:: Vinod Kone

Votes:: 0 Vote for this issue

Watchers:: 2 Start watching this issue

Dates

Created:: 08/Jul/16 18:48

Updated:: 26/Apr/17 17:00

Resolved:: 17/Jul/16 21:55