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=ubuntu%3A14.04,label_exp=(ubuntu)&&(!ubuntu-us1)&&(!ubuntu-eu2)&&(!qnode3)&&(!H23)/4521/display/redirect>
------------------------------------------ [...truncated 8.36 MB...] 3: I1130 23:57:17.935838 20061 master.cpp:3878] Authorizing agent with principal 'test-principal' 3: I1130 23:57:17.936296 20068 master.cpp:6104] Authorized registration of agent at slave(196)@172.17.0.2:42523 (b2d4ba8f5c2b) 3: I1130 23:57:17.936473 20068 master.cpp:6197] Registering agent at slave(196)@172.17.0.2:42523 (b2d4ba8f5c2b) with id 0719bcb0-1415-42e6-90ef-788c7bf7bfb3-S0 3: I1130 23:57:17.937196 20063 registrar.cpp:495] Applied 1 operations in 95526ns; attempting to update the registry 3: I1130 23:57:17.937796 20063 registrar.cpp:552] Successfully updated the registry in 541184ns 3: I1130 23:57:17.938026 20066 master.cpp:6246] Admitted agent 0719bcb0-1415-42e6-90ef-788c7bf7bfb3-S0 at slave(196)@172.17.0.2:42523 (b2d4ba8f5c2b) 3: I1130 23:57:17.938951 20079 slave.cpp:1199] Registered with master [email protected]:42523; given agent ID 0719bcb0-1415-42e6-90ef-788c7bf7bfb3-S0 3: I1130 23:57:17.938938 20066 master.cpp:6282] Registered agent 0719bcb0-1415-42e6-90ef-788c7bf7bfb3-S0 at slave(196)@172.17.0.2:42523 (b2d4ba8f5c2b) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] 3: I1130 23:57:17.939052 20072 task_status_update_manager.cpp:188] Resuming sending task status updates 3: I1130 23:57:17.939173 20071 hierarchical.cpp:553] Added agent 0719bcb0-1415-42e6-90ef-788c7bf7bfb3-S0 (b2d4ba8f5c2b) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (allocated: {}) 3: I1130 23:57:17.939275 20079 slave.cpp:1219] Checkpointing SlaveInfo to '/tmp/SlaveTest_HealthCheckUnregisterRace_zvhRIS/meta/slaves/0719bcb0-1415-42e6-90ef-788c7bf7bfb3-S0/slave.info' 3: I1130 23:57:17.939689 20079 slave.cpp:1298] Forwarding total oversubscribed resources {} 3: I1130 23:57:17.939860 20079 master.cpp:7049] Received update of agent 0719bcb0-1415-42e6-90ef-788c7bf7bfb3-S0 at slave(196)@172.17.0.2:42523 (b2d4ba8f5c2b) with total oversubscribed resources {} 3: I1130 23:57:17.940018 20079 master.cpp:7092] Ignoring update on agent 0719bcb0-1415-42e6-90ef-788c7bf7bfb3-S0 at slave(196)@172.17.0.2:42523 (b2d4ba8f5c2b) as it reports no changes 3: I1130 23:57:17.940304 20071 hierarchical.cpp:1431] Performed allocation for 1 agents in 960193ns 3: I1130 23:57:17.940747 20059 master.cpp:8423] Sending 1 offers to framework 0719bcb0-1415-42e6-90ef-788c7bf7bfb3-0000 (default) at [email protected]:42523 3: I1130 23:57:17.941280 20067 sched.cpp:921] Scheduler::resourceOffers took 102285ns 3: I1130 23:57:17.941710 20058 slave.cpp:912] Unregistering and shutting down 3: I1130 23:57:17.941771 20058 slave.cpp:875] Agent terminating 3: I1130 23:57:17.941980 20077 master.cpp:9476] Removing agent 0719bcb0-1415-42e6-90ef-788c7bf7bfb3-S0 at slave(196)@172.17.0.2:42523 (b2d4ba8f5c2b): the agent unregistered 3: I1130 23:57:17.942239 20077 master.cpp:1317] Agent 0719bcb0-1415-42e6-90ef-788c7bf7bfb3-S0 at slave(196)@172.17.0.2:42523 (b2d4ba8f5c2b) disconnected 3: I1130 23:57:17.942273 20077 master.cpp:3376] Disconnecting agent 0719bcb0-1415-42e6-90ef-788c7bf7bfb3-S0 at slave(196)@172.17.0.2:42523 (b2d4ba8f5c2b) 3: I1130 23:57:17.942317 20077 master.cpp:3395] Deactivating agent 0719bcb0-1415-42e6-90ef-788c7bf7bfb3-S0 at slave(196)@172.17.0.2:42523 (b2d4ba8f5c2b) 3: I1130 23:57:17.942379 20082 registrar.cpp:495] Applied 1 operations in 71597ns; attempting to update the registry 3: I1130 23:57:17.942522 20062 hierarchical.cpp:671] Agent 0719bcb0-1415-42e6-90ef-788c7bf7bfb3-S0 deactivated 3: I1130 23:57:17.942886 20077 master.cpp:10374] Removing offer 0719bcb0-1415-42e6-90ef-788c7bf7bfb3-O0 3: I1130 23:57:17.942888 20082 registrar.cpp:552] Successfully updated the registry in 456960ns 3: I1130 23:57:17.942992 20078 sched.cpp:947] Rescinded offer 0719bcb0-1415-42e6-90ef-788c7bf7bfb3-O0 3: I1130 23:57:17.943045 20078 sched.cpp:958] Scheduler::offerRescinded took 17882ns 3: I1130 23:57:17.943058 20077 master.cpp:9518] Removed agent 0719bcb0-1415-42e6-90ef-788c7bf7bfb3-S0 at slave(196)@172.17.0.2:42523 (b2d4ba8f5c2b): the agent unregistered 3: I1130 23:57:17.943325 20077 master.cpp:2138] Notifying framework 0719bcb0-1415-42e6-90ef-788c7bf7bfb3-0000 (default) at [email protected]:42523 of lost agent 0719bcb0-1415-42e6-90ef-788c7bf7bfb3-S0 (b2d4ba8f5c2b) 3: I1130 23:57:17.943513 20080 sched.cpp:1091] Lost agent 0719bcb0-1415-42e6-90ef-788c7bf7bfb3-S0 3: I1130 23:57:17.943568 20080 sched.cpp:1102] Scheduler::slaveLost took 33653ns 3: I1130 23:57:17.943624 20062 hierarchical.cpp:1106] Recovered cpus(allocated: *):2; mem(allocated: *):1024; disk(allocated: *):1024; ports(allocated: *):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000], allocated: {}) on agent 0719bcb0-1415-42e6-90ef-788c7bf7bfb3-S0 from framework 0719bcb0-1415-42e6-90ef-788c7bf7bfb3-0000 3: I1130 23:57:17.944213 20062 hierarchical.cpp:586] Removed agent 0719bcb0-1415-42e6-90ef-788c7bf7bfb3-S0 3: W1130 23:57:17.949100 20071 master.cpp:7839] Unable to mark unknown agent 0719bcb0-1415-42e6-90ef-788c7bf7bfb3-S0 unreachable 3: I1130 23:57:17.949523 20058 sched.cpp:2009] Asked to stop the driver 3: I1130 23:57:17.949648 20067 sched.cpp:1191] Stopping framework 0719bcb0-1415-42e6-90ef-788c7bf7bfb3-0000 3: I1130 23:57:17.949918 20059 master.cpp:9100] Processing TEARDOWN call for framework 0719bcb0-1415-42e6-90ef-788c7bf7bfb3-0000 (default) at [email protected]:42523 3: I1130 23:57:17.949954 20059 master.cpp:9112] Removing framework 0719bcb0-1415-42e6-90ef-788c7bf7bfb3-0000 (default) at [email protected]:42523 3: I1130 23:57:17.949965 20059 master.cpp:3339] Deactivating framework 0719bcb0-1415-42e6-90ef-788c7bf7bfb3-0000 (default) at [email protected]:42523 3: I1130 23:57:17.950089 20072 hierarchical.cpp:406] Deactivated framework 0719bcb0-1415-42e6-90ef-788c7bf7bfb3-0000 3: I1130 23:57:17.950479 20074 hierarchical.cpp:345] Removed framework 0719bcb0-1415-42e6-90ef-788c7bf7bfb3-0000 3: I1130 23:57:17.950943 20058 master.cpp:1159] Master terminating 3: [ OK ] SlaveTest.HealthCheckUnregisterRace (56 ms) 3: [ RUN ] SlaveTest.UnreachableAgentReregisterAfterFailover 3: I1130 23:57:17.956907 20058 cluster.cpp:170] Creating default 'local' authorizer 3: I1130 23:57:17.964632 20058 leveldb.cpp:174] Opened db in 7.314742ms 3: I1130 23:57:17.966578 20058 leveldb.cpp:181] Compacted db in 1.896557ms 3: I1130 23:57:17.966640 20058 leveldb.cpp:196] Created db iterator in 10270ns 3: I1130 23:57:17.966655 20058 leveldb.cpp:202] Seeked to beginning of db in 1893ns 3: I1130 23:57:17.966665 20058 leveldb.cpp:271] Iterated through 0 keys in the db in 706ns 3: I1130 23:57:17.966714 20058 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned 3: I1130 23:57:17.967439 20060 recover.cpp:451] Starting replica recovery 3: I1130 23:57:17.967691 20065 recover.cpp:477] Replica is in EMPTY status 3: I1130 23:57:17.968662 20075 replica.cpp:676] Replica in EMPTY status received a broadcasted recover request from __req_res__(213)@172.17.0.2:42523 3: I1130 23:57:17.969060 20061 recover.cpp:197] Received a recover response from a replica in EMPTY status 3: I1130 23:57:17.969503 20066 recover.cpp:568] Updating replica status to STARTING 3: I1130 23:57:17.970770 20081 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 1.124521ms 3: I1130 23:57:17.970800 20081 replica.cpp:322] Persisted replica status to STARTING 3: I1130 23:57:17.970868 20060 master.cpp:454] Master 753d424e-f8f5-49bd-8ebf-1d599402721a (b2d4ba8f5c2b) started on 172.17.0.2:42523 3: I1130 23:57:17.971170 20071 recover.cpp:477] Replica is in STARTING status 3: I1130 23:57:17.970903 20060 master.cpp:456] 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/tnlOxx/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/tnlOxx/master" --zk_session_timeout="10secs" 3: I1130 23:57:17.971221 20060 master.cpp:505] Master only allowing authenticated frameworks to register 3: I1130 23:57:17.971228 20060 master.cpp:511] Master only allowing authenticated agents to register 3: I1130 23:57:17.971231 20060 master.cpp:517] Master only allowing authenticated HTTP frameworks to register 3: I1130 23:57:17.971235 20060 credentials.hpp:37] Loading credentials for authentication from '/tmp/tnlOxx/credentials' 3: I1130 23:57:17.971493 20060 master.cpp:561] Using default 'crammd5' authenticator 3: I1130 23:57:17.971621 20060 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly' 3: I1130 23:57:17.971751 20060 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' 3: I1130 23:57:17.971868 20060 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' 3: I1130 23:57:17.971978 20060 master.cpp:640] Authorization enabled 3: I1130 23:57:17.972054 20078 replica.cpp:676] Replica in STARTING status received a broadcasted recover request from __req_res__(214)@172.17.0.2:42523 3: I1130 23:57:17.972115 20066 whitelist_watcher.cpp:77] No whitelist given 3: I1130 23:57:17.972128 20061 hierarchical.cpp:173] Initialized hierarchical allocator process 3: I1130 23:57:17.972301 20073 recover.cpp:197] Received a recover response from a replica in STARTING status 3: I1130 23:57:17.972687 20082 recover.cpp:568] Updating replica status to VOTING 3: I1130 23:57:17.973644 20073 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 849060ns 3: I1130 23:57:17.973670 20073 replica.cpp:322] Persisted replica status to VOTING 3: I1130 23:57:17.973816 20072 recover.cpp:582] Successfully joined the Paxos group 3: I1130 23:57:17.974161 20072 recover.cpp:466] Recover process terminated 3: I1130 23:57:17.974581 20060 master.cpp:2221] Elected as the leading master! 3: I1130 23:57:17.974609 20060 master.cpp:1701] Recovering from registrar 3: I1130 23:57:17.974719 20075 registrar.cpp:347] Recovering registrar 3: I1130 23:57:17.975366 20067 log.cpp:536] Attempting to start the writer 3: I1130 23:57:17.976486 20074 replica.cpp:496] Replica received implicit promise request from __req_res__(215)@172.17.0.2:42523 with proposal 1 3: I1130 23:57:17.977349 20074 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 829037ns 3: I1130 23:57:17.977377 20074 replica.cpp:344] Persisted promised to 1 3: I1130 23:57:17.978050 20064 coordinator.cpp:238] Coordinator attempting to fill missing positions 3: I1130 23:57:17.979193 20061 replica.cpp:391] Replica received explicit promise request from __req_res__(216)@172.17.0.2:42523 for position 0 with proposal 2 3: I1130 23:57:17.980432 20061 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 1.18365ms 3: I1130 23:57:17.980479 20061 replica.cpp:711] Persisted action NOP at position 0 3: I1130 23:57:17.981516 20059 replica.cpp:540] Replica received write request for position 0 from __req_res__(217)@172.17.0.2:42523 3: I1130 23:57:17.981573 20059 leveldb.cpp:436] Reading position from leveldb took 25748ns 3: I1130 23:57:17.982559 20059 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 941229ns 3: I1130 23:57:17.982586 20059 replica.cpp:711] Persisted action NOP at position 0 3: I1130 23:57:17.983172 20071 replica.cpp:694] Replica received learned notice for position 0 from log-network(3)@172.17.0.2:42523 3: I1130 23:57:17.984194 20071 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 989930ns 3: I1130 23:57:17.984225 20071 replica.cpp:711] Persisted action NOP at position 0 3: I1130 23:57:17.984678 20079 log.cpp:552] Writer started with ending position 0 3: I1130 23:57:17.986126 20073 leveldb.cpp:436] Reading position from leveldb took 26193ns 3: I1130 23:57:17.987027 20080 registrar.cpp:391] Successfully fetched the registry (0B) in 12.27904ms 3: I1130 23:57:17.987185 20080 registrar.cpp:495] Applied 1 operations in 40047ns; attempting to update the registry 3: I1130 23:57:17.987928 20063 log.cpp:560] Attempting to append 168 bytes to the log 3: I1130 23:57:17.988124 20069 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1 3: I1130 23:57:17.988826 20066 replica.cpp:540] Replica received write request for position 1 from __req_res__(218)@172.17.0.2:42523 3: I1130 23:57:17.990056 20066 leveldb.cpp:341] Persisting action (187 bytes) to leveldb took 1.158527ms 3: I1130 23:57:17.990113 20066 replica.cpp:711] Persisted action APPEND at position 1 3: I1130 23:57:17.990855 20065 replica.cpp:694] Replica received learned notice for position 1 from log-network(3)@172.17.0.2:42523 3: I1130 23:57:17.991956 20065 leveldb.cpp:341] Persisting action (189 bytes) to leveldb took 1.06821ms 3: I1130 23:57:17.991996 20065 replica.cpp:711] Persisted action APPEND at position 1 3: I1130 23:57:17.992748 20068 registrar.cpp:552] Successfully updated the registry in 5.507072ms 3: I1130 23:57:17.992862 20068 registrar.cpp:424] Successfully recovered registrar 3: I1130 23:57:17.992918 20080 log.cpp:579] Attempting to truncate the log to 1 3: I1130 23:57:17.993088 20067 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2 3: I1130 23:57:17.993428 20063 master.cpp:1814] Recovered 0 agents from the registry (129B); allowing 10mins for agents to re-register 3: I1130 23:57:17.993490 20074 hierarchical.cpp:211] Skipping recovery of hierarchical allocator: nothing to recover 3: I1130 23:57:17.993995 20064 replica.cpp:540] Replica received write request for position 2 from __req_res__(219)@172.17.0.2:42523 3: I1130 23:57:17.995028 20064 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 996485ns 3: I1130 23:57:17.995049 20064 replica.cpp:711] Persisted action TRUNCATE at position 2 3: I1130 23:57:17.995695 20076 replica.cpp:694] Replica received learned notice for position 2 from log-network(3)@172.17.0.2:42523 3: I1130 23:57:17.996760 20076 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 1.028819ms 3: I1130 23:57:17.996832 20076 leveldb.cpp:399] Deleting ~1 keys from leveldb took 33653ns 3: I1130 23:57:17.996848 20076 replica.cpp:711] Persisted action TRUNCATE at position 2 3: W1130 23:57:18.002115 20058 process.cpp:2756] Attempted to spawn already running process [email protected]:42523 3: I1130 23:57:18.002967 20058 containerizer.cpp:301] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni } 3: W1130 23:57:18.003453 20058 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges 3: W1130 23:57:18.003554 20058 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges 3: I1130 23:57:18.003583 20058 provisioner.cpp:297] Using default backend 'copy' 3: I1130 23:57:18.005324 20058 cluster.cpp:458] Creating default 'local' authorizer 3: I1130 23:57:18.007601 20068 slave.cpp:253] Mesos agent started on (197)@172.17.0.2:42523 3: I1130 23:57:18.007619 20068 slave.cpp:254] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://"; --appc_store_dir="/tmp/SlaveTest_UnreachableAgentReregisterAfterFailover_trfqhn/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/SlaveTest_UnreachableAgentReregisterAfterFailover_trfqhn/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/SlaveTest_UnreachableAgentReregisterAfterFailover_trfqhn/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/SlaveTest_UnreachableAgentReregisterAfterFailover_trfqhn/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/SlaveTest_UnreachableAgentReregisterAfterFailover_trfqhn/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --jwt_secret_key="/tmp/SlaveTest_UnreachableAgentReregisterAfterFailover_trfqhn/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" --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/SlaveTest_UnreachableAgentReregisterAfterFailover_trfqhn" --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/SlaveTest_UnreachableAgentReregisterAfterFailover_taNBps" --zk_session_timeout="10secs" 3: I1130 23:57:18.007972 20068 credentials.hpp:86] Loading credential for authentication from '/tmp/SlaveTest_UnreachableAgentReregisterAfterFailover_trfqhn/credential' 3: I1130 23:57:18.008108 20068 slave.cpp:286] Agent using credential for: test-principal 3: I1130 23:57:18.008126 20068 credentials.hpp:37] Loading credentials for authentication from '/tmp/SlaveTest_UnreachableAgentReregisterAfterFailover_trfqhn/http_credentials' 3: I1130 23:57:18.008366 20068 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-executor' 3: I1130 23:57:18.008469 20068 http.cpp:1066] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-executor' 3: I1130 23:57:18.008656 20068 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' 3: I1130 23:57:18.008741 20068 http.cpp:1066] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readonly' 3: I1130 23:57:18.009012 20068 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite' 3: I1130 23:57:18.009182 20068 http.cpp:1066] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readwrite' 3: I1130 23:57:18.010781 20068 slave.cpp:585] 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: I1130 23:57:18.011010 20068 slave.cpp:593] Agent attributes: [ ] 3: I1130 23:57:18.011020 20068 slave.cpp:602] Agent hostname: b2d4ba8f5c2b 3: I1130 23:57:18.011216 20078 task_status_update_manager.cpp:181] Pausing sending task status updates 3: I1130 23:57:18.012586 20080 state.cpp:64] Recovering state from '/tmp/SlaveTest_UnreachableAgentReregisterAfterFailover_taNBps/meta' 3: I1130 23:57:18.012879 20076 task_status_update_manager.cpp:207] Recovering task status update manager 3: I1130 23:57:18.013126 20082 containerizer.cpp:668] Recovering containerizer 3: I1130 23:57:18.014781 20064 provisioner.cpp:493] Provisioner recovery complete 3: I1130 23:57:18.015259 20059 slave.cpp:6513] Finished recovery 3: I1130 23:57:18.016227 20075 slave.cpp:999] New master detected at [email protected]:42523 3: I1130 23:57:18.016288 20060 task_status_update_manager.cpp:181] Pausing sending task status updates 3: I1130 23:57:18.016306 20075 slave.cpp:1034] Detecting new master 3: I1130 23:57:18.025615 20077 slave.cpp:1061] Authenticating with master [email protected]:42523 3: I1130 23:57:18.025681 20077 slave.cpp:1070] Using default CRAM-MD5 authenticatee 3: I1130 23:57:18.025926 20062 authenticatee.cpp:121] Creating new client SASL connection 3: I1130 23:57:18.026263 20076 master.cpp:8593] Authenticating slave(197)@172.17.0.2:42523 3: I1130 23:57:18.026437 20063 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(409)@172.17.0.2:42523 3: I1130 23:57:18.026787 20069 authenticator.cpp:98] Creating new server SASL connection 3: I1130 23:57:18.027076 20067 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 3: I1130 23:57:18.027101 20067 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' 3: I1130 23:57:18.027194 20067 authenticator.cpp:204] Received SASL authentication start 3: I1130 23:57:18.027247 20067 authenticator.cpp:326] Authentication requires more steps 3: I1130 23:57:18.027367 20066 authenticatee.cpp:259] Received SASL authentication step 3: I1130 23:57:18.027525 20066 authenticator.cpp:232] Received SASL authentication step 3: I1130 23:57:18.027549 20066 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'b2d4ba8f5c2b' server FQDN: 'b2d4ba8f5c2b' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 3: I1130 23:57:18.027557 20066 auxprop.cpp:181] Looking up auxiliary property '*userPassword' 3: I1130 23:57:18.027606 20066 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' 3: I1130 23:57:18.027621 20066 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'b2d4ba8f5c2b' server FQDN: 'b2d4ba8f5c2b' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 3: I1130 23:57:18.027627 20066 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true 3: I1130 23:57:18.027632 20066 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true 3: I1130 23:57:18.027657 20066 authenticator.cpp:318] Authentication success 3: I1130 23:57:18.027745 20074 authenticatee.cpp:299] Authentication success 3: I1130 23:57:18.027863 20082 master.cpp:8623] Successfully authenticated principal 'test-principal' at slave(197)@172.17.0.2:42523 3: I1130 23:57:18.027901 20061 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(409)@172.17.0.2:42523 3: I1130 23:57:18.028024 20065 slave.cpp:1153] Successfully authenticated with master [email protected]:42523 3: I1130 23:57:18.028240 20065 slave.cpp:1696] Will retry registration in 10.065732ms if necessary 3: I1130 23:57:18.028424 20078 master.cpp:6042] Received register agent message from slave(197)@172.17.0.2:42523 (b2d4ba8f5c2b) 3: I1130 23:57:18.028573 20078 master.cpp:3878] Authorizing agent with principal 'test-principal' 3: I1130 23:57:18.029250 20068 master.cpp:6104] Authorized registration of agent at slave(197)@172.17.0.2:42523 (b2d4ba8f5c2b) 3: I1130 23:57:18.029368 20068 master.cpp:6197] Registering agent at slave(197)@172.17.0.2:42523 (b2d4ba8f5c2b) with id 753d424e-f8f5-49bd-8ebf-1d599402721a-S0 3: I1130 23:57:18.029855 20081 registrar.cpp:495] Applied 1 operations in 66315ns; attempting to update the registry 3: I1130 23:57:18.030856 20080 log.cpp:560] Attempting to append 337 bytes to the log 3: I1130 23:57:18.031021 20077 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3 3: I1130 23:57:18.031802 20069 replica.cpp:540] Replica received write request for position 3 from __req_res__(220)@172.17.0.2:42523 3: I1130 23:57:18.033251 20069 leveldb.cpp:341] Persisting action (356 bytes) to leveldb took 1.386756ms 3: I1130 23:57:18.033308 20069 replica.cpp:711] Persisted action APPEND at position 3 3: I1130 23:57:18.034030 20073 replica.cpp:694] Replica received learned notice for position 3 from log-network(3)@172.17.0.2:42523 3: I1130 23:57:18.035142 20073 leveldb.cpp:341] Persisting action (358 bytes) to leveldb took 1.080964ms 3: I1130 23:57:18.035187 20073 replica.cpp:711] Persisted action APPEND at position 3 3: I1130 23:57:18.036048 20068 registrar.cpp:552] Successfully updated the registry in 6.124032ms 3: I1130 23:57:18.036219 20081 log.cpp:579] Attempting to truncate the log to 3 3: I1130 23:57:18.036279 20078 master.cpp:6246] Admitted agent 753d424e-f8f5-49bd-8ebf-1d599402721a-S0 at slave(197)@172.17.0.2:42523 (b2d4ba8f5c2b) 3: I1130 23:57:18.036417 20080 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4 3: I1130 23:57:18.036995 20078 master.cpp:6282] Registered agent 753d424e-f8f5-49bd-8ebf-1d599402721a-S0 at slave(197)@172.17.0.2:42523 (b2d4ba8f5c2b) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] 3: I1130 23:57:18.037161 20064 replica.cpp:540] Replica received write request for position 4 from __req_res__(221)@172.17.0.2:42523 3: I1130 23:57:18.037434 20067 slave.cpp:1199] Registered with master [email protected]:42523; given agent ID 753d424e-f8f5-49bd-8ebf-1d599402721a-S0 3: I1130 23:57:18.037541 20070 task_status_update_manager.cpp:188] Resuming sending task status updates 3: I1130 23:57:18.037705 20077 hierarchical.cpp:553] Added agent 753d424e-f8f5-49bd-8ebf-1d599402721a-S0 (b2d4ba8f5c2b) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (allocated: {}) 3: I1130 23:57:18.038035 20077 hierarchical.cpp:1431] Performed allocation for 1 agents in 149062ns 3: I1130 23:57:18.038195 20067 slave.cpp:1219] Checkpointing SlaveInfo to '/tmp/SlaveTest_UnreachableAgentReregisterAfterFailover_taNBps/meta/slaves/753d424e-f8f5-49bd-8ebf-1d599402721a-S0/slave.info' 3: I1130 23:57:18.038357 20064 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 1.120194ms 3: I1130 23:57:18.038391 20064 replica.cpp:711] Persisted action TRUNCATE at position 4 3: I1130 23:57:18.038606 20067 slave.cpp:1298] Forwarding total oversubscribed resources {} 3: I1130 23:57:18.038694 20067 slave.cpp:875] Agent terminating 3: I1130 23:57:18.038859 20068 master.cpp:7049] Received update of agent 753d424e-f8f5-49bd-8ebf-1d599402721a-S0 at slave(197)@172.17.0.2:42523 (b2d4ba8f5c2b) with total oversubscribed resources {} 3: I1130 23:57:18.039074 20068 master.cpp:7092] Ignoring update on agent 753d424e-f8f5-49bd-8ebf-1d599402721a-S0 at slave(197)@172.17.0.2:42523 (b2d4ba8f5c2b) as it reports no changes 3: I1130 23:57:18.039124 20076 replica.cpp:694] Replica received learned notice for position 4 from log-network(3)@172.17.0.2:42523 3: I1130 23:57:18.039166 20068 master.cpp:1317] Agent 753d424e-f8f5-49bd-8ebf-1d599402721a-S0 at slave(197)@172.17.0.2:42523 (b2d4ba8f5c2b) disconnected 3: I1130 23:57:18.039189 20068 master.cpp:3376] Disconnecting agent 753d424e-f8f5-49bd-8ebf-1d599402721a-S0 at slave(197)@172.17.0.2:42523 (b2d4ba8f5c2b) 3: I1130 23:57:18.039264 20068 master.cpp:3395] Deactivating agent 753d424e-f8f5-49bd-8ebf-1d599402721a-S0 at slave(197)@172.17.0.2:42523 (b2d4ba8f5c2b) 3: I1130 23:57:18.039386 20070 hierarchical.cpp:671] Agent 753d424e-f8f5-49bd-8ebf-1d599402721a-S0 deactivated 3: I1130 23:57:18.040230 20076 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 1.071869ms 3: I1130 23:57:18.040294 20076 leveldb.cpp:399] Deleting ~2 keys from leveldb took 35729ns 3: I1130 23:57:18.040323 20076 replica.cpp:711] Persisted action TRUNCATE at position 4 3: I1130 23:57:18.045658 20073 hierarchical.cpp:1431] Performed allocation for 1 agents in 91514ns 3: I1130 23:57:18.046461 20064 hierarchical.cpp:1431] Performed allocation for 1 agents in 91749ns 3: I1130 23:57:18.047128 20060 hierarchical.cpp:1431] Performed allocation for 1 agents in 130622ns 3: I1130 23:57:18.047844 20061 hierarchical.cpp:1431] Performed allocation for 1 agents in 100694ns 3: I1130 23:57:18.048640 20075 hierarchical.cpp:1431] Performed allocation for 1 agents in 88654ns 3: I1130 23:57:18.048668 20066 master.cpp:7879] Marking agent 753d424e-f8f5-49bd-8ebf-1d599402721a-S0 at slave(197)@172.17.0.2:42523 (b2d4ba8f5c2b) unreachable: health check timed out 3: I1130 23:57:18.049124 20069 registrar.cpp:495] Applied 1 operations in 125267ns; attempting to update the registry 3: I1130 23:57:18.049808 20076 log.cpp:560] Attempting to append 229 bytes to the log 3: I1130 23:57:18.049948 20082 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 5 3: I1130 23:57:18.050866 20074 replica.cpp:540] Replica received write request for position 5 from __req_res__(222)@172.17.0.2:42523 3: I1130 23:57:18.052175 20074 leveldb.cpp:341] Persisting action (248 bytes) to leveldb took 1.267071ms 3: I1130 23:57:18.052203 20074 replica.cpp:711] Persisted action APPEND at position 5 3: I1130 23:57:18.052839 20072 replica.cpp:694] Replica received learned notice for position 5 from log-network(3)@172.17.0.2:42523 3: I1130 23:57:18.053746 20072 leveldb.cpp:341] Persisting action (250 bytes) to leveldb took 881995ns 3: I1130 23:57:18.053768 20072 replica.cpp:711] Persisted action APPEND at position 5 3: I1130 23:57:18.054456 20075 registrar.cpp:552] Successfully updated the registry in 0ns 3: I1130 23:57:18.054636 20069 log.cpp:579] Attempting to truncate the log to 5 3: I1130 23:57:18.054636 20078 master.cpp:7927] Marked agent 753d424e-f8f5-49bd-8ebf-1d599402721a-S0 at slave(197)@172.17.0.2:42523 (b2d4ba8f5c2b) unreachable: health check timed out 3: I1130 23:57:18.054792 20079 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 6 3: I1130 23:57:18.055326 20076 hierarchical.cpp:586] Removed agent 753d424e-f8f5-49bd-8ebf-1d599402721a-S0 3: I1130 23:57:18.055456 20063 replica.cpp:540] Replica received write request for position 6 from __req_res__(223)@172.17.0.2:42523 3: I1130 23:57:18.056567 20063 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 1.064822ms 3: I1130 23:57:18.056604 20063 replica.cpp:711] Persisted action TRUNCATE at position 6 3: I1130 23:57:18.057252 20071 replica.cpp:694] Replica received learned notice for position 6 from log-network(3)@172.17.0.2:42523 3: I1130 23:57:18.058166 20071 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 889975ns 3: I1130 23:57:18.058223 20071 leveldb.cpp:399] Deleting ~2 keys from leveldb took 39065ns 3: I1130 23:57:18.058236 20071 replica.cpp:711] Persisted action TRUNCATE at position 6 3: I1130 23:57:18.059145 20058 master.cpp:1159] Master terminating 3: I1130 23:57:18.064050 20058 cluster.cpp:170] Creating default 'local' authorizer Build step 'Execute shell' marked build as failure Not sending mail to unregistered user [email protected] Not sending mail to unregistered user [email protected] Not sending mail to unregistered user [email protected] Not sending mail to unregistered user [email protected]
