hashicorp / hashicorp/serf

Previously coalesced member events are being flushed repeatedly

Open
#555 0 comments 0 reactions 0 assignees View on GitHub
Dominant language
Go
Stars
6.1k
Forks
609
Avg merge
15h 1m
Merged PRs (30d)
3

Description

The response of 'Stream' command (in this case is used with '*' to subscribe to all events) on member-update event includes the most recent state of all members which have previously updated in the past, in addition to the member (or members) which actually updated at a given moment.

For example, a log of serf agent:

```
2019-02-27 08:45:39.267487500 ==> Starting Serf agent...
2019-02-27 08:45:39.267959500 ==> Starting Serf agent RPC...
2019-02-27 08:45:39.268066500 ==> Serf agent running!
2019-02-27 08:45:39.268102500 Node name: '81a3cf3c-74e5-4a74-885d-7724aa68f5cd'
2019-02-27 08:45:39.268138500 Bind addr: '172.18.0.5:7946'
2019-02-27 08:45:39.268171500 RPC addr: '127.0.0.1:7373'
2019-02-27 08:45:39.268204500 Encrypted: false
2019-02-27 08:45:39.268237500 Snapshot: false
2019-02-27 08:45:39.268270500 Profile: lan
2019-02-27 08:45:39.268290500
2019-02-27 08:45:39.268311500 ==> Log data will now stream in as it occurs:
2019-02-27 08:45:39.268329500
2019-02-27 08:45:39.268363500 2019/02/27 08:45:39 [INFO] agent: Serf agent starting
2019-02-27 08:45:39.268397500 2019/02/27 08:45:39 [INFO] serf: EventMemberJoin: 81a3cf3c-74e5-4a74-885d-7724aa68f5cd 172.18.0.5
2019-02-27 08:45:40.011342500 2019/02/27 08:45:40 [INFO] agent.ipc: Accepted client: 127.0.0.1:36932
2019-02-27 08:45:40.067295500 2019/02/27 08:45:40 [INFO] agent: joining: [0e28124e-45a6-41d9-bb36-89f7094d7e32] replay: false
2019-02-27 08:45:40.070284500 2019/02/27 08:45:40 [INFO] serf: EventMemberJoin: 6bcc89cf-83cb-4526-a498-dd4b51fd0773 172.18.0.2
2019-02-27 08:45:40.070292500 2019/02/27 08:45:40 [INFO] serf: EventMemberJoin: 9a2a2b72-aa60-44f9-9685-8e3fd27f4c70 172.18.0.3
2019-02-27 08:45:40.070294500 2019/02/27 08:45:40 [INFO] serf: EventMemberJoin: 0e28124e-45a6-41d9-bb36-89f7094d7e32 172.18.0.4
2019-02-27 08:45:40.070295500 2019/02/27 08:45:40 [INFO] agent: joined: 1 nodes
2019-02-27 08:45:40.687374500 2019/02/27 08:45:40 [INFO] serf: EventMemberUpdate: 81a3cf3c-74e5-4a74-885d-7724aa68f5cd
2019-02-27 08:45:41.687869500 2019/02/27 08:45:41 [INFO] agent: Received event: member-join
2019-02-27 08:45:41.687883500 2019/02/27 08:45:41 [INFO] agent: Received event: member-update
2019-02-27 08:45:50.598393500 2019/02/27 08:45:50 [INFO] serf: EventMemberUpdate: 9a2a2b72-aa60-44f9-9685-8e3fd27f4c70
2019-02-27 08:45:51.599014500 2019/02/27 08:45:51 [INFO] agent: Received event: member-update
2019-02-27 08:45:56.244448500 2019/02/27 08:45:56 [INFO] serf: EventMemberUpdate: 0e28124e-45a6-41d9-bb36-89f7094d7e32
2019-02-27 08:45:57.246343500 2019/02/27 08:45:57 [INFO] agent: Received event: member-update
```

and debug output of received members from stream responses:

```
2019-02-27 08:45:41.692734500 member-join
2019-02-27 08:45:41.695961500 [ { Addr: ,
2019-02-27 08:45:41.695970500 DelegateCur: 5,
2019-02-27 08:45:41.695971500 DelegateMax: 5,
2019-02-27 08:45:41.695972500 DelegateMin: 2,
2019-02-27 08:45:41.695977500 Name: '6bcc89cf-83cb-4526-a498-dd4b51fd0773',
2019-02-27 08:45:41.695979500 Port: 7946,
2019-02-27 08:45:41.695980500 ProtocolCur: 2,
2019-02-27 08:45:41.695981500 ProtocolMax: 5,
2019-02-27 08:45:41.695982500 ProtocolMin: 1,
2019-02-27 08:45:41.695983500 Status: 'alive',
2019-02-27 08:45:41.695984500 Tags: {} },
2019-02-27 08:45:41.695985500 { Addr: ,
2019-02-27 08:45:41.695986500 DelegateCur: 5,
2019-02-27 08:45:41.695986500 DelegateMax: 5,
2019-02-27 08:45:41.695987500 DelegateMin: 2,
2019-02-27 08:45:41.695988500 Name: '9a2a2b72-aa60-44f9-9685-8e3fd27f4c70',
2019-02-27 08:45:41.695989500 Port: 7946,
2019-02-27 08:45:41.695990500 ProtocolCur: 2,
2019-02-27 08:45:41.695991500 ProtocolMax: 5,
2019-02-27 08:45:41.695992500 ProtocolMin: 1,
2019-02-27 08:45:41.695992500 Status: 'alive',
2019-02-27 08:45:41.695993500 Tags:
2019-02-27 08:45:41.695994500 { ROLE: 'tests',
2019-02-27 08:45:41.695995500 TAG1: 'value1',
2019-02-27 08:45:41.695996500 TAG2: 'value2',
2019-02-27 08:45:41.695997500 ID: '9a2a2b72-aa60-44f9-9685-8e3fd27f4c70' } },
2019-02-27 08:45:41.695998500 { Addr: ,
2019-02-27 08:45:41.695999500 DelegateCur: 5,
2019-02-27 08:45:41.695999500 DelegateMax: 5,
2019-02-27 08:45:41.696000500 DelegateMin: 2,
2019-02-27 08:45:41.696001500 Name: '0e28124e-45a6-41d9-bb36-89f7094d7e32',
2019-02-27 08:45:41.696002500 Port: 7946,
2019-02-27 08:45:41.696003500 ProtocolCur: 2,
2019-02-27 08:45:41.696004500 ProtocolMax: 5,
2019-02-27 08:45:41.696004500 ProtocolMin: 1,
2019-02-27 08:45:41.696005500 Status: 'alive',
2019-02-27 08:45:41.696006500 Tags:
2019-02-27 08:45:41.696007500 { ID: '0e28124e-45a6-41d9-bb36-89f7094d7e32',
2019-02-27 08:45:41.696008500 ROLE: 'tests-peer' } } ]

2019-02-27 08:45:41.696024500 member-update
2019-02-27 08:45:41.696260500 [ { Addr: ,
2019-02-27 08:45:41.696266500 DelegateCur: 5,
2019-02-27 08:45:41.696267500 DelegateMax: 5,
2019-02-27 08:45:41.696268500 DelegateMin: 2,
2019-02-27 08:45:41.696269500 Name: '81a3cf3c-74e5-4a74-885d-7724aa68f5cd',
2019-02-27 08:45:41.696270500 Port: 7946,
2019-02-27 08:45:41.696271500 ProtocolCur: 2,
2019-02-27 08:45:41.696272500 ProtocolMax: 5,
2019-02-27 08:45:41.696273500 ProtocolMin: 1,
2019-02-27 08:45:41.696273500 Status: 'alive',
2019-02-27 08:45:41.696274500 Tags:
2019-02-27 08:45:41.696275500 { ROLE: 'tests-peer2',
2019-02-27 08:45:41.696276500 ID: '81a3cf3c-74e5-4a74-885d-7724aa68f5cd' } } ]

2019-02-27 08:45:51.602352500 member-update
2019-02-27 08:45:51.602667500 [ { Addr: ,
2019-02-27 08:45:51.602673500 DelegateCur: 5,
2019-02-27 08:45:51.602674500 DelegateMax: 5,
2019-02-27 08:45:51.602675500 DelegateMin: 2,
2019-02-27 08:45:51.602677500 Name: '9a2a2b72-aa60-44f9-9685-8e3fd27f4c70',
2019-02-27 08:45:51.602678500 Port: 7946,
2019-02-27 08:45:51.602679500 ProtocolCur: 2,
2019-02-27 08:45:51.602680500 ProtocolMax: 5,
2019-02-27 08:45:51.602681500 ProtocolMin: 1,
2019-02-27 08:45:51.602683500 Status: 'alive',
2019-02-27 08:45:51.602684500 Tags:
2019-02-27 08:45:51.602685500 { ID: '9a2a2b72-aa60-44f9-9685-8e3fd27f4c70',
2019-02-27 08:45:51.602686500 ROLE: 'tests' } },
2019-02-27 08:45:51.602687500 { Addr: ,
2019-02-27 08:45:51.602689500 DelegateCur: 5,
2019-02-27 08:45:51.602690500 DelegateMax: 5,
2019-02-27 08:45:51.602691500 DelegateMin: 2,
2019-02-27 08:45:51.602692500 Name: '81a3cf3c-74e5-4a74-885d-7724aa68f5cd',
2019-02-27 08:45:51.602693500 Port: 7946,
2019-02-27 08:45:51.602694500 ProtocolCur: 2,
2019-02-27 08:45:51.602695500 ProtocolMax: 5,
2019-02-27 08:45:51.602697500 ProtocolMin: 1,
2019-02-27 08:45:51.602698500 Status: 'alive',
2019-02-27 08:45:51.602699500 Tags:
2019-02-27 08:45:51.602700500 { ROLE: 'tests-peer2',
2019-02-27 08:45:51.602701500 ID: '81a3cf3c-74e5-4a74-885d-7724aa68f5cd' } } ]

2019-02-27 08:45:57.248237500 member-update
2019-02-27 08:45:57.249014500 [ { Addr: ,
2019-02-27 08:45:57.249036500 DelegateCur: 5,
2019-02-27 08:45:57.249037500 DelegateMax: 5,
2019-02-27 08:45:57.249039500 DelegateMin: 2,
2019-02-27 08:45:57.249040500 Name: '81a3cf3c-74e5-4a74-885d-7724aa68f5cd',
2019-02-27 08:45:57.249042500 Port: 7946,
2019-02-27 08:45:57.249044500 ProtocolCur: 2,
2019-02-27 08:45:57.249048500 ProtocolMax: 5,
2019-02-27 08:45:57.249050500 ProtocolMin: 1,
2019-02-27 08:45:57.249052500 Status: 'alive',
2019-02-27 08:45:57.249053500 Tags:
2019-02-27 08:45:57.249055500 { ROLE: 'tests-peer2',
2019-02-27 08:45:57.249056500 ID: '81a3cf3c-74e5-4a74-885d-7724aa68f5cd' } },
2019-02-27 08:45:57.249057500 { Addr: ,
2019-02-27 08:45:57.249058500 DelegateCur: 5,
2019-02-27 08:45:57.249059500 DelegateMax: 5,
2019-02-27 08:45:57.249061500 DelegateMin: 2,
2019-02-27 08:45:57.249062500 Name: '9a2a2b72-aa60-44f9-9685-8e3fd27f4c70',
2019-02-27 08:45:57.249063500 Port: 7946,
2019-02-27 08:45:57.249064500 ProtocolCur: 2,
2019-02-27 08:45:57.249065500 ProtocolMax: 5,
2019-02-27 08:45:57.249067500 ProtocolMin: 1,
2019-02-27 08:45:57.249068500 Status: 'alive',
2019-02-27 08:45:57.249069500 Tags:
2019-02-27 08:45:57.249070500 { ID: '9a2a2b72-aa60-44f9-9685-8e3fd27f4c70',
2019-02-27 08:45:57.249071500 ROLE: 'tests' } },
2019-02-27 08:45:57.249072500 { Addr: ,
2019-02-27 08:45:57.249075500 DelegateCur: 5,
2019-02-27 08:45:57.249076500 DelegateMax: 5,
2019-02-27 08:45:57.249078500 DelegateMin: 2,
2019-02-27 08:45:57.249079500 Name: '0e28124e-45a6-41d9-bb36-89f7094d7e32',
2019-02-27 08:45:57.249080500 Port: 7946,
2019-02-27 08:45:57.249081500 ProtocolCur: 2,
2019-02-27 08:45:57.249082500 ProtocolMax: 5,
2019-02-27 08:45:57.249083500 ProtocolMin: 1,
2019-02-27 08:45:57.249084500 Status: 'alive',
2019-02-27 08:45:57.249086500 Tags:
2019-02-27 08:45:57.249087500 { ID: '0e28124e-45a6-41d9-bb36-89f7094d7e32',
2019-02-27 08:45:57.249088500 ROLE: 'tests-peer',
2019-02-27 08:45:57.249089500 TAG1: 'value3',
2019-02-27 08:45:57.249090500 TAG2: 'value4' } } ]
```

In this case, every time member-update was received only one member was actually updated, however, the response from stream included other members which were updated in the past:

first member-updated response included one member, because no other nodes were updated at that time

second member-updated response included two members (one from previous member-update and currently updated member)

third member-updated response included three members (both members from previously received member-update's and currently updated member)

It is possible that this problem might be caused by serf flushing old coalesced events:
In https://github.com/hashicorp/serf/blob/master/serf/coalesce_member.go#L40, it can be seen that latestEvents are always appended to and flushed over and over again as member-updates occur over time:

```
func (c *memberEventCoalescer) Flush(outCh chan<- Event) {
// Coalesce the various events we got into a single set of events.
events := make(map[EventType]*MemberEvent)
for name, cevent := range c.latestEvents {
previous, ok := c.lastEvents[name]

// If we sent the same event before, then ignore
// unless it is a MemberUpdate
if ok && previous == cevent.Type && cevent.Type != EventMemberUpdate {
continue
}

// Update our last event
c.lastEvents[name] = cevent.Type

// Add it to our event
newEvent, ok := events[cevent.Type]
if !ok {
newEvent = &MemberEvent{Type: cevent.Type}
events[cevent.Type] = newEvent
}
newEvent.Members = append(newEvent.Members, *cevent.Member)
}

// Send out those events
for _, event := range events {
outCh <- *event
}
}
```

However, events themselves are only added to latestEvents in the Coalesce function, but never removed, even if they have already been flushed:

```
func (c *memberEventCoalescer) Coalesce(raw Event) {
e := raw.(MemberEvent)
for _, m := range e.Members {
c.latestEvents[m.Name] = coalesceEvent{
Type: e.Type,
Member: &m,
}
}
}
```

Could you confirm, whether, this might be part which causes member-update to return all previously updated members?

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.