You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Greg Mann (JIRA)" <ji...@apache.org> on 2017/12/14 01:02:18 UTC
[jira] [Created] (MESOS-8333)
'PartitionTest.PartitionedSlaveReregistrationMasterFailover' is flaky
Greg Mann created MESOS-8333:
--------------------------------
Summary: 'PartitionTest.PartitionedSlaveReregistrationMasterFailover' is flaky
Key: MESOS-8333
URL: https://issues.apache.org/jira/browse/MESOS-8333
Project: Mesos
Issue Type: Bug
Components: test
Environment: {{../configure --enable-libevent --enable-ssl --enable-grpc}}
Reporter: Greg Mann
Observed on a recent test run on CentOS 7:
{code}
[ RUN ] PartitionTest.PartitionedSlaveReregistrationMasterFailover
I1213 17:00:05.837646 22366 cluster.cpp:172] Creating default 'local' authorizer
I1213 17:00:05.841521 22366 leveldb.cpp:174] Opened db in 3.594509ms
I1213 17:00:05.843317 22366 leveldb.cpp:181] Compacted db in 1.747033ms
I1213 17:00:05.843387 22366 leveldb.cpp:196] Created db iterator in 11318ns
I1213 17:00:05.843406 22366 leveldb.cpp:202] Seeked to beginning of db in 1747ns
I1213 17:00:05.843418 22366 leveldb.cpp:271] Iterated through 0 keys in the db in 438ns
I1213 17:00:05.843449 22366 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I1213 17:00:05.843945 22408 recover.cpp:451] Starting replica recovery
I1213 17:00:05.844269 22387 recover.cpp:477] Replica is in EMPTY status
I1213 17:00:05.845278 22417 replica.cpp:676] Replica in EMPTY status received a broadcasted recover request from __req_res__(23)@10.0.49.2:32874
I1213 17:00:05.845712 22384 recover.cpp:197] Received a recover response from a replica in EMPTY status
I1213 17:00:05.846271 22410 recover.cpp:568] Updating replica status to STARTING
I1213 17:00:05.847220 22414 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 757907ns
I1213 17:00:05.847277 22414 replica.cpp:322] Persisted replica status to STARTING
I1213 17:00:05.847569 22386 recover.cpp:477] Replica is in STARTING status
I1213 17:00:05.848453 22381 replica.cpp:676] Replica in STARTING status received a broadcasted recover request from __req_res__(24)@10.0.49.2:32874
I1213 17:00:05.848922 22427 recover.cpp:197] Received a recover response from a replica in STARTING status
I1213 17:00:05.849398 22412 recover.cpp:568] Updating replica status to VOTING
I1213 17:00:05.850281 22395 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 639730ns
I1213 17:00:05.850342 22395 replica.cpp:322] Persisted replica status to VOTING
I1213 17:00:05.850487 22391 recover.cpp:582] Successfully joined the Paxos group
I1213 17:00:05.850738 22391 recover.cpp:466] Recover process terminated
I1213 17:00:05.851450 22424 master.cpp:456] Master ccc06cbb-4a30-40ac-bfb2-220c5af2000d (core-dev) started on 10.0.49.2:32874
I1213 17:00:05.851496 22424 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/9d3p85/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/9d3p85/master" --zk_session_timeout="10secs"
I1213 17:00:05.851819 22424 master.cpp:507] Master only allowing authenticated frameworks to register
I1213 17:00:05.851841 22424 master.cpp:513] Master only allowing authenticated agents to register
I1213 17:00:05.851862 22424 master.cpp:519] Master only allowing authenticated HTTP frameworks to register
I1213 17:00:05.851881 22424 credentials.hpp:37] Loading credentials for authentication from '/tmp/9d3p85/credentials'
I1213 17:00:05.852226 22424 master.cpp:563] Using default 'crammd5' authenticator
I1213 17:00:05.852416 22424 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
I1213 17:00:05.852610 22424 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
I1213 17:00:05.852782 22424 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
I1213 17:00:05.852939 22424 master.cpp:642] Authorization enabled
I1213 17:00:05.853150 22387 hierarchical.cpp:175] Initialized hierarchical allocator process
I1213 17:00:05.853186 22380 whitelist_watcher.cpp:77] No whitelist given
I1213 17:00:05.856180 22394 master.cpp:2209] Elected as the leading master!
I1213 17:00:05.856257 22394 master.cpp:1689] Recovering from registrar
I1213 17:00:05.856468 22382 registrar.cpp:347] Recovering registrar
I1213 17:00:05.857106 22416 log.cpp:536] Attempting to start the writer
I1213 17:00:05.858768 22397 replica.cpp:496] Replica received implicit promise request from __req_res__(25)@10.0.49.2:32874 with proposal 1
I1213 17:00:05.859405 22397 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 581018ns
I1213 17:00:05.859446 22397 replica.cpp:344] Persisted promised to 1
I1213 17:00:05.860158 22400 coordinator.cpp:238] Coordinator attempting to fill missing positions
I1213 17:00:05.861610 22393 replica.cpp:391] Replica received explicit promise request from __req_res__(26)@10.0.49.2:32874 for position 0 with proposal 2
I1213 17:00:05.862282 22393 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 607326ns
I1213 17:00:05.862326 22393 replica.cpp:711] Persisted action NOP at position 0
I1213 17:00:05.863505 22417 replica.cpp:540] Replica received write request for position 0 from __req_res__(27)@10.0.49.2:32874
I1213 17:00:05.863590 22417 leveldb.cpp:436] Reading position from leveldb took 28917ns
I1213 17:00:05.864250 22417 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 608644ns
I1213 17:00:05.864292 22417 replica.cpp:711] Persisted action NOP at position 0
I1213 17:00:05.864977 22385 replica.cpp:694] Replica received learned notice for position 0 from log-network(3)@10.0.49.2:32874
I1213 17:00:05.865675 22385 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 633591ns
I1213 17:00:05.865720 22385 replica.cpp:711] Persisted action NOP at position 0
I1213 17:00:05.866323 22386 log.cpp:552] Writer started with ending position 0
I1213 17:00:05.867748 22392 leveldb.cpp:436] Reading position from leveldb took 35537ns
I1213 17:00:05.870522 22391 registrar.cpp:391] Successfully fetched the registry (0B) in 0ns
I1213 17:00:05.870645 22391 registrar.cpp:495] Applied 1 operations in 23818ns; attempting to update the registry
I1213 17:00:05.873178 22422 log.cpp:560] Attempting to append 161 bytes to the log
I1213 17:00:05.873366 22390 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
I1213 17:00:05.874300 22408 replica.cpp:540] Replica received write request for position 1 from __req_res__(28)@10.0.49.2:32874
I1213 17:00:05.875053 22408 leveldb.cpp:341] Persisting action (180 bytes) to leveldb took 624700ns
I1213 17:00:05.875098 22408 replica.cpp:711] Persisted action APPEND at position 1
I1213 17:00:05.875810 22387 replica.cpp:694] Replica received learned notice for position 1 from log-network(3)@10.0.49.2:32874
I1213 17:00:05.876462 22387 leveldb.cpp:341] Persisting action (182 bytes) to leveldb took 605420ns
I1213 17:00:05.876502 22387 replica.cpp:711] Persisted action APPEND at position 1
I1213 17:00:05.877425 22409 registrar.cpp:552] Successfully updated the registry in 0ns
I1213 17:00:05.877602 22409 registrar.cpp:424] Successfully recovered registrar
I1213 17:00:05.877667 22416 log.cpp:579] Attempting to truncate the log to 1
I1213 17:00:05.877872 22394 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
I1213 17:00:05.878166 22384 master.cpp:1802] Recovered 0 agents from the registry (123B); allowing 10mins for agents to re-register
I1213 17:00:05.878198 22394 hierarchical.cpp:213] Skipping recovery of hierarchical allocator: nothing to recover
I1213 17:00:05.878684 22407 replica.cpp:540] Replica received write request for position 2 from __req_res__(29)@10.0.49.2:32874
I1213 17:00:05.879348 22407 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 606343ns
I1213 17:00:05.879385 22407 replica.cpp:711] Persisted action TRUNCATE at position 2
I1213 17:00:05.880113 22406 replica.cpp:694] Replica received learned notice for position 2 from log-network(3)@10.0.49.2:32874
I1213 17:00:05.880795 22406 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 617263ns
I1213 17:00:05.880867 22406 leveldb.cpp:399] Deleting ~1 keys from leveldb took 30278ns
I1213 17:00:05.880978 22406 replica.cpp:711] Persisted action TRUNCATE at position 2
W1213 17:00:05.890133 22366 process.cpp:2756] Attempted to spawn already running process files@10.0.49.2:32874
I1213 17:00:05.890990 22366 containerizer.cpp:304] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
W1213 17:00:05.891352 22366 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges
W1213 17:00:05.891449 22366 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
I1213 17:00:05.891544 22366 provisioner.cpp:299] Using default backend 'copy'
I1213 17:00:05.892994 22366 cluster.cpp:460] Creating default 'local' authorizer
I1213 17:00:05.894520 22413 slave.cpp:258] Mesos agent started on (3)@10.0.49.2:32874
W1213 17:00:05.894878 22366 process.cpp:2756] Attempted to spawn already running process version@10.0.49.2:32874
I1213 17:00:05.894563 22413 slave.cpp:259] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/PartitionTest_PartitionedSlaveReregistrationMasterFailover_5bD0h3/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/PartitionTest_PartitionedSlaveReregistrationMasterFailover_5bD0h3/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/PartitionTest_PartitionedSlaveReregistrationMasterFailover_5bD0h3/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/PartitionTest_PartitionedSlaveReregistrationMasterFailover_5bD0h3/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/PartitionTest_PartitionedSlaveReregistrationMasterFailover_5bD0h3/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --jwt_secret_key="/tmp/PartitionTest_PartitionedSlaveReregistrationMasterFailover_5bD0h3/jwt_secret_key" --launcher="posix" --launcher_dir="/home/gmann/src/mesos2/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;mem:1024" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/PartitionTest_PartitionedSlaveReregistrationMasterFailover_5bD0h3" --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/PartitionTest_PartitionedSlaveReregistrationMasterFailover_RhNcIz" --zk_session_timeout="10secs"
I1213 17:00:05.894978 22413 credentials.hpp:86] Loading credential for authentication from '/tmp/PartitionTest_PartitionedSlaveReregistrationMasterFailover_5bD0h3/credential'
I1213 17:00:05.895151 22413 slave.cpp:291] Agent using credential for: test-principal
I1213 17:00:05.895256 22413 credentials.hpp:37] Loading credentials for authentication from '/tmp/PartitionTest_PartitionedSlaveReregistrationMasterFailover_5bD0h3/http_credentials'
I1213 17:00:05.895594 22413 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-executor'
I1213 17:00:05.895756 22413 http.cpp:1066] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-executor'
I1213 17:00:05.896013 22413 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
I1213 17:00:05.896157 22413 http.cpp:1066] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readonly'
I1213 17:00:05.896406 22413 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite'
I1213 17:00:05.896548 22413 http.cpp:1066] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readwrite'
I1213 17:00:05.902539 22366 sched.cpp:232] Version: 1.5.0
I1213 17:00:05.903090 22392 hierarchical.cpp:1517] Performed allocation for 0 agents in 37604ns
I1213 17:00:05.903158 22406 sched.cpp:336] New master detected at master@10.0.49.2:32874
I1213 17:00:05.903333 22406 sched.cpp:396] Authenticating with master master@10.0.49.2:32874
I1213 17:00:05.903370 22406 sched.cpp:403] Using default CRAM-MD5 authenticatee
I1213 17:00:05.903616 22400 authenticatee.cpp:121] Creating new client SASL connection
I1213 17:00:05.903409 22413 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":46053.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
I1213 17:00:05.903817 22413 slave.cpp:598] Agent attributes: [ ]
I1213 17:00:05.903861 22413 slave.cpp:607] Agent hostname: core-dev
I1213 17:00:05.904040 22395 task_status_update_manager.cpp:181] Pausing sending task status updates
I1213 17:00:05.905781 22422 state.cpp:66] Recovering state from '/tmp/PartitionTest_PartitionedSlaveReregistrationMasterFailover_RhNcIz/meta'
I1213 17:00:05.906124 22411 task_status_update_manager.cpp:207] Recovering task status update manager
I1213 17:00:05.906376 22390 containerizer.cpp:674] Recovering containerizer
I1213 17:00:05.908172 22418 provisioner.cpp:495] Provisioner recovery complete
I1213 17:00:05.908671 22382 slave.cpp:6724] Finished recovery
I1213 17:00:05.909543 22387 slave.cpp:1033] New master detected at master@10.0.49.2:32874
I1213 17:00:05.909569 22399 task_status_update_manager.cpp:181] Pausing sending task status updates
I1213 17:00:05.909636 22387 slave.cpp:1088] Detecting new master
I1213 17:00:05.909773 22387 slave.cpp:1115] Authenticating with master master@10.0.49.2:32874
I1213 17:00:05.909889 22387 slave.cpp:1124] Using default CRAM-MD5 authenticatee
I1213 17:00:05.910130 22410 authenticatee.cpp:121] Creating new client SASL connection
I1213 17:00:05.918442 22384 master.cpp:8920] Authenticating slave(3)@10.0.49.2:32874
I1213 17:00:05.918633 22394 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(14)@10.0.49.2:32874
I1213 17:00:05.918967 22385 authenticator.cpp:98] Creating new server SASL connection
I1213 17:00:05.929447 22388 master.cpp:8920] Authenticating scheduler-7f8c2474-49a2-4ba7-8c60-d9c4ba8bf11d@10.0.49.2:32874
I1213 17:00:05.929680 22402 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(13)@10.0.49.2:32874
I1213 17:00:05.930012 22415 authenticator.cpp:98] Creating new server SASL connection
I1213 17:00:05.944811 22383 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I1213 17:00:05.944864 22383 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I1213 17:00:05.945052 22407 authenticator.cpp:204] Received SASL authentication start
I1213 17:00:05.945152 22407 authenticator.cpp:326] Authentication requires more steps
I1213 17:00:05.945310 22381 authenticatee.cpp:259] Received SASL authentication step
I1213 17:00:05.945472 22381 authenticator.cpp:232] Received SASL authentication step
I1213 17:00:05.945520 22381 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'core-dev' server FQDN: 'core-dev' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1213 17:00:05.945552 22381 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I1213 17:00:05.945588 22381 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1213 17:00:05.945650 22381 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'core-dev' server FQDN: 'core-dev' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1213 17:00:05.945675 22381 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1213 17:00:05.945693 22381 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1213 17:00:05.945734 22381 authenticator.cpp:318] Authentication success
I1213 17:00:05.945870 22397 authenticatee.cpp:299] Authentication success
I1213 17:00:05.945955 22405 master.cpp:8950] Successfully authenticated principal 'test-principal' at slave(3)@10.0.49.2:32874
I1213 17:00:05.945993 22421 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(14)@10.0.49.2:32874
I1213 17:00:05.946123 22397 slave.cpp:1207] Successfully authenticated with master master@10.0.49.2:32874
I1213 17:00:05.946324 22397 slave.cpp:1684] Will retry registration in 6.983579ms if necessary
I1213 17:00:05.946447 22427 master.cpp:6077] Received register agent message from slave(3)@10.0.49.2:32874 (core-dev)
I1213 17:00:05.946533 22427 master.cpp:3866] Authorizing agent with principal 'test-principal'
I1213 17:00:05.946969 22413 master.cpp:6147] Authorized registration of agent at slave(3)@10.0.49.2:32874 (core-dev)
I1213 17:00:05.947079 22413 master.cpp:6240] Registering agent at slave(3)@10.0.49.2:32874 (core-dev) with id ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0
I1213 17:00:05.947576 22419 registrar.cpp:495] Applied 1 operations in 87230ns; attempting to update the registry
I1213 17:00:05.950042 22411 log.cpp:560] Attempting to append 327 bytes to the log
I1213 17:00:05.950218 22423 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3
I1213 17:00:05.950996 22423 replica.cpp:540] Replica received write request for position 3 from __req_res__(30)@10.0.49.2:32874
I1213 17:00:05.951720 22423 leveldb.cpp:341] Persisting action (346 bytes) to leveldb took 666327ns
I1213 17:00:05.951771 22423 replica.cpp:711] Persisted action APPEND at position 3
I1213 17:00:05.952435 22417 replica.cpp:694] Replica received learned notice for position 3 from log-network(3)@10.0.49.2:32874
I1213 17:00:05.953096 22417 leveldb.cpp:341] Persisting action (348 bytes) to leveldb took 606828ns
I1213 17:00:05.953142 22417 replica.cpp:711] Persisted action APPEND at position 3
I1213 17:00:05.953980 22414 registrar.cpp:552] Successfully updated the registry in 0ns
I1213 17:00:05.954150 22410 master.cpp:6288] Admitted agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0 at slave(3)@10.0.49.2:32874 (core-dev)
I1213 17:00:05.954233 22384 log.cpp:579] Attempting to truncate the log to 3
I1213 17:00:05.954423 22394 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4
I1213 17:00:05.954843 22400 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I1213 17:00:05.954823 22410 master.cpp:6337] Registered agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0 at slave(3)@10.0.49.2:32874 (core-dev) with cpus:2; mem:1024; disk:46053; ports:[31000-32000]
I1213 17:00:05.954921 22385 slave.cpp:1253] Registered with master master@10.0.49.2:32874; given agent ID ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0
I1213 17:00:05.954890 22400 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I1213 17:00:05.955058 22410 task_status_update_manager.cpp:188] Resuming sending task status updates
I1213 17:00:05.955112 22405 authenticator.cpp:204] Received SASL authentication start
I1213 17:00:05.955111 22407 hierarchical.cpp:574] Added agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0 (core-dev) with cpus:2; mem:1024; disk:46053; ports:[31000-32000] (allocated: {})
I1213 17:00:05.955195 22405 authenticator.cpp:326] Authentication requires more steps
I1213 17:00:05.955324 22395 authenticatee.cpp:259] Received SASL authentication step
I1213 17:00:05.955358 22385 slave.cpp:1273] Checkpointing SlaveInfo to '/tmp/PartitionTest_PartitionedSlaveReregistrationMasterFailover_RhNcIz/meta/slaves/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0/slave.info'
I1213 17:00:05.955379 22421 replica.cpp:540] Replica received write request for position 4 from __req_res__(31)@10.0.49.2:32874
I1213 17:00:05.955448 22407 hierarchical.cpp:1517] Performed allocation for 1 agents in 99510ns
I1213 17:00:05.955474 22397 authenticator.cpp:232] Received SASL authentication step
I1213 17:00:05.955529 22397 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'core-dev' server FQDN: 'core-dev' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1213 17:00:05.955559 22397 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I1213 17:00:05.955593 22397 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1213 17:00:05.955624 22397 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'core-dev' server FQDN: 'core-dev' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1213 17:00:05.955648 22397 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1213 17:00:05.955668 22397 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1213 17:00:05.955696 22397 authenticator.cpp:318] Authentication success
I1213 17:00:05.955857 22391 authenticatee.cpp:299] Authentication success
I1213 17:00:05.955873 22427 master.cpp:8950] Successfully authenticated principal 'test-principal' at scheduler-7f8c2474-49a2-4ba7-8c60-d9c4ba8bf11d@10.0.49.2:32874
I1213 17:00:05.955862 22385 slave.cpp:1330] Forwarding agent update {"offer_operations":{},"resource_categories":{"oversubscribed":true},"resource_version_uuid":"o2oDVhaeRHORqRv0HXgh+w==","slave_id":{"value":"ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0"}}
I1213 17:00:05.955914 22413 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(13)@10.0.49.2:32874
I1213 17:00:05.956046 22421 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 609936ns
I1213 17:00:05.956138 22419 sched.cpp:502] Successfully authenticated with master master@10.0.49.2:32874
I1213 17:00:05.956182 22421 replica.cpp:711] Persisted action TRUNCATE at position 4
I1213 17:00:05.956202 22419 sched.cpp:824] Sending SUBSCRIBE call to master@10.0.49.2:32874
I1213 17:00:05.956229 22411 master.cpp:7270] Received update of agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0 at slave(3)@10.0.49.2:32874 (core-dev) with total oversubscribed resources {}
I1213 17:00:05.956352 22419 sched.cpp:857] Will retry registration in 982.336937ms if necessary
I1213 17:00:05.956444 22411 master.cpp:7368] Ignoring update on agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0 at slave(3)@10.0.49.2:32874 (core-dev) as it reports no changes
I1213 17:00:05.956684 22411 master.cpp:2957] Received SUBSCRIBE call for framework 'default' at scheduler-7f8c2474-49a2-4ba7-8c60-d9c4ba8bf11d@10.0.49.2:32874
I1213 17:00:05.956779 22411 master.cpp:2274] Authorizing framework principal 'test-principal' to receive offers for roles '{ * }'
I1213 17:00:05.956782 22389 replica.cpp:694] Replica received learned notice for position 4 from log-network(3)@10.0.49.2:32874
I1213 17:00:05.957263 22426 master.cpp:3037] Subscribing framework default with checkpointing disabled and capabilities [ MULTI_ROLE, RESERVATION_REFINEMENT ]
I1213 17:00:05.957378 22389 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 535295ns
I1213 17:00:05.957435 22426 master.cpp:9141] Adding framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000 (default) at scheduler-7f8c2474-49a2-4ba7-8c60-d9c4ba8bf11d@10.0.49.2:32874 with roles { } suppressed
I1213 17:00:05.957530 22389 leveldb.cpp:399] Deleting ~2 keys from leveldb took 53210ns
I1213 17:00:05.957568 22389 replica.cpp:711] Persisted action TRUNCATE at position 4
I1213 17:00:05.957885 22409 sched.cpp:751] Framework registered with ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000
I1213 17:00:05.957948 22409 sched.cpp:765] Scheduler::registered took 24484ns
I1213 17:00:05.957993 22418 hierarchical.cpp:297] Added framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000
I1213 17:00:05.959031 22418 hierarchical.cpp:1517] Performed allocation for 1 agents in 831695ns
I1213 17:00:05.959424 22416 master.cpp:8750] Sending 1 offers to framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000 (default) at scheduler-7f8c2474-49a2-4ba7-8c60-d9c4ba8bf11d@10.0.49.2:32874
I1213 17:00:05.959959 22414 sched.cpp:921] Scheduler::resourceOffers took 91232ns
I1213 17:00:05.961392 22402 master.cpp:10671] Removing offer ccc06cbb-4a30-40ac-bfb2-220c5af2000d-O0
I1213 17:00:05.961510 22402 master.cpp:4273] Processing ACCEPT call for offers: [ ccc06cbb-4a30-40ac-bfb2-220c5af2000d-O0 ] on agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0 at slave(3)@10.0.49.2:32874 (core-dev) for framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000 (default) at scheduler-7f8c2474-49a2-4ba7-8c60-d9c4ba8bf11d@10.0.49.2:32874
I1213 17:00:05.961649 22402 master.cpp:3593] Authorizing framework principal 'test-principal' to launch task 634be9c9-b19a-4cf7-a9e6-d093b2590638
I1213 17:00:05.963029 22386 master.cpp:11426] Adding task 634be9c9-b19a-4cf7-a9e6-d093b2590638 with resources cpus(allocated: *):1; mem(allocated: *):512 on agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0 at slave(3)@10.0.49.2:32874 (core-dev)
I1213 17:00:05.963277 22386 master.cpp:5024] Launching task 634be9c9-b19a-4cf7-a9e6-d093b2590638 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000 (default) at scheduler-7f8c2474-49a2-4ba7-8c60-d9c4ba8bf11d@10.0.49.2:32874 with resources [{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":1.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":512.0},"type":"SCALAR"}] on agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0 at slave(3)@10.0.49.2:32874 (core-dev)
I1213 17:00:05.964076 22392 slave.cpp:1807] Got assigned task '634be9c9-b19a-4cf7-a9e6-d093b2590638' for framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000
I1213 17:00:05.964452 22415 hierarchical.cpp:1192] Recovered cpus(allocated: *):1; mem(allocated: *):512; disk(allocated: *):46053; ports(allocated: *):[31000-32000] (total: cpus:2; mem:1024; disk:46053; ports:[31000-32000], allocated: cpus(allocated: *):1; mem(allocated: *):512) on agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0 from framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000
I1213 17:00:05.964541 22415 hierarchical.cpp:1238] Framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000 filtered agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0 for 5secs
I1213 17:00:05.964629 22392 slave.cpp:2077] Authorizing task '634be9c9-b19a-4cf7-a9e6-d093b2590638' for framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000
I1213 17:00:05.964704 22392 slave.cpp:7732] Authorizing framework principal 'test-principal' to launch task 634be9c9-b19a-4cf7-a9e6-d093b2590638
I1213 17:00:05.965556 22381 slave.cpp:2471] Launching task '634be9c9-b19a-4cf7-a9e6-d093b2590638' for framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000
I1213 17:00:05.967726 22381 paths.cpp:702] Trying to chown '/tmp/PartitionTest_PartitionedSlaveReregistrationMasterFailover_RhNcIz/slaves/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0/frameworks/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000/executors/634be9c9-b19a-4cf7-a9e6-d093b2590638/runs/e7599e9a-0ec3-44bd-b5f9-909c985525db' to user 'gmann'
I1213 17:00:05.967936 22381 slave.cpp:8206] Launching executor '634be9c9-b19a-4cf7-a9e6-d093b2590638' of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000 with resources [{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":32.0},"type":"SCALAR"}] in work directory '/tmp/PartitionTest_PartitionedSlaveReregistrationMasterFailover_RhNcIz/slaves/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0/frameworks/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000/executors/634be9c9-b19a-4cf7-a9e6-d093b2590638/runs/e7599e9a-0ec3-44bd-b5f9-909c985525db'
I1213 17:00:05.968773 22381 slave.cpp:2557] Queued task '634be9c9-b19a-4cf7-a9e6-d093b2590638' for executor '634be9c9-b19a-4cf7-a9e6-d093b2590638' of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000
I1213 17:00:05.968878 22381 slave.cpp:984] Successfully attached '/tmp/PartitionTest_PartitionedSlaveReregistrationMasterFailover_RhNcIz/slaves/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0/frameworks/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000/executors/634be9c9-b19a-4cf7-a9e6-d093b2590638/runs/e7599e9a-0ec3-44bd-b5f9-909c985525db' to virtual path '/tmp/PartitionTest_PartitionedSlaveReregistrationMasterFailover_RhNcIz/slaves/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0/frameworks/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000/executors/634be9c9-b19a-4cf7-a9e6-d093b2590638/runs/latest'
I1213 17:00:05.968950 22381 slave.cpp:984] Successfully attached '/tmp/PartitionTest_PartitionedSlaveReregistrationMasterFailover_RhNcIz/slaves/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0/frameworks/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000/executors/634be9c9-b19a-4cf7-a9e6-d093b2590638/runs/e7599e9a-0ec3-44bd-b5f9-909c985525db' to virtual path '/frameworks/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000/executors/634be9c9-b19a-4cf7-a9e6-d093b2590638/runs/latest'
I1213 17:00:05.969229 22381 slave.cpp:3023] Launching container e7599e9a-0ec3-44bd-b5f9-909c985525db for executor '634be9c9-b19a-4cf7-a9e6-d093b2590638' of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000
I1213 17:00:05.969620 22381 slave.cpp:984] Successfully attached '/tmp/PartitionTest_PartitionedSlaveReregistrationMasterFailover_RhNcIz/slaves/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0/frameworks/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000/executors/634be9c9-b19a-4cf7-a9e6-d093b2590638/runs/e7599e9a-0ec3-44bd-b5f9-909c985525db' to virtual path '/tmp/PartitionTest_PartitionedSlaveReregistrationMasterFailover_RhNcIz/slaves/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0/frameworks/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000/executors/634be9c9-b19a-4cf7-a9e6-d093b2590638/runs/e7599e9a-0ec3-44bd-b5f9-909c985525db'
I1213 17:00:05.969960 22407 containerizer.cpp:1201] Starting container e7599e9a-0ec3-44bd-b5f9-909c985525db
I1213 17:00:05.970614 22407 containerizer.cpp:1373] Checkpointed ContainerConfig at '/tmp/PartitionTest_PartitionedSlaveReregistrationMasterFailover_5bD0h3/containers/e7599e9a-0ec3-44bd-b5f9-909c985525db/config'
I1213 17:00:05.970656 22407 containerizer.cpp:2930] Transitioning the state of container e7599e9a-0ec3-44bd-b5f9-909c985525db from PROVISIONING to PREPARING
I1213 17:00:05.974361 22403 containerizer.cpp:1842] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"arguments":["mesos-executor","--launcher_dir=\/home\/gmann\/src\/mesos2\/build\/src"],"shell":false,"value":"\/home\/gmann\/src\/mesos2\/build\/src\/mesos-executor"},"environment":{"variables":[{"name":"LIBPROCESS_PORT","type":"VALUE","value":"0"},{"name":"MESOS_AGENT_ENDPOINT","type":"VALUE","value":"10.0.49.2:32874"},{"name":"MESOS_CHECKPOINT","type":"VALUE","value":"0"},{"name":"MESOS_DIRECTORY","type":"VALUE","value":"\/tmp\/PartitionTest_PartitionedSlaveReregistrationMasterFailover_RhNcIz\/slaves\/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0\/frameworks\/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000\/executors\/634be9c9-b19a-4cf7-a9e6-d093b2590638\/runs\/e7599e9a-0ec3-44bd-b5f9-909c985525db"},{"name":"MESOS_EXECUTOR_AUTHENTICATION_TOKEN","type":"VALUE","value":"eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJjaWQiOiJlNzU5OWU5YS0wZWMzLTQ0YmQtYjVmOS05MDljOTg1NTI1ZGIiLCJlaWQiOiI2MzRiZTljOS1iMTlhLTRjZjctYTllNi1kMDkzYjI1OTA2MzgiLCJmaWQiOiJjY2MwNmNiYi00YTMwLTQwYWMtYmZiMi0yMjBjNWFmMjAwMGQtMDAwMCJ9.OpwRk0XWkt4j73zGMg8a20GvNnKxS9rfGGMmiykkYU4"},{"name":"MESOS_EXECUTOR_ID","type":"VALUE","value":"634be9c9-b19a-4cf7-a9e6-d093b2590638"},{"name":"MESOS_EXECUTOR_SHUTDOWN_GRACE_PERIOD","type":"VALUE","value":"5secs"},{"name":"MESOS_FRAMEWORK_ID","type":"VALUE","value":"ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000"},{"name":"MESOS_HTTP_COMMAND_EXECUTOR","type":"VALUE","value":"0"},{"name":"MESOS_SLAVE_ID","type":"VALUE","value":"ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0"},{"name":"MESOS_SLAVE_PID","type":"VALUE","value":"slave(3)@10.0.49.2:32874"},{"name":"MESOS_SANDBOX","type":"VALUE","value":"\/tmp\/PartitionTest_PartitionedSlaveReregistrationMasterFailover_RhNcIz\/slaves\/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0\/frameworks\/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000\/executors\/634be9c9-b19a-4cf7-a9e6-d093b2590638\/runs\/e7599e9a-0ec3-44bd-b5f9-909c985525db"}]},"task_environment":{},"user":"gmann","working_directory":"\/tmp\/PartitionTest_PartitionedSlaveReregistrationMasterFailover_RhNcIz\/slaves\/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0\/frameworks\/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000\/executors\/634be9c9-b19a-4cf7-a9e6-d093b2590638\/runs\/e7599e9a-0ec3-44bd-b5f9-909c985525db"}" --pipe_read="9" --pipe_write="12" --runtime_directory="/tmp/PartitionTest_PartitionedSlaveReregistrationMasterFailover_5bD0h3/containers/e7599e9a-0ec3-44bd-b5f9-909c985525db" --unshare_namespace_mnt="false"'
I1213 17:00:05.977418 22403 launcher.cpp:140] Forked child with pid '22828' for container 'e7599e9a-0ec3-44bd-b5f9-909c985525db'
I1213 17:00:05.977951 22403 containerizer.cpp:2930] Transitioning the state of container e7599e9a-0ec3-44bd-b5f9-909c985525db from PREPARING to ISOLATING
I1213 17:00:05.979351 22411 containerizer.cpp:2930] Transitioning the state of container e7599e9a-0ec3-44bd-b5f9-909c985525db from ISOLATING to FETCHING
I1213 17:00:05.979573 22426 fetcher.cpp:369] Starting to fetch URIs for container: e7599e9a-0ec3-44bd-b5f9-909c985525db, directory: /tmp/PartitionTest_PartitionedSlaveReregistrationMasterFailover_RhNcIz/slaves/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0/frameworks/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000/executors/634be9c9-b19a-4cf7-a9e6-d093b2590638/runs/e7599e9a-0ec3-44bd-b5f9-909c985525db
I1213 17:00:05.980710 22389 containerizer.cpp:2930] Transitioning the state of container e7599e9a-0ec3-44bd-b5f9-909c985525db from FETCHING to RUNNING
I1213 17:00:06.283241 22842 exec.cpp:162] Version: 1.5.0
I1213 17:00:06.293561 22387 slave.cpp:4275] Got registration for executor '634be9c9-b19a-4cf7-a9e6-d093b2590638' of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000 from executor(1)@10.0.49.2:33503
I1213 17:00:06.296553 22400 slave.cpp:2762] Sending queued task '634be9c9-b19a-4cf7-a9e6-d093b2590638' to executor '634be9c9-b19a-4cf7-a9e6-d093b2590638' of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000 at executor(1)@10.0.49.2:33503
I1213 17:00:06.299866 22875 exec.cpp:237] Executor registered on agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0
I1213 17:00:06.303679 22880 executor.cpp:171] Received SUBSCRIBED event
I1213 17:00:06.304567 22880 executor.cpp:175] Subscribed executor on core-dev
I1213 17:00:06.304713 22880 executor.cpp:171] Received LAUNCH event
I1213 17:00:06.306710 22880 executor.cpp:637] Starting task 634be9c9-b19a-4cf7-a9e6-d093b2590638
I1213 17:00:06.309931 22412 slave.cpp:4732] Handling status update TASK_STARTING (Status UUID: 357b9389-a871-4a41-a181-935998c05b17) for task 634be9c9-b19a-4cf7-a9e6-d093b2590638 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000 from executor(1)@10.0.49.2:33503
I1213 17:00:06.311885 22385 task_status_update_manager.cpp:328] Received task status update TASK_STARTING (Status UUID: 357b9389-a871-4a41-a181-935998c05b17) for task 634be9c9-b19a-4cf7-a9e6-d093b2590638 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000
I1213 17:00:06.311966 22385 task_status_update_manager.cpp:507] Creating StatusUpdate stream for task 634be9c9-b19a-4cf7-a9e6-d093b2590638 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000
I1213 17:00:06.312602 22385 task_status_update_manager.cpp:383] Forwarding task status update TASK_STARTING (Status UUID: 357b9389-a871-4a41-a181-935998c05b17) for task 634be9c9-b19a-4cf7-a9e6-d093b2590638 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000 to the agent
I1213 17:00:06.312885 22420 slave.cpp:5215] Forwarding the update TASK_STARTING (Status UUID: 357b9389-a871-4a41-a181-935998c05b17) for task 634be9c9-b19a-4cf7-a9e6-d093b2590638 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000 to master@10.0.49.2:32874
I1213 17:00:06.313241 22420 slave.cpp:5108] Task status update manager successfully handled status update TASK_STARTING (Status UUID: 357b9389-a871-4a41-a181-935998c05b17) for task 634be9c9-b19a-4cf7-a9e6-d093b2590638 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000
I1213 17:00:06.313343 22420 slave.cpp:5124] Sending acknowledgement for status update TASK_STARTING (Status UUID: 357b9389-a871-4a41-a181-935998c05b17) for task 634be9c9-b19a-4cf7-a9e6-d093b2590638 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000 to executor(1)@10.0.49.2:33503
I1213 17:00:06.313462 22393 master.cpp:7843] Status update TASK_STARTING (Status UUID: 357b9389-a871-4a41-a181-935998c05b17) for task 634be9c9-b19a-4cf7-a9e6-d093b2590638 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000 from agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0 at slave(3)@10.0.49.2:32874 (core-dev)
I1213 17:00:06.313567 22393 master.cpp:7899] Forwarding status update TASK_STARTING (Status UUID: 357b9389-a871-4a41-a181-935998c05b17) for task 634be9c9-b19a-4cf7-a9e6-d093b2590638 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000
I1213 17:00:06.313839 22393 master.cpp:10146] Updating the state of task 634be9c9-b19a-4cf7-a9e6-d093b2590638 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000 (latest state: TASK_STARTING, status update state: TASK_STARTING)
I1213 17:00:06.314075 22413 sched.cpp:1029] Scheduler::statusUpdate took 81020ns
I1213 17:00:06.314412 22413 master.cpp:5842] Processing ACKNOWLEDGE call 357b9389-a871-4a41-a181-935998c05b17 for task 634be9c9-b19a-4cf7-a9e6-d093b2590638 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000 (default) at scheduler-7f8c2474-49a2-4ba7-8c60-d9c4ba8bf11d@10.0.49.2:32874 on agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0
I1213 17:00:06.314813 22419 task_status_update_manager.cpp:401] Received task status update acknowledgement (UUID: 357b9389-a871-4a41-a181-935998c05b17) for task 634be9c9-b19a-4cf7-a9e6-d093b2590638 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000
I1213 17:00:06.315234 22421 slave.cpp:4010] Task status update manager successfully handled status update acknowledgement (UUID: 357b9389-a871-4a41-a181-935998c05b17) for task 634be9c9-b19a-4cf7-a9e6-d093b2590638 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000
I1213 17:00:06.320277 22880 executor.cpp:477] Running '/home/gmann/src/mesos2/build/src/mesos-containerizer launch <POSSIBLY-SENSITIVE-DATA>'
I1213 17:00:06.323053 22880 executor.cpp:650] Forked command at 22905
I1213 17:00:06.326375 22380 slave.cpp:4732] Handling status update TASK_RUNNING (Status UUID: c2b88898-0580-4288-b7f0-dcf3c3e8f031) for task 634be9c9-b19a-4cf7-a9e6-d093b2590638 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000 from executor(1)@10.0.49.2:33503
I1213 17:00:06.327826 22399 task_status_update_manager.cpp:328] Received task status update TASK_RUNNING (Status UUID: c2b88898-0580-4288-b7f0-dcf3c3e8f031) for task 634be9c9-b19a-4cf7-a9e6-d093b2590638 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000
I1213 17:00:06.327997 22399 task_status_update_manager.cpp:383] Forwarding task status update TASK_RUNNING (Status UUID: c2b88898-0580-4288-b7f0-dcf3c3e8f031) for task 634be9c9-b19a-4cf7-a9e6-d093b2590638 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000 to the agent
I1213 17:00:06.328306 22387 slave.cpp:5215] Forwarding the update TASK_RUNNING (Status UUID: c2b88898-0580-4288-b7f0-dcf3c3e8f031) for task 634be9c9-b19a-4cf7-a9e6-d093b2590638 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000 to master@10.0.49.2:32874
I1213 17:00:06.328640 22387 slave.cpp:5108] Task status update manager successfully handled status update TASK_RUNNING (Status UUID: c2b88898-0580-4288-b7f0-dcf3c3e8f031) for task 634be9c9-b19a-4cf7-a9e6-d093b2590638 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000
I1213 17:00:06.328716 22387 slave.cpp:5124] Sending acknowledgement for status update TASK_RUNNING (Status UUID: c2b88898-0580-4288-b7f0-dcf3c3e8f031) for task 634be9c9-b19a-4cf7-a9e6-d093b2590638 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000 to executor(1)@10.0.49.2:33503
I1213 17:00:06.328786 22418 master.cpp:7843] Status update TASK_RUNNING (Status UUID: c2b88898-0580-4288-b7f0-dcf3c3e8f031) for task 634be9c9-b19a-4cf7-a9e6-d093b2590638 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000 from agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0 at slave(3)@10.0.49.2:32874 (core-dev)
I1213 17:00:06.328871 22418 master.cpp:7899] Forwarding status update TASK_RUNNING (Status UUID: c2b88898-0580-4288-b7f0-dcf3c3e8f031) for task 634be9c9-b19a-4cf7-a9e6-d093b2590638 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000
I1213 17:00:06.329092 22418 master.cpp:10146] Updating the state of task 634be9c9-b19a-4cf7-a9e6-d093b2590638 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
I1213 17:00:06.329284 22416 sched.cpp:1029] Scheduler::statusUpdate took 49253ns
I1213 17:00:06.329592 22416 master.cpp:5842] Processing ACKNOWLEDGE call c2b88898-0580-4288-b7f0-dcf3c3e8f031 for task 634be9c9-b19a-4cf7-a9e6-d093b2590638 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000 (default) at scheduler-7f8c2474-49a2-4ba7-8c60-d9c4ba8bf11d@10.0.49.2:32874 on agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0
I1213 17:00:06.329964 22416 task_status_update_manager.cpp:401] Received task status update acknowledgement (UUID: c2b88898-0580-4288-b7f0-dcf3c3e8f031) for task 634be9c9-b19a-4cf7-a9e6-d093b2590638 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000
I1213 17:00:06.330282 22388 slave.cpp:4010] Task status update manager successfully handled status update acknowledgement (UUID: c2b88898-0580-4288-b7f0-dcf3c3e8f031) for task 634be9c9-b19a-4cf7-a9e6-d093b2590638 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000
W1213 17:00:06.334962 22366 process.cpp:2756] Attempted to spawn already running process version@10.0.49.2:32874
I1213 17:00:06.361163 22366 sched.cpp:232] Version: 1.5.0
I1213 17:00:06.361845 22392 sched.cpp:336] New master detected at master@10.0.49.2:32874
I1213 17:00:06.361963 22392 sched.cpp:396] Authenticating with master master@10.0.49.2:32874
I1213 17:00:06.362073 22392 sched.cpp:403] Using default CRAM-MD5 authenticatee
I1213 17:00:06.362354 22400 authenticatee.cpp:121] Creating new client SASL connection
I1213 17:00:06.387989 22412 master.cpp:8920] Authenticating scheduler-a872070c-2629-4049-a411-7ecb4fe83cc0@10.0.49.2:32874
I1213 17:00:06.388182 22407 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(15)@10.0.49.2:32874
I1213 17:00:06.388605 22381 authenticator.cpp:98] Creating new server SASL connection
I1213 17:00:06.396436 22406 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I1213 17:00:06.396492 22406 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I1213 17:00:06.396687 22406 authenticator.cpp:204] Received SASL authentication start
I1213 17:00:06.396766 22406 authenticator.cpp:326] Authentication requires more steps
I1213 17:00:06.396888 22406 authenticatee.cpp:259] Received SASL authentication step
I1213 17:00:06.397013 22406 authenticator.cpp:232] Received SASL authentication step
I1213 17:00:06.397056 22406 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'core-dev' server FQDN: 'core-dev' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1213 17:00:06.397084 22406 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I1213 17:00:06.397119 22406 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1213 17:00:06.397148 22406 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'core-dev' server FQDN: 'core-dev' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1213 17:00:06.397171 22406 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1213 17:00:06.397188 22406 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1213 17:00:06.397230 22406 authenticator.cpp:318] Authentication success
I1213 17:00:06.397392 22404 authenticatee.cpp:299] Authentication success
I1213 17:00:06.397466 22405 master.cpp:8950] Successfully authenticated principal 'test-principal' at scheduler-a872070c-2629-4049-a411-7ecb4fe83cc0@10.0.49.2:32874
I1213 17:00:06.397517 22427 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(15)@10.0.49.2:32874
I1213 17:00:06.397670 22404 sched.cpp:502] Successfully authenticated with master master@10.0.49.2:32874
I1213 17:00:06.397711 22404 sched.cpp:824] Sending SUBSCRIBE call to master@10.0.49.2:32874
I1213 17:00:06.397840 22404 sched.cpp:857] Will retry registration in 1.561018484secs if necessary
I1213 17:00:06.398057 22393 master.cpp:2957] Received SUBSCRIBE call for framework 'default' at scheduler-a872070c-2629-4049-a411-7ecb4fe83cc0@10.0.49.2:32874
I1213 17:00:06.398175 22393 master.cpp:2274] Authorizing framework principal 'test-principal' to receive offers for roles '{ * }'
I1213 17:00:06.398794 22413 master.cpp:3037] Subscribing framework default with checkpointing disabled and capabilities [ MULTI_ROLE, RESERVATION_REFINEMENT, PARTITION_AWARE ]
I1213 17:00:06.399008 22413 master.cpp:9141] Adding framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001 (default) at scheduler-a872070c-2629-4049-a411-7ecb4fe83cc0@10.0.49.2:32874 with roles { } suppressed
I1213 17:00:06.399401 22390 hierarchical.cpp:297] Added framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001
I1213 17:00:06.399492 22419 sched.cpp:751] Framework registered with ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001
I1213 17:00:06.399629 22419 sched.cpp:765] Scheduler::registered took 27216ns
I1213 17:00:06.400743 22390 hierarchical.cpp:1517] Performed allocation for 1 agents in 1.122279ms
I1213 17:00:06.401144 22421 master.cpp:8750] Sending 1 offers to framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001 (default) at scheduler-a872070c-2629-4049-a411-7ecb4fe83cc0@10.0.49.2:32874
I1213 17:00:06.401681 22380 sched.cpp:921] Scheduler::resourceOffers took 86144ns
I1213 17:00:06.403167 22389 master.cpp:10671] Removing offer ccc06cbb-4a30-40ac-bfb2-220c5af2000d-O1
I1213 17:00:06.403339 22389 master.cpp:4273] Processing ACCEPT call for offers: [ ccc06cbb-4a30-40ac-bfb2-220c5af2000d-O1 ] on agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0 at slave(3)@10.0.49.2:32874 (core-dev) for framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001 (default) at scheduler-a872070c-2629-4049-a411-7ecb4fe83cc0@10.0.49.2:32874
I1213 17:00:06.403503 22389 master.cpp:3593] Authorizing framework principal 'test-principal' to launch task f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9
I1213 17:00:06.405079 22423 master.cpp:11426] Adding task f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9 with resources cpus(allocated: *):1; mem(allocated: *):512 on agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0 at slave(3)@10.0.49.2:32874 (core-dev)
I1213 17:00:06.405362 22423 master.cpp:5024] Launching task f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001 (default) at scheduler-a872070c-2629-4049-a411-7ecb4fe83cc0@10.0.49.2:32874 with resources [{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":1.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":512.0},"type":"SCALAR"}] on agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0 at slave(3)@10.0.49.2:32874 (core-dev)
I1213 17:00:06.406360 22424 slave.cpp:1807] Got assigned task 'f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9' for framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001
I1213 17:00:06.406467 22426 hierarchical.cpp:1192] Recovered ports(allocated: *):[31000-32000]; disk(allocated: *):46053 (total: cpus:2; mem:1024; disk:46053; ports:[31000-32000], allocated: cpus(allocated: *):2; mem(allocated: *):1024) on agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0 from framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001
I1213 17:00:06.406571 22426 hierarchical.cpp:1238] Framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001 filtered agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0 for 5secs
I1213 17:00:06.407112 22424 slave.cpp:2077] Authorizing task 'f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9' for framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001
I1213 17:00:06.407196 22424 slave.cpp:7732] Authorizing framework principal 'test-principal' to launch task f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9
I1213 17:00:06.408238 22409 slave.cpp:2471] Launching task 'f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9' for framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001
I1213 17:00:06.409219 22409 paths.cpp:702] Trying to chown '/tmp/PartitionTest_PartitionedSlaveReregistrationMasterFailover_RhNcIz/slaves/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0/frameworks/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001/executors/f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9/runs/f678c81a-07b6-418b-a1f9-ea2a7e0595a3' to user 'gmann'
I1213 17:00:06.409505 22409 slave.cpp:8206] Launching executor 'f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9' of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001 with resources [{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":32.0},"type":"SCALAR"}] in work directory '/tmp/PartitionTest_PartitionedSlaveReregistrationMasterFailover_RhNcIz/slaves/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0/frameworks/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001/executors/f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9/runs/f678c81a-07b6-418b-a1f9-ea2a7e0595a3'
I1213 17:00:06.410639 22409 slave.cpp:2557] Queued task 'f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9' for executor 'f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9' of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001
I1213 17:00:06.410775 22409 slave.cpp:984] Successfully attached '/tmp/PartitionTest_PartitionedSlaveReregistrationMasterFailover_RhNcIz/slaves/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0/frameworks/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001/executors/f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9/runs/f678c81a-07b6-418b-a1f9-ea2a7e0595a3' to virtual path '/tmp/PartitionTest_PartitionedSlaveReregistrationMasterFailover_RhNcIz/slaves/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0/frameworks/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001/executors/f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9/runs/latest'
I1213 17:00:06.410856 22409 slave.cpp:984] Successfully attached '/tmp/PartitionTest_PartitionedSlaveReregistrationMasterFailover_RhNcIz/slaves/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0/frameworks/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001/executors/f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9/runs/f678c81a-07b6-418b-a1f9-ea2a7e0595a3' to virtual path '/frameworks/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001/executors/f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9/runs/latest'
I1213 17:00:06.410922 22409 slave.cpp:984] Successfully attached '/tmp/PartitionTest_PartitionedSlaveReregistrationMasterFailover_RhNcIz/slaves/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0/frameworks/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001/executors/f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9/runs/f678c81a-07b6-418b-a1f9-ea2a7e0595a3' to virtual path '/tmp/PartitionTest_PartitionedSlaveReregistrationMasterFailover_RhNcIz/slaves/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0/frameworks/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001/executors/f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9/runs/f678c81a-07b6-418b-a1f9-ea2a7e0595a3'
I1213 17:00:06.411244 22409 slave.cpp:3023] Launching container f678c81a-07b6-418b-a1f9-ea2a7e0595a3 for executor 'f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9' of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001
I1213 17:00:06.412129 22414 containerizer.cpp:1201] Starting container f678c81a-07b6-418b-a1f9-ea2a7e0595a3
I1213 17:00:06.413007 22414 containerizer.cpp:1373] Checkpointed ContainerConfig at '/tmp/PartitionTest_PartitionedSlaveReregistrationMasterFailover_5bD0h3/containers/f678c81a-07b6-418b-a1f9-ea2a7e0595a3/config'
I1213 17:00:06.413063 22414 containerizer.cpp:2930] Transitioning the state of container f678c81a-07b6-418b-a1f9-ea2a7e0595a3 from PROVISIONING to PREPARING
I1213 17:00:06.417315 22410 containerizer.cpp:1842] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"arguments":["mesos-executor","--launcher_dir=\/home\/gmann\/src\/mesos2\/build\/src"],"shell":false,"value":"\/home\/gmann\/src\/mesos2\/build\/src\/mesos-executor"},"environment":{"variables":[{"name":"LIBPROCESS_PORT","type":"VALUE","value":"0"},{"name":"MESOS_AGENT_ENDPOINT","type":"VALUE","value":"10.0.49.2:32874"},{"name":"MESOS_CHECKPOINT","type":"VALUE","value":"0"},{"name":"MESOS_DIRECTORY","type":"VALUE","value":"\/tmp\/PartitionTest_PartitionedSlaveReregistrationMasterFailover_RhNcIz\/slaves\/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0\/frameworks\/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001\/executors\/f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9\/runs\/f678c81a-07b6-418b-a1f9-ea2a7e0595a3"},{"name":"MESOS_EXECUTOR_AUTHENTICATION_TOKEN","type":"VALUE","value":"eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJjaWQiOiJmNjc4YzgxYS0wN2I2LTQxOGItYTFmOS1lYTJhN2UwNTk1YTMiLCJlaWQiOiJmMGNjMGJjMy01OWE3LTRmNTEtYWFhZS00MDlmNzZjYTBmYzkiLCJmaWQiOiJjY2MwNmNiYi00YTMwLTQwYWMtYmZiMi0yMjBjNWFmMjAwMGQtMDAwMSJ9.tHvOUnwttjZzgl3AasXi0F4RWjKTKOcr9vSMYTWE9-I"},{"name":"MESOS_EXECUTOR_ID","type":"VALUE","value":"f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9"},{"name":"MESOS_EXECUTOR_SHUTDOWN_GRACE_PERIOD","type":"VALUE","value":"5secs"},{"name":"MESOS_FRAMEWORK_ID","type":"VALUE","value":"ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001"},{"name":"MESOS_HTTP_COMMAND_EXECUTOR","type":"VALUE","value":"0"},{"name":"MESOS_SLAVE_ID","type":"VALUE","value":"ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0"},{"name":"MESOS_SLAVE_PID","type":"VALUE","value":"slave(3)@10.0.49.2:32874"},{"name":"MESOS_SANDBOX","type":"VALUE","value":"\/tmp\/PartitionTest_PartitionedSlaveReregistrationMasterFailover_RhNcIz\/slaves\/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0\/frameworks\/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001\/executors\/f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9\/runs\/f678c81a-07b6-418b-a1f9-ea2a7e0595a3"}]},"task_environment":{},"user":"gmann","working_directory":"\/tmp\/PartitionTest_PartitionedSlaveReregistrationMasterFailover_RhNcIz\/slaves\/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0\/frameworks\/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001\/executors\/f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9\/runs\/f678c81a-07b6-418b-a1f9-ea2a7e0595a3"}" --pipe_read="13" --pipe_write="14" --runtime_directory="/tmp/PartitionTest_PartitionedSlaveReregistrationMasterFailover_5bD0h3/containers/f678c81a-07b6-418b-a1f9-ea2a7e0595a3" --unshare_namespace_mnt="false"'
I1213 17:00:06.420735 22410 launcher.cpp:140] Forked child with pid '22919' for container 'f678c81a-07b6-418b-a1f9-ea2a7e0595a3'
I1213 17:00:06.421313 22410 containerizer.cpp:2930] Transitioning the state of container f678c81a-07b6-418b-a1f9-ea2a7e0595a3 from PREPARING to ISOLATING
I1213 17:00:06.422752 22404 containerizer.cpp:2930] Transitioning the state of container f678c81a-07b6-418b-a1f9-ea2a7e0595a3 from ISOLATING to FETCHING
I1213 17:00:06.422978 22408 fetcher.cpp:369] Starting to fetch URIs for container: f678c81a-07b6-418b-a1f9-ea2a7e0595a3, directory: /tmp/PartitionTest_PartitionedSlaveReregistrationMasterFailover_RhNcIz/slaves/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0/frameworks/ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001/executors/f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9/runs/f678c81a-07b6-418b-a1f9-ea2a7e0595a3
I1213 17:00:06.424177 22413 containerizer.cpp:2930] Transitioning the state of container f678c81a-07b6-418b-a1f9-ea2a7e0595a3 from FETCHING to RUNNING
I1213 17:00:06.709440 22960 exec.cpp:162] Version: 1.5.0
I1213 17:00:06.719645 22421 slave.cpp:4275] Got registration for executor 'f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9' of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001 from executor(1)@10.0.49.2:34284
I1213 17:00:06.722446 22399 slave.cpp:2762] Sending queued task 'f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9' to executor 'f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9' of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001 at executor(1)@10.0.49.2:34284
I1213 17:00:06.726068 22966 exec.cpp:237] Executor registered on agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0
I1213 17:00:06.729638 22971 executor.cpp:171] Received SUBSCRIBED event
I1213 17:00:06.730612 22971 executor.cpp:175] Subscribed executor on core-dev
I1213 17:00:06.730922 22971 executor.cpp:171] Received LAUNCH event
I1213 17:00:06.733036 22971 executor.cpp:637] Starting task f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9
I1213 17:00:06.735913 22409 slave.cpp:4732] Handling status update TASK_STARTING (Status UUID: fb27debf-2e3f-4797-953d-1315f034af0b) for task f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001 from executor(1)@10.0.49.2:34284
I1213 17:00:06.737869 22412 task_status_update_manager.cpp:328] Received task status update TASK_STARTING (Status UUID: fb27debf-2e3f-4797-953d-1315f034af0b) for task f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001
I1213 17:00:06.737941 22412 task_status_update_manager.cpp:507] Creating StatusUpdate stream for task f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001
I1213 17:00:06.738581 22412 task_status_update_manager.cpp:383] Forwarding task status update TASK_STARTING (Status UUID: fb27debf-2e3f-4797-953d-1315f034af0b) for task f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001 to the agent
I1213 17:00:06.738849 22397 slave.cpp:5215] Forwarding the update TASK_STARTING (Status UUID: fb27debf-2e3f-4797-953d-1315f034af0b) for task f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001 to master@10.0.49.2:32874
I1213 17:00:06.739192 22397 slave.cpp:5108] Task status update manager successfully handled status update TASK_STARTING (Status UUID: fb27debf-2e3f-4797-953d-1315f034af0b) for task f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001
I1213 17:00:06.739305 22397 slave.cpp:5124] Sending acknowledgement for status update TASK_STARTING (Status UUID: fb27debf-2e3f-4797-953d-1315f034af0b) for task f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001 to executor(1)@10.0.49.2:34284
I1213 17:00:06.739349 22381 master.cpp:7843] Status update TASK_STARTING (Status UUID: fb27debf-2e3f-4797-953d-1315f034af0b) for task f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001 from agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0 at slave(3)@10.0.49.2:32874 (core-dev)
I1213 17:00:06.739434 22381 master.cpp:7899] Forwarding status update TASK_STARTING (Status UUID: fb27debf-2e3f-4797-953d-1315f034af0b) for task f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001
I1213 17:00:06.739642 22381 master.cpp:10146] Updating the state of task f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001 (latest state: TASK_STARTING, status update state: TASK_STARTING)
I1213 17:00:06.739871 22397 sched.cpp:1029] Scheduler::statusUpdate took 70895ns
I1213 17:00:06.740164 22397 master.cpp:5842] Processing ACKNOWLEDGE call fb27debf-2e3f-4797-953d-1315f034af0b for task f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001 (default) at scheduler-a872070c-2629-4049-a411-7ecb4fe83cc0@10.0.49.2:32874 on agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0
I1213 17:00:06.740530 22391 task_status_update_manager.cpp:401] Received task status update acknowledgement (UUID: fb27debf-2e3f-4797-953d-1315f034af0b) for task f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001
I1213 17:00:06.740876 22427 slave.cpp:4010] Task status update manager successfully handled status update acknowledgement (UUID: fb27debf-2e3f-4797-953d-1315f034af0b) for task f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001
I1213 17:00:06.746740 22971 executor.cpp:477] Running '/home/gmann/src/mesos2/build/src/mesos-containerizer launch <POSSIBLY-SENSITIVE-DATA>'
I1213 17:00:06.749584 22971 executor.cpp:650] Forked command at 22997
I1213 17:00:06.752539 22398 slave.cpp:4732] Handling status update TASK_RUNNING (Status UUID: d8ae53e1-37da-4b65-bdd6-b9ae164d2d7c) for task f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001 from executor(1)@10.0.49.2:34284
I1213 17:00:06.754197 22401 task_status_update_manager.cpp:328] Received task status update TASK_RUNNING (Status UUID: d8ae53e1-37da-4b65-bdd6-b9ae164d2d7c) for task f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001
I1213 17:00:06.754371 22401 task_status_update_manager.cpp:383] Forwarding task status update TASK_RUNNING (Status UUID: d8ae53e1-37da-4b65-bdd6-b9ae164d2d7c) for task f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001 to the agent
I1213 17:00:06.754668 22421 slave.cpp:5215] Forwarding the update TASK_RUNNING (Status UUID: d8ae53e1-37da-4b65-bdd6-b9ae164d2d7c) for task f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001 to master@10.0.49.2:32874
I1213 17:00:06.754932 22421 slave.cpp:5108] Task status update manager successfully handled status update TASK_RUNNING (Status UUID: d8ae53e1-37da-4b65-bdd6-b9ae164d2d7c) for task f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001
I1213 17:00:06.755002 22421 slave.cpp:5124] Sending acknowledgement for status update TASK_RUNNING (Status UUID: d8ae53e1-37da-4b65-bdd6-b9ae164d2d7c) for task f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001 to executor(1)@10.0.49.2:34284
I1213 17:00:06.755185 22403 master.cpp:7843] Status update TASK_RUNNING (Status UUID: d8ae53e1-37da-4b65-bdd6-b9ae164d2d7c) for task f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001 from agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0 at slave(3)@10.0.49.2:32874 (core-dev)
I1213 17:00:06.755304 22403 master.cpp:7899] Forwarding status update TASK_RUNNING (Status UUID: d8ae53e1-37da-4b65-bdd6-b9ae164d2d7c) for task f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001
I1213 17:00:06.755548 22403 master.cpp:10146] Updating the state of task f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
I1213 17:00:06.755815 22389 sched.cpp:1029] Scheduler::statusUpdate took 76924ns
I1213 17:00:06.756201 22423 master.cpp:5842] Processing ACKNOWLEDGE call d8ae53e1-37da-4b65-bdd6-b9ae164d2d7c for task f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001 (default) at scheduler-a872070c-2629-4049-a411-7ecb4fe83cc0@10.0.49.2:32874 on agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0
I1213 17:00:06.756680 22411 task_status_update_manager.cpp:401] Received task status update acknowledgement (UUID: d8ae53e1-37da-4b65-bdd6-b9ae164d2d7c) for task f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001
I1213 17:00:06.757004 22396 slave.cpp:4010] Task status update manager successfully handled status update acknowledgement (UUID: d8ae53e1-37da-4b65-bdd6-b9ae164d2d7c) for task f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001
I1213 17:00:06.758961 22425 hierarchical.cpp:1517] Performed allocation for 1 agents in 159013ns
I1213 17:00:06.760164 22392 hierarchical.cpp:1517] Performed allocation for 1 agents in 132691ns
I1213 17:00:06.761142 22385 hierarchical.cpp:1517] Performed allocation for 1 agents in 153347ns
I1213 17:00:06.762048 22398 slave.cpp:6275] Current disk usage 50.58%. Max allowed age: 2.759181813407454days
I1213 17:00:06.762059 22413 hierarchical.cpp:1517] Performed allocation for 1 agents in 131702ns
I1213 17:00:06.763075 22419 hierarchical.cpp:1517] Performed allocation for 1 agents in 120194ns
I1213 17:00:06.763123 22380 master.cpp:8189] Marking agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0 at slave(3)@10.0.49.2:32874 (core-dev) unreachable: health check timed out
I1213 17:00:06.763716 22389 registrar.cpp:495] Applied 1 operations in 110553ns; attempting to update the registry
I1213 17:00:06.766468 22411 log.cpp:560] Attempting to append 223 bytes to the log
I1213 17:00:06.766674 22396 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 5
I1213 17:00:06.767644 22382 replica.cpp:540] Replica received write request for position 5 from __req_res__(32)@10.0.49.2:32874
I1213 17:00:06.768692 22382 leveldb.cpp:341] Persisting action (242 bytes) to leveldb took 975024ns
I1213 17:00:06.768746 22382 replica.cpp:711] Persisted action APPEND at position 5
I1213 17:00:06.769660 22414 replica.cpp:694] Replica received learned notice for position 5 from log-network(3)@10.0.49.2:32874
I1213 17:00:06.770359 22414 leveldb.cpp:341] Persisting action (244 bytes) to leveldb took 639528ns
I1213 17:00:06.770404 22414 replica.cpp:711] Persisted action APPEND at position 5
I1213 17:00:06.771392 22386 registrar.cpp:552] Successfully updated the registry in 0ns
I1213 17:00:06.771651 22395 master.cpp:8237] Marked agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0 at slave(3)@10.0.49.2:32874 (core-dev) unreachable: health check timed out
I1213 17:00:06.771666 22392 log.cpp:579] Attempting to truncate the log to 5
I1213 17:00:06.771855 22395 master.cpp:10146] Updating the state of task f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001 (latest state: TASK_UNREACHABLE, status update state: TASK_UNREACHABLE)
I1213 17:00:06.771905 22397 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 6
I1213 17:00:06.772306 22395 master.cpp:10252] Removing task f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9 with resources cpus(allocated: *):1; mem(allocated: *):512 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001 on agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0 at slave(3)@10.0.49.2:32874 (core-dev)
I1213 17:00:06.772356 22405 hierarchical.cpp:609] Removed agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0
I1213 17:00:06.772529 22395 master.cpp:7894] Sending status update TASK_UNREACHABLE for task f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001 'health check timed out'
I1213 17:00:06.772753 22395 master.cpp:10146] Updating the state of task 634be9c9-b19a-4cf7-a9e6-d093b2590638 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000 (latest state: TASK_LOST, status update state: TASK_LOST)
I1213 17:00:06.772905 22405 replica.cpp:540] Replica received write request for position 6 from __req_res__(33)@10.0.49.2:32874
I1213 17:00:06.772991 22407 sched.cpp:1029] Scheduler::statusUpdate took 80665ns
I1213 17:00:06.773130 22395 master.cpp:10252] Removing task 634be9c9-b19a-4cf7-a9e6-d093b2590638 with resources cpus(allocated: *):1; mem(allocated: *):512 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000 on agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0 at slave(3)@10.0.49.2:32874 (core-dev)
I1213 17:00:06.773353 22395 master.cpp:7894] Sending status update TASK_LOST for task 634be9c9-b19a-4cf7-a9e6-d093b2590638 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000 'health check timed out'
I1213 17:00:06.773701 22405 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 727556ns
I1213 17:00:06.773728 22395 master.cpp:2126] Notifying framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001 (default) at scheduler-a872070c-2629-4049-a411-7ecb4fe83cc0@10.0.49.2:32874 of lost agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0 (core-dev)
I1213 17:00:06.773757 22405 replica.cpp:711] Persisted action TRUNCATE at position 6
I1213 17:00:06.773799 22406 sched.cpp:1029] Scheduler::statusUpdate took 75856ns
I1213 17:00:06.773844 22395 master.cpp:2126] Notifying framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000 (default) at scheduler-7f8c2474-49a2-4ba7-8c60-d9c4ba8bf11d@10.0.49.2:32874 of lost agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0 (core-dev)
I1213 17:00:06.773972 22403 sched.cpp:1091] Lost agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0
I1213 17:00:06.774056 22401 sched.cpp:1091] Lost agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0
I1213 17:00:06.774076 22403 sched.cpp:1102] Scheduler::slaveLost took 40613ns
I1213 17:00:06.774147 22401 sched.cpp:1102] Scheduler::slaveLost took 32142ns
I1213 17:00:06.774575 22424 replica.cpp:694] Replica received learned notice for position 6 from log-network(3)@10.0.49.2:32874
I1213 17:00:06.775285 22424 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 650017ns
I1213 17:00:06.775377 22424 leveldb.cpp:399] Deleting ~2 keys from leveldb took 44824ns
I1213 17:00:06.775416 22424 replica.cpp:711] Persisted action TRUNCATE at position 6
I1213 17:00:06.776546 22366 master.cpp:1147] Master terminating
I1213 17:00:06.776923 22383 hierarchical.cpp:344] Removed framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001
I1213 17:00:06.777173 22388 slave.cpp:5347] Got exited event for master@10.0.49.2:32874
W1213 17:00:06.777238 22388 slave.cpp:5352] Master disconnected! Waiting for a new master to be elected
I1213 17:00:06.777317 22383 hierarchical.cpp:344] Removed framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000
I1213 17:00:06.783046 22366 cluster.cpp:172] Creating default 'local' authorizer
I1213 17:00:06.790777 22399 master.cpp:456] Master 85598744-e3d7-4d66-935c-2ae1faea4813 (core-dev) started on 10.0.49.2:32874
I1213 17:00:06.790814 22399 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/9d3p85/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="in_memory" --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/9d3p85/master" --zk_session_timeout="10secs"
I1213 17:00:06.791128 22399 master.cpp:507] Master only allowing authenticated frameworks to register
I1213 17:00:06.791146 22399 master.cpp:513] Master only allowing authenticated agents to register
I1213 17:00:06.791174 22399 master.cpp:519] Master only allowing authenticated HTTP frameworks to register
I1213 17:00:06.791189 22399 credentials.hpp:37] Loading credentials for authentication from '/tmp/9d3p85/credentials'
I1213 17:00:06.791517 22399 master.cpp:563] Using default 'crammd5' authenticator
I1213 17:00:06.791668 22399 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
I1213 17:00:06.791836 22399 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
I1213 17:00:06.791985 22399 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
I1213 17:00:06.792136 22399 master.cpp:642] Authorization enabled
I1213 17:00:06.792325 22383 whitelist_watcher.cpp:77] No whitelist given
I1213 17:00:06.792332 22416 hierarchical.cpp:175] Initialized hierarchical allocator process
I1213 17:00:06.794508 22422 master.cpp:2209] Elected as the leading master!
I1213 17:00:06.794548 22422 master.cpp:1689] Recovering from registrar
I1213 17:00:06.794739 22386 registrar.cpp:347] Recovering registrar
I1213 17:00:06.797003 22410 registrar.cpp:391] Successfully fetched the registry (0B) in 0ns
I1213 17:00:06.797102 22410 registrar.cpp:495] Applied 1 operations in 17771ns; attempting to update the registry
I1213 17:00:06.797729 22407 registrar.cpp:552] Successfully updated the registry in 0ns
I1213 17:00:06.797930 22407 registrar.cpp:424] Successfully recovered registrar
I1213 17:00:06.798475 22413 master.cpp:1802] Recovered 0 agents from the registry (123B); allowing 10mins for agents to re-register
I1213 17:00:06.798508 22421 hierarchical.cpp:213] Skipping recovery of hierarchical allocator: nothing to recover
I1213 17:00:06.805234 22406 slave.cpp:1033] New master detected at master@10.0.49.2:32874
I1213 17:00:06.805251 22419 task_status_update_manager.cpp:181] Pausing sending task status updates
I1213 17:00:06.805323 22395 sched.cpp:330] Scheduler::disconnected took 54274ns
I1213 17:00:06.805343 22390 sched.cpp:330] Scheduler::disconnected took 19397ns
I1213 17:00:06.805501 22390 sched.cpp:336] New master detected at master@10.0.49.2:32874
I1213 17:00:06.805435 22395 sched.cpp:336] New master detected at master@10.0.49.2:32874
I1213 17:00:06.805380 22406 slave.cpp:1088] Detecting new master
I1213 17:00:06.805634 22390 sched.cpp:396] Authenticating with master master@10.0.49.2:32874
I1213 17:00:06.805707 22390 sched.cpp:403] Using default CRAM-MD5 authenticatee
I1213 17:00:06.805711 22395 sched.cpp:396] Authenticating with master master@10.0.49.2:32874
I1213 17:00:06.805768 22395 sched.cpp:403] Using default CRAM-MD5 authenticatee
I1213 17:00:06.805835 22406 slave.cpp:1115] Authenticating with master master@10.0.49.2:32874
I1213 17:00:06.805918 22406 slave.cpp:1124] Using default CRAM-MD5 authenticatee
I1213 17:00:06.806020 22417 authenticatee.cpp:121] Creating new client SASL connection
I1213 17:00:06.806040 22401 authenticatee.cpp:121] Creating new client SASL connection
I1213 17:00:06.806154 22389 authenticatee.cpp:121] Creating new client SASL connection
I1213 17:00:06.833823 22411 master.cpp:8920] Authenticating scheduler-a872070c-2629-4049-a411-7ecb4fe83cc0@10.0.49.2:32874
I1213 17:00:06.834012 22396 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(17)@10.0.49.2:32874
I1213 17:00:06.834111 22411 master.cpp:8920] Authenticating slave(3)@10.0.49.2:32874
I1213 17:00:06.834379 22424 authenticator.cpp:98] Creating new server SASL connection
I1213 17:00:06.834396 22396 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(18)@10.0.49.2:32874
I1213 17:00:06.834517 22423 master.cpp:8920] Authenticating scheduler-7f8c2474-49a2-4ba7-8c60-d9c4ba8bf11d@10.0.49.2:32874
I1213 17:00:06.834774 22381 authenticator.cpp:98] Creating new server SASL connection
I1213 17:00:06.834800 22396 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(16)@10.0.49.2:32874
I1213 17:00:06.835088 22426 authenticator.cpp:98] Creating new server SASL connection
I1213 17:00:06.841990 22387 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I1213 17:00:06.842041 22387 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I1213 17:00:06.842234 22387 authenticator.cpp:204] Received SASL authentication start
I1213 17:00:06.842332 22387 authenticator.cpp:326] Authentication requires more steps
I1213 17:00:06.842456 22387 authenticatee.cpp:259] Received SASL authentication step
I1213 17:00:06.842586 22387 authenticator.cpp:232] Received SASL authentication step
I1213 17:00:06.842629 22387 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'core-dev' server FQDN: 'core-dev' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1213 17:00:06.842656 22387 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I1213 17:00:06.842692 22387 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1213 17:00:06.842722 22387 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'core-dev' server FQDN: 'core-dev' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1213 17:00:06.842744 22387 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1213 17:00:06.842766 22387 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1213 17:00:06.842792 22387 authenticator.cpp:318] Authentication success
I1213 17:00:06.842922 22402 authenticatee.cpp:299] Authentication success
I1213 17:00:06.842996 22415 master.cpp:8950] Successfully authenticated principal 'test-principal' at slave(3)@10.0.49.2:32874
I1213 17:00:06.843076 22418 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(18)@10.0.49.2:32874
I1213 17:00:06.843250 22414 slave.cpp:1207] Successfully authenticated with master master@10.0.49.2:32874
I1213 17:00:06.843694 22414 slave.cpp:1684] Will retry registration in 545820ns if necessary
I1213 17:00:06.844313 22384 master.cpp:6416] Received re-register agent message from agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0 at slave(3)@10.0.49.2:32874 (core-dev)
I1213 17:00:06.844455 22384 master.cpp:3866] Authorizing agent with principal 'test-principal'
I1213 17:00:06.844945 22392 master.cpp:6505] Authorized re-registration of agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0 at slave(3)@10.0.49.2:32874 (core-dev)
I1213 17:00:06.845043 22392 master.cpp:6645] Consulting registry about agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0 at slave(3)@10.0.49.2:32874(core-dev)
W1213 17:00:06.845448 22399 registry_operations.cpp:185] Allowing UNKNOWN agent to reregister: hostname: "core-dev"
resources {
name: "cpus"
type: SCALAR
scalar {
value: 2
}
}
resources {
name: "mem"
type: SCALAR
scalar {
value: 1024
}
}
resources {
name: "disk"
type: SCALAR
scalar {
value: 46053
}
}
resources {
name: "ports"
type: RANGES
ranges {
range {
begin: 31000
end: 32000
}
}
}
id {
value: "ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0"
}
checkpoint: true
port: 32874
I1213 17:00:06.845834 22399 registrar.cpp:495] Applied 1 operations in 412413ns; attempting to update the registry
I1213 17:00:06.847936 22386 registrar.cpp:552] Successfully updated the registry in 0ns
I1213 17:00:06.848112 22404 master.cpp:6696] Re-admitted agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0 at slave(3)@10.0.49.2:32874 (core-dev)
W1213 17:00:06.848268 22404 master.cpp:6833] Dropping update TASK_RUNNING for task f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001 'Unknown agent re-registered' for unknown framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001
W1213 17:00:06.848368 22404 master.cpp:6833] Dropping update TASK_RUNNING for task 634be9c9-b19a-4cf7-a9e6-d093b2590638 of framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000 'Unknown agent re-registered' for unknown framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000
I1213 17:00:06.848614 22404 master.cpp:11426] Adding task f0cc0bc3-59a7-4f51-aaae-409f76ca0fc9 with resources cpus(allocated: *):1; mem(allocated: *):512 on agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0 at slave(3)@10.0.49.2:32874 (core-dev)
I1213 17:00:06.848717 22404 master.cpp:11426] Adding task 634be9c9-b19a-4cf7-a9e6-d093b2590638 with resources cpus(allocated: *):1; mem(allocated: *):512 on agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0 at slave(3)@10.0.49.2:32874 (core-dev)
I1213 17:00:06.849114 22404 master.cpp:6902] Re-registered agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0 at slave(3)@10.0.49.2:32874 (core-dev) with cpus:2; mem:1024; disk:46053; ports:[31000-32000]
I1213 17:00:06.849190 22404 master.cpp:7156] Recovering framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001 from re-registering agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0 at slave(3)@10.0.49.2:32874 (core-dev)
I1213 17:00:06.849386 22404 master.cpp:9141] Adding framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001 (default) with roles { } suppressed
I1213 17:00:06.849387 22427 slave.cpp:1366] Re-registered with master master@10.0.49.2:32874
I1213 17:00:06.849500 22393 hierarchical.cpp:574] Added agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0 (core-dev) with cpus:2; mem:1024; disk:46053; ports:[31000-32000] (allocated: cpus(allocated: *):2; mem(allocated: *):1024)
I1213 17:00:06.849553 22408 task_status_update_manager.cpp:188] Resuming sending task status updates
I1213 17:00:06.849596 22404 master.cpp:7156] Recovering framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000 from re-registering agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0 at slave(3)@10.0.49.2:32874 (core-dev)
I1213 17:00:06.849666 22427 slave.cpp:1411] Forwarding agent update {"offer_operations":{},"resource_categories":{"oversubscribed":true},"resource_version_uuid":"o2oDVhaeRHORqRv0HXgh+w==","slave_id":{"value":"ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0"}}
I1213 17:00:06.849833 22404 master.cpp:9141] Adding framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000 (default) with roles { } suppressed
I1213 17:00:06.850055 22404 master.cpp:7270] Received update of agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0 at slave(3)@10.0.49.2:32874 (core-dev) with total oversubscribed resources {}
I1213 17:00:06.850224 22404 master.cpp:7368] Ignoring update on agent ccc06cbb-4a30-40ac-bfb2-220c5af2000d-S0 at slave(3)@10.0.49.2:32874 (core-dev) as it reports no changes
I1213 17:00:06.850391 22393 hierarchical.cpp:297] Added framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001
I1213 17:00:06.850450 22393 hierarchical.cpp:405] Deactivated framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001
I1213 17:00:06.850715 22393 hierarchical.cpp:1517] Performed allocation for 1 agents in 156564ns
I1213 17:00:06.851088 22393 hierarchical.cpp:297] Added framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000
I1213 17:00:06.851140 22393 hierarchical.cpp:405] Deactivated framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000
I1213 17:00:06.859843 22413 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I1213 17:00:06.859892 22413 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I1213 17:00:06.860050 22413 authenticator.cpp:204] Received SASL authentication start
I1213 17:00:06.860122 22413 authenticator.cpp:326] Authentication requires more steps
I1213 17:00:06.860282 22403 authenticatee.cpp:259] Received SASL authentication step
I1213 17:00:06.860493 22419 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I1213 17:00:06.860519 22426 authenticator.cpp:232] Received SASL authentication step
I1213 17:00:06.860571 22419 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I1213 17:00:06.860646 22426 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'core-dev' server FQDN: 'core-dev' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1213 17:00:06.860673 22426 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I1213 17:00:06.860703 22426 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1213 17:00:06.860739 22426 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'core-dev' server FQDN: 'core-dev' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1213 17:00:06.860761 22426 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1213 17:00:06.860769 22419 authenticator.cpp:204] Received SASL authentication start
I1213 17:00:06.860779 22426 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1213 17:00:06.860836 22426 authenticator.cpp:318] Authentication success
I1213 17:00:06.860846 22419 authenticator.cpp:326] Authentication requires more steps
I1213 17:00:06.860985 22419 authenticatee.cpp:259] Received SASL authentication step
I1213 17:00:06.861013 22406 master.cpp:8950] Successfully authenticated principal 'test-principal' at scheduler-a872070c-2629-4049-a411-7ecb4fe83cc0@10.0.49.2:32874
I1213 17:00:06.861055 22395 authenticatee.cpp:299] Authentication success
I1213 17:00:06.861090 22380 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(17)@10.0.49.2:32874
I1213 17:00:06.861116 22419 authenticator.cpp:232] Received SASL authentication step
I1213 17:00:06.861183 22419 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'core-dev' server FQDN: 'core-dev' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1213 17:00:06.861225 22419 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I1213 17:00:06.861268 22419 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1213 17:00:06.861299 22419 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'core-dev' server FQDN: 'core-dev' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1213 17:00:06.861323 22419 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1213 17:00:06.861346 22419 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1213 17:00:06.861374 22419 authenticator.cpp:318] Authentication success
I1213 17:00:06.861387 22411 sched.cpp:502] Successfully authenticated with master master@10.0.49.2:32874
I1213 17:00:06.861424 22411 sched.cpp:824] Sending SUBSCRIBE call to master@10.0.49.2:32874
I1213 17:00:06.861483 22381 authenticatee.cpp:299] Authentication success
I1213 17:00:06.861536 22411 sched.cpp:857] Will retry registration in 58.554738ms if necessary
I1213 17:00:06.861595 22394 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(16)@10.0.49.2:32874
I1213 17:00:06.861548 22409 master.cpp:8950] Successfully authenticated principal 'test-principal' at scheduler-7f8c2474-49a2-4ba7-8c60-d9c4ba8bf11d@10.0.49.2:32874
I1213 17:00:06.861733 22382 sched.cpp:502] Successfully authenticated with master master@10.0.49.2:32874
I1213 17:00:06.861776 22382 sched.cpp:824] Sending SUBSCRIBE call to master@10.0.49.2:32874
I1213 17:00:06.861843 22409 master.cpp:2957] Received SUBSCRIBE call for framework 'default' at scheduler-a872070c-2629-4049-a411-7ecb4fe83cc0@10.0.49.2:32874
I1213 17:00:06.861889 22382 sched.cpp:857] Will retry registration in 246.16091ms if necessary
I1213 17:00:06.861924 22409 master.cpp:2274] Authorizing framework principal 'test-principal' to receive offers for roles '{ * }'
I1213 17:00:06.862195 22409 master.cpp:2957] Received SUBSCRIBE call for framework 'default' at scheduler-7f8c2474-49a2-4ba7-8c60-d9c4ba8bf11d@10.0.49.2:32874
I1213 17:00:06.862275 22409 master.cpp:2274] Authorizing framework principal 'test-principal' to receive offers for roles '{ * }'
I1213 17:00:06.862427 22409 master.cpp:3037] Subscribing framework default with checkpointing disabled and capabilities [ MULTI_ROLE, RESERVATION_REFINEMENT, PARTITION_AWARE ]
I1213 17:00:06.862484 22409 master.cpp:7194] Updating framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001 (default) with roles { } suppressed
I1213 17:00:06.862660 22388 hierarchical.cpp:371] Activated framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001
I1213 17:00:06.862809 22409 master.cpp:3037] Subscribing framework default with checkpointing disabled and capabilities [ MULTI_ROLE, RESERVATION_REFINEMENT ]
I1213 17:00:06.862828 22418 sched.cpp:751] Framework registered with ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001
I1213 17:00:06.862874 22388 hierarchical.cpp:1517] Performed allocation for 1 agents in 95131ns
I1213 17:00:06.862917 22409 master.cpp:7194] Updating framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000 (default) with roles { } suppressed
I1213 17:00:06.862922 22412 slave.cpp:3546] Updating info for framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0001 with pid updated to scheduler-a872070c-2629-4049-a411-7ecb4fe83cc0@10.0.49.2:32874
I1213 17:00:06.862989 22418 sched.cpp:765] Scheduler::registered took 31340ns
I1213 17:00:06.863116 22412 task_status_update_manager.cpp:188] Resuming sending task status updates
I1213 17:00:06.863167 22418 hierarchical.cpp:371] Activated framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000
I1213 17:00:06.863276 22412 sched.cpp:751] Framework registered with ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000
I1213 17:00:06.863335 22412 sched.cpp:765] Scheduler::registered took 25596ns
I1213 17:00:06.863353 22409 slave.cpp:3546] Updating info for framework ccc06cbb-4a30-40ac-bfb2-220c5af2000d-0000 with pid updated to scheduler-7f8c2474-49a2-4ba7-8c60-d9c4ba8bf11d@10.0.49.2:32874
I1213 17:00:06.863428 22418 hierarchical.cpp:1517] Performed allocation for 1 agents in 116249ns
I1213 17:00:06.863477 22391 task_status_update_manager.cpp:188] Resuming sending task status updates
../../src/tests/partition_tests.cpp:1032: Failure
Failed to wait 15secs for runningAgainStatus1
*** Aborted at 1513213221 (unix time) try "date -d @1513213221" if you are using GNU date ***
PC: @ 0x55d1a60481d4 (unknown)
*** SIGSEGV (@0x0) received by PID 22366 (TID 0x7f45990f3b00) from PID 0; stack trace: ***
@ 0x7f458a3795e0 (unknown)
@ 0x55d1a60481d4 (unknown)
@ 0x55d1a603b313 (unknown)
@ 0x55d1a549ee71 (unknown)
@ 0x55d1a606760c (unknown)
@ 0x55d1a6061c82 (unknown)
@ 0x55d1a6041ef9 (unknown)
@ 0x55d1a6042712 (unknown)
@ 0x55d1a6042d58 (unknown)
@ 0x55d1a60496ac (unknown)
@ 0x55d1a6068231 (unknown)
@ 0x55d1a60627ca (unknown)
@ 0x55d1a60483f2 (unknown)
@ 0x55d1a5038117 (unknown)
@ 0x55d1a5037b9c (unknown)
@ 0x7f458939cc05 __libc_start_main
@ 0x55d1a45d5029 (unknown)
Segmentation fault (core dumped)
[gmann@core-dev build]$ I1213 17:00:22.195058 22994 exec.cpp:517] Agent exited ... shutting down
I1213 17:00:22.195103 22860 exec.cpp:517] Agent exited ... shutting down
I1213 17:00:22.195502 22953 executor.cpp:171] Received SHUTDOWN event
I1213 17:00:22.195500 22864 executor.cpp:171] Received SHUTDOWN event
I1213 17:00:22.195619 22953 executor.cpp:747] Shutting down
I1213 17:00:22.195698 22864 executor.cpp:747] Shutting down
I1213 17:00:22.195744 22953 executor.cpp:854] Sending SIGTERM to process tree at pid 22997
I1213 17:00:22.195751 22864 executor.cpp:854] Sending SIGTERM to process tree at pid 22905
I1213 17:00:22.249955 22953 executor.cpp:867] Sent SIGTERM to the following process trees:
[
--- 22997 sleep 60
]
I1213 17:00:22.249999 22953 executor.cpp:871] Scheduling escalation to SIGKILL in 3secs from now
I1213 17:00:22.250804 22864 executor.cpp:867] Sent SIGTERM to the following process trees:
[
--- 22905 sleep 60
]
I1213 17:00:22.250846 22864 executor.cpp:871] Scheduling escalation to SIGKILL in 3secs from now
I1213 17:00:22.268270 22952 executor.cpp:929] Command terminated with signal Terminated (pid: 22997)
I1213 17:00:22.272511 22996 process.cpp:2139] Failed to shutdown socket with fd 9, address 10.0.49.2:56878: Transport endpoint is not connected
I1213 17:00:22.341544 22861 executor.cpp:929] Command terminated with signal Terminated (pid: 22905)
I1213 17:00:22.345190 22904 process.cpp:2139] Failed to shutdown socket with fd 9, address 10.0.49.2:56880: Transport endpoint is not connected
I1213 17:00:23.272308 22996 process.cpp:887] Failed to accept socket: future discarded
I1213 17:00:23.344892 22904 process.cpp:887] Failed to accept socket: future discarded
{code}
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)