You are viewing a plain text version of this content. The canonical link for it is here.
Posted to builds@mesos.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2016/05/10 08:12:44 UTC
Build failed in Jenkins: mesos-reviewbot #12985
See <https://builds.apache.org/job/mesos-reviewbot/12985/>
------------------------------------------
[...truncated 114064 lines...]
I0510 06:08:28.799320 2474 registrar.cpp:463] Applied 1 operations in 19232ns; attempting to update the 'registry'
I0510 06:08:28.800166 2479 log.cpp:548] Attempting to append 170 bytes to the log
I0510 06:08:28.800336 2468 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
I0510 06:08:28.801158 2477 replica.cpp:537] Replica received write request for position 1 from (8604)@172.17.0.2:41165
I0510 06:08:28.801554 2477 leveldb.cpp:341] Persisting action (189 bytes) to leveldb took 350382ns
I0510 06:08:28.801587 2477 replica.cpp:712] Persisted action at 1
I0510 06:08:28.802284 2470 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
I0510 06:08:28.802701 2470 leveldb.cpp:341] Persisting action (191 bytes) to leveldb took 324315ns
I0510 06:08:28.802733 2470 replica.cpp:712] Persisted action at 1
I0510 06:08:28.802755 2470 replica.cpp:697] Replica learned APPEND action at position 1
I0510 06:08:28.803817 2471 registrar.cpp:508] Successfully updated the 'registry' in 4.427264ms
I0510 06:08:28.804023 2471 registrar.cpp:394] Successfully recovered registrar
I0510 06:08:28.804074 2478 log.cpp:567] Attempting to truncate the log to 1
I0510 06:08:28.804463 2467 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
I0510 06:08:28.804669 2472 master.cpp:1747] Recovered 0 agents from the Registry (131B) ; allowing 10mins for agents to re-register
I0510 06:08:28.804697 2465 hierarchical.cpp:169] Skipping recovery of hierarchical allocator: nothing to recover
I0510 06:08:28.805632 2466 replica.cpp:537] Replica received write request for position 2 from (8605)@172.17.0.2:41165
I0510 06:08:28.806058 2466 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 380821ns
I0510 06:08:28.806090 2466 replica.cpp:712] Persisted action at 2
I0510 06:08:28.806885 2465 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
I0510 06:08:28.807288 2465 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 366924ns
I0510 06:08:28.807368 2465 leveldb.cpp:399] Deleting ~1 keys from leveldb took 45059ns
I0510 06:08:28.807409 2465 replica.cpp:712] Persisted action at 2
I0510 06:08:28.807438 2465 replica.cpp:697] Replica learned TRUNCATE action at position 2
I0510 06:08:28.818120 2445 containerizer.cpp:178] Using isolation: posix/cpu,posix/mem,filesystem/posix,network/cni
W0510 06:08:28.818815 2445 backend.cpp:66] Failed to create 'bind' backend: BindBackend requires root privileges
I0510 06:08:28.820052 2445 cluster.cpp:398] Creating default 'local' authorizer
I0510 06:08:28.821311 2471 slave.cpp:204] Agent started on 230)@172.17.0.2:41165
I0510 06:08:28.821342 2471 slave.cpp:205] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="true" --authenticatee="crammd5" --authorizer="local" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/PersistentVolumeEndpointsTest_BadCredentials_q2rmRa/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" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/PersistentVolumeEndpointsTest_BadCredentials_q2rmRa/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/PersistentVolumeEndpointsTest_BadCredentials_q2rmRa/http_credentials" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-0.29.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="disk(role1):1024" --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/PersistentVolumeEndpointsTest_BadCredentials_q2rmRa"
I0510 06:08:28.821954 2471 credentials.hpp:86] Loading credential for authentication from '/tmp/PersistentVolumeEndpointsTest_BadCredentials_q2rmRa/credential'
I0510 06:08:28.822191 2471 slave.cpp:342] Agent using credential for: test-principal
I0510 06:08:28.822237 2471 credentials.hpp:37] Loading credentials for authentication from '/tmp/PersistentVolumeEndpointsTest_BadCredentials_q2rmRa/http_credentials'
I0510 06:08:28.822551 2471 slave.cpp:394] Using default 'basic' HTTP authenticator
I0510 06:08:28.823096 2471 resources.cpp:572] Parsing resources as JSON failed: disk(role1):1024
Trying semicolon-delimited string format instead
I0510 06:08:28.823446 2471 slave.cpp:593] Agent resources: disk(role1):1024; cpus(*):16; mem(*):47270; ports(*):[31000-32000]
I0510 06:08:28.823503 2471 slave.cpp:601] Agent attributes: [ ]
I0510 06:08:28.823513 2471 slave.cpp:606] Agent hostname: 5c2729022330
I0510 06:08:28.824690 2467 state.cpp:57] Recovering state from '/tmp/PersistentVolumeEndpointsTest_BadCredentials_q2rmRa/meta'
I0510 06:08:28.824944 2474 status_update_manager.cpp:200] Recovering status update manager
I0510 06:08:28.825142 2473 containerizer.cpp:444] Recovering containerizer
I0510 06:08:28.826273 2471 provisioner.cpp:245] Provisioner recovery complete
I0510 06:08:28.826655 2464 slave.cpp:4807] Finished recovery
I0510 06:08:28.827049 2464 slave.cpp:4979] Querying resource estimator for oversubscribable resources
I0510 06:08:28.827294 2466 slave.cpp:953] New master detected at master@172.17.0.2:41165
I0510 06:08:28.827298 2474 status_update_manager.cpp:174] Pausing sending status updates
I0510 06:08:28.827322 2466 slave.cpp:965] Delaying registration for 5.736583ms
I0510 06:08:28.827428 2466 slave.cpp:973] Detecting new master
I0510 06:08:28.827585 2466 slave.cpp:4993] Received oversubscribable resources from the resource estimator
I0510 06:08:28.833722 2468 slave.cpp:1022] Authenticating with master master@172.17.0.2:41165
I0510 06:08:28.833748 2468 slave.cpp:1027] Using default CRAM-MD5 authenticatee
I0510 06:08:28.834066 2465 authenticatee.cpp:121] Creating new client SASL connection
I0510 06:08:28.834314 2467 master.cpp:5827] Authenticating slave(230)@172.17.0.2:41165
I0510 06:08:28.834403 2476 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(497)@172.17.0.2:41165
I0510 06:08:28.834619 2471 authenticator.cpp:98] Creating new server SASL connection
I0510 06:08:28.834799 2472 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
I0510 06:08:28.834831 2472 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
I0510 06:08:28.834939 2472 authenticator.cpp:203] Received SASL authentication start
I0510 06:08:28.834997 2472 authenticator.cpp:325] Authentication requires more steps
I0510 06:08:28.835106 2479 authenticatee.cpp:258] Received SASL authentication step
I0510 06:08:28.835213 2479 authenticator.cpp:231] Received SASL authentication step
I0510 06:08:28.835242 2479 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: '5c2729022330' server FQDN: '5c2729022330' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0510 06:08:28.835258 2479 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
I0510 06:08:28.835289 2479 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0510 06:08:28.835307 2479 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: '5c2729022330' server FQDN: '5c2729022330' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0510 06:08:28.835315 2479 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0510 06:08:28.835321 2479 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0510 06:08:28.835335 2479 authenticator.cpp:317] Authentication success
I0510 06:08:28.835470 2472 authenticatee.cpp:298] Authentication success
I0510 06:08:28.835494 2467 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(497)@172.17.0.2:41165
I0510 06:08:28.835544 2473 master.cpp:5857] Successfully authenticated principal 'test-principal' at slave(230)@172.17.0.2:41165
I0510 06:08:28.835877 2474 slave.cpp:1092] Successfully authenticated with master master@172.17.0.2:41165
I0510 06:08:28.836012 2474 slave.cpp:1488] Will retry registration in 2.062913ms if necessary
I0510 06:08:28.836160 2475 master.cpp:4538] Registering agent at slave(230)@172.17.0.2:41165 (5c2729022330) with id 99ebb3fc-2b85-4aa1-98f1-58ff7bf7c9bd-S0
I0510 06:08:28.836549 2465 registrar.cpp:463] Applied 1 operations in 45817ns; attempting to update the 'registry'
I0510 06:08:28.837306 2478 log.cpp:548] Attempting to append 343 bytes to the log
I0510 06:08:28.837496 2471 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3
I0510 06:08:28.838389 2464 replica.cpp:537] Replica received write request for position 3 from (8621)@172.17.0.2:41165
I0510 06:08:28.838619 2464 leveldb.cpp:341] Persisting action (362 bytes) to leveldb took 185441ns
I0510 06:08:28.838660 2464 replica.cpp:712] Persisted action at 3
I0510 06:08:28.839002 2465 hierarchical.cpp:1488] No resources available to allocate!
I0510 06:08:28.839084 2465 hierarchical.cpp:1139] Performed allocation for 0 agents in 129197ns
I0510 06:08:28.839470 2475 replica.cpp:691] Replica received learned notice for position 3 from @0.0.0.0:0
I0510 06:08:28.839561 2476 slave.cpp:1488] Will retry registration in 37.528283ms if necessary
I0510 06:08:28.839717 2472 master.cpp:4526] Ignoring register agent message from slave(230)@172.17.0.2:41165 (5c2729022330) as admission is already in progress
I0510 06:08:28.839943 2475 leveldb.cpp:341] Persisting action (364 bytes) to leveldb took 430123ns
I0510 06:08:28.839975 2475 replica.cpp:712] Persisted action at 3
I0510 06:08:28.839998 2475 replica.cpp:697] Replica learned APPEND action at position 3
I0510 06:08:28.841567 2469 registrar.cpp:508] Successfully updated the 'registry' in 4.948224ms
I0510 06:08:28.841820 2465 log.cpp:567] Attempting to truncate the log to 3
I0510 06:08:28.841956 2476 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4
I0510 06:08:28.842643 2476 slave.cpp:3707] Received ping from slave-observer(217)@172.17.0.2:41165
I0510 06:08:28.842888 2470 master.cpp:4606] Registered agent 99ebb3fc-2b85-4aa1-98f1-58ff7bf7c9bd-S0 at slave(230)@172.17.0.2:41165 (5c2729022330) with disk(role1):1024; cpus(*):16; mem(*):47270; ports(*):[31000-32000]
I0510 06:08:28.842978 2464 slave.cpp:1136] Registered with master master@172.17.0.2:41165; given agent ID 99ebb3fc-2b85-4aa1-98f1-58ff7bf7c9bd-S0
I0510 06:08:28.843015 2464 fetcher.cpp:81] Clearing fetcher cache
I0510 06:08:28.843155 2470 status_update_manager.cpp:181] Resuming sending status updates
I0510 06:08:28.843215 2469 hierarchical.cpp:473] Added agent 99ebb3fc-2b85-4aa1-98f1-58ff7bf7c9bd-S0 (5c2729022330) with disk(role1):1024; cpus(*):16; mem(*):47270; ports(*):[31000-32000] (allocated: )
I0510 06:08:28.843353 2466 replica.cpp:537] Replica received write request for position 4 from (8622)@172.17.0.2:41165
I0510 06:08:28.843364 2464 slave.cpp:1159] Checkpointing SlaveInfo to '/tmp/PersistentVolumeEndpointsTest_BadCredentials_q2rmRa/meta/slaves/99ebb3fc-2b85-4aa1-98f1-58ff7bf7c9bd-S0/slave.info'
I0510 06:08:28.843472 2469 hierarchical.cpp:1488] No resources available to allocate!
I0510 06:08:28.843540 2469 hierarchical.cpp:1162] Performed allocation for agent 99ebb3fc-2b85-4aa1-98f1-58ff7bf7c9bd-S0 in 184400ns
I0510 06:08:28.843838 2464 slave.cpp:1196] Forwarding total oversubscribed resources
I0510 06:08:28.843983 2464 master.cpp:4950] Received update of agent 99ebb3fc-2b85-4aa1-98f1-58ff7bf7c9bd-S0 at slave(230)@172.17.0.2:41165 (5c2729022330) with total oversubscribed resources
I0510 06:08:28.844039 2466 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 652968ns
I0510 06:08:28.844063 2466 replica.cpp:712] Persisted action at 4
I0510 06:08:28.844552 2465 hierarchical.cpp:531] Agent 99ebb3fc-2b85-4aa1-98f1-58ff7bf7c9bd-S0 (5c2729022330) updated with oversubscribed resources (total: disk(role1):1024; cpus(*):16; mem(*):47270; ports(*):[31000-32000], allocated: )
I0510 06:08:28.844836 2468 replica.cpp:691] Replica received learned notice for position 4 from @0.0.0.0:0
I0510 06:08:28.844964 2473 process.cpp:3206] Handling HTTP event for process 'master' with path: '/master/create-volumes'
I0510 06:08:28.845031 2465 hierarchical.cpp:1488] No resources available to allocate!
I0510 06:08:28.845252 2465 hierarchical.cpp:1162] Performed allocation for agent 99ebb3fc-2b85-4aa1-98f1-58ff7bf7c9bd-S0 in 402280ns
I0510 06:08:28.845337 2468 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 404198ns
I0510 06:08:28.845404 2468 leveldb.cpp:399] Deleting ~2 keys from leveldb took 42106ns
I0510 06:08:28.845430 2468 replica.cpp:712] Persisted action at 4
I0510 06:08:28.845456 2468 replica.cpp:697] Replica learned TRUNCATE action at position 4
I0510 06:08:28.849308 2473 process.cpp:3206] Handling HTTP event for process 'master' with path: '/master/destroy-volumes'
I0510 06:08:28.852380 2467 slave.cpp:825] Agent terminating
I0510 06:08:28.852733 2473 master.cpp:1343] Agent 99ebb3fc-2b85-4aa1-98f1-58ff7bf7c9bd-S0 at slave(230)@172.17.0.2:41165 (5c2729022330) disconnected
I0510 06:08:28.852771 2473 master.cpp:2849] Disconnecting agent 99ebb3fc-2b85-4aa1-98f1-58ff7bf7c9bd-S0 at slave(230)@172.17.0.2:41165 (5c2729022330)
I0510 06:08:28.852869 2473 master.cpp:2868] Deactivating agent 99ebb3fc-2b85-4aa1-98f1-58ff7bf7c9bd-S0 at slave(230)@172.17.0.2:41165 (5c2729022330)
I0510 06:08:28.853209 2473 hierarchical.cpp:560] Agent 99ebb3fc-2b85-4aa1-98f1-58ff7bf7c9bd-S0 deactivated
I0510 06:08:28.857848 2478 master.cpp:1190] Master terminating
I0510 06:08:28.858556 2469 hierarchical.cpp:505] Removed agent 99ebb3fc-2b85-4aa1-98f1-58ff7bf7c9bd-S0
[ OK ] PersistentVolumeEndpointsTest.BadCredentials (89 ms)
[ RUN ] PersistentVolumeEndpointsTest.GoodCreateAndDestroyACL
I0510 06:08:28.868095 2445 cluster.cpp:149] Creating default 'local' authorizer
I0510 06:08:28.870792 2445 leveldb.cpp:174] Opened db in 2.20268ms
I0510 06:08:28.871738 2445 leveldb.cpp:181] Compacted db in 913212ns
I0510 06:08:28.871778 2445 leveldb.cpp:196] Created db iterator in 17864ns
I0510 06:08:28.871789 2445 leveldb.cpp:202] Seeked to beginning of db in 1825ns
I0510 06:08:28.871796 2445 leveldb.cpp:271] Iterated through 0 keys in the db in 182ns
I0510 06:08:28.871825 2445 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0510 06:08:28.872344 2479 recover.cpp:447] Starting replica recovery
I0510 06:08:28.872741 2479 recover.cpp:473] Replica is in EMPTY status
I0510 06:08:28.874014 2471 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (8629)@172.17.0.2:41165
I0510 06:08:28.874485 2472 recover.cpp:193] Received a recover response from a replica in EMPTY status
I0510 06:08:28.875217 2477 recover.cpp:564] Updating replica status to STARTING
I0510 06:08:28.875972 2470 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 512821ns
I0510 06:08:28.876009 2470 replica.cpp:320] Persisted replica status to STARTING
I0510 06:08:28.876262 2479 recover.cpp:473] Replica is in STARTING status
I0510 06:08:28.877140 2468 master.cpp:383] Master eeaf0ac8-c40e-49b7-8685-8ba57ec93784 (5c2729022330) started on 172.17.0.2:41165
I0510 06:08:28.877521 2465 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (8630)@172.17.0.2:41165
I0510 06:08:28.877168 2468 master.cpp:385] Flags at startup: --acls="create_volumes {
principals {
values: "test-principal"
}
roles {
type: ANY
}
}
destroy_volumes {
principals {
values: "test-principal"
}
creator_principals {
values: "test-principal"
}
}
" --allocation_interval="50ms" --allocator="HierarchicalDRF" --authenticate="true" --authenticate_http="true" --authenticate_http_frameworks="true" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/GrbDVB/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_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --max_slave_ping_timeouts="5" --quiet="false" --recovery_slave_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="100secs" --registry_strict="true" --roles="role1" --root_submissions="true" --slave_ping_timeout="15secs" --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" --webui_dir="/mesos/mesos-0.29.0/_inst/share/mesos/webui" --work_dir="/tmp/GrbDVB/master" --zk_session_timeout="10secs"
I0510 06:08:28.877805 2468 master.cpp:434] Master only allowing authenticated frameworks to register
I0510 06:08:28.877827 2468 master.cpp:440] Master only allowing authenticated agents to register
I0510 06:08:28.877843 2468 master.cpp:446] Master only allowing authenticated HTTP frameworks to register
I0510 06:08:28.877858 2468 credentials.hpp:37] Loading credentials for authentication from '/tmp/GrbDVB/credentials'
I0510 06:08:28.878214 2468 master.cpp:490] Using default 'crammd5' authenticator
I0510 06:08:28.878270 2478 recover.cpp:193] Received a recover response from a replica in STARTING status
I0510 06:08:28.878376 2468 master.cpp:561] Using default 'basic' HTTP authenticator
I0510 06:08:28.878720 2468 master.cpp:641] Using default 'basic' HTTP framework authenticator
I0510 06:08:28.879072 2474 recover.cpp:564] Updating replica status to VOTING
I0510 06:08:28.879124 2468 master.cpp:688] Authorization enabled
W0510 06:08:28.879151 2468 master.cpp:751] The '--roles' flag is deprecated. This flag will be removed in the future. See the Mesos 0.27 upgrade notes for more information
I0510 06:08:28.879508 2465 whitelist_watcher.cpp:77] No whitelist given
I0510 06:08:28.879586 2475 hierarchical.cpp:142] Initialized hierarchical allocator process
I0510 06:08:28.879952 2466 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 367647ns
I0510 06:08:28.879981 2466 replica.cpp:320] Persisted replica status to VOTING
I0510 06:08:28.880123 2466 recover.cpp:578] Successfully joined the Paxos group
I0510 06:08:28.880424 2466 recover.cpp:462] Recover process terminated
I0510 06:08:28.882156 2469 master.cpp:1939] The newly elected leader is master@172.17.0.2:41165 with id eeaf0ac8-c40e-49b7-8685-8ba57ec93784
I0510 06:08:28.882208 2469 master.cpp:1952] Elected as the leading master!
I0510 06:08:28.882241 2469 master.cpp:1639] Recovering from registrar
I0510 06:08:28.882423 2472 registrar.cpp:331] Recovering registrar
I0510 06:08:28.882998 2470 log.cpp:524] Attempting to start the writer
I0510 06:08:28.884101 2473 replica.cpp:493] Replica received implicit promise request from (8633)@172.17.0.2:41165 with proposal 1
I0510 06:08:28.884397 2473 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 265287ns
I0510 06:08:28.884419 2473 replica.cpp:342] Persisted promised to 1
I0510 06:08:28.884984 2471 coordinator.cpp:238] Coordinator attempting to fill missing positions
I0510 06:08:28.886256 2472 replica.cpp:388] Replica received explicit promise request from (8634)@172.17.0.2:41165 for position 0 with proposal 2
I0510 06:08:28.886579 2472 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 281990ns
I0510 06:08:28.886605 2472 replica.cpp:712] Persisted action at 0
I0510 06:08:28.887656 2479 replica.cpp:537] Replica received write request for position 0 from (8635)@172.17.0.2:41165
I0510 06:08:28.887713 2479 leveldb.cpp:436] Reading position from leveldb took 28959ns
I0510 06:08:28.888073 2479 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 311480ns
I0510 06:08:28.888095 2479 replica.cpp:712] Persisted action at 0
I0510 06:08:28.888703 2476 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
I0510 06:08:28.889160 2476 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 351661ns
I0510 06:08:28.889185 2476 replica.cpp:712] Persisted action at 0
I0510 06:08:28.889209 2476 replica.cpp:697] Replica learned NOP action at position 0
I0510 06:08:28.889876 2476 log.cpp:540] Writer started with ending position 0
I0510 06:08:28.891023 2468 leveldb.cpp:436] Reading position from leveldb took 27725ns
I0510 06:08:28.892030 2468 registrar.cpp:364] Successfully fetched the registry (0B) in 0ns
I0510 06:08:28.892114 2468 registrar.cpp:463] Applied 1 operations in 18092ns; attempting to update the 'registry'
I0510 06:08:28.892765 2477 log.cpp:548] Attempting to append 170 bytes to the log
I0510 06:08:28.892982 2464 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
I0510 06:08:28.893666 2473 replica.cpp:537] Replica received write request for position 1 from (8636)@172.17.0.2:41165
I0510 06:08:28.894105 2473 leveldb.cpp:341] Persisting action (189 bytes) to leveldb took 408448ns
I0510 06:08:28.894129 2473 replica.cpp:712] Persisted action at 1
I0510 06:08:28.894583 2471 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
I0510 06:08:28.894958 2471 leveldb.cpp:341] Persisting action (191 bytes) to leveldb took 347551ns
I0510 06:08:28.894984 2471 replica.cpp:712] Persisted action at 1
I0510 06:08:28.895007 2471 replica.cpp:697] Replica learned APPEND action at position 1
I0510 06:08:28.895970 2470 registrar.cpp:508] Successfully updated the 'registry' in 0ns
I0510 06:08:28.896148 2470 registrar.cpp:394] Successfully recovered registrar
I0510 06:08:28.896365 2469 log.cpp:567] Attempting to truncate the log to 1
I0510 06:08:28.896513 2466 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
I0510 06:08:28.896636 2479 master.cpp:1747] Recovered 0 agents from the Registry (131B) ; allowing 10mins for agents to re-register
I0510 06:08:28.896773 2475 hierarchical.cpp:169] Skipping recovery of hierarchical allocator: nothing to recover
I0510 06:08:28.897542 2474 replica.cpp:537] Replica received write request for position 2 from (8637)@172.17.0.2:41165
I0510 06:08:28.897939 2474 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 348307ns
I0510 06:08:28.897971 2474 replica.cpp:712] Persisted action at 2
I0510 06:08:28.898648 2464 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
I0510 06:08:28.899179 2464 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 403570ns
I0510 06:08:28.899250 2464 leveldb.cpp:399] Deleting ~1 keys from leveldb took 39154ns
I0510 06:08:28.899276 2464 replica.cpp:712] Persisted action at 2
I0510 06:08:28.899301 2464 replica.cpp:697] Replica learned TRUNCATE action at position 2
I0510 06:08:28.921373 2445 containerizer.cpp:178] Using isolation: posix/cpu,posix/mem,filesystem/posix,network/cni
W0510 06:08:28.922338 2445 backend.cpp:66] Failed to create 'bind' backend: BindBackend requires root privileges
I0510 06:08:28.923810 2445 cluster.cpp:398] Creating default 'local' authorizer
I0510 06:08:28.925410 2477 slave.cpp:204] Agent started on 231)@172.17.0.2:41165
I0510 06:08:28.925433 2477 slave.cpp:205] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="true" --authenticatee="crammd5" --authorizer="local" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/PersistentVolumeEndpointsTest_GoodCreateAndDestroyACL_ZNAFtq/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" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/PersistentVolumeEndpointsTest_GoodCreateAndDestroyACL_ZNAFtq/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/PersistentVolumeEndpointsTest_GoodCreateAndDestroyACL_ZNAFtq/http_credentials" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-0.29.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:1;mem:512;disk(role1):1024" --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/PersistentVolumeEndpointsTest_GoodCreateAndDestroyACL_ZNAFtq"
I0510 06:08:28.925916 2477 credentials.hpp:86] Loading credential for authentication from '/tmp/PersistentVolumeEndpointsTest_GoodCreateAndDestroyACL_ZNAFtq/credential'
I0510 06:08:28.926129 2477 slave.cpp:342] Agent using credential for: test-principal
I0510 06:08:28.926170 2477 credentials.hpp:37] Loading credentials for authentication from '/tmp/PersistentVolumeEndpointsTest_GoodCreateAndDestroyACL_ZNAFtq/http_credentials'
I0510 06:08:28.926476 2477 slave.cpp:394] Using default 'basic' HTTP authenticator
I0510 06:08:28.927088 2477 resources.cpp:572] Parsing resources as JSON failed: cpus:1;mem:512;disk(role1):1024
Trying semicolon-delimited string format instead
I0510 06:08:28.927530 2477 slave.cpp:593] Agent resources: cpus(*):1; mem(*):512; disk(role1):1024; ports(*):[31000-32000]
I0510 06:08:28.927606 2477 slave.cpp:601] Agent attributes: [ ]
I0510 06:08:28.927626 2477 slave.cpp:606] Agent hostname: 5c2729022330
I0510 06:08:28.929224 2478 state.cpp:57] Recovering state from '/tmp/PersistentVolumeEndpointsTest_GoodCreateAndDestroyACL_ZNAFtq/meta'
I0510 06:08:28.929500 2471 status_update_manager.cpp:200] Recovering status update manager
I0510 06:08:28.929766 2464 containerizer.cpp:444] Recovering containerizer
I0510 06:08:28.931167 2470 provisioner.cpp:245] Provisioner recovery complete
I0510 06:08:28.931479 2466 slave.cpp:4807] Finished recovery
I0510 06:08:28.932111 2466 slave.cpp:4979] Querying resource estimator for oversubscribable resources
I0510 06:08:28.932399 2467 status_update_manager.cpp:174] Pausing sending status updates
I0510 06:08:28.932396 2466 slave.cpp:953] New master detected at master@172.17.0.2:41165
I0510 06:08:28.932431 2466 slave.cpp:965] Delaying registration for 2.526178ms
I0510 06:08:28.932479 2466 slave.cpp:973] Detecting new master
I0510 06:08:28.932608 2466 slave.cpp:4993] Received oversubscribable resources from the resource estimator
Build timed out (after 180 minutes). Marking the build as failed.
Build was aborted
Jenkins build is back to normal : mesos-reviewbot #12989
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/mesos-reviewbot/12989/changes>
Build failed in Jenkins: mesos-reviewbot #12988
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/mesos-reviewbot/12988/changes>
Changes:
[alexr] Ensured subsequent kills are ignored after the task is reaped.
[alexr] Added KillPolicy to scheduler and executor Kill protobuf messages.
[alexr] Propagated KillPolicy in kill task from scheduler to executor.
[alexr] Updated HTTP command executor to support kill policy in Kill event.
------------------------------------------
[...truncated 115569 lines...]
I0510 16:04:36.985224 2470 replica.cpp:537] Replica received write request for position 1 from (8633)@172.17.0.2:35810
I0510 16:04:37.020961 2470 leveldb.cpp:341] Persisting action (189 bytes) to leveldb took 35.67265ms
I0510 16:04:37.021062 2470 replica.cpp:712] Persisted action at 1
I0510 16:04:37.022627 2460 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
I0510 16:04:37.031172 2462 hierarchical.cpp:1488] No resources available to allocate!
I0510 16:04:37.031287 2462 hierarchical.cpp:1139] Performed allocation for 0 agents in 191107ns
I0510 16:04:37.062695 2460 leveldb.cpp:341] Persisting action (191 bytes) to leveldb took 39.995795ms
I0510 16:04:37.062793 2460 replica.cpp:712] Persisted action at 1
I0510 16:04:37.062826 2460 replica.cpp:697] Replica learned APPEND action at position 1
I0510 16:04:37.064206 2470 registrar.cpp:508] Successfully updated the 'registry' in 80.824064ms
I0510 16:04:37.064350 2470 registrar.cpp:394] Successfully recovered registrar
I0510 16:04:37.064450 2460 log.cpp:567] Attempting to truncate the log to 1
I0510 16:04:37.064645 2470 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
I0510 16:04:37.064921 2460 master.cpp:1747] Recovered 0 agents from the Registry (131B) ; allowing 10mins for agents to re-register
I0510 16:04:37.064961 2471 hierarchical.cpp:169] Skipping recovery of hierarchical allocator: nothing to recover
I0510 16:04:37.065843 2461 replica.cpp:537] Replica received write request for position 2 from (8634)@172.17.0.2:35810
I0510 16:04:37.104619 2461 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 38.70964ms
I0510 16:04:37.104708 2461 replica.cpp:712] Persisted action at 2
I0510 16:04:37.105574 2469 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
I0510 16:04:37.143060 2469 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 37.432214ms
I0510 16:04:37.143229 2469 leveldb.cpp:399] Deleting ~1 keys from leveldb took 84990ns
I0510 16:04:37.143291 2469 replica.cpp:712] Persisted action at 2
I0510 16:04:37.143337 2469 replica.cpp:697] Replica learned TRUNCATE action at position 2
I0510 16:04:37.147747 2466 hierarchical.cpp:1488] No resources available to allocate!
I0510 16:04:37.147862 2466 hierarchical.cpp:1139] Performed allocation for 0 agents in 196545ns
I0510 16:04:37.149996 2439 containerizer.cpp:178] Using isolation: posix/cpu,posix/mem,filesystem/posix,network/cni
W0510 16:04:37.150810 2439 backend.cpp:66] Failed to create 'bind' backend: BindBackend requires root privileges
I0510 16:04:37.152228 2439 cluster.cpp:398] Creating default 'local' authorizer
I0510 16:04:37.154201 2470 slave.cpp:204] Agent started on 230)@172.17.0.2:35810
I0510 16:04:37.154224 2470 slave.cpp:205] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="true" --authenticatee="crammd5" --authorizer="local" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/PersistentVolumeEndpointsTest_BadCredentials_UtXk00/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" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/PersistentVolumeEndpointsTest_BadCredentials_UtXk00/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/PersistentVolumeEndpointsTest_BadCredentials_UtXk00/http_credentials" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-0.29.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="disk(role1):1024" --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/PersistentVolumeEndpointsTest_BadCredentials_UtXk00"
I0510 16:04:37.154665 2470 credentials.hpp:86] Loading credential for authentication from '/tmp/PersistentVolumeEndpointsTest_BadCredentials_UtXk00/credential'
I0510 16:04:37.154914 2470 slave.cpp:342] Agent using credential for: test-principal
I0510 16:04:37.154945 2470 credentials.hpp:37] Loading credentials for authentication from '/tmp/PersistentVolumeEndpointsTest_BadCredentials_UtXk00/http_credentials'
I0510 16:04:37.155191 2470 slave.cpp:394] Using default 'basic' HTTP authenticator
I0510 16:04:37.155508 2470 resources.cpp:572] Parsing resources as JSON failed: disk(role1):1024
Trying semicolon-delimited string format instead
I0510 16:04:37.155936 2470 slave.cpp:593] Agent resources: disk(role1):1024; cpus(*):16; mem(*):47270; ports(*):[31000-32000]
I0510 16:04:37.155995 2470 slave.cpp:601] Agent attributes: [ ]
I0510 16:04:37.156007 2470 slave.cpp:606] Agent hostname: e6116108716a
I0510 16:04:37.157539 2466 state.cpp:57] Recovering state from '/tmp/PersistentVolumeEndpointsTest_BadCredentials_UtXk00/meta'
I0510 16:04:37.157939 2471 status_update_manager.cpp:200] Recovering status update manager
I0510 16:04:37.158144 2471 containerizer.cpp:444] Recovering containerizer
I0510 16:04:37.159590 2468 provisioner.cpp:245] Provisioner recovery complete
I0510 16:04:37.159886 2469 slave.cpp:4812] Finished recovery
I0510 16:04:37.160434 2469 slave.cpp:4984] Querying resource estimator for oversubscribable resources
I0510 16:04:37.160866 2459 status_update_manager.cpp:174] Pausing sending status updates
I0510 16:04:37.160882 2464 slave.cpp:951] New master detected at master@172.17.0.2:35810
I0510 16:04:37.160910 2464 slave.cpp:963] Delaying registration for 4.183044ms
I0510 16:04:37.161041 2464 slave.cpp:971] Detecting new master
I0510 16:04:37.161172 2464 slave.cpp:4998] Received oversubscribable resources from the resource estimator
I0510 16:04:37.165508 2472 slave.cpp:1020] Authenticating with master master@172.17.0.2:35810
I0510 16:04:37.165540 2472 slave.cpp:1025] Using default CRAM-MD5 authenticatee
I0510 16:04:37.165828 2467 authenticatee.cpp:121] Creating new client SASL connection
I0510 16:04:37.166179 2471 master.cpp:5833] Authenticating slave(230)@172.17.0.2:35810
I0510 16:04:37.166338 2462 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(496)@172.17.0.2:35810
I0510 16:04:37.166577 2464 authenticator.cpp:98] Creating new server SASL connection
I0510 16:04:37.166839 2459 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
I0510 16:04:37.166877 2459 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
I0510 16:04:37.167014 2469 authenticator.cpp:203] Received SASL authentication start
I0510 16:04:37.167078 2469 authenticator.cpp:325] Authentication requires more steps
I0510 16:04:37.167189 2458 authenticatee.cpp:258] Received SASL authentication step
I0510 16:04:37.167487 2471 authenticator.cpp:231] Received SASL authentication step
I0510 16:04:37.167522 2471 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'e6116108716a' server FQDN: 'e6116108716a' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0510 16:04:37.167532 2471 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
I0510 16:04:37.167572 2471 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0510 16:04:37.167588 2471 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'e6116108716a' server FQDN: 'e6116108716a' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0510 16:04:37.167596 2471 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0510 16:04:37.167603 2471 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0510 16:04:37.167616 2471 authenticator.cpp:317] Authentication success
I0510 16:04:37.167692 2461 authenticatee.cpp:298] Authentication success
I0510 16:04:37.167773 2465 master.cpp:5863] Successfully authenticated principal 'test-principal' at slave(230)@172.17.0.2:35810
I0510 16:04:37.167834 2466 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(496)@172.17.0.2:35810
I0510 16:04:37.168089 2471 slave.cpp:1090] Successfully authenticated with master master@172.17.0.2:35810
I0510 16:04:37.168256 2471 slave.cpp:1486] Will retry registration in 7.66941ms if necessary
I0510 16:04:37.168431 2461 master.cpp:4544] Registering agent at slave(230)@172.17.0.2:35810 (e6116108716a) with id 0db53e5d-8988-4a39-95ac-6ed9d3071b48-S0
I0510 16:04:37.168969 2467 registrar.cpp:463] Applied 1 operations in 93475ns; attempting to update the 'registry'
I0510 16:04:37.169811 2462 log.cpp:548] Attempting to append 343 bytes to the log
I0510 16:04:37.169944 2463 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3
I0510 16:04:37.170811 2471 replica.cpp:537] Replica received write request for position 3 from (8650)@172.17.0.2:35810
I0510 16:04:37.176978 2465 slave.cpp:1486] Will retry registration in 943175ns if necessary
I0510 16:04:37.177211 2473 master.cpp:4532] Ignoring register agent message from slave(230)@172.17.0.2:35810 (e6116108716a) as admission is already in progress
I0510 16:04:37.178488 2470 slave.cpp:1486] Will retry registration in 79.081088ms if necessary
I0510 16:04:37.178624 2464 master.cpp:4532] Ignoring register agent message from slave(230)@172.17.0.2:35810 (e6116108716a) as admission is already in progress
I0510 16:04:37.198976 2466 hierarchical.cpp:1488] No resources available to allocate!
I0510 16:04:37.199105 2466 hierarchical.cpp:1139] Performed allocation for 0 agents in 230742ns
I0510 16:04:37.210088 2471 leveldb.cpp:341] Persisting action (362 bytes) to leveldb took 39.219589ms
I0510 16:04:37.210170 2471 replica.cpp:712] Persisted action at 3
I0510 16:04:37.211155 2471 replica.cpp:691] Replica received learned notice for position 3 from @0.0.0.0:0
I0510 16:04:37.235370 2471 leveldb.cpp:341] Persisting action (364 bytes) to leveldb took 24.159427ms
I0510 16:04:37.235468 2471 replica.cpp:712] Persisted action at 3
I0510 16:04:37.235507 2471 replica.cpp:697] Replica learned APPEND action at position 3
I0510 16:04:37.237362 2471 registrar.cpp:508] Successfully updated the 'registry' in 68.321024ms
I0510 16:04:37.237593 2472 log.cpp:567] Attempting to truncate the log to 3
I0510 16:04:37.237776 2468 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4
I0510 16:04:37.238404 2469 slave.cpp:3712] Received ping from slave-observer(214)@172.17.0.2:35810
I0510 16:04:37.238483 2470 master.cpp:4612] Registered agent 0db53e5d-8988-4a39-95ac-6ed9d3071b48-S0 at slave(230)@172.17.0.2:35810 (e6116108716a) with disk(role1):1024; cpus(*):16; mem(*):47270; ports(*):[31000-32000]
I0510 16:04:37.238548 2469 slave.cpp:1134] Registered with master master@172.17.0.2:35810; given agent ID 0db53e5d-8988-4a39-95ac-6ed9d3071b48-S0
I0510 16:04:37.238571 2469 fetcher.cpp:81] Clearing fetcher cache
I0510 16:04:37.238800 2468 hierarchical.cpp:473] Added agent 0db53e5d-8988-4a39-95ac-6ed9d3071b48-S0 (e6116108716a) with disk(role1):1024; cpus(*):16; mem(*):47270; ports(*):[31000-32000] (allocated: )
I0510 16:04:37.238950 2470 status_update_manager.cpp:181] Resuming sending status updates
I0510 16:04:37.238970 2468 hierarchical.cpp:1488] No resources available to allocate!
I0510 16:04:37.238997 2469 slave.cpp:1157] Checkpointing SlaveInfo to '/tmp/PersistentVolumeEndpointsTest_BadCredentials_UtXk00/meta/slaves/0db53e5d-8988-4a39-95ac-6ed9d3071b48-S0/slave.info'
I0510 16:04:37.239020 2470 replica.cpp:537] Replica received write request for position 4 from (8651)@172.17.0.2:35810
I0510 16:04:37.239032 2468 hierarchical.cpp:1162] Performed allocation for agent 0db53e5d-8988-4a39-95ac-6ed9d3071b48-S0 in 186060ns
I0510 16:04:37.239440 2469 slave.cpp:1194] Forwarding total oversubscribed resources
I0510 16:04:37.239611 2468 master.cpp:4956] Received update of agent 0db53e5d-8988-4a39-95ac-6ed9d3071b48-S0 at slave(230)@172.17.0.2:35810 (e6116108716a) with total oversubscribed resources
I0510 16:04:37.240283 2468 hierarchical.cpp:531] Agent 0db53e5d-8988-4a39-95ac-6ed9d3071b48-S0 (e6116108716a) updated with oversubscribed resources (total: disk(role1):1024; cpus(*):16; mem(*):47270; ports(*):[31000-32000], allocated: )
I0510 16:04:37.240442 2468 hierarchical.cpp:1488] No resources available to allocate!
I0510 16:04:37.240505 2468 hierarchical.cpp:1162] Performed allocation for agent 0db53e5d-8988-4a39-95ac-6ed9d3071b48-S0 in 172810ns
I0510 16:04:37.241276 2460 process.cpp:3206] Handling HTTP event for process 'master' with path: '/master/create-volumes'
I0510 16:04:37.245966 2473 process.cpp:3206] Handling HTTP event for process 'master' with path: '/master/destroy-volumes'
I0510 16:04:37.249969 2473 hierarchical.cpp:1488] No resources available to allocate!
I0510 16:04:37.250228 2473 hierarchical.cpp:1139] Performed allocation for 1 agents in 514356ns
I0510 16:04:37.251801 2460 slave.cpp:823] Agent terminating
I0510 16:04:37.252429 2473 master.cpp:1343] Agent 0db53e5d-8988-4a39-95ac-6ed9d3071b48-S0 at slave(230)@172.17.0.2:35810 (e6116108716a) disconnected
I0510 16:04:37.252472 2473 master.cpp:2849] Disconnecting agent 0db53e5d-8988-4a39-95ac-6ed9d3071b48-S0 at slave(230)@172.17.0.2:35810 (e6116108716a)
I0510 16:04:37.252558 2473 master.cpp:2868] Deactivating agent 0db53e5d-8988-4a39-95ac-6ed9d3071b48-S0 at slave(230)@172.17.0.2:35810 (e6116108716a)
I0510 16:04:37.252751 2471 hierarchical.cpp:560] Agent 0db53e5d-8988-4a39-95ac-6ed9d3071b48-S0 deactivated
I0510 16:04:37.258271 2439 master.cpp:1190] Master terminating
I0510 16:04:37.259174 2472 hierarchical.cpp:505] Removed agent 0db53e5d-8988-4a39-95ac-6ed9d3071b48-S0
I0510 16:04:37.269857 2470 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 30.747646ms
I0510 16:04:37.269949 2470 replica.cpp:712] Persisted action at 4
[ OK ] PersistentVolumeEndpointsTest.BadCredentials (712 ms)
[ RUN ] PersistentVolumeEndpointsTest.GoodCreateAndDestroyACL
I0510 16:04:37.277546 2439 cluster.cpp:149] Creating default 'local' authorizer
I0510 16:04:37.413784 2439 leveldb.cpp:174] Opened db in 135.778573ms
I0510 16:04:37.468405 2439 leveldb.cpp:181] Compacted db in 54.536509ms
I0510 16:04:37.468493 2439 leveldb.cpp:196] Created db iterator in 24186ns
I0510 16:04:37.468511 2439 leveldb.cpp:202] Seeked to beginning of db in 2885ns
I0510 16:04:37.468523 2439 leveldb.cpp:271] Iterated through 0 keys in the db in 362ns
I0510 16:04:37.468572 2439 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0510 16:04:37.469426 2459 recover.cpp:447] Starting replica recovery
I0510 16:04:37.470043 2459 recover.cpp:473] Replica is in EMPTY status
I0510 16:04:37.471251 2460 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (8658)@172.17.0.2:35810
I0510 16:04:37.471678 2467 recover.cpp:193] Received a recover response from a replica in EMPTY status
I0510 16:04:37.472209 2463 recover.cpp:564] Updating replica status to STARTING
I0510 16:04:37.474328 2458 master.cpp:383] Master 0a842bbb-1a41-4e18-94d5-e32946296e75 (e6116108716a) started on 172.17.0.2:35810
I0510 16:04:37.474364 2458 master.cpp:385] Flags at startup: --acls="create_volumes {
principals {
values: "test-principal"
}
roles {
type: ANY
}
}
destroy_volumes {
principals {
values: "test-principal"
}
creator_principals {
values: "test-principal"
}
}
" --allocation_interval="50ms" --allocator="HierarchicalDRF" --authenticate="true" --authenticate_http="true" --authenticate_http_frameworks="true" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/fsM9OM/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_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --max_slave_ping_timeouts="5" --quiet="false" --recovery_slave_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="100secs" --registry_strict="true" --roles="role1" --root_submissions="true" --slave_ping_timeout="15secs" --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" --webui_dir="/mesos/mesos-0.29.0/_inst/share/mesos/webui" --work_dir="/tmp/fsM9OM/master" --zk_session_timeout="10secs"
I0510 16:04:37.474860 2458 master.cpp:434] Master only allowing authenticated frameworks to register
I0510 16:04:37.474870 2458 master.cpp:440] Master only allowing authenticated agents to register
I0510 16:04:37.474876 2458 master.cpp:446] Master only allowing authenticated HTTP frameworks to register
I0510 16:04:37.474882 2458 credentials.hpp:37] Loading credentials for authentication from '/tmp/fsM9OM/credentials'
I0510 16:04:37.475220 2458 master.cpp:490] Using default 'crammd5' authenticator
I0510 16:04:37.475405 2458 master.cpp:561] Using default 'basic' HTTP authenticator
I0510 16:04:37.475658 2458 master.cpp:641] Using default 'basic' HTTP framework authenticator
I0510 16:04:37.475883 2458 master.cpp:688] Authorization enabled
W0510 16:04:37.475901 2458 master.cpp:751] The '--roles' flag is deprecated. This flag will be removed in the future. See the Mesos 0.27 upgrade notes for more information
I0510 16:04:37.476155 2467 whitelist_watcher.cpp:77] No whitelist given
I0510 16:04:37.476191 2466 hierarchical.cpp:142] Initialized hierarchical allocator process
I0510 16:04:37.478541 2467 master.cpp:1939] The newly elected leader is master@172.17.0.2:35810 with id 0a842bbb-1a41-4e18-94d5-e32946296e75
I0510 16:04:37.478600 2467 master.cpp:1952] Elected as the leading master!
I0510 16:04:37.478623 2467 master.cpp:1639] Recovering from registrar
I0510 16:04:37.478960 2467 registrar.cpp:331] Recovering registrar
I0510 16:04:37.510094 2464 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 37.679877ms
I0510 16:04:37.510181 2464 replica.cpp:320] Persisted replica status to STARTING
I0510 16:04:37.510552 2467 recover.cpp:473] Replica is in STARTING status
I0510 16:04:37.512071 2462 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (8661)@172.17.0.2:35810
I0510 16:04:37.512614 2468 recover.cpp:193] Received a recover response from a replica in STARTING status
I0510 16:04:37.513082 2466 recover.cpp:564] Updating replica status to VOTING
I0510 16:04:37.551941 2467 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 38.618306ms
I0510 16:04:37.552023 2467 replica.cpp:320] Persisted replica status to VOTING
I0510 16:04:37.552264 2470 recover.cpp:578] Successfully joined the Paxos group
I0510 16:04:37.552564 2470 recover.cpp:462] Recover process terminated
I0510 16:04:37.553243 2467 log.cpp:524] Attempting to start the writer
I0510 16:04:37.554998 2464 replica.cpp:493] Replica received implicit promise request from (8662)@172.17.0.2:35810 with proposal 1
I0510 16:04:37.593735 2464 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 38.693762ms
I0510 16:04:37.593778 2464 replica.cpp:342] Persisted promised to 1
I0510 16:04:37.594637 2469 coordinator.cpp:238] Coordinator attempting to fill missing positions
I0510 16:04:37.596562 2473 replica.cpp:388] Replica received explicit promise request from (8663)@172.17.0.2:35810 for position 0 with proposal 2
I0510 16:04:37.635548 2473 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 38.892909ms
I0510 16:04:37.635632 2473 replica.cpp:712] Persisted action at 0
I0510 16:04:37.637006 2463 replica.cpp:537] Replica received write request for position 0 from (8664)@172.17.0.2:35810
I0510 16:04:37.637080 2463 leveldb.cpp:436] Reading position from leveldb took 37272ns
I0510 16:04:37.673544 2463 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 36.393025ms
I0510 16:04:37.673641 2463 replica.cpp:712] Persisted action at 0
I0510 16:04:37.674937 2463 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
I0510 16:04:37.715350 2463 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 40.335984ms
I0510 16:04:37.715438 2463 replica.cpp:712] Persisted action at 0
I0510 16:04:37.715476 2463 replica.cpp:697] Replica learned NOP action at position 0
I0510 16:04:37.716931 2473 log.cpp:540] Writer started with ending position 0
I0510 16:04:37.718569 2473 leveldb.cpp:436] Reading position from leveldb took 62320ns
I0510 16:04:37.720100 2459 registrar.cpp:364] Successfully fetched the registry (0B) in 0ns
I0510 16:04:37.720237 2459 registrar.cpp:463] Applied 1 operations in 33844ns; attempting to update the 'registry'
I0510 16:04:37.721513 2460 log.cpp:548] Attempting to append 170 bytes to the log
I0510 16:04:37.722020 2460 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
I0510 16:04:37.723147 2468 replica.cpp:537] Replica received write request for position 1 from (8665)@172.17.0.2:35810
I0510 16:04:37.757163 2468 leveldb.cpp:341] Persisting action (189 bytes) to leveldb took 33.948943ms
I0510 16:04:37.757253 2468 replica.cpp:712] Persisted action at 1
I0510 16:04:37.758702 2459 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
I0510 16:04:37.794975 2459 leveldb.cpp:341] Persisting action (191 bytes) to leveldb took 36.20591ms
I0510 16:04:37.795061 2459 replica.cpp:712] Persisted action at 1
I0510 16:04:37.795091 2459 replica.cpp:697] Replica learned APPEND action at position 1
I0510 16:04:37.796522 2467 registrar.cpp:508] Successfully updated the 'registry' in 0ns
I0510 16:04:37.796692 2467 registrar.cpp:394] Successfully recovered registrar
I0510 16:04:37.796993 2466 log.cpp:567] Attempting to truncate the log to 1
I0510 16:04:37.797127 2463 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
I0510 16:04:37.797293 2462 master.cpp:1747] Recovered 0 agents from the Registry (131B) ; allowing 10mins for agents to re-register
I0510 16:04:37.797349 2461 hierarchical.cpp:169] Skipping recovery of hierarchical allocator: nothing to recover
I0510 16:04:37.798007 2473 replica.cpp:537] Replica received write request for position 2 from (8666)@172.17.0.2:35810
I0510 16:04:37.826721 2473 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 28.643019ms
I0510 16:04:37.826807 2473 replica.cpp:712] Persisted action at 2
I0510 16:04:37.827592 2469 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
I0510 16:04:37.851847 2469 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 24.200994ms
I0510 16:04:37.852008 2469 leveldb.cpp:399] Deleting ~1 keys from leveldb took 78418ns
I0510 16:04:37.852035 2469 replica.cpp:712] Persisted action at 2
I0510 16:04:37.852069 2469 replica.cpp:697] Replica learned TRUNCATE action at position 2
I0510 16:04:37.873960 2439 containerizer.cpp:178] Using isolation: posix/cpu,posix/mem,filesystem/posix,network/cni
W0510 16:04:37.875366 2439 backend.cpp:66] Failed to create 'bind' backend: BindBackend requires root privileges
I0510 16:04:37.877398 2439 cluster.cpp:398] Creating default 'local' authorizer
I0510 16:04:37.879978 2461 slave.cpp:204] Agent started on 231)@172.17.0.2:35810
I0510 16:04:37.880028 2461 slave.cpp:205] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="true" --authenticatee="crammd5" --authorizer="local" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/PersistentVolumeEndpointsTest_GoodCreateAndDestroyACL_ERXI7o/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" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/PersistentVolumeEndpointsTest_GoodCreateAndDestroyACL_ERXI7o/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/PersistentVolumeEndpointsTest_GoodCreateAndDestroyACL_ERXI7o/http_credentials" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-0.29.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:1;mem:512;disk(role1):1024" --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/PersistentVolumeEndpointsTest_GoodCreateAndDestroyACL_ERXI7o"
I0510 16:04:37.880579 2461 credentials.hpp:86] Loading credential for authentication from '/tmp/PersistentVolumeEndpointsTest_GoodCreateAndDestroyACL_ERXI7o/credential'
I0510 16:04:37.880858 2461 slave.cpp:342] Agent using credential for: test-principal
I0510 16:04:37.880919 2461 credentials.hpp:37] Loading credentials for authentication from '/tmp/PersistentVolumeEndpointsTest_GoodCreateAndDestroyACL_ERXI7o/http_credentials'
I0510 16:04:37.881232 2461 slave.cpp:394] Using default 'basic' HTTP authenticator
I0510 16:04:37.881922 2461 resources.cpp:572] Parsing resources as JSON failed: cpus:1;mem:512;disk(role1):1024
Trying semicolon-delimited string format instead
I0510 16:04:37.882457 2461 slave.cpp:593] Agent resources: cpus(*):1; mem(*):512; disk(role1):1024; ports(*):[31000-32000]
I0510 16:04:37.882534 2461 slave.cpp:601] Agent attributes: [ ]
I0510 16:04:37.882549 2461 slave.cpp:606] Agent hostname: e6116108716a
I0510 16:04:37.884428 2459 state.cpp:57] Recovering state from '/tmp/PersistentVolumeEndpointsTest_GoodCreateAndDestroyACL_ERXI7o/meta'
I0510 16:04:37.884992 2471 status_update_manager.cpp:200] Recovering status update manager
I0510 16:04:37.885273 2471 containerizer.cpp:444] Recovering containerizer
I0510 16:04:37.886862 2471 provisioner.cpp:245] Provisioner recovery complete
I0510 16:04:37.887295 2470 slave.cpp:4812] Finished recovery
I0510 16:04:37.887943 2470 slave.cpp:4984] Querying resource estimator for oversubscribable resources
I0510 16:04:37.888253 2471 status_update_manager.cpp:174] Pausing sending status updates
I0510 16:04:37.888301 2472 slave.cpp:951] New master detected at master@172.17.0.2:35810
I0510 16:04:37.888334 2472 slave.cpp:963] Delaying registration for 1.213535ms
I0510 16:04:37.888425 2472 slave.cpp:971] Detecting new master
I0510 16:04:37.888576 2472 slave.cpp:4998] Received oversubscribable resources from the resource estimator
Build timed out (after 180 minutes). Marking the build as failed.
Build was aborted
Build failed in Jenkins: mesos-reviewbot #12987
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/mesos-reviewbot/12987/changes>
Changes:
[alexr] Added Astronomer to Powered by Mesos list.
[alexr] Added Shopee to Powered by Mesos list.
[alexr] Added Weibo to Powered by Mesos list.
------------------------------------------
[...truncated 114114 lines...]
I0510 12:38:56.097906 2457 leveldb.cpp:436] Reading position from leveldb took 25972ns
I0510 12:38:56.098839 2462 registrar.cpp:364] Successfully fetched the registry (0B) in 9.645824ms
I0510 12:38:56.098959 2462 registrar.cpp:463] Applied 1 operations in 27019ns; attempting to update the 'registry'
I0510 12:38:56.099680 2464 log.cpp:548] Attempting to append 170 bytes to the log
I0510 12:38:56.099844 2461 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
I0510 12:38:56.100471 2457 replica.cpp:537] Replica received write request for position 1 from (8587)@172.17.0.3:37833
I0510 12:38:56.101068 2457 leveldb.cpp:341] Persisting action (189 bytes) to leveldb took 558848ns
I0510 12:38:56.101092 2457 replica.cpp:712] Persisted action at 1
I0510 12:38:56.101827 2459 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
I0510 12:38:56.102320 2459 leveldb.cpp:341] Persisting action (191 bytes) to leveldb took 464698ns
I0510 12:38:56.102345 2459 replica.cpp:712] Persisted action at 1
I0510 12:38:56.102370 2459 replica.cpp:697] Replica learned APPEND action at position 1
I0510 12:38:56.103288 2461 registrar.cpp:508] Successfully updated the 'registry' in 4.2688ms
I0510 12:38:56.103420 2461 registrar.cpp:394] Successfully recovered registrar
I0510 12:38:56.103569 2463 log.cpp:567] Attempting to truncate the log to 1
I0510 12:38:56.103689 2465 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
I0510 12:38:56.103976 2464 master.cpp:1747] Recovered 0 agents from the Registry (131B) ; allowing 10mins for agents to re-register
I0510 12:38:56.104017 2466 hierarchical.cpp:169] Skipping recovery of hierarchical allocator: nothing to recover
I0510 12:38:56.104496 2457 replica.cpp:537] Replica received write request for position 2 from (8588)@172.17.0.3:37833
I0510 12:38:56.104919 2457 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 345500ns
I0510 12:38:56.104946 2457 replica.cpp:712] Persisted action at 2
I0510 12:38:56.105438 2457 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
I0510 12:38:56.105583 2457 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 114821ns
I0510 12:38:56.105638 2457 leveldb.cpp:399] Deleting ~1 keys from leveldb took 30053ns
I0510 12:38:56.105655 2457 replica.cpp:712] Persisted action at 2
I0510 12:38:56.105682 2457 replica.cpp:697] Replica learned TRUNCATE action at position 2
I0510 12:38:56.118731 2438 containerizer.cpp:178] Using isolation: posix/cpu,posix/mem,filesystem/posix,network/cni
W0510 12:38:56.119732 2438 backend.cpp:66] Failed to create 'bind' backend: BindBackend requires root privileges
I0510 12:38:56.121330 2438 cluster.cpp:398] Creating default 'local' authorizer
I0510 12:38:56.123338 2460 slave.cpp:204] Agent started on 230)@172.17.0.3:37833
I0510 12:38:56.123383 2460 slave.cpp:205] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="true" --authenticatee="crammd5" --authorizer="local" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/PersistentVolumeEndpointsTest_BadCredentials_lbeh0n/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" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/PersistentVolumeEndpointsTest_BadCredentials_lbeh0n/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/PersistentVolumeEndpointsTest_BadCredentials_lbeh0n/http_credentials" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-0.29.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="disk(role1):1024" --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/PersistentVolumeEndpointsTest_BadCredentials_lbeh0n"
I0510 12:38:56.123936 2460 credentials.hpp:86] Loading credential for authentication from '/tmp/PersistentVolumeEndpointsTest_BadCredentials_lbeh0n/credential'
I0510 12:38:56.124200 2460 slave.cpp:342] Agent using credential for: test-principal
I0510 12:38:56.124229 2460 credentials.hpp:37] Loading credentials for authentication from '/tmp/PersistentVolumeEndpointsTest_BadCredentials_lbeh0n/http_credentials'
I0510 12:38:56.124452 2460 slave.cpp:394] Using default 'basic' HTTP authenticator
I0510 12:38:56.124830 2460 resources.cpp:572] Parsing resources as JSON failed: disk(role1):1024
Trying semicolon-delimited string format instead
I0510 12:38:56.125208 2460 slave.cpp:593] Agent resources: disk(role1):1024; cpus(*):16; mem(*):47270; ports(*):[31000-32000]
I0510 12:38:56.125265 2460 slave.cpp:601] Agent attributes: [ ]
I0510 12:38:56.125277 2460 slave.cpp:606] Agent hostname: 7f6e1b347adc
I0510 12:38:56.126715 2466 state.cpp:57] Recovering state from '/tmp/PersistentVolumeEndpointsTest_BadCredentials_lbeh0n/meta'
I0510 12:38:56.127039 2470 status_update_manager.cpp:200] Recovering status update manager
I0510 12:38:56.127229 2463 containerizer.cpp:444] Recovering containerizer
I0510 12:38:56.128597 2467 provisioner.cpp:245] Provisioner recovery complete
I0510 12:38:56.128890 2462 slave.cpp:4807] Finished recovery
I0510 12:38:56.129407 2462 slave.cpp:4979] Querying resource estimator for oversubscribable resources
I0510 12:38:56.129679 2457 status_update_manager.cpp:174] Pausing sending status updates
I0510 12:38:56.129698 2467 slave.cpp:953] New master detected at master@172.17.0.3:37833
I0510 12:38:56.129765 2467 slave.cpp:965] Delaying registration for 1.212445ms
I0510 12:38:56.129884 2467 slave.cpp:973] Detecting new master
I0510 12:38:56.130009 2467 slave.cpp:4993] Received oversubscribable resources from the resource estimator
I0510 12:38:56.132324 2471 slave.cpp:1022] Authenticating with master master@172.17.0.3:37833
I0510 12:38:56.132349 2471 slave.cpp:1027] Using default CRAM-MD5 authenticatee
I0510 12:38:56.132604 2461 authenticatee.cpp:121] Creating new client SASL connection
I0510 12:38:56.132869 2468 master.cpp:5827] Authenticating slave(230)@172.17.0.3:37833
I0510 12:38:56.133015 2465 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(497)@172.17.0.3:37833
I0510 12:38:56.133318 2459 authenticator.cpp:98] Creating new server SASL connection
I0510 12:38:56.133515 2467 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
I0510 12:38:56.133577 2467 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
I0510 12:38:56.133718 2469 authenticator.cpp:203] Received SASL authentication start
I0510 12:38:56.133780 2469 authenticator.cpp:325] Authentication requires more steps
I0510 12:38:56.133867 2469 authenticatee.cpp:258] Received SASL authentication step
I0510 12:38:56.134003 2464 authenticator.cpp:231] Received SASL authentication step
I0510 12:38:56.134039 2464 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: '7f6e1b347adc' server FQDN: '7f6e1b347adc' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0510 12:38:56.134054 2464 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
I0510 12:38:56.134125 2464 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0510 12:38:56.134157 2464 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: '7f6e1b347adc' server FQDN: '7f6e1b347adc' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0510 12:38:56.134166 2464 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0510 12:38:56.134172 2464 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0510 12:38:56.134192 2464 authenticator.cpp:317] Authentication success
I0510 12:38:56.134282 2469 authenticatee.cpp:298] Authentication success
I0510 12:38:56.134349 2463 master.cpp:5857] Successfully authenticated principal 'test-principal' at slave(230)@172.17.0.3:37833
I0510 12:38:56.134491 2468 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(497)@172.17.0.3:37833
I0510 12:38:56.134729 2462 slave.cpp:1092] Successfully authenticated with master master@172.17.0.3:37833
I0510 12:38:56.134887 2462 slave.cpp:1488] Will retry registration in 13.357587ms if necessary
I0510 12:38:56.135110 2465 master.cpp:4538] Registering agent at slave(230)@172.17.0.3:37833 (7f6e1b347adc) with id 0c41ee3f-adf8-4673-94ef-2d8070ccebc5-S0
I0510 12:38:56.135607 2460 registrar.cpp:463] Applied 1 operations in 69209ns; attempting to update the 'registry'
I0510 12:38:56.136381 2466 log.cpp:548] Attempting to append 343 bytes to the log
I0510 12:38:56.136512 2462 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3
I0510 12:38:56.137405 2461 replica.cpp:537] Replica received write request for position 3 from (8604)@172.17.0.3:37833
I0510 12:38:56.137570 2462 hierarchical.cpp:1488] No resources available to allocate!
I0510 12:38:56.137639 2462 hierarchical.cpp:1139] Performed allocation for 0 agents in 131691ns
I0510 12:38:56.138108 2461 leveldb.cpp:341] Persisting action (362 bytes) to leveldb took 658348ns
I0510 12:38:56.138135 2461 replica.cpp:712] Persisted action at 3
I0510 12:38:56.138820 2470 replica.cpp:691] Replica received learned notice for position 3 from @0.0.0.0:0
I0510 12:38:56.139341 2470 leveldb.cpp:341] Persisting action (364 bytes) to leveldb took 492061ns
I0510 12:38:56.139364 2470 replica.cpp:712] Persisted action at 3
I0510 12:38:56.139384 2470 replica.cpp:697] Replica learned APPEND action at position 3
I0510 12:38:56.140761 2460 registrar.cpp:508] Successfully updated the 'registry' in 5088us
I0510 12:38:56.141037 2467 log.cpp:567] Attempting to truncate the log to 3
I0510 12:38:56.141160 2465 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4
I0510 12:38:56.141690 2467 slave.cpp:3707] Received ping from slave-observer(219)@172.17.0.3:37833
I0510 12:38:56.142043 2466 replica.cpp:537] Replica received write request for position 4 from (8605)@172.17.0.3:37833
I0510 12:38:56.142113 2462 hierarchical.cpp:473] Added agent 0c41ee3f-adf8-4673-94ef-2d8070ccebc5-S0 (7f6e1b347adc) with disk(role1):1024; cpus(*):16; mem(*):47270; ports(*):[31000-32000] (allocated: )
I0510 12:38:56.142144 2460 slave.cpp:1136] Registered with master master@172.17.0.3:37833; given agent ID 0c41ee3f-adf8-4673-94ef-2d8070ccebc5-S0
I0510 12:38:56.142092 2468 master.cpp:4606] Registered agent 0c41ee3f-adf8-4673-94ef-2d8070ccebc5-S0 at slave(230)@172.17.0.3:37833 (7f6e1b347adc) with disk(role1):1024; cpus(*):16; mem(*):47270; ports(*):[31000-32000]
I0510 12:38:56.142163 2460 fetcher.cpp:81] Clearing fetcher cache
I0510 12:38:56.142269 2462 hierarchical.cpp:1488] No resources available to allocate!
I0510 12:38:56.142329 2462 hierarchical.cpp:1162] Performed allocation for agent 0c41ee3f-adf8-4673-94ef-2d8070ccebc5-S0 in 169163ns
I0510 12:38:56.142493 2458 status_update_manager.cpp:181] Resuming sending status updates
I0510 12:38:56.142675 2466 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 546914ns
I0510 12:38:56.142714 2466 replica.cpp:712] Persisted action at 4
I0510 12:38:56.142866 2460 slave.cpp:1159] Checkpointing SlaveInfo to '/tmp/PersistentVolumeEndpointsTest_BadCredentials_lbeh0n/meta/slaves/0c41ee3f-adf8-4673-94ef-2d8070ccebc5-S0/slave.info'
I0510 12:38:56.143270 2470 replica.cpp:691] Replica received learned notice for position 4 from @0.0.0.0:0
I0510 12:38:56.143332 2460 slave.cpp:1196] Forwarding total oversubscribed resources
I0510 12:38:56.143661 2470 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 360099ns
I0510 12:38:56.143725 2470 leveldb.cpp:399] Deleting ~2 keys from leveldb took 37592ns
I0510 12:38:56.143746 2470 replica.cpp:712] Persisted action at 4
I0510 12:38:56.143764 2470 replica.cpp:697] Replica learned TRUNCATE action at position 4
I0510 12:38:56.143753 2459 master.cpp:4950] Received update of agent 0c41ee3f-adf8-4673-94ef-2d8070ccebc5-S0 at slave(230)@172.17.0.3:37833 (7f6e1b347adc) with total oversubscribed resources
I0510 12:38:56.144510 2471 hierarchical.cpp:531] Agent 0c41ee3f-adf8-4673-94ef-2d8070ccebc5-S0 (7f6e1b347adc) updated with oversubscribed resources (total: disk(role1):1024; cpus(*):16; mem(*):47270; ports(*):[31000-32000], allocated: )
I0510 12:38:56.144704 2471 hierarchical.cpp:1488] No resources available to allocate!
I0510 12:38:56.144778 2471 hierarchical.cpp:1162] Performed allocation for agent 0c41ee3f-adf8-4673-94ef-2d8070ccebc5-S0 in 186557ns
I0510 12:38:56.145843 2462 process.cpp:3206] Handling HTTP event for process 'master' with path: '/master/create-volumes'
I0510 12:38:56.149893 2458 process.cpp:3206] Handling HTTP event for process 'master' with path: '/master/destroy-volumes'
I0510 12:38:56.153055 2460 slave.cpp:825] Agent terminating
I0510 12:38:56.153280 2467 master.cpp:1343] Agent 0c41ee3f-adf8-4673-94ef-2d8070ccebc5-S0 at slave(230)@172.17.0.3:37833 (7f6e1b347adc) disconnected
I0510 12:38:56.153406 2467 master.cpp:2849] Disconnecting agent 0c41ee3f-adf8-4673-94ef-2d8070ccebc5-S0 at slave(230)@172.17.0.3:37833 (7f6e1b347adc)
I0510 12:38:56.153468 2467 master.cpp:2868] Deactivating agent 0c41ee3f-adf8-4673-94ef-2d8070ccebc5-S0 at slave(230)@172.17.0.3:37833 (7f6e1b347adc)
I0510 12:38:56.153667 2462 hierarchical.cpp:560] Agent 0c41ee3f-adf8-4673-94ef-2d8070ccebc5-S0 deactivated
I0510 12:38:56.158758 2471 master.cpp:1190] Master terminating
I0510 12:38:56.159279 2472 hierarchical.cpp:505] Removed agent 0c41ee3f-adf8-4673-94ef-2d8070ccebc5-S0
[ OK ] PersistentVolumeEndpointsTest.BadCredentials (92 ms)
[ RUN ] PersistentVolumeEndpointsTest.GoodCreateAndDestroyACL
I0510 12:38:56.169261 2438 cluster.cpp:149] Creating default 'local' authorizer
I0510 12:38:56.172229 2438 leveldb.cpp:174] Opened db in 2.546201ms
I0510 12:38:56.173315 2438 leveldb.cpp:181] Compacted db in 1.051964ms
I0510 12:38:56.173372 2438 leveldb.cpp:196] Created db iterator in 19211ns
I0510 12:38:56.173385 2438 leveldb.cpp:202] Seeked to beginning of db in 1654ns
I0510 12:38:56.173394 2438 leveldb.cpp:271] Iterated through 0 keys in the db in 238ns
I0510 12:38:56.173434 2438 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0510 12:38:56.173979 2470 recover.cpp:447] Starting replica recovery
I0510 12:38:56.174391 2470 recover.cpp:473] Replica is in EMPTY status
I0510 12:38:56.175664 2465 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (8612)@172.17.0.3:37833
I0510 12:38:56.175905 2464 recover.cpp:193] Received a recover response from a replica in EMPTY status
I0510 12:38:56.176583 2458 recover.cpp:564] Updating replica status to STARTING
I0510 12:38:56.177408 2464 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 523695ns
I0510 12:38:56.177438 2464 replica.cpp:320] Persisted replica status to STARTING
I0510 12:38:56.177690 2471 recover.cpp:473] Replica is in STARTING status
I0510 12:38:56.178694 2468 master.cpp:383] Master f989e263-8c63-4570-a355-754352ac64d9 (7f6e1b347adc) started on 172.17.0.3:37833
I0510 12:38:56.178722 2468 master.cpp:385] Flags at startup: --acls="create_volumes {
principals {
values: "test-principal"
}
roles {
type: ANY
}
}
destroy_volumes {
principals {
values: "test-principal"
}
creator_principals {
values: "test-principal"
}
}
" --allocation_interval="50ms" --allocator="HierarchicalDRF" --authenticate="true" --authenticate_http="true" --authenticate_http_frameworks="true" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/FVNnT2/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_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --max_slave_ping_timeouts="5" --quiet="false" --recovery_slave_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="100secs" --registry_strict="true" --roles="role1" --root_submissions="true" --slave_ping_timeout="15secs" --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" --webui_dir="/mesos/mesos-0.29.0/_inst/share/mesos/webui" --work_dir="/tmp/FVNnT2/master" --zk_session_timeout="10secs"
I0510 12:38:56.179148 2468 master.cpp:434] Master only allowing authenticated frameworks to register
I0510 12:38:56.179160 2468 master.cpp:440] Master only allowing authenticated agents to register
I0510 12:38:56.179167 2468 master.cpp:446] Master only allowing authenticated HTTP frameworks to register
I0510 12:38:56.179173 2468 credentials.hpp:37] Loading credentials for authentication from '/tmp/FVNnT2/credentials'
I0510 12:38:56.179224 2460 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (8613)@172.17.0.3:37833
I0510 12:38:56.179455 2466 recover.cpp:193] Received a recover response from a replica in STARTING status
I0510 12:38:56.179484 2468 master.cpp:490] Using default 'crammd5' authenticator
I0510 12:38:56.179807 2468 master.cpp:561] Using default 'basic' HTTP authenticator
I0510 12:38:56.179980 2467 recover.cpp:564] Updating replica status to VOTING
I0510 12:38:56.179987 2468 master.cpp:641] Using default 'basic' HTTP framework authenticator
I0510 12:38:56.180160 2468 master.cpp:688] Authorization enabled
W0510 12:38:56.180181 2468 master.cpp:751] The '--roles' flag is deprecated. This flag will be removed in the future. See the Mesos 0.27 upgrade notes for more information
I0510 12:38:56.180426 2458 whitelist_watcher.cpp:77] No whitelist given
I0510 12:38:56.180440 2457 hierarchical.cpp:142] Initialized hierarchical allocator process
I0510 12:38:56.180601 2469 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 449889ns
I0510 12:38:56.180624 2469 replica.cpp:320] Persisted replica status to VOTING
I0510 12:38:56.180716 2467 recover.cpp:578] Successfully joined the Paxos group
I0510 12:38:56.181028 2467 recover.cpp:462] Recover process terminated
I0510 12:38:56.183462 2468 master.cpp:1939] The newly elected leader is master@172.17.0.3:37833 with id f989e263-8c63-4570-a355-754352ac64d9
I0510 12:38:56.183502 2468 master.cpp:1952] Elected as the leading master!
I0510 12:38:56.183540 2468 master.cpp:1639] Recovering from registrar
I0510 12:38:56.183722 2459 registrar.cpp:331] Recovering registrar
I0510 12:38:56.184363 2468 log.cpp:524] Attempting to start the writer
I0510 12:38:56.185788 2457 replica.cpp:493] Replica received implicit promise request from (8616)@172.17.0.3:37833 with proposal 1
I0510 12:38:56.186341 2457 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 517925ns
I0510 12:38:56.186363 2457 replica.cpp:342] Persisted promised to 1
I0510 12:38:56.187000 2469 coordinator.cpp:238] Coordinator attempting to fill missing positions
I0510 12:38:56.188329 2467 replica.cpp:388] Replica received explicit promise request from (8617)@172.17.0.3:37833 for position 0 with proposal 2
I0510 12:38:56.188752 2467 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 383689ns
I0510 12:38:56.188774 2467 replica.cpp:712] Persisted action at 0
I0510 12:38:56.189925 2468 replica.cpp:537] Replica received write request for position 0 from (8618)@172.17.0.3:37833
I0510 12:38:56.189983 2468 leveldb.cpp:436] Reading position from leveldb took 29599ns
I0510 12:38:56.190378 2468 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 351735ns
I0510 12:38:56.190402 2468 replica.cpp:712] Persisted action at 0
I0510 12:38:56.190963 2466 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
I0510 12:38:56.191401 2466 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 409378ns
I0510 12:38:56.191423 2466 replica.cpp:712] Persisted action at 0
I0510 12:38:56.191438 2466 replica.cpp:697] Replica learned NOP action at position 0
I0510 12:38:56.192023 2464 log.cpp:540] Writer started with ending position 0
I0510 12:38:56.193027 2466 leveldb.cpp:436] Reading position from leveldb took 24879ns
I0510 12:38:56.193985 2458 registrar.cpp:364] Successfully fetched the registry (0B) in 0ns
I0510 12:38:56.194082 2458 registrar.cpp:463] Applied 1 operations in 23171ns; attempting to update the 'registry'
I0510 12:38:56.194818 2463 log.cpp:548] Attempting to append 170 bytes to the log
I0510 12:38:56.194941 2462 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
I0510 12:38:56.195672 2463 replica.cpp:537] Replica received write request for position 1 from (8619)@172.17.0.3:37833
I0510 12:38:56.196172 2463 leveldb.cpp:341] Persisting action (189 bytes) to leveldb took 466399ns
I0510 12:38:56.196195 2463 replica.cpp:712] Persisted action at 1
I0510 12:38:56.196806 2468 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
I0510 12:38:56.197275 2468 leveldb.cpp:341] Persisting action (191 bytes) to leveldb took 440017ns
I0510 12:38:56.197299 2468 replica.cpp:712] Persisted action at 1
I0510 12:38:56.197314 2468 replica.cpp:697] Replica learned APPEND action at position 1
I0510 12:38:56.198230 2471 registrar.cpp:508] Successfully updated the 'registry' in 0ns
I0510 12:38:56.198395 2471 registrar.cpp:394] Successfully recovered registrar
I0510 12:38:56.198447 2459 log.cpp:567] Attempting to truncate the log to 1
I0510 12:38:56.198576 2463 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
I0510 12:38:56.198952 2470 master.cpp:1747] Recovered 0 agents from the Registry (131B) ; allowing 10mins for agents to re-register
I0510 12:38:56.198988 2461 hierarchical.cpp:169] Skipping recovery of hierarchical allocator: nothing to recover
I0510 12:38:56.199317 2469 replica.cpp:537] Replica received write request for position 2 from (8620)@172.17.0.3:37833
I0510 12:38:56.199776 2469 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 425915ns
I0510 12:38:56.199798 2469 replica.cpp:712] Persisted action at 2
I0510 12:38:56.200296 2472 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
I0510 12:38:56.200768 2472 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 378704ns
I0510 12:38:56.200820 2472 leveldb.cpp:399] Deleting ~1 keys from leveldb took 28876ns
I0510 12:38:56.200839 2472 replica.cpp:712] Persisted action at 2
I0510 12:38:56.200855 2472 replica.cpp:697] Replica learned TRUNCATE action at position 2
I0510 12:38:56.222414 2438 containerizer.cpp:178] Using isolation: posix/cpu,posix/mem,filesystem/posix,network/cni
W0510 12:38:56.223176 2438 backend.cpp:66] Failed to create 'bind' backend: BindBackend requires root privileges
I0510 12:38:56.224477 2438 cluster.cpp:398] Creating default 'local' authorizer
I0510 12:38:56.226112 2462 slave.cpp:204] Agent started on 231)@172.17.0.3:37833
I0510 12:38:56.226222 2462 slave.cpp:205] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="true" --authenticatee="crammd5" --authorizer="local" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/PersistentVolumeEndpointsTest_GoodCreateAndDestroyACL_H1662V/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" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/PersistentVolumeEndpointsTest_GoodCreateAndDestroyACL_H1662V/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/PersistentVolumeEndpointsTest_GoodCreateAndDestroyACL_H1662V/http_credentials" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-0.29.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:1;mem:512;disk(role1):1024" --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/PersistentVolumeEndpointsTest_GoodCreateAndDestroyACL_H1662V"
I0510 12:38:56.226721 2462 credentials.hpp:86] Loading credential for authentication from '/tmp/PersistentVolumeEndpointsTest_GoodCreateAndDestroyACL_H1662V/credential'
I0510 12:38:56.226946 2462 slave.cpp:342] Agent using credential for: test-principal
I0510 12:38:56.226975 2462 credentials.hpp:37] Loading credentials for authentication from '/tmp/PersistentVolumeEndpointsTest_GoodCreateAndDestroyACL_H1662V/http_credentials'
I0510 12:38:56.227200 2462 slave.cpp:394] Using default 'basic' HTTP authenticator
I0510 12:38:56.227644 2462 resources.cpp:572] Parsing resources as JSON failed: cpus:1;mem:512;disk(role1):1024
Trying semicolon-delimited string format instead
I0510 12:38:56.228008 2462 slave.cpp:593] Agent resources: cpus(*):1; mem(*):512; disk(role1):1024; ports(*):[31000-32000]
I0510 12:38:56.228063 2462 slave.cpp:601] Agent attributes: [ ]
I0510 12:38:56.228073 2462 slave.cpp:606] Agent hostname: 7f6e1b347adc
I0510 12:38:56.229610 2465 state.cpp:57] Recovering state from '/tmp/PersistentVolumeEndpointsTest_GoodCreateAndDestroyACL_H1662V/meta'
I0510 12:38:56.229936 2460 status_update_manager.cpp:200] Recovering status update manager
I0510 12:38:56.230218 2471 containerizer.cpp:444] Recovering containerizer
I0510 12:38:56.231714 2459 provisioner.cpp:245] Provisioner recovery complete
I0510 12:38:56.232079 2469 slave.cpp:4807] Finished recovery
I0510 12:38:56.232550 2469 slave.cpp:4979] Querying resource estimator for oversubscribable resources
I0510 12:38:56.232810 2467 slave.cpp:4993] Received oversubscribable resources from the resource estimator
I0510 12:38:56.232971 2464 status_update_manager.cpp:174] Pausing sending status updates
I0510 12:38:56.232976 2467 slave.cpp:953] New master detected at master@172.17.0.3:37833
I0510 12:38:56.233000 2467 slave.cpp:965] Delaying registration for 858545ns
I0510 12:38:56.233043 2467 slave.cpp:973] Detecting new master
Build timed out (after 180 minutes). Marking the build as failed.
Build was aborted
Build failed in Jenkins: mesos-reviewbot #12986
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/mesos-reviewbot/12986/>
------------------------------------------
[...truncated 114008 lines...]
I0510 09:41:23.111229 2470 registrar.cpp:463] Applied 1 operations in 23894ns; attempting to update the 'registry'
I0510 09:41:23.112061 2460 log.cpp:548] Attempting to append 170 bytes to the log
I0510 09:41:23.112202 2466 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
I0510 09:41:23.113229 2458 replica.cpp:537] Replica received write request for position 1 from (8602)@172.17.0.2:39121
I0510 09:41:23.113674 2458 leveldb.cpp:341] Persisting action (189 bytes) to leveldb took 396512ns
I0510 09:41:23.113705 2458 replica.cpp:712] Persisted action at 1
I0510 09:41:23.114403 2471 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
I0510 09:41:23.114809 2471 leveldb.cpp:341] Persisting action (191 bytes) to leveldb took 362720ns
I0510 09:41:23.114840 2471 replica.cpp:712] Persisted action at 1
I0510 09:41:23.114862 2471 replica.cpp:697] Replica learned APPEND action at position 1
I0510 09:41:23.116027 2467 registrar.cpp:508] Successfully updated the 'registry' in 4.720896ms
I0510 09:41:23.116225 2467 registrar.cpp:394] Successfully recovered registrar
I0510 09:41:23.116363 2458 log.cpp:567] Attempting to truncate the log to 1
I0510 09:41:23.116701 2471 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
I0510 09:41:23.117120 2460 master.cpp:1747] Recovered 0 agents from the Registry (131B) ; allowing 10mins for agents to re-register
I0510 09:41:23.117264 2461 hierarchical.cpp:169] Skipping recovery of hierarchical allocator: nothing to recover
I0510 09:41:23.117919 2467 replica.cpp:537] Replica received write request for position 2 from (8603)@172.17.0.2:39121
I0510 09:41:23.118340 2467 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 377205ns
I0510 09:41:23.118371 2467 replica.cpp:712] Persisted action at 2
I0510 09:41:23.119096 2464 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
I0510 09:41:23.119473 2464 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 337438ns
I0510 09:41:23.119565 2464 leveldb.cpp:399] Deleting ~1 keys from leveldb took 59209ns
I0510 09:41:23.119592 2464 replica.cpp:712] Persisted action at 2
I0510 09:41:23.119617 2464 replica.cpp:697] Replica learned TRUNCATE action at position 2
I0510 09:41:23.131003 2438 containerizer.cpp:178] Using isolation: posix/cpu,posix/mem,filesystem/posix,network/cni
W0510 09:41:23.131707 2438 backend.cpp:66] Failed to create 'bind' backend: BindBackend requires root privileges
I0510 09:41:23.133023 2438 cluster.cpp:398] Creating default 'local' authorizer
I0510 09:41:23.134280 2461 slave.cpp:204] Agent started on 230)@172.17.0.2:39121
I0510 09:41:23.134301 2461 slave.cpp:205] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="true" --authenticatee="crammd5" --authorizer="local" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/PersistentVolumeEndpointsTest_BadCredentials_l2ZmT1/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" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/PersistentVolumeEndpointsTest_BadCredentials_l2ZmT1/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/PersistentVolumeEndpointsTest_BadCredentials_l2ZmT1/http_credentials" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-0.29.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="disk(role1):1024" --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/PersistentVolumeEndpointsTest_BadCredentials_l2ZmT1"
I0510 09:41:23.134786 2461 credentials.hpp:86] Loading credential for authentication from '/tmp/PersistentVolumeEndpointsTest_BadCredentials_l2ZmT1/credential'
I0510 09:41:23.134999 2461 slave.cpp:342] Agent using credential for: test-principal
I0510 09:41:23.135033 2461 credentials.hpp:37] Loading credentials for authentication from '/tmp/PersistentVolumeEndpointsTest_BadCredentials_l2ZmT1/http_credentials'
I0510 09:41:23.135334 2461 slave.cpp:394] Using default 'basic' HTTP authenticator
I0510 09:41:23.135820 2461 resources.cpp:572] Parsing resources as JSON failed: disk(role1):1024
Trying semicolon-delimited string format instead
I0510 09:41:23.136262 2461 slave.cpp:593] Agent resources: disk(role1):1024; cpus(*):16; mem(*):47270; ports(*):[31000-32000]
I0510 09:41:23.136342 2461 slave.cpp:601] Agent attributes: [ ]
I0510 09:41:23.136364 2461 slave.cpp:606] Agent hostname: 2c448d2af3cc
I0510 09:41:23.137714 2468 state.cpp:57] Recovering state from '/tmp/PersistentVolumeEndpointsTest_BadCredentials_l2ZmT1/meta'
I0510 09:41:23.138159 2458 status_update_manager.cpp:200] Recovering status update manager
I0510 09:41:23.138384 2464 containerizer.cpp:444] Recovering containerizer
I0510 09:41:23.139696 2469 provisioner.cpp:245] Provisioner recovery complete
I0510 09:41:23.140010 2471 slave.cpp:4807] Finished recovery
I0510 09:41:23.140391 2471 slave.cpp:4979] Querying resource estimator for oversubscribable resources
I0510 09:41:23.140722 2460 status_update_manager.cpp:174] Pausing sending status updates
I0510 09:41:23.140732 2470 slave.cpp:953] New master detected at master@172.17.0.2:39121
I0510 09:41:23.140758 2470 slave.cpp:965] Delaying registration for 6.348531ms
I0510 09:41:23.140807 2470 slave.cpp:973] Detecting new master
I0510 09:41:23.140981 2470 slave.cpp:4993] Received oversubscribable resources from the resource estimator
I0510 09:41:23.147794 2472 hierarchical.cpp:1488] No resources available to allocate!
I0510 09:41:23.147843 2463 slave.cpp:1022] Authenticating with master master@172.17.0.2:39121
I0510 09:41:23.147876 2463 slave.cpp:1027] Using default CRAM-MD5 authenticatee
I0510 09:41:23.147891 2472 hierarchical.cpp:1139] Performed allocation for 0 agents in 145853ns
I0510 09:41:23.148104 2460 authenticatee.cpp:121] Creating new client SASL connection
I0510 09:41:23.148417 2468 master.cpp:5827] Authenticating slave(230)@172.17.0.2:39121
I0510 09:41:23.148583 2457 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(498)@172.17.0.2:39121
I0510 09:41:23.148860 2461 authenticator.cpp:98] Creating new server SASL connection
I0510 09:41:23.149090 2464 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
I0510 09:41:23.149126 2464 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
I0510 09:41:23.149226 2464 authenticator.cpp:203] Received SASL authentication start
I0510 09:41:23.149296 2464 authenticator.cpp:325] Authentication requires more steps
I0510 09:41:23.149391 2464 authenticatee.cpp:258] Received SASL authentication step
I0510 09:41:23.149579 2457 authenticator.cpp:231] Received SASL authentication step
I0510 09:41:23.149633 2457 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: '2c448d2af3cc' server FQDN: '2c448d2af3cc' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0510 09:41:23.149648 2457 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
I0510 09:41:23.149685 2457 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0510 09:41:23.149726 2457 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: '2c448d2af3cc' server FQDN: '2c448d2af3cc' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0510 09:41:23.149749 2457 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0510 09:41:23.149761 2457 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0510 09:41:23.149801 2457 authenticator.cpp:317] Authentication success
I0510 09:41:23.149948 2467 authenticatee.cpp:298] Authentication success
I0510 09:41:23.150085 2472 master.cpp:5857] Successfully authenticated principal 'test-principal' at slave(230)@172.17.0.2:39121
I0510 09:41:23.150177 2469 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(498)@172.17.0.2:39121
I0510 09:41:23.150409 2468 slave.cpp:1092] Successfully authenticated with master master@172.17.0.2:39121
I0510 09:41:23.150624 2468 slave.cpp:1488] Will retry registration in 2.564172ms if necessary
I0510 09:41:23.150876 2461 master.cpp:4538] Registering agent at slave(230)@172.17.0.2:39121 (2c448d2af3cc) with id 470ec799-e4dd-4007-b97a-2cc868bee741-S0
I0510 09:41:23.151350 2472 registrar.cpp:463] Applied 1 operations in 59779ns; attempting to update the 'registry'
I0510 09:41:23.152228 2471 log.cpp:548] Attempting to append 343 bytes to the log
I0510 09:41:23.152375 2459 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3
I0510 09:41:23.153152 2472 replica.cpp:537] Replica received write request for position 3 from (8619)@172.17.0.2:39121
I0510 09:41:23.153655 2472 leveldb.cpp:341] Persisting action (362 bytes) to leveldb took 452280ns
I0510 09:41:23.153690 2472 replica.cpp:712] Persisted action at 3
I0510 09:41:23.154186 2472 slave.cpp:1488] Will retry registration in 9.488642ms if necessary
I0510 09:41:23.154454 2472 replica.cpp:691] Replica received learned notice for position 3 from @0.0.0.0:0
I0510 09:41:23.154458 2465 master.cpp:4526] Ignoring register agent message from slave(230)@172.17.0.2:39121 (2c448d2af3cc) as admission is already in progress
I0510 09:41:23.154850 2472 leveldb.cpp:341] Persisting action (364 bytes) to leveldb took 349365ns
I0510 09:41:23.154881 2472 replica.cpp:712] Persisted action at 3
I0510 09:41:23.154902 2472 replica.cpp:697] Replica learned APPEND action at position 3
I0510 09:41:23.156486 2472 registrar.cpp:508] Successfully updated the 'registry' in 5.070848ms
I0510 09:41:23.156787 2463 log.cpp:567] Attempting to truncate the log to 3
I0510 09:41:23.156918 2472 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4
I0510 09:41:23.157573 2458 slave.cpp:3707] Received ping from slave-observer(218)@172.17.0.2:39121
I0510 09:41:23.157829 2469 replica.cpp:537] Replica received write request for position 4 from (8620)@172.17.0.2:39121
I0510 09:41:23.157832 2467 master.cpp:4606] Registered agent 470ec799-e4dd-4007-b97a-2cc868bee741-S0 at slave(230)@172.17.0.2:39121 (2c448d2af3cc) with disk(role1):1024; cpus(*):16; mem(*):47270; ports(*):[31000-32000]
I0510 09:41:23.158107 2462 slave.cpp:1136] Registered with master master@172.17.0.2:39121; given agent ID 470ec799-e4dd-4007-b97a-2cc868bee741-S0
I0510 09:41:23.158143 2462 fetcher.cpp:81] Clearing fetcher cache
I0510 09:41:23.158145 2470 hierarchical.cpp:473] Added agent 470ec799-e4dd-4007-b97a-2cc868bee741-S0 (2c448d2af3cc) with disk(role1):1024; cpus(*):16; mem(*):47270; ports(*):[31000-32000] (allocated: )
I0510 09:41:23.158285 2470 hierarchical.cpp:1488] No resources available to allocate!
I0510 09:41:23.158327 2467 status_update_manager.cpp:181] Resuming sending status updates
I0510 09:41:23.158359 2470 hierarchical.cpp:1162] Performed allocation for agent 470ec799-e4dd-4007-b97a-2cc868bee741-S0 in 166586ns
I0510 09:41:23.158498 2469 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 617598ns
I0510 09:41:23.158568 2469 replica.cpp:712] Persisted action at 4
I0510 09:41:23.158712 2462 slave.cpp:1159] Checkpointing SlaveInfo to '/tmp/PersistentVolumeEndpointsTest_BadCredentials_l2ZmT1/meta/slaves/470ec799-e4dd-4007-b97a-2cc868bee741-S0/slave.info'
I0510 09:41:23.159215 2462 slave.cpp:1196] Forwarding total oversubscribed resources
I0510 09:41:23.159512 2462 replica.cpp:691] Replica received learned notice for position 4 from @0.0.0.0:0
I0510 09:41:23.159580 2466 master.cpp:4950] Received update of agent 470ec799-e4dd-4007-b97a-2cc868bee741-S0 at slave(230)@172.17.0.2:39121 (2c448d2af3cc) with total oversubscribed resources
I0510 09:41:23.160025 2462 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 444883ns
I0510 09:41:23.160087 2462 leveldb.cpp:399] Deleting ~2 keys from leveldb took 34672ns
I0510 09:41:23.160107 2462 replica.cpp:712] Persisted action at 4
I0510 09:41:23.160125 2462 replica.cpp:697] Replica learned TRUNCATE action at position 4
I0510 09:41:23.160146 2466 hierarchical.cpp:531] Agent 470ec799-e4dd-4007-b97a-2cc868bee741-S0 (2c448d2af3cc) updated with oversubscribed resources (total: disk(role1):1024; cpus(*):16; mem(*):47270; ports(*):[31000-32000], allocated: )
I0510 09:41:23.160272 2466 hierarchical.cpp:1488] No resources available to allocate!
I0510 09:41:23.160326 2466 hierarchical.cpp:1162] Performed allocation for agent 470ec799-e4dd-4007-b97a-2cc868bee741-S0 in 146473ns
I0510 09:41:23.160398 2469 process.cpp:3206] Handling HTTP event for process 'master' with path: '/master/create-volumes'
I0510 09:41:23.163607 2463 process.cpp:3206] Handling HTTP event for process 'master' with path: '/master/destroy-volumes'
I0510 09:41:23.166760 2465 slave.cpp:825] Agent terminating
I0510 09:41:23.167560 2469 master.cpp:1343] Agent 470ec799-e4dd-4007-b97a-2cc868bee741-S0 at slave(230)@172.17.0.2:39121 (2c448d2af3cc) disconnected
I0510 09:41:23.167601 2469 master.cpp:2849] Disconnecting agent 470ec799-e4dd-4007-b97a-2cc868bee741-S0 at slave(230)@172.17.0.2:39121 (2c448d2af3cc)
I0510 09:41:23.167678 2469 master.cpp:2868] Deactivating agent 470ec799-e4dd-4007-b97a-2cc868bee741-S0 at slave(230)@172.17.0.2:39121 (2c448d2af3cc)
I0510 09:41:23.167842 2463 hierarchical.cpp:560] Agent 470ec799-e4dd-4007-b97a-2cc868bee741-S0 deactivated
I0510 09:41:23.171895 2459 master.cpp:1190] Master terminating
I0510 09:41:23.172408 2457 hierarchical.cpp:505] Removed agent 470ec799-e4dd-4007-b97a-2cc868bee741-S0
[ OK ] PersistentVolumeEndpointsTest.BadCredentials (93 ms)
[ RUN ] PersistentVolumeEndpointsTest.GoodCreateAndDestroyACL
I0510 09:41:23.181048 2438 cluster.cpp:149] Creating default 'local' authorizer
I0510 09:41:23.184065 2438 leveldb.cpp:174] Opened db in 2.688529ms
I0510 09:41:23.185104 2438 leveldb.cpp:181] Compacted db in 999640ns
I0510 09:41:23.185158 2438 leveldb.cpp:196] Created db iterator in 18044ns
I0510 09:41:23.185179 2438 leveldb.cpp:202] Seeked to beginning of db in 1790ns
I0510 09:41:23.185192 2438 leveldb.cpp:271] Iterated through 0 keys in the db in 293ns
I0510 09:41:23.185277 2438 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0510 09:41:23.185937 2471 recover.cpp:447] Starting replica recovery
I0510 09:41:23.186277 2471 recover.cpp:473] Replica is in EMPTY status
I0510 09:41:23.187623 2462 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (8627)@172.17.0.2:39121
I0510 09:41:23.187994 2471 recover.cpp:193] Received a recover response from a replica in EMPTY status
I0510 09:41:23.188722 2459 recover.cpp:564] Updating replica status to STARTING
I0510 09:41:23.189561 2460 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 613146ns
I0510 09:41:23.189599 2460 replica.cpp:320] Persisted replica status to STARTING
I0510 09:41:23.189822 2458 recover.cpp:473] Replica is in STARTING status
I0510 09:41:23.190976 2471 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (8628)@172.17.0.2:39121
I0510 09:41:23.191326 2472 master.cpp:383] Master 7af97aa5-6c02-420f-a30e-a2c4856e8434 (2c448d2af3cc) started on 172.17.0.2:39121
I0510 09:41:23.191445 2460 recover.cpp:193] Received a recover response from a replica in STARTING status
I0510 09:41:23.191350 2472 master.cpp:385] Flags at startup: --acls="create_volumes {
principals {
values: "test-principal"
}
roles {
type: ANY
}
}
destroy_volumes {
principals {
values: "test-principal"
}
creator_principals {
values: "test-principal"
}
}
" --allocation_interval="50ms" --allocator="HierarchicalDRF" --authenticate="true" --authenticate_http="true" --authenticate_http_frameworks="true" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/9Zhrjh/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_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --max_slave_ping_timeouts="5" --quiet="false" --recovery_slave_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="100secs" --registry_strict="true" --roles="role1" --root_submissions="true" --slave_ping_timeout="15secs" --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" --webui_dir="/mesos/mesos-0.29.0/_inst/share/mesos/webui" --work_dir="/tmp/9Zhrjh/master" --zk_session_timeout="10secs"
I0510 09:41:23.191998 2472 master.cpp:434] Master only allowing authenticated frameworks to register
I0510 09:41:23.192013 2472 master.cpp:440] Master only allowing authenticated agents to register
I0510 09:41:23.192025 2472 master.cpp:446] Master only allowing authenticated HTTP frameworks to register
I0510 09:41:23.192042 2472 credentials.hpp:37] Loading credentials for authentication from '/tmp/9Zhrjh/credentials'
I0510 09:41:23.192057 2467 recover.cpp:564] Updating replica status to VOTING
I0510 09:41:23.192454 2472 master.cpp:490] Using default 'crammd5' authenticator
I0510 09:41:23.192657 2472 master.cpp:561] Using default 'basic' HTTP authenticator
I0510 09:41:23.192716 2461 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 403109ns
I0510 09:41:23.192754 2461 replica.cpp:320] Persisted replica status to VOTING
I0510 09:41:23.192865 2472 master.cpp:641] Using default 'basic' HTTP framework authenticator
I0510 09:41:23.192961 2471 recover.cpp:578] Successfully joined the Paxos group
I0510 09:41:23.193048 2472 master.cpp:688] Authorization enabled
W0510 09:41:23.193074 2472 master.cpp:751] The '--roles' flag is deprecated. This flag will be removed in the future. See the Mesos 0.27 upgrade notes for more information
I0510 09:41:23.193361 2471 recover.cpp:462] Recover process terminated
I0510 09:41:23.193382 2468 hierarchical.cpp:142] Initialized hierarchical allocator process
I0510 09:41:23.193390 2461 whitelist_watcher.cpp:77] No whitelist given
I0510 09:41:23.196079 2463 master.cpp:1939] The newly elected leader is master@172.17.0.2:39121 with id 7af97aa5-6c02-420f-a30e-a2c4856e8434
I0510 09:41:23.196132 2463 master.cpp:1952] Elected as the leading master!
I0510 09:41:23.196162 2463 master.cpp:1639] Recovering from registrar
I0510 09:41:23.196388 2468 registrar.cpp:331] Recovering registrar
I0510 09:41:23.197124 2469 log.cpp:524] Attempting to start the writer
I0510 09:41:23.198513 2467 replica.cpp:493] Replica received implicit promise request from (8631)@172.17.0.2:39121 with proposal 1
I0510 09:41:23.199015 2467 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 442027ns
I0510 09:41:23.199046 2467 replica.cpp:342] Persisted promised to 1
I0510 09:41:23.199908 2461 coordinator.cpp:238] Coordinator attempting to fill missing positions
I0510 09:41:23.201360 2460 replica.cpp:388] Replica received explicit promise request from (8632)@172.17.0.2:39121 for position 0 with proposal 2
I0510 09:41:23.201894 2460 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 487445ns
I0510 09:41:23.201925 2460 replica.cpp:712] Persisted action at 0
I0510 09:41:23.203277 2466 replica.cpp:537] Replica received write request for position 0 from (8633)@172.17.0.2:39121
I0510 09:41:23.203352 2466 leveldb.cpp:436] Reading position from leveldb took 33509ns
I0510 09:41:23.203786 2466 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 372610ns
I0510 09:41:23.203817 2466 replica.cpp:712] Persisted action at 0
I0510 09:41:23.204572 2469 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
I0510 09:41:23.204952 2469 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 336570ns
I0510 09:41:23.204993 2469 replica.cpp:712] Persisted action at 0
I0510 09:41:23.205020 2469 replica.cpp:697] Replica learned NOP action at position 0
I0510 09:41:23.205654 2462 log.cpp:540] Writer started with ending position 0
I0510 09:41:23.206887 2463 leveldb.cpp:436] Reading position from leveldb took 36237ns
I0510 09:41:23.207991 2467 registrar.cpp:364] Successfully fetched the registry (0B) in 0ns
I0510 09:41:23.208096 2467 registrar.cpp:463] Applied 1 operations in 20387ns; attempting to update the 'registry'
I0510 09:41:23.209013 2460 log.cpp:548] Attempting to append 170 bytes to the log
I0510 09:41:23.209177 2466 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
I0510 09:41:23.210172 2468 replica.cpp:537] Replica received write request for position 1 from (8634)@172.17.0.2:39121
I0510 09:41:23.210572 2468 leveldb.cpp:341] Persisting action (189 bytes) to leveldb took 351668ns
I0510 09:41:23.210604 2468 replica.cpp:712] Persisted action at 1
I0510 09:41:23.211438 2468 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
I0510 09:41:23.211858 2468 leveldb.cpp:341] Persisting action (191 bytes) to leveldb took 384187ns
I0510 09:41:23.211891 2468 replica.cpp:712] Persisted action at 1
I0510 09:41:23.211913 2468 replica.cpp:697] Replica learned APPEND action at position 1
I0510 09:41:23.213143 2457 registrar.cpp:508] Successfully updated the 'registry' in 0ns
I0510 09:41:23.213343 2471 log.cpp:567] Attempting to truncate the log to 1
I0510 09:41:23.213376 2457 registrar.cpp:394] Successfully recovered registrar
I0510 09:41:23.213493 2470 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
I0510 09:41:23.213958 2465 master.cpp:1747] Recovered 0 agents from the Registry (131B) ; allowing 10mins for agents to re-register
I0510 09:41:23.214123 2462 hierarchical.cpp:169] Skipping recovery of hierarchical allocator: nothing to recover
I0510 09:41:23.214577 2458 replica.cpp:537] Replica received write request for position 2 from (8635)@172.17.0.2:39121
I0510 09:41:23.214943 2458 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 320601ns
I0510 09:41:23.214974 2458 replica.cpp:712] Persisted action at 2
I0510 09:41:23.215728 2463 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
I0510 09:41:23.216220 2463 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 340370ns
I0510 09:41:23.216282 2463 leveldb.cpp:399] Deleting ~1 keys from leveldb took 32060ns
I0510 09:41:23.216306 2463 replica.cpp:712] Persisted action at 2
I0510 09:41:23.216330 2463 replica.cpp:697] Replica learned TRUNCATE action at position 2
I0510 09:41:23.237218 2438 containerizer.cpp:178] Using isolation: posix/cpu,posix/mem,filesystem/posix,network/cni
W0510 09:41:23.238204 2438 backend.cpp:66] Failed to create 'bind' backend: BindBackend requires root privileges
I0510 09:41:23.239930 2438 cluster.cpp:398] Creating default 'local' authorizer
I0510 09:41:23.241643 2468 slave.cpp:204] Agent started on 231)@172.17.0.2:39121
I0510 09:41:23.241668 2468 slave.cpp:205] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="true" --authenticatee="crammd5" --authorizer="local" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/PersistentVolumeEndpointsTest_GoodCreateAndDestroyACL_t2Y1Y1/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" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/PersistentVolumeEndpointsTest_GoodCreateAndDestroyACL_t2Y1Y1/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/PersistentVolumeEndpointsTest_GoodCreateAndDestroyACL_t2Y1Y1/http_credentials" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-0.29.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:1;mem:512;disk(role1):1024" --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/PersistentVolumeEndpointsTest_GoodCreateAndDestroyACL_t2Y1Y1"
I0510 09:41:23.242349 2468 credentials.hpp:86] Loading credential for authentication from '/tmp/PersistentVolumeEndpointsTest_GoodCreateAndDestroyACL_t2Y1Y1/credential'
I0510 09:41:23.242581 2468 slave.cpp:342] Agent using credential for: test-principal
I0510 09:41:23.242627 2468 credentials.hpp:37] Loading credentials for authentication from '/tmp/PersistentVolumeEndpointsTest_GoodCreateAndDestroyACL_t2Y1Y1/http_credentials'
I0510 09:41:23.242939 2468 slave.cpp:394] Using default 'basic' HTTP authenticator
I0510 09:41:23.243356 2468 resources.cpp:572] Parsing resources as JSON failed: cpus:1;mem:512;disk(role1):1024
Trying semicolon-delimited string format instead
I0510 09:41:23.243804 2468 slave.cpp:593] Agent resources: cpus(*):1; mem(*):512; disk(role1):1024; ports(*):[31000-32000]
I0510 09:41:23.243876 2468 slave.cpp:601] Agent attributes: [ ]
I0510 09:41:23.243890 2468 slave.cpp:606] Agent hostname: 2c448d2af3cc
I0510 09:41:23.245787 2467 state.cpp:57] Recovering state from '/tmp/PersistentVolumeEndpointsTest_GoodCreateAndDestroyACL_t2Y1Y1/meta'
I0510 09:41:23.246242 2468 status_update_manager.cpp:200] Recovering status update manager
I0510 09:41:23.246505 2461 containerizer.cpp:444] Recovering containerizer
I0510 09:41:23.248225 2460 provisioner.cpp:245] Provisioner recovery complete
I0510 09:41:23.248802 2463 slave.cpp:4807] Finished recovery
I0510 09:41:23.249313 2463 slave.cpp:4979] Querying resource estimator for oversubscribable resources
I0510 09:41:23.249686 2466 status_update_manager.cpp:174] Pausing sending status updates
I0510 09:41:23.249708 2472 slave.cpp:953] New master detected at master@172.17.0.2:39121
I0510 09:41:23.249734 2472 slave.cpp:965] Delaying registration for 3.406628ms
I0510 09:41:23.249783 2472 slave.cpp:973] Detecting new master
I0510 09:41:23.249912 2472 slave.cpp:4993] Received oversubscribable resources from the resource estimator
Build timed out (after 180 minutes). Marking the build as failed.
Build was aborted