# horde-imp login fails often making it unusable [SOLVED]

## selig

I have been having trouble for a couple of weeks with horde and horde-imp. I am using imp for login, via imap-ssl-novalidate-cert, the server is localhost running courier-imap. The problem is, the login often takes ages only to tell me in the end that it was unsuccessful. Sometimes it logs me out by itself.

The only thing I can see in the logs is a normal "LOGIN FAILED" or sometimes "LOGIN" and "LOGOUT" from imap.

horde-3.3.8

horde-imp-4.3.7

courier-authlib-0.58

courier-imap-4.0.6-r3

I cannot use newer versions of courier because they lack vpopmail support which I absolutely need! (the vchkpw auth module) They have not been updated for a very long time so I suspect that some horde update must have caused this issue.

I can post some messages from the logs if needed but there is no interesting information there...

Thank you for any suggestions!Last edited by selig on Wed Sep 29, 2010 6:56 pm; edited 1 time in total

----------

## selig

Bump... I am still having issues with this and I absolutely do not know what to do about it. I tried reinstalling horde and creating a clean new configuration - however, it still behaves exactly like before.

Here you can see some debug output:

```

Sep 24 21:10:34 HORDE [debug] [imp] Hook _prefs_change_hook_last_login in application horde not called. [pid 24281 on line 1736 of "/var/www/fugu.example.com/htdocs/horde/lib/Horde.php"]

Sep 24 21:10:34 HORDE [debug] [imp] Hook _prefs_change_hook_vinbox_id in application horde not called. [pid 24281 on line 1736 of "/var/www/fugu.example.com/htdocs/horde/lib/Horde.php"]

Sep 24 21:10:34 HORDE [notice] [imp] Login success for master@example.com [86.49.58.2] to {fugu.example.com:143 [imap/notls]} [pid 24281 on line 307 of "/var/www/fugu.example.com/htdocs/horde/imp/lib/Session.php"]

Sep 24 21:10:34 HORDE [debug] [imp] Hook _prefs_change_hook_last_maintenance in application horde not called. [pid 24281 on line 1736 of "/var/www/fugu.example.com/htdocs/horde/lib/Horde.php"]

Sep 24 21:10:34 HORDE [debug] [imp] Max memory usage: 10223616 bytes [pid 24281 on line 339 of "/var/www/fugu.example.com/htdocs/horde/lib/Horde/Registry.php"]

Sep 24 21:10:34 HORDE [debug] [horde] Max memory usage: 7340032 bytes [pid 24281 on line 339 of "/var/www/fugu.example.com/htdocs/horde/lib/Horde/Registry.php"]

Sep 24 21:10:34 HORDE [error] [imp] FAILED LOGIN for master@example.com [86.49.58.2] to {fugu.example.com:143 [imap/notls]} [pid 24281 on line 139 of "/var/www/fugu.example.com/htdocs/horde/imp/lib/Auth/imp.php"]

Sep 24 21:10:34 HORDE [debug] [turba] Hook _horde_hook_share_init in application horde not called. [pid 24281 on line 1736 of "/var/www/fugu.example.com/htdocs/horde/lib/Horde.php"]

Sep 24 21:10:34 HORDE [debug] [turba] SQL Query by DataTree_sql::getByAttributes(): SELECT c.datatree_id, c.datatree_name FROM horde_datatree c LEFT JOIN horde_datatree_attributes a1 ON a1.datatree_id = c.datatree_id WHERE c.group_uid = ? AND (a1.attribute_name = ? AND a

1.attribute_key = ?)   GROUP BY c.datatree_id, c.datatree_name, c.datatree_order ORDER BY c.datatree_order, c.datatree_name, c.datatree_id, array (

  0 => 'horde.groups',

  1 => 'user',

  2 => 'master@example.com',

) [pid 24281 on line 1249 of "/var/www/fugu.example.com/htdocs/horde/lib/Horde/DataTree/sql.php"]

Sep 24 21:10:34 HORDE [debug] [turba] SQL Query by DataTree_sql::getByAttributes(): SELECT c.datatree_id, c.datatree_name FROM horde_datatree c LEFT JOIN horde_datatree_attributes a1 ON a1.datatree_id = c.datatree_id WHERE c.group_uid = ? AND (a1.attribute_name = ? AND a

1.attribute_value = ?)   GROUP BY c.datatree_id, c.datatree_name, c.datatree_order ORDER BY c.datatree_order, c.datatree_name, c.datatree_id, array (

  0 => 'horde.shares.turba',

  1 => 'owner',

  2 => 'master@example.com',

) [pid 24281 on line 1214 of "/var/www/fugu.example.com/htdocs/horde/lib/Horde/DataTree/sql.php"]

Sep 24 21:10:34 HORDE [debug] [turba] SQL Query by DataTree_sql::getByAttributes(): SELECT c.datatree_id, c.datatree_name FROM horde_datatree c LEFT JOIN horde_datatree_attributes a1 ON a1.datatree_id = c.datatree_id WHERE c.group_uid = ? AND (a1.attribute_name = ? AND a

1.attribute_key = ? AND a1.attribute_value \& ?)   GROUP BY c.datatree_id, c.datatree_name, c.datatree_order ORDER BY c.datatree_order, c.datatree_name, c.datatree_id, array (

  0 => 'horde.shares.turba',

  1 => 'perm_users',

  2 => 'master@example.com',

  3 => 4,

) [pid 24281 on line 1214 of "/var/www/fugu.example.com/htdocs/horde/lib/Horde/DataTree/sql.php"]

Sep 24 21:10:34 HORDE [debug] [turba] SQL Query by DataTree_sql::getByAttributes(): SELECT c.datatree_id, c.datatree_name FROM horde_datatree c LEFT JOIN horde_datatree_attributes a1 ON a1.datatree_id = c.datatree_id WHERE c.group_uid = ? AND (a1.attribute_name = ? AND a

1.attribute_value \& ?)   GROUP BY c.datatree_id, c.datatree_name, c.datatree_order ORDER BY c.datatree_order, c.datatree_name, c.datatree_id, array (

  0 => 'horde.shares.turba',

  1 => 'perm_creator',

  2 => 4,

) [pid 24281 on line 1214 of "/var/www/fugu.example.com/htdocs/horde/lib/Horde/DataTree/sql.php"]

Sep 24 21:10:34 HORDE [debug] [turba] SQL Query by DataTree_sql::getByAttributes(): SELECT c.datatree_id, c.datatree_name FROM horde_datatree c LEFT JOIN horde_datatree_attributes a1 ON a1.datatree_id = c.datatree_id WHERE c.group_uid = ? AND (a1.attribute_name = ? AND a

1.attribute_value \& ?)   GROUP BY c.datatree_id, c.datatree_name, c.datatree_order ORDER BY c.datatree_order, c.datatree_name, c.datatree_id, array (

  0 => 'horde.shares.turba',

  1 => 'perm_default',

  2 => 4,

) [pid 24281 on line 1214 of "/var/www/fugu.example.com/htdocs/horde/lib/Horde/DataTree/sql.php"]

Sep 24 21:10:34 HORDE [debug] [turba] SQL Query by DataTree_sql::_loadById(): SELECT datatree_id, datatree_parents FROM horde_datatree WHERE datatree_id IN (411, 294) AND group_uid = 'horde.shares.turba' ORDER BY datatree_id [pid 24281 on line 340 of "/var/www/fugu.jed.c

z/htdocs/horde/lib/Horde/DataTree/sql.php"]

Sep 24 21:10:34 HORDE [debug] [turba] SQL Query by DataTree_sql::_loadById(): SELECT datatree_id, datatree_name, datatree_parents, datatree_order FROM horde_datatree WHERE datatree_id IN (?, ?, ?, ?) AND group_uid = ? ORDER BY datatree_id, array (

  0 => 294,

  1 => 2,

  2 => 411,

  3 => 0,

  4 => 'horde.shares.turba',

) [pid 24281 on line 373 of "/var/www/fugu.example.com/htdocs/horde/lib/Horde/DataTree/sql.php"]

Sep 24 21:10:34 HORDE [debug] [turba] SQL Query by DataTree_sql::getAttributes(): SELECT datatree_id, attribute_name AS name, attribute_key AS "key", attribute_value AS value FROM horde_datatree_attributes WHERE datatree_id IN (411, 294) [pid 24281 on line 1085 of "/var/

www/fugu.example.com/htdocs/horde/lib/Horde/DataTree/sql.php"]

Sep 24 21:10:34 HORDE [debug] [turba] Hook _prefs_change_hook_columns in application horde not called. [pid 24281 on line 1736 of "/var/www/fugu.example.com/htdocs/horde/lib/Horde.php"]

Sep 24 21:10:34 HORDE [debug] [turba] SQL query by Turba_Driver_sql::_search(): SELECT object_id, owner_id, object_type, object_members, object_uid, object_name, object_email, object_alias, object_homeaddress, object_workaddress, object_homephone, object_workphone, objec

t_cellphone, object_fax, object_title, object_company, object_notes, object_pgppublickey, object_smimepublickey, object_freebusyurl FROM turba_objects WHERE (object_type = ? AND owner_id = ?) [pid 24281 on line 168 of "/var/www/fugu.example.com/htdocs/horde/turba/lib/Driver/s

ql.php"]

Sep 24 21:10:34 HORDE [debug] [horde] Max memory usage: 11010048 bytes [pid 24281 on line 339 of "/var/www/fugu.example.com/htdocs/horde/lib/Horde/Registry.php"]

Sep 24 21:10:34 HORDE [debug] [horde] IMAP errors: Unable to create selectable TCP socket (1025 >= 1024) [pid 24281 on line 175 of "/var/www/fugu.example.com/htdocs/horde/imp/lib/IMAP.php"]

Sep 24 21:10:34 HORDE [debug] [horde] Max memory usage: 6553600 bytes [pid 29939 on line 339 of "/var/www/fugu.example.com/htdocs/horde/lib/Horde/Registry.php"]

Sep 24 21:10:35 HORDE [debug] [horde] Max memory usage: 11796480 bytes [pid 24281 on line 339 of "/var/www/fugu.example.com/htdocs/horde/lib/Horde/Registry.php"]

Sep 24 21:10:35 HORDE [debug] [horde] Max memory usage: 6291456 bytes [pid 30520 on line 339 of "/var/www/fugu.example.com/htdocs/horde/lib/Horde/Registry.php"]

Sep 24 21:10:59 HORDE [error] [imp] FAILED LOGIN for master [86.49.58.2] to {fugu.example.com:143 [imap/notls]} [pid 30520 on line 139 of "/var/www/fugu.example.com/htdocs/horde/imp/lib/Auth/imp.php"]

Sep 24 21:11:40 HORDE [debug] [imp] Max memory usage: 8388608 bytes [pid 658 on line 339 of "/var/www/fugu.example.com/htdocs/horde/lib/Horde/Registry.php"]

Sep 24 21:11:55 HORDE [error] [imp] FAILED LOGIN for master [86.49.58.2] to {fugu.example.com:143 [imap/notls]} [pid 32703 on line 139 of "/var/www/fugu.example.com/htdocs/horde/imp/lib/Auth/imp.php"]

Sep 24 21:11:55 HORDE [debug] [imp] Max memory usage: 7864320 bytes [pid 32703 on line 339 of "/var/www/fugu.example.com/htdocs/horde/lib/Horde/Registry.php"]

Sep 24 21:11:55 HORDE [debug] [imp] IMAP errors: Login failed. Login failed. Login failed. Too many login failures [pid 32703 on line 175 of "/var/www/fugu.example.com/htdocs/horde/imp/lib/IMAP.php"]

Sep 24 21:11:55 HORDE [debug] [imp] Max memory usage: 9175040 bytes [pid 29939 on line 339 of "/var/www/fugu.example.com/htdocs/horde/lib/Horde/Registry.php"]

Sep 24 21:11:55 HORDE [debug] [horde] Max memory usage: 7602176 bytes [pid 29939 on line 339 of "/var/www/fugu.example.com/htdocs/horde/lib/Horde/Registry.php"]

Sep 24 21:11:56 HORDE [debug] [horde] Max memory usage: 6029312 bytes [pid 29939 on line 339 of "/var/www/fugu.example.com/htdocs/horde/lib/Horde/Registry.php"]

```

I only logged in. At 21:10:59 I tried clicking on "Mail" icon in Horde.

I really do not know why it says FAILED LOGIN after a successful login...

----------

## selig

It seems that the problem is in PHP rather than Horde... I tried restoring Horde from backups and it did not help - I tried versions from March which were 100% working.

Is there any problem with this?

```

# emerge -pv php

These are the packages that would be merged, in order:

Calculating dependencies... done!

[ebuild     U ] dev-lang/php-5.2.14 [5.2.13] USE="apache2 berkdb bzip2 calendar cli crypt ctype curl filter ftp gd gdbm hash iconv imap json mhash mysql mysqli ncurses nls pcre pdo pic posix* readline reflection session simplexml snmp soap spell spl sqlite ssl threads tokenizer truetype unicode xml xmlreader xmlrpc xmlwriter xsl zip zlib (-adabas) -bcmath (-birdstep) -cdb -cgi -cjk -concurrentmodphp -curlwrappers -db2 -dbase (-dbmaker) -debug -discard-path -doc -embed% (-empress) (-empress-bcs) (-esoob) -exif (-fdftk) (-firebird) -flatfile -force-cgi-redirect (-frontbase) -gd-external -gmp -inifile -interbase -iodbc -ipv6 -kerberos -kolab -ldap -ldap-sasl -libedit -mcve -msql -mssql -oci8 -oci8-instant-client -odbc -pcntl -postgres -qdbm -recode -sapdb -sharedext -sharedmem -sockets (-solid) -suhosin (-sybase-ct) -sysvipc -tidy -wddx -xpm -yaz (-fastbuild%) (-java-external%) (-sybase%)" 8,852 kB

```

PHP does not log any errors... and the only thing left for me to try is restoring some old version of PHP and trying it. There have been some changes in USE flags in the past months so maybe something caused Horde to stop working and it was not only an upgrade of PHP...

----------

## selig

Problem solved! When I looked at the Horde-imp source code, it was obvious that it gave a "FAILED LOGIN" message for every kind of error when it had trouble communicating with IMAP. I looked further and found out that Horde-imp could not open a port for communicating with IMAP. Then I googled a bit and found some discussion thread about this issue - the real problem was in PHP itself - it uses some unmaintained library for IMAP communication which nobody is willing to fix and it has the limit of 1024 open files per (apache) process. Ulimit does not help in this case, the only option is to bring down the number of open files per Apache process. I removed a few dozens of old virtual host entries from the configuration which had been erased anyway. Now everything is working again!   :Very Happy: 

----------

