[erlang-questions] Subordinate processes and stdout

[zxq9]

I wrote a toy broadcast to pid example today with R17, and in it I had the 
spawned processes output with io:format/2 instead of returning a message to 
the caller. It turns out, though, that unless the caller prints to stdout 
after the subordinates should have executed their own io call nothing is 
displayed if this is run in the shell (I haven't tried it as a script).

Here is a sample:

% Elementary broadcasting.
-module(bcast).
-export([start/0]).

start() ->
    Pids = [spawn(fun() -> listener() end) || _ <- lists:seq(1,3)],
    Message = "This is my message.",
    ok = bcast(Pids, Message),
    io:format("~p ~p: Weirdly initiates the first batch of messages.~n",
              [self(), now()]),
    io:format("~p ~p: Initiates the second batch.~n",
              [self(), now()]),
    [exit(P, kill) || P <- Pids],
    ok.

listener() ->
    receive
        {bcast, Message} ->
            Now = now(),
            io:format(user, "~p: ~p~n", [self(), Now]),
            io:format(user, "~p ~p: Received: ~p~n", [self(), now(), 
Message]),
            listener()
    end.

bcast(Pids, Message) ->
    [P ! {bcast, Message} || P <- Pids],
    ok.

And in the shell:

24> c(bcast).     
{ok,bcast}
25> bcast:start().
<0.138.0>: {1412,520755,828598}
<0.33.0> {1412,520755,828584}: Weirdly initiates the first batch of messages.
<0.139.0>: {1412,520755,828682}
<0.140.0>: {1412,520755,828690}
<0.138.0> {1412,520755,828803}: Received: "This is my message."
<0.33.0> {1412,520755,828812}: Initiates the second batch.
<0.139.0> {1412,520755,828815}: Received: "This is my message."
<0.140.0> {1412,520755,828845}: Received: "This is my message."
ok
26> bcast:start().
<0.33.0> {1412,520757,650460}: Weirdly initiates the first batch of messages.
<0.142.0>: {1412,520757,650474}
<0.143.0>: {1412,520757,650482}
<0.144.0>: {1412,520757,650486}
<0.33.0> {1412,520757,650656}: Initiates the second batch.
<0.142.0> {1412,520757,650665}: Received: "This is my message."
<0.143.0> {1412,520757,650671}: Received: "This is my message."
<0.144.0> {1412,520757,650676}: Received: "This is my message."
ok

The two io:format/2 calls in start/0 appear to be necessary to permit the 
subordinates to access stdout. If I comment out one, then only the first 
subordinate process' io:format/2 is displayed, if I comment out both 
bcast:start/0 quietly returns 'ok'. Even more weird, though, is that the 
timestamps demonstrate that the calls to now/0 are happening after start/0's 
calls to io -- which seems very odd.

What is happening here? I understand the group leader thing with stdout (at 
least I think I do -- this is all on a single, local node, anyway), but am 
puzzled at this behavior.

Regards,
-Craig