I was recently asked how I setup my websites to:

1. Redirect HTTP to HTTPS when not accessed via an onion service.
2. Serve the website over HTTPS when not accessed via an onion service.
3. Serve the website over HTTP when accessed via an onion service.

I will further explain:

• How the .onion available button is obtained in my setup.
• How to add an onion Alt-Svc that works.

I have a very simple setup. I have a tor daemon running on the same machine as nginx. As most of my websites are static, nginx serves their files directly in most cases. There is no software between tor and nginx; if there is for you, that drastically changes things and this post may be of little use to you. If you have extra software "behind" nginx (e.g. a python app generating a dynamic website), most likely this post will still be useful to you. For example, instead of telling nginx this like I do:

location / {
        try_files $uri $uri/ =404;
}

You might be telling nginx this:

location / {
        include proxy_params;
        proxy_pass http://unix:/path/to/some/app.sock;
}

I use Certbot (Let's Encrypt) for my CA, and it automatically generates some of the nginx config you will see below.

All of the nginx config blocks are in one file, /etc/nginx/sites-available/flashflow.pastly.xyz. As is standard with nginx on Debian, there's a symlink to that file in /etc/nginx/sites-enabled/ and /etc/nginx/nginx.conf was already set to load files in /etc/nginx/sites-enabled/.

This post uses flashflow.pastly.xyz and its onion address as an example. Whenever you see flashflow.pastly.xyz or its onion address, mentally replace the domains with your own.

Redirect HTTP to HTTPS when not accessed via an onion service.

This is entirely handled by nginx and uses a server {} block automatically generated by Certbot. It is this:

server {
    if ($host = flashflow.pastly.xyz) {
        return 301 https://$host$request_uri;
    } # managed by Certbot
    listen 80;
    listen [::]:80;
    server_name flashflow.pastly.xyz;
    return 404; # managed by Certbot
}

All this block does is redirect to HTTPS. It is used when the user is visiting flashflow.pastly.xyz on port 80, as indicated by the server_name and listen lines.

Serve the website over HTTPS when not accessed via an onion service.

This is entirely handled by nginx. Again as the server_name and listen lines indicate, this block is used when the user is visiting flashflow.pastly.xyz on port 443 (using TLS). This is overwhelmingly automatically generated by Certbot too.

I slightly simplified this block as presented here. We will edit this block later in this post to add Onion-Location and Alt-Svc headers.

server {
    server_name flashflow.pastly.xyz;
    root /var/www/flashflow.pastly.xyz;
    index index.html;
    location / {
        try_files $uri $uri/ =404;
    }
    listen [::]:443 ssl; # managed by Certbot
    listen 443 ssl; # managed by Certbot
    ssl_certificate /etc/letsencrypt/live/flashflow.pastly.xyz/fullchain.pem; # managed by Certbot
    ssl_certificate_key /etc/letsencrypt/live/flashflow.pastly.xyz/privkey.pem; # managed by Certbot
    include /etc/letsencrypt/options-ssl-nginx.conf; # managed by Certbot
    ssl_dhparam /etc/letsencrypt/ssl-dhparams.pem; # managed by Certbot
}

Serve the website over HTTP when accessed via an onion service.

This is the nginx config block. It is a simplified version of the previous one, as it is also actually serving the website, but with plain HTTP and when the user is visiting the onion service, not flashflow.pastly.xyz.

server {
    listen 80;
    listen [::]:80;
    server_name jsd33qlp6p2t3snyw4prmwdh2sukssefbpjy6katca5imn4zz4pepdid.onion;
    root /var/www/flashflow.pastly.xyz;
    index index.html;
    location / {
        try_files $uri $uri/ =404;
    }
}

These are the relevant lines from the tor's torrc. We will edit this block later in this post to add Alt-Svc support.

HiddenServiceDir /var/lib/tor/flashflow.pastly.xyz_service
HiddenServicePort 80

In this post I've shared two server {} blocks that tell nginx to listen on port 80. Nginx knows to use this block for onion service connections because the server_name (the hostname that the user's browser is telling nginx it wants to visit) is the onion service. Nginx uses the other server {} block with port 80 when the user's browser tells nginx that it wants to visit flashflow.pastly.xyz.

After adding those lines to the torrc, I reloaded tor (restart not required). Then I could learn what the onion address is:

$ cat /var/lib/tor/flashflow.pastly.xyz_service/hostname 
jsd33qlp6p2t3snyw4prmwdh2sukssefbpjy6katca5imn4zz4pepdid.onion

And from there knew what to put on the server_name line.

Whenever I edited nginx's config, I reloaded nginx when done (systemctl reload nginx) and verified it didn't say there was an error.

Whenever I edited tor's config, I reloaded tor when done (systemctl reload tor@default) and verified by checking tor's logs that there was no error (journalctl -eu tor@default) and that tor is still running (systemctl status tor@default).

How the .onion available button is obtained in my setup.

Verify that the preceeding steps are working. Verify that:

1. Visiting http://flashflow.pastly.xyz redirects to https://flashflow.pastly.xyz to serve the website.
2. Visiting http://jsd33qlp6[...]d.onion serves the website.

This button advertises the fact that the website is also available at an onion service, which improves users' security and may even improve their performance. Further, if they've configured Tor Browser to do so, Tor Browser can automatically redirect to the onion service instead of presenting a button for the user to maybe click.

Find the 2nd server {} block you added, the one that listens on port 443. We are now going to add a single line to it that instructs nginx to add an HTTP header in its responses.

server {
    server_name flashflow.pastly.xyz;
    [... lines omitted ...]
    location / {
        try_files $uri $uri/ =404;
        # ADD THE BELOW LINE
        add_header Onion-Location http://jsd33qlp6p2t3snyw4prmwdh2sukssefbpjy6katca5imn4zz4pepdid.onion$request_uri;
    }
    listen [::]:443 ssl; # managed by Certbot
    listen 443 ssl; # managed by Certbot
    [... lines omitted ...]
}

Reload nginx and verify it didn't say there was an error.

Visiting https://flashflow.pastly.xyz should now result in a purple .onion available button appearing in the URL bar when the page is done loading. Clicking it will take the user from https://flashflow.pastly.xyz/foo/bar to http://jsd33qlp6[...]d.onion/foo/bar.

How to add an onion Alt-Svc that works.

Verify that the preceeding steps are working. Verify that:

1. Visiting http://flashflow.pastly.xyz redirects to https://flashflow.pastly.xyz to serve the website.
2. Visiting http://jsd33qlp6[...]d.onion serves the website.
3. (Optional) visiting https://flashflow.pastly.xyz results in a purple .onion available button in the URL bar.

This is another HTTP header that tells the browser there is another way to fetch the given resource that it should consider using in the future instead. The Alt-Svc header is used in contexts entirely outside of Tor, but it can also be used to tell Tor Browser to consider secretly fetching content from this host from an onion service in the future.

Common gotcha: The onion service must also support HTTPS. The onion service does not need a TLS certificate that is valid for the onion address: it should just use the same certificate as the regular web service, even though it is invalid for the onion service. The browser verifies that the certificate it gets from jsd33qlp6[...]d.onion is valid for flashflow.pastly.xyz when using the .onion as an Alt-Svc for the .xyz.

Add to the torrc the following line:

HiddenServiceDir /var/lib/tor/flashflow.pastly.xyz_service
HiddenServicePort 80
# ADD THE BELOW LINE
HiddenServicePort 443

Reload tor when done (systemctl reload tor@default) and verify by checking tor's logs that there was no error (journalctl -eu tor@default) and that tor is still running (systemctl status tor@default).

Find the 2nd server {} block you added, the one that listens on port 443. We are now going to add a single line to it that instructs nginx to add an HTTP header in its responses, and edit the server_name line to list the onion service.

server {
    # EDIT THE BELOW LINE
    server_name flashflow.pastly.xyz jsd33qlp6p2t3snyw4prmwdh2sukssefbpjy6katca5imn4zz4pepdid.onion;
    [... lines omitted ...]
    location / {
        try_files $uri $uri/ =404;
        # ADD THE BELOW LINE
        add_header Alt-Svc 'h2="jsd33qlp6p2t3snyw4prmwdh2sukssefbpjy6katca5imn4zz4pepdid.onion:443"; ma=86400;';
    }
    listen [::]:443 ssl; # managed by Certbot
    listen 443 ssl; # managed by Certbot
    [... lines omitted ...]
}

Reload nginx and verify it didn't say there was an error.

You can verify the Alt-Svc header is being sent by, well, inspecting the headers that nginx sends when you request either https://flashflow.pastly.xyz or https://jsd33qlp6[...]d.onion.

$ curl --head https://flashflow.pastly.xyz
HTTP/2 200 
server: nginx/1.14.2
[... lines omitted ...]
onion-location: http://jsd33qlp6p2t3snyw4prmwdh2sukssefbpjy6katca5imn4zz4pepdid.onion/
alt-svc: h2="jsd33qlp6p2t3snyw4prmwdh2sukssefbpjy6katca5imn4zz4pepdid.onion:443"; ma=86400;
[... lines omitted ...]


# the --insecure flag tells curl to keep going even though it will see a
# cert that isn't valid for the onion service. This is expected, as
# explained previously.
$ torsocks curl --insecure --head https://jsd33qlp6p2t3snyw4prmwdh2sukssefbpjy6katca5imn4zz4pepdid.onion
HTTP/2 200 
server: nginx/1.14.2
[... lines omitted ...]
onion-location: http://jsd33qlp6p2t3snyw4prmwdh2sukssefbpjy6katca5imn4zz4pepdid.onion/
alt-svc: h2="jsd33qlp6p2t3snyw4prmwdh2sukssefbpjy6katca5imn4zz4pepdid.onion:443"; ma=86400;
[... lines omitted ...]

Verifying that Tor Browser actually uses the headers is harder and beyond the scope of this post. The basic idea is to abuse Alt-Svc to serve something different up via the onion service and check that you get the different content after a couple of page refreshes.

The Tor Project now has a status page which shows the state of our major services.

You can check status.torprojet.org for news about major outages in Tor services, including v3 and v2 onion services, directory authorities, our website (torproject.org), and the check.torproject.org tool. The status page also displays outages related to Tor internal services, like our GitLab instance.

This post documents why we launched status.torproject.org, how the service was built, and how it works.

Why a status page

The first step in setting up a service page was to realize we needed one in the first place. I surveyed internal users at the end of 2020 to see what could be improved, and one of the suggestions that came up was to "document downtimes of one hour or longer" and generally improve communications around monitoring. The latter is still on the sysadmin roadmap, but a status page seemed like a good solution for the former.

We already have two monitoring tools in the sysadmin team: Icinga (a fork of Nagios) and Prometheus, with Grafana dashboards. But those are hard to understand for users. Worse, they also tend to generate false positives, and don't clearly show users which issues are critical.

In the end, a manually curated dashboard provides important usability benefits over an automated system, and all major organisations have one.

Picking the right tool

It wasn't my first foray in status page design. In another life, I had setup a status page using a tool called Cachet. That was already a great improvement over the previous solutions, which were to use first a wiki and then a blog to post updates. But Cachet is a complex Laravel app, which also requires a web browser to update. It generally requires more maintenance than what we'd like, needing silly things like a SQL database and PHP web server.

So when I found cstate, I was pretty excited. It's basically a theme for the Hugo static site generator, which means that it's a set of HTML, CSS, and a sprinkle of Javascript. And being based on Hugo means that the site is generated from a set of Markdown files and the result is just plain HTML that can be hosted on any web server on the planet.

Deployment

At first, I wanted to deploy the site through GitLab CI, but at that time we didn't have GitLab pages set up. Even though we do have GitLab pages set up now, it's not (yet) integrated with our mirroring infrastructure. So, for now, the source is hosted and built in our legacy git and Jenkins services.

It is nice to have the content hosted in a git repository: sysadmins can just edit Markdown in the git repository and push to deploy changes, no web browser required. And it's trivial to setup a local environment to preview changes:

hugo serve --baseUrl=http://localhost/
firefox https://localhost:1313/

Only the sysadmin team and gitolite administrators have access to the repository, at this stage, but that could be improved if necessary. Merge requests can also be issued on the GitLab repository and then pushed by authorized personnel later on, naturally.

Availability

One of the concerns I have is that the site is hosted inside our normal mirror infrastructure. Naturally, if an outage occurs there, the site goes down. But I figured it's a bridge we'll cross when we get there. Because it's so easy to build the site from scratch, it's actually trivial to host a copy of the site on any GitLab server, thanks to the .gitlab-ci.yml file shipped (but not currently used) in the repository. If push comes to shove, we can just publish the site elsewhere and point DNS there.

And, of course, if DNS fails us, then we're in trouble, but that's the situation anyway: we can always register a new domain name for the status page when we need to. It doesn't seem like a priority at the moment.

Comments and feedback are welcome!

This article was first published on the Tor Project Blog.

Rust doesn't yet support asynchronous functions in traits, but several important async-related traits (like AsyncRead and Stream ) define their interface using functions that return Poll. So, what can you do when you have a function that is async, and you need to use it to implement one of these traits?

(I'll be assuming that you already know a little about pinning, futures, and async programming in Rust. That's not because they're easy “everybody-should-know-it” topics, but because I'm still learning them myself, and I don't understand them well enough be a good teacher. You can probably keep reading if you don't understand them well . )

A little background

Here's a situation I ran into earlier this year. In the end, I only solved it with help from Daniel Franke, so I decided that I should write up the solution here in case it can help somebody else.

I've been working on Arti, an implementation of the Tor protocols in Rust. After a bunch of hacking, I finally got to the point where I had a DataStream type that provides an anonymous connection over the Tor network:

impl DataStream {
    pub async fn read(&mut self, buf: &mut[u8]) -> io::Result<usize>
    { ... }
    pub async fn write(&mut self, buf: &[u8]) -> io::Result<usize>
    { ... }
}

Now, there's a lot of complexity hiding in those ellipses. Tor isn't a simple protocol: when it's trying to read, it may need to wait for data to arrive. It may also need to send messages in response to arriving data. It might need to update internal state, or even tear down an entire Tor circuit because of a protocol error. Async functions made it possible to implement all of this stuff in a more-or-less comprehensible way, so rewriting those functions to explicitly return a typed future was not an option.

But I wanted DataStream to implement AsyncRead and AsyncWrite, so I could use it with other code in the Rust async ecosystem. So let's look at AsyncRead (because it's simpler than AsyncWrite). The only required method in AsyncRead is:

pub fn poll_read(
    self: Pin<&mut Self>,
    cx: &mut Context<'_>,
    buf: &mut [u8]
) -> Poll<io::Result<usize>>

This read() has to check whether there's data can be read into buf immediately, without blocking. If there is, we read the data and return the number of bytes we read. Otherwise, we have to schedule ourself on cx, and return Poll::Pending.¹

Moving forward, getting stuck

Compare poll_read to the read function in DataStream. First off, there's a mismatch between how these two functions use their output buffers. Because DataStream::read is async, it returns a future that will hang on to its buffer until the future is finally ready. But poll_read has to return right away, and it can't store a reference to its buffer at all. So I started by defining a wrapper variant of DataStream to implements the behavior that poll_read would need:²

pub struct DataReaderImpl {
    s: DataStream,
    pending: Vec<u8>
    offset: usize,
    len: usize,
}
pub struct DataReaderImpl {
    s: DataStream,
    pending: Vec<u8>
}
impl DataReaderImpl {
    fn new(s: DataStream) -> DataReaderImpl {
        DataReaderImpl {
            s,
            pending: Vec::new(),
        }
    }
    // Load up to 1k into the pending buffer.
    async fn fill_buf(&mut self) -> io::Result<usize> {
        let mut data = vec![0;1024];
        let len = self.s.read(&mut data[..]).await?;
        data.truncate(len);
        self.pending.extend(data);
        Ok(len)
    }
    // pull bytes from the pending buffer into `buf`.
    fn extract_bytes(&mut self, buf: &mut [u8]) -> usize {
        let n = cmp::min(buf.len(), self.pending.len());
        buf[..n].copy_from_slice(&self.pending[..n]);
        self.pending.drain(0..n);
        n
    }
}

Then, I thought, it ought to be easy to write AsyncRead! Here was my first try:

// This won't work...
impl AsyncRead for DataReaderImpl {
    fn poll_read(mut self: Pin<&mut Self>,
                 cx: &mut Context<'_>,
                 buf: &mut [u8]) -> Poll<io::Result<usize>> {
       if self.pending.is_empty() {
            // looks like we need more bytes.
            let fut = self.fill_buf();
            futures::pin_mut!(fut);
            match fut.poll(cx) {
                Poll::Ready(Err(e)) =>
                    return Poll::Ready(Err(e)),
                Poll::Ready(Ok(n)) =>
                    if n == 0 {
                        return Poll::Ready(Ok(0)); // EOF
                    }
                Poll::Pending =>
                    todo!("crud, where do i put the future?"), // XXXX
            }
        }

        // We have some data; move it out to the caller.
        let n = self.extract_bytes(buf);
        Poll::Ready(Ok(n))
    }
}

Almost there! But what do I do if the future says it's pending? I need to store it and poll it again later the next time I call this function. But to do that, I won't be able to pin the future to the stack! I'll have to store it in the structure instead. And since the future comes from an async function, it won't have a type that I can name; I'll have to store it as a Box<dyn Future>.

Oh hang on, it'll need to be pinned. And sometimes there won't be a read in progress, so I won't have a future at all. Maybe I store it in an Option<Pin<Box<dyn Future>>>?

(This is the point where I had to take a break and figure out pin-projection³.)

But after I played around with that for a while, I hit the final snag: ultimately, I was trying to create a self-referential structure⁴, which you can't do in safe Rust. You see, the future returned by DataReaderImpl::fill_buf needs to hold a reference to the DataReaderImpl, and so the future needs to outlive the DataReaderImpl. That means you can't store it in the DataReaderImpl. You can't even store it and the DataReaderImpl in the same struct: that creates self-reference.

So what could I do? Was I supposed to use unsafe code or some tricky crate to make a self-referential struct anyway? Was my solution fundamentally flawed? Was I even trying to do something possible‽

I asked for help on Twitter. Fortunately, Daniel Franke got back to me, looked at my busted code, and walked me through the actual answer.

Hold the future or the reader: not both!

Here's the trick: We define an enum that holds the DataReaderImpl or the future that its fill_buf function returns, but not both at once. That way, we never have a self-referential structure!

First we had to define a new variation on fill_buf that will take ownership of the reader when it's called, and return ownership once it's done:

impl DataReaderImpl {
    async fn owning_fill_buf(mut self) -> (Self, io::Result<usize>) {
        let r = self.fill_buf().await;
        (self, r)
    }
}

Then we had to define an enum that could hold either the future or the DataReaderImpl object, along with a wrapper struct to hold the enum.

type OwnedResult = (DataReaderImpl, io::Result<usize>);
enum State {
    Closed,
    Ready(DataReaderImpl),
    Reading(Pin<Box<dyn Future<Output=OwnedResult>>>),
}
struct DataReader {
    state: Option<State>
}

Note that the DataReader struct holds an Option<State>—we'll want to modify the state object destructively, so we'll need to take ownership of the state in poll_read and then replace it with something else.⁵

With this groundwork in place we could finally give an implementation of AsyncRead that works:

impl AsyncRead for DataReader {
    fn poll_read(mut self: Pin<&mut Self>,
                 cx: &mut Context<'_>,
                 buf: &mut [u8]) -> Poll<io::Result<usize>> {
        // We're taking this temporarily. We have to put
        // something back before we return.
        let state = self.state.take().unwrap();

        // We own the state, so we can destructure it.
        let mut future = match state {
            State::Closed => {
                self.state = Some(State::Closed);
                return Poll::Ready(Ok(0));
            }
            State::Ready(mut imp) => {
                let n = imp.extract_bytes(buf);
                if n > 0 {
                    self.state = Some(State::Ready(imp));
                    // We have data, so we can give it back now.
                    return Poll::Ready(Ok(n));
                }
                // Nothing available; launch a read and poll it.
                Box::pin(imp.owning_fill_buf())
            }
            // If we have a future, we need to poll it.
            State::Reading(fut) => fut,
        };

        // Now we have a future for an in-progress read.
        // Can it make any progress?
        match future.as_mut().poll(cx) {
            Poll::Ready((_imp, Err(e))) => { // Error
                self.state = Some(State::Closed);
                Poll::Ready(Err(e))
            }
            Poll::Ready((_imp, Ok(0))) => { // EOF
                self.state = Some(State::Closed);
                Poll::Ready(Ok(0))
            }
            Poll::Ready((mut imp, Ok(_))) => {
                // We have some data!
                let n = imp.extract_bytes(buf);
                self.state = Some(State::Ready(imp));
                debug_assert!(n > 0);
                Poll::Ready(Ok(n))
            }
            Poll::Pending => {
                // We're pending; remember the future
                // and tell the caller.
                self.state = Some(State::Reading(future));
                Poll::Pending
            }
        }
    }
}

Now when poll_read() takes ownership of the previous state, it either owns a DataReaderImpl or a future returned by owning_fill_buf()—but never both at once, so we don't have any self-reference problems. When poll_read() done, it has to put a new valid state back before it returns.

Conclusions

For the current version of all this code, have a look at tor_proto::stream::data in Arti. Note that the code in Arti is more complex than what I have in this post, and some of that complexity is probably unnecessary: I've been learning more about Rust as I go along.

I hope that some day there's an easier way to do all of this (with real asynchronous traits, maybe?) but in the meantime, I hope that this write-up will be useful to somebody else.

I wrote for LWN for about two years. During that time, I wrote (what seems to me an impressive) 34 articles, but I always had a pile of ideas in the back of my mind. Those are ideas, notes, and scribbles lying around. Some were just completely abandoned because they didn't seem a good fit for LWN.

Concretely, I stored those in branches in a git repository, and used the branch name (and, naively, the last commit log) as indicators of the topic.

This was the state of affairs when I left:

remotes/private/attic/novena                    822ca2bb add letter i sent to novena, never published
remotes/private/attic/secureboot                de09d82b quick review, add note and graph
remotes/private/attic/wireguard                 5c5340d1 wireguard review, tutorial and comparison with alternatives
remotes/private/backlog/dat                     914c5edf Merge branch 'master' into backlog/dat
remotes/private/backlog/packet                  9b2c6d1a ham radio packet innovations and primer
remotes/private/backlog/performance-tweaks      dcf02676 config notes for http2
remotes/private/backlog/serverless              9fce6484 postponed until kubecon europe
remotes/private/fin/cost-of-hosting             00d8e499 cost-of-hosting article online
remotes/private/fin/kubecon                     f4fd7df2 remove published or spun off articles
remotes/private/fin/kubecon-overview            21fae984 publish kubecon overview article
remotes/private/fin/kubecon2018                 1edc5ec8 add series
remotes/private/fin/netconf                     3f4b7ece publish the netconf articles
remotes/private/fin/netdev                      6ee66559 publish articles from netdev 2.2
remotes/private/fin/pgp-offline                 f841deed pgp offline branch ready for publication
remotes/private/fin/primes                      c7e5b912 publish the ROCA paper
remotes/private/fin/runtimes                    4bee1d70 prepare publication of runtimes articles
remotes/private/fin/token-benchmarks            5a363992 regenerate timestamp automatically
remotes/private/ideas/astropy                   95d53152 astropy or python in astronomy
remotes/private/ideas/avaneya                   20a6d149 crowdfunded blade-runner-themed GPLv3 simcity-like simulator
remotes/private/ideas/backups-benchmarks        fe2f1f13 review of backup software through performance and features
remotes/private/ideas/cumin                     7bed3945 review of the cumin automation tool from WM foundation
remotes/private/ideas/future-of-distros         d086ca0d modern packaging problems and complex apps
remotes/private/ideas/on-dying                  a92ad23f another dying thing
remotes/private/ideas/openpgp-discovery         8f2782f0 openpgp discovery mechanisms (WKD, etc), thanks to jonas meurer
remotes/private/ideas/password-bench            451602c0 bruteforce estimates for various password patterns compared with RSA key sizes
remotes/private/ideas/prometheus-openmetrics    2568dbd6 openmetrics standardizing prom metrics enpoints
remotes/private/ideas/telling-time              f3c24a53 another way of telling time
remotes/private/ideas/wallabako                 4f44c5da talk about wallabako, read-it-later + kobo hacking
remotes/private/stalled/bench-bench-bench       8cef0504 benchmarking http benchmarking tools
remotes/private/stalled/debian-survey-democracy 909bdc98 free software surveys and debian democracy, volunteer vs paid work

Wow, what a mess! Let's see if I can make sense of this:

Attic

Those are articles that I thought about, then finally rejected, either because it didn't seem worth it, or my editors rejected it, or I just moved on:

• novena: the project is ooold now, didn't seem to fit a LWN article. it was basically "how can i build my novena now" and "you guys rock!" it seems like the MNT Reform is the brain child of the Novena now, and I dare say it's even cooler!
• secureboot: my LWN editors were critical of my approach, and probably rightly so - it's a really complex subject and I was probably out of my depth... it's also out of date now, we did manage secureboot in Debian
• wireguard: LWN ended up writing extensive coverage, and I was biased against Donenfeld because of conflicts in a previous project

Backlog

Those were articles I was planning to write about next.

• dat: I already had written Sharing and archiving data sets with Dat, but it seems I had more to say... mostly performance issues, beaker, no streaming, limited adoption... to be investigated, I guess?
• packet: a primer on data communications over ham radio, and the cool new tech that has emerged in the free software world. those are mainly notes about Pat, Direwolf, APRS and so on... just never got around to making sense of it or really using the tech...
• performance-tweaks: "optimizing websites at the age of http2", the unwritten story of the optimization of this website with HTTP/2 and friends
• serverless: god. one of the leftover topics at Kubecon, my notes on this were thin, and the actual subject, possibly even thinner... the only lie worse than the cloud is that there's no server at all! concretely, that's a pile of notes about Kubecon which I wanted to sort through. Probably belongs in the attic now.

Fin

Those are finished articles, they were published on my website and LWN, but the branches were kept because previous drafts had private notes that should not be published.

Ideas

• astropy: "Python in astronomy" - had a chat with saimn while writing about sigal, and it turns out he actually works on free software in astronomy, in Python... I actually expect LWN to cover this sooner than later, after Lee Phillips's introduction to SciPy
• avaneya: crowdfunded blade-runner-themed GPLv3 simcity-like simulator, i just have that link so far
• backups-benchmarks: review of backup software through performance and features, possibly based on those benchmarks, maybe based on this list from restic although they refused casync. benchmark articles are hard though, especially when you want to "cover them all"... I did write a silly Attic vs Bup back when those programs existed (2014), in a related note...
• ideas/cumin: review of the Cumin automation tool from WikiMedia Foundation... I ended up using the tool at work and writing service documentation for it
• ideas/future-of-distros: modern packaging problems and complex apps, starting from this discussion about the removal of Dolibarr from Debian, a summary of the thread from liw, and ideas from joeyh (now from the outside of Debian), then debates over the power of FTP masters - ugh, glad I didn't step in that rat's nest
• ideas/on-dying: "what happens when a hacker dies?" rather grim subject, but a more and more important one... joeyh has ideas again, phk as well, then there's a protocol for dying (really grim)... then there are site policies like GitHub, Facebook, etc... more in the branch, but that one I can't help but think about now that family has taken a bigger place in my life...
• ideas/openpgp-discovery: OpenPGP discovery mechanisms (WKD, etc), suggested by Jonas Meurer (somewhere?), only links to Mailveloppe, LEAP, WKD (or is it WKS?), another standard, probably would need to talk about OpenPGP CA now and how Debian and Tor manage their keyrings... pain in the back.
• ideas/password-bench: bruteforce estimates for various password patterns compared with RSA key sizes, spinoff of my smartcard article, in the crypto-bench, look at this shiny graph, surely that must mean an article, right?
• ideas/prometheus-openmetrics: "Evolving the Prometheus exposition format into a standard", seems like this happened
• ideas/telling-time: telling time to users is hard. xclock vs ttyclock, etc. maybe gameclock and undertime as well? syncing time is hard, but it turns out showing it is non trivial as well... basically turning this bug report into an article. for some reason I linked to this meme, derived from this meme, presumably a premonition of my stupid idea of writing undertime TIMEZONES!
• ideas/wallabako: "talk about wallabako, read-it-later + kobo hacking", that's it, not even a link to the project!

A lot of those branches were actually just an empty commit, with the commitlog being the "pitch", more or less. I'd send that list to my editors, sometimes with a few more links (basically the above), and they would nudge me one way or the other.

Sometimes they would actively discourage me to write about something, and I would do it anyways, send them a draft, and they would patiently make me rewrite it until it was a decent article. This was especially hard with the terminal emulator series, which took forever to write and even got my editors upset when they realized I had never installed Fedora (I ended up installing it, and I was proven wrong!)

Stalled

Oh, and then there's those: those are either "ideas" or "backlog" that got so far behind that I just moved them out of the way because I was tired of seeing them in my list.

• stalled/bench-bench-bench benchmarking http benchmarking tools, a horrible mess of links, copy-paste from terminals, and ideas about benchmarking... some of this trickled out into this benchmarking guide at Tor, but not much more than the list of tools
• stalled/debian-survey-democracy: "free software surveys and Debian democracy, volunteer vs paid work"... A long standing concern of mine is that all Debian work is supposed to be volunteer, and paying explicitly for work inside Debian has traditionally been frowned upon, even leading to serious drama and dissent (remember Dunc-Tank)? back when I was writing for LWN, I was also doing paid work for Debian LTS. I also learned that a lot (most?) Debian Developers were actually being paid by their job to work on Debian. So I was confused by this apparent contradiction, especially given how the LTS project has been mostly accepted, while Dunc-Tank was not... See also this talk at Debconf 16. I had hopes that this study would show the "hunch" people have offered (that most DDs are paid to work on Debian) but it seems to show the reverse (only 36% of DDs, and 18% of all respondents paid). So I am still confused and worried about the sustainability of Debian.

What do you think?

So that's all I got. As people might have noticed here, I have much less time to write these days, but if there's any subject in there I should pick, what is the one that you would find most interesting?

Oh! and I should mention that you can write to LWN! If you think people should know more about some Linux thing, you can get paid to write for it! Pitch it to the editors, they won't bite. The worst that can happen is that they say "yes" and there goes two years of your life learning to write. Because no, you don't know how to write, no one does. You need an editor to write.

That's why this article looks like crap and has a smiley.

Time flies. Back in 2008, I wrote a game clock. Since then, what was first called "chess clock" was renamed to pychessclock and then Gameclock (2008). It shipped with Debian 6 squeeze (2011), 7 wheezy (4.0, 2013, with a new UI), 8 jessie (5.0, 2015, with a code cleanup, translation, go timers), 9 stretch (2017), and 10 buster (2019), phew! Eight years in Debian over 4 releases, not bad!

But alas, Debian 11 bullseye (2021) won't ship with Gameclock because both Python 2 and GTK 2 were removed from Debian. I lack the time, interest, and energy to port this program. Even if I could find the time, everyone is on their phone nowadays.

So finding the right toolkit would require some serious thinking about how to make a portable program that can run on Linux and Android. I care less about Mac, iOS, and Windows, but, interestingly, it feels it wouldn't be much harder to cover those as well if I hit both Linux and Android (which is already hard enough, paradoxically).

(And before you ask, no, Java is not an option for me thanks. If I switch to anything else than Python, it would be Golang or Rust. And I did look at some toolkit options a few years ago, was excited by none.)

So there you have it: that is how software dies, I guess. Alternatives include:

• Chessclock - really old Ruby which made Gameclock rename
• Ghronos - also really old Java app
• Lichess - has a chess clock built into the app
• Otter - if you squint a little

PS: Monkeysign also suffered the same fate, for what that's worth. Alternatives include caff, GNOME Keysign, and pius. Note that this does not affect the larger Monkeysphere project, which will ship with Debian bullseye.

Last week I did two rounds of my Creating Python modules in Rust workshop. During the second session on Sunday, someone asked if we can create standard dunder methods, say __str__ or __repr__. I never did that before, and during the session I tried to read the docs and implement it. And I failed :)

Later I realized that I should have read the docs carefully. To add those methods, we will have to implement PyObjectProtocol for the Rust structure.

#[pyproto]
impl PyObjectProtocol for Ros {
    fn __repr__(&self) -> PyResult<String> {
        let cpus = self.sys.get_processors().len();
        let repr = format!("<Ros(CPUS: {})>", cpus);
        Ok(repr)
    }

    fn __str__(&self) -> PyResult<String> {
        let cpus = self.sys.get_processors().len();
        let repr = format!("<Ros(CPUS: {})>", cpus);
        Ok(repr)
    }
}

>>> from randomos import Ros
>>> r = Ros()
>>> r
<Ros (CPUS: 8)>
>>> str(r)
'<Ros (CPUS: 8)>'

This code example is in the ros-more branch of the code.

I am conducting 2 repeat sessions for a workshop on "Writing Python modules in Rust".

The first session is on 16th April, 1500 UTC onwards, and the repeat session will be on 18th April 0900 UTC. More details can be found in this issue.

You don't have to have any prior Rust knowledge. I will be providing working code, and we will go very slowly to have a working Python module with useful functions in it.

If you are planning to attend or know anyone else who may want to join, then please point them to the issue link.

The correct spelling is Tor, not TOR or any other variations. Please use the correct spelling of the project.

TL:DR; lost half my mail (150,000 messages, ~6GB) last night. Cause uncertain, but possibly a combination of a dead CMOS battery, systemd OnCalendar=daily, a (locking?) bug in syncmaildir, and generally, a system too exotic and complicated.

The crash

So I somehow lost half my mail:

anarcat@angela:~(main)$ du -sh Maildir/
7,9G    Maildir/

anarcat@curie:~(main)$ du -sh Maildir
14G     Maildir

anarcat@marcos:~$ du -sh Maildir
8,0G    Maildir

Those are three different machines:

• angela: my laptop, not always on
• curie: my workstation, mostly always on
• marcos: my mail server, always on

Those mails are synchronized using a rather exotic system based on SSH, syncmaildir and rsendmail.

The anomaly started on curie:

-- Reboot --
mar 22 16:13:00 curie systemd[3199]: Starting pull emails with syncmaildir...
mar 22 16:13:00 curie smd-pull[4801]: rm: impossible de supprimer '/home/anarcat/.smd/workarea/Maildir': Le dossier n'est pas vide
mar 22 16:13:00 curie systemd[3199]: smd-pull.service: Main process exited, code=exited, status=1/FAILURE
mar 22 16:13:00 curie systemd[3199]: smd-pull.service: Failed with result 'exit-code'.
mar 22 16:13:00 curie systemd[3199]: Failed to start pull emails with syncmaildir.
mar 22 16:14:00 curie systemd[3199]: Starting pull emails with syncmaildir...
mar 22 16:14:00 curie smd-pull[7025]:  4091 ?        00:00:00 smd-push
mar 22 16:14:00 curie smd-pull[7025]: Already running.
mar 22 16:14:00 curie smd-pull[7025]: If this is not the case, remove /home/anarcat/.smd/lock by hand.
mar 22 16:14:00 curie smd-pull[7025]: any: smd-pushpull@localhost: TAGS: error::context(locking) probable-cause(another-instance-is-running) human-intervention(necessary) suggested-actions(run(kill 4091) run(rm /home/anarcat/.smd/lock))
mar 22 16:14:00 curie systemd[3199]: smd-pull.service: Main process exited, code=exited, status=1/FAILURE
mar 22 16:14:00 curie systemd[3199]: smd-pull.service: Failed with result 'exit-code'.
mar 22 16:14:00 curie systemd[3199]: Failed to start pull emails with syncmaildir.

Then it seems like smd-push (from curie) started destroying the universe for some reason:

mar 22 16:20:00 curie systemd[3199]: Starting pull emails with syncmaildir...
mar 22 16:20:00 curie smd-pull[9319]:  4091 ?        00:00:00 smd-push
mar 22 16:20:00 curie smd-pull[9319]: Already running.
mar 22 16:20:00 curie smd-pull[9319]: If this is not the case, remove /home/anarcat/.smd/lock by hand.
mar 22 16:20:00 curie smd-pull[9319]: any: smd-pushpull@localhost: TAGS: error::context(locking) probable-cause(another-instance-is-running) human-intervention(necessary) suggested-actions(ru
mar 22 16:20:00 curie systemd[3199]: smd-pull.service: Main process exited, code=exited, status=1/FAILURE
mar 22 16:20:00 curie systemd[3199]: smd-pull.service: Failed with result 'exit-code'.
mar 22 16:20:00 curie systemd[3199]: Failed to start pull emails with syncmaildir.
mar 22 16:21:34 curie smd-push[4091]: default: smd-client@smd-server-anarcat: TAGS: stats::new-mails(0), del-mails(293920), bytes-received(0), xdelta-received(26995)
mar 22 16:21:35 curie smd-push[9374]: register: smd-client@smd-server-register: TAGS: stats::new-mails(0), del-mails(0), bytes-received(0), xdelta-received(215)
mar 22 16:21:35 curie systemd[3199]: smd-push.service: Succeeded.

Notice the del-mails(293920) there: it is actively trying to destroy basically every email in my mail spool.

Then somehow push and pull started both at once:

mar 22 16:21:35 curie systemd[3199]: Started push emails with syncmaildir.
mar 22 16:21:35 curie systemd[3199]: Starting push emails with syncmaildir...
mar 22 16:22:00 curie systemd[3199]: Starting pull emails with syncmaildir...
mar 22 16:22:00 curie smd-pull[10333]:  9455 ?        00:00:00 smd-push
mar 22 16:22:00 curie smd-pull[10333]: Already running.
mar 22 16:22:00 curie smd-pull[10333]: If this is not the case, remove /home/anarcat/.smd/lock by hand.
mar 22 16:22:00 curie smd-pull[10333]: any: smd-pushpull@localhost: TAGS: error::context(locking) probable-cause(another-instance-is-running) human-intervention(necessary) suggested-actions(r
mar 22 16:22:00 curie systemd[3199]: smd-pull.service: Main process exited, code=exited, status=1/FAILURE
mar 22 16:22:00 curie systemd[3199]: smd-pull.service: Failed with result 'exit-code'.
mar 22 16:22:00 curie systemd[3199]: Failed to start pull emails with syncmaildir.
mar 22 16:22:00 curie smd-push[9455]: smd-client: ERROR: Data transmission failed.
mar 22 16:22:00 curie smd-push[9455]: smd-client: ERROR: This problem is transient, please retry.
mar 22 16:22:00 curie smd-push[9455]: smd-client: ERROR: server sent ABORT or connection died
mar 22 16:22:00 curie smd-push[9455]: smd-server: ERROR: Unable to open Maildir/.kobo/cur/1498563708.M122624P22121.marcos,S=32234,W=32792:2,S: Maildir/.kobo/cur/1498563708.M122624P22121.marco
mar 22 16:22:00 curie smd-push[9455]: smd-server: ERROR: The problem should be transient, please retry.
mar 22 16:22:00 curie smd-push[9455]: smd-server: ERROR: Unable to open requested file.
mar 22 16:22:00 curie smd-push[9455]: default: smd-client@smd-server-anarcat: TAGS: stats::new-mails(0), del-mails(293920), bytes-received(0), xdelta-received(26995)
mar 22 16:22:00 curie smd-push[9455]: default: smd-client@smd-server-anarcat: TAGS: error::context(receive) probable-cause(network) human-intervention(avoidable) suggested-actions(retry)
mar 22 16:22:00 curie smd-push[9455]: default: smd-server@localhost: TAGS: error::context(transmit) probable-cause(simultaneous-mailbox-edit) human-intervention(avoidable) suggested-actions(r
mar 22 16:22:00 curie systemd[3199]: smd-push.service: Main process exited, code=exited, status=1/FAILURE
mar 22 16:22:00 curie systemd[3199]: smd-push.service: Failed with result 'exit-code'.
mar 22 16:22:00 curie systemd[3199]: Failed to start push emails with syncmaildir.

There it seems push tried to destroy the universe again: del-mails(293920).

Interestingly, the push started again in parallel with the pull, right that minute:

mar 22 16:22:00 curie systemd[3199]: Starting push emails with syncmaildir...

... but didn't complete for a while, here's pull trying to start again:

mar 22 16:24:00 curie systemd[3199]: Starting pull emails with syncmaildir...
mar 22 16:24:00 curie smd-pull[12051]: 10466 ?        00:00:00 smd-push
mar 22 16:24:00 curie smd-pull[12051]: Already running.
mar 22 16:24:00 curie smd-pull[12051]: If this is not the case, remove /home/anarcat/.smd/lock by hand.
mar 22 16:24:00 curie smd-pull[12051]: any: smd-pushpull@localhost: TAGS: error::context(locking) probable-cause(another-instance-is-running) human-intervention(necessary) suggested-actions(run(kill 10466) run(rm /home/anarcat/.smd/lock))
mar 22 16:24:00 curie systemd[3199]: smd-pull.service: Main process exited, code=exited, status=1/FAILURE
mar 22 16:24:00 curie systemd[3199]: smd-pull.service: Failed with result 'exit-code'.
mar 22 16:24:00 curie systemd[3199]: Failed to start pull emails with syncmaildir.

... and the long push finally resolving:

mar 22 16:24:00 curie smd-push[10466]: smd-client: ERROR: Data transmission failed.
mar 22 16:24:00 curie smd-push[10466]: smd-client: ERROR: This problem is transient, please retry.
mar 22 16:24:00 curie smd-push[10466]: smd-client: ERROR: server sent ABORT or connection died
mar 22 16:24:00 curie smd-push[10466]: smd-client: ERROR: Data transmission failed.
mar 22 16:24:00 curie smd-push[10466]: smd-client: ERROR: This problem is transient, please retry.
mar 22 16:24:00 curie smd-push[10466]: smd-client: ERROR: server sent ABORT or connection died
mar 22 16:24:00 curie smd-push[10466]: smd-server: ERROR: Unable to open Maildir/.kobo/cur/1498563708.M122624P22121.marcos,S=32234,W=32792:2,S: Maildir/.kobo/cur/1498563708.M122624P22121.marcos,S=32234,W=32792:2,S: No such file or directory
mar 22 16:24:00 curie smd-push[10466]: smd-server: ERROR: The problem should be transient, please retry.
mar 22 16:24:00 curie smd-push[10466]: smd-server: ERROR: Unable to open requested file.
mar 22 16:24:00 curie smd-push[10466]: default: smd-client@smd-server-anarcat: TAGS: stats::new-mails(0), del-mails(293920), bytes-received(0), xdelta-received(26995)
mar 22 16:24:00 curie smd-push[10466]: default: smd-client@smd-server-anarcat: TAGS: error::context(receive) probable-cause(network) human-intervention(avoidable) suggested-actions(retry)
mar 22 16:24:00 curie smd-push[10466]: default: smd-server@localhost: TAGS: error::context(transmit) probable-cause(simultaneous-mailbox-edit) human-intervention(avoidable) suggested-actions(retry)
mar 22 16:24:00 curie systemd[3199]: smd-push.service: Main process exited, code=exited, status=1/FAILURE
mar 22 16:24:00 curie systemd[3199]: smd-push.service: Failed with result 'exit-code'.
mar 22 16:24:00 curie systemd[3199]: Failed to start push emails with syncmaildir.
mar 22 16:24:00 curie systemd[3199]: Starting push emails with syncmaildir...

This pattern repeats until 16:35, when that locking issue silently recovered somehow:

mar 22 16:35:03 curie systemd[3199]: Starting pull emails with syncmaildir...
mar 22 16:35:41 curie smd-pull[20788]: default: smd-client@localhost: TAGS: stats::new-mails(5), del-mails(1), bytes-received(21885), xdelta-received(6863398)
mar 22 16:35:42 curie smd-pull[21373]: register: smd-client@localhost: TAGS: stats::new-mails(0), del-mails(0), bytes-received(0), xdelta-received(215)
mar 22 16:35:42 curie systemd[3199]: smd-pull.service: Succeeded.
mar 22 16:35:42 curie systemd[3199]: Started pull emails with syncmaildir.
mar 22 16:36:35 curie systemd[3199]: Starting pull emails with syncmaildir...
mar 22 16:36:36 curie smd-pull[21738]: default: smd-client@localhost: TAGS: stats::new-mails(0), del-mails(0), bytes-received(0), xdelta-received(214)
mar 22 16:36:37 curie smd-pull[21816]: register: smd-client@localhost: TAGS: stats::new-mails(0), del-mails(0), bytes-received(0), xdelta-received(215)
mar 22 16:36:37 curie systemd[3199]: smd-pull.service: Succeeded.
mar 22 16:36:37 curie systemd[3199]: Started pull emails with syncmaildir.

... notice that huge xdelta-received there, that's 7GB right there. Mysteriously, the curie mail spool survived this, possibly because smd-pull started failing again:

mar 22 16:38:00 curie systemd[3199]: Starting pull emails with syncmaildir...
mar 22 16:38:00 curie smd-pull[23556]: 21887 ?        00:00:00 smd-push
mar 22 16:38:00 curie smd-pull[23556]: Already running.
mar 22 16:38:00 curie smd-pull[23556]: If this is not the case, remove /home/anarcat/.smd/lock by hand.
mar 22 16:38:00 curie smd-pull[23556]: any: smd-pushpull@localhost: TAGS: error::context(locking) probable-cause(another-instance-is-running) human-intervention(necessary) suggested-actions(run(kill 21887) run(rm /home/anarcat/.smd/lock))
mar 22 16:38:00 curie systemd[3199]: smd-pull.service: Main process exited, code=exited, status=1/FAILURE
mar 22 16:38:00 curie systemd[3199]: smd-pull.service: Failed with result 'exit-code'.
mar 22 16:38:00 curie systemd[3199]: Failed to start pull emails with syncmaildir.

That could have been when i got on angela to check my mail, and it was busy doing the nasty removal stuff... although the times don't match. Here is when angela came back online:

anarcat@angela:~(main)$ last
anarcat  :0           :0               Mon Mar 22 19:57   still logged in
reboot   system boot  5.10.0-0.bpo.3-a Mon Mar 22 19:57   still running
anarcat  :0           :0               Mon Mar 22 17:43 - 18:47  (01:03)
reboot   system boot  5.10.0-0.bpo.3-a Mon Mar 22 17:39   still running

Then finally the sync on curie started failing with:

mar 22 16:46:35 curie systemd[3199]: Starting pull emails with syncmaildir...
mar 22 16:46:42 curie smd-pull[27455]: smd-server: ERROR: Client aborted, removing /home/anarcat/.smd/curie-anarcat__Maildir.db.txt.new and /home/anarcat/.smd/curie-anarcat__Maildir.db.txt.mtime.new
mar 22 16:46:42 curie smd-pull[27455]: smd-client: ERROR: Failed to copy Maildir/.debian/cur/1613401668.M901837P27073.marcos,S=3740,W=3815:2,S to Maildir/.koumbit/cur/1613401640.M415457P27063.marcos,S=3790,W=3865:2,S
mar 22 16:46:42 curie smd-pull[27455]: smd-client: ERROR: The destination already exists but its content differs.
mar 22 16:46:42 curie smd-pull[27455]: smd-client: ERROR: To fix this problem you have two options:
mar 22 16:46:42 curie smd-pull[27455]: smd-client: ERROR: - rename Maildir/.koumbit/cur/1613401640.M415457P27063.marcos,S=3790,W=3865:2,S by hand so that Maildir/.debian/cur/1613401668.M901837P27073.marcos,S=3740,W=3815:2,S
mar 22 16:46:42 curie smd-pull[27455]: smd-client: ERROR:   can be copied without replacing it.
mar 22 16:46:42 curie smd-pull[27455]: smd-client: ERROR:   Executing `cd; mv -n "Maildir/.koumbit/cur/1613401640.M415457P27063.marcos,S=3790,W=3865:2,S" "Maildir/.koumbit/cur/1616446002.1.localhost"` should work.
mar 22 16:46:42 curie smd-pull[27455]: smd-client: ERROR: - run smd-push so that your changes to Maildir/.koumbit/cur/1613401640.M415457P27063.marcos,S=3790,W=3865:2,S
mar 22 16:46:42 curie smd-pull[27455]: smd-client: ERROR:   are propagated to the other mailbox
mar 22 16:46:42 curie smd-pull[27455]: default: smd-client@localhost: TAGS: error::context(copy-message) probable-cause(concurrent-mailbox-edit) human-intervention(necessary) suggested-actions(run(mv -n "/home/anarcat/.smd/workarea/Maildir/.koumbit/cur/1613401640.M415457P27063.marcos,S=3790,W=3865:2,S" "/home/anarcat/.smd/workarea/Maildir/.koumbit/tmp/1613401640.M415457P27063.marcos,S=3790,W=3865:2,S") run(smd-push default))
mar 22 16:46:42 curie systemd[3199]: smd-pull.service: Main process exited, code=exited, status=1/FAILURE
mar 22 16:46:42 curie systemd[3199]: smd-pull.service: Failed with result 'exit-code'.
mar 22 16:46:42 curie systemd[3199]: Failed to start pull emails with syncmaildir.

It went on like this until I found the problem. This is, presumably, a good thing because those emails were not being destroyed.

On angela, things looked like this:

-- Reboot --
mar 22 17:39:29 angela systemd[1677]: Started run notmuch new at least once a day.
mar 22 17:39:29 angela systemd[1677]: Started run smd-pull regularly.
mar 22 17:40:46 angela systemd[1677]: Starting pull emails with syncmaildir...
mar 22 17:43:18 angela smd-pull[3916]: smd-server: ERROR: Unable to open Maildir/.tor/new/1616446842.M285912P26118.marcos,S=8860,W=8996: Maildir/.tor/new/1616446842.M285912P26118.marcos,S=886
0,W=8996: No such file or directory
mar 22 17:43:18 angela smd-pull[3916]: smd-server: ERROR: The problem should be transient, please retry.
mar 22 17:43:18 angela smd-pull[3916]: smd-server: ERROR: Unable to open requested file.
mar 22 17:43:18 angela smd-pull[3916]: smd-client: ERROR: Data transmission failed.
mar 22 17:43:18 angela smd-pull[3916]: smd-client: ERROR: This problem is transient, please retry.
mar 22 17:43:18 angela smd-pull[3916]: smd-client: ERROR: server sent ABORT or connection died
mar 22 17:43:18 angela smd-pull[3916]: default: smd-server@smd-server-anarcat: TAGS: error::context(transmit) probable-cause(simultaneous-mailbox-edit) human-intervention(avoidable) suggested
-actions(retry)
mar 22 17:43:18 angela smd-pull[3916]: default: smd-client@localhost: TAGS: error::context(receive) probable-cause(network) human-intervention(avoidable) suggested-actions(retry)
mar 22 17:43:18 angela systemd[1677]: smd-pull.service: Main process exited, code=exited, status=1/FAILURE
mar 22 17:43:18 angela systemd[1677]: smd-pull.service: Failed with result 'exit-code'.
mar 22 17:43:18 angela systemd[1677]: Failed to start pull emails with syncmaildir.
mar 22 17:43:18 angela systemd[1677]: Starting pull emails with syncmaildir...
mar 22 17:43:29 angela smd-pull[4847]: default: smd-client@localhost: TAGS: stats::new-mails(29), del-mails(0), bytes-received(401519), xdelta-received(38914)
mar 22 17:43:29 angela smd-pull[5600]: register: smd-client@localhost: TAGS: stats::new-mails(2), del-mails(0), bytes-received(92150), xdelta-received(471)
mar 22 17:43:29 angela systemd[1677]: smd-pull.service: Succeeded.
mar 22 17:43:29 angela systemd[1677]: Started pull emails with syncmaildir.
mar 22 17:43:29 angela systemd[1677]: Starting push emails with syncmaildir...
mar 22 17:43:32 angela smd-push[5693]: default: smd-client@smd-server-anarcat: TAGS: stats::new-mails(0), del-mails(0), bytes-received(0), xdelta-received(217)
mar 22 17:43:33 angela smd-push[6575]: register: smd-client@smd-server-register: TAGS: stats::new-mails(0), del-mails(0), bytes-received(0), xdelta-received(219)
mar 22 17:43:33 angela systemd[1677]: smd-push.service: Succeeded.
mar 22 17:43:33 angela systemd[1677]: Started push emails with syncmaildir.

Notice how long it took to get the first error, in that first failure: it failed after 3 minutes! Presumably that's when it started deleting all that mail. And this is during pull, not push, so the error didn't come from angela.

Affected data

It seems 2GB of mail from my main INBOX was destroyed. Another 2.4GB of spam (kept for training purposes) was also destroyed, along with 700MB of Sent mail. The rest is hard to figure out, because the folders are actually still there, just smaller. So I relied on ncdu to figure out the size changes.

(Note that I don't really archive (or delete much of) my mail since I use notmuch, which is why the INBOX is so large...)

Concretely, according to the notmuch-new.service which still runs periodically on marcos, here are the changes that happened on the server:

mar 22 16:17:12 marcos notmuch[10729]: Added 7 new messages to the database. Removed 57985 messages. Detected 1372 file renames.
mar 22 16:22:43 marcos notmuch[12826]: No new mail. Removed 143842 messages. Detected 6072 file renames.
mar 22 16:27:02 marcos notmuch[13969]: No new mail. Removed 82071 messages. Detected 1783 file renames.
mar 22 16:29:45 marcos notmuch[15079]: Added 22743 new messages to the database. Detected 1 file rename.
mar 22 16:31:48 marcos notmuch[16196]: Added 22779 new messages to the database. Removed 5 messages.
mar 22 16:33:11 marcos notmuch[17192]: Added 3711 new messages to the database.
mar 22 16:40:41 marcos notmuch[19122]: Added 74558 new messages to the database. Detected 1 file rename.
mar 22 16:43:21 marcos notmuch[20325]: Added 9061 new messages to the database. Detected 4 file renames.
mar 22 17:43:08 marcos notmuch[7420]: Added 1793 new messages to the database. Detected 6 file renames.

That is basically the entire mail spool destroyed at first (283 898 messages), and then bits and pieces of it progressively re-added (134 645 messages), somehow, so 149 253 mails were lost, presumably.

Recovery

I disabled the services all over the place:

systemctl --user --now disable smd-pull.service smd-pull.timer smd-push.service smd-push.timer notmuch-new.service notmuch-new.timer

(Well, technically, I did that only on angela, as I thought the problem was there. Luckily, curie kept going but it seems like it was harmless.)

I made a backup of the mail spool on curie:

tar cf - Maildir/ | pv -s 14G | gzip -c > Maildir.tgz

Then I crossed my fingers and ran smd-push -v -s, as that was suggested by smd error codes themselves. That thankfully started restoring mail. It failed a few times on weird cases of files being duplicates, but I resolved this by following the instructions. Or mostly: I actually deleted the files instead of moving them, which made smd even unhappier (if there ever was such a thing). I had to recreate some of those files, so, lesson learned: do follow the advice smd gives you, even if it seems useless or strange.

But then smd-push was humming along, uploading tens of thousands of messages, saturating the upload in the office, refilling the mail spool on the server... yaay!... ?

Except... well, of course that didn't quite work: the mail spool in the office eventually started to grow beyond the size of the mail spool on the workstation. That is what smd-push eventually settled on:

default: smd-client@smd-server-anarcat: TAGS: error::context(receive) probable-cause(network) human-intervention(avoidable) suggested-actions(retry)
default: smd-client@smd-server-anarcat: TAGS: error::context(receive) probable-cause(network) human-intervention(avoidable) suggested-actions(retry)
default: smd-client@smd-server-anarcat: TAGS: stats::new-mails(151697), del-mails(0), bytes-received(7539147811), xdelta-received(10881198)

It recreated 151 697 emails, adding about 2000 emails to the pool, kind of from nowhere at all. On marcos, before:

ncdu 1.13 ~ Use the arrow keys to navigate, press ? for help
--- /home/anarcat/Maildir ------------------------------------
    4,0 GiB [##########] /.notmuch
  717,3 MiB [#         ] /.Archives.2014
  498,2 MiB [#         ] /.feeds.debian-planet
  453,1 MiB [#         ] /.Archives.2012
  414,5 MiB [#         ] /.debian
  408,2 MiB [#         ] /.quoifaire
  389,8 MiB [          ] /.rapports
  356,6 MiB [          ] /.tor
  182,6 MiB [          ] /.koumbit
  179,8 MiB [          ] /tmp
   56,8 MiB [          ] /.nn
   43,0 MiB [          ] /.act-mtl
   32,6 MiB [          ] /.feeds.sysadvent
   31,7 MiB [          ] /.feeds.releases
   31,4 MiB [          ] /.Sent.2005
   26,3 MiB [          ] /.sage
   25,5 MiB [          ] /.freedombox
   24,0 MiB [          ] /.feeds.git-annex
   21,1 MiB [          ] /.Archives.2011
   19,1 MiB [          ] /.Sent.2003
   16,7 MiB [          ] /.bugtraq
   16,2 MiB [          ] /.mlug
 Total disk usage:   8,0 GiB  Apparent size:   7,6 GiB  Items: 184426

After:

ncdu 1.13 ~ Use the arrow keys to navigate, press ? for help
--- /home/anarcat/Maildir ------------------------------------
    4,7 GiB [##########] /.notmuch
    2,7 GiB [#####     ] /.junk
    1,9 GiB [###       ] /cur
  717,3 MiB [#         ] /.Archives.2014
  659,3 MiB [#         ] /.Sent
  513,9 MiB [#         ] /.Archives.2012
  498,2 MiB [#         ] /.feeds.debian-planet
  449,6 MiB [          ] /.Archives.2015
  414,5 MiB [          ] /.debian
  408,2 MiB [          ] /.quoifaire
  389,8 MiB [          ] /.rapports
  380,8 MiB [          ] /.Archives.2013
  356,6 MiB [          ] /.tor
  261,1 MiB [          ] /.Archives.2011
  240,9 MiB [          ] /.koumbit
  183,6 MiB [          ] /.Archives.2010
  179,8 MiB [          ] /tmp
  128,4 MiB [          ] /.lists
  106,1 MiB [          ] /.inso-interne
  103,0 MiB [          ] /.github
   75,0 MiB [          ] /.nanog
   69,8 MiB [          ] /.full-disclosure
 Total disk usage:  16,2 GiB  Apparent size:  15,5 GiB  Items: 341143

That is 156 717 files more.

On curie:

ncdu 1.13 ~ Use the arrow keys to navigate, press ? for help
--- /home/anarcat/Maildir ------------------------------------------------------------------
    2,7 GiB [##########] /.junk
    2,3 GiB [########  ] /.notmuch
    1,9 GiB [######    ] /cur
  661,2 MiB [##        ] /.Archives.2014
  655,3 MiB [##        ] /.Sent
  512,0 MiB [#         ] /.Archives.2012
  447,3 MiB [#         ] /.Archives.2015
  438,5 MiB [#         ] /.feeds.debian-planet
  406,5 MiB [#         ] /.quoifaire
  383,6 MiB [#         ] /.debian
  378,6 MiB [#         ] /.Archives.2013
  303,3 MiB [#         ] /.tor
  296,0 MiB [#         ] /.rapports
  237,6 MiB [          ] /.koumbit
  233,2 MiB [          ] /.Archives.2011
  182,1 MiB [          ] /.Archives.2010
  127,0 MiB [          ] /.lists
  104,8 MiB [          ] /.inso-interne
  102,7 MiB [          ] /.register
   89,6 MiB [          ] /.github
   67,1 MiB [          ] /.full-disclosure
   66,5 MiB [          ] /.nanog
 Total disk usage:  13,3 GiB  Apparent size:  12,6 GiB  Items: 342465

Interestingly, there are more files, but less disk usage. It's possible the notmuch database there is more efficient. So maybe there's nothing to worry about.

Last night's marcos backup has:

root@marcos:/home/anarcat# find /mnt/home/anarcat/Maildir | pv -l | wc -l
 341k 0:00:16 [20,4k/s] [                             <=>                                                                                                                                     ]
341040

... 341040 files, which seems about right, considering some mail was delivered during the day. An audit can be performed with hashdeep:

borg mount /media/sdb2/borg/::marcos-auto-2021-03-22 /mnt
hashdeep -c sha256 -r /mnt/home/anarcat/Maildir | pv -l -s 341k > Maildir-backup-manifest.txt

And then compared with:

hashdeep -c sha256 -k Maildir-backup-manifest.txt Maildir/

Some extra files should show up in the Maildir, and very few should actually be missing, because I shouldn't have deleted mail from the previous day the next day, or at least very few. The actual summary hashdeep gave me was:

hashdeep: Audit failed
   Input files examined: 0
  Known files expecting: 0
          Files matched: 339080
Files partially matched: 0
            Files moved: 782
        New files found: 107
  Known files not found: 106

So 106 files added, 107 deleted. Seems good enough for me...

Postfix was stopped at Mar 22 21:12:59 to try and stop external events from confusing things even further. I reviewed the delivery log to see if mail that came in during the problem window disappeared:

grep 'dovecot:.*stored mail into mailbox' /var/log/mail.log |
  tail -20 |
  sed 's/.*msgid=<//;s/>.*//' | 
  while read msgid; do 
    notmuch count --exclude=false id:$msgid |
      grep 0 && echo $msgid missing;
  done

And things looked okay. Now of course if we go further back, we find mail I actually deleted (because I do do that sometimes), so it's hard to use this log as an audit trail. We can only hope that the curie spool is sufficiently coherent to be relied on.

Worst case, we'll have to restore from last night's backup, but that's getting far away now: I get hundreds of mails a day in that mail spool, and reseting back to last night does not seem like a good idea.

A dry run of smd-pull on angela seems to agree that it's missing some files:

default: smd-client@localhost: TAGS: stats::new-mails(154914), del-mails(0), bytes-received(0), xdelta-received(0)

... a number of mails somewhere in between the other two, go figure. A "wet" run of this was started, without deletion (-n), which gave us:

default: smd-client@localhost: TAGS: stats::new-mails(154911), del-mails(0), bytes-received(7658160107), xdelta-received(10837609)

Strange that it sync'd three less emails, but that's still better than nothing, and we have a mail spool on angela again:

anarcat@angela:~(main)$ notmuch new
purging with prefix '.': spam moved (0), ham moved (0), deleted (0), done
Note: Ignoring non-mail file: /home/anarcat/Maildir//.uidvalidity
Processed 1779 total files in 26s (66 files/sec.).
Added 1190 new messages to the database. Removed 3 messages. Detected 593 file renames.
tagging with prefix '.': spam, sent, feeds, koumbit, tor, lists, rapports, folders, done.

Notice how only 1190 messages were re-added, that is because I killed notmuch before it had time to remove all those mails from its database.

Possible causes

I am totally at a loss as to why smd started destroying everything like it did. But a few things come to mind:

1. I rewired my office on that day.

2. This meant unplugging curie, the workstation.

3. It has a bad CMOS battery (known problem), so it jumped around the time continuum a few times, sometimes by years.

4. The smd services are ran from a systemd unit with OnCalendar=*:0/2. I have heard that it's possible that major time jumps "pile up" execution of jobs, and it seems this happened in this case.

5. It's possible that locking in smd is not as great as it could be, and that it corrupted its internal data structures on curie, which led it to command a destruction of the remote mail spool.

It's also possible that there was a disk failure on the server, marcos. But since it's running on a (software) RAID-1 array, and no errors have been found (according to dmesg), I don't think that's a plausible hypothesis.

Lessons learned

1. follow what smd says, even if it seems useless or strange.

2. trust but verify: just backup everything before you do anything, especially the largest data set.

3. daily backups are not great for email, unless you're ready to lose a day of email (which I'm not).

4. hashdeep is great. I keep finding new use cases for it. Last time it was to audit my camera SD card to make sure I didn't forget anything, and now this. it's fast and powerful.

5. borg is great too. the FUSE mount was especially useful, and it was pretty fast to explore the backup, even through that overhead: checksumming 15GB of mail took about 35 minutes, which gives a respectable 8MB/s, probably bottlenecked by the crap external USB drive I use for backups (!).

6. I really need to finish my backup system so that I have automated offsite backups, although in this case that would actually have been much slower (certainly not 8MB/s!).

Workarounds and solutions

I setup fake-hwclock on curie, so that the next power failure will not upset my clock that badly.

I am thinking of switching to ZFS or BTRFS for most of my filesystems, so that I can use filesystem snapshots (including remotely!) as a backup strategy. This seems so much more powerful than crawling the filesystem for changes, and allows for truly offsite backups protected from an attacker (hopefully). But it's a long way there.

I'm also thinking of rebuilding my mail setup without smd. It's not the first time something like this happens with smd. It's the first time I am more confident it's the root cause of the problem, however, and it makes me really nervous for the future.

I have used offlineimap in the past and it seems it was finally ported to Python 3 so that could be an option again. isync/mbsync is another option, which I tried before but do not remember why I didn't switch. A complete redesign with something like getmail and/or nncp could also be an option. But alas, I lack the time to go crazy with those experiments.

Somehow, doing like everyone else and just going with Google still doesn't seem to be an option for me. Screw big tech. But I am afraid they will win, eventually.

In any case, I'm just happy I got mail again, strangely.