Getting non-fatal 400 posting to capture endpoint during initial converge in bootstrap

[Vasu1105]

Description

While doing knife bootstrap it gives following error
ERROR: Failed to post reporting data to server (HTTP 400), saving to c:/chef/cache/failed-reporting-data.json

This does not affect the bootstrap process though.
This probably should be the 404 error as I don't have any reporting enabled and there is no any configuration for Automate 2 also in my config file. It's a simple bootstrap.

Chef Version

Latest Chef 15 version

Platform Version

Windows-2012R2

Replication Case

Just run any knife bootstrap command and use latest Chef 15 release version for bootstrap.

knife bootstrap ec2-54-185-185-29.us-west-2.compute.amazonaws.com -o winrm --node-name vj-winrmssl --connection-user 'Administrator' --connection-password 'password' --connection-port 5986 --winrm-auth-method 'ssl' -c ~/workspace/chef-repo/.chef/knife.rb --bootstrap-version '15.0.293' --winrm-ssl -r 'recipe[windows_task::default]' --winrm-ssl-peer-fingerprint '<certificate-thumbpring>' -E developement -VV

Client Output

Stacktrace

[ec2-54-185-185-29.us-west-2.compute.amazonaws.com] resolving cookbooks for run list: ["windows_task::default"]
 [ec2-54-185-185-29.us-west-2.compute.amazonaws.com] Synchronizing Cookbooks:
 [ec2-54-185-185-29.us-west-2.compute.amazonaws.com]   - windows_task (0.1.0)
 [ec2-54-185-185-29.us-west-2.compute.amazonaws.com] Installing Cookbook Gems:
 [ec2-54-185-185-29.us-west-2.compute.amazonaws.com] Compiling Cookbooks...
 [ec2-54-185-185-29.us-west-2.compute.amazonaws.com] Converging 2 resources
 [ec2-54-185-185-29.us-west-2.compute.amazonaws.com] Recipe: windows_task::default
 [ec2-54-185-185-29.us-west-2.compute.amazonaws.com]   * windows_task[chef-client 1] action create
 [ec2-54-185-185-29.us-west-2.compute.amazonaws.com]     - windows_task[chef-client 1] task created
 [ec2-54-185-185-29.us-west-2.compute.amazonaws.com]   * windows_task[TestTask] action create (up to date)
DEBUG: [WinRM] Waiting for output...
DEBUG: [WinRM] Processing output
 [ec2-54-185-185-29.us-west-2.compute.amazonaws.com] 
 [ec2-54-185-185-29.us-west-2.compute.amazonaws.com] Running handlers:
 [ec2-54-185-185-29.us-west-2.compute.amazonaws.com] Running handlers complete
 [ec2-54-185-185-29.us-west-2.compute.amazonaws.com] Chef Infra Client finished, 1/2 resources updated in 11 seconds
 [ec2-54-185-185-29.us-west-2.compute.amazonaws.com] [2019-05-10T19:35:53+00:00] ERROR: Failed to post reporting data to server (HTTP 400), saving to c:/chef/cache/failed-reporting-data.json
DEBUG: [WinRM] cleaning up command_id: 9443BE5E-71B4-40BD-8283-E0111B2E469B on shell_id 58BB214A-3FA6-4C11-806A-606D2CF970CF
DEBUG: [WinRM] @ec2-54-185-185-29.us-west-2.compute.amazonaws.com<{:transport=>:ssl, :disable_sspi=>false, :basic_auth_only=>false, :endpoint=>"https://ec2-54-185-185-29.us-west-2.compute.amazonaws.com:5986/wsman", :user=>"Administrator", :password=>"<hidden>", :no_ssl_peer_verification=>false, :realm=>nil, :service=>nil, :ca_trust_file=>nil, :ssl_peer_fingerprint=>"B98C229959C37F95736F282692786AA8A747E691"}> (If (Test-Path "C:/Users/Administrator/AppData/Local/Temp/86836a04-07c4-4ff5-bd7d-e625bdea9a8f/bootstrap.bat") { Remove-Item -Force -Path "C:/Users/Administrator/AppData/Local/Temp/86836a04-07c4-4ff5-bd7d-e625bdea9a8f/bootstrap.bat" })
DEBUG: [WinRM] Command created for If (Test-Path "C:/Users/Administrator/AppData/Local/Temp/86836a04-07c4-4ff5-bd7d-e625bdea9a8f/bootstrap.bat") { Remove-Item -Force -Path "C:/Users/Administrator/AppData/Local/Temp/86836a04-07c4-4ff5-bd7d-e625bdea9a8f/bootstrap.bat" }
if (!$?) { if($LASTEXITCODE) { exit $LASTEXITCODE } else { exit 1 } } with id: 27BD1DEA-4F97-47BE-BC4D-61ED303B65F6
DEBUG: [WinRM] creating command_id: 27BD1DEA-4F97-47BE-BC4D-61ED303B65F6 on shell_id 58BB214A-3FA6-4C11-806A-606D2CF970CF
DEBUG: [WinRM] Waiting for output...
DEBUG: [WinRM] Processing output

[kvivek1115]

Facing the same issue on windows node with ssh connection with latest stable chef 15.0.193 node side.
Also, this issue is not reproduced on Ubuntu node.

Seems this is not something related to knife bootstrap it raised when chef-client trying to log the end run a report on chef server.
same code work if node having chef-14 version.

chef/lib/chef/resource_reporter.rb

Lines 152 to 154 in c6f3b11

	begin
	rest_client.raw_request(:POST, resource_history_url, headers({ "Content-Encoding" => "gzip" }), compressed_data)
	rescue StandardError => e

might be @lamont-granquist can guide us better on this?

Need to check the chef-server logs will try standalone setup of chef server and reproduce the issue.

Thanks

[kvivek1115]

Hey, I have tested with latest chef-server version 12.18.14 it works fine.

We have faced this issue only on manage.chef.io so might require to update chef-server version on chef-manage as well?

[Vasu1105]

@vsingh-msys yes I am also testing with hosted Chef.

[kmf]

I'm getting the same issues. Using the latest Automate.

[kvivek1115]

Hi @kmf, I have setup the latest chef-automate and configured data collector over chef-server. Seems works fine for Ubuntu node. could you please let me more detail about the ur automate setup and step that you followed to reproduce the issue?
Thanks

[kmf]

@vsingh-msys I'm using chef-server-core-12.17.33 / Automate 20190506101326 ...
I guess we'll upgrade out Chef Server :D

[kmf]

Upgraded, still the same issue.

[kmf]

Created another issue explaining the problem : #8557

[lamont-granquist]

so same as #8557 need to get -l trace data for this failure to see what automate is actually returning

[kvivek1115]

Hi @lamont-granquist Attached chef-client trace logs of hosted chef manage seems issue looks like
API params resources have invalid element {"error":["Invalid element in array value of 'resources'"]}

Running handlers:
[2019-05-20T08:51:52+00:00] INFO: Running report handlers
Running handlers complete
[2019-05-20T08:51:52+00:00] INFO: Report handlers complete
Chef Infra Client finished, 1/1 resources updated in 05 seconds
[2019-05-20T08:51:52+00:00] INFO: Sending resource update report (run-id: 210b13c6-a269-4aa5-95a5-376ca4a1f0bb)
[2019-05-20T08:51:52+00:00] TRACE: {"action"=>"end", "resources"=>[{"type"=>:log, "name"=>"Welcome to Chef, Sam Doe!", "
id"=>"Welcome to Chef, Sam Doe!", "after"=>{:message=>"Welcome to Chef, Sam Doe!", :level=>:info}, "before"=>{}, "durati
on"=>6, "delta"=>"", "result"=>"write", "cookbook_name"=>"starter", "cookbook_version"=>"1.0.0"}], "status"=>"success",
"run_list"=>"[\"recipe[starter::default]\"]", "total_res_count"=>"1", "data"=>{}, "start_time"=>"2019-05-20 08:51:51 UTC
", "end_time"=>"2019-05-20 08:51:52 +0000", "expanded_run_list"=>"{\"id\":\"_default\",\"run_list\":[{\"type\":\"recipe\
",\"name\":\"starter::default\",\"version\":null,\"skipped\":false}]}"}
[2019-05-20T08:51:52+00:00] TRACE: Sending compressed run data...
[2019-05-20T08:51:52+00:00] TRACE: Signing the request as azure-win
[2019-05-20T08:51:52+00:00] TRACE: String to sign: 'Method:POST
Hashed Path:foPSk9RlaTgwxHXJ+HKDZ42KLrQ=
X-Ops-Content-Hash:tUkFLcaTH7uZhxKJXfuy2Ei7nV0=
X-Ops-Timestamp:2019-05-20T08:51:52Z
X-Ops-UserId:dzP+WltTFevlGiKeCCwQO5NvXs8='
[2019-05-20T08:51:52+00:00] TRACE: Header hash: {"X-Ops-Sign"=>"algorithm=sha1;version=1.1;", "X-Ops-Userid"=>"azure-win
", "X-Ops-Timestamp"=>"2019-05-20T08:51:52Z", "X-Ops-Content-Hash"=>"tUkFLcaTH7uZhxKJXfuy2Ei7nV0=", "X-Ops-Authorization
-1"=>"hG8e2Sc+2IOoCnLD00KSehgrOomzN0SGPEDBB67eMURrNUZCyf7sHzbDKQIZ", "X-Ops-Authorization-2"=>"O7fu6F1dF83WRotQ4CfX7Cb8s
lRQtYHT4L3dCOc843rSKZOO0vWPBXhGERcR", "X-Ops-Authorization-3"=>"7ZQLtgunidKReac2SAE+DiM7DfQGmG6Mb7capqCBDrsCcDLRLOpxpoF7
HMIm", "X-Ops-Authorization-4"=>"5QFmGiBhZEYbSfcnuy+hmtmteS+unDtkdmIbpXKg6DPFFggmJr7Z5Gg1RaUq", "X-Ops-Authorization-5"=
>"9iaheMYJaom7ybHP9C73GRYDeGQDOM+d0apRbQ/ThzjTGJR7qMejMSHdfOjS", "X-Ops-Authorization-6"=>"HJenLYKXrpjAj7T52zKH64xbXNZyn
Zacq4lwRmb9xA=="}
[2019-05-20T08:51:52+00:00] TRACE: Initiating POST to https://api.chef.io/organizations/viveksingh_msys/reports/nodes/az
ure-win/runs/210b13c6-a269-4aa5-95a5-376ca4a1f0bb
[2019-05-20T08:51:52+00:00] TRACE: ---- HTTP Request Header Data: ----
[2019-05-20T08:51:52+00:00] TRACE: X-Ops-Reporting-Protocol-Version: 0.1.0
[2019-05-20T08:51:52+00:00] TRACE: Content-Encoding: gzip
[2019-05-20T08:51:52+00:00] TRACE: X-Ops-Server-API-Version: 1
[2019-05-20T08:51:52+00:00] TRACE: X-OPS-SIGN: algorithm=sha1;version=1.1;
[2019-05-20T08:51:52+00:00] TRACE: X-OPS-USERID: azure-win
[2019-05-20T08:51:52+00:00] TRACE: X-OPS-TIMESTAMP: 2019-05-20T08:51:52Z
[2019-05-20T08:51:52+00:00] TRACE: X-OPS-CONTENT-HASH: tUkFLcaTH7uZhxKJXfuy2Ei7nV0=
[2019-05-20T08:51:52+00:00] TRACE: X-OPS-AUTHORIZATION-1: hG8e2Sc+2IOoCnLD00KSehgrOomzN0SGPEDBB67eMURrNUZCyf7sHzbDKQIZ
[2019-05-20T08:51:52+00:00] TRACE: X-OPS-AUTHORIZATION-2: O7fu6F1dF83WRotQ4CfX7Cb8slRQtYHT4L3dCOc843rSKZOO0vWPBXhGERcR
[2019-05-20T08:51:52+00:00] TRACE: X-OPS-AUTHORIZATION-3: 7ZQLtgunidKReac2SAE+DiM7DfQGmG6Mb7capqCBDrsCcDLRLOpxpoF7HMIm
[2019-05-20T08:51:52+00:00] TRACE: X-OPS-AUTHORIZATION-4: 5QFmGiBhZEYbSfcnuy+hmtmteS+unDtkdmIbpXKg6DPFFggmJr7Z5Gg1RaUq
[2019-05-20T08:51:52+00:00] TRACE: X-OPS-AUTHORIZATION-5: 9iaheMYJaom7ybHP9C73GRYDeGQDOM+d0apRbQ/ThzjTGJR7qMejMSHdfOjS
[2019-05-20T08:51:52+00:00] TRACE: X-OPS-AUTHORIZATION-6: HJenLYKXrpjAj7T52zKH64xbXNZynZacq4lwRmb9xA==
[2019-05-20T08:51:52+00:00] TRACE: HOST: api.chef.io:443
[2019-05-20T08:51:52+00:00] TRACE: X-REMOTE-REQUEST-ID: 210b13c6-a269-4aa5-95a5-376ca4a1f0bb
[2019-05-20T08:51:52+00:00] TRACE: Content-Length: 340
[2019-05-20T08:51:52+00:00] TRACE: ---- End HTTP Request Header Data ----
[2019-05-20T08:51:53+00:00] TRACE: ---- HTTP Status and Header Data: ----
[2019-05-20T08:51:53+00:00] TRACE: HTTP 1.1 400 Bad Request
[2019-05-20T08:51:53+00:00] TRACE: date: Mon, 20 May 2019 08:51:51 GMT
[2019-05-20T08:51:53+00:00] TRACE: server: openresty/1.11.2.1
[2019-05-20T08:51:53+00:00] TRACE: content-length: 59
[2019-05-20T08:51:53+00:00] TRACE: connection: Close
[2019-05-20T08:51:53+00:00] TRACE: ---- End HTTP Status/Header Data ----
[2019-05-20T08:51:53+00:00] TRACE: ---- HTTP Response Body ----
[2019-05-20T08:51:53+00:00] TRACE: {"error":["Invalid element in array value of 'resources'"]}
[2019-05-20T08:51:53+00:00] TRACE: ---- End HTTP Response Body -----
[2019-05-20T08:51:53+00:00] TRACE: ---- HTTP Request Body ----
@v☺↔T#��<�ʧ�↑e:♂S♠G쬣���mtr��@☼�A↕�t►u���S☺��X{>�/�♠|�.���\��eo��]����ҙ:v�y��I↑e0→∟��O�/i♦�♦e
�ç�|J~�T�Q♥▲�tU�b'�r͡&6� � 1��Ѥ����L2��9L♦5K*��i��6e���jW�ao�{
j���m���"�D����j↑0���8�‼L?k��+Y☻  x��vf$
[2019-05-20T08:51:53+00:00] TRACE: ---- End HTTP Request Body ----
[2019-05-20T08:51:53+00:00] INFO: HTTP Request Returned 400 Bad Request:
[2019-05-20T08:51:53+00:00] ERROR: Failed to post reporting data to server (HTTP 400), saving to c:/chef/cache/failed-re
porting-data.json

[jeffbyrnes]

I can confirm that I’m seeing the same

TRACE: {"error":["Invalid element in array value of 'resources'"]}

as @vsingh-msys reports above with their trace-level logs.

Version info:

jeffbyrnes@aws-jb:/etc/datadog-agent$ chef-client -v
Chef Infra Client: 15.0.300

and I’m using Hosted Chef.

[xacaxulu]

+1

[glasschef]

This seems to be due to the duration field no longer using .to_i.to_s, so the non-stringified integer breaks the legacy Reporting ingestion:

https://github.com/chef/chef/blob/master/lib/chef/resource_reporter.rb#L38

[stellarsquall]

+1

Any bootstrap I perform with Hosted Chef using Chef 15 produces this result.

[lock]

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.