Output more logging information

drivers/s3.go

@@ -274,6 +274,7 @@ func (os *s3Session) ReadData(ctx context.Context, name string) (*FileInfoReader
 }
 
 func (os *s3Session) saveDataPut(name string, data []byte, meta map[string]string) (string, error) {
+	now := time.Now()
 	bucket := aws.String(os.bucket)
 	keyname := aws.String(os.key + "/" + name)
 	var metadata map[string]*string
@@ -301,7 +302,7 @@ func (os *s3Session) saveDataPut(name string, data []byte, meta map[string]strin
 	}
 	glog.Infof("resp: %s", resp.String())
 	uri := os.getAbsURL(*keyname)
-	glog.V(common.VERBOSE).Infof("Saved to S3 %s", uri)
+	glog.V(common.VERBOSE).Infof("Saved to S3 %s bytes=%v dur=%s", uri, len(data), time.Since(now))
 	return uri, err
 }
 

eth/blockwatch/stack_test.go

@@ -119,7 +119,7 @@ func TestPopConcurrent(t *testing.T) {
 	// Insert headers into store
 	headerMap := make(map[ethcommon.Hash]bool)
 	for i := 0; i < 10; i++ {
-		hash := ethcommon.BytesToHash([]byte(string(i)))
+		hash := ethcommon.BytesToHash([]byte(string(rune(i))))
 		headerMap[hash] = true
 
 		require.Nil(store.InsertMiniHeader(&MiniHeader{Hash: hash}))
@@ -228,7 +228,7 @@ func TestPushConcurrent(t *testing.T) {
 	require := require.New(t)
 
 	headerHash := func(i int) ethcommon.Hash {
-		return ethcommon.BytesToHash([]byte(string(i)))
+		return ethcommon.BytesToHash([]byte(string(rune(i))))
 	}
 
 	// Insert headers into store

monitor/census.go

@@ -956,7 +956,7 @@ func SegmentFullyTranscoded(nonce, seqNo uint64, profiles string, errCode Segmen
 }
 
 func TranscodedSegmentAppeared(nonce, seqNo uint64, profile string) {
-	glog.V(logLevel).Infof("Logging LogTranscodedSegmentAppeared... nonce=%d SeqNo=%d profile=%s", nonce, seqNo, profile)
+	glog.V(logLevel).Infof("Logging LogTranscodedSegmentAppeared... nonce=%d seqNo=%d profile=%s", nonce, seqNo, profile)
 	census.segmentTranscodedAppeared(nonce, seqNo, profile)
 }
 

server/broadcast.go

@@ -288,7 +288,7 @@ func processSegment(cxn *rtmpConnection, seg *stream.HLSSegment) ([]string, erro
 		return nil, fmt.Errorf("Invalid duration %v", seg.Duration)
 	}
 
-	glog.V(common.DEBUG).Infof("Processing segment nonce=%d manifestID=%s seqNo=%d dur=%v", nonce, mid, seg.SeqNo, seg.Duration)
+	glog.V(common.DEBUG).Infof("Processing segment nonce=%d manifestID=%s seqNo=%d dur=%v bytes=%v", nonce, mid, seg.SeqNo, seg.Duration, len(seg.Data))
 	if monitor.Enabled {
 		monitor.SegmentEmerged(nonce, seg.SeqNo, len(BroadcastJobVideoProfiles))
 	}
@@ -308,11 +308,11 @@ func processSegment(cxn *rtmpConnection, seg *stream.HLSSegment) ([]string, erro
 				now := time.Now()
 				uri, err := ros.SaveData(name, seg.Data, map[string]string{"duration": segDurMs})
 				if err != nil {
-					glog.Errorf("Error saving %s to record store try=%d err=%v", name, i, err)
+					glog.Errorf("Error saving nonce=%d manifestID=%s name=%s to record store try=%d err=%v", nonce, mid, name, i, err)
 				} else {
 					cpl.InsertHLSSegmentJSON(vProfile, seg.SeqNo, uri, seg.Duration)
-					glog.Infof("Successfully saved name=%s size=%d bytes to record store took=%s",
-						name, len(seg.Data), time.Since(now))
+					glog.Infof("Successfully saved nonce=%d manifestID=%s name=%s size=%d bytes to record store took=%s",
+						nonce, mid, name, len(seg.Data), time.Since(now))
 					break
 				}
 			}
@@ -499,11 +499,11 @@ func transcodeSegment(cxn *rtmpConnection, seg *stream.HLSSegment, name string,
 					now := time.Now()
 					uri, err := bros.SaveData(name, data, map[string]string{"duration": segDurMs})
 					if err != nil {
-						glog.Errorf("Error saving %s to record store try=%d err=%v", name, i, err)
+						glog.Errorf("Error saving nonce=%d manifestID=%s name=%s to record store try=%d err=%v", nonce, cxn.mid, name, i, err)
 					} else {
 						cpl.InsertHLSSegmentJSON(&profile, seg.SeqNo, uri, seg.Duration)
-						glog.Infof("Successfully saved name=%s size=%d bytes to record store took=%s",
-							name, len(data), time.Since(now))
+						glog.Infof("Successfully saved nonce=%d manifestID=%s name=%s size=%d bytes to record store took=%s",
+							nonce, cxn.mid, name, len(data), time.Since(now))
 						break
 					}
 				}

server/mediaserver.go

@@ -706,8 +706,8 @@ func (s *LivepeerServer) HandlePush(w http.ResponseWriter, r *http.Request) {
 		http.Error(w, fmt.Sprintf(`ignoring file extension: %s`, ext), http.StatusBadRequest)
 		return
 	}
-	glog.Infof("Got push request at url=%s ua=%s addr=%s len=%d dur=%s", r.URL.String(), r.UserAgent(), r.RemoteAddr, len(body),
-		r.Header.Get("Content-Duration"))
+	glog.Infof("Got push request at url=%s ua=%s addr=%s len=%d dur=%s resolution=%s", r.URL.String(), r.UserAgent(), r.RemoteAddr, len(body),
+		r.Header.Get("Content-Duration"), r.Header.Get("Content-Resolution"))
 
 	now := time.Now()
 	mid := parseManifestID(r.URL.Path)
@@ -764,6 +764,10 @@ func (s *LivepeerServer) HandlePush(w http.ResponseWriter, r *http.Request) {
 			}
 		}(s, mid)
 	}
+	defer func(now time.Time) {
+		glog.Infof("Finished push request at url=%s ua=%s addr=%s len=%d dur=%s resolution=%s took=%s", r.URL.String(), r.UserAgent(), r.RemoteAddr, len(body),
+			r.Header.Get("Content-Duration"), r.Header.Get("Content-Resolution"), time.Since(now))
+	}(now)
 
 	fname := path.Base(r.URL.Path)
 	seq, err := strconv.ParseUint(strings.TrimSuffix(fname, ext), 10, 64)
@@ -795,7 +799,7 @@ func (s *LivepeerServer) HandlePush(w http.ResponseWriter, r *http.Request) {
 				cancel()
 				return
 			case <-tick.Done():
-				glog.V(common.VERBOSE).Infof("watchdog reset mid=%s seq=%d dur=%v started=%v", mid, seq, duration, now)
+				glog.V(common.VERBOSE).Infof("watchdog reset manifestID=%s seq=%d dur=%v started=%v", mid, seq, duration, now)
 				s.connectionLock.Lock()
 				if cxn, exists := s.rtmpConnections[mid]; exists {
 					cxn.lastUsed = time.Now()
@@ -813,6 +817,7 @@ func (s *LivepeerServer) HandlePush(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 	if len(urls) == 0 {
+		glog.Infof("No sessions available for manifestID=%s seqNo=%d name=%s", mid, seq, fname)
 		http.Error(w, "No sessions available", http.StatusServiceUnavailable)
 		return
 	}
@@ -827,6 +832,7 @@ func (s *LivepeerServer) HandlePush(w http.ResponseWriter, r *http.Request) {
 			}
 		}
 	}
+	glog.Infof("Finished transcoding push request at url=%s manifestID=%s seqNo=%d took=%s", r.URL.String(), mid, seq, time.Since(now))
 
 	boundary := common.RandName()
 	accept := r.Header.Get("Accept")
@@ -901,7 +907,7 @@ func (s *LivepeerServer) HandleRecordings(w http.ResponseWriter, r *http.Request
 	glog.V(common.DEBUG).Infof("Got recordings request=%s", r.URL.String())
 	now := time.Now()
 	defer func() {
-		glog.V(common.VERBOSE).Infof("request=%s took=%s", r.URL.String(), time.Since(now))
+		glog.V(common.VERBOSE).Infof("request=%s took=%s headers=%+v", r.URL.String(), time.Since(now), w.Header())
 	}()
 	returnMasterPlaylist := pp[3] == "index.m3u8"
 	var track string