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 14:40:02 UTC
Build failed in Jenkins: mesos-reviewbot #12987
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
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