[ 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)