entrypoint-router.sh - unexpected script termination in termination_handler()

[bfg100k]

So I started running the new container in my Synology NAS yesterday and woke up this morning to find a system notification telling me that the container has stopped unexpectedly (this container is started and stopped by my backup scripts). Did some troubleshooting and found out that the problem occurs in the termination_handler() function - it appears that the entrypoint-router.sh script exits after sending SIGTERM to the pipe process. The consequences are docker gets a "terminated" message on stderr (from the kill command), the script exits (due to the -e flag) and the temporary pipe file never gets deleted (verify by running the container interactively and checking the /tmp folder).

@Paraphraser , I'm not clear what the comment in line 150 means. Where will the user be issuing the "sudo killall Zerotier-one" command? Interactively inside the container? If I turn set -e off, the script will run the termination handler twice - once due to the trap and another when the wait on zerotier daemon ends.

[Paraphraser]

For anyone following along at home, please skip past this post and resume reading two posts further down. I misunderstood the question so this is waaay off-topic.

---

What was going to be a short answer somehow grew. Sorry. Bit of an occupational hazard with me.

Normally, a command like killall would never be issued. Or, maybe I should qualify that and say "never be issued by any sensible user".

I spend most of my time over on SensorsIot/IOTstack which is just a set of conventions applied to docker-compose service definitions plus a menu system, all for running arbitrary collections of Docker containers - sort of start with MING (Mosquitto, InfluxDB, Node-RED and Grafana) and work up.

IOTstack attracts all comers, from people with a solid tech background to those who simply have a gleam in their eye about some IoT gizmo they want to build and are now looking for a way to log and visualise their data, but who otherwise don't have a solid tech background.

Perhaps the best way to illustrate the skills range is to say that one of the biggest problems we encounter is unnecessary use of sudo resulting in anything from stuff being installed in the wrong place to incorrect permissions causing havoc. A lot of our scripts have a check at the start saying "don't run this as root".

It is those people I had in mind when I gave the killall example. Clobbering the daemon directly rather than using docker-compose to take down the container is something I've seen happen with other containers. I wondered how ZeroTier would react so I experimented and made sure that the entry-point script would handle it gracefully.

But maybe, just by mentioning killall I've created a "positively no fishing from the balconies" example - an old story about a motel overlooking a river which had never had any trouble until one idiot decided to try casting from the balcony, smashed a window with an errant sinker; the management put up the signs; and suddenly every twit in the vicinity was booking-in with fishing rod in hand.

Similarly, the reason line 145 in the entry-point script reads:

trap termination_handler INT TERM HUP

when, arguably, TERM would do the job is down to conditions I was able to trigger at various points which those picked up. On the other hand, you don't see EXIT because that never seems to get called once the container has been told to go away. I mention this because maybe an adjustment to that list would get the job done...?

Having said all that, the first point I'll make is that I only have Raspberry Pis to test with so maybe what you're seeing is down to a Synology NAS difference?

The second point is that the temporary pipe file is in non-persistent storage so it will eventually get cleaned-up when the container is recreated. Just not on a restart if something stops the termination handler from succeeding. I think of that as normal expected behaviour.

The third point is to ask what I know will probably come across, initially, as that oh-so-infuriating question of why do you want to do this anyway?

Please bear with me as I try to explain.

One of my contributions to the IOTstack world is Paraphraser/IOTstackBackup. That's a set of scripts for backup and restore of IOTstack environments. The basic structure is like this:

iotstack_backup is an umbrella script calling the scripts below
    iotstack_backup_general
    iotstack_backup_«database»
    …       

iotstack_restore is an umbrella script calling the scripts below
    iotstack_restore_general
    iotstack_restore_«database»
    …       

In essence, if a container can't be backed up, safely, by simply copying its persistent storage, then it will have a special-case script. Databases (other than SQLite) need care so there are special-case scripts for InfluxDB, MariaDB and NextCloud. However, without exception, those special-case scripts work while the container is up and running. Each special-case script just tells the corresponding database engine to handle the backup, and then the script looks after the results (typically sweeping them into a tar).

Which brings me back to the "general" backup script. That handles everything else. In IOTstack, "everything else" covers a lot of ground:

adguardhome
adminer
bind9
blynk_server
chronograf
dashmachine
deconz
dhcpd
diyhue
domoticz
dozzle
duckdns
espruinohub
gitea
grafana
heimdall
home_assistant
homebridge
homer
kapacitor
mosquitto
motioneye
n8n
nodered
octoprint
openhab
pihole
plex
portainer_agent
portainer-ce
prometheus
prometheus-cadvisor
prometheus-nodeexporter
python
qbittorrent
rtl_433
syncthing
tasmoadmin
telegraf
timescaledb
transmission
webthings_gateway
wireguard
zigbee2mqtt
zigbee2mqtt_assistant

Every single one of those is backed-up, while its container is running, simply by copying the contents of its persistent storage.

Restore is a slightly different question. That does require the stack to be down. The "general" restore just sticks the recovered docker-compose.yml in the right place and replaces the relevant persistent storage folders from the general backup (the long list above). The special cases all follow the recipe of erasing the old persistent storage (if it exists), bringing up the container so it self-initialises new persistent storage, puts the "backup files" where the container can see them, tells the database engine to restore, and stops the container again.

On a bare-metal build, instructions to bring up a database container will also result in a pull from DockerHub but, otherwise, all the "general" containers will only pull their images as a side effect of the next docker-compose up -d.

I can go from a blank SSD to a rebuilt Bullseye plus fully-restored and running IOTstack with about a gig of data in various databases in about half an hour. I run through the whole process reasonably frequently to give myself confidence that both the build scripts (PiBuilder) and the IOTstackBackup scripts work correctly, and that I'm not giving false comfort to anyone who uses my scripts.

nothing worse than a backup that can't be restored, right?

To summarise, this area of what you can and can't do when backing-up containers while they are running, and being sure the containers can subsequently be restored to the moment of the backup, is something I'm pretty familiar with.

I see absolutely nothing in the ZeroTier persistent storage that means it needs any special handling. Consider the following:

$ rm -rf ~/zerotier-backup.tar.gz ~/zerotier-one

$ DPS zerotier
NAMES      CREATED        STATUS
zerotier   43 hours ago   Up 43 hours
$ docker logs zerotier
Sun Jul 31 20:11:06 AEST 2022 - launching ZeroTier-One in routing mode
adding iptables-nft rules for bi-directional traffic (local interfaces eth0 wlan0 to/from ZeroTier)
Sun Jul 31 20:11:06 AEST 2022 - ZeroTier daemon is running as process 20

$ touch ~/zerotier-backup.tar.gz
$ tar -czf ~/zerotier-backup.tar.gz -C ~/IOTstack/volumes/zerotier-one .

$ mkdir ~/zerotier-one
$ tar -xzf ~/zerotier-backup.tar.gz -C ~/zerotier-one .
$ tree ~/zerotier-one
/home/pi/zerotier-one
├── authtoken.secret
├── controller.d
│   ├── network
│   └── trace
├── identity.public
├── identity.secret
├── networks.d
│   ├── xxxxxxxxxxxxxxxx.conf
│   └── xxxxxxxxxxxxxxxx.local.conf
├── peers.d
│   ├── yyyyyyyyyy.peer
│   ├── … .peer
├── planet
├── zerotier-one.pid
└── zerotier-one.port

5 directories, 19 files

$ TERMINATE zerotier
[+] Running 1/1
 ⠿ Container zerotier  Stopped                                                                                         2.8s
Going to remove zerotier
[+] Running 1/0
 ⠿ Container zerotier  Removed                                                                                         0.0s

$ sudo mv ~/IOTstack/volumes/zerotier-one ~/IOTstack/volumes/zerotier-one.off

$ sudo mv ~/zerotier-one ~/IOTstack/volumes/zerotier-one

$ UP zerotier
[+] Running 1/1
 ⠿ Container zerotier  Started                                                                                         0.4s

$ docker logs zerotier
Tue Aug  2 14:47:28 AEST 2022 - launching ZeroTier-One in routing mode
adding iptables-nft rules for bi-directional traffic (local interfaces eth0 wlan0 to/from ZeroTier)
Tue Aug  2 14:47:28 AEST 2022 - ZeroTier daemon is running as process 20

$ DPS zerotier
NAMES      CREATED          STATUS
zerotier   12 seconds ago   Up 11 seconds

$ tree ~/IOTstack/volumes/zerotier-one
/home/pi/IOTstack/volumes/zerotier-one
├── authtoken.secret
├── controller.d
│   ├── network
│   └── trace
├── identity.public
├── identity.secret
├── networks.d
│   ├── xxxxxxxxxxxxxxxx.conf
│   └── xxxxxxxxxxxxxxxx.local.conf
├── peers.d
│   ├── yyyyyyyyyy.peer
│   ├── … .peer
├── planet
├── zerotier-one.pid
└── zerotier-one.port

5 directories, 19 files
$ 

In words:

1. Prove ~/zerotier-backup.tar.gz ~/zerotier-one/ don't exist.
2. Show ZeroTier is running and seems happy enough. DPS is an alias on docker ps.
3. Take a snapshot with tar.
4. Create ~/zerotier-one/, restore into it, and show its content (with redactions to protect the innocent).
5. Clobber the container. TERMINATE is an alias on docker-compose.
6. Move existing persistent storage out of the way.
7. Move the restored version from step 4 into place as the new persistent storage.
8. Bring up the container (UP being another alias).
9. Show the container is running and happy.
10. Show the new persistent storage (with redactions).

The only likely candidate for the daemon getting upset is the pid file but, if you think about it, no daemon can ever be sure that its prior invocation had the chance to clean up so it has to make do.

Now, sure, a backup taken today might not be 100% appropriate if it's restored next week after a whole bunch of client changes. But that will be the case even if the container is stopped for the backup.

Bottom line: you shouldn't need to stop the ZeroTier container to back it up.

I'm not saying that what you've encountered doesn't represent a class of problem which should be tracked down and dealt with. My testing was limited to using docker and docker-compose commands to up/down/restart the container (and, while I was tinkering, build commands which replace the container at the end). But, again, only on the Raspberry Pi.

Somewhere in all that verbiage I hope I've helped.

[Paraphraser]

At the risk of telling you something you already know, when debugging the entry-point script I normally add these lines after the set:

LOGFILE="/var/lib/zerotier-one/debug.log"
touch "$LOGFILE"
exec >> "$LOGFILE"
exec 2>> "$LOGFILE"

Then, typically from another terminal window I can run:

$ tail -f ~/IOTstack/volumes/zerotier-one/debug.log

and then add echo statements to the script at all points of the compass to figure out what the heck is going on.

[bfg100k]

I think you may have mistaken my use case. I back up important data on my NAS and a few other PCs on LAN to a dedicated backup server (actually just a pi with a very large attached USB storage) in a remote location. I use ZT as I don't have access to static IPs at either end (so can't run traditional VPNs). To reduce risk, I will only bring up the ZT container during the scheduled backup window (via docker start/stop commands in my backup script). This container works as intended (my backups completed successfully) so this issue isn't a showstopper. Having said that, I was surprised to see the system notification so decided to look into it.

To clarify, the issue seems to be that in the termination_handler function, line 135 (i.e. kill -TERM ${TAIL_PIPE_PID}) returns an error (i.e. terminated in stderr) which causes the script to end (due to the -e switch setting) thus line 140 (i.e. rm "${TAIL_PIPE}") is never reached.

Can you confirm the above is not the case in your setup?

[Paraphraser]

OK - I definitely misunderstood. Completely! 🤦🏼‍♂️🤦🏼‍♂️🤦🏼‍♂️ Doh!

After instrumenting entrypoint-router.sh and building a local image, I agree. The termination handler gets as far as the wait and doesn't process the remove.

But, while I am seeing the "Terminated" (not appreciating its significance until now), I'm not getting any other complaints, alerts, notifications, whatever. Is that something specific you've set up?

After a bit more experimentation, I think it might be better to just delete these lines entirely:

#   # tell the pipe listener to go away too
#   if [ -d "/proc/${TAIL_PIPE_PID}" ] ; then
#       kill -TERM ${TAIL_PIPE_PID}
#       wait ${TAIL_PIPE_PID}
#   fi

#   # clean up the pipe file
#   rm "${TAIL_PIPE}"

with those lines commented-out:

$ docker exec zerotier ps
PID   USER     TIME  COMMAND
    1 root      0:00 sh /usr/sbin/entrypoint-router.sh -U
   20 root      0:00 tail -f /tmp/zerotier-ipc-oMBAkk
   21 root      0:01 zerotier-one -U
   27 root      0:00 ps
$ docker-compose restart zerotier
[+] Running 1/1
 ⠿ Container zerotier  Started                                                                                                                                                                             2.8s
$ docker exec zerotier ps
PID   USER     TIME  COMMAND
    1 root      0:00 sh /usr/sbin/entrypoint-router.sh -U
   20 root      0:00 tail -f /tmp/zerotier-ipc-PHmple
   21 root      0:00 zerotier-one -U
   27 root      0:00 ps
$ docker exec zerotier ls -l /tmp
total 0
-rw-------    1 root     root             0 Aug  2 23:43 zerotier-ipc-PHmple
-rw-------    1 root     root             0 Aug  2 23:39 zerotier-ipc-oMBAkk

with the container log showing:

Tue Aug  2 23:43:33 AEST 2022 - terminating ZeroTier-One
removing iptables-nft rules for bi-directional traffic (local interfaces eth0 wlan0 to/from ZeroTier)
Tue Aug  2 23:43:35 AEST 2022 - launching ZeroTier-One in routing mode
adding iptables-nft rules for bi-directional traffic (local interfaces eth0 wlan0 to/from ZeroTier)
Tue Aug  2 23:43:35 AEST 2022 - ZeroTier daemon is running as process 21

No "Terminated" and the first tail process has been cleaned-up. All we have left is the old log file. Although /tmp is not persisted, I have also seen sufficient restart loops to appreciate that we don't really want a zillion of these accumulating in a hurry.

Possibilities:

1. Remove the e flag. When I do that with the script "as is", I get a double-exit (calling the handler from the trap and then again after the last wait returns) so more work would be needed to go down that route.
2. Leave the e in place. Remove the lines of code that tell the pipe to die and rm the pipe file. Add startup code to clean-up any old logs.

3. Leave the e in place. Remove the lines of code that tell the pipe to die and rm the pipe file. Use a fixed name (instead of a randomly-generated name) for the log file. As in:

   # define where the ZeroTier daemon will write its output (if any)
   #TAIL_PIPE=$(mktemp /tmp/zerotier-ipc-XXXXXX)
   TAIL_PIPE=/tmp/zerotier-ipc-log
   cat /dev/null >"${TAIL_PIPE}"

   The pipe file will still start empty, be non-persistent so it will get cleaned-up on a termination, and won't fill up /tmp if the container goes into a restart loop.

I'm inclined to go with option 3. Thoughts?

[Paraphraser]

I've just pushed PR #16 containing the "option 3" fixes.

[bfg100k]

option 3 sounds good. Actually I did a test while troubleshooting with just commenting out the whole IF block for the pipe listener and it works (i.e. temp file is removed and no further complaints).

Regarding my system notification - yes its a Synology thing. When a docker container exits with a die event, DSM (the Synology OS) will send a system notification.

[Paraphraser]

Ah! The only way I could even see the "Terminated" was to send a restart to the container and then run docker logs, or instrument the script to redirect stderr.

Thinking back, probably the only reason for using mktemp was pure habit. Dumb.

I'd like to say I can't fault the revised script but, then, I didn't notice the problem with the earlier version so I'd rather leave it to your system to declare success or more work to do.