Frequent and apparently unrepeatable loss of messages - identification of the origin of the bug
Created by: ysard
First of all, I would like to thank the developer and the community for this essential application. It is absolutely crucial to be able to use this type of encryption on the same network as SMS without requiring an Internet connection.
The report is divided into two parts: in English and French. It is the same text modulo some typographical corrections.
Bug description
Due to a frequent and apparently unrepeatable loss of messages (encrypted or not) I decided to study in detail the logcats of the phones involved (See below for more information; in short terms: emitter = Phone 1 = CyanogenMod 11; receiver = Phone 2 = Android 5.1.1).
The loss of SMS messages is systematically detected a priori on phone 2. To my knowledge, no text messages have been lost following a sending to phone 1.
After a long time comparing the logs, I finally noticed that on phone 1 a shutdown of the application always results in a restart scheduled in the following second, while this is not the case on phone 2.
A stop on phone 1 is made via:
- return key held down ( "Kill with return button" option enabled in the developer options),
- or a deletion from the list of recent applications
No behavioural differences were observed following either of these methods.
On phone 2, it is simply a matter of removing the application from the list of recent applications.
Here is the transcript of a conversation between the 2 devices. A change of PID indicates that the application has been restarted. Silence was killed voluntarily once on phone 1, and twice on phone 2. The length column indicates the number of sms sent simultaneously (multiple sms). The indicator [?] indicates that the message has been lost.
length ID phone1 ID phone2 PID phone1 PID phone2
1 37439 answer 14025 . kill
answer 35319 . .
1 37441 answer 6267 .
answer 35321 . .
1 37443 answer . .
17h06 answer 35323 . .
17h20 1 37445 answer . .
17h20 1 37446 answer . .
17h21 1 37447 answer . .
17h23 answer 35327 . .
17h24 1 37449 answer . .
17h30 3 37450 answer . .
17h46 answer 35330 . 7318 removing the app from recent apps.
17h46 answer 35331 . 29145 removing the app from recent apps.
[?] 17h53 1 37453 ? . .
[?] 17h34 3 37454 ? . .
[?] 18h18 1 37455 ? . .
18h35 answer 35332 . 5335
Logcat in case of a stopping on phone 1:
I/ActivityManager( 520): Force stopping org.smssecure.smssecure appid=10136 user=0: from pid 520
I/ActivityManager( 520): Killing 14025:org.smssecure.smssecure/u0a136 (adj 0): stop org.smssecure.smssecure
W/ActivityManager( 520): Scheduling restart of crashed service org.smssecure.smssecure/.service.KeyCachingService in 1000ms
W/ActivityManager( 520): Force removing ActivityRecord{42517030 u0 org.smssecure.smssecure/.RoutingActivity t246}: app died, no saved state
W/WindowManager( 520): Rebuild removed 8 windows but added 7
[... stacktrace WindowManager...]
I/WindowState( 520): WIN DEATH: Window{423a93c8 u0 org.smssecure.smssecure/org.smssecure.smssecure.RoutingActivity}
I/Timeline( 7063): Timeline: Activity_launch_request id:org.smssecure.smssecure time:160479305
I/ActivityManager( 520): START u0 {act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] flg=0x10200000 cmp=org.smssecure.smssecure/.RoutingActivity bnds=[123,838][223,964]} from pid 7063
I/ActivityManager( 520): Start proc org.smssecure.smssecure for activity org.smssecure.smssecure/.RoutingActivity: pid=6267 uid=10136 gids={50136, 3003, 1028, 1015}
The lines that seem useful to me here are:
- Manual shutdown of PID 14025
- Programming for a restart in 1000ms
- Instant restart of the application
Logcat in case of a stopping on phone 2:
I/Timeline( 5299): Timeline: Activity_launch_request id:org.smssecure.smssecure time:9831807
I/ActivityManager( 2317): START u0 {act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] flg=0x10200000 cmp=org.smssecure.smssecure/.RoutingActivity bnds=[536,1114][712,1280] (has extras)} from uid 10017 on display 0
V/WindowManager( 2317): addAppToken: AppWindowToken{1c9b6f26 token=Token{1b486281 ActivityRecord{fabee68 u0 org.smssecure.smssecure/.RoutingActivity t46}}} to stack=1 task=46 at 0
V/WindowManager( 2317): Adding window Window{379de0b9 u0 Starting org.smssecure.smssecure} at 5 of 9 (after Window{694fd95 u0 com.android.settings/com.android.settings.UsbSettings})
I/ActivityManager( 2317): Start proc 29145:org.smssecure.smssecure/u0a144 for activity org.smssecure.smssecure/.RoutingActivity
W/PassphraseRequiredActionBarActivity(29145): onDestroy()
I/ActivityManager( 2317): Force stopping org.smssecure.smssecure appid=10144 user=0: from pid 4558
I/ActivityManager( 2317): Killing 29145:org.smssecure.smssecure/u0a144 (adj 0): stop org.smssecure.smssecure
I/WindowState( 2317): WIN DEATH: Window{196152dc u0 org.smssecure.smssecure/org.smssecure.smssecure.RoutingActivity}
D/ActivityManager( 2317): cleanUpApplicationRecord -- 29145
W/ActivityManager( 2317): Scheduling restart of crashed service org.smssecure.smssecure/.service.KeyCachingService in 1000ms
I/ActivityManager( 2317): Force stopping service ServiceRecord{11a75f44 u0 org.smssecure.smssecure/.service.KeyCachingService}
W/ActivityManager( 2317): Spurious death for ProcessRecord{24d31f6c 29145:org.smssecure.smssecure/u0a144}, curProc for 29145: null
I/Timeline( 5299): Timeline: Activity_launch_request id:org.smssecure.smssecure time:12718265
I/ActivityManager( 2317): START u0 {act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] flg=0x10200000 cmp=org.smssecure.smssecure/.RoutingActivity bnds=[536,1114][712,1280] (has extras)} from uid 10017 on display 0
V/WindowManager( 2317): addAppToken: AppWindowToken{1c2fbc8a token=Token{3919b6f5 ActivityRecord{1b9cbc2c u0 org.smssecure.smssecure/.RoutingActivity t49}}} to stack=1 task=49 at 0
V/WindowManager( 2317): Adding window Window{1c4ecfad u0 Starting org.smssecure.smssecure} at 5 of 14 (after Window{694fd95 u0 com.android.settings/com.android.settings.UsbSettings})
I/ActivityManager( 2317): Start proc 5335:org.smssecure.smssecure/u0a144 for activity org.smssecure.smssecure/.RoutingActivity
The lines that seem interesting to me here are:
- Starting PID 29145 at time 9831807
- Manual shutdown of PID 29145
- Programming for a restart in 1000ms
- Forced shutdown of the KeyCachingService service?????
- Spurious death??????
- Manual restart at time 12718265 with PID 5335
Between the 2 restarts there was a delay ((12718265-9831807)/1000) = 2886.458 seconds = 48 minutes. This is the time elapsed between the reception of messages 35331 and 35332. However, during this time, phone 1 sent 3 messages that were lost.
I then performed tests after unchecking the "restrict to launch" option associated with Silence on phone 2. (see screenshots below).
Protocol: Silence opening/Stop/wait 20 seconds(to allow a possible automatic restart)/sending a message from phone 1.
Logcat:
I/Timeline( 5299): Timeline: Activity_launch_request id:org.smssecure.smssecure time:26714000
[...]
I/ActivityManager( 2317): Start proc 6800:org.smssecure.smssecure/u0a144 for activity org.smssecure.smssecure/.RoutingActivity
[...]
I/ActivityManager( 2317): Force stopping org.smssecure.smssecure appid=10144 user=0: from pid 4558
I/ActivityManager( 2317): Killing 6800:org.smssecure.smssecure/u0a144 (adj 0): stop org.smssecure.smssecure
I/WindowState( 2317): WIN DEATH: Window{26e694d3 u0 org.smssecure.smssecure/org.smssecure.smssecure.RoutingActivity}
D/ActivityManager( 2317): cleanUpApplicationRecord -- 6800
W/ActivityManager( 2317): Scheduling restart of crashed service org.smssecure.smssecure/.service.KeyCachingService in 1000ms
I/ActivityManager( 2317): Force stopping service ServiceRecord{6c4d55b u0 org.smssecure.smssecure/.service.KeyCachingService}
W/ActivityManager( 2317): Spurious death for ProcessRecord{30e52604 6800:org.smssecure.smssecure/u0a144}, curProc for 6800: null
[...]
I/ActivityManager( 2317): Start proc 6898:org.smssecure.smssecure/u0a144 for broadcast org.smssecure.smssecure/.service.SmsListener
The process still does not seem to restart itself after Scheduling, but at least it is restarted when a message is received.
Quod Erat Demonstrandum
I would like to add that this problem could be strongly related to issues #539 (closed), #578, #629, #638, #697 of Silence. Besides, it's an issue on Signal that put me on a good path to resolution: https://github.com/signalapp/Signal-Android/issues/5253. Users were able to identify a recurring pattern about the affected devices (Samsung Galaxy: https://github.com/signalapp/Signal-Android/issues/5253#issuecomment-279016541). These devices apparently have an aggressive energy management system, specific to the manufacturer.
This issue was unilaterally closed during a spring clean-up due to lack of information. It's extremely stupid of them because it's just a bug that's hard to track...
How to reproduce
- Check "restrict at launch"
- Open Silence
- Remove Silence from recent applications
- Send an encrypted or unencrypted message
- The message is not received
Or:
- Uncheck "restrict at launch"
- Open Silence
- Remove Silence from recent applications
- Send an encrypted or unencrypted message
- The message is received
Any combination involving or not intelligent energy management does not change the observed behaviour, only the option "Restrict at launch is decisive":
- Smart management disabled + Restrict at launch checked: No reception
- Smart management disabled + Restrict at launch unchecked: Receive
- Smart management enabled + Restrict at launch unchecked: Receive
- Smart management enabled + Restrict at launch checked: No reception
Actual result:
- Sent sms are not received because the application was closed by the system or by the user and was not restarted automatically.
- Worrying messages such as "Force stopping service ServiceRecord" and "Spurious death" are related to a permanent shutdown of the service.
Expected result:
- The service should remain in the background or be automatically restarted as soon as a message arrives on the phone.
Screenshots
Device info
Receiver phone (2):
- Device: Lenovo K5 Vibe
- Android version: 5.1.1
- Silence version: 0.15.13
Emitter phone (1):
- Device: Acer v370 Liquid E2
- Android version: CyanogenMod 11 - Android 4.4.4
- Silence version: 0.15.13
Link to debug log
...
Version française
Bug description
Suite à une perte fréquente et en apparence non reproductible de messages (chiffrés ou non) j'ai décidé d'étudier en détails les logcats des téléphones impliqués (emitter = Phone 1 = CyanogenMod 11; receiver = Phone 2 = Android 5.1.1).
La perte de SMS se fait a priori systématiquement sur le téléphone 2. À ma connaissance aucun sms n'a été perdu suite à un envoi vers le téléphone 1.
Après avoir longtemps comparé les logs, j'ai fini par remarquer que sur le téléphone 1 un arrêt de l'application se traduit toujours par un redémarrage programmé dans la seconde qui suit, alors que ce n'est pas le cas sur le téléphone 2.
Un arrêt sur le téléphone 1 se fait via:
- touche retour maintenue enfoncée (option "Tuer avec bouton retour" activée dans les options pour les développeurs),
- ou une suppression depuis la liste des applications récentes
Aucune différence de comportement n'a été observée suite à l'une ou l'autre de ces méthodes.
Sur le téléphone 2, il s'agit simplement de retirer l'application de la liste des applications récentes.
Voici la retranscription d'une conversation entre les 2 appareils. Le changement de PID indique que l'application a été redémarrée. Silence a été tué volontairement 1 fois sur le téléphone 1, et 2 fois sur le téléphone 2. La colonne taille indique le nombre de sms envoyés simultanément (sms multiples). L'indicateur [?] indique que le message a été perdu.
length ID phone1 ID phone2 PID phone1 PID phone2
1 37439 rep 14025 . arrêt forcé
rep 35319 . .
1 37441 rep 6267 .
rep 35321 . .
1 37443 rep . .
17h06 rep 35323 . .
17h20 1 37445 rep . .
17h20 1 37446 rep . .
17h21 1 37447 rep . .
17h23 rep 35327 . .
17h24 1 37449 rep . .
17h30 3 37450 rep . .
17h46 rep 35330 . 7318 retrait manuel apps récentes
17h46 rep 35331 . 29145 retrait manuel apps récentes
[?] 17h53 1 37453 ? . .
[?] 17h34 3 37454 ? . .
[?] 18h18 1 37455 ? . .
18h35 rep 35332 . 5335
Logcat en cas d'arrêt sur le téléphone 1:
I/ActivityManager( 520): Force stopping org.smssecure.smssecure appid=10136 user=0: from pid 520
I/ActivityManager( 520): Killing 14025:org.smssecure.smssecure/u0a136 (adj 0): stop org.smssecure.smssecure
W/ActivityManager( 520): Scheduling restart of crashed service org.smssecure.smssecure/.service.KeyCachingService in 1000ms
W/ActivityManager( 520): Force removing ActivityRecord{42517030 u0 org.smssecure.smssecure/.RoutingActivity t246}: app died, no saved state
W/WindowManager( 520): Rebuild removed 8 windows but added 7
[... stacktrace WindowManager...]
I/WindowState( 520): WIN DEATH: Window{423a93c8 u0 org.smssecure.smssecure/org.smssecure.smssecure.RoutingActivity}
I/Timeline( 7063): Timeline: Activity_launch_request id:org.smssecure.smssecure time:160479305
I/ActivityManager( 520): START u0 {act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] flg=0x10200000 cmp=org.smssecure.smssecure/.RoutingActivity bnds=[123,838][223,964]} from pid 7063
I/ActivityManager( 520): Start proc org.smssecure.smssecure for activity org.smssecure.smssecure/.RoutingActivity: pid=6267 uid=10136 gids={50136, 3003, 1028, 1015}
Les lignes qui me paraissent utiles ici sont:
- Arrêt manuel du PID 14025
- Programmation pour un redémarrage dans 1000ms
- Redémarrage instantané de l'application
Logcat en cas d'arrêt sur le téléphone 2:
I/Timeline( 5299): Timeline: Activity_launch_request id:org.smssecure.smssecure time:9831807
I/ActivityManager( 2317): START u0 {act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] flg=0x10200000 cmp=org.smssecure.smssecure/.RoutingActivity bnds=[536,1114][712,1280] (has extras)} from uid 10017 on display 0
V/WindowManager( 2317): addAppToken: AppWindowToken{1c9b6f26 token=Token{1b486281 ActivityRecord{fabee68 u0 org.smssecure.smssecure/.RoutingActivity t46}}} to stack=1 task=46 at 0
V/WindowManager( 2317): Adding window Window{379de0b9 u0 Starting org.smssecure.smssecure} at 5 of 9 (after Window{694fd95 u0 com.android.settings/com.android.settings.UsbSettings})
I/ActivityManager( 2317): Start proc 29145:org.smssecure.smssecure/u0a144 for activity org.smssecure.smssecure/.RoutingActivity
W/PassphraseRequiredActionBarActivity(29145): onDestroy()
I/ActivityManager( 2317): Force stopping org.smssecure.smssecure appid=10144 user=0: from pid 4558
I/ActivityManager( 2317): Killing 29145:org.smssecure.smssecure/u0a144 (adj 0): stop org.smssecure.smssecure
I/WindowState( 2317): WIN DEATH: Window{196152dc u0 org.smssecure.smssecure/org.smssecure.smssecure.RoutingActivity}
D/ActivityManager( 2317): cleanUpApplicationRecord -- 29145
W/ActivityManager( 2317): Scheduling restart of crashed service org.smssecure.smssecure/.service.KeyCachingService in 1000ms
I/ActivityManager( 2317): Force stopping service ServiceRecord{11a75f44 u0 org.smssecure.smssecure/.service.KeyCachingService}
W/ActivityManager( 2317): Spurious death for ProcessRecord{24d31f6c 29145:org.smssecure.smssecure/u0a144}, curProc for 29145: null
I/Timeline( 5299): Timeline: Activity_launch_request id:org.smssecure.smssecure time:12718265
I/ActivityManager( 2317): START u0 {act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] flg=0x10200000 cmp=org.smssecure.smssecure/.RoutingActivity bnds=[536,1114][712,1280] (has extras)} from uid 10017 on display 0
V/WindowManager( 2317): addAppToken: AppWindowToken{1c2fbc8a token=Token{3919b6f5 ActivityRecord{1b9cbc2c u0 org.smssecure.smssecure/.RoutingActivity t49}}} to stack=1 task=49 at 0
V/WindowManager( 2317): Adding window Window{1c4ecfad u0 Starting org.smssecure.smssecure} at 5 of 14 (after Window{694fd95 u0 com.android.settings/com.android.settings.UsbSettings})
I/ActivityManager( 2317): Start proc 5335:org.smssecure.smssecure/u0a144 for activity org.smssecure.smssecure/.RoutingActivity
Les lignes qui me semblent intéressantes ici sont :
- Démarrage du PID 29145 au temps 9831807
- Arrêt manuel du PID 29145
- Programmation pour un redémarrage dans 1000ms
- Arrêt forcé du service KeyCachingService ????
- Spurious death ????
- Redémarrage manuel au temps 12718265 avec le PID 5335
Entre les 2 redémarrages il s'est écoulé ((12718265-9831807)/1000) = 2886.458 secondes = 48 minutes. C'est le temps écoulé entre la réception du message 35331 et 35332. Or pendant ce temps, le téléphone 1 a envoyé 3 messages qui ont été perdus.
J'ai ensuite réalisé des tests après avoir décoché l'option "restreindre au lancement" liée à Silence sur le téléphone 2. (voir captures d'écran plus bas).
Protocole: Ouverture de Silence/Arrêt/attente de 20 secondes (pour permettre un redémarrage automatique éventuel)/envoi de message depuis le téléphone 1.
Logcat:
I/Timeline( 5299): Timeline: Activity_launch_request id:org.smssecure.smssecure time:26714000
[...]
I/ActivityManager( 2317): Start proc 6800:org.smssecure.smssecure/u0a144 for activity org.smssecure.smssecure/.RoutingActivity
[...]
I/ActivityManager( 2317): Force stopping org.smssecure.smssecure appid=10144 user=0: from pid 4558
I/ActivityManager( 2317): Killing 6800:org.smssecure.smssecure/u0a144 (adj 0): stop org.smssecure.smssecure
I/WindowState( 2317): WIN DEATH: Window{26e694d3 u0 org.smssecure.smssecure/org.smssecure.smssecure.RoutingActivity}
D/ActivityManager( 2317): cleanUpApplicationRecord -- 6800
W/ActivityManager( 2317): Scheduling restart of crashed service org.smssecure.smssecure/.service.KeyCachingService in 1000ms
I/ActivityManager( 2317): Force stopping service ServiceRecord{6c4d55b u0 org.smssecure.smssecure/.service.KeyCachingService}
W/ActivityManager( 2317): Spurious death for ProcessRecord{30e52604 6800:org.smssecure.smssecure/u0a144}, curProc for 6800: null
[...]
I/ActivityManager( 2317): Start proc 6898:org.smssecure.smssecure/u0a144 for broadcast org.smssecure.smssecure/.service.SmsListener
Le processus ne semble toujours pas relancé tout seul après le Scheduling, mais au moins il l'est suite à la réception d'un message.
CQFD.
J'ajoute que ce problème pourrait être fortement lié aux issues #539 (closed), #578, #629, #638, #697 de Silence. Par ailleurs c'est une issue sur Signal qui m'a mis sur une bonne voie de résolution https://github.com/signalapp/Signal-Android/issues/5253. Les utilisateurs ont réussi à dégager un motif récurrent à propos des appareils touchés (Samsung Galaxy : https://github.com/signalapp/Signal-Android/issues/5253#issuecomment-279016541). Ces appareils ont apparemment une gestion de l'énergie agressive propre au constructeur. Cette issue a été close de façon unilatérale durant un nettoyage de printemps à cause du manque d'informations. C'est extrêmement stupide de leur part car c'est justement un bug difficile à tracer.
How to reproduce
- Check "restreindre au lancement"
- Ouvrir Silence
- Retirer Silence des applications récentes
- Envoyer un message chiffré ou non
- Le message n'est pas reçu
ou:
- Décocher "restreindre au lancement"
- Ouvrir Silence
- Retirer Silence des applications récentes
- Envoyer un message chiffré ou non
- Le message est reçu
Toute combinaison impliquant ou non la gestion intelligente de l'énergie ne change pas le comportement observé, seule l'option "Restreindre au lancement" est décisive:
- Gestion intelligente désactivée + Restreindre au lancement coché: Pas de réception
- Gestion intelligente désactivée + Restreindre au lancement décoché : Réception
- Gestion intelligente activée + Restreindre au lancement décoché : Réception
- Gestion intelligente activée + Restreindre au lancement coché: Pas de réception
Actual result:
- Sent sms are not received because the application was closed by the system or by the user and was not restarted automatically.
- Des messages inquiétants tels que "Force stopping service ServiceRecord" et "Spurious death" sont liés à un arrêt définitif du service.
Expected result: The service should remain in the background or be automatically restarted as soon as a message arrives on the phone.
Screenshots
Device info
Receiver phone (2):
- Device: Lenovo K5 Vibe
- Android version: 5.1.1
- Silence version: 0.15.13
Emitter phone (1):
- Device: Acer v370 Liquid E2
- Android version: CyanogenMod 11 - Android 4.4.4
- Silence version: 0.15.13
Link to debug log
...