Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Log warnings on php artisan optimize: Request macros already exist #10

Closed
onlime opened this issue Dec 9, 2024 · 13 comments
Closed

Log warnings on php artisan optimize: Request macros already exist #10

onlime opened this issue Dec 9, 2024 · 13 comments

Comments

@onlime
Copy link
Contributor

onlime commented Dec 9, 2024

I have integrated bilfeldt/laravel-request-logger in the most standard way in my L11 project (latest Laravel v11.34.2), without any config modifications and only by adding the LogRequestMiddleware to some api routes.

Request logging works fine, but whenever I run php artisan optimize on production, the CorrelationIdServiceProvider (L84-L129) logs these warnings:

Request::getUniqueId() already exists, skipping macro registration.  
Request::getCorrelationId() already exists, skipping macro registration.  
Request::getClientRequestId() already exists, skipping macro registration.  
Request::getUniqueId() already exists, skipping macro registration.  
Request::getCorrelationId() already exists, skipping macro registration.  
Request::getClientRequestId() already exists, skipping macro registration.  

It always logs twice for all 3 macros that it tries to register.
This is a problem for me, as I send out Slack notifications for every log level above WARNING.

Even if I run a optimize:clear right before in my deployment, it happens.

php artisan optimize:clear
php artisan optimize # => 6 warnings fired!

the following are the cause:

php artisan config:cache # => 3 warnings fired!
php artisan route:cache # => 3 warnings fired!

Honestly, I don't know if this is a general problem of some stale caching on optimize, as I don't have any other packages installed that log any warnings when registering any macros.

Would very much appreciate if you could investigate this, as it might fill up other's application logs as well.

@bilfeldt
Copy link
Owner

bilfeldt commented Dec 9, 2024

hi @onlime

  1. can you reproduce this on a clean L11 installation and just this package?
  2. Can you try outputting something in the boot method of this packages service provider
    public function boot()
    {
    if ($this->app->runningInConsole()) {
    $this->publishes([
    __DIR__.'/../config/config.php' => config_path('correlation-id.php'),
    ], 'config');
    }
    $this->bootQueueCallbacks();
    $this->bootRequestGetUniqueIdMacro();
    $this->bootRequestGetCorrelationIdMacro();
    $this->bootRequestGetClientRequestIdMacro();
    }
    to check if this methods is for some reason called multiple times?

@onlime
Copy link
Contributor Author

onlime commented Dec 10, 2024

Hi @bilfeldt thanks for your fast response! I can reproduce it with a fresh L11/Breeze/Inertia/Vue project, set up like this:

$ laravel new laravel-correlation-id

 ┌ Would you like to install a starter kit?
 │ Laravel Breeze
 ┌ Which Breeze stack would you like to install?
 │ Vue with Inertia
 ┌ Would you like any optional features?
 │ Dark mode
 │ ESLint with Prettier
 ┌ Which testing framework do you prefer?
 │ Pest
 ┌ Which database will your application use?
 │ SQLite
 ┌ Would you like to run the default database migrations?
 │ Yes

$ cd laravel-correlation-id
$ npm install && npm run build

$ herd link
$ herd secure

$ composer require bilfeldt/laravel-correlation-id

$ composer dev

the problem does not yet pop up when accessing https://laravel-correlation-id.test
But as soon as I also install bilfeldt/laravel-request-logger ...

$ composer require bilfeldt/laravel-request-logger
$ php artisan vendor:publish --provider="Bilfeldt\RequestLogger\RequestLoggerServiceProvider" --tag="request-logger-migrations"
$ php artisan migrate
$ php artisan vendor:publish --provider="Bilfeldt\RequestLogger\RequestLoggerServiceProvider" --tag="request-logger-config"

nothing is logged yet, but as soon as I run config:cache:

$ php artisan config:cache
$ tail -f storage/logs/laravel.log
[2024-12-10 23:34:45] local.WARNING: Request::getUniqueId() already exists, skipping macro registration.  
[2024-12-10 23:34:45] local.WARNING: Request::getCorrelationId() already exists, skipping macro registration.  
[2024-12-10 23:34:45] local.WARNING: Request::getClientRequestId() already exists, skipping macro registration.  

That's all I did, no single modification, just a fresh L11 project with a common stack. If you need this repo, I can publish it, but should be easy reproducible.

Tested on:

$ php -v
PHP 8.4.1 (cli) (built: Nov 21 2024 10:00:19) (NTS)
Copyright (c) The PHP Group
Zend Engine v4.4.1, Copyright (c) Zend Technologies
    with Zend OPcache v8.4.1, Copyright (c), by Zend Technologies

$ pa about

  Environment .........................................................................  
  Application Name ............................................................ Laravel  
  Laravel Version ............................................................. 11.35.0  
  PHP Version ................................................................... 8.4.1  
  Composer Version .............................................................. 2.8.3  
  Environment ................................................................... local  
  Debug Mode .................................................................. ENABLED  
  URL ..................................................... laravel-correlation-id.test  
  Maintenance Mode ................................................................ OFF  
  Timezone ........................................................................ UTC  
  Locale ........................................................................... en  

  Cache ...............................................................................  
  Config ....................................................................... CACHED  
  Events ....................................................................... CACHED  
  Routes ....................................................................... CACHED  
  Views ........................................................................ CACHED  

  Drivers .............................................................................  
  Broadcasting .................................................................... log  
  Cache ...................................................................... database  
  Database ..................................................................... sqlite  
  Logs ................................................................. stack / single  
  Mail ............................................................................ log  
  Queue ...................................................................... database  
  Session .................................................................... database  

@onlime
Copy link
Contributor Author

onlime commented Dec 11, 2024

I still didn't get much further... If I explicitly disable auto-discovery of bilfeldt/laravel-correlation-id in my project's composer.json:

    "extra": {
        "laravel": {
            "dont-discover": [
                "bilfeldt/laravel-correlation-id"
            ]
        }
    },

the problem disappears. But when a manually register it in bootstrap/providers.php, the problem pops up again:

return [
    App\Providers\AppServiceProvider::class,
    \Bilfeldt\CorrelationId\CorrelationIdServiceProvider::class,
];

The CorrelationIdServiceProvider's boot method always seems to be run twice, also tested by extra debug log:

local.DEBUG: Registering Request::getUniqueId() macro.  
local.DEBUG: Registering Request::getCorrelationId() macro.  
local.DEBUG: Registering Request::getClientRequestId() macro.  
local.WARNING: Request::getUniqueId() already exists, skipping macro registration.  
local.WARNING: Request::getCorrelationId() already exists, skipping macro registration.  
local.WARNING: Request::getClientRequestId() already exists, skipping macro registration.  

always testing with php artisan config:cache. It happen's even if I remove the published config/request-logger.php.

But now it gets interesting: It even registers the macros on php artisan config:clear. Makes sense, as config:cache ConfigCacheCommand silently calls config:clear first and the callSilent() -> runCommand() from CallsCommands trait does not seem to run it as independent Artisan command (not spawning a new process), but programmatically. So I assume, the whole framework is bootstrapped again.

To keep it short (can dig into it further tomorrow when working together with @pascalbaljet, as he's really deep into the framework and understands all the bootstrapping / service container internals): Just remove the Log::warning()s but keep your Request::hasMacro() checks.

@bilfeldt
Copy link
Owner

@onlime thanks very much for the detailed explanation, much appreciated 👍

When I added the warnings, it was because I was under the assumption that the boot method would only ever get called once. But it seems that for some reason, beyond my initial understanding, the service providers are booted up twice when config is cached. There seems to be another issues that might be related to this, but need more time to test it out.

If you wanna make a PR that simply removed the warnings, then I will happily merge that. I will still try to confirm that it is the framework that runs the boot method twice and not this package that does something wrong, but I will not have the time for that right now.

As you have the example up and running already, can I ask you if the AppServiceProvider that is created in a fresh Laravel 11 installation is also booted twice? Thanks.

@onlime
Copy link
Contributor Author

onlime commented Dec 11, 2024

Update/correction: Even if I comment out the config:clear in the framework's ConfigCacheCommand, the CorrelationIdServiceProvider::boot() is executed twice on config:cache.

#[AsCommand(name: 'config:cache')]
class ConfigCacheCommand extends Command
{
    // ...
    public function handle()
    {
        // $this->callSilent('config:clear');

so there must be really something wrong with CorrelationIdServiceProviders auto-loading, as the problem even occurs when only this package is installed without bilfeldt/laravel-request-logger.

My first guess was to move the macro registration from boot() to register(). But still does not do the trick. Also tried to delay registration by wrapping the 3 method calls into $this->app->booted(function () { ... } to ensure the framework is fully booted. Same problem.

So, maybe we should not even register the macros at all if $this->app->runningInConsole()? There's no Request in CLI, after all.

@onlime
Copy link
Contributor Author

onlime commented Dec 11, 2024

If you wanna make a PR that simply removed the warnings, then I will happily merge that. I will still try to confirm that it is the framework that runs the boot method twice and not this package that does something wrong, but I will not have the time for that right now.

No PR today from my side, if I don't fully understand the original cause. Will ask @pascalbaljet tomorrow. He usually finds such glitches in a couple of seconds.

As you have the example up and running already, can I ask you if the AppServiceProvider that is created in a fresh Laravel 11 installation is also booted twice? Thanks.

tested. Yes, it's also booted twice (both register() and boot() called twice) on config:cache (which internally calls config:clear, but it happens even if I remove the $this->callSilent('config:clear') line from ConfigCacheCommand), but NOT on a explicit php artisan config:cache.

I guess it's the fresh framework bootstrapping which gets called after config:clear in ConfigCacheCommand:

    protected function getFreshConfiguration()
    {
        $app = require $this->laravel->bootstrapPath('app.php');

        $app->useStoragePath($this->laravel->storagePath());

        $app->make(ConsoleKernelContract::class)->bootstrap();

        return $app['config']->all();
    }

pretty uncool, but they must have had their reasons for this. So yes, you can probably not do anything against that double framework bootstrapping, so we should just remove the warnings.

will PR tomorrow.

@bilfeldt
Copy link
Owner

Yes, it's also booted twice (both register() and boot() called twice) on config:cache

In that case this is a framework issue. If that is the case, then we should just accept that the file can be booted multiple times and conditionally register the macros in the service provider.

@onlime
Copy link
Contributor Author

onlime commented Dec 11, 2024

right! So let's not waste more time on it. Here's my PR: #11

I just find it a pity that there are no clear best practices for Laravel package maintainers. The Package Discovery and Service Providers section in the official docs is super short.

@onlime
Copy link
Contributor Author

onlime commented Dec 11, 2024

also, it would not really harm to register a macro twice, as it just registers the callback on a static $macros array. I assume, your Request::hasMacro() check is just there to prevent collisions / naming conflicts with custom app specific macros. So, maybe leave the logging, but just lower log level from WARNING to INFO.
What do you think about that?

@bilfeldt
Copy link
Owner

I assume, your Request::hasMacro() check is just there to prevent collisions / naming conflicts with custom app specific macros.

Completely right.

So, maybe leave the logging, but just lower log level from WARNING to INFO.

If the framework has decided to call the boot method twice, then it is expected behaviour and we should not log anything at all. The downside is that we do not get information if another macro with the same name exists.

Keeping this open until I have the time to merge your PR. Thanks.

@onlime
Copy link
Contributor Author

onlime commented Dec 11, 2024

If the framework has decided to call the boot method twice, then it is expected behaviour and we should not log anything at all. The downside is that we do not get information if another macro with the same name exists.

agree!

Keeping this open until I have the time to merge your PR. Thanks.

Take your time until tomorrow at least, when I have another opinion about this topic.

@onlime
Copy link
Contributor Author

onlime commented Jan 18, 2025

@bilfeldt can you please merge #11. thanks!

@bilfeldt
Copy link
Owner

Launched in v1.3.1 thanks @onlime

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants