Hostname identification happens too often

[martijnimhoff]

Description

When making a normal http request to my application with only a simple view the application identifies the hostname about eight times. See this Event log from clockwork:

---

Information

• hyn/multi-tenant version: 5.3
• laravel version: 5.7
• database driver and version: postgres 9.6
• webserver software and version: nginx
• php version: 7.2.16

---

tenancy.php config

<?php

/*
 * This file is part of the hyn/multi-tenant package.
 *
 * (c) Daniël Klabbers <daniel@klabbers.email>
 *
 * For the full copyright and license information, please view the LICENSE
 * file that was distributed with this source code.
 *
 * @see https://laravel-tenancy.com
 * @see https://github.com/hyn/multi-tenant
 */

use App\Tenancy\IdGenerator;
use App\Website;
use Hyn\Tenancy\Database\Connection;
use Hyn\Tenancy\Middleware\EagerIdentification;
use Hyn\Tenancy\Middleware\HostnameActions;
use Hyn\Tenancy\Models\Hostname;

return [
    'models'     => [
        'hostname' => Hostname::class,
        'website'  => Website::class,
    ],
    'middleware' => [
        EagerIdentification::class,
        HostnameActions::class,
    ],
    'website'    => [
        'disable-random-id'            => false,
        'random-id-generator'          => IdGenerator::class,
        'uuid-limit-length-to-32'      => false,
        'disk'                         => false,
        'auto-create-tenant-directory' => true,
        'auto-rename-tenant-directory' => false,
        'auto-delete-tenant-directory' => false,
        'cache'                        => 10,
    ],
    'hostname'   => [
        'default'                           => null,
        'auto-identification'               => true,
        'early-identification'              => false,
        'abort-without-identified-hostname' => true,
        'cache'                             => 10,
        'update-app-url'                    => true,
    ],
    'db'         => [
        'default'                           => 'system',
        'system-connection-name'            =>  Connection::DEFAULT_SYSTEM_NAME,
        'tenant-connection-name'            =>  Connection::DEFAULT_TENANT_NAME,
        'tenant-division-mode'              => 'database',
        'password-generator'                => Hyn\Tenancy\Generators\Database\DefaultPasswordGenerator::class,
        'tenant-migrations-path'            => database_path('migrations/tenant'),
        'tenant-seed-class'                 => DatabaseSeeder::class,
        'auto-create-tenant-database'       => true,
        'auto-create-tenant-database-user'  => true,
        'auto-rename-tenant-database'       => true,
        'auto-delete-tenant-database'       => false,
        'auto-delete-tenant-database-user'  => false,
        'force-tenant-connection-of-models' => [
            //
        ],
        'force-system-connection-of-models' => [
            //
        ],
    ],
    'routes'     => [
        'path'           => base_path('routes/tenants.php'),
        'replace-global' => false,
    ],
    'folders'    => [
        'config' => [
            'enabled'   => true,
            'blacklist' => [
                'database',
                'tenancy',
                'webserver',
            ],
        ],
        'routes' => [
            'enabled' => true,
            'prefix'  => null,
        ],
        'trans'  => [
            'enabled'         => true,
            'override-global' => true,
            'namespace'       => 'tenant',
        ],
        'vendor' => [
            'enabled' => true,
        ],
        'media'  => [
            'enabled' => true,
        ],
        'views'  => [
            'enabled'         => true,
            'namespace'       => null,
            'override-global' => true,
        ],
    ],
];

Query log:

[londoh]

I'm also seeing similar with multi-tenant 5.4.4 Logging queries shows that in total there are 21 calls to fetch website and hostname info:

[2019-06-08 18:32:25] local.DEBUG: select * from `websites` where `websites`.`id` = ? and `websites`.`deleted_at` is null limit 1 - a:1:{i:0;i:33;}  
[2019-06-08 18:32:25] local.DEBUG: select * from `websites` where `websites`.`id` = ? and `websites`.`deleted_at` is null limit 1 - a:1:{i:0;i:33;}  
[2019-06-08 18:32:25] local.DEBUG: select * from `websites` where `websites`.`id` = ? and `websites`.`deleted_at` is null limit 1 - a:1:{i:0;i:33;}  
[2019-06-08 18:32:25] local.DEBUG: select * from `websites` where `websites`.`id` = ? and `websites`.`deleted_at` is null limit 1 - a:1:{i:0;i:33;}  
[2019-06-08 18:32:25] local.DEBUG: select * from `websites` where `websites`.`id` = ? and `websites`.`deleted_at` is null limit 1 - a:1:{i:0;i:33;}  
[2019-06-08 18:32:25] local.DEBUG: select * from `websites` where `websites`.`id` = ? and `websites`.`deleted_at` is null limit 1 - a:1:{i:0;i:33;}  
[2019-06-08 18:32:25] local.DEBUG: select * from `websites` where `websites`.`id` = ? and `websites`.`deleted_at` is null limit 1 - a:1:{i:0;i:33;}  
[2019-06-08 18:32:25] local.DEBUG: select * from `websites` where `websites`.`id` = ? and `websites`.`deleted_at` is null limit 1 - a:1:{i:0;i:33;}  
[2019-06-08 18:32:25] local.DEBUG: select * from `websites` where `websites`.`id` = ? and `websites`.`deleted_at` is null limit 1 - a:1:{i:0;i:33;}  
[2019-06-08 18:32:25] local.DEBUG: select * from `websites` where `websites`.`id` = ? and `websites`.`deleted_at` is null limit 1 - a:1:{i:0;i:33;}  

[2019-06-08 18:32:25] local.DEBUG: select `websites`.`uuid` from `hostnames` inner join `websites` on `hostnames`.`website_id` = `websites`.`id` where `fqdn` = ? limit 1 - a:1:{i:0;s:22:"hyntest.lcl";}  
[2019-06-08 18:32:25] local.DEBUG: select * from `hostnames` where `fqdn` = ? and `hostnames`.`deleted_at` is null limit 1 - a:1:{i:0;s:22:"hyntest.lcl";}  
[2019-06-08 18:32:25] local.DEBUG: select * from `hostnames` where `hostnames`.`website_id` = ? and `hostnames`.`website_id` is not null and `hostnames`.`deleted_at` is null - a:1:{i:0;i:33;}  
[2019-06-08 18:32:25] local.DEBUG: select `websites`.`uuid` from `hostnames` inner join `websites` on `hostnames`.`website_id` = `websites`.`id` where `fqdn` = ? limit 1 - a:1:{i:0;s:22:"hyntest.lcl";}  
[2019-06-08 18:32:25] local.DEBUG: select `websites`.`uuid` from `hostnames` inner join `websites` on `hostnames`.`website_id` = `websites`.`id` where `fqdn` = ? limit 1 - a:1:{i:0;s:22:"hyntest.lcl";}  
[2019-06-08 18:32:25] local.DEBUG: select * from `hostnames` where `hostnames`.`website_id` = ? and `hostnames`.`website_id` is not null and `hostnames`.`deleted_at` is null - a:1:{i:0;i:33;}  
[2019-06-08 18:32:25] local.DEBUG: select * from `hostnames` where `hostnames`.`website_id` = ? and `hostnames`.`website_id` is not null and `hostnames`.`deleted_at` is null - a:1:{i:0;i:33;}  
[2019-06-08 18:32:25] local.DEBUG: select `websites`.`uuid` from `hostnames` inner join `websites` on `hostnames`.`website_id` = `websites`.`id` where `fqdn` = ? limit 1 - a:1:{i:0;s:22:"hyntest.lcl";}  
[2019-06-08 18:32:25] local.DEBUG: select * from `hostnames` where `hostnames`.`website_id` = ? and `hostnames`.`website_id` is not null and `hostnames`.`deleted_at` is null - a:1:{i:0;i:33;}  
[2019-06-08 18:32:25] local.DEBUG: select `websites`.`uuid` from `hostnames` inner join `websites` on `hostnames`.`website_id` = `websites`.`id` where `fqdn` = ? limit 1 - a:1:{i:0;s:22:"hyntest.lcl";}  
[2019-06-08 18:32:25] local.DEBUG: select * from `hostnames` where `hostnames`.`website_id` = ? and `hostnames`.`website_id` is not null and `hostnames`.`deleted_at` is null - a:1:{i:0;i:33;} 

• hyn/multi-tenant version: 5.4.4
• laravel version: 5.8.
• database driver and version: mariadb 10.3.15
• webserver software and version: apache 2.4.6
• php version: 7.2.19 config as per: https://github.com/tenancy/multi-tenant/issues/613

regards

l.

[fletch3555]

If either of you are using telescope or xdebug, could you attempt to track down the source of these calls? We'll attempt the same, but we would have to reproduce it first, whereas you already have a reproducible case.

[martijnimhoff]

I've ran it through xdebug, but i'm not really sure what to look for. What caught my eye is that the Environment class if often rebuild. I see this stack trace often:

It seems that when the EventProvider is booting all Listeners, then each time the Environment is rebuild because it is a dependency.

[luceos]

We're binding the Environment only once the app is booted, this is after the listeners have been bound. The reason for this is #706 .. What we need to do is delay resolving the environment in those listeners.

[luceos]

From the looks of it, this should already be happening. Then it would seem that binding the singleton only after the app is booted, is incorrect 🤔

[martijnimhoff]

Hmm any idea on how to fix that?

[martijnimhoff]

It seems @luceos already solved it in https://github.com/tenancy/multi-tenant/commit/1ea9d696191862c75f9e0a3d0141f73157db92d4

Now updating to the newest version ..

[martijnimhoff]

I'm now at hyn/multi-tenant 5.4 and laravel 5.8.*. This fixes most of the queries.

The newer version binds the Environment singleton earlier. However still, the HostnameProvider is booted before the TenancyProvider. This causes the Environment to be constructed twice and therefore all involved queries are ran twice.

Perhaps this is the cause: I have disabled auto discovery and imported the TenancyProvider manually. I can't work with autodiscovery, since I need to listen to certain Events from the tenancy package in my other service providers. Therefore I've manually added the TenancyProvider to the end of the app.providers array.

[drtheuns]

We just setup tenancy in an existing application as well. After updating to 5.4 most of the duplicate queries are gone, except for 2. Queries are run in the following order, based on the mysql general_log:

select * from information_schema.tables where table_schema = 'tenancy' and table_name = 'websites' and table_type = 'BASE TABLE'
select * from `hostnames` where `fqdn` = 'our_tenant.app.test' and `hostnames`.`deleted_at` is null limit 1
select * from `websites` where `websites`.`id` = 9 and `websites`.`deleted_at` is null limit 1
select * from information_schema.tables where table_schema = 'tenancy' and table_name = 'websites' and table_type = 'BASE TABLE'
select * from `websites` where `websites`.`id` = 9 and `websites`.`deleted_at` is null limit 1

hyn/multi-tenant: 5.4.4 laravel/framework: v5.8.30

Hope this might offer some more insight.

[chadidi]

Same here:

{
    "database": {
        "total": 14,
        "items": [
            {
                "connection": "system",
                "query": "select * from information_schema.tables where table_schema = 'public' and table_name = 'websites' and table_type = 'BASE TABLE';",
                "time": 1545.22
            },
            {
                "connection": "system",
                "query": "select * from \"hostnames\" where \"fqdn\" = 'test.me' and \"hostnames\".\"deleted_at\" is null limit 1;",
                "time": 183.29
            },
            {
                "connection": "system",
                "query": "select * from \"hostnames\" where \"fqdn\" = 'test.me' and \"hostnames\".\"deleted_at\" is null limit 1;",
                "time": 0.53
            },
            {
                "connection": "system",
                "query": "select * from \"hostnames\" where \"fqdn\" = 'test.me' and \"hostnames\".\"deleted_at\" is null limit 1;",
                "time": 0.52
            },
            {
                "connection": "system",
                "query": "select * from information_schema.tables where table_schema = 'public' and table_name = 'websites' and table_type = 'BASE TABLE';",
                "time": 1.35
            },
            {
                "connection": "system",
                "query": "select * from \"hostnames\" where \"fqdn\" = 'test.me' and \"hostnames\".\"deleted_at\" is null limit 1;",
                "time": 0.45
            },
            {
                "connection": "system",
                "query": "select * from \"hostnames\" where \"fqdn\" = 'test.me' and \"hostnames\".\"deleted_at\" is null limit 1;",
                "time": 0.48
            },
            {
                "connection": "system",
                "query": "select * from \"hostnames\" where \"fqdn\" = 'test.me' and \"hostnames\".\"deleted_at\" is null limit 1;",
                "time": 0.88
            },
            {
                "connection": "system",
                "query": "select * from information_schema.tables where table_schema = 'public' and table_name = 'websites' and table_type = 'BASE TABLE';",
                "time": 2.97
            },
            {
                "connection": "system",
                "query": "select * from \"hostnames\" where \"fqdn\" = 'test.me' and \"hostnames\".\"deleted_at\" is null limit 1;",
                "time": 0.41
            },
            {
                "connection": "system",
                "query": "select * from \"hostnames\" where \"fqdn\" = 'test.me' and \"hostnames\".\"deleted_at\" is null limit 1;",
                "time": 0.79
            },
            {
                "connection": "system",
                "query": "select * from \"hostnames\" where \"fqdn\" = 'test.me' and \"hostnames\".\"deleted_at\" is null limit 1;",
                "time": 0.44
            }
        ]
    }
}