Flaky test: nmz/endpoint

[AkihiroSuda]

4919228
https://travis-ci.org/osrg/namazu/builds/134960743

ok      github.com/osrg/namazu/nmz/cli  2.768s  coverage: 0.3% of statements
ok      github.com/osrg/namazu/nmz/cli/container/run    2.432s  coverage: 0.0% of statements
ok      github.com/osrg/namazu/nmz/cli/inspectors   2.568s  coverage: 12.6% of statements
ok      github.com/osrg/namazu/nmz/cli/tools    1.024s  coverage: 2.5% of statements
ok      github.com/osrg/namazu/nmz/container    2.534s  coverage: 0.0% of statements
ok      github.com/osrg/namazu/nmz/container/ns 1.025s  coverage: 0.0% of statements
No output has been received in the last 10m0s, this potentially indicates a stalled build or something wrong with the build itself.
The build has been terminated

Typical output:
https://travis-ci.org/osrg/namazu/builds/134956146

ok      github.com/osrg/namazu/nmz/cli  2.220s  coverage: 0.3% of statements
ok      github.com/osrg/namazu/nmz/cli/container/run    2.226s  coverage: 0.0% of statements
ok      github.com/osrg/namazu/nmz/cli/inspectors   2.230s  coverage: 12.6% of statements
ok      github.com/osrg/namazu/nmz/cli/tools    1.017s  coverage: 2.5% of statements
ok      github.com/osrg/namazu/nmz/container    2.223s  coverage: 0.0% of statements
ok      github.com/osrg/namazu/nmz/container/ns 1.015s  coverage: 0.0% of statements
ok      github.com/osrg/namazu/nmz/endpoint 2.404s  coverage: 72.1% of statements    <--- this
...

[AkihiroSuda]

locally reproducible. TestEndpointWithPacketEvent_256_4 seems hanging.

4919228
a.txt

[AkihiroSuda]

Test command	Reproducible?
for f in $(seq 1 5000);do ./endpoint.test -test.run TestEndpointWithPacketEvent_1_1 -test.v ; done	Yes ❗
for f in $(seq 1 5000);do ./endpoint.test -test.run TestEndpointWithPacketEvent_256_4 -test.v ; done	Yes
./endpoint.test -test.run TestEndpointWithPacketEvent_1_1 -test.v -test.count 5000	No
./endpoint.test -test.run TestEndpointWithPacketEvent_256_4 -test.v -test.count 5000	No:exclamation:

The result suggests that the cause of the issue is just related to the initialization of the test process.
So the issue is not likely to happen in the usual case.

minimized log:

=== RUN   TestEndpointWithPacketEvent_1_1
[NMZ-DBG] 09:59:17.61: REST getting action http://127.0.0.1:43185/api/v3/actions/restentity-2 (at log.go:210) 
[NMZ-DBG] 09:59:17.61: REST getting action http://127.0.0.1:43185/api/v3/actions/restentity-3 (at log.go:210) 
[NMZ-DBG] 09:59:17.61: ActionQueue[restentity-1]: Peeking (at log.go:210) 
[NMZ-DBG] 09:59:17.61: LOCAL EP handling event Signal{map[string]interface {}{"class":"PacketEvent", "option":map[string]interface {}{"src_entity":"localentity-0", "dst_entit
y":"localentity-0", "value":0}, "type":"event", "deferred":true, "uuid":"6e316b05-572e-47ce-8ed0-a7d9cb1c63c1", "entity":"localentity-0"}} (at log.go:210) 
[NMZ-DBG] 09:59:17.61: LOCAL EP handled event Signal{map[string]interface {}{"entity":"localentity-0", "class":"PacketEvent", "option":map[string]interface {}{"src_entity":"l
ocalentity-0", "dst_entity":"localentity-0", "value":0}, "type":"event", "deferred":true, "uuid":"6e316b05-572e-47ce-8ed0-a7d9cb1c63c1"}} (at log.go:210) 
[NMZ-DBG] 09:59:17.61: EP handling event Signal{map[string]interface {}{"class":"PacketEvent", "option":map[string]interface {}{"src_entity":"localentity-0", "dst_entity":"lo
calentity-0", "value":0}, "type":"event", "deferred":true, "uuid":"6e316b05-572e-47ce-8ed0-a7d9cb1c63c1", "entity":"localentity-0"}} (at log.go:210) 
[NMZ-DBG] 09:59:17.61: ActionQueue[restentity-3]: Peeking (at log.go:210) 
[NMZ-DBG] 09:59:17.61: ActionQueue[restentity-2]: Peeking (at log.go:210) 
[NMZ-DBG] 09:59:17.61: MO handling event Signal{map[string]interface {}{"uuid":"6e316b05-572e-47ce-8ed0-a7d9cb1c63c1", "entity":"localentity-0", "class":"PacketEvent", "optio
n":map[string]interface {}{"src_entity":"localentity-0", "dst_entity":"localentity-0", "value":0}, "type":"event", "deferred":true}} (at log.go:210) 
[NMZ-DBG] 09:59:17.61: MO handled event Signal{map[string]interface {}{"uuid":"6e316b05-572e-47ce-8ed0-a7d9cb1c63c1", "entity":"localentity-0", "class":"PacketEvent", "option
":map[string]interface {}{"src_entity":"localentity-0", "dst_entity":"localentity-0", "value":0}, "type":"event", "deferred":true}} (at log.go:210) 
[NMZ-DBG] 09:59:17.61: MO sending action Signal{map[string]interface {}{"class":"EventAcceptanceAction", "option":map[string]interface {}{}, "type":"action", "event_uuid":"6e
316b05-572e-47ce-8ed0-a7d9cb1c63c1", "uuid":"92f00b3f-db3a-4d60-8a69-949d950be7bd", "entity":"localentity-0"}} (at log.go:210) 
[NMZ-DBG] 09:59:17.61: MO sent action Signal{map[string]interface {}{"uuid":"92f00b3f-db3a-4d60-8a69-949d950be7bd", "entity":"localentity-0", "class":"EventAcceptanceAction",
 "option":map[string]interface {}{}, "type":"action", "event_uuid":"6e316b05-572e-47ce-8ed0-a7d9cb1c63c1"}} (at log.go:210) 
[NMZ-DBG] 09:59:17.61: EP handling action Signal{map[string]interface {}{"uuid":"92f00b3f-db3a-4d60-8a69-949d950be7bd", "entity":"localentity-0", "class":"EventAcceptanceActi
on", "option":map[string]interface {}{}, "type":"action", "event_uuid":"6e316b05-572e-47ce-8ed0-a7d9cb1c63c1"}} (at log.go:210) 
[NMZ-ERR] 09:59:17.61: Unknown Entity ID:localentity-0 (at log.go:235) 
[NMZ-DBG] 09:59:17.61: EP handled action Signal{map[string]interface {}{"uuid":"92f00b3f-db3a-4d60-8a69-949d950be7bd", "entity":"localentity-0", "class":"EventAcceptanceActio
n", "option":map[string]interface {}{}, "type":"action", "event_uuid":"6e316b05-572e-47ce-8ed0-a7d9cb1c63c1"}} (at log.go:210) 
[NMZ-DBG] 09:59:17.61: EP handled event Signal{map[string]interface {}{"uuid":"6e316b05-572e-47ce-8ed0-a7d9cb1c63c1", "entity":"localentity-0", "class":"PacketEvent", "option
":map[string]interface {}{"src_entity":"localentity-0", "dst_entity":"localentity-0", "value":0}, "type":"event", "deferred":true}} (at log.go:210)