mesos-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Anand Mazumdar (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (MESOS-5048) MesosContainerizerSlaveRecoveryTest.ResourceStatistics is flaky
Date Thu, 23 Jun 2016 16:03:16 GMT

    [ https://issues.apache.org/jira/browse/MESOS-5048?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15346665#comment-15346665
] 

Anand Mazumdar commented on MESOS-5048:
---------------------------------------

>From ASF CI

{code}
[ RUN      ] MesosContainerizerSlaveRecoveryTest.ResourceStatistics
I0623 15:32:22.710942 27298 cluster.cpp:155] Creating default 'local' authorizer
I0623 15:32:22.837335 27298 leveldb.cpp:174] Opened db in 125.927848ms
I0623 15:32:22.888108 27298 leveldb.cpp:181] Compacted db in 50.679183ms
I0623 15:32:22.888183 27298 leveldb.cpp:196] Created db iterator in 72310ns
I0623 15:32:22.888255 27298 leveldb.cpp:202] Seeked to beginning of db in 19469ns
I0623 15:32:22.888320 27298 leveldb.cpp:271] Iterated through 0 keys in the db in 17384ns
I0623 15:32:22.888425 27298 replica.cpp:779] Replica recovered with log positions 0 ->
0 with 1 holes and 0 unlearned
I0623 15:32:22.889354 27323 recover.cpp:451] Starting replica recovery
I0623 15:32:22.889649 27323 recover.cpp:477] Replica is in EMPTY status
I0623 15:32:22.890991 27323 replica.cpp:673] Replica in EMPTY status received a broadcasted
recover request from (13448)@172.17.0.3:52994
I0623 15:32:22.891391 27322 recover.cpp:197] Received a recover response from a replica in
EMPTY status
I0623 15:32:22.891698 27323 recover.cpp:568] Updating replica status to STARTING
I0623 15:32:22.892770 27321 master.cpp:382] Master 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5 (e59d5e9e8925)
started on 172.17.0.3:52994
I0623 15:32:22.892804 27321 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/11hAx2/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="/mesos/mesos-1.0.0/_inst/share/mesos/webui" --work_dir="/tmp/11hAx2/master"
--zk_session_timeout="10secs"
I0623 15:32:22.893110 27321 master.cpp:434] Master only allowing authenticated frameworks
to register
I0623 15:32:22.893123 27321 master.cpp:448] Master only allowing authenticated agents to register
I0623 15:32:22.893132 27321 master.cpp:461] Master only allowing authenticated HTTP frameworks
to register
I0623 15:32:22.893139 27321 credentials.hpp:37] Loading credentials for authentication from
'/tmp/11hAx2/credentials'
I0623 15:32:22.893389 27321 master.cpp:506] Using default 'crammd5' authenticator
I0623 15:32:22.893512 27321 master.cpp:578] Using default 'basic' HTTP authenticator
I0623 15:32:22.893654 27321 master.cpp:658] Using default 'basic' HTTP framework authenticator
I0623 15:32:22.893751 27321 master.cpp:705] Authorization enabled
I0623 15:32:22.893944 27330 hierarchical.cpp:142] Initialized hierarchical allocator process
I0623 15:32:22.893944 27317 whitelist_watcher.cpp:77] No whitelist given
I0623 15:32:22.896453 27317 master.cpp:1971] The newly elected leader is master@172.17.0.3:52994
with id 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5
I0623 15:32:22.896494 27317 master.cpp:1984] Elected as the leading master!
I0623 15:32:22.896512 27317 master.cpp:1671] Recovering from registrar
I0623 15:32:22.896677 27326 registrar.cpp:332] Recovering registrar
I0623 15:32:22.934186 27319 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took
42.403539ms
I0623 15:32:22.934264 27319 replica.cpp:320] Persisted replica status to STARTING
I0623 15:32:22.934563 27329 recover.cpp:477] Replica is in STARTING status
I0623 15:32:22.935645 27319 replica.cpp:673] Replica in STARTING status received a broadcasted
recover request from (13451)@172.17.0.3:52994
I0623 15:32:22.936084 27330 recover.cpp:197] Received a recover response from a replica in
STARTING status
I0623 15:32:22.936477 27319 recover.cpp:568] Updating replica status to VOTING
I0623 15:32:22.976192 27327 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took
39.586631ms
I0623 15:32:22.976263 27327 replica.cpp:320] Persisted replica status to VOTING
I0623 15:32:22.976524 27327 recover.cpp:582] Successfully joined the Paxos group
I0623 15:32:22.976842 27327 recover.cpp:466] Recover process terminated
I0623 15:32:22.977481 27327 log.cpp:553] Attempting to start the writer
I0623 15:32:22.978854 27327 replica.cpp:493] Replica received implicit promise request from
(13452)@172.17.0.3:52994 with proposal 1
I0623 15:32:23.020443 27327 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took
41.573214ms
I0623 15:32:23.020516 27327 replica.cpp:342] Persisted promised to 1
I0623 15:32:23.021294 27316 coordinator.cpp:238] Coordinator attempting to fill missing positions
I0623 15:32:23.022526 27331 replica.cpp:388] Replica received explicit promise request from
(13453)@172.17.0.3:52994 for position 0 with proposal 2
I0623 15:32:23.054338 27331 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 31.780979ms
I0623 15:32:23.054385 27331 replica.cpp:712] Persisted action at 0
I0623 15:32:23.055554 27329 replica.cpp:537] Replica received write request for position 0
from (13454)@172.17.0.3:52994
I0623 15:32:23.055620 27329 leveldb.cpp:436] Reading position from leveldb took 49202ns
I0623 15:32:23.079434 27329 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took
23.779706ms
I0623 15:32:23.079480 27329 replica.cpp:712] Persisted action at 0
I0623 15:32:23.080325 27318 replica.cpp:691] Replica received learned notice for position
0 from @0.0.0.0:0
I0623 15:32:23.096374 27318 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took
16.021877ms
I0623 15:32:23.096423 27318 replica.cpp:712] Persisted action at 0
I0623 15:32:23.096446 27318 replica.cpp:697] Replica learned NOP action at position 0
I0623 15:32:23.097120 27331 log.cpp:569] Writer started with ending position 0
I0623 15:32:23.098222 27327 leveldb.cpp:436] Reading position from leveldb took 52035ns
I0623 15:32:23.099272 27316 registrar.cpp:365] Successfully fetched the registry (0B) in 202.553088ms
I0623 15:32:23.099414 27316 registrar.cpp:464] Applied 1 operations in 47658ns; attempting
to update the 'registry'
I0623 15:32:23.100286 27317 log.cpp:577] Attempting to append 168 bytes to the log
I0623 15:32:23.100420 27323 coordinator.cpp:348] Coordinator attempting to write APPEND action
at position 1
I0623 15:32:23.102170 27320 replica.cpp:537] Replica received write request for position 1
from (13455)@172.17.0.3:52994
I0623 15:32:23.130511 27320 leveldb.cpp:341] Persisting action (187 bytes) to leveldb took
28.316188ms
I0623 15:32:23.130560 27320 replica.cpp:712] Persisted action at 1
I0623 15:32:23.131214 27327 replica.cpp:691] Replica received learned notice for position
1 from @0.0.0.0:0
I0623 15:32:23.164198 27327 leveldb.cpp:341] Persisting action (189 bytes) to leveldb took
32.955505ms
I0623 15:32:23.164229 27327 replica.cpp:712] Persisted action at 1
I0623 15:32:23.164247 27327 replica.cpp:697] Replica learned APPEND action at position 1
I0623 15:32:23.165186 27317 registrar.cpp:509] Successfully updated the 'registry' in 65.712128ms
I0623 15:32:23.165315 27317 registrar.cpp:395] Successfully recovered registrar
I0623 15:32:23.165390 27330 log.cpp:596] Attempting to truncate the log to 1
I0623 15:32:23.165491 27327 coordinator.cpp:348] Coordinator attempting to write TRUNCATE
action at position 2
I0623 15:32:23.165814 27331 master.cpp:1779] Recovered 0 agents from the Registry (129B) ;
allowing 10mins for agents to re-register
I0623 15:32:23.165920 27321 hierarchical.cpp:169] Skipping recovery of hierarchical allocator:
nothing to recover
I0623 15:32:23.166497 27321 replica.cpp:537] Replica received write request for position 2
from (13456)@172.17.0.3:52994
I0623 15:32:23.214545 27321 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took
48.029205ms
I0623 15:32:23.214622 27321 replica.cpp:712] Persisted action at 2
I0623 15:32:23.215384 27316 replica.cpp:691] Replica received learned notice for position
2 from @0.0.0.0:0
I0623 15:32:23.256412 27316 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took
41.021989ms
I0623 15:32:23.256556 27316 leveldb.cpp:399] Deleting ~1 keys from leveldb took 75829ns
I0623 15:32:23.256583 27316 replica.cpp:712] Persisted action at 2
I0623 15:32:23.256615 27316 replica.cpp:697] Replica learned TRUNCATE action at position 2
I0623 15:32:23.269613 27298 containerizer.cpp:201] Using isolation: posix/cpu,posix/mem,filesystem/posix,network/cni
W0623 15:32:23.270782 27298 backend.cpp:75] Failed to create 'aufs' backend: AufsBackend requires
root privileges, but is running as user mesos
W0623 15:32:23.271095 27298 backend.cpp:75] Failed to create 'bind' backend: BindBackend requires
root privileges
I0623 15:32:23.274850 27298 cluster.cpp:432] Creating default 'local' authorizer
I0623 15:32:23.276809 27323 slave.cpp:203] Agent started on 368)@172.17.0.3:52994
I0623 15:32:23.276846 27323 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="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs"
--containerizers="mesos" --credential="/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_x3jbsa/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="/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_x3jbsa/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="/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_x3jbsa/http_credentials"
--image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem"
--launcher_dir="/mesos/mesos-1.0.0/_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="/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_x3jbsa"
I0623 15:32:23.277407 27323 credentials.hpp:86] Loading credential for authentication from
'/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_x3jbsa/credential'
I0623 15:32:23.277590 27298 sched.cpp:224] Version: 1.0.0
I0623 15:32:23.279114 27317 sched.cpp:328] New master detected at master@172.17.0.3:52994
I0623 15:32:23.279227 27317 sched.cpp:394] Authenticating with master master@172.17.0.3:52994
I0623 15:32:23.279345 27317 sched.cpp:401] Using default CRAM-MD5 authenticatee
I0623 15:32:23.279646 27318 authenticatee.cpp:121] Creating new client SASL connection
I0623 15:32:23.280014 27317 master.cpp:5966] Authenticating scheduler-b6b07664-4f01-4bbb-898e-868aa0230f73@172.17.0.3:52994
I0623 15:32:23.280118 27318 authenticator.cpp:414] Starting authentication session for crammd5_authenticatee(770)@172.17.0.3:52994
I0623 15:32:23.280493 27326 authenticator.cpp:98] Creating new server SASL connection
I0623 15:32:23.280678 27318 authenticatee.cpp:213] Received SASL authentication mechanisms:
CRAM-MD5
I0623 15:32:23.280716 27318 authenticatee.cpp:239] Attempting to authenticate with mechanism
'CRAM-MD5'
I0623 15:32:23.280887 27318 authenticator.cpp:204] Received SASL authentication start
I0623 15:32:23.280961 27318 authenticator.cpp:326] Authentication requires more steps
I0623 15:32:23.281064 27326 authenticatee.cpp:259] Received SASL authentication step
I0623 15:32:23.281177 27318 authenticator.cpp:232] Received SASL authentication step
I0623 15:32:23.281365 27318 auxprop.cpp:107] Request to lookup properties for user: 'test-principal'
realm: 'e59d5e9e8925' server FQDN: 'e59d5e9e8925' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
I0623 15:32:23.281572 27318 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
I0623 15:32:23.281824 27318 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0623 15:32:23.282037 27318 auxprop.cpp:107] Request to lookup properties for user: 'test-principal'
realm: 'e59d5e9e8925' server FQDN: 'e59d5e9e8925' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
I0623 15:32:23.282202 27318 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since
SASL_AUXPROP_AUTHZID == true
I0623 15:32:23.282362 27318 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5'
since SASL_AUXPROP_AUTHZID == true
I0623 15:32:23.282537 27318 authenticator.cpp:318] Authentication success
I0623 15:32:23.282814 27331 authenticatee.cpp:299] Authentication success
I0623 15:32:23.282867 27318 master.cpp:5996] Successfully authenticated principal 'test-principal'
at scheduler-b6b07664-4f01-4bbb-898e-868aa0230f73@172.17.0.3:52994
I0623 15:32:23.282924 27331 authenticator.cpp:432] Authentication session cleanup for crammd5_authenticatee(770)@172.17.0.3:52994
I0623 15:32:23.283182 27318 sched.cpp:484] Successfully authenticated with master master@172.17.0.3:52994
I0623 15:32:23.283210 27318 sched.cpp:800] Sending SUBSCRIBE call to master@172.17.0.3:52994
I0623 15:32:23.283332 27318 sched.cpp:833] Will retry registration in 1.74726785secs if necessary
I0623 15:32:23.283458 27329 master.cpp:2548] Received SUBSCRIBE call for framework 'default'
at scheduler-b6b07664-4f01-4bbb-898e-868aa0230f73@172.17.0.3:52994
I0623 15:32:23.283484 27329 master.cpp:2010] Authorizing framework principal 'test-principal'
to receive offers for role '*'
I0623 15:32:23.283963 27329 master.cpp:2624] Subscribing framework default with checkpointing
enabled and capabilities [  ]
I0623 15:32:23.284487 27329 sched.cpp:723] Framework registered with 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-0000
I0623 15:32:23.284535 27329 sched.cpp:737] Scheduler::registered took 29039ns
I0623 15:32:23.284538 27316 hierarchical.cpp:268] Added framework 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-0000
I0623 15:32:23.284606 27316 hierarchical.cpp:1512] No allocations performed
I0623 15:32:23.284633 27316 hierarchical.cpp:1607] No inverse offers to send out!
I0623 15:32:23.284689 27316 hierarchical.cpp:1147] Performed allocation for 0 agents in 141681ns
I0623 15:32:23.290331 27323 slave.cpp:341] Agent using credential for: test-principal
I0623 15:32:23.290364 27323 credentials.hpp:37] Loading credentials for authentication from
'/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_x3jbsa/http_credentials'
I0623 15:32:23.290570 27323 slave.cpp:393] Using default 'basic' HTTP authenticator
I0623 15:32:23.290983 27323 resources.cpp:572] Parsing resources as JSON failed: cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]
Trying semicolon-delimited string format instead
I0623 15:32:23.291379 27323 slave.cpp:592] Agent resources: cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000]
I0623 15:32:23.291436 27323 slave.cpp:600] Agent attributes: [  ]
I0623 15:32:23.291448 27323 slave.cpp:605] Agent hostname: e59d5e9e8925
I0623 15:32:23.292748 27321 state.cpp:57] Recovering state from '/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_x3jbsa/meta'
I0623 15:32:23.292948 27320 status_update_manager.cpp:200] Recovering status update manager
I0623 15:32:23.293156 27324 containerizer.cpp:514] Recovering containerizer
I0623 15:32:23.294348 27320 provisioner.cpp:253] Provisioner recovery complete
I0623 15:32:23.294611 27316 slave.cpp:4840] Finished recovery
I0623 15:32:23.295055 27316 slave.cpp:5012] Querying resource estimator for oversubscribable
resources
I0623 15:32:23.295290 27329 status_update_manager.cpp:174] Pausing sending status updates
I0623 15:32:23.295296 27323 slave.cpp:967] New master detected at master@172.17.0.3:52994
I0623 15:32:23.295351 27323 slave.cpp:1029] Authenticating with master master@172.17.0.3:52994
I0623 15:32:23.295420 27323 slave.cpp:1040] Using default CRAM-MD5 authenticatee
I0623 15:32:23.295552 27323 slave.cpp:1002] Detecting new master
I0623 15:32:23.295660 27325 authenticatee.cpp:121] Creating new client SASL connection
I0623 15:32:23.295682 27323 slave.cpp:5026] Received oversubscribable resources  from the
resource estimator
I0623 15:32:23.295902 27326 master.cpp:5966] Authenticating slave(368)@172.17.0.3:52994
I0623 15:32:23.296005 27327 authenticator.cpp:414] Starting authentication session for crammd5_authenticatee(771)@172.17.0.3:52994
I0623 15:32:23.296198 27330 authenticator.cpp:98] Creating new server SASL connection
I0623 15:32:23.296375 27322 authenticatee.cpp:213] Received SASL authentication mechanisms:
CRAM-MD5
I0623 15:32:23.296408 27322 authenticatee.cpp:239] Attempting to authenticate with mechanism
'CRAM-MD5'
I0623 15:32:23.296509 27321 authenticator.cpp:204] Received SASL authentication start
I0623 15:32:23.296576 27321 authenticator.cpp:326] Authentication requires more steps
I0623 15:32:23.296671 27321 authenticatee.cpp:259] Received SASL authentication step
I0623 15:32:23.296793 27322 authenticator.cpp:232] Received SASL authentication step
I0623 15:32:23.296831 27322 auxprop.cpp:107] Request to lookup properties for user: 'test-principal'
realm: 'e59d5e9e8925' server FQDN: 'e59d5e9e8925' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
I0623 15:32:23.296845 27322 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
I0623 15:32:23.296875 27322 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0623 15:32:23.296891 27322 auxprop.cpp:107] Request to lookup properties for user: 'test-principal'
realm: 'e59d5e9e8925' server FQDN: 'e59d5e9e8925' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
I0623 15:32:23.296900 27322 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since
SASL_AUXPROP_AUTHZID == true
I0623 15:32:23.296905 27322 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5'
since SASL_AUXPROP_AUTHZID == true
I0623 15:32:23.296918 27322 authenticator.cpp:318] Authentication success
I0623 15:32:23.296989 27324 authenticatee.cpp:299] Authentication success
I0623 15:32:23.297107 27330 master.cpp:5996] Successfully authenticated principal 'test-principal'
at slave(368)@172.17.0.3:52994
I0623 15:32:23.297217 27326 authenticator.cpp:432] Authentication session cleanup for crammd5_authenticatee(771)@172.17.0.3:52994
I0623 15:32:23.297365 27321 slave.cpp:1108] Successfully authenticated with master master@172.17.0.3:52994
I0623 15:32:23.297549 27321 slave.cpp:1511] Will retry registration in 4.304294ms if necessary
I0623 15:32:23.297709 27325 master.cpp:4674] Registering agent at slave(368)@172.17.0.3:52994
(e59d5e9e8925) with id 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-S0
I0623 15:32:23.298085 27329 registrar.cpp:464] Applied 1 operations in 63758ns; attempting
to update the 'registry'
I0623 15:32:23.298720 27328 log.cpp:577] Attempting to append 337 bytes to the log
I0623 15:32:23.298926 27318 coordinator.cpp:348] Coordinator attempting to write APPEND action
at position 3
I0623 15:32:23.299706 27331 replica.cpp:537] Replica received write request for position 3
from (13472)@172.17.0.3:52994
I0623 15:32:23.302990 27316 slave.cpp:1511] Will retry registration in 16.7849ms if necessary
I0623 15:32:23.303120 27325 master.cpp:4662] Ignoring register agent message from slave(368)@172.17.0.3:52994
(e59d5e9e8925) as admission is already in progress
I0623 15:32:23.316866 27331 leveldb.cpp:341] Persisting action (356 bytes) to leveldb took
16.997724ms
I0623 15:32:23.316911 27331 replica.cpp:712] Persisted action at 3
I0623 15:32:23.317723 27324 replica.cpp:691] Replica received learned notice for position
3 from @0.0.0.0:0
I0623 15:32:23.320386 27318 slave.cpp:1511] Will retry registration in 14.963058ms if necessary
I0623 15:32:23.320518 27319 master.cpp:4662] Ignoring register agent message from slave(368)@172.17.0.3:52994
(e59d5e9e8925) as admission is already in progress
I0623 15:32:23.335928 27328 slave.cpp:1511] Will retry registration in 67.670541ms if necessary
I0623 15:32:23.336120 27322 master.cpp:4662] Ignoring register agent message from slave(368)@172.17.0.3:52994
(e59d5e9e8925) as admission is already in progress
I0623 15:32:23.349171 27324 leveldb.cpp:341] Persisting action (358 bytes) to leveldb took
31.425537ms
I0623 15:32:23.349220 27324 replica.cpp:712] Persisted action at 3
I0623 15:32:23.349246 27324 replica.cpp:697] Replica learned APPEND action at position 3
I0623 15:32:23.351620 27326 registrar.cpp:509] Successfully updated the 'registry' in 53472us
I0623 15:32:23.351944 27326 log.cpp:596] Attempting to truncate the log to 3
I0623 15:32:23.352589 27326 master.cpp:4743] Registered agent 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-S0
at slave(368)@172.17.0.3:52994 (e59d5e9e8925) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0623 15:32:23.352699 27326 coordinator.cpp:348] Coordinator attempting to write TRUNCATE
action at position 4
I0623 15:32:23.352876 27331 slave.cpp:1152] Registered with master master@172.17.0.3:52994;
given agent ID 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-S0
I0623 15:32:23.352900 27331 fetcher.cpp:86] Clearing fetcher cache
I0623 15:32:23.353024 27326 status_update_manager.cpp:181] Resuming sending status updates
I0623 15:32:23.353006 27320 hierarchical.cpp:481] Added agent 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-S0
(e59d5e9e8925) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated:
)
I0623 15:32:23.353229 27331 slave.cpp:1175] Checkpointing SlaveInfo to '/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_x3jbsa/meta/slaves/645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-S0/slave.info'
I0623 15:32:23.353471 27329 replica.cpp:537] Replica received write request for position 4
from (13473)@172.17.0.3:52994
I0623 15:32:23.353579 27331 slave.cpp:1212] Forwarding total oversubscribed resources 
I0623 15:32:23.353723 27331 slave.cpp:3742] Received ping from slave-observer(328)@172.17.0.3:52994
I0623 15:32:23.353848 27325 master.cpp:5089] Received update of agent 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-S0
at slave(368)@172.17.0.3:52994 (e59d5e9e8925) with total oversubscribed resources 
I0623 15:32:23.353865 27320 hierarchical.cpp:1607] No inverse offers to send out!
I0623 15:32:23.353926 27320 hierarchical.cpp:1170] Performed allocation for agent 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-S0
in 876411ns
I0623 15:32:23.354223 27325 master.cpp:5795] Sending 1 offers to framework 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-0000
(default) at scheduler-b6b07664-4f01-4bbb-898e-868aa0230f73@172.17.0.3:52994
I0623 15:32:23.354229 27320 hierarchical.cpp:539] Agent 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-S0
(e59d5e9e8925) updated with oversubscribed resources  (total: cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000])
I0623 15:32:23.354377 27320 hierarchical.cpp:1512] No allocations performed
I0623 15:32:23.354429 27320 hierarchical.cpp:1607] No inverse offers to send out!
I0623 15:32:23.354480 27320 hierarchical.cpp:1170] Performed allocation for agent 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-S0
in 215741ns
I0623 15:32:23.354645 27316 sched.cpp:897] Scheduler::resourceOffers took 113726ns
I0623 15:32:23.355957 27326 master.cpp:3466] Processing ACCEPT call for offers: [ 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-O0
] on agent 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-S0 at slave(368)@172.17.0.3:52994 (e59d5e9e8925)
for framework 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-0000 (default) at scheduler-b6b07664-4f01-4bbb-898e-868aa0230f73@172.17.0.3:52994
I0623 15:32:23.356031 27326 master.cpp:3104] Authorizing framework principal 'test-principal'
to launch task a3b71f19-9f66-4b84-8e9d-5b55af4225f1
I0623 15:32:23.357417 27330 master.cpp:7515] Adding task a3b71f19-9f66-4b84-8e9d-5b55af4225f1
with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on agent 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-S0
(e59d5e9e8925)
I0623 15:32:23.357602 27330 master.cpp:3955] Launching task a3b71f19-9f66-4b84-8e9d-5b55af4225f1
of framework 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-0000 (default) at scheduler-b6b07664-4f01-4bbb-898e-868aa0230f73@172.17.0.3:52994
with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on agent 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-S0
at slave(368)@172.17.0.3:52994 (e59d5e9e8925)
I0623 15:32:23.357918 27325 slave.cpp:1551] Got assigned task a3b71f19-9f66-4b84-8e9d-5b55af4225f1
for framework 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-0000
I0623 15:32:23.358062 27325 slave.cpp:5646] Checkpointing FrameworkInfo to '/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_x3jbsa/meta/slaves/645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-S0/frameworks/645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-0000/framework.info'
I0623 15:32:23.358392 27325 slave.cpp:5657] Checkpointing framework pid 'scheduler-b6b07664-4f01-4bbb-898e-868aa0230f73@172.17.0.3:52994'
to '/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_x3jbsa/meta/slaves/645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-S0/frameworks/645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-0000/framework.pid'
I0623 15:32:23.358680 27325 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
Trying semicolon-delimited string format instead
I0623 15:32:23.359164 27325 slave.cpp:1670] Launching task a3b71f19-9f66-4b84-8e9d-5b55af4225f1
for framework 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-0000
I0623 15:32:23.359242 27325 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
Trying semicolon-delimited string format instead
I0623 15:32:23.359851 27325 paths.cpp:528] Trying to chown '/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_x3jbsa/slaves/645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-S0/frameworks/645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-0000/executors/a3b71f19-9f66-4b84-8e9d-5b55af4225f1/runs/96d74c81-57dd-4959-8bfc-cb6bab408970'
to user 'mesos'
I0623 15:32:23.366346 27325 slave.cpp:6128] Checkpointing ExecutorInfo to '/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_x3jbsa/meta/slaves/645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-S0/frameworks/645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-0000/executors/a3b71f19-9f66-4b84-8e9d-5b55af4225f1/executor.info'
I0623 15:32:23.366998 27325 slave.cpp:5726] Launching executor a3b71f19-9f66-4b84-8e9d-5b55af4225f1
of framework 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-0000 with resources cpus(*):0.1; mem(*):32
in work directory '/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_x3jbsa/slaves/645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-S0/frameworks/645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-0000/executors/a3b71f19-9f66-4b84-8e9d-5b55af4225f1/runs/96d74c81-57dd-4959-8bfc-cb6bab408970'
I0623 15:32:23.367486 27322 containerizer.cpp:773] Starting container '96d74c81-57dd-4959-8bfc-cb6bab408970'
for executor 'a3b71f19-9f66-4b84-8e9d-5b55af4225f1' of framework '645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-0000'
I0623 15:32:23.367614 27325 slave.cpp:6151] Checkpointing TaskInfo to '/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_x3jbsa/meta/slaves/645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-S0/frameworks/645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-0000/executors/a3b71f19-9f66-4b84-8e9d-5b55af4225f1/runs/96d74c81-57dd-4959-8bfc-cb6bab408970/tasks/a3b71f19-9f66-4b84-8e9d-5b55af4225f1/task.info'
I0623 15:32:23.368203 27325 slave.cpp:1896] Queuing task 'a3b71f19-9f66-4b84-8e9d-5b55af4225f1'
for executor 'a3b71f19-9f66-4b84-8e9d-5b55af4225f1' of framework 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-0000
I0623 15:32:23.368320 27325 slave.cpp:920] Successfully attached file '/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_x3jbsa/slaves/645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-S0/frameworks/645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-0000/executors/a3b71f19-9f66-4b84-8e9d-5b55af4225f1/runs/96d74c81-57dd-4959-8bfc-cb6bab408970'
I0623 15:32:23.371162 27322 containerizer.cpp:1264] Launching 'mesos-containerizer' with flags
'--command="{"shell":true,"value":"\/mesos\/mesos-1.0.0\/_build\/src\/mesos-executor"}" --commands="{"commands":[]}"
--help="false" --pipe_read="23" --pipe_write="28" --sandbox="/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_x3jbsa/slaves/645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-S0/frameworks/645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-0000/executors/a3b71f19-9f66-4b84-8e9d-5b55af4225f1/runs/96d74c81-57dd-4959-8bfc-cb6bab408970"
--user="mesos"'
I0623 15:32:23.372831 27322 launcher.cpp:127] Forked child with pid '2966' for container '96d74c81-57dd-4959-8bfc-cb6bab408970'
I0623 15:32:23.373042 27322 containerizer.cpp:1299] Checkpointing executor's forked pid 2966
to '/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_x3jbsa/meta/slaves/645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-S0/frameworks/645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-0000/executors/a3b71f19-9f66-4b84-8e9d-5b55af4225f1/runs/96d74c81-57dd-4959-8bfc-cb6bab408970/pids/forked.pid'
I0623 15:32:23.406654 27329 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took
53.16527ms
I0623 15:32:23.406790 27329 replica.cpp:712] Persisted action at 4
I0623 15:32:23.408130 27321 replica.cpp:691] Replica received learned notice for position
4 from @0.0.0.0:0
I0623 15:32:23.448725 27321 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took
40.556641ms
I0623 15:32:23.449239 27321 leveldb.cpp:399] Deleting ~2 keys from leveldb took 377812ns
I0623 15:32:23.449273 27321 replica.cpp:712] Persisted action at 4
I0623 15:32:23.449337 27321 replica.cpp:697] Replica learned TRUNCATE action at position 4
I0623 15:32:23.533140  3004 exec.cpp:161] Version: 1.0.0
I0623 15:32:23.539949 27321 slave.cpp:2884] Got registration for executor 'a3b71f19-9f66-4b84-8e9d-5b55af4225f1'
of framework 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-0000 from executor(1)@172.17.0.3:35462
I0623 15:32:23.540535 27321 slave.cpp:2970] Checkpointing executor pid 'executor(1)@172.17.0.3:35462'
to '/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_x3jbsa/meta/slaves/645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-S0/frameworks/645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-0000/executors/a3b71f19-9f66-4b84-8e9d-5b55af4225f1/runs/96d74c81-57dd-4959-8bfc-cb6bab408970/pids/libprocess.pid'
I0623 15:32:23.541903 27321 slave.cpp:839] Agent terminating
I0623 15:32:23.542698 27298 containerizer.cpp:201] Using isolation: posix/cpu,posix/mem,filesystem/posix,network/cni
I0623 15:32:23.542753  2999 exec.cpp:236] Executor registered on agent 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-S0
I0623 15:32:23.542846 27329 master.cpp:1369] Agent 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-S0
at slave(368)@172.17.0.3:52994 (e59d5e9e8925) disconnected
I0623 15:32:23.542877 27329 master.cpp:2908] Disconnecting agent 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-S0
at slave(368)@172.17.0.3:52994 (e59d5e9e8925)
I0623 15:32:23.542943 27329 master.cpp:2927] Deactivating agent 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-S0
at slave(368)@172.17.0.3:52994 (e59d5e9e8925)
I0623 15:32:23.543118 27329 hierarchical.cpp:568] Agent 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-S0
deactivated
W0623 15:32:23.544533 27298 backend.cpp:75] Failed to create 'aufs' backend: AufsBackend requires
root privileges, but is running as user mesos
W0623 15:32:23.544700 27298 backend.cpp:75] Failed to create 'bind' backend: BindBackend requires
root privileges
I0623 15:32:23.550683 27298 cluster.cpp:432] Creating default 'local' authorizer
I0623 15:32:23.553174 27330 slave.cpp:203] Agent started on 369)@172.17.0.3:52994
I0623 15:32:23.553216 27330 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="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs"
--containerizers="mesos" --credential="/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_x3jbsa/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="/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_x3jbsa/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="/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_x3jbsa/http_credentials"
--image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem"
--launcher_dir="/mesos/mesos-1.0.0/_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="/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_x3jbsa"
I0623 15:32:23.554741 27330 credentials.hpp:86] Loading credential for authentication from
'/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_x3jbsa/credential'
I0623 15:32:23.554986 27330 slave.cpp:341] Agent using credential for: test-principal
I0623 15:32:23.555053 27330 credentials.hpp:37] Loading credentials for authentication from
'/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_x3jbsa/http_credentials'
I0623 15:32:23.555317 27330 slave.cpp:393] Using default 'basic' HTTP authenticator
I0623 15:32:23.555586 27330 resources.cpp:572] Parsing resources as JSON failed: cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]
Trying semicolon-delimited string format instead
I0623 15:32:23.556366 27330 slave.cpp:592] Agent resources: cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000]
I0623 15:32:23.556440 27330 slave.cpp:600] Agent attributes: [  ]
I0623 15:32:23.556457 27330 slave.cpp:605] Agent hostname: e59d5e9e8925
Received SUBSCRIBED event
Subscribed executor on e59d5e9e8925
../../src/tests/slave_recovery_tests.cpp:3973: Failure
Value of: containers.get().size()
  Actual: 0
Expected: 1u
Which is: 1
I0623 15:32:23.562470 27318 state.cpp:57] Recovering state from '/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_x3jbsa/meta'
I0623 15:32:23.562666 27318 state.cpp:697] No checkpointed resources found at '/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_x3jbsa/meta/resources/resources.info'
I0623 15:32:23.562995 27317 master.cpp:1408] Framework 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-0000
(default) at scheduler-b6b07664-4f01-4bbb-898e-868aa0230f73@172.17.0.3:52994 disconnected
I0623 15:32:23.563042 27317 master.cpp:2849] Disconnecting framework 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-0000
(default) at scheduler-b6b07664-4f01-4bbb-898e-868aa0230f73@172.17.0.3:52994
I0623 15:32:23.563091 27317 master.cpp:2873] Deactivating framework 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-0000
(default) at scheduler-b6b07664-4f01-4bbb-898e-868aa0230f73@172.17.0.3:52994
I0623 15:32:23.563410 27317 master.cpp:1421] Giving framework 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-0000
(default) at scheduler-b6b07664-4f01-4bbb-898e-868aa0230f73@172.17.0.3:52994 0ns to failover
I0623 15:32:23.563855 27317 hierarchical.cpp:379] Deactivated framework 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-0000
I0623 15:32:23.564260 27325 master.cpp:5647] Framework failover timeout, removing framework
645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-0000 (default) at scheduler-b6b07664-4f01-4bbb-898e-868aa0230f73@172.17.0.3:52994
I0623 15:32:23.564585 27325 master.cpp:6377] Removing framework 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-0000
(default) at scheduler-b6b07664-4f01-4bbb-898e-868aa0230f73@172.17.0.3:52994
I0623 15:32:23.565163 27325 master.cpp:6909] Updating the state of task a3b71f19-9f66-4b84-8e9d-5b55af4225f1
of framework 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-0000 (latest state: TASK_KILLED, status
update state: TASK_KILLED)
W0623 15:32:23.565871 27318 state.cpp:606] Failed to find status updates file '/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_x3jbsa/meta/slaves/645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-S0/frameworks/645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-0000/executors/a3b71f19-9f66-4b84-8e9d-5b55af4225f1/runs/96d74c81-57dd-4959-8bfc-cb6bab408970/tasks/a3b71f19-9f66-4b84-8e9d-5b55af4225f1/task.updates'
I0623 15:32:23.566649 27324 slave.cpp:839] Agent terminating
I0623 15:32:23.566614 27323 hierarchical.cpp:899] Recovered cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000],
allocated: ) on agent 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-S0 from framework 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-0000
I0623 15:32:23.567150 27325 master.cpp:6975] Removing task a3b71f19-9f66-4b84-8e9d-5b55af4225f1
with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-0000
on agent 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-S0 at slave(368)@172.17.0.3:52994 (e59d5e9e8925)
I0623 15:32:23.574358 27325 hierarchical.cpp:330] Removed framework 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-0000
I0623 15:32:23.583897 27330 master.cpp:1216] Master terminating
I0623 15:32:23.584374 27329 hierarchical.cpp:513] Removed agent 645fa8df-79d0-48c4-9d0f-cdd4bd675eb5-S0
[  FAILED  ] MesosContainerizerSlaveRecoveryTest.ResourceStatistics (897 ms)
{code}

> MesosContainerizerSlaveRecoveryTest.ResourceStatistics is flaky
> ---------------------------------------------------------------
>
>                 Key: MESOS-5048
>                 URL: https://issues.apache.org/jira/browse/MESOS-5048
>             Project: Mesos
>          Issue Type: Bug
>          Components: tests
>    Affects Versions: 0.28.0
>         Environment: Ubuntu 15.04
>            Reporter: Jian Qiu
>              Labels: flaky-test
>
> ./mesos-tests.sh --gtest_filter=MesosContainerizerSlaveRecoveryTest.ResourceStatistics
--gtest_repeat=100 --gtest_break_on_failure
> This is found in rb, and reproduced in my local machine. There are two types of failures.
However, the failure does not appear when enabling verbose...
> {code}
> ../../src/tests/environment.cpp:790: Failure
> Failed
> Tests completed with child processes remaining:
> -+- 1446 /mesos/mesos-0.29.0/_build/src/.libs/lt-mesos-tests 
>  \-+- 9171 sh -c /mesos/mesos-0.29.0/_build/src/mesos-executor 
>    \--- 9185 /mesos/mesos-0.29.0/_build/src/.libs/lt-mesos-executor 
> {code}
> And
> {code}
> I0328 15:42:36.982471  5687 exec.cpp:150] Version: 0.29.0
> I0328 15:42:37.008765  5708 exec.cpp:225] Executor registered on slave 731fb93b-26fe-4c7c-a543-fc76f106a62e-S0
> Registered executor on mesos
> ../../src/tests/slave_recovery_tests.cpp:3506: Failure
> Value of: containers.get().size()
>   Actual: 0
> Expected: 1u
> Which is: 1
> {code}



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Mime
View raw message