Binding errors are being logged even before `DataContext` is set

[MarchingCube]

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]

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]

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]

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]

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]

@MarchingCube do you remember how to disable them?

[maxkatz6]

@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.

[hhyyrylainen]

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]

@hhyyrylainen can you try this PR? https://github.com/AvaloniaUI/Avalonia/pull/13970

[hhyyrylainen]

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]

no need to compile it on your own. We have previews on all PRs: https://github.com/AvaloniaUI/Avalonia/pull/13970#issuecomment-1881485755

[hhyyrylainen]

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.