Unable to upgrade to v3 as all tests fail due to database name

[Sammyjo20]

Subject of the issue

Hi... me again 😆

I was trying to upgrade to v3 and when running all tests in parallel we're getting a weird issue:

It looks like the name of the database is being changed and is causing every test to fail in our application. Switching back down to v2 works.

Your environment

We're running Laravel 10 and PHP 8.1

Steps to reproduce

Tell us how to reproduce this issue in steps:

1. Upgrade to v3
2. Run parallel tests (with RefreshDatabase trait)

Expected behaviour

Run tests

Actual behaviour

As above

[Sammyjo20]

I think I figured it out - I believe it's caused by the laravel-correlation-id library installed from v3. I've been doing some debugging in the CorrelationIdServiceProvider and I have narrowed it down to the code which registers the getUniqueId macro.

My guess is that when Paratest loads (Pest) it also tries to register a macro on the request called getUniqueId but because this has already been registered (or returning something it doesn't expect) it fails.

I think the fix would be to rename this to something else.

[bilfeldt]

@Sammyjo20 Are you able to replicate this on a plane laravel 10 installation with just this package installed and running parallel testing?

The macro is only registered if another one is not already added and there is even logging occurring if that is the case:

https://github.com/bilfeldt/laravel-correlation-id/blob/bc089bc8ffd8e839ca63daf1a0cb0b935b263614/src/CorrelationIdServiceProvider.php#L84-L97

[Sammyjo20]

Hey @bilfeldt I had another look today and it turns out for us it's caused by the Log::warning() when the library has already loaded the macros. I believe this is probably some sort of package conflict in our application however I thought I'd raise this with you because when running Parallel tests we would be writing thousands of lines into our logs. When running parallel tests, each test boots the application so will be writing a warning like this for every test which isn't ideal.

I wonder if it's worth just removing the warning?

Note: In the screenshot one of the macro names has been changed (this was just me debugging)

[bilfeldt]

@Sammyjo20 thanks for the debugging.

So there are two questions that should be addressed first here:

1. Why does the logging cause problems?
2. Why are the macros already registered?

You might very well be right that the logs should be removed. But right now they are there because of a problem - namely that the macros are already registered.

Logging issues

If we start with the logging.

Everything called in the boot method of service provider should have access to the log facade:

This method is called after all other service providers have been registered, meaning you have access to all other services that have been registered by the framework

So my first question is what error you are getting?

Macro already registered

Can you in any way see where this was registered the first time? My guess is that it is registered in the exact same file, but that is for some reason being called twice.

[Sammyjo20]

So I believe the issue/behaviour is called with Parallel tests because this also baffled me once - I thought that the service providers were only loaded once and then kept in memory - but it turns out that after each test the application is terminated and then rebooted again.

You can see this behaviour by creating a fresh Laravel app and putting a dump()/Log in the boot() method of the service provider. You should see that the dump/Log is run after every test in parallel or not (I believe)

As to why the Logs are breaking our database name - I really have no idea. I think your check to see if the Macro has already been registered is correct but due to the nature of testing I think it would be fine to remove the warning.

[Sammyjo20]

So my first question is what error you are getting?

I'm getting a weird one:

However this could be caused by something else we're doing so I'm not too worried about the error - just wanted to note that the error goes away completely when I remove the Log::warning().

[Sammyjo20]

My guess is that it is registered in the exact same file, but that is for some reason being called twice.

Yes I believe it's just re-running the same file/provider for each test where it is seeing it is registered - which to me is okay and normal, so your check to see if it's registered is good

[bilfeldt]

I must admit I don't get it. I just ran this package with parallel testing in another project without any issues.

That the app is booted and terminated again should not cause any problems.

So far, this logic seems okay in my view and the error seems to be related to your codebase and not a plane parallel test suite I am afraid.

What if you write Log::warning('test') in the boot method of your AppServiceProvider provider? Does that break your test suite?

[Sammyjo20]

Hey @bilfeldt I've just tested putting Log::warning('test') in my AppServiceProvider and it ran okay. This is a really odd one.

[bilfeldt]

Oh yes it really is. We can setup a videocall on monday if that makes debugging easier?

It would be fun to try to elliminate other stuff from you app. What if you create a two dummy test classe and run them in parallel (you can add the @group Dummy docblock and just run php artisan test --parallel --group=Dummy)?

[bilfeldt]

Could it be that your app adds some global log context like the user and then there is a logging happening before the users table is created?

[bilfeldt]

Closes due to inactivity