[Bug] [Firebase Database] Repeatedly connecting and disconnecting every 2 mins, when app is in the background, without doing anything

[ebhsgit]

[READ] Step 1: Are you in the right place?

Issues filed here should be about bugs in the code in this repository.
If you have a general question, need help debugging, or fall into some
other category use one of these other channels:

• For general technical questions, post a question on StackOverflow
  with the firebase tag.
• For general Firebase discussion, use the firebase-talk
  google group.
• For help troubleshooting your application that does not fall under one
  of the above categories, reach out to the personalized
  Firebase support channel.

[REQUIRED] Step 2: Describe your environment

• Android Studio version: 2020.3.1
• Firebase Component: Database
• Component version: 20.0.1

[REQUIRED] Step 3: Describe the problem

Many android app clients are connecting and disconnecting repeatedly every 2 mins (~120_xxx ms), without doing anything in between.

This causes several issues

• Increased client device battery usage
• Increased download bandwidth usages due to constant SSL handshake - A very rough estimate of 1MB per user per day
• Constantly consumes a concurrent connection per user

---

The issue is caused by using DatabaseRef.get() in a PeriodicWorker (runs every 30 mins), and when a long running Foreground Service is also present

Expected Behaviour

Firebase Database to establish a connection when it invokes get() and then close the connection when the Worker completes.

Actual Behaviour

A connection is established at start of Worker and closed when Worker completes.
BUT then Firebase establishes a new connection ~1 sec after that, and closes the connection after 2 min. And tries to open another connection, and continues repeating this cycle.

---

Example snippet (of 1 client out of many) from firebase database:profile of production for about 15 minutes

{"pendingTime":0,"client":{"remoteAddress":{"address":"[same-client-ip]"},"userAgent":{"browser":"firebase","os":"android","platform":"native","userAgentString":"Firebase/5/20.0.1/28/Android","version":"20_0_1"}},"name":"concurrent-disconnect","timestamp":1631063531765}
{"pendingTime":1,"client":{"remoteAddress":{"address":"[same-client-ip]"},"userAgent":{"browser":"firebase","os":"android","platform":"native","userAgentString":"Firebase/5/20.0.1/28/Android","version":"20_0_1"}},"name":"concurrent-connect","timestamp":1631063532627}
{"pendingTime":1,"client":{"remoteAddress":{"address":"[same-client-ip]"},"userAgent":{"browser":"firebase","os":"android","platform":"native","userAgentString":"Firebase/5/20.0.1/28/Android","version":"20_0_1"}},"name":"concurrent-disconnect","timestamp":1631063652824}
{"pendingTime":0,"client":{"remoteAddress":{"address":"[same-client-ip]"},"userAgent":{"browser":"firebase","os":"android","platform":"native","userAgentString":"Firebase/5/20.0.1/28/Android","version":"20_0_1"}},"name":"concurrent-connect","timestamp":1631063653727}
{"pendingTime":1,"client":{"remoteAddress":{"address":"[same-client-ip]"},"userAgent":{"browser":"firebase","os":"android","platform":"native","userAgentString":"Firebase/5/20.0.1/28/Android","version":"20_0_1"}},"name":"concurrent-disconnect","timestamp":1631063773965}
{"pendingTime":0,"client":{"remoteAddress":{"address":"[same-client-ip]"},"userAgent":{"browser":"firebase","os":"android","platform":"native","userAgentString":"Firebase/5/20.0.1/28/Android","version":"20_0_1"}},"name":"concurrent-connect","timestamp":1631063774833}
{"pendingTime":0,"client":{"remoteAddress":{"address":"[same-client-ip]"},"userAgent":{"browser":"firebase","os":"android","platform":"native","userAgentString":"Firebase/5/20.0.1/28/Android","version":"20_0_1"}},"name":"concurrent-disconnect","timestamp":1631063895016}
{"pendingTime":0,"client":{"remoteAddress":{"address":"[same-client-ip]"},"userAgent":{"browser":"firebase","os":"android","platform":"native","userAgentString":"Firebase/5/20.0.1/28/Android","version":"20_0_1"}},"name":"concurrent-connect","timestamp":1631063895995}
{"pendingTime":0,"client":{"remoteAddress":{"address":"[same-client-ip]"},"userAgent":{"browser":"firebase","os":"android","platform":"native","userAgentString":"Firebase/5/20.0.1/28/Android","version":"20_0_1"}},"name":"concurrent-disconnect","timestamp":1631064016221}
{"pendingTime":0,"client":{"remoteAddress":{"address":"[same-client-ip]"},"userAgent":{"browser":"firebase","os":"android","platform":"native","userAgentString":"Firebase/5/20.0.1/28/Android","version":"20_0_1"}},"name":"concurrent-connect","timestamp":1631064017128}
{"pendingTime":0,"client":{"remoteAddress":{"address":"[same-client-ip]"},"userAgent":{"browser":"firebase","os":"android","platform":"native","userAgentString":"Firebase/5/20.0.1/28/Android","version":"20_0_1"}},"name":"concurrent-disconnect","timestamp":1631064137299}
{"pendingTime":0,"client":{"remoteAddress":{"address":"[same-client-ip]"},"userAgent":{"browser":"firebase","os":"android","platform":"native","userAgentString":"Firebase/5/20.0.1/28/Android","version":"20_0_1"}},"name":"concurrent-connect","timestamp":1631064138536}
{"pendingTime":0,"client":{"remoteAddress":{"address":"[same-client-ip]"},"userAgent":{"browser":"firebase","os":"android","platform":"native","userAgentString":"Firebase/5/20.0.1/28/Android","version":"20_0_1"}},"name":"concurrent-disconnect","timestamp":1631064258699}
{"pendingTime":0,"client":{"remoteAddress":{"address":"[same-client-ip]"},"userAgent":{"browser":"firebase","os":"android","platform":"native","userAgentString":"Firebase/5/20.0.1/28/Android","version":"20_0_1"}},"name":"concurrent-connect","timestamp":1631064259584}
{"pendingTime":0,"client":{"remoteAddress":{"address":"[same-client-ip]"},"userAgent":{"browser":"firebase","os":"android","platform":"native","userAgentString":"Firebase/5/20.0.1/28/Android","version":"20_0_1"}},"name":"concurrent-disconnect","timestamp":1631064379768}
{"pendingTime":0,"client":{"remoteAddress":{"address":"[same-client-ip]"},"userAgent":{"browser":"firebase","os":"android","platform":"native","userAgentString":"Firebase/5/20.0.1/28/Android","version":"20_0_1"}},"name":"concurrent-connect","timestamp":1631064380580}

When I reproduced it in a dev environment, I found the following logcat with debug enabled

...
...
...
 D/WebSocket: ws_61 - WebSocket reached EOF.
 D/WebSocket: ws_61 - closing itself
 D/Connection: conn_61 - Realtime connection lost
 D/Connection: conn_61 - closing realtime connection
 D/PersistentConnection: pc_0 - Got on disconnect due to OTHER
 D/PersistentConnection: pc_0 - Scheduling connection attempt
 D/ConnectionRetryHelper: Scheduling retry in 0ms
 D/PersistentConnection: pc_0 - Trying to fetch auth token
 D/PersistentConnection: pc_0 - Trying to fetch app check token
 D/WebSocket: ws_61 - closed
 D/WebSocket: ws_61 - WebSocket error.
    com.google.firebase.database.tubesock.WebSocketException: IO Exception
        at com.google.firebase.database.tubesock.WebSocketWriter.runWriter(WebSocketWriter.java:159)
        at com.google.firebase.database.tubesock.WebSocketWriter.access$000(WebSocketWriter.java:30)
        at com.google.firebase.database.tubesock.WebSocketWriter$1.run(WebSocketWriter.java:47)
        at java.lang.Thread.run(Thread.java:919)
     Caused by: java.net.SocketException: Socket is closed
        at com.android.org.conscrypt.AbstractConscryptSocket.checkOpen(AbstractConscryptSocket.java:581)
        at com.android.org.conscrypt.ConscryptFileDescriptorSocket$SSLOutputStream.write(ConscryptFileDescriptorSocket.java:643)
        at java.nio.channels.Channels$WritableByteChannelImpl.write(Channels.java:453)
        at com.google.firebase.database.tubesock.WebSocketWriter.writeMessage(WebSocketWriter.java:138)
        at com.google.firebase.database.tubesock.WebSocketWriter.runWriter(WebSocketWriter.java:152)
        at com.google.firebase.database.tubesock.WebSocketWriter.access$000(WebSocketWriter.java:30) 
        at com.google.firebase.database.tubesock.WebSocketWriter$1.run(WebSocketWriter.java:47) 
        at java.lang.Thread.run(Thread.java:919) 
 D/PersistentConnection: pc_0 - Successfully fetched token, opening connection
 D/Connection: conn_62 - Opening a connection
 D/WebSocket: ws_62 - websocket opened
 D/WebSocket: ws_62 - ws message: {"t":"c","d":{"t":"h","d":{"ts":1631332588172,"v":"5","h":"s-usc1c-nss-227.firebaseio.com","s":"ceXCNpzNUdXnULU5cX8zYWsexVNUBQb4"}}}
 D/WebSocket: ws_62 - Reset keepAlive
 D/WebSocket: ws_62 - Reset keepAlive. Remaining: 44998
 D/WebSocket: ws_62 - HandleNewFrameCount: 1
 D/WebSocket: ws_62 - handleIncomingFrame complete frame: {t=c, d={t=h, d={h=s-usc1c-nss-227.firebaseio.com, s=ceXCNpzNUdXnULU5cX8zYWsexVNUBQb4, v=5, ts=1631332588172}}}
 D/Connection: conn_62 - Got control message: {t=h, d={h=s-usc1c-nss-227.firebaseio.com, s=ceXCNpzNUdXnULU5cX8zYWsexVNUBQb4, v=5, ts=1631332588172}}
 D/Connection: conn_62 - realtime connection established
 D/PersistentConnection: pc_0 - onReady
 D/PersistentConnection: pc_0 - handling timestamp
 D/PersistentConnection: pc_0 - calling restore tokens
 D/PersistentConnection: pc_0 - Not restoring auth because auth token is null.
 D/PersistentConnection: pc_0 - Restoring outstanding listens
 D/PersistentConnection: pc_0 - Restoring writes.
 D/PersistentConnection: pc_0 - Restoring reads.
 D/WebSocket: ws_62 - WebSocket reached EOF.
 D/WebSocket: ws_62 - closing itself
 D/Connection: conn_62 - Realtime connection lost
 D/Connection: conn_62 - closing realtime connection
 D/PersistentConnection: pc_0 - Got on disconnect due to OTHER
 ...
 ...
 ...

Steps to reproduce:

I don't know the exact conditions to reproduce the issue, but it is always reproducible on a real device with a simple Periodic Worker and Foreground Service.
I was unable to reproduce in emulator.

• Create a project with the 2 classes below
• Start Periodic Worker with RtdbWorker.scheduleWorker()
• Start Foreground Service with FgService.start()
• Manually disable battery optimisation for app (Not sure if this step is required)

Let the FgService and Worker run the background.
Use the device as normal (including leaving the device on table, etc) for some extended period of time, and you will notice in logcat there are constant connection and disconnection

NOTE:

• The issue does not appear immediately after 1st run of the worker.
• May have some relationship/interaction with device Doze.
• Dev device is Samsung S9+

Relevant Code:

RtdbWorker.kt

package com.ebhs.rtdbworker

import android.content.Context
import android.util.Log
import androidx.work.*
import com.google.firebase.database.FirebaseDatabase
import com.google.firebase.database.Logger
import com.google.firebase.database.ktx.database
import com.google.firebase.database.ktx.getValue
import com.google.firebase.ktx.Firebase
import kotlinx.coroutines.Dispatchers
import kotlinx.coroutines.coroutineScope
import kotlinx.coroutines.tasks.await
import kotlinx.coroutines.withContext
import java.util.concurrent.TimeUnit

class RtdbWorker(context: Context, workerParams: WorkerParameters) : CoroutineWorker(context, workerParams) {
    companion object {
        const val TAG = "RtdbWorker"
        const val WorkerKey = "WorkerKey"

        //        const val docPath = "/doc/id123"
        const val docPath = "/doc/notExist"

        suspend fun tryGetData() = coroutineScope {
            Log.d(TAG, "Getting data")
            val data = getData()
            Log.d(TAG, "${data}")
        }

        fun scheduleWorker(context: Context) {
            Log.d(TAG, "Enqueuing work")

            val worker = PeriodicWorkRequestBuilder<RtdbWorker>(30, TimeUnit.MINUTES)
                .setBackoffCriteria(BackoffPolicy.EXPONENTIAL, 1, TimeUnit.MINUTES)
                .build()

            WorkManager.getInstance(context).enqueueUniquePeriodicWork(WorkerKey, ExistingPeriodicWorkPolicy.KEEP, worker)
        }

        fun stopWorker(context: Context) {
            WorkManager.getInstance(context).cancelUniqueWork(WorkerKey)
        }

        private suspend fun getData() = withContext(Dispatchers.IO) {
            Rtdb.instance.getReference(docPath)
                .get()
                .await()
                .getValue<Map<String, Any>>()
        }
    }

    override suspend fun doWork(): Result {
        val data = try {
            getData()
        } catch (e: Exception) {
            val errMsg = "Error message"
            Log.e(TAG, errMsg, e)
            return Result.retry()
        }

        Log.d(TAG, "${data}")
        return Result.success()
    }
}

object Rtdb {
    private val defaultInstance: FirebaseDatabase = Firebase.database

    init {
        defaultInstance.setPersistenceEnabled(true)
        defaultInstance.setLogLevel(Logger.Level.DEBUG)
    }

    @JvmStatic
    val instance: FirebaseDatabase
        get() = this.defaultInstance
}

FgService.kt

package com.ebhs.rtdbworker

import android.app.*
import android.content.Context
import android.content.Intent
import android.os.IBinder
import android.util.Log
import androidx.core.app.NotificationCompat
import androidx.core.app.NotificationManagerCompat

class FgService : Service() {

    companion object {
        const val TAG = "RtdbWorker.FgService"

        const val channelId = "fgService-channel"
        const val channelName = "Foreground Service"
        const val notificationTitle = "Foreground Service"
        const val notificationText = "Sticky. Does nothing"

        fun start(context: Context) {
            val intent = Intent(context, FgService::class.java)
            context.startForegroundService(intent)
        }

        fun stop(context: Context) {
            val intent = Intent(context, FgService::class.java)
            context.stopService(intent)
        }
    }

    override fun onBind(intent: Intent): IBinder? {
        return null
    }

    override fun onStartCommand(intent: Intent?, flags: Int, startId: Int): Int {
        Log.d(TAG, "onStartCommand")

        createNotificationChannel()
        val notification = createNotification()
        startForeground(1, notification)

        return START_STICKY
    }

    override fun onCreate() {
        Log.d(TAG, "onCreate")
        super.onCreate()
    }

    override fun onDestroy() {
        Log.d(TAG, "onDestroy")
        super.onDestroy()
    }

    override fun onTaskRemoved(rootIntent: Intent?) {
        Log.d(TAG, "onTaskRemoved")
        super.onTaskRemoved(rootIntent)
    }

    private fun createNotificationChannel() {
        val notMgr = NotificationManagerCompat.from(this)
        val fsChannel = notMgr.getNotificationChannel(channelId)
        if (fsChannel != null) {
            return
        }

        val channel = NotificationChannel(channelId, channelName, NotificationManager.IMPORTANCE_LOW)
        channel.enableVibration(false)
        channel.setShowBadge(false)

        notMgr.createNotificationChannel(channel)
    }

    private fun createNotification(): Notification {
        val notificationIntent = Intent(this, MainActivity::class.java)
        val pendingIntent = PendingIntent.getActivity(this, 0, notificationIntent, 0)

        return NotificationCompat.Builder(this, channelId)
            .setContentTitle(notificationTitle)
            .setContentText(notificationText)
            .setSmallIcon(R.drawable.ic_launcher_foreground)
            .setContentIntent(pendingIntent)
            .setStyle(NotificationCompat.BigTextStyle().bigText(notificationText))
            .build()
    }
}

build.gradle dependencies

dependencies {

    implementation 'androidx.core:core-ktx:1.6.0'
    implementation 'androidx.appcompat:appcompat:1.3.1'
    implementation 'com.google.android.material:material:1.4.0'
    implementation 'androidx.constraintlayout:constraintlayout:2.1.0'
    implementation 'androidx.navigation:navigation-fragment-ktx:2.3.5'
    implementation 'androidx.navigation:navigation-ui-ktx:2.3.5'
    implementation "androidx.work:work-runtime-ktx:2.4.0"
    implementation 'com.google.firebase:firebase-database-ktx:20.0.1'
    implementation 'org.jetbrains.kotlinx:kotlinx-coroutines-play-services:1.5.1'
    testImplementation 'junit:junit:4.+'
    androidTestImplementation 'androidx.test.ext:junit:1.1.3'
    androidTestImplementation 'androidx.test.espresso:espresso-core:3.4.0'
}

Require Foreground_Service permission in manifest.xml

    <uses-permission android:name="android.permission.FOREGROUND_SERVICE"/>

The firebase database project has only one node at \doc\id123 (See attached image)

Logcat and database:profile capture of the issue

rtdbworker.start1356_end1502.dbProfile.txt
rtdbworker.start1356_end1502.logcat.txt

[ebhsgit]

I have also noticed a NullPointerException every ~2.5 min with the app's production code.
Not sure if it related.

E/System: java.lang.NullPointerException: Null reference used for synchronization (monitor-enter)
        at com.android.org.conscrypt.ConscryptFileDescriptorSocket.finalize(ConscryptFileDescriptorSocket.java:1053)
        at java.lang.Daemons$FinalizerDaemon.doFinalize(Daemons.java:250)
        at java.lang.Daemons$FinalizerDaemon.runInternal(Daemons.java:237)

[ebhsgit]

Could be related to #2914

[aguatno]

Hi @ebhsgit sorry to hear you're running into this issue. I checked our system and it seems everything is running smoothly and couldn't find a similar issue. Just to confirm if the log below came from firebase.database.enableLogging(true)? If not could you share with us the debug logs from the console of the affected app? as explained here.

...
...
...
D/WebSocket: ws_61 - WebSocket reached EOF.
D/WebSocket: ws_61 - closing itself
D/Connection: conn_61 - Realtime connection lost

Also, if you could share a minimal repro, that would help us a lot digging into it.

[ebhsgit]

Hi @aguatno

Yes. The logs are from enabling Firebase Database logging.

The minimal code (and steps) to reproduce is already in the Relevant Code section...

[ebhsgit]

@aguatno

I've created a simple Android app with the supplied code
You can check it out here https://github.com/ebhsgit/firebase_rtdb_bug

To compile the project, you will need to copy and paste the google-services.json into the app folder.

[ebhsgit]

Hi @aguatno

Have you been able to reproduce the issue with the test project?
Let me know if you need more information.

[aguatno]

@ebhsgit thanks for the MCVE. I was able to run your app, though, do I have to write something on the Database? Also I'd like to ask if I am doing it correctly "clicked start service > worker > get value" back to home page and let the FgService and Worker run the background?

[ebhsgit]

@aguatno
Yes, that is correct.
Just need to Start Service and Start Worker. Then let them both continue to remain active in the background.
I also manually disable battery optimisation for the app vis Settings (Not sure if this step is required)

After sometime (don't know exactly, but several hours), the issue will present itself.

For the Database, it doesn't matter if any data exists at the doc path.
As long as Database instance is enabled, and the rules/permission to the path is allowed.
For my test project. I has left the Database rules in dev mode (allowed until a future date).
And only have one record

https://user-images.githubusercontent.com/48874658/132966166-c693cc0f-1209-4c9a-b2de-044a87a4255b.JPG