I've noticed what may be a bug. In "Recent Log messages" you can see 2 instances of "Session opened for ..." for each user that logs in. When I have the ldap_authorization_drupal_role module enabled, I can see the watchdog output messages (it's set at DEBUG) for ldap_authorization proceed in sequence again after the 2nd "Session opened for" message (the 2nd usage of user_login_submit() function).

The 2nd time that the messages show, the ldap_authorization consumer behavior begins anew. I've tracked this through more watchdog messages. Unfortunately, this can result in PHP errors with some code that I'm writing. It's entirely possible that these errors are my doing, but the fact remains that user_login_submit() is called twice.

I don't mean to sound upset, I love the way this module is being developed and it's already been pretty useful to me. I just wanted to point this out in the hopes that it can be confirmed so I don't feel crazy anymore!

Comments

johnbarclay’s picture

johnbarclay commented

Thanks. This is exactly what this module needs. More people looking at the innards of the code. All the simpletests and installation won't find such errors. Here are my initial thoughts:

user_login_submit() is likely only called once by ldap_authentication, at the end of the long _ldap_authentication_user_login_authenticate_validate() function.

?? do you think its being called by ldap_authentication and ldap_authorization 2x??

In the same file, I've had to work around a bug in core (http://drupal.org/node/1022362) where the user_login_authenticate_validate() function will ignore successful authentications by other modules, despite $form_state['uid'] being set. Until the bug is fixed (and its getting no love), I moved the user_login_authenticate_validate() function to the beginning of the sequence so that it doesn't submit the user_login_submit() a second time.

?? Is it possible your code is altering this order or successfully authenticating the user, but not setting $form_state['uid']??

I'll look more closely at this also and see if I can recreate the double call.

if (@in_array('user_login_authenticate_validate', $form['#validate'])) {
    $new_validation_sequence = array();
    foreach ($form['#validate'] as $validate_function_name) {
      if ($validate_function_name == 'user_login_authenticate_validate') {
        if ($auth_conf->authenticationMode == LDAP_AUTHENTICATION_MIXED) {
         // if mixed mode, allow drupal authentication first
          $new_validation_sequence[] = 'user_login_authenticate_validate';
          $new_validation_sequence[] = 'ldap_authentication_user_login_authenticate_validate';
        }
        elseif ($auth_conf->authenticationMode == LDAP_AUTHENTICATION_EXCLUSIVE) {
         // see drupal.org/node/1009990 and drupal.org/node/1022362 change back when fixed.
          $new_validation_sequence[] = 'user_login_authenticate_validate';
          $new_validation_sequence[] = 'ldap_authentication_user_login_authenticate_validate';
        }
        else { // misconfigured ldap authentication, restore to original validation sequence
        $new_validation_sequence[] = 'user_login_authenticate_validate';
        }
      }
      else {
        $new_validation_sequence[] = $validate_function_name;
      }
    }
  $form['#validate'] = $new_validation_sequence;

I

dayer4b’s picture

dayer4b commented

I threw a debug_backtrace() into watchdog in user.module to see what functions were calling user_login_submit() each time. This is without my module enabled, only ldap_authorization_drupal_role is being used as a Consumer.

first time:

backtrace:
file: [drupal-root]/modules/user/user.module
line: 2233
function: user_login_finalize
file: [drupal-root]/sites/all/modules/ldap/ldap_authentication/ldap_authentication.inc
line: 411
function: user_login_submit
file: [drupal-root]/sites/all/modules/ldap/ldap_authentication/ldap_authentication.module
line: 306
function: _ldap_authentication_user_login_authenticate_validate
file: [drupal-root]/includes/form.inc
line: 1390
function: ldap_authentication_user_login_authenticate_validate
file: [drupal-root]/includes/form.inc
line: 1331
function: form_execute_handlers
file: [drupal-root]/includes/form.inc
line: 1084
function: _form_validate
file: [drupal-root]/includes/form.inc
line: 819
function: drupal_validate_form
file: [drupal-root]/includes/form.inc
line: 350
function: drupal_process_form
file: [drupal-root]/includes/form.inc
line: 188
function: drupal_build_form
file: [drupal-root]/modules/user/user.module
line: 1380
function: drupal_get_form
file: 
line: 
function: user_block_view
file: [drupal-root]/includes/module.inc
line: 793
function: call_user_func_array
file: [drupal-root]/modules/block/block.module
line: 828
function: module_invoke
file: [drupal-root]/modules/block/block.module
line: 658
function: _block_render_blocks
file: [drupal-root]/modules/block/block.module
line: 316
function: block_list
file: [drupal-root]/modules/block/block.module
line: 269
function: block_get_blocks_by_region
file: [drupal-root]/includes/common.inc
line: 5480
function: block_page_build
file: [drupal-root]/includes/common.inc
line: 2536
function: drupal_render_page
file: [drupal-root]/includes/common.inc
line: 2431
function: drupal_deliver_html_page
file: [drupal-root]/includes/menu.inc
line: 516
function: drupal_deliver_page
file: [drupal-root]/index.php
line: 22
function: menu_execute_active_handler

second time:

backtrace:
file: [drupal-root]/modules/user/user.module
line: 2233
function: user_login_finalize
file: [drupal-root]/includes/form.inc
line: 1390
function: user_login_submit
file: [drupal-root]/includes/form.inc
line: 830
function: form_execute_handlers
file: [drupal-root]/includes/form.inc
line: 350
function: drupal_process_form
file: [drupal-root]/includes/form.inc
line: 188
function: drupal_build_form
file: [drupal-root]/modules/user/user.module
line: 1380
function: drupal_get_form
file: 
line: 
function: user_block_view
file: [drupal-root]/includes/module.inc
line: 793
function: call_user_func_array
file: [drupal-root]/modules/block/block.module
line: 828
function: module_invoke
file: [drupal-root]/modules/block/block.module
line: 658
function: _block_render_blocks
file: [drupal-root]/modules/block/block.module
line: 316
function: block_list
file: [drupal-root]/modules/block/block.module
line: 269
function: block_get_blocks_by_region
file: [drupal-root]/includes/common.inc
line: 5480
function: block_page_build
file: [drupal-root]/includes/common.inc
line: 2536
function: drupal_render_page
file: [drupal-root]/includes/common.inc
line: 2431
function: drupal_deliver_html_page
file: [drupal-root]/includes/menu.inc
line: 516
function: drupal_deliver_page
file: [drupal-root]/index.php
line: 22
function: menu_execute_active_handler

EDIT:

I put the debug_backtrace() into the user_login_finalize() function just prior to the "Session opened for ..." watchdog message. I don't see any mention of the LDAP modules in the second backtrace, but I know that with the LDAP module disabled entirely, this doesn't happen.

EDIT:

I simplified the file paths so it's easier to read the backtrace.

johnbarclay’s picture

johnbarclay commented

So the second time is the bug.

perhaps I need to clear the $form['#submit'] array when I do the fake submit around here:

  $fake_form_state['uid'] = $account->uid;

  user_login_submit(array(), $fake_form_state);
  global $user;
  $form_state['uid'] = $user->uid;
  return;

I don't see a good way to resolve this until the bug in core is fixed (http://drupal.org/node/1009990)

johnbarclay’s picture

johnbarclay commented
Version: 7.x-1.0-beta1 » 7.x-1.x-dev
johnbarclay’s picture

johnbarclay commented
Priority: Normal » Minor
johnbarclay’s picture

johnbarclay commented
Status: Active » Closed (won't fix)