Elmish.wpf: Potential logging improvements

[TysonMN]

I have some ideas about how to improve logging. I think they will lay a nice foundation to achieve the logging goals that @cmeeren has in mind (as briefly mentioned in #84).

1. Ability to send logs anywhere

Currently Elmish.WPF only allows its log events to be sent to System.Console or System.Diagnostics.Trace. Similar to Elmish.Program.withTrace, I suggest that Elmish.WPF accept a callback to allow users to send logs to a location of their choice. Let's call such a location a logging sink.

I still think it is a good idea to have functionality like ElmConfig.LogConsole and ElmConfig.LogTrace in the sense that it is helpful to users to be able to trivially employ those two logging sinks. However, in terms of implementation, I would prefer if it were like Emlish.Program.withConsoleTrace, which creates a new record instance with the appropriate change instead of requiring users to create a new record themselves.

Whatever API is used, I strongly suggest that the build-in support for logging to System.Console and System.Diagnostics.Trace be implemented via the the previously suggested callback API. This ensures that these build-in logging sinks are merely (very helpful) syntactic sugar for users instead of taking advantage of their proximity to Elmish.WPF and logging additional information not given to the logging callback (which is currently the situation with Elmish and something I intend to point out in a future issue there).

2. Use strong types to communicate all log event data

Currently Elmish.WPF handles each log event by sending a computed string to System.Console.WriteLine or System.Diagnostics.Trace.WriteLine. For the user-supplied logging callback discussed above, I suggest its input be a discriminated union with cases for each type of log event and containing all the relevant data. This gives users full control to employ techniques such as structured logging.

From such strongly-typed data, one can easily log to System.Console while also coloring the variable data or to a database that supports custom SQL queries on the variable data. Without the strongly-typed log event data, one would have to write string parsers to recover the stringly-typed log messages.

3. Communicate severity of log events

Currently Elmish.WPF does not differentiate the severity of its log events; the only way for users to understand the difference in severity between a trace-like event from

log "[%s] TrySetMember %s" propNameChain binder.Name

and an error-like event from

log "[%s] TrySetMember FAILED: Property %s doesn't exist" propNameChain binder.Name

is to read the resulting string in the log event.

This could be achieved with a log event level that is included in the strongly-typed log event data or as separate callback functions like how Elmish has Program.withTrace and Program.withErrorHandler. I am mostly indifferent about which implementation to pick. If it were up to me though, I would use the same approach as Elmish for consistency.

4. More logging

There are places that Elmish.WPF can helps users though additional logging. I found two locations by accident. Maybe there are more.

Both places I found are in ViewModel<'model, 'msg>.TrySetMember
when calling the respective set function. For example, in the Simple Counter Sample, remove the call to float in the binding, which seems to me like an easy mistake to make. Then moving the slider causes an exception to be thrown, which is caught by WPF and logged to System.Diagnostics.Trace (or some related variant thereof) as

System.Windows.Data Error: 8 : Cannot save value from target back to source. BindingExpression:Path=StepSize; DataItem='ViewModel`2' (HashCode=9847715); target element is 'Slider' (Name=''); target property is 'Value' (type 'Double') InvalidCastException:'System.InvalidCastException: Specified cast is not valid.
at Microsoft.FSharp.Core.LanguagePrimitives.IntrinsicFunctions.UnboxGenericT
at Elmish.WPF.Extensions.[email protected](Object p, model _arg7)
at Elmish.WPF.ViewModel`2.TrySetMember(SetMemberBinder binder, Object value)
at CallSite.Target(Closure , CallSite , Object , Object )
at System.Dynamic.UpdateDelegates.UpdateAndExecuteVoid2T0,T1
at MS.Internal.Data.PropertyPathWorker.SetValue(Object item, Object value)
at System.Windows.Data.BindingExpression.UpdateSource(Object value)'

I would rather this information be exposed from Elmish.WPF just like all other log events. (Maybe the location to which WPF logs this event is configurable. I have only briefly looked into this and didn't immediately find anything.) After catching that exception, I was able to easily create a log event with the message

Exception thrown calling 'set' for the binding "StepSize" in "main" with binding type "TwoWay[Validate]" for the value 2.0
System.InvalidCastException: Specified cast is not valid.
at Microsoft.FSharp.Core.LanguagePrimitives.IntrinsicFunctions.UnboxGenericT
at Elmish.WPF.Extensions.[email protected](Object p, model _arg7)
at Elmish.WPF.ViewModel`2.TrySetMember(SetMemberBinder binder, Object value)

It is true that the log message from WPF contains some information that my log message does not. However, my guess is that the information in my log message is a bit more useful. In particular, I can use this information to directly find the corresponding Elmish.WPF binding (because of the property name chain, which is missing from the WPF log message) and from there identify the corresponding WPF element instance (if that is also needed).

I bring up this general "more logging" suggestion since adding more reasons to log would add additional cases to the discriminated union the I suggested using above.

[TysonMN]

I am willing implement all of my suggestions. Of course, I won't start until receiving the blessing of the maintainers and deciding what the API should be.

[cmeeren]

Thank you so much for the detailed proposal! 🙏 I appreciate your hard work and am looking forward to improved logging in Elmish.WPF. It's good that you are willing to implement this yourself, because my capacity for maintenance and continued development is limited, and improving logging is not at the top of my list.

First, a concrete reply to:

In particular, I can use this information to directly find the corresponding Elmish.WPF binding (because of the property name chain, which is missing from the WPF log message)

It would be logged right before the exception:

https://github.com/elmish/Elmish.WPF/blob/ce4cd08bfed5018ff4852241afba9abd8a8b376a/src/Elmish.WPF/ViewModel.fs#L576

---

General thoughts on your proposal

First of all, I'd like to bring @et1975 into this conversation, because this is relevant for Elmish itself and the rest of the Elmish ecosystem and should be a joint effort to coordinate features, API, etc. (Please cc anyone else relevant.)

Now, here are some immediate thoughts I have after reading your proposal:

• I can't escape the feeling that it may be a bit over-engineered? I like generalization and abstractions as much as the next dev, but any complexity needs to be warranted. In my experience (which I'll be the first to admit certainly do not cover all use-cases), the logs output by Elmish.WPF are mostly just useful during development for:

  • Quickly finding binding errors
  • Checking binding efficiency by looking for parts of the app that should not be updating (for using lazy bindings) or looking for long function calls (for custom memoization)
  • Debugging the core Elmish.WPF implementation (to be honest, this may be the core reason why the logging exists in the first place)

  Now, there is certainly room for improvement in the current logging solution, but IMHO, as long as it's "good enough", it may not be necessary completely rethinking everything. With that in mind, could you elaborate a bit on where the current solution fails? What, concretely, is it you (actually, not theoretically) want to do with the Elmish.WPF logging that is currently not possible, and why?




• We should consider existing solutions like LibLog which AFAIK already has support for structured logging (I've never used it)




• I worry that using custom-made strongly typed logging may put too much pressure on the GC due to lots of allocations, or otherwise be ineffective. The design/implementation will have to consider this.




• Library logging is a somewhat controversial topic that's easy to get wrong, so let's make sure we don't rush to conclusions or solutions

[TysonMN]

In particular, I can use this information to directly find the corresponding Elmish.WPF binding (because of the property name chain, which is missing from the WPF log message)

It would be logged right before the exception:

True, but I see three issues with this.

1. It makes the developer read the log history instead of providing all the relevant information in a single log event. When something goes wrong, it is most helpful to provide all relevant information even if some of that information was given before for another reason.
2. Those two log event could be written to their sink arbitrarily far apart if the application is concurrently doing other things that produce log events.
3. When using my suggestion to separate trace and error logging event, if the user is currently ignoring trace event and only watching error events, then they won't even see the information from that previous logging call.

(P.S. What!! I didn't know that including an unmodified link to code displays like that in GitHub! I love it. I am going to use that a lot. Thanks! :) )

I can't escape the feeling that it may be a bit over-engineered? I like generalization and abstractions as much as the next dev, but any complexity needs to be warranted.

Certainly. However, your sentiment reminds me of (part of) the journey myself and other have taken as they "move" from object-oriented programming to functional programming. For example, it is easy to think that some function is simple because it only accepts a single argument. But the truth is that it is has hidden complexity because it makes many impure static calls. Refactoring this function to make it pure by taking in many callback now communicates its true complexity through its argument count.

Similarly, your existing logging is complicated, but this fact is hidden because the existing logging uses a stringly-typed argument. Refactoring this to use create an immutable data structure (like a discriminated union with each case containing the relevant variable data) makes explicit the extent to which the existing logging is already complicated.

In my experience ..., the logs output by Elmish.WPF are mostly just useful during development for:

• ...
• Checking binding efficiency by looking for parts of the app that should not be updating (for using lazy bindings) or looking for long function calls (for custom memoization)

My understanding of how to properly optimize follows this process.

1. measure the performance,
2. make the code correct,
3. make the code pretty,
4. make the code fast by making data-driven decisions.

In particular, this data could be the historical data already collected. Using historical data could make it significantly easier to identify when some binding began to take longer. In order to make this (easily) possible though, Elmish.WPF would need to support structured logging and arbitrary logging sinks to put logs into long-term storage and provide an interface to query them like Serilog.Sinks.Seq does.

Now, there is certainly room for improvement in the current logging solution, but IMHO, as long as it's "good enough", it may not be necessary completely rethinking everything.

The customers of a library are other developers. One interface between the library and the developers is the API of the code. Another is the information given to the developers in the form of logging. It is not a coincidence that conference talks about Elm often mention how amazingly good the error messages of its compiler are.

I worry that using custom-made strongly typed logging may put too much pressure on the GC due to lots of allocations, or otherwise be ineffective. The design/implementation will have to consider this.

If you are concerned with efficnetly, then I must tell you that your current approach logging can easily be improved. Currently every call to log first creates the string to log and then decides if it wants to log. If you want to be more efficient, then you should do these operations in the other order. To my eye, Serilog goes to great lengths to be very efficient. You could look at their codebase if you want more ideas about how to be more efficient.

In general though, I think this doesn't matter. If the developer wants trace logging on, then they are saying that they don't care about efficiency. When efficiency matters, then only error logging would be enabled, and error events are likely rare, so their efficiency doesn't matter.

could you elaborate a bit on where the current solution fails? What, concretely, is it you (actually, not theoretically) want to do with the Elmish.WPF logging that is currently not possible, and why?

My situation is that I am a consultant and plan to recommend to my client that we use Elmish.WPF. Their developers currently use WPF, but their only experience with functional programming began recently we joined their team. I want to improve the efficiency development process of those using Elmish.WPF for all of its users. A rising tide raises all ships, but I think the most benefit will come to those developers that would have the hardest time with current development experience.

Specifically, I want Elmish.WPF to support fully structured logging to any logging sink. Then I would use Serilog with sinks like Serilog.Sinks.Console locally to colorize the all variable data and use Serilog.Sinks.Seq locally to store log events for future analysis and as well as remotely to facilitate efficient analysis.

For example, in my previous project, we had about 20 instances of the application running automated tests 24 hours a day and all of them sent their logs to a single Seq server. Each morning, the first thing I did was to look a dashboard summaries of the previous 24 hours of logs to identify issues and create bug reports that went into the queue to be squashed.

It is hard to underestimate how much this centralized logging and ability to write SQL queries to analyze the logs improved the efficiency of our development process. We were in a difficult situation, and I think the project would have failed if it weren't for the improved efficiency that this logging setup enabled.

We should consider existing solutions like LibLog which AFAIK already has support for structured logging (I've never used it)

Oh, that is very interesting. I did not know about this. Thanks for sharing it.

My experience is that (.NET) library maintainers are reluctant to take on additional dependencies. I don't have a strong preference about this. If I had to choose though, I would not take on an additional dependency. It is interesting to consider though that LibLog supports copying/pasting a single file from their project in order to use it.

Library logging is a somewhat controversial topic that's easy to get wrong, so let's make sure we don't rush to conclusions or solutions

Definitely. I am in no rush.

(Hopefully that was everything I wanted to say in reply. I am out of time now, so I will double check later.)

[cmeeren]

My situation is that I am a consultant and plan to recommend to my client that we use Elmish.WPF.

That's awesome to hear! I will have to adjust my view of Elmish.WPF as "this interesting and niche project I took over and evolved into something I'd like to use on a day-by-day basis but don't because I'm only using WPF intermittently for a personal pet project" to "this interesting and niche project I took over that people are actually recommending and using for real-world apps".

In any case, It's clear you have given this a lot of thought and know what you are talking about, and I agree with basically all of your above points. I trust you to implement this in a solid, robust way. :) I'd just like @et1975 to pitch in here since this is relevant for core Elmish, too.

[TysonMN]

In any case, It's clear you have given this a lot of thought and know what you are talking about, and I agree with basically all of your above points. I trust you to implement this in a solid, robust way. :) I'd just like @et1975 to pitch in here since this is relevant for core Elmish, too.

Thanks for the compliment :D I have also enjoyed working with you and your willingness to accept the PRs that I have already contributed.

I am also interested to receive feedback from @et1975 and anyone else that would like to share.

could you elaborate a bit on where the current solution fails? What, concretely, is it you (actually, not theoretically) want to do with the Elmish.WPF logging that is currently not possible, and why?

I said some in my previous comment, but I can say more about this. (I can always say more :P )

the logs output by Elmish.WPF are mostly just useful during development

I agree, but development does not always occur locally on a developer's computer.

When doing performance testing, it is important that this testing occur on production hardware. In my experience, production hardware is never the same as the hardware used by developers in development. The production hardware on my previous project was an embedded system. Granted the application was a web API instead of a WPF GUI, but the same considerations still apply. My current client is currently running an existing product on hardware that is weaker than my development system. If my client says that the application performs too slowly when executing on production hardware, then I will want to see the see how long the Elmish.WPF bindings took. I want to see the logs from that testing.

I am also concerned with software correctness between development and production hardware for my current project. The production hardware for my current project only has a touch screen (including multitouch) and most of the developers on our team (including me) do not have development machines with touch interfaces. I am concerned about how we will handle this. In the worst case, we won't be able to know if our Elmish.WPF bindings related to multitouch are correct until someone tests this on the production hardware. If such testing reveals a problem, then I want to see the logs from that testing. (P.S. If anyone has suggestions about simulating multitouch, please do send them my way.)

I work remotely from my home. I collaborate and pair program with my coworkers using many tools, including Skype / GoToMeeting (to share voice, video, and screens), Visual Studio Live Share to collaboratively edit code, and a Seg logging server to collaboratively debug problems. For that last example, one person "drives" by running the program (either locally and/or on production hardware) while I "navigate" (in part) by analyzing the logs live as they are added to the Seq server. Interacting with the application gives focus to the applications window, which might cover up the console, and the "driver" shouldn't be focused on the logs anyway.

In my experience, I don't have access to System.Diagnostics.Trace when running on production hardware (because Visual Studio is not involved). My current client has an application currently in production on that multitouch hardware that runs in fullscreen mode. Recall that the only interface is the multitouch screen; there is no mouse and no keyboard. My expectation is that, even if we did have the console displayed (which I would typically not do in build given to the client), I am not sure it would be visible behind the fullscreen application.

I worry that using custom-made strongly typed logging may put too much pressure on the GC due to lots of allocations, or otherwise be ineffective. The design/implementation will have to consider this.

Does my suggestion have any effect on the garbage collector? I thought that discriminated unions were allocated on the stack. (I could be wrong though.) The garbage collector only cares about things allocated on the heap. I will read about this to improve my understanding and report back.

If I am correct though about discriminated unions being allocated on the stack, then I think my suggestion would be more efficient than the current approach when logging is disabled (which is the case in which efficiency matters the most). As I pointed out above, Elmish.WPF currently creates a formatted string before checking if logging is enabled. With my suggestions, the mapping from a discriminated union case to the formatted screen would happen after having checked if logging is enabled. Before checking if logging is enabled, my suggestion is simply to call a particular case constructor of a discriminated union. I expect that this is more efficient than computing the formattinged string.

[et1975]

I'm not seeing much yet that would affect core elmish logging, but ...

• i like structured logging, but I'm not going to bring any dependencies
  into the core
• i don't recommend taking logging dependencies in this lib either
• feels like a premature optimization, but we could potentialy change the
  tracing function to lazier version, something like this:
  https://github.com/FsStorm/FsShelter/blob/master/src/FsShelter/Task.fs#L11
• I could see WPF-specific logging using elmish facilities, but it could
  work the other way as well - whatever facility you implement is passed into
  elmish.

From elmish perspective the domain of interest is the messages and the
model state and in general i think a debugger integration would be a better
investment here as it would provide not only performance profiling, but
also remote/centralized collection and load and replay ability.

[TysonMN]

Does my suggestion have any effect on the garbage collector? I thought that discriminated unions were allocated on the stack. (I could be wrong though.) The garbage collector only cares about things allocated on the heap. I will read about this to improve my understanding and report back.

Oh, I was wrong. The MSDN documentation for Discriminated Unions implicitly says that discriminated unions are reference types (and thus allocated on the heap) by default but can also be a value type (and thus allocated on the stack) using an attribute. This would work with my suggestion. The purpose of the discriminated union instances in my suggestion is just to export data. They are short-lived data transfer objects, so we would be helping the GC out by making them structs.

in general i think a debugger integration would be a better
investment here as it would provide not only performance profiling, but
also remote/centralized collection and load and replay ability.

I am certainly willing to take your word as to the priority of such things since I am new to MVU, Elmish, and Elmish.WPF. In fact, it is because I have just "arrived" that I have created this issue about logging.

1. It is something that I know how to do,
2. doing it will give me experience working inside of Elmish.WPF,
3. I know doing it would be an improvement for me, and
4. I think it would also be an improvement for others.

When I am more experienced with MVU, Elmish, and Elmish.WPF, I am willing to consider taking on these items you mentioned here @et1975 as well as the things @cmeeren listed in #84.

[cmeeren]

They are short-lived data transfer objects, so we would be helping the GC out by making them structs.

Well... Helping the GC, sure, but AFAIK (I may be wrong), the size of a DU struct is the size of all of its data fields combined. For example, the size of each instance of the DU below would be four references (32 bytes on a 64-bit machine), regardless of which case is chosen, so you very quickly surpass the old recommended maximum struct size of 16B (nowadays I think the official recommendation is just "measure the performance and make a choice based on that", but for a sizable "msg"-type DU it could be very, very big).

f# [<Struct>] type Foo = | A of p: string | B of q: string * r: string | C of s: string

And as you can see, you also have to uniquely name each data field.

---

From elmish perspective the domain of interest is the messages and the model state and in general i think a debugger integration would be a better investment here as it would provide not only performance profiling, but also remote/centralized collection and load and replay ability.

Debugger integration would be great. I was thinking that the messages and the logging state would also be nice to log "properly" as described in this issue, but I didn't think of Program.withTrace and Program.withErrorHandler - using these, a logging solution implemented purely in Elmish.WPF would be able to log everything of interest. Isn't that correct, @et1975?

[TysonMN]

I say we stick with reference-type DUs to begin. At some point in the future, we can consider optimizing it to be a value type instead. Based on how we intended it to be used, making this change would not be breaking.

I was thinking that the messages and the logging state would also be nice to log "properly" as described in this issue, but I didn't think of Program.withTrace and Program.withErrorHandler - using these, a logging solution implemented purely in Elmish.WPF would be able to log everything of interest. Isn't that correct, @et1975?

Sounds correct to me.

[cmeeren]

Feel free to go ahead with implementing this!

If you make it work without any extra dependencies, that would be best.

[TysonMN]

Excellent. Thanks @cmeeren :)

I definitely won't add any dependencies.

I was thinking that I would order my commits from least breaking to most breaking. That way, we can easily choose a more conservative route, especially by dropping the later commits.

Planned commits:

• Patch changes
  
  
  
  1. Refactor to use discriminated unions
  
  
  2. Add try-with-log-swallow around the two set calls in ViewModel<'model, 'msg>.TrySetMember
  
  
• Minor changes
  
  
  
  1. Expose new function in Program (something like runWindowWithConfigAndLoggers) to allow logging to any sinks
  
  
• Major changes
  
  
  
  1. Create a generic WpfProgram record type and adjust Program functions accordingly to fluently pass in Elimsh.WPF-specific configuration
  
  

Even if my later commits go too far, they won't take much time to write, they could serve as a talking point about additional improvements, and they can easily be included in a separate PR when the timing is better.

P.S. I probably won't start at this point for a couple weeks.

[cmeeren]

• Minor changes

• Expose new function in Program (something like runWindowWithConfigAndLoggers) to allow logging to any sinks

Why not just extend the additional ElmConfig type? It's designed to be extended with whatever one would want to configure, e.g. loggers. This would also be a backwards-compatible change (assuming everyone uses it as designed, i.e. { ElmConfig.Default with ... }), and it does not add any complexity through new run alternatives.

• Major changes

• Create a generic WpfProgram record type and adjust Program functions accordingly to fluently pass in Elimsh.WPF-specific configuration

Given the existing ElmConfig, what would be the benefits of a custom WpfProgram record type? What does it allow Elmish.WPF to offer to users that would otherwise be difficult or impossible?

P.S. I probably won't start at this point for a couple weeks.

Sure, no hurry 👍

[TysonMN]

ElmConfig is a (fully) public record, so any change to it is a breaking change. Adding a property would not break anyone's code written how you intended...

Program.mkSimpleWpf init update bindings
|> Program.withConsoleTrace
|> Program.runWindowWithConfig
    { ElmConfig.Default with LogConsole = true; Measure = true }
    (MainWindow())

...but it would break code written like this:

let tysonsFavorteElmCong =
  { LogConsole = false
    LogTrace = false
    Measure = false
    MeasureLimitMs = 1 }
Program.mkSimpleWpf init update bindings
|> Program.withConsoleTrace
|> Program.runWindowWithConfig
     tysonsFavorteElmCong
    (MainWindow())

In contrast, the Program<,,,> record in Elmish is not fully public; its name is public but its constructor is private. Adding a property to that record is not a breaking change.

A second but minor issue is that (as far as I know) the copy and update syntax with each property on its own line is rather verbose. Here is the most concise syntax that I know, which has three extra lines:

Program.mkSimpleWpf init update bindings
|> Program.withConsoleTrace
|> Program.runWindowWithConfig
    {
      ElmConfig.Default with
        LogConsole = true
        Measure = true
    }
    (MainWindow())

Setting each property on its own line makes it easy to temporarily remove that modification by commenting out the whole line.

[cmeeren]

For the sake of completeness, another suggestion (breaking, which I'm comfortable with in this situation) would be to make the ElmConfig type internal, and implement "setters" like so:

f# let config = Config.default |> Config.withlogConsole |> Config.withLogger ...

And then pass this config to Program.wunWindowWithConfig.

But perhaps the best option is indeed to make a WPF-specific Program type. IMHO, I prefer that to runWindowWithConfigAndLoggers, even though it's breaking, because 1) the migration path would be simple, and 2) the API is cleaner and more ergonomic.

[BentTranberg]

I use lots of libraries with callbacks, log adapters, or other kinds of hooks for logging. I create what's needed to be able to route all of that to my logger. My F# development very rarely involves any debugging, but I log all the time. More importantly, once or twice a year something goes very wrong, perhaps on a customer's site, and also tends to have the "not on my machine" syndrome. Logs like this can be a lifesaver in these cases. The difference can be a few minutes logging to find the problem, versus a week involving hard work and travels. My point is, I keep the logging in the production release.

I appreciate the work you are doing on this issue very much.

[TysonMN]

Planned commits:

• Patch changes
  
  
  
  1. Refactor to use discriminated unions
  
  

Here is my first commit.

Instead of making all of the planned changes in one branch, I can make a PR for this, we can "officially" review this, and then I can make further improvements in a new branch.

[cmeeren]

Thanks! Please make a PR.

Please also describe in that PR how you envision the DU being used from client code.

One thing that struck me now is that any additions to the logging data DU would be a breaking change...

[TysonMN]

Will the create the PR shortly with example DU usage.

One thing that struck me now is that any additions to the logging data DU would be a breaking change...

Yep, that is definitely a tradeoff. Another way to arrange things so that such a change isn't breaking is to take in callbacks for each (of what are currently a) case of the DU. But then users might not notice when a new logging "case" is added. This reminds me of a blog post I plan on writing soon about how not all breaking changes are equally bad. Some breaking changes have an easy migration path, so the fact that they are breaking isn't such a big deal. I think this is one of those cases.

I am in no hurry to push anything through though. To prevent any new breaking change possibilities, I added a commit to make all new things internal.

My next plan was to review each existing log call in detail as well as where exceptions could be thrown. Based on this review, I would modify those internal types to improve the logging. This is consistent with but more thorough than my "second" planned commit.

Planned commits:

• Patch changes
  
  
  
  1. Add try-with-log-swallow around the two set calls in ViewModel<'model, 'msg>.TrySetMember
  
  

As part of this analysis, I was thinking about adding samples that show how each error can occur. Each sample would somehow "show" how to fix the error as well, such as by uncommenting some code. Even if we completely abandoned adding support for structured logging, I think these samples would still be valuable.

[cmeeren]

This reminds me of a blog post I plan on writing soon about how not all breaking changes are equally bad. Some breaking changes have an easy migration path, so the fact that they are breaking isn't such a big deal. I think this is one of those cases.

Interesting! Please share when it's done. I have been developing and just published FSharp.JsonApi, which also has a DU-based API (for error handling), and I landed on the same conclusion. I'd like to hear others' views on the issue, as well.

In any case, I agree:

• The migration path is clear
• I think it's important for new users to know about new error cases to log
• After the initial API is stabilized, new error cases probably won't be that common

To prevent any new breaking change possibilities, I added a commit to make all new things internal.

Great!

My next plan was to review each existing log call in detail as well as where exceptions could be thrown. Based on this review, I would modify those internal types to improve the logging.

Fantastic!

As part of this analysis, I was thinking about adding samples that show how each error can occur. Each sample would somehow "show" how to fix the error as well, such as by uncommenting some code. Even if we completely abandoned adding support for structured logging, I think these samples would still be valuable.

Not sure what you mean by "samples". I think perhaps the best solution here is just to document it, for example in the readme. That allows us to stay concise and show only what's relevant, as opposed to sample project(s), which carry a lot of baggage if one only wants to show a small, very specific thing.

---

We could also consider writing "adapters" or whatever you'd call it for popular logging libraries, e.g. Serilog.Elmish.WPF (or Elmish.WPF.Serilog), akin to Serilog.AspNetCore. Then users could just pop in a |> Program.withSerilog in their pipeline, and they wouldn't have to configure anything. (They'd of course be free to do it manually if they wanted.)

[TysonMN]

Not sure what you mean by "samples". I think perhaps the best solution here is just to document it, for example in the readme. That allows us to stay concise and show only what's relevant, as opposed to sample project(s), which carry a lot of baggage if one only wants to show a small, very specific thing.

Sure, that is reasonable.

I will still want such samples as I do my analysis, so I will create the samples I want in my fork. These samples will be "executable documentation" for how each error can occur.

It is sort of like having 100% test code coverage. If I don't know of an input that traverses some (error) path in the code, then it could either be that

1. such an input exists (and finding one would be informative) or
2. no such input exists (but the type system is too weak there to express that).

If this were all we wanted to capture in this "executable documentation", then we could simply add these as tests (though I would need an additional test project for the XAML). That is partially what lead me to considering and then suggesting sample projects.

So, yea...for now, I will begin to contribute readme documentation for the errors.

We could also consider writing "adapters" or whatever you'd call it for popular logging libraries, e.g. Serilog.Elmish.WPF (or Elmish.WPF.Serilog), akin to Serilog.AspNetCore. Then users could just pop in a |> Program.withSerilog in their pipeline, and they wouldn't have to configure anything. (They'd of course be free to do it manually if they wanted.)

Love this idea. A related example of which I am particularly found is Serilog.Sinks.XUnit. Any data logged to Serilog is sent to XUnit's ITestOutputHelper, which records all this data with the test. So if you look at a failing test on the build server, all this log data is available there.

...Serilog.Elmish.WPF (or Elmish.WPF.Serilog), akin to Serilog.AspNetCore...

For what its worth, I think the names when read (i.e. from left to right) should follow the data flow.
Thus, I think

• Serilog.Sinks.XUnit is named correctly because data first flowed into Serilog (from somewhere else) then out of Serilog and into XUnit's ITestOutputHelper,
• Serilog.AspNetCore is incorrectly named because this NuGet package routes logging data from within ASP .NET Core to Serilog, and
• Elmish.WPF.Serilog would be the correct name for the adapter you suggested.

[cmeeren]

Re. samples: What you say makes sense, but I'd prefer not to "pollute" the samples folder with what is essentially just internal tests. If you can find a way around that - for example, by having these as actual test projects somehow, or at least in another folder - then I could more readily accept that. I'm also open to other suggestions or further discussion.

Re. documentation: Actually, I think simply documenting the DU cases (and other to-be-public APIs) with normal doc comments can go a long way. When the API is finalized, something high-level should definitely be added to the readme, but I don't think the readme is the right place for a description of each possible error.

Re. naming of integration package: Sure :)

[TysonMN]

(This is mostly a comment to myself.)

WIth the release of .NET Core 3.0, the latest release of WPF is now open source.

I would like to better understand the behavior of the combination of the DynamicObject and WPF as it relates to some behavior that I described in https://github.com/elmish/Elmish.WPF/issues/114#issuecomment-532372429:

When using a TwoWay binding and replacing dispatch with ignore, TrySetMember returns true, which causes WPF to call TryGetMember for the same member.

I want to better understand why TryGetMember was called after TrySetMember returned true. A call to TryGetMember does not happen after calling TrySetMember if the return value is false or if an exception is thrown.

[cmeeren]

Earlier I mentioned LibLog; a more F#-oriented alternative that I forgot to mention is Logary. I don't know anything about it, but I figured it would be wise to mention it.

[cmeeren]

Just came across FsLibLog, add that to the list of things to check out. :)

[TysonMN]

I would like to make progress on this by just implementing
(1) Ability to send logs anywhere and
(3) Communicate severity of log events.

Sometime later, progress on "(4) More logging" can be made without a breaking change. Lastly, we can do "(2) Use strong types to communicate all log event data" (if ever). (In fact, we could do (2) in a more robust way by passing the logging arguments as a message template and property values like in string.Format or in a call in Serilog.)

---

We previously discussed in https://github.com/elmish/Elmish.WPF/issues/105#issuecomment-526397737 that passing in arguments via a record (like ElmConfig) is brittle in the sense that any change (including adding a field) is a breaking change. I prefer using an API like Elimish has (e.g. Program.withErrorHandler). Then the last call to start a Elmish.WPF program is always Program.runWindow.

As is common in situations like this, we can (probably) initially support both the current API and whatever we decide for the new API with deprecated attributes on the current API.

---

We previously discussed log levels in https://github.com/elmish/Elmish.WPF/pull/111#discussion_r322592629. I was thinking about it again; and my thought is that we currently have three:

• Error: such as "[%s] TryGetMember FAILED:...
• Information/Debug: "[%s] TryGetMember %s"
• Trace: "[%s] %s (%ims): %s"

As I understand and define a warning (see that linked comment), I don't think Elmish.WPF has any warning-level logging. There might be some places that fatal-level logging could be added, but I don't think there is any now, and I don't know of any such places off the top of my head.

[cmeeren]

Thank you! My capacity for Elmish.WPF is very limited at the moment, and I'm highly grateful for anything you (or others) want to drive forward. 👍

[TysonMN]

I created this issue arguing for

1. Use strong types to communicate all log event data [via a discriminated union of log event types]

but backed off that position in my previous comment when I said

we can do "(2) Use strong types to communicate all log event data" (if ever). (In fact, we could do (2) in a more robust way by passing the logging arguments as a message template and property values like in string.Format or in a call in Serilog.)

I am now against the discriminated union approach and in favor of what I will call the string.Format arguments approach.

As an example, instead of
https://github.com/elmish/Elmish.WPF/blob/a42856e2f6c23f7b78cf6cd4d6ce9f422ca694ba/src/Elmish.WPF/ViewModel.fs#L362

it would look more like
```F#
let format = "[{0}] PropertyChanged \"{1}\""
let keys = [| "PropertyNameChain"; "PropertyName" |]
let values = [| propNameChain; propName |]
log format keys values

Then I can send this data to Serilog by doing
```F#
let keys = keys |> Array.map "{%s}"
let messageTemplate = string.Format (format, keys)
serilogLogger.Infomration(messageTemplate, values)

or compute the full string message as
F# let message = string.Format (format, values)

This approach has the following advantages:

1. We can add or remove reasons to log without changing the public API.
2. Enables ability to take full advantage of structured loggers (like Serilog.)
3. Doesn't add a dependency to any logging framework (such as Serilog).

One disadvantage is that the types involved in call to log are weaker, but I could compensate for this with strongly-typed internal functions that are implemented by doing the weakly-typed calls and write tests for the strongly-typed functions.

[et1975]

You shouldn't generate the templates on the fly, pretty sure serilog holds
on to the templates and it looks like a memory leak in the long run.

[TysonMN]

I think this is the parsed message template caching code to which you are referring.

Interesting. I didn't know that Serilog caches the parsed message templates. Now that you mention it though, it makes sense.

I don't think this is an issue for two reasons. First, Serilog prevents memory leaks by clearing that cache if it gets too big. Second, while the message templates in my example code are generated, they are not arbitrary. There would be at most one for each current call to
https://github.com/elmish/Elmish.WPF/blob/a42856e2f6c23f7b78cf6cd4d6ce9f422ca694ba/src/Elmish.WPF/ViewModel.fs#L349-L353
in Elmish.WPF (but not exactly one because some calls to log currently pass in the same value for fmt). Currently, I count 24 calls to log in Elmish.WPF, so my code would send at most 24 different message templates to Serilog.

[TysonMN]

Quoting @cmeeren in https://github.com/elmish/Elmish.WPF/issues/105#issuecomment-526470027

But perhaps the best option is indeed to make a WPF-specific Program type. IMHO, I prefer that to runWindowWithConfigAndLoggers, even though it's breaking, because 1) the migration path would be simple, and 2) the API is cleaner and more ergonomic.

I should have some time to work on this tomorrow.

[cmeeren]

I don't remember the current state of this discussion and I don't have time to read it now, but I think we should consider using Microsoft.Extensions.Logging.Abstractions. It seems to be the "standard" generic logger for .NET going forward. I have recently used it myself in a library at work, and it works wonderfully.

For our purposes, we could have a Program.withLoggerFactory function that accepts an ILoggerFactory, and then pass that factory around to all parts of the code that need to log, e.g. pass it into the view model constructor. The view model could then simply call let log = loggerFactory.CreateLogger("Elmish.WPF.ViewModel") and use the log (of type ILogger) for logging (ILogger has methods such as LogInformation etc., can accept exceptions, and even supports structured logging IIRC).

With the library I mentioned, which is used in several ASP.NET Core APIs, it's trivial to simply get the ILoggerFactory for the logger I have otherwise configured (Serilog in my case) and pass it to the library.

[TysonMN]

I don't remember the current state of this discussion and I don't have time to read it now...

And my thoughts have evolved over time. I will summarize my current idea soon.

[TysonMN]

I will summarize my current idea soon.

I think https://github.com/elmish/Elmish.WPF/issues/105#issuecomment-635620255 still accurately describes how I would prefer to implement improved logging.

Quoting https://github.com/elmish/Elmish.WPF/issues/105#issue-484887536

[Communicating the severity of log events] could be achieved with a log event level that is included in the strongly-typed log event data or as separate callback functions like how Elmish has Program.withTrace and Program.withErrorHandler.

I current prefer such separate program computation functions.

I think we should consider using Microsoft.Extensions.Logging.Abstractions. It seems to be the "standard" generic logger for .NET going forward. I have recently used it myself in a library at work, and it works wonderfully.

Yes, this is reasonable. However, I would prefer not to add a dependency. I looked at the other logging libraries you suggested (LibLog - now deprecated, Logary, and FsLibLog). They all seem good but also overkill compared to what I think suffices for Elmish.WPF.

I don't think it will be too difficult to implement the logging approach I described above, so I will do so. That will make conversations about this approach easier.

[cmeeren]

I'll try to make a PR using Microsoft.Extensions.Logging.Abstractions.

All else being equal, I'd prefer not to take a dependency, but every time a sentence starts with "all else being equal", it never is. Stephen Cleary has a nice blog post about different library logging approaches and tradeoffs.

Microsoft.Extensions.Logging.Abstractions is a dependency I don't mind taking. It's very simple for users to plug into whatever else they're doing without boilerplate code.

[TysonMN]

I was going to start my logging work with some changes that can go into master. I will create PRs for this work.

[TysonMN]

All else being equal, I'd prefer not to take a dependency, but every time a sentence starts with "all else being equal", it never is. Stephen Cleary has a nice blog post about different library logging approaches and tradeoffs.

Microsoft.Extensions.Logging.Abstractions is a dependency I don't mind taking. It's very simple for users to plug into whatever else they're doing without boilerplate code.

As I said a bit in https://github.com/elmish/Elmish.WPF/pull/255#issuecomment-670923025, the pragmatist in me is happy to go along with your approach of taking on Microsoft.Extensions.Logging.Abstractions is a dependency. We can always change in the future to a custom logging interface.

[TysonMN]

This will be resolved in v4. Follow #253 for the progress of this.