[ https://issues.apache.org/jira/browse/MESOS-5812?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15380232#comment-15380232 ]
Anand Mazumdar commented on MESOS-5812: --------------------------------------- Yep, I forgot updating this JIRA thereafter. https://reviews.apache.org/r/49837 : Flaky fix that showed up on ASF. https://reviews.apache.org/r/49844 : The FD leak that was discovered while fixing the flakiness. > 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 > Assignee: Anand Mazumdar > > This test seems to be flaky, although on Mac OS X and CentOS 7 the error a > bit different. > On Mac OS X: > {noformat}[ 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) > {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)