Activesync update fail
Hi,
I have currently have a weird bug : since 1.9 my Activesync account stop updating sometimes and for now, the only "cure" I found is to reboot my phone. When I try to update manually, it just wait and finish to fail after a long time.
I try to add logs to messageserver as seen in question 42160 but I see nothing in it even after a working sync (and messageserver5 seems fine... Globally, my phone is fine).
I also try delete/recreate my account (fun part : delete/recreate and I still have to reboot).
Did anyone have a clue about what I can do next to debug ?
Edit: It happen randomly. Sometime it stop one time in a week and sometime, several times in a day. I suspect a roaming problem at first, but it seems to do it even if I stay on the same connexion.
Edit2:
nemo@Jolla:~$ devel-su ps axu | grep messageserver5
Password:
nemo 1085 0.1 1.6 82048 13696 ? Ssl 01:54 0:59 /usr/bin/messageserver5
nemo 1119 0.0 0.0 2008 228 ? Ss 01:54 0:00 /usr/bin/invoker -o --type=qt5 --global-syms /usr/bin/messageserver5
nemo 30054 0.1 0.0 4116 768 pts/0 S+ 15:42 0:00 grep --color messageserver5
nemo@Jolla:~$ devel-su ps axu | grep as-daemon
Password:
nemo 1004 0.0 0.0 2008 228 ? Ss 01:54 0:00 /usr/bin/invoker -o --type=qt5 --global-syms /usr/bin/as-daemon
nemo 1007 0.5 4.6 109192 38800 ? Ssl 01:54 4:53 /usr/bin/as-daemon
nemo 30082 0.1 0.0 4116 768 pts/0 S+ 15:42 0:00 grep --color as-daemon
messageserver5 does not seems to be stuck (as it flood me when I'm attached to it via strace) but as-daemon (I was wondering what it was... ActiveSync Daemon, that make sense...) don't seems to do anything I try to restart it with systemctl but I didn't find any service that seems ok. I just try to close it (kill -15) and it pop again from it's own. My mail just sync after that :-)
Thanks to you chris.adams, I found the guilty :-) I add some logging to .config/Nokia/activesync.conf, we will see :-)
edit3: Hum... When activesync stop making updates logs says : [Warning] QDBusAbstractAdaptor: Cannot relay signal DBusListener::externalRequest(int,qulonglong,RequestMakerRoutine,bool): Type not registered with QtDBus in parameter list: RequestMakerRoutine
It seems to be a "normal" message (as I've got far more lines that just this ones when it hang), but when as-daemon stop, it ONLY log this for every time it try to update.
The killing time is also fun. As I'm nice with my proccess, I just ask them to seppuku (pkill -15 as-daemon). So in a few seconds the process seems to remember all the stuffs it stack hours ago :
[4054] nov. 07 17:15:05 [Debug] General : ActiveSyncServer::createSyncAll( 4 )
[4054] nov. 07 17:15:05 [Debug] General : Job Job(0x164be10) created
[4054] nov. 07 17:15:05 [Debug] General : Job Job(0x1c492d0) created
[4054] nov. 07 17:15:05 [Debug] General : RequestMaker ActiveSyncServer::createSyncAll(int) started sync job in account 9
[4054] nov. 07 17:15:05 [Debug] General : RequestMaker ActiveSyncServer::createSyncAll(int) synchronization started
[4054] nov. 07 17:15:05 [Debug] General : Job Job(0x161ca68) created
[4054] nov. 07 17:15:05 [Debug] General : Starting job OperationRequest(0x161ca68)
[4054] nov. 07 17:15:05 [Debug] General : Request 125 started
[4054] nov. 07 17:15:05 [Debug] Network : QtConnectionManager: requested to go online (ask user = true )
[4054] nov. 07 17:15:05 [Debug] Network : QtConnectionManager: valid session found, trying to reopen
[4054] nov. 07 17:15:05 [Debug] Network : QtConnectionManager: reopening network session
[4054] nov. 07 17:15:05 [Debug] Network : Network session is being closed, state 3 , there are 0 transfers ( 0 pending)
[4054] nov. 07 17:15:05 [Debug] Network : virtual QtNetworkAccess::~QtNetworkAccess()
[4054] nov. 07 17:15:05 [Debug] Network : Network session closed
[4054] nov. 07 17:15:05 [Debug] Network : QtConnectionManager: opening network session "/net/connman/service/wifi_5056a801419b_6574686572_managed_psk" "ether" 0 (ask user = true )
[4054] nov. 07 17:15:05 [Debug] Network : Network session opened, state 3
[4054] nov. 07 17:15:05 [Debug] General : ActiveSyncServer::createSyncAll( 4 )
[4054] nov. 07 17:15:05 [Debug] General : Job Job(0x173adb0) created
[4054] nov. 07 17:15:05 [Debug] General : Job Job(0x1960128) created
[4054] nov. 07 17:15:05 [Debug] General : RequestMaker ActiveSyncServer::createSyncAll(int) started sync job in account 9
[4054] nov. 07 17:15:05 [Debug] General : RequestMaker ActiveSyncServer::createSyncAll(int) synchronization started
[4054] nov. 07 17:15:05 [Debug] General : Job Job(0x1a4ba10) created
[4054] nov. 07 17:15:05 [Debug] General : Starting job OperationRequest(0x1a4ba10)
[4054] nov. 07 17:15:05 [Debug] General : Request 126 started
[4054] nov. 07 17:15:05 [Debug] Network : QtConnectionManager: requested to go online (ask user = true )
[4054] nov. 07 17:15:05 [Debug] Network : QtConnectionManager: valid session found, trying to reopen
[4054] nov. 07 17:15:05 [Debug] Network : QtConnectionManager: reopening network session
[4054] nov. 07 17:15:05 [Debug] Network : Network session is being closed, state 3 , there are 0 transfers ( 0 pending)
[4054] nov. 07 17:15:05 [Debug] Network : Network session closed
[4054] nov. 07 17:15:05 [Debug] Network : QtConnectionManager: opening network session "/net/connman/service/wifi_5056a801419b_6574686572_managed_psk" "ether" 0 (ask user = true )
[4054] nov. 07 17:15:05 [Debug] Network : Network session opened, state 3
[4054] nov. 07 17:15:05 [Debug] General : ActiveSyncServer::createSyncAll( 4 )
And then, everybody dies :
[4054] nov. 07 17:15:13 [Debug] General : Job Job(0x1805118) destroyed
[4054] nov. 07 17:15:13 [Debug] General : Job Job(0x19156a0) destroyed
[4054] nov. 07 17:15:13 [Debug] General : Job Job(0x2bce370) destroyed
[4054] nov. 07 17:15:13 [Debug] General : Job Job(0x1c372a8) destroyed
[4054] nov. 07 17:15:13 [Debug] General : Job Job(0x1cce5d0) destroyed
[4054] nov. 07 17:15:13 [Debug] General : Job Job(0x1c6fef0) destroyed
[4054] nov. 07 17:15:13 [Debug] General : Job Job(0x18457d8) destroyed
[4054] nov. 07 17:15:13 [Debug] General : Job Job(0x18ac890) destroyed
[4054] nov. 07 17:15:13 [Debug] General : Job Job(0x18ac868) destroyed
[4054] nov. 07 17:15:13 [Debug] General : Job Job(0x1534de0) destroyed
[4054] nov. 07 17:15:13 [Debug] General : Job Job(0x1663d20) destroyed
[4054] nov. 07 17:15:13 [Debug] General : Job Job(0x1cf5218) destroyed
[4054] nov. 07 17:15:13 [Debug] General : Job Job(0x1cf5700) destroyed
[4054] nov. 07 17:15:13 [Debug] General : Job Job(0x1b8a9e8) destroyed
[4054] nov. 07 17:15:13 [Debug] General : Job Job(0x190e800) destroyed
[4054] nov. 07 17:15:13 [Debug] General : Job Job(0x1c63228) destroyed
[4054] nov. 07 17:15:13 [Debug] General : Job Job(0x192fed0) destroyed
$ grep -c 'nov. 07 17:15:.*Job.*destroyed' activesync.log
107
It seems to be really stuck... May I provide something to find out what ?
It sounds like a sync process is getting "stuck" (after the first time it succeeds, but prior to shutting down fully) resulting in subsequent sync attempts failing to begin.
Can you provide the output of:
devel-su ps axu | grep messageserver5
devel-su ps axu | grep as-daemon
once it's in the stuck state?
chris.adams ( 2015-11-06 10:38:55 +0200 )edit