Gilbert Song created MESOS-5671:
-----------------------------------
Summary: MemoryPressureMesosTest.CGROUPS_ROOT_Statistics is flaky.
Key: MESOS-5671
URL: https://issues.apache.org/jira/browse/MESOS-5671
Project: Mesos
Issue Type: Bug
Components: cgroups, tests
Environment: CentOS 6 with SSL enabled
Reporter: Gilbert Song
Assignee: Gilbert Song
{noformat}
[00:48:29] : [Step 10/10] [ RUN ]
MemoryPressureMesosTest.CGROUPS_ROOT_Statistics
[00:48:29]W: [Step 10/10] 1+0 records in
[00:48:29]W: [Step 10/10] 1+0 records out
[00:48:29]W: [Step 10/10] 1048576 bytes (1.0 MB) copied, 0.000517638 s, 2.0
GB/s
[00:48:30]W: [Step 10/10] I0617 00:48:30.000998 25413 cluster.cpp:155]
Creating default 'local' authorizer
[00:48:30]W: [Step 10/10] I0617 00:48:30.020459 25413 leveldb.cpp:174]
Opened db in 19.338463ms
[00:48:30]W: [Step 10/10] I0617 00:48:30.022897 25413 leveldb.cpp:181]
Compacted db in 2.416906ms
[00:48:30]W: [Step 10/10] I0617 00:48:30.022919 25413 leveldb.cpp:196]
Created db iterator in 4037ns
[00:48:30]W: [Step 10/10] I0617 00:48:30.022927 25413 leveldb.cpp:202]
Seeked to beginning of db in 769ns
[00:48:30]W: [Step 10/10] I0617 00:48:30.022932 25413 leveldb.cpp:271]
Iterated through 0 keys in the db in 390ns
[00:48:30]W: [Step 10/10] I0617 00:48:30.022944 25413 replica.cpp:779]
Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
[00:48:30]W: [Step 10/10] I0617 00:48:30.023272 25432 recover.cpp:451]
Starting replica recovery
[00:48:30]W: [Step 10/10] I0617 00:48:30.023425 25434 recover.cpp:477]
Replica is in EMPTY status
[00:48:30]W: [Step 10/10] I0617 00:48:30.023748 25434 replica.cpp:673]
Replica in EMPTY status received a broadcasted recover request from
(19361)@172.30.2.56:53790
[00:48:30]W: [Step 10/10] I0617 00:48:30.023849 25429 recover.cpp:197]
Received a recover response from a replica in EMPTY status
[00:48:30]W: [Step 10/10] I0617 00:48:30.024019 25435 recover.cpp:568]
Updating replica status to STARTING
[00:48:30]W: [Step 10/10] I0617 00:48:30.024338 25432 master.cpp:382]
Master 0e92ffa4-4f26-4cea-84d3-9c67612de1bd (ip-172-30-2-56.mesosphere.io)
started on 172.30.2.56:53790
[00:48:30]W: [Step 10/10] I0617 00:48:30.024348 25432 master.cpp:384] 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="true"
--authenticate_http_frameworks="true" --authenticators="crammd5"
--authorizers="local" --credentials="/tmp/jBjY5p/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="replicated_log" --registry_fetch_timeout="1mins"
--registry_store_timeout="100secs" --registry_strict="true"
--root_submissions="true" --user_sorter="drf" --version="false"
--webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/jBjY5p/master"
--zk_session_timeout="10secs"
[00:48:30]W: [Step 10/10] I0617 00:48:30.024502 25432 master.cpp:434]
Master only allowing authenticated frameworks to register
[00:48:30]W: [Step 10/10] I0617 00:48:30.024508 25432 master.cpp:448]
Master only allowing authenticated agents to register
[00:48:30]W: [Step 10/10] I0617 00:48:30.024513 25432 master.cpp:461]
Master only allowing authenticated HTTP frameworks to register
[00:48:30]W: [Step 10/10] I0617 00:48:30.024516 25432 credentials.hpp:37]
Loading credentials for authentication from '/tmp/jBjY5p/credentials'
[00:48:30]W: [Step 10/10] I0617 00:48:30.024603 25432 master.cpp:506] Using
default 'crammd5' authenticator
[00:48:30]W: [Step 10/10] I0617 00:48:30.024644 25432 master.cpp:578] Using
default 'basic' HTTP authenticator
[00:48:30]W: [Step 10/10] I0617 00:48:30.024701 25432 master.cpp:658] Using
default 'basic' HTTP framework authenticator
[00:48:30]W: [Step 10/10] I0617 00:48:30.024770 25432 master.cpp:705]
Authorization enabled
[00:48:30]W: [Step 10/10] I0617 00:48:30.024883 25435
whitelist_watcher.cpp:77] No whitelist given
[00:48:30]W: [Step 10/10] I0617 00:48:30.024885 25434 hierarchical.cpp:142]
Initialized hierarchical allocator process
[00:48:30]W: [Step 10/10] I0617 00:48:30.025539 25433 master.cpp:1969] The
newly elected leader is [email protected]:53790 with id
0e92ffa4-4f26-4cea-84d3-9c67612de1bd
[00:48:30]W: [Step 10/10] I0617 00:48:30.025555 25433 master.cpp:1982]
Elected as the leading master!
[00:48:30]W: [Step 10/10] I0617 00:48:30.025560 25433 master.cpp:1669]
Recovering from registrar
[00:48:30]W: [Step 10/10] I0617 00:48:30.025611 25432 registrar.cpp:332]
Recovering registrar
[00:48:30]W: [Step 10/10] I0617 00:48:30.026397 25431 leveldb.cpp:304]
Persisting metadata (8 bytes) to leveldb took 2.288187ms
[00:48:30]W: [Step 10/10] I0617 00:48:30.026438 25431 replica.cpp:320]
Persisted replica status to STARTING
[00:48:30]W: [Step 10/10] I0617 00:48:30.026486 25431 recover.cpp:477]
Replica is in STARTING status
[00:48:30]W: [Step 10/10] I0617 00:48:30.026793 25432 replica.cpp:673]
Replica in STARTING status received a broadcasted recover request from
(19364)@172.30.2.56:53790
[00:48:30]W: [Step 10/10] I0617 00:48:30.026897 25429 recover.cpp:197]
Received a recover response from a replica in STARTING status
[00:48:30]W: [Step 10/10] I0617 00:48:30.027031 25428 recover.cpp:568]
Updating replica status to VOTING
[00:48:30]W: [Step 10/10] I0617 00:48:30.028960 25432 leveldb.cpp:304]
Persisting metadata (8 bytes) to leveldb took 1.874668ms
[00:48:30]W: [Step 10/10] I0617 00:48:30.028975 25432 replica.cpp:320]
Persisted replica status to VOTING
[00:48:30]W: [Step 10/10] I0617 00:48:30.029007 25432 recover.cpp:582]
Successfully joined the Paxos group
[00:48:30]W: [Step 10/10] I0617 00:48:30.029047 25432 recover.cpp:466]
Recover process terminated
[00:48:30]W: [Step 10/10] I0617 00:48:30.029209 25430 log.cpp:553]
Attempting to start the writer
[00:48:30]W: [Step 10/10] I0617 00:48:30.029614 25429 replica.cpp:493]
Replica received implicit promise request from (19365)@172.30.2.56:53790 with
proposal 1
[00:48:30]W: [Step 10/10] I0617 00:48:30.031486 25429 leveldb.cpp:304]
Persisting metadata (8 bytes) to leveldb took 1.850474ms
[00:48:30]W: [Step 10/10] I0617 00:48:30.031502 25429 replica.cpp:342]
Persisted promised to 1
[00:48:30]W: [Step 10/10] I0617 00:48:30.031726 25431 coordinator.cpp:238]
Coordinator attempting to fill missing positions
[00:48:30]W: [Step 10/10] I0617 00:48:30.032245 25428 replica.cpp:388]
Replica received explicit promise request from (19366)@172.30.2.56:53790 for
position 0 with proposal 2
[00:48:30]W: [Step 10/10] I0617 00:48:30.034101 25428 leveldb.cpp:341]
Persisting action (8 bytes) to leveldb took 1.831441ms
[00:48:30]W: [Step 10/10] I0617 00:48:30.034117 25428 replica.cpp:712]
Persisted action at 0
[00:48:30]W: [Step 10/10] I0617 00:48:30.034561 25433 replica.cpp:537]
Replica received write request for position 0 from (19367)@172.30.2.56:53790
[00:48:30]W: [Step 10/10] I0617 00:48:30.034589 25433 leveldb.cpp:436]
Reading position from leveldb took 10586ns
[00:48:30]W: [Step 10/10] I0617 00:48:30.036419 25433 leveldb.cpp:341]
Persisting action (14 bytes) to leveldb took 1.817267ms
[00:48:30]W: [Step 10/10] I0617 00:48:30.036434 25433 replica.cpp:712]
Persisted action at 0
[00:48:30]W: [Step 10/10] I0617 00:48:30.036679 25429 replica.cpp:691]
Replica received learned notice for position 0 from @0.0.0.0:0
[00:48:30]W: [Step 10/10] I0617 00:48:30.038661 25429 leveldb.cpp:341]
Persisting action (16 bytes) to leveldb took 1.96521ms
[00:48:30]W: [Step 10/10] I0617 00:48:30.038677 25429 replica.cpp:712]
Persisted action at 0
[00:48:30]W: [Step 10/10] I0617 00:48:30.038682 25429 replica.cpp:697]
Replica learned NOP action at position 0
[00:48:30]W: [Step 10/10] I0617 00:48:30.038839 25435 log.cpp:569] Writer
started with ending position 0
[00:48:30]W: [Step 10/10] I0617 00:48:30.039198 25433 leveldb.cpp:436]
Reading position from leveldb took 10572ns
[00:48:30]W: [Step 10/10] I0617 00:48:30.039412 25433 registrar.cpp:365]
Successfully fetched the registry (0B) in 13.778944ms
[00:48:30]W: [Step 10/10] I0617 00:48:30.039448 25433 registrar.cpp:464]
Applied 1 operations in 4778ns; attempting to update the 'registry'
[00:48:30]W: [Step 10/10] I0617 00:48:30.039643 25428 log.cpp:577]
Attempting to append 205 bytes to the log
[00:48:30]W: [Step 10/10] I0617 00:48:30.039696 25432 coordinator.cpp:348]
Coordinator attempting to write APPEND action at position 1
[00:48:30]W: [Step 10/10] I0617 00:48:30.039945 25430 replica.cpp:537]
Replica received write request for position 1 from (19368)@172.30.2.56:53790
[00:48:30]W: [Step 10/10] I0617 00:48:30.041738 25430 leveldb.cpp:341]
Persisting action (224 bytes) to leveldb took 1.771112ms
[00:48:30]W: [Step 10/10] I0617 00:48:30.041754 25430 replica.cpp:712]
Persisted action at 1
[00:48:30]W: [Step 10/10] I0617 00:48:30.041977 25432 replica.cpp:691]
Replica received learned notice for position 1 from @0.0.0.0:0
[00:48:30]W: [Step 10/10] I0617 00:48:30.043805 25432 leveldb.cpp:341]
Persisting action (226 bytes) to leveldb took 1.810425ms
[00:48:30]W: [Step 10/10] I0617 00:48:30.043820 25432 replica.cpp:712]
Persisted action at 1
[00:48:30]W: [Step 10/10] I0617 00:48:30.043825 25432 replica.cpp:697]
Replica learned APPEND action at position 1
[00:48:30]W: [Step 10/10] I0617 00:48:30.044040 25430 registrar.cpp:509]
Successfully updated the 'registry' in 4.556032ms
[00:48:30]W: [Step 10/10] I0617 00:48:30.044100 25430 registrar.cpp:395]
Successfully recovered registrar
[00:48:30]W: [Step 10/10] I0617 00:48:30.044124 25428 log.cpp:596]
Attempting to truncate the log to 1
[00:48:30]W: [Step 10/10] I0617 00:48:30.044215 25431 coordinator.cpp:348]
Coordinator attempting to write TRUNCATE action at position 2
[00:48:30]W: [Step 10/10] I0617 00:48:30.044244 25430 master.cpp:1777]
Recovered 0 agents from the Registry (166B) ; allowing 10mins for agents to
re-register
[00:48:30]W: [Step 10/10] I0617 00:48:30.044317 25433 hierarchical.cpp:169]
Skipping recovery of hierarchical allocator: nothing to recover
[00:48:30]W: [Step 10/10] I0617 00:48:30.044497 25433 replica.cpp:537]
Replica received write request for position 2 from (19369)@172.30.2.56:53790
[00:48:30]W: [Step 10/10] I0617 00:48:30.046368 25433 leveldb.cpp:341]
Persisting action (16 bytes) to leveldb took 1.851883ms
[00:48:30]W: [Step 10/10] I0617 00:48:30.046383 25433 replica.cpp:712]
Persisted action at 2
[00:48:30]W: [Step 10/10] I0617 00:48:30.046583 25430 replica.cpp:691]
Replica received learned notice for position 2 from @0.0.0.0:0
[00:48:30]W: [Step 10/10] I0617 00:48:30.048426 25430 leveldb.cpp:341]
Persisting action (18 bytes) to leveldb took 1.821628ms
[00:48:30]W: [Step 10/10] I0617 00:48:30.048455 25430 leveldb.cpp:399]
Deleting ~1 keys from leveldb took 14283ns
[00:48:30]W: [Step 10/10] I0617 00:48:30.048463 25430 replica.cpp:712]
Persisted action at 2
[00:48:30]W: [Step 10/10] I0617 00:48:30.048468 25430 replica.cpp:697]
Replica learned TRUNCATE action at position 2
[00:48:30]W: [Step 10/10] I0617 00:48:30.055145 25413
containerizer.cpp:203] Using isolation: cgroups/mem,filesystem/posix,network/cni
[00:48:30]W: [Step 10/10] I0617 00:48:30.058349 25413
linux_launcher.cpp:101] Using /cgroup/freezer as the freezer hierarchy for the
Linux launcher
[00:48:30]W: [Step 10/10] I0617 00:48:30.069301 25413 cluster.cpp:432]
Creating default 'local' authorizer
[00:48:30]W: [Step 10/10] I0617 00:48:30.069707 25431 slave.cpp:203] Agent
started on 485)@172.30.2.56:53790
[00:48:30]W: [Step 10/10] I0617 00:48:30.069718 25431 slave.cpp:204] Flags
at startup: --acls="" --appc_simple_discovery_uri_prefix="http://";
--appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="true"
--authenticatee="crammd5" --authorizer="local"
--cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false"
--cgroups_hierarchy="/cgroup" --cgroups_limit_swap="false"
--cgroups_root="mesos_test_d7ff4961-cb6d-4d51-bb21-10129a5c5572"
--container_disk_watch_interval="15secs" --containerizers="mesos"
--credential="/mnt/teamcity/temp/buildTmp/MemoryPressureMesosTest_CGROUPS_ROOT_Statistics_AF5X0p/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="/tmp/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/MemoryPressureMesosTest_CGROUPS_ROOT_Statistics_AF5X0p/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/MemoryPressureMesosTest_CGROUPS_ROOT_Statistics_AF5X0p/http_credentials"
--image_provisioner_backend="copy" --initialize_driver_logging="true"
--isolation="cgroups/mem"
--launcher_dir="/mnt/teamcity/work/4240ba9ddd0997c3/build/src" --logbufsecs="0"
--logging_level="INFO" --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" --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/MemoryPressureMesosTest_CGROUPS_ROOT_Statistics_AF5X0p"
[00:48:30]W: [Step 10/10] I0617 00:48:30.069916 25431 credentials.hpp:86]
Loading credential for authentication from
'/mnt/teamcity/temp/buildTmp/MemoryPressureMesosTest_CGROUPS_ROOT_Statistics_AF5X0p/credential'
[00:48:30]W: [Step 10/10] I0617 00:48:30.069967 25431 slave.cpp:341] Agent
using credential for: test-principal
[00:48:30]W: [Step 10/10] I0617 00:48:30.069984 25431 credentials.hpp:37]
Loading credentials for authentication from
'/mnt/teamcity/temp/buildTmp/MemoryPressureMesosTest_CGROUPS_ROOT_Statistics_AF5X0p/http_credentials'
[00:48:30]W: [Step 10/10] I0617 00:48:30.070050 25431 slave.cpp:393] Using
default 'basic' HTTP authenticator
[00:48:30]W: [Step 10/10] I0617 00:48:30.070127 25431 resources.cpp:572]
Parsing resources as JSON failed:
cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]
[00:48:30]W: [Step 10/10] Trying semicolon-delimited string format instead
[00:48:30]W: [Step 10/10] I0617 00:48:30.070282 25431 slave.cpp:592] Agent
resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
[00:48:30]W: [Step 10/10] I0617 00:48:30.070309 25431 slave.cpp:600] Agent
attributes: [ ]
[00:48:30]W: [Step 10/10] I0617 00:48:30.070314 25431 slave.cpp:605] Agent
hostname: ip-172-30-2-56.mesosphere.io
[00:48:30]W: [Step 10/10] I0617 00:48:30.070484 25413 sched.cpp:224]
Version: 1.0.0
[00:48:30]W: [Step 10/10] I0617 00:48:30.070667 25433 sched.cpp:328] New
master detected at [email protected]:53790
[00:48:30]W: [Step 10/10] I0617 00:48:30.070711 25429 state.cpp:57]
Recovering state from
'/mnt/teamcity/temp/buildTmp/MemoryPressureMesosTest_CGROUPS_ROOT_Statistics_AF5X0p/meta'
[00:48:30]W: [Step 10/10] I0617 00:48:30.070749 25433 sched.cpp:394]
Authenticating with master [email protected]:53790
[00:48:30]W: [Step 10/10] I0617 00:48:30.070758 25433 sched.cpp:401] Using
default CRAM-MD5 authenticatee
[00:48:30]W: [Step 10/10] I0617 00:48:30.070793 25430
status_update_manager.cpp:200] Recovering status update manager
[00:48:30]W: [Step 10/10] I0617 00:48:30.070904 25432
authenticatee.cpp:121] Creating new client SASL connection
[00:48:30]W: [Step 10/10] I0617 00:48:30.070914 25430
containerizer.cpp:518] Recovering containerizer
[00:48:30]W: [Step 10/10] I0617 00:48:30.071049 25432 master.cpp:5943]
Authenticating [email protected]:53790
[00:48:30]W: [Step 10/10] I0617 00:48:30.071105 25428
authenticator.cpp:414] Starting authentication session for
crammd5_authenticatee(984)@172.30.2.56:53790
[00:48:30]W: [Step 10/10] I0617 00:48:30.071164 25434 authenticator.cpp:98]
Creating new server SASL connection
[00:48:30]W: [Step 10/10] I0617 00:48:30.071241 25434
authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
[00:48:30]W: [Step 10/10] I0617 00:48:30.071254 25434
authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
[00:48:30]W: [Step 10/10] I0617 00:48:30.071292 25434
authenticator.cpp:204] Received SASL authentication start
[00:48:30]W: [Step 10/10] I0617 00:48:30.071336 25434
authenticator.cpp:326] Authentication requires more steps
[00:48:30]W: [Step 10/10] I0617 00:48:30.071374 25434
authenticatee.cpp:259] Received SASL authentication step
[00:48:30]W: [Step 10/10] I0617 00:48:30.071553 25434
authenticator.cpp:232] Received SASL authentication step
[00:48:30]W: [Step 10/10] I0617 00:48:30.071574 25434 auxprop.cpp:107]
Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-56'
server FQDN: 'ip-172-30-2-56' SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
[00:48:30]W: [Step 10/10] I0617 00:48:30.071586 25434 auxprop.cpp:179]
Looking up auxiliary property '*userPassword'
[00:48:30]W: [Step 10/10] I0617 00:48:30.071594 25434 auxprop.cpp:179]
Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
[00:48:30]W: [Step 10/10] I0617 00:48:30.071604 25434 auxprop.cpp:107]
Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-56'
server FQDN: 'ip-172-30-2-56' SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
[00:48:30]W: [Step 10/10] I0617 00:48:30.071615 25434 auxprop.cpp:129]
Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
[00:48:30]W: [Step 10/10] I0617 00:48:30.071619 25434 auxprop.cpp:129]
Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID
== true
[00:48:30]W: [Step 10/10] I0617 00:48:30.071630 25434
authenticator.cpp:318] Authentication success
[00:48:30]W: [Step 10/10] I0617 00:48:30.071684 25428
authenticator.cpp:432] Authentication session cleanup for
crammd5_authenticatee(984)@172.30.2.56:53790
[00:48:30]W: [Step 10/10] I0617 00:48:30.071687 25431
authenticatee.cpp:299] Authentication success
[00:48:30]W: [Step 10/10] I0617 00:48:30.071704 25434 master.cpp:5973]
Successfully authenticated principal 'test-principal' at
[email protected]:53790
[00:48:30]W: [Step 10/10] I0617 00:48:30.071826 25431 sched.cpp:484]
Successfully authenticated with master [email protected]:53790
[00:48:30]W: [Step 10/10] I0617 00:48:30.071841 25431 sched.cpp:800]
Sending SUBSCRIBE call to [email protected]:53790
[00:48:30]W: [Step 10/10] I0617 00:48:30.071954 25431 sched.cpp:833] Will
retry registration in 731.385085ms if necessary
[00:48:30]W: [Step 10/10] I0617 00:48:30.071996 25434 master.cpp:2539]
Received SUBSCRIBE call for framework 'default' at
[email protected]:53790
[00:48:30]W: [Step 10/10] I0617 00:48:30.072013 25434 master.cpp:2008]
Authorizing framework principal 'test-principal' to receive offers for role '*'
[00:48:30]W: [Step 10/10] I0617 00:48:30.072180 25430 master.cpp:2615]
Subscribing framework default with checkpointing disabled and capabilities [ ]
[00:48:30]W: [Step 10/10] I0617 00:48:30.072305 25429 hierarchical.cpp:264]
Added framework 0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000
[00:48:30]W: [Step 10/10] I0617 00:48:30.072326 25429
hierarchical.cpp:1488] No allocations performed
[00:48:30]W: [Step 10/10] I0617 00:48:30.072335 25429
hierarchical.cpp:1583] No inverse offers to send out!
[00:48:30]W: [Step 10/10] I0617 00:48:30.072347 25429
hierarchical.cpp:1139] Performed allocation for 0 agents in 26673ns
[00:48:30]W: [Step 10/10] I0617 00:48:30.072351 25431 provisioner.cpp:253]
Provisioner recovery complete
[00:48:30]W: [Step 10/10] I0617 00:48:30.072371 25430 sched.cpp:723]
Framework registered with 0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000
[00:48:30]W: [Step 10/10] I0617 00:48:30.072403 25430 sched.cpp:737]
Scheduler::registered took 11852ns
[00:48:30]W: [Step 10/10] I0617 00:48:30.072587 25433 slave.cpp:4840]
Finished recovery
[00:48:30]W: [Step 10/10] I0617 00:48:30.072760 25433 slave.cpp:5012]
Querying resource estimator for oversubscribable resources
[00:48:30]W: [Step 10/10] I0617 00:48:30.072865 25431
status_update_manager.cpp:174] Pausing sending status updates
[00:48:30]W: [Step 10/10] I0617 00:48:30.072893 25432 slave.cpp:962] New
master detected at [email protected]:53790
[00:48:30]W: [Step 10/10] I0617 00:48:30.072906 25432 slave.cpp:1024]
Authenticating with master [email protected]:53790
[00:48:30]W: [Step 10/10] I0617 00:48:30.072917 25432 slave.cpp:1035] Using
default CRAM-MD5 authenticatee
[00:48:30]W: [Step 10/10] I0617 00:48:30.072948 25432 slave.cpp:997]
Detecting new master
[00:48:30]W: [Step 10/10] I0617 00:48:30.072976 25432 slave.cpp:5026]
Received oversubscribable resources from the resource estimator
[00:48:30]W: [Step 10/10] I0617 00:48:30.072974 25435
authenticatee.cpp:121] Creating new client SASL connection
[00:48:30]W: [Step 10/10] I0617 00:48:30.073099 25434 master.cpp:5943]
Authenticating slave(485)@172.30.2.56:53790
[00:48:30]W: [Step 10/10] I0617 00:48:30.073142 25434
authenticator.cpp:414] Starting authentication session for
crammd5_authenticatee(985)@172.30.2.56:53790
[00:48:30]W: [Step 10/10] I0617 00:48:30.073213 25431 authenticator.cpp:98]
Creating new server SASL connection
[00:48:30]W: [Step 10/10] I0617 00:48:30.073268 25431
authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
[00:48:30]W: [Step 10/10] I0617 00:48:30.073287 25431
authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
[00:48:30]W: [Step 10/10] I0617 00:48:30.073320 25431
authenticator.cpp:204] Received SASL authentication start
[00:48:30]W: [Step 10/10] I0617 00:48:30.073353 25431
authenticator.cpp:326] Authentication requires more steps
[00:48:30]W: [Step 10/10] I0617 00:48:30.073390 25431
authenticatee.cpp:259] Received SASL authentication step
[00:48:30]W: [Step 10/10] I0617 00:48:30.073444 25435
authenticator.cpp:232] Received SASL authentication step
[00:48:30]W: [Step 10/10] I0617 00:48:30.073460 25435 auxprop.cpp:107]
Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-56'
server FQDN: 'ip-172-30-2-56' SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
[00:48:30]W: [Step 10/10] I0617 00:48:30.073465 25435 auxprop.cpp:179]
Looking up auxiliary property '*userPassword'
[00:48:30]W: [Step 10/10] I0617 00:48:30.073472 25435 auxprop.cpp:179]
Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
[00:48:30]W: [Step 10/10] I0617 00:48:30.073477 25435 auxprop.cpp:107]
Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-56'
server FQDN: 'ip-172-30-2-56' SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
[00:48:30]W: [Step 10/10] I0617 00:48:30.073480 25435 auxprop.cpp:129]
Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
[00:48:30]W: [Step 10/10] I0617 00:48:30.073484 25435 auxprop.cpp:129]
Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID
== true
[00:48:30]W: [Step 10/10] I0617 00:48:30.073493 25435
authenticator.cpp:318] Authentication success
[00:48:30]W: [Step 10/10] I0617 00:48:30.073534 25431
authenticatee.cpp:299] Authentication success
[00:48:30]W: [Step 10/10] I0617 00:48:30.073561 25435 master.cpp:5973]
Successfully authenticated principal 'test-principal' at
slave(485)@172.30.2.56:53790
[00:48:30]W: [Step 10/10] I0617 00:48:30.073590 25433
authenticator.cpp:432] Authentication session cleanup for
crammd5_authenticatee(985)@172.30.2.56:53790
[00:48:30]W: [Step 10/10] I0617 00:48:30.073698 25431 slave.cpp:1103]
Successfully authenticated with master [email protected]:53790
[00:48:30]W: [Step 10/10] I0617 00:48:30.073742 25431 slave.cpp:1506] Will
retry registration in 17.704164ms if necessary
[00:48:30]W: [Step 10/10] I0617 00:48:30.073786 25434 master.cpp:4653]
Registering agent at slave(485)@172.30.2.56:53790
(ip-172-30-2-56.mesosphere.io) with id 0e92ffa4-4f26-4cea-84d3-9c67612de1bd-S0
[00:48:30]W: [Step 10/10] I0617 00:48:30.073874 25434 registrar.cpp:464]
Applied 1 operations in 9493ns; attempting to update the 'registry'
[00:48:30]W: [Step 10/10] I0617 00:48:30.074077 25430 log.cpp:577]
Attempting to append 390 bytes to the log
[00:48:30]W: [Step 10/10] I0617 00:48:30.074152 25432 coordinator.cpp:348]
Coordinator attempting to write APPEND action at position 3
[00:48:30]W: [Step 10/10] I0617 00:48:30.074385 25431 replica.cpp:537]
Replica received write request for position 3 from (19391)@172.30.2.56:53790
[00:48:30]W: [Step 10/10] I0617 00:48:30.076269 25431 leveldb.cpp:341]
Persisting action (409 bytes) to leveldb took 1.86243ms
[00:48:30]W: [Step 10/10] I0617 00:48:30.076284 25431 replica.cpp:712]
Persisted action at 3
[00:48:30]W: [Step 10/10] I0617 00:48:30.076551 25434 replica.cpp:691]
Replica received learned notice for position 3 from @0.0.0.0:0
[00:48:30]W: [Step 10/10] I0617 00:48:30.078383 25434 leveldb.cpp:341]
Persisting action (411 bytes) to leveldb took 1.815955ms
[00:48:30]W: [Step 10/10] I0617 00:48:30.078398 25434 replica.cpp:712]
Persisted action at 3
[00:48:30]W: [Step 10/10] I0617 00:48:30.078404 25434 replica.cpp:697]
Replica learned APPEND action at position 3
[00:48:30]W: [Step 10/10] I0617 00:48:30.078703 25432 registrar.cpp:509]
Successfully updated the 'registry' in 4.813056ms
[00:48:30]W: [Step 10/10] I0617 00:48:30.078745 25429 log.cpp:596]
Attempting to truncate the log to 3
[00:48:30]W: [Step 10/10] I0617 00:48:30.078806 25433 coordinator.cpp:348]
Coordinator attempting to write TRUNCATE action at position 4
[00:48:30]W: [Step 10/10] I0617 00:48:30.078909 25431 master.cpp:4721]
Registered agent 0e92ffa4-4f26-4cea-84d3-9c67612de1bd-S0 at
slave(485)@172.30.2.56:53790 (ip-172-30-2-56.mesosphere.io) with cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000]
[00:48:30]W: [Step 10/10] I0617 00:48:30.078928 25428 slave.cpp:3742]
Received ping from slave-observer(439)@172.30.2.56:53790
[00:48:30]W: [Step 10/10] I0617 00:48:30.078991 25430 hierarchical.cpp:473]
Added agent 0e92ffa4-4f26-4cea-84d3-9c67612de1bd-S0
(ip-172-30-2-56.mesosphere.io) with cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000] (allocated: )
[00:48:30]W: [Step 10/10] I0617 00:48:30.079001 25428 slave.cpp:1147]
Registered with master [email protected]:53790; given agent ID
0e92ffa4-4f26-4cea-84d3-9c67612de1bd-S0
[00:48:30]W: [Step 10/10] I0617 00:48:30.079020 25428 fetcher.cpp:86]
Clearing fetcher cache
[00:48:30]W: [Step 10/10] I0617 00:48:30.079093 25430
hierarchical.cpp:1583] No inverse offers to send out!
[00:48:30]W: [Step 10/10] I0617 00:48:30.079111 25430
hierarchical.cpp:1162] Performed allocation for agent
0e92ffa4-4f26-4cea-84d3-9c67612de1bd-S0 in 100093ns
[00:48:30]W: [Step 10/10] I0617 00:48:30.079150 25435 replica.cpp:537]
Replica received write request for position 4 from (19392)@172.30.2.56:53790
[00:48:30]W: [Step 10/10] I0617 00:48:30.079233 25429 master.cpp:5772]
Sending 1 offers to framework 0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000
(default) at [email protected]:53790
[00:48:30]W: [Step 10/10] I0617 00:48:30.079259 25434
status_update_manager.cpp:181] Resuming sending status updates
[00:48:30]W: [Step 10/10] I0617 00:48:30.079263 25428 slave.cpp:1170]
Checkpointing SlaveInfo to
'/mnt/teamcity/temp/buildTmp/MemoryPressureMesosTest_CGROUPS_ROOT_Statistics_AF5X0p/meta/slaves/0e92ffa4-4f26-4cea-84d3-9c67612de1bd-S0/slave.info'
[00:48:30]W: [Step 10/10] I0617 00:48:30.079396 25428 slave.cpp:1207]
Forwarding total oversubscribed resources
[00:48:30]W: [Step 10/10] I0617 00:48:30.079427 25429 sched.cpp:897]
Scheduler::resourceOffers took 25735ns
[00:48:30]W: [Step 10/10] I0617 00:48:30.079448 25428 master.cpp:5066]
Received update of agent 0e92ffa4-4f26-4cea-84d3-9c67612de1bd-S0 at
slave(485)@172.30.2.56:53790 (ip-172-30-2-56.mesosphere.io) with total
oversubscribed resources
[00:48:30]W: [Step 10/10] I0617 00:48:30.079608 25413 resources.cpp:572]
Parsing resources as JSON failed: cpus:1;mem:256;disk:1024
[00:48:30]W: [Step 10/10] Trying semicolon-delimited string format instead
[00:48:30]W: [Step 10/10] I0617 00:48:30.079612 25434 hierarchical.cpp:531]
Agent 0e92ffa4-4f26-4cea-84d3-9c67612de1bd-S0 (ip-172-30-2-56.mesosphere.io)
updated with oversubscribed resources (total: cpus(*):2; mem(*):1024;
disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024;
disk(*):1024; ports(*):[31000-32000])
[00:48:30]W: [Step 10/10] I0617 00:48:30.079645 25434
hierarchical.cpp:1488] No allocations performed
[00:48:30]W: [Step 10/10] I0617 00:48:30.079651 25434
hierarchical.cpp:1583] No inverse offers to send out!
[00:48:30]W: [Step 10/10] I0617 00:48:30.079660 25434
hierarchical.cpp:1162] Performed allocation for agent
0e92ffa4-4f26-4cea-84d3-9c67612de1bd-S0 in 26873ns
[00:48:30]W: [Step 10/10] I0617 00:48:30.079957 25428 master.cpp:3457]
Processing ACCEPT call for offers: [ 0e92ffa4-4f26-4cea-84d3-9c67612de1bd-O0 ]
on agent 0e92ffa4-4f26-4cea-84d3-9c67612de1bd-S0 at
slave(485)@172.30.2.56:53790 (ip-172-30-2-56.mesosphere.io) for framework
0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000 (default) at
[email protected]:53790
[00:48:30]W: [Step 10/10] I0617 00:48:30.079979 25428 master.cpp:3095]
Authorizing framework principal 'test-principal' to launch task
497f3d0f-ed77-4aef-9326-cf76c2dcbafb
[00:48:30]W: [Step 10/10] I0617 00:48:30.080334 25432 master.hpp:178]
Adding task 497f3d0f-ed77-4aef-9326-cf76c2dcbafb with resources cpus(*):1;
mem(*):256; disk(*):1024 on agent 0e92ffa4-4f26-4cea-84d3-9c67612de1bd-S0
(ip-172-30-2-56.mesosphere.io)
[00:48:30]W: [Step 10/10] I0617 00:48:30.080365 25432 master.cpp:3946]
Launching task 497f3d0f-ed77-4aef-9326-cf76c2dcbafb of framework
0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000 (default) at
[email protected]:53790 with resources
cpus(*):1; mem(*):256; disk(*):1024 on agent
0e92ffa4-4f26-4cea-84d3-9c67612de1bd-S0 at slave(485)@172.30.2.56:53790
(ip-172-30-2-56.mesosphere.io)
[00:48:30]W: [Step 10/10] I0617 00:48:30.080495 25429 hierarchical.cpp:891]
Recovered cpus(*):1; mem(*):768; ports(*):[31000-32000] (total: cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):1;
mem(*):256; disk(*):1024) on agent 0e92ffa4-4f26-4cea-84d3-9c67612de1bd-S0 from
framework 0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000
[00:48:30]W: [Step 10/10] I0617 00:48:30.080507 25428 slave.cpp:1546] Got
assigned task 497f3d0f-ed77-4aef-9326-cf76c2dcbafb for framework
0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000
[00:48:30]W: [Step 10/10] I0617 00:48:30.080528 25429 hierarchical.cpp:928]
Framework 0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000 filtered agent
0e92ffa4-4f26-4cea-84d3-9c67612de1bd-S0 for 5secs
[00:48:30]W: [Step 10/10] I0617 00:48:30.080602 25428 resources.cpp:572]
Parsing resources as JSON failed: cpus:0.1;mem:32
[00:48:30]W: [Step 10/10] Trying semicolon-delimited string format instead
[00:48:30]W: [Step 10/10] I0617 00:48:30.080718 25428 slave.cpp:1665]
Launching task 497f3d0f-ed77-4aef-9326-cf76c2dcbafb for framework
0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000
[00:48:30]W: [Step 10/10] I0617 00:48:30.080747 25428 resources.cpp:572]
Parsing resources as JSON failed: cpus:0.1;mem:32
[00:48:30]W: [Step 10/10] Trying semicolon-delimited string format instead
[00:48:30]W: [Step 10/10] I0617 00:48:30.081048 25428 paths.cpp:528] Trying
to chown
'/mnt/teamcity/temp/buildTmp/MemoryPressureMesosTest_CGROUPS_ROOT_Statistics_AF5X0p/slaves/0e92ffa4-4f26-4cea-84d3-9c67612de1bd-S0/frameworks/0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000/executors/497f3d0f-ed77-4aef-9326-cf76c2dcbafb/runs/9b1880d4-4b70-4eaf-b72e-cf207c4ee6b8'
to user 'root'
[00:48:30]W: [Step 10/10] I0617 00:48:30.082818 25435 leveldb.cpp:341]
Persisting action (16 bytes) to leveldb took 3.508394ms
[00:48:30]W: [Step 10/10] I0617 00:48:30.082859 25435 replica.cpp:712]
Persisted action at 4
[00:48:30]W: [Step 10/10] I0617 00:48:30.083400 25435 replica.cpp:691]
Replica received learned notice for position 4 from @0.0.0.0:0
[00:48:30]W: [Step 10/10] I0617 00:48:30.085247 25435 leveldb.cpp:341]
Persisting action (18 bytes) to leveldb took 1.827229ms
[00:48:30]W: [Step 10/10] I0617 00:48:30.085294 25435 leveldb.cpp:399]
Deleting ~2 keys from leveldb took 30113ns
[00:48:30]W: [Step 10/10] I0617 00:48:30.085304 25435 replica.cpp:712]
Persisted action at 4
[00:48:30]W: [Step 10/10] I0617 00:48:30.085310 25435 replica.cpp:697]
Replica learned TRUNCATE action at position 4
[00:48:30]W: [Step 10/10] I0617 00:48:30.085690 25428 slave.cpp:5729]
Launching executor 497f3d0f-ed77-4aef-9326-cf76c2dcbafb of framework
0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000 with resources cpus(*):0.1; mem(*):32
in work directory
'/mnt/teamcity/temp/buildTmp/MemoryPressureMesosTest_CGROUPS_ROOT_Statistics_AF5X0p/slaves/0e92ffa4-4f26-4cea-84d3-9c67612de1bd-S0/frameworks/0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000/executors/497f3d0f-ed77-4aef-9326-cf76c2dcbafb/runs/9b1880d4-4b70-4eaf-b72e-cf207c4ee6b8'
[00:48:30]W: [Step 10/10] I0617 00:48:30.085846 25428 slave.cpp:1891]
Queuing task '497f3d0f-ed77-4aef-9326-cf76c2dcbafb' for executor
'497f3d0f-ed77-4aef-9326-cf76c2dcbafb' of framework
0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000
[00:48:30]W: [Step 10/10] I0617 00:48:30.085849 25429
containerizer.cpp:777] Starting container
'9b1880d4-4b70-4eaf-b72e-cf207c4ee6b8' for executor
'497f3d0f-ed77-4aef-9326-cf76c2dcbafb' of framework
'0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000'
[00:48:30]W: [Step 10/10] I0617 00:48:30.085898 25428 slave.cpp:915]
Successfully attached file
'/mnt/teamcity/temp/buildTmp/MemoryPressureMesosTest_CGROUPS_ROOT_Statistics_AF5X0p/slaves/0e92ffa4-4f26-4cea-84d3-9c67612de1bd-S0/frameworks/0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000/executors/497f3d0f-ed77-4aef-9326-cf76c2dcbafb/runs/9b1880d4-4b70-4eaf-b72e-cf207c4ee6b8'
[00:48:30]W: [Step 10/10] I0617 00:48:30.087308 25428 mem.cpp:602] Started
listening for OOM events for container 9b1880d4-4b70-4eaf-b72e-cf207c4ee6b8
[00:48:30]W: [Step 10/10] I0617 00:48:30.087671 25428 mem.cpp:722] Started
listening on low memory pressure events for container
9b1880d4-4b70-4eaf-b72e-cf207c4ee6b8
[00:48:30]W: [Step 10/10] I0617 00:48:30.088007 25428 mem.cpp:722] Started
listening on medium memory pressure events for container
9b1880d4-4b70-4eaf-b72e-cf207c4ee6b8
[00:48:30]W: [Step 10/10] I0617 00:48:30.088412 25428 mem.cpp:722] Started
listening on critical memory pressure events for container
9b1880d4-4b70-4eaf-b72e-cf207c4ee6b8
[00:48:30]W: [Step 10/10] I0617 00:48:30.088750 25428 mem.cpp:353] Updated
'memory.soft_limit_in_bytes' to 288MB for container
9b1880d4-4b70-4eaf-b72e-cf207c4ee6b8
[00:48:30]W: [Step 10/10] I0617 00:48:30.089221 25428 mem.cpp:388] Updated
'memory.limit_in_bytes' to 288MB for container
9b1880d4-4b70-4eaf-b72e-cf207c4ee6b8
[00:48:30]W: [Step 10/10] I0617 00:48:30.089759 25430
containerizer.cpp:1271] Launching 'mesos-containerizer' with flags
'--command="{"shell":true,"value":"\/mnt\/teamcity\/work\/4240ba9ddd0997c3\/build\/src\/mesos-executor"}"
--commands="{"commands":[]}" --help="false" --pipe_read="110"
--pipe_write="111"
--sandbox="/mnt/teamcity/temp/buildTmp/MemoryPressureMesosTest_CGROUPS_ROOT_Statistics_AF5X0p/slaves/0e92ffa4-4f26-4cea-84d3-9c67612de1bd-S0/frameworks/0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000/executors/497f3d0f-ed77-4aef-9326-cf76c2dcbafb/runs/9b1880d4-4b70-4eaf-b72e-cf207c4ee6b8"
--user="root"'
[00:48:30]W: [Step 10/10] I0617 00:48:30.089825 25430
linux_launcher.cpp:281] Cloning child process with flags =
[00:48:30]W: [Step 10/10] WARNING: Logging before InitGoogleLogging() is
written to STDERR
[00:48:30]W: [Step 10/10] I0617 00:48:30.153952 10096 process.cpp:1060]
libprocess is initialized on 172.30.2.56:34658 with 8 worker threads
[00:48:30]W: [Step 10/10] I0617 00:48:30.156230 10096 logging.cpp:199]
Logging to STDERR
[00:48:30]W: [Step 10/10] I0617 00:48:30.157129 10096 exec.cpp:161]
Version: 1.0.0
[00:48:30]W: [Step 10/10] I0617 00:48:30.157197 10125 exec.cpp:211]
Executor started at: executor(1)@172.30.2.56:34658 with pid 10096
[00:48:30]W: [Step 10/10] I0617 00:48:30.157687 25431 slave.cpp:2879] Got
registration for executor '497f3d0f-ed77-4aef-9326-cf76c2dcbafb' of framework
0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000 from executor(1)@172.30.2.56:34658
[00:48:30]W: [Step 10/10] I0617 00:48:30.158280 10129 exec.cpp:236]
Executor registered on agent 0e92ffa4-4f26-4cea-84d3-9c67612de1bd-S0
[00:48:30]W: [Step 10/10] I0617 00:48:30.158689 25433 mem.cpp:353] Updated
'memory.soft_limit_in_bytes' to 288MB for container
9b1880d4-4b70-4eaf-b72e-cf207c4ee6b8
[00:48:30]W: [Step 10/10] I0617 00:48:30.159274 25435 slave.cpp:2056]
Sending queued task '497f3d0f-ed77-4aef-9326-cf76c2dcbafb' to executor
'497f3d0f-ed77-4aef-9326-cf76c2dcbafb' of framework
0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000 at executor(1)@172.30.2.56:34658
[00:48:30]W: [Step 10/10] I0617 00:48:30.159399 10129 exec.cpp:248]
Executor::registered took 64598ns
[00:48:30]W: [Step 10/10] I0617 00:48:30.159651 10128 exec.cpp:323]
Executor asked to run task '497f3d0f-ed77-4aef-9326-cf76c2dcbafb'
[00:48:30]W: [Step 10/10] I0617 00:48:30.159704 10128 exec.cpp:332]
Executor::launchTask took 30558ns
[00:48:30] : [Step 10/10] Received SUBSCRIBED event
[00:48:30] : [Step 10/10] Subscribed executor on
ip-172-30-2-56.mesosphere.io
[00:48:30] : [Step 10/10] Received LAUNCH event
[00:48:30] : [Step 10/10] Starting task 497f3d0f-ed77-4aef-9326-cf76c2dcbafb
[00:48:30] : [Step 10/10] sh -c 'while true; do dd count=512 bs=1M
if=/dev/zero of=./temp; done'
[00:48:30] : [Step 10/10] Forked command at 10134
[00:48:30]W: [Step 10/10] I0617 00:48:30.163949 10126 exec.cpp:546]
Executor sending status update TASK_RUNNING (UUID:
3e8d37f5-2ac4-4b5e-ba0a-83215b0eaae1) for task
497f3d0f-ed77-4aef-9326-cf76c2dcbafb of framework
0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000
[00:48:30]W: [Step 10/10] I0617 00:48:30.164324 25431 slave.cpp:3262]
Handling status update TASK_RUNNING (UUID:
3e8d37f5-2ac4-4b5e-ba0a-83215b0eaae1) for task
497f3d0f-ed77-4aef-9326-cf76c2dcbafb of framework
0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000 from executor(1)@172.30.2.56:34658
[00:48:30]W: [Step 10/10] I0617 00:48:30.164824 25428
status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID:
3e8d37f5-2ac4-4b5e-ba0a-83215b0eaae1) for task
497f3d0f-ed77-4aef-9326-cf76c2dcbafb of framework
0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000
[00:48:30]W: [Step 10/10] I0617 00:48:30.164849 25428
status_update_manager.cpp:497] Creating StatusUpdate stream for task
497f3d0f-ed77-4aef-9326-cf76c2dcbafb of framework
0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000
[00:48:30]W: [Step 10/10] I0617 00:48:30.165026 25428
status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID:
3e8d37f5-2ac4-4b5e-ba0a-83215b0eaae1) for task
497f3d0f-ed77-4aef-9326-cf76c2dcbafb of framework
0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000 to the agent
[00:48:30]W: [Step 10/10] I0617 00:48:30.165132 25433 slave.cpp:3660]
Forwarding the update TASK_RUNNING (UUID: 3e8d37f5-2ac4-4b5e-ba0a-83215b0eaae1)
for task 497f3d0f-ed77-4aef-9326-cf76c2dcbafb of framework
0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000 to [email protected]:53790
[00:48:30]W: [Step 10/10] I0617 00:48:30.165230 25433 slave.cpp:3554]
Status update manager successfully handled status update TASK_RUNNING (UUID:
3e8d37f5-2ac4-4b5e-ba0a-83215b0eaae1) for task
497f3d0f-ed77-4aef-9326-cf76c2dcbafb of framework
0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000
[00:48:30]W: [Step 10/10] I0617 00:48:30.165251 25433 slave.cpp:3570]
Sending acknowledgement for status update TASK_RUNNING (UUID:
3e8d37f5-2ac4-4b5e-ba0a-83215b0eaae1) for task
497f3d0f-ed77-4aef-9326-cf76c2dcbafb of framework
0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000 to executor(1)@172.30.2.56:34658
[00:48:30]W: [Step 10/10] I0617 00:48:30.165329 25430 master.cpp:5211]
Status update TASK_RUNNING (UUID: 3e8d37f5-2ac4-4b5e-ba0a-83215b0eaae1) for
task 497f3d0f-ed77-4aef-9326-cf76c2dcbafb of framework
0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000 from agent
0e92ffa4-4f26-4cea-84d3-9c67612de1bd-S0 at slave(485)@172.30.2.56:53790
(ip-172-30-2-56.mesosphere.io)
[00:48:30]W: [Step 10/10] I0617 00:48:30.165349 25430 master.cpp:5259]
Forwarding status update TASK_RUNNING (UUID:
3e8d37f5-2ac4-4b5e-ba0a-83215b0eaae1) for task
497f3d0f-ed77-4aef-9326-cf76c2dcbafb of framework
0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000
[00:48:30]W: [Step 10/10] I0617 00:48:30.165410 25430 master.cpp:6871]
Updating the state of task 497f3d0f-ed77-4aef-9326-cf76c2dcbafb of framework
0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000 (latest state: TASK_RUNNING, status
update state: TASK_RUNNING)
[00:48:30]W: [Step 10/10] I0617 00:48:30.165560 10128 exec.cpp:369]
Executor received status update acknowledgement
3e8d37f5-2ac4-4b5e-ba0a-83215b0eaae1 for task
497f3d0f-ed77-4aef-9326-cf76c2dcbafb of framework
0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000
[00:48:30]W: [Step 10/10] I0617 00:48:30.165628 25432 sched.cpp:1005]
Scheduler::statusUpdate took 78385ns
[00:48:30]W: [Step 10/10] I0617 00:48:30.165765 25432 master.cpp:4365]
Processing ACKNOWLEDGE call 3e8d37f5-2ac4-4b5e-ba0a-83215b0eaae1 for task
497f3d0f-ed77-4aef-9326-cf76c2dcbafb of framework
0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000 (default) at
[email protected]:53790 on agent
0e92ffa4-4f26-4cea-84d3-9c67612de1bd-S0
[00:48:30]W: [Step 10/10] I0617 00:48:30.165927 25428
status_update_manager.cpp:392] Received status update acknowledgement (UUID:
3e8d37f5-2ac4-4b5e-ba0a-83215b0eaae1) for task
497f3d0f-ed77-4aef-9326-cf76c2dcbafb of framework
0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000
[00:48:30]W: [Step 10/10] I0617 00:48:30.166052 25428 slave.cpp:2648]
Status update manager successfully handled status update acknowledgement (UUID:
3e8d37f5-2ac4-4b5e-ba0a-83215b0eaae1) for task
497f3d0f-ed77-4aef-9326-cf76c2dcbafb of framework
0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000
[00:48:30]W: [Step 10/10] I0617 00:48:30.583686 25428 master.cpp:4269]
Telling agent 0e92ffa4-4f26-4cea-84d3-9c67612de1bd-S0 at
slave(485)@172.30.2.56:53790 (ip-172-30-2-56.mesosphere.io) to kill task
497f3d0f-ed77-4aef-9326-cf76c2dcbafb of framework
0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000 (default) at
[email protected]:53790
[00:48:30]W: [Step 10/10] I0617 00:48:30.583760 25428 slave.cpp:2086] Asked
to kill task 497f3d0f-ed77-4aef-9326-cf76c2dcbafb of framework
0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000
[00:48:30]W: [Step 10/10] I0617 00:48:30.584074 10125 exec.cpp:343]
Executor asked to kill task '497f3d0f-ed77-4aef-9326-cf76c2dcbafb'
[00:48:30]W: [Step 10/10] I0617 00:48:30.584121 10125 exec.cpp:352]
Executor::killTask took 27333ns
[00:48:30]W: [Step 10/10] I0617 00:48:30.959868 25430 mem.cpp:625] OOM
notifier is triggered for container 9b1880d4-4b70-4eaf-b72e-cf207c4ee6b8
[00:48:30]W: [Step 10/10] I0617 00:48:30.959900 25430 mem.cpp:644] OOM
detected for container 9b1880d4-4b70-4eaf-b72e-cf207c4ee6b8
[00:48:30]W: [Step 10/10] I0617 00:48:30.960912 25430 mem.cpp:685] Memory
limit exceeded: Requested: 288MB Maximum Used: 288MB
[00:48:30]W: [Step 10/10]
[00:48:30]W: [Step 10/10] MEMORY STATISTICS:
[00:48:30]W: [Step 10/10] cache 297218048
[00:48:30]W: [Step 10/10] rss 4771840
[00:48:30]W: [Step 10/10] rss_huge 0
[00:48:30]W: [Step 10/10] mapped_file 0
[00:48:30]W: [Step 10/10] pgpgin 75849
[00:48:30]W: [Step 10/10] pgpgout 2121
[00:48:30]W: [Step 10/10] pgfault 19539
[00:48:30]W: [Step 10/10] pgmajfault 0
[00:48:30]W: [Step 10/10] inactive_anon 0
[00:48:30]W: [Step 10/10] active_anon 4771840
[00:48:30]W: [Step 10/10] inactive_file 296955904
[00:48:30]W: [Step 10/10] active_file 253952
[00:48:30]W: [Step 10/10] unevictable 0
[00:48:30]W: [Step 10/10] hierarchical_memory_limit 301989888
[00:48:30]W: [Step 10/10] total_cache 297218048
[00:48:30]W: [Step 10/10] total_rss 4771840
[00:48:30]W: [Step 10/10] total_rss_huge 0
[00:48:30]W: [Step 10/10] total_mapped_file 0
[00:48:30]W: [Step 10/10] total_pgpgin 75849
[00:48:30]W: [Step 10/10] total_pgpgout 2121
[00:48:30]W: [Step 10/10] total_pgfault 19539
[00:48:30]W: [Step 10/10] total_pgmajfault 0
[00:48:30]W: [Step 10/10] total_inactive_anon 0
[00:48:30]W: [Step 10/10] total_active_anon 4771840
[00:48:30]W: [Step 10/10] total_inactive_file 296873984
[00:48:30]W: [Step 10/10] total_active_file 253952
[00:48:30]W: [Step 10/10] total_unevictable 0
[00:48:30]W: [Step 10/10] I0617 00:48:30.961012 25430
containerizer.cpp:1833] Container 9b1880d4-4b70-4eaf-b72e-cf207c4ee6b8 has
reached its limit for resource mem(*):288 and will be terminated
[00:48:30]W: [Step 10/10] I0617 00:48:30.961050 25430
containerizer.cpp:1580] Destroying container
'9b1880d4-4b70-4eaf-b72e-cf207c4ee6b8'
[00:48:30]W: [Step 10/10] I0617 00:48:30.962447 25431 cgroups.cpp:2676]
Freezing cgroup
/cgroup/freezer/mesos_test_d7ff4961-cb6d-4d51-bb21-10129a5c5572/9b1880d4-4b70-4eaf-b72e-cf207c4ee6b8
[00:48:45] : [Step 10/10]
../../src/tests/containerizer/memory_pressure_tests.cpp:172: Failure
[00:48:45] : [Step 10/10] Failed to wait 15secs for killed
[00:48:45]W: [Step 10/10] I0617 00:48:45.585013 25429 master.cpp:1406]
Framework 0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000 (default) at
[email protected]:53790 disconnected
[00:48:45]W: [Step 10/10] I0617 00:48:45.585052 25429 master.cpp:2840]
Disconnecting framework 0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000 (default) at
[email protected]:53790
[00:48:45]W: [Step 10/10] I0617 00:48:45.585072 25429 master.cpp:2864]
Deactivating framework 0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000 (default) at
[email protected]:53790
[00:48:45]W: [Step 10/10] I0617 00:48:45.585110 25429 master.cpp:1419]
Giving framework 0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000 (default) at
[email protected]:53790 0ns to failover
[00:48:45]W: [Step 10/10] I0617 00:48:45.585193 25432 hierarchical.cpp:375]
Deactivated framework 0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000
[00:48:45]W: [Step 10/10] I0617 00:48:45.585247 25431 master.cpp:5624]
Framework failover timeout, removing framework
0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000 (default) at
[email protected]:53790
[00:48:45]W: [Step 10/10] I0617 00:48:45.585269 25431 master.cpp:6354]
Removing framework 0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000 (default) at
[email protected]:53790
[00:48:45]W: [Step 10/10] I0617 00:48:45.585325 25431 master.cpp:6871]
Updating the state of task 497f3d0f-ed77-4aef-9326-cf76c2dcbafb of framework
0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000 (latest state: TASK_KILLED, status
update state: TASK_KILLED)
[00:48:45]W: [Step 10/10] I0617 00:48:45.585352 25434 slave.cpp:2269] Asked
to shut down framework 0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000 by
[email protected]:53790
[00:48:45] : [Step 10/10]
../../src/tests/containerizer/memory_pressure_tests.cpp:128: Failure
[00:48:45]W: [Step 10/10] I0617 00:48:45.585373 25434 slave.cpp:2294]
Shutting down framework 0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000
[00:48:45] : [Step 10/10] Actual function call count doesn't match
EXPECT_CALL(sched, statusUpdate(&driver, _))...
[00:48:45] : [Step 10/10] Expected: to be called at least twice
[00:48:45]W: [Step 10/10] I0617 00:48:45.585387 25434 slave.cpp:4465]
Shutting down executor '497f3d0f-ed77-4aef-9326-cf76c2dcbafb' of framework
0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000 at executor(1)@172.30.2.56:34658
[00:48:45] : [Step 10/10] Actual: called once - unsatisfied and
active
[00:48:45]W: [Step 10/10] I0617 00:48:45.585476 25429 hierarchical.cpp:891]
Recovered cpus(*):1; mem(*):256; disk(*):1024 (total: cpus(*):2; mem(*):1024;
disk(*):1024; ports(*):[31000-32000], allocated: ) on agent
0e92ffa4-4f26-4cea-84d3-9c67612de1bd-S0 from framework
0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000
[00:48:45]W: [Step 10/10] I0617 00:48:45.585492 25431 master.cpp:6937]
Removing task 497f3d0f-ed77-4aef-9326-cf76c2dcbafb with resources cpus(*):1;
mem(*):256; disk(*):1024 of framework 0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000
on agent 0e92ffa4-4f26-4cea-84d3-9c67612de1bd-S0 at
slave(485)@172.30.2.56:53790 (ip-172-30-2-56.mesosphere.io)
[00:48:45]W: [Step 10/10] I0617 00:48:45.585698 25431 hierarchical.cpp:326]
Removed framework 0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000
[00:49:00] : [Step 10/10] ../../src/tests/cluster.cpp:551: Failure
[00:49:00] : [Step 10/10] Failed to wait 15secs for wait
[00:49:00]W: [Step 10/10] I0617 00:49:00.596581 25413 slave.cpp:834] Agent
terminating
[00:49:00]W: [Step 10/10] I0617 00:49:00.596611 25413 slave.cpp:2269] Asked
to shut down framework 0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000 by @0.0.0.0:0
[00:49:00]W: [Step 10/10] W0617 00:49:00.596624 25413 slave.cpp:2290]
Ignoring shutdown framework 0e92ffa4-4f26-4cea-84d3-9c67612de1bd-0000 because
it is terminating
[00:49:00]W: [Step 10/10] I0617 00:49:00.596742 25428 master.cpp:1367]
Agent 0e92ffa4-4f26-4cea-84d3-9c67612de1bd-S0 at slave(485)@172.30.2.56:53790
(ip-172-30-2-56.mesosphere.io) disconnected
[00:49:00]W: [Step 10/10] I0617 00:49:00.596761 25428 master.cpp:2899]
Disconnecting agent 0e92ffa4-4f26-4cea-84d3-9c67612de1bd-S0 at
slave(485)@172.30.2.56:53790 (ip-172-30-2-56.mesosphere.io)
[00:49:00]W: [Step 10/10] I0617 00:49:00.596807 25428 master.cpp:2918]
Deactivating agent 0e92ffa4-4f26-4cea-84d3-9c67612de1bd-S0 at
slave(485)@172.30.2.56:53790 (ip-172-30-2-56.mesosphere.io)
[00:49:00]W: [Step 10/10] I0617 00:49:00.596863 25428 hierarchical.cpp:560]
Agent 0e92ffa4-4f26-4cea-84d3-9c67612de1bd-S0 deactivated
[00:49:00]W: [Step 10/10] I0617 00:49:00.598708 25413 master.cpp:1214]
Master terminating
[00:49:00]W: [Step 10/10] I0617 00:49:00.598848 25431 hierarchical.cpp:505]
Removed agent 0e92ffa4-4f26-4cea-84d3-9c67612de1bd-S0
[00:49:00]W: [Step 10/10] I0617 00:49:00.601809 25433 cgroups.cpp:2676]
Freezing cgroup
/cgroup/freezer/mesos_test_d7ff4961-cb6d-4d51-bb21-10129a5c5572/9b1880d4-4b70-4eaf-b72e-cf207c4ee6b8
[00:49:00]W: [Step 10/10] I0617 00:49:00.602758 25434 cgroups.cpp:1409]
Successfully froze cgroup
/cgroup/freezer/mesos_test_d7ff4961-cb6d-4d51-bb21-10129a5c5572/9b1880d4-4b70-4eaf-b72e-cf207c4ee6b8
after 0ns
[00:49:00]W: [Step 10/10] I0617 00:49:00.603759 25431 cgroups.cpp:2694]
Thawing cgroup
/cgroup/freezer/mesos_test_d7ff4961-cb6d-4d51-bb21-10129a5c5572/9b1880d4-4b70-4eaf-b72e-cf207c4ee6b8
[00:49:00]W: [Step 10/10] I0617 00:49:00.604717 25433 cgroups.cpp:1438]
Successfully thawed cgroup
/cgroup/freezer/mesos_test_d7ff4961-cb6d-4d51-bb21-10129a5c5572/9b1880d4-4b70-4eaf-b72e-cf207c4ee6b8
after 0ns
[00:49:00]W: [Step 10/10] E0617 00:49:00.605662 25436 process.cpp:2050]
Failed to shutdown socket with fd 111: Transport endpoint is not connected
[00:49:15] : [Step 10/10] ../../src/tests/mesos.cpp:937: Failure
[00:49:15] : [Step 10/10] Failed to wait 15secs for
cgroups::destroy(hierarchy, cgroup)
[00:49:15] : [Step 10/10] [ FAILED ]
MemoryPressureMesosTest.CGROUPS_ROOT_Statistics (45618 ms)
{noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
