diff --git a/go/bind/keybase.go b/go/bind/keybase.go index d156e75837b2..f3ec7dab7966 100644 --- a/go/bind/keybase.go +++ b/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) diff --git a/go/libkb/leveldb.go b/go/libkb/leveldb.go index b6b88168b146..5d34b742950a 100644 --- a/go/libkb/leveldb.go +++ b/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") diff --git a/go/libkb/leveldb_test.go b/go/libkb/leveldb_test.go index 962a9edaf803..5f7a7c0afd58 100644 --- a/go/libkb/leveldb_test.go +++ b/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) diff --git a/go/service/config.go b/go/service/config.go index aa8239960a50..57fb456d062a 100644 --- a/go/service/config.go +++ b/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 diff --git a/go/service/main.go b/go/service/main.go index 6b2a7f3f3f7a..89f5301e9a1c 100644 --- a/go/service/main.go +++ b/go/service/main.go @@ -88,6 +88,12 @@ type Service struct { loginSuccess bool oneshotUsername string oneshotPaperkey string + + // Closed after the first real startup login attempt (offline or online) + // finishes, so RPCs that report login state (GetBootstrapStatus) can wait + // for it instead of racing a login that runs off the Init path on mobile. + initialLoginAttemptDone chan struct{} + initialLoginAttemptOnce sync.Once } type Shutdowner interface { @@ -114,6 +120,8 @@ func NewService(g *libkb.GlobalContext, isDaemon bool) *Service { walletState: stellar.NewWalletState(g, remote.NewRemoteNet(g)), offlineRPCCache: offline.NewRPCCache(g), httpSrv: manager.NewSrv(g), + + initialLoginAttemptDone: make(chan struct{}), } } @@ -1347,7 +1355,26 @@ func (d *Service) configurePath() { // If that fails for any reason, LoginProvisionedDevice is used, which should get // around any issue where the session.json file is out of date or missing since the // last time the service started. +// awaitInitialLoginAttempt blocks until the first startup login attempt has +// finished (however it went), the context is done, or maxWait elapses. Used +// by RPCs whose answer depends on login state so they don't race the login +// that runs off the Init path on mobile. +func (d *Service) awaitInitialLoginAttempt(m libkb.MetaContext, maxWait time.Duration) { + select { + case <-d.initialLoginAttemptDone: + case <-m.Ctx().Done(): + m.Debug("awaitInitialLoginAttempt: context done: %v", m.Ctx().Err()) + case <-time.After(maxWait): + m.Debug("awaitInitialLoginAttempt: gave up after %v", maxWait) + } +} + func (d *Service) tryLogin(ctx context.Context, mode libkb.LoginAttempt) { + if mode != libkb.LoginAttemptNone { + // Signal on every exit path; sync.Once makes repeat calls no-ops. + defer d.initialLoginAttemptOnce.Do(func() { close(d.initialLoginAttemptDone) }) + } + d.loginAttemptMu.Lock() defer d.loginAttemptMu.Unlock()