Merge branch 'release-1.16.8' into stable

conf/api.go

@@ -346,7 +346,7 @@ func (confMap ConfMap) UpdateFromFile(confFilePath string) (err error) {
 // To enable efficient comparisons, the elements of the ConfMap will be
 // sorted in the output (both by sectionName and by optionName).
 //
-func (confMap ConfMap) Dump() (buf string) {
+func (confMap ConfMap) Dump() (confMapString string) {
 	var (
 		confOption                ConfMapOption
 		confOptionName            string
@@ -360,7 +360,10 @@ func (confMap ConfMap) Dump() (buf string) {
 		confSectionNameSliceIndex int
 	)
 
-	buf = ""
+	// 1 Mibyte should be more than enough to hold the confMap so get the
+	// memory in 1 allocation
+	var buf strings.Builder
+	buf.Grow(1024 * 1024)
 
 	confSectionNameSlice = make([]string, 0, len(confMap))
 
@@ -374,10 +377,10 @@ func (confMap ConfMap) Dump() (buf string) {
 		confSection = confMap[confSectionName]
 
 		if 0 < confSectionNameSliceIndex {
-			buf += "\n"
+			buf.WriteString("\n")
 		}
 
-		buf += "[" + confSectionName + "]\n"
+		buf.WriteString("[" + confSectionName + "]\n")
 
 		confOptionNameSlice = make([]string, 0, len(confSection))
 		confOptionNameLenMax = 0
@@ -394,20 +397,22 @@ func (confMap ConfMap) Dump() (buf string) {
 		for _, confOptionName = range confOptionNameSlice {
 			confOption = confSection[confOptionName]
 
-			buf += confOptionName + ":" + strings.Repeat(" ", confOptionNameLenMax-len(confOptionName))
+			buf.WriteString(confOptionName + ":" +
+				strings.Repeat(" ", confOptionNameLenMax-len(confOptionName)))
 
 			for confOptionValueIndex, confOptionValue = range confOption {
 				if 0 == confOptionValueIndex {
-					buf += " " + confOptionValue
+					buf.WriteString(" " + confOptionValue)
 				} else {
-					buf += ", " + confOptionValue
+					buf.WriteString(", " + confOptionValue)
 				}
 			}
 
-			buf += "\n"
+			buf.WriteString("\n")
 		}
 	}
 
+	confMapString = buf.String()
 	return
 }
 

logger/api.go

@@ -866,7 +866,7 @@ func (log LogTarget) Write(p []byte) (n int, err error) {
 // "goroutine", and "package".  Not all fields are present in every message,
 // in which case the field name is not a key in the map.
 //
-func ParseLogEntry(entry string) map[string]string {
+func ParseLogEntry(entry string) (map[string]string, error) {
 	return parseLogEntry(entry)
 }
 

logger/api_test.go

@@ -5,6 +5,8 @@ import (
 	"strings"
 	"testing"
 
+	"github.com/stretchr/testify/assert"
+
 	"github.com/swiftstack/ProxyFS/conf"
 	"github.com/swiftstack/ProxyFS/utils"
 )
@@ -66,6 +68,8 @@ func TestAPI(t *testing.T) {
 }
 
 func testLogTargets(t *testing.T) {
+	assert := assert.New(t)
+
 	var targ LogTarget
 	targ.Init(10)
 
@@ -92,7 +96,9 @@ func testLogTargets(t *testing.T) {
 		t.Error("log target doesn't count correctly")
 	}
 
-	fields := ParseLogEntry(targ.LogBuf.LogEntries[0])
+	fields, err := ParseLogEntry(targ.LogBuf.LogEntries[0])
+	assert.Nil(err, "ParseLogEntry of '%s' should not fail", targ.LogBuf.LogEntries[0])
+
 	names := []string{
 		"time", "level", "msg", "goroutine", "package",
 	}
@@ -105,6 +111,8 @@ func testLogTargets(t *testing.T) {
 }
 
 func testParseLogEntry(t *testing.T) {
+	assert := assert.New(t)
+
 	var targ LogTarget
 	targ.Init(10)
 
@@ -115,12 +123,15 @@ func testParseLogEntry(t *testing.T) {
 	var (
 		fields map[string]string
 		names  []string
+		err    error
 	)
 
 	// test a trace log entry (logs as level=info
 	Tracef("%s %s", "Hello,", "World")
 
-	fields = ParseLogEntry(targ.LogBuf.LogEntries[0])
+	fields, err = ParseLogEntry(targ.LogBuf.LogEntries[0])
+	assert.Nil(err, "ParseLogEntry of '%s' should not fail", targ.LogBuf.LogEntries[0])
+
 	names = []string{
 		"time", "level", "msg", "goroutine", "package",
 	}
@@ -144,10 +155,12 @@ func testParseLogEntry(t *testing.T) {
 	}
 
 	// test an error entry
-	err := fmt.Errorf("this is the error")
+	err = fmt.Errorf("this is the error")
 	ErrorfWithError(err, "we had an error!")
 
-	fields = ParseLogEntry(targ.LogBuf.LogEntries[0])
+	fields, err = ParseLogEntry(targ.LogBuf.LogEntries[0])
+	assert.Nil(err, "ParseLogEntry of '%s' should not fail", targ.LogBuf.LogEntries[0])
+
 	names = []string{
 		"time", "level", "msg", "goroutine", "package", "error",
 	}
@@ -173,7 +186,9 @@ func testParseLogEntry(t *testing.T) {
 	msg_in := `When you put "something" in double quotes it means "something else"`
 	msg_out := `When you put \"something\" in double quotes it means \"something else\"`
 	Tracef(msg_in)
-	fields = ParseLogEntry(targ.LogBuf.LogEntries[0])
+	fields, err = ParseLogEntry(targ.LogBuf.LogEntries[0])
+	assert.Nil(err, "ParseLogEntry of '%s' should not fail", targ.LogBuf.LogEntries[0])
+
 	if fields["msg"] != msg_out {
 		t.Errorf("'msg' field contains '%s' should be '%s' in entry '%s'",
 			fields["msg"], msg_out, targ.LogBuf.LogEntries[0])
@@ -185,7 +200,9 @@ func testParseLogEntry(t *testing.T) {
 	err = fmt.Errorf(errmsg_in)
 	ErrorfWithError(err, msg_in)
 
-	fields = ParseLogEntry(targ.LogBuf.LogEntries[0])
+	fields, err = ParseLogEntry(targ.LogBuf.LogEntries[0])
+	assert.Nil(err, "ParseLogEntry of '%s' should not fail", targ.LogBuf.LogEntries[0])
+
 	if fields["msg"] != msg_out {
 		t.Errorf("'msg' field contains '%s' should be '%s' in entry '%s'",
 			fields["msg"], msg_out, targ.LogBuf.LogEntries[0])

logger/config.go

@@ -77,9 +77,10 @@ func (log LogTarget) write(p []byte) (n int, err error) {
 	return 0, nil
 }
 
-// Call to configure the logger.  This really should be done before using it,
-// but you can log things before calling.  However, they will not appear in
-// the logfile and will not be in the new text format.
+// openLogFile is called to open the log file and (re-) int the logger.  This
+// really should be done before using it, but you can log things before calling.
+// However, they will not appear in the logfile and will not be in the new text
+// format.
 //
 // Config variables that affect logging include:
 //     Logging.LogFilePath        string       if present, pathname to log file
@@ -88,8 +89,7 @@ func (log LogTarget) write(p []byte) (n int, err error) {
 //                                             also appear in packageTraceSettings)
 //     Logging.DebugLevelLogging  stringslice
 //
-
-func Up(confMap conf.ConfMap) (err error) {
+func openLogFile(confMap conf.ConfMap) (err error) {
 	log.SetFormatter(&log.TextFormatter{DisableColors: true, TimestampFormat: timeFormat})
 
 	// Fetch log file info, if provided
@@ -106,6 +106,7 @@ func Up(confMap conf.ConfMap) (err error) {
 	logToConsole, err := confMap.FetchOptionValueBool("Logging", "LogToConsole")
 	if err != nil {
 		logToConsole = false
+		err = nil
 	}
 
 	log.SetOutput(&logTargets)
@@ -130,7 +131,50 @@ func Up(confMap conf.ConfMap) (err error) {
 	debugConfSlice, _ := confMap.FetchOptionValueStringSlice("Logging", "DebugLevelLogging")
 	setDebugLoggingLevel(debugConfSlice)
 
-	return nil
+	Infof("logger opened logfile (PID %d)", os.Getpid())
+	return
+}
+
+// closeLogFile closes the output log file as part of shutdown or as part of
+// rotating to a new log file.
+//
+func closeLogFile(confMap conf.ConfMap) (err error) {
+
+	Infof("logger closing logfile (PID %d)", os.Getpid())
+
+	// We open and close our own logfile
+	if logFile != nil {
+		// Sync() flushes data cached in the kernel to disk, which is
+		// really only useful if the OS were to crash soon
+		logFile.Sync()
+		logFile.Close()
+	}
+	logTargets.Clear()
+	err = nil
+	return
+}
+
+// Up opens the logfile.  This really should be done before using the logfile,
+// but you can log things before calling.  However, they will not appear in
+// the logfile and will not be in the new text format.
+//
+// Config variables that affect logging include:
+//     Logging.LogFilePath        string       if present, pathname to log file
+//     Logging.LogToConsole       bool         if present and true, log to console as well as file
+//     Logging.TraceLevelLogging  stringslice  list of packages where tracing is enabled (name must
+//                                             also appear in packageTraceSettings)
+//     Logging.DebugLevelLogging  stringslice
+//
+
+func Up(confMap conf.ConfMap) (err error) {
+
+	err = openLogFile(confMap)
+	if err != nil {
+		return
+	}
+
+	Infof("logger is starting up (PID %d)", os.Getpid())
+	return
 }
 
 func SignaledStart(confMap conf.ConfMap) (err error) {
@@ -139,23 +183,20 @@ func SignaledStart(confMap conf.ConfMap) (err error) {
 }
 
 func SignaledFinish(confMap conf.ConfMap) (err error) {
-	err = Down(confMap)
+
+	Infof("logger is closing and reopening logfile (PID %d)", os.Getpid())
+	err = closeLogFile(confMap)
 	if nil == err {
-		err = Up(confMap)
+		err = openLogFile(confMap)
 	}
 	return
 }
 
 func Down(confMap conf.ConfMap) (err error) {
-	// We open and close our own logfile
-	if logFile != nil {
-		// Sync() flushes data cached in the kernel to disk, which is
-		// really only useful if the OS were to crash soon
-		logFile.Sync()
-		logFile.Close()
-	}
-	logTargets.Clear()
-	err = nil
+
+	log.Infof("logger is shutting down (PID %d)", os.Getpid())
+
+	err = closeLogFile(confMap)
 	return
 }
 
@@ -170,26 +211,29 @@ func Down(confMap conf.ConfMap) (err error) {
 //
 // time="2017-07-27T02:09:32.259383Z" level=error msg="retry.RequestWithRetry(): swiftclient.testRetry.request(1) failed after 6 attempts in 0.054 sec with unretriable error" error="Simulate an unretriable error" function=RequestWithRetry goroutine=20 package=swiftclient
 //
-func parseLogEntry(entry string) (fields map[string]string) {
+func parseLogEntry(entry string) (fields map[string]string, err error) {
 	var (
 		matches []string
 	)
 
 	var fieldRE = regexp.MustCompile(
 		`^time="(?P<time>[-:0-9.ZTt_]+)" level=(?P<level>[a-zA-Z]+) msg="(?P<msg>([^"]|\\")+)" (error="(?P<error>([^"]|\\")+)" )?function=(?P<function>\w+) goroutine=(?P<goroutine>\d+) package=(?P<package>\w+)`)
+
 	matches = fieldRE.FindStringSubmatch(entry)
 	if matches == nil {
-		Warnf("log entry not matched by regular expression fieldRE: '%s'", entry)
-		return nil
+		fmt.Printf("parseLogEntry: log entry not matched by regular expression fieldRE: '%s'\n", entry)
+		err = fmt.Errorf("log entry not matched by regular expression fieldRE: '%s'", entry)
+		return
 	}
+
 	fields = make(map[string]string)
 	for idx, name := range fieldRE.SubexpNames() {
 		if name != "" && matches[idx] != "" {
 			fields[name] = matches[idx]
 		}
 	}
 
-	return fields
+	return
 }
 
 // Parse the log entries, starting with the most recent, looking for a message
@@ -234,10 +278,11 @@ func parseLogForFunc(logcopy LogTarget, funcName string, logEntryRE *regexp.Rege
 			return
 		}
 
-		fields = ParseLogEntry(logEntry)
-		if fields == nil {
-			err = fmt.Errorf("parseLogForFunc(): log entry unparsable by ParseLogEntry(): '%s'",
-				logEntry)
+		fields, err = ParseLogEntry(logEntry)
+		if err != nil {
+			err = fmt.Errorf("parseLogForFunc(): log entry '%s' unparsable by ParseLogEntry(): %v",
+				logEntry, err)
+			return
 		}
 
 		if fields["msg"] == "" {

pfsagentd/fission.go

@@ -95,7 +95,11 @@ func fixAttrSizes(attr *fission.Attr) {
 		fileInode, ok = globals.fileInodeMap[inode.InodeNumber(attr.Ino)]
 		if ok {
 			if 0 == fileInode.chunkedPutList.Len() {
-				attr.Size = fileInode.extentMapFileSize
+				if 0 == fileInode.extentMapFileSize {
+					// Leave attr.Size as is... no reason to override it
+				} else {
+					attr.Size = fileInode.extentMapFileSize
+				}
 			} else {
 				chunkedPutContextElement = fileInode.chunkedPutList.Back()
 				chunkedPutContext = chunkedPutContextElement.Value.(*chunkedPutContextStruct)

pfsagentd/inode.go

@@ -197,6 +197,17 @@ func honorInodeCacheLimits() (delayedLeaseRequestList *list.List) {
 	for (nil != globals.unleasedFileInodeCacheLRU.Front()) && ((globals.unleasedFileInodeCacheLRU.Len() > fileInodeCacheLimitToEnforce) || (globals.config.ExtentMapEntryLimit < uint64(globals.extentMapEntriesCached))) {
 		fileInodeCacheLRUElement = globals.unleasedFileInodeCacheLRU.Front()
 		fileInode = fileInodeCacheLRUElement.Value.(*fileInodeStruct)
+		if 0 != fileInode.references {
+			// TODO: While this shouldn't be the case, the current mock Lease/Lock solution may
+			//       result in a referenced file being on the globals.unleasedFileInodeCacheLRU
+			//       leading to a race condition where a new DoRead() comes in, can't find the
+			//       "dirty" fileInode, and go off and fetch a stale copy from ProxyFS. Meanwhile,
+			//       the reference by the ChunkedPUTContext for the "dirty" fileInode eventually
+			//       finishes leading to proper updating of ProxyFS. Hence, a restart of PFSAgent
+			//       or a subsequent fileInode cache flush for the referenced file will result in
+			//       reading the correct/up-to-date contents of the file.
+			break
+		}
 		globals.unleasedFileInodeCacheLRU.Remove(fileInodeCacheLRUElement)
 		globals.extentMapEntriesCached -= fileInode.extentMapLenWhenUnreferenced
 		delete(globals.fileInodeMap, fileInode.InodeNumber)

release_notes.md

@@ -1,5 +1,22 @@
 # ProxyFS Release Notes
 
+## 1.16.8 (July 28, 2020)
+
+### Bug Fixes:
+
+Prevent premature invalidation of dirty file inode caching in
+PFSAgent leading to subsequent incorrect (stale) read results.
+
+Correct reporting of file size when a non-empty file is first
+accessed by PFSAgent.
+
+### Features:
+
+Log rotation events are not logged.
+
+Memory fragmentation has been improved particularly in calls to
+dump a configuration (package conf's ConfMap).
+
 ## 1.16.7 (July 16, 2020)
 
 ### Bug Fixes:

swiftclient/api_test.go

@@ -1192,10 +1192,11 @@ func parseRetryLogEntry(entry string) map[string]string {
 	var (
 		fields  = make(map[string]string)
 		matches []string
+		err     error
 	)
 
-	fields = logger.ParseLogEntry(entry)
-	if fields["msg"] == "" {
+	fields, err = logger.ParseLogEntry(entry)
+	if err != nil {
 		fmt.Fprintf(os.Stderr, "log entry not matched: '%s'\n", entry)
 	}