func (m *Mux) followLog(appID, jobID string, ch chan<- *rfc5424.Message) (stream.Stream, error) {
s := stream.New()
var jobDone <-chan struct{}
if jobID != "" {
jobDone = m.jobDoneCh(jobID, s.StopCh)
}
go func() {
msgs := make(chan message)
unsubscribe := m.subscribe(appID, msgs)
defer unsubscribe()
defer close(ch)
for {
select {
case msg, ok := <-msgs:
if !ok {
return
}
if jobID != "" && !strings.HasSuffix(string(msg.Message.Header.ProcID), jobID) {
// skip messages that aren't from the job we care about
continue
}
select {
case ch <- msg.Message:
case <-s.StopCh:
return
}
case <-s.StopCh:
return
case <-jobDone:
return
}
}
}()
return s, nil
}
/*
Stream manufactures a `pkg/stream.Stream`, starts a worker pumping events out of decoding, and returns that.
The 'outputCh' parameter must be a sendable channel. The "zero"-values of channel's content type will be created and used in the deserialization, then sent.
The return values from `httpclient.RawReq` are probably a useful starting point for the 'res' parameter.
Closing the returned `stream.Stream` shuts down the worker.
*/
func Stream(res *http.Response, outputCh interface{}) stream.Stream {
stream := stream.New()
var chanValue reflect.Value
if v, ok := outputCh.(reflect.Value); ok {
chanValue = v
} else {
chanValue = reflect.ValueOf(outputCh)
}
stopChanValue := reflect.ValueOf(stream.StopCh)
msgType := chanValue.Type().Elem().Elem()
go func() {
done := make(chan struct{})
defer func() {
chanValue.Close()
close(done)
}()
go func() {
select {
case <-stream.StopCh:
case <-done:
}
res.Body.Close()
}()
r := bufio.NewReader(res.Body)
dec := sse.NewDecoder(r)
for {
msg := reflect.New(msgType)
if err := dec.Decode(msg.Interface()); err != nil {
if err != io.EOF {
stream.Error = err
}
break
}
chosen, _, _ := reflect.Select([]reflect.SelectCase{
{
Dir: reflect.SelectRecv,
Chan: stopChanValue,
},
{
Dir: reflect.SelectSend,
Chan: chanValue,
Send: msg,
},
})
switch chosen {
case 0:
return
default:
}
}
}()
return stream
}
func (d *ServiceCache) Watch(ch chan *discoverd.Event, current bool) stream.Stream {
d.Lock()
if d.watchers == nil {
d.watchers = make(map[chan *discoverd.Event]struct{})
}
d.watchers[ch] = struct{}{}
stream := stream.New()
go func() {
defer func() {
d.Lock()
defer d.Unlock()
delete(d.watchers, ch)
}()
if current {
for _, inst := range d.instances {
select {
case ch <- &discoverd.Event{
Kind: discoverd.EventKindUp,
Instance: inst,
}:
case <-stream.StopCh:
go func() {
for range ch {
}
}()
d.Unlock()
return
case <-d.done:
close(ch)
d.Unlock()
return
}
}
}
d.Unlock()
select {
case <-stream.StopCh:
go func() {
for range ch {
}
}()
case <-d.done:
close(ch)
}
}()
return stream
}
// Leaders sends leader events to the given channel (sending nil when there is
// no leader, for example if there are no instances currently registered).
func (s *service) Leaders(leaders chan *Instance) (stream.Stream, error) {
events := make(chan *Event)
eventStream, err := s.client.c.Stream("GET", fmt.Sprintf("/services/%s/leader", s.name), nil, events)
if err != nil {
return nil, err
}
stream := stream.New()
go func() {
defer func() {
eventStream.Close()
// wait for stream to close to prevent race with Err read
for range events {
}
if err := eventStream.Err(); err != nil {
stream.Error = err
}
close(leaders)
}()
for {
select {
case event, ok := <-events:
if !ok {
return
}
if event.Kind != EventKindLeader {
continue
}
select {
case leaders <- event.Instance:
case <-stream.StopCh:
return
}
case <-stream.StopCh:
return
}
}
}()
return stream, nil
}
func getBuildLogStream(b *Build, ch chan string) (stream.Stream, error) {
stream := stream.New()
// if the build hasn't finished, tail the log from disk
if !b.Finished() {
t, err := tail.TailFile(b.LogFile, tail.Config{Follow: true, MustExist: true})
if err != nil {
return nil, err
}
go func() {
defer t.Stop()
defer close(ch)
for {
select {
case line, ok := <-t.Lines:
if !ok {
stream.Error = t.Err()
return
}
select {
case ch <- line.Text:
case <-stream.StopCh:
return
}
if strings.HasPrefix(line.Text, "build finished") {
return
}
case <-stream.StopCh:
return
}
}
}()
return stream, nil
}
// get the multipart log from S3 and serve just the "build.log" file
res, err := http.Get(b.LogURL)
if err != nil {
return nil, err
}
if res.StatusCode != http.StatusOK {
res.Body.Close()
return nil, fmt.Errorf("unexpected status %d getting build log", res.StatusCode)
}
_, params, err := mime.ParseMediaType(res.Header.Get("Content-Type"))
if err != nil {
res.Body.Close()
return nil, err
}
go func() {
defer res.Body.Close()
defer close(ch)
mr := multipart.NewReader(res.Body, params["boundary"])
for {
select {
case <-stream.StopCh:
return
default:
}
p, err := mr.NextPart()
if err != nil {
stream.Error = err
return
}
if p.FileName() != "build.log" {
continue
}
s := bufio.NewScanner(p)
for s.Scan() {
select {
case ch <- s.Text():
case <-stream.StopCh:
return
}
}
return
}
}()
return stream, nil
}
func (s *HostSuite) TestNotifyOOM(t *c.C) {
appID := random.UUID()
// subscribe to init log messages from the logaggregator
client, err := logaggc.New("")
t.Assert(err, c.IsNil)
opts := logagg.LogOpts{
Follow: true,
StreamTypes: []logagg.StreamType{logagg.StreamTypeInit},
}
rc, err := client.GetLog(appID, &opts)
t.Assert(err, c.IsNil)
defer rc.Close()
msgs := make(chan *logaggc.Message)
stream := stream.New()
defer stream.Close()
go func() {
defer close(msgs)
dec := json.NewDecoder(rc)
for {
var msg logaggc.Message
if err := dec.Decode(&msg); err != nil {
stream.Error = err
return
}
select {
case msgs <- &msg:
case <-stream.StopCh:
return
}
}
}()
// run the OOM job
cmd := exec.CommandUsingCluster(
s.clusterClient(t),
s.createArtifact(t, "test-apps"),
"/bin/oom",
)
cmd.Meta = map[string]string{"flynn-controller.app": appID}
runErr := make(chan error)
go func() {
runErr <- cmd.Run()
}()
// wait for the OOM notification
for {
select {
case err := <-runErr:
t.Assert(err, c.IsNil)
case msg, ok := <-msgs:
if !ok {
t.Fatalf("message stream closed unexpectedly: %s", stream.Err())
}
t.Log(msg.Msg)
if strings.Contains(msg.Msg, "FATAL: a container process was killed due to lack of available memory") {
return
}
case <-time.After(30 * time.Second):
t.Fatal("timed out waiting for OOM notification")
}
}
}
func ResumingStream(connect func(int64) (*http.Response, error, bool), outputCh interface{}) (stream.Stream, error) {
stream := stream.New()
firstErr := make(chan error)
go func() {
var once sync.Once
var lastID int64
stopChanValue := reflect.ValueOf(stream.StopCh)
outValue := reflect.ValueOf(outputCh)
defer outValue.Close()
for {
var res *http.Response
// nonRetryableErr will be set if a connection attempt should not
// be retried (for example if a 404 is returned).
var nonRetryableErr error
err := connectAttempts.Run(func() (err error) {
var retry bool
res, err, retry = connect(lastID)
if !retry {
nonRetryableErr = err
return nil
}
return
})
if nonRetryableErr != nil {
err = nonRetryableErr
}
once.Do(func() { firstErr <- err })
if err != nil {
stream.Error = err
return
}
chanValue := reflect.MakeChan(outValue.Type(), 0)
s := Stream(res, chanValue)
loop:
for {
chosen, v, ok := reflect.Select([]reflect.SelectCase{
{
Dir: reflect.SelectRecv,
Chan: stopChanValue,
},
{
Dir: reflect.SelectRecv,
Chan: chanValue,
},
})
switch chosen {
case 0:
s.Close()
return
default:
if !ok {
// TODO: check s.Err() for a special error sent from the
// server indicating the stream should not be retried
break loop
}
id := v.Elem().FieldByName("ID")
if id.Kind() == reflect.Int64 {
lastID = id.Int()
}
outValue.Send(v)
}
}
}
}()
return stream, <-firstErr
}
func (m *Mux) streamWithHistory(appID, jobID string, follow bool, ch chan<- *rfc5424.Message) (stream.Stream, error) {
l := m.logger.New("fn", "streamWithHistory", "app.id", appID, "job.id", jobID)
logs, err := m.logFiles(appID)
if err != nil {
return nil, err
}
if len(logs) == 0 {
return m.followLog(appID, jobID, ch)
}
msgs := make(chan message)
unsubscribeFn := make(chan func(), 1)
s := stream.New()
var jobDone <-chan struct{}
if jobID != "" {
jobDone = m.jobDoneCh(jobID, s.StopCh)
}
go func() {
var cursor *utils.HostCursor
var unsubscribe func()
var done bool
defer func() {
close(ch)
if unsubscribe != nil {
unsubscribe()
}
}()
for {
select {
case msg, ok := <-msgs:
if !ok {
return
}
if jobID != "" && !strings.HasSuffix(string(msg.Message.Header.ProcID), jobID) {
// skip messages that aren't from the job we care about
continue
}
if cursor != nil && !msg.HostCursor.After(*cursor) {
// skip messages with old cursors
continue
}
cursor = msg.HostCursor
select {
case ch <- msg.Message:
case <-s.StopCh:
return
}
case <-jobDone:
if unsubscribe != nil {
return
}
// we haven't finished reading the historical logs, exit when finished
done = true
jobDone = nil
case fn, ok := <-unsubscribeFn:
if !ok {
if done {
// historical logs done, and job already exited
return
}
unsubscribeFn = nil
continue
}
unsubscribe = fn
case <-s.StopCh:
return
}
}
}()
go func() {
defer close(unsubscribeFn)
for i, name := range logs[appID] {
if err := func() (err error) {
l := l.New("log", name)
f, err := os.Open(name)
if err != nil {
l.Error("error reading log", "error", err)
return err
}
defer f.Close()
sc := bufio.NewScanner(f)
sc.Split(rfc6587.SplitWithNewlines)
var eof bool
scan:
for sc.Scan() {
msgBytes := sc.Bytes()
// slice in msgBytes could get modified on next Scan(), need to copy it
msgCopy := make([]byte, len(msgBytes)-1)
copy(msgCopy, msgBytes)
msg, cursor, err := utils.ParseMessage(msgCopy)
if err != nil {
l.Error("error parsing log message", "error", err)
return err
}
select {
case msgs <- message{cursor, msg}:
case <-s.StopCh:
return nil
}
}
if err := sc.Err(); err != nil {
l.Error("error scanning log message", "error", err)
return err
}
if follow && !eof && i == len(logs[appID])-1 {
// got EOF on last file, subscribe to stream
eof = true
unsubscribeFn <- m.subscribe(appID, msgs)
// read to end of file again
goto scan
}
return nil
}(); err != nil {
close(msgs)
s.Error = err
return
}
}
if !follow {
close(msgs)
}
}()
return s, nil
}
// Run monitors a service using Check and sends up/down transitions to ch
func (m Monitor) Run(check Check, ch chan MonitorEvent) stream.Stream {
if m.StartInterval == 0 {
m.StartInterval = defaultStartInterval
}
if m.Interval == 0 {
m.Interval = defaultInterval
}
if m.Threshold == 0 {
m.Threshold = defaultThreshold
}
stream := stream.New()
go func() {
t := time.NewTicker(m.StartInterval)
defer close(ch)
status := MonitorStatusCreated
var upCount, downCount int
up := func() {
downCount = 0
upCount++
if status == MonitorStatusCreated || status == MonitorStatusDown && upCount >= m.Threshold {
if status == MonitorStatusCreated {
t.Stop()
t = time.NewTicker(m.Interval)
}
status = MonitorStatusUp
if m.Logger != nil {
m.Logger.Info("new monitor status", "status", status, "check", check)
}
select {
case ch <- MonitorEvent{
Status: status,
Check: check,
}:
case <-stream.StopCh:
}
}
}
down := func(err error) {
upCount = 0
downCount++
if m.Logger != nil {
m.Logger.Warn("healthcheck error", "check", check, "err", err)
}
if status == MonitorStatusUp && downCount >= m.Threshold {
status = MonitorStatusDown
if m.Logger != nil {
m.Logger.Info("new monitor status", "status", status, "check", check, "err", err)
}
select {
case ch <- MonitorEvent{
Status: status,
Err: err,
Check: check,
}:
case <-stream.StopCh:
}
}
}
check := func() {
if err := check.Check(); err != nil {
down(err)
} else {
up()
}
}
check()
outer:
for {
select {
case <-t.C:
check()
case <-stream.StopCh:
break outer
}
}
t.Stop()
}()
return stream
}
func (RegisterSuite) TestRegister(c *C) {
type step struct {
event bool // send an event
up bool // event type
register bool // event should trigger register
unregister bool // event should unregister service
setMeta bool // attempt SetMeta
success bool // true if SetMeta or Register should succeed
}
type called struct {
args map[string]interface{}
returnVal chan bool
}
run := func(c *C, steps []step) {
check := CheckFunc(func() error { return nil })
metaChan := make(chan called)
unregisterChan := make(chan called)
heartbeater := FakeHeartbeat{
addrFn: func() string {
return "notnil"
},
closeFn: func() error {
unregisterChan <- called{}
return nil
},
setMetaFn: func(meta map[string]string) error {
success := make(chan bool)
metaChan <- called{
args: map[string]interface{}{
"meta": meta,
},
returnVal: success,
}
if !<-success {
return errors.New("SetMeta failed")
}
return nil
},
}
registrarChan := make(chan called)
registrar := RegistrarFunc(func(service string, inst *discoverd.Instance) (discoverd.Heartbeater, error) {
success := make(chan bool)
registrarChan <- called{
args: map[string]interface{}{
"service": service,
"inst": inst,
},
returnVal: success,
}
defer func() { registrarChan <- called{} }()
if <-success {
return heartbeater, nil
}
return nil, errors.New("registrar failure")
})
monitorChan := make(chan bool)
monitor := func(c Check, ch chan MonitorEvent) stream.Stream {
stream := stream.New()
go func() {
defer close(ch)
outer:
for {
select {
case up, ok := <-monitorChan:
if !ok {
break outer
}
if up {
ch <- MonitorEvent{
Check: check,
Status: MonitorStatusUp,
}
} else {
ch <- MonitorEvent{
Check: check,
Status: MonitorStatusDown,
}
}
case <-stream.StopCh:
break outer
}
}
}()
return stream
}
reg := Registration{
Service: "test",
Instance: &discoverd.Instance{
Meta: make(map[string]string),
},
Registrar: registrar,
Monitor: monitor,
Check: check,
Events: make(chan MonitorEvent),
}
hb := reg.Register()
defer func() {
go func() { <-unregisterChan }()
hb.Close()
close(unregisterChan)
}()
errCh := make(chan bool)
errCheck := func(ch chan called, stop chan bool) {
go func() {
select {
case _, ok := <-ch:
if !ok {
return
}
errCh <- true
case <-stop:
errCh <- false
}
}()
}
var stop chan bool
currentMeta := make(map[string]string)
for _, step := range steps {
stop = make(chan bool)
var wait int
if step.event {
monitorChan <- step.up
}
if step.register {
call := <-registrarChan
c.Assert(call.args["inst"].(*discoverd.Instance).Meta, DeepEquals, currentMeta)
call.returnVal <- step.success
<-registrarChan
} else {
wait++
errCheck(registrarChan, stop)
}
if step.unregister {
// before unregistering, Addr should not be nil
c.Assert(hb.Addr(), Not(Equals), "")
select {
case <-unregisterChan:
case <-time.After(3 * time.Second):
c.Error("Timed out waiting for unregistration")
}
// Addr should be nil now
c.Assert(hb.Addr(), Equals, "")
} else {
wait++
errCheck(unregisterChan, stop)
}
if step.setMeta {
go func() {
call := <-metaChan
if call.returnVal != nil {
call.returnVal <- step.success
}
}()
// SetMeta needs to succeed every time, regardless of the situation
currentMeta["TEST"] = random.UUID()
c.Assert(hb.SetMeta(currentMeta), IsNil)
} else {
wait++
errCheck(metaChan, stop)
}
// check event forwarding
if step.event {
select {
case val := <-reg.Events:
if step.up {
c.Assert(val.Status, Equals, MonitorStatusUp)
} else {
c.Assert(val.Status, Equals, MonitorStatusDown)
}
case <-time.After(3 * time.Second):
c.Error("Timed out waiting for Registration.Events")
}
}
// check whether functions were called on this step that should not
// have ran
close(stop)
for i := 0; i < wait; i++ {
select {
case err := <-errCh:
if err {
c.Error("Received data on a channel that should not be recieving on this step")
}
}
}
}
close(monitorChan)
close(registrarChan)
close(metaChan)
}
for _, t := range []struct {
name string
steps []step
}{
{
name: "register success up/down/up",
steps: []step{
{event: true, up: true, register: true, success: true},
{event: true, unregister: true},
{event: true, up: true, register: true, success: true},
},
},
{
name: "register fails then succeeds",
steps: []step{
{event: true, up: true, register: true, success: false},
{register: true, success: true},
},
},
{
name: "register is called only once if we get two up events",
steps: []step{
{event: true, up: true, register: true, success: true},
{event: true, up: true, register: false},
},
},
{
name: "setmeta while registered",
steps: []step{
{event: true, up: true, register: true, success: true},
{setMeta: true, success: true},
},
},
{
name: "setmeta while offline",
steps: []step{
{setMeta: true, success: false},
// confirm that the right meta is sent when the process does
// come up
{event: true, up: true, register: true, success: true},
},
},
{
name: "setmeta while erroring registration",
steps: []step{
{event: true, up: true, register: true, success: false},
{register: true, success: false},
{setMeta: true, success: false},
{register: true, success: true},
},
},
{
name: "register failing then offline",
steps: []step{
{event: true, up: true, register: true, success: false},
{register: true, success: false},
{event: true},
{}, // make sure register does not run
{},
},
},
} {
c.Log("--- TEST:", t.name)
run(c, t.steps)
}
}
