Closed andrei-mart closed 4 years ago
andyholmes
commented
4 years ago It seems like the problem is in cache, did you already have messages downloaded before opening the window? Does anything look strange or empty in ~/.cache/gsconnect/<device-id>/sms.json or in the censored packets?
andrei-mart
commented
4 years ago Right, apparently something was in the cache. Perhaps data from older version. I used the clear cache button in setting, now the window came up and populated OK. I am OK if the issue is closed without any action. Though it might be helpful to automatically clear cache if data load fails.
andyholmes
commented
4 years ago Might not be a bad idea, I'll amend the issue title. Thanks for the logs, those will be helpful :)
ferdnyc
commented
4 years ago Though it might be helpful to automatically clear cache if data load fails.
Or perhaps to bring up the window, but with a "Clear Cache" button showing in place of the corrupted message history.
That way it's still the user's decision to clear the cache. (Vs. correcting the issue, say if it was something they introduced during testing or experimentation.) But it's as easy as possible, and at least there's still some visible UI instead of just a missing window.
Though... a cache is just a cache, I suppose. In theory it can be rebuilt. So deleting it automatically isn't really that destructive, now that I think about it.
andrei-mart
commented
4 years ago User does not own cache, it is maintained and consumed by the application, so it should be totally OK to discard. Empty window with button is anyway better then silent fail, which, I suppose, was caused by an unhandled exception. If feasible, generic handler showing a dialog box would be good to add.
andyholmes
commented
4 years ago Yeah, it's difficult to approach error handling in GSConnect, because we get a spread of users from "I just got the Linux" to "I could fix this if it were x86 assembly".
Usually a situation like this I use a full logError(), so this error would have shown in your normal logs (without our Generate Support Log thing). I think here it's probably best to log the error as normal, silently discard the cache, and just request the messages again. If the last step turns out to be noticeable it might be time to put an in-app notification in the window.
If the recent work in the SMS plugin fixes messaging for everyone, like it seems to be, it would be nice to toss the "Help" link that just opens another explanation about how it's not our fault :)
andrei-mart
commented
4 years ago Apparently, the problem is not because of corrupted cache, but because of its size. It happened again, so I was able to collect some data points. My sms.json is 370K with 127 threads, still valid json:
$ jq '."_threads"|length' sms.json
127Yes, I am not the one who cares about deleting old messages :-) So if I clear the cache, the windows comes up empty, and starts populating threads with data from the device. At some point it (silently) hits the limit, so some threads are not shown, but otherwise it works OK, until plugin is restarted. After restart the huge cache is here and window fails to create.
andrei-mart
commented
4 years ago On the second thought there could be something in the data, something not obvious. I collected syslog messages reflecting sequence "service restart / clean cache / show messages" Messages window came up empty, then was populated with approx. 50 threads. HTH
$ grep 12033 /var/log/syslog
Jul 4 11:34:11 tlusty gjs[12033]: Failed to load module "appmenu-gtk-module"
Jul 4 11:34:11 tlusty gjs[12033]: g_variant_new_string: assertion 'string != NULL' failed
Jul 4 11:34:11 tlusty dbus-daemon[2824]: [session uid=1000 pid=2824] Connection :1.221 (uid=1000 pid=12033 comm="gjs /home/andrei/.local/share/gnome-shell/extensio" label="unconfined") became a monitor.
Jul 4 11:34:17 tlusty gjs[12033]: JS WARNING: [/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/plugins/sms.js 221]: reference to undefined property "-1"
Jul 4 11:34:17 tlusty gjs[12033]: JS ERROR: TypeError: cache[(cache.length - 1)] is undefined#012_handleDigest@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/plugins/sms.js:221:17#012_handleMessages@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/plugins/sms.js:324:22#012handlePacket@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/plugins/sms.js:175:18#012receivePacket@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/device.js:441:29#012receive/<@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/protocol/core.js:299:32#012@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/daemon.js:1132:17
Jul 4 11:34:50 tlusty gjs[12033]: JS ERROR: sms: TypeError: message is undefined#012_onThreadsChanged@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/ui/messaging.js:982:17#012_init@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/ui/messaging.js:856:14#012get window@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/plugins/sms.js:162:28#012sms@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/plugins/sms.js:449:9#012_activateAction@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/plugins/base.js:63:35#012@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/daemon.js:1132:17
Jul 4 11:34:50 tlusty gjs[12033]: JS ERROR: TypeError: cache[(cache.length - 1)] is undefined#012_handleDigest@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/plugins/sms.js:221:17#012_handleMessages@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/plugins/sms.js:324:22#012handlePacket@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/plugins/sms.js:175:18#012receivePacket@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/device.js:441:29#012receive/<@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/protocol/core.js:299:32#012@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/daemon.js:1132:17
Jul 4 11:34:50 tlusty gjs[12033]: JS ERROR: TypeError: message is undefined#012_onThreadsChanged@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/ui/messaging.js:982:17#012_handleThread@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/plugins/sms.js:286:18#012_handleMessages@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/plugins/sms.js:328:22#012handlePacket@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/plugins/sms.js:175:18#012receivePacket@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/device.js:441:29#012receive/<@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/protocol/core.js:299:32#012@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/daemon.js:1132:17
Jul 4 11:36:57 tlusty gjs[12033]: JS ERROR: TypeError: message is undefined#012_onThreadsChanged@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/ui/messaging.js:982:17#012_handleThread@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/plugins/sms.js:286:18#012_handleMessages@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/plugins/sms.js:328:22#012handlePacket@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/plugins/sms.js:175:18#012receivePacket@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/device.js:441:29#012receive/<@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/protocol/core.js:299:32#012@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/daemon.js:1132:17
Jul 4 11:36:58 tlusty gjs[12033]: message repeated 19 times: [ JS ERROR: TypeError: message is undefined#012_onThreadsChanged@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/ui/messaging.js:982:17#012_handleThread@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/plugins/sms.js:286:18#012_handleMessages@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/plugins/sms.js:328:22#012handlePacket@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/plugins/sms.js:175:18#012receivePacket@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/device.js:441:29#012receive/<@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/protocol/core.js:299]
Jul 4 11:36:58 tlusty gjs[12033]: JS ERROR: TypeError: message is undefined#012_onThreadsChanged@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/ui/messaging.js:982:17#012_handleThread@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/plugins/sms.js:286:18#012_handleMessages@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/plugins/sms.js:328:22#012handlePacket@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/plugins/sms.js:175:18#012receivePacket@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/device.js:441:29#012receive/<@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/protocol/core.js:299:32#012@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/daemon.js:1132:17
Jul 4 11:37:01 tlusty gjs[12033]: message repeated 127 times: [ JS ERROR: TypeError: message is undefined#012_onThreadsChanged@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/ui/messaging.js:982:17#012_handleThread@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/plugins/sms.js:286:18#012_handleMessages@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/plugins/sms.js:328:22#012handlePacket@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/plugins/sms.js:175:18#012receivePacket@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/device.js:441:29#012receive/<@/home/andrei/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/protocol/core.js:299]Unless you're running out of RAM or have more than 9, 007, 199, 254, 740, 991 messages per thread, it's probably not a limit problem. On the other hand, it may be a similar problem in kdeconnect-android if that code makes a different assumption about max num threads/messages. I doubt that also, but I am less sure.
It seems like the problem starts at the message TypeError: cache[(cache.length - 1)]. Somehow a thread is being cached (an Array) with no messages (Array elements), so the equation ends up being 0 - 1 = -1. Since an array can't have negative elements, it's throwing a TypeError.
To help debug, in ~/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/plugins/sms.js try changing:
To the below (just adding || !cache.length to the if):
// If we don't have a thread for this message or it's newer
// than the last message in the cache, request the thread
if (!cache || !cache.length || cache[cache.length - 1].date < message.date) {
this.requestConversation(message.thread_id);
}Then just touch ~/.local/share/gnome-shell/extensions/gsconnect@andyholmes.github.io/service/daemon.js to restart the service.
This check shouldn't be needed since we should never have an empty thread, so this could highlight why that assumption is being broken. I can whip you up a ZIP if you're not comfortable making that change, I'll just have to cleanup my working tree a bit.
andrei-mart
commented
4 years ago Well, it is unlikely that 370K of data can cause out of memory error... Anyway, unfortunately I think I destroyed the test case. I went through messages in my device and deleted those I don't need, mostly notifications from automated systems, 2PA codes, etc. and issue is no longer reproduced. Also the device's cache subdirectory was completely wiped out at some point, and copy of sms.json that I had made was gone. It is funny, @ferdnyc hesitated to clean up the cache above in the thread :). If there was threads without messages I would be able to confirm. Nonetheless, I identified at least one case when thread may end up empty. https://github.com/andyholmes/gnome-shell-extension-gsconnect/blob/1e97d0f0eafaf98d91d223a4f206aac7edd52fc5/src/service/plugins/sms.js#L267 It means if thread consists of only messages with types outside of [0..5] range, the cache will remain empty list, and will be written down at the end of the function.
andrei-mart
commented
4 years ago Ah, I know what it was! There is no harm if I post it here
$ jq '.body.messages[]|select(.type==19)' /tmp/crunch.log
{
"addresses": [
{
"address": "Imminent extreme alert"
}
],
"body": "Residents on Mt Eden Rd are to shelter in place for emergent heavy equipment access.",
"date": 1500336321000,
"type": 19,
"read": 1,
"thread_id": 43,
"_id": 417,
"sub_id": -1,
"event": 1
}
{
"addresses": [
{
"address": "Imminent severe alert"
}
],
"body": "Cnh bo nhit cao. Thng tin Trung tam làm mt ti www.sccgov.org/heatwatch",
"date": 1504303196000,
"type": 19,
"read": 1,
"thread_id": 45,
"_id": 444,
"sub_id": -1,
"event": 1
}
{
"addresses": [
{
"address": "AMBER alert"
}
],
"body": "AMBER ALERT. SUSPECT VEHICLE 2012 BLACK FORD FUSION, WITH CA PLATE 8BDY654. CALL 911.",
"date": 1537889451000,
"type": 19,
"read": 1,
"thread_id": 60,
"_id": 580,
"sub_id": -1,
"event": 1
}
{
"addresses": [
{
"address": "Presidential alert"
}
],
"body": "THIS IS A TEST of the National Wireless Emergency Alert System. No action is needed.",
"date": 1538591010000,
"type": 19,
"read": 1,
"thread_id": 61,
"_id": 585,
"sub_id": -1,
"event": 1
}
{
"addresses": [
{
"address": "Imminent extreme alerts"
}
],
"body": "Silver Alert. Missing/Endangered Elderly. Details at http://chp.click/alert",
"date": 1572930146354,
"type": 19,
"read": 1,
"thread_id": 95,
"_id": 971,
"sub_id": -1,
"event": 1
}
{
"addresses": [
{
"address": "AMBER alerts"
}
],
"body": "AMBER ALERT. RED HYUNDAI ELANTRA, CA PLATE 5SKT544. Details at http://chp.click/alert",
"date": 1569121480253,
"type": 19,
"read": 1,
"thread_id": 136,
"_id": 936,
"sub_id": -1,
"event": 1
}Interesting, I didn't consider that as a cause. Are you using RCS messaging, or perhaps group MMS messages?
19 is way out of range for that field. That value comes from an enumeration defined by Android for the "message box", such as inbox, outbox, drafts, etc.
andrei-mart
commented
4 years ago These are emergency alerts broadcast to all cells in the area. Are you never getting something similar? I do not know where type comes from, that's what I was receiving from my device. I still have full support log I collected 2 weeks ago, it was in censored data.
andrei-mart
commented
4 years ago I see, you mean https://developer.android.com/reference/android/provider/Telephony.BaseMmsColumns#MESSAGE_BOX They really don't have a constant defined to fit this kind of messages.
andrei-mart
commented
4 years ago https://github.com/andyholmes/gnome-shell-extension-gsconnect/commit/6651d857497160a367da07f8f3d609f1be20f44c Do not see any linked issue or other explanation. Curious, why it was done. Other change is even more strict and pops messages with types other than 1 or 2. That may empty out the thread, too.
andyholmes
commented
4 years ago Curious, why it was done. Other change is even more strict and pops messages with types other than 1 or 2.
The SMS plugin will ignore messages out of the range of known constants, including only inbox, sent, outbox, drafts and failed. Any other types are ignored, because if we can't even determine whether the message was incoming/outgoing, how do we present it to the user? We might not even be able to figure out who the sender was.
In the messaging window we only handle inbox and sent, because outbox means waiting to be sent (we handle that UI), we can't edit or complete drafts (no protocol support), and failed messages are effectively not messages (also no protocol support for these errors).
The only reason we cache outbox, drafts and failed at all is because we can be confident that an outbox/draft message will end up as a sent/failed or be deleted. It will still carry the original message and thread IDs though, so ignoring them would just mean another full re-sort of the thread later, when we get the resolved message.
I guess I'll just have to figure out where 19 is coming from, because that's bizarre to me :/
andrei-mart
commented
4 years ago The documentation does not sound like the defined list of message box types is complete, so it should be OK if vendor defines own types. If I get a device from other vendor and more of these broadcast messages, I'll provide more information. Representation wise, having more information some solution might be found. For example, internal database of known vendors and their custom message types mapped to representation properties (left or right aligned). Unknown types might be center-aligned. I would actually prefer to see all types of messages, of course I need to be able to distinguish drafts, sent, failed etc., so there should be icon decorations or color or tooltip, whatever. Even if protocol does not allow to save draft messages from the computer, I may want to use message drafted at the device as a template. Nothing special is needed to support that, just display, so I can copy/paste the text. Anyway, these are items for future development. This ticket is about disagreement in design. Some code is written with assumption that thread can not be empty, while other breaks that by discarding messages from the thread, potentially all. They should agree on something.
andyholmes
commented
4 years ago The documentation does not sound like the defined list of message box types is complete, so it should be OK if vendor defines own types. [...] For example, internal database of known vendors and their custom message types mapped to representation properties (left or right aligned).
Well, strictly speaking it does cover every possible message state: drafted, sent, in process of sending, failed to send and received. This isn't intended as a type, but a state that just happens to imply a direction. I see no reason why a public broadcast wouldn't be considered a "received" message.
I'm not aware of such a list, but if it exists it could require access to source code that is just unavailable; not all vendors open source their apps.
I would actually prefer to see all types of messages, of course I need to be able to distinguish drafts, sent, failed etc., so there should be icon decorations or color or tooltip, whatever. Even if protocol does not allow to save draft messages from the computer, I may want to use message drafted at the device as a template. Nothing special is needed to support that, just display, so I can copy/paste the text.
Well, as I said this requires support in the protocol, because as far as I see drafts/outbox/failed aren't being forwarded by kdeconnect-android at all. outbox messages might just complete sending too fast to see, but I have draft and error texts in my database and neither are sent from the device.
Some references to internal Android queries:
So either there is a special content:// URI needed to access these, there is no database trigger for these types, or access is restricted by Android for 3rd party apps (or a combination). In any case, there's nothing that can be done on the client side to change that and in some cases this may not be fixable even in the Android app.
Some code is written with assumption that thread can not be empty, while other breaks that by discarding messages from the thread, potentially all. They should agree on something.
Sure, I'll just push the fix I mentioned before. It should prevent the original error and can't cause any harm.
I select Messages from the menu, nothing happens. As simple as that.
Support Log
I'm pasting lines from the log that seem relevant. Communication with the device happens, and look correct to me, response messages contain full messages history.
System Details (please complete the following information):
GSConnect environment (if applicable):
Additional Notes:
If I enable "legacy mode", the Send SMS comes up OK, though it does not display SMS history I believe by design.