[
https://issues.apache.org/jira/browse/MESOS-6823?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
James Peach reassigned MESOS-6823:
----------------------------------
Resolution: Fixed
Assignee: Jie Yu
Fix Version/s: 1.7.0
{noformat}
commit 32d4305b87e79ed02cc686e0c29b027e31c6b3a4
Author: Jie Yu
Date: Thu May 24 10:05:17 2018 -0700
Adjusted the tests that use nobody.
Used `$SUDO_USER` instead because `nobody` sometimes cannot access
direcotries under `$HOME` of the current user running the tests.
Review: https://reviews.apache.org/r/67291
{noformat}
> bool/UserContainerLoggerTest.ROOT_LOGROTATE_RotateWithSwitchUserTrueOrFalse/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
> Assignee: Jie Yu
> Priority: Major
> Labels: flaky, flaky-test, newbie
> Fix For: 1.7.0
>
>
> This showed up on our internal CI
> {code}
> [23:13:01] : [Step 11/11] [ RUN ]
> bool/UserContainerLoggerTest.ROOT_LOGROTATE_RotateWithSwitchUserTrueOrFalse/0
> [23:13:01] : [Step 11/11] I1219 23:13:01.653230 25712 cluster.cpp:160]
> Creating default 'local' authorizer
> [23:13:01] : [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] : [Step 11/11] I1219 23:13:01.654119 25732 master.cpp:382] Flags
> at startup: --acls="" --agent_ping_timeout="15secs"
> --agent_reregister_timeout="10mins" --allocation_interval="1secs"
> --allocator="HierarchicalDRF" --authenticate_agents="true"
> --authenticate_frameworks="true" --authenticate_http_frameworks="true"
> --authenticate_http_readonly="true" --authenticate_http_readwrite="true"
> --authenticators="crammd5" --authorizers="local"
> --credentials="/mnt/teamcity/temp/buildTmp/ev3icd/credentials"
> --framework_sorter="drf" --help="false" --hostname_lookup="true"
> --http_authenticators="basic" --http_framework_authenticators="basic"
> --initialize_driver_logging="true" --log_auto_initialize="true"
> --logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5"
> --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000"
> --quiet="false" --recovery_agent_removal_limit="100%" --registry="in_memory"
> --registry_fetch_timeout="1mins" --registry_gc_interval="15mins"
> --registry_max_agent_age="2weeks" --registry_max_agent_count="102400"
> --registry_store_timeout="100secs" --registry_strict="false"
> --root_submissions="true" --user_sorter="drf" --version="false"
> --webui_dir="/usr/local/share/mesos/webui"
> --work_dir="/mnt/teamcity/temp/buildTmp/ev3icd/master"
> --zk_session_timeout="10secs"
> [23:13:01] : [Step 11/11] I1219 23:13:01.654248 25732 master.cpp:432]
> Master only allowing authenticated frameworks to register
> [23:13:01] : [Step 11/11] I1219 23:13:01.654254 25732 master.cpp:446]
> Master only allowing authenticated agents to register
> [23:13:01] : [Step 11/11] I1219 23:13:01.654258 25732 master.cpp:459]
> Master only allowing authenticated HTTP frameworks to register
> [23:13:01] : [Step 11/11] I1219 23:13:01.654261 25732 credentials.hpp:37]
> Loading credentials for authentication from
> '/mnt/teamcity/temp/buildTmp/ev3icd/credentials'
> [23:13:01] : [Step 11/11] I1219 23:13:01.654343 25732 master.cpp:504] Using
> default 'crammd5' authenticator
> [23:13:01] : [Step 11/11] I1219 23:13:01.654386 25732 http.cpp:922] Using
> default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
> [23:13:01] : [Step 11/11] I1219 23:13:01.654429 25732 http.cpp:922] Using
> default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
> [23:13:01] : [Step 11/11] I1219 23:13:01.654458 25732 http.cpp:922] Using
> default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
> [23:13:01] : [Step 11/11] I1219 23:13:01.654477 25732 master.cpp:584]
> Authorization enabled
> [23:13:01] : [Step 11/11] I1219 23:13:01.654551 25733
> whitelist_watcher.cpp:77] No whitelist given
> [23:13:01] : [Step 11/11] I1219 23:13:01.654582 25730 hierarchical.cpp:149]
> Initialized hierarchical allocator process
> [23:13:01] : [Step 11/11] I1219 23:13:01.655076 25732 master.cpp:2046]
> Elected as the leading master!
> [23:13:01] : [Step 11/11] I1219 23:13:01.655086 25732 master.cpp:1568]
> Recovering from registrar
> [23:13:01] : [Step 11/11] I1219 23:13:01.655124 25729 registrar.cpp:329]
> Recovering registrar
> [23:13:01] : [Step 11/11] I1219 23:13:01.655354 25731 registrar.cpp:362]
> Successfully fetched the registry (0B) in 210944ns
> [23:13:01] : [Step 11/11] I1219 23:13:01.655385 25731 registrar.cpp:461]
> Applied 1 operations in 5006ns; attempting to update the registry
> [23:13:01] : [Step 11/11] I1219 23:13:01.655593 25732 registrar.cpp:506]
> Successfully updated the registry in 194048ns
> [23:13:01] : [Step 11/11] I1219 23:13:01.655658 25732 registrar.cpp:392]
> Successfully recovered registrar
> [23:13:01] : [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] : [Step 11/11] I1219 23:13:01.655840 25728 hierarchical.cpp:176]
> Skipping recovery of hierarchical allocator: nothing to recover
> [23:13:01] : [Step 11/11] I1219 23:13:01.656813 25712
> containerizer.cpp:220] Using isolation:
> posix/cpu,posix/mem,filesystem/posix,network/cni
> [23:13:01] : [Step 11/11] I1219 23:13:01.659867 25712
> linux_launcher.cpp:150] Using /sys/fs/cgroup/freezer as the freezer hierarchy
> for the Linux launcher
> [23:13:01] : [Step 11/11] I1219 23:13:01.667733 25712 cluster.cpp:446]
> Creating default 'local' authorizer
> [23:13:01] : [Step 11/11] I1219 23:13:01.668246 25730 slave.cpp:209] Mesos
> agent started on (684)@172.16.10.213:45407
> [23:13:01] : [Step 11/11] I1219 23:13:01.668257 25730 slave.cpp:210] Flags
> at startup: --acls="" --appc_simple_discovery_uri_prefix="http://";
> --appc_store_dir="/mnt/teamcity/temp/buildTmp/mesos/store/appc"
> --authenticate_http_readonly="true" --authenticate_http_readwrite="true"
> --authenticatee="crammd5" --authentication_backoff_factor="1secs"
> --authorizer="local" --cgroups_cpu_enable_pids_and_tids_count="false"
> --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup"
> --cgroups_limit_swap="false" --cgroups_root="mesos"
> --container_disk_watch_interval="15secs"
> --container_logger="org_apache_mesos_LogrotateContainerLogger"
> --containerizers="mesos"
> --credential="/mnt/teamcity/temp/buildTmp/bool_UserContainerLoggerTest_ROOT_LOGROTATE_RotateWithSwitchUserTrueOrFalse_0_DcAJjZ/credential"
> --default_role="*" --disk_watch_interval="1mins" --docker="docker"
> --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io";
> --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock"
> --docker_stop_timeout="0ns"
> --docker_store_dir="/mnt/teamcity/temp/buildTmp/mesos/store/docker"
> --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume"
> --enforce_container_disk_quota="false"
> --executor_registration_timeout="1mins"
> --executor_shutdown_grace_period="5secs"
> --fetcher_cache_dir="/mnt/teamcity/temp/buildTmp/bool_UserContainerLoggerTest_ROOT_LOGROTATE_RotateWithSwitchUserTrueOrFalse_0_DcAJjZ/fetch"
> --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks"
> --gc_disk_headroom="0.1" --hadoop_home="" --help="false"
> --hostname_lookup="true" --http_authenticators="basic"
> --http_command_executor="false"
> --http_credentials="/mnt/teamcity/temp/buildTmp/bool_UserContainerLoggerTest_ROOT_LOGROTATE_RotateWithSwitchUserTrueOrFalse_0_DcAJjZ/http_credentials"
> --http_heartbeat_interval="30secs" --image_provisioner_backend="copy"
> --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem"
> --launcher="linux"
> --launcher_dir="/mnt/teamcity/work/4240ba9ddd0997c3/build/src"
> --logbufsecs="0" --logging_level="INFO"
> --max_completed_executors_per_framework="150"
> --oversubscribed_resources_interval="15secs" --perf_duration="10secs"
> --perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false"
> --recover="reconnect" --recovery_timeout="15mins"
> --registration_backoff_factor="10ms"
> --resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]"
> --revocable_cpu_low_priority="true"
> --runtime_dir="/mnt/teamcity/temp/buildTmp/bool_UserContainerLoggerTest_ROOT_LOGROTATE_RotateWithSwitchUserTrueOrFalse_0_DcAJjZ"
> --sandbox_directory="/mnt/mesos/sandbox" --strict="true"
> --switch_user="true" --systemd_enable_support="true"
> --systemd_runtime_directory="/run/systemd/system" --version="false"
> --work_dir="/mnt/teamcity/temp/buildTmp/bool_UserContainerLoggerTest_ROOT_LOGROTATE_RotateWithSwitchUserTrueOrFalse_0_Ea40f6"
> [23:13:01] : [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_RotateWithSwitchUserTrueOrFalse_0_DcAJjZ/credential'
> [23:13:01] : [Step 11/11] I1219 23:13:01.668604 25730 slave.cpp:352] Agent
> using credential for: test-principal
> [23:13:01] : [Step 11/11] I1219 23:13:01.668614 25730 credentials.hpp:37]
> Loading credentials for authentication from
> '/mnt/teamcity/temp/buildTmp/bool_UserContainerLoggerTest_ROOT_LOGROTATE_RotateWithSwitchUserTrueOrFalse_0_DcAJjZ/http_credentials'
> [23:13:01] : [Step 11/11] I1219 23:13:01.668684 25730 http.cpp:922] Using
> default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
> [23:13:01] : [Step 11/11] I1219 23:13:01.668732 25730 http.cpp:922] Using
> default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite'
> [23:13:01] : [Step 11/11] I1219 23:13:01.669096 25730 slave.cpp:539] Agent
> resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> [23:13:01] : [Step 11/11] I1219 23:13:01.669124 25730 slave.cpp:547] Agent
> attributes: [ ]
> [23:13:01] : [Step 11/11] I1219 23:13:01.669129 25730 slave.cpp:552] Agent
> hostname: ip-172-16-10-213.mesosphere.io
> [23:13:01] : [Step 11/11] I1219 23:13:01.669481 25730 state.cpp:57]
> Recovering state from
> '/mnt/teamcity/temp/buildTmp/bool_UserContainerLoggerTest_ROOT_LOGROTATE_RotateWithSwitchUserTrueOrFalse_0_Ea40f6/meta'
> [23:13:01] : [Step 11/11] I1219 23:13:01.669692 25731
> status_update_manager.cpp:203] Recovering status update manager
> [23:13:01] : [Step 11/11] I1219 23:13:01.669780 25727
> containerizer.cpp:599] Recovering containerizer
> [23:13:01] : [Step 11/11] I1219 23:13:01.670794 25733 provisioner.cpp:253]
> Provisioner recovery complete
> [23:13:01] : [Step 11/11] I1219 23:13:01.670958 25726 slave.cpp:5407]
> Finished recovery
> [23:13:01] : [Step 11/11] I1219 23:13:01.671187 25726 slave.cpp:5581]
> Querying resource estimator for oversubscribable resources
> [23:13:01] : [Step 11/11] I1219 23:13:01.671315 25731
> status_update_manager.cpp:177] Pausing sending status updates
> [23:13:01] : [Step 11/11] I1219 23:13:01.671314 25726 slave.cpp:924] New
> master detected at master@172.16.10.213:45407
> [23:13:01] : [Step 11/11] I1219 23:13:01.671349 25726 slave.cpp:983]
> Authenticating with master master@172.16.10.213:45407
> [23:13:01] : [Step 11/11] I1219 23:13:01.671363 25726 slave.cpp:994] Using
> default CRAM-MD5 authenticatee
> [23:13:01] : [Step 11/11] I1219 23:13:01.671401 25726 slave.cpp:956]
> Detecting new master
> [23:13:01] : [Step 11/11] I1219 23:13:01.671442 25730
> authenticatee.cpp:121] Creating new client SASL connection
> [23:13:01] : [Step 11/11] I1219 23:13:01.671458 25726 slave.cpp:5595]
> Received oversubscribable resources {} from the resource estimator
> [23:13:01] : [Step 11/11] I1219 23:13:01.671689 25730 master.cpp:6751]
> Authenticating slave(684)@172.16.10.213:45407
> [23:13:01] : [Step 11/11] I1219 23:13:01.671737 25726
> authenticator.cpp:414] Starting authentication session for
> crammd5-authenticatee(1319)@172.16.10.213:45407
> [23:13:01] : [Step 11/11] I1219 23:13:01.671819 25732 authenticator.cpp:98]
> Creating new server SASL connection
> [23:13:01] : [Step 11/11] I1219 23:13:01.672016 25732
> authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
> [23:13:01] : [Step 11/11] I1219 23:13:01.672034 25732
> authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
> [23:13:01] : [Step 11/11] I1219 23:13:01.672106 25727
> authenticator.cpp:204] Received SASL authentication start
> [23:13:01] : [Step 11/11] I1219 23:13:01.672142 25727
> authenticator.cpp:326] Authentication requires more steps
> [23:13:01] : [Step 11/11] I1219 23:13:01.672174 25727
> authenticatee.cpp:259] Received SASL authentication step
> [23:13:01] : [Step 11/11] I1219 23:13:01.672231 25727
> authenticator.cpp:232] Received SASL authentication step
> [23:13:01] : [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_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> [23:13:01] : [Step 11/11] I1219 23:13:01.672258 25727 auxprop.cpp:181]
> Looking up auxiliary property '*userPassword'
> [23:13:01] : [Step 11/11] I1219 23:13:01.672273 25727 auxprop.cpp:181]
> Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> [23:13:01] : [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_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> [23:13:01] : [Step 11/11] I1219 23:13:01.672291 25727 auxprop.cpp:131]
> Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> [23:13:01] : [Step 11/11] I1219 23:13:01.672294 25727 auxprop.cpp:131]
> Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since
> SASL_AUXPROP_AUTHZID == true
> [23:13:01] : [Step 11/11] I1219 23:13:01.672303 25727
> authenticator.cpp:318] Authentication success
> [23:13:01] : [Step 11/11] I1219 23:13:01.672353 25732
> authenticatee.cpp:299] Authentication success
> [23:13:01] : [Step 11/11] I1219 23:13:01.672389 25727
> authenticator.cpp:432] Authentication session cleanup for
> crammd5-authenticatee(1319)@172.16.10.213:45407
> [23:13:01] : [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] : [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] : [Step 11/11] I1219 23:13:01.672525 25732 slave.cpp:1493] Will
> retry registration in 548917ns if necessary
> [23:13:01] : [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.mesosphere.io) with id
> c590a129-814c-4903-9681-e16da4da4c94-S0
> [23:13:01] : [Step 11/11] I1219 23:13:01.672755 25731 registrar.cpp:461]
> Applied 1 operations in 20881ns; attempting to update the registry
> [23:13:01] : [Step 11/11] I1219 23:13:01.673188 25731 registrar.cpp:506]
> Successfully updated the registry in 402944ns
> [23:13:01] : [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] : [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(*):1024; disk(*):1024; ports(*):[31000-32000]
> [23:13:01] : [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] : [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] : [Step 11/11] I1219 23:13:01.673519 25733 fetcher.cpp:90]
> Clearing fetcher cache
> [23:13:01] : [Step 11/11] I1219 23:13:01.673519 25732
> hierarchical.cpp:1690] No allocations performed
> [23:13:01] : [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] : [Step 11/11] I1219 23:13:01.673630 25730
> status_update_manager.cpp:184] Resuming sending status updates
> [23:13:01] : [Step 11/11] I1219 23:13:01.673707 25733 slave.cpp:1147]
> Checkpointing SlaveInfo to
> '/mnt/teamcity/temp/buildTmp/bool_UserContainerLoggerTest_ROOT_LOGROTATE_RotateWithSwitchUserTrueOrFalse_0_Ea40f6/meta/slaves/c590a129-814c-4903-9681-e16da4da4c94-S0/slave.info'
> [23:13:01] : [Step 11/11] I1219 23:13:01.673825 25733 slave.cpp:1184]
> Forwarding total oversubscribed resources {}
> [23:13:01] : [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
> oversubscribed resources {}
> [23:13:01] : [Step 11/11] I1219 23:13:01.673984 25732 hierarchical.cpp:561]
> Agent c590a129-814c-4903-9681-e16da4da4c94-S0
> (ip-172-16-10-213.mesosphere.io) updated with oversubscribed resources {}
> (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000],
> allocated: {})
> [23:13:01] : [Step 11/11] I1219 23:13:01.674024 25732
> hierarchical.cpp:1690] No allocations performed
> [23:13:01] : [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] : [Step 11/11] I1219 23:13:01.674474 25712 sched.cpp:232]
> Version: 1.2.0
> [23:13:01] : [Step 11/11] I1219 23:13:01.674671 25731 sched.cpp:336] New
> master detected at master@172.16.10.213:45407
> [23:13:01] : [Step 11/11] I1219 23:13:01.674700 25731 sched.cpp:402]
> Authenticating with master master@172.16.10.213:45407
> [23:13:01] : [Step 11/11] I1219 23:13:01.674706 25731 sched.cpp:409] Using
> default CRAM-MD5 authenticatee
> [23:13:01] : [Step 11/11] I1219 23:13:01.674800 25732
> authenticatee.cpp:121] Creating new client SASL connection
> [23:13:01] : [Step 11/11] I1219 23:13:01.674967 25732 master.cpp:6751]
> Authenticating
> scheduler-f456ebc6-14e6-4a87-b6df-a9b53a01d554@172.16.10.213:45407
> [23:13:01] : [Step 11/11] I1219 23:13:01.675021 25730
> authenticator.cpp:414] Starting authentication session for
> crammd5-authenticatee(1320)@172.16.10.213:45407
> [23:13:01] : [Step 11/11] I1219 23:13:01.675082 25730 authenticator.cpp:98]
> Creating new server SASL connection
> [23:13:01] : [Step 11/11] I1219 23:13:01.675256 25730
> authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
> [23:13:01] : [Step 11/11] I1219 23:13:01.675268 25730
> authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
> [23:13:01] : [Step 11/11] I1219 23:13:01.675348 25733
> authenticator.cpp:204] Received SASL authentication start
> [23:13:01] : [Step 11/11] I1219 23:13:01.675374 25733
> authenticator.cpp:326] Authentication requires more steps
> [23:13:01] : [Step 11/11] I1219 23:13:01.675406 25733
> authenticatee.cpp:259] Received SASL authentication step
> [23:13:01] : [Step 11/11] I1219 23:13:01.675482 25728
> authenticator.cpp:232] Received SASL authentication step
> [23:13:01] : [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_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> [23:13:01] : [Step 11/11] I1219 23:13:01.675508 25728 auxprop.cpp:181]
> Looking up auxiliary property '*userPassword'
> [23:13:01] : [Step 11/11] I1219 23:13:01.675516 25728 auxprop.cpp:181]
> Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> [23:13:01] : [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_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> [23:13:01] : [Step 11/11] I1219 23:13:01.675534 25728 auxprop.cpp:131]
> Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> [23:13:01] : [Step 11/11] I1219 23:13:01.675542 25728 auxprop.cpp:131]
> Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since
> SASL_AUXPROP_AUTHZID == true
> [23:13:01] : [Step 11/11] I1219 23:13:01.675554 25728
> authenticator.cpp:318] Authentication success
> [23:13:01] : [Step 11/11] I1219 23:13:01.675613 25731
> authenticatee.cpp:299] Authentication success
> [23:13:01] : [Step 11/11] I1219 23:13:01.675637 25728 master.cpp:6781]
> Successfully authenticated principal 'test-principal' at
> scheduler-f456ebc6-14e6-4a87-b6df-a9b53a01d554@172.16.10.213:45407
> [23:13:01] : [Step 11/11] I1219 23:13:01.675668 25732
> authenticator.cpp:432] Authentication session cleanup for
> crammd5-authenticatee(1320)@172.16.10.213:45407
> [23:13:01] : [Step 11/11] I1219 23:13:01.675787 25731 sched.cpp:508]
> Successfully authenticated with master master@172.16.10.213:45407
> [23:13:01] : [Step 11/11] I1219 23:13:01.675803 25731 sched.cpp:826]
> Sending SUBSCRIBE call to master@172.16.10.213:45407
> [23:13:01] : [Step 11/11] I1219 23:13:01.675851 25731 sched.cpp:859] Will
> retry registration in 1.955259957secs if necessary
> [23:13:01] : [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] : [Step 11/11] I1219 23:13:01.675926 25729 master.cpp:2082]
> Authorizing framework principal 'test-principal' to receive offers for role
> '*'
> [23:13:01] : [Step 11/11] I1219 23:13:01.676045 25729 master.cpp:2710]
> Subscribing framework default with checkpointing disabled and capabilities [
> ]
> [23:13:01] : [Step 11/11] I1219 23:13:01.676188 25727 sched.cpp:749]
> Framework registered with c590a129-814c-4903-9681-e16da4da4c94-0000
> [23:13:01] : [Step 11/11] I1219 23:13:01.676218 25726 hierarchical.cpp:277]
> Added framework c590a129-814c-4903-9681-e16da4da4c94-0000
> [23:13:01] : [Step 11/11] I1219 23:13:01.676242 25727 sched.cpp:763]
> Scheduler::registered took 36846ns
> [23:13:01] : [Step 11/11] I1219 23:13:01.676443 25726
> hierarchical.cpp:1785] No inverse offers to send out!
> [23:13:01] : [Step 11/11] I1219 23:13:01.676468 25726
> hierarchical.cpp:1292] Performed allocation for 1 agents in 236491ns
> [23:13:01] : [Step 11/11] I1219 23:13:01.676529 25732 master.cpp:6580]
> Sending 1 offers to framework c590a129-814c-4903-9681-e16da4da4c94-0000
> (default) at
> scheduler-f456ebc6-14e6-4a87-b6df-a9b53a01d554@172.16.10.213:45407
> [23:13:01] : [Step 11/11] I1219 23:13:01.676668 25732 sched.cpp:923]
> Scheduler::resourceOffers took 38617ns
> [23:13:01] : [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-4903-9681-e16da4da4c94-0000 (default) at
> scheduler-f456ebc6-14e6-4a87-b6df-a9b53a01d554@172.16.10.213:45407
> [23:13:01] : [Step 11/11] I1219 23:13:01.677145 25730 master.cpp:3176]
> Authorizing framework principal 'test-principal' to launch task
> 255e31f0-a34f-4560-beb8-ff120c315d24
> [23:13:01] : [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-4903-9681-e16da4da4c94-S0 (ip-172-16-10-213.mesosphere.io)
> [23:13:01] : [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-e16da4da4c94-S0 at
> slave(684)@172.16.10.213:45407 (ip-172-16-10-213.mesosphere.io)
> [23:13:01] : [Step 11/11] I1219 23:13:01.677855 25728 slave.cpp:1557] Got
> assigned task '255e31f0-a34f-4560-beb8-ff120c315d24' for framework
> c590a129-814c-4903-9681-e16da4da4c94-0000
> [23:13:01] : [Step 11/11] I1219 23:13:01.678030 25728 slave.cpp:1717]
> Launching task '255e31f0-a34f-4560-beb8-ff120c315d24' for framework
> c590a129-814c-4903-9681-e16da4da4c94-0000
> [23:13:01] : [Step 11/11] I1219 23:13:01.678251 25728 paths.cpp:530] Trying
> to chown
> '/mnt/teamcity/temp/buildTmp/bool_UserContainerLoggerTest_ROOT_LOGROTATE_RotateWithSwitchUserTrueOrFalse_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'
> to user 'nobody'
> [23:13:01] : [Step 11/11] I1219 23:13:01.684034 25728 slave.cpp:6334]
> Launching executor '255e31f0-a34f-4560-beb8-ff120c315d24' of framework
> c590a129-814c-4903-9681-e16da4da4c94-0000 with resources cpus(*):0.1;
> mem(*):32 in work directory
> '/mnt/teamcity/temp/buildTmp/bool_UserContainerLoggerTest_ROOT_LOGROTATE_RotateWithSwitchUserTrueOrFalse_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'
> [23:13:01] : [Step 11/11] I1219 23:13:01.684319 25728 slave.cpp:2039]
> Queued task '255e31f0-a34f-4560-beb8-ff120c315d24' for executor
> '255e31f0-a34f-4560-beb8-ff120c315d24' of framework
> c590a129-814c-4903-9681-e16da4da4c94-0000
> [23:13:01] : [Step 11/11] I1219 23:13:01.684326 25726
> containerizer.cpp:991] Starting container
> 56d7390e-0131-4648-8f91-862f52f11912 for executor
> '255e31f0-a34f-4560-beb8-ff120c315d24' of framework
> c590a129-814c-4903-9681-e16da4da4c94-0000
> [23:13:01] : [Step 11/11] I1219 23:13:01.684360 25728 slave.cpp:877]
> Successfully attached file
> '/mnt/teamcity/temp/buildTmp/bool_UserContainerLoggerTest_ROOT_LOGROTATE_RotateWithSwitchUserTrueOrFalse_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'
> [23:13:01] : [Step 11/11] I1219 23:13:01.691035 25726
> containerizer.cpp:1540] Launching 'mesos-containerizer' with flags
> '--help="false"
> --launch_info="{"command":{"arguments":["mesos-executor","--launcher_dir=\/mnt\/teamcity\/work\/4240ba9ddd0997c3\/build\/src"],"shell":false,"value":"\/mnt\/teamcity\/work\/4240ba9ddd0997c3\/build\/src\/mesos-executor"},"environment":{"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\/buildTmp\/bool_UserContainerLoggerTest_ROOT_LOGROTATE_RotateWithSwitchUserTrueOrFalse_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":"MESOS_EXECUTOR_ID","value":"255e31f0-a34f-4560-beb8-ff120c315d24"},{"name":"MESOS_EXECUTOR_SHUTDOWN_GRACE_PERIOD","value":"5secs"},{"name":"MESOS_FRAMEWORK_ID","value":"c590a129-814c-4903-9681-e16da4da4c94-0000"},{"name":"MESOS_HTTP_COMMAND_EXECUTOR","value":"0"},{"name":"MESOS_SLAVE_ID","value":"c590a129-814c-4903-9681-e16da4da4c94-S0"},{"name":"MESOS_SLAVE_PID","value":"slave(684)@172.16.10.213:45407"},{"name":"MESOS_SANDBOX","value":"\/mnt\/teamcity\/temp\/buildTmp\/bool_UserContainerLoggerTest_ROOT_LOGROTATE_RotateWithSwitchUserTrueOrFalse_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"}]},"err":{"fd":58,"type":"FD"},"out":{"fd":57,"type":"FD"},"user":"nobody","working_directory":"\/mnt\/teamcity\/temp\/buildTmp\/bool_UserContainerLoggerTest_ROOT_LOGROTATE_RotateWithSwitchUserTrueOrFalse_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"}"
> --pipe_read="56" --pipe_write="59"
> --runtime_directory="/mnt/teamcity/temp/buildTmp/bool_UserContainerLoggerTest_ROOT_LOGROTATE_RotateWithSwitchUserTrueOrFalse_0_DcAJjZ/containers/56d7390e-0131-4648-8f91-862f52f11912"
> --unshare_namespace_mnt="false"'
> [23:13:01] : [Step 11/11] I1219 23:13:01.691459 25729
> linux_launcher.cpp:429] Launching container
> 56d7390e-0131-4648-8f91-862f52f11912 and cloning with namespaces
> [23:13:01] : [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-4903-9681-e16da4da4c94-S0/frameworks/c590a129-814c-4903-9681-e16da4da4c94-0000/executors/255e31f0-a34f-4560-beb8-ff120c315d24/runs/56d7390e-0131-4648-8f91-862f52f11912
> [23:13:01] : [Step 11/11] WARNING: Logging before InitGoogleLogging() is
> written to STDERR
> [23:13:01] : [Step 11/11] WARNING: Logging before InitGoogleLogging() is
> written to STDERR
> [23:13:01] : [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=8 instead
> [23:13:01] : [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=8 instead
> [23:13:01] : [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] : [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] : [Step 11/11] I1219 23:13:01.746567 25732
> containerizer.cpp:2481] Container 56d7390e-0131-4648-8f91-862f52f11912 has
> exited
> [23:13:01] : [Step 11/11] I1219 23:13:01.746597 25732
> containerizer.cpp:2118] Destroying container
> 56d7390e-0131-4648-8f91-862f52f11912 in RUNNING state
> [23:13:01] : [Step 11/11] I1219 23:13:01.746821 25731
> linux_launcher.cpp:505] Asked to destroy container
> 56d7390e-0131-4648-8f91-862f52f11912
> [23:13:01] : [Step 11/11] I1219 23:13:01.747288 25731
> linux_launcher.cpp:548] Using freezer to destroy cgroup
> mesos/56d7390e-0131-4648-8f91-862f52f11912
> [23:13:01] : [Step 11/11] I1219 23:13:01.747941 25732 cgroups.cpp:2726]
> Freezing cgroup
> /sys/fs/cgroup/freezer/mesos/56d7390e-0131-4648-8f91-862f52f11912
> [23:13:01] : [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] : [Step 11/11] I1219 23:13:01.749860 25728 cgroups.cpp:2744]
> Thawing cgroup
> /sys/fs/cgroup/freezer/mesos/56d7390e-0131-4648-8f91-862f52f11912
> [23:13:01] : [Step 11/11] I1219 23:13:01.750797 25729 cgroups.cpp:1468]
> Successfully thawed cgroup
> /sys/fs/cgroup/freezer/mesos/56d7390e-0131-4648-8f91-862f52f11912 after
> 915968ns
> [23:13:01] : [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] : [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] : [Step 11/11] I1219 23:13:01.752601 25732 slave.cpp:3740]
> Handling 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 @0.0.0.0:0
> [23:13:01] : [Step 11/11] W1219 23:13:01.752883 25730
> containerizer.cpp:1933] Ignoring update for unknown container
> 56d7390e-0131-4648-8f91-862f52f11912
> [23:13:01] : [Step 11/11] I1219 23:13:01.753000 25729
> status_update_manager.cpp:323] Received 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
> [23:13:01] : [Step 11/11] I1219 23:13:01.753020 25729
> status_update_manager.cpp:500] Creating StatusUpdate stream for task
> 255e31f0-a34f-4560-beb8-ff120c315d24 of framework
> c590a129-814c-4903-9681-e16da4da4c94-0000
> [23:13:01] : [Step 11/11] I1219 23:13:01.753155 25729
> status_update_manager.cpp:377] Forwarding update TASK_FAILED (UUID:
> e64c0c36-291c-451e-91c0-d9615b4b49be) for task
> 255e31f0-a34f-4560-beb8-ff120c315d24 of framework
> c590a129-814c-4903-9681-e16da4da4c94-0000 to the agent
> [23:13:01] : [Step 11/11] I1219 23:13:01.753247 25727 slave.cpp:4181]
> Forwarding the update TASK_FAILED (UUID:
> e64c0c36-291c-451e-91c0-d9615b4b49be) for task
> 255e31f0-a34f-4560-beb8-ff120c315d24 of framework
> c590a129-814c-4903-9681-e16da4da4c94-0000 to master@172.16.10.213:45407
> [23:13:01] : [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-ff120c315d24 of framework
> c590a129-814c-4903-9681-e16da4da4c94-0000
> [23:13:01] : [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 at slave(684)@172.16.10.213:45407
> (ip-172-16-10-213.mesosphere.io)
> [23:13:01] : [Step 11/11] I1219 23:13:01.753437 25730 master.cpp:5834]
> Forwarding 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
> [23:13:01] : [Step 11/11] I1219 23:13:01.753484 25730 master.cpp:7871]
> Updating the state of task 255e31f0-a34f-4560-beb8-ff120c315d24 of framework
> c590a129-814c-4903-9681-e16da4da4c94-0000 (latest state: TASK_FAILED, status
> update state: TASK_FAILED)
> [23:13:01] : [Step 11/11] I1219 23:13:01.753600 25729 sched.cpp:1031]
> Scheduler::statusUpdate took 58620ns
> [23:13:01] : [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-e16da4da4c94-0000 (default) at
> scheduler-f456ebc6-14e6-4a87-b6df-a9b53a01d554@172.16.10.213:45407 on agent
> c590a129-814c-4903-9681-e16da4da4c94-S0
> [23:13:01] : [Step 11/11] I1219 23:13:01.753733 25731
> hierarchical.cpp:1024] Recovered cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000], allocated: {}) on agent
> c590a129-814c-4903-9681-e16da4da4c94-S0 from framework
> c590a129-814c-4903-9681-e16da4da4c94-0000
> [23:13:01] : [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-e16da4da4c94-S0 at slave(684)@172.16.10.213:45407
> (ip-172-16-10-213.mesosphere.io)
> [23:13:01] : [Step 11/11] ../../src/tests/container_logger_tests.cpp:692:
> Failure
> [23:13:01] : [Step 11/11] Value of: statusRunning.get().state()
> [23:13:01] : [Step 11/11] Actual: TASK_FAILED
> [23:13:01] : [Step 11/11] Expected: TASK_RUNNING
> [23:13:01] : [Step 11/11] I1219 23:13:01.753944 25726
> status_update_manager.cpp:395] Received status update acknowledgement (UUID:
> e64c0c36-291c-451e-91c0-d9615b4b49be) for task
> 255e31f0-a34f-4560-beb8-ff120c315d24 of framework
> c590a129-814c-4903-9681-e16da4da4c94-0000
> [23:13:01] : [Step 11/11] I1219 23:13:01.753983 25726
> status_update_manager.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] : [Step 11/11] I1219 23:13:01.754051 25726 slave.cpp:3028]
> Status update manager successfully handled status update acknowledgement
> (UUID: e64c0c36-291c-451e-91c0-d9615b4b49be) for task
> 255e31f0-a34f-4560-beb8-ff120c315d24 of framework
> c590a129-814c-4903-9681-e16da4da4c94-0000
> [23:13:01] : [Step 11/11] I1219 23:13:01.754065 25726 slave.cpp:6704]
> Completing task 255e31f0-a34f-4560-beb8-ff120c315d24
> [23:13:01] : [Step 11/11] I1219 23:13:01.754070 25726 slave.cpp:4772]
> Cleaning up executor '255e31f0-a34f-4560-beb8-ff120c315d24' of framework
> c590a129-814c-4903-9681-e16da4da4c94-0000
> [23:13:01] : [Step 11/11] I1219 23:13:01.754171 25731 gc.cpp:55] Scheduling
> '/mnt/teamcity/temp/buildTmp/bool_UserContainerLoggerTest_ROOT_LOGROTATE_RotateWithSwitchUserTrueOrFalse_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'
> for gc 6.9999912717837days in the future
> [23:13:01] : [Step 11/11] I1219 23:13:01.754189 25726 slave.cpp:4860]
> Cleaning up framework c590a129-814c-4903-9681-e16da4da4c94-0000
> [23:13:01] : [Step 11/11] I1219 23:13:01.754225 25731 gc.cpp:55] Scheduling
> '/mnt/teamcity/temp/buildTmp/bool_UserContainerLoggerTest_ROOT_LOGROTATE_RotateWithSwitchUserTrueOrFalse_0_Ea40f6/slaves/c590a129-814c-4903-9681-e16da4da4c94-S0/frameworks/c590a129-814c-4903-9681-e16da4da4c94-0000/executors/255e31f0-a34f-4560-beb8-ff120c315d24'
> for gc 6.99999127115852days in the future
> [23:13:01] : [Step 11/11] I1219 23:13:01.754243 25729
> status_update_manager.cpp:285] Closing status update streams for framework
> c590a129-814c-4903-9681-e16da4da4c94-0000
> [23:13:01] : [Step 11/11] I1219 23:13:01.754259 25731 gc.cpp:55] Scheduling
> '/mnt/teamcity/temp/buildTmp/bool_UserContainerLoggerTest_ROOT_LOGROTATE_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] : [Step 11/11] I1219 23:13:02.655233 25727
> hierarchical.cpp:1785] No inverse offers to send out!
> [23:13:02] : [Step 11/11] I1219 23:13:02.655295 25727
> hierarchical.cpp:1292] Performed allocation for 1 agents in 319498ns
> [23:13:02] : [Step 11/11] I1219 23:13:02.655410 25728 master.cpp:6580]
> Sending 1 offers to framework c590a129-814c-4903-9681-e16da4da4c94-0000
> (default) at
> scheduler-f456ebc6-14e6-4a87-b6df-a9b53a01d554@172.16.10.213:45407
> [23:13:02] : [Step 11/11] I1219 23:13:02.655586 25728 sched.cpp:923]
> Scheduler::resourceOffers took 14921ns
> [23:13:03] : [Step 11/11] I1219 23:13:03.656186 25733
> hierarchical.cpp:1690] No allocations performed
> [23:13:03] : [Step 11/11] I1219 23:13:03.656234 25733
> hierarchical.cpp:1785] No inverse offers to send out!
> [23:13:03] : [Step 11/11] I1219 23:13:03.656252 25733
> hierarchical.cpp:1292] Performed allocation for 1 agents in 283333ns
> [23:13:04] : [Step 11/11] I1219 23:13:04.656954 25727
> hierarchical.cpp:1690] No allocations performed
> [23:13:04] : [Step 11/11] I1219 23:13:04.656990 25727
> hierarchical.cpp:1785] No inverse offers to send out!
> [23:13:04] : [Step 11/11] I1219 23:13:04.657006 25727
> hierarchical.cpp:1292] Performed allocation for 1 agents in 129708ns
> [23:13:05] : [Step 11/11] I1219 23:13:05.657685 25726
> hierarchical.cpp:1690] No allocations performed
> [23:13:05] : [Step 11/11] I1219 23:13:05.657721 25726
> hierarchical.cpp:1785] No inverse offers to send out!
> [23:13:05] : [Step 11/11] I1219 23:13:05.657737 25726
> hierarchical.cpp:1292] Performed allocation for 1 agents in 129877ns
> [23:13:06] : [Step 11/11] I1219 23:13:06.658830 25728
> hierarchical.cpp:1690] No allocations performed
> [23:13:06] : [Step 11/11] I1219 23:13:06.658865 25728
> hierarchical.cpp:1785] No inverse offers to send out!
> [23:13:06] : [Step 11/11] I1219 23:13:06.658884 25728
> hierarchical.cpp:1292] Performed allocation for 1 agents in 143178ns
> [23:13:07] : [Step 11/11] I1219 23:13:07.659719 25731
> hierarchical.cpp:1690] No allocations performed
> [23:13:07] : [Step 11/11] I1219 23:13:07.659754 25731
> hierarchical.cpp:1785] No inverse offers to send out!
> [23:13:07] : [Step 11/11] I1219 23:13:07.659771 25731
> hierarchical.cpp:1292] Performed allocation for 1 agents in 141527ns
> [23:13:08] : [Step 11/11] I1219 23:13:08.660782 25727
> hierarchical.cpp:1690] No allocations performed
> [23:13:08] : [Step 11/11] I1219 23:13:08.660823 25727
> hierarchical.cpp:1785] No inverse offers to send out!
> [23:13:08] : [Step 11/11] I1219 23:13:08.660841 25727
> hierarchical.cpp:1292] Performed allocation for 1 agents in 158649ns
> [23:13:09] : [Step 11/11] I1219 23:13:09.661458 25729
> hierarchical.cpp:1690] No allocations performed
> [23:13:09] : [Step 11/11] I1219 23:13:09.661495 25729
> hierarchical.cpp:1785] No inverse offers to send out!
> [23:13:09] : [Step 11/11] I1219 23:13:09.661512 25729
> hierarchical.cpp:1292] Performed allocation for 1 agents in 134970ns
> [23:13:10] : [Step 11/11] I1219 23:13:10.662621 25732
> hierarchical.cpp:1690] No allocations performed
> [23:13:10] : [Step 11/11] I1219 23:13:10.662655 25732
> hierarchical.cpp:1785] No inverse offers to send out!
> [23:13:10] : [Step 11/11] I1219 23:13:10.662673 25732
> hierarchical.cpp:1292] Performed allocation for 1 agents in 144999ns
> [23:13:11] : [Step 11/11] I1219 23:13:11.663347 25733
> hierarchical.cpp:1690] No allocations performed
> [23:13:11] : [Step 11/11] I1219 23:13:11.663380 25733
> hierarchical.cpp:1785] No inverse offers to send out!
> [23:13:11] : [Step 11/11] I1219 23:13:11.663398 25733
> hierarchical.cpp:1292] Performed allocation for 1 agents in 130561ns
> [23:13:12] : [Step 11/11] I1219 23:13:12.663929 25726
> hierarchical.cpp:1690] No allocations performed
> [23:13:12] : [Step 11/11] I1219 23:13:12.663964 25726
> hierarchical.cpp:1785] No inverse offers to send out!
> [23:13:12] : [Step 11/11] I1219 23:13:12.663982 25726
> hierarchical.cpp:1292] Performed allocation for 1 agents in 134957ns
> [23:13:13] : [Step 11/11] I1219 23:13:13.664721 25728
> hierarchical.cpp:1690] No allocations performed
> [23:13:13] : [Step 11/11] I1219 23:13:13.664757 25728
> hierarchical.cpp:1785] No inverse offers to send out!
> [23:13:13] : [Step 11/11] I1219 23:13:13.664773 25728
> hierarchical.cpp:1292] Performed allocation for 1 agents in 133416ns
> [23:13:14] : [Step 11/11] I1219 23:13:14.666043 25727
> hierarchical.cpp:1690] No allocations performed
> [23:13:14] : [Step 11/11] I1219 23:13:14.666080 25727
> hierarchical.cpp:1785] No inverse offers to send out!
> [23:13:14] : [Step 11/11] I1219 23:13:14.666098 25727
> hierarchical.cpp:1292] Performed allocation for 1 agents in 134466ns
> [23:13:15] : [Step 11/11] I1219 23:13:15.666527 25731
> hierarchical.cpp:1690] No allocations performed
> [23:13:15] : [Step 11/11] I1219 23:13:15.666563 25731
> hierarchical.cpp:1785] No inverse offers to send out!
> [23:13:15] : [Step 11/11] I1219 23:13:15.666581 25731
> hierarchical.cpp:1292] Performed allocation for 1 agents in 141096ns
> [23:13:16] : [Step 11/11] I1219 23:13:16.667453 25732
> hierarchical.cpp:1690] No allocations performed
> [23:13:16] : [Step 11/11] I1219 23:13:16.667487 25732
> hierarchical.cpp:1785] No inverse offers to send out!
> [23:13:16] : [Step 11/11] I1219 23:13:16.667505 25732
> hierarchical.cpp:1292] Performed allocation for 1 agents in 135350ns
> [23:13:16] : [Step 11/11] I1219 23:13:16.672703 25730 slave.cpp:5581]
> Querying resource estimator for oversubscribable resources
> [23:13:16] : [Step 11/11] I1219 23:13:16.672827 25733 slave.cpp:5595]
> Received oversubscribable resources {} from the resource estimator
> [23:13:16] : [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] : [Step 11/11] ../../src/tests/container_logger_tests.cpp:694:
> Failure
> [23:13:16] : [Step 11/11] Failed to wait 15secs for statusFinished
> [23:13:16] : [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] : [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] : [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] : [Step 11/11] ../../src/tests/container_logger_tests.cpp:684:
> Failure
> [23:13:16] : [Step 11/11] Actual function call count doesn't match
> EXPECT_CALL(sched, statusUpdate(&driver, _))...
> [23:13:16] : [Step 11/11] Expected: to be called at least twice
> [23:13:16] : [Step 11/11] I Actual: called once - unsatisfied and
> active
> [23:13:16] : [Step 11/11] 1219 23:13:16.755024 25733 hierarchical.cpp:392]
> Deactivated framework c590a129-814c-4903-9681-e16da4da4c94-0000
> [23:13:16] : [Step 11/11] W1219 23:13:16.755056 25726 master.hpp:2313]
> Master attempted to send message to disconnected framework
> c590a129-814c-4903-9681-e16da4da4c94-0000 (default) at
> scheduler-f456ebc6-14e6-4a87-b6df-a9b53a01d554@172.16.10.213:45407
> [23:13:16] : [Step 11/11] I1219 23:13:16.755115 25726 master.cpp:1318]
> Giving framework c590a129-814c-4903-9681-e16da4da4c94-0000 (default) at
> scheduler-f456ebc6-14e6-4a87-b6df-a9b53a01d554@172.16.10.213:45407 0ns to
> failover
> [23:13:16] : [Step 11/11] I1219 23:13:16.755229 25728 master.cpp:6432]
> Framework failover timeout, removing framework
> c590a129-814c-4903-9681-e16da4da4c94-0000 (default) at
> scheduler-f456ebc6-14e6-4a87-b6df-a9b53a01d554@172.16.10.213:45407
> [23:13:16] : [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] : [Step 11/11] I1219 23:13:16.755247 25733
> hierarchical.cpp:1024] Recovered cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000], allocated: {}) on agent
> c590a129-814c-4903-9681-e16da4da4c94-S0 from framework
> c590a129-814c-4903-9681-e16da4da4c94-0000
> [23:13:16] : [Step 11/11] I1219 23:13:16.755383 25732 slave.cpp:2581] Asked
> to shut down framework c590a129-814c-4903-9681-e16da4da4c94-0000 by
> master@172.16.10.213:45407
> [23:13:16] : [Step 11/11] I1219 23:13:16.755400 25732 slave.cpp:2596]
> Cannot shut down unknown framework c590a129-814c-4903-9681-e16da4da4c94-0000
> [23:13:16] : [Step 11/11] I1219 23:13:16.755512 25729 hierarchical.cpp:343]
> Removed framework c590a129-814c-4903-9681-e16da4da4c94-0000
> [23:13:16] : [Step 11/11] I1219 23:13:16.755718 25727 slave.cpp:796] Agent
> terminating
> [23:13:16] : [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] : [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] : [Step 11/11] I1219 23:13:16.755841 25727 master.cpp:2997]
> Deactivating 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] : [Step 11/11] I1219 23:13:16.755882 25727 hierarchical.cpp:590]
> Agent c590a129-814c-4903-9681-e16da4da4c94-S0 deactivated
> [23:13:16] : [Step 11/11] I1219 23:13:16.757964 25712 master.cpp:1097]
> Master terminating
> [23:13:16] : [Step 11/11] I1219 23:13:16.758131 25726 hierarchical.cpp:523]
> Removed agent c590a129-814c-4903-9681-e16da4da4c94-S0
> [23:13:16] : [Step 11/11] [ FAILED ]
> bool/UserContainerLoggerTest.ROOT_LOGROTATE_RotateWithSwitchUserTrueOrFalse/0,
> where GetParam() = true (15107 ms)
> Build failed on step #11: Run tests 1
> bool/UserContainerLoggerTest.ROOT_LOGROTATE_RotateWithSwitchUserTrueOrFalse/0,
> OK OK
> cmake OK Build failed on step #8: Make check without running
> tests OK Build failed on step #8: Make check without
> running tests Build failed on step #8: Make check without
> running tests
> NWI Build failed on step #11: Run tests
> PortMappingIsolatorTest.ROOT_DNS
> PortMappingIsolatorTest.ROOT_ContainerICMPExternal
> PortMappingIsolatorTest.ROOT_NC_HostToContainerUDP
> build succeeded and all tests passed
> # build succeeded, but # of tests failed
> build succeeded, but the test suite did not finish
> step build step failed
> system error
> GTEST_FILTER:
> {code}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
