search

element-hq / element-android

A Matrix collaboration client for Android.
https://element.io/
GNU Affero General Public License v3.0
3.34k stars 709 forks source link

big battery drain after incoming call - infinite sync loop every 2-3 seconds #2163

Closed progserega closed 3 years ago

progserega commented 4 years ago

Element use too match battery.

I check on my server push:

root@im:~# cat /var/log/matrix-synapse/homeserver.log* | grep 'push actions for @progserega:rsprim.ru' | cut -d ' ' -f1 | sort | uniq -c
     13 2019-10-04
     37 2020-09-23
     81 2020-09-24

And sync:

root@im:~# cat /var/log/matrix-synapse/homeserver.log*|grep '@progserega:rsprim.ru' |grep YD201|grep sync|cut -d ' ' -f1 | sort | uniq -c
     13 2019-10-04
  11771 2020-09-23
  10685 2020-09-24

Screenshots Sorry for non-english screenshots.

Most translations:

23.09.2020: Screenshot_20200923-140317 Screenshot_20200923-140346 Screenshot_20200923-140420

24.09.2020 (no problems with push): Screenshot_20200924-195852 Screenshot_20200924-073906 Screenshot_20200924-073853 Screenshot_20200924-073822

Smartphone:

Additional context

progserega commented 4 years ago

I was send logs from app with description: "Logs for issue #2163"

progserega commented 4 years ago

What url's was got my android phone (YD201) today:

root@im:~# cat /var/log/matrix-synapse/homeserver.log* | grep 2020-09-24 | grep '@progserega:rsprim.ru' | grep YD201 | cut -d ' ' -f26 | cut -d '?' -f1 | cut -d '+' -f1 | cut -d '!' -f1 | sort | uniq -c | sort -n
      1 /_matrix/client/r0/capabilities
      1 /_matrix/client/r0/join/
      1 /_matrix/client/r0/sendToDevice/m.room.encrypted/1761307263
      1 /_matrix/client/r0/sendToDevice/m.room_key_request/$local.1a7ba32e-2ce3-4b32-89c3-fe13d1c85642
      1 /_matrix/client/r0/sendToDevice/m.room_key_request/$local.9d5d7a91-d610-480d-876b-5338d809128f
      1 /_matrix/client/r0/user/@progserega:rsprim.ru/openid/request_token
      1 /_matrix/client/r0/voip/turnServer
      1 /_matrix/media/r0/config
      2 /_matrix/client/r0/pushrules/global/room/
      7 /_matrix/client/unstable/room_keys/keys
     10 /_matrix/client/r0/pushers/set
     12 /_matrix/media/r0/upload
     13 /_matrix/client/unstable/room_keys/version
     16 /_matrix/client/r0/pushers
     28 /_matrix/client/r0/devices
     55 /_matrix/client/r0/keys/query
     64 /_matrix/client/r0/user/@progserega:rsprim.ru/account_data/im.vector.setting.breadcrumbs
    343 /_matrix/client/r0/groups/
    411 /_matrix/client/r0/rooms/
  10751 /_matrix/client/r0/sync
unclechu commented 4 years ago

I’d like to get back control of the polling interval. I used to be able to change it in old Riot whilst in Element I couldn’t find such an option.

progserega commented 4 years ago

Yesterday I clear all cache of element (in his menu) - this is stop battery drain.

But today I get incoming voice call. And after that (may be) battery drain come again. I get incoming call on Element-desktop, but element-android still screen on and was showing incoming call splash after call was ended. May be incoming call tell android-element sync every 2-3 seconds?

root@im:~# while /bin/true; do sleep 5; cat /var/log/matrix-synapse/homeserver.log|grep '@progserega:rsprim.ru'| grep 2020-09-26 |grep YD201|grep sync|cut -d ' ' -f1 | sort | uniq -c;done
   4381 2020-09-26
   4384 2020-09-26
   4387 2020-09-26
   4390 2020-09-26
   4391 2020-09-26
   4391 2020-09-26
   4394 2020-09-26
   4394 2020-09-26
   4397 2020-09-26

I open element-android and see "incoming call splash screen". But call was ended ~1hour ago. I clear "all cache" again, start element-android, wait when first sync is complete and start monitoring server logs again, but today this not help - sync started again and again every ~3 seconds:

root@im:~# while /bin/true; do sleep 5; cat /var/log/matrix-synapse/homeserver.log|grep '@progserega:rsprim.ru'| grep 2020-09-26 |grep YD201|grep sync|cut -d ' ' -f1 | sort | uniq -c;done
   4438 2020-09-26
   4439 2020-09-26
   4440 2020-09-26
   4440 2020-09-26
   4440 2020-09-26
   4444 2020-09-26
   4446 2020-09-26
   4448 2020-09-26
   4449 2020-09-26
   4450 2020-09-26
   4451 2020-09-26
   4453 2020-09-26
   4455 2020-09-26
   4456 2020-09-26
   4458 2020-09-26
   4458 2020-09-26
   4461 2020-09-26
   4462 2020-09-26
   4465 2020-09-26
   4467 2020-09-26
   4469 2020-09-26
   4471 2020-09-26
   4473 2020-09-26
   4475 2020-09-26
   4478 2020-09-26
   4480 2020-09-26
   4481 2020-09-26
   4483 2020-09-26
   4485 2020-09-26
   4487 2020-09-26
   4488 2020-09-26
   4489 2020-09-26
   4490 2020-09-26
   4491 2020-09-26
   4491 2020-09-26
   4493 2020-09-26
   4495 2020-09-26
   4498 2020-09-26
   4501 2020-09-26
   4501 2020-09-26
   4501 2020-09-26
   4503 2020-09-26
   4504 2020-09-26
   4506 2020-09-26
   4508 2020-09-26
   4509 2020-09-26
progserega commented 4 years ago

Only reboot phone stop this increment count of syncing. So, I think that need this steps for reproduce this bug:

  1. account A have element-android and element-desktop session
  2. account B start voice call to account A
  3. account A answer to incoming call on element-desktop
  4. from this moment element-android start sync every 2-3 seconds.
  5. end voice-call on element-desktop at account A
  6. element-android still delay sync every 2-3 seconds -> battery drain
  7. open app element-android on account A - see splash screen "incoming call"
  8. press "cancel" incoming call
  9. press "return" button
  10. sync delay not stopped - battery still drain
  11. reboot phone
  12. sync stopped and battery drain stopped
progserega commented 4 years ago

I get incoming call again and situation repeat. I try get adb logcat but in android's logs no information about "loop sync". I see sync requests in server's logs, but not in android logs at some time. Enable developer mode and "more logs" in element-android - not help.

But I found how stop sync request without reboot phone:

  1. press key for show all running app's
  2. press key "close all running app"
  3. after that - on server in logs I was see freeze count of sync requests from my phone.
progserega commented 4 years ago

Do you can add some battery/job/requests/traffic statistic in app for monitoring "what doing element today" in developer mode?

For example:

  1. number of sync today
  2. receive and send bytes over network today
  3. time in background non sleep mode
  4. etc.
progserega commented 3 years ago

I add monitoring of servers logs to zabbix. It show sync request from only my phone: 1

  1. At morning Tasker switch on "mobile data" and element get more sync request.
  2. After that at 9:15 I get up and clear all cache in settings of element and reboot phone
  3. At 10:00 I get incoming voip call and answer to it on my PC
  4. Element on phone begin sync-loop from this time
  5. At 10:45 I again clear all caches and reboot phone - sync gone.
progserega commented 3 years ago

Element 1.0.10 not fixed this problem: I was accept incoming voice call on pc at 8:40. And after that - element start many sync (graph show only sync from my phone to my matrix-server): 1 Screenshot_20201109-114043

progserega commented 3 years ago

So, for example overview situation of sync at more time window:

1

Element not syncing at night because I switch off data connection in phone.

onurays commented 3 years ago

@progserega I can reproduce the issue on v1.0.9; the app stucks on the incoming call screen and continue syncing because app is on the foreground, as you said. But with https://github.com/vector-im/element-android/pull/2058 (v1.0.10) I confirm that app is not showing incoming call screen when call answered/rejected from another device and syncs pauses. Do you still see stucked incoming call screen on v1.0.10?

And with v1.0.10 it is normal that you see regular sync requests during call ringing, but you shouldn't see any sync requests when the call answered from another device and the app is in the background.

Regular syncs:

2020-11-19 16:14:39.760 3451-3523/im.vector.app.debug V/SyncThread: Execute sync request with timeout 30000
2020-11-19 16:15:10.565 3451-3523/im.vector.app.debug V/SyncThread: Execute sync request with timeout 30000
2020-11-19 16:15:41.270 3451-3523/im.vector.app.debug V/SyncThread: Execute sync request with timeout 30000
2020-11-19 16:16:11.861 3451-3523/im.vector.app.debug V/SyncThread: Execute sync request with timeout 30000
2020-11-19 16:16:42.868 3451-3523/im.vector.app.debug V/SyncThread: Execute sync request with timeout 30000
2020-11-19 16:17:13.818 3451-3523/im.vector.app.debug V/SyncThread: Execute sync request with timeout 30000
progserega commented 3 years ago

Now I was switch from f-droid version to gplay and will test again.

F-droid version work more stable in this situation. This bug mostly not reproduce in f-droid version.

progserega commented 3 years ago

After reinstall f-droid to gplay version - I get some minimal syncs in graph yesterday. I try incoming call and all was nice ("incoming call" splash on android was hide after I accept incoming call on PC). But today I get more sync again: 11 And I send logs from element with description: "logs for issue 2163"

MurzNN commented 3 years ago

@onurays, how did you got the logs of android app like this?

2020-11-19 16:14:39.760 3451-3523/im.vector.app.debug V/SyncThread: Execute sync request with timeout 30000

I can't find the way to view those logs in Element app.

progserega commented 3 years ago

Now I check logs of server by execute: while /bin/true; do sleep 3; cat /var/log/matrix-synapse/homeserver.log|grep '@progserega:rsprim.ru' |grep YD201|grep sync|cut -d ' ' -f1 | sort | uniq -c;done.

And see, that element do not sync every 1-3-6 seconds. It sync only on each receive push event (new message). So my graph show only my messaging, not many unneeded syncs.

In result:

  1. Update app from 1.0.6->... ->1.0.10 from google play not clear app-data.
  2. Some settings in app data was tell app bad work with incoming calls.
  3. I backup broken 1.0.10 by "Titanium backup"
  4. I try reinstall app from f-droid - and it is said me, that "you need login again" - it is strange, but I login again with new full sync.
  5. F-droid version (1.0.10) was work with incoming calls, his splash and sync - correctly
  6. I backup f-droid 1.0.10 by "Titanium backup"
  7. remove f-droid version
  8. try restore backup of gplay version - it is restored, but not started - crash at start...
  9. I remove all versions and install clear gplay version again. Login in new session and I get correctly work with incoming calls, splash and syncs.

So, in result I sink bug was in broken app-data after updating 1.0.6->...->1.0.10. And after reinstall app with clear app-data - bug is gone. This is strange bug. Thank you for you help. I think issue can be close.

progserega commented 3 years ago

But only I do not understand - what occur every 2 hour: 1 At 10:30, at 12:30, at 14:30 and at 16:30? Many regularity syncs? Why?

progserega commented 3 years ago

3 day graph: 1 every 2 hour phone call many sync-requests to server. Why? And Element in top from battery use with 17%: Screenshot_20201130-155043

As I understand: on every incoming push event tell element do sync. If we get more events - phone will call many syncs. And battery will drain. As I understand this is need for decrypt messages and show it preview. But as I remember - in old riot we have options, which control this situation with variants:

  1. send text in push (insecure)
  2. send in push only events, but get text by riot syncs when it was receive event (good user experience)
  3. send in push only events and do not show message text in preview (battery safe mode). Show text only when user open app (call sync for receive all messages with its texts).

In last variants - we reduce sync calls and reduce battery usage, but events will be such "you have new X messages in Y rooms". In same situation this variant is excellent - if user want more "battery time".

May be I need open new issue for this option?

progserega commented 3 years ago

And tho question:

  1. Do the server send push evento for new messages in muted (without sounds) rooms?
  2. Do the element sync if it is receive push about "new messages in muted room"?

If always "yes" - so may be it is problem fro battery drain in situation with rooms, where often occur new messages, but this room is muted? For example - I have some rooms with notification of monitoring systems - some of them (with more events per day) is in muted, but may be this is not prevent "sync" on every muted events?

toshanmugaraj commented 3 years ago

Still issue is open with no progress 👍

progserega commented 3 years ago

I close this bug as party fixed: after voip call battery drain stops - it nice.

But periodicaly strange many syncs still occure. About this bug I create new issue: #2733