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 2017/12/13 02:47:13 UTC
Build failed in Jenkins: Mesos-Buildbot » cmake,gcc,--verbose --disable-libtool-wrappers --enable-libevent --enable-ssl,GLOG_v=1 MESOS_VERBOSE=1,centos:7,(ubuntu)&&(!ubuntu-us1)&&(!ubuntu-eu2)&&(!qnode3)&&(!H23) #4589
See <https://builds.apache.org/job/Mesos-Buildbot/BUILDTOOL=cmake,COMPILER=gcc,CONFIGURATION=--verbose%20--disable-libtool-wrappers%20--enable-libevent%20--enable-ssl,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1,OS=centos%3A7,label_exp=(ubuntu)&&(!ubuntu-us1)&&(!ubuntu-eu2)&&(!qnode3)&&(!H23)/4589/display/redirect?page=changes>
Changes:
[yujie.jay] Exposed resource provider information in master 'GET_AGENTS' response.
[bmahler] Moved a comment in the allocator to a more relevant location.
------------------------------------------
[...truncated 16.67 MB...]
3: I1213 02:46:54.703830 18364 log.cpp:536] Attempting to start the writer
3: I1213 02:46:54.706255 18358 replica.cpp:496] Replica received implicit promise request from __req_res__(1131)@172.17.0.5:39646 with proposal 1
3: I1213 02:46:54.707144 18358 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 847853ns
3: I1213 02:46:54.707183 18358 replica.cpp:344] Persisted promised to 1
3: I1213 02:46:54.708317 18366 coordinator.cpp:238] Coordinator attempting to fill missing positions
3: I1213 02:46:54.709885 18359 replica.cpp:391] Replica received explicit promise request from __req_res__(1132)@172.17.0.5:39646 for position 0 with proposal 2
3: I1213 02:46:54.710994 18359 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 1.055913ms
3: I1213 02:46:54.711061 18359 replica.cpp:711] Persisted action NOP at position 0
3: I1213 02:46:54.712656 18373 replica.cpp:540] Replica received write request for position 0 from __req_res__(1133)@172.17.0.5:39646
3: I1213 02:46:54.712770 18373 leveldb.cpp:436] Reading position from leveldb took 58536ns
3: I1213 02:46:54.713784 18373 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 915617ns
3: I1213 02:46:54.713846 18373 replica.cpp:711] Persisted action NOP at position 0
3: I1213 02:46:54.715009 18368 replica.cpp:694] Replica received learned notice for position 0 from log-network(67)@172.17.0.5:39646
3: I1213 02:46:54.716598 18368 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 1.538745ms
3: I1213 02:46:54.716665 18368 replica.cpp:711] Persisted action NOP at position 0
3: I1213 02:46:54.717749 18377 log.cpp:552] Writer started with ending position 0
3: I1213 02:46:54.719776 18366 leveldb.cpp:436] Reading position from leveldb took 40965ns
3: I1213 02:46:54.721726 18361 registrar.cpp:391] Successfully fetched the registry (0B) in 18.988032ms
3: I1213 02:46:54.721930 18361 registrar.cpp:495] Applied 1 operations in 60138ns; attempting to update the registry
3: I1213 02:46:54.723400 18371 log.cpp:560] Attempting to append 174 bytes to the log
3: I1213 02:46:54.723670 18370 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
3: I1213 02:46:54.724843 18356 replica.cpp:540] Replica received write request for position 1 from __req_res__(1134)@172.17.0.5:39646
3: I1213 02:46:54.732333 18356 leveldb.cpp:341] Persisting action (193 bytes) to leveldb took 7.418161ms
3: I1213 02:46:54.732380 18356 replica.cpp:711] Persisted action APPEND at position 1
3: I1213 02:46:54.733345 18358 replica.cpp:694] Replica received learned notice for position 1 from log-network(67)@172.17.0.5:39646
3: I1213 02:46:54.734338 18358 leveldb.cpp:341] Persisting action (195 bytes) to leveldb took 959893ns
3: I1213 02:46:54.734370 18358 replica.cpp:711] Persisted action APPEND at position 1
3: I1213 02:46:54.735743 18373 registrar.cpp:552] Successfully updated the registry in 13.712128ms
3: I1213 02:46:54.735958 18373 registrar.cpp:424] Successfully recovered registrar
3: I1213 02:46:54.736158 18364 log.cpp:579] Attempting to truncate the log to 1
3: I1213 02:46:54.736681 18372 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
3: I1213 02:46:54.736778 18361 master.cpp:1802] Recovered 0 agents from the registry (135B); allowing 10mins for agents to re-register
3: I1213 02:46:54.736848 18363 hierarchical.cpp:213] Skipping recovery of hierarchical allocator: nothing to recover
3: I1213 02:46:54.737653 18367 replica.cpp:540] Replica received write request for position 2 from __req_res__(1135)@172.17.0.5:39646
3: I1213 02:46:54.741482 18367 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 3.766465ms
3: I1213 02:46:54.741539 18367 replica.cpp:711] Persisted action TRUNCATE at position 2
3: I1213 02:46:54.742326 18358 replica.cpp:694] Replica received learned notice for position 2 from log-network(67)@172.17.0.5:39646
3: I1213 02:46:54.743077 18358 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 709826ns
3: I1213 02:46:54.743221 18358 leveldb.cpp:399] Deleting ~1 keys from leveldb took 98us
3: I1213 02:46:54.743263 18358 replica.cpp:711] Persisted action TRUNCATE at position 2
3: W1213 02:46:54.749477 18353 process.cpp:2756] Attempted to spawn already running process files@172.17.0.5:39646
3: I1213 02:46:54.750454 18353 containerizer.cpp:304] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
3: W1213 02:46:54.750941 18353 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
3: W1213 02:46:54.751051 18353 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
3: I1213 02:46:54.751080 18353 provisioner.cpp:299] Using default backend 'copy'
3: I1213 02:46:54.753135 18353 cluster.cpp:460] Creating default 'local' authorizer
3: I1213 02:46:54.755702 18364 slave.cpp:258] Mesos agent started on (412)@172.17.0.5:39646
3: I1213 02:46:54.755718 18364 slave.cpp:259] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/MasterTest_RecoveredSlaves_9naoNt/store/appc" --authenticate_http_executors="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authenticatee="crammd5" --authentication_backoff_factor="1secs" --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/MasterTest_RecoveredSlaves_9naoNt/credential" --default_role="*" --disallow_sharing_agent_pid_namespace="false" --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/MasterTest_RecoveredSlaves_9naoNt/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_reregistration_timeout="2secs" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/MasterTest_RecoveredSlaves_9naoNt/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --http_command_executor="false" --http_credentials="/tmp/MasterTest_RecoveredSlaves_9naoNt/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --jwt_secret_key="/tmp/MasterTest_RecoveredSlaves_9naoNt/jwt_secret_key" --launcher="posix" --launcher_dir="/mesos/build/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns" --quiet="false" --reconfiguration_policy="equal" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/MasterTest_RecoveredSlaves_9naoNt" --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/MasterTest_RecoveredSlaves_qh84Ag" --zk_session_timeout="10secs"
3: I1213 02:46:54.756199 18364 credentials.hpp:86] Loading credential for authentication from '/tmp/MasterTest_RecoveredSlaves_9naoNt/credential'
3: I1213 02:46:54.756487 18364 slave.cpp:291] Agent using credential for: test-principal
3: I1213 02:46:54.756525 18364 credentials.hpp:37] Loading credentials for authentication from '/tmp/MasterTest_RecoveredSlaves_9naoNt/http_credentials'
3: I1213 02:46:54.756919 18364 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-executor'
3: I1213 02:46:54.757046 18364 http.cpp:1066] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-executor'
3: I1213 02:46:54.757262 18364 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
3: I1213 02:46:54.757411 18364 http.cpp:1066] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readonly'
3: I1213 02:46:54.757663 18364 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite'
3: I1213 02:46:54.757766 18364 http.cpp:1066] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readwrite'
3: I1213 02:46:54.759431 18364 slave.cpp:590] Agent resources: [{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
3: I1213 02:46:54.759872 18364 slave.cpp:598] Agent attributes: [ ]
3: I1213 02:46:54.759891 18364 slave.cpp:607] Agent hostname: 9f7ea695d6b4
3: I1213 02:46:54.760226 18375 task_status_update_manager.cpp:181] Pausing sending task status updates
3: I1213 02:46:54.762841 18354 state.cpp:66] Recovering state from '/tmp/MasterTest_RecoveredSlaves_qh84Ag/meta'
3: I1213 02:46:54.763465 18360 task_status_update_manager.cpp:207] Recovering task status update manager
3: I1213 02:46:54.763906 18370 containerizer.cpp:674] Recovering containerizer
3: I1213 02:46:54.765877 18369 provisioner.cpp:495] Provisioner recovery complete
3: I1213 02:46:54.766384 18375 slave.cpp:6747] Finished recovery
3: I1213 02:46:54.767691 18364 slave.cpp:1033] New master detected at master@172.17.0.5:39646
3: I1213 02:46:54.767748 18373 task_status_update_manager.cpp:181] Pausing sending task status updates
3: I1213 02:46:54.767781 18364 slave.cpp:1088] Detecting new master
3: I1213 02:46:54.780441 18371 slave.cpp:1115] Authenticating with master master@172.17.0.5:39646
3: I1213 02:46:54.780597 18371 slave.cpp:1124] Using default CRAM-MD5 authenticatee
3: I1213 02:46:54.781143 18361 authenticatee.cpp:121] Creating new client SASL connection
3: I1213 02:46:54.781613 18361 master.cpp:8932] Authenticating slave(412)@172.17.0.5:39646
3: I1213 02:46:54.781895 18363 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(809)@172.17.0.5:39646
3: I1213 02:46:54.782315 18359 authenticator.cpp:98] Creating new server SASL connection
3: I1213 02:46:54.782599 18376 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
3: I1213 02:46:54.782631 18376 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
3: I1213 02:46:54.782776 18376 authenticator.cpp:204] Received SASL authentication start
3: I1213 02:46:54.782851 18376 authenticator.cpp:326] Authentication requires more steps
3: I1213 02:46:54.782992 18368 authenticatee.cpp:259] Received SASL authentication step
3: I1213 02:46:54.783125 18377 authenticator.cpp:232] Received SASL authentication step
3: I1213 02:46:54.783188 18377 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '9f7ea695d6b4' server FQDN: '9f7ea695d6b4' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
3: I1213 02:46:54.783202 18377 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
3: I1213 02:46:54.783260 18377 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
3: I1213 02:46:54.783283 18377 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '9f7ea695d6b4' server FQDN: '9f7ea695d6b4' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
3: I1213 02:46:54.783291 18377 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
3: I1213 02:46:54.783298 18377 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
3: I1213 02:46:54.783310 18377 authenticator.cpp:318] Authentication success
3: I1213 02:46:54.783412 18370 authenticatee.cpp:299] Authentication success
3: I1213 02:46:54.783478 18372 master.cpp:8962] Successfully authenticated principal 'test-principal' at slave(412)@172.17.0.5:39646
3: I1213 02:46:54.783560 18357 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(809)@172.17.0.5:39646
3: I1213 02:46:54.783756 18370 slave.cpp:1207] Successfully authenticated with master master@172.17.0.5:39646
3: I1213 02:46:54.783955 18370 slave.cpp:1684] Will retry registration in 8.664741ms if necessary
3: I1213 02:46:54.784096 18369 master.cpp:6077] Received register agent message from slave(412)@172.17.0.5:39646 (9f7ea695d6b4)
3: I1213 02:46:54.784171 18369 master.cpp:3866] Authorizing agent with principal 'test-principal'
3: I1213 02:46:54.785004 18365 master.cpp:6147] Authorized registration of agent at slave(412)@172.17.0.5:39646 (9f7ea695d6b4)
3: I1213 02:46:54.785189 18365 master.cpp:6240] Registering agent at slave(412)@172.17.0.5:39646 (9f7ea695d6b4) with id 4eaa8736-d2ab-43e4-bebf-9b18c8138d50-S0
3: I1213 02:46:54.786118 18362 registrar.cpp:495] Applied 1 operations in 164553ns; attempting to update the registry
3: I1213 02:46:54.787333 18354 log.cpp:560] Attempting to append 343 bytes to the log
3: I1213 02:46:54.787652 18371 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3
3: I1213 02:46:54.788702 18368 replica.cpp:540] Replica received write request for position 3 from __req_res__(1136)@172.17.0.5:39646
3: I1213 02:46:54.790060 18368 leveldb.cpp:341] Persisting action (362 bytes) to leveldb took 1.268566ms
3: I1213 02:46:54.790130 18368 replica.cpp:711] Persisted action APPEND at position 3
3: I1213 02:46:54.791245 18358 replica.cpp:694] Replica received learned notice for position 3 from log-network(67)@172.17.0.5:39646
3: I1213 02:46:54.792286 18358 leveldb.cpp:341] Persisting action (364 bytes) to leveldb took 973687ns
3: I1213 02:46:54.792340 18358 replica.cpp:711] Persisted action APPEND at position 3
3: I1213 02:46:54.793653 18364 registrar.cpp:552] Successfully updated the registry in 7.44704ms
3: I1213 02:46:54.793907 18364 log.cpp:579] Attempting to truncate the log to 3
3: I1213 02:46:54.793915 18373 master.cpp:6288] Admitted agent 4eaa8736-d2ab-43e4-bebf-9b18c8138d50-S0 at slave(412)@172.17.0.5:39646 (9f7ea695d6b4)
3: I1213 02:46:54.794049 18360 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4
3: I1213 02:46:54.794781 18359 replica.cpp:540] Replica received write request for position 4 from __req_res__(1137)@172.17.0.5:39646
3: I1213 02:46:54.794996 18373 master.cpp:6337] Registered agent 4eaa8736-d2ab-43e4-bebf-9b18c8138d50-S0 at slave(412)@172.17.0.5:39646 (9f7ea695d6b4) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
3: I1213 02:46:54.795400 18355 slave.cpp:1253] Registered with master master@172.17.0.5:39646; given agent ID 4eaa8736-d2ab-43e4-bebf-9b18c8138d50-S0
3: I1213 02:46:54.795400 18357 hierarchical.cpp:574] Added agent 4eaa8736-d2ab-43e4-bebf-9b18c8138d50-S0 (9f7ea695d6b4) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (allocated: {})
3: I1213 02:46:54.795631 18369 task_status_update_manager.cpp:188] Resuming sending task status updates
3: I1213 02:46:54.795727 18357 hierarchical.cpp:1517] Performed allocation for 1 agents in 158187ns
3: I1213 02:46:54.795892 18354 master.cpp:1147] Master terminating
3: I1213 02:46:54.795892 18355 slave.cpp:1273] Checkpointing SlaveInfo to '/tmp/MasterTest_RecoveredSlaves_qh84Ag/meta/slaves/4eaa8736-d2ab-43e4-bebf-9b18c8138d50-S0/slave.info'
3: I1213 02:46:54.796578 18375 hierarchical.cpp:609] Removed agent 4eaa8736-d2ab-43e4-bebf-9b18c8138d50-S0
3: I1213 02:46:54.796787 18355 slave.cpp:1330] Forwarding agent update {"offer_operations":{},"resource_categories":{"oversubscribed":true},"resource_version_uuid":"bTmTXa1aRpOAIdMN0A3QTw==","slave_id":{"value":"4eaa8736-d2ab-43e4-bebf-9b18c8138d50-S0"}}
3: I1213 02:46:54.797021 18355 slave.cpp:5370] Got exited event for master@172.17.0.5:39646
3: W1213 02:46:54.797053 18355 slave.cpp:5375] Master disconnected! Waiting for a new master to be elected
3: I1213 02:46:54.800067 18359 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 5.201627ms
3: I1213 02:46:54.800122 18359 replica.cpp:711] Persisted action TRUNCATE at position 4
3: I1213 02:46:54.802736 18353 slave.cpp:909] Agent terminating
3: I1213 02:46:54.813612 18353 cluster.cpp:172] Creating default 'local' authorizer
3: I1213 02:46:54.820142 18353 leveldb.cpp:174] Opened db in 6.221717ms
3: I1213 02:46:54.824069 18353 leveldb.cpp:181] Compacted db in 3.868033ms
3: I1213 02:46:54.824136 18353 leveldb.cpp:196] Created db iterator in 13626ns
3: I1213 02:46:54.824184 18353 leveldb.cpp:202] Seeked to beginning of db in 32737ns
3: I1213 02:46:54.824371 18353 leveldb.cpp:271] Iterated through 5 keys in the db in 170195ns
3: I1213 02:46:54.824473 18353 replica.cpp:779] Replica recovered with log positions 1 -> 4 with 0 holes and 1 unlearned
3: I1213 02:46:54.825361 18354 recover.cpp:451] Starting replica recovery
3: I1213 02:46:54.825739 18361 recover.cpp:477] Replica is in VOTING status
3: I1213 02:46:54.825940 18361 recover.cpp:466] Recover process terminated
3: I1213 02:46:54.829239 18374 master.cpp:456] Master 8ab130e5-eac6-430b-bd49-b23339f1fccd (9f7ea695d6b4) started on 172.17.0.5:39646
3: I1213 02:46:54.829260 18374 master.cpp:458] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate_agents="true" --authenticate_frameworks="true" --authenticate_http_frameworks="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/pVoNo3/credentials" --filter_gpu_resources="true" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_framework_authenticators="basic" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --max_unreachable_tasks_per_framework="1000" --port="5050" --quiet="false" --recovery_agent_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_gc_interval="15mins" --registry_max_agent_age="2weeks" --registry_max_agent_count="102400" --registry_store_timeout="100secs" --registry_strict="false" --root_submissions="true" --user_sorter="drf" --version="false" --webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/pVoNo3/master" --zk_session_timeout="10secs"
3: I1213 02:46:54.829612 18374 master.cpp:507] Master only allowing authenticated frameworks to register
3: I1213 02:46:54.829619 18374 master.cpp:513] Master only allowing authenticated agents to register
3: I1213 02:46:54.829624 18374 master.cpp:519] Master only allowing authenticated HTTP frameworks to register
3: I1213 02:46:54.829630 18374 credentials.hpp:37] Loading credentials for authentication from '/tmp/pVoNo3/credentials'
3: I1213 02:46:54.829910 18374 master.cpp:563] Using default 'crammd5' authenticator
3: I1213 02:46:54.830065 18374 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
3: I1213 02:46:54.830219 18374 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
3: I1213 02:46:54.830358 18374 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
3: I1213 02:46:54.830499 18374 master.cpp:642] Authorization enabled
3: I1213 02:46:54.830688 18373 hierarchical.cpp:175] Initialized hierarchical allocator process
3: I1213 02:46:54.830723 18354 whitelist_watcher.cpp:77] No whitelist given
3: I1213 02:46:54.833438 18369 master.cpp:2209] Elected as the leading master!
3: I1213 02:46:54.833462 18369 master.cpp:1689] Recovering from registrar
3: I1213 02:46:54.833611 18363 registrar.cpp:347] Recovering registrar
3: I1213 02:46:54.834199 18369 log.cpp:536] Attempting to start the writer
3: I1213 02:46:54.835561 18371 replica.cpp:496] Replica received implicit promise request from __req_res__(1138)@172.17.0.5:39646 with proposal 2
3: I1213 02:46:54.836686 18371 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 1.072512ms
3: I1213 02:46:54.836760 18371 replica.cpp:344] Persisted promised to 2
3: I1213 02:46:54.837635 18373 coordinator.cpp:238] Coordinator attempting to fill missing positions
3: I1213 02:46:54.839129 18364 replica.cpp:391] Replica received explicit promise request from __req_res__(1139)@172.17.0.5:39646 for position 4 with proposal 3
3: I1213 02:46:54.839251 18364 leveldb.cpp:436] Reading position from leveldb took 66486ns
3: I1213 02:46:54.840131 18364 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 811051ns
3: I1213 02:46:54.840183 18364 replica.cpp:711] Persisted action TRUNCATE at position 4
3: I1213 02:46:54.841570 18377 replica.cpp:540] Replica received write request for position 4 from __req_res__(1140)@172.17.0.5:39646
3: I1213 02:46:54.841686 18377 leveldb.cpp:436] Reading position from leveldb took 61984ns
3: I1213 02:46:54.842617 18377 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 847985ns
3: I1213 02:46:54.842663 18377 replica.cpp:711] Persisted action TRUNCATE at position 4
3: I1213 02:46:54.843585 18369 replica.cpp:694] Replica received learned notice for position 4 from log-network(68)@172.17.0.5:39646
3: I1213 02:46:54.844512 18369 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 880515ns
3: I1213 02:46:54.844595 18369 leveldb.cpp:399] Deleting ~2 keys from leveldb took 50446ns
3: I1213 02:46:54.844633 18369 replica.cpp:711] Persisted action TRUNCATE at position 4
3: I1213 02:46:54.845443 18362 log.cpp:552] Writer started with ending position 4
3: I1213 02:46:54.847085 18376 leveldb.cpp:436] Reading position from leveldb took 44321ns
3: I1213 02:46:54.847167 18376 leveldb.cpp:436] Reading position from leveldb took 19065ns
3: I1213 02:46:54.849081 18372 registrar.cpp:391] Successfully fetched the registry (304B) in 15.410176ms
3: I1213 02:46:54.849285 18372 registrar.cpp:495] Applied 1 operations in 73949ns; attempting to update the registry
3: I1213 02:46:54.850347 18366 log.cpp:560] Attempting to append 343 bytes to the log
3: I1213 02:46:54.850589 18357 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 5
3: I1213 02:46:54.851833 18355 replica.cpp:540] Replica received write request for position 5 from __req_res__(1141)@172.17.0.5:39646
3: I1213 02:46:54.854887 18355 leveldb.cpp:341] Persisting action (362 bytes) to leveldb took 2.983882ms
3: I1213 02:46:54.854915 18355 replica.cpp:711] Persisted action APPEND at position 5
3: I1213 02:46:54.855597 18356 replica.cpp:694] Replica received learned notice for position 5 from log-network(68)@172.17.0.5:39646
3: I1213 02:46:54.856240 18356 leveldb.cpp:341] Persisting action (364 bytes) to leveldb took 611407ns
3: I1213 02:46:54.856262 18356 replica.cpp:711] Persisted action APPEND at position 5
3: I1213 02:46:54.857326 18361 registrar.cpp:552] Successfully updated the registry in 7.98208ms
3: I1213 02:46:54.857486 18361 registrar.cpp:424] Successfully recovered registrar
3: I1213 02:46:54.857542 18372 log.cpp:579] Attempting to truncate the log to 5
3: I1213 02:46:54.857677 18365 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 6
3: I1213 02:46:54.858239 18370 hierarchical.cpp:213] Skipping recovery of hierarchical allocator: nothing to recover
3: I1213 02:46:54.858249 18366 master.cpp:1802] Recovered 1 agents from the registry (304B); allowing 10mins for agents to re-register
3: I1213 02:46:54.858427 18355 replica.cpp:540] Replica received write request for position 6 from __req_res__(1142)@172.17.0.5:39646
3: I1213 02:46:54.858990 18355 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 530678ns
3: I1213 02:46:54.859014 18355 replica.cpp:711] Persisted action TRUNCATE at position 6
3: I1213 02:46:54.859611 18377 replica.cpp:694] Replica received learned notice for position 6 from log-network(68)@172.17.0.5:39646
3: I1213 02:46:54.860165 18377 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 527850ns
3: I1213 02:46:54.860219 18377 leveldb.cpp:399] Deleting ~2 keys from leveldb took 33489ns
3: I1213 02:46:54.860235 18377 replica.cpp:711] Persisted action TRUNCATE at position 6
3: I1213 02:46:54.863693 18364 process.cpp:3503] Handling HTTP event for process 'master' with path: '/master/state'
3: I1213 02:46:54.865633 18370 http.cpp:1185] HTTP GET for /master/state from 172.17.0.5:56672
3: I1213 02:46:54.872738 18362 process.cpp:3503] Handling HTTP event for process 'master' with path: '/master/slaves'
3: I1213 02:46:54.874698 18376 http.cpp:1185] HTTP GET for /master/slaves from 172.17.0.5:56674
3: W1213 02:46:54.881222 18353 process.cpp:2756] Attempted to spawn already running process files@172.17.0.5:39646
3: I1213 02:46:54.882128 18353 containerizer.cpp:304] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
3: W1213 02:46:54.882578 18353 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
3: W1213 02:46:54.882688 18353 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
3: I1213 02:46:54.882716 18353 provisioner.cpp:299] Using default backend 'copy'
3: I1213 02:46:54.884706 18353 cluster.cpp:460] Creating default 'local' authorizer
3: I1213 02:46:54.887009 18374 slave.cpp:258] Mesos agent started on (413)@172.17.0.5:39646
3: I1213 02:46:54.887029 18374 slave.cpp:259] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/MasterTest_RecoveredSlaves_9naoNt/store/appc" --authenticate_http_executors="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authenticatee="crammd5" --authentication_backoff_factor="1secs" --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/MasterTest_RecoveredSlaves_9naoNt/credential" --default_role="*" --disallow_sharing_agent_pid_namespace="false" --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/MasterTest_RecoveredSlaves_9naoNt/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_reregistration_timeout="2secs" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/MasterTest_RecoveredSlaves_9naoNt/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --http_command_executor="false" --http_credentials="/tmp/MasterTest_RecoveredSlaves_9naoNt/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --jwt_secret_key="/tmp/MasterTest_RecoveredSlaves_9naoNt/jwt_secret_key" --launcher="posix" --launcher_dir="/mesos/build/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns" --quiet="false" --reconfiguration_policy="equal" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/MasterTest_RecoveredSlaves_9naoNt" --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/MasterTest_RecoveredSlaves_qh84Ag" --zk_session_timeout="10secs"
3: I1213 02:46:54.887466 18374 credentials.hpp:86] Loading credential for authentication from '/tmp/MasterTest_RecoveredSlaves_9naoNt/credential'
3: I1213 02:46:54.887624 18374 slave.cpp:291] Agent using credential for: test-principal
3: I1213 02:46:54.887648 18374 credentials.hpp:37] Loading credentials for authentication from '/tmp/MasterTest_RecoveredSlaves_9naoNt/http_credentials'
3: I1213 02:46:54.887961 18374 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-executor'
3: I1213 02:46:54.888085 18374 http.cpp:1066] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-executor'
3: I1213 02:46:54.888316 18374 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
3: I1213 02:46:54.888413 18374 http.cpp:1066] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readonly'
3: I1213 02:46:54.888604 18374 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite'
3: I1213 02:46:54.888697 18374 http.cpp:1066] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readwrite'
3: I1213 02:46:54.890228 18374 slave.cpp:590] Agent resources: [{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
3: I1213 02:46:54.890458 18374 slave.cpp:598] Agent attributes: [ ]
3: I1213 02:46:54.890468 18374 slave.cpp:607] Agent hostname: 9f7ea695d6b4
3: I1213 02:46:54.890626 18372 task_status_update_manager.cpp:181] Pausing sending task status updates
3: I1213 02:46:54.892236 18371 state.cpp:66] Recovering state from '/tmp/MasterTest_RecoveredSlaves_qh84Ag/meta'
3: I1213 02:46:54.892305 18371 state.cpp:724] No committed checkpointed resources found at '/tmp/MasterTest_RecoveredSlaves_qh84Ag/meta/resources/resources.info'
3: I1213 02:46:54.893848 18369 task_status_update_manager.cpp:207] Recovering task status update manager
3: I1213 02:46:54.894177 18355 containerizer.cpp:674] Recovering containerizer
3: I1213 02:46:54.896648 18361 provisioner.cpp:495] Provisioner recovery complete
3: I1213 02:46:54.897182 18372 slave.cpp:6747] Finished recovery
3: I1213 02:46:54.898077 18375 task_status_update_manager.cpp:181] Pausing sending task status updates
3: I1213 02:46:54.898075 18364 slave.cpp:1033] New master detected at master@172.17.0.5:39646
3: I1213 02:46:54.898181 18364 slave.cpp:1088] Detecting new master
3: I1213 02:46:54.900580 18362 slave.cpp:1115] Authenticating with master master@172.17.0.5:39646
3: I1213 02:46:54.900704 18362 slave.cpp:1124] Using default CRAM-MD5 authenticatee
3: I1213 02:46:54.901100 18359 authenticatee.cpp:121] Creating new client SASL connection
3: I1213 02:46:54.901401 18369 master.cpp:8932] Authenticating slave(413)@172.17.0.5:39646
3: I1213 02:46:54.901618 18354 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(810)@172.17.0.5:39646
3: I1213 02:46:54.901971 18356 authenticator.cpp:98] Creating new server SASL connection
3: I1213 02:46:54.902221 18370 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
3: I1213 02:46:54.902246 18370 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
3: I1213 02:46:54.902362 18370 authenticator.cpp:204] Received SASL authentication start
3: I1213 02:46:54.902426 18370 authenticator.cpp:326] Authentication requires more steps
3: I1213 02:46:54.902549 18355 authenticatee.cpp:259] Received SASL authentication step
3: I1213 02:46:54.902670 18355 authenticator.cpp:232] Received SASL authentication step
3: I1213 02:46:54.902704 18355 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '9f7ea695d6b4' server FQDN: '9f7ea695d6b4' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
3: I1213 02:46:54.902721 18355 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
write /dev/stdout: resource temporarily unavailable
+ docker rmi mesos-1513130807-9318
Error response from daemon: conflict: unable to remove repository reference "mesos-1513130807-9318" (must force) - container 9f7ea695d6b4 is using its referenced image 9f4a28031e70
Build step 'Execute shell' marked build as failure
Not sending mail to unregistered user xujyan@apple.com
Not sending mail to unregistered user gregorywmann@gmail.com
Not sending mail to unregistered user yujie.jay@gmail.com
Jenkins build is back to normal : Mesos-Buildbot » cmake,gcc,--verbose --disable-libtool-wrappers --enable-libevent --enable-ssl,GLOG_v=1 MESOS_VERBOSE=1,centos:7,(ubuntu)&&(!ubuntu-us1)&&(!ubuntu-eu2)&&(!qnode3)&&(!H23) #4590
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Mesos-Buildbot/BUILDTOOL=cmake,COMPILER=gcc,CONFIGURATION=--verbose%20--disable-libtool-wrappers%20--enable-libevent%20--enable-ssl,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1,OS=centos%3A7,label_exp=(ubuntu)&&(!ubuntu-us1)&&(!ubuntu-eu2)&&(!qnode3)&&(!H23)/4590/display/redirect>