[ https://issues.apache.org/jira/browse/MESOS-3968?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15363519#comment-15363519 ]
Joseph Wu commented on MESOS-3968: ---------------------------------- This test has been failing more frequently (on ASF and local builds): {code} [ RUN ] DiskQuotaTest.SlaveRecovery I0706 00:02:21.991916 19907 cluster.cpp:155] Creating default 'local' authorizer I0706 00:02:21.998934 19907 leveldb.cpp:174] Opened db in 6.606049ms I0706 00:02:22.000072 19907 leveldb.cpp:181] Compacted db in 1.093827ms I0706 00:02:22.000119 19907 leveldb.cpp:196] Created db iterator in 19963ns I0706 00:02:22.000128 19907 leveldb.cpp:202] Seeked to beginning of db in 1271ns I0706 00:02:22.000131 19907 leveldb.cpp:271] Iterated through 0 keys in the db in 120ns I0706 00:02:22.000169 19907 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0706 00:02:22.000886 19922 recover.cpp:451] Starting replica recovery I0706 00:02:22.001183 19922 recover.cpp:477] Replica is in EMPTY status I0706 00:02:22.002557 19927 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (1328)@127.0.0.1:54648 I0706 00:02:22.003260 19928 master.cpp:382] Master 8a9140ac-c7b3-45dd-961d-aeff38eae88e (centos71) started on 127.0.0.1:54648 I0706 00:02:22.003288 19928 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/XoD9Xk/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/XoD9Xk/master" --zk_session_timeout="10secs" W0706 00:02:22.003545 19928 master.cpp:387] ************************************************** Master bound to loopback interface! Cannot communicate with remote schedulers or agents. You might want to set '--ip' flag to a routable IP address. ************************************************** I0706 00:02:22.003564 19928 master.cpp:434] Master only allowing authenticated frameworks to register I0706 00:02:22.003569 19928 master.cpp:448] Master only allowing authenticated agents to register I0706 00:02:22.003573 19928 master.cpp:461] Master only allowing authenticated HTTP frameworks to register I0706 00:02:22.003577 19928 credentials.hpp:37] Loading credentials for authentication from '/tmp/XoD9Xk/credentials' I0706 00:02:22.003829 19928 master.cpp:506] Using default 'crammd5' authenticator I0706 00:02:22.003933 19928 master.cpp:578] Using default 'basic' HTTP authenticator I0706 00:02:22.004132 19923 recover.cpp:197] Received a recover response from a replica in EMPTY status I0706 00:02:22.004261 19928 master.cpp:658] Using default 'basic' HTTP framework authenticator I0706 00:02:22.004370 19928 master.cpp:705] Authorization enabled I0706 00:02:22.004560 19923 recover.cpp:568] Updating replica status to STARTING I0706 00:02:22.006342 19922 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 1.264999ms I0706 00:02:22.006395 19922 replica.cpp:320] Persisted replica status to STARTING I0706 00:02:22.006669 19924 recover.cpp:477] Replica is in STARTING status I0706 00:02:22.008113 19922 master.cpp:1972] The newly elected leader is master@127.0.0.1:54648 with id 8a9140ac-c7b3-45dd-961d-aeff38eae88e I0706 00:02:22.008174 19922 master.cpp:1985] Elected as the leading master! I0706 00:02:22.008215 19922 master.cpp:1672] Recovering from registrar I0706 00:02:22.008404 19923 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (1331)@127.0.0.1:54648 I0706 00:02:22.008600 19925 registrar.cpp:332] Recovering registrar I0706 00:02:22.009078 19928 recover.cpp:197] Received a recover response from a replica in STARTING status I0706 00:02:22.009968 19928 recover.cpp:568] Updating replica status to VOTING I0706 00:02:22.011096 19928 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 923116ns I0706 00:02:22.011121 19928 replica.cpp:320] Persisted replica status to VOTING I0706 00:02:22.011214 19928 recover.cpp:582] Successfully joined the Paxos group I0706 00:02:22.011320 19928 recover.cpp:466] Recover process terminated I0706 00:02:22.012004 19928 log.cpp:553] Attempting to start the writer I0706 00:02:22.013170 19928 replica.cpp:493] Replica received implicit promise request from (1332)@127.0.0.1:54648 with proposal 1 I0706 00:02:22.014192 19928 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 990028ns I0706 00:02:22.014220 19928 replica.cpp:342] Persisted promised to 1 I0706 00:02:22.015228 19928 coordinator.cpp:238] Coordinator attempting to fill missing positions I0706 00:02:22.016861 19925 replica.cpp:388] Replica received explicit promise request from (1333)@127.0.0.1:54648 for position 0 with proposal 2 I0706 00:02:22.017912 19925 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 1.005551ms I0706 00:02:22.017941 19925 replica.cpp:712] Persisted action at 0 I0706 00:02:22.019713 19923 replica.cpp:537] Replica received write request for position 0 from (1334)@127.0.0.1:54648 I0706 00:02:22.019953 19923 leveldb.cpp:436] Reading position from leveldb took 115287ns I0706 00:02:22.020992 19923 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 978261ns I0706 00:02:22.021014 19923 replica.cpp:712] Persisted action at 0 I0706 00:02:22.021916 19928 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0 I0706 00:02:22.022753 19928 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 801852ns I0706 00:02:22.022775 19928 replica.cpp:712] Persisted action at 0 I0706 00:02:22.022790 19928 replica.cpp:697] Replica learned NOP action at position 0 I0706 00:02:22.023401 19928 log.cpp:569] Writer started with ending position 0 I0706 00:02:22.024770 19923 leveldb.cpp:436] Reading position from leveldb took 25856ns I0706 00:02:22.025770 19928 registrar.cpp:365] Successfully fetched the registry (0B) in 17.095168ms I0706 00:02:22.025869 19928 registrar.cpp:464] Applied 1 operations in 15775ns; attempting to update the 'registry' I0706 00:02:22.026995 19921 log.cpp:577] Attempting to append 157 bytes to the log I0706 00:02:22.027148 19921 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1 I0706 00:02:22.027779 19921 replica.cpp:537] Replica received write request for position 1 from (1335)@127.0.0.1:54648 I0706 00:02:22.028738 19921 leveldb.cpp:341] Persisting action (176 bytes) to leveldb took 883317ns I0706 00:02:22.028765 19921 replica.cpp:712] Persisted action at 1 I0706 00:02:22.029538 19921 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0 I0706 00:02:22.030985 19921 leveldb.cpp:341] Persisting action (178 bytes) to leveldb took 1.414723ms I0706 00:02:22.031028 19921 replica.cpp:712] Persisted action at 1 I0706 00:02:22.031051 19921 replica.cpp:697] Replica learned APPEND action at position 1 I0706 00:02:22.032454 19921 registrar.cpp:509] Successfully updated the 'registry' in 6.53312ms I0706 00:02:22.032879 19922 log.cpp:596] Attempting to truncate the log to 1 I0706 00:02:22.032901 19921 registrar.cpp:395] Successfully recovered registrar I0706 00:02:22.033494 19922 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2 I0706 00:02:22.034296 19921 master.cpp:1780] Recovered 0 agents from the Registry (119B) ; allowing 10mins for agents to re-register I0706 00:02:22.035290 19923 replica.cpp:537] Replica received write request for position 2 from (1336)@127.0.0.1:54648 I0706 00:02:22.036347 19923 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 1.012226ms I0706 00:02:22.036386 19923 replica.cpp:712] Persisted action at 2 I0706 00:02:22.037621 19925 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0 I0706 00:02:22.039625 19925 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 1.956269ms I0706 00:02:22.039809 19925 leveldb.cpp:399] Deleting ~1 keys from leveldb took 144502ns I0706 00:02:22.039834 19925 replica.cpp:712] Persisted action at 2 I0706 00:02:22.039861 19925 replica.cpp:697] Replica learned TRUNCATE action at position 2 I0706 00:02:22.046433 19907 containerizer.cpp:196] Using isolation: posix/cpu,posix/mem,disk/du,filesystem/posix,network/cni W0706 00:02:22.047298 19907 backend.cpp:75] Failed to create 'bind' backend: BindBackend requires root privileges I0706 00:02:22.050290 19907 cluster.cpp:432] Creating default 'local' authorizer I0706 00:02:22.051465 19926 slave.cpp:203] Agent started on 37)@127.0.0.1:54648 I0706 00:02:22.051486 19926 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="1ms" --containerizers="mesos" --credential="/tmp/DiskQuotaTest_SlaveRecovery_NWOfjE/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/DiskQuotaTest_SlaveRecovery_NWOfjE/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/DiskQuotaTest_SlaveRecovery_NWOfjE/http_credentials" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem,disk/du" --launcher_dir="/vagrant/mesos/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/DiskQuotaTest_SlaveRecovery_NWOfjE" W0706 00:02:22.051818 19926 slave.cpp:207] ************************************************** Agent bound to loopback interface! Cannot communicate with remote master(s). You might want to set '--ip' flag to a routable IP address. ************************************************** I0706 00:02:22.051829 19926 credentials.hpp:86] Loading credential for authentication from '/tmp/DiskQuotaTest_SlaveRecovery_NWOfjE/credential' W0706 00:02:22.051834 19907 sched.cpp:1674] ************************************************** Scheduler driver bound to loopback interface! Cannot communicate with remote master(s). You might want to set 'LIBPROCESS_IP' environment variable to use a routable IP address. ************************************************** I0706 00:02:22.051946 19926 slave.cpp:341] Agent using credential for: test-principal I0706 00:02:22.052000 19926 credentials.hpp:37] Loading credentials for authentication from '/tmp/DiskQuotaTest_SlaveRecovery_NWOfjE/http_credentials' I0706 00:02:22.052124 19926 slave.cpp:393] Using default 'basic' HTTP authenticator I0706 00:02:22.052814 19907 sched.cpp:224] Version: 1.0.0 I0706 00:02:22.053140 19926 slave.cpp:592] Agent resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I0706 00:02:22.053187 19926 slave.cpp:600] Agent attributes: [ ] I0706 00:02:22.053196 19926 slave.cpp:605] Agent hostname: centos71 I0706 00:02:22.053483 19925 sched.cpp:328] New master detected at master@127.0.0.1:54648 I0706 00:02:22.053555 19925 sched.cpp:394] Authenticating with master master@127.0.0.1:54648 I0706 00:02:22.053566 19925 sched.cpp:401] Using default CRAM-MD5 authenticatee I0706 00:02:22.053818 19928 authenticatee.cpp:121] Creating new client SASL connection I0706 00:02:22.054312 19924 master.cpp:5967] Authenticating scheduler-b038a647-ffab-4290-b583-4f5308a567cf@127.0.0.1:54648 I0706 00:02:22.054641 19924 authenticator.cpp:98] Creating new server SASL connection I0706 00:02:22.054697 19927 state.cpp:57] Recovering state from '/tmp/DiskQuotaTest_SlaveRecovery_NWOfjE/meta' I0706 00:02:22.055033 19927 status_update_manager.cpp:200] Recovering status update manager I0706 00:02:22.055220 19924 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 I0706 00:02:22.055248 19924 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' I0706 00:02:22.055284 19927 containerizer.cpp:522] Recovering containerizer I0706 00:02:22.055362 19924 authenticator.cpp:204] Received SASL authentication start I0706 00:02:22.055402 19924 authenticator.cpp:326] Authentication requires more steps I0706 00:02:22.055472 19924 authenticatee.cpp:259] Received SASL authentication step I0706 00:02:22.055577 19926 authenticator.cpp:232] Received SASL authentication step I0706 00:02:22.055646 19926 authenticator.cpp:318] Authentication success I0706 00:02:22.055788 19923 authenticatee.cpp:299] Authentication success I0706 00:02:22.055837 19927 master.cpp:5997] Successfully authenticated principal 'test-principal' at scheduler-b038a647-ffab-4290-b583-4f5308a567cf@127.0.0.1:54648 I0706 00:02:22.056324 19923 sched.cpp:484] Successfully authenticated with master master@127.0.0.1:54648 I0706 00:02:22.057066 19926 master.cpp:2549] Received SUBSCRIBE call for framework 'default' at scheduler-b038a647-ffab-4290-b583-4f5308a567cf@127.0.0.1:54648 I0706 00:02:22.057158 19926 master.cpp:2011] Authorizing framework principal 'test-principal' to receive offers for role '*' I0706 00:02:22.057606 19926 master.cpp:2625] Subscribing framework default with checkpointing enabled and capabilities [ ] I0706 00:02:22.058117 19924 hierarchical.cpp:271] Added framework 8a9140ac-c7b3-45dd-961d-aeff38eae88e-0000 I0706 00:02:22.058208 19925 sched.cpp:723] Framework registered with 8a9140ac-c7b3-45dd-961d-aeff38eae88e-0000 I0706 00:02:22.058365 19926 provisioner.cpp:253] Provisioner recovery complete I0706 00:02:22.058894 19925 slave.cpp:4838] Finished recovery I0706 00:02:22.059669 19926 slave.cpp:967] New master detected at master@127.0.0.1:54648 I0706 00:02:22.059687 19923 status_update_manager.cpp:174] Pausing sending status updates I0706 00:02:22.059692 19926 slave.cpp:1029] Authenticating with master master@127.0.0.1:54648 I0706 00:02:22.059834 19926 slave.cpp:1040] Using default CRAM-MD5 authenticatee I0706 00:02:22.059960 19926 slave.cpp:1002] Detecting new master I0706 00:02:22.060247 19922 authenticatee.cpp:121] Creating new client SASL connection I0706 00:02:22.060688 19926 master.cpp:5967] Authenticating slave(37)@127.0.0.1:54648 I0706 00:02:22.061270 19924 authenticator.cpp:98] Creating new server SASL connection I0706 00:02:22.061575 19924 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 I0706 00:02:22.061596 19924 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' I0706 00:02:22.061725 19924 authenticator.cpp:204] Received SASL authentication start I0706 00:02:22.061759 19924 authenticator.cpp:326] Authentication requires more steps I0706 00:02:22.061827 19924 authenticatee.cpp:259] Received SASL authentication step I0706 00:02:22.061877 19924 authenticator.cpp:232] Received SASL authentication step I0706 00:02:22.061916 19924 authenticator.cpp:318] Authentication success I0706 00:02:22.061969 19926 authenticatee.cpp:299] Authentication success I0706 00:02:22.062037 19921 master.cpp:5997] Successfully authenticated principal 'test-principal' at slave(37)@127.0.0.1:54648 I0706 00:02:22.062718 19926 slave.cpp:1108] Successfully authenticated with master master@127.0.0.1:54648 I0706 00:02:22.063081 19926 master.cpp:4675] Registering agent at slave(37)@127.0.0.1:54648 (centos71) with id 8a9140ac-c7b3-45dd-961d-aeff38eae88e-S0 I0706 00:02:22.063468 19926 registrar.cpp:464] Applied 1 operations in 43710ns; attempting to update the 'registry' I0706 00:02:22.064153 19925 log.cpp:577] Attempting to append 323 bytes to the log I0706 00:02:22.064321 19922 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3 I0706 00:02:22.065376 19925 replica.cpp:537] Replica received write request for position 3 from (1354)@127.0.0.1:54648 I0706 00:02:22.066439 19925 leveldb.cpp:341] Persisting action (342 bytes) to leveldb took 1.027998ms I0706 00:02:22.066467 19925 replica.cpp:712] Persisted action at 3 I0706 00:02:22.067109 19925 replica.cpp:691] Replica received learned notice for position 3 from @0.0.0.0:0 I0706 00:02:22.067947 19925 leveldb.cpp:341] Persisting action (344 bytes) to leveldb took 806904ns I0706 00:02:22.067970 19925 replica.cpp:712] Persisted action at 3 I0706 00:02:22.067986 19925 replica.cpp:697] Replica learned APPEND action at position 3 I0706 00:02:22.069012 19925 registrar.cpp:509] Successfully updated the 'registry' in 5.478912ms I0706 00:02:22.069229 19925 log.cpp:596] Attempting to truncate the log to 3 I0706 00:02:22.069371 19925 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4 I0706 00:02:22.069586 19921 master.cpp:4744] Registered agent 8a9140ac-c7b3-45dd-961d-aeff38eae88e-S0 at slave(37)@127.0.0.1:54648 (centos71) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I0706 00:02:22.069783 19921 slave.cpp:1152] Registered with master master@127.0.0.1:54648; given agent ID 8a9140ac-c7b3-45dd-961d-aeff38eae88e-S0 I0706 00:02:22.069808 19925 hierarchical.cpp:478] Added agent 8a9140ac-c7b3-45dd-961d-aeff38eae88e-S0 (centos71) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: ) I0706 00:02:22.070189 19921 slave.cpp:1212] Forwarding total oversubscribed resources I0706 00:02:22.070276 19925 status_update_manager.cpp:181] Resuming sending status updates I0706 00:02:22.070520 19925 master.cpp:5796] Sending 1 offers to framework 8a9140ac-c7b3-45dd-961d-aeff38eae88e-0000 (default) at scheduler-b038a647-ffab-4290-b583-4f5308a567cf@127.0.0.1:54648 I0706 00:02:22.070647 19925 master.cpp:5090] Received update of agent 8a9140ac-c7b3-45dd-961d-aeff38eae88e-S0 at slave(37)@127.0.0.1:54648 (centos71) with total oversubscribed resources I0706 00:02:22.070757 19925 replica.cpp:537] Replica received write request for position 4 from (1355)@127.0.0.1:54648 I0706 00:02:22.071003 19921 hierarchical.cpp:542] Agent 8a9140ac-c7b3-45dd-961d-aeff38eae88e-S0 (centos71) updated with oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) I0706 00:02:22.072443 19925 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 1.657668ms I0706 00:02:22.072473 19925 replica.cpp:712] Persisted action at 4 I0706 00:02:22.072800 19928 master.cpp:3467] Processing ACCEPT call for offers: [ 8a9140ac-c7b3-45dd-961d-aeff38eae88e-O0 ] on agent 8a9140ac-c7b3-45dd-961d-aeff38eae88e-S0 at slave(37)@127.0.0.1:54648 (centos71) for framework 8a9140ac-c7b3-45dd-961d-aeff38eae88e-0000 (default) at scheduler-b038a647-ffab-4290-b583-4f5308a567cf@127.0.0.1:54648 I0706 00:02:22.072865 19928 master.cpp:3105] Authorizing framework principal 'test-principal' to launch task 69b0dc4a-c67c-4cf3-9c8a-fa280390ad0c I0706 00:02:22.073357 19928 replica.cpp:691] Replica received learned notice for position 4 from @0.0.0.0:0 I0706 00:02:22.074192 19923 master.cpp:7516] Adding task 69b0dc4a-c67c-4cf3-9c8a-fa280390ad0c with resources cpus(*):1; mem(*):128; disk(*):3 on agent 8a9140ac-c7b3-45dd-961d-aeff38eae88e-S0 (centos71) I0706 00:02:22.074280 19923 master.cpp:3956] Launching task 69b0dc4a-c67c-4cf3-9c8a-fa280390ad0c of framework 8a9140ac-c7b3-45dd-961d-aeff38eae88e-0000 (default) at scheduler-b038a647-ffab-4290-b583-4f5308a567cf@127.0.0.1:54648 with resources cpus(*):1; mem(*):128; disk(*):3 on agent 8a9140ac-c7b3-45dd-961d-aeff38eae88e-S0 at slave(37)@127.0.0.1:54648 (centos71) I0706 00:02:22.074522 19928 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 1.128554ms I0706 00:02:22.074592 19928 leveldb.cpp:399] Deleting ~2 keys from leveldb took 40354ns I0706 00:02:22.074609 19928 replica.cpp:712] Persisted action at 4 I0706 00:02:22.074630 19928 replica.cpp:697] Replica learned TRUNCATE action at position 4 I0706 00:02:22.075187 19925 slave.cpp:1551] Got assigned task 69b0dc4a-c67c-4cf3-9c8a-fa280390ad0c for framework 8a9140ac-c7b3-45dd-961d-aeff38eae88e-0000 I0706 00:02:22.076467 19925 slave.cpp:1670] Launching task 69b0dc4a-c67c-4cf3-9c8a-fa280390ad0c for framework 8a9140ac-c7b3-45dd-961d-aeff38eae88e-0000 I0706 00:02:22.077512 19925 paths.cpp:528] Trying to chown '/tmp/DiskQuotaTest_SlaveRecovery_NWOfjE/slaves/8a9140ac-c7b3-45dd-961d-aeff38eae88e-S0/frameworks/8a9140ac-c7b3-45dd-961d-aeff38eae88e-0000/executors/69b0dc4a-c67c-4cf3-9c8a-fa280390ad0c/runs/564657c9-460d-44dd-b0fa-86880122e235' to user 'vagrant' I0706 00:02:22.082195 19925 slave.cpp:5724] Launching executor 69b0dc4a-c67c-4cf3-9c8a-fa280390ad0c of framework 8a9140ac-c7b3-45dd-961d-aeff38eae88e-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/DiskQuotaTest_SlaveRecovery_NWOfjE/slaves/8a9140ac-c7b3-45dd-961d-aeff38eae88e-S0/frameworks/8a9140ac-c7b3-45dd-961d-aeff38eae88e-0000/executors/69b0dc4a-c67c-4cf3-9c8a-fa280390ad0c/runs/564657c9-460d-44dd-b0fa-86880122e235' I0706 00:02:22.082561 19923 containerizer.cpp:781] Starting container '564657c9-460d-44dd-b0fa-86880122e235' for executor '69b0dc4a-c67c-4cf3-9c8a-fa280390ad0c' of framework '8a9140ac-c7b3-45dd-961d-aeff38eae88e-0000' I0706 00:02:22.082801 19925 slave.cpp:1896] Queuing task '69b0dc4a-c67c-4cf3-9c8a-fa280390ad0c' for executor '69b0dc4a-c67c-4cf3-9c8a-fa280390ad0c' of framework 8a9140ac-c7b3-45dd-961d-aeff38eae88e-0000 I0706 00:02:22.087142 19921 launcher.cpp:126] Forked child with pid '21039' for container '564657c9-460d-44dd-b0fa-86880122e235' I0706 00:02:22.087393 19921 containerizer.cpp:1305] Checkpointing executor's forked pid 21039 to '/tmp/DiskQuotaTest_SlaveRecovery_NWOfjE/meta/slaves/8a9140ac-c7b3-45dd-961d-aeff38eae88e-S0/frameworks/8a9140ac-c7b3-45dd-961d-aeff38eae88e-0000/executors/69b0dc4a-c67c-4cf3-9c8a-fa280390ad0c/runs/564657c9-460d-44dd-b0fa-86880122e235/pids/forked.pid' I0706 00:02:22.239784 21071 exec.cpp:161] Version: 1.0.0 I0706 00:02:22.243418 19924 slave.cpp:2884] Got registration for executor '69b0dc4a-c67c-4cf3-9c8a-fa280390ad0c' of framework 8a9140ac-c7b3-45dd-961d-aeff38eae88e-0000 from executor(1)@127.0.0.1:47550 I0706 00:02:22.245038 19924 disk.cpp:171] Updating the disk resources for container 564657c9-460d-44dd-b0fa-86880122e235 to cpus(*):1.1; mem(*):160; disk(*):3 I0706 00:02:22.246254 21067 exec.cpp:236] Executor registered on agent 8a9140ac-c7b3-45dd-961d-aeff38eae88e-S0 I0706 00:02:22.246961 19928 slave.cpp:2061] Sending queued task '69b0dc4a-c67c-4cf3-9c8a-fa280390ad0c' to executor '69b0dc4a-c67c-4cf3-9c8a-fa280390ad0c' of framework 8a9140ac-c7b3-45dd-961d-aeff38eae88e-0000 at executor(1)@127.0.0.1:47550 Received SUBSCRIBED event Subscribed executor on centos71 Received LAUNCH event Starting task 69b0dc4a-c67c-4cf3-9c8a-fa280390ad0c /vagrant/mesos/build/src/mesos-containerizer launch --command="{"shell":true,"value":"dd if=\/dev\/zero of=file bs=1048576 count=2 && sleep 1000"}" --help="false" --unshare_namespace_mnt="false" Forked command at 21077 I0706 00:02:22.263149 19925 slave.cpp:3267] Handling status update TASK_RUNNING (UUID: c6f01f1a-8511-4b5d-b58f-483ece819a66) for task 69b0dc4a-c67c-4cf3-9c8a-fa280390ad0c of framework 8a9140ac-c7b3-45dd-961d-aeff38eae88e-0000 from executor(1)@127.0.0.1:47550 I0706 00:02:22.264904 19925 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: c6f01f1a-8511-4b5d-b58f-483ece819a66) for task 69b0dc4a-c67c-4cf3-9c8a-fa280390ad0c of framework 8a9140ac-c7b3-45dd-961d-aeff38eae88e-0000 I0706 00:02:22.265388 19925 status_update_manager.cpp:825] Checkpointing UPDATE for status update TASK_RUNNING (UUID: c6f01f1a-8511-4b5d-b58f-483ece819a66) for task 69b0dc4a-c67c-4cf3-9c8a-fa280390ad0c of framework 8a9140ac-c7b3-45dd-961d-aeff38eae88e-0000 I0706 00:02:22.268911 19925 slave.cpp:3660] Forwarding the update TASK_RUNNING (UUID: c6f01f1a-8511-4b5d-b58f-483ece819a66) for task 69b0dc4a-c67c-4cf3-9c8a-fa280390ad0c of framework 8a9140ac-c7b3-45dd-961d-aeff38eae88e-0000 to master@127.0.0.1:54648 I0706 00:02:22.269064 19925 slave.cpp:3570] Sending acknowledgement for status update TASK_RUNNING (UUID: c6f01f1a-8511-4b5d-b58f-483ece819a66) for task 69b0dc4a-c67c-4cf3-9c8a-fa280390ad0c of framework 8a9140ac-c7b3-45dd-961d-aeff38eae88e-0000 to executor(1)@127.0.0.1:47550 I0706 00:02:22.269260 19924 master.cpp:5235] Status update TASK_RUNNING (UUID: c6f01f1a-8511-4b5d-b58f-483ece819a66) for task 69b0dc4a-c67c-4cf3-9c8a-fa280390ad0c of framework 8a9140ac-c7b3-45dd-961d-aeff38eae88e-0000 from agent 8a9140ac-c7b3-45dd-961d-aeff38eae88e-S0 at slave(37)@127.0.0.1:54648 (centos71) I0706 00:02:22.269299 19924 master.cpp:5283] Forwarding status update TASK_RUNNING (UUID: c6f01f1a-8511-4b5d-b58f-483ece819a66) for task 69b0dc4a-c67c-4cf3-9c8a-fa280390ad0c of framework 8a9140ac-c7b3-45dd-961d-aeff38eae88e-0000 I0706 00:02:22.269480 19924 master.cpp:6910] Updating the state of task 69b0dc4a-c67c-4cf3-9c8a-fa280390ad0c of framework 8a9140ac-c7b3-45dd-961d-aeff38eae88e-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING) I0706 00:02:22.269971 19924 master.cpp:4387] Processing ACKNOWLEDGE call c6f01f1a-8511-4b5d-b58f-483ece819a66 for task 69b0dc4a-c67c-4cf3-9c8a-fa280390ad0c of framework 8a9140ac-c7b3-45dd-961d-aeff38eae88e-0000 (default) at scheduler-b038a647-ffab-4290-b583-4f5308a567cf@127.0.0.1:54648 on agent 8a9140ac-c7b3-45dd-961d-aeff38eae88e-S0 I0706 00:02:22.271059 19927 status_update_manager.cpp:392] Received status update acknowledgement (UUID: c6f01f1a-8511-4b5d-b58f-483ece819a66) for task 69b0dc4a-c67c-4cf3-9c8a-fa280390ad0c of framework 8a9140ac-c7b3-45dd-961d-aeff38eae88e-0000 I0706 00:02:22.271200 19927 status_update_manager.cpp:825] Checkpointing ACK for status update TASK_RUNNING (UUID: c6f01f1a-8511-4b5d-b58f-483ece819a66) for task 69b0dc4a-c67c-4cf3-9c8a-fa280390ad0c of framework 8a9140ac-c7b3-45dd-961d-aeff38eae88e-0000 I0706 00:02:22.271878 19907 slave.cpp:839] Agent terminating I0706 00:02:22.272349 19907 containerizer.cpp:196] Using isolation: posix/cpu,posix/mem,disk/du,filesystem/posix,network/cni I0706 00:02:22.272689 19925 master.cpp:1370] Agent 8a9140ac-c7b3-45dd-961d-aeff38eae88e-S0 at slave(37)@127.0.0.1:54648 (centos71) disconnected I0706 00:02:22.272713 19925 master.cpp:2909] Disconnecting agent 8a9140ac-c7b3-45dd-961d-aeff38eae88e-S0 at slave(37)@127.0.0.1:54648 (centos71) I0706 00:02:22.272764 19925 master.cpp:2928] Deactivating agent 8a9140ac-c7b3-45dd-961d-aeff38eae88e-S0 at slave(37)@127.0.0.1:54648 (centos71) I0706 00:02:22.274261 19924 hierarchical.cpp:571] Agent 8a9140ac-c7b3-45dd-961d-aeff38eae88e-S0 deactivated W0706 00:02:22.275003 19907 backend.cpp:75] Failed to create 'bind' backend: BindBackend requires root privileges I0706 00:02:22.282027 19907 cluster.cpp:432] Creating default 'local' authorizer I0706 00:02:22.283777 19927 slave.cpp:203] Agent started on 38)@127.0.0.1:54648 I0706 00:02:22.283797 19927 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="1ms" --containerizers="mesos" --credential="/tmp/DiskQuotaTest_SlaveRecovery_NWOfjE/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/DiskQuotaTest_SlaveRecovery_NWOfjE/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/DiskQuotaTest_SlaveRecovery_NWOfjE/http_credentials" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem,disk/du" --launcher_dir="/vagrant/mesos/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/DiskQuotaTest_SlaveRecovery_NWOfjE" W0706 00:02:22.284045 19927 slave.cpp:207] ************************************************** Agent bound to loopback interface! Cannot communicate with remote master(s). You might want to set '--ip' flag to a routable IP address. ************************************************** I0706 00:02:22.284055 19927 credentials.hpp:86] Loading credential for authentication from '/tmp/DiskQuotaTest_SlaveRecovery_NWOfjE/credential' I0706 00:02:22.284153 19927 slave.cpp:341] Agent using credential for: test-principal I0706 00:02:22.284171 19927 credentials.hpp:37] Loading credentials for authentication from '/tmp/DiskQuotaTest_SlaveRecovery_NWOfjE/http_credentials' I0706 00:02:22.284286 19927 slave.cpp:393] Using default 'basic' HTTP authenticator I0706 00:02:22.285024 19927 slave.cpp:592] Agent resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I0706 00:02:22.285087 19927 slave.cpp:600] Agent attributes: [ ] I0706 00:02:22.285099 19927 slave.cpp:605] Agent hostname: centos71 I0706 00:02:22.287653 19923 state.cpp:57] Recovering state from '/tmp/DiskQuotaTest_SlaveRecovery_NWOfjE/meta' I0706 00:02:22.287786 19923 state.cpp:697] No checkpointed resources found at '/tmp/DiskQuotaTest_SlaveRecovery_NWOfjE/meta/resources/resources.info' I0706 00:02:22.291002 19924 slave.cpp:4926] Recovering framework 8a9140ac-c7b3-45dd-961d-aeff38eae88e-0000 I0706 00:02:22.291090 19924 slave.cpp:5848] Recovering executor '69b0dc4a-c67c-4cf3-9c8a-fa280390ad0c' of framework 8a9140ac-c7b3-45dd-961d-aeff38eae88e-0000 I0706 00:02:22.291898 19923 status_update_manager.cpp:200] Recovering status update manager I0706 00:02:22.291926 19923 status_update_manager.cpp:208] Recovering executor '69b0dc4a-c67c-4cf3-9c8a-fa280390ad0c' of framework 8a9140ac-c7b3-45dd-961d-aeff38eae88e-0000 I0706 00:02:22.293239 19923 containerizer.cpp:522] Recovering containerizer I0706 00:02:22.293393 19923 containerizer.cpp:577] Recovering container '564657c9-460d-44dd-b0fa-86880122e235' for executor '69b0dc4a-c67c-4cf3-9c8a-fa280390ad0c' of framework 8a9140ac-c7b3-45dd-961d-aeff38eae88e-0000 I0706 00:02:22.295188 19926 provisioner.cpp:253] Provisioner recovery complete I0706 00:02:22.296641 19921 slave.cpp:4778] Sending reconnect request to executor '69b0dc4a-c67c-4cf3-9c8a-fa280390ad0c' of framework 8a9140ac-c7b3-45dd-961d-aeff38eae88e-0000 at executor(1)@127.0.0.1:47550 I0706 00:02:22.297539 21070 exec.cpp:282] Received reconnect request from agent 8a9140ac-c7b3-45dd-961d-aeff38eae88e-S0 I0706 00:02:22.298714 19921 slave.cpp:3054] Re-registering executor '69b0dc4a-c67c-4cf3-9c8a-fa280390ad0c' of framework 8a9140ac-c7b3-45dd-961d-aeff38eae88e-0000 I0706 00:02:22.299353 19921 disk.cpp:171] Updating the disk resources for container 564657c9-460d-44dd-b0fa-86880122e235 to cpus(*):1.1; mem(*):160; disk(*):3 I0706 00:02:22.300499 21066 exec.cpp:259] Executor re-registered on agent 8a9140ac-c7b3-45dd-961d-aeff38eae88e-S0 Received SUBSCRIBED event Subscribed executor on centos71 I0706 00:02:22.335578 19924 slave.cpp:3207] Cleaning up un-reregistered executors I0706 00:02:22.336192 19924 slave.cpp:4838] Finished recovery 2+0 records in 2+0 records out 2097152 bytes (2.1 MB) copied, 0.00147459 s, 1.4 GB/s I0706 00:02:22.340747 19924 slave.cpp:967] New master detected at master@127.0.0.1:54648 I0706 00:02:22.340803 19924 slave.cpp:1029] Authenticating with master master@127.0.0.1:54648 I0706 00:02:22.341225 19922 status_update_manager.cpp:174] Pausing sending status updates I0706 00:02:22.341254 19924 slave.cpp:1040] Using default CRAM-MD5 authenticatee I0706 00:02:22.341996 19924 slave.cpp:1002] Detecting new master I0706 00:02:22.342403 19927 authenticatee.cpp:121] Creating new client SASL connection I0706 00:02:22.344084 19927 master.cpp:5967] Authenticating slave(38)@127.0.0.1:54648 I0706 00:02:22.345186 19921 authenticator.cpp:98] Creating new server SASL connection I0706 00:02:22.345496 19921 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 I0706 00:02:22.345523 19921 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' I0706 00:02:22.345600 19921 authenticator.cpp:204] Received SASL authentication start I0706 00:02:22.345643 19921 authenticator.cpp:326] Authentication requires more steps I0706 00:02:22.345716 19921 authenticatee.cpp:259] Received SASL authentication step I0706 00:02:22.345887 19921 authenticator.cpp:232] Received SASL authentication step I0706 00:02:22.345954 19921 authenticator.cpp:318] Authentication success I0706 00:02:22.346141 19921 authenticatee.cpp:299] Authentication success I0706 00:02:22.346236 19921 master.cpp:5997] Successfully authenticated principal 'test-principal' at slave(38)@127.0.0.1:54648 I0706 00:02:22.346822 19924 slave.cpp:1108] Successfully authenticated with master master@127.0.0.1:54648 I0706 00:02:22.348000 19922 master.cpp:4836] Re-registering agent 8a9140ac-c7b3-45dd-961d-aeff38eae88e-S0 at slave(37)@127.0.0.1:54648 (centos71) I0706 00:02:22.348772 19927 slave.cpp:1254] Re-registered with master master@127.0.0.1:54648 I0706 00:02:22.349943 19927 slave.cpp:1290] Forwarding total oversubscribed resources I0706 00:02:22.350136 19922 master.cpp:5028] Sending updated checkpointed resources to agent 8a9140ac-c7b3-45dd-961d-aeff38eae88e-S0 at slave(38)@127.0.0.1:54648 (centos71) I0706 00:02:22.350602 19927 slave.cpp:2443] Updating framework 8a9140ac-c7b3-45dd-961d-aeff38eae88e-0000 pid to scheduler-b038a647-ffab-4290-b583-4f5308a567cf@127.0.0.1:54648 I0706 00:02:22.351361 19926 hierarchical.cpp:559] Agent 8a9140ac-c7b3-45dd-961d-aeff38eae88e-S0 reactivated I0706 00:02:22.351651 19922 master.cpp:5090] Received update of agent 8a9140ac-c7b3-45dd-961d-aeff38eae88e-S0 at slave(38)@127.0.0.1:54648 (centos71) with total oversubscribed resources I0706 00:02:22.352030 19927 slave.cpp:2582] Updated checkpointed resources from to I0706 00:02:22.352006 19922 hierarchical.cpp:542] Agent 8a9140ac-c7b3-45dd-961d-aeff38eae88e-S0 (centos71) updated with oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):1; mem(*):128; disk(*):3) I0706 00:02:22.353199 19925 status_update_manager.cpp:181] Resuming sending status updates I0706 00:02:22.353279 19925 status_update_manager.cpp:181] Resuming sending status updates ../../src/tests/disk_quota_tests.cpp:655: Failure Expected: (usage.get().disk_used_bytes()) > (Kilobytes(64).bytes()), actual: 0 vs 65536 {code} > DiskQuotaTest.SlaveRecovery is flaky > ------------------------------------ > > Key: MESOS-3968 > URL: https://issues.apache.org/jira/browse/MESOS-3968 > Project: Mesos > Issue Type: Bug > Components: test > Reporter: Benjamin Mahler > Labels: flaky-test, mesosphere > > {noformat: title=Failed Run} > [ RUN ] DiskQuotaTest.SlaveRecovery > I1120 12:02:54.015383 29806 leveldb.cpp:176] Opened db in 2.965411ms > I1120 12:02:54.018033 29806 leveldb.cpp:183] Compacted db in 2.585354ms > I1120 12:02:54.018175 29806 leveldb.cpp:198] Created db iterator in 27134ns > I1120 12:02:54.018275 29806 leveldb.cpp:204] Seeked to beginning of db in > 3025ns > I1120 12:02:54.018375 29806 leveldb.cpp:273] Iterated through 0 keys in the > db in 679ns > I1120 12:02:54.018491 29806 replica.cpp:780] Replica recovered with log > positions 0 -> 0 with 1 holes and 0 unlearned > I1120 12:02:54.021386 29838 recover.cpp:449] Starting replica recovery > I1120 12:02:54.021692 29838 recover.cpp:475] Replica is in EMPTY status > I1120 12:02:54.022189 29827 master.cpp:367] Master > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105 (a51e6bb03b55) started on > 172.17.5.188:41228 > I1120 12:02:54.022212 29827 master.cpp:369] Flags at startup: --acls="" > --allocation_interval="1secs" --allocator="HierarchicalDRF" > --authenticate="true" --authenticate_slaves="true" --authenticators="crammd5" > --authorizers="local" --credentials="/tmp/DsMniF/credentials" > --framework_sorter="drf" --help="false" --hostname_lookup="true" > --initialize_driver_logging="true" --log_auto_initialize="true" > --logbufsecs="0" --logging_level="INFO" --max_slave_ping_timeouts="5" > --quiet="false" --recovery_slave_removal_limit="100%" > --registry="replicated_log" --registry_fetch_timeout="1mins" > --registry_store_timeout="25secs" --registry_strict="true" > --root_submissions="true" --slave_ping_timeout="15secs" > --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" > --webui_dir="/mesos/mesos-0.26.0/_inst/share/mesos/webui" > --work_dir="/tmp/DsMniF/master" --zk_session_timeout="10secs" > I1120 12:02:54.022557 29827 master.cpp:414] Master only allowing > authenticated frameworks to register > I1120 12:02:54.022569 29827 master.cpp:419] Master only allowing > authenticated slaves to register > I1120 12:02:54.022578 29827 credentials.hpp:37] Loading credentials for > authentication from '/tmp/DsMniF/credentials' > I1120 12:02:54.022896 29827 master.cpp:458] Using default 'crammd5' > authenticator > I1120 12:02:54.023217 29827 master.cpp:495] Authorization enabled > I1120 12:02:54.023512 29831 whitelist_watcher.cpp:79] No whitelist given > I1120 12:02:54.023814 29833 replica.cpp:676] Replica in EMPTY status received > a broadcasted recover request from (562)@172.17.5.188:41228 > I1120 12:02:54.023519 29832 hierarchical.cpp:153] Initialized hierarchical > allocator process > I1120 12:02:54.025997 29831 recover.cpp:195] Received a recover response from > a replica in EMPTY status > I1120 12:02:54.027042 29832 recover.cpp:566] Updating replica status to > STARTING > I1120 12:02:54.027354 29830 master.cpp:1612] The newly elected leader is > master@172.17.5.188:41228 with id 9a3c45ec-28b3-49e6-a83f-1f2035cc1105 > I1120 12:02:54.027385 29830 master.cpp:1625] Elected as the leading master! > I1120 12:02:54.027403 29830 master.cpp:1385] Recovering from registrar > I1120 12:02:54.027679 29830 registrar.cpp:309] Recovering registrar > I1120 12:02:54.028439 29840 leveldb.cpp:306] Persisting metadata (8 bytes) to > leveldb took 1.195171ms > I1120 12:02:54.028539 29840 replica.cpp:323] Persisted replica status to > STARTING > I1120 12:02:54.028944 29840 recover.cpp:475] Replica is in STARTING status > I1120 12:02:54.030910 29840 replica.cpp:676] Replica in STARTING status > received a broadcasted recover request from (563)@172.17.5.188:41228 > I1120 12:02:54.031429 29840 recover.cpp:195] Received a recover response from > a replica in STARTING status > I1120 12:02:54.032032 29840 recover.cpp:566] Updating replica status to VOTING > I1120 12:02:54.032816 29840 leveldb.cpp:306] Persisting metadata (8 bytes) to > leveldb took 496492ns > I1120 12:02:54.032982 29840 replica.cpp:323] Persisted replica status to > VOTING > I1120 12:02:54.033254 29840 recover.cpp:580] Successfully joined the Paxos > group > I1120 12:02:54.033562 29840 recover.cpp:464] Recover process terminated > I1120 12:02:54.034631 29839 log.cpp:661] Attempting to start the writer > I1120 12:02:54.036386 29834 replica.cpp:496] Replica received implicit > promise request from (564)@172.17.5.188:41228 with proposal 1 > I1120 12:02:54.037082 29834 leveldb.cpp:306] Persisting metadata (8 bytes) to > leveldb took 642707ns > I1120 12:02:54.037116 29834 replica.cpp:345] Persisted promised to 1 > I1120 12:02:54.038153 29834 coordinator.cpp:240] Coordinator attempting to > fill missing positions > I1120 12:02:54.039929 29828 replica.cpp:391] Replica received explicit > promise request from (565)@172.17.5.188:41228 for position 0 with proposal 2 > I1120 12:02:54.040452 29828 leveldb.cpp:343] Persisting action (8 bytes) to > leveldb took 459163ns > I1120 12:02:54.040480 29828 replica.cpp:715] Persisted action at 0 > I1120 12:02:54.041595 29828 replica.cpp:540] Replica received write request > for position 0 from (566)@172.17.5.188:41228 > I1120 12:02:54.041657 29828 leveldb.cpp:438] Reading position from leveldb > took 31405ns > I1120 12:02:54.041990 29828 leveldb.cpp:343] Persisting action (14 bytes) to > leveldb took 285183ns > I1120 12:02:54.042017 29828 replica.cpp:715] Persisted action at 0 > I1120 12:02:54.042682 29828 replica.cpp:694] Replica received learned notice > for position 0 from @0.0.0.0:0 > I1120 12:02:54.043001 29828 leveldb.cpp:343] Persisting action (16 bytes) to > leveldb took 289557ns > I1120 12:02:54.043027 29828 replica.cpp:715] Persisted action at 0 > I1120 12:02:54.043047 29828 replica.cpp:700] Replica learned NOP action at > position 0 > I1120 12:02:54.044025 29828 log.cpp:677] Writer started with ending position 0 > I1120 12:02:54.045470 29832 leveldb.cpp:438] Reading position from leveldb > took 64416ns > I1120 12:02:54.046702 29835 registrar.cpp:342] Successfully fetched the > registry (0B) in 18.969088ms > I1120 12:02:54.046843 29835 registrar.cpp:441] Applied 1 operations in > 33491ns; attempting to update the 'registry' > I1120 12:02:54.047698 29835 log.cpp:685] Attempting to append 176 bytes to > the log > I1120 12:02:54.047878 29830 coordinator.cpp:350] Coordinator attempting to > write APPEND action at position 1 > I1120 12:02:54.048619 29830 replica.cpp:540] Replica received write request > for position 1 from (567)@172.17.5.188:41228 > I1120 12:02:54.049104 29830 leveldb.cpp:343] Persisting action (195 bytes) to > leveldb took 447606ns > I1120 12:02:54.049131 29830 replica.cpp:715] Persisted action at 1 > I1120 12:02:54.049968 29830 replica.cpp:694] Replica received learned notice > for position 1 from @0.0.0.0:0 > I1120 12:02:54.050310 29830 leveldb.cpp:343] Persisting action (197 bytes) to > leveldb took 312460ns > I1120 12:02:54.050335 29830 replica.cpp:715] Persisted action at 1 > I1120 12:02:54.050354 29830 replica.cpp:700] Replica learned APPEND action at > position 1 > I1120 12:02:54.051472 29837 registrar.cpp:486] Successfully updated the > 'registry' in 4.566016ms > I1120 12:02:54.051630 29837 registrar.cpp:372] Successfully recovered > registrar > I1120 12:02:54.051705 29830 log.cpp:704] Attempting to truncate the log to 1 > I1120 12:02:54.051820 29825 coordinator.cpp:350] Coordinator attempting to > write TRUNCATE action at position 2 > I1120 12:02:54.052055 29835 master.cpp:1422] Recovered 0 slaves from the > Registry (137B) ; allowing 10mins for slaves to re-register > I1120 12:02:54.052665 29839 replica.cpp:540] Replica received write request > for position 2 from (568)@172.17.5.188:41228 > I1120 12:02:54.052981 29839 leveldb.cpp:343] Persisting action (16 bytes) to > leveldb took 279767ns > I1120 12:02:54.053007 29839 replica.cpp:715] Persisted action at 2 > I1120 12:02:54.053591 29826 replica.cpp:694] Replica received learned notice > for position 2 from @0.0.0.0:0 > I1120 12:02:54.054116 29826 leveldb.cpp:343] Persisting action (18 bytes) to > leveldb took 455681ns > I1120 12:02:54.054214 29826 leveldb.cpp:401] Deleting ~1 keys from leveldb > took 36349ns > I1120 12:02:54.054291 29826 replica.cpp:715] Persisted action at 2 > I1120 12:02:54.054363 29826 replica.cpp:700] Replica learned TRUNCATE action > at position 2 > I1120 12:02:54.064028 29806 containerizer.cpp:143] Using isolation: > posix/cpu,posix/mem,posix/disk,filesystem/posix > W1120 12:02:54.064376 29806 backend.cpp:50] Failed to create 'bind' backend: > BindBackend requires root privileges > I1120 12:02:54.068229 29838 slave.cpp:191] Slave started on > 15)@172.17.5.188:41228 > I1120 12:02:54.068256 29838 slave.cpp:192] Flags at startup: > --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" > --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="1ms" > --containerizers="mesos" > --credential="/tmp/DiskQuotaTest_SlaveRecovery_jdV8yV/credential" > --default_role="*" --disk_watch_interval="1mins" --docker="docker" > --docker_auth_server="auth.docker.io" --docker_auth_server_port="443" > --docker_kill_orphans="true" > --docker_local_archives_dir="/tmp/mesos/images/docker" > --docker_puller="local" --docker_puller_timeout="60" > --docker_registry="registry-1.docker.io" --docker_registry_port="443" > --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" > --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" > --enforce_container_disk_quota="false" > --executor_registration_timeout="1mins" > --executor_shutdown_grace_period="5secs" > --fetcher_cache_dir="/tmp/DiskQuotaTest_SlaveRecovery_jdV8yV/fetch" > --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" > --gc_disk_headroom="0.1" --hadoop_home="" --help="false" > --hostname_lookup="true" --image_provisioner_backend="copy" > --initialize_driver_logging="true" > --isolation="posix/cpu,posix/mem,posix/disk" > --launcher_dir="/mesos/mesos-0.26.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;mem:1024;disk:1024;ports:[31000-32000]" > --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" > --strict="true" --switch_user="true" > --systemd_runtime_directory="/run/systemd/system" --version="false" > --work_dir="/tmp/DiskQuotaTest_SlaveRecovery_jdV8yV" > I1120 12:02:54.068590 29838 credentials.hpp:85] Loading credential for > authentication from '/tmp/DiskQuotaTest_SlaveRecovery_jdV8yV/credential' > I1120 12:02:54.068781 29838 slave.cpp:322] Slave using credential for: > test-principal > I1120 12:02:54.069118 29838 resources.cpp:474] Parsing resources as JSON > failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000] > Trying semicolon-delimited string format instead > I1120 12:02:54.069506 29838 slave.cpp:392] Slave resources: cpus(*):2; > mem(*):1024; disk(*):1024; ports(*):[31000-32000] > I1120 12:02:54.069566 29838 slave.cpp:400] Slave attributes: [ ] > I1120 12:02:54.069576 29838 slave.cpp:405] Slave hostname: a51e6bb03b55 > I1120 12:02:54.069582 29838 slave.cpp:410] Slave checkpoint: true > I1120 12:02:54.070355 29806 sched.cpp:166] Version: 0.26.0 > I1120 12:02:54.070415 29840 state.cpp:54] Recovering state from > '/tmp/DiskQuotaTest_SlaveRecovery_jdV8yV/meta' > I1120 12:02:54.070790 29826 status_update_manager.cpp:202] Recovering status > update manager > I1120 12:02:54.070873 29832 sched.cpp:264] New master detected at > master@172.17.5.188:41228 > I1120 12:02:54.070976 29832 sched.cpp:320] Authenticating with master > master@172.17.5.188:41228 > I1120 12:02:54.070996 29832 sched.cpp:327] Using default CRAM-MD5 > authenticatee > I1120 12:02:54.071059 29830 containerizer.cpp:385] Recovering containerizer > I1120 12:02:54.071216 29837 authenticatee.cpp:123] Creating new client SASL > connection > I1120 12:02:54.071487 29828 master.cpp:5156] Authenticating > scheduler-a51a061b-8755-4242-9a63-69e987a1c91d@172.17.5.188:41228 > I1120 12:02:54.071609 29826 authenticator.cpp:415] Starting authentication > session for crammd5_authenticatee(57)@172.17.5.188:41228 > I1120 12:02:54.071931 29839 authenticator.cpp:100] Creating new server SASL > connection > I1120 12:02:54.072005 29831 slave.cpp:4230] Finished recovery > I1120 12:02:54.072157 29827 authenticatee.cpp:214] Received SASL > authentication mechanisms: CRAM-MD5 > I1120 12:02:54.072187 29827 authenticatee.cpp:240] Attempting to authenticate > with mechanism 'CRAM-MD5' > I1120 12:02:54.072280 29835 authenticator.cpp:205] Received SASL > authentication start > I1120 12:02:54.072341 29835 authenticator.cpp:327] Authentication requires > more steps > I1120 12:02:54.072439 29838 authenticatee.cpp:260] Received SASL > authentication step > I1120 12:02:54.072506 29831 slave.cpp:4387] Querying resource estimator for > oversubscribable resources > I1120 12:02:54.072712 29839 authenticator.cpp:233] Received SASL > authentication step > I1120 12:02:54.072726 29831 slave.cpp:729] New master detected at > master@172.17.5.188:41228 > I1120 12:02:54.072747 29839 auxprop.cpp:109] Request to lookup properties for > user: 'test-principal' realm: 'a51e6bb03b55' server FQDN: 'a51e6bb03b55' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: false > I1120 12:02:54.072753 29828 status_update_manager.cpp:176] Pausing sending > status updates > I1120 12:02:54.072772 29839 auxprop.cpp:181] Looking up auxiliary property > '*userPassword' > I1120 12:02:54.072790 29831 slave.cpp:792] Authenticating with master > master@172.17.5.188:41228 > I1120 12:02:54.072811 29831 slave.cpp:797] Using default CRAM-MD5 > authenticatee > I1120 12:02:54.072821 29839 auxprop.cpp:181] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I1120 12:02:54.072849 29839 auxprop.cpp:109] Request to lookup properties for > user: 'test-principal' realm: 'a51e6bb03b55' server FQDN: 'a51e6bb03b55' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: true > I1120 12:02:54.072861 29839 auxprop.cpp:131] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I1120 12:02:54.072870 29839 auxprop.cpp:131] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I1120 12:02:54.072887 29839 authenticator.cpp:319] Authentication success > I1120 12:02:54.072921 29831 slave.cpp:765] Detecting new master > I1120 12:02:54.072978 29825 authenticatee.cpp:123] Creating new client SASL > connection > I1120 12:02:54.073007 29832 authenticatee.cpp:300] Authentication success > I1120 12:02:54.073041 29836 master.cpp:5186] Successfully authenticated > principal 'test-principal' at > scheduler-a51a061b-8755-4242-9a63-69e987a1c91d@172.17.5.188:41228 > I1120 12:02:54.073103 29834 authenticator.cpp:433] Authentication session > cleanup for crammd5_authenticatee(57)@172.17.5.188:41228 > I1120 12:02:54.073169 29831 slave.cpp:4401] Received oversubscribable > resources from the resource estimator > I1120 12:02:54.073313 29839 sched.cpp:409] Successfully authenticated with > master master@172.17.5.188:41228 > I1120 12:02:54.073338 29839 sched.cpp:716] Sending SUBSCRIBE call to > master@172.17.5.188:41228 > I1120 12:02:54.073359 29836 master.cpp:5156] Authenticating > slave(15)@172.17.5.188:41228 > I1120 12:02:54.073415 29839 sched.cpp:749] Will retry registration in > 689.900282ms if necessary > I1120 12:02:54.073447 29837 authenticator.cpp:415] Starting authentication > session for crammd5_authenticatee(58)@172.17.5.188:41228 > I1120 12:02:54.073626 29840 authenticator.cpp:100] Creating new server SASL > connection > I1120 12:02:54.073645 29836 master.cpp:2182] Received SUBSCRIBE call for > framework 'default' at > scheduler-a51a061b-8755-4242-9a63-69e987a1c91d@172.17.5.188:41228 > I1120 12:02:54.073698 29836 master.cpp:1651] Authorizing framework principal > 'test-principal' to receive offers for role '*' > I1120 12:02:54.073815 29827 authenticatee.cpp:214] Received SASL > authentication mechanisms: CRAM-MD5 > I1120 12:02:54.073845 29827 authenticatee.cpp:240] Attempting to authenticate > with mechanism 'CRAM-MD5' > I1120 12:02:54.073977 29840 authenticator.cpp:205] Received SASL > authentication start > I1120 12:02:54.074062 29840 authenticator.cpp:327] Authentication requires > more steps > I1120 12:02:54.074100 29830 master.cpp:2253] Subscribing framework default > with checkpointing enabled and capabilities [ ] > I1120 12:02:54.074146 29840 authenticatee.cpp:260] Received SASL > authentication step > I1120 12:02:54.074242 29837 authenticator.cpp:233] Received SASL > authentication step > I1120 12:02:54.074272 29837 auxprop.cpp:109] Request to lookup properties for > user: 'test-principal' realm: 'a51e6bb03b55' server FQDN: 'a51e6bb03b55' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: false > I1120 12:02:54.074285 29837 auxprop.cpp:181] Looking up auxiliary property > '*userPassword' > I1120 12:02:54.074309 29837 auxprop.cpp:181] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I1120 12:02:54.074326 29837 auxprop.cpp:109] Request to lookup properties for > user: 'test-principal' realm: 'a51e6bb03b55' server FQDN: 'a51e6bb03b55' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: true > I1120 12:02:54.074334 29837 auxprop.cpp:131] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I1120 12:02:54.074343 29837 auxprop.cpp:131] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I1120 12:02:54.074362 29837 authenticator.cpp:319] Authentication success > I1120 12:02:54.074432 29840 authenticatee.cpp:300] Authentication success > I1120 12:02:54.074466 29834 hierarchical.cpp:197] Added framework > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 > I1120 12:02:54.074501 29831 authenticator.cpp:433] Authentication session > cleanup for crammd5_authenticatee(58)@172.17.5.188:41228 > I1120 12:02:54.074522 29834 hierarchical.cpp:979] No resources available to > allocate! > I1120 12:02:54.074558 29834 hierarchical.cpp:1072] No inverse offers to send > out! > I1120 12:02:54.074553 29830 master.cpp:5186] Successfully authenticated > principal 'test-principal' at slave(15)@172.17.5.188:41228 > I1120 12:02:54.074589 29834 hierarchical.cpp:878] Performed allocation for 0 > slaves in 102842ns > I1120 12:02:54.074692 29837 slave.cpp:860] Successfully authenticated with > master master@172.17.5.188:41228 > I1120 12:02:54.074815 29837 slave.cpp:1254] Will retry registration in > 79918ns if necessary > I1120 12:02:54.074836 29840 sched.cpp:643] Framework registered with > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 > I1120 12:02:54.074882 29840 sched.cpp:657] Scheduler::registered took 22019ns > I1120 12:02:54.075027 29835 master.cpp:3865] Registering slave at > slave(15)@172.17.5.188:41228 (a51e6bb03b55) with id > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 > I1120 12:02:54.075202 29838 slave.cpp:1254] Will retry registration in > 21.508543ms if necessary > I1120 12:02:54.075392 29835 master.cpp:3853] Ignoring register slave message > from slave(15)@172.17.5.188:41228 (a51e6bb03b55) as admission is already in > progress > I1120 12:02:54.075512 29839 registrar.cpp:441] Applied 1 operations in > 69618ns; attempting to update the 'registry' > I1120 12:02:54.076251 29836 log.cpp:685] Attempting to append 345 bytes to > the log > I1120 12:02:54.076375 29825 coordinator.cpp:350] Coordinator attempting to > write APPEND action at position 3 > I1120 12:02:54.077157 29835 replica.cpp:540] Replica received write request > for position 3 from (582)@172.17.5.188:41228 > I1120 12:02:54.077776 29835 leveldb.cpp:343] Persisting action (364 bytes) to > leveldb took 574611ns > I1120 12:02:54.077800 29835 replica.cpp:715] Persisted action at 3 > I1120 12:02:54.078423 29836 replica.cpp:694] Replica received learned notice > for position 3 from @0.0.0.0:0 > I1120 12:02:54.078816 29836 leveldb.cpp:343] Persisting action (366 bytes) to > leveldb took 364281ns > I1120 12:02:54.078838 29836 replica.cpp:715] Persisted action at 3 > I1120 12:02:54.078855 29836 replica.cpp:700] Replica learned APPEND action at > position 3 > I1120 12:02:54.080191 29828 registrar.cpp:486] Successfully updated the > 'registry' in 4.57088ms > I1120 12:02:54.080413 29839 log.cpp:704] Attempting to truncate the log to 3 > I1120 12:02:54.080533 29838 coordinator.cpp:350] Coordinator attempting to > write TRUNCATE action at position 4 > I1120 12:02:54.081109 29833 slave.cpp:3169] Received ping from > slave-observer(14)@172.17.5.188:41228 > I1120 12:02:54.081207 29829 master.cpp:3933] Registered slave > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 at slave(15)@172.17.5.188:41228 > (a51e6bb03b55) with cpus(*):2; mem(*):1024; disk(*):1024; > ports(*):[31000-32000] > I1120 12:02:54.081274 29835 replica.cpp:540] Replica received write request > for position 4 from (583)@172.17.5.188:41228 > I1120 12:02:54.081352 29833 slave.cpp:904] Registered with master > master@172.17.5.188:41228; given slave ID > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 > I1120 12:02:54.081351 29831 hierarchical.cpp:346] Added slave > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 (a51e6bb03b55) with cpus(*):2; > mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: ) > I1120 12:02:54.081375 29833 fetcher.cpp:79] Clearing fetcher cache > I1120 12:02:54.081533 29840 status_update_manager.cpp:183] Resuming sending > status updates > I1120 12:02:54.081712 29835 leveldb.cpp:343] Persisting action (16 bytes) to > leveldb took 395576ns > I1120 12:02:54.081740 29835 replica.cpp:715] Persisted action at 4 > I1120 12:02:54.081778 29833 slave.cpp:927] Checkpointing SlaveInfo to > '/tmp/DiskQuotaTest_SlaveRecovery_jdV8yV/meta/slaves/9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0/slave.info' > I1120 12:02:54.082193 29833 slave.cpp:963] Forwarding total oversubscribed > resources > I1120 12:02:54.082223 29831 hierarchical.cpp:1072] No inverse offers to send > out! > I1120 12:02:54.082295 29831 hierarchical.cpp:894] Performed allocation for > slave 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 in 899836ns > I1120 12:02:54.082224 29838 replica.cpp:694] Replica received learned notice > for position 4 from @0.0.0.0:0 > I1120 12:02:54.082574 29827 master.cpp:4985] Sending 1 offers to framework > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 (default) at > scheduler-a51a061b-8755-4242-9a63-69e987a1c91d@172.17.5.188:41228 > I1120 12:02:54.082801 29827 master.cpp:4275] Received update of slave > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 at slave(15)@172.17.5.188:41228 > (a51e6bb03b55) with total oversubscribed resources > I1120 12:02:54.082866 29838 leveldb.cpp:343] Persisting action (18 bytes) to > leveldb took 437289ns > I1120 12:02:54.083017 29838 leveldb.cpp:401] Deleting ~2 keys from leveldb > took 46020ns > I1120 12:02:54.083115 29838 replica.cpp:715] Persisted action at 4 > I1120 12:02:54.083103 29837 hierarchical.cpp:402] Slave > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 (a51e6bb03b55) updated with > oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; > ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; > ports(*):[31000-32000]) > I1120 12:02:54.083201 29834 sched.cpp:813] Scheduler::resourceOffers took > 183293ns > I1120 12:02:54.083201 29838 replica.cpp:700] Replica learned TRUNCATE action > at position 4 > I1120 12:02:54.083613 29806 resources.cpp:474] Parsing resources as JSON > failed: cpus:1;mem:128;disk:3 > Trying semicolon-delimited string format instead > I1120 12:02:54.083685 29837 hierarchical.cpp:979] No resources available to > allocate! > I1120 12:02:54.083792 29837 hierarchical.cpp:1072] No inverse offers to send > out! > I1120 12:02:54.083818 29837 hierarchical.cpp:894] Performed allocation for > slave 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 in 553630ns > I1120 12:02:54.084825 29832 master.cpp:2921] Processing ACCEPT call for > offers: [ 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-O0 ] on slave > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 at slave(15)@172.17.5.188:41228 > (a51e6bb03b55) for framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 > (default) at scheduler-a51a061b-8755-4242-9a63-69e987a1c91d@172.17.5.188:41228 > I1120 12:02:54.084867 29832 master.cpp:2717] Authorizing framework principal > 'test-principal' to launch task a40b962c-6507-488b-812f-af506f2c1206 as user > 'mesos' > I1120 12:02:54.086195 29836 master.hpp:178] Adding task > a40b962c-6507-488b-812f-af506f2c1206 with resources cpus(*):1; mem(*):128; > disk(*):3 on slave 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 (a51e6bb03b55) > I1120 12:02:54.086338 29836 master.cpp:3251] Launching task > a40b962c-6507-488b-812f-af506f2c1206 of framework > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 (default) at > scheduler-a51a061b-8755-4242-9a63-69e987a1c91d@172.17.5.188:41228 with > resources cpus(*):1; mem(*):128; disk(*):3 on slave > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 at slave(15)@172.17.5.188:41228 > (a51e6bb03b55) > I1120 12:02:54.086685 29840 slave.cpp:1294] Got assigned task > a40b962c-6507-488b-812f-af506f2c1206 for framework > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 > I1120 12:02:54.086848 29840 slave.cpp:4920] Checkpointing FrameworkInfo to > '/tmp/DiskQuotaTest_SlaveRecovery_jdV8yV/meta/slaves/9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0/frameworks/9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000/framework.info' > I1120 12:02:54.086874 29833 hierarchical.cpp:746] Recovered cpus(*):1; > mem(*):896; disk(*):1021; ports(*):[31000-32000] (total: cpus(*):2; > mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):1; > mem(*):128; disk(*):3) on slave 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 from > framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 > I1120 12:02:54.086925 29833 hierarchical.cpp:783] Framework > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 filtered slave > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 for 5secs > I1120 12:02:54.087383 29840 slave.cpp:4931] Checkpointing framework pid > 'scheduler-a51a061b-8755-4242-9a63-69e987a1c91d@172.17.5.188:41228' to > '/tmp/DiskQuotaTest_SlaveRecovery_jdV8yV/meta/slaves/9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0/frameworks/9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000/framework.pid' > I1120 12:02:54.087718 29840 resources.cpp:474] Parsing resources as JSON > failed: cpus:0.1;mem:32 > Trying semicolon-delimited string format instead > I1120 12:02:54.088153 29840 slave.cpp:1410] Launching task > a40b962c-6507-488b-812f-af506f2c1206 for framework > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 > I1120 12:02:54.088251 29840 resources.cpp:474] Parsing resources as JSON > failed: cpus:0.1;mem:32 > Trying semicolon-delimited string format instead > I1120 12:02:54.088942 29840 paths.cpp:436] Trying to chown > '/tmp/DiskQuotaTest_SlaveRecovery_jdV8yV/slaves/9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0/frameworks/9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000/executors/a40b962c-6507-488b-812f-af506f2c1206/runs/d73a9e9b-b646-4f63-85b9-d632ceb1f075' > to user 'mesos' > I1120 12:02:54.092754 29840 slave.cpp:5360] Checkpointing ExecutorInfo to > '/tmp/DiskQuotaTest_SlaveRecovery_jdV8yV/meta/slaves/9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0/frameworks/9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000/executors/a40b962c-6507-488b-812f-af506f2c1206/executor.info' > I1120 12:02:54.093534 29840 slave.cpp:4999] Launching executor > a40b962c-6507-488b-812f-af506f2c1206 of framework > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 with resources cpus(*):0.1; > mem(*):32 in work directory > '/tmp/DiskQuotaTest_SlaveRecovery_jdV8yV/slaves/9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0/frameworks/9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000/executors/a40b962c-6507-488b-812f-af506f2c1206/runs/d73a9e9b-b646-4f63-85b9-d632ceb1f075' > I1120 12:02:54.094018 29838 containerizer.cpp:619] Starting container > 'd73a9e9b-b646-4f63-85b9-d632ceb1f075' for executor > 'a40b962c-6507-488b-812f-af506f2c1206' of framework > '9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000' > I1120 12:02:54.094111 29840 slave.cpp:5383] Checkpointing TaskInfo to > '/tmp/DiskQuotaTest_SlaveRecovery_jdV8yV/meta/slaves/9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0/frameworks/9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000/executors/a40b962c-6507-488b-812f-af506f2c1206/runs/d73a9e9b-b646-4f63-85b9-d632ceb1f075/tasks/a40b962c-6507-488b-812f-af506f2c1206/task.info' > I1120 12:02:54.094547 29840 slave.cpp:1628] Queuing task > 'a40b962c-6507-488b-812f-af506f2c1206' for executor > 'a40b962c-6507-488b-812f-af506f2c1206' of framework > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 > I1120 12:02:54.094662 29840 slave.cpp:682] Successfully attached file > '/tmp/DiskQuotaTest_SlaveRecovery_jdV8yV/slaves/9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0/frameworks/9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000/executors/a40b962c-6507-488b-812f-af506f2c1206/runs/d73a9e9b-b646-4f63-85b9-d632ceb1f075' > I1120 12:02:54.097172 29825 launcher.cpp:134] Forked child with pid '30021' > for container 'd73a9e9b-b646-4f63-85b9-d632ceb1f075' > I1120 12:02:54.097375 29825 containerizer.cpp:852] Checkpointing executor's > forked pid 30021 to > '/tmp/DiskQuotaTest_SlaveRecovery_jdV8yV/meta/slaves/9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0/frameworks/9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000/executors/a40b962c-6507-488b-812f-af506f2c1206/runs/d73a9e9b-b646-4f63-85b9-d632ceb1f075/pids/forked.pid' > WARNING: Logging before InitGoogleLogging() is written to STDERR > I1120 12:02:54.254101 30035 process.cpp:961] libprocess is initialized on > 172.17.5.188:52276 for 16 cpus > I1120 12:02:54.255296 30035 logging.cpp:177] Logging to STDERR > I1120 12:02:54.258533 30035 exec.cpp:136] Version: 0.26.0 > I1120 12:02:54.269281 30058 exec.cpp:186] Executor started at: > executor(1)@172.17.5.188:52276 with pid 30035 > I1120 12:02:54.272449 29837 slave.cpp:2405] Got registration for executor > 'a40b962c-6507-488b-812f-af506f2c1206' of framework > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 from executor(1)@172.17.5.188:52276 > I1120 12:02:54.272603 29837 slave.cpp:2490] Checkpointing executor pid > 'executor(1)@172.17.5.188:52276' to > '/tmp/DiskQuotaTest_SlaveRecovery_jdV8yV/meta/slaves/9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0/frameworks/9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000/executors/a40b962c-6507-488b-812f-af506f2c1206/runs/d73a9e9b-b646-4f63-85b9-d632ceb1f075/pids/libprocess.pid' > I1120 12:02:54.274507 29830 disk.cpp:154] Updating the disk resources for > container d73a9e9b-b646-4f63-85b9-d632ceb1f075 to cpus(*):1.1; mem(*):160; > disk(*):3 > I1120 12:02:54.275303 29839 slave.cpp:1793] Sending queued task > 'a40b962c-6507-488b-812f-af506f2c1206' to executor > 'a40b962c-6507-488b-812f-af506f2c1206' of framework > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 at executor(1)@172.17.5.188:52276 > I1120 12:02:54.275486 30058 exec.cpp:210] Executor registered on slave > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 > I1120 12:02:54.277315 30058 exec.cpp:222] Executor::registered took 318201ns > Registered executor on a51e6bb03b55 > I1120 12:02:54.278136 30051 exec.cpp:297] Executor asked to run task > 'a40b962c-6507-488b-812f-af506f2c1206' > Starting task a40b962c-6507-488b-812f-af506f2c1206 > I1120 12:02:54.278244 30051 exec.cpp:306] Executor::launchTask took 76292ns > sh -c 'dd if=/dev/zero of=file bs=1048576 count=2 && sleep 1000' > Forked command at 30067 > I1120 12:02:54.281972 30057 exec.cpp:519] Executor sending status update > TASK_RUNNING (UUID: ed7ce1df-70bd-42e9-a09d-e16b79d78f4c) for task > a40b962c-6507-488b-812f-af506f2c1206 of framework > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 > 2+0 records in > 2+0 records out > 2097152 bytes (2.1 MB) copied, 0.00335268 s, 626 MB/s > I1120 12:02:55.025218 29827 hierarchical.cpp:1164] Filtered offer with > cpus(*):1; mem(*):896; disk(*):1021; ports(*):[31000-32000] on slave > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 for framework > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 > I1120 12:02:55.025296 29827 hierarchical.cpp:979] No resources available to > allocate! > I1120 12:02:55.025339 29827 hierarchical.cpp:1072] No inverse offers to send > out! > I1120 12:02:55.025367 29827 hierarchical.cpp:878] Performed allocation for 1 > slaves in 821045ns > I1120 12:02:56.027402 29838 hierarchical.cpp:1164] Filtered offer with > cpus(*):1; mem(*):896; disk(*):1021; ports(*):[31000-32000] on slave > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 for framework > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 > I1120 12:02:56.027516 29838 hierarchical.cpp:979] No resources available to > allocate! > I1120 12:02:56.027566 29838 hierarchical.cpp:1072] No inverse offers to send > out! > I1120 12:02:56.027598 29838 hierarchical.cpp:878] Performed allocation for 1 > slaves in 1.05848ms > I1120 12:02:57.028882 29840 hierarchical.cpp:1164] Filtered offer with > cpus(*):1; mem(*):896; disk(*):1021; ports(*):[31000-32000] on slave > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 for framework > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 > I1120 12:02:57.028995 29840 hierarchical.cpp:979] No resources available to > allocate! > I1120 12:02:57.029047 29840 hierarchical.cpp:1072] No inverse offers to send > out! > I1120 12:02:57.029079 29840 hierarchical.cpp:878] Performed allocation for 1 > slaves in 991084ns > I1120 12:02:58.030680 29828 hierarchical.cpp:1164] Filtered offer with > cpus(*):1; mem(*):896; disk(*):1021; ports(*):[31000-32000] on slave > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 for framework > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 > I1120 12:02:58.030779 29828 hierarchical.cpp:979] No resources available to > allocate! > I1120 12:02:58.030824 29828 hierarchical.cpp:1072] No inverse offers to send > out! > I1120 12:02:58.030853 29828 hierarchical.cpp:878] Performed allocation for 1 > slaves in 869985ns > I1120 12:02:59.032424 29837 hierarchical.cpp:1164] Filtered offer with > cpus(*):1; mem(*):896; disk(*):1021; ports(*):[31000-32000] on slave > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 for framework > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 > I1120 12:02:59.032526 29837 hierarchical.cpp:979] No resources available to > allocate! > I1120 12:02:59.032574 29837 hierarchical.cpp:1072] No inverse offers to send > out! > I1120 12:02:59.032604 29837 hierarchical.cpp:878] Performed allocation for 1 > slaves in 930207ns > I1120 12:03:00.034873 29839 hierarchical.cpp:1072] No inverse offers to send > out! > I1120 12:03:00.034943 29839 hierarchical.cpp:878] Performed allocation for 1 > slaves in 851471ns > I1120 12:03:00.035372 29839 master.cpp:4985] Sending 1 offers to framework > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 (default) at > scheduler-a51a061b-8755-4242-9a63-69e987a1c91d@172.17.5.188:41228 > I1120 12:03:00.035830 29828 sched.cpp:813] Scheduler::resourceOffers took > 27519ns > I1120 12:03:01.036597 29838 hierarchical.cpp:979] No resources available to > allocate! > I1120 12:03:01.036702 29838 hierarchical.cpp:1072] No inverse offers to send > out! > I1120 12:03:01.036738 29838 hierarchical.cpp:878] Performed allocation for 1 > slaves in 786983ns > I1120 12:03:02.038766 29828 hierarchical.cpp:979] No resources available to > allocate! > I1120 12:03:02.038861 29828 hierarchical.cpp:1072] No inverse offers to send > out! > I1120 12:03:02.038895 29828 hierarchical.cpp:878] Performed allocation for 1 > slaves in 737171ns > I1120 12:03:03.040204 29836 hierarchical.cpp:979] No resources available to > allocate! > I1120 12:03:03.040279 29836 hierarchical.cpp:1072] No inverse offers to send > out! > I1120 12:03:03.040397 29836 hierarchical.cpp:878] Performed allocation for 1 > slaves in 677058ns > I1120 12:03:04.042060 29831 hierarchical.cpp:979] No resources available to > allocate! > I1120 12:03:04.042136 29831 hierarchical.cpp:1072] No inverse offers to send > out! > I1120 12:03:04.042163 29831 hierarchical.cpp:878] Performed allocation for 1 > slaves in 568286ns > I1120 12:03:05.043707 29838 hierarchical.cpp:979] No resources available to > allocate! > I1120 12:03:05.043797 29838 hierarchical.cpp:1072] No inverse offers to send > out! > I1120 12:03:05.043826 29838 hierarchical.cpp:878] Performed allocation for 1 > slaves in 701131ns > I1120 12:03:06.045091 29836 hierarchical.cpp:979] No resources available to > allocate! > I1120 12:03:06.045178 29836 hierarchical.cpp:1072] No inverse offers to send > out! > I1120 12:03:06.045208 29836 hierarchical.cpp:878] Performed allocation for 1 > slaves in 683215ns > I1120 12:03:07.046598 29835 hierarchical.cpp:979] No resources available to > allocate! > I1120 12:03:07.046681 29835 hierarchical.cpp:1072] No inverse offers to send > out! > I1120 12:03:07.046711 29835 hierarchical.cpp:878] Performed allocation for 1 > slaves in 645715ns > I1120 12:03:08.048492 29827 hierarchical.cpp:979] No resources available to > allocate! > I1120 12:03:08.048583 29827 hierarchical.cpp:1072] No inverse offers to send > out! > I1120 12:03:08.048614 29827 hierarchical.cpp:878] Performed allocation for 1 > slaves in 673997ns > I1120 12:03:09.050271 29832 hierarchical.cpp:979] No resources available to > allocate! > I1120 12:03:09.050374 29832 hierarchical.cpp:1072] No inverse offers to send > out! > I1120 12:03:09.050417 29832 hierarchical.cpp:878] Performed allocation for 1 > slaves in 894773ns > I1120 12:03:09.074158 29834 slave.cpp:4387] Querying resource estimator for > oversubscribable resources > I1120 12:03:09.074461 29834 slave.cpp:4401] Received oversubscribable > resources from the resource estimator > I1120 12:03:09.081683 29840 slave.cpp:3169] Received ping from > slave-observer(14)@172.17.5.188:41228 > ../../src/tests/disk_quota_tests.cpp:465: Failure > Failed to wait 15secs for status > I1120 12:03:09.089833 29825 master.cpp:1128] Framework > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 (default) at > scheduler-a51a061b-8755-4242-9a63-69e987a1c91d@172.17.5.188:41228 disconnected > I1120 12:03:09.090107 29825 master.cpp:2478] Disconnecting framework > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 (default) at > scheduler-a51a061b-8755-4242-9a63-69e987a1c91d@172.17.5.188:41228 > I1120 12:03:09.090232 29825 master.cpp:2502] Deactivating framework > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 (default) at > scheduler-a51a061b-8755-4242-9a63-69e987a1c91d@172.17.5.188:41228 > ../../src/tests/disk_quota_tests.cpp:459: Failure > Actual function call count doesn't match EXPECT_CALL(sched, > statusUpdate(&driver, _))... > Expected: to be called at least once > Actual: never called - unsatisfied and active > W1120 12:03:09.090963 29825 master.hpp:1623] Master attempted to send message > to disconnected framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 (default) > at scheduler-a51a061b-8755-4242-9a63-69e987a1c91d@172.17.5.188:41228 > I1120 12:03:09.091192 29825 master.cpp:1152] Giving framework > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 (default) at > scheduler-a51a061b-8755-4242-9a63-69e987a1c91d@172.17.5.188:41228 0ns to > failover > I1120 12:03:09.091501 29825 master.cpp:928] Master terminating > I1120 12:03:09.091677 29839 hierarchical.cpp:275] Deactivated framework > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 > W1120 12:03:09.091797 29825 master.cpp:6124] Removing task > a40b962c-6507-488b-812f-af506f2c1206 with resources cpus(*):1; mem(*):128; > disk(*):3 of framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 on slave > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 at slave(15)@172.17.5.188:41228 > (a51e6bb03b55) in non-terminal state TASK_STAGING > I1120 12:03:09.092192 29839 hierarchical.cpp:746] Recovered cpus(*):1; > mem(*):896; disk(*):1021; ports(*):[31000-32000] (total: cpus(*):2; > mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):1; > mem(*):128; disk(*):3) on slave 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 from > framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 > I1120 12:03:09.092428 29839 hierarchical.cpp:375] Removed slave > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-S0 > I1120 12:03:09.092726 29839 hierarchical.cpp:232] Removed framework > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 > I1120 12:03:09.093112 29836 slave.cpp:3215] master@172.17.5.188:41228 exited > W1120 12:03:09.093142 29836 slave.cpp:3218] Master disconnected! Waiting for > a new master to be elected > I1120 12:03:09.099444 29836 containerizer.cpp:1075] Destroying container > 'd73a9e9b-b646-4f63-85b9-d632ceb1f075' > I1120 12:03:09.127142 29834 containerizer.cpp:1258] Executor for container > 'd73a9e9b-b646-4f63-85b9-d632ceb1f075' has exited > I1120 12:03:09.130437 29831 slave.cpp:3553] Executor > 'a40b962c-6507-488b-812f-af506f2c1206' of framework > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 terminated with signal Killed > I1120 12:03:09.130599 29831 slave.cpp:2762] Handling status update > TASK_FAILED (UUID: f13c71f7-c85b-4b9f-a36d-42a95cce4ebc) for task > a40b962c-6507-488b-812f-af506f2c1206 of framework > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 from @0.0.0.0:0 > I1120 12:03:09.130785 29831 slave.cpp:5298] Terminating task > a40b962c-6507-488b-812f-af506f2c1206 > W1120 12:03:09.131325 29831 containerizer.cpp:967] Ignoring update for > unknown container: d73a9e9b-b646-4f63-85b9-d632ceb1f075 > I1120 12:03:09.132174 29830 status_update_manager.cpp:322] Received status > update TASK_FAILED (UUID: f13c71f7-c85b-4b9f-a36d-42a95cce4ebc) for task > a40b962c-6507-488b-812f-af506f2c1206 of framework > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 > I1120 12:03:09.132282 29830 status_update_manager.cpp:499] Creating > StatusUpdate stream for task a40b962c-6507-488b-812f-af506f2c1206 of > framework 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 > I1120 12:03:09.133081 29830 status_update_manager.cpp:826] Checkpointing > UPDATE for status update TASK_FAILED (UUID: > f13c71f7-c85b-4b9f-a36d-42a95cce4ebc) for task > a40b962c-6507-488b-812f-af506f2c1206 of framework > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 > I1120 12:03:09.133985 29832 slave.cpp:601] Slave terminating > I1120 12:03:09.136636 29830 status_update_manager.cpp:376] Forwarding update > TASK_FAILED (UUID: f13c71f7-c85b-4b9f-a36d-42a95cce4ebc) for task > a40b962c-6507-488b-812f-af506f2c1206 of framework > 9a3c45ec-28b3-49e6-a83f-1f2035cc1105-0000 to the slave > [ FAILED ] DiskQuotaTest.SlaveRecovery (15127 ms) > {noformat} > {noformat: title=Good Run} > [ RUN ] DiskQuotaTest.SlaveRecovery > I1120 14:23:00.508623 29809 leveldb.cpp:176] Opened db in 2.857109ms > I1120 14:23:00.509371 29809 leveldb.cpp:183] Compacted db in 691823ns > I1120 14:23:00.509424 29809 leveldb.cpp:198] Created db iterator in 25782ns > I1120 14:23:00.509436 29809 leveldb.cpp:204] Seeked to beginning of db in > 2026ns > I1120 14:23:00.509443 29809 leveldb.cpp:273] Iterated through 0 keys in the > db in 262ns > I1120 14:23:00.509493 29809 replica.cpp:780] Replica recovered with log > positions 0 -> 0 with 1 holes and 0 unlearned > I1120 14:23:00.510426 29829 recover.cpp:449] Starting replica recovery > I1120 14:23:00.510720 29829 recover.cpp:475] Replica is in EMPTY status > I1120 14:23:00.512007 29835 replica.cpp:676] Replica in EMPTY status received > a broadcasted recover request from (554)@172.17.10.237:40088 > I1120 14:23:00.512296 29838 master.cpp:367] Master > 1c180fae-4467-4812-9068-e694cb1c9940 (8b126df598c7) started on > 172.17.10.237:40088 > I1120 14:23:00.512548 29843 recover.cpp:195] Received a recover response from > a replica in EMPTY status > I1120 14:23:00.512320 29838 master.cpp:369] Flags at startup: --acls="" > --allocation_interval="1secs" --allocator="HierarchicalDRF" > --authenticate="true" --authenticate_slaves="true" --authenticators="crammd5" > --authorizers="local" --credentials="/tmp/EXdfqq/credentials" > --framework_sorter="drf" --help="false" --hostname_lookup="true" > --initialize_driver_logging="true" --log_auto_initialize="true" > --logbufsecs="0" --logging_level="INFO" --max_slave_ping_timeouts="5" > --quiet="false" --recovery_slave_removal_limit="100%" > --registry="replicated_log" --registry_fetch_timeout="1mins" > --registry_store_timeout="25secs" --registry_strict="true" > --root_submissions="true" --slave_ping_timeout="15secs" > --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" > --webui_dir="/mesos/mesos-0.26.0/_inst/share/mesos/webui" > --work_dir="/tmp/EXdfqq/master" --zk_session_timeout="10secs" > I1120 14:23:00.512601 29838 master.cpp:414] Master only allowing > authenticated frameworks to register > I1120 14:23:00.512614 29838 master.cpp:419] Master only allowing > authenticated slaves to register > I1120 14:23:00.512622 29838 credentials.hpp:37] Loading credentials for > authentication from '/tmp/EXdfqq/credentials' > I1120 14:23:00.512943 29838 master.cpp:458] Using default 'crammd5' > authenticator > I1120 14:23:00.512966 29835 recover.cpp:566] Updating replica status to > STARTING > I1120 14:23:00.513171 29838 master.cpp:495] Authorization enabled > I1120 14:23:00.513761 29832 hierarchical.cpp:153] Initialized hierarchical > allocator process > I1120 14:23:00.513826 29832 whitelist_watcher.cpp:79] No whitelist given > I1120 14:23:00.513903 29829 leveldb.cpp:306] Persisting metadata (8 bytes) to > leveldb took 496302ns > I1120 14:23:00.513922 29829 replica.cpp:323] Persisted replica status to > STARTING > I1120 14:23:00.514123 29832 recover.cpp:475] Replica is in STARTING status > I1120 14:23:00.515575 29830 replica.cpp:676] Replica in STARTING status > received a broadcasted recover request from (555)@172.17.10.237:40088 > I1120 14:23:00.515874 29828 recover.cpp:195] Received a recover response from > a replica in STARTING status > I1120 14:23:00.516531 29839 recover.cpp:566] Updating replica status to VOTING > I1120 14:23:00.517139 29828 leveldb.cpp:306] Persisting metadata (8 bytes) to > leveldb took 492016ns > I1120 14:23:00.517177 29828 replica.cpp:323] Persisted replica status to > VOTING > I1120 14:23:00.517336 29828 recover.cpp:580] Successfully joined the Paxos > group > I1120 14:23:00.517505 29842 master.cpp:1612] The newly elected leader is > master@172.17.10.237:40088 with id 1c180fae-4467-4812-9068-e694cb1c9940 > I1120 14:23:00.517542 29842 master.cpp:1625] Elected as the leading master! > I1120 14:23:00.517562 29842 master.cpp:1385] Recovering from registrar > I1120 14:23:00.517652 29828 recover.cpp:464] Recover process terminated > I1120 14:23:00.517840 29839 registrar.cpp:309] Recovering registrar > I1120 14:23:00.519129 29840 log.cpp:661] Attempting to start the writer > I1120 14:23:00.520586 29832 replica.cpp:496] Replica received implicit > promise request from (556)@172.17.10.237:40088 with proposal 1 > I1120 14:23:00.521001 29832 leveldb.cpp:306] Persisting metadata (8 bytes) to > leveldb took 376158ns > I1120 14:23:00.521056 29832 replica.cpp:345] Persisted promised to 1 > I1120 14:23:00.521869 29830 coordinator.cpp:240] Coordinator attempting to > fill missing positions > I1120 14:23:00.523301 29835 replica.cpp:391] Replica received explicit > promise request from (557)@172.17.10.237:40088 for position 0 with proposal 2 > I1120 14:23:00.523751 29835 leveldb.cpp:343] Persisting action (8 bytes) to > leveldb took 397806ns > I1120 14:23:00.523780 29835 replica.cpp:715] Persisted action at 0 > I1120 14:23:00.524871 29837 replica.cpp:540] Replica received write request > for position 0 from (558)@172.17.10.237:40088 > I1120 14:23:00.525171 29837 leveldb.cpp:438] Reading position from leveldb > took 200426ns > I1120 14:23:00.525580 29837 leveldb.cpp:343] Persisting action (14 bytes) to > leveldb took 328218ns > I1120 14:23:00.525609 29837 replica.cpp:715] Persisted action at 0 > I1120 14:23:00.526381 29843 replica.cpp:694] Replica received learned notice > for position 0 from @0.0.0.0:0 > I1120 14:23:00.526823 29843 leveldb.cpp:343] Persisting action (16 bytes) to > leveldb took 311618ns > I1120 14:23:00.526923 29843 replica.cpp:715] Persisted action at 0 > I1120 14:23:00.527019 29843 replica.cpp:700] Replica learned NOP action at > position 0 > I1120 14:23:00.527701 29835 log.cpp:677] Writer started with ending position 0 > I1120 14:23:00.529162 29839 leveldb.cpp:438] Reading position from leveldb > took 49313ns > I1120 14:23:00.530751 29828 registrar.cpp:342] Successfully fetched the > registry (0B) in 12.859136ms > I1120 14:23:00.530978 29828 registrar.cpp:441] Applied 1 operations in > 45309ns; attempting to update the 'registry' > I1120 14:23:00.531807 29830 log.cpp:685] Attempting to append 178 bytes to > the log > I1120 14:23:00.531935 29839 coordinator.cpp:350] Coordinator attempting to > write APPEND action at position 1 > I1120 14:23:00.532902 29842 replica.cpp:540] Replica received write request > for position 1 from (559)@172.17.10.237:40088 > I1120 14:23:00.533485 29842 leveldb.cpp:343] Persisting action (197 bytes) to > leveldb took 536837ns > I1120 14:23:00.533514 29842 replica.cpp:715] Persisted action at 1 > I1120 14:23:00.534164 29833 replica.cpp:694] Replica received learned notice > for position 1 from @0.0.0.0:0 > I1120 14:23:00.534489 29833 leveldb.cpp:343] Persisting action (199 bytes) to > leveldb took 291755ns > I1120 14:23:00.534524 29833 replica.cpp:715] Persisted action at 1 > I1120 14:23:00.534555 29833 replica.cpp:700] Replica learned APPEND action at > position 1 > I1120 14:23:00.535744 29837 registrar.cpp:486] Successfully updated the > 'registry' in 4.637184ms > I1120 14:23:00.535953 29837 registrar.cpp:372] Successfully recovered > registrar > I1120 14:23:00.536512 29837 master.cpp:1422] Recovered 0 slaves from the > Registry (139B) ; allowing 10mins for slaves to re-register > I1120 14:23:00.536036 29839 log.cpp:704] Attempting to truncate the log to 1 > I1120 14:23:00.537062 29835 coordinator.cpp:350] Coordinator attempting to > write TRUNCATE action at position 2 > I1120 14:23:00.538105 29836 replica.cpp:540] Replica received write request > for position 2 from (560)@172.17.10.237:40088 > I1120 14:23:00.538614 29836 leveldb.cpp:343] Persisting action (16 bytes) to > leveldb took 447383ns > I1120 14:23:00.538640 29836 replica.cpp:715] Persisted action at 2 > I1120 14:23:00.539374 29836 replica.cpp:694] Replica received learned notice > for position 2 from @0.0.0.0:0 > I1120 14:23:00.539808 29836 leveldb.cpp:343] Persisting action (18 bytes) to > leveldb took 375315ns > I1120 14:23:00.539885 29836 leveldb.cpp:401] Deleting ~1 keys from leveldb > took 49469ns > I1120 14:23:00.539938 29836 replica.cpp:715] Persisted action at 2 > I1120 14:23:00.539984 29836 replica.cpp:700] Replica learned TRUNCATE action > at position 2 > I1120 14:23:00.549140 29809 containerizer.cpp:143] Using isolation: > posix/cpu,posix/mem,posix/disk,filesystem/posix > W1120 14:23:00.549513 29809 backend.cpp:50] Failed to create 'bind' backend: > BindBackend requires root privileges > I1120 14:23:00.553772 29837 slave.cpp:191] Slave started on > 15)@172.17.10.237:40088 > I1120 14:23:00.553809 29837 slave.cpp:192] Flags at startup: > --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" > --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="1ms" > --containerizers="mesos" > --credential="/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/credential" > --default_role="*" --disk_watch_interval="1mins" --docker="docker" > --docker_auth_server="auth.docker.io" --docker_auth_server_port="443" > --docker_kill_orphans="true" > --docker_local_archives_dir="/tmp/mesos/images/docker" > --docker_puller="local" --docker_puller_timeout="60" > --docker_registry="registry-1.docker.io" --docker_registry_port="443" > --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" > --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" > --enforce_container_disk_quota="false" > --executor_registration_timeout="1mins" > --executor_shutdown_grace_period="5secs" > --fetcher_cache_dir="/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/fetch" > --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" > --gc_disk_headroom="0.1" --hadoop_home="" --help="false" > --hostname_lookup="true" --image_provisioner_backend="copy" > --initialize_driver_logging="true" > --isolation="posix/cpu,posix/mem,posix/disk" > --launcher_dir="/mesos/mesos-0.26.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;mem:1024;disk:1024;ports:[31000-32000]" > --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" > --strict="true" --switch_user="true" > --systemd_runtime_directory="/run/systemd/system" --version="false" > --work_dir="/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm" > I1120 14:23:00.554425 29837 credentials.hpp:85] Loading credential for > authentication from '/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/credential' > I1120 14:23:00.554700 29837 slave.cpp:322] Slave using credential for: > test-principal > I1120 14:23:00.554927 29837 resources.cpp:474] Parsing resources as JSON > failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000] > Trying semicolon-delimited string format instead > I1120 14:23:00.555559 29837 slave.cpp:392] Slave resources: cpus(*):2; > mem(*):1024; disk(*):1024; ports(*):[31000-32000] > I1120 14:23:00.555634 29837 slave.cpp:400] Slave attributes: [ ] > I1120 14:23:00.555649 29837 slave.cpp:405] Slave hostname: 8b126df598c7 > I1120 14:23:00.555660 29837 slave.cpp:410] Slave checkpoint: true > I1120 14:23:00.556748 29840 state.cpp:54] Recovering state from > '/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/meta' > I1120 14:23:00.556985 29835 status_update_manager.cpp:202] Recovering status > update manager > I1120 14:23:00.557191 29809 sched.cpp:166] Version: 0.26.0 > I1120 14:23:00.557224 29834 containerizer.cpp:385] Recovering containerizer > I1120 14:23:00.557792 29830 sched.cpp:264] New master detected at > master@172.17.10.237:40088 > I1120 14:23:00.557881 29830 sched.cpp:320] Authenticating with master > master@172.17.10.237:40088 > I1120 14:23:00.557900 29830 sched.cpp:327] Using default CRAM-MD5 > authenticatee > I1120 14:23:00.558094 29833 slave.cpp:4230] Finished recovery > I1120 14:23:00.558136 29835 authenticatee.cpp:123] Creating new client SASL > connection > I1120 14:23:00.558425 29831 master.cpp:5156] Authenticating > scheduler-6d6242c6-d043-47f4-b677-a3ca7dd7beb2@172.17.10.237:40088 > I1120 14:23:00.558540 29833 slave.cpp:4387] Querying resource estimator for > oversubscribable resources > I1120 14:23:00.558542 29828 authenticator.cpp:415] Starting authentication > session for crammd5_authenticatee(57)@172.17.10.237:40088 > I1120 14:23:00.558759 29833 authenticator.cpp:100] Creating new server SASL > connection > I1120 14:23:00.558790 29830 status_update_manager.cpp:176] Pausing sending > status updates > I1120 14:23:00.558800 29834 slave.cpp:729] New master detected at > master@172.17.10.237:40088 > I1120 14:23:00.558868 29834 slave.cpp:792] Authenticating with master > master@172.17.10.237:40088 > I1120 14:23:00.558890 29834 slave.cpp:797] Using default CRAM-MD5 > authenticatee > I1120 14:23:00.558967 29842 authenticatee.cpp:214] Received SASL > authentication mechanisms: CRAM-MD5 > I1120 14:23:00.559002 29842 authenticatee.cpp:240] Attempting to authenticate > with mechanism 'CRAM-MD5' > I1120 14:23:00.559113 29842 authenticator.cpp:205] Received SASL > authentication start > I1120 14:23:00.559131 29836 authenticatee.cpp:123] Creating new client SASL > connection > I1120 14:23:00.559203 29842 authenticator.cpp:327] Authentication requires > more steps > I1120 14:23:00.559296 29842 authenticatee.cpp:260] Received SASL > authentication step > I1120 14:23:00.559363 29834 slave.cpp:765] Detecting new master > I1120 14:23:00.559437 29839 authenticator.cpp:233] Received SASL > authentication step > I1120 14:23:00.559448 29833 master.cpp:5156] Authenticating > slave(15)@172.17.10.237:40088 > I1120 14:23:00.559478 29839 auxprop.cpp:109] Request to lookup properties for > user: 'test-principal' realm: '8b126df598c7' server FQDN: '8b126df598c7' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: false > I1120 14:23:00.559483 29834 slave.cpp:4401] Received oversubscribable > resources from the resource estimator > I1120 14:23:00.559497 29839 auxprop.cpp:181] Looking up auxiliary property > '*userPassword' > I1120 14:23:00.559553 29839 auxprop.cpp:181] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I1120 14:23:00.559593 29839 auxprop.cpp:109] Request to lookup properties for > user: 'test-principal' realm: '8b126df598c7' server FQDN: '8b126df598c7' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: true > I1120 14:23:00.559612 29839 auxprop.cpp:131] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I1120 14:23:00.559623 29839 auxprop.cpp:131] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I1120 14:23:00.559631 29833 authenticator.cpp:415] Starting authentication > session for crammd5_authenticatee(58)@172.17.10.237:40088 > I1120 14:23:00.559645 29839 authenticator.cpp:319] Authentication success > I1120 14:23:00.559837 29842 master.cpp:5186] Successfully authenticated > principal 'test-principal' at > scheduler-6d6242c6-d043-47f4-b677-a3ca7dd7beb2@172.17.10.237:40088 > I1120 14:23:00.559869 29833 authenticator.cpp:433] Authentication session > cleanup for crammd5_authenticatee(57)@172.17.10.237:40088 > I1120 14:23:00.559895 29835 authenticator.cpp:100] Creating new server SASL > connection > I1120 14:23:00.559948 29837 authenticatee.cpp:300] Authentication success > I1120 14:23:00.560255 29833 authenticatee.cpp:214] Received SASL > authentication mechanisms: CRAM-MD5 > I1120 14:23:00.560281 29833 authenticatee.cpp:240] Attempting to authenticate > with mechanism 'CRAM-MD5' > I1120 14:23:00.560405 29834 authenticator.cpp:205] Received SASL > authentication start > I1120 14:23:00.560443 29831 sched.cpp:409] Successfully authenticated with > master master@172.17.10.237:40088 > I1120 14:23:00.560461 29831 sched.cpp:716] Sending SUBSCRIBE call to > master@172.17.10.237:40088 > I1120 14:23:00.560479 29834 authenticator.cpp:327] Authentication requires > more steps > I1120 14:23:00.560540 29831 sched.cpp:749] Will retry registration in > 689.900282ms if necessary > I1120 14:23:00.560587 29834 authenticatee.cpp:260] Received SASL > authentication step > I1120 14:23:00.560686 29831 authenticator.cpp:233] Received SASL > authentication step > I1120 14:23:00.560703 29829 master.cpp:2182] Received SUBSCRIBE call for > framework 'default' at > scheduler-6d6242c6-d043-47f4-b677-a3ca7dd7beb2@172.17.10.237:40088 > I1120 14:23:00.560793 29831 auxprop.cpp:109] Request to lookup properties for > user: 'test-principal' realm: '8b126df598c7' server FQDN: '8b126df598c7' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: false > I1120 14:23:00.560808 29831 auxprop.cpp:181] Looking up auxiliary property > '*userPassword' > I1120 14:23:00.560832 29829 master.cpp:1651] Authorizing framework principal > 'test-principal' to receive offers for role '*' > I1120 14:23:00.560839 29831 auxprop.cpp:181] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I1120 14:23:00.560865 29831 auxprop.cpp:109] Request to lookup properties for > user: 'test-principal' realm: '8b126df598c7' server FQDN: '8b126df598c7' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: true > I1120 14:23:00.560878 29831 auxprop.cpp:131] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I1120 14:23:00.560888 29831 auxprop.cpp:131] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I1120 14:23:00.560905 29831 authenticator.cpp:319] Authentication success > I1120 14:23:00.560997 29828 authenticatee.cpp:300] Authentication success > I1120 14:23:00.561012 29829 master.cpp:5186] Successfully authenticated > principal 'test-principal' at slave(15)@172.17.10.237:40088 > I1120 14:23:00.561079 29831 authenticator.cpp:433] Authentication session > cleanup for crammd5_authenticatee(58)@172.17.10.237:40088 > I1120 14:23:00.561125 29829 master.cpp:2253] Subscribing framework default > with checkpointing enabled and capabilities [ ] > I1120 14:23:00.561327 29828 slave.cpp:860] Successfully authenticated with > master master@172.17.10.237:40088 > I1120 14:23:00.561463 29828 slave.cpp:1254] Will retry registration in > 79918ns if necessary > I1120 14:23:00.561574 29839 hierarchical.cpp:197] Added framework > 1c180fae-4467-4812-9068-e694cb1c9940-0000 > I1120 14:23:00.561635 29839 hierarchical.cpp:979] No resources available to > allocate! > I1120 14:23:00.561674 29839 hierarchical.cpp:1072] No inverse offers to send > out! > I1120 14:23:00.561691 29833 sched.cpp:643] Framework registered with > 1c180fae-4467-4812-9068-e694cb1c9940-0000 > I1120 14:23:00.561700 29839 hierarchical.cpp:878] Performed allocation for 0 > slaves in 102623ns > I1120 14:23:00.561728 29833 sched.cpp:657] Scheduler::registered took 17015ns > I1120 14:23:00.561784 29829 master.cpp:3865] Registering slave at > slave(15)@172.17.10.237:40088 (8b126df598c7) with id > 1c180fae-4467-4812-9068-e694cb1c9940-S0 > I1120 14:23:00.562244 29843 registrar.cpp:441] Applied 1 operations in > 58872ns; attempting to update the 'registry' > I1120 14:23:00.562871 29830 slave.cpp:1254] Will retry registration in > 21.508543ms if necessary > I1120 14:23:00.562975 29840 log.cpp:685] Attempting to append 347 bytes to > the log > I1120 14:23:00.562986 29836 master.cpp:3853] Ignoring register slave message > from slave(15)@172.17.10.237:40088 (8b126df598c7) as admission is already in > progress > I1120 14:23:00.563155 29833 coordinator.cpp:350] Coordinator attempting to > write APPEND action at position 3 > I1120 14:23:00.563832 29833 replica.cpp:540] Replica received write request > for position 3 from (574)@172.17.10.237:40088 > I1120 14:23:00.564071 29833 leveldb.cpp:343] Persisting action (366 bytes) to > leveldb took 200681ns > I1120 14:23:00.564095 29833 replica.cpp:715] Persisted action at 3 > I1120 14:23:00.564698 29843 replica.cpp:694] Replica received learned notice > for position 3 from @0.0.0.0:0 > I1120 14:23:00.565131 29843 leveldb.cpp:343] Persisting action (368 bytes) to > leveldb took 403511ns > I1120 14:23:00.565153 29843 replica.cpp:715] Persisted action at 3 > I1120 14:23:00.565171 29843 replica.cpp:700] Replica learned APPEND action at > position 3 > I1120 14:23:00.566464 29843 registrar.cpp:486] Successfully updated the > 'registry' in 4.146944ms > I1120 14:23:00.566681 29842 log.cpp:704] Attempting to truncate the log to 3 > I1120 14:23:00.566803 29839 coordinator.cpp:350] Coordinator attempting to > write TRUNCATE action at position 4 > I1120 14:23:00.567150 29838 slave.cpp:3169] Received ping from > slave-observer(14)@172.17.10.237:40088 > I1120 14:23:00.567309 29830 master.cpp:3933] Registered slave > 1c180fae-4467-4812-9068-e694cb1c9940-S0 at slave(15)@172.17.10.237:40088 > (8b126df598c7) with cpus(*):2; mem(*):1024; disk(*):1024; > ports(*):[31000-32000] > I1120 14:23:00.567924 29838 slave.cpp:904] Registered with master > master@172.17.10.237:40088; given slave ID > 1c180fae-4467-4812-9068-e694cb1c9940-S0 > I1120 14:23:00.567966 29838 fetcher.cpp:79] Clearing fetcher cache > I1120 14:23:00.568330 29843 hierarchical.cpp:346] Added slave > 1c180fae-4467-4812-9068-e694cb1c9940-S0 (8b126df598c7) with cpus(*):2; > mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: ) > I1120 14:23:00.569124 29828 status_update_manager.cpp:183] Resuming sending > status updates > I1120 14:23:00.569195 29828 replica.cpp:540] Replica received write request > for position 4 from (575)@172.17.10.237:40088 > I1120 14:23:00.569314 29843 hierarchical.cpp:1072] No inverse offers to send > out! > I1120 14:23:00.569357 29843 hierarchical.cpp:894] Performed allocation for > slave 1c180fae-4467-4812-9068-e694cb1c9940-S0 in 977691ns > I1120 14:23:00.569555 29838 slave.cpp:927] Checkpointing SlaveInfo to > '/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/meta/slaves/1c180fae-4467-4812-9068-e694cb1c9940-S0/slave.info' > I1120 14:23:00.570016 29843 master.cpp:4985] Sending 1 offers to framework > 1c180fae-4467-4812-9068-e694cb1c9940-0000 (default) at > scheduler-6d6242c6-d043-47f4-b677-a3ca7dd7beb2@172.17.10.237:40088 > I1120 14:23:00.570436 29828 leveldb.cpp:343] Persisting action (16 bytes) to > leveldb took 1.204214ms > I1120 14:23:00.570466 29828 replica.cpp:715] Persisted action at 4 > I1120 14:23:00.570574 29843 sched.cpp:813] Scheduler::resourceOffers took > 149218ns > I1120 14:23:00.570871 29838 slave.cpp:963] Forwarding total oversubscribed > resources > I1120 14:23:00.571166 29838 master.cpp:4275] Received update of slave > 1c180fae-4467-4812-9068-e694cb1c9940-S0 at slave(15)@172.17.10.237:40088 > (8b126df598c7) with total oversubscribed resources > I1120 14:23:00.571437 29838 hierarchical.cpp:402] Slave > 1c180fae-4467-4812-9068-e694cb1c9940-S0 (8b126df598c7) updated with > oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; > ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; > ports(*):[31000-32000]) > I1120 14:23:00.571689 29828 replica.cpp:694] Replica received learned notice > for position 4 from @0.0.0.0:0 > I1120 14:23:00.571741 29838 hierarchical.cpp:979] No resources available to > allocate! > I1120 14:23:00.571775 29838 hierarchical.cpp:1072] No inverse offers to send > out! > I1120 14:23:00.571789 29838 hierarchical.cpp:894] Performed allocation for > slave 1c180fae-4467-4812-9068-e694cb1c9940-S0 in 319667ns > I1120 14:23:00.572039 29809 resources.cpp:474] Parsing resources as JSON > failed: cpus:1;mem:128;disk:3 > Trying semicolon-delimited string format instead > I1120 14:23:00.572206 29828 leveldb.cpp:343] Persisting action (18 bytes) to > leveldb took 478524ns > I1120 14:23:00.572283 29828 leveldb.cpp:401] Deleting ~2 keys from leveldb > took 48209ns > I1120 14:23:00.572304 29828 replica.cpp:715] Persisted action at 4 > I1120 14:23:00.572325 29828 replica.cpp:700] Replica learned TRUNCATE action > at position 4 > I1120 14:23:00.573488 29840 master.cpp:2921] Processing ACCEPT call for > offers: [ 1c180fae-4467-4812-9068-e694cb1c9940-O0 ] on slave > 1c180fae-4467-4812-9068-e694cb1c9940-S0 at slave(15)@172.17.10.237:40088 > (8b126df598c7) for framework 1c180fae-4467-4812-9068-e694cb1c9940-0000 > (default) at > scheduler-6d6242c6-d043-47f4-b677-a3ca7dd7beb2@172.17.10.237:40088 > I1120 14:23:00.573539 29840 master.cpp:2717] Authorizing framework principal > 'test-principal' to launch task 47beaafe-f181-4d15-ab26-b35ba8296144 as user > 'mesos' > I1120 14:23:00.575311 29834 master.hpp:178] Adding task > 47beaafe-f181-4d15-ab26-b35ba8296144 with resources cpus(*):1; mem(*):128; > disk(*):3 on slave 1c180fae-4467-4812-9068-e694cb1c9940-S0 (8b126df598c7) > I1120 14:23:00.575539 29834 master.cpp:3251] Launching task > 47beaafe-f181-4d15-ab26-b35ba8296144 of framework > 1c180fae-4467-4812-9068-e694cb1c9940-0000 (default) at > scheduler-6d6242c6-d043-47f4-b677-a3ca7dd7beb2@172.17.10.237:40088 with > resources cpus(*):1; mem(*):128; disk(*):3 on slave > 1c180fae-4467-4812-9068-e694cb1c9940-S0 at slave(15)@172.17.10.237:40088 > (8b126df598c7) > I1120 14:23:00.575935 29832 slave.cpp:1294] Got assigned task > 47beaafe-f181-4d15-ab26-b35ba8296144 for framework > 1c180fae-4467-4812-9068-e694cb1c9940-0000 > I1120 14:23:00.576198 29832 slave.cpp:4920] Checkpointing FrameworkInfo to > '/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/meta/slaves/1c180fae-4467-4812-9068-e694cb1c9940-S0/frameworks/1c180fae-4467-4812-9068-e694cb1c9940-0000/framework.info' > I1120 14:23:00.576717 29832 slave.cpp:4931] Checkpointing framework pid > 'scheduler-6d6242c6-d043-47f4-b677-a3ca7dd7beb2@172.17.10.237:40088' to > '/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/meta/slaves/1c180fae-4467-4812-9068-e694cb1c9940-S0/frameworks/1c180fae-4467-4812-9068-e694cb1c9940-0000/framework.pid' > I1120 14:23:00.577040 29834 hierarchical.cpp:746] Recovered cpus(*):1; > mem(*):896; disk(*):1021; ports(*):[31000-32000] (total: cpus(*):2; > mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):1; > mem(*):128; disk(*):3) on slave 1c180fae-4467-4812-9068-e694cb1c9940-S0 from > framework 1c180fae-4467-4812-9068-e694cb1c9940-0000 > I1120 14:23:00.577139 29834 hierarchical.cpp:783] Framework > 1c180fae-4467-4812-9068-e694cb1c9940-0000 filtered slave > 1c180fae-4467-4812-9068-e694cb1c9940-S0 for 5secs > I1120 14:23:00.577150 29832 resources.cpp:474] Parsing resources as JSON > failed: cpus:0.1;mem:32 > Trying semicolon-delimited string format instead > I1120 14:23:00.577736 29832 slave.cpp:1410] Launching task > 47beaafe-f181-4d15-ab26-b35ba8296144 for framework > 1c180fae-4467-4812-9068-e694cb1c9940-0000 > I1120 14:23:00.577821 29832 resources.cpp:474] Parsing resources as JSON > failed: cpus:0.1;mem:32 > Trying semicolon-delimited string format instead > I1120 14:23:00.578716 29832 paths.cpp:436] Trying to chown > '/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/slaves/1c180fae-4467-4812-9068-e694cb1c9940-S0/frameworks/1c180fae-4467-4812-9068-e694cb1c9940-0000/executors/47beaafe-f181-4d15-ab26-b35ba8296144/runs/a1cdc1eb-668a-4671-bfee-c78a4b026026' > to user 'mesos' > I1120 14:23:00.583127 29832 slave.cpp:5360] Checkpointing ExecutorInfo to > '/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/meta/slaves/1c180fae-4467-4812-9068-e694cb1c9940-S0/frameworks/1c180fae-4467-4812-9068-e694cb1c9940-0000/executors/47beaafe-f181-4d15-ab26-b35ba8296144/executor.info' > I1120 14:23:00.583926 29832 slave.cpp:4999] Launching executor > 47beaafe-f181-4d15-ab26-b35ba8296144 of framework > 1c180fae-4467-4812-9068-e694cb1c9940-0000 with resources cpus(*):0.1; > mem(*):32 in work directory > '/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/slaves/1c180fae-4467-4812-9068-e694cb1c9940-S0/frameworks/1c180fae-4467-4812-9068-e694cb1c9940-0000/executors/47beaafe-f181-4d15-ab26-b35ba8296144/runs/a1cdc1eb-668a-4671-bfee-c78a4b026026' > I1120 14:23:00.584372 29841 containerizer.cpp:619] Starting container > 'a1cdc1eb-668a-4671-bfee-c78a4b026026' for executor > '47beaafe-f181-4d15-ab26-b35ba8296144' of framework > '1c180fae-4467-4812-9068-e694cb1c9940-0000' > I1120 14:23:00.584478 29832 slave.cpp:5383] Checkpointing TaskInfo to > '/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/meta/slaves/1c180fae-4467-4812-9068-e694cb1c9940-S0/frameworks/1c180fae-4467-4812-9068-e694cb1c9940-0000/executors/47beaafe-f181-4d15-ab26-b35ba8296144/runs/a1cdc1eb-668a-4671-bfee-c78a4b026026/tasks/47beaafe-f181-4d15-ab26-b35ba8296144/task.info' > I1120 14:23:00.585016 29832 slave.cpp:1628] Queuing task > '47beaafe-f181-4d15-ab26-b35ba8296144' for executor > '47beaafe-f181-4d15-ab26-b35ba8296144' of framework > 1c180fae-4467-4812-9068-e694cb1c9940-0000 > I1120 14:23:00.585150 29832 slave.cpp:682] Successfully attached file > '/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/slaves/1c180fae-4467-4812-9068-e694cb1c9940-S0/frameworks/1c180fae-4467-4812-9068-e694cb1c9940-0000/executors/47beaafe-f181-4d15-ab26-b35ba8296144/runs/a1cdc1eb-668a-4671-bfee-c78a4b026026' > I1120 14:23:00.589161 29839 launcher.cpp:134] Forked child with pid '30023' > for container 'a1cdc1eb-668a-4671-bfee-c78a4b026026' > I1120 14:23:00.589488 29839 containerizer.cpp:852] Checkpointing executor's > forked pid 30023 to > '/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/meta/slaves/1c180fae-4467-4812-9068-e694cb1c9940-S0/frameworks/1c180fae-4467-4812-9068-e694cb1c9940-0000/executors/47beaafe-f181-4d15-ab26-b35ba8296144/runs/a1cdc1eb-668a-4671-bfee-c78a4b026026/pids/forked.pid' > WARNING: Logging before InitGoogleLogging() is written to STDERR > I1120 14:23:00.738919 30037 process.cpp:961] libprocess is initialized on > 172.17.10.237:34984 for 16 cpus > I1120 14:23:00.739723 30037 logging.cpp:177] Logging to STDERR > I1120 14:23:00.741880 30037 exec.cpp:136] Version: 0.26.0 > I1120 14:23:00.748992 30051 exec.cpp:186] Executor started at: > executor(1)@172.17.10.237:34984 with pid 30037 > I1120 14:23:00.751570 29839 slave.cpp:2405] Got registration for executor > '47beaafe-f181-4d15-ab26-b35ba8296144' of framework > 1c180fae-4467-4812-9068-e694cb1c9940-0000 from executor(1)@172.17.10.237:34984 > I1120 14:23:00.751797 29839 slave.cpp:2490] Checkpointing executor pid > 'executor(1)@172.17.10.237:34984' to > '/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/meta/slaves/1c180fae-4467-4812-9068-e694cb1c9940-S0/frameworks/1c180fae-4467-4812-9068-e694cb1c9940-0000/executors/47beaafe-f181-4d15-ab26-b35ba8296144/runs/a1cdc1eb-668a-4671-bfee-c78a4b026026/pids/libprocess.pid' > I1120 14:23:00.753489 29836 disk.cpp:154] Updating the disk resources for > container a1cdc1eb-668a-4671-bfee-c78a4b026026 to cpus(*):1.1; mem(*):160; > disk(*):3 > I1120 14:23:00.754307 30058 exec.cpp:210] Executor registered on slave > 1c180fae-4467-4812-9068-e694cb1c9940-S0 > I1120 14:23:00.754490 29835 slave.cpp:1793] Sending queued task > '47beaafe-f181-4d15-ab26-b35ba8296144' to executor > '47beaafe-f181-4d15-ab26-b35ba8296144' of framework > 1c180fae-4467-4812-9068-e694cb1c9940-0000 at executor(1)@172.17.10.237:34984 > I1120 14:23:00.756805 30058 exec.cpp:222] Executor::registered took 303359ns > Registered executor on 8b126df598c7 > I1120 14:23:00.758246 30062 exec.cpp:297] Executor asked to run task > '47beaafe-f181-4d15-ab26-b35ba8296144' > I1120 14:23:00.758358 30062 exec.cpp:306] Executor::launchTask took 80134ns > Starting task 47beaafe-f181-4d15-ab26-b35ba8296144 > Forked command at 30069 > sh -c 'dd if=/dev/zero of=file bs=1048576 count=2 && sleep 1000' > I1120 14:23:00.762169 30063 exec.cpp:519] Executor sending status update > TASK_RUNNING (UUID: 5c27277f-1e83-4459-aa6b-e5d5ed413346) for task > 47beaafe-f181-4d15-ab26-b35ba8296144 of framework > 1c180fae-4467-4812-9068-e694cb1c9940-0000 > I1120 14:23:00.763514 29833 slave.cpp:2762] Handling status update > TASK_RUNNING (UUID: 5c27277f-1e83-4459-aa6b-e5d5ed413346) for task > 47beaafe-f181-4d15-ab26-b35ba8296144 of framework > 1c180fae-4467-4812-9068-e694cb1c9940-0000 from executor(1)@172.17.10.237:34984 > 2+0 records in > 2+0 records out > 2097152 bytes (2.1 MB) copied, 0.00252731 s, 830 MB/s > I1120 14:23:00.764075 29843 status_update_manager.cpp:322] Received status > update TASK_RUNNING (UUID: 5c27277f-1e83-4459-aa6b-e5d5ed413346) for task > 47beaafe-f181-4d15-ab26-b35ba8296144 of framework > 1c180fae-4467-4812-9068-e694cb1c9940-0000 > I1120 14:23:00.764118 29843 status_update_manager.cpp:499] Creating > StatusUpdate stream for task 47beaafe-f181-4d15-ab26-b35ba8296144 of > framework 1c180fae-4467-4812-9068-e694cb1c9940-0000 > I1120 14:23:00.764850 29843 status_update_manager.cpp:826] Checkpointing > UPDATE for status update TASK_RUNNING (UUID: > 5c27277f-1e83-4459-aa6b-e5d5ed413346) for task > 47beaafe-f181-4d15-ab26-b35ba8296144 of framework > 1c180fae-4467-4812-9068-e694cb1c9940-0000 > I1120 14:23:00.766163 29843 status_update_manager.cpp:376] Forwarding update > TASK_RUNNING (UUID: 5c27277f-1e83-4459-aa6b-e5d5ed413346) for task > 47beaafe-f181-4d15-ab26-b35ba8296144 of framework > 1c180fae-4467-4812-9068-e694cb1c9940-0000 to the slave > I1120 14:23:00.766497 29842 slave.cpp:3087] Forwarding the update > TASK_RUNNING (UUID: 5c27277f-1e83-4459-aa6b-e5d5ed413346) for task > 47beaafe-f181-4d15-ab26-b35ba8296144 of framework > 1c180fae-4467-4812-9068-e694cb1c9940-0000 to master@172.17.10.237:40088 > I1120 14:23:00.766685 29842 slave.cpp:3005] Status update manager > successfully handled status update TASK_RUNNING (UUID: > 5c27277f-1e83-4459-aa6b-e5d5ed413346) for task > 47beaafe-f181-4d15-ab26-b35ba8296144 of framework > 1c180fae-4467-4812-9068-e694cb1c9940-0000 > I1120 14:23:00.766789 29842 slave.cpp:3011] Sending acknowledgement for > status update TASK_RUNNING (UUID: 5c27277f-1e83-4459-aa6b-e5d5ed413346) for > task 47beaafe-f181-4d15-ab26-b35ba8296144 of framework > 1c180fae-4467-4812-9068-e694cb1c9940-0000 to executor(1)@172.17.10.237:34984 > I1120 14:23:00.766885 29836 master.cpp:4420] Status update TASK_RUNNING > (UUID: 5c27277f-1e83-4459-aa6b-e5d5ed413346) for task > 47beaafe-f181-4d15-ab26-b35ba8296144 of framework > 1c180fae-4467-4812-9068-e694cb1c9940-0000 from slave > 1c180fae-4467-4812-9068-e694cb1c9940-S0 at slave(15)@172.17.10.237:40088 > (8b126df598c7) > I1120 14:23:00.766930 29836 master.cpp:4468] Forwarding status update > TASK_RUNNING (UUID: 5c27277f-1e83-4459-aa6b-e5d5ed413346) for task > 47beaafe-f181-4d15-ab26-b35ba8296144 of framework > 1c180fae-4467-4812-9068-e694cb1c9940-0000 > I1120 14:23:00.767144 29836 master.cpp:6072] Updating the state of task > 47beaafe-f181-4d15-ab26-b35ba8296144 of framework > 1c180fae-4467-4812-9068-e694cb1c9940-0000 (latest state: TASK_RUNNING, status > update state: TASK_RUNNING) > I1120 14:23:00.767479 29834 sched.cpp:921] Scheduler::statusUpdate took > 186955ns > I1120 14:23:00.767841 29841 master.cpp:3577] Processing ACKNOWLEDGE call > 5c27277f-1e83-4459-aa6b-e5d5ed413346 for task > 47beaafe-f181-4d15-ab26-b35ba8296144 of framework > 1c180fae-4467-4812-9068-e694cb1c9940-0000 (default) at > scheduler-6d6242c6-d043-47f4-b677-a3ca7dd7beb2@172.17.10.237:40088 on slave > 1c180fae-4467-4812-9068-e694cb1c9940-S0 > I1120 14:23:00.768232 29828 status_update_manager.cpp:394] Received status > update acknowledgement (UUID: 5c27277f-1e83-4459-aa6b-e5d5ed413346) for task > 47beaafe-f181-4d15-ab26-b35ba8296144 of framework > 1c180fae-4467-4812-9068-e694cb1c9940-0000 > I1120 14:23:00.768232 30064 exec.cpp:343] Executor received status update > acknowledgement 5c27277f-1e83-4459-aa6b-e5d5ed413346 for task > 47beaafe-f181-4d15-ab26-b35ba8296144 of framework > 1c180fae-4467-4812-9068-e694cb1c9940-0000 > I1120 14:23:00.768399 29828 status_update_manager.cpp:826] Checkpointing ACK > for status update TASK_RUNNING (UUID: 5c27277f-1e83-4459-aa6b-e5d5ed413346) > for task 47beaafe-f181-4d15-ab26-b35ba8296144 of framework > 1c180fae-4467-4812-9068-e694cb1c9940-0000 > I1120 14:23:00.768795 29836 slave.cpp:601] Slave terminating > I1120 14:23:00.769071 29834 master.cpp:1089] Slave > 1c180fae-4467-4812-9068-e694cb1c9940-S0 at slave(15)@172.17.10.237:40088 > (8b126df598c7) disconnected > I1120 14:23:00.769114 29834 master.cpp:2537] Disconnecting slave > 1c180fae-4467-4812-9068-e694cb1c9940-S0 at slave(15)@172.17.10.237:40088 > (8b126df598c7) > I1120 14:23:00.769186 29834 master.cpp:2556] Deactivating slave > 1c180fae-4467-4812-9068-e694cb1c9940-S0 at slave(15)@172.17.10.237:40088 > (8b126df598c7) > I1120 14:23:00.769331 29839 hierarchical.cpp:431] Slave > 1c180fae-4467-4812-9068-e694cb1c9940-S0 deactivated > I1120 14:23:00.776927 29809 containerizer.cpp:143] Using isolation: > posix/cpu,posix/mem,posix/disk,filesystem/posix > W1120 14:23:00.777317 29809 backend.cpp:50] Failed to create 'bind' backend: > BindBackend requires root privileges > I1120 14:23:00.781699 29835 slave.cpp:191] Slave started on > 16)@172.17.10.237:40088 > I1120 14:23:00.781730 29835 slave.cpp:192] Flags at startup: > --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" > --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="1ms" > --containerizers="mesos" > --credential="/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/credential" > --default_role="*" --disk_watch_interval="1mins" --docker="docker" > --docker_auth_server="auth.docker.io" --docker_auth_server_port="443" > --docker_kill_orphans="true" > --docker_local_archives_dir="/tmp/mesos/images/docker" > --docker_puller="local" --docker_puller_timeout="60" > --docker_registry="registry-1.docker.io" --docker_registry_port="443" > --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" > --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" > --enforce_container_disk_quota="false" > --executor_registration_timeout="1mins" > --executor_shutdown_grace_period="5secs" > --fetcher_cache_dir="/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/fetch" > --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" > --gc_disk_headroom="0.1" --hadoop_home="" --help="false" > --hostname_lookup="true" --image_provisioner_backend="copy" > --initialize_driver_logging="true" > --isolation="posix/cpu,posix/mem,posix/disk" > --launcher_dir="/mesos/mesos-0.26.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;mem:1024;disk:1024;ports:[31000-32000]" > --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" > --strict="true" --switch_user="true" > --systemd_runtime_directory="/run/systemd/system" --version="false" > --work_dir="/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm" > I1120 14:23:00.782304 29835 credentials.hpp:85] Loading credential for > authentication from '/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/credential' > I1120 14:23:00.782572 29835 slave.cpp:322] Slave using credential for: > test-principal > I1120 14:23:00.782752 29835 resources.cpp:474] Parsing resources as JSON > failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000] > Trying semicolon-delimited string format instead > I1120 14:23:00.783296 29835 slave.cpp:392] Slave resources: cpus(*):2; > mem(*):1024; disk(*):1024; ports(*):[31000-32000] > I1120 14:23:00.783377 29835 slave.cpp:400] Slave attributes: [ ] > I1120 14:23:00.783392 29835 slave.cpp:405] Slave hostname: 8b126df598c7 > I1120 14:23:00.783403 29835 slave.cpp:410] Slave checkpoint: true > I1120 14:23:00.784399 29831 state.cpp:54] Recovering state from > '/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/meta' > I1120 14:23:00.784526 29831 state.cpp:681] No checkpointed resources found at > '/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/meta/resources/resources.info' > I1120 14:23:00.789577 29842 fetcher.cpp:79] Clearing fetcher cache > I1120 14:23:00.789696 29842 slave.cpp:4318] Recovering framework > 1c180fae-4467-4812-9068-e694cb1c9940-0000 > I1120 14:23:00.789835 29842 slave.cpp:5108] Recovering executor > '47beaafe-f181-4d15-ab26-b35ba8296144' of framework > 1c180fae-4467-4812-9068-e694cb1c9940-0000 > I1120 14:23:00.791198 29831 status_update_manager.cpp:202] Recovering status > update manager > I1120 14:23:00.791378 29831 status_update_manager.cpp:210] Recovering > executor '47beaafe-f181-4d15-ab26-b35ba8296144' of framework > 1c180fae-4467-4812-9068-e694cb1c9940-0000 > I1120 14:23:00.791455 29831 status_update_manager.cpp:499] Creating > StatusUpdate stream for task 47beaafe-f181-4d15-ab26-b35ba8296144 of > framework 1c180fae-4467-4812-9068-e694cb1c9940-0000 > I1120 14:23:00.791661 29842 slave.cpp:682] Successfully attached file > '/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/slaves/1c180fae-4467-4812-9068-e694cb1c9940-S0/frameworks/1c180fae-4467-4812-9068-e694cb1c9940-0000/executors/47beaafe-f181-4d15-ab26-b35ba8296144/runs/a1cdc1eb-668a-4671-bfee-c78a4b026026' > I1120 14:23:00.791911 29831 status_update_manager.cpp:802] Replaying status > update stream for task 47beaafe-f181-4d15-ab26-b35ba8296144 > I1120 14:23:00.792646 29838 containerizer.cpp:385] Recovering containerizer > I1120 14:23:00.792763 29838 containerizer.cpp:440] Recovering container > 'a1cdc1eb-668a-4671-bfee-c78a4b026026' for executor > '47beaafe-f181-4d15-ab26-b35ba8296144' of framework > 1c180fae-4467-4812-9068-e694cb1c9940-0000 > I1120 14:23:00.794885 29843 slave.cpp:4170] Sending reconnect request to > executor '47beaafe-f181-4d15-ab26-b35ba8296144' of framework > 1c180fae-4467-4812-9068-e694cb1c9940-0000 at executor(1)@172.17.10.237:34984 > I1120 14:23:00.796262 30063 exec.cpp:256] Received reconnect request from > slave 1c180fae-4467-4812-9068-e694cb1c9940-S0 > I1120 14:23:00.797771 29830 slave.cpp:2553] Re-registering executor > '47beaafe-f181-4d15-ab26-b35ba8296144' of framework > 1c180fae-4467-4812-9068-e694cb1c9940-0000 > I1120 14:23:00.798692 29839 disk.cpp:154] Updating the disk resources for > container a1cdc1eb-668a-4671-bfee-c78a4b026026 to cpus(*):1.1; mem(*):160; > disk(*):3 > I1120 14:23:00.798894 30056 exec.cpp:233] Executor re-registered on slave > 1c180fae-4467-4812-9068-e694cb1c9940-S0 > I1120 14:23:00.800634 30056 exec.cpp:245] Executor::reregistered took 93607ns > Re-registered executor on 8b126df598c7 > I1120 14:23:00.819314 29837 hierarchical.cpp:979] No resources available to > allocate! > I1120 14:23:00.819424 29837 hierarchical.cpp:1072] No inverse offers to send > out! > I1120 14:23:00.819461 29837 hierarchical.cpp:878] Performed allocation for 1 > slaves in 288853ns > I1120 14:23:00.819629 29842 slave.cpp:2702] Cleaning up un-reregistered > executors > I1120 14:23:00.819764 29842 slave.cpp:4230] Finished recovery > I1120 14:23:00.820565 29842 slave.cpp:4387] Querying resource estimator for > oversubscribable resources > I1120 14:23:00.821192 29839 slave.cpp:729] New master detected at > master@172.17.10.237:40088 > I1120 14:23:00.821283 29839 slave.cpp:792] Authenticating with master > master@172.17.10.237:40088 > I1120 14:23:00.821306 29839 slave.cpp:797] Using default CRAM-MD5 > authenticatee > I1120 14:23:00.821481 29839 slave.cpp:765] Detecting new master > I1120 14:23:00.821513 29838 status_update_manager.cpp:176] Pausing sending > status updates > I1120 14:23:00.821611 29839 slave.cpp:4401] Received oversubscribable > resources from the resource estimator > I1120 14:23:00.821673 29838 authenticatee.cpp:123] Creating new client SASL > connection > I1120 14:23:00.822047 29835 master.cpp:5156] Authenticating > slave(16)@172.17.10.237:40088 > I1120 14:23:00.822258 29838 authenticator.cpp:415] Starting authentication > session for crammd5_authenticatee(59)@172.17.10.237:40088 > I1120 14:23:00.822670 29838 authenticator.cpp:100] Creating new server SASL > connection > I1120 14:23:00.823243 29838 authenticatee.cpp:214] Received SASL > authentication mechanisms: CRAM-MD5 > I1120 14:23:00.823315 29838 authenticatee.cpp:240] Attempting to authenticate > with mechanism 'CRAM-MD5' > I1120 14:23:00.823498 29838 authenticator.cpp:205] Received SASL > authentication start > I1120 14:23:00.823575 29838 authenticator.cpp:327] Authentication requires > more steps > I1120 14:23:00.823665 29838 authenticatee.cpp:260] Received SASL > authentication step > I1120 14:23:00.823760 29838 authenticator.cpp:233] Received SASL > authentication step > I1120 14:23:00.823802 29838 auxprop.cpp:109] Request to lookup properties for > user: 'test-principal' realm: '8b126df598c7' server FQDN: '8b126df598c7' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: false > I1120 14:23:00.823817 29838 auxprop.cpp:181] Looking up auxiliary property > '*userPassword' > I1120 14:23:00.823868 29838 auxprop.cpp:181] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I1120 14:23:00.823894 29838 auxprop.cpp:109] Request to lookup properties for > user: 'test-principal' realm: '8b126df598c7' server FQDN: '8b126df598c7' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: true > I1120 14:23:00.823904 29838 auxprop.cpp:131] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I1120 14:23:00.823923 29838 auxprop.cpp:131] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I1120 14:23:00.823951 29838 authenticator.cpp:319] Authentication success > I1120 14:23:00.824367 29838 authenticatee.cpp:300] Authentication success > I1120 14:23:00.824472 29838 authenticator.cpp:433] Authentication session > cleanup for crammd5_authenticatee(59)@172.17.10.237:40088 > I1120 14:23:00.824760 29837 slave.cpp:860] Successfully authenticated with > master master@172.17.10.237:40088 > I1120 14:23:00.825790 29837 slave.cpp:1254] Will retry registration in > 15.206262ms if necessary > I1120 14:23:00.826516 29835 master.cpp:3951] Queuing up re-registration > request from slave(16)@172.17.10.237:40088 because authentication is still in > progress > I1120 14:23:00.827886 29835 master.cpp:5186] Successfully authenticated > principal 'test-principal' at slave(16)@172.17.10.237:40088 > I1120 14:23:00.828341 29835 master.cpp:4025] Re-registering slave > 1c180fae-4467-4812-9068-e694cb1c9940-S0 at slave(15)@172.17.10.237:40088 > (8b126df598c7) > I1120 14:23:00.828994 29835 master.cpp:4213] Sending updated checkpointed > resources to slave 1c180fae-4467-4812-9068-e694cb1c9940-S0 at > slave(16)@172.17.10.237:40088 (8b126df598c7) > I1120 14:23:00.829118 29829 hierarchical.cpp:419] Slave > 1c180fae-4467-4812-9068-e694cb1c9940-S0 reactivated > I1120 14:23:00.829162 29834 slave.cpp:1004] Re-registered with master > master@172.17.10.237:40088 > I1120 14:23:00.829407 29834 slave.cpp:1040] Forwarding total oversubscribed > resources > I1120 14:23:00.829641 29834 slave.cpp:2178] Updating framework > 1c180fae-4467-4812-9068-e694cb1c9940-0000 pid to > scheduler-6d6242c6-d043-47f4-b677-a3ca7dd7beb2@172.17.10.237:40088 > I1120 14:23:00.829697 29834 slave.cpp:2194] Checkpointing framework pid > 'scheduler-6d6242c6-d043-47f4-b677-a3ca7dd7beb2@172.17.10.237:40088' to > '/tmp/DiskQuotaTest_SlaveRecovery_7QsJEm/meta/slaves/1c180fae-4467-4812-9068-e694cb1c9940-S0/frameworks/1c180fae-4467-4812-9068-e694cb1c9940-0000/framework.pid' > I1120 14:23:00.830552 29834 slave.cpp:2274] Updated checkpointed resources > from to > I1120 14:23:00.830605 29834 status_update_manager.cpp:183] Resuming sending > status updates > I1120 14:23:00.830662 29834 status_update_manager.cpp:183] Resuming sending > status updates > I1120 14:23:00.831312 29838 master.cpp:4275] Received update of slave > 1c180fae-4467-4812-9068-e694cb1c9940-S0 at slave(16)@172.17.10.237:40088 > (8b126df598c7) with total oversubscribed resources > I1120 14:23:00.832479 29839 hierarchical.cpp:402] Slave > 1c180fae-4467-4812-9068-e694cb1c9940-S0 (8b126df598c7) updated with > oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; > ports(*):[31000-32000], allocated: cpus(*):1; mem(*):128; disk(*):3) > I1120 14:23:00.833010 29839 hierarchical.cpp:1164] Filtered offer with > cpus(*):1; mem(*):896; disk(*):1021; ports(*):[31000-32000] on slave > 1c180fae-4467-4812-9068-e694cb1c9940-S0 for framework > 1c180fae-4467-4812-9068-e694cb1c9940-0000 > I1120 14:23:00.833075 29839 hierarchical.cpp:979] No resources available to > allocate! > I1120 14:23:00.833114 29839 hierarchical.cpp:1072] No inverse offers to send > out! > I1120 14:23:00.833137 29839 hierarchical.cpp:894] Performed allocation for > slave 1c180fae-4467-4812-9068-e694cb1c9940-S0 in 600049ns > I1120 14:23:00.936514 29809 sched.cpp:1805] Asked to stop the driver > I1120 14:23:00.936625 29833 sched.cpp:1043] Stopping framework > '1c180fae-4467-4812-9068-e694cb1c9940-0000' > I1120 14:23:00.936650 29842 master.cpp:928] Master terminating > W1120 14:23:00.937158 29842 master.cpp:6124] Removing task > 47beaafe-f181-4d15-ab26-b35ba8296144 with resources cpus(*):1; mem(*):128; > disk(*):3 of framework 1c180fae-4467-4812-9068-e694cb1c9940-0000 on slave > 1c180fae-4467-4812-9068-e694cb1c9940-S0 at slave(16)@172.17.10.237:40088 > (8b126df598c7) in non-terminal state TASK_RUNNING > I1120 14:23:00.937296 29835 hierarchical.cpp:375] Removed slave > 1c180fae-4467-4812-9068-e694cb1c9940-S0 > I1120 14:23:00.937968 29828 hierarchical.cpp:232] Removed framework > 1c180fae-4467-4812-9068-e694cb1c9940-0000 > I1120 14:23:00.938364 29834 slave.cpp:3215] master@172.17.10.237:40088 exited > W1120 14:23:00.938438 29834 slave.cpp:3218] Master disconnected! Waiting for > a new master to be elected > I1120 14:23:00.942594 29833 containerizer.cpp:1075] Destroying container > 'a1cdc1eb-668a-4671-bfee-c78a4b026026' > I1120 14:23:01.027127 29838 containerizer.cpp:1258] Executor for container > 'a1cdc1eb-668a-4671-bfee-c78a4b026026' has exited > I1120 14:23:01.029253 29833 slave.cpp:3553] Executor > '47beaafe-f181-4d15-ab26-b35ba8296144' of framework > 1c180fae-4467-4812-9068-e694cb1c9940-0000 terminated with signal Killed > I1120 14:23:01.029403 29833 slave.cpp:2762] Handling status update > TASK_FAILED (UUID: d3f52651-280c-458f-844d-0901dcedc796) for task > 47beaafe-f181-4d15-ab26-b35ba8296144 of framework > 1c180fae-4467-4812-9068-e694cb1c9940-0000 from @0.0.0.0:0 > I1120 14:23:01.029593 29833 slave.cpp:5298] Terminating task > 47beaafe-f181-4d15-ab26-b35ba8296144 > W1120 14:23:01.029963 29831 containerizer.cpp:967] Ignoring update for > unknown container: a1cdc1eb-668a-4671-bfee-c78a4b026026 > I1120 14:23:01.030381 29834 status_update_manager.cpp:322] Received status > update TASK_FAILED (UUID: d3f52651-280c-458f-844d-0901dcedc796) for task > 47beaafe-f181-4d15-ab26-b35ba8296144 of framework > 1c180fae-4467-4812-9068-e694cb1c9940-0000 > I1120 14:23:01.030426 29833 slave.cpp:601] Slave terminating > I1120 14:23:01.030446 29834 status_update_manager.cpp:826] Checkpointing > UPDATE for status update TASK_FAILED (UUID: > d3f52651-280c-458f-844d-0901dcedc796) for task > 47beaafe-f181-4d15-ab26-b35ba8296144 of framework > 1c180fae-4467-4812-9068-e694cb1c9940-0000 > I1120 14:23:01.031471 29834 status_update_manager.cpp:376] Forwarding update > TASK_FAILED (UUID: d3f52651-280c-458f-844d-0901dcedc796) for task > 47beaafe-f181-4d15-ab26-b35ba8296144 of framework > 1c180fae-4467-4812-9068-e694cb1c9940-0000 to the slave > [ OK ] DiskQuotaTest.SlaveRecovery (530 ms) > {noformat} -- This message was sent by Atlassian JIRA (v6.3.4#6332)