Relationship Graph

View IssueDependency GraphShow Summary
Relationship Graph
related to related to child of child of duplicate of duplicate of

View Issue Details

Related ChangesetsJump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0003969SOGoActiveSyncpublic2016-12-23 19:262017-01-09 20:49
Reporterbeli3ver Assigned Toludovic  
PrioritynormalSeverityminorReproducibilityalways
Status resolvedResolutionfixed 
Platform[Server] LinuxOSDebianOS Version8 (Jessie)
Fixed in Version3.2.5 
Summary0003969: Active Sync HTTP 500 Error
Description

Hello,

since some days I get always on Active Syn this error:

Dec 23 20:20:10 sogod [1220]: 46.223.1.8 "POST /SOGo/Microsoft-Server-ActiveSync?User=XXXX&DeviceId=0T8D39M47T6658S7M9QNVUJRD4&DeviceType=iPhone&Cmd=Ping HTTP/1.0" 500 36/0 0.002 - - 0
Dec 23 20:20:10 sogod [1220]: 46.223.1.8 "POST /SOGo/Microsoft-Server-ActiveSync?User=XXXX&DeviceId=0T8D39M47T6658S7M9QNVUJRD4&DeviceType=iPhone&Cmd=Ping HTTP/1.0" 500 36/0 0.007 - - 0

I only update sogo.
I use Debian.
sogo:
Installed: 3.2.4.20161223-1
Candidate: 3.2.4.20161223-1

sogo-activesync:
Installed: 3.2.4.20161223-1
Candidate: 3.2.4.20161223-1

This is the important port of my nginx config

91 location ^~ /Microsoft-Server-ActiveSync {
92 proxy_pass http://127.0.0.1:20000/SOGo/Microsoft-Server-ActiveSync;
93 proxy_connect_timeout 400;
94 proxy_send_timeout 400;
95 proxy_read_timeout 400;
96 proxy_buffer_size 8k;
97 proxy_buffers 4 32k;
98 proxy_temp_file_write_size 64k;
99 proxy_busy_buffers_size 64k;
100 proxy_set_header X-Real-IP $remote_addr;
101 proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
102 proxy_set_header Host $host;
103 proxy_set_header x-webobjects-server-protocol HTTP/1.0;
104 proxy_set_header x-webobjects-server-name $server_name;
105 proxy_set_header x-webobjects-server-url $scheme://$host;
106 proxy_set_header x-webobjects-server-port $server_port;
107 proxy_set_header x-webobjects-remote-host $remote_addr;
108 client_body_buffer_size 128k;
109 }
110
111 location ^~/SOGo {
112 proxy_pass http://127.0.0.1:20000;
113 proxy_set_header X-Real-IP $remote_addr;
114 proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
115 proxy_set_header Host $host;
116 proxy_set_header x-webobjects-server-protocol HTTP/1.0;
117 proxy_set_header x-webobjects-server-name $server_name;
118 proxy_set_header x-webobjects-server-url $scheme://$host;
119 proxy_set_header x-webobjects-server-port $server_port;
120 proxy_set_header x-webobjects-remote-host $remote_addr;
121 proxy_connect_timeout 90;
122 proxy_send_timeout 90;
123 proxy_read_timeout 90;
124 proxy_buffer_size 4k;
125 proxy_buffers 4 32k;
126 proxy_busy_buffers_size 64k;
127 proxy_temp_file_write_size 64k;
128 client_body_buffer_size 128k;
129 break;
130 }

Maybe yout could help me.

TagsNo tags attached.

Relationships

Relationship GraphDependency Graph
has duplicate 0003971 resolvedludovic Stop working ActiveSync after last update 

Activities

ludovic

ludovic

2016-12-23 19:33

administrator   ~0011107

Produce a stack trace: https://sogo.nu/nc/support/faq/article/how-do-i-debug-sogo.html
beli3ver

beli3ver

2016-12-23 20:37

reporter   ~0011108

I tried

sogo@mail:~$ gdb --args /usr/sbin/sogod -WOUseWatchDog NO -WONoDetach YES -WOPort 20000 -WOWorkersCount 1 -WOLogFile - -WOPidFile /tmp/sogo.pid
GNU gdb (Debian 7.7.1+dfsg-5) 7.7.1
Copyright (C) 2014 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from /usr/sbin/sogod...(no debugging symbols found)...done.
(gdb) r
Starting program: /usr/sbin/sogod -WOUseWatchDog NO -WONoDetach YES -WOPort 20000 -WOWorkersCount 1 -WOLogFile - -WOPidFile /tmp/sogo.pid
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Dec 23 21:34:06 sogod [2322]: version 3.2.4 (build @shiva.inverse 201612230828) -- starting
Dec 23 21:34:06 sogod [2322]: vmem size check enabled: shutting down app when vmem > 384 MB
Dec 23 21:34:06 sogod [2322]: <0x0x555555ad1eb0[SOGoProductLoader]> SOGo products loaded from '/usr/lib/GNUstep/SOGo':
Dec 23 21:34:06 sogod [2322]: <0x0x555555ad1eb0[SOGoProductLoader]> PreferencesUI.SOGo, CommonUI.SOGo, Mailer.SOGo, ActiveSync.SOGo, ContactsUI.SOGo, MainUI.SOGo, Appointments.SOGo, AdministrationUI.SOGo, MailPartViewers.SOGo, MailerUI.SOGo, Contacts.SOGo, SchedulerUI.SOGo
[New Thread 0x7fffe85ee700 (LWP 2326)]
[Thread 0x7fffe85ee700 (LWP 2326) exited]
Dec 23 21:34:06 sogod [2322]: |SOGo| WOHttpAdaptor listening on address *:20000
^C
Program received signal SIGINT, Interrupt.
0x00007ffff453aaed in poll () at ../sysdeps/unix/syscall-template.S:81
81 ../sysdeps/unix/syscall-template.S: No such file or directory.
(gdb) b [NSException raise]
Function "[NSException raise]" not defined.
Make breakpoint pending on future shared library load? (y or [n]) y
Breakpoint 1 ([NSException raise]) pending.
(gdb) b abort
Breakpoint 2 at 0x7ffff4491300: file abort.c, line 51.
(gdb) c
Continuing.
Dec 23 21:35:16 sogod [2322]: <0x0x555555c3c330[SOGoCache]> Cache cleanup interval set every 300.000000 seconds
Dec 23 21:35:16 sogod [2322]: <0x0x555555c3c330[SOGoCache]> Using host(s) '127.0.0.1' as server(s)
Dec 23 21:35:16 sogod [2322]: 46.223.1.8 "POST /SOGo/Microsoft-Server-ActiveSync?User=malte.kiefer@mailgermania.de&DeviceId=0T8D39M47T6658S7M9QNVUJRD4&DeviceType=iPhone&Cmd=Ping HTTP/1.0" 500 36/0 0.022 - - 376K
Dec 23 21:35:16 sogod [2322]: 46.223.1.8 "POST /SOGo/Microsoft-Server-ActiveSync?User=malte.kiefer@mailgermania.de&DeviceId=0T8D39M47T6658S7M9QNVUJRD4&DeviceType=iPhone&Cmd=Ping HTTP/1.0" 500 36/0 0.003 - - 0
Dec 23 21:35:26 sogod [2322]: 46.223.1.8 "OPTIONS /SOGo/Microsoft-Server-ActiveSync HTTP/1.0" 200 0/0 0.033 - - 28K
Dec 23 21:35:27 sogod [2322]: <0x0x555555f41030[NGImap4Client]> Note: no key found for sorting, using 'DATE': (null)
Dec 23 21:35:27 sogod [2322]: <0x0x5555558f1170[SOGoActiveSyncDispatcher]> Change detected during Sync, we push the content.
Dec 23 21:35:27 sogod [2322]: 46.223.1.8 "POST /SOGo/Microsoft-Server-ActiveSync?User=malte.kiefer@kiefer-networks.de&DeviceId=0T8D39M47T6658S7M9QNVUJRD4&DeviceType=iPhone&Cmd=Sync HTTP/1.0" 200 472/99 0.790 - - 2M
Dec 23 21:35:28 sogod [2322]: <0x0x555555ad7470[SOGoActiveSyncDispatcher]> Change detected during Sync, we push the content.
Dec 23 21:35:28 sogod [2322]: 46.223.1.8 "POST /SOGo/Microsoft-Server-ActiveSync?User=malte.kiefer@kiefer-networks.de&DeviceId=0T8D39M47T6658S7M9QNVUJRD4&DeviceType=iPhone&Cmd=Sync HTTP/1.0" 200 3690/98 0.484 - - -16K
Dec 23 21:35:28 sogod [2322]: 46.223.1.8 "POST /SOGo/Microsoft-Server-ActiveSync?User=malte.kiefer@mailgermania.de&DeviceId=0T8D39M47T6658S7M9QNVUJRD4&DeviceType=iPhone&Cmd=Ping HTTP/1.0" 500 36/0 0.002 - - 0
Dec 23 21:35:28 sogod [2322]: 46.223.1.8 "POST /SOGo/Microsoft-Server-ActiveSync?User=malte.kiefer@mailgermania.de&DeviceId=0T8D39M47T6658S7M9QNVUJRD4&DeviceType=iPhone&Cmd=Ping HTTP/1.0" 500 36/0 0.002 - - 0
Dec 23 21:35:33 sogod [2322]: [WARN] <0x0x555555f5b780[SOGoWebDAVAclManager]> entry '{DAV:}write' already exists in DAV permissions table
Dec 23 21:35:33 sogod [2322]: [WARN] <0x0x555555f5b780[SOGoWebDAVAclManager]> entry '{DAV:}write-properties' already exists in DAV permissions table
Dec 23 21:35:33 sogod [2322]: [WARN] <0x0x555555f5b780[SOGoWebDAVAclManager]> entry '{DAV:}write-content' already exists in DAV permissions table
Dec 23 21:35:33 sogod [2322]: 46.223.1.8 "POST /SOGo/Microsoft-Server-ActiveSync?User=malte.kiefer@mailgermania.de&DeviceId=0T8D39M47T6658S7M9QNVUJRD4&DeviceType=iPhone&Cmd=FolderSync HTTP/1.0" 200 59/47 0.399 - - 4M
Dec 23 21:35:34 sogod [2322]: 46.223.1.8 "POST /SOGo/Microsoft-Server-ActiveSync?User=malte.kiefer@kiefer-networks.de&DeviceId=0T8D39M47T6658S7M9QNVUJRD4&DeviceType=iPhone&Cmd=FolderSync HTTP/1.0" 200 60/48 0.359 - - 0
Dec 23 21:35:35 sogod [2322]: 46.223.1.8 "POST /SOGo/Microsoft-Server-ActiveSync?User=malte.kiefer@mailgermania.de&DeviceId=0T8D39M47T6658S7M9QNVUJRD4&DeviceType=iPhone&Cmd=Ping HTTP/1.0" 500 36/0 0.001 - - 0
Dec 23 21:35:35 sogod [2322]: 46.223.1.8 "POST /SOGo/Microsoft-Server-ActiveSync?User=malte.kiefer@mailgermania.de&DeviceId=0T8D39M47T6658S7M9QNVUJRD4&DeviceType=iPhone&Cmd=Ping HTTP/1.0" 500 36/0 0.001 - - 0
Dec 23 21:35:37 sogod [2322]: <0x0x55555630cae0[NGImap4Client]> Note: no key found for sorting, using 'DATE': (null)
Dec 23 21:35:37 sogod [2322]: <0x0x555555f29890[SOGoActiveSyncDispatcher]> Change detected during Sync, we push the content.
Dec 23 21:35:37 sogod [2322]: 46.223.1.8 "POST /SOGo/Microsoft-Server-ActiveSync?User=malte.kiefer@kiefer-networks.de&DeviceId=0T8D39M47T6658S7M9QNVUJRD4&DeviceType=iPhone&Cmd=Sync HTTP/1.0" 200 78/99 0.640 - - 0
Dec 23 21:35:37 sogod [2322]: 46.223.1.8 "OPTIONS /SOGo/Microsoft-Server-ActiveSync HTTP/1.0" 200 0/0 0.019 - - 0
Dec 23 21:35:38 sogod [2322]: <0x0x555556306730[NGImap4Client]> Note: no key found for sorting, using 'DATE': (null)
Dec 23 21:35:38 sogod [2322]: <0x0x555555aa07a0[SOGoActiveSyncDispatcher]> Change detected during Sync, we push the content.
Dec 23 21:35:38 sogod [2322]: 46.223.1.8 "POST /SOGo/Microsoft-Server-ActiveSync?User=malte.kiefer@mailgermania.de&DeviceId=0T8D39M47T6658S7M9QNVUJRD4&DeviceType=iPhone&Cmd=Sync HTTP/1.0" 200 481/104 0.825 - - -16K
Dec 23 21:35:39 sogod [2322]: <0x0x555555aee8a0[SOGoActiveSyncDispatcher]> Change detected during Sync, we push the content.
Dec 23 21:35:39 sogod [2322]: 46.223.1.8 "POST /SOGo/Microsoft-Server-ActiveSync?User=malte.kiefer@mailgermania.de&DeviceId=0T8D39M47T6658S7M9QNVUJRD4&DeviceType=iPhone&Cmd=Sync HTTP/1.0" 200 3660/103 0.520 - - -16K
Dec 23 21:35:40 sogod [2322]: 46.223.1.8 "POST /SOGo/Microsoft-Server-ActiveSync?User=malte.kiefer@kiefer-networks.de&DeviceId=0T8D39M47T6658S7M9QNVUJRD4&DeviceType=iPhone&Cmd=Sync HTTP/1.0" 200 0/97 0.379 - - 0
Dec 23 21:35:41 sogod [2322]: 46.223.1.8 "POST /SOGo/Microsoft-Server-ActiveSync?User=malte.kiefer@kiefer-networks.de&DeviceId=0T8D39M47T6658S7M9QNVUJRD4&DeviceType=iPhone&Cmd=Sync HTTP/1.0" 200 0/99 0.394 - - 0
Dec 23 21:35:41 sogod [2322]: <0x0x555555f65880[NGImap4Client]> Note: no key found for sorting, using 'DATE': (null)
Dec 23 21:35:42 sogod [2322]: <0x0x555555f5b2c0[SOGoActiveSyncDispatcher]> Change detected during Sync, we push the content.
Dec 23 21:35:42 sogod [2322]: 46.223.1.8 "POST /SOGo/Microsoft-Server-ActiveSync?User=malte.kiefer@mailgermania.de&DeviceId=0T8D39M47T6658S7M9QNVUJRD4&DeviceType=iPhone&Cmd=Sync HTTP/1.0" 200 78/104 0.657 - - 0
Dec 23 21:35:42 sogod [2322]: 46.223.1.8 "POST /SOGo/Microsoft-Server-ActiveSync?User=malte.kiefer@mailgermania.de&DeviceId=0T8D39M47T6658S7M9QNVUJRD4&DeviceType=iPhone&Cmd=Ping HTTP/1.0" 500 36/0 0.002 - - 0
Dec 23 21:35:43 sogod [2322]: 46.223.1.8 "POST /SOGo/Microsoft-Server-ActiveSync?User=malte.kiefer@mailgermania.de&DeviceId=0T8D39M47T6658S7M9QNVUJRD4&DeviceType=iPhone&Cmd=Ping HTTP/1.0" 500 36/0 0.002 - - 0
Dec 23 21:35:45 sogod [2322]: 46.223.1.8 "POST /SOGo/Microsoft-Server-ActiveSync?User=malte.kiefer@kiefer-networks.de&DeviceId=0T8D39M47T6658S7M9QNVUJRD4&DeviceType=iPhone&Cmd=MoveItems HTTP/1.0" 200 29/103 0.501 - - 0
Dec 23 21:35:47 sogod [2322]: 46.223.1.8 "POST /SOGo/Microsoft-Server-ActiveSync?User=malte.kiefer@mailgermania.de&DeviceId=0T8D39M47T6658S7M9QNVUJRD4&DeviceType=iPhone&Cmd=MoveItems HTTP/1.0" 200 29/103 0.536 - - 0
^C
Program received signal SIGINT, Interrupt.
0x00007ffff453aaed in poll () at ../sysdeps/unix/syscall-template.S:81
81 in ../sysdeps/unix/syscall-template.S
(gdb) bt
#0 0x00007ffff453aaed in poll () at ../sysdeps/unix/syscall-template.S:81
0000001 0x00007ffff54d811e in ?? () from /usr/lib/libgnustep-base.so.1.24
0000002 0x00007ffff5416840 in ?? () from /usr/lib/libgnustep-base.so.1.24
0000003 0x00007ffff5416cf2 in ?? () from /usr/lib/libgnustep-base.so.1.24
0000004 0x00007ffff6bfd202 in ?? () from /usr/lib/libNGObjWeb.so.4.9
0000005 0x000055555555bbbe in ?? ()
0000006 0x00007ffff6c27289 in WOApplicationMain () from /usr/lib/libNGObjWeb.so.4.9
0000007 0x00007ffff6c47ba7 in WOWatchDogApplicationMain () from /usr/lib/libNGObjWeb.so.4.9
0000008 0x000055555555a9b9 in main ()
(gdb)
ludovic

ludovic

2016-12-23 20:49

administrator   ~0011109

Install all debugging symbols first - for SOPE, SOGo and GNUstep.
beli3ver

beli3ver

2016-12-23 21:13

reporter   ~0011111

here again

sogo@mail:~$ gdb --args /usr/sbin/sogod -WOUseWatchDog NO -WONoDetach YES -WOPort 20000 -WOWorkersCount 1 -WOLogFile - -WOPidFile /tmp/sogo.pid
GNU gdb (Debian 7.7.1+dfsg-5) 7.7.1
Copyright (C) 2014 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from /usr/sbin/sogod...Reading symbols from /usr/lib/debug//usr/sbin/sogod...done.
done.
(gdb) r
Starting program: /usr/sbin/sogod -WOUseWatchDog NO -WONoDetach YES -WOPort 20000 -WOWorkersCount 1 -WOLogFile - -WOPidFile /tmp/sogo.pid
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Dec 23 22:09:36 sogod [3588]: version 3.2.4 (build @shiva.inverse 201612230828) -- starting
Dec 23 22:09:36 sogod [3588]: vmem size check enabled: shutting down app when vmem > 384 MB
Dec 23 22:09:36 sogod [3588]: <0x0x555555ad1eb0[SOGoProductLoader]> SOGo products loaded from '/usr/lib/GNUstep/SOGo':
Dec 23 22:09:36 sogod [3588]: <0x0x555555ad1eb0[SOGoProductLoader]> PreferencesUI.SOGo, CommonUI.SOGo, Mailer.SOGo, ActiveSync.SOGo, ContactsUI.SOGo, MainUI.SOGo, Appointments.SOGo, AdministrationUI.SOGo, MailPartViewers.SOGo, MailerUI.SOGo, Contacts.SOGo, SchedulerUI.SOGo
[New Thread 0x7fffe85ee700 (LWP 3592)]
[Thread 0x7fffe85ee700 (LWP 3592) exited]
Dec 23 22:09:36 sogod [3588]: |SOGo| WOHttpAdaptor listening on address *:20000
^C
Program received signal SIGINT, Interrupt.
0x00007ffff453aaed in poll () at ../sysdeps/unix/syscall-template.S:81
81 ../sysdeps/unix/syscall-template.S: No such file or directory.
(gdb) b [NSException raise]
Breakpoint 1 at 0x7ffff538ab40: file NSException.m, line 960.
(gdb) b abort
Breakpoint 2 at 0x7ffff4491300: abort. (2 locations)
(gdb) c
Continuing.
Dec 23 22:12:26 sogod [3588]: <0x0x555555c513b0[SOGoCache]> Cache cleanup interval set every 300.000000 seconds
Dec 23 22:12:26 sogod [3588]: <0x0x555555c513b0[SOGoCache]> Using host(s) '127.0.0.1' as server(s)
Dec 23 22:12:26 sogod [3588]: 46.223.1.8 "POST /SOGo/Microsoft-Server-ActiveSync?User=malte.kiefer@mailgermania.de&DeviceId=0T8D39M47T6658S7M9QNVUJRD4&DeviceType=iPhone&Cmd=Ping HTTP/1.0" 500 36/0 0.011 - - 404K
Dec 23 22:12:26 sogod [3588]: 46.223.1.8 "POST /SOGo/Microsoft-Server-ActiveSync?User=malte.kiefer@mailgermania.de&DeviceId=0T8D39M47T6658S7M9QNVUJRD4&DeviceType=iPhone&Cmd=Ping HTTP/1.0" 500 36/0 0.002 - - 0
Dec 23 22:12:32 sogod [3588]: 46.223.1.8 "POST /SOGo/Microsoft-Server-ActiveSync?User=malte.kiefer@mailgermania.de&DeviceId=0T8D39M47T6658S7M9QNVUJRD4&DeviceType=iPhone&Cmd=Ping HTTP/1.0" 500 36/0 0.002 - - 0
Dec 23 22:12:33 sogod [3588]: 46.223.1.8 "POST /SOGo/Microsoft-Server-ActiveSync?User=malte.kiefer@mailgermania.de&DeviceId=0T8D39M47T6658S7M9QNVUJRD4&DeviceType=iPhone&Cmd=Ping HTTP/1.0" 500 36/0 0.002 - - 0
^C
Program received signal SIGINT, Interrupt.
0x00007ffff453aaed in poll () at ../sysdeps/unix/syscall-template.S:81
81 in ../sysdeps/unix/syscall-template.S
(gdb) bt
#0 0x00007ffff453aaed in poll () at ../sysdeps/unix/syscall-template.S:81
0000001 0x00007ffff54d811e in poll (timeout=29970, nfds=<optimized out>, __fds=<optimized out>) at /usr/include/x86_64-linux-gnu/bits/poll2.h:46
0000002 -[GSRunLoopCtxt pollUntil:within:] (self=<optimized out>, _cmd=0x7ffff58bd900 <_OBJC_SELECTOR_TABLE+1216>, milliseconds=29970, contexts=<optimized out>)
at GSRunLoopCtxt.m:430
0000003 0x00007ffff5416840 in -[NSRunLoop acceptInputForMode:beforeDate:] (self=0x555555bdd6d0, _cmd=0x2, mode=0x7ffff58be770 <_OBJC_INSTANCE_2>, limit_date=0x555555bb5fb0)
at NSRunLoop.m:1217
0000004 0x00007ffff5416cf2 in -[NSRunLoop runMode:beforeDate:] (self=0x555555bdd6d0, _cmd=0x555555b85a90, mode=0x7ffff58be770 <_OBJC_INSTANCE_2>, date=0x555555af5400)
at NSRunLoop.m:1288
0000005 0x00007ffff6bfd202 in -[WOCoreApplication run] (self=0x55555596d8b0, _cmd=0x555555763b20 <_OBJC_SELECTOR_TABLE+928>) at WOCoreApplication.m:584
0000006 0x000055555555bbbe in -[SOGo run] (self=0x55555596d8b0, _cmd=0x7ffff6f600d0 <_OBJC_SELECTOR_TABLE+208>) at SOGo.m:327
0000007 0x00007ffff6c27289 in WOApplicationMain (_appClassName=0x555555761ac0 <_OBJC_INSTANCE_0>, argc=13, argv=0x7fffffffec28) at WOApplicationMain.m:42
0000008 0x00007ffff6c47ba7 in WOWatchDogApplicationMain (appName=0x555555761ac0 <_OBJC_INSTANCE_0>, argc=13, argv=0x7fffffffec28) at WOWatchDogApplicationMain.m:1049
0000009 0x000055555555a9b9 in main (argc=13, argv=0x7fffffffec28, env=0x7fffffffec98) at sogod.m:51
(gdb) quit
A debugging session is active.

Inferior 1 [process 3588] will be killed.

Quit anyway? (y or n) y
anymemm

anymemm

2016-12-26 16:34

reporter   ~0011113

Dear all,

I am experiencing the same issue and I am trying to figure out why this is happening. First of all I'd like to mention that I've installed SOGo via the Mailcow installation script 0.14 offered by the Mailcow project [1] by André Peters. My SOGo instance is running on Debian Jessie, too, and currently version 3.2.4.20161221-1 from the Inverse nightly repository is installed.

I've enabled some debugging options in /etc/sogo/sogo.conf...

--- cut ---
/ Debug /
SOGoDebugRequests = YES;
SoDebugBaseURL = YES;
//ImapDebugEnabled = YES;
//LDAPDebugEnabled = YES;
//PGDebugEnabled = YES;
MySQL4DebugEnabled = YES;
//SOGoUIxDebugEnabled = YES;
WODontZipResponse = YES;
//WOLogFile = /var/log/sogo/sogo.log;
--- cut ---

...and I've also set some ActiveSync values according to the Microsoft Enterprise ActiveSync Tuning chapter from the SOGo manual:

--- cut ---
/ ActiveSync /
WOWorkersCount = 15;
WOWatchDogRequestTimeout = 3600;
SOGoMaximumPingInterval = 3540;
SOGoMaximumSyncInterval = 3540;
SOGoInternalSyncInterval = 30;
SOGoEASDebugEnabled = NO;
--- cut ---

I've hopefully properly customized the relevant portion of the nginx configuration according to the above settings:

--- cut ---
location ^~ /Microsoft-Server-ActiveSync {
proxy_pass http://127.0.0.1:20000/SOGo/Microsoft-Server-ActiveSync;
proxy_connect_timeout 90;
proxy_send_timeout 3600;
proxy_read_timeout 3600;
proxy_buffer_size 8k;
proxy_buffers 4 32k;
proxy_temp_file_write_size 64k;
proxy_busy_buffers_size 64k;
proxy_set_header X-Real-IP $remote_addr;
proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
proxy_set_header Host $host;
proxy_set_header x-webobjects-server-protocol HTTP/1.0;
proxy_set_header x-webobjects-server-name $server_name;
proxy_set_header x-webobjects-server-url $scheme://$host;
proxy_set_header x-webobjects-server-port $server_port;
proxy_set_header x-webobjects-remote-host $remote_addr;
client_body_buffer_size 128k;
}
--- cut ---

Now, when my mobile device issues a ping request the following is being logged to /var/log/sogo/sogo.log (some data replaced with generic values):

--- cut ---
Dec 26 17:09:47 sogod [18202]: |SOGo| starting method 'POST' on uri '/SOGo/Microsoft-Server-ActiveSync?Cmd=Ping&User=user%40domain.tld&DeviceId=SEC1234567899000&DeviceType=SAMSUNGGTI9195'
Dec 26 17:09:47 sogod [18202]: |SOGo| request took 0.001231 seconds to execute
Dec 26 17:09:47 sogod [18202]: 10.10.10.55 "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=Ping&User=user%40domain.tld&DeviceId=SEC1234567899000&DeviceType=SAMSUNGGTI9195 HTTP/1.0" 500 36/0 0.002 - - 0
--- cut ---

And this is what I'm seeing with tcpdump for the above request:

--- cut ---
17:09:47.399628 IP localhost.58389 > localhost.20000: Flags [P.], seq 1:585, ack 1, win 342, options [nop,nop,TS val 166406692 ecr 166406692], length 584
E..|.)@.@.&Q..........N ..>....k...V.q.....
.$ .$POST /SOGo/Microsoft-Server-ActiveSync?Cmd=Ping&User=user%40domain.tld&DeviceId=SEC1234567899000&DeviceType=SAMSUNGGTI9195 HTTP/1.0
X-Real-IP: 10.10.10.55
X-Forwarded-For: 10.10.10.55
Host: mail.domain.tld
x-webobjects-server-protocol: HTTP/1.0
x-webobjects-server-name: mail.domain.tld
x-webobjects-server-url: https://mail.domain.tld
x-webobjects-server-port: 443
x-webobjects-remote-host: 10.10.10.55
Connection: close
Content-Length: 0
Authorization: Basic sgfSDFGrtRGDFgsdfGSdfGdsfgsdgDgstertrterte==
MS-ASProtocolVersion: 14.1
User-Agent: SAMSUNG-GT-I9195/101.40402

17:09:47.399631 IP localhost.20000 > localhost.58389: Flags [.], ack 585, win 351, options [nop,nop,TS val 166406692 ecr 166406692], length 0
E..4.O@.@..r........N .....k..@L....(.....
.$ .$
17:09:47.401990 IP localhost.20000 > localhost.58389: Flags [P.], seq 1:30, ack 585, win 351, options [nop,nop,TS val 166406692 ecr 166406692], length 29
E..Q.P@.@..T........N .....k..@L....E.....
.$ .$HTTP/1.1 500 Request Failed

17:09:47.401994 IP localhost.58389 > localhost.20000: Flags [.], ack 30, win 342, options [nop,nop,TS val 166406692 ecr 166406692], length 0
E..4.@.@.(...........N ..@L.......V.(.....
.$ .$
17:09:47.402055 IP localhost.20000 > localhost.58389: Flags [P.], seq 30:83, ack 585, win 351, options [nop,nop,TS val 166406692 ecr 166406692], length 53
E..i.Q@.@..;........N ........@L..._.].....
.$ .*$Content-Length: 36
Sogo-Request-Duration: 0.001231

17:09:47.402058 IP localhost.58389 > localhost.20000: Flags [.], ack 83, win 342, options [nop,nop,TS val 166406692 ecr 166406692], length 0
E..4.+@.@.(...........N ..@L.......V.(.....
.$ .$
17:09:47.402080 IP localhost.20000 > localhost.58389: Flags [P.], seq 83:85, ack 585, win 351, options [nop,nop,TS val 166406692 ecr 166406692], length 2
E..6.R@.@..m........N ........@L..._......
.$ .*$

17:09:47.402082 IP localhost.58389 > localhost.20000: Flags [.], ack 85, win 342, options [nop,nop,TS val 166406692 ecr 166406692], length 0
E..4.,@.@.(...........N ..@L.......V.(.....
.$ .$
17:09:47.402111 IP localhost.20000 > localhost.58389: Flags [P.], seq 85:121, ack 585, win 351, options [nop,nop,TS val 166406692 ecr 166406692], length 36
E..X.S@.@..J........N ........@L....L.....
.$ .$the called object returned no result
17:09:47.402113 IP localhost.58389 > localhost.20000: Flags [.], ack 121, win 342, options [nop,nop,TS val 166406692 ecr 166406692], length 0
E..4.-@.@.(...........N ..@L.......V.(.....
.$ .$
17:09:47.402133 IP localhost.58389 > localhost.20000: Flags [F.], seq 585, ack 121, win 342, options [nop,nop,TS val 166406692 ecr 166406692], length 0
E..4..@.@.(...........N ..@L.......V.(.....
.$ .$
17:09:47.402225 IP localhost.20000 > localhost.58389: Flags [F.], seq 121, ack 586, win 351, options [nop,nop,TS val 166406692 ecr 166406692], length 0
E..4.T@.@..m........N ........@M....(.....
.$ .$
17:09:47.402229 IP localhost.58389 > localhost.20000: Flags [.], ack 122, win 342, options [nop,nop,TS val 166406692 ecr 166406692], length 0
E..4./@.@.(...........N ..@M.......V.(.....
.$ .$
--- cut ---

I don't know if this is relevant, but I've also seen the following some time earlier and I'm wondering if this somewhat "strange" SQL query being executed has someting to do with the issue:

--- cut ---
Dec 26 16:46:22 sogod [18202]: |SOGo| starting method 'POST' on uri '/SOGo/Microsoft-Server-ActiveSync?Cmd=Ping&User=user%40domain.tld&DeviceId=SEC1234567899000&DeviceType=SAMSUNGGTI9195'
2016-12-26 16:46:22.588 sogod[18202] <MySQL4Channel[0x0x7f4b720f5630] connection=0x0x7f4b72069070> SQL: SELECT * FROM sogo_view WHERE (c_uid = 'Ping') OR (mail = 'ping') OR (aliases = 'ping') OR (senderacl = 'ping');
2016-12-26 16:46:22.588 sogod[18202] <MySQL4Channel[0x0x7f4b720f5630] connection=0x0x7f4b72069070> query has results, entering fetch-mode.
Dec 26 16:46:22 sogod [18202]: |SOGo| request took 0.001726 seconds to execute
Dec 26 16:46:22 sogod [18202]: 10.10.10.55 "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=Ping&User=user%40domain.tld&DeviceId=SEC1234567899000&DeviceType=SAMSUNGGTI9195 HTTP/1.0" 500 36/0 0.003 - - 0
--- cut ---

Please notice that my device is set to use PUSH notification and is being synchronized with the server, but with some delay of max. 5 minutes. I might imagine that this is due to the failing ping requests described above.

I hope all of this helps to remedy the issue.

Regards and merry Xmas,

Anymemm

[1] https://mailcow.email
tfu

tfu

2016-12-29 11:07

reporter   ~0011122

Set SOGoEASDebugEnabled = YES upload your sogo.log with a few failed ping requests.
ludovic

ludovic

2016-12-29 13:05

administrator   ~0011124

That is because of this change:

https://github.com/inverse-inc/sope/commit/7b20f29a618ea380de9404278b0fc7c6a13fe51b

The iOS sends an empty POST request - we'll fix this.
ludovic

ludovic

2016-12-29 14:57

administrator   ~0011125

Additional fix in SOPE: https://github.com/inverse-inc/sope/commit/4deea9073f1e576b6c9e8dfff045af014f4a4caa

Related Changesets

sogo: master 5bc21e4f

2016-12-29 09:55

ludovic


Details Diff		 (fix) avoid trying to parse empty request (fixes 0003969) Affected Issues
0003969
mod - ActiveSync/SOGoActiveSyncDispatcher.m Diff File

sogo: v2 366681e6

2016-12-29 09:55

ludovic


Details Diff		 (fix) avoid trying to parse empty request (fixes 0003969) Affected Issues
0003969
mod - ActiveSync/SOGoActiveSyncDispatcher.m Diff File

sogo: maint 4c979e3f

2016-12-29 09:55

ludovic

Committer: francis


Details Diff		 (fix) avoid trying to parse empty request (fixes 0003969) Affected Issues
0003969
mod - ActiveSync/SOGoActiveSyncDispatcher.m Diff File

Issue History

Date Modified Username Field Change
2016-12-23 19:26 beli3ver New Issue
2016-12-23 19:33 ludovic Note Added: 0011107
2016-12-23 20:37 beli3ver Note Added: 0011108
2016-12-23 20:49 ludovic Note Added: 0011109
2016-12-23 21:13 beli3ver Note Added: 0011111
2016-12-26 16:34 anymemm Note Added: 0011113
2016-12-29 11:07 tfu Note Added: 0011122
2016-12-29 13:04 ludovic Relationship added has duplicate 0003971
2016-12-29 13:05 ludovic Note Added: 0011124
2016-12-29 14:56 ludovic Changeset attached => sogo master 5bc21e4f
2016-12-29 14:56 ludovic Assigned To => ludovic
2016-12-29 14:56 ludovic Resolution open => fixed
2016-12-29 14:56 ludovic Changeset attached => sogo v2 366681e6
2016-12-29 14:57 ludovic Note Added: 0011125
2016-12-29 14:57 ludovic Status new => resolved
2016-12-29 14:57 ludovic Fixed in Version => 3.2.5
2017-01-09 20:49 francis Changeset attached => sogo maint 4c979e3f