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 34EF7200CB4 for ; Tue, 27 Jun 2017 20:16:21 +0200 (CEST) Received: by cust-asf.ponee.io (Postfix) id 33042160BDC; Tue, 27 Jun 2017 18:16:21 +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 0A9E9160BD8 for ; Tue, 27 Jun 2017 20:16:18 +0200 (CEST) Received: (qmail 55505 invoked by uid 500); 27 Jun 2017 18:16:17 -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 55496 invoked by uid 99); 27 Jun 2017 18:16:17 -0000 Received: from pnap-us-west-generic-nat.apache.org (HELO spamd4-us-west.apache.org) (209.188.14.142) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 27 Jun 2017 18:16:17 +0000 Received: from localhost (localhost [127.0.0.1]) by spamd4-us-west.apache.org (ASF Mail Server at spamd4-us-west.apache.org) with ESMTP id 95D5DC03A3 for ; Tue, 27 Jun 2017 18:16:16 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd4-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: -99.2 X-Spam-Level: X-Spam-Status: No, score=-99.2 tagged_above=-999 required=6.31 tests=[KAM_ASCII_DIVIDERS=0.8, NORMAL_HTTP_TO_IP=0.001, RP_MATCHES_RCVD=-0.001, SPF_PASS=-0.001, URIBL_BLOCKED=0.001, USER_IN_WHITELIST=-100] autolearn=disabled Received: from mx1-lw-us.apache.org ([10.40.0.8]) by localhost (spamd4-us-west.apache.org [10.40.0.11]) (amavisd-new, port 10024) with ESMTP id 0f9Fy0AiZLuu for ; Tue, 27 Jun 2017 18:16:02 +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 EB18A5FD3F for ; Tue, 27 Jun 2017 18:16:01 +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 46B92E0C1D for ; Tue, 27 Jun 2017 18:16:01 +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 ED32D24120 for ; Tue, 27 Jun 2017 18:16:00 +0000 (UTC) Date: Tue, 27 Jun 2017 18:16:00 +0000 (UTC) From: "Vinod Kone (JIRA)" To: issues@mesos.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Updated] (MESOS-7725) PersistentVolumeEndpointsTest.ReserveAndSlaveRemoval test is flaky MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 archived-at: Tue, 27 Jun 2017 18:16:21 -0000 [ https://issues.apache.org/jira/browse/MESOS-7725?page=3Dcom.atlassia= n.jira.plugin.system.issuetabpanels:all-tabpanel ] Vinod Kone updated MESOS-7725: ------------------------------ Description:=20 Observed this on ASF CI. {code} [ RUN ] PersistentVolumeEndpointsTest.ReserveAndSlaveRemoval I0627 15:20:33.687146 30773 cluster.cpp:162] Creating default 'local' autho= rizer I0627 15:20:33.691745 30795 master.cpp:438] Master d8d232e5-1689-4780-b232-= c91e5c3277b1 (0b1049f05548) started on 172.17.0.2:44357 I0627 15:20:33.691800 30795 master.cpp:440] Flags at startup: --acls=3D"" -= -agent_ping_timeout=3D"15secs" --agent_reregister_timeout=3D"10mins" --allo= cation_interval=3D"50ms" --allocator=3D"HierarchicalDRF" --authenticate_age= nts=3D"true" --authenticate_frameworks=3D"true" --authenticate_http_framewo= rks=3D"true" --authenticate_http_readonly=3D"true" --authenticate_http_read= write=3D"true" --authenticators=3D"crammd5" --authorizers=3D"local" --crede= ntials=3D"/tmp/Wg4Ouh/credentials" --filter_gpu_resources=3D"true" --framew= ork_sorter=3D"drf" --help=3D"false" --hostname_lookup=3D"true" --http_authe= nticators=3D"basic" --http_framework_authenticators=3D"basic" --initialize_= driver_logging=3D"true" --log_auto_initialize=3D"true" --logbufsecs=3D"0" -= -logging_level=3D"INFO" --max_agent_ping_timeouts=3D"5" --max_completed_fra= meworks=3D"50" --max_completed_tasks_per_framework=3D"1000" --max_unreachab= le_tasks_per_framework=3D"1000" --port=3D"5050" --quiet=3D"false" --recover= y_agent_removal_limit=3D"100%" --registry=3D"in_memory" --registry_fetch_ti= meout=3D"1mins" --registry_gc_interval=3D"15mins" --registry_max_agent_age= =3D"2weeks" --registry_max_agent_count=3D"102400" --registry_store_timeout= =3D"100secs" --registry_strict=3D"false" --roles=3D"role1" --root_submissio= ns=3D"true" --user_sorter=3D"drf" --version=3D"false" --webui_dir=3D"/usr/l= ocal/share/mesos/webui" --work_dir=3D"/tmp/Wg4Ouh/master" --zk_session_time= out=3D"10secs" I0627 15:20:33.692142 30795 master.cpp:490] Master only allowing authentica= ted frameworks to register I0627 15:20:33.692150 30795 master.cpp:504] Master only allowing authentica= ted agents to register I0627 15:20:33.692154 30795 master.cpp:517] Master only allowing authentica= ted HTTP frameworks to register I0627 15:20:33.692160 30795 credentials.hpp:37] Loading credentials for aut= hentication from '/tmp/Wg4Ouh/credentials' I0627 15:20:33.692463 30795 master.cpp:562] Using default 'crammd5' authent= icator I0627 15:20:33.692612 30795 http.cpp:974] Creating default 'basic' HTTP aut= henticator for realm 'mesos-master-readonly' I0627 15:20:33.692831 30795 http.cpp:974] Creating default 'basic' HTTP aut= henticator for realm 'mesos-master-readwrite' I0627 15:20:33.692942 30795 http.cpp:974] Creating default 'basic' HTTP aut= henticator for realm 'mesos-master-scheduler' I0627 15:20:33.693061 30795 master.cpp:642] Authorization enabled W0627 15:20:33.693076 30795 master.cpp:705] The '--roles' flag is deprecate= d. This flag will be removed in the future. See the Mesos 0.27 upgrade note= s for more information I0627 15:20:33.693354 30780 hierarchical.cpp:169] Initialized hierarchical = allocator process I0627 15:20:33.693359 30782 whitelist_watcher.cpp:77] No whitelist given I0627 15:20:33.695943 30795 master.cpp:2161] Elected as the leading master! I0627 15:20:33.695960 30795 master.cpp:1700] Recovering from registrar I0627 15:20:33.696193 30795 registrar.cpp:345] Recovering registrar I0627 15:20:33.697032 30795 registrar.cpp:389] Successfully fetched the reg= istry (0B) in 811008ns I0627 15:20:33.697147 30795 registrar.cpp:493] Applied 1 operations in 4018= 3ns; attempting to update the registry I0627 15:20:33.697922 30792 registrar.cpp:550] Successfully updated the reg= istry in 709120ns I0627 15:20:33.698020 30792 registrar.cpp:422] Successfully recovered regis= trar I0627 15:20:33.698490 30789 master.cpp:1799] Recovered 0 agents from the re= gistry (129B); allowing 10mins for agents to re-register I0627 15:20:33.698511 30784 hierarchical.cpp:207] Skipping recovery of hier= archical allocator: nothing to recover I0627 15:20:33.707849 30773 containerizer.cpp:230] Using isolation: posix/c= pu,posix/mem,filesystem/posix,network/cni,environment_secret W0627 15:20:33.708729 30773 backend.cpp:76] Failed to create 'aufs' backend= : AufsBackend requires root privileges W0627 15:20:33.708909 30773 backend.cpp:76] Failed to create 'bind' backend= : BindBackend requires root privileges I0627 15:20:33.708955 30773 provisioner.cpp:255] Using default backend 'cop= y' I0627 15:20:33.711526 30773 cluster.cpp:448] Creating default 'local' autho= rizer I0627 15:20:33.714450 30776 slave.cpp:249] Mesos agent started on (451)@172= .17.0.2:44357 I0627 15:20:33.714649 30776 slave.cpp:250] Flags at startup: --acls=3D"" --= appc_simple_discovery_uri_prefix=3D"http://" --appc_store_dir=3D"/tmp/Persi= stentVolumeEndpointsTest_ReserveAndSlaveRemoval_RnxQRd/store/appc" --authen= ticate_http_readonly=3D"true" --authenticate_http_readwrite=3D"true" --auth= enticatee=3D"crammd5" --authentication_backoff_factor=3D"1secs" --authorize= r=3D"local" --cgroups_cpu_enable_pids_and_tids_count=3D"false" --cgroups_en= able_cfs=3D"false" --cgroups_hierarchy=3D"/sys/fs/cgroup" --cgroups_limit_s= wap=3D"false" --cgroups_root=3D"mesos" --container_disk_watch_interval=3D"1= 5secs" --containerizers=3D"mesos" --credential=3D"/tmp/PersistentVolumeEndp= ointsTest_ReserveAndSlaveRemoval_RnxQRd/credential" --default_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_de= lay=3D"6hrs" --docker_socket=3D"/var/run/docker.sock" --docker_stop_timeout= =3D"0ns" --docker_store_dir=3D"/tmp/PersistentVolumeEndpointsTest_ReserveAn= dSlaveRemoval_RnxQRd/store/docker" --docker_volume_checkpoint_dir=3D"/var/r= un/mesos/isolators/docker/volume" --enforce_container_disk_quota=3D"false" = --executor_registration_timeout=3D"1mins" --executor_reregistration_timeout= =3D"2secs" --executor_shutdown_grace_period=3D"5secs" --fetcher_cache_dir= =3D"/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_RnxQRd/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_l= ookup=3D"true" --http_command_executor=3D"false" --http_credentials=3D"/tmp= /PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_RnxQRd/http_credentia= ls" --http_heartbeat_interval=3D"30secs" --initialize_driver_logging=3D"tru= e" --isolation=3D"posix/cpu,posix/mem" --launcher=3D"posix" --launcher_dir= =3D"/mesos/build/src" --logbufsecs=3D"0" --logging_level=3D"INFO" --max_com= pleted_executors_per_framework=3D"150" --oversubscribed_resources_interval= =3D"15secs" --perf_duration=3D"10secs" --perf_interval=3D"1mins" --port=3D"= 5051" --qos_correction_interval_min=3D"0ns" --quiet=3D"false" --recover=3D"= reconnect" --recovery_timeout=3D"15mins" --registration_backoff_factor=3D"1= 0ms" --resources=3D"cpus:4" --revocable_cpu_low_priority=3D"true" --runtime= _dir=3D"/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_RnxQRd" -= -sandbox_directory=3D"/mnt/mesos/sandbox" --strict=3D"true" --switch_user= =3D"true" --systemd_enable_support=3D"true" --systemd_runtime_directory=3D"= /run/systemd/system" --version=3D"false" --work_dir=3D"/tmp/PersistentVolum= eEndpointsTest_ReserveAndSlaveRemoval_buPjGf" I0627 15:20:33.715536 30776 credentials.hpp:86] Loading credential for auth= entication from '/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_= RnxQRd/credential' I0627 15:20:33.715909 30776 slave.cpp:282] Agent using credential for: test= -principal I0627 15:20:33.716008 30776 credentials.hpp:37] Loading credentials for aut= hentication from '/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval= _RnxQRd/http_credentials' I0627 15:20:33.716431 30776 http.cpp:974] Creating default 'basic' HTTP aut= henticator for realm 'mesos-agent-readonly' I0627 15:20:33.716806 30776 http.cpp:974] Creating default 'basic' HTTP aut= henticator for realm 'mesos-agent-readwrite' I0627 15:20:33.717967 30776 slave.cpp:553] Agent resources: [{"name":"cpus"= ,"scalar":{"value":4.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":95= 614.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":367489.0},"type":"= SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"= type":"RANGES"}] I0627 15:20:33.718209 30776 slave.cpp:561] Agent attributes: [ ] I0627 15:20:33.718225 30776 slave.cpp:566] Agent hostname: 0b1049f05548 I0627 15:20:33.718375 30783 status_update_manager.cpp:177] Pausing sending = status updates I0627 15:20:33.720067 30795 state.cpp:64] Recovering state from '/tmp/Persi= stentVolumeEndpointsTest_ReserveAndSlaveRemoval_buPjGf/meta' I0627 15:20:33.720432 30778 status_update_manager.cpp:203] Recovering statu= s update manager I0627 15:20:33.720608 30795 containerizer.cpp:582] Recovering containerizer I0627 15:20:33.722419 30790 provisioner.cpp:416] Provisioner recovery compl= ete I0627 15:20:33.722766 30786 slave.cpp:6168] Finished recovery I0627 15:20:33.723409 30786 slave.cpp:6350] Querying resource estimator for= oversubscribable resources I0627 15:20:33.724009 30784 slave.cpp:946] New master detected at master@17= 2.17.0.2:44357 I0627 15:20:33.724221 30784 slave.cpp:981] Detecting new master I0627 15:20:33.724370 30784 slave.cpp:6364] Received oversubscribable resou= rces {} from the resource estimator I0627 15:20:33.725513 30784 slave.cpp:1008] Authenticating with master mast= er@172.17.0.2:44357 I0627 15:20:33.725639 30784 slave.cpp:1019] Using default CRAM-MD5 authenti= catee I0627 15:20:33.725975 30784 authenticatee.cpp:121] Creating new client SASL= connection I0627 15:20:33.726358 30784 master.cpp:7640] Authenticating slave(451)@172.= 17.0.2:44357 I0627 15:20:33.726567 30784 authenticator.cpp:414] Starting authentication = session for crammd5-authenticatee(938)@172.17.0.2:44357 I0627 15:20:33.726917 30784 authenticator.cpp:98] Creating new server SASL = connection I0627 15:20:33.727162 30784 authenticatee.cpp:213] Received SASL authentica= tion mechanisms: CRAM-MD5 I0627 15:20:33.727192 30784 authenticatee.cpp:239] Attempting to authentica= te with mechanism 'CRAM-MD5' I0627 15:20:33.727285 30784 authenticator.cpp:204] Received SASL authentica= tion start I0627 15:20:33.727344 30784 authenticator.cpp:326] Authentication requires = more steps I0627 15:20:33.727429 30784 authenticatee.cpp:259] Received SASL authentica= tion step I0627 15:20:33.727546 30781 status_update_manager.cpp:177] Pausing sending = status updates I0627 15:20:33.727591 30784 authenticator.cpp:232] Received SASL authentica= tion step I0627 15:20:33.727624 30784 auxprop.cpp:109] Request to lookup properties f= or user: 'test-principal' realm: '0b1049f05548' server FQDN: '0b1049f05548'= SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_= AUXPROP_AUTHZID: false=20 I0627 15:20:33.727640 30784 auxprop.cpp:181] Looking up auxiliary property = '*userPassword' I0627 15:20:33.727690 30784 auxprop.cpp:181] Looking up auxiliary property = '*cmusaslsecretCRAM-MD5' I0627 15:20:33.727715 30784 auxprop.cpp:109] Request to lookup properties f= or user: 'test-principal' realm: '0b1049f05548' server FQDN: '0b1049f05548'= SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_= AUXPROP_AUTHZID: true=20 I0627 15:20:33.727726 30784 auxprop.cpp:131] Skipping auxiliary property '*= userPassword' since SASL_AUXPROP_AUTHZID =3D=3D true I0627 15:20:33.727737 30784 auxprop.cpp:131] Skipping auxiliary property '*= cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID =3D=3D true I0627 15:20:33.727757 30784 authenticator.cpp:318] Authentication success I0627 15:20:33.727963 30784 authenticatee.cpp:299] Authentication success I0627 15:20:33.728052 30784 master.cpp:7670] Successfully authenticated pri= ncipal 'test-principal' at slave(451)@172.17.0.2:44357 I0627 15:20:33.728145 30784 authenticator.cpp:432] Authentication session c= leanup for crammd5-authenticatee(938)@172.17.0.2:44357 I0627 15:20:33.728500 30784 slave.cpp:1103] Successfully authenticated with= master master@172.17.0.2:44357 I0627 15:20:33.728786 30784 slave.cpp:1545] Will retry registration in 1.21= 6522ms if necessary I0627 15:20:33.729225 30784 master.cpp:5602] Received register agent messag= e from slave(451)@172.17.0.2:44357 (0b1049f05548) I0627 15:20:33.729265 30784 master.cpp:3742] Authorizing agent with princip= al 'test-principal' I0627 15:20:33.729861 30784 master.cpp:5662] Authorized registration of age= nt at slave(451)@172.17.0.2:44357 (0b1049f05548) I0627 15:20:33.729984 30784 master.cpp:5741] Registering agent at slave(451= )@172.17.0.2:44357 (0b1049f05548) with id d8d232e5-1689-4780-b232-c91e5c327= 7b1-S0 I0627 15:20:33.730517 30784 registrar.cpp:493] Applied 1 operations in 8987= 8ns; attempting to update the registry I0627 15:20:33.731552 30784 registrar.cpp:550] Successfully updated the reg= istry in 956928ns I0627 15:20:33.731950 30784 slave.cpp:1545] Will retry registration in 4.85= 3741ms if necessary I0627 15:20:33.732209 30784 master.cpp:5788] Admitted agent d8d232e5-1689-4= 780-b232-c91e5c3277b1-S0 at slave(451)@172.17.0.2:44357 (0b1049f05548) I0627 15:20:33.732918 30784 master.cpp:5819] Registered agent d8d232e5-1689= -4780-b232-c91e5c3277b1-S0 at slave(451)@172.17.0.2:44357 (0b1049f05548) wi= th [{"name":"cpus","scalar":{"value":4.0},"type":"SCALAR"},{"name":"mem","s= calar":{"value":95614.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":= 367489.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":3100= 0,"end":32000}]},"type":"RANGES"}] I0627 15:20:33.733402 30784 master.cpp:5602] Received register agent messag= e from slave(451)@172.17.0.2:44357 (0b1049f05548) I0627 15:20:33.733438 30784 master.cpp:3742] Authorizing agent with princip= al 'test-principal' I0627 15:20:33.734184 30784 hierarchical.cpp:587] Added agent d8d232e5-1689= -4780-b232-c91e5c3277b1-S0 (0b1049f05548) with cpus:4; mem:95614; disk:3674= 89; ports:[31000-32000] (allocated: {}) I0627 15:20:33.734509 30784 hierarchical.cpp:1938] No allocations performed I0627 15:20:33.734563 30784 hierarchical.cpp:1493] Performed allocation for= 1 agents in 203705ns I0627 15:20:33.734794 30784 slave.cpp:1149] Registered with master master@1= 72.17.0.2:44357; given agent ID d8d232e5-1689-4780-b232-c91e5c3277b1-S0 I0627 15:20:33.735222 30784 slave.cpp:1169] Checkpointing SlaveInfo to '/tm= p/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_buPjGf/meta/slaves/d= 8d232e5-1689-4780-b232-c91e5c3277b1-S0/slave.info' I0627 15:20:33.735703 30784 slave.cpp:1207] Forwarding total oversubscribed= resources {} I0627 15:20:33.735824 30784 slave.cpp:4866] Received ping from slave-observ= er(449)@172.17.0.2:44357 I0627 15:20:33.736479 30784 status_update_manager.cpp:184] Resuming sending= status updates I0627 15:20:33.736613 30784 master.cpp:6508] Received update of agent d8d23= 2e5-1689-4780-b232-c91e5c3277b1-S0 at slave(451)@172.17.0.2:44357 (0b1049f0= 5548) with total oversubscribed resources {} I0627 15:20:33.736809 30784 master.cpp:5662] Authorized registration of age= nt at slave(451)@172.17.0.2:44357 (0b1049f05548) I0627 15:20:33.736912 30784 master.cpp:5719] Agent d8d232e5-1689-4780-b232-= c91e5c3277b1-S0 at slave(451)@172.17.0.2:44357 (0b1049f05548) already regis= tered, resending acknowledgement W0627 15:20:33.737525 30777 slave.cpp:1193] Already registered with master = master@172.17.0.2:44357 I0627 15:20:33.737548 30777 slave.cpp:1207] Forwarding total oversubscribed= resources {} I0627 15:20:33.737752 30775 master.cpp:6508] Received update of agent d8d23= 2e5-1689-4780-b232-c91e5c3277b1-S0 at slave(451)@172.17.0.2:44357 (0b1049f0= 5548) with total oversubscribed resources {} I0627 15:20:33.744215 30775 hierarchical.cpp:1938] No allocations performed I0627 15:20:33.744280 30775 hierarchical.cpp:1493] Performed allocation for= 1 agents in 249949ns I0627 15:20:33.745524 30773 containerizer.cpp:230] Using isolation: posix/c= pu,posix/mem,filesystem/posix,network/cni,environment_secret W0627 15:20:33.746350 30773 backend.cpp:76] Failed to create 'aufs' backend= : AufsBackend requires root privileges W0627 15:20:33.746516 30773 backend.cpp:76] Failed to create 'bind' backend= : BindBackend requires root privileges I0627 15:20:33.746562 30773 provisioner.cpp:255] Using default backend 'cop= y' I0627 15:20:33.749130 30773 cluster.cpp:448] Creating default 'local' autho= rizer I0627 15:20:33.751713 30774 slave.cpp:249] Mesos agent started on (452)@172= .17.0.2:44357 I0627 15:20:33.751760 30774 slave.cpp:250] Flags at startup: --acls=3D"" --= appc_simple_discovery_uri_prefix=3D"http://" --appc_store_dir=3D"/tmp/Persi= stentVolumeEndpointsTest_ReserveAndSlaveRemoval_g5ycV6/store/appc" --authen= ticate_http_readonly=3D"true" --authenticate_http_readwrite=3D"true" --auth= enticatee=3D"crammd5" --authentication_backoff_factor=3D"1secs" --authorize= r=3D"local" --cgroups_cpu_enable_pids_and_tids_count=3D"false" --cgroups_en= able_cfs=3D"false" --cgroups_hierarchy=3D"/sys/fs/cgroup" --cgroups_limit_s= wap=3D"false" --cgroups_root=3D"mesos" --container_disk_watch_interval=3D"1= 5secs" --containerizers=3D"mesos" --credential=3D"/tmp/PersistentVolumeEndp= ointsTest_ReserveAndSlaveRemoval_g5ycV6/credential" --default_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_de= lay=3D"6hrs" --docker_socket=3D"/var/run/docker.sock" --docker_stop_timeout= =3D"0ns" --docker_store_dir=3D"/tmp/PersistentVolumeEndpointsTest_ReserveAn= dSlaveRemoval_g5ycV6/store/docker" --docker_volume_checkpoint_dir=3D"/var/r= un/mesos/isolators/docker/volume" --enforce_container_disk_quota=3D"false" = --executor_registration_timeout=3D"1mins" --executor_reregistration_timeout= =3D"2secs" --executor_shutdown_grace_period=3D"5secs" --fetcher_cache_dir= =3D"/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_g5ycV6/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_l= ookup=3D"true" --http_command_executor=3D"false" --http_credentials=3D"/tmp= /PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_g5ycV6/http_credentia= ls" --http_heartbeat_interval=3D"30secs" --initialize_driver_logging=3D"tru= e" --isolation=3D"posix/cpu,posix/mem" --launcher=3D"posix" --launcher_dir= =3D"/mesos/build/src" --logbufsecs=3D"0" --logging_level=3D"INFO" --max_com= pleted_executors_per_framework=3D"150" --oversubscribed_resources_interval= =3D"15secs" --perf_duration=3D"10secs" --perf_interval=3D"1mins" --port=3D"= 5051" --qos_correction_interval_min=3D"0ns" --quiet=3D"false" --recover=3D"= reconnect" --recovery_timeout=3D"15mins" --registration_backoff_factor=3D"1= 0ms" --resources=3D"cpus:3" --revocable_cpu_low_priority=3D"true" --runtime= _dir=3D"/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_g5ycV6" -= -sandbox_directory=3D"/mnt/mesos/sandbox" --strict=3D"true" --switch_user= =3D"true" --systemd_enable_support=3D"true" --systemd_runtime_directory=3D"= /run/systemd/system" --version=3D"false" --work_dir=3D"/tmp/PersistentVolum= eEndpointsTest_ReserveAndSlaveRemoval_QWO1D8" I0627 15:20:33.752180 30774 credentials.hpp:86] Loading credential for auth= entication from '/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_= g5ycV6/credential' I0627 15:20:33.752401 30774 slave.cpp:282] Agent using credential for: test= -principal I0627 15:20:33.752419 30774 credentials.hpp:37] Loading credentials for aut= hentication from '/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval= _g5ycV6/http_credentials' I0627 15:20:33.752648 30774 http.cpp:974] Creating default 'basic' HTTP aut= henticator for realm 'mesos-agent-readonly' I0627 15:20:33.752821 30774 http.cpp:974] Creating default 'basic' HTTP aut= henticator for realm 'mesos-agent-readwrite' I0627 15:20:33.753873 30774 slave.cpp:553] Agent resources: [{"name":"cpus"= ,"scalar":{"value":3.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":95= 614.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":367489.0},"type":"= SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"= type":"RANGES"}] I0627 15:20:33.754041 30774 slave.cpp:561] Agent attributes: [ ] I0627 15:20:33.754051 30774 slave.cpp:566] Agent hostname: 0b1049f05548 I0627 15:20:33.754200 30788 status_update_manager.cpp:177] Pausing sending = status updates I0627 15:20:33.755672 30792 state.cpp:64] Recovering state from '/tmp/Persi= stentVolumeEndpointsTest_ReserveAndSlaveRemoval_QWO1D8/meta' I0627 15:20:33.755934 30790 status_update_manager.cpp:203] Recovering statu= s update manager I0627 15:20:33.756114 30789 containerizer.cpp:582] Recovering containerizer I0627 15:20:33.756492 30778 process.cpp:3779] Handling HTTP event for proce= ss 'master' with path: '/master/reserve' I0627 15:20:33.757879 30783 provisioner.cpp:416] Provisioner recovery compl= ete I0627 15:20:33.758180 30784 slave.cpp:6168] Finished recovery I0627 15:20:33.758538 30780 http.cpp:1114] HTTP POST for /master/reserve fr= om 172.17.0.2:44414 I0627 15:20:33.758766 30784 slave.cpp:6350] Querying resource estimator for= oversubscribable resources I0627 15:20:33.758973 30795 status_update_manager.cpp:177] Pausing sending = status updates I0627 15:20:33.758972 30784 slave.cpp:946] New master detected at master@17= 2.17.0.2:44357 I0627 15:20:33.759085 30784 slave.cpp:981] Detecting new master I0627 15:20:33.759176 30784 slave.cpp:6364] Received oversubscribable resou= rces {} from the resource estimator I0627 15:20:33.759441 30780 master.cpp:3527] Authorizing principal 'test-pr= incipal' to reserve resources '[{"name":"cpus","reservations":[{"principal"= :"test-principal","role":"role1","type":"DYNAMIC"}],"scalar":{"value":4.0},= "type":"SCALAR"}]' I0627 15:20:33.761719 30779 master.cpp:8908] Sending updated checkpointed r= esources cpus(reservations: [(DYNAMIC,role1,test-principal)]):4 to agent d8= d232e5-1689-4780-b232-c91e5c3277b1-S0 at slave(451)@172.17.0.2:44357 (0b104= 9f05548) I0627 15:20:33.762620 30794 slave.cpp:3426] Updated checkpointed resources = from {} to cpus(reservations: [(DYNAMIC,role1,test-principal)]):4 I0627 15:20:33.763795 30775 slave.cpp:1008] Authenticating with master mast= er@172.17.0.2:44357 I0627 15:20:33.763928 30775 slave.cpp:1019] Using default CRAM-MD5 authenti= catee I0627 15:20:33.764186 30795 authenticatee.cpp:121] Creating new client SASL= connection I0627 15:20:33.764468 30796 master.cpp:7640] Authenticating slave(452)@172.= 17.0.2:44357 I0627 15:20:33.764649 30785 authenticator.cpp:414] Starting authentication = session for crammd5-authenticatee(939)@172.17.0.2:44357 I0627 15:20:33.764925 30795 authenticator.cpp:98] Creating new server SASL = connection I0627 15:20:33.765175 30777 authenticatee.cpp:213] Received SASL authentica= tion mechanisms: CRAM-MD5 I0627 15:20:33.765203 30777 authenticatee.cpp:239] Attempting to authentica= te with mechanism 'CRAM-MD5' I0627 15:20:33.765386 30785 authenticator.cpp:204] Received SASL authentica= tion start I0627 15:20:33.765439 30785 authenticator.cpp:326] Authentication requires = more steps I0627 15:20:33.765538 30784 authenticatee.cpp:259] Received SASL authentica= tion step I0627 15:20:33.765709 30789 authenticator.cpp:232] Received SASL authentica= tion step I0627 15:20:33.765758 30789 auxprop.cpp:109] Request to lookup properties f= or user: 'test-principal' realm: '0b1049f05548' server FQDN: '0b1049f05548'= SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_= AUXPROP_AUTHZID: false=20 I0627 15:20:33.765774 30789 auxprop.cpp:181] Looking up auxiliary property = '*userPassword' I0627 15:20:33.765825 30789 auxprop.cpp:181] Looking up auxiliary property = '*cmusaslsecretCRAM-MD5' I0627 15:20:33.765854 30789 auxprop.cpp:109] Request to lookup properties f= or user: 'test-principal' realm: '0b1049f05548' server FQDN: '0b1049f05548'= SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_= AUXPROP_AUTHZID: true=20 I0627 15:20:33.765867 30789 auxprop.cpp:131] Skipping auxiliary property '*= userPassword' since SASL_AUXPROP_AUTHZID =3D=3D true I0627 15:20:33.765877 30789 auxprop.cpp:131] Skipping auxiliary property '*= cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID =3D=3D true I0627 15:20:33.765902 30789 authenticator.cpp:318] Authentication success I0627 15:20:33.766007 30773 sched.cpp:232] Version: 1.4.0 I0627 15:20:33.766126 30790 authenticatee.cpp:299] Authentication success I0627 15:20:33.766155 30788 master.cpp:7670] Successfully authenticated pri= ncipal 'test-principal' at slave(452)@172.17.0.2:44357 I0627 15:20:33.766187 30789 authenticator.cpp:432] Authentication session c= leanup for crammd5-authenticatee(939)@172.17.0.2:44357 I0627 15:20:33.766543 30776 slave.cpp:1103] Successfully authenticated with= master master@172.17.0.2:44357 I0627 15:20:33.766687 30793 sched.cpp:336] New master detected at master@17= 2.17.0.2:44357 I0627 15:20:33.766753 30793 sched.cpp:407] Authenticating with master maste= r@172.17.0.2:44357 I0627 15:20:33.766767 30793 sched.cpp:414] Using default CRAM-MD5 authentic= atee I0627 15:20:33.766770 30776 slave.cpp:1545] Will retry registration in 2.62= 5286ms if necessary I0627 15:20:33.766901 30789 master.cpp:5602] Received register agent messag= e from slave(452)@172.17.0.2:44357 (0b1049f05548) I0627 15:20:33.766932 30789 master.cpp:3742] Authorizing agent with princip= al 'test-principal' I0627 15:20:33.766964 30797 authenticatee.cpp:121] Creating new client SASL= connection I0627 15:20:33.767232 30789 master.cpp:7640] Authenticating scheduler-f690f= 5d5-752a-499b-aca5-a83801ba224a@172.17.0.2:44357 I0627 15:20:33.767307 30776 authenticator.cpp:414] Starting authentication = session for crammd5-authenticatee(940)@172.17.0.2:44357 I0627 15:20:33.767468 30774 master.cpp:5662] Authorized registration of age= nt at slave(452)@172.17.0.2:44357 (0b1049f05548) I0627 15:20:33.767489 30797 authenticator.cpp:98] Creating new server SASL = connection I0627 15:20:33.767608 30774 master.cpp:5741] Registering agent at slave(452= )@172.17.0.2:44357 (0b1049f05548) with id d8d232e5-1689-4780-b232-c91e5c327= 7b1-S1 I0627 15:20:33.767666 30778 authenticatee.cpp:213] Received SASL authentica= tion mechanisms: CRAM-MD5 I0627 15:20:33.767691 30778 authenticatee.cpp:239] Attempting to authentica= te with mechanism 'CRAM-MD5' I0627 15:20:33.767819 30797 authenticator.cpp:204] Received SASL authentica= tion start I0627 15:20:33.767864 30797 authenticator.cpp:326] Authentication requires = more steps I0627 15:20:33.767958 30786 authenticatee.cpp:259] Received SASL authentica= tion step I0627 15:20:33.767989 30781 registrar.cpp:493] Applied 1 operations in 8929= 1ns; attempting to update the registry I0627 15:20:33.768164 30788 authenticator.cpp:232] Received SASL authentica= tion step I0627 15:20:33.768187 30788 auxprop.cpp:109] Request to lookup properties f= or user: 'test-principal' realm: '0b1049f05548' server FQDN: '0b1049f05548'= SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_= AUXPROP_AUTHZID: false=20 I0627 15:20:33.768198 30788 auxprop.cpp:181] Looking up auxiliary property = '*userPassword' I0627 15:20:33.768239 30788 auxprop.cpp:181] Looking up auxiliary property = '*cmusaslsecretCRAM-MD5' I0627 15:20:33.768260 30788 auxprop.cpp:109] Request to lookup properties f= or user: 'test-principal' realm: '0b1049f05548' server FQDN: '0b1049f05548'= SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_= AUXPROP_AUTHZID: true=20 I0627 15:20:33.768267 30788 auxprop.cpp:131] Skipping auxiliary property '*= userPassword' since SASL_AUXPROP_AUTHZID =3D=3D true I0627 15:20:33.768272 30788 auxprop.cpp:131] Skipping auxiliary property '*= cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID =3D=3D true I0627 15:20:33.768285 30788 authenticator.cpp:318] Authentication success I0627 15:20:33.768394 30792 authenticatee.cpp:299] Authentication success I0627 15:20:33.768615 30777 master.cpp:7670] Successfully authenticated pri= ncipal 'test-principal' at scheduler-f690f5d5-752a-499b-aca5-a83801ba224a@1= 72.17.0.2:44357 I0627 15:20:33.768641 30790 sched.cpp:513] Successfully authenticated with = master master@172.17.0.2:44357 I0627 15:20:33.768661 30790 sched.cpp:836] Sending SUBSCRIBE call to master= @172.17.0.2:44357 I0627 15:20:33.768661 30776 authenticator.cpp:432] Authentication session c= leanup for crammd5-authenticatee(940)@172.17.0.2:44357 I0627 15:20:33.768782 30781 registrar.cpp:550] Successfully updated the reg= istry in 722176ns I0627 15:20:33.768887 30790 sched.cpp:869] Will retry registration in 424.4= 78509ms if necessary I0627 15:20:33.769176 30785 master.cpp:2853] Received SUBSCRIBE call for fr= amework 'default' at scheduler-f690f5d5-752a-499b-aca5-a83801ba224a@172.17.= 0.2:44357 I0627 15:20:33.769222 30785 master.cpp:2197] Authorizing framework principa= l 'test-principal' to receive offers for roles '{ role1 }' I0627 15:20:33.770375 30796 slave.cpp:1545] Will retry registration in 37.0= 54423ms if necessary I0627 15:20:33.770567 30785 master.cpp:5788] Admitted agent d8d232e5-1689-4= 780-b232-c91e5c3277b1-S1 at slave(452)@172.17.0.2:44357 (0b1049f05548) I0627 15:20:33.771241 30784 slave.cpp:4866] Received ping from slave-observ= er(450)@172.17.0.2:44357 I0627 15:20:33.771467 30787 slave.cpp:1149] Registered with master master@1= 72.17.0.2:44357; given agent ID d8d232e5-1689-4780-b232-c91e5c3277b1-S1 I0627 15:20:33.771585 30789 status_update_manager.cpp:184] Resuming sending= status updates I0627 15:20:33.771392 30785 master.cpp:5819] Registered agent d8d232e5-1689= -4780-b232-c91e5c3277b1-S1 at slave(452)@172.17.0.2:44357 (0b1049f05548) wi= th [{"name":"cpus","scalar":{"value":3.0},"type":"SCALAR"},{"name":"mem","s= calar":{"value":95614.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":= 367489.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":3100= 0,"end":32000}]},"type":"RANGES"}] I0627 15:20:33.771682 30777 hierarchical.cpp:587] Added agent d8d232e5-1689= -4780-b232-c91e5c3277b1-S1 (0b1049f05548) with cpus:3; mem:95614; disk:3674= 89; ports:[31000-32000] (allocated: {}) I0627 15:20:33.771832 30787 slave.cpp:1169] Checkpointing SlaveInfo to '/tm= p/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_QWO1D8/meta/slaves/d= 8d232e5-1689-4780-b232-c91e5c3277b1-S1/slave.info' I0627 15:20:33.771932 30777 hierarchical.cpp:1938] No allocations performed I0627 15:20:33.771953 30785 master.cpp:5602] Received register agent messag= e from slave(452)@172.17.0.2:44357 (0b1049f05548) I0627 15:20:33.771975 30777 hierarchical.cpp:1493] Performed allocation for= 1 agents in 164163ns I0627 15:20:33.771996 30785 master.cpp:3742] Authorizing agent with princip= al 'test-principal' I0627 15:20:33.772150 30787 slave.cpp:1207] Forwarding total oversubscribed= resources {} I0627 15:20:33.772339 30785 master.cpp:2933] Subscribing framework default = with checkpointing disabled and capabilities [ RESERVATION_REFINEMENT ] I0627 15:20:33.773007 30785 master.cpp:6508] Received update of agent d8d23= 2e5-1689-4780-b232-c91e5c3277b1-S1 at slave(452)@172.17.0.2:44357 (0b1049f0= 5548) with total oversubscribed resources {} I0627 15:20:33.773047 30794 sched.cpp:759] Framework registered with d8d232= e5-1689-4780-b232-c91e5c3277b1-0000 I0627 15:20:33.773095 30794 sched.cpp:773] Scheduler::registered took 31019= ns I0627 15:20:33.773164 30785 master.cpp:5662] Authorized registration of age= nt at slave(452)@172.17.0.2:44357 (0b1049f05548) I0627 15:20:33.773227 30776 hierarchical.cpp:301] Added framework d8d232e5-= 1689-4780-b232-c91e5c3277b1-0000 I0627 15:20:33.773247 30785 master.cpp:5719] Agent d8d232e5-1689-4780-b232-= c91e5c3277b1-S1 at slave(452)@172.17.0.2:44357 (0b1049f05548) already regis= tered, resending acknowledgement W0627 15:20:33.773438 30783 slave.cpp:1193] Already registered with master = master@172.17.0.2:44357 I0627 15:20:33.773470 30783 slave.cpp:1207] Forwarding total oversubscribed= resources {} I0627 15:20:33.773676 30781 master.cpp:6508] Received update of agent d8d23= 2e5-1689-4780-b232-c91e5c3277b1-S1 at slave(452)@172.17.0.2:44357 (0b1049f0= 5548) with total oversubscribed resources {} I0627 15:20:33.774871 30776 hierarchical.cpp:2028] No inverse offers to sen= d out! I0627 15:20:33.774912 30776 hierarchical.cpp:1493] Performed allocation for= 2 agents in 1.518176ms I0627 15:20:33.776294 30783 master.cpp:7470] Sending 2 offers to framework = d8d232e5-1689-4780-b232-c91e5c3277b1-0000 (default) at scheduler-f690f5d5-7= 52a-499b-aca5-a83801ba224a@172.17.0.2:44357 I0627 15:20:33.776959 30776 sched.cpp:933] Scheduler::resourceOffers took 1= 33421ns /mesos/src/tests/persistent_volume_endpoints_tests.cpp:1859: Failure Value of: offeredSlaveId =3D=3D slaveId1 || offeredSlaveId =3D=3D slaveId2 Actual: false Expected: true I0627 15:20:33.778265 30791 master.cpp:1430] Framework d8d232e5-1689-4780-b= 232-c91e5c3277b1-0000 (default) at scheduler-f690f5d5-752a-499b-aca5-a83801= ba224a@172.17.0.2:44357 disconnected I0627 15:20:33.778303 30791 master.cpp:3203] Deactivating framework d8d232e= 5-1689-4780-b232-c91e5c3277b1-0000 (default) at scheduler-f690f5d5-752a-499= b-aca5-a83801ba224a@172.17.0.2:44357 I0627 15:20:33.779554 30787 hierarchical.cpp:410] Deactivated framework d8d= 232e5-1689-4780-b232-c91e5c3277b1-0000 I0627 15:20:33.779958 30791 master.cpp:3180] Disconnecting framework d8d232= e5-1689-4780-b232-c91e5c3277b1-0000 (default) at scheduler-f690f5d5-752a-49= 9b-aca5-a83801ba224a@172.17.0.2:44357 I0627 15:20:33.780009 30791 master.cpp:1445] Giving framework d8d232e5-1689= -4780-b232-c91e5c3277b1-0000 (default) at scheduler-f690f5d5-752a-499b-aca5= -a83801ba224a@172.17.0.2:44357 0ns to failover I0627 15:20:33.780483 30787 hierarchical.cpp:1177] Recovered ports(allocate= d: role1):[31000-32000]; mem(allocated: role1):95614; disk(allocated: role1= ):367489; cpus(allocated: role1)(reservations: [(DYNAMIC,role1,test-princip= al)]):4 (total: ports:[31000-32000]; mem:95614; disk:367489; cpus(reservati= ons: [(DYNAMIC,role1,test-principal)]):4, allocated: {}) on agent d8d232e5-= 1689-4780-b232-c91e5c3277b1-S0 from framework d8d232e5-1689-4780-b232-c91e5= c3277b1-0000 I0627 15:20:33.781185 30787 hierarchical.cpp:1177] Recovered cpus(allocated= : role1):3; mem(allocated: role1):95614; disk(allocated: role1):367489; por= ts(allocated: role1):[31000-32000] (total: cpus:3; mem:95614; disk:367489; = ports:[31000-32000], allocated: {}) on agent d8d232e5-1689-4780-b232-c91e5c= 3277b1-S1 from framework d8d232e5-1689-4780-b232-c91e5c3277b1-0000 I0627 15:20:33.781599 30789 master.cpp:7306] Framework failover timeout, re= moving framework d8d232e5-1689-4780-b232-c91e5c3277b1-0000 (default) at sch= eduler-f690f5d5-752a-499b-aca5-a83801ba224a@172.17.0.2:44357 I0627 15:20:33.781625 30789 master.cpp:8163] Removing framework d8d232e5-16= 89-4780-b232-c91e5c3277b1-0000 (default) at scheduler-f690f5d5-752a-499b-ac= a5-a83801ba224a@172.17.0.2:44357 I0627 15:20:33.781790 30787 slave.cpp:3136] Asked to shut down framework d8= d232e5-1689-4780-b232-c91e5c3277b1-0000 by master@172.17.0.2:44357 I0627 15:20:33.781803 30791 slave.cpp:3136] Asked to shut down framework d8= d232e5-1689-4780-b232-c91e5c3277b1-0000 by master@172.17.0.2:44357 I0627 15:20:33.781817 30787 slave.cpp:3151] Cannot shut down unknown framew= ork d8d232e5-1689-4780-b232-c91e5c3277b1-0000 I0627 15:20:33.781831 30791 slave.cpp:3151] Cannot shut down unknown framew= ork d8d232e5-1689-4780-b232-c91e5c3277b1-0000 I0627 15:20:33.782289 30780 hierarchical.cpp:353] Removed framework d8d232e= 5-1689-4780-b232-c91e5c3277b1-0000 I0627 15:20:33.788432 30787 slave.cpp:818] Agent terminating I0627 15:20:33.788750 30796 master.cpp:1316] Agent d8d232e5-1689-4780-b232-= c91e5c3277b1-S1 at slave(452)@172.17.0.2:44357 (0b1049f05548) disconnected I0627 15:20:33.788781 30796 master.cpp:3240] Disconnecting agent d8d232e5-1= 689-4780-b232-c91e5c3277b1-S1 at slave(452)@172.17.0.2:44357 (0b1049f05548) I0627 15:20:33.788859 30796 master.cpp:3259] Deactivating agent d8d232e5-16= 89-4780-b232-c91e5c3277b1-S1 at slave(452)@172.17.0.2:44357 (0b1049f05548) I0627 15:20:33.788995 30777 hierarchical.cpp:715] Agent d8d232e5-1689-4780-= b232-c91e5c3277b1-S1 deactivated I0627 15:20:33.796249 30779 hierarchical.cpp:1938] No allocations performed I0627 15:20:33.796330 30779 hierarchical.cpp:1493] Performed allocation for= 2 agents in 319501ns I0627 15:20:33.798933 30796 slave.cpp:818] Agent terminating I0627 15:20:33.799327 30795 master.cpp:1316] Agent d8d232e5-1689-4780-b232-= c91e5c3277b1-S0 at slave(451)@172.17.0.2:44357 (0b1049f05548) disconnected I0627 15:20:33.799360 30795 master.cpp:3240] Disconnecting agent d8d232e5-1= 689-4780-b232-c91e5c3277b1-S0 at slave(451)@172.17.0.2:44357 (0b1049f05548) I0627 15:20:33.799438 30795 master.cpp:3259] Deactivating agent d8d232e5-16= 89-4780-b232-c91e5c3277b1-S0 at slave(451)@172.17.0.2:44357 (0b1049f05548) I0627 15:20:33.799567 30787 hierarchical.cpp:715] Agent d8d232e5-1689-4780-= b232-c91e5c3277b1-S0 deactivated I0627 15:20:33.804204 30779 master.cpp:1158] Master terminating I0627 15:20:33.810475 30780 hierarchical.cpp:620] Removed agent d8d232e5-16= 89-4780-b232-c91e5c3277b1-S1 I0627 15:20:33.811208 30780 hierarchical.cpp:620] Removed agent d8d232e5-16= 89-4780-b232-c91e5c3277b1-S0 /mesos/3rdparty/libprocess/include/process/gmock.hpp:441: Failure Actual function call count doesn't match EXPECT_CALL(filter->mock, filter(t= esting::A()))... Expected args: message matcher (8-byte object = , 1, 1) Expected: to be called once Actual: never called - unsatisfied and active [ FAILED ] PersistentVolumeEndpointsTest.ReserveAndSlaveRemoval (138 ms) {code} [~neilconway] Can you take a look at this? This has been terribly flaky on = ASF CI. was: Observed this on ASF CI. Will paste the log once I find a failing build whose logs are not rotated o= ut. > PersistentVolumeEndpointsTest.ReserveAndSlaveRemoval test is flaky > ------------------------------------------------------------------ > > Key: MESOS-7725 > URL: https://issues.apache.org/jira/browse/MESOS-7725 > Project: Mesos > Issue Type: Bug > Reporter: Vinod Kone > Assignee: Neil Conway > Labels: flaky-test, mesosphere-oncall > > Observed this on ASF CI. > {code} > [ RUN ] PersistentVolumeEndpointsTest.ReserveAndSlaveRemoval > I0627 15:20:33.687146 30773 cluster.cpp:162] Creating default 'local' aut= horizer > I0627 15:20:33.691745 30795 master.cpp:438] Master d8d232e5-1689-4780-b23= 2-c91e5c3277b1 (0b1049f05548) started on 172.17.0.2:44357 > I0627 15:20:33.691800 30795 master.cpp:440] Flags at startup: --acls=3D""= --agent_ping_timeout=3D"15secs" --agent_reregister_timeout=3D"10mins" --al= location_interval=3D"50ms" --allocator=3D"HierarchicalDRF" --authenticate_a= gents=3D"true" --authenticate_frameworks=3D"true" --authenticate_http_frame= works=3D"true" --authenticate_http_readonly=3D"true" --authenticate_http_re= adwrite=3D"true" --authenticators=3D"crammd5" --authorizers=3D"local" --cre= dentials=3D"/tmp/Wg4Ouh/credentials" --filter_gpu_resources=3D"true" --fram= ework_sorter=3D"drf" --help=3D"false" --hostname_lookup=3D"true" --http_aut= henticators=3D"basic" --http_framework_authenticators=3D"basic" --initializ= e_driver_logging=3D"true" --log_auto_initialize=3D"true" --logbufsecs=3D"0"= --logging_level=3D"INFO" --max_agent_ping_timeouts=3D"5" --max_completed_f= rameworks=3D"50" --max_completed_tasks_per_framework=3D"1000" --max_unreach= able_tasks_per_framework=3D"1000" --port=3D"5050" --quiet=3D"false" --recov= ery_agent_removal_limit=3D"100%" --registry=3D"in_memory" --registry_fetch_= timeout=3D"1mins" --registry_gc_interval=3D"15mins" --registry_max_agent_ag= e=3D"2weeks" --registry_max_agent_count=3D"102400" --registry_store_timeout= =3D"100secs" --registry_strict=3D"false" --roles=3D"role1" --root_submissio= ns=3D"true" --user_sorter=3D"drf" --version=3D"false" --webui_dir=3D"/usr/l= ocal/share/mesos/webui" --work_dir=3D"/tmp/Wg4Ouh/master" --zk_session_time= out=3D"10secs" > I0627 15:20:33.692142 30795 master.cpp:490] Master only allowing authenti= cated frameworks to register > I0627 15:20:33.692150 30795 master.cpp:504] Master only allowing authenti= cated agents to register > I0627 15:20:33.692154 30795 master.cpp:517] Master only allowing authenti= cated HTTP frameworks to register > I0627 15:20:33.692160 30795 credentials.hpp:37] Loading credentials for a= uthentication from '/tmp/Wg4Ouh/credentials' > I0627 15:20:33.692463 30795 master.cpp:562] Using default 'crammd5' authe= nticator > I0627 15:20:33.692612 30795 http.cpp:974] Creating default 'basic' HTTP a= uthenticator for realm 'mesos-master-readonly' > I0627 15:20:33.692831 30795 http.cpp:974] Creating default 'basic' HTTP a= uthenticator for realm 'mesos-master-readwrite' > I0627 15:20:33.692942 30795 http.cpp:974] Creating default 'basic' HTTP a= uthenticator for realm 'mesos-master-scheduler' > I0627 15:20:33.693061 30795 master.cpp:642] Authorization enabled > W0627 15:20:33.693076 30795 master.cpp:705] The '--roles' flag is depreca= ted. This flag will be removed in the future. See the Mesos 0.27 upgrade no= tes for more information > I0627 15:20:33.693354 30780 hierarchical.cpp:169] Initialized hierarchica= l allocator process > I0627 15:20:33.693359 30782 whitelist_watcher.cpp:77] No whitelist given > I0627 15:20:33.695943 30795 master.cpp:2161] Elected as the leading maste= r! > I0627 15:20:33.695960 30795 master.cpp:1700] Recovering from registrar > I0627 15:20:33.696193 30795 registrar.cpp:345] Recovering registrar > I0627 15:20:33.697032 30795 registrar.cpp:389] Successfully fetched the r= egistry (0B) in 811008ns > I0627 15:20:33.697147 30795 registrar.cpp:493] Applied 1 operations in 40= 183ns; attempting to update the registry > I0627 15:20:33.697922 30792 registrar.cpp:550] Successfully updated the r= egistry in 709120ns > I0627 15:20:33.698020 30792 registrar.cpp:422] Successfully recovered reg= istrar > I0627 15:20:33.698490 30789 master.cpp:1799] Recovered 0 agents from the = registry (129B); allowing 10mins for agents to re-register > I0627 15:20:33.698511 30784 hierarchical.cpp:207] Skipping recovery of hi= erarchical allocator: nothing to recover > I0627 15:20:33.707849 30773 containerizer.cpp:230] Using isolation: posix= /cpu,posix/mem,filesystem/posix,network/cni,environment_secret > W0627 15:20:33.708729 30773 backend.cpp:76] Failed to create 'aufs' backe= nd: AufsBackend requires root privileges > W0627 15:20:33.708909 30773 backend.cpp:76] Failed to create 'bind' backe= nd: BindBackend requires root privileges > I0627 15:20:33.708955 30773 provisioner.cpp:255] Using default backend 'c= opy' > I0627 15:20:33.711526 30773 cluster.cpp:448] Creating default 'local' aut= horizer > I0627 15:20:33.714450 30776 slave.cpp:249] Mesos agent started on (451)@1= 72.17.0.2:44357 > I0627 15:20:33.714649 30776 slave.cpp:250] Flags at startup: --acls=3D"" = --appc_simple_discovery_uri_prefix=3D"http://" --appc_store_dir=3D"/tmp/Per= sistentVolumeEndpointsTest_ReserveAndSlaveRemoval_RnxQRd/store/appc" --auth= enticate_http_readonly=3D"true" --authenticate_http_readwrite=3D"true" --au= thenticatee=3D"crammd5" --authentication_backoff_factor=3D"1secs" --authori= zer=3D"local" --cgroups_cpu_enable_pids_and_tids_count=3D"false" --cgroups_= enable_cfs=3D"false" --cgroups_hierarchy=3D"/sys/fs/cgroup" --cgroups_limit= _swap=3D"false" --cgroups_root=3D"mesos" --container_disk_watch_interval=3D= "15secs" --containerizers=3D"mesos" --credential=3D"/tmp/PersistentVolumeEn= dpointsTest_ReserveAndSlaveRemoval_RnxQRd/credential" --default_role=3D"*" = --disk_watch_interval=3D"1mins" --docker=3D"docker" --docker_kill_orphans= =3D"true" --docker_registry=3D"https://registry-1.docker.io" --docker_remov= e_delay=3D"6hrs" --docker_socket=3D"/var/run/docker.sock" --docker_stop_tim= eout=3D"0ns" --docker_store_dir=3D"/tmp/PersistentVolumeEndpointsTest_Reser= veAndSlaveRemoval_RnxQRd/store/docker" --docker_volume_checkpoint_dir=3D"/v= ar/run/mesos/isolators/docker/volume" --enforce_container_disk_quota=3D"fal= se" --executor_registration_timeout=3D"1mins" --executor_reregistration_tim= eout=3D"2secs" --executor_shutdown_grace_period=3D"5secs" --fetcher_cache_d= ir=3D"/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_RnxQRd/fetc= h" --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_command_executor=3D"false" --http_credentials=3D"/t= mp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_RnxQRd/http_credent= ials" --http_heartbeat_interval=3D"30secs" --initialize_driver_logging=3D"t= rue" --isolation=3D"posix/cpu,posix/mem" --launcher=3D"posix" --launcher_di= r=3D"/mesos/build/src" --logbufsecs=3D"0" --logging_level=3D"INFO" --max_co= mpleted_executors_per_framework=3D"150" --oversubscribed_resources_interval= =3D"15secs" --perf_duration=3D"10secs" --perf_interval=3D"1mins" --port=3D"= 5051" --qos_correction_interval_min=3D"0ns" --quiet=3D"false" --recover=3D"= reconnect" --recovery_timeout=3D"15mins" --registration_backoff_factor=3D"1= 0ms" --resources=3D"cpus:4" --revocable_cpu_low_priority=3D"true" --runtime= _dir=3D"/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_RnxQRd" -= -sandbox_directory=3D"/mnt/mesos/sandbox" --strict=3D"true" --switch_user= =3D"true" --systemd_enable_support=3D"true" --systemd_runtime_directory=3D"= /run/systemd/system" --version=3D"false" --work_dir=3D"/tmp/PersistentVolum= eEndpointsTest_ReserveAndSlaveRemoval_buPjGf" > I0627 15:20:33.715536 30776 credentials.hpp:86] Loading credential for au= thentication from '/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemova= l_RnxQRd/credential' > I0627 15:20:33.715909 30776 slave.cpp:282] Agent using credential for: te= st-principal > I0627 15:20:33.716008 30776 credentials.hpp:37] Loading credentials for a= uthentication from '/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemov= al_RnxQRd/http_credentials' > I0627 15:20:33.716431 30776 http.cpp:974] Creating default 'basic' HTTP a= uthenticator for realm 'mesos-agent-readonly' > I0627 15:20:33.716806 30776 http.cpp:974] Creating default 'basic' HTTP a= uthenticator for realm 'mesos-agent-readwrite' > I0627 15:20:33.717967 30776 slave.cpp:553] Agent resources: [{"name":"cpu= s","scalar":{"value":4.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":= 95614.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":367489.0},"type"= :"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]}= ,"type":"RANGES"}] > I0627 15:20:33.718209 30776 slave.cpp:561] Agent attributes: [ ] > I0627 15:20:33.718225 30776 slave.cpp:566] Agent hostname: 0b1049f05548 > I0627 15:20:33.718375 30783 status_update_manager.cpp:177] Pausing sendin= g status updates > I0627 15:20:33.720067 30795 state.cpp:64] Recovering state from '/tmp/Per= sistentVolumeEndpointsTest_ReserveAndSlaveRemoval_buPjGf/meta' > I0627 15:20:33.720432 30778 status_update_manager.cpp:203] Recovering sta= tus update manager > I0627 15:20:33.720608 30795 containerizer.cpp:582] Recovering containeriz= er > I0627 15:20:33.722419 30790 provisioner.cpp:416] Provisioner recovery com= plete > I0627 15:20:33.722766 30786 slave.cpp:6168] Finished recovery > I0627 15:20:33.723409 30786 slave.cpp:6350] Querying resource estimator f= or oversubscribable resources > I0627 15:20:33.724009 30784 slave.cpp:946] New master detected at master@= 172.17.0.2:44357 > I0627 15:20:33.724221 30784 slave.cpp:981] Detecting new master > I0627 15:20:33.724370 30784 slave.cpp:6364] Received oversubscribable res= ources {} from the resource estimator > I0627 15:20:33.725513 30784 slave.cpp:1008] Authenticating with master ma= ster@172.17.0.2:44357 > I0627 15:20:33.725639 30784 slave.cpp:1019] Using default CRAM-MD5 authen= ticatee > I0627 15:20:33.725975 30784 authenticatee.cpp:121] Creating new client SA= SL connection > I0627 15:20:33.726358 30784 master.cpp:7640] Authenticating slave(451)@17= 2.17.0.2:44357 > I0627 15:20:33.726567 30784 authenticator.cpp:414] Starting authenticatio= n session for crammd5-authenticatee(938)@172.17.0.2:44357 > I0627 15:20:33.726917 30784 authenticator.cpp:98] Creating new server SAS= L connection > I0627 15:20:33.727162 30784 authenticatee.cpp:213] Received SASL authenti= cation mechanisms: CRAM-MD5 > I0627 15:20:33.727192 30784 authenticatee.cpp:239] Attempting to authenti= cate with mechanism 'CRAM-MD5' > I0627 15:20:33.727285 30784 authenticator.cpp:204] Received SASL authenti= cation start > I0627 15:20:33.727344 30784 authenticator.cpp:326] Authentication require= s more steps > I0627 15:20:33.727429 30784 authenticatee.cpp:259] Received SASL authenti= cation step > I0627 15:20:33.727546 30781 status_update_manager.cpp:177] Pausing sendin= g status updates > I0627 15:20:33.727591 30784 authenticator.cpp:232] Received SASL authenti= cation step > I0627 15:20:33.727624 30784 auxprop.cpp:109] Request to lookup properties= for user: 'test-principal' realm: '0b1049f05548' server FQDN: '0b1049f0554= 8' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SAS= L_AUXPROP_AUTHZID: false=20 > I0627 15:20:33.727640 30784 auxprop.cpp:181] Looking up auxiliary propert= y '*userPassword' > I0627 15:20:33.727690 30784 auxprop.cpp:181] Looking up auxiliary propert= y '*cmusaslsecretCRAM-MD5' > I0627 15:20:33.727715 30784 auxprop.cpp:109] Request to lookup properties= for user: 'test-principal' realm: '0b1049f05548' server FQDN: '0b1049f0554= 8' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SAS= L_AUXPROP_AUTHZID: true=20 > I0627 15:20:33.727726 30784 auxprop.cpp:131] Skipping auxiliary property = '*userPassword' since SASL_AUXPROP_AUTHZID =3D=3D true > I0627 15:20:33.727737 30784 auxprop.cpp:131] Skipping auxiliary property = '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID =3D=3D true > I0627 15:20:33.727757 30784 authenticator.cpp:318] Authentication success > I0627 15:20:33.727963 30784 authenticatee.cpp:299] Authentication success > I0627 15:20:33.728052 30784 master.cpp:7670] Successfully authenticated p= rincipal 'test-principal' at slave(451)@172.17.0.2:44357 > I0627 15:20:33.728145 30784 authenticator.cpp:432] Authentication session= cleanup for crammd5-authenticatee(938)@172.17.0.2:44357 > I0627 15:20:33.728500 30784 slave.cpp:1103] Successfully authenticated wi= th master master@172.17.0.2:44357 > I0627 15:20:33.728786 30784 slave.cpp:1545] Will retry registration in 1.= 216522ms if necessary > I0627 15:20:33.729225 30784 master.cpp:5602] Received register agent mess= age from slave(451)@172.17.0.2:44357 (0b1049f05548) > I0627 15:20:33.729265 30784 master.cpp:3742] Authorizing agent with princ= ipal 'test-principal' > I0627 15:20:33.729861 30784 master.cpp:5662] Authorized registration of a= gent at slave(451)@172.17.0.2:44357 (0b1049f05548) > I0627 15:20:33.729984 30784 master.cpp:5741] Registering agent at slave(4= 51)@172.17.0.2:44357 (0b1049f05548) with id d8d232e5-1689-4780-b232-c91e5c3= 277b1-S0 > I0627 15:20:33.730517 30784 registrar.cpp:493] Applied 1 operations in 89= 878ns; attempting to update the registry > I0627 15:20:33.731552 30784 registrar.cpp:550] Successfully updated the r= egistry in 956928ns > I0627 15:20:33.731950 30784 slave.cpp:1545] Will retry registration in 4.= 853741ms if necessary > I0627 15:20:33.732209 30784 master.cpp:5788] Admitted agent d8d232e5-1689= -4780-b232-c91e5c3277b1-S0 at slave(451)@172.17.0.2:44357 (0b1049f05548) > I0627 15:20:33.732918 30784 master.cpp:5819] Registered agent d8d232e5-16= 89-4780-b232-c91e5c3277b1-S0 at slave(451)@172.17.0.2:44357 (0b1049f05548) = with [{"name":"cpus","scalar":{"value":4.0},"type":"SCALAR"},{"name":"mem",= "scalar":{"value":95614.0},"type":"SCALAR"},{"name":"disk","scalar":{"value= ":367489.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31= 000,"end":32000}]},"type":"RANGES"}] > I0627 15:20:33.733402 30784 master.cpp:5602] Received register agent mess= age from slave(451)@172.17.0.2:44357 (0b1049f05548) > I0627 15:20:33.733438 30784 master.cpp:3742] Authorizing agent with princ= ipal 'test-principal' > I0627 15:20:33.734184 30784 hierarchical.cpp:587] Added agent d8d232e5-16= 89-4780-b232-c91e5c3277b1-S0 (0b1049f05548) with cpus:4; mem:95614; disk:36= 7489; ports:[31000-32000] (allocated: {}) > I0627 15:20:33.734509 30784 hierarchical.cpp:1938] No allocations perform= ed > I0627 15:20:33.734563 30784 hierarchical.cpp:1493] Performed allocation f= or 1 agents in 203705ns > I0627 15:20:33.734794 30784 slave.cpp:1149] Registered with master master= @172.17.0.2:44357; given agent ID d8d232e5-1689-4780-b232-c91e5c3277b1-S0 > I0627 15:20:33.735222 30784 slave.cpp:1169] Checkpointing SlaveInfo to '/= tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_buPjGf/meta/slaves= /d8d232e5-1689-4780-b232-c91e5c3277b1-S0/slave.info' > I0627 15:20:33.735703 30784 slave.cpp:1207] Forwarding total oversubscrib= ed resources {} > I0627 15:20:33.735824 30784 slave.cpp:4866] Received ping from slave-obse= rver(449)@172.17.0.2:44357 > I0627 15:20:33.736479 30784 status_update_manager.cpp:184] Resuming sendi= ng status updates > I0627 15:20:33.736613 30784 master.cpp:6508] Received update of agent d8d= 232e5-1689-4780-b232-c91e5c3277b1-S0 at slave(451)@172.17.0.2:44357 (0b1049= f05548) with total oversubscribed resources {} > I0627 15:20:33.736809 30784 master.cpp:5662] Authorized registration of a= gent at slave(451)@172.17.0.2:44357 (0b1049f05548) > I0627 15:20:33.736912 30784 master.cpp:5719] Agent d8d232e5-1689-4780-b23= 2-c91e5c3277b1-S0 at slave(451)@172.17.0.2:44357 (0b1049f05548) already reg= istered, resending acknowledgement > W0627 15:20:33.737525 30777 slave.cpp:1193] Already registered with maste= r master@172.17.0.2:44357 > I0627 15:20:33.737548 30777 slave.cpp:1207] Forwarding total oversubscrib= ed resources {} > I0627 15:20:33.737752 30775 master.cpp:6508] Received update of agent d8d= 232e5-1689-4780-b232-c91e5c3277b1-S0 at slave(451)@172.17.0.2:44357 (0b1049= f05548) with total oversubscribed resources {} > I0627 15:20:33.744215 30775 hierarchical.cpp:1938] No allocations perform= ed > I0627 15:20:33.744280 30775 hierarchical.cpp:1493] Performed allocation f= or 1 agents in 249949ns > I0627 15:20:33.745524 30773 containerizer.cpp:230] Using isolation: posix= /cpu,posix/mem,filesystem/posix,network/cni,environment_secret > W0627 15:20:33.746350 30773 backend.cpp:76] Failed to create 'aufs' backe= nd: AufsBackend requires root privileges > W0627 15:20:33.746516 30773 backend.cpp:76] Failed to create 'bind' backe= nd: BindBackend requires root privileges > I0627 15:20:33.746562 30773 provisioner.cpp:255] Using default backend 'c= opy' > I0627 15:20:33.749130 30773 cluster.cpp:448] Creating default 'local' aut= horizer > I0627 15:20:33.751713 30774 slave.cpp:249] Mesos agent started on (452)@1= 72.17.0.2:44357 > I0627 15:20:33.751760 30774 slave.cpp:250] Flags at startup: --acls=3D"" = --appc_simple_discovery_uri_prefix=3D"http://" --appc_store_dir=3D"/tmp/Per= sistentVolumeEndpointsTest_ReserveAndSlaveRemoval_g5ycV6/store/appc" --auth= enticate_http_readonly=3D"true" --authenticate_http_readwrite=3D"true" --au= thenticatee=3D"crammd5" --authentication_backoff_factor=3D"1secs" --authori= zer=3D"local" --cgroups_cpu_enable_pids_and_tids_count=3D"false" --cgroups_= enable_cfs=3D"false" --cgroups_hierarchy=3D"/sys/fs/cgroup" --cgroups_limit= _swap=3D"false" --cgroups_root=3D"mesos" --container_disk_watch_interval=3D= "15secs" --containerizers=3D"mesos" --credential=3D"/tmp/PersistentVolumeEn= dpointsTest_ReserveAndSlaveRemoval_g5ycV6/credential" --default_role=3D"*" = --disk_watch_interval=3D"1mins" --docker=3D"docker" --docker_kill_orphans= =3D"true" --docker_registry=3D"https://registry-1.docker.io" --docker_remov= e_delay=3D"6hrs" --docker_socket=3D"/var/run/docker.sock" --docker_stop_tim= eout=3D"0ns" --docker_store_dir=3D"/tmp/PersistentVolumeEndpointsTest_Reser= veAndSlaveRemoval_g5ycV6/store/docker" --docker_volume_checkpoint_dir=3D"/v= ar/run/mesos/isolators/docker/volume" --enforce_container_disk_quota=3D"fal= se" --executor_registration_timeout=3D"1mins" --executor_reregistration_tim= eout=3D"2secs" --executor_shutdown_grace_period=3D"5secs" --fetcher_cache_d= ir=3D"/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_g5ycV6/fetc= h" --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_command_executor=3D"false" --http_credentials=3D"/t= mp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_g5ycV6/http_credent= ials" --http_heartbeat_interval=3D"30secs" --initialize_driver_logging=3D"t= rue" --isolation=3D"posix/cpu,posix/mem" --launcher=3D"posix" --launcher_di= r=3D"/mesos/build/src" --logbufsecs=3D"0" --logging_level=3D"INFO" --max_co= mpleted_executors_per_framework=3D"150" --oversubscribed_resources_interval= =3D"15secs" --perf_duration=3D"10secs" --perf_interval=3D"1mins" --port=3D"= 5051" --qos_correction_interval_min=3D"0ns" --quiet=3D"false" --recover=3D"= reconnect" --recovery_timeout=3D"15mins" --registration_backoff_factor=3D"1= 0ms" --resources=3D"cpus:3" --revocable_cpu_low_priority=3D"true" --runtime= _dir=3D"/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_g5ycV6" -= -sandbox_directory=3D"/mnt/mesos/sandbox" --strict=3D"true" --switch_user= =3D"true" --systemd_enable_support=3D"true" --systemd_runtime_directory=3D"= /run/systemd/system" --version=3D"false" --work_dir=3D"/tmp/PersistentVolum= eEndpointsTest_ReserveAndSlaveRemoval_QWO1D8" > I0627 15:20:33.752180 30774 credentials.hpp:86] Loading credential for au= thentication from '/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemova= l_g5ycV6/credential' > I0627 15:20:33.752401 30774 slave.cpp:282] Agent using credential for: te= st-principal > I0627 15:20:33.752419 30774 credentials.hpp:37] Loading credentials for a= uthentication from '/tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemov= al_g5ycV6/http_credentials' > I0627 15:20:33.752648 30774 http.cpp:974] Creating default 'basic' HTTP a= uthenticator for realm 'mesos-agent-readonly' > I0627 15:20:33.752821 30774 http.cpp:974] Creating default 'basic' HTTP a= uthenticator for realm 'mesos-agent-readwrite' > I0627 15:20:33.753873 30774 slave.cpp:553] Agent resources: [{"name":"cpu= s","scalar":{"value":3.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":= 95614.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":367489.0},"type"= :"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]}= ,"type":"RANGES"}] > I0627 15:20:33.754041 30774 slave.cpp:561] Agent attributes: [ ] > I0627 15:20:33.754051 30774 slave.cpp:566] Agent hostname: 0b1049f05548 > I0627 15:20:33.754200 30788 status_update_manager.cpp:177] Pausing sendin= g status updates > I0627 15:20:33.755672 30792 state.cpp:64] Recovering state from '/tmp/Per= sistentVolumeEndpointsTest_ReserveAndSlaveRemoval_QWO1D8/meta' > I0627 15:20:33.755934 30790 status_update_manager.cpp:203] Recovering sta= tus update manager > I0627 15:20:33.756114 30789 containerizer.cpp:582] Recovering containeriz= er > I0627 15:20:33.756492 30778 process.cpp:3779] Handling HTTP event for pro= cess 'master' with path: '/master/reserve' > I0627 15:20:33.757879 30783 provisioner.cpp:416] Provisioner recovery com= plete > I0627 15:20:33.758180 30784 slave.cpp:6168] Finished recovery > I0627 15:20:33.758538 30780 http.cpp:1114] HTTP POST for /master/reserve = from 172.17.0.2:44414 > I0627 15:20:33.758766 30784 slave.cpp:6350] Querying resource estimator f= or oversubscribable resources > I0627 15:20:33.758973 30795 status_update_manager.cpp:177] Pausing sendin= g status updates > I0627 15:20:33.758972 30784 slave.cpp:946] New master detected at master@= 172.17.0.2:44357 > I0627 15:20:33.759085 30784 slave.cpp:981] Detecting new master > I0627 15:20:33.759176 30784 slave.cpp:6364] Received oversubscribable res= ources {} from the resource estimator > I0627 15:20:33.759441 30780 master.cpp:3527] Authorizing principal 'test-= principal' to reserve resources '[{"name":"cpus","reservations":[{"principa= l":"test-principal","role":"role1","type":"DYNAMIC"}],"scalar":{"value":4.0= },"type":"SCALAR"}]' > I0627 15:20:33.761719 30779 master.cpp:8908] Sending updated checkpointed= resources cpus(reservations: [(DYNAMIC,role1,test-principal)]):4 to agent = d8d232e5-1689-4780-b232-c91e5c3277b1-S0 at slave(451)@172.17.0.2:44357 (0b1= 049f05548) > I0627 15:20:33.762620 30794 slave.cpp:3426] Updated checkpointed resource= s from {} to cpus(reservations: [(DYNAMIC,role1,test-principal)]):4 > I0627 15:20:33.763795 30775 slave.cpp:1008] Authenticating with master ma= ster@172.17.0.2:44357 > I0627 15:20:33.763928 30775 slave.cpp:1019] Using default CRAM-MD5 authen= ticatee > I0627 15:20:33.764186 30795 authenticatee.cpp:121] Creating new client SA= SL connection > I0627 15:20:33.764468 30796 master.cpp:7640] Authenticating slave(452)@17= 2.17.0.2:44357 > I0627 15:20:33.764649 30785 authenticator.cpp:414] Starting authenticatio= n session for crammd5-authenticatee(939)@172.17.0.2:44357 > I0627 15:20:33.764925 30795 authenticator.cpp:98] Creating new server SAS= L connection > I0627 15:20:33.765175 30777 authenticatee.cpp:213] Received SASL authenti= cation mechanisms: CRAM-MD5 > I0627 15:20:33.765203 30777 authenticatee.cpp:239] Attempting to authenti= cate with mechanism 'CRAM-MD5' > I0627 15:20:33.765386 30785 authenticator.cpp:204] Received SASL authenti= cation start > I0627 15:20:33.765439 30785 authenticator.cpp:326] Authentication require= s more steps > I0627 15:20:33.765538 30784 authenticatee.cpp:259] Received SASL authenti= cation step > I0627 15:20:33.765709 30789 authenticator.cpp:232] Received SASL authenti= cation step > I0627 15:20:33.765758 30789 auxprop.cpp:109] Request to lookup properties= for user: 'test-principal' realm: '0b1049f05548' server FQDN: '0b1049f0554= 8' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SAS= L_AUXPROP_AUTHZID: false=20 > I0627 15:20:33.765774 30789 auxprop.cpp:181] Looking up auxiliary propert= y '*userPassword' > I0627 15:20:33.765825 30789 auxprop.cpp:181] Looking up auxiliary propert= y '*cmusaslsecretCRAM-MD5' > I0627 15:20:33.765854 30789 auxprop.cpp:109] Request to lookup properties= for user: 'test-principal' realm: '0b1049f05548' server FQDN: '0b1049f0554= 8' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SAS= L_AUXPROP_AUTHZID: true=20 > I0627 15:20:33.765867 30789 auxprop.cpp:131] Skipping auxiliary property = '*userPassword' since SASL_AUXPROP_AUTHZID =3D=3D true > I0627 15:20:33.765877 30789 auxprop.cpp:131] Skipping auxiliary property = '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID =3D=3D true > I0627 15:20:33.765902 30789 authenticator.cpp:318] Authentication success > I0627 15:20:33.766007 30773 sched.cpp:232] Version: 1.4.0 > I0627 15:20:33.766126 30790 authenticatee.cpp:299] Authentication success > I0627 15:20:33.766155 30788 master.cpp:7670] Successfully authenticated p= rincipal 'test-principal' at slave(452)@172.17.0.2:44357 > I0627 15:20:33.766187 30789 authenticator.cpp:432] Authentication session= cleanup for crammd5-authenticatee(939)@172.17.0.2:44357 > I0627 15:20:33.766543 30776 slave.cpp:1103] Successfully authenticated wi= th master master@172.17.0.2:44357 > I0627 15:20:33.766687 30793 sched.cpp:336] New master detected at master@= 172.17.0.2:44357 > I0627 15:20:33.766753 30793 sched.cpp:407] Authenticating with master mas= ter@172.17.0.2:44357 > I0627 15:20:33.766767 30793 sched.cpp:414] Using default CRAM-MD5 authent= icatee > I0627 15:20:33.766770 30776 slave.cpp:1545] Will retry registration in 2.= 625286ms if necessary > I0627 15:20:33.766901 30789 master.cpp:5602] Received register agent mess= age from slave(452)@172.17.0.2:44357 (0b1049f05548) > I0627 15:20:33.766932 30789 master.cpp:3742] Authorizing agent with princ= ipal 'test-principal' > I0627 15:20:33.766964 30797 authenticatee.cpp:121] Creating new client SA= SL connection > I0627 15:20:33.767232 30789 master.cpp:7640] Authenticating scheduler-f69= 0f5d5-752a-499b-aca5-a83801ba224a@172.17.0.2:44357 > I0627 15:20:33.767307 30776 authenticator.cpp:414] Starting authenticatio= n session for crammd5-authenticatee(940)@172.17.0.2:44357 > I0627 15:20:33.767468 30774 master.cpp:5662] Authorized registration of a= gent at slave(452)@172.17.0.2:44357 (0b1049f05548) > I0627 15:20:33.767489 30797 authenticator.cpp:98] Creating new server SAS= L connection > I0627 15:20:33.767608 30774 master.cpp:5741] Registering agent at slave(4= 52)@172.17.0.2:44357 (0b1049f05548) with id d8d232e5-1689-4780-b232-c91e5c3= 277b1-S1 > I0627 15:20:33.767666 30778 authenticatee.cpp:213] Received SASL authenti= cation mechanisms: CRAM-MD5 > I0627 15:20:33.767691 30778 authenticatee.cpp:239] Attempting to authenti= cate with mechanism 'CRAM-MD5' > I0627 15:20:33.767819 30797 authenticator.cpp:204] Received SASL authenti= cation start > I0627 15:20:33.767864 30797 authenticator.cpp:326] Authentication require= s more steps > I0627 15:20:33.767958 30786 authenticatee.cpp:259] Received SASL authenti= cation step > I0627 15:20:33.767989 30781 registrar.cpp:493] Applied 1 operations in 89= 291ns; attempting to update the registry > I0627 15:20:33.768164 30788 authenticator.cpp:232] Received SASL authenti= cation step > I0627 15:20:33.768187 30788 auxprop.cpp:109] Request to lookup properties= for user: 'test-principal' realm: '0b1049f05548' server FQDN: '0b1049f0554= 8' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SAS= L_AUXPROP_AUTHZID: false=20 > I0627 15:20:33.768198 30788 auxprop.cpp:181] Looking up auxiliary propert= y '*userPassword' > I0627 15:20:33.768239 30788 auxprop.cpp:181] Looking up auxiliary propert= y '*cmusaslsecretCRAM-MD5' > I0627 15:20:33.768260 30788 auxprop.cpp:109] Request to lookup properties= for user: 'test-principal' realm: '0b1049f05548' server FQDN: '0b1049f0554= 8' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SAS= L_AUXPROP_AUTHZID: true=20 > I0627 15:20:33.768267 30788 auxprop.cpp:131] Skipping auxiliary property = '*userPassword' since SASL_AUXPROP_AUTHZID =3D=3D true > I0627 15:20:33.768272 30788 auxprop.cpp:131] Skipping auxiliary property = '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID =3D=3D true > I0627 15:20:33.768285 30788 authenticator.cpp:318] Authentication success > I0627 15:20:33.768394 30792 authenticatee.cpp:299] Authentication success > I0627 15:20:33.768615 30777 master.cpp:7670] Successfully authenticated p= rincipal 'test-principal' at scheduler-f690f5d5-752a-499b-aca5-a83801ba224a= @172.17.0.2:44357 > I0627 15:20:33.768641 30790 sched.cpp:513] Successfully authenticated wit= h master master@172.17.0.2:44357 > I0627 15:20:33.768661 30790 sched.cpp:836] Sending SUBSCRIBE call to mast= er@172.17.0.2:44357 > I0627 15:20:33.768661 30776 authenticator.cpp:432] Authentication session= cleanup for crammd5-authenticatee(940)@172.17.0.2:44357 > I0627 15:20:33.768782 30781 registrar.cpp:550] Successfully updated the r= egistry in 722176ns > I0627 15:20:33.768887 30790 sched.cpp:869] Will retry registration in 424= .478509ms if necessary > I0627 15:20:33.769176 30785 master.cpp:2853] Received SUBSCRIBE call for = framework 'default' at scheduler-f690f5d5-752a-499b-aca5-a83801ba224a@172.1= 7.0.2:44357 > I0627 15:20:33.769222 30785 master.cpp:2197] Authorizing framework princi= pal 'test-principal' to receive offers for roles '{ role1 }' > I0627 15:20:33.770375 30796 slave.cpp:1545] Will retry registration in 37= .054423ms if necessary > I0627 15:20:33.770567 30785 master.cpp:5788] Admitted agent d8d232e5-1689= -4780-b232-c91e5c3277b1-S1 at slave(452)@172.17.0.2:44357 (0b1049f05548) > I0627 15:20:33.771241 30784 slave.cpp:4866] Received ping from slave-obse= rver(450)@172.17.0.2:44357 > I0627 15:20:33.771467 30787 slave.cpp:1149] Registered with master master= @172.17.0.2:44357; given agent ID d8d232e5-1689-4780-b232-c91e5c3277b1-S1 > I0627 15:20:33.771585 30789 status_update_manager.cpp:184] Resuming sendi= ng status updates > I0627 15:20:33.771392 30785 master.cpp:5819] Registered agent d8d232e5-16= 89-4780-b232-c91e5c3277b1-S1 at slave(452)@172.17.0.2:44357 (0b1049f05548) = with [{"name":"cpus","scalar":{"value":3.0},"type":"SCALAR"},{"name":"mem",= "scalar":{"value":95614.0},"type":"SCALAR"},{"name":"disk","scalar":{"value= ":367489.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31= 000,"end":32000}]},"type":"RANGES"}] > I0627 15:20:33.771682 30777 hierarchical.cpp:587] Added agent d8d232e5-16= 89-4780-b232-c91e5c3277b1-S1 (0b1049f05548) with cpus:3; mem:95614; disk:36= 7489; ports:[31000-32000] (allocated: {}) > I0627 15:20:33.771832 30787 slave.cpp:1169] Checkpointing SlaveInfo to '/= tmp/PersistentVolumeEndpointsTest_ReserveAndSlaveRemoval_QWO1D8/meta/slaves= /d8d232e5-1689-4780-b232-c91e5c3277b1-S1/slave.info' > I0627 15:20:33.771932 30777 hierarchical.cpp:1938] No allocations perform= ed > I0627 15:20:33.771953 30785 master.cpp:5602] Received register agent mess= age from slave(452)@172.17.0.2:44357 (0b1049f05548) > I0627 15:20:33.771975 30777 hierarchical.cpp:1493] Performed allocation f= or 1 agents in 164163ns > I0627 15:20:33.771996 30785 master.cpp:3742] Authorizing agent with princ= ipal 'test-principal' > I0627 15:20:33.772150 30787 slave.cpp:1207] Forwarding total oversubscrib= ed resources {} > I0627 15:20:33.772339 30785 master.cpp:2933] Subscribing framework defaul= t with checkpointing disabled and capabilities [ RESERVATION_REFINEMENT ] > I0627 15:20:33.773007 30785 master.cpp:6508] Received update of agent d8d= 232e5-1689-4780-b232-c91e5c3277b1-S1 at slave(452)@172.17.0.2:44357 (0b1049= f05548) with total oversubscribed resources {} > I0627 15:20:33.773047 30794 sched.cpp:759] Framework registered with d8d2= 32e5-1689-4780-b232-c91e5c3277b1-0000 > I0627 15:20:33.773095 30794 sched.cpp:773] Scheduler::registered took 310= 19ns > I0627 15:20:33.773164 30785 master.cpp:5662] Authorized registration of a= gent at slave(452)@172.17.0.2:44357 (0b1049f05548) > I0627 15:20:33.773227 30776 hierarchical.cpp:301] Added framework d8d232e= 5-1689-4780-b232-c91e5c3277b1-0000 > I0627 15:20:33.773247 30785 master.cpp:5719] Agent d8d232e5-1689-4780-b23= 2-c91e5c3277b1-S1 at slave(452)@172.17.0.2:44357 (0b1049f05548) already reg= istered, resending acknowledgement > W0627 15:20:33.773438 30783 slave.cpp:1193] Already registered with maste= r master@172.17.0.2:44357 > I0627 15:20:33.773470 30783 slave.cpp:1207] Forwarding total oversubscrib= ed resources {} > I0627 15:20:33.773676 30781 master.cpp:6508] Received update of agent d8d= 232e5-1689-4780-b232-c91e5c3277b1-S1 at slave(452)@172.17.0.2:44357 (0b1049= f05548) with total oversubscribed resources {} > I0627 15:20:33.774871 30776 hierarchical.cpp:2028] No inverse offers to s= end out! > I0627 15:20:33.774912 30776 hierarchical.cpp:1493] Performed allocation f= or 2 agents in 1.518176ms > I0627 15:20:33.776294 30783 master.cpp:7470] Sending 2 offers to framewor= k d8d232e5-1689-4780-b232-c91e5c3277b1-0000 (default) at scheduler-f690f5d5= -752a-499b-aca5-a83801ba224a@172.17.0.2:44357 > I0627 15:20:33.776959 30776 sched.cpp:933] Scheduler::resourceOffers took= 133421ns > /mesos/src/tests/persistent_volume_endpoints_tests.cpp:1859: Failure > Value of: offeredSlaveId =3D=3D slaveId1 || offeredSlaveId =3D=3D slaveId= 2 > Actual: false > Expected: true > I0627 15:20:33.778265 30791 master.cpp:1430] Framework d8d232e5-1689-4780= -b232-c91e5c3277b1-0000 (default) at scheduler-f690f5d5-752a-499b-aca5-a838= 01ba224a@172.17.0.2:44357 disconnected > I0627 15:20:33.778303 30791 master.cpp:3203] Deactivating framework d8d23= 2e5-1689-4780-b232-c91e5c3277b1-0000 (default) at scheduler-f690f5d5-752a-4= 99b-aca5-a83801ba224a@172.17.0.2:44357 > I0627 15:20:33.779554 30787 hierarchical.cpp:410] Deactivated framework d= 8d232e5-1689-4780-b232-c91e5c3277b1-0000 > I0627 15:20:33.779958 30791 master.cpp:3180] Disconnecting framework d8d2= 32e5-1689-4780-b232-c91e5c3277b1-0000 (default) at scheduler-f690f5d5-752a-= 499b-aca5-a83801ba224a@172.17.0.2:44357 > I0627 15:20:33.780009 30791 master.cpp:1445] Giving framework d8d232e5-16= 89-4780-b232-c91e5c3277b1-0000 (default) at scheduler-f690f5d5-752a-499b-ac= a5-a83801ba224a@172.17.0.2:44357 0ns to failover > I0627 15:20:33.780483 30787 hierarchical.cpp:1177] Recovered ports(alloca= ted: role1):[31000-32000]; mem(allocated: role1):95614; disk(allocated: rol= e1):367489; cpus(allocated: role1)(reservations: [(DYNAMIC,role1,test-princ= ipal)]):4 (total: ports:[31000-32000]; mem:95614; disk:367489; cpus(reserva= tions: [(DYNAMIC,role1,test-principal)]):4, allocated: {}) on agent d8d232e= 5-1689-4780-b232-c91e5c3277b1-S0 from framework d8d232e5-1689-4780-b232-c91= e5c3277b1-0000 > I0627 15:20:33.781185 30787 hierarchical.cpp:1177] Recovered cpus(allocat= ed: role1):3; mem(allocated: role1):95614; disk(allocated: role1):367489; p= orts(allocated: role1):[31000-32000] (total: cpus:3; mem:95614; disk:367489= ; ports:[31000-32000], allocated: {}) on agent d8d232e5-1689-4780-b232-c91e= 5c3277b1-S1 from framework d8d232e5-1689-4780-b232-c91e5c3277b1-0000 > I0627 15:20:33.781599 30789 master.cpp:7306] Framework failover timeout, = removing framework d8d232e5-1689-4780-b232-c91e5c3277b1-0000 (default) at s= cheduler-f690f5d5-752a-499b-aca5-a83801ba224a@172.17.0.2:44357 > I0627 15:20:33.781625 30789 master.cpp:8163] Removing framework d8d232e5-= 1689-4780-b232-c91e5c3277b1-0000 (default) at scheduler-f690f5d5-752a-499b-= aca5-a83801ba224a@172.17.0.2:44357 > I0627 15:20:33.781790 30787 slave.cpp:3136] Asked to shut down framework = d8d232e5-1689-4780-b232-c91e5c3277b1-0000 by master@172.17.0.2:44357 > I0627 15:20:33.781803 30791 slave.cpp:3136] Asked to shut down framework = d8d232e5-1689-4780-b232-c91e5c3277b1-0000 by master@172.17.0.2:44357 > I0627 15:20:33.781817 30787 slave.cpp:3151] Cannot shut down unknown fram= ework d8d232e5-1689-4780-b232-c91e5c3277b1-0000 > I0627 15:20:33.781831 30791 slave.cpp:3151] Cannot shut down unknown fram= ework d8d232e5-1689-4780-b232-c91e5c3277b1-0000 > I0627 15:20:33.782289 30780 hierarchical.cpp:353] Removed framework d8d23= 2e5-1689-4780-b232-c91e5c3277b1-0000 > I0627 15:20:33.788432 30787 slave.cpp:818] Agent terminating > I0627 15:20:33.788750 30796 master.cpp:1316] Agent d8d232e5-1689-4780-b23= 2-c91e5c3277b1-S1 at slave(452)@172.17.0.2:44357 (0b1049f05548) disconnecte= d > I0627 15:20:33.788781 30796 master.cpp:3240] Disconnecting agent d8d232e5= -1689-4780-b232-c91e5c3277b1-S1 at slave(452)@172.17.0.2:44357 (0b1049f0554= 8) > I0627 15:20:33.788859 30796 master.cpp:3259] Deactivating agent d8d232e5-= 1689-4780-b232-c91e5c3277b1-S1 at slave(452)@172.17.0.2:44357 (0b1049f05548= ) > I0627 15:20:33.788995 30777 hierarchical.cpp:715] Agent d8d232e5-1689-478= 0-b232-c91e5c3277b1-S1 deactivated > I0627 15:20:33.796249 30779 hierarchical.cpp:1938] No allocations perform= ed > I0627 15:20:33.796330 30779 hierarchical.cpp:1493] Performed allocation f= or 2 agents in 319501ns > I0627 15:20:33.798933 30796 slave.cpp:818] Agent terminating > I0627 15:20:33.799327 30795 master.cpp:1316] Agent d8d232e5-1689-4780-b23= 2-c91e5c3277b1-S0 at slave(451)@172.17.0.2:44357 (0b1049f05548) disconnecte= d > I0627 15:20:33.799360 30795 master.cpp:3240] Disconnecting agent d8d232e5= -1689-4780-b232-c91e5c3277b1-S0 at slave(451)@172.17.0.2:44357 (0b1049f0554= 8) > I0627 15:20:33.799438 30795 master.cpp:3259] Deactivating agent d8d232e5-= 1689-4780-b232-c91e5c3277b1-S0 at slave(451)@172.17.0.2:44357 (0b1049f05548= ) > I0627 15:20:33.799567 30787 hierarchical.cpp:715] Agent d8d232e5-1689-478= 0-b232-c91e5c3277b1-S0 deactivated > I0627 15:20:33.804204 30779 master.cpp:1158] Master terminating > I0627 15:20:33.810475 30780 hierarchical.cpp:620] Removed agent d8d232e5-= 1689-4780-b232-c91e5c3277b1-S1 > I0627 15:20:33.811208 30780 hierarchical.cpp:620] Removed agent d8d232e5-= 1689-4780-b232-c91e5c3277b1-S0 > /mesos/3rdparty/libprocess/include/process/gmock.hpp:441: Failure > Actual function call count doesn't match EXPECT_CALL(filter->mock, filter= (testing::A()))... > Expected args: message matcher (8-byte object , 1, 1) > Expected: to be called once > Actual: never called - unsatisfied and active > [ FAILED ] PersistentVolumeEndpointsTest.ReserveAndSlaveRemoval (138 ms= ) > {code} > [~neilconway] Can you take a look at this? This has been terribly flaky o= n ASF CI. -- This message was sent by Atlassian JIRA (v6.4.14#64029)