How should we handle print statements in Stan code?

[WardBrian]

Also forking off from #90.

Right now print statements in Stan end up getting sent to std::cerr unconditionally. Two things about this

1. If we're going to hardcode anything, we should probably make this std:cout
2. Some languages like Python have ways to redirect ""stdout"". I put this in quotes because Python's sys.stdout and C/C++'s stdout are not necessarily the same, the former does not even need to point to a valid file descriptor but could be a class. Unifying Stan's print statements with this language-specific behavior is tricky, though there are known tricks like what @bob-carpenter links to here: Improved error handling in the C API #90 (comment)

This is in many ways trickier than error messaging, since it is much harder to have it be zero-cost when you don't need it (the various redirection tricks you can use in Python all have a cost even if you never print anything. One potential solution is to have it be opt-in behavior, where you could write code like:

import sys
import bridgestan
m = bridgestan.StanModel(...) # initialize model

sys.stdout = # some file we want to redirect to
m.log_density(...) # would print to C's stdout, NOT that file
with bridgestan.redirect_stdout():
    m.log_density(...) # in this scope we WOULD redirect

[WardBrian]

Note: Julia's behavior is strictly better than Python's here, since their built-in redirect_stdout function does redirect C streams:

Create a pipe to which all C and Julia level stdout output will be redirected

So without us doing anything, print statements in Stan work just like print statements in Julia natively.

Python's library function of the same name does not behave the same, so there would be different behavior between print statements inside Stan and those inside Python.

[WardBrian]

Related: Any handling (including Julia's mentioned above) is predicated on Stan's print statements properly flushing the stream they're printing to. Currently they do not, see stan-dev/stanc3#1301

If for some reason that PR does not go through, we could flush cout as part of BridgeStan, but I'd like to avoid that if at all possible.

[aseyboldt]

It might also be an option to allow users of the C Api (ie the language bindings) to add a function that handles messages that stan want to print.

There could be a function bs_set_output_callback(model, &handle_msg_callback), where handle_msg_callback should have signature void handle_msg_callback(const *char).
Internally, brindgestan could then create a C++ stream object (inheriting from std:streambuffer I think, don't know C++ that well) that calls the provided C function on sync and overflow.
The default could just be to print to stderr.

The python interface could get a function that prints to the python stderr from the python c api:

pythonapi = ctypes.cdll.LoadLibrary(None)

PySys_WriteStderr = pythonapi.PySys_WriteStderr
PySys_WriteStderr.argtypes = [ctypes.c_char_p]
PySys_WriteStderr.restype = None

PySys_WriteStderr_ptr = ctypes.cast(PySys_WriteStderr, ctypes.c_void_p).value

I'm pretty sure something like this could be done for julia as well?

Also, maybe a lock is necessary to protect handle_msg_callback.

[WardBrian]

It seems like that’s a reasonable thing to do. I found at least one example of someone doing that, here: http://videocortex.io/2017/custom-stream-buffers/

The requirement to have a mutex for the function pointer would be slightly annoying, but I think we’re assuming most performant Stan program won’t have print statements anyway, it’s primarily for debugging and that sort of thing.

You could definitely do something similar from Julia, but there’s not really any need for it since Julia just “does the right thing”, and I don’t think we could do it from R. So it’s a question of if we’d want to implement it just for our Python bindings

[WardBrian]

Here's an existing Python library which does this: https://github.com/minrk/wurlitzer. It's using the same tricks we would if we were doing it purely from the Python side, and as a result confirms that this doesn't quite work on Windows (but they have an open PR to add support)

It even supports @bob-carpenter's main use case, which is re-directing stdout and stderr to a jupyter notebook automatically with %load_ext wurlitzer. I found it from an issue which was basically asking for this: ipython/ipykernel#110

I don't think we'd do much better than that, so I'm personally happy to point users who need C stream redirection inside Python to them

[WardBrian]

I put together something based on your callback suggestion and the above blog post @aseyboldt:
https://github.com/WardBrian/bridgestan/tree/feature/print-callback-from-python

It's definitely not ready for prime time, just wanted to confirm it would work (and it does!). Making the output stream a part of the model object seems like a bad idea (in particular, it makes all the log_density methods non-const) so I just did it as a global variable, which has its own problems to be sure.

[bob-carpenter]

It might also be an option to allow users of the C Api (ie the language bindings) to add a function that handles messages that stan want to print.

I like that we don't have to malloc a return that needs to be freed with this solution. The C client code would have to do that. But I'd take my opinion with a grain of salt---as a computer scientist, I can always be sold on another layer of indirection :-).

[aseyboldt]

This would be pretty nice to have.
I think the stream could live in the model object if it is protected by a mutex, without sacrificing the const. (At least it would be perfectly fine in rust, which I think might be a better guide than C++ for questions like that...). The cost of the mutex shouldn't be much of an issue I think, models shouldn't print stuff all the time anyway. And that way the user function doesn't need to guaranty thread safety. Not that I'm sure thread safety for the callback function would be enough to make the stream thread safe, the docs seem a bit vague about that.

[WardBrian]

I think the stream could live in the model object if it is protected by a mutex, without sacrificing the const.

Unlike Rust, C++ mutex's don't hold any object specifically. So the model object would need to have (seperately) a mutex and a pointer to the ostream, and that pointer needs to be passed in a non-const fashion to every usage. We could cast away that const, but that always makes me feel dirty.

Even if we could structure it how we could it Rust, also means every call which could print - namely all the log_density functions - needs to contend for a lock, even if the model never prints anything, which is a no-go.

If we wanted to deal with callbacks which aren't thread safe, I think the right place to lock is inside the streambuf, during the xputsc and overflow functions. This goes against the common advice of locking/unlocking a mutex as few times as possible, but for our use case it has the big advantage that models which never write to the ostream never need to contend for a lock. That still requires a non-const ostream pointer though
The Python callbacks we'd likely be using should be thread safe on their own thanks to the GIL, so I'm also not too afraid to say that this is a requirement of our API in general.

[bob-carpenter]

I think the right place to lock is inside the streambuf,

+1

[aseyboldt]

Even if we could structure it how we could it Rust, also means every call which could print - namely all the log_density functions - needs to contend for a lock, even if the model never prints anything, which is a no-go.

You are right, it seems I didn't think this through...

And good point about the GIL making the python function safe anyway.

[WardBrian]

At this point my branch for this (https://github.com/WardBrian/bridgestan/tree/feature/print-callback-from-python) has the callback protected by a mutex and is hooked up to the Python interface and tested.

It won't really work until Stan 2.32 is out and we've updated BridgeStan to use it, because of stan-dev/stanc3#1301, which is why I haven't opened a PR yet.