Page MenuHomePhorge

Login no longer possible after update
Closed, ResolvedPublic

Description

Hello everyone,

after our nightly maintenance all updated kolab instances show the same problem:
Login into roundcube is no longer possible. The request on /?_task=login is aborted after a minute and nginx terminates the connection with status 504. The update afaik only changed guam-libs (0.9.8-1) over (0.9.7-3) and erlang-eimap (0.4.3-1.1) over (0.4.2-2.1). So I suspect the error to be there!?

Could you please check you most recent commits for any changes that might cause this error? Is thee a way to further debug and provide more information for you?

Thanks a lot
Sebastian

Test login

  • Trying 127.0.0.1...
  • TCP_NODELAY set
  • Expire in 200 ms for 4 (transfer 0x563ebc0f1a90)
  • Connected to localhost (127.0.0.1) port 10000 (#0)

POST /?_task=login HTTP/1.1
Host: localhost:10000
User-Agent: curl/7.64.0
Accept: */*
Cookie: roundcube_sessid=6253p3m28lpb0ce6qngk3i5bib
Content-Length: 108
Content-Type: application/x-www-form-urlencoded

  • upload completely sent off: 108 out of 108 bytes

Expected results:
On systems with the software from yesterday these requests still work fine. Login is possible. iRony works.
Expected login Status 302 immediately

Actual results:
On the updated systems, when trying to log in (or get something from iRony) we get a 504 from nginx (which uses php-fpm 7.3):

RESP (1 minute later):
HTTP/1.1 504 Gateway Time-out
<html>
<head><title>504 Gateway Time-out</title></head>
<body>
<center><h1>504 Gateway Time-out</h1></center>
<hr><center>nginx/1.19.4</center>
</body>
</html>

Other tests
kolab lm is working
testsaslauthd -u cyrus-admin -p <<cyrus_password>>
kolab list-mailbox-metadata user/admin@testing.it
kolab-webadmin ist working
cyrus via imap is working

Versions:
We're running on Debian 10.
APT Packages & PHP Includes are pasted to https://git.kolab.org/P58

dpkg -l pykolab

Desired=Unknown/Install/Remove/Purge/Hold

Status=Not/Inst/Conf-files/Unpacked/halF-conf/Half-inst/trig-aWait/Trig-pend
/ Err?=(none)/Reinst-required (Status,Err: uppercase=bad)
/ Name Version Architecture Description

+++-==============-===============-============-====================================
ii pykolab 0.8.18-0~kolab2 all Kolab Groupware daemon and utilities

Relevant log snippets:
/var/log/mail.log
Nov 6 11:17:20 apps cyrus/imaps[12438]: starttls: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits reused) no authentication
Nov 6 11:17:20 apps cyrus/imaps[15925]: Option 'ldap_servers' is deprecated in favor of 'ldap_uri' since version 2.5.0.

/var/log/dirsrv/slapd-apps/access
[06/Nov/2020:11:17:20.371875269 +0100] conn=62 fd=68 slot=68 connection from 127.0.0.1 to 127.0.0.1
[06/Nov/2020:11:17:20.372244083 +0100] conn=62 op=0 BIND dn="uid=kolab-service,ou=Special Users,dc=testing,dc=it" method=128 version=3
[06/Nov/2020:11:17:20.409440751 +0100] conn=62 op=1 SRCH base="cn=config" scope=2 filter="(objectClass=vlvsearch)" attrs="* aci"
[06/Nov/2020:11:17:20.410575881 +0100] conn=62 op=1 RESULT err=0 tag=101 nentries=0 etime=0.0001387866
[06/Nov/2020:11:17:20.410919611 +0100] conn=62 op=2 SRCH base="ou=People,dc=testing,dc=it" scope=2 filter="(&(objectClass=inetorgperson)(|(uid=admin)(mail=admin@testing.it)(alias=admin@testing.it)))" attrs="displayName mail alias nsRoleDN uid nsUniqueId"
[06/Nov/2020:11:17:20.411439590 +0100] conn=62 op=2 RESULT err=0 tag=101 nentries=1 etime=0.0000682918
[06/Nov/2020:11:17:20.418621146 +0100] conn=62 op=0 RESULT err=0 tag=97 nentries=0 etime=0.0046576307 dn="uid=kolab-service,ou=special users,dc=testing,dc=it"
[06/Nov/2020:11:18:21.537415066 +0100] conn=62 op=3 UNBIND
[06/Nov/2020:11:18:21.537517075 +0100] conn=62 op=3 fd=68 closed - U1

nginx log
127.0.0.1 - - [06/Nov/2020:11:18:20 +0100] "POST /?_task=login HTTP/1.0" 499 0 "https://orga.testing.it/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/83.0.4103.122 Safari/537.36"

No entries in php-fpm log or pykolab.log.

Details

Ticket Type
Task

Event Timeline

transcending.it updated the task description. (Show Details)
transcending.it updated the task description. (Show Details)

I did some more testing with roundcube debug on:

log/roundcube/error.log
[06-Nov-2020 23:28:10,792415 +0100]: <c11pjd4t> IMAP Error: Login failed for admin@testing.it against localhost from 127.0.0.1(X-Real-IP: XXX). Failed to send LOGIN command in /usr/share/roundcubemail/program/lib/Roundcube/rcube_imap.php on line 200 (POST /?_task=login&_action=login)

log/roundcube/imap.log
06-Nov-2020 23:27:10,706912 +0100]: <c11pjd4t> [BCA1] Connecting to tls://localhost:143...
[06-Nov-2020 23:27:10,732441 +0100]: <c11pjd4t> [BCA1] S: * OK [CAPABILITY IMAP4rev1 STARTTLS LITERAL+ ID ENABLE SASL-IR LOGINDISABLED] apps.testing.it Cyrus IMAP 3.0.8-Debian-3.0.8-6+deb10u4 server ready
[06-Nov-2020 23:27:10,732705 +0100]: <c11pjd4t> [BCA1] C: A0001 STARTTLS
[06-Nov-2020 23:27:10,733497 +0100]: <c11pjd4t> [BCA1] S: A0001 OK Begin TLS negotiation now
[06-Nov-2020 23:27:10,739310 +0100]: <c11pjd4t> [BCA1] C: A0002 CAPABILITY

log/roundcube/userlogins.log
[06-Nov-2020 23:28:11,799921 +0100]: <c11pjd4t> Failed login for admin@testing.it from 127.0.0.1(X-Real-IP: 37.201.7.220,X-Forwarded-For: 37.201.7.220) in session c11pjd4tqknaca8e (error: -2)

log/roundcube/ldap.log
[06-Nov-2020 23:27:10,665946 +0100]: <c11pjd4t> C: Connect [localhost:389]
[06-Nov-2020 23:27:10,666308 +0100]: <c11pjd4t> S: OK
[06-Nov-2020 23:27:10,666447 +0100]: <c11pjd4t> C: Bind [dn: uid=kolab-service,ou=Special Users,dc=testing,dc=it]
[06-Nov-2020 23:27:10,703147 +0100]: <c11pjd4t> S: OK
[06-Nov-2020 23:27:10,703426 +0100]: <c11pjd4t> C: Search base dn: [ou=People,dc=testing,dc=it] scope [sub] with filter [(&(objectclass=inetorgperson)(|(uid=admin)(mail=admin@testing.it)(alias=admin@testing.it)))]
[06-Nov-2020 23:27:10,703504 +0100]: <c11pjd4t> C: Search base dn: [cn=config] scope [sub] with filter [(objectclass=vlvsearch)]
[06-Nov-2020 23:27:10,704881 +0100]: <c11pjd4t> S: 0 record(s) found
[06-Nov-2020 23:27:10,705010 +0100]: <c11pjd4t> Using function ldap_search on scope sub ($ns_function is ldap_search)
[06-Nov-2020 23:27:10,705069 +0100]: <c11pjd4t> C: (Without VLV) Setting a filter of (&(objectclass=inetorgperson)(|(uid=admin)(mail=admin@testing.it)(alias=admin@testing.it)))
[06-Nov-2020 23:27:10,705128 +0100]: <c11pjd4t> Executing search with return attributes: array (

0 => 'displayname',
1 => 'mail',
2 => 'alias',
3 => 'nsroledn',
4 => 'uid',
5 => 'nsuniqueid',

)
[06-Nov-2020 23:27:10,705785 +0100]: <c11pjd4t> S: 1 record(s) found
[06-Nov-2020 23:28:11,810905 +0100]: <c11pjd4t> C: Close

Hello folks,
good news. I managed to restore functionality on my systems with a workaround. I just copied the old versions of guam-libs and erlang-eimap and adjusted it's executable /usr/sbin/guam . Afterwards login is possible again and iRony is working. The old and new versions will reside next to each other in the libs folder. Any update of guam will disable the workaround but leave the old versions around so we have to delete them then.
Unfortunately I'm not an erlang programmer nor understanding the whole architecture well enough to actually provide a fix for the most recent version.
But now that we know the bug is definitely in one of these two packages, maybe someone else can?
Have a nice weekend

My ansible script to restore functionality:

- name: Copy old versions
  unarchive:
    src: files/guam-9.7.tgz
    dest: /usr/lib/erlang/lib/

- name: Replace version in executable
  lineinfile:
    path: /usr/sbin/guam
    line: "exec /usr/lib/erlang/lib/kolab_guam-0.9.7/bin/guam $*"
    regexp: "^exec.*"

- name: Restart guam
  service:
    name: guam
    state: restarted

I uploaded the previous guam 0.9.7-3 and erlang-eimap 0.4.2-2.1 here from DEBIAN 10 for those of you who don't have access anymore. But I strongly suggest to take any software only from trusted sources (i.e. your own machines - or maybe the kolab devs will upload old versions to the kolab repo so we can use apt).

Thanks for testing! I am not firm with ansible and got problems to follow your instructions...

I copied both folders from your tgz into /usr/lib/erlang/lib.
Then I copied /usr/lib/erlang/lib/kolab_guam-0.9.7/bin/guam to /usr/sbin/guam and restarted guam, but it failed to start.

I just wonder that /usr/sbin/guam (Version 0.9.8) is 66 bytes only and /usr/lib/erlang/lib/kolab_guam-0.9.7/bin/guam has 24770 bytes.

What do I do wrong?

Hi Sven,
Ansible lineinfile only means to change one line matching the regex. So the file /usr/sbin/guam is not a copy of the executable but just plain text marked as executable:

#!/bin/bash
exec /usr/lib/erlang/lib/kolab_guam-0.9.7/bin/guam $*

Hope this works now :)

I am sorry, but I still don't get it work on my ubuntu server.

exec /usr/lib/erlang/lib/kolab_guam-0.9.7/bin/guam start

is giving me

/usr/lib/erlang/lib/kolab_guam-0.9.7/bin/guam: 543: /usr/lib/erlang/lib/kolab_guam-0.9.7/bin/guam: /usr/lib/erlang/erts-10.2.4/bin/run_erl: not found

erts-9.2 is on my system, but 10.2.4 isn't? Do you got 10.2.?

Do you got any idea what I am doing wrong?

I made a link from erts-9.2 to erts-10.2.4 and tested

exec /usr/lib/erlang/lib/kolab_guam-0.9.7/bin/guam restart
Node 'kolab_guam@127.0.0.1' not responding to pings.

I'll have a look when I get back later. For now I just wanted to mention again that I'm using Debian so maybe my solution might not work at all un Ubuntu!

I guess you do not have Ubuntu 18.04 and your guam version is compiled with other versions.
I'll see tomorrow if I find a version of one of my backups to copy it.

Let me know if you have another idea. Thanks for your help!

Hello,

Same problem on Centos 7 (Login no longer possible after update).

However, transcending.it’s trick is working well. Thanks!

transcending.it, you are my hero!

My problem has been that I am using ubuntu18.04 and I took your uploaded files which NOT match to my system!

After getting guam-0.9.7 and eimap-0.4.2 out of my backup's, it is working now as well.

Thanks a lot for your help!

@sven.wtal erts-10.2.4 was indeed on my system. Glad that you found a working backup.
@SebastienWeber you're wecome

Btw. I'm testing the services first on a test system (testing.it from the logs - test cases taken from https://docs.kolab.org/administrator-guide/verifying-the-installation.html).

But this case was not tested before though it's pretty simple to test even on the CLI:

curl -v https://<<kolab>>/ | grep -E "Set-Cookie|_token"
curl -v -X POST --cookie "roundcube_sessid=<<from set-cookie>>" -d '_token=<<from _token>>&_task=login&_action=login&_user=admin&_pass=<<password>>' https://<<kolab>>/?_task=login

As Ansible:

- name: Test nginx/roundcube/php
  uri:
    url: https://{{kolab_subdom}}.{{domain_name}}/
    return_content: yes
  register: login_page

- name: Get login token
  set_fact:
    token: "{{login_page.content | regex_findall('_token\" value=\"(.*)\"') | first }}"

- name: Test roundcube login
  uri:
    url: https://{{kolab_subdom}}.{{domain_name}}/?_task=login
    method: POST
    headers:
      Cookie: "{{ login_page.cookies_string }}"
    body:
      _task: login
      _action: login
      _user: admin
      _pass: "{{password}}"
      _token: "{{token}}"
    body_format: form-urlencoded
    status_code: 302
    return_content: no
    follow_redirects: "no"
    timeout: 10
  no_log: True

Make a downgrade to guam 0.9.5 and erlang-eimap-0.4.0 on CentOS 7

See here

Thanks armageddon.
It works fine.

Please note that -nodeps in the command line should have two horizontal - in front. So rpm --nodeps

I uploaded the previous guam 0.9.7-3 and erlang-eimap 0.4.2-2.1 here from DEBIAN 10 for those of you who don't have access anymore. But I strongly suggest to take any software only from trusted sources (i.e. your own machines - or maybe the kolab devs will upload old versions to the kolab repo so we can use apt).

I second this proposal, for the time being uploading the older versions in the kolab repo would be a solution to make our systems usable again...

sicherha raised the priority of this task from Needs Triage to Unbreak Now!.Nov 10 2020, 9:56 PM
sicherha subscribed.

Do Guam's log files, which can commonly be found under /var/log/guam/, provide any helpful clues as to what is going wrong here?

I managed to restore an older backup and retrieve kolab_guam-0.9.7 and eimap-0.4.2 (Debian 9 amd64), and following @transcending.it advice I have my system up and running again. Just in case someone can benefit and save some time, I am uploading them here...


Have a look on this repository.

Thank you! Unfortunately I saw your message only after I had restored the library files from an old backup... thanks anyway!

emunson subscribed.

I opened T6073 but the packages linked by @armageddon are a work around for now. My issue is a duplicate of this one.

Do Guam's log files, which can commonly be found under /var/log/guam/, provide any helpful clues as to what is going wrong here?

The logs stayed empty for me despite using higher log levels (as documented in https://docs.kolab.org/administrator-guide/verifying-the-installation.html#troubleshooting-for-http-based-services). But I did not find the switch for guam log levels.

But looking at what actually changed (https://obs05.kolabsys.com/package/rdiff/Kolab:16/erlang-eimap?linkrev=base&rev=17) I see that in erlang-eimap-0.4.2.tar.gz/src/eimap.erl -> erlang-eimap-0.4.3.tar.gz/src/eimap.erl some kind of throttle was implemented. To me this kind of fits the symptoms of the service just not answering without an error. But again, I can't program Erlang so maybe I might be totally wrong.

@sicherha T6073 contain logs from my install as well as a CentOS install

Update for guam on Centos 7 this morning : no more error with roundcube login.
(Guam : 0.9.8 / 2.1.el7.kolab_16)

Ubuntu updated to guam-0.9.8-2 and my login problem is also solved.