Duplicate entries for same product id

klickreflex commented 3 years ago

After letting my client add products in Shopify I started noticing duplicate item in the Statamic product collection with the same product_id.

Differences I noticed where:

published status in one case
image URLs with/without timestamp suffix (like in #86)
the markdown files were suffixed with a 1 (screenshot 1)
There are variants in Statamic that don't exist in Shopify (screenshot 2)

I'm using webhooks to update Statamic.

screenshot 1

screenshot 2

jackabox commented 3 years ago

Hey @klickreflex - can you send over the two MD files for duplicate products?

A few questions:

Did the keys/url change of the shopify store?
Did the variants exist but were then deleted? There would always be one variant, default, but looks like it's adding them again.
Did this occur when they change the status from draft to published?

klickreflex commented 3 years ago

Hi @jackabox,

here are the MD files:

Did the keys/url change of the shopify store?

No, nothing has changed and the store is still in development mode / not public.

Did the variants exist but were then deleted? / Did this occur when they change the status from draft to published?

I need to ask my client but it was here first contact with Shopify and I'd assume it's not unlikely she tried some things and possibly doesn't remember every action she took. What I do know is that in the end her products don't require variants.

klickreflex commented 3 years ago

This is getting out of hand with more products being added :( CleanShot 2021-11-05 at 10 30 58@2x

jackabox commented 3 years ago

Hey @klickreflex can you privately send me the SHOPIFY_AUTH_KEY and SHOPIFY_AUTH_PASSWORD so I can run some imports in a test as you? I'm not able to replicate this so far.

jackabox commented 3 years ago

Hey @klickreflex, you could try adding some debugging into line #78 on the ImportSingleProductJob and see what happens. If you put it inside of the if statement and let me know.

It seems like the system is failing to find the other Entry that exists, which is odd as the MD files seem basically equivelant.

klickreflex commented 2 years ago

Hi @jackabox,

after taking the conversation to emaiI I thought it makes sense to continue here for others to potentially benefit.

In #86 I saw a proposed change to SHOPIFY_ASSET_PATH. I don't have that property in my .env at all and I don't find any documentation about it. Is it required or at least recommended to add?

Anything new since I sent you my credentials?

jackabox commented 2 years ago

Hey @klickreflex, haven't had the time to spin it up yet. I'm hoping to do so this week.

Did you manage to insert the debug and see what happened?

Regarding #86 this was for fixing the assets being imported. Are you getting duplicate images or just entries?

klickreflex commented 2 years ago

Did you manage to insert the debug and see what happened?

No, here's my follow-up question on this (sent via email on Nov 8th):

Regarding the requested debugging output what exactly do I have to do here? Just a var_dump of $entry? I’m not a php dev so I’m not too sure

Are you getting duplicate images or just entries?

Only duplicate entries.

jackabox commented 2 years ago

Okay, if you run the manual "import products" from the admin/terminal, does this duplicate the entries also?

As for debugging, yes, if you can add var_dump($entry) after line 78 in the ImportSingleProductJob (https://github.com/jackabox/statamic-shopify/blob/1.6.1/src/Jobs/ImportSingleProductJob.php#L78). So it would look like the following:

        if (!$entry) {
          var_dump($entry);

            $entry = Entry::make()
                ->collection('products')
                ->slug($this->data['handle']);
        }

Once you've done that, rerun the import and when it's creating the duplicate entry it should output here to the terminal (if running the queue in the terminal). The var_dump should be null, but might be something odd happening here.

klickreflex commented 2 years ago

Hi Jack, I added the var_dump and ran an import of one of the duplicates, but got no output. Removed the duplication manually, re-ran the import, no logging. Also, the entry isn't duplicated anymore.

Instead I've found a new issue: Some products have variants in Statamic despite not having any in Shopify (they're all called the same Default). I don't even know how to decide which variant to remove manually without maybe breaking anything, let alone preventing this from happening in the future :(

CleanShot 2021-11-29 at 19 50 20@2x

klickreflex commented 2 years ago

~When I delete both entries of one that has duplicates and reimport it manually via php artisan shopify:import:single 7440667738367 I end up with a duplicate again. ID of one such products is 7440667738367. Still no var_dump output on the CLI.~

Update 1: Seems like this was a wrong impression, maybe because the queud job was still pending.

Update 2: After deleting all collections and products and re-importing them I don't see any duplicates (at first glance). Will have a look over the client's shoulder when maintaining inventory.

jackabox commented 2 years ago

Hey @klickreflex thanks for digging deeper into this, I tried replicating it locally but couldn't get any duplication (perhaps because it was all new, or perhaps as no webhook was triggered).

Let me know if the imports have a double effect again after a webhook and if so you could try using a different queue driver, otherwise we'll have to debug some more.

jackabox commented 2 years ago

Hey @klickreflex has this normalised now?

klickreflex commented 2 years ago

Hi @jackabox

looks like it didn't happen again after dumping and reimporting everything. Searching for *.1.md yields no more results in the products collection.

jackabox commented 2 years ago

@klickreflex Odd issue, but glad it's fixed! Going to close this for now, feel free to flag if anything changes.

klickreflex commented 2 years ago

Hi @jackabox,

sorry I have to come up with this again. It happened again, this time I have an exact commit with the introduced duplication.

Note the published_at stamp of both generated items differ for a second. Could it somehow be that Shopify's webhooks fire faster than Statamic can process stuff?
My client told me she had the product as an unpublished draft first and published later when she found out it didn't show up in Statamic
A small amount of other new products have been imported without any problems

CleanShot 2022-01-10 at 19 14 37@2x

klickreflex commented 2 years ago

I've managed to reproduce the issue: duplication happens always when chancing puplication status from draft to published! Could you please have another look @jackabox?

Gonna record a screencast to show the behavior tomorrow.

klickreflex commented 2 years ago

Another Update: Now I've had duplication reproducably any time I created products containing 2 or more images, independent of publishing status. Products with one or no images haven't been duplicated thus far.

Which brings me to the question if the problem could occur because of server resources being exceeded with image generation? There are a couple of failed tasks in Horizon that only seem to run successfully upon a second or so try.

jackabox commented 2 years ago

Hey @klickreflex, thanks for this. What queue system are you using?

klickreflex commented 2 years ago

Hi @jackabox

I'm using Redis via Horizon.

I've send you a Loom video of me doing all sorts of stuff - did this maybe land in your spam (using a new adress and that seem to be flagged often as junk: klick@hey.com

klickreflex commented 2 years ago

And here are the errors I'm getting for failed jobs in Horizon:

With the latest corrupt product imports the entrie Cart stopped working. Can't add products to it and showind only the ss-cart-loading message. No JS errors though.

klickreflex commented 2 years ago

I've increased server resources, wiped all products and variation from Statamic (again) and triggered a reimport with php artisan shopify:import:all:

While this imported all products (without duplication, as always when invoked manually), again I'm getting a bunch of failed jobs in Horizon. Here's a full error log.

Also the cart still doesn't work anymore. (add to cart does nothing, cart itself is in loading state, no js errors).

Jackabox\Shopify\Jobs\ImportCollectionsForProductJob
ID
afb8b925-a3f7-4dc9-81eb-6e91417b16da
Queue
default
Attempts
1
Retries
0
Tags
Pushed At
2022-01-16 10:11:26
Failed At
2022-01-16 10:12:02
Exception
Error: Call to a member function selectedQueryColumns() on null in /home/forge/stage.crazyceramic.klick.re/vendor/laravel/framework/src/Illuminate/Collections/HigherOrderCollectionProxy.php:60
Stack trace:
#0 /home/forge/stage.crazyceramic.klick.re/vendor/laravel/framework/src/Illuminate/Collections/Traits/EnumeratesValues.php(242): Illuminate\Support\HigherOrderCollectionProxy->Illuminate\Support\{closure}()
#1 /home/forge/stage.crazyceramic.klick.re/vendor/laravel/framework/src/Illuminate/Collections/HigherOrderCollectionProxy.php(61): Illuminate\Support\Collection->each()
#2 /home/forge/stage.crazyceramic.klick.re/vendor/statamic/cms/src/Stache/Query/Builder.php(34): Illuminate\Support\HigherOrderCollectionProxy->__call()
#3 /home/forge/stage.crazyceramic.klick.re/vendor/statamic/cms/src/Query/Builder.php(270): Statamic\Stache\Query\Builder->get()
#4 /home/forge/stage.crazyceramic.klick.re/vendor/statamic/cms/src/Stache/Repositories/EntryRepository.php(40): Statamic\Query\Builder->first()
#5 /home/forge/stage.crazyceramic.klick.re/vendor/laravel/framework/src/Illuminate/Support/Facades/Facade.php(261): Statamic\Stache\Repositories\EntryRepository->find()
#6 /home/forge/stage.crazyceramic.klick.re/vendor/statamic/cms/src/Entries/Entry.php(303): Illuminate\Support\Facades\Facade::__callStatic()
#7 /home/forge/stage.crazyceramic.klick.re/vendor/jackabox/statamic-shopify/src/Jobs/ImportCollectionsForProductJob.php(52): Statamic\Entries\Entry->save()
#8 /home/forge/stage.crazyceramic.klick.re/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(36): Jackabox\Shopify\Jobs\ImportCollectionsForProductJob->handle()
#9 /home/forge/stage.crazyceramic.klick.re/vendor/laravel/framework/src/Illuminate/Container/Util.php(40): Illuminate\Container\BoundMethod::Illuminate\Container\{closure}()
#10 /home/forge/stage.crazyceramic.klick.re/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(93): Illuminate\Container\Util::unwrapIfClosure()
#11 /home/forge/stage.crazyceramic.klick.re/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(37): Illuminate\Container\BoundMethod::callBoundMethod()
#12 /home/forge/stage.crazyceramic.klick.re/vendor/laravel/framework/src/Illuminate/Container/Container.php(653): Illuminate\Container\BoundMethod::call()
#13 /home/forge/stage.crazyceramic.klick.re/vendor/laravel/framework/src/Illuminate/Bus/Dispatcher.php(128): Illuminate\Container\Container->call()
#14 /home/forge/stage.crazyceramic.klick.re/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(128): Illuminate\Bus\Dispatcher->Illuminate\Bus\{closure}()
#15 /home/forge/stage.crazyceramic.klick.re/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(103): Illuminate\Pipeline\Pipeline->Illuminate\Pipeline\{closure}()
#16 /home/forge/stage.crazyceramic.klick.re/vendor/laravel/framework/src/Illuminate/Bus/Dispatcher.php(132): Illuminate\Pipeline\Pipeline->then()
#17 /home/forge/stage.crazyceramic.klick.re/vendor/laravel/framework/src/Illuminate/Queue/CallQueuedHandler.php(120): Illuminate\Bus\Dispatcher->dispatchNow()
#18 /home/forge/stage.crazyceramic.klick.re/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(128): Illuminate\Queue\CallQueuedHandler->Illuminate\Queue\{closure}()
#19 /home/forge/stage.crazyceramic.klick.re/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(103): Illuminate\Pipeline\Pipeline->Illuminate\Pipeline\{closure}()
#20 /home/forge/stage.crazyceramic.klick.re/vendor/laravel/framework/src/Illuminate/Queue/CallQueuedHandler.php(122): Illuminate\Pipeline\Pipeline->then()
#21 /home/forge/stage.crazyceramic.klick.re/vendor/laravel/framework/src/Illuminate/Queue/CallQueuedHandler.php(70): Illuminate\Queue\CallQueuedHandler->dispatchThroughMiddleware()
#22 /home/forge/stage.crazyceramic.klick.re/vendor/laravel/framework/src/Illuminate/Queue/Jobs/Job.php(98): Illuminate\Queue\CallQueuedHandler->call()
#23 /home/forge/stage.crazyceramic.klick.re/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(428): Illuminate\Queue\Jobs\Job->fire()
#24 /home/forge/stage.crazyceramic.klick.re/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(378): Illuminate\Queue\Worker->process()
#25 /home/forge/stage.crazyceramic.klick.re/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(172): Illuminate\Queue\Worker->runJob()
#26 /home/forge/stage.crazyceramic.klick.re/vendor/laravel/framework/src/Illuminate/Queue/Console/WorkCommand.php(117): Illuminate\Queue\Worker->daemon()
#27 /home/forge/stage.crazyceramic.klick.re/vendor/laravel/framework/src/Illuminate/Queue/Console/WorkCommand.php(101): Illuminate\Queue\Console\WorkCommand->runWorker()
#28 /home/forge/stage.crazyceramic.klick.re/vendor/laravel/horizon/src/Console/WorkCommand.php(51): Illuminate\Queue\Console\WorkCommand->handle()
#29 /home/forge/stage.crazyceramic.klick.re/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(36): Laravel\Horizon\Console\WorkCommand->handle()
#30 /home/forge/stage.crazyceramic.klick.re/vendor/laravel/framework/src/Illuminate/Container/Util.php(40): Illuminate\Container\BoundMethod::Illuminate\Container\{closure}()
#31 /home/forge/stage.crazyceramic.klick.re/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(93): Illuminate\Container\Util::unwrapIfClosure()
#32 /home/forge/stage.crazyceramic.klick.re/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(37): Illuminate\Container\BoundMethod::callBoundMethod()
#33 /home/forge/stage.crazyceramic.klick.re/vendor/laravel/framework/src/Illuminate/Container/Container.php(653): Illuminate\Container\BoundMethod::call()
#34 /home/forge/stage.crazyceramic.klick.re/vendor/laravel/framework/src/Illuminate/Console/Command.php(136): Illuminate\Container\Container->call()
#35 /home/forge/stage.crazyceramic.klick.re/vendor/symfony/console/Command/Command.php(298): Illuminate\Console\Command->execute()
#36 /home/forge/stage.crazyceramic.klick.re/vendor/laravel/framework/src/Illuminate/Console/Command.php(121): Symfony\Component\Console\Command\Command->run()
#37 /home/forge/stage.crazyceramic.klick.re/vendor/symfony/console/Application.php(1005): Illuminate\Console\Command->run()
#38 /home/forge/stage.crazyceramic.klick.re/vendor/symfony/console/Application.php(299): Symfony\Component\Console\Application->doRunCommand()
#39 /home/forge/stage.crazyceramic.klick.re/vendor/symfony/console/Application.php(171): Symfony\Component\Console\Application->doRun()
#40 /home/forge/stage.crazyceramic.klick.re/vendor/laravel/framework/src/Illuminate/Console/Application.php(94): Symfony\Component\Console\Application->run()
#41 /home/forge/stage.crazyceramic.klick.re/vendor/laravel/framework/src/Illuminate/Foundation/Console/Kernel.php(129): Illuminate\Console\Application->run()
#42 /home/forge/stage.crazyceramic.klick.re/artisan(37): Illuminate\Foundation\Console\Kernel->handle()
#43 {main}
Data
{
"product": {
"id": "1219bebf-b0cf-4a36-ab37-9d7842c05fb6",
"collection": "products",
"blueprint": null,
"date": null,
"locale": null,
"localizations": null,
"afterSaveCallbacks": [
],
"withEvents": true,
"slug": "butterdose-igel",
"data": {
"items": {
"product_id": 7514730201343,
"published": true,
"published_at": "2022-01-16 09:11:20",
"title": "Butterdose Igel",
"content": "<p data-mce-fragment="1">Sehr süsse , kleine Butterdose für ein halbes Pfund Butter.</p> <p data-mce-fragment="1">Eine Freude für jeden Frühstückstisch!</p>",
"vendor": [
"crazyceramic"
],
"type": null,
"tags": null,
"options": [
],
"featured_image": "shopify/butter_igel_1.jpg",
"gallery": [
"shopify/butter_igel_1.jpg",
"shopify/butter_igel_2.jpg"
]
},
"escapeWhenCastingToString": false
},
"supplements": {
"items": [
],
"escapeWhenCastingToString": false
},
"initialPath": "/home/forge/stage.crazyceramic.klick.re/content/collections/products/butterdose-igel.md",
"published": true,
"selectedQueryColumns": null,
"origin": null
},
"collections": [
{
"id": 287386239231,
"handle": "morgenwonne",
"title": "Morgenwonne",
"updated_at": "2022-01-15T15:17:02+01:00",
"body_html": "",
"published_at": "2021-10-14T15:56:19+02:00",
"sort_order": "best-selling",
"template_suffix": "",
"published_scope": "web",
"admin_graphql_api_id": "gid://shopify/Collection/287386239231"
}
],
"job": null,
"connection": null,
"queue": null,
"chainConnection": null,
"chainQueue": null,
"chainCatchCallbacks": null,
"delay": null,
"afterCommit": null,
"middleware": [
],
"chained": [
]
}

My client it getting nervous, and understandably so and I really don't know what I can do to get things working.

klickreflex commented 2 years ago

@jackabox Could this be a caching issue? I've found this: https://benfurfie.co.uk/articles/how-to-fix-the-call-to-a-member-function-selectedquerycolumns-on-null-error-in-statamic-3

There are more errors that sound like it

Jackabox\Shopify\Jobs\ImportCollectionsForProductJob

ErrorException: file_put_contents(/home/forge/stage.crazyceramic.klick.re/storage/framework/cache/data/stache/indexes/entries/products/path): Failed to open stream: No such file or directory in /home/forge/stage.crazyceramic.klick.re/vendor/laravel/framework/src/Illuminate/Filesystem/Filesystem.php:187
--
Stack trace:
#0 [internal function]: Illuminate\Foundation\Bootstrap\HandleExceptions->handleError()
#1 /home/forge/stage.crazyceramic.klick.re/vendor/laravel/framework/src/Illuminate/Filesystem/Filesystem.php(187): file_put_contents()
#2 /home/forge/stage.crazyceramic.klick.re/vendor/laravel/framework/src/Illuminate/Cache/FileStore.php(77): Illuminate\Filesystem\Filesystem->put()

klickreflex commented 2 years ago

Yet Aanother observation:

I created one new product in Shopify, is it expected that ImportCollectionsForProductJob runs twice? With the same one second delay that the duplicate items show?

CleanShot 2022-01-16 at 11 54 34@2x

klickreflex commented 2 years ago

I was pointed to this core issue that might be the cause of all/some problems, but it's beyond my judgement: https://github.com/statamic/cms/issues/2993

klickreflex commented 2 years ago

After removing the Worker from forge I’m having no more duplicate imports caused by the shopify new product Webhook. However, running the CLI command php artisan shopify:import:all doesn’t do anything anymore then:

klickreflex commented 2 years ago

Last observation for today:

I've setup redis & horizon locally, too to check if I'm getting the same duplication
When importing a new product manually eg (php artisan shopify:import:product 7515993800959) it's being queued and imported. I saw no duplication locally
On Staging I ran the exact same single import (for the same product id) and ended up with a duplication

j6s commented 2 years ago

@klickreflex and me took a detailed look at the server. We noticed the following things:

When adding multiple images in shopify, shopify will actually trigger 2 webhooks: 1 for the creation including only the main image and a update webhook containing all other images as well
These webhooks are dispatched at roughly the same time (usually with at max. 1 second difference)
Each of those webhooks will dispatch a Job to the queue
If your queue has multiple workers running then these Jobs will be executed in parallel

Switching to a single queue worker fixes the issue - however this is not ideal since this will throttle all jobs in the system. Ideally, the dispatched jobs should not be allowed to run in parallel. I am not 100% familiar with how Jobs in laravel work, but from my quick research, using the WithoutOverlapping middleware on the Jobs could solve this.

jackabox commented 2 years ago

Thanks for the deep dive into this. I'll investigate using the details you have provided.

If using a single worker has resolved the issue, then I'll take a look at why multiple workers is causing an issue.

jackabox commented 2 years ago

@j6s / @klickreflex Digging into all of this a bit more.

There are a few things that aren't related here, apologies if I miss anything.

Limiting The Issue

What's the difference between your staging and your local environment? If you're not having the issue locally, but are on staging, this sounds like your configuration is different in some way. Whether this is PHP, dependencies installed, queue processes, etc.

Caching Issue

ErrorException: file_put_contents(/home/forge/stage.crazyceramic.klick

This error sounds like it is due to a caching issue, if you clear things from your end this should go away. Don't forget to restart the queue (horizon, etc) whenever you make changes also.

Regarding Processing Jobs

The jobs are only built to be on one process as they have to queue after each other to ensure that things are working as expected. When you are getting duplicate IDs, do you have multiple processes on the queue? WithoutOverlapping won't provide what we want here, but I'm looking into the ability to set a dedicated queue for the jobs that you can then set one process to, this would be the fix for this I believe.

jackabox commented 2 years ago

1.7.0 has a queue option in the config that will let you set a new queue with 1 process for now. This should make sure that things resolve 1 by 1.

statamic-rad-pack / shopify