Homebrewery Outage (Apr 21, 2022 ~23:30 EST)

[jeddai]

Trevor Buckner @calculuschild [20:20]
I got it. [HB is] getting a server 503 error when trying to view his user page.
Looks like it's crashing the server when he does. Probably has something in one of his brews that is making the server choke.
Wow this guy has a lot of brews...

Trevor Buckner @calculuschild 20:31
woah strange. After getting past ~180 brews in the database and trying to load the next page of 20, the whole MongoDB server just crashed.
Does he have some corrupted brew in there that even Mongo can't handle? WTF.
Here's the error log from our server:

Apr 21 21:29:48 homebrewery app/web.1     at MessageStream.messageHandler (/app/node_modules/mongodb/lib/cmap/connection.js:462:30)
Apr 21 21:29:48 homebrewery app/web.1     at MessageStream.emit (node:events:390:28)
Apr 21 21:29:48 homebrewery app/web.1     at processIncomingData (/app/node_modules/mongodb/lib/cmap/message_stream.js:108:16)
Apr 21 21:29:48 homebrewery app/web.1     at MessageStream._write (/app/node_modules/mongodb/lib/cmap/message_stream.js:28:9)
Apr 21 21:29:48 homebrewery app/web.1     at writeOrBuffer (node:internal/streams/writable:389:12)
Apr 21 21:29:48 homebrewery app/web.1     at _write (node:internal/streams/writable:330:10)
Apr 21 21:29:48 homebrewery app/web.1     at MessageStream.Writable.write (node:internal/streams/writable:334:10)
Apr 21 21:29:48 homebrewery app/web.1     at TLSSocket.ondata (node:internal/streams/readable:754:22)
Apr 21 21:29:48 homebrewery app/web.1     at TLSSocket.emit (node:events:390:28)
Apr 21 21:29:48 homebrewery app/web.1     at addChunk (node:internal/streams/readable:315:12) {
Apr 21 21:29:48 homebrewery app/web.1   topologyVersion: { processId: new ObjectId("624dbddacde28b4ead24e716"), counter: 7 },
Apr 21 21:29:48 homebrewery app/web.1   operationTime: new Timestamp({ t: 1650590978, i: 1 }),
Apr 21 21:29:48 homebrewery app/web.1   ok: 0,
Apr 21 21:29:48 homebrewery app/web.1   code: 10107,
Apr 21 21:29:48 homebrewery app/web.1   codeName: 'NotWritablePrimary',
Apr 21 21:29:48 homebrewery app/web.1   '$clusterTime': {
Apr 21 21:29:48 homebrewery app/web.1     clusterTime: new Timestamp({ t: 1650590987, i: 2 }),
Apr 21 21:29:48 homebrewery app/web.1     signature: {
Apr 21 21:29:48 homebrewery app/web.1       hash: new Binary(Buffer.from("59f159a2e67c5b8b99832b62048547e97135add3", "hex"), 0),
Apr 21 21:29:48 homebrewery app/web.1       keyId: new Long("7051624606771183618")
Apr 21 21:29:48 homebrewery app/web.1     }
Apr 21 21:29:48 homebrewery app/web.1   }
Apr 21 21:29:48 homebrewery app/web.1 }

Getting this on the Mongo Atlas end:

"An error occurred while querying your MongoDB deployment.
Please try again in a few minutes."

G.Ambatte @G-Ambatte [20:51]
At a guess? The primary server in the DB cluster failed or changed, and it wasn't handled well
This seems to be a similar error: https://jira.mongodb.org/browse/NODE-921

Trevor Buckner @calculuschild [20:54]
Maybe... Not sure why querying this user's brews in particular is causing the crash though...
More error logs from the first time his username showed up in the last few days:

Apr 21 15:06:56 homebrewery app/web.2 <--- Last few GCs --->
Apr 21 15:06:56 homebrewery app/web.2 [22:0x5220fb0] 40012550 ms: Scavenge (reduce) 243.8 (258.0) -> 243.8 (258.0) MB, 0.9 / 0.0 ms  (average mu = 0.776, current mu = 0.682) allocation failure 
Apr 21 15:06:56 homebrewery app/web.2 [22:0x5220fb0] 40012551 ms: Scavenge (reduce) 243.8 (258.0) -> 243.8 (259.0) MB, 1.0 / 0.0 ms  (average mu = 0.776, current mu = 0.682) allocation failure 
Apr 21 15:06:56 homebrewery app/web.2 [22:0x5220fb0] 40012640 ms: Mark-sweep (reduce) 244.7 (259.0) -> 244.7 (259.7) MB, 85.6 / 0.0 ms  (average mu = 0.649, current mu = 0.271) allocation failure scavenge might not succeed
Apr 21 15:06:56 homebrewery app/web.2 <--- JS stacktrace --->
Apr 21 15:06:56 homebrewery app/web.2 FATAL ERROR: Reached heap limit Allocation failed - JavaScript heap out of memory
Apr 21 15:06:56 homebrewery app/web.2  1: 0xb03020 node::Abort() [node]
Apr 21 15:06:56 homebrewery app/web.2  2: 0xa181fb node::FatalError(char const*, char const*) [node]
Apr 21 15:06:56 homebrewery app/web.2  3: 0xced8de v8::Utils::ReportOOMFailure(v8::internal::Isolate*, char const*, bool) [node]
Apr 21 15:06:56 homebrewery app/web.2  4: 0xcedc57 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, bool) [node]
Apr 21 15:06:56 homebrewery app/web.2  5: 0xea5ef5  [node]
Apr 21 15:06:56 homebrewery app/web.2  6: 0xeb55cd v8::internal::Heap::CollectGarbage(v8::internal::AllocationSpace, v8::internal::GarbageCollectionReason, v8::GCCallbackFlags) [node]
Apr 21 15:06:56 homebrewery app/web.2  7: 0xeb82ce v8::internal::Heap::AllocateRawWithRetryOrFailSlowPath(int, v8::internal::AllocationType, v8::internal::AllocationOrigin, v8::internal::AllocationAlignment) [node]
Apr 21 15:06:56 homebrewery app/web.2  8: 0xe79432 v8::internal::Factory::AllocateRaw(int, v8::internal::AllocationType, v8::internal::AllocationAlignment) [node]
Apr 21 15:06:56 homebrewery app/web.2  9: 0xe71a44 v8::internal::FactoryBase<v8::internal::Factory>::AllocateRawWithImmortalMap(int, v8::internal::AllocationType, v8::internal::Map, v8::internal::AllocationAlignment) [node]
Apr 21 15:06:56 homebrewery app/web.2 10: 0xe73760 v8::internal::FactoryBase<v8::internal::Factory>::NewRawOneByteString(int, v8::internal::AllocationType) [node]
Apr 21 15:06:56 homebrewery app/web.2 11: 0x124fb45 v8::internal::IncrementalStringBuilder::Extend() [node]
Apr 21 15:06:56 homebrewery app/web.2 12: 0xf9e1f0 v8::internal::JsonStringifier::SerializeString(v8::internal::Handle<v8::internal::String>) [node]
Apr 21 15:06:56 homebrewery app/web.2 13: 0xfa0281 v8::internal::JsonStringifier::Result v8::internal::JsonStringifier::Serialize_<true>(v8::internal::Handle<v8::internal::Object>, bool, v8::internal::Handle<v8::internal::Object>) [node]
Apr 21 15:06:56 homebrewery app/web.2 14: 0xfa23bc v8::internal::JsonStringifier::SerializeJSReceiverSlow(v8::internal::Handle<v8::internal::JSReceiver>) [node]
Apr 21 15:06:56 homebrewery app/web.2 15: 0xfa34cd v8::internal::JsonStringifier::Result v8::internal::JsonStringifier::Serialize_<false>(v8::internal::Handle<v8::internal::Object>, bool, v8::internal::Handle<v8::internal::Object>) [node]
Apr 21 15:06:56 homebrewery app/web.2 16: 0xfa4db1 v8::internal::JsonStringifier::SerializeArrayLikeSlow(v8::internal::Handle<v8::internal::JSReceiver>, unsigned int, unsigned int) [node]
Apr 21 15:06:56 homebrewery app/web.2 17: 0xfa1134 v8::internal::JsonStringifier::Result v8::internal::JsonStringifier::Serialize_<true>(v8::internal::Handle<v8::internal::Object>, bool, v8::internal::Handle<v8::internal::Object>) [node]
Apr 21 15:06:56 homebrewery app/web.2 18: 0xfa3ce1 v8::internal::JsonStringifier::Result v8::internal::JsonStringifier::Serialize_<false>(v8::internal::Handle<v8::internal::Object>, bool, v8::internal::Handle<v8::internal::Object>) [node]
Apr 21 15:06:56 homebrewery app/web.2 19: 0xfa55ff v8::internal::JsonStringify(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>) [node]
Apr 21 15:06:56 homebrewery app/web.2 20: 0xd6fdd7 v8::internal::Builtin_JsonStringify(int, unsigned long*, v8::internal::Isolate*) [node]
Apr 21 15:06:56 homebrewery app/web.2 21: 0x15e79b9  [node]
Apr 21 15:06:56 homebrewery app/web.2 Aborted
Apr 21 15:06:56 homebrewery heroku/router at=error code=H13 desc="Connection closed without response" method=PUT path="/api/update/niV3DORaoAzM" host=homebrewery.naturalcrit.com request_id=83ce6bd2-68fa-40f0-a60d-49392c2a6a79 fwd="187.116.74.241" dyno=web.2 connect=0ms service=2947ms status=503 bytes=0 protocol=https
Apr 21 15:06:56 homebrewery heroku/router at=error code=H13 desc="Connection closed without response" method=GET path="/user/King%20of%20Nowhere" host=homebrewery.naturalcrit.com request_id=34323ecb-8698-4972-9c81-f5417d129432 fwd="70.44.69.41" dyno=web.2 connect=0ms service=15667ms status=503 bytes=0 protocol=https
Apr 21 15:06:56 homebrewery heroku/router at=error code=H13 desc="Connection closed without response" method=GET path="/" host=homebrewery.naturalcrit.com request_id=437b5b93-6150-4e24-b7f8-5f814aa698ce fwd="70.44.69.41" dyno=web.2 connect=0ms service=3589ms status=503 bytes=0 protocol=https
Apr 21 15:06:56 homebrewery heroku/router at=error code=H13 desc="Connection closed without response" method=PUT path="/api/update/G-c2XecQYohy" host=homebrewery.naturalcrit.com request_id=dee2d68d-650d-47fc-a547-740fd0054c65 fwd="45.168.64.185" dyno=web.2 connect=0ms service=264ms status=503 bytes=0 protocol=https
Apr 21 15:06:56 homebrewery heroku/router at=error code=H13 desc="Connection closed without response" method=PUT path="/api/update/6DICuOp8Bo5P" host=homebrewery.naturalcrit.com request_id=084ee577-3a4e-4d49-8b5e-3bb8a5774520 fwd="98.97.56.179" dyno=web.2 connect=9ms service=7250ms status=503 bytes=0 protocol=https
Apr 21 15:06:57 homebrewery heroku/web.2 Process exited with status 134
Apr 21 15:06:57 homebrewery heroku/web.2 State changed from up to crashed
Apr 21 15:06:57 homebrewery heroku/web.2 State changed from crashed to starting
Apr 21 15:07:03 homebrewery heroku/web.2 Starting process with command `npm start`
Apr 21 15:07:05 homebrewery app/web.2 > [email protected] start
Apr 21 15:07:05 homebrewery app/web.2 > node server.js
Apr 21 15:07:06 homebrewery app/web.2 server on port: 50229
Apr 21 15:07:06 homebrewery heroku/web.2 State changed from starting to up

Trevor Buckner @calculuschild [21:01]
Resetting the Primary cluster to see if that makes any difference.

Charlie Humphreys @jeddai [21:22]
Hm the js heap note in that error makes me wonder if somehow their brew text is too big?
Could also be an issue with Atlas I suppose

Trevor Buckner @calculuschild [21:25]
It would have to be enormous.... There's a chance of some weird Markdown causing a REDOS issue. We've had that in the past. But if that's the case we wouldn't have the Atlas server crashing too.
Yeah, so I can page through the search results 20 brews at a time on the Atlas UI, but once I get to 179 and try to go further, it just hangs and results with either "timed out" or "there was an error" or the the database crashes.
It says "1-20 of many", "21-40 of many", etc. For every other user it would eventually reach the end and say "31-35 of 35", but we never get to the end with this user.

Gazook89 @Gazook89 [21:37]
from what i see in the modmail, we haven't asked him if he has any idea of how many brews he has
if he is under the impression he only has like 20 brews, but mongo says there are 100's(?), then that might be a clue?

Trevor Buckner @calculuschild [21:38]
Correct, I have not. I'll ask. And if it's more than 180 then we definitely have an issue because Atlas can't retrieve them.

[jeddai]

Apr 22, 2022 00:30 - HB back online, at least temporarily

[Gazook89]

Closing this discussion as resolved.