[
https://issues.apache.org/jira/browse/MESOS-6823?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15800734#comment-15800734
]
Benjamin Bannier commented on MESOS-6823:
-----------------------------------------
I believe the root cause here is twofold:
# if one runs {{make check}} as some user such as {{root}}, the default umask
on the system might lead to creation of needed executables which cannot be
executed by other users like e.g., {{nobody}}
# depending on user choices required binaries might be created in paths not
visible to some users such as {{nobody}} (think build directory somewhere under
{{/home/me}} or like here {{/root}}). Note that regardless on what we do with
permissions on e.g., Mesos build-controlled paths, the restrictive permissions
might be set on parent directories we (as Mesos build setup) wouldn't want to
touch directly.
I believe the Mesos build could be tweaked to deal with (1), but I have
difficulty seeing an exhaustive solution to (2).
Note that we have addressed these system setup issues in our internal CI so
that this particular tests now passes there.
We typically have avoided writing test which fork processes as others user due
to difficulties in making sure permissions are sufficient on the full path. I
find this especially unfortunate in the case of the containerizer where we have
literally zero tests for uses cases with {{ContainerLaunchInfo.user}} set to
anything. I believe it would be great to explore ways allowing us to add more
such tests instead of removing test code paths involving {{setuid}}. One
possibility might be to implement a specific {{TestFilter}} to ensure we run
such tests only in an environment not suffering from above problems.
> 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
> Labels: flaky, flaky-test, newbie
>
> 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
(v6.3.4#6332)
