0006088: WOWatchDogChild pid has been hanging - SOGo

ID	Project	Category	View Status	Date Submitted	Last Update

0006088	SOGo	ActiveSync	public	2025-02-10 08:32	2025-02-11 18:34

Reporter	madpatrick	Assigned To	qhivert
Priority	normal	Severity	minor	Reproducibility	unable to reproduce
Status	assigned	Resolution	open
Platform	Docker	OS	Debian	OS Version	12
Product Version	5.11.2

Summary	0006088: WOWatchDogChild pid has been hanging
Description	Hi, I see a lot of warnings in the log What could be the problem and how to resolve? (if it is an problem of course) I'm noticing often a delay in receiving new mails on the devices that are connected with active sync. 2025-02-07T19:01:07+01:00 [1:sogo1:sogo-app] Feb 07 19:01:07 sogod [7]: [WARN] <0x0x5583ee1a02a0[WOWatchDogChild]> pid 117 has been hanging in the same request for 1 minutes 2025-02-07T19:01:23+01:00 [1:sogo1:sogo-app] Feb 07 19:01:23 sogod [7]: [WARN] <0x0x5583ee1a12d0[WOWatchDogChild]> pid 116 has been hanging in the same request for 3 minutes 2025-02-07T19:01:43+01:00 [1:sogo1:sogo-app] Feb 07 19:01:43 sogod [7]: [WARN] <0x0x5583ee19fe00[WOWatchDogChild]> pid 119 has been hanging in the same request for 2 minutes 2025-02-07T19:01:57+01:00 [1:sogo1:sogo-app] Feb 07 19:01:57 sogod [7]: [WARN] <0x0x5583ee1b3150[WOWatchDogChild]> pid 115 has been hanging in the same request for 6 minutes 2025-02-07T19:02:00+01:00 [1:sogo1:sogo-app] Feb 07 19:02:00 sogod [7]: [WARN] <0x0x5583ee19f670[WOWatchDogChild]> pid 114 has been hanging in the same request for 5 minutes 2025-02-07T19:02:05+01:00 [1:sogo1:sogo-app] Feb 07 19:02:05 sogod [7]: [WARN] <0x0x5583ee15d200[WOWatchDogChild]> pid 104 has been hanging in the same request for 1 minutes 2025-02-07T19:02:07+01:00 [1:sogo1:sogo-app] Feb 07 19:02:07 sogod [7]: [WARN] <0x0x5583ee1a02a0[WOWatchDogChild]> pid 117 has been hanging in the same request for 2 minutes 2025-02-07T19:02:57+01:00 [1:sogo1:sogo-app] Feb 07 19:02:57 sogod [7]: [WARN] <0x0x5583ee1b3150[WOWatchDogChild]> pid 115 has been hanging in the same request for 7 minutes 2025-02-07T19:03:05+01:00 [1:sogo1:sogo-app] Feb 07 19:03:05 sogod [7]: [WARN] <0x0x5583ee15d200[WOWatchDogChild]> pid 104 has been hanging in the same request for 2 minutes 2025-02-07T19:03:07+01:00 [1:sogo1:sogo-app] Feb 07 19:03:07 sogod [7]: [WARN] <0x0x5583ee1a02a0[WOWatchDogChild]> pid 117 has been hanging in the same request for 3 minutes 2025-02-07T19:04:05+01:00 [1:sogo1:sogo-app] Feb 07 19:04:05 sogod [7]: [WARN] <0x0x5583ee15d200[WOWatchDogChild]> pid 104 has been hanging in the same request for 3 minutes 2025-02-07T19:04:07+01:00 [1:sogo1:sogo-app] Feb 07 19:04:07 sogod [7]: [WARN] <0x0x5583ee1a02a0[WOWatchDogChild]> pid 117 has been hanging in the same request for 4 minutes 2025-02-07T19:04:26+01:00 [1:sogo1:sogo-app] Feb 07 19:04:26 sogod [7]: [WARN] <0x0x5583ee19fe00[WOWatchDogChild]> pid 119 has been hanging in the same request for 1 minutes 2025-02-07T19:04:44+01:00 [1:sogo1:sogo-app] Feb 07 19:04:44 sogod [7]: [WARN] <0x0x5583ee1a12d0[WOWatchDogChild]> pid 116 has been hanging in the same request for 1 minutes 2025-02-07T19:05:05+01:00 [1:sogo1:sogo-app] Feb 07 19:05:05 sogod [7]: [WARN] <0x0x5583ee15d200[WOWatchDogChild]> pid 104 has been hanging in the same request for 4 minutes 2025-02-07T19:05:06+01:00 [1:sogo1:sogo-app] Feb 07 19:05:06 sogod [7]: [WARN] <0x0x5583ee19f670[WOWatchDogChild]> pid 114 has been hanging in the same request for 1 minutes 2025-02-07T19:05:26+01:00 [1:sogo1:sogo-app] Feb 07 19:05:26 sogod [7]: [WARN] <0x0x5583ee19fe00[WOWatchDogChild]> pid 119 has been hanging in the same request for 2 minutes 2025-02-07T19:05:44+01:00 [1:sogo1:sogo-app] Feb 07 19:05:44 sogod [7]: [WARN] <0x0x5583ee1b3150[WOWatchDogChild]> pid 115 has been hanging in the same request for 1 minutes Patrick
Tags	WOWatchDogChild ;pid

qhivert 2025-02-10 13:13 administrator ~0018062	Hello, Add this to your sogo.conf and restart sogo SOGoDebugRequests = YES; It will show the requests received like this Feb 10 10:22:12 sogod [100]: \|SOGo\| starting method 'POST' on uri '/SOGo/so/sogo-tests1@example.org/Mail/0/folderINBOX/view' The number between the brackets is the pid of the process. So you match the pid in the hanging log and the last request made on this pid.

madpatrick 2025-02-10 13:36 reporter ~0018065	Hi, I hope this is the information you need 2025-02-10T14:33:22+01:00 [1:sogo1:sogo-app] Feb 10 14:33:22 sogod [117]: <0x0x55a5e95ccd30[SOGoCache]> Cache cleanup interval set every 300.000000 seconds 2025-02-10T14:33:22+01:00 [1:sogo1:sogo-app] Feb 10 14:33:22 sogod [117]: <0x0x55a5e95ccd30[SOGoCache]> Using host(s) '127.0.0.1' as server(s) 2025-02-10T14:33:22+01:00 [1:sogo1:sogo-app] Feb 10 14:33:22 sogod [117]: [WARN] <0x0x7f3d05353ae0[WOxElemBuilder]> could not locate builders: WOxExtElemBuilder,WOxExtElemBuilder 2025-02-10T14:33:22+01:00 [1:sogo1:sogo1] 0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0 0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0 0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0 2025-02-10T14:33:22+01:00 [1:sogo1:sogo-app] Feb 10 14:33:22 sogod [117]: 127.0.0.1 "GET /SOGo HTTP/1.1" 302 0/0 0.054 - - 3M - 11 2025-02-10T14:33:25+01:00 [1:sogo1:sogo-app] 2025-02-10 13:33:25,595 INFO success: apache entered RUNNING state, process has stayed up for > than 5 seconds (startsecs) 2025-02-10T14:33:25+01:00 [1:sogo1:sogo-app] 2025-02-10 13:33:25,595 INFO success: cronie entered RUNNING state, process has stayed up for > than 5 seconds (startsecs) 2025-02-10T14:33:30+01:00 [1:sogo1:sogo-app] 2025-02-10 13:33:30,602 INFO success: memcached entered RUNNING state, process has stayed up for > than 10 seconds (startsecs) 2025-02-10T14:33:48+01:00 [1:sogo1:sogo-app] Feb 10 14:33:48 sogod [117]: 89.20.164.146, 192.168.1.1, 10.0.2.100 "POST /SOGo/Microsoft-Server-ActiveSync?User=patrick&DeviceId=L3KCTHG4TP0HB83FH7P93MPBNC&DeviceType=iPhone&Cmd=Sync HTTP/1.1" 200 0/107 0.325 - - 11M - 13 2025-02-10T14:33:50+01:00 [1:sogo1:sogo-app] Feb 10 14:33:50 sogod [117]: <0x0x55a5e9f8c4f0[SOGoWebDAVAclManager]> entry '{DAV:}write' already exists in DAV permissions table 2025-02-10T14:33:50+01:00 [1:sogo1:sogo-app] Feb 10 14:33:50 sogod [117]: <0x0x55a5e9f8c4f0[SOGoWebDAVAclManager]> entry '{DAV:}write-properties' already exists in DAV permissions table 2025-02-10T14:33:50+01:00 [1:sogo1:sogo-app] Feb 10 14:33:50 sogod [117]: <0x0x55a5e9f8c4f0[SOGoWebDAVAclManager]> entry '{DAV:}write-content' already exists in DAV permissions table 2025-02-10T14:33:50+01:00 [1:sogo1:sogo-app] Feb 10 14:33:50 sogod [117]: <0x0x55a5e98497b0[SOGoActiveSyncDispatcher]> Sleeping 30 seconds while detecting changes for user patrick in Ping... 2025-02-10T14:33:51+01:00 [1:sogo1:sogo-app] 2025-02-10 13:33:51,446 INFO success: sogod entered RUNNING state, process has stayed up for > than 30 seconds (startsecs) 2025-02-10T14:33:53+01:00 [1:sogo1:sogo-app] Feb 10 14:33:53 sogod [119]: <0x0x55a5e94bfd40[SOGoCache]> Cache cleanup interval set every 300.000000 seconds 2025-02-10T14:33:53+01:00 [1:sogo1:sogo-app] Feb 10 14:33:53 sogod [119]: <0x0x55a5e94bfd40[SOGoCache]> Using host(s) '127.0.0.1' as server(s) 2025-02-10T14:33:53+01:00 [1:sogo1:sogo-app] Feb 10 14:33:53 sogod [119]: 89.20.164.146, 192.168.1.1, 10.0.2.100 "POST /SOGo/Microsoft-Server-ActiveSync?User=patrick&DeviceId=L3KCTHG4TP0HB83FH7P93MPBNC&DeviceType=iPhone&Cmd=Sync HTTP/1.1" 200 0/106 0.132 - - 9M - 12 2025-02-10T14:33:53+01:00 [1:sogo1:sogo-app] Feb 10 14:33:53 sogod [119]: 89.20.164.146, 192.168.1.1, 10.0.2.100 "POST /SOGo/Microsoft-Server-ActiveSync?User=patrick&DeviceId=L3KCTHG4TP0HB83FH7P93MPBNC&DeviceType=iPhone&Cmd=Sync HTTP/1.1" 200 0/107 0.155 - - 2M - 12 2025-02-10T14:33:54+01:00 [1:sogo1:sogo-app] Feb 10 14:33:54 sogod [119]: 89.20.164.146, 192.168.1.1, 10.0.2.100 "POST /SOGo/Microsoft-Server-ActiveSync?User=patrick&DeviceId=L3KCTHG4TP0HB83FH7P93MPBNC&DeviceType=iPhone&Cmd=Sync HTTP/1.1" 200 0/105 0.112 - - 0 - 12 2025-02-10T14:33:55+01:00 [1:sogo1:sogo-app] Feb 10 14:33:55 sogod [119]: <0x0x55a5e9ec4650[SOGoWebDAVAclManager]> entry '{DAV:}write' already exists in DAV permissions table 2025-02-10T14:33:55+01:00 [1:sogo1:sogo-app] Feb 10 14:33:55 sogod [119]: <0x0x55a5e9ec4650[SOGoWebDAVAclManager]> entry '{DAV:}write-properties' already exists in DAV permissions table 2025-02-10T14:33:55+01:00 [1:sogo1:sogo-app] Feb 10 14:33:55 sogod [119]: <0x0x55a5e9ec4650[SOGoWebDAVAclManager]> entry '{DAV:}write-content' already exists in DAV permissions table 2025-02-10T14:33:55+01:00 [1:sogo1:sogo-app] Feb 10 14:33:55 sogod [119]: <0x0x55a5e97ed1f0[SOGoActiveSyncDispatcher]> Sleeping 30 seconds while detecting changes for user patrick in Ping... 2025-02-10T14:34:20+01:00 [1:sogo1:sogo-app] Feb 10 14:34:20 sogod [117]: 89.20.164.146, 192.168.1.1, 10.0.2.100 "POST /SOGo/Microsoft-Server-ActiveSync?User=patrick&DeviceId=L3KCTHG4TP0HB83FH7P93MPBNC&DeviceType=iPhone&Cmd=Ping HTTP/1.1" 200 13/0 30.228 - - 1M - 12 2025-02-10T14:34:25+01:00 [1:sogo1:sogo-app] Feb 10 14:34:25 sogod [119]: <0x0x55a5e97ed1f0[SOGoActiveSyncDispatcher]> Sleeping 30 seconds while detecting changes for user patrick in Ping... 2025-02-10T14:34:36+01:00 [1:sogo1:sogo-app] Feb 10 14:34:36 sogod [117]: <0x0x55a5e9aa63b0[SOGoActiveSyncDispatcher]> Sleeping 30 seconds while detecting changes for user thomas in Ping... 2025-02-10T14:34:55+01:00 [1:sogo1:sogo-app] Feb 10 14:34:55 sogod [7]: [WARN] <0x0x55a5e96f8950[WOWatchDogChild]> pid 119 has been hanging in the same request for 1 minutes 2025-02-10T14:34:55+01:00 [1:sogo1:sogo-app] Feb 10 14:34:55 sogod [119]: <0x0x55a5e97ed1f0[SOGoActiveSyncDispatcher]> Sleeping 30 seconds while detecting changes for user patrick in Ping... 2025-02-10T14:35:06+01:00 [1:sogo1:sogo-app] Feb 10 14:35:06 sogod [117]: <0x0x55a5e9aa63b0[SOGoActiveSyncDispatcher]> Sleeping 30 seconds while detecting changes for user thomas in Ping... 2025-02-10T14:35:25+01:00 [1:sogo1:sogo-app] Feb 10 14:35:25 sogod [119]: <0x0x55a5e97ed1f0[SOGoActiveSyncDispatcher]> Sleeping 30 seconds while detecting changes for user patrick in Ping... 2025-02-10T14:35:36+01:00 [1:sogo1:sogo-app] Feb 10 14:35:36 sogod [7]: [WARN] <0x0x55a5e96f9070[WOWatchDogChild]> pid 117 has been hanging in the same request for 1 minutes 2025-02-10T14:35:36+01:00 [1:sogo1:sogo-app] Feb 10 14:35:36 sogod [117]: <0x0x55a5e9aa63b0[SOGoActiveSyncDispatcher]> Sleeping 30 seconds while detecting changes for user thomas in Ping... 2025-02-10T14:35:39+01:00 [1:sogo1:sogo-app] Feb 10 14:35:39 sogod [120]: <0x0x55a5e94bfd80[SOGoCache]> Cache cleanup interval set every 300.000000 seconds 2025-02-10T14:35:39+01:00 [1:sogo1:sogo-app] Feb 10 14:35:39 sogod [120]: <0x0x55a5e94bfd80[SOGoCache]> Using host(s) '127.0.0.1' as server(s) 2025-02-10T14:35:40+01:00 [1:sogo1:sogo-app] Feb 10 14:35:40 sogod [120]: <0x0x55a5e9b2fa80[SOGoWebDAVAclManager]> entry '{DAV:}write' already exists in DAV permissions table 2025-02-10T14:35:40+01:00 [1:sogo1:sogo-app] Feb 10 14:35:40 sogod [120]: <0x0x55a5e9b2fa80[SOGoWebDAVAclManager]> entry '{DAV:}write-properties' already exists in DAV permissions table 2025-02-10T14:35:40+01:00 [1:sogo1:sogo-app] Feb 10 14:35:40 sogod [120]: <0x0x55a5e9b2fa80[SOGoWebDAVAclManager]> entry '{DAV:}write-content' already exists in DAV permissions table 2025-02-10T14:35:40+01:00 [1:sogo1:sogo-app] Feb 10 14:35:40 sogod [120]: <0x0x55a5e9525d00[SOGoActiveSyncDispatcher]> Sleeping 30 seconds while detecting changes for user jordy in Ping... 2025-02-10T14:35:55+01:00 [1:sogo1:sogo-app] Feb 10 14:35:55 sogod [7]: [WARN] <0x0x55a5e96f8950[WOWatchDogChild]> pid 119 has been hanging in the same request for 2 minutes 2025-02-10T14:35:55+01:00 [1:sogo1:sogo-app] Feb 10 14:35:55 sogod [119]: <0x0x55a5e97ed1f0[SOGoActiveSyncDispatcher]> Sleeping 30 seconds while detecting changes for user patrick in Ping... 2025-02-10T14:36:06+01:00 [1:sogo1:sogo-app] Feb 10 14:36:06 sogod [117]: <0x0x55a5e9aa63b0[SOGoActiveSyncDispatcher]> Sleeping 30 seconds while detecting changes for user thomas in Ping... 2025-02-10T14:36:10+01:00 [1:sogo1:sogo-app] Feb 10 14:36:10 sogod [120]: <0x0x55a5e9525d00[SOGoActiveSyncDispatcher]> Sleeping 30 seconds while detecting changes for user jordy in Ping...

madpatrick 2025-02-10 13:42 reporter ~0018066	And i also see this .... 2025-02-10T14:41:40+01:00 [1:sogo1:sogo-app] [Mon Feb 10 13:41:40.026072 2025] [proxy_http:error] [pid 17:tid 41] (70007)The timeout specified has expired: [client 10.0.2.100:33996] AH01102: error reading status line from remote server 127.0.0.1:20000 2025-02-10T14:41:40+01:00 [1:sogo1:sogo-app] [Mon Feb 10 13:41:40.026167 2025] [proxy:error] [pid 17:tid 41] [client 10.0.2.100:33996] AH00898: Error reading from remote server returned by /Microsoft-Server-ActiveSync ....

qhivert 2025-02-10 13:53 administrator ~0018067	Ok, you use ActiveSync so this is perfectly normal. You can find the doc here -> https://www.sogo.nu/files/docs/SOGoInstallationGuide.html#_microsoft_enterprise_activesync With ActiveSync, the device (outlook or a phone) will open a connection with sogo opened for a long time, asking to be notigied if a change is detected. This connection will keep a worker/child busy. You can also read a thread there to know more -> https://www.mail-archive.com/users@sogo.nu/msg20479.html

madpatrick 2025-02-10 14:00 reporter ~0018068	Ok. Thank you for the info. So basically it is normal that an email is not delivered at the device immediately ? Sometime it takes more then an hour or i need to manually refresh.

qhivert 2025-02-10 14:17 administrator ~0018069	No, from your log new changed should be pushed every 30s. You could try adding SOGoEASDebugEnabled = YES; You should see logs like this `Change detected during Sync, we push the content.` Beware that the configuration of your device can also change the timing. Which one is it?

madpatrick 2025-02-10 14:31 reporter ~0018070	Ok. I'll test The devices are alle Apple (iPhone or iPad) Not sure about Outlook

madpatrick 2025-02-10 14:51 reporter ~0018071	Look ok. But it that is not always the case. I'll do some more testing the coming days 2025-02-10T15:17:33+01:00 [1:sogo1:sogo-app] Feb 10 15:17:33 sogod [7]: [WARN] <0x0x5638c878c120[WOWatchDogChild]> pid 111 has been hanging in the same request for 2 minutes 2025-02-10T15:17:33+01:00 [1:sogo1:sogo-app] Feb 10 15:17:33 sogod [111]: <0x0x5638c8825140[SOGoActiveSyncDispatcher]> Change detected using Ping, we let the EAS client know to send a Sync. 2025-02-10T15:17:33+01:00 [1:sogo1:sogo-app] Feb 10 15:17:33 sogod [111]: 192.168.1.114, 192.168.1.1, 10.0.2.100 "POST /SOGo/Microsoft-Server-ActiveSync?User=patrick&DeviceId=73F403QNNH06PDN4K3PF2HSJQ0&DeviceType=iPad&Cmd=Ping HTTP/1.1" 200 58/0 120.368 - - 0 - 12 2025-02-10T15:17:34+01:00 [1:sogo1:sogo-app] Feb 10 15:17:34 sogod [111]: <0x0x5638c8b552a0[NGImap4Client]> Note: no key found for sorting, using 'DATE': (null) 2025-02-10T15:17:34+01:00 [1:sogo1:sogo-app] Feb 10 15:17:34 sogod [111]: <0x0x5638c8825b70[SOGoActiveSyncDispatcher]> Change detected during Sync, we push the content. 2025-02-10T15:17:34+01:00 [1:sogo1:sogo-app] Feb 10 15:17:34 sogod [111]: 192.168.1.114, 192.168.1.1, 10.0.2.100 "POST /SOGo/Microsoft-Server-ActiveSync?User=patrick&DeviceId=73F403QNNH06PDN4K3PF2HSJQ0&DeviceType=iPad&Cmd=Sync HTTP/1.1" 200 4249/112 0.201 - - 2M - 13 2025-02-10T15:17:34+01:00 [1:sogo1:sogo-app] Feb 10 15:17:34 sogod [111]: <0x0x5638c87a4100[SOGoActiveSyncDispatcher]> Change detected during Sync, we push the content. 2025-02-10T15:17:34+01:00 [1:sogo1:sogo-app] Feb 10 15:17:34 sogod [111]: 192.168.1.114, 192.168.1.1, 10.0.2.100 "POST /SOGo/Microsoft-Server-ActiveSync?User=patrick&DeviceId=73F403QNNH06PDN4K3PF2HSJQ0&DeviceType=iPad&Cmd=Sync HTTP/1.1" 200 23334/112 0.157 - - 128K - 12 2025-02-10T15:17:36+01:00 [1:sogo1:sogo-app] Feb 10 15:17:36 sogod [111]: <0x0x5638c8b50f80[SOGoActiveSyncDispatcher]> Change detected using Ping, we let the EAS client know to send a Sync. 2025-02-10T15:17:36+01:00 [1:sogo1:sogo-app] Feb 10 15:17:36 sogod [111]: 192.168.1.114, 192.168.1.1, 10.0.2.100 "POST /SOGo/Microsoft-Server-ActiveSync?User=patrick&DeviceId=73F403QNNH06PDN4K3PF2HSJQ0&DeviceType=iPad&Cmd=Ping HTTP/1.1" 200 58/0 0.164 - - 0 - 12 2025-02-10T15:17:36+01:00 [1:sogo1:sogo-app] Feb 10 15:17:36 sogod [111]: <0x0x5638c88ad710[NGImap4Client]> Note: no key found for sorting, using 'DATE': (null) 2025-02-10T15:17:36+01:00 [1:sogo1:sogo-app] Feb 10 15:17:36 sogod [111]: <0x0x5638c8546210[SOGoActiveSyncDispatcher]> Change detected during Sync, we push the content. 2025-02-10T15:17:36+01:00 [1:sogo1:sogo-app] Feb 10 15:17:36 sogod [111]: 192.168.1.114, 192.168.1.1, 10.0.2.100 "POST /SOGo/Microsoft-Server-ActiveSync?User=patrick&DeviceId=73F403QNNH06PDN4K3PF2HSJQ0&DeviceType=iPad&Cmd=Sync HTTP/1.1" 200 81/112 0.159 - - 0 - 12 2025-02-10T15:17:38+01:00 [1:sogo1:sogo-app] Feb 10 15:17:38 sogod [111]: <0x0x5638c8790f60[SOGoActiveSyncDispatcher]> Sleeping 30 seconds while detecting changes for user patrick in Ping..

madpatrick 2025-02-10 18:42 reporter ~0018072	Hi, Are these messages in the log something to look at ? 2025-02-10T19:36:01+01:00 [1:sogo1:sogo-app] [Mon Feb 10 18:36:01.490076 2025] [proxy_http:error] [pid 126:tid 133] (70007)The timeout specified has expired: [client 10.0.2.100:55216] AH01102: error reading status line from remote server 127.0.0.1:20000 2025-02-10T19:36:01+01:00 [1:sogo1:sogo-app] [Mon Feb 10 18:36:01.490118 2025] [proxy:error] [pid 126:tid 133] [client 10.0.2.100:55216] AH00898: Error reading from remote server returned by /Microsoft-Server-ActiveSync 2025-02-10T19:37:23+01:00 [1:sogo1:sogo-app] [Mon Feb 10 18:37:23.770125 2025] [proxy_http:error] [pid 126:tid 139] (70007)The timeout specified has expired: [client 10.0.2.100:40048] AH01102: error reading status line from remote server 127.0.0.1:20000 2025-02-10T19:37:23+01:00 [1:sogo1:sogo-app] [Mon Feb 10 18:37:23.770180 2025] [proxy:error] [pid 126:tid 139] [client 10.0.2.100:40048] AH00898: Error reading from remote server returned by /Microsoft-Server-ActiveSync 2025-02-10T19:37:24+01:00 [1:sogo1:sogo-app] [Mon Feb 10 18:37:24.910146 2025] [proxy_http:error] [pid 18:tid 86] (70007)The timeout specified has expired: [client 10.0.2.100:45926] AH01102: error reading status line from remote server 127.0.0.1:20000 2025-02-10T19:37:24+01:00 [1:sogo1:sogo-app] [Mon Feb 10 18:37:24.910193 2025] [proxy:error] [pid 18:tid 86] [client 10.0.2.100:45926] AH00898: Error reading from remote server returned by /Microsoft-Server-ActiveSync 2025-02-10T19:37:48+01:00 [1:sogo1:sogo-app] [Mon Feb 10 18:37:48.190039 2025] [proxy_http:error] [pid 18:tid 89] (70007)The timeout specified has expired: [client 10.0.2.100:56910] AH01102: error reading status line from remote server 127.0.0.1:20000 2025-02-10T19:37:48+01:00 [1:sogo1:sogo-app] [Mon Feb 10 18:37:48.190099 2025] [proxy:error] [pid 18:tid 89] [client 10.0.2.100:56910] AH00898: Error reading from remote server returned by /Microsoft-Server-ActiveSync

madpatrick 2025-02-10 19:27 reporter ~0018073	2025-02-10T20:25:24+01:00 [1:sogo1:sogo-app] Feb 10 20:25:24 sogod [119]: \|SOGo\| request took 0.137831 seconds to execute 2025-02-10T20:25:24+01:00 [1:sogo1:sogo-app] Feb 10 20:25:24 sogod [119]: 192.168.1.111, 192.168.1.1, 10.0.2.100 "POST /SOGo/Microsoft-Server-ActiveSync?User=patrick&DeviceId=L3KCTHG4TP0HB83FH7P93MPBNC&DeviceType=iPhone&Cmd=Sync HTTP/1.1" 200 0/102 0.142 - - 0 - 12 2025-02-10T20:25:26+01:00 [1:sogo1:sogo-app] Feb 10 20:25:26 sogod [119]: \|SOGo\| starting method 'POST' on uri '/SOGo/Microsoft-Server-ActiveSync?User=patrick&DeviceId=L3KCTHG4TP0HB83FH7P93MPBNC&DeviceType=iPhone&Cmd=Ping' 2025-02-10T20:25:27+01:00 [1:sogo1:sogo-app] Feb 10 20:25:27 sogod [119]: <0x0x56143ebf6c50[SOGoActiveSyncDispatcher]> Sleeping 30 seconds while detecting changes for user patrick in Ping... 2025-02-10T20:25:29+01:00 [1:sogo1:sogo-app] Feb 10 20:25:29 sogod [117]: \|SOGo\| starting method 'POST' on uri '/SOGo/Microsoft-Server-ActiveSync?User=thomas&DeviceId=BEPCT7NQG50CL3OTSHI41680JS&DeviceType=iPhone&Cmd=Ping' 2025-02-10T20:25:29+01:00 [1:sogo1:sogo-app] Feb 10 20:25:29 sogod [117]: <0x0x56143e9ecc20[SOGoActiveSyncDispatcher]> Sleeping 30 seconds while detecting changes for user thomas in Ping... 2025-02-10T20:25:30+01:00 [1:sogo1:sogo-app] Feb 10 20:25:30 sogod [120]: \|SOGo\| starting method 'POST' on uri '/SOGo/Microsoft-Server-ActiveSync?User=jordy&DeviceId=7R0RH86AJL3711ND1CV9QOTR1O&DeviceType=iPhone&Cmd=Ping' 2025-02-10T20:25:30+01:00 [1:sogo1:sogo-app] Feb 10 20:25:30 sogod [120]: <0x0x56143e207eb0[SOGoActiveSyncDispatcher]> Sleeping 30 seconds while detecting changes for user jordy in Ping... 2025-02-10T20:25:31+01:00 [1:sogo1:sogo-app] Feb 10 20:25:31 sogod [116]: \|SOGo\| request took 390.772990 seconds to execute 2025-02-10T20:25:31+01:00 [1:sogo1:sogo-app] Feb 10 20:25:31 sogod [116]: [ERROR] <0x0x56143e7d1ea0[WOHttpTransaction]> client disconnected during delivery of response for <WORequest[0x0x56143e8ca8f0]: method=POST uri=/SOGo/Microsoft-Server-ActiveSync?User=patrick&DeviceId=L3KCTHG4TP0HB83FH7P93MPBNC&DeviceType=iPhone&Cmd=Ping app=SOGo rqKey=Microsoft-Server-ActiveSync rqPath=(null)> (len=13): the socket was shutdown 2025-02-10T20:25:31+01:00 [1:sogo1:sogo-app] Feb 10 20:25:31 sogod [116]: 192.168.1.111, 192.168.1.1, 10.0.2.100 "POST /SOGo/Microsoft-Server-ActiveSync?User=patrick&DeviceId=L3KCTHG4TP0HB83FH7P93MPBNC&DeviceType=iPhone&Cmd=Ping HTTP/1.1" 200 13/0 390.775 - - 792K - 13 2025-02-10T20:25:35+01:00 [1:sogo1:sogo-app] Feb 10 20:25:35 sogod [7]: [WARN] <0x0x56143e234d20[WOWatchDogChild]> pid 112 has been hanging in the same request for 5 minutes 2025-02-10T20:25:36+01:00 [1:sogo1:sogo-app] Feb 10 20:25:36 sogod [112]: <0x0x56143ea2abd0[SOGoActiveSyncDispatcher]> Sleeping 30 seconds while detecting changes for user linda in Ping... 2025-02-10T20:25:39+01:00 [1:sogo1:sogo-app] Feb 10 20:25:39 sogod [7]: [WARN] <0x0x56143e235680[WOWatchDogChild]> pid 109 has been hanging in the same request for 14 minutes 2025-02-10T20:25:40+01:00 [1:sogo1:sogo-app] Feb 10 20:25:40 sogod [115]: \|SOGo\| request took 30.272350 seconds to execute 2025-02-10T20:25:40+01:00 [1:sogo1:sogo-app] Feb 10 20:25:40 sogod [115]: 192.168.1.111, 192.168.1.1, 10.0.2.100 "POST /SOGo/Microsoft-Server-ActiveSync?User=patrick&DeviceId=L3KCTHG4TP0HB83FH7P93MPBNC&DeviceType=iPhone&Cmd=Ping HTTP/1.1" 200 13/0 30.275 - - 0 - 13 2025-02-10T20:25:41+01:00 [1:sogo1:sogo-app] Feb 10 20:25:41 sogod [109]: <0x0x56143e05f7f0[SOGoActiveSyncDispatcher]> Change detected using Ping, we let the EAS client know to send a Sync. 2025-02-10T20:25:41+01:00 [1:sogo1:sogo-app] Feb 10 20:25:41 sogod [109]: [ERROR] <0x0x56143ea7b3a0[WOHttpTransaction]> client disconnected during delivery of response for <WORequest[0x0x56143dfdcb40]: method=POST uri=/SOGo/Microsoft-Server-ActiveSync?User=patrick&DeviceId=73F403QNNH06PDN4K3PF2HSJQ0&DeviceType=iPad&Cmd=Ping app=SOGo rqKey=Microsoft-Server-ActiveSync rqPath=(null)> (len=58): the socket was shutdown 2025-02-10T20:25:41+01:00 [1:sogo1:sogo-app] Feb 10 20:25:41 sogod [109]: 192.168.1.114, 192.168.1.1, 10.0.2.100 "POST /SOGo/Microsoft-Server-ActiveSync?User=patrick&DeviceId=73F403QNNH06PDN4K3PF2HSJQ0&DeviceType=iPad&Cmd=Ping HTTP/1.1" 200 58/0 841.370 - - 0 - 12 2025-02-10T20:25:41+01:00 [1:sogo1:sogo-app] Feb 10 20:25:41 sogod [109]: \|SOGo\| request took 841.368742 seconds to execute

qhivert 2025-02-11 08:57 administrator ~0018076	Those logs `client disconnected during delivery of response for` mean that the device shuts down the connection and sogo can't send any response. Maybe it comes from your nginc/apache configuration that has a timeout to low. `ProxyPass /Microsoft-Server-ActiveSync \ http://127.0.0.1:20000/SOGo/Microsoft-Server-ActiveSync \ retry=60 connectiontimeout=5 timeout=360 The above line sets a timeout for up to 360 seconds, or 6 minutes. If you want to let EAS clients keep their HTTP connections open for up to an hour, you must change the timeout parameter and set it to 3600.` It could also come from the device itself, the configuration of the app used or the wifi router that can set time limits.

madpatrick 2025-02-11 18:34 reporter ~0018084	I've changed it to timeout=3600 and WOWatchDogRequestTimeout = 60; Let's see what happens

Date Modified	Username	Field	Change
2025-02-10 08:32	madpatrick	New Issue
2025-02-10 08:32	madpatrick	Tag Attached: WOWatchDogChild ;pid
2025-02-10 13:13	qhivert	Note Added: 0018062
2025-02-10 13:13	qhivert	Assigned To	=> qhivert
2025-02-10 13:13	qhivert	Status	new => feedback
2025-02-10 13:36	madpatrick	Note Added: 0018065
2025-02-10 13:36	madpatrick	Status	feedback => assigned
2025-02-10 13:42	madpatrick	Note Added: 0018066
2025-02-10 13:53	qhivert	Note Added: 0018067
2025-02-10 13:53	qhivert	Status	assigned => feedback
2025-02-10 14:00	madpatrick	Note Added: 0018068
2025-02-10 14:00	madpatrick	Status	feedback => assigned
2025-02-10 14:17	qhivert	Note Added: 0018069
2025-02-10 14:17	qhivert	Status	assigned => feedback
2025-02-10 14:31	madpatrick	Note Added: 0018070
2025-02-10 14:31	madpatrick	Status	feedback => assigned
2025-02-10 14:51	madpatrick	Note Added: 0018071
2025-02-10 18:42	madpatrick	Note Added: 0018072
2025-02-10 19:27	madpatrick	Note Added: 0018073
2025-02-11 08:57	qhivert	Note Added: 0018076
2025-02-11 08:57	qhivert	Status	assigned => feedback
2025-02-11 18:34	madpatrick	Note Added: 0018084
2025-02-11 18:34	madpatrick	Status	feedback => assigned

View Issue Details

Activities

Issue History