Update
I've determined that the source of the problems could be caused by inadvertent local changes to folks-cache.py
(see followup comment below), so please ignore this for right now while I revert those.
Original Report
Yikes. One of my two devices wasn't showing status in the User Menu even though it was on the network, so I went looking for error output in the journal only to discover these messages being output, in bursts, at the rate of many per second:
Dec 01 02:54:45 teevey gjs[9775]: JS ERROR: TypeError: this.model.get_value(...) is null
ContactCompletion<._match@/home/ferd/.local/share/gnome-shell/extensions/[email protected]/widgets/telephony.js:184:20
wrapper@resource:///org/gnome/gjs/modules/lang.js:178:22
ContactCompletion<._add@/home/ferd/.local/share/gnome-shell/extensions/[email protected]/widgets/telephony.js:177:1
wrapper@resource:///org/gnome/gjs/modules/lang.js:178:22
ContactCompletion<._populate@/home/ferd/.local/share/gnome-shell/extensions/[email protected]/widgets/telephony.js:150:13
wrapper@resource:///org/gnome/gjs/modules/lang.js:178:22
ContactCompletion<._init/<@/home/ferd/.local/share/gnome-shell/extensions/[email protected]/widgets/telephony.js:140:13
ContactsCache<._init/<@/home/ferd/.local/share/gnome-shell/extensions/[email protected]/service/plugins/telephony.js:626:17
@/home/ferd/.local/share/gnome-shell/extensions/[email protected]/service/daemon.js:653:2
Dec 01 02:54:45 teevey gjs[9775]: JS ERROR: TypeError: this.model.get_value(...) is null
ContactCompletion<._match@/home/ferd/.local/share/gnome-shell/extensions/[email protected]/widgets/telephony.js:184:20
wrapper@resource:///org/gnome/gjs/modules/lang.js:178:22
ContactCompletion<._add@/home/ferd/.local/share/gnome-shell/extensions/[email protected]/widgets/telephony.js:177:1
wrapper@resource:///org/gnome/gjs/modules/lang.js:178:22
ContactCompletion<._populate@/home/ferd/.local/share/gnome-shell/extensions/[email protected]/widgets/telephony.js:150:13
wrapper@resource:///org/gnome/gjs/modules/lang.js:178:22
ContactCompletion<._init/<@/home/ferd/.local/share/gnome-shell/extensions/[email protected]/widgets/telephony.js:140:13
ContactsCache<._init/<@/home/ferd/.local/share/gnome-shell/extensions/[email protected]/service/plugins/telephony.js:626:17
@/home/ferd/.local/share/gnome-shell/extensions/[email protected]/service/daemon.js:653:2
Dec 01 02:54:45 teevey gjs[9775]: JS ERROR: TypeError: this.model.get_value(...) is null
ContactCompletion<._match@/home/ferd/.local/share/gnome-shell/extensions/[email protected]/widgets/telephony.js:184:20
wrapper@resource:///org/gnome/gjs/modules/lang.js:178:22
ContactCompletion<._add@/home/ferd/.local/share/gnome-shell/extensions/[email protected]/widgets/telephony.js:177:1
wrapper@resource:///org/gnome/gjs/modules/lang.js:178:22
ContactCompletion<._populate@/home/ferd/.local/share/gnome-shell/extensions/[email protected]/widgets/telephony.js:150:13
wrapper@resource:///org/gnome/gjs/modules/lang.js:178:22
ContactCompletion<._init/<@/home/ferd/.local/share/gnome-shell/extensions/[email protected]/widgets/telephony.js:140:13
ContactsCache<._init/<@/home/ferd/.local/share/gnome-shell/extensions/[email protected]/service/plugins/telephony.js:626:17
@/home/ferd/.local/share/gnome-shell/extensions/[email protected]/service/daemon.js:653:2
Dec 01 02:54:45 teevey gjs[9775]: JS ERROR: TypeError: this.model.get_value(...) is null
ContactCompletion<._match@/home/ferd/.local/share/gnome-shell/extensions/[email protected]/widgets/telephony.js:184:20
wrapper@resource:///org/gnome/gjs/modules/lang.js:178:22
ContactCompletion<._add@/home/ferd/.local/share/gnome-shell/extensions/[email protected]/widgets/telephony.js:177:1
wrapper@resource:///org/gnome/gjs/modules/lang.js:178:22
ContactCompletion<._populate@/home/ferd/.local/share/gnome-shell/extensions/[email protected]/widgets/telephony.js:150:13
wrapper@resource:///org/gnome/gjs/modules/lang.js:178:22
ContactCompletion<._init/<@/home/ferd/.local/share/gnome-shell/extensions/[email protected]/widgets/telephony.js:140:13
ContactsCache<._init/<@/home/ferd/.local/share/gnome-shell/extensions/[email protected]/service/plugins/telephony.js:626:17
@/home/ferd/.local/share/gnome-shell/extensions/[email protected]/service/daemon.js:653:2
In the three seconds from Dec 01 02:54:43 to Dec 01 02:54:45, grep
counts 1204 instances of 'model.get_value', but none immediately before and none since then. (As I type this sentence it's now Dec 01 03:07 locally.) They seem to come in infrequent bursts, but every time they do come it's a deluge. Here's a per-second count of the number of those messages logged, over the past 10k lines of my user journal:
% IFS="
"; for string in `journalctl --user -n 10000 |grep 'model.get_value' |cut -c1-15|uniq`; do echo -n "${string} - "; journalctl --user -n 10000 --no-pager |grep 'model.get_value' |grep -c "${string}"; done
Nov 30 21:01:22 - 201
Nov 30 21:01:23 - 402
Nov 30 21:01:24 - 601
Nov 30 21:39:00 - 157
Nov 30 21:39:01 - 231
Nov 30 21:39:02 - 215
Nov 30 21:39:03 - 517
Nov 30 21:39:04 - 84
Nov 30 22:42:18 - 247
Nov 30 22:42:19 - 481
Nov 30 22:42:20 - 476
Nov 30 23:39:13 - 201
Nov 30 23:39:14 - 561
Nov 30 23:39:15 - 442
Dec 01 00:53:52 - 36
Dec 01 00:53:53 - 354
Dec 01 00:53:54 - 641
Dec 01 00:53:55 - 173
Dec 01 01:42:12 - 380
Dec 01 01:42:13 - 635
Dec 01 01:42:14 - 189
Dec 01 02:13:14 - 146
Dec 01 02:13:15 - 508
Dec 01 02:13:16 - 550
Dec 01 02:54:43 - 352
Dec 01 02:54:44 - 413
Dec 01 02:54:45 - 439
Which, if you're playing along at home, means that 9,632 of the last 10,000 journal lines (96.3%) are that message. Or, going back farther, 18,431/20,000 (92.2%); 34,850/40,000 (87.1%); 44,346/50,000 (88.7%). Going back 50k lines only gets me as far as Nov 29 17:55:30 (a day and a half ago), and nowhere near the first instance of this issue. (Which may be Nov 26, though I also found a single, solitary matching log message back on Nov 22. The gjs
process hosting daemon.js
with PID 9775 was started on Nov 24. So only that one solitary outlier predates the current process, and these massive bursts didn't start up until the current daemon process had been running for around two days. Curiouser and curiouser.)
Each spam-burst looks to be preceded by this exact sequence. (That's based on a spot-check of two or three, I haven't examined every burst.) It always involves the same one of my two paired devices. (Not the one that isn't reporting correctly in the user menu, so that's probably completely unrelated and I'm not yet sure what the issue is there. But it makes sense that my phone 'lge' would be the device triggering this, as it's the only one for which the Telephony plugin is enabled. The other device is WiFi-only with no mobile service.)
Dec 01 02:54:34 teevey gjs[9775]: JS LOG: Failed to receive packet: Gio.TlsError: TLS connection closed unexpectedly
Dec 01 02:54:34 teevey gjs[9775]: JS LOG: Disconnected from 'lge'
Dec 01 02:54:41 teevey gjs[9775]: JS LOG: Daemon: Updating device
Dec 01 02:54:41 teevey gjs[9775]: JS LOG: Connecting to '${REDACTED}'
Dec 01 02:54:41 teevey gjs[9775]: JS LOG: Daemon: Updating device
Dec 01 02:54:42 teevey gjs[9775]: JS LOG: Authenticating '${REDACTED}'
Dec 01 02:54:42 teevey gjs[9775]: JS LOG: Connected to 'lge'
I'm still investigating here on my end, and will update if I come up with anything more to go on. For all the data I've spammed into this report (...revenge? π), I realize it's somewhat light on useful info so far. I apologize for that, and will attempt to rectify it. But, any thoughts would be welcome!