Activesync update fail

asked 2015-11-05 19:18:28 +0300

sedric
113 ●6 ●10 ●17

updated 2015-11-10 18:10:08 +0300

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 ?