geniass
geniass

Reputation: 399

Why does my time.Ticker work fine for 6 months then suddenly stop sending ticks?

I haven't been able to find any mention of this really weird issue after searching for a while. It's very rare but not the first time I've seen it happen.

I have written a simple Go program (compiled with go version go1.20.4 linux/amd64) that runs as a daemon to periodically sync some data from an external API. Here is the relevant code for polling:

    ticker := time.NewTicker(config.CollectionPollInterval)
    defer ticker.Stop()
    for {
        select {
        case <-ctx.Done():
            return nil
        case <-ticker.C:
            if err := syncAllCollections(); err != nil {
                return err
            }
        }
    }

where config.CollectionPollInterval is 24h.

So this code has been running as a "simple" systemd unit, polling the API once a day, every day for the last 6 months:

$ systemctl status my-go-process.service 
● my-go-process.service - daemon
     Loaded: loaded (/lib/systemd/system/my-go-process.service; enabled; vendor preset: enabled)
     Active: active (running) since Tue 2023-05-16 09:56:56 UTC; 6 months 8 days ago
   Main PID: 377922 (my-go-process)
      Tasks: 14 (limit: 38269)
     Memory: 5.0M
     CGroup: /system.slice/my-go-process.service
             └─377922 /usr/local/bin/my-go-process -config-file /home/config.json

Nov 02 09:57:21 tot my-go-process[377922]: 2023/11/02 09:57:21 main.go:89: ***********
Nov 02 09:57:21 tot my-go-process[377922]: 2023/11/02 09:57:21 main.go:96: ***********
Nov 02 09:57:21 tot my-go-process[377922]: 2023/11/02 09:57:21 main.go:89: ***********
Nov 02 09:57:22 tot my-go-process[377922]: 2023/11/02 09:57:22 main.go:96: ***********
Nov 02 09:57:22 tot my-go-process[377922]: 2023/11/02 09:57:22 main.go:89: ***********
Nov 02 09:57:22 tot my-go-process[377922]: 2023/11/02 09:57:22 main.go:96: ***********
Nov 02 09:57:22 tot my-go-process[377922]: 2023/11/02 09:57:22 main.go:89: ***********
Nov 02 09:57:23 tot my-go-process[377922]: 2023/11/02 09:57:23 main.go:96: ***********
Nov 02 09:57:23 tot my-go-process[377922]: 2023/11/02 09:57:23 main.go:89: ***********
Nov 02 09:57:23 tot my-go-process[377922]: 2023/11/02 09:57:23 main.go:96: ***********

Here is the Unit file:

[Unit]
Description=daemon
After=network.target [email protected]

[Service]
Type=simple
User=user
ExecStart=/usr/local/bin/my-go-process -config-file ${HOME}/config.json

[Install]
WantedBy=multi-user.target

However as the logs show, the last polling attempt happened on 2 Nov and since then the program has been completely frozen.

I managed to attach a debugger and this is where it is stuck: execution is stuck on the select statement

Here I'm inspecting the ticker variable in the debugger: ticker variable inspection

I'm not sure how to interpret this, I thought when is nanoseconds since 1970 but these values wouldn't make sense. I've also considered that the when int64 might have overflowed but that also doesn't make sense.

I would have liked to upload a reproducible example of this but it might take 6 months for it to happen again.

I'm at a loss for what else to try. The program is still running with the debugger attached if anyone has suggestions to try.


A few more details:

module my_package

go 1.13

require (
    github.com/jackc/pgtype v1.3.0
    github.com/jackc/pgx/v4 v4.6.0
)

Upvotes: 3

Views: 189

Answers (0)

Related Questions