See <https://builds.apache.org/job/Mesos-Buildbot/BUILDTOOL=cmake,COMPILER=gcc,CONFIGURATION=--verbose%20--disable-libtool-wrappers,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1,OS=ubuntu%3A14.04,label_exp=(ubuntu)&&(!ubuntu-us1)&&(!ubuntu-eu2)&&(!qnode3)&&(!H23)/4492/display/redirect?page=changes>
Changes: [bmahler] Optimized resources logging in master. ------------------------------------------ [...truncated 6.96 MB...] 3: I1122 22:07:57.614403 17381 master.cpp:9529] Updating the state of task 6d3c921f-bb52-4476-83e3-c4e2a1f38927 of framework 0441247d-3c69-4827-a070-be73019ed2af-0000 (latest state: TASK_KILLED, status update state: TASK_KILLED) 3: I1122 22:07:57.614445 17384 slave.cpp:3270] Asked to shut down framework 0441247d-3c69-4827-a070-be73019ed2af-0000 by [email protected]:36860 3: I1122 22:07:57.614476 17384 slave.cpp:3295] Shutting down framework 0441247d-3c69-4827-a070-be73019ed2af-0000 3: I1122 22:07:57.614532 17384 slave.cpp:5879] Shutting down executor 'default' of framework 0441247d-3c69-4827-a070-be73019ed2af-0000 at executor(40)@172.17.0.2:36860 3: I1122 22:07:57.614693 17385 exec.cpp:435] Executor asked to shutdown 3: I1122 22:07:57.614837 17385 exec.cpp:450] Executor::shutdown took 110235ns 3: I1122 22:07:57.615501 17381 master.cpp:9629] Removing task 6d3c921f-bb52-4476-83e3-c4e2a1f38927 with resources cpus(allocated: *):2; mem(allocated: *):1024; disk(allocated: *):1024; ports(allocated: *):[31000-32000] of framework 0441247d-3c69-4827-a070-be73019ed2af-0000 on agent 0441247d-3c69-4827-a070-be73019ed2af-S0 at slave(145)@172.17.0.2:36860 (b0c9a22117a9) 3: I1122 22:07:57.615931 17381 master.cpp:9658] Removing executor 'default' with resources [] of framework 0441247d-3c69-4827-a070-be73019ed2af-0000 on agent 0441247d-3c69-4827-a070-be73019ed2af-S0 at slave(145)@172.17.0.2:36860 (b0c9a22117a9) 3: I1122 22:07:57.616150 17372 hierarchical.cpp:1132] Recovered cpus(allocated: *):2; mem(allocated: *):1024; disk(allocated: *):1024; ports(allocated: *):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000], allocated: {}) on agent 0441247d-3c69-4827-a070-be73019ed2af-S0 from framework 0441247d-3c69-4827-a070-be73019ed2af-0000 3: I1122 22:07:57.616600 17376 slave.cpp:5135] Got exited event for executor(40)@172.17.0.2:36860 3: I1122 22:07:57.617000 17385 hierarchical.cpp:358] Removed framework 0441247d-3c69-4827-a070-be73019ed2af-0000 3: I1122 22:07:57.617102 17384 slave.cpp:5544] Executor 'default' of framework 0441247d-3c69-4827-a070-be73019ed2af-0000 exited with status 0 3: I1122 22:07:57.617213 17384 slave.cpp:5648] Cleaning up executor 'default' of framework 0441247d-3c69-4827-a070-be73019ed2af-0000 at executor(40)@172.17.0.2:36860 3: W1122 22:07:57.617416 17365 master.cpp:7480] Ignoring unknown exited executor 'default' of framework 0441247d-3c69-4827-a070-be73019ed2af-0000 on agent 0441247d-3c69-4827-a070-be73019ed2af-S0 at slave(145)@172.17.0.2:36860 (b0c9a22117a9) 3: I1122 22:07:57.617573 17382 gc.cpp:90] Scheduling '/tmp/SchedulerDriverEventTest_Offers_58BjM9/slaves/0441247d-3c69-4827-a070-be73019ed2af-S0/frameworks/0441247d-3c69-4827-a070-be73019ed2af-0000/executors/default/runs/6f26e573-024d-4c69-bd1f-0cbb7dc8b162' for gc 6.9999928537037days in the future 3: I1122 22:07:57.617718 17384 slave.cpp:5755] Cleaning up framework 0441247d-3c69-4827-a070-be73019ed2af-0000 3: I1122 22:07:57.617775 17382 gc.cpp:90] Scheduling '/tmp/SchedulerDriverEventTest_Offers_58BjM9/slaves/0441247d-3c69-4827-a070-be73019ed2af-S0/frameworks/0441247d-3c69-4827-a070-be73019ed2af-0000/executors/default' for gc 6.99999285131852days in the future 3: I1122 22:07:57.617831 17371 task_status_update_manager.cpp:289] Closing task status update streams for framework 0441247d-3c69-4827-a070-be73019ed2af-0000 3: I1122 22:07:57.617892 17371 task_status_update_manager.cpp:538] Cleaning up status update stream for task 6d3c921f-bb52-4476-83e3-c4e2a1f38927 of framework 0441247d-3c69-4827-a070-be73019ed2af-0000 3: I1122 22:07:57.617910 17384 slave.cpp:883] Agent terminating 3: I1122 22:07:57.617949 17382 gc.cpp:90] Scheduling '/tmp/SchedulerDriverEventTest_Offers_58BjM9/slaves/0441247d-3c69-4827-a070-be73019ed2af-S0/frameworks/0441247d-3c69-4827-a070-be73019ed2af-0000' for gc 6.99999284934222days in the future 3: I1122 22:07:57.618131 17386 master.cpp:1311] Agent 0441247d-3c69-4827-a070-be73019ed2af-S0 at slave(145)@172.17.0.2:36860 (b0c9a22117a9) disconnected 3: I1122 22:07:57.618162 17386 master.cpp:3370] Disconnecting agent 0441247d-3c69-4827-a070-be73019ed2af-S0 at slave(145)@172.17.0.2:36860 (b0c9a22117a9) 3: I1122 22:07:57.618242 17386 master.cpp:3389] Deactivating agent 0441247d-3c69-4827-a070-be73019ed2af-S0 at slave(145)@172.17.0.2:36860 (b0c9a22117a9) 3: I1122 22:07:57.618386 17383 hierarchical.cpp:697] Agent 0441247d-3c69-4827-a070-be73019ed2af-S0 deactivated 3: I1122 22:07:57.623343 17366 master.cpp:1153] Master terminating 3: I1122 22:07:57.624554 17365 hierarchical.cpp:633] Removed agent 0441247d-3c69-4827-a070-be73019ed2af-S0 3: [ OK ] SchedulerDriverEventTest.Offers (102 ms) 3: [ RUN ] SchedulerDriverEventTest.Rescind 3: I1122 22:07:57.634341 17364 cluster.cpp:162] Creating default 'local' authorizer 3: I1122 22:07:57.638761 17368 master.cpp:448] Master dfd0f6f0-6d49-49e0-9473-433ab9266619 (b0c9a22117a9) started on 172.17.0.2:36860 3: I1122 22:07:57.638789 17368 master.cpp:450] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate_agents="true" --authenticate_frameworks="true" --authenticate_http_frameworks="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/0VxlIl/credentials" --filter_gpu_resources="true" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_framework_authenticators="basic" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --max_unreachable_tasks_per_framework="1000" --port="5050" --quiet="false" --recovery_agent_removal_limit="100%" --registry="in_memory" --registry_fetch_timeout="1mins" --registry_gc_interval="15mins" --registry_max_agent_age="2weeks" --registry_max_agent_count="102400" --registry_store_timeout="100secs" --registry_strict="false" --root_submissions="true" --user_sorter="drf" --version="false" --webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/0VxlIl/master" --zk_session_timeout="10secs" 3: I1122 22:07:57.639297 17368 master.cpp:499] Master only allowing authenticated frameworks to register 3: I1122 22:07:57.639314 17368 master.cpp:505] Master only allowing authenticated agents to register 3: I1122 22:07:57.639322 17368 master.cpp:511] Master only allowing authenticated HTTP frameworks to register 3: I1122 22:07:57.639335 17368 credentials.hpp:37] Loading credentials for authentication from '/tmp/0VxlIl/credentials' 3: I1122 22:07:57.639771 17368 master.cpp:555] Using default 'crammd5' authenticator 3: I1122 22:07:57.639987 17368 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly' 3: I1122 22:07:57.640259 17368 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' 3: I1122 22:07:57.640441 17368 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' 3: I1122 22:07:57.640606 17368 master.cpp:634] Authorization enabled 3: I1122 22:07:57.640867 17372 whitelist_watcher.cpp:77] No whitelist given 3: I1122 22:07:57.640916 17369 hierarchical.cpp:173] Initialized hierarchical allocator process 3: I1122 22:07:57.646173 17375 master.cpp:2215] Elected as the leading master! 3: I1122 22:07:57.646239 17375 master.cpp:1695] Recovering from registrar 3: I1122 22:07:57.646462 17385 registrar.cpp:347] Recovering registrar 3: I1122 22:07:57.647644 17385 registrar.cpp:391] Successfully fetched the registry (0B) in 1.123072ms 3: I1122 22:07:57.647863 17385 registrar.cpp:495] Applied 1 operations in 64048ns; attempting to update the registry 3: I1122 22:07:57.648672 17385 registrar.cpp:552] Successfully updated the registry in 732928ns 3: I1122 22:07:57.648811 17385 registrar.cpp:424] Successfully recovered registrar 3: I1122 22:07:57.649312 17383 master.cpp:1808] Recovered 0 agents from the registry (129B); allowing 10mins for agents to re-register 3: I1122 22:07:57.649329 17385 hierarchical.cpp:211] Skipping recovery of hierarchical allocator: nothing to recover 3: W1122 22:07:57.650638 17364 process.cpp:2756] Attempted to spawn already running process [email protected]:36860 3: I1122 22:07:57.651943 17364 sched.cpp:232] Version: 1.5.0 3: I1122 22:07:57.653167 17380 sched.cpp:336] New master detected at [email protected]:36860 3: I1122 22:07:57.653369 17380 sched.cpp:396] Authenticating with master [email protected]:36860 3: I1122 22:07:57.653396 17380 sched.cpp:403] Using default CRAM-MD5 authenticatee 3: I1122 22:07:57.653903 17388 authenticatee.cpp:121] Creating new client SASL connection 3: I1122 22:07:57.654417 17375 master.cpp:8312] Authenticating [email protected]:36860 3: I1122 22:07:57.654568 17384 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(339)@172.17.0.2:36860 3: I1122 22:07:57.654942 17365 authenticator.cpp:98] Creating new server SASL connection 3: I1122 22:07:57.655236 17373 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 3: I1122 22:07:57.655267 17373 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' 3: I1122 22:07:57.655418 17381 authenticator.cpp:204] Received SASL authentication start 3: I1122 22:07:57.655485 17381 authenticator.cpp:326] Authentication requires more steps 3: I1122 22:07:57.655622 17376 authenticatee.cpp:259] Received SASL authentication step 3: I1122 22:07:57.655786 17371 authenticator.cpp:232] Received SASL authentication step 3: I1122 22:07:57.655830 17371 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'b0c9a22117a9' server FQDN: 'b0c9a22117a9' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 3: I1122 22:07:57.655851 17371 auxprop.cpp:181] Looking up auxiliary property '*userPassword' 3: I1122 22:07:57.655915 17371 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' 3: I1122 22:07:57.655947 17371 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'b0c9a22117a9' server FQDN: 'b0c9a22117a9' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 3: I1122 22:07:57.655961 17371 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true 3: I1122 22:07:57.655966 17371 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true 3: I1122 22:07:57.655983 17371 authenticator.cpp:318] Authentication success 3: I1122 22:07:57.656105 17386 authenticatee.cpp:299] Authentication success 3: I1122 22:07:57.656173 17387 master.cpp:8342] Successfully authenticated principal 'test-principal' at [email protected]:36860 3: I1122 22:07:57.656276 17374 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(339)@172.17.0.2:36860 3: I1122 22:07:57.656697 17367 sched.cpp:502] Successfully authenticated with master [email protected]:36860 3: I1122 22:07:57.656730 17367 sched.cpp:824] Sending SUBSCRIBE call to [email protected]:36860 3: I1122 22:07:57.656951 17367 sched.cpp:857] Will retry registration in 1.865460768secs if necessary 3: I1122 22:07:57.657258 17379 master.cpp:2963] Received SUBSCRIBE call for framework 'default' at [email protected]:36860 3: I1122 22:07:57.657374 17379 master.cpp:2280] Authorizing framework principal 'test-principal' to receive offers for roles '{ * }' 3: I1122 22:07:57.658114 17372 master.cpp:3043] Subscribing framework default with checkpointing disabled and capabilities [ RESERVATION_REFINEMENT ] 3: I1122 22:07:57.659652 17369 sched.cpp:751] Framework registered with dfd0f6f0-6d49-49e0-9473-433ab9266619-0000 3: I1122 22:07:57.659731 17369 sched.cpp:765] Scheduler::registered took 39478ns 3: I1122 22:07:57.659843 17370 hierarchical.cpp:306] Added framework dfd0f6f0-6d49-49e0-9473-433ab9266619-0000 3: I1122 22:07:57.660298 17370 hierarchical.cpp:1457] Performed allocation for 0 agents in 220635ns 3: I1122 22:07:57.660372 17365 sched.cpp:947] Rescinded offer O 3: I1122 22:07:57.660496 17365 sched.cpp:958] Scheduler::offerRescinded took 88988ns 3: I1122 22:07:57.660869 17364 sched.cpp:2009] Asked to stop the driver 3: I1122 22:07:57.661005 17383 sched.cpp:1191] Stopping framework dfd0f6f0-6d49-49e0-9473-433ab9266619-0000 3: I1122 22:07:57.661386 17385 master.cpp:8819] Processing TEARDOWN call for framework dfd0f6f0-6d49-49e0-9473-433ab9266619-0000 (default) at [email protected]:36860 3: I1122 22:07:57.661439 17385 master.cpp:8831] Removing framework dfd0f6f0-6d49-49e0-9473-433ab9266619-0000 (default) at [email protected]:36860 3: I1122 22:07:57.661469 17385 master.cpp:3333] Deactivating framework dfd0f6f0-6d49-49e0-9473-433ab9266619-0000 (default) at [email protected]:36860 3: I1122 22:07:57.661672 17379 hierarchical.cpp:419] Deactivated framework dfd0f6f0-6d49-49e0-9473-433ab9266619-0000 3: I1122 22:07:57.662205 17368 hierarchical.cpp:358] Removed framework dfd0f6f0-6d49-49e0-9473-433ab9266619-0000 3: I1122 22:07:57.662267 17366 master.cpp:1153] Master terminating 3: [ OK ] SchedulerDriverEventTest.Rescind (35 ms) 3: [ RUN ] SchedulerDriverEventTest.Update 3: I1122 22:07:57.669405 17364 cluster.cpp:162] Creating default 'local' authorizer 3: I1122 22:07:57.672785 17366 master.cpp:448] Master fa4328d8-76da-4ef6-a71c-0368545d3305 (b0c9a22117a9) started on 172.17.0.2:36860 3: I1122 22:07:57.672823 17366 master.cpp:450] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate_agents="true" --authenticate_frameworks="true" --authenticate_http_frameworks="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/taaaTo/credentials" --filter_gpu_resources="true" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_framework_authenticators="basic" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --max_unreachable_tasks_per_framework="1000" --port="5050" --quiet="false" --recovery_agent_removal_limit="100%" --registry="in_memory" --registry_fetch_timeout="1mins" --registry_gc_interval="15mins" --registry_max_agent_age="2weeks" --registry_max_agent_count="102400" --registry_store_timeout="100secs" --registry_strict="false" --root_submissions="true" --user_sorter="drf" --version="false" --webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/taaaTo/master" --zk_session_timeout="10secs" 3: I1122 22:07:57.673286 17366 master.cpp:499] Master only allowing authenticated frameworks to register 3: I1122 22:07:57.673295 17366 master.cpp:505] Master only allowing authenticated agents to register 3: I1122 22:07:57.673300 17366 master.cpp:511] Master only allowing authenticated HTTP frameworks to register 3: I1122 22:07:57.673306 17366 credentials.hpp:37] Loading credentials for authentication from '/tmp/taaaTo/credentials' 3: I1122 22:07:57.673734 17366 master.cpp:555] Using default 'crammd5' authenticator 3: I1122 22:07:57.673981 17366 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly' 3: I1122 22:07:57.674206 17366 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' 3: I1122 22:07:57.674360 17366 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' 3: I1122 22:07:57.674513 17366 master.cpp:634] Authorization enabled 3: I1122 22:07:57.674779 17372 hierarchical.cpp:173] Initialized hierarchical allocator process 3: I1122 22:07:57.674841 17368 whitelist_watcher.cpp:77] No whitelist given 3: I1122 22:07:57.678758 17384 master.cpp:2215] Elected as the leading master! 3: I1122 22:07:57.678822 17384 master.cpp:1695] Recovering from registrar 3: I1122 22:07:57.679077 17377 registrar.cpp:347] Recovering registrar 3: I1122 22:07:57.680119 17377 registrar.cpp:391] Successfully fetched the registry (0B) in 983808ns 3: I1122 22:07:57.680354 17377 registrar.cpp:495] Applied 1 operations in 53612ns; attempting to update the registry 3: I1122 22:07:57.681252 17377 registrar.cpp:552] Successfully updated the registry in 803840ns 3: I1122 22:07:57.681433 17377 registrar.cpp:424] Successfully recovered registrar 3: I1122 22:07:57.681970 17377 hierarchical.cpp:211] Skipping recovery of hierarchical allocator: nothing to recover 3: I1122 22:07:57.681965 17382 master.cpp:1808] Recovered 0 agents from the registry (129B); allowing 10mins for agents to re-register 3: W1122 22:07:57.682996 17364 process.cpp:2756] Attempted to spawn already running process [email protected]:36860 3: I1122 22:07:57.684016 17364 sched.cpp:232] Version: 1.5.0 3: I1122 22:07:57.684849 17384 sched.cpp:336] New master detected at [email protected]:36860 3: I1122 22:07:57.684975 17384 sched.cpp:396] Authenticating with master [email protected]:36860 3: I1122 22:07:57.684996 17384 sched.cpp:403] Using default CRAM-MD5 authenticatee 3: I1122 22:07:57.685415 17370 authenticatee.cpp:121] Creating new client SASL connection 3: I1122 22:07:57.686028 17373 master.cpp:8312] Authenticating [email protected]:36860 3: I1122 22:07:57.686254 17378 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(340)@172.17.0.2:36860 3: I1122 22:07:57.687050 17378 authenticator.cpp:98] Creating new server SASL connection 3: I1122 22:07:57.687484 17386 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 3: I1122 22:07:57.687530 17386 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' 3: I1122 22:07:57.687707 17376 authenticator.cpp:204] Received SASL authentication start 3: I1122 22:07:57.687799 17376 authenticator.cpp:326] Authentication requires more steps 3: I1122 22:07:57.687952 17376 authenticatee.cpp:259] Received SASL authentication step 3: I1122 22:07:57.688110 17376 authenticator.cpp:232] Received SASL authentication step 3: I1122 22:07:57.688151 17376 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'b0c9a22117a9' server FQDN: 'b0c9a22117a9' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 3: I1122 22:07:57.688194 17376 auxprop.cpp:181] Looking up auxiliary property '*userPassword' 3: I1122 22:07:57.688272 17376 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' 3: I1122 22:07:57.688310 17376 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'b0c9a22117a9' server FQDN: 'b0c9a22117a9' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 3: I1122 22:07:57.688329 17376 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true 3: I1122 22:07:57.688340 17376 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true 3: I1122 22:07:57.688361 17376 authenticator.cpp:318] Authentication success 3: I1122 22:07:57.688592 17374 authenticatee.cpp:299] Authentication success 3: I1122 22:07:57.688643 17379 master.cpp:8342] Successfully authenticated principal 'test-principal' at [email protected]:36860 3: I1122 22:07:57.688702 17376 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(340)@172.17.0.2:36860 3: I1122 22:07:57.689007 17380 sched.cpp:502] Successfully authenticated with master [email protected]:36860 3: I1122 22:07:57.689031 17380 sched.cpp:824] Sending SUBSCRIBE call to [email protected]:36860 3: I1122 22:07:57.689187 17380 sched.cpp:857] Will retry registration in 1.673004843secs if necessary 3: I1122 22:07:57.689422 17385 master.cpp:2963] Received SUBSCRIBE call for framework 'default' at [email protected]:36860 3: I1122 22:07:57.689523 17385 master.cpp:2280] Authorizing framework principal 'test-principal' to receive offers for roles '{ * }' 3: I1122 22:07:57.690310 17371 master.cpp:3043] Subscribing framework default with checkpointing disabled and capabilities [ RESERVATION_REFINEMENT ] 3: I1122 22:07:57.691373 17388 sched.cpp:751] Framework registered with fa4328d8-76da-4ef6-a71c-0368545d3305-0000 3: I1122 22:07:57.691437 17375 hierarchical.cpp:306] Added framework fa4328d8-76da-4ef6-a71c-0368545d3305-0000 3: I1122 22:07:57.691467 17388 sched.cpp:765] Scheduler::registered took 60577ns 3: I1122 22:07:57.691725 17375 hierarchical.cpp:1457] Performed allocation for 0 agents in 107560ns 3: I1122 22:07:57.692324 17386 sched.cpp:1029] Scheduler::statusUpdate took 77930ns 3: I1122 22:07:57.693209 17368 sched.cpp:1029] Scheduler::statusUpdate took 104586ns 3: I1122 22:07:57.693841 17364 sched.cpp:2009] Asked to stop the driver 3: I1122 22:07:57.693985 17371 sched.cpp:1191] Stopping framework fa4328d8-76da-4ef6-a71c-0368545d3305-0000 3: I1122 22:07:57.694249 17370 master.cpp:8819] Processing TEARDOWN call for framework fa4328d8-76da-4ef6-a71c-0368545d3305-0000 (default) at [email protected]:36860 3: I1122 22:07:57.694281 17370 master.cpp:8831] Removing framework fa4328d8-76da-4ef6-a71c-0368545d3305-0000 (default) at [email protected]:36860 3: I1122 22:07:57.694294 17370 master.cpp:3333] Deactivating framework fa4328d8-76da-4ef6-a71c-0368545d3305-0000 (default) at [email protected]:36860 3: I1122 22:07:57.694494 17388 hierarchical.cpp:419] Deactivated framework fa4328d8-76da-4ef6-a71c-0368545d3305-0000 3: I1122 22:07:57.694973 17365 hierarchical.cpp:358] Removed framework fa4328d8-76da-4ef6-a71c-0368545d3305-0000 3: I1122 22:07:57.695385 17383 master.cpp:1153] Master terminating 3: [ OK ] SchedulerDriverEventTest.Update (32 ms) 3: [ RUN ] SchedulerDriverEventTest.Message 3: I1122 22:07:57.702764 17364 cluster.cpp:162] Creating default 'local' authorizer 3: I1122 22:07:57.708801 17374 master.cpp:448] Master 048b3cfe-a90c-4b2e-9628-584bb2e8547c (b0c9a22117a9) started on 172.17.0.2:36860 3: I1122 22:07:57.708848 17374 master.cpp:450] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate_agents="true" --authenticate_frameworks="true" --authenticate_http_frameworks="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/4XZy8r/credentials" --filter_gpu_resources="true" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_framework_authenticators="basic" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --max_unreachable_tasks_per_framework="1000" --port="5050" --quiet="false" --recovery_agent_removal_limit="100%" --registry="in_memory" --registry_fetch_timeout="1mins" --registry_gc_interval="15mins" --registry_max_agent_age="2weeks" --registry_max_agent_count="102400" --registry_store_timeout="100secs" --registry_strict="false" --root_submissions="true" --user_sorter="drf" --version="false" --webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/4XZy8r/master" --zk_session_timeout="10secs" 3: I1122 22:07:57.709399 17374 master.cpp:499] Master only allowing authenticated frameworks to register 3: I1122 22:07:57.709414 17374 master.cpp:505] Master only allowing authenticated agents to register 3: I1122 22:07:57.709421 17374 master.cpp:511] Master only allowing authenticated HTTP frameworks to register 3: I1122 22:07:57.709429 17374 credentials.hpp:37] Loading credentials for authentication from '/tmp/4XZy8r/credentials' 3: I1122 22:07:57.709919 17374 master.cpp:555] Using default 'crammd5' authenticator 3: I1122 22:07:57.710186 17374 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly' 3: I1122 22:07:57.710409 17374 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' 3: I1122 22:07:57.710577 17374 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' 3: I1122 22:07:57.710722 17374 master.cpp:634] Authorization enabled 3: I1122 22:07:57.710945 17366 whitelist_watcher.cpp:77] No whitelist given 3: I1122 22:07:57.710999 17385 hierarchical.cpp:173] Initialized hierarchical allocator process 3: I1122 22:07:57.715080 17388 master.cpp:2215] Elected as the leading master! 3: I1122 22:07:57.715114 17388 master.cpp:1695] Recovering from registrar 3: I1122 22:07:57.715250 17373 registrar.cpp:347] Recovering registrar 3: I1122 22:07:57.715950 17373 registrar.cpp:391] Successfully fetched the registry (0B) in 659200ns 3: I1122 22:07:57.716096 17373 registrar.cpp:495] Applied 1 operations in 43685ns; attempting to update the registry 3: I1122 22:07:57.716778 17373 registrar.cpp:552] Successfully updated the registry in 617984ns 3: I1122 22:07:57.716905 17373 registrar.cpp:424] Successfully recovered registrar 3: I1122 22:07:57.717303 17380 master.cpp:1808] Recovered 0 agents from the registry (129B); allowing 10mins for agents to re-register 3: I1122 22:07:57.717335 17366 hierarchical.cpp:211] Skipping recovery of hierarchical allocator: nothing to recover 3: W1122 22:07:57.718689 17364 process.cpp:2756] Attempted to spawn already running process [email protected]:36860 3: I1122 22:07:57.720144 17364 sched.cpp:232] Version: 1.5.0 3: I1122 22:07:57.720904 17386 sched.cpp:336] New master detected at [email protected]:36860 3: I1122 22:07:57.721041 17386 sched.cpp:396] Authenticating with master [email protected]:36860 3: I1122 22:07:57.721065 17386 sched.cpp:403] Using default CRAM-MD5 authenticatee 3: I1122 22:07:57.721410 17387 authenticatee.cpp:121] Creating new client SASL connection 3: I1122 22:07:57.721801 17388 master.cpp:8312] Authenticating [email protected]:36860 3: I1122 22:07:57.721932 17368 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(341)@172.17.0.2:36860 3: I1122 22:07:57.722276 17365 authenticator.cpp:98] Creating new server SASL connection 3: I1122 22:07:57.722635 17382 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 3: I1122 22:07:57.722669 17382 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' 3: I1122 22:07:57.722990 17365 authenticator.cpp:204] Received SASL authentication start 3: I1122 22:07:57.723069 17365 authenticator.cpp:326] Authentication requires more steps 3: I1122 22:07:57.723206 17375 authenticatee.cpp:259] Received SASL authentication step 3: I1122 22:07:57.723361 17377 authenticator.cpp:232] Received SASL authentication step 3: I1122 22:07:57.723400 17377 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'b0c9a22117a9' server FQDN: 'b0c9a22117a9' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 3: I1122 22:07:57.723414 17377 auxprop.cpp:181] Looking up auxiliary property '*userPassword' 3: I1122 22:07:57.723467 17377 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' 3: I1122 22:07:57.723492 17377 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'b0c9a22117a9' server FQDN: 'b0c9a22117a9' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 3: I1122 22:07:57.723502 17377 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true 3: I1122 22:07:57.723510 17377 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true 3: I1122 22:07:57.723528 17377 authenticator.cpp:318] Authentication success 3: I1122 22:07:57.723610 17379 authenticatee.cpp:299] Authentication success 3: I1122 22:07:57.723716 17373 master.cpp:8342] Successfully authenticated principal 'test-principal' at [email protected]:36860 3: I1122 22:07:57.723788 17376 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(341)@172.17.0.2:36860 3: I1122 22:07:57.724004 17383 sched.cpp:502] Successfully authenticated with master [email protected]:36860 3: I1122 22:07:57.724032 17383 sched.cpp:824] Sending SUBSCRIBE call to [email protected]:36860 3: I1122 22:07:57.724236 17383 sched.cpp:857] Will retry registration in 761.162657ms if necessary 3: I1122 22:07:57.724665 17385 master.cpp:2963] Received SUBSCRIBE call for framework 'default' at [email protected]:36860 3: I1122 22:07:57.724851 17385 master.cpp:2280] Authorizing framework principal 'test-principal' to receive offers for roles '{ * }' 3: I1122 22:07:57.725571 17381 master.cpp:3043] Subscribing framework default with checkpointing disabled and capabilities [ RESERVATION_REFINEMENT ] 3: I1122 22:07:57.726452 17384 sched.cpp:751] Framework registered with 048b3cfe-a90c-4b2e-9628-584bb2e8547c-0000 3: I1122 22:07:57.726502 17384 sched.cpp:765] Scheduler::registered took 27992ns 3: I1122 22:07:57.727005 17378 hierarchical.cpp:306] Added framework 048b3cfe-a90c-4b2e-9628-584bb2e8547c-0000 3: I1122 22:07:57.727133 17368 sched.cpp:1165] Scheduler::frameworkMessage took 58483ns 3: I1122 22:07:57.727649 17378 hierarchical.cpp:1457] Performed allocation for 0 agents in 344477ns 3: I1122 22:07:57.727681 17364 sched.cpp:2009] Asked to stop the driver 3: I1122 22:07:57.727828 17380 sched.cpp:1191] Stopping framework 048b3cfe-a90c-4b2e-9628-584bb2e8547c-0000 3: I1122 22:07:57.728113 17366 master.cpp:8819] Processing TEARDOWN call for framework 048b3cfe-a90c-4b2e-9628-584bb2e8547c-0000 (default) at [email protected]:36860 3: I1122 22:07:57.728152 17366 master.cpp:8831] Removing framework 048b3cfe-a90c-4b2e-9628-584bb2e8547c-0000 (default) at [email protected]:36860 3: I1122 22:07:57.728174 17366 master.cpp:3333] Deactivating framework 048b3cfe-a90c-4b2e-9628-584bb2e8547c-0000 (default) at [email protected]:36860 3: I1122 22:07:57.728379 17376 hierarchical.cpp:419] Deactivated framework 048b3cfe-a90c-4b2e-9628-584bb2e8547c-0000 3: I1122 22:07:57.728957 17385 hierarchical.cpp:358] Removed framework 048b3cfe-a90c-4b2e-9628-584bb2e8547c-0000 3: I1122 22:07:57.729168 17370 master.cpp:1153] Master terminating 3: [ OK ] SchedulerDriverEventTest.Message (35 ms) 3: [ RUN ] SchedulerDriverEventTest.Failure 3: I1122 22:07:57.739755 17364 cluster.cpp:162] Creating default 'local' authorizer 3: I1122 22:07:57.746943 17386 master.cpp:448] Master 3379bcbe-afec-4d26-9b84-94428a6edb33 (b0c9a22117a9) started on 172.17.0.2:36860 3: I1122 22:07:57.746980 17386 master.cpp:450] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate_agents="true" --authenticate_frameworks="true" --authenticate_http_frameworks="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/7te4sv/credentials" --filter_gpu_resources="true" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_framework_authenticators="basic" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --max_unreachable_tasks_per_framework="1000" --port="5050" --quiet="false" --recovery_agent_removal_limit="100%" --registry="in_memory" --registry_fetch_timeout="1mins" --registry_gc_interval="15mins" --registry_max_agent_age="2weeks" --registry_max_agent_count="102400" --registry_store_timeout="100secs" --registry_strict="false" --root_submissions="true" --user_sorter="drf" --version="false" --webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/7te4sv/master" --zk_session_timeout="10secs" 3: I1122 22:07:57.747414 17386 master.cpp:499] Master only allowing authenticated frameworks to register 3: I1122 22:07:57.747422 17386 master.cpp:505] Master only allowing authenticated agents to register 3: I1122 22:07:57.747427 17386 master.cpp:511] Master only allowing authenticated HTTP frameworks to register 3: I1122 22:07:57.747432 17386 credentials.hpp:37] Loading credentials for authentication from '/tmp/7te4sv/credentials' 3: I1122 22:07:57.747849 17386 master.cpp:555] Using default 'crammd5' authenticator 3: I1122 22:07:57.748095 17386 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly' write /dev/stdout: resource temporarily unavailable Build step 'Execute shell' marked build as failure
