Skip to content

Commit 38c7734

Browse files
mjh1mjh1
authored
Add stream and playback IDs to logging and errors (#298)
* Add stream and playback IDs to logging and errors To make debugging easier * fix * remove streamID from error
1 parent 2a9cbdb commit 38c7734

File tree

1 file changed

+45
-40
lines changed

1 file changed

+45
-40
lines changed

‎internal/app/recordtester/recordtester_app.go

+45-40
Original file line numberDiff line numberDiff line change
@@ -97,9 +97,8 @@ func NewRecordTester(gctx context.Context, opts RecordTesterOptions, serfOpts Se
9797
return rt
9898
}
9999

100-
func (rt *recordTester) Start(fileName string, testDuration, pauseDuration time.Duration) (int, error) {
100+
func (rt *recordTester) Start(fileName string, testDuration, pauseDuration time.Duration) (i int, err error) {
101101
defer rt.cancel()
102-
var err error
103102
var broadcasters []string
104103
ingest, err := rt.getIngestInfo()
105104
if err != nil {
@@ -142,11 +141,17 @@ func (rt *recordTester) Start(fileName string, testDuration, pauseDuration time.
142141
}
143142
break
144143
}
144+
// Make sure we include the Stream and Playback IDs on any error message
145+
defer func() {
146+
if err != nil {
147+
err = fmt.Errorf("playbackId=%s %w", stream.PlaybackID, err)
148+
}
149+
}()
145150
apiTry = 0
146151
rt.streamID = stream.ID
147152
rt.stream = stream
148153
messenger.SendMessage(fmt.Sprintf(":information_source: Created stream id=%s", stream.ID))
149-
glog.V(model.VERBOSE).Infof("Created Livepeer stream id=%s streamKey=%s playbackId=%s name=%s", stream.ID, stream.StreamKey, stream.PlaybackID, streamName)
154+
glog.V(model.VERBOSE).Infof("Created Livepeer stream streamId=%s streamKey=%s playbackId=%s name=%s", stream.ID, stream.StreamKey, stream.PlaybackID, streamName)
150155
rtmpURL := fmt.Sprintf("%s/%s", ingest.Ingest, stream.StreamKey)
151156

152157
testerFuncs := []testers.StartTestFunc{}
@@ -169,20 +174,20 @@ func (rt *recordTester) Start(fileName string, testDuration, pauseDuration time.
169174
serfMember := rt.serfOpts.SerfMembers[index]
170175
mediaURL = fmt.Sprintf("%s/hls/%s/index.m3u8", serfMember.Tags["https"], stream.PlaybackID)
171176
}
172-
glog.V(model.SHORT).Infof("RTMP: %s", rtmpURL)
173-
glog.V(model.SHORT).Infof("MEDIA: %s", mediaURL)
177+
glog.V(model.SHORT).Infof("RTMP: %s streamId=%s playbackId=%s", rtmpURL, stream.ID, stream.PlaybackID)
178+
glog.V(model.SHORT).Infof("MEDIA: %s streamId=%s playbackId=%s", mediaURL, stream.ID, stream.PlaybackID)
174179
if rt.useHTTP {
175180
sterr := rt.doOneHTTPStream(fileName, streamName, broadcasters[0], testDuration, stream)
176181
if sterr != nil {
177-
glog.Warningf("Streaming returned error err=%v", sterr)
182+
glog.Warningf("Streaming returned error err=%v streamId=%s playbackId=%s", sterr, stream.ID, stream.PlaybackID)
178183
return 3, err
179184
}
180185
if streamTwice {
181-
glog.Infof("Pause specified, waiting %s before streaming second time", pauseDuration)
186+
glog.Infof("Pause specified, waiting %s before streaming second time. streamId=%s playbackId=%s", pauseDuration, stream.ID, stream.PlaybackID)
182187
time.Sleep(pauseDuration)
183188
sterr = rt.doOneHTTPStream(fileName, streamName, broadcasters[0], testDuration, stream)
184189
if sterr != nil {
185-
glog.Warningf("Second time streaming returned error err=%v", sterr)
190+
glog.Warningf("Second time streaming returned error err=%v streamId=%s playbackId=%s", sterr, stream.ID, stream.PlaybackID)
186191
return 3, err
187192
}
188193
}
@@ -192,46 +197,46 @@ func (rt *recordTester) Start(fileName string, testDuration, pauseDuration time.
192197
sr2.StartStreaming(fileName, rtmpURL, mediaURL, 2*time.Minute, testDuration)
193198
srerr := sr2.Err()
194199

195-
glog.Infof("Streaming stream id=%s done err=%v", stream.ID, srerr)
200+
glog.Infof("Streaming done err=%v streamId=%s playbackId=%s", srerr, stream.ID, stream.PlaybackID)
196201
var re *testers.RTMPError
197202
if errors.As(srerr, &re) {
198203
return 2, re
199204
}
200205
if srerr != nil {
201-
glog.Warningf("Streaming returned error err=%v", srerr)
206+
glog.Warningf("Streaming returned error err=%v streamId=%s playbackId=%s", srerr, stream.ID, stream.PlaybackID)
202207
return 3, srerr
203208
}
204209
stats, err := sr2.Stats()
205210
if err != nil {
206-
glog.Warningf("Stats returned error err=%v", err)
211+
glog.Warningf("Stats returned error err=%v streamId=%s playbackId=%s", err, stream.ID, stream.PlaybackID)
207212
return 21, err
208213
}
209-
glog.Infof("Streaming success rate=%v", stats.SuccessRate)
214+
glog.Infof("Streaming success rate=%v streamId=%s playbackId=%s", stats.SuccessRate, stream.ID, stream.PlaybackID)
210215
if err = rt.isCancelled(); err != nil {
211216
return 0, err
212217
}
213218
if streamTwice {
214-
glog.Infof("Pause specified, waiting %s before streaming second time", pauseDuration)
219+
glog.Infof("Pause specified, waiting %s before streaming second time. streamId=%s playbackId=%s", pauseDuration, stream.ID, stream.PlaybackID)
215220
time.Sleep(pauseDuration)
216221
sr2 := testers.NewStreamer2(rt.ctx, testers.Streamer2Options{MistMode: true}, testerFuncs...)
217222
go sr2.StartStreaming(fileName, rtmpURL, mediaURL, 30*time.Second, testDuration)
218223
<-sr2.Done()
219224
srerr := sr2.Err()
220-
glog.Infof("Streaming second stream id=%s done", stream.ID)
225+
glog.Infof("Streaming second done. streamId=%s playbackId=%s", stream.ID, stream.PlaybackID)
221226
var re *testers.RTMPError
222227
if errors.As(srerr, &re) {
223228
return 2, re
224229
}
225230
if srerr != nil {
226-
glog.Warningf("Streaming second returned error err=%v", srerr)
231+
glog.Warningf("Streaming second returned error err=%v streamId=%s playbackId=%s", srerr, stream.ID, stream.PlaybackID)
227232
return 3, srerr
228233
}
229234
stats, err := sr2.Stats()
230235
if err != nil {
231-
glog.Warningf("Stats returned error err=%v", err)
236+
glog.Warningf("Stats returned error err=%v streamId=%s playbackId=%s", err, stream.ID, stream.PlaybackID)
232237
return 21, err
233238
}
234-
glog.Infof("Streaming second time success rate=%v", stats.SuccessRate)
239+
glog.Infof("Streaming second time success rate=%v streamId=%s playbackId=%s", stats.SuccessRate, stream.ID, stream.PlaybackID)
235240
if err = rt.isCancelled(); err != nil {
236241
return 0, err
237242
}
@@ -240,15 +245,15 @@ func (rt *recordTester) Start(fileName string, testDuration, pauseDuration time.
240245
if err := rt.isCancelled(); err != nil {
241246
return 0, err
242247
}
243-
glog.Infof("Waiting 10 seconds")
248+
glog.Infof("Waiting 10 seconds. streamId=%s playbackId=%s", stream.ID, stream.PlaybackID)
244249
time.Sleep(10 * time.Second)
245250
// now get sessions
246251
sessions, err := rt.lapi.GetSessionsNew(stream.ID, false)
247252
if err != nil {
248-
glog.Errorf("Error getting sessions for stream id=%s err=%v", stream.ID, err)
253+
glog.Errorf("Error getting sessions err=%v streamId=%s playbackId=%s", err, stream.ID, stream.PlaybackID)
249254
return 252, err
250255
}
251-
glog.Infof("Sessions: %+v", sessions)
256+
glog.Infof("Sessions: %+v streamId=%s playbackId=%s", sessions, stream.ID, stream.PlaybackID)
252257

253258
expectedSessions := 1
254259
if streamTwice {
@@ -264,7 +269,7 @@ func (rt *recordTester) Start(fileName string, testDuration, pauseDuration time.
264269

265270
sess := sessions[0]
266271
if len(sess.Profiles) != len(stream.Profiles) {
267-
glog.Infof("session: %+v", sess)
272+
glog.Infof("session: %+v streamId=%s playbackId=%s", sess, stream.ID, stream.PlaybackID)
268273
err := fmt.Errorf("got %d profiles but should have %d", len(sess.Profiles), len(stream.Profiles))
269274
return 251, err
270275
}
@@ -276,7 +281,7 @@ func (rt *recordTester) Start(fileName string, testDuration, pauseDuration time.
276281
return 0, err
277282
}
278283

279-
glog.Info("Streaming done, waiting for recording URL to appear")
284+
glog.Infof("Streaming done, waiting for recording URL to appear. streamId=%s playbackId=%s", stream.ID, stream.PlaybackID)
280285
if rt.useForceURL {
281286
time.Sleep(5 * time.Second)
282287
} else {
@@ -291,7 +296,7 @@ func (rt *recordTester) Start(fileName string, testDuration, pauseDuration time.
291296
err := fmt.Errorf("error getting sessions for stream id=%s err=%v", stream.ID, err)
292297
return 252, err
293298
}
294-
glog.Infof("Sessions: %+v", sessions)
299+
glog.Infof("Sessions: %+v streamId=%s playbackId=%s", sessions, stream.ID, stream.PlaybackID)
295300
if err = rt.isCancelled(); err != nil {
296301
return 0, err
297302
}
@@ -310,7 +315,7 @@ func (rt *recordTester) Start(fileName string, testDuration, pauseDuration time.
310315
err := fmt.Errorf("recording URL should appear by now")
311316
return 249, err
312317
}
313-
glog.Infof("recordingURL=%s downloading now", sess.RecordingURL)
318+
glog.Infof("recordingURL=%s downloading now. streamId=%s playbackId=%s", sess.RecordingURL, stream.ID, stream.PlaybackID)
314319

315320
if err = rt.isCancelled(); err != nil {
316321
return 0, err
@@ -327,7 +332,7 @@ func (rt *recordTester) Start(fileName string, testDuration, pauseDuration time.
327332
return es, err
328333
}
329334
}
330-
glog.Info("Done Record Test")
335+
glog.Infof("Done Record Test. streamId=%s playbackId=%s", stream.ID, stream.PlaybackID)
331336

332337
rt.lapi.DeleteStream(stream.ID)
333338
return 0, nil
@@ -397,40 +402,40 @@ func (rt *recordTester) isCancelled() error {
397402
func (rt *recordTester) checkDownMp4(stream *api.Stream, url string, streamDuration time.Duration) (int, error) {
398403
es := 0
399404
started := time.Now()
400-
glog.V(model.VERBOSE).Infof("Downloading mp4 url=%s stream id=%s", url, stream.ID)
405+
glog.V(model.VERBOSE).Infof("Downloading mp4 url=%s streamId=%s playbackId=%s", url, stream.ID, stream.PlaybackID)
401406

402407
resp, err := http.Get(url)
403408
if err != nil {
404-
glog.Warningf("Error downloading mp4 for manifestID=%s url=%s", stream.ID, url)
409+
glog.Warningf("Error downloading mp4 url=%s streamId=%s playbackId=%s", url, stream.ID, stream.PlaybackID)
405410
return 3, err
406411
}
407412
if resp.StatusCode != http.StatusOK {
408-
glog.Warningf("HTTP error downloading mp4 for manifestID=%s url=%s status=%s", stream.ID, url, resp.Status)
413+
glog.Warningf("HTTP error downloading mp4 url=%s status=%s streamId=%s playbackId=%s", url, resp.Status, stream.ID, stream.PlaybackID)
409414
return 3, err
410415
}
411416
defer resp.Body.Close()
412417
body, err := ioutil.ReadAll(resp.Body)
413418
if err != nil {
414-
glog.Warningf("HTTP error downloading mp4 for manifestID=%s url=%s err=%v", stream.ID, url, err)
419+
glog.Warningf("HTTP error downloading mp4 url=%s err=%v streamId=%s playbackId=%s", url, err, stream.ID, stream.PlaybackID)
415420
return 3, err
416421
}
417-
glog.Infof("Downloaded bytes=%b manifestID=%s url=%s took=%s", len(body), stream.ID, url, time.Since(started))
422+
glog.Infof("Downloaded bytes=%b url=%s took=%s streamId=%s playbackId=%s", len(body), url, time.Since(started), stream.ID, stream.PlaybackID)
418423
bodyR := bytes.NewReader(body)
419424
dem := mp4.NewDemuxer(bodyR)
420425
streams, err := dem.Streams()
421426
if err != nil {
422-
glog.Warningf("Error parsing mp4 for manifestID=%s url=%s err=%v", stream.ID, url, err)
427+
glog.Warningf("Error parsing mp4 url=%s err=%v streamId=%s playbackId=%s", url, err, stream.ID, stream.PlaybackID)
423428
return 203, err
424429
}
425430
if len(streams) != 2 {
426431
ers := fmt.Errorf("expected only 2 streams (video and audio), got=%d, streams=%v", len(streams), streams)
427432
glog.Error(ers)
428433
return 203, err
429434
}
430-
glog.Infof("Got %d streams in mp4 file manifestID=%s url=%s", len(streams), stream.ID, url)
435+
glog.Infof("Got %d streams in mp4 file url=%s streamId=%s playbackId=%s", len(streams), url, stream.ID, stream.PlaybackID)
431436
dur, err := calcMP4FileDuration(body)
432437
if err != nil {
433-
glog.Warningf("Error parsing mp4 for manifestID=%s url=%s err=%v", stream.ID, url, err)
438+
glog.Warningf("Error parsing mp4 url=%s err=%v streamId=%s playbackId=%s", url, err, stream.ID, stream.PlaybackID)
434439
return 203, err
435440
}
436441
durDiff := streamDuration - dur
@@ -440,7 +445,7 @@ func (rt *recordTester) checkDownMp4(stream *api.Stream, url string, streamDurat
440445
if durDiff > 2*time.Second {
441446
ers := fmt.Errorf("duration of mp4 differ by %s (got %s, should %s)", durDiff, dur, streamDuration)
442447
glog.Error(ers)
443-
return 300, err
448+
return 300, ers
444449
}
445450
return es, nil
446451
}
@@ -450,24 +455,24 @@ func (rt *recordTester) checkDown(stream *api.Stream, url string, streamDuration
450455
started := time.Now()
451456
downloader := testers.NewM3utester2(rt.ctx, url, false, false, false, false, 5*time.Second, nil, false)
452457
<-downloader.Done()
453-
glog.Infof(`Pulling for %s (%s) stopped after %s`, stream.ID, stream.PlaybackID, time.Since(started))
458+
glog.Infof(`Pulling stopped after %s. streamId=%s playbackId=%s`, time.Since(started), stream.ID, stream.PlaybackID)
454459
if err := rt.isCancelled(); err != nil {
455460
return 0, err
456461
}
457462
vs := downloader.VODStats()
458463
rt.vodStats = vs
459464
if len(vs.SegmentsNum) != len(api.StandardProfiles)+1 {
460-
glog.Warningf("Number of renditions doesn't match! Has %d should %d", len(vs.SegmentsNum), len(api.StandardProfiles)+1)
465+
glog.Warningf("Number of renditions doesn't match! Has %d should %d. streamId=%s playbackId=%s", len(vs.SegmentsNum), len(api.StandardProfiles)+1, stream.ID, stream.PlaybackID)
461466
es = 35
462467
}
463-
glog.Infof("Stats for %s: %s", stream.ID, vs.String())
464-
glog.Infof("Stats for %s raw: %+v", stream.ID, vs)
468+
glog.Infof("Stats: %s streamId=%s playbackId=%s", vs.String(), stream.ID, stream.PlaybackID)
469+
glog.Infof("Stats raw: %+v streamId=%s playbackId=%s", vs, stream.ID, stream.PlaybackID)
465470
if ok, ers := vs.IsOk(streamDuration, false); !ok {
466-
glog.Warningf("NOT OK! (%s)", ers)
471+
glog.Warningf("NOT OK! (%s) streamId=%s playbackId=%s", ers, stream.ID, stream.PlaybackID)
467472
es = 36
468473
return es, errors.New(ers)
469474
} else {
470-
glog.Infoln("All ok!")
475+
glog.Infof("All ok! streamId=%s playbackId=%s", stream.ID, stream.PlaybackID)
471476
}
472477
return es, nil
473478
}

0 commit comments

Comments
 (0)