See <https://ci-builds.apache.org/job/Mesos/job/Mesos-Reviewbot-Linux/248/display/redirect>
Changes: ------------------------------------------ [...truncated 13.74 MB...] I0831 20:03:54.414850 5503 registrar.cpp:544] Successfully updated the registry in 744960ns I0831 20:03:54.414978 5503 registrar.cpp:416] Successfully recovered registrar I0831 20:03:54.415668 5518 hierarchical.cpp:676] Skipping recovery of hierarchical allocator: nothing to recover I0831 20:03:54.415678 5514 master.cpp:1819] Recovered 0 agents from the registry (144B); allowing 10mins for agents to reregister W0831 20:03:54.416544 5497 process.cpp:2877] Attempted to spawn already running process [email protected]:33975 I0831 20:03:54.417562 5497 sched.cpp:239] Version: 1.11.0 I0831 20:03:54.418216 5515 sched.cpp:343] New master detected at [email protected]:33975 I0831 20:03:54.418342 5515 sched.cpp:408] Authenticating with master [email protected]:33975 I0831 20:03:54.418365 5515 sched.cpp:415] Using default CRAM-MD5 authenticatee I0831 20:03:54.418704 5505 authenticatee.cpp:121] Creating new client SASL connection I0831 20:03:54.419013 5515 master.cpp:9727] Authenticating [email protected]:33975 I0831 20:03:54.419137 5504 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(282)@172.17.0.2:33975 I0831 20:03:54.419474 5506 authenticator.cpp:98] Creating new server SASL connection I0831 20:03:54.419886 5501 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 I0831 20:03:54.419941 5501 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' I0831 20:03:54.420166 5501 authenticator.cpp:204] Received SASL authentication start I0831 20:03:54.420351 5501 authenticator.cpp:326] Authentication requires more steps I0831 20:03:54.420549 5511 authenticatee.cpp:259] Received SASL authentication step I0831 20:03:54.420734 5511 authenticator.cpp:232] Received SASL authentication step I0831 20:03:54.420783 5511 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '24698f921814' server FQDN: '24698f921814' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0831 20:03:54.420800 5511 auxprop.cpp:181] Looking up auxiliary property '*userPassword' I0831 20:03:54.420871 5511 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0831 20:03:54.420913 5511 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '24698f921814' server FQDN: '24698f921814' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0831 20:03:54.420928 5511 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0831 20:03:54.420940 5511 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0831 20:03:54.420966 5511 authenticator.cpp:318] Authentication success I0831 20:03:54.421125 5517 authenticatee.cpp:299] Authentication success I0831 20:03:54.421259 5521 master.cpp:9759] Successfully authenticated principal 'test-principal' at [email protected]:33975 I0831 20:03:54.421361 5516 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(282)@172.17.0.2:33975 I0831 20:03:54.421738 5520 sched.cpp:520] Successfully authenticated with master [email protected]:33975 I0831 20:03:54.421794 5520 sched.cpp:835] Sending SUBSCRIBE call to [email protected]:33975 I0831 20:03:54.422020 5520 sched.cpp:870] Will retry registration in 347.591949ms if necessary I0831 20:03:54.422293 5498 master.cpp:2931] Refusing subscription of framework 'framework1' at [email protected]:33975: Roles { role1 } are not present in the master's --roles I0831 20:03:54.422612 5498 sched.cpp:1188] Got error 'Roles { role1 } are not present in the master's --roles' I0831 20:03:54.422639 5498 sched.cpp:2200] Asked to abort the driver I0831 20:03:54.422706 5498 sched.cpp:1199] Scheduler::error took 32976ns I0831 20:03:54.422770 5498 sched.cpp:1234] Aborting framework I0831 20:03:54.422788 5498 sched.cpp:1239] Not sending a deactivate message as master is disconnected W0831 20:03:54.423363 5497 process.cpp:2877] Attempted to spawn already running process [email protected]:33975 I0831 20:03:54.424068 5497 sched.cpp:239] Version: 1.11.0 I0831 20:03:54.424713 5511 sched.cpp:343] New master detected at [email protected]:33975 I0831 20:03:54.424896 5511 sched.cpp:408] Authenticating with master [email protected]:33975 I0831 20:03:54.424927 5511 sched.cpp:415] Using default CRAM-MD5 authenticatee I0831 20:03:54.425390 5521 authenticatee.cpp:121] Creating new client SASL connection I0831 20:03:54.425727 5511 master.cpp:9727] Authenticating [email protected]:33975 I0831 20:03:54.425926 5502 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(283)@172.17.0.2:33975 I0831 20:03:54.426290 5517 authenticator.cpp:98] Creating new server SASL connection I0831 20:03:54.426606 5508 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 I0831 20:03:54.426642 5508 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' I0831 20:03:54.426765 5516 authenticator.cpp:204] Received SASL authentication start I0831 20:03:54.426863 5516 authenticator.cpp:326] Authentication requires more steps I0831 20:03:54.426988 5516 authenticatee.cpp:259] Received SASL authentication step I0831 20:03:54.427129 5516 authenticator.cpp:232] Received SASL authentication step I0831 20:03:54.427172 5516 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '24698f921814' server FQDN: '24698f921814' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0831 20:03:54.427204 5516 auxprop.cpp:181] Looking up auxiliary property '*userPassword' I0831 20:03:54.427258 5516 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0831 20:03:54.427305 5516 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '24698f921814' server FQDN: '24698f921814' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0831 20:03:54.427328 5516 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0831 20:03:54.427358 5516 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0831 20:03:54.427395 5516 authenticator.cpp:318] Authentication success I0831 20:03:54.427546 5507 authenticatee.cpp:299] Authentication success I0831 20:03:54.427614 5500 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(283)@172.17.0.2:33975 I0831 20:03:54.427737 5499 master.cpp:9759] Successfully authenticated principal 'test-principal' at [email protected]:33975 I0831 20:03:54.428143 5510 sched.cpp:520] Successfully authenticated with master [email protected]:33975 I0831 20:03:54.428229 5510 sched.cpp:835] Sending SUBSCRIBE call to [email protected]:33975 I0831 20:03:54.428458 5510 sched.cpp:870] Will retry registration in 572.722353ms if necessary I0831 20:03:54.428783 5509 master.cpp:2941] Received SUBSCRIBE call for framework 'framework2' at [email protected]:33975 I0831 20:03:54.432657 5521 master.cpp:3024] Subscribing framework framework2 with checkpointing disabled and capabilities [ MULTI_ROLE, RESERVATION_REFINEMENT ] I0831 20:03:54.435271 5521 master.cpp:9958] Adding framework 780f06d5-c47f-4a34-9f60-35493d75e8bc-0000 (framework2) at [email protected]:33975 with roles { } suppressed I0831 20:03:54.436067 5521 sched.cpp:751] Framework registered with 780f06d5-c47f-4a34-9f60-35493d75e8bc-0000 I0831 20:03:54.436231 5521 sched.cpp:770] Scheduler::registered took 119237ns I0831 20:03:54.437119 5497 sched.cpp:2166] Asked to stop the driver I0831 20:03:54.437435 5499 sched.cpp:1204] Stopping framework 780f06d5-c47f-4a34-9f60-35493d75e8bc-0000 I0831 20:03:54.437901 5498 master.cpp:10323] Processing TEARDOWN call for framework 780f06d5-c47f-4a34-9f60-35493d75e8bc-0000 (framework2) at [email protected]:33975 I0831 20:03:54.437959 5498 master.cpp:10335] Removing framework 780f06d5-c47f-4a34-9f60-35493d75e8bc-0000 (framework2) at [email protected]:33975 I0831 20:03:54.437989 5498 master.cpp:3385] Deactivating framework 780f06d5-c47f-4a34-9f60-35493d75e8bc-0000 (framework2) at [email protected]:33975 I0831 20:03:54.438752 5504 hierarchical.cpp:1859] Allocation paused I0831 20:03:54.438863 5504 hierarchical.cpp:1869] Allocation resumed I0831 20:03:54.439222 5497 sched.cpp:2166] Asked to stop the driver I0831 20:03:54.439450 5502 sched.cpp:1204] Stopping framework I0831 20:03:54.440770 5497 master.cpp:1145] Master terminating [ OK ] MasterAllocatorTest/0.RoleTest (48 ms) [ RUN ] MasterAllocatorTest/0.FrameworkReregistersFirst W0831 20:03:54.449983 5497 process.cpp:2877] Attempted to spawn already running process [email protected]:33975 I0831 20:03:54.453343 5497 cluster.cpp:195] Creating default 'local' authorizer I0831 20:03:54.574106 5497 leveldb.cpp:174] Opened db in 120.347909ms I0831 20:03:54.608428 5497 leveldb.cpp:181] Compacted db in 34.249279ms I0831 20:03:54.608532 5497 leveldb.cpp:196] Created db iterator in 35597ns I0831 20:03:54.608562 5497 leveldb.cpp:202] Seeked to beginning of db in 2730ns I0831 20:03:54.608582 5497 leveldb.cpp:277] Iterated through 0 keys in the db in 767ns I0831 20:03:54.608667 5497 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0831 20:03:54.609752 5509 recover.cpp:437] Starting replica recovery I0831 20:03:54.610215 5514 recover.cpp:468] Replica is in EMPTY status I0831 20:03:54.612102 5510 replica.cpp:677] Replica in EMPTY status received a broadcasted recover request from __req_res__(1060)@172.17.0.2:33975 I0831 20:03:54.613220 5500 recover.cpp:197] Received a recover response from a replica in EMPTY status I0831 20:03:54.614169 5518 recover.cpp:564] Updating replica status to STARTING I0831 20:03:54.616528 5502 master.cpp:448] Master b34a52b5-8838-4ce1-bac7-2d5b1875baf2 (24698f921814) started on 172.17.0.2:33975 I0831 20:03:54.616575 5502 master.cpp:451] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="1secs" --allocator="hierarchical" --authenticate_agents="true" --authenticate_frameworks="true" --authenticate_http_frameworks="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authentication_v0_timeout="15secs" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/yEOZme/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_operator_event_stream_subscribers="1000" --max_unreachable_tasks_per_framework="1000" --memory_profiling="false" --min_allocatable_resources="cpus:0.01|mem:32" --offer_constraints_re2_max_mem="4KB" --offer_constraints_re2_max_program_size="100" --port="5050" --publish_per_framework_metrics="true" --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" --require_agent_domain="false" --role_sorter="drf" --root_submissions="true" --version="false" --webui_dir="/tmp/SRC/build/mesos-1.11.0/_inst/share/mesos/webui" --work_dir="/tmp/yEOZme/master" --zk_session_timeout="10secs" I0831 20:03:54.617175 5502 master.cpp:500] Master only allowing authenticated frameworks to register I0831 20:03:54.617199 5502 master.cpp:506] Master only allowing authenticated agents to register I0831 20:03:54.617215 5502 master.cpp:512] Master only allowing authenticated HTTP frameworks to register I0831 20:03:54.617231 5502 credentials.hpp:37] Loading credentials for authentication from '/tmp/yEOZme/credentials' I0831 20:03:54.617594 5502 master.cpp:556] Using default 'crammd5' authenticator I0831 20:03:54.617849 5502 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly' I0831 20:03:54.618129 5502 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' I0831 20:03:54.618399 5502 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' I0831 20:03:54.618651 5502 master.cpp:637] Authorization enabled I0831 20:03:54.619246 5507 hierarchical.cpp:637] Initialized hierarchical allocator process I0831 20:03:54.619249 5510 whitelist_watcher.cpp:77] No whitelist given I0831 20:03:54.623129 5516 master.cpp:2170] Elected as the leading master! I0831 20:03:54.623203 5516 master.cpp:1666] Recovering from registrar I0831 20:03:54.623461 5503 registrar.cpp:339] Recovering registrar I0831 20:03:54.649173 5501 leveldb.cpp:310] Persisting metadata (8 bytes) to leveldb took 34.70586ms I0831 20:03:54.649215 5501 replica.cpp:322] Persisted replica status to STARTING I0831 20:03:54.649526 5501 recover.cpp:468] Replica is in STARTING status I0831 20:03:54.650766 5505 replica.cpp:677] Replica in STARTING status received a broadcasted recover request from __req_res__(1061)@172.17.0.2:33975 I0831 20:03:54.651363 5508 recover.cpp:197] Received a recover response from a replica in STARTING status I0831 20:03:54.652256 5513 recover.cpp:564] Updating replica status to VOTING I0831 20:03:54.682713 5515 leveldb.cpp:310] Persisting metadata (8 bytes) to leveldb took 30.135694ms I0831 20:03:54.682787 5515 replica.cpp:322] Persisted replica status to VOTING I0831 20:03:54.683086 5518 recover.cpp:578] Successfully joined the Paxos group I0831 20:03:54.683506 5518 recover.cpp:447] Recover process terminated I0831 20:03:54.684574 5516 log.cpp:554] Attempting to start the writer I0831 20:03:54.687110 5517 replica.cpp:497] Replica received implicit promise request from __req_res__(1062)@172.17.0.2:33975 with proposal 1 I0831 20:03:54.716143 5517 leveldb.cpp:310] Persisting metadata (8 bytes) to leveldb took 28.972261ms I0831 20:03:54.716235 5517 replica.cpp:344] Persisted promised to 1 I0831 20:03:54.717502 5510 coordinator.cpp:238] Coordinator attempting to fill missing positions I0831 20:03:54.720105 5501 replica.cpp:391] Replica received explicit promise request from __req_res__(1063)@172.17.0.2:33975 for position 0 with proposal 2 I0831 20:03:54.749588 5501 leveldb.cpp:347] Persisting action (8 bytes) to leveldb took 29.345518ms I0831 20:03:54.749666 5501 replica.cpp:712] Persisted action NOP at position 0 I0831 20:03:54.751619 5508 replica.cpp:541] Replica received write request for position 0 from __req_res__(1064)@172.17.0.2:33975 I0831 20:03:54.751756 5508 leveldb.cpp:460] Reading position from leveldb took 70874ns I0831 20:03:54.783007 5508 leveldb.cpp:347] Persisting action (14 bytes) to leveldb took 31.138807ms I0831 20:03:54.783072 5508 replica.cpp:712] Persisted action NOP at position 0 I0831 20:03:54.784283 5503 replica.cpp:695] Replica received learned notice for position 0 from log-network(52)@172.17.0.2:33975 I0831 20:03:54.816439 5503 leveldb.cpp:347] Persisting action (16 bytes) to leveldb took 32.09028ms I0831 20:03:54.816514 5503 replica.cpp:712] Persisted action NOP at position 0 I0831 20:03:54.817642 5517 log.cpp:570] Writer started with ending position 0 I0831 20:03:54.820439 5511 leveldb.cpp:460] Reading position from leveldb took 55937ns I0831 20:03:54.822717 5508 registrar.cpp:383] Successfully fetched the registry (0B) in 199.1808ms I0831 20:03:54.822952 5508 registrar.cpp:487] Applied 1 operations in 68004ns; attempting to update the registry I0831 20:03:54.824355 5512 log.cpp:578] Attempting to append 183 bytes to the log I0831 20:03:54.824709 5498 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1 I0831 20:03:54.826179 5521 replica.cpp:541] Replica received write request for position 1 from __req_res__(1065)@172.17.0.2:33975 I0831 20:03:54.858228 5521 leveldb.cpp:347] Persisting action (202 bytes) to leveldb took 31.966898ms I0831 20:03:54.858297 5521 replica.cpp:712] Persisted action APPEND at position 1 I0831 20:03:54.859474 5517 replica.cpp:695] Replica received learned notice for position 1 from log-network(52)@172.17.0.2:33975 I0831 20:03:54.891625 5517 leveldb.cpp:347] Persisting action (204 bytes) to leveldb took 32.08312ms I0831 20:03:54.891695 5517 replica.cpp:712] Persisted action APPEND at position 1 I0831 20:03:54.893453 5508 registrar.cpp:544] Successfully updated the registry in 70.398976ms I0831 20:03:54.893726 5499 log.cpp:597] Attempting to truncate the log to 1 I0831 20:03:54.893764 5508 registrar.cpp:416] Successfully recovered registrar I0831 20:03:54.894006 5512 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2 I0831 20:03:54.894582 5499 master.cpp:1819] Recovered 0 agents from the registry (144B); allowing 10mins for agents to reregister I0831 20:03:54.894624 5509 hierarchical.cpp:676] Skipping recovery of hierarchical allocator: nothing to recover I0831 20:03:54.895767 5507 replica.cpp:541] Replica received write request for position 2 from __req_res__(1066)@172.17.0.2:33975 I0831 20:03:54.924993 5507 leveldb.cpp:347] Persisting action (16 bytes) to leveldb took 29.151181ms I0831 20:03:54.925053 5507 replica.cpp:712] Persisted action TRUNCATE at position 2 I0831 20:03:54.926235 5517 replica.cpp:695] Replica received learned notice for position 2 from log-network(52)@172.17.0.2:33975 I0831 20:03:54.966718 5517 leveldb.cpp:347] Persisting action (18 bytes) to leveldb took 40.41144ms I0831 20:03:54.966854 5517 leveldb.cpp:423] Deleting ~1 keys from leveldb took 74062ns I0831 20:03:54.966894 5517 replica.cpp:712] Persisted action TRUNCATE at position 2 W0831 20:03:54.974273 5497 process.cpp:2877] Attempted to spawn already running process [email protected]:33975 I0831 20:03:54.974931 5497 resolver.cpp:69] Creating default secret resolver I0831 20:03:54.975082 5497 cluster.cpp:620] Creating default 'local' authorizer I0831 20:03:54.977512 5504 slave.cpp:281] Mesos agent started on (131)@172.17.0.2:33975 I0831 20:03:54.977563 5504 slave.cpp:282] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://"; --appc_store_dir="/tmp/yEOZme/1G9On8/store/appc" --authenticate_http_readonly="true" --authenticate_http_readwrite="false" --authenticatee="crammd5" --authentication_backoff_factor="1secs" --authentication_timeout_max="1mins" --authentication_timeout_min="5secs" --authorizer="local" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_destroy_timeout="1mins" --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/yEOZme/1G9On8/credential" --default_role="*" --disallow_sharing_agent_ipc_namespace="false" --disallow_sharing_agent_pid_namespace="false" --disk_watch_interval="1mins" --docker="docker" --docker_ignore_runtime="false" --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/yEOZme/1G9On8/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --docker_volume_chown="false" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_reregistration_timeout="2secs" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/yEOZme/1G9On8/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/yEOZme/1G9On8/frameworks" --gc_delay="1weeks" --gc_disk_headroom="0.1" --gc_non_executor_container_sandboxes="false" --help="false" --hostname_lookup="true" --http_command_executor="false" --http_credentials="/tmp/yEOZme/1G9On8/http_credentials" --http_executor_domain_sockets="false" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/tmp/SRC/build/mesos-1.11.0/_build/sub/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --memory_profiling="false" --network_cni_metrics="true" --network_cni_root_dir_persist="false" --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;mem:1024" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/MasterAllocatorTest_0_FrameworkReregistersFirst_Orjxna" --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/MasterAllocatorTest_0_FrameworkReregistersFirst_RM0fnc" --zk_session_timeout="10secs" I0831 20:03:54.978519 5504 credentials.hpp:73] Loading credential for authentication from '/tmp/yEOZme/1G9On8/credential' I0831 20:03:54.978694 5497 sched.cpp:239] Version: 1.11.0 I0831 20:03:54.978801 5504 slave.cpp:314] Agent using credential for: test-principal I0831 20:03:54.978844 5504 credentials.hpp:37] Loading credentials for authentication from '/tmp/yEOZme/1G9On8/http_credentials' I0831 20:03:54.979204 5504 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' I0831 20:03:54.979647 5500 sched.cpp:343] New master detected at [email protected]:33975 I0831 20:03:54.979915 5500 sched.cpp:408] Authenticating with master [email protected]:33975 I0831 20:03:54.979919 5504 disk_profile_adaptor.cpp:78] Creating default disk profile adaptor module I0831 20:03:54.97997Build timed out (after 240 minutes). Marking the build as failed. 1 5500 sched.cpp:415] Using default CRAM-MD5 authenticatee I0831 20:03:54.980543 5501 authenticatee.cpp:121] Creating new client SASL connection I0831 20:03:54.981052 5500 master.cpp:9727] Authenticating [email protected]:33975 I0831 20:03:54.981290 5499 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(284)@172.17.0.2:33975 I0831 20:03:54.981818 5509 authenticator.cpp:98] Creating new server SASL connection I0831 20:03:54.982234 5503 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 I0831 20:03:54.981848 5504 slave.cpp:629] Agent resources: [{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":3748421.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}] I0831 20:03:54.982311 5503 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' I0831 20:03:54.982337 5504 slave.cpp:637] Agent attributes: [ ] I0831 20:03:54.982378 5504 slave.cpp:646] Agent hostname: 24698f921814 I0831 20:03:54.982563 5512 authenticator.cpp:204] Received SASL authentication start I0831 20:03:54.982710 5512 authenticator.cpp:326] Authentication requires more steps I0831 20:03:54.982730 5520 status_update_manager_process.hpp:379] Pausing operation status update manager I0831 20:03:54.982764 5521 task_status_update_manager.cpp:181] Pausing sending task status updates I0831 20:03:54.982913 5521 authenticatee.cpp:259] Received SASL authentication step I0831 20:03:54.983135 5521 authenticator.cpp:232] Received SASL authentication step I0831 20:03:54.983214 5521 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '24698f921814' server FQDN: '24698f921814' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0831 20:03:54.983244 5521 auxprop.cpp:181] Looking up auxiliary property '*userPassword' I0831 20:03:54.983321 5521 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0831 20:03:54.983368 5521 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '24698f921814' server FQDN: '24698f921814' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0831 20:03:54.983394 5521 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0831 20:03:54.983418 5521 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0831 20:03:54.983458 5521 authenticator.cpp:318] Authentication success I0831 20:03:54.983666 5511 authenticatee.cpp:299] Authentication success I0831 20:03:54.983831 5513 master.cpp:9759] Successfully authenticated principal 'test-principal' at [email protected]:33975 I0831 20:03:54.983870 5506 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(284)@172.17.0.2:33975 I0831 20:03:54.984449 5518 sched.cpp:520] Successfully authenticated with master [email protected]:33975 I0831 20:03:54.984499 5518 sched.cpp:835] Sending SUBSCRIBE call to [email protected]:33975 I0831 20:03:54.984766 5518 sched.cpp:870] Will retry registration in 1.151635859secs if necessary I0831 20:03:54.985186 5498 master.cpp:2941] Received SUBSCRIBE call for framework 'default' at [email protected]:33975 I0831 20:03:54.986150 5501 state.cpp:68] Recovering state from '/tmp/MasterAllocatorTest_0_FrameworkReregistersFirst_RM0fnc/meta' I0831 20:03:54.986572 5505 slave.cpp:7741] Finished recovering checkpointed state from '/tmp/MasterAllocatorTest_0_FrameworkReregistersFirst_RM0fnc/meta', beginning agent recovery I0831 20:03:54.987507 5498 task_status_update_manager.cpp:207] Recovering task status update manager I0831 20:03:54.989564 5521 master.cpp:3024] Subscribing framework default with checkpointing disabled and capabilities [ MULTI_ROLE, RESERVATION_REFINEMENT ] I0831 20:03:54.989578 5519 composing.cpp:343] Finished recovering all containerizers I0831 20:03:54.990130 5511 slave.cpp:8223] Recovering executors I0831 20:03:54.990283 5511 slave.cpp:8376] Finished recovery I0831 20:03:54.991129 5511 slave.cpp:1473] New master detected at [email protected]:33975 I0831 20:03:54.991142 5515 task_status_update_manager.cpp:181] Pausing sending task status updates I0831 20:03:54.991194 5501 status_update_manager_process.hpp:379] Pausing operation status update manager I0831 20:03:54.991286 5511 slave.cpp:1538] Detecting new master I0831 20:03:54.991746 5521 master.cpp:9958] Adding framework b34a52b5-8838-4ce1-bac7-2d5b1875baf2-0000 (default) at [email protected]:33975 with roles { } suppressed I0831 20:03:54.992378 5505 sched.cpp:751] Framework registered with b34a52b5-8838-4ce1-bac7-2d5b1875baf2-0000 I0831 20:03:54.992439 5505 sched.cpp:770] Scheduler::registered took 29013ns I0831 20:03:54.992964 5500 hierarchical.cpp:774] Added framework b34a52b5-8838-4ce1-bac7-2d5b1875baf2-0000 I0831 20:03:54.993312 5500 hierarchical.cpp:1935] Performed allocation for 0 agents in 117985ns I0831 20:03:55.001747 5509 slave.cpp:1565] Authenticating with master [email protected]:33975 I0831 20:03:55.001909 5509 slave.cpp:1574] Using default CRAM-MD5 authenticatee I0831 20:03:55.002308 5499 authenticatee.cpp:121] Creating new client SASL connection I0831 20:03:55.002570 5498 master.cpp:9727] Authenticating slave(131)@172.17.0.2:33975 I0831 20:03:55.002735 5516 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(285)@172.17.0.2:33975 I0831 20:03:55.003177 5507 authenticator.cpp:98] Creating new server SASL connection I0831 20:03:55.003501 5512 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 I0831 20:03:55.003530 5512 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' I0831 20:03:55.003638 5512 authenticator.cpp:204] Received SASL authentication start I0831 20:03:55.003692 5512 authenticator.cpp:326] Authentication requires more steps I0831 20:03:55.003796 5512 authenticatee.cpp:259] Received SASL authentication step I0831 20:03:55.003901 5512 authenticator.cpp:232] Received SASL authentication step I0831 20:03:55.003942 5512 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '24698f921814' server FQDN: '24698f921814' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0831 20:03:55.003957 5512 auxprop.cpp:181] Looking up auxiliary property '*userPassword' I0831 20:03:55.003988 5512 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0831 20:03:55.004014 5512 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '24698f921814' server FQDN: '24698f921814' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0831 20:03:55.004029 5512 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0831 20:03:55.004040 5512 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0831 20:03:55.004056 5512 authenticator.cpp:318] Authentication success I0831 20:03:55.004217 5517 authenticatee.cpp:299] Authentication success I0831 20:03:55.004272 5519 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(285)@172.17.0.2:33975 I0831 20:03:55.004277 5502 master.cpp:9759] Successfully authenticated principal 'test-principal' at slave(131)@172.17.0.2:33975 I0831 20:03:55.004894 5518 slave.cpp:1665] Successfully authenticated with master [email protected]:33975 I0831 20:03:55.005725 5518 slave.cpp:2131] Will retry registration in 15.629068ms if necessary I0831 20:03:55.006012 5511 master.cpp:6221] Received register agent message from slave(131)@172.17.0.2:33975 (24698f921814) I0831 20:03:55.006561 5511 master.cpp:3752] Authorizing principal 'test-principal' to perform actionBuild was aborted REGISTER_AGENT on ANY object
