celzero / rethink-app

DNS over HTTPS / DNS over Tor / DNSCrypt client, WireGuard proxifier, firewall, and connection tracker for Android.
https://rethinkfirewall.com/
Apache License 2.0
2.75k stars 137 forks source link

CursorWindowAllocation exceptions abound #218

Closed ignoramous closed 3 years ago

ignoramous commented 3 years ago

Fixes for #122 likely didn't work.

ignoramous commented 3 years ago

https://medium.com/androiddevelopers/large-database-queries-on-android-cb043ae626e8 has some pointers on how-to handle large queries.

https://medium.com/androiddevelopers/7-pro-tips-for-room-fbadea4bfbd1 some pro-tips from Google on using Room.

https://developer.android.com/reference/androidx/recyclerview/widget/AsyncListUtil Likely not required but still worth a look for recycler-views driven by the database.

Memory leaks elsewhere causing cursor-window-allocation-exceptions: https://stevevallay.github.io/blog/2014/11/17/memory-leak/

(errno-base.h)


Helpful commands:

# adb shell or adb root

# open fds
run-as com.celzero.bravedns ls -l /proc/<pid>/fd | wc -l

# open sockets
run-as com.celzero.bravedns ls -l /proc/<pid>/fd | grep "socket:" | wc -l

# per-process resource limits
run-as com.celzero.bravedns cat /proc/<pid>/limits

# memory maps for db cursors
run-as grep -i "CursorWindow" /proc/1147/maps

# process status (check if too many running kernel-threads)
less /proc/<pid>/status

# threads
run-as com.celzero.bravedns grep -inr "Name" --include="status" /proc/24001/task/*/status

# trace when root https://source.android.com/devices/tech/debug
debuggerd -b  /proc/24001

One such exception indicating "bad file descriptor"

01-03 01:45:00.092 14302 14456 E CursorWindow: CursorWindow: ashmem_set_prot_region() failed: errno=9.
ignoramous commented 3 years ago
01-03 03:20:35.232 23978 24128 E AndroidRuntime: android.database.CursorWindowAllocationException: Could not allocate CursorWindow '/data/user/0/com.celzero.bravedns/databases/bravedns.db' of size 2097152 due to error -13.
01-03 03:20:35.232 23978 24128 E AndroidRuntime: >--at android.database.CursorWindow.nativeCreate(Native Method)
01-03 03:20:35.232 23978 24128 E AndroidRuntime: >--at android.database.CursorWindow.<init>(CursorWindow.java:139)
01-03 03:20:35.232 23978 24128 E AndroidRuntime: >--at android.database.CursorWindow.<init>(CursorWindow.java:120)
01-03 03:20:35.232 23978 24128 E AndroidRuntime: >--at android.database.AbstractWindowedCursor.clearOrCreateWindow(AbstractWindowedCursor.java:202)
01-03 03:20:35.232 23978 24128 E AndroidRuntime: >--at android.database.sqlite.SQLiteCursor.fillWindow(SQLiteCursor.java:147)
01-03 03:20:35.232 23978 24128 E AndroidRuntime: >--at android.database.sqlite.SQLiteCursor.getCount(SQLiteCursor.java:140)
01-03 03:20:35.232 23978 24128 E AndroidRuntime: >--at android.database.AbstractCursor.moveToPosition(AbstractCursor.java:232)
01-03 03:20:35.232 23978 24128 E AndroidRuntime: >--at android.database.AbstractCursor.moveToFirst(AbstractCursor.java:271)
01-03 03:20:35.232 23978 24128 E AndroidRuntime: >--at com.celzero.bravedns.database.AppInfoDAO_Impl.getWhitelistCount(AppInfoDAO_Impl.java:2206)
01-03 03:20:35.232 23978 24128 E AndroidRuntime: >--at com.celzero.bravedns.database.AppInfoRepository.getWhitelistCount(AppInfoRepository.kt:171)
01-03 03:20:35.232 23978 24128 E AndroidRuntime: >--at com.celzero.bravedns.database.RefreshDatabase.updateCategoryInDB(RefreshDatabase.kt:285)
01-03 03:20:35.232 23978 24128 E AndroidRuntime: >--at com.celzero.bravedns.database.RefreshDatabase.insertNonAppToAppInfo(RefreshDatabase.kt:216)
01-03 03:20:35.232 23978 24128 E AndroidRuntime: >--at com.celzero.bravedns.service.IPTracker.insertNonAppToAppInfo(IPTracker.kt:154)
01-03 03:20:35.232 23978 24128 E AndroidRuntime: >--at com.celzero.bravedns.service.IPTracker.access$insertNonAppToAppInfo(IPTracker.kt:40)
01-03 03:20:35.232 23978 24128 E AndroidRuntime: >--at com.celzero.bravedns.service.IPTracker$insertToDB$1.invokeSuspend(IPTracker.kt:146)
01-03 03:20:35.232 23978 24128 E AndroidRuntime: >--at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
01-03 03:20:35.232 23978 24128 E AndroidRuntime: >--at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:106)
01-03 03:20:35.232 23978 24128 E AndroidRuntime: >--at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(CoroutineScheduler.kt:571)
01-03 03:20:35.232 23978 24128 E AndroidRuntime: >--at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.executeTask(CoroutineScheduler.kt:750)
01-03 03:20:35.232 23978 24128 E AndroidRuntime: >--at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.runWorker(CoroutineScheduler.kt:678)
01-03 03:20:35.232 23978 24128 E AndroidRuntime: >--at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:665)

In one instance, looks like a lot of count(*) queries may have undone the application here by pushing cursor-window to its limits: this blog post hints at count(*) queries being very expensive in terms of having to load the entire table in-memory to count items.

Probably, it is too inefficient to be doing what's being done currently and may be there's a way to do it more efficiently using views or some such.

ignoramous commented 3 years ago

errno = 13 Unrelated, but see: stackoverflow/how-to-fix-selinux-avc-denied-errors-when-launching-dnscrypt-as-init-d-script.

01-11 20:43:14.080 10332 10332 W arch_disk_io_0: type=1400 audit(0.0:158120): avc: denied { open } for path="/dev/ashmem" dev="tmpfs" ino=23409 scontext=u:r:untrusted_app:s0:c227,c257,c512,c768 tcontext=u:object_r:ashmem_device:s0 tclass=chr_file permissive=0
01-11 20:43:14.082 10332 11271 I GoLog   : response not blocked alt6.mobile-gtalk4.l.google.com cloaked domain not in blocklist 1:4J_-P38A___6f6AdNpCAAMQiIAA=
01-11 20:43:14.087 10332 11271 D RethinkDNS: RethinkVPNService Record Transaction: status- COMPLETE
01-11 20:43:14.089 10332 11096 D RethinkDNS: transaction.response - [B@f7bfbf5  
01-11 20:43:14.089 10332 11096 D RethinkDNS: transaction.response - 142.250.12.188
01-11 20:43:14.089   729 11273 E ResolverController: No valid NAT64 prefix (138, <unspecified>/0)
01-11 20:43:14.093  6389 11272 I NetworkManagementSocketTagger: tagSocketFd(-1, 1031, -1) failed with errno-9
01-11 20:43:14.093 10332 10332 D RethinkDNS: Status - true, WORKING             
01-11 20:43:14.094 10332 10397 E elzero.bravedn: Failed IAshmemDeviceService::open()
01-11 20:43:14.094 10332 10397 E CursorWindow: CursorWindow: ashmem_create_region() failed: errno=13.
01-11 20:43:14.102 10332 10397 E AndroidRuntime: FATAL EXCEPTION: arch_disk_io_0
01-11 20:43:14.102 10332 10397 E AndroidRuntime: Process: com.celzero.bravedns, PID: 10332
01-11 20:43:14.102 10332 10397 E AndroidRuntime: android.database.CursorWindowAllocationException: Could not allocate CursorWindow '/data/user/0/com.celzero.bravedns/databases/bravedns.db' of size 2097152 due to error -13.
01-11 20:43:14.102 10332 10397 E AndroidRuntime: >--at android.database.CursorWindow.nativeCreate(Native Method)
01-11 20:43:14.102 10332 10397 E AndroidRuntime: >--at android.database.CursorWindow.<init>(CursorWindow.java:139)
01-11 20:43:14.102 10332 10397 E AndroidRuntime: >--at android.database.CursorWindow.<init>(CursorWindow.java:120)
01-11 20:43:14.102 10332 10397 E AndroidRuntime: >--at android.database.AbstractWindowedCursor.clearOrCreateWindow(AbstractWindowedCursor.java:202)
01-11 20:43:14.102 10332 10397 E AndroidRuntime: >--at android.database.sqlite.SQLiteCursor.fillWindow(SQLiteCursor.java:147)
01-11 20:43:14.102 10332 10397 E AndroidRuntime: >--at android.database.sqlite.SQLiteCursor.getCount(SQLiteCursor.java:140)
01-11 20:43:14.102 10332 10397 E AndroidRuntime: >--at android.database.AbstractCursor.moveToPosition(AbstractCursor.java:232)
01-11 20:43:14.102 10332 10397 E AndroidRuntime: >--at android.database.AbstractCursor.moveToNext(AbstractCursor.java:281)
01-11 20:43:14.102 10332 10397 E AndroidRuntime: >--at androidx.room.InvalidationTracker$1.checkUpdatedTable(InvalidationTracker.java:417)
01-11 20:43:14.102 10332 10397 E AndroidRuntime: >--at androidx.room.InvalidationTracker$1.run(InvalidationTracker.java:388)
01-11 20:43:14.102 10332 10397 E AndroidRuntime: >--at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
01-11 20:43:14.102 10332 10397 E AndroidRuntime: >--at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
01-11 20:43:14.102 10332 10397 E AndroidRuntime: >--at java.lang.Thread.run(Thread.java:919)
01-11 20:43:14.103 10332 10457 I RethinkDNS: RethinkVPNService appWhiteList: 10027, 142.250.12.188
01-11 20:43:14.104 10332 11096 D RethinkDNS: IPTracker - Package for uid : 10027, 2
01-11 20:43:14.107  1299 11275 I DropBoxManagerService: add tag=data_app_crash isTagEnabled=true flags=0x2
01-11 20:43:14.108  1299  2753 W ActivityTaskManager:   Force finishing activity com.celzero.bravedns/.ui.HomeScreenActivity
01-11 20:43:14.113  1299 11275 D FrameworkEventCollector: recordAppIssue PN: com.celzero.bravedns
01-11 20:43:14.120  1299  2121 D gwy     : OS Event: crash      
ignoramous commented 3 years ago

So, looks like EACCESS when InvalidationTracker runs might be a Room bug: issuetracker.google/170228126.

hussainmohd-a commented 3 years ago

As of now, the occurrence of the issue is very minimal or zero. Will monitor for some more days before closing.

ignoramous commented 3 years ago

As above. We've wrapped almost all database access with try..catch blocks too (where ever it wasn't critical), so it is unlikely to crash as often.