Better error messaging with circular references in Eleventy layouts

[weaversam8]

Hey folks, sorry for the lack of a more descriptive issue name, but it isn't immediately apparent to me what's happening here.

I have my project set up to watch the various source files as I edit them (JS, SCSS, and HTML with Eleventy) and while editing, I noticed oddly that Eleventy seemed to crash with a lot of error messages that appeared low level. I believe it happened when I opened up a split terminal and installed another NPM package, but it could've just been a coincidence.

The relevant scripts from my package.json:

// ...
"html-build": "npx eleventy",
"html-watch": "npm run html-build -- --watch",
// ...
"start": "npm-run-all --parallel css-watch js-watch html-watch serve"
// ...

The initial error log that occurred, in the output:

Watching…
File added: src\html\_includes\app.liquid
Writing ./public/editor/index.html from ./src/html/editor.html.
Writing ./public/index.html from ./src/html/index.html.
Writing ./public/story/index.html from ./src/html/story.html.
Writing ./public/404.html from ./src/html/404.html.
Processed 4 files in 0.71 seconds
Watching…
File changed: src\html\_includes\app.liquid
127.0.0.1 - - [30/Apr/2019:22:19:26 +0000] "GET /editor HTTP/1.1" 301 - "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:67.0) Gecko/20100101 Fir "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:67.0) Gecko/20100101 Firefox/67.0"                                                         - "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:67.0) Gecko/20100101 Fi127.0.0.1 - - [30/Apr/2019:22:19:26 +0000] "GET /editor/ HTTP/1.1" 200
- "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:67.0) Gecko/20100101 Firefox/67.0"

<--- Last few GCs --->

[17768:0000020144E6D1F0]  1682621 ms: Mark-sweep 1233.1 (1287.9) -> 1233.0 (1256.9) MB, 3049.4 / 0.0 ms  (average mu = 0.685, current mu = 0.000) last resort GC in old space requested
[17768:0000020144E6D1F0]  1685959 ms: Mark-sweep 1233.0 (1256.9) -> 1233.0 (1256.9) MB, 3338.4 / 0.0 ms  (average mu = 0.525, current mu = 0.000) last resort GC in old space requested


<--- JS stacktrace --->

==== JS stack trace =========================================

    0: ExitFrame [pc: 000001883BADC5C1]
Security context: 0x01e253a1e6e1 <JSObject>
    1: getTemplateLayoutMap [0000035629260BA1] [C:\Users\username\Documents\project-name\static_site\node_modules\@11ty\eleventy\src\TemplateLayout.js:~53] [pc=000001883BD50E25](this=0x00943563c511 <TemplateContent map = 000000C358DC64B9>)
    2: /* anonymous */ [000001CF7AB822D1](this=0x028947f9ad11 <JSGlobal Object>,0x034953ecfcf1 <Object map = 0000...

FATAL ERROR: CALL_AND_RETRY_LAST Allocation failed - JavaScript heap out of memory
 1: 00007FF6CC4F08AA v8::internal::GCIdleTimeHandler::GCIdleTimeHandler+4810
 2: 00007FF6CC4C9C46 node::MakeCallback+4518
 3: 00007FF6CC4CA630 node_module_register+2160
 4: 00007FF6CC75AA4E v8::internal::FatalProcessOutOfMemory+846
 5: 00007FF6CC75A97F v8::internal::FatalProcessOutOfMemory+639
 6: 00007FF6CCC98984 v8::internal::Heap::MaxHeapGrowingFactor+11476
 7: 00007FF6CCC96718 v8::internal::Heap::MaxHeapGrowingFactor+2664
 8: 00007FF6CC839288 v8::internal::Factory::AllocateRawArray+56
 9: 00007FF6CC839C02 v8::internal::Factory::NewFixedArrayWithFiller+66
10: 00007FF6CC8A24DB v8::internal::HashTable<v8::internal::NumberDictionary,v8::internal::NumberDictionaryShape>::EntryToIndex+70043
11: 00007FF6CCCBEBC0 v8::internal::Bitmap::IsClean+30464
12: 000001883BADC5C1
npm ERR! code ELIFECYCLE
npm ERR! errno 134
npm ERR! project-name@0.0.1 html-build: `npx eleventy "--watch"`
npm ERR! Exit status 134
npm ERR!
npm ERR! Failed at the project-name@0.0.1 html-build script.
npm ERR! This is probably not a problem with npm. There is likely additional logging output above.

npm ERR! A complete log of this run can be found in:
npm ERR!     C:\Users\username\AppData\Roaming\npm-cache\_logs\2019-04-30T22_22_03_883Z-debug.log
npm ERR! code ELIFECYCLE
npm ERR! errno 134
npm ERR! project-name@0.0.1 html-watch: `npm run html-build --
--watch`
npm ERR! Exit status 134
npm ERR!
npm ERR! Failed at the project-name@0.0.1 html-watch script.
npm ERR! This is probably not a problem with npm. There is likely additional logging output above.

npm ERR! A complete log of this run can be found in:
npm ERR!     C:\Users\username\AppData\Roaming\npm-cache\_logs\2019-04-30T22_22_08_382Z-debug.log
ERROR: "html-watch" exited with 134.
npm ERR! code ELIFECYCLE
npm ERR! errno 1
npm ERR! project-name@0.0.1 start: `npm-run-all --parallel css-watch js-watch html-watch serve`
npm ERR! Exit status 1
npm ERR!
npm ERR! Failed at project-name@0.0.1 start script.
npm ERR! This is probably not a problem with npm. There is likely additional logging output above.

npm ERR! A complete log of this run can be found in:
npm ERR!     C:\Users\username\AppData\Roaming\npm-cache\_logs\2019-04-30T22_22_13_271Z-debug.log

As you can see, this is quite hefty. I included a successful run of Eleventy from the log right before the error hit... it seemed to come out of the blue. I notice a lot of references to memory issues, but my laptop seems to have enough memory currently free to run JS VM.

The kicker is that now I can't compile anything from Eleventy anymore. I tried to run it again in a new command window with debug flags on and the following output resulted.

Microsoft Windows [Version 10.0.17763.437]
(c) 2018 Microsoft Corporation. All rights reserved.

C:\Users\username>cd Documents

C:\Users\username\Documents>cd oroject-name

C:\Users\username\Documents\project-name>cd static_site

C:\Users\username\Documents\project-name\static_site>set DEBUG=Eleventy* eleventy

C:\Users\username\Documents\project-name\static_site>echo %DEBUG%
Eleventy* eleventy

C:\Users\username\Documents\project-name\static_site>npx eleventy
  Eleventy:UserConfig Resetting EleventyConfig to initial values. +0ms
  Eleventy:Config Setting up global TemplateConfig. +0ms
  Eleventy:UserConfig Adding universal filter 'slug' +15ms
  Eleventy:UserConfig Adding universal filter 'url' +2ms
  Eleventy:TemplateConfig rootConfig { templateFormats: [ 'liquid', 'ejs', 'md', 'hbs', 'mustache', 'haml', 'pug', 'njk', 'html', 'jstl', '11ty.js' ], pathPrefix: '/', markdownTemplateEngine: 'liquid', htmlTemplateEngine: 'liquid', dataTemplateEngine: 'liquid', passthroughFileCopy: true, htmlOutputSuffix: '-o', jsDataFileSuffix: '.11tydata', keys: { package: 'pkg', layout: 'layout', permalink: 'permalink', permalinkRoot: 'permalinkBypassOutputDir', engineOverride: 'templateEngineOverride' }, dir: { input: '.', includes: '_includes', data: '_data', output: '_site' }, filters: {}, handlebarsHelpers: {}, nunjucksFilters: {} } +0ms
  Eleventy:TemplateConfig Merging config with C:/Users/username/Documents/project-name/static_site/.eleventy.js +18ms
  Eleventy:TemplateConfig localConfig: { dir: { input: './src/html', output: './public' }, templateFormats: undefined, filters: {}, linters: {}, layoutAliases: {}, passthroughCopies: {}, liquidOptions: {}, liquidTags: {}, liquidFilters: { slug: [Function], url: [Function] }, liquidShortcodes: {}, liquidPairedShortcodes: {}, nunjucksFilters: { slug: [Function], url: [Function] }, nunjucksAsyncFilters: {}, nunjucksTags: {}, nunjucksShortcodes: {}, nunjucksPairedShortcodes: {}, handlebarsHelpers: { slug: [Function], url: [Function] }, handlebarsShortcodes: {}, handlebarsPairedShortcodes: {}, javascriptFunctions: { slug: [Function], url: [Function] }, pugOptions: {}, ejsOptions: {}, markdownHighlighter: null, libraryOverrides: {}, dynamicPermalinks: true, useGitIgnore: true, dataDeepMerge: false, experiments: Set {}, watchJavaScriptDependencies: true, browserSyncConfig: {} } +5ms
  Eleventy:TemplateConfig overrides: {} +18ms
  Eleventy:TemplateConfig Current configuration: { templateFormats: [ 'liquid', 'ejs', 'md', 'hbs', 'mustache', 'haml', 'pug', 'njk', 'html', 'jstl', '11ty.js' ], pathPrefix: '/', markdownTemplateEngine: 'liquid', htmlTemplateEngine: 'liquid', dataTemplateEngine: 'liquid', passthroughFileCopy: true, htmlOutputSuffix: '-o', jsDataFileSuffix: '.11tydata', keys: { package: 'pkg', layout: 'layout', permalink: 'permalink', permalinkRoot: 'permalinkBypassOutputDir', engineOverride: 'templateEngineOverride' }, dir: { input: './src/html', includes: '_includes', data: '_data', output: './public' }, filters: {}, handlebarsHelpers: { slug: [Function], url: [Function] }, nunjucksFilters: { slug: [Function], url: [Function] }, linters: {}, layoutAliases: {}, passthroughCopies: {}, liquidOptions: {}, liquidTags: {}, liquidFilters: { slug: [Function], url: [Function] }, liquidShortcodes: {}, liquidPairedShortcodes: {}, nunjucksAsyncFilters: {}, nunjucksTags: {}, nunjucksShortcodes: {}, nunjucksPairedShortcodes: {}, handlebarsShortcodes: {}, handlebarsPairedShortcodes: {}, javascriptFunctions: { slug: [Function], url: [Function] }, pugOptions: {}, ejsOptions: {}, markdownHighlighter: null, libraryOverrides: {}, dynamicPermalinks: true, useGitIgnore: true, dataDeepMerge: false, experiments: Set {}, watchJavaScriptDependencies: true, browserSyncConfig: {} } +3ms
  Eleventy:CommandCheck command: eleventy   +0ms
  Eleventy:TemplatePassthroughManager Resetting counts to 0 +0ms
  Eleventy:EleventyFiles C:/Users/username/Documents/project-name/static_site/.gitignore,src/html/.gitignore ignoring: !./public/** +0ms
  Eleventy Directories:
  Eleventy Input: ./src/html
  Eleventy Data: src/html/_data
  Eleventy Includes: src/html/_includes
  Eleventy Output: ./public
  Eleventy Template Formats: liquid,ejs,md,hbs,mustache,haml,pug,njk,html,jstl,11ty.js +0ms
  Eleventy:EleventyFiles Searching for: [ './src/html/**/*.liquid', './src/html/**/*.ejs', './src/html/**/*.md', './src/html/**/*.hbs', './src/html/**/*.mustache', './src/html/**/*.haml', './src/html/**/*.pug', './src/html/**/*.njk', './src/html/**/*.html', './src/html/**/*.jstl', './src/html/**/*.11ty.js', '!./public/**', '!./public/**', '!./src/html/_includes/**', '!./src/html/_data/**' ] +48ms
  Eleventy:TemplateWriter Found: [ './src/html/404.html', './src/html/editor.html', './src/html/index.html', './src/html/story.html' ] +0ms
  Eleventy:TemplatePassthroughManager TemplatePassthrough copy started. +98ms
  Eleventy:TemplatePassthroughManager `passthroughFileCopy` config paths: {} +2ms
  Eleventy:TemplatePassthroughManager `passthroughFileCopy` config normalized paths: [] +1ms
  Eleventy:TemplateData Using '.11tydata' to find data files. +0ms
  Eleventy:TemplateData getLocalDataPaths('./src/html/404.html'): [ './src/html/404.11tydata.js', './src/html/404.11tydata.json', './src/html/404.json' ] +3ms
  Eleventy:TemplateData Using '.11tydata' to find data files. +6ms
  Eleventy:TemplateData getLocalDataPaths('./src/html/editor.html'): [ './src/html/editor.11tydata.js', './src/html/editor.11tydata.json', './src/html/editor.json' ] +4ms
  Eleventy:TemplateData Using '.11tydata' to find data files. +9ms
  Eleventy:TemplateData getLocalDataPaths('./src/html/index.html'): [ './src/html/index.11tydata.js', './src/html/index.11tydata.json', './src/html/index.json' ] +2ms
  Eleventy:TemplateData Using '.11tydata' to find data files. +13ms
  Eleventy:TemplateData getLocalDataPaths('./src/html/story.html'): [ './src/html/story.11tydata.js', './src/html/story.11tydata.json', './src/html/story.json' ] +3ms
  Eleventy:TemplatePassthroughManager TemplatePassthrough copy finished. Current count: 0 +54ms

<--- Last few GCs --->

[21704:0000020B4A488F10]   116506 ms: Mark-sweep 1223.9 (1277.9) -> 1223.8 (1246.9) MB, 1683.5 / 0.0 ms  (average mu = 0.739, current mu = 0.000) last resort GC in old space requested
[21704:0000020B4A488F10]   117805 ms: Mark-sweep 1223.8 (1246.9) -> 1223.8 (1246.9) MB, 1299.7 / 0.0 ms  (average mu = 0.606, current mu = 0.000) last resort GC in old space requested


<--- JS stacktrace --->

==== JS stack trace =========================================

    0: ExitFrame [pc: 00000153D0F5C5C1]
Security context: 0x01cfbb31e6e1 <JSObject>
    1: getTemplateLayoutMap [000000903D502381] [C:\Users\username\Documents\project-name\static_site\node_modules\@11ty\eleventy\src\TemplateLayout.js:~53] [pc=00000153D15B3C42](this=0x0181fe4a85a9 <TemplateContent map = 000002E0238BB8D9>)
    2: /* anonymous */ [0000036840EB6AA1](this=0x02f1ea71ad11 <JSGlobal Object>,0x036840eb69a1 <Object map = 0000...

FATAL ERROR: CALL_AND_RETRY_LAST Allocation failed - JavaScript heap out of memory
 1: 00007FF6CC4F08AA v8::internal::GCIdleTimeHandler::GCIdleTimeHandler+4810
 2: 00007FF6CC4C9C46 node::MakeCallback+4518
 3: 00007FF6CC4CA630 node_module_register+2160
 4: 00007FF6CC75AA4E v8::internal::FatalProcessOutOfMemory+846
 5: 00007FF6CC75A97F v8::internal::FatalProcessOutOfMemory+639
 6: 00007FF6CCC98984 v8::internal::Heap::MaxHeapGrowingFactor+11476
 7: 00007FF6CCC96718 v8::internal::Heap::MaxHeapGrowingFactor+2664
 8: 00007FF6CC839288 v8::internal::Factory::AllocateRawArray+56
 9: 00007FF6CC839C02 v8::internal::Factory::NewFixedArrayWithFiller+66
10: 00007FF6CC8A24DB v8::internal::HashTable<v8::internal::NumberDictionary,v8::internal::NumberDictionaryShape>::EntryToIndex+70043
11: 00007FF6CCCBEBC0 v8::internal::Bitmap::IsClean+30464
12: 00000153D0F5C5C1

C:\Users\username\Documents\project-name\static_site>

Also, worth noting that the above retry attempt hung for several minutes. I ran it with debug flags, saw it hang (right after TemplatePassthrough copy finished), started writing this issue, and then looked back and realized it had crashed.

I'm probably going to restart my computer next but figured I'd capture this here now. Any ideas as to what could've caused this? I know it might not be related to the project but I wanted to document it in case it is.

[Ryuno-Ki]

Could you share some more information?

• Node version
• NPM version
• Operation System

I believe, this could help speed up debugging.
Would it work if you run those watch tasks in different terminals?
(I know, not as comfortable … but I usually see GC-errors happening with SASS and want to exclude that CSS-watch is the actual offender here).

[weaversam8]

Hey @Ryuno-Ki!

Node Version: v10.14.2
NPM Version: 6.2.0
Operating System: Windows 10 x64 Pro

I actually ran the second attempt (the second log I pasted in the initial issue) in a separate terminal after I had terminated all the watch tasks. I was literally just trying to run html-build as the only task that time, no watch tasks.

Diving into the code again, I think I found what it was-

I created a layout called app.liquid and then in the front-matter put the following:

---
layout: app
---

This created an infinite loop. Glad I figured it out. Might be nice to try and catch this sort of thing with an exception in the future.

[weaversam8]

I'd be happy to submit a PR if you can suggest where in the code I'd need to go to make the change :)

[Ryuno-Ki]

@weaversam8 Glad that you figured out the root issue :-)
I'd assume that something like a stack depth could be handy … like „recursing max N steps deep”.

@zachleat Your project! You know best where too look at.

[colabottles]

I am getting the same error and did not want to start a new issue so apologies if I posted in the wrong place. Here's what I am seeing via the terminal;

eleventy

<--- Last few GCs --->

[92851:0x10268f000]    74831 ms: Mark-sweep 1230.9 (1255.5) -> 1230.9 (1254.5) MB, 819.6 / 0.0 ms  (average mu = 0.641, current mu = 0.000) last resort GC in old space requested
[92851:0x10268f000]    75654 ms: Mark-sweep 1230.9 (1254.5) -> 1230.9 (1254.5) MB, 822.9 / 0.0 ms  (average mu = 0.467, current mu = 0.000) last resort GC in old space requested


<--- JS stacktrace --->

==== JS stack trace =========================================

    0: ExitFrame [pc: 0x19df9595be3d]
Security context: 0x2f790af1e6e9 <JSObject>
    1: getTemplateLayoutMap [0x2f7958a38531] [/usr/local/lib/node_modules/@11ty/eleventy/src/TemplateLayout.js:~54] [pc=0x19df95b87d16](this=0x2f790e1b1599 <TemplateContent map = 0x2f790af97441>)
    2: /* anonymous */ [0x2f7903d022f1](this=0x2f79fa79ad81 <JSGlobal Object>,0x2f793242eb71 <Object map = 0x2f790af9ae59>)
    3: StubFrame [pc: 0x19df959419b1]
  ...

FATAL ERROR: CALL_AND_RETRY_LAST Allocation failed - JavaScript heap out of memory
 1: 0x10003c597 node::Abort() [/usr/local/bin/node]
 2: 0x10003c7a1 node::OnFatalError(char const*, char const*) [/usr/local/bin/node]
 3: 0x1001ad575 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, bool) [/usr/local/bin/node]
 4: 0x100579242 v8::internal::Heap::FatalProcessOutOfMemory(char const*) [/usr/local/bin/node]
 5: 0x100582744 v8::internal::Heap::AllocateRawWithRetryOrFail(int, v8::internal::AllocationSpace, v8::internal::AllocationAlignment) [/usr/local/bin/node]
 6: 0x100551a46 v8::internal::Factory::NewFixedArrayWithFiller(v8::internal::Heap::RootListIndex, int, v8::internal::Object*, v8::internal::PretenureFlag) [/usr/local/bin/node]
 7: 0x1004f8e6e v8::internal::(anonymous namespace)::ElementsAccessorBase<v8::internal::(anonymous namespace)::FastPackedObjectElementsAccessor, v8::internal::(anonymous namespace)::ElementsKindTraits<(v8::internal::ElementsKind)2> >::GrowCapacity(v8::internal::Handle<v8::internal::JSObject>, unsigned int) [/usr/local/bin/node]
 8: 0x100793fef v8::internal::Runtime_GrowArrayElements(int, v8::internal::Object**, v8::internal::Isolate*) [/usr/local/bin/node]
 9: 0x19df9595be3d
[1]    92851 abort      eleventy

I had been modifying the Eleventy-Netlfy-Boilerplate here but ran into some issues with templating again. So as of right now, I cannot deploy for whatever reason, to Netlify.

I was last successful about a week and a half ago, so I don't know what had changed since then, I know I did an OS update on my Mac to the latest Mojave version, but that was pretty much it. Any help would be greatly appreciated. Thanks.

[weaversam8]

@colabottles I'm no expert, but the JavaScript heap out of memory error to me sounds like an infinite recursion issue (like I had.) Have you looked for any loops in your templates (either of the same type as mine or of a different type?)

Investigating the limited stack trace, if we look at the getTemplateLayoutMap() method in TemplateLayout.js, and we work off the Runtime_GrowArrayElements(...) lead in the stack trace, I'm guessing an array has grown to a size that is too large for the heap. Line 61 and Line 70 both include calls to the .push(...) method on an instance of Array. I am not exactly sure what the getTemplateLayoutMap() method is supposed to do, but it looks like it's processing the front matter of the page to try and get the template... that makes me suspicious that it's some sort of infinite loop in your template structure...

Again, I'm no expert in the internals of V8 so I don't really know how accurate this is, but maybe this is a lead to follow...

[colabottles]

@weaversam8 I will take a look through, That had crossed my mind when I initially read your issue. I didn't see anything glaring on my first pass through, but now that I have some time, I'm going to go back through and go through with a fine tooth comb. Thanks for your reply!

[colabottles]

@weaversam8 All files were fine, no loops in any template that I could see, but I'm no expert on this so I could be overlooking something someone with more experience would be able to spot quickly. I may try to back what I have up for code and then start over again from scratch. Not sure. I'm giving another few days before I do that. I'm also trying to find someone that would be willing to guide me through this and some templating questions I had about Eleventy.

[weaversam8]

@colabottles probably makes sense to try and make a minimum replication case you can publish... starting from scratch (or walking back to the last working state) should help with that.

If you have any questions about Eleventy (I've only worked with it a bit) feel free to reach out. You can get in touch with me via my Keybase!

[zachleat]

Thanks for the issue @weaversam8. Do you care if I switch it over to a Enhancement Request for loop detection in Eleventy layouts? I think this would be a great addition. Sometimes they are hard to spot, I’d love to have better messaging around this

[weaversam8]

@zachleat No, I don't mind! That sounds like a great plan!

[zachleat]

This repository is now using lodash style issue management for enhancements. This means enhancement issues will now be closed instead of leaving them open.

View the enhancement backlog here. Don’t forget to upvote the top comment with 👍!

[zachleat]

Thanks to @AleksandrHovhannisyan this shipped with 2.0.0-canary.10!

#2076