setPersistenceEnabled(true) and cache size not shrinking.

[whispernight]

Hi,

I have a question about this behavior since all information I found seems confusing. I have setPersistenceEnabled(true) with a RealTime Database. From what I read, I expect that by default, the cache size (sqlite db), does not grow over 10MB. I'm not using the keepSynced feature. My app performs many writes (1 every 10 seconds) and after months of use, the sqlite db (disk persistence) grows to a huge number (over 1GB).

If the app reboots, the firebase-database seems to go through this db upon the reboot and uses so much RAM that the device crashes. (Out of memory error)

Is this the intended behavior?

I went through the sdk firebase-database and I didn't find a prune or check for cache size after the database writes.

Here is a capture of my db already at 53.1 MB.

Thank you.

[schmidt-sebastian]

@whispernight Thanks for filing this issue and sorry for your trouble.

Can you confirm whether your app is able to connect to the backend? You can, for example, look for your writes in the Firebase Console.

We are only pruning data we have received from the backend, and not data that we still have to send. If we pruned data before sending, these writes would be lost. Thus, your local cache might exceed the cache size limit if your app has a large number of outstanding writes.

[whispernight]

@schmidt-sebastian Thank you I can confirm 100% that my app is connected and reading/writing from/to the backend. I never see the prune go off.

You said you only prune data received but not data that we still have to send; what about data that is already sent?

I can access this database that keeps growing and find all the records that I wrote into the back end. I never see a prune happen.

[schmidt-sebastian]

Data that has been sent to the backend should be removed immediately (unless you have an active query, in which case is tracked as part of the cache size).

Can you turn on logging and see if you can spot any of these log lines? https://github.com/firebase/firebase-android-sdk/blob/00d46269f1ef9ce0f1dd69ab727137a84332d85c/firebase-database/src/main/java/com/google/firebase/database/core/persistence/DefaultPersistenceManager.java#L248 Thanks!

[whispernight]

I turned on logging: database.setPersistenceEnabled(true); database.setLogLevel(Logger.Level.DEBUG);

This is how I write to firebase:

vistarFirebasePopRef.push().setValue(advertisement);

I don't see anything in the logs that contains the word 'cache' or 'prune'

I also tried debugging and putting a breakpoint right at the beggining of 'doPruneCheckAfterServerUpdate' but the breakpoint is never reached.

[schmidt-sebastian]

Can you share your logs?

[whispernight]

09-10 13:37:52.569 8250-8250/? W/FA: Application context is not an Application 09-10 13:37:52.572 8250-8272/? E/FA: Persisted config not initialized. Not logging error/warn 09-10 13:37:52.620 8250-8272/? I/FA: App measurement is starting up, version: 14710 09-10 13:37:52.620 8250-8272/? I/FA: To enable debug logging run: adb shell setprop log.tag.FA VERBOSE 09-10 13:37:52.620 8250-8272/? I/FA: To enable faster debug mode event logging run: adb shell setprop debug.firebase.analytics.app com.lf 09-10 13:37:52.620 8250-8272/? D/FA: Debug-level message logging enabled 09-10 13:37:52.646 8250-8282/? E/FirebaseInstanceId: Google Play services missing or without correct permission. 09-10 13:37:52.678 8250-8272/? W/FA: Service invalid 09-10 13:37:52.710 8250-8282/? E/FirebaseInstanceId: Google Play services missing or without correct permission. 09-10 13:37:53.777 1056-1056/? W/IInputConnectionWrapper: showStatusIcon on inactive InputConnection 09-10 13:37:53.787 8250-8272/com.lf I/FA: This instance being marked as an uploader 09-10 13:37:53.909 8250-8272/com.lf D/FA: Unable to get advertising id: com.google.android.gms.common.GooglePlayServicesNotAvailableException: com.google.android.gms.measurement.internal.zzbd.zzbz(Unknown Source) 09-10 13:38:13.152 8250-8341/com.lf D/PersistentConnection: pc_0 - Scheduling connection attempt 09-10 13:38:13.153 8250-8341/com.lf D/ConnectionRetryHelper: Scheduling retry in 0ms 09-10 13:38:13.169 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:38:13.303 8250-8341/com.lf D/Persistence: Reset active tracked queries in 134ms 09-10 13:38:13.320 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 151ms 09-10 13:38:22.692 8250-8341/com.lf D/Persistence: Loaded 88214 tracked queries in 9372ms 09-10 13:38:29.163 8250-8341/com.lf D/Persistence: Loaded 0 writes in 1ms 09-10 13:38:29.168 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:38:29.169 8250-8341/com.lf D/Persistence: Saved new tracked query in 0ms 09-10 13:38:29.182 8250-8341/com.lf D/Persistence: Loaded a total of 5 rows for a total of 9 nodes at /assets/SMT-UKMCCH in 10ms (Query: 0ms, Loading: 7ms, Serializing: 3ms) 09-10 13:38:29.190 8250-8341/com.lf D/PersistentConnection: pc_0 - Listening on assets/SMT-UKMCCH (params: {}) 09-10 13:38:29.191 8250-8341/com.lf D/PersistentConnection: pc_0 - Adding listen query: assets/SMT-UKMCCH (params: {}) 09-10 13:38:29.201 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 32ms 09-10 13:38:29.201 8250-8341/com.lf D/EventRaiser: Raising 1 event(s) 09-10 13:38:29.202 8250-8341/com.lf D/PersistentConnection: pc_0 - Trying to fetch auth token 09-10 13:38:29.202 8250-8250/com.lf D/EventRaiser: Raising /assets/SMT-UKMCCH: VALUE: {paramount_feature_enabled=true, description=Angel, console_product_type=Superman, paramount_feature_enabled_date=1567731088153, id=SMT-UKMCCH, registeredto=true, facility_id=20, facilityChange_count=7, corp_config=Angel_dev} 09-10 13:38:29.208 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:38:29.209 8250-8341/com.lf D/Persistence: Saved new tracked query in 1ms 09-10 13:38:29.222 8250-8341/com.lf D/Persistence: Loaded a total of 1 rows for a total of 204 nodes at /apple_config in 12ms (Query: 1ms, Loading: 5ms, Serializing: 6ms) 09-10 13:38:29.222 8250-8341/com.lf D/PersistentConnection: pc_0 - Listening on apple_config (params: {}) 09-10 13:38:29.222 8250-8341/com.lf D/PersistentConnection: pc_0 - Adding listen query: apple_config (params: {}) 09-10 13:38:29.227 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 19ms 09-10 13:38:29.227 8250-8341/com.lf D/EventRaiser: Raising 1 event(s) 09-10 13:38:29.228 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:38:29.228 8250-8341/com.lf D/Persistence: Saved new tracked query in 0ms 09-10 13:38:29.232 8250-8250/com.lf D/EventRaiser: Raising /apple_config: VALUE: {25={_enabled=false, rfid_enabled=true, nfc_enabled=true, csafe_id=128}, 10={_enabled=false, rfid_enabled=false, nfc_enabled=false, csafe_id=113}, 5={_enabled=true, rfid_enabled=true, nfc_enabled=true, csafe_id=94}, 49={_enabled=false, rfid_enabled=true, nfc_enabled=true, csafe_id=152}, 35={_enabled=false, rfid_enabled=true, nfc_enabled=true, csafe_id=138}, 38={_enabled=false, rfid_enabled=true, nfc_enabled=true, csafe_id=141}, 36={_enabled=true, rfid_enabled=true, nfc_enabled=true, csafe_id=139}, 19={_enabled=false, rfid_enabled=false, nfc_enabled=false, csafe_id=122}, 6={_enabled=false, rfid_enabled=true, nfc_enabled=true, csafe_id=95}, 31={_enabled=false, rfid_enabled=false, nfc_enabled=false, csafe_id=134}, 12={_enabled=false, rfid_enabled=false, nfc_enabled=false, csafe_id=115}, 28={_enabled=false, rfid_enabled=false, nfc_enabled=false, csafe_id=131}, 7={_enabled=false, rfid_enabled=false, nfc_enabled=false, csafe_id=110}, 4={_enabled=true, rfid_enabled=false, nfc_enabled=false, csafe_id=93}, 20={_enabled=false, rfid_enabled=false, nfc_enabled=false, csafe_id=123}, 17={_enabled=false, rfid_enabled=true, nfc_enabled=true, csafe_id=120}, 22={_enabled=false, rfid_enabled=false, nfc_enabled=false, csafe_id=125}, 1={_enabled=false, rfid_enabled=true, nfc_enabled=true, csafe_id=90}, 34={_enabled=false, rfid_enabled=true, nfc_enabled=true, csafe_id=137}, 0={_enabled=true, rfid_enabled=false, nfc_enabled=false, csafe_id=89}, 9={_enabled=false, rfid_enabled=false, nfc_enabled=false, csafe_id=112}, 24={_enabled=false, rfid_enabled=false, nfc_enabled=false, csafe_id=127}, 26={_enabled=false, rfid_enabled=false, nfc_enabled=false, csafe_id=129}, 23={_enabled=false, rfid_enabled=false, nfc_enabled=false, csafe_id=126}, 42={_enabled=true, rfid_enabled=true, nfc_enabled=true, csafe_id=145}, 41={_enabled=false, rfid_enabled=true, nfc_enabled=true, csafe_id=144}, 40={_enabled=false, rfid_enabled=false, nfc_enabled=false, csafe_id=143}, 15={_enabled=false, rfid_enabled=false, nfc_enabled=false, csafe_id=118}, 30={_enabled=false, rfid_enabled=false, nfc_enabled=false, csafe_id=133}, 18={_enabled=false, rfid_enabled=false, nfc_enabled=false, csafe_id=121}, 14={_enabled=true, rfid_enabled=true, nfc_enabled=true, csafe_id=117}, 2={_enabled=true, rfid_enabled=true, nfc_enabled=true, csafe_id=91}, 13={_enabled=false, rfid_enabled=false, nfc_enabled=false, csafe_id=116}, 8={_enabled=false, rfid_enabled=false, nfc_enabled=false, csafe_id=111}, 39={_enabled=false, rfid_enabled=true, nfc_enabled=true, csafe_id=142}, 27={_enabled=false, rfid_enabled=false, nfc_enabled=false, csafe_id=130}, 16={_enabled=false, rfid_enabled=false, nfc_enabled=false, csafe_id=119}, 32={_enabled=false, rfid_enabled=false, nfc_enabled=false, csafe_id=135}, 3={_enabled=false, rfid_enabled=true, nfc_enabled=true, csafe_id=92}, 44={_enabled=true, rfid_enabled=true, nfc_enabled=true, csafe_id=147}, 48={_enabled=false, rfid_enabled=false, nfc_enabled=false, csafe_id=151}, 46={_enabled=false, rfid_enabled=true, nfc_enabled=true, csafe_id=149}, 29={_enabled=false, rfid_enabled=false, nfc_enabled=false, csafe_id=132}, 45={_enabled=true, rfid_enabled=true, nfc_enabled=true, csafe_id=148}, 21={_enabled=false, rfid_enabled=false, nfc_enabled=false, csafe_id=124}, 11={_enabled=false, rfid_enabled=false, nfc_enabled=false, csafe_id=114}, 43={_enabled=true, rfid_enabled=true, nfc_enabled=true, csafe_id=146}, 47={plane 09-10 13:38:29.423 8250-8341/com.lf D/Persistence: Loaded a total of 193 rows for a total of 6351 nodes at /scale_workoutsv2 in 180ms (Query: 1ms, Loading: 23ms, Serializing: 156ms) 09-10 13:38:29.424 8250-8341/com.lf D/PersistentConnection: pc_0 - Listening on scale_workoutsv2 (params: {}) 09-10 13:38:29.424 8250-8341/com.lf D/PersistentConnection: pc_0 - Adding listen query: scale_workoutsv2 (params: {}) 09-10 13:38:29.436 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 208ms 09-10 13:38:29.436 8250-8341/com.lf D/EventRaiser: Raising 1 event(s) 09-10 13:38:29.436 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:38:29.437 8250-8341/com.lf D/Persistence: Saved new tracked query in 1ms 09-10 13:38:29.439 8250-8341/com.lf D/Persistence: Loaded a total of 1 rows for a total of 15 nodes at /corp_configs/v1/Angel_dev in 2ms (Query: 1ms, Loading: 0ms, Serializing: 1ms) 09-10 13:38:29.439 8250-8341/com.lf D/PersistentConnection: pc_0 - Listening on corp_configs/v1/Angel_dev (params: {}) 09-10 13:38:29.439 8250-8341/com.lf D/PersistentConnection: pc_0 - Adding listen query: corp_configs/v1/Angel_dev (params: {}) 09-10 13:38:29.444 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 8ms 09-10 13:38:29.444 8250-8341/com.lf D/EventRaiser: Raising 1 event(s) 09-10 13:38:29.445 8250-8341/com.lf D/PersistentConnection: pc_0 - Successfully fetched token, opening connection 09-10 13:38:29.450 8250-8341/com.lf D/Connection: conn_0 - Opening a connection 09-10 13:38:29.531 8250-8250/com.lf D/EventRaiser: Raising /scale_workoutsv2: VALUE: {workouts={-LkPbGhSjFsqgI23pX0J={customSortKeys={mosaic_promo=AAAAPw==}, description={defaultLocale=en-US, defaultValue=This 35 minute intermediate class combines speed and hill intervals with walking and active recoveries.}, isPresentationMetric=false, imageDrawable=img_ad72068c968b458fbcbd62eda7d2833e_full, workoutType=mosaic, name={defaultLocale=en-US, defaultValue=Intermediate Fusion - Nikki}, imageUrl=https://firebasestorage.googleapis.com/v0/b/dev_workout_assets/o/img_ad72068c968b458fbcbd62eda7d2833e_full.jpg?alt=media, workoutID=-LkPbGhSjFsqgI23pX0J, tags={Language=en-US, TerrainCapable=false, DateAdded=1562648400, GoalType=time, Goal=true, uniqueIdentifier=ad72068c-968b-458f-bcbd-62eda7d2833e, Scenic=false, BaseType=T, RunningPlan=undefined, InstructorLed=true, Intensity=intermediate, GoalUnit=min, ClosedCaption=false, EasyStart=true, Test=false, ActualGoalValue=2100, InstructorName=Nikki, Author=NEOU, Music=true, courseType=fusion, GoalValue=35, ChangeWorkoutCapable=true, Performance=false, feedFMvolume=0.1, feedFMstation=funrun, feedFMcutOffMilliseconds=15000, HeadphonesNeeded=true}, courseID=349483595}, -LZfat5yrOmWIiH2KTND={name={defaultLocale=en, resourceName=IDSA_FAMS, translationMap={da=FAMS, sv=FAMS}, defaultValue=FAMS}, workoutID=-LZfat5yrOmWIiH2KTND, description={defaultLocale=en, defaultValue=This workout is a 12-minute biking alternative to the 1.5-mile run required as part of the Federal Air Marshal Service Physical Training Assessment.}, tags={GoalUnit=min, ClosedCaption=false, EasyStart=false, Test=true, TerrainCapable=false, DateAdded=1556730599, Music=false, LoginSuggested=false, GoalType=time, GoalValue=12, ChangeWorkoutCapable=false, HeartRateStrapSuggested=false, Performance=false, ExternalApplicationLaunch=false, Goal=true, Scenic=false, HeadphonesNeeded=false, BaseType=R,C, RunningPlan=undefined, InstructorLed=false, author=****, Intensity=undefined}, imageDrawable=img_fams_large, courseID=, workoutType=fams}, -LZfat5w2_j0uQZjF-Y5={name={defaultLocale=en, resourceName=IDSA_METS, translationMap={zh_CN=MET, ja=メッツ, da=METS, tr=MET, fr=METs, de=MET, eu=METak, ar=مكافئات الأيض, nl=METS, pl=Równoważniki metaboliczne (MET), it=MET, fi=MET, en_GB=METs, sv=MET-värden, cy=METs, ca=MET, pt=METs, iw=יחידות שווה ערך מטבולי (MET), hu=MET, ru=МЕТы, zh_TW=MET, es=MET, ko=MET}, defaultValue=METs}, workoutID=-LZfat5w2_j0uQZjF-Y5, description={defaultLocale=en, defaultValue=Choose your calorie burn by selecting constant METs intensity during your workout.}, tags={ClosedCaption=false, EasyStart=false, Test=false, TerrainCapable=false, DateAdded=1556730599, Music=false, LoginSuggested=false, GoalType=undefined, ChangeWorkoutCapable=true, HeartRateStrapSuggested=false, Performance=false, ExternalApplicationLaunch=false, Goal=true, Scenic=false, HeadphonesNeeded=false, BaseType=R,C, RunningPlan=undefined, InstructorLed=false, author=****, Intensity=undefined}, imageDrawable=img_mets_large, courseID=, workoutType=mets_workout}, -L_KE9nLYuVQUxbrUTiM={name={defaultLocale=en, defaultValue=Panama Run}, workoutID=-L_KE9nLYuVQUxbrUTiM, description={defaultLocale=en, defaultValue=Visit a lush tropical rainforest, a remote island paradise, Central America's most impressive metropolis, and one of the world's most famous engineering feats in this running tour of Panama. You'll see the famous canal up close before heading into the jungle in search of Panama's wild side.}, tags={ClosedCaption=false, EasyStart=false, Test=false, TerrainCapable=false, DateAdded=1556730599, Music=false, LoginSuggested=false, GoalType=undefined, ChangeWorkoutCapable=true, HeartRateStrapSuggested=false, Performance=false, ExternalApplicationLaunch=false, Goal=true, Scenic=true, HeadphonesNeeded=false, BaseType=T,M, RunningPlan=undefined, InstructorLed=false, author=****, Intensity=undefined}, courseID=LFRNPK0501, workoutType=scape}, -LZfat6352x99L_ddNGm={name={defaultLocale=en, default 09-10 13:38:29.637 8250-8341/com.lf D/WebSocket: ws_0 - websocket opened 09-10 13:38:29.637 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive 09-10 13:38:29.642 8250-8366/com.lf D/WebSocket: ws_0 - ws message: {"t":"c","d":{"t":"h","d":{"ts":1568140737183,"v":"5","h":".firebaseio.com","s":"XLHA8v3mvZm218vJP9sVSIwE3et0OOut"}}} 09-10 13:38:29.642 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 44995 09-10 13:38:29.644 8250-8341/com.lf D/WebSocket: ws_0 - HandleNewFrameCount: 1 09-10 13:38:29.645 8250-8341/com.lf D/WebSocket: ws_0 - handleIncomingFrame complete frame: {d={d={v=5, h=.firebaseio.com, ts=1568140737183, s=XLHA8v3mvZm218vJP9sVSIwE3et0OOut}, t=h}, t=c} 09-10 13:38:29.645 8250-8341/com.lf D/Connection: conn_0 - Got control message: {d={v=5, h=.firebaseio.com, ts=1568140737183, s=XLHA8v3mvZm218vJP9sVSIwE3et0OOut}, t=h} 09-10 13:38:29.645 8250-8341/com.lf D/Connection: conn_0 - realtime connection established 09-10 13:38:29.645 8250-8341/com.lf D/PersistentConnection: pc_0 - onReady 09-10 13:38:29.645 8250-8341/com.lf D/PersistentConnection: pc_0 - handling timestamp 09-10 13:38:29.646 8250-8341/com.lf D/PersistentConnection: pc_0 - Sending first connection stats 09-10 13:38:29.647 8250-8341/com.lf D/Connection: conn_0 - Sending data: {} 09-10 13:38:29.647 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 44995 09-10 13:38:29.648 8250-8341/com.lf D/PersistentConnection: pc_0 - calling restore state 09-10 13:38:29.648 8250-8341/com.lf D/PersistentConnection: pc_0 - Not restoring auth because token is null. 09-10 13:38:29.648 8250-8341/com.lf D/PersistentConnection: pc_0 - Restoring outstanding listens 09-10 13:38:29.648 8250-8341/com.lf D/PersistentConnection: pc_0 - Restoring listen apple_config (params: {}) 09-10 13:38:29.673 8250-8366/com.lf D/WebSocket: ws_0 - ws message: {"t":"d","d":{"r":0,"b":{"s":"ok","d":""}}} 09-10 13:38:29.762 8250-8341/com.lf D/Connection: conn_0 - Sending data: {} 09-10 13:38:29.762 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 44885 09-10 13:38:29.763 8250-8341/com.lf D/PersistentConnection: pc_0 - Restoring listen corp_configs/v1/Angel_dev (params: {}) 09-10 13:38:29.778 8250-8341/com.lf D/Connection: conn_0 - Sending data: {} 09-10 13:38:29.778 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 44983 09-10 13:38:29.779 8250-8341/com.lf D/PersistentConnection: pc_0 - Restoring listen scale_workoutsv2 (params: {}) 09-10 13:38:29.784 8250-8366/com.lf D/WebSocket: ws_0 - ws message: {"t":"d","d":{"r":1,"b":{"s":"ok","d":{}}}} 09-10 13:38:29.804 8250-8366/com.lf D/WebSocket: ws_0 - ws message: {"t":"d","d":{"r":2,"b":{"s":"ok","d":{}}}} 09-10 13:38:30.043 8250-8250/com.lf D/EventRaiser: Raising /corp_configs/v1/Angel_dev: VALUE: {summaryImageID=workoutSummary, files={workoutSummary=https://firebasestorage.googleapis.com/v0/b/.appspot.com/o/advertising_demo%2FworkoutsummaryHD.jpg?alt=media&token=e9300cb7-0017-4c40-8d38-be2c3e4539bc, attract3=https://firebasestorage.googleapis.com/v0/b/****.appspot.com/o/images%2Fadvertising%2FAngel%2F2018_yamaha_yzf_r1m_4k-wide.zip?alt=media&token=3dbc509b-fa9f-48b8-ac89-80833d3ba39e, attract2=https://firebasestorage.googleapis.com/v0/b/****.appspot.com/o/images%2Fadvertising%2FAngel%2F2017_yamaha_fz_10-wide.zip?alt=media&token=2d14082e-0e91-4666-a27e-8b1c08da1976, attract4=https://firebasestorage.googleapis.com/v0/b/****.appspot.com/o/images%2Fadvertising%2FAngel%2Fbmw_hp4_race_4k-wide.zip?alt=media&token=f29e6fd1-e6db-4d75-a01e-dccbcc0b8dd2, attract5=https://firebasestorage.googleapis.com/v0/b/****.appspot.com/o/images%2Fadvertising%2FAngel%2Fktm_1290_super_duke-wide.zip?alt=media&token=595186b0-e1d4-4acf-bf12-7028a5a6d27e, countdownImage=https://firebasestorage.googleapis.com/v0/b/****.appspot.com/o/advertising_demo%2FcountdownHD.jpg?alt=media&token=e9300cb7-0017-4c40-8d38-be2c3e4539bc, attract1=https://firebasestorage.googleapis.com/v0/b/****.appspot.com/o/images%2Fadvertising%2FAngel%2F2017_kawasaki_ninja_h2_4k-wide.zip?alt=media&token=af6c9bda-a280-46e1-9d10-1d71bc29a322}, countdownImageID=countdownImage, attract_images={d=attract4, a=attract1, b=attract2, c=attract3, e=attract5}, theme=default} 09-10 13:38:30.056 8250-8250/com.lf D/LFATimer: reset timer : 0x39c6a803 timeOut = 30000 09-10 13:38:31.406 8250-8341/com.lf D/Connection: conn_0 - Sending data: {} 09-10 13:38:31.406 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 43372 09-10 13:38:31.408 8250-8341/com.lf D/PersistentConnection: pc_0 - Restoring listen assets/SMT-UKMCCH (params: {}) 09-10 13:38:31.410 8250-8341/com.lf D/Connection: conn_0 - Sending data: {} 09-10 13:38:31.410 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 44995 09-10 13:38:31.411 8250-8341/com.lf D/PersistentConnection: pc_0 - Restoring writes. 09-10 13:38:31.411 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 44999 09-10 13:38:31.411 8250-8341/com.lf D/WebSocket: ws_0 - HandleNewFrameCount: 1 09-10 13:38:31.411 8250-8341/com.lf D/WebSocket: ws_0 - handleIncomingFrame complete frame: {d={r=0, b={d=, s=ok}}, t=d} 09-10 13:38:31.411 8250-8341/com.lf D/Connection: conn_0 - received data message: {r=0, b={d=, s=ok}} 09-10 13:38:31.411 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 44999 09-10 13:38:31.412 8250-8341/com.lf D/WebSocket: ws_0 - HandleNewFrameCount: 1 09-10 13:38:31.412 8250-8341/com.lf D/WebSocket: ws_0 - handleIncomingFrame complete frame: {d={r=1, b={d={}, s=ok}}, t=d} 09-10 13:38:31.412 8250-8341/com.lf D/Connection: conn_0 - received data message: {r=1, b={d={}, s=ok}} 09-10 13:38:31.412 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:38:31.417 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 4ms 09-10 13:38:31.417 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 44994 09-10 13:38:31.417 8250-8341/com.lf D/WebSocket: ws_0 - HandleNewFrameCount: 1 09-10 13:38:31.417 8250-8341/com.lf D/WebSocket: ws_0 - handleIncomingFrame complete frame: {d={r=2, b={d={}, s=ok}}, t=d} 09-10 13:38:31.418 8250-8341/com.lf D/Connection: conn_0 - received data message: {r=2, b={d={}, s=ok}} 09-10 13:38:31.418 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:38:31.418 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 0ms 09-10 13:38:31.455 8250-8366/com.lf D/WebSocket: ws_0 - ws message: {"t":"d","d":{"r":3,"b":{"s":"ok","d":{}}}} 09-10 13:38:31.456 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 44961 09-10 13:38:31.456 8250-8341/com.lf D/WebSocket: ws_0 - HandleNewFrameCount: 1 09-10 13:38:31.456 8250-8341/com.lf D/WebSocket: ws_0 - handleIncomingFrame complete frame: {d={r=3, b={d={}, s=ok}}, t=d} 09-10 13:38:31.456 8250-8341/com.lf D/Connection: conn_0 - received data message: {r=3, b={d={}, s=ok}} 09-10 13:38:31.456 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:38:31.457 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 0ms 09-10 13:38:31.457 8250-8366/com.lf D/WebSocket: ws_0 - ws message: {"t":"d","d":{"r":4,"b":{"s":"ok","d":{}}}} 09-10 13:38:31.458 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 44998 09-10 13:38:31.458 8250-8341/com.lf D/WebSocket: ws_0 - HandleNewFrameCount: 1 09-10 13:38:31.458 8250-8341/com.lf D/WebSocket: ws_0 - handleIncomingFrame complete frame: {d={r=4, b={d={}, s=ok}}, t=d} 09-10 13:38:31.458 8250-8341/com.lf D/Connection: conn_0 - received data message: {r=4, b={d={}, s=ok}} 09-10 13:38:31.458 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:38:31.461 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 2ms 09-10 13:38:46.825 8250-8341/com.lf D/RepoOperation: set: /assets/SMT-UKMCCH/facility_id 09-10 13:38:46.825 8250-8341/com.lf D/DataOperation: set: /assets/SMT-UKMCCH/facility_id 20 09-10 13:38:46.826 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:38:46.829 8250-8341/com.lf D/Persistence: Persisted user overwrite in 2ms 09-10 13:38:46.848 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 20ms 09-10 13:38:46.852 8250-8341/com.lf D/Connection: conn_0 - Sending data: {} 09-10 13:38:46.853 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 29605 09-10 13:38:46.854 8250-8341/com.lf D/RepoOperation: Aborting transactions for path: /assets/SMT-UKMCCH/facility_id. Affected: /assets/SMT-UKMCCH/facility_id 09-10 13:38:46.859 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:38:46.862 8250-8341/com.lf D/Persistence: Saved new tracked query in 2ms 09-10 13:38:46.873 8250-8341/com.lf D/Persistence: Loaded a total of 2 rows for a total of 95 nodes at /facilities/20 in 9ms (Query: 0ms, Loading: 3ms, Serializing: 6ms) 09-10 13:38:46.874 8250-8341/com.lf D/PersistentConnection: pc_0 - Listening on facilities/20 (params: {}) 09-10 13:38:46.874 8250-8341/com.lf D/PersistentConnection: pc_0 - Adding listen query: facilities/20 (params: {}) 09-10 13:38:46.875 8250-8366/com.lf D/WebSocket: ws_0 - ws message: {"t":"d","d":{"r":5,"b":{"s":"ok","d":""}}} 09-10 13:38:46.907 8250-8341/com.lf D/Connection: conn_0 - Sending data: {} 09-10 13:38:46.907 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 44946 09-10 13:38:46.914 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 54ms 09-10 13:38:46.914 8250-8341/com.lf D/EventRaiser: Raising 1 event(s) 09-10 13:38:46.917 8250-8250/com.lf D/EventRaiser: Raising /facilities/20: VALUE: {lon=-87.89102500000001, facilityEndTime=8:30, city=Franklin Park, historyLog={1={0=Ads, 1=Disabled, 2=1562962037580, 3=1565023396219}, 10={0=Ads, 1=Enabled, 2=1567715935904, 3=1567716497869}, 5={0=Ads, 1=Disabled, 2=1567088108519, 3=1567088201261}, 0={0=Ads, 1=Enabled, 2=1561126582927, 3=1562962037580}, 14={0=Ads, 1=Enabled, 2=1567716660047, 3=1568059913062}, 11={0=Ads, 1=Disabled, 2=1567716497869, 3=1567716505888}, 9={0=Ads, 1=Disabled, 2=1567715927288, 3=1567715935904}, 2={0=Ads, 1=Enabled, 2=1565023396219, 3=1567084230987}, 13={0=Ads, 1=Disabled, 2=1567716651316, 3=1567716660047}, 8={0=Ads, 1=Enabled, 2=1567715178819, 3=1567715927287}, 6={0=Ads, 1=Enabled, 2=1567088201261, 3=1567715080273}, 16={0=Ads, 1=Enabled, 2=1568059980472, 3=NOW}, 15={0=Ads, 1=Disabled, 2=1568059913062, 3=1568059980472}, 12={0=Ads, 1=Enabled, 2=1567716505888, 3=1567716651316}, 7={0=Ads, 1=Disabled, 2=1567715080273, 3=1567715178819}, 4={0=Ads, 1=Enabled, 2=1567084247618, 3=1567088108519}, 3={0=Ads, 1=Disabled, 2=1567084230987, 3=1567084247618}}, phoneNo=8472883428, mqttLogWorkoutDataEnabled=true, modification_in_progress=false, facId=20, groupId=0, _locationName=20_Franklin Park Showroom Gym, ads_enabled=true, products_enabled={0=Aquaman, 1=Superman, 2=Bluth}, ipAddress=40.129.193.200, _config=NA, address=10601 Belmont Avenue, createdDate=11/19/2012, _locationId=07ol57PpSwGn2Hh3OFDLag, facName=Franklin Park Showroom Gym, state=Illinois, facilityStartTime=8:0, timezone=America/Chicago, postalCode=60131, country=United States of America, error_in_progress=, lat=41.9355297, mqttLogStatusEnabled=true} 09-10 13:38:46.925 8250-8341/com.lf D/RepoOperation: set: /assets/SMT-UKMCCH/console_product_type 09-10 13:38:46.925 8250-8341/com.lf D/DataOperation: set: /assets/SMT-UKMCCH/console_product_type Superman 09-10 13:38:46.925 8250-8366/com.lf D/WebSocket: ws_0 - ws message: {"t":"d","d":{"r":6,"b":{"s":"ok","d":{}}}} 09-10 13:38:46.925 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:38:46.929 8250-8341/com.lf D/Persistence: Persisted user overwrite in 3ms 09-10 13:38:46.947 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 21ms 09-10 13:38:46.948 8250-8341/com.lf D/Connection: conn_0 - Sending data: {} 09-10 13:38:46.948 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 44958 09-10 13:38:46.950 8250-8341/com.lf D/RepoOperation: Aborting transactions for path: /assets/SMT-UKMCCH/console_product_type. Affected: /assets/SMT-UKMCCH/console_product_type 09-10 13:38:46.950 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:38:46.951 8250-8341/com.lf D/Persistence: Saved new tracked query in 1ms 09-10 13:38:46.962 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 12ms 09-10 13:38:46.963 8250-8341/com.lf D/EventRaiser: Raising 1 event(s) 09-10 13:38:46.963 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 44985 09-10 13:38:46.963 8250-8250/com.lf D/EventRaiser: Raising /facilities/20/_config: VALUE: NA 09-10 13:38:46.963 8250-8341/com.lf D/WebSocket: ws_0 - HandleNewFrameCount: 1 09-10 13:38:46.963 8250-8341/com.lf D/WebSocket: ws_0 - handleIncomingFrame complete frame: {d={r=5, b={d=, s=ok}}, t=d} 09-10 13:38:46.963 8250-8341/com.lf D/Connection: conn_0 - received data message: {r=5, b={d=, s=ok}} 09-10 13:38:46.963 8250-8341/com.lf D/PersistentConnection: pc_0 - p response: {d=, s=ok} 09-10 13:38:46.964 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:38:46.965 8250-8341/com.lf D/Persistence: Deleted 1 write(s) with writeId 1 in 0ms 09-10 13:38:46.973 8250-8366/com.lf D/WebSocket: ws_0 - ws message: {"t":"d","d":{"r":7,"b":{"s":"ok","d":""}}} 09-10 13:38:46.981 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 15ms 09-10 13:38:46.985 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 44978 09-10 13:38:46.985 8250-8341/com.lf D/WebSocket: ws_0 - HandleNewFrameCount: 1 09-10 13:38:46.985 8250-8341/com.lf D/WebSocket: ws_0 - handleIncomingFrame complete frame: {d={r=6, b={d={}, s=ok}}, t=d} 09-10 13:38:46.985 8250-8341/com.lf D/Connection: conn_0 - received data message: {r=6, b={d={}, s=ok}} 09-10 13:38:46.985 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:38:46.987 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 1ms 09-10 13:38:46.987 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:38:46.988 8250-8341/com.lf D/Persistence: Saved new tracked query in 1ms 09-10 13:38:46.989 8250-8341/com.lf D/Persistence: Loaded a total of 1 rows for a total of 3 nodes at /_configs/NA in 1ms (Query: 0ms, Loading: 1ms, Serializing: 0ms) 09-10 13:38:46.990 8250-8341/com.lf D/PersistentConnection: pc_0 - Listening on _configs/NA (params: {}) 09-10 13:38:46.990 8250-8341/com.lf D/PersistentConnection: pc_0 - Adding listen query: _configs/NA (params: {}) 09-10 13:38:46.991 8250-8341/com.lf D/Connection: conn_0 - Sending data: {} 09-10 13:38:46.991 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 44993 09-10 13:38:47.002 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 15ms 09-10 13:38:47.002 8250-8341/com.lf D/EventRaiser: Raising 1 event(s) 09-10 13:38:47.003 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 44988 09-10 13:38:47.003 8250-8341/com.lf D/WebSocket: ws_0 - HandleNewFrameCount: 1 09-10 13:38:47.003 8250-8341/com.lf D/WebSocket: ws_0 - handleIncomingFrame complete frame: {d={r=7, b={d=, s=ok}}, t=d} 09-10 13:38:47.004 8250-8341/com.lf D/Connection: conn_0 - received data message: {r=7, b={d=, s=ok}} 09-10 13:38:47.004 8250-8341/com.lf D/PersistentConnection: pc_0 - p response: {d=, s=ok} 09-10 13:38:47.004 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:38:47.007 8250-8341/com.lf D/Persistence: Deleted 1 write(s) with writeId 2 in 1ms 09-10 13:38:47.012 8250-8366/com.lf D/WebSocket: ws_0 - ws message: {"t":"d","d":{"r":8,"b":{"s":"ok","d":{}}}} 09-10 13:38:47.018 8250-8250/com.lf D/EventRaiser: Raising /_configs/NA: VALUE: {server_url=https://sandbox-api.****.com, api_key=18b603fd-06c4-485e-9596-54855a34dfe3, network_id=ufNheiORTlG5gqPulWAWcw} 09-10 13:38:47.028 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 23ms 09-10 13:38:47.028 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 44974 09-10 13:38:47.029 8250-8341/com.lf D/WebSocket: ws_0 - HandleNewFrameCount: 1 09-10 13:38:47.031 8250-8341/com.lf D/WebSocket: ws_0 - handleIncomingFrame complete frame: {d={r=8, b={d={}, s=ok}}, t=d} 09-10 13:38:47.031 8250-8341/com.lf D/Connection: conn_0 - received data message: {r=8, b={d={}, s=ok}} 09-10 13:38:47.031 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:38:47.033 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 0ms 09-10 13:39:01.748 8250-8341/com.lf D/RepoOperation: set: /_inbox/-LoRTIUymjL8V1WwK3SL 09-10 13:39:01.748 8250-8341/com.lf D/DataOperation: set: /_inbox/-LoRTIUymjL8V1WwK3SL { advertiser=FP demo } 09-10 13:39:01.749 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:39:01.750 8250-8341/com.lf D/Persistence: Persisted user overwrite in 1ms 09-10 13:39:01.763 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 14ms 09-10 13:39:01.764 8250-8341/com.lf D/Connection: conn_0 - Sending data: {} 09-10 13:39:01.764 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 30264 09-10 13:39:01.767 8250-8341/com.lf D/RepoOperation: Aborting transactions for path: /_inbox/-LoRTIUymjL8V1WwK3SL. Affected: /_inbox/-LoRTIUymjL8V1WwK3SL 09-10 13:39:01.787 8250-8366/com.lf D/WebSocket: ws_0 - ws message: {"t":"d","d":{"r":9,"b":{"s":"ok","d":""}}} 09-10 13:39:01.788 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 44976 09-10 13:39:01.788 8250-8341/com.lf D/WebSocket: ws_0 - HandleNewFrameCount: 1 09-10 13:39:01.788 8250-8341/com.lf D/WebSocket: ws_0 - handleIncomingFrame complete frame: {d={r=9, b={d=, s=ok}}, t=d} 09-10 13:39:01.788 8250-8341/com.lf D/Connection: conn_0 - received data message: {r=9, b={d=, s=ok}} 09-10 13:39:01.788 8250-8341/com.lf D/PersistentConnection: pc_0 - p response: {d=, s=ok} 09-10 13:39:01.788 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:39:01.789 8250-8341/com.lf D/Persistence: Deleted 1 write(s) with writeId 3 in 1ms 09-10 13:39:01.792 8250-8341/com.lf D/Persistence: Persisted a total of 1 rows and deleted 0 rows for a set at /_inbox/-LoRTIUymjL8V1WwK3SL in 2ms 09-10 13:39:01.792 8250-8341/com.lf D/Persistence: Saved new tracked query in 0ms 09-10 13:39:01.806 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 18ms 09-10 13:39:12.096 8250-8341/com.lf D/RepoOperation: set: /_inbox/-LoRTL0kzikYGuUp_3Lg 09-10 13:39:12.096 8250-8341/com.lf D/DataOperation: set: /_inbox/-LoRTL0kzikYGuUp_3Lg { advertiser=FP demo } 09-10 13:39:12.096 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:39:12.098 8250-8341/com.lf D/Persistence: Persisted user overwrite in 1ms 09-10 13:39:12.107 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 10ms 09-10 13:39:12.108 8250-8341/com.lf D/Connection: conn_0 - Sending data: {} 09-10 13:39:12.108 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 34679 09-10 13:39:12.109 8250-8341/com.lf D/RepoOperation: Aborting transactions for path: /_inbox/-LoRTL0kzikYGuUp_3Lg. Affected: /_inbox/-LoRTL0kzikYGuUp_3Lg 09-10 13:39:12.130 8250-8366/com.lf D/WebSocket: ws_0 - ws message: {"t":"d","d":{"r":10,"b":{"s":"ok","d":""}}} 09-10 13:39:12.131 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 44977 09-10 13:39:12.131 8250-8341/com.lf D/WebSocket: ws_0 - HandleNewFrameCount: 1 09-10 13:39:12.131 8250-8341/com.lf D/WebSocket: ws_0 - handleIncomingFrame complete frame: {d={r=10, b={d=, s=ok}}, t=d} 09-10 13:39:12.131 8250-8341/com.lf D/Connection: conn_0 - received data message: {r=10, b={d=, s=ok}} 09-10 13:39:12.131 8250-8341/com.lf D/PersistentConnection: pc_0 - p response: {d=, s=ok} 09-10 13:39:12.131 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:39:12.132 8250-8341/com.lf D/Persistence: Deleted 1 write(s) with writeId 4 in 0ms 09-10 13:39:12.134 8250-8341/com.lf D/Persistence: Persisted a total of 1 rows and deleted 0 rows for a set at /_inbox/-LoRTL0kzikYGuUp_3Lg in 2ms 09-10 13:39:12.134 8250-8341/com.lf D/Persistence: Saved new tracked query in 0ms 09-10 13:39:12.142 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 10ms 09-10 13:39:22.535 8250-8341/com.lf D/RepoOperation: set: /_inbox/-LoRTNZrp3Z_8u2d5WFl 09-10 13:39:22.536 8250-8341/com.lf D/DataOperation: set: /_inbox/-LoRTNZrp3Z_8u2d5WFl { advertiser=FP demo } 09-10 13:39:22.536 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:39:22.537 8250-8341/com.lf D/Persistence: Persisted user overwrite in 1ms 09-10 13:39:22.549 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 13ms 09-10 13:39:22.550 8250-8341/com.lf D/Connection: conn_0 - Sending data: {} 09-10 13:39:22.550 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 34580 09-10 13:39:22.551 8250-8341/com.lf D/RepoOperation: Aborting transactions for path: /_inbox/-LoRTNZrp3Z_8u2d5WFl. Affected: /_inbox/-LoRTNZrp3Z_8u2d5WFl 09-10 13:39:22.573 8250-8366/com.lf D/WebSocket: ws_0 - ws message: {"t":"d","d":{"r":11,"b":{"s":"ok","d":""}}} 09-10 13:39:22.573 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 44976 09-10 13:39:22.573 8250-8341/com.lf D/WebSocket: ws_0 - HandleNewFrameCount: 1 09-10 13:39:22.573 8250-8341/com.lf D/WebSocket: ws_0 - handleIncomingFrame complete frame: {d={r=11, b={d=, s=ok}}, t=d} 09-10 13:39:22.573 8250-8341/com.lf D/Connection: conn_0 - received data message: {r=11, b={d=, s=ok}} 09-10 13:39:22.574 8250-8341/com.lf D/PersistentConnection: pc_0 - p response: {d=, s=ok} 09-10 13:39:22.574 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:39:22.574 8250-8341/com.lf D/Persistence: Deleted 1 write(s) with writeId 5 in 0ms 09-10 13:39:22.576 8250-8341/com.lf D/Persistence: Persisted a total of 1 rows and deleted 0 rows for a set at /_inbox/-LoRTNZrp3Z_8u2d5WFl in 1ms 09-10 13:39:22.577 8250-8341/com.lf D/Persistence: Saved new tracked query in 1ms 09-10 13:39:22.586 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 12ms 09-10 13:39:32.805 8250-8341/com.lf D/RepoOperation: set: /_inbox/-LoRTQ4KMXd6c9Gm-SKk 09-10 13:39:32.806 8250-8341/com.lf D/DataOperation: set: /_inbox/-LoRTQ4KMXd6c9Gm-SKk { advertiser=FP demo } 09-10 13:39:32.806 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:39:32.808 8250-8341/com.lf D/Persistence: Persisted user overwrite in 2ms 09-10 13:39:32.823 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 17ms 09-10 13:39:32.824 8250-8341/com.lf D/Connection: conn_0 - Sending data: {} 09-10 13:39:32.824 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 34748 09-10 13:39:32.826 8250-8341/com.lf D/RepoOperation: Aborting transactions for path: /_inbox/-LoRTQ4KMXd6c9Gm-SKk. Affected: /_inbox/-LoRTQ4KMXd6c9Gm-SKk 09-10 13:39:32.851 8250-8366/com.lf D/WebSocket: ws_0 - ws message: {"t":"d","d":{"r":12,"b":{"s":"ok","d":""}}} 09-10 13:39:32.852 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 44972 09-10 13:39:32.852 8250-8341/com.lf D/WebSocket: ws_0 - HandleNewFrameCount: 1 09-10 13:39:32.852 8250-8341/com.lf D/WebSocket: ws_0 - handleIncomingFrame complete frame: {d={r=12, b={d=, s=ok}}, t=d} 09-10 13:39:32.852 8250-8341/com.lf D/Connection: conn_0 - received data message: {r=12, b={d=, s=ok}} 09-10 13:39:32.852 8250-8341/com.lf D/PersistentConnection: pc_0 - p response: {d=, s=ok} 09-10 13:39:32.852 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:39:32.853 8250-8341/com.lf D/Persistence: Deleted 1 write(s) with writeId 6 in 1ms 09-10 13:39:32.855 8250-8341/com.lf D/Persistence: Persisted a total of 1 rows and deleted 0 rows for a set at /_inbox/-LoRTQ4KMXd6c9Gm-SKk in 1ms 09-10 13:39:32.855 8250-8341/com.lf D/Persistence: Saved new tracked query in 0ms 09-10 13:39:32.865 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 13ms 09-10 13:39:43.134 8250-8341/com.lf D/RepoOperation: set: /_inbox/-LoRTSaeLffnmCNIYkz0 09-10 13:39:43.134 8250-8341/com.lf D/DataOperation: set: /_inbox/-LoRTSaeLffnmCNIYkz0 { advertiser=FP demo } 09-10 13:39:43.134 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:39:43.136 8250-8341/com.lf D/Persistence: Persisted user overwrite in 2ms 09-10 13:39:43.148 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 14ms 09-10 13:39:43.149 8250-8341/com.lf D/Connection: conn_0 - Sending data: {} 09-10 13:39:43.149 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 34702 09-10 13:39:43.150 8250-8341/com.lf D/RepoOperation: Aborting transactions for path: /_inbox/-LoRTSaeLffnmCNIYkz0. Affected: /_inbox/-LoRTSaeLffnmCNIYkz0 09-10 13:39:43.232 8250-8366/com.lf D/WebSocket: ws_0 - ws message: {"t":"d","d":{"r":13,"b":{"s":"ok","d":""}}} 09-10 13:39:43.232 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 44916 09-10 13:39:43.232 8250-8341/com.lf D/WebSocket: ws_0 - HandleNewFrameCount: 1 09-10 13:39:43.232 8250-8341/com.lf D/WebSocket: ws_0 - handleIncomingFrame complete frame: {d={r=13, b={d=, s=ok}}, t=d} 09-10 13:39:43.232 8250-8341/com.lf D/Connection: conn_0 - received data message: {r=13, b={d=, s=ok}} 09-10 13:39:43.232 8250-8341/com.lf D/PersistentConnection: pc_0 - p response: {d=, s=ok} 09-10 13:39:43.232 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:39:43.233 8250-8341/com.lf D/Persistence: Deleted 1 write(s) with writeId 7 in 0ms 09-10 13:39:43.235 8250-8341/com.lf D/Persistence: Persisted a total of 1 rows and deleted 0 rows for a set at /_inbox/-LoRTSaeLffnmCNIYkz0 in 2ms 09-10 13:39:43.236 8250-8341/com.lf D/Persistence: Saved new tracked query in 1ms 09-10 13:39:43.255 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 22ms 09-10 13:39:53.640 8250-8341/com.lf D/RepoOperation: set: /_inbox/-LoRTV9sGqmbKJBTA7Qo 09-10 13:39:53.641 8250-8341/com.lf D/DataOperation: set: /_inbox/-LoRTV9sGqmbKJBTA7Qo { advertiser=FP demo } 09-10 13:39:53.641 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:39:53.646 8250-8341/com.lf D/Persistence: Persisted user overwrite in 4ms 09-10 13:39:53.674 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 31ms 09-10 13:39:53.676 8250-8341/com.lf D/Connection: conn_0 - Sending data: {} 09-10 13:39:53.677 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 34555 09-10 13:39:53.679 8250-8341/com.lf D/RepoOperation: Aborting transactions for path: /_inbox/-LoRTV9sGqmbKJBTA7Qo. Affected: /_inbox/-LoRTV9sGqmbKJBTA7Qo 09-10 13:39:53.709 8250-8366/com.lf D/WebSocket: ws_0 - ws message: {"t":"d","d":{"r":14,"b":{"s":"ok","d":""}}} 09-10 13:39:53.710 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 44966 09-10 13:39:53.710 8250-8341/com.lf D/WebSocket: ws_0 - HandleNewFrameCount: 1 09-10 13:39:53.711 8250-8341/com.lf D/WebSocket: ws_0 - handleIncomingFrame complete frame: {d={r=14, b={d=, s=ok}}, t=d} 09-10 13:39:53.712 8250-8341/com.lf D/Connection: conn_0 - received data message: {r=14, b={d=, s=ok}} 09-10 13:39:53.712 8250-8341/com.lf D/PersistentConnection: pc_0 - p response: {d=, s=ok} 09-10 13:39:53.712 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:39:53.714 8250-8341/com.lf D/Persistence: Deleted 1 write(s) with writeId 8 in 1ms 09-10 13:39:53.720 8250-8341/com.lf D/Persistence: Persisted a total of 1 rows and deleted 0 rows for a set at /_inbox/-LoRTV9sGqmbKJBTA7Qo in 4ms 09-10 13:39:53.722 8250-8341/com.lf D/Persistence: Saved new tracked query in 0ms 09-10 13:39:53.738 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 26ms 09-10 13:40:04.194 8250-8341/com.lf D/RepoOperation: set: /_inbox/-LoRTXjmRq0Inhn_vuLh 09-10 13:40:04.194 8250-8341/com.lf D/DataOperation: set: /_inbox/-LoRTXjmRq0Inhn_vuLh { advertiser=FP demo } 09-10 13:40:04.194 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:40:04.196 8250-8341/com.lf D/Persistence: Persisted user overwrite in 2ms 09-10 13:40:04.208 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 14ms 09-10 13:40:04.209 8250-8341/com.lf D/Connection: conn_0 - Sending data: {} 09-10 13:40:04.209 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 34501 09-10 13:40:04.210 8250-8341/com.lf D/RepoOperation: Aborting transactions for path: /_inbox/-LoRTXjmRq0Inhn_vuLh. Affected: /_inbox/-LoRTXjmRq0Inhn_vuLh 09-10 13:40:04.289 8250-8366/com.lf D/WebSocket: ws_0 - ws message: {"t":"d","d":{"r":15,"b":{"s":"ok","d":""}}} 09-10 13:40:04.289 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 44919 09-10 13:40:04.289 8250-8341/com.lf D/WebSocket: ws_0 - HandleNewFrameCount: 1 09-10 13:40:04.289 8250-8341/com.lf D/WebSocket: ws_0 - handleIncomingFrame complete frame: {d={r=15, b={d=, s=ok}}, t=d} 09-10 13:40:04.289 8250-8341/com.lf D/Connection: conn_0 - received data message: {r=15, b={d=, s=ok}} 09-10 13:40:04.289 8250-8341/com.lf D/PersistentConnection: pc_0 - p response: {d=, s=ok} 09-10 13:40:04.290 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:40:04.290 8250-8341/com.lf D/Persistence: Deleted 1 write(s) with writeId 9 in 0ms 09-10 13:40:04.292 8250-8341/com.lf D/Persistence: Persisted a total of 1 rows and deleted 0 rows for a set at /_inbox/-LoRTXjmRq0Inhn_vuLh in 1ms 09-10 13:40:04.292 8250-8341/com.lf D/Persistence: Saved new tracked query in 0ms 09-10 13:40:04.313 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 23ms 09-10 13:40:14.533 8250-8341/com.lf D/RepoOperation: set: /_inbox/-LoRT_GJEILvkzKnbk3n 09-10 13:40:14.533 8250-8341/com.lf D/DataOperation: set: /_inbox/-LoRT_GJEILvkzKnbk3n { advertiser=FP demo } 09-10 13:40:14.534 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:40:14.538 8250-8341/com.lf D/Persistence: Persisted user overwrite in 3ms 09-10 13:40:14.553 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 18ms 09-10 13:40:14.555 8250-8341/com.lf D/Connection: conn_0 - Sending data: {} 09-10 13:40:14.556 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 34732 09-10 13:40:14.557 8250-8341/com.lf D/RepoOperation: Aborting transactions for path: /_inbox/-LoRT_GJEILvkzKnbk3n. Affected: /_inbox/-LoRT_GJEILvkzKnbk3n 09-10 13:40:14.581 8250-8366/com.lf D/WebSocket: ws_0 - ws message: {"t":"d","d":{"r":16,"b":{"s":"ok","d":""}}} 09-10 13:40:14.582 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 44974 09-10 13:40:14.582 8250-8341/com.lf D/WebSocket: ws_0 - HandleNewFrameCount: 1 09-10 13:40:14.582 8250-8341/com.lf D/WebSocket: ws_0 - handleIncomingFrame complete frame: {d={r=16, b={d=, s=ok}}, t=d} 09-10 13:40:14.583 8250-8341/com.lf D/Connection: conn_0 - received data message: {r=16, b={d=, s=ok}} 09-10 13:40:14.583 8250-8341/com.lf D/PersistentConnection: pc_0 - p response: {d=, s=ok} 09-10 13:40:14.583 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:40:14.584 8250-8341/com.lf D/Persistence: Deleted 1 write(s) with writeId 10 in 1ms 09-10 13:40:14.586 8250-8341/com.lf D/Persistence: Persisted a total of 1 rows and deleted 0 rows for a set at /_inbox/-LoRT_GJEILvkzKnbk3n in 2ms 09-10 13:40:14.586 8250-8341/com.lf D/Persistence: Saved new tracked query in 0ms 09-10 13:40:14.595 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 12ms 09-10 13:40:25.086 8250-8341/com.lf D/RepoOperation: set: /_inbox/-LoRTbqDy7fFlAjY1JPO 09-10 13:40:25.087 8250-8341/com.lf D/DataOperation: set: /_inbox/-LoRTbqDy7fFlAjY1JPO { advertiser=FP demo } 09-10 13:40:25.087 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:40:25.088 8250-8341/com.lf D/Persistence: Persisted user overwrite in 1ms 09-10 13:40:25.106 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 19ms 09-10 13:40:25.106 8250-8341/com.lf D/Connection: conn_0 - Sending data: {} 09-10 13:40:25.107 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 34475 09-10 13:40:25.108 8250-8341/com.lf D/RepoOperation: Aborting transactions for path: /_inbox/-LoRTbqDy7fFlAjY1JPO. Affected: /_inbox/-LoRTbqDy7fFlAjY1JPO 09-10 13:40:25.130 8250-8366/com.lf D/WebSocket: ws_0 - ws message: {"t":"d","d":{"r":17,"b":{"s":"ok","d":""}}} 09-10 13:40:25.130 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 44976 09-10 13:40:25.130 8250-8341/com.lf D/WebSocket: ws_0 - HandleNewFrameCount: 1 09-10 13:40:25.131 8250-8341/com.lf D/WebSocket: ws_0 - handleIncomingFrame complete frame: {d={r=17, b={d=, s=ok}}, t=d} 09-10 13:40:25.131 8250-8341/com.lf D/Connection: conn_0 - received data message: {r=17, b={d=, s=ok}} 09-10 13:40:25.131 8250-8341/com.lf D/PersistentConnection: pc_0 - p response: {d=, s=ok} 09-10 13:40:25.131 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:40:25.132 8250-8341/com.lf D/Persistence: Deleted 1 write(s) with writeId 11 in 0ms 09-10 13:40:25.134 8250-8341/com.lf D/Persistence: Persisted a total of 1 rows and deleted 0 rows for a set at /_inbox/-LoRTbqDy7fFlAjY1JPO in 2ms 09-10 13:40:25.135 8250-8341/com.lf D/Persistence: Saved new tracked query in 1ms 09-10 13:40:25.145 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 14ms 09-10 13:40:35.355 8250-8341/com.lf D/RepoOperation: set: /_inbox/-LoRTeLfcdVU1bOivRXB 09-10 13:40:35.355 8250-8341/com.lf D/DataOperation: set: /_inbox/-LoRTeLfcdVU1bOivRXB { advertiser=FP demo } 09-10 13:40:35.356 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:40:35.358 8250-8341/com.lf D/Persistence: Persisted user overwrite in 2ms 09-10 13:40:35.372 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 16ms 09-10 13:40:35.374 8250-8341/com.lf D/Connection: conn_0 - Sending data: {} 09-10 13:40:35.374 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 34755 09-10 13:40:35.376 8250-8341/com.lf D/RepoOperation: Aborting transactions for path: /_inbox/-LoRTeLfcdVU1bOivRXB. Affected: /_inbox/-LoRTeLfcdVU1bOivRXB 09-10 13:40:35.397 8250-8366/com.lf D/WebSocket: ws_0 - ws message: {"t":"d","d":{"r":18,"b":{"s":"ok","d":""}}} 09-10 13:40:35.398 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 44976 09-10 13:40:35.398 8250-8341/com.lf D/WebSocket: ws_0 - HandleNewFrameCount: 1 09-10 13:40:35.398 8250-8341/com.lf D/WebSocket: ws_0 - handleIncomingFrame complete frame: {d={r=18, b={d=, s=ok}}, t=d} 09-10 13:40:35.398 8250-8341/com.lf D/Connection: conn_0 - received data message: {r=18, b={d=, s=ok}} 09-10 13:40:35.399 8250-8341/com.lf D/PersistentConnection: pc_0 - p response: {d=, s=ok} 09-10 13:40:35.399 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:40:35.400 8250-8341/com.lf D/Persistence: Deleted 1 write(s) with writeId 12 in 0ms 09-10 13:40:35.405 8250-8341/com.lf D/Persistence: Persisted a total of 1 rows and deleted 0 rows for a set at /_inbox/-LoRTeLfcdVU1bOivRXB in 5ms 09-10 13:40:35.407 8250-8341/com.lf D/Persistence: Saved new tracked query in 1ms 09-10 13:40:35.421 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 22ms 09-10 13:40:45.776 8250-8341/com.lf D/RepoOperation: set: /_inbox/-LoRTgtR1n6Gv7V3arV0 09-10 13:40:45.776 8250-8341/com.lf D/DataOperation: set: /_inbox/-LoRTgtR1n6Gv7V3arV0 { advertiser=FP demo } 09-10 13:40:45.776 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:40:45.778 8250-8341/com.lf D/Persistence: Persisted user overwrite in 2ms 09-10 13:40:45.790 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 14ms 09-10 13:40:45.791 8250-8341/com.lf D/Connection: conn_0 - Sending data: {} 09-10 13:40:45.791 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 34607 09-10 13:40:45.792 8250-8341/com.lf D/RepoOperation: Aborting transactions for path: /_inbox/-LoRTgtR1n6Gv7V3arV0. Affected: /_inbox/-LoRTgtR1n6Gv7V3arV0 09-10 13:40:45.839 8250-8366/com.lf D/WebSocket: ws_0 - ws message: {"t":"d","d":{"r":19,"b":{"s":"ok","d":""}}} 09-10 13:40:45.839 8250-8341/com.lf D/WebSocket: ws_0 - Reset keepAlive. Remaining: 44951 09-10 13:40:45.839 8250-8341/com.lf D/WebSocket: ws_0 - HandleNewFrameCount: 1 09-10 13:40:45.840 8250-8341/com.lf D/WebSocket: ws_0 - handleIncomingFrame complete frame: {d={r=19, b={d=, s=ok}}, t=d} 09-10 13:40:45.840 8250-8341/com.lf D/Connection: conn_0 - received data message: {r=19, b={d=, s=ok}} 09-10 13:40:45.840 8250-8341/com.lf D/PersistentConnection: pc_0 - p response: {d=, s=ok} 09-10 13:40:45.840 8250-8341/com.lf D/Persistence: Starting transaction. 09-10 13:40:45.841 8250-8341/com.lf D/Persistence: Deleted 1 write(s) with writeId 13 in 0ms 09-10 13:40:45.843 8250-8341/com.lf D/Persistence: Persisted a total of 1 rows and deleted 0 rows for a set at /_inbox/-LoRTgtR1n6Gv7V3arV0 in 2ms 09-10 13:40:45.845 8250-8341/com.lf D/Persistence: Saved new tracked query in 2ms 09-10 13:40:45.864 8250-8341/com.lf D/Persistence: Transaction completed. Elapsed: 24ms 09-10 13:40:56.166 8250-8341/com.lf D/RepoOperation: set: /_inbox/-LoRTjQoVMCsLpomPzM3 09-10 13:40:56.167 8250-8341/com.lf D/DataOperation: set: /_inbox/-LoRTjQoVMCsLpomPzM3 { advertiser=FP demo }

[schmidt-sebastian]

I skimmed through the code again (sorry, I am not super familiar with it). We only "prune" the cache when we receive an update from the server (which would log a "handleServerMessage" line) - a confirmed write doesn't trigger this. Do you have any active listeners in your app?

[whispernight]

I see, but then only that path gets cleaned up, so only server side updates get the cache cleanup applied?

I triggered a 'handleServerMessage' event by changing a value in firebase which I have a listener on. This is the log:

09-11 10:02:57.092 1336-1521/com.lf D/WebSocket: ws_0 - handleIncomingFrame complete frame: {d={a=d, b={d=barcelona, p=assets/{valueHere}/corp_config}}, t=d} 09-11 10:02:57.092 1336-1521/com.lf D/Connection: conn_0 - received data message: {a=d, b={d=barcelona, p=assets/{valueHere}/corp_config}} 09-11 10:02:57.092 1336-1521/com.lf D/PersistentConnection: pc_0 - handleServerMessage: d {d=barcelona, p=assets/assetId/corp_config} 09-11 10:02:57.092 1336-1521/com.lf D/RepoOperation: onDataUpdate: /assets/assetId/corp_config 09-11 10:02:57.092 1336-1521/com.lf D/RepoOperation: onDataUpdate: /assets/assetId/corp_config barcelona 09-11 10:02:57.093 1336-1521/com.lf D/Persistence: Starting transaction. 09-11 10:02:57.094 1336-1521/com.lf D/Persistence: Persisted a total of 1 rows and deleted 1 rows for a set at /assets/{valueHere}/corp_config in 1ms 09-11 10:02:57.108 1336-1521/com.lf D/Persistence: Transaction completed. Elapsed: 15ms 09-11 10:02:57.109 1336-1521/com.lf D/EventRaiser: Raising 1 event(s) 09-11 10:02:57.120 1336-1336/com.lf D/EventRaiser: Raising /assets/{valueHere}: VALUE: {valueHere} 09-11 10:02:57.122 1336-1521/com.lf D/Persistence: Starting transaction.

But this does not clean up the whole cache. What am I missing? Do I need an active listener on the path that is making the sqlite db huge?

Thank you

[whispernight]

I believe something similar happened to someone with iOS: https://github.com/firebase/firebase-ios-sdk/issues/1518 Did anything got implemented to fix this?

Thank you

[schmidt-sebastian]

Any active listener should trigger garbage collection. It doesn't have to be for the location that you want to be GCed.

As for the firebase/firebase-ios-sdk#1518, we never quite had the resources to fix this. Making changes in our garbage collection logic is always a bit risky and unless we are 100% certain of the root cause, it is sometimes better not to fix it (which is certainly not what you want to hear).

[whispernight]

I have some active listeners and as you can see a couple of comments above, they trigger "handleServerMessage" but they dont do a prune/cache cleanup.

[argzdev]

Hi @whispernight, just bumping this thread. Since this issue has been quite a while, may I ask if you're still encountering this issue on the latest SDK?

[google-oss-bot]

Hey @whispernight. We need more information to resolve this issue but there hasn't been an update in 5 weekdays. I'm marking the issue as stale and if there are no new updates in the next 5 days I will close it automatically.

If you have more information that will help us get to the bottom of this, just add a comment!

[google-oss-bot]

Since there haven't been any recent updates here, I am going to close this issue.

@whispernight if you're still experiencing this problem and want to continue the discussion just leave a comment here and we are happy to re-open this.