[Support] Event listeners are not called during import

[starlord-wst]

Environment:

• LDAP Server Type: ActiveDirectory
• LdapRecord-Laravel Major Version: v3
• PHP Version: 8.2.10
• Laravel version: v10.15.0

Hey @stevebauman,

After carefully reading both the core and Laravel version's documentation I implemented some listener classes that I'd use to log data during user import from AD. The reason I'm doing this is that I need more detailed logs than the builtin logger is providing.

I'm not sure if it's a bug or I missed something. The issue I'm experiencing is that the event listeners I registered never seem to be called.

I use the following service provider which lives in app/Providers/LdapEventServiceProvider.php

<?php

namespace App\Providers;

use LdapRecord\Container;
use Illuminate\Support\ServiceProvider;
use Illuminate\Support\Facades\Log;

class LdapEventServiceProvider extends ServiceProvider
{
    /**
     * The LDAP event listener mappings for the application.
     *
     * @return array
     */
    protected $listen = [
        \LdapRecord\Laravel\Events\Import\Started::class => [
            \App\Ldap\Listeners\ImportStarted::class
        ],
        \LdapRecord\Laravel\Events\Import\Saved::class => [
            \App\Ldap\Listeners\ObjectModified::class
        ],
        \LdapRecord\Laravel\Events\Import\Restored::class => [
            \App\Ldap\Listeners\ObjectRestored::class
        ],
        \LdapRecord\Laravel\Events\Import\Deleted::class => [
            \App\Ldap\Listeners\ObjectDeleted::class
        ],
        \LdapRecord\Laravel\Events\Import\ImportFailed::class => [
            \App\Ldap\Listeners\ObjectFailed::class
        ],
        \LdapRecord\Laravel\Events\Import\DeletedMissing::class => [
            \App\Ldap\Listeners\ImportDeletedMissing::class
        ],
        \LdapRecord\Laravel\Events\Import\Completed::class => [
            \App\Ldap\Listeners\ImportCompleted::class
        ],
    ];

    /**
     * Register the application LDAP event listeners.
     *
     * @return void
     */
    public function boot()
    {
        Log::info('----- Provider boot -----');
        $dispatcher = Container::getDispatcher();

        foreach ($this->listen as $event => $listeners) {
            foreach (array_unique($listeners) as $listener) {
                Log::info('Registering listener: ' . $event . ' - ' . $listener);
                $dispatcher->listen($event, $listener);
            }
        }
    }
}

The above provider is registered in config/app.php as follows:

'providers' => ServiceProvider::defaultProviders()->merge([
        /*
         * Package Service Providers...
         */
        Kyslik\ColumnSortable\ColumnSortableServiceProvider::class,

        /*
         * Application Service Providers...
         */
        App\Providers\AppServiceProvider::class,
        App\Providers\AuthServiceProvider::class,
        // App\Providers\BroadcastServiceProvider::class,
        App\Providers\EventServiceProvider::class,
        App\Providers\RouteServiceProvider::class,
        App\Providers\LdapEventServiceProvider::class,
    ])->toArray(),

One of my listeners look like this and I'd expected that it's being called at start even if one of LDAP/AD users fail to be imported during the process. app/Ldap/Listeners/ImportStarted.php:

<?php

namespace App\Ldap\Listeners;

use LdapRecord\Laravel\Events\Import\Started;
use App\Models\LdapImportLog;
use Illuminate\Support\Facades\Log;

class ImportStarted
{
    public function __construct()
    {
        Log::info('Construct');
    }

    public function handle(Started $event)
    {
        Log::info('Handle: ' . $event);
        $ldapImportLog = new LdapImportLog;
        $ldapImportLog->message = 'Import started';
        $ldapImportLog->save();
    }
}

(Please notice the log statements I inserted in the boot, construct and handle methods.)

When calling php artisan ldap:import users --filter "(memberOf=CN=Administrators,CN=Builtin,DC=iitest,DC=local)" the import starts and ends succesfully, saying Successfully imported / synchronized [1] user(s).

In the logs generated by the library during import I see that the import is really happening and I see the log message from the boot method about registering the listeners, but I don't see the message that the listerer is trying to log both in its constructor and handle method. And my ldap_import_logs table which I'd expect to be filled in the handle method of the listener is empty.

Part of an import log (the one that the library does) from an import:

[2023-10-02 16:58:50] local.INFO: ----- Provider boot -----  
[2023-10-02 16:58:50] local.INFO: Registering listener: LdapRecord\Laravel\Events\Import\Started - App\Ldap\Listeners\ImportStarted  
[2023-10-02 16:58:50] local.INFO: Registering listener: LdapRecord\Laravel\Events\Import\Saved - App\Ldap\Listeners\ObjectModified  
[2023-10-02 16:58:50] local.INFO: Registering listener: LdapRecord\Laravel\Events\Import\Restored - App\Ldap\Listeners\ObjectRestored  
[2023-10-02 16:58:50] local.INFO: Registering listener: LdapRecord\Laravel\Events\Import\Deleted - App\Ldap\Listeners\ObjectDeleted  
[2023-10-02 16:58:50] local.INFO: Registering listener: LdapRecord\Laravel\Events\Import\ImportFailed - App\Ldap\Listeners\ObjectFailed  
[2023-10-02 16:58:50] local.INFO: Registering listener: LdapRecord\Laravel\Events\Import\DeletedMissing - App\Ldap\Listeners\ImportDeletedMissing  
[2023-10-02 16:58:50] local.INFO: Registering listener: LdapRecord\Laravel\Events\Import\Completed - App\Ldap\Listeners\ImportCompleted  
[2023-10-02 16:58:55] local.INFO: ----- Provider boot -----  
[2023-10-02 16:58:55] local.INFO: Registering listener: LdapRecord\Laravel\Events\Import\Started - App\Ldap\Listeners\ImportStarted  
[2023-10-02 16:58:55] local.INFO: Registering listener: LdapRecord\Laravel\Events\Import\Saved - App\Ldap\Listeners\ObjectModified  
[2023-10-02 16:58:55] local.INFO: Registering listener: LdapRecord\Laravel\Events\Import\Restored - App\Ldap\Listeners\ObjectRestored  
[2023-10-02 16:58:55] local.INFO: Registering listener: LdapRecord\Laravel\Events\Import\Deleted - App\Ldap\Listeners\ObjectDeleted  
[2023-10-02 16:58:55] local.INFO: Registering listener: LdapRecord\Laravel\Events\Import\ImportFailed - App\Ldap\Listeners\ObjectFailed  
[2023-10-02 16:58:55] local.INFO: Registering listener: LdapRecord\Laravel\Events\Import\DeletedMissing - App\Ldap\Listeners\ImportDeletedMissing  
[2023-10-02 16:58:55] local.INFO: Registering listener: LdapRecord\Laravel\Events\Import\Completed - App\Ldap\Listeners\ImportCompleted  
[2023-10-02 16:58:55] local.INFO: LDAP (ldap://example.com) - Operation: Binding - Username: example\administrator  
[2023-10-02 16:58:55] local.INFO: LDAP (ldap://example.com) - Operation: Bound - Username: example\administrator  
[2023-10-02 16:58:55] local.INFO: LDAP (ldap://example.com) - Operation: Paginate - Base DN: dc=iitest,dc=local - Filter: (&(memberOf=CN=Administrators,CN=Builtin,DC=iitest,DC=local)(objectclass=\74\6f\70)(objectclass=\70\65\72\73\6f\6e)(objectclass=\6f\72\67\61\6e\69\7a\61\74\69\6f\6e\61\6c\70\65\72\73\6f\6e)(objectclass=\75\73\65\72)(!(objectclass=\63\6f\6d\70\75\74\65\72))) - Selected: (objectguid,*) - Time Elapsed: 229.64  
[2023-10-02 16:58:59] local.INFO: Starting import of [2] LDAP objects.  
[2023-10-02 16:58:59] local.INFO: Object with name [Administrator] is being synchronized.  
[2023-10-02 16:58:59] local.INFO: LDAP (ldap://example.com) - Operation: Read - Base DN: dc=iitest,dc=local - Filter: (&(objectclass=\74\6f\70)(objectclass=\67\72\6f\75\70)(objectclass=*)) - Selected: (objectguid,*) - Time Elapsed: 66.7  
[2023-10-02 16:58:59] local.INFO: LDAP (ldap://example.com) - Operation: Paginate - Base DN: dc=iitest,dc=local - Filter: (member=CN\3dAdministrator\2cCN\3dUsers\2cDC\3diitest\2cDC\3dlocal) - Selected: (objectguid,objectclass,member) - Time Elapsed: 80.69  
[2023-10-02 16:58:59] local.INFO: LDAP (ldap://example.com) - Operation: Search - Base DN: dc=iitest,dc=local - Filter: (objectsid=\53\2d\31\2d\35\2d\32\31\2d\31\39\37\36\33\33\36\34\36\30\2d\33\38\30\32\36\32\36\31\36\30\2d\33\39\30\35\39\31\36\31\34\31\2d\35\31\33) - Selected: (objectguid,*) - Time Elapsed: 75.64  
[2023-10-02 16:58:59] local.INFO: LDAP (ldap://example.com) - Operation: Read - Base DN: dc=iitest,dc=local - Filter: (&(objectclass=\74\6f\70)(objectclass=\67\72\6f\75\70)(objectclass=*)) - Selected: (objectguid,*) - Time Elapsed: 36.62  
[2023-10-02 16:59:00] local.INFO: LDAP (ldap://example.com) - Operation: Paginate - Base DN: dc=iitest,dc=local - Filter: (member=CN\3dAdministrator\2cCN\3dUsers\2cDC\3diitest\2cDC\3dlocal) - Selected: (objectguid,objectclass,member) - Time Elapsed: 125.8  
[2023-10-02 16:59:00] local.INFO: LDAP (ldap://example.com) - Operation: Search - Base DN: dc=iitest,dc=local - Filter: (objectsid=\53\2d\31\2d\35\2d\32\31\2d\31\39\37\36\33\33\36\34\36\30\2d\33\38\30\32\36\32\36\31\36\30\2d\33\39\30\35\39\31\36\31\34\31\2d\35\31\33) - Selected: (objectguid,*) - Time Elapsed: 82.73  
[2023-10-02 16:59:00] local.INFO: LDAP (ldap://example.com) - Operation: Read - Base DN: dc=iitest,dc=local - Filter: (&(objectclass=\74\6f\70)(objectclass=\67\72\6f\75\70)(objectclass=*)) - Selected: (objectguid,*) - Time Elapsed: 80.87  
[2023-10-02 16:59:00] local.INFO: LDAP (ldap://example.com) - Operation: Paginate - Base DN: dc=iitest,dc=local - Filter: (member=CN\3dAdministrator\2cCN\3dUsers\2cDC\3diitest\2cDC\3dlocal) - Selected: (objectguid,objectclass,member) - Time Elapsed: 80.29  
[2023-10-02 16:59:00] local.INFO: LDAP (ldap://example.com) - Operation: Search - Base DN: dc=iitest,dc=local - Filter: (objectsid=\53\2d\31\2d\35\2d\32\31\2d\31\39\37\36\33\33\36\34\36\30\2d\33\38\30\32\36\32\36\31\36\30\2d\33\39\30\35\39\31\36\31\34\31\2d\35\31\33) - Selected: (objectguid,*) - Time Elapsed: 76.89  
[2023-10-02 16:59:00] local.INFO: LDAP (ldap://example.com) - Operation: Read - Base DN: dc=iitest,dc=local - Filter: (&(objectclass=\74\6f\70)(objectclass=\67\72\6f\75\70)(objectclass=*)) - Selected: (objectguid,*) - Time Elapsed: 37.62  
[2023-10-02 16:59:00] local.INFO: LDAP (ldap://example.com) - Operation: Paginate - Base DN: dc=iitest,dc=local - Filter: (member=CN\3dAdministrator\2cCN\3dUsers\2cDC\3diitest\2cDC\3dlocal) - Selected: (objectguid,objectclass,member) - Time Elapsed: 129.55  
[2023-10-02 16:59:00] local.INFO: LDAP (ldap://example.com) - Operation: Search - Base DN: dc=iitest,dc=local - Filter: (objectsid=\53\2d\31\2d\35\2d\32\31\2d\31\39\37\36\33\33\36\34\36\30\2d\33\38\30\32\36\32\36\31\36\30\2d\33\39\30\35\39\31\36\31\34\31\2d\35\31\33) - Selected: (objectguid,*) - Time Elapsed: 77.72  
[2023-10-02 16:59:00] local.INFO: Object with name [Administrator] has been successfully synchronized.  
[2023-10-02 16:59:00] local.INFO: Object with name [admin] is being imported.  
[2023-10-02 16:59:00] local.INFO: Object with name [admin] is being synchronized.  
[2023-10-02 16:59:00] local.INFO: LDAP (ldap://example.com) - Operation: Read - Base DN: dc=iitest,dc=local - Filter: (&(objectclass=\74\6f\70)(objectclass=\67\72\6f\75\70)(objectclass=*)) - Selected: (objectguid,*) - Time Elapsed: 65.2  
[2023-10-02 16:59:00] local.INFO: LDAP (ldap://example.com) - Operation: Paginate - Base DN: dc=iitest,dc=local - Filter: (member=CN\3dadmin\2cCN\3dUsers\2cDC\3diitest\2cDC\3dlocal) - Selected: (objectguid,objectclass,member) - Time Elapsed: 83.65  
[2023-10-02 16:59:00] local.INFO: LDAP (ldap://example.com) - Operation: Search - Base DN: dc=iitest,dc=local - Filter: (objectsid=\53\2d\31\2d\35\2d\32\31\2d\31\39\37\36\33\33\36\34\36\30\2d\33\38\30\32\36\32\36\31\36\30\2d\33\39\30\35\39\31\36\31\34\31\2d\35\31\33) - Selected: (objectguid,*) - Time Elapsed: 77.82  
[2023-10-02 16:59:01] local.INFO: LDAP (ldap://example.com) - Operation: Read - Base DN: dc=iitest,dc=local - Filter: (&(objectclass=\74\6f\70)(objectclass=\67\72\6f\75\70)(objectclass=*)) - Selected: (objectguid,*) - Time Elapsed: 80.63  
[2023-10-02 16:59:01] local.INFO: LDAP (ldap://example.com) - Operation: Paginate - Base DN: dc=iitest,dc=local - Filter: (member=CN\3dadmin\2cCN\3dUsers\2cDC\3diitest\2cDC\3dlocal) - Selected: (objectguid,objectclass,member) - Time Elapsed: 84.69  
[2023-10-02 16:59:01] local.INFO: LDAP (ldap://example.com) - Operation: Search - Base DN: dc=iitest,dc=local - Filter: (objectsid=\53\2d\31\2d\35\2d\32\31\2d\31\39\37\36\33\33\36\34\36\30\2d\33\38\30\32\36\32\36\31\36\30\2d\33\39\30\35\39\31\36\31\34\31\2d\35\31\33) - Selected: (objectguid,*) - Time Elapsed: 77.11  
[2023-10-02 16:59:01] local.INFO: LDAP (ldap://example.com) - Operation: Read - Base DN: dc=iitest,dc=local - Filter: (&(objectclass=\74\6f\70)(objectclass=\67\72\6f\75\70)(objectclass=*)) - Selected: (objectguid,*) - Time Elapsed: 36.92  
[2023-10-02 16:59:01] local.INFO: LDAP (ldap://example.com) - Operation: Paginate - Base DN: dc=iitest,dc=local - Filter: (member=CN\3dadmin\2cCN\3dUsers\2cDC\3diitest\2cDC\3dlocal) - Selected: (objectguid,objectclass,member) - Time Elapsed: 51.5  
[2023-10-02 16:59:01] local.INFO: LDAP (ldap://example.com) - Operation: Search - Base DN: dc=iitest,dc=local - Filter: (objectsid=\53\2d\31\2d\35\2d\32\31\2d\31\39\37\36\33\33\36\34\36\30\2d\33\38\30\32\36\32\36\31\36\30\2d\33\39\30\35\39\31\36\31\34\31\2d\35\31\33) - Selected: (objectguid,*) - Time Elapsed: 72.3  
[2023-10-02 16:59:01] local.INFO: LDAP (ldap://example.com) - Operation: Read - Base DN: dc=iitest,dc=local - Filter: (&(objectclass=\74\6f\70)(objectclass=\67\72\6f\75\70)(objectclass=*)) - Selected: (objectguid,*) - Time Elapsed: 81.82  
[2023-10-02 16:59:01] local.INFO: LDAP (ldap://example.com) - Operation: Paginate - Base DN: dc=iitest,dc=local - Filter: (member=CN\3dadmin\2cCN\3dUsers\2cDC\3diitest\2cDC\3dlocal) - Selected: (objectguid,objectclass,member) - Time Elapsed: 79.42  
[2023-10-02 16:59:01] local.INFO: LDAP (ldap://example.com) - Operation: Search - Base DN: dc=iitest,dc=local - Filter: (objectsid=\53\2d\31\2d\35\2d\32\31\2d\31\39\37\36\33\33\36\34\36\30\2d\33\38\30\32\36\32\36\31\36\30\2d\33\39\30\35\39\31\36\31\34\31\2d\35\31\33) - Selected: (objectguid,*) - Time Elapsed: 85.77  
[2023-10-02 16:59:01] local.INFO: Object with name [admin] has been successfully synchronized.  
[2023-10-02 16:59:01] local.ERROR: Failed importing object [admin]. SQLSTATE[23502]: Not null violation: 7 ERROR:  null value in column "email" of relation "users" violates not-null constraint
DETAIL:  Failing row contains (54, admin, null, null, $2y$10$6hy1eQRVXyNoMDovXo8i/urd.PIqgT.mf/Sj4yQCTdDTm9ezYDjHK, null, 2023-10-02 16:59:01, 2023-10-02 16:59:01, MBH Jelzálogbank, null, null, t, t, t, t, f, 57d7504e-c386-42f9-a3e8-a91fd9e44800, default). (Connection: pgsql, SQL: insert into "users" ("guid", "domain", "password", "name", "email", "role_valuations", "role_revaluations", "role_admin_users", "role_admin_reports", "updated_at", "created_at") values (57d7504e-c386-42f9-a3e8-a91fd9e44800, default, $2y$10$6hy1eQRVXyNoMDovXo8i/urd.PIqgT.mf/Sj4yQCTdDTm9ezYDjHK, admin, ?, 1, 1, 1, 1, 2023-10-02 16:59:01, 2023-10-02 16:59:01) returning "id")  
[2023-10-02 16:59:01] local.INFO: Completed import. Imported [0] new LDAP objects. Synchronized [1] existing LDAP objects.  

I'm aware that one of the 2 users has invalid fields and the import of that certain row fails but I think based on the docs that this shouldn't be relevant in the issue I'm describing.

Thanks in advance for your time.

[stevebauman]

Hi @starlord-wst!

The LdapRecord-Laravel package utilizes native Laravel events, so you don't actually register the listeners inside of the core LdapRecord packages event listener, but rather Laravel's native event listener.

To have your listeners be fired, update your service provider to extend Laravel's built-in EventServiceProvider, and remove the boot() method. The built-in Laravel EventServiceProvider will handle registering your defined listeners inside of the $listen property:

use Illuminate\Foundation\Support\Providers\EventServiceProvider as ServiceProvider;

class EventServiceProvider extends ServiceProvider
{
    protected $listen = ['...'];
}

Can you give that a shot?

Also, if there was something you found misleading or unclear from the docs, let me know and I can update them! 👍

[starlord-wst]

Thanks for the quick response @stevebauman!

The suggested solution is working fine, the events are being fired properly.

Regarding the docs of the Laravel version of the library, the events section starts with the following sentence, which to me sounds like it's supposed to utilize the core version's dispatcher instead of using Laravel's built-in feature:

LdapRecord includes a robust event dispatcher that allows you to listen for various events that occur, such as authentication and object creation / modification.

Besides this the sections below the intro, including the Creating the service provider part has examples that further make it seem like the library has a custom event implementation. The provider described in that section is not extending Laravel's default EventServiceProvider, as seen below:

<?php

namespace App\Providers;

use LdapRecord\Container;
use Illuminate\Support\ServiceProvider;

class LdapEventServiceProvider extends ServiceProvider

Another thing that I noticed is in the Creating the listener section, where the example code suggests that all LdapRecord-Laravel events have a getModel() method, but that's not the case. It's only true for the LdapRecord\Models\Events namespace of the core library. LdapRecord-Laravel events in the LdapRecord\Laravel\Events\Import namespace that extend the Event class only have a public LdapModel $object; property and no getter called getModel(). I was able to fix the resuting error with accessing the public property instead of trying to call the getter, but I think the docs are not clear about this.

My suggestion is that in the Laravel version of the docs, the events section could include the sentence you wrote in your previous reply:

The LdapRecord-Laravel package utilizes native Laravel events, so you don't actually register the listeners inside of the core LdapRecord packages event listener, but rather Laravel's native event listener.

There coud also be a more detailed description of the import events' available properties and methods where applicable as neither the import section nor the event section of the docs include this.

One more thing: I'm trying to use the attributesToArray method of the User Ldap model in one of my loggers. Now the description of this method is:

Convert all the models attributes to their JSON encodable value

I'm not sure if I understand it correctly and if the below issue is really due to this, but I'd expect the returned array not to contain binary data. However when my logger tries to persist the return value of this method, I get the following error:

Illuminate\Database\QueryException 

  SQLSTATE[22P05]: Untranslatable character: 7 ERROR:  unsupported Unicode escape sequence
DETAIL:  \u0000 cannot be converted to text.

The array returned by attributesToArray contains some attributes like this one:

"logonhours":["\u00ff\u00ff\u00ff\u00ff\u00ff\u00ff\u00ff\u00ff\u00ff\u00ff\u00ff\u00ff\u00ff\u00ff\u00ff\u00ff\u00ff\u00ff\u00ff\u00ff\u00ff"],
"msexchmailboxsecuritydescriptor":["\u0001\u0000\u0004

I guess I could fix such errors with manually querying all the attributes I need but I'd still expect atributesToArray not to contain binary.

Let me know what you think on all of the above.

Thanks again!

[starlord-wst]

After further investigation, I think there's no binary in the return value of attributesToArray, instead PostgreSQL seems to be unable to handle the \u0000 unicode sequence. So the solution in my case could be to sanitize the strings in the returned array. And since it's Postgres-specific, I guess attributesToArray itself doesn't need fixing.

[stevebauman]

Regarding the docs of the Laravel version of the library, the events section starts with the following sentence, which to me sounds like it's supposed to utilize the core version's dispatcher instead of using Laravel's built-in feature:

Thanks! I've updated this document to include this important note at the top of the documentation:

LdapRecord core events (those that reside in the core LdapRecord framework) 
cannot be listened for in Larvel's event dispatcher. They must be listened
for using the core LdapRecord event dispatcher.

For LdapRecord-Laravel events (those that reside in the `LdapRecord\Laravel`
namespace), they can only be listened for in Laravel's event dispatcher,
and cannot be listened for in the LdapRecord core dispatcher.

Besides this the sections below the intro, including the Creating the service provider part has examples that further make it seem like the library has a custom event implementation. The provider described in that section is not extending Laravel's default EventServiceProvider, as seen below:

This is intended, because the service provider must not extend Laravel's built-in EventServiceProvider, as the docs are explaining how to listen for core LdapRecord events (snippet from the first sentence on the docs):

The core LdapRecord framework includes a robust event dispatcher that allows you to listen for various events that occur, such as authentication and object creation or modification.

Another thing that I noticed is in the Creating the listener section, where the example code suggests that all LdapRecord-Laravel events have a getModel() method, but that's not the case. It's only true for the LdapRecord\Models\Events namespace of the core library.

I would argue against this, as the example provided is showing a specific model event listener being registered (Saved), and the docs do not mention that all events have this method, and the doc is only for LdapRecord core events. However, I do agree it can be misleading, so I will remove the this method from the example listener so this can no longer cause any confusion 👍.

One more thing: I'm trying to use the attributesToArray method of the User Ldap model in one of my loggers. Now the description of this method is:

Convert all the models attributes to their JSON encodable value

I think you're correct that this doc block is misleading, as LdapRecord models are only configured to convert a specific set of attributes to their JSON encodable value. If there are some attributes that are missing from being converted for a specific model, I'd consider that a bug 👍 .

---

I really appreciate your thorough response and your help in making LdapRecord better for everyone. It takes time, thought, and effort to do this. Thanks again @starlord-wst! 🙏

[starlord-wst]

Thanks again for the support and updating the docs, I'm glad that I had the chance to contribute a bit to such a nice and useful project.