search

mozilla / addons

☂ Umbrella repository for Mozilla Addons ✨
Other
127 stars 41 forks source link

frontend app crashed due to heap OOM error #2082

Open bqbn opened 4 years ago

bqbn commented 4 years ago

Describe the problem and steps to reproduce it:

What happened?

At around 11 pm PDT on 5/13/2020, the AMO website started to return 5XX and users can't access the website.

When we logged onto the AWS console and started to investigate, we noticed that 9 out of 10 instances were in unhealthy state and were taken out of ELB.

The auto scaling group (ASG) had already spawned a few new instances due to health check failure, but the application on them crashed too.

We changed ASG health check from ELB to EC2 to prevent it from keeping spawning new instances and killing old ones. Then we logged onto the remaining old instances and found the following errors.

May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: [pino-mozlog] could not parse: { error: 'SyntaxError: Unexpected end of JSON input', data: '' }
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: [pino-mozlog] could not format: { error: 'Error: invalid pino record', record: {} }
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: [pino-mozlog] could not parse: { error: 'SyntaxError: Unexpected token < in JSON at position 0',
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: data: '<--- Last few GCs --->' }
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: [pino-mozlog] could not format: { error: 'Error: invalid pino record', record: {} }
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: [pino-mozlog] could not parse: { error: 'SyntaxError: Unexpected end of JSON input', data: '' }
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: [pino-mozlog] could not format: { error: 'Error: invalid pino record', record: {} }
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: [pino-mozlog] could not parse: { error: 'SyntaxError: Unexpected token : in JSON at position 4',
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: data:
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: '[229:0x41a7ce0] 565715711 ms: Scavenge 1293.1 (1424.2) -> 1292.3 (1424.8) MB, 2.8 / 0.0 ms  (average mu = 0.273, current mu = 0.262) allocation failure ' }
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: [pino-mozlog] could not format: { error: 'Error: invalid pino record', record: {} }
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: [pino-mozlog] could not parse: { error: 'SyntaxError: Unexpected token : in JSON at position 4',
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: data:
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: '[229:0x41a7ce0] 565715717 ms: Scavenge 1293.2 (1424.8) -> 1292.6 (1425.2) MB, 3.0 / 0.0 ms  (average mu = 0.273, current mu = 0.262) allocation failure ' }
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: [pino-mozlog] could not format: { error: 'Error: invalid pino record', record: {} }
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: [pino-mozlog] could not parse: { error: 'SyntaxError: Unexpected token : in JSON at position 4',
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: data:
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: '[229:0x41a7ce0] 565715722 ms: Scavenge 1293.4 (1425.2) -> 1292.9 (1426.2) MB, 2.8 / 0.0 ms  (average mu = 0.273, current mu = 0.262) allocation failure ' }
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: [pino-mozlog] could not format: { error: 'Error: invalid pino record', record: {} }
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: [pino-mozlog] could not parse: { error: 'SyntaxError: Unexpected end of JSON input', data: '' }
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: [pino-mozlog] could not format: { error: 'Error: invalid pino record', record: {} }
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: [pino-mozlog] could not parse: { error: 'SyntaxError: Unexpected end of JSON input', data: '' }
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: [pino-mozlog] could not format: { error: 'Error: invalid pino record', record: {} }
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: [pino-mozlog] could not parse: { error: 'SyntaxError: Unexpected token < in JSON at position 0',
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: data: '<--- JS stacktrace --->' }
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: [pino-mozlog] could not format: { error: 'Error: invalid pino record', record: {} }
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: [pino-mozlog] could not parse: { error: 'SyntaxError: Unexpected end of JSON input', data: '' }
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: [pino-mozlog] could not format: { error: 'Error: invalid pino record', record: {} }
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: [pino-mozlog] could not parse: { error: 'SyntaxError: Unexpected token = in JSON at position 0',
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: data:
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: '==== JS stack trace =========================================' }
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: [pino-mozlog] could not format: { error: 'Error: invalid pino record', record: {} }
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: [pino-mozlog] could not parse: { error: 'SyntaxError: Unexpected end of JSON input', data: '' }
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: [pino-mozlog] could not format: { error: 'Error: invalid pino record', record: {} }
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: [pino-mozlog] could not parse: { error: 'SyntaxError: Unexpected token : in JSON at position 5',
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: data: '    0: ExitFrame [pc: 0x1d2a07dbe1d]' }
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: [pino-mozlog] could not format: { error: 'Error: invalid pino record', record: {} }
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: [pino-mozlog] could not parse: { error: 'SyntaxError: Unexpected token : in JSON at position 5',
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: data: '    1: StubFrame [pc: 0x1d2a07847bb]' }
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: [pino-mozlog] could not format: { error: 'Error: invalid pino record', record: {} }
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: [pino-mozlog] could not parse: { error: 'SyntaxError: Unexpected token : in JSON at position 5',
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: data: '    2: ConstructFrame [pc: 0x1d2a078d145]' }
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: [pino-mozlog] could not format: { error: 'Error: invalid pino record', record: {} }
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: [pino-mozlog] could not parse: { error: 'SyntaxError: Unexpected token S in JSON at position 0',
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: data: 'Security context: 0x109164e9e6c1 <JSObject>' }
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: [pino-mozlog] could not format: { error: 'Error: invalid pino record', record: {} }
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: [pino-mozlog] could not parse: { error: 'SyntaxError: Unexpected token : in JSON at position 5',
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: data:
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: '    3: DoJoin(aka DoJoin) [0x109164e85e69] [native array.js:~87] [pc=0x1d2a570e90d](this=0x3b8b2d7826f1 <undefined>,l=0x15291b1a6669 <JSArray[3]>,m=3,A=0x3b8b2d7828c9 <true>,w=0x3b8b2d789d61 <String[1]:  >,v=0x3b8b2d7829a1 <false>)' }
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: [pino-mozlog] could not format: { error: 'Error: invalid pino record', record: {} }
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: [pino-mozlog] could not parse: { error: 'SyntaxError: Unexpected token : in JSON at position 5',
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: data: '    4: Join(aka Join) [0x109164e85eb9] [native arr...' }
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: [pino-mozlog] could not format: { error: 'Error: invalid pino record', record: {} }
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: [pino-mozlog] could not parse: { error: 'SyntaxError: Unexpected end of JSON input', data: '' }
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: [pino-mozlog] could not format: { error: 'Error: invalid pino record', record: {} }
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: FATAL ERROR: Ineffective mark-compacts near heap limit Allocation failed - JavaScript heap out of memory
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: 1: 0x8fb090 node::Abort() [/usr/local/bin/node]
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: 2: 0x8fb0dc  [/usr/local/bin/node]
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: 3: 0xb031ce v8::Utils::ReportOOMFailure(v8::internal::Isolate*, char const*, bool) [/usr/local/bin/node]
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: 4: 0xb03404 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, bool) [/usr/local/bin/node]
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: 5: 0xef7462  [/usr/local/bin/node]
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: 6: 0xef7568 v8::internal::Heap::CheckIneffectiveMarkCompact(unsigned long, double) [/usr/local/bin/node]
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: 7: 0xf03642 v8::internal::Heap::PerformGarbageCollection(v8::internal::GarbageCollector, v8::GCCallbackFlags) [/usr/local/bin/node]
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: 8: 0xf03f74 v8::internal::Heap::CollectGarbage(v8::internal::AllocationSpace, v8::internal::GarbageCollectionReason, v8::GCCallbackFlags) [/usr/local/bin/node]
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: 9: 0xf06be1 v8::internal::Heap::AllocateRawWithRetryOrFail(int, v8::internal::AllocationSpace, v8::internal::AllocationAlignment) [/usr/local/bin/node]
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: 10: 0xed0064 v8::internal::Factory::NewFillerObject(int, bool, v8::internal::AllocationSpace) [/usr/local/bin/node]
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: 11: 0x11701ee v8::internal::Runtime_AllocateInNewSpace(int, v8::internal::Object**, v8::internal::Isolate*) [/usr/local/bin/node]
May 14 05:57:45 ip-172-31-46-144 docker-addons-frontend[2730]: 12: 0x1d2a07dbe1d
May 14 05:57:59 ip-172-31-46-144 docker-addons-frontend[2730]: Aborted (core dumped)
May 14 05:57:59 ip-172-31-46-144 docker-addons-frontend[2730]: Done in 565733.25s.

What did you expect to happen?

We should try to find out why the frontend app crashed and fix the issue.

Anything else we should know?

We also found some errors on the addons-server, which happened during the incident time. They may be related.

May 14 05:58:34 ip-172-31-35-155 docker-addons[4927]: {"Timestamp": 1589435914428890112, "Type": "z.files", "Logger": "http_app_addons", "Hostname": "ip-172-31-35-155.us-west-2.compute.internal", "EnvVersion": "2.0", "Severity": 6, "Pid": 4815, "Fields": {"email": "969052585@qq.com(opens in new tab)", "uid": "anonymous-bf27990a604f49389ad18898fc2d49a3", "remoteAddressChain": "117.89.215.150", "msg": "UPLOAD: 'cbad12f6da124ee9a1d433c0aa252fb3_
1.8.1_0.crx' (66543 bytes) to '/mnt/efs/addons.mozilla.org/files/temp/3f87770a3b89463cae0e6fdb7d88eff7.xpi'"}, "severity": 200}
May 14 05:58:34 ip-172-31-35-155 docker-addons[4927]: {"Timestamp": 1589435914489447424, "Type": "z.devhub", "Logger": "http_app_addons", "Hostname": "ip-172-31-35-155.us-west-2.compute.internal", "EnvVersion": "2.0", "Severity": 6, "Pid": 4815, "Fields": {"uid": "anonymous-bf27990a604f49389ad18898fc2d49a3", "remoteAddressChain": "117.89.215.150", "msg": "FileUpload created: cbad12f6da124ee9a1d433c0aa252fb3"}, "severity": 200}
May 14 05:58:34 ip-172-31-35-155 docker-addons[4927]: {"Timestamp": 1589435914493316096, "Type": "z.files.utils", "Logger": "http_app_addons", "Hostname": "ip-172-31-35-155.us-west-2.compute.internal", "EnvVersion": "2.0", "Severity": 3, "Pid": 4815, "Fields": {"uid": "anonymous-bf27990a604f49389ad18898fc2d49a3", "remoteAddressChain": "117.89.215.150", "msg": "XPI parse error", "error": "BadZipFile('File is not a zip file',)", "traceback": "Uncaught exception:\n  File \"/data/olympia/src/olympia/files/utils.py\", line 973, in parse_xpi\n    xpi_info = Extractor.parse(xpi, minimal=minimal)\n  File \"/data/olympia/src/olympia/files/utils.py\", line 150, in parse\n    zip_file = SafeZip(xpi_fobj)\n  File \"/data/olympia/src/olympia/files/utils.py\", line 739, in __init__\n    self.is_valid = self.initialize_and_validate()\n  File \"/data/olympia/src/olympia/files/utils.py\", line 752, in initialize_and_validate\n    zip_file = zipfile.ZipFile(self.source, self.mode)\n  File \"/usr/local/lib/python3.6/zipfile.py\", line 1131, in __init__\n    self._RealGetContents()\n  File \"/usr/local/lib/python3.6/zipfile.py\", line 1198, in _RealGetContents\n    raise BadZipFile(\"File is not a zip file\")\n<class 'zipfile.BadZipFile'>\nBadZipFile('File is not a zip file',)\n"}, "severity": 500}
May 14 05:58:34 ip-172-31-35-155 docker-addons[4927]: {"Timestamp": 1589435914494262784, "Type": "z.devhub", "Logger": "http_app_addons", "Hostname": "ip-172-31-35-155.us-west-2.compute.internal", "EnvVersion": "2.0", "Severity": 6, "Pid": 4815, "Fields": {"uid": "anonymous-bf27990a604f49389ad18898fc2d49a3", "remoteAddressChain": "117.89.215.150", "msg": "could not parse addon for upload 3599151: ['\u672a\u80fd\u89e3\u6790\u6e05\u5355\u6587\u4ef6\u3002']"}, "severity": 200}

┆Issue is synchronized with this Jira Task

bqbn commented 4 years ago

There are more logs shared in this folder: https://drive.google.com/open?id=1G1z11bq3kWUC4jd9hTUO5ZGyovID2ZDe

These logs are from the remaining instances of 5/7/2020 push. The other 5 instances were auto terminated by AWS because they failed ASG health check.

willdurand commented 4 years ago

I have the feeling that we have an uncaught error in the saga layer (related to the fetchSiteStatus saga/action). It's a good candidate for causing all sort of problems, including OOMs.

bqbn commented 4 years ago

We were able to reproduce the issue in -stage env. We captured a core dump file and uploaded it in https://drive.google.com/drive/folders/1G1z11bq3kWUC4jd9hTUO5ZGyovID2ZDe.

KevinMind commented 6 months ago

Old Jira Ticket: https://mozilla-hub.atlassian.net/browse/ADDFRNT-176