Return-Path: X-Original-To: archive-asf-public-internal@cust-asf2.ponee.io Delivered-To: archive-asf-public-internal@cust-asf2.ponee.io Received: from cust-asf.ponee.io (cust-asf.ponee.io [163.172.22.183]) by cust-asf2.ponee.io (Postfix) with ESMTP id DC6D0200C09 for ; Wed, 25 Jan 2017 20:35:45 +0100 (CET) Received: by cust-asf.ponee.io (Postfix) id DADD8160B4E; Wed, 25 Jan 2017 19:35:45 +0000 (UTC) Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by cust-asf.ponee.io (Postfix) with SMTP id 960C0160B3D for ; Wed, 25 Jan 2017 20:35:43 +0100 (CET) Received: (qmail 47088 invoked by uid 500); 25 Jan 2017 19:35:42 -0000 Mailing-List: contact issues-help@mesos.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@mesos.apache.org Delivered-To: mailing list issues@mesos.apache.org Received: (qmail 47078 invoked by uid 99); 25 Jan 2017 19:35:42 -0000 Received: from pnap-us-west-generic-nat.apache.org (HELO spamd2-us-west.apache.org) (209.188.14.142) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 25 Jan 2017 19:35:42 +0000 Received: from localhost (localhost [127.0.0.1]) by spamd2-us-west.apache.org (ASF Mail Server at spamd2-us-west.apache.org) with ESMTP id 17F461A0315 for ; Wed, 25 Jan 2017 19:35:42 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd2-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: -1.998 X-Spam-Level: X-Spam-Status: No, score=-1.998 tagged_above=-999 required=6.31 tests=[KAM_LAZY_DOMAIN_SECURITY=1, NORMAL_HTTP_TO_IP=0.001, RP_MATCHES_RCVD=-2.999] autolearn=disabled Received: from mx1-lw-us.apache.org ([10.40.0.8]) by localhost (spamd2-us-west.apache.org [10.40.0.9]) (amavisd-new, port 10024) with ESMTP id KOts7kSHX3uR for ; Wed, 25 Jan 2017 19:35:29 +0000 (UTC) Received: from mailrelay1-us-west.apache.org (mailrelay1-us-west.apache.org [209.188.14.139]) by mx1-lw-us.apache.org (ASF Mail Server at mx1-lw-us.apache.org) with ESMTP id 74D295FC75 for ; Wed, 25 Jan 2017 19:35:28 +0000 (UTC) Received: from jira-lw-us.apache.org (unknown [207.244.88.139]) by mailrelay1-us-west.apache.org (ASF Mail Server at mailrelay1-us-west.apache.org) with ESMTP id 20B77E0416 for ; Wed, 25 Jan 2017 19:35:27 +0000 (UTC) Received: from jira-lw-us.apache.org (localhost [127.0.0.1]) by jira-lw-us.apache.org (ASF Mail Server at jira-lw-us.apache.org) with ESMTP id 84CDD2528D for ; Wed, 25 Jan 2017 19:35:26 +0000 (UTC) Date: Wed, 25 Jan 2017 19:35:26 +0000 (UTC) From: "Michael Park (JIRA)" To: issues@mesos.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Created] (MESOS-6990) `PartitionTest.TaskCompletedOnPartitionedAgent` is flaky MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 archived-at: Wed, 25 Jan 2017 19:35:46 -0000 Michael Park created MESOS-6990: ----------------------------------- Summary: `PartitionTest.TaskCompletedOnPartitionedAgent` is fl= aky Key: MESOS-6990 URL: https://issues.apache.org/jira/browse/MESOS-6990 Project: Mesos Issue Type: Bug Components: tests Reporter: Michael Park Observed in the ASF Jenkins CI: {noformat} /mesos/src/tests/partition_tests.cpp:2055: Failure Actual function call count doesn't match EXPECT_CALL(sched, statusUpdate(&d= river, _))... Expected: to be called once Actual: never called - unsatisfied and active {noformat} Full log for the test: {noformat} [ RUN ] PartitionTest.TaskCompletedOnPartitionedAgent I0125 15:16:42.170163 25314 cluster.cpp:160] Creating default 'local' autho= rizer I0125 15:16:42.171134 25325 master.cpp:383] Master 6361cb74-ebfe-43e5-9927-= 652201a9677a (9cdefe4ff6bc) started on 172.17.0.3:57726 I0125 15:16:42.171160 25325 master.cpp:385] Flags at startup: --acls=3D"" -= -agent_ping_timeout=3D"15secs" --agent_reregister_timeout=3D"10mins" --allo= cation_interval=3D"1secs" --allocator=3D"HierarchicalDRF" --authenticate_ag= ents=3D"true" --authenticate_frameworks=3D"true" --authenticate_http_framew= orks=3D"true" --authenticate_http_readonly=3D"true" --authenticate_http_rea= dwrite=3D"true" --authenticators=3D"crammd5" --authorizers=3D"local" --cred= entials=3D"/tmp/GAnqYR/credentials" --framework_sorter=3D"drf" --help=3D"fa= lse" --hostname_lookup=3D"true" --http_authenticators=3D"basic" --http_fram= ework_authenticators=3D"basic" --initialize_driver_logging=3D"true" --log_a= uto_initialize=3D"true" --logbufsecs=3D"0" --logging_level=3D"INFO" --max_a= gent_ping_timeouts=3D"5" --max_completed_frameworks=3D"50" --max_completed_= tasks_per_framework=3D"1000" --max_unreachable_tasks_per_framework=3D"1000"= --quiet=3D"false" --recovery_agent_removal_limit=3D"100%" --registry=3D"in= _memory" --registry_fetch_timeout=3D"1mins" --registry_gc_interval=3D"15min= s" --registry_max_agent_age=3D"2weeks" --registry_max_agent_count=3D"102400= " --registry_store_timeout=3D"100secs" --registry_strict=3D"false" --root_s= ubmissions=3D"true" --user_sorter=3D"drf" --version=3D"false" --webui_dir= =3D"/usr/local/share/mesos/webui" --work_dir=3D"/tmp/GAnqYR/master" --zk_se= ssion_timeout=3D"10secs" I0125 15:16:42.171417 25325 master.cpp:435] Master only allowing authentica= ted frameworks to register I0125 15:16:42.171427 25325 master.cpp:449] Master only allowing authentica= ted agents to register I0125 15:16:42.171433 25325 master.cpp:462] Master only allowing authentica= ted HTTP frameworks to register I0125 15:16:42.171439 25325 credentials.hpp:37] Loading credentials for aut= hentication from '/tmp/GAnqYR/credentials' I0125 15:16:42.171571 25325 master.cpp:507] Using default 'crammd5' authent= icator I0125 15:16:42.171614 25325 http.cpp:922] Using default 'basic' HTTP authen= ticator for realm 'mesos-master-readonly' I0125 15:16:42.171658 25325 http.cpp:922] Using default 'basic' HTTP authen= ticator for realm 'mesos-master-readwrite' I0125 15:16:42.171684 25325 http.cpp:922] Using default 'basic' HTTP authen= ticator for realm 'mesos-master-scheduler' I0125 15:16:42.171710 25325 master.cpp:587] Authorization enabled I0125 15:16:42.172552 25325 hierarchical.cpp:151] Initialized hierarchical = allocator process I0125 15:16:42.172575 25325 whitelist_watcher.cpp:77] No whitelist given I0125 15:16:42.173259 25325 master.cpp:2121] Elected as the leading master! I0125 15:16:42.173274 25325 master.cpp:1643] Recovering from registrar I0125 15:16:42.173328 25325 registrar.cpp:329] Recovering registrar I0125 15:16:42.173552 25325 registrar.cpp:362] Successfully fetched the reg= istry (0B) in 0ns I0125 15:16:42.173588 25325 registrar.cpp:461] Applied 1 operations in 8907= ns; attempting to update the registry I0125 15:16:42.173854 25325 registrar.cpp:506] Successfully updated the reg= istry in 0ns I0125 15:16:42.173898 25325 registrar.cpp:392] Successfully recovered regis= trar I0125 15:16:42.174008 25325 master.cpp:1759] Recovered 0 agents from the re= gistry (129B); allowing 10mins for agents to re-register I0125 15:16:42.174048 25325 hierarchical.cpp:178] Skipping recovery of hier= archical allocator: nothing to recover I0125 15:16:42.175926 25314 cluster.cpp:446] Creating default 'local' autho= rizer I0125 15:16:42.176554 25321 slave.cpp:209] Mesos agent started on (93)@172.= 17.0.3:57726 I0125 15:16:42.176578 25321 slave.cpp:210] Flags at startup: --acls=3D"" --= appc_simple_discovery_uri_prefix=3D"http://" --appc_store_dir=3D"/tmp/mesos= /store/appc" --authenticate_http_readonly=3D"true" --authenticate_http_read= write=3D"true" --authenticatee=3D"crammd5" --authentication_backoff_factor= =3D"1secs" --authorizer=3D"local" --cgroups_cpu_enable_pids_and_tids_count= =3D"false" --cgroups_enable_cfs=3D"false" --cgroups_hierarchy=3D"/sys/fs/cg= roup" --cgroups_limit_swap=3D"false" --cgroups_root=3D"mesos" --container_d= isk_watch_interval=3D"15secs" --containerizers=3D"mesos" --credential=3D"/t= mp/PartitionTest_TaskCompletedOnPartitionedAgent_wlDVRc/credential" --defau= lt_role=3D"*" --disk_watch_interval=3D"1mins" --docker=3D"docker" --docker_= kill_orphans=3D"true" --docker_registry=3D"https://registry-1.docker.io" --= docker_remove_delay=3D"6hrs" --docker_socket=3D"/var/run/docker.sock" --doc= ker_stop_timeout=3D"0ns" --docker_store_dir=3D"/tmp/mesos/store/docker" --d= ocker_volume_checkpoint_dir=3D"/var/run/mesos/isolators/docker/volume" --en= force_container_disk_quota=3D"false" --executor_registration_timeout=3D"1mi= ns" --executor_shutdown_grace_period=3D"5secs" --fetcher_cache_dir=3D"/tmp/= PartitionTest_TaskCompletedOnPartitionedAgent_wlDVRc/fetch" --fetcher_cache= _size=3D"2GB" --frameworks_home=3D"" --gc_delay=3D"1weeks" --gc_disk_headro= om=3D"0.1" --hadoop_home=3D"" --help=3D"false" --hostname_lookup=3D"true" -= -http_authenticators=3D"basic" --http_command_executor=3D"false" --http_cre= dentials=3D"/tmp/PartitionTest_TaskCompletedOnPartitionedAgent_wlDVRc/http_= credentials" --http_heartbeat_interval=3D"30secs" --image_provisioner_backe= nd=3D"copy" --initialize_driver_logging=3D"true" --isolation=3D"posix/cpu,p= osix/mem" --launcher=3D"posix" --launcher_dir=3D"/mesos/build/src" --logbuf= secs=3D"0" --logging_level=3D"INFO" --max_completed_executors_per_framework= =3D"150" --oversubscribed_resources_interval=3D"15secs" --perf_duration=3D"= 10secs" --perf_interval=3D"1mins" --qos_correction_interval_min=3D"0ns" --q= uiet=3D"false" --recover=3D"reconnect" --recovery_timeout=3D"15mins" --regi= stration_backoff_factor=3D"10ms" --resources=3D"cpus:2;gpus:0;mem:1024;disk= :1024;ports:[31000-32000]" --revocable_cpu_low_priority=3D"true" --runtime_= dir=3D"/tmp/PartitionTest_TaskCompletedOnPartitionedAgent_wlDVRc" --sandbox= _directory=3D"/mnt/mesos/sandbox" --strict=3D"true" --switch_user=3D"true" = --systemd_enable_support=3D"true" --systemd_runtime_directory=3D"/run/syste= md/system" --version=3D"false" --work_dir=3D"/tmp/PartitionTest_TaskComplet= edOnPartitionedAgent_3cCaq2" I0125 15:16:42.176937 25321 credentials.hpp:86] Loading credential for auth= entication from '/tmp/PartitionTest_TaskCompletedOnPartitionedAgent_wlDVRc/= credential' I0125 15:16:42.177004 25321 slave.cpp:352] Agent using credential for: test= -principal I0125 15:16:42.177014 25321 credentials.hpp:37] Loading credentials for aut= hentication from '/tmp/PartitionTest_TaskCompletedOnPartitionedAgent_wlDVRc= /http_credentials' I0125 15:16:42.177088 25321 http.cpp:922] Using default 'basic' HTTP authen= ticator for realm 'mesos-agent-readonly' I0125 15:16:42.177129 25321 http.cpp:922] Using default 'basic' HTTP authen= ticator for realm 'mesos-agent-readwrite' I0125 15:16:42.177423 25321 slave.cpp:539] Agent resources: cpus(*):2; mem(= *):1024; disk(*):1024; ports(*):[31000-32000] I0125 15:16:42.177453 25321 slave.cpp:547] Agent attributes: [ ] I0125 15:16:42.177458 25321 slave.cpp:552] Agent hostname: 9cdefe4ff6bc I0125 15:16:42.177510 25328 status_update_manager.cpp:177] Pausing sending = status updates I0125 15:16:42.177903 25327 state.cpp:60] Recovering state from '/tmp/Parti= tionTest_TaskCompletedOnPartitionedAgent_3cCaq2/meta' I0125 15:16:42.178035 25318 status_update_manager.cpp:203] Recovering statu= s update manager I0125 15:16:42.178190 25330 slave.cpp:5422] Finished recovery I0125 15:16:42.178570 25330 slave.cpp:5596] Querying resource estimator for= oversubscribable resources I0125 15:16:42.178709 25330 slave.cpp:929] New master detected at master@17= 2.17.0.3:57726 I0125 15:16:42.178733 25330 slave.cpp:964] Detecting new master I0125 15:16:42.178745 25314 sched.cpp:232] Version: 1.2.0 I0125 15:16:42.178773 25330 slave.cpp:5610] Received oversubscribable resou= rces {} from the resource estimator I0125 15:16:42.178813 25323 status_update_manager.cpp:177] Pausing sending = status updates I0125 15:16:42.178964 25323 sched.cpp:336] New master detected at master@17= 2.17.0.3:57726 I0125 15:16:42.178993 25323 sched.cpp:407] Authenticating with master maste= r@172.17.0.3:57726 I0125 15:16:42.179003 25323 sched.cpp:414] Using default CRAM-MD5 authentic= atee I0125 15:16:42.179086 25323 authenticatee.cpp:121] Creating new client SASL= connection I0125 15:16:42.179247 25323 master.cpp:7001] Authenticating scheduler-d2652= 1d5-3415-4739-ad0f-b828c3e00a34@172.17.0.3:57726 I0125 15:16:42.179306 25323 authenticator.cpp:414] Starting authentication = session for crammd5-authenticatee(217)@172.17.0.3:57726 I0125 15:16:42.179375 25323 authenticator.cpp:98] Creating new server SASL = connection I0125 15:16:42.179497 25323 authenticatee.cpp:213] Received SASL authentica= tion mechanisms: CRAM-MD5 I0125 15:16:42.179522 25323 authenticatee.cpp:239] Attempting to authentica= te with mechanism 'CRAM-MD5' I0125 15:16:42.179559 25323 authenticator.cpp:204] Received SASL authentica= tion start I0125 15:16:42.179605 25323 authenticator.cpp:326] Authentication requires = more steps I0125 15:16:42.179641 25323 authenticatee.cpp:259] Received SASL authentica= tion step I0125 15:16:42.179685 25323 authenticator.cpp:232] Received SASL authentica= tion step I0125 15:16:42.179704 25323 auxprop.cpp:109] Request to lookup properties f= or user: 'test-principal' realm: '9cdefe4ff6bc' server FQDN: '9cdefe4ff6bc'= SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_= AUXPROP_AUTHZID: false=20 I0125 15:16:42.179715 25323 auxprop.cpp:181] Looking up auxiliary property = '*userPassword' I0125 15:16:42.179730 25323 auxprop.cpp:181] Looking up auxiliary property = '*cmusaslsecretCRAM-MD5' I0125 15:16:42.179744 25323 auxprop.cpp:109] Request to lookup properties f= or user: 'test-principal' realm: '9cdefe4ff6bc' server FQDN: '9cdefe4ff6bc'= SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_= AUXPROP_AUTHZID: true=20 I0125 15:16:42.179754 25323 auxprop.cpp:131] Skipping auxiliary property '*= userPassword' since SASL_AUXPROP_AUTHZID =3D=3D true I0125 15:16:42.179762 25323 auxprop.cpp:131] Skipping auxiliary property '*= cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID =3D=3D true I0125 15:16:42.179778 25323 authenticator.cpp:318] Authentication success I0125 15:16:42.179831 25323 authenticatee.cpp:299] Authentication success I0125 15:16:42.179862 25323 master.cpp:7031] Successfully authenticated pri= ncipal 'test-principal' at scheduler-d26521d5-3415-4739-ad0f-b828c3e00a34@1= 72.17.0.3:57726 I0125 15:16:42.179890 25323 authenticator.cpp:432] Authentication session c= leanup for crammd5-authenticatee(217)@172.17.0.3:57726 I0125 15:16:42.179970 25323 sched.cpp:513] Successfully authenticated with = master master@172.17.0.3:57726 I0125 15:16:42.179983 25323 sched.cpp:836] Sending SUBSCRIBE call to master= @172.17.0.3:57726 I0125 15:16:42.180016 25323 sched.cpp:869] Will retry registration in 1.440= 407408secs if necessary I0125 15:16:42.180097 25323 master.cpp:2734] Received SUBSCRIBE call for fr= amework 'default' at scheduler-d26521d5-3415-4739-ad0f-b828c3e00a34@172.17.= 0.3:57726 I0125 15:16:42.180112 25323 master.cpp:2157] Authorizing framework principa= l 'test-principal' to receive offers for role '*' I0125 15:16:42.180222 25323 master.cpp:2810] Subscribing framework default = with checkpointing disabled and capabilities [ ] I0125 15:16:42.180383 25323 hierarchical.cpp:271] Added framework 6361cb74-= ebfe-43e5-9927-652201a9677a-0000 I0125 15:16:42.180404 25323 hierarchical.cpp:1677] No allocations performed I0125 15:16:42.180414 25323 hierarchical.cpp:1772] No inverse offers to sen= d out! I0125 15:16:42.180426 25323 hierarchical.cpp:1279] Performed allocation for= 0 agents in 33111ns I0125 15:16:42.180522 25323 sched.cpp:759] Framework registered with 6361cb= 74-ebfe-43e5-9927-652201a9677a-0000 I0125 15:16:42.180546 25323 sched.cpp:773] Scheduler::registered took 15260= ns I0125 15:16:42.180716 25321 slave.cpp:991] Authenticating with master maste= r@172.17.0.3:57726 I0125 15:16:42.180738 25321 slave.cpp:1002] Using default CRAM-MD5 authenti= catee I0125 15:16:42.180799 25321 authenticatee.cpp:121] Creating new client SASL= connection I0125 15:16:42.180920 25321 master.cpp:7001] Authenticating slave(93)@172.1= 7.0.3:57726 I0125 15:16:42.180964 25321 authenticator.cpp:414] Starting authentication = session for crammd5-authenticatee(218)@172.17.0.3:57726 I0125 15:16:42.181020 25321 authenticator.cpp:98] Creating new server SASL = connection I0125 15:16:42.181123 25321 authenticatee.cpp:213] Received SASL authentica= tion mechanisms: CRAM-MD5 I0125 15:16:42.181144 25321 authenticatee.cpp:239] Attempting to authentica= te with mechanism 'CRAM-MD5' I0125 15:16:42.181177 25321 authenticator.cpp:204] Received SASL authentica= tion start I0125 15:16:42.181210 25321 authenticator.cpp:326] Authentication requires = more steps I0125 15:16:42.181243 25321 authenticatee.cpp:259] Received SASL authentica= tion step I0125 15:16:42.181291 25321 authenticator.cpp:232] Received SASL authentica= tion step I0125 15:16:42.181308 25321 auxprop.cpp:109] Request to lookup properties f= or user: 'test-principal' realm: '9cdefe4ff6bc' server FQDN: '9cdefe4ff6bc'= SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_= AUXPROP_AUTHZID: false=20 I0125 15:16:42.181319 25321 auxprop.cpp:181] Looking up auxiliary property = '*userPassword' I0125 15:16:42.181329 25321 auxprop.cpp:181] Looking up auxiliary property = '*cmusaslsecretCRAM-MD5' I0125 15:16:42.181341 25321 auxprop.cpp:109] Request to lookup properties f= or user: 'test-principal' realm: '9cdefe4ff6bc' server FQDN: '9cdefe4ff6bc'= SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_= AUXPROP_AUTHZID: true=20 I0125 15:16:42.181351 25321 auxprop.cpp:131] Skipping auxiliary property '*= userPassword' since SASL_AUXPROP_AUTHZID =3D=3D true I0125 15:16:42.181360 25321 auxprop.cpp:131] Skipping auxiliary property '*= cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID =3D=3D true I0125 15:16:42.181375 25321 authenticator.cpp:318] Authentication success I0125 15:16:42.181414 25321 authenticatee.cpp:299] Authentication success I0125 15:16:42.181443 25321 master.cpp:7031] Successfully authenticated pri= ncipal 'test-principal' at slave(93)@172.17.0.3:57726 I0125 15:16:42.181471 25321 authenticator.cpp:432] Authentication session c= leanup for crammd5-authenticatee(218)@172.17.0.3:57726 I0125 15:16:42.181548 25321 slave.cpp:1086] Successfully authenticated with= master master@172.17.0.3:57726 I0125 15:16:42.181596 25321 slave.cpp:1508] Will retry registration in 19.2= 50331ms if necessary I0125 15:16:42.181694 25321 master.cpp:5299] Registering agent at slave(93)= @172.17.0.3:57726 (9cdefe4ff6bc) with id 6361cb74-ebfe-43e5-9927-652201a967= 7a-S0 I0125 15:16:42.181819 25321 registrar.cpp:461] Applied 1 operations in 1927= 5ns; attempting to update the registry I0125 15:16:42.182193 25321 registrar.cpp:506] Successfully updated the reg= istry in 0ns I0125 15:16:42.182413 25321 master.cpp:5370] Registered agent 6361cb74-ebfe= -43e5-9927-652201a9677a-S0 at slave(93)@172.17.0.3:57726 (9cdefe4ff6bc) wit= h cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I0125 15:16:42.182545 25321 hierarchical.cpp:478] Added agent 6361cb74-ebfe= -43e5-9927-652201a9677a-S0 (9cdefe4ff6bc) with cpus(*):2; mem(*):1024; disk= (*):1024; ports(*):[31000-32000] (allocated: {}) I0125 15:16:42.182763 25321 hierarchical.cpp:1772] No inverse offers to sen= d out! I0125 15:16:42.182782 25321 hierarchical.cpp:1302] Performed allocation for= agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0 in 218565ns I0125 15:16:42.182821 25321 slave.cpp:1132] Registered with master master@1= 72.17.0.3:57726; given agent ID 6361cb74-ebfe-43e5-9927-652201a9677a-S0 I0125 15:16:42.182834 25321 fetcher.cpp:90] Clearing fetcher cache I0125 15:16:42.183110 25321 slave.cpp:1160] Checkpointing SlaveInfo to '/tm= p/PartitionTest_TaskCompletedOnPartitionedAgent_3cCaq2/meta/slaves/6361cb74= -ebfe-43e5-9927-652201a9677a-S0/slave.info' I0125 15:16:42.183348 25321 slave.cpp:1198] Forwarding total oversubscribed= resources {} I0125 15:16:42.183396 25321 slave.cpp:4286] Received ping from slave-observ= er(93)@172.17.0.3:57726 I0125 15:16:42.183537 25321 master.cpp:6830] Sending 1 offers to framework = 6361cb74-ebfe-43e5-9927-652201a9677a-0000 (default) at scheduler-d26521d5-3= 415-4739-ad0f-b828c3e00a34@172.17.0.3:57726 I0125 15:16:42.183598 25321 master.cpp:5863] Received update of agent 6361c= b74-ebfe-43e5-9927-652201a9677a-S0 at slave(93)@172.17.0.3:57726 (9cdefe4ff= 6bc) with total oversubscribed resources {} I0125 15:16:42.183658 25321 status_update_manager.cpp:184] Resuming sending= status updates I0125 15:16:42.183769 25321 sched.cpp:933] Scheduler::resourceOffers took 3= 4059ns I0125 15:16:42.183820 25321 hierarchical.cpp:548] Agent 6361cb74-ebfe-43e5-= 9927-652201a9677a-S0 (9cdefe4ff6bc) updated with oversubscribed resources {= } (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], all= ocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) I0125 15:16:42.183866 25321 hierarchical.cpp:1677] No allocations performed I0125 15:16:42.183876 25321 hierarchical.cpp:1772] No inverse offers to sen= d out! I0125 15:16:42.183886 25321 hierarchical.cpp:1302] Performed allocation for= agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0 in 40916ns I0125 15:16:42.184298 25325 master.cpp:3728] Processing ACCEPT call for off= ers: [ 6361cb74-ebfe-43e5-9927-652201a9677a-O0 ] on agent 6361cb74-ebfe-43e= 5-9927-652201a9677a-S0 at slave(93)@172.17.0.3:57726 (9cdefe4ff6bc) for fra= mework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 (default) at scheduler-d26= 521d5-3415-4739-ad0f-b828c3e00a34@172.17.0.3:57726 I0125 15:16:42.184329 25325 master.cpp:3316] Authorizing framework principa= l 'test-principal' to launch task 1 W0125 15:16:42.184788 25325 validation.cpp:1018] Executor 'default' for tas= k '1' uses less CPUs (None) than the minimum required (0.01). Please update= your executor, as this will be mandatory in future releases. W0125 15:16:42.184808 25325 validation.cpp:1030] Executor 'default' for tas= k '1' uses less memory (None) than the minimum required (32MB). Please upda= te your executor, as this will be mandatory in future releases. I0125 15:16:42.184877 25325 master.cpp:8882] Adding task 1 with resources c= pus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on agent 6361cb= 74-ebfe-43e5-9927-652201a9677a-S0 at slave(93)@172.17.0.3:57726 (9cdefe4ff6= bc) I0125 15:16:42.184931 25325 master.cpp:4378] Launching task 1 of framework = 6361cb74-ebfe-43e5-9927-652201a9677a-0000 (default) at scheduler-d26521d5-3= 415-4739-ad0f-b828c3e00a34@172.17.0.3:57726 with resources cpus(*):2; mem(*= ):1024; disk(*):1024; ports(*):[31000-32000] on agent 6361cb74-ebfe-43e5-99= 27-652201a9677a-S0 at slave(93)@172.17.0.3:57726 (9cdefe4ff6bc) I0125 15:16:42.185075 25316 slave.cpp:1576] Got assigned task '1' for frame= work 6361cb74-ebfe-43e5-9927-652201a9677a-0000 I0125 15:16:42.185384 25316 slave.cpp:1736] Launching task '1' for framewor= k 6361cb74-ebfe-43e5-9927-652201a9677a-0000 I0125 15:16:42.185916 25316 paths.cpp:547] Trying to chown '/tmp/PartitionT= est_TaskCompletedOnPartitionedAgent_3cCaq2/slaves/6361cb74-ebfe-43e5-9927-6= 52201a9677a-S0/frameworks/6361cb74-ebfe-43e5-9927-652201a9677a-0000/executo= rs/default/runs/5aa95fbe-c14f-4d50-9f28-6a605d3a212a' to user 'mesos' I0125 15:16:42.186097 25316 slave.cpp:6331] Launching executor 'default' of= framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 with resources {} in w= ork directory '/tmp/PartitionTest_TaskCompletedOnPartitionedAgent_3cCaq2/sl= aves/6361cb74-ebfe-43e5-9927-652201a9677a-S0/frameworks/6361cb74-ebfe-43e5-= 9927-652201a9677a-0000/executors/default/runs/5aa95fbe-c14f-4d50-9f28-6a605= d3a212a' I0125 15:16:42.186307 25316 slave.cpp:2058] Queued task '1' for executor 'd= efault' of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 I0125 15:16:42.187432 25316 exec.cpp:162] Version: 1.2.0 I0125 15:16:42.187597 25316 slave.cpp:882] Successfully attached file '/tmp= /PartitionTest_TaskCompletedOnPartitionedAgent_3cCaq2/slaves/6361cb74-ebfe-= 43e5-9927-652201a9677a-S0/frameworks/6361cb74-ebfe-43e5-9927-652201a9677a-0= 000/executors/default/runs/5aa95fbe-c14f-4d50-9f28-6a605d3a212a' I0125 15:16:42.187671 25316 exec.cpp:212] Executor started at: executor(35)= @172.17.0.3:57726 with pid 25314 I0125 15:16:42.187741 25316 slave.cpp:3325] Got registration for executor '= default' of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 from execut= or(35)@172.17.0.3:57726 I0125 15:16:42.187927 25316 exec.cpp:237] Executor registered on agent 6361= cb74-ebfe-43e5-9927-652201a9677a-S0 I0125 15:16:42.187952 25316 exec.cpp:249] Executor::registered took 15906ns I0125 15:16:42.188055 25316 slave.cpp:2271] Sending queued task '1' to exec= utor 'default' of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 at ex= ecutor(35)@172.17.0.3:57726 I0125 15:16:42.188148 25316 exec.cpp:320] Executor asked to run task '1' I0125 15:16:42.188211 25316 exec.cpp:329] Executor::launchTask took 55213ns I0125 15:16:42.188321 25324 exec.cpp:546] Executor sending status update TA= SK_RUNNING (UUID: 18117425-d755-4536-b9e6-5749a3260021) for task 1 of frame= work 6361cb74-ebfe-43e5-9927-652201a9677a-0000 I0125 15:16:42.188499 25319 slave.cpp:3756] Handling status update TASK_RUN= NING (UUID: 18117425-d755-4536-b9e6-5749a3260021) for task 1 of framework 6= 361cb74-ebfe-43e5-9927-652201a9677a-0000 from executor(35)@172.17.0.3:57726 I0125 15:16:42.188787 25319 status_update_manager.cpp:323] Received status = update TASK_RUNNING (UUID: 18117425-d755-4536-b9e6-5749a3260021) for task 1= of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 I0125 15:16:42.188809 25319 status_update_manager.cpp:500] Creating StatusU= pdate stream for task 1 of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0= 000 I0125 15:16:42.188954 25319 status_update_manager.cpp:377] Forwarding updat= e TASK_RUNNING (UUID: 18117425-d755-4536-b9e6-5749a3260021) for task 1 of f= ramework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 to the agent I0125 15:16:42.189065 25319 slave.cpp:4196] Forwarding the update TASK_RUNN= ING (UUID: 18117425-d755-4536-b9e6-5749a3260021) for task 1 of framework 63= 61cb74-ebfe-43e5-9927-652201a9677a-0000 to master@172.17.0.3:57726 I0125 15:16:42.189131 25319 slave.cpp:4090] Status update manager successfu= lly handled status update TASK_RUNNING (UUID: 18117425-d755-4536-b9e6-5749a= 3260021) for task 1 of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 I0125 15:16:42.189152 25319 slave.cpp:4106] Sending acknowledgement for sta= tus update TASK_RUNNING (UUID: 18117425-d755-4536-b9e6-5749a3260021) for ta= sk 1 of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 to executor(35)= @172.17.0.3:57726 I0125 15:16:42.189227 25319 master.cpp:6008] Status update TASK_RUNNING (UU= ID: 18117425-d755-4536-b9e6-5749a3260021) for task 1 of framework 6361cb74-= ebfe-43e5-9927-652201a9677a-0000 from agent 6361cb74-ebfe-43e5-9927-652201a= 9677a-S0 at slave(93)@172.17.0.3:57726 (9cdefe4ff6bc) I0125 15:16:42.189252 25319 master.cpp:6076] Forwarding status update TASK_= RUNNING (UUID: 18117425-d755-4536-b9e6-5749a3260021) for task 1 of framewor= k 6361cb74-ebfe-43e5-9927-652201a9677a-0000 I0125 15:16:42.189299 25319 master.cpp:8138] Updating the state of task 1 o= f framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 (latest state: TASK_R= UNNING, status update state: TASK_RUNNING) I0125 15:16:42.189342 25319 exec.cpp:369] Executor received status update a= cknowledgement 18117425-d755-4536-b9e6-5749a3260021 for task 1 of framework= 6361cb74-ebfe-43e5-9927-652201a9677a-0000 I0125 15:16:42.189419 25319 sched.cpp:1041] Scheduler::statusUpdate took 16= 303ns I0125 15:16:42.189539 25319 master.cpp:5015] Processing ACKNOWLEDGE call 18= 117425-d755-4536-b9e6-5749a3260021 for task 1 of framework 6361cb74-ebfe-43= e5-9927-652201a9677a-0000 (default) at scheduler-d26521d5-3415-4739-ad0f-b8= 28c3e00a34@172.17.0.3:57726 on agent 6361cb74-ebfe-43e5-9927-652201a9677a-S= 0 I0125 15:16:42.189623 25319 status_update_manager.cpp:395] Received status = update acknowledgement (UUID: 18117425-d755-4536-b9e6-5749a3260021) for tas= k 1 of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 I0125 15:16:42.189699 25319 slave.cpp:3045] Status update manager successfu= lly handled status update acknowledgement (UUID: 18117425-d755-4536-b9e6-57= 49a3260021) for task 1 of framework 6361cb74-ebfe-43e5-9927-652201a9677a-00= 00 I0125 15:16:42.189985 25319 hierarchical.cpp:1677] No allocations performed I0125 15:16:42.190217 25319 hierarchical.cpp:1772] No inverse offers to sen= d out! I0125 15:16:42.190347 25319 hierarchical.cpp:1279] Performed allocation for= 1 agents in 391006ns I0125 15:16:42.190134 25330 slave.cpp:5596] Querying resource estimator for= oversubscribable resources I0125 15:16:42.190619 25319 slave.cpp:4286] Received ping from slave-observ= er(93)@172.17.0.3:57726 I0125 15:16:42.190814 25319 slave.cpp:5610] Received oversubscribable resou= rces {} from the resource estimator I0125 15:16:42.191201 25330 hierarchical.cpp:1677] No allocations performed I0125 15:16:42.191373 25330 hierarchical.cpp:1772] No inverse offers to sen= d out! I0125 15:16:42.191480 25330 hierarchical.cpp:1279] Performed allocation for= 1 agents in 305591ns I0125 15:16:42.191308 25326 slave.cpp:5596] Querying resource estimator for= oversubscribable resources I0125 15:16:42.191682 25326 slave.cpp:4286] Received ping from slave-observ= er(93)@172.17.0.3:57726 I0125 15:16:42.191872 25326 slave.cpp:5610] Received oversubscribable resou= rces {} from the resource estimator I0125 15:16:42.192205 25317 hierarchical.cpp:1677] No allocations performed I0125 15:16:42.192353 25317 hierarchical.cpp:1772] No inverse offers to sen= d out! I0125 15:16:42.192467 25317 hierarchical.cpp:1279] Performed allocation for= 1 agents in 303235ns I0125 15:16:42.192337 25326 slave.cpp:5596] Querying resource estimator for= oversubscribable resources I0125 15:16:42.192814 25326 slave.cpp:4286] Received ping from slave-observ= er(93)@172.17.0.3:57726 I0125 15:16:42.193055 25320 slave.cpp:5610] Received oversubscribable resou= rces {} from the resource estimator I0125 15:16:42.193411 25328 slave.cpp:5596] Querying resource estimator for= oversubscribable resources I0125 15:16:42.193467 25328 slave.cpp:4286] Received ping from slave-observ= er(93)@172.17.0.3:57726 I0125 15:16:42.193518 25328 slave.cpp:5189] Current disk usage 10.11%. Max = allowed age: 5.592125848493229days I0125 15:16:42.193629 25328 slave.cpp:5610] Received oversubscribable resou= rces {} from the resource estimator I0125 15:16:42.193706 25326 hierarchical.cpp:1677] No allocations performed I0125 15:16:42.193720 25326 hierarchical.cpp:1772] No inverse offers to sen= d out! I0125 15:16:42.193733 25326 hierarchical.cpp:1279] Performed allocation for= 1 agents in 54039ns I0125 15:16:42.193912 25320 hierarchical.cpp:1677] No allocations performed I0125 15:16:42.193925 25320 hierarchical.cpp:1772] No inverse offers to sen= d out! I0125 15:16:42.193939 25320 hierarchical.cpp:1279] Performed allocation for= 1 agents in 53293ns I0125 15:16:42.194070 25330 master.cpp:6236] Marking agent 6361cb74-ebfe-43= e5-9927-652201a9677a-S0 at slave(93)@172.17.0.3:57726 (9cdefe4ff6bc) unreac= hable: health check timed out I0125 15:16:42.194226 25330 registrar.cpp:461] Applied 1 operations in 3675= 5ns; attempting to update the registry I0125 15:16:42.194615 25330 registrar.cpp:506] Successfully updated the reg= istry in 0ns I0125 15:16:42.194725 25330 master.cpp:6284] Marked agent 6361cb74-ebfe-43e= 5-9927-652201a9677a-S0 at slave(93)@172.17.0.3:57726 (9cdefe4ff6bc) unreach= able: health check timed out I0125 15:16:42.194778 25330 master.cpp:8138] Updating the state of task 1 o= f framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 (latest state: TASK_L= OST, status update state: TASK_LOST) I0125 15:16:42.194928 25330 master.cpp:8232] Removing task 1 with resources= cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework = 6361cb74-ebfe-43e5-9927-652201a9677a-0000 on agent 6361cb74-ebfe-43e5-9927-= 652201a9677a-S0 at slave(93)@172.17.0.3:57726 (9cdefe4ff6bc) I0125 15:16:42.195008 25330 master.cpp:6071] Sending status update TASK_LOS= T for task 1 of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 'Agent = 9cdefe4ff6bc is unreachable: health check timed out' I0125 15:16:42.195078 25330 master.cpp:8261] Removing executor 'default' wi= th resources {} of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 on a= gent 6361cb74-ebfe-43e5-9927-652201a9677a-S0 at slave(93)@172.17.0.3:57726 = (9cdefe4ff6bc) I0125 15:16:42.195186 25330 master.cpp:2038] Notifying framework 6361cb74-e= bfe-43e5-9927-652201a9677a-0000 (default) at scheduler-d26521d5-3415-4739-a= d0f-b828c3e00a34@172.17.0.3:57726 of lost agent 6361cb74-ebfe-43e5-9927-652= 201a9677a-S0 (9cdefe4ff6bc) I0125 15:16:42.195349 25330 hierarchical.cpp:510] Removed agent 6361cb74-eb= fe-43e5-9927-652201a9677a-S0 I0125 15:16:42.195626 25330 sched.cpp:1041] Scheduler::statusUpdate took 29= 701ns I0125 15:16:42.195675 25330 sched.cpp:1103] Lost agent 6361cb74-ebfe-43e5-9= 927-652201a9677a-S0 I0125 15:16:42.195703 25330 sched.cpp:1114] Scheduler::slaveLost took 19580= ns I0125 15:16:42.195803 25320 slave.cpp:5596] Querying resource estimator for= oversubscribable resources I0125 15:16:42.195927 25320 slave.cpp:4286] Received ping from slave-observ= er(93)@172.17.0.3:57726 I0125 15:16:42.196137 25320 slave.cpp:5610] Received oversubscribable resou= rces {} from the resource estimator I0125 15:16:42.196570 25325 slave.cpp:922] Lost leading master I0125 15:16:42.196722 25321 status_update_manager.cpp:177] Pausing sending = status updates I0125 15:16:42.196892 25325 slave.cpp:964] Detecting new master I0125 15:16:42.197209 25325 slave.cpp:929] New master detected at master@17= 2.17.0.3:57726 I0125 15:16:42.197353 25325 slave.cpp:964] Detecting new master I0125 15:16:42.197535 25325 slave.cpp:991] Authenticating with master maste= r@172.17.0.3:57726 I0125 15:16:42.197669 25325 slave.cpp:1002] Using default CRAM-MD5 authenti= catee I0125 15:16:42.197832 25325 status_update_manager.cpp:177] Pausing sending = status updates I0125 15:16:42.198011 25325 authenticatee.cpp:121] Creating new client SASL= connection I0125 15:16:42.198261 25325 master.cpp:7001] Authenticating slave(93)@172.1= 7.0.3:57726 I0125 15:16:42.198429 25325 authenticator.cpp:414] Starting authentication = session for crammd5-authenticatee(219)@172.17.0.3:57726 I0125 15:16:42.198621 25325 authenticator.cpp:98] Creating new server SASL = connection I0125 15:16:42.198868 25325 authenticatee.cpp:213] Received SASL authentica= tion mechanisms: CRAM-MD5 I0125 15:16:42.199010 25325 authenticatee.cpp:239] Attempting to authentica= te with mechanism 'CRAM-MD5' I0125 15:16:42.199162 25325 authenticator.cpp:204] Received SASL authentica= tion start I0125 15:16:42.199326 25325 authenticator.cpp:326] Authentication requires = more steps I0125 15:16:42.199478 25325 authenticatee.cpp:259] Received SASL authentica= tion step I0125 15:16:42.199645 25325 authenticator.cpp:232] Received SASL authentica= tion step I0125 15:16:42.199780 25325 auxprop.cpp:109] Request to lookup properties f= or user: 'test-principal' realm: '9cdefe4ff6bc' server FQDN: '9cdefe4ff6bc'= SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_= AUXPROP_AUTHZID: false=20 I0125 15:16:42.199906 25325 auxprop.cpp:181] Looking up auxiliary property = '*userPassword' I0125 15:16:42.200032 25325 auxprop.cpp:181] Looking up auxiliary property = '*cmusaslsecretCRAM-MD5' I0125 15:16:42.200166 25325 auxprop.cpp:109] Request to lookup properties f= or user: 'test-principal' realm: '9cdefe4ff6bc' server FQDN: '9cdefe4ff6bc'= SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_= AUXPROP_AUTHZID: true=20 I0125 15:16:42.200287 25325 auxprop.cpp:131] Skipping auxiliary property '*= userPassword' since SASL_AUXPROP_AUTHZID =3D=3D true I0125 15:16:42.200405 25325 auxprop.cpp:131] Skipping auxiliary property '*= cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID =3D=3D true I0125 15:16:42.200536 25325 authenticator.cpp:318] Authentication success I0125 15:16:42.200724 25325 authenticatee.cpp:299] Authentication success I0125 15:16:42.200877 25325 master.cpp:7031] Successfully authenticated pri= ncipal 'test-principal' at slave(93)@172.17.0.3:57726 I0125 15:16:42.201025 25325 authenticator.cpp:432] Authentication session c= leanup for crammd5-authenticatee(219)@172.17.0.3:57726 I0125 15:16:42.201233 25325 slave.cpp:1086] Successfully authenticated with= master master@172.17.0.3:57726 I0125 15:16:42.201454 25325 slave.cpp:1508] Will retry registration in 8.04= 2063ms if necessary I0125 15:16:42.201716 25325 master.cpp:5522] Re-registering agent 6361cb74-= ebfe-43e5-9927-652201a9677a-S0 at slave(93)@172.17.0.3:57726 (9cdefe4ff6bc) I0125 15:16:42.202100 25325 registrar.cpp:461] Applied 1 operations in 2596= 9ns; attempting to update the registry I0125 15:16:42.202669 25325 registrar.cpp:506] Successfully updated the reg= istry in 0ns I0125 15:16:42.203146 25325 master.cpp:5694] Re-registered agent 6361cb74-e= bfe-43e5-9927-652201a9677a-S0 at slave(93)@172.17.0.3:57726 (9cdefe4ff6bc) = with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I0125 15:16:42.203568 25325 master.cpp:5714] Shutting down framework 6361cb= 74-ebfe-43e5-9927-652201a9677a-0000 at re-registered agent 6361cb74-ebfe-43= e5-9927-652201a9677a-S0 at slave(93)@172.17.0.3:57726 (9cdefe4ff6bc) becaus= e the framework is not partition-aware I0125 15:16:42.203729 25325 master.cpp:5802] Sending updated checkpointed r= esources {} to agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0 at slave(93)@1= 72.17.0.3:57726 (9cdefe4ff6bc) I0125 15:16:42.203348 25330 hierarchical.cpp:478] Added agent 6361cb74-ebfe= -43e5-9927-652201a9677a-S0 (9cdefe4ff6bc) with cpus(*):2; mem(*):1024; disk= (*):1024; ports(*):[31000-32000] (allocated: {}) I0125 15:16:42.204207 25330 hierarchical.cpp:1772] No inverse offers to sen= d out! I0125 15:16:42.204551 25330 hierarchical.cpp:1302] Performed allocation for= agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0 in 556594ns I0125 15:16:42.204411 25326 master.cpp:6830] Sending 1 offers to framework = 6361cb74-ebfe-43e5-9927-652201a9677a-0000 (default) at scheduler-d26521d5-3= 415-4739-ad0f-b828c3e00a34@172.17.0.3:57726 I0125 15:16:42.204952 25326 sched.cpp:933] Scheduler::resourceOffers took 1= 9578ns I0125 15:16:42.203431 25327 slave.cpp:1240] Re-registered with master maste= r@172.17.0.3:57726 I0125 15:16:42.205257 25327 slave.cpp:1277] Forwarding total oversubscribed= resources {} I0125 15:16:42.205466 25327 slave.cpp:4286] Received ping from slave-observ= er(94)@172.17.0.3:57726 I0125 15:16:42.205631 25327 slave.cpp:2598] Asked to shut down framework 63= 61cb74-ebfe-43e5-9927-652201a9677a-0000 by master@172.17.0.3:57726 I0125 15:16:42.205770 25327 slave.cpp:2623] Shutting down framework 6361cb7= 4-ebfe-43e5-9927-652201a9677a-0000 I0125 15:16:42.205899 25327 slave.cpp:5005] Shutting down executor 'default= ' of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 at executor(35)@17= 2.17.0.3:57726 W0125 15:16:42.206079 25327 slave.cpp:2763] Ignoring updating pid for frame= work 6361cb74-ebfe-43e5-9927-652201a9677a-0000 because it is terminating I0125 15:16:42.205346 25318 status_update_manager.cpp:184] Resuming sending= status updates I0125 15:16:42.206244 25319 master.cpp:5863] Received update of agent 6361c= b74-ebfe-43e5-9927-652201a9677a-S0 at slave(93)@172.17.0.3:57726 (9cdefe4ff= 6bc) with total oversubscribed resources {} I0125 15:16:42.206284 25327 slave.cpp:2830] Ignoring new checkpointed resou= rces identical to the current version: {} I0125 15:16:42.196985 25316 exec.cpp:546] Executor sending status update TA= SK_FINISHED (UUID: f76e9293-a5c4-4e9b-8e68-974a4a671f81) for task 1 of fram= ework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 I0125 15:16:42.206491 25329 hierarchical.cpp:548] Agent 6361cb74-ebfe-43e5-= 9927-652201a9677a-S0 (9cdefe4ff6bc) updated with oversubscribed resources {= } (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], all= ocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) I0125 15:16:42.206758 25329 hierarchical.cpp:1677] No allocations performed I0125 15:16:42.206795 25329 hierarchical.cpp:1772] No inverse offers to sen= d out! I0125 15:16:42.206827 25316 exec.cpp:410] Executor asked to shutdown I0125 15:16:42.207140 25316 exec.cpp:425] Executor::shutdown took 24713ns I0125 15:16:42.206925 25328 slave.cpp:3756] Handling status update TASK_FIN= ISHED (UUID: f76e9293-a5c4-4e9b-8e68-974a4a671f81) for task 1 of framework = 6361cb74-ebfe-43e5-9927-652201a9677a-0000 from executor(35)@172.17.0.3:5772= 6 W0125 15:16:42.207347 25328 slave.cpp:3825] Ignoring status update TASK_FIN= ISHED (UUID: f76e9293-a5c4-4e9b-8e68-974a4a671f81) for task 1 of framework = 6361cb74-ebfe-43e5-9927-652201a9677a-0000 for terminating framework 6361cb7= 4-ebfe-43e5-9927-652201a9677a-0000 I0125 15:16:42.207540 25316 slave.cpp:4328] Got exited event for executor(3= 5)@172.17.0.3:57726 I0125 15:16:42.206830 25329 hierarchical.cpp:1302] Performed allocation for= agent 6361cb74-ebfe-43e5-9927-652201a9677a-S0 in 104733ns /mesos/src/tests/partition_tests.cpp:2064: Failure Failed to wait 15secs for finishedStatus I0125 15:16:57.211380 25326 master.cpp:1378] Framework 6361cb74-ebfe-43e5-9= 927-652201a9677a-0000 (default) at scheduler-d26521d5-3415-4739-ad0f-b828c3= e00a34@172.17.0.3:57726 disconnected I0125 15:16:57.211426 25326 master.cpp:3078] Deactivating framework 6361cb7= 4-ebfe-43e5-9927-652201a9677a-0000 (default) at scheduler-d26521d5-3415-473= 9-ad0f-b828c3e00a34@172.17.0.3:57726 /mesos/src/tests/partition_tests.cpp:2055: Failure Actual function call count doesn't match EXPECT_CALL(sched, statusUpdate(&d= river, _))... Expected: to be called once Actual: never called - unsatisfied and active I0125 15:16:57.211555 25327 hierarchical.cpp:386] Deactivated framework 636= 1cb74-ebfe-43e5-9927-652201a9677a-0000 I0125 15:16:57.211673 25326 master.cpp:3055] Disconnecting framework 6361cb= 74-ebfe-43e5-9927-652201a9677a-0000 (default) at scheduler-d26521d5-3415-47= 39-ad0f-b828c3e00a34@172.17.0.3:57726 I0125 15:16:57.211701 25326 master.cpp:1393] Giving framework 6361cb74-ebfe= -43e5-9927-652201a9677a-0000 (default) at scheduler-d26521d5-3415-4739-ad0f= -b828c3e00a34@172.17.0.3:57726 0ns to failover I0125 15:16:57.211863 25327 hierarchical.cpp:1011] Recovered cpus(*):2; mem= (*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2; mem(*):10= 24; disk(*):1024; ports(*):[31000-32000], allocated: {}) on agent 6361cb74-= ebfe-43e5-9927-652201a9677a-S0 from framework 6361cb74-ebfe-43e5-9927-65220= 1a9677a-0000 I0125 15:16:57.211979 25326 master.cpp:6682] Framework failover timeout, re= moving framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 (default) at sch= eduler-d26521d5-3415-4739-ad0f-b828c3e00a34@172.17.0.3:57726 I0125 15:16:57.212059 25326 master.cpp:7555] Removing framework 6361cb74-eb= fe-43e5-9927-652201a9677a-0000 (default) at scheduler-d26521d5-3415-4739-ad= 0f-b828c3e00a34@172.17.0.3:57726 I0125 15:16:57.212182 25326 master.cpp:8261] Removing executor 'default' wi= th resources {} of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 on a= gent 6361cb74-ebfe-43e5-9927-652201a9677a-S0 at slave(93)@172.17.0.3:57726 = (9cdefe4ff6bc) I0125 15:16:57.212309 25315 slave.cpp:2598] Asked to shut down framework 63= 61cb74-ebfe-43e5-9927-652201a9677a-0000 by master@172.17.0.3:57726 W0125 15:16:57.212338 25315 slave.cpp:2619] Ignoring shutdown framework 636= 1cb74-ebfe-43e5-9927-652201a9677a-0000 because it is terminating I0125 15:16:57.212626 25328 hierarchical.cpp:337] Removed framework 6361cb7= 4-ebfe-43e5-9927-652201a9677a-0000 I0125 15:16:57.213990 25326 slave.cpp:4691] Executor 'default' of framework= 6361cb74-ebfe-43e5-9927-652201a9677a-0000 exited with status 0 I0125 15:16:57.214105 25326 slave.cpp:4791] Cleaning up executor 'default' = of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 at executor(35)@172.= 17.0.3:57726 W0125 15:16:57.214220 25327 master.cpp:6132] Ignoring unknown exited execut= or 'default' of framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 on agen= t 6361cb74-ebfe-43e5-9927-652201a9677a-S0 at slave(93)@172.17.0.3:57726 (9c= defe4ff6bc) I0125 15:16:57.214432 25318 gc.cpp:55] Scheduling '/tmp/PartitionTest_TaskC= ompletedOnPartitionedAgent_3cCaq2/slaves/6361cb74-ebfe-43e5-9927-652201a967= 7a-S0/frameworks/6361cb74-ebfe-43e5-9927-652201a9677a-0000/executors/defaul= t/runs/5aa95fbe-c14f-4d50-9f28-6a605d3a212a' for gc 1.00002452166984weeks i= n the future I0125 15:16:57.214548 25326 slave.cpp:4879] Cleaning up framework 6361cb74-= ebfe-43e5-9927-652201a9677a-0000 I0125 15:16:57.214648 25319 gc.cpp:55] Scheduling '/tmp/PartitionTest_TaskC= ompletedOnPartitionedAgent_3cCaq2/slaves/6361cb74-ebfe-43e5-9927-652201a967= 7a-S0/frameworks/6361cb74-ebfe-43e5-9927-652201a9677a-0000/executors/defaul= t' for gc 1.00002452166984weeks in the future I0125 15:16:57.214687 25319 gc.cpp:55] Scheduling '/tmp/PartitionTest_TaskC= ompletedOnPartitionedAgent_3cCaq2/slaves/6361cb74-ebfe-43e5-9927-652201a967= 7a-S0/frameworks/6361cb74-ebfe-43e5-9927-652201a9677a-0000' for gc 1.000024= 52166984weeks in the future I0125 15:16:57.214817 25329 status_update_manager.cpp:285] Closing status u= pdate streams for framework 6361cb74-ebfe-43e5-9927-652201a9677a-0000 I0125 15:16:57.214866 25329 status_update_manager.cpp:531] Cleaning up stat= us update stream for task 1 of framework 6361cb74-ebfe-43e5-9927-652201a967= 7a-0000 I0125 15:16:57.215348 25314 slave.cpp:801] Agent terminating I0125 15:16:57.215633 25328 master.cpp:1261] Agent 6361cb74-ebfe-43e5-9927-= 652201a9677a-S0 at slave(93)@172.17.0.3:57726 (9cdefe4ff6bc) disconnected I0125 15:16:57.215654 25328 master.cpp:3115] Disconnecting agent 6361cb74-e= bfe-43e5-9927-652201a9677a-S0 at slave(93)@172.17.0.3:57726 (9cdefe4ff6bc) I0125 15:16:57.215690 25328 master.cpp:3134] Deactivating agent 6361cb74-eb= fe-43e5-9927-652201a9677a-S0 at slave(93)@172.17.0.3:57726 (9cdefe4ff6bc) I0125 15:16:57.215837 25329 hierarchical.cpp:577] Agent 6361cb74-ebfe-43e5-= 9927-652201a9677a-S0 deactivated I0125 15:16:57.217043 25314 master.cpp:1100] Master terminating I0125 15:16:57.217226 25320 hierarchical.cpp:510] Removed agent 6361cb74-eb= fe-43e5-9927-652201a9677a-S0 [ FAILED ] PartitionTest.TaskCompletedOnPartitionedAgent (15049 ms) [ RUN ] PartitionTest.PartitionAwareTaskCompletedOnPartitionedAgent I0125 15:16:57.221556 25314 cluster.cpp:160] Creating default 'local' autho= rizer I0125 15:16:57.222678 25323 master.cpp:383] Master 1e5e2e94-5d6d-4d94-9e38-= fe48278c30a3 (9cdefe4ff6bc) started on 172.17.0.3:57726 I0125 15:16:57.222707 25323 master.cpp:385] Flags at startup: --acls=3D"" -= -agent_ping_timeout=3D"15secs" --agent_reregister_timeout=3D"10mins" --allo= cation_interval=3D"1secs" --allocator=3D"HierarchicalDRF" --authenticate_ag= ents=3D"true" --authenticate_frameworks=3D"true" --authenticate_http_framew= orks=3D"true" --authenticate_http_readonly=3D"true" --authenticate_http_rea= dwrite=3D"true" --authenticators=3D"crammd5" --authorizers=3D"local" --cred= entials=3D"/tmp/h7cPEl/credentials" --framework_sorter=3D"drf" --help=3D"fa= lse" --hostname_lookup=3D"true" --http_authenticators=3D"basic" --http_fram= ework_authenticators=3D"basic" --initialize_driver_logging=3D"true" --log_a= uto_initialize=3D"true" --logbufsecs=3D"0" --logging_level=3D"INFO" --max_a= gent_ping_timeouts=3D"5" --max_completed_frameworks=3D"50" --max_completed_= tasks_per_framework=3D"1000" --max_unreachable_tasks_per_framework=3D"1000"= --quiet=3D"false" --recovery_agent_removal_limit=3D"100%" --registry=3D"in= _memory" --registry_fetch_timeout=3D"1mins" --registry_gc_interval=3D"15min= s" --registry_max_agent_age=3D"2weeks" --registry_max_agent_count=3D"102400= " --registry_store_timeout=3D"100secs" --registry_strict=3D"false" --root_s= ubmissions=3D"true" --user_sorter=3D"drf" --version=3D"false" --webui_dir= =3D"/usr/local/share/mesos/webui" --work_dir=3D"/tmp/h7cPEl/master" --zk_se= ssion_timeout=3D"10secs" I0125 15:16:57.222909 25323 master.cpp:435] Master only allowing authentica= ted frameworks to register I0125 15:16:57.222921 25323 master.cpp:449] Master only allowing authentica= ted agents to register I0125 15:16:57.222930 25323 master.cpp:462] Master only allowing authentica= ted HTTP frameworks to register I0125 15:16:57.222962 25323 credentials.hpp:37] Loading credentials for aut= hentication from '/tmp/h7cPEl/credentials' I0125 15:16:57.223172 25323 master.cpp:507] Using default 'crammd5' authent= icator I0125 15:16:57.223227 25323 http.cpp:922] Using default 'basic' HTTP authen= ticator for realm 'mesos-master-readonly' I0125 15:16:57.223306 25323 http.cpp:922] Using default 'basic' HTTP authen= ticator for realm 'mesos-master-readwrite' I0125 15:16:57.223387 25323 http.cpp:922] Using default 'basic' HTTP authen= ticator for realm 'mesos-master-scheduler' I0125 15:16:57.223441 25323 master.cpp:587] Authorization enabled I0125 15:16:57.223608 25318 hierarchical.cpp:151] Initialized hierarchical = allocator process I0125 15:16:57.223614 25317 whitelist_watcher.cpp:77] No whitelist given I0125 15:16:57.224509 25323 master.cpp:2121] Elected as the leading master! I0125 15:16:57.224520 25323 master.cpp:1643] Recovering from registrar I0125 15:16:57.224572 25323 registrar.cpp:329] Recovering registrar I0125 15:16:57.224820 25323 registrar.cpp:362] Successfully fetched the reg= istry (0B) in 0ns I0125 15:16:57.224876 25323 registrar.cpp:461] Applied 1 operations in 2816= 6ns; attempting to update the registry I0125 15:16:57.225240 25315 registrar.cpp:506] Successfully updated the reg= istry in 0ns I0125 15:16:57.225291 25315 registrar.cpp:392] Successfully recovered regis= trar I0125 15:16:57.225442 25327 master.cpp:1759] Recovered 0 agents from the re= gistry (129B); allowing 10mins for agents to re-register I0125 15:16:57.225457 25315 hierarchical.cpp:178] Skipping recovery of hier= archical allocator: nothing to recover I0125 15:16:57.227869 25314 cluster.cpp:446] Creating default 'local' autho= rizer I0125 15:16:57.228396 25329 slave.cpp:209] Mesos agent started on (94)@172.= 17.0.3:57726 I0125 15:16:57.228420 25329 slave.cpp:210] Flags at startup: --acls=3D"" --= appc_simple_discovery_uri_prefix=3D"http://" --appc_store_dir=3D"/tmp/mesos= /store/appc" --authenticate_http_readonly=3D"true" --authenticate_http_read= write=3D"true" --authenticatee=3D"crammd5" --authentication_backoff_factor= =3D"1secs" --authorizer=3D"local" --cgroups_cpu_enable_pids_and_tids_count= =3D"false" --cgroups_enable_cfs=3D"false" --cgroups_hierarchy=3D"/sys/fs/cg= roup" --cgroups_limit_swap=3D"false" --cgroups_root=3D"mesos" --container_d= isk_watch_interval=3D"15secs" --containerizers=3D"mesos" --credential=3D"/t= mp/PartitionTest_PartitionAwareTaskCompletedOnPartitionedAgent_J0iSpX/crede= ntial" --default_role=3D"*" --disk_watch_interval=3D"1mins" --docker=3D"doc= ker" --docker_kill_orphans=3D"true" --docker_registry=3D"https://registry-1= .docker.io" --docker_remove_delay=3D"6hrs" --docker_socket=3D"/var/run/dock= er.sock" --docker_stop_timeout=3D"0ns" --docker_store_dir=3D"/tmp/mesos/sto= re/docker" --docker_volume_checkpoint_dir=3D"/var/run/mesos/isolators/docke= r/volume" --enforce_container_disk_quota=3D"false" --executor_registration_= timeout=3D"1mins" --executor_shutdown_grace_period=3D"5secs" --fetcher_cach= e_dir=3D"/tmp/PartitionTest_PartitionAwareTaskCompletedOnPartitionedAgent_J= 0iSpX/fetch" --fetcher_cache_size=3D"2GB" --frameworks_home=3D"" --gc_delay= =3D"1weeks" --gc_disk_headroom=3D"0.1" --hadoop_home=3D"" --help=3D"false" = --hostname_lookup=3D"true" --http_authenticators=3D"basic" --http_command_e= xecutor=3D"false" --http_credentials=3D"/tmp/PartitionTest_PartitionAwareTa= skCompletedOnPartitionedAgent_J0iSpX/http_credentials" --http_heartbeat_int= erval=3D"30secs" --image_provisioner_backend=3D"copy" --initialize_driver_l= ogging=3D"true" --isolation=3D"posix/cpu,posix/mem" --launcher=3D"posix" --= launcher_dir=3D"/mesos/build/src" --logbufsecs=3D"0" --logging_level=3D"INF= O" --max_completed_executors_per_framework=3D"150" --oversubscribed_resourc= es_interval=3D"15secs" --perf_duration=3D"10secs" --perf_interval=3D"1mins"= --qos_correction_interval_min=3D"0ns" --quiet=3D"false" --recover=3D"recon= nect" --recovery_timeout=3D"15mins" --registration_backoff_factor=3D"10ms" = --resources=3D"cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]" --revo= cable_cpu_low_priority=3D"true" --runtime_dir=3D"/tmp/PartitionTest_Partiti= onAwareTaskCompletedOnPartitionedAgent_J0iSpX" --sandbox_directory=3D"/mnt/= mesos/sandbox" --strict=3D"true" --switch_user=3D"true" --systemd_enable_su= pport=3D"true" --systemd_runtime_directory=3D"/run/systemd/system" --versio= n=3D"false" --work_dir=3D"/tmp/PartitionTest_PartitionAwareTaskCompletedOnP= artitionedAgent_Nlglx9" I0125 15:16:57.228858 25329 credentials.hpp:86] Loading credential for auth= entication from '/tmp/PartitionTest_PartitionAwareTaskCompletedOnPartitione= dAgent_J0iSpX/credential' I0125 15:16:57.229053 25329 slave.cpp:352] Agent using credential for: test= -principal I0125 15:16:57.229068 25329 credentials.hpp:37] Loading credentials for aut= hentication from '/tmp/PartitionTest_PartitionAwareTaskCompletedOnPartition= edAgent_J0iSpX/http_credentials' I0125 15:16:57.229094 25314 sched.cpp:232] Version: 1.2.0 I0125 15:16:57.229192 25327 sched.cpp:336] New master detected at master@17= 2.17.0.3:57726 I0125 15:16:57.229267 25327 sched.cpp:407] Authenticating with master maste= r@172.17.0.3:57726 I0125 15:16:57.229300 25327 sched.cpp:414] Using default CRAM-MD5 authentic= atee I0125 15:16:57.229444 25323 authenticatee.cpp:121] Creating new client SASL= connection I0125 15:16:57.229449 25329 http.cpp:922] Using default 'basic' HTTP authen= ticator for realm 'mesos-agent-readonly' I0125 15:16:57.229508 25329 http.cpp:922] Using default 'basic' HTTP authen= ticator for realm 'mesos-agent-readwrite' I0125 15:16:57.229660 25323 master.cpp:7001] Authenticating scheduler-37186= e29-2b70-417f-b5fd-5816fd31b070@172.17.0.3:57726 I0125 15:16:57.229821 25318 authenticator.cpp:414] Starting authentication = session for crammd5-authenticatee(220)@172.17.0.3:57726 I0125 15:16:57.229969 25324 authenticator.cpp:98] Creating new server SASL = connection I0125 15:16:57.230144 25320 authenticatee.cpp:213] Received SASL authentica= tion mechanisms: CRAM-MD5 I0125 15:16:57.230175 25320 authenticatee.cpp:239] Attempting to authentica= te with mechanism 'CRAM-MD5' I0125 15:16:57.230168 25329 slave.cpp:539] Agent resources: cpus(*):2; mem(= *):1024; disk(*):1024; ports(*):[31000-32000] I0125 15:16:57.230226 25329 slave.cpp:547] Agent attributes: [ ] I0125 15:16:57.230270 25329 slave.cpp:552] Agent hostname: 9cdefe4ff6bc I0125 15:16:57.230490 25324 authenticator.cpp:204] Received SASL authentica= tion start I0125 15:16:57.230528 25320 status_update_manager.cpp:177] Pausing sending = status updates I0125 15:16:57.230558 25324 authenticator.cpp:326] Authentication requires = more steps I0125 15:16:57.230625 25324 authenticatee.cpp:259] Received SASL authentica= tion step I0125 15:16:57.230711 25315 authenticator.cpp:232] Received SASL authentica= tion step I0125 15:16:57.230732 25315 auxprop.cpp:109] Request to lookup properties f= or user: 'test-principal' realm: '9cdefe4ff6bc' server FQDN: '9cdefe4ff6bc'= SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_= AUXPROP_AUTHZID: false=20 I0125 15:16:57.230801 25315 auxprop.cpp:181] Looking up auxiliary property = '*userPassword' I0125 15:16:57.230813 25315 auxprop.cpp:181] Looking up auxiliary property = '*cmusaslsecretCRAM-MD5' I0125 15:16:57.230823 25315 auxprop.cpp:109] Request to lookup properties f= or user: 'test-principal' realm: '9cdefe4ff6bc' server FQDN: '9cdefe4ff6bc'= SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_= AUXPROP_AUTHZID: true=20 I0125 15:16:57.230835 25315 auxprop.cpp:131] Skipping auxiliary property '*= userPassword' since SASL_AUXPROP_AUTHZID =3D=3D true I0125 15:16:57.230844 25315 auxprop.cpp:131] Skipping auxiliary property '*= cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID =3D=3D true I0125 15:16:57.230857 25315 authenticator.cpp:318] Authentication success I0125 15:16:57.230922 25316 authenticator.cpp:432] Authentication session c= leanup for crammd5-authenticatee(220)@172.17.0.3:57726 I0125 15:16:57.230903 25324 authenticatee.cpp:299] Authentication success I0125 15:16:57.231065 25315 master.cpp:7031] Successfully authenticated pri= ncipal 'test-principal' at scheduler-37186e29-2b70-417f-b5fd-5816fd31b070@1= 72.17.0.3:57726 I0125 15:16:57.231142 25316 sched.cpp:513] Successfully authenticated with = master master@172.17.0.3:57726 I0125 15:16:57.231158 25316 sched.cpp:836] Sending SUBSCRIBE call to master= @172.17.0.3:57726 I0125 15:16:57.231207 25316 sched.cpp:869] Will retry registration in 1.296= 809111secs if necessary I0125 15:16:57.231364 25317 master.cpp:2734] Received SUBSCRIBE call for fr= amework 'default' at scheduler-37186e29-2b70-417f-b5fd-5816fd31b070@172.17.= 0.3:57726 I0125 15:16:57.231384 25317 master.cpp:2157] Authorizing framework principa= l 'test-principal' to receive offers for role '*' I0125 15:16:57.231644 25322 master.cpp:2810] Subscribing framework default = with checkpointing disabled and capabilities [ PARTITION_AWARE ] I0125 15:16:57.231863 25321 hierarchical.cpp:271] Added framework 1e5e2e94-= 5d6d-4d94-9e38-fe48278c30a3-0000 I0125 15:16:57.231931 25315 sched.cpp:759] Framework registered with 1e5e2e= 94-5d6d-4d94-9e38-fe48278c30a3-0000 I0125 15:16:57.232040 25329 state.cpp:60] Recovering state from '/tmp/Parti= tionTest_PartitionAwareTaskCompletedOnPartitionedAgent_Nlglx9/meta' I0125 15:16:57.232167 25315 sched.cpp:773] Scheduler::registered took 29197= ns I0125 15:16:57.232100 25321 hierarchical.cpp:1677] No allocations performed I0125 15:16:57.232317 25321 hierarchical.cpp:1772] No inverse offers to sen= d out! I0125 15:16:57.232334 25321 hierarchical.cpp:1279] Performed allocation for= 0 agents in 249903ns I0125 15:16:57.232494 25327 status_update_manager.cpp:203] Recovering statu= s update manager I0125 15:16:57.232693 25318 slave.cpp:5422] Finished recovery I0125 15:16:57.233031 25318 slave.cpp:5596] Querying resource estimator for= oversubscribable resources I0125 15:16:57.233135 25318 slave.cpp:929] New master detected at master@17= 2.17.0.3:57726 I0125 15:16:57.233150 25326 status_update_manager.cpp:177] Pausing sending = status updates I0125 15:16:57.233340 25318 slave.cpp:964] Detecting new master I0125 15:16:57.233417 25318 slave.cpp:5610] Received oversubscribable resou= rces {} from the resource estimator I0125 15:16:57.233471 25318 slave.cpp:991] Authenticating with master maste= r@172.17.0.3:57726 I0125 15:16:57.233492 25318 slave.cpp:1002] Using default CRAM-MD5 authenti= catee I0125 15:16:57.233583 25318 authenticatee.cpp:121] Creating new client SASL= connection I0125 15:16:57.233708 25318 master.cpp:7001] Authenticating slave(94)@172.1= 7.0.3:57726 I0125 15:16:57.233757 25318 authenticator.cpp:414] Starting authentication = session for crammd5-authenticatee(221)@172.17.0.3:57726 I0125 15:16:57.233835 25318 authenticator.cpp:98] Creating new server SASL = connection I0125 15:16:57.233952 25318 authenticatee.cpp:213] Received SASL authentica= tion mechanisms: CRAM-MD5 I0125 15:16:57.233974 25318 authenticatee.cpp:239] Attempting to authentica= te with mechanism 'CRAM-MD5' I0125 15:16:57.234019 25318 authenticator.cpp:204] Received SASL authentica= tion start I0125 15:16:57.234061 25318 authenticator.cpp:326] Authentication requires = more steps I0125 15:16:57.234109 25318 authenticatee.cpp:259] Received SASL authentica= tion step I0125 15:16:57.234153 25318 authenticator.cpp:232] Received SASL authentica= tion step I0125 15:16:57.234171 25318 auxprop.cpp:109] Request to lookup properties f= or user: 'test-principal' realm: '9cdefe4ff6bc' server FQDN: '9cdefe4ff6bc'= SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_= AUXPROP_AUTHZID: false=20 I0125 15:16:57.234185 25318 auxprop.cpp:181] Looking up auxiliary property = '*userPassword' I0125 15:16:57.234197 25318 auxprop.cpp:181] Looking up auxiliary property = '*cmusaslsecretCRAM-MD5' I0125 15:16:57.234211 25318 auxprop.cpp:109] Request to lookup properties f= or user: 'test-principal' realm: '9cdefe4ff6bc' server FQDN: '9cdefe4ff6bc'= SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_= AUXPROP_AUTHZID: true=20 I0125 15:16:57.234222 25318 auxprop.cpp:131] Skipping auxiliary property '*= userPassword' since SASL_AUXPROP_AUTHZID =3D=3D true I0125 15:16:57.234230 25318 auxprop.cpp:131] Skipping auxiliary property '*= cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID =3D=3D true I0125 15:16:57.234244 25318 authenticator.cpp:318] Authentication success I0125 15:16:57.234302 25318 authenticatee.cpp:299] Authentication success I0125 15:16:57.234339 25318 master.cpp:7031] Successfully authenticated pri= ncipal 'test-principal' at slave(94)@172.17.0.3:57726 I0125 15:16:57.234375 25318 authenticator.cpp:432] Authentication session c= leanup for crammd5-authenticatee(221)@172.17.0.3:57726 I0125 15:16:57.234467 25318 slave.cpp:1086] Successfully authenticated with= master master@172.17.0.3:57726 I0125 15:16:57.234524 25318 slave.cpp:1508] Will retry registration in 2.17= 2659ms if necessary I0125 15:16:57.234637 25318 master.cpp:5299] Registering agent at slave(94)= @172.17.0.3:57726 (9cdefe4ff6bc) with id 1e5e2e94-5d6d-4d94-9e38-fe48278c30= a3-S0 I0125 15:16:57.234752 25318 registrar.cpp:461] Applied 1 operations in 1592= 1ns; attempting to update the registry I0125 15:16:57.235049 25318 registrar.cpp:506] Successfully updated the reg= istry in 0ns I0125 15:16:57.235239 25318 master.cpp:5370] Registered agent 1e5e2e94-5d6d= -4d94-9e38-fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff6bc) wit= h cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I0125 15:16:57.235347 25318 hierarchical.cpp:478] Added agent 1e5e2e94-5d6d= -4d94-9e38-fe48278c30a3-S0 (9cdefe4ff6bc) with cpus(*):2; mem(*):1024; disk= (*):1024; ports(*):[31000-32000] (allocated: {}) I0125 15:16:57.235530 25318 hierarchical.cpp:1772] No inverse offers to sen= d out! I0125 15:16:57.235553 25318 hierarchical.cpp:1302] Performed allocation for= agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 in 191700ns I0125 15:16:57.235595 25318 slave.cpp:1132] Registered with master master@1= 72.17.0.3:57726; given agent ID 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 I0125 15:16:57.235612 25318 fetcher.cpp:90] Clearing fetcher cache I0125 15:16:57.235841 25318 slave.cpp:1160] Checkpointing SlaveInfo to '/tm= p/PartitionTest_PartitionAwareTaskCompletedOnPartitionedAgent_Nlglx9/meta/s= laves/1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0/slave.info' I0125 15:16:57.236044 25318 slave.cpp:1198] Forwarding total oversubscribed= resources {} I0125 15:16:57.236088 25318 slave.cpp:4286] Received ping from slave-observ= er(95)@172.17.0.3:57726 I0125 15:16:57.236207 25318 master.cpp:6830] Sending 1 offers to framework = 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 (default) at scheduler-37186e29-2= b70-417f-b5fd-5816fd31b070@172.17.0.3:57726 I0125 15:16:57.236268 25318 master.cpp:5863] Received update of agent 1e5e2= e94-5d6d-4d94-9e38-fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff= 6bc) with total oversubscribed resources {} I0125 15:16:57.236335 25318 status_update_manager.cpp:184] Resuming sending= status updates I0125 15:16:57.236446 25318 sched.cpp:933] Scheduler::resourceOffers took 2= 4637ns I0125 15:16:57.236496 25318 hierarchical.cpp:548] Agent 1e5e2e94-5d6d-4d94-= 9e38-fe48278c30a3-S0 (9cdefe4ff6bc) updated with oversubscribed resources {= } (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], all= ocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) I0125 15:16:57.236543 25318 hierarchical.cpp:1677] No allocations performed I0125 15:16:57.236559 25318 hierarchical.cpp:1772] No inverse offers to sen= d out! I0125 15:16:57.236572 25318 hierarchical.cpp:1302] Performed allocation for= agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 in 52891ns I0125 15:16:57.236970 25317 master.cpp:3728] Processing ACCEPT call for off= ers: [ 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-O0 ] on agent 1e5e2e94-5d6d-4d9= 4-9e38-fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff6bc) for fra= mework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 (default) at scheduler-371= 86e29-2b70-417f-b5fd-5816fd31b070@172.17.0.3:57726 I0125 15:16:57.237028 25317 master.cpp:3316] Authorizing framework principa= l 'test-principal' to launch task 1 W0125 15:16:57.237627 25330 validation.cpp:1018] Executor 'default' for tas= k '1' uses less CPUs (None) than the minimum required (0.01). Please update= your executor, as this will be mandatory in future releases. W0125 15:16:57.237646 25330 validation.cpp:1030] Executor 'default' for tas= k '1' uses less memory (None) than the minimum required (32MB). Please upda= te your executor, as this will be mandatory in future releases. I0125 15:16:57.237792 25330 master.cpp:8882] Adding task 1 with resources c= pus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on agent 1e5e2e= 94-5d6d-4d94-9e38-fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff6= bc) I0125 15:16:57.237908 25330 master.cpp:4378] Launching task 1 of framework = 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 (default) at scheduler-37186e29-2= b70-417f-b5fd-5816fd31b070@172.17.0.3:57726 with resources cpus(*):2; mem(*= ):1024; disk(*):1024; ports(*):[31000-32000] on agent 1e5e2e94-5d6d-4d94-9e= 38-fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff6bc) I0125 15:16:57.238124 25330 slave.cpp:1576] Got assigned task '1' for frame= work 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 I0125 15:16:57.238366 25330 slave.cpp:1736] Launching task '1' for framewor= k 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 I0125 15:16:57.238796 25330 paths.cpp:547] Trying to chown '/tmp/PartitionT= est_PartitionAwareTaskCompletedOnPartitionedAgent_Nlglx9/slaves/1e5e2e94-5d= 6d-4d94-9e38-fe48278c30a3-S0/frameworks/1e5e2e94-5d6d-4d94-9e38-fe48278c30a= 3-0000/executors/default/runs/2b9c4031-c64e-456c-ae85-8789b26f6452' to user= 'mesos' I0125 15:16:57.238963 25330 slave.cpp:6331] Launching executor 'default' of= framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 with resources {} in w= ork directory '/tmp/PartitionTest_PartitionAwareTaskCompletedOnPartitionedA= gent_Nlglx9/slaves/1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0/frameworks/1e5e2= e94-5d6d-4d94-9e38-fe48278c30a3-0000/executors/default/runs/2b9c4031-c64e-4= 56c-ae85-8789b26f6452' I0125 15:16:57.239156 25330 slave.cpp:2058] Queued task '1' for executor 'd= efault' of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 I0125 15:16:57.239377 25320 slave.cpp:882] Successfully attached file '/tmp= /PartitionTest_PartitionAwareTaskCompletedOnPartitionedAgent_Nlglx9/slaves/= 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0/frameworks/1e5e2e94-5d6d-4d94-9e38-= fe48278c30a3-0000/executors/default/runs/2b9c4031-c64e-456c-ae85-8789b26f64= 52' I0125 15:16:57.240170 25315 exec.cpp:162] Version: 1.2.0 I0125 15:16:57.240241 25317 exec.cpp:212] Executor started at: executor(36)= @172.17.0.3:57726 with pid 25314 I0125 15:16:57.240470 25315 slave.cpp:3325] Got registration for executor '= default' of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 from execut= or(36)@172.17.0.3:57726 I0125 15:16:57.240638 25318 exec.cpp:237] Executor registered on agent 1e5e= 2e94-5d6d-4d94-9e38-fe48278c30a3-S0 I0125 15:16:57.240746 25315 slave.cpp:2271] Sending queued task '1' to exec= utor 'default' of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 at ex= ecutor(36)@172.17.0.3:57726 I0125 15:16:57.240878 25318 exec.cpp:249] Executor::registered took 105704n= s I0125 15:16:57.240934 25318 exec.cpp:320] Executor asked to run task '1' I0125 15:16:57.241022 25318 exec.cpp:329] Executor::launchTask took 66708ns I0125 15:16:57.241179 25317 exec.cpp:546] Executor sending status update TA= SK_RUNNING (UUID: cf817a99-c7fe-474f-adbf-397b19fc7ef5) for task 1 of frame= work 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 I0125 15:16:57.241276 25317 slave.cpp:3756] Handling status update TASK_RUN= NING (UUID: cf817a99-c7fe-474f-adbf-397b19fc7ef5) for task 1 of framework 1= e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 from executor(36)@172.17.0.3:57726 I0125 15:16:57.241582 25328 status_update_manager.cpp:323] Received status = update TASK_RUNNING (UUID: cf817a99-c7fe-474f-adbf-397b19fc7ef5) for task 1= of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 I0125 15:16:57.241618 25328 status_update_manager.cpp:500] Creating StatusU= pdate stream for task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0= 000 I0125 15:16:57.241770 25328 status_update_manager.cpp:377] Forwarding updat= e TASK_RUNNING (UUID: cf817a99-c7fe-474f-adbf-397b19fc7ef5) for task 1 of f= ramework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 to the agent I0125 15:16:57.241904 25330 slave.cpp:4196] Forwarding the update TASK_RUNN= ING (UUID: cf817a99-c7fe-474f-adbf-397b19fc7ef5) for task 1 of framework 1e= 5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 to master@172.17.0.3:57726 I0125 15:16:57.241987 25330 slave.cpp:4090] Status update manager successfu= lly handled status update TASK_RUNNING (UUID: cf817a99-c7fe-474f-adbf-397b1= 9fc7ef5) for task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 I0125 15:16:57.242010 25330 slave.cpp:4106] Sending acknowledgement for sta= tus update TASK_RUNNING (UUID: cf817a99-c7fe-474f-adbf-397b19fc7ef5) for ta= sk 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 to executor(36)= @172.17.0.3:57726 I0125 15:16:57.242105 25330 master.cpp:6008] Status update TASK_RUNNING (UU= ID: cf817a99-c7fe-474f-adbf-397b19fc7ef5) for task 1 of framework 1e5e2e94-= 5d6d-4d94-9e38-fe48278c30a3-0000 from agent 1e5e2e94-5d6d-4d94-9e38-fe48278= c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff6bc) I0125 15:16:57.242136 25330 master.cpp:6076] Forwarding status update TASK_= RUNNING (UUID: cf817a99-c7fe-474f-adbf-397b19fc7ef5) for task 1 of framewor= k 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 I0125 15:16:57.242192 25330 master.cpp:8138] Updating the state of task 1 o= f framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 (latest state: TASK_R= UNNING, status update state: TASK_RUNNING) I0125 15:16:57.242241 25330 exec.cpp:369] Executor received status update a= cknowledgement cf817a99-c7fe-474f-adbf-397b19fc7ef5 for task 1 of framework= 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 I0125 15:16:57.242321 25330 sched.cpp:1041] Scheduler::statusUpdate took 13= 730ns I0125 15:16:57.242394 25330 master.cpp:5015] Processing ACKNOWLEDGE call cf= 817a99-c7fe-474f-adbf-397b19fc7ef5 for task 1 of framework 1e5e2e94-5d6d-4d= 94-9e38-fe48278c30a3-0000 (default) at scheduler-37186e29-2b70-417f-b5fd-58= 16fd31b070@172.17.0.3:57726 on agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S= 0 I0125 15:16:57.242480 25330 status_update_manager.cpp:395] Received status = update acknowledgement (UUID: cf817a99-c7fe-474f-adbf-397b19fc7ef5) for tas= k 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 I0125 15:16:57.242555 25330 slave.cpp:3045] Status update manager successfu= lly handled status update acknowledgement (UUID: cf817a99-c7fe-474f-adbf-39= 7b19fc7ef5) for task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-00= 00 I0125 15:16:57.242779 25317 hierarchical.cpp:1677] No allocations performed I0125 15:16:57.242794 25317 hierarchical.cpp:1772] No inverse offers to sen= d out! I0125 15:16:57.242801 25330 slave.cpp:5596] Querying resource estimator for= oversubscribable resources I0125 15:16:57.242807 25317 hierarchical.cpp:1279] Performed allocation for= 1 agents in 57725ns I0125 15:16:57.243042 25330 slave.cpp:4286] Received ping from slave-observ= er(95)@172.17.0.3:57726 I0125 15:16:57.243192 25330 slave.cpp:5610] Received oversubscribable resou= rces {} from the resource estimator I0125 15:16:57.243371 25320 slave.cpp:5596] Querying resource estimator for= oversubscribable resources I0125 15:16:57.243417 25318 hierarchical.cpp:1677] No allocations performed I0125 15:16:57.243522 25318 hierarchical.cpp:1772] No inverse offers to sen= d out! I0125 15:16:57.243425 25320 slave.cpp:4286] Received ping from slave-observ= er(95)@172.17.0.3:57726 I0125 15:16:57.243571 25318 hierarchical.cpp:1279] Performed allocation for= 1 agents in 189209ns I0125 15:16:57.243598 25320 slave.cpp:5610] Received oversubscribable resou= rces {} from the resource estimator I0125 15:16:57.243758 25322 hierarchical.cpp:1677] No allocations performed I0125 15:16:57.243774 25322 hierarchical.cpp:1772] No inverse offers to sen= d out! I0125 15:16:57.243788 25322 hierarchical.cpp:1279] Performed allocation for= 1 agents in 71161ns I0125 15:16:57.243882 25318 slave.cpp:5596] Querying resource estimator for= oversubscribable resources I0125 15:16:57.244040 25318 slave.cpp:4286] Received ping from slave-observ= er(95)@172.17.0.3:57726 I0125 15:16:57.244092 25318 slave.cpp:5610] Received oversubscribable resou= rces {} from the resource estimator I0125 15:16:57.244354 25320 slave.cpp:5596] Querying resource estimator for= oversubscribable resources I0125 15:16:57.244480 25320 slave.cpp:5189] Current disk usage 10.11%. Max = allowed age: 5.592058203640729days I0125 15:16:57.244604 25320 slave.cpp:4286] Received ping from slave-observ= er(95)@172.17.0.3:57726 I0125 15:16:57.244709 25320 slave.cpp:5610] Received oversubscribable resou= rces {} from the resource estimator I0125 15:16:57.244755 25326 hierarchical.cpp:1677] No allocations performed I0125 15:16:57.244787 25326 hierarchical.cpp:1772] No inverse offers to sen= d out! I0125 15:16:57.244817 25326 hierarchical.cpp:1279] Performed allocation for= 1 agents in 250871ns I0125 15:16:57.244976 25324 hierarchical.cpp:1677] No allocations performed I0125 15:16:57.244992 25324 hierarchical.cpp:1772] No inverse offers to sen= d out! I0125 15:16:57.244982 25317 slave.cpp:5596] Querying resource estimator for= oversubscribable resources I0125 15:16:57.245005 25324 hierarchical.cpp:1279] Performed allocation for= 1 agents in 60156ns I0125 15:16:57.245086 25317 slave.cpp:4286] Received ping from slave-observ= er(95)@172.17.0.3:57726 I0125 15:16:57.245157 25317 slave.cpp:5610] Received oversubscribable resou= rces {} from the resource estimator I0125 15:16:57.245025 25321 master.cpp:6236] Marking agent 1e5e2e94-5d6d-4d= 94-9e38-fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff6bc) unreac= hable: health check timed out I0125 15:16:57.245483 25317 registrar.cpp:461] Applied 1 operations in 2561= 7ns; attempting to update the registry I0125 15:16:57.245762 25322 registrar.cpp:506] Successfully updated the reg= istry in 0ns I0125 15:16:57.245857 25317 master.cpp:6284] Marked agent 1e5e2e94-5d6d-4d9= 4-9e38-fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff6bc) unreach= able: health check timed out I0125 15:16:57.246047 25320 hierarchical.cpp:510] Removed agent 1e5e2e94-5d= 6d-4d94-9e38-fe48278c30a3-S0 I0125 15:16:57.246070 25317 master.cpp:8138] Updating the state of task 1 o= f framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 (latest state: TASK_U= NREACHABLE, status update state: TASK_UNREACHABLE) I0125 15:16:57.246251 25317 master.cpp:8232] Removing task 1 with resources= cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework = 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 on agent 1e5e2e94-5d6d-4d94-9e38-= fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff6bc) I0125 15:16:57.246330 25317 master.cpp:6071] Sending status update TASK_UNR= EACHABLE for task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 = 'Agent 9cdefe4ff6bc is unreachable: health check timed out' I0125 15:16:57.246498 25317 master.cpp:8261] Removing executor 'default' wi= th resources {} of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 on a= gent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 = (9cdefe4ff6bc) I0125 15:16:57.246628 25327 sched.cpp:1041] Scheduler::statusUpdate took 31= 098ns I0125 15:16:57.246682 25317 master.cpp:2038] Notifying framework 1e5e2e94-5= d6d-4d94-9e38-fe48278c30a3-0000 (default) at scheduler-37186e29-2b70-417f-b= 5fd-5816fd31b070@172.17.0.3:57726 of lost agent 1e5e2e94-5d6d-4d94-9e38-fe4= 8278c30a3-S0 (9cdefe4ff6bc) I0125 15:16:57.246773 25317 sched.cpp:1103] Lost agent 1e5e2e94-5d6d-4d94-9= e38-fe48278c30a3-S0 I0125 15:16:57.246807 25317 sched.cpp:1114] Scheduler::slaveLost took 23178= ns I0125 15:16:57.246893 25330 exec.cpp:546] Executor sending status update TA= SK_FINISHED (UUID: adf6618e-4d53-4a0a-8364-f822a1acf41f) for task 1 of fram= ework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 I0125 15:16:57.247026 25324 slave.cpp:3756] Handling status update TASK_FIN= ISHED (UUID: adf6618e-4d53-4a0a-8364-f822a1acf41f) for task 1 of framework = 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 from executor(36)@172.17.0.3:5772= 6 I0125 15:16:57.247184 25324 slave.cpp:922] Lost leading master I0125 15:16:57.247201 25324 slave.cpp:964] Detecting new master I0125 15:16:57.247205 25315 status_update_manager.cpp:177] Pausing sending = status updates I0125 15:16:57.247407 25315 status_update_manager.cpp:177] Pausing sending = status updates I0125 15:16:57.247414 25325 slave.cpp:929] New master detected at master@17= 2.17.0.3:57726 I0125 15:16:57.247458 25325 slave.cpp:964] Detecting new master I0125 15:16:57.247612 25325 slave.cpp:991] Authenticating with master maste= r@172.17.0.3:57726 I0125 15:16:57.247632 25325 slave.cpp:1002] Using default CRAM-MD5 authenti= catee I0125 15:16:57.247735 25325 authenticatee.cpp:121] Creating new client SASL= connection I0125 15:16:57.247905 25325 master.cpp:7001] Authenticating slave(94)@172.1= 7.0.3:57726 I0125 15:16:57.247949 25325 status_update_manager.cpp:323] Received status = update TASK_FINISHED (UUID: adf6618e-4d53-4a0a-8364-f822a1acf41f) for task = 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 I0125 15:16:57.248000 25325 authenticator.cpp:414] Starting authentication = session for crammd5-authenticatee(222)@172.17.0.3:57726 I0125 15:16:57.248051 25325 slave.cpp:4090] Status update manager successfu= lly handled status update TASK_FINISHED (UUID: adf6618e-4d53-4a0a-8364-f822= a1acf41f) for task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 I0125 15:16:57.248071 25325 slave.cpp:4106] Sending acknowledgement for sta= tus update TASK_FINISHED (UUID: adf6618e-4d53-4a0a-8364-f822a1acf41f) for t= ask 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 to executor(36= )@172.17.0.3:57726 I0125 15:16:57.248119 25325 authenticator.cpp:98] Creating new server SASL = connection I0125 15:16:57.248225 25325 exec.cpp:369] Executor received status update a= cknowledgement adf6618e-4d53-4a0a-8364-f822a1acf41f for task 1 of framework= 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 I0125 15:16:57.248257 25325 authenticatee.cpp:213] Received SASL authentica= tion mechanisms: CRAM-MD5 I0125 15:16:57.248278 25325 authenticatee.cpp:239] Attempting to authentica= te with mechanism 'CRAM-MD5' I0125 15:16:57.248311 25325 authenticator.cpp:204] Received SASL authentica= tion start I0125 15:16:57.248352 25325 authenticator.cpp:326] Authentication requires = more steps I0125 15:16:57.248383 25325 authenticatee.cpp:259] Received SASL authentica= tion step I0125 15:16:57.248416 25325 authenticator.cpp:232] Received SASL authentica= tion step I0125 15:16:57.248431 25325 auxprop.cpp:109] Request to lookup properties f= or user: 'test-principal' realm: '9cdefe4ff6bc' server FQDN: '9cdefe4ff6bc'= SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_= AUXPROP_AUTHZID: false=20 I0125 15:16:57.248440 25325 auxprop.cpp:181] Looking up auxiliary property = '*userPassword' I0125 15:16:57.248450 25325 auxprop.cpp:181] Looking up auxiliary property = '*cmusaslsecretCRAM-MD5' I0125 15:16:57.248457 25325 auxprop.cpp:109] Request to lookup properties f= or user: 'test-principal' realm: '9cdefe4ff6bc' server FQDN: '9cdefe4ff6bc'= SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_= AUXPROP_AUTHZID: true=20 I0125 15:16:57.248462 25325 auxprop.cpp:131] Skipping auxiliary property '*= userPassword' since SASL_AUXPROP_AUTHZID =3D=3D true I0125 15:16:57.248466 25325 auxprop.cpp:131] Skipping auxiliary property '*= cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID =3D=3D true I0125 15:16:57.248476 25325 authenticator.cpp:318] Authentication success I0125 15:16:57.248518 25325 authenticatee.cpp:299] Authentication success I0125 15:16:57.248546 25325 master.cpp:7031] Successfully authenticated pri= ncipal 'test-principal' at slave(94)@172.17.0.3:57726 I0125 15:16:57.248570 25325 authenticator.cpp:432] Authentication session c= leanup for crammd5-authenticatee(222)@172.17.0.3:57726 I0125 15:16:57.248622 25325 slave.cpp:1086] Successfully authenticated with= master master@172.17.0.3:57726 I0125 15:16:57.248702 25325 slave.cpp:1508] Will retry registration in 18.9= 92503ms if necessary I0125 15:16:57.248834 25325 master.cpp:5522] Re-registering agent 1e5e2e94-= 5d6d-4d94-9e38-fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff6bc) I0125 15:16:57.249008 25325 registrar.cpp:461] Applied 1 operations in 2632= 0ns; attempting to update the registry I0125 15:16:57.249282 25325 registrar.cpp:506] Successfully updated the reg= istry in 0ns I0125 15:16:57.249460 25325 master.cpp:8882] Adding task 1 with resources c= pus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on agent 1e5e2e= 94-5d6d-4d94-9e38-fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff6= bc) I0125 15:16:57.249578 25325 master.cpp:5694] Re-registered agent 1e5e2e94-5= d6d-4d94-9e38-fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff6bc) = with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I0125 15:16:57.249624 25325 master.cpp:5802] Sending updated checkpointed r= esources {} to agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 at slave(94)@1= 72.17.0.3:57726 (9cdefe4ff6bc) I0125 15:16:57.249718 25325 hierarchical.cpp:478] Added agent 1e5e2e94-5d6d= -4d94-9e38-fe48278c30a3-S0 (9cdefe4ff6bc) with cpus(*):2; mem(*):1024; disk= (*):1024; ports(*):[31000-32000] (allocated: {}) I0125 15:16:57.249862 25325 hierarchical.cpp:1772] No inverse offers to sen= d out! I0125 15:16:57.249879 25325 hierarchical.cpp:1302] Performed allocation for= agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 in 144682ns I0125 15:16:57.249923 25325 slave.cpp:1240] Re-registered with master maste= r@172.17.0.3:57726 I0125 15:16:57.249945 25325 slave.cpp:1277] Forwarding total oversubscribed= resources {} I0125 15:16:57.249994 25325 slave.cpp:2830] Ignoring new checkpointed resou= rces identical to the current version: {} I0125 15:16:57.250017 25325 slave.cpp:4286] Received ping from slave-observ= er(96)@172.17.0.3:57726 I0125 15:16:57.250128 25325 master.cpp:6830] Sending 1 offers to framework = 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 (default) at scheduler-37186e29-2= b70-417f-b5fd-5816fd31b070@172.17.0.3:57726 I0125 15:16:57.250182 25325 master.cpp:5863] Received update of agent 1e5e2= e94-5d6d-4d94-9e38-fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff= 6bc) with total oversubscribed resources {} I0125 15:16:57.250241 25325 status_update_manager.cpp:184] Resuming sending= status updates W0125 15:16:57.250252 25325 status_update_manager.cpp:191] Resending status= update TASK_FINISHED (UUID: adf6618e-4d53-4a0a-8364-f822a1acf41f) for task= 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 I0125 15:16:57.250267 25325 status_update_manager.cpp:377] Forwarding updat= e TASK_FINISHED (UUID: adf6618e-4d53-4a0a-8364-f822a1acf41f) for task 1 of = framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 to the agent I0125 15:16:57.250396 25325 sched.cpp:933] Scheduler::resourceOffers took 1= 3924ns I0125 15:16:57.250452 25325 hierarchical.cpp:548] Agent 1e5e2e94-5d6d-4d94-= 9e38-fe48278c30a3-S0 (9cdefe4ff6bc) updated with oversubscribed resources {= } (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], all= ocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) I0125 15:16:57.250499 25325 hierarchical.cpp:1677] No allocations performed I0125 15:16:57.250514 25325 hierarchical.cpp:1772] No inverse offers to sen= d out! I0125 15:16:57.250529 25325 hierarchical.cpp:1302] Performed allocation for= agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 in 55022ns I0125 15:16:57.250571 25325 slave.cpp:4196] Forwarding the update TASK_FINI= SHED (UUID: adf6618e-4d53-4a0a-8364-f822a1acf41f) for task 1 of framework 1= e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 to master@172.17.0.3:57726 I0125 15:16:57.250669 25325 master.cpp:6008] Status update TASK_FINISHED (U= UID: adf6618e-4d53-4a0a-8364-f822a1acf41f) for task 1 of framework 1e5e2e94= -5d6d-4d94-9e38-fe48278c30a3-0000 from agent 1e5e2e94-5d6d-4d94-9e38-fe4827= 8c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff6bc) I0125 15:16:57.250689 25325 master.cpp:6076] Forwarding status update TASK_= FINISHED (UUID: adf6618e-4d53-4a0a-8364-f822a1acf41f) for task 1 of framewo= rk 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 I0125 15:16:57.250733 25325 master.cpp:8138] Updating the state of task 1 o= f framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 (latest state: TASK_F= INISHED, status update state: TASK_FINISHED) I0125 15:16:57.250803 25325 sched.cpp:1041] Scheduler::statusUpdate took 25= 761ns I0125 15:16:57.250862 25325 master.cpp:5015] Processing ACKNOWLEDGE call ad= f6618e-4d53-4a0a-8364-f822a1acf41f for task 1 of framework 1e5e2e94-5d6d-4d= 94-9e38-fe48278c30a3-0000 (default) at scheduler-37186e29-2b70-417f-b5fd-58= 16fd31b070@172.17.0.3:57726 on agent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S= 0 I0125 15:16:57.250885 25325 master.cpp:8232] Removing task 1 with resources= cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework = 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 on agent 1e5e2e94-5d6d-4d94-9e38-= fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff6bc) I0125 15:16:57.250984 25325 status_update_manager.cpp:395] Received status = update acknowledgement (UUID: adf6618e-4d53-4a0a-8364-f822a1acf41f) for tas= k 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 I0125 15:16:57.251021 25325 status_update_manager.cpp:531] Cleaning up stat= us update stream for task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30= a3-0000 I0125 15:16:57.251101 25325 slave.cpp:3045] Status update manager successfu= lly handled status update acknowledgement (UUID: adf6618e-4d53-4a0a-8364-f8= 22a1acf41f) for task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-00= 00 I0125 15:16:57.251116 25325 slave.cpp:6721] Completing task 1 I0125 15:16:57.251276 25327 master.cpp:6528] Performing explicit task state= reconciliation for 1 tasks of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30= a3-0000 (default) at scheduler-37186e29-2b70-417f-b5fd-5816fd31b070@172.17.= 0.3:57726 I0125 15:16:57.251310 25327 master.cpp:6658] Sending explicit reconciliatio= n state TASK_UNKNOWN for task 1 of framework 1e5e2e94-5d6d-4d94-9e38-fe4827= 8c30a3-0000 (default) at scheduler-37186e29-2b70-417f-b5fd-5816fd31b070@172= .17.0.3:57726 I0125 15:16:57.251400 25321 sched.cpp:1041] Scheduler::statusUpdate took 19= 457ns I0125 15:16:57.252044 25324 process.cpp:3697] Handling HTTP event for proce= ss 'master' with path: '/master/state' I0125 15:16:57.252405 25325 http.cpp:420] HTTP GET for /master/state from 1= 72.17.0.3:47454 I0125 15:16:57.262833 25314 sched.cpp:2021] Asked to stop the driver I0125 15:16:57.262905 25317 sched.cpp:1203] Stopping framework 1e5e2e94-5d6= d-4d94-9e38-fe48278c30a3-0000 I0125 15:16:57.263093 25327 master.cpp:7543] Processing TEARDOWN call for f= ramework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 (default) at scheduler-3= 7186e29-2b70-417f-b5fd-5816fd31b070@172.17.0.3:57726 I0125 15:16:57.263118 25327 master.cpp:7555] Removing framework 1e5e2e94-5d= 6d-4d94-9e38-fe48278c30a3-0000 (default) at scheduler-37186e29-2b70-417f-b5= fd-5816fd31b070@172.17.0.3:57726 I0125 15:16:57.263162 25327 master.cpp:3078] Deactivating framework 1e5e2e9= 4-5d6d-4d94-9e38-fe48278c30a3-0000 (default) at scheduler-37186e29-2b70-417= f-b5fd-5816fd31b070@172.17.0.3:57726 I0125 15:16:57.263269 25325 hierarchical.cpp:386] Deactivated framework 1e5= e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 I0125 15:16:57.263411 25327 master.cpp:8261] Removing executor 'default' wi= th resources {} of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 on a= gent 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 = (9cdefe4ff6bc) I0125 15:16:57.263497 25315 slave.cpp:2598] Asked to shut down framework 1e= 5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 by master@172.17.0.3:57726 I0125 15:16:57.263595 25315 slave.cpp:2623] Shutting down framework 1e5e2e9= 4-5d6d-4d94-9e38-fe48278c30a3-0000 I0125 15:16:57.263659 25315 slave.cpp:5005] Shutting down executor 'default= ' of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 at executor(36)@17= 2.17.0.3:57726 I0125 15:16:57.263728 25315 exec.cpp:410] Executor asked to shutdown I0125 15:16:57.263756 25315 exec.cpp:425] Executor::shutdown took 17870ns I0125 15:16:57.263811 25315 slave.cpp:4328] Got exited event for executor(3= 6)@172.17.0.3:57726 I0125 15:16:57.263916 25325 hierarchical.cpp:1011] Recovered cpus(*):2; mem= (*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2; mem(*):10= 24; disk(*):1024; ports(*):[31000-32000], allocated: {}) on agent 1e5e2e94-= 5d6d-4d94-9e38-fe48278c30a3-S0 from framework 1e5e2e94-5d6d-4d94-9e38-fe482= 78c30a3-0000 I0125 15:16:57.264025 25325 hierarchical.cpp:337] Removed framework 1e5e2e9= 4-5d6d-4d94-9e38-fe48278c30a3-0000 I0125 15:16:57.264405 25315 slave.cpp:4691] Executor 'default' of framework= 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 exited with status 0 I0125 15:16:57.264453 25315 slave.cpp:4791] Cleaning up executor 'default' = of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 at executor(36)@172.= 17.0.3:57726 W0125 15:16:57.264505 25321 master.cpp:6132] Ignoring unknown exited execut= or 'default' of framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 on agen= t 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 (9c= defe4ff6bc) I0125 15:16:57.264669 25325 gc.cpp:55] Scheduling '/tmp/PartitionTest_Parti= tionAwareTaskCompletedOnPartitionedAgent_Nlglx9/slaves/1e5e2e94-5d6d-4d94-9= e38-fe48278c30a3-S0/frameworks/1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000/ex= ecutors/default/runs/2b9c4031-c64e-456c-ae85-8789b26f6452' for gc 6.9999969= 3789333days in the future I0125 15:16:57.264698 25315 slave.cpp:4879] Cleaning up framework 1e5e2e94-= 5d6d-4d94-9e38-fe48278c30a3-0000 I0125 15:16:57.264727 25325 gc.cpp:55] Scheduling '/tmp/PartitionTest_Parti= tionAwareTaskCompletedOnPartitionedAgent_Nlglx9/slaves/1e5e2e94-5d6d-4d94-9= e38-fe48278c30a3-S0/frameworks/1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000/ex= ecutors/default' for gc 6.99999693700148days in the future I0125 15:16:57.264781 25325 status_update_manager.cpp:285] Closing status u= pdate streams for framework 1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000 I0125 15:16:57.264807 25315 gc.cpp:55] Scheduling '/tmp/PartitionTest_Parti= tionAwareTaskCompletedOnPartitionedAgent_Nlglx9/slaves/1e5e2e94-5d6d-4d94-9= e38-fe48278c30a3-S0/frameworks/1e5e2e94-5d6d-4d94-9e38-fe48278c30a3-0000' f= or gc 6.99999693552days in the future I0125 15:16:57.264999 25321 slave.cpp:801] Agent terminating I0125 15:16:57.265214 25323 master.cpp:1261] Agent 1e5e2e94-5d6d-4d94-9e38-= fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff6bc) disconnected I0125 15:16:57.265230 25323 master.cpp:3115] Disconnecting agent 1e5e2e94-5= d6d-4d94-9e38-fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff6bc) I0125 15:16:57.265259 25323 master.cpp:3134] Deactivating agent 1e5e2e94-5d= 6d-4d94-9e38-fe48278c30a3-S0 at slave(94)@172.17.0.3:57726 (9cdefe4ff6bc) I0125 15:16:57.265339 25319 hierarchical.cpp:577] Agent 1e5e2e94-5d6d-4d94-= 9e38-fe48278c30a3-S0 deactivated I0125 15:16:57.269418 25314 master.cpp:1100] Master terminating I0125 15:16:57.269567 25322 hierarchical.cpp:510] Removed agent 1e5e2e94-5d= 6d-4d94-9e38-fe48278c30a3-S0 [ OK ] PartitionTest.PartitionAwareTaskCompletedOnPartitionedAgent (5= 1 ms) {noformat} -- This message was sent by Atlassian JIRA (v6.3.4#6332)