GDP

I can still reproduce, but the problem only seems to happen when the log is created on a log server other than gdp-01 (or maybe gdp-02):

dhcp-45-14:apps mellis$ ./gcl-create -C mellis@berkeley.edu -k none edu.berkeley.eecs.bid.mellis.esp3
Created new GCL ipbR0X_iH2ys0EOhFYmJg3nJHuaa_prManMHZsUgvNo
    on log server edu.berkeley.eecs.gdp-01.gdplogd
exiting with status OK
dhcp-45-14:apps mellis$ ./gdp-reader -s edu.berkeley.eecs.bid.mellis.esp3
Reading GCL ipbR0X_iH2ys0EOhFYmJg3nJHuaa_prManMHZsUgvNo
^C
Exiting on signal 2
dhcp-45-14:apps mellis$ ./gcl-create -C mellis@berkeley.edu -k none edu.berkeley.eecs.bid.mellis.esp4
Created new GCL bt-ndEGfEJ6e1TPsUhPBP7Y8IPYZ3j19vnNB9hBSeCE
    on log server edu.berkeley.eecs.gdp-01.gdplogd
exiting with status OK
dhcp-45-14:apps mellis$ ./gdp-reader -s edu.berkeley.eecs.bid.mellis.esp4
Reading GCL bt-ndEGfEJ6e1TPsUhPBP7Y8IPYZ3j19vnNB9hBSeCE
^C
Exiting on signal 2
dhcp-45-14:apps mellis$ ./gcl-create -C mellis@berkeley.edu -k none edu.berkeley.eecs.bid.mellis.esp5
Created new GCL LH0AAfMgh4k59mprk3ELhs9Cb7Ch9eVpWvRCabJ7Kyg
    on log server edu.berkeley.eecs.gdp-04.gdplogd

exiting with status OK
dhcp-45-14:apps mellis$ 
dhcp-45-14:apps mellis$ ./gdp-reader -s edu.berkeley.eecs.bid.mellis.esp5
Reading GCL LH0AAfMgh4k59mprk3ELhs9Cb7Ch9eVpWvRCabJ7Kyg
[ERROR] gdp-reader: Cannot open GCL:
    ERROR: 600 no route available [Berkeley:Swarm-GDP:600]
exiting after 0 records with status ERROR: 600 no route available [Berkeley:Swarm-GDP:600]
dhcp-45-14:apps mellis$ 

A bit of detail (not sure how important it is):

• gdp-01 is running on 14.04, where a watcher programs restarts the log-server on a server-crash in a few minutes.
• gdp-0[2,3,4] are running systemd, which is also setup for restarts in case of crashes (not sure of the frequency, something systemd specific).

This may explain the different behavior, but it'll be nice to have a look at the logs if there are server restarts.

I did get a chance between meetings yesterday to look through logs, and I didn't see any restarts around the same time as the logs were created. This surprised me because when I did get it to fail, it definitely killed the log daemon, but it appears that David's problem is that the advertisement isn't being processed by the routing layer. I don't know whether the advertisement was never written by the log daemon, if the advertisement is stuck somewhere in the (TCP) network, or if the router read it but didn't process it.

I suspect that a reboot on the servers (which need a systems update anyway) would fix the problem temporarily, but at some point we need to figure out the root problem. I've been trying to figure out how to add debugging hooks before I restart, but I'm running out of ideas.

I found a definite bug in the router code that caused log names to get mangled in some circumstances if they had zero octets. That fix has been running since about 16:30PT yesterday afternoon, and so far so good. However, I'm not clear how this relates to routes that seem to appear and disappear, so I'm going to leave this as "In Progress" for at least a few days.

To be a bit more explicit, this turned out to be several intertwined problems. David's original problem was caused by his extraordinary bad luck in choosing names that had zero octets in the internal name. His second instance of the problem (which only worked on logs created on gdp-01) was again just a coincidence. The assertion failure in post_subscribe appears to have been an unrelated problem where certain error conditions on subscribe commands weren't handled properly. The other problems seem to be because, due to routing issues, duplicate logs were sometimes being created, which badly confused the routing layer.

It's a complete mystery to me why the problem only appeared recently. My guess that it was just that, as we add more logs, the chances of a log with a zero octet in the name goes up.