Last active
April 7, 2016 19:34
-
-
Save philcryer/8696300 to your computer and use it in GitHub Desktop.
for the past week, running chef-client in my QA environment stalls for ~5mins... I cut out cookbooks, took out environments, and then built a new chef-server, but the problem persists.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| chef-client -l debug | |
| ==== | |
| [2014-01-29T14:08:44-06:00] DEBUG: Sending HTTP Request via POST to dc2mgmtdpsqa01.mgmt.sdirect:443/reports/nodes/dc2ctscomqa01.mgmt.sdirect/runs | |
| [2014-01-29T14:08:44-06:00] DEBUG: ---- HTTP Status and Header Data: ---- | |
| [2014-01-29T14:08:44-06:00] DEBUG: HTTP 1.1 404 Object Not Found | |
| [2014-01-29T14:08:44-06:00] DEBUG: server: nginx/1.4.4 | |
| [2014-01-29T14:08:44-06:00] DEBUG: date: Wed, 29 Jan 2014 20:08:50 GMT | |
| [2014-01-29T14:08:44-06:00] DEBUG: content-type: text/html | |
| [2014-01-29T14:08:44-06:00] DEBUG: transfer-encoding: chunked | |
| [2014-01-29T14:08:44-06:00] DEBUG: connection: close | |
| [2014-01-29T14:08:44-06:00] DEBUG: content-encoding: gzip | |
| [2014-01-29T14:08:44-06:00] DEBUG: ---- End HTTP Status/Header Data ---- | |
| [2014-01-29T14:08:44-06:00] DEBUG: decompressing gzip response | |
| [2014-01-29T14:08:44-06:00] DEBUG: Reporting error starting run. URL: reports/nodes/dc2ctscomqa01.mgmt.sdirect/runs Received 404. Disabling reporting for run. | |
| [2014-01-29T14:08:44-06:00] DEBUG: Synchronizing cookbooks | |
| resolving cookbooks for run list: ["base", "web", "logging"] | |
| [2014-01-29T14:08:44-06:00] DEBUG: Signing the request as dc2ctscomqa01.mgmt.sdirect | |
| [2014-01-29T14:08:44-06:00] DEBUG: String to sign: 'Method:POST | |
| Hashed Path:zXHyJOjo6pCoVGEbbPQWMq1P1mY= | |
| X-Ops-Content-Hash:9BB4C2UTT4tWSj0TyZ7CgzmB1GQ= | |
| X-Ops-Timestamp:2014-01-29T20:08:44Z | |
| X-Ops-UserId:dc2ctscomqa01.mgmt.sdirect' | |
| Header hash: {"X-Ops-Sign"=>"algorithm=sha1;version=1.0;", "X-Ops-Userid"=>"dc2ctscomqa01.mgmt.sdirect", "X-Ops-Timestamp"=>"2014-01-29T20:08:44Z", "X-Ops-Content-Hash"=>"9BB4C2UTT4tWSj0TyZ7CgzmB1GQ=", "X-Ops-Authorization-1"=>"KjWZsRIrpjYV0hYIIeMWSweutKJsNHoV0TZC8MLTMHhjnAzKi4lE8hf2Hmyx", "X-Ops-Authorization-2"=>"EkMv6jXXnU9RYnGwqEg8yao//Vxuh6fdkhTtt+o9FUuUG5xgNWiKd/I5ZcGH", "X-Ops-Authorization-3"=>"SiQQrHR3rJvY8ZOYc6U58mjBIt86YysHhWdRrH5TU2pNCmwJg3NWKv2rEiVO", "X-Ops-Authorization-4"=>"5KRW2eoqRGob2LFvlKYm2+agT6H8XEYVkrZH0PqC8GOR+h9G99akYU1rrGgg", "X-Ops-Authorization-5"=>"g81oUZNOLZz+cA+AAqqwxQD+abvbPNd9cCe2Muivezw33ToY/FKj1PBP8ams", "X-Ops-Authorization-6"=>"2AzEsVHYzSvvbqf29HqVpVh6179GWAP5TZjCksZXjQ=="} | |
| [2014-01-29T14:08:44-06:00] DEBUG: Sending HTTP Request via POST to dc2mgmtdpsqa01.mgmt.sdirect:443/environments/_default/cookbook_versions | |
| [2014-01-29T14:13:44-06:00] ERROR: Timeout connecting to dc2mgmtdpsqa01.mgmt.sdirect:443 for /environments/_default/cookbook_versions, retry 1/5 | |
| [2014-01-29T14:18:50-06:00] ERROR: Timeout connecting to dc2mgmtdpsqa01.mgmt.sdirect:443 for /environments/_default/cookbook_versions, retry 2/5 | |
| [2014-01-29T14:23:55-06:00] ERROR: Timeout connecting to dc2mgmtdpsqa01.mgmt.sdirect:443 for /environments/_default/cookbook_versions, retry 3/5 | |
| [2014-01-29T14:24:00-06:00] DEBUG: ---- HTTP Status and Header Data: ---- | |
| [2014-01-29T14:24:00-06:00] DEBUG: HTTP 1.1 401 Unauthorized | |
| [2014-01-29T14:24:00-06:00] DEBUG: server: nginx/1.4.4 | |
| [2014-01-29T14:24:00-06:00] DEBUG: date: Wed, 29 Jan 2014 20:24:06 GMT | |
| [2014-01-29T14:24:00-06:00] DEBUG: content-length: 103 | |
| [2014-01-29T14:24:00-06:00] DEBUG: connection: close | |
| [2014-01-29T14:24:00-06:00] DEBUG: x-ops-api-info: flavor=osc;version=11.0.2;erchef=1.2.6 | |
| [2014-01-29T14:24:00-06:00] DEBUG: ---- End HTTP Status/Header Data ---- | |
| ================================================================================ | |
| Error Resolving Cookbooks for Run List: | |
| ================================================================================ | |
| Authentication Error: | |
| --------------------- | |
| Failed to authenticate to the chef server (http 401). | |
| The request failed because your clock has drifted by more than 15 minutes. | |
| Syncing your clock to an NTP Time source should resolve the issue. | |
| [2014-01-29T14:24:00-06:00] DEBUG: Re-raising exception: Net::HTTPServerException - 401 "Unauthorized" | |
| /opt/chef/embedded/lib/ruby/1.9.1/net/http.rb:2633:in `error!' | |
| /opt/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.6.0/lib/chef/rest.rb:207:in `block in raw_http_request' | |
| /opt/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.6.0/lib/chef/rest.rb:289:in `retriable_rest_request' | |
| /opt/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.6.0/lib/chef/rest.rb:167:in `raw_http_request' | |
| /opt/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.6.0/lib/chef/rest.rb:161:in `api_request' | |
| /opt/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.6.0/lib/chef/rest.rb:121:in `post' | |
| /opt/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.6.0/lib/chef/client.rb:402:in `sync_cookbooks' | |
| /opt/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.6.0/lib/chef/client.rb:243:in `setup_run_context' | |
| /opt/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.6.0/lib/chef/client.rb:492:in `do_run' | |
| /opt/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.6.0/lib/chef/client.rb:199:in `block in run' | |
| /opt/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.6.0/lib/chef/client.rb:193:in `fork' | |
| /opt/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.6.0/lib/chef/client.rb:193:in `run' | |
| /opt/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.6.0/lib/chef/application.rb:183:in `run_chef_client' | |
| /opt/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.6.0/lib/chef/application/client.rb:302:in `block in run_application' | |
| /opt/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.6.0/lib/chef/application/client.rb:294:in `loop' | |
| /opt/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.6.0/lib/chef/application/client.rb:294:in `run_application' | |
| /opt/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.6.0/lib/chef/application.rb:66:in `run' | |
| /opt/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.6.0/bin/chef-client:26:in `<top (required)>' | |
| /usr/bin/chef-client:23:in `load' | |
| /usr/bin/chef-client:23:in `<main>' | |
| [2014-01-29T14:24:00-06:00] ERROR: Running exception handlers | |
| [2014-01-29T14:24:00-06:00] ERROR: Exception handlers complete | |
| [2014-01-29T14:24:00-06:00] FATAL: Stacktrace dumped to /var/chef/cache/chef-stacktrace.out | |
| [2014-01-29T14:24:00-06:00] DEBUG: Net::HTTPServerException: 401 "Unauthorized" | |
| /opt/chef/embedded/lib/ruby/1.9.1/net/http.rb:2633:in `error!' | |
| /opt/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.6.0/lib/chef/rest.rb:207:in `block in raw_http_request' | |
| /opt/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.6.0/lib/chef/rest.rb:289:in `retriable_rest_request' | |
| /opt/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.6.0/lib/chef/rest.rb:167:in `raw_http_request' | |
| /opt/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.6.0/lib/chef/rest.rb:161:in `api_request' | |
| /opt/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.6.0/lib/chef/rest.rb:121:in `post' | |
| /opt/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.6.0/lib/chef/client.rb:402:in `sync_cookbooks' | |
| /opt/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.6.0/lib/chef/client.rb:243:in `setup_run_context' | |
| /opt/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.6.0/lib/chef/client.rb:492:in `do_run' | |
| /opt/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.6.0/lib/chef/client.rb:199:in `block in run' | |
| /opt/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.6.0/lib/chef/client.rb:193:in `fork' | |
| /opt/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.6.0/lib/chef/client.rb:193:in `run' | |
| /opt/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.6.0/lib/chef/application.rb:183:in `run_chef_client' | |
| /opt/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.6.0/lib/chef/application/client.rb:302:in `block in run_application' | |
| /opt/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.6.0/lib/chef/application/client.rb:294:in `loop' | |
| /opt/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.6.0/lib/chef/application/client.rb:294:in `run_application' | |
| /opt/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.6.0/lib/chef/application.rb:66:in `run' | |
| /opt/chef/embedded/lib/ruby/gems/1.9.1/gems/chef-11.6.0/bin/chef-client:26:in `<top (required)>' | |
| /usr/bin/chef-client:23:in `load' | |
| /usr/bin/chef-client:23:in `<main>' | |
| Chef Client failed. 0 resources updated | |
| [2014-01-29T14:24:00-06:00] DEBUG: Server doesn't support resource history, skipping resource report. | |
| [2014-01-29T14:24:00-06:00] FATAL: Chef::Exceptions::ChildConvergeError: Chef run process exited unsuccessfully (exit code 1) | |
| (note the servers are in sync via ntp) | |
| Wed Jan 29 14:28:53 CST 2014 | |
| [root@dc2ctscomqa01 ~]# | |
| root@dc2mgmtdpsqa01:/etc/chef-server# date | |
| Wed Jan 29 14:29:01 CST 2014 | |
| chef-server | |
| ===== | |
| ==> /var/log/chef-server/nginx/access.log <== | |
| 10.187.255.155 - - [29/Jan/2014:14:02:36 -0600] "GET /nodes/dc2ctscomqa01.mgmt.sdirect HTTP/1.1" 200 "0.009" 6550 "-" "Chef Client/11.6.0 (ruby-1.9.3-p429; ohai-6.18.0; x86_64-linux; +http://opscode.com)" "127.0.0.1:8000" "200" "0.009" "11.6.0" "algorithm=sha1;version=1.0;" "dc2ctscomqa01.mgmt.sdirect" "2014-01-29T20:02:30Z" "2jmj7l5rSw0yVb/vlWAYkK/YBwk=" 980 | |
| 10.187.255.155 - - [29/Jan/2014:14:02:36 -0600] "GET /roles/base HTTP/1.1" 200 "0.007" 416 "-" "Chef Client/11.6.0 (ruby-1.9.3-p429; ohai-6.18.0; x86_64-linux; +http://opscode.com)" "127.0.0.1:8000" "200" "0.007" "11.6.0" "algorithm=sha1;version=1.0;" "dc2ctscomqa01.mgmt.sdirect" "2014-01-29T20:02:30Z" "2jmj7l5rSw0yVb/vlWAYkK/YBwk=" 958 | |
| 10.187.255.155 - - [29/Jan/2014:14:02:36 -0600] "GET /environments/qa HTTP/1.1" 200 "0.007" 426 "-" "Chef Client/11.6.0 (ruby-1.9.3-p429; ohai-6.18.0; x86_64-linux; +http://opscode.com)" "127.0.0.1:8000" "200" "0.007" "11.6.0" "algorithm=sha1;version=1.0;" "dc2ctscomqa01.mgmt.sdirect" "2014-01-29T20:02:30Z" "2jmj7l5rSw0yVb/vlWAYkK/YBwk=" 963 | |
| 10.187.255.155 - - [29/Jan/2014:14:02:36 -0600] "POST /reports/nodes/dc2ctscomqa01.mgmt.sdirect/runs HTTP/1.1" 404 "0.040" 173 "-" "Chef Client/11.6.0 (ruby-1.9.3-p429; ohai-6.18.0; x86_64-linux; +http://opscode.com)" "127.0.0.1:8000" "404" "0.002" "11.6.0" "algorithm=sha1;version=1.0;" "dc2ctscomqa01.mgmt.sdirect" "2014-01-29T20:02:30Z" "qg48NbWYP0WoNFVHuD3NglRIUQw=" 1195 | |
| ==> /var/log/chef-server/erchef/erchef.log.1 <== | |
| 2014-01-29T20:02:36Z [email protected] INFO req_id=rQ+HGR2IwgTi80sCYI8LmQ==; status=200; method=GET; path=/nodes/dc2ctscomqa01.mgmt.sdirect; user=dc2ctscomqa01.mgmt.sdirect; msg=[]; req_time=6; rdbms_time=2; rdbms_count=2 | |
| 2014-01-29T20:02:36Z [email protected] INFO req_id=Rp5tKTW+oQwu/ZBv26CtdQ==; status=200; method=GET; path=/roles/base; user=dc2ctscomqa01.mgmt.sdirect; msg=[]; req_time=5; rdbms_time=1; rdbms_count=2 | |
| 2014-01-29T20:02:36Z [email protected] INFO req_id=FY8cNbaBVfLkmhXxQwiOSA==; status=200; method=GET; path=/environments/qa; user=dc2ctscomqa01.mgmt.sdirect; msg=[]; req_time=4; rdbms_time=1; rdbms_count=2 | |
| ==> /var/log/chef-server/chef-solr/current <== | |
| 2014-01-29_20:03:59.88267 Jan 29, 2014 2:03:59 PM org.apache.solr.core.SolrCore execute | |
| 2014-01-29_20:03:59.88268 INFO: [] webapp=/solr path=/select params={sort=X_CHEF_id_CHEF_X+asc&indent=off&start=0&q=*:*&wt=json&fq=%2BX_CHEF_database_CHEF_X:chef_00000000000000000000000000000000+%2BX_CHEF_type_CHEF_X:node&rows=1000} hits=1 status=0 QTime=0 | |
| ==> /var/log/chef-server/nginx/access.log <== | |
| 10.12.217.3 - - [29/Jan/2014:14:03:59 -0600] "GET /search/node?q=*:*&sort=X_CHEF_id_CHEF_X%20asc&start=0&rows=1000 HTTP/1.1" 200 "0.009" 6578 "-" "Chef Knife/11.8.2 (ruby-1.9.3-p484; ohai-6.20.0; x86_64-darwin11.2.0; +http://opscode.com)" "127.0.0.1:8000" "200" "0.009" "11.8.2" "algorithm=sha1;version=1.0;" "phil" "2014-01-29T20:04:00Z" "2jmj7l5rSw0yVb/vlWAYkK/YBwk=" 995 | |
| ==> /var/log/chef-server/erchef/erchef.log.1 <== | |
| 2014-01-29T20:03:59Z [email protected] INFO req_id=d3yZuJ79+OrFeenKvURFxQ==; status=200; method=GET; path=/search/node?q=*:*&sort=X_CHEF_id_CHEF_X%20asc&start=0&rows=1000; user=phil; msg={search,1,1,1}; req_time=6; rdbms_time=0; rdbms_count=3; solr_time=2; solr_count=1 | |
| ==> /var/log/chef-server/nginx/access.log <== | |
| 10.12.217.3 - - [29/Jan/2014:14:04:24 -0600] "GET /nodes/dc2ctscomqa01.mgmt.sdirect HTTP/1.1" 200 "0.006" 6550 "-" "Chef Knife/11.8.2 (ruby-1.9.3-p484; ohai-6.20.0; x86_64-darwin11.2.0; +http://opscode.com)" "127.0.0.1:8000" "200" "0.006" "11.8.2" "algorithm=sha1;version=1.0;" "phil" "2014-01-29T20:04:24Z" "2jmj7l5rSw0yVb/vlWAYkK/YBwk=" 964 | |
| ==> /var/log/chef-server/erchef/erchef.log.1 <== | |
| 2014-01-29T20:04:24Z [email protected] INFO req_id=9KuRSgpFPBf89orbNzPqXw==; status=200; method=GET; path=/nodes/dc2ctscomqa01.mgmt.sdirect; user=phil; msg=[]; req_time=4; rdbms_time=0; rdbms_count=3 | |
| ==> /var/log/chef-server/chef-solr/current <== | |
| 2014-01-29_20:04:35.30927 Jan 29, 2014 2:04:35 PM org.apache.solr.core.SolrDeletionPolicy onInit | |
| 2014-01-29_20:04:35.30929 INFO: SolrDeletionPolicy.onInit: commits:num=1 | |
| 2014-01-29_20:04:35.30930 commit{dir=/var/opt/chef-server/chef-solr/data/index,segFN=segments_j,version=1391020345542,generation=19,filenames=[_7_1.del, _9.tis, _8.tis, _d.tii, _1.frq, _a.tii, _e.frq, _9.tii, _3.fdt, _2.tii, _c.tii, _7.fnm, _4.frq, _7.tis, _c.tis, _7.nrm, _c.nrm, _d.tis, _a.tis, _g.fdt, _d.frq, _a.prx, _g.fdx, _2.prx, _9.prx, _5_2.del, _c.prx, _7.tii, _8.frq, _2.fdt, _2.frq, _9.fdt, _7.fdx, segments_j, _2.fdx, _6_1.del, _9.fdx, _7.fdt, _f.fdt, _1.fdx, _f.fdx, _2.tis, _g.nrm, _8.tii, _1.fdt, _0.frq, _6.fdt, _c.frq, _2.nrm, _a.fnm, _6.fdx, _e.fdx, _3.fnm, _6.tis, _e.fdt, _1.tii, _e.nrm, _g.prx, _2_2.del, _1.tis, _3_2.del, _9.fnm, _4.nrm, _6.tii, _5.frq, _g.frq, _d.prx, _d.fdx, _2.fnm, _b.frq, _3.fdx, _8.nrm, _d.fdt, _d.nrm, _6.fnm, _c.fnm, _a.nrm, _f.frq, _f.tis, _g.tis, _0.tis, _5.prx, _5.fdt, _a_1.del, _4.prx, _4.fnm, _c.fdx, _1.fnm, _8_1.del, _c.fdt, _4.fdx, _5.tis, _5.nrm, _g.tii, _7.frq, _9_1.del, _4_1.del, _f.tii, _e.fnm, _0.prx, _f.nrm, _3.nrm, _0.fnm, _a.frq, _d.fnm, _3.prx, _5.tii, _1.prx, _8.fnm, _f.prx, _0.tii, _e.prx, _1.nrm, _6.nrm, _3.tii, _3.frq, _9.nrm, _6.frq, _e.tis, _b.nrm, _a.fdt, _a.fdx, _e.tii, _g.fnm, _1_3.del, _4.tis, _4.tii, _0.nrm, _5.fnm, _b.prx, _b_2.del, _b.tis, _4.fdt, _9.frq, _b.tii, _7.prx, _8.prx, _f.fnm, _6.prx, _b.fnm, _5.fdx, _b.fdt, _0.fdx, _8.fdx, _b.fdx, _0.fdt, _3.tis, _8.fdt] | |
| 2014-01-29_20:04:35.30949 Jan 29, 2014 2:04:35 PM org.apache.solr.core.SolrDeletionPolicy updateCommits | |
| 2014-01-29_20:04:35.30950 INFO: newest commit = 1391020345542 | |
| ==> /var/log/chef-server/nginx/access.log <== | |
| 10.12.217.3 - - [29/Jan/2014:14:04:35 -0600] "PUT /nodes/dc2ctscomqa01.mgmt.sdirect HTTP/1.1" 200 "0.141" 6543 "-" "Chef Knife/11.8.2 (ruby-1.9.3-p484; ohai-6.20.0; x86_64-darwin11.2.0; +http://opscode.com)" "127.0.0.1:8000" "200" "0.037" "11.8.2" "algorithm=sha1;version=1.0;" "phil" "2014-01-29T20:04:35Z" "c+QySmBAMTrDyLTFnjAihqkkh18=" 19868 | |
| ==> /var/log/chef-server/chef-solr/current <== | |
| 2014-01-29_20:04:35.32764 Jan 29, 2014 2:04:35 PM org.apache.solr.update.processor.LogUpdateProcessor finish | |
| 2014-01-29_20:04:35.32765 INFO: {add=[0000000000007381e308996ed183a5ce]} 0 39 | |
| 2014-01-29_20:04:35.32786 Jan 29, 2014 2:04:35 PM org.apache.solr.core.SolrCore execute | |
| 2014-01-29_20:04:35.32787 INFO: [] webapp=/solr path=/update params={} status=0 QTime=39 | |
| ==> /var/log/chef-server/chef-expander/current <== | |
| 2014-01-29_20:04:35.33595 [Wed, 29 Jan 2014 14:04:35 -0600] INFO: indexed node[0000000000007381e308996ed183a5ce] database[chef_00000000000000000000000000000000] transit,xml,solr-post | 0,0.03493046760559082,0.08341622352600098 | | |
| ==> /var/log/chef-server/erchef/erchef.log.1 <== | |
| 2014-01-29T20:04:35Z [email protected] INFO req_id=1iXn5mnsq/tferM3b7vKxg==; status=200; method=PUT; path=/nodes/dc2ctscomqa01.mgmt.sdirect; user=phil; msg=[]; req_time=30; rdbms_time=13; rdbms_count=4 | |
| ==> /var/log/chef-server/nginx/access.log <== | |
| 10.187.255.155 - - [29/Jan/2014:14:04:46 -0600] "GET /nodes/dc2ctscomqa01.mgmt.sdirect HTTP/1.1" 200 "0.006" 6543 "-" "Chef Client/11.6.0 (ruby-1.9.3-p429; ohai-6.18.0; x86_64-linux; +http://opscode.com)" "127.0.0.1:8000" "200" "0.006" "11.6.0" "algorithm=sha1;version=1.0;" "dc2ctscomqa01.mgmt.sdirect" "2014-01-29T20:04:40Z" "2jmj7l5rSw0yVb/vlWAYkK/YBwk=" 980 | |
| 10.187.255.155 - - [29/Jan/2014:14:04:46 -0600] "GET /roles/base HTTP/1.1" 200 "0.004" 416 "-" "Chef Client/11.6.0 (ruby-1.9.3-p429; ohai-6.18.0; x86_64-linux; +http://opscode.com)" "127.0.0.1:8000" "200" "0.004" "11.6.0" "algorithm=sha1;version=1.0;" "dc2ctscomqa01.mgmt.sdirect" "2014-01-29T20:04:40Z" "2jmj7l5rSw0yVb/vlWAYkK/YBwk=" 958 | |
| 10.187.255.155 - - [29/Jan/2014:14:04:46 -0600] "GET /environments/qa HTTP/1.1" 200 "0.004" 426 "-" "Chef Client/11.6.0 (ruby-1.9.3-p429; ohai-6.18.0; x86_64-linux; +http://opscode.com)" "127.0.0.1:8000" "200" "0.004" "11.6.0" "algorithm=sha1;version=1.0;" "dc2ctscomqa01.mgmt.sdirect" "2014-01-29T20:04:40Z" "2jmj7l5rSw0yVb/vlWAYkK/YBwk=" 963 | |
| 10.187.255.155 - - [29/Jan/2014:14:04:46 -0600] "POST /reports/nodes/dc2ctscomqa01.mgmt.sdirect/runs HTTP/1.1" 404 "0.039" 173 "-" "Chef Client/11.6.0 (ruby-1.9.3-p429; ohai-6.18.0; x86_64-linux; +http://opscode.com)" "127.0.0.1:8000" "404" "0.001" "11.6.0" "algorithm=sha1;version=1.0;" "dc2ctscomqa01.mgmt.sdirect" "2014-01-29T20:04:40Z" "09lkxt8P5f2HZgqpBe8nZpVAPY0=" 1195 | |
| ==> /var/log/chef-server/erchef/erchef.log.1 <== | |
| 2014-01-29T20:04:46Z [email protected] INFO req_id=mDSzJ3QkAP1c3WsyHznsiQ==; status=200; method=GET; path=/nodes/dc2ctscomqa01.mgmt.sdirect; user=dc2ctscomqa01.mgmt.sdirect; msg=[]; req_time=3; rdbms_time=1; rdbms_count=2 | |
| 2014-01-29T20:04:46Z [email protected] INFO req_id=yvWa643ajrEgbwSf4TIUmA==; status=200; method=GET; path=/roles/base; user=dc2ctscomqa01.mgmt.sdirect; msg=[]; req_time=2; rdbms_time=0; rdbms_count=2 | |
| 2014-01-29T20:04:46Z [email protected] INFO req_id=BYdGM+SgZf1dxVManvxn2w==; status=200; method=GET; path=/environments/qa; user=dc2ctscomqa01.mgmt.sdirect; msg=[]; req_time=2; rdbms_time=0; rdbms_count=2 | |
| ==> /var/log/chef-server/chef-solr/current <== | |
| 2014-01-29_20:05:35.31031 Jan 29, 2014 2:05:35 PM org.apache.solr.update.DirectUpdateHandler2 commit | |
| 2014-01-29_20:05:35.31035 INFO: start commit(optimize=false,waitFlush=true,waitSearcher=true,expungeDeletes=false) | |
| 2014-01-29_20:05:35.38302 Jan 29, 2014 2:05:35 PM org.apache.solr.core.SolrDeletionPolicy onCommit | |
| 2014-01-29_20:05:35.38304 INFO: SolrDeletionPolicy.onCommit: commits:num=2 | |
| 2014-01-29_20:05:35.38304 commit{dir=/var/opt/chef-server/chef-solr/data/index,segFN=segments_j,version=1391020345542,generation=19,filenames=[_7_1.del, _9.tis, _8.tis, _d.tii, _1.frq, _a.tii, _e.frq, _9.tii, _3.fdt, _2.tii, _c.tii, _7.fnm, _4.frq, _7.tis, _c.tis, _7.nrm, _c.nrm, _d.tis, _a.tis, _g.fdt, _d.frq, _a.prx, _g.fdx, _2.prx, _9.prx, _5_2.del, _c.prx, _7.tii, _8.frq, _2.fdt, _2.frq, _9.fdt, _7.fdx, segments_j, _2.fdx, _6_1.del, _9.fdx, _7.fdt, _f.fdt, _1.fdx, _f.fdx, _2.tis, _g.nrm, _8.tii, _1.fdt, _0.frq, _6.fdt, _c.frq, _2.nrm, _a.fnm, _6.fdx, _e.fdx, _3.fnm, _6.tis, _e.fdt, _1.tii, _e.nrm, _g.prx, _2_2.del, _1.tis, _3_2.del, _9.fnm, _4.nrm, _6.tii, _5.frq, _g.frq, _d.prx, _d.fdx, _2.fnm, _b.frq, _3.fdx, _8.nrm, _d.fdt, _d.nrm, _6.fnm, _c.fnm, _a.nrm, _f.frq, _f.tis, _g.tis, _0.tis, _5.prx, _5.fdt, _a_1.del, _4.prx, _4.fnm, _c.fdx, _1.fnm, _8_1.del, _c.fdt, _4.fdx, _5.tis, _5.nrm, _g.tii, _7.frq, _9_1.del, _4_1.del, _f.tii, _e.fnm, _0.prx, _f.nrm, _3.nrm, _0.fnm, _a.frq, _d.fnm, _3.prx, _5.tii, _1.prx, _8.fnm, _f.prx, _0.tii, _e.prx, _1.nrm, _6.nrm, _3.tii, _3.frq, _9.nrm, _6.frq, _e.tis, _b.nrm, _a.fdt, _a.fdx, _e.tii, _g.fnm, _1_3.del, _4.tis, _4.tii, _0.nrm, _5.fnm, _b.prx, _b_2.del, _b.tis, _4.fdt, _9.frq, _b.tii, _7.prx, _8.prx, _f.fnm, _6.prx, _b.fnm, _5.fdx, _b.fdt, _0.fdx, _8.fdx, _b.fdx, _0.fdt, _3.tis, _8.fdt] | |
| 2014-01-29_20:05:35.38306 commit{dir=/var/opt/chef-server/chef-solr/data/index,segFN=segments_k,version=1391020345543,generation=20,filenames=[_7_1.del, _9.tis, _8.tis, _d.tii, _1.frq, _a.tii, _e.frq, _9.tii, _3.fdt, _2.tii, _c.tii, _7.fnm, _4.frq, _7.tis, _h.fdt, _c.tis, _7.nrm, _h.fdx, _c.nrm, _g_1.del, _d.tis, _a.tis, _g.fdt, _d.frq, _a.prx, _g.fdx, _2.prx, _9.prx, _5_2.del, _c.prx, _7.tii, _8.frq, _2.fdt, _2.frq, _9.fdt, segments_k, _7.fdx, _h.frq, _2.fdx, _6_1.del, _9.fdx, _7.fdt, _f.fdt, _1.fdx, _f.fdx, _2.tis, _g.nrm, _8.tii, _1.fdt, _0.frq, _6.fdt, _c.frq, _2.nrm, _a.fnm, _6.fdx, _e.fdx, _3.fnm, _6.tis, _e.fdt, _1.tii, _e.nrm, _g.prx, _2_2.del, _1.tis, _3_2.del, _9.fnm, _4.nrm, _6.tii, _5.frq, _g.frq, _d.prx, _d.fdx, _2.fnm, _b.frq, _3.fdx, _8.nrm, _d.fdt, _d.nrm, _6.fnm, _c.fnm, _a.nrm, _f.frq, _h.prx, _f.tis, _g.tis, _0.tis, _5.prx, _5.fdt, _a_1.del, _4.prx, _4.fnm, _h.nrm, _c.fdx, _1.fnm, _8_1.del, _c.fdt, _4.fdx, _5.tis, _5.nrm, _g.tii, _7.frq, _9_1.del, _4_1.del, _f.tii, _e.fnm, _0.prx, _f.nrm, _3.nrm, _h.fnm, _0.fnm, _a.frq, _d.fnm, _3.prx, _5.tii, _h.tis, _1.prx, _8.fnm, _f.prx, _0.tii, _h.tii, _e.prx, _1.nrm, _6.nrm, _3.tii, _3.frq, _9.nrm, _6.frq, _e.tis, _b.nrm, _a.fdt, _a.fdx, _e.tii, _g.fnm, _1_3.del, _4.tis, _4.tii, _0.nrm, _5.fnm, _b.prx, _b_2.del, _b.tis, _4.fdt, _9.frq, _b.tii, _7.prx, _8.prx, _f.fnm, _6.prx, _b.fnm, _5.fdx, _b.fdt, _0.fdx, _8.fdx, _b.fdx, _0.fdt, _3.tis, _8.fdt] | |
| 2014-01-29_20:05:35.38690 Jan 29, 2014 2:05:35 PM org.apache.solr.core.SolrDeletionPolicy updateCommits | |
| 2014-01-29_20:05:35.38691 INFO: newest commit = 1391020345543 | |
| 2014-01-29_20:05:35.38691 Jan 29, 2014 2:05:35 PM org.apache.solr.search.SolrIndexSearcher <init> | |
| 2014-01-29_20:05:35.38691 INFO: Opening Searcher@7021c000 main | |
| 2014-01-29_20:05:35.38705 Jan 29, 2014 2:05:35 PM org.apache.solr.update.DirectUpdateHandler2 commit | |
| 2014-01-29_20:05:35.38706 INFO: end_commit_flush | |
| 2014-01-29_20:05:35.38706 Jan 29, 2014 2:05:35 PM org.apache.solr.search.SolrIndexSearcher warm | |
| 2014-01-29_20:05:35.38706 INFO: autowarming Searcher@7021c000 main from Searcher@4d98cf9d main | |
| 2014-01-29_20:05:35.38706 fieldValueCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cumulative_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0} | |
| 2014-01-29_20:05:35.38727 Jan 29, 2014 2:05:35 PM org.apache.solr.search.SolrIndexSearcher warm | |
| 2014-01-29_20:05:35.38727 INFO: autowarming result for Searcher@7021c000 main | |
| 2014-01-29_20:05:35.38727 fieldValueCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cumulative_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0} | |
| 2014-01-29_20:05:35.38746 Jan 29, 2014 2:05:35 PM org.apache.solr.search.SolrIndexSearcher warm | |
| 2014-01-29_20:05:35.38747 INFO: autowarming Searcher@7021c000 main from Searcher@4d98cf9d main | |
| 2014-01-29_20:05:35.38747 filterCache{lookups=1,hits=0,hitratio=0.00,inserts=1,evictions=0,size=1,warmupTime=0,cumulative_lookups=14,cumulative_hits=0,cumulative_hitratio=0.00,cumulative_inserts=14,cumulative_evictions=0} | |
| 2014-01-29_20:05:35.38766 Jan 29, 2014 2:05:35 PM org.apache.solr.search.SolrIndexSearcher warm | |
| 2014-01-29_20:05:35.38767 INFO: autowarming result for Searcher@7021c000 main | |
| 2014-01-29_20:05:35.38767 filterCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=14,cumulative_hits=0,cumulative_hitratio=0.00,cumulative_inserts=14,cumulative_evictions=0} | |
| 2014-01-29_20:05:35.38785 Jan 29, 2014 2:05:35 PM org.apache.solr.search.SolrIndexSearcher warm | |
| 2014-01-29_20:05:35.38786 INFO: autowarming Searcher@7021c000 main from Searcher@4d98cf9d main | |
| 2014-01-29_20:05:35.38786 queryResultCache{lookups=2,hits=1,hitratio=0.50,inserts=1,evictions=0,size=1,warmupTime=0,cumulative_lookups=18,cumulative_hits=3,cumulative_hitratio=0.16,cumulative_inserts=15,cumulative_evictions=0} | |
| 2014-01-29_20:05:35.38807 Jan 29, 2014 2:05:35 PM org.apache.solr.search.SolrIndexSearcher warm | |
| 2014-01-29_20:05:35.38808 INFO: autowarming result for Searcher@7021c000 main | |
| 2014-01-29_20:05:35.38808 queryResultCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=18,cumulative_hits=3,cumulative_hitratio=0.16,cumulative_inserts=15,cumulative_evictions=0} | |
| 2014-01-29_20:05:35.38830 Jan 29, 2014 2:05:35 PM org.apache.solr.search.SolrIndexSearcher warm | |
| 2014-01-29_20:05:35.38830 INFO: autowarming Searcher@7021c000 main from Searcher@4d98cf9d main | |
| 2014-01-29_20:05:35.38831 documentCache{lookups=4,hits=3,hitratio=0.75,inserts=1,evictions=0,size=1,warmupTime=0,cumulative_lookups=68,cumulative_hits=35,cumulative_hitratio=0.51,cumulative_inserts=33,cumulative_evictions=0} | |
| 2014-01-29_20:05:35.38851 Jan 29, 2014 2:05:35 PM org.apache.solr.search.SolrIndexSearcher warm | |
| 2014-01-29_20:05:35.38851 INFO: autowarming result for Searcher@7021c000 main | |
| 2014-01-29_20:05:35.38852 documentCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=68,cumulative_hits=35,cumulative_hitratio=0.51,cumulative_inserts=33,cumulative_evictions=0} | |
| 2014-01-29_20:05:35.38871 Jan 29, 2014 2:05:35 PM org.apache.solr.core.QuerySenderListener newSearcher | |
| 2014-01-29_20:05:35.38872 INFO: QuerySenderListener sending requests to Searcher@7021c000 main | |
| 2014-01-29_20:05:35.38891 Jan 29, 2014 2:05:35 PM org.apache.solr.core.QuerySenderListener newSearcher | |
| 2014-01-29_20:05:35.38892 INFO: QuerySenderListener done. | |
| 2014-01-29_20:05:35.38916 Jan 29, 2014 2:05:35 PM org.apache.solr.core.SolrCore registerSearcher | |
| 2014-01-29_20:05:35.38916 INFO: [] Registered new searcher Searcher@7021c000 main | |
| 2014-01-29_20:05:35.38944 Jan 29, 2014 2:05:35 PM org.apache.solr.search.SolrIndexSearcher close | |
| 2014-01-29_20:05:35.38944 INFO: Closing Searcher@4d98cf9d main | |
| 2014-01-29_20:05:35.38944 fieldValueCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cumulative_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0} | |
| 2014-01-29_20:05:35.38945 filterCache{lookups=1,hits=0,hitratio=0.00,inserts=1,evictions=0,size=1,warmupTime=0,cumulative_lookups=14,cumulative_hits=0,cumulative_hitratio=0.00,cumulative_inserts=14,cumulative_evictions=0} | |
| 2014-01-29_20:05:35.38945 queryResultCache{lookups=2,hits=1,hitratio=0.50,inserts=1,evictions=0,size=1,warmupTime=0,cumulative_lookups=18,cumulative_hits=3,cumulative_hitratio=0.16,cumulative_inserts=15,cumulative_evictions=0} | |
| 2014-01-29_20:05:35.38945 documentCache{lookups=4,hits=3,hitratio=0.75,inserts=1,evictions=0,size=1,warmupTime=0,cumulative_lookups=68,cumulative_hits=35,cumulative_hitratio=0.51,cumulative_inserts=33,cumulative_evictions=0} | |
| q^Croot@dc2mgmtdpsqa01:/etc/chef-server# | |
| root@dc2mgmtdpsqa01:/etc/chef-server# | |
| root@dc2mgmtdpsqa01:/etc/chef-server# | |
| root@dc2mgmtdpsqa01:/etc/chef-server# chef-server-ctl stop | |
| ok: down: bookshelf: 0s, normally up | |
| ok: down: chef-expander: 0s, normally up | |
| ok: down: chef-server-webui: 0s, normally up | |
| ok: down: chef-solr: 1s, normally up | |
| ok: down: erchef: 0s, normally up | |
| ok: down: nginx: 0s, normally up | |
| ok: down: postgresql: 1s, normally up | |
| ok: down: rabbitmq: 0s, normally up | |
| root@dc2mgmtdpsqa01:/etc/chef-server# chef-server-ctl start | |
| ok: run: bookshelf: (pid 13255) 0s | |
| ok: run: chef-expander: (pid 13279) 1s | |
| ok: run: chef-server-webui: (pid 13284) 0s | |
| ok: run: chef-solr: (pid 13304) 0s | |
| ok: run: erchef: (pid 13337) 1s | |
| ok: run: nginx: (pid 13378) 0s | |
| ok: run: postgresql: (pid 13387) 1s | |
| ok: run: rabbitmq: (pid 13396) 0s | |
| root@dc2mgmtdpsqa01:/etc/chef-server# chef-server-ctl tail | |
| ==> /var/log/chef-server/erchef/erchef.log.1 <== | |
| 2014-01-29T20:02:36Z [email protected] INFO req_id=Rp5tKTW+oQwu/ZBv26CtdQ==; status=200; method=GET; path=/roles/base; user=dc2ctscomqa01.mgmt.sdirect; msg=[]; req_time=5; rdbms_time=1; rdbms_count=2 | |
| 2014-01-29T20:02:36Z [email protected] INFO req_id=FY8cNbaBVfLkmhXxQwiOSA==; status=200; method=GET; path=/environments/qa; user=dc2ctscomqa01.mgmt.sdirect; msg=[]; req_time=4; rdbms_time=1; rdbms_count=2 | |
| 2014-01-29T20:03:59Z [email protected] INFO req_id=d3yZuJ79+OrFeenKvURFxQ==; status=200; method=GET; path=/search/node?q=*:*&sort=X_CHEF_id_CHEF_X%20asc&start=0&rows=1000; user=phil; msg={search,1,1,1}; req_time=6; rdbms_time=0; rdbms_count=3; solr_time=2; solr_count=1 | |
| 2014-01-29T20:04:24Z [email protected] INFO req_id=9KuRSgpFPBf89orbNzPqXw==; status=200; method=GET; path=/nodes/dc2ctscomqa01.mgmt.sdirect; user=phil; msg=[]; req_time=4; rdbms_time=0; rdbms_count=3 | |
| 2014-01-29T20:04:35Z [email protected] INFO req_id=1iXn5mnsq/tferM3b7vKxg==; status=200; method=PUT; path=/nodes/dc2ctscomqa01.mgmt.sdirect; user=phil; msg=[]; req_time=30; rdbms_time=13; rdbms_count=4 | |
| 2014-01-29T20:04:46Z [email protected] INFO req_id=mDSzJ3QkAP1c3WsyHznsiQ==; status=200; method=GET; path=/nodes/dc2ctscomqa01.mgmt.sdirect; user=dc2ctscomqa01.mgmt.sdirect; msg=[]; req_time=3; rdbms_time=1; rdbms_count=2 | |
| 2014-01-29T20:04:46Z [email protected] INFO req_id=yvWa643ajrEgbwSf4TIUmA==; status=200; method=GET; path=/roles/base; user=dc2ctscomqa01.mgmt.sdirect; msg=[]; req_time=2; rdbms_time=0; rdbms_count=2 | |
| 2014-01-29T20:04:46Z [email protected] INFO req_id=BYdGM+SgZf1dxVManvxn2w==; status=200; method=GET; path=/environments/qa; user=dc2ctscomqa01.mgmt.sdirect; msg=[]; req_time=2; rdbms_time=0; rdbms_count=2 | |
| 2014-01-29T20:08:29Z [email protected] INFO req_id=Q4+LThVgkHkAPFXKtSMPtg==; status=200; method=GET; path=/nodes/dc2ctscomqa01.mgmt.sdirect; user=phil; msg=[]; req_time=72; rdbms_time=46; rdbms_count=3 | |
| 2014-01-29T20:08:39Z [email protected] INFO req_id=uBf1edzBG3Qruw4hFBpIXQ==; status=200; method=PUT; path=/nodes/dc2ctscomqa01.mgmt.sdirect; user=phil; msg=[]; req_time=49; rdbms_time=3; rdbms_count=4 | |
| ==> /var/log/chef-server/erchef/erchef.log.idx <== | |
| ==> /var/log/chef-server/erchef/erchef.log.siz <== | |
| ==> /var/log/chef-server/erchef/current <== | |
| 2014-01-29_20:08:18.65959 {proc_lib,init_p_do_apply,3, | |
| 2014-01-29_20:08:18.65959 [{file,"proc_lib.erl"},{line,227}]}]}, | |
| 2014-01-29_20:08:18.65959 {connection_info, | |
| 2014-01-29_20:08:18.65959 {network,"127.0.0.1",5672, | |
| 2014-01-29_20:08:18.65960 {<<"chef">>, | |
| 2014-01-29_20:08:18.65960 <<"9351ae47f02a1e9943558e542787c4204f4e84f48a496d42c45fd6ccfd32e26c1d2d3c5b101bce2337d0783f4c5ad48d764d">>}, | |
| 2014-01-29_20:08:18.65960 <<"/chef">>}}} | |
| 2014-01-29_20:08:19.73487 | |
| 2014-01-29_20:08:19.73488 =INFO REPORT==== 29-Jan-2014::14:08:19 === | |
| 2014-01-29_20:08:19.73488 Negotiated maximums: (Channel = 0, Frame = 131072, Heartbeat = 0) | |
| ==> /var/log/chef-server/nginx/rewrite-port-80.log <== | |
| ==> /var/log/chef-server/nginx/access.log <== | |
| 10.12.217.3 - - [29/Jan/2014:14:04:24 -0600] "GET /nodes/dc2ctscomqa01.mgmt.sdirect HTTP/1.1" 200 "0.006" 6550 "-" "Chef Knife/11.8.2 (ruby-1.9.3-p484; ohai-6.20.0; x86_64-darwin11.2.0; +http://opscode.com)" "127.0.0.1:8000" "200" "0.006" "11.8.2" "algorithm=sha1;version=1.0;" "phil" "2014-01-29T20:04:24Z" "2jmj7l5rSw0yVb/vlWAYkK/YBwk=" 964 | |
| 10.12.217.3 - - [29/Jan/2014:14:04:35 -0600] "PUT /nodes/dc2ctscomqa01.mgmt.sdirect HTTP/1.1" 200 "0.141" 6543 "-" "Chef Knife/11.8.2 (ruby-1.9.3-p484; ohai-6.20.0; x86_64-darwin11.2.0; +http://opscode.com)" "127.0.0.1:8000" "200" "0.037" "11.8.2" "algorithm=sha1;version=1.0;" "phil" "2014-01-29T20:04:35Z" "c+QySmBAMTrDyLTFnjAihqkkh18=" 19868 | |
| 10.187.255.155 - - [29/Jan/2014:14:04:46 -0600] "GET /nodes/dc2ctscomqa01.mgmt.sdirect HTTP/1.1" 200 "0.006" 6543 "-" "Chef Client/11.6.0 (ruby-1.9.3-p429; ohai-6.18.0; x86_64-linux; +http://opscode.com)" "127.0.0.1:8000" "200" "0.006" "11.6.0" "algorithm=sha1;version=1.0;" "dc2ctscomqa01.mgmt.sdirect" "2014-01-29T20:04:40Z" "2jmj7l5rSw0yVb/vlWAYkK/YBwk=" 980 | |
| 10.187.255.155 - - [29/Jan/2014:14:04:46 -0600] "GET /roles/base HTTP/1.1" 200 "0.004" 416 "-" "Chef Client/11.6.0 (ruby-1.9.3-p429; ohai-6.18.0; x86_64-linux; +http://opscode.com)" "127.0.0.1:8000" "200" "0.004" "11.6.0" "algorithm=sha1;version=1.0;" "dc2ctscomqa01.mgmt.sdirect" "2014-01-29T20:04:40Z" "2jmj7l5rSw0yVb/vlWAYkK/YBwk=" 958 | |
| 10.187.255.155 - - [29/Jan/2014:14:04:46 -0600] "GET /environments/qa HTTP/1.1" 200 "0.004" 426 "-" "Chef Client/11.6.0 (ruby-1.9.3-p429; ohai-6.18.0; x86_64-linux; +http://opscode.com)" "127.0.0.1:8000" "200" "0.004" "11.6.0" "algorithm=sha1;version=1.0;" "dc2ctscomqa01.mgmt.sdirect" "2014-01-29T20:04:40Z" "2jmj7l5rSw0yVb/vlWAYkK/YBwk=" 963 | |
| 10.187.255.155 - - [29/Jan/2014:14:04:46 -0600] "POST /reports/nodes/dc2ctscomqa01.mgmt.sdirect/runs HTTP/1.1" 404 "0.039" 173 "-" "Chef Client/11.6.0 (ruby-1.9.3-p429; ohai-6.18.0; x86_64-linux; +http://opscode.com)" "127.0.0.1:8000" "404" "0.001" "11.6.0" "algorithm=sha1;version=1.0;" "dc2ctscomqa01.mgmt.sdirect" "2014-01-29T20:04:40Z" "09lkxt8P5f2HZgqpBe8nZpVAPY0=" 1195 | |
| 10.187.255.155 - - [29/Jan/2014:14:06:57 -0600] "POST /environments/qa/cookbook_versions HTTP/1.1" 502 "260.917" 172 "-" "Chef Client/11.6.0 (ruby-1.9.3-p429; ohai-6.18.0; x86_64-linux; +http://opscode.com)" "127.0.0.1:8000" "502" "260.879" "11.6.0" "algorithm=sha1;version=1.0;" "dc2ctscomqa01.mgmt.sdirect" "2014-01-29T20:02:30Z" "htSzEEmG345s5Lg2Z/u5Sxd2Ybo=" 1084 | |
| 10.187.255.155 - - [29/Jan/2014:14:06:57 -0600] "POST /environments/qa/cookbook_versions HTTP/1.1" 502 "130.651" 172 "-" "Chef Client/11.6.0 (ruby-1.9.3-p429; ohai-6.18.0; x86_64-linux; +http://opscode.com)" "127.0.0.1:8000" "502" "130.611" "11.6.0" "algorithm=sha1;version=1.0;" "dc2ctscomqa01.mgmt.sdirect" "2014-01-29T20:04:40Z" "9BB4C2UTT4tWSj0TyZ7CgzmB1GQ=" 1071 | |
| 10.12.217.3 - - [29/Jan/2014:14:08:29 -0600] "GET /nodes/dc2ctscomqa01.mgmt.sdirect HTTP/1.1" 200 "0.114" 6543 "-" "Chef Knife/11.8.2 (ruby-1.9.3-p484; ohai-6.20.0; x86_64-darwin11.2.0; +http://opscode.com)" "127.0.0.1:8000" "200" "0.114" "11.8.2" "algorithm=sha1;version=1.0;" "phil" "2014-01-29T20:08:29Z" "2jmj7l5rSw0yVb/vlWAYkK/YBwk=" 964 | |
| 10.12.217.3 - - [29/Jan/2014:14:08:39 -0600] "PUT /nodes/dc2ctscomqa01.mgmt.sdirect HTTP/1.1" 200 "0.191" 6542 "-" "Chef Knife/11.8.2 (ruby-1.9.3-p484; ohai-6.20.0; x86_64-darwin11.2.0; +http://opscode.com)" "127.0.0.1:8000" "200" "0.051" "11.8.2" "algorithm=sha1;version=1.0;" "phil" "2014-01-29T20:08:39Z" "5n3Ks0vnp0b4dwD6nuPNgDraUSM=" 19874 | |
| ==> /var/log/chef-server/nginx/current <== | |
| ==> /var/log/chef-server/nginx/error.log <== | |
| 2014/01/29 14:06:57 [error] 10998#0: *4773 upstream prematurely closed connection while reading response header from upstream, client: 10.187.255.155, server: dc2mgmtdpsqa01.mgmt.sdirect, request: "POST /environments/qa/cookbook_versions HTTP/1.1", upstream: "http://127.0.0.1:8000/environments/qa/cookbook_versions", host: "dc2mgmtdpsqa01.mgmt.sdirect:443" | |
| 2014/01/29 14:06:57 [error] 10998#0: *4789 upstream prematurely closed connection while reading response header from upstream, client: 10.187.255.155, server: dc2mgmtdpsqa01.mgmt.sdirect, request: "POST /environments/qa/cookbook_versions HTTP/1.1", upstream: "http://127.0.0.1:8000/environments/qa/cookbook_versions", host: "dc2mgmtdpsqa01.mgmt.sdirect:443" | |
| ==> /var/log/chef-server/chef-solr/current <== | |
| 2014-01-29_20:08:14.11802 INFO: [] Registered new searcher Searcher@3e643af4 main | |
| 2014-01-29_20:08:39.93788 Jan 29, 2014 2:08:39 PM org.apache.solr.core.SolrDeletionPolicy onInit | |
| 2014-01-29_20:08:39.93790 INFO: SolrDeletionPolicy.onInit: commits:num=1 | |
| 2014-01-29_20:08:39.93790 commit{dir=/var/opt/chef-server/chef-solr/data/index,segFN=segments_k,version=1391020345543,generation=20,filenames=[_7_1.del, _9.tis, _8.tis, _d.tii, _1.frq, _a.tii, _e.frq, _9.tii, _3.fdt, _2.tii, _c.tii, _7.fnm, _4.frq, _7.tis, _h.fdt, _c.tis, _7.nrm, _h.fdx, _c.nrm, _g_1.del, _d.tis, _a.tis, _g.fdt, _d.frq, _a.prx, _g.fdx, _2.prx, _9.prx, _5_2.del, _c.prx, _7.tii, _8.frq, _2.fdt, _2.frq, _9.fdt, segments_k, _7.fdx, _h.frq, _2.fdx, _6_1.del, _9.fdx, _7.fdt, _f.fdt, _1.fdx, _f.fdx, _2.tis, _g.nrm, _8.tii, _1.fdt, _0.frq, _6.fdt, _c.frq, _2.nrm, _a.fnm, _6.fdx, _e.fdx, _3.fnm, _6.tis, _e.fdt, _1.tii, _e.nrm, _g.prx, _2_2.del, _1.tis, _3_2.del, _9.fnm, _4.nrm, _6.tii, _5.frq, _g.frq, _d.prx, _d.fdx, _2.fnm, _b.frq, _3.fdx, _8.nrm, _d.fdt, _d.nrm, _6.fnm, _c.fnm, _a.nrm, _f.frq, _h.prx, _f.tis, _g.tis, _0.tis, _5.prx, _5.fdt, _a_1.del, _4.prx, _4.fnm, _h.nrm, _c.fdx, _1.fnm, _8_1.del, _c.fdt, _4.fdx, _5.tis, _5.nrm, _g.tii, _7.frq, _9_1.del, _4_1.del, _f.tii, _e.fnm, _0.prx, _f.nrm, _3.nrm, _h.fnm, _0.fnm, _a.frq, _d.fnm, _3.prx, _5.tii, _h.tis, _1.prx, _8.fnm, _f.prx, _0.tii, _h.tii, _e.prx, _1.nrm, _6.nrm, _3.tii, _3.frq, _9.nrm, _6.frq, _e.tis, _b.nrm, _a.fdt, _a.fdx, _e.tii, _g.fnm, _1_3.del, _4.tis, _4.tii, _0.nrm, _5.fnm, _b.prx, _b_2.del, _b.tis, _4.fdt, _9.frq, _b.tii, _7.prx, _8.prx, _f.fnm, _6.prx, _b.fnm, _5.fdx, _b.fdt, _0.fdx, _8.fdx, _b.fdx, _0.fdt, _3.tis, _8.fdt] | |
| 2014-01-29_20:08:39.93845 Jan 29, 2014 2:08:39 PM org.apache.solr.core.SolrDeletionPolicy updateCommits | |
| 2014-01-29_20:08:39.93847 INFO: newest commit = 1391020345543 | |
| 2014-01-29_20:08:39.99900 Jan 29, 2014 2:08:39 PM org.apache.solr.update.processor.LogUpdateProcessor finish | |
| 2014-01-29_20:08:39.99901 INFO: {add=[0000000000007381e308996ed183a5ce]} 0 155 | |
| 2014-01-29_20:08:39.99947 Jan 29, 2014 2:08:39 PM org.apache.solr.core.SolrCore execute | |
| 2014-01-29_20:08:39.99948 INFO: [] webapp=/solr path=/update params={} status=0 QTime=155 | |
| ==> /var/log/chef-server/rabbitmq/current <== | |
| 2014-01-29_20:08:16.40612 starting exchange, queue and binding recovery ...done | |
| 2014-01-29_20:08:18.94759 starting mirror queue slave sup ...done | |
| 2014-01-29_20:08:18.94792 starting adding mirrors to queues ...done | |
| 2014-01-29_20:08:18.95815 -- message delivery logic ready | |
| 2014-01-29_20:08:18.95824 starting error log relay ...done | |
| 2014-01-29_20:08:18.95861 starting networking ...done | |
| 2014-01-29_20:08:18.96455 starting direct_client ...done | |
| 2014-01-29_20:08:18.96476 starting notify cluster nodes ...done | |
| 2014-01-29_20:08:18.96486 | |
| 2014-01-29_20:08:18.96486 broker running | |
| ==> /var/log/chef-server/postgresql/current <== | |
| 2014-01-29_19:48:17.91715 VALUES ($1, $2) | |
| 2014-01-29_20:06:57.88397 received TERM from runit, sending INT instead to force quit connections | |
| 2014-01-29_20:06:57.88531 LOG: received fast shutdown request | |
| 2014-01-29_20:06:57.88532 LOG: aborting any active transactions | |
| 2014-01-29_20:06:57.88576 LOG: autovacuum launcher shutting down | |
| 2014-01-29_20:06:57.88606 LOG: shutting down | |
| 2014-01-29_20:06:57.89966 LOG: database system is shut down | |
| 2014-01-29_20:08:12.90036 LOG: database system was shut down at 2014-01-29 20:06:57 GMT | |
| 2014-01-29_20:08:12.90647 LOG: database system is ready to accept connections | |
| 2014-01-29_20:08:12.90711 LOG: autovacuum launcher started | |
| ==> /var/log/chef-server/chef-pedant/http-traffic.log <== | |
| -> "1b2\r\n" | |
| reading 434 bytes... | |
| -> "\x1F\x8B\b\x00\x00\x00\x00\x00\x00\x03e\x91Ko\xAA@\x00\x85\xFFJ\xC3\xD6\xDB\xA0hQ\xDC\xCD\x00\"\xA2\"\x14,\x98I\x1A\x10\x98\xC2\xC0\x002<\x9B\xFB\xDF\xAF\xED\xF6\x9E\xD5y$g\xF3}s4(bn\xCB\x11\x9A&\xF1\xC8\xFD\xE1\xAA6\xCC\xD3\xFB'y\x86-\xF7\xFA#\xA8j\xFA\xF9\xE5\xE2\xC2\xA3.\xBF\x18\xAA\xFF[\"z\xD2u\xA8g\xE0\f1\xA9\xBFH\xAAI\xFD\x1C\x02K\xDD\x01`\xCA\xC0\xDA\x80\x9F]\xC6\xC6\xD3\xAB\x80\x94jz\xA3\x88W\x8E\xA1\xA9\x89\x864`\xC7/\x11\xB5\xF1\xFA\xC3\xC9\x1Fm6#\xC7\xA6\xF6\x02;\r\xAD\x87!\xA7\x88oB\xD1\xEB\xA6\xCAZ\xAAB\xE7\x9C\xBA\xD1N\x16\xEF\xB30\xD0\xCD\bF\xF2\x9E`\xBFu\x11\x7F\xB8\xCE\x105\xC3\xD2\xBD\x0E\nNr\x90x\xF9\xD837k\xBC\xB9|>H\xC5ns\xF7\xC6\xF8\xB0<.JJMYu\x9E\xC7+v\x12\x95\xFE\x94\x10\xC4[m\x1F\xCE+\xA0#Z\xE1.\x13W\xCB\x9B\x14\xD5\x8D\xDCDv\xA5\xC3\xBA~\xFB(\x11\x1F?&m\x14\x9C\x83\xE6#\xBE\xCE\xCB\x90\xDD\xF1: \xD7<\t,\xD3Y\xF8\x82\x9Bx'\xB6\x97&D\x99\xC0V\xA4\en6\x9B\x8C\xBDU\xA7\x15\xF9zs\xAE\x97\"\x8Da\xA3\x05\xB5\x0E\x96\xDEx\xF7{\xB6\xA3\x98A\xFBNJ\xBF\x8F\x96\x87\xD0\xC5\x95c\xCB\x0Fe\x8Fhp^SY\x9DC\\\x80\x8BD\xAFyY\bC{\xD1|\xE2\x8DJ\xC16\x95)\xD4^\xC6\xF0<w\x83q\xEAD\x7FaE\x93\x82x\x91z\xA4\x05\xC6\xF8> \x9AY\xBA\x02,\x00\x11\xFD\x85\xA4\x9E\x95\xFF\xB9=\x19\aQ\x91Rn\x9B\x04y\x13\xFF\xFD\a\xDB7\xD3\xF0\x03\x02\x00\x00" | |
| read 434 bytes | |
| reading 2 bytes... | |
| -> "\r\n" | |
| read 2 bytes | |
| -> "0\r\n" | |
| -> "\r\n" | |
| Conn keep-alive | |
| ==> /var/log/chef-server/bookshelf/current <== | |
| 2014-01-29_20:08:10.56048 ** Found 0 name clashes in code paths | |
| 2014-01-29_20:08:10.57418 | |
| 2014-01-29_20:08:10.57419 =INFO REPORT==== 29-Jan-2014::14:08:10 === | |
| 2014-01-29_20:08:10.57419 bookshelf using config: [{ip,"127.0.0.1"}, | |
| 2014-01-29_20:08:10.57419 {port,4321}, | |
| 2014-01-29_20:08:10.57420 {log_dir,"/var/log/chef-server/bookshelf"}, | |
| 2014-01-29_20:08:10.57420 {disk_store,"/var/opt/chef-server/bookshelf/data/"}, | |
| 2014-01-29_20:08:10.57420 {stream_download,true}, | |
| 2014-01-29_20:08:10.57420 {access_key_id, | |
| 2014-01-29_20:08:10.57420 <<"d7066cf64651d53bd1049efc1349922971640773">>}] | |
| ==> /var/log/chef-server/chef-expander/current <== | |
| 2014-01-29_20:08:18.27951 from /opt/chef-server/embedded/service/chef-expander/lib/chef/expander/cluster_supervisor.rb:112:in `maintain_workers' | |
| 2014-01-29_20:08:18.27952 from /opt/chef-server/embedded/service/chef-expander/lib/chef/expander/cluster_supervisor.rb:68:in `start' | |
| 2014-01-29_20:08:18.27953 from /opt/chef-server/embedded/service/chef-expander/bin/chef-expander:29:in `<main>' | |
| 2014-01-29_20:08:19.27619 [Wed, 29 Jan 2014 14:08:19 -0600] ERROR: worker 1 (PID: 13560) died with status 1 | |
| 2014-01-29_20:08:19.27629 [Wed, 29 Jan 2014 14:08:19 -0600] ERROR: worker 2 (PID: 13563) died with status 1 | |
| 2014-01-29_20:08:19.27635 [Wed, 29 Jan 2014 14:08:19 -0600] INFO: Starting cluster worker 1 | |
| 2014-01-29_20:08:19.27728 [Wed, 29 Jan 2014 14:08:19 -0600] INFO: Starting cluster worker 2 | |
| 2014-01-29_20:08:19.29009 [Wed, 29 Jan 2014 14:08:19 -0600] INFO: Starting Consumers for vnodes 0-511 | |
| 2014-01-29_20:08:19.29248 [Wed, 29 Jan 2014 14:08:19 -0600] INFO: Starting Consumers for vnodes 512-1023 | |
| 2014-01-29_20:08:40.01170 [Wed, 29 Jan 2014 14:08:40 -0600] INFO: indexed node[0000000000007381e308996ed183a5ce] database[chef_00000000000000000000000000000000] transit,xml,solr-post | 1,0.02129960060119629,0.22336840629577637 | | |
| ==> /var/log/chef-server/chef-server-webui/current <== | |
| 2014-01-29_20:08:11.68058 I, [2014-01-29T14:08:11.680508 #13284] INFO -- : listening on addr=127.0.0.1:9462 fd=7 | |
| 2014-01-29_20:08:11.68080 I, [2014-01-29T14:08:11.680768 #13284] INFO -- : worker=0 spawning... | |
| 2014-01-29_20:08:11.68153 I, [2014-01-29T14:08:11.681477 #13284] INFO -- : worker=1 spawning... | |
| 2014-01-29_20:08:11.68197 I, [2014-01-29T14:08:11.681921 #13284] INFO -- : master process ready | |
| 2014-01-29_20:08:11.68254 I, [2014-01-29T14:08:11.682456 #13318] INFO -- : worker=0 spawned pid=13318 | |
| 2014-01-29_20:08:11.68262 I, [2014-01-29T14:08:11.682592 #13318] INFO -- : Refreshing Gem list | |
| 2014-01-29_20:08:11.68650 I, [2014-01-29T14:08:11.686412 #13320] INFO -- : worker=1 spawned pid=13320 | |
| 2014-01-29_20:08:11.68660 I, [2014-01-29T14:08:11.686563 #13320] INFO -- : Refreshing Gem list | |
| 2014-01-29_20:08:18.72372 I, [2014-01-29T14:08:18.723632 #13320] INFO -- : worker=1 ready | |
| 2014-01-29_20:08:18.78965 I, [2014-01-29T14:08:18.789568 #13318] INFO -- : worker=0 ready | |
| ==> /var/log/chef-server/nginx/access.log <== | |
| 10.187.255.155 - - [29/Jan/2014:14:08:50 -0600] "GET /nodes/dc2ctscomqa01.mgmt.sdirect HTTP/1.1" 200 "0.005" 6542 "-" "Chef Client/11.6.0 (ruby-1.9.3-p429; ohai-6.18.0; x86_64-linux; +http://opscode.com)" "127.0.0.1:8000" "200" "0.005" "11.6.0" "algorithm=sha1;version=1.0;" "dc2ctscomqa01.mgmt.sdirect" "2014-01-29T20:08:44Z" "2jmj7l5rSw0yVb/vlWAYkK/YBwk=" 980 | |
| 10.187.255.155 - - [29/Jan/2014:14:08:50 -0600] "GET /roles/base HTTP/1.1" 200 "0.005" 416 "-" "Chef Client/11.6.0 (ruby-1.9.3-p429; ohai-6.18.0; x86_64-linux; +http://opscode.com)" "127.0.0.1:8000" "200" "0.005" "11.6.0" "algorithm=sha1;version=1.0;" "dc2ctscomqa01.mgmt.sdirect" "2014-01-29T20:08:44Z" "2jmj7l5rSw0yVb/vlWAYkK/YBwk=" 958 | |
| 10.187.255.155 - - [29/Jan/2014:14:08:50 -0600] "POST /reports/nodes/dc2ctscomqa01.mgmt.sdirect/runs HTTP/1.1" 404 "0.043" 173 "-" "Chef Client/11.6.0 (ruby-1.9.3-p429; ohai-6.18.0; x86_64-linux; +http://opscode.com)" "127.0.0.1:8000" "404" "0.002" "11.6.0" "algorithm=sha1;version=1.0;" "dc2ctscomqa01.mgmt.sdirect" "2014-01-29T20:08:44Z" "0wAIx74wLJsb4ViDxVo0IwaJzrY=" 1195 | |
| ==> /var/log/chef-server/erchef/erchef.log.1 <== | |
| 2014-01-29T20:08:50Z [email protected] INFO req_id=YqRbI3V1zVratVYlGtdkdA==; status=200; method=GET; path=/nodes/dc2ctscomqa01.mgmt.sdirect; user=dc2ctscomqa01.mgmt.sdirect; msg=[]; req_time=4; rdbms_time=1; rdbms_count=2 | |
| 2014-01-29T20:08:50Z [email protected] INFO req_id=BVRYi569Z+DIsvl3xWdOWg==; status=200; method=GET; path=/roles/base; user=dc2ctscomqa01.mgmt.sdirect; msg=[]; req_time=3; rdbms_time=1; rdbms_count=2 | |
| ==> /var/log/chef-server/chef-solr/current <== | |
| 2014-01-29_20:09:39.94600 Jan 29, 2014 2:09:39 PM org.apache.solr.update.DirectUpdateHandler2 commit | |
| 2014-01-29_20:09:39.94603 INFO: start commit(optimize=false,waitFlush=true,waitSearcher=true,expungeDeletes=false) | |
| 2014-01-29_20:09:40.12046 Jan 29, 2014 2:09:40 PM org.apache.solr.core.SolrDeletionPolicy onCommit | |
| 2014-01-29_20:09:40.12048 INFO: SolrDeletionPolicy.onCommit: commits:num=2 | |
| 2014-01-29_20:09:40.12048 commit{dir=/var/opt/chef-server/chef-solr/data/index,segFN=segments_k,version=1391020345543,generation=20,filenames=[_7_1.del, _9.tis, _8.tis, _d.tii, _1.frq, _a.tii, _e.frq, _9.tii, _3.fdt, _2.tii, _c.tii, _7.fnm, _4.frq, _7.tis, _h.fdt, _c.tis, _7.nrm, _h.fdx, _c.nrm, _g_1.del, _d.tis, _a.tis, _g.fdt, _d.frq, _a.prx, _g.fdx, _2.prx, _9.prx, _5_2.del, _c.prx, _7.tii, _8.frq, _2.fdt, _2.frq, _9.fdt, segments_k, _7.fdx, _h.frq, _2.fdx, _6_1.del, _9.fdx, _7.fdt, _f.fdt, _1.fdx, _f.fdx, _2.tis, _g.nrm, _8.tii, _1.fdt, _0.frq, _6.fdt, _c.frq, _2.nrm, _a.fnm, _6.fdx, _e.fdx, _3.fnm, _6.tis, _e.fdt, _1.tii, _e.nrm, _g.prx, _2_2.del, _1.tis, _3_2.del, _9.fnm, _4.nrm, _6.tii, _5.frq, _g.frq, _d.prx, _d.fdx, _2.fnm, _b.frq, _3.fdx, _8.nrm, _d.fdt, _d.nrm, _6.fnm, _c.fnm, _a.nrm, _f.frq, _h.prx, _f.tis, _g.tis, _0.tis, _5.prx, _5.fdt, _a_1.del, _4.prx, _4.fnm, _h.nrm, _c.fdx, _1.fnm, _8_1.del, _c.fdt, _4.fdx, _5.tis, _5.nrm, _g.tii, _7.frq, _9_1.del, _4_1.del, _f.tii, _e.fnm, _0.prx, _f.nrm, _3.nrm, _h.fnm, _0.fnm, _a.frq, _d.fnm, _3.prx, _5.tii, _h.tis, _1.prx, _8.fnm, _f.prx, _0.tii, _h.tii, _e.prx, _1.nrm, _6.nrm, _3.tii, _3.frq, _9.nrm, _6.frq, _e.tis, _b.nrm, _a.fdt, _a.fdx, _e.tii, _g.fnm, _1_3.del, _4.tis, _4.tii, _0.nrm, _5.fnm, _b.prx, _b_2.del, _b.tis, _4.fdt, _9.frq, _b.tii, _7.prx, _8.prx, _f.fnm, _6.prx, _b.fnm, _5.fdx, _b.fdt, _0.fdx, _8.fdx, _b.fdx, _0.fdt, _3.tis, _8.fdt] | |
| 2014-01-29_20:09:40.12052 commit{dir=/var/opt/chef-server/chef-solr/data/index,segFN=segments_l,version=1391020345544,generation=21,filenames=[_7_1.del, _9.tis, _8.tis, _d.tii, _1.frq, _a.tii, _e.frq, _9.tii, _3.fdt, _2.tii, _c.tii, _7.fnm, _4.frq, _7.tis, _h.fdt, _c.tis, _7.nrm, _h.fdx, _c.nrm, _g_1.del, _d.tis, _a.tis, _g.fdt, _d.frq, _a.prx, _g.fdx, _2.prx, _9.prx, _5_2.del, _c.prx, _7.tii, _8.frq, _2.fdt, _2.frq, _9.fdt, _7.fdx, _h.frq, segments_l, _2.fdx, _6_1.del, _9.fdx, _7.fdt, _f.fdt, _1.fdx, _f.fdx, _2.tis, _g.nrm, _8.tii, _1.fdt, _0.frq, _6.fdt, _c.frq, _2.nrm, _a.fnm, _6.fdx, _e.fdx, _3.fnm, _6.tis, _e.fdt, _i.fdx, _1.tii, _i.fdt, _e.nrm, _g.prx, _2_2.del, _1.tis, _i.frq, _3_2.del, _9.fnm, _4.nrm, _6.tii, _5.frq, _g.frq, _d.prx, _d.fdx, _2.fnm, _b.frq, _3.fdx, _8.nrm, _d.fdt, _d.nrm, _6.fnm, _c.fnm, _a.nrm, _f.frq, _h.prx, _f.tis, _g.tis, _0.tis, _5.prx, _5.fdt, _a_1.del, _4.prx, _4.fnm, _h.nrm, _c.fdx, _1.fnm, _8_1.del, _i.tis, _c.fdt, _4.fdx, _5.tis, _5.nrm, _g.tii, _7.frq, _9_1.del, _i.tii, _4_1.del, _f.tii, _e.fnm, _0.prx, _f.nrm, _3.nrm, _h.fnm, _0.fnm, _a.frq, _d.fnm, _3.prx, _5.tii, _h.tis, _1.prx, _8.fnm, _f.prx, _0.tii, _h.tii, _e.prx, _1.nrm, _6.nrm, _i.prx, _h_1.del, _i.nrm, _3.tii, _3.frq, _9.nrm, _6.frq, _e.tis, _b.nrm, _a.fdt, _a.fdx, _e.tii, _g.fnm, _1_3.del, _4.tis, _4.tii, _0.nrm, _5.fnm, _b.prx, _b_2.del, _b.tis, _4.fdt, _9.frq, _b.tii, _7.prx, _8.prx, _f.fnm, _6.prx, _b.fnm, _5.fdx, _b.fdt, _0.fdx, _8.fdx, _i.fnm, _b.fdx, _0.fdt, _3.tis, _8.fdt] | |
| 2014-01-29_20:09:40.12103 Jan 29, 2014 2:09:40 PM org.apache.solr.core.SolrDeletionPolicy updateCommits | |
| 2014-01-29_20:09:40.12104 INFO: newest commit = 1391020345544 | |
| 2014-01-29_20:09:40.14604 Jan 29, 2014 2:09:40 PM org.apache.solr.search.SolrIndexSearcher <init> | |
| 2014-01-29_20:09:40.14605 INFO: Opening Searcher@736fbc5 main | |
| 2014-01-29_20:09:40.14833 Jan 29, 2014 2:09:40 PM org.apache.solr.search.SolrIndexSearcher warm | |
| 2014-01-29_20:09:40.14834 INFO: autowarming Searcher@736fbc5 main from Searcher@3e643af4 main | |
| 2014-01-29_20:09:40.14834 fieldValueCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cumulative_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0} | |
| 2014-01-29_20:09:40.14885 Jan 29, 2014 2:09:40 PM org.apache.solr.search.SolrIndexSearcher warm | |
| 2014-01-29_20:09:40.14886 INFO: autowarming result for Searcher@736fbc5 main | |
| 2014-01-29_20:09:40.14886 fieldValueCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cumulative_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0} | |
| 2014-01-29_20:09:40.14937 Jan 29, 2014 2:09:40 PM org.apache.solr.search.SolrIndexSearcher warm | |
| 2014-01-29_20:09:40.14938 INFO: autowarming Searcher@736fbc5 main from Searcher@3e643af4 main | |
| 2014-01-29_20:09:40.14938 filterCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cumulative_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0} | |
| 2014-01-29_20:09:40.14986 Jan 29, 2014 2:09:40 PM org.apache.solr.search.SolrIndexSearcher warm | |
| 2014-01-29_20:09:40.14987 INFO: autowarming result for Searcher@736fbc5 main | |
| 2014-01-29_20:09:40.14987 filterCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cumulative_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0} | |
| 2014-01-29_20:09:40.15042 Jan 29, 2014 2:09:40 PM org.apache.solr.search.SolrIndexSearcher warm | |
| 2014-01-29_20:09:40.15043 INFO: autowarming Searcher@736fbc5 main from Searcher@3e643af4 main | |
| 2014-01-29_20:09:40.15043 queryResultCache{lookups=0,hits=0,hitratio=0.00,inserts=2,evictions=0,size=2,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cumulative_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0} | |
| 2014-01-29_20:09:40.15093 Jan 29, 2014 2:09:40 PM org.apache.solr.search.SolrIndexSearcher warm | |
| 2014-01-29_20:09:40.15094 INFO: autowarming result for Searcher@736fbc5 main | |
| 2014-01-29_20:09:40.15094 queryResultCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cumulative_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0} | |
| 2014-01-29_20:09:40.15141 Jan 29, 2014 2:09:40 PM org.apache.solr.search.SolrIndexSearcher warm | |
| 2014-01-29_20:09:40.15142 INFO: autowarming Searcher@736fbc5 main from Searcher@3e643af4 main | |
| 2014-01-29_20:09:40.15142 documentCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cumulative_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0} | |
| 2014-01-29_20:09:40.15192 Jan 29, 2014 2:09:40 PM org.apache.solr.search.SolrIndexSearcher warm | |
| 2014-01-29_20:09:40.15193 INFO: autowarming result for Searcher@736fbc5 main | |
| 2014-01-29_20:09:40.15193 documentCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cumulative_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0} | |
| 2014-01-29_20:09:40.15274 Jan 29, 2014 2:09:40 PM org.apache.solr.update.DirectUpdateHandler2 commit | |
| 2014-01-29_20:09:40.15275 INFO: end_commit_flush | |
| 2014-01-29_20:09:40.15419 Jan 29, 2014 2:09:40 PM org.apache.solr.core.QuerySenderListener newSearcher | |
| 2014-01-29_20:09:40.15420 INFO: QuerySenderListener sending requests to Searcher@736fbc5 main | |
| 2014-01-29_20:09:40.15464 Jan 29, 2014 2:09:40 PM org.apache.solr.core.QuerySenderListener newSearcher | |
| 2014-01-29_20:09:40.15465 INFO: QuerySenderListener done. | |
| 2014-01-29_20:09:40.15514 Jan 29, 2014 2:09:40 PM org.apache.solr.core.SolrCore registerSearcher | |
| 2014-01-29_20:09:40.15515 INFO: [] Registered new searcher Searcher@736fbc5 main | |
| 2014-01-29_20:09:40.15865 Jan 29, 2014 2:09:40 PM org.apache.solr.search.SolrIndexSearcher close | |
| 2014-01-29_20:09:40.15866 INFO: Closing Searcher@3e643af4 main | |
| 2014-01-29_20:09:40.15867 fieldValueCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cumulative_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0} | |
| 2014-01-29_20:09:40.15867 filterCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cumulative_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0} | |
| 2014-01-29_20:09:40.15867 queryResultCache{lookups=0,hits=0,hitratio=0.00,inserts=2,evictions=0,size=2,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cumulative_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0} | |
| 2014-01-29_20:09:40.15867 documentCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cumulative_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0} | |
| ==> /var/log/chef-server/nginx/error.log <== | |
| 2014/01/29 14:13:50 [error] 13379#0: *11 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 10.187.255.155, server: dc2mgmtdpsqa01.mgmt.sdirect, request: "POST /environments/_default/cookbook_versions HTTP/1.1", upstream: "http://127.0.0.1:8000/environments/_default/cookbook_versions", host: "dc2mgmtdpsqa01.mgmt.sdirect:443" | |
| ==> /var/log/chef-server/nginx/access.log <== | |
| 10.187.255.155 - - [29/Jan/2014:14:13:50 -0600] "POST /environments/_default/cookbook_versions HTTP/1.1" 504 "300.099" 182 "-" "Chef Client/11.6.0 (ruby-1.9.3-p429; ohai-6.18.0; x86_64-linux; +http://opscode.com)" "127.0.0.1:8000" "504" "300.062" "11.6.0" "algorithm=sha1;version=1.0;" "dc2ctscomqa01.mgmt.sdirect" "2014-01-29T20:08:44Z" "9BB4C2UTT4tWSj0TyZ7CgzmB1GQ=" 1077 | |
| ==> /var/log/chef-server/nginx/error.log <== | |
| 2014/01/29 14:18:55 [error] 13379#0: *13 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 10.187.255.155, server: dc2mgmtdpsqa01.mgmt.sdirect, request: "POST /environments/_default/cookbook_versions HTTP/1.1", upstream: "http://127.0.0.1:8000/environments/_default/cookbook_versions", host: "dc2mgmtdpsqa01.mgmt.sdirect:443" | |
| ==> /var/log/chef-server/nginx/access.log <== | |
| 10.187.255.155 - - [29/Jan/2014:14:18:55 -0600] "POST /environments/_default/cookbook_versions HTTP/1.1" 504 "300.087" 182 "-" "Chef Client/11.6.0 (ruby-1.9.3-p429; ohai-6.18.0; x86_64-linux; +http://opscode.com)" "127.0.0.1:8000" "504" "300.048" "11.6.0" "algorithm=sha1;version=1.0;" "dc2ctscomqa01.mgmt.sdirect" "2014-01-29T20:08:44Z" "9BB4C2UTT4tWSj0TyZ7CgzmB1GQ=" 1077 | |
| ==> /var/log/chef-server/nginx/error.log <== | |
| 2014/01/29 14:24:00 [error] 13379#0: *15 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 10.187.255.155, server: dc2mgmtdpsqa01.mgmt.sdirect, request: "POST /environments/_default/cookbook_versions HTTP/1.1", upstream: "http://127.0.0.1:8000/environments/_default/cookbook_versions", host: "dc2mgmtdpsqa01.mgmt.sdirect:443" | |
| ==> /var/log/chef-server/nginx/access.log <== | |
| 10.187.255.155 - - [29/Jan/2014:14:24:00 -0600] "POST /environments/_default/cookbook_versions HTTP/1.1" 504 "300.098" 182 "-" "Chef Client/11.6.0 (ruby-1.9.3-p429; ohai-6.18.0; x86_64-linux; +http://opscode.com)" "127.0.0.1:8000" "504" "300.061" "11.6.0" "algorithm=sha1;version=1.0;" "dc2ctscomqa01.mgmt.sdirect" "2014-01-29T20:08:44Z" "9BB4C2UTT4tWSj0TyZ7CgzmB1GQ=" 1077 | |
| 10.187.255.155 - - [29/Jan/2014:14:24:06 -0600] "POST /environments/_default/cookbook_versions HTTP/1.1" 401 "0.077" 103 "-" "Chef Client/11.6.0 (ruby-1.9.3-p429; ohai-6.18.0; x86_64-linux; +http://opscode.com)" "127.0.0.1:8000" "401" "0.039" "11.6.0" "algorithm=sha1;version=1.0;" "dc2ctscomqa01.mgmt.sdirect" "2014-01-29T20:08:44Z" "9BB4C2UTT4tWSj0TyZ7CgzmB1GQ=" 1077 | |
| ==> /var/log/chef-server/erchef/erchef.log.1 <== | |
| 2014-01-29T20:24:06Z [email protected] INFO req_id=BvChybQaloXUV/1lyMhJSw==; status=401; method=POST; path=/environments/_default/cookbook_versions; user=dc2ctscomqa01.mgmt.sdirect; msg=bad_clock; req_time=34 |
have you looked into msg=bad_clock?
Did you ever find a solution to this? My coworkers and I are running up against this very same wall.
@philcryer @jquast @ccelebi @L2G
I'm experiencing the same problem. My theory is that there is some process, like cookbook dependency resolution, that is taking a really long time, and when that time reaches 15 minutes, the Chef Server erroneously concludes that the nodes clock is out of sync. This is what tipped me off.
erchef/erchef.log.5:2016-04-06T19:01:15Z [email protected] INFO req_id=fZ3GXdlCbxWJWm/bIXyVCA==; status=200; method=GET; path=/environments/redacted_environment_name; user=redacted-node-name.something.com; msg=[]; req_time=146; rdbms_time=110; rdbms_count=2
erchef/erchef.log.5:2016-04-06T19:16:38Z [email protected] INFO req_id=/oeZI0616OzWsFtnEU1/Xg==; status=401; method=POST; path=/environments/redacted_environment_name/cookbook_versions; user=redacted-node-name.something.com; msg=bad_clock; req_time=41
You'll notice that:
- The time difference between the two requests is just about 15 minutes.
- Each of the requests is for the cookbook_versions of a particular environment
I believe you can see the same in @philcryer 's message above as well if you look at both snippets from the erchef log. You'll notice cI'm going to try to set the Chef Server logging to more verbose and try to find out what process is taking so long. But I have a sneaking suspicion that it's related to Chef Server 11 itself and may get resolved with an upgrade to Chef Server 12.
@philcryer @jquast @ccelebi @L2G @coderanger
OK, I believe my suspicions are confirmed. Even though it's very difficult to gather the evidence, there is compelling reason to believe that the cookbook resolver is timing out, in a way, because of unresolvable cookbook dependencies. I was able to prove this by copying working cookbook_versions from a similar environment into the environment where this error was manifesting. After I did that, the node in question had a successful chef-client run with no clock drift error. My hope is that this type of error is better handled and reported in Chef Server 12 server.
Additionally, for anyone else that may be still experiencing this: Though the Chef Server error does not help much, what it does seem to reveal is that that set of cookbooks that exist on the Chef Server cannot resolve properly for the given run list. Pinning cookbook_versions in the environment is the only way they can resolve properly. Which means that when Chef Server tries to resolve with all the latest versions of each cookbook in the run list, it can't. This is just my opinion, but this is not a particularly acceptable situation, as you may want a dev environment to always use the latest version of a cookbook a leave its cookbook_versions completely unpinned.
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
think i'm having the same issue.
it sucks.