Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Log error if there are no event handlers registered #11280

Merged
merged 1 commit into from
Oct 14, 2021

Conversation

benbuzbee
Copy link
Contributor

We see this error all the time

no handler registered for event
event.Message=, event.Annotations=, event.Timestamp=0001-01-01T00:00:00Z, event.TaskName=, event.AllocID=, event.TaskID=,

So we're handling an even with all default fields. I noted that this can
happen if only err is set as in

func (d *driverPluginClient) handleTaskEvents(reqCtx context.Context, ch chan *TaskEvent, stream proto.Driver_TaskEventsClient) {
	defer close(ch)
	for {
		ev, err := stream.Recv()
		if err != nil {
			if err != io.EOF {
				ch <- &TaskEvent{
					Err: grpcutils.HandleReqCtxGrpcErr(err, reqCtx, d.doneCtx),
				}
			}

In this case Err fails to be serialized by the logger, see this test


	ev := &drivers.TaskEvent{
		Err: fmt.Errorf("errz"),
	}
	i.logger.Warn("ben test", "event", ev)
	i.logger.Warn("ben test2", "event err str", ev.Err.Error())
	i.logger.Warn("ben test3", "event err", ev.Err)
	ev.Err = nil
	i.logger.Warn("ben test4", "nil error", ev.Err)

2021-10-06T22:37:56.736Z INFO nomad.stdout {"@level":"warn","@message":"ben test","@module":"client.driver_mgr","@timestamp":"2021-10-06T22:37:56.643900Z","driver":"mock_driver","event":{"TaskID":"","TaskName":"","AllocID":"","Timestamp":"0001-01-01T00:00:00Z","Message":"","Annotations":null,"Err":{}}}
2021-10-06T22:37:56.736Z INFO nomad.stdout {"@level":"warn","@message":"ben test2","@module":"client.driver_mgr","@timestamp":"2021-10-06T22:37:56.644226Z","driver":"mock_driver","event err str":"errz"}
2021-10-06T22:37:56.736Z INFO nomad.stdout {"@level":"warn","@message":"ben test3","@module":"client.driver_mgr","@timestamp":"2021-10-06T22:37:56.644240Z","driver":"mock_driver","event err":"errz"}
2021-10-06T22:37:56.736Z INFO nomad.stdout {"@level":"warn","@message":"ben test4","@module":"client.driver_mgr","@timestamp":"2021-10-06T22:37:56.644252Z","driver":"mock_driver","nil error":null}

Note in the first example err is set to an empty object and the error is
lost.

What we want is the last two examples which call out the err field
explicitly so we can see what it is in this case

Copy link
Member

@jrasell jrasell left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM and thanks @benbuzbee! Would you be able to add the changelog entry as detailed in this documentation?

@jrasell jrasell added backport/1.0 stage/accepted Confirmed, and intend to work on. No timeline committment though. type/bug labels Oct 7, 2021
@jrasell jrasell self-assigned this Oct 7, 2021
We see this error all the time
```
no handler registered for event
event.Message=, event.Annotations=, event.Timestamp=0001-01-01T00:00:00Z, event.TaskName=, event.AllocID=, event.TaskID=,
```

So we're handling an even with all default fields. I noted that this can
happen if only err is set as in

```
func (d *driverPluginClient) handleTaskEvents(reqCtx context.Context, ch chan *TaskEvent, stream proto.Driver_TaskEventsClient) {
	defer close(ch)
	for {
		ev, err := stream.Recv()
		if err != nil {
			if err != io.EOF {
				ch <- &TaskEvent{
					Err: grpcutils.HandleReqCtxGrpcErr(err, reqCtx, d.doneCtx),
				}
			}
```

In this case Err fails to be serialized by the logger, see this test

```

	ev := &drivers.TaskEvent{
		Err: fmt.Errorf("errz"),
	}
	i.logger.Warn("ben test", "event", ev)
	i.logger.Warn("ben test2", "event err str", ev.Err.Error())
	i.logger.Warn("ben test3", "event err", ev.Err)
	ev.Err = nil
	i.logger.Warn("ben test4", "nil error", ev.Err)

2021-10-06T22:37:56.736Z INFO nomad.stdout {"@Level":"warn","@message":"ben test","@module":"client.driver_mgr","@timestamp":"2021-10-06T22:37:56.643900Z","driver":"mock_driver","event":{"TaskID":"","TaskName":"","AllocID":"","Timestamp":"0001-01-01T00:00:00Z","Message":"","Annotations":null,"Err":{}}}
2021-10-06T22:37:56.736Z INFO nomad.stdout {"@Level":"warn","@message":"ben test2","@module":"client.driver_mgr","@timestamp":"2021-10-06T22:37:56.644226Z","driver":"mock_driver","event err str":"errz"}
2021-10-06T22:37:56.736Z INFO nomad.stdout {"@Level":"warn","@message":"ben test3","@module":"client.driver_mgr","@timestamp":"2021-10-06T22:37:56.644240Z","driver":"mock_driver","event err":"errz"}
2021-10-06T22:37:56.736Z INFO nomad.stdout {"@Level":"warn","@message":"ben test4","@module":"client.driver_mgr","@timestamp":"2021-10-06T22:37:56.644252Z","driver":"mock_driver","nil error":null}
```

Note in the first example err is set to an empty object and the error is
lost.

What we want is the last two examples which call out the err field
explicitly so we can see what it is in this case
@benbuzbee
Copy link
Contributor Author

LGTM and thanks @benbuzbee! Would you be able to add the changelog entry as detailed in this documentation?

Sure I didn't see any other changes related to plugins so I made up the component name "client/plugins/drivermanager" let me know if I should use something else

@jrasell jrasell merged commit fa5addc into hashicorp:main Oct 14, 2021
@benbuzbee benbuzbee deleted the log-err branch October 15, 2021 17:29
lgfa29 pushed a commit that referenced this pull request Nov 15, 2021
Log error if there are no event handlers registered
lgfa29 pushed a commit that referenced this pull request Nov 15, 2021
Log error if there are no event handlers registered
@github-actions
Copy link

I'm going to lock this pull request because it has been closed for 120 days ⏳. This helps our maintainers find and focus on the active contributions.
If you have found a problem that seems related to this change, please open a new issue and complete the issue template so we can capture all the details necessary to investigate further.

@github-actions github-actions bot locked as resolved and limited conversation to collaborators Nov 10, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
stage/accepted Confirmed, and intend to work on. No timeline committment though. type/bug
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants