[Elastic Agent] Elastic Agent takes long to shut down #29650

AndersonQ · 2021-12-30T18:16:12Z

What does this PR do?

WIP:

The agent shuts down the applications concurrently
stop ignoring errors when stopping applications/services
set process (x-pack/elastic-agent/pkg/core/plugin/process/app.go) state to failure when it fails to stop
fix typos
add more logs: erros, info, debug

Why is it important?

It's part of the effort to support the new M1 Macs.

Checklist

My code follows the style guidelines of this project
I have commented my code, particularly in hard-to-understand areas
I have made corresponding changes to the documentation
I have made corresponding change to the default configuration files
I have added tests that prove my fix is effective or that my feature works
I have added an entry in CHANGELOG.next.asciidoc or CHANGELOG-developer.next.asciidoc.

Author's Checklist

do the TODOs
remove investigation logs
remove investigation changes

How to test this PR locally

Related issues

Closes [Elastic Agent] Elastic Agent takes long to shut down #27530

Screenshots

Logs

Before the fix:

[vagrant@archlinux elastic-agent-7.16.3-linux-x86_64]$ time sudo systemctl stop elastic-agent.service

real	1m30.173s
user	0m0.009s
sys	0m0.009s
[vagrant@archlinux elastic-agent-7.16.3-linux-x86_64]$

{"log.level":"info","@timestamp":"2022-01-24T16:01:15.460Z","log.origin":{"file.name":"cmd/run.go","file.line":184},"message":"Shutting down Elastic Agent and sending last events...","ecs.version":"1.6.0"}

[...]

{"log.level":"info","@timestamp":"2022-01-24T16:01:47.452Z","log.origin":{"file.name":"log/reporter.go","file.line":40},"message":"2022-01-24T16:01:47Z - message: Application: filebeat--7.16.3--36643631373035623733363936343635[8e074b30-f029-409d-869b-d5fd78181398]: State changed to DEGRADED: Missed last check-in - type: 'STATE' - sub_type: 'RUNNING'","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-01-24T16:01:55.497Z","log.origin":{"file.name":"process/app.go","file.line":176},"message":"Signaling application to stop because of shutdown: metricbeat--7.16.3","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-01-24T16:01:55.497Z","log.origin":{"file.name":"log/reporter.go","file.line":40},"message":"2022-01-24T16:01:55Z - message: Application: filebeat--7.16.3[8e074b30-f029-409d-869b-d5fd78181398]: State changed to STOPPED: Stopped - type: 'STATE' - sub_type: 'STOPPED'","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-01-24T16:02:35.547Z","log.origin":{"file.name":"process/app.go","file.line":176},"message":"Signaling application to stop because of shutdown: filebeat--7.16.3--36643631373035623733363936343635","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-01-24T16:02:35.547Z","log.origin":{"file.name":"log/reporter.go","file.line":40},"message":"2022-01-24T16:02:35Z - message: Application: metricbeat--7.16.3[8e074b30-f029-409d-869b-d5fd78181398]: State changed to STOPPED: Stopped - type: 'STATE' - sub_type: 'STOPPED'","ecs.version":"1.6.0"}

After the fix:

[vagrant@archlinux ~]$ time systemctl stop elastic-agent.service

[vagrant@archlinux ~]$ time systemctl stop elastic-agent.service

real	0m10.535s
user	0m0.008s
sys	0m0.007s
[vagrant@archlinux ~]$

{"log.level":"info","@timestamp":"2022-01-26T15:14:44.858Z","log.origin":{"file.name":"cmd/run.go","file.line":189},"message":"Shutting down Elastic Agent and sending last events...","ecs.version":"1.6.0"}

[...]

{"log.level":"error","@timestamp":"2022-01-26T15:14:45.359Z","log.origin":{"file.name":"process/app.go","file.line":290},"message":"failed to stop metricbeat: os: process already finished","ecs.version":"1.6.0"}
{"log.level":"error","@timestamp":"2022-01-26T15:14:45.359Z","log.origin":{"file.name":"process/app.go","file.line":290},"message":"failed to stop metricbeat_monitoring: os: process already finished","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-01-26T15:14:46.359Z","log.origin":{"file.name":"log/reporter.go","file.line":40},"message":"2022-01-26T15:14:46Z - message: Application: metricbeat--7.16.3-SNAPSHOT--36643631373035623733363936343635[0c1bba5c-6961-4c23-ae43-f4c8847a27c9]: State changed to STOPPED: Stopped - type: 'STATE' - sub_type: 'STOPPED'","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-01-26T15:14:46.359Z","log.origin":{"file.name":"log/reporter.go","file.line":40},"message":"2022-01-26T15:14:46Z - message: Application: metricbeat--7.16.3-SNAPSHOT[0c1bba5c-6961-4c23-ae43-f4c8847a27c9]: State changed to STOPPED: Stopped - type: 'STATE' - sub_type: 'STOPPED'","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-01-26T15:14:55.360Z","log.origin":{"file.name":"process/app.go","file.line":315},"message":"gracefulKill timed out after 10000000000, killing filebeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-01-26T15:14:55.360Z","log.origin":{"file.name":"process/app.go","file.line":315},"message":"gracefulKill timed out after 10000000000, killing filebeat_monitoring","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-01-26T15:14:55.360Z","log.origin":{"file.name":"log/reporter.go","file.line":40},"message":"2022-01-26T15:14:55Z - message: Application: filebeat--7.16.3-SNAPSHOT--36643631373035623733363936343635[0c1bba5c-6961-4c23-ae43-f4c8847a27c9]: State changed to STOPPED: Stopped - type: 'STATE' - sub_type: 'STOPPED'","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-01-26T15:14:55.360Z","log.origin":{"file.name":"log/reporter.go","file.line":40},"message":"2022-01-26T15:14:55Z - message: Application: filebeat--7.16.3-SNAPSHOT[0c1bba5c-6961-4c23-ae43-f4c8847a27c9]: State changed to STOPPED: Stopped - type: 'STATE' - sub_type: 'STOPPED'","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-01-26T15:14:55.361Z","log.origin":{"file.name":"application/managed_mode.go","file.line":319},"message":"Agent is stopped","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-01-26T15:14:55.361Z","log.origin":{"file.name":"cmd/run.go","file.line":197},"message":"Shutting down completed.","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-01-26T15:14:55.361Z","log.logger":"api","log.origin":{"file.name":"api/server.go","file.line":66},"message":"Stats endpoint (/opt/Elastic/Agent/data/tmp/elastic-agent.sock) finished: accept unix /opt/Elastic/Agent/data/tmp/elastic-agent.sock: use of closed network connection","ecs.version":"1.6.0"}

mergify · 2021-12-30T18:16:23Z

This pull request does not have a backport label. Could you fix it @AndersonQ? 🙏
To fixup this pull request, you need to add the backport labels for the needed
branches, such as:

backport-v./d./d./d is the label to automatically backport to the 7./d branch. /d is the digit

NOTE: backport-skip has been added to this pull request.

elasticmachine · 2021-12-30T18:38:32Z

💚 Build Succeeded

the below badges are clickable and redirect to their specific view in the CI or DOCS

Expand to view the summary

Build stats

Start Time: 2022-02-11T07:20:32.917+0000
Duration: 101 min 28 sec

Test stats 🧪

Test	Results
Failed	0
Passed	7232
Skipped	16
Total	7248

💚 Flaky test report

Tests succeeded.

🤖 GitHub comments

To re-run your PR in the CI, just comment with:

/test : Re-trigger the build.
/package : Generate the packages and run the E2E tests.
/beats-tester : Run the installation tests with beats-tester.
run elasticsearch-ci/docs : Re-trigger the docs validation. (use unformatted text in the comment!)

michalpristas · 2021-12-31T07:04:24Z

dev-tools/mage/crossbuild.go

-// Types is the list of package types
-var SelectedPackageTypes []PackageType
+// SelectedPackageTypes is the list of package types
+var SelectedPackageTypes []PackageType = []PackageType{TarGz}


windows does not have targz. careful and test on windows vm for sure

michalpristas · 2021-12-31T07:05:24Z

dev-tools/mage/build.go

 		LDFlags: []string{
-			"-s", // Strip all debug symbols from binary (does not affect Go stack traces).
+			// "-s", // Strip all debug symbols from binary (does not affect Go stack traces).


not sure having debug symbols on prod binaries was intended here

I'll remove it before the merge. Actually, I think if it could be configurable it'd valuable to have it in development mode

There is a "DEV" flag that exists in other places, it could be used to enable or not symbols?

beats/dev-tools/mage/settings.go

Lines 123 to 127 in a7f8517

DevBuild, err = strconv.ParseBool(EnvOr("DEV", "false"))

if err != nil {

panic(errors.Wrap(err, "failed to parse DEV env value"))

}

michalpristas · 2021-12-31T07:07:47Z

x-pack/elastic-agent/pkg/core/plugin/process/app.go

@@ -279,8 +289,13 @@ func (a *Application) gracefulKill(proc *process.Info) {
 		return
 	}

+	alog := logp.NewLogger("anderson")


reminder to remove this before merge

michalpristas · 2021-12-31T07:09:49Z

can you add some results from tests. how long it took before vs now after a change

jlind23 · 2022-01-17T14:36:05Z

@ph @AndersonQ could you please update this PR and make it move?

ph · 2022-01-17T16:24:17Z

Thanks @AndersonQ

elasticmachine · 2022-01-17T16:39:36Z

Pinging @elastic/elastic-agent-control-plane (Team:Elastic-Agent-Control-Plane)

ph

Added a few comments, is there enough existing test around shutdown?

ph · 2022-01-17T18:50:48Z

dev-tools/mage/build.go

 		LDFlags: []string{
-			"-s", // Strip all debug symbols from binary (does not affect Go stack traces).
+			// "-s", // Strip all debug symbols from binary (does not affect Go stack traces).


There is a "DEV" flag that exists in other places, it could be used to enable or not symbols?

beats/dev-tools/mage/settings.go

Lines 123 to 127 in a7f8517

DevBuild, err = strconv.ParseBool(EnvOr("DEV", "false"))

if err != nil {

panic(errors.Wrap(err, "failed to parse DEV env value"))

}

ph · 2022-01-17T18:55:13Z

x-pack/elastic-agent/pkg/agent/cmd/run.go

@@ -90,6 +91,8 @@ func run(streams *cli.IOStreams, override cfgOverrider) error {
 		return err
 	}

+	// TODO: remove before review
+	cfg.Settings.LoggingConfig.Level = logp.DebugLevel


@AndersonQ Oops, did you need to have the logging in test? while testing you can update the configuration to have it enable?

x-pack/elastic-agent/pkg/agent/operation/operator.go

ph · 2022-01-17T19:06:33Z

x-pack/elastic-agent/pkg/core/plugin/process/app.go

@@ -280,7 +286,9 @@ func (a *Application) gracefulKill(proc *process.Info) {
 	}

 	// send stop signal to request stop
-	proc.Stop()
+	if err := proc.Stop(); err != nil {
+		a.logger.Error(fmt.Errorf("failed to stop %s: %w", a.Name(), err))


Instead of calling fmt.Errorf( you can call a.logger.Errorf(

ph · 2022-01-17T19:07:40Z

x-pack/elastic-agent/pkg/core/plugin/service/app.go

@@ -275,6 +278,7 @@ func (a *Application) Stop() {
 func (a *Application) Shutdown() {
 	a.appLock.Lock()
 	defer a.appLock.Unlock()
+	a.logger.Infof("Signaling service to stop because of shutdown: %s", a.id)


s/Signaling/signaling Don't use capitalization when starting a logging statement.

ph · 2022-01-17T19:07:53Z

x-pack/elastic-agent/pkg/core/plugin/service/app.go

@@ -294,6 +298,7 @@ func (a *Application) Shutdown() {
 //
 // It updates the status of the application and handles restarting the application is needed.
 func (a *Application) OnStatusChange(s *server.ApplicationState, status proto.StateObserved_Status, msg string, payload map[string]interface{}) {
+


Extra space?

ph

Should have used request changes.

blakerouse

Need to fix the lock

x-pack/elastic-agent/pkg/agent/operation/operator.go

ph

Lets split build changes vs fixing the shutdow issue.

ph · 2022-01-20T21:01:07Z

dev-tools/mage/build.go

+		// Strip all debug symbols from binary (does not affect Go stack traces).
+		args.LDFlags = append(args.LDFlags, "-s")
+	}
+
 	return args


@AndersonQ Could you move this into his own pull request? Since this changes is not required for solving the "takes long to shutdown".

done: #29961

ph

Can you add a changelog entry?

…7530-long-shutdown

AndersonQ · 2022-01-31T14:06:16Z

@ph, @blakerouse could you re-review it please?

ph

@AndersonQ Changes LGTM, is there enough test coverage around that area of code? Can you investigate that? That the only thing that is preventing me from approving it.

x-pack/elastic-agent/CHANGELOG.next.asciidoc

x-pack/elastic-agent/pkg/agent/operation/operator.go

AndersonQ · 2022-02-01T16:20:42Z

@AndersonQ Changes LGTM, is there enough test coverage around that area of code? Can you investigate that? That the only thing that is preventing me from approving it.

not for the shutdown function. the coverage on the package isn't that great:

ok  	github.com/elastic/beats/v7/x-pack/elastic-agent/pkg/agent/operation	16.567s	coverage: 50.2% of statements

Well, I could do a manual test, compare the elastic and beats logs when shutting down to check that they shutdown successfully

ph · 2022-02-01T17:49:00Z

x-pack/elastic-agent/pkg/agent/transpiler/steps_test.go

@@ -120,6 +125,8 @@ func TestExecFile_StdOut(t *testing.T) {
 }

 func TestExecFile_NoOutput(t *testing.T) {
+	t.Skip("skipping failing tests")
+


@AndersonQ is this new? I haven't seen that in the original PR commits?

that's a mistake, the're failing on master as well... let me fix it

blakerouse

Looks good, lock is fixed! Thanks.

ph · 2022-02-02T19:40:43Z

Change LGTM thanks !

AndersonQ · 2022-02-10T13:45:43Z

/package

jlind23 · 2022-02-10T13:49:23Z

/test

jlind23 · 2022-02-10T16:58:05Z

@AndersonQ @ph the only issue left in the e2e testing repo is about the k8s autodiscover. Can we merge this PR then?

ph · 2022-02-10T19:39:19Z

@jlind23 LGTM, this would be 8.0 8.1 8.2?

mergify · 2022-02-10T21:11:44Z

This pull request is now in conflicts. Could you fix it? 🙏
To fixup this pull request, you can check out it locally. See documentation: https://help.github.com/articles/checking-out-pull-requests-locally/

git fetch upstream
git checkout -b 27530-long-shutdown upstream/27530-long-shutdown
git merge upstream/main
git push upstream 27530-long-shutdown

jlind23 · 2022-02-11T07:47:07Z

I would rather keep it in 8.2 only to avoid any side effect.

…into feature/use-with-kind-k8s-env * 'feature/use-with-kind-k8s-env' of github.com:v1v/beats: (52 commits) ci: home is declared within withBeatsEnv ci: use withKindEnv step ci: use getBranchesFromAliases and support next-patch-8 (elastic#30400) Update fields.yml (elastic#29609) Heartbeat: fix browser metrics and trace mappings (elastic#30258) Apply light edits to 8.0 changelog (elastic#30351) packetbeat/beater: make sure Npcap installation runs before interfaces are needed (elastic#30396) Add a ring-buffer reporter to libbeat (elastic#28750) Osquerybeat: Add install verification for osquerybeat (elastic#30388) update windows matrix support (elastic#30373) Refactor of metricbeat process-gathering metrics and system/process (elastic#30076) adjust next changelog wording (elastic#30371) [Metricbeat] azure: move event report into loop validDim loop (elastic#29945) fix: report GitHub Check before the cache (elastic#30372) Add support for non-unique keys in Kafka output headers (elastic#30369) ci: 6 major branch reached EOL (elastic#30357) reduce Elastic Agent shut down time by stopping processes concurrently (elastic#29650) [Filebeat] Add message to register encode/decode debug logs (elastic#30271) [libbeat] kafka message header support (elastic#29940) Heartbeat: set duration to zero for syntax errors (elastic#30227) ...

amolnater-qasource · 2022-02-28T11:13:49Z

Hi Team
Test results on 8.1 BC-4 for this PR has been shared at #27530 (comment)

UPDATE:
We will be validating the same on 8.2 Snapshot.

Thanks!

wip

2d123da

botelastic bot added the needs_team Indicates that the issue/PR needs a Team:* label label Dec 30, 2021

mergify bot added the backport-skip Skip notification from the automated backport with mergify label Dec 30, 2021

michalpristas reviewed Dec 31, 2021

View reviewed changes

jlind23 added the Team:Elastic-Agent-Control-Plane Label for the Agent Control Plane team label Jan 17, 2022

botelastic bot removed the needs_team Indicates that the issue/PR needs a Team:* label label Jan 17, 2022

remove debug stuff

82c3cdb

add TODO and restore style

65af2f6

AndersonQ marked this pull request as ready for review January 17, 2022 16:39

AndersonQ requested a review from a team as a code owner January 17, 2022 16:39

AndersonQ added 2 commits January 17, 2022 18:05

undo typo fixes, they will be fixed on another PR

5c5f418

undo

091fc25

ph reviewed Jan 17, 2022

View reviewed changes

ph suggested changes Jan 17, 2022

View reviewed changes

AndersonQ added 2 commits January 18, 2022 15:39

PR changes

1191569

keep debug symbols, no inline nor optimisations for dev builds

8d605e7

blakerouse requested changes Jan 18, 2022

View reviewed changes

x-pack/elastic-agent/pkg/agent/operation/operator.go Show resolved Hide resolved

pr change

89a5f59

ph suggested changes Jan 20, 2022

View reviewed changes

AndersonQ self-assigned this Jan 24, 2022

revert build flags and debug symbols

9dff80f

ph suggested changes Jan 25, 2022

View reviewed changes

AndersonQ added the bug label Jan 28, 2022

AndersonQ added 4 commits January 31, 2022 14:56

Merge branch 'master' into 27530-long-shutdown

6d254e9

Merge branch '27530-long-shutdown' of github.com:elastic/beats into 2…

13aa80c

…7530-long-shutdown

reset to master some files

5ca3cc2

checkout file to master

70d7b54

ph suggested changes Jan 31, 2022

View reviewed changes

x-pack/elastic-agent/CHANGELOG.next.asciidoc Outdated Show resolved Hide resolved

x-pack/elastic-agent/pkg/agent/operation/operator.go Show resolved Hide resolved

pr changes

e2b14d8

AndersonQ requested a review from ph February 1, 2022 16:25

ph reviewed Feb 1, 2022

View reviewed changes

don't skip tests

079d3e2

blakerouse approved these changes Feb 2, 2022

View reviewed changes

ph approved these changes Feb 2, 2022

View reviewed changes

Merge branch 'main' into 27530-long-shutdown

27e0e39

ph added backport-v8.2.0 Automated backport with mergify and removed backport-skip Skip notification from the automated backport with mergify labels Feb 11, 2022

AndersonQ merged commit 952c2eb into main Feb 14, 2022

AndersonQ deleted the 27530-long-shutdown branch February 14, 2022 09:25

AndersonQ mentioned this pull request Feb 14, 2022

[Elastic Agent] Adjust next changelog wording #30371

Merged

2 tasks

ph mentioned this pull request Feb 1, 2022

[Ingest Manager] elastic-agent process is not properly terminated after restart elastic/elastic-agent#127

Closed

	DevBuild, err = strconv.ParseBool(EnvOr("DEV", "false"))
	if err != nil {
	panic(errors.Wrap(err, "failed to parse DEV env value"))
	}

[Elastic Agent] Elastic Agent takes long to shut down #29650

[Elastic Agent] Elastic Agent takes long to shut down #29650

Conversation

AndersonQ commented Dec 30, 2021 • edited Loading

What does this PR do?

WIP:

Why is it important?

Checklist

Author's Checklist

How to test this PR locally

Related issues

Screenshots

Logs

Before the fix:

After the fix:

mergify bot commented Dec 30, 2021

elasticmachine commented Dec 30, 2021 • edited by jenkins-beats-ci bot Loading

💚 Build Succeeded

Build stats

Test stats 🧪

💚 Flaky test report

🤖 GitHub comments

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

michalpristas commented Dec 31, 2021

jlind23 commented Jan 17, 2022

ph commented Jan 17, 2022

elasticmachine commented Jan 17, 2022

ph left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ph left a comment

Choose a reason for hiding this comment

blakerouse left a comment

Choose a reason for hiding this comment

ph left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ph left a comment

Choose a reason for hiding this comment

AndersonQ commented Jan 31, 2022

ph left a comment

Choose a reason for hiding this comment

AndersonQ commented Feb 1, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

blakerouse left a comment

Choose a reason for hiding this comment

ph commented Feb 2, 2022

AndersonQ commented Feb 10, 2022

jlind23 commented Feb 10, 2022

jlind23 commented Feb 10, 2022

ph commented Feb 10, 2022

mergify bot commented Feb 10, 2022

jlind23 commented Feb 11, 2022

amolnater-qasource commented Feb 28, 2022 • edited Loading

AndersonQ commented Dec 30, 2021 •

edited

Loading

elasticmachine commented Dec 30, 2021 •

edited by jenkins-beats-ci bot

Loading

AndersonQ commented Feb 1, 2022 •

edited

Loading

amolnater-qasource commented Feb 28, 2022 •

edited

Loading