Hi Marcus,
Thanks very much for your reply. We have apache in front of sogo, and as
fas as I can see, apache is logging nothing special at the time of these
authentication attempts.
We had 5 of these auth attempts this morning at 06:01. Here are some
more (probably too many) logs from sogo, and further down the same same
period apache logs.
Hopefully someone here can spot something that I am missing.
Sogo this morning:
Nov 01 06:01:35 sogod [26091]: |SOGo| starting method 'POST' on uri
'/SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=user_av&DeviceId=C1EFA48B85&DeviceType=SAMSUNGSMT805'
Nov 01 06:01:37 sogod [25952]: [WARN] <0x0x55e5d00d6ff0[WOWatchDogChild]> pid
25975 has been hanging in the same request for 3 minutes
Nov 01 06:01:38 sogod [26098]: <0x0x55e5d9a5b710[SOGoActiveSyncDispatcher]>
Sleeping 30 seconds while detecting changes for user user_heu in Ping...
Nov 01 06:01:38 sogod [26058]: |SOGo| starting method 'POST' on uri
'/SOGo/Microsoft-Server-ActiveSync?Cmd=Ping&User=user_ta&DeviceId=androidc1214775124&DeviceType=Android'
Nov 01 06:01:38 sogod [25975]: <0x0x55e5d6bc06f0[SOGoActiveSyncDispatcher]>
Sleeping 30 seconds while detecting changes for user user_bie in Ping...
Nov 01 06:01:40 sogod [26091]: |SOGo| request took 4.681785 seconds to execute
Nov 01 06:01:40 sogod [26091]: 198.54.173.196 "POST
/SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=user_av&DeviceId=SEC16FB85&DeviceType=SAMSUNGSMT805
HTTP/1.1" 503 0/144 4.683 - - 0
Nov 01 06:01:40 sogod [25978]: |SOGo| request took 36.488380 seconds to execute
Nov 01 06:01:40 sogod [25978]: 198.54.173.196 "POST
/SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=user_av&DeviceId=SEC16F5&DeviceType=SAMSUNGSMT805
HTTP/1.1" 200 0/144 36.489 - - 0
Nov 01 06:01:40 sogod [25992]: |SOGo| request took 24.210513 seconds to execute
Nov 01 06:01:40 sogod [25992]: 198.54.173.196 "POST
/SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=user_av&DeviceId=SEC1EFA48B85&DeviceType=SAMSUNGSMT805
HTTP/1.1" 503 0/144 24.212 - - 0
Nov 01 06:01:40 sogod [26065]: <0x0x55e5d6bc43a0[SOGoActiveSyncDispatcher]>
Sleeping 30 seconds while detecting changes for user user_pi in Ping...
Nov 01 06:01:40 sogod [26058]: <0x0x55e5d93c02a0[SOGoActiveSyncDispatcher]>
Sleeping 30 seconds while detecting changes for user user_ta in Ping...
Nov 01 06:01:40 sogod [25974]: <0x0x55e5d4680b20[SOGoActiveSyncDispatcher]>
Sleeping 30 seconds while detecting changes for user user_sa in Ping...
Nov 01 06:01:41 sogod [25990]: <0x0x55e5d3da6ed0[SOGoActiveSyncDispatcher]>
Sleeping 30 seconds while detecting changes for user user_vi in Ping...
Nov 01 06:01:41 sogod [25980]: <0x0x55e5d278e3d0[SOGoActiveSyncDispatcher]>
Sleeping 30 seconds while detecting changes for user user_sa in Ping...
Nov 01 06:01:42 sogod [25992]: |SOGo| starting method 'POST' on uri
'/SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=user_av&DeviceId=S6FC1EFA48B85&DeviceType=SAMSUNGSMT805'
Nov 01 06:01:42 sogod [25992]: |SOGo| request took 0.417357 seconds to execute
Nov 01 06:01:42 sogod [25992]: 198.54.173.196 "POST
/SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=user_av&DeviceId=SEC16FC1EB85&DeviceType=SAMSUNGSMT805
HTTP/1.1" 200 0/144 0.419 - - 0
Nov 01 06:01:43 sogod [25984]: <0x0x55e5d919e0b0[SOGoActiveSyncDispatcher]>
Sleeping 30 seconds while detecting changes for user user_fo in Ping...
Nov 01 06:01:44 sogod [25979]: <0x0x55e5d84d9e50[SOGoActiveSyncDispatcher]>
Sleeping 30 seconds while detecting changes for user user_to in Ping...
Nov 01 06:01:45 sogod [25952]: [WARN] <0x0x55e5d017b990[WOWatchDogChild]> pid
26071 has been hanging in the same request for 3 minutes
Nov 01 06:01:45 sogod [25981]: |SOGo| request took 332.461077 seconds to execute
Nov 01 06:01:45 sogod [25981]: [ERROR] <0x0x55e5d4e0f3e0[WOHttpTransaction]> client disconnected
during delivery of response for <WORequest[0x0x55e5d2b21740]: method=POST
uri=/SOGo/Microsoft-Server-ActiveSync?User=user_sa%40merit.unu.edu&DeviceId=7B687EA44DD55&DeviceType=Outlook&Cmd=Ping
app=SOGo rqKey=Microsoft-Server-ActiveSync rqPath=(null)> (len=13): the socket was shutd
Nov 01 06:01:45 sogod [25981]: 52.125.140.40 "POST
/SOGo/Microsoft-Server-ActiveSync?User=user_sa%40merit.unu.edu&DeviceId=7C3DEA44DD55&DeviceType=Outlook&Cmd=Ping
HTTP/1.1" 200 13/246 332.463 - - 0
Nov 01 06:01:46 sogod [26071]: <0x0x55e5d7556c00[SOGoActiveSyncDispatcher]>
Sleeping 30 seconds while detecting changes for user user_kro in Ping...
Nov 01 06:01:46 sogod [26075]: <0x0x55e5d65ae130[SOGoActiveSyncDispatcher]>
Sleeping 30 seconds while detecting changes for user user_sa in Ping...
Nov 01 06:01:46 sogod [25981]: |SOGo| starting method 'POST' on uri
'/SOGo/Microsoft-Server-ActiveSync?Cmd=FolderSync&User=user_av&DeviceId=SEC16FC48B85&DeviceType=SAMSUNGSMT805'
Nov 01 06:01:46 sogod [26084]: <0x0x55e5d8f67c60[SOGoActiveSyncDispatcher]>
Sleeping 30 seconds while detecting changes for user user_pa in Ping...
2018-11-01 06:01:47.380 sogod[25981] ERROR(-[NGLdapSearchResultEnumerator
nextObject]): does not support result references yet ..
2018-11-01 06:01:47.535 sogod[25981] ERROR(-[NGLdapSearchResultEnumerator
nextObject]): does not support result references yet ..
2018-11-01 06:01:47.699 sogod[25981] ERROR(-[NGLdapSearchResultEnumerator
nextObject]): does not support result references yet ..
2018-11-01 06:01:47.854 sogod[25981] ERROR(-[NGLdapSearchResultEnumerator
nextObject]): does not support result references yet ..
Nov 01 06:01:47 sogod [25981]: |SOGo| request took 0.992236 seconds to execute
Nov 01 06:01:47 sogod [25981]: 198.54.173.196 "POST
/SOGo/Microsoft-Server-ActiveSync?Cmd=FolderSync&User=user_av&DeviceId=SEC16FC1EB85&DeviceType=SAMSUNGSMT805
HTTP/1.1" 200 59/47 0.994 - - 0
Nov 01 06:01:47 sogod [25981]: |SOGo| starting method 'POST' on uri
'/SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=user_av&DeviceId=SEC16FC1EFA48B85&DeviceType=SAMSUNGSMT805'
Nov 01 06:01:48 sogod [25981]: |SOGo| request took 0.416119 seconds to execute
Nov 01 06:01:48 sogod [25981]: 198.54.173.196 "POST
/SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=user_av&DeviceId=SEC148B85&DeviceType=SAMSUNGSMT805
HTTP/1.1" 200 0/144 0.418 - - 0
Nov 01 06:01:48 sogod [25952]: [WARN] <0x0x55e5d012a580[WOWatchDogChild]> pid
25991 has been hanging in the same request for 2 minutes
Nov 01 06:01:48 sogod [25952]: [WARN] <0x0x55e5d00e86f0[WOWatchDogChild]> pid
25977 has been hanging in the same request for 2 minutes
Nov 01 06:01:48 sogod [25991]: <0x0x55e5d2772220[SOGoActiveSyncDispatcher]>
Sleeping 30 seconds while detecting changes for user user_sa in Ping...
Nov 01 06:01:49 sogod [25977]: <0x0x55e5d420f6d0[SOGoActiveSyncDispatcher]>
Sleeping 30 seconds while detecting changes for user app in Ping...
Nov 01 06:01:50 sogod [25981]: |SOGo| starting method 'POST' on uri
'/SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=user_av&DeviceId=SEC16FA48B85&DeviceType=SAMSUNGSMT805'
Nov 01 06:01:50 sogod [25981]: |SOGo| request took 0.417733 seconds to execute
Nov 01 06:01:50 sogod [25981]: 198.54.173.196 "POST
/SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=user_av&DeviceId=SEC16FC1E85&DeviceType=SAMSUNGSMT805
HTTP/1.1" 200 0/144 0.419 - - 0
Nov 01 06:01:50 sogod [25952]: [WARN] <0x0x55e5d02c30b0[WOWatchDogChild]> pid
26053 has been hanging in the same request for 8 minutes
Nov 01 06:01:51 sogod [26080]: <0x0x55e5d52d2cf0[SOGoActiveSyncDispatcher]>
Sleeping 30 seconds while detecting changes for user user_ba in Ping...
Nov 01 06:01:53 sogod [26081]: <0x0x55e5d3d60740[SOGoActiveSyncDispatcher]>
Sleeping 30 seconds while detecting changes for user user_al in Ping...
Nov 01 06:01:53 sogod [26053]: <0x0x55e5d919b290[SOGoActiveSyncDispatcher]>
Sleeping 30 seconds while detecting changes for user user_kro in Ping...
Nov 01 06:01:56 sogod [25981]: |SOGo| starting method 'POST' on uri
'/SOGo/so/user_wa/Mail/0/folderINBOX/uids'
Nov 01 06:01:56 sogod [25992]: |SOGo| starting method 'GET' on uri
'/SOGo/so/user_wa/Mail/0/folderINBOX/unseenCount'
Nov 01 06:01:56 sogod [25981]: <0x0x55e5d04e62a0[SOGoWebAuthenticator]> tried
wrong password for user
'MrJ54LE+7X6anHUhvquAveMgjYnUBkJm8EamFiQiOyEH/O6cATAqcXHJlVuyXVjJqepwNAePata192iGmBMSWPDEwlzmq32s2cgXwmAoQ7e6+3DWAcVFmwfa0Fs0g0CvdsxeryIozk216wgC1gplbErOzeKLwLo+m3cWK1iVjVVUSS0OOuY0yg6iYCHklo9C0YQFiaWejubJNQj4/oWaHg=='!
Nov 01 06:01:56 sogod [25992]: <0x0x55e5cfe56bb0[SOGoWebAuthenticator]> tried
wrong password for user
'MrJ54LE+7X6anHUhvquAveMgjYnUBkJm8EamFiQiOyEH/O6cATAqcXHJlVuyXVjJqepwNAePata192iGmBMSWPDEwlzmq32s2cgXwmAoQ7e6+3DWAcVFmwfa0Fs0g0CvdsxeryIozk216wgC1gplbErOzeKLwLo+m3cWK1iVjVVUSS0OOuY0yg6iYCHklo9C0YQFiaWejubJNQj4/oWaHg=='!
Nov 01 06:01:56 sogod [25981]: |SOGo| request took 0.013067 seconds to execute
Nov 01 06:01:56 sogod [25992]: |SOGo| request took 0.013976 seconds to execute
Nov 01 06:01:56 sogod [25992]: 185.186.207.1 "GET
/SOGo/so/user_wa/Mail/0/folderINBOX/unseenCount HTTP/1.1" 200 4506/0 0.016 13947 67% 0
Nov 01 06:01:56 sogod [25981]: 185.186.207.1 "POST
/SOGo/so/user_wa/Mail/0/folderINBOX/uids HTTP/1.1" 200 4506/92 0.016 13947 67% 0
Nov 01 06:01:56 sogod [25978]: |SOGo| starting method 'GET' on uri
'/SOGo/so/user_wa/Mail/0/folderSent_SP_Items/unseenCount'
Nov 01 06:01:56 sogod [25978]: <0x0x55e5d04e6f80[SOGoWebAuthenticator]> tried
wrong password for user
'MrJ54LE+7X6anHUhvquAveMgjYnUBkJm8EamFiQiOyEH/O6cATAqcXHJlVuyXVjJqepwNAePata192iGmBMSWPDEwlzmq32s2cgXwmAoQ7e6+3DWAcVFmwfa0Fs0g0CvdsxeryIozk216wgC1gplbErOzeKLwLo+m3cWK1iVjVVUSS0OOuY0yg6iYCHklo9C0YQFiaWejubJNQj4/oWaHg=='!
Nov 01 06:01:56 sogod [25992]: |SOGo| starting method 'GET' on uri
'/SOGo/so/user_wa/Mail/0/folderDeleted_SP_Items/unseenCount'
Nov 01 06:01:56 sogod [25992]: <0x0x55e5cfe56bb0[SOGoWebAuthenticator]> tried
wrong password for user
'MrJ54LE+7X6anHUhvquAveMgjYnUBkJm8EamFiQiOyEH/O6cATAqcXHJlVuyXVjJqepwNAePata192iGmBMSWPDEwlzmq32s2cgXwmAoQ7e6+3DWAcVFmwfa0Fs0g0CvdsxeryIozk216wgC1gplbErOzeKLwLo+m3cWK1iVjVVUSS0OOuY0yg6iYCHklo9C0YQFiaWejubJNQj4/oWaHg=='!
Nov 01 06:01:56 sogod [25978]: |SOGo| request took 0.012359 seconds to execute
Nov 01 06:01:56 sogod [25978]: 185.186.207.1 "GET
/SOGo/so/user_wa/Mail/0/folderSent_SP_Items/unseenCount HTTP/1.1" 200 4506/0 0.014
13947 67% 0
Nov 01 06:01:56 sogod [25992]: |SOGo| request took 0.011852 seconds to execute
Nov 01 06:01:56 sogod [25992]: 185.186.207.1 "GET
/SOGo/so/user_wa/Mail/0/folderDeleted_SP_Items/unseenCount HTTP/1.1" 200 4506/0
0.014 13947 67% 0
Nov 01 06:01:56 sogod [25992]: |SOGo| starting method 'GET' on uri
'/SOGo/so/user_wa/Mail/0/folderDrafts/unseenCount'
Nov 01 06:01:56 sogod [25992]: <0x0x55e5cfe56bb0[SOGoWebAuthenticator]> tried
wrong password for user
'MrJ54LE+7X6anHUhvquAveMgjYnUBkJm8EamFiQiOyEH/O6cATAqcXHJlVuyXVjJqepwNAePata192iGmBMSWPDEwlzmq32s2cgXwmAoQ7e6+3DWAcVFmwfa0Fs0g0CvdsxeryIozk216wgC1gplbErOzeKLwLo+m3cWK1iVjVVUSS0OOuY0yg6iYCHklo9C0YQFiaWejubJNQj4/oWaHg=='!
Nov 01 06:01:56 sogod [25992]: |SOGo| request took 0.009721 seconds to execute
Nov 01 06:01:56 sogod [25992]: 185.186.207.1 "GET
/SOGo/so/user_wa/Mail/0/folderDrafts/unseenCount HTTP/1.1" 200 4506/0 0.012 13947
67% 0
Nov 01 06:01:59 sogod [25952]: [WARN] <0x0x55e5d017c7e0[WOWatchDogChild]> pid
26098 has been hanging in the same request for 4 minutes
And this same minute from apache's point of view:
198.54.173.196 - - [01/Nov/2018:06:01:03 +0100] "POST
/Microsoft-Server-ActiveSync?Cmd=FolderSync&User=user_av&DeviceId=SEC1EFA48B85&DeviceType=SAMSUNGSMT805
HTTP/1.1" 200 904 "-" "Android-SAMSUNG-SM-T805/101.60001"
198.54.173.196 - - [01/Nov/2018:06:01:22 +0100] "POST
/Microsoft-Server-ActiveSync?Cmd=FolderSync&User=user_av&DeviceId=SECC1EFA48B85&DeviceType=SAMSUNGSMT805
HTTP/1.1" 200 904 "-" "Android-SAMSUNG-SM-T805/101.60001"
198.54.173.196 - - [01/Nov/2018:06:01:35 +0100] "POST
/Microsoft-Server-ActiveSync?Cmd=FolderSync&User=user_av&DeviceId=SECC1EFA48B85&DeviceType=SAMSUNGSMT805
HTTP/1.1" 200 904 "-" "Android-SAMSUNG-SM-T805/101.60001"
198.54.173.196 - - [01/Nov/2018:06:01:35 +0100] "POST
/Microsoft-Server-ActiveSync?Cmd=Sync&User=user_av&DeviceId=SEC16EFA48B85&DeviceType=SAMSUNGSMT805
HTTP/1.1" 503 790 "-" "Android-SAMSUNG-SM-T805/101.60001"
198.54.173.196 - - [01/Nov/2018:06:01:03 +0100] "POST
/Microsoft-Server-ActiveSync?Cmd=Sync&User=user_av&DeviceId=SEC16EFA48B85&DeviceType=SAMSUNGSMT805
HTTP/1.1" 200 816 "-" "Android-SAMSUNG-SM-T805/101.60001"
198.54.173.196 - - [01/Nov/2018:06:01:16 +0100] "POST
/Microsoft-Server-ActiveSync?Cmd=Sync&User=user_av&DeviceId=SEC16EFA48B85&DeviceType=SAMSUNGSMT805
HTTP/1.1" 503 791 "-" "Android-SAMSUNG-SM-T805/101.60001"
198.54.173.196 - - [01/Nov/2018:06:01:42 +0100] "POST
/Microsoft-Server-ActiveSync?Cmd=Sync&User=user_av&DeviceId=SEC16EFA48B85&DeviceType=SAMSUNGSMT805
HTTP/1.1" 200 815 "-" "Android-SAMSUNG-SM-T805/101.60001"
198.54.173.196 - - [01/Nov/2018:06:01:46 +0100] "POST
/Microsoft-Server-ActiveSync?Cmd=FolderSync&User=user_av&DeviceId=SEC1EFA48B85&DeviceType=SAMSUNGSMT805
HTTP/1.1" 200 904 "-" "Android-SAMSUNG-SM-T805/101.60001"
198.54.173.196 - - [01/Nov/2018:06:01:47 +0100] "POST
/Microsoft-Server-ActiveSync?Cmd=Sync&User=user_av&DeviceId=SEC16FC48B85&DeviceType=SAMSUNGSMT805
HTTP/1.1" 200 815 "-" "Android-SAMSUNG-SM-T805/101.60001"
198.54.173.196 - - [01/Nov/2018:06:01:50 +0100] "POST
/Microsoft-Server-ActiveSync?Cmd=Sync&User=user_av&DeviceId=SEC16FC48B85&DeviceType=SAMSUNGSMT805
HTTP/1.1" 200 815 "-" "Android-SAMSUNG-SM-T805/101.60001"
185.186.207.1 - - [01/Nov/2018:06:01:56 +0100] "POST /SOGo/so/user_wa/Mail/0/folderINBOX/uids
HTTP/1.1" 200 10168 "https://webmail.merit.unu.edu/SOGo/so/user_wa/Mail/view";
"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/70.0.3538.77
Safari/537.36"
185.186.207.1 - - [01/Nov/2018:06:01:56 +0100] "GET /SOGo/so/user_wa/Mail/0/folderINBOX/unseenCount
HTTP/1.1" 200 10110 "https://webmail.merit.unu.edu/SOGo/so/user_wa/Mail/view";
"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/70.0.3538.77
Safari/537.36"
185.186.207.1 - - [01/Nov/2018:06:01:56 +0100] "GET
/SOGo/so/user_wa/Mail/0/folderSent_SP_Items/unseenCount HTTP/1.1" 200 9994
"https://webmail.merit.unu.edu/SOGo/so/user_wa/Mail/view"; "Mozilla/5.0 (Windows NT 10.0;
Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/70.0.3538.77 Safari/537.36"
185.186.207.1 - - [01/Nov/2018:06:01:56 +0100] "GET
/SOGo/so/user_wa/Mail/0/folderDeleted_SP_Items/unseenCount HTTP/1.1" 200 9994
"https://webmail.merit.unu.edu/SOGo/so/user_wa/Mail/view"; "Mozilla/5.0 (Windows NT 10.0;
Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/70.0.3538.77 Safari/537.36"
185.186.207.1 - - [01/Nov/2018:06:01:56 +0100] "GET /SOGo/so/user_wa/Mail/0/folderDrafts/unseenCount
HTTP/1.1" 200 10052 "https://webmail.merit.unu.edu/SOGo/so/user_wa/Mail/view";
"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/70.0.3538.77
Safari/537.36"
52.125.140.40 - - [01/Nov/2018:06:01:28 +0100] "POST
/Microsoft-Server-ActiveSync?User=user_sa%40merit.unu.edu&DeviceId=7C3DB6844DD55&DeviceType=Outlook&Cmd=Ping
HTTP/1.1" 502 5747 "-" "Outlook-iOS-Android/1.0"
41.238.138.36 - - [01/Nov/2018:06:01:38 +0100] "POST
/Microsoft-Server-ActiveSync?Cmd=Ping&User=user_ta&DeviceId=androidc175124&DeviceType=Android HTTP/1.1"
502 5595 "-" "Android/7.0-EAS-2.0"
Seems to me that apache is not noticing anything special...
Anyone with an idea to get some additional logs...?
MJ
--
users@sogo.nu
https://inverse.ca/sogo/lists
