go startup fixes 1

go/bind/keybase.go

@@ -316,7 +316,7 @@ func InitOnce(homeDir, mobileSharedHome, logFile, runModeStr string,
 ) {
 	startOnce.Do(func() {
 		if err := Init(homeDir, mobileSharedHome, logFile, runModeStr, accessGroupOverride, dnsNSFetcher, nvh, mobileOsVersion, isIPad, installReferrerListener, isIOS, shareIntentDonator); err != nil {
-			kbCtx.Log.Errorf("Init error: %s", err)
+			log("Init error: %s", err)
 		}
 	})
 }
@@ -342,18 +342,10 @@ func Init(homeDir, mobileSharedHome, logFile, runModeStr string,
 		log("Go: Init complete: %v err: %v", time.Since(begin), err)
 	}()
 
-	if isIOS {
-		// buffer of bytes
-		buffer = make([]byte, 300*1024)
-	} else {
-		const targetBufferSize = 300 * 1024
-		// bufferSize must be divisible by 3 to ensure that we don't split
-		// our b64 encode across a payload boundary if we go over our buffer
-		// size.
-		const bufferSize = targetBufferSize - (targetBufferSize % 3)
-		// buffer for the conn.Read
-		buffer = make([]byte, bufferSize)
-	}
+	// Buffer for the conn.Read. Size must stay divisible by 3 so we don't
+	// split a b64 encode across a payload boundary if we go over the buffer
+	// size.
+	buffer = make([]byte, 300*1024)
 
 	var perfLogFile, ekLogFile, guiLogFile string
 	if logFile != "" {
@@ -367,15 +359,6 @@ func Init(homeDir, mobileSharedHome, logFile, runModeStr string,
 	}
 	libkb.IsIPad = isIPad
 
-	// Reduce OS threads on mobile so we don't have too much contention with JS thread
-	// oldProcs := runtime.GOMAXPROCS(0)
-	// newProcs := oldProcs - 2
-	// if newProcs <= 0 {
-	// 	newProcs = 1
-	// }
-	// runtime.GOMAXPROCS(newProcs)
-	// fmt.Printf("Go: setting GOMAXPROCS to: %d previous: %d\n", newProcs, oldProcs)
-
 	startTrace(logFile)
 
 	dnsNSFetcher := newDNSNSFetcher(externalDNSNSFetcher)
@@ -434,28 +417,41 @@ func Init(homeDir, mobileSharedHome, logFile, runModeStr string,
 	captureStderr(logFile)
 
 	kbSvc = service.NewService(kbCtx, false)
-	if err = kbSvc.StartLoopbackServer(libkb.LoginAttemptOffline); err != nil {
+	// LoginAttemptNone: the login attempt happens inside RunBackgroundOperations
+	// below, off the Init path. It can block for seconds (leveldb
+	// open/recovery, keychain reads) and Init runs on the native main thread;
+	// GetBootstrapStatus waits for the attempt so the GUI doesn't see a stale
+	// logged-out state.
+	phase := time.Now()
+	if err = kbSvc.StartLoopbackServer(libkb.LoginAttemptNone); err != nil {
 		log("failed to start loopback: %s", err)
 		return err
 	}
+	log("Go: Init: loopback server up: %s", time.Since(phase))
 	kbCtx.SetService()
 	uir := service.NewUIRouter(kbCtx)
 	kbCtx.SetUIRouter(uir)
 	kbCtx.SetDNSNameServerFetcher(dnsNSFetcher)
+	phase = time.Now()
 	if err = kbSvc.SetupCriticalSubServices(); err != nil {
 		log("failed subservices setup: %s", err)
 		return err
 	}
+	log("Go: Init: critical subservices up: %s", time.Since(phase))
 	kbSvc.SetupChatModules(nil)
 	if installReferrerListener != nil {
 		kbSvc.SetInstallReferrerListener(newInstallReferrerListener(installReferrerListener))
 	}
-	kbSvc.RunBackgroundOperations(uir)
 	kbChatCtx = kbSvc.ChatG()
 	kbChatCtx.NativeVideoHelper = newVideoHelper(nvh)
 	if shareIntentDonator != nil {
 		kbChatCtx.ShareIntentDonator = shareIntentDonatorAdapter{wrapped: shareIntentDonator}
 	}
+	// Runs the startup login attempt and then the long-lived background
+	// tasks. Off the Init thread so a slow login can't hold up app launch;
+	// must start after the chat context fields above are set since chat
+	// modules read them once started.
+	go kbSvc.RunBackgroundOperations(uir)
 
 	logs := status.Logs{
 		Service: config.GetLogFile(),
@@ -499,7 +495,7 @@ func Init(homeDir, mobileSharedHome, logFile, runModeStr string,
 }
 
 func LogToService(str string) {
-	kbCtx.Log.Info(str)
+	log("%s", str)
 }
 
 type serviceCn struct{}
@@ -530,6 +526,9 @@ func (s serviceCn) NewChat(config libkbfs.Config, params libkbfs.InitParams, ctx
 // LogSend sends a log to Keybase
 func LogSend(statusJSON string, feedback string, sendLogs, sendMaxBytes bool, traceDir, cpuProfileDir string) (res string, err error) {
 	defer func() { err = flattenError(err) }()
+	if !isInited() {
+		return "", errors.New("LogSend: service not initialized")
+	}
 	env := kbCtx.Env
 	logSendContext.UID = env.GetUID()
 	logSendContext.InstallID = env.GetInstallID()
@@ -556,6 +555,9 @@ func LogSend(statusJSON string, feedback string, sendLogs, sendMaxBytes bool, tr
 
 // WriteArr sends raw bytes encoded msgpack rpc payload from the native layer (iOS and Android)
 func WriteArr(b []byte) (err error) {
+	// The copy is load-bearing: gomobile only pins b's backing memory for
+	// the duration of this call, and the loopback conn's Write retains the
+	// slice instead of copying it.
 	bytes := make([]byte, len(b))
 	copy(bytes, b)
 	defer func() { err = flattenError(err) }()
@@ -589,10 +591,8 @@ func WriteArr(b []byte) (err error) {
 	return nil
 }
 
-const bufferSize = 1024 * 1024
-
-// buffer for the conn.Read
-var buffer = make([]byte, bufferSize)
+// buffer for the conn.Read; allocated in Init.
+var buffer []byte
 
 // ReadArr is a blocking read for msgpack rpc data.
 // It is called serially by the mobile run loops.
@@ -618,7 +618,11 @@ func ReadArr() (data []byte, err error) {
 	}
 
 	n, err := currentConn.Read(buffer)
-	if n > 0 && err == nil {
+	if n > 0 {
+		// Deliver data even if err != nil (allowed by the net.Conn
+		// contract); the error will surface on the next call. Returning a
+		// view of the shared buffer is safe because gomobile copies the
+		// bytes across the boundary and ReadArr is called serially.
 		return buffer[0:n], nil
 	}
 
@@ -694,17 +698,22 @@ func Reset() error {
 // jsReadyCh is closed once and stays closed, so repeated engine resets are no-ops.
 func NotifyJSReady() {
 	jsReadyOnce.Do(func() {
+		connMutex.Lock()
+		currentConn := conn
+		connMutex.Unlock()
 		log("Go: JS signaled ready, unblocking RPC communication appState=%s conn=%s",
-			appStateForLog(), describeConn(conn))
+			appStateForLog(), describeConn(currentConn))
 		close(jsReadyCh)
 	})
 }
 
 // ForceGC Forces a gc
 func ForceGC() {
-	log("Flushing global caches")
-	kbCtx.FlushCaches()
-	log("Done flushing global caches")
+	if kbCtx != nil {
+		log("Flushing global caches")
+		kbCtx.FlushCaches()
+		log("Done flushing global caches")
+	}
 	runtime.GC()
 	log("Starting force gc")
 	debug.FreeOSMemory()
@@ -743,6 +752,35 @@ func SetAppStateBackground() {
 	}
 	defer kbCtx.Trace("SetAppStateBackground", nil)()
 	kbCtx.MobileAppState.Update(keybase1.MobileAppState_BACKGROUND)
+	flushLocalDbs()
+}
+
+// flushLocalDbs flushes the leveldb memtables in the background. An unclean
+// kill while suspended (routine on iOS) with a non-empty journal forces a
+// journal replay — or a whole-DB recovery — during the next launch, which is
+// the main cold-start cost. Called when the app heads to the background so
+// the journals are empty if the OS kills the process.
+func flushLocalDbs() {
+	if kbCtx == nil {
+		return
+	}
+	flush := func(name string, db *libkb.JSONLocalDb) {
+		if db == nil {
+			return
+		}
+		ldb, ok := db.GetEngine().(*libkb.LevelDb)
+		if !ok {
+			return
+		}
+		begin := time.Now()
+		if err := ldb.Flush(); err != nil {
+			log("Go: flushLocalDbs: %s flush error: %v", name, err)
+			return
+		}
+		log("Go: flushLocalDbs: %s flushed in %s", name, time.Since(begin))
+	}
+	go flush("LocalDb", kbCtx.LocalDb)
+	go flush("LocalChatDb", kbCtx.LocalChatDb)
 }
 
 func SetAppStateInactive() {
@@ -795,22 +833,30 @@ func BackgroundSync() string {
 		return msg
 	}
 
+	// Flip to BACKGROUNDACTIVE only if still BACKGROUND, so a foreground
+	// transition that lands after the check above isn't overwritten. If the
+	// check fails, NextUpdate below fires immediately and we bail out.
 	nextState := keybase1.MobileAppState_BACKGROUNDACTIVE
-	kbCtx.MobileAppState.Update(nextState)
-	resultCh := make(chan string, 1)
-	go func() {
-		select {
-		case state := <-kbCtx.MobileAppState.NextUpdate(&nextState):
-			// if literally anything happens, let's get out of here
-			msg := fmt.Sprintf("bailing out early, appstate change: %v", state)
-			kbCtx.Log.Debug("BackgroundSync: %s", msg)
-			resultCh <- msg
-		case <-time.After(10 * time.Second):
-			kbCtx.MobileAppState.Update(keybase1.MobileAppState_BACKGROUND)
-			resultCh <- "completed 10s window"
-		}
-	}()
-	return <-resultCh
+	kbCtx.MobileAppState.UpdateWithCheck(nextState, func(s keybase1.MobileAppState) bool {
+		return s == keybase1.MobileAppState_BACKGROUND
+	})
+	select {
+	case state := <-kbCtx.MobileAppState.NextUpdate(&nextState):
+		// if literally anything happens, let's get out of here
+		msg := fmt.Sprintf("bailing out early, appstate change: %v", state)
+		kbCtx.Log.Debug("BackgroundSync: %s", msg)
+		return msg
+	case <-time.After(10 * time.Second):
+		// Drop back to BACKGROUND only if we still hold BACKGROUNDACTIVE;
+		// the app may have foregrounded between the timer firing and this
+		// update, and clobbering FOREGROUND would cancel live RPCs and
+		// strand the service in BACKGROUND while the user is in the app.
+		kbCtx.MobileAppState.UpdateWithCheck(keybase1.MobileAppState_BACKGROUND,
+			func(s keybase1.MobileAppState) bool {
+				return s == keybase1.MobileAppState_BACKGROUNDACTIVE
+			})
+		return "completed 10s window"
+	}
 }
 
 // pushPendingMessageFailure sends at most one notification that a message
@@ -844,6 +890,7 @@ func AppWillExit(pusher PushNotifier) {
 		pushPendingMessageFailure(obrs, pusher)
 	}
 	kbCtx.MobileAppState.Update(keybase1.MobileAppState_BACKGROUND)
+	flushLocalDbs()
 }
 
 // AppDidEnterBackground notifies the service that the app is in the background
@@ -874,6 +921,7 @@ func AppDidEnterBackground() bool {
 	if stayRunning {
 		kbCtx.Log.Debug("AppDidEnterBackground: setting background active")
 		kbCtx.MobileAppState.Update(keybase1.MobileAppState_BACKGROUNDACTIVE)
+		flushLocalDbs()
 		return true
 	}
 	SetAppStateBackground()
@@ -899,6 +947,7 @@ func AppBeginBackgroundTask(pusher PushNotifier) {
 	// Poll active deliveries in case we can shutdown early
 	beginTime := libkb.ForceWallClock(time.Now())
 	ticker := time.NewTicker(5 * time.Second)
+	defer ticker.Stop()
 	appState := kbCtx.MobileAppState.State()
 	if appState != keybase1.MobileAppState_BACKGROUNDACTIVE {
 		kbCtx.Log.Debug("AppBeginBackgroundTask: not in background mode, early out")
@@ -969,6 +1018,9 @@ func startTrace(logFile string) {
 	if os.Getenv("KEYBASE_TRACE_MOBILE") != "1" {
 		return
 	}
+	if logFile == "" {
+		return
+	}
 
 	tname := filepath.Join(filepath.Dir(logFile), "svctrace.out")
 	f, err := os.Create(tname)

go/libkb/leveldb.go

@@ -230,6 +230,38 @@ func (l *LevelDb) ForceOpen() error {
 	return l.doWhileOpenAndNukeIfCorrupted(func() error { return nil })
 }
 
+// levelDbFlushSentinelKey lives in the "pm" table so the db cleaner ignores
+// it. Written before CompactRange so the memtable contains at least one key
+// and isMemOverlaps returns true for the full-range compaction.
+var levelDbFlushSentinelKey = []byte(levelDbTablePerm + ":ff:flush-sentinel")
+
+// Flush writes the current memtable to disk and rotates the journal. An
+// unclean process kill (routine on iOS) with a non-empty journal forces a
+// journal replay on the next open, or worse a whole-DB recovery if the
+// journal tail is corrupt — both of which block startup. Flushing while
+// entering the background leaves a near-empty journal so the next cold start
+// opens fast. No-op if the DB is not currently open; does not trigger a lazy
+// open.
+func (l *LevelDb) Flush() (err error) {
+	l.RLock()
+	defer l.RUnlock()
+	if l.db == nil {
+		return nil
+	}
+	// Write the sentinel so the memtable is non-empty; then compact the full
+	// key space (util.Range{} with nil Start/Limit) so isMemOverlaps always
+	// returns true regardless of what other keys are live. A narrow range
+	// keyed only on the sentinel could miss the memtable flush if a concurrent
+	// write rotated the memtable between the Put and CompactRange.
+	if err = l.db.Put(levelDbFlushSentinelKey, nil, nil); err != nil {
+		return err
+	}
+	if err = l.db.CompactRange(util.Range{}); err != nil {
+		return err
+	}
+	return l.db.Delete(levelDbFlushSentinelKey, nil)
+}
+
 func (l *LevelDb) Stats() (stats string) {
 	if err := l.doWhileOpenAndNukeIfCorrupted(func() (err error) {
 		stats, err = l.db.GetProperty("leveldb.stats")

go/libkb/leveldb_test.go

@@ -13,6 +13,7 @@ import (
 	"time"
 
 	"github.com/stretchr/testify/require"
+	"github.com/syndtr/goleveldb/leveldb"
 )
 
 type teardowner struct {
@@ -110,6 +111,35 @@ func TestLevelDb(t *testing.T) {
 				require.False(t, found)
 			},
 		},
+		{
+			name: "flush", testBody: func(t *testing.T) {
+				tc := SetupTest(t, "LevelDb-flush", 0)
+				defer tc.Cleanup()
+				db, err := createTempLevelDbForTest(&tc, &td)
+				require.NoError(t, err)
+
+				// Flush before the lazy open is a no-op.
+				require.NoError(t, db.Flush())
+
+				key, err := testLevelDbPut(db)
+				require.NoError(t, err)
+
+				require.NoError(t, db.Flush())
+				require.NoError(t, db.Flush())
+
+				// Data survives the flush and the sentinel is cleaned up.
+				val, found, err := db.Get(key)
+				require.NoError(t, err)
+				require.True(t, found)
+				require.Equal(t, []byte{1, 2, 3, 4}, val)
+				_, err = db.db.Get(levelDbFlushSentinelKey, nil)
+				require.Equal(t, leveldb.ErrNotFound, err)
+
+				// Writes still work after a flush.
+				_, err = testLevelDbPut(db)
+				require.NoError(t, err)
+			},
+		},
 		{
 			name: "cleaner", testBody: func(t *testing.T) {
 				tc := SetupTest(t, "LevelDb-cleaner", 0)

go/service/config.go

@@ -351,6 +351,10 @@ func (h ConfigHandler) WaitForClient(_ context.Context, arg keybase1.WaitForClie
 func (h ConfigHandler) GetBootstrapStatus(ctx context.Context, sessionID int) (res keybase1.BootstrapStatus, err error) {
 	m := libkb.NewMetaContext(ctx, h.G()).WithLogTag("CFG")
 	defer m.Trace("GetBootstrapStatus", &err)()
+	// The GUI gates its first render on this RPC. Wait out the startup login
+	// attempt (which can be slow: leveldb open/recovery, keychain reads) so
+	// we don't report loggedIn=false while it is still in flight.
+	h.svc.awaitInitialLoginAttempt(m, 30*time.Second)
 	eng := engine.NewBootstrap(h.G())
 	if err = engine.RunEngine2(m, eng); err != nil {
 		return res, err