[8.1.0-SNAPSHOT] Fleet Server can't enroll: FAILED: Missed two check-ins

[mtojek]

Hi,

we adopted elastic-package to use predefined agent policies and confirmed with @juliaElastic that we're ready for switch (main branch is green).

Since yesterday we're facing problems with enrollment:

Attaching to elastic-package-stack_fleet-server_1
�[36mfleet-server_1               |�[0m Performing setup of Fleet in Kibana
�[36mfleet-server_1               |�[0m 
�[36mfleet-server_1               |�[0m {"log.level":"info","@timestamp":"2022-02-03T08:05:21.515Z","log.origin":{"file.name":"cmd/enroll_cmd.go","file.line":587},"message":"Spawning Elastic Agent daemon as a subprocess to complete bootstrap process.","ecs.version":"1.6.0"}
�[36mfleet-server_1               |�[0m {"log.level":"info","@timestamp":"2022-02-03T08:05:21.712Z","log.origin":{"file.name":"application/application.go","file.line":78},"message":"Detecting execution mode","ecs.version":"1.6.0"}
�[36mfleet-server_1               |�[0m {"log.level":"info","@timestamp":"2022-02-03T08:05:21.713Z","log.origin":{"file.name":"application/application.go","file.line":98},"message":"Agent is in Fleet Server bootstrap mode","ecs.version":"1.6.0"}
�[36mfleet-server_1               |�[0m {"log.level":"info","@timestamp":"2022-02-03T08:05:22.031Z","log.logger":"api","log.origin":{"file.name":"api/server.go","file.line":62},"message":"Starting stats endpoint","ecs.version":"1.6.0"}
�[36mfleet-server_1               |�[0m {"log.level":"info","@timestamp":"2022-02-03T08:05:22.031Z","log.origin":{"file.name":"application/fleet_server_bootstrap.go","file.line":134},"message":"Agent is starting","ecs.version":"1.6.0"}
�[36mfleet-server_1               |�[0m {"log.level":"info","@timestamp":"2022-02-03T08:05:22.031Z","log.logger":"api","log.origin":{"file.name":"api/server.go","file.line":64},"message":"Metrics endpoint listening on: /usr/share/elastic-agent/state/data/tmp/elastic-agent.sock (configured: unix:///usr/share/elastic-agent/state/data/tmp/elastic-agent.sock)","ecs.version":"1.6.0"}
�[36mfleet-server_1               |�[0m {"log.level":"info","@timestamp":"2022-02-03T08:05:22.034Z","log.origin":{"file.name":"application/fleet_server_bootstrap.go","file.line":144},"message":"Agent is stopped","ecs.version":"1.6.0"}
�[36mfleet-server_1               |�[0m {"log.level":"info","@timestamp":"2022-02-03T08:05:22.141Z","log.origin":{"file.name":"stateresolver/stateresolver.go","file.line":48},"message":"New State ID is Wb5PhdQX","ecs.version":"1.6.0"}
�[36mfleet-server_1               |�[0m {"log.level":"info","@timestamp":"2022-02-03T08:05:22.142Z","log.origin":{"file.name":"stateresolver/stateresolver.go","file.line":49},"message":"Converging state requires execution of 1 step(s)","ecs.version":"1.6.0"}
�[36mfleet-server_1               |�[0m {"log.level":"info","@timestamp":"2022-02-03T08:05:22.733Z","log.origin":{"file.name":"log/reporter.go","file.line":40},"message":"2022-02-03T08:05:22Z - message: Application: fleet-server--8.1.0-SNAPSHOT[]: State changed to STARTING: Starting - type: 'STATE' - sub_type: 'STARTING'","ecs.version":"1.6.0"}
�[36mfleet-server_1               |�[0m {"log.level":"info","@timestamp":"2022-02-03T08:05:22.735Z","log.origin":{"file.name":"stateresolver/stateresolver.go","file.line":66},"message":"Updating internal state","ecs.version":"1.6.0"}
�[36mfleet-server_1               |�[0m {"log.level":"info","@timestamp":"2022-02-03T08:05:24.523Z","log.origin":{"file.name":"cmd/enroll_cmd.go","file.line":792},"message":"Fleet Server - Starting","ecs.version":"1.6.0"}
�[36mfleet-server_1               |�[0m {"log.level":"warn","@timestamp":"2022-02-03T08:06:27.040Z","log.origin":{"file.name":"status/reporter.go","file.line":236},"message":"Elastic Agent status changed to: 'degraded'","ecs.version":"1.6.0"}
�[36mfleet-server_1               |�[0m {"log.level":"info","@timestamp":"2022-02-03T08:06:27.040Z","log.origin":{"file.name":"log/reporter.go","file.line":40},"message":"2022-02-03T08:06:27Z - message: Application: fleet-server--8.1.0-SNAPSHOT[]: State changed to DEGRADED: Missed last check-in - type: 'STATE' - sub_type: 'RUNNING'","ecs.version":"1.6.0"}
�[36mfleet-server_1               |�[0m {"log.level":"info","@timestamp":"2022-02-03T08:07:21.517Z","log.origin":{"file.name":"cmd/run.go","file.line":203},"message":"Shutting down Elastic Agent and sending last events...","ecs.version":"1.6.0"}
�[36mfleet-server_1               |�[0m {"log.level":"info","@timestamp":"2022-02-03T08:07:21.519Z","log.origin":{"file.name":"operation/operator.go","file.line":223},"message":"waiting for installer of pipeline 'default' to finish","ecs.version":"1.6.0"}
�[36mfleet-server_1               |�[0m {"log.level":"info","@timestamp":"2022-02-03T08:07:21.520Z","log.origin":{"file.name":"process/app.go","file.line":176},"message":"Signaling application to stop because of shutdown: fleet-server--8.1.0-SNAPSHOT","ecs.version":"1.6.0"}
�[36mfleet-server_1               |�[0m {"log.level":"error","@timestamp":"2022-02-03T08:07:27.047Z","log.origin":{"file.name":"status/reporter.go","file.line":236},"message":"Elastic Agent status changed to: 'error'","ecs.version":"1.6.0"}
�[36mfleet-server_1               |�[0m {"log.level":"error","@timestamp":"2022-02-03T08:07:27.047Z","log.origin":{"file.name":"log/reporter.go","file.line":36},"message":"2022-02-03T08:07:27Z - message: Application: fleet-server--8.1.0-SNAPSHOT[]: State changed to FAILED: Missed two check-ins - type: 'ERROR' - sub_type: 'FAILED'","ecs.version":"1.6.0"}
�[36mfleet-server_1               |�[0m {"log.level":"info","@timestamp":"2022-02-03T08:07:51.570Z","log.origin":{"file.name":"status/reporter.go","file.line":236},"message":"Elastic Agent status changed to: 'online'","ecs.version":"1.6.0"}
�[36mfleet-server_1               |�[0m {"log.level":"info","@timestamp":"2022-02-03T08:07:51.570Z","log.origin":{"file.name":"log/reporter.go","file.line":40},"message":"2022-02-03T08:07:51Z - message: Application: fleet-server--8.1.0-SNAPSHOT[]: State changed to STOPPED: Stopped - type: 'STATE' - sub_type: 'STOPPED'","ecs.version":"1.6.0"}
�[36mfleet-server_1               |�[0m {"log.level":"info","@timestamp":"2022-02-03T08:07:51.570Z","log.origin":{"file.name":"cmd/run.go","file.line":211},"message":"Shutting down completed.","ecs.version":"1.6.0"}
�[36mfleet-server_1               |�[0m {"log.level":"info","@timestamp":"2022-02-03T08:07:51.570Z","log.logger":"api","log.origin":{"file.name":"api/server.go","file.line":66},"message":"Stats endpoint (/usr/share/elastic-agent/state/data/tmp/elastic-agent.sock) finished: accept unix /usr/share/elastic-agent/state/data/tmp/elastic-agent.sock: use of closed network connection","ecs.version":"1.6.0"}
�[36mfleet-server_1               |�[0m Error: fleet-server failed: context canceled
�[36mfleet-server_1               |�[0m For help, please see our troubleshooting guide at https://www.elastic.co/guide/en/fleet/8.1/fleet-troubleshooting.html
�[36mfleet-server_1               |�[0m Error: enrollment failed: exit status 1
�[36mfleet-server_1               |�[0m For help, please see our troubleshooting guide at https://www.elastic.co/guide/en/fleet/8.1/fleet-troubleshooting.html

More logs: https://beats-ci.elastic.co/job/Ingest-manager/job/integrations/job/main/98/artifact/build/elastic-stack-dump/synthetics/logs/

It affects the Integrations main branch, incl. synthetics, containerd, etc.

Steps to reproduce:

elastic-package stack update -v -d --version 8.1.0-SNAPSHOT
elastic-package stack up -v -d --version 8.1.0-SNAPSHOT

Thanks for any help with investigating this problem.

cc @jlind23 @joshdover

[joshdover]

Curious that there's no logs from Fleet server related to the policy it selected.

One possible workaround could be to add FLEET_SERVER_POLICY_ID=fleet-server-managed-ep to the env vars for Fleet Server here: https://github.com/elastic/elastic-package/blob/main/internal/profile/_static/docker-compose-stack.yml#L79

But we should figure out what the root issue here is regardless of if the workaround works.

[mtojek]

Hey @joshdover, we tried it with Julia while working on migration to hosted policies. With FLEET_SERVER_POLICY_ID=fleet-server-managed-ep it will break compatibility with 7.x stack. If it isn't really necessary, I would postpone introducing this env. Otherwise, we'll have to implement some hack/forked stack.

[mtojek]

We did some investigation and it seems that the root cause is in the Elastic Agent Docker image. The last stable one we managed to build is this one: elastic/elastic-package#683 (@sha256:a5c580573376d65ed2eba92d359b411cdae4bf52745af8e3bb8c0c91f8ce53a5).

It maps onto:

elastic-agent@cd978fd268e2:~$ ./elastic-agent diagnostics
elastic-agent  version: 8.1.0
               build_commit: 56b227d00945ae97d7e8663df048c29f311b8894  build_time: 2022-02-01 07:01:00 +0000 UTC  snapshot_build: true
Applications:
  *  name: metricbeat  route_key: default
     error: Get "http://unix/": dial unix /usr/share/elastic-agent/state/data/tmp/default/metricbeat/metricbeat.sock: connect: no such file or directory

[mtojek]

We suspect that problem might have been introduced with this PR: elastic/beats#29031

cc @ph @blakerouse

[ph]

I will take a look, but I think the PR you have is the only major thing that I know that could have impact the agent.

[juliaElastic]

@criamico @mtojek this change might be related as well: elastic/kibana#108252

when starting elastic-package locally, I see this in fleet-server logs:
Kibana Fleet setup failed: http POST request to http://kibana:5601/api/fleet/setup fails: Forbidden: <nil>. Response: {"statusCode":403,"error":"Forbidden","message":"Forbidden"}

what is more, .fleet-agents index is not created, I have a suspicion that fleet-server might not have access to fleet API at all

[joshdover]

I don't think it's related to elastic/kibana#108252. I've been able to successfully run this on main without any issues as a manual test:

# Create new elastic/fleet-server token
curl --request POST \
  --url http://localhost:9200/_security/service/elastic/fleet-server/credential/token \
  -u elastic:changeme

# Copy token response into authz header below
curl --request POST \
  --url http://localhost:5601/api/fleet/setup \
  --header 'authorization: Bearer <token>' \
  --header 'content-type: application/json' \
  --header 'kbn-xsrf: x' 

Do we need to update the token that we're using? Maybe our manual hardcoded token isn't working anymore due to a change in ES?

[mtojek]

@joshdover In this PR I forced the specific Docker image for Elastic Agent and it passed. Elasticsearch, Kibana images were the same.