Web server subprocess logging to stdout sometimes not available until after subprocess terminates

Questions & Answers
,
1

I’m running raco static-web from inside another Racket program using subprocess[1], and, inside a thread, monitoring the subprocess’s stdout with sync/enable-break. The weird thing is that with raco static-web in particular, the output sent by that command to stdout is not picked up by my program until the raco process is killed in some way.

Example Gist. See the screenshot at the bottom also. (I’m working on this for a GUI app, but I created this not-exactly-MVE to remove GUI stuff from the equation.) This is running on macOS.

Twist: with any other long-running program I run this way (make, raco pollen start, etc.), stuff appears on the port as it is generated by the subprocess, as expected. So it must be something to do with the way raco static-web does logging, or more specifically with the dispatcher created by make in web-server/dispatchers/dispatch-logresp.

  1. I know that it would probably be better for me just to run the web server directly inside my own program, and that’s probably the direction I’ll go eventually. But I am very curious to understand what causes this behavior anyway. ↩︎

2

Can you install raco static-web from source, and revert back to df097e1475f1f6cb648f2d457e94a3dd2659542e, which is the commit right before I changed raco static-web to use dispatch-logresp? Do you get the same behavior?

3

In fact I have that package installed via --link from a local git clone. And yes, I do get the same behavior after checking out df097e14, deleting the compiled folder, doing raco pkg setup raco-static-web and restarting DrRacket.

1 Like
4

So I think the difference is that Pollen uses stderr for those messages, and stderr is not buffered. On the other hand, raco static-web uses stdout, which got buffered.

I don’t know how to fix that though.

5

Ok, that rings some bells. The stdout port returned by subprocess is initially set to a buffer mode of 'block, and I can set it to 'none…

  (displayln (list (file-stream-buffer-mode out)
                   (file-stream-buffer-mode out 'none)
                   (file-stream-buffer-mode out)))
;;  → '(block #<void> none)

…but this doesn’t keep it from behaving like a block-buffered port. I guess maybe that part is up to the OS.

Maybe the logger could be modified to flush-output more frequently? But now that the mystery is cleared up somewhat, I can move on to moving the web server inside my code rather than doing a subprocess.

6

Really the fix here seems like it would be to use Racket's logging infrastructure, rather than printing directly to stdout.

7

Yes, this is what I had in mind as part of inlining the web server code. (I assume it’s not possible to listen to a logger from another program running under a whole other instance of racket in a subprocess…right?)

8

You would need some kind of inter-process communication, and there isn't any infrastructure that I know of for doing that automatically yet. Logging can automatically go to syslog, and you could read from that, or you could build your own IPC.

9

Sorry, I'm a bit lost on why you want to run another Racket program via subprocess. Couldn't you do something like this instead:

#lang racket

(require raco/all-tools)

(define static-web (hash-ref (all-tools) "static-web"))
(dynamic-require (second static-web) #f)

Here, you have full control of the application: you can parameterize current-output-port, current-command-line-arguments, and whatnot. And you can run it in a separate thread.

10

I’ve been trying to make a GUI app that would run arbitrary command-line programs (or scripts) and display the output in an editor canvas in real time, just as if you were running it in the console. So it’s not that I specifically wanted to run a Racket program via a subprocess, I just wanted to be able to run anything and see the output in real time. My approach works great with all the commands/scripts I tested except for raco static-web. And I was too curious about why that would possibly be to drop the issue.

Assuming the problem is caused by block-buffering stdout outside of Racket’s control, there are probably many other programs/scripts that would exhibit the same problem when run from my app. And maybe there isn’t a reliable way to make this app without delving into pseudo-tty stuff, which, “that way lies madness”, likely.

11

If you run static-web in the terminal, do you see the output sent to stdout right away?

12

I do, for example, typically see it immediately.

But I have seen issues where in Github Actions the output is incorrectly buffered. I can't remember if that was using logging infrastructure or print/displayln.

1 Like
13

Yep! Though, in that case, raco is being run from inside an interactive shell with a TTY device, which IIUC is not the case when running it via subprocess.