|
|
Further log review before the issue occurred shows that the following request by process ID 2749216 which then hung for 5 minutes before it started outputting millions of warnings in the logfile.
Mar 13 12:20:30 sogod [2749216]: 127.0.0.1 "GET /SOGo/so/REDACTEDUSER/Calendar/eventslist?asc=1&day=20250313&filterpopup=view_next7&search=title_Category_Location&sort=start&value= HTTP/1.1" 200 2542/0 0.035 - - 0 - 15
Mar 13 12:21:33 sogod [2749207]: [WARN] <0x0x558820bc99f0[WOWatchDogChild]> pid 2749216 has been hanging in the same request for 1 minutes
Mar 13 12:22:33 sogod [2749207]: [WARN] <0x0x558820bc99f0[WOWatchDogChild]> pid 2749216 has been hanging in the same request for 2 minutes
Mar 13 12:23:33 sogod [2749207]: [WARN] <0x0x558820bc99f0[WOWatchDogChild]> pid 2749216 has been hanging in the same request for 3 minutes
Mar 13 12:24:33 sogod [2749207]: [WARN] <0x0x558820bc99f0[WOWatchDogChild]> pid 2749216 has been hanging in the same request for 4 minutes
Mar 13 12:25:33 sogod [2749207]: [WARN] <0x0x558820bc99f0[WOWatchDogChild]> pid 2749216 has been hanging in the same request for 5 minutes
2025-03-13 12:26:07.702 sogod[2749216:2749216] caught SIGPIPE - ignoring!
2025-03-13 12:26:07.703 sogod[2749216:2749216] WARNING(-[NGBufferedStream writeBytes:count:]): got passed in length 2048MB (2147606914 bytes, errcode=2147483647) ...
2025-03-13 12:26:07.703 sogod[2749216:2749216] WARNING(-[NGBufferedStream writeBytes:count:]): got passed in length 2048MB (2147606916 bytes, errcode=2147483647) ... |
|
|
Just had it occur with another process as shown after the process had been hanging on a previous request. Not really seeing what exactly is causing the process to hang. There were a couple of ERRORS but it that was a bit before it started hanging.
Mar 13 15:54:40 sogod [2788380]: 127.0.0.1 "REPORT /SOGo/dav/REDACTEDUSER/Calendar/redacted_personal/ HTTP/1.1" 207 460/234 0.057 - - 0 - 13
Mar 13 15:54:40 sogod [2788380]: [ERROR] <0x55ed9d644ae0[SOGoAppointmentFolder]:redacted_personal> DAV property '{http://calendarserver.org/ns/}updated-by' has no matching SQL field, response could be incomplete
Mar 13 15:54:40 sogod [2788380]: [ERROR] <0x55ed9d644ae0[SOGoAppointmentFolder]:redacted_personal> DAV property '{http://calendarserver.org/ns/}created-by' has no matching SQL field, response could be incomplete
Mar 13 15:54:40 sogod [2788380]: [ERROR] <0x55ed9d644ae0[SOGoAppointmentFolder]:redacted_personal> DAV property '{urn:ietf:params:xml:ns:caldav}schedule-tag' has no matching SQL field, response could be incomplete
Mar 13 15:54:40 sogod [2788380]: 127.0.0.1 "REPORT /SOGo/dav/REDACTEDUSER/Calendar/redacted_personal/ HTTP/1.1" 207 1336/502 0.026 3106 56% 0 - 13
Mar 13 15:54:41 sogod [2788380]: 127.0.0.1 "OPTIONS /SOGo/dav/REDACTEDUSER/ HTTP/1.1" 401 0/0 0.001 - - 0 - 13
Mar 13 15:54:42 sogod [2788380]: 127.0.0.1 "OPTIONS /SOGo/dav/REDACTEDUSER/ HTTP/1.1" 200 0/0 0.002 - - 0 - 13
Mar 13 15:54:42 sogod [2788380]: 127.0.0.1 "REPORT /SOGo/dav/REDACTEDUSER/ HTTP/1.1" 401 0/768 0.001 - - 0 - 13
Mar 13 15:54:42 sogod [2788380]: 127.0.0.1 "REPORT /SOGo/dav/REDACTEDUSER/ HTTP/1.1" 207 431/768 0.038 1412 69% 0 - 13
Mar 13 15:54:42 sogod [2788380]: 127.0.0.1 "PROPFIND /SOGo/dav/REDACTEDUSER/Calendar/ HTTP/1.1" 401 0/2237 0.001 - - 0 - 13
Mar 13 15:54:42 sogod [2788380]: 127.0.0.1 "PROPFIND /SOGo/dav/REDACTEDUSER/Calendar/ HTTP/1.1" 207 1707/2237 0.069 12364 86% 0 - 13
Mar 13 15:54:49 sogod [2788380]: 127.0.0.1 "GET /SOGo/ HTTP/1.1" 200 1077/0 0.003 2550 57% 0 - 13
Mar 13 15:54:51 sogod [2788380]: 127.0.0.1 "OPTIONS /SOGo/dav/REDACTEDUSER/ HTTP/1.1" 401 0/0 0.001 - - 0 - 13
Mar 13 15:54:51 sogod [2788380]: 127.0.0.1 "OPTIONS /SOGo/dav/REDACTEDUSER/ HTTP/1.1" 200 0/0 0.002 - - 0 - 13
Mar 13 15:54:51 sogod [2788380]: 127.0.0.1 "REPORT /SOGo/dav/REDACTEDUSER/ HTTP/1.1" 401 0/768 0.001 - - 0 - 13
Mar 13 15:54:52 sogod [2788380]: 127.0.0.1 "REPORT /SOGo/dav/REDACTEDUSER/ HTTP/1.1" 207 583/768 0.143 3370 82% 0 - 13
Mar 13 15:54:52 sogod [2788380]: 127.0.0.1 "PROPFIND /SOGo/dav/REDACTEDUSER/Calendar/ HTTP/1.1" 401 0/2237 0.001 - - 0 - 13
Mar 13 15:54:52 sogod [2788380]: 127.0.0.1 "PROPFIND /SOGo/dav/REDACTEDUSER/Calendar/ HTTP/1.1" 207 1566/2237 0.035 10460 85% 0 - 13
Mar 13 15:55:59 sogod [2788365]: [WARN] <0x0x55ed9d8e3f60[WOWatchDogChild]> pid 2788380 has been hanging in the same request for 1 minutes
Mar 13 15:56:59 sogod [2788365]: [WARN] <0x0x55ed9d8e3f60[WOWatchDogChild]> pid 2788380 has been hanging in the same request for 2 minutes
Mar 13 15:57:59 sogod [2788365]: [WARN] <0x0x55ed9d8e3f60[WOWatchDogChild]> pid 2788380 has been hanging in the same request for 3 minutes
Mar 13 15:58:59 sogod [2788365]: [WARN] <0x0x55ed9d8e3f60[WOWatchDogChild]> pid 2788380 has been hanging in the same request for 4 minutes
Mar 13 15:59:59 sogod [2788365]: [WARN] <0x0x55ed9d8e3f60[WOWatchDogChild]> pid 2788380 has been hanging in the same request for 5 minutes
Mar 13 16:00:59 sogod [2788365]: [WARN] <0x0x55ed9d8e3f60[WOWatchDogChild]> pid 2788380 has been hanging in the same request for 6 minutes
Mar 13 16:01:59 sogod [2788365]: [WARN] <0x0x55ed9d8e3f60[WOWatchDogChild]> pid 2788380 has been hanging in the same request for 7 minutes
Mar 13 16:02:59 sogod [2788365]: [WARN] <0x0x55ed9d8e3f60[WOWatchDogChild]> pid 2788380 has been hanging in the same request for 8 minutes
Mar 13 16:03:59 sogod [2788365]: [WARN] <0x0x55ed9d8e3f60[WOWatchDogChild]> pid 2788380 has been hanging in the same request for 9 minutes
Mar 13 16:04:59 sogod [2788365]: [WARN] <0x0x55ed9d8e3f60[WOWatchDogChild]> pid 2788380 has been hanging in the same request for 10 minutes
Mar 13 16:05:59 sogod [2788365]: [WARN] <0x0x55ed9d8e3f60[WOWatchDogChild]> pid 2788380 has been hanging in the same request for 11 minutes
Mar 13 16:06:59 sogod [2788365]: [WARN] <0x0x55ed9d8e3f60[WOWatchDogChild]> pid 2788380 has been hanging in the same request for 12 minutes
Mar 13 16:07:59 sogod [2788365]: [WARN] <0x0x55ed9d8e3f60[WOWatchDogChild]> pid 2788380 has been hanging in the same request for 13 minutes
Mar 13 16:08:59 sogod [2788365]: [WARN] <0x0x55ed9d8e3f60[WOWatchDogChild]> pid 2788380 has been hanging in the same request for 14 minutes
Mar 13 16:09:59 sogod [2788365]: [WARN] <0x0x55ed9d8e3f60[WOWatchDogChild]> pid 2788380 has been hanging in the same request for 15 minutes
2025-03-13 16:10:39.446 sogod[2788380:2788380] WARNING(-[NGBufferedStream writeBytes:count:]): got passed in length 2048MB (2147610359 bytes, errcode=2147483647) ...
2025-03-13 16:10:39.446 sogod[2788380:2788380] WARNING(-[NGBufferedStream writeBytes:count:]): got passed in length 2048MB (2147610361 bytes, errcode=2147483647) ...
2025-03-13 16:10:39.446 sogod[2788380:2788380] WARNING(-[NGBufferedStream writeBytes:count:]): got passed in length 2048MB (2147610363 bytes, errcode=2147483647) ...
2025-03-13 16:10:39.446 sogod[2788380:2788380] WARNING(-[NGBufferedStream writeBytes:count:]): got passed in length 2048MB (2147610365 bytes, errcode=2147483647) ...
2025-03-13 16:10:39.446 sogod[2788380:2788380] WARNING(-[NGBufferedStream writeBytes:count:]): got passed in length 2048MB (2147610367 bytes, errcode=2147483647) ...
2025-03-13 16:10:39.446 sogod[2788380:2788380] WARNING(-[NGBufferedStream writeBytes:count:]): got passed in length 2048MB (2147610369 bytes, errcode=2147483647) ...
2025-03-13 16:10:39.446 sogod[2788380:2788380] WARNING(-[NGBufferedStream writeBytes:count:]): got passed in length 2048MB (2147610371 bytes, errcode=2147483647) ... |
|
|
Still seeing this occurring quite often:
Mar 20 11:44:12 sogod [2889371]: [WARN] <0x0x55f88f82d5c0[WOWatchDogChild]> pid 2906089 has been hanging in the same request for 1 minutes
Mar 20 11:45:12 sogod [2889371]: [WARN] <0x0x55f88f82d5c0[WOWatchDogChild]> pid 2906089 has been hanging in the same request for 2 minutes
Mar 20 11:46:12 sogod [2889371]: [WARN] <0x0x55f88f82d5c0[WOWatchDogChild]> pid 2906089 has been hanging in the same request for 3 minutes
Mar 20 11:47:12 sogod [2889371]: [WARN] <0x0x55f88f82d5c0[WOWatchDogChild]> pid 2906089 has been hanging in the same request for 4 minutes
Mar 20 11:48:12 sogod [2889371]: [WARN] <0x0x55f88f82d5c0[WOWatchDogChild]> pid 2906089 has been hanging in the same request for 5 minutes
2025-03-20 11:48:48.214 sogod[2906089:2906089] caught SIGPIPE - ignoring!
2025-03-20 11:48:48.214 sogod[2906089:2906089] WARNING(-[NGBufferedStream writeBytes:count:]): got passed in length 2048MB (2147560963 bytes, errcode=2147483647) ...
2025-03-20 11:48:48.214 sogod[2906089:2906089] WARNING(-[NGBufferedStream writeBytes:count:]): got passed in length 2048MB (2147560965 bytes, errcode=2147483647) ...
2025-03-20 11:48:48.215 sogod[2906089:2906089] WARNING(-[NGBufferedStream writeBytes:count:]): got passed in length 2048MB (2147560967 bytes, errcode=2147483647) ...
Mar 20 12:16:36 sogod [2906688]: [WARN] <0x0x563f297d69c0[WOWatchDogChild]> pid 2906704 has been hanging in the same request for 1 minutes
Mar 20 12:17:36 sogod [2906688]: [WARN] <0x0x563f297d69c0[WOWatchDogChild]> pid 2906704 has been hanging in the same request for 2 minutes
Mar 20 12:18:36 sogod [2906688]: [WARN] <0x0x563f297d69c0[WOWatchDogChild]> pid 2906704 has been hanging in the same request for 3 minutes
Mar 20 12:19:36 sogod [2906688]: [WARN] <0x0x563f297d69c0[WOWatchDogChild]> pid 2906704 has been hanging in the same request for 4 minutes
Mar 20 12:20:36 sogod [2906688]: [WARN] <0x0x563f297d69c0[WOWatchDogChild]> pid 2906704 has been hanging in the same request for 5 minutes
2025-03-20 12:21:11.770 sogod[2906704:2906704] caught SIGPIPE - ignoring!
2025-03-20 12:21:11.771 sogod[2906704:2906704] WARNING(-[NGBufferedStream writeBytes:count:]): got passed in length 2048MB (2147560958 bytes, errcode=2147483647) ...
2025-03-20 12:21:11.771 sogod[2906704:2906704] WARNING(-[NGBufferedStream writeBytes:count:]): got passed in length 2048MB (2147560960 bytes, errcode=2147483647) ...
2025-03-20 12:21:11.771 sogod[2906704:2906704] WARNING(-[NGBufferedStream writeBytes:count:]): got passed in length 2048MB (2147560962 bytes, errcode=2147483647) ...
2025-03-20 12:21:11.771 sogod[2906704:2906704] WARNING(-[NGBufferedStream writeBytes:count:]): got passed in length 2048MB (2147560964 bytes, errcode=2147483647) ...
2025-03-20 12:21:11.771 sogod[2906704:2906704] WARNING(-[NGBufferedStream writeBytes:count:]): got passed in length 2048MB (2147560966 bytes, errcode=2147483647) ...
Anyone else seeing this issue? |
|
|
Here is a GDB backtrace when the issue is occurring:
#0 0x00007fe85a250887 in __GI___libc_write (fd=2, buf=buf@entry=0x560a01357900, nbytes=nbytes@entry=166) at ../sysdeps/unix/sysv/linux/write.c:26
0000001 0x00007fe85a755a36 in _NSLog_standard_printf_handler (message=<optimized out>) at ./Source/NSLog.m:185
0000002 0x00007fe85a755f19 in NSLogv (format=<optimized out>, args=0x7ffff988d480) at ./Source/NSLog.m:440
0000003 0x00007fe85a75623d in NSLog (format=<optimized out>) at ./Source/NSLog.m:297
0000004 0x00007fe85ad19249 in ?? () from /usr/lib/libNGStreams.so.4.9
0000005 0x00007fe85ad1b29d in ?? () from /usr/lib/libNGStreams.so.4.9
0000006 0x00007fe85ae69f50 in ?? () from /usr/lib/libNGMime.so.4.9
0000007 0x00007fe85ae696ec in ?? () from /usr/lib/libNGMime.so.4.9
0000008 0x00007fe85ae69cdf in ?? () from /usr/lib/libNGMime.so.4.9
0000009 0x00007fe85ae672a1 in ?? () from /usr/lib/libNGMime.so.4.9
0000010 0x00007fe85ae9addb in ?? () from /usr/lib/libNGMime.so.4.9
0000011 0x00007fe856411ff0 in -[SOGoMailFolder postData:flags:] (self=0x560900137c80, _cmd=0x7fe856447b00 <_OBJC_SELECTOR_TABLE+4384>, _data=0x560900016d10,
_flags=0x7fe856445a80 <_OBJC_INSTANCE_143.3>) at SOGoMailFolder.m:1055
0000012 0x00007fe856401ee1 in -[SOGoDraftObject sendMailAndCopyToSent:] (self=0x56090011c870, _cmd=0x7fe856447a30 <_OBJC_SELECTOR_TABLE+4176>,
copyToSent=1 '\001') at SOGoDraftObject.m:2394
0000013 0x00007fe856400f94 in -[SOGoDraftObject sendMail] (self=0x56090011c870, _cmd=0x7fe855dcadd0 <_OBJC_SELECTOR_TABLE+2352>) at SOGoDraftObject.m:2243
0000014 0x00007fe855dac8ec in -[UIxMailEditor sendAction] (self=0x5608ffb1fdd0, _cmd=0x5608ffb1dd80) at UIxMailEditor.m:907
0000015 0x00007fe85b084839 in ?? () from /usr/lib/libNGObjWeb.so.4.9
0000016 0x00007fe855ed534b in -[UIxComponent performActionNamed:] (self=0x5608ffb1fdd0, _cmd=0x7fe85b251960, _actionName=0x5608fedbe1d0) at UIxComponent.m:820
0000017 0x00007fe85b111d5c in ?? () from /usr/lib/libNGObjWeb.so.4.9
0000018 0x00007fe85b111ea9 in ?? () from /usr/lib/libNGObjWeb.so.4.9
0000019 0x00007fe85b111abe in ?? () from /usr/lib/libNGObjWeb.so.4.9
0000020 0x00007fe85b111ea9 in ?? () from /usr/lib/libNGObjWeb.so.4.9
0000021 0x00007fe85b10ba1c in ?? () from /usr/lib/libNGObjWeb.so.4.9
0000022 0x00007fe85b10e298 in ?? () from /usr/lib/libNGObjWeb.so.4.9
0000023 0x00007fe85b086998 in ?? () from /usr/lib/libNGObjWeb.so.4.9
0000024 0x00007fe85b040124 in ?? () from /usr/lib/libNGObjWeb.so.4.9
0000025 0x00007fe85b040493 in ?? () from /usr/lib/libNGObjWeb.so.4.9
0000026 0x00005608fdca5c5d in -[SOGo dispatchRequest:] (self=0x5608feddbd10, _cmd=0x7fe85b23d9c0, _request=0x5609000b8d40) at SOGo.m:597
0000027 0x00007fe85b0fa26f in ?? () from /usr/lib/libNGObjWeb.so.4.9
0000028 0x00007fe85b0fa641 in ?? () from /usr/lib/libNGObjWeb.so.4.9
0000029 0x00007fe85b0f5b85 in ?? () from /usr/lib/libNGObjWeb.so.4.9
0000030 0x00007fe85b0f5de0 in ?? () from /usr/lib/libNGObjWeb.so.4.9
0000031 0x00007fe85b0f626d in ?? () from /usr/lib/libNGObjWeb.so.4.9
0000032 0x00007fe85b0f65a2 in ?? () from /usr/lib/libNGObjWeb.so.4.9
0000033 0x00007fe85a75ca31 in -[NSNotificationCenter _postAndRelease:] (self=0x5608fec1e930, _cmd=<optimized out>, notification=0x5608fff99a70)
at ./Source/NSNotificationCenter.m:1198
0000034 0x00007fe85ac80a0a in ?? () from /usr/lib/libNGExtensions.so.4.9
0000035 0x00007fe85a879d7e in -[GSRunLoopCtxt pollUntil:within:] (self=<optimized out>, _cmd=0x7fe85aaa63c0 <_OBJC_SELECTOR_TABLE+1184>,
milliseconds=<optimized out>, contexts=0x5608fedd2350) at ./Source/unix/GSRunLoopCtxt.m:600
0000036 0x00007fe85a7a8a37 in -[NSRunLoop acceptInputForMode:beforeDate:] (self=0x5608fed066d0, _cmd=0x7fe85aaa63f0 <_OBJC_SELECTOR_TABLE+1232>,
mode=0x7fe85aaa71f0 <_OBJC_INSTANCE_2>, limit_date=0x5608ffca2590) at ./Source/NSRunLoop.m:1254
0000037 0x00007fe85a7a87d4 in -[NSRunLoop runMode:beforeDate:] (self=<optimized out>, _cmd=<optimized out>, mode=0x7fe85aaa71f0 <_OBJC_INSTANCE_2>,
date=<optimized out>) at ./Source/NSRunLoop.m:1334
0000038 0x00007fe85b03f869 in ?? () from /usr/lib/libNGObjWeb.so.4.9
0000039 0x00005608fdca4b85 in -[SOGo run] (self=0x5608feddbd10, _cmd=0x7fe85b1e02f0) at SOGo.m:340
0000040 0x00007fe85b090e37 in ?? () from /usr/lib/libNGObjWeb.so.4.9
0000041 0x00007fe85b09135b in ?? () from /usr/lib/libNGObjWeb.so.4.9
0000042 0x00007fe85b091b2e in ?? () from /usr/lib/libNGObjWeb.so.4.9
0000043 0x00007fe85b092da1 in ?? () from /usr/lib/libNGObjWeb.so.4.9
0000044 0x00007fe85b0935d7 in WOWatchDogApplicationMain () from /usr/lib/libNGObjWeb.so.4.9
0000045 0x00005608fdca349d in main (argc=7, argv=0x7ffff9890c78, env=0x7ffff9890cb8) at sogod.m:59 |
|
|
I only noticed this issue starting March 11th as well as the recently nightly versions. Looked through the commits and didn't see anything that would have introduced it recently though.
I had the sope4.9-dbg and sogo-dbg packages but not the gnustep-base-runtime-dbgsym package which I just installed. I'll try to get another trace if I can catch it happening again. |
