Kasper Møller Andersen (Oct 24 2022 at 12:47): Kasper Møller Andersen (Oct 24 2022 at 12:47):This isn't so much an idea as it is an experience story in using Elm, which hopefully Roc can improve upon.
It's a two pronged story, which touches both logging/analytics/reporting and error handling in the language.
The first issue is how logging relates to managed effects. In my mind, when a function returns an effect of some kind, it tells me a lot about what kind of function this is. If a function wants to do something, like send a network request, then that's very different from a function that just does some local computation. They are obviously both pure, but just mentally, I handle them differently, making it valuable for me to only have functions return effects when that effect is part of the business logic of that function.
Unfortunately, logging information from functions is also an effect. So if I want to log something from a function which otherwise doesn't return an effect, then I need to "pollute" its signature with this new information, which doesn't help me understand what the purpose of the function is. In fact, since I work on Falcon LogScale (formerly Humio), our mantra at work is to "log everything". In terms of effects, that means returning logging effects from all over the code base. That's not something we do today, because it's painful to do unfortunately.
Next up is error handling. My experience is that Elm encourages developers to use "default values" as an important strategy for dealing with errors that do not occur directly as a result of, say, a network request. For example, if you have two different custom types with different constraints that need to be used together, it's easy to unfold all branches and see what all the possible interactions between them are. But for some of those branches, it's by far the easiest strategy to leave a comment ala -- THIS CANNOT HAPPEN and then provide a default value that allows the program to continue running.
It's good to allow the program to continue in a incomplete state when you reasonably can, but I would much rather be allowed to log an error in this case. So why can't I do that? If this case exists in a view function, I might just be completely unable to report something other than to render it to screen. But even if it happens in a place where I am able to propagate an effect up, if I have some ImpossibleCase error, then it also creates a lot of noise, because propagating errors can be very noisy in Elm.
The sweet spot I would really like to have is to be able to provide a default value where the case happens, but also to report an error in some way, without polluting all my type signatures from the given function and up through to be returned by update. Debug.log already exists and is pretty much perfect for this, except it's not allowed in production builds of course. As it is now, I have had to fix issues where the author was wrong about THIS CANNOT HAPPEN, and it's both annoying to track down that this was where the error originated, but also a bit nerve wrecking to have no idea how many of those cases our users are hitting in practice.
I don't need to be sold on the benefits of pure computation though, and I know Debug.log is impure. If this were to be done in Roc, then maybe a platform could define this kind of write-only escape hatch for logging. Maybe only writing to stderr/the browser console is allowed, and it's up to the program author to figure what they want to do with the information that is printed there. That would be safer than allowing writing to some file or sending network requests at least.
Richard Feldman (Oct 24 2022 at 13:47):regarding "this cannot happen," I'm assuming https://github.com/roc-lang/roc/issues/4384 should address that
Richard Feldman (Oct 24 2022 at 13:58):as for logging, I've thought about this situation but there are some problems with any "pretend logging isn't a side effect" design:
Richard Feldman (Oct 24 2022 at 14:00):the only design I thought of that seemed plausible also seems very complicated from an implementation perspective: basically have some sort of log keyword, and what it does is append strings to a list, then when the entire Roc call chain finishes, that list comes back as part of the return value
Richard Feldman (Oct 24 2022 at 14:01):so the log messages don't get sent in realtime; rather, they get accumulated as the program runs and then the platform periodically receives a big list of them, which it can then persist somewhere
Richard Feldman (Oct 24 2022 at 14:02):so it's kinda like every function in the Roc program getting an extra list as an argument and an extra list as a return value
Ayaz Hafiz (Oct 24 2022 at 14:02):What if logging called out to a host-provided roc_log or similar? It doesn't eliminate the optimization problem but it makes it easier to deal with, since roc_log must be foreign. I think it would address the escape hatch problem too, if you only allow it to send e.g. strings
Richard Feldman (Oct 24 2022 at 14:04):an escape hatch with strings is pretty straightforward - you can just serialize whatever you actually want to send as json :big_smile:
Ayaz Hafiz (Oct 24 2022 at 14:05):I guess the same is true of crash, though, and possibly even roc_alloc via Boxing of strings - is that possible/worth trying to restrict?
Richard Feldman (Oct 24 2022 at 14:07):roc_alloc only receives number of bytes to allocate; it isn't told what will go in there
Richard Feldman (Oct 24 2022 at 14:08):doing it with crash is interesting; I need to think about that more :thinking:
Richard Feldman (Oct 24 2022 at 14:08):but anyway, when I thought through this more (awhile ago), I ended up wondering how valuable it actually was to do logging outside the context of effects anyway
Richard Feldman (Oct 24 2022 at 14:11):like usually if I'm digging through logs trying to figure out what happened, it's either because:
Richard Feldman (Oct 24 2022 at 14:12):1 can be addressed with something that is intended for debugging and doesn't have to be robust to optimizations (like how expect works today)
Richard Feldman (Oct 24 2022 at 14:13):2 can be addressed using normal effects, because if you have logged all the relevant info from your tasks, you can reproduce everything else by calling the pure functions that glue those tasks together
Richard Feldman (Oct 24 2022 at 14:14):but I'd love to hear your perspective on that, as someone who presumably makes heavier use of logging than I do :big_smile:
Kasper Møller Andersen (Oct 24 2022 at 14:14):crash is a nice improvement for sure, but I don't think it's the complete picture. In our application, I'm quite sure we don't want to crash on many of these cases.
The places where we want to crash are things like defining a regex from a literal that we control. If that ends up crashing, it will definitely happen during development, so it's very obvious.
But our application is quite complicated, and our users use it for business critical things. It's also not like we're swimming in these impossible cases, but most of the time we can still allow people to continue sensibly with a default value. In the ideal world, we would allow this degraded experience, but still be told about the behavior.
Brendan Hansknecht (Oct 24 2022 at 14:26):Question:
In roc we could technically have a platform with two different effect types, or a platform that annotated what types of effects are possible by a function. Does that alleviate this isssue at all?
Sure it is still an effect, but you can see that it is only an logging effect for example.
Kasper Møller Andersen (Oct 24 2022 at 14:31):2 can be addressed using normal effects, because if you have logged all the relevant info from your tasks, you can reproduce everything else by calling the pure functions that glue those tasks together
Not in all cases I think. You might have different servers writing data to the same S3 bucket, where the end result depends on the timing of the servers, network congestion, and more.
I'd also love to know more about the general Roc story on debugging in production. Presumably you can't record every effect when that includes e.g. reading big files.
Kasper Møller Andersen (Oct 24 2022 at 14:43):I'm not sure a restriction on logging output can possibly exist that couldn't be used as a general "perform any side effect" escape hatch.
I'm curious how much Roc should protect against this sort of thing. Reading from stderr to perform side effects outside of the program feels a bit contrived. Surely you could also perform side effects outside the program based on e.g. which syscalls, network calls, etc., the program makes. If someone were to do this on purpose, I assume it's for an application they are themselves writing. I have a hard time seeing it as e.g. a security issue.
Richard Feldman (Oct 24 2022 at 15:05):it's not so much a security issue as an ecosystem concern; in the future, we want to make an increasing amount of tooling that relies on functions being referentially transparent in order to do things like skipping work (e.g. not rerunning tests because their inputs didn't change, so we assume their outputs couldn't have), time travel debugging, etc.
Richard Feldman (Oct 24 2022 at 15:09):so I think it's really important to take into account not just "what's encouraged" but also "what's possible" - because if someone makes a platform with a lot of "conveniences" that break current (or future planned) tooling, they probably won't pitch it as "tooling-unfriendly" when marketing is to beginners who won't know enough about the language to realize that downside until it's too late
Richard Feldman (Oct 24 2022 at 17:20):another concern about synchronous logging: defs get reordered (just like in Elm and Haskell), which means the log statements might get run in a different order than they appear in the source code, which could lead to confusing logs
Richard Feldman (Oct 24 2022 at 17:21):so if we were to introduce a log keyword, we might need to consider making it an error for defs to be out of order - like you'd have to order them in a way where log statements would execute in source order
Richard Feldman (Oct 24 2022 at 17:26):there are some other interesting points made on this Reddit thread, in particular: https://www.reddit.com/r/scala/comments/537imy/comment/d7qqbb7/
Richard Feldman (Oct 24 2022 at 17:57):incidentally, this is definitely one of those scenarios where I want to take a step back and ask "what are the problems that logging solves, and are there other - potentially better - ways they could be solved using other approaches?"
Kasper Møller Andersen (Oct 24 2022 at 19:24):To be clear, my suggestion of allowing logging to console is just the thing I've wished for in Elm, since that's been the shortest path to achieving my desired outcome. I'm not suggesting that as a be-all, end-all approach, but just a starting point :blush:
Looking at my experience with our backend in Scala, and writing our frontend in Elm, I still think logs makes sense both based on on events and not. Let's break them down:
Logs based on events make a lot of sense on both the backend and frontend. On the backend, we care a lot about the time that something takes. How long does it take us to respond to an incoming request? How long to open and parse some file? How long to start up the server? This is in addition to the actual time that the event takes place. This allows us to look at how our response times are doing over time for example, and also to correlate it with the number of requests at any time. Additionally, the timestamps of each log event allow us to correlate with other log sources, like system logs that describe the RAM and CPU usage of our program. This gives us a good idea of how our program is running and what our capacity is. We can further instrument our code with tracing, to help get even more accurate data for how each service runs, if we are so inclined.
Aside from what we care about as developers, audit logging is also an important aspect of logging events. That is, it should be clear who took what action when.
When implementing logging like this, it's important to think about if you want structured logs or not. Your average log line is most often "unstructured", and structured logs can gather things up more easily. For example, a "structured log" may just be a dictionary of json data. When your server gets a request, it adds a request ID to the dictionary, and passes the dictionary to the next function that is called. This function can then add information to the dict, and when the response is finally served, the log line can be printed with all the data it has gathered up around this one request.
Logging things which are not based on events also depends on how you define "events". For example, if you're building a video streaming service, maybe you want to log what kind of video quality clients are getting as they stream. If they're streaming an hour long movie, you may want to sample their bitrate every minute for example. That's still a timer-based event, but it's an event that only exists to do logging. This is also generally what "metrics" are: just looking at how the application is doing, without being tied to any specific event.
Similarly, on the frontend, it's natural to do logging based on events. But I've also wanted to just poke at the model in my Elm application more than once, to see what users had in there. For example, we've wanted to see how many of our users have set up their applications to render their logs with feature X. But feature X depends on multiple things, like which settings the user has saved on their account, the changes they've made just for their current session, and crucially also the shape of the data they are looking at. This means there is no single event we can look at to determine if feature X is in use. We would have to determine if X is in use at a number of different events, which increases odds that we miss something. And since the feature is about how users render their logs, we already calculate exactly the answer we need in the view function, and trying to extract that logic to somewhere without the rendering can be messy.
Richard Feldman (Oct 24 2022 at 19:34):Kasper Møller Andersen said:
On the backend, we care a lot about the time that something takes. How long does it take us to respond to an incoming request? How long to open and parse some file? How long to start up the server? This is in addition to the actual time that the event takes place. This allows us to look at how our response times are doing over time for example, and also to correlate it with the number of requests at any time. Additionally, the timestamps of each log event allow us to correlate with other log sources, like system logs that describe the RAM and CPU usage of our program. This gives us a good idea of how our program is running and what our capacity is. We can further instrument our code with tracing, to help get even more accurate data for how each service runs, if we are so inclined.
Aside from what we care about as developers, audit logging is also an important aspect of logging events. That is, it should be clear who took what action when.
When implementing logging like this, it's important to think about if you want structured logs or not. Your average log line is most often "unstructured", and structured logs can gather things up more easily. For example, a "structured log" may just be a dictionary of json data. When your server gets a request, it adds a request ID to the dictionary, and passes the dictionary to the next function that is called. This function can then add information to the dict, and when the response is finally served, the log line can be printed with all the data it has gathered up around this one request.
yeah, these are both things that platforms can make really nice I think, because they have complete programmatic access to every single I/O action that gets taken! :grinning_face_with_smiling_eyes:
Kasper Møller Andersen (Oct 25 2022 at 10:24):yeah, these are both things that platforms can make really nice I think, because they have complete programmatic access to every single I/O action that gets taken!
Nice, that sounds promising! To be clear, there are many more things than timing and IO that we care about though. We also want to see that e.g. some job ran and what its results were. We want to know that users are enabling our new feature. We want to know what framerate our client is rendering at, and so on.
The entire reason Humio was created back in the day was to allow people to simply ask any question they could think of. If you can log the data, then you can answer the question, so Humio enables people to log as much as they can. I'm a staunch believer in having accessible logging for this reason: it empowers people to be creative and poke at not only their code, but also how the program behaves at runtime, and how users interact with the program. A "traditional" question for developers when logging might be "How did this thing come to be null?!", but when you can log everything, you can easily answer questions like "What are the most used search terms for these kinds of requests?" and "When do people use our product, and if we have a rush of users at certain points, how does that affect the service?".
So I want to circle back on this you said earlier:
like usually if I'm digging through logs trying to figure out what happened
I really want to emphasize that using logs to retrace application steps is just one problem that logs help solve, and which I agree can be better solved by having effects that you can replay, at least in some scenarios (I can also imagine scenarios where I would prefer logs).
But it's important that logging makes an application observable while it's running. This means that you also use logs to predict problems before they become actual problems. For example, if you can see the response time on requests for a service is trending upwards, then you have some time to stop it from growing too high. And if you can see users are making a lot of bad requests, then maybe it's a sign that they are misunderstanding your API, and you need to improve documentation.
Kasper Møller Andersen (Oct 25 2022 at 10:39):Thinking about logging as managed effects more, this is really the key for me. If I all of a sudden want to log something deep inside some function that has no managed effects, I have to convert it and every parent above it that doesn't have effects to now have it. This is a nice barrier to have when you don't want e.g. file reads, network requests, etc. all over the place, but for logging, the purpose is not to bring side effects into the program, but to expose the program in a way that hopefully makes us smarter.
Kasper Møller Andersen (Oct 25 2022 at 10:40):Also, I realize I sound like I'm giving a sales pitch, and I work with logging, so keep that bias in mind :big_smile:
Anton (Oct 25 2022 at 11:08):If I all of a sudden want to log something deep inside some function that has no managed effects, I have to convert it and every parent above it that doesn't have effects to now have it.
This is a good point
Anton (Oct 25 2022 at 11:13):We also wanted to be able to trace all values from program execution for easy debugging. Could we use the same design that was planned for that for logging as well?
Anton (Oct 25 2022 at 13:10):If I all of a sudden want to log something deep inside some function that has no managed effects, I have to convert it and every parent above it that doesn't have effects to now have it.
Eventually the editor could make this process easy and perhaps auto-collapse all logging code and types. That seems like a nice compromise to me.
Martin Stewart (Oct 25 2022 at 13:22):Imo, I wouldn't mind losing logs if there are better alternatives for debugging. In the context of a server, requests could be saved and then you could replay that code locally and step through the execution to see what happened.
It feels like logging is popular because most debugging tools are so primitive. I used to work with C# and the debugger built into Visual Studio was fantastic. As a result I rarely ever used Console.log to debug my code (until the code was deployed anyway, then Visual Studio's debugger couldn't help much and it was back to using Console.log)
Edit: Looks like my points got addressed earlier.
Richard Feldman (Oct 25 2022 at 16:37):all of a sudden want to log something deep inside some function that has no managed effects
:thinking: I'd be curious what specific examples of this you've run into, to understand the use cases better
Georges Boris (Oct 25 2022 at 16:52):imo this sounds more like something suited to a perf profiler unless talking about a language with unmanaged effects...
I understand the reasoning of "I want to log if this impossible state is reached" but it seems not ideal for a state to both be unreachable and at the same time you want your process to continue with resilience...
using the "let it crash" philosophy (common on BEAM systems) - this would be the case for you to crash the process, log the crash reason for future debugging, and restart the process from a previous known-valid-state where the impossible state is hopefully not easy to reach again.
Georges Boris (Oct 25 2022 at 16:52):this should be rarer for type-safe languages.
Anton (Oct 25 2022 at 17:42):imo this sounds more like something suited to a perf profiler
In my experience a perf profiler is typically not used on live systems but more for local stress testing.
As a sidenote; I do think a lot of the mentioned performance monitoring cases can be handled from inside the platform.
Brendan Hansknecht (Oct 25 2022 at 17:51):Quick aside on perf monitoring that i hope won't derail too much:
Perf monitoring on live systems is amazing. Obviously it is too costly to run all the time, but having a system that can take one server out of the fleet, turn on perf monitoring for a few seconds and then turn it back off is awesome. You basically get a ton of miniperf traces without having noticable effects on the end user. In aggregate, you get a very complete picture of the full system perf.
Kasper Møller Andersen (Oct 30 2022 at 15:18):I'd be curious what specific examples of this you've run into, to understand the use cases better
I haven't kept accurate track of course, but in the domain of writing web applications using Elm, the most common thing is definitely matching two sets of disparate modeling up, and now there's an "impossible" branch. This can happen in a number of different ways of course. Maybe the modeling is just sloppy and can be fixed up pretty easily, in which case that is preferable. But remodeling is not always an option or even the right solution.
I feel like I often get these conflicts in the view function, as that is where you are often "unfolding" all the modeling you've done, but there you are prohibited from returning managed effects. And there can be many different messages that are part of getting to an "impossible" branch, so it's very onerous to detect reliably in the update.
I've also had this experience in JSON decoders, where I need to account for some potential shape of the data that I know should not occur (e.g. field X is only present when field Y has value Z, etc.).
Trying to extrapolate from my (more limited) Scala experience writing backend services, things like service initialization are often about reading e.g. configurations into memory without sending anything out of the application. Or if you're just writing data to some buffer in memory on a network request, you might still send a 200 OK response back, but the function that crafts that response probably isn't the function that writes into the buffer. So if I want to log something when I write to the buffer, I'll need to return a managed effect even though the function wouldn't have one without the logging.
using the "let it crash" philosophy (common on BEAM systems) - this would be the case for you to crash the process, log the crash reason for future debugging, and restart the process from a previous known-valid-state where the impossible state is hopefully not easy to reach again.
I'm not sure how this applies here. I agree with the "let it crash" approach, in-so-far as you have the tools to do so in a useful way. Crashing when doing internal testing is great for example (so I'm all for adding e.g. debug_crash to Roc), but unless the language is built around setting up small processes and restarting them in case of crashes, then I don't think it's desirable in production. Business needs vary of course, but for us, we cannot accept that our Elm application crashes, and at the same time, we know the application needs to deal with unknown error states. This is a feature though, since it means we can continue servicing users while e.g. upgrading our backend with new behavior that the existing client might not be prepared for.
Kasper Møller Andersen (Oct 30 2022 at 15:26):And since everyone is talking a lot about performance in here, I just want to re-emphasize that performance is just one of multiple concerns that logging is useful in addressing. Since logging provides a completely live view of everything that goes on in your application, performance and error tracking is obvious things to do, but you can also log e.g. sales, and use that to estimate daily revenue for example.
Richard Feldman (Oct 30 2022 at 15:49):a thought about how logging from views could work in that example: the platform could offer (the equivalent of(
Html.log : Str, Html msg -> Html msg
so it's a wrapper around an element, and when the platform encounters it, it runs a logging effect that you specified in Program passing the given string
Richard Feldman (Oct 30 2022 at 15:50):there are ways that could be fancier, but the basic idea is that it's a way to log from view without crashing
Georges Boris (Oct 30 2022 at 17:17):also - the let it crash approach can work in production in Roc if the platform is suited for it. The platform is the one responsible for dealing with exceptions if I'm not mistaken - so if you want to create some resiliency to errors you (or the platform maintainer) may create tools to catch an exception and continue the process from a previous state or something like that.
Richard Feldman (Jun 15 2023 at 22:57):Richard Feldman said:
another concern about synchronous logging: defs get reordered (just like in Elm and Haskell), which means the log statements might get run in a different order than they appear in the source code, which could lead to confusing logs
worth noting: this is no longer a concern, since now unordered defs are planned to be a warning
Richard Feldman (Jun 15 2023 at 23:02):I want to revisit the idea of a synchronous logging keyword of some sort, given the realization that it seems like one of the following has to be true: either...
dbg can never work in WebAssembly, or when embedding Roc into an existing code base (like we're doing at Vendr, embedding it into a NodeJS TypeScript backend), or:dbg is implemented in a way where platform authors can choose to make it become arbitrary synchronous logging (or other effects) anyway Richard Feldman (Jun 15 2023 at 23:02):the first option doesn't really seem reasonable to me long-term
Richard Feldman (Jun 15 2023 at 23:02):so if we're ending up with the second one by process of elimination, should we consider leaning into it and making it a language feature, since people will be able to access it one way or another if they want it anyway?
Richard Feldman (Jun 15 2023 at 23:04):like concretely, we could give host authors a roc_log function (similar to roc_alloc) today which gets called every time a roc function hits a log keyword
Richard Feldman (Jun 15 2023 at 23:04):here's a concern about that from earlier in the thread:
Richard Feldman said:
as for logging, I've thought about this situation but there are some problems with any "pretend logging isn't a side effect" design:
- It's important that the Roc compiler is free to do optimizations under the assumption that Roc functions are pure. After inlining, this might mean that logging operations get optimized away and no longer log things. Preventing that from happening sounds complicated; we'd need to flag functions that log as "actually not a pure function" and then make sure that propagates virally to all other functions which call those functions.
- I'm not sure a restriction on logging output can possibly exist that couldn't be used as a general "perform any side effect" escape hatch. For example, if you restrict logging to just write to stderr, then the host can watch stderr and look for special messages about which side effects to perform. The side effects couldn't return any values, and the ergonomics wouldn't be good, but those would be the only restrictions.
Richard Feldman (Jun 15 2023 at 23:05):here are some points in favor of having it:
Kasper Møller Andersen said:
To be clear, my suggestion of allowing logging to console is just the thing I've wished for in Elm, since that's been the shortest path to achieving my desired outcome. I'm not suggesting that as a be-all, end-all approach, but just a starting point :blush:
Looking at my experience with our backend in Scala, and writing our frontend in Elm, I still think logs makes sense both based on on events and not. Let's break them down:
Logs based on events make a lot of sense on both the backend and frontend. On the backend, we care a lot about the time that something takes. How long does it take us to respond to an incoming request? How long to open and parse some file? How long to start up the server? This is in addition to the actual time that the event takes place. This allows us to look at how our response times are doing over time for example, and also to correlate it with the number of requests at any time. Additionally, the timestamps of each log event allow us to correlate with other log sources, like system logs that describe the RAM and CPU usage of our program. This gives us a good idea of how our program is running and what our capacity is. We can further instrument our code with tracing, to help get even more accurate data for how each service runs, if we are so inclined.
Aside from what we care about as developers, audit logging is also an important aspect of logging events. That is, it should be clear who took what action when.
When implementing logging like this, it's important to think about if you want structured logs or not. Your average log line is most often "unstructured", and structured logs can gather things up more easily. For example, a "structured log" may just be a dictionary of json data. When your server gets a request, it adds a request ID to the dictionary, and passes the dictionary to the next function that is called. This function can then add information to the dict, and when the response is finally served, the log line can be printed with all the data it has gathered up around this one request.
Logging things which are not based on events also depends on how you define "events". For example, if you're building a video streaming service, maybe you want to log what kind of video quality clients are getting as they stream. If they're streaming an hour long movie, you may want to sample their bitrate every minute for example. That's still a timer-based event, but it's an event that only exists to do logging. This is also generally what "metrics" are: just looking at how the application is doing, without being tied to any specific event.
Similarly, on the frontend, it's natural to do logging based on events. But I've also wanted to just poke at the model in my Elm application more than once, to see what users had in there. For example, we've wanted to see how many of our users have set up their applications to render their logs with feature X. But feature X depends on multiple things, like which settings the user has saved on their account, the changes they've made just for their current session, and crucially also the shape of the data they are looking at. This means there is no single event we can look at to determine if feature X is in use. We would have to determine if X is in use at a number of different events, which increases odds that we miss something. And since the feature is about how users render their logs, we already calculate exactly the answer we need in the
viewfunction, and trying to extract that logic to somewhere without the rendering can be messy.
Richard Feldman (Jun 15 2023 at 23:09):a general thing that concerns me about this idea is unforeseen consequences
Richard Feldman (Jun 15 2023 at 23:09):like right now if you run a roc build with --optimize (which eliminates dbg and expect), as long as roc_alloc and friends actually do nothing but manage memory, then Roc functions are actually pure and can be treated as such
Richard Feldman (Jun 15 2023 at 23:10):however, this would change that...there would definitely be observable consequences to a Roc function running or not running (say, because we realized we could optimize it away into a constant at compile time in an optimization pass someday)
Richard Feldman (Jun 15 2023 at 23:10):which might just mean those Roc programs run slower, but I wonder if there are other consequences (e.g. for tooling) that I'm not thinking about
Richard Feldman (Jun 15 2023 at 23:49):this is an example of the type of thing I hadn't thought about:
What if another part of your program happens to open up the log file?
Anton (Jun 16 2023 at 09:29):I'm not sure a restriction on logging output can possibly exist that couldn't be used as a general "perform any side effect" escape hatch.
Arbitrary side effects could be executed as well by monitoring CPU frequency, power, and temperature. That seems really convoluted until someone makes a library for it. In Roc there is always the need to trust the platform.
Brendan Hansknecht (Jun 16 2023 at 13:26):It also can be done more directly throughroc_alloc.
Brendan Hansknecht (Jun 16 2023 at 13:27):I do think this makes it easy easier to do and it's something that people 100% clearly see as a side effect
Brendan Hansknecht (Jun 16 2023 at 13:30):So i think logshould be thought about differently/more seriously. Is it just something pragmatic and realistic to make the language more useful? Is directly exposing an effect a bad idea? Is it too easy to use for arbitrary side effects? Isdbg a better name just for the mental perception?
Richard Feldman (Jun 16 2023 at 14:07):yeah, one concrete scenario that comes to mind that log would make possible: suppose I have a calculation whose speed I want to monitor in a server in production, including with --optimize enabled, and for various reasons it doesn't make sense to have that calculation be a Task
Richard Feldman (Jun 16 2023 at 14:09):but then again, with things like that I always wonder "should it really not be a Task?"
Richard Feldman (Jun 16 2023 at 14:10):if it takes that long to run
Anton (Jun 16 2023 at 14:35):Related tangent; I've been thinking that it could be valuable to have a "normal" and "no-task" view for roc code in the editor. In the no-task view everything looks like pure code (no Task in type signatures, no backpassing) but impure code is indicated with something like a dashed underline. The no-task view could remove a lot of the cognitive load of working with Task, thereby also making it nicer to use a Task for logging.
Richard Feldman (Jun 16 2023 at 14:49):interesting!
Richard Feldman (Jun 16 2023 at 14:49):sort of like "view this code as if it were algebraic effects" :big_smile:
Anton (Jun 16 2023 at 15:21):It is quite similar indeed, but with the important distinction that the no-task view simplifies type signatures.
Richard Feldman (Jun 18 2023 at 02:10):some other things to think about with this idea:
log does, how does a platform specify "you can use these different services for these different types of logs" (like how does it know what the different types even are? Does it ask the application author to provide a function to specify?) Also, if libraries in the ecosystem are doing logging, how do they agree on a common format for what the different levels mean? (Hardcoding levels into the language is one option, but that's pretty limiting for a feature that's designed to help you understand what your program is doing.) Richard Feldman (Jun 18 2023 at 03:38):the more I think about this overall idea the more reasonable it seems to me.
when I think about the practical things I like about pure FP, this particular side effect doesn't remove any of them. I've been trying to think of some implication I'm missing, and so far I haven't been able to come up with one. It seems like the upsides outweigh the downsides...but if others feel differently, I'd love to hear that perspective!
Sky Rose (Jun 19 2023 at 18:24):I think there's a distinction between "logging about the code" and "logging about the world".
Some examples of "logging about the world":
These are important side effects, you wouldn't want them to be duplicated or hidden by optimizations, but they're all happening near other side effects anyway, so it's not a problem to have them in real effect-based logging.
Some examples of "logging about the code":
These could happen anywhere, and you specifically don't want to have to refactor to use real effects to add them, but also it's okay if they get duplicated / removed by the compiler. You want to see what the code is doing, so if the compiler runs a function twice, you want to know that. These are what we want to do synchronously.
But idk if there's a logging API that Roc could have to enforce this split so that synchronous logging is only used for logging about the code, and that all logging about the world is still done in effects.
Richard Feldman (Jun 19 2023 at 19:03):I think "hidden by optimizations" would need to be impossible for this feature to be viable
Richard Feldman (Jun 19 2023 at 19:03):rather, they would just unavoidably prevent certain optimizations from happening, so that would be a tradeoff of using them
Bryce Miller (Jun 20 2023 at 12:38):Richard Feldman said:
dbgcan never work in WebAssembly, or when embedding Roc into an existing code base (like we're doing at Vendr, embedding it into a NodeJS TypeScript backend), or:dbgis implemented in a way where platform authors can choose to make it become arbitrary synchronous logging (or other effects) anyway
Could you expand on this? I’m not sure I follow completely.
Richard Feldman (Jun 20 2023 at 12:58):sure! The first design is where we hardcode dbg to print to stderr. This works on every target except wasm, which has no stderr or any equivalent. (console.log is a JS thing; wasm alone doesn't even know what the "console" is.)
Richard Feldman (Jun 20 2023 at 12:59):the second option is to have a roc_dbg function implemented in the host, which would work like roc_alloc in that it gets called every time you do a dbg in your Roc code. This means we're running arbitrary C code (or equivalent) written by the platform author every time dbg runs, which means they can put whatever side effects they want in there. (Although with the relevant restriction that they can't return anything.)
Bryce Miller (Jun 20 2023 at 13:12):Ok, got it. So currently, is there any way for platforms to provide synchronous effects such as logging? If a platform defined an Html.log function, could the platform author make that function perform synchronous effects?
Richard Feldman (Jun 20 2023 at 13:12):currently there is no way to do this, and that's by design
Bryce Miller (Jun 20 2023 at 13:13):Ah ok. And that makes logging, particularly perf monitoring, difficult
Richard Feldman (Jun 20 2023 at 13:13):indeed! :big_smile:
Bryce Miller (Jun 20 2023 at 13:18):So we aren’t thrilled about the idea of a dbg keyword that is meant for logging but could really perform any effect. We also aren’t thrilled about the optimizations we’d have to give up with that design.
What if we designed a way for platforms to define synchronous effectful functions? They would always have the signature a -> a. And somehow they would be differentiated from the other functions exposed by the platform.
This way, the platform author would be able to name the function according to what it does, and would have less incentive to shoehorn effects into a dbg keyword
Bryce Miller (Jun 20 2023 at 13:18):And it would be very easy to find all the code that’s forgoing the optimizations
Bryce Miller (Jun 20 2023 at 13:18):But maybe that’s already easy enough with the keyword approach
Richard Feldman (Jun 20 2023 at 13:25):Bryce Miller said:
What if we designed a way for platforms to define synchronous effectful functions? They would always have the signature
a -> a. And somehow they would be differentiated from the other functions exposed by the platform.
this would essentially make Roc an imperative language, which is a change I'd rather not make :big_smile:
Richard Feldman (Jun 20 2023 at 13:26):logging/tracing has some unique characteristics that set it apart from other side-effecting functions
Richard Feldman (Jun 20 2023 at 13:27):so I think it's possible we can special-case it without changing the overall character of the language
Bryce Miller (Jun 20 2023 at 15:37):Yeah two minutes after I wrote that I realized that using the keyword approach gives platform authors only one “thing that behaves like an imperative effectful function”, which way better than allowing an arbitrary number of them
Bryce Miller (Jun 20 2023 at 15:40):If not for the use cases requiring synchronous logging I would dislike the idea of adding a dbg keyword that impacts optimized builds. But not supporting those use cases is a tough sell.
Bryce Miller (Jun 20 2023 at 15:43):Or is it?
Brendan Hansknecht (Jun 20 2023 at 15:48):Personally, I don't think synchronous logging really matters. I would guess that most platforms will be set up in a way that logging will be mostly synchronous anyway. Tasks don't need to swap threads or control in general. They can keep running on the same thread.
My bigger concern is logging in code that is currently no where near a Task. It is in what would be 100% pure code paths. It may even be extra debug logging in libraries. In all of those case, you want to be able to easily enable logging. For the library cases, hopefully you can just pass a flag to the compiler to enable logging in that library. For your own code, maybe in some cases it makes sense to deal with threading through a task, but at a minimum, you would want to be able to sprinkle in logging for debugging without re-orchestrating your code.
Bryce Miller (Jun 20 2023 at 15:50):I like the idea of enabling debugging with a compiler flag way more than just arbitrarily allowing it any time.
Brendan Hansknecht (Jun 20 2023 at 15:53):I think it will have to be toggle-able. Otherwise, a library wouldn't be able to leave in their logging. Which defeats are large chunk of the point of logging (the ability to inspect what a library is doing to figure out why you are getting bad results).
Bryce Miller (Jun 20 2023 at 15:53):Because having a dbg keyword is basically like having one effectful imperative function that can be called anywhere at any time
Bryce Miller (Jun 20 2023 at 15:54):And I’m not sure how you call Roc a pure functional language with a feature like that. But maybe I just don’t understand the idea.
Brendan Hansknecht (Jun 20 2023 at 15:55):I mean haskell can wrap arbitrary c code that can do anything and is consider a pure functional language.
Brendan Hansknecht (Jun 20 2023 at 15:56):I think there is a line where practicality is more important.
Bryce Miller (Jun 20 2023 at 15:56):Hmm true.
Brendan Hansknecht (Jun 20 2023 at 15:56):But yeah, it is 100% a side effect.
Bryce Miller (Jun 20 2023 at 15:57):If a Haskell function wraps C code is that reflected in the type somehow?
Bryce Miller (Jun 20 2023 at 15:57):Like can you tell which functions can do that?
Brendan Hansknecht (Jun 20 2023 at 15:59):I don't think so. I mean they use C types, but you can just convert those to normal types, but I am not super familiar with haskell.
Bryce Miller (Jun 20 2023 at 16:01):I guess what I’m getting at is this: How would I know whether a function Str -> Str does side effects? I’m having trouble understanding how you could special case this enough to avoid diluting the usefulness of “pure” functions.
Bryce Miller (Jun 20 2023 at 16:02):Maybe a concrete proposal would help me grasp it.
Richard Feldman (Jun 20 2023 at 16:13):Bryce Miller said:
If a Haskell function wraps C code is that reflected in the type somehow?
it is not, no
Richard Feldman (Jun 20 2023 at 16:13):any Haskell function with any type can potentially be calling arbitrary C code
Richard Feldman (Jun 20 2023 at 16:16):Bryce Miller said:
Maybe a concrete proposal would help me grasp it.
the relevant part of this proposal is that the side effects from dbg (or maybe the keyword would end up being called log or trace) are sort of "fire-and-forget" in that they don't return. So like for example there's no foo = dbg ... where you're getting an answer back from the arbitrary C function
Richard Feldman (Jun 20 2023 at 16:16):meaning you couldn't use this keyword to violate "if you call a Roc function with the same arguments, it should return the same answer every time"
Brendan Hansknecht (Jun 20 2023 at 17:44):This is just my personal proposal, which does not match exactly what started this discussion,
but hopefully gives a concrete example that is close enough to help understanding.
Note: always remember that exact names or cli arg formats can be changed
Roc already has a dbg keyword.
Currently, dbg is limited to native platforms, prints to stderr, and does not run in optimized builds.
dbg can not automatically work with web assembly because web assembly is sandboxed.
It would require the platform expose some JS to the web assembly to function.
Fundamentally, this is proposal is an expansions of dbg.
Personally, I want to keep it called dbg to focus on the use case.
I am also fine with something like trace as a name.
I believe this should only be used for debug/trace logging, it should not be used for general purpose logging.
This is definitely my personal opinion, and the opinion that contratradicts ideas higher up in this thread the most.
dbg will be defined as approximately dbg: U8, Inspectable -> {}.
Currently I am just going to handwave Inspectable. That is other stuff that is already being worked on.
For now, you can just assume that it magically know how to convert anything to a Str to be logged.
The U8 parameter is the verbosity level required to print this message.
This enables a library to have many levels of verbosity.
Maybe level 0 will print only very high level tasks, 1 will print important function calls, 2 will print lots of debug info inside of a function, etc.
Each library can choose what the values mean to them, I would even advise individual libraries define constants to give names to the levels.
The reason for avoid names like Debug, Inspect, Trace, etc is that it is too restrictive.
Logging in some libraries can get very verbose and need exceptionally fine grain control.
As a direct example, Google libraries tend to use ~0-12. Most libraries just use 3, 5, and 9, but other libaries use many more values.
Note, I think it would be nice to also expose a version of the function without an explicit log level.
It would just default to a log level of 0. That way, new user can skip learning about that at the beginning.
This is a simple example of use:
# Fib.roc
myFib = \x ->
dbg 0 "myFib: \(x)"
if x <= 1 then
dbg 1 "Exit case: \(x)"
x
else
dbg 1 "Recursive case: \(x)"
myFib (x - 1) + myFib (x - 2)
On the platform side, they would be required to define roc_dbg(log: u8, msg: RocStr) -> void.
Since platforms define this, it can be used for web assembly platforms.
By default, dbg is disabled in optimized builds.
In non-optimized builds, it is by default enable to level 0 for the app package only.
This ensures some logging in debug, but avoids pulling in logs from all packages an app depends on.
From the cli, exact log level can be set for both individual modules, entire packages, and the whole progrm.
The arg is --log-level or in short form -l
Enable level 1 for whole program:
roc run/build/dev/etc Main.roc --log-level=1
Enable level 5 for the Main module only:
roc run/build/dev/etc Main.roc --log-level=Main:5
Enable level 3 for the Main module and level 0 for everything else:
roc run/build/dev/etc Main.roc --log-level=0,Main:3
Also, I think this should work at the package/library level.
So if you had an Http package with many modules, it would be:
roc run/build/dev/etc Main.roc --log-level=Http.*:3
It can be used for arbitrary side effects that can't return any data to the app.
Any proposal that adds logging to the host has this issue.
I could send json over dbg and have the host use that as a command.
That said, this can already be done through hacking roc_alloc.
It could easily be used for all logging instead of just tracing.
Bryce Miller (Jun 20 2023 at 18:19):Richard Feldman said:
meaning you couldn't use this keyword to violate "if you call a Roc function with the same arguments, it should return the same answer every time"
Ah, so the only way to observe these effects would be with a Task, in which case all bets are off anyway.
Bryce Miller (Jun 20 2023 at 21:35):Yeah that was the missing piece for me. It makes a lot more sense now.
Bryce Miller (Jun 20 2023 at 21:38):Thanks for humoring me!
Bryce Miller (Jun 20 2023 at 21:38):I really like the idea of making it opt-in for production builds.
Last updated: Jun 16 2026 at 16:19 UTC