[NOT_REPRODUCIBLE] 503 Service Temporarily Unavailable (Pods Evicted) after resetting event consumers

spacecat · November 2, 2020, 6:27pm

I have…

[ ] Checked the logs and have uploaded a log file and provided a link because I found something suspicious there. Please do not post the log file in the topic because very often something important is missing.

I’m submitting a…

[ ] Regression (a behavior that stopped working in a new release)
[ x] Bug report
[ ] Performance issue
[ ] Documentation issue or request

Current behavior

It all started with med wanting to upload some images into a folder in an app. I have two apps. One for dev and one for prod. I had uploaded some files in the dev app some time ago.

Now I wanted to upload the exact same files to the prod app. I tried doing this but Squidex told med “File has already been uploaded”. I then went to Administration>Consumers and reset “Recursive Deleter”, “AssetUsageTracker”, and “HistoryService”. These were the ones that I thought could be interfering with me wanting to upload those files that I mentioned above.

After resetting these consumer Squidex became unresponsive.
I checked my pods and I had a lot of Evicted Squidex pods.
My StatefulSet pod (Mongo) had also stopped working so the old pod was terminated and new one was created. The STS pod didn’t want to come back online so I manually deleted the pod and then after a minute or two it came back online.

After everything was back to normal again I could go ahead and upload the files. But now my app is complaining (giving me an exception) that it can’t find the assets of my prod app. Haven’t debugged this yet but it’s working locally/dev.

Expected behavior

Running/resetting consumer from within Administration>Consumers should not crash Squidex (STS pod and Squidex pod)

Minimal reproduction of the problem

Run/reset these consumer:
“Recursive Deleter”, “AssetUsageTracker”, and “HistoryService”.

Environment

[ x] Self hosted with docker
[ ] Self hosted with IIS
[ ] Self hosted with other version
[ ] Cloud version

Version: squidex/squidex:dev-5061

Browser:

[ x] Chrome (desktop)
[ ] Chrome (Android)
[ ] Chrome (iOS)
[ ] Firefox
[ ] Safari (desktop)
[ ] Safari (iOS)
[ ] IE
[ ] Edge

Others:

Sebastian · November 2, 2020, 9:15pm

Usually I would say that it is a stackoverflow-exception, but it is weird that MongoDB also crashed. Do you know why?

spacecat · November 3, 2020, 12:21am

I’ve no idea why any of this is happening tbh

spacecat · November 3, 2020, 12:27pm

I have now deleted the asset entirely from Squidex - by first removing any reference to the file from within content pages with an Asset field and then I also deleted the file from “Assets”. So I should be able to upload that same file again right? But no, Squidex won’t let me - it gives me a “Asset has already been uploaded.”. So I’m stuck where I was yesterday. This time before I go ahead and make Squidex crash again by resetting the consumers I thought I’d check with you first, Sebastian. What are your thoughts? Where should I start looking for clues?

Another thing that I noticed in the Asset UI after I tried to upload the above mentioned file is that the UI will not try to upload a file a second time. It’s as if it freezes because of a JavaScript error or something - not really sure. So I have to refresh my browser (F5) and then it will try to upload files again.

Sebastian · November 3, 2020, 12:52pm

You are talking about so many different things:

Upload file again: This seems to be a chrome restriction, I have never found a solution, but when you drag and drop the same file again the event handlers are just not invoked. If you select another file B and then A again it works fine.
Crash: The responsible class is EventConsumerGrain, but I cannot reproduce the problem yet in debug mode.
Same Asset: Thats weird, you can check the file in the asset collection and mark it as deleted. But the recursive deleted should do it.

spacecat · November 3, 2020, 2:19pm

You’re right, too many things at the same time.

So let’s focus on 3. Same Asset for now.

check the file in the asset collection and mark it as deleted

If you mean in Assets > [My Folder] > [My File] I’ve already deleted the file by clicking on the garbage bin icon.

It’s been over an hour now I think since I deleted the file. I thought that if I go away for a while, and come back, then any background process doing operations on any assets would have completed. I still can’t upload that same file, however.

spacecat · November 3, 2020, 2:26pm

I’m seeing this in the logs - nothing else after this log message - duno if it helps:

{
  "logLevel": "Information",
  "filters": {
    "appId": "99733981-5831-40da-b5ed-9cf0e289ffff",
    "appName": "my-app",
    "userId": "5bacce9c5935680001f6cbab",
    "clientId": "squidex-frontend",
    "costs": 1
  },
  "elapsedRequestMs": 9,
  "app": {
    "name": "Squidex",
    "version": "4.0.0.0",
    "sessionId": "55dbbffb-793d-4a48-890c-805702e5d244"
  },
  "web": {
    "requestId": "|630a848a-4da80b41fe12c4f6.",
    "requestPath": "/api/apps/my-app/assets",
    "requestMethod": "POST"
  },
  "timestamp": "2020-11-03T14:21:27Z"
}

Sebastian · November 3, 2020, 2:27pm

The files itself are not relevant, when a file is uploaded a hash is calculated and based on thsi hash the check is done. The files are MongoDB in States_Assets2 collection

spacecat · November 3, 2020, 2:32pm

Okay.

Experimenting some more:

What I did now was to copy the file in Explorer, rename the new file, and then try to upload it.

This works but it’s obviously not what I want.

spacecat · November 3, 2020, 2:35pm

I can try to check the state of States_Assets2 but you’d need to tell me what to look for?

Sebastian · November 3, 2020, 2:40pm

A file is considered as duplicate if the following criterias match:

Same hash
Same file size
Same file name.

So you can search for the file name in your mongo collection and check the state.

Something like { "fn": "my-file.png" }

spacecat · November 3, 2020, 2:51pm

Okay, will do some investigation.

Btw, I’m running the following version of mongo:

mongo:4.2.8

Sebastian · November 3, 2020, 2:55pm

That should not matter.

spacecat · November 3, 2020, 3:44pm

Looks like a dupe?

These exist multiple times:

        "fn" : "rokare-746w.jpg",
        "fh" : "JPyISKBh2q/4W4Xntuh4vsz9exf18urul6Qw6GYH0NE=",
        "fs" : NumberLong(133471),

MongoDB Query:

> db.States_Assets.find({fn:"rokare-746w.jpg"}).pretty()
{
        "_id" : "646a187b-f434-449b-a007-e7a1a1b53b7e",
        "_ai" : "20733981-5831-40da-b5ed-9cf0e289ffff",
        "pi" : BinData(3,"Zm4RfciNTkeQubcllkl8NQ=="),
        "ct" : ISODate("2020-10-12T18:43:37Z"),
        "mt" : ISODate("2020-11-02T17:45:32Z"),
        "ai" : {
                "_id" : BinData(3,"gTlzIDFY2kC17Zzw4on//w=="),
                "Name" : "db"
        },
        "mm" : "image/jpeg",
        "fn" : "rokare-746w.jpg",
        "fh" : "JPyISKBh2q/4W4Xntuh4vsz9exf18urul6Qw6GYH0NE=",
        "sl" : "rokare-746w.jpg",
        "fs" : NumberLong(133471),
        "fv" : NumberLong(0),
        "vs" : NumberLong(1),
        "at" : 1,
        "cb" : "subject:5bacce9c5935680001f6cba6",
        "mb" : "subject:5bacce9c5935680001f6cba6",
        "td" : [
                "755b8a19-6935-4457-a0ff-c998632041c8",
                "eacd509c-cd10-4970-8adf-49e75b3e8c0d",
                "ec883d71-3b8d-4224-88db-fbd89b0f055c"
        ],
        "dl" : true,
        "md" : {
                "pixelWidth" : NumberLong(746),
                "pixelHeight" : NumberLong(1119)
        }
}
{
        "_id" : "8207436b-8091-413f-92a2-3c854fa55030",
        "_ai" : "1b1836f6-321e-4e1e-8059-3aa3eec5154e",
        "pi" : BinData(3,"hEmS1rjtWkGSdMqNw2V45Q=="),
        "ct" : ISODate("2020-10-12T18:43:37Z"),
        "mt" : ISODate("2020-10-22T10:37:19Z"),
        "ai" : {
                "_id" : BinData(3,"9jYYGx4yHk6AWTqj7sUVTg=="),
                "Name" : "dev-db"
        },
        "mm" : "image/jpeg",
        "fn" : "rokare-746w.jpg",
        "fh" : "JPyISKBh2q/4W4Xntuh4vsz9exf18urul6Qw6GYH0NE=",
        "sl" : "rokare-746w.jpg",
        "fs" : NumberLong(133471),
        "fv" : NumberLong(0),
        "vs" : NumberLong(1),
        "at" : 1,
        "cb" : "subject:5bacce9c5935680001f6cba6",
        "mb" : "subject:5bacce9c5935680001f6cba6",
        "td" : [
                "e18817f7-f3d0-42ef-9633-77868e4436d6",
                "593581e0-3f91-45ea-9dff-742c0ad97a8d",
                "7e65ff08-cc11-4af2-bfab-458cdcfa6e1a"
        ],
        "dl" : true,
        "md" : {
                "pixelWidth" : NumberLong(746),
                "pixelHeight" : NumberLong(1119)
        }
}
{
        "_id" : "7d9099f6-cf59-4b6a-be9c-433cdb0fdf0c",
        "_ai" : "1b1836f6-321e-4e1e-8059-3aa3eec5154e",
        "pi" : BinData(3,"tPNHSZRsT0Gh9AKdPkk4/w=="),
        "ct" : ISODate("2020-10-22T10:39:25Z"),
        "mt" : ISODate("2020-11-03T12:18:14Z"),
        "ai" : {
                "_id" : BinData(3,"9jYYGx4yHk6AWTqj7sUVTg=="),
                "Name" : "dev-db"
        },
        "mm" : "image/jpeg",
        "fn" : "rokare-746w.jpg",
        "fh" : "JPyISKBh2q/4W4Xntuh4vsz9exf18urul6Qw6GYH0NE=",
        "sl" : "rokare-746w.jpg",
        "fs" : NumberLong(133471),
        "fv" : NumberLong(0),
        "vs" : NumberLong(1),
        "at" : 1,
        "cb" : "subject:5bacce9c5935680001f6cba6",
        "mb" : "subject:5bacce9c5935680001f6cba6",
        "td" : [
                "e18817f7-f3d0-42ef-9633-77868e4436d6",
                "593581e0-3f91-45ea-9dff-742c0ad97a8d",
                "7e65ff08-cc11-4af2-bfab-458cdcfa6e1a"
        ],
        "dl" : true,
        "md" : {
                "pixelWidth" : NumberLong(746),
                "pixelHeight" : NumberLong(1119),
                "imageQuality" : NumberLong(90),
                "description" : "JFIF File"
        }
}
{
        "_id" : "cdf8efe0-6c5a-4d3a-a66c-4767d0aa3ba7",
        "_ai" : "20733981-5831-40da-b5ed-9cf0e289ffff",
        "pi" : BinData(3,"rPkOn7vejUm+Ox9sVi3EMA=="),
        "ct" : ISODate("2020-11-02T17:59:06Z"),
        "mt" : ISODate("2020-11-02T17:59:06Z"),
        "ai" : {
                "_id" : BinData(3,"gTlzIDFY2kC17Zzw4on//w=="),
                "Name" : "db"
        },
        "mm" : "image/jpeg",
        "fn" : "rokare-746w.jpg",
        "fh" : "JPyISKBh2q/4W4Xntuh4vsz9exf18urul6Qw6GYH0NE=",
        "sl" : "rokare-746w.jpg",
        "fs" : NumberLong(133471),
        "fv" : NumberLong(0),
        "vs" : NumberLong(0),
        "at" : 1,
        "cb" : "subject:5bacce9c5935680001f6cba6",
        "mb" : "subject:5bacce9c5935680001f6cba6",
        "td" : [
                "755b8a19-6935-4457-a0ff-c998632041c8",
                "eacd509c-cd10-4970-8adf-49e75b3e8c0d",
                "ec883d71-3b8d-4224-88db-fbd89b0f055c"
        ],
        "dl" : false,
        "md" : {
                "pixelWidth" : NumberLong(746),
                "pixelHeight" : NumberLong(1119),
                "imageQuality" : NumberLong(90),
                "description" : "JFIF File"
        }
}
>

Sebastian · November 3, 2020, 4:02pm

Yes, seems to be so. I would just set them to deleted { “dl”: true } for now and it should work. It could have gone wrong during the migration or so.

spacecat · November 3, 2020, 4:13pm

Actually, after looking around some more in the UI I noticed the “tags” section in right column of the UI. I haven’t really payed attention to this feature before but after reading up on “Assets” I know understand it better.

I noticed that the file “rokare-746w.jpg” that appeared 4 times in the MongoDB logs also appears 4 times in the UI under different tags (3 times if I just click on the different tags, and 1 time if I just search for the file in the search bar). I don’t know however why the file is not showing when I have “All tags” selected?

So I guess what happened earlier when I thought I had completely deleted the file rokare-746w.jpg all that I had done was to remove it from that particular folder that the file was in.

So how DO you delete a file completely? I first remove it from a folder and then I also go through all of the tags that the file has automatically/manually been tagged with?

Sebastian · November 3, 2020, 4:30pm

The UI has two modes:

Search mode (a tag is selected or a file name is entered to the search): You get a flat list of files.
Folder mode (no search): You only see the files in the current folder.

You should be able to find it with the first mode. If it does not work properly it is a bug, but I would upgrade first, because I am working on a lot of improvements where the 5.0 is still clunky.

spacecat · November 3, 2020, 5:01pm

Btw, you mentioned States_Assets2 earlier. I can only see a States_Assets collection.There is however a States_RestoreStates2 collection:

show collections
Events
Identity_PersistedGrants
Identity_Roles
Identity_Users
Identity_XmlRepository
Key
Migration
Orleans_OrleansMembershipV2
Orleans_OrleansReminderV2
Projections_AssetStats
Projections_History
RequestLog
RuleEvents
RuleStatistics
States_Apps
States_AssetFolders
States_Assets
States_BackupState
States_EventConsumerState
States_Index_AppsByName
States_Index_AppsByUser
States_Index_RulesByApp
States_Index_SchemasByApp
States_Index_Tags
States_Repository
States_RestoreState
States_RestoreState2
States_Rules
States_Schemas
States_UISettings
States_UsageTracker
States_XmlRepository
TextIndex
TextIndexerState
Usages
UsagesV2
fullText.chunks
fullText.files

spacecat · November 3, 2020, 5:04pm

I deleted the file from all tags and now it is "dl" : true for all four occurrences.

Why 4 occurrences BTW?

I have uploaded the same file, with the same filename and size in two different apps. So there should be at least two occurrences. But what about the other two? Are those other two there because I put the file inside of a folder so those two occurrences are referencing the folders?

spacecat · November 3, 2020, 5:11pm

The UI has two modes:

Okay, I will try to upload the same set of files in two the same apps again and see if it works. It should work now since I’ve deleted all files from all folder AND tags. Let you know how it goes.