[
https://issues.apache.org/jira/browse/MESOS-5752?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15357779#comment-15357779
]
Jie Yu commented on MESOS-5752:
-------------------------------
[~xujyan] Can you take a look? It was introduced in this patch:
https://github.com/apache/mesos/commit/f23ef4c158cf5ed69e6d90c2c678654cfa0b48a6
> ROOT_GarbageCollectorUndeletableFilesTest.BusyMountPoint is flaky
> -----------------------------------------------------------------
>
> Key: MESOS-5752
> URL: https://issues.apache.org/jira/browse/MESOS-5752
> Project: Mesos
> Issue Type: Bug
> Affects Versions: 1.0.0
> Environment: Centos 7
> Reporter: Jie Yu
>
> {noformat}
> [19:17:15] : [Step 10/10] [ RUN ]
> ROOT_GarbageCollectorUndeletableFilesTest.BusyMountPoint
> [19:17:15]W: [Step 10/10] I0630 19:17:15.084791 31223 cluster.cpp:155]
> Creating default 'local' authorizer
> [19:17:15]W: [Step 10/10] I0630 19:17:15.089606 31223 leveldb.cpp:174]
> Opened db in 4.713001ms
> [19:17:15]W: [Step 10/10] I0630 19:17:15.090878 31223 leveldb.cpp:181]
> Compacted db in 1.253446ms
> [19:17:15]W: [Step 10/10] I0630 19:17:15.090898 31223 leveldb.cpp:196]
> Created db iterator in 3553ns
> [19:17:15]W: [Step 10/10] I0630 19:17:15.090903 31223 leveldb.cpp:202]
> Seeked to beginning of db in 599ns
> [19:17:15]W: [Step 10/10] I0630 19:17:15.090909 31223 leveldb.cpp:271]
> Iterated through 0 keys in the db in 364ns
> [19:17:15]W: [Step 10/10] I0630 19:17:15.090920 31223 replica.cpp:779]
> Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> [19:17:15]W: [Step 10/10] I0630 19:17:15.091115 31243 recover.cpp:451]
> Starting replica recovery
> [19:17:15]W: [Step 10/10] I0630 19:17:15.091217 31242 recover.cpp:477]
> Replica is in EMPTY status
> [19:17:15]W: [Step 10/10] I0630 19:17:15.091442 31243 replica.cpp:673]
> Replica in EMPTY status received a broadcasted recover request from
> (3210)@172.30.2.172:43264
> [19:17:15]W: [Step 10/10] I0630 19:17:15.091569 31240 recover.cpp:197]
> Received a recover response from a replica in EMPTY status
> [19:17:15]W: [Step 10/10] I0630 19:17:15.091693 31241 recover.cpp:568]
> Updating replica status to STARTING
> [19:17:15]W: [Step 10/10] I0630 19:17:15.091995 31237 master.cpp:382]
> Master 9c6bf850-2a66-41f8-a0ad-13c674886778 (ip-172-30-2-172.mesosphere.io)
> started on 172.30.2.172:43264
> [19:17:15]W: [Step 10/10] I0630 19:17:15.092010 31237 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/BD92iQ/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/BD92iQ/master"
> --zk_session_timeout="10secs"
> [19:17:15]W: [Step 10/10] I0630 19:17:15.092118 31237 master.cpp:434]
> Master only allowing authenticated frameworks to register
> [19:17:15]W: [Step 10/10] I0630 19:17:15.092123 31237 master.cpp:448]
> Master only allowing authenticated agents to register
> [19:17:15]W: [Step 10/10] I0630 19:17:15.092126 31237 master.cpp:461]
> Master only allowing authenticated HTTP frameworks to register
> [19:17:15]W: [Step 10/10] I0630 19:17:15.092130 31237 credentials.hpp:37]
> Loading credentials for authentication from '/tmp/BD92iQ/credentials'
> [19:17:15]W: [Step 10/10] I0630 19:17:15.092205 31237 master.cpp:506] Using
> default 'crammd5' authenticator
> [19:17:15]W: [Step 10/10] I0630 19:17:15.092239 31237 master.cpp:578] Using
> default 'basic' HTTP authenticator
> [19:17:15]W: [Step 10/10] I0630 19:17:15.092298 31237 master.cpp:658] Using
> default 'basic' HTTP framework authenticator
> [19:17:15]W: [Step 10/10] I0630 19:17:15.092339 31237 master.cpp:705]
> Authorization enabled
> [19:17:15]W: [Step 10/10] I0630 19:17:15.092438 31239
> whitelist_watcher.cpp:77] No whitelist given
> [19:17:15]W: [Step 10/10] I0630 19:17:15.092481 31244 hierarchical.cpp:142]
> Initialized hierarchical allocator process
> [19:17:15]W: [Step 10/10] I0630 19:17:15.093005 31243 leveldb.cpp:304]
> Persisting metadata (8 bytes) to leveldb took 1.280756ms
> [19:17:15]W: [Step 10/10] I0630 19:17:15.093022 31243 replica.cpp:320]
> Persisted replica status to STARTING
> [19:17:15]W: [Step 10/10] I0630 19:17:15.093035 31240 master.cpp:1971] The
> newly elected leader is [email protected]:43264 with id
> 9c6bf850-2a66-41f8-a0ad-13c674886778
> [19:17:15]W: [Step 10/10] I0630 19:17:15.093063 31240 master.cpp:1984]
> Elected as the leading master!
> [19:17:15]W: [Step 10/10] I0630 19:17:15.093073 31240 master.cpp:1671]
> Recovering from registrar
> [19:17:15]W: [Step 10/10] I0630 19:17:15.093080 31239 recover.cpp:477]
> Replica is in STARTING status
> [19:17:15]W: [Step 10/10] I0630 19:17:15.093130 31242 registrar.cpp:332]
> Recovering registrar
> [19:17:15]W: [Step 10/10] I0630 19:17:15.093397 31239 replica.cpp:673]
> Replica in STARTING status received a broadcasted recover request from
> (3213)@172.30.2.172:43264
> [19:17:15]W: [Step 10/10] I0630 19:17:15.093489 31240 recover.cpp:197]
> Received a recover response from a replica in STARTING status
> [19:17:15]W: [Step 10/10] I0630 19:17:15.093610 31239 recover.cpp:568]
> Updating replica status to VOTING
> [19:17:15]W: [Step 10/10] I0630 19:17:15.094800 31238 leveldb.cpp:304]
> Persisting metadata (8 bytes) to leveldb took 1.0927ms
> [19:17:15]W: [Step 10/10] I0630 19:17:15.094816 31238 replica.cpp:320]
> Persisted replica status to VOTING
> [19:17:15]W: [Step 10/10] I0630 19:17:15.094853 31238 recover.cpp:582]
> Successfully joined the Paxos group
> [19:17:15]W: [Step 10/10] I0630 19:17:15.094902 31238 recover.cpp:466]
> Recover process terminated
> [19:17:15]W: [Step 10/10] I0630 19:17:15.095093 31237 log.cpp:553]
> Attempting to start the writer
> [19:17:15]W: [Step 10/10] I0630 19:17:15.095526 31243 replica.cpp:493]
> Replica received implicit promise request from (3214)@172.30.2.172:43264 with
> proposal 1
> [19:17:15]W: [Step 10/10] I0630 19:17:15.096683 31243 leveldb.cpp:304]
> Persisting metadata (8 bytes) to leveldb took 1.139956ms
> [19:17:15]W: [Step 10/10] I0630 19:17:15.096698 31243 replica.cpp:342]
> Persisted promised to 1
> [19:17:15]W: [Step 10/10] I0630 19:17:15.096878 31237 coordinator.cpp:238]
> Coordinator attempting to fill missing positions
> [19:17:15]W: [Step 10/10] I0630 19:17:15.097285 31241 replica.cpp:388]
> Replica received explicit promise request from (3215)@172.30.2.172:43264 for
> position 0 with proposal 2
> [19:17:15]W: [Step 10/10] I0630 19:17:15.098515 31241 leveldb.cpp:341]
> Persisting action (8 bytes) to leveldb took 1.207696ms
> [19:17:15]W: [Step 10/10] I0630 19:17:15.098529 31241 replica.cpp:712]
> Persisted action at 0
> [19:17:15]W: [Step 10/10] I0630 19:17:15.098958 31239 replica.cpp:537]
> Replica received write request for position 0 from (3216)@172.30.2.172:43264
> [19:17:15]W: [Step 10/10] I0630 19:17:15.098981 31239 leveldb.cpp:436]
> Reading position from leveldb took 10608ns
> [19:17:15]W: [Step 10/10] I0630 19:17:15.100450 31239 leveldb.cpp:341]
> Persisting action (14 bytes) to leveldb took 1.455496ms
> [19:17:15]W: [Step 10/10] I0630 19:17:15.100466 31239 replica.cpp:712]
> Persisted action at 0
> [19:17:15]W: [Step 10/10] I0630 19:17:15.100706 31242 replica.cpp:691]
> Replica received learned notice for position 0 from @0.0.0.0:0
> [19:17:15]W: [Step 10/10] I0630 19:17:15.101811 31242 leveldb.cpp:341]
> Persisting action (16 bytes) to leveldb took 1.088226ms
> [19:17:15]W: [Step 10/10] I0630 19:17:15.101826 31242 replica.cpp:712]
> Persisted action at 0
> [19:17:15]W: [Step 10/10] I0630 19:17:15.101831 31242 replica.cpp:697]
> Replica learned NOP action at position 0
> [19:17:15]W: [Step 10/10] I0630 19:17:15.101984 31241 log.cpp:569] Writer
> started with ending position 0
> [19:17:15]W: [Step 10/10] I0630 19:17:15.102241 31238 leveldb.cpp:436]
> Reading position from leveldb took 8110ns
> [19:17:15]W: [Step 10/10] I0630 19:17:15.102439 31242 registrar.cpp:365]
> Successfully fetched the registry (0B) in 9.28896ms
> [19:17:15]W: [Step 10/10] I0630 19:17:15.102473 31242 registrar.cpp:464]
> Applied 1 operations in 3645ns; attempting to update the 'registry'
> [19:17:15]W: [Step 10/10] I0630 19:17:15.102630 31244 log.cpp:577]
> Attempting to append 209 bytes to the log
> [19:17:15]W: [Step 10/10] I0630 19:17:15.102674 31244 coordinator.cpp:348]
> Coordinator attempting to write APPEND action at position 1
> [19:17:15]W: [Step 10/10] I0630 19:17:15.102957 31241 replica.cpp:537]
> Replica received write request for position 1 from (3217)@172.30.2.172:43264
> [19:17:15]W: [Step 10/10] I0630 19:17:15.104032 31241 leveldb.cpp:341]
> Persisting action (228 bytes) to leveldb took 1.057255ms
> [19:17:15]W: [Step 10/10] I0630 19:17:15.104048 31241 replica.cpp:712]
> Persisted action at 1
> [19:17:15]W: [Step 10/10] I0630 19:17:15.104243 31243 replica.cpp:691]
> Replica received learned notice for position 1 from @0.0.0.0:0
> [19:17:15]W: [Step 10/10] I0630 19:17:15.105320 31243 leveldb.cpp:341]
> Persisting action (230 bytes) to leveldb took 1.058823ms
> [19:17:15]W: [Step 10/10] I0630 19:17:15.105334 31243 replica.cpp:712]
> Persisted action at 1
> [19:17:15]W: [Step 10/10] I0630 19:17:15.105340 31243 replica.cpp:697]
> Replica learned APPEND action at position 1
> [19:17:15]W: [Step 10/10] I0630 19:17:15.105554 31242 registrar.cpp:509]
> Successfully updated the 'registry' in 3.062784ms
> [19:17:15]W: [Step 10/10] I0630 19:17:15.105593 31242 registrar.cpp:395]
> Successfully recovered registrar
> [19:17:15]W: [Step 10/10] I0630 19:17:15.105640 31244 log.cpp:596]
> Attempting to truncate the log to 1
> [19:17:15]W: [Step 10/10] I0630 19:17:15.105753 31239 master.cpp:1779]
> Recovered 0 agents from the Registry (170B) ; allowing 10mins for agents to
> re-register
> [19:17:15]W: [Step 10/10] I0630 19:17:15.105778 31240 hierarchical.cpp:169]
> Skipping recovery of hierarchical allocator: nothing to recover
> [19:17:15]W: [Step 10/10] I0630 19:17:15.105820 31237 coordinator.cpp:348]
> Coordinator attempting to write TRUNCATE action at position 2
> [19:17:15]W: [Step 10/10] I0630 19:17:15.106083 31244 replica.cpp:537]
> Replica received write request for position 2 from (3218)@172.30.2.172:43264
> [19:17:15]W: [Step 10/10] I0630 19:17:15.107131 31244 leveldb.cpp:341]
> Persisting action (16 bytes) to leveldb took 1.027321ms
> [19:17:15]W: [Step 10/10] I0630 19:17:15.107146 31244 replica.cpp:712]
> Persisted action at 2
> [19:17:15]W: [Step 10/10] I0630 19:17:15.107422 31238 replica.cpp:691]
> Replica received learned notice for position 2 from @0.0.0.0:0
> [19:17:15]W: [Step 10/10] I0630 19:17:15.108517 31238 leveldb.cpp:341]
> Persisting action (18 bytes) to leveldb took 1.076488ms
> [19:17:15]W: [Step 10/10] I0630 19:17:15.108546 31238 leveldb.cpp:399]
> Deleting ~1 keys from leveldb took 14675ns
> [19:17:15]W: [Step 10/10] I0630 19:17:15.108554 31238 replica.cpp:712]
> Persisted action at 2
> [19:17:15]W: [Step 10/10] I0630 19:17:15.108559 31238 replica.cpp:697]
> Replica learned TRUNCATE action at position 2
> [19:17:15]W: [Step 10/10] I0630 19:17:15.117233 31223
> containerizer.cpp:200] Using isolation:
> posix/cpu,posix/mem,filesystem/posix,network/cni
> [19:17:15]W: [Step 10/10] I0630 19:17:15.121891 31223
> linux_launcher.cpp:101] Using /sys/fs/cgroup/freezer as the freezer hierarchy
> for the Linux launcher
> [19:17:15]W: [Step 10/10] I0630 19:17:15.122577 31223 cluster.cpp:432]
> Creating default 'local' authorizer
> [19:17:15]W: [Step 10/10] I0630 19:17:15.122927 31241 slave.cpp:203] Agent
> started on 63)@172.30.2.172:43264
> [19:17:15]W: [Step 10/10] I0630 19:17:15.122941 31241 slave.cpp:204] Flags
> at startup: --acls="" --appc_simple_discovery_uri_prefix="http://";
> --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="true"
> --authenticatee="crammd5" --authorizer="local"
> --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false"
> --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false"
> --cgroups_root="mesos" --container_disk_watch_interval="15secs"
> --containerizers="mesos"
> --credential="/mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/credential"
> --default_role="*" --disk_watch_interval="1mins" --docker="docker"
> --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io";
> --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock"
> --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker"
> --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume"
> --enforce_container_disk_quota="false"
> --executor_registration_timeout="1mins"
> --executor_shutdown_grace_period="5secs"
> --fetcher_cache_dir="/mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/fetch"
> --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks"
> --gc_disk_headroom="0.1" --hadoop_home="" --help="false"
> --hostname_lookup="true" --http_authenticators="basic"
> --http_command_executor="false"
> --http_credentials="/mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/http_credentials"
> --image_provisioner_backend="copy" --initialize_driver_logging="true"
> --isolation="posix/cpu,posix/mem"
> --launcher_dir="/mnt/teamcity/work/4240ba9ddd0997c3/build/src"
> --logbufsecs="0" --logging_level="INFO"
> --oversubscribed_resources_interval="15secs" --perf_duration="10secs"
> --perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false"
> --recover="reconnect" --recovery_timeout="15mins"
> --registration_backoff_factor="10ms"
> --resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]"
> --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox"
> --strict="true" --switch_user="true" --systemd_enable_support="true"
> --systemd_runtime_directory="/run/systemd/system" --version="false"
> --work_dir="/mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM"
> [19:17:15]W: [Step 10/10] I0630 19:17:15.123149 31241 credentials.hpp:86]
> Loading credential for authentication from
> '/mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/credential'
> [19:17:15]W: [Step 10/10] I0630 19:17:15.123222 31241 slave.cpp:341] Agent
> using credential for: test-principal
> [19:17:15]W: [Step 10/10] I0630 19:17:15.123234 31241 credentials.hpp:37]
> Loading credentials for authentication from
> '/mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/http_credentials'
> [19:17:15]W: [Step 10/10] I0630 19:17:15.123292 31241 slave.cpp:393] Using
> default 'basic' HTTP authenticator
> [19:17:15]W: [Step 10/10] I0630 19:17:15.123373 31241 resources.cpp:572]
> Parsing resources as JSON failed:
> cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]
> [19:17:15]W: [Step 10/10] Trying semicolon-delimited string format instead
> [19:17:15]W: [Step 10/10] I0630 19:17:15.123452 31241 resources.cpp:572]
> Parsing resources as JSON failed:
> cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]
> [19:17:15]W: [Step 10/10] Trying semicolon-delimited string format instead
> [19:17:15]W: [Step 10/10] I0630 19:17:15.123476 31223 sched.cpp:224]
> Version: 1.0.0
> [19:17:15]W: [Step 10/10] I0630 19:17:15.123620 31238 sched.cpp:328] New
> master detected at [email protected]:43264
> [19:17:15]W: [Step 10/10] I0630 19:17:15.123615 31241 slave.cpp:592] Agent
> resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> [19:17:15]W: [Step 10/10] I0630 19:17:15.123638 31241 slave.cpp:600] Agent
> attributes: [ ]
> [19:17:15]W: [Step 10/10] I0630 19:17:15.123643 31241 slave.cpp:605] Agent
> hostname: ip-172-30-2-172.mesosphere.io
> [19:17:15]W: [Step 10/10] I0630 19:17:15.123648 31238 sched.cpp:394]
> Authenticating with master [email protected]:43264
> [19:17:15]W: [Step 10/10] I0630 19:17:15.123659 31238 sched.cpp:401] Using
> default CRAM-MD5 authenticatee
> [19:17:15]W: [Step 10/10] I0630 19:17:15.123752 31244
> authenticatee.cpp:121] Creating new client SASL connection
> [19:17:15]W: [Step 10/10] I0630 19:17:15.123966 31239 master.cpp:5966]
> Authenticating
> [email protected]:43264
> [19:17:15]W: [Step 10/10] I0630 19:17:15.123997 31241 state.cpp:57]
> Recovering state from
> '/mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/meta'
> [19:17:15]W: [Step 10/10] I0630 19:17:15.124028 31240
> authenticator.cpp:414] Starting authentication session for
> crammd5_authenticatee(171)@172.30.2.172:43264
> [19:17:15]W: [Step 10/10] I0630 19:17:15.124138 31239 authenticator.cpp:98]
> Creating new server SASL connection
> [19:17:15]W: [Step 10/10] I0630 19:17:15.124179 31241
> status_update_manager.cpp:200] Recovering status update manager
> [19:17:15]W: [Step 10/10] I0630 19:17:15.124284 31243
> containerizer.cpp:526] Recovering containerizer
> [19:17:15]W: [Step 10/10] I0630 19:17:15.124323 31240
> authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
> [19:17:15]W: [Step 10/10] I0630 19:17:15.124338 31240
> authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
> [19:17:15]W: [Step 10/10] I0630 19:17:15.124374 31240
> authenticator.cpp:204] Received SASL authentication start
> [19:17:15]W: [Step 10/10] I0630 19:17:15.124413 31240
> authenticator.cpp:326] Authentication requires more steps
> [19:17:15]W: [Step 10/10] I0630 19:17:15.124464 31244
> authenticatee.cpp:259] Received SASL authentication step
> [19:17:15]W: [Step 10/10] I0630 19:17:15.124526 31244
> authenticator.cpp:232] Received SASL authentication step
> [19:17:15]W: [Step 10/10] I0630 19:17:15.124541 31244 auxprop.cpp:107]
> Request to lookup properties for user: 'test-principal' realm:
> 'ip-172-30-2-172.mesosphere.io' server FQDN: 'ip-172-30-2-172.mesosphere.io'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> [19:17:15]W: [Step 10/10] I0630 19:17:15.124546 31244 auxprop.cpp:179]
> Looking up auxiliary property '*userPassword'
> [19:17:15]W: [Step 10/10] I0630 19:17:15.124552 31244 auxprop.cpp:179]
> Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> [19:17:15]W: [Step 10/10] I0630 19:17:15.124558 31244 auxprop.cpp:107]
> Request to lookup properties for user: 'test-principal' realm:
> 'ip-172-30-2-172.mesosphere.io' server FQDN: 'ip-172-30-2-172.mesosphere.io'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> [19:17:15]W: [Step 10/10] I0630 19:17:15.124562 31244 auxprop.cpp:129]
> Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> [19:17:15]W: [Step 10/10] I0630 19:17:15.124567 31244 auxprop.cpp:129]
> Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since
> SASL_AUXPROP_AUTHZID == true
> [19:17:15]W: [Step 10/10] I0630 19:17:15.124574 31244
> authenticator.cpp:318] Authentication success
> [19:17:15]W: [Step 10/10] I0630 19:17:15.124615 31244 master.cpp:5996]
> Successfully authenticated principal 'test-principal' at
> [email protected]:43264
> [19:17:15]W: [Step 10/10] I0630 19:17:15.124632 31240
> authenticator.cpp:432] Authentication session cleanup for
> crammd5_authenticatee(171)@172.30.2.172:43264
> [19:17:15]W: [Step 10/10] I0630 19:17:15.124649 31242
> authenticatee.cpp:299] Authentication success
> [19:17:15]W: [Step 10/10] I0630 19:17:15.124754 31239 sched.cpp:484]
> Successfully authenticated with master [email protected]:43264
> [19:17:15]W: [Step 10/10] I0630 19:17:15.124768 31239 sched.cpp:800]
> Sending SUBSCRIBE call to [email protected]:43264
> [19:17:15]W: [Step 10/10] I0630 19:17:15.124804 31239 sched.cpp:833] Will
> retry registration in 1.363250285secs if necessary
> [19:17:15]W: [Step 10/10] I0630 19:17:15.124850 31244 master.cpp:2548]
> Received SUBSCRIBE call for framework 'default' at
> [email protected]:43264
> [19:17:15]W: [Step 10/10] I0630 19:17:15.124866 31244 master.cpp:2010]
> Authorizing framework principal 'test-principal' to receive offers for role
> '*'
> [19:17:15]W: [Step 10/10] I0630 19:17:15.124964 31244 master.cpp:2624]
> Subscribing framework default with checkpointing disabled and capabilities [
> ]
> [19:17:15]W: [Step 10/10] I0630 19:17:15.125099 31239 sched.cpp:723]
> Framework registered with 9c6bf850-2a66-41f8-a0ad-13c674886778-0000
> [19:17:15]W: [Step 10/10] I0630 19:17:15.125152 31239 sched.cpp:737]
> Scheduler::registered took 37597ns
> [19:17:15]W: [Step 10/10] I0630 19:17:15.125185 31241 hierarchical.cpp:268]
> Added framework 9c6bf850-2a66-41f8-a0ad-13c674886778-0000
> [19:17:15]W: [Step 10/10] I0630 19:17:15.125200 31241
> hierarchical.cpp:1512] No allocations performed
> [19:17:15]W: [Step 10/10] I0630 19:17:15.125205 31241
> hierarchical.cpp:1607] No inverse offers to send out!
> [19:17:15]W: [Step 10/10] I0630 19:17:15.125213 31241
> hierarchical.cpp:1147] Performed allocation for 0 agents in 18084ns
> [19:17:15]W: [Step 10/10] I0630 19:17:15.125511 31244 provisioner.cpp:253]
> Provisioner recovery complete
> [19:17:15]W: [Step 10/10] I0630 19:17:15.125680 31242 slave.cpp:4840]
> Finished recovery
> [19:17:15]W: [Step 10/10] I0630 19:17:15.125882 31242 slave.cpp:5012]
> Querying resource estimator for oversubscribable resources
> [19:17:15]W: [Step 10/10] I0630 19:17:15.126009 31240
> status_update_manager.cpp:174] Pausing sending status updates
> [19:17:15]W: [Step 10/10] I0630 19:17:15.126008 31237 slave.cpp:967] New
> master detected at [email protected]:43264
> [19:17:15]W: [Step 10/10] I0630 19:17:15.126030 31237 slave.cpp:1029]
> Authenticating with master [email protected]:43264
> [19:17:15]W: [Step 10/10] I0630 19:17:15.126040 31237 slave.cpp:1040] Using
> default CRAM-MD5 authenticatee
> [19:17:15]W: [Step 10/10] I0630 19:17:15.126073 31237 slave.cpp:1002]
> Detecting new master
> [19:17:15]W: [Step 10/10] I0630 19:17:15.126099 31243
> authenticatee.cpp:121] Creating new client SASL connection
> [19:17:15]W: [Step 10/10] I0630 19:17:15.126123 31237 slave.cpp:5026]
> Received oversubscribable resources from the resource estimator
> [19:17:15]W: [Step 10/10] I0630 19:17:15.126269 31243 master.cpp:5966]
> Authenticating slave(63)@172.30.2.172:43264
> [19:17:15]W: [Step 10/10] I0630 19:17:15.126319 31242
> authenticator.cpp:414] Starting authentication session for
> crammd5_authenticatee(172)@172.30.2.172:43264
> [19:17:15]W: [Step 10/10] I0630 19:17:15.126375 31242 authenticator.cpp:98]
> Creating new server SASL connection
> [19:17:15]W: [Step 10/10] I0630 19:17:15.126535 31243
> authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
> [19:17:15]W: [Step 10/10] I0630 19:17:15.126549 31243
> authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
> [19:17:15]W: [Step 10/10] I0630 19:17:15.126576 31243
> authenticator.cpp:204] Received SASL authentication start
> [19:17:15]W: [Step 10/10] I0630 19:17:15.126602 31243
> authenticator.cpp:326] Authentication requires more steps
> [19:17:15]W: [Step 10/10] I0630 19:17:15.126660 31240
> authenticatee.cpp:259] Received SASL authentication step
> [19:17:15]W: [Step 10/10] I0630 19:17:15.126700 31240
> authenticator.cpp:232] Received SASL authentication step
> [19:17:15]W: [Step 10/10] I0630 19:17:15.126713 31240 auxprop.cpp:107]
> Request to lookup properties for user: 'test-principal' realm:
> 'ip-172-30-2-172.mesosphere.io' server FQDN: 'ip-172-30-2-172.mesosphere.io'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> [19:17:15]W: [Step 10/10] I0630 19:17:15.126721 31240 auxprop.cpp:179]
> Looking up auxiliary property '*userPassword'
> [19:17:15]W: [Step 10/10] I0630 19:17:15.126734 31240 auxprop.cpp:179]
> Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> [19:17:15]W: [Step 10/10] I0630 19:17:15.126745 31240 auxprop.cpp:107]
> Request to lookup properties for user: 'test-principal' realm:
> 'ip-172-30-2-172.mesosphere.io' server FQDN: 'ip-172-30-2-172.mesosphere.io'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> [19:17:15]W: [Step 10/10] I0630 19:17:15.126752 31240 auxprop.cpp:129]
> Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> [19:17:15]W: [Step 10/10] I0630 19:17:15.126756 31240 auxprop.cpp:129]
> Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since
> SASL_AUXPROP_AUTHZID == true
> [19:17:15]W: [Step 10/10] I0630 19:17:15.126768 31240
> authenticator.cpp:318] Authentication success
> [19:17:15]W: [Step 10/10] I0630 19:17:15.126824 31237
> authenticatee.cpp:299] Authentication success
> [19:17:15]W: [Step 10/10] I0630 19:17:15.126848 31240 master.cpp:5996]
> Successfully authenticated principal 'test-principal' at
> slave(63)@172.30.2.172:43264
> [19:17:15]W: [Step 10/10] I0630 19:17:15.126874 31243
> authenticator.cpp:432] Authentication session cleanup for
> crammd5_authenticatee(172)@172.30.2.172:43264
> [19:17:15]W: [Step 10/10] I0630 19:17:15.126960 31239 slave.cpp:1108]
> Successfully authenticated with master [email protected]:43264
> [19:17:15]W: [Step 10/10] I0630 19:17:15.127003 31239 slave.cpp:1511] Will
> retry registration in 5.71085ms if necessary
> [19:17:15]W: [Step 10/10] I0630 19:17:15.127058 31241 master.cpp:4674]
> Registering agent at slave(63)@172.30.2.172:43264
> (ip-172-30-2-172.mesosphere.io) with id
> 9c6bf850-2a66-41f8-a0ad-13c674886778-S0
> [19:17:15]W: [Step 10/10] I0630 19:17:15.127166 31244 registrar.cpp:464]
> Applied 1 operations in 11173ns; attempting to update the 'registry'
> [19:17:15]W: [Step 10/10] I0630 19:17:15.127341 31237 log.cpp:577]
> Attempting to append 395 bytes to the log
> [19:17:15]W: [Step 10/10] I0630 19:17:15.127384 31237 coordinator.cpp:348]
> Coordinator attempting to write APPEND action at position 3
> [19:17:15]W: [Step 10/10] I0630 19:17:15.127634 31243 replica.cpp:537]
> Replica received write request for position 3 from (3236)@172.30.2.172:43264
> [19:17:15]W: [Step 10/10] I0630 19:17:15.128716 31243 leveldb.cpp:341]
> Persisting action (414 bytes) to leveldb took 1.065209ms
> [19:17:15]W: [Step 10/10] I0630 19:17:15.128731 31243 replica.cpp:712]
> Persisted action at 3
> [19:17:15]W: [Step 10/10] I0630 19:17:15.128950 31241 replica.cpp:691]
> Replica received learned notice for position 3 from @0.0.0.0:0
> [19:17:15]W: [Step 10/10] I0630 19:17:15.130023 31241 leveldb.cpp:341]
> Persisting action (416 bytes) to leveldb took 1.055965ms
> [19:17:15]W: [Step 10/10] I0630 19:17:15.130038 31241 replica.cpp:712]
> Persisted action at 3
> [19:17:15]W: [Step 10/10] I0630 19:17:15.130044 31241 replica.cpp:697]
> Replica learned APPEND action at position 3
> [19:17:15]W: [Step 10/10] I0630 19:17:15.130393 31244 registrar.cpp:509]
> Successfully updated the 'registry' in 3.206144ms
> [19:17:15]W: [Step 10/10] I0630 19:17:15.130439 31240 log.cpp:596]
> Attempting to truncate the log to 3
> [19:17:15]W: [Step 10/10] I0630 19:17:15.130494 31237 coordinator.cpp:348]
> Coordinator attempting to write TRUNCATE action at position 4
> [19:17:15]W: [Step 10/10] I0630 19:17:15.130570 31240 slave.cpp:3742]
> Received ping from slave-observer(61)@172.30.2.172:43264
> [19:17:15]W: [Step 10/10] I0630 19:17:15.130565 31242 master.cpp:4743]
> Registered agent 9c6bf850-2a66-41f8-a0ad-13c674886778-S0 at
> slave(63)@172.30.2.172:43264 (ip-172-30-2-172.mesosphere.io) with cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> [19:17:15]W: [Step 10/10] I0630 19:17:15.130625 31240 slave.cpp:1152]
> Registered with master [email protected]:43264; given agent ID
> 9c6bf850-2a66-41f8-a0ad-13c674886778-S0
> [19:17:15]W: [Step 10/10] I0630 19:17:15.130635 31240 fetcher.cpp:86]
> Clearing fetcher cache
> [19:17:15]W: [Step 10/10] I0630 19:17:15.130635 31244 hierarchical.cpp:481]
> Added agent 9c6bf850-2a66-41f8-a0ad-13c674886778-S0
> (ip-172-30-2-172.mesosphere.io) with cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000] (allocated: )
> [19:17:15]W: [Step 10/10] I0630 19:17:15.130695 31241
> status_update_manager.cpp:181] Resuming sending status updates
> [19:17:15]W: [Step 10/10] I0630 19:17:15.130823 31244
> hierarchical.cpp:1607] No inverse offers to send out!
> [19:17:15]W: [Step 10/10] I0630 19:17:15.130848 31244
> hierarchical.cpp:1170] Performed allocation for agent
> 9c6bf850-2a66-41f8-a0ad-13c674886778-S0 in 186035ns
> [19:17:15]W: [Step 10/10] I0630 19:17:15.130875 31240 slave.cpp:1175]
> Checkpointing SlaveInfo to
> '/mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/meta/slaves/9c6bf850-2a66-41f8-a0ad-13c674886778-S0/slave.info'
> [19:17:15]W: [Step 10/10] I0630 19:17:15.130882 31243 replica.cpp:537]
> Replica received write request for position 4 from (3237)@172.30.2.172:43264
> [19:17:15]W: [Step 10/10] I0630 19:17:15.130959 31239 master.cpp:5795]
> Sending 1 offers to framework 9c6bf850-2a66-41f8-a0ad-13c674886778-0000
> (default) at [email protected]:43264
> [19:17:15]W: [Step 10/10] I0630 19:17:15.131042 31240 slave.cpp:1212]
> Forwarding total oversubscribed resources
> [19:17:15]W: [Step 10/10] I0630 19:17:15.131115 31244 master.cpp:5089]
> Received update of agent 9c6bf850-2a66-41f8-a0ad-13c674886778-S0 at
> slave(63)@172.30.2.172:43264 (ip-172-30-2-172.mesosphere.io) with total
> oversubscribed resources
> [19:17:15]W: [Step 10/10] I0630 19:17:15.131131 31241 sched.cpp:897]
> Scheduler::resourceOffers took 51497ns
> [19:17:15]W: [Step 10/10] I0630 19:17:15.131232 31239 hierarchical.cpp:539]
> Agent 9c6bf850-2a66-41f8-a0ad-13c674886778-S0 (ip-172-30-2-172.mesosphere.io)
> updated with oversubscribed resources (total: cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000])
> [19:17:15]W: [Step 10/10] I0630 19:17:15.131290 31223 resources.cpp:572]
> Parsing resources as JSON failed: cpus:1;mem:128;disk:1
> [19:17:15]W: [Step 10/10] Trying semicolon-delimited string format instead
> [19:17:15]W: [Step 10/10] I0630 19:17:15.131295 31239
> hierarchical.cpp:1512] No allocations performed
> [19:17:15]W: [Step 10/10] I0630 19:17:15.131304 31239
> hierarchical.cpp:1607] No inverse offers to send out!
> [19:17:15]W: [Step 10/10] I0630 19:17:15.131311 31239
> hierarchical.cpp:1170] Performed allocation for agent
> 9c6bf850-2a66-41f8-a0ad-13c674886778-S0 in 32378ns
> [19:17:15]W: [Step 10/10] I0630 19:17:15.131572 31244 master.cpp:3466]
> Processing ACCEPT call for offers: [ 9c6bf850-2a66-41f8-a0ad-13c674886778-O0
> ] on agent 9c6bf850-2a66-41f8-a0ad-13c674886778-S0 at
> slave(63)@172.30.2.172:43264 (ip-172-30-2-172.mesosphere.io) for framework
> 9c6bf850-2a66-41f8-a0ad-13c674886778-0000 (default) at
> [email protected]:43264
> [19:17:15]W: [Step 10/10] I0630 19:17:15.131594 31244 master.cpp:3104]
> Authorizing framework principal 'test-principal' to launch task test-task123
> [19:17:15]W: [Step 10/10] I0630 19:17:15.131937 31243 leveldb.cpp:341]
> Persisting action (16 bytes) to leveldb took 1.035295ms
> [19:17:15]W: [Step 10/10] I0630 19:17:15.131938 31237 master.cpp:7515]
> Adding task test-task123 with resources cpus(*):1; mem(*):128; disk(*):1 on
> agent 9c6bf850-2a66-41f8-a0ad-13c674886778-S0 (ip-172-30-2-172.mesosphere.io)
> [19:17:15]W: [Step 10/10] I0630 19:17:15.131958 31243 replica.cpp:712]
> Persisted action at 4
> [19:17:15]W: [Step 10/10] I0630 19:17:15.131981 31237 master.cpp:3955]
> Launching task test-task123 of framework
> 9c6bf850-2a66-41f8-a0ad-13c674886778-0000 (default) at
> [email protected]:43264 with
> resources cpus(*):1; mem(*):128; disk(*):1 on agent
> 9c6bf850-2a66-41f8-a0ad-13c674886778-S0 at slave(63)@172.30.2.172:43264
> (ip-172-30-2-172.mesosphere.io)
> [19:17:15]W: [Step 10/10] I0630 19:17:15.132159 31237 hierarchical.cpp:899]
> Recovered cpus(*):1; mem(*):896; disk(*):1023; ports(*):[31000-32000] (total:
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated:
> cpus(*):1; mem(*):128; disk(*):1) on agent
> 9c6bf850-2a66-41f8-a0ad-13c674886778-S0 from framework
> 9c6bf850-2a66-41f8-a0ad-13c674886778-0000
> [19:17:15]W: [Step 10/10] I0630 19:17:15.132184 31244 slave.cpp:1551] Got
> assigned task test-task123 for framework
> 9c6bf850-2a66-41f8-a0ad-13c674886778-0000
> [19:17:15]W: [Step 10/10] I0630 19:17:15.132202 31237 hierarchical.cpp:936]
> Framework 9c6bf850-2a66-41f8-a0ad-13c674886778-0000 filtered agent
> 9c6bf850-2a66-41f8-a0ad-13c674886778-S0 for 5secs
> [19:17:15]W: [Step 10/10] I0630 19:17:15.132256 31239 replica.cpp:691]
> Replica received learned notice for position 4 from @0.0.0.0:0
> [19:17:15]W: [Step 10/10] I0630 19:17:15.132292 31244 resources.cpp:572]
> Parsing resources as JSON failed: cpus:0.1;mem:32
> [19:17:15]W: [Step 10/10] Trying semicolon-delimited string format instead
> [19:17:15]W: [Step 10/10] I0630 19:17:15.132413 31244 slave.cpp:1670]
> Launching task test-task123 for framework
> 9c6bf850-2a66-41f8-a0ad-13c674886778-0000
> [19:17:15]W: [Step 10/10] I0630 19:17:15.132442 31244 resources.cpp:572]
> Parsing resources as JSON failed: cpus:0.1;mem:32
> [19:17:15]W: [Step 10/10] Trying semicolon-delimited string format instead
> [19:17:15]W: [Step 10/10] I0630 19:17:15.132755 31244 paths.cpp:528] Trying
> to chown
> '/mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/slaves/9c6bf850-2a66-41f8-a0ad-13c674886778-S0/frameworks/9c6bf850-2a66-41f8-a0ad-13c674886778-0000/executors/test-task123/runs/0d146f10-0d93-4b01-96e2-095c7dcf2b4b'
> to user 'root'
> [19:17:15]W: [Step 10/10] I0630 19:17:15.133651 31239 leveldb.cpp:341]
> Persisting action (18 bytes) to leveldb took 1.306211ms
> [19:17:15]W: [Step 10/10] I0630 19:17:15.133707 31239 leveldb.cpp:399]
> Deleting ~2 keys from leveldb took 25790ns
> [19:17:15]W: [Step 10/10] I0630 19:17:15.133719 31239 replica.cpp:712]
> Persisted action at 4
> [19:17:15]W: [Step 10/10] I0630 19:17:15.133726 31239 replica.cpp:697]
> Replica learned TRUNCATE action at position 4
> [19:17:15]W: [Step 10/10] I0630 19:17:15.136097 31244 slave.cpp:5726]
> Launching executor test-task123 of framework
> 9c6bf850-2a66-41f8-a0ad-13c674886778-0000 with resources cpus(*):0.1;
> mem(*):32 in work directory
> '/mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/slaves/9c6bf850-2a66-41f8-a0ad-13c674886778-S0/frameworks/9c6bf850-2a66-41f8-a0ad-13c674886778-0000/executors/test-task123/runs/0d146f10-0d93-4b01-96e2-095c7dcf2b4b'
> [19:17:15]W: [Step 10/10] I0630 19:17:15.136209 31244 slave.cpp:1896]
> Queuing task 'test-task123' for executor 'test-task123' of framework
> 9c6bf850-2a66-41f8-a0ad-13c674886778-0000
> [19:17:15]W: [Step 10/10] I0630 19:17:15.136229 31241
> containerizer.cpp:785] Starting container
> '0d146f10-0d93-4b01-96e2-095c7dcf2b4b' for executor 'test-task123' of
> framework '9c6bf850-2a66-41f8-a0ad-13c674886778-0000'
> [19:17:15]W: [Step 10/10] I0630 19:17:15.136258 31244 slave.cpp:920]
> Successfully attached file
> '/mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/slaves/9c6bf850-2a66-41f8-a0ad-13c674886778-S0/frameworks/9c6bf850-2a66-41f8-a0ad-13c674886778-0000/executors/test-task123/runs/0d146f10-0d93-4b01-96e2-095c7dcf2b4b'
> [19:17:15]W: [Step 10/10] I0630 19:17:15.136987 31243
> containerizer.cpp:1276] Launching 'mesos-containerizer' with flags
> '--command="{"shell":true,"value":"\/mnt\/teamcity\/work\/4240ba9ddd0997c3\/build\/src\/mesos-executor"}"
> --commands="{"commands":[]}" --help="false" --pipe_read="7"
> --pipe_write="10"
> --sandbox="/mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/slaves/9c6bf850-2a66-41f8-a0ad-13c674886778-S0/frameworks/9c6bf850-2a66-41f8-a0ad-13c674886778-0000/executors/test-task123/runs/0d146f10-0d93-4b01-96e2-095c7dcf2b4b"
> --user="root"'
> [19:17:15]W: [Step 10/10] I0630 19:17:15.137044 31243
> linux_launcher.cpp:281] Cloning child process with flags =
> [19:17:15]W: [Step 10/10] I0630 19:17:15.207006 3412 exec.cpp:161]
> Version: 1.0.0
> [19:17:15]W: [Step 10/10] I0630 19:17:15.207625 31243 slave.cpp:2884] Got
> registration for executor 'test-task123' of framework
> 9c6bf850-2a66-41f8-a0ad-13c674886778-0000 from executor(1)@172.30.2.172:40229
> [19:17:15]W: [Step 10/10] I0630 19:17:15.208122 3408 exec.cpp:236]
> Executor registered on agent 9c6bf850-2a66-41f8-a0ad-13c674886778-S0
> [19:17:15]W: [Step 10/10] I0630 19:17:15.208317 31242 slave.cpp:2061]
> Sending queued task 'test-task123' to executor 'test-task123' of framework
> 9c6bf850-2a66-41f8-a0ad-13c674886778-0000 at executor(1)@172.30.2.172:40229
> [19:17:15] : [Step 10/10] Received SUBSCRIBED event
> [19:17:15] : [Step 10/10] Subscribed executor on
> ip-172-30-2-172.mesosphere.io
> [19:17:15] : [Step 10/10] Received LAUNCH event
> [19:17:15] : [Step 10/10] Starting task test-task123
> [19:17:15] : [Step 10/10] Forked command at 3414
> [19:17:15] : [Step 10/10] sh -c 'touch test2.txt; mkdir test1; mount --bind
> test1 test1'
> [19:17:15]W: [Step 10/10] I0630 19:17:15.212513 31237 slave.cpp:3267]
> Handling status update TASK_RUNNING (UUID:
> 5d1ed007-382b-4a2b-8d2e-709a02d4a743) for task test-task123 of framework
> 9c6bf850-2a66-41f8-a0ad-13c674886778-0000 from executor(1)@172.30.2.172:40229
> [19:17:15]W: [Step 10/10] I0630 19:17:15.212956 31238
> status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID:
> 5d1ed007-382b-4a2b-8d2e-709a02d4a743) for task test-task123 of framework
> 9c6bf850-2a66-41f8-a0ad-13c674886778-0000
> [19:17:15]W: [Step 10/10] I0630 19:17:15.212980 31238
> status_update_manager.cpp:497] Creating StatusUpdate stream for task
> test-task123 of framework 9c6bf850-2a66-41f8-a0ad-13c674886778-0000
> [19:17:15]W: [Step 10/10] I0630 19:17:15.213213 31238
> status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID:
> 5d1ed007-382b-4a2b-8d2e-709a02d4a743) for task test-task123 of framework
> 9c6bf850-2a66-41f8-a0ad-13c674886778-0000 to the agent
> [19:17:15]W: [Step 10/10] I0630 19:17:15.213311 31242 slave.cpp:3660]
> Forwarding the update TASK_RUNNING (UUID:
> 5d1ed007-382b-4a2b-8d2e-709a02d4a743) for task test-task123 of framework
> 9c6bf850-2a66-41f8-a0ad-13c674886778-0000 to [email protected]:43264
> [19:17:15]W: [Step 10/10] I0630 19:17:15.213394 31242 slave.cpp:3554]
> Status update manager successfully handled status update TASK_RUNNING (UUID:
> 5d1ed007-382b-4a2b-8d2e-709a02d4a743) for task test-task123 of framework
> 9c6bf850-2a66-41f8-a0ad-13c674886778-0000
> [19:17:15]W: [Step 10/10] I0630 19:17:15.213416 31242 slave.cpp:3570]
> Sending acknowledgement for status update TASK_RUNNING (UUID:
> 5d1ed007-382b-4a2b-8d2e-709a02d4a743) for task test-task123 of framework
> 9c6bf850-2a66-41f8-a0ad-13c674886778-0000 to executor(1)@172.30.2.172:40229
> [19:17:15]W: [Step 10/10] I0630 19:17:15.213474 31239 master.cpp:5234]
> Status update TASK_RUNNING (UUID: 5d1ed007-382b-4a2b-8d2e-709a02d4a743) for
> task test-task123 of framework 9c6bf850-2a66-41f8-a0ad-13c674886778-0000 from
> agent 9c6bf850-2a66-41f8-a0ad-13c674886778-S0 at slave(63)@172.30.2.172:43264
> (ip-172-30-2-172.mesosphere.io)
> [19:17:15]W: [Step 10/10] I0630 19:17:15.213500 31239 master.cpp:5282]
> Forwarding status update TASK_RUNNING (UUID:
> 5d1ed007-382b-4a2b-8d2e-709a02d4a743) for task test-task123 of framework
> 9c6bf850-2a66-41f8-a0ad-13c674886778-0000
> [19:17:15] : [Step 10/10] ../../src/tests/gc_tests.cpp:963: Failure
> [19:17:15]W: [Step 10/10] I0630 19:17:15.213548 31239 master.cpp:6909]
> Updating the state of task test-task123 of framework
> 9c6bf850-2a66-41f8-a0ad-13c674886778-0000 (latest state: TASK_RUNNING, status
> update state: TASK_RUNNING)
> [19:17:15] : [Step 10/10] Value of: os::exists(path::join(sandbox,
> mountPoint_))
> [19:17:15] : [Step 10/10] Actual: false
> [19:17:15]W: [Step 10/10] I0630 19:17:15.213657 31243 sched.cpp:1005]
> Scheduler::statusUpdate took 54225ns
> [19:17:15] : [Step 10/10] Expected: true
> [19:17:15]W: [Step 10/10] I0630 19:17:15.213809 31239 master.cpp:4386]
> Processing ACKNOWLEDGE call 5d1ed007-382b-4a2b-8d2e-709a02d4a743 for task
> test-task123 of framework 9c6bf850-2a66-41f8-a0ad-13c674886778-0000 (default)
> at [email protected]:43264 on agent
> 9c6bf850-2a66-41f8-a0ad-13c674886778-S0
> [19:17:15]W: [Step 10/10] I0630 19:17:15.213891 31239
> status_update_manager.cpp:392] Received status update acknowledgement (UUID:
> 5d1ed007-382b-4a2b-8d2e-709a02d4a743) for task test-task123 of framework
> 9c6bf850-2a66-41f8-a0ad-13c674886778-0000
> [19:17:15]W: [Step 10/10] I0630 19:17:15.213979 31239 slave.cpp:2653]
> Status update manager successfully handled status update acknowledgement
> (UUID: 5d1ed007-382b-4a2b-8d2e-709a02d4a743) for task test-task123 of
> framework 9c6bf850-2a66-41f8-a0ad-13c674886778-0000
> [19:17:15] : [Step 10/10] Command exited with status 0 (pid: 3414)
> [19:17:15]W: [Step 10/10] I0630 19:17:15.312355 31243 slave.cpp:3267]
> Handling status update TASK_FINISHED (UUID:
> 9512f6f4-21ea-4ffb-9858-edc3421cd6a9) for task test-task123 of framework
> 9c6bf850-2a66-41f8-a0ad-13c674886778-0000 from executor(1)@172.30.2.172:40229
> [19:17:15]W: [Step 10/10] I0630 19:17:15.312757 31243 slave.cpp:6066]
> Terminating task test-task123
> [19:17:15]W: [Step 10/10] I0630 19:17:15.313128 31243
> status_update_manager.cpp:320] Received status update TASK_FINISHED (UUID:
> 9512f6f4-21ea-4ffb-9858-edc3421cd6a9) for task test-task123 of framework
> 9c6bf850-2a66-41f8-a0ad-13c674886778-0000
> [19:17:15]W: [Step 10/10] I0630 19:17:15.313175 31243
> status_update_manager.cpp:374] Forwarding update TASK_FINISHED (UUID:
> 9512f6f4-21ea-4ffb-9858-edc3421cd6a9) for task test-task123 of framework
> 9c6bf850-2a66-41f8-a0ad-13c674886778-0000 to the agent
> [19:17:15]W: [Step 10/10] I0630 19:17:15.313251 31237 slave.cpp:3660]
> Forwarding the update TASK_FINISHED (UUID:
> 9512f6f4-21ea-4ffb-9858-edc3421cd6a9) for task test-task123 of framework
> 9c6bf850-2a66-41f8-a0ad-13c674886778-0000 to [email protected]:43264
> [19:17:15]W: [Step 10/10] I0630 19:17:15.313319 31237 slave.cpp:3554]
> Status update manager successfully handled status update TASK_FINISHED (UUID:
> 9512f6f4-21ea-4ffb-9858-edc3421cd6a9) for task test-task123 of framework
> 9c6bf850-2a66-41f8-a0ad-13c674886778-0000
> [19:17:15]W: [Step 10/10] I0630 19:17:15.313333 31237 slave.cpp:3570]
> Sending acknowledgement for status update TASK_FINISHED (UUID:
> 9512f6f4-21ea-4ffb-9858-edc3421cd6a9) for task test-task123 of framework
> 9c6bf850-2a66-41f8-a0ad-13c674886778-0000 to executor(1)@172.30.2.172:40229
> [19:17:15]W: [Step 10/10] I0630 19:17:15.313387 31239 master.cpp:5234]
> Status update TASK_FINISHED (UUID: 9512f6f4-21ea-4ffb-9858-edc3421cd6a9) for
> task test-task123 of framework 9c6bf850-2a66-41f8-a0ad-13c674886778-0000 from
> agent 9c6bf850-2a66-41f8-a0ad-13c674886778-S0 at slave(63)@172.30.2.172:43264
> (ip-172-30-2-172.mesosphere.io)
> [19:17:15]W: [Step 10/10] I0630 19:17:15.313415 31239 master.cpp:5282]
> Forwarding status update TASK_FINISHED (UUID:
> 9512f6f4-21ea-4ffb-9858-edc3421cd6a9) for task test-task123 of framework
> 9c6bf850-2a66-41f8-a0ad-13c674886778-0000
> [19:17:15]W: [Step 10/10] I0630 19:17:15.313474 31239 master.cpp:6909]
> Updating the state of task test-task123 of framework
> 9c6bf850-2a66-41f8-a0ad-13c674886778-0000 (latest state: TASK_FINISHED,
> status update state: TASK_FINISHED)
> [19:17:15]W: [Step 10/10] I0630 19:17:15.313616 31240 sched.cpp:1005]
> Scheduler::statusUpdate took 56224ns
> [19:17:15]W: [Step 10/10] I0630 19:17:15.313650 31244 hierarchical.cpp:899]
> Recovered cpus(*):1; mem(*):128; disk(*):1 (total: cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000], allocated: ) on agent
> 9c6bf850-2a66-41f8-a0ad-13c674886778-S0 from framework
> 9c6bf850-2a66-41f8-a0ad-13c674886778-0000
> [19:17:15]W: [Step 10/10] I0630 19:17:15.313802 31241 master.cpp:4386]
> Processing ACKNOWLEDGE call 9512f6f4-21ea-4ffb-9858-edc3421cd6a9 for task
> test-task123 of framework 9c6bf850-2a66-41f8-a0ad-13c674886778-0000 (default)
> at [email protected]:43264 on agent
> 9c6bf850-2a66-41f8-a0ad-13c674886778-S0
> [19:17:15]W: [Step 10/10] I0630 19:17:15.313834 31241 master.cpp:6975]
> Removing task test-task123 with resources cpus(*):1; mem(*):128; disk(*):1 of
> framework 9c6bf850-2a66-41f8-a0ad-13c674886778-0000 on agent
> 9c6bf850-2a66-41f8-a0ad-13c674886778-S0 at slave(63)@172.30.2.172:43264
> (ip-172-30-2-172.mesosphere.io)
> [19:17:15]W: [Step 10/10] I0630 19:17:15.314010 31243
> status_update_manager.cpp:392] Received status update acknowledgement (UUID:
> 9512f6f4-21ea-4ffb-9858-edc3421cd6a9) for task test-task123 of framework
> 9c6bf850-2a66-41f8-a0ad-13c674886778-0000
> [19:17:15]W: [Step 10/10] I0630 19:17:15.314044 31243
> status_update_manager.cpp:528] Cleaning up status update stream for task
> test-task123 of framework 9c6bf850-2a66-41f8-a0ad-13c674886778-0000
> [19:17:15]W: [Step 10/10] I0630 19:17:15.314158 31243 slave.cpp:2653]
> Status update manager successfully handled status update acknowledgement
> (UUID: 9512f6f4-21ea-4ffb-9858-edc3421cd6a9) for task test-task123 of
> framework 9c6bf850-2a66-41f8-a0ad-13c674886778-0000
> [19:17:15]W: [Step 10/10] I0630 19:17:15.314175 31243 slave.cpp:6107]
> Completing task test-task123
> [19:17:16]W: [Step 10/10] I0630 19:17:16.093226 31243
> hierarchical.cpp:1607] No inverse offers to send out!
> [19:17:16]W: [Step 10/10] I0630 19:17:16.093273 31243
> hierarchical.cpp:1147] Performed allocation for 1 agents in 228824ns
> [19:17:16]W: [Step 10/10] I0630 19:17:16.093356 31241 master.cpp:5795]
> Sending 1 offers to framework 9c6bf850-2a66-41f8-a0ad-13c674886778-0000
> (default) at [email protected]:43264
> [19:17:16]W: [Step 10/10] I0630 19:17:16.093500 31241 sched.cpp:897]
> Scheduler::resourceOffers took 9728ns
> [19:17:16]W: [Step 10/10] I0630 19:17:16.314436 31237 slave.cpp:3788]
> executor(1)@172.30.2.172:40229 exited
> [19:17:16]W: [Step 10/10] I0630 19:17:16.332780 31242
> containerizer.cpp:1821] Executor for container
> '0d146f10-0d93-4b01-96e2-095c7dcf2b4b' has exited
> [19:17:16]W: [Step 10/10] I0630 19:17:16.332798 31242
> containerizer.cpp:1585] Destroying container
> '0d146f10-0d93-4b01-96e2-095c7dcf2b4b'
> [19:17:16]W: [Step 10/10] I0630 19:17:16.334414 31237 cgroups.cpp:2676]
> Freezing cgroup
> /sys/fs/cgroup/freezer/mesos/0d146f10-0d93-4b01-96e2-095c7dcf2b4b
> [19:17:16]W: [Step 10/10] I0630 19:17:16.335834 31241 cgroups.cpp:1409]
> Successfully froze cgroup
> /sys/fs/cgroup/freezer/mesos/0d146f10-0d93-4b01-96e2-095c7dcf2b4b after
> 1.394176ms
> [19:17:16]W: [Step 10/10] I0630 19:17:16.337170 31241 cgroups.cpp:2694]
> Thawing cgroup
> /sys/fs/cgroup/freezer/mesos/0d146f10-0d93-4b01-96e2-095c7dcf2b4b
> [19:17:16]W: [Step 10/10] I0630 19:17:16.338600 31238 cgroups.cpp:1438]
> Successfully thawed cgroup
> /sys/fs/cgroup/freezer/mesos/0d146f10-0d93-4b01-96e2-095c7dcf2b4b after
> 1.412096ms
> [19:17:16]W: [Step 10/10] I0630 19:17:16.339936 31239 provisioner.cpp:411]
> Ignoring destroy request for unknown container
> 0d146f10-0d93-4b01-96e2-095c7dcf2b4b
> [19:17:16]W: [Step 10/10] I0630 19:17:16.340039 31239 slave.cpp:4147]
> Executor 'test-task123' of framework
> 9c6bf850-2a66-41f8-a0ad-13c674886778-0000 exited with status 0
> [19:17:16]W: [Step 10/10] I0630 19:17:16.340059 31239 slave.cpp:4251]
> Cleaning up executor 'test-task123' of framework
> 9c6bf850-2a66-41f8-a0ad-13c674886778-0000 at executor(1)@172.30.2.172:40229
> [19:17:16]W: [Step 10/10] I0630 19:17:16.340191 31239 slave.cpp:4339]
> Cleaning up framework 9c6bf850-2a66-41f8-a0ad-13c674886778-0000
> [19:17:16]W: [Step 10/10] I0630 19:17:16.340201 31242 gc.cpp:55] Scheduling
> '/mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/slaves/9c6bf850-2a66-41f8-a0ad-13c674886778-S0/frameworks/9c6bf850-2a66-41f8-a0ad-13c674886778-0000/executors/test-task123/runs/0d146f10-0d93-4b01-96e2-095c7dcf2b4b'
> for gc 6.99999606342519days in the future
> [19:17:16]W: [Step 10/10] I0630 19:17:16.340306 31242 gc.cpp:55] Scheduling
> '/mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/slaves/9c6bf850-2a66-41f8-a0ad-13c674886778-S0/frameworks/9c6bf850-2a66-41f8-a0ad-13c674886778-0000/executors/test-task123'
> for gc 6.99999606276444days in the future
> [19:17:16]W: [Step 10/10] I0630 19:17:16.340337 31242 gc.cpp:55] Scheduling
> '/mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/slaves/9c6bf850-2a66-41f8-a0ad-13c674886778-S0/frameworks/9c6bf850-2a66-41f8-a0ad-13c674886778-0000'
> for gc 6.99999606177185days in the future
> [19:17:16]W: [Step 10/10] I0630 19:17:16.340361 31244
> status_update_manager.cpp:282] Closing status update streams for framework
> 9c6bf850-2a66-41f8-a0ad-13c674886778-0000
> [19:17:16]W: [Step 10/10] I0630 19:17:16.341758 31241 slave.cpp:5012]
> Querying resource estimator for oversubscribable resources
> [19:17:16]W: [Step 10/10] I0630 19:17:16.341822 31240
> hierarchical.cpp:1512] No allocations performed
> [19:17:16]W: [Step 10/10] I0630 19:17:16.341838 31240
> hierarchical.cpp:1607] No inverse offers to send out!
> [19:17:16]W: [Step 10/10] I0630 19:17:16.341853 31240
> hierarchical.cpp:1147] Performed allocation for 1 agents in 74626ns
> [19:17:16]W: [Step 10/10] I0630 19:17:16.341855 31238 gc.cpp:133] Deleting
> /mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/slaves/9c6bf850-2a66-41f8-a0ad-13c674886778-S0/frameworks/9c6bf850-2a66-41f8-a0ad-13c674886778-0000
> [19:17:16]W: [Step 10/10] I0630 19:17:16.341882 31241 slave.cpp:4557]
> Framework 9c6bf850-2a66-41f8-a0ad-13c674886778-0000 seems to have exited.
> Ignoring registration timeout for executor 'test-task123'
> [19:17:16]W: [Step 10/10] I0630 19:17:16.341924 31241 slave.cpp:3778] No
> pings from master received within 75secs
> [19:17:16]W: [Step 10/10] I0630 19:17:16.341975 31241 slave.cpp:3742]
> Received ping from slave-observer(61)@172.30.2.172:43264
> [19:17:16]W: [Step 10/10] I0630 19:17:16.342025 31241 slave.cpp:5026]
> Received oversubscribable resources from the resource estimator
> [19:17:16]W: [Step 10/10] E0630 19:17:16.342058 31238 rmdir.hpp:82] Failed
> to delete directory
> /mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/slaves/9c6bf850-2a66-41f8-a0ad-13c674886778-S0/frameworks/9c6bf850-2a66-41f8-a0ad-13c674886778-0000/mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/slaves/9c6bf850-2a66-41f8-a0ad-13c674886778-S0/frameworks/9c6bf850-2a66-41f8-a0ad-13c674886778-0000/executors/test-task123/runs/0d146f10-0d93-4b01-96e2-095c7dcf2b4b/test1:
> Device or resource busy
> [19:17:16]W: [Step 10/10] E0630 19:17:16.342078 31238 rmdir.hpp:82] Failed
> to delete directory
> /mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/slaves/9c6bf850-2a66-41f8-a0ad-13c674886778-S0/frameworks/9c6bf850-2a66-41f8-a0ad-13c674886778-0000/mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/slaves/9c6bf850-2a66-41f8-a0ad-13c674886778-S0/frameworks/9c6bf850-2a66-41f8-a0ad-13c674886778-0000/executors/test-task123/runs/0d146f10-0d93-4b01-96e2-095c7dcf2b4b:
> Directory not empty
> [19:17:16]W: [Step 10/10] I0630 19:17:16.342082 31241 slave.cpp:4649]
> Current disk usage 1.67%. Max allowed age: 6.183419343392488days
> [19:17:16]W: [Step 10/10] E0630 19:17:16.342090 31238 rmdir.hpp:82] Failed
> to delete directory
> /mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/slaves/9c6bf850-2a66-41f8-a0ad-13c674886778-S0/frameworks/9c6bf850-2a66-41f8-a0ad-13c674886778-0000/mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/slaves/9c6bf850-2a66-41f8-a0ad-13c674886778-S0/frameworks/9c6bf850-2a66-41f8-a0ad-13c674886778-0000/executors/test-task123/runs:
> Directory not empty
> [19:17:16]W: [Step 10/10] E0630 19:17:16.342118 31238 rmdir.hpp:82] Failed
> to delete directory
> /mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/slaves/9c6bf850-2a66-41f8-a0ad-13c674886778-S0/frameworks/9c6bf850-2a66-41f8-a0ad-13c674886778-0000/mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/slaves/9c6bf850-2a66-41f8-a0ad-13c674886778-S0/frameworks/9c6bf850-2a66-41f8-a0ad-13c674886778-0000/executors/test-task123:
> Directory not empty
> [19:17:16]W: [Step 10/10] I0630 19:17:16.342121 31241 slave.cpp:956]
> Re-detecting master
> [19:17:16]W: [Step 10/10] I0630 19:17:16.342129 31241 slave.cpp:1002]
> Detecting new master
> [19:17:16]W: [Step 10/10] E0630 19:17:16.342140 31238 rmdir.hpp:82] Failed
> to delete directory
> /mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/slaves/9c6bf850-2a66-41f8-a0ad-13c674886778-S0/frameworks/9c6bf850-2a66-41f8-a0ad-13c674886778-0000/mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/slaves/9c6bf850-2a66-41f8-a0ad-13c674886778-S0/frameworks/9c6bf850-2a66-41f8-a0ad-13c674886778-0000/executors:
> Directory not empty
> [19:17:16]W: [Step 10/10] E0630 19:17:16.342165 31238 rmdir.hpp:82] Failed
> to delete directory
> /mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/slaves/9c6bf850-2a66-41f8-a0ad-13c674886778-S0/frameworks/9c6bf850-2a66-41f8-a0ad-13c674886778-0000/mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/slaves/9c6bf850-2a66-41f8-a0ad-13c674886778-S0/frameworks/9c6bf850-2a66-41f8-a0ad-13c674886778-0000:
> Directory not empty
> [19:17:16]W: [Step 10/10] I0630 19:17:16.342176 31238 gc.cpp:146] Deleted
> '/mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/slaves/9c6bf850-2a66-41f8-a0ad-13c674886778-S0/frameworks/9c6bf850-2a66-41f8-a0ad-13c674886778-0000'
> [19:17:16]W: [Step 10/10] I0630 19:17:16.342181 31243
> status_update_manager.cpp:174] Pausing sending status updates
> [19:17:16]W: [Step 10/10] I0630 19:17:16.342203 31243
> status_update_manager.cpp:174] Pausing sending status updates
> [19:17:16]W: [Step 10/10] I0630 19:17:16.342205 31241 slave.cpp:967] New
> master detected at [email protected]:43264
> [19:17:16]W: [Step 10/10] I0630 19:17:16.342219 31241 slave.cpp:1029]
> Authenticating with master [email protected]:43264
> [19:17:16]W: [Step 10/10] I0630 19:17:16.342228 31241 slave.cpp:1040] Using
> default CRAM-MD5 authenticatee
> [19:17:16]W: [Step 10/10] I0630 19:17:16.342224 31238 gc.cpp:170] Pruning
> directories with remaining removal time 0ns
> [19:17:16]W: [Step 10/10] I0630 19:17:16.342262 31238 gc.cpp:170] Pruning
> directories with remaining removal time 0ns
> [19:17:16]W: [Step 10/10] I0630 19:17:16.342265 31241 slave.cpp:1002]
> Detecting new master
> [19:17:16]W: [Step 10/10] I0630 19:17:16.342277 31238 gc.cpp:133] Deleting
> /mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/slaves/9c6bf850-2a66-41f8-a0ad-13c674886778-S0/frameworks/9c6bf850-2a66-41f8-a0ad-13c674886778-0000/executors/test-task123/runs/0d146f10-0d93-4b01-96e2-095c7dcf2b4b
> [19:17:16]W: [Step 10/10] E0630 19:17:16.342310 31238 rmdir.hpp:82] Failed
> to delete directory
> /mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/slaves/9c6bf850-2a66-41f8-a0ad-13c674886778-S0/frameworks/9c6bf850-2a66-41f8-a0ad-13c674886778-0000/executors/test-task123/runs/0d146f10-0d93-4b01-96e2-095c7dcf2b4b/mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/slaves/9c6bf850-2a66-41f8-a0ad-13c674886778-S0/frameworks/9c6bf850-2a66-41f8-a0ad-13c674886778-0000/executors/test-task123/runs/0d146f10-0d93-4b01-96e2-095c7dcf2b4b/test1:
> Device or resource busy
> [19:17:16]W: [Step 10/10] I0630 19:17:16.342309 31239
> authenticatee.cpp:121] Creating new client SASL connection
> [19:17:16]W: [Step 10/10] E0630 19:17:16.342327 31238 rmdir.hpp:82] Failed
> to delete directory
> /mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/slaves/9c6bf850-2a66-41f8-a0ad-13c674886778-S0/frameworks/9c6bf850-2a66-41f8-a0ad-13c674886778-0000/executors/test-task123/runs/0d146f10-0d93-4b01-96e2-095c7dcf2b4b/mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/slaves/9c6bf850-2a66-41f8-a0ad-13c674886778-S0/frameworks/9c6bf850-2a66-41f8-a0ad-13c674886778-0000/executors/test-task123/runs/0d146f10-0d93-4b01-96e2-095c7dcf2b4b:
> Directory not empty
> [19:17:16]W: [Step 10/10] I0630 19:17:16.342339 31238 gc.cpp:146] Deleted
> '/mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/slaves/9c6bf850-2a66-41f8-a0ad-13c674886778-S0/frameworks/9c6bf850-2a66-41f8-a0ad-13c674886778-0000/executors/test-task123/runs/0d146f10-0d93-4b01-96e2-095c7dcf2b4b'
> [19:17:16]W: [Step 10/10] I0630 19:17:16.342386 31238 gc.cpp:133] Deleting
> /mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/slaves/9c6bf850-2a66-41f8-a0ad-13c674886778-S0/frameworks/9c6bf850-2a66-41f8-a0ad-13c674886778-0000/executors/test-task123
> [19:17:16]W: [Step 10/10] E0630 19:17:16.342448 31238 rmdir.hpp:82] Failed
> to delete directory
> /mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/slaves/9c6bf850-2a66-41f8-a0ad-13c674886778-S0/frameworks/9c6bf850-2a66-41f8-a0ad-13c674886778-0000/executors/test-task123/mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/slaves/9c6bf850-2a66-41f8-a0ad-13c674886778-S0/frameworks/9c6bf850-2a66-41f8-a0ad-13c674886778-0000/executors/test-task123/runs/0d146f10-0d93-4b01-96e2-095c7dcf2b4b/test1:
> Device or resource busy
> [19:17:16]W: [Step 10/10] E0630 19:17:16.342473 31238 rmdir.hpp:82] Failed
> to delete directory
> /mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/slaves/9c6bf850-2a66-41f8-a0ad-13c674886778-S0/frameworks/9c6bf850-2a66-41f8-a0ad-13c674886778-0000/executors/test-task123/mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/slaves/9c6bf850-2a66-41f8-a0ad-13c674886778-S0/frameworks/9c6bf850-2a66-41f8-a0ad-13c674886778-0000/executors/test-task123/runs/0d146f10-0d93-4b01-96e2-095c7dcf2b4b:
> Directory not empty
> [19:17:16]W: [Step 10/10] E0630 19:17:16.342485 31238 rmdir.hpp:82] Failed
> to delete directory
> /mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/slaves/9c6bf850-2a66-41f8-a0ad-13c674886778-S0/frameworks/9c6bf850-2a66-41f8-a0ad-13c674886778-0000/executors/test-task123/mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/slaves/9c6bf850-2a66-41f8-a0ad-13c674886778-S0/frameworks/9c6bf850-2a66-41f8-a0ad-13c674886778-0000/executors/test-task123/runs:
> Directory not empty
> [19:17:16]W: [Step 10/10] E0630 19:17:16.342495 31238 rmdir.hpp:82] Failed
> to delete directory
> /mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/slaves/9c6bf850-2a66-41f8-a0ad-13c674886778-S0/frameworks/9c6bf850-2a66-41f8-a0ad-13c674886778-0000/executors/test-task123/mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/slaves/9c6bf850-2a66-41f8-a0ad-13c674886778-S0/frameworks/9c6bf850-2a66-41f8-a0ad-13c674886778-0000/executors/test-task123:
> Directory not empty
> [19:17:16]W: [Step 10/10] I0630 19:17:16.342500 31238 gc.cpp:146] Deleted
> '/mnt/teamcity/temp/buildTmp/ROOT_GarbageCollectorUndeletableFilesTest_BusyMountPoint_WwHDWM/slaves/9c6bf850-2a66-41f8-a0ad-13c674886778-S0/frameworks/9c6bf850-2a66-41f8-a0ad-13c674886778-0000/executors/test-task123'
> [19:17:16]W: [Step 10/10] I0630 19:17:16.342622 31239 master.cpp:5966]
> Authenticating slave(63)@172.30.2.172:43264
> [19:17:16]W: [Step 10/10] I0630 19:17:16.342674 31241
> authenticator.cpp:414] Starting authentication session for
> crammd5_authenticatee(173)@172.30.2.172:43264
> [19:17:16]W: [Step 10/10] I0630 19:17:16.342747 31242 authenticator.cpp:98]
> Creating new server SASL connection
> [19:17:16]W: [Step 10/10] I0630 19:17:16.342924 31242
> authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
> [19:17:16]W: [Step 10/10] I0630 19:17:16.342944 31242
> authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
> [19:17:16]W: [Step 10/10] I0630 19:17:16.342999 31240
> authenticator.cpp:204] Received SASL authentication start
> [19:17:16]W: [Step 10/10] I0630 19:17:16.343040 31240
> authenticator.cpp:326] Authentication requires more steps
> [19:17:16]W: [Step 10/10] I0630 19:17:16.343071 31240
> authenticatee.cpp:259] Received SASL authentication step
> [19:17:16]W: [Step 10/10] I0630 19:17:16.343134 31239
> authenticator.cpp:232] Received SASL authentication step
> [19:17:16]W: [Step 10/10] I0630 19:17:16.343149 31239 auxprop.cpp:107]
> Request to lookup properties for user: 'test-principal' realm:
> 'ip-172-30-2-172.mesosphere.io' server FQDN: 'ip-172-30-2-172.mesosphere.io'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> [19:17:16]W: [Step 10/10] I0630 19:17:16.343155 31239 auxprop.cpp:179]
> Looking up auxiliary property '*userPassword'
> [19:17:16]W: [Step 10/10] I0630 19:17:16.343163 31239 auxprop.cpp:179]
> Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> [19:17:16]W: [Step 10/10] I0630 19:17:16.343168 31239 auxprop.cpp:107]
> Request to lookup properties for user: 'test-principal' realm:
> 'ip-172-30-2-172.mesosphere.io' server FQDN: 'ip-172-30-2-172.mesosphere.io'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> [19:17:16]W: [Step 10/10] I0630 19:17:16.343173 31239 auxprop.cpp:129]
> Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> [19:17:16]W: [Step 10/10] I0630 19:17:16.343176 31239 auxprop.cpp:129]
> Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since
> SASL_AUXPROP_AUTHZID == true
> [19:17:16]W: [Step 10/10] I0630 19:17:16.343185 31239
> authenticator.cpp:318] Authentication success
> [19:17:16]W: [Step 10/10] I0630 19:17:16.343230 31241
> authenticatee.cpp:299] Authentication success
> [19:17:16]W: [Step 10/10] I0630 19:17:16.343250 31239 master.cpp:5996]
> Successfully authenticated principal 'test-principal' at
> slave(63)@172.30.2.172:43264
> [19:17:16]W: [Step 10/10] I0630 19:17:16.343273 31240
> authenticator.cpp:432] Authentication session cleanup for
> crammd5_authenticatee(173)@172.30.2.172:43264
> [19:17:16]W: [Step 10/10] I0630 19:17:16.343441 31241 slave.cpp:1108]
> Successfully authenticated with master [email protected]:43264
> [19:17:16]W: [Step 10/10] I0630 19:17:16.343474 31241 slave.cpp:1468]
> Reregistering completed framework 9c6bf850-2a66-41f8-a0ad-13c674886778-0000
> [19:17:16]W: [Step 10/10] I0630 19:17:16.343566 31241 slave.cpp:1511] Will
> retry registration in 15.007489ms if necessary
> [19:17:16]W: [Step 10/10] I0630 19:17:16.343641 31239 master.cpp:4835]
> Re-registering agent 9c6bf850-2a66-41f8-a0ad-13c674886778-S0 at
> slave(63)@172.30.2.172:43264 (ip-172-30-2-172.mesosphere.io)
> [19:17:16]W: [Step 10/10] I0630 19:17:16.343690 31239 master.cpp:5027]
> Sending updated checkpointed resources to agent
> 9c6bf850-2a66-41f8-a0ad-13c674886778-S0 at slave(63)@172.30.2.172:43264
> (ip-172-30-2-172.mesosphere.io)
> [19:17:16]W: [Step 10/10] I0630 19:17:16.343722 31237 slave.cpp:1254]
> Re-registered with master [email protected]:43264
> [19:17:16]W: [Step 10/10] I0630 19:17:16.343761 31237 slave.cpp:1290]
> Forwarding total oversubscribed resources
> [19:17:16]W: [Step 10/10] I0630 19:17:16.343780 31244
> status_update_manager.cpp:181] Resuming sending status updates
> [19:17:16]W: [Step 10/10] I0630 19:17:16.343844 31238 master.cpp:5089]
> Received update of agent 9c6bf850-2a66-41f8-a0ad-13c674886778-S0 at
> slave(63)@172.30.2.172:43264 (ip-172-30-2-172.mesosphere.io) with total
> oversubscribed resources
> [19:17:16]W: [Step 10/10] I0630 19:17:16.343988 31238 hierarchical.cpp:539]
> Agent 9c6bf850-2a66-41f8-a0ad-13c674886778-S0 (ip-172-30-2-172.mesosphere.io)
> updated with oversubscribed resources (total: cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000])
> [19:17:16]W: [Step 10/10] I0630 19:17:16.344041 31238
> hierarchical.cpp:1512] No allocations performed
> [19:17:16]W: [Step 10/10] I0630 19:17:16.344053 31238
> hierarchical.cpp:1607] No inverse offers to send out!
> [19:17:16]W: [Step 10/10] I0630 19:17:16.344054 31237 slave.cpp:2582]
> Updated checkpointed resources from to
> [19:17:16]W: [Step 10/10] I0630 19:17:16.344068 31238
> hierarchical.cpp:1170] Performed allocation for agent
> 9c6bf850-2a66-41f8-a0ad-13c674886778-S0 in 46202ns
> [19:17:16]W: [Step 10/10] I0630 19:17:16.350636 31223 sched.cpp:1964] Asked
> to stop the driver
> [19:17:16]W: [Step 10/10] I0630 19:17:16.350702 31242 sched.cpp:1167]
> Stopping framework '9c6bf850-2a66-41f8-a0ad-13c674886778-0000'
> [19:17:16]W: [Step 10/10] I0630 19:17:16.350814 31241 master.cpp:6365]
> Processing TEARDOWN call for framework
> 9c6bf850-2a66-41f8-a0ad-13c674886778-0000 (default) at
> [email protected]:43264
> [19:17:16]W: [Step 10/10] I0630 19:17:16.350838 31241 master.cpp:6377]
> Removing framework 9c6bf850-2a66-41f8-a0ad-13c674886778-0000 (default) at
> [email protected]:43264
> [19:17:16]W: [Step 10/10] I0630 19:17:16.350945 31244 hierarchical.cpp:379]
> Deactivated framework 9c6bf850-2a66-41f8-a0ad-13c674886778-0000
> [19:17:16]W: [Step 10/10] I0630 19:17:16.350965 31240 slave.cpp:2274] Asked
> to shut down framework 9c6bf850-2a66-41f8-a0ad-13c674886778-0000 by
> [email protected]:43264
> [19:17:16]W: [Step 10/10] W0630 19:17:16.350983 31240 slave.cpp:2289]
> Cannot shut down unknown framework 9c6bf850-2a66-41f8-a0ad-13c674886778-0000
> [19:17:16]W: [Step 10/10] I0630 19:17:16.351065 31244 hierarchical.cpp:899]
> Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000],
> allocated: ) on agent 9c6bf850-2a66-41f8-a0ad-13c674886778-S0 from framework
> 9c6bf850-2a66-41f8-a0ad-13c674886778-0000
> [19:17:16]W: [Step 10/10] I0630 19:17:16.351189 31244 hierarchical.cpp:330]
> Removed framework 9c6bf850-2a66-41f8-a0ad-13c674886778-0000
> [19:17:16]W: [Step 10/10] I0630 19:17:16.351487 31223 slave.cpp:839] Agent
> terminating
> [19:17:16]W: [Step 10/10] I0630 19:17:16.351884 31238 master.cpp:1369]
> Agent 9c6bf850-2a66-41f8-a0ad-13c674886778-S0 at slave(63)@172.30.2.172:43264
> (ip-172-30-2-172.mesosphere.io) disconnected
> [19:17:16]W: [Step 10/10] I0630 19:17:16.351904 31238 master.cpp:2908]
> Disconnecting agent 9c6bf850-2a66-41f8-a0ad-13c674886778-S0 at
> slave(63)@172.30.2.172:43264 (ip-172-30-2-172.mesosphere.io)
> [19:17:16]W: [Step 10/10] I0630 19:17:16.351934 31238 master.cpp:2927]
> Deactivating agent 9c6bf850-2a66-41f8-a0ad-13c674886778-S0 at
> slave(63)@172.30.2.172:43264 (ip-172-30-2-172.mesosphere.io)
> [19:17:16]W: [Step 10/10] I0630 19:17:16.352011 31237 hierarchical.cpp:568]
> Agent 9c6bf850-2a66-41f8-a0ad-13c674886778-S0 deactivated
> [19:17:16]W: [Step 10/10] I0630 19:17:16.353452 31223 master.cpp:1216]
> Master terminating
> [19:17:16]W: [Step 10/10] I0630 19:17:16.353572 31241 hierarchical.cpp:513]
> Removed agent 9c6bf850-2a66-41f8-a0ad-13c674886778-S0
> [19:17:16] : [Step 10/10] [ FAILED ]
> ROOT_GarbageCollectorUndeletableFilesTest.BusyMountPoint (1271 ms)
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
