Long delay on SOGo login with Google calendar subscription

sardaukar commented 4 years ago

Prior to placing the issue, please check following: (fill out each checkbox with an X once done)

[x] I understand, that not following or deleting the below instructions, will result in immediate closing and deletion of my issue.
[x] I have understood that answers are voluntary and community-driven, and not commercial support.
[x] I have verified that my issue has not been already answered in the past. I also checked previous issues.

Description of the bug:

It takes a really long time to login to SOGo (>50 seconds). It stays on the "Authenticating..." page for a long time, then proceeds.

Docker container logs of affected containers:

 Jul 17 12:08:50 756d7002c16e 2020-07-17 12:08:50.282 sogod[69:69] Adding uh 55358 ul 56691                                                                    _
_   Jul 17 12:08:50 756d7002c16e 2020-07-17 12:08:50.290 sogod[69:69] Adding uh 55357 ul 56881                                                                    _
_   Jul 17 12:08:50 756d7002c16e 2020-07-17 12:08:50.294 sogod[69:69] Adding uh 55358 ul 56611                                                                    _
_   Jul 17 12:08:50 756d7002c16e 2020-07-17 12:08:50.301 sogod[69:69] Adding uh 55356 ul 57211                                                                    _
_   Jul 17 12:08:50 756d7002c16e 2020-07-17 12:08:50.311 sogod[69:69] Adding uh 55356 ul 57173                                                                    _
_   Jul 17 12:08:50 756d7002c16e 2020-07-17 12:08:50.313 sogod[69:69] Adding uh 55357 ul 56349                                                                    _
_   Jul 17 12:08:50 756d7002c16e 2020-07-17 12:08:50.316 sogod[69:69] Adding uh 55356 ul 57225                                                                    _
_   Jul 17 12:08:50 756d7002c16e 2020-07-17 12:08:50.320 sogod[69:69] Adding uh 55357 ul 56960                                                                    _
_   Jul 17 12:08:50 756d7002c16e 2020-07-17 12:08:50.330 sogod[69:69] Adding uh 55357 ul 56908                                                                    _
_   Jul 17 12:08:50 756d7002c16e 2020-07-17 12:08:50.332 sogod[69:69] Adding uh 55357 ul 56846                                                                    _
_   Jul 17 12:08:50 756d7002c16e 2020-07-17 12:08:50.334 sogod[69:69] Adding uh 55356 ul 57140                                                                    _
_   Jul 17 12:08:50 756d7002c16e 2020-07-17 12:08:50.338 sogod[69:69] Adding uh 55357 ul 56490                                                                    _
_   Jul 17 12:08:58 756d7002c16e sogod [87]: mailcowdockerized_watchdog-mailcow_1.mailcowdockerized_mailcow-network "GET /SOGo.index/ HTTP/1.1" 200 2531/0 0.02   _
_   3 - - 0 - 13                                                                                                                                                  _
_   Jul 17 12:08:59 756d7002c16e sogod [69]: [ERROR] <0x0x55d6e6dedab0[iCalEvent]> Event with no end date; setting duration to PT1H for UID mug42n5acui3qc7jeah   _
_   lhktjs4@google.com                                                                                                                                            _
_   Jul 17 12:09:01 756d7002c16e CRON[100]: pam_unix(cron:session): session opened for user sogo by (uid=0)                                                       _
_   Jul 17 12:09:01 756d7002c16e CRON[99]: pam_unix(cron:session): session opened for user sogo by (uid=0)                                                        _
_   Jul 17 12:09:01 756d7002c16e CRON[101]: (sogo) CMD (  /usr/sbin/sogo-ealarms-notify -p /etc/sogo/sieve.creds 2>/dev/null)                                     _
_   Jul 17 12:09:01 756d7002c16e CRON[102]: (sogo) CMD (  /usr/sbin/sogo-tool expire-sessions 480)                                                                _
_   Jul 17 12:09:02 756d7002c16e CRON[99]: pam_unix(cron:session): session closed for user sogo                                                                   _
_   Jul 17 12:09:02 756d7002c16e CRON[100]: pam_unix(cron:session): session closed for user sogo                                                                  _
_   Jul 17 12:09:44 756d7002c16e sogod [87]: mailcowdockerized_watchdog-mailcow_1.mailcowdockerized_mailcow-network "GET /SOGo.index/ HTTP/1.1" 200 2531/0 0.01   _
_   5 - - 0 - 13                                                                                                                                                  _
_   Jul 17 12:09:45 756d7002c16e sogod [11]: [WARN] <0x0x55d6e06ec660[WOWatchDogChild]> pid 69 has been hanging in the same request for 1 minutes                 _
_   Jul 17 12:09:52 756d7002c16e sogod [69]: 217.129.4.71 "POST /SOGo/connect HTTP/1.0" 200 50/76 67.035 - - 426M - 14                                            _
_   Jul 17 12:09:52 756d7002c16e sogod [69]: |SOGo| terminating app, vMem size limit (384 MB) has been reached (currently 612 MB)                                 _
_   Jul 17 12:09:53 756d7002c16e sogod [11]: <0x0x55d6e06ec660[WOWatchDogChild]> child 69 exited                                                                  _
_   Jul 17 12:09:53 756d7002c16e sogod [11]: <0x0x55d6e053ee80[WOWatchDog]> child spawned with pid 107                                                            _
_   Jul 17 12:09:53 756d7002c16e sogod [107]: <0x0x55d6e0556c70[WOHttpAdaptor]> notified the watchdog that we are ready                                           _
_   Jul 17 12:09:54 756d7002c16e sogod [107]: <0x0x55d6e05f2060[SOGoCache]> Cache cleanup interval set every 900.000000 seconds                                   _
_   Jul 17 12:09:54 756d7002c16e sogod [107]: <0x0x55d6e05f2060[SOGoCache]> Using host(s) 'memcached' as server(s)                                                _
_   Jul 17 12:09:54 756d7002c16e sogod [107]: 217.129.4.71 "GET /SOGo/so/bruno%40nootch.net HTTP/1.0" 302 0/0 0.017 - - 1M - 12                                   _
_   Jul 17 12:09:54 756d7002c16e sogod [107]: 217.129.4.71 "GET /SOGo/so/bruno%40nootch.net/view HTTP/1.0" 302 0/0 0.014 - - 1M - 12                              _
_   Jul 17 12:09:54 756d7002c16e sogod [107]: 217.129.4.71 "GET /SOGo/so/bruno@nootch.net/Mail HTTP/1.0" 302 0/0 0.003 - - 0 - 12                                 _
_   Jul 17 12:09:54 756d7002c16e sogod [107]: 217.129.4.71 "GET /SOGo/so/bruno@nootch.net/Mail/view HTTP/1.0" 200 19889/0 0.127 85390 76% 4M - 12                 _
_   Jul 17 12:09:55 756d7002c16e sogod [107]: [WARN] <0x0x55d6e0a221a0[SOGoWebDAVAclManager]> entry '{DAV:}write' already exists in DAV permissions table         _
_   Jul 17 12:09:55 756d7002c16e sogod [107]: [WARN] <0x0x55d6e0a221a0[SOGoWebDAVAclManager]> entry '{DAV:}write-properties' already exists in DAV permissions    _
_   table                                                                                                                                                         _
_   Jul 17 12:09:55 756d7002c16e sogod [107]: [WARN] <0x0x55d6e0a221a0[SOGoWebDAVAclManager]> entry '{DAV:}write-content' already exists in DAV permissions tab   _
_   le                                                                                                                                                            _
_   Jul 17 12:09:55 756d7002c16e sogod [107]: 217.129.4.71 "GET /SOGo/so/bruno@nootch.net/Calendar/alarmslist?browserTime=1594987813 HTTP/1.0" 200 63/0 0.042 -   _
_    - 0 - 13                                                                                                                                                     _
_   Jul 17 12:09:55 756d7002c16e sogod [87]: 217.129.4.71 "GET /SOGo/so/bruno@nootch.net/Mail/0/view HTTP/1.0" 200 4941/0 0.336 - - 2M - 14                       _
_   Jul 17 12:09:55 756d7002c16e 2020-07-17 12:09:55.776 sogod[87:87] parseTimeZone: cannot parse time notation 'GMT'                                             _
_   Jul 17 12:09:55 756d7002c16e sogod [87]: 217.129.4.71 "POST /SOGo/so/bruno@nootch.net/Mail/0/folderINBOX/view HTTP/1.0" 200 4298/45 0.155 - - 2M - 14         _
_   Jul 17 12:09:56 756d7002c16e sogod [87]: 217.129.4.71 "POST /SOGo/so/bruno@nootch.net/Mail/unseenCount HTTP/1.0" 200 345/294 0.551 - - 0 - 13

Reproduction of said bug:

Logout, log back in.

System information:

Question	Answer
My operating system	Linux
Is Apparmor, SELinux or similar active?	No
Virtualization technlogy (KVM, VMware, Xen, etc - LXC and OpenVZ are not supported	None
Server/VM specifications (Memory, CPU Cores)	1 vCPU on Vultr, 2GB RAM
Docker Version (`docker version`)	19.03.12, build 48a66213fe
Docker-Compose Version (`docker-compose version`)	1.26.2, build eefe0d31
Reverse proxy (custom solution)	nginx

Output of git diff origin/master, any other changes to the code? If so, please post them.

new file mode 100644
index 00000000..1d678ffa
--- /dev/null
+++ b/data/conf/postfix/mailcow_anonymize_headers.pcre_
@@ -0,0 +1,9 @@
+if /^\s*Received:.*Authenticated sender.*\(Postcow\)/
+/^\s*Received:.*Authenticated sender:(.+)/
+  REPLACE Received: from localhost (localhost [127.0.0.1]) (Authenticated sender:$1
+/^\s*User-Agent/        IGNORE
+/^\s*X-Enigmail/        IGNORE
+/^\s*X-Mailer/          IGNORE
+/^\s*X-Originating-IP/  IGNORE
+/^\s*X-Forward/         IGNORE
+endif

All third-party firewalls and custom iptables rules are unsupported. Please check the Docker docs about how to use Docker with your own ruleset. Nevertheless, iptabels output can help us to help you: iptables -L -vn, ip6tables -L -vn, iptables -L -vn -t nat and ip6tables -L -vn -t nat.

Not using firewall.

DNS problems? Please run docker exec -it $(docker ps -qf name=acme-mailcow) dig +short stackoverflow.com @172.22.1.254 (set the IP accordingly, if you changed the internal mailcow network) and post the output.

151.101.193.69
151.101.129.69
151.101.1.69
151.101.65.69

sardaukar commented 4 years ago

This issue went away when I removed an external Google calendar on my account!

andryyy commented 4 years ago

Oh, that's interesting. You may create an issue with inverse.ca. But I think it is ok, depending on the amount of elements. I don't use external calendars and cannot test it.

mkuron commented 4 years ago

I've seen that too. When you add the calendar, you can select whether you want it to be synced every time you log in. If the calendar contains hundreds of events, that takes a while. It would be nicer if SOGo did that asynchronously, but until it does that, it will delay your login.

andryyy commented 4 years ago

Hm. :/

dragoangel commented 3 years ago

I wrote a half year ago to sogo bug tracker about it. They tried helpinig, but later start to ignore this issue. Actually option: reload calendar on login can work as denial of service 🤦‍♂️: you will see bunch of errors in sogo logs and white screen after login endlessly Here link to Sogo bugtracker: https://sogo.nu/bugs/view.php?id=4939

stale[bot] commented 3 years ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

mailcow / mailcow-dockerized

Long delay on SOGo login with Google calendar subscription #3662