Uploaded image for project: 'Mesos'
  1. Mesos
  2. MESOS-9401

AgentAPITest.GetFrameworks is flaky

    XMLWordPrintableJSON

    Details

    • Type: Bug
    • Status: Open
    • Priority: Major
    • Resolution: Unresolved
    • Affects Version/s: 1.8.0
    • Fix Version/s: None
    • Component/s: test
    • Labels:

      Description

      The following I saw in a macOS run:

      14:39:11  [ RUN      ] ContentType/AgentAPITest.GetFrameworks/1
      14:39:11  I1119 06:39:15.264891 2668864320 cluster.cpp:173] Creating default 'local' authorizer
      14:39:11  I1119 06:39:15.266228 170434560 master.cpp:413] Master be3714c6-f7ac-4dce-8791-7bddc37889d4 (Jenkinss-Mac-mini.local) started on 10.0.49.4:61227
      14:39:11  I1119 06:39:15.266257 170434560 master.cpp:416] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="1000secs" --allocator="hierarchical" --authenticate_agents="true" --authenticate_frameworks="true" --authenticate_http_frameworks="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authentication_v0_timeout="15secs" --authenticators="crammd5" --authorizers="local" --credentials="/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/dFgHko/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" --memory_profiling="false" --min_allocatable_resources="cpus:0.01|mem:32" --port="5050" --publish_per_framework_metrics="true" --quiet="false" --recovery_agent_removal_limit="100%" --registry="in_memory" --registry_fetch_timeout="1mins" --registry_gc_interval="15mins" --registry_max_agent_age="2weeks" --registry_max_agent_count="102400" --registry_store_timeout="100secs" --registry_strict="false" --require_agent_domain="false" --role_sorter="drf" --root_submissions="true" --version="false" --webui_dir="/usr/local/share/mesos/webui" --work_dir="/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/dFgHko/master" --zk_session_timeout="10secs"
      14:39:11  I1119 06:39:15.266446 170434560 master.cpp:465] Master only allowing authenticated frameworks to register
      14:39:11  I1119 06:39:15.266455 170434560 master.cpp:471] Master only allowing authenticated agents to register
      14:39:11  I1119 06:39:15.266460 170434560 master.cpp:477] Master only allowing authenticated HTTP frameworks to register
      14:39:11  I1119 06:39:15.266484 170434560 credentials.hpp:37] Loading credentials for authentication from '/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/dFgHko/credentials'
      14:39:11  I1119 06:39:15.266654 170434560 master.cpp:521] Using default 'crammd5' authenticator
      14:39:11  I1119 06:39:15.266732 170434560 http.cpp:1042] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
      14:39:11  I1119 06:39:15.266801 170434560 http.cpp:1042] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
      14:39:11  I1119 06:39:15.266851 170434560 http.cpp:1042] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
      14:39:11  I1119 06:39:15.266904 170434560 master.cpp:602] Authorization enabled
      14:39:11  I1119 06:39:15.267139 169361408 hierarchical.cpp:175] Initialized hierarchical allocator process
      14:39:11  I1119 06:39:15.267357 170971136 whitelist_watcher.cpp:77] No whitelist given
      14:39:11  I1119 06:39:15.268975 170971136 master.cpp:2105] Elected as the leading master!
      14:39:11  I1119 06:39:15.269001 170971136 master.cpp:1660] Recovering from registrar
      14:39:11  I1119 06:39:15.269045 169897984 registrar.cpp:339] Recovering registrar
      14:39:11  I1119 06:39:15.269253 169361408 registrar.cpp:383] Successfully fetched the registry (0B) in 187136ns
      14:39:11  I1119 06:39:15.269342 169361408 registrar.cpp:487] Applied 1 operations in 22753ns; attempting to update the registry
      14:39:11  I1119 06:39:15.269572 168288256 registrar.cpp:544] Successfully updated the registry in 187136ns
      14:39:11  I1119 06:39:15.269637 168288256 registrar.cpp:416] Successfully recovered registrar
      14:39:11  I1119 06:39:15.269793 170434560 master.cpp:1774] Recovered 0 agents from the registry (155B); allowing 10mins for agents to reregister
      14:39:11  I1119 06:39:15.269825 167215104 hierarchical.cpp:215] Skipping recovery of hierarchical allocator: nothing to recover
      14:39:11  W1119 06:39:15.272145 2668864320 process.cpp:2829] Attempted to spawn already running process files@10.0.49.4:61227
      14:39:11  I1119 06:39:15.272856 2668864320 containerizer.cpp:305] Using isolation { environment_secret, filesystem/posix, posix/mem, posix/cpu }
      14:39:11  I1119 06:39:15.273074 2668864320 provisioner.cpp:298] Using default backend 'copy'
      14:39:11  I1119 06:39:15.273936 2668864320 cluster.cpp:485] Creating default 'local' authorizer
      14:39:11  I1119 06:39:15.275010 169361408 slave.cpp:267] Mesos agent started on (828)@10.0.49.4:61227
      14:39:11  I1119 06:39:15.275039 169361408 slave.cpp:268] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/ContentType_AgentAPITest_GetFrameworks_1_Rt51JW/store/appc" --authenticate_http_executors="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authenticatee="crammd5" --authentication_backoff_factor="1secs" --authentication_timeout_max="1mins" --authentication_timeout_min="5secs" --authorizer="local" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/ContentType_AgentAPITest_GetFrameworks_1_Rt51JW/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="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/ContentType_AgentAPITest_GetFrameworks_1_Rt51JW/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_reregistration_timeout="2secs" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/ContentType_AgentAPITest_GetFrameworks_1_Rt51JW/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/ContentType_AgentAPITest_GetFrameworks_1_Rt51JW/frameworks" --gc_delay="1weeks" --gc_disk_headroom="0.1" --gc_non_executor_container_sandboxes="false" --help="false" --hostname_lookup="true" --http_command_executor="false" --http_credentials="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/ContentType_AgentAPITest_GetFrameworks_1_Rt51JW/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --jwt_secret_key="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/ContentType_AgentAPITest_GetFrameworks_1_Rt51JW/jwt_secret_key" --launcher="posix" --launcher_dir="/Users/jenkins/workspace/workspace/mesos/Mesos_CI-build/FLAG/SSL/label/mac/mesos/build/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --memory_profiling="false" --network_cni_metrics="true" --oversubscribed_resources_interval="15secs" --port="5051" --qos_correction_interval_min="0ns" --quiet="false" --reconfiguration_policy="equal" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]" --runtime_dir="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/ContentType_AgentAPITest_GetFrameworks_1_Rt51JW" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --version="false" --work_dir="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/ContentType_AgentAPITest_GetFrameworks_1_6fUr73" --zk_session_timeout="10secs"
      14:39:11  I1119 06:39:15.275311 169361408 credentials.hpp:86] Loading credential for authentication from '/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/ContentType_AgentAPITest_GetFrameworks_1_Rt51JW/credential'
      14:39:11  W1119 06:39:15.275388 2668864320 process.cpp:2829] Attempted to spawn already running process version@10.0.49.4:61227
      14:39:11  I1119 06:39:15.275434 169361408 slave.cpp:300] Agent using credential for: test-principal
      14:39:11  I1119 06:39:15.275447 169361408 credentials.hpp:37] Loading credentials for authentication from '/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/ContentType_AgentAPITest_GetFrameworks_1_Rt51JW/http_credentials'
      14:39:11  I1119 06:39:15.275643 169361408 http.cpp:1042] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-executor'
      14:39:11  I1119 06:39:15.275707 169361408 http.cpp:1063] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-executor'
      14:39:11  I1119 06:39:15.275797 169361408 http.cpp:1042] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
      14:39:11  I1119 06:39:15.275840 169361408 http.cpp:1063] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readonly'
      14:39:11  I1119 06:39:15.275915 169361408 http.cpp:1042] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite'
      14:39:11  I1119 06:39:15.275976 169361408 http.cpp:1063] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readwrite'
      14:39:11  I1119 06:39:15.276202 169361408 disk_profile_adaptor.cpp:80] Creating default disk profile adaptor module
      14:39:11  I1119 06:39:15.276495 169361408 slave.cpp:615] Agent resources: [{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
      14:39:11  I1119 06:39:15.276616 169361408 slave.cpp:623] Agent attributes: [  ]
      14:39:11  I1119 06:39:15.276629 169361408 slave.cpp:632] Agent hostname: Jenkinss-Mac-mini.local
      14:39:11  I1119 06:39:15.276681 2668864320 sched.cpp:232] Version: 1.8.0
      14:39:11  I1119 06:39:15.276784 167751680 task_status_update_manager.cpp:181] Pausing sending task status updates
      14:39:11  I1119 06:39:15.276967 168824832 sched.cpp:336] New master detected at master@10.0.49.4:61227
      14:39:11  I1119 06:39:15.277015 168824832 sched.cpp:401] Authenticating with master master@10.0.49.4:61227
      14:39:11  I1119 06:39:15.277029 168824832 sched.cpp:408] Using default CRAM-MD5 authenticatee
      14:39:11  I1119 06:39:15.277178 167751680 authenticatee.cpp:121] Creating new client SASL connection
      14:39:11  I1119 06:39:15.277346 169897984 master.cpp:9699] Authenticating scheduler-f91fa9d2-c57e-4118-b7ba-81f46d378a79@10.0.49.4:61227
      14:39:11  I1119 06:39:15.277380 170434560 state.cpp:66] Recovering state from '/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/ContentType_AgentAPITest_GetFrameworks_1_6fUr73/meta'
      14:39:11  I1119 06:39:15.277441 168824832 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(1512)@10.0.49.4:61227
      14:39:11  I1119 06:39:15.277501 168288256 slave.cpp:6915] Finished recovering checkpointed state from '/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/ContentType_AgentAPITest_GetFrameworks_1_6fUr73/meta', beginning agent recovery
      14:39:11  I1119 06:39:15.277590 167751680 authenticator.cpp:98] Creating new server SASL connection
      14:39:11  I1119 06:39:15.277578 169361408 task_status_update_manager.cpp:207] Recovering task status update manager
      14:39:11  I1119 06:39:15.277705 170971136 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
      14:39:11  I1119 06:39:15.277731 170971136 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
      14:39:11  I1119 06:39:15.277789 170434560 authenticator.cpp:204] Received SASL authentication start
      14:39:11  I1119 06:39:15.277865 170434560 authenticator.cpp:326] Authentication requires more steps
      14:39:11  I1119 06:39:15.277918 168288256 containerizer.cpp:727] Recovering Mesos containers
      14:39:11  I1119 06:39:15.278023 167751680 authenticatee.cpp:259] Received SASL authentication step
      14:39:11  I1119 06:39:15.278050 168288256 containerizer.cpp:1053] Recovering isolators
      14:39:11  I1119 06:39:15.278092 169361408 authenticator.cpp:232] Received SASL authentication step
      14:39:11  I1119 06:39:15.278115 169361408 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'Jenkinss-Mac-mini.local' server FQDN: 'Jenkinss-Mac-mini.local' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
      14:39:11  I1119 06:39:15.278144 169361408 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
      14:39:11  I1119 06:39:15.278185 169361408 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
      14:39:11  I1119 06:39:15.278205 169361408 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'Jenkinss-Mac-mini.local' server FQDN: 'Jenkinss-Mac-mini.local' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
      14:39:11  I1119 06:39:15.278218 169361408 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
      14:39:11  I1119 06:39:15.278228 169361408 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
      14:39:11  I1119 06:39:15.278241 169361408 authenticator.cpp:318] Authentication success
      14:39:11  I1119 06:39:15.278412 169897984 authenticatee.cpp:299] Authentication success
      14:39:11  I1119 06:39:15.278461 168288256 master.cpp:9731] Successfully authenticated principal 'test-principal' at scheduler-f91fa9d2-c57e-4118-b7ba-81f46d378a79@10.0.49.4:61227
      14:39:11  I1119 06:39:15.278484 170971136 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(1512)@10.0.49.4:61227
      14:39:11  I1119 06:39:15.278705 169361408 sched.cpp:513] Successfully authenticated with master master@10.0.49.4:61227
      14:39:11  I1119 06:39:15.278726 169361408 sched.cpp:817] Sending SUBSCRIBE call to master@10.0.49.4:61227
      14:39:11  I1119 06:39:15.278820 169361408 sched.cpp:850] Will retry registration in 180.347158ms if necessary
      14:39:11  I1119 06:39:15.278838 169897984 containerizer.cpp:1092] Recovering provisioner
      14:39:11  I1119 06:39:15.278961 167215104 master.cpp:2876] Received SUBSCRIBE call for framework 'default' at scheduler-f91fa9d2-c57e-4118-b7ba-81f46d378a79@10.0.49.4:61227
      14:39:11  I1119 06:39:15.278980 167215104 master.cpp:2177] Authorizing framework principal 'test-principal' to receive offers for roles '{ * }'
      14:39:11  I1119 06:39:15.279155 168288256 provisioner.cpp:494] Provisioner recovery complete
      14:39:11  I1119 06:39:15.279166 167751680 master.cpp:2957] Subscribing framework default with checkpointing disabled and capabilities [ MULTI_ROLE, RESERVATION_REFINEMENT ]
      14:39:11  I1119 06:39:15.279510 168824832 composing.cpp:339] Finished recovering all containerizers
      14:39:11  I1119 06:39:15.279649 169361408 slave.cpp:7144] Recovering executors
      14:39:11  I1119 06:39:15.279739 169361408 slave.cpp:7297] Finished recovery
      14:39:11  I1119 06:39:15.280234 167751680 master.cpp:9929] Adding framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000 (default) at scheduler-f91fa9d2-c57e-4118-b7ba-81f46d378a79@10.0.49.4:61227 with roles {  } suppressed
      14:39:11  I1119 06:39:15.280364 169361408 slave.cpp:1260] New master detected at master@10.0.49.4:61227
      14:39:11  I1119 06:39:15.280418 169361408 slave.cpp:1325] Detecting new master
      14:39:11  I1119 06:39:15.280503 170434560 task_status_update_manager.cpp:181] Pausing sending task status updates
      14:39:11  I1119 06:39:15.280575 168824832 sched.cpp:744] Framework registered with be3714c6-f7ac-4dce-8791-7bddc37889d4-0000
      14:39:11  I1119 06:39:15.280624 169897984 hierarchical.cpp:304] Added framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000
      14:39:11  I1119 06:39:15.280637 168824832 sched.cpp:758] Scheduler::registered took 41698ns
      14:39:11  I1119 06:39:15.280748 169897984 hierarchical.cpp:1566] Performed allocation for 0 agents in 39282ns
      14:39:11  I1119 06:39:15.291321 170971136 slave.cpp:1352] Authenticating with master master@10.0.49.4:61227
      14:39:11  I1119 06:39:15.291391 170971136 slave.cpp:1361] Using default CRAM-MD5 authenticatee
      14:39:11  I1119 06:39:15.291515 167751680 authenticatee.cpp:121] Creating new client SASL connection
      14:39:11  I1119 06:39:15.291652 170434560 master.cpp:9699] Authenticating slave(828)@10.0.49.4:61227
      14:39:11  I1119 06:39:15.291715 168288256 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(1513)@10.0.49.4:61227
      14:39:11  I1119 06:39:15.291827 168824832 authenticator.cpp:98] Creating new server SASL connection
      14:39:11  I1119 06:39:15.291947 169897984 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
      14:39:11  I1119 06:39:15.291980 169897984 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
      14:39:11  I1119 06:39:15.292027 167215104 authenticator.cpp:204] Received SASL authentication start
      14:39:11  I1119 06:39:15.292095 167215104 authenticator.cpp:326] Authentication requires more steps
      14:39:11  I1119 06:39:15.292170 169361408 authenticatee.cpp:259] Received SASL authentication step
      14:39:11  I1119 06:39:15.292229 170971136 authenticator.cpp:232] Received SASL authentication step
      14:39:11  I1119 06:39:15.292248 170971136 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'Jenkinss-Mac-mini.local' server FQDN: 'Jenkinss-Mac-mini.local' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
      14:39:11  I1119 06:39:15.292261 170971136 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
      14:39:11  I1119 06:39:15.292274 170971136 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
      14:39:11  I1119 06:39:15.292284 170971136 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'Jenkinss-Mac-mini.local' server FQDN: 'Jenkinss-Mac-mini.local' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
      14:39:11  I1119 06:39:15.292294 170971136 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
      14:39:11  I1119 06:39:15.292302 170971136 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
      14:39:11  I1119 06:39:15.292312 170971136 authenticator.cpp:318] Authentication success
      14:39:11  I1119 06:39:15.292369 167751680 authenticatee.cpp:299] Authentication success
      14:39:11  I1119 06:39:15.292409 170434560 master.cpp:9731] Successfully authenticated principal 'test-principal' at slave(828)@10.0.49.4:61227
      14:39:11  I1119 06:39:15.292420 168288256 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(1513)@10.0.49.4:61227
      14:39:11  I1119 06:39:15.292557 168824832 slave.cpp:1452] Successfully authenticated with master master@10.0.49.4:61227
      14:39:11  I1119 06:39:15.292769 168824832 slave.cpp:1883] Will retry registration in 1.614395ms if necessary
      14:39:11  I1119 06:39:15.292850 170971136 master.cpp:6650] Received register agent message from slave(828)@10.0.49.4:61227 (Jenkinss-Mac-mini.local)
      14:39:11  I1119 06:39:15.292981 170971136 master.cpp:3986] Authorizing agent providing resources 'cpus:2; mem:1024; disk:1024; ports:[31000-32000]' with principal 'test-principal'
      14:39:11  I1119 06:39:15.293256 169897984 master.cpp:6717] Authorized registration of agent at slave(828)@10.0.49.4:61227 (Jenkinss-Mac-mini.local)
      14:39:11  I1119 06:39:15.293342 169897984 master.cpp:6832] Registering agent at slave(828)@10.0.49.4:61227 (Jenkinss-Mac-mini.local) with id be3714c6-f7ac-4dce-8791-7bddc37889d4-S0
      14:39:11  I1119 06:39:15.293634 167215104 registrar.cpp:487] Applied 1 operations in 140802ns; attempting to update the registry
      14:39:11  I1119 06:39:15.293885 167215104 registrar.cpp:544] Successfully updated the registry in 221952ns
      14:39:11  I1119 06:39:15.293956 168288256 master.cpp:6880] Admitted agent be3714c6-f7ac-4dce-8791-7bddc37889d4-S0 at slave(828)@10.0.49.4:61227 (Jenkinss-Mac-mini.local)
      14:39:11  I1119 06:39:15.294142 168288256 master.cpp:6925] Registered agent be3714c6-f7ac-4dce-8791-7bddc37889d4-S0 at slave(828)@10.0.49.4:61227 (Jenkinss-Mac-mini.local) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
      14:39:11  I1119 06:39:15.294226 169897984 slave.cpp:1485] Registered with master master@10.0.49.4:61227; given agent ID be3714c6-f7ac-4dce-8791-7bddc37889d4-S0
      14:39:11  I1119 06:39:15.294286 170971136 task_status_update_manager.cpp:188] Resuming sending task status updates
      14:39:11  I1119 06:39:15.294329 169361408 hierarchical.cpp:603] Added agent be3714c6-f7ac-4dce-8791-7bddc37889d4-S0 (Jenkinss-Mac-mini.local) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (allocated: {})
      14:39:11  I1119 06:39:15.294559 169897984 slave.cpp:1505] Checkpointing SlaveInfo to '/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/ContentType_AgentAPITest_GetFrameworks_1_6fUr73/meta/slaves/be3714c6-f7ac-4dce-8791-7bddc37889d4-S0/slave.info'
      14:39:11  I1119 06:39:15.294680 169361408 hierarchical.cpp:1566] Performed allocation for 1 agents in 268880ns
      14:39:11  I1119 06:39:15.294847 170434560 master.cpp:9514] Sending offers [ be3714c6-f7ac-4dce-8791-7bddc37889d4-O0 ] to framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000 (default) at scheduler-f91fa9d2-c57e-4118-b7ba-81f46d378a79@10.0.49.4:61227
      14:39:11  I1119 06:39:15.295161 167215104 sched.cpp:914] Scheduler::resourceOffers took 101264ns
      14:39:11  I1119 06:39:15.295339 169897984 slave.cpp:1554] Forwarding agent update {"operations":{},"resource_version_uuid":{"value":"pIFlAHOPSGSAkO4feS0sAw=="},"slave_id":{"value":"be3714c6-f7ac-4dce-8791-7bddc37889d4-S0"},"update_oversubscribed_resources":false}
      14:39:11  I1119 06:39:15.295725 168288256 master.cpp:7984] Ignoring update on agent be3714c6-f7ac-4dce-8791-7bddc37889d4-S0 at slave(828)@10.0.49.4:61227 (Jenkinss-Mac-mini.local) as it reports no changes
      14:39:11  I1119 06:39:15.296494 169897984 process.cpp:3588] Handling HTTP event for process 'slave(828)' with path: '/slave(828)/api/v1'
      14:39:11  I1119 06:39:15.297157 170434560 http.cpp:1182] HTTP POST for /slave(828)/api/v1 from 10.0.49.4:63781
      14:39:11  I1119 06:39:15.297356 170434560 http.cpp:1454] Processing GET_FRAMEWORKS call
      14:39:11  I1119 06:39:15.298992 168824832 master.cpp:11513] Removing offer be3714c6-f7ac-4dce-8791-7bddc37889d4-O0
      14:39:11  I1119 06:39:15.299257 168824832 master.cpp:4511] Processing ACCEPT call for offers: [ be3714c6-f7ac-4dce-8791-7bddc37889d4-O0 ] on agent be3714c6-f7ac-4dce-8791-7bddc37889d4-S0 at slave(828)@10.0.49.4:61227 (Jenkinss-Mac-mini.local) for framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000 (default) at scheduler-f91fa9d2-c57e-4118-b7ba-81f46d378a79@10.0.49.4:61227
      14:39:11  I1119 06:39:15.299327 168824832 master.cpp:3563] Authorizing framework principal 'test-principal' to launch task 1
      14:39:11  I1119 06:39:15.300367 170434560 master.cpp:4088] Adding task 1 with resources cpus(allocated: *):2; mem(allocated: *):1024; disk(allocated: *):1024; ports(allocated: *):[31000-32000] of framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000 (default) at scheduler-f91fa9d2-c57e-4118-b7ba-81f46d378a79@10.0.49.4:61227 on agent be3714c6-f7ac-4dce-8791-7bddc37889d4-S0 at slave(828)@10.0.49.4:61227 (Jenkinss-Mac-mini.local)
      14:39:11  I1119 06:39:15.300609 170434560 master.cpp:5483] Launching task 1 of framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000 (default) at scheduler-f91fa9d2-c57e-4118-b7ba-81f46d378a79@10.0.49.4:61227 with resources [{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}] on agent be3714c6-f7ac-4dce-8791-7bddc37889d4-S0 at slave(828)@10.0.49.4:61227 (Jenkinss-Mac-mini.local) on  new executor
      14:39:11  I1119 06:39:15.301375 167215104 slave.cpp:2020] Got assigned task '1' for framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000
      14:39:11  I1119 06:39:15.302006 167215104 slave.cpp:2394] Authorizing task '1' for framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000
      14:39:11  I1119 06:39:15.302045 167215104 slave.cpp:8472] Authorizing framework principal 'test-principal' to launch task 1
      14:39:11  I1119 06:39:15.302819 167215104 slave.cpp:2837] Launching task '1' for framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000
      14:39:11  I1119 06:39:15.302872 167215104 paths.cpp:752] Creating sandbox '/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/ContentType_AgentAPITest_GetFrameworks_1_6fUr73/slaves/be3714c6-f7ac-4dce-8791-7bddc37889d4-S0/frameworks/be3714c6-f7ac-4dce-8791-7bddc37889d4-0000/executors/1/runs/28632eb3-e3fb-41cf-8698-1353f9ccfa10' for user 'jenkins'
      14:39:11  I1119 06:39:15.303869 167215104 slave.cpp:9000] Launching executor '1' of framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000 with resources [{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":32.0},"type":"SCALAR"}] in work directory '/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/ContentType_AgentAPITest_GetFrameworks_1_6fUr73/slaves/be3714c6-f7ac-4dce-8791-7bddc37889d4-S0/frameworks/be3714c6-f7ac-4dce-8791-7bddc37889d4-0000/executors/1/runs/28632eb3-e3fb-41cf-8698-1353f9ccfa10'
      14:39:11  I1119 06:39:15.304333 167215104 slave.cpp:3034] Queued task '1' for executor '1' of framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000
      14:39:11  I1119 06:39:15.304420 167215104 slave.cpp:994] Successfully attached '/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/ContentType_AgentAPITest_GetFrameworks_1_6fUr73/slaves/be3714c6-f7ac-4dce-8791-7bddc37889d4-S0/frameworks/be3714c6-f7ac-4dce-8791-7bddc37889d4-0000/executors/1/runs/28632eb3-e3fb-41cf-8698-1353f9ccfa10' to virtual path '/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/ContentType_AgentAPITest_GetFrameworks_1_6fUr73/slaves/be3714c6-f7ac-4dce-8791-7bddc37889d4-S0/frameworks/be3714c6-f7ac-4dce-8791-7bddc37889d4-0000/executors/1/runs/latest'
      14:39:11  I1119 06:39:15.304605 167215104 slave.cpp:3515] Launching container 28632eb3-e3fb-41cf-8698-1353f9ccfa10 for executor '1' of framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000
      14:39:11  I1119 06:39:15.304941 167215104 slave.cpp:994] Successfully attached '/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/ContentType_AgentAPITest_GetFrameworks_1_6fUr73/slaves/be3714c6-f7ac-4dce-8791-7bddc37889d4-S0/frameworks/be3714c6-f7ac-4dce-8791-7bddc37889d4-0000/executors/1/runs/28632eb3-e3fb-41cf-8698-1353f9ccfa10' to virtual path '/frameworks/be3714c6-f7ac-4dce-8791-7bddc37889d4-0000/executors/1/runs/latest'
      14:39:11  I1119 06:39:15.304965 167215104 slave.cpp:994] Successfully attached '/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/ContentType_AgentAPITest_GetFrameworks_1_6fUr73/slaves/be3714c6-f7ac-4dce-8791-7bddc37889d4-S0/frameworks/be3714c6-f7ac-4dce-8791-7bddc37889d4-0000/executors/1/runs/28632eb3-e3fb-41cf-8698-1353f9ccfa10' to virtual path '/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/ContentType_AgentAPITest_GetFrameworks_1_6fUr73/slaves/be3714c6-f7ac-4dce-8791-7bddc37889d4-S0/frameworks/be3714c6-f7ac-4dce-8791-7bddc37889d4-0000/executors/1/runs/28632eb3-e3fb-41cf-8698-1353f9ccfa10'
      14:39:11  I1119 06:39:15.305202 169361408 containerizer.cpp:1288] Starting container 28632eb3-e3fb-41cf-8698-1353f9ccfa10
      14:39:11  I1119 06:39:15.306092 169361408 containerizer.cpp:1454] Checkpointed ContainerConfig at '/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/ContentType_AgentAPITest_GetFrameworks_1_Rt51JW/containers/28632eb3-e3fb-41cf-8698-1353f9ccfa10/config'
      14:39:11  I1119 06:39:15.306118 169361408 containerizer.cpp:3130] Transitioning the state of container 28632eb3-e3fb-41cf-8698-1353f9ccfa10 from PROVISIONING to PREPARING
      14:39:11  I1119 06:39:15.307767 169897984 containerizer.cpp:1947] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"arguments":["mesos-executor","--launcher_dir=/Users/jenkins/workspace/workspace/mesos/Mesos_CI-build/FLAG/SSL/label/mac/mesos/build/src"],"shell":false,"value":"/Users/jenkins/workspace/workspace/mesos/Mesos_CI-build/FLAG/SSL/label/mac/mesos/build/src/mesos-executor"},"environment":{"variables":[{"name":"LIBPROCESS_PORT","type":"VALUE","value":"0"},{"name":"MESOS_AGENT_ENDPOINT","type":"VALUE","value":"10.0.49.4:61227"},{"name":"MESOS_CHECKPOINT","type":"VALUE","value":"0"},{"name":"MESOS_DIRECTORY","type":"VALUE","value":"/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/ContentType_AgentAPITest_GetFrameworks_1_6fUr73/slaves/be3714c6-f7ac-4dce-8791-7bddc37889d4-S0/frameworks/be3714c6-f7ac-4dce-8791-7bddc37889d4-0000/executors/1/runs/28632eb3-e3fb-41cf-8698-1353f9ccfa10"},{"name":"MESOS_EXECUTOR_AUTHENTICATION_TOKEN","type":"VALUE","value":"eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJjaWQiOiIyODYzMmViMy1lM2ZiLTQxY2YtODY5OC0xMzUzZjljY2ZhMTAiLCJlaWQiOiIxIiwiZmlkIjoiYmUzNzE0YzYtZjdhYy00ZGNlLTg3OTEtN2JkZGMzNzg4OWQ0LTAwMDAifQ.OoSLOnlVGd8hsijTazWpBeFFobk0XKOq8-LuL4l2s2c"},{"name":"MESOS_EXECUTOR_ID","type":"VALUE","value":"1"},{"name":"MESOS_EXECUTOR_SHUTDOWN_GRACE_PERIOD","type":"VALUE","value":"5secs"},{"name":"MESOS_FRAMEWORK_ID","type":"VALUE","value":"be3714c6-f7ac-4dce-8791-7bddc37889d4-0000"},{"name":"MESOS_HTTP_COMMAND_EXECUTOR","type":"VALUE","value":"0"},{"name":"MESOS_SLAVE_ID","type":"VALUE","value":"be3714c6-f7ac-4dce-8791-7bddc37889d4-S0"},{"name":"MESOS_SLAVE_PID","type":"VALUE","value":"slave(828)@10.0.49.4:61227"},{"name":"MESOS_SANDBOX","type":"VALUE","value":"/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/ContentType_AgentAPITest_GetFrameworks_1_6fUr73/slaves/be3714c6-f7ac-4dce-8791-7bddc37889d4-S0/frameworks/be3714c6-f7ac-4dce-8791-7bddc37889d4-0000/executors/1/runs/28632eb3-e3fb-41cf-8698-1353f9ccfa10"}]},"task_environment":{},"user":"jenkins","working_directory":"/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/ContentType_AgentAPITest_GetFrameworks_1_6fUr73/slaves/be3714c6-f7ac-4dce-8791-7bddc37889d4-S0/frameworks/be3714c6-f7ac-4dce-8791-7bddc37889d4-0000/executors/1/runs/28632eb3-e3fb-41cf-8698-1353f9ccfa10"}" --pipe_read="24" --pipe_write="28" --runtime_directory="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/ContentType_AgentAPITest_GetFrameworks_1_Rt51JW/containers/28632eb3-e3fb-41cf-8698-1353f9ccfa10"'
      14:39:11  I1119 06:39:15.309439 169897984 launcher.cpp:145] Forked child with pid '71895' for container '28632eb3-e3fb-41cf-8698-1353f9ccfa10'
      14:39:11  I1119 06:39:15.310206 169897984 containerizer.cpp:3130] Transitioning the state of container 28632eb3-e3fb-41cf-8698-1353f9ccfa10 from PREPARING to ISOLATING
      14:39:11  I1119 06:39:15.312588 169897984 containerizer.cpp:3130] Transitioning the state of container 28632eb3-e3fb-41cf-8698-1353f9ccfa10 from ISOLATING to FETCHING
      14:39:11  I1119 06:39:15.312872 170434560 fetcher.cpp:369] Starting to fetch URIs for container: 28632eb3-e3fb-41cf-8698-1353f9ccfa10, directory: /var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/ContentType_AgentAPITest_GetFrameworks_1_6fUr73/slaves/be3714c6-f7ac-4dce-8791-7bddc37889d4-S0/frameworks/be3714c6-f7ac-4dce-8791-7bddc37889d4-0000/executors/1/runs/28632eb3-e3fb-41cf-8698-1353f9ccfa10
      14:39:11  I1119 06:39:15.313565 167751680 containerizer.cpp:3130] Transitioning the state of container 28632eb3-e3fb-41cf-8698-1353f9ccfa10 from FETCHING to RUNNING
      14:39:11  [warn] kq_init: detected broken kqueue; not using.: Undefined error: 0
      14:39:11  I1119 06:39:15.474073 151658496 exec.cpp:162] Version: 1.8.0
      14:39:11  I1119 06:39:15.477310 167751680 slave.cpp:4809] Got registration for executor '1' of framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000 from executor(1)@10.0.49.4:63782
      14:39:11  I1119 06:39:15.478510 168288256 slave.cpp:3247] Sending queued task '1' to executor '1' of framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000 at executor(1)@10.0.49.4:63782
      14:39:11  I1119 06:39:15.478849 149512192 exec.cpp:236] Executor registered on agent be3714c6-f7ac-4dce-8791-7bddc37889d4-S0
      14:39:11  I1119 06:39:15.485213 148975616 executor.cpp:184] Received SUBSCRIBED event
      14:39:11  I1119 06:39:15.485697 148975616 executor.cpp:188] Subscribed executor on Jenkinss-Mac-mini.local
      14:39:11  I1119 06:39:15.485786 148975616 executor.cpp:184] Received LAUNCH event
      14:39:11  I1119 06:39:15.491688 148975616 executor.cpp:687] Starting task 1
      14:39:11  I1119 06:39:15.497985 167215104 slave.cpp:5275] Handling status update TASK_STARTING (Status UUID: aca86396-e493-4a95-9bd3-d723058e9da7) for task 1 of framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000 from executor(1)@10.0.49.4:63782
      14:39:11  I1119 06:39:15.498713 148975616 executor.cpp:502] Running '/Users/jenkins/workspace/workspace/mesos/Mesos_CI-build/FLAG/SSL/label/mac/mesos/build/src/mesos-containerizer launch <POSSIBLY-SENSITIVE-DATA>'
      14:39:11  I1119 06:39:15.498822 167751680 task_status_update_manager.cpp:328] Received task status update TASK_STARTING (Status UUID: aca86396-e493-4a95-9bd3-d723058e9da7) for task 1 of framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000
      14:39:11  I1119 06:39:15.498853 167751680 task_status_update_manager.cpp:507] Creating StatusUpdate stream for task 1 of framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000
      14:39:11  I1119 06:39:15.499197 167751680 task_status_update_manager.cpp:383] Forwarding task status update TASK_STARTING (Status UUID: aca86396-e493-4a95-9bd3-d723058e9da7) for task 1 of framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000 to the agent
      14:39:11  I1119 06:39:15.499266 169897984 slave.cpp:5767] Forwarding the update TASK_STARTING (Status UUID: aca86396-e493-4a95-9bd3-d723058e9da7) for task 1 of framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000 to master@10.0.49.4:61227
      14:39:11  I1119 06:39:15.499434 169897984 slave.cpp:5660] Task status update manager successfully handled status update TASK_STARTING (Status UUID: aca86396-e493-4a95-9bd3-d723058e9da7) for task 1 of framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000
      14:39:11  I1119 06:39:15.499503 169897984 slave.cpp:5676] Sending acknowledgement for status update TASK_STARTING (Status UUID: aca86396-e493-4a95-9bd3-d723058e9da7) for task 1 of framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000 to executor(1)@10.0.49.4:63782
      14:39:11  I1119 06:39:15.499511 168288256 master.cpp:8420] Status update TASK_STARTING (Status UUID: aca86396-e493-4a95-9bd3-d723058e9da7) for task 1 of framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000 from agent be3714c6-f7ac-4dce-8791-7bddc37889d4-S0 at slave(828)@10.0.49.4:61227 (Jenkinss-Mac-mini.local)
      14:39:11  I1119 06:39:15.499544 168288256 master.cpp:8477] Forwarding status update TASK_STARTING (Status UUID: aca86396-e493-4a95-9bd3-d723058e9da7) for task 1 of framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000
      14:39:11  I1119 06:39:15.499650 168288256 master.cpp:10978] Updating the state of task 1 of framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000 (latest state: TASK_STARTING, status update state: TASK_STARTING)
      14:39:11  I1119 06:39:15.499884 167215104 sched.cpp:1022] Scheduler::statusUpdate took 108414ns
      14:39:11  I1119 06:39:15.500064 170434560 master.cpp:6286] Processing ACKNOWLEDGE call for status aca86396-e493-4a95-9bd3-d723058e9da7 for task 1 of framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000 (default) at scheduler-f91fa9d2-c57e-4118-b7ba-81f46d378a79@10.0.49.4:61227 on agent be3714c6-f7ac-4dce-8791-7bddc37889d4-S0
      14:39:11  I1119 06:39:15.500166 148975616 executor.cpp:702] Forked command at 71923
      14:39:11  I1119 06:39:15.500257 169897984 task_status_update_manager.cpp:401] Received task status update acknowledgement (UUID: aca86396-e493-4a95-9bd3-d723058e9da7) for task 1 of framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000
      14:39:11  I1119 06:39:15.500407 170971136 slave.cpp:4511] Task status update manager successfully handled status update acknowledgement (UUID: aca86396-e493-4a95-9bd3-d723058e9da7) for task 1 of framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000
      14:39:11  I1119 06:39:15.507848 168824832 slave.cpp:5275] Handling status update TASK_RUNNING (Status UUID: a49a359c-1cb8-4551-8df3-bc28ac2b7a2a) for task 1 of framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000 from executor(1)@10.0.49.4:63782
      14:39:11  I1119 06:39:15.508744 169897984 task_status_update_manager.cpp:328] Received task status update TASK_RUNNING (Status UUID: a49a359c-1cb8-4551-8df3-bc28ac2b7a2a) for task 1 of framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000
      14:39:11  I1119 06:39:15.508831 169897984 task_status_update_manager.cpp:383] Forwarding task status update TASK_RUNNING (Status UUID: a49a359c-1cb8-4551-8df3-bc28ac2b7a2a) for task 1 of framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000 to the agent
      14:39:11  I1119 06:39:15.509007 168288256 slave.cpp:5767] Forwarding the update TASK_RUNNING (Status UUID: a49a359c-1cb8-4551-8df3-bc28ac2b7a2a) for task 1 of framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000 to master@10.0.49.4:61227
      14:39:11  I1119 06:39:15.509145 168288256 slave.cpp:5660] Task status update manager successfully handled status update TASK_RUNNING (Status UUID: a49a359c-1cb8-4551-8df3-bc28ac2b7a2a) for task 1 of framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000
      14:39:11  I1119 06:39:15.509188 168288256 slave.cpp:5676] Sending acknowledgement for status update TASK_RUNNING (Status UUID: a49a359c-1cb8-4551-8df3-bc28ac2b7a2a) for task 1 of framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000 to executor(1)@10.0.49.4:63782
      14:39:11  I1119 06:39:15.509207 170971136 master.cpp:8420] Status update TASK_RUNNING (Status UUID: a49a359c-1cb8-4551-8df3-bc28ac2b7a2a) for task 1 of framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000 from agent be3714c6-f7ac-4dce-8791-7bddc37889d4-S0 at slave(828)@10.0.49.4:61227 (Jenkinss-Mac-mini.local)
      14:39:11  I1119 06:39:15.509243 170971136 master.cpp:8477] Forwarding status update TASK_RUNNING (Status UUID: a49a359c-1cb8-4551-8df3-bc28ac2b7a2a) for task 1 of framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000
      14:39:11  I1119 06:39:15.509382 170971136 master.cpp:10978] Updating the state of task 1 of framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
      14:39:11  I1119 06:39:15.509624 168824832 sched.cpp:1022] Scheduler::statusUpdate took 107500ns
      14:39:11  I1119 06:39:15.509821 169361408 master.cpp:6286] Processing ACKNOWLEDGE call for status a49a359c-1cb8-4551-8df3-bc28ac2b7a2a for task 1 of framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000 (default) at scheduler-f91fa9d2-c57e-4118-b7ba-81f46d378a79@10.0.49.4:61227 on agent be3714c6-f7ac-4dce-8791-7bddc37889d4-S0
      14:39:11  I1119 06:39:15.510013 168288256 task_status_update_manager.cpp:401] Received task status update acknowledgement (UUID: a49a359c-1cb8-4551-8df3-bc28ac2b7a2a) for task 1 of framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000
      14:39:11  I1119 06:39:15.510170 167751680 slave.cpp:4511] Task status update manager successfully handled status update acknowledgement (UUID: a49a359c-1cb8-4551-8df3-bc28ac2b7a2a) for task 1 of framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000
      14:39:11  I1119 06:39:15.511095 169897984 process.cpp:3588] Handling HTTP event for process 'slave(828)' with path: '/slave(828)/api/v1'
      14:39:11  I1119 06:39:15.511780 168288256 http.cpp:1182] HTTP POST for /slave(828)/api/v1 from 10.0.49.4:63785
      14:39:11  I1119 06:39:15.511982 168288256 http.cpp:1454] Processing GET_FRAMEWORKS call
      14:39:11  I1119 06:39:15.513320 2668864320 sched.cpp:2008] Asked to stop the driver
      14:39:11  I1119 06:39:15.513387 170434560 sched.cpp:1184] Stopping framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000
      14:39:11  I1119 06:39:15.513556 167215104 master.cpp:10231] Processing TEARDOWN call for framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000 (default) at scheduler-f91fa9d2-c57e-4118-b7ba-81f46d378a79@10.0.49.4:61227
      14:39:11  I1119 06:39:15.513588 167215104 master.cpp:10243] Removing framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000 (default) at scheduler-f91fa9d2-c57e-4118-b7ba-81f46d378a79@10.0.49.4:61227
      14:39:11  I1119 06:39:15.513605 167215104 master.cpp:3252] Deactivating framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000 (default) at scheduler-f91fa9d2-c57e-4118-b7ba-81f46d378a79@10.0.49.4:61227
      14:39:11  I1119 06:39:15.513739 167215104 master.cpp:10978] Updating the state of task 1 of framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000 (latest state: TASK_KILLED, status update state: TASK_KILLED)
      14:39:11  I1119 06:39:15.513789 167751680 hierarchical.cpp:418] Deactivated framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000
      14:39:11  I1119 06:39:15.513829 168824832 slave.cpp:3902] Asked to shut down framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000 by master@10.0.49.4:61227
      14:39:11  I1119 06:39:15.513851 168824832 slave.cpp:3927] Shutting down framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000
      14:39:11  I1119 06:39:15.513883 168824832 slave.cpp:6646] Shutting down executor '1' of framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000 at executor(1)@10.0.49.4:63782
      14:39:11  I1119 06:39:15.514106 167215104 master.cpp:11076] Removing task 1 with resources cpus(allocated: *):2; mem(allocated: *):1024; disk(allocated: *):1024; ports(allocated: *):[31000-32000] of framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000 on agent be3714c6-f7ac-4dce-8791-7bddc37889d4-S0 at slave(828)@10.0.49.4:61227 (Jenkinss-Mac-mini.local)
      14:39:11  I1119 06:39:15.514303 169361408 hierarchical.cpp:1238] 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 be3714c6-f7ac-4dce-8791-7bddc37889d4-S0 from framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000
      14:39:11  I1119 06:39:15.514572 169897984 hierarchical.cpp:357] Removed framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000
      14:39:11  I1119 06:39:15.514663 147902464 exec.cpp:445] Executor asked to shutdown
      14:39:11  I1119 06:39:15.514859 149512192 executor.cpp:184] Received SHUTDOWN event
      14:39:11  I1119 06:39:15.514885 149512192 executor.cpp:805] Shutting down
      14:39:11  I1119 06:39:15.514914 149512192 executor.cpp:918] Sending SIGTERM to process tree at pid 71923
      14:39:11  I1119 06:39:15.552628 149512192 executor.cpp:931] Sent SIGTERM to the following process trees:
      14:39:11  [ 
      14:39:11  -+- 71923 /bin/sh /Users/jenkins/workspace/workspace/mesos/Mesos_CI-build/FLAG/SSL/label/mac/mesos/build/src/mesos-containerizer launch --help=false --launch_info={"command":{"shell":true,"value":"sleep 1000"},"environment":{"variables":[{"name":"PATH","type":"VALUE","value":"/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin"},{"name":"PWD","type":"VALUE","value":"/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/ContentType_AgentAPITest_GetFrameworks_1_6fUr73/slaves/be3714c6-f7ac-4dce-8791-7bddc37889d4-S0/frameworks/be3714c6-f7ac-4dce-8791-7bddc37889d4-0000/executors/1/runs/28632eb3-e3fb-41cf-8698-1353f9ccfa10"},{"name":"MESOS_SLAVE_PID","type":"VALUE","value":"slave(828)@10.0.49.4:61227"},{"name":"MESOS_FRAMEWORK_ID","type":"VALUE","value":"be3714c6-f7ac-4dce-8791-7bddc37889d4-0000"},{"name":"MESOS_EXECUTOR_ID","type":"VALUE","value":"1"},{"name":"MESOS_EXECUTOR_AUTHENTICATION_TOKEN","type":"VALUE","value":"eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJjaWQiOiIyODYzMmViMy1lM2ZiLTQxY2YtODY5OC0xMzUzZjljY2ZhMTAiLCJlaWQiOiIxIiwiZmlkIjoiYmUzNzE0YzYtZjdhYy00ZGNlLTg3OTEtN2JkZGMzNzg4OWQ0LTAwMDAifQ.OoSLOnlVGd8hsijTazWpBeFFobk0XKOq8-LuL4l2s2c"},{"name":"MESOS_CHECKPOINT","type":"VALUE","value":"0"},{"name":"MESOS_SLAVE_ID","type":"VALUE","value":"be3714c6-f7ac-4dce-8791-7bddc37889d4-S0"},{"name":"MESOS_SANDBOX","type":"VALUE","value":"/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/ContentType_AgentAPITest_GetFrameworks_1_6fUr73/slaves/be3714c6-f7ac-4dce-8791-7bddc37889d4-S0/frameworks/be3714c6-f7ac-4dce-8791-7bddc37889d4-0000/executors/1/runs/28632eb3-e3fb-41cf-8698-1353f9ccfa10"},{"name":"MESOS_EXECUTOR_SHUTDOWN_GRACE_PERIOD","type":"VALUE","value":"5secs"},{"name":"SHLVL","type":"VALUE","value":"0"},{"name":"DUALCASE","type":"VALUE","value":"1"},{"name":"MESOS_AGENT_ENDPOINT","type":"VALUE","value":"10.0.49.4:61227"},{"name":"DYLD_LIBRARY_PATH","type":"VALUE","value":"/Users/jenkins/workspace/workspace/mesos/Mesos_CI-build/FLAG/SSL/label/mac/mesos/build/src/.libs"},{"name":"__CF_USER_TEXT_ENCODING","type":"VALUE","value":"0x1F5:0x0:0x0"},{"name":"MESOS_DIRECTORY","type":"VALUE","value":"/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/ContentType_AgentAPITest_GetFrameworks_1_6fUr73/slaves/be3714c6-f7ac-4dce-8791-7bddc37889d4-S0/frameworks/be3714c6-f7ac-4dce-8791-7bddc37889d4-0000/executors/1/runs/28632eb3-e3fb-41cf-8698-1353f9ccfa10"},{"name":"LIBPROCESS_PORT","type":"VALUE","value":"0"},{"name":"MESOS_HTTP_COMMAND_EXECUTOR","type":"VALUE","value":"0"},{"name":"BIN_SH","type":"VALUE","value":"xpg4"}]}}
      14:39:11   \--- 71934 (sh)
      14:39:11  ]
      14:39:11  I1119 06:39:15.552690 149512192 executor.cpp:935] Scheduling escalation to SIGKILL in 3secs from now
      14:39:11  I1119 06:39:15.570111 151121920 executor.cpp:1003] Command terminated with signal Terminated: 15 (pid: 71923)
      14:39:11  I1119 06:39:15.576234 168824832 slave.cpp:5275] Handling status update TASK_KILLED (Status UUID: c5d92cee-03c1-45ce-8cb0-81d0dfc968d8) for task 1 of framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000 from executor(1)@10.0.49.4:63782
      14:39:11  W1119 06:39:15.576290 168824832 slave.cpp:5344] Ignoring status update TASK_KILLED (Status UUID: c5d92cee-03c1-45ce-8cb0-81d0dfc968d8) for task 1 of framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000 for terminating framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000
      14:39:51  I1119 06:39:51.104415 167215104 slave.cpp:6719] Killing executor '1' of framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000 at executor(1)@10.0.49.4:63782
      14:39:51  I1119 06:39:51.106272 168288256 slave.cpp:5899] Got exited event for executor(1)@10.0.49.4:63782
      14:39:51  ../../src/tests/api_tests.cpp:5500: Failure
      14:39:51  Failed to wait 15secs for executorTerminated
      14:39:51  I1119 06:39:51.106459 170434560 containerizer.cpp:2463] Destroying container 28632eb3-e3fb-41cf-8698-1353f9ccfa10 in RUNNING state
      14:39:51  I1119 06:39:51.106482 170434560 containerizer.cpp:3130] Transitioning the state of container 28632eb3-e3fb-41cf-8698-1353f9ccfa10 from RUNNING to DESTROYING
      14:39:51  I1119 06:39:51.106822 170434560 launcher.cpp:161] Asked to destroy container 28632eb3-e3fb-41cf-8698-1353f9ccfa10
      14:39:51  I1119 06:39:51.107393 2668864320 slave.cpp:915] Agent terminating
      14:39:51  I1119 06:39:51.107439 2668864320 slave.cpp:3902] Asked to shut down framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000 by @0.0.0.0:0
      14:39:51  W1119 06:39:51.107461 2668864320 slave.cpp:3923] Ignoring shutdown framework be3714c6-f7ac-4dce-8791-7bddc37889d4-0000 because it is terminating
      14:39:51  I1119 06:39:51.165649 168824832 master.cpp:1273] Agent be3714c6-f7ac-4dce-8791-7bddc37889d4-S0 at slave(828)@10.0.49.4:61227 (Jenkinss-Mac-mini.local) disconnected
      14:39:51  I1119 06:39:51.165710 168824832 master.cpp:3289] Disconnecting agent be3714c6-f7ac-4dce-8791-7bddc37889d4-S0 at slave(828)@10.0.49.4:61227 (Jenkinss-Mac-mini.local)
      14:39:51  I1119 06:39:51.165760 168824832 master.cpp:3308] Deactivating agent be3714c6-f7ac-4dce-8791-7bddc37889d4-S0 at slave(828)@10.0.49.4:61227 (Jenkinss-Mac-mini.local)
      14:39:51  I1119 06:39:51.165907 169361408 hierarchical.cpp:801] Agent be3714c6-f7ac-4dce-8791-7bddc37889d4-S0 deactivated
      14:39:51  I1119 06:39:51.205538 167751680 containerizer.cpp:2969] Container 28632eb3-e3fb-41cf-8698-1353f9ccfa10 has exited
      14:39:51  I1119 06:39:51.206760 168824832 provisioner.cpp:597] Ignoring destroy request for unknown container 28632eb3-e3fb-41cf-8698-1353f9ccfa10
      14:39:51  I1119 06:39:51.214574 2668864320 master.cpp:1115] Master terminating
      14:39:51  I1119 06:39:51.215334 168288256 hierarchical.cpp:643] Removed agent be3714c6-f7ac-4dce-8791-7bddc37889d4-S0
      14:39:51  ../../3rdparty/libprocess/include/process/gmock.hpp:545: Failure
      14:39:51  Actual function call count doesn't match EXPECT_CALL(filter->mock, filter(pid, testing::A<const DispatchEvent&>()))...
      14:39:51      Expected args: dispatch matcher 16-byte object <59-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00>
      14:39:51           Expected: to be called once
      14:39:51             Actual: never called - unsatisfied and active
      14:39:51  [  FAILED  ] ContentType/AgentAPITest.GetFrameworks/1, where GetParam() = application/json (35956 ms)
      

        Attachments

          Activity

            People

            • Assignee:
              Unassigned
              Reporter:
              tillt Till Toenshoff
            • Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

              • Created:
                Updated: