ServerLog


Log everything going to and coming from the server.

Display that traffic in order of event time.  Event time is when the event happened.  For a message or bundle sent that is the time it was sent plus its latency.  Messages received come time stamped with their event time.


I built this after being stumped by one of those node not found things.  a bundle had been sent with latency, the response from the server had not yet arrived, and something else found the synth still alive, freed it with nil latency (succesfully), then the bundle already sent failed to find the node.  using ServerLog you can see right away what the real order of excecution was.  


It also highlights fails and nils in red.  you can notice quickly when a bundle was sent out with a nil that probably shouldn't have.


s = Server.default;

ServerLog.start(s);


g = Group.new(s);

h = Group.tail(g);


// execute these at the same time

(

s.sendBundle(0.2, g.freeMsg);

h.free;

)

This should have been posted :


Group(1000)


Group(1001)


Group(1001)

FAILURE /n_run Node not found


ServerLog.report(500) // show last 500 events


// the gui is far easier to read

ServerLog.gui



This failure happened because the bundle had a delta of 0.2, while the free message for node 1000 was sent afterwards, but without a delta.


On the gui you can see the events ordered correctly.  You see /n_free followed by an /n_end confirmation from the server, then you see the /n_free for node 1000 being executed afterwards.


Status replies are logged every time there is a change.  The server is polled a few times a second to request a status update.  The position of the status.reply in the server log is a result of when the poll happened and when it was returned.  It is not a direct response to the messages to add or delete nodes.


There is still one big mystery:  why does the /fail appear BEFORE the /n_end ??  0.03 seconds or so.  Does the language and the server have different clocks ?  Or is there a bug up in there somewhere ?