User batch add script failing

I was wondering if anyone could help shed some light on the problem
I’m having with a batch user creation script I’m writing. The rt.log
shows basically a steady stream of ‘Could not create a new user’
errors.

I can see in the extra mysql logging that I turned on that things are
starting off normally for the Principals table portion, but falls off
when it gets to the Users table. Here is a snippet of log for the
creation of one user.

14 Query     set autocommit=1
14 Query     SELECT  * FROM Users WHERE id = '8282828282100011'
14 Query     SELECT  * FROM Users WHERE EmailAddress =

‘devnull.16@metrocast.net’
14 Query set autocommit=0
14 Query INSERT INTO Principals (PrincipalType, Disabled,
ObjectId) VALUES (‘User’, ‘0’, ‘0’)
14 Query SELECT * FROM Principals WHERE id = ‘1237’
14 Query UPDATE Principals SET ObjectId=‘1237’ WHERE id=‘1237’
14 Query SELECT * FROM Users WHERE EmailAddress =
‘devnull.16@metrocast.net’
14 Query rollback
14 Query set autocommit=1

Here’s the hash of user information after it’s been assembled before
it gets passed to the Create method of my RT::User object:

$user fields before create_1 = {
“Comments” => “Autocreate from metrocast customer mysql db”,
“Privileged” => 0,
“City” => “ROCHESTER”,
“RealName” => “METROCAST TEST ACCT HBO ONLY NoHSI”,
“State” => “NH”,
“EmailAddress” => “devnull.16@metrocast.net”,
“Gecos” => 327830,
“HomePhone” => “6039999999”,
“Password” => “placeholderpassword.16”,
“Address1” => “21 JARVIS AVE”,
“Disabled” => 0,
“WorkPhone” => “0000000000”,
“Zip” => “03868”,
“Name” => “8282828282100011”
};

Here is the id and message I get back from the Create method:

$User create result id_1 = 0;
$User create result Message_1 = “Could not create user”;

I threw in some extra debugging output manually into RT/User.pm in the
Create function as well. I can see that when the $principal->Create
method is called, it populates $principal_id correctly. The mysql log
output above shows that the call to $principal->__Set is taking place.
However, the $self->SUPER::Create is definitely not behaving as
expected because $self->Id comes back undefined and I have no idea
why.

I’m running rt-4.0.6 on a CentOS 6.2 server with just the stock
perl-5.10.1. I’ve already successfully done an rtldapimportant to get
my employee accounts all working.

My RT_SiteConfig.pm:

Set($LogToFile, ‘debug’);
Set($LogStackTraces, ‘debug’);
Set( $rtname, ‘rtserver.example.com’);
Set($WebPath, ‘’);
Set($WebBaseURL , ‘https://rtserver.example.com’);
Set($WebImagesURL , $WebPath . ‘/NoAuth/images/’);
Set( $WebDomain, ‘rtserver.example.com’ );
Set(@Plugins, (‘RT::Authen::ExternalAuth’,
‘RT::Extension::LDAPImport’, ‘RT::OnlineDocs’));
Set($ExternalAuthPriority, [
‘Metrocast_LDAP’,
‘Metrocast_LDAP_Customers’,
]
);
Set($ExternalInfoPriority, [
‘Metrocast_LDAP’,
‘Metrocast_LDAP_Customers’
]
);
Set($ExternalServiceUsesSSLorTLS, 0);
Set($AutoCreateNonExternalUsers, 0);
Set($ExternalSettings, {
‘Metrocast_LDAP’ => { ##snipped
‘Metrocast_LDAP_Customers’ => { ##snipped

Here’s the actual script I’m running:

#!/usr/bin/perl

use strict;
use warnings;

use 5.10.0;

use Getopt::Long;

use YAML::Any qw/LoadFile/;

use MC;
use MC::LDAP;
use MC::DB::MySQL;

$|++;

use lib ‘/opt/rt4/lib’;

use RT::Interface::CLI qw(CleanEnv GetCurrentUser loc);

CleanEnv();

use RT;
use RT::Util;

use RT::Tickets;
use RT::CurrentUser;
use RT::CustomField;
use RT::Transaction;

use RT::Config;

RT::LoadConfig();

RT::Init();

Make sure external auth is disabled and autocreate is enabled.

RT->Config->Set( ExternalInfoPriority => [ ] );
RT->Config->Set( Plugins => [‘RT::OnlineDocs’] );
RT->Config->Set( AutoCreate => { Privileged => 0 } );
RT->Config->Set( AutoCreateNonExternalUsers => 1 );

our $opts = LoadFile(‘/root/.dataload.yaml’)
or die “LoadFile error: $!\n”;

our $rtopts = LoadFile(‘/root/.rt.yaml’);

$opts->{conf_filename} = ‘/root/.dataload.conf’;
$opts->{lockfile} = ‘/tmp/.dataload.lock’;
$opts->{debug} = 1;
$opts->{verbose} = 0;
$opts->{test} = 0;

GetOptions( $opts,

                'conf=s',
                'debug!',
                'verbose',
                'test!',
                'q|quiet',
                'db_columns=s@{,}',

);

From my database columns (doing SELECT … AS to match up the names)

my @db_account_fields = qw(
Gecos
Name
RealName
Address1
Address2
City
State
Zip
HomePhone
WorkPhone
);

my $dbgfh = 0;

if ( $opts->{debug} ) {

$dbgfh = FileHandle->new( '/tmp/rt_create_user.debuglog', '>>' )
    or die "Error opening debuglog: $!\n";


print $dbgfh "Begin $0 debug log ----- " . scalar localtime() . "\n";

}

Verify external auth plugins are disabled…

ddump( $dbgfh, ‘RT->Config->Get(Plugins)’, RT->Config->Get(‘Plugins’)
) if $opts->{debug};

ddump( $dbgfh, ‘rt methods’, Class::Inspector->methods( ‘RT’, ‘full’,
‘public’ ) );

my $MCDB = MC::DB::MySQL->new({ opts => $opts, debugfh => $dbgfh });
my $MCL = MC::LDAP->new({ opts => $opts, debugfh => $dbgfh });

my $conf = $MCDB->{conf};

Grab all my customer info

my $customer_accounts = fetch_db_accounts();

die “No RT server url!\n”
unless defined $rtopts->{rt_url} && $rtopts->{rt_url};

die “No RT username!\n”
unless defined $rtopts->{rt_username} && $rtopts->{rt_username};

die “No RT password!\n”
unless defined $rtopts->{rt_password} && $rtopts->{rt_password};

my $counter = 1;

my $User = RT::User->new( $RT::SystemUser );

for ( keys %$customer_accounts ) {

ddump( $dbgfh, 'current_account', $customer_accounts->{$_} ) if

$opts->{debug};

my %user_fields = (
        Disabled      => 0,
        Privileged    => 0,
        EmailAddress  => "devnull.${counter}\@metrocast.net",
        Password      => "placeholderpassword.${counter}",
        Comments      => 'Autocreate from metrocast customer mysql db',
);


for my $field ( @db_account_fields ) {

    ddump( $dbgfh, 'current_field', $field ) if $opts->{debug};

    # Ignore fields that don't have a value
    if ( defined $customer_accounts->{$_}->{$field}
         &&      $customer_accounts->{$_}->{$field} ) {

        ddump( $dbgfh, 'current_field_has_a_value',

$customer_accounts->{$_}->{$field} ) if $opts->{debug};

        $user_fields{$field} = $customer_accounts->{$_}->{$field};

    }

}

ddump( $dbgfh, 'user fields before create', \%user_fields ) if

$opts->{debug};

ddump( $dbgfh, 'user object after new', $User ) if $opts->{debug};

my ( $id, $Message ) = $User->Create( %user_fields );

ddump( $dbgfh, 'User create result id', $id ) if $opts->{debug};
ddump( $dbgfh, 'User create result Message', $Message ) if $opts->{debug};

ddump( $dbgfh, 'user object after create', $User ) if $opts->{debug};
ddump( $dbgfh, 'user object methods', Class::Inspector->methods(

ref $User, ‘full’, ‘public’ ) ) if $opts->{debug};

$counter++;

}

if ( $opts->{debug} ) {
$dbgfh->close;
}

And here’s some rt.log output:

[Wed Jun 27 22:43:04 2012] [info]:
RT::Authen::ExternalAuth::CanonicalizeUserInfo returning Address1: 21
JARVIS AVE, City: ROCHESTER, Comments: Autocreate from metrocast
customer mysql db, Disabled: , EmailAddress: devnull.16@metrocast.net,
Gecos: 327830, HomePhone: 6039999999, Name: 8282828282100011,
Password: placeholderpassword.16, Privileged: , RealName: METROCAST
TEST ACCT HBO ONLY NoHSI, State: NH, WorkPhone: 0000000000, Zip: 03868
(/opt/rt4/local/plugins/RT-Authen-ExternalAuth/lib/RT/Authen/ExternalAuth.pm:651)
Trace begun at /opt/rt6/lib/RT.pm line 250

Log::Dispatch::ANON(‘Log::Dispatch=HASH(0x3ae3d20)’,
‘RT::Authen::ExternalAuth::CanonicalizeUserInfo’, ‘returning’,
‘Address1: 21 JARVIS AVE, City: ROCHESTER, Comments: Autocreate from
metrocast customer mysql db, Disabled: , EmailAddress:
devnull.16@metrocast.net, Gecos: 327830, HomePhone: 6039999999, Name:
8282828282100011, Password: placeholderpassword.16, Privileged: ,
RealName: METROCAST TEST ACCT HBO ONLY NoHSI, State: NH, WorkPhone:
0000000000, Zip: 03868’) called at
/opt/rt4/local/plugins/RT-Authen-ExternalAuth/lib/RT/Authen/ExternalAuth.pm
line 651

RT::Authen::ExternalAuth::CanonicalizeUserInfo(‘RT::User=HASH(0x38af218)’,
‘HASH(0x25302d0)’) called at
/opt/rt4/local/plugins/RT-Authen-ExternalAuth/lib/RT/Authen/ExternalAuth.pm
line 668

RT::Authen::ExternalAuth::ANON(‘RT::User=HASH(0x38af218)’,
‘HASH(0x25302d0)’) called at /opt/rt4/lib/RT/User.pm line 137

RT::User::Create(‘RT::User=HASH(0x38af218)’, ‘Comments’, ‘Autocreate
from metrocast customer mysql db’, ‘Privileged’, 0, ‘City’,
‘ROCHESTER’, ‘RealName’, ‘METROCAST TEST ACCT HBO ONLY NoHSI’,
‘State’, ‘NH’, ‘EmailAddress’, ‘devnull.16@metrocast.net’, ‘Gecos’,
327830, ‘HomePhone’, 6039999999, ‘Password’, ‘placeholderpassword.16’,
‘Address1’, ‘21 JARVIS AVE’, ‘Disabled’, 0, ‘WorkPhone’, 0000000000,
‘Zip’, 03868, ‘Name’, 8282828282100011) called at
rt_create_user_test.pl line 166

[Wed Jun 27 22:43:04 2012] [error]: Could not create a new user -
Comments-Autocreate from metrocast customer mysql
db-RealName-METROCAST TEST ACCT HBO ONLY
NoHSI-City-ROCHESTER-State-NH-EmailAddress-devnull.16@metrocast.net-Gecos-327830-Password-!sha512!G020YZAYl+tYGnAs!1kzwrXghKFKxJPSiK+WnFN5mNcpQactP4F4vcC8x52D0BF7GHGpfU+Yf6mPtw0ZAYh4j8T7c8++KWVaKwXHAAQ-HomePhone-6039999999-Address1-21
JARVIS AVE-Zip-03868-WorkPhone-0000000000-Name-8282828282100011
(/opt/rt4/lib/RT/User.pm:206)
Trace begun at /opt/rt4/lib/RT.pm line 250

Log::Dispatch::ANON(‘Log::Dispatch=HASH(0x3ae3d20)’, ‘Could not
create a new user - Comments-Autocreate from metrocast customer mysql
db-RealName-METROCAST TEST ACCT HBO ONLY
NoHSI-City-ROCHESTER-State-NH-EmailAddress-devnull.16@metrocast.net-Gecos-327830-Password-!sha512!G020YZAYl+tYGnAs!1kzwrXghKFKxJPSiK+WnFN5mNcpQactP4F4vcC8x52D0BF7GHGpfU+Yf6mPtw0ZAYh4j8T7c8++KWVaKwXHAAQ-HomePhone-6039999999-Address1-21
JARVIS AVE-Zip-03868-WorkPhone-0000000000-Name-8282828282100011’)
called at /opt/rt4/lib/RT/User.pm line 206

RT::User::Create(‘RT::User=HASH(0x38af218)’, ‘Comments’, ‘Autocreate
from metrocast customer mysql db’, ‘Privileged’, 0, ‘City’,
‘ROCHESTER’, ‘RealName’, ‘METROCAST TEST ACCT HBO ONLY NoHSI’,
‘State’, ‘NH’, ‘EmailAddress’, ‘devnull.16@metrocast.net’, ‘Gecos’,
327830, ‘HomePhone’, 6039999999, ‘Password’, ‘placeholderpassword.16’,
‘Address1’, ‘21 JARVIS AVE’, ‘Disabled’, 0, ‘WorkPhone’, 0000000000,
‘Zip’, 03868, ‘Name’, 8282828282100011) called at
rt_create_user_test.pl line 166

Any clues why this is failing?

Thanks,

Andy Harrison
public key: 0x67518262

The fact that you see errors like this:

[Wed Jun 27 22:43:04 2012] [info]:
RT::Authen::ExternalAuth::CanonicalizeUserInfo returning Address1: 21
JARVIS AVE, City: ROCHESTER, Comments: Autocreate from metrocast
customer mysql db, Disabled: , EmailAddress: devnull.16@metrocast.net,
Gecos: 327830, HomePhone: 6039999999, Name: 8282828282100011,
Password: placeholderpassword.16, Privileged: , RealName: METROCAST
TEST ACCT HBO ONLY NoHSI, State: NH, WorkPhone: 0000000000, Zip: 03868
(/opt/rt4/local/plugins/RT-Authen-ExternalAuth/lib/RT/Authen/ExternalAuth.pm:651)
Trace begun at /opt/rt6/lib/RT.pm line 250

Means that your code below to clobber Plugins isn’t working, in large
part because the Plugins have already been loaded during LoadConfig
and Init.

use RT::Config;

RT::LoadConfig();

RT::Init();

Make sure external auth is disabled and autocreate is enabled.

RT->Config->Set( ExternalInfoPriority => );
RT->Config->Set( Plugins => [‘RT::OnlineDocs’] );
RT->Config->Set( AutoCreate => { Privileged => 0 } );
RT->Config->Set( AutoCreateNonExternalUsers => 1 );

You may find it easier to cheat and run your script with
RT_SITE_CONFIG=/my/smaller/rt_site_config.pm myscrips.pl
and rt_site_config.pm doesn’t declare any of your ExternalAuth
plugins.

Also, pelase note that AutoCreate only comes into play for users
created in the WebUI, so is irrelevant here. Also,
AutoCreateNonExternalUsers is an RT-Authen-ExternalAuth config option
and is irrelevant if you’re disabling RT-Authen-ExternalAuth.

If you don’t want a second site config, you’ll need to ensure that
your config changes happen before RT loads and parses plugins.

-kevin

The fact that you see errors like this:

[Wed Jun 27 22:43:04 2012] [info]:
RT::Authen::ExternalAuth::CanonicalizeUserInfo returning Address1: 21
JARVIS AVE, City: ROCHESTER, Comments: Autocreate from metrocast
customer mysql db, Disabled: , EmailAddress: devnull.16@metrocast.net,
Gecos: 327830, HomePhone: 6039999999, Name: 8282828282100011,
Password: placeholderpassword.16, Privileged: , RealName: METROCAST
TEST ACCT HBO ONLY NoHSI, State: NH, WorkPhone: 0000000000, Zip: 03868
(/opt/rt4/local/plugins/RT-Authen-ExternalAuth/lib/RT/Authen/ExternalAuth.pm:651)
Trace begun at /opt/rt6/lib/RT.pm line 250

Means that your code below to clobber Plugins isn’t working, in large
part because the Plugins have already been loaded during LoadConfig
and Init.

use RT::Config;

RT::LoadConfig();

RT::Init();

Make sure external auth is disabled and autocreate is enabled.

RT->Config->Set( ExternalInfoPriority => );
RT->Config->Set( Plugins => [‘RT::OnlineDocs’] );
RT->Config->Set( AutoCreate => { Privileged => 0 } );
RT->Config->Set( AutoCreateNonExternalUsers => 1 );

You may find it easier to cheat and run your script with
RT_SITE_CONFIG=/my/smaller/rt_site_config.pm myscrips.pl
and rt_site_config.pm doesn’t declare any of your ExternalAuth
plugins.

Also, pelase note that AutoCreate only comes into play for users
created in the WebUI, so is irrelevant here. Also,
AutoCreateNonExternalUsers is an RT-Authen-ExternalAuth config option
and is irrelevant if you’re disabling RT-Authen-ExternalAuth.

If you don’t want a second site config, you’ll need to ensure that
your config changes happen before RT loads and parses plugins.

-kevin

Oops… I must have corked something when I was cleaning the script
up to post here, I had that taken care of previously. I was just
looking to make sure the LDAP related items weren’t showing up, didn’t
look for that telltale CanonicalizeUserInfo log entry.

Regardless, your suggestion to use the RT_SITE_CONFIG variable is
easier so I did that. It pared down the log output but the it’s still
the same problem.

[Thu Jun 28 18:20:35 2012] [error]: Could not create a new user -
Comments-Autocreate from metrocast customer mysql
db-RealName-METROCAST TEST ACCT HBO ONLY
NoHSI-City-ROCHESTER-State-NH-EmailAddress-devnull.16@metrocast.net-Gecos-327830-Password-!sha512!8LUzx22g0JywKrDy!lz/mt/QovpBky0DSbAjiAg6veGNwsu4ZT2YtR6kwWxa8v3VISHtLOb7wPB271zGL87VgKZIW9LCxgR0bn+ylZA-HomePhone-6039999999-Address1-21
JARVIS AVE-Zip-03868-WorkPhone-0000000000-Name-8282828282100011
(/opt/rt4/lib/RT/User.pm:280)
Trace begun at /opt/rt4/lib/RT.pm line 250

Log::Dispatch::ANON(‘Log::Dispatch=HASH(0x3b1dda0)’, ‘Could not
create a new user - Comments-Autocreate from metrocast customer mysql
db-RealName-METROCAST TEST ACCT HBO ONLY
NoHSI-City-ROCHESTER-State-NH-EmailAddress-devnull.16@metrocast.net-Gecos-327830-Password-!sha512!8LUzx22g0JywKrDy!lz/mt/QovpBky0DSbAjiAg6veGNwsu4ZT2YtR6kwWxa8v3VISHtLOb7wPB271zGL87VgKZIW9LCxgR0bn+ylZA-HomePhone-6039999999-Address1-21
JARVIS AVE-Zip-03868-WorkPhone-0000000000-Name-8282828282100011’)
called at /opt/rt4/lib/RT/User.pm line 280

RT::User::Create(undef, ‘Comments’, ‘Autocreate from metrocast
customer mysql db’, ‘Privileged’, 0, ‘City’, ‘ROCHESTER’, ‘RealName’,
‘METROCAST TEST ACCT HBO ONLY NoHSI’, ‘State’, ‘NH’, ‘EmailAddress’,
‘devnull.16@metrocast.net’, ‘Gecos’, 327830, ‘HomePhone’, 6039999999,
‘Password’, ‘placeholderpassword.16’, ‘Address1’, ‘21 JARVIS AVE’,
‘Disabled’, 0, ‘WorkPhone’, 0000000000, ‘Zip’, 03868, ‘Name’,
8282828282100011) called at rt_create_user_test.pl line 166

So I started chasing down the $self->SUPER::Create from RT::User and
moved onto RT::Record and put some debugging output in there. Inside
RT::Record::Create, the $self->SUPER::Create call gets an expected
value back for $id. If I run a Dumper() directly on the
$self->Load($id), it comes back with ( 1, ‘Found Object’ ) and I
verified that none of the errno cases were matched, though that’s
obvious since $id is a plain scalar with an integer.

Since ref $self shows an RT::Principal object at this stage, I tried a
few of those methods. $self->id shows the expected integer.
$self->IsUser is 1. $self->IsGroup is undefined.
$self->PrincipalType is ‘User’. $self->Disabled is 0.
$self->ObjectId is also 0.

So, after the Load, I made a new user obj:

my $curUserObj = RT::User->new();

But then doing a Dumper( $curUserObj->Load($self->id) ) comes back
with ( 0, “Couldn’t find row” ).

Not sure how to dig deeper at this point. Any suggestions?

Andy Harrison
public key: 0x67518262

Just noticed that ValidateName() sub in RT::Record…

So, disregard this. Works a lot better now that I’m not using our
billing system’s customer account number for the Name.

#facepalm

Andy Harrison
public key: 0x67518262