Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Binding errors are being logged even before DataContext is set #5762

Closed
MarchingCube opened this issue Apr 12, 2021 · 11 comments · Fixed by #13970
Closed

Binding errors are being logged even before DataContext is set #5762

MarchingCube opened this issue Apr 12, 2021 · 11 comments · Fixed by #13970
Assignees
Labels

Comments

@MarchingCube
Copy link
Collaborator

Describe the bug
After enabling binding error logging in my app I've noticed that there are literally thousands of errors reported every time I do something.

Many are reported when binding is initialized but before DataContext is set. This causes "null target" notifications to be raised and logged.

Examples from ControlCatalog:

[Binding] Error in binding to 'Avalonia.Controls.NativeMenuItem'.'Command': 'Null value in expression ''.' (NativeMenuItem #44307222)
[Binding] Error in binding to 'Avalonia.Controls.NativeMenuItem'.'IsChecked': 'Null value in expression ''.' (NativeMenuItem #44307222)
[Binding] Error in binding to 'Avalonia.Controls.NativeMenuItem'.'Command': 'Null value in expression ''.' (NativeMenuItem #63220684)
[Binding] Error in binding to 'Avalonia.Controls.NativeMenuItem'.'IsChecked': 'Null value in expression ''.' (NativeMenuItem #63220684)
[Binding] Error in binding to 'Avalonia.Controls.NativeMenuItem'.'Command': 'Null value in expression ''.' (NativeMenuItem #32115247)
[Binding] Error in binding to 'Avalonia.Controls.NativeMenuItem'.'IsChecked': 'Null value in expression ''.' (NativeMenuItem #32115247)

To Reproduce

  1. Set a breakpoint in ExpressionNode.TargetNullNotification
  2. Start ControlCatalog.
  3. Observe breakpoint being hit constantly

Expected behavior
I think logging errors before DataContext is set only causes confusion and degrades performance. One might think that binding has an actual problem but said binding will function correctly as soon as DataContext is set.

Since general UI creation is like

  1. Create a view (control)
  2. Assign DataContext

we can't expect DataContext to be set while initializing objects.

Desktop (please complete the following information):

  • OS: Windows
  • Version: master
@grokys
Copy link
Member

grokys commented Apr 13, 2021

Yeah I've noticed the binding errors in NativeMenuItem but this happens because NativeMenuItem isn't a control and doesn't override LogBindingError as Visual does. We need to fix this, but I think it's a different problem to the one you're talking about.

However I've not been able to reproduce this with controls. As you can see from the above link they should only log binding errors once they're attached to a logical or visual tree.

@timothyparez
Copy link

timothyparez commented Jul 9, 2021

I believe I am seeing this with KeyBinding

[Binding] Error in binding to 'Avalonia.Input.KeyBinding'.'Command': 'Null value in expression ''.' (KeyBinding #38446258)
[Binding] Error in binding to 'Avalonia.Input.KeyBinding'.'Command': 'Null value in expression ''.' (KeyBinding #10472004)

Desktop

  • Ubuntu 20.10
  • Latest NuGet Package

@grokys
Copy link
Member

grokys commented Aug 23, 2021

I've taken more of a look into this, and the problem is that while in Visual we suppress binding errors before a control is attached to a tree, things like NativeMenuItem and KeyBinding inherit directly from AvaloniaObject so we don't have that concept.

One solution might be to on a case-by-case basis add to NativeMenuItem, KeyBinding etc a check to see if DataContext is null and if so don't log the error, however this has some downsides: specifically, if a binding isn't using DataContext (e.g. using an explicit Source) then useful errors could be hidden from the log.

Ideally we'd be able to detect when a binding is using DataContext and only check for a null DataContext in that case, but we don't have that information available at the point where a binding logs an error.

I think this one will either have to be tackled as part of a general overhaul of our binding infrastructure, or we can use the hack mentioned above. Thoughts?

@timothyparez
Copy link

I do not just get this for KeyBinding I also get this for normal bindings.

[Binding] Error in binding to 'Avalonia.Controls.TextBlock'.'Text': 'Null value in expression 'User'.' (TextBlock #53517805)
[Binding] Error in binding to 'Avalonia.Controls.TextBlock'.'Text': 'Null value in expression 'User'.' (TextBlock #11898202)

@GaNacereddine
Copy link

@MarchingCube do you remember how to disable them?

@maxkatz6
Copy link
Member

@MarchingCube do you remember how to disable them?

You can implement ILogSink and set property Logger.Sink with your custom logger sink implementation. In which you can filter log messages.

grokys added a commit that referenced this issue Sep 21, 2023
As `BindingExpression` now has enough information to decide when it's appropriate to log an error/warning or not.

Fixes #5762
Fixes #9422
grokys added a commit that referenced this issue Sep 21, 2023
As `BindingExpression` now has enough information to decide when it's appropriate to log an error/warning or not.

Fixes #5762
Fixes #9422
grokys added a commit that referenced this issue Sep 22, 2023
As `BindingExpression` now has enough information to decide when it's appropriate to log an error/warning or not.

Fixes #5762
Fixes #9422
grokys added a commit that referenced this issue Sep 22, 2023
As `BindingExpression` now has enough information to decide when it's appropriate to log an error/warning or not.

Fixes #5762
Fixes #9422
grokys added a commit that referenced this issue Sep 22, 2023
As `BindingExpression` now has enough information to decide when it's appropriate to log an error/warning or not.

Fixes #5762
Fixes #9422
grokys added a commit that referenced this issue Oct 16, 2023
As `BindingExpression` now has enough information to decide when it's appropriate to log an error/warning or not.

Fixes #5762
Fixes #9422
grokys added a commit that referenced this issue Oct 18, 2023
As `BindingExpression` now has enough information to decide when it's appropriate to log an error/warning or not.

Fixes #5762
Fixes #9422
@hhyyrylainen
Copy link

I updated to Avalonia 11.0.6 (from the 0.x versions) and I noticed that on shutdown I now get a bunch of:

2024-01-11 16:19:33.6146|INFO|ThriveLauncher.AvaloniaLogger|[Binding]Error in binding to 'Avalonia.Animation.AnimatorKeyFrame'.'Value': 'Null value in expression '{empty}' at '$parent[ProgressBar, 0]'.'(AnimatorKeyFrame #30481338)
2024-01-11 16:19:33.6213|INFO|ThriveLauncher.AvaloniaLogger|[Binding]Error in binding to 'Avalonia.Animation.AnimatorKeyFrame'.'Value': 'Null value in expression '{empty}' at '$parent[ProgressBar, 0]'.'(AnimatorKeyFrame #5896594)
2024-01-11 16:19:33.6267|INFO|ThriveLauncher.AvaloniaLogger|[Binding]Error in binding to 'Avalonia.Animation.AnimatorKeyFrame'.'Value': 'Null value in expression '{empty}' at '$parent[ProgressBar, 0]'.'(AnimatorKeyFrame #53069346)
2024-01-11 16:19:33.6318|INFO|ThriveLauncher.AvaloniaLogger|[Binding]Error in binding to 'Avalonia.Animation.AnimatorKeyFrame'.'Value': 'Null value in expression '{empty}' at '$parent[ProgressBar, 0]'.'(AnimatorKeyFrame #7862068)
2024-01-11 16:19:33.6371|INFO|ThriveLauncher.AvaloniaLogger|[Binding]Error in binding to 'Avalonia.Animation.AnimatorKeyFrame'.'Value': 'Null value in expression '{empty}' at '$parent[ProgressBar, 0]'.'(AnimatorKeyFrame #3649754)
2024-01-11 16:19:33.6411|INFO|ThriveLauncher.AvaloniaLogger|[Binding]Error in binding to 'Avalonia.Animation.AnimatorKeyFrame'.'Value': 'Null value in expression '{empty}' at '$parent[ProgressBar, 0]'.'(AnimatorKeyFrame #32847787)
2024-01-11 16:19:33.6459|INFO|ThriveLauncher.AvaloniaLogger|[Binding]Error in binding to 'Avalonia.Animation.AnimatorKeyFrame'.'Value': 'Null value in expression '{empty}' at '$parent[ProgressBar, 0]'.'(AnimatorKeyFrame #27194634)
2024-01-11 16:19:33.6504|INFO|ThriveLauncher.AvaloniaLogger|[Binding]Error in binding to 'Avalonia.Animation.AnimatorKeyFrame'.'Value': 'Null value in expression '{empty}' at '$parent[ProgressBar, 0]'.'(AnimatorKeyFrame #43425119)
2024-01-11 16:19:33.6553|INFO|ThriveLauncher.AvaloniaLogger|[Binding]Error in binding to 'Avalonia.Animation.AnimatorKeyFrame'.'Value': 'Null value in expression '{empty}' at '$parent[ProgressBar, 0]'.'(AnimatorKeyFrame #55281755)
2024-01-11 16:19:33.6598|INFO|ThriveLauncher.AvaloniaLogger|[Binding]Error in binding to 'Avalonia.Animation.AnimatorKeyFrame'.'Value': 'Null value in expression '{empty}' at '$parent[ProgressBar, 0]'.'(AnimatorKeyFrame #27773751)
2024-01-11 16:19:33.6641|INFO|ThriveLauncher.AvaloniaLogger|[Binding]Error in binding to 'Avalonia.Animation.AnimatorKeyFrame'.'Value': 'Null value in expression '{empty}' at '$parent[ProgressBar, 0]'.'(AnimatorKeyFrame #48637172)
2024-01-11 16:19:33.6691|INFO|ThriveLauncher.AvaloniaLogger|[Binding]Error in binding to 'Avalonia.Animation.AnimatorKeyFrame'.'Value': 'Null value in expression '{empty}' at '$parent[ProgressBar, 0]'.'(AnimatorKeyFrame #35081372)
2024-01-11 16:19:33.6863|INFO|ThriveLauncher.AvaloniaLogger|[Binding]Error in binding to 'Avalonia.Animation.AnimatorKeyFrame'.'Value': 'Null value in expression '{empty}' at '$parent[ProgressBar, 0]'.'(AnimatorKeyFrame #47296894)
2024-01-11 16:19:33.6920|INFO|ThriveLauncher.AvaloniaLogger|[Binding]Error in binding to 'Avalonia.Animation.AnimatorKeyFrame'.'Value': 'Null value in expression '{empty}' at '$parent[ProgressBar, 0]'.'(AnimatorKeyFrame #23018869)
2024-01-11 16:19:33.6967|INFO|ThriveLauncher.AvaloniaLogger|[Binding]Error in binding to 'Avalonia.Animation.AnimatorKeyFrame'.'Value': 'Null value in expression '{empty}' at '$parent[ProgressBar, 0]'.'(AnimatorKeyFrame #5843233)
2024-01-11 16:19:33.7017|INFO|ThriveLauncher.AvaloniaLogger|[Binding]Error in binding to 'Avalonia.Animation.AnimatorKeyFrame'.'Value': 'Null value in expression '{empty}' at '$parent[ProgressBar, 0]'.'(AnimatorKeyFrame #52589099)
2024-01-11 16:19:33.7063|INFO|ThriveLauncher.AvaloniaLogger|[Binding]Error in binding to 'Avalonia.Animation.AnimatorKeyFrame'.'Value': 'Null value in expression '{empty}' at '$parent[ProgressBar, 0]'.'(AnimatorKeyFrame #3539844)
2024-01-11 16:19:33.7108|INFO|ThriveLauncher.AvaloniaLogger|[Binding]Error in binding to 'Avalonia.Animation.AnimatorKeyFrame'.'Value': 'Null value in expression '{empty}' at '$parent[ProgressBar, 0]'.'(AnimatorKeyFrame #31858597)
2024-01-11 16:19:33.7156|INFO|ThriveLauncher.AvaloniaLogger|[Binding]Error in binding to 'Avalonia.Animation.AnimatorKeyFrame'.'Value': 'Null value in expression '{empty}' at '$parent[ProgressBar, 0]'.'(AnimatorKeyFrame #18291919)
2024-01-11 16:19:33.7208|INFO|ThriveLauncher.AvaloniaLogger|[Binding]Error in binding to 'Avalonia.Animation.AnimatorKeyFrame'.'Value': 'Null value in expression '{empty}' at '$parent[ProgressBar, 0]'.'(AnimatorKeyFrame #30409547)
2024-01-11 16:19:33.7257|INFO|ThriveLauncher.AvaloniaLogger|[Binding]Error in binding to 'Avalonia.Animation.AnimatorKeyFrame'.'Value': 'Null value in expression '{empty}' at '$parent[ProgressBar, 0]'.'(AnimatorKeyFrame #5250475)
2024-01-11 16:19:33.7302|INFO|ThriveLauncher.AvaloniaLogger|[Binding]Error in binding to 'Avalonia.Animation.AnimatorKeyFrame'.'Value': 'Null value in expression '{empty}' at '$parent[ProgressBar, 0]'.'(AnimatorKeyFrame #47254279)
2024-01-11 16:19:33.7354|INFO|ThriveLauncher.AvaloniaLogger|[Binding]Error in binding to 'Avalonia.Animation.AnimatorKeyFrame'.'Value': 'Null value in expression '{empty}' at '$parent[ProgressBar, 0]'.'(AnimatorKeyFrame #22635327)
2024-01-11 16:19:33.7401|INFO|ThriveLauncher.AvaloniaLogger|[Binding]Error in binding to 'Avalonia.Animation.AnimatorKeyFrame'.'Value': 'Null value in expression '{empty}' at '$parent[ProgressBar, 0]'.'(AnimatorKeyFrame #2391358)

Putting a breakpoint when that is printed I was able to dig in and find out that it seems this is caused when the controls are removed. ControlLocator.ControlTracker.Detached() StyledElement.OnDetachedFromLogicalTreeCore() are in the callstack just before all the observer and value forwarding stuff begins.

Most of the callstack:

LoggingUtils.LogIfNecessary<object>()
AvaloniaObject.SetDirectValueUnchecked<object>()
DirectUntypedBindingObserver<object>.OnNext()
LightweightObservableBase<object>.PublishNext() [2]
BindingExpression.InnerListener.OnNext()
LightweightObservableBase<object>.PublishNext() [1]
ExpressionObserver.ValueChanged()
ExpressionNode.NextValueChanged()
ExpressionNode.ValueChanged() [2]
ExpressionNode.ValueChanged() [2]
ExpressionNode.StartListening()
ExpressionNode.set_Target()
ExpressionNode.ValueChanged() [1]
ExpressionNode.ValueChanged() [1]
AnonymousObserver<ILogical>.OnNext()
LightweightObservableBase<ILogical>.PublishNext()
ControlLocator.ControlTracker.Detached()
StyledElement.OnDetachedFromLogicalTreeCore() 
StyledElement.OnDetachedFromLogicalTreeCore() [11]
StyledElement.OnDetachedFromLogicalTreeCore() [10]
StyledElement.OnDetachedFromLogicalTreeCore() [9]
StyledElement.Avalonia.LogicalTree.ILogical.NotifyDetachedFromLogicalTree() [2]
TemplatedControl.OnDetachedFromLogicalTree()
StyledElement.OnDetachedFromLogicalTreeCore() [8]
StyledElement.OnDetachedFromLogicalTreeCore() [7]
StyledElement.OnDetachedFromLogicalTreeCore() [6]
StyledElement.OnDetachedFromLogicalTreeCore() [5]
StyledElement.OnDetachedFromLogicalTreeCore() [4]
StyledElement.OnDetachedFromLogicalTreeCore() [3]
StyledElement.OnDetachedFromLogicalTreeCore() [2]
StyledElement.OnDetachedFromLogicalTreeCore() [1]
StyledElement.Avalonia.LogicalTree.ILogical.NotifyDetachedFromLogicalTree() /StyledElement.cs:line 443 [1]
TopLevel.HandleClosed()
WindowBase.HandleClosed()
Window.HandleClosed()
X11Window.Cleanup()

I've written some custom animations, but this might be from the default progress bar functionality.

@timunie
Copy link
Contributor

timunie commented Jan 11, 2024

@hhyyrylainen can you try this PR? #13970

@hhyyrylainen
Copy link

I might be able to but I haven't tried compiling Avalonia myself at all so I'd need to figure that out. I've relied entirely on the nuget packages so far.

@timunie
Copy link
Contributor

timunie commented Jan 11, 2024

no need to compile it on your own. We have previews on all PRs: #13970 (comment)

@hhyyrylainen
Copy link

Oh that's very nice. I gave a quick spin after changing all Avalonia package versions to 11.1.999-cibuild0043390-beta and it seems the log errors are entirely gone. And as an added bonus this also fixes errors that I had coming from <Window.KeyBindings> for years now even on the old avalonia version.

I didn't do a full rigorous test but the basic functionality of my app didn't break with the changes. Though for the other issue I just reported it seems this causes slightly more error prints on shutdown (Tmds.DBus.Protocol.DBusException: org.freedesktop.DBus.Error.UnknownMethod: Method Destroy is not implemented on interface org.freedesktop.IBus.Service), I'll post there about testing the nightly.

github-merge-queue bot pushed a commit that referenced this issue Jan 29, 2024
* Update ncrunch config.

* WIP: Benchmarks

* Initial refactor of binding infrastructure.

- `ExpressionObserver` has been removed and its functionality merged with `BindingExpression`
- `BindingExpression` handles all types of `BindingMode` itself; doesn't require `BindingOperations.Apply` to set up a separate observable for `TwoWay/`OneWayToSource` bindings
  - This allows us to fix some long-standing issues with `OneWayToSource` bindings
- Expression nodes have been refactored
  - No longer split between `Avalonia.Base` and `Avalonia.Markup`
  - Categorize them according to whether they use reflection or not

A few tests are failing around binding warnings: this is because the next step here is to fix binding warnings.

* Make default binding Source = UnsetProperty.

Null is a theoretically valid value for `Source`; setting it to null shouldn't mean "use the data context".

* Move logging to BindingExpression.

As `BindingExpression` now has enough information to decide when it's appropriate to log an error/warning or not.

Fixes #5762
Fixes #9422

* Add compatibility hack for older compiled bindings.

Previously, `CompiledBindingPathBuilder` didn't have a `TemplatedParent` method and instead the XAML compiler rewrite templated parent bindings to be a `$self.TemplateParent` property binding. resulting in extraneous logs.

Add a constructor with an  `apiVersion`  to `CompiledBindingPathBuilder` which will be used by newer versions of the XAML compiler, and if a usage is detected using an `apiVersion` of 0, then upgrade `$self.TemplatedParent` to use a `TemplatedParentPathElement`.

* Log errors from property accessors.

* Don't log errors for named control bindings...

...on elements which aren't yet rooted.

* Log errors for failed conversions.

* Use consistent wording for binding warnings.

"Could not convert" instead of "Cannot convert".

* Log warnings for converter exceptions.

* Don't convert new TargetTypeConverters each time.

* Added failing test for implicit conversion.

* Support cast operators in compiled bindings.

A bit of a hack as we'd ideally not be using reflection when using compiled bindings.

* This shouldn't be a public API.

Should only be used for tests.

* Make enum/int conversion work.

* Check for SetValue equality after conversion.

And also use "identity equals" where value types and strings use `object.Equals` and reference types use `object.ReferenceEquals`.

* Added ConverterCulture back to bindings.

* Fix merge error.

Removed deleted files from csproj that were re-added due to indentation changes.

* Use BindingExpression directly in ValueStoe.

* Introduce BindingExpressionBase.

And `UntypedBindingExpressionBase`.

* Make TemplateBinding a BindingExpression.

* Make DynamicResource use a BindingExpression.

* WIP: Start exposing a BindingExpression API.

* Finish exposing a BindingExpression API.

* Fix OneTimeBinding.

* Remove unneeded classes/methods.

* Don't call obsolete API.

* Make BindingExpressionBase the public API.

This matches WPF's API.

* Added BindingExpressionBase.UpdateTarget.

* Initial implementation of UpdateSourceTrigger.

* Don't use weak references for values.

If they're boxed values, they can get collected.

* No need for virtual/generic methods here now.

* Reintroduce support for binding anchors.

Turns out these were needed by animations, just our animation system has no unit tests so I missed that fact earlier. Add a basic animation unit test that fails without anchor support, and add binding anchors back in. Currently a private API as I suspect this feature shouldn't be needed outside the framework.

* Include new property in clone.

And add real-life example of `UpdateSourceTrigger=LostFocus` to BindingDemo.

* Fix merge error.

* Updated BindingExpression tests.

- Make them run for both compiled and reflection bindings (found a bunch of tests that fail with compiled bindings)
- Make them not depend on converting the `BindingExpression` to an observable and instead test the end result of the binding on an `AvaloniaObject`

* Fix compiled binding indexer tests.

* Use data validation plugins in PropertyAccessorNode.

Added a warning suppression for now: we may need a separate `DataValidators` list for AOT-friendly plugins.

* Don't separate plugins by reflection.

`DataAnnotationsValidationPlugin` is public and so it can't be moved. No point in moving the others if this one will be in the wrong place.

* Remove unneeded methods.

* Make reflection binding tests use a string.

Convert the `System.Linq.Expression` to a string and then use this, as reflection bindings will always be instanced with a string path.

* Added TODO12 plan for IBinding2.

* Use more specific exception.

* Fix nits from code review.

* Make expression nodes sealed where possible.

* Unsubscribe on Stop, don't re-subscribe.

D'oh.

* Tweak ExpressionNode lists.

Saves a few K in benchmarks and it's a cleaner API.

* Add a pooled option in BindingExpressionGrammar.

Micro-optimization.

* Avoid allocations when enumerating binding plugins.

* Add IBinding2 support to observable bind overloads.

In the case of `TemplateBinding`, the `IObservable<object?>` bind overload is selected by C#. Add an explicit check for an `IBinding2` here to use the more performant code-path.

* Remove disposed binding from ImmediateBindingFrame.

* Added TemplateBinding benchmarks.

* Remove duplicate items.

Seems to have been caused by a merge error.

* Fix exception when closing color picker.

And add tests.

* Don't skip converter when binding to self.

* Don't pass UnsetValue to converters.

This follows WPF behavior.

* Log element name if present.

More useful than just logging the control hash code.

* Respect binding priority.

* Throw on mismatched binding priorities.

We don't want to respect the binding priority in this case as it breaks `TemplateBindings` when the default `LocalValue` priority is passed. Instead make sure that the priority parameter matches that of the expression.

This reverts commit a72765d.

* Convert to target type in TemplateBinding.

* Short-circuit target type conversion for same types.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging a pull request may close this issue.

7 participants