feature: improved logging

[blackmagic0]

Debug mode improves console errors and catches syntax errors that alpine does not report in a meaningful way. When debug mode is enabled console errors will include the element where the error was thrown.

This is an expensive operation because Syntax Errors can only be detected through events on the window, additionally logging elements to the console is expensive. Because of this, by default debug mode is disabled similar to React __DEV__ not being enabled for prod builds.

With this feature a variety of common development issues can be resolved faster using browsers development tools to locate broken elements and diagnose issues previously hard decipher from Alpine's original error logs.

Can be enabled by calling the Alpine.enableDebugMode() before Alpine.start() is called.

Primarily this will help with debugging the following types of issues:

• Invalid identifiers and expressions in directives
• Syntax Errors caused by malformed expressions in x-data

Here is a codepen example of the feature: https://codepen.io/jacobpozaic/pen/XWMLEmp
Here is a codepen example of the feature ( new iteration ) : https://codepen.io/jacobpozaic/pen/eYvqwbg
More examples in tests

Update:

• Improved error messages in console
• Fix issue logging errors present in previous implementation when x-data is initialized with reference/syntax error, evaluated data will use empty object instead of undefined so nested errors can be found and logged, and to prevent bogus errors
• Trying to maintain compatible with devtools

[blackmagic0]

You can find a benchmark of execution time differences from alpine:init to alpine:initialized when debug mode was enabled/disabled here: https://docs.google.com/spreadsheets/d/1FVO6UXwXYkkysJ6YcNfhnJZM1_qu5HTig2GiVj1xgb0/edit?usp=sharing

If you would like to try this in your own application here is what we did to measure execution time:

<script>
    window.alpineLoadTime = 0;
    document.addEventListener( "alpine:init", () => {
        window.alpineLoadTime = (new Date()).getTime();
    } );
    document.addEventListener( "alpine:initialized", () => {
        window.alpineLoadTime = (new Date()).getTime() - window.alpineLoadTime;
        console.log("Alpine Loading Took:" + window.alpineLoadTime );
    } );
</script>

[danddanddand]

I wonder if this should be turned on by default for CDN build and off by default for minified build. I would hate to see people have this on in prod and take up useless cpu cycles but thinking of examples like this which have few elements using common name like show would benefit from it being on by default.

For things like codepen/repl.it/jsfiddle/etc you'd always want debug mode on to clean up these errors.

[danddanddand]

Please don't merge this.

I did some more testing tonight and I think there is better way to do this that won't require the window.addEventListener( "error", listener ) crap (and a mode to compensate for using that strategy). When @JacobPozaic and I originally coded it we couldn't catch the

const func = new AsyncFunction( ['__self', 'scope'], `with (scope) { __self.result = ${rightSideSafeExpression} }; __self.finished = true; return __self.result;` );

and it seemed like it was getting hoisted to global scope. The event strategy works because that constructor is evaluated immediately and because it's on different scope, removing the event listener always works (but adding/removing all those event listeners might be expensive).

Note: async functions created with the AsyncFunction constructor do not create closures to their creation contexts; they are always created in the global scope.

When running them, they will only be able to access their own local variables and global ones, not the ones from the scope in which the AsyncFunction constructor was called.
(source: https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Global_Objects/AsyncFunction#description).

I think we might have been mistaken so we'll play with this Friday and likely simplify this and tidy tests up.

[calebporzio]

Thanks for looking into this.

[HugoDF]

@calebporzio what was wrong with the approach we had in v2 of throwing the error and in some cases attaching additional information to it? That didn't require a way to enabled/disable the "debug mode"

[HugoDF]

Syntax Errors can only be detected through events on the window, additionally logging elements to the console is expensive

I'm not sure about this, surely we can try/catch or .catch() the relevant functionality to handle errors.

From prior research, if some of the code that is throwing is inside a Promise chain or async function you'll need to handle both "error" and "unhandledrejection", see https://github.com/alpine-collective/alpinejs-devtools/blob/master/packages/shell-chrome/src/backend.js#L108-L120

For reference these are the PRs that added support in v2

• Feat: better (eval) error messages/context #887
• Attach el + expression to eval error #1000

(this is probably not relevant to anyone else, but whatever we end up with it would be useful that the solution that ends up being implemented can support displaying errors in the devtools alpine-collective/alpinejs-devtools#247)

[danddanddand]

Thanks @HugoDF, we were working under some false assumptions with initial implementation but we have mostly working cleaner version without need for debug mode garbage. We are just trying to sort out side effects but I suspect we'll have working branch for review by 5pm EST

[HugoDF]

Sure thing

It would be ideal if the implementation was 1-1 with Alpine v2 in terms of adding details to the errors + using console.warn, unless @calebporzio has a new direction he wants to take.

[danddanddand]

It would be ideal if the implementation was 1-1 with Alpine v2 in terms of adding details to the errors + using console.warn, unless @calebporzio has a new direction he wants to take.

Okay, sorry we come from react world with dev mode using console.error so we didn't put much thought into it but we'll switch to console.warn

[calebporzio]

@HugoDF - nothing was wrong with it. I liked it - I'm not fully tracking what this PR uniquely offers anyways. I'm down for a PR to make it work like V2

[danddanddand]

nothing was wrong with it. I liked it - I'm not fully tracking what this PR uniquely offers anyways. I'm down for a PR to make it work like V2

This is what we're implementing, it should work same/better than V2 and be compatible with devtools (alpine-collective/alpinejs-devtools#247). We're just trying to handle some edge cases right now where V3 bombs in new tests. Likely V2 would've bombed too but we're getting closer.

[blackmagic0]

@HugoDF We have updated this, can you confirm this is compatible with devtools?

[HugoDF]

@JacobPozaic I'll test it out and let you know but the code looks like it should be compatible 👍

[danddanddand]

I added test to confirm empty error on init is caught/logged correctly related to this (#1652)

Note: x-init should probably short circuit itself before evaluation tho

[blackmagic0]

Fixed merge conflicts

[danddanddand]

This is ready for review or feedback. I've been using this build for a few days of development and it's been solid and useful.

There are a few ways to make the tests more sophisticated like attaching error listener and asserting element and expression got added but I'm not sure it's needed?

[HugoDF]

What's the reason for this swallowing the error?

if the error in x-data is not thrown Devtools won't pick it up

[danddanddand]

In those cases I think it was causing crazy down the line side effects as well that were essentially bogus errors because future lifecycle stuff like injecting magics depended on defined data. That's based on my foggy memory since it was last week but I'll know more once I test it a bit more again.

@danddanddand the way this was dealt with in v2 was to intercept all errors and re-throw them out of band using setTimeout, see:

https://github.com/alpinejs/alpine/blob/2.x/src/index.js#L94-L98

Okay we will try that

[blackmagic0]

Made a change that should address this now

[HugoDF]

@danddanddand @JacobPozaic I've tried it out with devtools and it looks like errors during x-on:click are being picked up fine but not ones during x-data/x-init, seems to be linked to the rethrows logic.

[danddanddand]

I've tried it out with devtools and it looks like errors during x-on:click are being picked up fine but not ones during x-data/x-init, seems to be linked to the rethrows logic.

@HugoDF I'm a little foggy on it now, but I'm going to get together with @JacobPozaic shortly to go over it. I think it was related to trying to handle test below having multiple errors be displayed and the way javascript interpreter was evaluating it. Seemed to hoist the replaceItems reference error out of the try/catch so there was no longer opportunity to intercept it and append el/expression. I'll dig into it again with him and see how throwing error is handled in those cases. I think we just came to conclusion since we couldn't actually stop evaluation on that one and we know expression is invalid, safer to continue with safe expression and because syntax error was hoisted it was in console anyway (just not with el/expression). In those cases I think it was causing crazy down the line side effects as well that were essentially bogus errors because future lifecycle stuff like injecting magics depended on defined data. That's based on my foggy memory since it was last week but I'll know more once I test it a bit more again.

test('x-data with reference error and multiple errors',
    [html`
        <div id="xdata" x-data="{ items : [ {v:'one'},{v:'two'}], replaceItems }">
            <template id="xtext" x-for="item in items">
                <span x-text="item.v"></span>
            </template>
        </div>
    `,
        setupConsoleInterceptor( "xdata", "xtext" )
    ],
    assertConsoleInterceptorHadErrorWithCorrectElement()
)

[HugoDF]

In those cases I think it was causing crazy down the line side effects as well that were essentially bogus errors because future lifecycle stuff like injecting magics depended on defined data. That's based on my foggy memory since it was last week but I'll know more once I test it a bit more again.

@danddanddand the way this was dealt with in v2 was to re-throw errors out of band using setTimeout, see:

alpine/src/index.js

Lines 94 to 98 in ffba225

	} catch (error) {
	setTimeout(() => {
	throw error
	}, 0)
	}

[HugoDF]

I'm getting an interesting issue with a broken x-data at the moment, interesting because the error is different in Firefox and Chrome

Chrome stack trace

Uncaught TypeError: Cannot set property 'result' of undefined
    at cdn.js:379
    at tryCatch (cdn.js:406)
    at evaluate (cdn.js:329)
    at cdn.js:2275
    at Function.<anonymous> (cdn.js:688)
    at flushHandlers (cdn.js:452)
    at stopDeferring (cdn.js:456)
    at deferHandlingDirectives (cdn.js:459)
    at initTree (cdn.js:649)
    at cdn.js:607

Firefox stack trace

Uncaught TypeError: func is undefined
    generateEvaluatorFromString http://localhost:8080/cdn.js:379
    tryCatch http://localhost:8080/cdn.js:406
    evaluate http://localhost:8080/cdn.js:329
    <anonymous> http://localhost:8080/cdn.js:2275
    skipDuringClone http://localhost:8080/cdn.js:688
    flushHandlers http://localhost:8080/cdn.js:452
    stopDeferring http://localhost:8080/cdn.js:456
    deferHandlingDirectives http://localhost:8080/cdn.js:459
    initTree http://localhost:8080/cdn.js:649
    start http://localhost:8080/cdn.js:607
    onMutate http://localhost:8080/cdn.js:188
    onMutate http://localhost:8080/cdn.js:188
    MutationCallback* http://localhost:8080/cdn.js:108
    <anonymous> http://localhost:8080/cdn.js:2541

[danddanddand]

@HugoDF I think I'm going to try going back to strategy of having the safeAsyncFunction return a valid result every time because in trying to use this version, it's not as good of a dev experience with errors like yours above. There are more down stream side effects that just a result of having func that is a ticking time bomb like in your examples. I'll play with it some more today. Our tests are proving that exceptions that get through have el/expression added and console warning is there with element/expression. We just have to be more careful about swallowing the exception. If you'd like to discuss or peer program with us just chat me on discord.

[HugoDF]

Yeah maybe

We could dispatch alpine:error events on error? With the element and expression, that would work as well and get rid of the whole crashing/error situation.

[calebporzio]

Any update on this? Mainly looking for @HugoDF to approve of this PR. I think he originally implemented the handling in V2 so I'd like for his stamp of approval before going any further. Thanks

[danddanddand]

I have not looked at it in a while but I’ve used this branch a lot for development because it was only way to find needle in the haystack errors (if you have a lot of Alpine components on the page and get unexpected error). I’ll bring it up to date tomorrow at work and review it again.

My main issue with branch is the way evaluations were being evaluated asynchronously I don’t like catching and re-throwing error as in many cases it lead to down the stream errors. I think it would work better if evaluation wasn’t async but I’m guessing you have reasons for it. I’d personally prefer to return empty object and not throw the error (just log it and dispatch event like @HugoDF suggested). That also seemed to be strategy of petite vue which was done after this branch (see last line of https://github.com/vuejs/petite-vue/blob/main/src/eval.ts). They aren’t doing async evaluation so less balls in air.

Anyway, I’ll update branch with @JacobPozaic this week and likely recommend @HugoDF reviews again for merge. If you have any thoughts on above might help us.

[calebporzio]

Great, thanks @danddanddand

[blackmagic0]

An alternative implementation @danddanddand and I prefer is here: #1904

Can you please review @HugoDF

[HugoDF]

An alternative implementation @danddanddand and I prefer is here: #1904

Can you please review @HugoDF

That PR looks reasonable approach wise

I'll see what it'll take to make devtools display the right info

[blackmagic0]

Closed, other PR is preferable. #1904