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 B00DE200BE7 for ; Tue, 20 Dec 2016 18:51:01 +0100 (CET) Received: by cust-asf.ponee.io (Postfix) id AEBB5160B12; Tue, 20 Dec 2016 17:51:01 +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 13144160B3C for ; Tue, 20 Dec 2016 18:50:59 +0100 (CET) Received: (qmail 40361 invoked by uid 500); 20 Dec 2016 17:50:59 -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 40215 invoked by uid 99); 20 Dec 2016 17:50:58 -0000 Received: from arcas.apache.org (HELO arcas) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 20 Dec 2016 17:50:58 +0000 Received: from arcas.apache.org (localhost [127.0.0.1]) by arcas (Postfix) with ESMTP id BBA382C2AB8 for ; Tue, 20 Dec 2016 17:50:58 +0000 (UTC) Date: Tue, 20 Dec 2016 17:50:58 +0000 (UTC) From: "Anand Mazumdar (JIRA)" To: issues@mesos.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Commented] (MESOS-6823) bool/UserContainerLoggerTest.ROOT_LOGROTATE_RotateWithSwitchUserTrueOrFalse/0 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, 20 Dec 2016 17:51:01 -0000 [ https://issues.apache.org/jira/browse/MESOS-6823?page=3Dcom.atlassian= .jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=3D1576= 4797#comment-15764797 ]=20 Anand Mazumdar commented on MESOS-6823: --------------------------------------- cc: [~kaysoky] [~sivaramsk] > bool/UserContainerLoggerTest.ROOT_LOGROTATE_RotateWithSwitchUserTrueOrFal= se/0 is flaky > -------------------------------------------------------------------------= ------------- > > Key: MESOS-6823 > URL: https://issues.apache.org/jira/browse/MESOS-6823 > Project: Mesos > Issue Type: Bug > Environment: Ubuntu 12/14 both with/without SSL > Reporter: Anand Mazumdar > Labels: flaky, flaky-test > > This showed up on our internal CI > {code} > [23:13:01] :=09 [Step 11/11] [ RUN ] bool/UserContainerLoggerTest.RO= OT_LOGROTATE_RotateWithSwitchUserTrueOrFalse/0 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.653230 25712 cluster.cpp:160]= Creating default 'local' authorizer > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.654103 25732 master.cpp:380] = Master c590a129-814c-4903-9681-e16da4da4c94 (ip-172-16-10-213.mesosphere.io= ) started on 172.16.10.213:45407 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.654119 25732 master.cpp:382] = Flags at startup: --acls=3D"" --agent_ping_timeout=3D"15secs" --agent_rereg= ister_timeout=3D"10mins" --allocation_interval=3D"1secs" --allocator=3D"Hie= rarchicalDRF" --authenticate_agents=3D"true" --authenticate_frameworks=3D"t= rue" --authenticate_http_frameworks=3D"true" --authenticate_http_readonly= =3D"true" --authenticate_http_readwrite=3D"true" --authenticators=3D"crammd= 5" --authorizers=3D"local" --credentials=3D"/mnt/teamcity/temp/buildTmp/ev3= icd/credentials" --framework_sorter=3D"drf" --help=3D"false" --hostname_loo= kup=3D"true" --http_authenticators=3D"basic" --http_framework_authenticator= s=3D"basic" --initialize_driver_logging=3D"true" --log_auto_initialize=3D"t= rue" --logbufsecs=3D"0" --logging_level=3D"INFO" --max_agent_ping_timeouts= =3D"5" --max_completed_frameworks=3D"50" --max_completed_tasks_per_framewor= k=3D"1000" --quiet=3D"false" --recovery_agent_removal_limit=3D"100%" --regi= stry=3D"in_memory" --registry_fetch_timeout=3D"1mins" --registry_gc_interva= l=3D"15mins" --registry_max_agent_age=3D"2weeks" --registry_max_agent_count= =3D"102400" --registry_store_timeout=3D"100secs" --registry_strict=3D"false= " --root_submissions=3D"true" --user_sorter=3D"drf" --version=3D"false" --w= ebui_dir=3D"/usr/local/share/mesos/webui" --work_dir=3D"/mnt/teamcity/temp/= buildTmp/ev3icd/master" --zk_session_timeout=3D"10secs" > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.654248 25732 master.cpp:432] = Master only allowing authenticated frameworks to register > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.654254 25732 master.cpp:446] = Master only allowing authenticated agents to register > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.654258 25732 master.cpp:459] = Master only allowing authenticated HTTP frameworks to register > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.654261 25732 credentials.hpp:= 37] Loading credentials for authentication from '/mnt/teamcity/temp/buildTm= p/ev3icd/credentials' > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.654343 25732 master.cpp:504] = Using default 'crammd5' authenticator > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.654386 25732 http.cpp:922] Us= ing default 'basic' HTTP authenticator for realm 'mesos-master-readonly' > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.654429 25732 http.cpp:922] Us= ing default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.654458 25732 http.cpp:922] Us= ing default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.654477 25732 master.cpp:584] = Authorization enabled > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.654551 25733 whitelist_watche= r.cpp:77] No whitelist given > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.654582 25730 hierarchical.cpp= :149] Initialized hierarchical allocator process > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.655076 25732 master.cpp:2046]= Elected as the leading master! > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.655086 25732 master.cpp:1568]= Recovering from registrar > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.655124 25729 registrar.cpp:32= 9] Recovering registrar > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.655354 25731 registrar.cpp:36= 2] Successfully fetched the registry (0B) in 210944ns > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.655385 25731 registrar.cpp:46= 1] Applied 1 operations in 5006ns; attempting to update the registry > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.655593 25732 registrar.cpp:50= 6] Successfully updated the registry in 194048ns > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.655658 25732 registrar.cpp:39= 2] Successfully recovered registrar > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.655799 25732 master.cpp:1684]= Recovered 0 agents from the registry (174B); allowing 10mins for agents to= re-register > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.655840 25728 hierarchical.cpp= :176] Skipping recovery of hierarchical allocator: nothing to recover > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.656813 25712 containerizer.cp= p:220] Using isolation: posix/cpu,posix/mem,filesystem/posix,network/cni > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.659867 25712 linux_launcher.c= pp:150] Using /sys/fs/cgroup/freezer as the freezer hierarchy for the Linux= launcher > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.667733 25712 cluster.cpp:446]= Creating default 'local' authorizer > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.668246 25730 slave.cpp:209] M= esos agent started on (684)@172.16.10.213:45407 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.668257 25730 slave.cpp:210] F= lags at startup: --acls=3D"" --appc_simple_discovery_uri_prefix=3D"http://"= --appc_store_dir=3D"/mnt/teamcity/temp/buildTmp/mesos/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" --container_logger=3D"org_apache_mesos_LogrotateContainerLogger" --c= ontainerizers=3D"mesos" --credential=3D"/mnt/teamcity/temp/buildTmp/bool_Us= erContainerLoggerTest_ROOT_LOGROTATE_RotateWithSwitchUserTrueOrFalse_0_DcAJ= jZ/credential" --default_role=3D"*" --disk_watch_interval=3D"1mins" --docke= r=3D"docker" --docker_kill_orphans=3D"true" --docker_registry=3D"https://re= gistry-1.docker.io" --docker_remove_delay=3D"6hrs" --docker_socket=3D"/var/= run/docker.sock" --docker_stop_timeout=3D"0ns" --docker_store_dir=3D"/mnt/t= eamcity/temp/buildTmp/mesos/store/docker" --docker_volume_checkpoint_dir=3D= "/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota=3D"= false" --executor_registration_timeout=3D"1mins" --executor_shutdown_grace_= period=3D"5secs" --fetcher_cache_dir=3D"/mnt/teamcity/temp/buildTmp/bool_Us= erContainerLoggerTest_ROOT_LOGROTATE_RotateWithSwitchUserTrueOrFalse_0_DcAJ= jZ/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" --h= ostname_lookup=3D"true" --http_authenticators=3D"basic" --http_command_exec= utor=3D"false" --http_credentials=3D"/mnt/teamcity/temp/buildTmp/bool_UserC= ontainerLoggerTest_ROOT_LOGROTATE_RotateWithSwitchUserTrueOrFalse_0_DcAJjZ/= http_credentials" --http_heartbeat_interval=3D"30secs" --image_provisioner_= backend=3D"copy" --initialize_driver_logging=3D"true" --isolation=3D"posix/= cpu,posix/mem" --launcher=3D"linux" --launcher_dir=3D"/mnt/teamcity/work/42= 40ba9ddd0997c3/build/src" --logbufsecs=3D"0" --logging_level=3D"INFO" --max= _completed_executors_per_framework=3D"150" --oversubscribed_resources_inter= val=3D"15secs" --perf_duration=3D"10secs" --perf_interval=3D"1mins" --qos_c= orrection_interval_min=3D"0ns" --quiet=3D"false" --recover=3D"reconnect" --= recovery_timeout=3D"15mins" --registration_backoff_factor=3D"10ms" --resour= ces=3D"cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cp= u_low_priority=3D"true" --runtime_dir=3D"/mnt/teamcity/temp/buildTmp/bool_U= serContainerLoggerTest_ROOT_LOGROTATE_RotateWithSwitchUserTrueOrFalse_0_DcA= JjZ" --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"/mnt/teamcity/te= mp/buildTmp/bool_UserContainerLoggerTest_ROOT_LOGROTATE_RotateWithSwitchUse= rTrueOrFalse_0_Ea40f6" > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.668517 25730 credentials.hpp:= 86] Loading credential for authentication from '/mnt/teamcity/temp/buildTmp= /bool_UserContainerLoggerTest_ROOT_LOGROTATE_RotateWithSwitchUserTrueOrFals= e_0_DcAJjZ/credential' > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.668604 25730 slave.cpp:352] A= gent using credential for: test-principal > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.668614 25730 credentials.hpp:= 37] Loading credentials for authentication from '/mnt/teamcity/temp/buildTm= p/bool_UserContainerLoggerTest_ROOT_LOGROTATE_RotateWithSwitchUserTrueOrFal= se_0_DcAJjZ/http_credentials' > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.668684 25730 http.cpp:922] Us= ing default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.668732 25730 http.cpp:922] Us= ing default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite' > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.669096 25730 slave.cpp:539] A= gent resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000= ] > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.669124 25730 slave.cpp:547] A= gent attributes: [ ] > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.669129 25730 slave.cpp:552] A= gent hostname: ip-172-16-10-213.mesosphere.io > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.669481 25730 state.cpp:57] Re= covering state from '/mnt/teamcity/temp/buildTmp/bool_UserContainerLoggerTe= st_ROOT_LOGROTATE_RotateWithSwitchUserTrueOrFalse_0_Ea40f6/meta' > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.669692 25731 status_update_ma= nager.cpp:203] Recovering status update manager > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.669780 25727 containerizer.cp= p:599] Recovering containerizer > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.670794 25733 provisioner.cpp:= 253] Provisioner recovery complete > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.670958 25726 slave.cpp:5407] = Finished recovery > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.671187 25726 slave.cpp:5581] = Querying resource estimator for oversubscribable resources > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.671315 25731 status_update_ma= nager.cpp:177] Pausing sending status updates > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.671314 25726 slave.cpp:924] N= ew master detected at master@172.16.10.213:45407 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.671349 25726 slave.cpp:983] A= uthenticating with master master@172.16.10.213:45407 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.671363 25726 slave.cpp:994] U= sing default CRAM-MD5 authenticatee > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.671401 25726 slave.cpp:956] D= etecting new master > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.671442 25730 authenticatee.cp= p:121] Creating new client SASL connection > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.671458 25726 slave.cpp:5595] = Received oversubscribable resources {} from the resource estimator > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.671689 25730 master.cpp:6751]= Authenticating slave(684)@172.16.10.213:45407 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.671737 25726 authenticator.cp= p:414] Starting authentication session for crammd5-authenticatee(1319)@172.= 16.10.213:45407 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.671819 25732 authenticator.cp= p:98] Creating new server SASL connection > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.672016 25732 authenticatee.cp= p:213] Received SASL authentication mechanisms: CRAM-MD5 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.672034 25732 authenticatee.cp= p:239] Attempting to authenticate with mechanism 'CRAM-MD5' > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.672106 25727 authenticator.cp= p:204] Received SASL authentication start > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.672142 25727 authenticator.cp= p:326] Authentication requires more steps > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.672174 25727 authenticatee.cp= p:259] Received SASL authentication step > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.672231 25727 authenticator.cp= p:232] Received SASL authentication step > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.672247 25727 auxprop.cpp:109]= Request to lookup properties for user: 'test-principal' realm: 'ip-172-16-= 10-213.mesosphere.io' server FQDN: 'ip-172-16-10-213.mesosphere.io' SASL_AU= XPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_= AUTHZID: false=20 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.672258 25727 auxprop.cpp:181]= Looking up auxiliary property '*userPassword' > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.672273 25727 auxprop.cpp:181]= Looking up auxiliary property '*cmusaslsecretCRAM-MD5' > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.672286 25727 auxprop.cpp:109]= Request to lookup properties for user: 'test-principal' realm: 'ip-172-16-= 10-213.mesosphere.io' server FQDN: 'ip-172-16-10-213.mesosphere.io' SASL_AU= XPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_= AUTHZID: true=20 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.672291 25727 auxprop.cpp:131]= Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID =3D= =3D true > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.672294 25727 auxprop.cpp:131]= Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AU= THZID =3D=3D true > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.672303 25727 authenticator.cp= p:318] Authentication success > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.672353 25732 authenticatee.cp= p:299] Authentication success > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.672389 25727 authenticator.cp= p:432] Authentication session cleanup for crammd5-authenticatee(1319)@172.1= 6.10.213:45407 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.672400 25729 master.cpp:6781]= Successfully authenticated principal 'test-principal' at slave(684)@172.16= .10.213:45407 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.672461 25732 slave.cpp:1078] = Successfully authenticated with master master@172.16.10.213:45407 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.672525 25732 slave.cpp:1493] = Will retry registration in 548917ns if necessary > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.672613 25729 master.cpp:5162]= Registering agent at slave(684)@172.16.10.213:45407 (ip-172-16-10-213.meso= sphere.io) with id c590a129-814c-4903-9681-e16da4da4c94-S0 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.672755 25731 registrar.cpp:46= 1] Applied 1 operations in 20881ns; attempting to update the registry > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.673188 25731 registrar.cpp:50= 6] Successfully updated the registry in 402944ns > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.673383 25733 slave.cpp:4263] = Received ping from slave-observer(620)@172.16.10.213:45407 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.673396 25730 master.cpp:5233]= Registered agent c590a129-814c-4903-9681-e16da4da4c94-S0 at slave(684)@172= .16.10.213:45407 (ip-172-16-10-213.mesosphere.io) with cpus(*):2; mem(*):10= 24; disk(*):1024; ports(*):[31000-32000] > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.673471 25732 hierarchical.cpp= :491] Added agent c590a129-814c-4903-9681-e16da4da4c94-S0 (ip-172-16-10-213= .mesosphere.io) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-= 32000] (allocated: {}) > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.673506 25733 slave.cpp:1124] = Registered with master master@172.16.10.213:45407; given agent ID c590a129-= 814c-4903-9681-e16da4da4c94-S0 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.673519 25733 fetcher.cpp:90] = Clearing fetcher cache > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.673519 25732 hierarchical.cpp= :1690] No allocations performed > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.673543 25732 hierarchical.cpp= :1315] Performed allocation for agent c590a129-814c-4903-9681-e16da4da4c94-= S0 in 52849ns > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.673630 25730 status_update_ma= nager.cpp:184] Resuming sending status updates > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.673707 25733 slave.cpp:1147] = Checkpointing SlaveInfo to '/mnt/teamcity/temp/buildTmp/bool_UserContainerL= oggerTest_ROOT_LOGROTATE_RotateWithSwitchUserTrueOrFalse_0_Ea40f6/meta/slav= es/c590a129-814c-4903-9681-e16da4da4c94-S0/slave.info' > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.673825 25733 slave.cpp:1184] = Forwarding total oversubscribed resources {} > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.673895 25729 master.cpp:5636]= Received update of agent c590a129-814c-4903-9681-e16da4da4c94-S0 at slave(= 684)@172.16.10.213:45407 (ip-172-16-10-213.mesosphere.io) with total oversu= bscribed resources {} > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.673984 25732 hierarchical.cpp= :561] Agent c590a129-814c-4903-9681-e16da4da4c94-S0 (ip-172-16-10-213.mesos= phere.io) updated with oversubscribed resources {} (total: cpus(*):2; mem(*= ):1024; disk(*):1024; ports(*):[31000-32000], allocated: {}) > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.674024 25732 hierarchical.cpp= :1690] No allocations performed > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.674041 25732 hierarchical.cpp= :1315] Performed allocation for agent c590a129-814c-4903-9681-e16da4da4c94-= S0 in 39010ns > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.674474 25712 sched.cpp:232] V= ersion: 1.2.0 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.674671 25731 sched.cpp:336] N= ew master detected at master@172.16.10.213:45407 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.674700 25731 sched.cpp:402] A= uthenticating with master master@172.16.10.213:45407 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.674706 25731 sched.cpp:409] U= sing default CRAM-MD5 authenticatee > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.674800 25732 authenticatee.cp= p:121] Creating new client SASL connection > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.674967 25732 master.cpp:6751]= Authenticating scheduler-f456ebc6-14e6-4a87-b6df-a9b53a01d554@172.16.10.21= 3:45407 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.675021 25730 authenticator.cp= p:414] Starting authentication session for crammd5-authenticatee(1320)@172.= 16.10.213:45407 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.675082 25730 authenticator.cp= p:98] Creating new server SASL connection > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.675256 25730 authenticatee.cp= p:213] Received SASL authentication mechanisms: CRAM-MD5 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.675268 25730 authenticatee.cp= p:239] Attempting to authenticate with mechanism 'CRAM-MD5' > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.675348 25733 authenticator.cp= p:204] Received SASL authentication start > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.675374 25733 authenticator.cp= p:326] Authentication requires more steps > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.675406 25733 authenticatee.cp= p:259] Received SASL authentication step > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.675482 25728 authenticator.cp= p:232] Received SASL authentication step > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.675500 25728 auxprop.cpp:109]= Request to lookup properties for user: 'test-principal' realm: 'ip-172-16-= 10-213.mesosphere.io' server FQDN: 'ip-172-16-10-213.mesosphere.io' SASL_AU= XPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_= AUTHZID: false=20 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.675508 25728 auxprop.cpp:181]= Looking up auxiliary property '*userPassword' > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.675516 25728 auxprop.cpp:181]= Looking up auxiliary property '*cmusaslsecretCRAM-MD5' > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.675525 25728 auxprop.cpp:109]= Request to lookup properties for user: 'test-principal' realm: 'ip-172-16-= 10-213.mesosphere.io' server FQDN: 'ip-172-16-10-213.mesosphere.io' SASL_AU= XPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_= AUTHZID: true=20 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.675534 25728 auxprop.cpp:131]= Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID =3D= =3D true > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.675542 25728 auxprop.cpp:131]= Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AU= THZID =3D=3D true > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.675554 25728 authenticator.cp= p:318] Authentication success > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.675613 25731 authenticatee.cp= p:299] Authentication success > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.675637 25728 master.cpp:6781]= Successfully authenticated principal 'test-principal' at scheduler-f456ebc= 6-14e6-4a87-b6df-a9b53a01d554@172.16.10.213:45407 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.675668 25732 authenticator.cp= p:432] Authentication session cleanup for crammd5-authenticatee(1320)@172.1= 6.10.213:45407 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.675787 25731 sched.cpp:508] S= uccessfully authenticated with master master@172.16.10.213:45407 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.675803 25731 sched.cpp:826] S= ending SUBSCRIBE call to master@172.16.10.213:45407 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.675851 25731 sched.cpp:859] W= ill retry registration in 1.955259957secs if necessary > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.675909 25729 master.cpp:2634]= Received SUBSCRIBE call for framework 'default' at scheduler-f456ebc6-14e6= -4a87-b6df-a9b53a01d554@172.16.10.213:45407 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.675926 25729 master.cpp:2082]= Authorizing framework principal 'test-principal' to receive offers for rol= e '*' > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.676045 25729 master.cpp:2710]= Subscribing framework default with checkpointing disabled and capabilities= [ ] > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.676188 25727 sched.cpp:749] F= ramework registered with c590a129-814c-4903-9681-e16da4da4c94-0000 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.676218 25726 hierarchical.cpp= :277] Added framework c590a129-814c-4903-9681-e16da4da4c94-0000 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.676242 25727 sched.cpp:763] S= cheduler::registered took 36846ns > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.676443 25726 hierarchical.cpp= :1785] No inverse offers to send out! > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.676468 25726 hierarchical.cpp= :1292] Performed allocation for 1 agents in 236491ns > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.676529 25732 master.cpp:6580]= Sending 1 offers to framework c590a129-814c-4903-9681-e16da4da4c94-0000 (d= efault) at scheduler-f456ebc6-14e6-4a87-b6df-a9b53a01d554@172.16.10.213:454= 07 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.676668 25732 sched.cpp:923] S= cheduler::resourceOffers took 38617ns > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.677119 25730 master.cpp:3589]= Processing ACCEPT call for offers: [ c590a129-814c-4903-9681-e16da4da4c94-= O0 ] on agent c590a129-814c-4903-9681-e16da4da4c94-S0 at slave(684)@172.16.= 10.213:45407 (ip-172-16-10-213.mesosphere.io) for framework c590a129-814c-4= 903-9681-e16da4da4c94-0000 (default) at scheduler-f456ebc6-14e6-4a87-b6df-a= 9b53a01d554@172.16.10.213:45407 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.677145 25730 master.cpp:3176]= Authorizing framework principal 'test-principal' to launch task 255e31f0-a= 34f-4560-beb8-ff120c315d24 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.677578 25731 master.cpp:8499]= Adding task 255e31f0-a34f-4560-beb8-ff120c315d24 with resources cpus(*):2;= mem(*):1024; disk(*):1024; ports(*):[31000-32000] on agent c590a129-814c-4= 903-9681-e16da4da4c94-S0 (ip-172-16-10-213.mesosphere.io) > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.677628 25731 master.cpp:4241]= Launching task 255e31f0-a34f-4560-beb8-ff120c315d24 of framework c590a129-= 814c-4903-9681-e16da4da4c94-0000 (default) at scheduler-f456ebc6-14e6-4a87-= b6df-a9b53a01d554@172.16.10.213:45407 with resources cpus(*):2; mem(*):1024= ; disk(*):1024; ports(*):[31000-32000] on agent c590a129-814c-4903-9681-e16= da4da4c94-S0 at slave(684)@172.16.10.213:45407 (ip-172-16-10-213.mesosphere= .io) > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.677855 25728 slave.cpp:1557] = Got assigned task '255e31f0-a34f-4560-beb8-ff120c315d24' for framework c590= a129-814c-4903-9681-e16da4da4c94-0000 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.678030 25728 slave.cpp:1717] = Launching task '255e31f0-a34f-4560-beb8-ff120c315d24' for framework c590a12= 9-814c-4903-9681-e16da4da4c94-0000 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.678251 25728 paths.cpp:530] T= rying to chown '/mnt/teamcity/temp/buildTmp/bool_UserContainerLoggerTest_RO= OT_LOGROTATE_RotateWithSwitchUserTrueOrFalse_0_Ea40f6/slaves/c590a129-814c-= 4903-9681-e16da4da4c94-S0/frameworks/c590a129-814c-4903-9681-e16da4da4c94-0= 000/executors/255e31f0-a34f-4560-beb8-ff120c315d24/runs/56d7390e-0131-4648-= 8f91-862f52f11912' to user 'nobody' > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.684034 25728 slave.cpp:6334] = Launching executor '255e31f0-a34f-4560-beb8-ff120c315d24' of framework c590= a129-814c-4903-9681-e16da4da4c94-0000 with resources cpus(*):0.1; mem(*):32= in work directory '/mnt/teamcity/temp/buildTmp/bool_UserContainerLoggerTes= t_ROOT_LOGROTATE_RotateWithSwitchUserTrueOrFalse_0_Ea40f6/slaves/c590a129-8= 14c-4903-9681-e16da4da4c94-S0/frameworks/c590a129-814c-4903-9681-e16da4da4c= 94-0000/executors/255e31f0-a34f-4560-beb8-ff120c315d24/runs/56d7390e-0131-4= 648-8f91-862f52f11912' > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.684319 25728 slave.cpp:2039] = Queued task '255e31f0-a34f-4560-beb8-ff120c315d24' for executor '255e31f0-a= 34f-4560-beb8-ff120c315d24' of framework c590a129-814c-4903-9681-e16da4da4c= 94-0000 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.684326 25726 containerizer.cp= p:991] Starting container 56d7390e-0131-4648-8f91-862f52f11912 for executor= '255e31f0-a34f-4560-beb8-ff120c315d24' of framework c590a129-814c-4903-968= 1-e16da4da4c94-0000 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.684360 25728 slave.cpp:877] S= uccessfully attached file '/mnt/teamcity/temp/buildTmp/bool_UserContainerLo= ggerTest_ROOT_LOGROTATE_RotateWithSwitchUserTrueOrFalse_0_Ea40f6/slaves/c59= 0a129-814c-4903-9681-e16da4da4c94-S0/frameworks/c590a129-814c-4903-9681-e16= da4da4c94-0000/executors/255e31f0-a34f-4560-beb8-ff120c315d24/runs/56d7390e= -0131-4648-8f91-862f52f11912' > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.691035 25726 containerizer.cp= p:1540] Launching 'mesos-containerizer' with flags '--help=3D"false" --laun= ch_info=3D"{"command":{"arguments":["mesos-executor","--launcher_dir=3D\/mn= t\/teamcity\/work\/4240ba9ddd0997c3\/build\/src"],"shell":false,"value":"\/= mnt\/teamcity\/work\/4240ba9ddd0997c3\/build\/src\/mesos-executor"},"enviro= nment":{"variables":[{"name":"LIBPROCESS_PORT","value":"0"},{"name":"MESOS_= AGENT_ENDPOINT","value":"172.16.10.213:45407"},{"name":"MESOS_CHECKPOINT","= value":"0"},{"name":"MESOS_DIRECTORY","value":"\/mnt\/teamcity\/temp\/build= Tmp\/bool_UserContainerLoggerTest_ROOT_LOGROTATE_RotateWithSwitchUserTrueOr= False_0_Ea40f6\/slaves\/c590a129-814c-4903-9681-e16da4da4c94-S0\/frameworks= \/c590a129-814c-4903-9681-e16da4da4c94-0000\/executors\/255e31f0-a34f-4560-= beb8-ff120c315d24\/runs\/56d7390e-0131-4648-8f91-862f52f11912"},{"name":"ME= SOS_EXECUTOR_ID","value":"255e31f0-a34f-4560-beb8-ff120c315d24"},{"name":"M= ESOS_EXECUTOR_SHUTDOWN_GRACE_PERIOD","value":"5secs"},{"name":"MESOS_FRAMEW= ORK_ID","value":"c590a129-814c-4903-9681-e16da4da4c94-0000"},{"name":"MESOS= _HTTP_COMMAND_EXECUTOR","value":"0"},{"name":"MESOS_SLAVE_ID","value":"c590= a129-814c-4903-9681-e16da4da4c94-S0"},{"name":"MESOS_SLAVE_PID","value":"sl= ave(684)@172.16.10.213:45407"},{"name":"MESOS_SANDBOX","value":"\/mnt\/team= city\/temp\/buildTmp\/bool_UserContainerLoggerTest_ROOT_LOGROTATE_RotateWit= hSwitchUserTrueOrFalse_0_Ea40f6\/slaves\/c590a129-814c-4903-9681-e16da4da4c= 94-S0\/frameworks\/c590a129-814c-4903-9681-e16da4da4c94-0000\/executors\/25= 5e31f0-a34f-4560-beb8-ff120c315d24\/runs\/56d7390e-0131-4648-8f91-862f52f11= 912"}]},"err":{"fd":58,"type":"FD"},"out":{"fd":57,"type":"FD"},"user":"nob= ody","working_directory":"\/mnt\/teamcity\/temp\/buildTmp\/bool_UserContain= erLoggerTest_ROOT_LOGROTATE_RotateWithSwitchUserTrueOrFalse_0_Ea40f6\/slave= s\/c590a129-814c-4903-9681-e16da4da4c94-S0\/frameworks\/c590a129-814c-4903-= 9681-e16da4da4c94-0000\/executors\/255e31f0-a34f-4560-beb8-ff120c315d24\/ru= ns\/56d7390e-0131-4648-8f91-862f52f11912"}" --pipe_read=3D"56" --pipe_write= =3D"59" --runtime_directory=3D"/mnt/teamcity/temp/buildTmp/bool_UserContain= erLoggerTest_ROOT_LOGROTATE_RotateWithSwitchUserTrueOrFalse_0_DcAJjZ/contai= ners/56d7390e-0131-4648-8f91-862f52f11912" --unshare_namespace_mnt=3D"false= "' > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.691459 25729 linux_launcher.c= pp:429] Launching container 56d7390e-0131-4648-8f91-862f52f11912 and clonin= g with namespaces=20 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.696854 25733 fetcher.cpp:349]= Starting to fetch URIs for container: 56d7390e-0131-4648-8f91-862f52f11912= , directory: /mnt/teamcity/temp/buildTmp/bool_UserContainerLoggerTest_ROOT_= LOGROTATE_RotateWithSwitchUserTrueOrFalse_0_Ea40f6/slaves/c590a129-814c-490= 3-9681-e16da4da4c94-S0/frameworks/c590a129-814c-4903-9681-e16da4da4c94-0000= /executors/255e31f0-a34f-4560-beb8-ff120c315d24/runs/56d7390e-0131-4648-8f9= 1-862f52f11912 > [23:13:01] :=09 [Step 11/11] WARNING: Logging before InitGoogleLogging() = is written to STDERR > [23:13:01] :=09 [Step 11/11] WARNING: Logging before InitGoogleLogging() = is written to STDERR > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.730624 18385 process.cpp:2693= ] Overriding default number of worker threads 8, using the value LIBPROCESS= _NUM_WORKER_THREADS=3D8 instead > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.730624 18384 process.cpp:2693= ] Overriding default number of worker threads 8, using the value LIBPROCESS= _NUM_WORKER_THREADS=3D8 instead > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.731956 18384 process.cpp:1237= ] libprocess is initialized on 127.0.0.1:46747 with 8 worker threads > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.732246 18385 process.cpp:1237= ] libprocess is initialized on 127.0.0.1:58468 with 8 worker threads > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.746567 25732 containerizer.cp= p:2481] Container 56d7390e-0131-4648-8f91-862f52f11912 has exited > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.746597 25732 containerizer.cp= p:2118] Destroying container 56d7390e-0131-4648-8f91-862f52f11912 in RUNNIN= G state > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.746821 25731 linux_launcher.c= pp:505] Asked to destroy container 56d7390e-0131-4648-8f91-862f52f11912 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.747288 25731 linux_launcher.c= pp:548] Using freezer to destroy cgroup mesos/56d7390e-0131-4648-8f91-862f5= 2f11912 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.747941 25732 cgroups.cpp:2726= ] Freezing cgroup /sys/fs/cgroup/freezer/mesos/56d7390e-0131-4648-8f91-862f= 52f11912 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.748867 25726 cgroups.cpp:1439= ] Successfully froze cgroup /sys/fs/cgroup/freezer/mesos/56d7390e-0131-4648= -8f91-862f52f11912 after 902912ns > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.749860 25728 cgroups.cpp:2744= ] Thawing cgroup /sys/fs/cgroup/freezer/mesos/56d7390e-0131-4648-8f91-862f5= 2f11912 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.750797 25729 cgroups.cpp:1468= ] Successfully thawed cgroup /sys/fs/cgroup/freezer/mesos/56d7390e-0131-464= 8-8f91-862f52f11912 after 915968ns > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.752313 25728 provisioner.cpp:= 324] Ignoring destroy request for unknown container 56d7390e-0131-4648-8f91= -862f52f11912 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.752542 25732 slave.cpp:4672] = Executor '255e31f0-a34f-4560-beb8-ff120c315d24' of framework c590a129-814c-= 4903-9681-e16da4da4c94-0000 exited with status 1 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.752601 25732 slave.cpp:3740] = Handling status update TASK_FAILED (UUID: e64c0c36-291c-451e-91c0-d9615b4b4= 9be) for task 255e31f0-a34f-4560-beb8-ff120c315d24 of framework c590a129-81= 4c-4903-9681-e16da4da4c94-0000 from @0.0.0.0:0 > [23:13:01] :=09 [Step 11/11] W1219 23:13:01.752883 25730 containerizer.cp= p:1933] Ignoring update for unknown container 56d7390e-0131-4648-8f91-862f5= 2f11912 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.753000 25729 status_update_ma= nager.cpp:323] Received status update TASK_FAILED (UUID: e64c0c36-291c-451e= -91c0-d9615b4b49be) for task 255e31f0-a34f-4560-beb8-ff120c315d24 of framew= ork c590a129-814c-4903-9681-e16da4da4c94-0000 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.753020 25729 status_update_ma= nager.cpp:500] Creating StatusUpdate stream for task 255e31f0-a34f-4560-beb= 8-ff120c315d24 of framework c590a129-814c-4903-9681-e16da4da4c94-0000 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.753155 25729 status_update_ma= nager.cpp:377] Forwarding update TASK_FAILED (UUID: e64c0c36-291c-451e-91c0= -d9615b4b49be) for task 255e31f0-a34f-4560-beb8-ff120c315d24 of framework c= 590a129-814c-4903-9681-e16da4da4c94-0000 to the agent > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.753247 25727 slave.cpp:4181] = Forwarding the update TASK_FAILED (UUID: e64c0c36-291c-451e-91c0-d9615b4b49= be) for task 255e31f0-a34f-4560-beb8-ff120c315d24 of framework c590a129-814= c-4903-9681-e16da4da4c94-0000 to master@172.16.10.213:45407 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.753336 25727 slave.cpp:4075] = Status update manager successfully handled status update TASK_FAILED (UUID:= e64c0c36-291c-451e-91c0-d9615b4b49be) for task 255e31f0-a34f-4560-beb8-ff1= 20c315d24 of framework c590a129-814c-4903-9681-e16da4da4c94-0000 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.753413 25730 master.cpp:5772]= Status update TASK_FAILED (UUID: e64c0c36-291c-451e-91c0-d9615b4b49be) for= task 255e31f0-a34f-4560-beb8-ff120c315d24 of framework c590a129-814c-4903-= 9681-e16da4da4c94-0000 from agent c590a129-814c-4903-9681-e16da4da4c94-S0 a= t slave(684)@172.16.10.213:45407 (ip-172-16-10-213.mesosphere.io) > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.753437 25730 master.cpp:5834]= Forwarding status update TASK_FAILED (UUID: e64c0c36-291c-451e-91c0-d9615b= 4b49be) for task 255e31f0-a34f-4560-beb8-ff120c315d24 of framework c590a129= -814c-4903-9681-e16da4da4c94-0000 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.753484 25730 master.cpp:7871]= Updating the state of task 255e31f0-a34f-4560-beb8-ff120c315d24 of framewo= rk c590a129-814c-4903-9681-e16da4da4c94-0000 (latest state: TASK_FAILED, st= atus update state: TASK_FAILED) > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.753600 25729 sched.cpp:1031] = Scheduler::statusUpdate took 58620ns > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.753720 25726 master.cpp:4878]= Processing ACKNOWLEDGE call e64c0c36-291c-451e-91c0-d9615b4b49be for task = 255e31f0-a34f-4560-beb8-ff120c315d24 of framework c590a129-814c-4903-9681-e= 16da4da4c94-0000 (default) at scheduler-f456ebc6-14e6-4a87-b6df-a9b53a01d55= 4@172.16.10.213:45407 on agent c590a129-814c-4903-9681-e16da4da4c94-S0 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.753733 25731 hierarchical.cpp= :1024] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-3200= 0] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], al= located: {}) on agent c590a129-814c-4903-9681-e16da4da4c94-S0 from framewor= k c590a129-814c-4903-9681-e16da4da4c94-0000 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.753742 25726 master.cpp:7967]= Removing task 255e31f0-a34f-4560-beb8-ff120c315d24 with resources cpus(*):= 2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework c590a129-= 814c-4903-9681-e16da4da4c94-0000 on agent c590a129-814c-4903-9681-e16da4da4= c94-S0 at slave(684)@172.16.10.213:45407 (ip-172-16-10-213.mesosphere.io) > [23:13:01] :=09 [Step 11/11] ../../src/tests/container_logger_tests.cpp:6= 92: Failure > [23:13:01] :=09 [Step 11/11] Value of: statusRunning.get().state() > [23:13:01] :=09 [Step 11/11] Actual: TASK_FAILED > [23:13:01] :=09 [Step 11/11] Expected: TASK_RUNNING > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.753944 25726 status_update_ma= nager.cpp:395] Received status update acknowledgement (UUID: e64c0c36-291c-= 451e-91c0-d9615b4b49be) for task 255e31f0-a34f-4560-beb8-ff120c315d24 of fr= amework c590a129-814c-4903-9681-e16da4da4c94-0000 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.753983 25726 status_update_ma= nager.cpp:531] Cleaning up status update stream for task 255e31f0-a34f-4560= -beb8-ff120c315d24 of framework c590a129-814c-4903-9681-e16da4da4c94-0000 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.754051 25726 slave.cpp:3028] = Status update manager successfully handled status update acknowledgement (U= UID: e64c0c36-291c-451e-91c0-d9615b4b49be) for task 255e31f0-a34f-4560-beb8= -ff120c315d24 of framework c590a129-814c-4903-9681-e16da4da4c94-0000 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.754065 25726 slave.cpp:6704] = Completing task 255e31f0-a34f-4560-beb8-ff120c315d24 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.754070 25726 slave.cpp:4772] = Cleaning up executor '255e31f0-a34f-4560-beb8-ff120c315d24' of framework c5= 90a129-814c-4903-9681-e16da4da4c94-0000 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.754171 25731 gc.cpp:55] Sched= uling '/mnt/teamcity/temp/buildTmp/bool_UserContainerLoggerTest_ROOT_LOGROT= ATE_RotateWithSwitchUserTrueOrFalse_0_Ea40f6/slaves/c590a129-814c-4903-9681= -e16da4da4c94-S0/frameworks/c590a129-814c-4903-9681-e16da4da4c94-0000/execu= tors/255e31f0-a34f-4560-beb8-ff120c315d24/runs/56d7390e-0131-4648-8f91-862f= 52f11912' for gc 6.9999912717837days in the future > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.754189 25726 slave.cpp:4860] = Cleaning up framework c590a129-814c-4903-9681-e16da4da4c94-0000 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.754225 25731 gc.cpp:55] Sched= uling '/mnt/teamcity/temp/buildTmp/bool_UserContainerLoggerTest_ROOT_LOGROT= ATE_RotateWithSwitchUserTrueOrFalse_0_Ea40f6/slaves/c590a129-814c-4903-9681= -e16da4da4c94-S0/frameworks/c590a129-814c-4903-9681-e16da4da4c94-0000/execu= tors/255e31f0-a34f-4560-beb8-ff120c315d24' for gc 6.99999127115852days in t= he future > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.754243 25729 status_update_ma= nager.cpp:285] Closing status update streams for framework c590a129-814c-49= 03-9681-e16da4da4c94-0000 > [23:13:01] :=09 [Step 11/11] I1219 23:13:01.754259 25731 gc.cpp:55] Sched= uling '/mnt/teamcity/temp/buildTmp/bool_UserContainerLoggerTest_ROOT_LOGROT= ATE_RotateWithSwitchUserTrueOrFalse_0_Ea40f6/slaves/c590a129-814c-4903-9681= -e16da4da4c94-S0/frameworks/c590a129-814c-4903-9681-e16da4da4c94-0000' for = gc 6.99999127048593days in the future > [23:13:02] :=09 [Step 11/11] I1219 23:13:02.655233 25727 hierarchical.cpp= :1785] No inverse offers to send out! > [23:13:02] :=09 [Step 11/11] I1219 23:13:02.655295 25727 hierarchical.cpp= :1292] Performed allocation for 1 agents in 319498ns > [23:13:02] :=09 [Step 11/11] I1219 23:13:02.655410 25728 master.cpp:6580]= Sending 1 offers to framework c590a129-814c-4903-9681-e16da4da4c94-0000 (d= efault) at scheduler-f456ebc6-14e6-4a87-b6df-a9b53a01d554@172.16.10.213:454= 07 > [23:13:02] :=09 [Step 11/11] I1219 23:13:02.655586 25728 sched.cpp:923] S= cheduler::resourceOffers took 14921ns > [23:13:03] :=09 [Step 11/11] I1219 23:13:03.656186 25733 hierarchical.cpp= :1690] No allocations performed > [23:13:03] :=09 [Step 11/11] I1219 23:13:03.656234 25733 hierarchical.cpp= :1785] No inverse offers to send out! > [23:13:03] :=09 [Step 11/11] I1219 23:13:03.656252 25733 hierarchical.cpp= :1292] Performed allocation for 1 agents in 283333ns > [23:13:04] :=09 [Step 11/11] I1219 23:13:04.656954 25727 hierarchical.cpp= :1690] No allocations performed > [23:13:04] :=09 [Step 11/11] I1219 23:13:04.656990 25727 hierarchical.cpp= :1785] No inverse offers to send out! > [23:13:04] :=09 [Step 11/11] I1219 23:13:04.657006 25727 hierarchical.cpp= :1292] Performed allocation for 1 agents in 129708ns > [23:13:05] :=09 [Step 11/11] I1219 23:13:05.657685 25726 hierarchical.cpp= :1690] No allocations performed > [23:13:05] :=09 [Step 11/11] I1219 23:13:05.657721 25726 hierarchical.cpp= :1785] No inverse offers to send out! > [23:13:05] :=09 [Step 11/11] I1219 23:13:05.657737 25726 hierarchical.cpp= :1292] Performed allocation for 1 agents in 129877ns > [23:13:06] :=09 [Step 11/11] I1219 23:13:06.658830 25728 hierarchical.cpp= :1690] No allocations performed > [23:13:06] :=09 [Step 11/11] I1219 23:13:06.658865 25728 hierarchical.cpp= :1785] No inverse offers to send out! > [23:13:06] :=09 [Step 11/11] I1219 23:13:06.658884 25728 hierarchical.cpp= :1292] Performed allocation for 1 agents in 143178ns > [23:13:07] :=09 [Step 11/11] I1219 23:13:07.659719 25731 hierarchical.cpp= :1690] No allocations performed > [23:13:07] :=09 [Step 11/11] I1219 23:13:07.659754 25731 hierarchical.cpp= :1785] No inverse offers to send out! > [23:13:07] :=09 [Step 11/11] I1219 23:13:07.659771 25731 hierarchical.cpp= :1292] Performed allocation for 1 agents in 141527ns > [23:13:08] :=09 [Step 11/11] I1219 23:13:08.660782 25727 hierarchical.cpp= :1690] No allocations performed > [23:13:08] :=09 [Step 11/11] I1219 23:13:08.660823 25727 hierarchical.cpp= :1785] No inverse offers to send out! > [23:13:08] :=09 [Step 11/11] I1219 23:13:08.660841 25727 hierarchical.cpp= :1292] Performed allocation for 1 agents in 158649ns > [23:13:09] :=09 [Step 11/11] I1219 23:13:09.661458 25729 hierarchical.cpp= :1690] No allocations performed > [23:13:09] :=09 [Step 11/11] I1219 23:13:09.661495 25729 hierarchical.cpp= :1785] No inverse offers to send out! > [23:13:09] :=09 [Step 11/11] I1219 23:13:09.661512 25729 hierarchical.cpp= :1292] Performed allocation for 1 agents in 134970ns > [23:13:10] :=09 [Step 11/11] I1219 23:13:10.662621 25732 hierarchical.cpp= :1690] No allocations performed > [23:13:10] :=09 [Step 11/11] I1219 23:13:10.662655 25732 hierarchical.cpp= :1785] No inverse offers to send out! > [23:13:10] :=09 [Step 11/11] I1219 23:13:10.662673 25732 hierarchical.cpp= :1292] Performed allocation for 1 agents in 144999ns > [23:13:11] :=09 [Step 11/11] I1219 23:13:11.663347 25733 hierarchical.cpp= :1690] No allocations performed > [23:13:11] :=09 [Step 11/11] I1219 23:13:11.663380 25733 hierarchical.cpp= :1785] No inverse offers to send out! > [23:13:11] :=09 [Step 11/11] I1219 23:13:11.663398 25733 hierarchical.cpp= :1292] Performed allocation for 1 agents in 130561ns > [23:13:12] :=09 [Step 11/11] I1219 23:13:12.663929 25726 hierarchical.cpp= :1690] No allocations performed > [23:13:12] :=09 [Step 11/11] I1219 23:13:12.663964 25726 hierarchical.cpp= :1785] No inverse offers to send out! > [23:13:12] :=09 [Step 11/11] I1219 23:13:12.663982 25726 hierarchical.cpp= :1292] Performed allocation for 1 agents in 134957ns > [23:13:13] :=09 [Step 11/11] I1219 23:13:13.664721 25728 hierarchical.cpp= :1690] No allocations performed > [23:13:13] :=09 [Step 11/11] I1219 23:13:13.664757 25728 hierarchical.cpp= :1785] No inverse offers to send out! > [23:13:13] :=09 [Step 11/11] I1219 23:13:13.664773 25728 hierarchical.cpp= :1292] Performed allocation for 1 agents in 133416ns > [23:13:14] :=09 [Step 11/11] I1219 23:13:14.666043 25727 hierarchical.cpp= :1690] No allocations performed > [23:13:14] :=09 [Step 11/11] I1219 23:13:14.666080 25727 hierarchical.cpp= :1785] No inverse offers to send out! > [23:13:14] :=09 [Step 11/11] I1219 23:13:14.666098 25727 hierarchical.cpp= :1292] Performed allocation for 1 agents in 134466ns > [23:13:15] :=09 [Step 11/11] I1219 23:13:15.666527 25731 hierarchical.cpp= :1690] No allocations performed > [23:13:15] :=09 [Step 11/11] I1219 23:13:15.666563 25731 hierarchical.cpp= :1785] No inverse offers to send out! > [23:13:15] :=09 [Step 11/11] I1219 23:13:15.666581 25731 hierarchical.cpp= :1292] Performed allocation for 1 agents in 141096ns > [23:13:16] :=09 [Step 11/11] I1219 23:13:16.667453 25732 hierarchical.cpp= :1690] No allocations performed > [23:13:16] :=09 [Step 11/11] I1219 23:13:16.667487 25732 hierarchical.cpp= :1785] No inverse offers to send out! > [23:13:16] :=09 [Step 11/11] I1219 23:13:16.667505 25732 hierarchical.cpp= :1292] Performed allocation for 1 agents in 135350ns > [23:13:16] :=09 [Step 11/11] I1219 23:13:16.672703 25730 slave.cpp:5581] = Querying resource estimator for oversubscribable resources > [23:13:16] :=09 [Step 11/11] I1219 23:13:16.672827 25733 slave.cpp:5595] = Received oversubscribable resources {} from the resource estimator > [23:13:16] :=09 [Step 11/11] I1219 23:13:16.673852 25731 slave.cpp:4263] = Received ping from slave-observer(620)@172.16.10.213:45407 > [23:13:16] :=09 [Step 11/11] ../../src/tests/container_logger_tests.cpp:6= 94: Failure > [23:13:16] :=09 [Step 11/11] Failed to wait 15secs for statusFinished > [23:13:16] :=09 [Step 11/11] I1219 23:13:16.754849 25726 master.cpp:1305]= Framework c590a129-814c-4903-9681-e16da4da4c94-0000 (default) at scheduler= -f456ebc6-14e6-4a87-b6df-a9b53a01d554@172.16.10.213:45407 disconnected > [23:13:16] :=09 [Step 11/11] I1219 23:13:16.754892 25726 master.cpp:2919]= Disconnecting framework c590a129-814c-4903-9681-e16da4da4c94-0000 (default= ) at scheduler-f456ebc6-14e6-4a87-b6df-a9b53a01d554@172.16.10.213:45407 > [23:13:16] :=09 [Step 11/11] I1219 23:13:16.754911 25726 master.cpp:2943]= Deactivating framework c590a129-814c-4903-9681-e16da4da4c94-0000 (default)= at scheduler-f456ebc6-14e6-4a87-b6df-a9b53a01d554@172.16.10.213:45407 > [23:13:16] :=09 [Step 11/11] ../../src/tests/container_logger_tests.cpp:6= 84: Failure > [23:13:16] :=09 [Step 11/11] Actual function call count doesn't match EXP= ECT_CALL(sched, statusUpdate(&driver, _))... > [23:13:16] :=09 [Step 11/11] Expected: to be called at least twi= ce > [23:13:16] :=09 [Step 11/11] I Actual: called once - unsatisfie= d and active > [23:13:16] :=09 [Step 11/11] 1219 23:13:16.755024 25733 hierarchical.cpp:= 392] Deactivated framework c590a129-814c-4903-9681-e16da4da4c94-0000 > [23:13:16] :=09 [Step 11/11] W1219 23:13:16.755056 25726 master.hpp:2313]= Master attempted to send message to disconnected framework c590a129-814c-4= 903-9681-e16da4da4c94-0000 (default) at scheduler-f456ebc6-14e6-4a87-b6df-a= 9b53a01d554@172.16.10.213:45407 > [23:13:16] :=09 [Step 11/11] I1219 23:13:16.755115 25726 master.cpp:1318]= Giving framework c590a129-814c-4903-9681-e16da4da4c94-0000 (default) at sc= heduler-f456ebc6-14e6-4a87-b6df-a9b53a01d554@172.16.10.213:45407 0ns to fai= lover > [23:13:16] :=09 [Step 11/11] I1219 23:13:16.755229 25728 master.cpp:6432]= Framework failover timeout, removing framework c590a129-814c-4903-9681-e16= da4da4c94-0000 (default) at scheduler-f456ebc6-14e6-4a87-b6df-a9b53a01d554@= 172.16.10.213:45407 > [23:13:16] :=09 [Step 11/11] I1219 23:13:16.755246 25728 master.cpp:7303]= Removing framework c590a129-814c-4903-9681-e16da4da4c94-0000 (default) at = scheduler-f456ebc6-14e6-4a87-b6df-a9b53a01d554@172.16.10.213:45407 > [23:13:16] :=09 [Step 11/11] I1219 23:13:16.755247 25733 hierarchical.cpp= :1024] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-3200= 0] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], al= located: {}) on agent c590a129-814c-4903-9681-e16da4da4c94-S0 from framewor= k c590a129-814c-4903-9681-e16da4da4c94-0000 > [23:13:16] :=09 [Step 11/11] I1219 23:13:16.755383 25732 slave.cpp:2581] = Asked to shut down framework c590a129-814c-4903-9681-e16da4da4c94-0000 by m= aster@172.16.10.213:45407 > [23:13:16] :=09 [Step 11/11] I1219 23:13:16.755400 25732 slave.cpp:2596] = Cannot shut down unknown framework c590a129-814c-4903-9681-e16da4da4c94-000= 0 > [23:13:16] :=09 [Step 11/11] I1219 23:13:16.755512 25729 hierarchical.cpp= :343] Removed framework c590a129-814c-4903-9681-e16da4da4c94-0000 > [23:13:16] :=09 [Step 11/11] I1219 23:13:16.755718 25727 slave.cpp:796] A= gent terminating > [23:13:16] :=09 [Step 11/11] I1219 23:13:16.755803 25727 master.cpp:1258]= Agent c590a129-814c-4903-9681-e16da4da4c94-S0 at slave(684)@172.16.10.213:= 45407 (ip-172-16-10-213.mesosphere.io) disconnected > [23:13:16] :=09 [Step 11/11] I1219 23:13:16.755820 25727 master.cpp:2978]= Disconnecting agent c590a129-814c-4903-9681-e16da4da4c94-S0 at slave(684)@= 172.16.10.213:45407 (ip-172-16-10-213.mesosphere.io) > [23:13:16] :=09 [Step 11/11] I1219 23:13:16.755841 25727 master.cpp:2997]= Deactivating agent c590a129-814c-4903-9681-e16da4da4c94-S0 at slave(684)@1= 72.16.10.213:45407 (ip-172-16-10-213.mesosphere.io) > [23:13:16] :=09 [Step 11/11] I1219 23:13:16.755882 25727 hierarchical.cpp= :590] Agent c590a129-814c-4903-9681-e16da4da4c94-S0 deactivated > [23:13:16] :=09 [Step 11/11] I1219 23:13:16.757964 25712 master.cpp:1097]= Master terminating > [23:13:16] :=09 [Step 11/11] I1219 23:13:16.758131 25726 hierarchical.cpp= :523] Removed agent c590a129-814c-4903-9681-e16da4da4c94-S0 > [23:13:16] :=09 [Step 11/11] [ FAILED ] bool/UserContainerLoggerTest.RO= OT_LOGROTATE_RotateWithSwitchUserTrueOrFalse/0, where GetParam() =3D true (= 15107 ms) > Build failed on step #11: Run tests 1 > bool/UserContainerLoggerTest.ROOT_LOGROTATE_RotateWithSwitchUserTrueOrFal= se/0, > OK=09OK > cmake=09=09OK=09Build failed on step #8: Make check without running tests= =09OK=09=09Build failed on step #8: Make check without running tests=09=09B= uild failed on step #8: Make check without running tests > NWI=09=09=09=09Build failed on step #11: Run tests PortMappingIsolatorTes= t.ROOT_DNS > PortMappingIsolatorTest.ROOT_ContainerICMPExternal > PortMappingIsolatorTest.ROOT_NC_HostToContainerUDP > build succeeded and all tests passed > #=09build succeeded, but # of tests failed > build succeeded, but the test suite did not finish > step=09build step failed > system error > GTEST_FILTER: > {code} -- This message was sent by Atlassian JIRA (v6.3.4#6332)