Joomla User creation fails

[rouhu]

The creation v2 plugin creates LDAP users ok but not the Joomla users. It gives Joomla error after submitting registration form. Warning Registration failed: There is nothing in the joomla logs.

Thanks, Timo

[ShMaunder]

Hi Timo,

Hmm, think that is a generic error indide of Joomla so will be hard to track down. Just to check, is the auto register switched on in the "user - joomla" plugin? Also, will the Joomla user have a valid group such as registered or does it use the default group from com_users option box? Might also be worth checking the full debug log generated from "SHLog - LDAP" plugin.

[rouhu]

Thanks for the tips but did not help. I can trouble shoot this more if you are able to give some pointers to php files where this could origin. Error appears soon as the plugin "LDAP - User Creation" is activated.

Here is the SHLog: 2014-02-03T19:59:45+00:00 12821 The user 'testuser' has been successfully created. 2014-02-03T19:59:45+00:00 11904 SHLdapEventDebug::onUserBeforeSave called. 2014-02-03T19:59:45+00:00 101 Closed connection. 2014-02-03T19:59:45+00:00 11909 SHLdapEventDebug::onContentPrepareData called. 2014-02-03T19:59:45+00:00 11909 SHLdapEventDebug::onContentPrepareData called. 2014-02-03T19:59:45+00:00 11910 SHLdapEventDebug::onContentPrepareForm called.

[ShMaunder]

Ok, think we need to find out what the array values of $user and $new are in onUserBeforeSave(). Can you insert: print_r($user); print_r($new); die; in /libraries/shmanic/ldap/event/debug.php somewhere in the onUserBeforeSave function. Send over the results either here or via email.

On a side note, I will add something similar into the repo to drop these into the debug logs permanently instead of having to hack them in.

[ShMaunder]

Just to add to the side note; commits a45c51bfa2873a387c92df569fb79b2d8d614726 and d416dbd2823a90600609f23a8de5e8d43ce5fd9a add the $user and $new arrays to the debug logs while obscuring the password.

[rouhu]

Here is the debug output when creating a new user:

2014-02-05T17:01:42+00:00 11951 onUserBeforeSave user array 'array ( 'isRoot' => NULL, 'id' => 0, 'name' => NULL, 'username' => NULL, 'email' => NULL, 'password' => NULL, 'password_clear' => '', 'block' => NULL, 'sendEmail' => 0, 'registerDate' => NULL, 'lastvisitDate' => NULL, 'activation' => NULL, 'params' => NULL, 'groups' => array ( ), 'guest' => 1, 'lastResetTime' => NULL, 'resetCount' => NULL, 'aid' => 0, )', new array 'array ( 'isRoot' => NULL, 'id' => 0, 'name' => 'Test User', 'username' => 'testuser', 'email' => 'timo@yahoo.com', 'password' => 'OBSECURED', 'password_clear' => 'OBSECURED', 'block' => NULL, 'sendEmail' => 0, 'registerDate' => '2014-02-05 17:01:41', 'lastvisitDate' => NULL, 'activation' => NULL, 'params' => '{}', 'groups' => array ( 0 => '2', ), 'guest' => 1, 'lastResetTime' => NULL, 'resetCount' => NULL, 'aid' => 0, 'password2' => 'hello123', 'password1' => 'hello123', 'email1' => 'timo@yahoo.com', 'email2' => 'timo@yahoo.com', )'.

[ShMaunder]

Hmm, not sure about that guest field being true. Is the "Guest User Group" in your com_users options still set to the default of - Guest? Can you authenticate with other LDAP users already in your directory without using the creation tool?

I need to extend the above commit to obscure password[1,2] as well.

I might need to have a brief remote session with you to get to the bottom of what is going on.

[rouhu]

The "Guest User Group" is set to Public. The LDAP authentication works fine. As ITWerx previously mentioned on issue #1 comments the issues is: On first registration attempt only LDAP user is registered and Joomla user not. On second attempt the Joomla user is registered ok. So, to be able to create joomla users the LDAP account must already exists. It does not seem to work all in one go.

Based on the debug log it feels like the sequence of actions is wrong. It tries to look for the LDAP user even before its created.

Entire log when creating new user at joomla admin: 2014-02-06T19:51:21+00:00 11910 SHLdapEventDebug::onContentPrepareForm called. 2014-02-06T19:51:21+00:00 101 Attempting connection to LDAP with host localhost 2014-02-06T19:51:21+00:00 101 Successfully connected to localhost. Setting the following parameters: ldapV3 2014-02-06T19:51:21+00:00 101 Successfully connected. 2014-02-06T19:51:21+00:00 101 Attempt to retrieve user distinguished name using 'uid=jacktest,ou=Users,dc=freecloud,dc=mobi' with direct bind. 2014-02-06T19:51:21+00:00 101 Failed to read direct bind without auth DN uid=jacktest,ou=Users,dc=freecloud,dc=mobi. 2014-02-06T19:51:21+00:00 101 Closed connection. 2014-02-06T19:51:22+00:00 101 Attempting connection to LDAP with host localhost 2014-02-06T19:51:22+00:00 101 Successfully connected to localhost. Setting the following parameters: ldapV3 2014-02-06T19:51:22+00:00 101 Successfully connected. 2014-02-06T19:51:22+00:00 101 Attempt to retrieve user distinguished name using 'uid=jacktest,ou=Users,dc=freecloud,dc=mobi' with direct bind. 2014-02-06T19:51:22+00:00 101 Failed to read direct bind without auth DN uid=jacktest,ou=Users,dc=freecloud,dc=mobi. 2014-02-06T19:51:22+00:00 12821 The user 'jacktest' has been successfully created. 2014-02-06T19:51:22+00:00 11904 SHLdapEventDebug::onUserBeforeSave called. 2014-02-06T19:51:22+00:00 11951 onUserBeforeSave user array 'array ( 'isRoot' => NULL, 'id' => 0, 'name' => NULL, 'username' => NULL, 'email' => NULL, 'password' => NULL, 'password_clear' => '', 'block' => NULL, 'sendEmail' => 0, 'registerDate' => NULL, 'lastvisitDate' => NULL, 'activation' => NULL, 'params' => NULL, 'groups' => array ( ), 'guest' => 1, 'lastResetTime' => NULL, 'resetCount' => NULL, 'aid' => 0, )', new array 'array ( 'isRoot' => NULL, 'id' => 0, 'name' => 'Jack test', 'username' => 'jacktest', 'email' => 'info@testuser.com', 'password' => 'OBSECURED', 'password_clear' => 'OBSECURED', 'block' => '0', 'sendEmail' => '0', 'registerDate' => '', 'lastvisitDate' => '', 'activation' => NULL, 'params' => '{"admin_style":"","admin_language":"","language":"","editor":"","helpsite":"","timezone":""}', 'groups' => array ( 0 => '2', ), 'guest' => 1, 'lastResetTime' => '', 'resetCount' => '0', 'aid' => 0, 'password2' => 'jacktest', 'tags' => NULL, )'. 2014-02-06T19:51:22+00:00 101 Closed connection. 2014-02-06T19:51:22+00:00 11909 SHLdapEventDebug::onContentPrepareData called. 2014-02-06T19:51:22+00:00 11910 SHLdapEventDebug::onContentPrepareForm called. 2014-02-06T19:51:22+00:00 11909 SHLdapEventDebug::onContentPrepareData called.

[ShMaunder]

I was wrong on my last post regarding guest. There are certainly events missing after the onUserBeforeSave. Something must be failing between onUserBeforeSave and onUserAfterSave. Unfortunately, version 2.0 is very new and is unnecessarily complex and inefficient in places such as the user creation (i.e. we see a lot of repeated events and/or a lack of event reporting).

The looking for a LDAP user early in the sequence is actually a sanity check to ensure the user doesn't exist in LDAP first. One of the reasons for this is to prevent a exception from occurring when the LDAP has not been sync'd with Joomla and the resulting actions may delete an existing LDAP user (hence why there is an Delete on Fail option in the user creation plug-in).

I will paste the log of a successful creation from my testing environment:

2014-02-06T23:22:21+00:00       12202   The XML profile is loaded and appears to be valid.
2014-02-06T23:22:41+00:00       11909   SHLdapEventDebug::onContentPrepareData called.
2014-02-06T23:22:41+00:00       11909   SHLdapEventDebug::onContentPrepareData called.
2014-02-06T23:22:41+00:00       11910   SHLdapEventDebug::onContentPrepareForm called.
2014-02-06T23:22:41+00:00       12202   The XML profile is loaded and appears to be valid.
2014-02-06T23:22:41+00:00       101     Attempting connection to LDAP with host ldap2.shmanic.net
2014-02-06T23:22:41+00:00       101     Successfully connected to ldap2.shmanic.net. Setting the following parameters: ldapV3
2014-02-06T23:22:41+00:00       101     Successfully connected.
2014-02-06T23:22:41+00:00       101     Attempt to retrieve user distinguished name using '(uid=testman2)'  with search.
2014-02-06T23:22:41+00:00       101     Closed connection.
2014-02-06T23:22:41+00:00       101     Attempting connection to LDAP with host ldap2.shmanic.net
2014-02-06T23:22:41+00:00       101     Successfully connected to ldap2.shmanic.net. Setting the following parameters: ldapV3
2014-02-06T23:22:41+00:00       101     Successfully connected.
2014-02-06T23:22:41+00:00       101     Attempt to retrieve user distinguished name using '(uid=testman2)'  with search.
2014-02-06T23:22:41+00:00       12821   The user 'testman2' has been successfully created.
2014-02-06T23:22:41+00:00       11904   SHLdapEventDebug::onUserBeforeSave called.
2014-02-06T23:22:41+00:00       11951   onUserBeforeSave user array 'array ( 'isRoot' => NULL, 'id' => 0, 'name' => NULL, 'username' => NULL, 'email' => NULL, 'password' => NULL, 'password_clear' => '', 'block' => NULL, 'sendEmail' => 0, 'registerDate' => NULL, 'lastvisitDate' => NULL, 'activation' => NULL, 'params' => NULL, 'groups' => array ( ), 'guest' => 1, 'lastResetTime' => NULL, 'resetCount' => NULL, 'aid' => 0, )', new array 'array ( 'isRoot' => NULL, 'id' => 0, 'name' => 'Test Man2', 'username' => 'testman2', 'email' => 'testman2@example.com', 'password' => '__OBSECURED__', 'password_clear' => '__OBSECURED__', 'block' => NULL, 'sendEmail' => 0, 'registerDate' => '2014-02-06 23:22:41', 'lastvisitDate' => NULL, 'activation' => NULL, 'params' => '{}', 'groups' => array ( 0 => '2', ), 'guest' => 1, 'lastResetTime' => NULL, 'resetCount' => NULL, 'aid' => 0, 'password2' => 'hello321', 'password1' => 'hello321', 'email1' => 'testman2@example.com', 'email2' => 'testman2@example.com', 'ldap_profile' => array ( 'telephoneNumber' => '.54645645', 'description' => '', ), )'.
2014-02-06T23:22:41+00:00       10634   Successfully committed add operation for user 'testman2' with attributes array ( 'telephoneNumber' => array ( 0 => '.54645645', ), ).
2014-02-06T23:22:41+00:00       11905   SHLdapEventDebug::onUserAfterSave called.
2014-02-06T23:22:41+00:00       12221   Attempting to sync LDAP user profile for 'testman2'.
2014-02-06T23:22:41+00:00       12225   Updated one or more LDAP user profile fields in the Joomla database for 'testman2' with result Success.
2014-02-06T23:22:41+00:00       12224   Updated LDAP user profile for 'testman2'.
2014-02-06T23:22:43+00:00       101     Closed connection.
2014-02-06T23:22:43+00:00       11909   SHLdapEventDebug::onContentPrepareData called.
2014-02-06T23:22:43+00:00       11910   SHLdapEventDebug::onContentPrepareForm called.

I was using the default example user creation XML though I also had several other plug-ins such as the profile enabled.

Over the weekend, I'll look into what happens between events 11951 and 10634. It is either during those two events or just after that the user is saved to the Joomla database.

[ShMaunder]

Bug confirmed.

The SHLdapHelper::triggerEvent() method was modified to include both BOOLEAN and empty return values. Thought I had updated all the triggerEvent calls to deal with the change, but at least one was missed in SHLdapEventBouncer: if (SHLdapHelper::triggerEvent('onUserBeforeSave', array($user, $isNew, $new))) will only proceed if true, but actually triggerEvent is successful with either empty or true returns.

Needs to be changed to: if (SHLdapHelper::triggerEvent('onUserBeforeSave', array($user, $isNew, $new)) !== false)

As a work around before next release, "LDAP - Profile" can be enabled as it returns a true value hence why this wasn't picked up during testing.

[ShMaunder]

Fixed in branch "2.0.x". Thanks for reporting.

Closing.