laravel / telescope

An elegant debug assistant for the Laravel framework.
https://laravel.com/docs/telescope
MIT License
4.88k stars 582 forks source link

Eloquent Model creation assigning ID=0 #289

Closed jcorrego closed 5 years ago

jcorrego commented 6 years ago

I dont know why, but i had a weird case with just one eloquent model, or at least have just detected this case, when i do a try to create by any of the possible ways :

new XXX; xxx->save();
XXX:create
auth()->user()->xxxs()->create()

In all cases i get an id assigned of 0, and of course the record is not saved, but i dont get any error... I then edit telescope config file, and commented all the watchers, and the code works again, records are saved... This only happens in production environment. And also tested with tinker in production and cretion works ok...

themsaid commented 6 years ago

How is this Telescope related?

jcorrego commented 6 years ago

How is this Telescope related?

This just happened after installing telescope, and like i said inactivating the watchers, everything works fine, aso soon as i activate them, model create gets id=0

jeremeallen commented 6 years ago

Changing my .env file to:

APP_ENV=production

Then trying something like:

        $submission = Test::create([
            'name' => 'Test name'
        ]);

        dd($submission->id);

Always returns id = 0 with the .env set to production. Set .env to local and the id auto increment is returned.

If I have .env set to production and in the TelescopeServiceProvider, I do this:

        Telescope::filter(function (IncomingEntry $entry) {
            return true;

Don't actually do that ^^ just pointing out ....

Then I get ids returned in production

JohnYeohMY commented 6 years ago

i have the same problem. but i heard that telescope is not for production use right?

themsaid commented 6 years ago

I can't replicate this issue, can someone please try on a fresh laravel installation? Seems there's something special in your applications that we need to figure out.

jeremeallen commented 6 years ago

Agreed I can't reproduce on a new project either. Fired up a new project, added in components one by one .... I match packages and versions and everything works as expected in a new Laravel install.

"require": {
        "php": "^7.1.3",
        "barryvdh/laravel-cors": "^0.11.2",
        "fideloper/proxy": "^4.0",
        "hisorange/browser-detect": "^3.1",
        "laravel/framework": "5.7.*",
        "laravel/tinker": "^1.0",
        "rollbar/rollbar-laravel": "^4.0",
        "tedivm/jshrink": "^1.3"
    },
    "require-dev": {
        "beyondcode/laravel-dump-server": "^1.0",
        "filp/whoops": "^2.0",
        "fzaninotto/faker": "^1.4",
        "laravel/telescope": "^0.1.5",
        "mockery/mockery": "^1.0",
        "nunomaduro/collision": "^2.0",
        "phpunit/phpunit": "^7.0"
    },

Understand the issue is with my existing app and code.

richfoxton commented 6 years ago

I was having a similar issue. A Horizon job kept failing on my production server after telescope had been added (even though it was only a dev dependency) - the same job was working fine on my dev machine. See error below...

image

Temporarily changed the .env file to local and debug to true on production and it started working again. Removed telescope completely from project and the job worked again.

See log below...first job had .env variables set to local, second (failed) was with production, third with production variables after removing telescope completely. Nothing else changed.

image

moh-abdullah-it commented 6 years ago

i have the same problem.
if i tray create any row by use create method or new model and save. return id = 0 when disable telescope .... work fine

malekhijazi commented 6 years ago

I'm facing the same problem. After saving the id is 0.

If I change the APP_ENV to "local" everything works fine When I change the APP_ENV to "production" or "development" the issue happens.

themsaid commented 6 years ago

@malekhijazi after saving, is the record stored in the DB or not?

malekhijazi commented 6 years ago

@themsaid yes its saving in the database but after $model->save(), $model->id is being returned 0 but all other attributes are correct.

I have the ID as auto increment and im not manually assigning the id

mojosef commented 6 years ago

I'm having this issue also after installing telescope in a particular project. It appears to only happen if the action is in a controller.

More info if needed: https://stackoverflow.com/questions/53141694/laravel-is-returning-0-for-model-id-on-production-server-forge

csanda87 commented 6 years ago

@themsaid Do you think this has anything to do with taking a 5.6 app to 5.7? I've noticed the same issues as above when installing telescope on upgraded projects.

$model->id being returned as 0 when ENV=production.

But it only seems to be a problem with older apps that have been upgraded. A new 5.7 app works with no problems. I followed the upgrade guide to do my upgrades. https://laravel.com/docs/5.7/upgrade#upgrade-5.7.0

As soon as I remove passport the $model->id begins to work correct again on these apps.

malekhijazi commented 6 years ago

@themsaid did a little debugging and found the problem was from the QueryWatcher.

When I disabled it in watchers array in telescope.php it works fine.

Another situation that works is setting keeping the QueryWatcher enabled and setting the slow to 0

As for what @csanda87 said, I did upgrade from 5.6 to 5.7 before installing telescope as it was a requirement.

Hope this helps

themsaid commented 6 years ago

@malekhijazi so if you disable the QueryWatcher but keep the ModelWatcher it works?

malekhijazi commented 6 years ago

@themsaid yes.

Setting this Watchers\QueryWatcher::class => [ 'enabled' => env('TELESCOPE_QUERY_WATCHER', false), 'slow' => 100, ],

or Watchers\QueryWatcher::class => [ 'enabled' => env('TELESCOPE_QUERY_WATCHER', true), 'slow' => 0, ],

works

paras-malhotra commented 6 years ago

Which version/release of Telescope are you guys using?

malekhijazi commented 6 years ago

@paras-malhotra "laravel/telescope": "^0.1.6",

mojosef commented 6 years ago

@paras-malhotra "laravel/telescope": "^0.1.6", ( Same on 0.1.5 )

leonardochen30 commented 6 years ago

Is for the first query executed

malinky commented 6 years ago

I faced a similar issue on Forge with APP_ENV=production. Local environment is fine. After $model->save() the ID returned is 0. The record is saved in the database.

I've since removed Telescope on production and it is working again.

I upgraded the Laravel app from 5.5 through to 5.7.11 to install Telescope (v0.1.2).

staudenmeir commented 6 years ago

This issue reminds me of https://github.com/laravel/framework/issues/25768#issuecomment-424179984.

Could it be that the QueryWatcher executes a query directly after the query it's listening to? This would override the connection's lastInsertId() value with 0 (if it's a non-INSERT query).

themsaid commented 6 years ago

Everyone reported this, are you using the same connection of your app to store Telescope entries?

csanda87 commented 6 years ago

Yes they all use the same db connection.

themsaid commented 6 years ago

@csanda87 is the issue resolved if you use a separate connection? Which is recommended since you don't want Telescope to slow down your database server in case recording went out of hand.

themsaid commented 5 years ago

This is now fixed guys.

jihadismail8 commented 5 years ago

i still have the same problem

cbaconnier commented 5 years ago

The issue seems back. I have set 'enabled' => env('TELESCOPE_QUERY_WATCHER', true), to false and now it's working.

Watchers\QueryWatcher::class => [
        'enabled' => env('TELESCOPE_QUERY_WATCHER', false),
        'ignore_packages' => true,
        'slow' => 100,
    ],

Thank to @malekhijazi for the comment.

Telescope 2.0.5 Laravel 5.8.26

And I do believe I had the issue with Laravel 5.8.23.

bcorcoran commented 5 years ago

I can confirm along with @cbaconnier that this seems to be back. Why is the query watcher modifying the primary key / id?

I notice that if i dump the model, id:0 is placed at the end of the object. With query watcher disabled, id is first and has the correct value.

This wasted a lot of time; I thought I was doing something wrong.

Additional info:

APP_ENV=local
APP_DEBUG=true

I had to set TELESCOPE_QUERY_WATCHER=false so I could get on with my life, but I'd really like the query watcher to work...

tormjens commented 5 years ago

I've also noticed this issue in one of my projects running latest of both Laravel and Telescope.

Disabling the query watcher does indeed make it work, but the query watcher is a neat thing to have in local/staging.

I would also like to know why the query watcher would be modifying primary key/id. I feel the behavior is kind of strange.

bcorcoran commented 5 years ago

@themsaid any input on this?

barryvdh commented 5 years ago

When a query is fired inside the QueryExecuted event, it will overwrite the lastInsertId. This is probably happening inside withoutRecording so it isn't logged. But maybe you can create your own logger?

use Illuminate\Database\Events\QueryExecuted;
use Illuminate\Support\Facades\Event;

    public function boot()
    {
        Event::listen(QueryExecuted::class, function($event) {
            dump($event->sql);
        });
    }

That way, we can narrow down what is causing the extra query.

You aren't using any custom tagging/after recording hook? Or perhaps disable the retrieving of the user inside the record method from Telescope (if your model/auth is different somehow)

bcorcoran commented 5 years ago

@barryvdh No custom tagging or hooks. Not even using this with a user, so auth is irrelevant. In fact I was only trying to use $model->associate($newItem) and it was inserting 0 as the ID in the pivot table.

This is obviously a bug... and at best it's bad (and undocumented) behavior.

barryvdh commented 5 years ago

Not saying that it isn't, but just trying to help narrow it down.

bcorcoran commented 5 years ago

I apologize for my tone-you're totally right.

That said, I have not done anything with telescope at all other than install/view it. I don't think my model setup is strange in any way- I'm doing only things listed in the documentation.

Thinking about it now though, is it possible this could be conflicting with https://github.com/owen-it/laravel-auditing ?

barryvdh commented 5 years ago

No experience with that. I do feel that the current behavior of Laravel itself might be a bit confusing. Ideally the query event would be executed after getting the lastInsertId, otherwise conflicts are bound to happen (had this case with debugbar also once)

Not sure why laravel-auditing would run any queries. There are some Eloquent models created, but it only watches for whitelisted models, right?

bcorcoran commented 5 years ago

As far as I understand it, yes. It's the only thing I didn't write (other than things provided by laravel itself) that I'm using on the model, so it is the only thing that came to mind.

barryvdh commented 5 years ago

So did you try dumping queries? Does anything come after the insert?

barryvdh commented 5 years ago

Wouldn't it be possible for Telescope to force a new connection? Eg. copy the current connections etc (if default) and create a second connection for it? So they can never interfere?

barryvdh commented 5 years ago

So did anyone try to dump the queries? I can't replicate this and am kinda worried about this breaking anything, but seems unlikely. Can you also check you are running v2.0.6?

tormjens commented 4 years ago

I'm still experiencing this. Did anyone manage to come up with a solution that does not turn off the query watcher?

piperone commented 4 years ago

I put this into a model I was trying to persist.

public static function boot()
{
    parent::boot();
    Event::listen(QueryExecuted::class, function($event) {
        \Log::info($event->sql);
    });
}

The relevant output is as follows:

local.INFO: insert into `my_table` (`field`, `second_field`, `third_field`, `fourth_field`, `updated_at`, `created_at`) values (?, ?, ?, ?, ?, ?)  

local.INFO: {"field":"foo","second_field":"bar","third_field":null,"fourth_field":10,"updated_at":"2020-03-23 12:11:47","created_at":"2020-03-23 12:11:47","id":0}

local.INFO: insert into `telescope_entries` (`batch_id`, `content`, `created_at`, `family_hash`, `type`, `uuid`) values (?, ?, ?, ?, ?, ?) - A bunch of (?, ? ...) follows 

local.INFO: insert into `telescope_entries_tags` (`entry_uuid`, `tag`) values (?, ?), (?, ?), (?, ?), (?, ?), (?, ?), (?, ?), (?, ?), (?, ?)

It doesn't tell me much other than the fact that the id has been changed to 0. What about you, @barryvdh ?

Running telescope 3.2

thijndehaas commented 4 years ago

This also is happening on my Laravel setup and only in production. I changed TELESCOPE_QUERY_WATCHER to false and this fixed the problem.

PHP 7.4.4 MariaDB 10.2.31 laravel/telescope v3.2.1 laravel/framework v7.6.2

APP_ENV=production
APP_DEBUG=true

Can we test anything else?

bcorcoran commented 3 years ago

This is still happening on Laravel 8.17.1 and Telescope 4.3.1. Local env.

TELESCOPE_QUERY_WATCHER=false is the only way that I can avoid this issue at present.

Any model that I try to return an ID from returns 0.

This also happens while doing $model->relationship()->create([]);

Both models are created successfully, but the relationship ID is saved as 0, which breaks the application.

darinda commented 3 years ago

I stumbled upon this issue and thought i had the same problem, turned out in my case it looked the same (id being 0 after creation) but actually was not related to telescope. In fact in my case the corresponding model did not use auto increment keys (but a separate column) but i forgot to add public $incrementing = false; to that model.

Maybe this could be helpful for others discovering this issue via google.

alex-p-ysbm commented 3 years ago

In our case the issue occurs because an extra query is executed in the user's 'email getter. The watcher tries to log the auth user so the query is executed between an insert operation and getPdo()->lastInsertId() statement. And this is the reason why the id is reseted.

pppdns commented 3 years ago

This issue is still happening (Telescope 4.4.0, Laravel 8.19.0). I just spent 4 hours debugging before I found this thread. Can we reopen this ticket? This seems like a serious design flaw to me. We sould at least update the Telescope docs with a warning that there may be weird side effects.

When I disable Telescope or the query watcher the issue goes away immediately.

driesvints commented 3 years ago

We need a proper way to reproduce this before we can look into this again.

piperone commented 3 years ago

@driesvints Would you consider opening this issue again, though? It is an issue that people are experiencing. Thanks.

driesvints commented 3 years ago

We've decided to rather document this to suggest using a separate database connection for Telescope. I'll send in a PR to the docs shortly.