You are viewing a plain text version of this content. The canonical link for it is here.
Posted to builds@mesos.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2020/08/31 16:57:10 UTC
Build failed in Jenkins: Mesos » Mesos-Reviewbot-Linux #247
See <https://ci-builds.apache.org/job/Mesos/job/Mesos-Reviewbot-Linux/247/display/redirect?page=changes>
Changes:
[Andrei Sekretenko] Fixed compilation failure due to -Wmissing-braces in `Master::Master()`.
[Andrei Sekretenko] Fixed distcheck failure due to wrongly referencing non-existent header.
------------------------------------------
[...truncated 13.69 MB...]
I0831 16:03:42.512357 5518 slave.cpp:1565] Authenticating with master master@172.17.0.2:39327
I0831 16:03:42.512444 5518 slave.cpp:1574] Using default CRAM-MD5 authenticatee
I0831 16:03:42.512745 5525 authenticatee.cpp:121] Creating new client SASL connection
I0831 16:03:42.513088 5540 master.cpp:9727] Authenticating slave(129)@172.17.0.2:39327
I0831 16:03:42.513221 5527 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(279)@172.17.0.2:39327
I0831 16:03:42.513484 5535 authenticator.cpp:98] Creating new server SASL connection
I0831 16:03:42.513829 5529 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0831 16:03:42.513895 5529 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0831 16:03:42.514077 5531 authenticator.cpp:204] Received SASL authentication start
I0831 16:03:42.514147 5531 authenticator.cpp:326] Authentication requires more steps
I0831 16:03:42.514256 5531 authenticatee.cpp:259] Received SASL authentication step
I0831 16:03:42.514384 5526 authenticator.cpp:232] Received SASL authentication step
I0831 16:03:42.514415 5526 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'e2c8098d0f04' server FQDN: 'e2c8098d0f04' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0831 16:03:42.514427 5526 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0831 16:03:42.514469 5526 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0831 16:03:42.514493 5526 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'e2c8098d0f04' server FQDN: 'e2c8098d0f04' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0831 16:03:42.514505 5526 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0831 16:03:42.514514 5526 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0831 16:03:42.514530 5526 authenticator.cpp:318] Authentication success
I0831 16:03:42.514627 5534 authenticatee.cpp:299] Authentication success
I0831 16:03:42.514734 5532 master.cpp:9759] Successfully authenticated principal 'test-principal' at slave(129)@172.17.0.2:39327
I0831 16:03:42.514782 5536 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(279)@172.17.0.2:39327
I0831 16:03:42.515065 5537 slave.cpp:1665] Successfully authenticated with master master@172.17.0.2:39327
I0831 16:03:42.515463 5537 slave.cpp:2131] Will retry registration in 3.70922ms if necessary
I0831 16:03:42.515609 5538 master.cpp:6221] Received register agent message from slave(129)@172.17.0.2:39327 (e2c8098d0f04)
I0831 16:03:42.515972 5538 master.cpp:3752] Authorizing principal 'test-principal' to perform action REGISTER_AGENT on ANY object
I0831 16:03:42.516472 5519 master.cpp:6288] Authorized registration of agent at slave(129)@172.17.0.2:39327 (e2c8098d0f04)
I0831 16:03:42.516590 5519 master.cpp:6400] Registering agent at slave(129)@172.17.0.2:39327 (e2c8098d0f04) with id e45ea530-e630-4cc8-95c8-c56929625397-S6
I0831 16:03:42.517753 5528 registrar.cpp:487] Applied 1 operations in 761047ns; attempting to update the registry
I0831 16:03:42.519011 5528 registrar.cpp:544] Successfully updated the registry in 0ns
I0831 16:03:42.519254 5535 master.cpp:6448] Admitted agent e45ea530-e630-4cc8-95c8-c56929625397-S6 at slave(129)@172.17.0.2:39327 (e2c8098d0f04)
I0831 16:03:42.519950 5535 master.cpp:6493] Registered agent e45ea530-e630-4cc8-95c8-c56929625397-S6 at slave(129)@172.17.0.2:39327 (e2c8098d0f04) with cpus:1; mem:100; disk:50; ports:[31000-32000]
I0831 16:03:42.520115 5531 slave.cpp:1698] Registered with master master@172.17.0.2:39327; given agent ID e45ea530-e630-4cc8-95c8-c56929625397-S6
I0831 16:03:42.520295 5522 task_status_update_manager.cpp:188] Resuming sending task status updates
I0831 16:03:42.520282 5520 hierarchical.cpp:1041] Added agent e45ea530-e630-4cc8-95c8-c56929625397-S6 (e2c8098d0f04) with cpus:1; mem:100; disk:50; ports:[31000-32000] (offered or allocated: {})
I0831 16:03:42.520500 5531 slave.cpp:1733] Checkpointing SlaveInfo to '/tmp/MasterAllocatorTest_0_MinAllocatableResources_DsHgZ8/meta/slaves/e45ea530-e630-4cc8-95c8-c56929625397-S6/slave.info'
I0831 16:03:42.520535 5532 status_update_manager_process.hpp:385] Resuming operation status update manager
I0831 16:03:42.520881 5520 hierarchical.cpp:1935] Performed allocation for 1 agents in 224692ns
I0831 16:03:42.521579 5531 slave.cpp:1793] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"k+GxcCQeTmObROw50RZiXw=="},"slave_id":{"value":"e45ea530-e630-4cc8-95c8-c56929625397-S6"},"update_oversubscribed_resources":false}
I0831 16:03:42.522325 5533 master.cpp:7635] Ignoring update on agent e45ea530-e630-4cc8-95c8-c56929625397-S6 at slave(129)@172.17.0.2:39327 (e2c8098d0f04) as it reports no changes
W0831 16:03:42.667043 5517 process.cpp:2877] Attempted to spawn already running process files@172.17.0.2:39327
I0831 16:03:42.667685 5517 resolver.cpp:69] Creating default secret resolver
I0831 16:03:42.668368 5517 containerizer.cpp:320] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
W0831 16:03:42.668928 5517 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges
W0831 16:03:42.668952 5517 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
W0831 16:03:42.668967 5517 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
I0831 16:03:42.668992 5517 provisioner.cpp:294] Using default backend 'copy'
I0831 16:03:42.671514 5517 cluster.cpp:620] Creating default 'local' authorizer
I0831 16:03:42.673806 5539 slave.cpp:281] Mesos agent started on (130)@172.17.0.2:39327
I0831 16:03:42.673830 5539 slave.cpp:282] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/GJoVR3/dXvsYN/store/appc" --authenticate_http_readonly="true" --authenticate_http_readwrite="false" --authenticatee="crammd5" --authentication_backoff_factor="1secs" --authentication_timeout_max="1mins" --authentication_timeout_min="5secs" --authorizer="local" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_destroy_timeout="1mins" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/GJoVR3/dXvsYN/credential" --default_role="*" --disallow_sharing_agent_ipc_namespace="false" --disallow_sharing_agent_pid_namespace="false" --disk_watch_interval="1mins" --docker="docker" --docker_ignore_runtime="false" --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/GJoVR3/dXvsYN/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --docker_volume_chown="false" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_reregistration_timeout="2secs" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/GJoVR3/dXvsYN/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/GJoVR3/dXvsYN/frameworks" --gc_delay="1weeks" --gc_disk_headroom="0.1" --gc_non_executor_container_sandboxes="false" --help="false" --hostname_lookup="true" --http_command_executor="false" --http_credentials="/tmp/GJoVR3/dXvsYN/http_credentials" --http_executor_domain_sockets="false" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/tmp/SRC/build/mesos-1.11.0/_build/sub/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --memory_profiling="false" --network_cni_metrics="true" --network_cni_root_dir_persist="false" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns" --quiet="false" --reconfiguration_policy="equal" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:1;mem:10;disk:10;ports:[1-10]" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/MasterAllocatorTest_0_MinAllocatableResources_UFpbkh" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_enable_support="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/MasterAllocatorTest_0_MinAllocatableResources_OGQUFK" --zk_session_timeout="10secs"
I0831 16:03:42.674268 5539 credentials.hpp:73] Loading credential for authentication from '/tmp/GJoVR3/dXvsYN/credential'
I0831 16:03:42.674415 5539 slave.cpp:314] Agent using credential for: test-principal
I0831 16:03:42.674437 5539 credentials.hpp:37] Loading credentials for authentication from '/tmp/GJoVR3/dXvsYN/http_credentials'
I0831 16:03:42.674633 5539 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
I0831 16:03:42.675132 5539 disk_profile_adaptor.cpp:78] Creating default disk profile adaptor module
I0831 16:03:42.676179 5539 slave.cpp:629] Agent resources: [{"name":"cpus","scalar":{"value":1.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":10.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":10.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":1,"end":10}]},"type":"RANGES"}]
I0831 16:03:42.676376 5539 slave.cpp:637] Agent attributes: [ ]
I0831 16:03:42.676390 5539 slave.cpp:646] Agent hostname: e2c8098d0f04
I0831 16:03:42.676558 5535 status_update_manager_process.hpp:379] Pausing operation status update manager
I0831 16:03:42.676594 5528 task_status_update_manager.cpp:181] Pausing sending task status updates
I0831 16:03:42.679180 5520 state.cpp:68] Recovering state from '/tmp/MasterAllocatorTest_0_MinAllocatableResources_OGQUFK/meta'
I0831 16:03:42.679502 5524 slave.cpp:7741] Finished recovering checkpointed state from '/tmp/MasterAllocatorTest_0_MinAllocatableResources_OGQUFK/meta', beginning agent recovery
I0831 16:03:42.680054 5537 task_status_update_manager.cpp:207] Recovering task status update manager
I0831 16:03:42.680546 5531 containerizer.cpp:830] Recovering Mesos containers
I0831 16:03:42.680900 5531 containerizer.cpp:1170] Recovering isolators
I0831 16:03:42.681877 5529 containerizer.cpp:1209] Recovering provisioner
I0831 16:03:42.682857 5526 provisioner.cpp:518] Provisioner recovery complete
I0831 16:03:42.684116 5536 composing.cpp:343] Finished recovering all containerizers
I0831 16:03:42.684410 5533 slave.cpp:8223] Recovering executors
I0831 16:03:42.684516 5533 slave.cpp:8376] Finished recovery
I0831 16:03:42.685353 5525 task_status_update_manager.cpp:181] Pausing sending task status updates
I0831 16:03:42.685389 5518 slave.cpp:1473] New master detected at master@172.17.0.2:39327
I0831 16:03:42.685403 5521 status_update_manager_process.hpp:379] Pausing operation status update manager
I0831 16:03:42.685506 5518 slave.cpp:1538] Detecting new master
I0831 16:03:42.686991 5538 slave.cpp:1565] Authenticating with master master@172.17.0.2:39327
I0831 16:03:42.687072 5538 slave.cpp:1574] Using default CRAM-MD5 authenticatee
I0831 16:03:42.687345 5531 authenticatee.cpp:121] Creating new client SASL connection
I0831 16:03:42.687605 5535 master.cpp:9727] Authenticating slave(130)@172.17.0.2:39327
I0831 16:03:42.687825 5529 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(280)@172.17.0.2:39327
I0831 16:03:42.688329 5528 authenticator.cpp:98] Creating new server SASL connection
I0831 16:03:42.688627 5532 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0831 16:03:42.688653 5532 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0831 16:03:42.688760 5532 authenticator.cpp:204] Received SASL authentication start
I0831 16:03:42.688822 5532 authenticator.cpp:326] Authentication requires more steps
I0831 16:03:42.688946 5532 authenticatee.cpp:259] Received SASL authentication step
I0831 16:03:42.689067 5530 authenticator.cpp:232] Received SASL authentication step
I0831 16:03:42.689100 5530 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'e2c8098d0f04' server FQDN: 'e2c8098d0f04' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0831 16:03:42.689112 5530 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0831 16:03:42.689152 5530 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0831 16:03:42.689175 5530 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'e2c8098d0f04' server FQDN: 'e2c8098d0f04' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0831 16:03:42.689188 5530 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0831 16:03:42.689195 5530 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0831 16:03:42.689211 5530 authenticator.cpp:318] Authentication success
I0831 16:03:42.689357 5539 authenticatee.cpp:299] Authentication success
I0831 16:03:42.689400 5524 master.cpp:9759] Successfully authenticated principal 'test-principal' at slave(130)@172.17.0.2:39327
I0831 16:03:42.689455 5534 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(280)@172.17.0.2:39327
I0831 16:03:42.690035 5520 slave.cpp:1665] Successfully authenticated with master master@172.17.0.2:39327
I0831 16:03:42.690783 5520 slave.cpp:2131] Will retry registration in 10.30743ms if necessary
I0831 16:03:42.690944 5527 master.cpp:6221] Received register agent message from slave(130)@172.17.0.2:39327 (e2c8098d0f04)
I0831 16:03:42.691321 5527 master.cpp:3752] Authorizing principal 'test-principal' to perform action REGISTER_AGENT on ANY object
I0831 16:03:42.691946 5518 master.cpp:6288] Authorized registration of agent at slave(130)@172.17.0.2:39327 (e2c8098d0f04)
I0831 16:03:42.692045 5518 master.cpp:6400] Registering agent at slave(130)@172.17.0.2:39327 (e2c8098d0f04) with id e45ea530-e630-4cc8-95c8-c56929625397-S7
I0831 16:03:42.692826 5540 registrar.cpp:487] Applied 1 operations in 379526ns; attempting to update the registry
I0831 16:03:42.693604 5540 registrar.cpp:544] Successfully updated the registry in 0ns
I0831 16:03:42.693862 5528 master.cpp:6448] Admitted agent e45ea530-e630-4cc8-95c8-c56929625397-S7 at slave(130)@172.17.0.2:39327 (e2c8098d0f04)
I0831 16:03:42.695232 5524 slave.cpp:1698] Registered with master master@172.17.0.2:39327; given agent ID e45ea530-e630-4cc8-95c8-c56929625397-S7
I0831 16:03:42.695212 5528 master.cpp:6493] Registered agent e45ea530-e630-4cc8-95c8-c56929625397-S7 at slave(130)@172.17.0.2:39327 (e2c8098d0f04) with cpus:1; mem:10; disk:10; ports:[1-10]
I0831 16:03:42.695261 5532 hierarchical.cpp:1041] Added agent e45ea530-e630-4cc8-95c8-c56929625397-S7 (e2c8098d0f04) with cpus:1; mem:10; disk:10; ports:[1-10] (offered or allocated: {})
I0831 16:03:42.695355 5537 task_status_update_manager.cpp:188] Resuming sending task status updates
I0831 16:03:42.695595 5532 hierarchical.cpp:1935] Performed allocation for 1 agents in 166366ns
I0831 16:03:42.695634 5524 slave.cpp:1733] Checkpointing SlaveInfo to '/tmp/MasterAllocatorTest_0_MinAllocatableResources_OGQUFK/meta/slaves/e45ea530-e630-4cc8-95c8-c56929625397-S7/slave.info'
I0831 16:03:42.695761 5539 status_update_manager_process.hpp:385] Resuming operation status update manager
I0831 16:03:42.696761 5524 slave.cpp:1793] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"OZouIDErT+eKXpv91VfrRg=="},"slave_id":{"value":"e45ea530-e630-4cc8-95c8-c56929625397-S7"},"update_oversubscribed_resources":false}
I0831 16:03:42.697450 5524 master.cpp:7635] Ignoring update on agent e45ea530-e630-4cc8-95c8-c56929625397-S7 at slave(130)@172.17.0.2:39327 (e2c8098d0f04) as it reports no changes
W0831 16:03:42.844776 5517 process.cpp:2877] Attempted to spawn already running process version@172.17.0.2:39327
I0831 16:03:42.845747 5517 sched.cpp:239] Version: 1.11.0
I0831 16:03:42.846508 5535 sched.cpp:343] New master detected at master@172.17.0.2:39327
I0831 16:03:42.846601 5535 sched.cpp:408] Authenticating with master master@172.17.0.2:39327
I0831 16:03:42.846630 5535 sched.cpp:415] Using default CRAM-MD5 authenticatee
I0831 16:03:42.846935 5540 authenticatee.cpp:121] Creating new client SASL connection
I0831 16:03:42.847234 5535 master.cpp:9727] Authenticating scheduler-61acd792-9331-4b91-8493-82d76a28a9d8@172.17.0.2:39327
I0831 16:03:42.847419 5528 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(281)@172.17.0.2:39327
I0831 16:03:42.847862 5537 authenticator.cpp:98] Creating new server SASL connection
I0831 16:03:42.848100 5532 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0831 16:03:42.848129 5532 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0831 16:03:42.848249 5532 authenticator.cpp:204] Received SASL authentication start
I0831 16:03:42.848299 5532 authenticator.cpp:326] Authentication requires more steps
I0831 16:03:42.848412 5532 authenticatee.cpp:259] Received SASL authentication step
I0831 16:03:42.848541 5532 authenticator.cpp:232] Received SASL authentication step
I0831 16:03:42.848580 5532 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'e2c8098d0f04' server FQDN: 'e2c8098d0f04' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0831 16:03:42.848592 5532 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0831 16:03:42.848620 5532 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0831 16:03:42.848644 5532 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'e2c8098d0f04' server FQDN: 'e2c8098d0f04' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0831 16:03:42.848655 5532 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0831 16:03:42.848664 5532 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0831 16:03:42.848678 5532 authenticator.cpp:318] Authentication success
I0831 16:03:42.848889 5520 authenticatee.cpp:299] Authentication success
I0831 16:03:42.849017 5523 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(281)@172.17.0.2:39327
I0831 16:03:42.849050 5519 master.cpp:9759] Successfully authenticated principal 'test-principal' at scheduler-61acd792-9331-4b91-8493-82d76a28a9d8@172.17.0.2:39327
I0831 16:03:42.849587 5525 sched.cpp:520] Successfully authenticated with master master@172.17.0.2:39327
I0831 16:03:42.849647 5525 sched.cpp:835] Sending SUBSCRIBE call to master@172.17.0.2:39327
I0831 16:03:42.849937 5525 sched.cpp:870] Will retry registration in 511.404882ms if necessary
I0831 16:03:42.850317 5521 master.cpp:2941] Received SUBSCRIBE call for framework 'default' at scheduler-61acd792-9331-4b91-8493-82d76a28a9d8@172.17.0.2:39327
I0831 16:03:42.854317 5526 master.cpp:3024] Subscribing framework default with checkpointing disabled and capabilities [ MULTI_ROLE, RESERVATION_REFINEMENT ]
I0831 16:03:42.858319 5526 master.cpp:9958] Adding framework e45ea530-e630-4cc8-95c8-c56929625397-0000 (default) at scheduler-61acd792-9331-4b91-8493-82d76a28a9d8@172.17.0.2:39327 with roles { } suppressed
I0831 16:03:42.859375 5528 sched.cpp:751] Framework registered with e45ea530-e630-4cc8-95c8-c56929625397-0000
I0831 16:03:42.859489 5528 sched.cpp:770] Scheduler::registered took 48780ns
I0831 16:03:42.859745 5535 hierarchical.cpp:774] Added framework e45ea530-e630-4cc8-95c8-c56929625397-0000
I0831 16:03:42.862994 5535 hierarchical.cpp:1935] Performed allocation for 8 agents in 2.845293ms
I0831 16:03:42.864413 5537 master.cpp:9536] Sending offers [ e45ea530-e630-4cc8-95c8-c56929625397-O0, e45ea530-e630-4cc8-95c8-c56929625397-O1, e45ea530-e630-4cc8-95c8-c56929625397-O2, e45ea530-e630-4cc8-95c8-c56929625397-O3 ] to framework e45ea530-e630-4cc8-95c8-c56929625397-0000 (default) at scheduler-61acd792-9331-4b91-8493-82d76a28a9d8@172.17.0.2:39327
I0831 16:03:42.866115 5539 sched.cpp:934] Scheduler::resourceOffers took 204795ns
I0831 16:03:42.866313 5517 sched.cpp:2166] Asked to stop the driver
I0831 16:03:42.866462 5534 sched.cpp:1204] Stopping framework e45ea530-e630-4cc8-95c8-c56929625397-0000
I0831 16:03:42.866765 5536 master.cpp:10323] Processing TEARDOWN call for framework e45ea530-e630-4cc8-95c8-c56929625397-0000 (default) at scheduler-61acd792-9331-4b91-8493-82d76a28a9d8@172.17.0.2:39327
I0831 16:03:42.866796 5536 master.cpp:10335] Removing framework e45ea530-e630-4cc8-95c8-c56929625397-0000 (default) at scheduler-61acd792-9331-4b91-8493-82d76a28a9d8@172.17.0.2:39327
I0831 16:03:42.866812 5536 master.cpp:3385] Deactivating framework e45ea530-e630-4cc8-95c8-c56929625397-0000 (default) at scheduler-61acd792-9331-4b91-8493-82d76a28a9d8@172.17.0.2:39327
I0831 16:03:42.867172 5533 hierarchical.cpp:887] Deactivated framework e45ea530-e630-4cc8-95c8-c56929625397-0000
I0831 16:03:42.867489 5536 master.cpp:11834] Removing offer e45ea530-e630-4cc8-95c8-c56929625397-O3
I0831 16:03:42.867892 5518 slave.cpp:1002] Agent terminating
I0831 16:03:42.867866 5533 hierarchical.cpp:1658] Recovered ports(allocated: *):[31000-32000]; cpus(allocated: *):1; mem(allocated: *):100; disk(allocated: *):50 (total: cpus:1; mem:100; disk:50; ports:[31000-32000], offered or allocated: {}) on agent e45ea530-e630-4cc8-95c8-c56929625397-S6 from framework e45ea530-e630-4cc8-95c8-c56929625397-0000
I0831 16:03:42.868019 5536 master.cpp:11834] Removing offer e45ea530-e630-4cc8-95c8-c56929625397-O2
I0831 16:03:42.868414 5536 master.cpp:11834] Removing offer e45ea530-e630-4cc8-95c8-c56929625397-O1
I0831 16:03:42.868865 5536 master.cpp:11834] Removing offer e45ea530-e630-4cc8-95c8-c56929625397-O0
I0831 16:03:42.869151 5534 slave.cpp:4285] Asked to shut down framework e45ea530-e630-4cc8-95c8-c56929625397-0000 by master@172.17.0.2:39327
I0831 16:03:42.869187 5534 slave.cpp:4300] Cannot shut down unknown framework e45ea530-e630-4cc8-95c8-c56929625397-0000
I0831 16:03:42.869179 5541 slave.cpp:4285] Asked to shut down framework e45ea530-e630-4cc8-95c8-c56929625397-0000 by master@172.17.0.2:39327
I0831 16:03:42.869172 5535 slave.cpp:4285] Asked to shut down framework e45ea530-e630-4cc8-95c8-c56929625397-0000 by master@172.17.0.2:39327
I0831 16:03:42.869235 5539 slave.cpp:4285] Asked to shut down framework e45ea530-e630-4cc8-95c8-c56929625397-0000 by master@172.17.0.2:39327
I0831 16:03:42.869223 5541 slave.cpp:4300] Cannot shut down unknown framework e45ea530-e630-4cc8-95c8-c56929625397-0000
I0831 16:03:42.869241 5524 slave.cpp:4285] Asked to shut down framework e45ea530-e630-4cc8-95c8-c56929625397-0000 by master@172.17.0.2:39327
I0831 16:03:42.869271 5539 slave.cpp:4300] Cannot shut down unknown framework e45ea530-e630-4cc8-95c8-c56929625397-0000
I0831 16:03:42.869277 5535 slave.cpp:4300] Cannot shut down unknown framework e45ea530-e630-4cc8-95c8-c56929625397-0000
I0831 16:03:42.869297 5524 slave.cpp:4300] Cannot shut down unknown framework e45ea530-e630-4cc8-95c8-c56929625397-0000
I0831 16:03:42.869297 5519 slave.cpp:4285] Asked to shut down framework e45ea530-e630-4cc8-95c8-c56929625397-0000 by master@172.17.0.2:39327
I0831 16:03:42.869338 5532 slave.cpp:4285] Asked to shut down framework e45ea530-e630-4cc8-95c8-c56929625397-0000 by master@172.17.0.2:39327
I0831 16:03:42.869379 5519 slave.cpp:4300] Cannot shut down unknown framework e45ea530-e630-4cc8-95c8-c56929625397-0000
I0831 16:03:42.869390 5532 slave.cpp:4300] Cannot shut down unknown framework e45ea530-e630-4cc8-95c8-c56929625397-0000
I0831 16:03:42.869721 5536 master.cpp:1297] Agent e45ea530-e630-4cc8-95c8-c56929625397-S0 at slave(123)@172.17.0.2:39327 (e2c8098d0f04) disconnected
I0831 16:03:42.869747 5536 master.cpp:3420] Disconnecting agent e45ea530-e630-4cc8-95c8-c56929625397-S0 at slave(123)@172.17.0.2:39327 (e2c8098d0f04)
I0831 16:03:42.869807 5536 master.cpp:3439] Deactivating agent e45ea530-e630-4cc8-95c8-c56929625397-S0 at slave(123)@172.17.0.2:39327 (e2c8098d0f04)
I0831 16:03:42.870396 5533 hierarchical.cpp:1658] Recovered ports(allocatBuild timed out (after 240 minutes). Marking the build as failed.
ed: *):[1-10]; cpus(allocated: *):1; mem(allocated: *):10; disk(allocated: *):10 (total: cpus:1; mem:10; disk:10; ports:[1-10], offered or allocated: {}) on agent e45ea530-e630-4cc8-95c8-c56929625397-S7 from framework e45ea530-e630-4cc8-95c8-c56929625397-0000
I0831 16:03:42.872684 5533 hierarchical.cpp:1658] Recovered ports(allocated: *):[1-5]; cpus(allocated: *):1; mem(allocated: *):100 (total: cpus:1; mem:100; ports:[1-5], offered or allocated: {}) on agent e45ea530-e630-4cc8-95c8-c56929625397-S4 from framework e45ea530-e630-4cc8-95c8-c56929625397-0000
I0831 16:03:42.874663 5533 hierarchical.cpp:1658] Recovered ports(allocated: *):[1-5]; cpus(allocated: *):0.5; mem(allocated: *):10; disk(allocated: *):100 (total: cpus:0.5; mem:10; disk:100; ports:[1-5], offered or allocated: {}) on agent e45ea530-e630-4cc8-95c8-c56929625397-S5 from framework e45ea530-e630-4cc8-95c8-c56929625397-0000
I0831 16:03:42.876471 5533 hierarchical.cpp:1859] Allocation paused
I0831 16:03:42.877189 5533 hierarchical.cpp:831] Removed framework e45ea530-e630-4cc8-95c8-c56929625397-0000
I0831 16:03:42.877282 5533 hierarchical.cpp:1869] Allocation resumed
I0831 16:03:42.877362 5533 hierarchical.cpp:1238] Agent e45ea530-e630-4cc8-95c8-c56929625397-S0 deactivated
I0831 16:03:42.879895 5531 hierarchical.cpp:1935] Performed allocation for 8 agents in 390142ns
I0831 16:03:42.891081 5539 slave.cpp:1002] Agent terminating
I0831 16:03:42.892205 5529 master.cpp:1297] Agent e45ea530-e630-4cc8-95c8-c56929625397-S1 at slave(124)@172.17.0.2:39327 (e2c8098d0f04) disconnected
I0831 16:03:42.892256 5529 master.cpp:3420] Disconnecting agent e45ea530-e630-4cc8-95c8-c56929625397-S1 at slave(124)@172.17.0.2:39327 (e2c8098d0f04)
I0831 16:03:42.892318 5529 master.cpp:3439] Deactivating agent e45ea530-e630-4cc8-95c8-c56929625397-S1 at slave(124)@172.17.0.2:39327 (e2c8098d0f04)
I0831 16:03:42.892462 5531 hierarchical.cpp:1238] Agent e45ea530-e630-4cc8-95c8-c56929625397-S1 deactivated
I0831 16:03:42.902570 5519 slave.cpp:1002] Agent terminating
I0831 16:03:42.903789 5527 master.cpp:1297] Agent e45ea530-e630-4cc8-95c8-c56929625397-S2 at slave(125)@172.17.0.2:39327 (e2c8098d0f04) disconnected
I0831 16:03:42.903834 5527 master.cpp:3420] Disconnecting agent e45ea530-e630-4cc8-95c8-c56929625397-S2 at slave(125)@172.17.0.2:39327 (e2c8098d0f04)
I0831 16:03:42.903903 5527 master.cpp:3439] Deactivating agent e45ea530-e630-4cc8-95c8-c56929625397-S2 at slave(125)@172.17.0.2:39327 (e2c8098d0f04)
I0831 16:03:42.904047 5528 hierarchical.cpp:1238] Agent e45ea530-e630-4cc8-95c8-c56929625397-S2 deactivated
I0831 16:03:42.914711 5517 slave.cpp:1002] Agent terminating
I0831 16:03:42.915796 5519 master.cpp:1297] Agent e45ea530-e630-4cc8-95c8-c56929625397-S3 at slave(126)@172.17.0.2:39327 (e2c8098d0f04) disconnected
I0831 16:03:42.915836 5519 master.cpp:3420] Disconnecting agent e45ea530-e630-4cc8-95c8-c56929625397-S3 at slave(126)@172.17.0.2:39327 (e2c8098d0f04)
I0831 16:03:42.915930 5519 master.cpp:3439] Deactivating agent e45ea530-e630-4cc8-95c8-c56929625397-S3 at slave(126)@172.17.0.2:39327 (e2c8098d0f04)
I0831 16:03:42.916137 5521 hierarchical.cpp:1238] Agent e45ea530-e630-4cc8-95c8-c56929625397-S3 deactivated
I0831 16:03:42.926681 5517 slave.cpp:1002] Agent terminating
I0831 16:03:42.927444 5519 master.cpp:1297] Agent e45ea530-e630-4cc8-95c8-c56929625397-S4 at slave(127)@172.17.0.2:39327 (e2c8098d0f04) disconnected
I0831 16:03:42.927470 5519 master.cpp:3420] Disconnecting agent e45ea530-e630-4cc8-95c8-c56929625397-S4 at slave(127)@172.17.0.2:39327 (e2c8098d0f04)
I0831 16:03:42.927536 5519 master.cpp:3439] Deactivating agent e45ea530-e630-4cc8-95c8-c56929625397-S4 at slave(127)@172.17.0.2:39327 (e2c8098d0f04)
I0831 16:03:42.927666 5518 hierarchical.cpp:1238] Agent e45ea530-e630-4cc8-95c8-c56929625397-S4 deactivated
I0831 16:03:42.935750 5517 slave.cpp:1002] Agent terminating
I0831 16:03:42.936637 5519 master.cpp:1297] Agent e45ea530-e630-4cc8-95c8-c56929625397-S5 at slave(128)@172.17.0.2:39327 (e2c8098d0f04) disconnected
I0831 16:03:42.936666 5519 master.cpp:3420] Disconnecting agent e45ea530-e630-4cc8-95c8-c56929625397-S5 at slave(128)@172.17.0.2:39327 (e2c8098d0f04)
I0831 16:03:42.936733 5519 master.cpp:3439] Deactivating agent e45ea530-e630-4cc8-95c8-c56929625397-S5 at slave(128)@172.17.0.2:39327 (e2c8098d0f04)
I0831 16:03:42.936895 5534 hierarchical.cpp:1238] Agent e45ea530-e630-4cc8-95c8-c56929625397-S5 deactivated
I0831 16:03:42.943979 5517 slave.cpp:1002] Agent terminating
I0831 16:03:42.944746 5520 master.cpp:1297] Agent e45ea530-e630-4cc8-95c8-c56929625397-S6 at slave(129)@172.17.0.2:39327 (e2c8098d0f04) disconnected
I0831 16:03:42.944770 5520 master.cpp:3420] Disconnecting agent e45ea530-e630-4cc8-95c8-c56929625397-S6 at slave(129)@172.17.0.2:39327 (e2c8098d0f04)
I0831 16:03:42.944828 5520 master.cpp:3439] Deactivating agent e45ea530-e630-4cc8-95c8-c56929625397-S6 at slave(129)@172.17.0.2:39327 (e2c8098d0f04)
I0831 16:03:42.945029 5530 hierarchical.cpp:1238] Agent e45ea530-e630-4cc8-95c8-c56929625397-S6 deactivated
I0831 16:03:42.953037 5517 slave.cpp:1002] Agent terminating
I0831 16:03:42.953830 5520 master.cpp:1297] Agent e45ea530-e630-4cc8-95c8-c56929625397-S7 at slave(130)@172.17.0.2:39327 (e2c8098d0f04) disconnected
I0831 16:03:42.953856 5520 master.cpp:3420] Disconnecting agent e45ea530-e630-4cc8-95c8-c56929625397-S7 at slave(130)@172.17.0.2:39327 (e2c8098d0f04)
I0831 16:03:42.953922 5520 master.cpp:3439] Deactivating agent e45ea530-e630-4cc8-95c8-c56929625397-S7 at slave(130)@172.17.0.2:39327 (e2c8098d0f04)
I0831 16:03:42.954128 5530 hierarchical.cpp:1238] Agent e45ea530-e630-4cc8-95c8-c56929625397-S7 deactivated
I0831 16:03:42.962854 5517 master.cpp:1145] Master terminating
I0831 16:03:42.963196 5531 hierarchical.cpp:1214] Removed all filters for agent e45ea530-e630-4cc8-95c8-c56929625397-S6
I0831 16:03:42.963223 5531 hierarchical.cpp:1090] Removed agent e45ea530-e630-4cc8-95c8-c56929625397-S6
I0831 16:03:42.963555 5519 hierarchical.cpp:1214] Removed all filters for agent e45ea530-e630-4cc8-95c8-c56929625397-S5
I0831 16:03:42.963584 5519 hierarchical.cpp:1090] Removed agent e45ea530-e630-4cc8-95c8-c56929625397-S5
I0831 16:03:42.963871 5523 hierarchical.cpp:1214] Removed all filters for agent e45ea530-e630-4cc8-95c8-c56929625397-S4
I0831 16:03:42.963901 5523 hierarchical.cpp:1090] Removed agent e45ea530-e630-4cc8-95c8-c56929625397-S4
I0831 16:03:42.964370 5530 hierarchical.cpp:1214] Removed all filters for agent e45ea530-e630-4cc8-95c8-c56929625397-S0
I0831 16:03:42.964418 5530 hierarchical.cpp:1090] Removed agent e45ea530-e630-4cc8-95c8-c56929625397-S0
I0831 16:03:42.964710 5530 hierarchical.cpp:1214] Removed all filters for agent e45ea530-e630-4cc8-95c8-c56929625397-S7
I0831 16:03:42.964752 5530 hierarchical.cpp:1090] Removed agent e45ea530-e630-4cc8-95c8-c56929625397-S7
I0831 16:03:42.965034 5530 hierarchical.cpp:1214] Removed all filters for agent e45ea530-e630-4cc8-95c8-c56929625397-S1
I0831 16:03:42.965072 5530 hierarchical.cpp:1090] Removed agent e45ea530-e630-4cc8-95c8-c56929625397-S1
I0831 16:03:42.965384 5530 hierarchical.cpp:1214] Removed all filters for agent e45ea530-e630-4cc8-95c8-c56929625397-S2
I0831 16:03:42.965423 5530 hierarchical.cpp:1090] Removed agent e45ea530-e630-4cc8-95c8-c56929625397-S2
I0831 16:03:42.965713 5530 hierarchical.cpp:1214] Removed all filters for agent e45ea530-e630-4cc8-95c8-c56929625397-S3
I0831 16:03:42.965754 5530 hierarchical.cpp:1090] Removed agent e45ea530-e630-4cc8-95c8-c56929625397-S3
[ OK ] MasterAllocatorTest/0.MinAllocatableResources (1870 ms)
[ RUN ] MasterAllocatorTest/0.Whitelist
I0831 16:03:42.988225 5517 cluster.cpp:195] Creating default 'local' authorizer
I0831 16:03:42.992883 5534 master.cpp:448] Master 8ebed9f9-31f1-477d-9d11-dfe2d7188b40 (e2c8098d0f04) started on 172.17.0.2:39327
I0831 16:03:42.992908 5534 master.cpp:451] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="1secs" --allocator="hierarchical" --authenticate_agents="true" --authenticate_frameworks="true" --authenticate_http_frameworBuild was aborted
ks="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authentication_v0_timeout="15secs" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/DJLGOo/credentials" --filter_gpu_resources="true" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_framework_authenticators="basic" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --max_operator_event_stream_subscribers="1000" --max_unreachable_tasks_per_framework="1000" --memory_profiling="false" --min_allocatable_resources="cpus:0.01|mem:32" --offer_constraints_re2_max_mem="4KB" --offer_constraints_re2_max_program_size="100" --port="5050" --publish_per_framework_metrics="true" --quiet="false" --recovery_agent_removal_limit="100%" --registry="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" --require_agent_domain="false" --role_sorter="drf" --root_submissions="true" --version="false" --webui_dir="/tmp/SRC/build/mesos-1.11.0/_inst/share/mesos/webui" --whitelist="whitelist.txt" --work_dir="/tmp/DJLGOo/master" --zk_session_timeout="10secs"
I0831 16:03:42.993304 5534 master.cpp:500] Master only allowing authenticated frameworks to register
I0831 16:03:42.993317 5534 master.cpp:506] Master only allowing authenticated agents to register
Jenkins build is back to normal : Mesos » Mesos-Reviewbot-Linux #252
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://ci-builds.apache.org/job/Mesos/job/Mesos-Reviewbot-Linux/252/display/redirect>
Build failed in Jenkins: Mesos » Mesos-Reviewbot-Linux #251
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://ci-builds.apache.org/job/Mesos/job/Mesos-Reviewbot-Linux/251/display/redirect>
Changes:
------------------------------------------
[...truncated 13.44 MB...]
I0901 08:17:40.452705 5527 slave.cpp:637] Agent attributes: [ ]
I0901 08:17:40.452718 5527 slave.cpp:646] Agent hostname: 0f73b3326edc
I0901 08:17:40.453037 5524 status_update_manager_process.hpp:379] Pausing operation status update manager
I0901 08:17:40.453060 5523 task_status_update_manager.cpp:181] Pausing sending task status updates
I0901 08:17:40.454382 5515 state.cpp:68] Recovering state from '/tmp/MasterAllocatorTest_0_SlaveLost_cpbrRU/meta'
I0901 08:17:40.454814 5525 slave.cpp:7741] Finished recovering checkpointed state from '/tmp/MasterAllocatorTest_0_SlaveLost_cpbrRU/meta', beginning agent recovery
I0901 08:17:40.455665 5520 task_status_update_manager.cpp:207] Recovering task status update manager
I0901 08:17:40.456362 5528 containerizer.cpp:830] Recovering Mesos containers
I0901 08:17:40.456758 5528 containerizer.cpp:1170] Recovering isolators
I0901 08:17:40.457690 5518 containerizer.cpp:1209] Recovering provisioner
I0901 08:17:40.458956 5519 provisioner.cpp:518] Provisioner recovery complete
I0901 08:17:40.459820 5527 composing.cpp:343] Finished recovering all containerizers
I0901 08:17:40.460089 5511 slave.cpp:8223] Recovering executors
I0901 08:17:40.460198 5511 slave.cpp:8376] Finished recovery
I0901 08:17:40.461585 5522 task_status_update_manager.cpp:181] Pausing sending task status updates
I0901 08:17:40.461628 5521 status_update_manager_process.hpp:379] Pausing operation status update manager
I0901 08:17:40.461601 5511 slave.cpp:1473] New master detected at master@172.17.0.3:34493
I0901 08:17:40.461843 5511 slave.cpp:1538] Detecting new master
I0901 08:17:40.466346 5532 slave.cpp:1565] Authenticating with master master@172.17.0.3:34493
I0901 08:17:40.466532 5532 slave.cpp:1574] Using default CRAM-MD5 authenticatee
I0901 08:17:40.466922 5528 authenticatee.cpp:121] Creating new client SASL connection
I0901 08:17:40.467291 5523 master.cpp:9727] Authenticating slave(117)@172.17.0.3:34493
I0901 08:17:40.467558 5518 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(264)@172.17.0.3:34493
I0901 08:17:40.468091 5531 authenticator.cpp:98] Creating new server SASL connection
I0901 08:17:40.468533 5524 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0901 08:17:40.468592 5524 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0901 08:17:40.468780 5524 authenticator.cpp:204] Received SASL authentication start
I0901 08:17:40.468889 5524 authenticator.cpp:326] Authentication requires more steps
I0901 08:17:40.469058 5524 authenticatee.cpp:259] Received SASL authentication step
I0901 08:17:40.469246 5524 authenticator.cpp:232] Received SASL authentication step
I0901 08:17:40.469297 5524 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '0f73b3326edc' server FQDN: '0f73b3326edc' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0901 08:17:40.469324 5524 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0901 08:17:40.469395 5524 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0901 08:17:40.469439 5524 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '0f73b3326edc' server FQDN: '0f73b3326edc' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0901 08:17:40.469462 5524 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0901 08:17:40.469482 5524 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0901 08:17:40.469511 5524 authenticator.cpp:318] Authentication success
I0901 08:17:40.469703 5515 authenticatee.cpp:299] Authentication success
I0901 08:17:40.469863 5525 master.cpp:9759] Successfully authenticated principal 'test-principal' at slave(117)@172.17.0.3:34493
I0901 08:17:40.469877 5514 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(264)@172.17.0.3:34493
I0901 08:17:40.470511 5516 slave.cpp:1665] Successfully authenticated with master master@172.17.0.3:34493
I0901 08:17:40.471284 5516 slave.cpp:2131] Will retry registration in 17.00382ms if necessary
I0901 08:17:40.471475 5533 master.cpp:6221] Received register agent message from slave(117)@172.17.0.3:34493 (0f73b3326edc)
I0901 08:17:40.471907 5533 master.cpp:3752] Authorizing principal 'test-principal' to perform action REGISTER_AGENT on ANY object
I0901 08:17:40.472517 5521 master.cpp:6288] Authorized registration of agent at slave(117)@172.17.0.3:34493 (0f73b3326edc)
I0901 08:17:40.472692 5521 master.cpp:6400] Registering agent at slave(117)@172.17.0.3:34493 (0f73b3326edc) with id a7738cb3-b080-4ca4-bcd8-e8046bbcf5bb-S1
I0901 08:17:40.473467 5513 registrar.cpp:487] Applied 1 operations in 280295ns; attempting to update the registry
I0901 08:17:40.474102 5513 registrar.cpp:544] Successfully updated the registry in 557056ns
I0901 08:17:40.474330 5513 master.cpp:6448] Admitted agent a7738cb3-b080-4ca4-bcd8-e8046bbcf5bb-S1 at slave(117)@172.17.0.3:34493 (0f73b3326edc)
I0901 08:17:40.475019 5513 master.cpp:6493] Registered agent a7738cb3-b080-4ca4-bcd8-e8046bbcf5bb-S1 at slave(117)@172.17.0.3:34493 (0f73b3326edc) with cpus:3; mem:256; disk:1024; ports:[31000-32000]
I0901 08:17:40.475414 5529 hierarchical.cpp:1041] Added agent a7738cb3-b080-4ca4-bcd8-e8046bbcf5bb-S1 (0f73b3326edc) with cpus:3; mem:256; disk:1024; ports:[31000-32000] (offered or allocated: {})
I0901 08:17:40.475473 5519 slave.cpp:1698] Registered with master master@172.17.0.3:34493; given agent ID a7738cb3-b080-4ca4-bcd8-e8046bbcf5bb-S1
I0901 08:17:40.475734 5524 task_status_update_manager.cpp:188] Resuming sending task status updates
I0901 08:17:40.476184 5519 slave.cpp:1733] Checkpointing SlaveInfo to '/tmp/MasterAllocatorTest_0_SlaveLost_cpbrRU/meta/slaves/a7738cb3-b080-4ca4-bcd8-e8046bbcf5bb-S1/slave.info'
I0901 08:17:40.476327 5525 status_update_manager_process.hpp:385] Resuming operation status update manager
I0901 08:17:40.477620 5529 hierarchical.cpp:1935] Performed allocation for 1 agents in 1.771644ms
I0901 08:17:40.478152 5519 slave.cpp:1793] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"/76qu2FnQzewKeQ9aoPh9Q=="},"slave_id":{"value":"a7738cb3-b080-4ca4-bcd8-e8046bbcf5bb-S1"},"update_oversubscribed_resources":false}
I0901 08:17:40.478534 5517 master.cpp:9536] Sending offers [ a7738cb3-b080-4ca4-bcd8-e8046bbcf5bb-O1 ] to framework a7738cb3-b080-4ca4-bcd8-e8046bbcf5bb-0000 (default) at scheduler-c1f5712c-4f60-4d7b-8181-040a2d5a3f86@172.17.0.3:34493
I0901 08:17:40.479519 5522 sched.cpp:934] Scheduler::resourceOffers took 144779ns
I0901 08:17:40.479924 5517 master.cpp:7635] Ignoring update on agent a7738cb3-b080-4ca4-bcd8-e8046bbcf5bb-S1 at slave(117)@172.17.0.3:34493 (0f73b3326edc) as it reports no changes
I0901 08:17:40.481137 5510 sched.cpp:2166] Asked to stop the driver
I0901 08:17:40.481338 5528 sched.cpp:1204] Stopping framework a7738cb3-b080-4ca4-bcd8-e8046bbcf5bb-0000
I0901 08:17:40.481608 5512 master.cpp:10323] Processing TEARDOWN call for framework a7738cb3-b080-4ca4-bcd8-e8046bbcf5bb-0000 (default) at scheduler-c1f5712c-4f60-4d7b-8181-040a2d5a3f86@172.17.0.3:34493
I0901 08:17:40.481647 5512 master.cpp:10335] Removing framework a7738cb3-b080-4ca4-bcd8-e8046bbcf5bb-0000 (default) at scheduler-c1f5712c-4f60-4d7b-8181-040a2d5a3f86@172.17.0.3:34493
I0901 08:17:40.481667 5512 master.cpp:3385] Deactivating framework a7738cb3-b080-4ca4-bcd8-e8046bbcf5bb-0000 (default) at scheduler-c1f5712c-4f60-4d7b-8181-040a2d5a3f86@172.17.0.3:34493
I0901 08:17:40.482082 5531 hierarchical.cpp:887] Deactivated framework a7738cb3-b080-4ca4-bcd8-e8046bbcf5bb-0000
I0901 08:17:40.482350 5512 master.cpp:11834] Removing offer a7738cb3-b080-4ca4-bcd8-e8046bbcf5bb-O1
I0901 08:17:40.482507 5510 slave.cpp:1002] Agent terminating
I0901 08:17:40.482956 5531 hierarchical.cpp:1658] Recovered ports(allocated: *):[31000-32000]; cpus(allocated: *):3; mem(allocated: *):256; disk(allocated: *):1024 (total: cpus:3; mem:256; disk:1024; ports:[31000-32000], offered or allocated: {}) on agent a7738cb3-b080-4ca4-bcd8-e8046bbcf5bb-S1 from framework a7738cb3-b080-4ca4-bcd8-e8046bbcf5bb-0000
I0901 08:17:40.484767 5531 hierarchical.cpp:1859] Allocation paused
I0901 08:17:40.485359 5531 hierarchical.cpp:831] Removed framework a7738cb3-b080-4ca4-bcd8-e8046bbcf5bb-0000
I0901 08:17:40.485450 5531 hierarchical.cpp:1869] Allocation resumed
I0901 08:17:40.627272 5521 master.cpp:1297] Agent a7738cb3-b080-4ca4-bcd8-e8046bbcf5bb-S1 at slave(117)@172.17.0.3:34493 (0f73b3326edc) disconnected
I0901 08:17:40.627331 5521 master.cpp:3420] Disconnecting agent a7738cb3-b080-4ca4-bcd8-e8046bbcf5bb-S1 at slave(117)@172.17.0.3:34493 (0f73b3326edc)
I0901 08:17:40.627434 5521 master.cpp:3439] Deactivating agent a7738cb3-b080-4ca4-bcd8-e8046bbcf5bb-S1 at slave(117)@172.17.0.3:34493 (0f73b3326edc)
I0901 08:17:40.627660 5518 hierarchical.cpp:1238] Agent a7738cb3-b080-4ca4-bcd8-e8046bbcf5bb-S1 deactivated
I0901 08:17:40.644981 5510 master.cpp:1145] Master terminating
I0901 08:17:40.645311 5515 hierarchical.cpp:1214] Removed all filters for agent a7738cb3-b080-4ca4-bcd8-e8046bbcf5bb-S1
I0901 08:17:40.645337 5515 hierarchical.cpp:1090] Removed agent a7738cb3-b080-4ca4-bcd8-e8046bbcf5bb-S1
[ OK ] MasterAllocatorTest/0.SlaveLost (424 ms)
[ RUN ] MasterAllocatorTest/0.SlaveAdded
I0901 08:17:40.657145 5510 cluster.cpp:195] Creating default 'local' authorizer
I0901 08:17:40.661676 5533 master.cpp:448] Master 411a707d-17a7-4838-9b3a-3770d00bb1e0 (0f73b3326edc) started on 172.17.0.3:34493
I0901 08:17:40.661712 5533 master.cpp:451] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="50ms" --allocator="hierarchical" --authenticate_agents="true" --authenticate_frameworks="true" --authenticate_http_frameworks="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authentication_v0_timeout="15secs" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/AgK9ah/credentials" --filter_gpu_resources="true" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_framework_authenticators="basic" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --max_operator_event_stream_subscribers="1000" --max_unreachable_tasks_per_framework="1000" --memory_profiling="false" --min_allocatable_resources="cpus:0.01|mem:32" --offer_constraints_re2_max_mem="4KB" --offer_constraints_re2_max_program_size="100" --port="5050" --publish_per_framework_metrics="true" --quiet="false" --recovery_agent_removal_limit="100%" --registry="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" --require_agent_domain="false" --role_sorter="drf" --root_submissions="true" --version="false" --webui_dir="/tmp/SRC/build/mesos-1.11.0/_inst/share/mesos/webui" --work_dir="/tmp/AgK9ah/master" --zk_session_timeout="10secs"
I0901 08:17:40.662123 5533 master.cpp:500] Master only allowing authenticated frameworks to register
I0901 08:17:40.662147 5533 master.cpp:506] Master only allowing authenticated agents to register
I0901 08:17:40.662164 5533 master.cpp:512] Master only allowing authenticated HTTP frameworks to register
I0901 08:17:40.662184 5533 credentials.hpp:37] Loading credentials for authentication from '/tmp/AgK9ah/credentials'
I0901 08:17:40.662443 5533 master.cpp:556] Using default 'crammd5' authenticator
I0901 08:17:40.662645 5533 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
I0901 08:17:40.662837 5533 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
I0901 08:17:40.663022 5533 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
I0901 08:17:40.663199 5533 master.cpp:637] Authorization enabled
I0901 08:17:40.663590 5521 whitelist_watcher.cpp:77] No whitelist given
I0901 08:17:40.663617 5513 hierarchical.cpp:637] Initialized hierarchical allocator process
I0901 08:17:40.667326 5534 master.cpp:2170] Elected as the leading master!
I0901 08:17:40.667383 5534 master.cpp:1666] Recovering from registrar
I0901 08:17:40.667618 5512 registrar.cpp:339] Recovering registrar
I0901 08:17:40.668231 5512 registrar.cpp:383] Successfully fetched the registry (0B) in 553984ns
I0901 08:17:40.668356 5512 registrar.cpp:487] Applied 1 operations in 31836ns; attempting to update the registry
I0901 08:17:40.669070 5528 registrar.cpp:544] Successfully updated the registry in 658176ns
I0901 08:17:40.669217 5528 registrar.cpp:416] Successfully recovered registrar
I0901 08:17:40.670018 5523 master.cpp:1819] Recovered 0 agents from the registry (144B); allowing 10mins for agents to reregister
I0901 08:17:40.670032 5520 hierarchical.cpp:676] Skipping recovery of hierarchical allocator: nothing to recover
W0901 08:17:40.678612 5510 process.cpp:2877] Attempted to spawn already running process files@172.17.0.3:34493
I0901 08:17:40.679234 5510 resolver.cpp:69] Creating default secret resolver
I0901 08:17:40.679352 5510 cluster.cpp:620] Creating default 'local' authorizer
I0901 08:17:40.681483 5526 slave.cpp:281] Mesos agent started on (118)@172.17.0.3:34493
I0901 08:17:40.681512 5526 slave.cpp:282] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/AgK9ah/shW3tj/store/appc" --authenticate_http_readonly="true" --authenticate_http_readwrite="false" --authenticatee="crammd5" --authentication_backoff_factor="1secs" --authentication_timeout_max="1mins" --authentication_timeout_min="5secs" --authorizer="local" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_destroy_timeout="1mins" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/AgK9ah/shW3tj/credential" --default_role="*" --disallow_sharing_agent_ipc_namespace="false" --disallow_sharing_agent_pid_namespace="false" --disk_watch_interval="1mins" --docker="docker" --docker_ignore_runtime="false" --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/AgK9ah/shW3tj/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --docker_volume_chown="false" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_reregistration_timeout="2secs" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/AgK9ah/shW3tj/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/AgK9ah/shW3tj/frameworks" --gc_delay="1weeks" --gc_disk_headroom="0.1" --gc_non_executor_container_sandboxes="false" --help="false" --hostname_lookup="true" --http_command_executor="false" --http_credentials="/tmp/AgK9ah/shW3tj/http_credentials" --http_executor_domain_sockets="false" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/tmp/SRC/build/mesos-1.11.0/_build/sub/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --memory_profiling="false" --network_cni_metrics="true" --network_cni_root_dir_persist="false" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns" --quiet="false" --reconfiguration_policy="equal" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:3;mem:1024" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/MasterAllocatorTest_0_SlaveAdded_SlgKnD" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_enable_support="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/MasterAllocatorTest_0_SlaveAdded_RelrhX" --zk_session_timeout="10secs"
I0901 08:17:40.682020 5526 credentials.hpp:73] Loading credential for authentication from '/tmp/AgK9ah/shW3tj/credential'
W0901 08:17:40.682154 5510 process.cpp:2877] Attempted to spawn already running process version@172.17.0.3:34493
I0901 08:17:40.682162 5526 slave.cpp:314] Agent using credential for: test-principal
I0901 08:17:40.682204 5526 credentials.hpp:37] Loading credentials for authentication from '/tmp/AgK9ah/shW3tj/http_credentials'
I0901 08:17:40.682533 5526 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
I0901 08:17:40.682973 5526 disk_profile_adaptor.cpp:78] Creating default disk profile adaptor module
I0901 08:17:40.683362 5510 sched.cpp:239] Version: 1.11.0
I0901 08:17:40.684167 5527 sched.cpp:343] New master detected at master@172.17.0.3:34493
I0901 08:17:40.684306 5527 sched.cpp:408] Authenticating with master master@172.17.0.3:34493
I0901 08:17:40.684330 5527 sched.cpp:415] Using default CRAM-MD5 authenticatee
I0901 08:17:40.684108 5526 slave.cpp:629] Agent resources: [{"name":"cpus","scalar":{"value":3.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":3748421.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
I0901 08:17:40.684509 5526 slave.cpp:637] Agent attributes: [ ]
I0901 08:17:40.684535 5526 slave.cpp:646] Agent hostname: 0f73b3326edc
I0901 08:17:40.684727 5514 authenticatee.cpp:121] Creating new client SASL connection
I0901 08:17:40.684841 5533 task_status_update_manager.cpp:181] Pausing sending task status updates
I0901 08:17:40.684875 5525 status_update_manager_process.hpp:379] Pausing operation status update manager
I0901 08:17:40.685048 5527 master.cpp:9727] Authenticating scheduler-bfdd3ba8-a8c3-43bb-b2c7-df480d6ea530@172.17.0.3:34493
I0901 08:17:40.685175 5530 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(265)@172.17.0.3:34493
I0901 08:17:40.685602 5522 authenticator.cpp:98] Creating new server SASL connection
I0901 08:17:40.685921 5512 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0901 08:17:40.685958 5512 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0901 08:17:40.686089 5512 authenticator.cpp:204] Received SASL authentication start
I0901 08:17:40.686156 5512 authenticator.cpp:326] Authentication requires more steps
I0901 08:17:40.686259 5512 authenticatee.cpp:259] Received SASL authentication step
I0901 08:17:40.686437 5511 authenticator.cpp:232] Received SASL authentication step
I0901 08:17:40.686488 5511 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '0f73b3326edc' server FQDN: '0f73b3326edc' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0901 08:17:40.686511 5511 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0901 08:17:40.686561 5511 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0901 08:17:40.686596 5511 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '0f73b3326edc' server FQDN: '0f73b3326edc' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0901 08:17:40.686614 5511 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0901 08:17:40.686625 5511 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0901 08:17:40.686642 5511 authenticator.cpp:318] Authentication success
I0901 08:17:40.686805 5528 authenticatee.cpp:299] Authentication success
I0901 08:17:40.686885 5511 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(265)@172.17.0.3:34493
I0901 08:17:40.686918 5529 master.cpp:9759] Successfully authenticated principal 'test-principal' at scheduler-bfdd3ba8-a8c3-43bb-b2c7-df480d6ea530@172.17.0.3:34493
I0901 08:17:40.687321 5521 sched.cpp:520] Successfully authenticated with master master@172.17.0.3:34493
I0901 08:17:40.687366 5521 sched.cpp:835] Sending SUBSCRIBE call to master@172.17.0.3:34493
I0901 08:17:40.687374 5519 state.cpp:68] Recovering state from '/tmp/MasterAllocatorTest_0_SlaveAdded_RelrhX/meta'
I0901 08:17:40.687568 5521 sched.cpp:870] Will retry registration in 1.649102339secs if necessary
I0901 08:17:40.687750 5533 slave.cpp:7741] Finished recovering checkpointed state from '/tmp/MasterAllocatorTest_0_SlaveAdded_RelrhX/meta', beginning agent recovery
I0901 08:17:40.687906 5534 master.cpp:2941] Received SUBSCRIBE call for framework 'default' at scheduler-bfdd3ba8-a8c3-43bb-b2c7-df480d6ea530@172.17.0.3:34493
I0901 08:17:40.688499 5525 task_status_update_manager.cpp:207] Recovering task status update manager
I0901 08:17:40.690212 5523 composing.cpp:343] Finished recovering all containerizers
I0901 08:17:40.690639 5528 slave.cpp:8223] Recovering executors
I0901 08:17:40.690745 5528 slave.cpp:8376] Finished recovery
I0901 08:17:40.691303 5511 master.cpp:3024] Subscribing framework default with checkpointing disabled and capabilities [ MULTI_ROLE, RESERVATION_REFINEMENT ]
I0901 08:17:40.691617 5518 task_status_update_manager.cpp:181] Pausing sending task status updates
I0901 08:17:40.691676 5519 status_update_manager_process.hpp:379] Pausing operation status update manager
I0901 08:17:40.691717 5517 slave.cpp:1473] New master detected at master@172.17.0.3:34493
I0901 08:17:40.691884 5517 slave.cpp:1538] Detecting new master
I0901 08:17:40.693183 5525 slave.cpp:1565] Authenticating with master master@172.17.0.3:34493
I0901 08:17:40.693266 5525 slave.cpp:1574] Using default CRAM-MD5 authenticatee
I0901 08:17:40.693564 5530 authenticatee.cpp:121] Creating new client SASL connection
I0901 08:17:40.693930 5511 master.cpp:9958] Adding framework 411a707d-17a7-4838-9b3a-3770d00bb1e0-0000 (default) at scheduler-bfdd3ba8-a8c3-43bb-b2c7-df480d6ea530@172.17.0.3:34493 with roles { } suppressed
I0901 08:17:40.694847 5511 master.cpp:9727] Authenticating slave(118)@172.17.0.3:34493
I0901 08:17:40.694898 5522 sched.cpp:751] Framework registered with 411a707d-17a7-4838-9b3a-3770d00bb1e0-0000
I0901 08:17:40.695005 5522 sched.cpp:770] Scheduler::registered took 55622ns
I0901 08:17:40.695037 5512 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(266)@172.17.0.3:34493
I0901 08:17:40.695310 5534 hierarchical.cpp:774] Added framework 411a707d-17a7-4838-9b3a-3770d00bb1e0-0000
I0901 08:17:40.695389 5524 authenticator.cpp:98] Creating new server SASL connection
I0901 08:17:40.695612 5534 hierarchical.cpp:1935] Performed allocation for 0 agents in 107932ns
I0901 08:17:40.695772 5532 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0901 08:17:40.695825 5532 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0901 08:17:40.696012 5515 authenticator.cpp:204] Received SASL authentication start
I0901 08:17:40.696123 5515 authenticator.cpp:326] Authentication requires more steps
I0901 08:17:40.696275 5515 authenticatee.cpp:259] Received SASL authentication step
I0901 08:17:40.696444 5513 authenticator.cpp:232] Received SASL authentication step
I0901 08:17:40.696492 5513 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '0f73b3326edc' server FQDN: '0f73b3326edc' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0901 08:17:40.696509 5513 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0901 08:17:40.696542 5513 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0901 08:17:40.696574 5513 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '0f73b3326edc' server FQDN: '0f73b3326edc' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0901 08:17:40.696593 5513 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0901 08:17:40.696609 5513 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0901 08:17:40.696630 5513 authenticator.cpp:318] Authentication success
I0901 08:17:40.696815 5523 authenticatee.cpp:299] Authentication success
I0901 08:17:40.696846 5520 master.cpp:9759] Successfully authenticated principal 'test-principal' at slave(118)@172.17.0.3:34493
I0901 08:17:40.696907 5528 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(266)@172.17.0.3:34493
I0901 08:17:40.697320 5533 slave.cpp:1665] Successfully authenticated with master master@172.17.0.3:34493
I0901 08:17:40.697829 5533 slave.cpp:2131] Will retry registration in 9.743236ms if necessary
I0901 08:17:40.697994 5519 master.cpp:6221] Received register agent message from slave(118)@172.17.0.3:34493 (0f73b3326edc)
I0901 08:17:40.698468 5519 master.cpp:3752] Authorizing principal 'test-principal' to perform action REGISTER_AGENT on ANY object
I0901 08:17:40.699097 5525 master.cpp:6288] Authorized registration of agent at slave(118)@172.17.0.3:34493 (0f73b3326edc)
I0901 08:17:40.699183 5525 master.cpp:6400] Registering agent at slave(118)@172.17.0.3:34493 (0f73b3326edc) with id 411a707d-17a7-4838-9b3a-3770d00bb1e0-S0
I0901 08:17:40.699924 5522 registrar.cpp:487] Applied 1 operations in 315161ns; attempting to update the registry
I0901 08:17:40.700634 5522 registrar.cpp:544] Successfully updated the registry in 641024ns
I0901 08:17:40.700858 5532 master.cpp:6448] Admitted agent 411a707d-17a7-4838-9b3a-3770d00bb1e0-S0 at slave(118)@172.17.0.3:34493 (0f73b3326edc)
I0901 08:17:40.701766 5515 slave.cpp:1698] Registered with master master@172.17.0.3:34493; given agent ID 411a707d-17a7-4838-9b3a-3770d00bb1e0-S0
I0901 08:17:40.701755 5532 master.cpp:6493] Registered agent 411a707d-17a7-4838-9b3a-3770d00bb1e0-S0 at slave(118)@172.17.0.3:34493 (0f73b3326edc) with cpus:3; mem:1024; disk:3748421; ports:[31000-32000]
I0901 08:17:40.701877 5513 hierarchical.cpp:1041] Added agent 411a707d-17a7-4838-9b3a-3770d00bb1e0-S0 (0f73b3326edc) with cpus:3; mem:1024; disk:3748421; ports:[31000-32000] (offered or allocated: {})
I0901 08:17:40.701942 5526 task_status_update_manager.cpp:188] Resuming sending task status updates
I0901 08:17:40.702283 5515 slave.cpp:1733] Checkpointing SlaveInfo to '/tmp/MasterAllocatorTest_0_SlaveAdded_RelrhX/meta/slaves/411a707d-17a7-4838-9b3a-3770d00bb1e0-S0/slave.info'
I0901 08:17:40.702376 5516 status_update_manager_process.hpp:385] Resuming operation status update manager
I0901 08:17:40.703186 5513 hierarchical.cpp:1935] Performed allocation for 1 agents in 1.100406ms
I0901 08:17:40.703665 5515 slave.cpp:1793] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"8agVmbDiRg2eNG+jcLC2Ug=="},"slave_id":{"value":"411a707d-17a7-4838-9b3a-3770d00bb1e0-S0"},"update_oversubscribed_resources":false}
I0901 08:17:40.703969 5521 master.cpp:9536] Sending offers [ 411a707d-17a7-4838-9b3a-3770d00bb1e0-O0 ] to framework 411a707d-17a7-4838-9b3a-3770d00bb1e0-0000 (default) at scheduler-bfdd3ba8-a8c3-43bb-b2c7-df480d6ea530@172.17.0.3:34493
I0901 08:17:40.704869 5521 master.cpp:7635] Ignoring update on agent 411a707d-17a7-4838-9b3a-3770d00bb1e0-S0 at slave(118)@172.17.0.3:34493 (0f73b3326edc) as it reports no changes
I0901 08:17:40.705334 5517 sched.cpp:934] Scheduler::resourceOffers took 808506ns
I0901 08:17:40.706822 5527 master.cpp:4314] Processing ACCEPT call for offers: [ 411a707d-17a7-4838-9b3a-3770d00bb1e0-O0 ] on agent 411a707d-17a7-4838-9b3a-3770d00bb1e0-S0 at slave(118)@172.17.0.3:34493 (0f73b3326edc) for framework 411a707d-17a7-4838-9b3a-3770d00bb1e0-0000 (default) at scheduler-bfdd3ba8-a8c3-43bb-b2c7-df480d6ea530@172.17.0.3:34493
I0901 08:17:40.707334 5527 master.cpp:11834] Removing offer 411a707d-17a7-4838-9b3a-3770d00bb1e0-O0
W0901 08:17:40.708770 5527 validation.cpp:1716] Executor 'default' for task '8393ffae-0a73-454e-8d50-f2d4ebbbe29f' uses less CPUs (None) than the minimum required (0.01). Please update your executor, as this will be mandatory in future releases.
W0901 08:17:40.708806 5527 validation.cpp:1728] Executor 'default' for task '8393ffae-0a73-454e-8d50-f2d4ebbbe29f' uses less memory (None) than the minimum required (32MB). Please update your executor, as this will be mandatory in future releases.
I0901 08:17:40.709085 5Build timed out (after 240 minutes). Marking the build as failed.
527 master.cpp:3831] Adding executor 'default' with resources {} of framework 411a707d-17a7-4838-9b3a-3770d00bb1e0-0000 (default) at scheduler-bfdd3ba8-a8c3-43bb-b2c7-df480d6ea530@172.17.0.3:34493 on agent 411a707d-17a7-4838-9b3a-3770d00bb1e0-S0 at slave(118)@172.17.0.3:34493 (0f73b3326edc)
I0901 08:17:40.709285 5527 master.cpp:3857] Adding task 8393ffae-0a73-454e-8d50-f2d4ebbbe29f with resources cpus(allocated: *):2; mem(allocated: *):512 of framework 411a707d-17a7-4838-9b3a-3770d00bb1e0-0000 (default) at scheduler-bfdd3ba8-a8c3-43bb-b2c7-df480d6ea530@172.17.0.3:34493 on agent 411a707d-17a7-4838-9b3a-3770d00bb1e0-S0 at slave(118)@172.17.0.3:34493 (0f73b3326edc)
I0901 08:17:40.709758 5527 master.cpp:4993] Launching task 8393ffae-0a73-454e-8d50-f2d4ebbbe29f of framework 411a707d-17a7-4838-9b3a-3770d00bb1e0-0000 (default) at scheduler-bfdd3ba8-a8c3-43bb-b2c7-df480d6ea530@172.17.0.3:34493 with resources [{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":512.0},"type":"SCALAR"}] on agent 411a707d-17a7-4838-9b3a-3770d00bb1e0-S0 at slave(118)@172.17.0.3:34493 (0f73b3326edc) on new executor
I0901 08:17:40.710254 5530 hierarchical.cpp:1859] Allocation paused
I0901 08:17:40.710641 5530 hierarchical.cpp:1658] Recovered ports(allocated: *):[31000-32000]; cpus(allocated: *):1; mem(allocated: *):512; disk(allocated: *):3748421 (total: cpus:3; mem:1024; disk:3748421; ports:[31000-32000], offered or allocated: mem(allocated: *):512; cpus(allocated: *):2) on agent 411a707d-17a7-4838-9b3a-3770d00bb1e0-S0 from framework 411a707d-17a7-4838-9b3a-3770d00bb1e0-0000
I0901 08:17:40.710997 5519 slave.cpp:2300] Got assigned task '8393ffae-0a73-454e-8d50-f2d4ebbbe29f' for framework 411a707d-17a7-4838-9b3a-3770d00bb1e0-0000
I0901 08:17:40.711627 5530 hierarchical.cpp:1707] Framework 411a707d-17a7-4838-9b3a-3770d00bb1e0-0000 filtered agent 411a707d-17a7-4838-9b3a-3770d00bb1e0-S0 for 100ms
I0901 08:17:40.712308 5530 hierarchical.cpp:1869] Allocation resumed
I0901 08:17:40.712750 5519 slave.cpp:2707] Authorizing task '8393ffae-0a73-454e-8d50-f2d4ebbbe29f' for framework 411a707d-17a7-4838-9b3a-3770d00bb1e0-0000
I0901 08:17:40.712846 5519 slave.cpp:9715] Authorizing framework principal 'test-principal' to launch task 8393ffae-0a73-454e-8d50-f2d4ebbbe29f
I0901 08:17:40.715116 5514 slave.cpp:3181] Launching task '8393ffae-0a73-454e-8d50-f2d4ebbbe29f' for framework 411a707d-17a7-4838-9b3a-3770d00bb1e0-0000
I0901 08:17:40.715117 5532 hierarchical.cpp:2764] Filtered offer with ports:[31000-32000]; cpus:1; mem:512; disk:3748421 on agent 411a707d-17a7-4838-9b3a-3770d00bb1e0-S0 for role * of framework 411a707d-17a7-4838-9b3a-3770d00bb1e0-0000
I0901 08:17:40.715216 5514 paths.cpp:832] Creating sandbox '/tmp/MasterAllocatorTest_0_SlaveAdded_RelrhX/slaves/411a707d-17a7-4838-9b3a-3770d00bb1e0-S0/frameworks/411a707d-17a7-4838-9b3a-3770d00bb1e0-0000/executors/default/runs/2cc9e88a-57e5-4a78-b235-58d3bca4ff52' for user 'mesos'
I0901 08:17:40.715234 5532 hierarchical.cpp:1935] Performed allocation for 1 agents in 418164ns
I0901 08:17:40.716020 5514 slave.cpp:10379] Launching executor 'default' of framework 411a707d-17a7-4838-9b3a-3770d00bb1e0-0000 with resources [] in work directory '/tmp/MasterAllocatorTest_0_SlaveAdded_RelrhX/slaves/411a707d-17a7-4838-9b3a-3770d00bb1e0-S0/frameworks/411a707d-17a7-4838-9b3a-3770d00bb1e0-0000/executors/default/runs/2cc9e88a-57e5-4a78-b235-58d3bca4ff52'
I0901 08:17:40.717340 5514 slave.cpp:3415] Queued task '8393ffae-0a73-454e-8d50-f2d4ebbbe29f' for executor 'default' of framework 411a707d-17a7-4838-9b3a-3770d00bb1e0-0000
I0901 08:17:40.717478 5514 slave.cpp:1206] Successfully attached '/tmp/MasterAllocatorTest_0_SlaveAdded_RelrhX/slaves/411a707d-17a7-4838-9b3a-3770d00bb1e0-S0/frameworks/411a707d-17a7-4838-9b3a-3770d00bb1e0-0000/executors/default/runs/2cc9e88a-57e5-4a78-b235-58d3bca4ff52' to virtual path '/tmp/MasterAllocatorTest_0_SlaveAdded_RelrhX/slaves/411a707d-17a7-4838-9b3a-3770d00bb1e0-S0/frameworks/411a707d-17a7-4838-9b3a-3770d00bb1e0-0000/executors/default/runs/latest'
I0901 08:17:40.717541 5514 slave.cpp:1206] Successfully attached '/tmp/MasterAllocatorTest_0_SlaveAdded_RelrhX/slaves/411a707d-17a7-4838-9b3a-3770d00bb1e0-S0/frameworks/411a707d-17a7-4838-9b3a-3770d00bb1e0-0000/executors/default/runs/2cc9e88a-57e5-4a78-b235-58d3bca4ff52' to virtual path '/frameworks/411a707d-17a7-4838-9b3a-3770d00bb1e0-0000/executors/default/runs/latest'
I0901 08:17:40.717595 5514 slave.cpp:1206] Successfully attached '/tmp/MasterAllocatorTest_0_SlaveAdded_RelrhX/slaves/411a707d-17a7-4838-9b3a-3770d00bb1e0-S0/frameworks/411a707d-17a7-4838-9b3a-3770d00bb1e0-0000/executors/default/runs/2cc9e88a-57e5-4a78-b235-58d3bca4ff52' to virtual path '/tmp/MasterAllocatorTest_0_SlaveAdded_RelrhX/slaves/411a707d-17a7-4838-9b3a-3770d00bb1e0-S0/frameworks/411a707d-17a7-4838-9b3a-3770d00bb1e0-0000/executors/default/runs/2cc9e88a-57e5-4a78-b235-58d3bca4ff52'
I0901 08:17:40.718217 5514 slave.cpp:3876] Launching container 2cc9e88a-57e5-4a78-b235-58d3bca4ff52 for executor 'default' of framework 411a707d-17a7-4838-9b3a-3770d00bb1e0-0000
W0901 08:17:40.719348 5513 process.cpp:2877] Attempted to spawn already running process version@172.17.0.3:34493
I0901 08:17:40.719616 5513 exec.cpp:164] Version: 1.11.0
I0901 08:17:40.719998 5518 exec.cpp:213] Executor started at: executor(32)@172.17.0.3:34493 with pid 5510
I0901 08:17:40.720309 5518 slave.cpp:5487] Got registration for executor 'default' of framework 411a707d-17a7-4838-9b3a-3770d00bb1e0-0000 from executor(32)@172.17.0.3:34493
I0901 08:17:40.720947 5515 exec.cpp:237] Executor registered on agent 411a707d-17a7-4838-9b3a-3770d00bb1e0-S0
I0901 08:17:40.721024 5515 exec.cpp:249] Executor::registered took 31440ns
I0901 08:17:40.722517 5525 slave.cpp:3641] Sending queued task '8393ffae-0a73-454e-8d50-f2d4ebbbe29f' to executor 'default' of framework 411a707d-17a7-4838-9b3a-3770d00bb1e0-0000 at executor(32)@172.17.0.3:34493
I0901 08:17:40.722972 5512 exec.cpp:331] Executor asked to run task '8393ffae-0a73-454e-8d50-f2d4ebbbe29f'
I0901 08:17:40.723104 5512 exec.cpp:340] Executor::launchTask took 103098ns
I0901 08:17:40.723224 5512 exec.cpp:614] Executor sending status update TASK_RUNNING (Status UUID: b6f9c3d3-66a4-44a4-8287-2613960a8146) for task 8393ffae-0a73-454e-8d50-f2d4ebbbe29f of framework 411a707d-17a7-4838-9b3a-3770d00bb1e0-0000
I0901 08:17:40.723606 5512 slave.cpp:5980] Handling status update TASK_RUNNING (Status UUID: b6f9c3d3-66a4-44a4-8287-2613960a8146) for task 8393ffae-0a73-454e-8d50-f2d4ebbbe29f of framework 411a707d-17a7-4838-9b3a-3770d00bb1e0-0000 from executor(32)@172.17.0.3:34493
I0901 08:17:40.724494 5512 task_status_update_manager.cpp:328] Received task status update TASK_RUNNING (Status UUID: b6f9c3d3-66a4-44a4-8287-2613960a8146) for task 8393ffae-0a73-454e-8d50-f2d4ebbbe29f of framework 411a707d-17a7-4838-9b3a-3770d00bb1e0-0000
I0901 08:17:40.724545 5512 task_status_update_manager.cpp:507] Creating StatusUpdate stream for task 8393ffae-0a73-454e-8d50-f2d4ebbbe29f of framework 411a707d-17a7-4838-9b3a-3770d00bb1e0-0000
I0901 08:17:40.725277 5512 task_status_update_manager.cpp:383] Forwarding task status update TASK_RUNNING (Status UUID: b6f9c3d3-66a4-44a4-8287-2613960a8146) for task 8393ffae-0a73-454e-8d50-f2d4ebbbe29f of framework 411a707d-17a7-4838-9b3a-3770d00bb1e0-0000 to the agent
I0901 08:17:40.725636 5516 slave.cpp:6526] Forwarding the update TASK_RUNNING (Status UUID: b6f9c3d3-66a4-44a4-8287-2613960a8146) for task 8393ffae-0a73-454e-8d50-f2d4ebbbe29f of framework 411a707d-17a7-4838-9b3a-3770d00bb1e0-0000 to master@172.17.0.3:34493
I0901 08:17:40.725950 5516 slave.cpp:6410] Task status update manager successfully handled status update TASK_RUNNING (Status UUID: b6f9c3d3-66a4-44a4-8287-2613960a8146) for task 8393ffae-0a73-454e-8d50-f2d4ebbbe29f of framework 411a707d-17a7-4838-9b3a-3770d00bb1e0-0000
I0901 08:17:40.726104 5528 master.cpp:8117] Status update TASK_RUNNING (Status UUID: b6f9c3d3-66a4-44a4-8287-2613960a8146) for task 8393ffae-0a73-454e-8d50-f2d4ebbbe29f of framework 411a7Build was aborted
07d-17a7-4838-9b3a-3770d00bb1e0-0000 from agent 411a707d-17a7-4838-9b3a-3770d00bb1e0-S0 at slave(118)@172.17.0.3:34493 (0f73b3326edc)
Build failed in Jenkins: Mesos » Mesos-Reviewbot-Linux #250
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://ci-builds.apache.org/job/Mesos/job/Mesos-Reviewbot-Linux/250/display/redirect?page=changes>
Changes:
[zhq527725] Enabled CSI volume access for non-root users.
[zhq527725] Relaxed unknown volume check when unpublishing volumes.
------------------------------------------
[...truncated 13.66 MB...]
I0901 04:12:51.331288 5521 slave.cpp:1538] Detecting new master
I0901 04:12:51.332841 5515 slave.cpp:1565] Authenticating with master master@172.17.0.2:33863
I0901 04:12:51.332996 5515 slave.cpp:1574] Using default CRAM-MD5 authenticatee
I0901 04:12:51.333407 5523 authenticatee.cpp:121] Creating new client SASL connection
I0901 04:12:51.333806 5515 master.cpp:9727] Authenticating slave(129)@172.17.0.2:33863
I0901 04:12:51.334026 5516 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(277)@172.17.0.2:33863
I0901 04:12:51.334517 5520 authenticator.cpp:98] Creating new server SASL connection
I0901 04:12:51.334913 5525 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0901 04:12:51.334949 5525 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0901 04:12:51.335079 5525 authenticator.cpp:204] Received SASL authentication start
I0901 04:12:51.335150 5525 authenticator.cpp:326] Authentication requires more steps
I0901 04:12:51.335269 5525 authenticatee.cpp:259] Received SASL authentication step
I0901 04:12:51.335400 5525 authenticator.cpp:232] Received SASL authentication step
I0901 04:12:51.335435 5525 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '2e7f058cc395' server FQDN: '2e7f058cc395' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0901 04:12:51.335451 5525 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0901 04:12:51.335496 5525 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0901 04:12:51.335525 5525 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '2e7f058cc395' server FQDN: '2e7f058cc395' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0901 04:12:51.335541 5525 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0901 04:12:51.335551 5525 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0901 04:12:51.335569 5525 authenticator.cpp:318] Authentication success
I0901 04:12:51.335673 5509 authenticatee.cpp:299] Authentication success
I0901 04:12:51.335762 5526 master.cpp:9759] Successfully authenticated principal 'test-principal' at slave(129)@172.17.0.2:33863
I0901 04:12:51.335803 5517 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(277)@172.17.0.2:33863
I0901 04:12:51.336228 5525 slave.cpp:1665] Successfully authenticated with master master@172.17.0.2:33863
I0901 04:12:51.336650 5525 slave.cpp:2131] Will retry registration in 13.595082ms if necessary
I0901 04:12:51.336830 5518 master.cpp:6221] Received register agent message from slave(129)@172.17.0.2:33863 (2e7f058cc395)
I0901 04:12:51.337237 5518 master.cpp:3752] Authorizing principal 'test-principal' to perform action REGISTER_AGENT on ANY object
I0901 04:12:51.337787 5513 master.cpp:6288] Authorized registration of agent at slave(129)@172.17.0.2:33863 (2e7f058cc395)
I0901 04:12:51.337904 5513 master.cpp:6400] Registering agent at slave(129)@172.17.0.2:33863 (2e7f058cc395) with id e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S7
I0901 04:12:51.338778 5521 registrar.cpp:487] Applied 1 operations in 407707ns; attempting to update the registry
I0901 04:12:51.339694 5523 registrar.cpp:544] Successfully updated the registry in 0ns
I0901 04:12:51.339892 5516 master.cpp:6448] Admitted agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S7 at slave(129)@172.17.0.2:33863 (2e7f058cc395)
I0901 04:12:51.340626 5516 master.cpp:6493] Registered agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S7 at slave(129)@172.17.0.2:33863 (2e7f058cc395) with cpus:1; mem:10; disk:10; ports:[1-10]
I0901 04:12:51.340788 5522 hierarchical.cpp:1041] Added agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S7 (2e7f058cc395) with cpus:1; mem:10; disk:10; ports:[1-10] (offered or allocated: {})
I0901 04:12:51.340821 5527 slave.cpp:1698] Registered with master master@172.17.0.2:33863; given agent ID e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S7
I0901 04:12:51.340981 5519 task_status_update_manager.cpp:188] Resuming sending task status updates
I0901 04:12:51.341177 5522 hierarchical.cpp:1935] Performed allocation for 1 agents in 143869ns
I0901 04:12:51.341253 5527 slave.cpp:1733] Checkpointing SlaveInfo to '/tmp/MasterAllocatorTest_0_MinAllocatableResources_5AFQ0o/meta/slaves/e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S7/slave.info'
I0901 04:12:51.341293 5522 status_update_manager_process.hpp:385] Resuming operation status update manager
I0901 04:12:51.342480 5527 slave.cpp:1793] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"HAJhPuCqQ6CuJBl95YnNGQ=="},"slave_id":{"value":"e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S7"},"update_oversubscribed_resources":false}
I0901 04:12:51.343262 5527 master.cpp:7635] Ignoring update on agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S7 at slave(129)@172.17.0.2:33863 (2e7f058cc395) as it reports no changes
W0901 04:12:51.512737 5505 process.cpp:2877] Attempted to spawn already running process version@172.17.0.2:33863
I0901 04:12:51.513849 5505 sched.cpp:239] Version: 1.11.0
I0901 04:12:51.514590 5508 sched.cpp:343] New master detected at master@172.17.0.2:33863
I0901 04:12:51.514712 5508 sched.cpp:408] Authenticating with master master@172.17.0.2:33863
I0901 04:12:51.514734 5508 sched.cpp:415] Using default CRAM-MD5 authenticatee
I0901 04:12:51.515045 5515 authenticatee.cpp:121] Creating new client SASL connection
I0901 04:12:51.515352 5508 master.cpp:9727] Authenticating scheduler-6f3e84f0-6c4c-4220-b098-306c0c94bd53@172.17.0.2:33863
I0901 04:12:51.515507 5516 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(278)@172.17.0.2:33863
I0901 04:12:51.515825 5524 authenticator.cpp:98] Creating new server SASL connection
I0901 04:12:51.516068 5519 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0901 04:12:51.516103 5519 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0901 04:12:51.516224 5519 authenticator.cpp:204] Received SASL authentication start
I0901 04:12:51.516284 5519 authenticator.cpp:326] Authentication requires more steps
I0901 04:12:51.516398 5519 authenticatee.cpp:259] Received SASL authentication step
I0901 04:12:51.516546 5526 authenticator.cpp:232] Received SASL authentication step
I0901 04:12:51.516592 5526 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '2e7f058cc395' server FQDN: '2e7f058cc395' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0901 04:12:51.516618 5526 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0901 04:12:51.516670 5526 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0901 04:12:51.516711 5526 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '2e7f058cc395' server FQDN: '2e7f058cc395' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0901 04:12:51.516732 5526 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0901 04:12:51.516757 5526 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0901 04:12:51.516790 5526 authenticator.cpp:318] Authentication success
I0901 04:12:51.516903 5509 authenticatee.cpp:299] Authentication success
I0901 04:12:51.516980 5517 master.cpp:9759] Successfully authenticated principal 'test-principal' at scheduler-6f3e84f0-6c4c-4220-b098-306c0c94bd53@172.17.0.2:33863
I0901 04:12:51.517119 5525 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(278)@172.17.0.2:33863
I0901 04:12:51.517346 5526 sched.cpp:520] Successfully authenticated with master master@172.17.0.2:33863
I0901 04:12:51.517383 5526 sched.cpp:835] Sending SUBSCRIBE call to master@172.17.0.2:33863
I0901 04:12:51.517585 5526 sched.cpp:870] Will retry registration in 355.826088ms if necessary
I0901 04:12:51.517792 5518 master.cpp:2941] Received SUBSCRIBE call for framework 'default' at scheduler-6f3e84f0-6c4c-4220-b098-306c0c94bd53@172.17.0.2:33863
I0901 04:12:51.521178 5513 master.cpp:3024] Subscribing framework default with checkpointing disabled and capabilities [ MULTI_ROLE, RESERVATION_REFINEMENT ]
I0901 04:12:51.525583 5513 master.cpp:9958] Adding framework e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-0000 (default) at scheduler-6f3e84f0-6c4c-4220-b098-306c0c94bd53@172.17.0.2:33863 with roles { } suppressed
I0901 04:12:51.526636 5508 sched.cpp:751] Framework registered with e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-0000
I0901 04:12:51.526701 5508 sched.cpp:770] Scheduler::registered took 26242ns
I0901 04:12:51.526988 5523 hierarchical.cpp:774] Added framework e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-0000
I0901 04:12:51.530483 5523 hierarchical.cpp:1935] Performed allocation for 8 agents in 3.277356ms
I0901 04:12:51.532150 5524 master.cpp:9536] Sending offers [ e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-O0, e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-O1, e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-O2, e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-O3 ] to framework e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-0000 (default) at scheduler-6f3e84f0-6c4c-4220-b098-306c0c94bd53@172.17.0.2:33863
I0901 04:12:51.533186 5528 sched.cpp:934] Scheduler::resourceOffers took 119480ns
I0901 04:12:51.533318 5505 sched.cpp:2166] Asked to stop the driver
I0901 04:12:51.533453 5522 sched.cpp:1204] Stopping framework e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-0000
I0901 04:12:51.533746 5519 master.cpp:10323] Processing TEARDOWN call for framework e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-0000 (default) at scheduler-6f3e84f0-6c4c-4220-b098-306c0c94bd53@172.17.0.2:33863
I0901 04:12:51.533788 5519 master.cpp:10335] Removing framework e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-0000 (default) at scheduler-6f3e84f0-6c4c-4220-b098-306c0c94bd53@172.17.0.2:33863
I0901 04:12:51.533810 5519 master.cpp:3385] Deactivating framework e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-0000 (default) at scheduler-6f3e84f0-6c4c-4220-b098-306c0c94bd53@172.17.0.2:33863
I0901 04:12:51.533975 5517 hierarchical.cpp:887] Deactivated framework e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-0000
I0901 04:12:51.534595 5519 master.cpp:11834] Removing offer e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-O3
I0901 04:12:51.534677 5505 slave.cpp:1002] Agent terminating
I0901 04:12:51.534899 5529 hierarchical.cpp:1658] Recovered ports(allocated: *):[1-5]; cpus(allocated: *):0.5; mem(allocated: *):10; disk(allocated: *):100 (total: cpus:0.5; mem:10; disk:100; ports:[1-5], offered or allocated: {}) on agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S5 from framework e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-0000
I0901 04:12:51.535213 5519 master.cpp:11834] Removing offer e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-O1
I0901 04:12:51.535761 5519 master.cpp:11834] Removing offer e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-O2
I0901 04:12:51.536203 5519 master.cpp:11834] Removing offer e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-O0
I0901 04:12:51.536448 5509 slave.cpp:4285] Asked to shut down framework e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-0000 by master@172.17.0.2:33863
I0901 04:12:51.536470 5510 slave.cpp:4285] Asked to shut down framework e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-0000 by master@172.17.0.2:33863
I0901 04:12:51.536502 5509 slave.cpp:4300] Cannot shut down unknown framework e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-0000
I0901 04:12:51.536512 5510 slave.cpp:4300] Cannot shut down unknown framework e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-0000
I0901 04:12:51.536502 5517 slave.cpp:4285] Asked to shut down framework e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-0000 by master@172.17.0.2:33863
I0901 04:12:51.536573 5517 slave.cpp:4300] Cannot shut down unknown framework e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-0000
I0901 04:12:51.536588 5525 slave.cpp:4285] Asked to shut down framework e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-0000 by master@172.17.0.2:33863
I0901 04:12:51.536625 5525 slave.cpp:4300] Cannot shut down unknown framework e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-0000
I0901 04:12:51.536653 5507 slave.cpp:4285] Asked to shut down framework e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-0000 by master@172.17.0.2:33863
I0901 04:12:51.536698 5507 slave.cpp:4300] Cannot shut down unknown framework e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-0000
I0901 04:12:51.536752 5511 slave.cpp:4285] Asked to shut down framework e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-0000 by master@172.17.0.2:33863
I0901 04:12:51.536798 5511 slave.cpp:4300] Cannot shut down unknown framework e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-0000
I0901 04:12:51.536792 5526 slave.cpp:4285] Asked to shut down framework e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-0000 by master@172.17.0.2:33863
I0901 04:12:51.536828 5526 slave.cpp:4300] Cannot shut down unknown framework e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-0000
I0901 04:12:51.537189 5519 master.cpp:1297] Agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S0 at slave(122)@172.17.0.2:33863 (2e7f058cc395) disconnected
I0901 04:12:51.537217 5519 master.cpp:3420] Disconnecting agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S0 at slave(122)@172.17.0.2:33863 (2e7f058cc395)
I0901 04:12:51.537286 5519 master.cpp:3439] Deactivating agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S0 at slave(122)@172.17.0.2:33863 (2e7f058cc395)
I0901 04:12:51.537250 5529 hierarchical.cpp:1658] Recovered ports(allocated: *):[31000-32000]; cpus(allocated: *):1; mem(allocated: *):100; disk(allocated: *):50 (total: cpus:1; mem:100; disk:50; ports:[31000-32000], offered or allocated: {}) on agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S6 from framework e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-0000
I0901 04:12:51.539513 5529 hierarchical.cpp:1658] Recovered ports(allocated: *):[1-10]; cpus(allocated: *):1; mem(allocated: *):10; disk(allocated: *):10 (total: cpus:1; mem:10; disk:10; ports:[1-10], offered or allocated: {}) on agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S7 from framework e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-0000
I0901 04:12:51.541687 5529 hierarchical.cpp:1658] Recovered ports(allocated: *):[1-5]; cpus(allocated: *):1; mem(allocated: *):100 (total: cpus:1; mem:100; ports:[1-5], offered or allocated: {}) on agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S4 from framework e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-0000
I0901 04:12:51.543301 5529 hierarchical.cpp:1859] Allocation paused
I0901 04:12:51.544092 5529 hierarchical.cpp:831] Removed framework e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-0000
I0901 04:12:51.544195 5529 hierarchical.cpp:1869] Allocation resumed
I0901 04:12:51.544277 5529 hierarchical.cpp:1238] Agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S0 deactivated
I0901 04:12:51.547294 5515 hierarchical.cpp:1935] Performed allocation for 8 agents in 495212ns
I0901 04:12:51.556768 5505 slave.cpp:1002] Agent terminating
I0901 04:12:51.557585 5528 master.cpp:1297] Agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S1 at slave(123)@172.17.0.2:33863 (2e7f058cc395) disconnected
I0901 04:12:51.557624 5528 master.cpp:3420] Disconnecting agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S1 at slave(123)@172.17.0.2:33863 (2e7f058cc395)
I0901 04:12:51.557693 5528 master.cpp:3439] Deactivating agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S1 at slave(123)@172.17.0.2:33863 (2e7f058cc395)
I0901 04:12:51.557860 5508 hierarchical.cpp:1238] Agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S1 deactivated
I0901 04:12:51.567517 5505 slave.cpp:1002] Agent terminating
I0901 04:12:51.568562 5513 master.cpp:1297] Agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S2 at slave(124)@172.17.0.2:33863 (2e7f058cc395) disconnected
I0901 04:12:51.568622 5513 master.cpp:3420] Disconnecting agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S2 at slave(124)@172.17.0.2:33863 (2e7f058cc395)
I0901 04:12:51.568758 5513 master.cpp:3439] Deactivating agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S2 at slave(124)@172.17.0.2:33863 (2e7f058cc395)
I0901 04:12:51.569154 5518 hierarchical.cpp:1238] Agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S2 deactivated
I0901 04:12:51.576655 5505 slave.cpp:1002] Agent terminating
I0901 04:12:51.577474 5508 master.cpp:1297] Agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S3 at slave(125)@172.17.0.2:33863 (2e7f058cc395) disconnected
I0901 04:12:51.577510 5508 master.cpp:3420] Disconnecting agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S3 at slave(125)@172.17.0.2:33863 (2e7f058cc395)
I0901 04:12:51.577581 5508 master.cpp:3439] Deactivating agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S3 at slave(125)@172.17.0.2:33863 (2e7f058cc395)
I0901 04:12:51.577814 5529 hierarchical.cpp:1238] Agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S3 deactivated
I0901 04:12:51.585512 5505 slave.cpp:1002] Agent terminating
I0901 04:12:51.586246 5512 master.cpp:1297] Agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S4 at slave(126)@172.17.0.2:33863 (2e7f058cc395) disconnected
I0901 04:12:51.586308 5512 master.cpp:3420] Disconnecting agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S4 at slave(126)@172.17.0.2:33863 (2e7f058cc395)
I0901 04:12:51.586462 5512 master.cpp:3439] Deactivating agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S4 at slave(126)@172.17.0.2:33863 (2e7f058cc395)
I0901 04:12:51.586673 5514 hierarchical.cpp:1238] Agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S4 deactivated
I0901 04:12:51.597558 5507 slave.cpp:1002] Agent terminating
I0901 04:12:51.598603 5508 master.cpp:1297] Agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S5 at slave(127)@172.17.0.2:33863 (2e7f058cc395) disconnected
I0901 04:12:51.598654 5508 master.cpp:3420] Disconnecting agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S5 at slave(127)@172.17.0.2:33863 (2e7f058cc395)
I0901 04:12:51.598753 5508 master.cpp:3439] Deactivating agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S5 at slave(127)@172.17.0.2:33863 (2e7f058cc395)
I0901 04:12:51.598929 5528 hierarchical.cpp:1238] Agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S5 deactivated
I0901 04:12:51.609072 5505 slave.cpp:1002] Agent terminating
I0901 04:12:51.609846 5515 master.cpp:1297] Agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S6 at slave(128)@172.17.0.2:33863 (2e7f058cc395) disconnected
I0901 04:12:51.609920 5515 master.cpp:3420] Disconnecting agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S6 at slave(128)@172.17.0.2:33863 (2e7f058cc395)
I0901 04:12:51.610082 5515 master.cpp:3439] Deactivating agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S6 at slave(128)@172.17.0.2:33863 (2e7f058cc395)
I0901 04:12:51.610379 5520 hierarchical.cpp:1238] Agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S6 deactivated
I0901 04:12:51.619027 5510 slave.cpp:1002] Agent terminating
I0901 04:12:51.620076 5528 master.cpp:1297] Agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S7 at slave(129)@172.17.0.2:33863 (2e7f058cc395) disconnected
I0901 04:12:51.620118 5528 master.cpp:3420] Disconnecting agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S7 at slave(129)@172.17.0.2:33863 (2e7f058cc395)
I0901 04:12:51.620214 5528 master.cpp:3439] Deactivating agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S7 at slave(129)@172.17.0.2:33863 (2e7f058cc395)
I0901 04:12:51.620460 5520 hierarchical.cpp:1238] Agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S7 deactivated
I0901 04:12:51.629426 5505 master.cpp:1145] Master terminating
I0901 04:12:51.629894 5511 hierarchical.cpp:1214] Removed all filters for agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S5
I0901 04:12:51.629940 5511 hierarchical.cpp:1090] Removed agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S5
I0901 04:12:51.630285 5522 hierarchical.cpp:1214] Removed all filters for agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S6
I0901 04:12:51.630313 5522 hierarchical.cpp:1090] Removed agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S6
I0901 04:12:51.630550 5522 hierarchical.cpp:1214] Removed all filters for agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S0
I0901 04:12:51.630575 5522 hierarchical.cpp:1090] Removed agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S0
I0901 04:12:51.630807 5528 hierarchical.cpp:1214] Removed all filters for agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S3
I0901 04:12:51.630839 5528 hierarchical.cpp:1090] Removed agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S3
I0901 04:12:51.631152 5520 hierarchical.cpp:1214] Removed all filters for agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S7
I0901 04:12:51.631201 5520 hierarchical.cpp:1090] Removed agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S7
I0901 04:12:51.631441 5520 hierarchical.cpp:1214] Removed all filters for agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S4
I0901 04:12:51.631476 5520 hierarchical.cpp:1090] Removed agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S4
I0901 04:12:51.631736 5520 hierarchical.cpp:1214] Removed all filters for agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S1
I0901 04:12:51.631783 5520 hierarchical.cpp:1090] Removed agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S1
I0901 04:12:51.632052 5520 hierarchical.cpp:1214] Removed all filters for agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S2
I0901 04:12:51.632091 5520 hierarchical.cpp:1090] Removed agent e9ff7454-bfb0-40bc-b4a5-9033fd7eeda9-S2
[ OK ] MasterAllocatorTest/0.MinAllocatableResources (1745 ms)
[ RUN ] MasterAllocatorTest/0.Whitelist
I0901 04:12:51.650084 5505 cluster.cpp:195] Creating default 'local' authorizer
I0901 04:12:51.655222 5529 master.cpp:448] Master 831292e6-98d0-4bb0-8ae0-e9bd1ac41f58 (2e7f058cc395) started on 172.17.0.2:33863
I0901 04:12:51.655272 5529 master.cpp:451] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="1secs" --allocator="hierarchical" --authenticate_agents="true" --authenticate_frameworks="true" --authenticate_http_frameworks="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authentication_v0_timeout="15secs" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/g7RqN2/credentials" --filter_gpu_resources="true" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_framework_authenticators="basic" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --max_operator_event_stream_subscribers="1000" --max_unreachable_tasks_per_framework="1000" --memory_profiling="false" --min_allocatable_resources="cpus:0.01|mem:32" --offer_constraints_re2_max_mem="4KB" --offer_constraints_re2_max_program_size="100" --port="5050" --publish_per_framework_metrics="true" --quiet="false" --recovery_agent_removal_limit="100%" --registry="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" --require_agent_domain="false" --role_sorter="drf" --root_submissions="true" --version="false" --webui_dir="/tmp/SRC/build/mesos-1.11.0/_inst/share/mesos/webui" --whitelist="whitelist.txt" --work_dir="/tmp/g7RqN2/master" --zk_session_timeout="10secs"
I0901 04:12:51.655999 5529 master.cpp:500] Master only allowing authenticated frameworks to register
I0901 04:12:51.656029 5529 master.cpp:506] Master only allowing authenticated agents to register
I0901 04:12:51.656049 5529 master.cpp:512] Master only allowing authenticated HTTP frameworks to register
I0901 04:12:51.656069 5529 credentials.hpp:37] Loading credentials for authentication from '/tmp/g7RqN2/credentials'
I0901 04:12:51.656561 5529 master.cpp:556] Using default 'crammd5' authenticator
I0901 04:12:51.656929 5529 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
I0901 04:12:51.657325 5529 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
I0901 04:12:51.657652 5529 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheBuild timed out (after 240 minutes). Marking the build as failed.
duler'
I0901 04:12:51.657963 5529 master.cpp:637] Authorization enabled
I0901 04:12:51.658560 5526 hierarchical.cpp:637] Initialized hierarchical allocator process
I0901 04:12:51.659133 5527 hierarchical.cpp:1250] Updated agent whitelist: { dummy-agent1 }
I0901 04:12:51.664510 5519 master.cpp:2170] Elected as the leading master!
I0901 04:12:51.664549 5519 master.cpp:1666] Recovering from registrar
I0901 04:12:51.664744 5525 registrar.cpp:339] Recovering registrar
I0901 04:12:51.665488 5525 registrar.cpp:383] Successfully fetched the registry (0B) in 0ns
I0901 04:12:51.665647 5525 registrar.cpp:487] Applied 1 operations in 56188ns; attempting to update the registry
I0901 04:12:51.666604 5522 registrar.cpp:544] Successfully updated the registry in 0ns
I0901 04:12:51.666779 5522 registrar.cpp:416] Successfully recovered registrar
I0901 04:12:51.667337 5523 hierarchical.cpp:676] Skipping recovery of hierarchical allocator: nothing to recover
I0901 04:12:51.667389 5524 master.cpp:1819] Recovered 0 agents from the registry (144B); allowing 10mins for agents to reregister
I0901 04:12:51.670266 5528 hierarchical.cpp:1935] Performed allocation for 0 agents in 64978ns
I0901 04:12:51.671088 5527 hierarchical.cpp:1250] Updated agent whitelist: { dummy-agent1, dummy-agent2 }
I0901 04:12:51.671291 5505 master.cpp:1145] Master terminating
[ OK ] MasterAllocatorTest/0.Whitelist (30 ms)
[ RUN ] MasterAllocatorTest/0.RoleTest
I0901 04:12:51.680305 5505 cluster.cpp:195] Creating default 'local' authorizer
I0901 04:12:51.684489 5514 master.cpp:448] Master 6497a3f9-aaf2-49c1-b846-fba01d0e8466 (2e7f058cc395) started on 172.17.0.2:33863
I0901 04:12:51.684521 5514 master.cpp:451] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="1secs" --allocator="hierarchical" --authenticate_agents="true" --authenticate_frameworks="true" --authenticate_http_frameworks="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authentication_v0_timeout="15secs" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/LeWgEM/credentials" --filter_gpu_resources="true" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_framework_authenticators="basic" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --max_operator_event_stream_subscribers="1000" --max_unreachable_tasks_per_framework="1000" --memory_profiling="false" --min_allocatable_resources="cpus:0.01|mem:32" --offer_constraints_re2_max_mem="4KB" --offer_constraints_re2_max_program_size="100" --port="5050" --publish_per_framework_metrics="true" --quiet="false" --recovery_agent_removal_limit="100%" --registry="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" --require_agent_domain="false" --role_sorter="drf" --roles="role2" --root_submissions="true" --version="false" --webui_dir="/tmp/SRC/build/mesos-1.11.0/_inst/share/mesos/webui" --work_dir="/tmp/LeWgEM/master" --zk_session_timeout="10secs"
I0901 04:12:51.684876 5514 master.cpp:500] Master only allowing authenticated frameworks to register
I0901 04:12:51.684890 5514 master.cpp:506] Master only allowing authenticated agents to register
I0901 04:12:51.684900 5514 master.cpp:512] Master only allowing authenticated HTTP frameworks to register
I0901 04:12:51.684908 5514 credentials.hpp:37] Loading credentials for authentication from '/tmp/LeWgEM/credentials'
I0901 04:12:51.685159 5514 master.cpp:556] Using default 'crammd5' authenticator
I0901 04:12:51.685339 5514 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
I0901 04:12:51.685523 5514 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
I0901 04:12:51.685680 5514 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
I0901 04:12:51.685830 5514 master.cpp:637] Authorization enabled
W0901 04:12:51.685850 5514 master.cpp:700] The '--roles' flag is deprecated. This flag will be removed in the future. See the Mesos 0.27 upgrade notes for more information
I0901 04:12:51.686223 5526 hierarchical.cpp:637] Initialized hierarchical allocator process
I0901 04:12:51.686265 5516 whitelist_watcher.cpp:77] No whitelist given
I0901 04:12:51.689477 5520 master.cpp:2170] Elected as the leading master!
I0901 04:12:51.689543 5520 master.cpp:1666] Recovering from registrar
I0901 04:12:51.689940 5512 registrar.cpp:339] Recovering registrar
I0901 04:12:51.691177 5512 registrar.cpp:383] Successfully fetched the registry (0B) in 1.157888ms
I0901 04:12:51.691416 5512 registrar.cpp:487] Applied 1 operations in 66213ns; attempting to update the registry
I0901 04:12:51.692395 5512 registrar.cpp:544] Successfully updated the registry in 882176ns
I0901 04:12:51.692698 5512 registrar.cpp:416] Successfully recovered registrar
I0901 04:12:51.693384 5510 master.cpp:1819] Recovered 0 agents from the registry (144B); allowing 10mins for agents to reregister
I0901 04:12:51.693408 5508 hierarchical.cpp:676] Skipping recovery of hierarchical allocator: nothing to recover
W0901 04:12:51.695936 5505 process.cpp:2877] Attempted to spawn already running process version@172.17.0.2:33863
I0901 04:12:51.696977 5505 sched.cpp:239] Version: 1.11.0
I0901 04:12:51.697715 5514 sched.cpp:343] New master detected at master@172.17.0.2:33863
I0901 04:12:51.697866 5514 sched.cpp:408] Authenticating with master master@172.17.0.2:33863
I0901 04:12:51.697894 5514 sched.cpp:415] Using default CRAM-MD5 authenticatee
I0901 04:12:51.698297 5517 authenticatee.cpp:121] Creating new client SASL connection
I0901 04:12:51.698815 5513 master.cpp:9727] Authenticating scheduler-d54e9f2c-5a97-45c2-bb48-c27ce279c1f6@172.17.0.2:33863
I0901 04:12:51.699084 5525 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(279)@172.17.0.2:33863
I0901 04:12:51.699523 5506 authenticator.cpp:98] Creating new server SASL connection
I0901 04:12:51.699923 5511 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0901 04:12:51.699992 5511 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0901 04:12:51.700203 5511 authenticator.cpp:204] Received SASL authentication start
I0901 04:12:51.700325 5511 authenticator.cpp:326] Authentication requires more steps
I0901 04:12:51.700521 5511 authenticatee.cpp:259] Received SASL authentication step
I0901 04:12:51.700711 5511 authenticator.cpp:232] Received SASL authentication step
I0901 04:12:51.700764 5511 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '2e7f058cc395' server FQDN: '2e7f058cc395' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0901 04:12:51.700789 5511 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0901 04:12:51.700868 5511 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0901 04:12:51.700920 5511 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '2e7f058cc395' server FQDN: '2e7f058cc395' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0901 04:12:51.700944 5511 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0901 04:12:51.700963 5511 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0901 04:12:51.700996 5511 authenticator.cpp:318] Authentication success
I0901 04:12:51.701155 5522 authenticatee.cpp:299] Authentication success
I0901 04:12:51.701333 5510 master.cpp:9759] Successfully authenticated principal 'test-principal' at scheduler-d54e9f2c-5a97-45c2-bb48-c27ce279c1f6@172.17.0.2:33863
I0901 04:12:51.701350 5528 authenticator.cBuild was aborted
pp:432] Authentication session cleanup for crammd5-authenticatee(279)@172.17.0.2:33863
I0901 04:12:51.701733 5523 sched.cpp:520] Successfully authenticated with master master@172.17.0.2:33863
Build failed in Jenkins: Mesos » Mesos-Reviewbot-Linux #249
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://ci-builds.apache.org/job/Mesos/job/Mesos-Reviewbot-Linux/249/display/redirect?page=changes>
Changes:
[gregorywmann] Fixed broken authorization in the CSI server.
------------------------------------------
[...truncated 7.96 MB...]
I0831 23:20:20.068832 5640 leveldb.cpp:347] Persisting action (16 bytes) to leveldb took 29.327859ms
I0831 23:20:20.068892 5640 replica.cpp:712] Persisted action TRUNCATE at position 4
I0831 23:20:20.069613 5655 replica.cpp:695] Replica received learned notice for position 4 from log-network(1)@172.17.0.4:37375
I0831 23:20:20.078194 5612 process.cpp:935] Stopped the socket accept loop
I0831 23:20:20.078203 5613 process.cpp:935] Stopped the socket accept loop
I0831 23:20:20.079102 5615 process.cpp:935] Stopped the socket accept loop
I0831 23:20:20.079335 5611 process.cpp:935] Stopped the socket accept loop
I0831 23:20:20.080948 5619 process.cpp:935] Stopped the socket accept loop
I0831 23:20:20.081610 5633 scheduler.cpp:416] Connected with the master at http://172.17.0.4:37375/master/api/v1/scheduler
I0831 23:20:20.084144 5634 scheduler.cpp:246] Adding authentication headers to SUBSCRIBE call to http://172.17.0.4:37375/master/api/v1/scheduler
I0831 23:20:20.092317 5640 scheduler.cpp:600] Sending SUBSCRIBE call to http://172.17.0.4:37375/master/api/v1/scheduler
I0831 23:20:20.095140 5642 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I0831 23:20:20.102371 5632 http.cpp:1436] HTTP POST for /master/api/v1/scheduler from 172.17.0.4:37594
I0831 23:20:20.105744 5632 master.cpp:2666] Received subscription request for HTTP framework 'Event Call Scheduler using libprocess (C++)'
I0831 23:20:20.110924 5655 leveldb.cpp:347] Persisting action (18 bytes) to leveldb took 41.262602ms
I0831 23:20:20.111069 5655 leveldb.cpp:423] Deleting ~2 keys from leveldb took 75183ns
I0831 23:20:20.111104 5655 replica.cpp:712] Persisted action TRUNCATE at position 4
I0831 23:20:20.113168 5640 master.cpp:2751] Subscribing framework 'Event Call Scheduler using libprocess (C++)' with checkpointing disabled and capabilities [ MULTI_ROLE, RESERVATION_REFINEMENT ]
I0831 23:20:20.117125 5640 master.cpp:9958] Adding framework c9d498db-5640-4b1e-a958-2780891a60f2-0000 (Event Call Scheduler using libprocess (C++)) with roles { } suppressed
I0831 23:20:20.120321 5654 hierarchical.cpp:774] Added framework c9d498db-5640-4b1e-a958-2780891a60f2-0000
I0831 23:20:20.120462 5641 scheduler.cpp:845] Enqueuing event SUBSCRIBED received from http://172.17.0.4:37375/master/api/v1/scheduler
I0831 23:20:20.121500 5641 scheduler.cpp:845] Enqueuing event HEARTBEAT received from http://172.17.0.4:37375/master/api/v1/scheduler
Received a SUBSCRIBED event
Subscribed with ID c9d498db-5640-4b1e-a958-2780891a60f2-0000
Received a HEARTBEAT event
I0831 23:20:20.123450 5654 hierarchical.cpp:1935] Performed allocation for 1 agents in 2.830395ms
I0831 23:20:20.124379 5646 master.cpp:9536] Sending offers [ c9d498db-5640-4b1e-a958-2780891a60f2-O0 ] to framework c9d498db-5640-4b1e-a958-2780891a60f2-0000 (Event Call Scheduler using libprocess (C++))
I0831 23:20:20.126494 5650 scheduler.cpp:845] Enqueuing event OFFERS received from http://172.17.0.4:37375/master/api/v1/scheduler
Received an OFFERS event
Received offer c9d498db-5640-4b1e-a958-2780891a60f2-O0 with ports(allocated: *):[31000-32000]; cpus(allocated: *):2; mem(allocated: *):10240; disk(allocated: *):3748421
Launching task 0 using offer c9d498db-5640-4b1e-a958-2780891a60f2-O0
Launching task 1 using offer c9d498db-5640-4b1e-a958-2780891a60f2-O0
I0831 23:20:20.132601 5633 scheduler.cpp:246] Adding authentication headers to ACCEPT call to http://172.17.0.4:37375/master/api/v1/scheduler
I0831 23:20:20.133432 5655 scheduler.cpp:600] Sending ACCEPT call to http://172.17.0.4:37375/master/api/v1/scheduler
I0831 23:20:20.134954 5652 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I0831 23:20:20.137490 5654 http.cpp:1436] HTTP POST for /master/api/v1/scheduler from 172.17.0.4:37592
I0831 23:20:20.139808 5654 master.cpp:4314] Processing ACCEPT call for offers: [ c9d498db-5640-4b1e-a958-2780891a60f2-O0 ] on agent c9d498db-5640-4b1e-a958-2780891a60f2-S0 at slave(2)@172.17.0.4:37375 (c8c11e6bf65b) for framework c9d498db-5640-4b1e-a958-2780891a60f2-0000 (Event Call Scheduler using libprocess (C++))
I0831 23:20:20.140702 5654 master.cpp:11834] Removing offer c9d498db-5640-4b1e-a958-2780891a60f2-O0
W0831 23:20:20.143961 5654 validation.cpp:1716] Executor 'default' for task '0' uses less CPUs (None) than the minimum required (0.01). Please update your executor, as this will be mandatory in future releases.
W0831 23:20:20.144022 5654 validation.cpp:1728] Executor 'default' for task '0' uses less memory (None) than the minimum required (32MB). Please update your executor, as this will be mandatory in future releases.
I0831 23:20:20.144578 5654 master.cpp:3831] Adding executor 'default' with resources {} of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000 (Event Call Scheduler using libprocess (C++)) on agent c9d498db-5640-4b1e-a958-2780891a60f2-S0 at slave(2)@172.17.0.4:37375 (c8c11e6bf65b)
I0831 23:20:20.145181 5654 master.cpp:3857] Adding task 0 with resources cpus(allocated: *):1; mem(allocated: *):128 of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000 (Event Call Scheduler using libprocess (C++)) on agent c9d498db-5640-4b1e-a958-2780891a60f2-S0 at slave(2)@172.17.0.4:37375 (c8c11e6bf65b)
I0831 23:20:20.146402 5654 master.cpp:4993] Launching task 0 of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000 (Event Call Scheduler using libprocess (C++)) with resources [{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":1.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":128.0},"type":"SCALAR"}] on agent c9d498db-5640-4b1e-a958-2780891a60f2-S0 at slave(2)@172.17.0.4:37375 (c8c11e6bf65b) on new executor
I0831 23:20:20.148244 5646 slave.cpp:2300] Got assigned task '0' for framework c9d498db-5640-4b1e-a958-2780891a60f2-0000
W0831 23:20:20.149063 5654 validation.cpp:1716] Executor 'default' for task '1' uses less CPUs (None) than the minimum required (0.01). Please update your executor, as this will be mandatory in future releases.
W0831 23:20:20.149108 5654 validation.cpp:1728] Executor 'default' for task '1' uses less memory (None) than the minimum required (32MB). Please update your executor, as this will be mandatory in future releases.
I0831 23:20:20.149602 5654 master.cpp:3857] Adding task 1 with resources cpus(allocated: *):1; mem(allocated: *):128 of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000 (Event Call Scheduler using libprocess (C++)) on agent c9d498db-5640-4b1e-a958-2780891a60f2-S0 at slave(2)@172.17.0.4:37375 (c8c11e6bf65b)
I0831 23:20:20.150291 5654 master.cpp:4993] Launching task 1 of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000 (Event Call Scheduler using libprocess (C++)) with resources [{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":1.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":128.0},"type":"SCALAR"}] on agent c9d498db-5640-4b1e-a958-2780891a60f2-S0 at slave(2)@172.17.0.4:37375 (c8c11e6bf65b) on existing executor
I0831 23:20:20.150899 5642 hierarchical.cpp:1859] Allocation paused
I0831 23:20:20.151865 5653 hierarchical.cpp:1658] Recovered ports(allocated: *):[31000-32000]; disk(allocated: *):3748421; mem(allocated: *):9984 (total: cpus:2; mem:10240; disk:3748421; ports:[31000-32000], offered or allocated: mem(allocated: *):256; cpus(allocated: *):2) on agent c9d498db-5640-4b1e-a958-2780891a60f2-S0 from framework c9d498db-5640-4b1e-a958-2780891a60f2-0000
I0831 23:20:20.153352 5646 slave.cpp:2300] Got assigned task '1' for framework c9d498db-5640-4b1e-a958-2780891a60f2-0000
I0831 23:20:20.153707 5653 hierarchical.cpp:1707] Framework c9d498db-5640-4b1e-a958-2780891a60f2-0000 filtered agent c9d498db-5640-4b1e-a958-2780891a60f2-S0 for 5secs
I0831 23:20:20.155818 5646 slave.cpp:2707] Authorizing task '0' for framework c9d498db-5640-4b1e-a958-2780891a60f2-0000
I0831 23:20:20.155982 5646 slave.cpp:9715] Authorizing framework principal 'test-principal' to launch task 0
I0831 23:20:20.156028 5653 hierarchical.cpp:1869] Allocation resumed
I0831 23:20:20.158577 5646 slave.cpp:2707] Authorizing task '1' for framework c9d498db-5640-4b1e-a958-2780891a60f2-0000
I0831 23:20:20.158763 5646 slave.cpp:9715] Authorizing framework principal 'test-principal' to launch task 1
I0831 23:20:20.164865 5646 slave.cpp:3181] Launching task '0' for framework c9d498db-5640-4b1e-a958-2780891a60f2-0000
I0831 23:20:20.166746 5646 paths.cpp:832] Creating sandbox '/tmp/mesos-GKkUkb/agents/1/work/slaves/c9d498db-5640-4b1e-a958-2780891a60f2-S0/frameworks/c9d498db-5640-4b1e-a958-2780891a60f2-0000/executors/default/runs/c213dd8c-e024-4d2d-8acb-7b84c09a6d00' for user 'mesos'
I0831 23:20:20.167718 5646 slave.cpp:10379] Launching executor 'default' of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000 with resources [] in work directory '/tmp/mesos-GKkUkb/agents/1/work/slaves/c9d498db-5640-4b1e-a958-2780891a60f2-S0/frameworks/c9d498db-5640-4b1e-a958-2780891a60f2-0000/executors/default/runs/c213dd8c-e024-4d2d-8acb-7b84c09a6d00'
I0831 23:20:20.170339 5646 slave.cpp:3415] Queued task '0' for executor 'default' of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000
I0831 23:20:20.170734 5646 slave.cpp:3181] Launching task '1' for framework c9d498db-5640-4b1e-a958-2780891a60f2-0000
I0831 23:20:20.170892 5646 slave.cpp:3415] Queued task '1' for executor 'default' of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000
I0831 23:20:20.171036 5646 slave.cpp:1206] Successfully attached '/tmp/mesos-GKkUkb/agents/1/work/slaves/c9d498db-5640-4b1e-a958-2780891a60f2-S0/frameworks/c9d498db-5640-4b1e-a958-2780891a60f2-0000/executors/default/runs/c213dd8c-e024-4d2d-8acb-7b84c09a6d00' to virtual path '/tmp/mesos-GKkUkb/agents/1/work/slaves/c9d498db-5640-4b1e-a958-2780891a60f2-S0/frameworks/c9d498db-5640-4b1e-a958-2780891a60f2-0000/executors/default/runs/latest'
I0831 23:20:20.171099 5646 slave.cpp:1206] Successfully attached '/tmp/mesos-GKkUkb/agents/1/work/slaves/c9d498db-5640-4b1e-a958-2780891a60f2-S0/frameworks/c9d498db-5640-4b1e-a958-2780891a60f2-0000/executors/default/runs/c213dd8c-e024-4d2d-8acb-7b84c09a6d00' to virtual path '/frameworks/c9d498db-5640-4b1e-a958-2780891a60f2-0000/executors/default/runs/latest'
I0831 23:20:20.171151 5646 slave.cpp:1206] Successfully attached '/tmp/mesos-GKkUkb/agents/1/work/slaves/c9d498db-5640-4b1e-a958-2780891a60f2-S0/frameworks/c9d498db-5640-4b1e-a958-2780891a60f2-0000/executors/default/runs/c213dd8c-e024-4d2d-8acb-7b84c09a6d00' to virtual path '/tmp/mesos-GKkUkb/agents/1/work/slaves/c9d498db-5640-4b1e-a958-2780891a60f2-S0/frameworks/c9d498db-5640-4b1e-a958-2780891a60f2-0000/executors/default/runs/c213dd8c-e024-4d2d-8acb-7b84c09a6d00'
I0831 23:20:20.172180 5646 slave.cpp:3876] Launching container c213dd8c-e024-4d2d-8acb-7b84c09a6d00 for executor 'default' of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000
I0831 23:20:20.172858 5641 containerizer.cpp:1405] Starting container c213dd8c-e024-4d2d-8acb-7b84c09a6d00
I0831 23:20:20.173601 5641 containerizer.cpp:3414] Transitioning the state of container c213dd8c-e024-4d2d-8acb-7b84c09a6d00 from STARTING to PROVISIONING after 414976ns
I0831 23:20:20.181059 5641 containerizer.cpp:1584] Checkpointed ContainerConfig at '/tmp/mesos-GKkUkb/agents/1/run/containers/c213dd8c-e024-4d2d-8acb-7b84c09a6d00/config'
I0831 23:20:20.181114 5641 containerizer.cpp:3414] Transitioning the state of container c213dd8c-e024-4d2d-8acb-7b84c09a6d00 from PROVISIONING to PREPARING after 7520us
I0831 23:20:20.194919 5651 containerizer.cpp:2110] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"shell":true,"value":"/tmp/SRC/build/mesos-1.11.0/_build/sub/src/test-http-executor"},"environment":{"variables":[{"name":"LIBPROCESS_PORT","type":"VALUE","value":"0"},{"name":"MESOS_AGENT_ENDPOINT","type":"VALUE","value":"172.17.0.4:37375"},{"name":"MESOS_CHECKPOINT","type":"VALUE","value":"0"},{"name":"MESOS_DIRECTORY","type":"VALUE","value":"/tmp/mesos-GKkUkb/agents/1/work/slaves/c9d498db-5640-4b1e-a958-2780891a60f2-S0/frameworks/c9d498db-5640-4b1e-a958-2780891a60f2-0000/executors/default/runs/c213dd8c-e024-4d2d-8acb-7b84c09a6d00"},{"name":"MESOS_EXECUTOR_ID","type":"VALUE","value":"default"},{"name":"MESOS_EXECUTOR_SHUTDOWN_GRACE_PERIOD","type":"VALUE","value":"5secs"},{"name":"MESOS_FRAMEWORK_ID","type":"VALUE","value":"c9d498db-5640-4b1e-a958-2780891a60f2-0000"},{"name":"MESOS_HTTP_COMMAND_EXECUTOR","type":"VALUE","value":"0"},{"name":"MESOS_SLAVE_ID","type":"VALUE","value":"c9d498db-5640-4b1e-a958-2780891a60f2-S0"},{"name":"MESOS_SLAVE_PID","type":"VALUE","value":"slave(2)@172.17.0.4:37375"},{"name":"MESOS_SANDBOX","type":"VALUE","value":"/tmp/mesos-GKkUkb/agents/1/work/slaves/c9d498db-5640-4b1e-a958-2780891a60f2-S0/frameworks/c9d498db-5640-4b1e-a958-2780891a60f2-0000/executors/default/runs/c213dd8c-e024-4d2d-8acb-7b84c09a6d00"}]},"task_environment":{},"user":"mesos","working_directory":"/tmp/mesos-GKkUkb/agents/1/work/slaves/c9d498db-5640-4b1e-a958-2780891a60f2-S0/frameworks/c9d498db-5640-4b1e-a958-2780891a60f2-0000/executors/default/runs/c213dd8c-e024-4d2d-8acb-7b84c09a6d00"}" --pipe_read="20" --pipe_write="21" --runtime_directory="/tmp/mesos-GKkUkb/agents/1/run/containers/c213dd8c-e024-4d2d-8acb-7b84c09a6d00" --unshare_namespace_mnt="false"'
I0831 23:20:20.200439 5651 launcher.cpp:145] Forked child with pid '5661' for container 'c213dd8c-e024-4d2d-8acb-7b84c09a6d00'
I0831 23:20:20.202102 5651 containerizer.cpp:3414] Transitioning the state of container c213dd8c-e024-4d2d-8acb-7b84c09a6d00 from PREPARING to ISOLATING after 20.979968ms
I0831 23:20:20.204627 5651 containerizer.cpp:3414] Transitioning the state of container c213dd8c-e024-4d2d-8acb-7b84c09a6d00 from ISOLATING to FETCHING after 2.514176ms
I0831 23:20:20.205022 5645 fetcher.cpp:369] Starting to fetch URIs for container: c213dd8c-e024-4d2d-8acb-7b84c09a6d00, directory: /tmp/mesos-GKkUkb/agents/1/work/slaves/c9d498db-5640-4b1e-a958-2780891a60f2-S0/frameworks/c9d498db-5640-4b1e-a958-2780891a60f2-0000/executors/default/runs/c213dd8c-e024-4d2d-8acb-7b84c09a6d00
I0831 23:20:20.208364 5652 containerizer.cpp:3414] Transitioning the state of container c213dd8c-e024-4d2d-8acb-7b84c09a6d00 from FETCHING to RUNNING after 3.719936ms
I0831 23:20:20.254086 5642 slave.cpp:2131] Will retry registration in 806.861086ms if necessary
I0831 23:20:20.254417 5654 master.cpp:6221] Received register agent message from slave(3)@172.17.0.4:37375 (c8c11e6bf65b)
I0831 23:20:20.254953 5654 master.cpp:3752] Authorizing ANY principal to perform action REGISTER_AGENT on ANY object
I0831 23:20:20.255787 5640 master.cpp:6288] Authorized registration of agent at slave(3)@172.17.0.4:37375 (c8c11e6bf65b)
I0831 23:20:20.255970 5640 master.cpp:6400] Registering agent at slave(3)@172.17.0.4:37375 (c8c11e6bf65b) with id c9d498db-5640-4b1e-a958-2780891a60f2-S1
I0831 23:20:20.257016 5639 registrar.cpp:487] Applied 1 operations in 429783ns; attempting to update the registry
I0831 23:20:20.260152 5633 log.cpp:578] Attempting to append 518 bytes to the log
I0831 23:20:20.260376 5653 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 5
I0831 23:20:20.261677 5652 replica.cpp:541] Replica received write request for position 5 from __req_res__(10)@172.17.0.4:37375
I0831 23:20:20.295912 5652 leveldb.cpp:347] Persisting action (537 bytes) to leveldb took 34.154977ms
I0831 23:20:20.295996 5652 replica.cpp:712] Persisted action APPEND at position 5
I0831 23:20:20.296975 5642 replica.cpp:695] Replica received learned notice for position 5 from log-network(1)@172.17.0.4:37375
I0831 23:20:20.329313 5642 leveldb.cpp:347] Persisting action (539 bytes) to leveldb took 32.287951ms
I0831 23:20:20.329358 5642 replica.cpp:712] Persisted action APPEND at position 5
I0831 23:20:20.331255 5643 registrar.cpp:544] Successfully updated the registry in 74.12096ms
I0831 23:20:20.331550 5639 master.cpp:6448] Admitted agent c9d498db-5640-4b1e-a958-2780891a60f2-S1 at slave(3)@172.17.0.4:37375 (c8c11e6bf65b)
I0831 23:20:20.331828 5632 log.cpp:597] Attempting to truncate the log to 5
I0831 23:20:20.331980 5650 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 6
I0831 23:20:20.332752 5639 master.cpp:6493] Registered agent c9d498db-5640-4b1e-a958-2780891a60f2-S1 at slave(3)@172.17.0.4:37375 (c8c11e6bf65b) with cpus:2; mem:10240; disk:3748421; ports:[31000-32000]
I0831 23:20:20.332854 5634 slave.cpp:1698] Registered with master master@172.17.0.4:37375; given agent ID c9d498db-5640-4b1e-a958-2780891a60f2-S1
I0831 23:20:20.333060 5641 task_status_update_manager.cpp:188] Resuming sending task status updates
I0831 23:20:20.333087 5651 hierarchical.cpp:1041] Added agent c9d498db-5640-4b1e-a958-2780891a60f2-S1 (c8c11e6bf65b) with cpus:2; mem:10240; disk:3748421; ports:[31000-32000] (offered or allocated: {})
I0831 23:20:20.333186 5648 replica.cpp:541] Replica received write request for position 6 from __req_res__(11)@172.17.0.4:37375
I0831 23:20:20.333493 5634 slave.cpp:1733] Checkpointing SlaveInfo to '/tmp/mesos-GKkUkb/agents/2/work/meta/slaves/c9d498db-5640-4b1e-a958-2780891a60f2-S1/slave.info'
I0831 23:20:20.333571 5638 status_update_manager_process.hpp:385] Resuming operation status update manager
I0831 23:20:20.334923 5651 hierarchical.cpp:1935] Performed allocation for 1 agents in 1.515109ms
I0831 23:20:20.335189 5634 slave.cpp:1793] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"+MP+klr5TvWlNCSIRskuqQ=="},"slave_id":{"value":"c9d498db-5640-4b1e-a958-2780891a60f2-S1"},"update_oversubscribed_resources":false}
I0831 23:20:20.335485 5640 master.cpp:9536] Sending offers [ c9d498db-5640-4b1e-a958-2780891a60f2-O1 ] to framework c9d498db-5640-4b1e-a958-2780891a60f2-0000 (Event Call Scheduler using libprocess (C++))
I0831 23:20:20.336647 5640 master.cpp:7635] Ignoring update on agent c9d498db-5640-4b1e-a958-2780891a60f2-S1 at slave(3)@172.17.0.4:37375 (c8c11e6bf65b) as it reports no changes
I0831 23:20:20.337771 5655 scheduler.cpp:845] Enqueuing event OFFERS received from http://172.17.0.4:37375/master/api/v1/scheduler
Received an OFFERS event
Received offer c9d498db-5640-4b1e-a958-2780891a60f2-O1 with ports(allocated: *):[31000-32000]; cpus(allocated: *):2; mem(allocated: *):10240; disk(allocated: *):3748421
Launching task 2 using offer c9d498db-5640-4b1e-a958-2780891a60f2-O1
Launching task 3 using offer c9d498db-5640-4b1e-a958-2780891a60f2-O1
I0831 23:20:20.340698 5636 scheduler.cpp:246] Adding authentication headers to ACCEPT call to http://172.17.0.4:37375/master/api/v1/scheduler
I0831 23:20:20.341472 5641 scheduler.cpp:600] Sending ACCEPT call to http://172.17.0.4:37375/master/api/v1/scheduler
I0831 23:20:20.342811 5637 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I0831 23:20:20.371352 5648 leveldb.cpp:347] Persisting action (16 bytes) to leveldb took 38.10201ms
I0831 23:20:20.371410 5648 replica.cpp:712] Persisted action TRUNCATE at position 6
I0831 23:20:20.372155 5640 replica.cpp:695] Replica received learned notice for position 6 from log-network(1)@172.17.0.4:37375
I0831 23:20:20.386157 5653 http.cpp:1436] HTTP POST for /master/api/v1/scheduler from 172.17.0.4:37592
I0831 23:20:20.387632 5653 master.cpp:4314] Processing ACCEPT call for offers: [ c9d498db-5640-4b1e-a958-2780891a60f2-O1 ] on agent c9d498db-5640-4b1e-a958-2780891a60f2-S1 at slave(3)@172.17.0.4:37375 (c8c11e6bf65b) for framework c9d498db-5640-4b1e-a958-2780891a60f2-0000 (Event Call Scheduler using libprocess (C++))
I0831 23:20:20.388243 5653 master.cpp:11834] Removing offer c9d498db-5640-4b1e-a958-2780891a60f2-O1
W0831 23:20:20.389930 5653 validation.cpp:1716] Executor 'default' for task '2' uses less CPUs (None) than the minimum required (0.01). Please update your executor, as this will be mandatory in future releases.
W0831 23:20:20.389967 5653 validation.cpp:1728] Executor 'default' for task '2' uses less memory (None) than the minimum required (32MB). Please update your executor, as this will be mandatory in future releases.
I0831 23:20:20.390305 5653 master.cpp:3831] Adding executor 'default' with resources {} of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000 (Event Call Scheduler using libprocess (C++)) on agent c9d498db-5640-4b1e-a958-2780891a60f2-S1 at slave(3)@172.17.0.4:37375 (c8c11e6bf65b)
I0831 23:20:20.390569 5653 master.cpp:3857] Adding task 2 with resources cpus(allocated: *):1; mem(allocated: *):128 of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000 (Event Call Scheduler using libprocess (C++)) on agent c9d498db-5640-4b1e-a958-2780891a60f2-S1 at slave(3)@172.17.0.4:37375 (c8c11e6bf65b)
I0831 23:20:20.391117 5653 master.cpp:4993] Launching task 2 of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000 (Event Call Scheduler using libprocess (C++)) with resources [{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":1.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":128.0},"type":"SCALAR"}] on agent c9d498db-5640-4b1e-a958-2780891a60f2-S1 at slave(3)@172.17.0.4:37375 (c8c11e6bf65b) on new executor
I0831 23:20:20.392318 5639 slave.cpp:2300] Got assigned task '2' for framework c9d498db-5640-4b1e-a958-2780891a60f2-0000
W0831 23:20:20.392884 5653 validation.cpp:1716] Executor 'default' for task '3' uses less CPUs (None) than the minimum required (0.01). Please update your executor, as this will be mandatory in future releases.
W0831 23:20:20.392918 5653 validation.cpp:1728] Executor 'default' for task '3' uses less memory (None) than the minimum required (32MB). Please update your executor, as this will be mandatory in future releases.
I0831 23:20:20.393270 5653 master.cpp:3857] Adding task 3 with resources cpus(allocated: *):1; mem(allocated: *):128 of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000 (Event Call Scheduler using libprocess (C++)) on agent c9d498db-5640-4b1e-a958-2780891a60f2-S1 at slave(3)@172.17.0.4:37375 (c8c11e6bf65b)
I0831 23:20:20.393734 5653 master.cpp:4993] Launching task 3 of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000 (Event Call Scheduler using libprocess (C++)) with resources [{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":1.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":128.0},"type":"SCALAR"}] on agent c9d498db-5640-4b1e-a958-2780891a60f2-S1 at slave(3)@172.17.0.4:37375 (c8c11e6bf65b) on existing executor
I0831 23:20:20.394162 5652 hierarchical.cpp:1859] Allocation paused
I0831 23:20:20.394249 5639 slave.cpp:2707] Authorizing task '2' for framework c9d498db-5640-4b1e-a958-2780891a60f2-0000
I0831 23:20:20.394345 5639 slave.cpp:9715] Authorizing framework principal 'test-principal' to launch task 2
I0831 23:20:20.394600 5652 hierarchical.cpp:1658] Recovered ports(allocated: *):[31000-32000]; disk(allocated: *):3748421; mem(allocated: *):9984 (total: cpus:2; mem:10240; disk:3748421; ports:[31000-32000], offered or allocated: mem(allocated: *):256; cpus(allocated: *):2) on agent c9d498db-5640-4b1e-a958-2780891a60f2-S1 from framework c9d498db-5640-4b1e-a958-2780891a60f2-0000
I0831 23:20:20.395675 5652 hierarchical.cpp:1707] Framework c9d498db-5640-4b1e-a958-2780891a60f2-0000 filtered agent c9d498db-5640-4b1e-a958-2780891a60f2-S1 for 5secs
I0831 23:20:20.396291 5639 slave.cpp:2300] Got assigned task '3' for framework c9d498db-5640-4b1e-a958-2780891a60f2-0000
I0831 23:20:20.396334 5652 hierarchical.cpp:1869] Allocation resumed
I0831 23:20:20.398227 5639 slave.cpp:2707] Authorizing task '3' for framework c9d498db-5640-4b1e-a958-2780891a60f2-0000
I0831 23:20:20.398315 5639 slave.cpp:9715] Authorizing framework principal 'test-principal' to launch task 3
I0831 23:20:20.400624 5639 slave.cpp:3181] Launching task '2' for framework c9d498db-5640-4b1e-a958-2780891a60f2-0000
I0831 23:20:20.400719 5639 paths.cpp:832] Creating sandbox '/tmp/mesos-GKkUkb/agents/2/work/slaves/c9d498db-5640-4b1e-a958-2780891a60f2-S1/frameworks/c9d498db-5640-4b1e-a958-2780891a60f2-0000/executors/default/runs/062b6cf4-d7be-4d62-8e7f-caf885bb6556' for user 'mesos'
I0831 23:20:20.401505 5639 slave.cpp:10379] Launching executor 'default' of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000 with resources [] in work directory '/tmp/mesos-GKkUkb/agents/2/work/slaves/c9d498db-5640-4b1e-a958-2780891a60f2-S1/frameworks/c9d498db-5640-4b1e-a958-2780891a60f2-0000/executors/default/runs/062b6cf4-d7be-4d62-8e7f-caf885bb6556'
I0831 23:20:20.402884 5639 slave.cpp:3415] Queued task '2' for executor 'default' of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000
I0831 23:20:20.403451 5639 slave.cpp:1206] Successfully attached '/tmp/mesos-GKkUkb/agents/2/work/slaves/c9d498db-5640-4b1e-a958-2780891a60f2-S1/frameworks/c9d498db-5640-4b1e-a958-2780891a60f2-0000/executors/default/runs/062b6cf4-d7be-4d62-8e7f-caf885bb6556' to virtual path '/tmp/mesos-GKkUkb/agents/2/work/slaves/c9d498db-5640-4b1e-a958-2780891a60f2-S1/frameworks/c9d498db-5640-4b1e-a958-2780891a60f2-0000/executors/default/runs/latest'
I0831 23:20:20.403501 5639 slave.cpp:1206] Successfully attached '/tmp/mesos-GKkUkb/agents/2/work/slaves/c9d498db-5640-4b1e-a958-2780891a60f2-S1/frameworks/c9d498db-5640-4b1e-a958-2780891a60f2-0000/executors/default/runs/062b6cf4-d7be-4d62-8e7f-caf885bb6556' to virtual path '/frameworks/c9d498db-5640-4b1e-a958-2780891a60f2-0000/executors/default/runs/latest'
I0831 23:20:20.403537 5639 slave.cpp:1206] Successfully attached '/tmp/mesos-GKkUkb/agents/2/work/slaves/c9d498db-5640-4b1e-a958-2780891a60f2-S1/frameworks/c9d498db-5640-4b1e-a958-2780891a60f2-0000/executors/default/runs/062b6cf4-d7be-4d62-8e7f-caf885bb6556' to virtual path '/tmp/mesos-GKkUkb/agents/2/work/slaves/c9d498db-5640-4b1e-a958-2780891a60f2-S1/frameworks/c9d498db-5640-4b1e-a958-2780891a60f2-0000/executors/default/runs/062b6cf4-d7be-4d62-8e7f-caf885bb6556'
I0831 23:20:20.404147 5639 slave.cpp:3181] Launching task '3' for framework c9d498db-5640-4b1e-a958-2780891a60f2-0000
I0831 23:20:20.404273 5639 slave.cpp:3415] Queued task '3' for executor 'default' of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000
I0831 23:20:20.404523 5639 slave.cpp:3876] Launching container 062b6cf4-d7be-4d62-8e7f-caf885bb6556 for executor 'default' of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000
I0831 23:20:20.404852 5633 containerizer.cpp:1405] Starting container 062b6cf4-d7be-4d62-8e7f-caf885bb6556
I0831 23:20:20.405450 5633 containerizer.cpp:3414] Transitioning the state of container 062b6cf4-d7be-4d62-8e7f-caf885bb6556 from STARTING to PROVISIONING after 308992ns
I0831 23:20:20.406333 5633 containerizer.cpp:1584] Checkpointed ContainerConfig at '/tmp/mesos-GKkUkb/agents/2/run/containers/062b6cf4-d7be-4d62-8e7f-caf885bb6556/config'
I0831 23:20:20.406394 5633 containerizer.cpp:3414] Transitioning the state of container 062b6cf4-d7be-4d62-8e7f-caf885bb6556 from PROVISIONING to PREPARING after 944128ns
I0831 23:20:20.413810 5641 containerizer.cpp:2110] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"shell":true,"value":"/tmp/SRC/build/mesos-1.11.0/_build/sub/src/test-http-executor"},"environment":{"variables":[{"name":"LIBPROCESS_PORT","type":"VALUE","value":"0"},{"name":"MESOS_AGENT_ENDPOINT","type":"VALUE","value":"172.17.0.4:37375"},{"name":"MESOS_CHECKPOINT","type":"VALUE","value":"0"},{"name":"MESOS_DIRECTORY","type":"VALUE","value":"/tmp/mesos-GKkUkb/agents/2/work/slaves/c9d498db-5640-4b1e-a958-2780891a60f2-S1/frameworks/c9d498db-5640-4b1e-a958-2780891a60f2-0000/executors/default/runs/062b6cf4-d7be-4d62-8e7f-caf885bb6556"},{"name":"MESOS_EXECUTOR_ID","type":"VALUE","value":"default"},{"name":"MESOS_EXECUTOR_SHUTDOWN_GRACE_PERIOD","type":"VALUE","value":"5secs"},{"name":"MESOS_FRAMEWORK_ID","type":"VALUE","value":"c9d498db-5640-4b1e-a958-2780891a60f2-0000"},{"name":"MESOS_HTTP_COMMAND_EXECUTOR","type":"VALUE","value":"0"},{"name":"MESOS_SLAVE_ID","type":"VALUE","value":"c9d498db-5640-4b1e-a958-2780891a60f2-S1"},{"name":"MESOS_SLAVE_PID","type":"VALUE","value":"slave(3)@172.17.0.4:37375"},{"name":"MESOS_SANDBOX","type":"VALUE","value":"/tmp/mesos-GKkUkb/agents/2/work/slaves/c9d498db-5640-4b1e-a958-2780891a60f2-S1/frameworks/c9d498db-5640-4b1e-a958-2780891a60f2-0000/executors/default/runs/062b6cf4-d7be-4d62-8e7f-caf885bb6556"}]},"task_environment":{},"user":"mesos","working_directory":"/tmp/mesos-GKkUkb/agents/2/work/slaves/c9d498db-5640-4b1e-a958-2780891a60f2-S1/frameworks/c9d498db-5640-4b1e-a958-2780891a60f2-0000/executors/default/runs/062b6cf4-d7be-4d62-8e7f-caf885bb6556"}" --pipe_read="24" --pipe_write="25" --runtime_directory="/tmp/mesos-GKkUkb/agents/2/run/containers/062b6cf4-d7be-4d62-8e7f-caf885bb6556" --unshare_namespace_mnt="false"'
I0831 23:20:20.416795 5641 launcher.cpp:145] Forked child with pid '5664' for container '062b6cf4-d7be-4d62-8e7f-caf885bb6556'
I0831 23:20:20.417619 5648 slave.cpp:2131] Will retry registration in 1.379132501secs if necessary
I0831 23:20:20.417858 5641 containerizer.cpp:3414] Transitioning the state of container 062b6cf4-d7be-4d62-8e7f-caf885bb6556 from PREPARING to ISOLATING after 11.452928ms
I0831 23:20:20.418030 5649 master.cpp:6221] Received register agent message from slave(1)@172.17.0.4:37375 (c8c11e6bf65b)
I0831 23:20:20.418648 5649 master.cpp:3752] Authorizing ANY principal to perform action REGISTER_AGENT on ANY object
I0831 23:20:20.419793 5636 master.cpp:6288] Authorized registration of agent at slave(1)@172.17.0.4:37375 (c8c11e6bf65b)
I0831 23:20:20.419963 5636 master.cpp:6400] Registering agent at slave(1)@172.17.0.4:37375 (c8c11e6bf65b) with id c9d498db-5640-4b1e-a958-2780891a60f2-S2
I0831 23:20:20.420487 5641 containerizer.cpp:3414] Transitioning the state of container 062b6cf4-d7be-4d62-8e7f-caf885bb6556 from ISOLATING to FETCHING after 2.624256ms
I0831 23:20:20.420737 5643 fetcher.cpp:369] Starting to fetch URIs for container: 062b6cf4-d7be-4d62-8e7f-caf885bb6556, directory: /tmp/mesos-GKkUkb/agents/2/work/slaves/c9d498db-5640-4b1e-a958-2780891a60f2-S1/frameworks/c9d498db-5640-4b1e-a958-2780891a60f2-0000/executors/default/runs/062b6cf4-d7be-4d62-8e7f-caf885bb6556
I0831 23:20:20.421109 5648 registrar.cpp:487] Applied 1 operations in 463444ns; attempting to update the registry
I0831 23:20:20.423166 5652 containerizer.cpp:3414] Transitioning the state of container 062b6cf4-d7be-4d62-8e7f-caf885bb6556 from FETCHING to RUNNING after 2.688768ms
I0831 23:20:20.458799 5640 leveldb.cpp:347] Persisting action (18 bytes) to leveldb took 86.562404ms
I0831 23:20:20.459003 5640 leveldb.cpp:423] Deleting ~2 keys from leveldb took 104391ns
I0831 23:20:20.459040 5640 replica.cpp:712] Persisted action TRUNCATE at position 6
I0831 23:20:20.460798 5649 log.cpp:578] Attempting to append 684 bytes to the log
I0831 23:20:20.461012 5650 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 7
I0831 23:20:20.462289 5636 replica.cpp:541] Replica received write request for position 7 from __req_res__(12)@172.17.0.4:37375
I0831 23:20:20.522728 5636 leveldb.cpp:347] Persisting action (703 bytes) to leveldb took 60.362812ms
I0831 23:20:20.522775 5636 replica.cpp:712] Persisted action APPEND at position 7
I0831 23:20:20.523730 5633 replica.cpp:695] Replica received learned notice for position 7 from log-network(1)@172.17.0.4:37375
I0831 23:20:20.584767 5677 executor.cpp:210] Version: 1.11.0
I0831 23:20:20.585261 5677 executor.cpp:286] Using URL http://172.17.0.4:37375/slave(2)/api/v1/executor for the executor API endpoint
I0831 23:20:20.589624 5633 leveldb.cpp:347] Persisting action (705 bytes) to leveldb took 65.849428ms
I0831 23:20:20.589668 5633 replica.cpp:712] Persisted action APPEND at position 7
I0831 23:20:20.591289 5647 registrar.cpp:544] Successfully updated the registry in 170.053888ms
I0831 23:20:20.591532 5649 master.cpp:6448] Admitted agent c9d498db-5640-4b1e-a958-2780891a60f2-S2 at slave(1)@172.17.0.4:37375 (c8c11e6bf65b)
I0831 23:20:20.591743 5655 log.cpp:597] Attempting to truncate the log to 7
I0831 23:20:20.591909 5650 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 8
I0831 23:20:20.592573 5649 master.cpp:6493] Registered agent c9d498db-5640-4b1e-a958-2780891a60f2-S2 at slave(1)@172.17.0.4:37375 (c8c11e6bf65b) with cpus:2; mem:10240; disk:3748421; ports:[31000-32000]
I0831 23:20:20.592660 5646 slave.cpp:1698] Registered with master master@172.17.0.4:37375; given agent ID c9d498db-5640-4b1e-a958-2780891a60f2-S2
I0831 23:20:20.592783 5636 task_status_update_manager.cpp:188] Resuming sending task status updates
I0831 23:20:20.592876 5637 hierarchical.cpp:1041] Added agent c9d498db-5640-4b1e-a958-2780891a60f2-S2 (c8c11e6bf65b) with cpus:2; mem:10240; disk:3748421; ports:[31000-32000] (offered or allocated: {})
I0831 23:20:20.592989 5654 replica.cpp:541] Replica received write request for position 8 from __req_res__(13)@172.17.0.4:37375
I0831 23:20:20.593212 5646 slave.cpp:1733] Checkpointing SlaveInfo to '/tmp/mesos-GKkUkb/agents/0/work/meta/slaves/c9d498db-5640-4b1e-a958-2780891a60f2-S2/slave.info'
I0831 23:20:20.593271 5641 status_update_manager_process.hpp:385] Resuming operation status update manager
I0831 23:20:20.594630 5646 slave.cpp:1793] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"pVTpXMU5SnS8xzpTN5UQyQ=="},"slave_id":{"value":"c9d498db-5640-4b1e-a958-2780891a60f2-S2"},"update_oversubscribed_resources":false}
I0831 23:20:20.594681 5637 hierarchical.cpp:1935] Performed allocation for 1 agents in 1.52738ms
I0831 23:20:20.594756 5646 process.cpp:3671] Handling HTTP event for process 'slave(2)' with path: '/slave(2)/api/v1/executor'
I0831 23:20:20.595197 5647 master.cpp:9536] Sending offers [ c9d498db-5640-4b1e-a958-2780891a60f2-O2 ] to framework c9d498db-5640-4b1e-a958-2780891a60f2-0000 (Event Call Scheduler using libprocess (C++))
I0831 23:20:20.596398 5647 master.cpp:7635] Ignoring update on agent c9d498db-5640-4b1e-a958-2780891a60f2-S2 at slave(1)@172.17.0.4:37375 (c8c11e6bf65b) as it reports no changes
I0831 23:20:20.597440 5634 http.cpp:1436] HTTP POST for /slave(2)/api/v1/executor from 172.17.0.4:37596
I0831 23:20:20.597956 5634 slave.cpp:5251] Received Subscribe request for HTTP executor 'default' of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000
I0831 23:20:20.598007 5636 scheduler.cpp:845] Enqueuing event OFFERS received from http://172.17.0.4:37375/master/api/v1/scheduler
Received an OFFERS event
Received offer c9d498db-5640-4b1e-a958-2780891a60f2-O2 with ports(allocated: *):[31000-32000]; cpus(allocated: *):2; mem(allocated: *):10240; disk(allocated: *):3748421
Launching task 4 using offer c9d498db-5640-4b1e-a958-2780891a60f2-O2
I0831 23:20:20.600409 5637 scheduler.cpp:246] Adding authentication headers to ACCEPT call to http://172.17.0.4:37375/master/api/v1/scheduler
I0831 23:20:20.601147 5633 scheduler.cpp:600] Sending ACCEPT call to http://172.17.0.4:37375/master/api/v1/scheduler
I0831 23:20:20.602365 5639 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I0831 23:20:20.604794 5632 slave.cpp:3641] Sending queued task '0' to executor 'default' of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000 (via HTTP)
I0831 23:20:20.605408 5632 slave.cpp:3641] Sending queued task '1' to executor 'default' of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000 (via HTTP)
Received a SUBSCRIBED event
Starting task 0
Finishing task 0
Starting task 1
I0831 23:20:20.610060 5637 process.cpp:3671] Handling HTTP event for process 'slave(2)' with path: '/slave(2)/api/v1/executor'
Finishing task 1
I0831 23:20:20.611431 5653 process.cpp:3671] Handling HTTP event for process 'slave(2)' with path: '/slave(2)/api/v1/executor'
I0831 23:20:20.612205 5653 http.cpp:1436] HTTP POST for /slave(2)/api/v1/executor from 172.17.0.4:37598
I0831 23:20:20.612607 5653 slave.cpp:5980] Handling status update TASK_RUNNING (Status UUID: ec15da08-798c-499a-8aa7-9ad4525495ad) for task 0 of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000
I0831 23:20:20.613104 5649 hierarchical.cpp:2764] Filtered offer with ports:[31000-32000]; mem:9984; disk:3748421 on agent c9d498db-5640-4b1e-a958-2780891a60f2-S0 for role * of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000
I0831 23:20:20.613338 5649 hierarchical.cpp:2764] Filtered offer with ports:[31000-32000]; mem:9984; disk:3748421 on agent c9d498db-5640-4b1e-a958-2780891a60f2-S1 for role * of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000
I0831 23:20:20.613469 5649 hierarchical.cpp:1935] Performed allocation for 3 agents in 909883ns
I0831 23:20:20.614552 5653 process.cpp:3671] Handling HTTP event for process 'slave(2)' with path: '/slave(2)/api/v1/executor'
I0831 23:20:20.615180 5653 process.cpp:3671] Handling HTTP event for process 'slave(2)' with path: '/slave(2)/api/v1/executor'
I0831 23:20:20.616998 5653 http.cpp:1436] HTTP POST for /slave(2)/api/v1/executor from 172.17.0.4:37598
I0831 23:20:20.617225 5653 slave.cpp:5980] Handling status update TASK_FINISHED (Status UUID: b5d6a8eb-fe29-4a31-a6d3-a1c60ed31c54) for task 0 of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000
I0831 23:20:20.618769 5655 task_status_update_manager.cpp:328] Received task status update TASK_RUNNING (Status UUID: ec15da08-798c-499a-8aa7-9ad4525495ad) for task 0 of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000
I0831 23:20:20.618861 5655 task_status_update_manager.cpp:507] Creating StatusUpdate stream for task 0 of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000
I0831 23:20:20.618978 5653 http.cpp:1436] HTTP POST for /slave(2)/api/v1/executor from 172.17.0.4:37598
I0831 23:20:20.619141 5653 slave.cpp:5980] Handling status update TASK_RUNNING (Status UUID: 1d5a8dc7-bcdc-4540-810b-18fe6f3cc370) for task 1 of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000
I0831 23:20:20.620182 5655 task_status_update_manager.cpp:383] Forwarding task status update TASK_RUNNING (Status UUID: ec15da08-798c-499a-8aa7-9ad4525495ad) for task 0 of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000 to the agent
I0831 23:20:20.620715 5653 http.cpp:1436] HTTP POST for /slave(2)/api/v1/executor from 172.17.0.4:37598
I0831 23:20:20.620895 5653 slave.cpp:5980] Handling status update TASK_FINISHED (Status UUID: b73fa864-3d3e-4f6f-ba0a-e632eb907ab5) for task 1 of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000
I0831 23:20:20.621533 5653 slave.cpp:6526] Forwarding the update TASK_RUNNING (Status UUID: ec15da08-798c-499a-8aa7-9ad4525495ad) for task 0 of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000 to master@172.17.0.4:37375
I0831 23:20:20.621927 5653 slave.cpp:6410] Task status update manager successfully handled status update TASK_RUNNING (Status UUID: ec15da08-798c-499a-8aa7-9ad4525495ad) for task 0 of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000
I0831 23:20:20.622119 5634 master.cpp:8117] Status update TASK_RUNNING (Status UUID: ec15da08-798c-499a-8aa7-9ad4525495ad) for task 0 of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000 from agent c9d498db-5640-4b1e-a958-2780891a60f2-S0 at slave(2)@172.17.0.4:37375 (c8c11e6bf65b)
I0831 23:20:20.622212 5634 master.cpp:8174] Forwarding status update TASK_RUNNING (Status UUID: ec15da08-798c-499a-8aa7-9ad4525495ad) for task 0 of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000
I0831 23:20:20.622684 5650 task_status_update_manager.cpp:328] Received task status update TASK_RUNNING (Status UUID: 1d5a8dc7-bcdc-4540-810b-18fe6f3cc370) for task 1 of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000
I0831 23:20:20.622809 5650 task_status_update_manager.cpp:507] Creating StatusUpdate stream for task 1 of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000
I0831 23:20:20.623170 5634 master.cpp:11151] Updating the state of task 0 of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000 (latest state: TASK_FINISHED, status update state: TASK_RUNNING)
I0831 23:20:20.623538 5650 task_status_update_manager.cpp:383] Forwarding task status update TASK_RUNNING (Status UUID: 1d5a8dc7-bcdc-4540-810b-18fe6f3cc370) for task 1 of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000 to the agent
I0831 23:20:20.623769 5648 slave.cpp:6526] Forwarding the update TASK_RUNNING (Status UUID: 1d5a8dc7-bcdc-4540-810b-18fe6f3cc370) for task 1 of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000 to master@172.17.0.4:37375
I0831 23:20:20.623986 5650 task_status_update_manager.cpp:328] Received task status update TASK_FINISHED (Status UUID: b5d6a8eb-fe29-4a31-a6d3-a1c60ed31c54) for task 0 of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000
I0831 23:20:20.624011 5648 slave.cpp:6410] Task status update manager successfully handled status update TASK_RUNNING (Status UUID: 1d5a8dc7-bcdc-4540-810b-18fe6f3cc370) for task 1 of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000
I0831 23:20:20.624184 5641 hierarchical.cpp:1658] Recovered cpus(allocated: *):1; mem(allocated: *):128 (total: cpus:2; mem:10240; disk:3748421; ports:[31000-32000], offered or allocated: mem(allocated: *):128; cpus(allocated: *):1) on agent c9d498db-5640-4b1e-a958-2780891a60f2-S0 from framework c9d498db-5640-4b1e-a958-2780891a60f2-0000
I0831 23:20:20.624209 5638 scheduler.cpp:845] Enqueuing event UPDATE received from http://172.17.0.4:37375/master/api/v1/scheduler
I0831 23:20:20.624219 5637 master.cpp:8117] Status update TASK_RUNNING (Status UUID: 1d5a8dc7-bcdc-4540-810b-18fe6f3cc370) for task 1 of framework c9d498db-5640-4b1e-a958-2780891a60f2-0000 from agent c9d498db-5640-4b1e-a958-2780891a60f2-S0 at slave(2)@172.17.0.4:37375 (c8c11e6bf65b)
I0831 23:20:20.624296 5648 slave.cpp:6410] Task status update manager successfully handled status update TASK_FINISHED (Status UUID: b5d6a8eb-fe29-4a31-a6d3-a1c60ed31c54) for task 0 of framework c9d498db-5640-4b1e-a958-2780891a60f2-000Build timed out (after 240 minutes). Marking the build as failed.
Build was aborted
Build failed in Jenkins: Mesos » Mesos-Reviewbot-Linux #248
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://ci-builds.apache.org/job/Mesos/job/Mesos-Reviewbot-Linux/248/display/redirect>
Changes:
------------------------------------------
[...truncated 13.74 MB...]
I0831 20:03:54.414850 5503 registrar.cpp:544] Successfully updated the registry in 744960ns
I0831 20:03:54.414978 5503 registrar.cpp:416] Successfully recovered registrar
I0831 20:03:54.415668 5518 hierarchical.cpp:676] Skipping recovery of hierarchical allocator: nothing to recover
I0831 20:03:54.415678 5514 master.cpp:1819] Recovered 0 agents from the registry (144B); allowing 10mins for agents to reregister
W0831 20:03:54.416544 5497 process.cpp:2877] Attempted to spawn already running process version@172.17.0.2:33975
I0831 20:03:54.417562 5497 sched.cpp:239] Version: 1.11.0
I0831 20:03:54.418216 5515 sched.cpp:343] New master detected at master@172.17.0.2:33975
I0831 20:03:54.418342 5515 sched.cpp:408] Authenticating with master master@172.17.0.2:33975
I0831 20:03:54.418365 5515 sched.cpp:415] Using default CRAM-MD5 authenticatee
I0831 20:03:54.418704 5505 authenticatee.cpp:121] Creating new client SASL connection
I0831 20:03:54.419013 5515 master.cpp:9727] Authenticating scheduler-58545a66-9c46-4855-8713-0c585528b871@172.17.0.2:33975
I0831 20:03:54.419137 5504 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(282)@172.17.0.2:33975
I0831 20:03:54.419474 5506 authenticator.cpp:98] Creating new server SASL connection
I0831 20:03:54.419886 5501 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0831 20:03:54.419941 5501 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0831 20:03:54.420166 5501 authenticator.cpp:204] Received SASL authentication start
I0831 20:03:54.420351 5501 authenticator.cpp:326] Authentication requires more steps
I0831 20:03:54.420549 5511 authenticatee.cpp:259] Received SASL authentication step
I0831 20:03:54.420734 5511 authenticator.cpp:232] Received SASL authentication step
I0831 20:03:54.420783 5511 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '24698f921814' server FQDN: '24698f921814' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0831 20:03:54.420800 5511 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0831 20:03:54.420871 5511 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0831 20:03:54.420913 5511 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '24698f921814' server FQDN: '24698f921814' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0831 20:03:54.420928 5511 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0831 20:03:54.420940 5511 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0831 20:03:54.420966 5511 authenticator.cpp:318] Authentication success
I0831 20:03:54.421125 5517 authenticatee.cpp:299] Authentication success
I0831 20:03:54.421259 5521 master.cpp:9759] Successfully authenticated principal 'test-principal' at scheduler-58545a66-9c46-4855-8713-0c585528b871@172.17.0.2:33975
I0831 20:03:54.421361 5516 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(282)@172.17.0.2:33975
I0831 20:03:54.421738 5520 sched.cpp:520] Successfully authenticated with master master@172.17.0.2:33975
I0831 20:03:54.421794 5520 sched.cpp:835] Sending SUBSCRIBE call to master@172.17.0.2:33975
I0831 20:03:54.422020 5520 sched.cpp:870] Will retry registration in 347.591949ms if necessary
I0831 20:03:54.422293 5498 master.cpp:2931] Refusing subscription of framework 'framework1' at scheduler-58545a66-9c46-4855-8713-0c585528b871@172.17.0.2:33975: Roles { role1 } are not present in the master's --roles
I0831 20:03:54.422612 5498 sched.cpp:1188] Got error 'Roles { role1 } are not present in the master's --roles'
I0831 20:03:54.422639 5498 sched.cpp:2200] Asked to abort the driver
I0831 20:03:54.422706 5498 sched.cpp:1199] Scheduler::error took 32976ns
I0831 20:03:54.422770 5498 sched.cpp:1234] Aborting framework
I0831 20:03:54.422788 5498 sched.cpp:1239] Not sending a deactivate message as master is disconnected
W0831 20:03:54.423363 5497 process.cpp:2877] Attempted to spawn already running process version@172.17.0.2:33975
I0831 20:03:54.424068 5497 sched.cpp:239] Version: 1.11.0
I0831 20:03:54.424713 5511 sched.cpp:343] New master detected at master@172.17.0.2:33975
I0831 20:03:54.424896 5511 sched.cpp:408] Authenticating with master master@172.17.0.2:33975
I0831 20:03:54.424927 5511 sched.cpp:415] Using default CRAM-MD5 authenticatee
I0831 20:03:54.425390 5521 authenticatee.cpp:121] Creating new client SASL connection
I0831 20:03:54.425727 5511 master.cpp:9727] Authenticating scheduler-5d0303e3-c8d8-4277-ae9f-ccaf9f91e72f@172.17.0.2:33975
I0831 20:03:54.425926 5502 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(283)@172.17.0.2:33975
I0831 20:03:54.426290 5517 authenticator.cpp:98] Creating new server SASL connection
I0831 20:03:54.426606 5508 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0831 20:03:54.426642 5508 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0831 20:03:54.426765 5516 authenticator.cpp:204] Received SASL authentication start
I0831 20:03:54.426863 5516 authenticator.cpp:326] Authentication requires more steps
I0831 20:03:54.426988 5516 authenticatee.cpp:259] Received SASL authentication step
I0831 20:03:54.427129 5516 authenticator.cpp:232] Received SASL authentication step
I0831 20:03:54.427172 5516 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '24698f921814' server FQDN: '24698f921814' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0831 20:03:54.427204 5516 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0831 20:03:54.427258 5516 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0831 20:03:54.427305 5516 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '24698f921814' server FQDN: '24698f921814' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0831 20:03:54.427328 5516 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0831 20:03:54.427358 5516 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0831 20:03:54.427395 5516 authenticator.cpp:318] Authentication success
I0831 20:03:54.427546 5507 authenticatee.cpp:299] Authentication success
I0831 20:03:54.427614 5500 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(283)@172.17.0.2:33975
I0831 20:03:54.427737 5499 master.cpp:9759] Successfully authenticated principal 'test-principal' at scheduler-5d0303e3-c8d8-4277-ae9f-ccaf9f91e72f@172.17.0.2:33975
I0831 20:03:54.428143 5510 sched.cpp:520] Successfully authenticated with master master@172.17.0.2:33975
I0831 20:03:54.428229 5510 sched.cpp:835] Sending SUBSCRIBE call to master@172.17.0.2:33975
I0831 20:03:54.428458 5510 sched.cpp:870] Will retry registration in 572.722353ms if necessary
I0831 20:03:54.428783 5509 master.cpp:2941] Received SUBSCRIBE call for framework 'framework2' at scheduler-5d0303e3-c8d8-4277-ae9f-ccaf9f91e72f@172.17.0.2:33975
I0831 20:03:54.432657 5521 master.cpp:3024] Subscribing framework framework2 with checkpointing disabled and capabilities [ MULTI_ROLE, RESERVATION_REFINEMENT ]
I0831 20:03:54.435271 5521 master.cpp:9958] Adding framework 780f06d5-c47f-4a34-9f60-35493d75e8bc-0000 (framework2) at scheduler-5d0303e3-c8d8-4277-ae9f-ccaf9f91e72f@172.17.0.2:33975 with roles { } suppressed
I0831 20:03:54.436067 5521 sched.cpp:751] Framework registered with 780f06d5-c47f-4a34-9f60-35493d75e8bc-0000
I0831 20:03:54.436231 5521 sched.cpp:770] Scheduler::registered took 119237ns
I0831 20:03:54.437119 5497 sched.cpp:2166] Asked to stop the driver
I0831 20:03:54.437435 5499 sched.cpp:1204] Stopping framework 780f06d5-c47f-4a34-9f60-35493d75e8bc-0000
I0831 20:03:54.437901 5498 master.cpp:10323] Processing TEARDOWN call for framework 780f06d5-c47f-4a34-9f60-35493d75e8bc-0000 (framework2) at scheduler-5d0303e3-c8d8-4277-ae9f-ccaf9f91e72f@172.17.0.2:33975
I0831 20:03:54.437959 5498 master.cpp:10335] Removing framework 780f06d5-c47f-4a34-9f60-35493d75e8bc-0000 (framework2) at scheduler-5d0303e3-c8d8-4277-ae9f-ccaf9f91e72f@172.17.0.2:33975
I0831 20:03:54.437989 5498 master.cpp:3385] Deactivating framework 780f06d5-c47f-4a34-9f60-35493d75e8bc-0000 (framework2) at scheduler-5d0303e3-c8d8-4277-ae9f-ccaf9f91e72f@172.17.0.2:33975
I0831 20:03:54.438752 5504 hierarchical.cpp:1859] Allocation paused
I0831 20:03:54.438863 5504 hierarchical.cpp:1869] Allocation resumed
I0831 20:03:54.439222 5497 sched.cpp:2166] Asked to stop the driver
I0831 20:03:54.439450 5502 sched.cpp:1204] Stopping framework
I0831 20:03:54.440770 5497 master.cpp:1145] Master terminating
[ OK ] MasterAllocatorTest/0.RoleTest (48 ms)
[ RUN ] MasterAllocatorTest/0.FrameworkReregistersFirst
W0831 20:03:54.449983 5497 process.cpp:2877] Attempted to spawn already running process version@172.17.0.2:33975
I0831 20:03:54.453343 5497 cluster.cpp:195] Creating default 'local' authorizer
I0831 20:03:54.574106 5497 leveldb.cpp:174] Opened db in 120.347909ms
I0831 20:03:54.608428 5497 leveldb.cpp:181] Compacted db in 34.249279ms
I0831 20:03:54.608532 5497 leveldb.cpp:196] Created db iterator in 35597ns
I0831 20:03:54.608562 5497 leveldb.cpp:202] Seeked to beginning of db in 2730ns
I0831 20:03:54.608582 5497 leveldb.cpp:277] Iterated through 0 keys in the db in 767ns
I0831 20:03:54.608667 5497 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0831 20:03:54.609752 5509 recover.cpp:437] Starting replica recovery
I0831 20:03:54.610215 5514 recover.cpp:468] Replica is in EMPTY status
I0831 20:03:54.612102 5510 replica.cpp:677] Replica in EMPTY status received a broadcasted recover request from __req_res__(1060)@172.17.0.2:33975
I0831 20:03:54.613220 5500 recover.cpp:197] Received a recover response from a replica in EMPTY status
I0831 20:03:54.614169 5518 recover.cpp:564] Updating replica status to STARTING
I0831 20:03:54.616528 5502 master.cpp:448] Master b34a52b5-8838-4ce1-bac7-2d5b1875baf2 (24698f921814) started on 172.17.0.2:33975
I0831 20:03:54.616575 5502 master.cpp:451] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="1secs" --allocator="hierarchical" --authenticate_agents="true" --authenticate_frameworks="true" --authenticate_http_frameworks="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authentication_v0_timeout="15secs" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/yEOZme/credentials" --filter_gpu_resources="true" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_framework_authenticators="basic" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --max_operator_event_stream_subscribers="1000" --max_unreachable_tasks_per_framework="1000" --memory_profiling="false" --min_allocatable_resources="cpus:0.01|mem:32" --offer_constraints_re2_max_mem="4KB" --offer_constraints_re2_max_program_size="100" --port="5050" --publish_per_framework_metrics="true" --quiet="false" --recovery_agent_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_gc_interval="15mins" --registry_max_agent_age="2weeks" --registry_max_agent_count="102400" --registry_store_timeout="100secs" --registry_strict="false" --require_agent_domain="false" --role_sorter="drf" --root_submissions="true" --version="false" --webui_dir="/tmp/SRC/build/mesos-1.11.0/_inst/share/mesos/webui" --work_dir="/tmp/yEOZme/master" --zk_session_timeout="10secs"
I0831 20:03:54.617175 5502 master.cpp:500] Master only allowing authenticated frameworks to register
I0831 20:03:54.617199 5502 master.cpp:506] Master only allowing authenticated agents to register
I0831 20:03:54.617215 5502 master.cpp:512] Master only allowing authenticated HTTP frameworks to register
I0831 20:03:54.617231 5502 credentials.hpp:37] Loading credentials for authentication from '/tmp/yEOZme/credentials'
I0831 20:03:54.617594 5502 master.cpp:556] Using default 'crammd5' authenticator
I0831 20:03:54.617849 5502 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
I0831 20:03:54.618129 5502 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
I0831 20:03:54.618399 5502 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
I0831 20:03:54.618651 5502 master.cpp:637] Authorization enabled
I0831 20:03:54.619246 5507 hierarchical.cpp:637] Initialized hierarchical allocator process
I0831 20:03:54.619249 5510 whitelist_watcher.cpp:77] No whitelist given
I0831 20:03:54.623129 5516 master.cpp:2170] Elected as the leading master!
I0831 20:03:54.623203 5516 master.cpp:1666] Recovering from registrar
I0831 20:03:54.623461 5503 registrar.cpp:339] Recovering registrar
I0831 20:03:54.649173 5501 leveldb.cpp:310] Persisting metadata (8 bytes) to leveldb took 34.70586ms
I0831 20:03:54.649215 5501 replica.cpp:322] Persisted replica status to STARTING
I0831 20:03:54.649526 5501 recover.cpp:468] Replica is in STARTING status
I0831 20:03:54.650766 5505 replica.cpp:677] Replica in STARTING status received a broadcasted recover request from __req_res__(1061)@172.17.0.2:33975
I0831 20:03:54.651363 5508 recover.cpp:197] Received a recover response from a replica in STARTING status
I0831 20:03:54.652256 5513 recover.cpp:564] Updating replica status to VOTING
I0831 20:03:54.682713 5515 leveldb.cpp:310] Persisting metadata (8 bytes) to leveldb took 30.135694ms
I0831 20:03:54.682787 5515 replica.cpp:322] Persisted replica status to VOTING
I0831 20:03:54.683086 5518 recover.cpp:578] Successfully joined the Paxos group
I0831 20:03:54.683506 5518 recover.cpp:447] Recover process terminated
I0831 20:03:54.684574 5516 log.cpp:554] Attempting to start the writer
I0831 20:03:54.687110 5517 replica.cpp:497] Replica received implicit promise request from __req_res__(1062)@172.17.0.2:33975 with proposal 1
I0831 20:03:54.716143 5517 leveldb.cpp:310] Persisting metadata (8 bytes) to leveldb took 28.972261ms
I0831 20:03:54.716235 5517 replica.cpp:344] Persisted promised to 1
I0831 20:03:54.717502 5510 coordinator.cpp:238] Coordinator attempting to fill missing positions
I0831 20:03:54.720105 5501 replica.cpp:391] Replica received explicit promise request from __req_res__(1063)@172.17.0.2:33975 for position 0 with proposal 2
I0831 20:03:54.749588 5501 leveldb.cpp:347] Persisting action (8 bytes) to leveldb took 29.345518ms
I0831 20:03:54.749666 5501 replica.cpp:712] Persisted action NOP at position 0
I0831 20:03:54.751619 5508 replica.cpp:541] Replica received write request for position 0 from __req_res__(1064)@172.17.0.2:33975
I0831 20:03:54.751756 5508 leveldb.cpp:460] Reading position from leveldb took 70874ns
I0831 20:03:54.783007 5508 leveldb.cpp:347] Persisting action (14 bytes) to leveldb took 31.138807ms
I0831 20:03:54.783072 5508 replica.cpp:712] Persisted action NOP at position 0
I0831 20:03:54.784283 5503 replica.cpp:695] Replica received learned notice for position 0 from log-network(52)@172.17.0.2:33975
I0831 20:03:54.816439 5503 leveldb.cpp:347] Persisting action (16 bytes) to leveldb took 32.09028ms
I0831 20:03:54.816514 5503 replica.cpp:712] Persisted action NOP at position 0
I0831 20:03:54.817642 5517 log.cpp:570] Writer started with ending position 0
I0831 20:03:54.820439 5511 leveldb.cpp:460] Reading position from leveldb took 55937ns
I0831 20:03:54.822717 5508 registrar.cpp:383] Successfully fetched the registry (0B) in 199.1808ms
I0831 20:03:54.822952 5508 registrar.cpp:487] Applied 1 operations in 68004ns; attempting to update the registry
I0831 20:03:54.824355 5512 log.cpp:578] Attempting to append 183 bytes to the log
I0831 20:03:54.824709 5498 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
I0831 20:03:54.826179 5521 replica.cpp:541] Replica received write request for position 1 from __req_res__(1065)@172.17.0.2:33975
I0831 20:03:54.858228 5521 leveldb.cpp:347] Persisting action (202 bytes) to leveldb took 31.966898ms
I0831 20:03:54.858297 5521 replica.cpp:712] Persisted action APPEND at position 1
I0831 20:03:54.859474 5517 replica.cpp:695] Replica received learned notice for position 1 from log-network(52)@172.17.0.2:33975
I0831 20:03:54.891625 5517 leveldb.cpp:347] Persisting action (204 bytes) to leveldb took 32.08312ms
I0831 20:03:54.891695 5517 replica.cpp:712] Persisted action APPEND at position 1
I0831 20:03:54.893453 5508 registrar.cpp:544] Successfully updated the registry in 70.398976ms
I0831 20:03:54.893726 5499 log.cpp:597] Attempting to truncate the log to 1
I0831 20:03:54.893764 5508 registrar.cpp:416] Successfully recovered registrar
I0831 20:03:54.894006 5512 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
I0831 20:03:54.894582 5499 master.cpp:1819] Recovered 0 agents from the registry (144B); allowing 10mins for agents to reregister
I0831 20:03:54.894624 5509 hierarchical.cpp:676] Skipping recovery of hierarchical allocator: nothing to recover
I0831 20:03:54.895767 5507 replica.cpp:541] Replica received write request for position 2 from __req_res__(1066)@172.17.0.2:33975
I0831 20:03:54.924993 5507 leveldb.cpp:347] Persisting action (16 bytes) to leveldb took 29.151181ms
I0831 20:03:54.925053 5507 replica.cpp:712] Persisted action TRUNCATE at position 2
I0831 20:03:54.926235 5517 replica.cpp:695] Replica received learned notice for position 2 from log-network(52)@172.17.0.2:33975
I0831 20:03:54.966718 5517 leveldb.cpp:347] Persisting action (18 bytes) to leveldb took 40.41144ms
I0831 20:03:54.966854 5517 leveldb.cpp:423] Deleting ~1 keys from leveldb took 74062ns
I0831 20:03:54.966894 5517 replica.cpp:712] Persisted action TRUNCATE at position 2
W0831 20:03:54.974273 5497 process.cpp:2877] Attempted to spawn already running process files@172.17.0.2:33975
I0831 20:03:54.974931 5497 resolver.cpp:69] Creating default secret resolver
I0831 20:03:54.975082 5497 cluster.cpp:620] Creating default 'local' authorizer
I0831 20:03:54.977512 5504 slave.cpp:281] Mesos agent started on (131)@172.17.0.2:33975
I0831 20:03:54.977563 5504 slave.cpp:282] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/yEOZme/1G9On8/store/appc" --authenticate_http_readonly="true" --authenticate_http_readwrite="false" --authenticatee="crammd5" --authentication_backoff_factor="1secs" --authentication_timeout_max="1mins" --authentication_timeout_min="5secs" --authorizer="local" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_destroy_timeout="1mins" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/yEOZme/1G9On8/credential" --default_role="*" --disallow_sharing_agent_ipc_namespace="false" --disallow_sharing_agent_pid_namespace="false" --disk_watch_interval="1mins" --docker="docker" --docker_ignore_runtime="false" --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/yEOZme/1G9On8/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --docker_volume_chown="false" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_reregistration_timeout="2secs" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/yEOZme/1G9On8/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/yEOZme/1G9On8/frameworks" --gc_delay="1weeks" --gc_disk_headroom="0.1" --gc_non_executor_container_sandboxes="false" --help="false" --hostname_lookup="true" --http_command_executor="false" --http_credentials="/tmp/yEOZme/1G9On8/http_credentials" --http_executor_domain_sockets="false" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/tmp/SRC/build/mesos-1.11.0/_build/sub/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --memory_profiling="false" --network_cni_metrics="true" --network_cni_root_dir_persist="false" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns" --quiet="false" --reconfiguration_policy="equal" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:2;mem:1024" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/MasterAllocatorTest_0_FrameworkReregistersFirst_Orjxna" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_enable_support="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/MasterAllocatorTest_0_FrameworkReregistersFirst_RM0fnc" --zk_session_timeout="10secs"
I0831 20:03:54.978519 5504 credentials.hpp:73] Loading credential for authentication from '/tmp/yEOZme/1G9On8/credential'
I0831 20:03:54.978694 5497 sched.cpp:239] Version: 1.11.0
I0831 20:03:54.978801 5504 slave.cpp:314] Agent using credential for: test-principal
I0831 20:03:54.978844 5504 credentials.hpp:37] Loading credentials for authentication from '/tmp/yEOZme/1G9On8/http_credentials'
I0831 20:03:54.979204 5504 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
I0831 20:03:54.979647 5500 sched.cpp:343] New master detected at master@172.17.0.2:33975
I0831 20:03:54.979915 5500 sched.cpp:408] Authenticating with master master@172.17.0.2:33975
I0831 20:03:54.979919 5504 disk_profile_adaptor.cpp:78] Creating default disk profile adaptor module
I0831 20:03:54.97997Build timed out (after 240 minutes). Marking the build as failed.
1 5500 sched.cpp:415] Using default CRAM-MD5 authenticatee
I0831 20:03:54.980543 5501 authenticatee.cpp:121] Creating new client SASL connection
I0831 20:03:54.981052 5500 master.cpp:9727] Authenticating scheduler-73c2fe47-954b-47d5-944d-3f16ade7f8e9@172.17.0.2:33975
I0831 20:03:54.981290 5499 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(284)@172.17.0.2:33975
I0831 20:03:54.981818 5509 authenticator.cpp:98] Creating new server SASL connection
I0831 20:03:54.982234 5503 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0831 20:03:54.981848 5504 slave.cpp:629] Agent resources: [{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":3748421.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
I0831 20:03:54.982311 5503 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0831 20:03:54.982337 5504 slave.cpp:637] Agent attributes: [ ]
I0831 20:03:54.982378 5504 slave.cpp:646] Agent hostname: 24698f921814
I0831 20:03:54.982563 5512 authenticator.cpp:204] Received SASL authentication start
I0831 20:03:54.982710 5512 authenticator.cpp:326] Authentication requires more steps
I0831 20:03:54.982730 5520 status_update_manager_process.hpp:379] Pausing operation status update manager
I0831 20:03:54.982764 5521 task_status_update_manager.cpp:181] Pausing sending task status updates
I0831 20:03:54.982913 5521 authenticatee.cpp:259] Received SASL authentication step
I0831 20:03:54.983135 5521 authenticator.cpp:232] Received SASL authentication step
I0831 20:03:54.983214 5521 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '24698f921814' server FQDN: '24698f921814' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0831 20:03:54.983244 5521 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0831 20:03:54.983321 5521 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0831 20:03:54.983368 5521 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '24698f921814' server FQDN: '24698f921814' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0831 20:03:54.983394 5521 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0831 20:03:54.983418 5521 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0831 20:03:54.983458 5521 authenticator.cpp:318] Authentication success
I0831 20:03:54.983666 5511 authenticatee.cpp:299] Authentication success
I0831 20:03:54.983831 5513 master.cpp:9759] Successfully authenticated principal 'test-principal' at scheduler-73c2fe47-954b-47d5-944d-3f16ade7f8e9@172.17.0.2:33975
I0831 20:03:54.983870 5506 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(284)@172.17.0.2:33975
I0831 20:03:54.984449 5518 sched.cpp:520] Successfully authenticated with master master@172.17.0.2:33975
I0831 20:03:54.984499 5518 sched.cpp:835] Sending SUBSCRIBE call to master@172.17.0.2:33975
I0831 20:03:54.984766 5518 sched.cpp:870] Will retry registration in 1.151635859secs if necessary
I0831 20:03:54.985186 5498 master.cpp:2941] Received SUBSCRIBE call for framework 'default' at scheduler-73c2fe47-954b-47d5-944d-3f16ade7f8e9@172.17.0.2:33975
I0831 20:03:54.986150 5501 state.cpp:68] Recovering state from '/tmp/MasterAllocatorTest_0_FrameworkReregistersFirst_RM0fnc/meta'
I0831 20:03:54.986572 5505 slave.cpp:7741] Finished recovering checkpointed state from '/tmp/MasterAllocatorTest_0_FrameworkReregistersFirst_RM0fnc/meta', beginning agent recovery
I0831 20:03:54.987507 5498 task_status_update_manager.cpp:207] Recovering task status update manager
I0831 20:03:54.989564 5521 master.cpp:3024] Subscribing framework default with checkpointing disabled and capabilities [ MULTI_ROLE, RESERVATION_REFINEMENT ]
I0831 20:03:54.989578 5519 composing.cpp:343] Finished recovering all containerizers
I0831 20:03:54.990130 5511 slave.cpp:8223] Recovering executors
I0831 20:03:54.990283 5511 slave.cpp:8376] Finished recovery
I0831 20:03:54.991129 5511 slave.cpp:1473] New master detected at master@172.17.0.2:33975
I0831 20:03:54.991142 5515 task_status_update_manager.cpp:181] Pausing sending task status updates
I0831 20:03:54.991194 5501 status_update_manager_process.hpp:379] Pausing operation status update manager
I0831 20:03:54.991286 5511 slave.cpp:1538] Detecting new master
I0831 20:03:54.991746 5521 master.cpp:9958] Adding framework b34a52b5-8838-4ce1-bac7-2d5b1875baf2-0000 (default) at scheduler-73c2fe47-954b-47d5-944d-3f16ade7f8e9@172.17.0.2:33975 with roles { } suppressed
I0831 20:03:54.992378 5505 sched.cpp:751] Framework registered with b34a52b5-8838-4ce1-bac7-2d5b1875baf2-0000
I0831 20:03:54.992439 5505 sched.cpp:770] Scheduler::registered took 29013ns
I0831 20:03:54.992964 5500 hierarchical.cpp:774] Added framework b34a52b5-8838-4ce1-bac7-2d5b1875baf2-0000
I0831 20:03:54.993312 5500 hierarchical.cpp:1935] Performed allocation for 0 agents in 117985ns
I0831 20:03:55.001747 5509 slave.cpp:1565] Authenticating with master master@172.17.0.2:33975
I0831 20:03:55.001909 5509 slave.cpp:1574] Using default CRAM-MD5 authenticatee
I0831 20:03:55.002308 5499 authenticatee.cpp:121] Creating new client SASL connection
I0831 20:03:55.002570 5498 master.cpp:9727] Authenticating slave(131)@172.17.0.2:33975
I0831 20:03:55.002735 5516 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(285)@172.17.0.2:33975
I0831 20:03:55.003177 5507 authenticator.cpp:98] Creating new server SASL connection
I0831 20:03:55.003501 5512 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0831 20:03:55.003530 5512 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0831 20:03:55.003638 5512 authenticator.cpp:204] Received SASL authentication start
I0831 20:03:55.003692 5512 authenticator.cpp:326] Authentication requires more steps
I0831 20:03:55.003796 5512 authenticatee.cpp:259] Received SASL authentication step
I0831 20:03:55.003901 5512 authenticator.cpp:232] Received SASL authentication step
I0831 20:03:55.003942 5512 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '24698f921814' server FQDN: '24698f921814' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0831 20:03:55.003957 5512 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0831 20:03:55.003988 5512 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0831 20:03:55.004014 5512 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '24698f921814' server FQDN: '24698f921814' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0831 20:03:55.004029 5512 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0831 20:03:55.004040 5512 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0831 20:03:55.004056 5512 authenticator.cpp:318] Authentication success
I0831 20:03:55.004217 5517 authenticatee.cpp:299] Authentication success
I0831 20:03:55.004272 5519 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(285)@172.17.0.2:33975
I0831 20:03:55.004277 5502 master.cpp:9759] Successfully authenticated principal 'test-principal' at slave(131)@172.17.0.2:33975
I0831 20:03:55.004894 5518 slave.cpp:1665] Successfully authenticated with master master@172.17.0.2:33975
I0831 20:03:55.005725 5518 slave.cpp:2131] Will retry registration in 15.629068ms if necessary
I0831 20:03:55.006012 5511 master.cpp:6221] Received register agent message from slave(131)@172.17.0.2:33975 (24698f921814)
I0831 20:03:55.006561 5511 master.cpp:3752] Authorizing principal 'test-principal' to perform actionBuild was aborted
REGISTER_AGENT on ANY object