Logging after an automatic update

Hey,

I recently filed an issue about running syncthing inside a tmux detached session https://github.com/syncthing/syncthing/issues/2144 => In a nutshell, apparently tmux does not let the monitor “respawn” itself after, and we don’t really know why.

Anyway, the reason for me using tmux was mainly to try and capture the syncthing logs, but it seems to me that logging won’t persist after an automatic update, even when I just try to just redirect syncthing’s stdout to a file (e.g. ./syncthing &> mylogfile.log). I guess this is still due to syncthing’s monitor restart.

As I understood from issue #411, syncthing’s philosophy about logging is to put everything on stdout (or stderr) which I find is a good idea. However, what happens after the - arguably frequent - updates? I may be wrong but I don’t see a straight forward way of capturing the new updated monitor’s stdout.

Should we assume that automatic updates are just for these early versions of syncthing and not for the long term? I think they are disabled for distributed packages (homebrew, apt-get…). They seem to me like a great feature though, especially for development purposes.

Furthermore, it seems to me that syncthing’s logs after a fresh update could always be interesting.

The auto-update is disabled in packages, because the package manager (apt-get, yum, …) is responsible for updates.

I am also interested in the logging after auto-update, as I always have to shutdown synthing and manually start it to enable logging. (I am using syncthing &> logfile as an @reboot cronjob).

There is allready a discussion and a commit on github to enable -logfile on all platforms, not only windows.

Processes spawned by other processes inherit stdout/err from the parent, as explained in the post. Given syncthing is restarting itself, it starts a copy of itself and then exists, which means that stdout and stderr should be inherited.

If restarts are handled by your service manager, then your service manager handles that

Hi Audrius, thanks for your answer.

Ok, now that is weird, because I can assure you that nothing displays on my terminal (just with ./syncthing) when syncthing’s monitor restarts after an automatic update. Instead I get back to the prompt:

[XXXXX] 08:48:32 INFO: Automatic upgrade (current "v0.11.18" < latest "v0.11.19")
[XXXXX] 08:48:35 WARNING: Automatically upgraded to version "v0.11.19". Restarting in 1 minute.
[XXXXX] 08:49:35 OK: Exiting
[monitor] 08:49:35 INFO: Restarting monitor...
hippo ~/libs $

I don’t know what it’s worth, but I tried to capture the file descriptors associated to the syncthing processes, and it seems that the monitor’s standard output after update is pointing to /dev/null:

Before update:

hippo ~ $ ps aux | grep "[s]yncthing"
hippo     6865  0.6  0.4 257580  5028 pts/10   Sl+  08:48   0:00 ./syncthing
hippo     6869  118  3.1 216256 31704 pts/10   Sl+  08:48   0:05 ./syncthing
hippo ~ $ ls -l /proc/6865/fd
total 0
lrwx------ 1 hippo hippo 64 Aug 13 08:48 0 -> /dev/pts/10
lrwx------ 1 hippo hippo 64 Aug 13 08:48 1 -> /dev/pts/10
lrwx------ 1 hippo hippo 64 Aug 13 08:48 2 -> /dev/pts/10
lr-x------ 1 hippo hippo 64 Aug 13 08:48 3 -> /dev/urandom
lr-x------ 1 hippo hippo 64 Aug 13 08:48 4 -> pipe:[1095925]
lr-x------ 1 hippo hippo 64 Aug 13 08:48 6 -> pipe:[1095926]
hippo ~ $ ls -l /proc/6869/fd
total 0
lr-x------ 1 hippo hippo 64 Aug 13 08:48 0 -> /dev/null
l-wx------ 1 hippo hippo 64 Aug 13 08:48 1 -> pipe:[1095926]
lrwx------ 1 hippo hippo 64 Aug 13 08:48 10 -> socket:[1095945]
lrwx------ 1 hippo hippo 64 Aug 13 08:48 11 -> socket:[1095946]
lrwx------ 1 hippo hippo 64 Aug 13 08:48 12 -> socket:[1095949]
lrwx------ 1 hippo hippo 64 Aug 13 08:48 13 -> socket:[1095953]
lrwx------ 1 hippo hippo 64 Aug 13 08:48 14 -> socket:[1095957]
lrwx------ 1 hippo hippo 64 Aug 13 08:48 15 -> socket:[1096140]
lrwx------ 1 hippo hippo 64 Aug 13 08:48 17 -> socket:[1095964]
lrwx------ 1 hippo hippo 64 Aug 13 08:48 19 -> socket:[1095469]
l-wx------ 1 hippo hippo 64 Aug 13 08:48 2 -> pipe:[1095925]
lr-x------ 1 hippo hippo 64 Aug 13 08:48 20 -> /home/hippo/.config/syncthing/index-v0.11.0.db/000236.ldb
lr-x------ 1 hippo hippo 64 Aug 13 08:48 3 -> /dev/urandom
l-wx------ 1 hippo hippo 64 Aug 13 08:48 4 -> /home/hippo/.config/syncthing/index-v0.11.0.db/000234.log
lrwx------ 1 hippo hippo 64 Aug 13 08:48 5 -> /home/hippo/.config/syncthing/index-v0.11.0.db/LOCK
l-wx------ 1 hippo hippo 64 Aug 13 08:48 6 -> /home/hippo/.config/syncthing/index-v0.11.0.db/LOG
l-wx------ 1 hippo hippo 64 Aug 13 08:48 7 -> /home/hippo/.config/syncthing/index-v0.11.0.db/MANIFEST-000235
lrwx------ 1 hippo hippo 64 Aug 13 08:48 8 -> socket:[1095944]
lrwx------ 1 hippo hippo 64 Aug 13 08:48 9 -> anon_inode:[eventpoll]

After update:

hippo ~ $ ps aux | grep "[s]yncthing"
hippo     6929  0.4  0.5 192048  5048 pts/10   Sl   08:49   0:00 ./syncthing
hippo     6934  100  3.0 362948 30500 pts/10   Sl   08:49   0:07 ./syncthing
hippo ~ $ ls -l /proc/6929/fd
total 0
lr-x------ 1 hippo hippo 64 Aug 13 08:49 0 -> /dev/null
l-wx------ 1 hippo hippo 64 Aug 13 08:49 1 -> /dev/null
l-wx------ 1 hippo hippo 64 Aug 13 08:49 2 -> /dev/null
lr-x------ 1 hippo hippo 64 Aug 13 08:49 3 -> /dev/urandom
lr-x------ 1 hippo hippo 64 Aug 13 08:49 4 -> pipe:[1095672]
lr-x------ 1 hippo hippo 64 Aug 13 08:49 6 -> pipe:[1095673]
hippo ~ $ ls -l /proc/6934/fd
total 0
lr-x------ 1 hippo hippo 64 Aug 13 08:49 0 -> /dev/null
l-wx------ 1 hippo hippo 64 Aug 13 08:49 1 -> pipe:[1095673]
lrwx------ 1 hippo hippo 64 Aug 13 08:49 10 -> socket:[1096368]
lrwx------ 1 hippo hippo 64 Aug 13 08:49 11 -> socket:[1096369]
lrwx------ 1 hippo hippo 64 Aug 13 08:49 12 -> socket:[1096372]
lrwx------ 1 hippo hippo 64 Aug 13 08:49 13 -> socket:[1096376]
lrwx------ 1 hippo hippo 64 Aug 13 08:49 14 -> socket:[1096380]
lrwx------ 1 hippo hippo 64 Aug 13 08:49 17 -> socket:[1096387]
l-wx------ 1 hippo hippo 64 Aug 13 08:49 2 -> pipe:[1095672]
lr-x------ 1 hippo hippo 64 Aug 13 08:49 3 -> /dev/urandom
l-wx------ 1 hippo hippo 64 Aug 13 08:49 4 -> /home/hippo/.config/syncthing/index-v0.11.0.db/000239.log
lrwx------ 1 hippo hippo 64 Aug 13 08:49 5 -> /home/hippo/.config/syncthing/index-v0.11.0.db/LOCK
l-wx------ 1 hippo hippo 64 Aug 13 08:49 6 -> /home/hippo/.config/syncthing/index-v0.11.0.db/LOG
l-wx------ 1 hippo hippo 64 Aug 13 08:49 7 -> /home/hippo/.config/syncthing/index-v0.11.0.db/MANIFEST-000240
lrwx------ 1 hippo hippo 64 Aug 13 08:49 8 -> socket:[1096705]
lrwx------ 1 hippo hippo 64 Aug 13 08:49 9 -> anon_inode:[eventpoll]

Open an issue on github, someone needs to look at it

Thanks