mesos-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Greg Mann (JIRA)" <j...@apache.org>
Subject [jira] [Updated] (MESOS-4968) ResourceOffersTest.ResourceOfferWithMultipleSlaves is flaky
Date Wed, 23 Mar 2016 18:44:25 GMT

     [ https://issues.apache.org/jira/browse/MESOS-4968?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Greg Mann updated MESOS-4968:
-----------------------------
    Environment: Ubuntu 14.04 with clang and gcc, with and without libevent/SSL  (was: Ubuntu 14.04 with clang and gcc, without libevent/SSL)

> ResourceOffersTest.ResourceOfferWithMultipleSlaves is flaky
> -----------------------------------------------------------
>
>                 Key: MESOS-4968
>                 URL: https://issues.apache.org/jira/browse/MESOS-4968
>             Project: Mesos
>          Issue Type: Bug
>          Components: tests
>         Environment: Ubuntu 14.04 with clang and gcc, with and without libevent/SSL
>            Reporter: Greg Mann
>              Labels: flaky-test, mesosphere
>
> Just observed on the ASF CI:
> {code}
> [ RUN      ] ResourceOffersTest.ResourceOfferWithMultipleSlaves
> I0317 16:31:52.635798 32063 cluster.cpp:139] Creating default 'local' authorizer
> I0317 16:31:52.743732 32063 leveldb.cpp:174] Opened db in 107.706253ms
> I0317 16:31:52.782537 32063 leveldb.cpp:181] Compacted db in 38.758479ms
> I0317 16:31:52.782641 32063 leveldb.cpp:196] Created db iterator in 34392ns
> I0317 16:31:52.782662 32063 leveldb.cpp:202] Seeked to beginning of db in 10490ns
> I0317 16:31:52.782675 32063 leveldb.cpp:271] Iterated through 0 keys in the db in 7177ns
> I0317 16:31:52.782728 32063 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> I0317 16:31:52.783476 32094 recover.cpp:447] Starting replica recovery
> I0317 16:31:52.783738 32094 recover.cpp:473] Replica is in EMPTY status
> I0317 16:31:52.785109 32086 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (9482)@172.17.0.2:43540
> I0317 16:31:52.785851 32081 recover.cpp:193] Received a recover response from a replica in EMPTY status
> I0317 16:31:52.786602 32085 recover.cpp:564] Updating replica status to STARTING
> I0317 16:31:52.790009 32090 master.cpp:376] Master 0196163d-91f7-4337-9dd7-9fef49e8cd75 (76df5a57a9ca) started on 172.17.0.2:43540
> I0317 16:31:52.790082 32090 master.cpp:378] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="true" --authenticate_http="true" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/Rxm8q7/credentials" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --max_slave_ping_timeouts="5" --quiet="false" --recovery_slave_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="100secs" --registry_strict="true" --root_submissions="true" --slave_ping_timeout="15secs" --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" --webui_dir="/mesos/mesos-0.29.0/_inst/share/mesos/webui" --work_dir="/tmp/Rxm8q7/master" --zk_session_timeout="10secs"
> I0317 16:31:52.790520 32090 master.cpp:423] Master only allowing authenticated frameworks to register
> I0317 16:31:52.790534 32090 master.cpp:428] Master only allowing authenticated slaves to register
> I0317 16:31:52.790541 32090 credentials.hpp:35] Loading credentials for authentication from '/tmp/Rxm8q7/credentials'
> I0317 16:31:52.790952 32090 master.cpp:468] Using default 'crammd5' authenticator
> I0317 16:31:52.791162 32090 master.cpp:537] Using default 'basic' HTTP authenticator
> I0317 16:31:52.791335 32090 master.cpp:571] Authorization enabled
> I0317 16:31:52.791538 32092 whitelist_watcher.cpp:77] No whitelist given
> I0317 16:31:52.791584 32089 hierarchical.cpp:144] Initialized hierarchical allocator process
> I0317 16:31:52.794270 32089 master.cpp:1806] The newly elected leader is master@172.17.0.2:43540 with id 0196163d-91f7-4337-9dd7-9fef49e8cd75
> I0317 16:31:52.794325 32089 master.cpp:1819] Elected as the leading master!
> I0317 16:31:52.794342 32089 master.cpp:1508] Recovering from registrar
> I0317 16:31:52.794919 32093 registrar.cpp:307] Recovering registrar
> I0317 16:31:52.815771 32081 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 28.36765ms
> I0317 16:31:52.815862 32081 replica.cpp:320] Persisted replica status to STARTING
> I0317 16:31:52.816234 32096 recover.cpp:473] Replica is in STARTING status
> I0317 16:31:52.818017 32082 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (9484)@172.17.0.2:43540
> I0317 16:31:52.818408 32090 recover.cpp:193] Received a recover response from a replica in STARTING status
> I0317 16:31:52.819475 32090 recover.cpp:564] Updating replica status to VOTING
> I0317 16:31:52.840878 32090 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 21.14905ms
> I0317 16:31:52.840965 32090 replica.cpp:320] Persisted replica status to VOTING
> I0317 16:31:52.841151 32090 recover.cpp:578] Successfully joined the Paxos group
> I0317 16:31:52.841361 32090 recover.cpp:462] Recover process terminated
> I0317 16:31:52.842133 32090 log.cpp:659] Attempting to start the writer
> I0317 16:31:52.843859 32090 replica.cpp:493] Replica received implicit promise request from (9485)@172.17.0.2:43540 with proposal 1
> I0317 16:31:52.866013 32090 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 22.148046ms
> I0317 16:31:52.866120 32090 replica.cpp:342] Persisted promised to 1
> I0317 16:31:52.867507 32090 coordinator.cpp:238] Coordinator attempting to fill missing positions
> I0317 16:31:52.869362 32090 replica.cpp:388] Replica received explicit promise request from (9486)@172.17.0.2:43540 for position 0 with proposal 2
> I0317 16:31:52.891146 32090 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 21.762946ms
> I0317 16:31:52.891257 32090 replica.cpp:712] Persisted action at 0
> I0317 16:31:52.892900 32085 replica.cpp:537] Replica received write request for position 0 from (9487)@172.17.0.2:43540
> I0317 16:31:52.893028 32085 leveldb.cpp:436] Reading position from leveldb took 71935ns
> I0317 16:31:52.916239 32085 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 23.179851ms
> I0317 16:31:52.916335 32085 replica.cpp:712] Persisted action at 0
> I0317 16:31:52.917539 32094 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
> I0317 16:31:52.941332 32094 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 23.784309ms
> I0317 16:31:52.941417 32094 replica.cpp:712] Persisted action at 0
> I0317 16:31:52.941452 32094 replica.cpp:697] Replica learned NOP action at position 0
> I0317 16:31:52.942643 32094 log.cpp:675] Writer started with ending position 0
> I0317 16:31:52.944149 32094 leveldb.cpp:436] Reading position from leveldb took 89370ns
> I0317 16:31:52.945827 32091 registrar.cpp:340] Successfully fetched the registry (0B) in 150.809856ms
> I0317 16:31:52.946007 32091 registrar.cpp:439] Applied 1 operations in 56238ns; attempting to update the 'registry'
> I0317 16:31:52.946954 32094 log.cpp:683] Attempting to append 170 bytes to the log
> I0317 16:31:52.947252 32094 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
> I0317 16:31:52.948446 32094 replica.cpp:537] Replica received write request for position 1 from (9488)@172.17.0.2:43540
> I0317 16:31:52.974792 32094 leveldb.cpp:341] Persisting action (189 bytes) to leveldb took 26.324846ms
> I0317 16:31:52.974887 32094 replica.cpp:712] Persisted action at 1
> I0317 16:31:52.976449 32094 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
> I0317 16:31:52.999909 32094 leveldb.cpp:341] Persisting action (191 bytes) to leveldb took 23.456466ms
> I0317 16:31:53.000002 32094 replica.cpp:712] Persisted action at 1
> I0317 16:31:53.000039 32094 replica.cpp:697] Replica learned APPEND action at position 1
> I0317 16:31:53.001710 32082 registrar.cpp:484] Successfully updated the 'registry' in 55.634176ms
> I0317 16:31:53.001929 32082 registrar.cpp:370] Successfully recovered registrar
> I0317 16:31:53.002017 32094 log.cpp:702] Attempting to truncate the log to 1
> I0317 16:31:53.002205 32082 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
> I0317 16:31:53.002441 32094 master.cpp:1616] Recovered 0 slaves from the Registry (131B) ; allowing 10mins for slaves to re-register
> I0317 16:31:53.002730 32091 hierarchical.cpp:171] Skipping recovery of hierarchical allocator: nothing to recover
> I0317 16:31:53.003767 32092 replica.cpp:537] Replica received write request for position 2 from (9489)@172.17.0.2:43540
> I0317 16:31:53.041689 32092 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 37.901762ms
> I0317 16:31:53.041787 32092 replica.cpp:712] Persisted action at 2
> I0317 16:31:53.043413 32092 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
> I0317 16:31:53.075132 32092 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 31.716913ms
> I0317 16:31:53.075299 32092 leveldb.cpp:399] Deleting ~1 keys from leveldb took 96076ns
> I0317 16:31:53.075328 32092 replica.cpp:712] Persisted action at 2
> I0317 16:31:53.075362 32092 replica.cpp:697] Replica learned TRUNCATE action at position 2
> I0317 16:31:53.087807 32063 containerizer.cpp:149] Using isolation: posix/cpu,posix/mem,filesystem/posix
> W0317 16:31:53.088914 32063 backend.cpp:66] Failed to create 'bind' backend: BindBackend requires root privileges
> I0317 16:31:53.092515 32093 slave.cpp:193] Slave started on 286)@172.17.0.2:43540
> I0317 16:31:53.092586 32093 slave.cpp:194] Flags at startup: --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_pZkayQ/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_pZkayQ/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-0.29.0/_build/src" --logbufsecs="0" --logging_level="INFO" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:2;mem:1024" --revocable_cpu_low_priority="true" --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/ResourceOffersTest_ResourceOfferWithMultipleSlaves_pZkayQ"
> I0317 16:31:53.093057 32093 credentials.hpp:83] Loading credential for authentication from '/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_pZkayQ/credential'
> I0317 16:31:53.093334 32093 slave.cpp:324] Slave using credential for: test-principal
> I0317 16:31:53.093514 32093 resources.cpp:572] Parsing resources as JSON failed: cpus:2;mem:1024
> Trying semicolon-delimited string format instead
> I0317 16:31:53.094039 32093 slave.cpp:464] Slave resources: cpus(*):2; mem(*):1024; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0317 16:31:53.094117 32093 slave.cpp:472] Slave attributes: [  ]
> I0317 16:31:53.094132 32093 slave.cpp:477] Slave hostname: 76df5a57a9ca
> I0317 16:31:53.095661 32091 state.cpp:58] Recovering state from '/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_pZkayQ/meta'
> I0317 16:31:53.095962 32089 status_update_manager.cpp:200] Recovering status update manager
> I0317 16:31:53.096174 32091 containerizer.cpp:407] Recovering containerizer
> I0317 16:31:53.097944 32087 provisioner.cpp:245] Provisioner recovery complete
> I0317 16:31:53.098002 32063 containerizer.cpp:149] Using isolation: posix/cpu,posix/mem,filesystem/posix
> I0317 16:31:53.098474 32087 slave.cpp:4565] Finished recovery
> I0317 16:31:53.099041 32087 slave.cpp:4737] Querying resource estimator for oversubscribable resources
> I0317 16:31:53.099365 32096 status_update_manager.cpp:174] Pausing sending status updates
> I0317 16:31:53.099375 32091 slave.cpp:796] New master detected at master@172.17.0.2:43540
> I0317 16:31:53.099467 32091 slave.cpp:859] Authenticating with master master@172.17.0.2:43540
> I0317 16:31:53.099485 32091 slave.cpp:864] Using default CRAM-MD5 authenticatee
> I0317 16:31:53.099647 32091 slave.cpp:832] Detecting new master
> I0317 16:31:53.099705 32083 authenticatee.cpp:121] Creating new client SASL connection
> I0317 16:31:53.099861 32087 slave.cpp:4751] Received oversubscribable resources  from the resource estimator
> I0317 16:31:53.100008 32088 master.cpp:5659] Authenticating slave(286)@172.17.0.2:43540
> I0317 16:31:53.100121 32087 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(614)@172.17.0.2:43540
> I0317 16:31:53.100344 32088 authenticator.cpp:98] Creating new server SASL connection
> I0317 16:31:53.100603 32083 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
> I0317 16:31:53.100643 32083 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0317 16:31:53.100750 32088 authenticator.cpp:203] Received SASL authentication start
> W0317 16:31:53.100757 32063 backend.cpp:66] Failed to create 'bind' backend: BindBackend requires root privileges
> I0317 16:31:53.100816 32088 authenticator.cpp:325] Authentication requires more steps
> I0317 16:31:53.100898 32088 authenticatee.cpp:258] Received SASL authentication step
> I0317 16:31:53.101102 32093 authenticator.cpp:231] Received SASL authentication step
> I0317 16:31:53.101142 32093 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: '76df5a57a9ca' server FQDN: '76df5a57a9ca' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
> I0317 16:31:53.101160 32093 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
> I0317 16:31:53.101209 32093 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0317 16:31:53.101255 32093 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: '76df5a57a9ca' server FQDN: '76df5a57a9ca' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
> I0317 16:31:53.101270 32093 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0317 16:31:53.101280 32093 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0317 16:31:53.101302 32093 authenticator.cpp:317] Authentication success
> I0317 16:31:53.101470 32093 authenticatee.cpp:298] Authentication success
> I0317 16:31:53.101559 32093 master.cpp:5689] Successfully authenticated principal 'test-principal' at slave(286)@172.17.0.2:43540
> I0317 16:31:53.101642 32093 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(614)@172.17.0.2:43540
> I0317 16:31:53.101976 32093 slave.cpp:927] Successfully authenticated with master master@172.17.0.2:43540
> I0317 16:31:53.102121 32093 slave.cpp:1321] Will retry registration in 19711us if necessary
> I0317 16:31:53.102473 32086 master.cpp:4370] Registering slave at slave(286)@172.17.0.2:43540 (76df5a57a9ca) with id 0196163d-91f7-4337-9dd7-9fef49e8cd75-S0
> I0317 16:31:53.102900 32081 registrar.cpp:439] Applied 1 operations in 104925ns; attempting to update the 'registry'
> I0317 16:31:53.104300 32096 log.cpp:683] Attempting to append 339 bytes to the log
> I0317 16:31:53.104409 32083 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3
> I0317 16:31:53.105547 32086 replica.cpp:537] Replica received write request for position 3 from (9512)@172.17.0.2:43540
> I0317 16:31:53.105753 32095 slave.cpp:193] Slave started on 287)@172.17.0.2:43540
> I0317 16:31:53.105789 32095 slave.cpp:194] Flags at startup: --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_X1UxGz/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_X1UxGz/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-0.29.0/_build/src" --logbufsecs="0" --logging_level="INFO" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:2;mem:1024" --revocable_cpu_low_priority="true" --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/ResourceOffersTest_ResourceOfferWithMultipleSlaves_X1UxGz"
> I0317 16:31:53.106307 32095 credentials.hpp:83] Loading credential for authentication from '/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_X1UxGz/credential'
> I0317 16:31:53.106539 32095 slave.cpp:324] Slave using credential for: test-principal
> I0317 16:31:53.106712 32095 resources.cpp:572] Parsing resources as JSON failed: cpus:2;mem:1024
> Trying semicolon-delimited string format instead
> I0317 16:31:53.107216 32095 slave.cpp:464] Slave resources: cpus(*):2; mem(*):1024; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0317 16:31:53.107302 32095 slave.cpp:472] Slave attributes: [  ]
> I0317 16:31:53.107316 32095 slave.cpp:477] Slave hostname: 76df5a57a9ca
> I0317 16:31:53.108665 32084 state.cpp:58] Recovering state from '/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_X1UxGz/meta'
> I0317 16:31:53.108948 32095 status_update_manager.cpp:200] Recovering status update manager
> I0317 16:31:53.109158 32096 containerizer.cpp:407] Recovering containerizer
> I0317 16:31:53.112571 32092 provisioner.cpp:245] Provisioner recovery complete
> I0317 16:31:53.112829 32063 containerizer.cpp:149] Using isolation: posix/cpu,posix/mem,filesystem/posix
> I0317 16:31:53.112964 32095 slave.cpp:4565] Finished recovery
> I0317 16:31:53.113559 32095 slave.cpp:4737] Querying resource estimator for oversubscribable resources
> W0317 16:31:53.113787 32063 backend.cpp:66] Failed to create 'bind' backend: BindBackend requires root privileges
> I0317 16:31:53.114090 32095 slave.cpp:796] New master detected at master@172.17.0.2:43540
> I0317 16:31:53.114181 32095 slave.cpp:859] Authenticating with master master@172.17.0.2:43540
> I0317 16:31:53.114207 32095 slave.cpp:864] Using default CRAM-MD5 authenticatee
> I0317 16:31:53.114284 32096 status_update_manager.cpp:174] Pausing sending status updates
> I0317 16:31:53.114382 32095 slave.cpp:832] Detecting new master
> I0317 16:31:53.114425 32096 authenticatee.cpp:121] Creating new client SASL connection
> I0317 16:31:53.114500 32095 slave.cpp:4751] Received oversubscribable resources  from the resource estimator
> I0317 16:31:53.114795 32083 master.cpp:5659] Authenticating slave(287)@172.17.0.2:43540
> I0317 16:31:53.115020 32084 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(615)@172.17.0.2:43540
> I0317 16:31:53.115280 32081 authenticator.cpp:98] Creating new server SASL connection
> I0317 16:31:53.115486 32084 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
> I0317 16:31:53.115532 32084 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0317 16:31:53.115645 32084 authenticator.cpp:203] Received SASL authentication start
> I0317 16:31:53.115725 32084 authenticator.cpp:325] Authentication requires more steps
> I0317 16:31:53.115818 32084 authenticatee.cpp:258] Received SASL authentication step
> I0317 16:31:53.115999 32084 authenticator.cpp:231] Received SASL authentication step
> I0317 16:31:53.116037 32084 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: '76df5a57a9ca' server FQDN: '76df5a57a9ca' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
> I0317 16:31:53.116053 32084 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
> I0317 16:31:53.116106 32084 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0317 16:31:53.116138 32084 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: '76df5a57a9ca' server FQDN: '76df5a57a9ca' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
> I0317 16:31:53.116153 32084 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0317 16:31:53.116163 32084 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0317 16:31:53.116183 32084 authenticator.cpp:317] Authentication success
> I0317 16:31:53.116405 32084 master.cpp:5689] Successfully authenticated principal 'test-principal' at slave(287)@172.17.0.2:43540
> I0317 16:31:53.116495 32084 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(615)@172.17.0.2:43540
> I0317 16:31:53.117792 32083 slave.cpp:193] Slave started on 288)@172.17.0.2:43540
> I0317 16:31:53.117831 32083 slave.cpp:194] Flags at startup: --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_ivNM01/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_ivNM01/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-0.29.0/_build/src" --logbufsecs="0" --logging_level="INFO" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:2;mem:1024" --revocable_cpu_low_priority="true" --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/ResourceOffersTest_ResourceOfferWithMultipleSlaves_ivNM01"
> I0317 16:31:53.118285 32083 credentials.hpp:83] Loading credential for authentication from '/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_ivNM01/credential'
> I0317 16:31:53.118491 32083 slave.cpp:324] Slave using credential for: test-principal
> I0317 16:31:53.118563 32094 authenticatee.cpp:298] Authentication success
> I0317 16:31:53.118656 32083 resources.cpp:572] Parsing resources as JSON failed: cpus:2;mem:1024
> Trying semicolon-delimited string format instead
> I0317 16:31:53.118938 32095 slave.cpp:927] Successfully authenticated with master master@172.17.0.2:43540
> I0317 16:31:53.119091 32095 slave.cpp:1321] Will retry registration in 17.304605ms if necessary
> I0317 16:31:53.119128 32083 slave.cpp:464] Slave resources: cpus(*):2; mem(*):1024; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0317 16:31:53.119185 32083 slave.cpp:472] Slave attributes: [  ]
> I0317 16:31:53.119196 32083 slave.cpp:477] Slave hostname: 76df5a57a9ca
> I0317 16:31:53.119395 32081 master.cpp:4370] Registering slave at slave(287)@172.17.0.2:43540 (76df5a57a9ca) with id 0196163d-91f7-4337-9dd7-9fef49e8cd75-S1
> I0317 16:31:53.120662 32081 state.cpp:58] Recovering state from '/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_ivNM01/meta'
> I0317 16:31:53.120932 32090 status_update_manager.cpp:200] Recovering status update manager
> I0317 16:31:53.121235 32087 containerizer.cpp:407] Recovering containerizer
> I0317 16:31:53.122521 32063 containerizer.cpp:149] Using isolation: posix/cpu,posix/mem,filesystem/posix
> I0317 16:31:53.123252 32087 provisioner.cpp:245] Provisioner recovery complete
> W0317 16:31:53.123344 32063 backend.cpp:66] Failed to create 'bind' backend: BindBackend requires root privileges
> I0317 16:31:53.123991 32081 slave.cpp:4565] Finished recovery
> I0317 16:31:53.124574 32081 slave.cpp:4737] Querying resource estimator for oversubscribable resources
> I0317 16:31:53.124866 32091 status_update_manager.cpp:174] Pausing sending status updates
> I0317 16:31:53.124881 32081 slave.cpp:796] New master detected at master@172.17.0.2:43540
> I0317 16:31:53.124984 32081 slave.cpp:859] Authenticating with master master@172.17.0.2:43540
> I0317 16:31:53.125103 32081 slave.cpp:864] Using default CRAM-MD5 authenticatee
> I0317 16:31:53.125378 32081 slave.cpp:832] Detecting new master
> I0317 16:31:53.125512 32081 slave.cpp:4751] Received oversubscribable resources  from the resource estimator
> I0317 16:31:53.125566 32088 master.cpp:4358] Ignoring register slave message from slave(286)@172.17.0.2:43540 (76df5a57a9ca) as admission is already in progress
> I0317 16:31:53.125674 32089 authenticatee.cpp:121] Creating new client SASL connection
> I0317 16:31:53.125872 32096 slave.cpp:1321] Will retry registration in 16.581037ms if necessary
> I0317 16:31:53.126107 32081 master.cpp:5659] Authenticating slave(288)@172.17.0.2:43540
> I0317 16:31:53.126250 32096 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(616)@172.17.0.2:43540
> I0317 16:31:53.126498 32082 authenticator.cpp:98] Creating new server SASL connection
> I0317 16:31:53.126742 32089 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
> I0317 16:31:53.126783 32089 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0317 16:31:53.126916 32085 authenticator.cpp:203] Received SASL authentication start
> I0317 16:31:53.126993 32085 authenticator.cpp:325] Authentication requires more steps
> I0317 16:31:53.127115 32089 authenticatee.cpp:258] Received SASL authentication step
> I0317 16:31:53.127259 32091 authenticator.cpp:231] Received SASL authentication step
> I0317 16:31:53.127293 32091 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: '76df5a57a9ca' server FQDN: '76df5a57a9ca' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
> I0317 16:31:53.127308 32091 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
> I0317 16:31:53.127357 32091 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0317 16:31:53.127382 32091 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: '76df5a57a9ca' server FQDN: '76df5a57a9ca' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
> I0317 16:31:53.127394 32091 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0317 16:31:53.127404 32091 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0317 16:31:53.127424 32091 authenticator.cpp:317] Authentication success
> I0317 16:31:53.127598 32089 authenticatee.cpp:298] Authentication success
> I0317 16:31:53.127779 32085 slave.cpp:193] Slave started on 289)@172.17.0.2:43540
> I0317 16:31:53.127903 32091 master.cpp:5689] Successfully authenticated principal 'test-principal' at slave(288)@172.17.0.2:43540
> I0317 16:31:53.128116 32089 slave.cpp:927] Successfully authenticated with master master@172.17.0.2:43540
> I0317 16:31:53.127809 32085 slave.cpp:194] Flags at startup: --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_X6hYou/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_X6hYou/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-0.29.0/_build/src" --logbufsecs="0" --logging_level="INFO" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:2;mem:1024" --revocable_cpu_low_priority="true" --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/ResourceOffersTest_ResourceOfferWithMultipleSlaves_X6hYou"
> I0317 16:31:53.128269 32085 credentials.hpp:83] Loading credential for authentication from '/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_X6hYou/credential'
> I0317 16:31:53.128391 32089 slave.cpp:1321] Will retry registration in 17.678963ms if necessary
> I0317 16:31:53.128495 32085 slave.cpp:324] Slave using credential for: test-principal
> I0317 16:31:53.128533 32087 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(616)@172.17.0.2:43540
> I0317 16:31:53.128612 32082 master.cpp:4370] Registering slave at slave(288)@172.17.0.2:43540 (76df5a57a9ca) with id 0196163d-91f7-4337-9dd7-9fef49e8cd75-S2
> I0317 16:31:53.128703 32085 resources.cpp:572] Parsing resources as JSON failed: cpus:2;mem:1024
> Trying semicolon-delimited string format instead
> I0317 16:31:53.129300 32085 slave.cpp:464] Slave resources: cpus(*):2; mem(*):1024; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0317 16:31:53.129364 32085 slave.cpp:472] Slave attributes: [  ]
> I0317 16:31:53.129380 32085 slave.cpp:477] Slave hostname: 76df5a57a9ca
> I0317 16:31:53.130594 32093 state.cpp:58] Recovering state from '/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_X6hYou/meta'
> I0317 16:31:53.131108 32093 status_update_manager.cpp:200] Recovering status update manager
> I0317 16:31:53.131134 32063 containerizer.cpp:149] Using isolation: posix/cpu,posix/mem,filesystem/posix
> I0317 16:31:53.131386 32093 containerizer.cpp:407] Recovering containerizer
> I0317 16:31:53.132987 32088 provisioner.cpp:245] Provisioner recovery complete
> I0317 16:31:53.133401 32083 slave.cpp:4565] Finished recovery
> I0317 16:31:53.138638 32091 slave.cpp:1321] Will retry registration in 32.096084ms if necessary
> I0317 16:31:53.138909 32091 master.cpp:4358] Ignoring register slave message from slave(287)@172.17.0.2:43540 (76df5a57a9ca) as admission is already in progress
> I0317 16:31:53.144634 32091 slave.cpp:1321] Will retry registration in 25.46288ms if necessary
> I0317 16:31:53.144917 32088 master.cpp:4358] Ignoring register slave message from slave(286)@172.17.0.2:43540 (76df5a57a9ca) as admission is already in progress
> I0317 16:31:53.146539 32085 slave.cpp:1321] Will retry registration in 12.815689ms if necessary
> I0317 16:31:53.146916 32085 master.cpp:4358] Ignoring register slave message from slave(288)@172.17.0.2:43540 (76df5a57a9ca) as admission is already in progress
> I0317 16:31:53.160727 32085 slave.cpp:1321] Will retry registration in 11.033778ms if necessary
> I0317 16:31:53.161092 32085 master.cpp:4358] Ignoring register slave message from slave(288)@172.17.0.2:43540 (76df5a57a9ca) as admission is already in progress
> I0317 16:31:53.170780 32085 slave.cpp:1321] Will retry registration in 137.201004ms if necessary
> I0317 16:31:53.171142 32085 master.cpp:4358] Ignoring register slave message from slave(286)@172.17.0.2:43540 (76df5a57a9ca) as admission is already in progress
> I0317 16:31:53.171764 32081 slave.cpp:1321] Will retry registration in 56.960724ms if necessary
> I0317 16:31:53.171931 32081 master.cpp:4358] Ignoring register slave message from slave(287)@172.17.0.2:43540 (76df5a57a9ca) as admission is already in progress
> I0317 16:31:53.173300 32086 leveldb.cpp:341] Persisting action (358 bytes) to leveldb took 67.638838ms
> I0317 16:31:53.173387 32086 replica.cpp:712] Persisted action at 3
> I0317 16:31:53.173653 32086 slave.cpp:1321] Will retry registration in 89.683754ms if necessary
> I0317 16:31:53.174126 32086 master.cpp:4358] Ignoring register slave message from slave(288)@172.17.0.2:43540 (76df5a57a9ca) as admission is already in progress
> I0317 16:31:53.175120 32081 replica.cpp:691] Replica received learned notice for position 3 from @0.0.0.0:0
> I0317 16:31:53.178517 32083 slave.cpp:4737] Querying resource estimator for oversubscribable resources
> I0317 16:31:53.178916 32089 slave.cpp:4751] Received oversubscribable resources  from the resource estimator
> W0317 16:31:53.179052 32063 backend.cpp:66] Failed to create 'bind' backend: BindBackend requires root privileges
> I0317 16:31:53.179175 32089 slave.cpp:796] New master detected at master@172.17.0.2:43540
> I0317 16:31:53.179203 32085 status_update_manager.cpp:174] Pausing sending status updates
> I0317 16:31:53.179316 32089 slave.cpp:859] Authenticating with master master@172.17.0.2:43540
> I0317 16:31:53.179339 32089 slave.cpp:864] Using default CRAM-MD5 authenticatee
> I0317 16:31:53.179532 32089 slave.cpp:832] Detecting new master
> I0317 16:31:53.179654 32091 authenticatee.cpp:121] Creating new client SASL connection
> I0317 16:31:53.179956 32089 master.cpp:5659] Authenticating slave(289)@172.17.0.2:43540
> I0317 16:31:53.180085 32086 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(617)@172.17.0.2:43540
> I0317 16:31:53.181392 32083 authenticator.cpp:98] Creating new server SASL connection
> I0317 16:31:53.181632 32096 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
> I0317 16:31:53.181676 32096 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0317 16:31:53.181777 32096 authenticator.cpp:203] Received SASL authentication start
> I0317 16:31:53.181859 32096 authenticator.cpp:325] Authentication requires more steps
> I0317 16:31:53.181949 32096 authenticatee.cpp:258] Received SASL authentication step
> I0317 16:31:53.182051 32096 authenticator.cpp:231] Received SASL authentication step
> I0317 16:31:53.182088 32096 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: '76df5a57a9ca' server FQDN: '76df5a57a9ca' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
> I0317 16:31:53.182106 32096 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
> I0317 16:31:53.182162 32096 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0317 16:31:53.182204 32096 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: '76df5a57a9ca' server FQDN: '76df5a57a9ca' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
> I0317 16:31:53.182257 32096 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0317 16:31:53.182276 32096 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0317 16:31:53.182303 32096 authenticator.cpp:317] Authentication success
> I0317 16:31:53.182502 32096 authenticatee.cpp:298] Authentication success
> I0317 16:31:53.182612 32096 master.cpp:5689] Successfully authenticated principal 'test-principal' at slave(289)@172.17.0.2:43540
> I0317 16:31:53.182714 32096 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(617)@172.17.0.2:43540
> I0317 16:31:53.183099 32096 slave.cpp:927] Successfully authenticated with master master@172.17.0.2:43540
> I0317 16:31:53.183331 32096 slave.cpp:1321] Will retry registration in 1.878556ms if necessary
> I0317 16:31:53.183542 32083 master.cpp:4370] Registering slave at slave(289)@172.17.0.2:43540 (76df5a57a9ca) with id 0196163d-91f7-4337-9dd7-9fef49e8cd75-S3
> I0317 16:31:53.186738 32087 slave.cpp:193] Slave started on 290)@172.17.0.2:43540
> I0317 16:31:53.186789 32087 slave.cpp:194] Flags at startup: --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_7yanQW/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_7yanQW/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-0.29.0/_build/src" --logbufsecs="0" --logging_level="INFO" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:2;mem:1024" --revocable_cpu_low_priority="true" --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/ResourceOffersTest_ResourceOfferWithMultipleSlaves_7yanQW"
> I0317 16:31:53.187301 32087 credentials.hpp:83] Loading credential for authentication from '/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_7yanQW/credential'
> I0317 16:31:53.187563 32087 slave.cpp:324] Slave using credential for: test-principal
> I0317 16:31:53.187890 32087 resources.cpp:572] Parsing resources as JSON failed: cpus:2;mem:1024
> Trying semicolon-delimited string format instead
> I0317 16:31:53.187986 32084 slave.cpp:1321] Will retry registration in 2.221321ms if necessary
> I0317 16:31:53.188395 32084 master.cpp:4358] Ignoring register slave message from slave(289)@172.17.0.2:43540 (76df5a57a9ca) as admission is already in progress
> I0317 16:31:53.188462 32087 slave.cpp:464] Slave resources: cpus(*):2; mem(*):1024; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0317 16:31:53.188554 32087 slave.cpp:472] Slave attributes: [  ]
> I0317 16:31:53.188570 32087 slave.cpp:477] Slave hostname: 76df5a57a9ca
> I0317 16:31:53.190417 32095 state.cpp:58] Recovering state from '/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_7yanQW/meta'
> I0317 16:31:53.191129 32089 status_update_manager.cpp:200] Recovering status update manager
> I0317 16:31:53.191647 32085 containerizer.cpp:407] Recovering containerizer
> I0317 16:31:53.192730 32063 containerizer.cpp:149] Using isolation: posix/cpu,posix/mem,filesystem/posix
> I0317 16:31:53.192780 32083 slave.cpp:1321] Will retry registration in 32.970276ms if necessary
> I0317 16:31:53.193006 32085 master.cpp:4358] Ignoring register slave message from slave(289)@172.17.0.2:43540 (76df5a57a9ca) as admission is already in progress
> I0317 16:31:53.194291 32093 provisioner.cpp:245] Provisioner recovery complete
> I0317 16:31:53.195027 32093 slave.cpp:4565] Finished recovery
> I0317 16:31:53.195971 32093 slave.cpp:4737] Querying resource estimator for oversubscribable resources
> I0317 16:31:53.196740 32093 slave.cpp:796] New master detected at master@172.17.0.2:43540
> I0317 16:31:53.196847 32084 status_update_manager.cpp:174] Pausing sending status updates
> I0317 16:31:53.197134 32093 slave.cpp:859] Authenticating with master master@172.17.0.2:43540
> I0317 16:31:53.197269 32093 slave.cpp:864] Using default CRAM-MD5 authenticatee
> I0317 16:31:53.197770 32082 authenticatee.cpp:121] Creating new client SASL connection
> I0317 16:31:53.198164 32082 master.cpp:5659] Authenticating slave(290)@172.17.0.2:43540
> I0317 16:31:53.198457 32082 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(618)@172.17.0.2:43540
> I0317 16:31:53.198863 32082 authenticator.cpp:98] Creating new server SASL connection
> I0317 16:31:53.199170 32082 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
> I0317 16:31:53.199328 32082 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0317 16:31:53.199525 32082 authenticator.cpp:203] Received SASL authentication start
> I0317 16:31:53.199615 32082 authenticator.cpp:325] Authentication requires more steps
> I0317 16:31:53.199707 32082 authenticatee.cpp:258] Received SASL authentication step
> I0317 16:31:53.199810 32082 authenticator.cpp:231] Received SASL authentication step
> I0317 16:31:53.199846 32082 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: '76df5a57a9ca' server FQDN: '76df5a57a9ca' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
> I0317 16:31:53.199862 32082 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
> I0317 16:31:53.199918 32082 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0317 16:31:53.199957 32082 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: '76df5a57a9ca' server FQDN: '76df5a57a9ca' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
> I0317 16:31:53.199972 32082 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0317 16:31:53.199983 32082 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0317 16:31:53.200004 32082 authenticator.cpp:317] Authentication success
> I0317 16:31:53.200166 32082 authenticatee.cpp:298] Authentication success
> I0317 16:31:53.200263 32082 master.cpp:5689] Successfully authenticated principal 'test-principal' at slave(290)@172.17.0.2:43540
> I0317 16:31:53.200361 32095 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(618)@172.17.0.2:43540
> I0317 16:31:53.200469 32093 slave.cpp:832] Detecting new master
> I0317 16:31:53.201043 32093 slave.cpp:4751] Received oversubscribable resources  from the resource estimator
> I0317 16:31:53.206349 32093 slave.cpp:927] Successfully authenticated with master master@172.17.0.2:43540
> I0317 16:31:53.206538 32093 slave.cpp:1321] Will retry registration in 17.281605ms if necessary
> I0317 16:31:53.206981 32093 master.cpp:4370] Registering slave at slave(290)@172.17.0.2:43540 (76df5a57a9ca) with id 0196163d-91f7-4337-9dd7-9fef49e8cd75-S4
> I0317 16:31:53.225544 32096 slave.cpp:1321] Will retry registration in 35.389556ms if necessary
> I0317 16:31:53.225881 32096 master.cpp:4358] Ignoring register slave message from slave(290)@172.17.0.2:43540 (76df5a57a9ca) as admission is already in progress
> I0317 16:31:53.226611 32096 slave.cpp:1321] Will retry registration in 97.566732ms if necessary
> I0317 16:31:53.226790 32096 master.cpp:4358] Ignoring register slave message from slave(289)@172.17.0.2:43540 (76df5a57a9ca) as admission is already in progress
> I0317 16:31:53.229537 32096 slave.cpp:1321] Will retry registration in 131.038153ms if necessary
> I0317 16:31:53.229746 32096 master.cpp:4358] Ignoring register slave message from slave(287)@172.17.0.2:43540 (76df5a57a9ca) as admission is already in progress
> W0317 16:31:53.240841 32063 backend.cpp:66] Failed to create 'bind' backend: BindBackend requires root privileges
> I0317 16:31:53.244199 32088 slave.cpp:193] Slave started on 291)@172.17.0.2:43540
> I0317 16:31:53.244266 32088 slave.cpp:194] Flags at startup: --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_oEJ0zp/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_oEJ0zp/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-0.29.0/_build/src" --logbufsecs="0" --logging_level="INFO" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:2;mem:1024" --revocable_cpu_low_priority="true" --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/ResourceOffersTest_ResourceOfferWithMultipleSlaves_oEJ0zp"
> I0317 16:31:53.244717 32088 credentials.hpp:83] Loading credential for authentication from '/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_oEJ0zp/credential'
> I0317 16:31:53.244949 32088 slave.cpp:324] Slave using credential for: test-principal
> I0317 16:31:53.245108 32088 resources.cpp:572] Parsing resources as JSON failed: cpus:2;mem:1024
> Trying semicolon-delimited string format instead
> I0317 16:31:53.245632 32088 slave.cpp:464] Slave resources: cpus(*):2; mem(*):1024; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0317 16:31:53.245707 32088 slave.cpp:472] Slave attributes: [  ]
> I0317 16:31:53.245720 32088 slave.cpp:477] Slave hostname: 76df5a57a9ca
> I0317 16:31:53.247097 32088 state.cpp:58] Recovering state from '/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_oEJ0zp/meta'
> I0317 16:31:53.247376 32086 status_update_manager.cpp:200] Recovering status update manager
> I0317 16:31:53.247547 32086 containerizer.cpp:407] Recovering containerizer
> I0317 16:31:53.249081 32088 provisioner.cpp:245] Provisioner recovery complete
> I0317 16:31:53.249312 32081 leveldb.cpp:341] Persisting action (360 bytes) to leveldb took 74.165136ms
> I0317 16:31:53.249397 32081 replica.cpp:712] Persisted action at 3
> I0317 16:31:53.249420 32084 slave.cpp:4565] Finished recovery
> I0317 16:31:53.249433 32081 replica.cpp:697] Replica learned APPEND action at position 3
> I0317 16:31:53.250023 32084 slave.cpp:4737] Querying resource estimator for oversubscribable resources
> I0317 16:31:53.250596 32088 slave.cpp:796] New master detected at master@172.17.0.2:43540
> I0317 16:31:53.250836 32088 slave.cpp:859] Authenticating with master master@172.17.0.2:43540
> I0317 16:31:53.250977 32088 slave.cpp:864] Using default CRAM-MD5 authenticatee
> I0317 16:31:53.250694 32089 status_update_manager.cpp:174] Pausing sending status updates
> I0317 16:31:53.251358 32095 authenticatee.cpp:121] Creating new client SASL connection
> I0317 16:31:53.251540 32088 slave.cpp:832] Detecting new master
> I0317 16:31:53.251711 32088 slave.cpp:4751] Received oversubscribable resources  from the resource estimator
> I0317 16:31:53.251855 32091 registrar.cpp:484] Successfully updated the 'registry' in 148.869888ms
> I0317 16:31:53.252037 32088 log.cpp:702] Attempting to truncate the log to 3
> I0317 16:31:53.252135 32082 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4
> I0317 16:31:53.252400 32091 registrar.cpp:439] Applied 4 operations in 241268ns; attempting to update the 'registry'
> I0317 16:31:53.253443 32090 master.cpp:5659] Authenticating slave(291)@172.17.0.2:43540
> I0317 16:31:53.255300 32095 replica.cpp:537] Replica received write request for position 4 from (9569)@172.17.0.2:43540
> I0317 16:31:53.255564 32084 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(619)@172.17.0.2:43540
> I0317 16:31:53.255769 32090 master.cpp:4438] Registered slave 0196163d-91f7-4337-9dd7-9fef49e8cd75-S0 at slave(286)@172.17.0.2:43540 (76df5a57a9ca) with cpus(*):2; mem(*):1024; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0317 16:31:53.255949 32084 authenticator.cpp:98] Creating new server SASL connection
> I0317 16:31:53.256105 32090 hierarchical.cpp:473] Added slave 0196163d-91f7-4337-9dd7-9fef49e8cd75-S0 (76df5a57a9ca) with cpus(*):2; mem(*):1024; disk(*):3.70122e+06; ports(*):[31000-32000] (allocated: )
> I0317 16:31:53.256280 32084 slave.cpp:971] Registered with master master@172.17.0.2:43540; given slave ID 0196163d-91f7-4337-9dd7-9fef49e8cd75-S0
> I0317 16:31:53.256304 32084 fetcher.cpp:81] Clearing fetcher cache
> I0317 16:31:53.256362 32087 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
> I0317 16:31:53.256429 32087 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0317 16:31:53.256435 32063 containerizer.cpp:149] Using isolation: posix/cpu,posix/mem,filesystem/posix
> I0317 16:31:53.256597 32091 status_update_manager.cpp:181] Resuming sending status updates
> I0317 16:31:53.256716 32084 slave.cpp:994] Checkpointing SlaveInfo to '/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_pZkayQ/meta/slaves/0196163d-91f7-4337-9dd7-9fef49e8cd75-S0/slave.info'
> I0317 16:31:53.256804 32090 hierarchical.cpp:1453] No resources available to allocate!
> I0317 16:31:53.256836 32090 hierarchical.cpp:1150] Performed allocation for slave 0196163d-91f7-4337-9dd7-9fef49e8cd75-S0 in 700215ns
> I0317 16:31:53.257004 32081 authenticator.cpp:203] Received SASL authentication start
> I0317 16:31:53.257093 32081 authenticator.cpp:325] Authentication requires more steps
> I0317 16:31:53.257117 32084 slave.cpp:1030] Forwarding total oversubscribed resources 
> I0317 16:31:53.257187 32081 authenticatee.cpp:258] Received SASL authentication step
> I0317 16:31:53.257207 32084 slave.cpp:3482] Received ping from slave-observer(275)@172.17.0.2:43540
> I0317 16:31:53.257354 32081 authenticator.cpp:231] Received SASL authentication step
> I0317 16:31:53.257390 32081 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: '76df5a57a9ca' server FQDN: '76df5a57a9ca' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
> I0317 16:31:53.257382 32089 master.cpp:4782] Received update of slave 0196163d-91f7-4337-9dd7-9fef49e8cd75-S0 at slave(286)@172.17.0.2:43540 (76df5a57a9ca) with total oversubscribed resources 
> I0317 16:31:53.257405 32081 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
> I0317 16:31:53.257465 32081 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0317 16:31:53.257494 32081 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: '76df5a57a9ca' server FQDN: '76df5a57a9ca' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
> I0317 16:31:53.257508 32081 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0317 16:31:53.257516 32081 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0317 16:31:53.257535 32081 authenticator.cpp:317] Authentication success
> W0317 16:31:53.257856 32063 backend.cpp:66] Failed to create 'bind' backend: BindBackend requires root privileges
> I0317 16:31:53.257879 32096 authenticatee.cpp:298] Authentication success
> I0317 16:31:53.257963 32081 master.cpp:5689] Successfully authenticated principal 'test-principal' at slave(291)@172.17.0.2:43540
> I0317 16:31:53.257984 32096 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(619)@172.17.0.2:43540
> I0317 16:31:53.258035 32089 hierarchical.cpp:531] Slave 0196163d-91f7-4337-9dd7-9fef49e8cd75-S0 (76df5a57a9ca) updated with oversubscribed resources  (total: cpus(*):2; mem(*):1024; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: )
> I0317 16:31:53.258234 32089 hierarchical.cpp:1453] No resources available to allocate!
> I0317 16:31:53.258270 32089 hierarchical.cpp:1150] Performed allocation for slave 0196163d-91f7-4337-9dd7-9fef49e8cd75-S0 in 185126ns
> I0317 16:31:53.258595 32086 slave.cpp:927] Successfully authenticated with master master@172.17.0.2:43540
> I0317 16:31:53.262271 32083 slave.cpp:193] Slave started on 292)@172.17.0.2:43540
> I0317 16:31:53.262496 32086 slave.cpp:1321] Will retry registration in 10.152236ms if necessary
> I0317 16:31:53.262521 32082 slave.cpp:1321] Will retry registration in 21.962237ms if necessary
> I0317 16:31:53.262718 32084 master.cpp:4370] Registering slave at slave(291)@172.17.0.2:43540 (76df5a57a9ca) with id 0196163d-91f7-4337-9dd7-9fef49e8cd75-S5
> I0317 16:31:53.262346 32083 slave.cpp:194] Flags at startup: --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_Wlbu4B/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_Wlbu4B/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-0.29.0/_build/src" --logbufsecs="0" --logging_level="INFO" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:2;mem:1024" --revocable_cpu_low_priority="true" --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/ResourceOffersTest_ResourceOfferWithMultipleSlaves_Wlbu4B"
> I0317 16:31:53.262900 32083 credentials.hpp:83] Loading credential for authentication from '/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_Wlbu4B/credential'
> I0317 16:31:53.263069 32084 master.cpp:4358] Ignoring register slave message from slave(290)@172.17.0.2:43540 (76df5a57a9ca) as admission is already in progress
> I0317 16:31:53.263188 32083 slave.cpp:324] Slave using credential for: test-principal
> I0317 16:31:53.263439 32083 resources.cpp:572] Parsing resources as JSON failed: cpus:2;mem:1024
> Trying semicolon-delimited string format instead
> I0317 16:31:53.264017 32083 slave.cpp:464] Slave resources: cpus(*):2; mem(*):1024; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0317 16:31:53.264103 32083 slave.cpp:472] Slave attributes: [  ]
> I0317 16:31:53.264122 32083 slave.cpp:477] Slave hostname: 76df5a57a9ca
> I0317 16:31:53.264401 32084 slave.cpp:1321] Will retry registration in 181.00181ms if necessary
> I0317 16:31:53.264533 32089 master.cpp:4358] Ignoring register slave message from slave(288)@172.17.0.2:43540 (76df5a57a9ca) as admission is already in progress
> I0317 16:31:53.265970 32083 state.cpp:58] Recovering state from '/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_Wlbu4B/meta'
> I0317 16:31:53.266609 32089 status_update_manager.cpp:200] Recovering status update manager
> I0317 16:31:53.266808 32081 containerizer.cpp:407] Recovering containerizer
> I0317 16:31:53.267633 32063 containerizer.cpp:149] Using isolation: posix/cpu,posix/mem,filesystem/posix
> I0317 16:31:53.268285 32084 provisioner.cpp:245] Provisioner recovery complete
> I0317 16:31:53.269002 32091 slave.cpp:4565] Finished recovery
> W0317 16:31:53.269062 32063 backend.cpp:66] Failed to create 'bind' backend: BindBackend requires root privileges
> I0317 16:31:53.269997 32091 slave.cpp:4737] Querying resource estimator for oversubscribable resources
> I0317 16:31:53.270234 32091 slave.cpp:796] New master detected at master@172.17.0.2:43540
> I0317 16:31:53.270331 32091 slave.cpp:859] Authenticating with master master@172.17.0.2:43540
> I0317 16:31:53.270352 32091 slave.cpp:864] Using default CRAM-MD5 authenticatee
> I0317 16:31:53.270481 32094 status_update_manager.cpp:174] Pausing sending status updates
> I0317 16:31:53.270540 32091 slave.cpp:832] Detecting new master
> I0317 16:31:53.270687 32091 slave.cpp:4751] Received oversubscribable resources  from the resource estimator
> I0317 16:31:53.270820 32094 authenticatee.cpp:121] Creating new client SASL connection
> I0317 16:31:53.271123 32096 master.cpp:5659] Authenticating slave(292)@172.17.0.2:43540
> I0317 16:31:53.271255 32084 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(620)@172.17.0.2:43540
> I0317 16:31:53.271602 32082 authenticator.cpp:98] Creating new server SASL connection
> I0317 16:31:53.272631 32088 slave.cpp:193] Slave started on 293)@172.17.0.2:43540
> I0317 16:31:53.272668 32088 slave.cpp:194] Flags at startup: --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_OGRld5/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_OGRld5/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-0.29.0/_build/src" --logbufsecs="0" --logging_level="INFO" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:2;mem:1024" --revocable_cpu_low_priority="true" --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/ResourceOffersTest_ResourceOfferWithMultipleSlaves_OGRld5"
> I0317 16:31:53.273138 32088 credentials.hpp:83] Loading credential for authentication from '/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_OGRld5/credential'
> I0317 16:31:53.273313 32082 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
> I0317 16:31:53.273353 32082 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0317 16:31:53.273450 32082 authenticator.cpp:203] Received SASL authentication start
> I0317 16:31:53.273525 32082 authenticator.cpp:325] Authentication requires more steps
> I0317 16:31:53.273555 32093 slave.cpp:1321] Will retry registration in 22.063922ms if necessary
> I0317 16:31:53.273672 32093 authenticatee.cpp:258] Received SASL authentication step
> I0317 16:31:53.273775 32082 master.cpp:4358] Ignoring register slave message from slave(291)@172.17.0.2:43540 (76df5a57a9ca) as admission is already in progress
> I0317 16:31:53.273782 32093 authenticator.cpp:231] Received SASL authentication step
> I0317 16:31:53.273840 32093 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: '76df5a57a9ca' server FQDN: '76df5a57a9ca' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
> I0317 16:31:53.273859 32093 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
> I0317 16:31:53.273915 32093 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0317 16:31:53.273957 32093 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: '76df5a57a9ca' server FQDN: '76df5a57a9ca' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
> I0317 16:31:53.273978 32093 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0317 16:31:53.273991 32093 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0317 16:31:53.274014 32093 authenticator.cpp:317] Authentication success
> I0317 16:31:53.274190 32093 authenticatee.cpp:298] Authentication success
> I0317 16:31:53.274283 32084 master.cpp:5689] Successfully authenticated principal 'test-principal' at slave(292)@172.17.0.2:43540
> I0317 16:31:53.274318 32093 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(620)@172.17.0.2:43540
> I0317 16:31:53.274695 32084 slave.cpp:927] Successfully authenticated with master master@172.17.0.2:43540
> I0317 16:31:53.274811 32084 slave.cpp:1321] Will retry registration in 8.975994ms if necessary
> I0317 16:31:53.275122 32084 master.cpp:4370] Registering slave at slave(292)@172.17.0.2:43540 (76df5a57a9ca) with id 0196163d-91f7-4337-9dd7-9fef49e8cd75-S6
> I0317 16:31:53.284827 32084 slave.cpp:1321] Will retry registration in 17.811944ms if necessary
> I0317 16:31:53.285150 32084 master.cpp:4358] Ignoring register slave message from slave(292)@172.17.0.2:43540 (76df5a57a9ca) as admission is already in progress
> I0317 16:31:53.285871 32084 slave.cpp:1321] Will retry registration in 41.896779ms if necessary
> I0317 16:31:53.286046 32084 master.cpp:4358] Ignoring register slave message from slave(290)@172.17.0.2:43540 (76df5a57a9ca) as admission is already in progress
> I0317 16:31:53.296638 32096 slave.cpp:1321] Will retry registration in 34.747976ms if necessary
> I0317 16:31:53.296962 32096 master.cpp:4358] Ignoring register slave message from slave(291)@172.17.0.2:43540 (76df5a57a9ca) as admission is already in progress
> I0317 16:31:53.300526 32088 slave.cpp:324] Slave using credential for: test-principal
> I0317 16:31:53.300786 32088 resources.cpp:572] Parsing resources as JSON failed: cpus:2;mem:1024
> Trying semicolon-delimited string format instead
> I0317 16:31:53.301376 32088 slave.cpp:464] Slave resources: cpus(*):2; mem(*):1024; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0317 16:31:53.301579 32088 slave.cpp:472] Slave attributes: [  ]
> I0317 16:31:53.301693 32088 slave.cpp:477] Slave hostname: 76df5a57a9ca
> I0317 16:31:53.302315 32063 containerizer.cpp:149] Using isolation: posix/cpu,posix/mem,filesystem/posix
> W0317 16:31:53.303107 32063 backend.cpp:66] Failed to create 'bind' backend: BindBackend requires root privileges
> I0317 16:31:53.303565 32090 state.cpp:58] Recovering state from '/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_OGRld5/meta'
> I0317 16:31:53.303890 32086 slave.cpp:1321] Will retry registration in 65.823798ms if necessary
> I0317 16:31:53.304136 32090 master.cpp:4358] Ignoring register slave message from slave(292)@172.17.0.2:43540 (76df5a57a9ca) as admission is already in progress
> I0317 16:31:53.304208 32086 status_update_manager.cpp:200] Recovering status update manager
> I0317 16:31:53.304478 32089 containerizer.cpp:407] Recovering containerizer
> I0317 16:31:53.306411 32096 provisioner.cpp:245] Provisioner recovery complete
> I0317 16:31:53.306596 32091 slave.cpp:193] Slave started on 294)@172.17.0.2:43540
> I0317 16:31:53.307014 32087 slave.cpp:4565] Finished recovery
> I0317 16:31:53.306656 32091 slave.cpp:194] Flags at startup: --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_RHO3py/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_RHO3py/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-0.29.0/_build/src" --logbufsecs="0" --logging_level="INFO" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:2;mem:1024" --revocable_cpu_low_priority="true" --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/ResourceOffersTest_ResourceOfferWithMultipleSlaves_RHO3py"
> I0317 16:31:53.307250 32091 credentials.hpp:83] Loading credential for authentication from '/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_RHO3py/credential'
> I0317 16:31:53.307538 32091 slave.cpp:324] Slave using credential for: test-principal
> I0317 16:31:53.307759 32091 resources.cpp:572] Parsing resources as JSON failed: cpus:2;mem:1024
> Trying semicolon-delimited string format instead
> I0317 16:31:53.307914 32087 slave.cpp:4737] Querying resource estimator for oversubscribable resources
> I0317 16:31:53.308403 32088 status_update_manager.cpp:174] Pausing sending status updates
> I0317 16:31:53.308358 32091 slave.cpp:464] Slave resources: cpus(*):2; mem(*):1024; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0317 16:31:53.308441 32091 slave.cpp:472] Slave attributes: [  ]
> I0317 16:31:53.308441 32087 slave.cpp:796] New master detected at master@172.17.0.2:43540
> I0317 16:31:53.308459 32091 slave.cpp:477] Slave hostname: 76df5a57a9ca
> I0317 16:31:53.308542 32087 slave.cpp:859] Authenticating with master master@172.17.0.2:43540
> I0317 16:31:53.308567 32087 slave.cpp:864] Using default CRAM-MD5 authenticatee
> I0317 16:31:53.309041 32082 authenticatee.cpp:121] Creating new client SASL connection
> I0317 16:31:53.309082 32087 slave.cpp:832] Detecting new master
> I0317 16:31:53.309103 32095 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 53.756668ms
> I0317 16:31:53.309146 32095 replica.cpp:712] Persisted action at 4
> I0317 16:31:53.309453 32095 master.cpp:5659] Authenticating slave(293)@172.17.0.2:43540
> I0317 16:31:53.309581 32087 slave.cpp:4751] Received oversubscribable resources  from the resource estimator
> I0317 16:31:53.309686 32096 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(621)@172.17.0.2:43540
> I0317 16:31:53.309962 32094 authenticator.cpp:98] Creating new server SASL connection
> I0317 16:31:53.310263 32086 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
> I0317 16:31:53.310310 32086 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0317 16:31:53.310451 32095 authenticator.cpp:203] Received SASL authentication start
> I0317 16:31:53.310506 32063 containerizer.cpp:149] Using isolation: posix/cpu,posix/mem,filesystem/posix
> I0317 16:31:53.310529 32095 authenticator.cpp:325] Authentication requires more steps
> I0317 16:31:53.310740 32085 authenticatee.cpp:258] Received SASL authentication step
> I0317 16:31:53.310814 32095 replica.cpp:691] Replica received learned notice for position 4 from @0.0.0.0:0
> I0317 16:31:53.310948 32085 authenticator.cpp:231] Received SASL authentication step
> I0317 16:31:53.310983 32085 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: '76df5a57a9ca' server FQDN: '76df5a57a9ca' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
> I0317 16:31:53.310998 32085 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
> I0317 16:31:53.311058 32085 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0317 16:31:53.311086 32085 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: '76df5a57a9ca' server FQDN: '76df5a57a9ca' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
> I0317 16:31:53.311099 32085 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0317 16:31:53.311107 32085 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0317 16:31:53.311127 32085 authenticator.cpp:317] Authentication success
> I0317 16:31:53.311287 32089 authenticatee.cpp:298] Authentication success
> I0317 16:31:53.311357 32085 master.cpp:5689] Successfully authenticated principal 'test-principal' at slave(293)@172.17.0.2:43540
> I0317 16:31:53.311504 32092 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(621)@172.17.0.2:43540
> I0317 16:31:53.312186 32091 state.cpp:58] Recovering state from '/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_RHO3py/meta'
> I0317 16:31:53.312511 32091 status_update_manager.cpp:200] Recovering status update manager
> I0317 16:31:53.312705 32089 slave.cpp:927] Successfully authenticated with master master@172.17.0.2:43540
> I0317 16:31:53.312767 32086 containerizer.cpp:407] Recovering containerizer
> I0317 16:31:53.312860 32089 slave.cpp:1321] Will retry registration in 8.956678ms if necessary
> I0317 16:31:53.313186 32089 master.cpp:4370] Registering slave at slave(293)@172.17.0.2:43540 (76df5a57a9ca) with id 0196163d-91f7-4337-9dd7-9fef49e8cd75-S7
> W0317 16:31:53.313962 32063 backend.cpp:66] Failed to create 'bind' backend: BindBackend requires root privileges
> I0317 16:31:53.316969 32083 provisioner.cpp:245] Provisioner recovery complete
> I0317 16:31:53.317064 32090 slave.cpp:193] Slave started on 295)@172.17.0.2:43540
> I0317 16:31:53.317153 32090 slave.cpp:194] Flags at startup: --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_ZYxgO1/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_ZYxgO1/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-0.29.0/_build/src" --logbufsecs="0" --logging_level="INFO" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:2;mem:1024" --revocable_cpu_low_priority="true" --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/ResourceOffersTest_ResourceOfferWithMultipleSlaves_ZYxgO1"
> I0317 16:31:53.317610 32090 credentials.hpp:83] Loading credential for authentication from '/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_ZYxgO1/credential'
> I0317 16:31:53.317811 32090 slave.cpp:324] Slave using credential for: test-principal
> I0317 16:31:53.317821 32094 slave.cpp:4565] Finished recovery
> I0317 16:31:53.317975 32090 resources.cpp:572] Parsing resources as JSON failed: cpus:2;mem:1024
> Trying semicolon-delimited string format instead
> I0317 16:31:53.318377 32094 slave.cpp:4737] Querying resource estimator for oversubscribable resources
> I0317 16:31:53.318447 32090 slave.cpp:464] Slave resources: cpus(*):2; mem(*):1024; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0317 16:31:53.318521 32090 slave.cpp:472] Slave attributes: [  ]
> I0317 16:31:53.318534 32090 slave.cpp:477] Slave hostname: 76df5a57a9ca
> I0317 16:31:53.318650 32084 slave.cpp:796] New master detected at master@172.17.0.2:43540
> I0317 16:31:53.318743 32084 slave.cpp:859] Authenticating with master master@172.17.0.2:43540
> I0317 16:31:53.318769 32084 slave.cpp:864] Using default CRAM-MD5 authenticatee
> I0317 16:31:53.318907 32084 slave.cpp:832] Detecting new master
> I0317 16:31:53.319026 32084 slave.cpp:4751] Received oversubscribable resources  from the resource estimator
> I0317 16:31:53.318663 32094 status_update_manager.cpp:174] Pausing sending status updates
> I0317 16:31:53.319288 32096 authenticatee.cpp:121] Creating new client SASL connection
> I0317 16:31:53.319649 32063 sched.cpp:222] Version: 0.29.0
> I0317 16:31:53.319975 32088 state.cpp:58] Recovering state from '/tmp/ResourceOffersTest_ResourceOfferWithMultipleSlaves_ZYxgO1/meta'
> I0317 16:31:53.320080 32089 master.cpp:5659] Authenticating slave(294)@172.17.0.2:43540
> I0317 16:31:53.320312 32091 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(622)@172.17.0.2:43540
> I0317 16:31:53.320755 32096 status_update_manager.cpp:200] Recovering status update manager
> I0317 16:31:53.320801 32086 sched.cpp:326] New master detected at master@172.17.0.2:43540
> I0317 16:31:53.320883 32086 sched.cpp:382] Authenticating with master master@172.17.0.2:43540
> I0317 16:31:53.320905 32086 sched.cpp:389] Using default CRAM-MD5 authenticatee
> I0317 16:31:53.320953 32096 containerizer.cpp:407] Recovering containerizer
> I0317 16:31:53.321233 32086 authenticatee.cpp:121] Creating new client SASL connection
> I0317 16:31:53.321844 32093 master.cpp:5659] Authenticating scheduler-b6838900-3b2b-49c2-abcb-b00ea1c734f4@172.17.0.2:43540
> I0317 16:31:53.321966 32083 authenticator.cpp:98] Creating new server SASL connection
> I0317 16:31:53.322016 32091 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(623)@172.17.0.2:43540
> I0317 16:31:53.322273 32083 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
> I0317 16:31:53.322300 32091 authenticator.cpp:98] Creating new server SASL connection
> I0317 16:31:53.322314 32083 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0317 16:31:53.322499 32083 slave.cpp:1321] Will retry registration in 441332ns if necessary
> I0317 16:31:53.322540 32091 authenticator.cpp:203] Received SASL authentication start
> I0317 16:31:53.322610 32091 authenticator.cpp:325] Authentication requires more steps
> I0317 16:31:53.322630 32086 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
> I0317 16:31:53.322661 32086 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0317 16:31:53.322871 32091 provisioner.cpp:245] Provisioner recovery complete
> I0317 16:31:53.322888 32081 authenticator.cpp:203] Received SASL authentication start
> I0317 16:31:53.322954 32081 authenticator.cpp:325] Authentication requires more steps
> I0317 16:31:53.323045 32081 authenticatee.cpp:258] Received SASL authentication step
> I0317 16:31:53.323165 32084 authenticator.cpp:231] Received SASL authentication step
> I0317 16:31:53.323202 32084 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: '76df5a57a9ca' server FQDN: '76df5a57a9ca' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
> I0317 16:31:53.323217 32084 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
> I0317 16:31:53.323279 32084 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0317 16:31:53.323289 32086 slave.cpp:4565] Finished recovery
> I0317 16:31:53.323312 32084 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: '76df5a57a9ca' server FQDN: '76df5a57a9ca' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
> I0317 16:31:53.323324 32084 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0317 16:31:53.323333 32084 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0317 16:31:53.323353 32084 authenticator.cpp:317] Authentication success
> I0317 16:31:53.323518 32084 authenticatee.cpp:298] Authentication success
> I0317 16:31:53.323623 32084 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(623)@172.17.0.2:43540
> I0317 16:31:53.323947 32093 master.cpp:4358] Ignoring register slave message from slave(293)@172.17.0.2:43540 (76df5a57a9ca) as admission is already in progress
> I0317 16:31:53.323961 32086 slave.cpp:4737] Querying resource estimator for oversubscribable resources
> I0317 16:31:53.324038 32096 sched.cpp:471] Successfully authenticated with master master@172.17.0.2:43540
> I0317 16:31:53.324064 32096 sched.cpp:776] Sending SUBSCRIBE call to master@172.17.0.2:43540
> I0317 16:31:53.324170 32096 sched.cpp:809] Will retry registration in 500.472097ms if necessary
> I0317 16:31:53.324188 32091 slave.cpp:1321] Will retry registration in 44.448753ms if necessary
> I0317 16:31:53.324327 32083 authenticatee.cpp:258] Received SASL authentication step
> I0317 16:31:53.324407 32093 master.cpp:5689] Successfully authenticated principal 'test-principal' at scheduler-b6838900-3b2b-49c2-abcb-b00ea1c734f4@172.17.0.2:43540
> I0317 16:31:53.324447 32083 authenticator.cpp:231] Received SASL authentication step
> I0317 16:31:53.324481 32083 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: '76df5a57a9ca' server FQDN: '76df5a57a9ca' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
> I0317 16:31:53.324497 32083 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
> I0317 16:31:53.324537 32083 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0317 16:31:53.324559 32093 master.cpp:2326] Received SUBSCRIBE call for framework 'default' at scheduler-b6838900-3b2b-49c2-abcb-b00ea1c734f4@172.17.0.2:43540
> I0317 16:31:53.324580 32093 master.cpp:1845] Authorizing framework principal 'test-principal' to receive offers for role '*'
> I0317 16:31:53.324573 32083 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: '76df5a57a9ca' server FQDN: '76df5a57a9ca' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
> I0317 16:31:53.324610 32083 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0317 16:31:53.324621 32083 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0317 16:31:53.324640 32083 authenticator.cpp:317] Authentication success
> I0317 16:31:53.324836 32093 master.cpp:4358] Ignoring register slave message from slave(293)@172.17.0.2:43540 (76df5a57a9ca) as admission is already in progress
> I0317 16:31:53.324906 32093 master.cpp:5689] Successfully authenticated principal 'test-principal' at slave(294)@172.17.0.2:43540
> I0317 16:31:53.324982 32093 master.cpp:2397] Subscribing framework default with checkpointing disabled and capabilities [  ]
> I0317 16:31:53.325026 32083 authenticatee.cpp:298] Authentication success
> I0317 16:31:53.324930 32085 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(622)@172.17.0.2:43540
> I0317 16:31:53.325211 32083 slave.cpp:1321] Will retry registration in 106.056181ms if necessary
> I0317 16:31:53.325479 32085 hierarchical.cpp:265] Added framework 0196163d-91f7-4337-9dd7-9fef49e8cd75-0000
> I0317 16:31:53.325683 32093 master.cpp:4358] Ignoring register slave message from slave(289)@172.17.0.2:43540 (76df5a57a9ca) as admission is already in progress
> I0317 16:31:53.325736 32083 sched.cpp:703] Framework registered with 0196163d-91f7-4337-9dd7-9fef49e8cd75-0000
> I0317 16:31:53.325778 32083 sched.cpp:717] Scheduler::registered took 28022ns
> I0317 16:31:53.325789 32081 slave.cpp:796] New master detected at master@172.17.0.2:43540
> I0317 16:31:53.325819 32083 status_update_manager.cpp:174] Pausing sending status updates
> I0317 16:31:53.325901 32089 slave.cpp:927] Successfully authenticated with master master@172.17.0.2:43540
> I0317 16:31:53.325935 32081 slave.cpp:859] Authenticating with master master@172.17.0.2:43540
> I0317 16:31:53.325958 32081 slave.cpp:864] Using default CRAM-MD5 authenticatee
> I0317 16:31:53.326087 32089 slave.cpp:1321] Will retry registration in 8.262313ms if necessary
> I0317 16:31:53.326138 32081 slave.cpp:832] Detecting new master
> I0317 16:31:53.326251 32083 authenticatee.cpp:121] Creating new client SASL connection
> I0317 16:31:53.326310 32085 hierarchical.cpp:1548] No inverse offers to send out!
> I0317 16:31:53.326351 32085 hierarchical.cpp:1130] Performed allocation for 1 slaves in 857164ns
> I0317 16:31:53.326419 32089 master.cpp:4370] Registering slave at slave(294)@172.17.0.2:43540 (76df5a57a9ca) with id 0196163d-91f7-4337-9dd7-9fef49e8cd75-S8
> I0317 16:31:53.326822 32081 slave.cpp:4751] Received oversubscribable resources  from the resource estimator
> I0317 16:31:53.327114 32089 master.cpp:5488] Sending 1 offers to framework 0196163d-91f7-4337-9dd7-9fef49e8cd75-0000 (default) at scheduler-b6838900-3b2b-49c2-abcb-b00ea1c734f4@172.17.0.2:43540
> I0317 16:31:53.327725 32089 master.cpp:5659] Authenticating slave(295)@172.17.0.2:43540
> I0317 16:31:53.327816 32094 sched.cpp:873] Scheduler::resourceOffers took 318203ns
> I0317 16:31:53.328331 32063 sched.cpp:1903] Asked to stop the driver
> I0317 16:31:53.328474 32089 sched.cpp:1143] Stopping framework '0196163d-91f7-4337-9dd7-9fef49e8cd75-0000'
> I0317 16:31:53.328629 32083 slave.cpp:1321] Will retry registration in 13.899081ms if necessary
> I0317 16:31:53.328737 32092 master.cpp:6061] Processing TEARDOWN call for framework 0196163d-91f7-4337-9dd7-9fef49e8cd75-0000 (default) at scheduler-b6838900-3b2b-49c2-abcb-b00ea1c734f4@172.17.0.2:43540
> I0317 16:31:53.328770 32092 master.cpp:6073] Removing framework 0196163d-91f7-4337-9dd7-9fef49e8cd75-0000 (default) at scheduler-b6838900-3b2b-49c2-abcb-b00ea1c734f4@172.17.0.2:43540
> I0317 16:31:53.328919 32083 hierarchical.cpp:375] Deactivated framework 0196163d-91f7-4337-9dd7-9fef49e8cd75-0000
> I0317 16:31:53.328997 32083 slave.cpp:2079] Asked to shut down framework 0196163d-91f7-4337-9dd7-9fef49e8cd75-0000 by master@172.17.0.2:43540
> W0317 16:31:53.329027 32083 slave.cpp:2094] Cannot shut down unknown framework 0196163d-91f7-4337-9dd7-9fef49e8cd75-0000
> I0317 16:31:53.329593 32083 hierarchical.cpp:890] Recovered cpus(*):2; mem(*):1024; disk(*):3.70122e+06; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: ) on slave 0196163d-91f7-4337-9dd7-9fef49e8cd75-S0 from framework 0196163d-91f7-4337-9dd7-9fef49e8cd75-0000
> I0317 16:31:53.329941 32092 master.cpp:4358] Ignoring register slave message from slave(290)@172.17.0.2:43540 (76df5a57a9ca) as admission is already in progress
> I0317 16:31:53.330127 32084 hierarchical.cpp:326] Removed framework 0196163d-91f7-4337-9dd7-9fef49e8cd75-0000
> I0317 16:31:53.331360 32094 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(624)@172.17.0.2:43540
> I0317 16:31:53.331728 32088 slave.cpp:1321] Will retry registration in 151.78908ms if necessary
> I0317 16:31:53.331933 32088 master.cpp:4358] Ignoring register slave message from slave(291)@172.17.0.2:43540 (76df5a57a9ca) as admission is already in progress
> I0317 16:31:53.332417 32092 authenticator.cpp:98] Creating new server SASL connection
> I0317 16:31:53.332729 32092 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
> I0317 16:31:53.332765 32092 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0317 16:31:53.332847 32092 authenticator.cpp:203] Received SASL authentication start
> I0317 16:31:53.332921 32092 authenticator.cpp:325] Authentication requires more steps
> I0317 16:31:53.333004 32092 authenticatee.cpp:258] Received SASL authentication step
> I0317 16:31:53.333106 32092 authenticator.cpp:231] Received SASL authentication step
> I0317 16:31:53.333137 32092 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: '76df5a57a9ca' server FQDN: '76df5a57a9ca' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
> I0317 16:31:53.333149 32092 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
> I0317 16:31:53.333194 32092 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0317 16:31:53.333241 32092 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: '76df5a57a9ca' server FQDN: '76df5a57a9ca' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
> I0317 16:31:53.333266 32092 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0317 16:31:53.333279 32092 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0317 16:31:53.333302 32092 authenticator.cpp:317] Authentication success
> I0317 16:31:53.333482 32092 authenticatee.cpp:298] Authentication success
> I0317 16:31:53.333575 32092 master.cpp:5689] Successfully authenticated principal 'test-principal' at slave(295)@172.17.0.2:43540
> I0317 16:31:53.333667 32092 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(624)@172.17.0.2:43540
> I0317 16:31:53.333971 32092 slave.cpp:927] Successfully authenticated with master master@172.17.0.2:43540
> I0317 16:31:53.334074 32092 slave.cpp:1321] Will retry registration in 13.498871ms if necessary
> I0317 16:31:53.334384 32092 master.cpp:4370] Registering slave at slave(295)@172.17.0.2:43540 (76df5a57a9ca) with id 0196163d-91f7-4337-9dd7-9fef49e8cd75-S9
> I0317 16:31:53.334939 32090 slave.cpp:1321] Will retry registration in 5.494497ms if necessary
> I0317 16:31:53.335175 32090 master.cpp:4358] Ignoring register slave message from slave(294)@172.17.0.2:43540 (76df5a57a9ca) as admission is already in progress
> I0317 16:31:53.335952 32086 slave.cpp:668] Slave terminating
> I0317 16:31:53.336267 32086 master.cpp:1212] Slave 0196163d-91f7-4337-9dd7-9fef49e8cd75-S0 at slave(286)@172.17.0.2:43540 (76df5a57a9ca) disconnected
> I0317 16:31:53.336303 32086 master.cpp:2681] Disconnecting slave 0196163d-91f7-4337-9dd7-9fef49e8cd75-S0 at slave(286)@172.17.0.2:43540 (76df5a57a9ca)
> I0317 16:31:53.336365 32086 master.cpp:2700] Deactivating slave 0196163d-91f7-4337-9dd7-9fef49e8cd75-S0 at slave(286)@172.17.0.2:43540 (76df5a57a9ca)
> I0317 16:31:53.340410 32086 hierarchical.cpp:560] Slave 0196163d-91f7-4337-9dd7-9fef49e8cd75-S0 deactivated
> I0317 16:31:53.340770 32063 slave.cpp:668] Slave terminating
> I0317 16:31:53.343119 32095 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 32.291311ms
> I0317 16:31:53.343245 32095 leveldb.cpp:399] Deleting ~2 keys from leveldb took 91711ns
> I0317 16:31:53.343247 32086 slave.cpp:1321] Will retry registration in 337182ns if necessary
> I0317 16:31:53.343281 32095 replica.cpp:712] Persisted action at 4
> I0317 16:31:53.343315 32095 replica.cpp:697] Replica learned TRUNCATE action at position 4
> I0317 16:31:53.343489 32082 master.cpp:4358] Ignoring register slave message from slave(294)@172.17.0.2:43540 (76df5a57a9ca) as admission is already in progress
> I0317 16:31:53.344532 32086 slave.cpp:1321] Will retry registration in 55.726101ms if necessary
> I0317 16:31:53.344867 32091 master.cpp:4358] Ignoring register slave message from slave(290)@172.17.0.2:43540 (76df5a57a9ca) as admission is already in progress
> I0317 16:31:53.345196 32086 slave.cpp:668] Slave terminating
> I0317 16:31:53.345613 32086 slave.cpp:1321] Will retry registration in 25.184692ms if necessary
> I0317 16:31:53.345805 32086 master.cpp:4358] Ignoring register slave message from slave(294)@172.17.0.2:43540 (76df5a57a9ca) as admission is already in progress
> I0317 16:31:53.348780 32092 slave.cpp:1321] Will retry registration in 34.731801ms if necessary
> I0317 16:31:53.349040 32086 master.cpp:4358] Ignoring register slave message from slave(295)@172.17.0.2:43540 (76df5a57a9ca) as admission is already in progress
> I0317 16:31:53.349493 32082 log.cpp:683] Attempting to append 1003 bytes to the log
> I0317 16:31:53.349710 32096 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 5
> I0317 16:31:53.351014 32063 slave.cpp:668] Slave terminating
> I0317 16:31:53.351953 32096 replica.cpp:537] Replica received write request for position 5 from (9622)@172.17.0.2:43540
> I0317 16:31:53.356771 32063 slave.cpp:668] Slave terminating
> I0317 16:31:53.361335 32063 slave.cpp:668] Slave terminating
> I0317 16:31:53.368293 32094 slave.cpp:668] Slave terminating
> I0317 16:31:53.371337 32085 slave.cpp:1321] Will retry registration in 155.489751ms if necessary
> I0317 16:31:53.371691 32086 slave.cpp:1321] Will retry registration in 245.502849ms if necessary
> I0317 16:31:53.373518 32087 master.cpp:4358] Ignoring register slave message from slave(293)@172.17.0.2:43540 (76df5a57a9ca) as admission is already in progress
> I0317 16:31:53.373689 32087 master.cpp:4358] Ignoring register slave message from slave(294)@172.17.0.2:43540 (76df5a57a9ca) as admission is already in progress
> I0317 16:31:53.374321 32063 slave.cpp:668] Slave terminating
> I0317 16:31:53.385280 32096 leveldb.cpp:341] Persisting action (1022 bytes) to leveldb took 33.297688ms
> I0317 16:31:53.385376 32096 replica.cpp:712] Persisted action at 5
> I0317 16:31:53.389591 32093 slave.cpp:1321] Will retry registration in 54.982679ms if necessary
> I0317 16:31:53.389953 32093 master.cpp:4358] Ignoring register slave message from slave(295)@172.17.0.2:43540 (76df5a57a9ca) as admission is already in progress
> I0317 16:31:53.391055 32083 replica.cpp:691] Replica received learned notice for position 5 from @0.0.0.0:0
> I0317 16:31:53.393159 32063 slave.cpp:668] Slave terminating
> I0317 16:31:53.405388 32087 slave.cpp:668] Slave terminating
> I0317 16:31:53.411324 32083 leveldb.cpp:341] Persisting action (1024 bytes) to leveldb took 20.262946ms
> I0317 16:31:53.411413 32083 replica.cpp:712] Persisted action at 5
> I0317 16:31:53.411450 32083 replica.cpp:697] Replica learned APPEND action at position 5
> I0317 16:31:53.421093 32063 master.cpp:1065] Master terminating
> I0317 16:31:53.421715 32091 hierarchical.cpp:505] Removed slave 0196163d-91f7-4337-9dd7-9fef49e8cd75-S0
> I0317 16:31:53.426599 32083 registrar.cpp:484] Successfully updated the 'registry' in 171.705856ms
> I0317 16:31:53.427611 32083 registrar.cpp:439] Applied 5 operations in 243279ns; attempting to update the 'registry'
> *** Aborted at 1458232313 (unix time) try "date -d @1458232313" if you are using GNU date ***
> PC: @                0x0 (unknown)
> *** SIGSEGV (@0x0) received by PID 32063 (TID 0x2ac839b6e700) from PID 0; stack trace: ***
>     @     0x2ac861f83ff7 (unknown)
>     @     0x2ac861f88159 (unknown)
>     @     0x2ac8317cb340 (unknown)
> make[4]: Leaving directory `/mesos/mesos-0.29.0/_build/src'
> make[4]: *** [check-local] Segmentation fault
> make[3]: Leaving directory `/mesos/mesos-0.29.0/_build/src'
> make[3]: *** [check-am] Error 2
> make[2]: Leaving directory `/mesos/mesos-0.29.0/_build/src'
> make[2]: *** [check] Error 2
> make[1]: Leaving directory `/mesos/mesos-0.29.0/_build'
> make[1]: *** [check-recursive] Error 1
> make: *** [distcheck] Error 1
> + docker rmi mesos-1458229922-17682
> Untagged: mesos-1458229922-17682:latest
> Deleted: 7b1725d71bd85088d72498fabaa68d8f797b262a5aa5ec4a727e3b1e9a1deddf
> Deleted: 85b9280e12adf2da920145f06a86d98e6d58df787f79d876377efebe26930fb5
> Deleted: 6ed0cd7b7179bb548f1b17acd65f4fe004d9b618a21cbf461d8cdde3e0befcca
> Deleted: ba29a21dd8b56db500a62446adc2eb128395490aab03d10f9fcaf69fa1121064
> Deleted: fa4c4b289ff8000ff0bdc04f4014c382090b2ba0c87b6da1618a5a5e03ea303f
> Deleted: c090f18ab3e8867063d97870c74352bd3c43c53e4fcb53d0bc68af020a6ccbbc
> Deleted: 389ff416fcd5614176701aa3f255e38a2b5a2e1f19b94961d59ed99f6ddb6b0f
> Deleted: 937cbebaa858ceba207af77ef445557905ac3f203cec6c82c6c059bcd230cf11
> Deleted: b6cf9aca2f441408037c70022ed67c5acdd8545904dc18ae8c4a0aa517f0ad7c
> Deleted: e2e9d28f81294dacc395c9a8253799474e1410774ce4ce94d5c4b7ffac01334a
> Deleted: d3d1a9b5d17a595f23b6de7f91c56ce065e6c42d1e7775600b75d0a5764c0668
> Deleted: 0b5e89656454575ff409269c4653eedf185cc7f352bc7c2e45d388138dab8cc5
> Deleted: 3878480379a32185c8b963d6dfda1dad01cd2c14249f14bac24233914024a6b0
> Deleted: 75ff92d040f53af7695fd1b77e14d332180c5e262085dda77c3842e777af5fba
> Deleted: e5abc259bf6ad865d2e9d38975016b6eb8c7bac879427542802e4089b5193b68
> Deleted: 1a857c368e1373d119d3588b08cc052fd8f46926ee2bcb4c256922c6523b3266
> Build step 'Execute shell' marked build as failure
> {code}



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Mime
View raw message